{"action":"created","issue":{"url":"https://api.github.com/repos/PowerDNS/pdns/issues/2344","labels_url":"https://api.github.com/repos/PowerDNS/pdns/issues/2344/labels{/name}","comments_url":"https://api.github.com/repos/PowerDNS/pdns/issues/2344/comments","events_url":"https://api.github.com/repos/PowerDNS/pdns/issues/2344/events","html_url":"https://github.com/PowerDNS/pdns/issues/2344","id":60503895,"number":2344,"title":"\"signature crypto failed\" on pre-signed root zone (.) served by Auth","user":{"login":"jpmens","id":60706,"avatar_url":"https://avatars.githubusercontent.com/u/60706?v=3","gravatar_id":"","url":"https://api.github.com/users/jpmens","html_url":"https://github.com/jpmens","followers_url":"https://api.github.com/users/jpmens/followers","following_url":"https://api.github.com/users/jpmens/following{/other_user}","gists_url":"https://api.github.com/users/jpmens/gists{/gist_id}","starred_url":"https://api.github.com/users/jpmens/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jpmens/subscriptions","organizations_url":"https://api.github.com/users/jpmens/orgs","repos_url":"https://api.github.com/users/jpmens/repos","events_url":"https://api.github.com/users/jpmens/events{/privacy}","received_events_url":"https://api.github.com/users/jpmens/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":6,"created_at":"2015-03-10T14:04:37Z","updated_at":"2015-03-10T14:34:25Z","closed_at":null,"body":"PowerDNS auth 3.4.3\r\n\r\nBoth BIND and Unbound fail to validate a pre-signed root zone served by PowerDNS auth with the following (full Unbound log below):\r\n\r\n```\r\n[1425993073] unbound[25511:0] info: validator: response has failed AUTHORITY rrset: ns1.example.com. NSEC IN\r\n[1425993073] unbound[25511:0] info: Validate: message contains bad rrsets\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_FINISHED_STATE\r\n[1425993073] unbound[25511:0] info: validation failure <kdkdkdkkUNBOUND. A IN>: signature crypto failed for <ns1.example.com. NSEC IN> from 100.96.1.8\r\n\r\n```\r\n\r\nPowerDNS is a slave to a signer (in this example BIND) and successfully transfers a zone in. This zone can be queried and also transferred out, and all appears to be okay. Incidentally, an outgoing XFR from PowerDNS is sucessfully validated by `ldns-verify-zone`.\r\n\r\n```\r\n+-------------+                         +--------------+\r\n|             |                         |              |\r\n|    BIND     |              XFR        |   PDNS       |\r\n|             +------------------------->              |\r\n|             |                         |              |\r\n+------^------+                         +--------^-----+\r\n       |                                         |      \r\n       |                                         |      \r\n       |                                         |      \r\n       |                                         |      \r\n       |                                         |      \r\n       |   path (A)                      path (B)|      \r\n       |                                         |      \r\n       +-----------------+-----------+-----------+      \r\n                         |           |                  \r\n                         |  Unbound  |                  \r\n                         |           |                  \r\n                         |           |                  \r\n                         +-----------+                  \r\n```\r\n\r\n1. If the lower _unbound_ is configured to take path (A), i.e. query the BIND server directly, validation succeeds.\r\n2. If, on the other hand, Unbound queries path (B), i.e. PowerDNS which has slaved the root zone, validation fails.\r\n\r\n(In this particular case by \"configure Unbound to\", I have had BIND and PowerDNS listening on the correct IP address alternatively.)\r\n\r\nReplacing the lower _Unbound_ by _BIND_ also produces validation errors.\r\n\r\n\r\n#### `unbound.conf`\r\n\r\n```\r\nserver:\r\n\tverbosity: 1\r\n\tport: 5353\r\n\tdo-ip4: yes\r\n\tdo-ip6: no\r\n\taccess-control: 0.0.0.0/0 allow\r\n\tchroot: \"\"\r\n\tusername: \"\"\r\n\tdirectory: \"/tmp/unbound/etc/unbound\"\r\n\tlogfile: \"/tmp/unbound/etc/unbound/unbound.log\"\r\n\tuse-syslog: no \r\n\troot-hints: \"jpm.hints\"\r\n\ttrust-anchor: \". IN DNSKEY 257 3 5 AwEAAarSRUAN4R4KZcwepDCor+j+yyj1Yq/nMUHZYB4cngUNZNAfgQ3g udSqsJ1MN7b41ElROzFgsb0NnnblEsruSADpiJEmtLqYkdIyhVUNSs7Y i7O16F0Yd7/ZMbiWjglmhMa6VzdQlsRHzO8W8w1lsgEJpMT8oUma71fj QRQPxRxpA5sYgLpsxrM3eJ/wMoWcKEhH2r65nguHRnjn2MD+8RHfuGuS EbNaa7Rz8Yd+jHYtcdAB65MrFktbUNgvNOqwFD6qOr1Mx3hYc3TTA5x0 1kZMnXmIEIcfLZ8nSjv7km9UKTdEJOvtGaxinu3MjHc4Q8nPKzNzylNp ynU3DNq4ZKs=\"\r\n\tval-log-level: 2\r\n```\r\n\r\n```\r\n$ cat jpm.hints\r\n.       3600000     NS      ns1.example.com.\r\nns1.example.com. 3600000 IN A    100.96.1.8\r\n```\r\n\r\n\r\n#### AXFR from BIND (signed)\r\n\r\n```\r\n.                       300     IN      SOA     ns1.example.com. hostmaster.example.com. 105 1800 1800 1814400 3600\r\n.                       300     IN      RRSIG   A 5 0 300 20150409130934 20150310120934 46980 . F3w8fxl7Awmc6vHRWwADEeBuxRQzYK5WHStC/rsI5LMH7aHAV0eN8HUg O7ret2DEclxj3Ew0g0JPhKmYYRVPQHsb/8j29IpJ3R6tcRTm6sjHvnDd sIiHaL9fKXXQ56T1xwK3UdEPTouZLZkgdb+ytOT42/jgtY1cKqEY+MXo hXk=\r\n.                       300     IN      RRSIG   TXT 5 0 300 20150409130934 20150310120934 46980 . FhqgGzD5DyO6dm3uaPNqYjvbM4QoYyj7w0gCMFQ0WNEj/fkk2JOnyAKT kuxAwmv5mYKf0gYU1CbgL1JN4DWftb0r2CnHjiRTtpL4FsFm87b73iqc 99/IiOmZ0Fw7PNz3xh/7gpykcW+M6GNi+wcd/gD8bbo+dKTeGhW6+yP3 /dI=\r\n.                       300     IN      TXT     \"BIND inline-signed, xfr-out to PowerDNS 3.4.3 (jenkins@autotest.powerdns.com built 20150302135804)\"\r\n.                       300     IN      A       127.0.0.1\r\n.                       3600    IN      NSEC    ns1.example.com. A NS SOA TXT RRSIG NSEC DNSKEY\r\n.                       3600    IN      RRSIG   NSEC 5 0 3600 20150409130934 20150310120934 46980 . oBrCbGV5jxywIlGkI8GzZ8aG/WaeFjfFBu554SXhrIUD83jZGX0gemzH jtb8GBpYChwRbf6zX8jsfEdOcio2tvI11qUEoThmSatMT86yEjk6I77e BhaJ+mNW3Z3Sp9vj79eKLUf1l7Siw/9tzL8fwE6Nlh4KUJsjA/aawnkL HQY=\r\n.                       300     IN      RRSIG   NS 5 0 300 20150409121329 20150310120027 46980 . M/7NJ1J3JNOkN0ts2vu+xjlibu7H/QaeD98cn25oP/+yQ51kopXFg8Tw Ia3uhizDayekQtgzxEKS0FO35cAgVIrXJT53ZgFQkrNpdsChYsijurk3 +Sy5fkxGRpGpPV+VPv7AAzaKHSG0WsE/1gdSs6PsqV2qczkCc6lNlSBL 2hQ=\r\n.                       300     IN      NS      ns1.example.com.\r\n.                       300     IN      DNSKEY  256 3 5 AwEAAaeqjSUmwbeNHKuXT/xw857JCh6bK40o+QMCmWluKok3AspfK6kL w6UPCzoK4cUlfCLuIlYChXeYRSTdMz1gXkiTSMfjIn80FBMb2YWRC2Xa Pk21IFbH6AOMb0cw4MsL5pFlCntYdu6Hj0LQBvMEjUmJWR/WFwC1nvNp W66K7PLd\r\n.                       300     IN      DNSKEY  257 3 5 AwEAAarSRUAN4R4KZcwepDCor+j+yyj1Yq/nMUHZYB4cngUNZNAfgQ3g udSqsJ1MN7b41ElROzFgsb0NnnblEsruSADpiJEmtLqYkdIyhVUNSs7Y i7O16F0Yd7/ZMbiWjglmhMa6VzdQlsRHzO8W8w1lsgEJpMT8oUma71fj QRQPxRxpA5sYgLpsxrM3eJ/wMoWcKEhH2r65nguHRnjn2MD+8RHfuGuS EbNaa7Rz8Yd+jHYtcdAB65MrFktbUNgvNOqwFD6qOr1Mx3hYc3TTA5x0 1kZMnXmIEIcfLZ8nSjv7km9UKTdEJOvtGaxinu3MjHc4Q8nPKzNzylNp ynU3DNq4ZKs=\r\n.                       300     IN      RRSIG   DNSKEY 5 0 300 20150409130027 20150310120027 21481 . LTbqj/T7UEKL9irEAMVoj/PKfNFdgYwpA8f4ImfuW5aluWd1sjXbgOkF L8+PJ4jspwjfXw6v4C7Qn10QXrF1nW+cbrWQSLVsFR8JhOsU4v0j/xjG E0leXe7OWuSilZcYr/MICEOJ36pHuHznTBiT1PBXGZOJaWkmW2gCiPT7 /jNcwj+FJMTxFQYFxWadb1hUywdDQ7WYH9EbVri2nFS5kV3zhbMBQYK4 8qEQ9a0uffEbkPpUPBU4fQJKPGDOXi4ikCIpuUfQKiC35o1XWdACQQ0v J4S+vH5Oz6gkEwjqldcAObdLJ8mJDcbn/7TfoBuGdofgdAPJ1/Yqp/M7 Rtz6IQ==\r\n.                       300     IN      RRSIG   DNSKEY 5 0 300 20150409130027 20150310120027 46980 . KnlbysltVGFLcp5Wr16US221wHpf/NATGnaGedmnfFFKewwRltvVHMFJ DO2revTe6HAf4AEO+6NTZr1UCJ1O2EdKWePJzdMDsmuvPxBviRlRyKW+ A56mQlq/JgtPfebLJC5pfMpMZEjhfKliUnWy//bgyHzU+A7ayMgJs6pU Pig=\r\n.                       300     IN      RRSIG   SOA 5 0 300 20150409130934 20150310120934 46980 . cAfAkcQLs7Am5bdFCYn2wV141E8Cq85jd65x43/zBEKTZgwBslVn9wDi hTYyrXnbpiGkgmqZTpmh/LGJs1FnLjYXvdh1K+09uk/5YWKRK0wknKxJ 79xPkPegJjmrveGG2jxZD9i42KcgRX6ilaz7jEPLenzKuGoOO70DvN52 2q4=\r\nns1.example.com.        3600    IN      NSEC    . A RRSIG NSEC\r\nns1.example.com.        300     IN      RRSIG   A 5 3 300 20150409121329 20150310120027 46980 . WYE3z/2pijqd8ks4dQHLZUAHFTx1CgEKtqTKIqMpKvdB5JslxPjEHnkO 4paF7OH02WkFnbc1kamBmJwFUzUnM2q4jIx3NpLwKCWPU2ElZX26pSpq +DbOOiT6ixTgS/eHth9X3Pbd3nGF2pde5xhFnlHzAbLDORcZUNT8Iw8e zZ0=\r\nns1.example.com.        3600    IN      RRSIG   NSEC 5 3 3600 20150409121329 20150310120027 46980 . b2CYfX7Ea4CfoaGOngG/t2YZnCZxfwDovePA3jCFisHLuMr9j8TuiSjV 1N50M5pcxZIE3UPp5gTskyp4FJ1FD+KrTJdbpxZIGlZi9ONL72gXhacW /GT2MvoyPx3LcFdweErEGR8StErQ8UCjBKZm58Thl1fH/N1no8xnIJ7+ 9/A=\r\nns1.example.com.        300     IN      A       100.96.1.8\r\n```\r\n\r\n#### AXFR from BIND (multiline)\r\n\r\n```\r\n.                       300 IN SOA ns1.example.com. hostmaster.example.com. (\r\n                                105        ; serial\r\n                                1800       ; refresh (30 minutes)\r\n                                1800       ; retry (30 minutes)\r\n                                1814400    ; expire (3 weeks)\r\n                                3600       ; minimum (1 hour)\r\n                                )\r\n.                       300 IN RRSIG A 5 0 300 (\r\n                                20150409130934 20150310120934 46980 .\r\n                                F3w8fxl7Awmc6vHRWwADEeBuxRQzYK5WHStC/rsI5LMH\r\n                                7aHAV0eN8HUgO7ret2DEclxj3Ew0g0JPhKmYYRVPQHsb\r\n                                /8j29IpJ3R6tcRTm6sjHvnDdsIiHaL9fKXXQ56T1xwK3\r\n                                UdEPTouZLZkgdb+ytOT42/jgtY1cKqEY+MXohXk= )\r\n.                       300 IN RRSIG TXT 5 0 300 (\r\n                                20150409130934 20150310120934 46980 .\r\n                                FhqgGzD5DyO6dm3uaPNqYjvbM4QoYyj7w0gCMFQ0WNEj\r\n                                /fkk2JOnyAKTkuxAwmv5mYKf0gYU1CbgL1JN4DWftb0r\r\n                                2CnHjiRTtpL4FsFm87b73iqc99/IiOmZ0Fw7PNz3xh/7\r\n                                gpykcW+M6GNi+wcd/gD8bbo+dKTeGhW6+yP3/dI= )\r\n.                       300 IN TXT \"BIND inline-signed, xfr-out to PowerDNS 3.4.3 (jenkins@autotest.powerdns.com built 20150302135804)\"\r\n.                       300 IN A 127.0.0.1\r\n.                       3600 IN NSEC ns1.example.com. A NS SOA TXT RRSIG NSEC DNSKEY\r\n\r\n.                       3600 IN RRSIG NSEC 5 0 3600 (\r\n                                20150409130934 20150310120934 46980 .\r\n                                oBrCbGV5jxywIlGkI8GzZ8aG/WaeFjfFBu554SXhrIUD\r\n                                83jZGX0gemzHjtb8GBpYChwRbf6zX8jsfEdOcio2tvI1\r\n                                1qUEoThmSatMT86yEjk6I77eBhaJ+mNW3Z3Sp9vj79eK\r\n                                LUf1l7Siw/9tzL8fwE6Nlh4KUJsjA/aawnkLHQY= )\r\n.                       300 IN RRSIG NS 5 0 300 (\r\n                                20150409121329 20150310120027 46980 .\r\n                                M/7NJ1J3JNOkN0ts2vu+xjlibu7H/QaeD98cn25oP/+y\r\n                                Q51kopXFg8TwIa3uhizDayekQtgzxEKS0FO35cAgVIrX\r\n                                JT53ZgFQkrNpdsChYsijurk3+Sy5fkxGRpGpPV+VPv7A\r\n                                AzaKHSG0WsE/1gdSs6PsqV2qczkCc6lNlSBL2hQ= )\r\n.                       300 IN NS ns1.example.com.\r\n.                       300 IN DNSKEY 256 3 5 (\r\n                                AwEAAaeqjSUmwbeNHKuXT/xw857JCh6bK40o+QMCmWlu\r\n                                Kok3AspfK6kLw6UPCzoK4cUlfCLuIlYChXeYRSTdMz1g\r\n                                XkiTSMfjIn80FBMb2YWRC2XaPk21IFbH6AOMb0cw4MsL\r\n                                5pFlCntYdu6Hj0LQBvMEjUmJWR/WFwC1nvNpW66K7PLd\r\n                                ) ; ZSK; alg = RSASHA1; key id = 46980\r\n.                       300 IN DNSKEY 257 3 5 (\r\n                                AwEAAarSRUAN4R4KZcwepDCor+j+yyj1Yq/nMUHZYB4c\r\n                                ngUNZNAfgQ3gudSqsJ1MN7b41ElROzFgsb0NnnblEsru\r\n                                SADpiJEmtLqYkdIyhVUNSs7Yi7O16F0Yd7/ZMbiWjglm\r\n                                hMa6VzdQlsRHzO8W8w1lsgEJpMT8oUma71fjQRQPxRxp\r\n                                A5sYgLpsxrM3eJ/wMoWcKEhH2r65nguHRnjn2MD+8RHf\r\n                                uGuSEbNaa7Rz8Yd+jHYtcdAB65MrFktbUNgvNOqwFD6q\r\n                                Or1Mx3hYc3TTA5x01kZMnXmIEIcfLZ8nSjv7km9UKTdE\r\n                                JOvtGaxinu3MjHc4Q8nPKzNzylNpynU3DNq4ZKs=\r\n                                ) ; KSK; alg = RSASHA1; key id = 21481\r\n.                       300 IN RRSIG DNSKEY 5 0 300 (\r\n                                20150409130027 20150310120027 21481 .\r\n                                LTbqj/T7UEKL9irEAMVoj/PKfNFdgYwpA8f4ImfuW5al\r\n                                uWd1sjXbgOkFL8+PJ4jspwjfXw6v4C7Qn10QXrF1nW+c\r\n                                brWQSLVsFR8JhOsU4v0j/xjGE0leXe7OWuSilZcYr/MI\r\n                                CEOJ36pHuHznTBiT1PBXGZOJaWkmW2gCiPT7/jNcwj+F\r\n                                JMTxFQYFxWadb1hUywdDQ7WYH9EbVri2nFS5kV3zhbMB\r\n                                QYK48qEQ9a0uffEbkPpUPBU4fQJKPGDOXi4ikCIpuUfQ\r\n                                KiC35o1XWdACQQ0vJ4S+vH5Oz6gkEwjqldcAObdLJ8mJ\r\n                                Dcbn/7TfoBuGdofgdAPJ1/Yqp/M7Rtz6IQ== )\r\n.                       300 IN RRSIG DNSKEY 5 0 300 (\r\n                                20150409130027 20150310120027 46980 .\r\n                                KnlbysltVGFLcp5Wr16US221wHpf/NATGnaGedmnfFFK\r\n                                ewwRltvVHMFJDO2revTe6HAf4AEO+6NTZr1UCJ1O2EdK\r\n                                WePJzdMDsmuvPxBviRlRyKW+A56mQlq/JgtPfebLJC5p\r\n                                fMpMZEjhfKliUnWy//bgyHzU+A7ayMgJs6pUPig= )\r\n.                       300 IN RRSIG SOA 5 0 300 (\r\n                                20150409130934 20150310120934 46980 .\r\n                                cAfAkcQLs7Am5bdFCYn2wV141E8Cq85jd65x43/zBEKT\r\n                                ZgwBslVn9wDihTYyrXnbpiGkgmqZTpmh/LGJs1FnLjYX\r\n                                vdh1K+09uk/5YWKRK0wknKxJ79xPkPegJjmrveGG2jxZ\r\n                                D9i42KcgRX6ilaz7jEPLenzKuGoOO70DvN522q4= )\r\nns1.example.com.        3600 IN NSEC . A RRSIG NSEC\r\nns1.example.com.        300 IN RRSIG A 5 3 300 (\r\n                                20150409121329 20150310120027 46980 .\r\n                                WYE3z/2pijqd8ks4dQHLZUAHFTx1CgEKtqTKIqMpKvdB\r\n                                5JslxPjEHnkO4paF7OH02WkFnbc1kamBmJwFUzUnM2q4\r\n                                jIx3NpLwKCWPU2ElZX26pSpq+DbOOiT6ixTgS/eHth9X\r\n                                3Pbd3nGF2pde5xhFnlHzAbLDORcZUNT8Iw8ezZ0= )\r\nns1.example.com.        3600 IN RRSIG NSEC 5 3 3600 (\r\n                                20150409121329 20150310120027 46980 .\r\n                                b2CYfX7Ea4CfoaGOngG/t2YZnCZxfwDovePA3jCFisHL\r\n                                uMr9j8TuiSjV1N50M5pcxZIE3UPp5gTskyp4FJ1FD+Kr\r\n                                TJdbpxZIGlZi9ONL72gXhacW/GT2MvoyPx3LcFdweErE\r\n                                GR8StErQ8UCjBKZm58Thl1fH/N1no8xnIJ7+9/A= )\r\nns1.example.com.        300 IN A 100.96.1.8\r\n\r\n```\r\n\r\n\r\n#### PowerDNS root zone in domains table\r\n\r\n```\r\n| 42 |                                | 127.0.0.1:53      | 1425993032 | SLAVE |            NULL | NULL    |\r\n```\r\n\r\n#### PowerDNS root zone in records table after XFR-in\r\n\r\n```\r\n)> select * from records where domain_id = 42;\r\n+--------+-----------+-----------------+--------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+------+-------------+----------+-----------------+------+\r\n| id     | domain_id | name            | type   | content                                                                                                                                                                                                                                                                                                                                                                                                       | ttl  | prio | change_date | disabled | ordername       | auth |\r\n+--------+-----------+-----------------+--------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+------+-------------+----------+-----------------+------+\r\n| 361770 |        42 |                 | SOA    | ns1.example.com. hostmaster.example.com. 105 1800 1800 1814400 3600                                                                                                                                                                                                                                                                                                                                           |  300 |    0 |        NULL |        0 |                 |    1 |\r\n| 361771 |        42 |                 | RRSIG  | A 5 0 300 20150409130934 20150310120934 46980 . F3w8fxl7Awmc6vHRWwADEeBuxRQzYK5WHStC/rsI5LMH7aHAV0eN8HUgO7ret2DEclxj3Ew0g0JPhKmYYRVPQHsb/8j29IpJ3R6tcRTm6sjHvnDdsIiHaL9fKXXQ56T1xwK3UdEPTouZLZkgdb+ytOT42/jgtY1cKqEY+MXohXk=                                                                                                                                                                                  |  300 |    0 |        NULL |        0 | NULL            |    1 |\r\n| 361772 |        42 |                 | RRSIG  | TXT 5 0 300 20150409130934 20150310120934 46980 . FhqgGzD5DyO6dm3uaPNqYjvbM4QoYyj7w0gCMFQ0WNEj/fkk2JOnyAKTkuxAwmv5mYKf0gYU1CbgL1JN4DWftb0r2CnHjiRTtpL4FsFm87b73iqc99/IiOmZ0Fw7PNz3xh/7gpykcW+M6GNi+wcd/gD8bbo+dKTeGhW6+yP3/dI=                                                                                                                                                                                |  300 |    0 |        NULL |        0 | NULL            |    1 |\r\n| 361773 |        42 |                 | TXT    | \"BIND inline-signed, xfr-out to PowerDNS 3.4.3 (jenkins@autotest.powerdns.com built 20150302135804)\"                                                                                                                                                                                                                                                                                                          |  300 |    0 |        NULL |        0 |                 |    1 |\r\n| 361774 |        42 |                 | A      | 127.0.0.1                                                                                                                                                                                                                                                                                                                                                                                                     |  300 |    0 |        NULL |        0 |                 |    1 |\r\n| 361775 |        42 |                 | RRSIG  | NSEC 5 0 3600 20150409130934 20150310120934 46980 . oBrCbGV5jxywIlGkI8GzZ8aG/WaeFjfFBu554SXhrIUD83jZGX0gemzHjtb8GBpYChwRbf6zX8jsfEdOcio2tvI11qUEoThmSatMT86yEjk6I77eBhaJ+mNW3Z3Sp9vj79eKLUf1l7Siw/9tzL8fwE6Nlh4KUJsjA/aawnkLHQY=                                                                                                                                                                              | 3600 |    0 |        NULL |        0 | NULL            |    1 |\r\n| 361776 |        42 |                 | RRSIG  | NS 5 0 300 20150409121329 20150310120027 46980 . M/7NJ1J3JNOkN0ts2vu+xjlibu7H/QaeD98cn25oP/+yQ51kopXFg8TwIa3uhizDayekQtgzxEKS0FO35cAgVIrXJT53ZgFQkrNpdsChYsijurk3+Sy5fkxGRpGpPV+VPv7AAzaKHSG0WsE/1gdSs6PsqV2qczkCc6lNlSBL2hQ=                                                                                                                                                                                 |  300 |    0 |        NULL |        0 | NULL            |    1 |\r\n| 361777 |        42 |                 | NS     | ns1.example.com                                                                                                                                                                                                                                                                                                                                                                                               |  300 |    0 |        NULL |        0 |                 |    1 |\r\n| 361778 |        42 |                 | DNSKEY | 256 3 5 AwEAAaeqjSUmwbeNHKuXT/xw857JCh6bK40o+QMCmWluKok3AspfK6kLw6UPCzoK4cUlfCLuIlYChXeYRSTdMz1gXkiTSMfjIn80FBMb2YWRC2XaPk21IFbH6AOMb0cw4MsL5pFlCntYdu6Hj0LQBvMEjUmJWR/WFwC1nvNpW66K7PLd                                                                                                                                                                                                                      |  300 |    0 |        NULL |        0 |                 |    1 |\r\n| 361779 |        42 |                 | DNSKEY | 257 3 5 AwEAAarSRUAN4R4KZcwepDCor+j+yyj1Yq/nMUHZYB4cngUNZNAfgQ3gudSqsJ1MN7b41ElROzFgsb0NnnblEsruSADpiJEmtLqYkdIyhVUNSs7Yi7O16F0Yd7/ZMbiWjglmhMa6VzdQlsRHzO8W8w1lsgEJpMT8oUma71fjQRQPxRxpA5sYgLpsxrM3eJ/wMoWcKEhH2r65nguHRnjn2MD+8RHfuGuSEbNaa7Rz8Yd+jHYtcdAB65MrFktbUNgvNOqwFD6qOr1Mx3hYc3TTA5x01kZMnXmIEIcfLZ8nSjv7km9UKTdEJOvtGaxinu3MjHc4Q8nPKzNzylNpynU3DNq4ZKs=                                          |  300 |    0 |        NULL |        0 |                 |    1 |\r\n| 361780 |        42 |                 | RRSIG  | DNSKEY 5 0 300 20150409130027 20150310120027 21481 . LTbqj/T7UEKL9irEAMVoj/PKfNFdgYwpA8f4ImfuW5aluWd1sjXbgOkFL8+PJ4jspwjfXw6v4C7Qn10QXrF1nW+cbrWQSLVsFR8JhOsU4v0j/xjGE0leXe7OWuSilZcYr/MICEOJ36pHuHznTBiT1PBXGZOJaWkmW2gCiPT7/jNcwj+FJMTxFQYFxWadb1hUywdDQ7WYH9EbVri2nFS5kV3zhbMBQYK48qEQ9a0uffEbkPpUPBU4fQJKPGDOXi4ikCIpuUfQKiC35o1XWdACQQ0vJ4S+vH5Oz6gkEwjqldcAObdLJ8mJDcbn/7TfoBuGdofgdAPJ1/Yqp/M7Rtz6IQ== |  300 |    0 |        NULL |        0 | NULL            |    1 |\r\n| 361781 |        42 |                 | RRSIG  | DNSKEY 5 0 300 20150409130027 20150310120027 46980 . KnlbysltVGFLcp5Wr16US221wHpf/NATGnaGedmnfFFKewwRltvVHMFJDO2revTe6HAf4AEO+6NTZr1UCJ1O2EdKWePJzdMDsmuvPxBviRlRyKW+A56mQlq/JgtPfebLJC5pfMpMZEjhfKliUnWy//bgyHzU+A7ayMgJs6pUPig=                                                                                                                                                                             |  300 |    0 |        NULL |        0 | NULL            |    1 |\r\n| 361782 |        42 |                 | RRSIG  | SOA 5 0 300 20150409130934 20150310120934 46980 . cAfAkcQLs7Am5bdFCYn2wV141E8Cq85jd65x43/zBEKTZgwBslVn9wDihTYyrXnbpiGkgmqZTpmh/LGJs1FnLjYXvdh1K+09uk/5YWKRK0wknKxJ79xPkPegJjmrveGG2jxZD9i42KcgRX6ilaz7jEPLenzKuGoOO70DvN522q4=                                                                                                                                                                                |  300 |    0 |        NULL |        0 | NULL            |    1 |\r\n| 361783 |        42 | ns1.example.com | RRSIG  | A 5 3 300 20150409121329 20150310120027 46980 . WYE3z/2pijqd8ks4dQHLZUAHFTx1CgEKtqTKIqMpKvdB5JslxPjEHnkO4paF7OH02WkFnbc1kamBmJwFUzUnM2q4jIx3NpLwKCWPU2ElZX26pSpq+DbOOiT6ixTgS/eHth9X3Pbd3nGF2pde5xhFnlHzAbLDORcZUNT8Iw8ezZ0=                                                                                                                                                                                  |  300 |    0 |        NULL |        0 | NULL            |    1 |\r\n| 361784 |        42 | ns1.example.com | RRSIG  | NSEC 5 3 3600 20150409121329 20150310120027 46980 . b2CYfX7Ea4CfoaGOngG/t2YZnCZxfwDovePA3jCFisHLuMr9j8TuiSjV1N50M5pcxZIE3UPp5gTskyp4FJ1FD+KrTJdbpxZIGlZi9ONL72gXhacW/GT2MvoyPx3LcFdweErEGR8StErQ8UCjBKZm58Thl1fH/N1no8xnIJ7+9/A=                                                                                                                                                                              | 3600 |    0 |        NULL |        0 | NULL            |    1 |\r\n| 361785 |        42 | ns1.example.com | A      | 100.96.1.8                                                                                                                                                                                                                                                                                                                                                                                                    |  300 |    0 |        NULL |        0 | com example ns1 |    1 |\r\n| 361786 |        42 | com             | NULL   | NULL                                                                                                                                                                                                                                                                                                                                                                                                          | NULL | NULL |        NULL |        0 | NULL            |    1 |\r\n| 361787 |        42 | example.com     | NULL   | NULL                                                                                                                                                                                                                                                                                                                                                                                                          | NULL | NULL |        NULL |        0 | NULL            |    1 |\r\n+--------+-----------+-----------------+--------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+------+-------------+----------+-----------------+------+\r\n18 rows in set (0.00 sec)\r\n```\r\n\r\n\r\n### Response from Unbound with PowerDNS as root slave\r\n\r\n```\r\ndig -p 5353 @127.0.0.1   kdkdkdkkUNBOUND\r\n\r\n; <<>> DiG 9.9.6-P1 <<>> -p 5353 @127.0.0.1 kdkdkdkkUNBOUND\r\n; (1 server found)\r\n;; global options: +cmd\r\n;; Got answer:\r\n;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 28921\r\n;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1\r\n\r\n;; OPT PSEUDOSECTION:\r\n; EDNS: version: 0, flags:; udp: 4096\r\n;; QUESTION SECTION:\r\n;kdkdkdkkUNBOUND.               IN      A\r\n\r\n;; Query time: 58 msec\r\n;; SERVER: 127.0.0.1#5353(127.0.0.1)\r\n;; WHEN: Tue Mar 10 14:11:13 CET 2015\r\n;; MSG SIZE  rcvd: 44\r\n```\r\n\r\n### Response from Unbound with BIND as root slave\r\n\r\n```\r\ndig -p 5353 @127.0.0.1   kdkdkdkkUNBOUND\r\n\r\n; <<>> DiG 9.9.6-P1 <<>> -p 5353 @127.0.0.1 kdkdkdkkUNBOUND\r\n; (1 server found)\r\n;; global options: +cmd\r\n;; Got answer:\r\n;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 18315\r\n;; flags: qr rd ra ad; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1\r\n\r\n;; OPT PSEUDOSECTION:\r\n; EDNS: version: 0, flags:; udp: 4096\r\n;; QUESTION SECTION:\r\n;kdkdkdkkUNBOUND.               IN      A\r\n\r\n;; AUTHORITY SECTION:\r\n.                       300     IN      SOA     ns1.example.com. hostmaster.example.com. 105 1800 1800 1814400 3600\r\n\r\n;; Query time: 4 msec\r\n;; SERVER: 127.0.0.1#5353(127.0.0.1)\r\n;; WHEN: Tue Mar 10 14:16:19 CET 2015\r\n;; MSG SIZE  rcvd: 105\r\n```\r\n\r\n\r\n\r\n### Reproducing\r\n\r\n1. Configure BIND to serve a root zone\r\n2. Configure auto-dnssec on the zone\r\n3. Transfer to PowerDNS\r\n\r\n#### `named.conf`\r\n\r\n```\r\noptions {\r\n\r\n        directory \"/tmp/zones\";\r\n\r\n        listen-on port 53 { 127.0.0.1; };\r\n        listen-on-v6 { none; };\r\n        allow-query { any; };\r\n        dnssec-enable yes;\r\n        notify no;\r\n};\r\n\r\nzone \".\" IN {\r\n        type master;\r\n        file \"root/root.zone\";\r\n        key-directory \"root\";\r\n        auto-dnssec maintain;\r\n        inline-signing yes;\r\n        allow-transfer { any; };\r\n};\r\n```\r\n\r\n#### Create keys\r\n\r\n```\r\n$ cd /tmp/zones/root\r\n$ dnssec-keygen .\r\n$ dnssec-keygen -f KSK .\r\n```\r\n\r\n\r\n#### root zone master file\r\n\r\n```\r\n$ORIGIN .\r\n$TTL 300\r\n@ IN SOA ns1.example.com. hostmaster.example.com. (\r\n                                    102 1800 1800 1814400 3600\r\n                              )\r\n          NS ns1.example.com.\r\n          A  127.0.0.1\r\n          TXT \"BIND inline-signed, xfr-out to PowerDNS 3.4.3 (jenkins@autotest.powerdns.com built 20150302135804)\"\r\n\r\nns1.example.com. IN A 100.96.1.8\r\n```\r\n\r\n### Full `unbound.log`\r\n\r\n```\r\n[1425993064] unbound[25511:0] debug: module config: \"validator iterator\"\r\n[1425993064] unbound[25511:0] notice: init module 0: validator\r\n[1425993064] unbound[25511:0] info: adding trusted key . DNSKEY IN\r\n[1425993064] unbound[25511:0] info: last_queried: 1425992767 Tue Mar 10 14:06:07 2015\r\n[1425993064] unbound[25511:0] info: last_success: 1425992767 Tue Mar 10 14:06:07 2015\r\n[1425993064] unbound[25511:0] info: next_probe_time: 1426034327 Wed Mar 11 01:38:47 2015\r\n[1425993064] unbound[25511:0] info: query_interval: 43200\r\n[1425993064] unbound[25511:0] info: retry_time: 8640\r\n[1425993064] unbound[25511:0] info: query_failed: 0\r\n[1425993064] unbound[25511:0] debug: validator nsec3cfg keysz 1024 mxiter 150\r\n[1425993064] unbound[25511:0] debug: validator nsec3cfg keysz 2048 mxiter 500\r\n[1425993064] unbound[25511:0] debug: validator nsec3cfg keysz 4096 mxiter 2500\r\n[1425993064] unbound[25511:0] notice: init module 1: iterator\r\n[1425993064] unbound[25511:0] debug: target fetch policy for level 0 is 3\r\n[1425993064] unbound[25511:0] debug: target fetch policy for level 1 is 2\r\n[1425993064] unbound[25511:0] debug: target fetch policy for level 2 is 1\r\n[1425993064] unbound[25511:0] debug: target fetch policy for level 3 is 0\r\n[1425993064] unbound[25511:0] debug: target fetch policy for level 4 is 0\r\n[1425993064] unbound[25511:0] debug: donotq: 127.0.0.0/8\r\n[1425993064] unbound[25511:0] debug: total of 59530 outgoing ports available\r\n[1425993064] unbound[25511:0] debug: start threads\r\n[1425993064] unbound[25511:0] debug: event mini-event-1.5.2 uses not_obtainable method.\r\n[1425993064] unbound[25511:0] debug: Reading root hints from jpm.hints\r\n[1425993064] unbound[25511:0] info: DelegationPoint<.>: 1 names (1 missing), 1 addrs (0 result, 1 avail) parentNS\r\n[1425993064] unbound[25511:0] info:   ns1.example.com.  A\r\n[1425993064] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993064] unbound[25511:0] debug: cache memory msg=66072 rrset=66072 infra=2600 val=66344\r\n[1425993064] unbound[25511:0] info: start of service (unbound 1.5.2).\r\n[1425993064] unbound[25511:0] debug: autotrust probe timer callback\r\n[1425993073] unbound[25511:0] debug: udp request from ip4 127.0.0.1 port 35260 (len 16)\r\n[1425993073] unbound[25511:0] debug: mesh_run: start\r\n[1425993073] unbound[25511:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new\r\n[1425993073] unbound[25511:0] info: validator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: validator: pass to next module\r\n[1425993073] unbound[25511:0] debug: mesh_run: validator module exit state is module_wait_module\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass\r\n[1425993073] unbound[25511:0] debug: process_request: new external request event\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE\r\n[1425993073] unbound[25511:0] info: resolving kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: request has dependency depth of 0\r\n[1425993073] unbound[25511:0] info: priming . IN NS\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_wait_subquery\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass\r\n[1425993073] unbound[25511:0] info: iterator operate: query . NS IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY TARGETS STATE\r\n[1425993073] unbound[25511:0] info: processQueryTargets: . NS IN\r\n[1425993073] unbound[25511:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (0 missing), 1 addrs (0 result, 1 avail) parentNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com. * A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: attempt to get extra 2 targets\r\n[1425993073] unbound[25511:0] debug: selrtt 376\r\n[1425993073] unbound[25511:0] info: sending query: . NS IN\r\n[1425993073] unbound[25511:0] debug: sending to target: <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] debug: dnssec status: expected\r\n[1425993073] unbound[25511:0] debug: EDNS lookup known=0 vs=0\r\n[1425993073] unbound[25511:0] debug: serviced query UDP timeout=376 msec\r\n[1425993073] unbound[25511:0] debug: inserted new pending reply id=27ea\r\n[1425993073] unbound[25511:0] debug: opened UDP if=0 port=54618\r\n[1425993073] unbound[25511:0] debug: comm point start listening 8\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_wait_reply\r\n[1425993073] unbound[25511: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\r\n[1425993073] unbound[25511:0] info: 0pvCD mod1  . NS IN\r\n[1425993073] unbound[25511:0] info: 1RDdc mod1 rep kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: cache memory msg=66072 rrset=66072 infra=2897 val=66344\r\n[1425993073] unbound[25511:0] debug: answer cb\r\n[1425993073] unbound[25511:0] debug: Incoming reply id = 27ea\r\n[1425993073] unbound[25511:0] debug: Incoming reply addr = ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: lookup size is 1 entries\r\n[1425993073] unbound[25511:0] debug: received udp reply.\r\n[1425993073] unbound[25511:0] debug: udp message[389:0] 27EA84000001000200000003000002000100002E00010000012C0093000205000000012C55266CE954FEDCDBB7840033FECD27527724D3A4374B6CDAFBBEC639626EEEC7FD069E0FDF1C9F6E683FFFB2439D64A295C583C4F021ADEE862CC36B27A442D833C44292D053B7E5C020548AD7253E7766015092B36976C0A162C8A3BAB937F92CB97E4C464691A93D5F953EFEC003368A1D21B45AC13FD60752B3A3ECA95DAA73390273A94D95204BDA1400000200010000012C0011036E7331076578616D706C6503636F6D00C0BA002E00010000012C0093000105030000012C55266CE954FEDCDBB78400598137CFFDA98A3A9DF24B387501CB654007153C750A\r\n[1425993073] unbound[25511:0] debug: udp message[389:256] 010AB6A4CA22A3292AF741E49B25C4F8C41E790EE29685ECE1F4D969059DB73591A981989C05533527336AB88C8C773692F028258F536125657DBAA52A6AF836CE3A24FA8B14E04BF787B61F57DCF6DDDE7185DA975EE718459E51F301B2C339171950D4FC230F1ECD9DC0BA000100010000012C0004646001080000290690000080000000\r\n[1425993073] unbound[25511:0] debug: outnet handle udp reply\r\n[1425993073] unbound[25511:0] debug: serviced query: EDNS works for ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: measured roundtrip at 8 msec\r\n[1425993073] unbound[25511:0] debug: svcd callbacks start\r\n[1425993073] unbound[25511:0] debug: worker svcd callback for qstate 0xb7c530\r\n[1425993073] unbound[25511:0] debug: mesh_run: start\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply\r\n[1425993073] unbound[25511:0] info: iterator operate: query . NS IN\r\n[1425993073] unbound[25511:0] debug: process_response: new external response event\r\n[1425993073] unbound[25511:0] info: scrub for . NS IN\r\n[1425993073] unbound[25511:0] info: response for . NS IN\r\n[1425993073] unbound[25511:0] info: reply from <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0\r\n;; flags: qr aa ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 2 \r\n;; QUESTION SECTION:\r\n.\tIN\tNS\r\n\r\n;; ANSWER SECTION:\r\n.\t300\tIN\tNS\tns1.example.com.\r\n.\t300\tIN\tRRSIG\tNS 5 0 300 20150409121329 20150310120027 46980 . M/7NJ1J3JNOkN0ts2vu+xjlibu7H/QaeD98cn25oP/+yQ51kopXFg8TwIa3uhizDayekQtgzxEKS0FO35cAgVIrXJT53ZgFQkrNpdsChYsijurk3+Sy5fkxGRpGpPV+VPv7AAzaKHSG0WsE/1gdSs6PsqV2qczkCc6lNlSBL2hQ= ;{id = 46980}\r\n\r\n;; AUTHORITY SECTION:\r\n\r\n;; ADDITIONAL SECTION:\r\nns1.example.com.\t300\tIN\tA\t100.96.1.8\r\nns1.example.com.\t300\tIN\tRRSIG\tA 5 3 300 20150409121329 20150310120027 46980 . WYE3z/2pijqd8ks4dQHLZUAHFTx1CgEKtqTKIqMpKvdB5JslxPjEHnkO4paF7OH02WkFnbc1kamBmJwFUzUnM2q4jIx3NpLwKCWPU2ElZX26pSpq+DbOOiT6ixTgS/eHth9X3Pbd3nGF2pde5xhFnlHzAbLDORcZUNT8Iw8ezZ0= ;{id = 46980}\r\n;; MSG SIZE  rcvd: 378\r\n\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: query response was ANSWER\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state PRIME RESPONSE STATE\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_finished\r\n[1425993073] unbound[25511:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_moddone\r\n[1425993073] unbound[25511:0] info: validator operate: query . NS IN\r\n[1425993073] unbound[25511:0] debug: validator: nextmodule returned\r\n[1425993073] unbound[25511:0] debug: not validating response, is valrec(validation recursion lookup)\r\n[1425993073] unbound[25511:0] debug: mesh_run: validator module exit state is module_finished\r\n[1425993073] unbound[25511:0] info: priming successful for . NS IN\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (1 missing), 1 addrs (0 result, 1 avail) parentNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com.  A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_wait_subquery event:module_event_pass\r\n[1425993073] unbound[25511:0] info: iterator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)\r\n[1425993073] unbound[25511:0] info: resolving (init part 2):  kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)\r\n[1425993073] unbound[25511:0] info: resolving (init part 3):  kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY TARGETS STATE\r\n[1425993073] unbound[25511:0] info: processQueryTargets: kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (0 missing), 1 addrs (0 result, 1 avail) parentNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com. * A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: attempt to get extra 3 targets\r\n[1425993073] unbound[25511:0] debug: servselect ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug:    rtt=293\r\n[1425993073] unbound[25511:0] debug: selrtt 293\r\n[1425993073] unbound[25511:0] info: sending query: kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: sending to target: <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] debug: dnssec status: expected\r\n[1425993073] unbound[25511:0] debug: EDNS lookup known=1 vs=0\r\n[1425993073] unbound[25511:0] debug: serviced query UDP timeout=293 msec\r\n[1425993073] unbound[25511:0] debug: inserted new pending reply id=8e24\r\n[1425993073] unbound[25511:0] debug: opened UDP if=0 port=21218\r\n[1425993073] unbound[25511:0] debug: comm point start listening 9\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_wait_reply\r\n[1425993073] unbound[25511: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\r\n[1425993073] unbound[25511:0] info: 0RDd mod1 rep kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: cache memory msg=66321 rrset=66893 infra=2897 val=66344\r\n[1425993073] unbound[25511:0] debug: svcd callbacks end\r\n[1425993073] unbound[25511:0] debug: close of port 54618\r\n[1425993073] unbound[25511:0] debug: close fd 8\r\n[1425993073] unbound[25511:0] debug: answer cb\r\n[1425993073] unbound[25511:0] debug: Incoming reply id = 8e24\r\n[1425993073] unbound[25511:0] debug: Incoming reply addr = ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: lookup size is 1 entries\r\n[1425993073] unbound[25511:0] debug: received udp reply.\r\n[1425993073] unbound[25511:0] debug: udp message[482:0] 8E24840300010000000500010F6B646B646B646B6B554E424F554E44000001000100000600010000012C0032036E7331076578616D706C6503636F6D000A686F73746D6173746572C030000000690000070800000708001BAF8000000E1000002E00010000012C0093000605000000012C55267A0E54FEDEFEB784007007C091C40BB3B026E5B7450989F6C15D78D44F02ABCE6377AE71E37FF3044293660C01B25567F700E2853632AD79DBA621A4826A994E99A1FCB189B351672E3617BDD8752BED3DBA4FF96162912B4C249CAC49EFDC4F90F7A02639ABBDE186DA3C590FD8B8D8A720457EA295ACFB8C43CB7A7CCAB86A0E3BBD03BCDE76DAAEC02C002F\r\n[1425993073] unbound[25511:0] debug: udp message[482:256] 000100000E10000B0141000006000000000003C02C002F000100000E100019036E7331076578616D706C6503636F6D000006400000000003C02C002E000100000E100093002F050300000E1055266CE954FEDCDBB784006F60987D7EC46B809FA1A18E9E01BFB766199C26717F00E8BDE3C0DE30858AC1CBB8CAFD8FC4EE8928D5D4DE74339A5CC59204DD43E9E604EC932A78149D450FE2AB4C975BA716481A5662F4E34BEF681785A716FC64F632FA323F1DCB705770784AC4191F12B44AD0F140A304A666E7C4E19757C7FCDD67A3CC67209EFEF7F00000290690000080000000\r\n[1425993073] unbound[25511:0] debug: outnet handle udp reply\r\n[1425993073] unbound[25511:0] debug: measured roundtrip at 37 msec\r\n[1425993073] unbound[25511:0] debug: svcd callbacks start\r\n[1425993073] unbound[25511:0] debug: worker svcd callback for qstate 0xb80540\r\n[1425993073] unbound[25511:0] debug: mesh_run: start\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply\r\n[1425993073] unbound[25511:0] info: iterator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: process_response: new external response event\r\n[1425993073] unbound[25511:0] info: scrub for . NS IN\r\n[1425993073] unbound[25511:0] info: response for kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] info: reply from <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0\r\n;; flags: qr aa ; QUERY: 1, ANSWER: 0, AUTHORITY: 5, ADDITIONAL: 0 \r\n;; QUESTION SECTION:\r\nkdkdkdkkUNBOUND.\tIN\tA\r\n\r\n;; ANSWER SECTION:\r\n\r\n;; AUTHORITY SECTION:\r\n.\t300\tIN\tSOA\tns1.example.com. hostmaster.example.com. 105 1800 1800 1814400 3600\r\n.\t300\tIN\tRRSIG\tSOA 5 0 300 20150409130934 20150310120934 46980 . cAfAkcQLs7Am5bdFCYn2wV141E8Cq85jd65x43/zBEKTZgwBslVn9wDihTYyrXnbpiGkgmqZTpmh/LGJs1FnLjYXvdh1K+09uk/5YWKRK0wknKxJ79xPkPegJjmrveGG2jxZD9i42KcgRX6ilaz7jEPLenzKuGoOO70DvN522q4= ;{id = 46980}\r\nns1.example.com.\t3600\tIN\tNSEC\tA. RRSIG NSEC\r\nns1.example.com.\t3600\tIN\tNSEC\tns1.example.com. A RRSIG NSEC\r\nns1.example.com.\t3600\tIN\tRRSIG\tNSEC 5 3 3600 20150409121329 20150310120027 46980 . b2CYfX7Ea4CfoaGOngG/t2YZnCZxfwDovePA3jCFisHLuMr9j8TuiSjV1N50M5pcxZIE3UPp5gTskyp4FJ1FD+KrTJdbpxZIGlZi9ONL72gXhacW/GT2MvoyPx3LcFdweErEGR8StErQ8UCjBKZm58Thl1fH/N1no8xnIJ7+9/A= ;{id = 46980}\r\n\r\n;; ADDITIONAL SECTION:\r\n;; MSG SIZE  rcvd: 471\r\n\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: query response was NXDOMAIN ANSWER\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: finishing processing for kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_finished\r\n[1425993073] unbound[25511:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone\r\n[1425993073] unbound[25511:0] info: validator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: validator: nextmodule returned\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_INIT_STATE\r\n[1425993073] unbound[25511:0] debug: validator classification nameerror\r\n[1425993073] unbound[25511:0] info: signer is . TYPE0 CLASS0\r\n[1425993073] unbound[25511:0] info: prime trust anchor\r\n[1425993073] unbound[25511:0] info: generate request . DNSKEY IN\r\n[1425993073] unbound[25511:0] debug: mesh_run: validator module exit state is module_wait_subquery\r\n[1425993073] unbound[25511:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass\r\n[1425993073] unbound[25511:0] info: validator operate: query . DNSKEY IN\r\n[1425993073] unbound[25511:0] debug: validator: pass to next module\r\n[1425993073] unbound[25511:0] debug: mesh_run: validator module exit state is module_wait_module\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass\r\n[1425993073] unbound[25511:0] debug: process_request: new external request event\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE\r\n[1425993073] unbound[25511:0] info: resolving . DNSKEY IN\r\n[1425993073] unbound[25511:0] debug: request has dependency depth of 0\r\n[1425993073] unbound[25511:0] debug: cache delegation returns delegpt\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (1 missing), 1 addrs (0 result, 1 avail) cacheNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com.  A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)\r\n[1425993073] unbound[25511:0] info: resolving (init part 2):  . DNSKEY IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)\r\n[1425993073] unbound[25511:0] info: resolving (init part 3):  . DNSKEY IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY TARGETS STATE\r\n[1425993073] unbound[25511:0] info: processQueryTargets: . DNSKEY IN\r\n[1425993073] unbound[25511:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (0 missing), 1 addrs (0 result, 1 avail) cacheNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com. * A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: attempt to get extra 3 targets\r\n[1425993073] unbound[25511:0] debug: servselect ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug:    rtt=261\r\n[1425993073] unbound[25511:0] debug: selrtt 261\r\n[1425993073] unbound[25511:0] info: sending query: . DNSKEY IN\r\n[1425993073] unbound[25511:0] debug: sending to target: <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] debug: dnssec status: expected\r\n[1425993073] unbound[25511:0] debug: EDNS lookup known=1 vs=0\r\n[1425993073] unbound[25511:0] debug: serviced query UDP timeout=261 msec\r\n[1425993073] unbound[25511:0] debug: inserted new pending reply id=655c\r\n[1425993073] unbound[25511:0] debug: opened UDP if=0 port=10450\r\n[1425993073] unbound[25511:0] debug: comm point start listening 8\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_wait_reply\r\n[1425993073] unbound[25511: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\r\n[1425993073] unbound[25511:0] info: 0vRDCD mod1  . DNSKEY IN\r\n[1425993073] unbound[25511:0] info: 1RDdc mod0 rep kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: cache memory msg=66586 rrset=67816 infra=2897 val=66344\r\n[1425993073] unbound[25511:0] debug: svcd callbacks end\r\n[1425993073] unbound[25511:0] debug: close of port 21218\r\n[1425993073] unbound[25511:0] debug: close fd 9\r\n[1425993073] unbound[25511:0] debug: answer cb\r\n[1425993073] unbound[25511:0] debug: Incoming reply id = 655c\r\n[1425993073] unbound[25511:0] debug: Incoming reply addr = ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: lookup size is 1 entries\r\n[1425993073] unbound[25511:0] debug: received udp reply.\r\n[1425993073] unbound[25511:0] debug: udp message[894:0] 655C84000001000400000001000030000100002E00010000012C0093003005000000012C552677EB54FEDCDBB784002A795BCAC96D54614B729E56AF5E944B6DB5C07A5FFCD0131A768679D9A77C514A7B0C1196DBD51CC1490CEDAB7AF4DEE8701FE0010EFBA35366BD54089D4ED8474A59E3C9CDD303B26BAF3F106F891951C8A5BE039EA6425ABF260B4F7DE6CB242E697CCA4C6448E17CA9625275B2FFF6E0C87CD4F80EDAC8C809B3AA543E2800002E00010000012C0113003005000000012C552677EB54FEDCDB53E9002D36EA8FF4FB50428BF62AC400C5688FF3CA7CD15D818C2903C7F82267EE5B96A5B96775B235DB80E9052FCF8F2788ECA708DF\r\n[1425993073] unbound[25511:0] debug: udp message[894:256] 5F0EAFE02ED09F5D105EB1759D6F9C6EB59048B56C151F0984EB14E2FD23FF18C613495E5DEECE5AE4A2959718AFF308084389DFAA47B87CE74C1893D4F0571993896969265B680288F4FBFE335CC23F8524C4F1150605C5669D6F5854CB074343B5981FD11B56B8B69C54B9915DF385B3014182B8F2A110F5AD2E7DF11B90FA543C15387D024A3C60CE5E2E22902229B947D02A20B7E68D5759D002410D2F2784BEBC7E4ECFA8241308EA95D70039B74B27C9890DC6E7FFB4DFA01B867687E07403C9D7F62AA7F33B46DCFA2100003000010000012C01080101030503010001AAD245400DE11E0A65CC1EA430A8AFE8FECB28F562AFE73141D9601E1C9E050D\r\n[1425993073] unbound[25511:0] debug: udp message[894:512] 64D01F810DE0B9D4AAB09D4C37B6F8D449513B3160B1BD0D9E76E512CAEE4800E9889126B4BA9891D23285550D4ACED88BB3B5E85D1877BFD931B8968E096684C6BA57375096C447CCEF16F30D65B20109A4C4FCA1499AEF57E341140FC51C69039B1880BA6CC6B337789FF032859C284847DABEB99E0B874678E7D8C0FEF111DFB86B9211B35A6BB473F1877E8C762D71D001EB932B164B5B50D82F34EAB0143EAA3ABD4CC778587374D3039C74D6464C9D798810871F2D9F274A3BFB926F5429374424EBED19AC629EEDCC8C773843C9CF2B3373CA5369CA75370CDAB864AB00003000010000012C00880100030503010001A7AA8D2526C1B78D1CAB974FFC\r\n[1425993073] unbound[25511:0] debug: udp message[894:768] 70F39EC90A1E9B2B8D28F9030299696E2A893702CA5F2BA90BC3A50F0B3A0AE1C5257C22EE2256028577984524DD333D605E489348C7E3227F3414131BD985910B65DA3E4DB52056C7E8038C6F4730E0CB0BE691650A7B5876EE878F42D006F3048D4989591FD61700B59EF3695BAE8AECF2DD0000290690000080000000\r\n[1425993073] unbound[25511:0] debug: outnet handle udp reply\r\n[1425993073] unbound[25511:0] debug: measured roundtrip at 3 msec\r\n[1425993073] unbound[25511:0] debug: svcd callbacks start\r\n[1425993073] unbound[25511:0] debug: worker svcd callback for qstate 0xb7c530\r\n[1425993073] unbound[25511:0] debug: mesh_run: start\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply\r\n[1425993073] unbound[25511:0] info: iterator operate: query . DNSKEY IN\r\n[1425993073] unbound[25511:0] debug: process_response: new external response event\r\n[1425993073] unbound[25511:0] info: scrub for . NS IN\r\n[1425993073] unbound[25511:0] info: response for . DNSKEY IN\r\n[1425993073] unbound[25511:0] info: reply from <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0\r\n;; flags: qr aa ; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 0 \r\n;; QUESTION SECTION:\r\n.\tIN\tDNSKEY\r\n\r\n;; ANSWER SECTION:\r\n.\t300\tIN\tDNSKEY\t257 3 5 AwEAAarSRUAN4R4KZcwepDCor+j+yyj1Yq/nMUHZYB4cngUNZNAfgQ3gudSqsJ1MN7b41ElROzFgsb0NnnblEsruSADpiJEmtLqYkdIyhVUNSs7Yi7O16F0Yd7/ZMbiWjglmhMa6VzdQlsRHzO8W8w1lsgEJpMT8oUma71fjQRQPxRxpA5sYgLpsxrM3eJ/wMoWcKEhH2r65nguHRnjn2MD+8RHfuGuSEbNaa7Rz8Yd+jHYtcdAB65MrFktbUNgvNOqwFD6qOr1Mx3hYc3TTA5x01kZMnXmIEIcfLZ8nSjv7km9UKTdEJOvtGaxinu3MjHc4Q8nPKzNzylNpynU3DNq4ZKs= ;{id = 21481 (ksk), size = 2048b}\r\n.\t300\tIN\tDNSKEY\t256 3 5 AwEAAaeqjSUmwbeNHKuXT/xw857JCh6bK40o+QMCmWluKok3AspfK6kLw6UPCzoK4cUlfCLuIlYChXeYRSTdMz1gXkiTSMfjIn80FBMb2YWRC2XaPk21IFbH6AOMb0cw4MsL5pFlCntYdu6Hj0LQBvMEjUmJWR/WFwC1nvNpW66K7PLd ;{id = 46980 (zsk), size = 1024b}\r\n.\t300\tIN\tRRSIG\tDNSKEY 5 0 300 20150409130027 20150310120027 46980 . KnlbysltVGFLcp5Wr16US221wHpf/NATGnaGedmnfFFKewwRltvVHMFJDO2revTe6HAf4AEO+6NTZr1UCJ1O2EdKWePJzdMDsmuvPxBviRlRyKW+A56mQlq/JgtPfebLJC5pfMpMZEjhfKliUnWy//bgyHzU+A7ayMgJs6pUPig= ;{id = 46980}\r\n.\t300\tIN\tRRSIG\tDNSKEY 5 0 300 20150409130027 20150310120027 21481 . LTbqj/T7UEKL9irEAMVoj/PKfNFdgYwpA8f4ImfuW5aluWd1sjXbgOkFL8+PJ4jspwjfXw6v4C7Qn10QXrF1nW+cbrWQSLVsFR8JhOsU4v0j/xjGE0leXe7OWuSilZcYr/MICEOJ36pHuHznTBiT1PBXGZOJaWkmW2gCiPT7/jNcwj+FJMTxFQYFxWadb1hUywdDQ7WYH9EbVri2nFS5kV3zhbMBQYK48qEQ9a0uffEbkPpUPBU4fQJKPGDOXi4ikCIpuUfQKiC35o1XWdACQQ0vJ4S+vH5Oz6gkEwjqldcAObdLJ8mJDcbn/7TfoBuGdofgdAPJ1/Yqp/M7Rtz6IQ== ;{id = 21481}\r\n\r\n;; AUTHORITY SECTION:\r\n\r\n;; ADDITIONAL SECTION:\r\n;; MSG SIZE  rcvd: 883\r\n\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: query response was ANSWER\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: finishing processing for . DNSKEY IN\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_finished\r\n[1425993073] unbound[25511:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone\r\n[1425993073] unbound[25511:0] info: validator operate: query . DNSKEY IN\r\n[1425993073] unbound[25511:0] debug: validator: nextmodule returned\r\n[1425993073] unbound[25511:0] debug: not validating response, is valrec(validation recursion lookup)\r\n[1425993073] unbound[25511:0] debug: mesh_run: validator module exit state is module_finished\r\n[1425993073] unbound[25511:0] info: validator: inform_super, sub is . DNSKEY IN\r\n[1425993073] unbound[25511:0] info: super is kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: anchor matched DNSKEY.\r\n[1425993073] unbound[25511:0] info: validate keys with anchor(DS): sec_status_secure\r\n[1425993073] unbound[25511:0] info: Successfully primed trust anchor . DNSKEY IN\r\n[1425993073] unbound[25511:0] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass\r\n[1425993073] unbound[25511:0] info: validator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_FINDKEY_STATE\r\n[1425993073] unbound[25511:0] info: validator: FindKey kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_VALIDATE_STATE\r\n[1425993073] unbound[25511:0] info: verify rrset . SOA IN\r\n[1425993073] unbound[25511:0] debug: verify sig 46980 5\r\n[1425993073] unbound[25511:0] debug: verify result: sec_status_secure\r\n[1425993073] unbound[25511:0] info: verify rrset ns1.example.com. NSEC IN\r\n[1425993073] unbound[25511:0] debug: verify sig 46980 5\r\n[1425993073] unbound[25511:0] debug: verify: signature mismatch\r\n[1425993073] unbound[25511:0] debug: rrset failed to verify: no valid signatures\r\n[1425993073] unbound[25511:0] debug: verify result: sec_status_bogus\r\n[1425993073] unbound[25511:0] info: validator: response has failed AUTHORITY rrset: ns1.example.com. NSEC IN\r\n[1425993073] unbound[25511:0] info: Validate: message contains bad rrsets\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_FINISHED_STATE\r\n[1425993073] unbound[25511:0] debug: validation failed, blacklist and retry to fetch data\r\n[1425993073] unbound[25511:0] debug: blacklist add ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: pass back to next module\r\n[1425993073] unbound[25511:0] debug: mesh_run: validator module exit state is module_restart_next\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_finished event:module_event_pass\r\n[1425993073] unbound[25511:0] debug: process_request: new external request event\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE\r\n[1425993073] unbound[25511:0] info: resolving kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: request has dependency depth of 0\r\n[1425993073] unbound[25511:0] debug: cache blacklisted, going to the network\r\n[1425993073] unbound[25511:0] debug: cache delegation returns delegpt\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (1 missing), 1 addrs (0 result, 1 avail) cacheNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com.  A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)\r\n[1425993073] unbound[25511:0] info: resolving (init part 2):  kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)\r\n[1425993073] unbound[25511:0] info: resolving (init part 3):  kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY TARGETS STATE\r\n[1425993073] unbound[25511:0] info: processQueryTargets: kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (0 missing), 1 addrs (0 result, 1 avail) cacheNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com. * A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: attempt to get extra 3 targets\r\n[1425993073] unbound[25511:0] debug: servselect ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug:    rtt=201\r\n[1425993073] unbound[25511:0] debug: selrtt 480201\r\n[1425993073] unbound[25511:0] info: sending query: kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: sending to target: <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] debug: dnssec status: expected\r\n[1425993073] unbound[25511:0] debug: EDNS lookup known=1 vs=0\r\n[1425993073] unbound[25511:0] debug: serviced query UDP timeout=201 msec\r\n[1425993073] unbound[25511:0] debug: inserted new pending reply id=df87\r\n[1425993073] unbound[25511:0] debug: opened UDP if=0 port=24978\r\n[1425993073] unbound[25511:0] debug: comm point start listening 9\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_wait_reply\r\n[1425993073] unbound[25511: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\r\n[1425993073] unbound[25511:0] info: 0RDd mod1 rep kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: cache memory msg=66811 rrset=68935 infra=2897 val=67497\r\n[1425993073] unbound[25511:0] debug: svcd callbacks end\r\n[1425993073] unbound[25511:0] debug: close of port 10450\r\n[1425993073] unbound[25511:0] debug: close fd 8\r\n[1425993073] unbound[25511:0] debug: answer cb\r\n[1425993073] unbound[25511:0] debug: Incoming reply id = df87\r\n[1425993073] unbound[25511:0] debug: Incoming reply addr = ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: lookup size is 1 entries\r\n[1425993073] unbound[25511:0] debug: received udp reply.\r\n[1425993073] unbound[25511:0] debug: udp message[482:0] DF87840300010000000500010F6B646B646B646B6B554E424F554E44000001000100000600010000012C0032036E7331076578616D706C6503636F6D000A686F73746D6173746572C030000000690000070800000708001BAF8000000E1000002E00010000012C0093000605000000012C55267A0E54FEDEFEB784007007C091C40BB3B026E5B7450989F6C15D78D44F02ABCE6377AE71E37FF3044293660C01B25567F700E2853632AD79DBA621A4826A994E99A1FCB189B351672E3617BDD8752BED3DBA4FF96162912B4C249CAC49EFDC4F90F7A02639ABBDE186DA3C590FD8B8D8A720457EA295ACFB8C43CB7A7CCAB86A0E3BBD03BCDE76DAAEC02C002F\r\n[1425993073] unbound[25511:0] debug: udp message[482:256] 000100000E10000B0141000006000000000003C02C002F000100000E100019036E7331076578616D706C6503636F6D000006400000000003C02C002E000100000E100093002F050300000E1055266CE954FEDCDBB784006F60987D7EC46B809FA1A18E9E01BFB766199C26717F00E8BDE3C0DE30858AC1CBB8CAFD8FC4EE8928D5D4DE74339A5CC59204DD43E9E604EC932A78149D450FE2AB4C975BA716481A5662F4E34BEF681785A716FC64F632FA323F1DCB705770784AC4191F12B44AD0F140A304A666E7C4E19757C7FCDD67A3CC67209EFEF7F00000290690000080000000\r\n[1425993073] unbound[25511:0] debug: outnet handle udp reply\r\n[1425993073] unbound[25511:0] debug: measured roundtrip at 2 msec\r\n[1425993073] unbound[25511:0] debug: svcd callbacks start\r\n[1425993073] unbound[25511:0] debug: worker svcd callback for qstate 0xb80540\r\n[1425993073] unbound[25511:0] debug: mesh_run: start\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply\r\n[1425993073] unbound[25511:0] info: iterator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: process_response: new external response event\r\n[1425993073] unbound[25511:0] info: scrub for . NS IN\r\n[1425993073] unbound[25511:0] info: response for kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] info: reply from <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0\r\n;; flags: qr aa ; QUERY: 1, ANSWER: 0, AUTHORITY: 5, ADDITIONAL: 0 \r\n;; QUESTION SECTION:\r\nkdkdkdkkUNBOUND.\tIN\tA\r\n\r\n;; ANSWER SECTION:\r\n\r\n;; AUTHORITY SECTION:\r\n.\t300\tIN\tSOA\tns1.example.com. hostmaster.example.com. 105 1800 1800 1814400 3600\r\n.\t300\tIN\tRRSIG\tSOA 5 0 300 20150409130934 20150310120934 46980 . cAfAkcQLs7Am5bdFCYn2wV141E8Cq85jd65x43/zBEKTZgwBslVn9wDihTYyrXnbpiGkgmqZTpmh/LGJs1FnLjYXvdh1K+09uk/5YWKRK0wknKxJ79xPkPegJjmrveGG2jxZD9i42KcgRX6ilaz7jEPLenzKuGoOO70DvN522q4= ;{id = 46980}\r\nns1.example.com.\t3600\tIN\tNSEC\tA. RRSIG NSEC\r\nns1.example.com.\t3600\tIN\tNSEC\tns1.example.com. A RRSIG NSEC\r\nns1.example.com.\t3600\tIN\tRRSIG\tNSEC 5 3 3600 20150409121329 20150310120027 46980 . b2CYfX7Ea4CfoaGOngG/t2YZnCZxfwDovePA3jCFisHLuMr9j8TuiSjV1N50M5pcxZIE3UPp5gTskyp4FJ1FD+KrTJdbpxZIGlZi9ONL72gXhacW/GT2MvoyPx3LcFdweErEGR8StErQ8UCjBKZm58Thl1fH/N1no8xnIJ7+9/A= ;{id = 46980}\r\n\r\n;; ADDITIONAL SECTION:\r\n;; MSG SIZE  rcvd: 471\r\n\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: query response was NXDOMAIN ANSWER\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: finishing processing for kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_finished\r\n[1425993073] unbound[25511:0] debug: validator[module 0] operate: extstate:module_restart_next event:module_event_moddone\r\n[1425993073] unbound[25511:0] info: validator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] info: validator operate: chased to . TYPE0 CLASS0\r\n[1425993073] unbound[25511:0] debug: validator: nextmodule returned\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_INIT_STATE\r\n[1425993073] unbound[25511:0] debug: validator classification nameerror\r\n[1425993073] unbound[25511:0] info: signer is . TYPE0 CLASS0\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_FINDKEY_STATE\r\n[1425993073] unbound[25511:0] info: validator: FindKey kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_VALIDATE_STATE\r\n[1425993073] unbound[25511:0] info: verify rrset cached . SOA IN\r\n[1425993073] unbound[25511:0] info: verify rrset ns1.example.com. NSEC IN\r\n[1425993073] unbound[25511:0] debug: verify sig 46980 5\r\n[1425993073] unbound[25511:0] debug: verify: signature mismatch\r\n[1425993073] unbound[25511:0] debug: rrset failed to verify: no valid signatures\r\n[1425993073] unbound[25511:0] debug: verify result: sec_status_bogus\r\n[1425993073] unbound[25511:0] info: validator: response has failed AUTHORITY rrset: ns1.example.com. NSEC IN\r\n[1425993073] unbound[25511:0] info: Validate: message contains bad rrsets\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_FINISHED_STATE\r\n[1425993073] unbound[25511:0] debug: validation failed, blacklist and retry to fetch data\r\n[1425993073] unbound[25511:0] debug: blacklist ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: blacklist add ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: pass back to next module\r\n[1425993073] unbound[25511:0] debug: mesh_run: validator module exit state is module_restart_next\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_finished event:module_event_pass\r\n[1425993073] unbound[25511:0] debug: process_request: new external request event\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE\r\n[1425993073] unbound[25511:0] info: resolving kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: request has dependency depth of 0\r\n[1425993073] unbound[25511:0] debug: cache blacklisted, going to the network\r\n[1425993073] unbound[25511:0] debug: cache delegation returns delegpt\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (1 missing), 1 addrs (0 result, 1 avail) cacheNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com.  A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)\r\n[1425993073] unbound[25511:0] info: resolving (init part 2):  kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)\r\n[1425993073] unbound[25511:0] info: resolving (init part 3):  kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY TARGETS STATE\r\n[1425993073] unbound[25511:0] info: processQueryTargets: kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (0 missing), 1 addrs (0 result, 1 avail) cacheNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com. * A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: attempt to get extra 3 targets\r\n[1425993073] unbound[25511:0] debug: servselect ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug:    rtt=157\r\n[1425993073] unbound[25511:0] debug: selrtt 480157\r\n[1425993073] unbound[25511:0] info: sending query: kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: sending to target: <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] debug: dnssec status: expected\r\n[1425993073] unbound[25511:0] debug: EDNS lookup known=1 vs=0\r\n[1425993073] unbound[25511:0] debug: serviced query UDP timeout=157 msec\r\n[1425993073] unbound[25511:0] debug: inserted new pending reply id=e127\r\n[1425993073] unbound[25511:0] debug: opened UDP if=0 port=14789\r\n[1425993073] unbound[25511:0] debug: comm point start listening 8\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_wait_reply\r\n[1425993073] unbound[25511: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\r\n[1425993073] unbound[25511:0] info: 0RDd mod1 rep kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: cache memory msg=66811 rrset=68935 infra=2897 val=67497\r\n[1425993073] unbound[25511:0] debug: svcd callbacks end\r\n[1425993073] unbound[25511:0] debug: close of port 24978\r\n[1425993073] unbound[25511:0] debug: close fd 9\r\n[1425993073] unbound[25511:0] debug: answer cb\r\n[1425993073] unbound[25511:0] debug: Incoming reply id = e127\r\n[1425993073] unbound[25511:0] debug: Incoming reply addr = ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: lookup size is 1 entries\r\n[1425993073] unbound[25511:0] debug: received udp reply.\r\n[1425993073] unbound[25511:0] debug: udp message[482:0] E127840300010000000500010F6B646B646B646B6B554E424F554E44000001000100000600010000012C0032036E7331076578616D706C6503636F6D000A686F73746D6173746572C030000000690000070800000708001BAF8000000E1000002E00010000012C0093000605000000012C55267A0E54FEDEFEB784007007C091C40BB3B026E5B7450989F6C15D78D44F02ABCE6377AE71E37FF3044293660C01B25567F700E2853632AD79DBA621A4826A994E99A1FCB189B351672E3617BDD8752BED3DBA4FF96162912B4C249CAC49EFDC4F90F7A02639ABBDE186DA3C590FD8B8D8A720457EA295ACFB8C43CB7A7CCAB86A0E3BBD03BCDE76DAAEC02C002F\r\n[1425993073] unbound[25511:0] debug: udp message[482:256] 000100000E10000B0141000006000000000003C02C002F000100000E100019036E7331076578616D706C6503636F6D000006400000000003C02C002E000100000E100093002F050300000E1055266CE954FEDCDBB784006F60987D7EC46B809FA1A18E9E01BFB766199C26717F00E8BDE3C0DE30858AC1CBB8CAFD8FC4EE8928D5D4DE74339A5CC59204DD43E9E604EC932A78149D450FE2AB4C975BA716481A5662F4E34BEF681785A716FC64F632FA323F1DCB705770784AC4191F12B44AD0F140A304A666E7C4E19757C7FCDD67A3CC67209EFEF7F00000290690000080000000\r\n[1425993073] unbound[25511:0] debug: outnet handle udp reply\r\n[1425993073] unbound[25511:0] debug: measured roundtrip at 1 msec\r\n[1425993073] unbound[25511:0] debug: svcd callbacks start\r\n[1425993073] unbound[25511:0] debug: worker svcd callback for qstate 0xb80540\r\n[1425993073] unbound[25511:0] debug: mesh_run: start\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply\r\n[1425993073] unbound[25511:0] info: iterator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: process_response: new external response event\r\n[1425993073] unbound[25511:0] info: scrub for . NS IN\r\n[1425993073] unbound[25511:0] info: response for kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] info: reply from <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0\r\n;; flags: qr aa ; QUERY: 1, ANSWER: 0, AUTHORITY: 5, ADDITIONAL: 0 \r\n;; QUESTION SECTION:\r\nkdkdkdkkUNBOUND.\tIN\tA\r\n\r\n;; ANSWER SECTION:\r\n\r\n;; AUTHORITY SECTION:\r\n.\t300\tIN\tSOA\tns1.example.com. hostmaster.example.com. 105 1800 1800 1814400 3600\r\n.\t300\tIN\tRRSIG\tSOA 5 0 300 20150409130934 20150310120934 46980 . cAfAkcQLs7Am5bdFCYn2wV141E8Cq85jd65x43/zBEKTZgwBslVn9wDihTYyrXnbpiGkgmqZTpmh/LGJs1FnLjYXvdh1K+09uk/5YWKRK0wknKxJ79xPkPegJjmrveGG2jxZD9i42KcgRX6ilaz7jEPLenzKuGoOO70DvN522q4= ;{id = 46980}\r\nns1.example.com.\t3600\tIN\tNSEC\tA. RRSIG NSEC\r\nns1.example.com.\t3600\tIN\tNSEC\tns1.example.com. A RRSIG NSEC\r\nns1.example.com.\t3600\tIN\tRRSIG\tNSEC 5 3 3600 20150409121329 20150310120027 46980 . b2CYfX7Ea4CfoaGOngG/t2YZnCZxfwDovePA3jCFisHLuMr9j8TuiSjV1N50M5pcxZIE3UPp5gTskyp4FJ1FD+KrTJdbpxZIGlZi9ONL72gXhacW/GT2MvoyPx3LcFdweErEGR8StErQ8UCjBKZm58Thl1fH/N1no8xnIJ7+9/A= ;{id = 46980}\r\n\r\n;; ADDITIONAL SECTION:\r\n;; MSG SIZE  rcvd: 471\r\n\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: query response was NXDOMAIN ANSWER\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: finishing processing for kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_finished\r\n[1425993073] unbound[25511:0] debug: validator[module 0] operate: extstate:module_restart_next event:module_event_moddone\r\n[1425993073] unbound[25511:0] info: validator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] info: validator operate: chased to . TYPE0 CLASS0\r\n[1425993073] unbound[25511:0] debug: validator: nextmodule returned\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_INIT_STATE\r\n[1425993073] unbound[25511:0] debug: validator classification nameerror\r\n[1425993073] unbound[25511:0] info: signer is . TYPE0 CLASS0\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_FINDKEY_STATE\r\n[1425993073] unbound[25511:0] info: validator: FindKey kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_VALIDATE_STATE\r\n[1425993073] unbound[25511:0] info: verify rrset cached . SOA IN\r\n[1425993073] unbound[25511:0] info: verify rrset ns1.example.com. NSEC IN\r\n[1425993073] unbound[25511:0] debug: verify sig 46980 5\r\n[1425993073] unbound[25511:0] debug: verify: signature mismatch\r\n[1425993073] unbound[25511:0] debug: rrset failed to verify: no valid signatures\r\n[1425993073] unbound[25511:0] debug: verify result: sec_status_bogus\r\n[1425993073] unbound[25511:0] info: validator: response has failed AUTHORITY rrset: ns1.example.com. NSEC IN\r\n[1425993073] unbound[25511:0] info: Validate: message contains bad rrsets\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_FINISHED_STATE\r\n[1425993073] unbound[25511:0] debug: validation failed, blacklist and retry to fetch data\r\n[1425993073] unbound[25511:0] debug: blacklist ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: blacklist ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: blacklist add ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: pass back to next module\r\n[1425993073] unbound[25511:0] debug: mesh_run: validator module exit state is module_restart_next\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_finished event:module_event_pass\r\n[1425993073] unbound[25511:0] debug: process_request: new external request event\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE\r\n[1425993073] unbound[25511:0] info: resolving kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: request has dependency depth of 0\r\n[1425993073] unbound[25511:0] debug: cache blacklisted, going to the network\r\n[1425993073] unbound[25511:0] debug: cache delegation returns delegpt\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (1 missing), 1 addrs (0 result, 1 avail) cacheNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com.  A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)\r\n[1425993073] unbound[25511:0] info: resolving (init part 2):  kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)\r\n[1425993073] unbound[25511:0] info: resolving (init part 3):  kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY TARGETS STATE\r\n[1425993073] unbound[25511:0] info: processQueryTargets: kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (0 missing), 1 addrs (0 result, 1 avail) cacheNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com. * A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: attempt to get extra 3 targets\r\n[1425993073] unbound[25511:0] debug: servselect ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug:    rtt=125\r\n[1425993073] unbound[25511:0] debug: selrtt 480125\r\n[1425993073] unbound[25511:0] info: sending query: kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: sending to target: <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] debug: dnssec status: expected\r\n[1425993073] unbound[25511:0] debug: EDNS lookup known=1 vs=0\r\n[1425993073] unbound[25511:0] debug: serviced query UDP timeout=125 msec\r\n[1425993073] unbound[25511:0] debug: inserted new pending reply id=d226\r\n[1425993073] unbound[25511:0] debug: opened UDP if=0 port=50781\r\n[1425993073] unbound[25511:0] debug: comm point start listening 9\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_wait_reply\r\n[1425993073] unbound[25511: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\r\n[1425993073] unbound[25511:0] info: 0RDd mod1 rep kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: cache memory msg=66811 rrset=68935 infra=2897 val=67497\r\n[1425993073] unbound[25511:0] debug: svcd callbacks end\r\n[1425993073] unbound[25511:0] debug: close of port 14789\r\n[1425993073] unbound[25511:0] debug: close fd 8\r\n[1425993073] unbound[25511:0] debug: answer cb\r\n[1425993073] unbound[25511:0] debug: Incoming reply id = d226\r\n[1425993073] unbound[25511:0] debug: Incoming reply addr = ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: lookup size is 1 entries\r\n[1425993073] unbound[25511:0] debug: received udp reply.\r\n[1425993073] unbound[25511:0] debug: udp message[482:0] D226840300010000000500010F6B646B646B646B6B554E424F554E44000001000100000600010000012C0032036E7331076578616D706C6503636F6D000A686F73746D6173746572C030000000690000070800000708001BAF8000000E1000002E00010000012C0093000605000000012C55267A0E54FEDEFEB784007007C091C40BB3B026E5B7450989F6C15D78D44F02ABCE6377AE71E37FF3044293660C01B25567F700E2853632AD79DBA621A4826A994E99A1FCB189B351672E3617BDD8752BED3DBA4FF96162912B4C249CAC49EFDC4F90F7A02639ABBDE186DA3C590FD8B8D8A720457EA295ACFB8C43CB7A7CCAB86A0E3BBD03BCDE76DAAEC02C002F\r\n[1425993073] unbound[25511:0] debug: udp message[482:256] 000100000E10000B0141000006000000000003C02C002F000100000E100019036E7331076578616D706C6503636F6D000006400000000003C02C002E000100000E100093002F050300000E1055266CE954FEDCDBB784006F60987D7EC46B809FA1A18E9E01BFB766199C26717F00E8BDE3C0DE30858AC1CBB8CAFD8FC4EE8928D5D4DE74339A5CC59204DD43E9E604EC932A78149D450FE2AB4C975BA716481A5662F4E34BEF681785A716FC64F632FA323F1DCB705770784AC4191F12B44AD0F140A304A666E7C4E19757C7FCDD67A3CC67209EFEF7F00000290690000080000000\r\n[1425993073] unbound[25511:0] debug: outnet handle udp reply\r\n[1425993073] unbound[25511:0] debug: measured roundtrip at 1 msec\r\n[1425993073] unbound[25511:0] debug: svcd callbacks start\r\n[1425993073] unbound[25511:0] debug: worker svcd callback for qstate 0xb80540\r\n[1425993073] unbound[25511:0] debug: mesh_run: start\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply\r\n[1425993073] unbound[25511:0] info: iterator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: process_response: new external response event\r\n[1425993073] unbound[25511:0] info: scrub for . NS IN\r\n[1425993073] unbound[25511:0] info: response for kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] info: reply from <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0\r\n;; flags: qr aa ; QUERY: 1, ANSWER: 0, AUTHORITY: 5, ADDITIONAL: 0 \r\n;; QUESTION SECTION:\r\nkdkdkdkkUNBOUND.\tIN\tA\r\n\r\n;; ANSWER SECTION:\r\n\r\n;; AUTHORITY SECTION:\r\n.\t300\tIN\tSOA\tns1.example.com. hostmaster.example.com. 105 1800 1800 1814400 3600\r\n.\t300\tIN\tRRSIG\tSOA 5 0 300 20150409130934 20150310120934 46980 . cAfAkcQLs7Am5bdFCYn2wV141E8Cq85jd65x43/zBEKTZgwBslVn9wDihTYyrXnbpiGkgmqZTpmh/LGJs1FnLjYXvdh1K+09uk/5YWKRK0wknKxJ79xPkPegJjmrveGG2jxZD9i42KcgRX6ilaz7jEPLenzKuGoOO70DvN522q4= ;{id = 46980}\r\nns1.example.com.\t3600\tIN\tNSEC\tA. RRSIG NSEC\r\nns1.example.com.\t3600\tIN\tNSEC\tns1.example.com. A RRSIG NSEC\r\nns1.example.com.\t3600\tIN\tRRSIG\tNSEC 5 3 3600 20150409121329 20150310120027 46980 . b2CYfX7Ea4CfoaGOngG/t2YZnCZxfwDovePA3jCFisHLuMr9j8TuiSjV1N50M5pcxZIE3UPp5gTskyp4FJ1FD+KrTJdbpxZIGlZi9ONL72gXhacW/GT2MvoyPx3LcFdweErEGR8StErQ8UCjBKZm58Thl1fH/N1no8xnIJ7+9/A= ;{id = 46980}\r\n\r\n;; ADDITIONAL SECTION:\r\n;; MSG SIZE  rcvd: 471\r\n\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: query response was NXDOMAIN ANSWER\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: finishing processing for kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_finished\r\n[1425993073] unbound[25511:0] debug: validator[module 0] operate: extstate:module_restart_next event:module_event_moddone\r\n[1425993073] unbound[25511:0] info: validator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] info: validator operate: chased to . TYPE0 CLASS0\r\n[1425993073] unbound[25511:0] debug: validator: nextmodule returned\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_INIT_STATE\r\n[1425993073] unbound[25511:0] debug: validator classification nameerror\r\n[1425993073] unbound[25511:0] info: signer is . TYPE0 CLASS0\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_FINDKEY_STATE\r\n[1425993073] unbound[25511:0] info: validator: FindKey kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_VALIDATE_STATE\r\n[1425993073] unbound[25511:0] info: verify rrset cached . SOA IN\r\n[1425993073] unbound[25511:0] info: verify rrset ns1.example.com. NSEC IN\r\n[1425993073] unbound[25511:0] debug: verify sig 46980 5\r\n[1425993073] unbound[25511:0] debug: verify: signature mismatch\r\n[1425993073] unbound[25511:0] debug: rrset failed to verify: no valid signatures\r\n[1425993073] unbound[25511:0] debug: verify result: sec_status_bogus\r\n[1425993073] unbound[25511:0] info: validator: response has failed AUTHORITY rrset: ns1.example.com. NSEC IN\r\n[1425993073] unbound[25511:0] info: Validate: message contains bad rrsets\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_FINISHED_STATE\r\n[1425993073] unbound[25511:0] debug: validation failed, blacklist and retry to fetch data\r\n[1425993073] unbound[25511:0] debug: blacklist ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: blacklist ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: blacklist ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: blacklist add ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: pass back to next module\r\n[1425993073] unbound[25511:0] debug: mesh_run: validator module exit state is module_restart_next\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_finished event:module_event_pass\r\n[1425993073] unbound[25511:0] debug: process_request: new external request event\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE\r\n[1425993073] unbound[25511:0] info: resolving kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: request has dependency depth of 0\r\n[1425993073] unbound[25511:0] debug: cache blacklisted, going to the network\r\n[1425993073] unbound[25511:0] debug: cache delegation returns delegpt\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (1 missing), 1 addrs (0 result, 1 avail) cacheNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com.  A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)\r\n[1425993073] unbound[25511:0] info: resolving (init part 2):  kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)\r\n[1425993073] unbound[25511:0] info: resolving (init part 3):  kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY TARGETS STATE\r\n[1425993073] unbound[25511:0] info: processQueryTargets: kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (0 missing), 1 addrs (0 result, 1 avail) cacheNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com. * A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: attempt to get extra 3 targets\r\n[1425993073] unbound[25511:0] debug: servselect ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug:    rtt=101\r\n[1425993073] unbound[25511:0] debug: selrtt 480101\r\n[1425993073] unbound[25511:0] info: sending query: kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: sending to target: <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] debug: dnssec status: expected\r\n[1425993073] unbound[25511:0] debug: EDNS lookup known=1 vs=0\r\n[1425993073] unbound[25511:0] debug: serviced query UDP timeout=101 msec\r\n[1425993073] unbound[25511:0] debug: inserted new pending reply id=bab2\r\n[1425993073] unbound[25511:0] debug: opened UDP if=0 port=18250\r\n[1425993073] unbound[25511:0] debug: comm point start listening 8\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_wait_reply\r\n[1425993073] unbound[25511: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\r\n[1425993073] unbound[25511:0] info: 0RDd mod1 rep kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: cache memory msg=66811 rrset=68935 infra=2897 val=67497\r\n[1425993073] unbound[25511:0] debug: svcd callbacks end\r\n[1425993073] unbound[25511:0] debug: close of port 50781\r\n[1425993073] unbound[25511:0] debug: close fd 9\r\n[1425993073] unbound[25511:0] debug: answer cb\r\n[1425993073] unbound[25511:0] debug: Incoming reply id = bab2\r\n[1425993073] unbound[25511:0] debug: Incoming reply addr = ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: lookup size is 1 entries\r\n[1425993073] unbound[25511:0] debug: received udp reply.\r\n[1425993073] unbound[25511:0] debug: udp message[482:0] BAB2840300010000000500010F6B646B646B646B6B554E424F554E44000001000100000600010000012C0032036E7331076578616D706C6503636F6D000A686F73746D6173746572C030000000690000070800000708001BAF8000000E1000002E00010000012C0093000605000000012C55267A0E54FEDEFEB784007007C091C40BB3B026E5B7450989F6C15D78D44F02ABCE6377AE71E37FF3044293660C01B25567F700E2853632AD79DBA621A4826A994E99A1FCB189B351672E3617BDD8752BED3DBA4FF96162912B4C249CAC49EFDC4F90F7A02639ABBDE186DA3C590FD8B8D8A720457EA295ACFB8C43CB7A7CCAB86A0E3BBD03BCDE76DAAEC02C002F\r\n[1425993073] unbound[25511:0] debug: udp message[482:256] 000100000E10000B0141000006000000000003C02C002F000100000E100019036E7331076578616D706C6503636F6D000006400000000003C02C002E000100000E100093002F050300000E1055266CE954FEDCDBB784006F60987D7EC46B809FA1A18E9E01BFB766199C26717F00E8BDE3C0DE30858AC1CBB8CAFD8FC4EE8928D5D4DE74339A5CC59204DD43E9E604EC932A78149D450FE2AB4C975BA716481A5662F4E34BEF681785A716FC64F632FA323F1DCB705770784AC4191F12B44AD0F140A304A666E7C4E19757C7FCDD67A3CC67209EFEF7F00000290690000080000000\r\n[1425993073] unbound[25511:0] debug: outnet handle udp reply\r\n[1425993073] unbound[25511:0] debug: measured roundtrip at 1 msec\r\n[1425993073] unbound[25511:0] debug: svcd callbacks start\r\n[1425993073] unbound[25511:0] debug: worker svcd callback for qstate 0xb80540\r\n[1425993073] unbound[25511:0] debug: mesh_run: start\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply\r\n[1425993073] unbound[25511:0] info: iterator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: process_response: new external response event\r\n[1425993073] unbound[25511:0] info: scrub for . NS IN\r\n[1425993073] unbound[25511:0] info: response for kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] info: reply from <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0\r\n;; flags: qr aa ; QUERY: 1, ANSWER: 0, AUTHORITY: 5, ADDITIONAL: 0 \r\n;; QUESTION SECTION:\r\nkdkdkdkkUNBOUND.\tIN\tA\r\n\r\n;; ANSWER SECTION:\r\n\r\n;; AUTHORITY SECTION:\r\n.\t300\tIN\tSOA\tns1.example.com. hostmaster.example.com. 105 1800 1800 1814400 3600\r\n.\t300\tIN\tRRSIG\tSOA 5 0 300 20150409130934 20150310120934 46980 . cAfAkcQLs7Am5bdFCYn2wV141E8Cq85jd65x43/zBEKTZgwBslVn9wDihTYyrXnbpiGkgmqZTpmh/LGJs1FnLjYXvdh1K+09uk/5YWKRK0wknKxJ79xPkPegJjmrveGG2jxZD9i42KcgRX6ilaz7jEPLenzKuGoOO70DvN522q4= ;{id = 46980}\r\nns1.example.com.\t3600\tIN\tNSEC\tA. RRSIG NSEC\r\nns1.example.com.\t3600\tIN\tNSEC\tns1.example.com. A RRSIG NSEC\r\nns1.example.com.\t3600\tIN\tRRSIG\tNSEC 5 3 3600 20150409121329 20150310120027 46980 . b2CYfX7Ea4CfoaGOngG/t2YZnCZxfwDovePA3jCFisHLuMr9j8TuiSjV1N50M5pcxZIE3UPp5gTskyp4FJ1FD+KrTJdbpxZIGlZi9ONL72gXhacW/GT2MvoyPx3LcFdweErEGR8StErQ8UCjBKZm58Thl1fH/N1no8xnIJ7+9/A= ;{id = 46980}\r\n\r\n;; ADDITIONAL SECTION:\r\n;; MSG SIZE  rcvd: 471\r\n\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: query response was NXDOMAIN ANSWER\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: finishing processing for kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_finished\r\n[1425993073] unbound[25511:0] debug: validator[module 0] operate: extstate:module_restart_next event:module_event_moddone\r\n[1425993073] unbound[25511:0] info: validator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] info: validator operate: chased to . TYPE0 CLASS0\r\n[1425993073] unbound[25511:0] debug: validator: nextmodule returned\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_INIT_STATE\r\n[1425993073] unbound[25511:0] debug: validator classification nameerror\r\n[1425993073] unbound[25511:0] info: signer is . TYPE0 CLASS0\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_FINDKEY_STATE\r\n[1425993073] unbound[25511:0] info: validator: FindKey kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_VALIDATE_STATE\r\n[1425993073] unbound[25511:0] info: verify rrset cached . SOA IN\r\n[1425993073] unbound[25511:0] info: verify rrset ns1.example.com. NSEC IN\r\n[1425993073] unbound[25511:0] debug: verify sig 46980 5\r\n[1425993073] unbound[25511:0] debug: verify: signature mismatch\r\n[1425993073] unbound[25511:0] debug: rrset failed to verify: no valid signatures\r\n[1425993073] unbound[25511:0] debug: verify result: sec_status_bogus\r\n[1425993073] unbound[25511:0] info: validator: response has failed AUTHORITY rrset: ns1.example.com. NSEC IN\r\n[1425993073] unbound[25511:0] info: Validate: message contains bad rrsets\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_FINISHED_STATE\r\n[1425993073] unbound[25511:0] debug: validation failed, blacklist and retry to fetch data\r\n[1425993073] unbound[25511:0] debug: blacklist ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: blacklist ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: blacklist ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: blacklist ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: blacklist add ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: pass back to next module\r\n[1425993073] unbound[25511:0] debug: mesh_run: validator module exit state is module_restart_next\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_finished event:module_event_pass\r\n[1425993073] unbound[25511:0] debug: process_request: new external request event\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE\r\n[1425993073] unbound[25511:0] info: resolving kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: request has dependency depth of 0\r\n[1425993073] unbound[25511:0] debug: cache blacklisted, going to the network\r\n[1425993073] unbound[25511:0] debug: cache delegation returns delegpt\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (1 missing), 1 addrs (0 result, 1 avail) cacheNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com.  A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)\r\n[1425993073] unbound[25511:0] info: resolving (init part 2):  kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)\r\n[1425993073] unbound[25511:0] info: resolving (init part 3):  kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY TARGETS STATE\r\n[1425993073] unbound[25511:0] info: processQueryTargets: kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0\r\n[1425993073] unbound[25511:0] info: DelegationPoint<.>: 1 names (0 missing), 1 addrs (0 result, 1 avail) cacheNS\r\n[1425993073] unbound[25511:0] info:   ns1.example.com. * A\r\n[1425993073] unbound[25511:0] debug:    ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: attempt to get extra 3 targets\r\n[1425993073] unbound[25511:0] debug: servselect ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug:    rtt=81\r\n[1425993073] unbound[25511:0] debug: selrtt 480081\r\n[1425993073] unbound[25511:0] info: sending query: kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: sending to target: <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] debug: dnssec status: expected\r\n[1425993073] unbound[25511:0] debug: EDNS lookup known=1 vs=0\r\n[1425993073] unbound[25511:0] debug: serviced query UDP timeout=81 msec\r\n[1425993073] unbound[25511:0] debug: inserted new pending reply id=da6a\r\n[1425993073] unbound[25511:0] debug: opened UDP if=0 port=7248\r\n[1425993073] unbound[25511:0] debug: comm point start listening 9\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_wait_reply\r\n[1425993073] unbound[25511: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\r\n[1425993073] unbound[25511:0] info: 0RDd mod1 rep kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: cache memory msg=66811 rrset=68935 infra=2897 val=67497\r\n[1425993073] unbound[25511:0] debug: svcd callbacks end\r\n[1425993073] unbound[25511:0] debug: close of port 18250\r\n[1425993073] unbound[25511:0] debug: close fd 8\r\n[1425993073] unbound[25511:0] debug: answer cb\r\n[1425993073] unbound[25511:0] debug: Incoming reply id = da6a\r\n[1425993073] unbound[25511:0] debug: Incoming reply addr = ip4 100.96.1.8 port 53 (len 16)\r\n[1425993073] unbound[25511:0] debug: lookup size is 1 entries\r\n[1425993073] unbound[25511:0] debug: received udp reply.\r\n[1425993073] unbound[25511:0] debug: udp message[482:0] DA6A840300010000000500010F6B646B646B646B6B554E424F554E44000001000100000600010000012C0032036E7331076578616D706C6503636F6D000A686F73746D6173746572C030000000690000070800000708001BAF8000000E1000002E00010000012C0093000605000000012C55267A0E54FEDEFEB784007007C091C40BB3B026E5B7450989F6C15D78D44F02ABCE6377AE71E37FF3044293660C01B25567F700E2853632AD79DBA621A4826A994E99A1FCB189B351672E3617BDD8752BED3DBA4FF96162912B4C249CAC49EFDC4F90F7A02639ABBDE186DA3C590FD8B8D8A720457EA295ACFB8C43CB7A7CCAB86A0E3BBD03BCDE76DAAEC02C002F\r\n[1425993073] unbound[25511:0] debug: udp message[482:256] 000100000E10000B0141000006000000000003C02C002F000100000E100019036E7331076578616D706C6503636F6D000006400000000003C02C002E000100000E100093002F050300000E1055266CE954FEDCDBB784006F60987D7EC46B809FA1A18E9E01BFB766199C26717F00E8BDE3C0DE30858AC1CBB8CAFD8FC4EE8928D5D4DE74339A5CC59204DD43E9E604EC932A78149D450FE2AB4C975BA716481A5662F4E34BEF681785A716FC64F632FA323F1DCB705770784AC4191F12B44AD0F140A304A666E7C4E19757C7FCDD67A3CC67209EFEF7F00000290690000080000000\r\n[1425993073] unbound[25511:0] debug: outnet handle udp reply\r\n[1425993073] unbound[25511:0] debug: measured roundtrip at 1 msec\r\n[1425993073] unbound[25511:0] debug: svcd callbacks start\r\n[1425993073] unbound[25511:0] debug: worker svcd callback for qstate 0xb80540\r\n[1425993073] unbound[25511:0] debug: mesh_run: start\r\n[1425993073] unbound[25511:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply\r\n[1425993073] unbound[25511:0] info: iterator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: process_response: new external response event\r\n[1425993073] unbound[25511:0] info: scrub for . NS IN\r\n[1425993073] unbound[25511:0] info: response for kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] info: reply from <.> 100.96.1.8#53\r\n[1425993073] unbound[25511:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0\r\n;; flags: qr aa ; QUERY: 1, ANSWER: 0, AUTHORITY: 5, ADDITIONAL: 0 \r\n;; QUESTION SECTION:\r\nkdkdkdkkUNBOUND.\tIN\tA\r\n\r\n;; ANSWER SECTION:\r\n\r\n;; AUTHORITY SECTION:\r\n.\t300\tIN\tSOA\tns1.example.com. hostmaster.example.com. 105 1800 1800 1814400 3600\r\n.\t300\tIN\tRRSIG\tSOA 5 0 300 20150409130934 20150310120934 46980 . cAfAkcQLs7Am5bdFCYn2wV141E8Cq85jd65x43/zBEKTZgwBslVn9wDihTYyrXnbpiGkgmqZTpmh/LGJs1FnLjYXvdh1K+09uk/5YWKRK0wknKxJ79xPkPegJjmrveGG2jxZD9i42KcgRX6ilaz7jEPLenzKuGoOO70DvN522q4= ;{id = 46980}\r\nns1.example.com.\t3600\tIN\tNSEC\tA. RRSIG NSEC\r\nns1.example.com.\t3600\tIN\tNSEC\tns1.example.com. A RRSIG NSEC\r\nns1.example.com.\t3600\tIN\tRRSIG\tNSEC 5 3 3600 20150409121329 20150310120027 46980 . b2CYfX7Ea4CfoaGOngG/t2YZnCZxfwDovePA3jCFisHLuMr9j8TuiSjV1N50M5pcxZIE3UPp5gTskyp4FJ1FD+KrTJdbpxZIGlZi9ONL72gXhacW/GT2MvoyPx3LcFdweErEGR8StErQ8UCjBKZm58Thl1fH/N1no8xnIJ7+9/A= ;{id = 46980}\r\n\r\n;; ADDITIONAL SECTION:\r\n;; MSG SIZE  rcvd: 471\r\n\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state QUERY RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: query response was NXDOMAIN ANSWER\r\n[1425993073] unbound[25511:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE\r\n[1425993073] unbound[25511:0] info: finishing processing for kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: mesh_run: iterator module exit state is module_finished\r\n[1425993073] unbound[25511:0] debug: validator[module 0] operate: extstate:module_restart_next event:module_event_moddone\r\n[1425993073] unbound[25511:0] info: validator operate: query kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] info: validator operate: chased to . TYPE0 CLASS0\r\n[1425993073] unbound[25511:0] debug: validator: nextmodule returned\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_INIT_STATE\r\n[1425993073] unbound[25511:0] debug: validator classification nameerror\r\n[1425993073] unbound[25511:0] info: signer is . TYPE0 CLASS0\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_FINDKEY_STATE\r\n[1425993073] unbound[25511:0] info: validator: FindKey kdkdkdkkUNBOUND. A IN\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_VALIDATE_STATE\r\n[1425993073] unbound[25511:0] info: verify rrset cached . SOA IN\r\n[1425993073] unbound[25511:0] info: verify rrset ns1.example.com. NSEC IN\r\n[1425993073] unbound[25511:0] debug: verify sig 46980 5\r\n[1425993073] unbound[25511:0] debug: verify: signature mismatch\r\n[1425993073] unbound[25511:0] debug: rrset failed to verify: no valid signatures\r\n[1425993073] unbound[25511:0] debug: verify result: sec_status_bogus\r\n[1425993073] unbound[25511:0] info: validator: response has failed AUTHORITY rrset: ns1.example.com. NSEC IN\r\n[1425993073] unbound[25511:0] info: Validate: message contains bad rrsets\r\n[1425993073] unbound[25511:0] debug: val handle processing q with state VAL_FINISHED_STATE\r\n[1425993073] unbound[25511:0] info: validation failure <kdkdkdkkUNBOUND. A IN>: signature crypto failed for <ns1.example.com. NSEC IN> from 100.96.1.8\r\n[1425993073] unbound[25511:0] debug: mesh_run: validator module exit state is module_finished\r\n[1425993073] unbound[25511:0] debug: query took 0.057499 sec\r\n[1425993073] unbound[25511: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\r\n[1425993073] unbound[25511:0] info: average recursion processing time 0.057499 sec\r\n[1425993073] unbound[25511:0] info: histogram of recursion processing times\r\n[1425993073] unbound[25511:0] info: [25%]=0 median[50%]=0 [75%]=0\r\n[1425993073] unbound[25511:0] info: lower(secs) upper(secs) recursions\r\n[1425993073] unbound[25511:0] info:    0.032768    0.065536 1\r\n[1425993073] unbound[25511:0] debug: cache memory msg=66811 rrset=68935 infra=2897 val=67497\r\n[1425993073] unbound[25511:0] debug: svcd callbacks end\r\n[1425993073] unbound[25511:0] debug: close of port 7248\r\n[1425993073] unbound[25511:0] debug: close fd 9\r\n[1425993122] unbound[25511:0] info: service stopped (unbound 1.5.2).\r\n[1425993122] unbound[25511:0] debug: stop threads\r\n[1425993122] unbound[25511:0] debug: cleanup.\r\n[1425993122] unbound[25511:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch\r\n[1425993122] unbound[25511:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0\r\n[1425993122] unbound[25511:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out\r\n[1425993122] unbound[25511:0] info: average recursion processing time 0.057499 sec\r\n[1425993122] unbound[25511:0] info: histogram of recursion processing times\r\n[1425993122] unbound[25511:0] info: [25%]=0 median[50%]=0 [75%]=0\r\n[1425993122] unbound[25511:0] info: lower(secs) upper(secs) recursions\r\n[1425993122] unbound[25511:0] info:    0.032768    0.065536 1\r\n[1425993122] unbound[25511:0] debug: cache memory msg=66072 rrset=66072 infra=2897 val=67497\r\n[1425993122] unbound[25511:0] debug: Exit cleanup.\r\n[1425993122] unbound[25511:0] debug: switching log to stderr\r\n```"},"comment":{"url":"https://api.github.com/repos/PowerDNS/pdns/issues/comments/78065555","html_url":"https://github.com/PowerDNS/pdns/issues/2344#issuecomment-78065555","issue_url":"https://api.github.com/repos/PowerDNS/pdns/issues/2344","id":78065555,"user":{"login":"jpmens","id":60706,"avatar_url":"https://avatars.githubusercontent.com/u/60706?v=3","gravatar_id":"","url":"https://api.github.com/users/jpmens","html_url":"https://github.com/jpmens","followers_url":"https://api.github.com/users/jpmens/followers","following_url":"https://api.github.com/users/jpmens/following{/other_user}","gists_url":"https://api.github.com/users/jpmens/gists{/gist_id}","starred_url":"https://api.github.com/users/jpmens/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jpmens/subscriptions","organizations_url":"https://api.github.com/users/jpmens/orgs","repos_url":"https://api.github.com/users/jpmens/repos","events_url":"https://api.github.com/users/jpmens/events{/privacy}","received_events_url":"https://api.github.com/users/jpmens/received_events","type":"User","site_admin":false},"created_at":"2015-03-10T14:34:24Z","updated_at":"2015-03-10T14:34:24Z","body":"### Bind\r\n\r\n```\r\n$ dig +norec +dnssec foobar @127.0.0.1 +multiline\r\n;; AUTHORITY SECTION:\r\n.                       300 IN SOA ns1.example.com. hostmaster.example.com. (\r\n                                105        ; serial\r\n                                1800       ; refresh (30 minutes)\r\n                                1800       ; retry (30 minutes)\r\n                                1814400    ; expire (3 weeks)\r\n                                3600       ; minimum (1 hour)\r\n                                )\r\n.                       300 IN RRSIG SOA 5 0 300 (\r\n                                20150409130934 20150310120934 46980 .\r\n                                cAfAkcQLs7Am5bdFCYn2wV141E8Cq85jd65x43/zBEKT\r\n                                ZgwBslVn9wDihTYyrXnbpiGkgmqZTpmh/LGJs1FnLjYX\r\n                                vdh1K+09uk/5YWKRK0wknKxJ79xPkPegJjmrveGG2jxZ\r\n                                D9i42KcgRX6ilaz7jEPLenzKuGoOO70DvN522q4= )\r\n.                       3600 IN NSEC ns1.example.com. A NS SOA TXT RRSIG NSEC DNSKEY\r\n.                       3600 IN RRSIG NSEC 5 0 3600 (\r\n                                20150409130934 20150310120934 46980 .\r\n                                oBrCbGV5jxywIlGkI8GzZ8aG/WaeFjfFBu554SXhrIUD\r\n                                83jZGX0gemzHjtb8GBpYChwRbf6zX8jsfEdOcio2tvI1\r\n                                1qUEoThmSatMT86yEjk6I77eBhaJ+mNW3Z3Sp9vj79eK\r\n                                LUf1l7Siw/9tzL8fwE6Nlh4KUJsjA/aawnkLHQY= )\r\nns1.example.com.        3600 IN NSEC . A RRSIG NSEC\r\nns1.example.com.        3600 IN RRSIG NSEC 5 3 3600 (\r\n                                20150409121329 20150310120027 46980 .\r\n                                b2CYfX7Ea4CfoaGOngG/t2YZnCZxfwDovePA3jCFisHL\r\n                                uMr9j8TuiSjV1N50M5pcxZIE3UPp5gTskyp4FJ1FD+Kr\r\n                                TJdbpxZIGlZi9ONL72gXhacW/GT2MvoyPx3LcFdweErE\r\n                                GR8StErQ8UCjBKZm58Thl1fH/N1no8xnIJ7+9/A= )\r\n\r\n```\r\n\r\n### PowerDNS\r\n\r\n```\r\ndig +norec +dnssec foobar @100.96.1.8 +multiline\r\n;; AUTHORITY SECTION:\r\n.                       300 IN SOA ns1.example.com. hostmaster.example.com. (\r\n                                105        ; serial\r\n                                1800       ; refresh (30 minutes)\r\n                                1800       ; retry (30 minutes)\r\n                                1814400    ; expire (3 weeks)\r\n                                3600       ; minimum (1 hour)\r\n                                )\r\n.                       300 IN RRSIG SOA 5 0 300 (\r\n                                20150409130934 20150310120934 46980 .\r\n                                cAfAkcQLs7Am5bdFCYn2wV141E8Cq85jd65x43/zBEKT\r\n                                ZgwBslVn9wDihTYyrXnbpiGkgmqZTpmh/LGJs1FnLjYX\r\n                                vdh1K+09uk/5YWKRK0wknKxJ79xPkPegJjmrveGG2jxZ\r\n                                D9i42KcgRX6ilaz7jEPLenzKuGoOO70DvN522q4= )\r\nns1.example.com.        3600 IN NSEC A. RRSIG NSEC\r\nns1.example.com.        3600 IN NSEC ns1.example.com. A RRSIG NSEC\r\nns1.example.com.        3600 IN RRSIG NSEC 5 3 3600 (\r\n                                20150409121329 20150310120027 46980 .\r\n                                b2CYfX7Ea4CfoaGOngG/t2YZnCZxfwDovePA3jCFisHL\r\n                                uMr9j8TuiSjV1N50M5pcxZIE3UPp5gTskyp4FJ1FD+Kr\r\n                                TJdbpxZIGlZi9ONL72gXhacW/GT2MvoyPx3LcFdweErE\r\n                                GR8StErQ8UCjBKZm58Thl1fH/N1no8xnIJ7+9/A= )\r\n```\r\n"}}