[BUG] iwl4965: huge latency and errors when unblocking the hardware rfkill

[BUG] iwl4965: huge latency and errors when unblocking the hardware rfkill

[Andrew Lutomirski]

This is wireless-testing c80200cd38c265da90f0d9d031ace84aa56b0453, pulled today.

I have a Lenovo X61s with a physical rfkill switch (the kind that
slides between blocked and unblocked).

If I turn off the hardware rfkill switch (set to block) while
associated, I lose the connection (obviously).  If I turn it back on
again (set to unblock), I get a lot of latency (my mouse stops moving
for a second or two) and I sometimes get errors in the syslog like
this:

iwl4965: Error sending REPLY_CT_KILL_CONFIG_CMD: time out after 500ms.

The card fails to associate afterwards.  If I tell network-manager to
turn off wireless, then block rfkill, then wait a few seconds, then
unblock it, then turn nm back on, everything works again.

This seems like at least two different bugs:

 - iwl4965 causes latency.  This latency issue has been reproducible
every time for me on 2.6.24-ubuntu_something, 2.5.25, wireless-compat
(recent), and current wireless-testing.
 - iwl4965 doesn't work right after hard unblocking rfkill.

I'm happy to do further troubleshooting and/or test patches.

--Andy

Re: [BUG] iwl4965: huge latency and errors when unblocking the hardware rfkill

[Dan Williams]

On Mon, 2008-07-07 at 14:56 -0400, Andrew Lutomirski wrote:
> This is wireless-testing c80200cd38c265da90f0d9d031ace84aa56b0453, pulled today.
> 
> I have a Lenovo X61s with a physical rfkill switch (the kind that
> slides between blocked and unblocked).
> 
> If I turn off the hardware rfkill switch (set to block) while
> associated, I lose the connection (obviously).  If I turn it back on
> again (set to unblock), I get a lot of latency (my mouse stops moving
> for a second or two) and I sometimes get errors in the syslog like
> this:
> 
> iwl4965: Error sending REPLY_CT_KILL_CONFIG_CMD: time out after 500ms.
> 
> The card fails to associate afterwards.  If I tell network-manager to
> turn off wireless, then block rfkill, then wait a few seconds, then
> unblock it, then turn nm back on, everything works again.
> 
> This seems like at least two different bugs:
> 
>  - iwl4965 causes latency.  This latency issue has been reproducible
> every time for me on 2.6.24-ubuntu_something, 2.5.25, wireless-compat
> (recent), and current wireless-testing.
>  - iwl4965 doesn't work right after hard unblocking rfkill.
> 
> I'm happy to do further troubleshooting and/or test patches.

It depends on what HAL reports for the killswitch's status.  NM asks HAL
what the radio's rfkill state is every 6 seconds (since we can't get
event notifications when the state changes until 2.6.27).  If HAL
reports the radio is killed, NM won't touch the device.  It sounds like
something is trying to poke the device before it's ready, which may mean
that either NM isn't aware you have a killswitch, or HAL isn't correctly
talking to the iwlwifi killswitch bits (either old-style or new-style
with Henrique's patches).

Can you post some logs from /var/log/daemon.log around when flipping the
killswitch to BLOCKED, waiting about 20 seconds, then flipping it back
to UNBLOCKED and waiting 10 seconds?  That will tell whether NM is
correctly talking to HAL or not.

Dan

Re: [BUG] iwl4965: huge latency and errors when unblocking the hardware rfkill

[Andrew Lutomirski]

[-- Attachment #1: Type: text/plain, Size: 3782 bytes --]

On Mon, Jul 7, 2008 at 3:45 PM, Dan Williams <dcbw@redhat.com> wrote:
> On Mon, 2008-07-07 at 14:56 -0400, Andrew Lutomirski wrote:
>> This is wireless-testing c80200cd38c265da90f0d9d031ace84aa56b0453, pulled today.
>>
>> I have a Lenovo X61s with a physical rfkill switch (the kind that
>> slides between blocked and unblocked).
>>
>> If I turn off the hardware rfkill switch (set to block) while
>> associated, I lose the connection (obviously).  If I turn it back on
>> again (set to unblock), I get a lot of latency (my mouse stops moving
>> for a second or two) and I sometimes get errors in the syslog like
>> this:
>>
>> iwl4965: Error sending REPLY_CT_KILL_CONFIG_CMD: time out after 500ms.
>>
>> The card fails to associate afterwards.  If I tell network-manager to
>> turn off wireless, then block rfkill, then wait a few seconds, then
>> unblock it, then turn nm back on, everything works again.
>>
>> This seems like at least two different bugs:
>>
>>  - iwl4965 causes latency.  This latency issue has been reproducible
>> every time for me on 2.6.24-ubuntu_something, 2.5.25, wireless-compat
>> (recent), and current wireless-testing.
>>  - iwl4965 doesn't work right after hard unblocking rfkill.
>>
>> I'm happy to do further troubleshooting and/or test patches.
>
> It depends on what HAL reports for the killswitch's status.  NM asks HAL
> what the radio's rfkill state is every 6 seconds (since we can't get
> event notifications when the state changes until 2.6.27).  If HAL
> reports the radio is killed, NM won't touch the device.  It sounds like
> something is trying to poke the device before it's ready, which may mean
> that either NM isn't aware you have a killswitch, or HAL isn't correctly
> talking to the iwlwifi killswitch bits (either old-style or new-style
> with Henrique's patches).

OK.  But IMO iwl4965 should still avoid freaking out when this happens.

>
> Can you post some logs from /var/log/daemon.log around when flipping the
> killswitch to BLOCKED, waiting about 20 seconds, then flipping it back
> to UNBLOCKED and waiting 10 seconds?  That will tell whether NM is
> correctly talking to HAL or not.

Attached.  While the connection was failing to happen after
re-enabling the radio, dmesg showed a lot of crap like:

[ 4514.797450] wlan0: authenticated
[ 4514.797450] wlan0: associate with AP 00:11:88:06:72:98
[ 4514.800735] wlan0: RX ReassocResp from 00:11:88:06:72:98
(capab=0x401 status=0 aid=164)
[ 4514.800743] wlan0: associated
[ 4516.834866] wlan0: No ProbeResp from current AP 00:11:88:06:72:98 -
assume out of range
[ 4519.235695] wlan0: no IPv6 routers present
[ 4520.865993] wlan0: authenticate with AP 00:11:88:06:72:98
[ 4520.870660] wlan0: authenticated
[ 4520.870660] wlan0: associate with AP 00:11:88:06:72:98
[ 4520.873867] wlan0: RX ReassocResp from 00:11:88:06:72:98
(capab=0x401 status=0 aid=164)
[ 4520.873867] wlan0: associated
[ 4522.890579] wlan0: No ProbeResp from current AP 00:11:88:06:72:98 -
assume out of range
[ 4526.909697] wlan0: authenticate with AP 00:11:88:06:72:98
[ 4526.917697] wlan0: authenticate with AP 00:11:88:06:72:98
[ 4526.917697] wlan0: authenticated
[ 4526.917697] wlan0: associate with AP 00:11:88:06:72:98
[ 4526.921697] wlan0: RX ReassocResp from 00:11:88:06:72:98
(capab=0x401 status=0 aid=164)
[ 4526.921697] wlan0: associated
[ 4528.953389] wlan0: No ProbeResp from current AP 00:11:88:06:72:98 -
assume out of range
[ 4533.066068] wlan0: authenticate with AP 00:11:88:06:72:98
[ 4533.070907] wlan0: authenticate with AP 00:11:88:06:72:98
[ 4533.070907] wlan0: authenticated
[ 4533.070907] wlan0: associate with AP 00:11:88:06:72:98
[ 4533.074906] wlan0: RX ReassocResp from 00:11:88:06:72:98
(capab=0x401 status=0 aid=164)
[ 4533.074906] wlan0: associated

--Andy

>
> Dan
>
>

[-- Attachment #2: rfkill.txt --]
[-- Type: text/plain, Size: 29076 bytes --]

--- Switch to blocked ---

Jul  7 15:51:20 phlogiston hcid[6063]: HCI dev 0 down
Jul  7 15:51:20 phlogiston hcid[6063]: Stopping security manager 0
Jul  7 15:51:20 phlogiston hcid[6063]: Device hci0 has been disabled
Jul  7 15:51:21 phlogiston hcid[6063]: HCI dev 0 unregistered
Jul  7 15:51:21 phlogiston hcid[6063]: Unregister path: /org/bluez/hci0
Jul  7 15:51:21 phlogiston hcid[6063]: Device hci0 has been removed
Jul  7 15:51:21 phlogiston NetworkManager: <debug> [1215460281.122917] nm_hal_device_removed(): Device removed (hal udi is '/org/freedesktop/Hal/devices/usb_device_a5c_2110_noserial_if0_bluetooth_hci_1fe1ee067b'). 
Jul  7 15:51:21 phlogiston NetworkManager: <debug> [1215460281.126580] nm_hal_device_removed(): Device removed (hal udi is '/org/freedesktop/Hal/devices/usb_device_a5c_2110_noserial_if0'). 
Jul  7 15:51:21 phlogiston NetworkManager: <debug> [1215460281.129545] nm_hal_device_removed(): Device removed (hal udi is '/org/freedesktop/Hal/devices/usb_device_a5c_2110_noserial_if1'). 
Jul  7 15:51:21 phlogiston NetworkManager: <debug> [1215460281.134001] nm_hal_device_removed(): Device removed (hal udi is '/org/freedesktop/Hal/devices/usb_device_a5c_2110_noserial_if2'). 
Jul  7 15:51:21 phlogiston NetworkManager: <debug> [1215460281.138517] nm_hal_device_removed(): Device removed (hal udi is '/org/freedesktop/Hal/devices/usb_device_a5c_2110_noserial_if3'). 
Jul  7 15:51:21 phlogiston NetworkManager: <debug> [1215460281.142934] nm_hal_device_removed(): Device removed (hal udi is '/org/freedesktop/Hal/devices/usb_device_a5c_2110_noserial'). 
Jul  7 15:51:25 phlogiston NetworkManager: <info>  Supplicant state changed: 0 
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: Registering new address record for 18.74.7.143 on wlan0.IPv4.
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: Registering new address record for 18.74.7.143 on wlan0.IPv4.
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: Registering new address record for 18.74.7.143 on wlan0.IPv4.
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:51:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:51:28 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:51:28 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:51:28 phlogiston avahi-daemon[5729]: Registering new address record for 18.74.7.143 on wlan0.IPv4.
Jul  7 15:51:28 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:51:28 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:51:45 phlogiston NetworkManager: <info>  wlan0: link timed out. 
Jul  7 15:51:45 phlogiston NetworkManager: <info>  SWITCH: found better connection 'wlan0/MIT' than current connection 'wlan0/MIT'.  same_ssid=1, have_link=0 
Jul  7 15:51:45 phlogiston NetworkManager: <info>  Will activate connection 'wlan0/MIT'. 
Jul  7 15:51:45 phlogiston NetworkManager: <info>  Device wlan0 activation scheduled... 
Jul  7 15:51:45 phlogiston NetworkManager: <info>  Deactivating device wlan0. 
Jul  7 15:51:45 phlogiston dhclient: There is already a pid file /var/run/dhclient.wlan0.pid with pid 6215
Jul  7 15:51:45 phlogiston dhclient: killed old client process, removed PID file
Jul  7 15:51:45 phlogiston dhclient: wmaster0: unknown hardware address type 801
Jul  7 15:51:45 phlogiston dhclient: wmaster0: unknown hardware address type 801
Jul  7 15:51:45 phlogiston dhclient: DHCPRELEASE on wlan0 to 18.7.21.127 port 67
Jul  7 15:51:45 phlogiston avahi-daemon[5729]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 18.74.7.143.
Jul  7 15:51:45 phlogiston avahi-daemon[5729]: Interface wlan0.IPv4 no longer relevant for mDNS.
Jul  7 15:51:46 phlogiston ntpd[6789]: sendto(91.189.94.4) (fd=21): Invalid argument
Jul  7 15:51:46 phlogiston NetworkManager: <info>  Activation (wlan0) started... 
Jul  7 15:51:46 phlogiston NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... 
Jul  7 15:51:46 phlogiston NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started... 
Jul  7 15:51:46 phlogiston NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... 
Jul  7 15:51:46 phlogiston NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. 
Jul  7 15:51:46 phlogiston NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting... 
Jul  7 15:51:46 phlogiston NetworkManager: <info>  Activation (wlan0/wireless): access point 'MIT' is unencrypted, no key needed. 
Jul  7 15:51:46 phlogiston NetworkManager: <info>  DHCP daemon state is now 14 (normal exit) for interface wlan0 
Jul  7 15:51:46 phlogiston NetworkManager: <info>  DHCP daemon state is now 11 (unknown) for interface wlan0 
Jul  7 15:51:46 phlogiston NetworkManager: <info>  DHCP daemon state is now 14 (normal exit) for interface wlan0 
Jul  7 15:51:47 phlogiston ntpd[6789]: sendto(209.67.219.106) (fd=21): Invalid argument
Jul  7 15:51:48 phlogiston NetworkManager: <info>  SUP: sending command 'INTERFACE_ADD wlan0^I^Iwext^I/var/run/wpa_supplicant0^I' 
Jul  7 15:51:48 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:51:48 phlogiston NetworkManager: <info>  SUP: response was 'OK' 
Jul  7 15:51:48 phlogiston NetworkManager: <info>  SUP: sending command 'AP_SCAN 1' 
Jul  7 15:51:48 phlogiston NetworkManager: <info>  SUP: response was 'OK' 
Jul  7 15:51:48 phlogiston NetworkManager: <info>  SUP: sending command 'ADD_NETWORK' 
Jul  7 15:51:48 phlogiston NetworkManager: <info>  SUP: response was '0' 
Jul  7 15:51:48 phlogiston NetworkManager: <info>  SUP: sending command 'SET_NETWORK 0 ssid 4d4954' 
Jul  7 15:51:48 phlogiston NetworkManager: <info>  SUP: response was 'OK' 
Jul  7 15:51:48 phlogiston NetworkManager: <info>  SUP: sending command 'SET_NETWORK 0 key_mgmt NONE' 
Jul  7 15:51:48 phlogiston NetworkManager: <info>  SUP: response was 'OK' 
Jul  7 15:51:48 phlogiston NetworkManager: <info>  SUP: sending command 'ENABLE_NETWORK 0' 
Jul  7 15:51:48 phlogiston NetworkManager: <info>  SUP: response was 'OK' 
Jul  7 15:51:48 phlogiston NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete. 

--- Switch to unblocked.  Nasty latency within a couple seconds. ---

Jul  7 15:52:06 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:06 phlogiston last message repeated 5 times
Jul  7 15:52:06 phlogiston NetworkManager: <info>  Supplicant state changed: 1 
Jul  7 15:52:06 phlogiston NetworkManager: <info>  Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to access point 'MIT'. 
Jul  7 15:52:06 phlogiston NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled. 
Jul  7 15:52:06 phlogiston NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) started... 
Jul  7 15:52:06 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:07 phlogiston NetworkManager: <info>  Activation (wlan0) Beginning DHCP transaction. 
Jul  7 15:52:07 phlogiston NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete. 
Jul  7 15:52:07 phlogiston dhclient: There is already a pid file /var/run/dhclient.wlan0.pid with pid 0
Jul  7 15:52:07 phlogiston dhclient: wmaster0: unknown hardware address type 801
Jul  7 15:52:07 phlogiston NetworkManager: <info>  DHCP daemon state is now 12 (successfully started) for interface wlan0 
Jul  7 15:52:08 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:08 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:08 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:08 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:08 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:08 phlogiston NetworkManager: <info>  Supplicant state changed: 0 
Jul  7 15:52:09 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:09 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:09 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:09 phlogiston dhclient: wmaster0: unknown hardware address type 801
Jul  7 15:52:09 phlogiston NetworkManager: <info>  DHCP daemon state is now 1 (starting) for interface wlan0 
Jul  7 15:52:10 phlogiston dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 3
Jul  7 15:52:13 phlogiston dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 5
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:13 phlogiston NetworkManager: <info>  Old device 'wlan0' activating, won't change. 
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:13 phlogiston NetworkManager: <info>  Supplicant state changed: 1 
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:13 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:15 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:15 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:15 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:15 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:15 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:15 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:15 phlogiston NetworkManager: <info>  Supplicant state changed: 0 
Jul  7 15:52:15 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:15 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:15 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:18 phlogiston dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 11
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:19 phlogiston NetworkManager: <info>  Old device 'wlan0' activating, won't change. 
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:19 phlogiston NetworkManager: <info>  Supplicant state changed: 1 
Jul  7 15:52:19 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:21 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:21 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:21 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:21 phlogiston NetworkManager: <info>  Supplicant state changed: 0 
Jul  7 15:52:21 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:21 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:21 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:25 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:25 phlogiston NetworkManager: <info>  Supplicant state changed: 1 
Jul  7 15:52:25 phlogiston NetworkManager: <info>  Old device 'wlan0' activating, won't change. 
Jul  7 15:52:29 phlogiston dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 13
Jul  7 15:52:29 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:29 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:29 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:29 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:29 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:29 phlogiston NetworkManager: <info>  Supplicant state changed: 0 
Jul  7 15:52:29 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:29 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:29 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:29 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:33 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:33 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:33 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:33 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:33 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:33 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:33 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:33 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:33 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:33 phlogiston NetworkManager: <info>  Old device 'wlan0' activating, won't change. 
Jul  7 15:52:34 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:34 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:34 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:34 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:34 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:34 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:34 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:34 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:34 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:34 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:52:34 phlogiston NetworkManager: <info>  Supplicant state changed: 1 
Jul  7 15:52:34 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:52:34 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:52:38 phlogiston NetworkManager: <info>  Old device 'wlan0' activating, won't change. 
Jul  7 15:52:42 phlogiston dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 8
Jul  7 15:52:50 phlogiston dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 7
Jul  7 15:52:52 phlogiston ntpd[6789]: sendto(91.189.94.4) (fd=21): Invalid argument
Jul  7 15:52:52 phlogiston ntpd[6789]: sendto(209.67.219.106) (fd=21): Invalid argument
Jul  7 15:52:57 phlogiston dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 11
Jul  7 15:53:08 phlogiston dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 3
Jul  7 15:53:11 phlogiston dhclient: No DHCPOFFERS received.
Jul  7 15:53:11 phlogiston avahi-autoipd(wlan0)[15995]: Found user 'avahi-autoipd' (UID 105) and group 'avahi-autoipd' (GID 113).
Jul  7 15:53:11 phlogiston avahi-autoipd(wlan0)[15995]: Successfully called chroot().
Jul  7 15:53:11 phlogiston avahi-autoipd(wlan0)[15995]: Successfully dropped root privileges.
Jul  7 15:53:11 phlogiston avahi-autoipd(wlan0)[15995]: Starting with address 169.254.8.246
Jul  7 15:53:16 phlogiston avahi-autoipd(wlan0)[15995]: Callout BIND, address 169.254.8.246 on interface wlan0
Jul  7 15:53:16 phlogiston avahi-daemon[5729]: Joining mDNS multicast group on interface wlan0.IPv4 with address 169.254.8.246.
Jul  7 15:53:16 phlogiston avahi-daemon[5729]: New relevant interface wlan0.IPv4 for mDNS.
Jul  7 15:53:16 phlogiston avahi-daemon[5729]: Registering new address record for 169.254.8.246 on wlan0.IPv4.
Jul  7 15:53:16 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:53:20 phlogiston avahi-autoipd(wlan0)[15995]: Successfully claimed IP address 169.254.8.246
Jul  7 15:53:20 phlogiston NetworkManager: <info>  DHCP daemon state is now 9 (fail) for interface wlan0 
Jul  7 15:53:20 phlogiston NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Timeout) started... 
Jul  7 15:53:20 phlogiston NetworkManager: <info>  Activation (wlan0) failure scheduled... 
Jul  7 15:53:20 phlogiston NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Timeout) complete. 
Jul  7 15:53:20 phlogiston NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Timeout) scheduled... 
Jul  7 15:53:20 phlogiston NetworkManager: <info>  DHCP daemon state is now 14 (normal exit) for interface wlan0 
Jul  7 15:53:20 phlogiston NetworkManager: <info>  Activation (wlan0) failed for access point (MIT) 
Jul  7 15:53:20 phlogiston NetworkManager: <info>  Activation (wlan0) failed. 
Jul  7 15:53:20 phlogiston NetworkManager: <info>  Deactivating device wlan0. 
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: Registering new address record for 169.254.8.246 on wlan0.IPv4.
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: Registering new address record for 169.254.8.246 on wlan0.IPv4.
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: Registering new address record for fe80::21f:3bff:fe99:6ef9 on wlan0.*.
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: Registering new address record for 169.254.8.246 on wlan0.IPv4.
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_address() failed: Not permitted
Jul  7 15:53:20 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:53:21 phlogiston NetworkManager: nm_utils_supplicant_request_with_check: assertion `ctrl != NULL' failed
Jul  7 15:53:21 phlogiston NetworkManager: <WARN>  nm_device_802_11_wireless_scan(): (wlan0): could not trigger wireless scan 
Jul  7 15:53:21 phlogiston avahi-daemon[5729]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 169.254.8.246.
Jul  7 15:53:21 phlogiston avahi-daemon[5729]: Interface wlan0.IPv4 no longer relevant for mDNS.
Jul  7 15:53:26 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:53:40 phlogiston last message repeated 2 times
Jul  7 15:53:55 phlogiston ntpd[6789]: sendto(91.189.94.4) (fd=21): Invalid argument
Jul  7 15:53:58 phlogiston ntpd[6789]: sendto(209.67.219.106) (fd=21): Invalid argument
Jul  7 15:54:10 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:54:39 phlogiston ntpd[6789]: Deleting interface #3 wlan0, fe80::21f:3bff:fe99:6ef9#123, interface stats: received=0, sent=0, dropped=0, active_time=301 secs
Jul  7 15:54:39 phlogiston ntpd[6789]: Deleting interface #5 wlan0, 18.74.7.143#123, interface stats: received=4, sent=4, dropped=6, active_time=301 secs
Jul  7 15:54:40 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:55:10 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted
Jul  7 15:55:40 phlogiston avahi-daemon[5729]: iface.c: avahi_server_add_service() failed: Not permitted

Re: [BUG] iwl4965: huge latency and errors when unblocking the hardware rfkill

[Tomas Winkler]

On Mon, Jul 7, 2008 at 9:56 PM, Andrew Lutomirski <andy@luto.us> wrote:
> This is wireless-testing c80200cd38c265da90f0d9d031ace84aa56b0453, pulled today.
>
> I have a Lenovo X61s with a physical rfkill switch (the kind that
> slides between blocked and unblocked).
>
> If I turn off the hardware rfkill switch (set to block) while
> associated, I lose the connection (obviously).  If I turn it back on
> again (set to unblock), I get a lot of latency (my mouse stops moving
> for a second or two) and I sometimes get errors in the syslog like
> this:
>
> iwl4965: Error sending REPLY_CT_KILL_CONFIG_CMD: time out after 500ms.
>
> The card fails to associate afterwards.  If I tell network-manager to
> turn off wireless, then block rfkill, then wait a few seconds, then
> unblock it, then turn nm back on, everything works again.
>
> This seems like at least two different bugs:
>
>  - iwl4965 causes latency.  This latency issue has been reproducible
> every time for me on 2.6.24-ubuntu_something, 2.5.25, wireless-compat
> (recent), and current wireless-testing.
>  - iwl4965 doesn't work right after hard unblocking rfkill.
>
> I'm happy to do further troubleshooting and/or test patches.
>
> --Andy
> --
> To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>
We have few RF kill fixes, just need to rebase them again after latest
Henrique's patches. Hope to post them in next days.
Thanks
Tomas

Re: [BUG] iwl4965: huge latency and errors when unblocking the hardware rfkill

[Dan Williams]

On Mon, 2008-07-07 at 16:01 -0400, Andrew Lutomirski wrote:
> On Mon, Jul 7, 2008 at 3:45 PM, Dan Williams <dcbw@redhat.com> wrote:
> > On Mon, 2008-07-07 at 14:56 -0400, Andrew Lutomirski wrote:
> >> This is wireless-testing c80200cd38c265da90f0d9d031ace84aa56b0453, pulled today.
> >>
> >> I have a Lenovo X61s with a physical rfkill switch (the kind that
> >> slides between blocked and unblocked).
> >>
> >> If I turn off the hardware rfkill switch (set to block) while
> >> associated, I lose the connection (obviously).  If I turn it back on
> >> again (set to unblock), I get a lot of latency (my mouse stops moving
> >> for a second or two) and I sometimes get errors in the syslog like
> >> this:
> >>
> >> iwl4965: Error sending REPLY_CT_KILL_CONFIG_CMD: time out after 500ms.
> >>
> >> The card fails to associate afterwards.  If I tell network-manager to
> >> turn off wireless, then block rfkill, then wait a few seconds, then
> >> unblock it, then turn nm back on, everything works again.
> >>
> >> This seems like at least two different bugs:
> >>
> >>  - iwl4965 causes latency.  This latency issue has been reproducible
> >> every time for me on 2.6.24-ubuntu_something, 2.5.25, wireless-compat
> >> (recent), and current wireless-testing.
> >>  - iwl4965 doesn't work right after hard unblocking rfkill.
> >>
> >> I'm happy to do further troubleshooting and/or test patches.
> >
> > It depends on what HAL reports for the killswitch's status.  NM asks HAL
> > what the radio's rfkill state is every 6 seconds (since we can't get
> > event notifications when the state changes until 2.6.27).  If HAL
> > reports the radio is killed, NM won't touch the device.  It sounds like
> > something is trying to poke the device before it's ready, which may mean
> > that either NM isn't aware you have a killswitch, or HAL isn't correctly
> > talking to the iwlwifi killswitch bits (either old-style or new-style
> > with Henrique's patches).
> 
> OK.  But IMO iwl4965 should still avoid freaking out when this happens.
> 
> >
> > Can you post some logs from /var/log/daemon.log around when flipping the
> > killswitch to BLOCKED, waiting about 20 seconds, then flipping it back
> > to UNBLOCKED and waiting 10 seconds?  That will tell whether NM is
> > correctly talking to HAL or not.
> 
> Attached.  While the connection was failing to happen after
> re-enabling the radio, dmesg showed a lot of crap like:
> 
> [ 4514.797450] wlan0: authenticated
> [ 4514.797450] wlan0: associate with AP 00:11:88:06:72:98
> [ 4514.800735] wlan0: RX ReassocResp from 00:11:88:06:72:98
> (capab=0x401 status=0 aid=164)
> [ 4514.800743] wlan0: associated
> [ 4516.834866] wlan0: No ProbeResp from current AP 00:11:88:06:72:98 -
> assume out of range

This doesn't look like /var/log/daemon.log...

Dan

Re: [BUG] iwl4965: huge latency and errors when unblocking the hardware rfkill

[Holger Schurig]

> This doesn't look like /var/log/daemon.log...

Dan, he posted something inline and something as attachment.

Re: [BUG] iwl4965: huge latency and errors when unblocking the hardware rfkill

[Dan Williams]

On Mon, 2008-07-07 at 16:01 -0400, Andrew Lutomirski wrote:
> On Mon, Jul 7, 2008 at 3:45 PM, Dan Williams <dcbw@redhat.com> wrote:
> > On Mon, 2008-07-07 at 14:56 -0400, Andrew Lutomirski wrote:
> >> This is wireless-testing c80200cd38c265da90f0d9d031ace84aa56b0453, pulled today.
> >>
> >> I have a Lenovo X61s with a physical rfkill switch (the kind that
> >> slides between blocked and unblocked).
> >>
> >> If I turn off the hardware rfkill switch (set to block) while
> >> associated, I lose the connection (obviously).  If I turn it back on
> >> again (set to unblock), I get a lot of latency (my mouse stops moving
> >> for a second or two) and I sometimes get errors in the syslog like
> >> this:
> >>
> >> iwl4965: Error sending REPLY_CT_KILL_CONFIG_CMD: time out after 500ms.
> >>
> >> The card fails to associate afterwards.  If I tell network-manager to
> >> turn off wireless, then block rfkill, then wait a few seconds, then
> >> unblock it, then turn nm back on, everything works again.
> >>
> >> This seems like at least two different bugs:
> >>
> >>  - iwl4965 causes latency.  This latency issue has been reproducible
> >> every time for me on 2.6.24-ubuntu_something, 2.5.25, wireless-compat
> >> (recent), and current wireless-testing.
> >>  - iwl4965 doesn't work right after hard unblocking rfkill.
> >>
> >> I'm happy to do further troubleshooting and/or test patches.
> >
> > It depends on what HAL reports for the killswitch's status.  NM asks HAL
> > what the radio's rfkill state is every 6 seconds (since we can't get
> > event notifications when the state changes until 2.6.27).  If HAL
> > reports the radio is killed, NM won't touch the device.  It sounds like
> > something is trying to poke the device before it's ready, which may mean
> > that either NM isn't aware you have a killswitch, or HAL isn't correctly
> > talking to the iwlwifi killswitch bits (either old-style or new-style
> > with Henrique's patches).
> 
> OK.  But IMO iwl4965 should still avoid freaking out when this happens.
> 
> >
> > Can you post some logs from /var/log/daemon.log around when flipping the
> > killswitch to BLOCKED, waiting about 20 seconds, then flipping it back
> > to UNBLOCKED and waiting 10 seconds?  That will tell whether NM is
> > correctly talking to HAL or not.
> 
> Attached.  While the connection was failing to happen after
> re-enabling the radio, dmesg showed a lot of crap like:

Ok, so with the patches HAL no longer knows about the killswitch and NM
is unable to poll the switch for the radio state.  So NM doesn't stop
trying to poke the radio and connect to stuff because it doesn't know
the radio is off.

Yes, iwlwifi shouldn't freak out.  We also need to get HAL fixed up to
recognize the new rfkill stuff as a switch.

Dan