odd state reached when AP deauths you after assoc

odd state reached when AP deauths you after assoc

[Luis R. Rodriguez]

I ran into this when ath5k with wpa_supplicant with config file with
a wrong password against a Cisco AP. It seems the Cisco AP auths you
and lets you assoc but later it deauths you -- I guess after it
determines you are auth credentials failed. When this happens I get:

mcgrof@tux ~ $ iw dev wlan0 link
Authenticated with 00:0b:85:5b:8d:6c (on wlan0)
Not connected.

The log *after* this is below. I'll try to reproduce again, I can reproduce
all the time.

[  171.905675] wlan0: deauthenticating from 00:0b:85:5b:a6:ec by local choice (reason=3)
[  171.929065] ------------[ cut here ]------------
[  171.929106] WARNING: at net/mac80211/scan.c:267 ieee80211_scan_completed+0x240/0x270 [mac80211]()
[  171.929112] Hardware name: 7660A14
[  171.929117] Modules linked in: i915 drm_kms_helper drm i2c_algo_bit binfmt_misc ppdev bridge stp bnep lp parport snd_hda_codec_analog snd_hda_intel snd_hda_codec snd_pcm_oss snd_mixer_oss snd_pcm arc4 snd_seq_dummy snd_seq_oss snd_seq_midi snd_rawmidi ath5k snd_seq_midi_event snd_seq joydev snd_timer snd_seq_device mac80211 ath snd pcmcia soundcore cfg80211 thinkpad_acpi video intel_agp psmouse snd_page_alloc nvram led_class yenta_socket rsrc_nonstatic pcmcia_core output agpgart pcspkr serio_raw btusb iTCO_wdt iTCO_vendor_support ohci1394 ieee1394 e1000e
[  171.929226] Pid: 4022, comm: wpa_supplicant Not tainted 2.6.32-rc5-wl #27
[  171.929231] Call Trace:
[  171.929245]  [<c05a3a23>] ? printk+0x1d/0x22
[  171.929269]  [<f8379040>] ? ieee80211_scan_completed+0x240/0x270 [mac80211]
[  171.929281]  [<c0146121>] warn_slowpath_common+0x71/0xd0
[  171.929306]  [<f8379040>] ? ieee80211_scan_completed+0x240/0x270 [mac80211]
[  171.929316]  [<c014619a>] warn_slowpath_null+0x1a/0x20
[  171.929340]  [<f8379040>] ieee80211_scan_completed+0x240/0x270 [mac80211]
[  171.929363]  [<f83790b9>] ieee80211_scan_cancel+0x49/0x80 [mac80211]
[  171.929388]  [<f83826ca>] ieee80211_stop+0x59a/0x5b0 [mac80211]
[  171.929399]  [<c04e513e>] ? dev_deactivate+0x17e/0x1a0
[  171.929412]  [<c04d34cb>] dev_close+0x6b/0xc0
[  171.929421]  [<c05a6733>] ? _spin_unlock_bh+0x13/0x20
[  171.929430]  [<c04d150f>] ? dev_set_rx_mode+0x2f/0x40
[  171.929438]  [<c04d2d44>] dev_change_flags+0x84/0x1d0
[  171.929448]  [<c05207ea>] devinet_ioctl+0x54a/0x600
[  171.929456]  [<c04d489d>] ? dev_ioctl+0x28d/0x530
[  171.929465]  [<c0521c6a>] inet_ioctl+0x9a/0xc0
[  171.929475]  [<c04c25c8>] sock_ioctl+0x68/0x270
[  171.929483]  [<c04c2560>] ? sock_ioctl+0x0/0x270
[  171.929493]  [<c021bb9d>] vfs_ioctl+0x2d/0x90
[  171.929501]  [<c021bd62>] do_vfs_ioctl+0x72/0x5f0
[  171.929510]  [<c02267bf>] ? mntput_no_expire+0x1f/0xd0
[  171.929520]  [<c020c2ca>] ? __fput+0x17a/0x1f0
[  171.929529]  [<c020c367>] ? fput+0x27/0x30
[  171.929537]  [<c0207aec>] ? filp_close+0x4c/0x80
[  171.929545]  [<c021c34b>] sys_ioctl+0x6b/0x70
[  171.929554]  [<c01030dc>] sysenter_do_call+0x12/0x28
[  171.929560] ---[ end trace d6c0a8110c16e049 ]---
[  171.937047] phy0: device now idle
[  171.938704] ------------[ cut here ]------------
[  171.938733] WARNING: at net/wireless/core.c:619 wdev_cleanup_work+0xbf/0xe0 [cfg80211]()
[  171.938741] Hardware name: 7660A14
[  171.938746] Modules linked in: i915 drm_kms_helper drm i2c_algo_bit binfmt_misc ppdev bridge stp bnep lp parport snd_hda_codec_analog snd_hda_intel snd_hda_codec snd_pcm_oss snd_mixer_oss snd_pcm arc4 snd_seq_dummy snd_seq_oss snd_seq_midi snd_rawmidi ath5k snd_seq_midi_event snd_seq joydev snd_timer snd_seq_device mac80211 ath snd pcmcia soundcore cfg80211 thinkpad_acpi video intel_agp psmouse snd_page_alloc nvram led_class yenta_socket rsrc_nonstatic pcmcia_core output agpgart pcspkr serio_raw btusb iTCO_wdt iTCO_vendor_support ohci1394 ieee1394 e1000e
[  171.938873] Pid: 9, comm: events/0 Tainted: G        W  2.6.32-rc5-wl #27
[  171.938880] Call Trace:
[  171.938892]  [<c05a3a23>] ? printk+0x1d/0x22
[  171.938910]  [<f82cd18f>] ? wdev_cleanup_work+0xbf/0xe0 [cfg80211]
[  171.938922]  [<c0146121>] warn_slowpath_common+0x71/0xd0
[  171.938939]  [<f82cd18f>] ? wdev_cleanup_work+0xbf/0xe0 [cfg80211]
[  171.938950]  [<c014619a>] warn_slowpath_null+0x1a/0x20
[  171.938967]  [<f82cd18f>] wdev_cleanup_work+0xbf/0xe0 [cfg80211]
[  171.938981]  [<c01639b4>] worker_thread+0x134/0x200
[  171.938998]  [<f82cd0d0>] ? wdev_cleanup_work+0x0/0xe0 [cfg80211]
[  171.939010]  [<c0168600>] ? autoremove_wake_function+0x0/0x50
[  171.939021]  [<c0163880>] ? worker_thread+0x0/0x200
[  171.939031]  [<c01682b4>] kthread+0x74/0x80
[  171.939041]  [<c0168240>] ? kthread+0x0/0x80
[  171.939051]  [<c0103c47>] kernel_thread_helper+0x7/0x10
[  171.939059] ---[ end trace d6c0a8110c16e04a ]---
[  171.957054] CE: hpet increasing min_delta_ns to 15000 nsec
[  173.591594] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[  173.816116] phy0: device no longer idle - scanning
[  177.440103] ------------[ cut here ]------------
[  177.440138] WARNING: at net/wireless/scan.c:88 cfg80211_scan_done+0x4b/0x50 [cfg80211]()
[  177.440145] Hardware name: 7660A14
[  177.440150] Modules linked in: i915 drm_kms_helper drm i2c_algo_bit binfmt_misc ppdev bridge stp bnep lp parport snd_hda_codec_analog snd_hda_intel snd_hda_codec snd_pcm_oss snd_mixer_oss snd_pcm arc4 snd_seq_dummy snd_seq_oss snd_seq_midi snd_rawmidi ath5k snd_seq_midi_event snd_seq joydev snd_timer snd_seq_device mac80211 ath snd pcmcia soundcore cfg80211 thinkpad_acpi video intel_agp psmouse snd_page_alloc nvram led_class yenta_socket rsrc_nonstatic pcmcia_core output agpgart pcspkr serio_raw btusb iTCO_wdt iTCO_vendor_support ohci1394 ieee1394 e1000e
[  177.440256] Pid: 1864, comm: phy0 Tainted: G        W  2.6.32-rc5-wl #27
[  177.440262] Call Trace:
[  177.440275]  [<c05a3a23>] ? printk+0x1d/0x22
[  177.440293]  [<f82d17fb>] ? cfg80211_scan_done+0x4b/0x50 [cfg80211]
[  177.440306]  [<c0146121>] warn_slowpath_common+0x71/0xd0
[  177.440322]  [<f82d17fb>] ? cfg80211_scan_done+0x4b/0x50 [cfg80211]
[  177.440332]  [<c014619a>] warn_slowpath_null+0x1a/0x20
[  177.440349]  [<f82d17fb>] cfg80211_scan_done+0x4b/0x50 [cfg80211]
[  177.440374]  [<f8378e54>] ieee80211_scan_completed+0x54/0x270 [mac80211]
[  177.440397]  [<f8379236>] ieee80211_scan_work+0x146/0x4b0 [mac80211]
[  177.440408]  [<c01bb51d>] ? probe_workqueue_execution+0x8d/0xb0
[  177.440420]  [<c01639b4>] worker_thread+0x134/0x200
[  177.440444]  [<f83790f0>] ? ieee80211_scan_work+0x0/0x4b0 [mac80211]
[  177.440454]  [<c0168600>] ? autoremove_wake_function+0x0/0x50
[  177.440463]  [<c0163880>] ? worker_thread+0x0/0x200
[  177.440471]  [<c01682b4>] kthread+0x74/0x80
[  177.440479]  [<c0168240>] ? kthread+0x0/0x80
[  177.440488]  [<c0103c47>] kernel_thread_helper+0x7/0x10
[  177.440494] ---[ end trace d6c0a8110c16e04b ]---
[  177.443939] phy0: device now idle
[  183.714141] phy0: device no longer idle - scanning
[  187.335604] wlan0: direct probe to AP 00:0b:85:5b:a6:ec (try 1)
[  187.338695] wlan0: direct probe responded
[  187.338703] wlan0: authenticate with AP 00:0b:85:5b:a6:ec (try 1)
[  187.340329] wlan0: authenticated
[  187.340635] wlan0: associate with AP 00:0b:85:5b:a6:ec (try 1)
[  187.343385] wlan0: RX AssocResp from 00:0b:85:5b:a6:ec (capab=0x431 status=0 aid=52)
[  187.343392] wlan0: associated
[  187.343401] phy0: Allocated STA 00:0b:85:5b:a6:ec
[  187.344165] phy0: Inserted STA 00:0b:85:5b:a6:ec
[  187.344924] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[  187.345770] cfg80211: Calling CRDA for country: US
[  187.352927] cfg80211: Received country IE:
[  187.352935] cfg80211: Regulatory domain: US
[  187.352939] 	(start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[  187.352947] 	(2402000 KHz - 2477000 KHz @ 40000 KHz), (10000 mBi, 10000 mBm)
[  187.352952] cfg80211: CRDA thinks this should applied:
[  187.352956] cfg80211: Regulatory domain: US
[  187.352960] 	(start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[  187.352967] 	(2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[  187.352974] 	(5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
[  187.352980] 	(5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[  187.352987] 	(5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[  187.352994] 	(5651000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[  187.353000] 	(5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
[  187.353005] cfg80211: We intersect both of these and get:
[  187.353010] cfg80211: Regulatory domain: 98
[  187.353014] 	(start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[  187.353020] 	(2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[  187.353033] cfg80211: Disabling channel 2467 MHz on phy0 due to Country IE
[  187.353038] cfg80211: Disabling channel 2472 MHz on phy0 due to Country IE
[  187.353044] cfg80211: Disabling channel 2484 MHz on phy0 due to Country IE
[  187.353050] cfg80211: Leaving channel 5180 MHz intact on phy0 - no rule found in band on Country IE
[  187.353060] wlan0: dropped frame to 00:0b:85:5b:a6:ec (unauthorized port)
[  187.353068] cfg80211: Leaving channel 5200 MHz intact on phy0 - no rule found in band on Country IE
[  187.353075] cfg80211: Leaving channel 5220 MHz intact on phy0 - no rule found in band on Country IE
[  187.353083] cfg80211: Leaving channel 5240 MHz intact on phy0 - no rule found in band on Country IE
[  187.353091] cfg80211: Leaving channel 5260 MHz intact on phy0 - no rule found in band on Country IE
[  187.353098] cfg80211: Leaving channel 5280 MHz intact on phy0 - no rule found in band on Country IE
[  187.353106] cfg80211: Leaving channel 5300 MHz intact on phy0 - no rule found in band on Country IE
[  187.353113] cfg80211: Leaving channel 5320 MHz intact on phy0 - no rule found in band on Country IE
[  187.353121] cfg80211: Leaving channel 5500 MHz intact on phy0 - no rule found in band on Country IE
[  187.353129] cfg80211: Leaving channel 5520 MHz intact on phy0 - no rule found in band on Country IE
[  187.353136] cfg80211: Leaving channel 5540 MHz intact on phy0 - no rule found in band on Country IE
[  187.353144] cfg80211: Leaving channel 5560 MHz intact on phy0 - no rule found in band on Country IE
[  187.353151] cfg80211: Leaving channel 5580 MHz intact on phy0 - no rule found in band on Country IE
[  187.353159] cfg80211: Leaving channel 5600 MHz intact on phy0 - no rule found in band on Country IE
[  187.353167] cfg80211: Leaving channel 5620 MHz intact on phy0 - no rule found in band on Country IE
[  187.353175] cfg80211: Leaving channel 5640 MHz intact on phy0 - no rule found in band on Country IE
[  187.353183] cfg80211: Leaving channel 5660 MHz intact on phy0 - no rule found in band on Country IE
[  187.353190] cfg80211: Leaving channel 5680 MHz intact on phy0 - no rule found in band on Country IE
[  187.353198] cfg80211: Leaving channel 5700 MHz intact on phy0 - no rule found in band on Country IE
[  187.353205] cfg80211: Leaving channel 5745 MHz intact on phy0 - no rule found in band on Country IE
[  187.353213] cfg80211: Leaving channel 5765 MHz intact on phy0 - no rule found in band on Country IE
[  187.353221] cfg80211: Leaving channel 5785 MHz intact on phy0 - no rule found in band on Country IE
[  187.353228] cfg80211: Leaving channel 5805 MHz intact on phy0 - no rule found in band on Country IE
[  187.353236] cfg80211: Leaving channel 5825 MHz intact on phy0 - no rule found in band on Country IE
[  187.353253] cfg80211: Current regulatory domain updated by AP to: US
[  187.353258] 	(start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[  187.353265] 	(2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[  187.805098] wlan0: dropped frame to 00:0b:85:5b:a6:ec (unauthorized port)
[  188.804121] wlan0: dropped frame to 00:0b:85:5b:a6:ec (unauthorized port)
[  191.290511] wlan0: deauthenticated from 00:0b:85:5b:a6:ec (Reason: 1)
[  191.290536] phy0: device now idle
[  191.290573] phy0: Removed STA 00:0b:85:5b:a6:ec
[  191.321556] phy0: Destroyed STA 00:0b:85:5b:a6:ec
[  191.421927] phy0: device no longer idle - scanning
[  194.672155] wlan0: direct probe to AP 00:0b:85:5b:a6:e3 (try 1)
[  194.673139] wlan0: direct probe responded
[  194.673146] wlan0: authenticate with AP 00:0b:85:5b:a6:e3 (try 1)
[  194.674160] wlan0: authenticated
[  194.674494] wlan0: associate with AP 00:0b:85:5b:a6:e3 (try 1)
[  194.677426] wlan0: RX AssocResp from 00:0b:85:5b:a6:e3 (capab=0x11 status=0 aid=70)
[  194.677433] wlan0: associated
[  194.677442] phy0: Allocated STA 00:0b:85:5b:a6:e3
[  194.677931] phy0: Inserted STA 00:0b:85:5b:a6:e3
[  196.804059] wlan0: dropped frame to 00:0b:85:5b:a6:e3 (unauthorized port)
[  197.689989] wlan0: deauthenticated from 00:0b:85:5b:a6:e3 (Reason: 1)
[  197.690012] phy0: device now idle
[  197.690047] phy0: Removed STA 00:0b:85:5b:a6:e3
[  197.717474] phy0: Destroyed STA 00:0b:85:5b:a6:e3
[  197.805059] wlan0: no IPv6 routers present
[  197.818000] phy0: device no longer idle - scanning
[  201.079270] phy0: device now idle
[  201.084747] phy0: device no longer idle - in use
[  201.084770] wlan0: direct probe to AP 00:0b:85:5b:a6:ec (try 1)
[  201.089664] wlan0: direct probe responded
[  201.089668] wlan0: authenticate with AP 00:0b:85:5b:a6:ec (try 1)
[  201.092158] wlan0: authenticated
[  201.092452] wlan0: associate with AP 00:0b:85:5b:a6:ec (try 1)
[  201.096074] wlan0: RX AssocResp from 00:0b:85:5b:a6:ec (capab=0x431 status=0 aid=52)
[  201.096081] wlan0: associated
[  201.096090] phy0: Allocated STA 00:0b:85:5b:a6:ec
[  201.096552] phy0: Inserted STA 00:0b:85:5b:a6:ec
[  204.093552] wlan0: deauthenticated from 00:0b:85:5b:a6:ec (Reason: 1)
[  204.093575] phy0: device now idle
[  204.093612] phy0: Removed STA 00:0b:85:5b:a6:ec
[  204.113479] phy0: Destroyed STA 00:0b:85:5b:a6:ec
[  204.214013] phy0: device no longer idle - scanning
[  207.471524] phy0: device now idle
[  207.476732] phy0: device no longer idle - in use
[  207.476756] wlan0: direct probe to AP 00:0b:85:5b:a6:e3 (try 1)
[  207.477684] wlan0: direct probe responded
[  207.477687] wlan0: authenticate with AP 00:0b:85:5b:a6:e3 (try 1)
[  207.479033] wlan0: authenticated
[  207.479171] wlan0: associate with AP 00:0b:85:5b:a6:e3 (try 1)
[  207.480744] wlan0: RX AssocResp from 00:0b:85:5b:a6:e3 (capab=0x11 status=0 aid=72)
[  207.480748] wlan0: associated
[  207.480752] phy0: Allocated STA 00:0b:85:5b:a6:e3
[  207.480965] phy0: Inserted STA 00:0b:85:5b:a6:e3
[  210.489907] wlan0: deauthenticated from 00:0b:85:5b:a6:e3 (Reason: 1)
[  210.489930] phy0: device now idle
[  210.489968] phy0: Removed STA 00:0b:85:5b:a6:e3
[  210.521484] phy0: Destroyed STA 00:0b:85:5b:a6:e3
[  210.621987] phy0: device no longer idle - scanning
[  213.876178] phy0: device now idle
[  213.879982] phy0: device no longer idle - in use
[  213.880004] wlan0: direct probe to AP 00:0b:85:5b:8d:6c (try 1)
[  214.080136] wlan0: direct probe to AP 00:0b:85:5b:8d:6c (try 2)
[  214.089058] wlan0: direct probe responded
[  214.089066] wlan0: authenticate with AP 00:0b:85:5b:8d:6c (try 1)
[  214.107502] wlan0: authenticated
[  214.107916] wlan0: associate with AP 00:0b:85:5b:8d:6c (try 1)
[  214.122278] wlan0: RX AssocResp from 00:0b:85:5b:8d:6c (capab=0x401 status=17 aid=0)
[  214.122285] wlan0: AP denied association (code=17)

  Luis

Re: odd state reached when AP deauths you after assoc

[Luis R. Rodriguez]

On Wed, Oct 28, 2009 at 11:37 AM, Luis R. Rodriguez
<lrodriguez@atheros.com> wrote:
> I ran into this when ath5k with wpa_supplicant with config file with
> a wrong password against a Cisco AP. It seems the Cisco AP auths you
> and lets you assoc but later it deauths you -- I guess after it
> determines you are auth credentials failed. When this happens I get:
>
> mcgrof@tux ~ $ iw dev wlan0 link
> Authenticated with 00:0b:85:5b:8d:6c (on wlan0)
> Not connected.

So here is the log when using a wrong password against a cisco AP:

[ 1858.773080] phy0: device now idle
[ 1858.776409] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 1858.905642] phy0: device no longer idle - scanning
[ 1860.057062] cfg80211: Found new beacon on frequency: 5180 MHz (Ch 36) on phy0
[ 1860.233974] cfg80211: Found new beacon on frequency: 5200 MHz (Ch 40) on phy0
[ 1860.289658] cfg80211: Found new beacon on frequency: 5220 MHz (Ch 44) on phy0
[ 1860.401686] cfg80211: Found new beacon on frequency: 5240 MHz (Ch 48) on phy0
[ 1862.426385] cfg80211: Found new beacon on frequency: 5745 MHz (Ch
149) on phy0
[ 1862.667996] cfg80211: Found new beacon on frequency: 5785 MHz (Ch
157) on phy0
[ 1862.772666] cfg80211: Found new beacon on frequency: 5805 MHz (Ch
161) on phy0
[ 1863.016600] wlan0: direct probe to AP 00:0b:85:5b:a6:ec (try 1)
[ 1863.025332] wlan0: direct probe responded
[ 1863.025340] wlan0: authenticate with AP 00:0b:85:5b:a6:ec (try 1)
[ 1863.029490] wlan0: authenticated
[ 1863.029675] wlan0: associate with AP 00:0b:85:5b:a6:ec (try 1)
[ 1863.044240] wlan0: RX AssocResp from 00:0b:85:5b:a6:ec (capab=0x431
status=0 aid=59)
[ 1863.044248] wlan0: associated
[ 1863.044258] phy0: Allocated STA 00:0b:85:5b:a6:ec
[ 1863.045048] phy0: Inserted STA 00:0b:85:5b:a6:ec
[ 1863.045566] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[ 1863.046086] cfg80211: Calling CRDA for country: US
[ 1863.053060] wlan0: dropped frame to 00:0b:85:5b:a6:ec (unauthorized port)
[ 1863.053242] cfg80211: Received country IE:
[ 1863.053247] cfg80211: Regulatory domain: US
[ 1863.053252]  (start_freq - end_freq @ bandwidth),
(max_antenna_gain, max_eirp)
[ 1863.053260]  (2402000 KHz - 2477000 KHz @ 40000 KHz), (10000 mBi, 10000 mBm)
[ 1863.053265] cfg80211: CRDA thinks this should applied:
[ 1863.053269] cfg80211: Regulatory domain: US
[ 1863.053273]  (start_freq - end_freq @ bandwidth),
(max_antenna_gain, max_eirp)
[ 1863.053281]  (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[ 1863.053288]  (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
[ 1863.053294]  (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 1863.053301]  (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 1863.053307]  (5651000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 1863.053314]  (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
[ 1863.053319] cfg80211: We intersect both of these and get:
[ 1863.053323] cfg80211: Regulatory domain: 98
[ 1863.053327]  (start_freq - end_freq @ bandwidth),
(max_antenna_gain, max_eirp)
[ 1863.053334]  (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[ 1863.053344] cfg80211: Disabling channel 2467 MHz on phy0 due to Country IE
[ 1863.053349] cfg80211: Disabling channel 2472 MHz on phy0 due to Country IE
[ 1863.053355] cfg80211: Disabling channel 2484 MHz on phy0 due to Country IE
[ 1863.053361] cfg80211: Leaving channel 5180 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053367] cfg80211: Leaving channel 5200 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053373] cfg80211: Leaving channel 5220 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053379] cfg80211: Leaving channel 5240 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053386] cfg80211: Leaving channel 5260 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053392] cfg80211: Leaving channel 5280 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053398] cfg80211: Leaving channel 5300 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053404] cfg80211: Leaving channel 5320 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053411] cfg80211: Leaving channel 5500 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053417] cfg80211: Leaving channel 5520 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053423] cfg80211: Leaving channel 5540 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053429] cfg80211: Leaving channel 5560 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053435] cfg80211: Leaving channel 5580 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053441] cfg80211: Leaving channel 5600 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053447] cfg80211: Leaving channel 5620 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053454] cfg80211: Leaving channel 5640 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053460] cfg80211: Leaving channel 5660 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053466] cfg80211: Leaving channel 5680 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053472] cfg80211: Leaving channel 5700 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053478] cfg80211: Leaving channel 5745 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053485] cfg80211: Leaving channel 5765 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053491] cfg80211: Leaving channel 5785 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053497] cfg80211: Leaving channel 5805 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053503] cfg80211: Leaving channel 5825 MHz intact on phy0 - no
rule found in band on Country IE
[ 1863.053519] cfg80211: Current regulatory domain updated by AP to: US
[ 1863.053524]  (start_freq - end_freq @ bandwidth),
(max_antenna_gain, max_eirp)
[ 1863.053531]  (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[ 1863.296154] wlan0: dropped frame to 00:0b:85:5b:a6:ec (unauthorized port)
[ 1864.296183] wlan0: dropped frame to 00:0b:85:5b:a6:ec (unauthorized port)
[ 1866.881205] wlan0: deauthenticated from 00:0b:85:5b:a6:ec (Reason: 1)
[ 1866.881228] phy0: device now idle
[ 1866.881265] phy0: Removed STA 00:0b:85:5b:a6:ec
[ 1866.913511] phy0: Destroyed STA 00:0b:85:5b:a6:ec
[ 1867.013816] phy0: device no longer idle - scanning
[ 1870.268556] phy0: device now idle
[ 1870.272935] phy0: device no longer idle - in use
[ 1870.272957] wlan0: direct probe to AP 00:0b:85:5b:8d:6c (try 1)
[ 1870.468116] wlan0: direct probe to AP 00:0b:85:5b:8d:6c (try 2)
[ 1870.668115] wlan0: direct probe to AP 00:0b:85:5b:8d:6c (try 3)
[ 1870.672686] wlan0: direct probe responded
[ 1870.672693] wlan0: authenticate with AP 00:0b:85:5b:8d:6c (try 1)
[ 1870.674428] wlan0: authenticated
[ 1870.674602] wlan0: associate with AP 00:0b:85:5b:8d:6c (try 1)
[ 1870.677800] wlan0: RX AssocResp from 00:0b:85:5b:8d:6c (capab=0x421
status=17 aid=0)
[ 1870.677807] wlan0: AP denied association (code=17)
[ 1870.679901] wlan0: RX AssocResp from 00:0b:85:5b:8d:6c (capab=0x421
status=17 aid=0)
[ 1870.679908] wlan0: AP denied association (code=17)
[ 1873.297089] wlan0: no IPv6 routers present

This puts the device into a funky state.

This can also be reached even if the AP does not deauth you but instead just
denies association:

This puts the device into a funky state.

This can also be reached even if the AP does not deauth you but instead just
denies association:

[ 1958.579149] cfg80211: Found new beacon on frequency: 5745 MHz (Ch
149) on phy0
[ 1958.820612] cfg80211: Found new beacon on frequency: 5785 MHz (Ch
157) on phy0
[ 1958.953174] cfg80211: Found new beacon on frequency: 5805 MHz (Ch
161) on phy0
[ 1959.167831] wlan0: direct probe to AP 00:0b:85:5b:8d:6c (try 1)
[ 1959.180785] wlan0: direct probe responded
[ 1959.180793] wlan0: authenticate with AP 00:0b:85:5b:8d:6c (try 1)
[ 1959.189268] wlan0: authenticated
[ 1959.189414] wlan0: associate with AP 00:0b:85:5b:8d:6c (try 1)
[ 1959.201056] wlan0: RX AssocResp from 00:0b:85:5b:8d:6c (capab=0x401
status=17 aid=0)
[ 1959.201063] wlan0: AP denied association (code=17)

  Luis

Re: odd state reached when AP deauths you after assoc

[Johannes Berg]

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

On Wed, 2009-10-28 at 11:37 -0700, Luis R. Rodriguez wrote:
> I ran into this when ath5k with wpa_supplicant with config file with
> a wrong password against a Cisco AP. It seems the Cisco AP auths you
> and lets you assoc but later it deauths you -- I guess after it
> determines you are auth credentials failed. When this happens I get:
> 
> mcgrof@tux ~ $ iw dev wlan0 link
> Authenticated with 00:0b:85:5b:8d:6c (on wlan0)
> Not connected.

I'm guessing that you're using -Dnl80211. You need this patch, or
equivalent:
http://johannes.sipsolutions.net/patches/hostap/all/2009-10-26-12%3a59/deauth-on-disassoc.patch

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 801 bytes --]

Re: odd state reached when AP deauths you after assoc

[Luis R. Rodriguez]

On Wed, Oct 28, 2009 at 1:24 PM, Johannes Berg
<johannes@sipsolutions.net> wrote:
> On Wed, 2009-10-28 at 11:37 -0700, Luis R. Rodriguez wrote:
>> I ran into this when ath5k with wpa_supplicant with config file with
>> a wrong password against a Cisco AP. It seems the Cisco AP auths you
>> and lets you assoc but later it deauths you -- I guess after it
>> determines you are auth credentials failed. When this happens I get:
>>
>> mcgrof@tux ~ $ iw dev wlan0 link
>> Authenticated with 00:0b:85:5b:8d:6c (on wlan0)
>> Not connected.
>
> I'm guessing that you're using -Dnl80211. You need this patch, or
> equivalent:
> http://johannes.sipsolutions.net/patches/hostap/all/2009-10-26-12%3a59/deauth-on-disassoc.patch

Indeed, it fixes my woes, thanks.

  Luis

Re: odd state reached when AP deauths you after assoc

[Luis R. Rodriguez]

On Thu, Oct 29, 2009 at 1:55 PM, Luis R. Rodriguez
<lrodriguez@atheros.com> wrote:
> On Wed, Oct 28, 2009 at 1:24 PM, Johannes Berg
> <johannes@sipsolutions.net> wrote:
>> On Wed, 2009-10-28 at 11:37 -0700, Luis R. Rodriguez wrote:
>>> I ran into this when ath5k with wpa_supplicant with config file with
>>> a wrong password against a Cisco AP. It seems the Cisco AP auths you
>>> and lets you assoc but later it deauths you -- I guess after it
>>> determines you are auth credentials failed. When this happens I get:
>>>
>>> mcgrof@tux ~ $ iw dev wlan0 link
>>> Authenticated with 00:0b:85:5b:8d:6c (on wlan0)
>>> Not connected.
>>
>> I'm guessing that you're using -Dnl80211. You need this patch, or
>> equivalent:
>> http://johannes.sipsolutions.net/patches/hostap/all/2009-10-26-12%3a59/deauth-on-disassoc.patch
>
> Indeed, it fixes my woes, thanks.

Well almost, after a while of being connected it then does this:

CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
CTRL-EVENT-SCAN-RESULTS
Trying to authenticate with 00:0b:85:5b:8d:6c (SSID='ATH-GLOBAL' freq=2462 MHz)
Trying to associate with 00:0b:85:5b:8d:6c (SSID='ATH-GLOBAL' freq=2462 MHz)
Associated with 00:0b:85:5b:8d:6c
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
CTRL-EVENT-SCAN-RESULTS
Trying to authenticate with 00:0b:85:5b:9a:bc (SSID='ATH-GLOBAL' freq=2412 MHz)
Trying to associate with 00:0b:85:5b:9a:bc (SSID='ATH-GLOBAL' freq=2412 MHz)
Associated with 00:0b:85:5b:9a:bc
CTRL-EVENT-EAP-STARTED EAP authentication started
CTRL-EVENT-EAP-STARTED EAP authentication started
CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
OpenSSL: tls_connection_handshake - Failed to read possible
Application Data error:00000000:lib(0):func(0):reason(0)

And I then end up with the same:

>>> mcgrof@tux ~ $ iw dev wlan0 link
>>> Authenticated with 00:0b:85:5b:8d:6c (on wlan0)
>>> Not connected.

But this time if I hit ctrl-c it gets cleared and I can auth/assoc
fine after that. But an issue is still present.

  Luis

Re: odd state reached when AP deauths you after assoc

[Johannes Berg]

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

On Thu, 2009-10-29 at 14:19 -0700, Luis R. Rodriguez wrote:
> On Thu, Oct 29, 2009 at 1:55 PM, Luis R. Rodriguez
> <lrodriguez@atheros.com> wrote:
> > On Wed, Oct 28, 2009 at 1:24 PM, Johannes Berg
> > <johannes@sipsolutions.net> wrote:
> >> On Wed, 2009-10-28 at 11:37 -0700, Luis R. Rodriguez wrote:
> >>> I ran into this when ath5k with wpa_supplicant with config file with
> >>> a wrong password against a Cisco AP. It seems the Cisco AP auths you
> >>> and lets you assoc but later it deauths you -- I guess after it
> >>> determines you are auth credentials failed. When this happens I get:
> >>>
> >>> mcgrof@tux ~ $ iw dev wlan0 link
> >>> Authenticated with 00:0b:85:5b:8d:6c (on wlan0)
> >>> Not connected.
> >>
> >> I'm guessing that you're using -Dnl80211. You need this patch, or
> >> equivalent:
> >> http://johannes.sipsolutions.net/patches/hostap/all/2009-10-26-12%3a59/deauth-on-disassoc.patch
> >
> > Indeed, it fixes my woes, thanks.
> 
> Well almost, after a while of being connected it then does this:
> 
> CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
> CTRL-EVENT-SCAN-RESULTS
> Trying to authenticate with 00:0b:85:5b:8d:6c (SSID='ATH-GLOBAL' freq=2462 MHz)
> Trying to associate with 00:0b:85:5b:8d:6c (SSID='ATH-GLOBAL' freq=2462 MHz)
> Associated with 00:0b:85:5b:8d:6c
> CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
> CTRL-EVENT-SCAN-RESULTS
> Trying to authenticate with 00:0b:85:5b:9a:bc (SSID='ATH-GLOBAL' freq=2412 MHz)
> Trying to associate with 00:0b:85:5b:9a:bc (SSID='ATH-GLOBAL' freq=2412 MHz)
> Associated with 00:0b:85:5b:9a:bc
> CTRL-EVENT-EAP-STARTED EAP authentication started
> CTRL-EVENT-EAP-STARTED EAP authentication started
> CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
> OpenSSL: tls_connection_handshake - Failed to read possible
> Application Data error:00000000:lib(0):func(0):reason(0)
> 
> And I then end up with the same:
> 
> >>> mcgrof@tux ~ $ iw dev wlan0 link
> >>> Authenticated with 00:0b:85:5b:8d:6c (on wlan0)
> >>> Not connected.

Might be due to that bssid_changed check I was unsure about -- try
removing that.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 801 bytes --]

Re: odd state reached when AP deauths you after assoc

[Luis R. Rodriguez]

On Thu, Oct 29, 2009 at 2:28 PM, Johannes Berg
<johannes@sipsolutions.net> wrote:
> On Thu, 2009-10-29 at 14:19 -0700, Luis R. Rodriguez wrote:
>> On Thu, Oct 29, 2009 at 1:55 PM, Luis R. Rodriguez
>> <lrodriguez@atheros.com> wrote:
>> > On Wed, Oct 28, 2009 at 1:24 PM, Johannes Berg
>> > <johannes@sipsolutions.net> wrote:
>> >> On Wed, 2009-10-28 at 11:37 -0700, Luis R. Rodriguez wrote:
>> >>> I ran into this when ath5k with wpa_supplicant with config file with
>> >>> a wrong password against a Cisco AP. It seems the Cisco AP auths you
>> >>> and lets you assoc but later it deauths you -- I guess after it
>> >>> determines you are auth credentials failed. When this happens I get:
>> >>>
>> >>> mcgrof@tux ~ $ iw dev wlan0 link
>> >>> Authenticated with 00:0b:85:5b:8d:6c (on wlan0)
>> >>> Not connected.
>> >>
>> >> I'm guessing that you're using -Dnl80211. You need this patch, or
>> >> equivalent:
>> >> http://johannes.sipsolutions.net/patches/hostap/all/2009-10-26-12%3a59/deauth-on-disassoc.patch
>> >
>> > Indeed, it fixes my woes, thanks.
>>
>> Well almost, after a while of being connected it then does this:
>>
>> CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
>> CTRL-EVENT-SCAN-RESULTS
>> Trying to authenticate with 00:0b:85:5b:8d:6c (SSID='ATH-GLOBAL' freq=2462 MHz)
>> Trying to associate with 00:0b:85:5b:8d:6c (SSID='ATH-GLOBAL' freq=2462 MHz)
>> Associated with 00:0b:85:5b:8d:6c
>> CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
>> CTRL-EVENT-SCAN-RESULTS
>> Trying to authenticate with 00:0b:85:5b:9a:bc (SSID='ATH-GLOBAL' freq=2412 MHz)
>> Trying to associate with 00:0b:85:5b:9a:bc (SSID='ATH-GLOBAL' freq=2412 MHz)
>> Associated with 00:0b:85:5b:9a:bc
>> CTRL-EVENT-EAP-STARTED EAP authentication started
>> CTRL-EVENT-EAP-STARTED EAP authentication started
>> CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
>> OpenSSL: tls_connection_handshake - Failed to read possible
>> Application Data error:00000000:lib(0):func(0):reason(0)
>>
>> And I then end up with the same:
>>
>> >>> mcgrof@tux ~ $ iw dev wlan0 link
>> >>> Authenticated with 00:0b:85:5b:8d:6c (on wlan0)
>> >>> Not connected.
>
> Might be due to that bssid_changed check I was unsure about -- try
> removing that.

OK will do -- it took a while to trigger so will wait and see if it
happens again, and if it happens often enough I can at least confirm
it would fix it. Otherwise not sure what triggered it. I failed to
check the logs to see what disconnect event exactly triggered.

  Luis