[Opendnssec-user] Problems receiving NOTIFY's

Tue Oct 2 08:30:43 UTC 2018

Hello all,

I am having difficulty with my installation of OpenDNSSEC. My
architecture is this (warning ASCII art):
                              ._.
                        (Soft)|H|
 ns1.example.com              |S|
.-----------------------------|M|---------------------------------------.
| .-----------------.      .--'-'------------.      .-----------------. |
| | PDNS            |      | OpenDNSSEC      |      | PDNS            | |
| | 'hidden-master' | <==> | 'signer'        | <==> | 'master'        | |
| | 127.0.53.1      |  |   | 127.0.53.2      |  |   | 127.0.53.3      | |
| `-----------------'  |   `-----------------'  |   `-----------------' |
|                      `- NOTIFY/{AI}XFR        `- NOTIFY/{AI}XFR       |
`-----------------------------------------------------------------------'

I am running PowerDNS 4.1.4 (the most recent release) from the
official PowerDNS Debian repo and OpenDNSSEC 2.1.3 from the Debian Sid
repository on Debian Stretch x86_64.

When I run `ods-signer retransfer example.com` I get log output like
this (everything set to the most verbose level):

# from ods-signerd
[cmdhandler] accept client 9
received command retransfer example.com
[cmdhandler] retransfer command
[xfrd] zone example.com sets timer timeout now
[cmdhandler] forward a notify
[xfrhandler] read forwarded dns packet: 6 bytes received
[netio] dispatch timeout event without checking for other events
[xfrd] zone example.com make request [tcp round 0 master 127.0.53.1:0]
[xfrd] zone example.com open tcp connection to 127.0.53.1
[xfrd] zone example.com request axfr to 127.0.53.1
[domain] tsig sign query with key: secret1.example.com.
[domain] tsig sign query with algorithm: hmac-sha256.
[xfrd] tsig append rr to request id=32070
[xfrd] zone example.com sending tcp query id=32070
[xfrd] zone example.com done writing, get ready for reading
[dnshandler] forwarded notify: 6 bytes sent
[cmdhandler] zone example.com being re-transfered
[cmdhandler] done handling command retransfer example.com
[xfrd] zone example.com xfr packet parsed (res 1)
[file] openfile example.com.xfrd count 1
AXFR of domain 'example.com' to 127.0.53.2 finished
[xfrd] zone example.com xfr packet parsed (res 1)
[file] openfile example.com.xfrd count 1
[xfrd] zone example.com xfr packet parsed (res 4)
[file] openfile example.com.xfrd count 1
[file] openfile example.com.xfrd count 1
[xfrd] reschedule task for zone example.com: disk serial=4
acquired=1538459132, memory serial=4 acquired=1538459102
[scheduler] schedule task [forceread] for example.com
[engine] wake up workers
[xfrd] zone example.com transfer done [notify acquired 0, serial on
disk 4, notify serial 0]
[xfrd] zone example.com xfr done
# there's more stuff, but that's not the problem here

# from pdns (hidden master)
AXFR of domain 'example.com' initiated by 127.0.53.2
AXFR of domain 'example.com' allowed: TSIG signed request with
authorized key 'secret1.example.com' and algorithm 'hmac-sha256'
AXFR of domain 'example.com' to 127.0.53.2 finished

# from pdns (master)
Remote 127.0.53.2 wants 'example.com|SOA', do = 0, bufsize = 512:
packetcache MISS
Received secure NOTIFY for example.com from 127.0.53.2, allowed by
TSIG key 'secret2.example.com'
# there's more, but that's not the problem here

As you can see, everything seems to go fine. The ods-signerd makes an
AXFR and gets the most recent version (serial 4) from the hidden
master.

Unfortunately, sending a NOTIFY from the hidden master to OpenDNSSEC
doesn't work as well. Running `pdns_control notify example.com` gets
me output like this

# from ods-signerd
[query] add tsig ok
[socket] TCP_READ: new tcplen 3473
[socket] TCP_WRITE: bytes transmitted 2 (sent 2)
[socket] TCP_WRITE: bytes transmitted 3475
[socket] TCP_WRITE: tcplen 3473
[socket] TCP_WRITE: sizeof tcplen 2
[axfr] zone transfer example.com completed
[socket] incoming tcp message
[socket] TCP_READ: reset query
[netio] handler removed
[socket] incoming udp message
[query] tsig OK
[query] incoming notify for zone example.com
example.com[acl] match 127.0.53.1
[query] forward notify for zone example.com from client 127.0.53.1
[xfrd] zone example.com sets timer timeout now
[dnshandler] forwarded notify: 0 bytes sent
[socket] query processed qstate=0
[query] add tsig ok
[xfrhandler] read forwarded dns packet: 0 bytes received
[netio] dispatch timeout event without checking for other events
[xfrd] zone example.com make request [udp round 0 master 127.0.53.1:0]
[domain] tsig sign query with key: secret1.example.com.
[domain] tsig sign query with algorithm: hmac-sha256.
[xfrd] tsig append rr to request id=49406
[xfrd] zone example.com request udp/ixfr=4 to 127.0.53.1
[xfrd] zone example.com sets timer timeout now
[xfrd] zone example.com read data from udp
[xfrd] bad packet: zone example.com received error code REFUSED from 127.0.53.1
[xfrd] zone example.com xfr packet parsed (res 0)
[xfrd] bad ixfr packet from 127.0.53.1
[xfrd] zone example.com make request [udp round 1 master 127.0.53.1:0]
[domain] tsig sign query with key: secret1.example.com.
[domain] tsig sign query with algorithm: hmac-sha256.
[xfrd] tsig append rr to request id=25930
[xfrd] zone example.com request udp/ixfr=4 to 127.0.53.1
[xfrd] zone example.com sets timer timeout now
[xfrd] zone example.com read data from udp
[xfrd] bad packet: zone example.com received error code REFUSED from 127.0.53.1
[xfrd] zone example.com xfr packet parsed (res 0)
[xfrd] bad ixfr packet from 127.0.53.1
[xfrd] zone example.com make request [udp round 2 master 127.0.53.1:0]
[domain] tsig sign query with key: secret1.example.com.
[domain] tsig sign query with algorithm: hmac-sha256.
[xfrd] tsig append rr to request id=47823
[xfrd] zone example.com request udp/ixfr=4 to 127.0.53.1
[xfrd] zone example.com sets timer timeout now
[xfrd] zone example.com read data from udp
[xfrd] bad packet: zone example.com received error code REFUSED from 127.0.53.1
[xfrd] zone example.com xfr packet parsed (res 0)
[xfrd] bad ixfr packet from 127.0.53.1
[xfrd] zone example.com sets timer timeout retry 3600
[xfrd] zone example.com make request wait retry

# from pdns (hidden master)
Notification request for domain 'example.com' received from operator
Queued also-notification of domain 'example.com' to 127.0.53.2:53
Remote 127.0.0.1 wants 'example.com|IXFR', do = 0, bufsize = 512:
packetcache MISS
Removed from notification list: 'example.com' to 127.0.53.2:53 (was
acknowledged)

So, ods-signerd sees REFUSED errors from the hidden master, but the
hidden master only sees a request from 127.0.0.1 (the wrong IP!) that
it does serve.

Some further investigation:

$ dig @127.0.53.1 -b 127.0.53.2 -y 'the:right:key' IXFR=4 example.com
# this succeeds
$ dig @127.0.53.1 -b 127.0.0.1 -y 'the:right:key' IXFR=4 example.com
# this also succeeds
$ sudo grep -r '127.0.0.1' /etc/opendnssec/
# no results

So, here are my questions:
- how come OpenDNSSEC can request an AXFR when it initiates it itself,
but fails at an IXFR when receiving a NOTIFY?
- why doe the IXFR request come from OpenDNSSEC on 127.0.0.1 when
according to the config it should come from 127.0.53.2?
(Signer>Listener>Interface=127.0.53.2:53 in conf.xml and there are no
other Interfaces defined there)
    - When ods-signerd starts it has log entries like "[socket] bind
udp/ipv4 socket '127.0.53.2:15354': No such file or directory", but
later in netstat I can see that it bound to 127.0.53.2:53 at least
- how come OpenDNSSEC, even when sending from the "wrong" address
can't get the IXFR response properly, even though dig can?

Thank you for your consideration of this issue. Apologies for the wall
of logs, but I wanted to get as much information into the right hands
as possible.

Thanks,
Scott

Scott Colby