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@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
[email protected]
http://mailman.powerdns.com/mailman/listinfo/pdns-users
_______________________________________________
Pdns-users mailing list
[email protected]
http://mailman.powerdns.com/mailman/listinfo/pdns-users
