Re: Forcing dhclient to not ignore tun0 interface when it's available
On Thu 02 Mar 2023 at 11:44:17 (+0100), davenull@tuxfamily.org wrote:
>
> I finally had the time to dig into the logs from two days ago, when
> the problem happens again
> It seems that dhclient does it requests trying different interfaces
> EXCEPT tun0 (see syslog below)
>
> I looked into /etc/dhcp/dhclient.conf, which mostly commented. In the
> non-commented part shown below
> I don't see anything related to which interfaces are to be used as
> arguments when dhclient is executed
> But I'm not a dhclient expert.
>
> At boot time/without VPN, dhclient is executed with enp.* interface
> accondinng to systemctl/ps -eFH.
> But It still tries different interfaces according to logs. And I have
> no idea how it detects
> which interfaces to use for it requests and why it doesn't detect tun0.
> Maybe because tun0 is not yet exposed by the system at boot time when
> dhclient is started?
>
> It stills try wlan interface even if it is down, which is weird, but
> doesn't seem to do harm except
> spamming syslog and spending a few additional seconds before trying
> another interface.
It's not clear what the status of your vpn was when the logs were
written, AFAICT. It's obviously not soon after booting, as you have
processes running with PIDs in the 40,000s.
It would make sense to start and stop the vnc from a terminal in which
script (bsdutils) was running, preferably with -T to add timestamps to
each command. You could then reconcile the logs with what you were doing.
> ------------
> dave@debian-laptop:~$ systemctl status
>
> ├─ifup@enp2s0f0.service
> │ └─1093 /sbin/dhclient -4 -v -i -pf
> /run/dhclient.enp2s0f0.pid -lf /var/lib/dhcp/dhclient.enp2s0f0.leases
> -I -df /var/lib/dhcp/dhclient6.enp2s0f0.leases enp2s0f0
>
> ------------
I don't know why ifupdown is running, as I thought you were
controlling the network with connman.
> dave@debian-laptop:~$ sudo ausearch --interpret --file /etc/resolv.conf
> ----
> type=PROCTITLE msg=audit(28/02/2023 14:30:57.787:658) : proctitle=mv
> -f /etc/resolv.conf.dhclient-new.46082 /etc/resolv.conf
> type=PATH msg=audit(28/02/2023 14:30:57.787:658) : item=3
> name=/etc/resolv.conf inode=786809 dev=fd:01 mode=file,644 ouid=root
> ogid=root rdev=00:00 nametype=DELETE cap_fp=none cap_fi=none cap_fe=0
> cap_fver=0 cap_frootid=0
> type=PATH msg=audit(28/02/2023 14:30:57.787:658) : item=2
> name=/etc/resolv.conf.dhclient-new.46082 inode=786811 dev=fd:01
> mode=file,644 ouid=root ogid=root rdev=00:00 nametype=DELETE
> cap_fp=none cap_fi=none cap_fe=0 cap_fver=0 cap_frootid=0
> type=PATH msg=audit(28/02/2023 14:30:57.787:658) : item=1 name=/etc/
> inode=783361 dev=fd:01 mode=dir,755 ouid=root ogid=root rdev=00:00
> nametype=PARENT cap_fp=none cap_fi=none cap_fe=0 cap_fver=0
> cap_frootid=0
> type=PATH msg=audit(28/02/2023 14:30:57.787:658) : item=0 name=/etc/
> inode=783361 dev=fd:01 mode=dir,755 ouid=root ogid=root rdev=00:00
> nametype=PARENT cap_fp=none cap_fi=none cap_fe=0 cap_fver=0
> cap_frootid=0
> type=CWD msg=audit(28/02/2023 14:30:57.787:658) : cwd=/
> type=SYSCALL msg=audit(28/02/2023 14:30:57.787:658) : arch=x86_64
> syscall=rename success=no exit=EPERM(Opération non permise)
> a0=0x7ffc38ee0a9e a1=0x7ffc38ee0ac2 a2=0x0 a3=0xfffffffffffffa4d
> items=4 ppid=46082 pid=46093 auid=unset uid=root gid=root euid=root
> suid=root fsuid=root egid=root sgid=root fsgid=root tty=(none)
> ses=unset comm=mv exe=/usr/bin/mv subj=unconfined key=(null)
> ----
>
> Note : exit=EPERM can be ignored, because it happened while I made
> /etc/resolv.conf immutable
This appears to show mv -f /etc/resolv.conf.dhclient-new.46082 /etc/resolv.conf
failing, as expected.
> ------------
>
> dave@debian-laptop:~$ less /var/log/syslog
> Feb 28 14:30:48 debian-laptop dhclient[2016]: DHCPDISCOVER on wlp3s0
> to 255.255.255.255 port 67 interval 3
> Feb 28 14:30:51 debian-laptop dhclient[39759]: DHCPDISCOVER on
> enx8c8caa616f43 to 255.255.255.255 port 67 interval 5
> Feb 28 14:30:51 debian-laptop dhclient[2016]: DHCPDISCOVER on wlp3s0
> to 255.255.255.255 port 67 interval 4
> Feb 28 14:30:55 debian-laptop dhclient[2016]: DHCPDISCOVER on wlp3s0
> to 255.255.255.255 port 67 interval 11
> Feb 28 14:30:56 debian-laptop dhclient[39759]: DHCPDISCOVER on
> enx8c8caa616f43 to 255.255.255.255 port 67 interval 9
> Feb 28 14:30:57 debian-laptop dhclient[1003]: DHCPREQUEST for
> 192.168.1.192 on enp2s0f0 to 192.168.1.1 port 67
> Feb 28 14:30:57 debian-laptop dhclient[1003]: DHCPACK of 192.168.1.192
> from 192.168.1.1
> Feb 28 14:30:57 debian-laptop connmand[1038]: enp2s0f0 {add} address
> 192.168.1.192/24 label enp2s0f0 family 2
> Feb 28 14:30:57 debian-laptop avahi-daemon[1034]: Registering new
> address record for 192.168.1.192 on enp2s0f0.IPv4.
> Feb 28 14:30:57 debian-laptop dhclient[1003]: bound to 192.168.1.192
> -- renewal in 17866 seconds.
One might expect this to be where mv -f fails.
> Feb 28 14:31:05 debian-laptop dhclient[39759]: DHCPDISCOVER on
> enx8c8caa616f43 to 255.255.255.255 port 67 interval 12
> Feb 28 14:31:06 debian-laptop dhclient[2016]: DHCPDISCOVER on wlp3s0
> to 255.255.255.255 port 67 interval 11
> Feb 28 14:31:17 debian-laptop dhclient[39759]: DHCPDISCOVER on
> enx8c8caa616f43 to 255.255.255.255 port 67 interval 14
> Feb 28 14:31:17 debian-laptop systemd[1]: Started Run anacron jobs.
> Feb 28 14:31:17 debian-laptop anacron[46104]: Anacron 2.3 started on
> 2023-02-28
> Feb 28 14:31:17 debian-laptop anacron[46104]: Normal exit (0 jobs run)
> Feb 28 14:31:17 debian-laptop systemd[1]: anacron.service: Succeeded.
> Feb 28 14:31:17 debian-laptop dhclient[2016]: DHCPDISCOVER on wlp3s0
> to 255.255.255.255 port 67 interval 13
> Feb 28 14:31:24 debian-laptop dhclient[39759]: DHCPDISCOVER on wlp3s0
> to 255.255.255.255 port 67 interval 8
> Feb 28 14:31:30 debian-laptop dhclient[2016]: DHCPDISCOVER on wlp3s0
> to 255.255.255.255 port 67 interval 8
> Feb 28 14:31:31 debian-laptop dhclient[39759]: DHCPDISCOVER on
> enx8c8caa616f43 to 255.255.255.255 port 67 interval 16
> Feb 28 14:31:32 debian-laptop dhclient[39759]: DHCPDISCOVER on wlp3s0
> to 255.255.255.255 port 67 interval 17
> Feb 28 14:31:37 debian-laptop rtkit-daemon[1368]: Supervising 18
> threads of 8 processes of 1 users.
> Feb 28 14:31:37 debian-laptop rtkit-daemon[1368]: Supervising 18
> threads of 8 processes of 1 users.
> Feb 28 14:31:38 debian-laptop dhclient[2016]: DHCPDISCOVER on wlp3s0
> to 255.255.255.255 port 67 interval 11
> Feb 28 14:31:47 debian-laptop dhclient[39759]: DHCPDISCOVER on
> enx8c8caa616f43 to 255.255.255.255 port 67 interval 5
> Feb 28 14:31:49 debian-laptop dhclient[2016]: No DHCPOFFERS received.
> Feb 28 14:31:49 debian-laptop dhclient[2016]: No working leases in
> persistent database - sleeping.
> Feb 28 14:31:49 debian-laptop dave:
> /etc/dhcp/dhclient-exit-hooks.d/zzz_avahi-autoipd returned non-zero
> exit status 1
> Feb 28 14:31:49 debian-laptop dhclient[39759]: DHCPDISCOVER on wlp3s0
> to 255.255.255.255 port 67 interval 19
> Feb 28 14:31:52 debian-laptop dhclient[39759]: No DHCPOFFERS received.
> Feb 28 14:31:52 debian-laptop dhclient[39759]: No working leases in
> persistent database - sleeping.
> Feb 28 14:31:52 debian-laptop dave:
> /etc/dhcp/dhclient-exit-hooks.d/zzz_avahi-autoipd returned non-zero
> exit status 1
> Feb 28 14:32:08 debian-laptop dhclient[39759]: DHCPDISCOVER on wlp3s0
> to 255.255.255.255 port 67 interval 15
> Feb 28 14:32:23 debian-laptop dhclient[39759]: DHCPDISCOVER on wlp3s0
> to 255.255.255.255 port 67 interval 2
> Feb 28 14:32:25 debian-laptop dhclient[39759]: No DHCPOFFERS received.
> Feb 28 14:32:25 debian-laptop dhclient[39759]: No working leases in
> persistent database - sleeping.
> Feb 28 14:32:25 debian-laptop dave:
> /etc/dhcp/dhclient-exit-hooks.d/zzz_avahi-autoipd returned non-zero
> exit status 1
> Feb 28 14:32:48 debian-laptop dhclient[39759]: DHCPDISCOVER on
> wlp3s0:avahi to 255.255.255.255 port 67 interval 8
> Feb 28 14:32:56 debian-laptop dhclient[39759]: DHCPDISCOVER on
> wlp3s0:avahi to 255.255.255.255 port 67 interval 11
> Feb 28 14:33:07 debian-laptop dhclient[39759]: DHCPDISCOVER on
> wlp3s0:avahi to 255.255.255.255 port 67 interval 12
>
> ------------
There seems to be a process, 1003, that succeeds in obtaining an
IP address of 192.168.1.192 on ethernet, and another, 2016, that
has set up the wireless interface, but presumably has no
connection to the DHCP server. These processes have been running
since soon after booting, perhaps within seconds.
The third process, 39759, is obviously much more recent, and is
trying to get an address for the interface enx8c…, but also the
wifi interface at the same time as PID 2016. Perhaps this
process was started when connecting or disconnecting the vpn, IDK.
In any case, when both 2016 (at 31:49) and 39759 (at 32:25) fail
to get leases, it looks as if avahi-autoipd kicks in, and 39759
starts sending to the link-local address.
All this is guesswork: I don't run ifupdown, dhclient or
avahi-autoipd, so my logs aren't comparable in many respects.
Also, the immutable resolv.conf might cause subsequent commands
that consult it to go awry.
Cheers,
David.
Reply to: