Re: [SOLVED] Re: Why does resolv.conf keep changing?
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
Reply to: