NM stop trying to get a DHCP lease

[Jean-Christian de Rivaz <jc eclis ch>]

Hi,

On a armhf Debian Jessie embedded device with a ethernet and a mobile 
modem connectivity I get this strange situation where NetworkManager 
stop trying to get a DHCP lease. 'nmcli d' return this:

DEVICE   TYPE      STATE CONNECTION
ttyACM4  gsm       connected gsm1
ppp0     unknown   connected ppp0
eth0     ethernet  connecting (getting IP configuration)  Wired 
connection 1
wlan0    wifi      disconnected --
lo       loopback  unmanaged --
sit0     sit       unmanaged                              --

But the /var/log/daemon.log show no dhcpclient activation since a least 
24 hours. The last related dhcpclient log are this, after there are only 
mobile modem related messages:

3854128:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
(eth0): link connected
3854129:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
(eth0): device state change: unavailable -> disconnected (reason 
'carrier-changed') [20 30 40]
3854130:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
Auto-activating connection 'Wired connection 1'.
3854131:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) starting connection 'Wired connection 1'
3854132:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...
3854133:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) Stage 1 of 5 (Device Prepare) started...
3854134:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
(eth0): device state change: disconnected -> prepare (reason 'none') [30 
40 0]
3854135:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...
3854136:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) Stage 1 of 5 (Device Prepare) complete.
3854137:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) Stage 2 of 5 (Device Configure) starting...
3854138:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
(eth0): device state change: prepare -> config (reason 'none') [40 50 0]
3854139:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) Stage 2 of 5 (Device Configure) successful.
3854140:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.
3854141:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) Stage 2 of 5 (Device Configure) complete.
3854142:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
3854143:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
(eth0): device state change: config -> ip-config (reason 'none') [50 70 0]
3854144:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) Beginning DHCPv4 transaction (timeout in 45 seconds)
3854145:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
dhclient started with pid 4044
3854146:Jul 14 10:07:41 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
3854147:Jul 14 10:07:42 menhir-15220006 NetworkManager[1106]: <info> 
(eth0): DHCPv4 state changed nbi -> preinit
3854151:Jul 14 10:07:42 menhir-15220006 dhclient: DHCPREQUEST on eth0 to 
255.255.255.255 port 67
3854164:Jul 14 10:07:48 menhir-15220006 dhclient: DHCPREQUEST on eth0 to 
255.255.255.255 port 67
3854166:Jul 14 10:07:55 menhir-15220006 dhclient: DHCPDISCOVER on eth0 
to 255.255.255.255 port 67 interval 8
3854167:Jul 14 10:08:03 menhir-15220006 dhclient: DHCPDISCOVER on eth0 
to 255.255.255.255 port 67 interval 15
3854168:Jul 14 10:08:18 menhir-15220006 dhclient: DHCPDISCOVER on eth0 
to 255.255.255.255 port 67 interval 14
3854169:Jul 14 10:08:19 menhir-15220006 NetworkManager[1106]: <info> 
(eth0): link disconnected (deferring action for 4 seconds)
3854170:Jul 14 10:08:22 menhir-15220006 NetworkManager[1106]: <info> 
(eth0): link connected
3854171:Jul 14 10:08:26 menhir-15220006 NetworkManager[1106]: <warn> 
(eth0): DHCPv4 request timed out.
3854172:Jul 14 10:08:27 menhir-15220006 NetworkManager[1106]: <info> 
(eth0): canceled DHCP transaction, DHCP client pid 4044
3854173:Jul 14 10:08:27 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) Stage 4 of 5 (IPv4 Configure Timeout) scheduled...
3854174:Jul 14 10:08:27 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) Stage 4 of 5 (IPv4 Configure Timeout) started...
3854175:Jul 14 10:08:27 menhir-15220006 NetworkManager[1106]: <info> 
Activation (eth0) Stage 4 of 5 (IPv4 Configure Timeout) complete.

While it way probably true that there was no DHCP server on that link at 
this time because this was part of a test procedure, the ethernet link 
get a working DHCP server some minutes later. But NetworkManager don't 
seem to try anymore to find a DHCP server since a full day now, so the 
device continue to use the mobile modem despite having a fully working 
ethernet connection available.

I that the expected behavior or did I miss something ?

Best Regards,
Jean-Christian de Rivaz