Hello,
I now manage to build unbound and compile it using my own version ob
openssl-1.1.x as I do not have an other packaged version available.
unbound compile but makte test end with "testdata/autotrust_rollalgo.rpl failed"
I run ./testbound -p testdata/autotrust_rollalgo.rpl and attach the output.
May my openssl build be not compatible / missing a feature?
Andreas
[1477405490] unbound[26329:0] info: Start of unbound 1.5.10 testbound program.
testbound is spooling key file: /tmp/testbound_26329_auto_example.com.tmp
[1477405490] unbound[26329:0] info: Scenario has 35 steps
[1477405490] unbound[26329:0] info: Scenario: Test autotrust with algorithm rollover
testbound is starting: [unbound] [-d] [-c] [/tmp/testbound_26329_cfg.tmp]
Oct 25 14:24:50 unbound[26329:0] notice: init module 0: validator
Oct 25 14:24:50 unbound[26329:0] notice: init module 1: iterator
Jan 01 00:00:00 unbound[26329:0] info: fake timer set 0.000000
Jan 01 00:00:00 unbound[26329:0] info: start of service (unbound 1.5.10).
Jan 01 00:00:00 unbound[26329:0] info: testbound: entering fake runloop
Jan 01 00:00:00 unbound[26329:0] info: testbound: do STEP 5 TIME_PASSES
Aug 24 07:46:40 unbound[26329:0] info: elapsed 1251100000.000000 now 1251100000.000000
Aug 24 07:46:40 unbound[26329:0] info: fake_timer callback
Aug 24 07:46:40 unbound[26329:0] info: pending serviced query . NS IN
Aug 24 07:46:40 unbound[26329:0] notice: pending serviced query zone . flags CD DO
Aug 24 07:46:40 unbound[26329:0] info: testbound: created fake pending
Aug 24 07:46:40 unbound[26329:0] info: fake timer set 3412.000000
Aug 24 07:46:40 unbound[26329:0] info: testbound: end of event stage
Aug 24 07:46:40 unbound[26329:0] info: check of pending
Aug 24 07:46:40 unbound[26329:0] info: matched query time 6 in range [0, 100] with entry line 23
Aug 24 07:46:40 unbound[26329:0] debug: matched ip 193.0.14.129 port 53
Aug 24 07:46:40 unbound[26329:0] info: matched pkt: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
. IN NS
;; ANSWER SECTION:
. 3600 IN NS k.root-servers.net.
;; AUTHORITY SECTION:
;; ADDITIONAL SECTION:
k.root-servers.net. 3600 IN A 193.0.14.129
;; MSG SIZE rcvd: 82
Aug 24 07:46:40 unbound[26329:0] info: serviced pending delete
Aug 24 07:46:40 unbound[26329:0] info: pending serviced query example.com. DNSKEY IN
Aug 24 07:46:40 unbound[26329:0] notice: pending serviced query zone . flags DO
Aug 24 07:46:40 unbound[26329:0] info: testbound: created fake pending
Aug 24 07:46:40 unbound[26329:0] info: testbound: end of event stage
Aug 24 07:46:40 unbound[26329:0] info: check of pending
Aug 24 07:46:40 unbound[26329:0] info: matched query time 6 in range [0, 100] with entry line 35
Aug 24 07:46:40 unbound[26329:0] debug: matched ip 193.0.14.129 port 53
Aug 24 07:46:40 unbound[26329:0] info: matched pkt: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1
;; QUESTION SECTION:
com. IN NS
;; ANSWER SECTION:
;; AUTHORITY SECTION:
com. 3600 IN NS a.gtld-servers.net.
;; ADDITIONAL SECTION:
a.gtld-servers.net. 3600 IN A 192.5.6.30
;; MSG SIZE rcvd: 90
Aug 24 07:46:40 unbound[26329:0] info: serviced pending delete
Aug 24 07:46:40 unbound[26329:0] info: pending serviced query example.com. DNSKEY IN
Aug 24 07:46:40 unbound[26329:0] notice: pending serviced query zone com. flags DO
Aug 24 07:46:40 unbound[26329:0] info: testbound: created fake pending
Aug 24 07:46:40 unbound[26329:0] info: testbound: end of event stage
Aug 24 07:46:40 unbound[26329:0] info: check of pending
Aug 24 07:46:40 unbound[26329:0] info: matched query time 6 in range [0, 100] with entry line 51
Aug 24 07:46:40 unbound[26329:0] debug: matched ip 192.5.6.30 port 53
Aug 24 07:46:40 unbound[26329:0] info: matched pkt: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1
;; QUESTION SECTION:
example.com. IN NS
;; ANSWER SECTION:
;; AUTHORITY SECTION:
example.com. 3600 IN NS ns.example.com.
;; ADDITIONAL SECTION:
ns.example.com. 3600 IN A 1.2.3.4
;; MSG SIZE rcvd: 98
Aug 24 07:46:40 unbound[26329:0] info: serviced pending delete
Aug 24 07:46:40 unbound[26329:0] info: pending serviced query example.com. DNSKEY IN
Aug 24 07:46:40 unbound[26329:0] notice: pending serviced query zone example.com. flags DO
Aug 24 07:46:40 unbound[26329:0] info: testbound: created fake pending
Aug 24 07:46:40 unbound[26329:0] info: testbound: end of event stage
Aug 24 07:46:40 unbound[26329:0] info: check of pending
Aug 24 07:46:40 unbound[26329:0] info: matched query time 6 in range [0, 10] with entry line 84
Aug 24 07:46:40 unbound[26329:0] debug: matched ip 1.2.3.4 port 53
Aug 24 07:46:40 unbound[26329:0] info: matched pkt: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
example.com. IN DNSKEY
;; ANSWER SECTION:
example.com. 10800 IN DNSKEY 257 3 5 AwEAAc3Z5DQDJpH4oPdNtC4BUQHk50XMD+dHr4r8psHmivIa83hxR5CRgCtd9sENCW9Ae8OIO19xw9t/RPaEAqQa+OE= ;{id = 55582 (ksk), size = 512b}
example.com. 10800 IN DNSKEY 256 3 5 AQPQ41chR9DEHt/aIzIFAqanbDlRflJoRs5yz1jFsoRIT7dWf0r+PeDuewdxkszNH6wnU4QL8pfKFRh5PIYVBLK3 ;{id = 30899 (zsk), size = 512b}
example.com. 10800 IN RRSIG DNSKEY 5 2 10800 20090924111500 20090821111500 30899 example.com. b/HK231jIQLX8IhlZfup3r0yhpXaasbPE6LzxoEVVvWaTZWcLmeV8jDIcn0qO7Yvs7bIJN20lwVAV0GcHH3hWQ== ;{id = 30899}
example.com. 10800 IN RRSIG DNSKEY 5 2 10800 20090924111500 20090821111500 55582 example.com. PCHme1QLoULxqjhg5tMlpR0qJlBfstEUVq18TtNoKQe9le1YhJ9caheXcTWoK+boLhXxg9u6Yyvq8FboQh0OjA== ;{id = 55582}
;; AUTHORITY SECTION:
;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 453
Aug 24 07:46:40 unbound[26329:0] info: serviced pending delete
Aug 24 07:46:40 unbound[26329:0] info: fake timer set 5188.000000
Aug 24 07:46:40 unbound[26329:0] info: fake timer set 5188.000000
Aug 24 07:46:40 unbound[26329:0] info: testbound: end of event stage
Aug 24 07:46:40 unbound[26329:0] info: testbound: do STEP 6 TRAFFIC
Aug 24 07:46:40 unbound[26329:0] info: testbound: end of event stage
Aug 24 07:46:40 unbound[26329:0] info: testbound: do STEP 7 ASSIGN
Aug 24 07:46:40 unbound[26329:0] info: assign t0 = 1251100000
Aug 24 07:46:40 unbound[26329:0] info: testbound: end of event stage
Aug 24 07:46:40 unbound[26329:0] info: testbound: do STEP 8 ASSIGN
Aug 24 07:46:40 unbound[26329:0] info: assign probe0 = 5188
Aug 24 07:46:40 unbound[26329:0] info: testbound: end of event stage
Aug 24 07:46:40 unbound[26329:0] info: testbound: do STEP 10 CHECK_AUTOTRUST
/tmp/testbound_26329_auto_example.com.tmp: 1 ok : ; autotrust trust anchor file
/tmp/testbound_26329_auto_example.com.tmp: 2 ok : ;;id: example.com. 1
/tmp/testbound_26329_auto_example.com.tmp: 3 ok : ;;last_queried: 1251100000 ;;Mon Aug 24 07:46:40 2009
/tmp/testbound_26329_auto_example.com.tmp: 4 ok : ;;last_success: 1251100000 ;;Mon Aug 24 07:46:40 2009
/tmp/testbound_26329_auto_example.com.tmp: 5 ok : ;;next_probe_time: 1251105188 ;;Mon Aug 24 09:13:08 2009
/tmp/testbound_26329_auto_example.com.tmp: 6 ok : ;;query_failed: 0
/tmp/testbound_26329_auto_example.com.tmp: 7 ok : ;;query_interval: 5400
/tmp/testbound_26329_auto_example.com.tmp: 8 ok : ;;retry_time: 3600
/tmp/testbound_26329_auto_example.com.tmp: 9 ok : example.com. 10800 IN DNSKEY 257 3 5 AwEAAc3Z5DQDJpH4oPdNtC4BUQHk50XMD+dHr4r8psHmivIa83hxR5CRgCtd9sENCW9Ae8OIO19xw9t/RPaEAqQa+OE= ;{id = 55582 (ksk), size = 512b} ;;state=2 [ VALID ] ;;count=0 ;;lastchange=1251100000 ;;Mon Aug 24 07:46:40 2009
Aug 24 07:46:40 unbound[26329:0] info: autotrust example.com is OK
Aug 24 07:46:40 unbound[26329:0] info: testbound: end of event stage
Aug 24 07:46:40 unbound[26329:0] info: testbound: do STEP 11 TIME_PASSES
Sep 23 07:46:40 unbound[26329:0] info: elapsed 2592000.000000 now 1253692000.000000
Sep 23 07:46:40 unbound[26329:0] info: fake_timer callback
Sep 23 07:46:40 unbound[26329:0] info: pending serviced query . NS IN
Sep 23 07:46:40 unbound[26329:0] notice: pending serviced query zone . flags CD DO
Sep 23 07:46:40 unbound[26329:0] info: testbound: created fake pending
Sep 23 07:46:40 unbound[26329:0] info: fake timer set 3374.000000
Sep 23 07:46:40 unbound[26329:0] info: testbound: end of event stage
Sep 23 07:46:40 unbound[26329:0] info: check of pending
Sep 23 07:46:40 unbound[26329:0] info: matched query time 12 in range [0, 100] with entry line 23
Sep 23 07:46:40 unbound[26329:0] debug: matched ip 193.0.14.129 port 53
Sep 23 07:46:40 unbound[26329:0] info: matched pkt: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; QUESTION SECTION:
. IN NS
;; ANSWER SECTION:
. 3600 IN NS k.root-servers.net.
;; AUTHORITY SECTION:
;; ADDITIONAL SECTION:
k.root-servers.net. 3600 IN A 193.0.14.129
;; MSG SIZE rcvd: 82
Sep 23 07:46:40 unbound[26329:0] info: serviced pending delete
Sep 23 07:46:40 unbound[26329:0] info: pending serviced query example.com. DNSKEY IN
Sep 23 07:46:40 unbound[26329:0] notice: pending serviced query zone . flags DO
Sep 23 07:46:40 unbound[26329:0] info: testbound: created fake pending
Sep 23 07:46:40 unbound[26329:0] info: testbound: end of event stage
Sep 23 07:46:40 unbound[26329:0] info: check of pending
Sep 23 07:46:40 unbound[26329:0] info: matched query time 12 in range [0, 100] with entry line 35
Sep 23 07:46:40 unbound[26329:0] debug: matched ip 193.0.14.129 port 53
Sep 23 07:46:40 unbound[26329:0] info: matched pkt: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1
;; QUESTION SECTION:
com. IN NS
;; ANSWER SECTION:
;; AUTHORITY SECTION:
com. 3600 IN NS a.gtld-servers.net.
;; ADDITIONAL SECTION:
a.gtld-servers.net. 3600 IN A 192.5.6.30
;; MSG SIZE rcvd: 90
Sep 23 07:46:40 unbound[26329:0] info: serviced pending delete
Sep 23 07:46:40 unbound[26329:0] info: pending serviced query example.com. DNSKEY IN
Sep 23 07:46:40 unbound[26329:0] notice: pending serviced query zone com. flags DO
Sep 23 07:46:40 unbound[26329:0] info: testbound: created fake pending
Sep 23 07:46:40 unbound[26329:0] info: testbound: end of event stage
Sep 23 07:46:40 unbound[26329:0] info: check of pending
Sep 23 07:46:40 unbound[26329:0] info: matched query time 12 in range [0, 100] with entry line 51
Sep 23 07:46:40 unbound[26329:0] debug: matched ip 192.5.6.30 port 53
Sep 23 07:46:40 unbound[26329:0] info: matched pkt: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1
;; QUESTION SECTION:
example.com. IN NS
;; ANSWER SECTION:
;; AUTHORITY SECTION:
example.com. 3600 IN NS ns.example.com.
;; ADDITIONAL SECTION:
ns.example.com. 3600 IN A 1.2.3.4
;; MSG SIZE rcvd: 98
Sep 23 07:46:40 unbound[26329:0] info: serviced pending delete
Sep 23 07:46:40 unbound[26329:0] info: pending serviced query example.com. DNSKEY IN
Sep 23 07:46:40 unbound[26329:0] notice: pending serviced query zone example.com. flags DO
Sep 23 07:46:40 unbound[26329:0] info: testbound: created fake pending
Sep 23 07:46:40 unbound[26329:0] info: testbound: end of event stage
Sep 23 07:46:40 unbound[26329:0] info: check of pending
Sep 23 07:46:40 unbound[26329:0] info: matched query time 12 in range [11, 40] with entry line 104
Sep 23 07:46:40 unbound[26329:0] debug: matched ip 1.2.3.4 port 53
Sep 23 07:46:40 unbound[26329:0] info: matched pkt: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
example.com. IN DNSKEY
;; ANSWER SECTION:
example.com. 10800 IN DNSKEY 257 3 5 AwEAAc3Z5DQDJpH4oPdNtC4BUQHk50XMD+dHr4r8psHmivIa83hxR5CRgCtd9sENCW9Ae8OIO19xw9t/RPaEAqQa+OE= ;{id = 55582 (ksk), size = 512b}
example.com. 10800 IN DNSKEY 257 3 3 ALXLUsWqUrY3JYER3T4TBJIIs70j+sDS/UT2QRp61SE7S3EEXopNXoFE73JLRmvpi/UrOO/Vz4Se6wXv/CYCKjGw06U4WRgRYXcpEhJROyNapmdIKSxhOzfLVE1gqA0PweZR8dtY3aNQSRn3sPpwJr6Mi/PqQKAMMrZ9ckJpf1+bQMOOvxgzz2U1GS18b3yZKcgTMEaJzd/GZYzi/BN2DzQ0MsrSwYXfsNLFOBbs8PJMW4LYIxeeOe6rUgkWOF7CC9Dh/dduQ1QrsJhmZAEFfd6ByYV+ ;{id = 2855 (ksk), size = 512b}
example.com. 10800 IN RRSIG DNSKEY 5 2 10800 20091024111500 20090921111500 55582 example.com. aCZVA+PLXxm15p46499FCPHvhR/MSpMSRTZT6PoUy2e+wdk7bszLdsEmfWym81UN2Xx1JOj5104c43c3QnvjNQ== ;{id = 55582}
example.com. 10800 IN RRSIG DNSKEY 3 2 10800 20091024111500 20090921111500 2855 example.com. AKdhmjqEbe0STsFNq/UxOidElaWHWCy2hSPQ7oN0Tsq56w6Hsk72PpM= ;{id = 2855}
;; AUTHORITY SECTION:
;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 577
Sep 23 07:46:40 unbound[26329:0] info: serviced pending delete
Sep 23 07:46:40 unbound[26329:0] info: fake timer set 4928.000000
Sep 23 07:46:40 unbound[26329:0] info: fake timer set 4928.000000
Sep 23 07:46:40 unbound[26329:0] info: testbound: end of event stage
Sep 23 07:46:40 unbound[26329:0] info: testbound: do STEP 12 TRAFFIC
Sep 23 07:46:40 unbound[26329:0] info: testbound: end of event stage
Sep 23 07:46:40 unbound[26329:0] info: testbound: do STEP 13 ASSIGN
Sep 23 07:46:40 unbound[26329:0] info: assign t1 = 1253692000
Sep 23 07:46:40 unbound[26329:0] info: testbound: end of event stage
Sep 23 07:46:40 unbound[26329:0] info: testbound: do STEP 14 ASSIGN
Sep 23 07:46:40 unbound[26329:0] info: assign probe1 = 4928
Sep 23 07:46:40 unbound[26329:0] info: testbound: end of event stage
Sep 23 07:46:40 unbound[26329:0] info: testbound: do STEP 15 CHECK_AUTOTRUST
/tmp/testbound_26329_auto_example.com.tmp: 1 ok : ; autotrust trust anchor file
/tmp/testbound_26329_auto_example.com.tmp: 2 ok : ;;id: example.com. 1
/tmp/testbound_26329_auto_example.com.tmp: 3 ok : ;;last_queried: 1253692000 ;;Wed Sep 23 07:46:40 2009
/tmp/testbound_26329_auto_example.com.tmp: 4 ok : ;;last_success: 1253692000 ;;Wed Sep 23 07:46:40 2009
/tmp/testbound_26329_auto_example.com.tmp: 5 ok : ;;next_probe_time: 1253696928 ;;Wed Sep 23 09:08:48 2009
/tmp/testbound_26329_auto_example.com.tmp: 6 ok : ;;query_failed: 0
/tmp/testbound_26329_auto_example.com.tmp: 7 ok : ;;query_interval: 5400
/tmp/testbound_26329_auto_example.com.tmp: 8 ok : ;;retry_time: 3600
Sep 23 07:46:40 unbound[26329:0] error: mismatch in file /tmp/testbound_26329_auto_example.com.tmp, line 9
Sep 23 07:46:40 unbound[26329:0] error: file has : example.com. 10800 IN DNSKEY 257 3 5 AwEAAc3Z5DQDJpH4oPdNtC4BUQHk50XMD+dHr4r8psHmivIa83hxR5CRgCtd9sENCW9Ae8OIO19xw9t/RPaEAqQa+OE= ;{id = 55582 (ksk), size = 512b} ;;state=2 [ VALID ] ;;count=0 ;;lastchange=1251100000 ;;Mon Aug 24 07:46:40 2009
Sep 23 07:46:40 unbound[26329:0] error: should be: example.com. 10800 IN DNSKEY 257 3 3 ALXLUsWqUrY3JYER3T4TBJIIs70j+sDS/UT2QRp61SE7S3EEXopNXoFE73JLRmvpi/UrOO/Vz4Se6wXv/CYCKjGw06U4WRgRYXcpEhJROyNapmdIKSxhOzfLVE1gqA0PweZR8dtY3aNQSRn3sPpwJr6Mi/PqQKAMMrZ9ckJpf1+bQMOOvxgzz2U1GS18b3yZKcgTMEaJzd/GZYzi/BN2DzQ0MsrSwYXfsNLFOBbs8PJMW4LYIxeeOe6rUgkWOF7CC9Dh/dduQ1QrsJhmZAEFfd6ByYV+ ;{id = 2855 (ksk), size = 512b} ;;state=1 [ ADDPEND ] ;;count=1 ;;lastchange=1253692000 ;;Wed Sep 23 07:46:40 2009
Sep 23 07:46:40 unbound[26329:0] error: autotrust check failed, could not read line
Sep 23 07:46:40 unbound[26329:0] error: file /tmp/testbound_26329_auto_example.com.tmp, line 10
Sep 23 07:46:40 unbound[26329:0] error: should be: example.com. 10800 IN DNSKEY 257 3 5 AwEAAc3Z5DQDJpH4oPdNtC4BUQHk50XMD+dHr4r8psHmivIa83hxR5CRgCtd9sENCW9Ae8OIO19xw9t/RPaEAqQa+OE= ;{id = 55582 (ksk), size = 512b} ;;state=2 [ VALID ] ;;count=0 ;;lastchange=${$t0} ;;${ctime $t0}
Sep 23 07:46:40 unbound[26329:0] fatal error: autotrust_check failed
