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
signature.asc
Description: This is a digitally signed message part.
-- https://lists.nic.cz/cgi-bin/mailman/listinfo/knot-dns-users
