Mysterious hangs - cfg80211 - ath9k

Hi List,

I am experiencing a puzzling problem with WLAN on a Toshiba Qosmio F750 laptop, running CERN SLC 5.8 (mostly identical to RHEL 5.8), but with kernel 2.6.39.4. (The kernel that came with the distro did not work properly with WLAN on this machine at all.)

What happens is that the WLAN comes up flawlessly, and works well until it suddenly hangs. This happens when (or seconds after) I see an entry like the following in the log:

Jun 18 19:04:42 redcat kernel: cfg80211: Calling CRDA to update world regulatory domain

I do not understand why cfg80211 does this long after the connection has been established. If I understand correctly, this "regulatory domain" business only makes sense when the WLAN interface is started.

Subsequent DHCP requests are issued, but never answered:

Jun 18 19:23:38 redcat dhclient: DHCPREQUEST on wlan0 to 137.138.16.6 port 67 (xid=0x63998557)
Jun 18 19:24:16 redcat last message repeated 3 times
Jun 18 19:25:30 redcat last message repeated 6 times
.....
Jun 18 19:50:10 redcat dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67 (xid=0x63998557)
Jun 18 19:50:55 redcat last message repeated 3 times
.....
Jun 18 19:58:41 redcat dhclient: No DHCPOFFERS received.

I interpret this as something has (effectively) been turned off, but that the drivers do not realize this.

Restarting WLAN when the problem has occurred is simple:

root@redcat 97 # /sbin/ifdown wlan0
root@redcat 98 # /sbin/ifup wlan0

What puzzles me even more is that cfg80211 seems to be activated and mess up things at highly irregular intervals, ranging from a few minutes to many hours:

root@redcat 105 # tail -2000l /var/log/messages | grep cfg80211

Jun 17 20:28:51 redcat kernel: cfg80211: Calling CRDA to update world regulatory domain
Jun 17 23:09:37 redcat kernel: cfg80211: Calling CRDA to update world regulatory domain
Jun 17 23:36:01 redcat kernel: cfg80211: Calling CRDA to update world regulatory domain
Jun 18 09:27:59 redcat kernel: cfg80211: Calling CRDA to update world regulatory domain
Jun 18 11:57:48 redcat kernel: cfg80211: Calling CRDA to update world regulatory domain
Jun 18 18:42:00 redcat kernel: cfg80211: Calling CRDA to update world regulatory domain
Jun 18 18:46:49 redcat kernel: cfg80211: Calling CRDA to update world regulatory domain
Jun 18 19:04:42 redcat kernel: cfg80211: Calling CRDA to update world regulatory domain
Jun 18 22:40:42 redcat kernel: cfg80211: Calling CRDA to update world regulatory domain

At the time of writing this (Tue 19 Jun 2012 09:27:54 CEST) the WLAN has not stopped since the last entry in the above. What on earth is governing the timing in this?

Some relevant info on the laptop:

root@redcat 108 # lspci
.....
03:00.0 Network controller: Atheros Communications Inc. AR9285 Wireless Network Adapter (PCI-Express) (rev 01)
.....

root@redcat 109 # lsmod
Module Size Used by
.....

ath9k                  89934  0
mac80211              160999  1 ath9k
ath9k_common            3051  1 ath9k

.....
ath9k_hw 291258 2 ath9k,ath9k_common
ath 15289 2 ath9k,ath9k_hw
.....
cfg80211 141299 3 ath9k,mac80211,ath

Any ideas will be greatly appreciated. I will be happy to test patches. Please CC me at [email protected] since I am not on the list.

Regards,
-- Jon Wikne

please quickly try
http://linuxwireless.org/en/users/Download#Where_to_download_bleeding_edge

or the latest wireless testing tree
http://linuxwireless.org/en/developers/Documentation/git-guide#Cloning_latest_wireless-testing

thanks,
shafi

I tried to install compat-wireless-2012-05-10. It worked for 4½ hours, then same problem.

Maybe there is something wrong with my understanding here, but I do not see why the "cfg80211: Calling CRDA to update world regulatory domain" should occur hours after the connection has been established, and what triggers it, apparently at random....

Is there a reason to believe it could make a difference if I try this too?

Regards,
-- Jon Wikne

Now I downloaded this (more than 1GB), just to realize that it is a complete kernel tree for kernel 3.5.0-rc3. I don't really feel ready for an experimental upgrade from 2.6.39.4 to that right now....

With basis in compat-wireless-2012-05-10 I tried to comment out the call to call_crda in net/wireless/reg.c and return -EALREADY in line 1483, just to see if that circumvented the problem. It did not. The damage (whatever that might be) already seems to be done _before_ the call_crda is made in reg.c.

I am a bit at a loss as to how to proceed. There are several things i do not understand.

1) The call to update CRDA (even with my crude, experimental, dummy return) seems to cause no trouble when it is done the first time the line comes up. Could someone please explain to me what causes the subsequent calls at highly irregular intervals, and why that seems to be necessary or desirable?

2) Is this a known problem that is being worked on (in which case I will just shut up and wait), or am I the first to report it?

Thanks in advance for any further info or suggestions.

Regards,
-- Jon Wikne

Hi,

please provide the complete log. you can also enable ath9k debugging. sudo modprobe -v ath9k debug=0x601
http://linuxwireless.org/en/users/Drivers/ath9k/debug
so you need to bring the interface up/down to make it working right ? a recent fix, but not relevant to this i think
http://permalink.gmane.org/gmane.linux.kernel.wireless.general/92657

thanks,
shafi

There is nothing relevant in the regular logs apart from lines like these:

Jun 20 17:11:09 redcat kernel: cfg80211: Calling CRDA to update world regulatory domain
Jun 20 17:11:09 redcat kernel: ath9k 0000:03:00.0: PCI INT A -> GSI 18 (level, low) -> IRQ 18

when the WLAN comes up normally, and and an additional line like this:

Jun 20 17:42:32 redcat kernel: cfg80211: Calling CRDA to update world regulatory domain

when it fails / hangs at some unpredictable point in time later.

OK, done. I don't know when the error might reappear, but I will copy the /sys/kernel/debug/ieee80211/phy0/ tree and put on some server for forensics when it does. There is a lot of info there which I do not know how to interpret.

Regards,
-- Jon

ok, you can also post the complete logs, once the issues appears with ath9k debug messages

thanks,
shafi

Thanks.

It has been some months since I have had the possibility to pursue this issue now. The reason is that the problem occurs only shortly after a DHCP "lease" is renewed, and not _always_ but seemingly random. This means that when using this system on networks with long DHCP lease times, as I mostly do, the problem appears only rarely. However, with _short_ lease times, like the about 1500 seconds typically at the CERN WLAN network, the "Calling CRDA" hang appears more frequently, and does represent a significant problem.

Anyway, since June I have:

1) Upgraded to compat-wireless-2012-05-10, just in case the problem had been solved. No luck there! ;-)

2) Applied:

modprobe -v ath9k debug=0x601
mount -t debugfs debugfs /sys/kernel/debug/

when using the driver.

When the problem occurs, I still se no other WLAN related messages in the ordinary log files than:

Oct  9 23:02:55 redcat kernel: wlan0: authenticate with 00:20:a6:b0:c1:0e
Oct  9 23:02:55 redcat kernel: wlan0: send auth to 00:20:a6:b0:c1:0e (try 1/3)
Oct  9 23:02:55 redcat kernel: wlan0: authenticated
Oct  9 23:02:55 redcat kernel: ath9k 0000:03:00.0: wlan0: disabling HT as WMM/QoS is not supported by the AP
Oct  9 23:02:55 redcat kernel: ath9k 0000:03:00.0: wlan0: disabling VHT as WMM/QoS is not supported by the AP
Oct  9 23:02:55 redcat kernel: wlan0: associate with 00:20:a6:b0:c1:0e (try 1/3)
Oct  9 23:02:55 redcat kernel: wlan0: RX AssocResp from 00:20:a6:b0:c1:0e (capab=0x421 status=0 aid=5)
Oct  9 23:02:55 redcat kernel: wlan0: associated
Oct  9 23:02:55 redcat dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67 (xid=0x7913599d)
Oct  9 23:02:55 redcat dhclient: DHCPACK from 137.138.16.6 (xid=0x7913599d)
Oct  9 23:02:55 redcat avahi-daemon[3736]: New relevant interface wlan0.IPv4 for mDNS.
Oct  9 23:02:55 redcat avahi-daemon[3736]: Joining mDNS multicast group on interface wlan0.IPv4 with address 128.141.230.110.
Oct  9 23:02:55 redcat avahi-daemon[3736]: Registering new address record for 128.141.230.110 on wlan0.
Oct  9 23:02:55 redcat NET[12486]: /sbin/dhclient-script : updated /etc/resolv.conf
Oct  9 23:02:55 redcat dhclient: bound to 128.141.230.110 -- renewal in 1590 seconds.
Oct  9 23:29:25 redcat dhclient: DHCPREQUEST on wlan0 to 137.138.16.6 port 67 (xid=0x7913599d)
Oct  9 23:29:25 redcat dhclient: DHCPACK from 137.138.16.6 (xid=0x7913599d)
Oct  9 23:29:25 redcat dhclient: bound to 128.141.230.110 -- renewal in 1488 seconds.
Oct  9 23:54:13 redcat dhclient: DHCPREQUEST on wlan0 to 137.138.16.6 port 67 (xid=0x7913599d)
Oct  9 23:54:13 redcat dhclient: DHCPACK from 137.138.16.6 (xid=0x7913599d)
Oct  9 23:54:13 redcat dhclient: bound to 128.141.230.110 -- renewal in 1579 seconds.
Oct  9 23:57:00 redcat kernel: cfg80211: Calling CRDA to update world regulatory domain

After the last message here, the WLAN hangs. There is also a message about the DRDA in dmesg, but nothing else.

Subsequently, as for WLAN related messages, I see only:

Oct 10 00:20:32 redcat dhclient: DHCPREQUEST on wlan0 to 137.138.16.6 port 67 (xid=0x7913599d)
Oct 10 00:21:19 redcat last message repeated 4 times
Oct 10 00:22:23 redcat last message repeated 5 times

until I restart WLAN, i.e.

/sbin/ifdown wlan0
/sbin/ifup wlan0

I have prepared two files with the content of all the files in the directory

/sys/kernel/debug/ieee80211/phy0/ath9k/

for "forensics", one when the system functions normally, and one when the problem is there. These can be downloaded here:

http://shaimina.wikne.no/jon/ath9k/

The only (to me) obvious difference is in:

/sys/kernel/debug/ieee80211/phy0/ath9k/stations

which is practically blank when the CRDA error is present.

To me, it might seem that the WLAN chip (AR9285 in my case) has been effectively turned off....

Please CC me if posting a reply. I'm not on the list.

Regards,
-- Jon Wikne