Bug 8450

Summary:	Wireless cannot stay up for more than a couple of seconds
Product:	Mageia	Reporter:	Vladimir Gurevich <mageia>
Component:	RPM Packages	Assignee:	Mageia Bug Squad <bugsquad>
Status:	RESOLVED FIXED	QA Contact:
Severity:	major
Priority:	release_blocker	CC:	mageia, mageia, mageia, tmb
Version:	Cauldron
Target Milestone:	---
Hardware:	x86_64
OS:	Linux
Whiteboard:
Source RPM:		CVE:
Status comment:

Description Vladimir Gurevich 2012-12-20 18:14:00 CET

Description of problem:

When attempting to connect using Broadcom Wireless, connection is established successfully and then goes down, after just a couple of seconds. This used to work before without any problems and then stopped working on all my machines running Cauldron. Other devices still work, so I am quite sure there were no configuration changes.

Not sure whether this is the proprietary driver broadcom-wl, wpa_supplicant or Networkmanager.

Version-Release number of selected component (if applicable):

broadcom-wl-kernel-desktop-latest-5.100.82.112-51.mga3.nonfree
broadcom-wl-kernel-3.7.1-desktop-1.mga3-5.100.82.112-51.mga3.nonfree
wpa_supplicant-1.0-4.mga3
networkmanager-0.9.6.4-1.mga3
knetworkmanager-0.9.0.5-1.mga3

How reproducible:

Always.

Steps to Reproduce:

1. Disconnect the Ethernet cable

Dec 20 08:53:33 skype kernel: tg3 0000:09:00.0 eth0: Link is down
Dec 20 08:53:34 skype NetworkManager[2949]: <info> (eth0): carrier now OFF (device state 100, deferring action for 4 seconds)
Dec 20 08:53:36 skype kernel: dell_wmi: Unknown key e044 pressed
Dec 20 08:53:39 skype NetworkManager[2949]: <info> (eth0): device state change: activated -> unavailable (reason 'carrier-changed') [100 20 40]
Dec 20 08:53:39 skype NetworkManager[2949]: <info> (eth0): deactivating device (reason 'carrier-changed') [40]
Dec 20 08:53:39 skype NetworkManager[2949]: <info> (eth0): canceled DHCP transaction, DHCP client pid 7608
Dec 20 08:53:39 skype avahi-daemon[2959]: Withdrawing address record for 192.168.0.130 on eth0.
Dec 20 08:53:39 skype avahi-daemon[2959]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.0.130.
Dec 20 08:53:39 skype avahi-daemon[2959]: Interface eth0.IPv4 no longer relevant for mDNS.
Dec 20 08:53:39 skype NetworkManager[2949]: <info> ((null)): removing resolv.conf from /sbin/resolvconf
Dec 20 08:53:40 skype systemd[1]: Stopping Name Service Cache Daemon...
Dec 20 08:53:40 skype systemd[1]: Starting Name Service Cache Daemon...
Dec 20 08:53:41 skype nscd: 31504 cannot stat() file `/etc/netgroup': No such file or directory
Dec 20 08:53:41 skype nscd: 31504 cannot create /var/db/nscd/passwd; no persistent database used
Dec 20 08:53:41 skype nscd: 31504 cannot create /var/db/nscd/group; no persistent database used
Dec 20 08:53:41 skype nscd: 31504 cannot create /var/db/nscd/services; no persistent database used
Dec 20 08:53:41 skype nscd: 31504 cannot create /var/db/nscd/netgroup; no persistent database used
Dec 20 08:53:41 skype systemd[1]: Started Name Service Cache Daemon.
Dec 20 08:53:41 skype dbus-daemon[2960]: dbus[2960]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Dec 20 08:53:41 skype dbus[2960]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Dec 20 08:53:41 skype mgaapplet[6343]: Checking Network: seems disabled
Dec 20 08:53:41 skype dbus-daemon[2960]: dbus[2960]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Dec 20 08:53:41 skype dbus[2960]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Dec 20 08:53:41 skype ntpd[5176]: Deleting interface #9 eth0, 192.168.0.130#123, interface stats: received=0, sent=0, dropped=0, active_time=82456 secs
Dec 20 08:53:41 skype ntpd[5176]: peers refreshed

2. Turn on wireless using the dedicated switch on the laptop
3. Usually, it doesn't come up automatically (as it used to). Here is a typical output from /var/log/messages:

^@Dec 20 08:53:53 skype wpa_supplicant[3099]: ioctl[SIOCGIWSCAN]: Invalid argument
Dec 20 08:53:59 skype NetworkManager[2949]: <info> (eth1): supplicant interface state: inactive -> disconnected
Dec 20 08:53:59 skype NetworkManager[2949]: <info> (eth1): supplicant interface state: disconnected -> inactive


4.  I use KDE NetworkManager applet and click on the connection, that represent
my access point:

Dec 20 08:54:13 skype NetworkManager[2949]: <info> Activation (eth1) starting connection 'paulidav'
Dec 20 08:54:13 skype NetworkManager[2949]: <info> (eth1): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Dec 20 08:54:13 skype NetworkManager[2949]: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) scheduled...
Dec 20 08:54:13 skype NetworkManager[2949]: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) started...
Dec 20 08:54:13 skype NetworkManager[2949]: <info> Activation (eth1) Stage 2 of 5 (Device Configure) scheduled...
Dec 20 08:54:13 skype NetworkManager[2949]: <info> Activation (eth1) Stage 1 of 5 (Device Prepare) complete.
Dec 20 08:54:13 skype NetworkManager[2949]: <info> Activation (eth1) Stage 2 of 5 (Device Configure) starting...
Dec 20 08:54:13 skype NetworkManager[2949]: <info> (eth1): device state change: prepare -> config (reason 'none') [40 50 0]
Dec 20 08:54:13 skype NetworkManager[2949]: <info> Activation (eth1/wireless): connection 'paulidav' has security, and secrets exist.  No new secrets needed.
Dec 20 08:54:13 skype NetworkManager[2949]: <info> Config: added 'ssid' value 'paulidav'
Dec 20 08:54:13 skype NetworkManager[2949]: <info> Config: added 'scan_ssid' value '1'
Dec 20 08:54:13 skype NetworkManager[2949]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Dec 20 08:54:13 skype NetworkManager[2949]: <info> Config: added 'psk' value '<omitted>'
Dec 20 08:54:13 skype NetworkManager[2949]: <info> Config: added 'proto' value 'WPA RSN'
Dec 20 08:54:13 skype NetworkManager[2949]: <info> Activation (eth1) Stage 2 of 5 (Device Configure) complete.
Dec 20 08:54:13 skype NetworkManager[2949]: <info> Config: set interface ap_scan to 1
Dec 20 08:54:13 skype NetworkManager[2949]: <info> (eth1): supplicant interface state: inactive -> scanning
Dec 20 08:54:15 skype wpa_supplicant[3099]: ioctl[SIOCGIWSCAN]: Resource temporarily unavailable
Dec 20 08:54:17 skype NetworkManager[2949]: <info> (eth1): supplicant interface state: scanning -> 4-way handshake
Dec 20 08:54:17 skype NetworkManager[2949]: <info> (eth1): supplicant interface state: 4-way handshake -> completed
Dec 20 08:54:17 skype NetworkManager[2949]: <info> Activation (eth1/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'paulidav'.
Dec 20 08:54:17 skype NetworkManager[2949]: <info> Activation (eth1) Stage 3 of 5 (IP Configure Start) scheduled.
Dec 20 08:54:17 skype NetworkManager[2949]: <info> Activation (eth1) Stage 3 of 5 (IP Configure Start) started...
Dec 20 08:54:17 skype NetworkManager[2949]: <info> (eth1): device state change: config -> ip-config (reason 'none') [50 70 0]
Dec 20 08:54:17 skype NetworkManager[2949]: <info> Activation (eth1) Beginning DHCPv4 transaction (timeout in 45 seconds)
Dec 20 08:54:17 skype NetworkManager[2949]: <info> dhclient started with pid 31555
Dec 20 08:54:17 skype NetworkManager[2949]: <info> Activation (eth1) Stage 3 of 5 (IP Configure Start) complete.
Dec 20 08:54:17 skype dhclient: Internet Systems Consortium DHCP Client 4.2.4-P2
Dec 20 08:54:17 skype dhclient: Copyright 2004-2012 Internet Systems Consortium.
Dec 20 08:54:17 skype dhclient: All rights reserved.
Dec 20 08:54:17 skype dhclient: For info, please visit https://www.isc.org/software/dhcp/
Dec 20 08:54:17 skype dhclient: 
Dec 20 08:54:17 skype ifplugd(eth1)[3317]: Link beat detected.
Dec 20 08:54:17 skype NetworkManager[2949]: <info> (eth1): DHCPv4 state changed nbi -> preinit
Dec 20 08:54:17 skype dhclient: Listening on LPF/eth1/00:1f:3a:57:00:84
Dec 20 08:54:17 skype dhclient: Sending on   LPF/eth1/00:1f:3a:57:00:84
Dec 20 08:54:17 skype dhclient: Sending on   Socket/fallback
Dec 20 08:54:17 skype dhclient: DHCPDISCOVER on eth1 to 255.255.255.255 port 67 interval 6
Dec 20 08:54:17 skype dhclient: DHCPREQUEST on eth1 to 255.255.255.255 port 67
Dec 20 08:54:17 skype dhclient: DHCPOFFER from 192.168.0.254
Dec 20 08:54:17 skype dhclient: DHCPACK from 192.168.0.254
Dec 20 08:54:17 skype dhclient: bound to 192.168.0.245 -- renewal in 10761 seconds.
Dec 20 08:54:17 skype NetworkManager[2949]: <info> (eth1): DHCPv4 state changed preinit -> bound
Dec 20 08:54:17 skype NetworkManager[2949]: <info>   address 192.168.0.245
Dec 20 08:54:17 skype NetworkManager[2949]: <info>   prefix 24 (255.255.255.0)
Dec 20 08:54:17 skype NetworkManager[2949]: <info>   gateway 192.168.0.254
Dec 20 08:54:17 skype NetworkManager[2949]: <info>   nameserver '192.168.0.254'
Dec 20 08:54:17 skype NetworkManager[2949]: <info>   domain name 'den.paulidav.org'
Dec 20 08:54:17 skype NetworkManager[2949]: <info> Activation (eth1) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Dec 20 08:54:17 skype NetworkManager[2949]: <info> Activation (eth1) Stage 5 of 5 (IPv4 Commit) started...
Dec 20 08:54:17 skype avahi-daemon[2959]: Joining mDNS multicast group on interface eth1.IPv4 with address 192.168.0.245.
Dec 20 08:54:17 skype avahi-daemon[2959]: New relevant interface eth1.IPv4 for mDNS.
Dec 20 08:54:17 skype avahi-daemon[2959]: Registering new address record for 192.168.0.245 on eth1.IPv4.
Dec 20 08:54:18 skype ifplugd(eth1)[3317]: Executing '/etc/ifplugd/ifplugd.action eth1 up'.
Dec 20 08:54:18 skype NetworkManager[2949]: <info> (eth1): device state change: ip-config -> activated (reason 'none') [70 100 0]
Dec 20 08:54:19 skype NetworkManager[2949]: <info> ((null)): writing resolv.conf to /sbin/resolvconf
Dec 20 08:54:19 skype ntpd[5176]: Listen normally on 10 eth1 192.168.0.245 UDP 123
Dec 20 08:54:19 skype ntpd[5176]: peers refreshed
Dec 20 08:54:19 skype systemd[1]: Stopping Name Service Cache Daemon...
Dec 20 08:54:19 skype systemd[1]: Starting Name Service Cache Daemon...
Dec 20 08:54:19 skype systemd[1]: PID file /var/run/nscd/nscd.pid not readable (yet?) after start.
Dec 20 08:54:19 skype nscd: 31668 cannot stat() file `/etc/netgroup': No such file or directory
Dec 20 08:54:19 skype systemd[1]: Started Name Service Cache Daemon.
Dec 20 08:54:19 skype nscd: 31668 cannot create /var/db/nscd/passwd; no persistent database used
Dec 20 08:54:19 skype nscd: 31668 cannot create /var/db/nscd/group; no persistent database used
Dec 20 08:54:19 skype nscd: 31668 cannot create /var/db/nscd/services; no persistent database used
Dec 20 08:54:19 skype nscd: 31668 cannot create /var/db/nscd/netgroup; no persistent database used
Dec 20 08:54:19 skype NetworkManager[2949]: <info> Policy set 'paulidav' (eth1) as default for IPv4 routing and DNS.
Dec 20 08:54:19 skype NetworkManager[2949]: <info> Activation (eth1) successful, device activated.
Dec 20 08:54:19 skype dbus-daemon[2960]: dbus[2960]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Dec 20 08:54:19 skype dbus[2960]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Dec 20 08:54:19 skype NetworkManager[2949]: <info> Activation (eth1) Stage 5 of 5 (IPv4 Commit) complete.
Dec 20 08:54:19 skype dbus-daemon[2960]: dbus[2960]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Dec 20 08:54:19 skype dbus[2960]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'

4. A couple of seconds later....

Dec 20 08:54:27 skype wpa_supplicant[3099]: ioctl[SIOCGIWSCAN]: Resource temporarily unavailable
Dec 20 08:54:27 skype NetworkManager[2949]: <info> (eth1): supplicant interface state: completed -> disconnected
Dec 20 08:54:27 skype NetworkManager[2949]: <info> (eth1): supplicant interface state: disconnected -> scanning
Dec 20 08:54:27 skype ifplugd(eth1)[3317]: Link beat lost.
Dec 20 08:54:33 skype ifplugd(eth1)[3317]: Executing '/etc/ifplugd/ifplugd.action eth1 down'.
Dec 20 08:54:33 skype NetworkManager[2949]: <info> (eth1): device state change: activated -> disconnected (reason 'user-requested') [100 30 39]
Dec 20 08:54:33 skype NetworkManager[2949]: <info> (eth1): deactivating device (reason 'user-requested') [39]
Dec 20 08:54:34 skype NetworkManager[2949]: <info> (eth1): canceled DHCP transaction, DHCP client pid 31555
Dec 20 08:54:34 skype NetworkManager[2949]: <info> ((null)): removing resolv.conf from /sbin/resolvconf
Dec 20 08:54:34 skype avahi-daemon[2959]: Withdrawing address record for 192.168.0.245 on eth1.
Dec 20 08:54:34 skype avahi-daemon[2959]: Leaving mDNS multicast group on interface eth1.IPv4 with address 192.168.0.245.
Dec 20 08:54:34 skype avahi-daemon[2959]: Interface eth1.IPv4 no longer relevant for mDNS.
Dec 20 08:54:34 skype systemd[1]: Stopping Name Service Cache Daemon...
Dec 20 08:54:34 skype systemd[1]: Starting Name Service Cache Daemon...
Dec 20 08:54:34 skype systemd[1]: PID file /var/run/nscd/nscd.pid not readable (yet?) after start.
Dec 20 08:54:34 skype nscd: 32001 cannot stat() file `/etc/netgroup': No such file or directory
Dec 20 08:54:34 skype systemd[1]: Started Name Service Cache Daemon.
Dec 20 08:54:34 skype nscd: 32001 cannot create /var/db/nscd/passwd; no persistent database used
Dec 20 08:54:34 skype nscd: 32001 cannot create /var/db/nscd/group; no persistent database used
Dec 20 08:54:34 skype nscd: 32001 cannot create /var/db/nscd/services; no persistent database used
Dec 20 08:54:34 skype nscd: 32001 cannot create /var/db/nscd/netgroup; no persistent database used
Dec 20 08:54:34 skype dbus-daemon[2960]: dbus[2960]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Dec 20 08:54:34 skype dbus[2960]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Dec 20 08:54:34 skype NetworkManager[2949]: <info> (eth1): supplicant interface state: scanning -> disconnected
Dec 20 08:54:34 skype ifplugd(eth1)[3317]: Program executed successfully.
Dec 20 08:54:34 skype dbus-daemon[2960]: dbus[2960]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Dec 20 08:54:34 skype dbus[2960]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Dec 20 08:54:35 skype ntpd[5176]: Deleting interface #10 eth1, 192.168.0.245#123, interface stats: received=0, sent=0, dropped=0, active_time=16 secs
Dec 20 08:54:35 skype ntpd[5176]: peers refreshed

So, in summary, about 7 seconds after successful connection NetworkManager somehow is told that link is lost and this causes the problem.

System info: Dell Latitude D830 Laptop, 
[root@skype skype]# lspci -d 14e4:
09:00.0 Ethernet controller: Broadcom Corporation NetXtreme BCM5755M Gigabit Ethernet PCI Express (rev 02)
0c:00.0 Network controller: Broadcom Corporation BCM4321 802.11a/b/g/n (rev 03)
[root@skype skype]#

Comment 1 Manuel Hiebel 2012-12-21 23:53:32 CET

any ideas Olivier or Thomas ?

can be related to https://bugs.mageia.org/show_bug.cgi?id=7828 ?

CC: (none) => mageia, tmb

Comment 2 Vladimir Gurevich 2013-01-04 08:31:16 CET

The bug is still there.

It temporarily disappeared when upgraded to knetworkmanager-0.9.0.6-1.mga3 and then reappeared after KDE-4.9.95 upgrade came in.

Comment 3 Sander Lepik 2013-01-04 09:26:37 CET

In this case this doesn't seem to be related with bug #7828 nor broadcom at all. I'm quite sure it has something to do with networkmanager. I've seen such problem with Intel's iwl3945 and also with rt2800usb. All problems started to happen after some latest updates. Yesterday we were testing with the Intel's module and after switching back to Mageia tools for wifi it was working OK (well, we had to boot into Windows to enable wifi and then reboot to mageia but other than that the wifi was stable), can't say the same about NM, with iwl3945 it was unable to connect at all.

Priority: Normal => release_blocker
CC: (none) => sander.lepik

Comment 4 Vladimir Gurevich 2013-01-10 07:31:48 CET

I can confirm that this is networkmanager. I reconfigured my network interfaces NOT to be managed by networkmanager and the problem is gone -- drakroam manages WiFi just fine. 

Still, it would be nice to have network manager working correctly.

Sander Lepik 2013-01-20 16:40:12 CET

Summary: Broadcom Wireless cannot stay up for more than a couple of seconds => Wireless cannot stay up for more than a couple of seconds

Comment 5 Damien Lallement 2013-01-21 19:26:20 CET

I reproduce and confirm this bug on cauldron.

CC: (none) => mageia

Comment 6 Damien Lallement 2013-01-21 19:27:24 CET

Even with "NM_CONTROLLED=yes", I can use nm to control my WiFI connexion.
With "NM_CONTROLLED=no", I can use drakroam. <3

Comment 7 Sander Lepik 2013-02-13 08:39:59 CET

I think this bug may be the same as #9028.

Comment 8 Vladimir Gurevich 2013-03-11 03:59:47 CET

The problem seems to be gone now (kernel-3.8.1 and neworkmanager-0.9.8). Difficult to say when exaclty and whether it was indeed the duplicate of #9028 (at least wpa_supplicant is running in my system).

Comment 9 Sander Lepik 2013-03-11 08:28:14 CET

Marking as fixed then.

Status: NEW => RESOLVED
Resolution: (none) => FIXED