On 2019-08-06 22:24:49 +0200, Michael Biebl wrote:
> Ok, so the current state of affairs is:
>
> dhcp=dhclient works always
> dhcp=internal (the default) fails (sometimes)
>
> ?
That's right.
Here are more complete logs for dhcp=internal, first those
corresponding to a success, then those corresponding to a
failure.
cventin:~> journalctl -b -11 -u NetworkManager
-- Logs begin at Tue 2016-04-19 07:35:01 CEST, end at Wed 2019-08-07 11:15:01
CEST. --
Aug 06 15:00:21 cventin systemd[1]: Starting Network Manager...
Aug 06 15:00:21 cventin NetworkManager[766]: <info> [1565096421.8155]
NetworkManager (version 1.19.90) is starting... (for the first time)
Aug 06 15:00:21 cventin NetworkManager[766]: <info> [1565096421.8156] Read
config: /etc/NetworkManager/NetworkManager.conf (lib: no-mac-addr-change.conf)
Aug 06 15:00:21 cventin NetworkManager[766]: <warn> [1565096421.8157] config:
unknown key 'wifi.cloned-mac-address' in section [device-mac-addr-change-wifi]
of file '/usr/lib/NetworkManager/conf.d/no-mac-addr-change.conf'
Aug 06 15:00:21 cventin NetworkManager[766]: <warn> [1565096421.8157] config:
unknown key 'ethernet.cloned-mac-address' in section
[device-mac-addr-change-wifi] of file
'/usr/lib/NetworkManager/conf.d/no-mac-addr-change.conf'
Aug 06 15:00:21 cventin NetworkManager[766]: <info> [1565096421.8183]
bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
Aug 06 15:00:21 cventin NetworkManager[766]: <info> [1565096421.8244]
manager[0x558e247f6020]: monitoring kernel firmware directory '/lib/firmware'.
Aug 06 15:00:21 cventin NetworkManager[766]: <info> [1565096421.8245]
monitoring ifupdown state file '/run/network/ifstate'.
Aug 06 15:00:23 cventin systemd[1]: Started Network Manager.
Aug 06 15:00:23 cventin NetworkManager[766]: <info> [1565096423.8146]
hostname: hostname: using hostnamed
Aug 06 15:00:23 cventin NetworkManager[766]: <info> [1565096423.8147]
hostname: hostname changed from (none) to "cventin"
Aug 06 15:00:23 cventin NetworkManager[766]: <info> [1565096423.8153]
dns-mgr[0x558e247d2240]: init: dns=default,systemd-resolved
rc-manager=resolvconf
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.4806] Loaded
device plugin: NMWifiFactory
(/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-wifi.so)
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.5546] Loaded
device plugin: NMBluezManager
(/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-bluetooth.so)
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.5610] Loaded
device plugin: NMWwanFactory
(/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-wwan.so)
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.5843] Loaded
device plugin: NMTeamFactory
(/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-team.so)
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.5884] Loaded
device plugin: NMAtmManager
(/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-adsl.so)
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.5887] manager:
rfkill: Wi-Fi enabled by radio killswitch; enabled by state file
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.5889] manager:
rfkill: WWAN enabled by radio killswitch; enabled by state file
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.5891] manager:
Networking is enabled by state file
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.5893]
dhcp-init: Using DHCP client 'internal'
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.6139]
settings: Loaded settings plugin: ifupdown
("/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-settings-plugin-ifupdown.so")
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.6139]
settings: Loaded settings plugin: keyfile (internal)
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.6139]
ifupdown: management mode: unmanaged
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.6140]
ifupdown: interface-parser: parsing file /etc/network/interfaces
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.6140]
ifupdown: interface-parser: source line includes interfaces file(s)
/etc/network/interfaces.d/*
Aug 06 15:00:24 cventin NetworkManager[766]: <warn> [1565096424.6141]
ifupdown: interfaces file /etc/network/interfaces.d/* doesn't exist
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.6141]
ifupdown: interface-parser: finished parsing file /etc/network/interfaces
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.6479] device
(lo): carrier: link connected
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.6483] manager:
(lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.6495] manager:
(enp0s25): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.6544]
settings: (enp0s25): created default wired connection 'Wired connection 2'
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.6553] device
(enp0s25): state change: unmanaged -> unavailable (reason 'managed',
sys-iface-state: 'external')
Aug 06 15:00:24 cventin NetworkManager[766]: <info> [1565096424.8903]
modem-manager: ModemManager available
Aug 06 15:00:28 cventin NetworkManager[766]: <info> [1565096428.4309] device
(enp0s25): carrier: link connected
Aug 06 15:00:28 cventin NetworkManager[766]: <info> [1565096428.4315] device
(enp0s25): state change: unavailable -> disconnected (reason 'carrier-changed',
sys-iface-state: 'managed')
Aug 06 15:00:28 cventin NetworkManager[766]: <info> [1565096428.4328] policy:
auto-activating connection 'Wired connection 1'
(c89d3bc3-8d9e-44f8-ac86-7e6884d08219)
Aug 06 15:00:28 cventin NetworkManager[766]: <info> [1565096428.4340] device
(enp0s25): Activation: starting connection 'Wired connection 1'
(c89d3bc3-8d9e-44f8-ac86-7e6884d08219)
Aug 06 15:00:28 cventin NetworkManager[766]: <info> [1565096428.4342] device
(enp0s25): state change: disconnected -> prepare (reason 'none',
sys-iface-state: 'managed')
Aug 06 15:00:28 cventin NetworkManager[766]: <info> [1565096428.4348] manager:
NetworkManager state is now CONNECTING
Aug 06 15:00:28 cventin NetworkManager[766]: <info> [1565096428.4351] device
(enp0s25): state change: prepare -> config (reason 'none', sys-iface-state:
'managed')
Aug 06 15:00:28 cventin NetworkManager[766]: <info> [1565096428.4359] device
(enp0s25): state change: config -> ip-config (reason 'none', sys-iface-state:
'managed')
Aug 06 15:00:28 cventin NetworkManager[766]: <info> [1565096428.4365] dhcp4
(enp0s25): activation: beginning transaction (timeout in 45 seconds)
Aug 06 15:00:34 cventin NetworkManager[766]: <info> [1565096434.0690] dhcp4
(enp0s25): state changed unknown -> bound
Aug 06 15:00:34 cventin NetworkManager[766]: <info> [1565096434.0705] device
(enp0s25): state change: ip-config -> ip-check (reason 'none', sys-iface-state:
'managed')
Aug 06 15:00:34 cventin NetworkManager[766]: <info> [1565096434.0730] device
(enp0s25): state change: ip-check -> secondaries (reason 'none',
sys-iface-state: 'managed')
Aug 06 15:00:34 cventin NetworkManager[766]: <info> [1565096434.0734] device
(enp0s25): state change: secondaries -> activated (reason 'none',
sys-iface-state: 'managed')
Aug 06 15:00:34 cventin NetworkManager[766]: <info> [1565096434.0740] manager:
NetworkManager state is now CONNECTED_LOCAL
Aug 06 15:00:34 cventin NetworkManager[766]: <info> [1565096434.0755] manager:
NetworkManager state is now CONNECTED_SITE
Aug 06 15:00:34 cventin NetworkManager[766]: <info> [1565096434.0756] policy:
set 'Wired connection 1' (enp0s25) as default for IPv4 routing and DNS
Aug 06 15:00:34 cventin NetworkManager[766]: <info> [1565096434.0808] device
(enp0s25): Activation: successful, device activated.
Aug 06 15:00:34 cventin NetworkManager[766]: <info> [1565096434.0818] manager:
NetworkManager state is now CONNECTED_GLOBAL
Aug 06 15:00:34 cventin NetworkManager[766]: <info> [1565096434.0826] manager:
startup complete
Aug 06 15:12:13 cventin NetworkManager[766]: <info> [1565097133.8531]
modem-manager: ModemManager no longer available
Aug 06 15:12:16 cventin systemd[1]: Stopping Network Manager...
Aug 06 15:12:16 cventin NetworkManager[766]: <info> [1565097136.8430] caught
SIGTERM, shutting down normally.
Aug 06 15:12:16 cventin NetworkManager[766]: <info> [1565097136.8443] dhcp4
(enp0s25): canceled DHCP transaction
Aug 06 15:12:16 cventin NetworkManager[766]: <info> [1565097136.8444] dhcp4
(enp0s25): state changed bound -> done
Aug 06 15:12:16 cventin NetworkManager[766]: <info> [1565097136.8444] device
(enp0s25): DHCPv4: 480 seconds grace period started
Aug 06 15:12:16 cventin NetworkManager[766]: <info> [1565097136.8449] manager:
NetworkManager state is now CONNECTED_SITE
Aug 06 15:12:16 cventin NetworkManager[766]: <info> [1565097136.8517] exiting
(success)
Aug 06 15:12:16 cventin systemd[1]: NetworkManager.service: Succeeded.
Aug 06 15:12:16 cventin systemd[1]: Stopped Network Manager.
cventin:~> journalctl -b -10 -u NetworkManager
-- Logs begin at Tue 2016-04-19 07:35:01 CEST, end at Wed 2019-08-07 11:15:01
CEST. --
Aug 06 15:12:53 cventin systemd[1]: Starting Network Manager...
Aug 06 15:12:54 cventin NetworkManager[807]: <info> [1565097174.0730]
NetworkManager (version 1.19.90) is starting... (for the first time)
Aug 06 15:12:54 cventin NetworkManager[807]: <info> [1565097174.0731] Read
config: /etc/NetworkManager/NetworkManager.conf (lib: no-mac-addr-change.conf)
Aug 06 15:12:54 cventin NetworkManager[807]: <warn> [1565097174.0732] config:
unknown key 'wifi.cloned-mac-address' in section [device-mac-addr-change-wifi]
of file '/usr/lib/NetworkManager/conf.d/no-mac-addr-change.conf'
Aug 06 15:12:54 cventin NetworkManager[807]: <warn> [1565097174.0732] config:
unknown key 'ethernet.cloned-mac-address' in section
[device-mac-addr-change-wifi] of file
'/usr/lib/NetworkManager/conf.d/no-mac-addr-change.conf'
Aug 06 15:12:54 cventin NetworkManager[807]: <info> [1565097174.0769]
bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
Aug 06 15:12:54 cventin NetworkManager[807]: <info> [1565097174.0823]
manager[0x55d6af5ac020]: monitoring kernel firmware directory '/lib/firmware'.
Aug 06 15:12:54 cventin NetworkManager[807]: <info> [1565097174.0823]
monitoring ifupdown state file '/run/network/ifstate'.
Aug 06 15:12:54 cventin systemd[1]: Started Network Manager.
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7226]
hostname: hostname: using hostnamed
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7226]
hostname: hostname changed from (none) to "cventin"
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7232]
dns-mgr[0x55d6af589240]: init: dns=default,systemd-resolved
rc-manager=resolvconf
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7328] Loaded
device plugin: NMWifiFactory
(/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-wifi.so)
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7396] Loaded
device plugin: NMBluezManager
(/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-bluetooth.so)
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7406] Loaded
device plugin: NMWwanFactory
(/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-wwan.so)
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7436] Loaded
device plugin: NMTeamFactory
(/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-team.so)
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7446] Loaded
device plugin: NMAtmManager
(/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-device-plugin-adsl.so)
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7449] manager:
rfkill: Wi-Fi enabled by radio killswitch; enabled by state file
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7450] manager:
rfkill: WWAN enabled by radio killswitch; enabled by state file
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7451] manager:
Networking is enabled by state file
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7453]
dhcp-init: Using DHCP client 'internal'
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7466]
settings: Loaded settings plugin: ifupdown
("/usr/lib/x86_64-linux-gnu/NetworkManager/1.19.90/libnm-settings-plugin-ifupdown.so")
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7466]
settings: Loaded settings plugin: keyfile (internal)
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7466]
ifupdown: management mode: unmanaged
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7467]
ifupdown: interface-parser: parsing file /etc/network/interfaces
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7467]
ifupdown: interface-parser: source line includes interfaces file(s)
/etc/network/interfaces.d/*
Aug 06 15:12:55 cventin NetworkManager[807]: <warn> [1565097175.7467]
ifupdown: interfaces file /etc/network/interfaces.d/* doesn't exist
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7468]
ifupdown: interface-parser: finished parsing file /etc/network/interfaces
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7517] device
(lo): carrier: link connected
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7521] manager:
(lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7532] manager:
(enp0s25): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7565]
settings: (enp0s25): created default wired connection 'Wired connection 2'
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.7572] device
(enp0s25): state change: unmanaged -> unavailable (reason 'managed',
sys-iface-state: 'external')
Aug 06 15:12:55 cventin NetworkManager[807]: <info> [1565097175.9889]
modem-manager: ModemManager available
Aug 06 15:12:59 cventin NetworkManager[807]: <info> [1565097179.5367] device
(enp0s25): carrier: link connected
Aug 06 15:12:59 cventin NetworkManager[807]: <info> [1565097179.5375] device
(enp0s25): state change: unavailable -> disconnected (reason 'carrier-changed',
sys-iface-state: 'managed')
Aug 06 15:12:59 cventin NetworkManager[807]: <info> [1565097179.5393] policy:
auto-activating connection 'Wired connection 1'
(c89d3bc3-8d9e-44f8-ac86-7e6884d08219)
Aug 06 15:12:59 cventin NetworkManager[807]: <info> [1565097179.5407] device
(enp0s25): Activation: starting connection 'Wired connection 1'
(c89d3bc3-8d9e-44f8-ac86-7e6884d08219)
Aug 06 15:12:59 cventin NetworkManager[807]: <info> [1565097179.5410] device
(enp0s25): state change: disconnected -> prepare (reason 'none',
sys-iface-state: 'managed')
Aug 06 15:12:59 cventin NetworkManager[807]: <info> [1565097179.5419] manager:
NetworkManager state is now CONNECTING
Aug 06 15:12:59 cventin NetworkManager[807]: <info> [1565097179.5424] device
(enp0s25): state change: prepare -> config (reason 'none', sys-iface-state:
'managed')
Aug 06 15:12:59 cventin NetworkManager[807]: <info> [1565097179.5434] device
(enp0s25): state change: config -> ip-config (reason 'none', sys-iface-state:
'managed')
Aug 06 15:12:59 cventin NetworkManager[807]: <info> [1565097179.5441] dhcp4
(enp0s25): activation: beginning transaction (timeout in 45 seconds)
Aug 06 15:13:05 cventin NetworkManager[807]: <info> [1565097185.2693] dhcp4
(enp0s25): state changed unknown -> expire
Aug 06 15:14:04 cventin NetworkManager[807]: <info> [1565097244.3113]
modem-manager: ModemManager no longer available
Aug 06 15:14:06 cventin systemd[1]: Stopping Network Manager...
Aug 06 15:14:06 cventin NetworkManager[807]: <info> [1565097246.3392] caught
SIGTERM, shutting down normally.
Aug 06 15:14:06 cventin NetworkManager[807]: <info> [1565097246.3655] dhcp4
(enp0s25): canceled DHCP transaction
Aug 06 15:14:06 cventin NetworkManager[807]: <info> [1565097246.3655] dhcp4
(enp0s25): state changed expire -> done
Aug 06 15:14:06 cventin NetworkManager[807]: <info> [1565097246.3656] dhcp4
(enp0s25): canceled DHCP transaction
Aug 06 15:14:06 cventin NetworkManager[807]: <info> [1565097246.3665] manager:
startup complete
Aug 06 15:14:06 cventin NetworkManager[807]: <info> [1565097246.3732] exiting
(success)
Aug 06 15:14:06 cventin systemd[1]: NetworkManager.service: Succeeded.
Aug 06 15:14:06 cventin systemd[1]: Stopped Network Manager.
The first difference is: "state changed unknown -> bound" in the first
case, "state changed unknown -> expire" in the second case.
With dhclient instead of internal, one has:
[...]
Aug 06 15:48:15 cventin NetworkManager[797]: <info> [1565099295.6037] dhcp4
(enp0s25): dhclient started with pid 1052
Aug 06 15:48:15 cventin dhclient[1052]: DHCPREQUEST for 140.77.13.17 on enp0s25
to 255.255.255.255 port 67
Aug 06 15:48:21 cventin dhclient[1052]: DHCPREQUEST for 140.77.13.17 on enp0s25
to 255.255.255.255 port 67
Aug 06 15:48:21 cventin dhclient[1052]: DHCPNAK from 10.0.1.1
Aug 06 15:48:21 cventin NetworkManager[797]: <info> [1565099301.7956] dhcp4
(enp0s25): state changed unknown -> expire
Aug 06 15:48:21 cventin NetworkManager[797]: <info> [1565099301.8037] dhcp4
(enp0s25): state changed expire -> unknown
Aug 06 15:48:21 cventin dhclient[1052]: DHCPDISCOVER on enp0s25 to
255.255.255.255 port 67 interval 4
Aug 06 15:48:21 cventin dhclient[1052]: DHCPOFFER of 140.77.13.17 from
140.77.1.12
Aug 06 15:48:21 cventin dhclient[1052]: DHCPREQUEST for 140.77.13.17 on enp0s25
to 255.255.255.255 port 67
Aug 06 15:48:21 cventin dhclient[1052]: DHCPACK of 140.77.13.17 from 140.77.1.12
Aug 06 15:48:21 cventin NetworkManager[797]: <info> [1565099301.8160] dhcp4
(enp0s25): address 140.77.13.17
[...]
--
Vincent Lefèvre <vinc...@vinc17.net> - Web: <https://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <https://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / AriC project (LIP, ENS-Lyon)
