You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@trafficcontrol.apache.org by dg...@apache.org on 2019/03/15 19:37:22 UTC

[trafficcontrol] branch 3.0.x updated: Modified logging to include the resolver IP address and override the … (#3364) (#3408)

This is an automated email from the ASF dual-hosted git repository.

dgelinas pushed a commit to branch 3.0.x
in repository https://gitbox.apache.org/repos/asf/trafficcontrol.git


The following commit(s) were added to refs/heads/3.0.x by this push:
     new f247d0e  Modified logging to include the resolver IP address and override the … (#3364) (#3408)
f247d0e is described below

commit f247d0ef52d7617faeaf0f614fc9a56483cf87f5
Author: Steve Malenfant <sm...@users.noreply.github.com>
AuthorDate: Fri Mar 15 15:37:17 2019 -0400

    Modified logging to include the resolver IP address and override the … (#3364) (#3408)
    
    * Modified logging to include the resolver IP address and override the client address when EDNS0 client subnet extensions are enabled and a client subnet is present. Updated docs and tests. This resolves #3363.
    
    * Updated the changelog to include a note about the logging change.
    
    (cherry picked from commit 60ca6c409ea6270fb671b5ffb0f53ff37c55a037)
---
 CHANGELOG.md                                       |  2 +-
 docs/source/admin/traffic_ops/using.rst            |  2 +
 docs/source/admin/traffic_router.rst               | 60 ++++++++++++++++------
 .../core/dns/DNSAccessEventBuilder.java            | 13 ++++-
 .../traffic_router/core/dns/DNSAccessRecord.java   | 15 +++++-
 .../traffic_router/core/dns/NameServer.java        |  2 +
 .../core/dns/DNSAccessEventBuilderTest.java        | 54 ++++++++++++++++---
 .../core/dns/protocol/AbstractProtocolTest.java    |  8 +--
 8 files changed, 125 insertions(+), 31 deletions(-)

diff --git a/CHANGELOG.md b/CHANGELOG.md
index 2f55dc5..9ed407f 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -11,7 +11,7 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/).
   - validates modulus of private and public keys
   - validates current timestamp falls within the certificate date bracket
   - validates certificate subjects against the DS URL
-- Traffic Router, changed lookup of TLS certificates to be case-insensitive
+- Modified Traffic Router logging format to include an additional field for DNS log entries, namely `rhi`. This defaults to '-' and is only used when EDNS0 client subnet extensions are enabled and a client subnet is present in the request. When enabled and a subnet is present, the subnet appears in the `chi` field and the resolver address is in the `rhi` field.
 
 ## [3.0.0] - 2019-02-13
 ### Added
diff --git a/docs/source/admin/traffic_ops/using.rst b/docs/source/admin/traffic_ops/using.rst
index af40b1f..9257b43 100644
--- a/docs/source/admin/traffic_ops/using.rst
+++ b/docs/source/admin/traffic_ops/using.rst
@@ -734,6 +734,8 @@ Traffic Router Profile
 +-----------------------------------------+------------------------+--------------------------------------------------------------------------------------------------------------------------------------------------+
 | CoverageZoneJsonURL                     | CRConfig.xml           | The location (URL) to retrieve the coverage zone map file in JSON format from.                                                                   |
 +-----------------------------------------+------------------------+--------------------------------------------------------------------------------------------------------------------------------------------------+
+| ecsEnable                               | CRConfig.json          | Boolean value to enable or disable ENDS0 client subnet extensions.                                                                               |
++-----------------------------------------+------------------------+--------------------------------------------------------------------------------------------------------------------------------------------------+
 | geolocation.polling.url                 | CRConfig.json          | The location (URL) to retrieve the geo database file from.                                                                                       |
 +-----------------------------------------+------------------------+--------------------------------------------------------------------------------------------------------------------------------------------------+
 | geolocation.polling.interval            | CRConfig.json          | How often to refresh the coverage geo location database  in ms                                                                                   |
diff --git a/docs/source/admin/traffic_router.rst b/docs/source/admin/traffic_router.rst
index 052a9bc..ff59a9c 100644
--- a/docs/source/admin/traffic_router.rst
+++ b/docs/source/admin/traffic_router.rst
@@ -197,6 +197,30 @@ Message Format
 
 .. Note:: Any value that is a single dash character or a dash character enclosed in quotes represents an empty value
 
+.. table:: Fields Always Present
+
+	+-------+----------------------------------------------------------------------------------+-------------------------------------------------------------------------------------+
+	| Name  | Description                                                                      | Data                                                                                |
+	+=======+==================================================================================+=====================================================================================+
+	| qtype | Whether the request was for DNS or HTTP                                          | Always "DNS" or "HTTP"                                                              |
+	+-------+----------------------------------------------------------------------------------+-------------------------------------------------------------------------------------+
+	| chi   | The IP address of the requester                                                  | Depends on whether this was a DNS or HTTP request, see other sections               |
+	+-------+----------------------------------------------------------------------------------+-------------------------------------------------------------------------------------+
+	| rhi   | The IP address of the request source address                                     | Depends on whether this was a DNS or HTTP request, see other sections               |
+	+-------+----------------------------------------------------------------------------------+-------------------------------------------------------------------------------------+
+	| ttms  | The amount of time in milliseconds it took Traffic Router to process the request | A number greater than or equal to zero                                              |
+	+-------+----------------------------------------------------------------------------------+-------------------------------------------------------------------------------------+
+	| rtype | Routing result type                                                              | One of ERROR, CZ, DEEP_CZ, GEO, MISS, STATIC_ROUTE, DS_REDIRECT, DS_MISS, INIT, FED |
+	+-------+----------------------------------------------------------------------------------+-------------------------------------------------------------------------------------+
+	| rloc  | GeoLocation of result                                                            | Latitude and longitude in degrees as floating point numbers                         |
+	+-------+----------------------------------------------------------------------------------+-------------------------------------------------------------------------------------+
+	| rdtl  | Result details Associated with unusual conditions                                | One of DS_NOT_FOUND, DS_NO_BYPASS, DS_BYPASS, DS_CZ_ONLY, DS_CZ_BACKUP_CG           |
+	+-------+----------------------------------------------------------------------------------+-------------------------------------------------------------------------------------+
+	| rerr  | Message about an internal Traffic Router error                                   | String                                                                              |
+	+-------+----------------------------------------------------------------------------------+-------------------------------------------------------------------------------------+
+
+.. seealso:: If `Regional Geo-Blocking <regionalgeo-qht>`_ is enabled on the :term:`Delivery Service`, an additional field (``rgb``) will appear.
+
 Sample Message
 """"""""""""""
 
@@ -207,6 +231,8 @@ Items within brackets below are detailed under the HTTP and DNS sections::
 
 .. Note:: The above message samples contain fields that are always present for every single access event to Traffic Router
 
+	144140678.000 qtype=DNS chi=192.168.10.11 rhi=- ttms=789 [Fields Specific to the DNS request] rtype=CZ rloc="40.252611,58.439389" rdtl=- rerr="-" [Fields Specific to the DNS result]
+	144140678.000 qtype=HTTP chi=192.168.10.11 rhi=- ttms=789 [Fields Specific to the HTTP request] rtype=GEO rloc="40.252611,58.439389" rdtl=- rerr="-" [Fields Specific to the HTTP result]
 
 Fields Always Present
 """""""""""""""""""""
@@ -293,7 +319,7 @@ HTTP Specifics
 Sample Message
 ::
 
-  1452197640.936 qtype=HTTP chi=69.241.53.218 url="http://foo.mm-test.jenkins.cdnlab.comcast.net/some/asset.m3u8" cqhm=GET cqhv=HTTP/1.1 rtype=GEO rloc="40.252611,58.439389" rdtl=- rerr="-" pssc=302 ttms=0 rurl="http://odol-atsec-sim-114.mm-test.jenkins.cdnlab.comcast.net:8090/some/asset.m3u8" rh="Accept: */*" rh="myheader: asdasdasdasfasg"
+	1452197640.936 qtype=HTTP chi=69.241.53.218 rhi=- url="http://foo.mm-test.jenkins.cdnlab.comcast.net/some/asset.m3u8" cqhm=GET cqhv=HTTP/1.1 rtype=GEO rloc="40.252611,58.439389" rdtl=- rerr="-" pssc=302 ttms=0 rurl="http://odol-atsec-sim-114.mm-test.jenkins.cdnlab.comcast.net:8090/some/asset.m3u8" rh="Accept: */*" rh="myheader: asdasdasdasfasg"
 
 .. table:: Request Fields
 
@@ -324,7 +350,7 @@ DNS Specifics
 Sample Message
 ::
 
-  144140678.000 qtype=DNS chi=192.168.10.11 ttms=123 xn=65535 fqdn=www.example.com. type=A class=IN ttl=12345 rcode=NOERROR rtype=CZ rloc="40.252611,58.439389" rdtl=- rerr="-" ans="192.168.1.2 192.168.3.4 0:0:0:0:0:ffff:c0a8:102 0:0:0:0:0:ffff:c0a8:304"
+	144140678.000 qtype=DNS chi=192.168.10.11 rhi=- ttms=123 xn=65535 fqdn=www.example.com. type=A class=IN ttl=12345 rcode=NOERROR rtype=CZ rloc="40.252611,58.439389" rdtl=- rerr="-" ans="192.168.1.2 192.168.3.4 0:0:0:0:0:ffff:c0a8:102 0:0:0:0:0:ffff:c0a8:304"
 
 .. _qname: http://www.zytrax.com/books/dns/ch15/#qname
 
@@ -332,20 +358,22 @@ Sample Message
 
 .. table:: Request Fields
 
-	+------+------------------------------------------------------------------+--------------------------------------------------------+
-	|Name  |Description                                                       |Data                                                    |
-	+======+==================================================================+========================================================+
-	|xn    |The ID from the client DNS request header                         |a whole number between 0 and 65535 (inclusive)          |
-	+------+------------------------------------------------------------------+--------------------------------------------------------+
-	|fqdn  |The qname field from the client DNS request message (i.e. The     |A series of DNS labels/domains separated by '.'         |
-	|      |fully qualified domain name the client is requesting be resolved) |characters and ending with a '.' character (see qname_) |
-	+------+------------------------------------------------------------------+--------------------------------------------------------+
-	|type  |The qtype field from the client DNS request message (i.e.         |Examples are A (IpV4), AAAA (IpV6), NS (Name Service),  |
-	|      |the type of resolution that's requested such as IPv4, IPv6)       |SOA (Start of Authority), and CNAME, (see qtype_)       |
-	+------+------------------------------------------------------------------+--------------------------------------------------------+
-	|class |The qclass field from the client DNS request message (i.e. The    |Either IN (Internet resource) or ANY (Traffic router    |
-	|      |class of resource being requested)                                |rejects requests with any other value of class)         |
-	+------+------------------------------------------------------------------+--------------------------------------------------------+
+	+-------+---------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------+
+	| Name  | Description                                                                     | Data                                                                                              |
+	+=======+=================================================================================+===================================================================================================+
+	| xn    | The ID from the client DNS request header                                       | a whole number between 0 and 65535 (inclusive)                                                    |
+	+-------+---------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------+
+	| rhi   | The IP address of the resolver when ENDS0 client subnet extensions are enabled. | An IPv4 or IPv6 string, or dash if request is for resolver only and no client subnet is present   |
+	+-------+---------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------+
+	| fqdn  | The qname field from the client DNS request message (i.e. the                   | A series of DNS labels/domains separated by '.' characters and ending with a '.' character        |
+	|       | :abbr:`FQDN (Fully Qualified Domain Name)` the client is requesting be          |                                                                                                   |
+	+-------+---------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------+
+	| type  | The qtype field from the client DNS request message (i.e. the typeof resolution | Examples are A (IpV4), AAAA (IpV6), :abbr:`NS (Name Service)`,  :abbr:`SOA (Start of Authority)`, |
+	|       | that's requested such as IPv4, IPv6)                                            | and :abbr:`CNAME (Canonical Name)`, (see qtype_)                                                  |
+	+-------+---------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------+
+	| class | The qclass field from the client DNS request message (i.e. the class of         | Either :abbr:`IN (Internet resource)` or ANY (Traffic Router rejects requests with any other      |
+	|       | resource being requested)                                                       | value of class)                                                                                   |
+	+-------+---------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------+
 
 .. table:: Response Fields
 
diff --git a/traffic_router/core/src/main/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/DNSAccessEventBuilder.java b/traffic_router/core/src/main/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/DNSAccessEventBuilder.java
index feeb64e..4c19592 100644
--- a/traffic_router/core/src/main/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/DNSAccessEventBuilder.java
+++ b/traffic_router/core/src/main/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/DNSAccessEventBuilder.java
@@ -65,9 +65,18 @@ public class DNSAccessEventBuilder {
 
         final double ttms = (System.nanoTime() - dnsAccessRecord.getRequestNanoTime()) / 1000000.0;
 
-        final String addressString = dnsAccessRecord.getClient().getHostAddress();
+        final String clientAddressString = dnsAccessRecord.getClient().getHostAddress();
+        final String resolverAddressString = dnsAccessRecord.getResolver().getHostAddress();
 
-        final StringBuilder stringBuilder = new StringBuilder(timeString).append(" qtype=DNS chi=").append(addressString).append(" ttms=").append(String.format("%.03f", ttms));
+        final StringBuilder stringBuilder = new StringBuilder(timeString).append(" qtype=DNS chi=").append(clientAddressString).append(" rhi=");
+
+        if (!clientAddressString.equals(resolverAddressString)) {
+            stringBuilder.append(resolverAddressString);
+        } else {
+            stringBuilder.append('-');
+        }
+
+        stringBuilder.append(" ttms=").append(String.format("%.03f", ttms));
 
         if (dnsAccessRecord.getDnsMessage() == null) {
             return stringBuilder.append(" xn=- fqdn=- type=- class=- rcode=-").toString();
diff --git a/traffic_router/core/src/main/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/DNSAccessRecord.java b/traffic_router/core/src/main/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/DNSAccessRecord.java
index 8bf54f4..9c255d9 100644
--- a/traffic_router/core/src/main/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/DNSAccessRecord.java
+++ b/traffic_router/core/src/main/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/DNSAccessRecord.java
@@ -29,6 +29,7 @@ import java.net.InetAddress;
 public final class DNSAccessRecord {
     private final long queryInstant;
     private final InetAddress client;
+    private final InetAddress resolver;
     private final Message dnsMessage;
     private final ResultType resultType;
     private final ResultDetails resultDetails;
@@ -43,6 +44,10 @@ public final class DNSAccessRecord {
         return client;
     }
 
+    public InetAddress getResolver() {
+        return resolver;
+    }
+
     public Message getDnsMessage() {
         return dnsMessage;
     }
@@ -65,7 +70,8 @@ public final class DNSAccessRecord {
 
     public static class Builder {
         private final long queryInstant;
-        private final InetAddress client;
+        private final InetAddress resolver;
+        private InetAddress client;
         private Message dnsMessage;
         private ResultType resultType;
         private ResultDetails resultDetails;
@@ -75,6 +81,7 @@ public final class DNSAccessRecord {
         public Builder(final long queryInstant, final InetAddress client) {
             this.queryInstant = queryInstant;
             this.client = client;
+            this.resolver = client;
             this.requestNanoTime = System.nanoTime();
         }
 
@@ -83,6 +90,11 @@ public final class DNSAccessRecord {
             return this;
         }
 
+        public Builder client(final InetAddress client) {
+            this.client = client;
+            return this;
+        }
+
         public Builder resultType(final ResultType resultType) {
             this.resultType = resultType;
             return this;
@@ -106,6 +118,7 @@ public final class DNSAccessRecord {
     private DNSAccessRecord(final Builder builder) {
         queryInstant = builder.queryInstant;
         client = builder.client;
+        resolver = builder.resolver;
         dnsMessage = builder.dnsMessage;
         resultType = builder.resultType;
         resultDetails = builder.resultDetails;
diff --git a/traffic_router/core/src/main/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/NameServer.java b/traffic_router/core/src/main/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/NameServer.java
index 87102ea..57be1c4 100644
--- a/traffic_router/core/src/main/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/NameServer.java
+++ b/traffic_router/core/src/main/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/NameServer.java
@@ -130,6 +130,8 @@ public class NameServer {
 				}
 			}
 			if ((ipaddr!= null) && (isEcsEnable())) {
+				builder.client(ipaddr);
+
 				LOGGER.debug("DNS: Using Client IP Address from ECS Option" + ipaddr.getHostAddress() + "/" 
 						+ nmask);
 				lookup(qname, qtype, ipaddr, response, flags, dnssecRequest, builder);
diff --git a/traffic_router/core/src/test/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/DNSAccessEventBuilderTest.java b/traffic_router/core/src/test/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/DNSAccessEventBuilderTest.java
index ad757c8..c9a8eac 100644
--- a/traffic_router/core/src/test/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/DNSAccessEventBuilderTest.java
+++ b/traffic_router/core/src/test/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/DNSAccessEventBuilderTest.java
@@ -42,6 +42,7 @@ import static org.powermock.api.mockito.PowerMockito.whenNew;
 public class DNSAccessEventBuilderTest {
 
     private InetAddress client;
+    private InetAddress resolver;
 
     @Before
     public void before() throws Exception {
@@ -53,6 +54,9 @@ public class DNSAccessEventBuilderTest {
 
         client = mock(InetAddress.class);
         when(client.getHostAddress()).thenReturn("192.168.10.11");
+
+        resolver = mock(InetAddress.class);
+        when(resolver.getHostAddress()).thenReturn("10.0.0.211");
     }
 
     @Test
@@ -63,7 +67,7 @@ public class DNSAccessEventBuilderTest {
         DNSAccessRecord dnsAccessRecord = new DNSAccessRecord.Builder(144140678000L, client).build();
 
         String dnsAccessEvent = DNSAccessEventBuilder.create(dnsAccessRecord, new WireParseException("invalid record length"));
-        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 ttms=789.000 xn=- fqdn=- type=- class=- rcode=-" +
+        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 rhi=- ttms=789.000 xn=- fqdn=- type=- class=- rcode=-" +
                 " rtype=- rloc=\"-\" rdtl=- rerr=\"Bad Request:WireParseException:invalid record length\" ttl=\"-\" ans=\"-\""));
     }
 
@@ -100,7 +104,7 @@ public class DNSAccessEventBuilderTest {
         DNSAccessRecord dnsAccessRecord = new DNSAccessRecord.Builder(144140678000L, client).dnsMessage(response).build();
         String dnsAccessEvent = DNSAccessEventBuilder.create(dnsAccessRecord);
 
-        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 ttms=789.123" +
+        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 rhi=- ttms=789.123" +
                 " xn=65535 fqdn=www.example.com. type=A class=IN" +
                 " rcode=NOERROR rtype=- rloc=\"-\" rdtl=- rerr=\"-\" ttl=\"1 2 3\" ans=\"foo bar baz\""));
 
@@ -108,7 +112,7 @@ public class DNSAccessEventBuilderTest {
         when(System.nanoTime()).thenReturn(100000000L + 456000L);
         dnsAccessEvent = DNSAccessEventBuilder.create(dnsAccessRecord);
 
-        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 ttms=0.456" +
+        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 rhi=- ttms=0.456" +
                 " xn=65535 fqdn=www.example.com. type=A class=IN" +
                 " rcode=NOERROR rtype=- rloc=\"-\" rdtl=- rerr=\"-\" ttl=\"1 2 3\" ans=\"foo bar baz\""));
     }
@@ -121,7 +125,7 @@ public class DNSAccessEventBuilderTest {
 
         DNSAccessRecord dnsAccessRecord = new DNSAccessRecord.Builder(144140678000L, client).dnsMessage(query).build();
         String dnsAccessEvent = DNSAccessEventBuilder.create(dnsAccessRecord, new RuntimeException("boom it failed"));
-        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 ttms=789.876" +
+        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 rhi=- ttms=789.876" +
                 " xn=65535 fqdn=www.example.com. type=A class=IN" +
                 " rcode=SERVFAIL rtype=- rloc=\"-\" rdtl=- rerr=\"Server Error:RuntimeException:boom it failed\" ttl=\"-\" ans=\"-\""));
     }
@@ -163,22 +167,58 @@ public class DNSAccessEventBuilderTest {
         DNSAccessRecord dnsAccessRecord = builder.build();
         String dnsAccessEvent = DNSAccessEventBuilder.create(dnsAccessRecord);
 
-        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 ttms=789.000" +
+        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 rhi=- ttms=789.000" +
                 " xn=65535 fqdn=www.example.com. type=A class=IN" +
                 " rcode=NOERROR rtype=CZ rloc=\"39.75,-104.99\" rdtl=- rerr=\"-\" ttl=\"1 2 3\" ans=\"foo bar baz\""));
 
         dnsAccessRecord = builder.resultType(ResultType.GEO).build();
         dnsAccessEvent = DNSAccessEventBuilder.create(dnsAccessRecord);
 
-        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 ttms=0.123" +
+        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 rhi=- ttms=0.123" +
                 " xn=65535 fqdn=www.example.com. type=A class=IN" +
                 " rcode=NOERROR rtype=GEO rloc=\"39.75,-104.99\" rdtl=- rerr=\"-\" ttl=\"1 2 3\" ans=\"foo bar baz\""));
 
         dnsAccessRecord = builder.resultType(ResultType.MISS).resultDetails(ResultDetails.DS_NOT_FOUND).build();
         dnsAccessEvent = DNSAccessEventBuilder.create(dnsAccessRecord);
 
-        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 ttms=0.246" +
+        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 rhi=- ttms=0.246" +
                 " xn=65535 fqdn=www.example.com. type=A class=IN" +
                 " rcode=NOERROR rtype=MISS rloc=\"39.75,-104.99\" rdtl=DS_NOT_FOUND rerr=\"-\" ttl=\"1 2 3\" ans=\"foo bar baz\""));
     }
+
+    @Test
+    public void itLogsResolverAndClient() throws Exception {
+        final Name name = Name.fromString("www.example.com.");
+
+        when(System.currentTimeMillis()).thenReturn(144140678789L).thenReturn(144140678000L);
+        when(System.nanoTime()).thenReturn(100000000L, 100000000L + 789000321L, 100000000L + 123123L, 100000000L + 246001L );
+
+        final Record question = Record.newRecord(name, Type.A, DClass.IN, 12345L);
+        final Message response = spy(Message.newQuery(question));
+        response.getHeader().setRcode(Rcode.NOERROR);
+
+        final Record record1 = mock(Record.class);
+        when(record1.rdataToString()).thenReturn("foo");
+        when(record1.getTTL()).thenReturn(1L);
+
+        Record[] records = new Record[] {record1};
+        when(response.getSectionArray(Section.ANSWER)).thenReturn(records);
+
+        InetAddress answerAddress = Inet4Address.getByName("192.168.1.23");
+
+        ARecord addressRecord = new ARecord(name, DClass.IN, 54321L, answerAddress);
+        response.addRecord(addressRecord, Section.ANSWER);
+
+        Geolocation resultLocation = new Geolocation(39.7528,-104.9997);
+        ResultType resultType = ResultType.CZ;
+        final DNSAccessRecord.Builder builder = new DNSAccessRecord.Builder(144140678000L, resolver)
+                .dnsMessage(response).resultType(resultType).resultLocation(resultLocation).client(client);
+
+        DNSAccessRecord dnsAccessRecord = builder.build();
+        String dnsAccessEvent = DNSAccessEventBuilder.create(dnsAccessRecord);
+
+        assertThat(dnsAccessEvent, equalTo("144140678.000 qtype=DNS chi=192.168.10.11 rhi=10.0.0.211 ttms=789.000" +
+                " xn=65535 fqdn=www.example.com. type=A class=IN" +
+                " rcode=NOERROR rtype=CZ rloc=\"39.75,-104.99\" rdtl=- rerr=\"-\" ttl=\"1\" ans=\"foo\""));
+    }
 }
\ No newline at end of file
diff --git a/traffic_router/core/src/test/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/protocol/AbstractProtocolTest.java b/traffic_router/core/src/test/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/protocol/AbstractProtocolTest.java
index cdb7691..f9852b4 100644
--- a/traffic_router/core/src/test/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/protocol/AbstractProtocolTest.java
+++ b/traffic_router/core/src/test/java/com/comcast/cdn/traffic_control/traffic_router/core/dns/protocol/AbstractProtocolTest.java
@@ -100,7 +100,7 @@ public class AbstractProtocolTest {
 
         abstractProtocol.run();
 
-        verify(accessLogger).info("144140678.000 qtype=DNS chi=192.168.23.45 ttms=345.123 xn=65535 fqdn=www.example.com. type=A class=IN rcode=NOERROR rtype=- rloc=\"-\" rdtl=- rerr=\"-\" ttl=\"3600\" ans=\"192.168.8.9\"");
+        verify(accessLogger).info("144140678.000 qtype=DNS chi=192.168.23.45 rhi=- ttms=345.123 xn=65535 fqdn=www.example.com. type=A class=IN rcode=NOERROR rtype=- rloc=\"-\" rdtl=- rerr=\"-\" ttl=\"3600\" ans=\"192.168.8.9\"");
     }
 
     @Test
@@ -123,7 +123,7 @@ public class AbstractProtocolTest {
         abstractProtocol.setNameServer(nameServer);
         abstractProtocol.run();
 
-        verify(accessLogger).info("144140678.000 qtype=DNS chi=192.168.23.45 ttms=345.123 xn=65535 fqdn=John\\032Wayne. type=TYPE65530 class=CLASS43210 rcode=REFUSED rtype=- rloc=\"-\" rdtl=- rerr=\"-\" ttl=\"-\" ans=\"-\"");
+        verify(accessLogger).info("144140678.000 qtype=DNS chi=192.168.23.45 rhi=- ttms=345.123 xn=65535 fqdn=John\\032Wayne. type=TYPE65530 class=CLASS43210 rcode=REFUSED rtype=- rloc=\"-\" rdtl=- rerr=\"-\" ttl=\"-\" ans=\"-\"");
     }
 
     @Test
@@ -131,7 +131,7 @@ public class AbstractProtocolTest {
         FakeAbstractProtocol abstractProtocol = new FakeAbstractProtocol(client, new byte[] {1,2,3,4,5,6,7});
         abstractProtocol.setNameServer(nameServer);
         abstractProtocol.run();
-        verify(accessLogger).info("144140678.000 qtype=DNS chi=192.168.23.45 ttms=345.123 xn=- fqdn=- type=- class=- rcode=- rtype=- rloc=\"-\" rdtl=- rerr=\"Bad Request:WireParseException:end of input\" ttl=\"-\" ans=\"-\"");
+        verify(accessLogger).info("144140678.000 qtype=DNS chi=192.168.23.45 rhi=- ttms=345.123 xn=- fqdn=- type=- class=- rcode=- rtype=- rloc=\"-\" rdtl=- rerr=\"Bad Request:WireParseException:end of input\" ttl=\"-\" ans=\"-\"");
     }
 
     @Test
@@ -154,7 +154,7 @@ public class AbstractProtocolTest {
         abstractProtocol.setNameServer(nameServer);
         abstractProtocol.run();
 
-        verify(accessLogger).info("144140678.000 qtype=DNS chi=192.168.23.45 ttms=345.123 xn=65535 fqdn=John\\032Wayne. type=TYPE65530 class=CLASS43210 rcode=SERVFAIL rtype=- rloc=\"-\" rdtl=- rerr=\"Server Error:RuntimeException:Aw snap!\" ttl=\"-\" ans=\"-\"");
+        verify(accessLogger).info("144140678.000 qtype=DNS chi=192.168.23.45 rhi=- ttms=345.123 xn=65535 fqdn=John\\032Wayne. type=TYPE65530 class=CLASS43210 rcode=SERVFAIL rtype=- rloc=\"-\" rdtl=- rerr=\"Server Error:RuntimeException:Aw snap!\" ttl=\"-\" ans=\"-\"");
 
     }