CRC ok but CipherErr 3

Live forum: http://rt2x00.serialmonkey.com/viewtopic.php?t=4898

TomDeMan

17-07-2008 14:06:58

I get this error frequently

Jul 17 155537 lxntv13 kernel rt61 ERROR CRC ok but CipherErr 3 (len = 78, Mcast=0, Cipher=TKIP, KeyId=0)

and ping replies stutter now and then.

The setup is the latest rt61 driver using WPA2/AES but the access point is cisco that can do both WPA2/AES and TKIP at the same time. You just have to choose which encryption you want to use at the client side when you start.
What happens is that RTMPCheckRxError() has pRxD->CipherAlg set to 3 (TKIP) somehow. That should probably be AES to get it to decrypt well. Anyone have any idea how this pRxD->CipherAlg was filled in with TKIP ? Or is this an error in the cisco AP ?

It shouldn't be difficult to reproduce if you have one of those Cisco Aironet access points, I have an 1130AG with these details

System Software Version IOS (tm) C1130 Software (C1130-K9W7-M)

Product/Model Number AIR-AP1131AG-E-K9
Top Assembly Serial Number FCZ0918Q00H
System Software Filename c1130-k9w7-tar.123-2.JA2

and the trick to get it to behave badly is to set cipher = AES CCMP + TKIP

Here's the probably relevant parts of the log

Jul 17 155536 lxntv13 kernel rt61 Wpa2PairMsg1Action <-----
Jul 17 155536 lxntv13 kernel rt61 <----- WpaEAPOLKeyAction
Jul 17 155536 lxntv13 kernel rt61 MlmeDequeue, num=0
Jul 17 155536 lxntv13 kernel !!! report EAPOL DATA to MLME (len=153) !!!
Jul 17 155536 lxntv13 kernel rt61 ====> RTMPHandleInterrupt
Jul 17 155536 lxntv13 kernel rt61 RTMPHandleMgmtRingDmaDoneInterrupt...
Jul 17 155536 lxntv13 kernel rt61 <==== RTMPHandleInterrupt (1 handled)
Jul 17 155536 lxntv13 kernel rt61 ====> RTMPHandleInterrupt
Jul 17 155536 lxntv13 kernel rt61 <==== RTMPHandleInterrupt (1 handled)
Jul 17 155536 lxntv13 kernel rt61 ====> RTMPHandleInterrupt
Jul 17 155536 lxntv13 kernel rt61 <==== RTMPHandleInterrupt (1 handled)
Jul 17 155536 lxntv13 kernel rt61 MlmeEnqueueForRecv, num=1
Jul 17 155536 lxntv13 kernel rt61 -----> WpaEAPOLKeyAction
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Key Description Version 2
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Key Type 1
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Key Index 0
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Install 1
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Key Ack 1
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Key MIC 1
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Secure 1
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Error 0
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Request 0
Jul 17 155536 lxntv13 kernel rt61 KeyInfo EKD_DL 1
Jul 17 155536 lxntv13 kernel rt61 Receive EAPOL Key Pairwise Message 3
Jul 17 155536 lxntv13 kernel rt61 Wpa2PairMsg3Action ----->
Jul 17 155536 lxntv13 kernel rt61 MIC VALID in msg 3 of 4-way handshake!!!!!!!!!!
Jul 17 155536 lxntv13 kernel EKD = 1
Jul 17 155536 lxntv13 kernel plaintext =
Jul 17 155536 lxntv13 kernel 30 14 1 0 0 f ac 2 1 0 0 f ac 4 1 0
Jul 17 155536 lxntv13 kernel 0 f ac 2 28 0 dd 26 0 f ac 1 5 0 c1 df
Jul 17 155536 lxntv13 kernel cf f4 e 7a 53 cb c9 5f a8 45 9b 41 95 29 d4 cb
Jul 17 155536 lxntv13 kernel b8 c1 87 d7 20 b3 81 75 39 f9 e4 45 8d f2 dd 0
Jul 17 155536 lxntv13 kernel 0 0 0 0 a 0 1 0
Jul 17 155536 lxntv13 kernel
Jul 17 155536 lxntv13 kernel rt61 RSN IE mismatched !!!!!!!!!!
Jul 17 155536 lxntv13 kernel rt61 KeyDataLen = 72
Jul 17 155536 lxntv13 kernel WPA2 RSN IE length 40 contained in Msg3 =
Jul 17 155536 lxntv13 kernel KeyDataLength 32
Jul 17 155536 lxntv13 kernel pKDE =
Jul 17 155536 lxntv13 kernel pKDE->Type ddpKDE->Len 0x26pKDE->OUI 0 f ac
Jul 17 155536 lxntv13 kernel GTK Key[1] len=32 c1dfcff40e7a53cbc95fa8459b419529d4cbb8c187d720b3817539f9e4458df2
Jul 17 155536 lxntv13 kernel rt61 pAd->SharedKey[1].CipherAlg = 3
Jul 17 155536 lxntv13 kernel rt61 AsicAddSharedKeyEntry TKIP key #1
Jul 17 155536 lxntv13 kernel Key =c1dfcff40e7a53cbc95fa8459b419529
Jul 17 155536 lxntv13 kernel Rx MIC Key = d4cbb8c187d720b3
Jul 17 155536 lxntv13 kernel Tx MIC Key = 817539f9e4458df2
Jul 17 155536 lxntv13 kernel rt61 pAd->SharedKey[0].CipherAlg = 4
Jul 17 155536 lxntv13 kernel rt61 AsicAddSharedKeyEntry AES key #0
Jul 17 155536 lxntv13 kernel Key =7e09568958d24841c7868a09742bd7dd
Jul 17 155536 lxntv13 kernel Rx MIC Key = 432d4b3748cbe826
Jul 17 155536 lxntv13 kernel Tx MIC Key = a7b929731e94af3b
Jul 17 155536 lxntv13 kernel rt61 MlmeHardTransmit
Jul 17 155536 lxntv13 kernel rt61 WriteTxD scatter #1 = 131 + 0 + 0 ... = 131
Jul 17 155536 lxntv13 kernel MLMEHardTransmit use rate 1
Jul 17 155536 lxntv13 kernel rt61 Wpa2PairMsg3Action <-----
Jul 17 155536 lxntv13 kernel rt61 <----- WpaEAPOLKeyAction
...
Jul 17 155536 lxntv13 kernel rt61 -----> WpaEAPOLKeyAction
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Key Description Version 2
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Key Type 0
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Key Index 0
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Install 0
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Key Ack 1
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Key MIC 1
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Secure 1
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Error 0
Jul 17 155536 lxntv13 kernel rt61 KeyInfo Request 0
Jul 17 155536 lxntv13 kernel rt61 KeyInfo EKD_DL 1
Jul 17 155536 lxntv13 kernel rt61 Receive EAPOL Key Group Message 1
Jul 17 155536 lxntv13 kernel rt61 WpaGroupMsg1Action ----->
Jul 17 155536 lxntv13 kernel rt61 MIC VALID in group msg 1 of 2-way handshake!!!!!!!!!!
Jul 17 155536 lxntv13 kernel rt61 Install = 0!!!!EKD_DL = 1!!!!!KeyIndex = 0!
Jul 17 155536 lxntv13 kernel plaintext =
Jul 17 155536 lxntv13 kernel dd 26 0 f ac 1 6 0 15 33 ab 6a e4 79 38 5d
Jul 17 155536 lxntv13 kernel 63 53 aa 45 8d dc 24 84 28 35 cb 57 fa 98 6 84
Jul 17 155536 lxntv13 kernel a2 af d1 18 de 93 6e f4 b8 c1 87 d7 20 b3 81 75
Jul 17 155536 lxntv13 kernel
Jul 17 155536 lxntv13 kernel
Jul 17 155536 lxntv13 kernel GTK =
Jul 17 155536 lxntv13 kernel 27 48 e7 b7 ac 35 93 a0 bb 29 f2 fc 8e 4c 1d 45
Jul 17 155536 lxntv13 kernel 04 2c 5d 8a ee 19 c4 50 e1 38 ac 14 d4 02 b1 13
Jul 17 155536 lxntv13 kernel
Jul 17 155536 lxntv13 kernel
Jul 17 155536 lxntv13 kernel rt61 pAd->SharedKey[0].CipherAlg = 3
Jul 17 155536 lxntv13 kernel rt61 AsicAddSharedKeyEntry TKIP key #0
Jul 17 155536 lxntv13 kernel Key =dd26000fac0106001533ab6ae479385d
Jul 17 155536 lxntv13 kernel Rx MIC Key = 6353aa458ddc2484
Jul 17 155536 lxntv13 kernel Tx MIC Key = 2835cb57fa980684
Jul 17 155536 lxntv13 kernel rt61 ====> RTMPSendPacket
Jul 17 155536 lxntv13 kernel rt61 RTMPHardTransmit(RTS=0, Frag=1)
Jul 17 155536 lxntv13 kernel rt61 RTMPCheckDHCPFrame - not DHCP, ip 0 ipv4 0 udp 0 destport 0
Jul 17 155536 lxntv13 kernel rt61 RTMPHardTransmit(bEAP=1) - TKIP key#0, KeyLen=32
Jul 17 155536 lxntv13 kernel rt61 WriteTxD scatter #2 = 32 + 99 + 0 ... = 131
Jul 17 155536 lxntv13 kernel rt61 pAd->SharedKey[0].CipherAlg = 3
Jul 17 155536 lxntv13 kernel rt61 AsicAddSharedKeyEntry TKIP key #0
Jul 17 155536 lxntv13 kernel Key =dd26000fac0106001533ab6ae479385d
Jul 17 155536 lxntv13 kernel Rx MIC Key = 6353aa458ddc2484
Jul 17 155536 lxntv13 kernel Tx MIC Key = 2835cb57fa980684
Jul 17 155536 lxntv13 kernel rt61 ====> RTMPHandleInterrupt
Jul 17 155536 lxntv13 kernel rt61 <==== RTMPHandleInterrupt (1 handled)
Jul 17 155536 lxntv13 kernel rt61 WpaGroupMsg1Action <-----
Jul 17 155536 lxntv13 kernel rt61 <----- WpaEAPOLKeyAction
...
Jul 17 155537 lxntv13 kernel rt61 SYNC - PeerBeacon from 001244bac990 - Dtim=0/2, Rssi=d2
Jul 17 155537 lxntv13 kernel rt61 Rx My BEACON
Jul 17 155537 lxntv13 kernel rt61 MlmeDequeue, num=0
Jul 17 155537 lxntv13 kernel rt61 ====> RTMPHandleInterrupt
Jul 17 155537 lxntv13 kernel rt61 <==== RTMPHandleInterrupt (1 handled)
Jul 17 155537 lxntv13 kernel rt61 ERROR CRC ok but CipherErr 3 (len = 78, Mcast=0, Cipher=TKIP, KeyId=0)
Jul 17 155537 lxntv13 kernel 08422c00000df03e - 3081001244bac990
Jul 17 155537 lxntv13 kernel 00137f2452b68013 - 0c1a8f0392b0a5e1
Jul 17 155537 lxntv13 kernel ef53d2b910b3a22f - 8bbe68b657be7517
Jul 17 155537 lxntv13 kernel ea18b1155720fdd7 - b4b79392cfd08885
Jul 17 155537 lxntv13 kernel rt61 RxDone - drop error frame (len=78)
...

Vern

18-07-2008 16:06:59

Hi TomDeMan,

Looks like either there's a cipher type mismatch, or a key mismatch, or both, between you and your AP.

TomDeMan

18-07-2008 16:16:20

What strikes me is that it works well for some time, then goes bad for a couple of seconds, etc...
So the PSK is fine, I was wondering if it's an AP error or rt61 that can be fixed somehow

Vern

18-07-2008 21:02:09

Check for possible interference. Googling on 'hidden node' and 'exposed nod' may help.

Thanks,

TomDeMan

23-07-2008 10:44:50

That doesn't seem to be the problem, the AP is only 5 meters away from my desk. When I do the same thing from a windows box there's no interruptions in the pings.
Also, I have an AP log that shows re-authentications for the linux laptop only


Event Log

Start Display at Index Max Number of Events to Display
Index Time Severity Description
1 Mar 8 173746.219 GMT Information Interface Dot11Radio0, Station 000d.f03e.3081 Associated KEY_MGMT[WPAv2 PSK]
2 Mar 8 173743.360 GMT Debugging Station 000d.f03e.3081 Authentication failed
3 Mar 8 173738.208 GMT Information Interface Dot11Radio0, Deauthenticating Station 000d.f03e.3081 Reason Previous authentication no longer valid
4 Mar 8 173535.208 GMT Information Interface Dot11Radio0, Station 000d.f03e.3081 Associated KEY_MGMT[WPAv2 PSK]
5 Mar 8 173531.243 GMT Debugging Station 000d.f03e.3081 Authentication failed
6 Mar 8 173525.389 GMT Debugging Station 000d.f03e.3081 Authentication failed

seems like a problem with the group key or something. I'll do some more tests, any help to point me in the right direction is welcome...

Vern

23-07-2008 17:15:35

Hi TomDeMan,

Does your AP periodically rekey? It may be that the driver does not handle that well.

Thanks,

TomDeMan

23-07-2008 20:28:35

Hi Vern,

The cisco web config does say

Broadcast Key Rotation Interval
Enable Rotation with Interval 60 sec

Is this what you mean ? That seems like something pretty standard the driver should handle.
The more specialised cisco settings are turned off

Cisco Compliant TKIP Features
Enable Message Integrity Check (MIC)
Enable Per Packet Keying (PPK)

So both of these are off.

I'll have a go at turning the broadcast key rotation interval off and see if it happens again, but if this is missing I would like to add it if possible.

TomDeMan

24-07-2008 08:59:32

Hey Vern,

Just did some more tests and I do get better results with that key rotation switched off, ping replies now are all good. But now and then there's still a ping that takes a bit longer (but doesn't timeout like before), the AP logs this

154303.867 GMT Information Interface Dot11Radio0, Station 000d.f03e.3081 Associated KEY_MGMT[WPAv2 PSK]
154259.716 GMT Information Interface Dot11Radio0, Deauthenticating Station 000d.f03e.3081 Reason Previous authentication no longer valid
154056.717 GMT Information Interface Dot11Radio0, Station 000d.f03e.3081 Associated KEY_MGMT[WPAv2 PSK]
154054.564 GMT Information Interface Dot11Radio0, Deauthenticating Station 000d.f03e.3081 Reason Previous authentication no longer valid
153851.564 GMT Information Interface Dot11Radio0, Station 000d.f03e.3081 Associated KEY_MGMT[WPAv2 PSK]

So reauthentication still happens and takes a while but recovery is quick compared to before with the key rotation on (where it took 10, 20, ... seconds to recover).
The messages debug log still shows an error "KeyInfo error 0" quite a lot but the CipherErr is gone.

So first the key rotation should be fixed I think, because other APs are out of my control most of the time I won't be able to switch off that setting everywhere I go.
Then something needs to be done about "Keyinfo error 0" because it will speed up traffic if reauthentication isn't done anymore.

I'll take a dive into the code, hints are still welcome but this hint was a hit already, thanks.