Bug 597572

Summary: NetworkManager asleep: Network fails to start
Product: [openSUSE] openSUSE 11.3 Reporter: Klaus Kämpf <kkaempf>
Component: NetworkAssignee: E-mail List <gnome-bugs>
Status: RESOLVED DUPLICATE QA Contact: E-mail List <qa-bugs>
Severity: Critical    
Priority: P5 - None CC: adrian.schroeter, alexvkaam, carlosflange, Eduard.Avetisyan, f.alabas, markus.zimmermann, s.assmann, wstephenson
Version: Final   
Target Milestone: Milestone 6   
Hardware: i586   
OS: Other   
Whiteboard:
Found By: Development Services Priority:
Business Priority: Blocker: Yes
Marketing QA Status: --- IT Deployment: ---
Attachments: /etc/sysconfig/network
/var/log/NetworkManager
/var/log/messages
networkmanager okay at bootup
networkmanager fail at boot
Hardware Summary

Description Klaus Kämpf 2010-04-17 10:53:12 UTC
I did a "zypper dup" from 11.2 to 11.3M5 on my laptop. After fresh reboot, the network completely fails to start. "ifconfig" only shows 'lo', while 'rcnetwork {start,stop}' shows all network interfaces.
Comment 1 Klaus Kämpf 2010-04-17 10:56:52 UTC
Created attachment 355138 [details]
/etc/sysconfig/network
Comment 2 Klaus Kämpf 2010-04-17 10:57:24 UTC
Created attachment 355139 [details]
/var/log/NetworkManager
Comment 3 Klaus Kämpf 2010-04-17 11:08:28 UTC
Created attachment 355141 [details]
/var/log/messages

Tried restarting the network and reloading the eth0 driver (e1000e) - no success :-/

NetworkManager is reporting "carrier is OFF" while the ethernet plug shows "green" ?!
Comment 4 Klaus Kämpf 2010-04-17 11:11:36 UTC
This is a NetworkManager bug, not a driver bug.

Setting eth0 manually (via 'ifconfig') + editing resolv.conf + setting the default route makes network working again.
Comment 5 Will Stephenson 2010-05-04 14:51:05 UTC
Is NetworkManager asleep?

Do eg "qdbus --system org.freedesktop.NetworkManager /org/freedesktop/NetworkManager state"

If it is asleep, as below, call the "wake" command on the same interface over dbus.

NM_STATE_UNKNOWN = 0
    The NetworkManager daemon is in an unknown state. 
NM_STATE_ASLEEP = 1
    The NetworkManager daemon is asleep and all interfaces managed by it are inactive. 
NM_STATE_CONNECTING = 2
    The NetworkManager daemon is connecting a device. FIXME: What does this mean when one device is active and another is connecting? 
NM_STATE_CONNECTED = 3
    The NetworkManager daemon is connected. 
NM_STATE_DISCONNECTED = 4
    The NetworkManager daemon is disconnected.
Comment 6 Bin Li 2010-05-20 04:56:35 UTC
Klaus,

 Would you mind try to Comment 5?
Comment 7 Klaus Kämpf 2010-05-20 07:36:07 UTC
Uhm, sorry, I updated to M6 meanwhile (M5 was just too buggy :-}) and networking is running fine now.
Comment 8 Will Stephenson 2010-06-16 18:31:27 UTC
I am sorry to disagree; this is with RC1 today:  
NM started in NM_STATE_ASLEEP again.  It wakes on wake() as in #5.  Bin Li, any ideas?

Jun 16 20:17:26 gorse NetworkManager: <info>  starting...
Jun 16 20:17:26 gorse NetworkManager: <info>  Trying to start the modem-manager...
Jun 16 20:17:26 gorse NetworkManager: Loaded plugin ifcfg-suse: (C) 2008 Novell, Inc.  To report bugs please use the NetworkManager mailing list.
Jun 16 20:17:26 gorse NetworkManager: Loaded plugin keyfile: (c) 2007 - 2008 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
Jun 16 20:17:26 gorse NetworkManager: <info>  Found wlan radio killswitch rfkill2 (at /sys/devices/pci0000:00/0000:00:1c.1/0000:03:00.0/ieee80211/phy0/rfkill2) (driver <unknown>)
Jun 16 20:17:26 gorse NetworkManager: <info>  WiFi enabled by radio killswitch; enabled by state file
Jun 16 20:17:26 gorse NetworkManager: <info>  WWAN enabled by radio killswitch; enabled by state file
Jun 16 20:17:26 gorse NetworkManager: <info>  (eth0): carrier is OFF
Jun 16 20:17:26 gorse NetworkManager: <info>  (eth0): new Ethernet device (driver: 'e1000e')
Jun 16 20:17:26 gorse NetworkManager: <info>  (eth0): exported as /org/freedesktop/NetworkManager/Devices/0
Jun 16 20:17:26 gorse NetworkManager: <info>  (wlan0): driver supports SSID scans (scan_capa 0x01).
Jun 16 20:17:26 gorse NetworkManager: <info>  (wlan0): new 802.11 WiFi device (driver: 'iwl3945')
Jun 16 20:17:26 gorse NetworkManager: <info>  (wlan0): exported as /org/freedesktop/NetworkManager/Devices/1
Jun 16 20:17:26 gorse NetworkManager: <info>  modem-manager is now available
Jun 16 20:17:26 gorse NetworkManager: <WARN>  default_adapter_cb(): bluez error getting default adapter: The name org.bluez was not provided by any .service files
Jun 16 20:17:26 gorse NetworkManager: <info>  Trying to start the supplicant...
Jun 16 20:17:26 gorse NetworkManager: <info>  (wlan0): supplicant manager state:  down -> idle
Jun 16 20:17:27 gorse NetworkManager: <WARN>  device_creator(): /sys/devices/virtual/net/pan0: couldn't determine device driver; ignoring...
Comment 9 Will Stephenson 2010-06-16 18:57:23 UTC
Same system, earlier in the day, NM started normally.

Where's the race condition?

Jun 16 16:37:13 gorse NetworkManager: <info>  starting...
Jun 16 16:37:13 gorse NetworkManager: <info>  Trying to start the modem-manager...
Jun 16 16:37:13 gorse NetworkManager: Loaded plugin ifcfg-suse: (C) 2008 Novell, Inc.  To report bugs please use the NetworkManager mailing list.
Jun 16 16:37:13 gorse NetworkManager: Loaded plugin keyfile: (c) 2007 - 2008 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
Jun 16 16:37:13 gorse NetworkManager: <info>  Found wlan radio killswitch rfkill2 (at /sys/devices/pci0000:00/0000:00:1c.1/0000:03:00.0/ieee80211/phy0/rfkill2) (driver <unknown>)
Jun 16 16:37:13 gorse NetworkManager: <info>  WiFi enabled by radio killswitch; enabled by state file
Jun 16 16:37:13 gorse NetworkManager: <info>  WWAN enabled by radio killswitch; enabled by state file
Jun 16 16:37:13 gorse NetworkManager: <info>  (eth0): carrier is OFF
Jun 16 16:37:13 gorse NetworkManager: <info>  (eth0): new Ethernet device (driver: 'e1000e')
Jun 16 16:37:13 gorse NetworkManager: <info>  (eth0): exported as /org/freedesktop/NetworkManager/Devices/0
Jun 16 16:37:13 gorse NetworkManager: <info>  (eth0): now managed
Jun 16 16:37:13 gorse NetworkManager: <info>  (eth0): device state change: 1 -> 2 (reason 2)
Jun 16 16:37:13 gorse NetworkManager: <info>  (eth0): bringing up device.
Jun 16 16:37:13 gorse NetworkManager: <info>  (eth0): preparing device.
Jun 16 16:37:13 gorse NetworkManager: <info>  (eth0): deactivating device (reason: 2).
Jun 16 16:37:13 gorse NetworkManager: Added default wired connection 'Auto eth0' for /sys/devices/pci0000:00/0000:00:1c.0/0000:02:00.0/net/eth0
Jun 16 16:37:13 gorse NetworkManager: <info>  (wlan0): driver supports SSID scans (scan_capa 0x01).
Jun 16 16:37:13 gorse NetworkManager: <info>  (wlan0): new 802.11 WiFi device (driver: 'iwl3945')
Jun 16 16:37:13 gorse NetworkManager: <info>  (wlan0): exported as /org/freedesktop/NetworkManager/Devices/1
Jun 16 16:37:13 gorse NetworkManager: <info>  (wlan0): now managed
Jun 16 16:37:13 gorse NetworkManager: <info>  (wlan0): device state change: 1 -> 2 (reason 2)
Jun 16 16:37:13 gorse NetworkManager: <info>  (wlan0): bringing up device.
Jun 16 16:37:13 gorse NetworkManager: <info>  (wlan0): preparing device.
Jun 16 16:37:13 gorse NetworkManager: <info>  (wlan0): deactivating device (reason: 2).
Jun 16 16:37:13 gorse NetworkManager: supplicant_interface_acquire: assertion `mgr_state == NM_SUPPLICANT_MANAGER_STATE_IDLE' failed
Jun 16 16:37:13 gorse NetworkManager: <info>  modem-manager is now available
Jun 16 16:37:13 gorse NetworkManager: <WARN>  default_adapter_cb(): bluez error getting default adapter: The name org.bluez was not provided by any .service files
Jun 16 16:37:13 gorse NetworkManager: <info>  Trying to start the supplicant...
Jun 16 16:37:13 gorse NetworkManager: <info>  (wlan0): supplicant manager state:  down -> idle
Jun 16 16:37:13 gorse NetworkManager: <info>  (wlan0): device state change: 2 -> 3 (reason 0)
Jun 16 16:37:13 gorse NetworkManager: <info>  (wlan0): supplicant interface state:  starting -> ready
Jun 16 16:37:15 gorse NetworkManager: <info>  (eth0): carrier now ON (device state 2)
Jun 16 16:37:15 gorse NetworkManager: <info>  (eth0): device state change: 2 -> 3 (reason 40)
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) starting connection 'Auto eth0'
Jun 16 16:37:15 gorse NetworkManager: <info>  (eth0): device state change: 3 -> 4 (reason 0)
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) started...
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) complete.
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) starting...
Jun 16 16:37:15 gorse NetworkManager: <info>  (eth0): device state change: 4 -> 5 (reason 0)
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) successful.
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) complete.
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
Jun 16 16:37:15 gorse NetworkManager: <info>  (eth0): device state change: 5 -> 7 (reason 0)
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) Beginning DHCP transaction (timeout in 45 seconds)
Jun 16 16:37:15 gorse NetworkManager: <info>  dhclient started with pid 1849
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP6 Configure Get) scheduled...
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP6 Configure Get) started...
Jun 16 16:37:15 gorse NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP6 Configure Get) complete.
Jun 16 16:37:16 gorse NetworkManager: <info>  DHCP: device eth0 state changed (null) -> preinit
Jun 16 16:37:16 gorse NetworkManager: <WARN>  device_creator(): /sys/devices/virtual/net/pan0: couldn't determine device driver; ignoring...
Jun 16 16:37:25 gorse NetworkManager: <info>  DHCP: device eth0 state changed preinit -> bound
Jun 16 16:37:25 gorse NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP4 Configure Get) scheduled...
Jun 16 16:37:25 gorse NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP4 Configure Get) started...
Jun 16 16:37:25 gorse NetworkManager: <info>    address 10.10.4.45
Jun 16 16:37:25 gorse NetworkManager: <info>    prefix 16 (255.255.0.0)
Jun 16 16:37:25 gorse NetworkManager: <info>    gateway 10.10.0.8
Jun 16 16:37:25 gorse NetworkManager: <info>    hostname 'gorse'
Jun 16 16:37:25 gorse NetworkManager: <info>    nameserver '10.10.0.1'
Jun 16 16:37:25 gorse NetworkManager: <info>    nameserver '10.10.2.88'
Jun 16 16:37:25 gorse NetworkManager: <info>    domain name 'suse.de'
Jun 16 16:37:25 gorse NetworkManager: <info>    domain name 'arch.suse.de'
Jun 16 16:37:25 gorse NetworkManager: <info>    domain name 'nue.novell.com'
Jun 16 16:37:25 gorse NetworkManager: <info>    wins '149.44.160.146'
Jun 16 16:37:25 gorse NetworkManager: <info>  Activation (eth0) Stage 5 of 5 (IP Configure Commit) scheduled...
Jun 16 16:37:25 gorse NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP4 Configure Get) complete.
Jun 16 16:37:25 gorse NetworkManager: <info>  Activation (eth0) Stage 5 of 5 (IP Configure Commit) started...
Jun 16 16:37:26 gorse NetworkManager: <debug> [1276699046.019853] run_netconfig(): Spawning '/sbin/netconfig modify --service NetworkManager'
Jun 16 16:37:26 gorse NetworkManager: <debug> [1276699046.022169] write_to_netconfig(): Writing to netconfig: INTERFACE='eth0'#012
Jun 16 16:37:26 gorse NetworkManager: <debug> [1276699046.022257] write_to_netconfig(): Writing to netconfig: DNSSEARCH='suse.de suse.de arch.suse.de nue.novell.com'#012
Jun 16 16:37:26 gorse NetworkManager: <debug> [1276699046.022294] write_to_netconfig(): Writing to netconfig: DNSSERVERS='10.10.0.1 10.10.2.88'#012
Jun 16 16:37:26 gorse NetworkManager: <info>  Clearing nscd hosts cache.
Jun 16 16:37:26 gorse NetworkManager: <info>  (eth0): device state change: 7 -> 8 (reason 0)
Jun 16 16:37:26 gorse NetworkManager: <debug> [1276699046.026815] run_netconfig(): Spawning '/sbin/netconfig modify --service NetworkManager'
Jun 16 16:37:26 gorse NetworkManager: <debug> [1276699046.030111] write_to_netconfig(): Writing to netconfig: INTERFACE='eth0'#012
Jun 16 16:37:26 gorse NetworkManager: <debug> [1276699046.030180] write_to_netconfig(): Writing to netconfig: DNSSEARCH='suse.de suse.de arch.suse.de nue.novell.com'#012
Jun 16 16:37:26 gorse NetworkManager: <debug> [1276699046.030201] write_to_netconfig(): Writing to netconfig: DNSSERVERS='10.10.0.1 10.10.2.88'#012
Jun 16 16:37:26 gorse NetworkManager: <info>  Clearing nscd hosts cache.
Jun 16 16:37:26 gorse NetworkManager: <info>  Policy set 'Auto eth0' (eth0) as default for routing and DNS.
Jun 16 16:37:26 gorse NetworkManager: <info>  Activation (eth0) successful, device activated.
Jun 16 16:37:26 gorse NetworkManager: <info>  Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete.
Jun 16 16:37:26 gorse nm-dispatcher.action: Script '/etc/NetworkManager/dispatcher.d/autofs' exited with error status 1.
Comment 10 Will Stephenson 2010-06-16 18:58:42 UTC
*** Bug 589978 has been marked as a duplicate of this bug. ***
Comment 11 Will Stephenson 2010-06-17 05:36:01 UTC
Adrian, was this the case when you showed me this bug earlier in the week?:

I found a way to reproduce this bug, that was also the case the last time I reproduced it (comment #8):

If suspend-to-ram fails to suspend completely (machine does not enter S3 state although suspend light starts blinking) and I have to force power the machine to power off, then on the next start, NM starts asleep. 

My hunch is that NM sleeps when it receives a notification that the machine is suspending, persists this sleep state somewhere and this state is not reset on a normal boot after a forced powerdown.
Comment 12 Will Stephenson 2010-06-17 05:51:38 UTC
I was able to make suspend fail with bug 614989 - mounting an SD card.
Comment 13 Adrian Schröter 2010-06-17 07:35:45 UTC
My problems are directly after fresh boot, even in runlevel 3 the network manager is timing out running "nm-online".
Comment 14 Cristian Rodriguez 2010-06-17 15:05:40 UTC
(In reply to comment #13)
> My problems are directly after fresh boot, even in runlevel 3 the network
> manager is timing out running "nm-online".

Saw the same problem , but is a race condition, happends randomly :-|
Comment 15 Alexander van Kaam 2010-06-27 09:42:06 UTC
Have the same issue with my system, its an Asus P5W DH Deluxe, it has 2 Marvell 88E8053 Gigabit LAN connectors and 1 Wifi RTL8187L (although the manual is vague about which wifi chipset) with only 1st LAN port connected

Every now and then with M7 and RC1 it will not automatically connected to the network, system becomes really slow as soon as it reaches the desktop, if I wait about 60sec and then right click Knetworkmanager in the system tray and select eth0 it will connect just fine.   I would say about 3 out of 10 boots it will not connect.

qdbus --system org.freedesktop.NetworkManager /org/freedesktop/NetworkManager state 
2

qdbus --system org.freedesktop.NetworkManager /org/freedesktop/NetworkManager wake 
Error: org.freedesktop.DBus.GLib.UnmappedError.NmMangerError.Code7 
Already awake


Adding 2 log files: 

networkmanager-ok.log which is an ok bootup 
networkmanager-fail.log where he refuses to automatically log on and where I used Knetworkmanager and selected eth0 after a few minutes and then it did connect
Comment 16 Alexander van Kaam 2010-06-27 09:43:20 UTC
Created attachment 371957 [details]
networkmanager okay at bootup
Comment 17 Alexander van Kaam 2010-06-27 09:43:48 UTC
Created attachment 371958 [details]
networkmanager fail at boot
Comment 18 Adrian Schröter 2010-06-28 06:29:17 UTC
I have too a not working networkmanager after boot by default (being in state 1 after boot).
It always helps to wake him manually via command line, but this is IMHO really a ship stopper, because average users woun't be able to do that. So they will neither be able to download an update later.

This is current Factory on x86_64 on a Dell e6410.

Can I provide any kind of usefull debug data or debug myself ? I am really willing to invest time here.
Comment 19 Stefan Assmann 2010-07-16 16:04:42 UTC
still happens in 11.3 final.
Comment 20 Eduard Avetisyan 2010-07-17 21:41:46 UTC
Happens to me, too, with 11.3 final (actually, I wonder how does one release with such a bug).
/usr/bin/nm-online 
helped
Comment 21 Markus Zimmermann 2010-07-18 00:39:02 UTC
I'm also affected on a Thinkpad x60 with a fresh installed openSUSE 11.3 final.
nm-tool said that the networkmanager is asleep
only a "qdbus --system org.freedesktop.NetworkManager /org/freedesktop/NetworkManager wake" could solve it "nm-online" doesn't do the trick for me.
I will monitor when it actually happens.
Comment 22 Fatih Alabas 2010-07-18 17:10:42 UTC
I have got the same problem after having fresh installed the 11.3. Network Manager never connects to internet through my Ethernet Router. Actually this was a random case with 11.2 and I could manage it by simply clicking multiple times on the wired connection name on KDE`s Network Applet for waking up the network manager. However this time with 11.3. it does not give a reaction to my odd clicks. 

If I setup Network via traditional method with ifup, it is ok.

For my convenience, I still wanted to use network manager and then I had to setup network manager adding a new wired connection by entering all the network information manually in order to get a properly working network connection.
Comment 23 Fatih Alabas 2010-07-18 17:12:30 UTC
Created attachment 376629 [details]
Hardware Summary
Comment 24 Bin Li 2010-07-19 02:05:04 UTC
Let's focus it in bnc#585433.

*** This bug has been marked as a duplicate of bug 585433 ***