AR9462 problems connecting again..

AR9462 problems connecting again..

[Linus Torvalds]

So I've had problems connecting to some networks before on my
Chromebook Pixel, but now I'm testing a new Ubiquiti network at home,
and can see this issue at home too.

I know the wireless works, because other devices work fine on that
network. Also, I know the AR9462 works, because I still have my old
network up and it connects to that.

And it *occasionally* connects to the new one. But it's rare, and it
clearly has problems.

It looks something like this:

[   73.757869] wlp1s0: authenticate with 20:9f:db:e7:80:80
[   73.771471] wlp1s0: send auth to 20:9f:db:e7:80:80 (try 1/3)
[   73.773706] wlp1s0: authenticated
[   73.775122] wlp1s0: associate with 20:9f:db:e7:80:80 (try 1/3)
[   73.787434] wlp1s0: RX AssocResp from 20:9f:db:e7:80:80
(capab=0x431 status=0 aid=9)
[   73.787573] wlp1s0: associated
[   77.784931] wlp1s0: deauthenticated from 20:9f:db:e7:80:80 (Reason:
2=PREV_AUTH_NOT_VALID)

and the password I used definitely is right, and sometimes works.
Despite that PREV_AUTH_NOT_VALID thing.

Any suggestions for what I should do to give you guys any sane and
useful debug output?

              Linus

Re: AR9462 problems connecting again..

[Sujith Manoharan]

Linus Torvalds wrote:
> So I've had problems connecting to some networks before on my
> Chromebook Pixel, but now I'm testing a new Ubiquiti network at home,
> and can see this issue at home too.

Can you please post the output of 'iw dev wlp1s0 scan' ?

Sujith

Re: AR9462 problems connecting again..

[Linus Torvalds]

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

On Sat, Feb 21, 2015 at 10:50 PM, Sujith Manoharan <sujith@msujith.org> wrote:
>
> Can you please post the output of 'iw dev wlp1s0 scan' ?

Attached.

It's the "UniFi-home" SSID that doesn't work. The 1gnoraNT one is the
old working one that I'm obviously associated with, and that has
multiple AP's.

(The UniFi-home also has two AP's, but they should all show up as a
single network)

                 Linus

[-- Attachment #2: out --]
[-- Type: application/octet-stream, Size: 4360 bytes --]

BSS 60:a4:4c:8d:99:24(on wlp1s0) -- associated
	TSF: 466674859 usec (0d, 00:07:46)
	freq: 5805
	beacon interval: 100 TUs
	capability: ESS Privacy (0x0011)
	signal: -17.00 dBm
	last seen: 178 ms ago
	Information elements from Probe Response frame:
	SSID: 1gnoraNT
	Supported rates: 6.0* 9.0 12.0* 18.0 24.0* 36.0 48.0 54.0 
	RSN:	 * Version: 1
		 * Group cipher: CCMP
		 * Pairwise ciphers: CCMP
		 * Authentication suites: PSK
		 * Capabilities: 16-PTKSA-RC 1-GTKSA-RC (0x000c)
	HT capabilities:
		Capabilities: 0x9bd
			RX LDPC
			HT20
			SM Power Save disabled
			RX Greenfield
			RX HT20 SGI
			TX STBC
			RX STBC 1-stream
			Max AMSDU length: 7935 bytes
			No DSSS/CCK HT40
		Maximum RX AMPDU length 65535 bytes (exponent: 0x003)
		Minimum RX AMPDU time spacing: 4 usec (0x05)
		HT RX MCS rate indexes supported: 0-23
		HT TX MCS rate indexes are undefined
	HT operation:
		 * primary channel: 161
		 * secondary channel offset: no secondary
		 * STA channel width: 20 MHz
		 * RIFS: 1
		 * HT protection: no
		 * non-GF present: 1
		 * OBSS non-GF present: 0
		 * dual beacon: 0
		 * dual CTS protection: 0
		 * STBC beacon: 0
		 * L-SIG TXOP Prot: 0
		 * PCO active: 0
		 * PCO phase: 0
	Extended capabilities: 6
	WMM:	 * Parameter version 1
		 * u-APSD
		 * BE: CW 15-1023, AIFSN 3
		 * BK: CW 15-1023, AIFSN 7
		 * VI: CW 7-15, AIFSN 2, TXOP 3008 usec
		 * VO: CW 3-7, AIFSN 2, TXOP 1504 usec
BSS 60:a4:4c:8d:99:20(on wlp1s0)
	TSF: 474695613 usec (0d, 00:07:54)
	freq: 2437
	beacon interval: 100 TUs
	capability: ESS Privacy ShortSlotTime (0x0411)
	signal: 1.00 dBm
	last seen: 6708 ms ago
	Information elements from Probe Response frame:
	SSID: 1gnoraNT
	Supported rates: 1.0* 2.0* 5.5* 11.0* 18.0 24.0 36.0 54.0 
	DS Parameter set: channel 6
	ERP: <no flags>
	ERP D4.0: <no flags>
	RSN:	 * Version: 1
		 * Group cipher: CCMP
		 * Pairwise ciphers: CCMP
		 * Authentication suites: PSK
		 * Capabilities: 16-PTKSA-RC 1-GTKSA-RC (0x000c)
	Extended supported rates: 6.0 9.0 12.0 48.0 
	HT capabilities:
		Capabilities: 0x19bd
			RX LDPC
			HT20
			SM Power Save disabled
			RX Greenfield
			RX HT20 SGI
			TX STBC
			RX STBC 1-stream
			Max AMSDU length: 7935 bytes
			DSSS/CCK HT40
		Maximum RX AMPDU length 65535 bytes (exponent: 0x003)
		Minimum RX AMPDU time spacing: 4 usec (0x05)
		HT RX MCS rate indexes supported: 0-23
		HT TX MCS rate indexes are undefined
	HT operation:
		 * primary channel: 6
		 * secondary channel offset: no secondary
		 * STA channel width: 20 MHz
		 * RIFS: 1
		 * HT protection: no
		 * non-GF present: 1
		 * OBSS non-GF present: 0
		 * dual beacon: 0
		 * dual CTS protection: 0
		 * STBC beacon: 0
		 * L-SIG TXOP Prot: 0
		 * PCO active: 0
		 * PCO phase: 0
	Extended capabilities: 6
	WMM:	 * Parameter version 1
		 * u-APSD
		 * BE: CW 15-1023, AIFSN 3
		 * BK: CW 15-1023, AIFSN 7
		 * VI: CW 7-15, AIFSN 2, TXOP 3008 usec
		 * VO: CW 3-7, AIFSN 2, TXOP 1504 usec
BSS 20:9f:db:e7:80:80(on wlp1s0)
	TSF: 160767143950 usec (1d, 20:39:27)
	freq: 2462
	beacon interval: 100 TUs
	capability: ESS Privacy ShortPreamble ShortSlotTime (0x0431)
	signal: -49.00 dBm
	last seen: 6652 ms ago
	Information elements from Probe Response frame:
	SSID: UniFi-home
	Supported rates: 1.0* 2.0* 5.5* 11.0* 6.0* 9.0 12.0* 18.0 
	DS Parameter set: channel 11
	ERP: <no flags>
	RSN:	 * Version: 1
		 * Group cipher: CCMP
		 * Pairwise ciphers: CCMP
		 * Authentication suites: PSK
		 * Capabilities: 1-PTKSA-RC 1-GTKSA-RC (0x0000)
	Extended supported rates: 24.0* 36.0 48.0 54.0 
	HT capabilities:
		Capabilities: 0x1ac
			HT20
			SM Power Save disabled
			RX HT20 SGI
			TX STBC
			RX STBC 1-stream
			Max AMSDU length: 3839 bytes
			No DSSS/CCK HT40
		Maximum RX AMPDU length 65535 bytes (exponent: 0x003)
		Minimum RX AMPDU time spacing: 8 usec (0x06)
		HT RX MCS rate indexes supported: 0-15
		HT TX MCS rate indexes are undefined
	HT operation:
		 * primary channel: 11
		 * secondary channel offset: no secondary
		 * STA channel width: 20 MHz
		 * RIFS: 1
		 * HT protection: no
		 * non-GF present: 1
		 * OBSS non-GF present: 0
		 * dual beacon: 0
		 * dual CTS protection: 0
		 * STBC beacon: 0
		 * L-SIG TXOP Prot: 0
		 * PCO active: 0
		 * PCO phase: 0
	WMM:	 * Parameter version 1
		 * BE: CW 15-1023, AIFSN 3
		 * BK: CW 15-1023, AIFSN 7
		 * VI: CW 7-15, AIFSN 2, TXOP 3008 usec
		 * VO: CW 3-7, AIFSN 2, TXOP 1504 usec

Re: AR9462 problems connecting again..

[Adrian Chadd]

On 21 February 2015 at 15:34, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
> So I've had problems connecting to some networks before on my
> Chromebook Pixel, but now I'm testing a new Ubiquiti network at home,
> and can see this issue at home too.
>
> I know the wireless works, because other devices work fine on that
> network. Also, I know the AR9462 works, because I still have my old
> network up and it connects to that.
>
> And it *occasionally* connects to the new one. But it's rare, and it
> clearly has problems.
>
> It looks something like this:
>
> [   73.757869] wlp1s0: authenticate with 20:9f:db:e7:80:80
> [   73.771471] wlp1s0: send auth to 20:9f:db:e7:80:80 (try 1/3)
> [   73.773706] wlp1s0: authenticated
> [   73.775122] wlp1s0: associate with 20:9f:db:e7:80:80 (try 1/3)
> [   73.787434] wlp1s0: RX AssocResp from 20:9f:db:e7:80:80
> (capab=0x431 status=0 aid=9)
> [   73.787573] wlp1s0: associated
> [   77.784931] wlp1s0: deauthenticated from 20:9f:db:e7:80:80 (Reason:
> 2=PREV_AUTH_NOT_VALID)
>
> and the password I used definitely is right, and sometimes works.
> Despite that PREV_AUTH_NOT_VALID thing.
>
> Any suggestions for what I should do to give you guys any sane and
> useful debug output?

Just a wild shot - try disabling fast authentication and see if that
makes a difference?

wpa_supplicant.conf:

fast_reauth=0

I recall having issues with fast_reauth once, but I never stuck around
that location long enough to debug it.




-adrian

Re: AR9462 problems connecting again..

[Linus Torvalds]

On Sun, Feb 22, 2015 at 10:24 AM, Adrian Chadd <adrian@freebsd.org> wrote:
>
> Just a wild shot - try disabling fast authentication and see if that
> makes a difference?
>
> wpa_supplicant.conf:
>
> fast_reauth=0
>
> I recall having issues with fast_reauth once, but I never stuck around
> that location long enough to debug it.

Nope. Did that, killed wpa_supplicant (which restarts it), tried
connecting, still failed.

                          Linus

Re: [ath9k-devel] AR9462 problems connecting again..

[Dave Taht]

On Sun, Feb 22, 2015 at 10:30 AM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
> On Sun, Feb 22, 2015 at 10:24 AM, Adrian Chadd <adrian@freebsd.org> wrote:
>>
>> Just a wild shot - try disabling fast authentication and see if that
>> makes a difference?
>>
>> wpa_supplicant.conf:
>>
>> fast_reauth=0
>>
>> I recall having issues with fast_reauth once, but I never stuck around
>> that location long enough to debug it.
>
> Nope. Did that, killed wpa_supplicant (which restarts it), tried
> connecting, still failed.

Hint: Several unifi (and most ubnt) products are well supported by
openwrt directly, which by reflashing your device to it via their web
interface would

A) probably fix the problem, and
B) give you more insight into fixing it, if it persists, by giving you
full access on both sides of the connection.

https://downloads.openwrt.org/snapshots/trunk/ar71xx/generic/

I have been replacing ubnt´s default firmware on first boot for 6+
years now. It is good hardware, after you do that.

-- 
Dave Täht

http://www.bufferbloat.net/projects/cerowrt/wiki

Re: [ath9k-devel] AR9462 problems connecting again..

[Linus Torvalds]

On Sun, Feb 22, 2015 at 10:58 AM, Dave Taht <dave.taht@gmail.com> wrote:
>
> Hint: Several unifi (and most ubnt) products are well supported by
> openwrt directly,

I want Linux to "just work". None of this "oh, you can change
something else and it probably works".  I want to fix the problem in
*linux*.

There's clearly something wrong with the AR9462 driver and/or how it
uses the wireless infrastructure, and it should be fixed. Not worked
around with "use some other AP software".

Especially since this has happened before.

Besides, the reason I'm trying to use UniFi is because I want to have
seamless roaming ("zero-handoff"). And I do *not* want to play the
endless openwrt configuration games in the hopes I can get something
like that working. I've tried openwrt, and I don't like tinkering with
my AP's. I just want things to work out of the box.

                          Linus

Re: [ath9k-devel] AR9462 problems connecting again..

[Kyle Bassett]

On Sun, Feb 22, 2015 at 4:54 PM, Kyle Bassett <kylebassett@gmail.com> wrote:
> On Sun, Feb 22, 2015 at 4:45 PM, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
>>
>> On Sun, Feb 22, 2015 at 10:58 AM, Dave Taht <dave.taht@gmail.com> wrote:
>> >
>> > Hint: Several unifi (and most ubnt) products are well supported by
>> > openwrt directly,
>>
>> I want Linux to "just work". None of this "oh, you can change
>> something else and it probably works".  I want to fix the problem in
>> *linux*.
>>
>>
>> There's clearly something wrong with the AR9462 driver and/or how it
>> uses the wireless infrastructure, and it should be fixed. Not worked
>> around with "use some other AP software".
>>
>


A side note on this, what is the current method for unit testing WAP's and
client devices?  I'm sure every vendor has their own flavor, although I feel
some clearly defined FOSS method should exist as well.

I bring this up is because I have personally experienced bugs inside the
UniFi offerings, and on miscellaneous Linux/non-linux client devices as
well.

Re: AR9462 problems connecting again..

[Adrian Chadd]

On 22 February 2015 at 10:30, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
> On Sun, Feb 22, 2015 at 10:24 AM, Adrian Chadd <adrian@freebsd.org> wrote:
>>
>> Just a wild shot - try disabling fast authentication and see if that
>> makes a difference?
>>
>> wpa_supplicant.conf:
>>
>> fast_reauth=0
>>
>> I recall having issues with fast_reauth once, but I never stuck around
>> that location long enough to debug it.
>
> Nope. Did that, killed wpa_supplicant (which restarts it), tried
> connecting, still failed.

Hm, can you enable wpa debugging to log everything whilst it's
associating / reassociating?

(maybe log_devel debug? I tend to run wpa_supplicant at the command
line with debugging enabled, rather than doing it after-the-fact.)




-adrian

Re: AR9462 problems connecting again..

[Linus Torvalds]

On Sun, Feb 22, 2015 at 11:39 AM, Adrian Chadd <adrian@freebsd.org> wrote:
>
> Hm, can you enable wpa debugging to log everything whilst it's
> associating / reassociating?

Ugh. When I add "-dd" to the command line, it has now worked three
times in a row, when before it worked once out of ten tries.

So my guess is that it's something timing-dependent.

Or it's something where once it starts working, it stays working until
I reboot. I'll try that.

                         Linus

Re: AR9462 problems connecting again..

[Linus Torvalds]

On Sun, Feb 22, 2015 at 1:50 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> Ugh. When I add "-dd" to the command line, it has now worked three
> times in a row, when before it worked once out of ten tries.
>
> So my guess is that it's something timing-dependent.

So it stays working with -dd, but I do get *occasional* failures that
then seem to clear up on retry. So it ends up working in the end, but
I think I have a few example failures in the logs.

So for example, from my dmesg, I get this:

[14:07:15] wlp1s0: authenticate with 20:9f:db:e7:80:80
[14:07:15] wlp1s0: send auth to 20:9f:db:e7:80:80 (try 1/3)
[14:07:15] wlp1s0: send auth to 20:9f:db:e7:80:80 (try 2/3)
[14:07:15] wlp1s0: send auth to 20:9f:db:e7:80:80 (try 3/3)
[14:07:15] wlp1s0: authentication with 20:9f:db:e7:80:80 timed out
[14:07:18] wlp1s0: authenticate with 20:9f:db:e7:80:80
[14:07:18] wlp1s0: send auth to 20:9f:db:e7:80:80 (try 1/3)
[14:07:18] wlp1s0: authenticated
[14:07:18] wlp1s0: associate with 20:9f:db:e7:80:80 (try 1/3)
[14:07:18] wlp1s0: RX AssocResp from 20:9f:db:e7:80:80 (capab=0x431
status=0 aid=16)
[14:07:18] wlp1s0: associated
[14:07:22] wlp1s0: deauthenticated from 20:9f:db:e7:80:80 (Reason:
2=PREV_AUTH_NOT_VALID)

with another failure at 14:07:22, but then it ends up working a bit
later at 14:07:33.

I've got the wpa supplicant log for this timeframe, but I'd rather not
send it out in public. I see "[REMOVED] for what looks like the key
data, but there's a lot of other hex data. Is any of it sensitive?

                                  Linus

Re: AR9462 problems connecting again..

[Adrian Chadd]

On 22 February 2015 at 15:00, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
> On Sun, Feb 22, 2015 at 1:50 PM, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
>>
>> Ugh. When I add "-dd" to the command line, it has now worked three
>> times in a row, when before it worked once out of ten tries.
>>
>> So my guess is that it's something timing-dependent.
>
> So it stays working with -dd, but I do get *occasional* failures that
> then seem to clear up on retry. So it ends up working in the end, but
> I think I have a few example failures in the logs.
>
> So for example, from my dmesg, I get this:
>
> [14:07:15] wlp1s0: authenticate with 20:9f:db:e7:80:80
> [14:07:15] wlp1s0: send auth to 20:9f:db:e7:80:80 (try 1/3)
> [14:07:15] wlp1s0: send auth to 20:9f:db:e7:80:80 (try 2/3)
> [14:07:15] wlp1s0: send auth to 20:9f:db:e7:80:80 (try 3/3)
> [14:07:15] wlp1s0: authentication with 20:9f:db:e7:80:80 timed out
> [14:07:18] wlp1s0: authenticate with 20:9f:db:e7:80:80
> [14:07:18] wlp1s0: send auth to 20:9f:db:e7:80:80 (try 1/3)
> [14:07:18] wlp1s0: authenticated
> [14:07:18] wlp1s0: associate with 20:9f:db:e7:80:80 (try 1/3)
> [14:07:18] wlp1s0: RX AssocResp from 20:9f:db:e7:80:80 (capab=0x431
> status=0 aid=16)
> [14:07:18] wlp1s0: associated
> [14:07:22] wlp1s0: deauthenticated from 20:9f:db:e7:80:80 (Reason:
> 2=PREV_AUTH_NOT_VALID)
>
> with another failure at 14:07:22, but then it ends up working a bit
> later at 14:07:33.
>
> I've got the wpa supplicant log for this timeframe, but I'd rather not
> send it out in public. I see "[REMOVED] for what looks like the key
> data, but there's a lot of other hex data. Is any of it sensitive?

I /think/ it's okay? The removed stuff is the pre-shared key pieces.

So if I were debugging this (on any OS); I'd start by looking at
what's going on over the air. I'd be worried that there's something
failing to transmit right / be heard by the recipient. In the past
it's been things like EAPOL frames not going out at basic rate (and
listening to the rate control code for what rate it should be
transmitted at) and that makes it transmit at rates wholly unsuited
for the initial handshake.

Do you have another laptop with an atheros NIC in it that you could
use in monitor mode to capture all the frames?

(Also, you can email me the log file privately if you'd like.)



-adrian

Re: AR9462 problems connecting again..

[Linus Torvalds]

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

On Sun, Feb 22, 2015 at 4:54 PM, Adrian Chadd <adrian@freebsd.org> wrote:
>
> I /think/ it's okay? The removed stuff is the pre-shared key pieces.

Ok. Attached is what seems to be the relevant part of the
wpa_supplicant.log file.

The datestamp has been changed so that it can be matched up with the
dmesg, and I added empty lines for pauses when I was trying to figure
out what the heck it was doing, but other than that it's the raw log.

> Do you have another laptop with an atheros NIC in it that you could
> use in monitor mode to capture all the frames?

Nope, everything else I have seems to be intel wireless. I think one
of the kids machines is a Mac Mini with an ath5k thing, but I'm hoping
the wpa_supplicant.log is sufficient to give somebody an idea.

                            Linus

[-- Attachment #2: wpa_supplicant.log --]
[-- Type: text/x-log, Size: 41341 bytes --]


14:07:10.971480: EAPOL: disable timer tick
14:07:10.971578: EAPOL: Supplicant port status: Unauthorized


14:07:12.886125: nl80211: Event message available
14:07:12.886287: nl80211: Regulatory beacon hint
14:07:12.886318: wlp1s0: Event CHANNEL_LIST_CHANGED (31) received
14:07:12.886608: nl80211: Regulatory information - country=US
14:07:12.886646: nl80211: 2402-2472 @ 40 MHz
14:07:12.886670: nl80211: 5170-5250 @ 80 MHz
14:07:12.886691: nl80211: 5250-5330 @ 80 MHz
14:07:12.886711: nl80211: 5490-5600 @ 80 MHz
14:07:12.886733: nl80211: 5650-5710 @ 40 MHz
14:07:12.886755: nl80211: 5735-5835 @ 80 MHz
14:07:12.886777: nl80211: 57240-63720 @ 2160 MHz
14:07:12.886822: nl80211: Added 802.11b mode based on 802.11g information
14:07:12.886848: P2P: Add operating class 81
14:07:12.886870: P2P: Channels - hexdump(len=11): 01 02 03 04 05 06 07 08 09 0a 0b
14:07:12.886902: P2P: Add operating class 124
14:07:12.886921: P2P: Channels - hexdump(len=1): a1
14:07:12.886948: wlp1s0: P2P: Update channel list

14:07:13.011791: nl80211: Event message available
14:07:13.011987: nl80211: New scan results available
14:07:13.012055: wlp1s0: Event SCAN_RESULTS (3) received
14:07:13.012281: nl80211: Received scan results (3 BSSes)
14:07:13.012464: wlp1s0: BSS: Start scan result update 1
14:07:13.012501: wlp1s0: BSS: Add new id 0 BSSID 60:a4:4c:8d:99:24 SSID '1gnoraNT'
14:07:13.012530: dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/7/BSSs/0'
14:07:13.012745: wlp1s0: BSS: Add new id 1 BSSID 60:a4:4c:8d:99:20 SSID '1gnoraNT'
14:07:13.012767: dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/7/BSSs/1'
14:07:13.012905: wlp1s0: BSS: Add new id 2 BSSID 20:9f:db:e7:80:80 SSID 'UniFi-home'
14:07:13.012925: dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/7/BSSs/2'
14:07:13.013080: BSS: last_scan_res_used=3/32 last_scan_full=0
14:07:13.013115: wlp1s0: New scan results available
14:07:13.013191: wlp1s0: No suitable network found
14:07:13.013209: wlp1s0: Short-circuit new scan request since there are no enabled networks
14:07:13.013221: wlp1s0: State: DISCONNECTED -> INACTIVE
14:07:13.013272: wlp1s0: Checking for other virtual interfaces sharing same radio (phy0) in event_scan_results
14:07:13.014248: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
14:07:13.014265: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlp1s0' added
14:07:13.014412: nl80211: if_removed already cleared - ignore event
14:07:13.017250: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7

14:07:13.060305: dbus: Register network object '/fi/w1/wpa_supplicant1/Interfaces/7/Networks/0'

14:07:13.072845: wlp1s0: Setting scan request: 0 sec 0 usec
14:07:13.073000: wlp1s0: State: INACTIVE -> SCANNING
14:07:13.073054: Scan SSID - hexdump_ascii(len=10):
     55 6e 69 46 69 2d 68 6f 6d 65                     UniFi-home      
14:07:13.073078: wlp1s0: Starting AP scan for wildcard SSID
14:07:13.073088: WPS: Building WPS IE for Probe Request
14:07:13.073096: WPS:  * Version (hardcoded 0x10)
14:07:13.073104: WPS:  * Request Type
14:07:13.073111: WPS:  * Config Methods (108)
14:07:13.073129: WPS:  * UUID-E
14:07:13.073137: WPS:  * Primary Device Type
14:07:13.073145: WPS:  * RF Bands (3)
14:07:13.073153: WPS:  * Association State
14:07:13.073160: WPS:  * Configuration Error (0)
14:07:13.073167: WPS:  * Device Password ID (0)
14:07:13.073175: WPS:  * Device Name
14:07:13.073184: P2P: * P2P IE header
14:07:13.073192: P2P: * Capability dev=25 group=00
14:07:13.073200: P2P: * Listen Channel: Regulatory Class 81 Channel 1
14:07:13.077659: Scan requested (ret=0) - scan timeout 30 seconds
14:07:13.077697: nl80211: Event message available
14:07:13.077716: nl80211: Scan trigger
14:07:13.078248: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7


14:07:16.056351: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
14:07:16.056498: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlp1s0' added
14:07:16.056652: nl80211: if_removed already cleared - ignore event
14:07:16.056728: nl80211: Event message available
14:07:16.056810: nl80211: New scan results available
14:07:16.056879: wlp1s0: Event SCAN_RESULTS (3) received
14:07:16.057386: nl80211: Received scan results (3 BSSes)
14:07:16.057735: wlp1s0: BSS: Start scan result update 2
14:07:16.057828: BSS: last_scan_res_used=3/32 last_scan_full=0
14:07:16.057870: wlp1s0: New scan results available
14:07:16.058086: wlp1s0: Selecting BSS from priority group 0
14:07:16.058181: wlp1s0: 0: 60:a4:4c:8d:99:24 ssid='1gnoraNT' wpa_ie_len=0 rsn_ie_len=20 caps=0x11 level=-20
14:07:16.058237: wlp1s0:    skip - SSID mismatch
14:07:16.058298: wlp1s0: 1: 60:a4:4c:8d:99:20 ssid='1gnoraNT' wpa_ie_len=0 rsn_ie_len=20 caps=0x411 level=37
14:07:16.058348: wlp1s0:    skip - SSID mismatch
14:07:16.058379: wlp1s0: 2: 20:9f:db:e7:80:80 ssid='UniFi-home' wpa_ie_len=0 rsn_ie_len=20 caps=0x431 level=-68
14:07:16.058404: wlp1s0:    selected based on RSN IE
14:07:16.058445: wlp1s0:    selected BSS 20:9f:db:e7:80:80 ssid='UniFi-home'
14:07:16.058471: wlp1s0: Request association: reassociate: 1  selected: 20:9f:db:e7:80:80  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: SCANNING
14:07:16.058496: wlp1s0: Automatic auth_alg selection: 0x1
14:07:16.058515: RSN: PMKSA cache search - network_ctx=0x7f0ab41bf340 try_opportunistic=0
14:07:16.058533: RSN: Search for BSSID 20:9f:db:e7:80:80
14:07:16.058550: RSN: No PMKSA cache entry found
14:07:16.058568: wlp1s0: RSN: using IEEE 802.11i/D9.0
14:07:16.058589: wlp1s0: WPA: Selected cipher suites: group 16 pairwise 16 key_mgmt 2 proto 2
14:07:16.058607: wlp1s0: WPA: clearing AP WPA IE
14:07:16.058628: WPA: set AP 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
14:07:16.058660: wlp1s0: WPA: using GTK CCMP
14:07:16.058680: wlp1s0: WPA: using PTK CCMP
14:07:16.058697: wlp1s0: WPA: using KEY_MGMT WPA-PSK
14:07:16.058715: 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
14:07:16.058764: wlp1s0: Cancelling scan request
14:07:16.058793: wlp1s0: SME: Trying to authenticate with 20:9f:db:e7:80:80 (SSID='UniFi-home' freq=2462 MHz)
14:07:16.058815: wlp1s0: No keys have been configured - skip key clearing
14:07:16.058844: wlp1s0: State: SCANNING -> AUTHENTICATING
14:07:16.058961: EAPOL: External notification - EAP success=0
14:07:16.058998: EAPOL: Supplicant port status: Unauthorized
14:07:16.059166: EAPOL: External notification - EAP fail=0
14:07:16.059202: EAPOL: Supplicant port status: Unauthorized
14:07:16.059283: EAPOL: External notification - portControl=Auto
14:07:16.059312: EAPOL: Supplicant port status: Unauthorized
14:07:16.059389: nl80211: Authenticate (ifindex=3)
14:07:16.059418:   * bssid=20:9f:db:e7:80:80
14:07:16.059441:   * freq=2462
14:07:16.059466:   * SSID - hexdump_ascii(len=10):
     55 6e 69 46 69 2d 68 6f 6d 65                     UniFi-home      
14:07:16.059506:   * IEs - hexdump(len=0): [NULL]
14:07:16.059525:   * Auth Type 0

14:07:16.071731: nl80211: Authentication request send successfully
14:07:16.071811: RSN: Ignored PMKID candidate without preauth flag
14:07:16.071859: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7
14:07:16.072060: nl80211: Event message available
14:07:16.072097: nl80211: New station 20:9f:db:e7:80:80
14:07:16.072121: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7/BSSs/0
14:07:16.072218: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7/BSSs/1
14:07:16.072307: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7/BSSs/2

14:07:16.384167: nl80211: Event message available
14:07:16.384298: nl80211: Delete station 20:9f:db:e7:80:80
14:07:16.390554: nl80211: Event message available
14:07:16.390659: nl80211: MLME event 37; timeout with 20:9f:db:e7:80:80
14:07:16.390702: wlp1s0: Event AUTH_TIMED_OUT (14) received
14:07:16.390739: wlp1s0: SME: Authentication timed out
14:07:16.390759: Added BSSID 20:9f:db:e7:80:80 into blacklist
14:07:16.390781: wlp1s0: Blacklist count 1 --> request scan in 100 ms
14:07:16.390800: wlp1s0: Setting scan request: 0 sec 100000 usec
14:07:16.390820: wlp1s0: State: AUTHENTICATING -> DISCONNECTED
14:07:16.390836: wpa_driver_nl80211_set_operstate: operstate 0->0 (DORMANT)
14:07:16.390853: netlink: Operstate: linkmode=-1, operstate=5
14:07:16.391010: EAPOL: External notification - portEnabled=0
14:07:16.391084: EAPOL: Supplicant port status: Unauthorized
14:07:16.391235: EAPOL: External notification - portValid=0
14:07:16.391259: EAPOL: Supplicant port status: Unauthorized
14:07:16.391324: EAPOL: External notification - EAP success=0
14:07:16.391345: EAPOL: Supplicant port status: Unauthorized
14:07:16.396129: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7

14:07:16.490997: wlp1s0: State: DISCONNECTED -> SCANNING
14:07:16.491298: Scan SSID - hexdump_ascii(len=10):
     55 6e 69 46 69 2d 68 6f 6d 65                     UniFi-home      
14:07:16.491376: wlp1s0: Starting AP scan for wildcard SSID
14:07:16.491402: WPS: Building WPS IE for Probe Request
14:07:16.491423: WPS:  * Version (hardcoded 0x10)
14:07:16.491443: WPS:  * Request Type
14:07:16.491460: WPS:  * Config Methods (108)
14:07:16.491479: WPS:  * UUID-E
14:07:16.491497: WPS:  * Primary Device Type
14:07:16.491516: WPS:  * RF Bands (3)
14:07:16.491539: WPS:  * Association State
14:07:16.491556: WPS:  * Configuration Error (0)
14:07:16.491573: WPS:  * Device Password ID (0)
14:07:16.491590: WPS:  * Device Name
14:07:16.491614: P2P: * P2P IE header
14:07:16.491632: P2P: * Capability dev=25 group=00
14:07:16.491650: P2P: * Listen Channel: Regulatory Class 81 Channel 1
14:07:16.497711: Scan requested (ret=0) - scan timeout 30 seconds
14:07:16.497785: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7
14:07:16.497961: nl80211: Event message available
14:07:16.497997: nl80211: Scan trigger



14:07:19.476335: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
14:07:19.476615: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlp1s0' added
14:07:19.476778: nl80211: if_removed already cleared - ignore event
14:07:19.476858: nl80211: Event message available
14:07:19.476924: nl80211: New scan results available
14:07:19.476964: wlp1s0: Event SCAN_RESULTS (3) received
14:07:19.477246: nl80211: Received scan results (3 BSSes)
14:07:19.477430: wlp1s0: BSS: Start scan result update 3
14:07:19.477481: BSS: last_scan_res_used=3/32 last_scan_full=0
14:07:19.477507: wlp1s0: New scan results available
14:07:19.477590: wlp1s0: Selecting BSS from priority group 0
14:07:19.477621: wlp1s0: 0: 60:a4:4c:8d:99:24 ssid='1gnoraNT' wpa_ie_len=0 rsn_ie_len=20 caps=0x11 level=-21
14:07:19.477666: wlp1s0:    skip - SSID mismatch
14:07:19.477689: wlp1s0: 1: 60:a4:4c:8d:99:20 ssid='1gnoraNT' wpa_ie_len=0 rsn_ie_len=20 caps=0x411 level=35
14:07:19.477707: wlp1s0:    skip - SSID mismatch
14:07:19.477727: wlp1s0: 2: 20:9f:db:e7:80:80 ssid='UniFi-home' wpa_ie_len=0 rsn_ie_len=20 caps=0x431 level=-57
14:07:19.477745: wlp1s0:    skip - blacklisted (count=1 limit=0)
14:07:19.477761: wlp1s0: No APs found - clear blacklist and try again
14:07:19.477776: Removed BSSID 20:9f:db:e7:80:80 from blacklist (clear)
14:07:19.477795: wlp1s0: Selecting BSS from priority group 0
14:07:19.477815: wlp1s0: 0: 60:a4:4c:8d:99:24 ssid='1gnoraNT' wpa_ie_len=0 rsn_ie_len=20 caps=0x11 level=-21
14:07:19.477831: wlp1s0:    skip - SSID mismatch
14:07:19.477851: wlp1s0: 1: 60:a4:4c:8d:99:20 ssid='1gnoraNT' wpa_ie_len=0 rsn_ie_len=20 caps=0x411 level=35
14:07:19.477875: wlp1s0:    skip - SSID mismatch
14:07:19.477907: wlp1s0: 2: 20:9f:db:e7:80:80 ssid='UniFi-home' wpa_ie_len=0 rsn_ie_len=20 caps=0x431 level=-57
14:07:19.477936: wlp1s0:    selected based on RSN IE
14:07:19.477971: wlp1s0:    selected BSS 20:9f:db:e7:80:80 ssid='UniFi-home'
14:07:19.478009: wlp1s0: Request association: reassociate: 0  selected: 20:9f:db:e7:80:80  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: SCANNING
14:07:19.478064: wlp1s0: Automatic auth_alg selection: 0x1
14:07:19.478090: RSN: PMKSA cache search - network_ctx=(nil) try_opportunistic=0
14:07:19.478113: RSN: Search for BSSID 20:9f:db:e7:80:80
14:07:19.478138: RSN: No PMKSA cache entry found
14:07:19.478163: wlp1s0: RSN: using IEEE 802.11i/D9.0
14:07:19.478190: wlp1s0: WPA: Selected cipher suites: group 16 pairwise 16 key_mgmt 2 proto 2
14:07:19.478218: wlp1s0: WPA: clearing AP WPA IE
14:07:19.478244: WPA: set AP 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
14:07:19.478293: wlp1s0: WPA: using GTK CCMP
14:07:19.478317: wlp1s0: WPA: using PTK CCMP
14:07:19.478334: wlp1s0: WPA: using KEY_MGMT WPA-PSK
14:07:19.478351: 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
14:07:19.478381: wlp1s0: Cancelling scan request
14:07:19.478402: wlp1s0: SME: Trying to authenticate with 20:9f:db:e7:80:80 (SSID='UniFi-home' freq=2462 MHz)
14:07:19.478419: wlp1s0: No keys have been configured - skip key clearing
14:07:19.478437: wlp1s0: State: SCANNING -> AUTHENTICATING
14:07:19.478529: EAPOL: External notification - EAP success=0
14:07:19.478554: EAPOL: Supplicant port status: Unauthorized
14:07:19.478668: EAPOL: External notification - EAP fail=0
14:07:19.478691: EAPOL: Supplicant port status: Unauthorized
14:07:19.478757: EAPOL: External notification - portControl=Auto
14:07:19.478777: EAPOL: Supplicant port status: Unauthorized
14:07:19.478850: nl80211: Authenticate (ifindex=3)
14:07:19.478873:   * bssid=20:9f:db:e7:80:80
14:07:19.478890:   * freq=2462
14:07:19.478905:   * SSID - hexdump_ascii(len=10):
     55 6e 69 46 69 2d 68 6f 6d 65                     UniFi-home      
14:07:19.478936:   * IEs - hexdump(len=0): [NULL]
14:07:19.478952:   * Auth Type 0
14:07:19.491512: nl80211: Authentication request send successfully
14:07:19.491554: RSN: Ignored PMKID candidate without preauth flag
14:07:19.491585: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7
14:07:19.491738: nl80211: Event message available
14:07:19.491771: nl80211: New station 20:9f:db:e7:80:80
14:07:19.491796: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7/BSSs/0
14:07:19.491898: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7/BSSs/1
14:07:19.491997: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7/BSSs/2
14:07:19.493794: nl80211: Event message available
14:07:19.493878: nl80211: MLME event 37
14:07:19.493911: nl80211: Authenticate event
14:07:19.493930: wlp1s0: Event AUTH (11) received
14:07:19.493951: wlp1s0: SME: Authentication response: peer=20:9f:db:e7:80:80 auth_type=0 auth_transaction=2 status_code=0
14:07:19.493971: wlp1s0: Trying to associate with 20:9f:db:e7:80:80 (SSID='UniFi-home' freq=2462 MHz)
14:07:19.493987: wlp1s0: State: AUTHENTICATING -> ASSOCIATING
14:07:19.494001: wpa_driver_nl80211_set_operstate: operstate 0->0 (DORMANT)
14:07:19.494016: netlink: Operstate: linkmode=-1, operstate=5
14:07:19.494181: 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
14:07:19.494223: nl80211: Associate (ifindex=3)
14:07:19.494245:   * bssid=20:9f:db:e7:80:80
14:07:19.494264:   * freq=2462
14:07:19.494279:   * SSID - hexdump_ascii(len=10):
     55 6e 69 46 69 2d 68 6f 6d 65                     UniFi-home      
14:07:19.494315:   * IEs - 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
14:07:19.494335:   * pairwise=0xfac04
14:07:19.494347:   * group=0xfac04
14:07:19.494401: nl80211: Association request send successfully
14:07:19.499290: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7
14:07:19.502837: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
14:07:19.502888: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlp1s0' added
14:07:19.502958: nl80211: if_removed already cleared - ignore event
14:07:19.502985: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
14:07:19.503004: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlp1s0' added
14:07:19.503066: nl80211: if_removed already cleared - ignore event
14:07:19.503092: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
14:07:19.503111: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlp1s0' added
14:07:19.503152: nl80211: if_removed already cleared - ignore event
14:07:19.503176: nl80211: Event message available
14:07:19.503216: nl80211: MLME event 38
14:07:19.503237: nl80211: Associate event
14:07:19.503259: wlp1s0: Event ASSOC (0) received
14:07:19.503279: wlp1s0: Association info event
14:07:19.503298: resp_ies - hexdump(len=146): 01 08 02 04 0b 0c 12 16 18 24 32 04 30 48 60 6c 2d 1a ac 01 1b ff ff 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 33 1a ac 01 1b ff ff 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3d 16 0b 08 0c 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 34 16 0b 08 0c 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 dd 18 00 50 f2 02 01 01 01 00 03 a4 00 00 27 a4 00 00 42 43 5e 00 62 32 2f 00
14:07:19.503397: wlp1s0: freq=2462 MHz
14:07:19.503411: wlp1s0: State: ASSOCIATING -> ASSOCIATED
14:07:19.503424: wpa_driver_nl80211_set_operstate: operstate 0->0 (DORMANT)
14:07:19.503435: netlink: Operstate: linkmode=-1, operstate=5
14:07:19.503536: wlp1s0: Associated to a new BSS: BSSID=20:9f:db:e7:80:80
14:07:19.503560: wlp1s0: No keys have been configured - skip key clearing
14:07:19.503575: wlp1s0: Associated with 20:9f:db:e7:80:80
14:07:19.503587: wlp1s0: WPA: Association event - clear replay counter
14:07:19.503599: wlp1s0: WPA: Clear old PTK
14:07:19.503610: EAPOL: External notification - portEnabled=0
14:07:19.503621: EAPOL: Supplicant port status: Unauthorized
14:07:19.503689: EAPOL: External notification - portValid=0
14:07:19.503705: EAPOL: Supplicant port status: Unauthorized
14:07:19.503749: EAPOL: External notification - EAP success=0
14:07:19.503763: EAPOL: Supplicant port status: Unauthorized
14:07:19.503804: EAPOL: External notification - portEnabled=1
14:07:19.503818: EAPOL: SUPP_PAE entering state CONNECTING
14:07:19.503828: EAPOL: enable timer tick
14:07:19.503838: EAPOL: SUPP_BE entering state IDLE
14:07:19.503852: wlp1s0: Setting authentication timeout: 10 sec 0 usec
14:07:19.503864: wlp1s0: Cancelling scan request
14:07:19.503885: nl80211: Event message available
14:07:19.503919: nl80211: Ignore connect event (cmd=46) when using userspace SME
14:07:19.504378: wlp1s0: RX EAPOL from 20:9f:db:e7:80:80
14:07:19.504416: wlp1s0: Setting authentication timeout: 10 sec 0 usec
14:07:19.504433: wlp1s0: IEEE 802.1X RX: version=2 type=3 length=95
14:07:19.504446: wlp1s0:   EAPOL-Key type=2
14:07:19.504461: wlp1s0:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
14:07:19.504474: wlp1s0:   key_length=16 key_data_length=0
14:07:19.504485:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 01
14:07:19.504499:   key_nonce - hexdump(len=32): 5d c0 82 5f 17 49 48 3c 76 75 c5 3e e2 d2 85 fe df d2 f4 6c 79 36 a6 3b 0c 72 5f 28 f3 c8 2e 32
14:07:19.504519:   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
14:07:19.504534:   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
14:07:19.504547:   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
14:07:19.504560:   key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
14:07:19.504581: wlp1s0: State: ASSOCIATED -> 4WAY_HANDSHAKE
14:07:19.504682: wlp1s0: WPA: RX message 1 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)
14:07:19.504705: RSN: msg 1/4 key data - hexdump(len=0):
14:07:19.505692: WPA: Renewed SNonce - hexdump(len=32): 8d 66 b1 e5 b0 ac ca f0 11 b2 8e c3 17 cc 21 4f e3 2c 05 e9 71 54 29 33 e9 b9 0d d9 89 66 be ad
14:07:19.505738: WPA: PTK derivation - A1=9c:2a:70:55:68:a3 A2=20:9f:db:e7:80:80
14:07:19.505753: WPA: Nonce1 - hexdump(len=32): 8d 66 b1 e5 b0 ac ca f0 11 b2 8e c3 17 cc 21 4f e3 2c 05 e9 71 54 29 33 e9 b9 0d d9 89 66 be ad
14:07:19.505772: WPA: Nonce2 - hexdump(len=32): 5d c0 82 5f 17 49 48 3c 76 75 c5 3e e2 d2 85 fe df d2 f4 6c 79 36 a6 3b 0c 72 5f 28 f3 c8 2e 32
14:07:19.505792: WPA: PMK - hexdump(len=32): [REMOVED]
14:07:19.505803: WPA: PTK - hexdump(len=48): [REMOVED]
14:07:19.505814: WPA: WPA IE for msg 2/4 - 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
14:07:19.505833: WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 01
14:07:19.505850: wlp1s0: WPA: Sending EAPOL-Key 2/4
14:07:19.505868: WPA: KCK - hexdump(len=16): [REMOVED]
14:07:19.505880: WPA: Derived Key MIC - hexdump(len=16): 8d 43 7a 12 ee 85 ec d0 26 88 e8 e1 b3 a2 cb 94
14:07:19.508658: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7
14:07:19.509707: wlp1s0: RX EAPOL from 20:9f:db:e7:80:80
14:07:19.509770: wlp1s0: IEEE 802.1X RX: version=2 type=3 length=151
14:07:19.509788: wlp1s0:   EAPOL-Key type=2
14:07:19.509808: wlp1s0:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
14:07:19.509825: wlp1s0:   key_length=16 key_data_length=56
14:07:19.509840:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 02
14:07:19.509859:   key_nonce - hexdump(len=32): 5d c0 82 5f 17 49 48 3c 76 75 c5 3e e2 d2 85 fe df d2 f4 6c 79 36 a6 3b 0c 72 5f 28 f3 c8 2e 32
14:07:19.509886:   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
14:07:19.509906:   key_rsc - hexdump(len=8): 1e c3 02 00 00 00 00 00
14:07:19.509924:   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
14:07:19.509942:   key_mic - hexdump(len=16): 14 e0 b0 ca 99 c1 d1 6f d2 b2 d5 24 2a 42 53 b4
14:07:19.509989: RSN: encrypted key data - hexdump(len=56): 29 71 36 bb 24 08 d7 39 bc 97 d7 b1 bd 3e f8 37 3b f1 58 c9 b0 8d 98 88 61 71 fa 0c 7d 72 5b fd 21 fe d4 09 ab fe 63 23 b1 1c 1e a1 13 cb bc c0 f7 94 e9 b9 ab 43 2d 22
14:07:19.510064: WPA: decrypted EAPOL-Key key data - hexdump(len=48): [REMOVED]
14:07:19.510088: wlp1s0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
14:07:19.510108: wlp1s0: WPA: RX message 3 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)
14:07:19.510122: WPA: IE KeyData - hexdump(len=48): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00 dd 16 00 0f ac 01 01 00 87 61 3e a2 ef 3b 39 c8 c3 1f 50 63 b0 39 b8 b5 dd 00
14:07:19.510162: 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
14:07:19.510209: WPA: GTK in EAPOL-Key - hexdump(len=24): [REMOVED]
14:07:19.510233: wlp1s0: WPA: Sending EAPOL-Key 4/4
14:07:19.510259: WPA: KCK - hexdump(len=16): [REMOVED]
14:07:19.510275: WPA: Derived Key MIC - hexdump(len=16): 6c 0c be 9c ea c7 b0 2c 7c 53 cc fd f1 27 fc 7b
14:07:19.510338: wlp1s0: WPA: Installing PTK to the driver
14:07:19.510405: wpa_driver_nl80211_set_key: ifindex=3 alg=3 addr=0x7f0ab41cad68 key_idx=0 set_tx=1 seq_len=6 key_len=16
14:07:19.510435:    addr=20:9f:db:e7:80:80
14:07:19.510844: EAPOL: External notification - portValid=1
14:07:19.510872: wlp1s0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
14:07:19.510965: RSN: received GTK in pairwise handshake - hexdump(len=18): [REMOVED]
14:07:19.510989: WPA: Group Key - hexdump(len=16): [REMOVED]
14:07:19.511009: wlp1s0: WPA: Installing GTK to the driver (keyidx=1 tx=0 len=16)
14:07:19.511038: WPA: RSC - hexdump(len=6): 1e c3 02 00 00 00
14:07:19.511086: wpa_driver_nl80211_set_key: ifindex=3 alg=3 addr=0x7f0ab33c53c6 key_idx=1 set_tx=0 seq_len=6 key_len=16
14:07:19.511120:    broadcast key
14:07:19.511205: wlp1s0: WPA: Key negotiation completed with 20:9f:db:e7:80:80 [PTK=CCMP GTK=CCMP]
14:07:19.511223: wlp1s0: Cancelling authentication timeout
14:07:19.511238: wlp1s0: State: GROUP_HANDSHAKE -> COMPLETED
14:07:19.511253: wlp1s0: CTRL-EVENT-CONNECTED - Connection to 20:9f:db:e7:80:80 completed [id=0 id_str=]
14:07:19.511264: wpa_driver_nl80211_set_operstate: operstate 0->1 (UP)
14:07:19.511276: netlink: Operstate: linkmode=-1, operstate=6
14:07:19.511418: EAPOL: External notification - portValid=1
14:07:19.511443: EAPOL: External notification - EAP success=1
14:07:19.511459: EAPOL: SUPP_PAE entering state AUTHENTICATING
14:07:19.511475: EAPOL: SUPP_BE entering state SUCCESS
14:07:19.511487: EAP: EAP entering state DISABLED
14:07:19.511508: EAPOL: SUPP_PAE entering state AUTHENTICATED
14:07:19.511518: EAPOL: Supplicant port status: Authorized
14:07:19.511583: EAPOL: SUPP_BE entering state IDLE
14:07:19.511598: EAPOL authentication completed successfully
14:07:19.511640: RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
14:07:19.511656: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlp1s0' added
14:07:19.511696: nl80211: if_removed already cleared - ignore event
14:07:19.516100: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7


14:07:20.504233: EAPOL: startWhen --> 0
14:07:20.504335: EAPOL: disable timer tick
14:07:20.511791: wlp1s0: RX EAPOL from 20:9f:db:e7:80:80
14:07:20.511880: wlp1s0: IEEE 802.1X RX: version=2 type=3 length=151
14:07:20.511905: wlp1s0:   EAPOL-Key type=2
14:07:20.511932: wlp1s0:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
14:07:20.511957: wlp1s0:   key_length=16 key_data_length=56
14:07:20.511977:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 03
14:07:20.512005:   key_nonce - hexdump(len=32): 5d c0 82 5f 17 49 48 3c 76 75 c5 3e e2 d2 85 fe df d2 f4 6c 79 36 a6 3b 0c 72 5f 28 f3 c8 2e 32
14:07:20.512068:   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
14:07:20.512095:   key_rsc - hexdump(len=8): 20 c3 02 00 00 00 00 00
14:07:20.512118:   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
14:07:20.512142:   key_mic - hexdump(len=16): 16 ba 4f 33 60 ab a5 c3 cc 70 05 39 e2 39 b0 c6
14:07:20.512204: RSN: encrypted key data - hexdump(len=56): 29 71 36 bb 24 08 d7 39 bc 97 d7 b1 bd 3e f8 37 3b f1 58 c9 b0 8d 98 88 61 71 fa 0c 7d 72 5b fd 21 fe d4 09 ab fe 63 23 b1 1c 1e a1 13 cb bc c0 f7 94 e9 b9 ab 43 2d 22
14:07:20.512268: WPA: decrypted EAPOL-Key key data - hexdump(len=48): [REMOVED]
14:07:20.512299: wlp1s0: State: COMPLETED -> 4WAY_HANDSHAKE
14:07:20.512476: wlp1s0: WPA: RX message 3 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)
14:07:20.512516: WPA: IE KeyData - hexdump(len=48): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00 dd 16 00 0f ac 01 01 00 87 61 3e a2 ef 3b 39 c8 c3 1f 50 63 b0 39 b8 b5 dd 00
14:07:20.512602: 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
14:07:20.512641: WPA: GTK in EAPOL-Key - hexdump(len=24): [REMOVED]
14:07:20.512674: wlp1s0: WPA: Sending EAPOL-Key 4/4
14:07:20.512716: WPA: KCK - hexdump(len=16): [REMOVED]
14:07:20.512740: WPA: Derived Key MIC - hexdump(len=16): 4d 4d 71 45 dd c0 59 db 07 22 06 f2 de 4f 2d fd
14:07:20.512839: wlp1s0: WPA: Installing PTK to the driver
14:07:20.513170: wpa_driver_nl80211_set_key: ifindex=3 alg=3 addr=0x7f0ab41cad68 key_idx=0 set_tx=1 seq_len=6 key_len=16
14:07:20.513231:    addr=20:9f:db:e7:80:80
14:07:20.513830: EAPOL: External notification - portValid=1
14:07:20.513885: wlp1s0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
14:07:20.514659: RSN: received GTK in pairwise handshake - hexdump(len=18): [REMOVED]
14:07:20.514693: WPA: Group Key - hexdump(len=16): [REMOVED]
14:07:20.514713: wlp1s0: WPA: Installing GTK to the driver (keyidx=1 tx=0 len=16)
14:07:20.514727: WPA: RSC - hexdump(len=6): 20 c3 02 00 00 00
14:07:20.514784: wpa_driver_nl80211_set_key: ifindex=3 alg=3 addr=0x7f0ab33c53c6 key_idx=1 set_tx=0 seq_len=6 key_len=16
14:07:20.514809:    broadcast key
14:07:20.514953: wlp1s0: WPA: Key negotiation completed with 20:9f:db:e7:80:80 [PTK=CCMP GTK=CCMP]
14:07:20.514975: wlp1s0: Cancelling authentication timeout
14:07:20.514993: wlp1s0: State: GROUP_HANDSHAKE -> COMPLETED
14:07:20.515086: EAPOL: External notification - portValid=1
14:07:20.515111: EAPOL: External notification - EAP success=1
14:07:20.515126: EAP: EAP entering state DISABLED
14:07:20.517598: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7


14:07:21.512532: wlp1s0: RX EAPOL from 20:9f:db:e7:80:80
14:07:21.512656: wlp1s0: IEEE 802.1X RX: version=2 type=3 length=151
14:07:21.512705: wlp1s0:   EAPOL-Key type=2
14:07:21.512762: wlp1s0:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
14:07:21.512794: wlp1s0:   key_length=16 key_data_length=56
14:07:21.512815:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 04
14:07:21.512842:   key_nonce - hexdump(len=32): 5d c0 82 5f 17 49 48 3c 76 75 c5 3e e2 d2 85 fe df d2 f4 6c 79 36 a6 3b 0c 72 5f 28 f3 c8 2e 32
14:07:21.512877:   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
14:07:21.512905:   key_rsc - hexdump(len=8): 21 c3 02 00 00 00 00 00
14:07:21.512929:   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
14:07:21.512954:   key_mic - hexdump(len=16): 72 52 fb d9 df 40 70 38 00 90 fd 04 94 ce 49 47
14:07:21.513011: RSN: encrypted key data - hexdump(len=56): 29 71 36 bb 24 08 d7 39 bc 97 d7 b1 bd 3e f8 37 3b f1 58 c9 b0 8d 98 88 61 71 fa 0c 7d 72 5b fd 21 fe d4 09 ab fe 63 23 b1 1c 1e a1 13 cb bc c0 f7 94 e9 b9 ab 43 2d 22
14:07:21.513116: WPA: decrypted EAPOL-Key key data - hexdump(len=48): [REMOVED]
14:07:21.513151: wlp1s0: State: COMPLETED -> 4WAY_HANDSHAKE
14:07:21.513331: wlp1s0: WPA: RX message 3 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)
14:07:21.513366: WPA: IE KeyData - hexdump(len=48): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00 dd 16 00 0f ac 01 01 00 87 61 3e a2 ef 3b 39 c8 c3 1f 50 63 b0 39 b8 b5 dd 00
14:07:21.513386: 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
14:07:21.513398: WPA: GTK in EAPOL-Key - hexdump(len=24): [REMOVED]
14:07:21.513413: wlp1s0: WPA: Sending EAPOL-Key 4/4
14:07:21.513430: WPA: KCK - hexdump(len=16): [REMOVED]
14:07:21.513443: WPA: Derived Key MIC - hexdump(len=16): 54 de c5 24 de 6e f8 08 7f bd 93 8d 85 9f bc 6f
14:07:21.513537: wlp1s0: WPA: Installing PTK to the driver
14:07:21.513652: wpa_driver_nl80211_set_key: ifindex=3 alg=3 addr=0x7f0ab41cad68 key_idx=0 set_tx=1 seq_len=6 key_len=16
14:07:21.513702:    addr=20:9f:db:e7:80:80
14:07:21.514084: EAPOL: External notification - portValid=1
14:07:21.514128: wlp1s0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
14:07:21.514246: RSN: received GTK in pairwise handshake - hexdump(len=18): [REMOVED]
14:07:21.514273: WPA: Group Key - hexdump(len=16): [REMOVED]
14:07:21.514295: wlp1s0: WPA: Installing GTK to the driver (keyidx=1 tx=0 len=16)
14:07:21.514300: WPA: RSC - hexdump(len=6): 21 c3 02 00 00 00
14:07:21.514325: wpa_driver_nl80211_set_key: ifindex=3 alg=3 addr=0x7f0ab33c53c6 key_idx=1 set_tx=0 seq_len=6 key_len=16
14:07:21.514333:    broadcast key
14:07:21.514460: wlp1s0: WPA: Key negotiation completed with 20:9f:db:e7:80:80 [PTK=CCMP GTK=CCMP]
14:07:21.514486: wlp1s0: Cancelling authentication timeout
14:07:21.514506: wlp1s0: State: GROUP_HANDSHAKE -> COMPLETED
14:07:21.514594: EAPOL: External notification - portValid=1
14:07:21.514618: EAPOL: External notification - EAP success=1
14:07:21.514643: EAP: EAP entering state DISABLED
14:07:21.518424: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7


14:07:22.513566: wlp1s0: RX EAPOL from 20:9f:db:e7:80:80
14:07:22.513676: wlp1s0: IEEE 802.1X RX: version=2 type=3 length=151
14:07:22.513711: wlp1s0:   EAPOL-Key type=2
14:07:22.513745: wlp1s0:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
14:07:22.513774: wlp1s0:   key_length=16 key_data_length=56
14:07:22.513802:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 05
14:07:22.513829:   key_nonce - hexdump(len=32): 5d c0 82 5f 17 49 48 3c 76 75 c5 3e e2 d2 85 fe df d2 f4 6c 79 36 a6 3b 0c 72 5f 28 f3 c8 2e 32
14:07:22.513861:   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
14:07:22.513887:   key_rsc - hexdump(len=8): 24 c3 02 00 00 00 00 00
14:07:22.513909:   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
14:07:22.513933:   key_mic - hexdump(len=16): 3a 19 8e 94 11 1a aa 0a 04 9a 7c 96 09 6a 0f 65
14:07:22.513988: RSN: encrypted key data - hexdump(len=56): 29 71 36 bb 24 08 d7 39 bc 97 d7 b1 bd 3e f8 37 3b f1 58 c9 b0 8d 98 88 61 71 fa 0c 7d 72 5b fd 21 fe d4 09 ab fe 63 23 b1 1c 1e a1 13 cb bc c0 f7 94 e9 b9 ab 43 2d 22
14:07:22.514107: WPA: decrypted EAPOL-Key key data - hexdump(len=48): [REMOVED]
14:07:22.514141: wlp1s0: State: COMPLETED -> 4WAY_HANDSHAKE
14:07:22.514320: wlp1s0: WPA: RX message 3 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)
14:07:22.514365: WPA: IE KeyData - hexdump(len=48): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00 dd 16 00 0f ac 01 01 00 87 61 3e a2 ef 3b 39 c8 c3 1f 50 63 b0 39 b8 b5 dd 00
14:07:22.514416: 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
14:07:22.514452: WPA: GTK in EAPOL-Key - hexdump(len=24): [REMOVED]
14:07:22.514485: wlp1s0: WPA: Sending EAPOL-Key 4/4
14:07:22.514536: WPA: KCK - hexdump(len=16): [REMOVED]
14:07:22.514565: WPA: Derived Key MIC - hexdump(len=16): 2a 2a 79 af 1b 19 94 89 a4 fd 84 c0 a7 a4 9b 3a
14:07:22.514664: wlp1s0: WPA: Installing PTK to the driver
14:07:22.514776: wpa_driver_nl80211_set_key: ifindex=3 alg=3 addr=0x7f0ab41cad68 key_idx=0 set_tx=1 seq_len=6 key_len=16
14:07:22.514828:    addr=20:9f:db:e7:80:80
14:07:22.515228: EAPOL: External notification - portValid=1
14:07:22.515281: wlp1s0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
14:07:22.515397: RSN: received GTK in pairwise handshake - hexdump(len=18): [REMOVED]
14:07:22.515423: WPA: Group Key - hexdump(len=16): [REMOVED]
14:07:22.515444: wlp1s0: WPA: Installing GTK to the driver (keyidx=1 tx=0 len=16)
14:07:22.515460: WPA: RSC - hexdump(len=6): 24 c3 02 00 00 00
14:07:22.515528: wpa_driver_nl80211_set_key: ifindex=3 alg=3 addr=0x7f0ab33c53c6 key_idx=1 set_tx=0 seq_len=6 key_len=16
14:07:22.515555:    broadcast key
14:07:22.515722: wlp1s0: WPA: Key negotiation completed with 20:9f:db:e7:80:80 [PTK=CCMP GTK=CCMP]
14:07:22.515748: wlp1s0: Cancelling authentication timeout
14:07:22.515792: wlp1s0: State: GROUP_HANDSHAKE -> COMPLETED
14:07:22.515880: EAPOL: External notification - portValid=1
14:07:22.515904: EAPOL: External notification - EAP success=1
14:07:22.515920: EAP: EAP entering state DISABLED
14:07:22.519416: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7
14:07:23.513500: RTM_NEWLINK: operstate=1 ifi_flags=0x1003 ([UP])
14:07:23.513662: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlp1s0' added
14:07:23.513842: nl80211: if_removed already cleared - ignore event
14:07:23.536309: nl80211: Event message available
14:07:23.536454: nl80211: Delete station 20:9f:db:e7:80:80
14:07:23.542786: nl80211: Event message available
14:07:23.542882: nl80211: MLME event 39
14:07:23.542903: nl80211: Deauthenticate event
14:07:23.542927: wlp1s0: Event DEAUTH (12) received
14:07:23.542946: wlp1s0: Deauthentication notification
14:07:23.542964: wlp1s0:  * reason 2
14:07:23.542982: wlp1s0:  * address 20:9f:db:e7:80:80
14:07:23.542997: Deauthentication frame IE(s) - hexdump(len=0): [NULL]
14:07:23.543055: wlp1s0: CTRL-EVENT-DISCONNECTED bssid=20:9f:db:e7:80:80 reason=2
14:07:23.543096: wlp1s0: Auto connect enabled: try to reconnect (wps=0 wpa_state=9)
14:07:23.543115: wlp1s0: Setting scan request: 0 sec 100000 usec
14:07:23.543133: Added BSSID 20:9f:db:e7:80:80 into blacklist
14:07:23.543155: wlp1s0: Blacklist count 1 --> request scan in 100 ms
14:07:23.543172: wlp1s0: Not rescheduling scan to ensure that specific SSID scans occur
14:07:23.543388: wlp1s0: Disconnect event - remove keys
14:07:23.543485: wpa_driver_nl80211_set_key: ifindex=3 alg=0 addr=(nil) key_idx=0 set_tx=0 seq_len=0 key_len=0
14:07:23.551379: wpa_driver_nl80211_set_key: ifindex=3 alg=0 addr=(nil) key_idx=1 set_tx=0 seq_len=0 key_len=0
14:07:23.551706: wpa_driver_nl80211_set_key: ifindex=3 alg=0 addr=(nil) key_idx=2 set_tx=0 seq_len=0 key_len=0
14:07:23.551884: wpa_driver_nl80211_set_key: ifindex=3 alg=0 addr=(nil) key_idx=3 set_tx=0 seq_len=0 key_len=0
14:07:23.551995: wpa_driver_nl80211_set_key: ifindex=3 alg=0 addr=0x7f0ab41a7e08 key_idx=0 set_tx=0 seq_len=0 key_len=0
14:07:23.552087:    addr=20:9f:db:e7:80:80
14:07:23.552218: wlp1s0: State: COMPLETED -> DISCONNECTED
14:07:23.552284: wpa_driver_nl80211_set_operstate: operstate 1->0 (DORMANT)
14:07:23.552310: netlink: Operstate: linkmode=-1, operstate=5
14:07:23.552487: EAPOL: External notification - portEnabled=0
14:07:23.552519: EAPOL: SUPP_PAE entering state DISCONNECTED
14:07:23.552537: EAPOL: Supplicant port status: Unauthorized
14:07:23.552659: EAPOL: SUPP_BE entering state INITIALIZE
14:07:23.552685: EAPOL: Supplicant port status: Unauthorized
14:07:23.552741: EAPOL: External notification - portValid=0
14:07:23.552758: EAPOL: Supplicant port status: Unauthorized
14:07:23.552806: EAPOL: External notification - EAP success=0
14:07:23.552823: EAPOL: Supplicant port status: Unauthorized
14:07:23.552893: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
14:07:23.552914: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlp1s0' added
14:07:23.552946: nl80211: if_removed already cleared - ignore event
14:07:23.552962: nl80211: Event message available
14:07:23.552984: nl80211: Ignore disconnect event when using userspace SME
14:07:23.557565: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7
14:07:23.565840: nl80211: Event message available
14:07:23.565923: nl80211: Regulatory domain change
14:07:23.565950: wlp1s0: Event CHANNEL_LIST_CHANGED (31) received
14:07:23.566181: nl80211: Regulatory information - country=00
14:07:23.566210: nl80211: 2402-2472 @ 40 MHz
14:07:23.566230: nl80211: 2457-2482 @ 40 MHz
14:07:23.566248: nl80211: 2474-2494 @ 20 MHz
14:07:23.566267: nl80211: 5170-5250 @ 80 MHz
14:07:23.566284: nl80211: 5250-5330 @ 80 MHz
14:07:23.566301: nl80211: 5490-5730 @ 160 MHz
14:07:23.566317: nl80211: 5735-5835 @ 80 MHz
14:07:23.566354: nl80211: 57240-63720 @ 2160 MHz
14:07:23.566398: nl80211: Added 802.11b mode based on 802.11g information
14:07:23.566420: P2P: Add operating class 81
14:07:23.566437: P2P: Channels - hexdump(len=11): 01 02 03 04 05 06 07 08 09 0a 0b
14:07:23.566467: wlp1s0: P2P: Update channel list
14:07:23.570997: nl80211: Event message available
14:07:23.571078: nl80211: Regulatory domain change
14:07:23.571100: wlp1s0: Event CHANNEL_LIST_CHANGED (31) received
14:07:23.571306: nl80211: Regulatory information - country=US
14:07:23.571330: nl80211: 2402-2472 @ 40 MHz
14:07:23.571347: nl80211: 5170-5250 @ 80 MHz
14:07:23.571364: nl80211: 5250-5330 @ 80 MHz
14:07:23.571380: nl80211: 5490-5600 @ 80 MHz
14:07:23.571396: nl80211: 5650-5710 @ 40 MHz
14:07:23.571411: nl80211: 5735-5835 @ 80 MHz
14:07:23.571426: nl80211: 57240-63720 @ 2160 MHz
14:07:23.571462: nl80211: Added 802.11b mode based on 802.11g information
14:07:23.571481: P2P: Add operating class 81
14:07:23.571498: P2P: Channels - hexdump(len=11): 01 02 03 04 05 06 07 08 09 0a 0b
14:07:23.571525: wlp1s0: P2P: Update channel list
14:07:23.643319: wlp1s0: State: DISCONNECTED -> SCANNING
14:07:23.643497: Scan SSID - hexdump_ascii(len=10):
     55 6e 69 46 69 2d 68 6f 6d 65                     UniFi-home      
14:07:23.643575: wlp1s0: Starting AP scan for wildcard SSID
14:07:23.643607: WPS: Building WPS IE for Probe Request
14:07:23.643636: WPS:  * Version (hardcoded 0x10)
14:07:23.643664: WPS:  * Request Type
14:07:23.643683: WPS:  * Config Methods (108)
14:07:23.643696: WPS:  * UUID-E
14:07:23.643709: WPS:  * Primary Device Type
14:07:23.643722: WPS:  * RF Bands (3)
14:07:23.643736: WPS:  * Association State
14:07:23.643749: WPS:  * Configuration Error (0)
14:07:23.643763: WPS:  * Device Password ID (0)
14:07:23.643777: WPS:  * Device Name
14:07:23.643797: P2P: * P2P IE header
14:07:23.643810: P2P: * Capability dev=25 group=00
14:07:23.643825: P2P: * Listen Channel: Regulatory Class 81 Channel 1
14:07:23.648488: Scan requested (ret=0) - scan timeout 30 seconds
14:07:23.648536: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/7
14:07:23.648664: nl80211: Event message available
14:07:23.648704: nl80211: Scan trigger

Re: AR9462 problems connecting again..

[Adrian Chadd]

On 22 February 2015 at 17:41, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
> On Sun, Feb 22, 2015 at 4:54 PM, Adrian Chadd <adrian@freebsd.org> wrote:
>>
>> I /think/ it's okay? The removed stuff is the pre-shared key pieces.
>
> Ok. Attached is what seems to be the relevant part of the
> wpa_supplicant.log file.
>
> The datestamp has been changed so that it can be matched up with the
> dmesg, and I added empty lines for pauses when I was trying to figure
> out what the heck it was doing, but other than that it's the raw log.
>
>> Do you have another laptop with an atheros NIC in it that you could
>> use in monitor mode to capture all the frames?
>
> Nope, everything else I have seems to be intel wireless. I think one
> of the kids machines is a Mac Mini with an ath5k thing, but I'm hoping
> the wpa_supplicant.log is sufficient to give somebody an idea.

Do you have a 5GHz SSID setup on this access point? Is this kind of
messed up diassociation-to-steer-you-to-another-band thing?




-adrian

Re: AR9462 problems connecting again..

[Linus Torvalds]

On Sun, Feb 22, 2015 at 5:55 PM, Adrian Chadd <adrian@freebsd.org> wrote:
>
> Do you have a 5GHz SSID setup on this access point? Is this kind of
> messed up diassociation-to-steer-you-to-another-band thing?

Nope. That's the older single-band UniFi UAP - 2.4GHz only.

                       Linus

Re: AR9462 problems connecting again..

[Adrian Chadd]

So the interesting part thus far:

14:07:23.513500: RTM_NEWLINK: operstate=1 ifi_flags=0x1003 ([UP])
14:07:23.513662: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlp1s0' added
14:07:23.513842: nl80211: if_removed already cleared - ignore event
14:07:23.536309: nl80211: Event message available
14:07:23.536454: nl80211: Delete station 20:9f:db:e7:80:80
14:07:23.542786: nl80211: Event message available
14:07:23.542882: nl80211: MLME event 39
14:07:23.542903: nl80211: Deauthenticate event
14:07:23.542927: wlp1s0: Event DEAUTH (12) received
14:07:23.542946: wlp1s0: Deauthentication notification
14:07:23.542964: wlp1s0:  * reason 2
14:07:23.542982: wlp1s0:  * address 20:9f:db:e7:80:80
14:07:23.542997: Deauthentication frame IE(s) - hexdump(len=0): [NULL]
14:07:23.543055: wlp1s0: CTRL-EVENT-DISCONNECTED
bssid=20:9f:db:e7:80:80 reason=2
14:07:23.543096: wlp1s0: Auto connect enabled: try to reconnect (wps=0
wpa_state=9)
14:07:23.543115: wlp1s0: Setting scan request: 0 sec 100000 usec
14:07:23.543133: Added BSSID 20:9f:db:e7:80:80 into blacklist

You've associated, you do the 4-way handshake, that works fine; then
one second later you do it again; then one second later it fails and
it sends a disconnect.

Whenever I've seen this in the past, it's been because some part of
the EAPOL exchange is being transmitted at the wrong rate or something
about the sequence number/etc is incorrect. So, hm, I'd want to verify
that the whole exchange is working correctly and peek into the header
values for each of those.





-adrian

Re: [ath9k-devel] AR9462 problems connecting again..

[Sujith Manoharan]

Linus Torvalds wrote:
> 14:07:23.542927: wlp1s0: Event DEAUTH (12) received
> 14:07:23.542946: wlp1s0: Deauthentication notification
> 14:07:23.542964: wlp1s0:  * reason 2
> 14:07:23.542982: wlp1s0:  * address 20:9f:db:e7:80:80
> 14:07:23.542997: Deauthentication frame IE(s) - hexdump(len=0): [NULL]
> 14:07:23.543055: wlp1s0: CTRL-EVENT-DISCONNECTED bssid=20:9f:db:e7:80:80 reason=2

Sporadic association problems could be a problem with the chosen rates.
This would show the rates for the EAPOL frames:

iw dev wlp1s0 interface add mon0 type monitor
ifconfig mon0 up
tshark -i mon0 -Y eapol -T fields -e radiotap.datarate -e wlan -e eapol -e wlan.sa -e wlan.da
Run wpa_s.

Does setting a lower rate improve connectivity ?

'iw dev wlp1s0 set bitrates ht-mcs-2.4 1' would choose a lower
rate for the key-exchange frames.

Sujith

Re: [ath9k-devel] AR9462 problems connecting again..

[Sujith Manoharan]

Sujith Manoharan wrote:
> 'iw dev wlp1s0 set bitrates ht-mcs-2.4 1' would choose a lower
> rate for the key-exchange frames.

Or 'iw dev wlp1s0 set bitrates ht-mcs-2.4 0' to choose the lowest
HT rate.

Sujith

Re: AR9462 problems connecting again..

[Jouni Malinen]

On Sun, Feb 22, 2015 at 05:41:25PM -0800, Linus Torvalds wrote:
> Ok. Attached is what seems to be the relevant part of the
> wpa_supplicant.log file.
> 
> The datestamp has been changed so that it can be matched up with the
> dmesg, and I added empty lines for pauses when I was trying to figure
> out what the heck it was doing, but other than that it's the raw log.

> 14:07:16.059389: nl80211: Authenticate (ifindex=3)
> 14:07:16.390659: nl80211: MLME event 37; timeout with 20:9f:db:e7:80:80

I'm assuming this is unrelated to the issue of getting disconnected
after 4-way handshake, but anyway, something here prevent the simple
Authentication frame exchange from completing (i.e., either the AP did
not reply to these these frames or the response was lost for some
reason). The following attempt did you go through without issues.

> 14:07:19.478850: nl80211: Authenticate (ifindex=3)
> 14:07:19.493911: nl80211: Authenticate event

> 14:07:19.494223: nl80211: Associate (ifindex=3)
> 14:07:19.503237: nl80211: Associate event

> 14:07:19.504682: wlp1s0: WPA: RX message 1 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)
> 14:07:19.505850: wlp1s0: WPA: Sending EAPOL-Key 2/4
> 14:07:19.510108: wlp1s0: WPA: RX message 3 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)
> 14:07:19.510233: wlp1s0: WPA: Sending EAPOL-Key 4/4

So it looks like both the AP and the station are able to send and
receive EAPOL frames. EAPOL-Key message 1/4..3/4 worked fine. However,
I'm assuming msg 4/4 did not make it through for some reason.

> 14:07:19.510338: wlp1s0: WPA: Installing PTK to the driver
> 14:07:19.510405: wpa_driver_nl80211_set_key: ifindex=3 alg=3 addr=0x7f0ab41cad68 key_idx=0 set_tx=1 seq_len=6 key_len=16
> 14:07:19.510435:    addr=20:9f:db:e7:80:80

And this is where IEEE 802.11 RSN gets a bit messy.. The station
installs a key for encrypting all unicast frames to the AP now that it
believes 4-way handshake has been completed successfully.

> 14:07:19.511009: wlp1s0: WPA: Installing GTK to the driver (keyidx=1 tx=0 len=16)

And same for a key to decrypt received broadcast/multicast frames.

> 14:07:19.511205: wlp1s0: WPA: Key negotiation completed with 20:9f:db:e7:80:80 [PTK=CCMP GTK=CCMP]
> 14:07:19.511223: wlp1s0: Cancelling authentication timeout
> 14:07:19.511238: wlp1s0: State: GROUP_HANDSHAKE -> COMPLETED
> 14:07:19.511253: wlp1s0: CTRL-EVENT-CONNECTED - Connection to 20:9f:db:e7:80:80 completed [id=0 id_str=]

As far as the station is concerned, everything looked fine until here
and connection was established successfully.

> 14:07:20.512476: wlp1s0: WPA: RX message 3 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)

However, the AP disagrees.. It looks like this specific AP uses a one
second timeout on EAPOL-Key timeouts. This EAPOL-Key frame was likely
unencrypted since the AP did not receive (or accept, but more likely not
receive) msg 4/4. We are currently allowing such unencrypted EAPOL
frames (but not other ethertypes) to get processed even when the
pairwise key has been configured.

> 14:07:20.512674: wlp1s0: WPA: Sending EAPOL-Key 4/4

And here's an attempt to reply.. Alas, this will likely go out encrypted
since we have the pairwise key configured and the AP will be dropping it
most likely since it would configure the pairwise key for this station
only after having receive valid 4/4.

> 14:07:20.513170: wpa_driver_nl80211_set_key: ifindex=3 alg=3 addr=0x7f0ab41cad68 key_idx=0 set_tx=1 seq_len=6 key_len=16

And station reconfigured the key..

> 14:07:21.513331: wlp1s0: WPA: RX message 3 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)
> 14:07:22.514320: wlp1s0: WPA: RX message 3 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)

These are the following two retries from AP, one second apart. Trying
EAPOL-Key frames four times in normal behavior, so based on timing here,
the issue is in AP not receiving (or accepting) msg 4/4.

> 14:07:23.542903: nl80211: Deauthenticate event

And this is the expected deauthentication by the AP after the last
EAPOL-Key frame retransmission failed to get a valid response.


So yes, this is a race condition of sorts. It is interesting if verbose
debugging in wpa_supplicant is enough to make this less likely to fail.
That will give some more time between the EAPOL-Key msg 4/4 transmission
(packet socket send() on the netdev) and pairwise key configuration
(netlink send). In theory, it could be possible to get even the first
EAPOL-Key msg 4/4 encrypted if the kernel operations for Data frame
transmission and nl80211 key configuration get reordered. Though, if
that were to be happening commonly, we would see significantly more
issues with this, so I'd assume this is not really the main issue here.

I'm not sure why the AP would not accept EAPOL-Key msg 4/4, so it would
be interesting to see a wireless capture log to confirm that the first
attempt of sending that out did indeed result in the frame going out and
doing so without encryption.


As far as making this issue less likely to cause connectivity issues, I
guess we could make mac80211 do a similar hack that some drivers use
here and force the EAPOL-Key msg 4/4 retransmissions to go out without
encryption even though the pairwise key was configured. I think it would
be nicer to control this from user space (i.e., wpa_supplicant could
indicate with the send command that the frame needs to go out without
encryption), but that is unfortunately not something that the current
mechanism used for sending out EAPOL frames in station mode supports.
mac80211 should be able to track this state if it were to look at which
EAPOL-Key frames has been exchanged and start encrypting them only after
the AP has transmitted an encrypted frame with the new pairwise key.
This is somewhat ugly, but doable. (Though, this would be yet another
justification for finally trying to come up with an alternative
mechanism for handling EAPOL frame TX/RX that is really a special case
for IEEE 802.1X.)

-- 
Jouni Malinen                                            PGP id EFC895FA

Re: AR9462 problems connecting again..

[wim torfs]

If it is the case that the 4-way handshake fails, then I have seen this 
issue before. The problem is that messages 1 to 4 are sent with the 
previous key. However, right after sending message 4/4, does 
wpa_supplicant set the new key. In some cases, such as in a high 
throughput environment, this could result that the key is set even 
before the last packet is sent out. As a result, the AP receives a 
packet which is encrypted with the wrong key, since it still listens 
with the old key.

I did not notice this issue while authenticating for the first time, 
only after the first rekey operation.

A solution would be to adjust wpa_supplicant to wait for the 
transmission ack before it sets its key, however, this causes issues 
with the key reception and transmission count, which could be 
circumvented by copying the old counter values upon setting the new key, 
but this is a dirty hack. Another solution would require some more 
invasive operations, that is, the new key should somehow be linked to 
the message 4/4 and should only be set by the driver upon transmission 
of the message 4/4.

Best regards,
Wim.


On 02/23/2015 11:37 AM, Jouni Malinen wrote:
> On Sun, Feb 22, 2015 at 05:41:25PM -0800, Linus Torvalds wrote:
>> Ok. Attached is what seems to be the relevant part of the
>> wpa_supplicant.log file.
>>
>> The datestamp has been changed so that it can be matched up with the
>> dmesg, and I added empty lines for pauses when I was trying to figure
>> out what the heck it was doing, but other than that it's the raw log.
>
>> 14:07:16.059389: nl80211: Authenticate (ifindex=3)
>> 14:07:16.390659: nl80211: MLME event 37; timeout with 20:9f:db:e7:80:80
>
> I'm assuming this is unrelated to the issue of getting disconnected
> after 4-way handshake, but anyway, something here prevent the simple
> Authentication frame exchange from completing (i.e., either the AP did
> not reply to these these frames or the response was lost for some
> reason). The following attempt did you go through without issues.
>
>> 14:07:19.478850: nl80211: Authenticate (ifindex=3)
>> 14:07:19.493911: nl80211: Authenticate event
>
>> 14:07:19.494223: nl80211: Associate (ifindex=3)
>> 14:07:19.503237: nl80211: Associate event
>
>> 14:07:19.504682: wlp1s0: WPA: RX message 1 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)
>> 14:07:19.505850: wlp1s0: WPA: Sending EAPOL-Key 2/4
>> 14:07:19.510108: wlp1s0: WPA: RX message 3 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)
>> 14:07:19.510233: wlp1s0: WPA: Sending EAPOL-Key 4/4
>
> So it looks like both the AP and the station are able to send and
> receive EAPOL frames. EAPOL-Key message 1/4..3/4 worked fine. However,
> I'm assuming msg 4/4 did not make it through for some reason.
>
>> 14:07:19.510338: wlp1s0: WPA: Installing PTK to the driver
>> 14:07:19.510405: wpa_driver_nl80211_set_key: ifindex=3 alg=3 addr=0x7f0ab41cad68 key_idx=0 set_tx=1 seq_len=6 key_len=16
>> 14:07:19.510435:    addr=20:9f:db:e7:80:80
>
> And this is where IEEE 802.11 RSN gets a bit messy.. The station
> installs a key for encrypting all unicast frames to the AP now that it
> believes 4-way handshake has been completed successfully.
>
>> 14:07:19.511009: wlp1s0: WPA: Installing GTK to the driver (keyidx=1 tx=0 len=16)
>
> And same for a key to decrypt received broadcast/multicast frames.
>
>> 14:07:19.511205: wlp1s0: WPA: Key negotiation completed with 20:9f:db:e7:80:80 [PTK=CCMP GTK=CCMP]
>> 14:07:19.511223: wlp1s0: Cancelling authentication timeout
>> 14:07:19.511238: wlp1s0: State: GROUP_HANDSHAKE ->  COMPLETED
>> 14:07:19.511253: wlp1s0: CTRL-EVENT-CONNECTED - Connection to 20:9f:db:e7:80:80 completed [id=0 id_str=]
>
> As far as the station is concerned, everything looked fine until here
> and connection was established successfully.
>
>> 14:07:20.512476: wlp1s0: WPA: RX message 3 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)
>
> However, the AP disagrees.. It looks like this specific AP uses a one
> second timeout on EAPOL-Key timeouts. This EAPOL-Key frame was likely
> unencrypted since the AP did not receive (or accept, but more likely not
> receive) msg 4/4. We are currently allowing such unencrypted EAPOL
> frames (but not other ethertypes) to get processed even when the
> pairwise key has been configured.
>
>> 14:07:20.512674: wlp1s0: WPA: Sending EAPOL-Key 4/4
>
> And here's an attempt to reply.. Alas, this will likely go out encrypted
> since we have the pairwise key configured and the AP will be dropping it
> most likely since it would configure the pairwise key for this station
> only after having receive valid 4/4.
>
>> 14:07:20.513170: wpa_driver_nl80211_set_key: ifindex=3 alg=3 addr=0x7f0ab41cad68 key_idx=0 set_tx=1 seq_len=6 key_len=16
>
> And station reconfigured the key..
>
>> 14:07:21.513331: wlp1s0: WPA: RX message 3 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)
>> 14:07:22.514320: wlp1s0: WPA: RX message 3 of 4-Way Handshake from 20:9f:db:e7:80:80 (ver=2)
>
> These are the following two retries from AP, one second apart. Trying
> EAPOL-Key frames four times in normal behavior, so based on timing here,
> the issue is in AP not receiving (or accepting) msg 4/4.
>
>> 14:07:23.542903: nl80211: Deauthenticate event
>
> And this is the expected deauthentication by the AP after the last
> EAPOL-Key frame retransmission failed to get a valid response.
>
>
> So yes, this is a race condition of sorts. It is interesting if verbose
> debugging in wpa_supplicant is enough to make this less likely to fail.
> That will give some more time between the EAPOL-Key msg 4/4 transmission
> (packet socket send() on the netdev) and pairwise key configuration
> (netlink send). In theory, it could be possible to get even the first
> EAPOL-Key msg 4/4 encrypted if the kernel operations for Data frame
> transmission and nl80211 key configuration get reordered. Though, if
> that were to be happening commonly, we would see significantly more
> issues with this, so I'd assume this is not really the main issue here.
>
> I'm not sure why the AP would not accept EAPOL-Key msg 4/4, so it would
> be interesting to see a wireless capture log to confirm that the first
> attempt of sending that out did indeed result in the frame going out and
> doing so without encryption.
>
>
> As far as making this issue less likely to cause connectivity issues, I
> guess we could make mac80211 do a similar hack that some drivers use
> here and force the EAPOL-Key msg 4/4 retransmissions to go out without
> encryption even though the pairwise key was configured. I think it would
> be nicer to control this from user space (i.e., wpa_supplicant could
> indicate with the send command that the frame needs to go out without
> encryption), but that is unfortunately not something that the current
> mechanism used for sending out EAPOL frames in station mode supports.
> mac80211 should be able to track this state if it were to look at which
> EAPOL-Key frames has been exchanged and start encrypting them only after
> the AP has transmitted an encrypted frame with the new pairwise key.
> This is somewhat ugly, but doable. (Though, this would be yet another
> justification for finally trying to come up with an alternative
> mechanism for handling EAPOL frame TX/RX that is really a special case
> for IEEE 802.1X.)
>

Re: AR9462 problems connecting again..

[Jouni Malinen]

On Mon, Feb 23, 2015 at 11:55:30AM +0100, wim torfs wrote:
> If it is the case that the 4-way handshake fails, then I have seen
> this issue before. The problem is that messages 1 to 4 are sent with
> the previous key. However, right after sending message 4/4, does
> wpa_supplicant set the new key. In some cases, such as in a high
> throughput environment, this could result that the key is set even
> before the last packet is sent out. As a result, the AP receives a
> packet which is encrypted with the wrong key, since it still listens
> with the old key.

The specific case here is not PTK rekeying, i.e., it is for the initial
4-way handshake, so there is no previous pairwise key in place. That
said, I guess it would be possible for some drivers to hit this even
with the initial PTK configuration if hardware acceleration is used for
encryption and the frame gets delayed sufficiently long while waiting
for medium access.

> A solution would be to adjust wpa_supplicant to wait for the
> transmission ack before it sets its key, however, this causes issues
> with the key reception and transmission count, which could be
> circumvented by copying the old counter values upon setting the new
> key, but this is a dirty hack. Another solution would require some
> more invasive operations, that is, the new key should somehow be
> linked to the message 4/4 and should only be set by the driver upon
> transmission of the message 4/4.

I've been thinking of adding EAPOL TX status reporting into
wpa_supplicant at least to make the debug log more helpful. However,
this does indeed cause issues for RX and I'm not really sure I'd like to
delay pairwise key configuration. The proper way of handling this would
be by doing what the standard really implies, i.e., configure the key
for RX only at first and then enable it for TX after EAPOL-Key msg 4/4
has been transmitted. Though, that should really be interpreted with
something like "enable for TX after the AP has used the key" due to this
possibility for retransmissions of EAPOL-Key 3/4. That said, there are
corner cases even with this design, e.g., due to the STA wanting to
transmit Data frames to the AP immediately after EAPOL-Key 4/4; those
should really be encrypted, so the behavior here would likely need to be
conditional on ethertype (RX-only for EAPOL, RX+TX for everything else).

Things get even messier with PTK rekeying when there would actually need
to be support for two keys (even with the same key index..) so that the
retransmitted EAPOL-Key 3/4 case could be detected and replied to in a
way that the AP understands the response. This gets unfortunately ugly
and I'd assume almost no station implements this in a way that would
handle all cases cleanly (i.e., just hope for msg 4/4 to go through and
reassociate as a backup plan if things fail..).

-- 
Jouni Malinen                                            PGP id EFC895FA

Re: AR9462 problems connecting again..

[Jouni Malinen]

On Sun, Feb 22, 2015 at 05:41:25PM -0800, Linus Torvalds wrote:
> Nope, everything else I have seems to be intel wireless. I think one
> of the kids machines is a Mac Mini with an ath5k thing, but I'm hoping
> the wpa_supplicant.log is sufficient to give somebody an idea.

It looks like there are two issues here: 1) EAPOL-Key message 4/4 (i.e.,
the second Data frame sent by the station during association) is somehow
not seen or accepted by the AP, 2) recovery from that msg 4/4 getting
lost does not work in the intended way.

For (1), one would likely need to see a wireless capture from a separate
WLAN radio to say something certain about what exactly happened.
ath5k-compatible radios would not be sufficient since this would need to
be able to see HT frames which ath9k is mostly like using here. I
haven't used iwlwifi as a sniffer, so I do not know whether that would
be a workable option for this.

In my tests, I can see the rate control algorithm (minstrel_ht) using a
pretty high rate (even MCS14 with 2-stream device, which is one short of
maximum) which is quite a bit higher than I would myself have selected
for an EAPOL frame (especially for EAPOL-Key 4/4 which has these lovely
issues with retransmissions) more or less immediately after association.
Anyway, that frame is supposed to get additional fall-back TX rates for
link layer retransmissions and those should make it much more likely for
this to be received by the AP. Sniffer trace would confirm that.


For (2), wpa_supplicant debug log gives a pretty clear idea on what is
happening and based on that, I can easily reproduce this part. In fact,
I now have a fully automated test script for verifying this with
mac80211_hwsim.

Some alternative means of improving this was discussed in this thread.
I'm not completely happy with this, but the following mac80211 changes
do fix this retransmission case and will likely make the issue you are
seeing disappear since it allows any of the four EAPOL-Key msg 4/4
transmissions to be received by the AP to avoid the disconnection. This
doesn't fix the initial trigger behind the issue, but with those EAPOL
retransmissions working, the likelihood of all four attempts failing
(with each getting multiple link-layer retransmissions) is quite small.


mac80211: Do not encrypt EAPOL frames before peer has used the key

The 4-way handshake design is a bit inconvenient for the case where msg
3/4 needs to be transmitted (e.g., AP not receiving first transmission
of 4/4). The supplicant side has already configured the pairwise key at
that point in time and while we allow unencrypted msg 3/4 to be
received, we were sending out 4/4 encrypted which will result in it
getting dropped. User space would be aware of when the EAPOL frame
should not be encrypted, but we do not have convenient means of telling
mac80211 that. For now, use a mac80211-specific hack to avoid EAPOL
frame encryption to allow retransmission of 4-way handshake messages 3/4
and 4/4 to work in a way that the authenticator side can process 4/4.

---
 net/mac80211/key.h |  2 ++
 net/mac80211/rx.c  | 11 +++++++++++
 net/mac80211/tx.c  | 13 +++++++++++++
 3 files changed, 26 insertions(+)

diff --git a/net/mac80211/key.h b/net/mac80211/key.h
index d57a9915..3e23276 100644
--- a/net/mac80211/key.h
+++ b/net/mac80211/key.h
@@ -120,6 +120,8 @@ struct ieee80211_key {
 
 	/* number of times this key has been used */
 	int tx_rx_count;
+	/* whether a valid RX decryption has happened with this key */
+	bool valid_rx_seen;
 
 #ifdef CONFIG_MAC80211_DEBUGFS
 	struct {
diff --git a/net/mac80211/rx.c b/net/mac80211/rx.c
index 1101563..8f3f86c 100644
--- a/net/mac80211/rx.c
+++ b/net/mac80211/rx.c
@@ -1691,6 +1691,16 @@ ieee80211_rx_h_decrypt(struct ieee80211_rx_data *rx)
 	return result;
 }
 
+static ieee80211_rx_result debug_noinline
+ieee80211_rx_h_check_key_use(struct ieee80211_rx_data *rx)
+{
+	struct ieee80211_rx_status *status = IEEE80211_SKB_RXCB(rx->skb);
+
+	if ((status->flag & RX_FLAG_DECRYPTED) && rx->key)
+		rx->key->valid_rx_seen = true;
+	return RX_CONTINUE;
+}
+
 static inline struct ieee80211_fragment_entry *
 ieee80211_reassemble_add(struct ieee80211_sub_if_data *sdata,
 			 unsigned int frag, unsigned int seq, int rx_queue,
@@ -3139,6 +3149,7 @@ static void ieee80211_rx_handlers(struct ieee80211_rx_data *rx,
 		CALL_RXH(ieee80211_rx_h_uapsd_and_pspoll)
 		CALL_RXH(ieee80211_rx_h_sta_process)
 		CALL_RXH(ieee80211_rx_h_decrypt)
+		CALL_RXH(ieee80211_rx_h_check_key_use)
 		CALL_RXH(ieee80211_rx_h_defragment)
 		CALL_RXH(ieee80211_rx_h_michael_mic_verify)
 		/* must be after MMIC verify so header is counted in MPDU mic */
diff --git a/net/mac80211/tx.c b/net/mac80211/tx.c
index 88a18ff..c314c59 100644
--- a/net/mac80211/tx.c
+++ b/net/mac80211/tx.c
@@ -612,6 +612,19 @@ ieee80211_tx_h_select_key(struct ieee80211_tx_data *tx)
 		return TX_DROP;
 	}
 
+	if (tx->key &&
+	    unlikely(info->control.flags & IEEE80211_TX_CTRL_PORT_CTRL_PROTO) &&
+	    !tx->key->valid_rx_seen) {
+		/* Do not encrypt EAPOL frames before peer has used the key */
+		/* FIX: This is not really complete.. It would be at least
+		 * theoretically possible for the peer to never send a Data
+		 * frame and if we were to initiate reauthentication or
+		 * rekeying, we might need to encrypt the initiating EAPOL
+		 * frame.
+		 */
+		tx->key = NULL;
+	}
+
 	if (tx->key) {
 		bool skip_hw = false;
 
-- 
Jouni Malinen                                            PGP id EFC895FA

Re: AR9462 problems connecting again..

[Emmanuel Grumbach]

On Mon, Feb 23, 2015 at 7:17 PM, Jouni Malinen <j@w1.fi> wrote:
> On Sun, Feb 22, 2015 at 05:41:25PM -0800, Linus Torvalds wrote:
>> Nope, everything else I have seems to be intel wireless. I think one
>> of the kids machines is a Mac Mini with an ath5k thing, but I'm hoping
>> the wpa_supplicant.log is sufficient to give somebody an idea.
>
> It looks like there are two issues here: 1) EAPOL-Key message 4/4 (i.e.,
> the second Data frame sent by the station during association) is somehow
> not seen or accepted by the AP, 2) recovery from that msg 4/4 getting
> lost does not work in the intended way.
>
> For (1), one would likely need to see a wireless capture from a separate
> WLAN radio to say something certain about what exactly happened.
> ath5k-compatible radios would not be sufficient since this would need to
> be able to see HT frames which ath9k is mostly like using here. I
> haven't used iwlwifi as a sniffer, so I do not know whether that would
> be a workable option for this.

iwlwifi as a sniffer is good enough for that.

>
> In my tests, I can see the rate control algorithm (minstrel_ht) using a
> pretty high rate (even MCS14 with 2-stream device, which is one short of
> maximum) which is quite a bit higher than I would myself have selected
> for an EAPOL frame (especially for EAPOL-Key 4/4 which has these lovely
> issues with retransmissions) more or less immediately after association.
> Anyway, that frame is supposed to get additional fall-back TX rates for
> link layer retransmissions and those should make it much more likely for
> this to be received by the AP. Sniffer trace would confirm that.
>

IIRC we had lots of issues with that and iwlwifi's rate control doesn't jump to
high rates immediately.

>
> For (2), wpa_supplicant debug log gives a pretty clear idea on what is
> happening and based on that, I can easily reproduce this part. In fact,
> I now have a fully automated test script for verifying this with
> mac80211_hwsim.
>
> Some alternative means of improving this was discussed in this thread.
> I'm not completely happy with this, but the following mac80211 changes
> do fix this retransmission case and will likely make the issue you are
> seeing disappear since it allows any of the four EAPOL-Key msg 4/4
> transmissions to be received by the AP to avoid the disconnection. This
> doesn't fix the initial trigger behind the issue, but with those EAPOL
> retransmissions working, the likelihood of all four attempts failing
> (with each getting multiple link-layer retransmissions) is quite small.
>
>
> mac80211: Do not encrypt EAPOL frames before peer has used the key
>
> The 4-way handshake design is a bit inconvenient for the case where msg
> 3/4 needs to be transmitted (e.g., AP not receiving first transmission

needs to *re*transmitted I guess.

> of 4/4). The supplicant side has already configured the pairwise key at
> that point in time and while we allow unencrypted msg 3/4 to be
> received, we were sending out 4/4 encrypted which will result in it
> getting dropped. User space would be aware of when the EAPOL frame
> should not be encrypted, but we do not have convenient means of telling
> mac80211 that. For now, use a mac80211-specific hack to avoid EAPOL
> frame encryption to allow retransmission of 4-way handshake messages 3/4
> and 4/4 to work in a way that the authenticator side can process 4/4.
>
> ---
>  net/mac80211/key.h |  2 ++
>  net/mac80211/rx.c  | 11 +++++++++++
>  net/mac80211/tx.c  | 13 +++++++++++++
>  3 files changed, 26 insertions(+)
>
> diff --git a/net/mac80211/key.h b/net/mac80211/key.h
> index d57a9915..3e23276 100644
> --- a/net/mac80211/key.h
> +++ b/net/mac80211/key.h
> @@ -120,6 +120,8 @@ struct ieee80211_key {
>
>         /* number of times this key has been used */
>         int tx_rx_count;
> +       /* whether a valid RX decryption has happened with this key */
> +       bool valid_rx_seen;
>
>  #ifdef CONFIG_MAC80211_DEBUGFS
>         struct {
> diff --git a/net/mac80211/rx.c b/net/mac80211/rx.c
> index 1101563..8f3f86c 100644
> --- a/net/mac80211/rx.c
> +++ b/net/mac80211/rx.c
> @@ -1691,6 +1691,16 @@ ieee80211_rx_h_decrypt(struct ieee80211_rx_data *rx)
>         return result;
>  }
>
> +static ieee80211_rx_result debug_noinline
> +ieee80211_rx_h_check_key_use(struct ieee80211_rx_data *rx)
> +{
> +       struct ieee80211_rx_status *status = IEEE80211_SKB_RXCB(rx->skb);
> +
> +       if ((status->flag & RX_FLAG_DECRYPTED) && rx->key)
> +               rx->key->valid_rx_seen = true;
> +       return RX_CONTINUE;
> +}
> +
>  static inline struct ieee80211_fragment_entry *
>  ieee80211_reassemble_add(struct ieee80211_sub_if_data *sdata,
>                          unsigned int frag, unsigned int seq, int rx_queue,
> @@ -3139,6 +3149,7 @@ static void ieee80211_rx_handlers(struct ieee80211_rx_data *rx,
>                 CALL_RXH(ieee80211_rx_h_uapsd_and_pspoll)
>                 CALL_RXH(ieee80211_rx_h_sta_process)
>                 CALL_RXH(ieee80211_rx_h_decrypt)
> +               CALL_RXH(ieee80211_rx_h_check_key_use)
>                 CALL_RXH(ieee80211_rx_h_defragment)
>                 CALL_RXH(ieee80211_rx_h_michael_mic_verify)
>                 /* must be after MMIC verify so header is counted in MPDU mic */
> diff --git a/net/mac80211/tx.c b/net/mac80211/tx.c
> index 88a18ff..c314c59 100644
> --- a/net/mac80211/tx.c
> +++ b/net/mac80211/tx.c
> @@ -612,6 +612,19 @@ ieee80211_tx_h_select_key(struct ieee80211_tx_data *tx)
>                 return TX_DROP;
>         }
>
> +       if (tx->key &&
> +           unlikely(info->control.flags & IEEE80211_TX_CTRL_PORT_CTRL_PROTO) &&
> +           !tx->key->valid_rx_seen) {
> +               /* Do not encrypt EAPOL frames before peer has used the key */
> +               /* FIX: This is not really complete.. It would be at least
> +                * theoretically possible for the peer to never send a Data
> +                * frame and if we were to initiate reauthentication or
> +                * rekeying, we might need to encrypt the initiating EAPOL
> +                * frame.
> +                */
> +               tx->key = NULL;
> +       }
> +
>         if (tx->key) {
>                 bool skip_hw = false;
>
> --
> Jouni Malinen                                            PGP id EFC895FA
> --
> 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

Re: AR9462 problems connecting again..

[Linus Torvalds]

On Mon, Feb 23, 2015 at 9:17 AM, Jouni Malinen <j@w1.fi> wrote:
>
> mac80211: Do not encrypt EAPOL frames before peer has used the key

Hmm. This patch does not seem to make a difference. I thought it did
at first, but then removed the wpa_supplicant debugging, and got the
same failures.

On Sun, Feb 22, 2015 at 10:01 PM, Sujith Manoharan <sujith@msujith.org> wrote:
>
> Or 'iw dev wlp1s0 set bitrates ht-mcs-2.4 0' to choose the lowest
> HT rate.

This *might* have worked. But it's a bit hard to really make sure,
since it sometimes does succeed even without debugging when I do
nothing at all, but it did work twice in a row after doing that.

> Sporadic association problems could be a problem with the chosen rates.
> This would show the rates for the EAPOL frames:
>
> iw dev wlp1s0 interface add mon0 type monitor
> ifconfig mon0 up

Hmm. I don't actually see a "mon0" interface after the "iw dev
interface add" thing. Yes, "iw" sees it when I do "iw dev", but
"ifconfig" does not.

This machine has a fairly minimal kernel config. Does that "type
monitor" interface perhaps need some debug infrastructure that I
haven't added?

> tshark -i mon0 -Y eapol -T fields -e radiotap.datarate -e wlan -e eapol -e wlan.sa -e wlan.da

.. and then this fails, presumably for similar reasons.

                        Linus

Re: AR9462 problems connecting again..

[Linus Torvalds]

On Mon, Feb 23, 2015 at 12:06 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> This machine has a fairly minimal kernel config. Does that "type
> monitor" interface perhaps need some debug infrastructure that I
> haven't added?

Nope. Same behavior with a F21 kernel (which means that the touchpad
doesn't work, but that's a separate and known issue with this
platform).

                       Linus

Re: AR9462 problems connecting again..

[Jouni Malinen]

On Mon, Feb 23, 2015 at 12:06:09PM -0800, Linus Torvalds wrote:
> On Mon, Feb 23, 2015 at 9:17 AM, Jouni Malinen <j@w1.fi> wrote:
> > mac80211: Do not encrypt EAPOL frames before peer has used the key
> 
> Hmm. This patch does not seem to make a difference. I thought it did
> at first, but then removed the wpa_supplicant debugging, and got the
> same failures.

Interesting. That would seem to imply that this AP does not like
something about the EAPOL-Key msg 4/4 from the station during the faster
timing (no wpa_supplicant debug) and would even be unable to accept the
responses during retransmissions.. I'm not sure what could cause that.
Is there anything that the AP could provide as far as logging is
concerned?

How far is the station from the AP? Would it be possible to see whether
the behavior changes if you were within, say, five meters or so? This
should allow the higher transmit rate proposed by minstrel_ht to work
pretty reliably and that could confirm if this is indeed related to too
high a rate being used here and then for some reason being unable to
fall back to a sufficiently low rate to work at higher distance.

It would be useful if you can capture the 802.11 frame exchange from a
failed connection case with an external wireless sniffer. It sounds
like this should be doable with iwlwifi and while I haven't tested this
myself, I'd assume something like this would do the trick (this is
assuming that the interface is not being used at the time, e.g., with
wpa_supplicant):

sudo iw dev wlan0 set type monitor
sudo ip link set wlan0 up
sudo iw dev wlan0 set freq 2462 HT20
sudo dumpcap -i wlan0 -w /tmp/wlan0.pcap

# test connection and stop dumpcap after the failure
# and "sudo ip link set wlan0 down; sudo iw dev wlan0 set type station"
# to restore normal station mode

-- 
Jouni Malinen                                            PGP id EFC895FA

Re: AR9462 problems connecting again..

[Linus Torvalds]

On Mon, Feb 23, 2015 at 1:30 PM, Jouni Malinen <j@w1.fi> wrote:
>
> How far is the station from the AP? Would it be possible to see whether
> the behavior changes if you were within, say, five meters or so?

Well, it was pretty much within five meters already, but there was a
thin wall in between (and the old AP was right next to the laptop,
which might add some noise even if they are on different channels).
Going closer does seem to help, but again, it's not like this is 100%
reproducible to begin with.

So the theory that the driver starts at too high a transmit rate, and
then does not handle failures well, might be true. Of course, "not
handle failures well" is something of an understatement.

> It would be useful if you can capture the 802.11 frame exchange from a
> failed connection case with an external wireless sniffer.

I will try with my (much more reliable) iwlwifi laptop. At least the
merge window is over, so I should have some time. Knock wood.

              Linus

Re: AR9462 problems connecting again..

[Adrian Chadd]

On 23 February 2015 at 13:53, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
> On Mon, Feb 23, 2015 at 1:30 PM, Jouni Malinen <j@w1.fi> wrote:
>>
>> How far is the station from the AP? Would it be possible to see whether
>> the behavior changes if you were within, say, five meters or so?
>
> Well, it was pretty much within five meters already, but there was a
> thin wall in between (and the old AP was right next to the laptop,
> which might add some noise even if they are on different channels).
> Going closer does seem to help, but again, it's not like this is 100%
> reproducible to begin with.
>
> So the theory that the driver starts at too high a transmit rate, and
> then does not handle failures well, might be true. Of course, "not
> handle failures well" is something of an understatement.
>
>> It would be useful if you can capture the 802.11 frame exchange from a
>> failed connection case with an external wireless sniffer.
>
> I will try with my (much more reliable) iwlwifi laptop. At least the
> merge window is over, so I should have some time. Knock wood.

Hm, can we just hack mac80211/ath9k to set /all/ EAPOL frames to the
lowest negotiated basic rate and test? That way we don't have to worry
about things resetting fixed rates or whatnot.

I've done that with FreeBSD's atheros/intel drivers and net80211 stack
to fix exactly these, although I'm thinking about adding a patch based
on Jouni's note about EAPOL encrypting the final response.

Does ath9k have an easy interface for dumping out the TX descriptors
and response? That way we can see (a) what it's transmitting as, and
(b) whether the hardware indicated it got an ACK for the particular
frame.


-adrian

Re: AR9462 problems connecting again..

[Jouni Malinen]

On Mon, Feb 23, 2015 at 02:22:32PM -0800, Adrian Chadd wrote:
> On 23 February 2015 at 13:53, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
> > So the theory that the driver starts at too high a transmit rate, and
> > then does not handle failures well, might be true. Of course, "not
> > handle failures well" is something of an understatement.

> Hm, can we just hack mac80211/ath9k to set /all/ EAPOL frames to the
> lowest negotiated basic rate and test? That way we don't have to worry
> about things resetting fixed rates or whatnot.

This did not get exactly supportive response when this was proposed last
time (Sep 2013). Anyway, for a quick test, this can be done with the
following one-liner:

diff --git a/net/mac80211/tx.c b/net/mac80211/tx.c
index c314c59..b45038f 100644
--- a/net/mac80211/tx.c
+++ b/net/mac80211/tx.c
@@ -566,6 +566,7 @@ ieee80211_tx_h_check_control_port_protocol(struct ieee80211_tx_data *tx)
 		if (tx->sdata->control_port_no_encrypt)
 			info->flags |= IEEE80211_TX_INTFL_DONT_ENCRYPT;
 		info->control.flags |= IEEE80211_TX_CTRL_PORT_CTRL_PROTO;
+		info->flags |= IEEE80211_TX_CTL_USE_MINRATE;
 	}
 
 	return TX_CONTINUE;


Even I think that this goes a bit too far especially on 2.4 GHz band,
but I would actually consider limiting EAPOL frames to using non-HT/VHT
(e.g., 6 Mbps OFDM at least for EAPOL-Key frames) to avoid some
interoperability issues. I would say that the current minstrel_ht
behavior is somewhat excessive for EAPOL-Key frames in the other
direction. Using MCS 14 with fallback to something like MCS 5 for the
second Data frame after an association can certainly fail.

Number of Linux drivers do already limit EAPOL frame TX rate, so this
specific item is mainly applicable only to driver that use minstrel from
mac80211 (e.g., ath9k). Though, that IEEE80211_TX_CTL_USE_MINRATE would
likely affect most mac80211 drivers.

-- 
Jouni Malinen                                            PGP id EFC895FA

Re: AR9462 problems connecting again..

[Linus Torvalds]

On Mon, Feb 23, 2015 at 2:43 PM, Jouni Malinen <j@w1.fi> wrote:
>
> This did not get exactly supportive response when this was proposed last
> time (Sep 2013). Anyway, for a quick test, this can be done with the
> following one-liner:

fwiw, that one-liner seems to work fine for me.

Which I guess is not a huge surprise.

Side note: I've done the "turn off wifi and turn it back on" several
times to test that patch, and it has worked every time. BUT I also see
this odd behavior where the logs show that it tries to authenticate
twice: the first time it does that "send auth to 20:9f .." thing three
times (looks like 100ms apart), and nothing happens so it does
"authentication with 20:9f .. timed out". Then it waits three seconds
and tries again, and now it succeeds on the first try.

The only downside of that seems to be that it takes an extra 3s to
connect to the network - but it does now seem to *reliably* connect -
so it's not a big problem, but I wonder why it should be that
repeatable. Is there some difference between the first and the second
time it tries to authenticate?

Anyway, even if people don't like that particular patch, it does seem
like *something* like that should be done.

                         Linus

Re: AR9462 problems connecting again..

[Jouni Malinen]

On Mon, Feb 23, 2015 at 03:00:39PM -0800, Linus Torvalds wrote:
> On Mon, Feb 23, 2015 at 2:43 PM, Jouni Malinen <j@w1.fi> wrote:
> >
> > This did not get exactly supportive response when this was proposed last
> > time (Sep 2013). Anyway, for a quick test, this can be done with the
> > following one-liner:
> 
> fwiw, that one-liner seems to work fine for me.

Good to know. That seems to confirm that the issue is most likely in
some of the higher HT rates not working with that AP for some reason at
least for EAPOL frames immediately following the association. This
should really have worked since I'm pretty sure minstrel will add a
lower MCS index as a fallback rate, but maybe there are some interop
issues or just close enough to being below the required signal strength
(though, I'd find that somewhat unlikely unless there is something
messed up with the antennas etc. taken into account your description on
how close the devices are and what's between them).

> Side note: I've done the "turn off wifi and turn it back on" several
> times to test that patch, and it has worked every time. BUT I also see
> this odd behavior where the logs show that it tries to authenticate
> twice: the first time it does that "send auth to 20:9f .." thing three
> times (looks like 100ms apart), and nothing happens so it does
> "authentication with 20:9f .. timed out". Then it waits three seconds
> and tries again, and now it succeeds on the first try.
> 
> The only downside of that seems to be that it takes an extra 3s to
> connect to the network - but it does now seem to *reliably* connect -
> so it's not a big problem, but I wonder why it should be that
> repeatable. Is there some difference between the first and the second
> time it tries to authenticate?

There have been some issues in this area in the past, but it is a bit
difficult to say what could have caused it here without a wireless
capture from the operating channel of the AP. It is possible that those
Authentication frames were not actually transmitted due to some issue or
they could have even been sent out on incorrect channel, etc. That
shouldn't really happen that frequently (i.e., others should be seeing
and reporting this as well..), but it's possible something gets messed
up in channel configuration.

> Anyway, even if people don't like that particular patch, it does seem
> like *something* like that should be done.

Agreed. Just need to figure out a suitable compromise somewhere in the
middle of the minimum and close-to-maximum rates. As far as ath9k is
concerned, it would actually support four different rates for retry
series where minstrel uses only three, so it would be easy even for that
driver on its own to add a lower rate at the end if we cannot find
consensus on something more generic in mac80211. That said, I'd rather
see minstrel getting more conservative for EAPOL frames.

-- 
Jouni Malinen                                            PGP id EFC895FA

Re: AR9462 problems connecting again..

[Sujith Manoharan]

Jouni Malinen wrote:
> Even I think that this goes a bit too far especially on 2.4 GHz band,
> but I would actually consider limiting EAPOL frames to using non-HT/VHT
> (e.g., 6 Mbps OFDM at least for EAPOL-Key frames) to avoid some
> interoperability issues. I would say that the current minstrel_ht
> behavior is somewhat excessive for EAPOL-Key frames in the other
> direction. Using MCS 14 with fallback to something like MCS 5 for the
> second Data frame after an association can certainly fail.
> 
> Number of Linux drivers do already limit EAPOL frame TX rate, so this
> specific item is mainly applicable only to driver that use minstrel from
> mac80211 (e.g., ath9k). Though, that IEEE80211_TX_CTL_USE_MINRATE would
> likely affect most mac80211 drivers.

We had this in the ath9k RC, where EAPOL frames were sent out at min-rate
on the VO queue. I think instead of re-introducing it in the driver,
having it in minstrel is cleaner.

Sujith

Re: AR9462 problems connecting again..

[Andrew McGregor]

(sorry to send HTML the first time... oops)

Over the weekend I found a bug in minstrel-ht that might well be
implicated here.

The last retransmit rate is meant to be a 'get the packet there
reliably' rate; minstrel-ht doesn't do that right, and can pick a
fairly flaky rate instead.

Can't generate a proper patch right now, so this diff might not apply
cleanly, but the fix is simply to change 75 to 99 in the two places
below:

@@ -437,7 +448,7 @@ minstrel_ht_set_best_prob_rate(struct mi
     (max_tp_group != MINSTREL_CCK_GROUP))
  return;

- if (mrs->prob_ewma > MINSTREL_FRAC(75, 100)) {
+ if (mrs->prob_ewma > MINSTREL_FRAC(99, 100)) {
  cur_tp_avg = minstrel_ht_get_tp_avg(mi, cur_group, cur_idx);
  if (cur_tp_avg > tmp_tp_avg)
  mi->max_prob_rate = index;
@@ -526,7 +537,7 @@ minstrel_ht_prob_rate_reduce_streams(str
  * Rules for rate selection:
  *  - max_prob_rate must use only one stream, as a tradeoff between delivery
  *    probability and throughput during strong fluctuations
- *  - as long as the max prob rate has a probability of more than 75%, pick
+ *  - as long as the max prob rate has a probability of more than 99%, pick
  *    higher throughput rates, even if the probablity is a bit lower
  */
 static void

On Tue, Feb 24, 2015 at 11:29 AM, Sujith Manoharan <sujith@msujith.org> wrote:

> Jouni Malinen wrote:
>
> > Even I think that this goes a bit too far especially on 2.4 GHz band,
>
> > but I would actually consider limiting EAPOL frames to using non-HT/VHT
>
> > (e.g., 6 Mbps OFDM at least for EAPOL-Key frames) to avoid some
>
> > interoperability issues. I would say that the current minstrel_ht
>
> > behavior is somewhat excessive for EAPOL-Key frames in the other
>
> > direction. Using MCS 14 with fallback to something like MCS 5 for the
>
> > second Data frame after an association can certainly fail.
>
> >
>
> > Number of Linux drivers do already limit EAPOL frame TX rate, so this
>
> > specific item is mainly applicable only to driver that use minstrel from
>
> > mac80211 (e.g., ath9k). Though, that IEEE80211_TX_CTL_USE_MINRATE would
>
> > likely affect most mac80211 drivers.
>
>
> We had this in the ath9k RC, where EAPOL frames were sent out at min-rate
>
> on the VO queue. I think instead of re-introducing it in the driver,
>
> having it in minstrel is cleaner.
>
>
> Sujith
>
> --
>
> 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

Re: AR9462 problems connecting again..

[Jouni Malinen]

On Tue, Feb 24, 2015 at 01:29:27PM +1100, Andrew McGregor wrote:
> Over the weekend I found a bug in minstrel-ht that might well be
> implicated here.
> 
> The last retransmit rate is meant to be a 'get the packet there
> reliably' rate; minstrel-ht doesn't do that right, and can pick a
> fairly flaky rate instead.
> 
> Can't generate a proper patch right now, so this diff might not apply
> cleanly, but the fix is simply to change 75 to 99 in the two places
> below:

While this may indeed be helpful, I don't think it is sufficient for
this EAPOL frame related issue. What I would like to see is minstrel_ht
using a basic rate (something non-HT) at the end of the retry series for
EAPOL frames.

The current behavior looks very suspicious to me. The early EAPOL frames
after association are being used to probe for higher rates. This results
in the total number of retry attempts actually getting smaller than any
other frame, i.e., minstrel_ht seems to be using significantly _less_
robust choices for the EAPOL frames than following "normal" data frames!
This should really be the other way around..

As an example, I'm seeing this on 5 GHz band (with the 75 to 99 change
in place, but behavior was more or less identical without it):
- the first EAPOL frame (msg 2/4) getting one attempt at MCS 3, 2
  attempts at MCS 0, 2 attempts at MCS 0 (yes, identical to the previous
  one) with total maximum of 5 attempts
- the second EAPOL frame (msg 4/4) getting one attempt at MCS 9, 2
  attempts at MCS 0, 2 attempts at MCS 0 with total maximum of 5
  attempts
- another data frame after this: 5 attempts at MCS 9, 5 attempts at MCS
  3, 5 attempts at MCS 3 with total maximum of 15 attempts(!!)

This cannot be the best approach here.. For the
IEEE80211_TX_CTRL_PORT_CTRL_PROTO cases, there are identified issues
where failing to deliver the frame results is significant issues either
in getting connected in the first place or getting disconnected if
rekeying fails. 

I'm not sure how this would be implemented cleanly in minstrel_ht or
whether that is even the best place (i.e., rate.c could do this
instead), but I'd like that third attempt for control port cases to be
dropped to use a (lowish) basic rate and non-MCS at that since there may
be some interop issues with HT MCS early during association.
Alternatively with drivers like ath9k that support 4 rate values, it
would also be fine to add this basic rate attempt (or well, I'd have
multiple, say 4, such attempts) as an additional 4th entry which does
not currently seem to get used with minstrel at all.

The "(lowish) basic rate" here could be defined as 6 Mbps OFDM for 5 GHz
band and either that or maybe even 2 Mbps or 5.5 Mbps on 2.4 GHz (if
included by the AP in basic rate set).

-- 
Jouni Malinen                                            PGP id EFC895FA

Re: [ath9k-devel] AR9462 problems connecting again..

[Dave Taht]

On Tue, Feb 24, 2015 at 2:26 AM, Jouni Malinen <j@w1.fi> wrote:
> On Tue, Feb 24, 2015 at 01:29:27PM +1100, Andrew McGregor wrote:
>> Over the weekend I found a bug in minstrel-ht that might well be
>> implicated here.
>>
>> The last retransmit rate is meant to be a 'get the packet there
>> reliably' rate; minstrel-ht doesn't do that right, and can pick a
>> fairly flaky rate instead.
>>
>> Can't generate a proper patch right now, so this diff might not apply
>> cleanly, but the fix is simply to change 75 to 99 in the two places
>> below:
>
> While this may indeed be helpful, I don't think it is sufficient for
> this EAPOL frame related issue. What I would like to see is minstrel_ht
> using a basic rate (something non-HT) at the end of the retry series for
> EAPOL frames.
>
> The current behavior looks very suspicious to me. The early EAPOL frames
> after association are being used to probe for higher rates. This results
> in the total number of retry attempts actually getting smaller than any
> other frame, i.e., minstrel_ht seems to be using significantly _less_
> robust choices for the EAPOL frames than following "normal" data frames!
> This should really be the other way around..
>
> As an example, I'm seeing this on 5 GHz band (with the 75 to 99 change
> in place, but behavior was more or less identical without it):
> - the first EAPOL frame (msg 2/4) getting one attempt at MCS 3, 2
>   attempts at MCS 0, 2 attempts at MCS 0 (yes, identical to the previous
>   one) with total maximum of 5 attempts
> - the second EAPOL frame (msg 4/4) getting one attempt at MCS 9, 2
>   attempts at MCS 0, 2 attempts at MCS 0 with total maximum of 5
>   attempts
> - another data frame after this: 5 attempts at MCS 9, 5 attempts at MCS
>   3, 5 attempts at MCS 3 with total maximum of 15 attempts(!!)

I would in general prefer that the excessive retries in the present
driver layers in wifi be
dramatically reduced, the packet dropped and the problem punted to
higher layers.

> This cannot be the best approach here..

Falling back faster to the lowest possible rate with minimum retries,
and then giving up sooner would be better. 15 attempts? jeeze....

> For the
> IEEE80211_TX_CTRL_PORT_CTRL_PROTO cases, there are identified issues
> where failing to deliver the frame results is significant issues either
> in getting connected in the first place or getting disconnected if
> rekeying fails.
>
> I'm not sure how this would be implemented cleanly in minstrel_ht or
> whether that is even the best place (i.e., rate.c could do this
> instead), but I'd like that third attempt for control port cases to be
> dropped to use a (lowish) basic rate and non-MCS at that since there may
> be some interop issues with HT MCS early during association.
> Alternatively with drivers like ath9k that support 4 rate values, it
> would also be fine to add this basic rate attempt (or well, I'd have
> multiple, say 4, such attempts) as an additional 4th entry which does
> not currently seem to get used with minstrel at all.
>
> The "(lowish) basic rate" here could be defined as 6 Mbps OFDM for 5 GHz
> band and either that or maybe even 2 Mbps or 5.5 Mbps on 2.4 GHz (if
> included by the AP in basic rate set).
>
> --
> Jouni Malinen                                            PGP id EFC895FA
> _______________________________________________
> ath9k-devel mailing list
> ath9k-devel@lists.ath9k.org
> https://lists.ath9k.org/mailman/listinfo/ath9k-devel



-- 
Dave Täht
Let's make wifi fast, less jittery and reliable again!

https://plus.google.com/u/0/107942175615993706558/posts/TVX3o84jjmb

Re: [ath9k-devel] AR9462 problems connecting again..

[Thomas Hühn]

Hi Jouni,

Currently Minstrel_HT just skips EAPOL packets for its rate sampling on non-mrr chips by testing: (info->control.flags & IEEE80211_TX_CTRL_PORT_CTRL_PROTO)
On mrr hardware it uses them for probing. 
But the general MRR-chain should look like this for ath5k and ath9k chips that support 4 mrr chains:

mrr[0]:= max_tp_rate[0]
mrr[1]:= max_tp_rate[1]
mrr[2]:= max_prob_rate
mrr[3]:= basic_rate

So for Minstrel Sampling Packets as well as for data packets, the 4th mrr stage should use the slowest rate in case all other 3 mrr stages failed with their retry attempts.

I do see two possible options for control frames like EAPOL to be send out in a more robust fashion:
 - exclude those frames from AMPDU aggragates 
 - change their mrr setup to be more conservative

What do you think about this ?

Greetings Thomas


> Am 24.02.2015 um 11:26 schrieb Jouni Malinen <j@w1.fi>:
> 
> On Tue, Feb 24, 2015 at 01:29:27PM +1100, Andrew McGregor wrote:
>> Over the weekend I found a bug in minstrel-ht that might well be
>> implicated here.
>> 
>> The last retransmit rate is meant to be a 'get the packet there
>> reliably' rate; minstrel-ht doesn't do that right, and can pick a
>> fairly flaky rate instead.
>> 
>> Can't generate a proper patch right now, so this diff might not apply
>> cleanly, but the fix is simply to change 75 to 99 in the two places
>> below:
> 
> While this may indeed be helpful, I don't think it is sufficient for
> this EAPOL frame related issue. What I would like to see is minstrel_ht
> using a basic rate (something non-HT) at the end of the retry series for
> EAPOL frames.
> 
> The current behavior looks very suspicious to me. The early EAPOL frames
> after association are being used to probe for higher rates. This results
> in the total number of retry attempts actually getting smaller than any
> other frame, i.e., minstrel_ht seems to be using significantly _less_
> robust choices for the EAPOL frames than following "normal" data frames!
> This should really be the other way around..
> 
> As an example, I'm seeing this on 5 GHz band (with the 75 to 99 change
> in place, but behavior was more or less identical without it):
> - the first EAPOL frame (msg 2/4) getting one attempt at MCS 3, 2
>  attempts at MCS 0, 2 attempts at MCS 0 (yes, identical to the previous
>  one) with total maximum of 5 attempts
> - the second EAPOL frame (msg 4/4) getting one attempt at MCS 9, 2
>  attempts at MCS 0, 2 attempts at MCS 0 with total maximum of 5
>  attempts
> - another data frame after this: 5 attempts at MCS 9, 5 attempts at MCS
>  3, 5 attempts at MCS 3 with total maximum of 15 attempts(!!)
> 
> This cannot be the best approach here.. For the
> IEEE80211_TX_CTRL_PORT_CTRL_PROTO cases, there are identified issues
> where failing to deliver the frame results is significant issues either
> in getting connected in the first place or getting disconnected if
> rekeying fails. 
> 
> I'm not sure how this would be implemented cleanly in minstrel_ht or
> whether that is even the best place (i.e., rate.c could do this
> instead), but I'd like that third attempt for control port cases to be
> dropped to use a (lowish) basic rate and non-MCS at that since there may
> be some interop issues with HT MCS early during association.
> Alternatively with drivers like ath9k that support 4 rate values, it
> would also be fine to add this basic rate attempt (or well, I'd have
> multiple, say 4, such attempts) as an additional 4th entry which does
> not currently seem to get used with minstrel at all.
> 
> The "(lowish) basic rate" here could be defined as 6 Mbps OFDM for 5 GHz
> band and either that or maybe even 2 Mbps or 5.5 Mbps on 2.4 GHz (if
> included by the AP in basic rate set).
> 
> -- 
> Jouni Malinen                                            PGP id EFC895FA
> _______________________________________________
> ath9k-devel mailing list
> ath9k-devel@lists.ath9k.org
> https://lists.ath9k.org/mailman/listinfo/ath9k-devel

Re: [ath9k-devel] AR9462 problems connecting again..

[Jouni Malinen]

On Tue, Feb 24, 2015 at 06:54:47PM +0100, Thomas Hühn wrote:
> Currently Minstrel_HT just skips EAPOL packets for its rate sampling on non-mrr chips by testing: (info->control.flags & IEEE80211_TX_CTRL_PORT_CTRL_PROTO)

Yeah, I noticed that when going through the implementation, but it was
indeed only for cases other than ath9k-like drivers.

> On mrr hardware it uses them for probing. 
> But the general MRR-chain should look like this for ath5k and ath9k chips that support 4 mrr chains:
> 
> mrr[0]:= max_tp_rate[0]
> mrr[1]:= max_tp_rate[1]
> mrr[2]:= max_prob_rate
> mrr[3]:= basic_rate

Where is that mrr[3] part implemented? I did not find it when reviewing
the design (hw->max_rates >= 3 is used, but not >= 4) and this does not
match my experiments either when printing out all four values from
ath9k. In every single case I observed, the last entry was unused (idx =
-1) and only MCS values were used (i.e., not even a single case of basic
rate visible; basic rates being 6, 12, 24 Mbps OFDM in this specific
case with the AP that I used in the tests).

> So for Minstrel Sampling Packets as well as for data packets, the 4th mrr stage should use the slowest rate in case all other 3 mrr stages failed with their retry attempts.
> 
> I do see two possible options for control frames like EAPOL to be send out in a more robust fashion:
>  - exclude those frames from AMPDU aggragates 

ath9k does that for IEEE80211_TX_CTL_RATE_CTRL_PROBE which seemed to
get set for the initial EAPOL frames. I guess this could be done more
generically for all EAPOL frames.

>  - change their mrr setup to be more conservative

That mrr[3]:= basic_rate is the part I was really asking for as far as
EAPOL frames are concerned.

-- 
Jouni Malinen                                            PGP id EFC895FA

Re: [ath9k-devel] AR9462 problems connecting again..

[Thomas Hühn]

Hi Jouni,

> Where is that mrr[3] part implemented? I did not find it when reviewing
> the design (hw->max_rates >= 3 is used, but not >= 4) and this does not
> match my experiments either when printing out all four values from
> ath9k. In every single case I observed, the last entry was unused (idx =
> -1) and only MCS values were used (i.e., not even a single case of basic
> rate visible; basic rates being 6, 12, 24 Mbps OFDM in this specific
> case with the AP that I used in the tests).

Minstrel_HT does only set mrr[0..2] and does not touch the fourth mrr[3], assumed chips with 4 mrr stages.
In function minstrel_ht_update_rates() the rate table struct ieee80211_sta_rates is set for the first 3 out of 4 rates and the fouth rate (mrr[3]) is „-1“.
In case of ath9k, the driver in xmit.c allocates in function ath_tx_fill_desc() a  struct ath_tx_info info by  memset(&info, 0, sizeof(info)) .. so all info->rates[xy].Rate == 0.
Than function ath_buf_set_rate() sets all info->rates[xy].Rate to those values specified in the rate table (struct ieee8021_sta_rate) IF (!rates[i].count || (rates[i].idx < 0)) …
… so info->rates[3].Rate is untouched and still  „0“.

I just added a printk() to xmit.c in function ath_tx_fill_desc() just before ath9k_hw_set_txdesc() is called.
>From the log I get, e.g.:

[  169.543554] mrr setup: mrr[0]:133 mrr[1]:132 mrr[2]:134 mrr[3]:0 

I have not check yet if info->rates[3].Rate == 0 is the lowest possible rate… but I would guess so.


Greetings Thomas

Re: [ath9k-devel] AR9462 problems connecting again..

[Adrian Chadd]

Hi,

I thought about doing this for rate probing with FreeBSD's sample rate
algorithm, but after actually having to use the damned thing in noisy
environments I realised that it just wasn't worth the effort to
optimise rate control selection whilst doing EAPOL frames.

If we did more useful software retransmission at lower rates then
sure, one could just be much more conservative about the rates and
retry a few times at a lower rate. However, since that isn't the case
and we only get three or so attempts at EAPOL exchange - once a second
- before an AP decides we're no good, I figured I'd just skip anything
other than the lowest basic rates for the frame exchange and make it
associate quicker.

I had the same problem with DHCP - initial DHCP leases were failing
because the rate control code started high/medium and didn't degrade
quickly enough before the next round of DHCP attempts. DHCP backs off
even more aggressively, so failing that initial DHCP was quite
expensive.



-adrian

Re: [ath9k-devel] AR9462 problems connecting again..

[Jouni Malinen]

On Tue, Feb 24, 2015 at 11:38:02PM +0100, Thomas Hühn wrote:
> Minstrel_HT does only set mrr[0..2] and does not touch the fourth mrr[3], assumed chips with 4 mrr stages.
> In function minstrel_ht_update_rates() the rate table struct ieee80211_sta_rates is set for the first 3 out of 4 rates and the fouth rate (mrr[3]) is „-1“.

Agreed.

> In case of ath9k, the driver in xmit.c allocates in function ath_tx_fill_desc() a  struct ath_tx_info info by  memset(&info, 0, sizeof(info)) .. so all info->rates[xy].Rate == 0.
> Than function ath_buf_set_rate() sets all info->rates[xy].Rate to those values specified in the rate table (struct ieee8021_sta_rate) IF (!rates[i].count || (rates[i].idx < 0)) …
> … so info->rates[3].Rate is untouched and still  „0“.

Sure, it can be 0 and so is the number of tries at that rate..

> I just added a printk() to xmit.c in function ath_tx_fill_desc() just before ath9k_hw_set_txdesc() is called.
> From the log I get, e.g.:
> 
> [  169.543554] mrr setup: mrr[0]:133 mrr[1]:132 mrr[2]:134 mrr[3]:0 
> 
> I have not check yet if info->rates[3].Rate == 0 is the lowest possible rate… but I would guess so.

It is not and even if it were, it does not matter since this 4th item is
used for _0_ tries. I've verified the exact behavior with a sniffer for
a case where the target device does not ACK frames. ath9k ends up
sending at exactly the three different rates indicated in the first
three values and nothing else. With RC probing (which happens to occur
for the initial EAPOL frames, this results in only one attempt at
MCS(>0) and two + two attempts at MCS0. No non-MCS rates are tried. As
pointed out previously, this is likely fine for normal data frames, but
not for EAPOL.

-- 
Jouni Malinen                                            PGP id EFC895FA

Re: [ath9k-devel] AR9462 problems connecting again..

[Thomas Hühn]

Hi Jouni,

>> In case of ath9k, the driver in xmit.c allocates in function ath_tx_fill_desc() a  struct ath_tx_info info by  memset(&info, 0, sizeof(info)) .. so all info->rates[xy].Rate == 0.
>> Than function ath_buf_set_rate() sets all info->rates[xy].Rate to those values specified in the rate table (struct ieee8021_sta_rate) IF (!rates[i].count || (rates[i].idx < 0)) …
>> … so info->rates[3].Rate is untouched and still  „0“.
> 
> Sure, it can be 0 and so is the number of tries at that rate..

You are absolutely right … as the tries are 0 as well, the 4th mrr[3] is not used. I missed that obvious point.


>> I just added a printk() to xmit.c in function ath_tx_fill_desc() just before ath9k_hw_set_txdesc() is called.
>> From the log I get, e.g.:
>> 
>> [  169.543554] mrr setup: mrr[0]:133 mrr[1]:132 mrr[2]:134 mrr[3]:0 
>> 
>> I have not check yet if info->rates[3].Rate == 0 is the lowest possible rate… but I would guess so.
> 
> It is not and even if it were, it does not matter since this 4th item is
> used for _0_ tries. I've verified the exact behavior with a sniffer for
> a case where the target device does not ACK frames. ath9k ends up
> sending at exactly the three different rates indicated in the first
> three values and nothing else. With RC probing (which happens to occur
> for the initial EAPOL frames, this results in only one attempt at
> MCS(>0) and two + two attempts at MCS0. No non-MCS rates are tried. As
> pointed out previously, this is likely fine for normal data frames, but
> not for EAPOL.

I do agree in changing the way to assign a (mrr) rate set for  EAPOL frames in the most robust fashion.

Greetings Thomas


> 
> -- 
> Jouni Malinen                                            PGP id EFC895FA
> _______________________________________________
> ath9k-devel mailing list
> ath9k-devel@lists.ath9k.org
> https://lists.ath9k.org/mailman/listinfo/ath9k-devel

Re: [ath9k-devel] AR9462 problems connecting again..

[Felix Fietkau]

On 2015-02-25 07:14, Jouni Malinen wrote:
> On Tue, Feb 24, 2015 at 06:54:47PM +0100, Thomas Hühn wrote:
>> Currently Minstrel_HT just skips EAPOL packets for its rate sampling on non-mrr chips by testing: (info->control.flags & IEEE80211_TX_CTRL_PORT_CTRL_PROTO)
> 
> Yeah, I noticed that when going through the implementation, but it was
> indeed only for cases other than ath9k-like drivers.
> 
>> On mrr hardware it uses them for probing. 
>> But the general MRR-chain should look like this for ath5k and ath9k chips that support 4 mrr chains:
>> 
>> mrr[0]:= max_tp_rate[0]
>> mrr[1]:= max_tp_rate[1]
>> mrr[2]:= max_prob_rate
>> mrr[3]:= basic_rate
> 
> Where is that mrr[3] part implemented? I did not find it when reviewing
> the design (hw->max_rates >= 3 is used, but not >= 4) and this does not
> match my experiments either when printing out all four values from
> ath9k. In every single case I observed, the last entry was unused (idx =
> -1) and only MCS values were used (i.e., not even a single case of basic
> rate visible; basic rates being 6, 12, 24 Mbps OFDM in this specific
> case with the AP that I used in the tests).
Minstrel_ht does *NOT* use mrr[3], nor should it. For normal data
packets, a little packet loss under tough conditions is good, otherwise
we risk lots of wasted airtime and bufferbloat.

>> So for Minstrel Sampling Packets as well as for data packets, the 4th mrr stage should use the slowest rate in case all other 3 mrr stages failed with their retry attempts.
>> 
>> I do see two possible options for control frames like EAPOL to be send out in a more robust fashion:
>>  - exclude those frames from AMPDU aggragates 
> 
> ath9k does that for IEEE80211_TX_CTL_RATE_CTRL_PROBE which seemed to
> get set for the initial EAPOL frames. I guess this could be done more
> generically for all EAPOL frames.
I agree.

>>  - change their mrr setup to be more conservative
> 
> That mrr[3]:= basic_rate is the part I was really asking for as far as
> EAPOL frames are concerned.
I don't think we need that. If we just exclude EAPOL from both probing
and aggregation, it should be safe. While it's connecting, that leaves
in low rates in the retry chain anyway.

If it still fails often enough to be noticeable under normal conditions,
there must be something seriously wrong outside of rate control, and we
should not paper over it with a crude band-aid workaround.

- Felix

Re: [ath9k-devel] AR9462 problems connecting again..

[Jouni Malinen]

On Wed, Feb 25, 2015 at 06:00:08PM +1300, Felix Fietkau wrote:
> Minstrel_ht does *NOT* use mrr[3], nor should it. For normal data
> packets, a little packet loss under tough conditions is good, otherwise
> we risk lots of wasted airtime and bufferbloat.

I agree for normal data packets, but EAPOL frames are not really normal
data packet even though they happen to be transmitted as Data frames.
EAPOL frames are rare enough to not wast much airtime (and recovery from
an issue would anyway use way more airtime) and bufferbloat is
irrelevant for EAPOL frames. For EAPOL frames, little packet loss is not
good. Especially for EAPOL-Key msg 4/4, the only recovery option in many
cases is to reassociate with the AP and start from scratch.

> > That mrr[3]:= basic_rate is the part I was really asking for as far as
> > EAPOL frames are concerned.
> I don't think we need that. If we just exclude EAPOL from both probing
> and aggregation, it should be safe. While it's connecting, that leaves
> in low rates in the retry chain anyway.

Not low enough IMHO. EAPOL is a special case and needs to be addressed
as such. It is special for at least two reasons: being very early in the
association (well, the very _first_ Data frames using rate control) and
being critical for maintaining the connection (AP will disconnect if it
does not reply response).

What happens now is way too optimistic:
- one try at MCS 2 followed by four tries at MCS 0 for EAPOL-Key msg 2/4
- one try at MCS 9 (or so) followed by four tries at MCS 0 for EAPOL-Key
  msg 4/4 (this being the most critical frame in the connection sequence
  due to not having a good recovery mechanism)

Dropping probing from these would allow one more attempt at the first
rate and I guess it would also drop the first rate to somewhat lower.

I'm fine with using these MCS rates as the first option, but I do think
that we have to add one more rate to the end (or change the 3rd rate if
that is easier for implementation) to be non-MCS and I think one of the
basic rates (say, 6 Mbps on 5 GHz and maybe 2 or 5.5 Mbps on 2.4 GHz)
with number of tries (say, 4).

There have been way too many cases reported where "strange issues" with
4-way exchange (those EAPOL-Key frames) result in connection failing.
While not all of these can be explained with the TX rate, I'm pretty
sure large portion of these issues are indeed caused by too optimistic
TX rate selection. Such policies may be acceptable for other Data
frames, but not for EAPOL.

> If it still fails often enough to be noticeable under normal conditions,
> there must be something seriously wrong outside of rate control, and we
> should not paper over it with a crude band-aid workaround.

There may be something else wrong (say, some kind of interference), but
there is no way we can assume normal users to be able to fix such
issues. If we make EAPOL frames go through more robustly, the connection
can be established in more cases and this can result in relatively
functional network connection and rate control can handle the less
critical data frames through whatever means to get optimal throughput
from the network. As such, I do think we do need to "paper over" this
for EAPOL frames.

-- 
Jouni Malinen                                            PGP id EFC895FA

Re: [ath9k-devel] AR9462 problems connecting again..

[Linus Torvalds]

On Wed, Feb 25, 2015 at 6:47 AM, Jouni Malinen <j@w1.fi> wrote:
>
> There may be something else wrong (say, some kind of interference), but
> there is no way we can assume normal users to be able to fix such
> issues. If we make EAPOL frames go through more robustly, the connection
> can be established in more cases and this can result in relatively
> functional network connection and rate control can handle the less
> critical data frames through whatever means to get optimal throughput
> from the network. As such, I do think we do need to "paper over" this
> for EAPOL frames.

While I realize that people may disagree about the exact details of
how to fix this in the long run, may I suggest that in the meantime we
at least get the two workaround patches applied?

I'm talking about the two from Jouni - the "don't encrypt EAPOL
frames" one, and the one-liner that makes all EAPOL frames go at the
lowest data rate.

Even if "lowest data rate" is ridiculously low, and even if that might
disturb other things going on on the same channel at the same time,
those authentication packets shouldn't be so common as to be a
problem.  No?

Jouni has a few packet dumps for me, and he's stumped as to what
exactly is going on, but those two patches (well, the one-liner "low
data rate EAPOL" in particular, it seems) do seem to make my
connections go through reliably.

And it seems that other drivers already are working around the EAPOL
issue in similar ways, judging by the comments about iwlwifi.

Last time I had connection issues with this laptop, nothing ended up
happening in the end, and I had people pipe up saying they had had
similar problems. I'd hate for the same "nothing" to happen this time
just because people aren't 100% sure what the final right thing is to
do. So I'd really like people to apply the simple workarounds for now
because clearly something is badly wrong, and *if* there is some
better resolution later, that's fine.

I'll happily test patches. It seems to be pretty repeatable for me,
even if that "pretty repeatable" seems to be very much about the
laptop being in one very particular place (it's right next to another
AP, there's random other electronics around, since it's on my messy
desk etc). So I wouldn't be at all surprised by horribly interference.
And the AP is supposed to be ceiling- or wall-mounted, but because I'm
just testing things out it's just sitting on a table in the next room,
so for all I know it's in the *exact* worst position for the antennas
etc etc.

So I'm sure I can improve reception of my laptop, but that's not the
point. The point is that bad wireless networks aren't so unusual, and
right now things clearly don't work as well as they could.

Does anybody hate Jouni's two patches *so* much that they can
articulate *why* it would be wrong to apply them as interim patches?
And if so, do you have better patches for me to try? Because if not..

                                 Linus

Re: [ath9k-devel] AR9462 problems connecting again..

[Peter Stuge]

Linus Torvalds wrote:
> Last time I had connection issues with this laptop, nothing ended up
> happening in the end, and I had people pipe up saying they had had
> similar problems. I'd hate for the same "nothing" to happen this time
> just because people aren't 100% sure what the final right thing is to
> do. So I'd really like people to apply the simple workarounds for now
> because clearly something is badly wrong, and *if* there is some
> better resolution later, that's fine.
..
> So I'm sure I can improve reception of my laptop, but that's not the
> point. The point is that bad wireless networks aren't so unusual, and
> right now things clearly don't work as well as they could.

Those two patches (the one-liner in particular) should have gone
in already 5-10 years ago. This has been an embarrassing problem
for many years.

I'm glad that people jumped this time around.


//Peter

Re: [ath9k-devel] AR9462 problems connecting again..

[Adrian Chadd]

On 25 February 2015 at 10:14, Linus Torvalds
<torvalds@linux-foundation.org> wrote:


> While I realize that people may disagree about the exact details of
> how to fix this in the long run, may I suggest that in the meantime we
> at least get the two workaround patches applied?
>
> I'm talking about the two from Jouni - the "don't encrypt EAPOL
> frames" one, and the one-liner that makes all EAPOL frames go at the
> lowest data rate.
>
> Even if "lowest data rate" is ridiculously low, and even if that might
> disturb other things going on on the same channel at the same time,
> those authentication packets shouldn't be so common as to be a
> problem.  No?
>
> Jouni has a few packet dumps for me, and he's stumped as to what
> exactly is going on, but those two patches (well, the one-liner "low
> data rate EAPOL" in particular, it seems) do seem to make my
> connections go through reliably.
>
> And it seems that other drivers already are working around the EAPOL
> issue in similar ways, judging by the comments about iwlwifi.

[snip]

> So I'm sure I can improve reception of my laptop, but that's not the
> point. The point is that bad wireless networks aren't so unusual, and
> right now things clearly don't work as well as they could.
>
> Does anybody hate Jouni's two patches *so* much that they can
> articulate *why* it would be wrong to apply them as interim patches?
> And if so, do you have better patches for me to try? Because if not..

I agree with you. I think you should just have EAPOL frames go out at
the lowest rate for now and then worry about experimenting with more
interesting ways to make EAPOL / DHCP frames cheaper. It fixes a lot
of problems in noisy areas. That hack was hiding around in various
commercial drivers I've seen, and it's been in FreeBSD for a while.

Same with DHCP traffic too - it's the second set of data frames that
the rate control code sees, and it's the primary reason I dropped the
initial sample rate down in FreeBSD so the DHCP exchange would have a
better chance of succeeding after association.



-adrian

Re: [ath9k-devel] AR9462 problems connecting again..

[Andrew McGregor]

On Thu, Feb 26, 2015 at 7:22 AM, Adrian Chadd <adrian@freebsd.org> wrote:
> On 25 February 2015 at 10:14, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
>
>
>> While I realize that people may disagree about the exact details of
>> how to fix this in the long run, may I suggest that in the meantime we
>> at least get the two workaround patches applied?
>>
>> I'm talking about the two from Jouni - the "don't encrypt EAPOL
>> frames" one, and the one-liner that makes all EAPOL frames go at the
>> lowest data rate.
>>
>> Even if "lowest data rate" is ridiculously low, and even if that might
>> disturb other things going on on the same channel at the same time,
>> those authentication packets shouldn't be so common as to be a
>> problem.  No?
>>
>> Jouni has a few packet dumps for me, and he's stumped as to what
>> exactly is going on, but those two patches (well, the one-liner "low
>> data rate EAPOL" in particular, it seems) do seem to make my
>> connections go through reliably.
>>
>> And it seems that other drivers already are working around the EAPOL
>> issue in similar ways, judging by the comments about iwlwifi.
>
> [snip]
>
>> So I'm sure I can improve reception of my laptop, but that's not the
>> point. The point is that bad wireless networks aren't so unusual, and
>> right now things clearly don't work as well as they could.
>>
>> Does anybody hate Jouni's two patches *so* much that they can
>> articulate *why* it would be wrong to apply them as interim patches?
>> And if so, do you have better patches for me to try? Because if not..
>
> I agree with you. I think you should just have EAPOL frames go out at
> the lowest rate for now and then worry about experimenting with more
> interesting ways to make EAPOL / DHCP frames cheaper. It fixes a lot
> of problems in noisy areas. That hack was hiding around in various
> commercial drivers I've seen, and it's been in FreeBSD for a while.
>
> Same with DHCP traffic too - it's the second set of data frames that
> the rate control code sees, and it's the primary reason I dropped the
> initial sample rate down in FreeBSD so the DHCP exchange would have a
> better chance of succeeding after association.
>
>
>
> -adrian

+1

Really, who cares about efficiency here; these are rare control packets.

Re: [ath9k-devel] AR9462 problems connecting again..

[Linus Torvalds]

On Wed, Feb 25, 2015 at 10:14 AM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> I'm talking about the two from Jouni - the "don't encrypt EAPOL
> frames" one, and the one-liner that makes all EAPOL frames go at the
> lowest data rate.

So I just found out and confirmed that this is not Atheros-specific in
any way - it looks like it's simply the UniFi AP that does not like
high-data-rate authentification frames at all.

Because it looks like the brcmsmac driver has *exactly* the same
behavior with this AP (in an Apple Macbook air). I assume brcmsmac
uses the net/80211/tx.c logic too.

And Jouni's one-liner fixes that one too, although as usual, maybe
there is some testing noise, and I screwed something up. This time I
only did the one-liner, so that's the critical one.

It's interesting to note how nothing else has been unhappy with that
network (admittedly it's been mainly android devices and a HP printer
that I've tested), so it looks like everybody else does low-rate
authentication packets anyway.

So this actually looks like a Ubiquiti UniFi AP bug to me, but it also
looks like presumably everybody else does low-rate initial packets,
and our kernel 802.11 layer should just follow suit. The whole
robustness principle and "be conservative in what you send, and
liberal in what you accept" etc.

                        Linus

Re: [ath9k-devel] AR9462 problems connecting again..

[Arend van Spriel]

On 02/26/15 06:55, Linus Torvalds wrote:
> Because it looks like the brcmsmac driver has*exactly*  the same
> behavior with this AP (in an Apple Macbook air). I assume brcmsmac
> uses the net/80211/tx.c logic too.

That makes sense as brcmsmac is a mac80211 driver that uses the 
minstrel-ht rate control algorithm. iwlwifi is also a mac80211 driver 
but it uses a different rate control algorithm so if you have that lying 
around it would be interesting to test that (if you did not already do 
that).

Regards,
Arend

Re: [ath9k-devel] AR9462 problems connecting again..

[Jouni Malinen]

On Wed, Feb 25, 2015 at 10:14:45AM -0800, Linus Torvalds wrote:
> While I realize that people may disagree about the exact details of
> how to fix this in the long run, may I suggest that in the meantime we
> at least get the two workaround patches applied?

> Does anybody hate Jouni's two patches *so* much that they can
> articulate *why* it would be wrong to apply them as interim patches?
> And if so, do you have better patches for me to try? Because if not..

Of all people, I do actually have some hatred on the one-liner to force
minimum rate for all EAPOL TX attempts. That is punishing the vast
majority of cases where the AP is perfectly fine with higher MCS rates
being used (and MCS 0 being sufficient fallback option) for EAPOL. Being
able to use higher TX rates as the initial attempt is a nice feature and
even though this may be limited to number of upstream Linux drivers
today, that part of the feature is an improvement, IMHO. This can even
be more robust in some environments especially when going through long
EAP exchange with certain types of interference.

That said, it is clear to me that we need to modify the current behavior
to be more conservative with some of the EAPOL frame retries. I'm not
familiar enough with the current minstrel implementation to prepare a
clean patch doing the approach I think that should be used here (replace
the last rate with a low basic rate and add couple of tries with it). I
have reason to believe that Felix might be able to look at this in
couple of weeks, though.

In other words, I think I'll send out a more formal version of the
patches so that they can be applied now if desired while keeping in mind
that we may want to replace the minrate-for-EAPOL with something else
later. As far as the EAPOL-Key msg 4/4 retries without encryption patch
is concerned, I think I have enough concern on the couple of corner
cases that I know it does not address (and may break), so it may take
some more time before I'm ready to suggest it (or a bit modified version
of it) to be applied, though.

-- 
Jouni Malinen                                            PGP id EFC895FA

Re: [ath9k-devel] AR9462 problems connecting again..

[Peter Stuge]

Jouni Malinen wrote:
> punishing the vast majority of cases where the AP is perfectly fine
> with higher MCS rates

First make it work (everywhere), then make it fast (where possible).


//Peter

Re: [ath9k-devel] AR9462 problems connecting again..

[Adrian Chadd]

On 26 February 2015 at 02:20, Jouni Malinen <j@w1.fi> wrote:
> On Wed, Feb 25, 2015 at 10:14:45AM -0800, Linus Torvalds wrote:
>> While I realize that people may disagree about the exact details of
>> how to fix this in the long run, may I suggest that in the meantime we
>> at least get the two workaround patches applied?
>
>> Does anybody hate Jouni's two patches *so* much that they can
>> articulate *why* it would be wrong to apply them as interim patches?
>> And if so, do you have better patches for me to try? Because if not..
>
> Of all people, I do actually have some hatred on the one-liner to force
> minimum rate for all EAPOL TX attempts. That is punishing the vast
> majority of cases where the AP is perfectly fine with higher MCS rates
> being used (and MCS 0 being sufficient fallback option) for EAPOL. Being
> able to use higher TX rates as the initial attempt is a nice feature and
> even though this may be limited to number of upstream Linux drivers
> today, that part of the feature is an improvement, IMHO. This can even
> be more robust in some environments especially when going through long
> EAP exchange with certain types of interference.

I remember running the math - well, the "airtime" math, and realised
it was almost always cheaper to do the single, non-aggregated EAPOL
frame exchange at the lowest rate than to try higher rates and fall
back to the lowest rates.




-adrian

Re: AR9462 problems connecting again..

[Sujith Manoharan]

Linus Torvalds wrote:
> I've got the wpa supplicant log for this timeframe, but I'd rather not
> send it out in public. I see "[REMOVED] for what looks like the key
> data, but there's a lot of other hex data. Is any of it sensitive?

Unless the '-K' option is used with wpa_s, the keys are not displayed
in the debug output when '-dd' is used, so it would be helpful to
have the wpa_s log.

Sujith