On Mon, 2016-01-04 at 19:29 -0800, Adam Jacobs wrote:
> Okay, here's some better logging showing the failure. I reproduced
> this by starting wpa_supplicant manually, with the same flags as DBUS
> uses plus -dd. It does appear the problem is cryptobinding-related.
>
> I still haven't found a combination of options that reproduces the
> failure without using NetworkManager, but I've only tried a few.
>
>
> Also, the failure seems to happen pretty consistently after around 30
> minutes.
The relevant pieces:
1451963729.358345: EAP-PEAP: Compound_MAC data - hexdump(len=61): 00 0c
00 38 00 00 00 00 a8 c8 90 39 15 20 a4 c6 90 9d 62 2c 02 e6 84 85 d9 04
4c 44 76 40 f5 00 03 0c 4f de cd aa 5a 36 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 19
1451963729.358417: EAP-PEAP: Invalid Compound_MAC in cryptobinding TLV
1451963729.358431: EAP-PEAP: Received MAC - hexdump(len=20): c2 57 d5
64 8d d3 a6 08 bc de 5e ab bc e4 20 22 55 57 76 6f
1451963729.358448: EAP-PEAP: Expected MAC - hexdump(len=20): c9 26 98
4a 2b 87 4c 54 b0 f8 28 81 75 cc 3d 3c 46 2d 61 e9
1451963729.358464: EAP-TLV: Result TLV - hexdump(len=2): 00 01
1451963729.358475: EAP-TLV: TLV Result - Success - EAP-TLV/Phase2
Completed
1451963729.358488: EAP-TLV: Earlier failure - force failed Phase 2
I'll leave it for Jouni to dig into...
Dan
>
>
>
>
> 1451963600.200010: wlan0: BSS: Remove id 134 BSSID f8:4f:57:13:f3:6d
> SSID 'QA-testnet' due to wpa_bss_flush_by_age
> 1451963600.200048: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/134'
> 1451963600.200123: wlan0: BSS: Remove id 136 BSSID f8:4f:57:13:f3:6b
> SSID 'NoFrags' due to wpa_bss_flush_by_age
> 1451963600.200136: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/136'
> 1451963600.200173: wlan0: BSS: Remove id 137 BSSID f8:4f:57:13:f3:6c
> SSID 'key-testnet' due to wpa_bss_flush_by_age
> 1451963600.200184: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/137'
> 1451963600.200218: wlan0: BSS: Remove id 113 BSSID 00:1d:7e:ce:85:97
> SSID 'demonet' due to wpa_bss_flush_by_age
> 1451963600.200229: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/113'
> 1451963600.200261: wlan0: BSS: Remove id 138 BSSID f8:4f:57:13:f3:64
> SSID 'NoFrags' due to wpa_bss_flush_by_age
> 1451963600.200272: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/138'
> 1451963600.200304: wlan0: BSS: Remove id 139 BSSID 84:61:a0:d8:68:00
> SSID 'Sandwiches2' due to wpa_bss_flush_by_age
> 1451963600.200314: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/139'
> 1451963600.200347: wlan0: BSS: Remove id 127 BSSID c0:25:5c:de:10:8f
> SSID 'Mocana-SECURE' due to wpa_bss_flush_by_age
> 1451963600.200357: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/127'
> 1451963600.200388: wlan0: BSS: Remove id 98 BSSID c0:25:5c:de:10:8b
> SSID 'NoFrags' due to wpa_bss_flush_by_age
> 1451963600.200399: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/98'
> 1451963600.200429: wlan0: BSS: Remove id 128 BSSID c0:25:5c:de:10:8d
> SSID 'QA-testnet' due to wpa_bss_flush_by_age
> 1451963600.200440: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/128'
> 1451963600.200469: wlan0: BSS: Remove id 126 BSSID c0:25:5c:de:10:8c
> SSID 'key-testnet' due to wpa_bss_flush_by_age
> 1451963600.200480: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/126'
> 1451963600.200509: wlan0: BSS: Remove id 129 BSSID 84:b8:02:22:98:80
> SSID 'EONCRNA' due to wpa_bss_flush_by_age
> 1451963600.200520: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/129'
> 1451963600.200550: wlan0: BSS: Remove id 118 BSSID 84:b8:02:22:98:81
> SSID 'EONCRNA-Guest' due to wpa_bss_flush_by_age
> 1451963600.200561: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/118'
> 1451963600.200590: wlan0: BSS: Remove id 140 BSSID 34:a8:4e:1c:b3:21
> SSID 'EONCRNA-Guest' due to wpa_bss_flush_by_age
> 1451963600.200601: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/140'
> 1451963600.200630: wlan0: BSS: Remove id 141 BSSID 24:a2:e1:ee:14:a8
> SSID 'Edutect Wireless Network' due to wpa_bss_flush_by_age
> 1451963600.200641: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/141'
> 1451963600.200670: wlan0: BSS: Remove id 124 BSSID f8:4f:57:13:f3:6e
> SSID 'Mocana-GUEST' due to wpa_bss_flush_by_age
> 1451963600.200680: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/124'
> 1451963600.200710: wlan0: BSS: Remove id 131 BSSID c0:25:5c:de:10:8e
> SSID 'Mocana-GUEST' due to wpa_bss_flush_by_age
> 1451963600.200720: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/131'
> 1451963600.200757: p2p-dev-wlan0: BSS: Remove id 134 BSSID
> f8:4f:57:13:f3:6d SSID 'QA-testnet' due to wpa_bss_flush_by_age
> 1451963600.200771: p2p-dev-wlan0: BSS: Remove id 136 BSSID
> f8:4f:57:13:f3:6b SSID 'NoFrags' due to wpa_bss_flush_by_age
> 1451963600.200785: p2p-dev-wlan0: BSS: Remove id 137 BSSID
> f8:4f:57:13:f3:6c SSID 'key-testnet' due to wpa_bss_flush_by_age
> 1451963600.200798: p2p-dev-wlan0: BSS: Remove id 113 BSSID
> 00:1d:7e:ce:85:97 SSID 'demonet' due to wpa_bss_flush_by_age
> 1451963600.200811: p2p-dev-wlan0: BSS: Remove id 138 BSSID
> f8:4f:57:13:f3:64 SSID 'NoFrags' due to wpa_bss_flush_by_age
> 1451963600.200824: p2p-dev-wlan0: BSS: Remove id 139 BSSID
> 84:61:a0:d8:68:00 SSID 'Sandwiches2' due to wpa_bss_flush_by_age
> 1451963600.200837: p2p-dev-wlan0: BSS: Remove id 127 BSSID
> c0:25:5c:de:10:8f SSID 'Mocana-SECURE' due to wpa_bss_flush_by_age
> 1451963600.200850: p2p-dev-wlan0: BSS: Remove id 98 BSSID
> c0:25:5c:de:10:8b SSID 'NoFrags' due to wpa_bss_flush_by_age
> 1451963600.200863: p2p-dev-wlan0: BSS: Remove id 128 BSSID
> c0:25:5c:de:10:8d SSID 'QA-testnet' due to wpa_bss_flush_by_age
> 1451963600.200876: p2p-dev-wlan0: BSS: Remove id 126 BSSID
> c0:25:5c:de:10:8c SSID 'key-testnet' due to wpa_bss_flush_by_age
> 1451963600.200889: p2p-dev-wlan0: BSS: Remove id 129 BSSID
> 84:b8:02:22:98:80 SSID 'EONCRNA' due to wpa_bss_flush_by_age
> 1451963600.200902: p2p-dev-wlan0: BSS: Remove id 118 BSSID
> 84:b8:02:22:98:81 SSID 'EONCRNA-Guest' due to wpa_bss_flush_by_age
> 1451963600.200916: p2p-dev-wlan0: BSS: Remove id 140 BSSID
> 34:a8:4e:1c:b3:21 SSID 'EONCRNA-Guest' due to wpa_bss_flush_by_age
> 1451963600.200930: p2p-dev-wlan0: BSS: Remove id 141 BSSID
> 24:a2:e1:ee:14:a8 SSID 'Edutect Wireless Network' due to
> wpa_bss_flush_by_age
> 1451963600.200943: p2p-dev-wlan0: BSS: Remove id 124 BSSID
> f8:4f:57:13:f3:6e SSID 'Mocana-GUEST' due to wpa_bss_flush_by_age
> 1451963600.200959: p2p-dev-wlan0: BSS: Remove id 131 BSSID
> c0:25:5c:de:10:8e SSID 'Mocana-GUEST' due to wpa_bss_flush_by_age
> 1451963600.205178: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3
> 1451963657.605411: dbus: fi.w1.wpa_supplicant1.Interface.Scan
> (/fi/w1/wpa_supplicant1/Interfaces/3) [a{sv}]
> 1451963657.605461: wlan0: Add radio work 'scan'@0x555b677d8300
> 1451963657.605474: wlan0: First radio work item in the queue -
> schedule start immediately
> 1451963657.605673: wlan0: Starting radio work 'scan'@0x555b677d8300 a
> fter 0.000196 second wait
> 1451963657.605859: wlan0: nl80211: scan request
> 1451963657.605900: nl80211: Scan SSID - hexdump_ascii(len=0): [NULL]
> 1451963657.606464: Scan requested (ret=0) - scan timeout 30 seconds
> 1451963657.606504: nl80211: Event message available
> 1451963657.606523: nl80211: Ignored event (cmd=33) for foreign
> interface (ifindex 3 wdev 0x0)
> 1451963657.606539: nl80211: Drv Event 33 (NL80211_CMD_TRIGGER_SCAN)
> received for wlan0
> 1451963657.606554: wlan0: nl80211: Scan trigger
> 1451963657.606570: wlan0: Event SCAN_STARTED (47) received
> 1451963657.606585: wlan0: Own scan request started a scan in 0.000087
> seconds
> 1451963657.611014: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3
> 1451963659.208171: RTM_NEWLINK: ifi_index=3 ifname=wlan0 wext
> ifi_family=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
> 1451963659.208233: nl80211: Event message available
> 1451963659.208267: nl80211: Ignored event (cmd=34) for foreign
> interface (ifindex 3 wdev 0x0)
> 1451963659.208285: nl80211: Drv Event 34
> (NL80211_CMD_NEW_SCAN_RESULTS) received for wlan0
> 1451963659.208304: wlan0: nl80211: New scan results available
> 1451963659.208323: nl80211: Scan probed for SSID ''
> 1451963659.208352: nl80211: Scan included frequencies: 2412 2417 2422
> 2427 2432 2437 2442 2447 2452 2457 2462 5180 5200 5220 5240 5260 5280
> 5300 5320 5745 5765 5785 5805 5825
> 1451963659.208447: wlan0: Event SCAN_RESULTS (3) received
> 1451963659.208462: wlan0: Scan completed in 1.601878 seconds
> 1451963659.208658: nl80211: Associated on 5785 MHz
> 1451963659.208711: nl80211: Associated with 3c:0e:23:8e:48:3f
> 1451963659.208843: nl80211: Received scan results (31 BSSes)
> 1451963659.209113: nl80211: Scan results indicate BSS status with
> 3c:0e:23:8e:48:3f as associated
> 1451963659.209242: wlan0: BSS: Start scan result update 20
> 1451963659.209394: wlan0: BSS: Add new id 146 BSSID f8:4f:57:13:f3:6b
> SSID 'NoFrags'
> 1451963659.209417: dbus: Register BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/146'
> 1451963659.209611: wlan0: BSS: Add new id 147 BSSID f8:4f:57:13:f3:6d
> SSID 'QA-testnet'
> 1451963659.209635: dbus: Register BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/147'
> 1451963659.209812: wlan0: BSS: Add new id 148 BSSID f8:4f:57:13:f3:6c
> SSID 'key-testnet'
> 1451963659.209836: dbus: Register BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/148'
> 1451963659.210008: wlan0: BSS: Add new id 149 BSSID 00:1d:7e:ce:85:97
> SSID 'demonet'
> 1451963659.210031: dbus: Register BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/149'
> 1451963659.210178: wlan0: BSS: Add new id 150 BSSID f8:4f:57:13:f3:64
> SSID 'NoFrags'
> 1451963659.210201: dbus: Register BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/150'
> 1451963659.210355: wlan0: BSS: Add new id 151 BSSID 30:b5:c2:3e:70:be
> SSID 'surfsup'
> 1451963659.210377: dbus: Register BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/151'
> 1451963659.210477: WPS: Unknown Vendor Extension (Vendor ID 9442)
> 1451963659.210497: WPS: Unknown Vendor Extension (Vendor ID 9442)
> 1451963659.210607: wlan0: BSS: Add new id 152 BSSID 84:b8:02:22:98:80
> SSID 'EONCRNA'
> 1451963659.210629: dbus: Register BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/152'
> 1451963659.210804: wlan0: BSS: Add new id 153 BSSID 84:b8:02:22:98:81
> SSID 'EONCRNA-Guest'
> 1451963659.210828: dbus: Register BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/153'
> 1451963659.210982: wlan0: BSS: Add new id 154 BSSID 34:a8:4e:1c:b3:21
> SSID 'EONCRNA-Guest'
> 1451963659.211005: dbus: Register BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/154'
> 1451963659.211202: wlan0: BSS: Add new id 155 BSSID f8:4f:57:13:f3:6e
> SSID 'Mocana-GUEST'
> 1451963659.211226: dbus: Register BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/155'
> 1451963659.211556: wlan0: BSS: Add new id 156 BSSID 24:de:c6:79:d4:81
> SSID 'vlguest'
> 1451963659.211607: dbus: Register BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/156'
> 1451963659.211903: BSS: last_scan_res_used=31/64
> 1451963659.211956: wlan0: New scan results available (own=1 ext=0)
> 1451963659.212044: bgscan simple: scan result notification
> 1451963659.212087: WPS: Unknown Vendor Extension (Vendor ID 9442)
> 1451963659.212115: WPS: Unknown Vendor Extension (Vendor ID 9442)
> 1451963659.212141: WPS: AP[0] e4:f4:c6:14:7b:9d type=0 tries=0
> last_attempt=-1 sec ago blacklist=0
> 1451963659.212171: WPS: AP[1] 30:b5:c2:3e:70:be type=0 tries=0
> last_attempt=-1 sec ago blacklist=0
> 1451963659.212199: WPS: AP[2] 30:b5:c2:3e:70:bf type=0 tries=0
> last_attempt=-1 sec ago blacklist=0
> 1451963659.212225: WPS: AP[3] e4:f4:c6:14:7b:9e type=0 tries=0
> last_attempt=-1 sec ago blacklist=0
> 1451963659.212266: wlan0: Radio work 'scan'@0x555b677d8300 done in
> 1.606589 seconds
> 1451963659.212294: wlan0: Selecting BSS from priority group 0
> 1451963659.212335: wlan0: 0: 74:a0:2f:63:4f:ef ssid='ETSYguest'
> wpa_ie_len=0 rsn_ie_len=20 caps=0x1111 level=-66
> 1451963659.212365: wlan0: skip - SSID mismatch
> 1451963659.212406: wlan0: 1: 74:a0:2f:63:4f:ee ssid='CarrierPigeon'
> wpa_ie_len=0 rsn_ie_len=24 caps=0x1111 level=-66
> 1451963659.212434: wlan0: skip - SSID mismatch
> 1451963659.212473: wlan0: 2: 74:a0:2f:63:4f:ed ssid='MostlyHarmless'
> wpa_ie_len=0 rsn_ie_len=20 caps=0x1111 level=-67
> 1451963659.212500: wlan0: skip - SSID mismatch
> 1451963659.212538: wlan0: 3: 3c:0e:23:8e:48:3f ssid='Mocana-SECURE'
> wpa_ie_len=0 rsn_ie_len=20 caps=0x1011 level=-60
> 1451963659.212748: wlan0: selected based on RSN IE
> 1451963659.212923: wlan0: selected BSS 3c:0e:23:8e:48:3f
> ssid='Mocana-SECURE'
> 1451963659.213083: p2p-dev-wlan0: Updating scan results from sibling
> 1451963659.213563: nl80211: Received scan results (31 BSSes)
> 1451963659.213906: p2p-dev-wlan0: BSS: Start scan result update 18
> 1451963659.214135: p2p-dev-wlan0: BSS: Add new id 146 BSSID
> f8:4f:57:13:f3:6b SSID 'NoFrags'
> 1451963659.214262: p2p-dev-wlan0: BSS: Add new id 147 BSSID
> f8:4f:57:13:f3:6d SSID 'QA-testnet'
> 1451963659.214308: p2p-dev-wlan0: BSS: Add new id 148 BSSID
> f8:4f:57:13:f3:6c SSID 'key-testnet'
> 1451963659.214366: p2p-dev-wlan0: BSS: Add new id 149 BSSID
> 00:1d:7e:ce:85:97 SSID 'demonet'
> 1451963659.214405: p2p-dev-wlan0: BSS: Add new id 150 BSSID
> f8:4f:57:13:f3:64 SSID 'NoFrags'
> 1451963659.214439: p2p-dev-wlan0: BSS: Add new id 151 BSSID
> 30:b5:c2:3e:70:be SSID 'surfsup'
> 1451963659.214474: p2p-dev-wlan0: BSS: Add new id 152 BSSID
> 84:b8:02:22:98:80 SSID 'EONCRNA'
> 1451963659.214522: p2p-dev-wlan0: BSS: Add new id 153 BSSID
> 84:b8:02:22:98:81 SSID 'EONCRNA-Guest'
> 1451963659.214559: p2p-dev-wlan0: BSS: Add new id 154 BSSID
> 34:a8:4e:1c:b3:21 SSID 'EONCRNA-Guest'
> 1451963659.214617: p2p-dev-wlan0: BSS: Add new id 155 BSSID
> f8:4f:57:13:f3:6e SSID 'Mocana-GUEST'
> 1451963659.214658: p2p-dev-wlan0: BSS: Add new id 156 BSSID
> 24:de:c6:79:d4:81 SSID 'vlguest'
> 1451963659.214690: BSS: last_scan_res_used=31/64
> 1451963659.214727: p2p-dev-wlan0: New scan results available (own=0
> ext=0)
> 1451963659.214765: WPS: Unknown Vendor Extension (Vendor ID 9442)
> 1451963659.214795: WPS: Unknown Vendor Extension (Vendor ID 9442)
> 1451963659.214821: WPS: AP[0] 30:b5:c2:3e:70:be type=0 tries=0
> last_attempt=-1 sec ago blacklist=0
> 1451963659.214851: WPS: AP[1] 30:b5:c2:3e:70:bf type=0 tries=0
> last_attempt=-1 sec ago blacklist=0
> 1451963659.214878: WPS: AP[2] e4:f4:c6:14:7b:9d type=0 tries=0
> last_attempt=-1 sec ago blacklist=0
> 1451963659.214905: WPS: AP[3] e4:f4:c6:14:7b:9e type=0 tries=0
> last_attempt=-1 sec ago blacklist=0
> 1451963659.214963: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3
> 1451963659.215324: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/2
> 1451963659.215707: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/1
> 1451963659.215992: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/0
> 1451963659.216207: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/3
> 1451963659.216381: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/4
> 1451963659.216586: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/5
> 1451963659.216842: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/6
> 1451963659.217052: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/84
> 1451963659.217268: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/133
> 1451963659.217511: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/135
> 1451963659.217768: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/16
> 1451963659.217914: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/17
> 1451963659.218045: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/24
> 1451963659.218187: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/144
> 1451963659.218446: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/130
> 1451963659.218587: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/101
> 1451963659.218726: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/54
> 1451963659.218991: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/36
> 1451963659.219247: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/145
> 1451963659.219483: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3/BSSs/142
> 1451963659.252932: dbus: org.freedesktop.DBus.Properties.GetAll
> (/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/146) [s]
> 1451963659.253312: dbus: org.freedesktop.DBus.Properties.GetAll
> (/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/147) [s]
> 1451963659.253640: dbus: org.freedesktop.DBus.Properties.GetAll
> (/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/148) [s]
> 1451963659.253958: dbus: org.freedesktop.DBus.Properties.GetAll
> (/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/149) [s]
> 1451963659.258493: dbus: org.freedesktop.DBus.Properties.GetAll
> (/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/150) [s]
> 1451963659.258789: dbus: org.freedesktop.DBus.Properties.GetAll
> (/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/151) [s]
> 1451963659.258872: WPS: Unknown Vendor Extension (Vendor ID 9442)
> 1451963659.258886: WPS: Unknown Vendor Extension (Vendor ID 9442)
> 1451963659.259057: dbus: org.freedesktop.DBus.Properties.GetAll
> (/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/153) [s]
> 1451963659.259255: dbus: org.freedesktop.DBus.Properties.GetAll
> (/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/152) [s]
> 1451963659.259504: dbus: org.freedesktop.DBus.Properties.GetAll
> (/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/154) [s]
> 1451963659.259728: dbus: org.freedesktop.DBus.Properties.GetAll
> (/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/155) [s]
> 1451963659.269528: dbus: org.freedesktop.DBus.Properties.GetAll
> (/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/156) [s]
> 1451963720.274518: wlan0: BSS: Remove id 69 BSSID 24:de:c6:79:d4:90
> SSID 'vlcorp' due to wpa_bss_flush_by_age
> 1451963720.274581: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/69'
> 1451963720.274702: wlan0: BSS: Remove id 106 BSSID 24:de:c6:79:d4:92
> SSID 'vlmobile' due to wpa_bss_flush_by_age
> 1451963720.274739: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/106'
> 1451963720.274790: wlan0: BSS: Remove id 143 BSSID 84:18:3a:02:46:68
> SSID 'RS_20_7.1' due to wpa_bss_flush_by_age
> 1451963720.274811: dbus: Unregister BSS object
> '/fi/w1/wpa_supplicant1/Interfaces/3/BSSs/143'
> 1451963720.274868: p2p-dev-wlan0: BSS: Remove id 69 BSSID
> 24:de:c6:79:d4:90 SSID 'vlcorp' due to wpa_bss_flush_by_age
> 1451963720.274893: p2p-dev-wlan0: BSS: Remove id 106 BSSID
> 24:de:c6:79:d4:92 SSID 'vlmobile' due to wpa_bss_flush_by_age
> 1451963720.274912: p2p-dev-wlan0: BSS: Remove id 143 BSSID
> 84:18:3a:02:46:68 SSID 'RS_20_7.1' due to wpa_bss_flush_by_age
> 1451963720.279823: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3
> 1451963729.285604: l2_packet_receive: src=3c:0e:23:8e:48:3f len=57
> 1451963729.285691: wlan0: RX EAPOL from 3c:0e:23:8e:48:3f
> 1451963729.285710: RX EAPOL - hexdump(len=57): 02 00 00 35 01 01 00
> 35 01 00 6e 65 74 77 6f 72 6b 69 64 3d 4d 6f 63 61 6e 61 2d 53 45 43
> 55 52 45 2c 6e 61 73 69 64 3d 57 69 72 65 6c 65 73 73 2c 70 6f 72 74
> 69 64 3d 31
> 1451963729.285751: EAPOL: Received EAP-Packet frame
> 1451963729.285766: EAPOL: SUPP_PAE entering state RESTART
> 1451963729.285779: EAP: EAP entering state INITIALIZE
> 1451963729.285792: EAP: maintaining EAP method data for fast
> reauthentication
> 1451963729.285806: EAPOL: enable timer tick
> 1451963729.285824: EAP: EAP entering state IDLE
> 1451963729.285838: EAPOL: SUPP_PAE entering state AUTHENTICATING
> 1451963729.285852: EAPOL: SUPP_BE entering state REQUEST
> 1451963729.285866: EAPOL: getSuppRsp
> 1451963729.285880: EAP: EAP entering state RECEIVED
> 1451963729.285907: EAP: Received EAP-Request id=1 method=1 vendor=0
> vendorMethod=0
> 1451963729.285923: EAP: EAP entering state IDENTITY
> 1451963729.285939: wlan0: CTRL-EVENT-EAP-STARTED EAP authentication
> started
> 1451963729.285953: EAP: Status notification: started (param=)
> 1451963729.286060: EAP: EAP-Request Identity data -
> hexdump_ascii(len=48):
> 00 6e 65 74 77 6f 72 6b 69 64 3d 4d 6f 63 61 6e
> _networkid=Mocan
> 61 2d 53 45 43 55 52 45 2c 6e 61 73 69 64 3d 57 a
> -SECURE,nasid=W
> 69 72 65 6c 65 73 73 2c 70 6f 72 74 69 64 3d 31
> ireless,portid=1
> 1451963729.286185: EAP: using real identity - hexdump_ascii(len=7):
> 61 6a 61 63 6f 62 73 ajacobs
> 1451963729.286236: EAP: EAP entering state SEND_RESPONSE
> 1451963729.286259: EAP: EAP entering state IDLE
> 1451963729.286280: EAPOL: SUPP_BE entering state RESPONSE
> 1451963729.286300: EAPOL: txSuppRsp
> 1451963729.286320: TX EAPOL: dst=3c:0e:23:8e:48:3f
> 1451963729.286343: TX EAPOL - hexdump(len=16): 01 00 00 0c 02 01 00
> 0c 01 61 6a 61 63 6f 62 73
> 1451963729.286429: EAPOL: SUPP_BE entering state RECEIVE
> 1451963729.298687: l2_packet_receive: src=3c:0e:23:8e:48:3f len=10
> 1451963729.298755: wlan0: RX EAPOL from 3c:0e:23:8e:48:3f
> 1451963729.298773: RX EAPOL - hexdump(len=10): 02 00 00 06 01 02 00
> 06 19 20
> 1451963729.298797: EAPOL: Received EAP-Packet frame
> 1451963729.298810: EAPOL: SUPP_BE entering state REQUEST
> 1451963729.298823: EAPOL: getSuppRsp
> 1451963729.298837: EAP: EAP entering state RECEIVED
> 1451963729.298860: EAP: Received EAP-Request id=2 method=25 vendor=0
> vendorMethod=0
> 1451963729.298875: EAP: EAP entering state GET_METHOD
> 1451963729.298892: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0
> method=25
> 1451963729.298905: EAP: Status notification: accept proposed method
> (param=PEAP)
> 1451963729.299014: EAP: Using previous method data for fast re
> -authentication
> 1451963729.299036: EAP: Initialize selected EAP method: vendor 0
> method 25 (PEAP)
> 1451963729.299065: wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method
> 25 (PEAP) selected
> 1451963729.299089: EAP: EAP entering state METHOD
> 1451963729.299114: SSL: Received packet(len=6) - Flags 0x20
> 1451963729.299136: EAP-PEAP: Start (server ver=0, own ver=0)
> 1451963729.299156: EAP-PEAP: Using PEAP version 0
> 1451963729.299217: SSL: (where=0x10 ret=0x1)
> 1451963729.299474: SSL: (where=0x1001 ret=0x1)
> 1451963729.299505: SSL: SSL_connect:before/connect initialization
> 1451963729.299563: OpenSSL: TX ver=0x0 content_type=256
> 1451963729.299588: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.299614: OpenSSL: TX ver=0x301 content_type=22
> 1451963729.299635: OpenSSL: Message - hexdump(len=220): [REMOVED]
> 1451963729.299657: SSL: (where=0x1001 ret=0x1)
> 1451963729.299677: SSL: SSL_connect:unknown state
> 1451963729.299700: SSL: (where=0x1002 ret=0xffffffff)
> 1451963729.299720: SSL: SSL_connect:error in unknown state
> 1451963729.299745: SSL: SSL_connect - want more data
> 1451963729.299766: SSL: 225 bytes pending from ssl_out
> 1451963729.299790: SSL: 225 bytes left to be sent out (of total 225
> bytes)
> 1451963729.299816: EAP: method process -> ignore=FALSE
> methodState=MAY_CONT decision=FAIL eapRespData=0x555b677d8300
> 1451963729.299844: EAP: EAP entering state SEND_RESPONSE
> 1451963729.299866: EAP: EAP entering state IDLE
> 1451963729.299889: EAPOL: SUPP_BE entering state RESPONSE
> 1451963729.299910: EAPOL: txSuppRsp
> 1451963729.299931: TX EAPOL: dst=3c:0e:23:8e:48:3f
> 1451963729.299955: TX EAPOL - hexdump(len=239): 01 00 00 eb 02 02 00
> eb 19 80 00 00 00 e1 16 03 01 00 dc 01 00 00 d8 03 01 db 8e 3c 7b a9
> bd ca 13 d4 da a3 fe 43 c2 2d cf a1 77 d1 cd 10 5f 69 9e 2a ba 00 ba
> 55 c8 65 d5 20 1f 48 00 00 c8 d4 6a ba 00 99 d0 0a 30 3d ea 8c 3a 69
> c8 1e 66 54 98 7e ce 77 c3 25 ae c3 af 43 00 62 c0 14 c0 0a 00 39 00
> 38 00 37 00 36 00 88 00 87 00 86 00 85 c0 0f c0 05 00 35 00 84 c0 13
> c0 09 00 33 00 32 00 31 00 30 00 9a 00 99 00 98 00 97 00 45 00 44 00
> 43 00 42 c0 0e c0 04 00 2f 00 96 00 41 c0 11 c0 07 c0 0c c0 02 00 05
> 00 04 c0 12 c0 08 00 16 00 13 00 10 00 0d c0 0d c0 03 00 0a 00 ff 01
> 00 00 2d 00 0b 00 04 03 00 01 02 00 0a 00 1c 00 1a 00 17 00 19 00 1c
> 00 1b 00 18 00 1a 00 16 00 0e 00 0d 00 0b 00 0c 00 09 00 0a 00 0f 00
> 01 01
> 1451963729.300207: EAPOL: SUPP_BE entering state RECEIVE
> 1451963729.310898: l2_packet_receive: src=3c:0e:23:8e:48:3f len=159
> 1451963729.310987: wlan0: RX EAPOL from 3c:0e:23:8e:48:3f
> 1451963729.311007: RX EAPOL - hexdump(len=159): 02 00 00 9b 01 03 00
> 9b 19 80 00 00 00 91 16 03 01 00 51 02 00 00 4d 03 01 56 8b 35 51 79
> fb 1d 00 17 77 6b de f6 0a c0 1f 47 1c 66 81 8b 93 ce e6 a9 d3 be 76
> fb f6 c5 bd 20 1f 48 00 00 c8 d4 6a ba 00 99 d0 0a 30 3d ea 8c 3a 69
> c8 1e 66 54 98 7e ce 77 c3 25 ae c3 af 43 c0 14 00 00 05 ff 01 00 01
> 00 14 03 01 00 01 01 16 03 01 00 30 61 18 9d a5 c8 e2 5d c0 95 fe 04
> 73 ac 89 c0 10 55 93 59 5b f1 96 58 b1 8d ab 09 c5 d5 d7 85 7b 4c 32
> 58 38 ed 9a eb da 7f 8f 48 22 a6 86 02 fc
> 1451963729.311089: EAPOL: Received EAP-Packet frame
> 1451963729.311104: EAPOL: SUPP_BE entering state REQUEST
> 1451963729.311119: EAPOL: getSuppRsp
> 1451963729.311134: EAP: EAP entering state RECEIVED
> 1451963729.311158: EAP: Received EAP-Request id=3 method=25 vendor=0
> vendorMethod=0
> 1451963729.311174: EAP: EAP entering state METHOD
> 1451963729.311195: SSL: Received packet(len=155) - Flags 0x80
> 1451963729.311209: SSL: TLS Message Length: 145
> 1451963729.311240: OpenSSL: RX ver=0x0 content_type=256
> 1451963729.311275: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.311299: OpenSSL: RX ver=0x301 content_type=22
> 1451963729.311353: OpenSSL: Message - hexdump(len=81): [REMOVED]
> 1451963729.311387: SSL: (where=0x1001 ret=0x1)
> 1451963729.311411: SSL: SSL_connect:unknown state
> 1451963729.311425: OpenSSL: RX ver=0x0 content_type=256
> 1451963729.311438: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.311451: OpenSSL: RX ver=0x301 content_type=20
> 1451963729.311464: OpenSSL: Message - hexdump(len=1): [REMOVED]
> 1451963729.311709: OpenSSL: RX ver=0x0 content_type=256
> 1451963729.311726: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.311776: OpenSSL: RX ver=0x301 content_type=22
> 1451963729.311789: OpenSSL: Message - hexdump(len=16): [REMOVED]
> 1451963729.311801: SSL: (where=0x1001 ret=0x1)
> 1451963729.311813: SSL: SSL_connect:unknown state
> 1451963729.311826: OpenSSL: TX ver=0x0 content_type=256
> 1451963729.311838: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.311852: OpenSSL: TX ver=0x301 content_type=20
> 1451963729.311863: OpenSSL: Message - hexdump(len=1): [REMOVED]
> 1451963729.311879: SSL: (where=0x1001 ret=0x1)
> 1451963729.311890: SSL: SSL_connect:unknown state
> 1451963729.311937: OpenSSL: TX ver=0x0 content_type=256
> 1451963729.311949: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.311962: OpenSSL: TX ver=0x301 content_type=22
> 1451963729.311973: OpenSSL: Message - hexdump(len=16): [REMOVED]
> 1451963729.311984: SSL: (where=0x1001 ret=0x1)
> 1451963729.311995: SSL: SSL_connect:unknown state
> 1451963729.312007: SSL: (where=0x1001 ret=0x1)
> 1451963729.312018: SSL: SSL_connect:unknown state
> 1451963729.312040: SSL: (where=0x20 ret=0x1)
> 1451963729.312052: SSL: (where=0x1002 ret=0x1)
> 1451963729.312064: SSL: 59 bytes pending from ssl_out
> 1451963729.312081: SSL: No Application Data included
> 1451963729.312093: SSL: 59 bytes left to be sent out (of total 59
> bytes)
> 1451963729.312107: EAP-PEAP: TLS done, proceed to Phase 2
> 1451963729.312118: EAP-PEAP: using label 'client EAP encryption' in
> key derivation
> 1451963729.312227: OpenSSL: Using internal PRF
> 1451963729.312239: EAP-PEAP: Derived key - hexdump(len=64): [REMOVED]
> 1451963729.312252: EAP-PEAP: Derived Session-Id - hexdump(len=65): 19
> db 8e 3c 7b a9 bd ca 13 d4 da a3 fe 43 c2 2d cf a1 77 d1 cd 10 5f 69
> 9e 2a ba 00 ba 55 c8 65 d5 56 8b 35 51 79 fb 1d 00 17 77 6b de f6 0a
> c0 1f 47 1c 66 81 8b 93 ce e6 a9 d3 be 76 fb f6 c5 bd
> 1451963729.312286: EAP-PEAP: Workaround - allow outer EAP-Success to
> terminate PEAP resumption
> 1451963729.312298: EAP: method process -> ignore=FALSE
> methodState=MAY_CONT decision=COND_SUCC eapRespData=0x555b677937b0
> 1451963729.312314: EAP: Session-Id - hexdump(len=65): 19 db 8e 3c 7b
> a9 bd ca 13 d4 da a3 fe 43 c2 2d cf a1 77 d1 cd 10 5f 69 9e 2a ba 00
> ba 55 c8 65 d5 56 8b 35 51 79 fb 1d 00 17 77 6b de f6 0a c0 1f 47 1c
> 66 81 8b 93 ce e6 a9 d3 be 76 fb f6 c5 bd
> 1451963729.312346: EAP: EAP entering state SEND_RESPONSE
> 1451963729.312358: EAP: EAP entering state IDLE
> 1451963729.312370: EAPOL: SUPP_BE entering state RESPONSE
> 1451963729.312381: EAPOL: txSuppRsp
> 1451963729.312394: TX EAPOL: dst=3c:0e:23:8e:48:3f
> 1451963729.312407: TX EAPOL - hexdump(len=69): 01 00 00 41 02 03 00
> 41 19 00 14 03 01 00 01 01 16 03 01 00 30 f9 64 5b 0c c2 ab 90 ea a0
> b9 16 4a 37 6d f8 e2 a1 dc b9 99 e9 37 1f 57 0c 67 d6 01 d8 ed 82 bc
> 07 bd 60 e1 5f 7a 47 38 f8 83 ac 9d 6d 78 34 c1
> 1451963729.312483: EAPOL: SUPP_BE entering state RECEIVE
> 1451963729.319731: l2_packet_receive: src=3c:0e:23:8e:48:3f len=47
> 1451963729.319795: wlan0: RX EAPOL from 3c:0e:23:8e:48:3f
> 1451963729.319816: RX EAPOL - hexdump(len=47): 02 00 00 2b 01 05 00
> 2b 19 00 17 03 01 00 20 b5 d2 47 17 de b2 ad 91 4e 02 55 3b 4d 07 7a
> 32 b2 8a 1b ab 9f d2 2b 16 57 fd 7c 7e d4 44 98 5a
> 1451963729.319862: EAPOL: Received EAP-Packet frame
> 1451963729.319880: EAPOL: SUPP_BE entering state REQUEST
> 1451963729.319896: EAPOL: getSuppRsp
> 1451963729.319912: EAP: EAP entering state RECEIVED
> 1451963729.319935: EAP: Received EAP-Request id=5 method=25 vendor=0
> vendorMethod=0
> 1451963729.319955: EAP: EAP entering state METHOD
> 1451963729.319977: SSL: Received packet(len=43) - Flags 0x00
> 1451963729.320022: EAP-PEAP: received 37 bytes encrypted data for
> Phase 2
> 1451963729.320058: OpenSSL: RX ver=0x0 content_type=256
> 1451963729.320081: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.320104: EAP-PEAP: Decrypted Phase 2 EAP - hexdump(len=1):
> 01
> 1451963729.320119: EAP-PEAP: received Phase 2: code=1 identifier=5
> length=5
> 1451963729.320133: EAP-PEAP: Phase 2 Request: type=1
> 1451963729.320146: EAP: using real identity - hexdump_ascii(len=7):
> 61 6a 61 63 6f 62 73 ajacobs
> 1451963729.320186: EAP-PEAP: Encrypting Phase 2 data -
> hexdump(len=12): [REMOVED]
> 1451963729.320213: OpenSSL: TX ver=0x0 content_type=256
> 1451963729.320232: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.320252: OpenSSL: TX ver=0x0 content_type=256
> 1451963729.320271: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.320292: SSL: 74 bytes left to be sent out (of total 74
> bytes)
> 1451963729.320313: EAP: method process -> ignore=FALSE
> methodState=MAY_CONT decision=FAIL eapRespData=0x555b677acd90
> 1451963729.320337: EAP: Session-Id - hexdump(len=65): 19 db 8e 3c 7b
> a9 bd ca 13 d4 da a3 fe 43 c2 2d cf a1 77 d1 cd 10 5f 69 9e 2a ba 00
> ba 55 c8 65 d5 56 8b 35 51 79 fb 1d 00 17 77 6b de f6 0a c0 1f 47 1c
> 66 81 8b 93 ce e6 a9 d3 be 76 fb f6 c5 bd
> 1451963729.320396: EAP: EAP entering state SEND_RESPONSE
> 1451963729.320414: EAP: EAP entering state IDLE
> 1451963729.320432: EAPOL: SUPP_BE entering state RESPONSE
> 1451963729.320452: EAPOL: txSuppRsp
> 1451963729.320469: TX EAPOL: dst=3c:0e:23:8e:48:3f
> 1451963729.320487: TX EAPOL - hexdump(len=84): 01 00 00 50 02 05 00
> 50 19 00 17 03 01 00 20 cd 33 91 31 e1 01 15 e1 eb 0b f6 8b f0 63 71
> 1b 2a 29 22 24 20 18 4b 9b a2 52 c5 c3 7e 53 15 e6 17 03 01 00 20 b5
> fc 76 b6 b9 72 50 91 c5 72 25 fb a5 09 3a 41 bb 79 18 c6 e5 21 b3 75
> a2 18 e3 2b 54 5f 78 13
> 1451963729.320590: EAPOL: SUPP_BE entering state RECEIVE
> 1451963729.328439: l2_packet_receive: src=3c:0e:23:8e:48:3f len=63
> 1451963729.328518: wlan0: RX EAPOL from 3c:0e:23:8e:48:3f
> 1451963729.328534: RX EAPOL - hexdump(len=63): 02 00 00 3b 01 06 00
> 3b 19 00 17 03 01 00 30 05 ba 86 0e 5b a7 5a 27 1d f9 b2 05 ee 77 06
> 84 46 ab 6a db 5a f8 10 30 f3 a1 1f ee 3f ee fa f7 39 40 0c d2 2d 2a
> b7 dc a4 8e b4 ae fc 79 17 96
> 1451963729.328573: EAPOL: Received EAP-Packet frame
> 1451963729.328586: EAPOL: SUPP_BE entering state REQUEST
> 1451963729.328598: EAPOL: getSuppRsp
> 1451963729.328612: EAP: EAP entering state RECEIVED
> 1451963729.328633: EAP: Received EAP-Request id=6 method=25 vendor=0
> vendorMethod=0
> 1451963729.328648: EAP: EAP entering state METHOD
> 1451963729.328664: SSL: Received packet(len=59) - Flags 0x00
> 1451963729.328678: EAP-PEAP: received 53 bytes encrypted data for
> Phase 2
> 1451963729.328704: OpenSSL: RX ver=0x0 content_type=256
> 1451963729.328739: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.328765: EAP-PEAP: Decrypted Phase 2 EAP - hexdump(len=16):
> 01 06 00 10 fe 00 01 37 00 00 00 22 00 00 00 01
> 1451963729.328794: EAP-PEAP: received Phase 2: code=1 identifier=6
> length=20
> 1451963729.328808: EAP-PEAP: Phase 2 Request: type=1
> 1451963729.328820: EAP: using real identity - hexdump_ascii(len=7):
> 61 6a 61 63 6f 62 73 ajacobs
> 1451963729.328851: EAP-PEAP: Encrypting Phase 2 data -
> hexdump(len=12): [REMOVED]
> 1451963729.328871: OpenSSL: TX ver=0x0 content_type=256
> 1451963729.328884: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.328899: OpenSSL: TX ver=0x0 content_type=256
> 1451963729.328911: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.328926: SSL: 74 bytes left to be sent out (of total 74
> bytes)
> 1451963729.328942: EAP: method process -> ignore=FALSE
> methodState=MAY_CONT decision=FAIL eapRespData=0x555b677acd90
> 1451963729.328958: EAP: Session-Id - hexdump(len=65): 19 db 8e 3c 7b
> a9 bd ca 13 d4 da a3 fe 43 c2 2d cf a1 77 d1 cd 10 5f 69 9e 2a ba 00
> ba 55 c8 65 d5 56 8b 35 51 79 fb 1d 00 17 77 6b de f6 0a c0 1f 47 1c
> 66 81 8b 93 ce e6 a9 d3 be 76 fb f6 c5 bd
> 1451963729.328996: EAP: EAP entering state SEND_RESPONSE
> 1451963729.329009: EAP: EAP entering state IDLE
> 1451963729.329022: EAPOL: SUPP_BE entering state RESPONSE
> 1451963729.329033: EAPOL: txSuppRsp
> 1451963729.329046: TX EAPOL: dst=3c:0e:23:8e:48:3f
> 1451963729.329059: TX EAPOL - hexdump(len=84): 01 00 00 50 02 06 00
> 50 19 00 17 03 01 00 20 75 83 4b 53 bd 61 9b b8 f5 65 8d 7f fb de cd
> 3d fa 00 41 7f 46 6e 8e 2a ac 5f 76 a2 44 21 28 bc 17 03 01 00 20 92
> 8f cb 83 6d 76 ea 66 52 0b 73 a7 a2 c6 ac 58 de 3c 75 33 cf a1 82 e2
> 9f 0d 82 04 f3 f8 14 08
> 1451963729.329147: EAPOL: SUPP_BE entering state RECEIVE
> 1451963729.336516: l2_packet_receive: src=3c:0e:23:8e:48:3f len=79
> 1451963729.336594: wlan0: RX EAPOL from 3c:0e:23:8e:48:3f
> 1451963729.336611: RX EAPOL - hexdump(len=79): 02 00 00 4b 01 07 00
> 4b 19 00 17 03 01 00 40 91 06 2d 02 8d c9 30 0f c5 3b e9 8a c0 d6 f9
> 3c c7 07 52 df 7e 3e be 1f d4 e9 ef 2d 39 c6 fb 60 75 41 4b da 2c d8
> 5b 9b bd 5a 7f 3e f8 9b e2 fc f0 dc 13 8f 5a ee c5 32 b6 ab f6 46 11
> 8c f9 f0
> 1451963729.336656: EAPOL: Received EAP-Packet frame
> 1451963729.336669: EAPOL: SUPP_BE entering state REQUEST
> 1451963729.336680: EAPOL: getSuppRsp
> 1451963729.336694: EAP: EAP entering state RECEIVED
> 1451963729.336714: EAP: Received EAP-Request id=7 method=25 vendor=0
> vendorMethod=0
> 1451963729.336729: EAP: EAP entering state METHOD
> 1451963729.336746: SSL: Received packet(len=75) - Flags 0x00
> 1451963729.336761: EAP-PEAP: received 69 bytes encrypted data for
> Phase 2
> 1451963729.336786: OpenSSL: RX ver=0x0 content_type=256
> 1451963729.336820: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.336845: EAP-PEAP: Decrypted Phase 2 EAP - hexdump(len=31):
> 1a 01 07 00 1e 10 08 e6 ff ea ab fa ef 05 f4 e0 44 c8 56 5c 8d 6d 52
> 41 44 49 55 53 2d 30 31
> 1451963729.336875: EAP-PEAP: received Phase 2: code=1 identifier=7
> length=35
> 1451963729.336889: EAP-PEAP: Phase 2 Request: type=26
> 1451963729.336902: EAP-MSCHAPV2: RX identifier 7 mschapv2_id 7
> 1451963729.336917: EAP-MSCHAPV2: Received challenge
> 1451963729.336928: EAP-MSCHAPV2: Authentication Servername -
> hexdump_ascii(len=9):
> 52 41 44 49 55 53 2d 30 31 RADIUS-01
> 1451963729.336958: EAP-MSCHAPV2: Generating Challenge Response
> 1451963729.336971: Get randomness: len=16 entropy=340
> 1451963729.338033: MSCHAPV2: Identity - hexdump_ascii(len=7):
> 61 6a 61 63 6f 62 73 ajacobs
> 1451963729.338073: MSCHAPV2: Username - hexdump_ascii(len=7):
> 61 6a 61 63 6f 62 73 ajacobs
> 1451963729.338100: MSCHAPV2: auth_challenge - hexdump(len=16): 08 e6
> ff ea ab fa ef 05 f4 e0 44 c8 56 5c 8d 6d
> 1451963729.338118: MSCHAPV2: peer_challenge - hexdump(len=16): 9f a2
> ac c1 04 a0 36 6b fd 49 42 dd ea c7 93 fe
> 1451963729.338135: MSCHAPV2: username - hexdump_ascii(len=7):
> 61 6a 61 63 6f 62 73 ajacobs
> 1451963729.338162: MSCHAPV2: password - hexdump_ascii(len=12):
> [REMOVED]
> 1451963729.338193: MSCHAPV2: NT Response - hexdump(len=24): 4e 48 06
> ec d8 1c ee 1a 47 1c a6 34 1c d6 79 ee f4 49 06 68 57 eb ab 76
> 1451963729.338219: MSCHAPV2: Auth Response - hexdump(len=20): a4 fc
> cb e6 86 12 e4 ff 4f 89 4a 39 58 83 42 6e 13 a9 e1 e9
> 1451963729.338240: MSCHAPV2: Master Key - hexdump(len=16): [REMOVED]
> 1451963729.338253: EAP-MSCHAPV2: TX identifier 7 mschapv2_id 7
> (response)
> 1451963729.338267: EAP-PEAP: Encrypting Phase 2 data -
> hexdump(len=66): [REMOVED]
> 1451963729.338286: OpenSSL: TX ver=0x0 content_type=256
> 1451963729.338300: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.338315: OpenSSL: TX ver=0x0 content_type=256
> 1451963729.338327: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.338342: SSL: 138 bytes left to be sent out (of total 138
> bytes)
> 1451963729.338358: EAP: method process -> ignore=FALSE
> methodState=MAY_CONT decision=FAIL eapRespData=0x555b677b4420
> 1451963729.338374: EAP: Session-Id - hexdump(len=65): 19 db 8e 3c 7b
> a9 bd ca 13 d4 da a3 fe 43 c2 2d cf a1 77 d1 cd 10 5f 69 9e 2a ba 00
> ba 55 c8 65 d5 56 8b 35 51 79 fb 1d 00 17 77 6b de f6 0a c0 1f 47 1c
> 66 81 8b 93 ce e6 a9 d3 be 76 fb f6 c5 bd
> 1451963729.338412: EAP: EAP entering state SEND_RESPONSE
> 1451963729.338424: EAP: EAP entering state IDLE
> 1451963729.338437: EAPOL: SUPP_BE entering state RESPONSE
> 1451963729.338449: EAPOL: txSuppRsp
> 1451963729.338461: TX EAPOL: dst=3c:0e:23:8e:48:3f
> 1451963729.338475: TX EAPOL - hexdump(len=148): 01 00 00 90 02 07 00
> 90 19 00 17 03 01 00 20 11 87 2f 26 02 4e 92 93 40 56 ac ad e6 a5 47
> cc 8b a2 7d 13 69 5d 09 7f 47 41 66 2b a7 43 ef 20 17 03 01 00 60 3a
> 1a 92 13 aa fd 40 a6 b3 a4 7b 67 3e bb ca 6b 61 a3 a5 e3 3c 40 aa 73
> b5 b2 a1 7b 97 c2 d9 85 20 4f 31 cc 9f a3 72 03 00 b7 63 79 42 7e c9
> fa 67 3b 93 0b ae 0d 6c f3 c3 d0 32 0b e5 fe 00 10 3f f5 0d 73 b5 c3
> f0 6a 3a ad 31 a8 97 42 9c 50 b0 66 27 a0 e3 0f 5c df 12 01 c1 5a b9
> ab f2 8e
> 1451963729.338579: EAPOL: SUPP_BE entering state RECEIVE
> 1451963729.349263: l2_packet_receive: src=3c:0e:23:8e:48:3f len=95
> 1451963729.349315: wlan0: RX EAPOL from 3c:0e:23:8e:48:3f
> 1451963729.349328: RX EAPOL - hexdump(len=95): 02 00 00 5b 01 08 00
> 5b 19 00 17 03 01 00 50 9c 3c 73 86 ec 4c a6 c7 42 13 24 7d 35 7f dd
> 15 83 ae 4f 88 c0 ae e6 d5 d9 67 8a b0 d6 6b 50 94 f2 33 d7 21 e0 b5
> 95 e7 93 b4 bf ef 6a 78 56 b6 c9 63 d1 49 2c a7 a1 83 29 51 f1 b7 46
> ba 1d e7 1e 8f 46 11 35 d2 97 25 19 81 08 4d 77 4d dc 3e
> 1451963729.349367: EAPOL: Received EAP-Packet frame
> 1451963729.349378: EAPOL: SUPP_BE entering state REQUEST
> 1451963729.349387: EAPOL: getSuppRsp
> 1451963729.349397: EAP: EAP entering state RECEIVED
> 1451963729.349414: EAP: Received EAP-Request id=8 method=25 vendor=0
> vendorMethod=0
> 1451963729.349425: EAP: EAP entering state METHOD
> 1451963729.349438: SSL: Received packet(len=91) - Flags 0x00
> 1451963729.349449: EAP-PEAP: received 85 bytes encrypted data for
> Phase 2
> 1451963729.349471: OpenSSL: RX ver=0x0 content_type=256
> 1451963729.349482: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.349502: EAP-PEAP: Decrypted Phase 2 EAP - hexdump(len=47):
> 1a 03 07 00 2e 53 3d 41 34 46 43 43 42 45 36 38 36 31 32 45 34 46 46
> 34 46 38 39 34 41 33 39 35 38 38 33 34 32 36 45 31 33 41 39 45 31 45
> 39
> 1451963729.349526: EAP-PEAP: received Phase 2: code=1 identifier=8
> length=51
> 1451963729.349536: EAP-PEAP: Phase 2 Request: type=26
> 1451963729.349546: EAP-MSCHAPV2: RX identifier 8 mschapv2_id 7
> 1451963729.349556: EAP-MSCHAPV2: Received success
> 1451963729.349566: EAP-MSCHAPV2: Success message -
> hexdump_ascii(len=0):
> 1451963729.349576: EAP-MSCHAPV2: Authentication succeeded
> 1451963729.349586: EAP-PEAP: Encrypting Phase 2 data -
> hexdump(len=6): [REMOVED]
> 1451963729.349600: OpenSSL: TX ver=0x0 content_type=256
> 1451963729.349609: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.349620: OpenSSL: TX ver=0x0 content_type=256
> 1451963729.349629: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.349640: SSL: 74 bytes left to be sent out (of total 74
> bytes)
> 1451963729.349650: EAP: method process -> ignore=FALSE
> methodState=MAY_CONT decision=FAIL eapRespData=0x555b677acd90
> 1451963729.349663: EAP: Session-Id - hexdump(len=65): 19 db 8e 3c 7b
> a9 bd ca 13 d4 da a3 fe 43 c2 2d cf a1 77 d1 cd 10 5f 69 9e 2a ba 00
> ba 55 c8 65 d5 56 8b 35 51 79 fb 1d 00 17 77 6b de f6 0a c0 1f 47 1c
> 66 81 8b 93 ce e6 a9 d3 be 76 fb f6 c5 bd
> 1451963729.349690: EAP: EAP entering state SEND_RESPONSE
> 1451963729.349700: EAP: EAP entering state IDLE
> 1451963729.349710: EAPOL: SUPP_BE entering state RESPONSE
> 1451963729.349719: EAPOL: txSuppRsp
> 1451963729.349728: TX EAPOL: dst=3c:0e:23:8e:48:3f
> 1451963729.349738: TX EAPOL - hexdump(len=84): 01 00 00 50 02 08 00
> 50 19 00 17 03 01 00 20 26 48 e1 ed dd 9d cd fd 25 5f 9a 14 32 bd b2
> f7 95 e7 d5 94 e0 cb 16 c6 ca 11 d0 a9 94 41 ad 80 17 03 01 00 20 18
> 09 f9 67 97 ff d7 de 3a 98 2b bf 54 e4 dd fb 94 a1 5f bd f4 c9 6d f5
> 44 cc ae 15 f7 76 58 18
> 1451963729.349806: EAPOL: SUPP_BE entering state RECEIVE
> 1451963729.357577: l2_packet_receive: src=3c:0e:23:8e:48:3f len=111
> 1451963729.357677: wlan0: RX EAPOL from 3c:0e:23:8e:48:3f
> 1451963729.357700: RX EAPOL - hexdump(len=111): 02 00 00 6b 01 0a 00
> 6b 19 00 17 03 01 00 60 b3 f5 a1 6d 73 91 4f f7 46 85 59 71 fd e9 5a
> f4 dd 00 02 4c 71 da 8d 18 2b 0a ec 18 7e 99 09 2f 1e 36 b3 56 17 b9
> f2 da 8a a2 ac 72 f1 aa 40 de 89 18 1e e0 68 42 c3 ee d0 21 c1 ef 1e
> 13 47 45 e7 43 80 61 e2 4b ff b5 55 81 ba 58 15 a9 25 10 e4 d3 b7 4e
> 39 0f 2e 53 a9 63 b6 d9 02 a0 5b a7
> 1451963729.357790: EAPOL: Received EAP-Packet frame
> 1451963729.357809: EAPOL: SUPP_BE entering state REQUEST
> 1451963729.357825: EAPOL: getSuppRsp
> 1451963729.357843: EAP: EAP entering state RECEIVED
> 1451963729.357876: EAP: Received EAP-Request id=10 method=25 vendor=0
> vendorMethod=0
> 1451963729.357916: EAP: EAP entering state METHOD
> 1451963729.357942: SSL: Received packet(len=107) - Flags 0x00
> 1451963729.357968: EAP-PEAP: received 101 bytes encrypted data for
> Phase 2
> 1451963729.358006: OpenSSL: RX ver=0x0 content_type=256
> 1451963729.358028: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.358071: EAP-PEAP: Decrypted Phase 2 EAP - hexdump(len=71):
> 01 0a 00 47 21 80 03 00 02 00 01 00 0c 00 38 00 00 00 00 a8 c8 90 39
> 15 20 a4 c6 90 9d 62 2c 02 e6 84 85 d9 04 4c 44 76 40 f5 00 03 0c 4f
> de cd aa 5a 36 c2 57 d5 64 8d d3 a6 08 bc de 5e ab bc e4 20 22 55 57
> 76 6f
> 1451963729.358139: EAP-PEAP: received Phase 2: code=1 identifier=10
> length=71
> 1451963729.358158: EAP-PEAP: Phase 2 Request: type=33
> 1451963729.358173: EAP-TLV: Received TLVs - hexdump(len=66): 80 03 00
> 02 00 01 00 0c 00 38 00 00 00 00 a8 c8 90 39 15 20 a4 c6 90 9d 62 2c
> 02 e6 84 85 d9 04 4c 44 76 40 f5 00 03 0c 4f de cd aa 5a 36 c2 57 d5
> 64 8d d3 a6 08 bc de 5e ab bc e4 20 22 55 57 76 6f
> 1451963729.358222: EAP-PEAP: Cryptobinding TLV - hexdump(len=56): 00
> 00 00 00 a8 c8 90 39 15 20 a4 c6 90 9d 62 2c 02 e6 84 85 d9 04 4c 44
> 76 40 f5 00 03 0c 4f de cd aa 5a 36 c2 57 d5 64 8d d3 a6 08 bc de 5e
> ab bc e4 20 22 55 57 76 6f
> 1451963729.358281: EAP-PEAP: TK - hexdump(len=60): [REMOVED]
> 1451963729.358296: EAP-PEAP: IPMK from TK - hexdump(len=40):
> [REMOVED]
> 1451963729.358313: EAP-PEAP: CMK from TK - hexdump(len=20): [REMOVED]
> 1451963729.358345: EAP-PEAP: Compound_MAC data - hexdump(len=61): 00
> 0c 00 38 00 00 00 00 a8 c8 90 39 15 20 a4 c6 90 9d 62 2c 02 e6 84 85
> d9 04 4c 44 76 40 f5 00 03 0c 4f de cd aa 5a 36 00 00 00 00 00 00 00
> 00 00 00 00 00 00 00 00 00 00 00 00 00 19
> 1451963729.358417: EAP-PEAP: Invalid Compound_MAC in cryptobinding
> TLV
> 1451963729.358431: EAP-PEAP: Received MAC - hexdump(len=20): c2 57 d5
> 64 8d d3 a6 08 bc de 5e ab bc e4 20 22 55 57 76 6f
> 1451963729.358448: EAP-PEAP: Expected MAC - hexdump(len=20): c9 26 98
> 4a 2b 87 4c 54 b0 f8 28 81 75 cc 3d 3c 46 2d 61 e9
> 1451963729.358464: EAP-TLV: Result TLV - hexdump(len=2): 00 01
> 1451963729.358475: EAP-TLV: TLV Result - Success - EAP-TLV/Phase2
> Completed
> 1451963729.358488: EAP-TLV: Earlier failure - force failed Phase 2
> 1451963729.358504: EAP-PEAP: Encrypting Phase 2 data -
> hexdump(len=11): [REMOVED]
> 1451963729.358533: OpenSSL: TX ver=0x0 content_type=256
> 1451963729.358547: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.358562: OpenSSL: TX ver=0x0 content_type=256
> 1451963729.358572: OpenSSL: Message - hexdump(len=5): [REMOVED]
> 1451963729.358587: SSL: 74 bytes left to be sent out (of total 74
> bytes)
> 1451963729.358602: EAP: method process -> ignore=FALSE
> methodState=DONE decision=FAIL eapRespData=0x555b677acd90
> 1451963729.358622: EAP: Session-Id - hexdump(len=65): 19 db 8e 3c 7b
> a9 bd ca 13 d4 da a3 fe 43 c2 2d cf a1 77 d1 cd 10 5f 69 9e 2a ba 00
> ba 55 c8 65 d5 56 8b 35 51 79 fb 1d 00 17 77 6b de f6 0a c0 1f 47 1c
> 66 81 8b 93 ce e6 a9 d3 be 76 fb f6 c5 bd
> 1451963729.358659: EAP: EAP entering state SEND_RESPONSE
> 1451963729.358672: EAP: EAP entering state IDLE
> 1451963729.358685: EAPOL: SUPP_BE entering state RESPONSE
> 1451963729.358696: EAPOL: txSuppRsp
> 1451963729.358710: TX EAPOL: dst=3c:0e:23:8e:48:3f
> 1451963729.358721: TX EAPOL - hexdump(len=84): 01 00 00 50 02 0a 00
> 50 19 00 17 03 01 00 20 b9 80 43 b3 2e 10 f0 6e cc 1b e0 22 01 d1 01
> 19 ce 73 e4 40 0b f5 ce cb b5 92 ae be 2c c4 02 91 17 03 01 00 20 76
> 5a a4 de 29 20 e9 df ad 47 a3 30 4a 20 24 f7 2e 2c 74 bf 3f cc 56 17
> ba 20 45 f2 30 a4 55 c3
> 1451963729.358832: EAPOL: SUPP_BE entering state RECEIVE
> 1451963729.366083: l2_packet_receive: src=3c:0e:23:8e:48:3f len=8
> 1451963729.366123: wlan0: RX EAPOL from 3c:0e:23:8e:48:3f
> 1451963729.366134: RX EAPOL - hexdump(len=8): 02 00 00 04 04 0a 00 04
> 1451963729.366149: EAPOL: Received EAP-Packet frame
> 1451963729.366159: EAPOL: SUPP_BE entering state REQUEST
> 1451963729.366167: EAPOL: getSuppRsp
> 1451963729.366176: EAP: EAP entering state RECEIVED
> 1451963729.366190: EAP: Received EAP-Failure
> 1451963729.366199: EAP: Status notification: completion
> (param=failure)
> 1451963729.366270: EAP: EAP entering state FAILURE
> 1451963729.366291: wlan0: CTRL-EVENT-EAP-FAILURE EAP authentication
> failed
> 1451963729.366304: EAPOL: SUPP_PAE entering state HELD
> 1451963729.366319: EAPOL: Supplicant port status: Unauthorized
> 1451963729.366334: nl80211: Set supplicant port unauthorized for
> 3c:0e:23:8e:48:3f
> 1451963729.366546: EAPOL: SUPP_BE entering state RECEIVE
> 1451963729.366573: EAPOL: SUPP_BE entering state FAIL
> 1451963729.366586: EAPOL: SUPP_BE entering state IDLE
> 1451963729.366600: EAPOL authentication completed - result=FAILURE
> 1451963729.366621: wlan0: Setting authentication timeout: 2 sec 0
> usec
> 1451963731.366835: wlan0: Authentication with 3c:0e:23:8e:48:3f timed
> out.
> 1451963731.366868: Added BSSID 3c:0e:23:8e:48:3f into blacklist
> 1451963731.366878: TDLS: Remove peers on disassociation
> 1451963731.366885: wlan0: WPA: Clear old PMK and PTK
> 1451963731.366895: wlan0: Request to deauthenticate -
> bssid=3c:0e:23:8e:48:3f pending_bssid=00:00:00:00:00:00 reason=3
> state=COMPLETED
> 1451963731.366901: TDLS: Tear down peers
> 1451963731.366906:
> wpa_driver_nl80211_deauthenticate(addr=3c:0e:23:8e:48:3f
> reason_code=3)
> 1451963731.386988: wlan0: Event DEAUTH (12) received
> 1451963731.387015: wlan0: Deauthentication notification
> 1451963731.387024: wlan0: * reason 3 (locally generated)
> 1451963731.387032: Deauthentication frame IE(s) - hexdump(len=0):
> [NULL]
> 1451963731.387047: wlan0: CTRL-EVENT-DISCONNECTED
> bssid=3c:0e:23:8e:48:3f reason=3 locally_generated=1
> 1451963731.387063: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0
> ssid="Mocana-SECURE" auth_failures=1 duration=10 reason=AUTH_FAILED
> 1451963731.387075: wlan0: Auto connect enabled: try to reconnect
> (wps=0/0 wpa_state=9)
> 1451963731.387087: wlan0: Setting scan request: 0.100000 sec
> 1451963731.387096: BSSID 3c:0e:23:8e:48:3f blacklist count
> incremented to 2
> 1451963731.387216: wlan0: Blacklist count 2 --> request scan in 500
> ms
> 1451963731.387233: wlan0: Ignore new scan request for 0.500000 sec
> since an earlier request is scheduled to trigger sooner
> 1451963731.387242: TDLS: Remove peers on disassociation
> 1451963731.387251: wlan0: WPA: Clear old PMK and PTK
> 1451963731.387354: wlan0: Disconnect event - remove keys
> 1451963731.387381: wpa_driver_nl80211_set_key: ifindex=3 (wlan0)
> alg=0 addr=(nil) key_idx=0 set_tx=0 seq_len=0 key_len=0
> 1451963731.387422: wpa_driver_nl80211_set_key: ifindex=3 (wlan0)
> alg=0 addr=(nil) key_idx=1 set_tx=0 seq_len=0 key_len=0
> 1451963731.387451: wpa_driver_nl80211_set_key: ifindex=3 (wlan0)
> alg=0 addr=(nil) key_idx=2 set_tx=0 seq_len=0 key_len=0
> 1451963731.387482: wpa_driver_nl80211_set_key: ifindex=3 (wlan0)
> alg=0 addr=0x555b677a6550 key_idx=0 set_tx=0 seq_len=0 key_len=0
> 1451963731.387496: addr=3c:0e:23:8e:48:3f
> 1451963731.387518: wlan0: State: COMPLETED -> DISCONNECTED
> 1451963731.387529: nl80211: Set wlan0 operstate 1->0 (DORMANT)
> 1451963731.387539: netlink: Operstate: ifindex=3 linkmode=-1 (no
> change), operstate=5 (IF_OPER_DORMANT)
> 1451963731.387555: bgscan: Deinitializing module 'simple'
> 1451963731.387566: nl80211: Signal monitor threshold=0 hysteresis=0
> 1451963731.387587: WMM AC: WMM AC is disabled
> 1451963731.387630: EAPOL: External notification - portEnabled=0
> 1451963731.387642: EAPOL: SUPP_PAE entering state DISCONNECTED
> 1451963731.387650: EAPOL: Supplicant port status: Unauthorized
> 1451963731.387659: nl80211: Skip set_supp_port(unauthorized) while
> not associated
> 1451963731.387667: EAPOL: SUPP_BE entering state INITIALIZE
> 1451963731.387676: EAP: EAP entering state DISABLED
> 1451963731.387686: EAPOL: External notification - portValid=0
> 1451963731.387706: wlan0: State: DISCONNECTED -> DISCONNECTED
> 1451963731.387713: nl80211: Set wlan0 operstate 0->0 (DORMANT)
> 1451963731.387719: netlink: Operstate: ifindex=3 linkmode=-1 (no
> change), operstate=5 (IF_OPER_DORMANT)
> 1451963731.387729: EAPOL: External notification - portEnabled=0
> 1451963731.387737: EAPOL: External notification - portValid=0
> 1451963731.387745: wlan0: Ignore new scan request for 1.000000 sec
> since an earlier request is scheduled to trigger sooner
> 1451963731.387766: RTM_NEWLINK: ifi_index=3 ifname=wlan0 wext
> ifi_family=0 ifi_flags=0x1043 ([UP][RUNNING])
> 1451963731.387782: RTM_NEWLINK: ifi_index=3 ifname=wlan0 operstate=2
> linkmode=1 ifi_family=0 ifi_flags=0x1003 ([UP])
> 1451963731.387796: nl80211: Event message available
> 1451963731.387808: nl80211: Ignored event (cmd=20) for foreign
> interface (ifindex 3 wdev 0x0)
> 1451963731.387816: nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION)
> received for wlan0
> 1451963731.387823: nl80211: Delete station 3c:0e:23:8e:48:3f
> 1451963731.387834: nl80211: Event message available
> 1451963731.387842: nl80211: Ignored event (cmd=39) for foreign
> interface (ifindex 3 wdev 0x0)
> 1451963731.387849: nl80211: Drv Event 39 (NL80211_CMD_DEAUTHENTICATE)
> received for wlan0
> 1451963731.387855: nl80211: MLME event 39
> (NL80211_CMD_DEAUTHENTICATE) on wlan0(7c:7a:91:86:c9:3c)
> A1=3c:0e:23:8e:48:3f A2=7c:7a:91:86:c9:3c
> 1451963731.387865: nl80211: MLME event frame - hexdump(len=26): c0 00
> 00 00 3c 0e 23 8e 48 3f 7c 7a 91 86 c9 3c 3c 0e 23 8e 48 3f 00 00 03
> 00
> 1451963731.387877: nl80211: Deauthenticate event
> 1451963731.387883: nl80211: Ignore deauth event triggered due to own
> deauth request
> 1451963731.387892: nl80211: Event message available
> 1451963731.387900: nl80211: Ignored event (cmd=48) for foreign
> interface (ifindex 3 wdev 0x0)
> 1451963731.387907: nl80211: Drv Event 48 (NL80211_CMD_DISCONNECT)
> received for wlan0
> 1451963731.387913: nl80211: Ignore disconnect event when using
> userspace SME
> 1451963731.389558: nl80211: Event message available
> 1451963731.389584: nl80211: Drv Event 36 (NL80211_CMD_REG_CHANGE)
> received for p2p-dev-wlan0
> 1451963731.389591: nl80211: Regulatory domain change
> 1451963731.389596: * initiator=0
> 1451963731.389601: * type=1
> 1451963731.389610: p2p-dev-wlan0: Event CHANNEL_LIST_CHANGED (28)
> received
> 1451963731.389619: p2p-dev-wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE
> type=WORLD
> 1451963731.389747: nl80211: Regulatory information - country=00
> 1451963731.389757: nl80211: 2402-2472 @ 40 MHz 20 mBm
> 1451963731.389764: nl80211: 2457-2482 @ 40 MHz 20 mBm (no IR)
> 1451963731.389772: nl80211: 2474-2494 @ 20 MHz 20 mBm (no OFDM) (no
> IR)
> 1451963731.389779: nl80211: 5170-5250 @ 80 MHz 20 mBm (no IR)
> 1451963731.389787: nl80211: 5250-5330 @ 80 MHz 20 mBm (DFS) (no IR)
> 1451963731.389794: nl80211: 5490-5730 @ 160 MHz 20 mBm (DFS) (no IR)
> 1451963731.389802: nl80211: 5735-5835 @ 80 MHz 20 mBm (no IR)
> 1451963731.389809: nl80211: 57240-63720 @ 2160 MHz 0 mBm
> 1451963731.389826: nl80211: Added 802.11b mode based on 802.11g
> information
> 1451963731.389835: P2P: Add operating class 81
> 1451963731.389842: P2P: Channels - hexdump(len=11): 01 02 03 04 05 06
> 07 08 09 0a 0b
> 1451963731.389858: P2P: Update channel list
> 1451963731.389869: P2P: channels: 81:1,2,3,4,5,6,7,8,9,10,11
> 1451963731.389876: P2P: cli_channels:
> 1451963731.389882: wlan0: Updating hw mode
> 1451963731.389981: nl80211: Regulatory information - country=00
> 1451963731.389989: nl80211: 2402-2472 @ 40 MHz 20 mBm
> 1451963731.389996: nl80211: 2457-2482 @ 40 MHz 20 mBm (no IR)
> 1451963731.390003: nl80211: 2474-2494 @ 20 MHz 20 mBm (no OFDM) (no
> IR)
> 1451963731.390011: nl80211: 5170-5250 @ 80 MHz 20 mBm (no IR)
> 1451963731.390018: nl80211: 5250-5330 @ 80 MHz 20 mBm (DFS) (no IR)
> 1451963731.390025: nl80211: 5490-5730 @ 160 MHz 20 mBm (DFS) (no IR)
> 1451963731.390032: nl80211: 5735-5835 @ 80 MHz 20 mBm (no IR)
> 1451963731.390039: nl80211: 57240-63720 @ 2160 MHz 0 mBm
> 1451963731.390055: nl80211: Added 802.11b mode based on 802.11g
> information
> 1451963731.392696: dbus: flush_object_timeout_handler: Timeout -
> sending changed properties of object
> /fi/w1/wpa_supplicant1/Interfaces/3
> 1451963731.487289: wlan0: State: DISCONNECTED -> SCANNING
> 1451963731.487386: Scan SSID - hexdump_ascii(len=13):
> 4d 6f 63 61 6e 61 2d 53 45 43 55 52 45 Mocana-SECURE
> 1451963731.487397: wlan0: Starting AP scan for wildcard SSID
>
> ________________________________________
> From: Jouni Malinen [j@xxxxx]
> Sent: Monday, January 04, 2016 15:29
> To: Adam Jacobs
> Cc: hostap@xxxxxxxxxxxxxxxxxxx
> Subject: Re: EAP-TLV: Earlier failure - force failed Phase 2
>
> On Mon, Jan 04, 2016 at 02:46:43PM -0800, Adam Jacobs wrote:
> > My laptop runs Ubuntu, and when I reproduced the error, it was
> > invoking wpa_supplicant via NetworkManager. Of course, to test
> > disabling TLS1.2, I had to shut off NetworkManager and invoke
> > wpa_supplicant manually.
> >
> > What I've now discovered is that if I invoke wpa_supplicant
> > manually, everything works fine even if I DON'T disable TLS1.2.
>
> You might want to try to test this with NetworkManager and just
> increasing debug verbosity for wpa_supplicant, e.g., by killing the
> existing wpa_supplicant process and starting another one with
> something
> like "-dddtu -f /tmp/wpas.log" on the command line.
>
> > My config looks like this:
> >
> > network={
> > ssid="Mocana-SECURE"
> > key_mgmt=WPA-EAP
> > eap=PEAP
> > identity="ajacobs"
> > password="**********"
> > phase2="auth=MSCHAPV2"
> > ca_cert="/usr/local/etc/MocanaRoot.pem"
> > }
>
> Based on couple of logs that Dan pointed me to, the only real
> differences to that with NM would be addition of fragment_size=1300
> (or
> something around that value) and proactive_key_caching=1. I don't
> know
> how either of these would cause the issue, but well, I guess it is
> worth
> trying these (or that debugging mechanism with NM mentioned above).
> In
> any case, I don't think I can do much more without the issue being
> reproduced with verbose debugging enabled in wpa_supplicant.
>
> > So it must be something about the way NetworkManager is
> > calling/managing NetworkSupplicant that causes this failure.
> > Unfortunately I don't know of any way to debug that further, and
> > as I've shown wpa_supplicant to be working properly it is probably
> > no longer the domain of this group, Still, I'm happy to take
> > suggestions if anyone has any ideas for debugging further.
>
> NM should not be able to configure wpa_supplicant in a way that
> causes
> this type of interop issues, so I'd interpret that a bit differently:
> at
> least one configuration of wpa_supplicant works, but something else
> in
> the configuration or timing or whatever makes this fail in some other
> cases.
>
> --
> Jouni Malinen PGP id
> EFC895FA
>
> _______________________________________________
> Hostap mailing list
> Hostap@xxxxxxxxxxxxxxxxxxx
> http://lists.infradead.org/mailman/listinfo/hostap
_______________________________________________
Hostap mailing list
Hostap@xxxxxxxxxxxxxxxxxxx
http://lists.infradead.org/mailman/listinfo/hostap
