Re: No ip from dhcp (com.redhat.dhcp.OperationInProgress)

[Dan Williams <dcbw redhat com>]

On Wed, 2007-04-18 at 15:26 +0200, Paulus Esterhazy wrote:
> Hello developers,
> 
> I'm using network-manager 0.6.4-6ubuntu7 from soon-to-be-released Ubuntu 
> feisty. This looks like a bug in networkmanager - perhaps you can shed 
> some light on the reason why this happens.
> 
> When I resume from hibernation with only a wired via-rhine based 
> ethernet card plugged in, I get no IP address from dhcp. When I 
> "deactivate network" and manually do "sudo dhclient eth0", it works 
> immediately. Deactivating/reactivating has no effect, neither has 
> killing and restarting all nm processes.

Apparently a dhcdbd bug, or some interaction between dhcdbd and
hibernate/suspend, possibly a race condition.  I'd bet that NM has told
dhcdbd to down the interface, and dhcdbd tried to release its acquired
address.  The machine goes to sleep during that operation, and when it
wakes up dhcdbd still thinks it's releasing the address, and doesn't let
any other operation happen.

Please file a bug on bugzilla.redhat.com, targetted against the dhcdbd
component.

Arguably NM could _try_ to handle this, but there's not much of a point
(and it's quite wrong) to do "sleep(5); retry" or something like that,
especially if there's no guarantee that dhcdbd will resurrect itself.

We'd like to get rid of dhcdbd completely in the near future and drive
the DHCP client ourselves inside NetworkManager until a better solution
comes along.  dhcdbd just isn't working out for us.  Ideally there would
be a system-wide dhcp daemon that would handle _all_ interfaces, rather
than a 'dhclient-per-interface' setup.  And that daemon would speak
dbus, like dhcdbd does now.

Dan

> A report on launchpad:
> https://bugs.launchpad.net/ubuntu/+source/network-manager/+bug/102716
> 
> There's also a similar bug in openSuSE:
> https://bugzilla.novell.com/show_bug.cgi?id=254412
> 
> Here's a syslog excerpt. As you can see, running dhclient manually works 
> fine.
> 
> Apr 18 15:11:29 psyche NetworkManager: <information>^IGoing to sleep.
> Apr 18 15:11:29 psyche NetworkManager: <information>^IActivation (eth0): 
> cancelling...
> Apr 18 15:11:29 psyche NetworkManager: <information>^IActivation (eth0) 
> cancellation handler scheduled...
> Apr 18 15:11:29 psyche NetworkManager: <information>^IActivation (eth0): 
> waiting for device to cancel activation.
> Apr 18 15:11:30 psyche NetworkManager: <information>^IActivation (eth0) 
> Beginning DHCP transaction.
> Apr 18 15:11:30 psyche NetworkManager: <information>^ICouldn't send DHCP 
> 'up' message because: name 'com.redhat.dhcp.OperationInProgress', 
> message 'interface eth0 is being released. Please try again later.'.
> Apr 18 15:11:30 psyche NetworkManager: <information>^IActivation (eth0) 
> failure scheduled...
> Apr 18 15:11:30 psyche NetworkManager: <information>^IActivation (eth0) 
> Stage 3 of 5 (IP Configure Start) complete.
> Apr 18 15:11:30 psyche NetworkManager: <information>^IActivation (eth0) 
> cancellation handled.
> Apr 18 15:11:30 psyche NetworkManager: <information>^IActivation (eth0): 
> cancelled.
> Apr 18 15:11:30 psyche dhclient: receive_packet failed on eth0: Network 
> is down
> Apr 18 15:11:30 psyche kernel: [  221.605486] bridge-eth0: disabling the 
> bridge
> Apr 18 15:11:30 psyche NetworkManager: <information>^IActivation (eth0) 
> failed.
> Apr 18 15:11:30 psyche NetworkManager: <information>^IDeactivating 
> device eth0.
> Apr 18 15:11:30 psyche kernel: [  221.617417] bridge-eth0: down
> Apr 18 15:11:38 psyche dhclient: There is already a pid file 
> /var/run/dhclient.pid with pid 5564
> Apr 18 15:11:38 psyche dhclient: removed stale PID file
> Apr 18 15:11:38 psyche dhclient: Internet Systems Consortium DHCP Client 
> V3.0.4
> Apr 18 15:11:38 psyche dhclient: Copyright 2004-2006 Internet Systems 
> Consortium.
> Apr 18 15:11:38 psyche dhclient: All rights reserved.
> Apr 18 15:11:38 psyche dhclient: For info, please visit 
> http://www.isc.org/sw/dhcp/
> Apr 18 15:11:38 psyche dhclient:
> Apr 18 15:11:38 psyche kernel: [  229.404503] eth0: link up, 100Mbps, 
> full-duplex, lpa 0x45E1
> Apr 18 15:11:38 psyche kernel: [  229.406150] bridge-eth0: enabling the 
> bridge
> Apr 18 15:11:38 psyche kernel: [  229.406514] bridge-eth0: up
> Apr 18 15:11:38 psyche NetworkManager: <information>^IWill activate 
> wired connection 'eth0' because it now has a link.
> Apr 18 15:11:39 psyche dhclient: Listening on LPF/eth0/00:0b:6a:6e:c5:0c
> Apr 18 15:11:39 psyche dhclient: Sending on   LPF/eth0/00:0b:6a:6e:c5:0c
> Apr 18 15:11:39 psyche dhclient: Sending on   Socket/fallback
> Apr 18 15:11:40 psyche dhclient: DHCPREQUEST on eth0 to 255.255.255.255 
> port 67
> Apr 18 15:11:40 psyche dhclient: DHCPACK from 192.168.2.1
> Apr 18 15:11:40 psyche dhclient: bound to 192.168.2.102 -- renewal in 
> 128225450 seconds.
> 
> Thanks
> --
> Paulus Esterhazy
> 
> _______________________________________________
> NetworkManager-list mailing list
> NetworkManager-list gnome org
> http://mail.gnome.org/mailman/listinfo/networkmanager-list