I was asked to check DHCP issues on a UTM 625 firewall
| 9.717-3 with 2 updates in queue |
the dhcpd is restarting every 5 minutes. No idea why.
dhcpd log:
2024:04:29-00:00:44 fw-625-2 dhcpd: Server starting service. 2024:04:29-00:02:27 fw-625-1 dhcpd: DHCPDISCOVER from ba:a6:21:bd:a2:c6 via eth6 2024:04:29-00:02:28 fw-625-1 dhcpd: DHCPOFFER on xx.xx.xx.157 to ba:a6:21:bd:a2:c6 via eth6 2024:04:29-00:02:29 fw-625-1 dhcpd: DHCPREQUEST for xx.xx.xx.157 (xx.xx.xy.1) from ba:a6:21:bd:a2:c6 via eth6 2024:04:29-00:02:29 fw-625-1 dhcpd: DHCPACK on xx.xx.xx.157 to ba:a6:21:bd:a2:c6 via eth6 2024:04:29-00:03:30 fw-625-1 dhcpd: DHCPREQUEST for xx.xx.xx.64 from 58:c9:35:2f:bb:19 via eth6 2024:04:29-00:03:30 fw-625-1 dhcpd: DHCPACK on xx.xx.xx.64 to 58:c9:35:2f:bb:19 via eth6 2024:04:29-00:04:43 fw-625-1 dhcpd: DHCPREQUEST for xx.xx.xy.220 from dc:72:9b:f0:5f:6d (825cc253923465) via eth6 2024:04:29-00:04:43 fw-625-1 dhcpd: DHCPACK on xx.xx.xy.220 to dc:72:9b:f0:5f:6d (825cc253923465) via eth6 2024:04:29-00:04:48 fw-625-1 dhcpd: DHCPREQUEST for xx.xx.xy.210 from a4:97:b1:dc:3f:25 (hostname05777) via eth6 2024:04:29-00:04:48 fw-625-1 dhcpd: DHCPACK on xx.xx.xy.210 to a4:97:b1:dc:3f:25 (hostname05777) via eth6 2024:04:29-00:04:55 fw-625-1 dhcpd: DHCPREQUEST for xx.xx.xz.247 from cc:08:fa:9a:10:2f (hostname06434) via eth6 2024:04:29-00:04:55 fw-625-1 dhcpd: DHCPACK on xx.xx.xz.247 to cc:08:fa:9a:10:2f (hostname06434) via eth6 2024:04:29-00:05:44 fw-625-2 dhcpd: Internet Systems Consortium DHCP Server 4.4.1 2024:04:29-00:05:44 fw-625-2 dhcpd: Copyright 2004-2018 Internet Systems Consortium. 2024:04:29-00:05:44 fw-625-2 dhcpd: All rights reserved. 2024:04:29-00:05:44 fw-625-2 dhcpd: For info, please visit https://www.isc.org/software/dhcp/ 2024:04:29-00:05:44 fw-625-2 dhcpd: WARNING: Host declarations are global. They are not limited to the scope you declared them in. 2024:04:29-00:05:44 fw-625-2 dhcpd: Config file: /etc/dhcpd.conf 2024:04:29-00:05:44 fw-625-2 dhcpd: Database file: /var/state/dhcp/dhcpd.leases 2024:04:29-00:05:44 fw-625-2 dhcpd: PID file: /var/run/dhcpd.pid 2024:04:29-00:05:44 fw-625-2 dhcpd: Internet Systems Consortium DHCP Server 4.4.1 2024:04:29-00:05:44 fw-625-2 dhcpd: Copyright 2004-2018 Internet Systems Consortium. 2024:04:29-00:05:44 fw-625-2 dhcpd: All rights reserved. 2024:04:29-00:05:44 fw-625-2 dhcpd: For info, please visit https://www.isc.org/software/dhcp/ 2024:04:29-00:05:44 fw-625-2 dhcpd: Wrote 0 deleted host decls to leases file. 2024:04:29-00:05:44 fw-625-2 dhcpd: Wrote 0 new dynamic host decls to leases file. 2024:04:29-00:05:44 fw-625-2 dhcpd: Wrote 645 leases to leases file. 2024:04:29-00:05:44 fw-625-2 dhcpd: Listening on LPF/eth0/00:1a:8c:f0:98:e0/xz.xz.xz.0/24 2024:04:29-00:05:44 fw-625-2 dhcpd: Sending on LPF/eth0/00:1a:8c:f0:98:e0/xz.xz.xz.0/24 2024:04:29-00:05:44 fw-625-2 dhcpd: Listening on LPF/eth6/00:1a:8c:f0:98:e6/xx.xx.xy.0/22 2024:04:29-00:05:44 fw-625-2 dhcpd: Sending on LPF/eth6/00:1a:8c:f0:98:e6/xx.xx.xy.0/22 2024:04:29-00:05:44 fw-625-2 dhcpd: Listening on LPF/eth9/00:1a:8c:f0:98:e9/xx.xz.xz.0/24 2024:04:29-00:05:44 fw-625-2 dhcpd: Sending on LPF/eth9/00:1a:8c:f0:98:e9/xx.xz.xz.0/24 2024:04:29-00:05:44 fw-625-2 dhcpd: Sending on Socket/fallback/fallback-net 2024:04:29-00:05:44 fw-625-2 dhcpd: Server starting service. 2024:04:29-00:08:30 fw-625-1 dhcpd: DHCPREQUEST for xx.xx.xx.64 from 58:c9:35:2f:bb:19 via eth6 2024:04:29-00:08:30 fw-625-1 dhcpd: DHCPACK on xx.xx.xx.64 to 58:c9:35:2f:bb:19 via eth6 2024:04:29-00:09:44 fw-625-1 dhcpd: DHCPREQUEST for xx.xx.xy.220 from dc:72:9b:f0:5f:6d (825cc253923465) via eth6 2024:04:29-00:09:44 fw-625-1 dhcpd: DHCPACK on xx.xx.xy.220 to dc:72:9b:f0:5f:6d (825cc253923465) via eth6 2024:04:29-00:09:48 fw-625-1 dhcpd: DHCPREQUEST for xx.xx.xy.210 from a4:97:b1:dc:3f:25 (hostname05777) via eth6 2024:04:29-00:09:48 fw-625-1 dhcpd: DHCPACK on xx.xx.xy.210 to a4:97:b1:dc:3f:25 (hostname05777) via eth6 2024:04:29-00:09:55 fw-625-1 dhcpd: DHCPREQUEST for xx.xx.xz.247 from cc:08:fa:9a:10:2f (hostname06434) via eth6 2024:04:29-00:09:55 fw-625-1 dhcpd: DHCPACK on xx.xx.xz.247 to cc:08:fa:9a:10:2f (hostname06434) via eth6 2024:04:29-00:10:44 fw-625-2 dhcpd: Internet Systems Consortium DHCP Server 4.4.1 2024:04:29-00:10:44 fw-625-2 dhcpd: Copyright 2004-2018 Internet Systems Consortium. 2024:04:29-00:10:44 fw-625-2 dhcpd: All rights reserved. 2024:04:29-00:10:44 fw-625-2 dhcpd: For info, please visit https://www.isc.org/software/dhcp/ 2024:04:29-00:10:44 fw-625-2 dhcpd: WARNING: Host declarations are global. They are not limited to the scope you declared them in. 2024:04:29-00:10:44 fw-625-2 dhcpd: Config file: /etc/dhcpd.conf 2024:04:29-00:10:44 fw-625-2 dhcpd: Database file: /var/state/dhcp/dhcpd.leases 2024:04:29-00:10:44 fw-625-2 dhcpd: PID file: /var/run/dhcpd.pid 2024:04:29-00:10:44 fw-625-2 dhcpd: Internet Systems Consortium DHCP Server 4.4.1 2024:04:29-00:10:44 fw-625-2 dhcpd: Copyright 2004-2018 Internet Systems Consortium. 2024:04:29-00:10:44 fw-625-2 dhcpd: All rights reserved. 2024:04:29-00:10:44 fw-625-2 dhcpd: For info, please visit https://www.isc.org/software/dhcp/ 2024:04:29-00:10:44 fw-625-2 dhcpd: Wrote 0 deleted host decls to leases file. 2024:04:29-00:10:44 fw-625-2 dhcpd: Wrote 0 new dynamic host decls to leases file. 2024:04:29-00:10:44 fw-625-2 dhcpd: Wrote 645 leases to leases file. 2024:04:29-00:10:44 fw-625-2 dhcpd: Listening on LPF/eth0/00:1a:8c:f0:98:e0/xz.xz.xz.0/24 2024:04:29-00:10:44 fw-625-2 dhcpd: Sending on LPF/eth0/00:1a:8c:f0:98:e0/xz.xz.xz.0/24 2024:04:29-00:10:44 fw-625-2 dhcpd: Listening on LPF/eth6/00:1a:8c:f0:98:e6/xx.xx.xy.0/22 2024:04:29-00:10:44 fw-625-2 dhcpd: Sending on LPF/eth6/00:1a:8c:f0:98:e6/xx.xx.xy.0/22 2024:04:29-00:10:44 fw-625-2 dhcpd: Listening on LPF/eth9/00:1a:8c:f0:98:e9/xx.xz.xz.0/24 2024:04:29-00:10:44 fw-625-2 dhcpd: Sending on LPF/eth9/00:1a:8c:f0:98:e9/xx.xz.xz.0/24 2024:04:29-00:10:44 fw-625-2 dhcpd: Sending on Socket/fallback/fallback-net 2024:04:29-00:10:44 fw-625-2 dhcpd: Server starting service. 2024:04:29-00:11:15 fw-625-1 dhcpd: DHCPREQUEST for xx.xx.xx.157 from ba:a6:21:bd:a2:c6 via eth6
ha log (5 minute interval):
2024:04:29-00:00:44 fw-625-1 repctl[9560]: [i] recheck(1057): got ALRM: replication recheck triggered Setup_replication_done = 1 2024:04:29-00:04:18 fw-625-2 repctl[9338]: [i] recheck(1057): got ALRM: replication recheck triggered Setup_replication_done = 1 2024:04:29-00:05:44 fw-625-1 repctl[9560]: [i] recheck(1057): got ALRM: replication recheck triggered Setup_replication_done = 1 2024:04:29-00:09:18 fw-625-2 repctl[9338]: [i] recheck(1057): got ALRM: replication recheck triggered Setup_replication_done = 1 2024:04:29-00:10:45 fw-625-1 repctl[9560]: [i] recheck(1057): got ALRM: replication recheck triggered Setup_replication_done = 1 2024:04:29-00:14:18 fw-625-2 repctl[9338]: [i] recheck(1057): got ALRM: replication recheck triggered Setup_replication_done = 1 2024:04:29-00:15:45 fw-625-1 repctl[9560]: [i] recheck(1057): got ALRM: replication recheck triggered Setup_replication_done = 1 2024:04:29-00:19:18 fw-625-2 repctl[9338]: [i] recheck(1057): got ALRM: replication recheck triggered Setup_replication_done = 1
fallback msg log (showing handle dhcpd-leases and /var/mdw/scripts/dhcpd trigger at exact timestamp):
2024:04:29-00:05:43 fw-625-1 [user:notice] cluster_sync[39263]: Args = , called by 6826 /usr/local/bin/ha_daemon 2024:04:29-00:05:43 fw-625-1 [user:notice] cluster_sync[39263]: ### handle 'up2date-sys' 2024:04:29-00:05:43 fw-625-1 [user:notice] cluster_sync[39263]: xxx.xxx.xxx.1 -> xxx.xxx.xxx.2 2024:04:29-00:05:43 fw-625-1 [user:notice] cluster_sync[39263]: only_new: empty filelist 2024:04:29-00:05:43 fw-625-1 [user:notice] cluster_sync[39263]: ### handle 'up2date-pattern' 2024:04:29-00:05:43 fw-625-1 [user:notice] cluster_sync[39263]: xxx.xxx.xxx.1 -> xxx.xxx.xxx.2 2024:04:29-00:05:43 fw-625-1 [user:notice] cluster_sync[39263]: only_new: empty filelist 2024:04:29-00:05:43 fw-625-1 [user:notice] cluster_sync[39263]: ### handle 'cluster-basic' 2024:04:29-00:05:43 fw-625-1 [user:notice] cluster_sync[39263]: xxx.xxx.xxx.1 -> xxx.xxx.xxx.2 2024:04:29-00:05:43 fw-625-1 [user:notice] cluster_sync[39263]: rsync --include /etc/ssh/ssh_host_* --exclude /etc/ssh/** --include /root/.ssh/known_hosts --include /root/.ssh/config --exclude /root/.ssh/** --include /home/login/.ssh/known_hosts --include /home/login/.ssh/config --exclude /home/login/.ssh/** --include /var/sec/chroot-openvpn/var/run/ipp.txt --exclude /var/sec/chroot-openvpn/var/run/** --exclude /var/storage/chroot-http/etc/adsync/*.~!~ --include /var/storage/chroot-smtp/spx/auth/spx-auth-v2.ks --exclude /var/storage/chroot-smtp/spx/auth/* --sockopts=SO_KEEPALIVE --archive --protect-args --delete --relative --no-implied-dirs /etc/ssh /root/.ssh /var/lib/postgresql/.ssh /etc/logremote /etc/krb5.conf /var/confd/var/storage/snapshots /var/sec/chroot-openvpn/var/run /var/log/reporting/accu /var/log/reporting/exec /var/storage/chroot-http/etc/adsync /var/storage/chroot-smtp/spx/auth /var/sec/chroot-quagga/var/run/gw_info /var/sec/chroot-quagga/var/run/gw6_info ClusterSyncUser@xxx.xxx.xxx.2::cluster_sync/ 2024:04:29-00:05:44 fw-625-1 [user:notice] cluster_sync[39263]: 2024:04:29-00:05:44 fw-625-1 [user:notice] cluster_sync[39263]: ### handle 'dhcpd-leases' 2024:04:29-00:05:44 fw-625-1 [user:notice] cluster_sync[39263]: xxx.xxx.xxx.1 -> xxx.xxx.xxx.2 2024:04:29-00:05:44 fw-625-1 [user:notice] cluster_sync[39263]: rsync --sockopts=SO_KEEPALIVE --archive --protect-args --files-from=/tmp/cluster_sync.Reroz --from0 --relative --no-implied-dirs / ClusterSyncUser@xxx.xxx.xxx.2::cluster_sync/ 2024:04:29-00:05:44 fw-625-1 [user:notice] cluster_sync[39263]: rsync --sockopts=SO_KEEPALIVE --archive --protect-args /tmp/cluster_sync.Reroz ClusterSyncUser@xxx.xxx.xxx.2::cluster_sync/var/sec/chroot-dhcps/var/state/dhcp/dhcpd-leases-trigger 2024:04:29-00:05:44 fw-625-1 [user:notice] cluster_sync[39263]: 2024:04:29-00:05:44 fw-625-1 [user:notice] cluster_sync[39263]: ### handle 'logfiles' 2024:04:29-00:05:44 fw-625-1 [user:notice] cluster_sync[39263]: xxx.xxx.xxx.1 -> xxx.xxx.xxx.2 2024:04:29-00:05:44 fw-625-1 [user:notice] cluster_sync[39263]: extra delete run ... 2024:04:29-00:05:44 fw-625-2 [daemon:notice] watch_path[6749]: path '/var/sec/chroot-dhcps/var/state/dhcp/dhcpd-leases-trigger' changed 00:05:44 2024:04:29-00:05:44 fw-625-2 [daemon:notice] watch_path[6749]: forking and calling '/var/mdw/scripts/dhcpd trigger; /var/mdw/scripts/dhcpd6 trigger' 2024:04:29-00:05:44 fw-625-1 [user:notice] cluster_sync[39263]: rsync --sockopts=SO_KEEPALIVE --archive --protect-args --delete --ignore-existing --existing --include-from=/tmp/cluster_sync.Reroz --exclude=/*** --relative --no-implied-dirs /var/log/afc /var/log/aua /var/log/confd /var/log/dhcpd /var/log/http /var/log/ips /var/log/logging /var/log/login /var/log/mdw /var/log/named /var/log/notifier /var/log/openvpn /var/log/packetfilter /var/log/red /var/log/reverseproxy /var/log/service_monitor /var/log/smtp /var/log/sshd /var/log/system /var/log/webadmin /var/log/wireless ClusterSyncUser@xxx.xxx.xxx.2::cluster_sync/ 2024:04:29-00:05:44 fw-625-2 [daemon:notice] watch_path[6749]: /var/mdw/scripts/dhcpd trigger; /var/mdw/scripts/dhcpd6 trigger: returns with 0 2024:04:29-00:05:45 fw-625-1 [user:notice] cluster_sync[39263]: 2024:04:29-00:05:45 fw-625-1 [user:notice] cluster_sync[39263]: rsync --sockopts=SO_KEEPALIVE --archive --protect-args --relative --no-implied-dirs /var/log/afc /var/log/aua /var/log/confd /var/log/dhcpd /var/log/http /var/log/ips /var/log/logging /var/log/login /var/log/mdw /var/log/named /var/log/notifier /var/log/openvpn /var/log/packetfilter /var/log/red /var/log/reverseproxy /var/log/service_monitor /var/log/smtp /var/log/sshd /var/log/system /var/log/webadmin /var/log/wireless ClusterSyncUser@xxx.xxx.xxx.2::cluster_sync/ 2024:04:29-00:05:47 fw-625-1 [user:notice] cluster_sync[39263]: 2024:04:29-00:05:47 fw-625-1 [user:notice] cluster_sync[39263]: ### handle 'sandstorm_rrd'
found this: Sophos UTM DHCP server: "dhcpd: Server starting service" every 5 minutes
selfmonitoring shows 1 entry:
2024:04:29-07:15:47 fw-625-2 selfmonng[40483]: I check Failed increment dhcpd_running counter 1 - 3
Any idea what to check?