Is this bug still present in Precise? -- You received this bug notification because you are a member of Desktop Packages, which is subscribed to network-manager in Ubuntu. https://bugs.launchpad.net/bugs/583705
Title: DHCP transaction took too long, stopping it Status in “network-manager” package in Ubuntu: New Bug description: Binary package hint: network-manager When doing a cold start for a lucid slave in virtual box, nm doesn't obtain an IP address and output the following in /var/log/syslog: May 21 09:50:30 lucid64 NetworkManager: <info> (eth0): DHCP transaction took too long, stopping it. May 21 09:50:30 lucid64 NetworkManager: <info> (eth0): canceled DHCP transaction, dhcp client pid 756 May 21 09:50:30 lucid64 NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Timeout) scheduled... May 21 09:50:30 lucid64 NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Timeout) started... May 21 09:50:30 lucid64 NetworkManager: <info> (eth0): device state change: 7 -> 9 (reason 5) May 21 09:50:30 lucid64 NetworkManager: <info> Marking connection 'Auto eth0' invalid. May 21 09:50:30 lucid64 NetworkManager: <info> Activation (eth0) failed. May 21 09:50:30 lucid64 NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Timeout) complete. May 21 09:50:30 lucid64 NetworkManager: <info> (eth0): device state change: 9 -> 3 (reason 0) May 21 09:50:30 lucid64 NetworkManager: <info> (eth0): deactivating device (reason: 0). If I select the 'Auto eth0' in the nm-applet menu it succeeds with: May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) starting connection 'Auto eth0' May 21 09:54:24 lucid64 NetworkManager: <info> (eth0): device state change: 3 -> 4 (reason 0) May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled... May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) started... May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) Stage 2 of 5 (Device Configure) scheduled... May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) complete. May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) Stage 2 of 5 (Device Configure) starting... May 21 09:54:24 lucid64 NetworkManager: <info> (eth0): device state change: 4 -> 5 (reason 0) May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) Stage 2 of 5 (Device Configure) successful. May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled. May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) Stage 2 of 5 (Device Configure) complete. May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started... May 21 09:54:24 lucid64 NetworkManager: <info> (eth0): device state change: 5 -> 7 (reason 0) May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) Beginning DHCP transaction (timeout in 45 seconds) May 21 09:54:24 lucid64 NetworkManager: <info> dhclient started with pid 1419 May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Get) scheduled... May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) complete. May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Get) started... May 21 09:54:24 lucid64 NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Get) complete. May 21 09:54:24 lucid64 dhclient: Internet Systems Consortium DHCP Client V3.1.3 May 21 09:54:24 lucid64 dhclient: Copyright 2004-2009 Internet Systems Consortium. May 21 09:54:24 lucid64 dhclient: All rights reserved. May 21 09:54:24 lucid64 dhclient: For info, please visit https://www.isc.org/software/dhcp/ May 21 09:54:24 lucid64 dhclient: May 21 09:54:24 lucid64 NetworkManager: <info> DHCP: device eth0 state changed normal exit -> preinit May 21 09:54:24 lucid64 dhclient: Listening on LPF/eth0/08:00:27:cf:44:62 May 21 09:54:24 lucid64 dhclient: Sending on LPF/eth0/08:00:27:cf:44:62 May 21 09:54:24 lucid64 dhclient: Sending on Socket/fallback May 21 09:54:27 lucid64 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 5 May 21 09:54:27 lucid64 dhclient: DHCPOFFER of 192.168.0.24 from 192.168.0.254 May 21 09:54:27 lucid64 dhclient: DHCPREQUEST of 192.168.0.24 on eth0 to 255.255.255.255 port 67 May 21 09:54:27 lucid64 dhclient: DHCPACK of 192.168.0.24 from 192.168.0.254 May 21 09:54:27 lucid64 dhclient: bound to 192.168.0.24 -- renewal in 350100 seconds. May 21 09:54:27 lucid64 NetworkManager: <info> DHCP: device eth0 state changed preinit -> bound May 21 09:54:27 lucid64 NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) scheduled... May 21 09:54:27 lucid64 NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) started... May 21 09:54:27 lucid64 NetworkManager: <info> address 192.168.0.24 May 21 09:54:27 lucid64 NetworkManager: <info> prefix 24 (255.255.255.0) May 21 09:54:27 lucid64 NetworkManager: <info> gateway 192.168.0.254 May 21 09:54:27 lucid64 NetworkManager: <info> nameserver '212.27.40.240' May 21 09:54:27 lucid64 NetworkManager: <info> nameserver '212.27.40.241' May 21 09:54:27 lucid64 NetworkManager: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) scheduled... May 21 09:54:27 lucid64 NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) complete. May 21 09:54:27 lucid64 NetworkManager: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) started... May 21 09:54:27 lucid64 avahi-daemon[745]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.0.24. May 21 09:54:27 lucid64 avahi-daemon[745]: New relevant interface eth0.IPv4 for mDNS. May 21 09:54:27 lucid64 avahi-daemon[745]: Registering new address record for 192.168.0.24 on eth0.IPv4. May 21 09:54:28 lucid64 NetworkManager: <info> (eth0): device state change: 7 -> 8 (reason 0) May 21 09:54:28 lucid64 NetworkManager: <info> Policy set 'Auto eth0' (eth0) as default for routing and DNS. May 21 09:54:28 lucid64 NetworkManager: <info> Activation (eth0) successful, device activated. May 21 09:54:28 lucid64 NetworkManager: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete. It also succeeds on reboot. It also succeds if i do 'dhclient eth0'. Using wireshark with a display filter for the corresponding MAC address reveals that the DHCP request is not sent during the first boot. How can I debug this further ? Also, reading the dhclient manpage says that it should fallback to a previsouly acquired lease, this never occurs. Is there a way to: - force a fallback address ? - make dhclient use a previous lease ? - make nm retry the dhcp request ? I attributed this bug to nm as it's the only one producing output in syslog and I'm unclear about which package is really responsible here. Finally, this bug is transient, *sometimes* the host get its IP address and I also encounter the problem with a karmic vm (but less often). I seem to be able to reproduce the problem more reliably for a couple of days on lucid though. To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/network-manager/+bug/583705/+subscriptions -- Mailing list: https://launchpad.net/~desktop-packages Post to : [email protected] Unsubscribe : https://launchpad.net/~desktop-packages More help : https://help.launchpad.net/ListHelp
