Small zone update took 13 seconds to complete
dnssec:checking that the NSEC3 record for the apex is properly signed when a DNSKEY is added via UPDATE
system test failed with:
I:dnssec:checking that the NSEC3 record for the apex is properly signed when a DNSKEY is added via UPDATE (159)
; Communication with 10.53.0.3#30812 failed: timed out
I:dnssec:stopping servers
R:dnssec:FAIL
E:dnssec:2022-05-09T09:25:06+0000
FAIL dnssec (exit status: 2)
Communication with 10.53.0.3#30812 failed: timed out
comes from this nsupdate
code:
(
echo zone update-nsec3.example
echo server 10.53.0.3 "$PORT"
grep DNSKEY "${kskname}.key" | sed -e 's/^/update add /' -e 's/IN/300 IN/'
echo send
) | $NSUPDATE
The default nsupdate
timeout is 12 second:
$ time ( echo -e "zone update-nsec3.example\nserver 10.53.0.3 12345\nsend" | nsupdate )
; Communication with 10.53.0.3#12345 failed: timed out
real 0m12.040s
According to ns3/named.run
it seems that the zone update took 13 seconds to complete/fail (send failed: operation canceled
):
09-May-2022 09:24:51.064 clientmgr @0x60c000006700 attach: 2
09-May-2022 09:24:51.064 query client=0x61f000151c80 thread=0x7f23f7f62640(<unknown-query>): query_reset
09-May-2022 09:24:51.064 client @0x61f000151c80 (no-peer): allocate new client
09-May-2022 09:24:51.064 client @0x61f000151c80 10.53.0.1#49014: UDP request
09-May-2022 09:24:51.064 client @0x61f000151c80 10.53.0.1#49014: using view '_default'
09-May-2022 09:24:51.064 client @0x61f000151c80 10.53.0.1#49014: request is not signed
09-May-2022 09:24:51.064 client @0x61f000151c80 10.53.0.1#49014: recursion not available
09-May-2022 09:24:51.064 client @0x61f000151c80 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': prerequisites are OK
09-May-2022 09:24:51.064 client @0x61f000151c80 10.53.0.1#49014: update 'update-nsec3.example/IN' approved
09-May-2022 09:24:51.064 client @0x61f000151c80 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': update section prescan OK
09-May-2022 09:24:51.064 client @0x61f000151c80 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': adding an RR at 'update-nsec3.example' DNSKEY 257 3 7 AwEAAcMtKfINfZtuWA/i2KM2Ppi7pRaUOzARZhOYUGjOojSvPyhAWOXh t7GjbITaUQH7tKEyEK0ZD2OshdnqEu4+6hW3cLaKlgTYxJX86++zqnJb eEhtz9ARhyKGIE02kNMjFhAh7wkn33VcV7bQzLjf5jJsNi5+5FioxEXr sGPMoB+7k/Cq+GvNRVyQCosMhvE517osbEOyh5RLRGuDGs789wSSH/IW fOPoZunJxrEvs8wehrnMDyA4zdOCpxmQs1VygFX4NeVoyLRVKwGyfHy0 vyrJHTVs8BRM1nNsOMZpCtZWPQRX828tPV9yyMUqU6ERxWdUf5a3l2fi 6DVYcb1N278=
09-May-2022 09:24:51.064 client @0x61f000151c80 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': checking for NSEC3PARAM changes
09-May-2022 09:24:51.068 client @0x61f000151c80 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': updated data signatures
09-May-2022 09:24:51.068 client @0x61f000151c80 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': removed any orphaned NSEC records
09-May-2022 09:24:51.068 client @0x61f000151c80 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': rebuilding NSEC3 chains
09-May-2022 09:24:51.068 client @0x61f000151c80 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': signing rebuilt NSEC3 chain
09-May-2022 09:24:51.068 client @0x61f000151c80 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': writing journal update-nsec3.example.db.signed.jnl
09-May-2022 09:24:51.068 journal file update-nsec3.example.db.signed.jnl does not exist, creating it
09-May-2022 09:24:51.068 writing to journal
09-May-2022 09:24:51.068 del update-nsec3.example. 300 IN SOA mname1. . 2000042407 20 20 1814400 3600
09-May-2022 09:24:51.068 del update-nsec3.example. 300 IN RRSIG SOA 13 2 300 20220608082241 20220509082241 14802 update-nsec3.example. SijqLjgxJdEDXVtpjheS8LkNBb5AgbPFLVNagGBpm9sMyvtNiNxjoV+V jETZDUkRJMjFTiItYhawE55ws+K6og==
09-May-2022 09:24:51.068 del update-nsec3.example. 300 IN RRSIG DNSKEY 13 2 300 20220608082241 20220509082241 14802 update-nsec3.example. GGF25XNZQU1G4sNDpbP8LbDDN7h7Bq1MQ/JfCp0mUjAemkTYUmj2+wGd kdyk3lOvIDo4Po8gCV6KLLe0hQJwBw==
09-May-2022 09:24:51.068 del update-nsec3.example. 300 IN RRSIG DNSKEY 13 2 300 20220608082241 20220509082241 25481 update-nsec3.example. 9YjF2dDh+2ryxCYLtBpB1uQor8zv7YUUXJV1vZwztoOEG3V6tVO6SLp2 0Mo3xguexDWJUpQMcbRL1AnMtuxWyA==
09-May-2022 09:24:51.068 del B8V5JKM06MQ7LQCJ60FGESOBNV5MCNUH.update-nsec3.example. 300 IN RRSIG NSEC3 13 3 300 20220608082241 20220509082241 14802 update-nsec3.example. MnwzTiwzEmxRM+ebwBskZQz7pKk+Tyunv0QXgwfRVtvvO6BsqfAi1OBG I9PL7mKijThyEw2ZHiSk4rZ8JtqoVg==
09-May-2022 09:24:51.068 del B8V5JKM06MQ7LQCJ60FGESOBNV5MCNUH.update-nsec3.example. 300 IN NSEC3 1 0 10 - B9VFOBC8CSPMRSJC47TM47PIPT9HENS9 NS SOA RRSIG DNSKEY NSEC3PARAM
09-May-2022 09:24:51.068 add update-nsec3.example. 300 IN SOA mname1. . 2000042408 20 20 1814400 3600
09-May-2022 09:24:51.068 add re-sign update-nsec3.example. 300 IN RRSIG SOA 7 2 300 20220608092451 20220509082451 2148 update-nsec3.example. NrdVuqNT17I05O4oaUYnQf8qNXYb9PitF2xgQnhc6oJLnEwGQ+LGskOF epLpJsnVxW4z4ZT6Xy9n/Ynd6V+duug9R0sPdEBOTvCWiXb+mpjMQxQL /7gncZFKMN72g7RiaYBgC2u7R+ha0efippyur10OMuPRWvz0t2CDRLVE JfyGXWnWWZFAMhoEHOAJsghU1i8MFs4SM3cOndJEh0p5PT1jU0wo6/hS pyUWmR27eDrAYsrxd/ZChVkicYhpA8eChb6xHRYk3/Ui8cEYqh8p2N8n BDy+92vNMWFO3aCYDX4f0FRwbzMpZ5rtKBNxRnw6NhD+3bgGJUV8a8Od QxbWBA==
09-May-2022 09:24:51.068 add re-sign update-nsec3.example. 300 IN RRSIG SOA 13 2 300 20220608092451 20220509082451 14802 update-nsec3.example. MVXp+aeCkf3OC3ncn0UxHSRQp7WXCpmOg4FhG6iRkEnCENHTpPnPo5BQ nhtQ+Z67yoCuQcAEn36l5nuOaO03KA==
09-May-2022 09:24:51.068 add re-sign update-nsec3.example. 300 IN RRSIG DNSKEY 7 2 300 20220605041617 20220509082451 2148 update-nsec3.example. qInTflpkllghyHsC77oDG4BvMLlScV8te5NFgWi2L6VFmkrvgQHV0bob bK5+ItF8erMOBUqLb+ljW9aJkmmriy6pUT4e4e442LTkquuB3FkaOQaN Mv2ivjlEVKvF3o426eYL1cLb9+jd4WHpJsOajmy9nJ3xr9GlcWNLldUo PCMdXMU1bTk86wVa40MKxuFEK4M+PUiGx8FoWSweI2JBjzUcDqCNUU23 dFZ3r8TyQXPK8wNWOLUukHbAenCRYFsC8u5Cfey3fjU43vQigM3U9jHH dWQsSVyo6/Kr7LqWMye+xppO2qCVHd4FSif5ZwTMR2D3c1GFpG7CH7s9 byOS/A==
09-May-2022 09:24:51.068 add re-sign update-nsec3.example. 300 IN RRSIG DNSKEY 13 2 300 20220605041617 20220509082451 25481 update-nsec3.example. R7kmOVYTkWQnvCL40MsDLNlAKRy90Qe3zxnuCcirNWPkT80WjLZvnZX7 yRwnd5dfze7FgJGus72hDL1oiAKGdw==
09-May-2022 09:24:51.068 add re-sign update-nsec3.example. 0 IN RRSIG TYPE65534 7 2 0 20220605041617 20220509082451 2148 update-nsec3.example. OLuKSExxvWIqBSoe6NsVx/2gBJWvMfDDfav0ot2ujN7d3GQNAdjFWM5S yvPrzUQzLgeuDqqQ3de0kpnynQGOMHS+STsHaIrq817+F2GIhOmN98cS HNUSoc7HVcD6XqTun4JVTYPM2brA80LdtROj56ZV/7Zq/F4W8IDySMDy FMJQzL2BwkkhRTKpswMZqhlal3VYCJosWC5YX5FwvQ/N9tjY0n9mCRYe xo2whWjl17ESXapHcCKxcOnHKHc1XMkYUlyNuTxnlqiyITAKFAavv/+f weV+LuhDKXVk+7U3qpl8Ef52qdskwUIc7Gguxw+1wZXeDB2aszex78n7 RufmJA==
09-May-2022 09:24:51.068 add re-sign update-nsec3.example. 0 IN RRSIG TYPE65534 13 2 0 20220605041617 20220509082451 14802 update-nsec3.example. okd7cM0dOW7e2NEDtVED/8rB7o5N2n09DvStk7vu7raLosLbJxz/tz1K NQj5/A0FtolGSNsJSYSc5ApDhzt9vw==
09-May-2022 09:24:51.068 add re-sign B8V5JKM06MQ7LQCJ60FGESOBNV5MCNUH.update-nsec3.example. 300 IN RRSIG NSEC3 13 3 300 20220605041617 20220509082451 14802 update-nsec3.example. KH+YTWy3JSPjjAdZfwRn4qxMl4pJRdzM+n/DZvKGZ4Qv7hFMVSEjeCxJ XKbjqz2QmtVX3F5RILO+GA9inhNYMg==
09-May-2022 09:24:51.068 add re-sign B8V5JKM06MQ7LQCJ60FGESOBNV5MCNUH.update-nsec3.example. 300 IN RRSIG NSEC3 7 3 300 20220605041617 20220509082451 2148 update-nsec3.example. TgIZzfZ9pYENI7pFdydADeNg2W/wMdFJcLYFrU5RFyppHn6lK1HikskK AU7YtSR9+NDzlZjp6gCxPXr56if8ARXbwOhHRMBWR26xfdwlq36FizWp mM0j91tjXwmyLVsmppxw+SCURq1k6mpq+I9ZN856vrswLVHEf2bpq2pe LC+9gt3x4aeVdMuyS4yel5YeIRgNmZ3kiL4RkXWA8xiXWAOfnVl3Vrtt aJu0M+LouFr/ICzKwHFlfS2p/uYS8XwOJhywSHKueLHGAlrA0G1u9iGW of1N/8omkT7NVf43tFjc+m9ANmmHVhRhe+g/zpzzoIorMIB/R2c+gSmk DWDhWA==
09-May-2022 09:24:51.068 add update-nsec3.example. 300 IN DNSKEY 257 3 7 AwEAAcMtKfINfZtuWA/i2KM2Ppi7pRaUOzARZhOYUGjOojSvPyhAWOXh t7GjbITaUQH7tKEyEK0ZD2OshdnqEu4+6hW3cLaKlgTYxJX86++zqnJb eEhtz9ARhyKGIE02kNMjFhAh7wkn33VcV7bQzLjf5jJsNi5+5FioxEXr sGPMoB+7k/Cq+GvNRVyQCosMhvE517osbEOyh5RLRGuDGs789wSSH/IW fOPoZunJxrEvs8wehrnMDyA4zdOCpxmQs1VygFX4NeVoyLRVKwGyfHy0 vyrJHTVs8BRM1nNsOMZpCtZWPQRX828tPV9yyMUqU6ERxWdUf5a3l2fi 6DVYcb1N278=
09-May-2022 09:24:51.068 add B8V5JKM06MQ7LQCJ60FGESOBNV5MCNUH.update-nsec3.example. 300 IN NSEC3 1 0 10 - B9VFOBC8CSPMRSJC47TM47PIPT9HENS9 NS SOA RRSIG DNSKEY NSEC3PARAM TYPE65534
09-May-2022 09:24:51.068 add update-nsec3.example. 0 IN TYPE65534 \# 5 0708640000
09-May-2022 09:24:54.068 clientmgr @0x60c000006700 attach: 3
09-May-2022 09:24:54.716 query client=0x61f000152a80 thread=0x7f23f7f62640(<unknown-query>): query_reset
09-May-2022 09:24:54.716 client @0x61f000152a80 (no-peer): allocate new client
09-May-2022 09:24:54.716 client @0x61f000152a80 10.53.0.1#49014: UDP request
09-May-2022 09:24:54.716 client @0x61f000152a80 10.53.0.1#49014: using view '_default'
09-May-2022 09:24:54.716 client @0x61f000152a80 10.53.0.1#49014: request is not signed
09-May-2022 09:24:54.716 client @0x61f000152a80 10.53.0.1#49014: recursion not available
09-May-2022 09:24:57.072 clientmgr @0x60c000006700 attach: 4
09-May-2022 09:24:57.072 query client=0x61f000153880 thread=0x7f23f7f62640(<unknown-query>): query_reset
09-May-2022 09:24:57.072 client @0x61f000153880 (no-peer): allocate new client
09-May-2022 09:24:57.072 client @0x61f000153880 10.53.0.1#49014: UDP request
09-May-2022 09:24:57.072 client @0x61f000153880 10.53.0.1#49014: using view '_default'
09-May-2022 09:24:57.072 client @0x61f000153880 10.53.0.1#49014: request is not signed
09-May-2022 09:24:57.072 client @0x61f000153880 10.53.0.1#49014: recursion not available
09-May-2022 09:25:00.076 clientmgr @0x60c000006700 attach: 5
09-May-2022 09:25:00.076 query client=0x61f000154680 thread=0x7f23f7f62640(<unknown-query>): query_reset
09-May-2022 09:25:00.076 client @0x61f000154680 (no-peer): allocate new client
09-May-2022 09:25:00.076 client @0x61f000154680 10.53.0.1#49014: UDP request
09-May-2022 09:25:00.076 client @0x61f000154680 10.53.0.1#49014: using view '_default'
09-May-2022 09:25:00.076 client @0x61f000154680 10.53.0.1#49014: request is not signed
09-May-2022 09:25:00.076 client @0x61f000154680 10.53.0.1#49014: recursion not available
09-May-2022 09:25:03.120 no longer listening on 10.53.0.3#30812
09-May-2022 09:25:04.108 client @0x61f000151c80 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': committing update transaction
09-May-2022 09:25:04.108 zone_settimer: zone update-nsec3.example/IN: enter
09-May-2022 09:25:04.108 zone_needdump: zone update-nsec3.example/IN: enter
09-May-2022 09:25:04.108 zone_settimer: zone update-nsec3.example/IN: enter
09-May-2022 09:25:04.108 zone_settimer: zone update-nsec3.example/IN: enter
09-May-2022 09:25:04.108 zone update-nsec3.example/IN: dns_zone_signwithkey(algorithm=7, keyid=2148)
09-May-2022 09:25:04.108 zone_settimer: zone update-nsec3.example/IN: enter
09-May-2022 09:25:04.108 client @0x61f000152a80 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': prerequisites are OK
09-May-2022 09:25:04.108 client @0x61f000152a80 10.53.0.1#49014: update 'update-nsec3.example/IN' approved
09-May-2022 09:25:04.108 client @0x61f000152a80 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': update section prescan OK
09-May-2022 09:25:04.108 client @0x61f000152a80 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': adding an RR at 'update-nsec3.example' DNSKEY 257 3 7 AwEAAcMtKfINfZtuWA/i2KM2Ppi7pRaUOzARZhOYUGjOojSvPyhAWOXh t7GjbITaUQH7tKEyEK0ZD2OshdnqEu4+6hW3cLaKlgTYxJX86++zqnJb eEhtz9ARhyKGIE02kNMjFhAh7wkn33VcV7bQzLjf5jJsNi5+5FioxEXr sGPMoB+7k/Cq+GvNRVyQCosMhvE517osbEOyh5RLRGuDGs789wSSH/IW fOPoZunJxrEvs8wehrnMDyA4zdOCpxmQs1VygFX4NeVoyLRVKwGyfHy0 vyrJHTVs8BRM1nNsOMZpCtZWPQRX828tPV9yyMUqU6ERxWdUf5a3l2fi 6DVYcb1N278=
09-May-2022 09:25:04.108 client @0x61f000152a80 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': redundant request
09-May-2022 09:25:04.108 client @0x61f000153880 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': prerequisites are OK
09-May-2022 09:25:04.108 client @0x61f000153880 10.53.0.1#49014: update 'update-nsec3.example/IN' approved
09-May-2022 09:25:04.108 client @0x61f000153880 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': update section prescan OK
09-May-2022 09:25:04.108 client @0x61f000153880 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': adding an RR at 'update-nsec3.example' DNSKEY 257 3 7 AwEAAcMtKfINfZtuWA/i2KM2Ppi7pRaUOzARZhOYUGjOojSvPyhAWOXh t7GjbITaUQH7tKEyEK0ZD2OshdnqEu4+6hW3cLaKlgTYxJX86++zqnJb eEhtz9ARhyKGIE02kNMjFhAh7wkn33VcV7bQzLjf5jJsNi5+5FioxEXr sGPMoB+7k/Cq+GvNRVyQCosMhvE517osbEOyh5RLRGuDGs789wSSH/IW fOPoZunJxrEvs8wehrnMDyA4zdOCpxmQs1VygFX4NeVoyLRVKwGyfHy0 vyrJHTVs8BRM1nNsOMZpCtZWPQRX828tPV9yyMUqU6ERxWdUf5a3l2fi 6DVYcb1N278=
09-May-2022 09:25:04.108 client @0x61f000153880 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': redundant request
09-May-2022 09:25:04.108 client @0x61f000154680 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': prerequisites are OK
09-May-2022 09:25:04.108 client @0x61f000151c80 10.53.0.1#49014: send failed: operation canceled
09-May-2022 09:25:04.108 client @0x61f000154680 10.53.0.1#49014: update 'update-nsec3.example/IN' approved
09-May-2022 09:25:04.108 client @0x61f000151c80 10.53.0.1#49014: reset client
09-May-2022 09:25:04.108 client @0x61f000154680 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': update section prescan OK
09-May-2022 09:25:04.108 client @0x61f000151c80 10.53.0.1#49014: freeing client
09-May-2022 09:25:04.108 query client=0x61f000151c80 thread=0x7f23f7f62640(<unknown-query>): query_reset
09-May-2022 09:25:04.108 client @0x61f000154680 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': adding an RR at 'update-nsec3.example' DNSKEY 257 3 7 AwEAAcMtKfINfZtuWA/i2KM2Ppi7pRaUOzARZhOYUGjOojSvPyhAWOXh t7GjbITaUQH7tKEyEK0ZD2OshdnqEu4+6hW3cLaKlgTYxJX86++zqnJb eEhtz9ARhyKGIE02kNMjFhAh7wkn33VcV7bQzLjf5jJsNi5+5FioxEXr sGPMoB+7k/Cq+GvNRVyQCosMhvE517osbEOyh5RLRGuDGs789wSSH/IW fOPoZunJxrEvs8wehrnMDyA4zdOCpxmQs1VygFX4NeVoyLRVKwGyfHy0 vyrJHTVs8BRM1nNsOMZpCtZWPQRX828tPV9yyMUqU6ERxWdUf5a3l2fi 6DVYcb1N278=
09-May-2022 09:25:04.108 client @0x61f000154680 10.53.0.1#49014: updating zone 'update-nsec3.example/IN': redundant request
09-May-2022 09:25:04.108 clientmgr @0x60c000006700 detach: 4
09-May-2022 09:25:04.108 client @0x61f000152a80 10.53.0.1#49014: send failed: operation canceled
09-May-2022 09:25:04.108 client @0x61f000152a80 10.53.0.1#49014: reset client
09-May-2022 09:25:04.108 client @0x61f000152a80 10.53.0.1#49014: freeing client
09-May-2022 09:25:04.108 query client=0x61f000152a80 thread=0x7f23f7f62640(<unknown-query>): query_reset
09-May-2022 09:25:04.108 clientmgr @0x60c000006700 detach: 3
09-May-2022 09:25:04.108 exclusive task mode: starting
09-May-2022 09:25:04.108 client @0x61f000153880 10.53.0.1#49014: send failed: operation canceled
09-May-2022 09:25:04.108 client @0x61f000153880 10.53.0.1#49014: reset client
09-May-2022 09:25:04.108 client @0x61f000153880 10.53.0.1#49014: freeing client
09-May-2022 09:25:04.108 query client=0x61f000153880 thread=0x7f23f7f62640(<unknown-query>): query_reset
09-May-2022 09:25:04.108 clientmgr @0x60c000006700 detach: 2
09-May-2022 09:25:04.108 client @0x61f000154680 10.53.0.1#49014: send failed: operation canceled
09-May-2022 09:25:04.108 client @0x61f000154680 10.53.0.1#49014: reset client
09-May-2022 09:25:04.108 client @0x61f000154680 10.53.0.1#49014: freeing client
09-May-2022 09:25:04.108 query client=0x61f000154680 thread=0x7f23f7f62640(<unknown-query>): query_reset
09-May-2022 09:25:04.108 clientmgr @0x60c000006700 detach: 1
The system was likely heavily overloaded as this action takes sub 100 ms on my Linux laptop.