Re: kern/51797: iwm(4) does not work after if_iwm.c rev. 1.45

To: nonaka%NetBSD.org@localhost, gnats-admin%netbsd.org@localhost, netbsd-bugs%netbsd.org@localhost, ryoon%NetBSD.org@localhost
Subject: Re: kern/51797: iwm(4) does not work after if_iwm.c rev. 1.45
From: Ryo ONODERA <ryo_on%yk.rim.or.jp@localhost>
Date: Thu, 19 Jan 2017 13:55:01 +0000 (UTC)
The following reply was made to PR kern/51797; it has been noted by GNATS.

From: Ryo ONODERA <ryo_on%yk.rim.or.jp@localhost>
To: nonakap%gmail.com@localhost
Cc: gnats-bugs%netbsd.org@localhost
Subject: Re: kern/51797: iwm(4) does not work after if_iwm.c rev. 1.45
Date: Thu, 19 Jan 2017 22:54:47 +0900 (JST)

 From: Kimihiro Nonaka <nonakap%gmail.com@localhost>, Date: Sat, 14 Jan 2017 15:58:43 +0900
 
 > 2017-01-14 15:35 GMT+09:00 Kimihiro Nonaka <nonakap%gmail.com@localhost>:
 > 
 >>> And it cannot connect to Android .11g AP like before.
 >>
 >> Could you tell me Android AP setting?
 > 
 > And could you send wpa_supplicant.conf (please mask psk) and output of
 > `wpa_supplicant -dd -i iwm -c <your wpa_supplicant.conf>'.
 
 Hi,
 
 # I will test if_iwm.c r1.65 soon.
 
 Here is my config file:
 $ cat /opt/share/wpa_supplicant-xperia.conf
 ctrl_interface=/var/run/wpa_supplicant
 ctrl_interface_group=wheel
 network={
 	ssid="xterm"
 	key_mgmt=WPA-PSK
 	psk="***"
 }
 
 
 Here is the output of wap_supplicant:
 
 $ sudo wpa_supplicant -dd -i iwm0 -c /opt/share/wpa_supplicant-xperia.conf
 wpa_supplicant v2.6
 Successfully initialized wpa_supplicant
 Initializing interface 'iwm0' conf '/opt/share/wpa_supplicant-xperia.conf' driver 'default' ctrl_interface 'N/A' bridge 'N/A'
 Configuration file '/opt/share/wpa_supplicant-xperia.conf' -> '/opt/share/wpa_supplicant-xperia.conf'
 Reading configuration file '/opt/share/wpa_supplicant-xperia.conf'
 ctrl_interface='/var/run/wpa_supplicant'
 ctrl_interface_group='wheel'
 Line: 3 - start of a new network block
 ssid - hexdump_ascii(len=5):
      78 74 65 72 6d                                    xterm
 key_mgmt: 0x2
 PSK (ASCII passphrase) - hexdump_ascii(len=13): [REMOVED]
 PSK (from passphrase) - hexdump(len=32): [REMOVED]
 Priority group 0
    id=0 ssid='xterm'
 Add interface iwm0 to a new radio N/A
 iwm0: Own MAC address: 5c:e0:c5:a8:88:ab
 bsd_set_key: alg=0 addr=0x0 key_idx=0 set_tx=0 seq_len=0 key_len=0
 bsd_del_key: key_idx=0
 bsd_set_key: alg=0 addr=0x0 key_idx=1 set_tx=0 seq_len=0 key_len=0
 bsd_del_key: key_idx=1
 bsd_set_key: alg=0 addr=0x0 key_idx=2 set_tx=0 seq_len=0 key_len=0
 bsd_del_key: key_idx=2
 bsd_set_key: alg=0 addr=0x0 key_idx=3 set_tx=0 seq_len=0 key_len=0
 bsd_del_key: key_idx=3
 wpa_driver_bsd_set_countermeasures: enabled=0
 iwm0: RSN: flushing PMKID list in the driver
 iwm0: Setting scan request: 0.100000 sec
 ENGINE: Loading dynamic engine
 ENGINE: Loading dynamic engine
 EAPOL: SUPP_PAE entering state DISCONNECTED
 EAPOL: Supplicant port status: Unauthorized
 EAPOL: KEY_RX entering state NO_KEY_RECEIVE
 EAPOL: SUPP_BE entering state INITIALIZE
 EAP: EAP entering state DISABLED
 ctrl_interface_group=0 (from group name 'wheel')
 iwm0: Added interface iwm0
 iwm0: State: DISCONNECTED -> DISCONNECTED
 iwm0: State: DISCONNECTED -> SCANNING
 iwm0: Starting AP scan for wildcard SSID
 iwm0: Add radio work 'scan'@0x73c4f39ec140
 iwm0: First radio work item in the queue - schedule start immediately
 iwm0: Starting radio work 'scan'@0x73c4f39ec140 after 0.000011 second wait
 wpa_driver_bsd_set_wpa: enabled=1
 wpa_driver_bsd_set_wpa_internal: wpa=3 privacy=1
 EAPOL: disable timer tick
 iwm0: Event SCAN_RESULTS (3) received
 Received 624 bytes of scan results (7 BSSes)
 iwm0: BSS: Start scan result update 1
 iwm0: BSS: Add new id 0 BSSID 88:57:ee:36:87:30 SSID 'Buffalo-G-873E' freq 2422
 iwm0: BSS: Add new id 1 BSSID a4:12:42:67:d4:32 SSID 'SWEETS3' freq 2452
 iwm0: BSS: Add new id 2 BSSID 10:6f:3f:28:dc:d5 SSID '' freq 5200
 iwm0: BSS: Add new id 3 BSSID 10:6f:3f:28:dc:d4 SSID 'SWEETS2' freq 2417
 iwm0: BSS: Add new id 4 BSSID bc:6e:64:88:25:0b SSID 'xterm' freq 2417
 iwm0: BSS: Add new id 5 BSSID b6:12:42:67:d4:32 SSID '\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00' freq 2457
 iwm0: BSS: Add new id 6 BSSID 00:00:00:00:00:00 SSID '' freq 5200
 BSS: last_scan_res_used=7/32
 iwm0: New scan results available (own=0 ext=0)
 iwm0: Radio work 'scan'@0x73c4f39ec140 done in 5.534076 seconds
 iwm0: radio_work_free('scan'@0x73c4f39ec140: num_active_works --> 0
 iwm0: Selecting BSS from priority group 0
 iwm0: 0: 88:57:ee:36:87:30 ssid='Buffalo-G-873E' wpa_ie_len=0 rsn_ie_len=20 caps=0x11 level=94 freq=2422
 iwm0:    skip - SSID mismatch
 iwm0: 1: a4:12:42:67:d4:32 ssid='SWEETS3' wpa_ie_len=22 rsn_ie_len=0 caps=0x31 level=87 freq=2452
 iwm0:    skip - SSID mismatch
 iwm0: 2: 10:6f:3f:28:dc:d5 ssid='' wpa_ie_len=26 rsn_ie_len=0 caps=0x11 level=69 freq=5200
 iwm0:    skip - SSID not known
 iwm0: 3: 10:6f:3f:28:dc:d4 ssid='SWEETS2' wpa_ie_len=26 rsn_ie_len=0 caps=0x31 level=53 freq=2417
 iwm0:    skip - SSID mismatch
 iwm0: 4: bc:6e:64:88:25:0b ssid='xterm' wpa_ie_len=0 rsn_ie_len=20 caps=0x31 level=36 freq=2417
 iwm0:    selected based on RSN IE
 iwm0:    selected BSS bc:6e:64:88:25:0b ssid='xterm'
 iwm0: Considering connect request: reassociate: 0  selected: bc:6e:64:88:25:0b  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: SCANNING  ssid=0x73c4f3919800  current_ssid=0x0
 iwm0: Request association with bc:6e:64:88:25:0b
 iwm0: Add radio work 'connect'@0x73c4f39ec140
 iwm0: First radio work item in the queue - schedule start immediately
 iwm0: Starting radio work 'connect'@0x73c4f39ec140 after 0.000007 second wait
 iwm0: Trying to associate with bc:6e:64:88:25:0b (SSID='xterm' freq=2417 MHz)
 iwm0: Cancelling scan request
 iwm0: WPA: clearing own WPA/RSN IE
 iwm0: Automatic auth_alg selection: 0x1
 RSN: PMKSA cache search - network_ctx=0x73c4f3919800 try_opportunistic=0
 RSN: Search for BSSID bc:6e:64:88:25:0b
 RSN: No PMKSA cache entry found
 iwm0: RSN: using IEEE 802.11i/D9.0
 iwm0: WPA: Selected cipher suites: group 16 pairwise 16 key_mgmt 2 proto 2
 iwm0: WPA: clearing AP WPA IE
 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 0c 00
 iwm0: WPA: using GTK CCMP
 iwm0: WPA: using PTK CCMP
 iwm0: WPA: using KEY_MGMT WPA-PSK
 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
 iwm0: State: SCANNING -> ASSOCIATING
 Limit connection to BSSID bc:6e:64:88:25:0b freq=2417 MHz based on scan results (bssid_set=0)
 wpa_driver_bsd_associate: ssid 'xterm' wpa ie len 22 pairwise 16 group 16 key mgmt 2
 wpa_driver_bsd_set_drop_unencrypted: enabled=1
 wpa_driver_bsd_associate: set PRIVACY 1
 iwm0: Setting authentication timeout: 10 sec 0 usec
 EAPOL: External notification - EAP success=0
 EAPOL: External notification - EAP fail=0
 EAPOL: External notification - portControl=Auto
 iwm0: Event ASSOC (0) received
 iwm0: State: ASSOCIATING -> ASSOCIATED
 iwm0: Associated to a new BSS: BSSID=bc:6e:64:88:25:0b
 iwm0: Associated with bc:6e:64:88:25:0b
 iwm0: WPA: Association event - clear replay counter
 iwm0: WPA: Clear old PTK
 EAPOL: External notification - portEnabled=0
 EAPOL: External notification - portValid=0
 EAPOL: External notification - EAP success=0
 EAPOL: External notification - portEnabled=1
 EAPOL: SUPP_PAE entering state CONNECTING
 EAPOL: enable timer tick
 EAPOL: SUPP_BE entering state IDLE
 iwm0: Setting authentication timeout: 10 sec 0 usec
 iwm0: Cancelling scan request
 iwm0: RX EAPOL from bc:6e:64:88:25:0b
 RX EAPOL - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 01 c8 33 32 f0 3e 31 c4 64 0f 8c 0a 00 d3 16 bd 7d 02 0e 4e 64 28 93 ae 4e bc 37 84 66 10 0b 81 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
 iwm0: Setting authentication timeout: 10 sec 0 usec
 iwm0: IEEE 802.1X RX: version=2 type=3 length=95
 WPA: RX EAPOL-Key - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 01 c8 33 32 f0 3e 31 c4 64 0f 8c 0a 00 d3 16 bd 7d 02 0e 4e 64 28 93 ae 4e bc 37 84 66 10 0b 81 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
 iwm0:   EAPOL-Key type=2
 iwm0:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
 iwm0:   key_length=16 key_data_length=0
   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 01
   key_nonce - hexdump(len=32): c8 33 32 f0 3e 31 c4 64 0f 8c 0a 00 d3 16 bd 7d 02 0e 4e 64 28 93 ae 4e bc 37 84 66 10 0b 81 02
   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
   key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 iwm0: State: ASSOCIATED -> 4WAY_HANDSHAKE
 iwm0: WPA: RX message 1 of 4-Way Handshake from bc:6e:64:88:25:0b (ver=2)
 RSN: msg 1/4 key data - hexdump(len=0):
 Get randomness: len=32 entropy=8
 WPA: Renewed SNonce - hexdump(len=32): c9 b2 67 45 ac 40 2e 21 77 db 84 20 ad 87 14 fe 18 11 4a b7 f9 93 62 fd 3c 23 60 c8 c0 ae 14 2f
 WPA: PTK derivation - A1=5c:e0:c5:a8:88:ab A2=bc:6e:64:88:25:0b
 WPA: Nonce1 - hexdump(len=32): c9 b2 67 45 ac 40 2e 21 77 db 84 20 ad 87 14 fe 18 11 4a b7 f9 93 62 fd 3c 23 60 c8 c0 ae 14 2f
 WPA: Nonce2 - hexdump(len=32): c8 33 32 f0 3e 31 c4 64 0f 8c 0a 00 d3 16 bd 7d 02 0e 4e 64 28 93 ae 4e bc 37 84 66 10 0b 81 02
 WPA: PMK - hexdump(len=32): [REMOVED]
 WPA: PTK - hexdump(len=48): [REMOVED]
 WPA: KCK - hexdump(len=16): [REMOVED]
 WPA: KEK - hexdump(len=16): [REMOVED]
 WPA: TK - hexdump(len=16): [REMOVED]
 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
 WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 01
 iwm0: WPA: Sending EAPOL-Key 2/4
 WPA: KCK - hexdump(len=16): [REMOVED]
 WPA: Derived Key MIC - hexdump(len=16): b3 f4 cc 40 29 82 df 5c 69 ea c0 2e 52 5d d7 1a
 WPA: TX EAPOL-Key - hexdump(len=121): 01 03 00 75 02 01 0a 00 00 00 00 00 00 00 00 00 01 c9 b2 67 45 ac 40 2e 21 77 db 84 20 ad 87 14 fe 18 11 4a b7 f9 93 62 fd 3c 23 60 c8 c0 ae 14 2f 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 b3 f4 cc 40 29 82 df 5c 69 ea c0 2e 52 5d d7 1a 00 16 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
 iwm0: RX EAPOL from bc:6e:64:88:25:0b
 RX EAPOL - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 02 c8 33 32 f0 3e 31 c4 64 0f 8c 0a 00 d3 16 bd 7d 02 0e 4e 64 28 93 ae 4e bc 37 84 66 10 0b 81 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
 iwm0: IEEE 802.1X RX: version=2 type=3 length=95
 WPA: RX EAPOL-Key - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 02 c8 33 32 f0 3e 31 c4 64 0f 8c 0a 00 d3 16 bd 7d 02 0e 4e 64 28 93 ae 4e bc 37 84 66 10 0b 81 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
 iwm0:   EAPOL-Key type=2
 iwm0:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
 iwm0:   key_length=16 key_data_length=0
   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 02
   key_nonce - hexdump(len=32): c8 33 32 f0 3e 31 c4 64 0f 8c 0a 00 d3 16 bd 7d 02 0e 4e 64 28 93 ae 4e bc 37 84 66 10 0b 81 02
   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
   key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 iwm0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
 iwm0: WPA: RX message 1 of 4-Way Handshake from bc:6e:64:88:25:0b (ver=2)
 RSN: msg 1/4 key data - hexdump(len=0):
 WPA: PTK derivation - A1=5c:e0:c5:a8:88:ab A2=bc:6e:64:88:25:0b
 WPA: Nonce1 - hexdump(len=32): c9 b2 67 45 ac 40 2e 21 77 db 84 20 ad 87 14 fe 18 11 4a b7 f9 93 62 fd 3c 23 60 c8 c0 ae 14 2f
 WPA: Nonce2 - hexdump(len=32): c8 33 32 f0 3e 31 c4 64 0f 8c 0a 00 d3 16 bd 7d 02 0e 4e 64 28 93 ae 4e bc 37 84 66 10 0b 81 02
 WPA: PMK - hexdump(len=32): [REMOVED]
 WPA: PTK - hexdump(len=48): [REMOVED]
 WPA: KCK - hexdump(len=16): [REMOVED]
 WPA: KEK - hexdump(len=16): [REMOVED]
 WPA: TK - hexdump(len=16): [REMOVED]
 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
 WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 02
 iwm0: WPA: Sending EAPOL-Key 2/4
 WPA: KCK - hexdump(len=16): [REMOVED]
 WPA: Derived Key MIC - hexdump(len=16): 4d 3f e3 45 32 f8 ab 44 58 5e 36 36 41 7a 40 32
 WPA: TX EAPOL-Key - hexdump(len=121): 01 03 00 75 02 01 0a 00 00 00 00 00 00 00 00 00 02 c9 b2 67 45 ac 40 2e 21 77 db 84 20 ad 87 14 fe 18 11 4a b7 f9 93 62 fd 3c 23 60 c8 c0 ae 14 2f 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 4d 3f e3 45 32 f8 ab 44 58 5e 36 36 41 7a 40 32 00 16 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
 iwm0: Event DISASSOC (1) received
 iwm0: Disassociation notification
 iwm0: CTRL-EVENT-DISCONNECTED bssid=bc:6e:64:88:25:0b reason=0
 iwm0: WPA: 4-Way Handshake failed - pre-shared key may be incorrect
 iwm0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="xterm" auth_failures=1 duration=10 reason=WRONG_KEY
 iwm0: Auto connect enabled: try to reconnect (wps=0/0 wpa_state=7)
 iwm0: Setting scan request: 0.100000 sec
 iwm0: Radio work 'connect'@0x73c4f39ec140 done in 1.152498 seconds
 iwm0: radio_work_free('connect'@0x73c4f39ec140: num_active_works --> 0
 Added BSSID bc:6e:64:88:25:0b into blacklist
 iwm0: Blacklist count 1 --> request scan in 100 ms
 iwm0: Ignore new scan request for 0.100000 sec since an earlier request is scheduled to trigger sooner
 iwm0: WPA: Clear old PMK and PTK
 iwm0: Disconnect event - remove keys
 iwm0: State: 4WAY_HANDSHAKE -> DISCONNECTED
 EAPOL: External notification - portEnabled=0
 EAPOL: SUPP_PAE entering state DISCONNECTED
 EAPOL: Supplicant port status: Unauthorized
 EAPOL: SUPP_BE entering state INITIALIZE
 EAPOL: External notification - portValid=0
 EAPOL: External notification - EAP success=0
 iwm0: State: DISCONNECTED -> SCANNING
 iwm0: Starting AP scan for wildcard SSID
 iwm0: Add radio work 'scan'@0x73c4f39ec140
 iwm0: First radio work item in the queue - schedule start immediately
 iwm0: Starting radio work 'scan'@0x73c4f39ec140 after 0.000007 second wait
 wpa_driver_bsd_set_wpa: enabled=1
 wpa_driver_bsd_set_wpa_internal: wpa=3 privacy=1
 EAPOL: startWhen --> 0
 EAPOL: disable timer tick
 iwm0: Event SCAN_RESULTS (3) received
 Received 520 bytes of scan results (6 BSSes)
 iwm0: BSS: Start scan result update 2
 BSS: a4:12:42:67:d4:32 changed freq 2452 --> 2457
 BSS: last_scan_res_used=6/32
 iwm0: New scan results available (own=0 ext=0)
 iwm0: Radio work 'scan'@0x73c4f39ec140 done in 5.533930 seconds
 iwm0: radio_work_free('scan'@0x73c4f39ec140: num_active_works --> 0
 iwm0: Postpone network selection by 4 seconds since all networks are disabled
 iwm0: Try to associate due to network getting re-enabled
 iwm0: CTRL-EVENT-SSID-REENABLED id=0 ssid="xterm"
 iwm0: Selecting BSS from priority group 0
 iwm0: 0: a4:12:42:67:d4:32 ssid='SWEETS3' wpa_ie_len=22 rsn_ie_len=0 caps=0x31 level=90 freq=2457
 iwm0:    skip - SSID mismatch
 iwm0: 1: 10:6f:3f:28:dc:d5 ssid='' wpa_ie_len=26 rsn_ie_len=0 caps=0x11 level=69 freq=5200
 iwm0:    skip - SSID not known
 iwm0: 2: 10:6f:3f:28:dc:d4 ssid='SWEETS2' wpa_ie_len=26 rsn_ie_len=0 caps=0x31 level=53 freq=2417
 iwm0:    skip - SSID mismatch
 iwm0: 3: bc:6e:64:88:25:0b ssid='xterm' wpa_ie_len=0 rsn_ie_len=20 caps=0x31 level=36 freq=2417
 iwm0:    skip - blacklisted (count=1 limit=0)
 iwm0: 4: b6:12:42:67:d4:32 ssid='\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00' wpa_ie_len=0 rsn_ie_len=0 caps=0x31 level=90 freq=2457
 iwm0:    skip - SSID mismatch
 iwm0: 5: 00:00:00:00:00:00 ssid='' wpa_ie_len=0 rsn_ie_len=0 caps=0x0 level=0 freq=5200
 iwm0:    skip - SSID not known
 iwm0: No APs found - clear blacklist and try again
 Removed BSSID bc:6e:64:88:25:0b from blacklist (clear)
 iwm0: Selecting BSS from priority group 0
 iwm0: 0: a4:12:42:67:d4:32 ssid='SWEETS3' wpa_ie_len=22 rsn_ie_len=0 caps=0x31 level=90 freq=2457
 iwm0:    skip - SSID mismatch
 iwm0: 1: 10:6f:3f:28:dc:d5 ssid='' wpa_ie_len=26 rsn_ie_len=0 caps=0x11 level=69 freq=5200
 iwm0:    skip - SSID not known
 iwm0: 2: 10:6f:3f:28:dc:d4 ssid='SWEETS2' wpa_ie_len=26 rsn_ie_len=0 caps=0x31 level=53 freq=2417
 iwm0:    skip - SSID mismatch
 iwm0: 3: bc:6e:64:88:25:0b ssid='xterm' wpa_ie_len=0 rsn_ie_len=20 caps=0x31 level=36 freq=2417
 iwm0:    selected based on RSN IE
 iwm0:    selected BSS bc:6e:64:88:25:0b ssid='xterm'
 iwm0: Considering connect request: reassociate: 0  selected: bc:6e:64:88:25:0b  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: SCANNING  ssid=0x73c4f3919800  current_ssid=0x0
 iwm0: Request association with bc:6e:64:88:25:0b
 iwm0: Re-association to the same ESS
 iwm0: Add radio work 'connect'@0x73c4f39ec140
 iwm0: First radio work item in the queue - schedule start immediately
 iwm0: Starting radio work 'connect'@0x73c4f39ec140 after 0.000004 second wait
 iwm0: Trying to associate with bc:6e:64:88:25:0b (SSID='xterm' freq=2417 MHz)
 iwm0: Cancelling scan request
 iwm0: WPA: clearing own WPA/RSN IE
 iwm0: Automatic auth_alg selection: 0x1
 RSN: PMKSA cache search - network_ctx=0x73c4f3919800 try_opportunistic=0
 RSN: Search for BSSID bc:6e:64:88:25:0b
 RSN: No PMKSA cache entry found
 iwm0: RSN: using IEEE 802.11i/D9.0
 iwm0: WPA: Selected cipher suites: group 16 pairwise 16 key_mgmt 2 proto 2
 iwm0: WPA: clearing AP WPA IE
 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 0c 00
 iwm0: WPA: using GTK CCMP
 iwm0: WPA: using PTK CCMP
 iwm0: WPA: using KEY_MGMT WPA-PSK
 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
 iwm0: State: SCANNING -> ASSOCIATING
 Limit connection to BSSID bc:6e:64:88:25:0b freq=2417 MHz based on scan results (bssid_set=0)
 wpa_driver_bsd_associate: ssid 'xterm' wpa ie len 22 pairwise 16 group 16 key mgmt 2
 wpa_driver_bsd_set_drop_unencrypted: enabled=1
 wpa_driver_bsd_associate: set PRIVACY 1
 iwm0: Setting authentication timeout: 10 sec 0 usec
 EAPOL: External notification - EAP success=0
 EAPOL: External notification - EAP fail=0
 EAPOL: External notification - portControl=Auto
 iwm0: Event ASSOC (0) received
 iwm0: State: ASSOCIATING -> ASSOCIATED
 iwm0: Associated to a new BSS: BSSID=bc:6e:64:88:25:0b
 iwm0: Associated with bc:6e:64:88:25:0b
 iwm0: WPA: Association event - clear replay counter
 iwm0: WPA: Clear old PTK
 EAPOL: External notification - portEnabled=0
 EAPOL: External notification - portValid=0
 EAPOL: External notification - EAP success=0
 EAPOL: External notification - portEnabled=1
 EAPOL: SUPP_PAE entering state CONNECTING
 EAPOL: enable timer tick
 EAPOL: SUPP_BE entering state IDLE
 iwm0: Setting authentication timeout: 10 sec 0 usec
 iwm0: Cancelling scan request
 iwm0: RX EAPOL from bc:6e:64:88:25:0b
 RX EAPOL - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 01 ac f6 4c fa c9 47 1b 8b 62 94 50 42 fc a8 c6 a9 41 dd 2d 50 2e ff c3 c4 05 4d e8 25 e2 cf d3 a7 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
 iwm0: Setting authentication timeout: 10 sec 0 usec
 iwm0: IEEE 802.1X RX: version=2 type=3 length=95
 WPA: RX EAPOL-Key - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 01 ac f6 4c fa c9 47 1b 8b 62 94 50 42 fc a8 c6 a9 41 dd 2d 50 2e ff c3 c4 05 4d e8 25 e2 cf d3 a7 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
 iwm0:   EAPOL-Key type=2
 iwm0:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
 iwm0:   key_length=16 key_data_length=0
   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 01
   key_nonce - hexdump(len=32): ac f6 4c fa c9 47 1b 8b 62 94 50 42 fc a8 c6 a9 41 dd 2d 50 2e ff c3 c4 05 4d e8 25 e2 cf d3 a7
   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
   key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 iwm0: State: ASSOCIATED -> 4WAY_HANDSHAKE
 iwm0: WPA: RX message 1 of 4-Way Handshake from bc:6e:64:88:25:0b (ver=2)
 RSN: msg 1/4 key data - hexdump(len=0):
 Get randomness: len=32 entropy=7
 WPA: Renewed SNonce - hexdump(len=32): 25 4a a8 e8 db b9 c4 40 8a 17 7b 3a 96 37 86 0d 6c 4f 24 9d d4 c5 1f 5e e9 52 df a5 95 41 03 4a
 WPA: PTK derivation - A1=5c:e0:c5:a8:88:ab A2=bc:6e:64:88:25:0b
 WPA: Nonce1 - hexdump(len=32): 25 4a a8 e8 db b9 c4 40 8a 17 7b 3a 96 37 86 0d 6c 4f 24 9d d4 c5 1f 5e e9 52 df a5 95 41 03 4a
 WPA: Nonce2 - hexdump(len=32): ac f6 4c fa c9 47 1b 8b 62 94 50 42 fc a8 c6 a9 41 dd 2d 50 2e ff c3 c4 05 4d e8 25 e2 cf d3 a7
 WPA: PMK - hexdump(len=32): [REMOVED]
 WPA: PTK - hexdump(len=48): [REMOVED]
 WPA: KCK - hexdump(len=16): [REMOVED]
 WPA: KEK - hexdump(len=16): [REMOVED]
 WPA: TK - hexdump(len=16): [REMOVED]
 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
 WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 01
 iwm0: WPA: Sending EAPOL-Key 2/4
 WPA: KCK - hexdump(len=16): [REMOVED]
 WPA: Derived Key MIC - hexdump(len=16): 9d 00 79 6c 17 d9 94 1e 80 b7 90 4a e7 bc 33 3e
 WPA: TX EAPOL-Key - hexdump(len=121): 01 03 00 75 02 01 0a 00 00 00 00 00 00 00 00 00 01 25 4a a8 e8 db b9 c4 40 8a 17 7b 3a 96 37 86 0d 6c 4f 24 9d d4 c5 1f 5e e9 52 df a5 95 41 03 4a 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 9d 00 79 6c 17 d9 94 1e 80 b7 90 4a e7 bc 33 3e 00 16 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
 iwm0: RX EAPOL from bc:6e:64:88:25:0b
 RX EAPOL - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 02 ac f6 4c fa c9 47 1b 8b 62 94 50 42 fc a8 c6 a9 41 dd 2d 50 2e ff c3 c4 05 4d e8 25 e2 cf d3 a7 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
 iwm0: IEEE 802.1X RX: version=2 type=3 length=95
 WPA: RX EAPOL-Key - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 02 ac f6 4c fa c9 47 1b 8b 62 94 50 42 fc a8 c6 a9 41 dd 2d 50 2e ff c3 c4 05 4d e8 25 e2 cf d3 a7 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
 iwm0:   EAPOL-Key type=2
 iwm0:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
 iwm0:   key_length=16 key_data_length=0
   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 02
   key_nonce - hexdump(len=32): ac f6 4c fa c9 47 1b 8b 62 94 50 42 fc a8 c6 a9 41 dd 2d 50 2e ff c3 c4 05 4d e8 25 e2 cf d3 a7
   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
   key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 iwm0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
 iwm0: WPA: RX message 1 of 4-Way Handshake from bc:6e:64:88:25:0b (ver=2)
 RSN: msg 1/4 key data - hexdump(len=0):
 WPA: PTK derivation - A1=5c:e0:c5:a8:88:ab A2=bc:6e:64:88:25:0b
 WPA: Nonce1 - hexdump(len=32): 25 4a a8 e8 db b9 c4 40 8a 17 7b 3a 96 37 86 0d 6c 4f 24 9d d4 c5 1f 5e e9 52 df a5 95 41 03 4a
 WPA: Nonce2 - hexdump(len=32): ac f6 4c fa c9 47 1b 8b 62 94 50 42 fc a8 c6 a9 41 dd 2d 50 2e ff c3 c4 05 4d e8 25 e2 cf d3 a7
 WPA: PMK - hexdump(len=32): [REMOVED]
 WPA: PTK - hexdump(len=48): [REMOVED]
 WPA: KCK - hexdump(len=16): [REMOVED]
 WPA: KEK - hexdump(len=16): [REMOVED]
 WPA: TK - hexdump(len=16): [REMOVED]
 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
 WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 02
 iwm0: WPA: Sending EAPOL-Key 2/4
 WPA: KCK - hexdump(len=16): [REMOVED]
 WPA: Derived Key MIC - hexdump(len=16): ce 48 aa cf 5e e3 2a 6e d5 87 ec 3f 7c fb 25 98
 WPA: TX EAPOL-Key - hexdump(len=121): 01 03 00 75 02 01 0a 00 00 00 00 00 00 00 00 00 02 25 4a a8 e8 db b9 c4 40 8a 17 7b 3a 96 37 86 0d 6c 4f 24 9d d4 c5 1f 5e e9 52 df a5 95 41 03 4a 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 ce 48 aa cf 5e e3 2a 6e d5 87 ec 3f 7c fb 25 98 00 16 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
 iwm0: Event DISASSOC (1) received
 iwm0: Disassociation notification
 iwm0: CTRL-EVENT-DISCONNECTED bssid=bc:6e:64:88:25:0b reason=0
 iwm0: WPA: 4-Way Handshake failed - pre-shared key may be incorrect
 iwm0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="xterm" auth_failures=2 duration=20 reason=WRONG_KEY
 iwm0: Auto connect enabled: try to reconnect (wps=0/0 wpa_state=7)
 iwm0: Setting scan request: 0.100000 sec
 iwm0: Radio work 'connect'@0x73c4f39ec140 done in 1.156160 seconds
 iwm0: radio_work_free('connect'@0x73c4f39ec140: num_active_works --> 0
 Added BSSID bc:6e:64:88:25:0b into blacklist
 iwm0: Blacklist count 2 --> request scan in 500 ms
 iwm0: Ignore new scan request for 0.500000 sec since an earlier request is scheduled to trigger sooner
 iwm0: WPA: Clear old PMK and PTK
 iwm0: Disconnect event - remove keys
 iwm0: State: 4WAY_HANDSHAKE -> DISCONNECTED
 EAPOL: External notification - portEnabled=0
 EAPOL: SUPP_PAE entering state DISCONNECTED
 EAPOL: Supplicant port status: Unauthorized
 EAPOL: SUPP_BE entering state INITIALIZE
 EAPOL: External notification - portValid=0
 EAPOL: External notification - EAP success=0
 iwm0: State: DISCONNECTED -> SCANNING
 iwm0: Starting AP scan for wildcard SSID
 iwm0: Add radio work 'scan'@0x73c4f39ec140
 iwm0: First radio work item in the queue - schedule start immediately
 iwm0: Starting radio work 'scan'@0x73c4f39ec140 after 0.000006 second wait
 wpa_driver_bsd_set_wpa: enabled=1
 wpa_driver_bsd_set_wpa_internal: wpa=3 privacy=1
 EAPOL: startWhen --> 0
 EAPOL: disable timer tick
 ^Ciwm0: Removing interface iwm0
 iwm0: Request to deauthenticate - bssid=00:00:00:00:00:00 pending_bssid=00:00:00:00:00:00 reason=3 state=SCANNING
 iwm0: State: SCANNING -> DISCONNECTED
 EAPOL: External notification - portEnabled=0
 EAPOL: External notification - portValid=0
 wpa_driver_bsd_set_countermeasures: enabled=0
 iwm0: WPA: Clear old PMK and PTK
 Removed BSSID bc:6e:64:88:25:0b from blacklist (clear)
 iwm0: BSS: Remove id 0 BSSID 88:57:ee:36:87:30 SSID 'Buffalo-G-873E' due to wpa_bss_flush
 iwm0: BSS: Remove id 1 BSSID a4:12:42:67:d4:32 SSID 'SWEETS3' due to wpa_bss_flush
 iwm0: BSS: Remove id 2 BSSID 10:6f:3f:28:dc:d5 SSID '' due to wpa_bss_flush
 iwm0: BSS: Remove id 3 BSSID 10:6f:3f:28:dc:d4 SSID 'SWEETS2' due to wpa_bss_flush
 iwm0: BSS: Remove id 4 BSSID bc:6e:64:88:25:0b SSID 'xterm' due to wpa_bss_flush
 iwm0: BSS: Remove id 5 BSSID b6:12:42:67:d4:32 SSID '\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00' due to wpa_bss_flush
 iwm0: BSS: Remove id 6 BSSID 00:00:00:00:00:00 SSID '' due to wpa_bss_flush
 iwm0: Cancelling scan request
 iwm0: Cancelling authentication timeout
 Remove interface iwm0 from radio
 iwm0: Remove radio work 'scan'@0x73c4f39ec140 (started)
 iwm0: radio_work_free('scan'@0x73c4f39ec140: num_active_works --> 0
 Remove radio
 wpa_driver_bsd_set_wpa: enabled=0
 wpa_driver_bsd_set_wpa_internal: wpa=0 privacy=0
 wpa_driver_bsd_set_wpa_internal: wpa=0 privacy=0
 
 
 
 > Regards,
 > -- 
 > Kimihiro Nonaka
Prev by Date: Re: kern/51797: iwm(4) does not work after if_iwm.c rev. 1.45
Next by Date: Re: kern/51797: iwm(4) does not work after if_iwm.c rev. 1.45
Previous by Thread: Re: kern/51797: iwm(4) does not work after if_iwm.c rev. 1.45
Next by Thread: Re: kern/51797: iwm(4) does not work after if_iwm.c rev. 1.45
Indexes:
Home | Main Index | Thread Index | Old Index