Bug 2005 – Log prints "tuning to channel 0" and firmware error after triggering S3

Bug 2005 - Log prints "tuning to channel 0" and firmware error after triggering S3

Summary:

Log prints "tuning to channel 0" and firmware error after triggering S3

Status:	VERIFIED FIXED

Product:	iwlwifi
Component:	firmware error
Version:	iwlwifi-2.6 development tree
Platform:	4965 (Intel(R) WiFi Link 4965) Fedora 10

Importance:	P1 major
Assigned To:	Abhijeet Kolekar
QA Contact:	Jeff Zheng

URL:
Keywords:

Depends on:
Blocks:
	Show dependency tree / graph

Reported:	2009-05-22 01:47 by ximin luo
Modified:	2009-06-08 19:42 (History)

Attachments
IWL_DL_INFO & IWL_DL_MAC80211 log (43.80 KB, application/octet-stream) 2009-05-26 22:35, ximin luo	Details
Try this patch. (780 bytes, patch) 2009-05-29 14:31, Abhijeet Kolekar	Details \| Diff
Add an attachment (proposed patch, testcase, etc.)

Note

You need to log in before you can comment on or make changes to this bug.

Description From ximin luo 2009-05-22 01:47:49

Test Environment
===============================================
Platform        :       Intel SDV M3M31
Wireless Card   :       Intel(R) WiFi Link 4965
OS              :       Redhat Fedora release 10 (Cambridge) 64bit
AP              :       Cisco 1250
uCode           :       iwlwifi-4965-2.ucode 228.57.2.23
Source          :       57747450baf1b4ccf94e5c1826afb3d438def78b
                     (Tue Mar 24 13:30:49 2009)

Issues
================================================
dmesg prints many “iwlagn 0000:01:00.0: Correctable OTP ECC error, continue
read” after loading iwlagn.
After resuming from S3, Microcode SW error is detected (SYSASSERT (#05) line
1419). And log has "tuning to channel 0".

Steps to Reproduce
================================================
1. modprobe -r iwlagn
2. modprobe iwlagn ----> dmesg prints many "OTP ECC error"
3. ifconfig wlan0 up
4. iwconfig wlan0 channel <> essid <>
5. ifconfig wlan0 <IP_ADDR>
6. echo -n mem > /sys/power/state
7. resume from S3 and dmesg print uCode error

Part of log message
================================================
usb 6-1: reset low speed USB device using uhci_hcd and address 2
e1000e: eth0 NIC Link is Up 100 Mbps Full Duplex, Flow Control: RX/TX
0000:00:19.0: eth0: 10/100 speed: disabling TSO
iwlagn 0000:01:00.0: check 52 fields 1 | 16
iwlagn 0000:01:00.0: check 52 CCK 2 | 16
iwlagn 0000:01:00.0: check mac addr 3 | 16
iwlagn 0000:01:00.0: check basic rate 4 | 17
iwlagn 0000:01:00.0: check assoc id 5 | 17
iwlagn 0000:01:00.0: check CCK and short slot 6 | 17
iwlagn 0000:01:00.0: check CCK & auto detect 7 | 17
iwlagn 0000:01:00.0: check TGG and auto detect 8 | 17
iwlagn 0000:01:00.0: Tuning to channel 0
iwlagn 0000:01:00.0: Not a valid iwl_rxon_assoc_cmd field values
iwlagn 0000:01:00.0: Invalid RXON configuration.  Not committing.
Registered led device: iwl-phy40::radio
Registered led device: iwl-phy40::assoc
Registered led device: iwl-phy40::RX
Registered led device: iwl-phy40::TX
iwlagn 0000:01:00.0: check 52 fields 1 | 16
iwlagn 0000:01:00.0: check 52 CCK 2 | 16
iwlagn 0000:01:00.0: check mac addr 3 | 16
iwlagn 0000:01:00.0: check basic rate 4 | 17
iwlagn 0000:01:00.0: check assoc id 5 | 17
iwlagn 0000:01:00.0: check CCK and short slot 6 | 17
iwlagn 0000:01:00.0: check CCK & auto detect 7 | 17
iwlagn 0000:01:00.0: check TGG and auto detect 8 | 17
iwlagn 0000:01:00.0: Tuning to channel 0
iwlagn 0000:01:00.0: Not a valid iwl_rxon_assoc_cmd field values
iwlagn 0000:01:00.0: Invalid RXON configuration.  Not committing.
iwlagn 0000:01:00.0: Microcode SW error detected.  Restarting 0x2000000.
iwlagn 0000:01:00.0: Start IWL Error Log Dump:
iwlagn 0000:01:00.0: Status: 0x000213E6, count: 5
iwlagn 0000:01:00.0: Desc                               Time       data1     
data2      line
iwlagn 0000:01:00.0: SYSASSERT                    (#05) 0000016726 0x0000058B
0x00000000 1419
iwlagn 0000:01:00.0: blink1  blink2  ilink1  ilink2
iwlagn 0000:01:00.0: 0x0145A 0x01492 0x006DE 0x00000
iwlagn 0000:01:00.0: Start IWL Event Log Dump: display count 8, wraps 0
iwlagn 0000:01:00.0: EVT_LOGT:0000000000:0x0000023b:0117
iwlagn 0000:01:00.0: EVT_LOGT:0000000014:0x00000000:1208
iwlagn 0000:01:00.0: EVT_LOGT:0000009622:0x0400009b:0401
iwlagn 0000:01:00.0: EVT_LOGT:0000011791:0x0401009c:0401
iwlagn 0000:01:00.0: EVT_LOGT:0000011824:0x040200a4:0401
iwlagn 0000:01:00.0: EVT_LOGT:0000014508:0x04030077:0401
iwlagn 0000:01:00.0: EVT_LOGT:0000016725:0x04040097:0401
iwlagn 0000:01:00.0: EVT_LOGT:0000016732:0x00000000:0125
ieee80211 phy40: I iwl_irq_handle_error Restarting adapter due to uCode error.
PM: Finishing wakeup.
Restarting tasks ... done.

------- Comment #1 From ximin luo 2009-05-24 23:48:39 -------

retest it on 4965+32bit and also get WARNING next to firmware.

Test Environment
===============================================
Platform        :       Intel SDV M3M31
Wireless Card   :       Intel(R) WiFi Link 4965
OS              :       Redhat Fedora release 10 (Cambridge) 32bit
AP              :       Cisco 1250
uCode           :       iwlwifi-4965-2.ucode 228.57.2.23
Source          :       commit c612430a75805c0fb5d2b0339653567afa111ab6
                     (Fri May 22 14:17:56 2009)
Peer            :       Intel SDV M3M31

Part of log message
==============================================
iwlagn 0000:03:00.0: check 52 fields 1 | 16
iwlagn 0000:03:00.0: check 52 CCK 2 | 16
iwlagn 0000:03:00.0: check mac addr 3 | 16
iwlagn 0000:03:00.0: check basic rate 4 | 17
iwlagn 0000:03:00.0: check assoc id 5 | 17
iwlagn 0000:03:00.0: check CCK and short slot 6 | 17
iwlagn 0000:03:00.0: check CCK & auto detect 7 | 17
iwlagn 0000:03:00.0: check TGG and auto detect 8 | 17
iwlagn 0000:03:00.0: Tuning to channel 0
iwlagn 0000:03:00.0: Not a valid iwl_rxon_assoc_cmd field values
iwlagn 0000:03:00.0: Invalid RXON configuration.  Not committing.
iwlagn 0000:03:00.0: Microcode SW error detected.  Restarting 0x2000000.
iwlagn 0000:03:00.0: Start IWL Error Log Dump:
iwlagn 0000:03:00.0: Status: 0x000213E6, count: 5
iwlagn 0000:03:00.0: Desc                               Time       data1     
data2      line
iwlagn 0000:03:00.0: SYSASSERT                    (#05) 0000030225 0x0000058B
0x00000000 1419
iwlagn 0000:03:00.0: blink1  blink2  ilink1  ilink2
iwlagn 0000:03:00.0: 0x0145A 0x01492 0x006DE 0x00000
iwlagn 0000:03:00.0: Start IWL Event Log Dump: display count 9, wraps 0
iwlagn 0000:03:00.0: EVT_LOGT:0000000001:0x0000023b:0117
iwlagn 0000:03:00.0: EVT_LOGT:0000000014:0x00000000:1208
iwlagn 0000:03:00.0: EVT_LOGT:0000023473:0x0400009b:0401
iwlagn 0000:03:00.0: EVT_LOGT:0000025726:0x0401009c:0401
iwlagn 0000:03:00.0: EVT_LOGT:0000025760:0x040200a4:0401
iwlagn 0000:03:00.0: EVT_LOGT:0000027970:0x04030048:0401
iwlagn 0000:03:00.0: EVT_LOGT:0000028118:0x04040077:0401
iwlagn 0000:03:00.0: EVT_LOGT:0000030224:0x04050097:0401
iwlagn 0000:03:00.0: EVT_LOGT:0000030232:0x00000000:0125
ieee80211 phy0: I iwl_irq_handle_error Restarting adapter due to uCode error.
------------[ cut here ]------------
WARNING: at drivers/net/wireless/iwlwifi/iwl-core.c:2502
warn_slowpath_null+0x10/0x15()
Hardware name: Crestline & ICH8M Chipset
Modules linked in: iwlagn iwlcore rfkill mac80211 cfg80211 sco bridge stp bnep
l2cap bluetooth sunrpc ipv6 cpufreq_ondemand a
cpi_cpufreq dm_mirror dm_region_hash dm_log dm_multipath dm_mod uinput sr_mod
arc4 ecb cdrom video ac iTCO_wdt button output
i2c_i801 i2c_core iTCO_vendor_support e1000 battery pcspkr sg serio_raw
ata_generic ata_piix libata sd_mod scsi_mod ext3 jbd
mbcache uhci_hcd ohci_hcd ehci_hcd [last unloaded: cfg80211]
Pid: 2209, comm: bash Not tainted 2.6.30-rc6-wl #16
Call Trace:
 [<c04291c0>] warn_slowpath_fmt+0x72/0xa1
 [<c065d288>] ? __schedule+0x91b/0x973
 [<c0431133>] ? process_timeout+0x0/0xa
 [<fb2d46f4>] ? iwl_mac_start+0x10be/0x118b [iwlagn]
 [<c065d202>] ? __schedule+0x895/0x973
 [<c04291ff>] warn_slowpath_null+0x10/0x15
 [<fb11ee72>] iwl_bss_info_changed+0x85/0x6d7 [iwlcore]
 [<fb11eded>] ? iwl_bss_info_changed+0x0/0x6d7 [iwlcore]
 [<fae9a1e1>] ieee80211_bss_info_change_notify+0x121/0x150 [mac80211]
 [<faead739>] ieee80211_reconfig+0x1cb/0x2c0 [mac80211]
 [<c04258c8>] ? __cond_resched+0x25/0x3b
 [<faea677c>] ieee80211_resume+0x15/0x17 [mac80211]
 [<fa98f914>] wiphy_resume+0x4f/0x5d [cfg80211]
 [<c058a539>] device_resume+0xeb/0x29e
 [<c044c52f>] hibernation_snapshot+0x18d/0x1c5
 [<c044c613>] hibernate+0xac/0x17d
 [<c044b2c3>] ? state_store+0x0/0xa2
 [<c044b318>] state_store+0x55/0xa2
 [<c044b2c3>] ? state_store+0x0/0xa2
 [<c050afb9>] kobj_attr_store+0x1a/0x22
 [<c04cbb97>] sysfs_write_file+0xb4/0xdf
 [<c04cbae3>] ? sysfs_write_file+0x0/0xdf
 [<c048ed4c>] vfs_write+0x8a/0x12e
 [<c048ee89>] sys_write+0x3b/0x60
 [<c0402984>] sysenter_do_call+0x12/0x22
---[ end trace 1cd1ab54eeddaef1 ]---
PM: Image restored successfully.
Restarting tasks ... done.
PM: Basic memory bitmaps freed

------- Comment #2 From reinette chatre 2009-05-26 16:04:15 -------

Ximin,

It sounds as though this is easy for you to reproduce. Could you please rerun
your test with debug of 0x3? I would like to see the entire log (not just the
errors).

Could you please also try a test with the following patch reverted:

commit 3fc046d75ec6df93eccc27274e46dfdbca5f049d
Author: Johannes Berg <johannes@sipsolutions.net>
Date:   Tue May 19 15:27:15 2009 -0700

    iwlwifi: revamp bss_info_changed

------- Comment #3 From ximin luo 2009-05-26 22:35:40 -------

Created an attachment (id=2011) [details]
IWL_DL_INFO & IWL_DL_MAC80211 log

(In reply to comment #2)
Hi Reinette,
> It sounds as though this is easy for you to reproduce. Could you please rerun
> your test with debug of 0x3? I would like to see the entire log (not just the
> errors).
[Ximin] Please see attached file that is debug of 0x03 log.
> Could you please also try a test with the following patch reverted:
> commit 3fc046d75ec6df93eccc27274e46dfdbca5f049d
> Author: Johannes Berg <johannes@sipsolutions.net>
> Date:   Tue May 19 15:27:15 2009 -0700
>     iwlwifi: revamp bss_info_changed
[Ximin] After git-revert the upper patch, log does not print WARNING (at
drivers/net/wireless/iwlwifi/iwl-core.c:2502) but still prints firmware error.

------- Comment #4 From Abhijeet Kolekar 2009-05-29 14:31:53 -------

Created an attachment (id=2016) [details]
Try this patch.

Not Sure whether this is related to S3 resume. I am not able to test it here.
This may be one of the reasons before going to sleep and forgetting to sync
staging with active.

------- Comment #5 From ximin luo 2009-05-30 22:57:31 -------

(In reply to comment #4)
> Created an attachment (id=2016) [details] [details]
> Try this patch.
> Not Sure whether this is related to S3 resume. I am not able to test it here.
> This may be one of the reasons before going to sleep and forgetting to sync
> staging with active.

After applying your patch on commit ec5ef63589354c84243bd09742970df42478c3d3,
log does not print that message.

------- Comment #6 From ximin luo 2009-05-30 22:59:19 -------

Detailed Test Environment
===============================================
Platform        :       Intel SDV M3M31
Wireless Card   :       Intel(R) WiFi Link 4965
OS              :       Redhat Fedora release 10 (Cambridge) 64bit
AP              :       Cisco 1250
uCode           :       iwlwifi-4965-2.ucode 228.57.2.23
Source          :       ec5ef63589354c84243bd09742970df42478c3d3
                                         (Fri May 29 14:25:14 2009)

------- Comment #7 From Jeff Zheng 2009-06-01 16:59:35 -------

*** Bug 2007 has been marked as a duplicate of this bug. ***

------- Comment #8 From ximin luo 2009-06-01 19:54:31 -------

I retest it on 2.6.30-rc7-wl in BSS/IBSS mode and get different log. 

Testing Environment
==============================================
Platform        :       Intel SDV M3M41 
Wireless Card   :       Intel(R) WiFi Link 5100
OS              :       Redhat Fedora release 10 (Cambridge) 32bit
AP              :       Cisco 1250
uCode           :       iwlwifi-5000-2.ucode 8.24.2.12
Source          :       commit 3a3125607c0a32056666b37537fb5e980d0a0a7b
                     (Sat May 30 21:15:06 2009)
Peer            :       Intel SDV M3M31


After triggering S3 in BSS mode, I only see:

iwlagn 0000:02:00.0: check 52 fields 1 | 16
iwlagn 0000:02:00.0: check 52 CCK 2 | 16
iwlagn 0000:02:00.0: check mac addr 3 | 16
iwlagn 0000:02:00.0: check basic rate 4 | 17
iwlagn 0000:02:00.0: check assoc id 5 | 17
iwlagn 0000:02:00.0: check CCK and short slot 6 | 17
iwlagn 0000:02:00.0: check CCK & auto detect 7 | 17
iwlagn 0000:02:00.0: check TGG and auto detect 8 | 17
iwlagn 0000:02:00.0: Tuning to channel 0
iwlagn 0000:02:00.0: Not a valid iwl_rxon_assoc_cmd field values
iwlagn 0000:02:00.0: Invalid RXON configuration.  Not committing.
Registered led device: iwl-phy2::radio
Registered led device: iwl-phy2::assoc
Registered led device: iwl-phy2::RX
Registered led device: iwl-phy2::TX

If I test it on IBSS mode, log prints not only the above message also fw error:

 check 52 fields 1 | 16
iwlagn 0000:02:00.0: check 52 CCK 2 | 16
iwlagn 0000:02:00.0: check mac addr 3 | 16
iwlagn 0000:02:00.0: check basic rate 4 | 17
iwlagn 0000:02:00.0: check assoc id 5 | 17
iwlagn 0000:02:00.0: check CCK and short slot 6 | 17
iwlagn 0000:02:00.0: check CCK & auto detect 7 | 17
iwlagn 0000:02:00.0: check TGG and auto detect 8 | 17
iwlagn 0000:02:00.0: Tuning to channel 0
iwlagn 0000:02:00.0: Not a valid iwl_rxon_assoc_cmd field values
iwlagn 0000:02:00.0: Invalid RXON configuration.  Not committing.
iwlagn 0000:02:00.0: Microcode SW error detected.  Restarting 0x2000000.
iwlagn 0000:02:00.0: Start IWL Error Log Dump:
iwlagn 0000:02:00.0: Status: 0x000212E6, count: 5
iwlagn 0000:02:00.0: Desc                               Time       data1     
data2      line
iwlagn 0000:02:00.0: SYSASSERT                    (#05) 0568127728 0x00000001
0x00000000 1309
iwlagn 0000:02:00.0: blink1  blink2  ilink1  ilink2
iwlagn 0000:02:00.0: 0x0391A 0x0391A 0x008B2 0x00000
iwlagn 0000:02:00.0: Start IWL Event Log Dump: display count 86, wraps 0
iwlagn 0000:02:00.0: EVT_LOGT:0000000000:0x0000027a:0117
iwlagn 0000:02:00.0: EVT_LOGT:0000000007:0x00000325:1074
iwlagn 0000:02:00.0: EVT_LOGT:0000000023:0x00000000:1208
iwlagn 0000:02:00.0: EVT_LOGT:0000000890:0x0000007a:1501
iwlagn 0000:02:00.0: EVT_LOGT:0000000890:0x00000001:1527
iwlagn 0000:02:00.0: EVT_LOGT:0000000891:0x00000000:1527

------- Comment #9 From Abhijeet Kolekar 2009-06-08 10:04:13 -------

Looks like fixed in recent ABAT after the patch.

------- Comment #10 From ximin luo 2009-06-08 19:42:34 -------

Didn't see this issue on 2.6.30-rc8-wl, mark it as verified.