Investigate slow DHCP lease on wired network

[fawkesley]

Hi folks!

First thing to say, when connected, the internet in the new space is blazing, well done everyone involved, it's awesome.

We've noticed an issue when testing out the wired internet — it can take over 30 second to allocate a DHCP lease. Here's an extract from my /var/log/syslog which demonstrates:

tail -f /var/log/syslog |grep dhclient
May 17 11:06:02 zeus NetworkManager[1176]: <info>  [1526551562.1799] dhcp4 (enp4s0): dhclient started with pid 7526
May 17 11:06:02 zeus kernel: [ 5356.135650] audit: type=1400 audit(1526551562.179:51): apparmor="DENIED" operation="open" profile="/sbin/dhclient" name="/etc/ld.so.preload" pid=7526 comm="dhclient" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
May 17 11:06:02 zeus dhclient[7526]: DHCPREQUEST of 10.0.29.159 on enp4s0 to 255.255.255.255 port 67 (xid=0x5adb4293)
May 17 11:06:05 zeus dhclient[7526]: DHCPREQUEST of 10.0.29.159 on enp4s0 to 255.255.255.255 port 67 (xid=0x5adb4293)
May 17 11:06:08 zeus dhclient[7526]: DHCPREQUEST of 10.0.29.159 on enp4s0 to 255.255.255.255 port 67 (xid=0x5adb4293)
May 17 11:06:14 zeus dhclient[7526]: DHCPDISCOVER on enp4s0 to 255.255.255.255 port 67 interval 3 (xid=0x23b9b723)
May 17 11:06:17 zeus dhclient[7526]: DHCPDISCOVER on enp4s0 to 255.255.255.255 port 67 interval 6 (xid=0x23b9b723)
May 17 11:06:23 zeus dhclient[7526]: DHCPDISCOVER on enp4s0 to 255.255.255.255 port 67 interval 13 (xid=0x23b9b723)
May 17 11:06:36 zeus dhclient[7526]: DHCPDISCOVER on enp4s0 to 255.255.255.255 port 67 interval 16 (xid=0x23b9b723)
May 17 11:06:37 zeus dhclient[7526]: DHCPREQUEST of 10.0.29.159 on enp4s0 to 255.255.255.255 port 67 (xid=0x23b7b923)
May 17 11:06:37 zeus dhclient[7526]: DHCPOFFER of 10.0.29.159 from 10.0.0.1
May 17 11:06:38 zeus dhclient[7526]: DHCPACK of 10.0.29.159 from 10.0.0.1
May 17 11:06:38 zeus dhclient[7526]: bound to 10.0.29.159 -- renewal in 42009 seconds.

Can someone guide me on who to talk to / where to poke / how to start looking into this?

Thanks!

[skos-ninja]

Hi Paul,

Would you be able to confirm if this is a constant issue and if it happens on both wired and wireless?

Thanks,
Jake

[johnmckerrell]

I don’t have logs but I also found that when using wired it took “a while” to connect. It also seemed to lose the IP address and I had to renew to get it back (on a Mac).

…

On 17 May 2018, at 11:26, Jake Oliver ***@***.***> wrote: Hi Paul, Would you be able to confirm if this is a constant issue and if it happens on both wired and wireless? Thanks, Jake — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#796 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AABqa8uIxk18aqAxeWHjfUROvcfJYWrrks5tzVBegaJpZM4UCyG2>.

[fawkesley]

Hi @skos-ninja, I've tried both wired a few times now yes, it's consistent. Wired takes around 35s, wireless is very fast:

May 17 13:05:57 zeus NetworkManager[1176]: <info>  [1526558757.2025] dhcp4 (wlp6s0): dhclient started with pid 27296
May 17 13:05:57 zeus kernel: [12551.256523] audit: type=1400 audit(1526558757.202:74): apparmor="DENIED" operation="open" profile="/sbin/dhclient" name="/etc/ld.so.preload" pid=27296 comm="dhclient" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
May 17 13:05:57 zeus dhclient[27296]: DHCPREQUEST of 10.0.29.160 on wlp6s0 to 255.255.255.255 port 67 (xid=0xc2010ab)
May 17 13:05:57 zeus dhclient[27296]: DHCPACK of 10.0.29.160 from 10.0.0.1
May 17 13:05:57 zeus dhclient[27296]: bound to 10.0.29.160 -- renewal in 35956 seconds.

[skos-ninja]

So this seems to be because the switch we are using by default has spanning tree enabled.

I can disable this and it will speed this up or we can leave it enabled to ensure no network loops can happen.

[skos-ninja]

I have disabled this for now. Do note that if someone creates a network loop then this can break the network currently.

In future we can organise this better once we have more switches

[fawkesley]

Wow, I've learned something, thanks a lot @skos-ninja