linux-only "freshness" auth problem??

linux-only "freshness" auth problem??

[Michael Tokarev]

Hello.

I'm facing quite an interesting issue here.

Hotel wifi, with psk auth. All devices works fine, including
various models of cell phones, various laptops.  But one laptop
does not work, the network refuses to authenticate, NetworkManager
re-asks for the password.  The same laptop, when rebooted into
windows, with the same password, connects to wifi network instantly.
Reboot into linux - and NetworkManager asks for the password again
(psk stored in /etc/NetworkManager/system-connections/<Netname> is
the right one).

Reboot the access point, and linux also assotiates instantly.  Now
everything works.

But after some time (within one day so far), after next attempt to
use this wifi network, linux again asks for a password endlessly.
Rebooting AP helps, as is rebooting this laptop into windows.  But
rebooting into linux does not help, the AP refuses to authenticate
linux.

There's another hotel nearby, they run another wifi network.  I
tried to use their network (our hotel staff know their password).
And the behavour is exactly the same -- only this my laptop, when
booted into linux, is not authenticated by the AP, this laptop
when booted into windows connects instantly, as are other devices
like cell phones or laptops.

So the thing is definitely this laptop.  However, I never had any
probs with its wifi support so far, it always worked fine before
this story.

So I really wonder what the problem is, what's the difference
between linux and windows for a "non-fresh" AP, why it refuses
to auth linux, and finally fix the problem so it wont appear
again... ;)

I'm running linux kernel 3.16 on debian jessie.  The NIC is this
one:

  03:00.0 Network controller:
   Intel Corporation Centrino Advanced-N 6235 (rev 24)

Here's how a typical auth attempt looks like:

Aug 21 11:31:49 x200la wpa_supplicant[1546]: wlan0: SME: Trying to authenticate with c0:4a:00:49:1b:f2 (SSID='Prada' freq=2437 MHz)
Aug 21 11:31:49 x200la kernel: wlan0: authenticate with c0:4a:00:49:1b:f2
Aug 21 11:31:49 x200la kernel: wlan0: send auth to c0:4a:00:49:1b:f2 (try 1/3)
Aug 21 11:31:49 x200la wpa_supplicant[1546]: wlan0: Trying to associate with c0:4a:00:49:1b:f2 (SSID='Prada' freq=2437 MHz)
Aug 21 11:31:49 x200la kernel: wlan0: authenticated
Aug 21 11:31:49 x200la kernel: wlan0: waiting for beacon from c0:4a:00:49:1b:f2
Aug 21 11:31:49 x200la NetworkManager[1337]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Aug 21 11:31:49 x200la NetworkManager[1337]: <info> (wlan0): supplicant interface state: authenticating -> associating
Aug 21 11:31:49 x200la wpa_supplicant[1546]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="Prada" auth_failures=1 duration=10 reason=CONN_FAILED
Aug 21 11:31:49 x200la NetworkManager[1337]: <info> (wlan0): supplicant interface state: associating -> disconnected
Aug 21 11:31:54 x200la NetworkManager[1337]: <info> (wlan0): supplicant interface state: disconnected -> scanning

Any hints please? :)

Thank you!

/mjt

Re: linux-only "freshness" auth problem??

[Rafał Miłecki]

On 21 August 2015 at 11:35, Michael Tokarev <mjt@tls.msk.ru> wrote:
> Any hints please? :)

Disable NetworkManager (or make it ignore WiFi interface) and
temporary use wpa_supplicant. Get a log with debugging enables when it
fails and when it success. Look for errors in fail log, compare it
with success one.

-- 
Rafał

Re: linux-only "freshness" auth problem??

[Johannes Berg]

On Fri, 2015-08-21 at 12:35 +0300, Michael Tokarev wrote:
> 
> Aug 21 11:31:49 x200la kernel: wlan0: authenticated
> Aug 21 11:31:49 x200la kernel: wlan0: waiting for beacon from c0:4a:00:49:1b:f2

Do you see any *kernel* messages after this? I'm half expecting to see
that the beacon never arrives, or something like that?

Are the hotels running similar equipment perhaps? If rebooting the AP
helps then perhaps the APs aren't actually beaconing quite properly -
maybe you could put the card into sniffer mode (monitor mode) and
capture what's going on over the air for a bit after this happened?

johannes

Re: linux-only "freshness" auth problem??

[Michael Tokarev]

21.08.2015 13:16, Johannes Berg wrote:
> On Fri, 2015-08-21 at 12:35 +0300, Michael Tokarev wrote:
>>
>> Aug 21 11:31:49 x200la kernel: wlan0: authenticated
>> Aug 21 11:31:49 x200la kernel: wlan0: waiting for beacon from c0:4a:00:49:1b:f2
>
> Do you see any *kernel* messages after this? I'm half expecting to see
> that the beacon never arrives, or something like that?

The kernel log is repeated.  The next log line is again scanning start,
since NetworkManager (or wpa_supplicant, I'm not familiar with the machinery
involved) request scan again.

> Are the hotels running similar equipment perhaps? If rebooting the AP
> helps then perhaps the APs aren't actually beaconing quite properly -
> maybe you could put the card into sniffer mode (monitor mode) and
> capture what's going on over the air for a bit after this happened?

Can you give some more specific comments please?  We just rebooted the
AP the next time, it all started working again, and I need to install
all the necessary tools while it is working ;)  Since I'm not familiar
with wifi machinery, maybe you can give me specific command lines to
run? :)

Thank you!

/mjt

Re: linux-only "freshness" auth problem??

[Michael Tokarev]

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

21.08.2015 12:53, Rafał Miłecki wrote:
> On 21 August 2015 at 11:35, Michael Tokarev <mjt@tls.msk.ru> wrote:
>> Any hints please? :)
>
> Disable NetworkManager (or make it ignore WiFi interface) and
> temporary use wpa_supplicant. Get a log with debugging enables when it
> fails and when it success. Look for errors in fail log, compare it
> with success one.

That's good hint.  Thank you very much!

I tried what you suggested.  Unfortunately the difference does not tell
me much, or actually, does not tell me the _why_, it looks like the AP
misbehaves somehow.

Here are the main difference (- for bad, + for good):

  nl80211: Association request send successfully
-nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION) received for wlan0
-nl80211: Delete station c0:4a:00:49:1b:f2
  nl80211: Drv Event 38 (NL80211_CMD_ASSOCIATE) received for wlan0
-nl80211: MLME event 38; timeout with c0:4a:00:49:1b:f2
-wlan0: Event ASSOC_TIMED_OUT (15) received
-wlan0: SME: Association timed out
-wlan0: Radio work 'sme-connect'@0x7fbf84e5a700 done in 0.137132 seconds
...

So in "good" case, there's one event, CMD_DEL_STATION, received
right before the CMD_ASSOTIATE.  The rest look similar besides a
few probably irrelevant details (timings, frequency, etc).

I'm attaching the diff between the two attempts, and 2 complete logs
(gzipped).  The "bad" log is larger since it contain several attempts
to connect, while the good one is just one successful attempt.

Can something be said about the problem based on these logs?

Thank you very much!

/mjt

[-- Attachment #2: wifi-log-prada-bad-good-diff --]
[-- Type: text/plain, Size: 16458 bytes --]

--- wifi-log-prada-bad	2015-08-22 11:26:37.385963536 +0300
+++ wifi-log-prada-good	2015-08-22 11:32:24.300616639 +0300
@@ -21,21 +21,21 @@
 nl80211: Using driver-based off-channel TX
 nl80211: interface wlan0 in phy phy0
 nl80211: Set mode ifindex 3 iftype 2 (STATION)
-nl80211: Subscribe to mgmt frames with non-AP handle 0x7fbf84e3af30
-nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7fbf84e3af30 match=040a
-nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7fbf84e3af30 match=040b
-nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7fbf84e3af30 match=040c
-nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7fbf84e3af30 match=040d
-nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7fbf84e3af30 match=090a
-nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7fbf84e3af30 match=090b
-nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7fbf84e3af30 match=090c
-nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7fbf84e3af30 match=090d
-nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7fbf84e3af30 match=0409506f9a09
-nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7fbf84e3af30 match=7f506f9a09
-nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7fbf84e3af30 match=0801
-nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7fbf84e3af30 match=06
-nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7fbf84e3af30 match=0a07
-nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7fbf84e3af30 match=0a11
+nl80211: Subscribe to mgmt frames with non-AP handle 0x7f530ede7f30
+nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7f530ede7f30 match=040a
+nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7f530ede7f30 match=040b
+nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7f530ede7f30 match=040c
+nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7f530ede7f30 match=040d
+nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7f530ede7f30 match=090a
+nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7f530ede7f30 match=090b
+nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7f530ede7f30 match=090c
+nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7f530ede7f30 match=090d
+nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7f530ede7f30 match=0409506f9a09
+nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7f530ede7f30 match=7f506f9a09
+nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7f530ede7f30 match=0801
+nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7f530ede7f30 match=06
+nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7f530ede7f30 match=0a07
+nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x7f530ede7f30 match=0a11
 netlink: Operstate: ifindex=3 linkmode=1 (userspace-control), operstate=5 (IF_OPER_DORMANT)
 nl80211: driver param='(null)'
 Add interface wlan0 to a new radio phy0
@@ -68,10 +68,6 @@
 EAPOL: KEY_RX entering state NO_KEY_RECEIVE
 EAPOL: SUPP_BE entering state INITIALIZE
 EAP: EAP entering state DISABLED
-Using existing control interface directory.
-ctrl_iface bind(PF_UNIX) failed: Address already in use
-ctrl_iface exists, but does not allow connections - assuming it was leftover from forced program termination
-Successfully replaced leftover ctrl_iface socket '/var/run/wpa_supplicant/wlan0'
 wlan0: Added interface wlan0
 wlan0: State: DISCONNECTED -> DISCONNECTED
 nl80211: Set wlan0 operstate 0->0 (DORMANT)
@@ -79,63 +75,66 @@
 random: Got 20/20 bytes from /dev/random
 wlan0: State: DISCONNECTED -> SCANNING
 wlan0: Starting AP scan for wildcard SSID
-wlan0: Add radio work 'scan'@0x7fbf84e5a700
+wlan0: Add radio work 'scan'@0x7f530ee07700
 wlan0: First radio work item in the queue - schedule start immediately
-wlan0: Starting radio work 'scan'@0x7fbf84e5a700 after 0.000006 second wait
+wlan0: Starting radio work 'scan'@0x7f530ee07700 after 0.000007 second wait
 wlan0: nl80211: scan request
 Scan requested (ret=0) - scan timeout 10 seconds
 nl80211: Drv Event 33 (NL80211_CMD_TRIGGER_SCAN) received for wlan0
 wlan0: nl80211: Scan trigger
 wlan0: Event SCAN_STARTED (49) received
-wlan0: Own scan request started a scan in 0.000025 seconds
+wlan0: Own scan request started a scan in 0.000029 seconds
 EAPOL: disable timer tick
+RTM_NEWLINK: ifi_index=3 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1003 ([UP])
 nl80211: Drv Event 34 (NL80211_CMD_NEW_SCAN_RESULTS) received for wlan0
 wlan0: nl80211: New scan results available
 nl80211: Scan probed for SSID ''
 nl80211: Scan included frequencies: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472 5180 5200 5220 5240 5260 5280 5300 5320 5500 5520 5540 5560 5580 5600 5620 5640 5660 5680 5700 5745 5765 5785 5805 5825
 wlan0: Event SCAN_RESULTS (3) received
-wlan0: Scan completed in 3.225426 seconds
-nl80211: Received scan results (7 BSSes)
+wlan0: Scan completed in 3.243051 seconds
+nl80211: Received scan results (9 BSSes)
 wlan0: BSS: Start scan result update 1
 wlan0: BSS: Add new id 0 BSSID c0:4a:00:49:1b:f2 SSID 'Prada'
 wlan0: BSS: Add new id 1 BSSID f8:1a:67:91:c3:7c SSID 'Dionis2'
-wlan0: BSS: Add new id 2 BSSID f8:1a:67:d7:0b:5c SSID 'Lover'
-wlan0: BSS: Add new id 3 BSSID 54:e6:fc:bb:b9:fe SSID 'Lover'
+wlan0: BSS: Add new id 2 BSSID 54:e6:fc:bb:b9:fe SSID 'Lover'
+wlan0: BSS: Add new id 3 BSSID f8:1a:67:d7:0b:5c SSID 'Lover'
 wlan0: BSS: Add new id 4 BSSID a0:f3:c1:d3:64:8c SSID 'Lover'
-wlan0: BSS: Add new id 5 BSSID 14:cc:20:47:55:60 SSID 'Renessanse'
-wlan0: BSS: Add new id 6 BSSID 0a:18:d6:47:c6:99 SSID 'Blumarin'
-BSS: last_scan_res_used=7/32
+wlan0: BSS: Add new id 5 BSSID 4a:d9:e7:21:89:fb SSID 'Blumarin'
+wlan0: BSS: Add new id 6 BSSID 14:cc:20:47:55:60 SSID 'Renessanse'
+wlan0: BSS: Add new id 7 BSSID 4a:d9:e7:21:88:28 SSID 'Blumarin'
+wlan0: BSS: Add new id 8 BSSID 14:d6:4d:9d:a2:91 SSID 'LOVER'
+BSS: last_scan_res_used=9/32
 wlan0: New scan results available (own=1 ext=0)
 WPS: AP c0:4a:00:49:1b:f2 type 0 added
 WPS: AP f8:1a:67:91:c3:7c type 0 added
-WPS: AP f8:1a:67:d7:0b:5c type 0 added
 WPS: AP 54:e6:fc:bb:b9:fe type 0 added
+WPS: AP f8:1a:67:d7:0b:5c type 0 added
 WPS: AP a0:f3:c1:d3:64:8c type 0 added
 WPS: AP[0] c0:4a:00:49:1b:f2 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
 WPS: AP[1] f8:1a:67:91:c3:7c type=0 tries=0 last_attempt=-1 sec ago blacklist=0
-WPS: AP[2] f8:1a:67:d7:0b:5c type=0 tries=0 last_attempt=-1 sec ago blacklist=0
-WPS: AP[3] 54:e6:fc:bb:b9:fe type=0 tries=0 last_attempt=-1 sec ago blacklist=0
+WPS: AP[2] 54:e6:fc:bb:b9:fe type=0 tries=0 last_attempt=-1 sec ago blacklist=0
+WPS: AP[3] f8:1a:67:d7:0b:5c type=0 tries=0 last_attempt=-1 sec ago blacklist=0
 WPS: AP[4] a0:f3:c1:d3:64:8c type=0 tries=0 last_attempt=-1 sec ago blacklist=0
-wlan0: Radio work 'scan'@0x7fbf84e5a700 done in 3.228616 seconds
+wlan0: Radio work 'scan'@0x7f530ee07700 done in 3.246058 seconds
 wlan0: Selecting BSS from priority group 0
-wlan0: 0: c0:4a:00:49:1b:f2 ssid='Prada' wpa_ie_len=22 rsn_ie_len=20 caps=0x431 level=-76 wps
+wlan0: 0: c0:4a:00:49:1b:f2 ssid='Prada' wpa_ie_len=22 rsn_ie_len=20 caps=0x431 level=-67 wps
 wlan0:    selected based on RSN IE
 wlan0:    selected BSS c0:4a:00:49:1b:f2 ssid='Prada'
-wlan0: Considering connect request: reassociate: 0  selected: c0:4a:00:49:1b:f2  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: SCANNING  ssid=0x7fbf84e3b0f0  current_ssid=(nil)
+wlan0: Considering connect request: reassociate: 0  selected: c0:4a:00:49:1b:f2  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: SCANNING  ssid=0x7f530ede80f0  current_ssid=(nil)
 wlan0: Request association with c0:4a:00:49:1b:f2
 WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=7): 00 05 50 72 61 64 61
-WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=3): 03 01 0b
-WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=3): 2a 01 03
+WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=3): 03 01 02
+WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=3): 2a 01 00
 WPA: RSN IE in EAPOL-Key - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
 WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=28): 33 1a ef 11 03 ff ff 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 04 06 e6 a7 0c 00
-WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=24): 3d 16 0b 07 17 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
-WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=24): 34 16 0b 07 17 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
+WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=24): 3d 16 02 0d 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
+WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=24): 34 16 02 0d 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 WPA: WPA IE in EAPOL-Key - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 04 01 00 00 50 f2 04 01 00 00 50 f2 02
 WPA: WMM Parameter Element - hexdump(len=24): 00 50 f2 02 01 01 83 00 03 a4 00 00 27 a4 00 00 42 43 5e 00 62 32 2f 00
 TDLS: TDLS is allowed in the target BSS
-wlan0: Add radio work 'sme-connect'@0x7fbf84e5a700
+wlan0: Add radio work 'sme-connect'@0x7f530ee07700
 wlan0: First radio work item in the queue - schedule start immediately
-wlan0: Starting radio work 'sme-connect'@0x7fbf84e5a700 after 0.000008 second wait
+wlan0: Starting radio work 'sme-connect'@0x7f530ee07700 after 0.000009 second wait
 wlan0: Automatic auth_alg selection: 0x1
 RSN: PMKSA cache search - network_ctx=(nil) try_opportunistic=0
 RSN: Search for BSSID c0:4a:00:49:1b:f2
@@ -152,7 +151,7 @@
 WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
 FT: Stored MDIE and FTIE from (Re)Association Response - hexdump(len=0):
 wlan0: Cancelling scan request
-wlan0: SME: Trying to authenticate with c0:4a:00:49:1b:f2 (SSID='Prada' freq=2462 MHz)
+wlan0: SME: Trying to authenticate with c0:4a:00:49:1b:f2 (SSID='Prada' freq=2417 MHz)
 wlan0: State: SCANNING -> AUTHENTICATING
 EAPOL: External notification - EAP success=0
 EAPOL: External notification - EAP fail=0
@@ -161,13 +160,12 @@
 wlan0: Shared frequencies (len=0): completed iteration
 nl80211: Authenticate (ifindex=3)
   * bssid=c0:4a:00:49:1b:f2
-  * freq=2462
+  * freq=2417
   * SSID - hexdump_ascii(len=5):
      50 72 61 64 61                                    Prada           
   * IEs - hexdump(len=0): [NULL]
   * Auth Type 0
 nl80211: Authentication request send successfully
-RTM_NEWLINK: ifi_index=3 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1003 ([UP])
 nl80211: Drv Event 19 (NL80211_CMD_NEW_STATION) received for wlan0
 nl80211: New station c0:4a:00:49:1b:f2
 nl80211: Drv Event 37 (NL80211_CMD_AUTHENTICATE) received for wlan0
@@ -180,14 +178,14 @@
 wlan0: set_disable_ht40: 0
 wlan0: set_disable_sgi: 0
 wlan0: set_disable_ldpc: 0
-wlan0: Trying to associate with c0:4a:00:49:1b:f2 (SSID='Prada' freq=2462 MHz)
+wlan0: Trying to associate with c0:4a:00:49:1b:f2 (SSID='Prada' freq=2417 MHz)
 wlan0: State: AUTHENTICATING -> ASSOCIATING
 nl80211: Set wlan0 operstate 0->0 (DORMANT)
 netlink: Operstate: ifindex=3 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
 WPA: set own WPA/RSN IE - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
 nl80211: Associate (ifindex=3)
   * bssid=c0:4a:00:49:1b:f2
-  * freq=2462
+  * freq=2417
   * SSID - hexdump_ascii(len=5):
      50 72 61 64 61                                    Prada           
   * IEs - hexdump(len=32): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00 7f 08 00 00 0a 02 00 00 00 40
@@ -200,2369 +198,163 @@
   * vhtcaps - hexdump(len=12): 00 00 00 00 00 00 00 00 00 00 00 00
   * vhtcaps_mask - hexdump(len=12): 00 00 00 00 00 00 00 00 00 00 00 00
 nl80211: Association request send successfully
-nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION) received for wlan0
-nl80211: Delete station c0:4a:00:49:1b:f2
 nl80211: Drv Event 38 (NL80211_CMD_ASSOCIATE) received for wlan0
-nl80211: MLME event 38; timeout with c0:4a:00:49:1b:f2
-wlan0: Event ASSOC_TIMED_OUT (15) received
-wlan0: SME: Association timed out
-wlan0: Radio work 'sme-connect'@0x7fbf84e5a700 done in 0.137132 seconds
-Added BSSID c0:4a:00:49:1b:f2 into blacklist
-wlan0: Blacklist count 1 --> request scan in 100 ms
-wlan0: Setting scan request: 0.100000 sec
-wlan0: State: ASSOCIATING -> DISCONNECTED
-nl80211: Set wlan0 operstate 0->0 (DORMANT)
-netlink: Operstate: ifindex=3 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
-EAPOL: External notification - portEnabled=0
-EAPOL: External notification - portValid=0
-EAPOL: External notification - EAP success=0
-wlan0: State: DISCONNECTED -> SCANNING
-wlan0: Starting AP scan for wildcard SSID
-wlan0: Add radio work 'scan'@0x7fbf84e5a700
-wlan0: First radio work item in the queue - schedule start immediately
-wlan0: Starting radio work 'scan'@0x7fbf84e5a700 after 0.000006 second wait
-wlan0: nl80211: scan request
-Scan requested (ret=0) - scan timeout 30 seconds
-nl80211: Drv Event 33 (NL80211_CMD_TRIGGER_SCAN) received for wlan0
-wlan0: nl80211: Scan trigger
-wlan0: Event SCAN_STARTED (49) received
-wlan0: Own scan request started a scan in 0.000023 seconds
-RTM_NEWLINK: ifi_index=3 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1003 ([UP])
-nl80211: Drv Event 34 (NL80211_CMD_NEW_SCAN_RESULTS) received for wlan0
-wlan0: nl80211: New scan results available
-nl80211: Scan probed for SSID ''
-nl80211: Scan included frequencies: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472 5180 5200 5220 5240 5260 5280 5300 5320 5500 5520 5540 5560 5580 5600 5620 5640 5660 5680 5700 5745 5765 5785 5805 5825
-wlan0: Event SCAN_RESULTS (3) received
-wlan0: Scan completed in 3.245981 seconds
-nl80211: Received scan results (10 BSSes)
-wlan0: BSS: Start scan result update 2
-wlan0: BSS: Add new id 7 BSSID 4a:d9:e7:21:89:fb SSID 'Blumarin'
-wlan0: BSS: Add new id 8 BSSID 0a:18:d6:47:c3:8b SSID 'Blumarin'
-wlan0: BSS: Add new id 9 BSSID 14:cc:20:48:0c:7e SSID 'Elen2'
-BSS: last_scan_res_used=10/32
-wlan0: New scan results available (own=1 ext=0)
-WPS: AP 14:cc:20:48:0c:7e type 0 added
-WPS: AP[0] c0:4a:00:49:1b:f2 type=0 tries=0 last_attempt=-1 sec ago blacklist=1
-WPS: AP[1] f8:1a:67:91:c3:7c type=0 tries=0 last_attempt=-1 sec ago blacklist=0
-WPS: AP[2] f8:1a:67:d7:0b:5c type=0 tries=0 last_attempt=-1 sec ago blacklist=0
-WPS: AP[3] 54:e6:fc:bb:b9:fe type=0 tries=0 last_attempt=-1 sec ago blacklist=0
-WPS: AP[4] a0:f3:c1:d3:64:8c type=0 tries=0 last_attempt=-1 sec ago blacklist=0
-WPS: AP[5] 14:cc:20:48:0c:7e type=0 tries=0 last_attempt=-1 sec ago blacklist=0
-wlan0: Radio work 'scan'@0x7fbf84e5a700 done in 3.248987 seconds
-wlan0: Selecting BSS from priority group 0
-wlan0: 0: c0:4a:00:49:1b:f2 ssid='Prada' wpa_ie_len=22 rsn_ie_len=20 caps=0x431 level=-76 wps
-wlan0:    selected based on RSN IE
-wlan0:    selected BSS c0:4a:00:49:1b:f2 ssid='Prada'
-wlan0: Considering connect request: reassociate: 0  selected: c0:4a:00:49:1b:f2  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: SCANNING  ssid=0x7fbf84e3b0f0  current_ssid=(nil)
-wlan0: Request association with c0:4a:00:49:1b:f2
-wlan0: Re-association to the same ESS
-WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=7): 00 05 50 72 61 64 61
-WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=3): 03 01 0b
-WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=3): 2a 01 03
-WPA: RSN IE in EAPOL-Key - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
-WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=28): 33 1a ad 01 03 ff ff 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 04 06 e6 a7 0c 00
-WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=24): 3d 16 0b 07 17 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
-WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=24): 34 16 0b 07 17 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
-WPA: WPA IE in EAPOL-Key - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 04 01 00 00 50 f2 04 01 00 00 50 f2 02
+nl80211: Associate event
+wlan0: Event ASSOC (0) received

[-- Attachment #3: wifi-log-prada-bad.gz --]
[-- Type: application/gzip, Size: 9414 bytes --]

[-- Attachment #4: wifi-log-prada-good.gz --]
[-- Type: application/gzip, Size: 5350 bytes --]

Re: linux-only "freshness" auth problem??

[Michael Tokarev]

22.08.2015 11:51, Michael Tokarev wrote:

> Here are the main difference (- for bad, + for good):
>
>   nl80211: Association request send successfully
> -nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION) received for wlan0
> -nl80211: Delete station c0:4a:00:49:1b:f2
>   nl80211: Drv Event 38 (NL80211_CMD_ASSOCIATE) received for wlan0
> -nl80211: MLME event 38; timeout with c0:4a:00:49:1b:f2
> -wlan0: Event ASSOC_TIMED_OUT (15) received
> -wlan0: SME: Association timed out
> -wlan0: Radio work 'sme-connect'@0x7fbf84e5a700 done in 0.137132 seconds
> ...
>
> So in "good" case, there's one event, CMD_DEL_STATION, received
> right before the CMD_ASSOTIATE.  The rest look similar besides a
> few probably irrelevant details (timings, frequency, etc).

In "bad" case ofcourse :)

Thanks!

/mjt

Re: linux-only "freshness" auth problem??

[Johannes Berg]

> > Do you see any *kernel* messages after this? I'm half expecting to see
> > that the beacon never arrives, or something like that?
> 
> The kernel log is repeated.  The next log line is again scanning start,
> since NetworkManager (or wpa_supplicant, I'm not familiar with the machinery
> involved) request scan again.

Ok, that's interesting.

> > Are the hotels running similar equipment perhaps? If rebooting the AP
> > helps then perhaps the APs aren't actually beaconing quite properly -
> > maybe you could put the card into sniffer mode (monitor mode) and
> > capture what's going on over the air for a bit after this happened?
> 
> Can you give some more specific comments please?  We just rebooted the
> AP the next time, it all started working again, and I need to install
> all the necessary tools while it is working ;)  Since I'm not familiar
> with wifi machinery, maybe you can give me specific command lines to
> run? :)

Oh, well, there's some information here:

https://wireless.wiki.kernel.org/en/users/documentation/iw

iw wlan0 set type monitor
iw wlan0 set channel X
ip link set wlan0 up
tcpdump -i wlan0 -s0 -w /tmp/dump

could capture this on another machine.

johannes