misc/142547: wpa_supplicant drops connection on key renegotiation

Sat Jan 9 22:10:03 UTC 2010

>Number:         142547
>Category:       misc
>Synopsis:       wpa_supplicant drops connection on key renegotiation
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    freebsd-bugs
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Sat Jan 09 22:10:01 UTC 2010
>Closed-Date:
>Last-Modified:
>Originator:     Kevin Dorne
>Release:        8.0-STABLE amd64
>Organization:
>Environment:
FreeBSD [hostname] 8.0-STABLE FreeBSD 8.0-STABLE #0: Sat Dec 19 02:54:18 PST 2009     root@:/usr/obj/usr/src/sys/GENERIC  amd64

>Description:
I am using a Thinkpad T61 with Intel 4965agn wireless card, connecting to an access point using WPA authentication.

On system startup, the networking works, but once the WPA key is renegotiated, the connection drops.  I can get the connection back by restarting the networking (/etc/rc.d/netif restart).

This does not occur on the same machine running Linux, so it's not a hardware issue.

Relevant lines in

/boot/loader.conf:
if_iwn_load="YES"
iwnfw_load="YES"
wlan_wep_load="YES"
wlan_ccmp_load="YES"
wlan_tkip_load="YES"
legal.intel_iwn.license_ack=1

/etc/rc.conf:
wlans_iwn0="wlan0"
ifconfig_wlan0="WPA DHCP"

/etc/wpa_supplicant.conf:
ctrl_interface=/var/run/wpa_supplicant
ctrl_interface_group=wheel
eapol_version=1
ap_scan=1
fast_reauth=1

network={
  ssid="[ssid]"
  scan_ssid=1
  key_mgmt=WPA-PSK
  psk="[pass]"
}

dmesg:
iwn0: <Intel(R) PRO/Wireless 4965BGN> mem 0xdf2fe000-0xdf2fffff irq 17 at device 0.0 on pci3
iwn0: Reg Domain: MoW1, address 00:21:5c:5c:ae:1d
iwn0: [ITHREAD]
iwn0: 11a rates: 6Mbps 9Mbps 12Mbps 18Mbps 24Mbps 36Mbps 48Mbps 54Mbps
iwn0: 11b rates: 1Mbps 2Mbps 5.5Mbps 11Mbps
iwn0: 11g rates: 1Mbps 2Mbps 5.5Mbps 11Mbps 6Mbps 9Mbps 12Mbps 18Mbps 24Mbps 36Mbps 48Mbps 54Mbps
iwn0: 11na MCS: 15Mbps 30Mbps 45Mbps 60Mbps 90Mbps 120Mbps 135Mbps 150Mbps 30Mbps 60Mbps 90Mbps 120Mbps 180Mbps 240Mbps 270Mbps 300Mbps
iwn0: 11ng MCS: 15Mbps 30Mbps 45Mbps 60Mbps 90Mbps 120Mbps 135Mbps 150Mbps 30Mbps 60Mbps 90Mbps 120Mbps 180Mbps 240Mbps 270Mbps 300Mbps

Messages from wpa_supplicant on renegotiate:
2010-01-09 13:21:09 RSN: encrypted key data - hexdump(len=48): 8a 3d e7 ef 49 43 2a d2 37 8f bd 0f d0 2b 1e 54 4b 5a 6d 63 76 bf 33 8c dd 8a 7b af 69 4e c1 6a c4 7b bc a8 f3 78 ec 28 56 d8 71 83 0a 1f 27 b7
2010-01-09 13:21:09 WPA: decrypted EAPOL-Key key data - hexdump(len=40): [REMOVED]
2010-01-09 13:21:09 WPA: RX message 1 of Group Key Handshake from 00:22:a4:37:b3:d9 (ver=2)
2010-01-09 13:21:09 RSN: msg 1/2 key data - hexdump(len=40): dd 26 00 0f ac 01 02 00 92 f1 7e a1 81 7f 92 e5 bf 29 cc a9 69 ee 07 47 ee 66 86 e6 c8 81 36 75 35 5a 7b 7e f4 f0 42 0c
2010-01-09 13:21:09 RSN: received GTK in group key handshake - hexdump(len=34): 02 00 92 f1 7e a1 81 7f 92 e5 bf 29 cc a9 69 ee 07 47 ee 66 86 e6 c8 81 36 75 35 5a 7b 7e f4 f0 42 0c
2010-01-09 13:21:09 State: COMPLETED -> GROUP_HANDSHAKE
2010-01-09 13:21:09 WPA: Group Key - hexdump(len=32): [REMOVED]
2010-01-09 13:21:09 WPA: Installing GTK to the driver (keyidx=2 tx=0 len=32).
2010-01-09 13:21:09 WPA: RSC - hexdump(len=6): 10 00 00 00 00 00
2010-01-09 13:21:09 wpa_driver_bsd_set_key: alg=TKIP addr=ff:ff:ff:ff:ff:ff key_idx=2 set_tx=0 seq_len=6 key_len=32
2010-01-09 13:21:09 WPA: Sending EAPOL-Key 2/2
2010-01-09 13:21:09 WPA: TX EAPOL-Key - hexdump(len=99): 01 03 00 5f 02 03 02 00 00 00 00 00 00 00 00 00 03 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c0 70 91 96 53 f8 d8 9c fd e9 26 79 27 c5 18 03 00 00
2010-01-09 13:21:09 WPA: Group rekeying completed with 00:22:a4:37:b3:d9 [GTK=TKIP]
2010-01-09 13:21:09 Cancelling authentication timeout
2010-01-09 13:21:09 State: GROUP_HANDSHAKE -> COMPLETED
2010-01-09 13:21:09 EAPOL: startWhen --> 0
2010-01-09 13:21:09 EAPOL: disable timer tick
2010-01-09 13:21:09 RX EAPOL from 00:22:a4:37:b3:d9
2010-01-09 13:21:09 RX EAPOL - hexdump(len=147): 01 03 00 8f 02 13 82 00 20 00 00 00 00 00 00 00 04 d8 72 4a 1f cf 42 d1 fe 14 bd 12 28 d4 45 54 11 21 3b 46 b3 11 6f 47 d5 65 d6 2c fc 0e 2e e8 da 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 dd 6b bb 8c 01 8f fb 9e 90 2a dc fe 79 8a ea 8a 00 30 f0 18 5d 96 aa 75 c9 8e ed cb 5a b1 0f 87 8d 43 b6 1e 4c c2 e4 3a a0 f2 4a 71 9b d7 fe e7 4e 43 dd 42 c1 7a dd c3 02 31 94 79 1e 87 f6 8b e5 cf
2010-01-09 13:21:09 IEEE 802.1X RX: version=1 type=3 length=143
2010-01-09 13:21:09   EAPOL-Key type=2
2010-01-09 13:21:09   key_info 0x1382 (ver=2 keyidx=0 rsvd=0 Group Ack MIC Secure Encr)
2010-01-09 13:21:09   key_length=32 key_data_length=48
2010-01-09 13:21:09   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 04
2010-01-09 13:21:09   key_nonce - hexdump(len=32): d8 72 4a 1f cf 42 d1 fe 14 bd 12 28 d4 45 54 11 21 3b 46 b3 11 6f 47 d5 65 d6 2c fc 0e 2e e8 da
2010-01-09 13:21:09   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2010-01-09 13:21:09   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
2010-01-09 13:21:09   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
2010-01-09 13:21:09   key_mic - hexdump(len=16): dd 6b bb 8c 01 8f fb 9e 90 2a dc fe 79 8a ea 8a
2010-01-09 13:21:09 WPA: RX EAPOL-Key - hexdump(len=147): 01 03 00 8f 02 13 82 00 20 00 00 00 00 00 00 00 04 d8 72 4a 1f cf 42 d1 fe 14 bd 12 28 d4 45 54 11 21 3b 46 b3 11 6f 47 d5 65 d6 2c fc 0e 2e e8 da 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 dd 6b bb 8c 01 8f fb 9e 90 2a dc fe 79 8a ea 8a 00 30 f0 18 5d 96 aa 75 c9 8e ed cb 5a b1 0f 87 8d 43 b6 1e 4c c2 e4 3a a0 f2 4a 71 9b d7 fe e7 4e 43 dd 42 c1 7a dd c3 02 31 94 79 1e 87 f6 8b e5 cf
2010-01-09 13:21:09 RSN: encrypted key data - hexdump(len=48): f0 18 5d 96 aa 75 c9 8e ed cb 5a b1 0f 87 8d 43 b6 1e 4c c2 e4 3a a0 f2 4a 71 9b d7 fe e7 4e 43 dd 42 c1 7a dd c3 02 31 94 79 1e 87 f6 8b e5 cf
2010-01-09 13:21:09 WPA: decrypted EAPOL-Key key data - hexdump(len=40): [REMOVED]
2010-01-09 13:21:09 WPA: RX message 1 of Group Key Handshake from 00:22:a4:37:b3:d9 (ver=2)
2010-01-09 13:21:09 RSN: msg 1/2 key data - hexdump(len=40): dd 26 00 0f ac 01 01 00 b5 e6 9b a6 82 ee 5f 6f 88 bf 9b 83 47 1f 61 1a 7b be 9e 23 fa b1 77 20 ba 51 99 ab 9a 08 b6 50
2010-01-09 13:21:09 RSN: received GTK in group key handshake - hexdump(len=34): 01 00 b5 e6 9b a6 82 ee 5f 6f 88 bf 9b 83 47 1f 61 1a 7b be 9e 23 fa b1 77 20 ba 51 99 ab 9a 08 b6 50
2010-01-09 13:21:09 State: COMPLETED -> GROUP_HANDSHAKE
2010-01-09 13:21:09 WPA: Group Key - hexdump(len=32): [REMOVED]
2010-01-09 13:21:09 WPA: Installing GTK to the driver (keyidx=1 tx=0 len=32).
2010-01-09 13:21:09 WPA: RSC - hexdump(len=6): 00 00 00 00 00 00
2010-01-09 13:21:09 wpa_driver_bsd_set_key: alg=TKIP addr=ff:ff:ff:ff:ff:ff key_idx=1 set_tx=0 seq_len=6 key_len=32
2010-01-09 13:21:09 WPA: Sending EAPOL-Key 2/2
>How-To-Repeat:
Happens most times the key is renegotiated.  It seems not to do it on occasion when there's heavy, continuous network traffic, but I'm not 100% sure about that.
>Fix:
None.  Workaround is to restart network using /etc/rc.d/netif restart.

>Release-Note:
>Audit-Trail:
>Unformatted: