On Thu, Oct 26, 2017 at 09:35:03AM -0400, Greg Wooledge wrote: > On Thu, Oct 26, 2017 at 09:06:09AM -0400, Roberto C. Sánchez wrote: > > debian:/etc# systemctl status networking > > [...] > > Is this the new normal, for things to get captured in some systemd log > > that I cannot grep out of /var/log? I specifically recall in the past > > on older pre-systemd systems that these exchanges between the DHCP > > client and server would get logged by syslog. > > > > I guess this explains why things that I recalled being logged in the > > past suddenly disappeared from syslog. > > I seem to have the information in both places. > > wooledg:~$ grep dhclient /var/log/syslog > Oct 26 08:39:56 wooledg dhclient[514]: DHCPREQUEST of 10.76.172.97 on eth0 to > 10.127.1.4 port 67 > Oct 26 08:39:56 wooledg dhclient[514]: DHCPACK of 10.76.172.97 from 10.127.1.4 > Oct 26 08:39:56 wooledg dhclient[514]: bound to 10.76.172.97 -- renewal in > 119104 seconds. > > Are you sure you've got rsyslog installed and running? > I do have a syslog package installed and running. It is possible I misremembered what was previously logged where, but there is a clear discrepancy between what goes to syslog and what systemd captures:
debian:/etc# date Thu Oct 26 09:39:02 EDT 2017 debian:/etc# chattr +i /etc/resolv.conf debian:/etc# systemctl restart networking debian:/etc# egrep 'Oct 26 09:39.*dhclient' /var/log/syslog Oct 26 09:39:10 debian dhclient[35357]: Killed old client process Oct 26 09:39:11 debian dhclient[35357]: Internet Systems Consortium DHCP Client 4.3.5 Oct 26 09:39:11 debian dhclient[35357]: Copyright 2004-2016 Internet Systems Consortium. Oct 26 09:39:11 debian dhclient[35357]: All rights reserved. Oct 26 09:39:11 debian dhclient[35357]: For info, please visit https://www.isc.org/software/dhcp/ Oct 26 09:39:11 debian dhclient[35357]: Oct 26 09:39:11 debian dhclient[35357]: Listening on LPF/eth1/a0:48:1c:b8:01:d1 Oct 26 09:39:11 debian dhclient[35357]: Sending on LPF/eth1/a0:48:1c:b8:01:d1 Oct 26 09:39:11 debian dhclient[35357]: Sending on Socket/fallback Oct 26 09:39:11 debian dhclient[35357]: DHCPRELEASE on eth1 to 192.168.63.1 port 67 Oct 26 09:39:12 debian dhclient[35528]: Internet Systems Consortium DHCP Client 4.3.5 Oct 26 09:39:12 debian dhclient[35528]: Copyright 2004-2016 Internet Systems Consortium. Oct 26 09:39:12 debian dhclient[35528]: All rights reserved. Oct 26 09:39:12 debian dhclient[35528]: For info, please visit https://www.isc.org/software/dhcp/ Oct 26 09:39:12 debian dhclient[35528]: Oct 26 09:39:12 debian dhclient[35528]: Listening on LPF/eth1/a0:48:1c:b8:01:d1 Oct 26 09:39:12 debian dhclient[35528]: Sending on LPF/eth1/a0:48:1c:b8:01:d1 Oct 26 09:39:12 debian dhclient[35528]: Sending on Socket/fallback Oct 26 09:39:12 debian dhclient[35528]: DHCPDISCOVER on eth1 to 255.255.255.255 port 67 interval 7 Oct 26 09:39:19 debian dhclient[35528]: DHCPDISCOVER on eth1 to 255.255.255.255 port 67 interval 13 Oct 26 09:39:19 debian dhclient[35528]: DHCPREQUEST of 192.168.63.197 on eth1 to 255.255.255.255 port 67 Oct 26 09:39:19 debian dhclient[35528]: DHCPOFFER of 192.168.63.197 from 192.168.63.1 Oct 26 09:39:19 debian dhclient[35528]: DHCPACK of 192.168.63.197 from 192.168.63.1 Oct 26 09:39:19 debian dhclient[35528]: bound to 192.168.63.197 -- renewal in 14309 seconds. debian:/etc# systemctl status networking ● networking.service - Raise network interfaces Loaded: loaded (/lib/systemd/system/networking.service; enabled; vendor preset: enabled) Active: active (exited) since Thu 2017-10-26 09:39:19 EDT; 56s ago Docs: man:interfaces(5) Process: 35274 ExecStop=/sbin/ifdown -a --read-environment --exclude=lo (code=exited, status=0/SUCCESS) Process: 35433 ExecStart=/sbin/ifup -a --read-environment (code=exited, status=0/SUCCESS) Process: 35427 ExecStartPre=/bin/sh -c [ "$CONFIGURE_INTERFACES" != "no" ] && [ -n "$(ifquery --read-en Main PID: 35433 (code=exited, status=0/SUCCESS) Tasks: 1 (limit: 9830) CGroup: /system.slice/networking.service └─35558 /sbin/dhclient -4 -v -pf /run/dhclient.eth1.pid -lf /var/lib/dhcp/dhclient.eth1.leases Oct 26 09:39:12 debian ifup[35433]: Sending on LPF/eth1/a0:48:1c:b8:01:d1 Oct 26 09:39:12 debian ifup[35433]: Sending on Socket/fallback Oct 26 09:39:12 debian ifup[35433]: DHCPDISCOVER on eth1 to 255.255.255.255 port 67 interval 7 Oct 26 09:39:19 debian ifup[35433]: DHCPDISCOVER on eth1 to 255.255.255.255 port 67 interval 13 Oct 26 09:39:19 debian ifup[35433]: DHCPREQUEST of 192.168.63.197 on eth1 to 255.255.255.255 port 67 Oct 26 09:39:19 debian ifup[35433]: DHCPOFFER of 192.168.63.197 from 192.168.63.1 Oct 26 09:39:19 debian ifup[35433]: DHCPACK of 192.168.63.197 from 192.168.63.1 Oct 26 09:39:19 debian ifup[35433]: mv: cannot move '/etc/resolv.conf.dhclient-new.35546' to '/etc/reso Oct 26 09:39:19 debian ifup[35433]: bound to 192.168.63.197 -- renewal in 14309 seconds. Oct 26 09:39:19 debian systemd[1]: Started Raise network interfaces. In particular, systemd appears to capture this line: ifup[35433]: mv: cannot move '/etc/resolv.conf.dhclient-new.35546' to '/etc/resolve.conf' That line is not anywhere in syslog. As you pointed out in another post, dhclient-script is riddled with bugs. The blind use of 'mv -f' to replace resolv.conf appears to be one of those bugs. There is no provision for that command to fail, nor is there any effort to capture and report antying that may appear on the standard error stream. Though it does check the exit status of any hook scripts that it executes. Even simply logging the fact that it is replacing resolv.conf would be a nice thing and would have saved me hours of troubleshooting. I also looked back through my logs and found lots of dhclient entries from the last day or so and many leading up to about a month ago, but there is a gap there as well. That was part of made the initial troubleshootin difficult. Somehow resolv.conf would change and I could not correlate the change to anything that was being logged. Regards, -Roberto -- Roberto C. Sánchez
