Ticket #14266: wpa_tracing_t410.txt

File wpa_tracing_t410.txt, 14.4 KB (added by ttcoder, 8 months ago)

terminal tracing: failure to connect to livebox

Line 
1
2Welcome to the Haiku shell.
3
4~/Desktop> wpa_supplicant
5wpa_supplicant v2.7-devel
6Initializing interface '/dev/net/iprowifi4965/0' conf 'N/A' driver 'default' ctrl_interface 'N/A' bridge 'N/A'
7wpa_driver_bsd_capa: drivercaps=0x0581e201,cryptocaps=0x00000000
8Add interface /dev/net/iprowifi4965/0 to a new radio N/A
9/dev/net/iprowifi4965/0: Failed to attach pkt_type filter
10/dev/net/iprowifi4965/0: Own MAC address: 00:23:14:97:51:7c
11bsd_set_key: alg=0 addr=(nil) key_idx=0 set_tx=0 seq_len=0 key_len=0
12bsd_del_key: key_idx=0
13bsd_set_key: alg=0 addr=(nil) key_idx=1 set_tx=0 seq_len=0 key_len=0
14bsd_del_key: key_idx=1
15bsd_set_key: alg=0 addr=(nil) key_idx=2 set_tx=0 seq_len=0 key_len=0
16bsd_del_key: key_idx=2
17bsd_set_key: alg=0 addr=(nil) key_idx=3 set_tx=0 seq_len=0 key_len=0
18bsd_del_key: key_idx=3
19wpa_driver_bsd_set_countermeasures: enabled=0
20/dev/net/iprowifi4965/0: RSN: flushing PMKID list in the driver
21/dev/net/iprowifi4965/0: State: DISCONNECTED -> INACTIVE
22/dev/net/iprowifi4965/0: Added interface /dev/net/iprowifi4965/0
23/dev/net/iprowifi4965/0: State: INACTIVE -> DISCONNECTED
24ssid - hexdump_ascii(len=12):
25     4c 69 76 65 62 6f 78 2d 37 61 30 63               Livebox-7a0c   
26scan_ssid=1 (0x1)
27PSK (ASCII passphrase) - hexdump_ascii(len=26): [REMOVED]
28PSK (from passphrase) - hexdump(len=32): [REMOVED]
29/dev/net/iprowifi4965/0: Setting scan request: 0.000000 sec
30/dev/net/iprowifi4965/0: State: DISCONNECTED -> SCANNING
31Scan SSID - hexdump_ascii(len=12):
32     4c 69 76 65 62 6f 78 2d 37 61 30 63               Livebox-7a0c   
33/dev/net/iprowifi4965/0: Starting AP scan for wildcard SSID
34/dev/net/iprowifi4965/0: Add radio work 'scan'@0x199663f0
35/dev/net/iprowifi4965/0: First radio work item in the queue - schedule start immediately
36/dev/net/iprowifi4965/0: Starting radio work 'scan'@0x199663f0 after 0.000019 second wait
37wpa_driver_bsd_set_wpa: enabled=1
38wpa_driver_bsd_set_wpa_internal: wpa=3 privacy=1
39/dev/net/iprowifi4965/0: Event SCAN_RESULTS (3) received
40Received 0 bytes of scan results (0 BSSes)
41/dev/net/iprowifi4965/0: BSS: Start scan result update 1
42BSS: last_scan_res_used=0/0
43/dev/net/iprowifi4965/0: New scan results available (own=0 ext=0)
44/dev/net/iprowifi4965/0: Radio work 'scan'@0x199663f0 done in 0.003257 seconds
45/dev/net/iprowifi4965/0: radio_work_free('scan'@0x199663f0): num_active_works --> 0
46/dev/net/iprowifi4965/0: No suitable network found
47/dev/net/iprowifi4965/0: Setting scan request: 5.000000 sec
48/dev/net/iprowifi4965/0: Event SCAN_RESULTS (3) received
49Received 268 bytes of scan results (1 BSSes)
50Sorted scan results
51d0:ae:ec:3e:a9:b0 freq=2437 qual=81 noise=-95 level=-55 flags=0x0 age=0 est=1000
52IEs - hexdump(len=230): 00 0c 4c 69 76 65 62 6f 78 2d 37 61 30 63 01 0c 82 84 8b 96 0c 12 18 24 30 48 60 6c 2a 01 00 00 0c 4c 69 76 65 62 6f 78 2d 37 61 30 63 01 08 82 84 8b 96 0c 12 18 24 03 01 06 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 00 00 dd 1a 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02 2a 01 00 32 04 30 48 60 6c dd 18 00 50 f2 02 01 01 83 00 03 a4 00 00 27 a4 00 00 42 43 5e 00 62 32 2f 00 2d 1a 0c 10 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 06 08 08 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 dd 09 00 03 7f 01 01 00 00 ff 7f dd 0a 00 03 7f 04 01 00 00 00 00 00 07 06 46 52 20 01 0d 14
53/dev/net/iprowifi4965/0: BSS: Start scan result update 2
54/dev/net/iprowifi4965/0: BSS: Add new id 0 BSSID d0:ae:ec:3e:a9:b0 SSID 'Livebox-7a0c' freq 2437
55BSS: last_scan_res_used=1/32
56Add randomness: count=1 entropy=0
57random pool - hexdump(len=128): [REMOVED]
58random_mix_pool - hexdump(len=8): [REMOVED]
59random_mix_pool - hexdump(len=5): [REMOVED]
60random pool - hexdump(len=128): [REMOVED]
61/dev/net/iprowifi4965/0: New scan results available (own=0 ext=0)
62/dev/net/iprowifi4965/0: Scan results matching the currently selected network
63/dev/net/iprowifi4965/0: 0: d0:ae:ec:3e:a9:b0 freq=2437 level=-55 snr=-55 est_throughput=1000
64/dev/net/iprowifi4965/0: Selecting BSS from priority group 0
65/dev/net/iprowifi4965/0: 0: d0:ae:ec:3e:a9:b0 ssid='Livebox-7a0c' wpa_ie_len=26 rsn_ie_len=24 caps=0x31 level=-55 freq=2437
66/dev/net/iprowifi4965/0:    selected based on RSN IE
67/dev/net/iprowifi4965/0:    selected BSS d0:ae:ec:3e:a9:b0 ssid='Livebox-7a0c'
68/dev/net/iprowifi4965/0: Considering connect request: reassociate: 1  selected: d0:ae:ec:3e:a9:b0  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: SCANNING  ssid=0x199ba280  current_ssid=0x199ba280
69/dev/net/iprowifi4965/0: Request association with d0:ae:ec:3e:a9:b0
70/dev/net/iprowifi4965/0: No ongoing scan/p2p-scan found to abort
71/dev/net/iprowifi4965/0: Add radio work 'connect'@0x199663f0
72/dev/net/iprowifi4965/0: First radio work item in the queue - schedule start immediately
73/dev/net/iprowifi4965/0: Starting radio work 'connect'@0x199663f0 after 0.000250 second wait
74/dev/net/iprowifi4965/0: Trying to associate with d0:ae:ec:3e:a9:b0 (SSID='Livebox-7a0c' freq=2437 MHz)
75/dev/net/iprowifi4965/0: Cancelling scan request
76/dev/net/iprowifi4965/0: WPA: clearing own WPA/RSN IE
77/dev/net/iprowifi4965/0: RSN: using IEEE 802.11i/D9.0
78/dev/net/iprowifi4965/0: WPA: Selected cipher suites: group 8 pairwise 24 key_mgmt 2 proto 2
79WPA: set AP WPA IE - hexdump(len=28): dd 1a 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02
80WPA: set AP RSN IE - hexdump(len=26): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 00 00
81/dev/net/iprowifi4965/0: WPA: using GTK TKIP
82/dev/net/iprowifi4965/0: WPA: using PTK CCMP
83/dev/net/iprowifi4965/0: WPA: using KEY_MGMT WPA-PSK
84WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
85PSK (set in config) - hexdump(len=32): [REMOVED]
86WPA: Set PMK based on external data - hexdump(len=32): [REMOVED]
87/dev/net/iprowifi4965/0: Automatic auth_alg selection: 0x1
88Failed to add supported operating classes IE
89/dev/net/iprowifi4965/0: State: SCANNING -> ASSOCIATING
90Limit connection to BSSID d0:ae:ec:3e:a9:b0 freq=2437 MHz based on scan results (bssid_set=0 wps=0)
91wpa_driver_bsd_associate: ssid 'Livebox-7a0c' wpa ie len 22 pairwise 16 group 8 key mgmt 2
92wpa_driver_bsd_set_drop_unencrypted: enabled=1
93bsd_set_opt_ie: set WPA+RSN ie (len 22)
94wpa_driver_bsd_associate: set PRIVACY 1
95/dev/net/iprowifi4965/0: Setting authentication timeout: 10 sec 0 usec
96
97
98/dev/net/iprowifi4965/0: Authentication with d0:ae:ec:3e:a9:b0 timed out.
99Added BSSID d0:ae:ec:3e:a9:b0 into blacklist
100/dev/net/iprowifi4965/0: WPA: Clear old PMK and PTK
101/dev/net/iprowifi4965/0: Request to deauthenticate - bssid=00:00:00:00:00:00 pending_bssid=d0:ae:ec:3e:a9:b0 reason=3 state=ASSOCIATING
102/dev/net/iprowifi4965/0: Event DEAUTH (11) received
103/dev/net/iprowifi4965/0: Deauthentication notification
104/dev/net/iprowifi4965/0:  * reason 3 (locally generated)
105Deauthentication frame IE(s) - hexdump(len=0): [NULL]
106/dev/net/iprowifi4965/0: CTRL-EVENT-DISCONNECTED bssid=d0:ae:ec:3e:a9:b0 reason=3 locally_generated=1
107/dev/net/iprowifi4965/0: Auto connect enabled: try to reconnect (wps=0/0 wpa_state=5)
108/dev/net/iprowifi4965/0: Setting scan request: 0.100000 sec
109/dev/net/iprowifi4965/0: Radio work 'connect'@0x199663f0 done in 10.010843 seconds
110/dev/net/iprowifi4965/0: radio_work_free('connect'@0x199663f0): num_active_works --> 0
111BSSID d0:ae:ec:3e:a9:b0 blacklist count incremented to 2
112/dev/net/iprowifi4965/0: Blacklist count 2 --> request scan in 500 ms
113/dev/net/iprowifi4965/0: Ignore new scan request for 0.500000 sec since an earlier request is scheduled to trigger sooner
114/dev/net/iprowifi4965/0: WPA: Clear old PMK and PTK
115/dev/net/iprowifi4965/0: Disconnect event - remove keys
116/dev/net/iprowifi4965/0: State: ASSOCIATING -> DISCONNECTED
117/dev/net/iprowifi4965/0: State: DISCONNECTED -> DISCONNECTED
118/dev/net/iprowifi4965/0: Ignore new scan request for 1.000000 sec since an earlier request is scheduled to trigger sooner
119/dev/net/iprowifi4965/0: State: DISCONNECTED -> SCANNING
120Scan SSID - hexdump_ascii(len=12):
121     4c 69 76 65 62 6f 78 2d 37 61 30 63               Livebox-7a0c   
122/dev/net/iprowifi4965/0: Starting AP scan for wildcard SSID
123/dev/net/iprowifi4965/0: Add radio work 'scan'@0x199663f0
124/dev/net/iprowifi4965/0: First radio work item in the queue - schedule start immediately
125/dev/net/iprowifi4965/0: Starting radio work 'scan'@0x199663f0 after 0.000071 second wait
126wpa_driver_bsd_set_wpa: enabled=1
127wpa_driver_bsd_set_wpa_internal: wpa=3 privacy=1
128/dev/net/iprowifi4965/0: Event SCAN_RESULTS (3) received
129Received 268 bytes of scan results (1 BSSes)
130Sorted scan results
131d0:ae:ec:3e:a9:b0 freq=2437 qual=81 noise=-95 level=-55 flags=0x0 age=0 est=1000
132IEs - hexdump(len=230): 00 0c 4c 69 76 65 62 6f 78 2d 37 61 30 63 01 0c 82 84 8b 96 0c 12 18 24 30 48 60 6c 2a 01 00 00 0c 4c 69 76 65 62 6f 78 2d 37 61 30 63 01 08 82 84 8b 96 0c 12 18 24 03 01 06 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 00 00 dd 1a 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02 2a 01 00 32 04 30 48 60 6c dd 18 00 50 f2 02 01 01 83 00 03 a4 00 00 27 a4 00 00 42 43 5e 00 62 32 2f 00 2d 1a 0c 10 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 06 08 08 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 dd 09 00 03 7f 01 01 00 00 ff 7f dd 0a 00 03 7f 04 01 00 00 00 00 00 07 06 46 52 20 01 0d 14
133/dev/net/iprowifi4965/0: BSS: Start scan result update 3
134BSS: last_scan_res_used=1/32
135Add randomness: count=2 entropy=1
136random pool - hexdump(len=128): [REMOVED]
137random_mix_pool - hexdump(len=8): [REMOVED]
138random_mix_pool - hexdump(len=5): [REMOVED]
139random pool - hexdump(len=128): [REMOVED]
140/dev/net/iprowifi4965/0: New scan results available (own=0 ext=0)
141/dev/net/iprowifi4965/0: Radio work 'scan'@0x199663f0 done in 1.220929 seconds
142/dev/net/iprowifi4965/0: radio_work_free('scan'@0x199663f0): num_active_works --> 0
143/dev/net/iprowifi4965/0: Selecting BSS from priority group 0
144/dev/net/iprowifi4965/0: 0: d0:ae:ec:3e:a9:b0 ssid='Livebox-7a0c' wpa_ie_len=26 rsn_ie_len=24 caps=0x31 level=-55 freq=2437
145/dev/net/iprowifi4965/0:    skip - blacklisted (count=2 limit=0)
146/dev/net/iprowifi4965/0: No APs found - clear blacklist and try again
147Removed BSSID d0:ae:ec:3e:a9:b0 from blacklist (clear)
148/dev/net/iprowifi4965/0: Selecting BSS from priority group 0
149/dev/net/iprowifi4965/0: 0: d0:ae:ec:3e:a9:b0 ssid='Livebox-7a0c' wpa_ie_len=26 rsn_ie_len=24 caps=0x31 level=-55 freq=2437
150/dev/net/iprowifi4965/0:    selected based on RSN IE
151/dev/net/iprowifi4965/0:    selected BSS d0:ae:ec:3e:a9:b0 ssid='Livebox-7a0c'
152/dev/net/iprowifi4965/0: Considering connect request: reassociate: 1  selected: d0:ae:ec:3e:a9:b0  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: SCANNING  ssid=0x199ba280  current_ssid=(nil)
153/dev/net/iprowifi4965/0: Request association with d0:ae:ec:3e:a9:b0
154/dev/net/iprowifi4965/0: Re-association to the same ESS
155/dev/net/iprowifi4965/0: No ongoing scan/p2p-scan found to abort
156/dev/net/iprowifi4965/0: Add radio work 'connect'@0x199663f0
157/dev/net/iprowifi4965/0: First radio work item in the queue - schedule start immediately
158/dev/net/iprowifi4965/0: Starting radio work 'connect'@0x199663f0 after 0.000062 second wait
159/dev/net/iprowifi4965/0: Trying to associate with d0:ae:ec:3e:a9:b0 (SSID='Livebox-7a0c' freq=2437 MHz)
160/dev/net/iprowifi4965/0: Cancelling scan request
161/dev/net/iprowifi4965/0: WPA: clearing own WPA/RSN IE
162/dev/net/iprowifi4965/0: RSN: using IEEE 802.11i/D9.0
163/dev/net/iprowifi4965/0: WPA: Selected cipher suites: group 8 pairwise 24 key_mgmt 2 proto 2
164WPA: set AP WPA IE - hexdump(len=28): dd 1a 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02
165WPA: set AP RSN IE - hexdump(len=26): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 00 00
166/dev/net/iprowifi4965/0: WPA: using GTK TKIP
167/dev/net/iprowifi4965/0: WPA: using PTK CCMP
168/dev/net/iprowifi4965/0: WPA: using KEY_MGMT WPA-PSK
169WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
170PSK (set in config) - hexdump(len=32): [REMOVED]
171WPA: Set PMK based on external data - hexdump(len=32): [REMOVED]
172/dev/net/iprowifi4965/0: Automatic auth_alg selection: 0x1
173Failed to add supported operating classes IE
174/dev/net/iprowifi4965/0: State: SCANNING -> ASSOCIATING
175Limit connection to BSSID d0:ae:ec:3e:a9:b0 freq=2437 MHz based on scan results (bssid_set=0 wps=0)
176wpa_driver_bsd_associate: ssid 'Livebox-7a0c' wpa ie len 22 pairwise 16 group 8 key mgmt 2
177wpa_driver_bsd_set_drop_unencrypted: enabled=1
178bsd_set_opt_ie: set WPA+RSN ie (len 22)
179wpa_driver_bsd_associate: set PRIVACY 1
180/dev/net/iprowifi4965/0: Setting authentication timeout: 10 sec 0 usec
181
182/dev/net/iprowifi4965/0: Removing interface /dev/net/iprowifi4965/0
183/dev/net/iprowifi4965/0: Request to deauthenticate - bssid=00:00:00:00:00:00 pending_bssid=d0:ae:ec:3e:a9:b0 reason=3 state=ASSOCIATING
184/dev/net/iprowifi4965/0: Event DEAUTH (11) received
185/dev/net/iprowifi4965/0: Deauthentication notification
186/dev/net/iprowifi4965/0:  * reason 3 (locally generated)
187Deauthentication frame IE(s) - hexdump(len=0): [NULL]
188/dev/net/iprowifi4965/0: CTRL-EVENT-DISCONNECTED bssid=d0:ae:ec:3e:a9:b0 reason=3 locally_generated=1
189/dev/net/iprowifi4965/0: Auto connect disabled: do not try to re-connect
190/dev/net/iprowifi4965/0: Radio work 'connect'@0x199663f0 done in 2.387597 seconds
191/dev/net/iprowifi4965/0: radio_work_free('connect'@0x199663f0): num_active_works --> 0
192/dev/net/iprowifi4965/0: Ignore connection failure indication since interface has been put into disconnected state
193/dev/net/iprowifi4965/0: WPA: Clear old PMK and PTK
194/dev/net/iprowifi4965/0: Disconnect event - remove keys
195/dev/net/iprowifi4965/0: State: ASSOCIATING -> DISCONNECTED
196/dev/net/iprowifi4965/0: State: DISCONNECTED -> DISCONNECTED
197wpa_driver_bsd_set_countermeasures: enabled=0
198/dev/net/iprowifi4965/0: WPA: Clear old PMK and PTK
199/dev/net/iprowifi4965/0: BSS: Remove id 0 BSSID d0:ae:ec:3e:a9:b0 SSID 'Livebox-7a0c' due to wpa_bss_flush
200/dev/net/iprowifi4965/0: Cancelling scan request
201/dev/net/iprowifi4965/0: Cancelling authentication timeout
202Remove interface /dev/net/iprowifi4965/0 from radio
203Remove radio
204wpa_driver_bsd_set_wpa: enabled=0
205
206(..)
207Remove interface /dev/net/iprowifi4965/0 from radio
208Remove radio
209wpa_driver_bsd_set_wpa: enabled=0
210wpa_driver_bsd_set_wpa_internal: wpa=0 privacy=0
211bsd_set_opt_ie: set WPA+RSN ie (len 0)
212wpa_driver_bsd_set_wpa_internal: wpa=0 privacy=0
213bsd_set_opt_ie: set WPA+RSN ie (len 0)
214eloop: could not process SIGINT or SIGTERM in two seconds. Looks like there
215is a bug that ends up in a busy loop that prevents clean shutdown.
216Killing program forcefully.
217
218~/Desktop>