[Pdns-users] 3.4-rc1 with ddns, tsig and bind's allow-update-forwarding
Martin Chandler
mchandler at aventer.net
Thu Aug 28 07:33:18 UTC 2014
Hi Ruben,
> Can you share all the logging and not cut out some parts?
>
> I've tested this with a normal nsupdate command, as that's
essentially what dhcpd is doing as well.
> I'll try to set that up in the same way here, but that takes a bit of
time.
Sorry for cutting out some parts of the log.
Here is a complete record:
Aug 28 10:09:38 ddnstest1 dhcpd: DHCPDISCOVER from 52:54:00:41:5f:23 via
eth1
Aug 28 10:09:39 ddnstest1 dhcpd: DHCPOFFER on 172.16.100.34 to
52:54:00:41:5f:23 (client-ubuntu) via eth1
Aug 28 10:09:39 ddnstest1 named[10387]: client 127.0.0.1#52371/key
ddns_update: signer "ddns_update" approved
Aug 28 10:09:39 ddnstest1 named[10387]: client 127.0.0.1#52371/key
ddns_update: forwarding update for zone 'example.com/IN'
Aug 28 10:09:39 ddnstest1 pdns[10413]: TCP Remote 127.0.0.1 wants
'example.com|SOA', do = 0, bufsize = 512: packetcache MISS
Aug 28 10:09:39 ddnstest1 pdns[10413]: Query: select algorithm, secret
from tsigkeys where name=E'ddns_update'
Aug 28 10:09:39 ddnstest1 pdns[10413]: UPDATE (38423) from 127.0.0.1 for
example.com: Processing started.
Aug 28 10:09:39 ddnstest1 pdns[10413]: Query: select content from
domains, domainmetadata where domainmetadata.domain_id=domains.id and
name=E'example.com' and domainmetadata.kind=E'ALLOW-DNSUPDATE-FROM'
Aug 28 10:09:39 ddnstest1 pdns[10413]: Query: select content from
domains, domainmetadata where domainmetadata.domain_id=domains.id and
name=E'example.com' and domainmetadata.kind=E'TSIG-ALLOW-DNSUPDATE'
Aug 28 10:09:39 ddnstest1 pdns[10413]: Query: select
id,name,master,last_check,notified_serial,type from domains where
name=E'example.com'
Aug 28 10:09:39 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and type='SOA' and name=E'example.com'
Aug 28 10:09:39 ddnstest1 pdns[10413]: UPDATE (38423) from 127.0.0.1 for
example.com: starting transaction.
Aug 28 10:09:39 ddnstest1 pdns[10413]: Command: begin
Aug 28 10:09:39 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and name=E'client-ubuntu.example.com'
Aug 28 10:09:39 ddnstest1 pdns[10413]: Query: select content from
domains, domainmetadata where domainmetadata.domain_id=domains.id and
name=E'example.com' and domainmetadata.kind=E'NSEC3PARAM'
Aug 28 10:09:39 ddnstest1 pdns[10413]: Query: select content from
domains, domainmetadata where domainmetadata.domain_id=domains.id and
name=E'example.com' and domainmetadata.kind=E'PRESIGNED'
Aug 28 10:09:39 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and type='A' and
name=E'client-ubuntu.example.com'
Aug 28 10:09:39 ddnstest1 pdns[10413]: UPDATE (38423) from 127.0.0.1 for
example.com: Adding record client-ubuntu.example.com|A
Aug 28 10:09:39 ddnstest1 pdns[10413]: Command: insert into records
(content,ttl,prio,type,domain_id,disabled,name,auth) values
(E'172.16.100.34',300,0,'A',1,0::bool,E'client-ubuntu.example.com','1')
Aug 28 10:09:39 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and name=E'client-ubuntu.example.com'
Aug 28 10:09:39 ddnstest1 pdns[10413]: Command: update records set
ordername=E'client-ubuntu',auth=1::bool where
name=E'client-ubuntu.example.com' and domain_id='1' and disabled=false
Aug 28 10:09:39 ddnstest1 pdns[10413]: Command: delete from records
where domain_id='1' and name='client-ubuntu.example.com' and type is null
Aug 28 10:09:39 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and type='TXT' and
name=E'client-ubuntu.example.com'
Aug 28 10:09:39 ddnstest1 pdns[10413]: UPDATE (38423) from 127.0.0.1 for
example.com: Adding record client-ubuntu.example.com|TXT
Aug 28 10:09:39 ddnstest1 pdns[10413]: Command: insert into records
(content,ttl,prio,type,domain_id,disabled,name,auth) values
(E'"00bc035b76ccfec55f7d52a28a35c10053"',300,0,'TXT',1,0::bool,E'client-ubuntu.example.com','1')
Aug 28 10:09:39 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and name=E'client-ubuntu.example.com'
Aug 28 10:09:39 ddnstest1 pdns[10413]: Command: update records set
ordername=E'client-ubuntu',auth=1::bool where
name=E'client-ubuntu.example.com' and domain_id='1' and disabled=false
Aug 28 10:09:39 ddnstest1 pdns[10413]: Command: delete from records
where domain_id='1' and name='client-ubuntu.example.com' and type is null
Aug 28 10:09:39 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and type='SOA' and name=E'example.com'
Aug 28 10:09:39 ddnstest1 pdns[10413]: Query: select content from
domains, domainmetadata where domainmetadata.domain_id=domains.id and
name=E'example.com' and domainmetadata.kind=E'SOA-EDIT-DNSUPDATE'
Aug 28 10:09:39 ddnstest1 pdns[10413]: Command: delete from records
where domain_id=1 and name=E'example.com' and type=E'SOA'
Aug 28 10:09:39 ddnstest1 dhcpd: DHCPREQUEST for 172.16.100.34
(172.16.100.5) from 52:54:00:41:5f:23 (client-ubuntu) via eth1
Aug 28 10:09:39 ddnstest1 dhcpd: DHCPACK on 172.16.100.34 to
52:54:00:41:5f:23 (client-ubuntu) via eth1
Aug 28 10:09:39 ddnstest1 pdns[10413]: Command: insert into records
(content,ttl,prio,type,domain_id,disabled,name,auth) values
(E'ns1.example.com. admin.example.com 2014082805 10800 3600 604800
3600',3600,0,'SOA',1,0::bool,E'example.com','1')
Aug 28 10:09:39 ddnstest1 pdns[10413]: UPDATE (38423) from 127.0.0.1 for
example.com: Increasing SOA serial (2014082804 -> 2014082805)
Aug 28 10:09:39 ddnstest1 pdns[10413]: Command: update records set
ordername=E'',auth=1::bool where name=E'example.com' and domain_id='1'
and disabled=false
Aug 28 10:09:39 ddnstest1 pdns[10413]: Command: commit
Aug 28 10:09:39 ddnstest1 pdns[10413]: UPDATE (38423) from 127.0.0.1 for
example.com: Update completed, 3 changed records committed.
Aug 28 10:09:39 ddnstest1 named[10387]: zone example.com/IN: forwarded
dynamic update: master 127.0.0.1#54 returned: NOERROR
Aug 28 10:09:39 ddnstest1 dhcpd: Unable to add forward map from
client-ubuntu.example.com to 172.16.100.34: tsig verify failure
Aug 28 10:09:39 ddnstest1 named[10387]: error (network unreachable)
resolving './NS/IN': 2001:500:3::42#53
Aug 28 10:09:39 ddnstest1 named[10387]: error (network unreachable)
resolving 'ntp.ubuntu.com/A/IN': 2001:500:3::42#53
Aug 28 10:09:40 ddnstest1 named[10387]: error (network unreachable)
resolving 'ubuntu.com/DS/IN': 2001:503:c27::2:30#53
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: select
id,name,master,last_check,type from domains where type='SLAVE'
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: select
id,name,master,last_check,notified_serial,type from domains where
type='MASTER'
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and type='SOA' and
name=E'100.16.172.in-addr.arpa'
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and type='SOA' and name=E'example.com'
Aug 28 10:10:04 ddnstest1 pdns[10413]: 1 domain for which we are master
needs notifications
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and type='NS' and name=E'example.com'
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and name=E'ns1.example.com'
Aug 28 10:10:04 ddnstest1 pdns[10413]: Queued notification of domain
'example.com' to 172.16.100.5:53
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: select content from
domains, domainmetadata where domainmetadata.domain_id=domains.id and
name=E'example.com' and domainmetadata.kind=E'ALSO-NOTIFY'
Aug 28 10:10:04 ddnstest1 pdns[10413]: Command: update domains set
notified_serial=2014082805 where id=1
Aug 28 10:10:04 ddnstest1 named[10387]: client 127.0.0.1#11543: received
notify for zone 'example.com'
Aug 28 10:10:04 ddnstest1 pdns[10413]: Remote 127.0.0.1 wants
'example.com|SOA', do = 0, bufsize = 1680: packetcache MISS
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and type='SOA' and name=E'example.com'
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: select content from
domains, domainmetadata where domainmetadata.domain_id=domains.id and
name=E'example.com' and domainmetadata.kind=E'SOA-EDIT'
Aug 28 10:10:04 ddnstest1 named[10387]: zone example.com/IN: Transfer
started.
Aug 28 10:10:04 ddnstest1 named[10387]: transfer of 'example.com/IN'
from 127.0.0.1#54: connected using 127.0.0.1#42375
Aug 28 10:10:04 ddnstest1 pdns[10413]: gpgsql Connection successful.
Connected to database 'powerdns' on '127.0.0.1'.
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: select content from
domains, domainmetadata where domainmetadata.domain_id=domains.id and
name=E'example.com' and domainmetadata.kind=E'PRESIGNED'
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: select cryptokeys.id,
flags, case when active then 1 else 0 end as active, content from
domains, cryptokeys where cryptokeys.domain_id=domains.id and
name=E'example.com'
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: select content from
domains, domainmetadata where domainmetadata.domain_id=domains.id and
name=E'example.com' and domainmetadata.kind=E'NSEC3PARAM'
Aug 28 10:10:04 ddnstest1 pdns[10413]: IXFR of domain 'example.com'
initiated by 127.0.0.1 with serial 2014082804
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and type='SOA' and name=E'example.com'
Aug 28 10:10:04 ddnstest1 pdns[10413]: AXFR of domain 'example.com'
allowed: client IP 127.0.0.1 is in allow-axfr-ips
Aug 28 10:10:04 ddnstest1 pdns[10413]: gpgsql Connection successful.
Connected to database 'powerdns' on '127.0.0.1'.
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and type='SOA' and name=E'example.com'
Aug 28 10:10:04 ddnstest1 pdns[10413]: IXFR fallback to AXFR for domain
'example.com' our serial 2014082805
Aug 28 10:10:04 ddnstest1 pdns[10413]: gpgsql Connection successful.
Connected to database 'powerdns' on '127.0.0.1'.
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: select content from
domains, domainmetadata where domainmetadata.domain_id=domains.id and
name=E'example.com' and domainmetadata.kind=E'PRESIGNED'
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: select cryptokeys.id,
flags, case when active then 1 else 0 end as active, content from
domains, cryptokeys where cryptokeys.domain_id=domains.id and
name=E'example.com'
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: select content from
domains, domainmetadata where domainmetadata.domain_id=domains.id and
name=E'example.com' and domainmetadata.kind=E'NSEC3PARAM'
Aug 28 10:10:04 ddnstest1 pdns[10413]: AXFR of domain 'example.com'
initiated by 127.0.0.1
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and type='SOA' and name=E'example.com'
Aug 28 10:10:04 ddnstest1 pdns[10413]: AXFR of domain 'example.com'
allowed: client IP 127.0.0.1 is in allow-axfr-ips
Aug 28 10:10:04 ddnstest1 pdns[10413]: gpgsql Connection successful.
Connected to database 'powerdns' on '127.0.0.1'.
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and type='SOA' and name=E'example.com'
Aug 28 10:10:04 ddnstest1 pdns[10413]: gpgsql Connection successful.
Connected to database 'powerdns' on '127.0.0.1'.
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: select content from
domains, domainmetadata where domainmetadata.domain_id=domains.id and
name=E'example.com' and domainmetadata.kind=E'SOA-EDIT'
Aug 28 10:10:04 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE (disabled=false OR 0::bool) and domain_id='1' order by
name, type
Aug 28 10:10:04 ddnstest1 pdns[10413]: AXFR of domain 'example.com' to
127.0.0.1 finished
Aug 28 10:10:04 ddnstest1 named[10387]: zone example.com/IN: transferred
serial 2014082805
Aug 28 10:10:04 ddnstest1 named[10387]: transfer of 'example.com/IN'
from 127.0.0.1#54: Transfer completed: 3 messages, 7 records, 310 bytes,
0.138 secs (2246 bytes/sec)
Aug 28 10:10:05 ddnstest1 pdns[10413]: Removed from notification list:
'example.com' to 172.16.100.5:53 (was acknowledged)
Aug 28 10:10:07 ddnstest1 pdns[10413]: Query: select
id,name,master,last_check,type from domains where type='SLAVE'
Aug 28 10:10:07 ddnstest1 pdns[10413]: Query: select
id,name,master,last_check,notified_serial,type from domains where
type='MASTER'
Aug 28 10:10:07 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and type='SOA' and
name=E'100.16.172.in-addr.arpa'
Aug 28 10:10:07 ddnstest1 pdns[10413]: Query: SELECT
content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM
records WHERE disabled=false and type='SOA' and name=E'example.com'
Aug 28 10:10:07 ddnstest1 pdns[10413]: No master domains need notifications
Aug 28 10:10:20 ddnstest1 dhcpd: DHCPRELEASE of 172.16.100.34 from
52:54:00:41:5f:23 (client-ubuntu) via eth1 (found)
I tried with nsupdate as well to no avail:
martin at ddnstest1:~$ nsupdate <<!
> server 127.0.0.1 53
> zone example.com
> prereq nxdomain client-ubuntu.example.com 300 A 172.16.100.34
> update add client-ubuntu.example.com 300 A 172.16.100.34
> update add client-ubuntu.example.com 300 TXT
"00bc035b76ccfec55f7d52a28a35c10053"
> key ddns_update hdD/wdMScNJhp0Dgpm6q8Q==
> send
> answer
> !
; TSIG error with server: tsig verify failure
Answer:
;; ->>HEADER<<- opcode: UPDATE, status: NOERROR, id: 23889
;; flags: qr aa; ZONE: 1, PREREQ: 0, UPDATE: 0, ADDITIONAL: 1
;; ZONE SECTION:
;example.com. IN SOA
;; TSIG PSEUDOSECTION:
ddns_update. 0 ANY TSIG hmac-md5.sig-alg.reg.int. 1409210441 300 16
bIvv9qSxov+oyTJXlq6CBA== 23889 NOERROR 0
As before, going from dhcpd (or nsupdate) straight to PDNS works fine.
Thanks,
Martin
(2014年08月28日 15:19), Ruben d'Arco wrote:
> Hi Martin,
>
> Can you share all the logging and not cut out some parts?
>
> I've tested this with a normal nsupdate command, as that's essentially what dhcpd is doing as well.
> I'll try to set that up in the same way here, but that takes a bit of time.
>
> Regards,
> Ruben
>
>
> On Thu, Aug 28, 2014 at 10:01:18AM +0900, Martin Chandler wrote:
>> Hi Ruben,
>>
>> Thank you very much for all your help.
>>
>> I tried your branch, and while the dynamic records get inserted, for
>> some reason dhcpd still logs a tsig verify failure at the end of the
>> transaction.
>> Perhaps as a result, when DHCPRELEASE is sent, the records are not deleted.
>>
>> Here is the log:
>> Aug 28 09:36:50 ddnstest1 dhcpd: DHCPDISCOVER from 52:54:00:41:5f:23
>> via eth1
>> Aug 28 09:36:51 ddnstest1 dhcpd: DHCPOFFER on 172.16.100.34 to
>> 52:54:00:41:5f:23 (client-ubuntu) via eth1
>> Aug 28 09:36:51 ddnstest1 named[1034]: client 127.0.0.1#30418/key
>> ddns_update: signer "ddns_update" approved
>> Aug 28 09:36:51 ddnstest1 named[1034]: client 127.0.0.1#30418/key
>> ddns_update: forwarding update for zone 'example.com/IN'
>> Aug 28 09:36:51 ddnstest1 pdns[10041]: TCP Remote 127.0.0.1 wants
>> 'example.com|SOA', do = 0, bufsize = 512: packetcache MISS
>> Aug 28 09:36:51 ddnstest1 pdns[10041]: Query: select algorithm,
>> secret from tsigkeys where name=E'ddns_update'
>> Aug 28 09:36:51 ddnstest1 pdns[10041]: UPDATE (19329) from 127.0.0.1
>> for example.com: Processing started.
>> :
>> lots of query logs for inserting the records
>> :
>> Aug 28 09:36:51 ddnstest1 pdns[10041]: UPDATE (19329) from 127.0.0.1
>> for example.com: Update completed, 3 changed records committed.
>> Aug 28 09:36:51 ddnstest1 named[1034]: zone example.com/IN:
>> forwarded dynamic update: master 127.0.0.1#54 returned: NOERROR
>> Aug 28 09:36:51 ddnstest1 dhcpd: DHCPREQUEST for 172.16.100.34
>> (172.16.100.5) from 52:54:00:41:5f:23 (client-ubuntu) via eth1
>> Aug 28 09:36:51 ddnstest1 dhcpd: DHCPACK on 172.16.100.34 to
>> 52:54:00:41:5f:23 (client-ubuntu) via eth1
>> Aug 28 09:36:51 ddnstest1 dhcpd: Unable to add forward map from
>> client-ubuntu.example.com to 172.16.100.34: tsig verify failure
>>
>> :
>> Aug 28 09:37:58 ddnstest1 dhcpd: DHCPRELEASE of 172.16.100.34 from
>> 52:54:00:41:5f:23 (client-ubuntu) via eth1 (found)
>>
>> no further logs, and the dynamic records are not deleted.
>>
>> One other small issue:
>> I notice that to increase the serial number in the SOA, PDNS is
>> deleting and then inserting a new SOA record with the updated
>> serial.
>> In a separate installation I have a schema that holds additional
>> information in the records table, and that information would be
>> lost.
>> Is there a reason for delete/insert instead of update?
>>
>> Regards,
>> Martin
>>
>>
>> (2014年08月27日 22:20), Ruben d'Arco wrote:
>>> Hi Martin,
>>>
>>> I've (with some help) fixed the bug.
>>> I currently have the code here https://github.com/cyclops1982/pdns/tree/tsigforward
>>> Could you build and try that version and see if it works for you?
>>>
>>> Regards,
>>> Ruben
>>>
>>>
>>> On Tue, Aug 26, 2014 at 09:36:57AM +0200, Ruben d'Arco wrote:
>>>> Hi Martin,
>>>>
>>>> No worries. PDNS is not my work, just hobby so i have to squeeze it in between all kinds of stuff :-)
>>>>
>>>> I am able to reproduce the issue locally now, which is already wonderful as that gives me options to debug it further.
>>>>
>>>> When a update message is forwarded, the message ID is rewritten (as per rfc2136). I think PDNS validates the message with that new ID, and it might need to do it with the old ID. I still need to figure out what is correct here. The old ID is in the message somewhere together with the TSIG record. I need to try and implement a fix like that to validate if this really is the case.
>>>>
>>>> So, we're moving forward and i hope i can give you a patched PDNS later this week.
>>>>
>>>> Regards,
>>>> Ruben
>>>>
>>>>
>>>> On Tue, Aug 26, 2014 at 03:57:31PM +0900, Martin Chandler wrote:
>>>>> Hi Ruben,
>>>>>
>>>>> Sorry to keep bothering you on this, but I notice that dhcpd sends
>>>>> the original update request via UDP, but bind forwards the request
>>>>> via TCP.
>>>>>
>>>>> Could it be that there is some difference in the way PDNS is
>>>>> handling TCP packets over UDP packets, and somehow mis-reading the
>>>>> data that BIND is sending?
>>>>>
>>>>> That would possible explain why setting the dhcp server to talk
>>>>> straight to PDNS works, because it would be sending the expected UDP
>>>>> packet, but forwarding over TCP fails.
>>>>>
>>>>> btw, I also tried setting up a CentOS 6.5 server:
>>>>> BIND 9.8.2
>>>>> DHCPD 4.1.1
>>>>> PDNS 3.4-rc1
>>>>>
>>>>> but get the same results (i.e. unsuccessful).
>>>>>
>>>>> Thanks,
>>>>> Martin
>>>>
>>>> _______________________________________________
>>>> Pdns-users mailing list
>>>> Pdns-users at mailman.powerdns.com
>>>> http://mailman.powerdns.com/mailman/listinfo/pdns-users
More information about the Pdns-users
mailing list