Dhcpcd takes upwards of 10 seconds to restore address on ethernet

English Network/Internet
#1

I have a relatives PC running Suse 13.1. It has been working fine for a long time just fine, but recently their Ethernet has been taking a substantially long time to come up after a resume from suspend. My interpretation of the logs is that it isn’t properly renewing its connections, but reading the man pages of NM and dhcpcd didn’t produce any results for me. Here is their NM log:

http://pastebin.kde.org/pjiqbbx6x

There are two resumes here - one after 5 hours, in which case it takes 6 seconds to renew the connection, and then one where I just toggle on / off networking and the connection comes back in a second.
I’ll also include a log from one of my machines on their network, to just show that NM with, in this case dhclient, can renew properly even after upwards of 12 hours of downtime, so I don’t think its an issue with their router.

The central gap in the uplink time is here:


2014-05-01T20:15:31.590118-04:00 RubyTempest NetworkManager[724]: <info> (enp3s0): DHCPv4 state changed nbi -> preinit
2014-05-01T20:15:36.971723-04:00 RubyTempest NetworkManager[724]: <info> (enp3s0): DHCPv4 state changed preinit -> reboot

Which leads me to think its a dhcpcd configuration upset. In the network restart, preinit takes less than a second.

http://pastebin.kde.org/p6wwggrhp

Here, the renewal is effectively instant, but this is using dhclient on my Arch system. I just don’t think its a router timeout.

So I tried reading man pages and dhcpcd documentation but couldn’t find anything on preinit taking forever. Any ideas?

#2

Try switching to “dhclient”

Yast → System → /etc/sysconfig editor → network → dhcp → dhcp client → DHCLIENT_BIN

#3

Tried that, it seems to improve the preinit times but not by much. It is still 6 seconds to bring the network back up.

http://pastebin.kde.org/pbh42sqz6

Here are the gaps, first two seconds between disconnected and bringing the carrier up:

2014-05-02T08:34:35.441001-04:00 RubyTempest NetworkManager[718]: <info> NetworkManager state is now DISCONNECTED
2014-05-02T08:34:37.592211-04:00 RubyTempest NetworkManager[718]: <info> (enp3s0): carrier now ON (device state 20)

Then three seconds in preinit still, this time with dhclient:

2014-05-02T08:34:37.615521-04:00 RubyTempest NetworkManager[718]: <info> (enp3s0): DHCPv4 state changed nbi -> preinit
2014-05-02T08:34:40.307961-04:00  RubyTempest NetworkManager[718]: <info> (enp3s0): DHCPv4 state  changed preinit -> reboot

And lastly it spends a second in Stage 5:

2014-05-02T08:34:40.309587-04:00  RubyTempest NetworkManager[718]: <info> Activation (enp3s0) Stage  5 of 5 (IPv4 Commit) started...
2014-05-02T08:34:41.310514-04:00  RubyTempest NetworkManager[718]: <info> (enp3s0): device state  change: ip-config -> secondaries (reason 'none') [70 90 0]

This seems to indicate it is some configuration in networkmanager itself that is making it bring the network back up so slowly. I’m curious why it isn’t doing instant renewals, is there a tweak in something other than NetworkManager.conf that lets you expend the dhcp renewal period?

#4

Well now, I am really puzzled.

I had assumed that your network was set for “ifup” rather than “NetworkManager”.

The reason I assumed that, is that “NetworkManager” always uses “dhclient” and never uses “dhcpcd”.

Now I’m wondering if you have some mixup of “ifup” and “NetworkManager”. I thought that only happened in 12.3.

#5

I reformatted the system fresh with 13.1 instead of trying to upgrade it - and like I said, it was working fine a month ago.

My understanding is that NM prefers dhclient, but that sysctl setting does provoke it into using dhcpcd on Suse.