Bug 469906

Summary: mac80211-phy0: failed to remove key (0, 00:19:77:00:4f:f4) from hardware (-22)
Product: [Fedora] Fedora Reporter: Tom London <selinux>
Component: kernelAssignee: John W. Linville <linville>
Status: CLOSED RAWHIDE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: medium    
Version: 10CC: dongpo.liu, kernel-maint, quintela
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2009-01-22 19:17:12 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 Tom London 2008-11-04 17:38:07 UTC
Description of problem:
Notice very frequent supplicant transitions and "failed to remove" message when connected to 802.1X wireless network.

Not sure this is a bug.....

Nov  4 09:17:44 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
Nov  4 09:22:15 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> associating
Nov  4 09:22:15 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated
Nov  4 09:22:47 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> 4-way handshake
Nov  4 09:22:47 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  4-way handshake -> group handshake
Nov  4 09:22:47 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
Nov  4 09:24:16 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> associating
Nov  4 09:24:16 tlondon kernel: mac80211-phy0: failed to remove key (0, 00:19:77:00:4f:f4) from hardware (-22)
Nov  4 09:24:16 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated
Nov  4 09:24:20 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> 4-way handshake
Nov  4 09:24:20 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  4-way handshake -> group handshake
Nov  4 09:24:20 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
Nov  4 09:27:44 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> group handshake
Nov  4 09:27:44 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed


Version-Release number of selected component (if applicable):
kernel-2.6.27.4-73.fc10.x86_64
iwl4965-firmware-228.57.2.21-3.noarch
NetworkManager-0.7.0-0.11.svn4229.fc10.x86_64

How reproducible:
Typically, several times a day....

Steps to Reproduce:
1.
2.
3.
  
Actual results:


Expected results:


Additional info:

Comment 1 Tom London 2008-11-04 18:03:33 UTC
I seem to get this message if I disable wireless in NM by unclicking the "Enable Wireless" box.

Nov  4 10:01:07 tlondon NetworkManager: <info>  (wlan0): taking down device.
Nov  4 10:01:07 tlondon kernel: mac80211-phy0: failed to remove key (0, 00:19:77:00:54:b4) from hardware (-22)
Nov  4 10:01:09 tlondon kernel: hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
Nov  4 10:01:09 tlondon kernel: iwlagn 0000:03:00.0: PCI INT A disabled

Again, not sure if this is an issue.....

Comment 2 Tom London 2008-11-10 21:35:30 UTC
Continues with kernel-2.6.27.5-91.fc10.x86_64:

Nov 10 12:43:34 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> associating
Nov 10 12:43:34 tlondon kernel: mac80211-phy0: failed to remove key (0, 00:19:77:00:54:b4) from hardware (-22)
Nov 10 12:43:34 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated
Nov 10 12:44:05 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> 4-way handshake
Nov 10 12:44:05 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  4-way handshake -> group handshake
Nov 10 12:44:05 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
Nov 10 12:45:54 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> group handshake
Nov 10 12:45:54 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
Nov 10 12:47:33 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> associating
Nov 10 12:47:33 tlondon kernel: mac80211-phy0: failed to remove key (0, 00:19:77:00:4f:f4) from hardware (-22)
Nov 10 12:47:33 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated

Comment 3 Tom London 2008-11-12 21:47:14 UTC
With kernel-2.6.27.5-101.fc10.x86_64, I noticed  a "DHCPREQUEST loop", and when I disabled wireless in NetworkManager, I got :

Nov 12 13:42:17 tlondon kernel: iwlagn: index 255 not used in uCode key table.

More complete snippet below.

Nov 12 13:41:03 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 12 13:41:17 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 12 13:41:33 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 12 13:41:45 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 12 13:42:05 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 12 13:42:17 tlondon NetworkManager: <info>  (wlan0): device state change: 8 -> 2
Nov 12 13:42:17 tlondon NetworkManager: <info>  (wlan0): deactivating device (reason: 0).
Nov 12 13:42:17 tlondon NetworkManager: <info>  wlan0: canceled DHCP transaction, dhcp client pid 3426
Nov 12 13:42:17 tlondon avahi-daemon[2627]: Withdrawing address record for 10.11.14.42 on wlan0.
Nov 12 13:42:17 tlondon avahi-daemon[2627]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 10.11.14.42.
Nov 12 13:42:17 tlondon avahi-daemon[2627]: Interface wlan0.IPv4 no longer relevant for mDNS.
Nov 12 13:42:17 tlondon kernel: iwlagn: index 255 not used in uCode key table.
Nov 12 13:42:17 tlondon kernel: iwlagn: index 255 not used in uCode key table.
Nov 12 13:42:17 tlondon NetworkManager: <info>  (wlan0): taking down device.
Nov 12 13:42:17 tlondon kernel: mac80211-phy0: failed to remove key (0, 00:19:77:00:54:b4) from hardware (-22)
Nov 12 13:42:19 tlondon pulseaudio[3257]: module-alsa-sink.c: Increasing wakeup watermark to 30.66 ms
Nov 12 13:42:19 tlondon kernel: hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
Nov 12 13:42:19 tlondon avahi-daemon[2627]: Withdrawing address record for fe80::213:e8ff:fe77:49e7 on wlan0.
Nov 12 13:42:19 tlondon kernel: iwlagn 0000:03:00.0: PCI INT A disabled
Nov 12 13:42:19 tlondon ntpd[2548]: Deleting interface #4 wlan0, fe80::213:e8ff:fe77:49e7#123, interface stats: received=0, sent=0, dropped=0, active_time=17930 secs
Nov 12 13:42:19 tlondon ntpd[2548]: Deleting interface #7 wlan0, 10.11.14.42#123, interface stats: received=0, sent=0, dropped=0, active_time=17861 secs

Comment 4 Bug Zapper 2008-11-26 04:45:12 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 10 development cycle.
Changing version to '10'.

More information and reason for this action is here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 5 John W. Linville 2009-01-20 17:51:38 UTC
Can you recreate this issue with a current rawhide kernel?

Comment 6 Tom London 2009-01-20 18:01:33 UTC
Don't believe so.  Get this when "disabling/enabling" now:



Jan 20 09:59:58 tlondon NetworkManager: <info>  (wlan1): device state change: 8 -> 2
Jan 20 09:59:58 tlondon NetworkManager: <info>  (wlan1): deactivating device (reason: 0).
Jan 20 09:59:59 tlondon NetworkManager: <info>  wlan1: canceled DHCP transaction, dhcp client pid 3433
Jan 20 10:00:00 tlondon nscd: 6944 Access Vector Cache (AVC) started
Jan 20 10:00:00 tlondon nscd: 6964 Access Vector Cache (AVC) started
Jan 20 10:00:00 tlondon NetworkManager: <info>  Policy set 'Auto eth1' (eth1) as default for routing and DNS.
Jan 20 10:00:00 tlondon avahi-daemon[2756]: Withdrawing address record for 10.11.14.37 on wlan1.
Jan 20 10:00:00 tlondon avahi-daemon[2756]: Leaving mDNS multicast group on interface wlan1.IPv4 with address 10.11.14.37.
Jan 20 10:00:00 tlondon avahi-daemon[2756]: Interface wlan1.IPv4 no longer relevant for mDNS.
Jan 20 10:00:01 tlondon NetworkManager: <info>  (wlan1): taking down device.
Jan 20 10:00:01 tlondon avahi-daemon[2756]: Withdrawing address record for fe80::221:5dff:feac:c692 on wlan1.
Jan 20 10:00:01 tlondon kernel: iwlagn 0000:03:00.0: PCI INT A disabled
Jan 20 10:00:01 tlondon dbus: Rejected send message, 22 matched rules; type="method_return", sender=":1.8" (uid=0 pid=2572 comm="NetworkManager --pid-file=/var/run/NetworkManager/") interface="(unset)" member="(unset)" error name="(unset)" requested_reply=0 destination=":1.38" (uid=500 pid=3375 comm="nm-applet --sm-disable "))
Jan 20 10:00:01 tlondon dbus: Rejected send message, 23 matched rules; type="method_return", sender=":1.9" (uid=0 pid=2577 comm="/usr/sbin/wpa_supplicant -c /etc/wpa_supplicant/wp") interface="(unset)" member="(unset)" error name="(unset)" requested_reply=0 destination=":1.8" (uid=0 pid=2572 comm="NetworkManager --pid-file=/var/run/NetworkManager/"))
Jan 20 10:00:03 tlondon ntpd[2661]: Deleting interface #5 wlan1, fe80::221:5dff:feac:c692#123, interface stats: received=0, sent=0, dropped=0, active_time=5205 secs
Jan 20 10:00:03 tlondon ntpd[2661]: Deleting interface #7 wlan1, 10.11.14.37#123, interface stats: received=0, sent=0, dropped=0, active_time=5030 secs


Jan 20 10:00:26 tlondon pulseaudio[3331]: module-alsa-sink.c: Increasing wakeup watermark to 136.05 ms
Jan 20 10:00:32 tlondon NetworkManager: <WARN>  nm_device_wifi_set_enabled(): not in expected unavailable state!
Jan 20 10:00:32 tlondon NetworkManager: <info>  (wlan1): bringing up device.
Jan 20 10:00:32 tlondon kernel: iwlagn 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
Jan 20 10:00:33 tlondon kernel: Registered led device: iwl-phy0:radio
Jan 20 10:00:33 tlondon kernel: Registered led device: iwl-phy0:assoc
Jan 20 10:00:33 tlondon kernel: Registered led device: iwl-phy0:RX
Jan 20 10:00:33 tlondon kernel: Registered led device: iwl-phy0:TX
Jan 20 10:00:33 tlondon kernel: ADDRCONF(NETDEV_UP): wlan1: link is not ready
Jan 20 10:00:33 tlondon NetworkManager: <info>  (wlan1): device state change: 2 -> 3
Jan 20 10:00:33 tlondon dbus: Rejected send message, 22 matched rules; type="method_return", sender=":1.8" (uid=0 pid=2572 comm="NetworkManager --pid-file=/var/run/NetworkManager/") interface="(unset)" member="(unset)" error name="(unset)" requested_reply=0 destination=":1.38" (uid=500 pid=3375 comm="nm-applet --sm-disable "))
Jan 20 10:00:33 tlondon NetworkManager: <info>  (wlan1): supplicant interface state:  starting -> ready
Jan 20 10:00:36 tlondon NetworkManager: <info>  Activation (wlan1) starting connection 'Auto insidex'
Jan 20 10:00:36 tlondon NetworkManager: <info>  (wlan1): device state change: 3 -> 4
Jan 20 10:00:36 tlondon NetworkManager: <info>  Activation (wlan1) Stage 1 of 5 (Device Prepare) scheduled...
Jan 20 10:00:36 tlondon NetworkManager: <info>  Activation (wlan1) Stage 1 of 5 (Device Prepare) started...
Jan 20 10:00:36 tlondon NetworkManager: <info>  Activation (wlan1) Stage 2 of 5 (Device Configure) scheduled...
Jan 20 10:00:36 tlondon NetworkManager: <info>  Activation (wlan1) Stage 1 of 5 (Device Prepare) complete.
Jan 20 10:00:36 tlondon NetworkManager: <info>  Activation (wlan1) Stage 2 of 5 (Device Configure) starting...
Jan 20 10:00:36 tlondon NetworkManager: <info>  (wlan1): device state change: 4 -> 5
Jan 20 10:00:36 tlondon NetworkManager: <info>  Activation (wlan1/wireless): connection 'Auto insidex' has security, and secrets exist.  No new secrets needed.
Jan 20 10:00:36 tlondon NetworkManager: <info>  Config: added 'ssid' value 'insidex'
Jan 20 10:00:36 tlondon NetworkManager: <info>  Config: added 'scan_ssid' value '1'
Jan 20 10:00:36 tlondon NetworkManager: <info>  Config: added 'key_mgmt' value 'WPA-EAP'
Jan 20 10:00:36 tlondon NetworkManager: <info>  Config: added 'password' value '<omitted>'
Jan 20 10:00:36 tlondon NetworkManager: <info>  Config: added 'eap' value 'PEAP'
Jan 20 10:00:36 tlondon NetworkManager: <info>  Config: added 'fragment_size' value '1300'
Jan 20 10:00:36 tlondon NetworkManager: <info>  Config: added 'phase1' value 'peapver=0'
Jan 20 10:00:36 tlondon NetworkManager: <info>  Config: added 'phase2' value 'auth=MSCHAPV2'
Jan 20 10:00:36 tlondon NetworkManager: <info>  Config: added 'identity' value 'tlondon'
Jan 20 10:00:36 tlondon NetworkManager: <info>  Activation (wlan1) Stage 2 of 5 (Device Configure) complete.
Jan 20 10:00:36 tlondon NetworkManager: <info>  Config: set interface ap_scan to 1
Jan 20 10:00:41 tlondon NetworkManager: <info>  (wlan1): supplicant connection state:  disconnected -> scanning
Jan 20 10:00:42 tlondon NetworkManager: <info>  (wlan1): supplicant connection state:  scanning -> associating
Jan 20 10:00:43 tlondon NetworkManager: <info>  (wlan1): supplicant connection state:  associating -> disconnected

Comment 7 John W. Linville 2009-01-22 19:17:12 UTC
Not sure if you are saying that comment 6 represents a problem or not -- if so, it seems different from the original problem here.  If it is a problem, please open a new bug that spells that out clearly for me. :-)

Comment 8 Tom London 2009-01-22 19:25:56 UTC
No, this is "working for me".

Apologize for my confusion:

Although I filed the bug against rawhide, it was triaged against 10.

As I continue to run/test rawhide, I can't test against 10.  So I was reporting "works for me in rawhide".

Sorry for any confusion.....  [Hints for doing this 'right' welcomed!]