Nov 30 11:26:51 NickDeb unbound[106181]: Nov 30 11:26:51 unbound[106181:0] debug: increased limit(open files) from 1024 to 4140
Nov 30 11:26:51 NickDeb unbound[106181]: Nov 30 11:26:51 unbound[106181:0] debug: creating udp4 socket 172.16.198.20 53
Nov 30 11:26:51 NickDeb unbound[106181]: Nov 30 11:26:51 unbound[106181:0] debug: creating tcp4 socket 172.16.198.20 53
Nov 30 11:26:51 NickDeb unbound[106181]: Nov 30 11:26:51 unbound[106181:0] debug: creating tcp4 socket 172.16.198.20 8953
Nov 30 11:26:51 NickDeb unbound[106181]: Nov 30 11:26:51 unbound[106181:0] debug: switching log to syslog
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: setup SSL certificates
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: chdir to /etc/unbound
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: drop user privileges, run as unbound
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: module config: "iterator"
Nov 30 11:26:51 NickDeb unbound: [106181:0] notice: init module 0: iterator
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: target fetch policy for level 0 is 3
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: target fetch policy for level 1 is 2
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: target fetch policy for level 2 is 1
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: target fetch policy for level 3 is 0
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: target fetch policy for level 4 is 0
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: donotq: 127.0.0.0/8
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: total of 59480 outgoing ports available
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: start threads
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: libevent 2.0.21-stable user epoll method.
Nov 30 11:26:51 NickDeb unbound: [106181:0] info: DelegationPoint<mytest.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug:    ip4 172.20.0.1 port 53 (len 16)
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: no config, using builtin root hints.
Nov 30 11:26:51 NickDeb unbound: [106181:0] debug: cache memory msg=66072 rrset=66072 infra=5224 val=0 subnet=0
Nov 30 11:26:51 NickDeb unbound: [106181:0] info: start of service (unbound 1.6.8).
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: 172.16.198.20 mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: udp request from ip4 172.16.198.20 port 47861 (len 16)
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: mesh_run: start
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: process_request: new external request event
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: iter_handle processing q with state INIT REQUEST STATE
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: resolving mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: request has dependency depth of 0
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: use stub mytest. NS IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: cache delegation returns delegpt
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: DelegationPoint<mytest.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug:    ip4 172.20.0.1 port 53 (len 16)
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: resolving (init part 2):  mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: use stub mytest. NS IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: resolving (init part 3):  mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: processQueryTargets: mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: DelegationPoint<mytest.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug:    ip4 172.20.0.1 port 53 (len 16)
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: attempt to get extra 3 targets
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: selrtt 376
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: sending query: mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: sending to target: <mytest.> 172.20.0.1#53
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: dnssec status: not expected
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: EDNS lookup known=0 vs=0
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: serviced query UDP timeout=376 msec
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: inserted new pending reply id=9053
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: opened UDP if=0 port=24396
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: comm point start listening 12
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: mesh_run: iterator module exit state is module_wait_reply
Nov 30 11:27:19 NickDeb unbound: [106181: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
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: 0RDd mod0 rep mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: cache memory msg=66072 rrset=66072 infra=5528 val=0 subnet=0
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: answer cb
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: Incoming reply id = 9053
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: Incoming reply addr = ip4 172.20.0.1 port 53 (len 16)
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: lookup size is 1 entries
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: received udp reply.
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: udp message[83:0] 905384900001000000010002066D7974657374076578616D706C65066D79746573740000010001C00C00020001000151800005026E73C00CC03300010001000151800004AC1500010000291000000080000000
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: outnet handle udp reply
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: serviced query: EDNS works for ip4 172.20.0.1 port 53 (len 16)
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: measured roundtrip at 1 msec
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: svcd callbacks start
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: worker svcd callback for qstate 0x559339a1f890
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: mesh_run: start
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_reply
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: iterator operate: query mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: process_response: new external response event
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: scrub for mytest. NS IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: response for mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: reply from <mytest.> 172.20.0.1#53
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr aa ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1 #012;; QUESTION SECTION:#012mytest.example.mytest.#011IN#011A#012#012;; ANSWER SECTION:#012#012;; AUTHORITY SECTION:#012mytest.example.mytest.#01186400#011IN#011NS#011ns.mytest.example.mytest.#012#012;; ADDITIONAL SECTION:#012ns.mytest.example.mytest.#01186400#011IN#011A#011172.21.0.1#012;; MSG SIZE  rcvd: 72
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: query response was REFERRAL
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: found in cache ns.mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: DelegationPoint<mytest.example.mytest.>: 1 names (1 missing), 1 addrs (0 result, 1 avail) parentNS
Nov 30 11:27:19 NickDeb unbound: [106181:0] info:   ns.mytest.example.mytest.  A
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug:    ip4 172.21.0.1 port 53 (len 16)
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: cleared outbound list for next round
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: processQueryTargets: mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: DelegationPoint<mytest.example.mytest.>: 1 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
Nov 30 11:27:19 NickDeb unbound: [106181:0] info:   ns.mytest.example.mytest. * A
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug:    ip4 172.21.0.1 port 53 (len 16)
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: attempt to get extra 3 targets
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: selrtt 376
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: sending query: mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: sending to target: <mytest.example.mytest.> 172.21.0.1#53
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: dnssec status: not expected
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: EDNS lookup known=0 vs=0
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: serviced query UDP timeout=376 msec
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: inserted new pending reply id=374b
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: opened UDP if=0 port=26777
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: comm point start listening 13
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: mesh_run: iterator module exit state is module_wait_reply
Nov 30 11:27:19 NickDeb unbound: [106181: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
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: 0RDd mod0 rep mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: cache memory msg=66072 rrset=66587 infra=5847 val=0 subnet=0
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: svcd callbacks end
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: close of port 24396
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: close fd 12
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: timeout udp
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: try edns1xx0 <mytest.example.mytest.> 172.21.0.1#53
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: EDNS lookup known=0 vs=0
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: serviced query UDP timeout=376 msec
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: inserted new pending reply id=a9b1
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: opened UDP if=0 port=21864
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: comm point start listening 12
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: close of port 26777
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: close fd 13
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: timeout udp
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: svcd callbacks start
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: worker svcd callback for qstate 0x559339a1f890
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: mesh_run: start
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: iterator operate: query mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: process_response: new external response event
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: query response was timeout
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: processQueryTargets: mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 1
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: DelegationPoint<mytest.example.mytest.>: 1 names (0 missing), 1 addrs (1 result, 0 avail) parentNS
Nov 30 11:27:19 NickDeb unbound: [106181:0] info:   ns.mytest.example.mytest. * A
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug:    ip4 172.21.0.1 port 53 (len 16)
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: attempt to get extra 3 targets
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: servselect ip4 172.21.0.1 port 53 (len 16)
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug:    rtt=752
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: selrtt 752
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: sending query: mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: sending to target: <mytest.example.mytest.> 172.21.0.1#53
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: dnssec status: not expected
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: EDNS lookup known=0 vs=0
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: serviced query UDP timeout=752 msec
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: inserted new pending reply id=ad53
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: opened UDP if=0 port=64334
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: comm point start listening 13
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: mesh_run: iterator module exit state is module_wait_reply
Nov 30 11:27:19 NickDeb unbound: [106181: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
Nov 30 11:27:19 NickDeb unbound: [106181:0] info: 0RDd mod0 rep mytest.example.mytest. A IN
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: cache memory msg=66072 rrset=66587 infra=5847 val=0 subnet=0
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: svcd callbacks end
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: close of port 21864
Nov 30 11:27:19 NickDeb unbound: [106181:0] debug: close fd 12
Nov 30 11:27:20 NickDeb unbound: [106181:0] debug: timeout udp
Nov 30 11:27:20 NickDeb unbound: [106181:0] debug: try edns1xx0 <mytest.example.mytest.> 172.21.0.1#53
Nov 30 11:27:20 NickDeb unbound: [106181:0] debug: EDNS lookup known=0 vs=0
Nov 30 11:27:20 NickDeb unbound: [106181:0] debug: serviced query UDP timeout=752 msec
Nov 30 11:27:20 NickDeb unbound: [106181:0] debug: inserted new pending reply id=4e14
Nov 30 11:27:20 NickDeb unbound: [106181:0] debug: opened UDP if=0 port=65316
Nov 30 11:27:20 NickDeb unbound: [106181:0] debug: comm point start listening 12
Nov 30 11:27:20 NickDeb unbound: [106181:0] debug: close of port 64334
Nov 30 11:27:20 NickDeb unbound: [106181:0] debug: close fd 13
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: timeout udp
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: svcd callbacks start
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: worker svcd callback for qstate 0x559339a1f890
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: mesh_run: start
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Nov 30 11:27:21 NickDeb unbound: [106181:0] info: iterator operate: query mytest.example.mytest. A IN
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: process_response: new external response event
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: query response was timeout
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Nov 30 11:27:21 NickDeb unbound: [106181:0] info: processQueryTargets: mytest.example.mytest. A IN
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 2
Nov 30 11:27:21 NickDeb unbound: [106181:0] info: DelegationPoint<mytest.example.mytest.>: 1 names (0 missing), 1 addrs (1 result, 0 avail) parentNS
Nov 30 11:27:21 NickDeb unbound: [106181:0] info:   ns.mytest.example.mytest. * A
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug:    ip4 172.21.0.1 port 53 (len 16)
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: attempt to get extra 3 targets
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: servselect ip4 172.21.0.1 port 53 (len 16)
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug:    rtt=1504
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: selrtt 1504
Nov 30 11:27:21 NickDeb unbound: [106181:0] info: sending query: mytest.example.mytest. A IN
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: sending to target: <mytest.example.mytest.> 172.21.0.1#53
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: dnssec status: not expected
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: EDNS lookup known=0 vs=0
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: serviced query UDP timeout=1504 msec
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: inserted new pending reply id=80e1
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: opened UDP if=0 port=33423
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: comm point start listening 13
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: mesh_run: iterator module exit state is module_wait_reply
Nov 30 11:27:21 NickDeb unbound: [106181: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
Nov 30 11:27:21 NickDeb unbound: [106181:0] info: 0RDd mod0 rep mytest.example.mytest. A IN
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: cache memory msg=66072 rrset=66587 infra=5847 val=0 subnet=0
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: svcd callbacks end
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: close of port 65316
Nov 30 11:27:21 NickDeb unbound: [106181:0] debug: close fd 12
Nov 30 11:27:22 NickDeb unbound: [106181:0] debug: timeout udp
Nov 30 11:27:22 NickDeb unbound: [106181:0] debug: try edns1xx0 <mytest.example.mytest.> 172.21.0.1#53
Nov 30 11:27:22 NickDeb unbound: [106181:0] debug: EDNS lookup known=0 vs=0
Nov 30 11:27:22 NickDeb unbound: [106181:0] debug: serviced query UDP timeout=1504 msec
Nov 30 11:27:22 NickDeb unbound: [106181:0] debug: inserted new pending reply id=9fa0
Nov 30 11:27:22 NickDeb unbound: [106181:0] debug: opened UDP if=0 port=30071
Nov 30 11:27:22 NickDeb unbound: [106181:0] debug: comm point start listening 12
Nov 30 11:27:22 NickDeb unbound: [106181:0] debug: close of port 33423
Nov 30 11:27:22 NickDeb unbound: [106181:0] debug: close fd 13
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: timeout udp
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: svcd callbacks start
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: worker svcd callback for qstate 0x559339a1f890
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: mesh_run: start
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Nov 30 11:27:24 NickDeb unbound: [106181:0] info: iterator operate: query mytest.example.mytest. A IN
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: process_response: new external response event
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: query response was timeout
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Nov 30 11:27:24 NickDeb unbound: [106181:0] info: processQueryTargets: mytest.example.mytest. A IN
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 3
Nov 30 11:27:24 NickDeb unbound: [106181:0] info: DelegationPoint<mytest.example.mytest.>: 1 names (0 missing), 1 addrs (1 result, 0 avail) parentNS
Nov 30 11:27:24 NickDeb unbound: [106181:0] info:   ns.mytest.example.mytest. * A
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug:    ip4 172.21.0.1 port 53 (len 16)
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: servselect ip4 172.21.0.1 port 53 (len 16)
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug:    rtt=3008
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: selrtt 3008
Nov 30 11:27:24 NickDeb unbound: [106181:0] info: sending query: mytest.example.mytest. A IN
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: sending to target: <mytest.example.mytest.> 172.21.0.1#53
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: dnssec status: not expected
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: EDNS lookup known=0 vs=0
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: serviced query UDP timeout=3008 msec
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: inserted new pending reply id=10f6
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: opened UDP if=0 port=58840
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: comm point start listening 13
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: mesh_run: iterator module exit state is module_wait_reply
Nov 30 11:27:24 NickDeb unbound: [106181: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
Nov 30 11:27:24 NickDeb unbound: [106181:0] info: 0RDd mod0 rep mytest.example.mytest. A IN
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: cache memory msg=66072 rrset=66587 infra=5847 val=0 subnet=0
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: svcd callbacks end
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: close of port 30071
Nov 30 11:27:24 NickDeb unbound: [106181:0] debug: close fd 12
Nov 30 11:27:27 NickDeb unbound: [106181:0] debug: timeout udp
Nov 30 11:27:27 NickDeb unbound: [106181:0] debug: try edns1xx0 <mytest.example.mytest.> 172.21.0.1#53
Nov 30 11:27:27 NickDeb unbound: [106181:0] debug: EDNS lookup known=0 vs=0
Nov 30 11:27:27 NickDeb unbound: [106181:0] debug: serviced query UDP timeout=3008 msec
Nov 30 11:27:27 NickDeb unbound: [106181:0] debug: inserted new pending reply id=790d
Nov 30 11:27:27 NickDeb unbound: [106181:0] debug: opened UDP if=0 port=14470
Nov 30 11:27:27 NickDeb unbound: [106181:0] debug: comm point start listening 12
Nov 30 11:27:27 NickDeb unbound: [106181:0] debug: close of port 58840
Nov 30 11:27:27 NickDeb unbound: [106181:0] debug: close fd 13
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: timeout udp
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: svcd callbacks start
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: worker svcd callback for qstate 0x559339a1f890
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: mesh_run: start
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Nov 30 11:27:30 NickDeb unbound: [106181:0] info: iterator operate: query mytest.example.mytest. A IN
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: process_response: new external response event
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: query response was timeout
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Nov 30 11:27:30 NickDeb unbound: [106181:0] info: processQueryTargets: mytest.example.mytest. A IN
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 4
Nov 30 11:27:30 NickDeb unbound: [106181:0] info: DelegationPoint<mytest.example.mytest.>: 1 names (0 missing), 1 addrs (1 result, 0 avail) parentNS
Nov 30 11:27:30 NickDeb unbound: [106181:0] info:   ns.mytest.example.mytest. * A
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug:    ip4 172.21.0.1 port 53 (len 16)
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: servselect ip4 172.21.0.1 port 53 (len 16)
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug:    rtt=6016
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: selrtt 6016
Nov 30 11:27:30 NickDeb unbound: [106181:0] info: sending query: mytest.example.mytest. A IN
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: sending to target: <mytest.example.mytest.> 172.21.0.1#53
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: dnssec status: not expected
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: EDNS lookup known=0 vs=0
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: serviced query: send probe to see  if use of EDNS causes timeouts
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: serviced query UDP timeout=1000 msec
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: inserted new pending reply id=8c69
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: opened UDP if=0 port=27970
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: comm point start listening 13
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: mesh_run: iterator module exit state is module_wait_reply
Nov 30 11:27:30 NickDeb unbound: [106181: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
Nov 30 11:27:30 NickDeb unbound: [106181:0] info: 0RDd mod0 rep mytest.example.mytest. A IN
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: cache memory msg=66072 rrset=66587 infra=5847 val=0 subnet=0
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: svcd callbacks end
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: close of port 14470
Nov 30 11:27:30 NickDeb unbound: [106181:0] debug: close fd 12
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: timeout udp
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: svcd callbacks start
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: worker svcd callback for qstate 0x559339a1f890
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: mesh_run: start
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: iterator operate: query mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: process_response: new external response event
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: query response was timeout
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: processQueryTargets: mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 5
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: DelegationPoint<mytest.example.mytest.>: 1 names (0 missing), 1 addrs (0 result, 0 avail) parentNS
Nov 30 11:27:31 NickDeb unbound: [106181:0] info:   ns.mytest.example.mytest. * A
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug:    ip4 172.21.0.1 port 53 (len 16)
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: No more query targets, attempting last resort
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: found in cache ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: new pside target ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: try parent-side glue lookup
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: mesh_run: iterator module exit state is module_wait_subquery
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_pass
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: iterator operate: query ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: iter_handle processing q with state INIT REQUEST STATE
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: resolving ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: request has dependency depth of 1
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: cache blacklisted, going to the network
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: use stub mytest. NS IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: cache delegation returns delegpt
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: DelegationPoint<mytest.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug:    ip4 172.20.0.1 port 53 (len 16)
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: resolving (init part 2):  ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: resolving (init part 3):  ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: processQueryTargets: ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: DelegationPoint<mytest.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug:    ip4 172.20.0.1 port 53 (len 16)
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: attempt to get extra 2 targets
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: servselect ip4 172.20.0.1 port 53 (len 16)
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug:    rtt=284
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: selrtt 284
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: sending query: ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: sending to target: <mytest.> 172.20.0.1#53
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: dnssec status: not expected
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: EDNS lookup known=1 vs=0
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: serviced query UDP timeout=284 msec
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: inserted new pending reply id=da8c
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: opened UDP if=0 port=56884
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: comm point start listening 12
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: mesh_run: iterator module exit state is module_wait_reply
Nov 30 11:27:31 NickDeb unbound: [106181: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
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: 0vRDCD mod0  ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: 1RDdc mod0 rep mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: cache memory msg=66072 rrset=66587 infra=5847 val=0 subnet=0
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: svcd callbacks end
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: close of port 27970
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: close fd 13
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: answer cb
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: Incoming reply id = da8c
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: Incoming reply addr = ip4 172.20.0.1 port 53 (len 16)
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: lookup size is 1 entries
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: received udp reply.
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: udp message[69:0] DA8C84900001000100000001026E73066D7974657374076578616D706C65066D79746573740000010001C00C00010001000151800004AC1500010000291000000080000000
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: outnet handle udp reply
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: measured roundtrip at 0 msec
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: svcd callbacks start
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: worker svcd callback for qstate 0x559339a1b880
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: mesh_run: start
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_reply
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: iterator operate: query ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: process_response: new external response event
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: scrub for mytest. NS IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: response for ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: reply from <mytest.> 172.20.0.1#53
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0#012;; flags: qr aa ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0 #012;; QUESTION SECTION:#012ns.mytest.example.mytest.#011IN#011A#012#012;; ANSWER SECTION:#012ns.mytest.example.mytest.#01186400#011IN#011A#011172.21.0.1#012#012;; AUTHORITY SECTION:#012#012;; ADDITIONAL SECTION:#012;; MSG SIZE  rcvd: 58
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: query response was ANSWER
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: finishing processing for ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: store parent-side negative ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: mesh_run: iterator module exit state is module_finished
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: processTargetResponse ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: processTargetResponse super mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: added target response
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: DelegationPoint<mytest.example.mytest.>: 1 names (0 missing), 1 addrs (0 result, 0 avail) parentNS
Nov 30 11:27:31 NickDeb unbound: [106181:0] info:   ns.mytest.example.mytest. * A PSIDE_A
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug:    ip4 172.21.0.1 port 53 (len 16)
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: iterator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: iterator operate: query mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: processQueryTargets: mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 5
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: DelegationPoint<mytest.example.mytest.>: 1 names (0 missing), 1 addrs (0 result, 0 avail) parentNS
Nov 30 11:27:31 NickDeb unbound: [106181:0] info:   ns.mytest.example.mytest. * A PSIDE_A
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug:    ip4 172.21.0.1 port 53 (len 16)
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: No more query targets, attempting last resort
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: found in cache ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: found parent-side ns.mytest.example.mytest. A IN
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: out of query targets -- returning SERVFAIL
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: store error response in message cache
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: return error response SERVFAIL
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: mesh_run: iterator module exit state is module_finished
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: query took 12.301053 sec
Nov 30 11:27:31 NickDeb unbound: [106181: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
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: average recursion processing time 12.301053 sec
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: histogram of recursion processing times
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: [25%]=0 median[50%]=0 [75%]=0
Nov 30 11:27:31 NickDeb unbound: [106181:0] info: lower(secs) upper(secs) recursions
Nov 30 11:27:31 NickDeb unbound: [106181:0] info:    8.000000   16.000000 1
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: cache memory msg=66561 rrset=66831 infra=5847 val=0 subnet=0
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: svcd callbacks end
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: close of port 56884
Nov 30 11:27:31 NickDeb unbound: [106181:0] debug: close fd 12
