DBUS communication problem? - Solution

[Barney Livingston <barney barnoid org uk>]

I posted here before regarding the problem I was having with NetworkManager 
communicating with dhclient over DBUS (see below). After much frustration 
I've managed to track down the cause.

It turns out that the message from NetworkManager to dhcdbd wasn't getting 
through because my network device names contained dashes (-). I have them 
renamed using ifrename to avoid confusion. The "Couldn't allocate the dbus 
message" warning in the log was coming from the DBUS library, not 
NetworkManager. Removing the dashes has fixed the problem.

Hopefully this might be of use in case anyone else ever names their network 
devices like so.

Barney


Previously I wrote:
NetworkManager on my Debian etch/unstable laptop seems to have trouble 
communicating with dhclient over DBUS. It gets most of the way with 
configuring the wired interface but then gives up when it comes to running 
dhclient such that it never runs (see attached syslog extract).

My user is in the netdev group and dhclient-script seems to be including the 
required dbus code from /etc/dhcp3/dhclient-exit-hooks.d/dhcdbd. Everything 
works manually.

Some package versions:
dbus  1.0.2-1
libdbus-1-3  1.0.2-1
dhcp3-client  3.0.4-13
dhcdbd  2.0-2
network-manager  0.6.4-6
network-manager-kde  1:0.1-4

Kernel 2.6.17.6-suspend2

Hardware: Thinkpad T60, IPW3945 wireless, E1000 wired

Thanks,

Barney

Feb  8 12:33:40 jarvis NetworkManager: <information>^IWill activate 
connection 'eth-wired'.
Feb  8 12:33:40 jarvis NetworkManager: <information>^IDevice eth-wired 
activation scheduled...
Feb  8 12:33:40 jarvis NetworkManager: <information>^IActivation (eth-wired) 
started...
Feb  8 12:33:40 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 1 of 5 (Device Prepare) scheduled...
Feb  8 12:33:40 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 1 of 5 (Device Prepare) started...
Feb  8 12:33:40 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 2 of 5 (Device Configure) scheduled...
Feb  8 12:33:40 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 1 of 5 (Device Prepare) complete.
Feb  8 12:33:40 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 2 of 5 (Device Configure) starting...
Feb  8 12:33:40 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 2 of 5 (Device Configure) successful.
Feb  8 12:33:40 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 3 of 5 (IP Configure Start) scheduled.
Feb  8 12:33:40 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 2 of 5 (Device Configure) complete.
Feb  8 12:33:40 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 3 of 5 (IP Configure Start) started...
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Beginning DHCP transaction.
Feb  8 12:33:41 jarvis NetworkManager: <WARNING>^I 
nm_dhcp_manager_begin_transaction (): nm_dhcp_manager_begin_transaction(): 
Couldn't allocate the dbus message
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
failure scheduled...
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 3 of 5 (IP Configure Start) complete.
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
failed.
Feb  8 12:33:41 jarvis NetworkManager: <information>^IDeactivating device 
eth-wired.
Feb  8 12:33:41 jarvis NetworkManager: <information>^ISWITCH: no current 
connection, found better connection 'eth-wired'.
Feb  8 12:33:41 jarvis NetworkManager: <WARNING>^I 
nm_dhcp_manager_get_state_for_device (): 
nm_dhcp_manager_get_state_for_device(): Couldn't allocate the dbus message
Feb  8 12:33:41 jarvis NetworkManager: <information>^IWill activate 
connection 'eth-wired'.
Feb  8 12:33:41 jarvis NetworkManager: <information>^IDevice eth-wired 
activation scheduled...
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
started...
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 1 of 5 (Device Prepare) scheduled...
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 1 of 5 (Device Prepare) started...
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 2 of 5 (Device Configure) scheduled...
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 1 of 5 (Device Prepare) complete.
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 2 of 5 (Device Configure) starting...
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 2 of 5 (Device Configure) successful.
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 3 of 5 (IP Configure Start) scheduled.
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 2 of 5 (Device Configure) complete.
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 3 of 5 (IP Configure Start) started...
Feb  8 12:33:41 jarvis NetworkManager: <information>^IGoing to sleep.
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired): 
cancelling...
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired) 
cancellation handler scheduled...
Feb  8 12:33:41 jarvis NetworkManager: <information>^IActivation (eth-wired): 
waiting for device to cancel activation.
Feb  8 12:33:42 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Beginning DHCP transaction.
Feb  8 12:33:42 jarvis NetworkManager: <WARNING>^I 
nm_dhcp_manager_begin_transaction (): nm_dhcp_manager_begin_transaction(): 
Couldn't allocate the dbus message
Feb  8 12:33:42 jarvis NetworkManager: <information>^IActivation (eth-wired) 
failure scheduled...
Feb  8 12:33:42 jarvis NetworkManager: <information>^IActivation (eth-wired) 
Stage 3 of 5 (IP Configure Start) complete.
Feb  8 12:33:42 jarvis NetworkManager: <information>^IActivation (eth-wired) 
cancellation handled.
Feb  8 12:33:42 jarvis NetworkManager: <information>^IActivation (eth-wired): 
cancelled.
Feb  8 12:33:42 jarvis NetworkManager: <information>^IActivation (eth-wired) 
failed.
Feb  8 12:33:42 jarvis NetworkManager: <information>^IDeactivating device 
eth-wired.