fedora 26 ddns stopped working finding so far

[Barry Scott]

I'm in the middle of debugging why dhcpd is no longer updating name/ptr info in dns.

Under fedora 25 I had a working setup so, unless there is a subtle config change I should have a good set of conf files.

I have been assuming that there is a reason why dhcpd fails to send to named.

I have defined DEBUG_DNS_UPDATES in hopes of seeing a interesting log.

I have been adding log_error lines to ddns.c which will mean that the line
number off a bit.

I see this error ever time a host tries to use ddns:

	"DDNS: ddns.c(1601): error in ddns_modify_fwd already running for 0x55e58a398240"

This is the complete sequence from dhcpd startup to the error:

Jul 30 16:31:12 fable systemd[1]: Stopped DHCPv4 Server Daemon.
Jul 30 16:31:12 fable systemd[1]: Starting DHCPv4 Server Daemon...
Jul 30 16:31:12 fable dhcpd[13240]: Internet Systems Consortium DHCP Server 4.3.5
Jul 30 16:31:12 fable dhcpd[13240]: Copyright 2004-2016 Internet Systems Consortium.
Jul 30 16:31:12 fable dhcpd[13240]: All rights reserved.
Jul 30 16:31:12 fable dhcpd[13240]: For info, please visit https://www.isc.org/software/dhcp/
Jul 30 16:31:12 fable dhcpd[13240]: WARNING: Overwriting trace file "/var/log/dhcpd-trace.log"
Jul 30 16:31:12 fable dhcpd[13240]: ldap_gssapi_principal is not set,GSSAPI Authentication for LDAP will not be used
Jul 30 16:31:12 fable dhcpd[13240]: Not searching LDAP since ldap-server, ldap-port and ldap-base-dn were not specified in the config file
Jul 30 16:31:12 fable dhcpd[13240]: Config file: /etc/dhcp/dhcpd.conf
Jul 30 16:31:12 fable dhcpd[13240]: Database file: /var/lib/dhcpd/dhcpd.leases
Jul 30 16:31:12 fable dhcpd[13240]: PID file: /var/run/dhcpd.pid
Jul 30 16:31:12 fable dhcpd[13240]: Source compiled to use binary-leases
Jul 30 16:31:12 fable dhcpd[13240]: Wrote 0 deleted host decls to leases file.
Jul 30 16:31:12 fable dhcpd[13240]: Wrote 0 new dynamic host decls to leases file.
Jul 30 16:31:12 fable dhcpd[13240]: Wrote 54 leases to leases file.
Jul 30 16:31:12 fable dhcpd[13240]: Listening on LPF/eno1/4c:72:b9:32:15:28/172.16.2.0/24
Jul 30 16:31:12 fable dhcpd[13240]: Sending on   LPF/eno1/4c:72:b9:32:15:28/172.16.2.0/24
Jul 30 16:31:12 fable systemd[1]: Started DHCPv4 Server Daemon.
Jul 30 16:31:12 fable dhcpd[13240]: Sending on   Socket/fallback/fallback-net
Jul 30 16:31:12 fable dhcpd[13240]: Server starting service.
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_updates ddns_update_style 3
Jul 30 16:31:17 fable dhcpd[13240]: ddns.c(123): Allocating ddns_cb=0x55e58a398240
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_updates goto noclient
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_update s1 1 ddns_hostname rpi3
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_update s3 1 ddns_domainname  chelsea.private.
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_update ddns_fwd_name rpi3.chelsea.private.
Jul 30 16:31:17 fable dhcpd[13240]: qqq ddns_updates at client_updates:
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_updates at in do_remove 0
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_updates at line 375
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_updates ddns_ttl 1800
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_updates s1 1 at line 470
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_updates perform updates at line 587
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_fwd_srv_connector
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_fwd_srv_connector DDNS_UPDATE_ADDR
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_fwd_srv_connector DDNS_UPDATE_ADDR before call ddns_modify_fwd
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_modify_fwd
Jul 30 16:31:17 fable dhcpd[13240]: QQQ dns_client_lazy
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_modify_fwd_add1
Jul 30 16:31:17 fable dhcpd[13240]: [176B blob data]
Jul 30 16:31:17 fable dhcpd[13240]: DDNS: ddns.c(1601): error in ddns_modify_fwd already running for 0x55e58a398240
Jul 30 16:31:17 fable dhcpd[13240]: QQQ ddns_fwd_srv_connector DDNS_UPDATE_ADDR after call ddns_modify_fwd
Jul 30 16:31:17 fable dhcpd[13240]: ddns.c(1618): freeing ddns_cb=0x55e58a398240
Jul 30 16:31:17 fable dhcpd[13240]: reuse_lease: lease age 16 (secs) under 25% threshold, reply with unaltered, existing lease for 172.16.2.170
Jul 30 16:31:17 fable dhcpd[13240]: DHCPREQUEST for 172.16.2.170 from b8:27:eb:b4:b3:b3 (rpi3) via eno1
Jul 30 16:31:17 fable dhcpd[13240]: DHCPACK on 172.16.2.170 to b8:27:eb:b4:b3:b3 (rpi3) via eno1

Here is my instrumented code around line ddns.c(1601):

		if (ddns_cb->flags & DDNS_UPDATE_ADDR) {
                        log_error("QQQ ddns_fwd_srv_connector DDNS_UPDATE_ADDR");
			ddns_cb->state    = DDNS_STATE_ADD_FW_NXDOMAIN;
			ddns_cb->cur_func = ddns_fwd_srv_add1;
                        log_error("QQQ ddns_fwd_srv_connector DDNS_UPDATE_ADDR before call ddns_modify_fwd");
			result = ddns_modify_fwd(ddns_cb, MDL);
                        log_error("QQQ ddns_fwd_srv_connector DDNS_UPDATE_ADDR after call ddns_modify_fwd");

It seems that the "already running" log is saying there is a bug in the code?

Is there a fix for this? If not how can I help track down a fix?

Barry