Re: [knot-dns-users] DDNS with DNSSEC, is this expected behavior or a bug

Hi Libor, I don't know why the message appears three times. I was also wondering about this. I had a quick look at a tcpdump and nsupdate does indeed send three requests: 12:27:57.973741 IP6 (flowlabel 0x5e7e8, hlim 64, next-header UDP (17) payload length: 37) ::1.5835 > ::1.53: [bad udp cksum 0x0038 -> 0x19f7!] 53303 update SOA? example.org. (29) 12:27:57.976086 IP6 (flowlabel 0x0f4a8, hlim 64, next-header UDP (17) payload length: 37) ::1.53 > ::1.5835: [bad udp cksum 0x0038 -> 0x99f6!] 53303 update- q: SOA? example.org. 0/0/0 (29) 12:27:57.976554 IP6 (flowlabel 0x5e7e8, hlim 64, next-header UDP (17) payload length: 65) ::1.5835 > ::1.53: [bad udp cksum 0x0054 -> 0x0d44!] 32688 update [2n] SOA? example.org. ns: example.org. ANY [0s] A 192.12.0.1, example.org. [1m] A 127.0.0.1 (57) 12:27:57.989710 IP6 (flowlabel 0x0f4a8, hlim 64, next-header UDP (17) payload length: 37) ::1.53 > ::1.5835: [bad udp cksum 0x0038 -> 0xea7d!] 32688 update- q: SOA? example.org. 0/0/0 (29) 12:27:57.989970 IP6 (flowlabel 0x5e7e8, hlim 64, next-header UDP (17) payload length: 37) ::1.5835 > ::1.53: [bad udp cksum 0x0038 -> 0xa04c!] 18914 update SOA? example.org. (29) 12:27:57.992947 IP6 (flowlabel 0x0f4a8, hlim 64, next-header UDP (17) payload length: 37) ::1.53 > ::1.5835: [bad udp cksum 0x0038 -> 0x204c!] 18914 update- q: SOA? example.org. 0/0/0 (29) Here is a trimmed down version of my configuration file which shows the same behavior: $ head -v -n-1 /etc/knot/knot.conf ==> /etc/knot/knot.conf <== server: listen: 0.0.0.0@53 listen: ::@53 user: knot:knot log: - target: syslog any: info policy: - id: default algorithm: RSASHA256 ksk-size: 3248 zsk-size: 2432 nsec3: on nsec3-iterations: 330 ksk-lifetime: 365d cds-cdnskey-publish: none acl: - id: example.org action: update template: - id: default file: zones/%s semantic-checks: on serial-policy: unixtime - id: signed file: zones/%s dnssec-policy: default dnssec-signing: on semantic-checks: on serial-policy: unixtime zone: - domain: example.org template: signed file: zones_ddns/%s zonefile-load: difference $ head -v -n-1 example.org ==> example.org <== example.org. 3600 SOA ns1.example.org. hostmaster.example.org 1530570453 3600 1200 3628800 60 example.org. 3600 NS ns1.example.org. The problem with knot not responding to DDNS updates happened after a server reboot or shortly after. I could see packets arriving at the server in tcpdump, but knot didn't react to them and didn't log anything. The log messages after the reboot where these: Okt 15 21:12:24 server knotd[508]: info: [<zone>] zone will be loaded Okt 15 21:12:24 server knotd[508]: info: [<zone>] DNSSEC, key, tag 36134, algorithm RSASHA256, KSK, public, active Okt 15 21:12:24 server knotd[508]: info: [<zone>] DNSSEC, key, tag 62508, algorithm RSASHA256, public, active Okt 15 21:12:24 server knotd[508]: info: [<zone>] DNSSEC, signing started Okt 15 21:12:25 server knotd[508]: info: [<zone>] DNSSEC, successfully signed Okt 15 21:12:25 server knotd[508]: info: [<zone>] loaded, serial 1539630745, 7076 bytes Okt 15 21:12:25 server knotd[508]: info: [<zone>] DNSSEC, next signing at 2018-10-19T11:32:26 Okt 15 21:12:25 server knotd[508]: info: [<zone>] zone file updated, serial 1539336748 -> 1539630745 after my manual knot restart this got logged: Okt 16 15:25:32 server knotd[3033]: info: [<zone>] zone will be loaded Okt 16 15:25:32 server knotd[3033]: info: [<zone>] DNSSEC, key, tag 36134, algorithm RSASHA256, KSK, public, active Okt 16 15:25:32 server knotd[3033]: info: [<zone>] DNSSEC, key, tag 62508, algorithm RSASHA256, public, active Okt 16 15:25:32 server knotd[3033]: info: [<zone>] DNSSEC, signing started Okt 16 15:25:32 server knotd[3033]: info: [<zone>] DNSSEC, zone is up-to-date Okt 16 15:25:32 server knotd[3033]: info: [<zone>] loaded, serial 1539630745, 7076 bytes Okt 16 15:25:32 server knotd[3033]: info: [<zone>] DNSSEC, next signing at 2018-10-19T11:32:26 I don't know if these log are useful, but I don't have much more information. Thanks, Maxi On Donnerstag, 18. Oktober 2018 09:55:05 CEST libor.peltan wrote: > Hi Maxi, > > thanks much for detailed report! > > First, the 1970 time information is indeed a cosmetic bug. It's just a > dumb conversion of zero timestamp, in our semantics infinite future. > Please interpret it as "not scheduled" until we fix it. > > However, it's not clear to me how this can ever happen. Next re-sign is > always planned based on ksk-lifetime, zsk-lifetime and/or > rrsig-lifetime. Could you please share also (at least) the policy > section of your configuration to check? I will also take a look on this > anyway. > > The snippet of log you sent us looks also a little weird, but maybe you > know the explanation here, why did Knot receive DDNS three times in one > second, with just the middle one actually changing the zone. If you > think there is also a bug, please share more information to this, > otherwise ok. > > Please let us know if the situation with not responding to DDNS appears > again. > > Danke! > > Libor > > Dne 17.10.18 v 23:25 Maximilian Engelhardt napsal(a): >> Hi, >> >> I'm using a zone with DNSSEC signing enabled that is updated using DDNS. >> >> The update procedure is very simple and looks like this: >> ==> test_ddns.sh <== >> #! /bin/sh >> >> ZONE="example.org." >> >> cat << EOF | nsupdate >> server localhost >> zone ${ZONE} >> >> update delete ${ZONE} A >> update add ${ZONE} 60 IN A 127.0.0.1 >> >> send >> quit >> EOF >> >> And the corresponding output in the knot log is this: >> >> Okt 17 22:58:46 backroad knotd[14134]: info: [example.org.] DDNS, >> processing 1 updates Okt 17 22:58:46 backroad knotd[14134]: info: >> [example.org.] DNSSEC, zone is up-to-date Okt 17 22:58:46 backroad >> knotd[14134]: info: [example.org.] DNSSEC, next signing at >> 1970-01-01T01:00:00 Okt 17 22:58:46 backroad knotd[14134]: info: >> [example.org.] DDNS, finished, no changes to the zone were made Okt 17 >> 22:58:46 backroad knotd[14134]: info: [example.org.] DDNS, processing 1 >> updates Okt 17 22:58:46 backroad knotd[14134]: info: [example.org.] >> DNSSEC, successfully signed Okt 17 22:58:46 backroad knotd[14134]: info: >> [example.org.] DNSSEC, next signing at 2018-10-24T22:58:46 Okt 17 >> 22:58:46 backroad knotd[14134]: info: [example.org.] DDNS, update >> finished, serial 1539809849 -> 1539809926, 0.02 seconds Okt 17 22:58:46 >> backroad knotd[14134]: info: [example.org.] DDNS, processing 1 updates >> Okt 17 22:58:46 backroad knotd[14134]: info: [example.org.] DNSSEC, zone >> is up-to-date Okt 17 22:58:46 backroad knotd[14134]: info: [example.org.] >> DNSSEC, next signing at 1970-01-01T01:00:00 Okt 17 22:58:46 backroad >> knotd[14134]: info: [example.org.] DDNS, finished, no changes to the zone >> were made Okt 17 22:58:46 backroad knotd[14134]: info: [example.org.] >> zone file updated, serial 1539809849 -> 1539809926 >> >> I'm wondering if the "next signing at 1970-01-01T01:00:00" output is >> correct as this seems suspicious to me. >> >> Running "knotc zone-status example.org" gives the following output: >> [example.org.] role: master | serial: 1539809926 | transaction: none | >> freeze: no | refresh: not scheduled | update: not scheduled | expiration: >> not scheduled | journal flush: not scheduled | notify: not scheduled | >> DNSSEC re-sign: not scheduled | NSEC3 resalt: +29D23h53m28s | parent DS >> query: not scheduled >> >> Is this expected behavior or a bug in knot? >> >> I can give more information or create a proper bugreport if needed. >> >> I also recently had the problem that knot didn't respond to ddns updates >> until it was restarted. I don't know if this is related or a different >> problem, however I currently don't have more information about this. >> >> Thanks, >> Maxi