NetworkManager

[Gutsy] NetworkManager fails at startup: waitpid () from /lib/libpthread.so.0

Bug #139966 reported by TJ on 2007-09-16

This bug report is a duplicate of: Bug #141233: MASTER network-manager crashes when wpasupplicant ctrl socket is not available. Edit Remove

Affects		Status	Importance	Assigned to	Milestone
	NetworkManager	Fix Released	Unknown	gnome-bugs #477650
	network-manager (Ubuntu)	Triaged	Medium	Alexander Sack

Bug Description

Binary package hint: network-manager

Gutsy 64-bit Tribe-5 + updates to 16th September, 2007. Recent updates (from /root/.synaptic/log/)

2007-09-07.014923.log:26:network-manager (0.6.5-0ubuntu9) to 0.6.5-0ubuntu10
2007-09-11.163912.log:40:network-manager (0.6.5-0ubuntu10) to 0.6.5-0ubuntu11

NetworkManager: 0x00002b3af925bc7f in waitpid () from /lib/libpthread.so.0

On startup NetworkManager consistently fails, leaving NetworkManagerDispatcher running. Once logged into Gnome there is no network.

The issue appears to be related to NM connecting to the WPA 802.11g WAP. Starting NetworkManager manually doesn't have the problem, so possibly a timing issue with wpa_supplicant?

$ sudu su
$ /etc/dbus-1/event.d/26NetworkManagerDispatcher stop
$ /etc/dbus-1/event.d/25NetworkManager start
$ /etc/dbus-1/event.d/26NetworkManagerDispatcher start

These are the 'failure' and 'good' log fragments:

----- daemon.log (from PC start-up sequence) ------
NetworkManager: <info> Updating allowed wireless network lists.
NetworkManager: <info> SWITCH: no current connection, found better connection 'eth1'.
NetworkManager: <info> Will activate connection 'eth1/tjworld.net'.
NetworkManager: <info> Device eth1 activation scheduled...
NetworkManager: <info> Activation (eth1) started...
NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) starting...
NetworkManager: <info> Activation (eth1/wireless): access point 'tjworld.net' is encrypted, but NO valid key exists. New key needed.
NetworkManager: <info> Activation (eth1) New wireless user key requested for network 'tjworld.net'.
NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info> Activation (eth1) New wireless user key for network 'tjworld.net' received.
NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) starting...
NetworkManager: <info> Activation (eth1/wireless): access point 'tjworld.net' is encrypted, and a key exists. No new key needed.
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (0/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (1/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (2/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (3/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (4/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (5/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (6/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (7/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (8/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (9/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (10/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (11/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (12/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (13/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (14/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (15/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (16/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (17/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (18/10).
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (19/10).
NetworkManager: <info> Error opening supplicant global control interface.
NetworkManager: <WARN> real_act_stage2_config(): Activation (eth1/wireless): couldn't connect to the supplicant.
NetworkManager: <info> Activation (eth1) failure scheduled...
NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info> Activation (eth1) failed for access point (tjworld.net)
NetworkManager: <info> Activation (eth1) failed.
NetworkManager: <info> Deactivating device eth1.
NetworkManager: <WARN> nm_signal_handler(): Caught signal 11. Generating backtrace...
NetworkManager: ******************* START **********************************
NetworkManager: (no debugging symbols found)
NetworkManager: Using host libthread_db library "/lib/libthread_db.so.1".
NetworkManager: (no debugging symbols found)
Sep 16 17:57:33 hephaestion last message repeated 13 times
NetworkManager: [Thread debugging using libthread_db enabled]
NetworkManager: [New Thread 47532296399184 (LWP 5331)]
NetworkManager: [New Thread 1090525520 (LWP 6498)]
NetworkManager: [New Thread 1082132816 (LWP 5468)]
NetworkManager: (no debugging symbols found)
Sep 16 17:57:34 hephaestion last message repeated 2 times
NetworkManager: 0x00002b3af925bc7f in waitpid () from /lib/libpthread.so.0
NetworkManager: ******************* END **********************************

----- daemon.log (manually starting NetworkManager after Gnome login) -----
NetworkManager: <info> Activation (eth1) New wireless user key for network 'tjworld.net' received.
NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info> Activation (eth1) Stage 2 of 5 (Device Configure) starting...
NetworkManager: <info> Activation (eth1/wireless): access point 'tjworld.net' is encrypted, and a key exists. No new key needed.
NetworkManager: <info> supplicant_interface_init() - connect to global ctrl socket (0/10).
NetworkManager: <info> SUP: sending command 'INTERFACE_ADD eth1^I^Iwext^I/var/run/wpa_supplicant3^I'
NetworkManager: <info> SUP: response was 'OK'
NetworkManager: <info> supplicant_init() - connect to device ctrl socket (2/10).

See original description

TJ (tj) on 2007-09-16

description:

updated

TJ (tj) on 2007-09-16

description:

updated

Revision history for this message

TJ (tj) wrote on 2007-09-16:

On a hunch I uninstalled VMware-server-1.0.3-44356 because I noticed it was reporting a bridge attached to eth1, which is the WiFi interface.

After the first restart NetworkManager doesn't show this failure. I'll continue to check on this after each restart and update the bug status as appropriate.

Revision history for this message

TJ (tj) wrote on 2007-09-17:

VMWare appears not to be the cause.

Starting the PC this morning from cold NetworkManager has consistently failed to connect to WiFi - in fact I have had to connect a wired connection to get any network connectivity. The workaround described above of restarting NetworkManager(Dispatcher) hasn't solved it. Tried restarting wpasupplicant too but that didn't help.

I noticed from the log files that avahi would get report the correct WiFi DHCP lease being assigned and then immediately drop it because NetworkManager had failed.

NetworkManager: ******************* END **********************************
dhclient: DHCPDISCOVER on eth1 to 255.255.255.255 port 67 interval 2
dhclient: No DHCPOFFERS received.
dhclient: Trying recorded lease 10.254.251.52
avahi-autoipd(eth1)[6213]: A routable address has been configured.
avahi-autoipd(eth1)[6213]: Callout UNBIND, address 169.254.3.217 on interface eth1
avahi-autoipd(eth1)[6213]: No longer a routable address configured, restarting probe process.
avahi-daemon[5696]: Joining mDNS multicast group on interface eth1.IPv4 with address 10.254.251.52.
avahi-autoipd(eth1)[6213]: A routable address has been configured.
avahi-daemon[5696]: New relevant interface eth1.IPv4 for mDNS.
avahi-daemon[5696]: Registering new address record for 10.254.251.52 on eth1.IPv4.
avahi-daemon[5696]: Withdrawing address record for 10.254.251.52 on eth1.
avahi-daemon[5696]: Leaving mDNS multicast group on interface eth1.IPv4 with address 10.254.251.52.
avahi-autoipd(eth1)[6214]: client: RTNETLINK answers: Cannot assign requested address
avahi-daemon[5696]: Interface eth1.IPv4 no longer relevant for mDNS.
avahi-daemon[5696]: Joining mDNS multicast group on interface eth1.IPv4 with address 10.254.251.52.
avahi-autoipd(eth1)[6214]: Script execution failed with return value 2
avahi-daemon[5696]: New relevant interface eth1.IPv4 for mDNS.
avahi-daemon[5696]: Registering new address record for 10.254.251.52 on eth1.IPv4.
avahi-autoipd(eth1)[6213]: No longer a routable address configured, restarting probe process.
avahi-daemon[5696]: Withdrawing address record for 10.254.251.52 on eth1.
avahi-daemon[5696]: Leaving mDNS multicast group on interface eth1.IPv4 with address 10.254.251.52.
avahi-daemon[5696]: Interface eth1.IPv4 no longer relevant for mDNS.
dhclient: No working leases in persistent database - sleeping.

VMWare appears not to be the cause.

I noticed from the log files that avahi would get report the correct WiFi DHCP lease being assigned and then immediately drop it because NetworkManager had failed.

NetworkManager: ******************* END **********************************
 dhclient: DHCPDISCOVER on eth1 to 255.255.255.255 port 67 interval 2
 dhclient: No DHCPOFFERS received.
 dhclient: Trying recorded lease 10.254.251.52
 avahi-autoipd(eth1)[6213]: A routable address has been configured.
 avahi-autoipd(eth1)[6213]: Callout UNBIND, address 169.254.3.217 on interface eth1
 avahi-autoipd(eth1)[6213]: No longer a routable address configured, restarting probe process.
 avahi-daemon[5696]: Joining mDNS multicast group on interface eth1.IPv4 with address 10.254.251.52.
 avahi-autoipd(eth1)[6213]: A routable address has been configured.
 avahi-daemon[5696]: New relevant interface eth1.IPv4 for mDNS.
 avahi-daemon[5696]: Registering new address record for 10.254.251.52 on eth1.IPv4.
 avahi-daemon[5696]: Withdrawing address record for 10.254.251.52 on eth1.
 avahi-daemon[5696]: Leaving mDNS multicast group on interface eth1.IPv4 with address 10.254.251.52.
 avahi-autoipd(eth1)[6214]: client: RTNETLINK answers: Cannot assign requested address
 avahi-daemon[5696]: Interface eth1.IPv4 no longer relevant for mDNS.
 avahi-daemon[5696]: Joining mDNS multicast group on interface eth1.IPv4 with address 10.254.251.52.
 avahi-autoipd(eth1)[6214]: Script execution failed with return value 2
 avahi-daemon[5696]: New relevant interface eth1.IPv4 for mDNS.
 avahi-daemon[5696]: Registering new address record for 10.254.251.52 on eth1.IPv4.
 avahi-autoipd(eth1)[6213]: No longer a routable address configured, restarting probe process.
 avahi-daemon[5696]: Withdrawing address record for 10.254.251.52 on eth1.
 avahi-daemon[5696]: Leaving mDNS multicast group on interface eth1.IPv4 with address 10.254.251.52.
 avahi-daemon[5696]: Interface eth1.IPv4 no longer relevant for mDNS.
 dhclient: No working leases in persistent database - sleeping.

Revision history for this message

Brian Murray (brian-murray) wrote on 2007-09-18:

What wireless driver are you using? I am not having any issues connecting to a WPA WAP using network-manager and ipw3945.

Changed in network-manager:
status:	New → Incomplete
importance:	Undecided → Medium

Revision history for this message

Jan Mynarik (jan-mynarik) wrote on 2007-09-19:

Download full text (7.1 KiB)

Same problem here with ipw2200 driver:

Same problem here with ipw2200 driver:

Sep 18 20:14:32 localhost NetworkManager: <info>  Updating allowed wireless network lists. 
Sep 18 20:14:32 localhost NetworkManager: <info>  SWITCH: no current connection, found better connection 'eth1'. 
Sep 18 20:14:32 localhost NetworkManager: <info>  Will activate connection 'eth1/pogonet'. 
Sep 18 20:14:32 localhost NetworkManager: <info>  Device eth1 activation scheduled... 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1) started... 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1) Stage 1 of 5 (Device Prepare) scheduled... 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1) Stage 1 of 5 (Device Prepare) started... 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1) Stage 2 of 5 (Device Configure) scheduled... 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1) Stage 1 of 5 (Device Prepare) complete. 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1) Stage 2 of 5 (Device Configure) starting... 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1/wireless): access point 'pogonet' is encrypted, but NO valid key exists.  New key needed. 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1) New wireless user key requested for network 'pogonet'. 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1) Stage 2 of 5 (Device Configure) complete. 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1) New wireless user key for network 'pogonet' received. 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1) Stage 1 of 5 (Device Prepare) scheduled... 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1) Stage 1 of 5 (Device Prepare) started... 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1) Stage 2 of 5 (Device Configure) scheduled... 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1) Stage 1 of 5 (Device Prepare) complete. 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1) Stage 2 of 5 (Device Configure) starting... 
Sep 18 20:14:32 localhost NetworkManager: <info>  Activation (eth1/wireless): access point 'pogonet' is encrypted, and a key exists.  No new key needed. 
Sep 18 20:14:33 localhost NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (0/10). 
Sep 18 20:14:33 localhost NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (1/10). 
Sep 18 20:14:33 localhost NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (2/10). 
Sep 18 20:14:33 localhost NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (3/10). 
Sep 18 20:14:34 localhost NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (4/10). 
Sep 18 20:14:34 localhost NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (5/10). 
Sep 18 20:14:34 localhost NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (6/10). 
Sep 18 20:14:34 localhost NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (7/10). 
Sep 18 20:14:34 localhost NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (8/10). 
Sep 18 20:14:34 localhost NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (9/10). 
Sep 18 20:14:34 localhost NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (10/10). 
Sep 18 20:14:34 localhost NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (11/10). 
Sep 18 20:14:34 localhost NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (12/10). 
Sep 18 20:14:34 localhost NetworkManager: <info>  supplicant_interface_init() - connect to global ctrl socket (13/10). 
Sep 18 20:14:35 localhost NetworkManager: <info>  SUP: sending command 'INTERFACE_ADD eth1^I^Iwext^I/var/run/wpa_supplicant3^I' 
Sep 18 20:14:40 localhost NetworkManager: <info>  SUP: response was 'OK' 
Sep 18 20:14:40 localhost NetworkManager: <info>  Error opening control interface to supplicant. 
Sep 18 20:14:40 localhost NetworkManager: <WARN>  real_act_stage2_config(): Activation (eth1/wireless): couldn't connect to the supplicant. 
Sep 18 20:14:40 localhost NetworkManager: <info>  Activation (eth1) failure scheduled... 
Sep 18 20:14:40 localhost NetworkManager: <info>  Activation (eth1) Stage 2 of 5 (Device Configure) complete. 
Sep 18 20:14:40 localhost NetworkManager: <info>  Activation (eth1) failed for access point (pogonet) 
Sep 18 20:14:40 localhost NetworkManager: <info>  Activation (eth1) failed. 
Sep 18 20:14:40 localhost NetworkManager: <info>  Deactivating device eth1. 
Sep 18 20:14:40 localhost NetworkManager: <WARN>  nm_signal_handler(): Caught signal 11.  Generating backtrace... 
Sep 18 20:14:40 localhost NetworkManager: ******************* START **********************************
Sep 18 20:14:47 localhost NetworkManager: (no debugging symbols found)
Sep 18 20:14:47 localhost NetworkManager: Using host libthread_db library "/lib/tls/i686/cmov/libthread_db.so.1".
Sep 18 20:14:47 localhost NetworkManager: (no debugging symbols found)
Sep 18 20:14:51 localhost last message repeated 15 times
Sep 18 20:14:51 localhost NetworkManager: [Thread debugging using libthread_db enabled]
Sep 18 20:14:51 localhost NetworkManager: [New Thread -1212220992 (LWP 4931)]
Sep 18 20:14:51 localhost NetworkManager: [New Thread -1229010032 (LWP 6387)]
Sep 18 20:14:51 localhost NetworkManager: [New Thread -1220617328 (LWP 5067)]
Sep 18 20:14:51 localhost NetworkManager: [New Thread -1212224624 (LWP 5060)]
Sep 18 20:14:51 localhost NetworkManager: (no debugging symbols found)
Sep 18 20:14:52 localhost last message repeated 7 times
Sep 18 20:14:52 localhost NetworkManager: 0xffffe410 in __kernel_vsyscall ()
Sep 18 20:14:52 localhost NetworkManager: ******************* END **********************************
Sep 18 20:16:54 localhost NetworkManager: <info>  starting... 
Sep 18 20:16:54 localhost NetworkManager: <info>  New VPN service 'openvpn' (org.freedesktop.NetworkManager.openvpn). 
Sep 18 20:16:54 localhost NetworkManager: <info>  New VPN service 'ppp' (org.freedesktop.NetworkManager.ppp_starter). 
Sep 18 20:16:54 localhost NetworkManager: <info>  New VPN service 'vpnc' (org.freedesktop.NetworkManager.vpnc). 
Sep 18 20:16:54 localhost NetworkManager: <WARN>  load_services(): Error loading VPN service file '/etc/NetworkManager/VPN/nm-pptp-service.name': program does not exist, or is not executable. 
Sep 18 20:16:54 localhost NetworkManager: <info>  Found radio killswitch /org/freedesktop/Hal/devices/dell_wlan_switch 
Sep 18 20:16:54 localhost NetworkManager: <info>  eth1: Device is fully-supported using driver 'ipw2200'. 
Sep 18 20:16:54 localhost NetworkManager: <info>  nm_device_init(): waiting for device's worker thread to start 
Sep 18 20:16:54 localhost NetworkManager: <info>  nm_device_init(): device's worker thread started, continuing. 
Sep 18 20:16:54 localhost NetworkManager: <info>  Now managing wireless (802.11) device 'eth1'.

Changed in network-manager:
status:	Incomplete → Confirmed

Revision history for this message

unggnu (unggnu) wrote on 2007-09-19:

syslog Edit (32.0 KiB, text/plain)

I can confirm this with ipw2200. Sometimes after boot nm-applet is running but isn't shown in tray and Wlan connection isn't established. After system reboot it works normally fine again.
I have restarted Network-Manager with "sudo /etc/dbus-1/event.d/25NetworkManager restart && sudo /etc/dbus-1/event.d/26NetworkManagerDispatcher restart" which lets nm-applet appear in tray for some seconds but then it was vanished again.
According to syslog there was a problem with wpa_supplicant and according to ps it was still running so I killed it. After another Network-Manager restart nm-applet was shown again in tray and connection was established fine. So at least for me it is no nm-applet problem but a Network-Manager and it seems to be for at least some others too.
So the workaround is to run this command "sudo killall wpa_supplicant && sudo /etc/dbus-1/event.d/25Networager restart" but since it happens on nearly every second Gutsy start it is no solution.

Revision history for this message

unggnu (unggnu) wrote on 2007-09-19:

The correct workaround command is: "sudo killall wpa_supplicant && sudo /etc/dbus-1/event.d/25NetworkManager restart".

Brian Murray (brian-murray) on 2007-09-19

Changed in network-manager:
status:	Confirmed → Triaged

Brian Murray (brian-murray) on 2007-09-19

Changed in network-manager:
assignee:	nobody → asac

Revision history for this message

TJ (tj) wrote on 2007-09-19:

I haven't seen this again since the updates of 17/18th September.

The chipset is ipw3945.

Revision history for this message

Gavin Graham (gavingraham) wrote on 2007-09-20:

As of todays updates, I have not been able to re- create the fault and that is without about 6 reboots now.

Bug Watch Updater (bug-watch-updater) on 2007-09-20

Changed in network-manager:
status:	Unknown → New

Revision history for this message

TJ (tj) wrote on 2007-09-20:

Hah! spoke to soon... after the early-morning updates of 20th September 2007, starting the PC from cold the problem re-appears. Using wired for now until I can find a reliable workaround.

Gutsy 64-bit, ipw3945, WPA2, Sony Vaio VGN-FE41Z

Revision history for this message

unggnu (unggnu) wrote on 2007-09-20:

#10

@TJ
Does my workaround not work for you? Maybe you could insert this in rc.local with a sleep and a check for running NetworkManager daemon.

Revision history for this message

TJ (tj) wrote on 2007-09-20:

#11

I appear to have fixed it by building without the patch:

41t_nm_device_wireless_index_ctrl_sockets_by_run_count.patch

I'll have to do a few more cold starts to be sure.

Revision history for this message

Bernard S. Jansen (bernard-jansen) wrote on 2008-01-15:

#12

This bug also appears to affect my Intel 4965 AGN, using modules iwl4965 and iwlwifi_mac80211. Extract from /var/log/syslog during boot-up:

Jan 15 21:16:32 blue NetworkManager: <info> Updating allowed wireless network lists.
Jan 15 21:16:32 blue NetworkManager: <info> SWITCH: no current connection, found better connection 'wlan0'.
Jan 15 21:16:32 blue dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/wlan0 for sub-path wlan0.dbus.get.reason
Jan 15 21:16:32 blue NetworkManager: <info> Will activate connection 'wlan0/nextlink'.
Jan 15 21:16:32 blue NetworkManager: <info> Device wlan0 activation scheduled...
Jan 15 21:16:32 blue NetworkManager: <info> Activation (wlan0) started...
Jan 15 21:16:32 blue NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Jan 15 21:16:32 blue NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Jan 15 21:16:32 blue NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Jan 15 21:16:32 blue NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Jan 15 21:16:32 blue NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Jan 15 21:16:32 blue NetworkManager: <info> Activation (wlan0/wireless): access point 'nextlink' is encrypted, but NO valid key exists. New key needed.
Jan 15 21:16:32 blue NetworkManager: <info> Activation (wlan0) New wireless user key requested for network 'nextlink'.
Jan 15 21:16:32 blue NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Jan 15 21:16:32 blue NetworkManager: <WARN> nm_dbus_get_user_key_for_network_cb(): nm_dbus_get_user_key_for_network_cb(): dbus returned an error. (org.freedesktop.NetworkManagerInfo.GetKeyError) org.freedesktop.NetworkManagerInfo.GetKeyError
Jan 15 21:16:32 blue NetworkManager: <info> Activation (wlan0) failure scheduled...

Manual connection works fine (using KNetworkManager in Kubuntu).

unggnu: Could you please provide some more detail on how to implement the workaround you suggested? Perhaps suggest appropriate syntax for rc.local for the "sleep and a check for running NetWorkManager daemon"?

This bug also appears to affect my Intel 4965 AGN, using modules iwl4965 and iwlwifi_mac80211.  Extract from /var/log/syslog during boot-up:

Jan 15 21:16:32 blue NetworkManager: <info>  Updating allowed wireless network lists. 
Jan 15 21:16:32 blue NetworkManager: <info>  SWITCH: no current connection, found better connection 'wlan0'. 
Jan 15 21:16:32 blue dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/wlan0 for sub-path wlan0.dbus.get.reason
Jan 15 21:16:32 blue NetworkManager: <info>  Will activate connection 'wlan0/nextlink'. 
Jan 15 21:16:32 blue NetworkManager: <info>  Device wlan0 activation scheduled... 
Jan 15 21:16:32 blue NetworkManager: <info>  Activation (wlan0) started... 
Jan 15 21:16:32 blue NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... 
Jan 15 21:16:32 blue NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started... 
Jan 15 21:16:32 blue NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... 
Jan 15 21:16:32 blue NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. 
Jan 15 21:16:32 blue NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting... 
Jan 15 21:16:32 blue NetworkManager: <info>  Activation (wlan0/wireless): access point 'nextlink' is encrypted, but NO valid key exists.  New key needed. 
Jan 15 21:16:32 blue NetworkManager: <info>  Activation (wlan0) New wireless user key requested for network 'nextlink'. 
Jan 15 21:16:32 blue NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete. 
Jan 15 21:16:32 blue NetworkManager: <WARN>  nm_dbus_get_user_key_for_network_cb(): nm_dbus_get_user_key_for_network_cb(): dbus returned an error.   (org.freedesktop.NetworkManagerInfo.GetKeyError) org.freedesktop.NetworkManagerInfo.GetKeyError  
Jan 15 21:16:32 blue NetworkManager: <info>  Activation (wlan0) failure scheduled...

Manual connection works fine (using KNetworkManager in Kubuntu).

unggnu: Could you please provide some more detail on how to implement the workaround you suggested?  Perhaps suggest appropriate syntax for rc.local for the "sleep and a check for running NetWorkManager daemon"?

Revision history for this message

Bernard S. Jansen (bernard-jansen) wrote on 2008-01-17:

#13

Please ignore my previous comment. (Though I think that's already happened... :-) I was barking up the wrong tree entirely.

Bug Watch Updater (bug-watch-updater) on 2008-02-15