GNOME Bugzilla – Bug 644551
repeated errors in dmesg
Last modified: 2011-04-28 22:42:57 UTC
Since I have updated to NetworkManager 0.8.996 I see repeated errors in dmesg like the following: [ 1286.750258] iwl3945 0000:03:00.0: Microcode SW error detected. Restarting 0x82000008. [ 1286.750268] iwl3945 0000:03:00.0: Loaded firmware version: 15.32.2.9 [ 1286.750304] iwl3945 0000:03:00.0: Start IWL Error Log Dump: [ 1286.750309] iwl3945 0000:03:00.0: Status: 0x0002A2E4, count: 1 [ 1286.750314] iwl3945 0000:03:00.0: Desc Time asrtPC blink2 ilink1 nmiPC Line [ 1286.750543] iwl3945 0000:03:00.0: SYSASSERT (0x5) 0001680217 0x008B6 0x13756 0x00320 0x00000 764 [ 1286.750547] [ 1286.750677] iwl3945 0000:03:00.0: Start IWL Event Log Dump: display last 20 count [ 1286.750720] iwl3945 0000:03:00.0: 0001679867 0x00000001 1106 [ 1286.750746] iwl3945 0000:03:00.0: 0001679867 0x0000000f 1106 [ 1286.750771] iwl3945 0000:03:00.0: 0001679869 0x00000428 1105 [ 1286.750796] iwl3945 0000:03:00.0: 0001679873 0x00000483 1115 [ 1286.750821] iwl3945 0000:03:00.0: 0001679876 0x00000006 0463 [ 1286.750846] iwl3945 0000:03:00.0: 0001679877 0x00000006 0462 [ 1286.750871] iwl3945 0000:03:00.0: 0001680003 0x04130097 0401 [ 1286.750896] iwl3945 0000:03:00.0: 0001680005 0x00000006 0451 [ 1286.750921] iwl3945 0000:03:00.0: 0001680025 0x00000000 0451 [ 1286.750947] iwl3945 0000:03:00.0: 0001680157 0x44140080 0401 [ 1286.750972] iwl3945 0000:03:00.0: 0001680172 0x00000017 0452 [ 1286.750997] iwl3945 0000:03:00.0: 0001680177 0x00113b6e 0450 [ 1286.751023] iwl3945 0000:03:00.0: 0001680182 0x00113b6e 0450 [ 1286.751048] iwl3945 0000:03:00.0: 0001680187 0x00113b6e 0450 [ 1286.751073] iwl3945 0000:03:00.0: 0001680192 0x00113b6e 0450 [ 1286.751098] iwl3945 0000:03:00.0: 0001680197 0x00113b6e 0450 [ 1286.751123] iwl3945 0000:03:00.0: 0001680202 0x00123b6e 0450 [ 1286.751148] iwl3945 0000:03:00.0: 0001680207 0x00123b6e 0450 [ 1286.751173] iwl3945 0000:03:00.0: 0001680213 0x00123b6e 0450 [ 1286.751198] iwl3945 0000:03:00.0: 0001680218 0x00000100 0125 [ 1286.751212] iwl3945 0000:03:00.0: Error Reply type 0x000002FC cmd REPLY_SCAN_CMD (0x80) seq 0x4414 ser 0x00340000 [ 1286.755637] iwl3945 0000:03:00.0: Can't stop Rx DMA. The connection works, though. This only happens with NetworkManager 0.8.996. Until NetworkManager 0.8.2 this didn't occur. If I use wpa_supplicant directly for a connection, there are no such dmesg entries, too. My system: - Debian unstable with Linux 2.6.37.3 - Network controller: Intel Corporation PRO/Wireless 3945ABG [Golan] Network Connection (rev 02) - lspci -vn 0280: 8086:4227 (rev 02) Subsystem: 8086:1011 Flags: bus master, fast devsel, latency 0, IRQ 49 Memory at edf00000 (32-bit, non-prefetchable) [size=4K] Capabilities: [c8] Power Management version 2 Capabilities: [d0] MSI: Enable+ Count=1/1 Maskable- 64bit+ Capabilities: [e0] Express Legacy Endpoint, MSI 00 Capabilities: [100] Advanced Error Reporting Capabilities: [140] Device Serial Number 00-13-02-ff-ff-99-a5-61 Kernel driver in use: iwl3945 - /var/log/messages Mar 12 09:36:37 DK wpa_action: creating sendsigs omission pidfile: /lib/init/rw/sendsigs.omit.d/wpasupplicant.wpa_supplicant.wlan0.pid Mar 12 09:36:37 DK wpa_action: bssid=00:1e:e5:5b:2d:f5 Mar 12 09:36:37 DK wpa_action: ssid=DK Mar 12 09:36:37 DK wpa_action: id=1 Mar 12 09:36:37 DK wpa_action: mode=station Mar 12 09:36:37 DK wpa_action: pairwise_cipher=TKIP Mar 12 09:36:37 DK wpa_action: group_cipher=TKIP Mar 12 09:36:37 DK wpa_action: key_mgmt=WPA2-PSK Mar 12 09:36:37 DK wpa_action: wpa_state=COMPLETED Mar 12 09:36:37 DK wpa_action: ip_address=192.168.1.2 Mar 12 09:36:37 DK wpa_action: WPA_IFACE=wlan0 WPA_ACTION=DISCONNECTED Mar 12 09:36:37 DK wpa_action: WPA_ID=1 WPA_ID_STR= WPA_CTRL_DIR=/var/run/wpa_supplicant Mar 12 09:36:37 DK wpa_action: DISCONNECTED event blocked by hysteresis check Mar 12 09:36:37 DK wpa_action: WPA_IFACE=wlan0 WPA_ACTION=CONNECTED Mar 12 09:36:37 DK wpa_action: WPA_ID=1 WPA_ID_STR= WPA_CTRL_DIR=/var/run/wpa_supplicant Mar 12 09:36:37 DK wpa_action: CONNECTED event blocked by hysteresis check Mar 12 09:37:43 DK rsyslogd-2177: imuxsock lost 66 messages from pid 3806 due to rate-limiting Mar 12 09:37:43 DK kernel: [ 1274.656105] cfg80211: Calling CRDA to update world regulatory domain Mar 12 09:37:43 DK kernel: [ 1274.663774] cfg80211: World regulatory domain updated: Mar 12 09:37:43 DK kernel: [ 1274.663779] (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp) Mar 12 09:37:43 DK kernel: [ 1274.663782] (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Mar 12 09:37:43 DK kernel: [ 1274.663785] (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm) Mar 12 09:37:43 DK kernel: [ 1274.663788] (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm) Mar 12 09:37:43 DK kernel: [ 1274.663791] (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Mar 12 09:37:43 DK kernel: [ 1274.663794] (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) Mar 12 09:37:54 DK kernel: [ 1284.997977] ADDRCONF(NETDEV_UP): eth2: link is not ready Mar 12 09:37:54 DK kernel: [ 1285.070871] ADDRCONF(NETDEV_UP): wlan0: link is not ready Mar 12 09:37:58 DK kernel: [ 1289.583571] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
While it would be good to find out what's going on here, this is in the end both a kernel driver error (the card's firmware should never be crashing due to input from the kernel, since the driver should be validating it), and likely a wpa_supplicant error. There hasn't been any different in what the new NM actually sends to wpa_supplicant. However, NM is now using the new wpa_supplicant D-Bus interface, so any behavior differences can likely be attributed to a bug in wpa_supplicant's new D-Bus interface. First, what is the NetworkManager log output when connecting to the AP? NM will print the configuration it's sending to wpa_supplicant in /var/log/messages or /var/log/daemon.log. It'll look like this: <info> Activation (wlan12/wireless): connection 'Auto soho' has security, and secrets exist. No new secrets needed. Config: added 'ssid' value 'soho' <info> Config: added 'scan_ssid' value '1' <info> Config: added 'key_mgmt' value 'WPA-PSK' <info> Config: added 'psk' value '<omitted>' <info> Config: added 'proto' value 'RSN' <info> Config: added 'pairwise' value 'TKIP CCMP' <info> Config: added 'group' value 'TKIP' <info> Activation (wlan12) Stage 2 of 5 (Device Configure) complete. if you're able to compare what NM 0.8.2 was sending with what NM 0.8.996 is sending, perhaps we can figure out if there's actually anything different on the NM side or not. If there is no difference here between NM 0.8.2 and 0.8.996, then the bug is in wpa_supplicant. Send, is the config that's sent really TKIP + WPA2 ? That's not an often-used configuration, and I'm not even sure it's legal as WPA2/RSN require CCMP as the authentication algorithm, and perhaps that's why the iwl3945's firmware is crashing. I've requested some information from the kernel driver developers to figure out what might be going on here, and if we need more information.
Here is the output of /var/log/daemon.log with NM 0.8.996 Mar 16 12:22:18 DK NetworkManager[2621]: <info> Activation (wlan0/wireless): access point 'Auto DK' has security, but secrets are required. Mar 16 12:22:18 DK NetworkManager[2621]: <info> (wlan0): device state change: 50 -> 60 (reason 0) Mar 16 12:22:18 DK NetworkManager[2621]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete. Mar 16 12:22:24 DK NetworkManager[2621]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... Mar 16 12:22:24 DK NetworkManager[2621]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started... Mar 16 12:22:24 DK NetworkManager[2621]: <info> (wlan0): device state change: 60 -> 40 (reason 0) Mar 16 12:22:24 DK NetworkManager[2621]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... Mar 16 12:22:24 DK NetworkManager[2621]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. Mar 16 12:22:24 DK NetworkManager[2621]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting... Mar 16 12:22:24 DK NetworkManager[2621]: <info> (wlan0): device state change: 40 -> 50 (reason 0) Mar 16 12:22:24 DK NetworkManager[2621]: <info> Activation (wlan0/wireless): connection 'Auto DK' has security, and secrets exist. No new secrets needed. Mar 16 12:22:24 DK NetworkManager[2621]: <info> Config: added 'ssid' value 'DK' Mar 16 12:22:24 DK NetworkManager[2621]: <info> Config: added 'scan_ssid' value '1' Mar 16 12:22:24 DK NetworkManager[2621]: <info> Config: added 'key_mgmt' value 'WPA-PSK' Mar 16 12:22:24 DK NetworkManager[2621]: <info> Config: added 'auth_alg' value 'OPEN' Mar 16 12:22:24 DK NetworkManager[2621]: <info> Config: added 'psk' value '<omitted>' Mar 16 12:22:24 DK NetworkManager[2621]: <info> Config: added 'proto' value 'RSN' Mar 16 12:22:24 DK NetworkManager[2621]: <info> Config: added 'pairwise' value 'CCMP' Mar 16 12:22:24 DK NetworkManager[2621]: <info> Config: added 'group' value 'CCMP' Mar 16 12:22:24 DK NetworkManager[2621]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete. I'll try to downgrade NM to 0.8.2 as soon as possible. Thanks for the hint to TKIP+WPA2! Indeed my WLAN has been setup in the wrong way since years. I corrected that, but problem persists, so this is not the reason for the firmware crashes. Thanks for looking into this! Regards denk
OK, by downgrading to 0.8.4 RC1 those repeating errors in dmesg are gone! Output of /var/log/daemon.log Mar 19 09:37:02 DK NetworkManager[2583]: <info> Activation (wlan0/wireless): connection 'Auto DK' has security, and secrets exist. No new secrets needed. Mar 19 09:37:02 DK NetworkManager[2583]: <info> Config: added 'ssid' value 'DK' Mar 19 09:37:02 DK NetworkManager[2583]: <info> Config: added 'scan_ssid' value '1' Mar 19 09:37:02 DK NetworkManager[2583]: <info> Config: added 'key_mgmt' value 'WPA-PSK' Mar 19 09:37:02 DK NetworkManager[2583]: <info> Config: added 'auth_alg' value 'OPEN' Mar 19 09:37:02 DK NetworkManager[2583]: <info> Config: added 'psk' value '<omitted>' Mar 19 09:37:02 DK NetworkManager[2583]: <info> Config: added 'proto' value 'RSN' Mar 19 09:37:02 DK NetworkManager[2583]: <info> Config: added 'pairwise' value 'CCMP' Mar 19 09:37:02 DK NetworkManager[2583]: <info> Config: added 'group' value 'CCMP' Mar 19 09:37:02 DK NetworkManager[2583]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete. If you need further information, please ask! Regards denk
Anything new on this?
It appears there are some errors in the kernel driver for the 3945. One thing you can try is to add "disable_hw_scan=1" to the modprobe options for your 3945, which you can do by adding: options iwl3945 disable_hw_scan=1 to /etc/modprobe.conf or /etc/modprobe.d/local.conf depending on what you have on your system. After a reboot, does that fix the problem?
Thanks for your response! If I add options iwl3945 disable_hw_scan=1 and after reboot, the problem seems to be fixed. But instead I get the following errors in dmesg now: [ 366.957069] iwl3945 0000:03:00.0: Failed to get channel info for channel 104 [0] [ 367.636060] iwl3945 0000:03:00.0: Failed to get channel info for channel 116 [0] [ 368.315046] iwl3945 0000:03:00.0: Failed to get channel info for channel 128 [0] [ 368.994064] iwl3945 0000:03:00.0: Failed to get channel info for channel 140 [0] [ 407.125039] iwl3945 0000:03:00.0: Failed to get channel info for channel 100 [0] [ 407.804033] iwl3945 0000:03:00.0: Failed to get channel info for channel 112 [0] [ 408.231034] iwl3945 0000:03:00.0: Failed to get channel info for channel 116 [0] [ 408.910034] iwl3945 0000:03:00.0: Failed to get channel info for channel 128 [0] [ 409.590035] iwl3945 0000:03:00.0: Failed to get channel info for channel 140 [0] Can you explain me the impact of these?
(In reply to comment #5) > It appears there are some errors in the kernel driver for the 3945. One thing > you can try is to add "disable_hw_scan=1" to the modprobe options for your > 3945, which you can do by adding: > > options iwl3945 disable_hw_scan=1 > > to /etc/modprobe.conf or /etc/modprobe.d/local.conf depending on what you have > on your system. After a reboot, does that fix the problem? On non NM systems for me, using the same kernel and firmware version results in NOT seeing this spammed to the system log. If it's a bug in the kernel, it's certainly being trigger by ONLY NM. However, with testing nm 0.9, it's constant (and I believe even contributing to a kernel panic that I seem to be getting at random, every couple of days). I have tested even using the new wpa_supplicant interface via. connman on 2.6.38.x, and the spam is also not present in my system logs.
I am also seeing this in Fedora 15 Beta. See: https://bugzilla.redhat.com/show_bug.cgi?id=683571
This issue is clearly a kernel driver issue, but it's probably aggravated by NetworkManager because NM talks to the card a lot more than static configuration tools do. Again, if there is ever a "Microcode SW Error" detected message, there is a driver problem and that needs to be fixed in the kernel. The drivers need to be able to handle this sort of thing. For now, you may be able to quiet the spam by locking the connection to a single BSSID in nm-connection-editor which suppresses NM's periodic scan, but you need periodic scans if you are ever in a multi-AP network so that roaming works correctly. But while we're waiting for the kernel to be fixed, you can try the workaround of locking to your AP's BSSID and that should make dmesg quieter. Again, not something NM can fix (even though it may aggravate the problem) because the problem needs to be fixed at the source, which is the kernel drivers. Kernel drivers should never crash, panic, lock up, etc, and if they do, then we need to fix the drivers.
See https://bugzilla.redhat.com/show_bug.cgi?id=688252 for more details and associated kernel driver patch links.