<html>
  <head>
    <meta http-equiv="Content-Type" content="text/html; charset=utf-8">
  </head>
  <body text="#000000" bgcolor="#FFFFFF">
    In named.conf I have an update log defined:<br>
    <font color="#993300"><tt>        channel update_channel {</tt><tt><br>
      </tt><tt>                file "/var/log/named/update.log" versions
        4 size 10m;</tt><tt><br>
      </tt><tt>                print-category yes;</tt><tt><br>
      </tt><tt>                print-severity yes;</tt><tt><br>
      </tt><tt>                print-time yes;</tt><tt><br>
      </tt><tt>                severity info;</tt><tt><br>
      </tt><tt>        };</tt><tt><br>
      </tt></font>You could define it and the check to see if the update
    is refused.  You can also<br>
    run a<font color="#993300"><tt> tcpdump -i <interface> port
        domain</tt><tt><br>
      </tt></font>to watch the conversation between DHCP and DNS.  My
    services are both on the<br>
    same machine so <interface> would be <font color="#993300"><tt>lo</tt></font>.<br>
    <br>
    HTH,<br>
    Bill<br>
    <br>
    <div class="moz-cite-prefix">On 7/30/2017 11:43 AM, Barry Scott
      wrote:<br>
    </div>
    <blockquote type="cite"
      cite="mid:2381902.QbpTcEs9Se@varric.chelsea.private">
      <pre wrap="">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 <a class="moz-txt-link-freetext" href="https://www.isc.org/software/dhcp/">https://www.isc.org/software/dhcp/</a>
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

_______________________________________________
dhcp-users mailing list
<a class="moz-txt-link-abbreviated" href="mailto:dhcp-users@lists.isc.org">dhcp-users@lists.isc.org</a>
<a class="moz-txt-link-freetext" href="https://lists.isc.org/mailman/listinfo/dhcp-users">https://lists.isc.org/mailman/listinfo/dhcp-users</a>
</pre>
    </blockquote>
    <br>
  </body>
</html>