Log everything each record type parses

dns/src/record/a.rs

@@ -1,5 +1,7 @@
 use std::net::Ipv4Addr;
 
+use log::*;
+
 use crate::wire::*;
 
 
@@ -28,9 +30,11 @@ impl Wire for A {
 
         if let [a, b, c, d] = *buf {
             let address = Ipv4Addr::new(a, b, c, d);
+            trace!("Parsed IPv4 address -> {:?}", address);
             Ok(A { address })
         }
         else {
+            warn!("Received non-four length -> {:?}", buf.len());
             Err(WireError::WrongLength { expected: 4, got: buf.len() as u16 })
         }
     }

dns/src/record/aaaa.rs

@@ -1,5 +1,7 @@
 use std::net::Ipv6Addr;
 
+use log::*;
+
 use crate::wire::*;
 
 
@@ -29,9 +31,12 @@ impl Wire for AAAA {
         if let [a, b, c, d, e, f, g, h, i, j, k, l, m, n, o, p] = *buf {
             let address = Ipv6Addr::from([a, b, c, d, e, f, g, h, i, j, k, l, m, n, o, p]);
             // probably the best two lines of code I have ever written
+
+            trace!("Parsed IPv6 address -> {:?}", address);
             Ok(AAAA { address })
         }
         else {
+            warn!("Received non-sixteen length -> {:?}", buf.len());
             Err(WireError::WrongLength { expected: 16, got: buf.len() as u16 })
         }
     }

dns/src/record/caa.rs

@@ -1,3 +1,5 @@
+use log::*;
+
 use crate::wire::*;
 
 
@@ -27,23 +29,34 @@ impl Wire for CAA {
     #[cfg_attr(all(test, feature = "with_mutagen"), ::mutagen::mutate)]
     fn read(len: u16, c: &mut Cursor<&[u8]>) -> Result<Self, WireError> {
         let flags = c.read_u8()?;
+        trace!("Parsed flags -> {:#08b}", flags);
+
+        let critical = flags & 0b_1000_0000 == 0b_1000_0000;
+        trace!("Parsed critical flag -> {:?}", critical);
+
         let tag_length = c.read_u8()?;
+        trace!("Parsed tag length -> {:?}", tag_length);
 
-        let mut tag = Vec::new();
+        let mut tag_buf = Vec::new();
         for _ in 0 .. tag_length {
-            tag.push(c.read_u8()?);
+            tag_buf.push(c.read_u8()?);
         }
 
-        let mut value = Vec::new();
-        for _ in 0 .. len.saturating_sub(u16::from(tag_length)).saturating_sub(2) {
-            value.push(c.read_u8()?);
+        let tag = String::from_utf8_lossy(&tag_buf).to_string();
+        trace!("Parsed tag -> {:?}", tag);
+
+        let remaining_length = len.saturating_sub(u16::from(tag_length)).saturating_sub(2);
+        trace!("Remaining length -> {:?}", remaining_length);
+
+        let mut value_buf = Vec::new();
+        for _ in 0 .. remaining_length {
+            value_buf.push(c.read_u8()?);
         }
 
-        Ok(CAA {
-            critical: flags & 0b_1000_0000 == 0b_1000_0000,
-            tag: String::from_utf8_lossy(&tag).to_string(),
-            value: String::from_utf8_lossy(&value).to_string(),
-        })
+        let value = String::from_utf8_lossy(&value_buf).to_string();
+        trace!("Parsed value -> {:?}", value);
+
+        Ok(CAA { critical, tag, value })
     }
 }
 

dns/src/record/cname.rs

@@ -1,3 +1,5 @@
+use log::*;
+
 use crate::strings::ReadLabels;
 use crate::wire::*;
 
@@ -21,6 +23,7 @@ impl Wire for CNAME {
     #[cfg_attr(all(test, feature = "with_mutagen"), ::mutagen::mutate)]
     fn read(_len: u16, c: &mut Cursor<&[u8]>) -> Result<Self, WireError> {
         let domain = c.read_labels()?;
+        trace!("Parsed domain -> {:?}", domain);
         Ok(CNAME { domain })
     }
 }

dns/src/record/mx.rs

@@ -1,8 +1,8 @@
+use log::*;
+
 use crate::strings::ReadLabels;
 use crate::wire::*;
 
-use log::{warn, debug};
-
 
 /// An **MX** _(mail exchange)_ record, which contains the hostnames for mail
 /// servers that handle mail sent to the domain.
@@ -28,7 +28,10 @@ impl Wire for MX {
     #[cfg_attr(all(test, feature = "with_mutagen"), ::mutagen::mutate)]
     fn read(len: u16, c: &mut Cursor<&[u8]>) -> Result<Self, WireError> {
         let preference = c.read_u16::<BigEndian>()?;
+        trace!("Parsed preference -> {:?}", preference);
+
         let exchange = c.read_labels()?;
+        trace!("Parsed exchange -> {:?}", exchange);
 
         if 2 + exchange.len() + 1 == len as usize {
             debug!("Length {} is correct", len);

dns/src/record/ns.rs

@@ -1,7 +1,7 @@
 use crate::strings::ReadLabels;
 use crate::wire::*;
 
-use log::{warn, debug};
+use log::*;
 
 
 /// A **NS** _(name server)_ record, which is used to point domains to name
@@ -24,6 +24,7 @@ impl Wire for NS {
     #[cfg_attr(all(test, feature = "with_mutagen"), ::mutagen::mutate)]
     fn read(len: u16, c: &mut Cursor<&[u8]>) -> Result<Self, WireError> {
         let nameserver = c.read_labels()?;
+        trace!("Parsed nameserver -> {:?}", nameserver);
 
         if nameserver.len() + 1 == len as usize {
             debug!("Length {} is correct", nameserver.len() + 1);

dns/src/record/opt.rs

@@ -1,5 +1,7 @@
 use std::io;
 
+use log::*;
+
 use crate::wire::*;
 
 
@@ -61,15 +63,25 @@ impl OPT {
     #[cfg_attr(all(test, feature = "with_mutagen"), ::mutagen::mutate)]
     pub fn read(c: &mut Cursor<&[u8]>) -> Result<Self, WireError> {
         let udp_payload_size = c.read_u16::<BigEndian>()?;  // replaces the class field
-        let higher_bits = c.read_u8()?;                     // replaces the ttl field...
-        let edns0_version = c.read_u8()?;                   // ...as does this...
-        let flags = c.read_u16::<BigEndian>()?;             // ...as does this
+        trace!("Parsed UDP payload size -> {:?}", udp_payload_size);
+
+        let higher_bits = c.read_u8()?;  // replaces the ttl field...
+        trace!("Parsed higher bits -> {:#08b}", higher_bits);
+
+        let edns0_version = c.read_u8()?;  // ...as does this...
+        trace!("Parsed EDNS(0) version -> {:?}", edns0_version);
+
+        let flags = c.read_u16::<BigEndian>()?;  // ...as does this
+        trace!("Parsed flags -> {:#08b}", flags);
 
         let data_length = c.read_u16::<BigEndian>()?;
+        trace!("Parsed data length -> {:?}", data_length);
+
         let mut data = Vec::new();
         for _ in 0 .. data_length {
             data.push(c.read_u8()?);
         }
+        trace!("Parsed data -> {:#x?}", data);
 
         Ok(OPT { udp_payload_size, higher_bits, edns0_version, flags, data })
     }

dns/src/record/ptr.rs

@@ -1,3 +1,5 @@
+use log::*;
+
 use crate::strings::ReadLabels;
 use crate::wire::*;
 
@@ -27,6 +29,7 @@ impl Wire for PTR {
     #[cfg_attr(all(test, feature = "with_mutagen"), ::mutagen::mutate)]
     fn read(_len: u16, c: &mut Cursor<&[u8]>) -> Result<Self, WireError> {
         let cname = c.read_labels()?;
+        trace!("Parsed cname -> {:?}", cname);
         Ok(PTR { cname })
     }
 }

dns/src/record/soa.rs

@@ -1,8 +1,8 @@
+use log::*;
+
 use crate::strings::ReadLabels;
 use crate::wire::*;
 
-use log::{warn, debug};
-
 
 /// A **SOA** _(start of authority)_ record, which contains administrative
 /// information about the zone the domain is in. These are returned when a
@@ -48,13 +48,25 @@ impl Wire for SOA {
     #[cfg_attr(all(test, feature = "with_mutagen"), ::mutagen::mutate)]
     fn read(len: u16, c: &mut Cursor<&[u8]>) -> Result<Self, WireError> {
         let mname = c.read_labels()?;
+        trace!("Parsed mname -> {:?}", mname);
+
         let rname = c.read_labels()?;
+        trace!("Parsed rname -> {:?}", rname);
+
+        let serial = c.read_u32::<BigEndian>()?;
+        trace!("Parsed serial -> {:?}", serial);
 
-        let serial           = c.read_u32::<BigEndian>()?;
         let refresh_interval = c.read_u32::<BigEndian>()?;
-        let retry_interval   = c.read_u32::<BigEndian>()?;
-        let expire_limit     = c.read_u32::<BigEndian>()?;
-        let minimum_ttl      = c.read_u32::<BigEndian>()?;
+        trace!("Parsed refresh interval -> {:?}", refresh_interval);
+
+        let retry_interval = c.read_u32::<BigEndian>()?;
+        trace!("Parsed retry interval -> {:?}", retry_interval);
+
+        let expire_limit = c.read_u32::<BigEndian>()?;
+        trace!("Parsed expire limit -> {:?}", expire_limit);
+
+        let minimum_ttl = c.read_u32::<BigEndian>()?;
+        trace!("Parsed minimum TTL -> {:?}", minimum_ttl);
 
         let got_length = mname.len() + rname.len() + 4 * 5 + 2;
         if got_length == len as usize {

dns/src/record/srv.rs

@@ -1,8 +1,8 @@
+use log::*;
+
 use crate::strings::ReadLabels;
 use crate::wire::*;
 
-use log::{debug, warn};
-
 
 /// A **SRV** record, which contains an IP address as well as a port number,
 /// for specifying the location of services more precisely.
@@ -35,9 +35,16 @@ impl Wire for SRV {
     #[cfg_attr(all(test, feature = "with_mutagen"), ::mutagen::mutate)]
     fn read(len: u16, c: &mut Cursor<&[u8]>) -> Result<Self, WireError> {
         let priority = c.read_u16::<BigEndian>()?;
-        let weight   = c.read_u16::<BigEndian>()?;
-        let port     = c.read_u16::<BigEndian>()?;
-        let target   = c.read_labels()?;
+        trace!("Parsed priority -> {:?}", priority);
+
+        let weight = c.read_u16::<BigEndian>()?;
+        trace!("Parsed weight -> {:?}", weight);
+
+        let port = c.read_u16::<BigEndian>()?;
+        trace!("Parsed port -> {:?}", port);
+
+        let target = c.read_labels()?;
+        trace!("Parsed target -> {:?}", target);
 
         let got_length = 3 * 2 + target.len() + 1;
         if got_length == len as usize {

dns/src/record/txt.rs

@@ -1,7 +1,7 @@
-use crate::wire::*;
-
 use log::*;
 
+use crate::wire::*;
+
 
 /// A **TXT** record, which holds arbitrary descriptive text.
 ///
@@ -32,6 +32,7 @@ impl Wire for TXT {
         loop {
             let next_len = c.read_u8()?;
             total_len += next_len as usize + 1;
+            trace!("Parsed slice length -> {:?} (total so far {:?})", next_len, total_len);
 
             for _ in 0 .. next_len {
                 buf.push(c.read_u8()?);
@@ -41,7 +42,7 @@ impl Wire for TXT {
                 break;
             }
             else {
-                debug!("Got length 255 so looping");
+                trace!("Got length 255, so looping");
             }
         }
 
@@ -53,6 +54,8 @@ impl Wire for TXT {
         }
 
         let message = String::from_utf8_lossy(&buf).to_string();
+        trace!("Parsed message -> {:?}", message);
+
         Ok(TXT { message })
     }
 }

dns/src/strings.rs

@@ -2,8 +2,8 @@
 
 use std::io::{self, Write};
 
-use log::debug;
 use byteorder::{ReadBytesExt, WriteBytesExt};
+use log::*;
 
 use crate::wire::*;
 
@@ -75,14 +75,14 @@ fn read_string_recursive(name_buf: &mut Vec<u8>, c: &mut Cursor<&[u8]>, recursio
             let name_two = c.read_u8()?;
             let offset = u16::from_be_bytes([name_one, name_two]);
 
-            debug!("Backtracking to offset {}", offset);
+            trace!("Backtracking to offset {}", offset);
             let new_pos = c.position();
             c.set_position(u64::from(offset));
             recursions.push(offset);
 
             read_string_recursive(name_buf, c, recursions)?;
 
-            debug!("Coming back to {}", new_pos);
+            trace!("Coming back to {}", new_pos);
             c.set_position(new_pos);
             recursions.pop();
             break;

dns/src/wire.rs

@@ -4,7 +4,7 @@ pub(crate) use std::io::Cursor;
 pub(crate) use byteorder::{BigEndian, ReadBytesExt, WriteBytesExt};
 
 use std::io;
-use log::{error, info, debug};
+use log::*;
 
 use crate::record::{Record, OPT};
 use crate::strings::{ReadLabels, WriteLabels};
@@ -58,12 +58,15 @@ impl Response {
     /// Reads bytes off of the given slice, parsing them into a response.
     #[cfg_attr(all(test, feature = "with_mutagen"), ::mutagen::mutate)]
     pub fn from_bytes(bytes: &[u8]) -> Result<Self, WireError> {
-        debug!("Parsing bytes -> {:?}", bytes);
-
+        info!("Parsing response");
+        trace!("Bytes -> {:?}", bytes);
         let mut c = Cursor::new(bytes);
+
         let transaction_id = c.read_u16::<BigEndian>()?;
+        trace!("Read txid -> {:?}", transaction_id);
+
         let flags = Flags::from_u16(c.read_u16::<BigEndian>()?);
-        debug!("Read flags: {:#?}", flags);
+        trace!("Read flags -> {:#?}", flags);
 
         let query_count      = c.read_u16::<BigEndian>()?;
         let answer_count     = c.read_u16::<BigEndian>()?;
@@ -110,7 +113,10 @@ impl Query {
     #[cfg_attr(all(test, feature = "with_mutagen"), ::mutagen::mutate)]
     fn from_bytes(qname: String, c: &mut Cursor<&[u8]>) -> Result<Self, WireError> {
         let qtype = c.read_u16::<BigEndian>()?;
+        trace!("Read qtype -> {:?}", qtype);
+
         let qclass = QClass::from_u16(c.read_u16::<BigEndian>()?);
+        trace!("Read qclass -> {:?}", qtype);
 
         Ok(Query { qtype, qclass, qname })
     }
@@ -124,17 +130,23 @@ impl Answer {
     #[cfg_attr(all(test, feature = "with_mutagen"), ::mutagen::mutate)]
     fn from_bytes(qname: String, c: &mut Cursor<&[u8]>) -> Result<Self, WireError> {
         let qtype = c.read_u16::<BigEndian>()?;
+        trace!("Read qtype -> {:?}", qtype);
+
         if qtype == OPT::RR_TYPE {
             let opt = OPT::read(c)?;
             Ok(Answer::Pseudo { qname, opt })
         }
         else {
             let qclass = QClass::from_u16(c.read_u16::<BigEndian>()?);
+            trace!("Read qclass -> {:?}", qtype);
+
             let ttl = c.read_u32::<BigEndian>()?;
+            trace!("Read TTL -> {:?}", ttl);
 
-            let len = c.read_u16::<BigEndian>()?;
-            let record = Record::from_bytes(qtype, len, c)?;
+            let record_length = c.read_u16::<BigEndian>()?;
+            trace!("Read record length -> {:?}", record_length);
 
+            let record = Record::from_bytes(qtype, record_length, c)?;
             Ok(Answer::Standard { qclass, qname, record, ttl })
         }
 
@@ -153,7 +165,7 @@ impl Record {
         macro_rules! try_record {
             ($record:tt) => {
                 if $record::RR_TYPE == qtype {
-                    info!("Deciphering {} record (type {}, len {})", $record::NAME, qtype, len);
+                    info!("Parsing {} record (type {}, len {})", $record::NAME, qtype, len);
                     return Wire::read(len, c).map(Record::$record)
                 }
             }