Bug 738508

Summary: ipw2200: Failed to send {label}: Already sending a command.
Product: [Fedora] Fedora Reporter: Sam Varshavchik <mrsam>
Component: kernelAssignee: John W. Linville <linville>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 15CC: dcbw, gansalmon, itamar, jonathan, kernel-maint, madhu.chinakonda, psimerda
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-06-06 19:32:24 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Sam Varshavchik 2011-09-15 02:37:29 UTC
Description of problem:

When NetworkManager decides to start roaming from one AP to another, back and forth, eventually at some point ipw2200 logs this kernel message, there's no more wireless connectivity, some kernel thread starts burning up all the CPU, and the only way to return to normalcy is to rmmod and modprobe ipw2200, again.

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

2.6.40.4-5.fc15.i686

How reproducible:

Always

Steps to Reproduce:
1. Set up a pair of APs bridged to the same network, and bound to the same SSID, and position yourself about halfway between the two, with some conditions that randomly fluctuates the relative signal strength of each AP, independently of each other. A visit to a hotel with crappy wireless connectivity and an incompetent wireless setup should be a fairly decent test case.
2. Let NetworkManager loose, and have it ping-pong the poor laptop between a pair of APs, like this:

Sep 14 22:17:14 lc2440 NetworkManager[641]: <info> (eth1): roamed from BSSID C4:10:8A:16:04:A9 (Wyndham-Guest) to C4:10:8A:15:ED:49 (Wyndham-Guest)
Sep 14 22:17:48 lc2440 NetworkManager[641]: <info> (eth1): roamed from BSSID C4:10:8A:15:ED:49 (Wyndham-Guest) to C4:10:8A:16:04:A9 (Wyndham-Guest)
Sep 14 22:21:55 lc2440 NetworkManager[641]: <info> (eth1): roamed from BSSID C4:10:8A:16:04:A9 (Wyndham-Guest) to C4:10:8A:15:ED:49 (Wyndham-Guest)

Well, that's not enough to lose all connectivity, not just yet. Things are still plodding along.

3. Wait for one of these messages to get logged:

Sep 14 22:12:39 lc2440 kernel: [ 3345.127442] ipw2200: Failed to send SYSTEM_CONFIG: Already sending a command.
Sep 14 22:14:17 lc2440 kernel: [ 3442.599281] ipw2200: Failed to send SYSTEM_CONFIG: Already sending a command.
Sep 14 22:15:54 lc2440 kernel: [ 3539.856428] ipw2200: Failed to send ASSOCIATE: Already sending a command.
Sep 14 22:19:43 lc2440 kernel: [ 3768.706845] ipw2200: Failed to send SYSTEM_CONFIG: Already sending a command.
  
Actual results:

Once one of these gets logged, wireless is dead, and some kernel thread usually starts eating 100% CPU. rmmoding ipw2200 and modprobing it back in, restores wireless. For a few more minutes.

Expected results:

Well, NetworkManager really shouldn't be this dumb and start jumping between APs like this, and the frequent roaming is very counterproductive, but things don't really fall apart completely until ipw2200 can't handle the strain, and gives up the ghost.

Additional info:

Here's an example occurence of ipw2200's crash, and what typically goes into /var/log/messages when it happens.

Sep 14 22:17:46 lc2440 NetworkManager[641]: <info> (eth1): supplicant interface state: completed -> disconnected
Sep 14 22:17:46 lc2440 NetworkManager[641]: <info> (eth1): supplicant interface state: disconnected -> scanning
Sep 14 22:17:47 lc2440 NetworkManager[641]: <info> (eth1): supplicant interface state: scanning -> associating
Sep 14 22:17:47 lc2440 NetworkManager[641]: <info> (eth1): supplicant interface state: associating -> disconnected
Sep 14 22:17:48 lc2440 NetworkManager[641]: <info> (eth1): roamed from BSSID C4:10:8A:15:ED:49 (Wyndham-Guest) to C4:10:8A:16:04:A9 (Wyndham-Guest)
Sep 14 22:17:48 lc2440 NetworkManager[641]: <info> (eth1): supplicant interface state: disconnected -> completed
Sep 14 22:18:18 lc2440 ntpd_intres[2729]: host name not found: shorty.email-scan.com
Sep 14 22:19:02 lc2440 NetworkManager[641]: <info> (eth1): supplicant interface state: completed -> disconnected
Sep 14 22:19:03 lc2440 NetworkManager[641]: <info> (eth1): supplicant interface state: disconnected -> scanning
Sep 14 22:19:03 lc2440 NetworkManager[641]: <info> (eth1): supplicant interface state: scanning -> associating
Sep 14 22:19:05 lc2440 NetworkManager[641]: <info> (eth1): supplicant interface state: associating -> completed
Sep 14 22:19:42 lc2440 NetworkManager[641]: <info> (eth1): supplicant interface state: completed -> disconnected
Sep 14 22:19:42 lc2440 NetworkManager[641]: <info> (eth1): supplicant interface state: disconnected -> scanning
Sep 14 22:19:43 lc2440 NetworkManager[641]: <info> (eth1): supplicant interface state: scanning -> associating
Sep 14 22:19:43 lc2440 kernel: [ 3768.706845] ipw2200: Failed to send SYSTEM_CONFIG: Already sending a command.
Sep 14 22:19:43 lc2440 NetworkManager[641]: <info> (eth1): supplicant interface state: associating -> disconnected

Comment 1 Pavel Šimerda (pavlix) 2011-10-19 19:04:44 UTC
I'm seeing the "Failed to send SYSTEM_CONFIG" error on a network with just one AP and no roaming.

Kernel 2.6.40.3-0.fc15.i686 (and some other 2.6.40.3-x.fc15).

Comment 2 Dan Williams 2012-04-28 16:21:55 UTC
Probably a dup of bug 802106 but would need a backport to the F15 kernel.

Comment 3 Josh Boyer 2012-06-06 19:32:24 UTC
F15 has 2.6.43.8 now.  If you are still seeing this problem with that kernel, please let us know.