[Unbound-users] validating failure against Comcast forwarders
Robert Edmonds
edmonds at debian.org
Tue Aug 13 14:56:43 UTC 2013
hi,
i'm trying to debug a validation failure for the name
"businessipv6.trials.comcast.net". it only occurs when i use comcast's
DNSSEC-enabled recursives as forwarders for unbound (75.75.75.75,
2001:558:feed::1). i see debug messages in syslog from unbound like
"CNAME response was wildcard expansion and did not prove original data
did not exist". is there a bug in unbound or in comcast's responses?
if the latter, i will report it to them.
here is some debug output: first query is to unbound operating in full
recursive mode, which successfully validates; second query is to unbound
operating in forwarding mode, which returns SERVFAIL; third query is
directly to one of comcast's validating recursive servers, which returns
a response with the 'AD' bit.
i've also attached data from a separate run demonstrating the issue.
(unbound-control dump_cache, unbound-control dump_infra, syslog with
verbosity 4, and packet capture.)
root at chase{0}:~# unbound-control forward
off (using root hints)
root at chase{0}:~# dig +dnssec @::1 businessipv6.trials.comcast.net
; <<>> DiG 9.9.3-P2 <<>> +dnssec @::1 businessipv6.trials.comcast.net
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 10566
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 4, AUTHORITY: 8, ADDITIONAL: 21
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
;; QUESTION SECTION:
;businessipv6.trials.comcast.net. IN A
;; ANSWER SECTION:
businessipv6.trials.comcast.net. 7200 IN CNAME trials.comcast.net.
businessipv6.trials.comcast.net. 7200 IN RRSIG CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqS ibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZg kq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt 3wk=
trials.comcast.net. 7200 IN A 69.241.25.127
trials.comcast.net. 7200 IN RRSIG A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. 43ohDOeBaDWah1rKIKABxFEAwIAsKIPUVWLXJ9lp21m83ccxqzw0uQJv qhcxekcJFYEDUCJFwn2j8THZWlCKM+jro+0KOPqMsVGaWkND0EDxwXuE 5buknodCkn6q0fjHAnXW8cXZ68tmC8eCXYoZUJISzmspBYrcyynjunUo OZs=
;; AUTHORITY SECTION:
*.trials.comcast.net. 3600 IN NSEC troubleshooting.comcast.net. CNAME RRSIG NSEC
*.trials.comcast.net. 3600 IN RRSIG NSEC 5 3 3600 20130819220517 20130812190017 52026 comcast.net. uRrFYkj5tKT0eJCl93Jcw5g+Pf2sOrACse2VA/zwmEeEwj9D85lU8qo/ QwpCV+VHs533vXNNsiYYdCW54BhH68YGu7maNktf0l0yJqqmANg+4U26 A9Q5aqiKq0ZnTrjis3Uk0TRq0rIMPZreS6DsLro/GEgEWtDde5Gp9tUu n1s=
comcast.net. 7200 IN NS dns103.comcast.net.
comcast.net. 7200 IN NS dns104.comcast.net.
comcast.net. 7200 IN NS dns105.comcast.net.
comcast.net. 7200 IN NS dns102.comcast.net.
comcast.net. 7200 IN NS dns101.comcast.net.
comcast.net. 7200 IN RRSIG NS 5 2 7200 20130819220517 20130812190017 52026 comcast.net. A7eTXBXu4UuAhzaBSeRtcTAFsSP+GX9I9uyr3MF3KrWijVDQQW0pgCN6 S+TI+Otpi7C/mvjym3UP4qzM1n8/Xjifh8S/JmtE5h2kEqpNiHFB1Amc NKuSaTJlqN0b36B/Ux+9NoFomZsN2gJ1souTEiff0IaEu4g+2t9Df0W6 fQo=
;; ADDITIONAL SECTION:
dns103.comcast.net. 7200 IN AAAA 2001:558:1014:c:68:87:76:228
dns104.comcast.net. 7200 IN AAAA 2001:558:100a:5:68:87:68:244
dns105.comcast.net. 7200 IN AAAA 2001:558:100e:5:68:87:72:244
dns102.comcast.net. 7200 IN AAAA 2001:558:1004:7:68:87:85:132
dns101.comcast.net. 7200 IN AAAA 2001:558:fe23:8:69:252:250:103
dns103.comcast.net. 7200 IN A 68.87.76.228
dns104.comcast.net. 7200 IN A 68.87.68.244
dns105.comcast.net. 7200 IN A 68.87.72.244
dns102.comcast.net. 7200 IN A 68.87.85.132
dns101.comcast.net. 7200 IN A 69.252.250.103
dns103.comcast.net. 7200 IN RRSIG AAAA 5 3 7200 20130819220517 20130812190017 52026 comcast.net. R2otbBFPIrgSwRrUjgLOsXe3hLpjBhKJA1o3emUn9NZzR2LBvYE4uOiZ MnOyi06WkM/Yg2t0MxfGE4YV7E91IKvQj4AhWXyuy9FUl+eHDF8Ivu70 UVM3zm+VFz/xDolXxRiVoCO/Z/ai5eXp0Y5EhXZXXcuGzOmnKsFXgcmA qBY=
dns104.comcast.net. 7200 IN RRSIG AAAA 5 3 7200 20130819220517 20130812190017 52026 comcast.net. vbsLLYzuULtGjVprUSbsByJ7G9anDH7HmqGioiHFRG/b3lAqlCL7Gn06 65kF9JeAcjBEYuHDnc698jU5VahBoCS17dAty3RH4utzDWhRj5AW0sVS GY+844Do+al3PgK4D9CS9Re4DpjjNA+m1SyC6r3ihMyw/SBMeo7ZmFwz SGw=
dns105.comcast.net. 7200 IN RRSIG AAAA 5 3 7200 20130819220517 20130812190017 52026 comcast.net. QUcw5f4xKpdfOJJ0uXaJBnSjtRdpi0qiWNZbKR2kBBFuTzWlhenL9fon Gdn3ACtw5n7zKHFFHcyJgP+FuOJZt4gRPJRN9W4OpxlK6O+LEI/J5Jsw Y29Yt7sCJKcQnp81Stx8iUyXUzt6YgyVv/GZiuqUyuyjuq9rgoFT0TEp Kj8=
dns102.comcast.net. 7200 IN RRSIG AAAA 5 3 7200 20130819220517 20130812190017 52026 comcast.net. J1Lrk4fSw576t949j2KojwNjwQQxLt/qbjZP85JJeZ+8LPFVDfCi9aSs 2sETuWoBEyfyvB6wjrKiAjg4BrmgmB7vLV1/yuLvr/8YnPANe+bkIezi cRvhhYVodsNnj5u/xPCgNti1PRVsdVk7SgqrPjxRs6GHucn53+mvhsUI DFU=
dns101.comcast.net. 7200 IN RRSIG AAAA 5 3 7200 20130819220517 20130812190017 52026 comcast.net. on7EYhQAp0v7GmKHcLi+4V6ED4edYbLmnoP+BmJvLTkVDFkIPw6oGsip Cjl/sWzS6unrN8P9tt7HpYYjr9w9iZfOtjJ796Gp8o+ViQx8+QZmjnpc rnLZaHgUIUrSBMUni3XoxO63QGnzHWdlcpLf+cTOYhghFbGZsYy9zt6R JT8=
dns103.comcast.net. 7200 IN RRSIG A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. zAZDI93qbalClGpRb4jAvMFvXt6sQPTesin743/M/5VgXOrLNXpKkCcW vSu0uR/slrSszl4yz1PbQN9TVoJKVs4f6F3iUOolesvZs5WTfYYJRzCy pEtWLZNsKXzA/x7IA371F0T+oGb8qtp6mENzTgbu89FHrcUr0Y/+vL6L hoM=
dns104.comcast.net. 7200 IN RRSIG A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. cVMR/SVzbnP8Ut+b3LfztEj65OzgQQeNihhTLSLlPuOxuUOb2Iu6ryer pE9VaN8S/pxg6ftWxWttmitufJeabmWs+493jtTWssE6eM5CGCyJxOal 0XxjaGuj4f0iOnh763jzMGxPMSKRFQQEbLh499vVq4jMz/T+dXCoC0c2 lk8=
dns105.comcast.net. 7200 IN RRSIG A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. TdB00q6wEZ9+o4rSeLtjkozdT0RKsTQglip7+hnfvrb7oZ98ZWd/Ldr5 XOzhsO+vDI0QGGL5HGYLvsMaXuKjpbCEAioIJ/RzzwCRuvXSCSa8/HMf 2cMD8dwZLE2YyRzgLaL+Om0xUbWl1KQ34c4czul+DOLFyQvmyPIGTWWH G3s=
dns102.comcast.net. 7200 IN RRSIG A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. INMxmoy9jDfasHYJRrl/LXcWiOQJmDgE6bdJ8tT58R1rje9KTtNSlJ73 /6opL982HsN6UMOI14wszP+mL3ajBnAy67TY8Ssff7Vu4QZfHjsrJm/h NfK4SmJGp2puJvJnusxdD0XGwQYG/j+lsd/1nEbf6sXeJeOUDRbhGf1j rAY=
dns101.comcast.net. 7200 IN RRSIG A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. DPOqgXwJxIGlSyDuXtgL0PVPlGUnZjifKY6V1YxRamUrxzGyksgyAYmD +7loyfIH39hrJB7mADOgtf8jOprs/P4uS6KJX96sDNzC9xWcxq7JOPGc RxX9/+RxHjl6lyNONgtmL7aNx+l9G676IsiudoS6/OJcmqs0gXANgjFq O/U=
;; Query time: 963 msec
;; SERVER: ::1#53(::1)
;; WHEN: Tue Aug 13 10:41:35 EDT 2013
;; MSG SIZE rcvd: 2860
root at chase{0}:~# unbound-control forward 75.75.75.75 2001:558:feed::1
ok
root at chase{0}:~# unbound-control flush_zone "."
ok removed 73 rrsets, 27 messages and 3 key entries
root at chase{0}:~# dig +dnssec @::1 businessipv6.trials.comcast.net
; <<>> DiG 9.9.3-P2 <<>> +dnssec @::1 businessipv6.trials.comcast.net
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 54096
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
;; QUESTION SECTION:
;businessipv6.trials.comcast.net. IN A
;; Query time: 318 msec
;; SERVER: ::1#53(::1)
;; WHEN: Tue Aug 13 10:42:15 EDT 2013
;; MSG SIZE rcvd: 60
root at chase{0}:~# dig +dnssec @2001:558:feed::1 businessipv6.trials.comcast.net
; <<>> DiG 9.9.3-P2 <<>> +dnssec @2001:558:feed::1 businessipv6.trials.comcast.net
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 22099
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4000
;; QUESTION SECTION:
;businessipv6.trials.comcast.net. IN A
;; ANSWER SECTION:
businessipv6.trials.comcast.net. 1338 IN CNAME trials.comcast.net.
businessipv6.trials.comcast.net. 1338 IN RRSIG CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqS ibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZg kq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt 3wk=
trials.comcast.net. 1338 IN A 69.241.25.127
trials.comcast.net. 1338 IN RRSIG A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. 43ohDOeBaDWah1rKIKABxFEAwIAsKIPUVWLXJ9lp21m83ccxqzw0uQJv qhcxekcJFYEDUCJFwn2j8THZWlCKM+jro+0KOPqMsVGaWkND0EDxwXuE 5buknodCkn6q0fjHAnXW8cXZ68tmC8eCXYoZUJISzmspBYrcyynjunUo OZs=
;; Query time: 11 msec
;; SERVER: 2001:558:feed::1#53(2001:558:feed::1)
;; WHEN: Tue Aug 13 10:42:26 EDT 2013
;; MSG SIZE rcvd: 432
root at chase{0}:~#
--
Robert Edmonds
edmonds at debian.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: businessipv6.trials.comcast.net.cache
Type: chemical/x-cache
Size: 5641 bytes
Desc: not available
URL: <http://lists.nlnetlabs.nl/pipermail/unbound-users/attachments/20130813/1780f747/attachment.bin>
-------------- next part --------------
75.75.75.75 . ttl 880 ping 9 var 19 rtt 85 rto 85 tA 0 tAAAA 0 tother 0 ednsknown 1 edns 0 delay 0 lame dnssec 0 rec 0 A 0 other 0
2001:558:feed::1 . ttl 880 ping 4 var 15 rtt 64 rto 64 tA 0 tAAAA 0 tother 0 ednsknown 1 edns 0 delay 0 lame dnssec 0 rec 0 A 0 other 0
-------------- next part --------------
Aug 13 10:30:17 chase unbound-anchor: /var/lib/unbound/root.key has content
Aug 13 10:30:17 chase unbound-anchor: success: the anchor is ok
Aug 13 10:30:17 chase unbound: [16907:0] notice: init module 0: validator
Aug 13 10:30:17 chase unbound: [16907:0] notice: init module 1: iterator
Aug 13 10:30:17 chase unbound: [16907:0] info: start of service (unbound 1.4.20).
Aug 13 10:30:22 chase unbound: [16907:0] debug: remote control operation completed
Aug 13 10:30:22 chase unbound: [16907:0] debug: close fd 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: pass to next module
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_wait_module
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_request: new external request event
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 376
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=0 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=376 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=e443
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=36914
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDd mod1 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=66072 rrset=66072 infra=2889 val=66344
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = e443
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[432:0] E443819000010004000000010C627573696E6573736970763606747269616C7307636F6D63617374036E65740000010001C00C0005000100001C200002C019C00C002E000100001C20009F0005050300001C205212969D520930C1CB3A07636F6D63617374036E65740041FD7E8C274A9EE97F2C92DB36C5C30B06B680302314415FA50DE9E805E30DC75E6A7F3C0FF1A98B2A9289B5E518BC0736B090B4F75A6C071272071E81AD6C39AC855133DC6FB035949D4E0456B338D59066366092AF2D03EE754A5EC6C629386C5866783A1BE694DF673D3A2042846F08BA70FAB997167B5F1CE1FECBEDDF09C0190001000100001A5E000445F1197FC019002E0001
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[432:256] 00001A5E009F0001050300001C205212969D520930C1CB3A07636F6D63617374036E657400E37A210CE78168359A875ACA20A001C45100C0802C2883D45562D727D969DB59BCDDC731AB3C34B9026FAA17317A4709158103502245C27DA3F131D95A508A33E8EBA3ED0A38FA8CB1519A5A4343D040F1C17B84E5BBA49E8742927EAAD1F8C70275D6F1C5D9EBCB660BC7825D8A19509212CE6B29058ADCCB29E3BA7528399B0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query: EDNS works for ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 11 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191f650
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: sanitize: removing extraneous answer RRset: trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0117200#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0117200#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 234
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was CNAME
Aug 13 10:30:27 chase unbound: [16907:0] info: cname msg ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0117200#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0117200#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 234
Aug 13 10:30:27 chase unbound: [16907:0] debug: cleared outbound list for query restart
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=297
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 297
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=0 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=376 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=ab24
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=29510
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDd mod1 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=66072 rrset=66520 infra=3178 val=66344
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 36914
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = ab24
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[234:0] AB248190000100020000000106747269616C7307636F6D63617374036E65740000010001C00C0001000100001A5D000445F1197FC00C002E000100001A5D009F0001050300001C205212969D520930C1CB3A07636F6D63617374036E657400E37A210CE78168359A875ACA20A001C45100C0802C2883D45562D727D969DB59BCDDC731AB3C34B9026FAA17317A4709158103502245C27DA3F131D95A508A33E8EBA3ED0A38FA8CB1519A5A4343D040F1C17B84E5BBA49E8742927EAAD1F8C70275D6F1C5D9EBCB660BC7825D8A19509212CE6B29058ADCCB29E3BA7528399B0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query: EDNS works for ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 14 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191f650
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: chased to trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012trials.comcast.net.#0116749#011IN#011A#01169.241.25.127#012trials.comcast.net.#0116749#011IN#011RRSIG#011A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. 43ohDOeBaDWah1rKIKABxFEAwIAsKIPUVWLXJ9lp21m83ccxqzw0uQJvqhcxekcJFYEDUCJFwn2j8THZWlCKM+jro+0KOPqMsVGaWkND0EDxwXuE5buknodCkn6q0fjHAnXW8cXZ68tmC8eCXYoZUJISzmspBYrcyynjunUoOZs=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 223
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was ANSWER
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: finishing processing for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: prepending 1 rrsets
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: nextmodule returned
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_INIT_STATE
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator classification cname
Aug 13 10:30:27 chase unbound: [16907:0] info: signer is comcast.net. TYPE0 CLASS0
Aug 13 10:30:27 chase unbound: [16907:0] info: chased extract ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0117200#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0117200#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012trials.comcast.net.#0116749#011IN#011A#01169.241.25.127#012trials.comcast.net.#0116749#011IN#011RRSIG#011A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. 43ohDOeBaDWah1rKIKABxFEAwIAsKIPUVWLXJ9lp21m83ccxqzw0uQJvqhcxekcJFYEDUCJFwn2j8THZWlCKM+jro+0KOPqMsVGaWkND0EDxwXuE5buknodCkn6q0fjHAnXW8cXZ68tmC8eCXYoZUJISzmspBYrcyynjunUoOZs=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 421
Aug 13 10:30:27 chase unbound: [16907:0] info: prime trust anchor
Aug 13 10:30:27 chase unbound: [16907:0] info: generate request . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_wait_subquery
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: pass to next module
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_wait_module
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_request: new external request event
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=297
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=297
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 297
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=297 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=2ccb
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=41644
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 2 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDCD mod1 . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: 1RDdc mod0 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=66581 rrset=66939 infra=3178 val=66344
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 29510
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = 2ccb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[736:0] 2CCB81B00001000300000001000030000100003000010001792100880100030803010001C153C96B26A53B38F50D052957A952A7EDFBBF9CDDE96176C7E1F9A9A1FA8AE058B722B4B3356C106259EE9ECA6596D046A42D9006E2D7A3DBCB72C787FE8F7ED0F555FE9B934084EFD8D2B890A275567F3C4B1B29B1DD38B9C7FC7B54ABC5E58E617F9396BF627BA6F12E9981450ADBB88258ADF53F49F39FA2DD482A487A9F00003000010001792101080101030803010001A80020A95566BA42E886BB804CDA84E47EF56DBD7AEC612615552CEC906D2116D0EF207028C51554144DFEAFE7C7CB8F005DD18234133AC0710A81182CE1FD14AD2283BC83435F9DF2
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[736:256] F6313251931A176DF0DA51E54F42E604860DFB359580250F559CC543C4FFD51CBE3DE8CFD06719237F9FC47EE729DA06835FA452E825E9A18EBC2ECBCF563474652C33CF56A9033BCDF5D973121797EC8089041B6E03A1B72D0A735B984E03687309332324F27C2DBA85E9DB15E83A0143382E974B0621C18E625ECEC907577D9E7BADE95241A81EBBE8A901D4D3276E40B114C0A2E6FC38D19C2E6AAB02644B2813F575FC21601E0DEE49CD9EE96A43103E524D62873D00002E0001000179210113003008000002A300521948FF520582804A5C00098FE7098BEA245319F4DF9251A2A5353AD88A3B06920B4AE53891CF5A3F9CDB256A10697AE3453AD2242E
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[736:512] 444281517D85E247F4E59A3B5C0C89E5E4EF0A5105C8068A1E814DD41E41FEE4344C07C610D6AB7FA739713DAC5B986BE9FD5B21CA7C3A42849DE3DC04F36CB9E08672EF2D5E0A84779836EB67B2EED3E82864B2A141991E576179A16405A2056DD771139B6443CEB83CF5AB74E1EF2B8D9C567996CAB603461765E78A4ADFB8C5BA3F303F5CEE2EF0F366B0EEF0A042C725E96E6298C5B73E5E1D9EEEF391C623D67C7C32DE3D6E3B03F205FAFBDFB9050C09CD5E546A901ECAF3467FDC78F11B3EB57B5B866B4B6580FB93DD4999B23AE7D886900000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 9 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191b640
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 3, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; .#011IN#011DNSKEY#012#012;; ANSWER SECTION:#012.#01196545#011IN#011DNSKEY#011256 3 8 AwEAAcFTyWsmpTs49Q0FKVepUqft+7+c3elhdsfh+amh+orgWLcitLM1bBBiWe6eymWW0EakLZAG4tej28tyx4f+j37Q9VX+m5NAhO/Y0riQonVWfzxLGymx3Ti5x/x7VKvF5Y5hf5OWv2J7pvEumYFFCtu4glit9T9J85+i3UgqSHqf ;{id = 49656 (zsk), size = 1024b}#012.#01196545#011IN#011DNSKEY#011257 3 8 AwEAAagAIKlVZrpC6Ia7gEzahOR+9W29euxhJhVVLOyQbSEW0O8gcCjFFVQUTf6v58fLjwBd0YI0EzrAcQqBGCzh/RStIoO8g0NfnfL2MTJRkxoXbfDaUeVPQuYEhg37NZWAJQ9VnMVDxP/VHL496M/QZxkjf5/Efucp2gaDX6RS6CXpoY68LsvPVjR0ZSwzz1apAzvN9dlzEheX7ICJBBtuA6G3LQpzW5hOA2hzCTMjJPJ8LbqF6dsV6DoBQzgul0sGIcGOYl7OyQdXfZ57relSQageu+ipAdTTJ25AsRTAoub8ONGcLmqrAmRLKBP1dfwhYB4N7knNnulqQxA+Uk1ihz0= ;{id = 19036 (ksk), size = 2048b}#012.#01196545#011IN#011RRSIG#011DNSKEY 8 0 172800 20130824235959 20130810000000 19036 . CY/nCYvqJFMZ9N+SUaKlNTrYijsGkgtK5TiRz1o/nNslahBpeuNFOtIkLkRCgVF9heJH9OWaO1wMieXk7wpRBcgGih6BTdQeQf7kNEwHxhDWq3+nOXE9rFuYa+n9WyHKfDpChJ3j3ATzbLnghnLvLV4KhHeYNutnsu7T6ChksqFBmR5XYXmhZAWiBW3XcRObZEPOuDz1q3Th7yuNnFZ5lsq2A0YXZeeKSt+4xbo/MD9c7i7w82aw7vCgQscl6W5imMW3Pl4dnu7zkcYj1nx8Mt49bjsD8gX6+9+5BQwJzV5UapAeyvNGf9x48Rs+tXtbhmtLZYD7k91JmbI659iGkA==#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 725
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was ANSWER
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: finishing processing for . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: nextmodule returned
Aug 13 10:30:27 chase unbound: [16907:0] debug: not validating response due to CD bit
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: inform_super, sub is . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: super is businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: autotrust process for . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: anchor matched DNSKEY.
Aug 13 10:30:27 chase unbound: [16907:0] debug: autotrust: validate DNSKEY with anchor: sec_status_secure
Aug 13 10:30:27 chase unbound: [16907:0] debug: . key 19036 in DNS response
Aug 13 10:30:27 chase unbound: [16907:0] debug: next probe set in 42799 seconds
Aug 13 10:30:27 chase unbound: [16907:0] debug: autotrust: write to disk: /var/lib/unbound/root.key.16907-0
Aug 13 10:30:27 chase unbound: [16907:0] debug: autotrust: replaced /var/lib/unbound/root.key
Aug 13 10:30:27 chase unbound: [16907:0] debug: autotrust: no changes
Aug 13 10:30:27 chase unbound: [16907:0] debug: anchor matched DNSKEY.
Aug 13 10:30:27 chase unbound: [16907:0] info: validate keys with anchor(DS): sec_status_secure
Aug 13 10:30:27 chase unbound: [16907:0] info: Successfully primed trust anchor . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINDKEY_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: FindKey businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: current keyname . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: target keyname comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: striplab 1
Aug 13 10:30:27 chase unbound: [16907:0] info: next keyname net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: No DS RRset
Aug 13 10:30:27 chase unbound: [16907:0] info: generate request net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_wait_subquery
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: pass to next module
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_wait_module
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_request: new external request event
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=297
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=234
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 234
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=297 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=9a5a
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=39745
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 2 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDCD mod1 net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: 1RDdc mod0 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=66798 rrset=67873 infra=3178 val=67312
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 41644
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = 9a5a
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[239:0] 9A5A81B00001000200000001036E657400002B0001C00C002B000100012F0D00248C2E08027862B27F5F516EBE19680444D4CE5E762981931842C465F00236401D8BD973EEC00C002E000100012F0D0093002B0801000151805212B180520968F0C1F80057340207D7995510A226DDEC12B347F920C1AC0460D2A149FA7BB799BA3E15D9764BA2FCD26A1C14858F0CCB7FC4EB44E6E292E141E0002E3BB3987F4B3B7D5C38AFCFB6A5EF86119BD6E23B9C5C45AB4496A7607D3B6FBF4FF83A28183573D714CAE963C616D21E2F7D96E7FC3FD18C7ED2EFCAE929D71D4AD3E3660CC4D8AB0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 14 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191b640
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; net.#011IN#011DS#012#012;; ANSWER SECTION:#012net.#01177581#011IN#011DS#01135886 8 2 7862b27f5f516ebe19680444d4ce5e762981931842c465f00236401d8bd973ee#012net.#01177581#011IN#011RRSIG#011DS 8 1 86400 20130820000000 20130812230000 49656 . VzQCB9eZVRCiJt3sErNH+SDBrARg0qFJ+nu3mbo+Fdl2S6L80mocFIWPDMt/xOtE5uKS4UHgAC47s5h/Szt9XDivz7al74YRm9biO5xcRatElqdgfTtvv0/4OigYNXPXFMrpY8YW0h4vfZbn/D/RjH7S78rpKdcdStPjZgzE2Ks=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 228
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was ANSWER
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: finishing processing for net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: nextmodule returned
Aug 13 10:30:27 chase unbound: [16907:0] debug: not validating response due to CD bit
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: inform_super, sub is net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: super is businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: verify rrset net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: verify sig 49656 8
Aug 13 10:30:27 chase unbound: [16907:0] debug: verify result: sec_status_secure
Aug 13 10:30:27 chase unbound: [16907:0] info: validated DS net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINDKEY_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: FindKey businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: current keyname . DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: target keyname comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: striplab 1
Aug 13 10:30:27 chase unbound: [16907:0] info: next keyname net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: DS RRset net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: generate request net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_wait_subquery
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: pass to next module
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_wait_module
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_request: new external request event
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=238
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=234
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 234
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=234 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=63f6
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=19928
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 2 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDCD mod1 net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: 1RDdc mod0 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=67019 rrset=68297 infra=3178 val=67312
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 39745
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = 63f6
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[743:0] 63F681B00001000300000001036E65740000300001C00C00300001000009C70086010003080103E4A70D2B9C4126CEAFBDC1A0DF563665D2F00252306A4DF66948B0F50FCE7678B7E901CD69EE05A6FEDFCADEABE24514B4D3714E63EE2CDAEDB657C0597FB66E8DF2D2169EBF1796F3696412A6183300753876A5AAAFD37B640AA32B283542B2BB09C32BB4D3D743AD9A219DF30F7D2741B140495FEA1462CDDD37A5D7BB732FC00C00300001000009C7010601010308010398067CEA5972048FA9A58178382D60B41CFDA7F1E2BC5EA80796627FEBD8AE207B1AD53AC70C6E9370EADAFE9C9E18AC07D272998539974AE5051A1F4108D8B0543BB2C9BE8E04
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[743:256] 6CB636D7BD2ABF0DC16838ABECE14A839FE03FA00BD744CE0D3215DC13D03284BE634FB742B88DB4034B862299BFAE3CAB85EB289E596ACF6180ABBFC0BD282F093337B6B93E8DB9605FB25D9F0D4A15E25EB9A8CC30D3A0FB9FEA7B45B7705A4019D1F03ADE65D55C1645EA4A43B6C603ED2501F638617CB404FEBF396EF83715A4ACE568B605AA8DD3A4B31962350C7BBB6B1B6120E787C20D34CF19614E9A18087D25768433F92EB9CD6622FDF4498B22D205BE8964EBE7C00C002E0001000009C701170030080100015180520BB2A1520276F58C2E036E6574002A16D3EADFB75D4D2F8523B1B509937EF384810ECA0D5C26B0CCE8EF4EFD1FDB38EF9419
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[743:512] 59EFDDDEAA937534787FD764AC58012C28574A8F69DAB021BDD3961E0E46C91034A643A867C4CDF21DFA3E04D34D59B322DB89A1577532E8D8F64B002C3BD86F80021F7B9C83FC90AF7D67D392A04BC5BF022906C32EE994C7801F4F9079691AEDC9CEF2538096ABAFA3264045E3314B4CEE6FFD5B4CA16D5CEB691628AE79433A34821F5A6ED05C2C5014E30B81C7153A505C880932090B8058F5D386CC9DBBE552E95C96F70DF7B84FFC5F181D62331FCE9262F114D807E565E77EEAA8C27DE0A169BAC871ADE7ECAD3455F57D5EB4F22E4C87FCBAA0B4F2789ECC0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 12 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191b640
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 3, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; net.#011IN#011DNSKEY#012#012;; ANSWER SECTION:#012net.#0112503#011IN#011DNSKEY#011256 3 8 AQPkpw0rnEEmzq+9waDfVjZl0vACUjBqTfZpSLD1D852eLfpAc1p7gWm/t/K3qviRRS003FOY+4s2u22V8BZf7ZujfLSFp6/F5bzaWQSphgzAHU4dqWqr9N7ZAqjKyg1QrK7CcMrtNPXQ62aIZ3zD30nQbFASV/qFGLN3Tel17tzLw== ;{id = 55565 (zsk), size = 1024b}#012net.#0112503#011IN#011DNSKEY#011257 3 8 AQOYBnzqWXIEj6mlgXg4LWC0HP2n8eK8XqgHlmJ/69iuIHsa1TrHDG6TcOra/pyeGKwH0nKZhTmXSuUFGh9BCNiwVDuyyb6OBGy2Nte9Kr8NwWg4q+zhSoOf4D+gC9dEzg0yFdwT0DKEvmNPt0K4jbQDS4Yimb+uPKuF6yieWWrPYYCrv8C9KC8JMze2uT6NuWBfsl2fDUoV4l65qMww06D7n+p7RbdwWkAZ0fA63mXVXBZF6kpDtsYD7SUB9jhhfLQE/r85bvg3FaSs5Wi2BaqN06SzGWI1DHu7axthIOeHwg00zxlhTpoYCH0ldoQz+S65zWYi/fRJiyLSBb6JZOvn ;{id = 35886 (ksk), size = 2048b}#012net.#0112503#011IN#011RRSIG#011DNSKEY 8 1 86400 20130814163857 20130807163357 35886 net. KhbT6t+3XU0vhSOxtQmTfvOEgQ7KDVwmsMzo7079H9s475QZWe/d3qqTdTR4f9dkrFgBLChXSo9p2rAhvdOWHg5GyRA0pkOoZ8TN8h36PgTTTVmzItuJoVd1MujY9ksALDvYb4ACH3ucg/yQr31n05KgS8W/AikGwy7plMeAH0+QeWka7cnO8lOAlquvoyZAReMxS0zub/1bTKFtXOtpFiiueUM6NIIfWm7QXCxQFOMLgccVOlBciAkyCQuAWPXThsydu+VS6VyW9w33uE/8XxgdYjMfzpJi8RTYB+Vl537qqMJ94KFpushxrefsrTRV9X1etPIuTIf8uqC08niezA==#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 732
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was ANSWER
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: finishing processing for net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: nextmodule returned
Aug 13 10:30:27 chase unbound: [16907:0] debug: not validating response due to CD bit
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: inform_super, sub is net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: super is businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt DS match algo 8 keytag 35886
Aug 13 10:30:27 chase unbound: [16907:0] debug: DS match digest ok, trying signature
Aug 13 10:30:27 chase unbound: [16907:0] debug: DS matched DNSKEY.
Aug 13 10:30:27 chase unbound: [16907:0] info: validated DNSKEY net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINDKEY_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: FindKey businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: current keyname net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: target keyname comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: striplab 0
Aug 13 10:30:27 chase unbound: [16907:0] info: next keyname comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: DS RRset net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: generate request comcast.net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_wait_subquery
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query comcast.net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: pass to next module
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_wait_module
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_request: new external request event
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving comcast.net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: comcast.net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=238
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=187
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 187
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: comcast.net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=238 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=09ec
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=6218
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 2 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDCD mod1 comcast.net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: 1RDdc mod0 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=67240 rrset=69235 infra=3178 val=68284
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 19928
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = 09ec
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[287:0] 09EC81B0000100030000000107636F6D63617374036E657400002B0001C00C002B00010001492500249FCD050230C0F50E68DCC9A2F279A994C07CF22CED97AADF44C2B1FE38A1B32BA1A34174C00C002B00010001492500189FCD0501DDC19733884EE533B35B4B57717BEA9B0EF2C4D1C00C002E0001000149250097002B08020001518052104FB4520704CCD90D036E657400904050872457FCEDAC3A3112561D75E971B483A1A874DF82E9457751E124C52CB904D695356D57CD5C3B2D944AAF24D99817D52419E6EFDF21C5D3F98A6542A46DDCAF94DBB4098D9D0F011548BFDBFB31B09830F77BBC2AC86126BBA7AFF94C1DC7F90A715D8FCC7904479A
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[287:256] D815D3974EA19BB2E2AE746C4302E86ABA29B2E10000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 12 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191b640
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query comcast.net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for comcast.net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 3, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; comcast.net.#011IN#011DS#012#012;; ANSWER SECTION:#012comcast.net.#01184261#011IN#011DS#01140909 5 2 30c0f50e68dcc9a2f279a994c07cf22ced97aadf44c2b1fe38a1b32ba1a34174#012comcast.net.#01184261#011IN#011DS#01140909 5 1 ddc19733884ee533b35b4b57717bea9b0ef2c4d1#012comcast.net.#01184261#011IN#011RRSIG#011DS 8 2 86400 20130818043812 20130811032812 55565 net. kEBQhyRX/O2sOjESVh116XG0g6GodN+C6UV3UeEkxSy5BNaVNW1XzVw7LZRKryTZmBfVJBnm798hxdP5imVCpG3cr5TbtAmNnQ8BFUi/2/sxsJgw93u8KshhJrunr/lMHcf5CnFdj8x5BEea2BXTl06hm7LirnRsQwLoaropsuE=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 276
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was ANSWER
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: finishing processing for comcast.net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query comcast.net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: nextmodule returned
Aug 13 10:30:27 chase unbound: [16907:0] debug: not validating response due to CD bit
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: inform_super, sub is comcast.net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: super is businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: verify rrset comcast.net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: verify sig 55565 8
Aug 13 10:30:27 chase unbound: [16907:0] debug: verify result: sec_status_secure
Aug 13 10:30:27 chase unbound: [16907:0] info: validated DS comcast.net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINDKEY_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: FindKey businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: current keyname net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: target keyname comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: striplab 0
Aug 13 10:30:27 chase unbound: [16907:0] info: next keyname comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: DS RRset comcast.net. DS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: generate request comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_wait_subquery
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: pass to next module
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_wait_module
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_request: new external request event
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=191
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=187
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 187
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=187 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=afbc
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=21972
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 2 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDCD mod1 comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: 1RDdc mod0 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=67469 rrset=69717 infra=3178 val=68284
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 6218
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = afbc
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[934:0] AFBC81B0000100040000000107636F6D63617374036E65740000300001C00C003000010000080501080101030503010001C753C17B8A204454A0468E1C211A7CF0A01D6F03ABC39FB433C3D6C642C02507ED58DF49742982F918506FBA14DF4834FDAE1F26F345EFE6E041BC1C3F3390AB5A201CEB61921C6DC86E5CA6796E2C248F58483131A50C6D230F48F7AE3889924DDD0E4CA02AF57C16CC04268F57EFE0966ED7F858A817AA777FD8972C9620CAE17BA316CC36EDE5A95E51D9B794AE41BD0DD6398C6B31125F060962D19771EE6F8B8A4186513D3948024259313F179DBDA7A54F984AC583F79481F8BE306B28CCD013B3B3A01E253AC25585BBC317
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[934:256] 55595330BA9F8DB0F165AF8C10D8DD38A53AFB02F497BB0CE0F7C90960726890F343CCE339277D027BE803F162BAE8C131C00C003000010000080500880100030503010001E709CBCAE337B647C493CF1CF0F3E9FEFA8E4F5C7431A3098C92E808AEFB0725A3C5B70800B051847AEC5A24A21141463170DC78F0EADDE3F14F8ED2EAEC1A0697CEBBAA35DE58AC0F8548D4760D10A076C6B848ACC126FD3646006D86BEDB087D41D99C54C96934BF8808B6C38FC8C1D4F33A8FE898390848EB18ECE4E5787FC00C002E000100000805011F0030050200000E10521CF86D517E8C2D9FCD07636F6D63617374036E657400368CC3EEA5A7545D2F8908652785CE89
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[934:512] E604B4410D5F6718C2D9B51D5B4200A694F6A19652B0F17C49CE7E899FD7C5D3C1B3609E1FA5D82B28FE6A17028E7B78A0A2395B9B46F5FCA6039FE8D76F937DC80D6416E25AF5EC0B1049B1C4F4C0E8A258F8EB1EA94AC4D214643E75ADE08BFAE44854A59B14236EFAD61AAD700FEFE0C72F1A52D26EBED3C41F1923917C7107C81F8037124FFC84408303D16D4674EA621AB5643A22FE4D9A75E2EEFA76797260D7C1124C46C627466B7352660B37C42D57C17C3BF932A00A03AF044A4A3EB3D87D762EF39F708BEB1D42D1134E2C7DA3A7411817FB463DBD86673618E8BA795AD47CC253CB41587B5E368AA3B414C00C002E000100000805009F00300502
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[934:768] 00000E105212969D520930C1CB3A07636F6D63617374036E657400813B2551AE2C0C1A591998468ED8BDCAF912F802B01E2CE367FD0A76CBED73A0B1EC32CABDF7C40D99B1BD98A103FC99038B9987E74759DA5834795949AAA32B592FC879A79B8E27070D54594ECE4E542A86A086183E792D6A5013C4606A2C6425CC04E03EA908616F0CC0DA5BF3AEFA2D5B5B3AE710BADE32E450E34D1059CF0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 11 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191b640
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; comcast.net.#011IN#011DNSKEY#012#012;; ANSWER SECTION:#012comcast.net.#0112053#011IN#011DNSKEY#011257 3 5 AwEAAcdTwXuKIERUoEaOHCEafPCgHW8Dq8OftDPD1sZCwCUH7VjfSXQpgvkYUG+6FN9INP2uHybzRe/m4EG8HD8zkKtaIBzrYZIcbchuXKZ5biwkj1hIMTGlDG0jD0j3rjiJkk3dDkygKvV8FswEJo9X7+CWbtf4WKgXqnd/2JcsliDK4XujFsw27eWpXlHZt5SuQb0N1jmMazESXwYJYtGXce5vi4pBhlE9OUgCQlkxPxedvaelT5hKxYP3lIH4vjBrKMzQE7OzoB4lOsJVhbvDF1VZUzC6n42w8WWvjBDY3TilOvsC9Je7DOD3yQlgcmiQ80PM4zknfQJ76APxYrrowTE= ;{id = 40909 (ksk), size = 2048b}#012comcast.net.#0112053#011IN#011DNSKEY#011256 3 5 AwEAAecJy8rjN7ZHxJPPHPDz6f76jk9cdDGjCYyS6Aiu+wclo8W3CACwUYR67FokohFBRjFw3Hjw6t3j8U+O0ursGgaXzruqNd5YrA+FSNR2DRCgdsa4SKzBJv02RgBthr7bCH1B2ZxUyWk0v4gItsOPyMHU8zqP6Jg5CEjrGOzk5Xh/ ;{id = 52026 (zsk), size = 1024b}#012comcast.net.#0112053#011IN#011RRSIG#011DNSKEY 5 2 3600 20130827190517 20130429150517 40909 comcast.net. NozD7qWnVF0viQhlJ4XOieYEtEENX2cYwtm1HVtCAKaU9qGWUrDxfEnOfomf18XTwbNgnh+l2Cso/moXAo57eKCiOVubRvX8pgOf6Ndvk33IDWQW4lr17AsQSbHE9MDoolj46x6pSsTSFGQ+da3gi/rkSFSlmxQjbvrWGq1wD+/gxy8aUtJuvtPEHxkjkXxxB8gfgDcST/yEQIMD0W1GdOpiGrVkOiL+TZp14u76dnlyYNfBEkxGxidGa3NSZgs3xC1XwXw7+TKgCgOvBEpKPrPYfXYu859wi+sdQtETTix9o6dBGBf7Rj29hmc2GOi6eVrUfMJTy0FYe142iqO0FA==#012comcast.net.#0112053#011IN#011RRSIG#011DNSKEY 5 2 3600 20130819220517 20130812190017 52026 comcast.net. gTslUa4sDBpZGZhGjti9yvkS+AKwHizjZ/0Kdsvtc6Cx7DLKvffEDZmxvZihA/yZA4uZh+dHWdpYNHlZSaqjK1kvyHmnm44nBw1UWU7OTlQqhqCGGD55LWpQE8RgaixkJcwE4D6pCGFvDMDaW/Ou+i1bWzrnELreMuRQ400QWc8=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 923
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was ANSWER
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: finishing processing for comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: nextmodule returned
Aug 13 10:30:27 chase unbound: [16907:0] debug: not validating response due to CD bit
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: inform_super, sub is comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] info: super is businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt DS match algo 5 keytag 40909
Aug 13 10:30:27 chase unbound: [16907:0] debug: DS match digest ok, trying signature
Aug 13 10:30:27 chase unbound: [16907:0] debug: DS matched DNSKEY.
Aug 13 10:30:27 chase unbound: [16907:0] info: validated DNSKEY comcast.net. DNSKEY IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINDKEY_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: FindKey businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_VALIDATE_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: verify rrset businessipv6.trials.comcast.net. CNAME IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: verify sig 52026 5
Aug 13 10:30:27 chase unbound: [16907:0] debug: verify result: sec_status_secure
Aug 13 10:30:27 chase unbound: [16907:0] info: verify rrset trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: verify sig 52026 5
Aug 13 10:30:27 chase unbound: [16907:0] debug: verify result: sec_status_secure
Aug 13 10:30:27 chase unbound: [16907:0] debug: Validating a cname response
Aug 13 10:30:27 chase unbound: [16907:0] debug: CNAME response was wildcard expansion and did not prove original data did not exist
Aug 13 10:30:27 chase unbound: [16907:0] info: validate(cname): sec_status_bogus
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINISHED_STATE
Aug 13 10:30:27 chase unbound: [16907:0] debug: validation failed, blacklist and retry to fetch data
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist add ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist add ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: pass back to next module
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_restart_next
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_finished event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_request: new external request event
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache blacklisted, going to the network
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=191
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=152
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 480152
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=191 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=6022
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=17972
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDd mod1 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=67698 rrset=70856 infra=3178 val=69457
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 21972
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = 6022
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[432:0] 6022819000010004000000010C627573696E6573736970763606747269616C7307636F6D63617374036E65740000010001C00C0005000100001A5D0002C019C00C002E000100001A5D009F0005050300001C205212969D520930C1CB3A07636F6D63617374036E65740041FD7E8C274A9EE97F2C92DB36C5C30B06B680302314415FA50DE9E805E30DC75E6A7F3C0FF1A98B2A9289B5E518BC0736B090B4F75A6C071272071E81AD6C39AC855133DC6FB035949D4E0456B338D59066366092AF2D03EE754A5EC6C629386C5866783A1BE694DF673D3A2042846F08BA70FAB997167B5F1CE1FECBEDDF09C0190001000100001A5D000445F1197FC019002E0001
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[432:256] 00001A5D009F0001050300001C205212969D520930C1CB3A07636F6D63617374036E657400E37A210CE78168359A875ACA20A001C45100C0802C2883D45562D727D969DB59BCDDC731AB3C34B9026FAA17317A4709158103502245C27DA3F131D95A508A33E8EBA3ED0A38FA8CB1519A5A4343D040F1C17B84E5BBA49E8742927EAAD1F8C70275D6F1C5D9EBCB660BC7825D8A19509212CE6B29058ADCCB29E3BA7528399B0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 13 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191f650
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: sanitize: removing extraneous answer RRset: trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0116749#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0116749#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 234
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was CNAME
Aug 13 10:30:27 chase unbound: [16907:0] info: cname msg ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0116749#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0116749#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 234
Aug 13 10:30:27 chase unbound: [16907:0] debug: cleared outbound list for query restart
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache blacklisted, going to the network
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=156
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=152
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 480152
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=156 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=1f80
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=52849
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDd mod1 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=67698 rrset=70856 infra=3178 val=69457
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 17972
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = 1f80
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[234:0] 1F808190000100020000000106747269616C7307636F6D63617374036E65740000010001C00C0001000100001A65000445F1197FC00C002E000100001A65009F0001050300001C205212969D520930C1CB3A07636F6D63617374036E657400E37A210CE78168359A875ACA20A001C45100C0802C2883D45562D727D969DB59BCDDC731AB3C34B9026FAA17317A4709158103502245C27DA3F131D95A508A33E8EBA3ED0A38FA8CB1519A5A4343D040F1C17B84E5BBA49E8742927EAAD1F8C70275D6F1C5D9EBCB660BC7825D8A19509212CE6B29058ADCCB29E3BA7528399B0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 12 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191f650
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: chased to trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012trials.comcast.net.#0116757#011IN#011A#01169.241.25.127#012trials.comcast.net.#0116757#011IN#011RRSIG#011A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. 43ohDOeBaDWah1rKIKABxFEAwIAsKIPUVWLXJ9lp21m83ccxqzw0uQJvqhcxekcJFYEDUCJFwn2j8THZWlCKM+jro+0KOPqMsVGaWkND0EDxwXuE5buknodCkn6q0fjHAnXW8cXZ68tmC8eCXYoZUJISzmspBYrcyynjunUoOZs=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 223
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was ANSWER
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: finishing processing for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: prepending 1 rrsets
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_restart_next event:module_event_moddone
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: chased to . TYPE0 CLASS0
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: nextmodule returned
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_INIT_STATE
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator classification cname
Aug 13 10:30:27 chase unbound: [16907:0] info: signer is comcast.net. TYPE0 CLASS0
Aug 13 10:30:27 chase unbound: [16907:0] info: chased extract ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0117200#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0117200#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012trials.comcast.net.#0116749#011IN#011A#01169.241.25.127#012trials.comcast.net.#0116749#011IN#011RRSIG#011A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. 43ohDOeBaDWah1rKIKABxFEAwIAsKIPUVWLXJ9lp21m83ccxqzw0uQJvqhcxekcJFYEDUCJFwn2j8THZWlCKM+jro+0KOPqMsVGaWkND0EDxwXuE5buknodCkn6q0fjHAnXW8cXZ68tmC8eCXYoZUJISzmspBYrcyynjunUoOZs=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 421
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINDKEY_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: FindKey businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_VALIDATE_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: verify rrset cached businessipv6.trials.comcast.net. CNAME IN
Aug 13 10:30:27 chase unbound: [16907:0] info: verify rrset cached trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: Validating a cname response
Aug 13 10:30:27 chase unbound: [16907:0] debug: CNAME response was wildcard expansion and did not prove original data did not exist
Aug 13 10:30:27 chase unbound: [16907:0] info: validate(cname): sec_status_bogus
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINISHED_STATE
Aug 13 10:30:27 chase unbound: [16907:0] debug: validation failed, blacklist and retry to fetch data
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist add ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist add ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: pass back to next module
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_restart_next
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_finished event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_request: new external request event
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache blacklisted, going to the network
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=129
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=152
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 480129
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=152 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=f5df
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=23186
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDd mod1 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=67698 rrset=70856 infra=3178 val=69457
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 52849
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = f5df
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[432:0] F5DF81B000010004000000010C627573696E6573736970763606747269616C7307636F6D63617374036E65740000010001C00C000500010000081A0002C019C00C002E00010000081A009F0005050300001C205212969D520930C1CB3A07636F6D63617374036E65740041FD7E8C274A9EE97F2C92DB36C5C30B06B680302314415FA50DE9E805E30DC75E6A7F3C0FF1A98B2A9289B5E518BC0736B090B4F75A6C071272071E81AD6C39AC855133DC6FB035949D4E0456B338D59066366092AF2D03EE754A5EC6C629386C5866783A1BE694DF673D3A2042846F08BA70FAB997167B5F1CE1FECBEDDF09C019000100010000081A000445F1197FC019002E0001
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[432:256] 0000081A009F0001050300001C205212969D520930C1CB3A07636F6D63617374036E657400E37A210CE78168359A875ACA20A001C45100C0802C2883D45562D727D969DB59BCDDC731AB3C34B9026FAA17317A4709158103502245C27DA3F131D95A508A33E8EBA3ED0A38FA8CB1519A5A4343D040F1C17B84E5BBA49E8742927EAAD1F8C70275D6F1C5D9EBCB660BC7825D8A19509212CE6B29058ADCCB29E3BA7528399B0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 10 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191f650
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: sanitize: removing extraneous answer RRset: trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0112074#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0112074#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 234
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was CNAME
Aug 13 10:30:27 chase unbound: [16907:0] info: cname msg ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0112074#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0112074#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 234
Aug 13 10:30:27 chase unbound: [16907:0] debug: cleared outbound list for query restart
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache blacklisted, going to the network
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=129
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=124
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 480124
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=124 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=0d97
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=15189
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDd mod1 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=67698 rrset=70856 infra=3178 val=69457
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 23186
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = 0d97
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[234:0] 0D9781B0000100020000000106747269616C7307636F6D63617374036E65740000010001C00C000100010000081A000445F1197FC00C002E00010000081A009F0001050300001C205212969D520930C1CB3A07636F6D63617374036E657400E37A210CE78168359A875ACA20A001C45100C0802C2883D45562D727D969DB59BCDDC731AB3C34B9026FAA17317A4709158103502245C27DA3F131D95A508A33E8EBA3ED0A38FA8CB1519A5A4343D040F1C17B84E5BBA49E8742927EAAD1F8C70275D6F1C5D9EBCB660BC7825D8A19509212CE6B29058ADCCB29E3BA7528399B0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 12 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191f650
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: chased to trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012trials.comcast.net.#0112074#011IN#011A#01169.241.25.127#012trials.comcast.net.#0112074#011IN#011RRSIG#011A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. 43ohDOeBaDWah1rKIKABxFEAwIAsKIPUVWLXJ9lp21m83ccxqzw0uQJvqhcxekcJFYEDUCJFwn2j8THZWlCKM+jro+0KOPqMsVGaWkND0EDxwXuE5buknodCkn6q0fjHAnXW8cXZ68tmC8eCXYoZUJISzmspBYrcyynjunUoOZs=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 223
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was ANSWER
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: finishing processing for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: prepending 1 rrsets
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_restart_next event:module_event_moddone
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: chased to . TYPE0 CLASS0
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: nextmodule returned
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_INIT_STATE
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator classification cname
Aug 13 10:30:27 chase unbound: [16907:0] info: signer is comcast.net. TYPE0 CLASS0
Aug 13 10:30:27 chase unbound: [16907:0] info: chased extract ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0117200#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0117200#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012trials.comcast.net.#0116749#011IN#011A#01169.241.25.127#012trials.comcast.net.#0116749#011IN#011RRSIG#011A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. 43ohDOeBaDWah1rKIKABxFEAwIAsKIPUVWLXJ9lp21m83ccxqzw0uQJvqhcxekcJFYEDUCJFwn2j8THZWlCKM+jro+0KOPqMsVGaWkND0EDxwXuE5buknodCkn6q0fjHAnXW8cXZ68tmC8eCXYoZUJISzmspBYrcyynjunUoOZs=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 421
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINDKEY_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: FindKey businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_VALIDATE_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: verify rrset cached businessipv6.trials.comcast.net. CNAME IN
Aug 13 10:30:27 chase unbound: [16907:0] info: verify rrset cached trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: Validating a cname response
Aug 13 10:30:27 chase unbound: [16907:0] debug: CNAME response was wildcard expansion and did not prove original data did not exist
Aug 13 10:30:27 chase unbound: [16907:0] info: validate(cname): sec_status_bogus
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINISHED_STATE
Aug 13 10:30:27 chase unbound: [16907:0] debug: validation failed, blacklist and retry to fetch data
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist add ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist add ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: pass back to next module
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_restart_next
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_finished event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_request: new external request event
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache blacklisted, going to the network
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=129
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=105
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 480105
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=105 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=6bca
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=7132
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDd mod1 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=67698 rrset=70856 infra=3178 val=69457
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 15189
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = 6bca
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[432:0] 6BCA819000010004000000010C627573696E6573736970763606747269616C7307636F6D63617374036E65740000010001C00C0005000100001B380002C019C00C002E000100001B38009F0005050300001C205212969D520930C1CB3A07636F6D63617374036E65740041FD7E8C274A9EE97F2C92DB36C5C30B06B680302314415FA50DE9E805E30DC75E6A7F3C0FF1A98B2A9289B5E518BC0736B090B4F75A6C071272071E81AD6C39AC855133DC6FB035949D4E0456B338D59066366092AF2D03EE754A5EC6C629386C5866783A1BE694DF673D3A2042846F08BA70FAB997167B5F1CE1FECBEDDF09C0190001000100001A66000445F1197FC019002E0001
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[432:256] 00001A66009F0001050300001C205212969D520930C1CB3A07636F6D63617374036E657400E37A210CE78168359A875ACA20A001C45100C0802C2883D45562D727D969DB59BCDDC731AB3C34B9026FAA17317A4709158103502245C27DA3F131D95A508A33E8EBA3ED0A38FA8CB1519A5A4343D040F1C17B84E5BBA49E8742927EAAD1F8C70275D6F1C5D9EBCB660BC7825D8A19509212CE6B29058ADCCB29E3BA7528399B0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 11 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191f650
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: sanitize: removing extraneous answer RRset: trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0116968#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0116968#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 234
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was CNAME
Aug 13 10:30:27 chase unbound: [16907:0] info: cname msg ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0116968#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0116968#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 234
Aug 13 10:30:27 chase unbound: [16907:0] debug: cleared outbound list for query restart
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache blacklisted, going to the network
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=129
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=89
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 480089
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=129 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=1bea
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=43218
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDd mod1 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=67698 rrset=70856 infra=3178 val=69457
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 7132
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = 1bea
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[234:0] 1BEA8190000100020000000106747269616C7307636F6D63617374036E65740000010001C00C0001000100001A5D000445F1197FC00C002E000100001A5D009F0001050300001C205212969D520930C1CB3A07636F6D63617374036E657400E37A210CE78168359A875ACA20A001C45100C0802C2883D45562D727D969DB59BCDDC731AB3C34B9026FAA17317A4709158103502245C27DA3F131D95A508A33E8EBA3ED0A38FA8CB1519A5A4343D040F1C17B84E5BBA49E8742927EAAD1F8C70275D6F1C5D9EBCB660BC7825D8A19509212CE6B29058ADCCB29E3BA7528399B0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 21 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191f650
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: chased to trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012trials.comcast.net.#0116749#011IN#011A#01169.241.25.127#012trials.comcast.net.#0116749#011IN#011RRSIG#011A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. 43ohDOeBaDWah1rKIKABxFEAwIAsKIPUVWLXJ9lp21m83ccxqzw0uQJvqhcxekcJFYEDUCJFwn2j8THZWlCKM+jro+0KOPqMsVGaWkND0EDxwXuE5buknodCkn6q0fjHAnXW8cXZ68tmC8eCXYoZUJISzmspBYrcyynjunUoOZs=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 223
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was ANSWER
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: finishing processing for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: prepending 1 rrsets
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_restart_next event:module_event_moddone
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: chased to . TYPE0 CLASS0
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: nextmodule returned
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_INIT_STATE
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator classification cname
Aug 13 10:30:27 chase unbound: [16907:0] info: signer is comcast.net. TYPE0 CLASS0
Aug 13 10:30:27 chase unbound: [16907:0] info: chased extract ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0117200#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0117200#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012trials.comcast.net.#0116749#011IN#011A#01169.241.25.127#012trials.comcast.net.#0116749#011IN#011RRSIG#011A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. 43ohDOeBaDWah1rKIKABxFEAwIAsKIPUVWLXJ9lp21m83ccxqzw0uQJvqhcxekcJFYEDUCJFwn2j8THZWlCKM+jro+0KOPqMsVGaWkND0EDxwXuE5buknodCkn6q0fjHAnXW8cXZ68tmC8eCXYoZUJISzmspBYrcyynjunUoOZs=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 421
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINDKEY_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: FindKey businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_VALIDATE_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: verify rrset cached businessipv6.trials.comcast.net. CNAME IN
Aug 13 10:30:27 chase unbound: [16907:0] info: verify rrset cached trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: Validating a cname response
Aug 13 10:30:27 chase unbound: [16907:0] debug: CNAME response was wildcard expansion and did not prove original data did not exist
Aug 13 10:30:27 chase unbound: [16907:0] info: validate(cname): sec_status_bogus
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINISHED_STATE
Aug 13 10:30:27 chase unbound: [16907:0] debug: validation failed, blacklist and retry to fetch data
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist add ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist add ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: pass back to next module
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_restart_next
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_finished event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_request: new external request event
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache blacklisted, going to the network
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=119
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=89
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 480089
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=119 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=6f20
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=10621
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDd mod1 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=67698 rrset=70856 infra=3178 val=69457
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 43218
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = 6f20
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[432:0] 6F20819000010004000000010C627573696E6573736970763606747269616C7307636F6D63617374036E65740000010001C00C0005000100001C200002C019C00C002E000100001C20009F0005050300001C205212969D520930C1CB3A07636F6D63617374036E65740041FD7E8C274A9EE97F2C92DB36C5C30B06B680302314415FA50DE9E805E30DC75E6A7F3C0FF1A98B2A9289B5E518BC0736B090B4F75A6C071272071E81AD6C39AC855133DC6FB035949D4E0456B338D59066366092AF2D03EE754A5EC6C629386C5866783A1BE694DF673D3A2042846F08BA70FAB997167B5F1CE1FECBEDDF09C0190001000100001A5E000445F1197FC019002E0001
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[432:256] 00001A5E009F0001050300001C205212969D520930C1CB3A07636F6D63617374036E657400E37A210CE78168359A875ACA20A001C45100C0802C2883D45562D727D969DB59BCDDC731AB3C34B9026FAA17317A4709158103502245C27DA3F131D95A508A33E8EBA3ED0A38FA8CB1519A5A4343D040F1C17B84E5BBA49E8742927EAAD1F8C70275D6F1C5D9EBCB660BC7825D8A19509212CE6B29058ADCCB29E3BA7528399B0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 11 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191f650
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: sanitize: removing extraneous answer RRset: trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0117200#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0117200#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 234
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was CNAME
Aug 13 10:30:27 chase unbound: [16907:0] info: cname msg ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0117200#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0117200#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 234
Aug 13 10:30:27 chase unbound: [16907:0] debug: cleared outbound list for query restart
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache blacklisted, going to the network
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=95
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=89
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 480089
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=89 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=7a43
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=35227
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDd mod1 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=67698 rrset=70856 infra=3178 val=69457
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 10621
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = 7a43
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[234:0] 7A438190000100020000000106747269616C7307636F6D63617374036E65740000010001C00C0001000100001A5D000445F1197FC00C002E000100001A5D009F0001050300001C205212969D520930C1CB3A07636F6D63617374036E657400E37A210CE78168359A875ACA20A001C45100C0802C2883D45562D727D969DB59BCDDC731AB3C34B9026FAA17317A4709158103502245C27DA3F131D95A508A33E8EBA3ED0A38FA8CB1519A5A4343D040F1C17B84E5BBA49E8742927EAAD1F8C70275D6F1C5D9EBCB660BC7825D8A19509212CE6B29058ADCCB29E3BA7528399B0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 12 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191f650
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: chased to trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012trials.comcast.net.#0116749#011IN#011A#01169.241.25.127#012trials.comcast.net.#0116749#011IN#011RRSIG#011A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. 43ohDOeBaDWah1rKIKABxFEAwIAsKIPUVWLXJ9lp21m83ccxqzw0uQJvqhcxekcJFYEDUCJFwn2j8THZWlCKM+jro+0KOPqMsVGaWkND0EDxwXuE5buknodCkn6q0fjHAnXW8cXZ68tmC8eCXYoZUJISzmspBYrcyynjunUoOZs=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 223
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was ANSWER
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: finishing processing for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: prepending 1 rrsets
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_restart_next event:module_event_moddone
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: chased to . TYPE0 CLASS0
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: nextmodule returned
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_INIT_STATE
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator classification cname
Aug 13 10:30:27 chase unbound: [16907:0] info: signer is comcast.net. TYPE0 CLASS0
Aug 13 10:30:27 chase unbound: [16907:0] info: chased extract ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0117200#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0117200#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012trials.comcast.net.#0116749#011IN#011A#01169.241.25.127#012trials.comcast.net.#0116749#011IN#011RRSIG#011A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. 43ohDOeBaDWah1rKIKABxFEAwIAsKIPUVWLXJ9lp21m83ccxqzw0uQJvqhcxekcJFYEDUCJFwn2j8THZWlCKM+jro+0KOPqMsVGaWkND0EDxwXuE5buknodCkn6q0fjHAnXW8cXZ68tmC8eCXYoZUJISzmspBYrcyynjunUoOZs=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 421
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINDKEY_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: FindKey businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_VALIDATE_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: verify rrset cached businessipv6.trials.comcast.net. CNAME IN
Aug 13 10:30:27 chase unbound: [16907:0] info: verify rrset cached trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: Validating a cname response
Aug 13 10:30:27 chase unbound: [16907:0] debug: CNAME response was wildcard expansion and did not prove original data did not exist
Aug 13 10:30:27 chase unbound: [16907:0] info: validate(cname): sec_status_bogus
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINISHED_STATE
Aug 13 10:30:27 chase unbound: [16907:0] debug: validation failed, blacklist and retry to fetch data
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist add ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: blacklist add ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: pass back to next module
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_restart_next
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_finished event:module_event_pass
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_request: new external request event
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache blacklisted, going to the network
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=95
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=77
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 480077
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=95 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=60ad
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=47216
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDd mod1 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=67698 rrset=70856 infra=3178 val=69457
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 35227
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = 60ad
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[432:0] 60AD819000010004000000010C627573696E6573736970763606747269616C7307636F6D63617374036E65740000010001C00C0005000100001C200002C019C00C002E000100001C20009F0005050300001C205212969D520930C1CB3A07636F6D63617374036E65740041FD7E8C274A9EE97F2C92DB36C5C30B06B680302314415FA50DE9E805E30DC75E6A7F3C0FF1A98B2A9289B5E518BC0736B090B4F75A6C071272071E81AD6C39AC855133DC6FB035949D4E0456B338D59066366092AF2D03EE754A5EC6C629386C5866783A1BE694DF673D3A2042846F08BA70FAB997167B5F1CE1FECBEDDF09C0190001000100001A5E000445F1197FC019002E0001
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[432:256] 00001A5E009F0001050300001C205212969D520930C1CB3A07636F6D63617374036E657400E37A210CE78168359A875ACA20A001C45100C0802C2883D45562D727D969DB59BCDDC731AB3C34B9026FAA17317A4709158103502245C27DA3F131D95A508A33E8EBA3ED0A38FA8CB1519A5A4343D040F1C17B84E5BBA49E8742927EAAD1F8C70275D6F1C5D9EBCB660BC7825D8A19509212CE6B29058ADCCB29E3BA7528399B0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 13 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191f650
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: sanitize: removing extraneous answer RRset: trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 75.75.75.75#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0117200#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0117200#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 234
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was CNAME
Aug 13 10:30:27 chase unbound: [16907:0] info: cname msg ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0117200#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0117200#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 234
Aug 13 10:30:27 chase unbound: [16907:0] debug: cleared outbound list for query restart
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state INIT REQUEST STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: resolving businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: request has dependency depth of 0
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache blacklisted, going to the network
Aug 13 10:30:27 chase unbound: [16907:0] debug: forwarding request
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: processQueryTargets: businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Aug 13 10:30:27 chase unbound: [16907:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: attempt to get extra 3 targets
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip4 75.75.75.75 port 53 (len 16)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=79
Aug 13 10:30:27 chase unbound: [16907:0] debug: servselect ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: rtt=77
Aug 13 10:30:27 chase unbound: [16907:0] debug: selrtt 480077
Aug 13 10:30:27 chase unbound: [16907:0] info: sending query: trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: sending to target: <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] debug: dnssec status: not expected
Aug 13 10:30:27 chase unbound: [16907:0] debug: EDNS lookup known=1 vs=0
Aug 13 10:30:27 chase unbound: [16907:0] debug: serviced query UDP timeout=77 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: inserted new pending reply id=dd57
Aug 13 10:30:27 chase unbound: [16907:0] debug: opened UDP if=0 port=29370
Aug 13 10:30:27 chase unbound: [16907:0] debug: comm point start listening 15
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_wait_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: 0RDd mod1 rep businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=67698 rrset=70856 infra=3178 val=69457
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 47216
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 16
Aug 13 10:30:27 chase unbound: [16907:0] debug: answer cb
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply id = dd57
Aug 13 10:30:27 chase unbound: [16907:0] debug: Incoming reply addr = ip6 2001:558:feed::1 port 53 (len 28)
Aug 13 10:30:27 chase unbound: [16907:0] debug: lookup size is 1 entries
Aug 13 10:30:27 chase unbound: [16907:0] debug: received udp reply.
Aug 13 10:30:27 chase unbound: [16907:0] debug: udp message[234:0] DD5781B0000100020000000106747269616C7307636F6D63617374036E65740000010001C00C000100010000081A000445F1197FC00C002E00010000081A009F0001050300001C205212969D520930C1CB3A07636F6D63617374036E657400E37A210CE78168359A875ACA20A001C45100C0802C2883D45562D727D969DB59BCDDC731AB3C34B9026FAA17317A4709158103502245C27DA3F131D95A508A33E8EBA3ED0A38FA8CB1519A5A4343D040F1C17B84E5BBA49E8742927EAAD1F8C70275D6F1C5D9EBCB660BC7825D8A19509212CE6B29058ADCCB29E3BA7528399B0000290FA0000080000000
Aug 13 10:30:27 chase unbound: [16907:0] debug: outnet handle udp reply
Aug 13 10:30:27 chase unbound: [16907:0] debug: measured roundtrip at 11 msec
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks start
Aug 13 10:30:27 chase unbound: [16907:0] debug: worker svcd callback for qstate 0x191f650
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: start
Aug 13 10:30:27 chase unbound: [16907:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: iterator operate: chased to trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: process_response: new external response event
Aug 13 10:30:27 chase unbound: [16907:0] info: scrub for . NS IN
Aug 13 10:30:27 chase unbound: [16907:0] info: response for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: reply from <.> 2001:558:feed::1#53
Aug 13 10:30:27 chase unbound: [16907:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012trials.comcast.net.#0112074#011IN#011A#01169.241.25.127#012trials.comcast.net.#0112074#011IN#011RRSIG#011A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. 43ohDOeBaDWah1rKIKABxFEAwIAsKIPUVWLXJ9lp21m83ccxqzw0uQJvqhcxekcJFYEDUCJFwn2j8THZWlCKM+jro+0KOPqMsVGaWkND0EDxwXuE5buknodCkn6q0fjHAnXW8cXZ68tmC8eCXYoZUJISzmspBYrcyynjunUoOZs=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 223
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: query response was ANSWER
Aug 13 10:30:27 chase unbound: [16907:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: finishing processing for businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: prepending 1 rrsets
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: iterator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator[module 0] operate: extstate:module_restart_next event:module_event_moddone
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: query businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] info: validator operate: chased to . TYPE0 CLASS0
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator: nextmodule returned
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_INIT_STATE
Aug 13 10:30:27 chase unbound: [16907:0] debug: validator classification cname
Aug 13 10:30:27 chase unbound: [16907:0] info: signer is comcast.net. TYPE0 CLASS0
Aug 13 10:30:27 chase unbound: [16907:0] info: chased extract ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr rd ra ; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012;; businessipv6.trials.comcast.net.#011IN#011A#012#012;; ANSWER SECTION:#012businessipv6.trials.comcast.net.#0117200#011IN#011CNAME#011trials.comcast.net.#012businessipv6.trials.comcast.net.#0117200#011IN#011RRSIG#011CNAME 5 3 7200 20130819220517 20130812190017 52026 comcast.net. Qf1+jCdKnul/LJLbNsXDCwa2gDAjFEFfpQ3p6AXjDcdean88D/GpiyqSibXlGLwHNrCQtPdabAcScgcega1sOayFUTPcb7A1lJ1OBFazONWQZjZgkq8tA+51Sl7Gxik4bFhmeDob5pTfZz06IEKEbwi6cPq5lxZ7Xxzh/svt3wk=#012trials.comcast.net.#0116749#011IN#011A#01169.241.25.127#012trials.comcast.net.#0116749#011IN#011RRSIG#011A 5 3 7200 20130819220517 20130812190017 52026 comcast.net. 43ohDOeBaDWah1rKIKABxFEAwIAsKIPUVWLXJ9lp21m83ccxqzw0uQJvqhcxekcJFYEDUCJFwn2j8THZWlCKM+jro+0KOPqMsVGaWkND0EDxwXuE5buknodCkn6q0fjHAnXW8cXZ68tmC8eCXYoZUJISzmspBYrcyynjunUoOZs=#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012#012;; Query time: 0 msec#012;; WHEN: Wed Dec 31 19:00:00 1969#012;; MSG SIZE rcvd: 421
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINDKEY_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: validator: FindKey businessipv6.trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_VALIDATE_STATE
Aug 13 10:30:27 chase unbound: [16907:0] info: verify rrset cached businessipv6.trials.comcast.net. CNAME IN
Aug 13 10:30:27 chase unbound: [16907:0] info: verify rrset cached trials.comcast.net. A IN
Aug 13 10:30:27 chase unbound: [16907:0] debug: Validating a cname response
Aug 13 10:30:27 chase unbound: [16907:0] debug: CNAME response was wildcard expansion and did not prove original data did not exist
Aug 13 10:30:27 chase unbound: [16907:0] info: validate(cname): sec_status_bogus
Aug 13 10:30:27 chase unbound: [16907:0] debug: val handle processing q with state VAL_FINISHED_STATE
Aug 13 10:30:27 chase unbound: [16907:0] debug: mesh_run: validator module exit state is module_finished
Aug 13 10:30:27 chase unbound: [16907:0] debug: query took 0.216838 sec
Aug 13 10:30:27 chase unbound: [16907:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out
Aug 13 10:30:27 chase unbound: [16907:0] info: average recursion processing time 0.216838 sec
Aug 13 10:30:27 chase unbound: [16907:0] info: histogram of recursion processing times
Aug 13 10:30:27 chase unbound: [16907:0] info: [25%]=0 median[50%]=0 [75%]=0
Aug 13 10:30:27 chase unbound: [16907:0] info: lower(secs) upper(secs) recursions
Aug 13 10:30:27 chase unbound: [16907:0] info: 0.131072 0.262144 1
Aug 13 10:30:27 chase unbound: [16907:0] debug: cache memory msg=67698 rrset=70856 infra=3178 val=69457
Aug 13 10:30:27 chase unbound: [16907:0] debug: svcd callbacks end
Aug 13 10:30:27 chase unbound: [16907:0] debug: close of port 29370
Aug 13 10:30:27 chase unbound: [16907:0] debug: close fd 15
Aug 13 10:30:30 chase unbound: [16907:0] debug: new control connection from ip4 127.0.0.1 port 44266 (len 16)
Aug 13 10:30:30 chase unbound: [16907:0] debug: comm point stop listening 15
Aug 13 10:30:30 chase unbound: [16907:0] debug: comm point start listening 15
Aug 13 10:30:30 chase unbound: [16907:0] debug: remote control connection authenticated
Aug 13 10:30:30 chase unbound: [16907:0] info: control cmd: verbosity 0
-------------- next part --------------
A non-text attachment was scrubbed...
Name: businessipv6.trials.comcast.net.pcap
Type: application/vnd.tcpdump.pcap
Size: 12066 bytes
Desc: not available
URL: <http://lists.nlnetlabs.nl/pipermail/unbound-users/attachments/20130813/1780f747/attachment-0001.bin>
More information about the Unbound-users
mailing list