Ticket #925: wpa_debug_fault-moredebug-f.txt

File wpa_debug_fault-moredebug-f.txt, 14.1 kB (added by gtm.kramer@inter.nl.net, 2 years ago)

wpa_supplicant debug output with non-working r1711

Line 
1 With madwifi r1711:
2
3 [root@macbook ~]# wpa_supplicant -c wpa_supplicant-test.conf -i ath0 -D madwifi -dd -t
4 Sep 29 19:01:26.377537: Initializing interface 'ath0' conf 'wpa_supplicant-test.conf' driver 'madwifi' ctrl_interface 'N/A'
5 Sep 29 19:01:26.377973: Configuration file 'wpa_supplicant-test.conf' -> '/root/wpa_supplicant-test.conf'
6 Sep 29 19:01:26.378127: Reading configuration file '/root/wpa_supplicant-test.conf'
7 Sep 29 19:01:26.378324: ctrl_interface='/var/run/wpa_supplicant'
8 Sep 29 19:01:26.379288: ctrl_interface_group=10 (from group name 'wheel')
9 Sep 29 19:01:26.379367: Line: 4 - start of a new network block
10 Sep 29 19:01:26.379448: ssid - hexdump_ascii(len=14):
11      63 77 70 35 36 30 2d 61 78 73 21 73 73 34         hiddenessid 
12 Sep 29 19:01:26.379542: key_mgmt: 0x2
13 Sep 29 19:01:26.379615: proto: 0x1
14 Sep 29 19:01:26.379686: pairwise: 0x8
15 Sep 29 19:01:26.379755: group: 0x8
16 Sep 29 19:01:26.379824: PSK (ASCII passphrase) - hexdump_ascii(len=28): [REMOVED]
17 Sep 29 19:01:26.412941: PSK (from passphrase) - hexdump(len=32): [REMOVED]
18 Sep 29 19:01:26.413503: Priority group 0
19 Sep 29 19:01:26.413651:    id=0 ssid='hiddenessid'
20 Sep 29 19:01:26.413795: Initializing interface (2) 'ath0'
21 Sep 29 19:01:26.417881: EAPOL: SUPP_PAE entering state DISCONNECTED
22 Sep 29 19:01:26.418031: EAPOL: KEY_RX entering state NO_KEY_RECEIVE
23 Sep 29 19:01:26.418183: EAPOL: SUPP_BE entering state INITIALIZE
24 Sep 29 19:01:26.418356: EAP: EAP entering state DISABLED
25 Sep 29 19:01:26.418530: EAPOL: External notification - portEnabled=0
26 Sep 29 19:01:26.418684: EAPOL: External notification - portValid=0
27 Sep 29 19:01:26.425015: SIOCGIWRANGE: WE(compiled)=20 WE(source)=13 enc_capa=0xf
28 Sep 29 19:01:26.425182:   capabilities: key_mgmt 0xf enc 0xf
29 Sep 29 19:01:26.438286: Own MAC address: 00:16:cb:b8:5f:f1
30 Sep 29 19:01:26.438592: wpa_driver_madwifi_del_key: keyidx=0
31 Sep 29 19:01:26.438786: wpa_driver_madwifi_del_key: keyidx=1
32 Sep 29 19:01:26.438944: wpa_driver_madwifi_del_key: keyidx=2
33 Sep 29 19:01:26.439089: wpa_driver_madwifi_del_key: keyidx=3
34 Sep 29 19:01:26.439233: wpa_driver_madwifi_set_countermeasures: enabled=0
35 Sep 29 19:01:26.439379: wpa_driver_madwifi_set_drop_unencrypted: enabled=1
36 Sep 29 19:01:26.439549: Setting scan request: 0 sec 100000 usec
37 Sep 29 19:01:26.440647: Added interface ath0
38 Sep 29 19:01:26.440858: Wireless event: cmd=0x8b06 len=8
39 Sep 29 19:01:26.441022: Ignore event for foreign ifindex 3
40 Sep 29 19:01:26.441178: RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
41 Sep 29 19:01:26.441339: RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
42 Sep 29 19:01:26.542327: State: DISCONNECTED -> SCANNING
43 Sep 29 19:01:26.542512: Starting AP scan (broadcast SSID)
44 Sep 29 19:01:26.650001: Wireless event: cmd=0x8b1a len=8
45 Sep 29 19:01:35.825265: Wireless event: cmd=0x8b19 len=8
46 Sep 29 19:01:35.825502: Received 730 bytes of scan results (4 BSSes)
47 Sep 29 19:01:35.825581: Scan results: 4
48 Sep 29 19:01:35.825654: Selecting BSS from priority group 0
49 Sep 29 19:01:35.825725: 0: 00:1f:c5:e4:95:de ssid='hiddenessid' wpa_ie_len=24 rsn_ie_len=0 caps=0x11
50 Sep 29 19:01:35.825808:    selected based on WPA IE
51 Sep 29 19:01:35.825891: Trying to associate with 00:1f:c5:e4:95:de (SSID='hiddenessid' freq=2412 MHz)
52 Sep 29 19:01:35.825966: Cancelling scan request
53 Sep 29 19:01:35.826037: WPA: clearing own WPA/RSN IE
54 Sep 29 19:01:35.826108: Automatic auth_alg selection: 0x1
55 Sep 29 19:01:35.826199: WPA: using IEEE 802.11i/D3.0
56 Sep 29 19:01:35.826272: WPA: Selected cipher suites: group 8 pairwise 8 key_mgmt 2
57 Sep 29 19:01:35.826346: WPA: set AP WPA IE - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02
58 Sep 29 19:01:35.826430: WPA: clearing AP RSN IE
59 Sep 29 19:01:35.826502: WPA: using GTK TKIP
60 Sep 29 19:01:35.826574: WPA: using PTK TKIP
61 Sep 29 19:01:35.826646: WPA: using KEY_MGMT WPA-PSK
62 Sep 29 19:01:35.826718: WPA: Set own WPA IE default - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02
63 Sep 29 19:01:35.826803: No keys have been configured - skip key clearing
64 Sep 29 19:01:35.826874: wpa_driver_madwifi_set_drop_unencrypted: enabled=1
65 Sep 29 19:01:35.826951: State: SCANNING -> ASSOCIATING
66 Sep 29 19:01:35.827024: wpa_driver_madwifi_associate
67 ioctl[IEEE80211_IOCTL_SETMLME]: Invalid argument
68 Sep 29 19:01:35.828424: Association request to the driver failed
69 Sep 29 19:01:35.828503: Setting authentication timeout: 15 sec 0 usec
70 Sep 29 19:01:35.828578: EAPOL: External notification - EAP success=0
71 Sep 29 19:01:35.828669: EAPOL: External notification - EAP fail=0
72 Sep 29 19:01:35.828758: EAPOL: External notification - portControl=Auto
73 Sep 29 19:01:35.828863: Wireless event: cmd=0x8b1a len=23
74 Sep 29 19:01:35.832286: Wireless event: cmd=0x8b15 len=20
75 Sep 29 19:01:35.832363: Wireless event: new AP: 00:1f:c5:e4:95:de
76 Sep 29 19:01:35.832437: State: ASSOCIATING -> ASSOCIATED
77 Sep 29 19:01:35.832518: Associated to a new BSS: BSSID=00:1f:c5:e4:95:de
78 Sep 29 19:01:35.832591: No keys have been configured - skip key clearing
79 Sep 29 19:01:35.832666: Associated with 00:1f:c5:e4:95:de
80 Sep 29 19:01:35.832738: WPA: Association event - clear replay counter
81 Sep 29 19:01:35.832809: EAPOL: External notification - portEnabled=0
82 Sep 29 19:01:35.832897: EAPOL: External notification - portValid=0
83 Sep 29 19:01:35.833012: EAPOL: External notification - EAP success=0
84 Sep 29 19:01:35.833101: EAPOL: External notification - portEnabled=1
85 Sep 29 19:01:35.833173: EAPOL: SUPP_PAE entering state CONNECTING
86 Sep 29 19:01:35.833243: EAPOL: SUPP_BE entering state IDLE
87 Sep 29 19:01:35.833326: Setting authentication timeout: 10 sec 0 usec
88 Sep 29 19:01:35.833415: RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
89 Sep 29 19:01:35.833665: RX EAPOL from 00:1f:c5:e4:95:de
90 Sep 29 19:01:35.833742: RX EAPOL - hexdump(len=99): 01 03 00 5f fe 00 89 00 20 00 00 00 00 00 00 00 01 44 10 97 89 f8 d7 52 bc b7 c2 41 c4 17 ad 54 c2 11 c4 86 61 9e 7d 98 fe 8a 53 2f c9 31 e1 d6 db 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
91 Sep 29 19:01:35.833863: Setting authentication timeout: 10 sec 0 usec
92 Sep 29 19:01:35.833941: IEEE 802.1X RX: version=1 type=3 length=95
93 Sep 29 19:01:35.834017:   EAPOL-Key type=254
94 Sep 29 19:01:35.834089: WPA: RX EAPOL-Key - hexdump(len=99): 01 03 00 5f fe 00 89 00 20 00 00 00 00 00 00 00 01 44 10 97 89 f8 d7 52 bc b7 c2 41 c4 17 ad 54 c2 11 c4 86 61 9e 7d 98 fe 8a 53 2f c9 31 e1 d6 db 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
95 Sep 29 19:01:35.834227: State: ASSOCIATED -> 4WAY_HANDSHAKE
96 Sep 29 19:01:35.834300: WPA: RX message 1 of 4-Way Handshake from 00:1f:c5:e4:95:de (ver=1)
97 Sep 29 19:01:35.834374: WPA: WPA IE for msg 2/4 - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02
98 Sep 29 19:01:35.837266: WPA: Renewed SNonce - hexdump(len=32): c6 02 e3 c6 d2 1b f3 c7 63 7a a7 06 76 4c 68 71 f1 cb 2f ad 1c 1b 5f c9 9f 0e a7 91 bf 94 a8 32
99 Sep 29 19:01:35.837377: WPA: PMK - hexdump(len=32): [REMOVED]
100 Sep 29 19:01:35.837444: WPA: PTK - hexdump(len=64): [REMOVED]
101 Sep 29 19:01:35.837516: WPA: Sending EAPOL-Key 2/4
102 Sep 29 19:01:35.837602: WPA: TX EAPOL-Key - hexdump(len=123): 01 03 00 77 fe 01 09 00 20 00 00 00 00 00 00 00 01 c6 02 e3 c6 d2 1b f3 c7 63 7a a7 06 76 4c 68 71 f1 cb 2f ad 1c 1b 5f c9 9f 0e a7 91 bf 94 a8 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5b f4 c6 04 94 cd 47 b4 f1 09 82 0b 93 eb 13 5e 00 18 dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02
103 Sep 29 19:01:35.843408: RX EAPOL from 00:1f:c5:e4:95:de
104 Sep 29 19:01:35.843516: RX EAPOL - hexdump(len=123): 01 03 00 77 fe 01 c9 00 20 00 00 00 00 00 00 00 02 44 10 97 89 f8 d7 52 bc b7 c2 41 c4 17 ad 54 c2 11 c4 86 61 9e 7d 98 fe 8a 53 2f c9 31 e1 d6 db 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2c 6c bc a7 af 2d b0 38 1b b9 9d 9a 04 24 6c 75 00 18 dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02
105 Sep 29 19:01:35.843649: IEEE 802.1X RX: version=1 type=3 length=119
106 Sep 29 19:01:35.843721:   EAPOL-Key type=254
107 Sep 29 19:01:35.843793: WPA: RX EAPOL-Key - hexdump(len=123): 01 03 00 77 fe 01 c9 00 20 00 00 00 00 00 00 00 02 44 10 97 89 f8 d7 52 bc b7 c2 41 c4 17 ad 54 c2 11 c4 86 61 9e 7d 98 fe 8a 53 2f c9 31 e1 d6 db 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2c 6c bc a7 af 2d b0 38 1b b9 9d 9a 04 24 6c 75 00 18 dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02
108 Sep 29 19:01:35.843930: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
109 Sep 29 19:01:35.844002: WPA: RX message 3 of 4-Way Handshake from 00:1f:c5:e4:95:de (ver=1)
110 Sep 29 19:01:35.844076: WPA: IE KeyData - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02
111 Sep 29 19:01:35.844161: WPA: Sending EAPOL-Key 4/4
112 Sep 29 19:01:35.844235: WPA: TX EAPOL-Key - hexdump(len=99): 01 03 00 5f fe 01 09 00 20 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 f2 ce 4e 34 84 fa 9c c5 16 b2 4e 42 26 7a 79 27 00 00
113 Sep 29 19:01:35.844421: WPA: Installing PTK to the driver.
114 Sep 29 19:01:35.844565: WPA: RSC - hexdump(len=6): 00 00 00 00 00 00
115 Sep 29 19:01:35.844641: wpa_driver_madwifi_set_key: alg=TKIP key_idx=0 set_tx=1 seq_len=6 key_len=32
116 Sep 29 19:01:35.844742: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
117 Sep 29 19:01:37.561278: Wireless event: cmd=0x8b15 len=20
118 Sep 29 19:01:37.561373: Wireless event: new AP: 00:00:00:00:00:00
119 Sep 29 19:01:37.561449: Setting scan request: 0 sec 100000 usec
120 Sep 29 19:01:37.561541: Added BSSID 00:1f:c5:e4:95:de into blacklist
121 Sep 29 19:01:37.561616: State: GROUP_HANDSHAKE -> DISCONNECTED
122 Sep 29 19:01:37.561688: EAPOL: External notification - portEnabled=0
123 Sep 29 19:01:37.561757: EAPOL: SUPP_PAE entering state DISCONNECTED
124 Sep 29 19:01:37.561822: EAPOL: SUPP_BE entering state INITIALIZE
125 Sep 29 19:01:37.561912: EAPOL: External notification - portValid=0
126 Sep 29 19:01:37.562001: EAPOL: External notification - EAP success=0
127 Sep 29 19:01:37.562091: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
128 Sep 29 19:01:37.562164: wpa_driver_madwifi_del_key: keyidx=0
129 Sep 29 19:01:37.569601: wpa_driver_madwifi_del_key: keyidx=1
130 Sep 29 19:01:37.569685: wpa_driver_madwifi_del_key: keyidx=2
131 Sep 29 19:01:37.569763: wpa_driver_madwifi_del_key: keyidx=3
132 Sep 29 19:01:37.569841: wpa_driver_madwifi_del_key: keyidx=0
133 Sep 29 19:01:37.569933: RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
134 Sep 29 19:01:37.665488: State: DISCONNECTED -> SCANNING
135 Sep 29 19:01:37.665588: Starting AP scan (broadcast SSID)
136 Sep 29 19:01:37.665826: Wireless event: cmd=0x8b1a len=8
137 Sep 29 19:01:38.437501: EAPOL: startWhen --> 0
138 Sep 29 19:01:45.837683: Authentication with 00:00:00:00:00:00 timed out.
139 Sep 29 19:01:45.837781: Added BSSID 00:00:00:00:00:00 into blacklist
140 Sep 29 19:01:45.837854: State: SCANNING -> DISCONNECTED
141 Sep 29 19:01:45.837926: No keys have been configured - skip key clearing
142 Sep 29 19:01:45.837998: EAPOL: External notification - portEnabled=0
143 Sep 29 19:01:45.838086: EAPOL: External notification - portValid=0
144 Sep 29 19:01:45.838178: Setting scan request: 0 sec 0 usec
145 Sep 29 19:01:45.838270: State: DISCONNECTED -> SCANNING
146 Sep 29 19:01:45.838343: Starting AP scan (broadcast SSID)
147 Sep 29 19:01:45.950384: Wireless event: cmd=0x8b1a len=8
148 Sep 29 19:01:55.074030: Wireless event: cmd=0x8b19 len=8
149 Sep 29 19:01:55.074226: Received 730 bytes of scan results (4 BSSes)
150 Sep 29 19:01:55.074303: Scan results: 4
151 Sep 29 19:01:55.074386: Selecting BSS from priority group 0
152 Sep 29 19:01:55.074458: 0: 00:1f:c5:e4:95:de ssid='hiddenessid' wpa_ie_len=24 rsn_ie_len=0 caps=0x11
153 Sep 29 19:01:55.074537:    selected based on WPA IE
154 Sep 29 19:01:55.074615: Trying to associate with 00:1f:c5:e4:95:de (SSID='hiddenessid' freq=2412 MHz)
155 Sep 29 19:01:55.074690: Cancelling scan request
156 Sep 29 19:01:55.074761: WPA: clearing own WPA/RSN IE
157 Sep 29 19:01:55.074832: Automatic auth_alg selection: 0x1
158 Sep 29 19:01:55.074915: WPA: using IEEE 802.11i/D3.0
159 Sep 29 19:01:55.074988: WPA: Selected cipher suites: group 8 pairwise 8 key_mgmt 2
160 Sep 29 19:01:55.075062: WPA: set AP WPA IE - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02
161 Sep 29 19:01:55.075146: WPA: clearing AP RSN IE
162 Sep 29 19:01:55.075218: WPA: using GTK TKIP
163 Sep 29 19:01:55.075291: WPA: using PTK TKIP
164 Sep 29 19:01:55.075363: WPA: using KEY_MGMT WPA-PSK
165 Sep 29 19:01:55.075435: WPA: Set own WPA IE default - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02
166 Sep 29 19:01:55.075519: No keys have been configured - skip key clearing
167 Sep 29 19:01:55.075591: wpa_driver_madwifi_set_drop_unencrypted: enabled=1
168 Sep 29 19:01:55.075669: State: SCANNING -> ASSOCIATING
169 Sep 29 19:01:55.075742: wpa_driver_madwifi_associate
170 ioctl[IEEE80211_IOCTL_SETMLME]: Invalid argument
171 Sep 29 19:01:55.078327: Association request to the driver failed
172 Sep 29 19:01:55.078417: Setting authentication timeout: 15 sec 0 usec
173 Sep 29 19:01:55.078492: EAPOL: External notification - EAP success=0
174 Sep 29 19:01:55.078584: EAPOL: External notification - EAP fail=0
175 Sep 29 19:01:55.078673: EAPOL: External notification - portControl=Auto
176 Sep 29 19:01:55.078781: Wireless event: cmd=0x8b1a len=23
177
178 CTRL-C pressed:
179
180 Sep 29 19:02:05.230238: CTRL-EVENT-TERMINATING - signal 2 received
181 Sep 29 19:02:05.230337: Removing interface ath0
182 Sep 29 19:02:05.230407: State: ASSOCIATING -> DISCONNECTED
183 Sep 29 19:02:05.230511: No keys have been configured - skip key clearing
184 Sep 29 19:02:05.230580: EAPOL: External notification - portEnabled=0
185 Sep 29 19:02:05.230667: EAPOL: External notification - portValid=0
186 Sep 29 19:02:05.230752: wpa_driver_madwifi_set_drop_unencrypted: enabled=0
187 Sep 29 19:02:05.230832: wpa_driver_madwifi_set_countermeasures: enabled=0
188 Sep 29 19:02:05.230912: No keys have been configured - skip key clearing
189 Sep 29 19:02:05.271764: Removed BSSID 00:00:00:00:00:00 from blacklist (clear)
190 Sep 29 19:02:05.271983: Removed BSSID 00:1f:c5:e4:95:de from blacklist (clear)
191 Sep 29 19:02:05.272224: Cancelling scan request
192