On (10/26/15 07:51), Grumbach, Emmanuel wrote: > > On 10/26/2015 08:41 AM, Sergey Senozhatsky wrote: > >> Hi, > >> > >> linux-next 20151022 > >> > >> > > > > Can be reproduced reliably? > > Seems like a bad race between the end of session protection for the > > authentication and the start of the session protection for the deauth. > > I think I found the hole in the locks in there, but it is going to be > > tricky to solve. > > Not sure if I found the race. Can you please send the complete log? > If you have timestamps, it'd greatly helps... > dmesg output should do. > Hi, not really sure if I can reproduce this one easily. seen once. --- Oct 26 15:20:51 dhclient[399]: DHCPDISCOVER on wlp2s0 to 255.255.255.255 port 67 interval 7 Oct 26 15:20:58 dhclient[399]: DHCPDISCOVER on wlp2s0 to 255.255.255.255 port 67 interval 17 Oct 26 15:21:09 dhclient[539]: DHCPDISCOVER on wlp2s0 to 255.255.255.255 port 67 interval 7 Oct 26 15:21:09 kernel: wlp2s0: authenticate with 00:04:96:69:0d:80 Oct 26 15:21:09 kernel: wlp2s0: send auth to 00:04:96:69:0d:80 (try 1/3) Oct 26 15:21:09 kernel: wlp2s0: authenticated Oct 26 15:21:09 kernel: wlp2s0: associate with 00:04:96:69:0d:80 (try 1/3) Oct 26 15:21:09 kernel: wlp2s0: RX AssocResp from 00:04:96:69:0d:80 (capab=0x11 status=0 aid=24) Oct 26 15:21:09 kernel: wlp2s0: associated Oct 26 15:21:09 kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlp2s0: link becomes ready Oct 26 15:21:09 kernel: wlp2s0: deauthenticating from 00:04:96:69:0d:80 by local choice (Reason: 3=DEAUTH_LEAVING) Oct 26 15:21:12 kernel: wlp2s0: authenticate with 00:04:96:61:e9:f0 Oct 26 15:21:12 kernel: wlp2s0: send auth to 00:04:96:61:e9:f0 (try 1/3) Oct 26 15:21:12 kernel: wlp2s0: authenticated Oct 26 15:21:12 kernel: wlp2s0: associate with 00:04:96:61:e9:f0 (try 1/3) Oct 26 15:21:12 kernel: wlp2s0: RX AssocResp from 00:04:96:61:e9:f0 (capab=0x11 status=0 aid=16) Oct 26 15:21:12 kernel: wlp2s0: associated Oct 26 15:21:12 kernel: wlp2s0: deauthenticating from 00:04:96:61:e9:f0 by local choice (Reason: 3=DEAUTH_LEAVING) Oct 26 15:21:16 dhclient[539]: DHCPDISCOVER on wlp2s0 to 255.255.255.255 port 67 interval 10 Oct 26 15:21:22 kernel: wlp2s0: authenticate with 00:04:96:69:0d:80 Oct 26 15:21:22 kernel: wlp2s0: send auth to 00:04:96:69:0d:80 (try 1/3) Oct 26 15:21:22 kernel: wlp2s0: authenticated Oct 26 15:21:22 kernel: wlp2s0: associate with 00:04:96:69:0d:80 (try 1/3) Oct 26 15:21:22 kernel: wlp2s0: RX AssocResp from 00:04:96:69:0d:80 (capab=0x11 status=0 aid=25) Oct 26 15:21:22 kernel: wlp2s0: associated Oct 26 15:21:22 kernel: wlp2s0: deauthenticating from 00:04:96:69:0d:80 by local choice (Reason: 3=DEAUTH_LEAVING) Oct 26 15:21:26 dhclient[539]: DHCPDISCOVER on wlp2s0 to 255.255.255.255 port 67 interval 9 Oct 26 15:21:35 dhclient[539]: DHCPDISCOVER on wlp2s0 to 255.255.255.255 port 67 interval 12 Oct 26 15:21:47 kernel: wlp2s0: authenticate with 00:04:96:69:0d:80 Oct 26 15:21:47 kernel: wlp2s0: send auth to 00:04:96:69:0d:80 (try 1/3) Oct 26 15:21:47 kernel: wlp2s0: authenticated Oct 26 15:21:47 kernel: wlp2s0: associate with 00:04:96:69:0d:80 (try 1/3) Oct 26 15:21:47 kernel: wlp2s0: RX AssocResp from 00:04:96:69:0d:80 (capab=0x11 status=0 aid=25) Oct 26 15:21:47 kernel: wlp2s0: associated Oct 26 15:21:47 kernel: wlp2s0: deauthenticating from 00:04:96:69:0d:80 by local choice (Reason: 3=DEAUTH_LEAVING) Oct 26 15:21:47 dhclient[539]: DHCPDISCOVER on wlp2s0 to 255.255.255.255 port 67 interval 18 Oct 26 15:22:05 dhclient[539]: DHCPDISCOVER on wlp2s0 to 255.255.255.255 port 67 interval 5 Oct 26 15:22:10 dhclient[539]: No DHCPOFFERS received. Oct 26 15:22:10 dhclient[539]: No working leases in persistent database - sleeping. Oct 26 15:22:34 kernel: wlp2s0: authenticate with 00:04:96:69:0d:80 Oct 26 15:22:34 kernel: wlp2s0: send auth to 00:04:96:69:0d:80 (try 1/3) Oct 26 15:22:34 kernel: wlp2s0: authenticated Oct 26 15:22:34 kernel: wlp2s0: associate with 00:04:96:69:0d:80 (try 1/3) Oct 26 15:22:34 kernel: wlp2s0: RX AssocResp from 00:04:96:69:0d:80 (capab=0x11 status=0 aid=29) Oct 26 15:22:34 kernel: wlp2s0: associated Oct 26 15:22:34 kernel: wlp2s0: deauthenticating from 00:04:96:69:0d:80 by local choice (Reason: 3=DEAUTH_LEAVING) Oct 26 15:22:34 kernel: wlp2s0: authenticate with 00:04:96:61:cd:e0 Oct 26 15:22:34 kernel: wlp2s0: send auth to 00:04:96:61:cd:e0 (try 1/3) Oct 26 15:22:34 kernel: wlp2s0: aborting authentication with 00:04:96:61:cd:e0 by local choice (Reason: 3=DEAUTH_LEAVING) Oct 26 15:22:34 kernel: ------------[ cut here ]------------ Oct 26 15:22:34 kernel: WARNING: CPU: 0 PID: 1006 at drivers/net/wireless/iwlwifi/mvm/time-event.c:513 iwl_mvm_time_event_send_add+0x72/0x1b6 [iwlmvm]() Oct 26 15:22:34 kernel: Modules linked in: mousedev arc4 nls_iso8859_1 nls_cp437 vfat fat serio_raw psmouse atkbd coretemp hwmon i915 libps2 iwlmvm i2c_algo_bit mac80211 drm_kms_helper cfbfillrect intel_powerclamp syscopyarea cfbimgblt sysfillrect sysimgblt crc32c_intel fb_sys_fops cfbcopyarea iwlwifi drm r8 Oct 26 15:22:34 kernel: CPU: 0 PID: 1006 Comm: iwconfig Not tainted 4.3.0-rc6-next-20151022-dbg-00002-g4041783-dirty #260 Oct 26 15:22:34 kernel: 0000000000000000 ffff8800c69479c8 ffffffff811dd4ad 0000000000000000 Oct 26 15:22:34 kernel: ffff8800c6947a00 ffffffff8103db4e ffffffffa04fd261 ffff88041c7cdfc8 Oct 26 15:22:34 kernel: ffff88041cc87a20 ffff88041c7ceb28 ffff8800c6947aac ffff8800c6947a10 Oct 26 15:22:34 kernel: Call Trace: Oct 26 15:22:34 kernel: [<ffffffff811dd4ad>] dump_stack+0x4b/0x63 Oct 26 15:22:34 kernel: [<ffffffff8103db4e>] warn_slowpath_common+0x99/0xb2 Oct 26 15:22:34 kernel: [<ffffffffa04fd261>] ? iwl_mvm_time_event_send_add+0x72/0x1b6 [iwlmvm] Oct 26 15:22:34 kernel: [<ffffffff8103dc1a>] warn_slowpath_null+0x1a/0x1c Oct 26 15:22:34 kernel: [<ffffffffa04fd261>] iwl_mvm_time_event_send_add+0x72/0x1b6 [iwlmvm] Oct 26 15:22:34 kernel: [<ffffffff8107979f>] ? __lock_is_held+0x3c/0x57 Oct 26 15:22:34 kernel: [<ffffffffa04fdb8b>] iwl_mvm_protect_session+0x150/0x219 [iwlmvm] Oct 26 15:22:34 kernel: [<ffffffffa04fdb8b>] ? iwl_mvm_protect_session+0x150/0x219 [iwlmvm] Oct 26 15:22:34 kernel: [<ffffffffa04ecf57>] ? iwl_mvm_ref_sync+0x37/0x10c [iwlmvm] Oct 26 15:22:34 kernel: [<ffffffffa04ed475>] iwl_mvm_mac_mgd_prepare_tx+0xa4/0xc2 [iwlmvm] Oct 26 15:22:34 kernel: [<ffffffffa04ed475>] ? iwl_mvm_mac_mgd_prepare_tx+0xa4/0xc2 [iwlmvm] Oct 26 15:22:34 kernel: [<ffffffffa047be43>] ieee80211_mgd_deauth+0x14f/0x3b0 [mac80211] Oct 26 15:22:34 kernel: [<ffffffff8107979f>] ? __lock_is_held+0x3c/0x57 Oct 26 15:22:34 kernel: [<ffffffffa0446758>] ieee80211_deauth+0x18/0x1a [mac80211] Oct 26 15:22:34 kernel: [<ffffffffa02bc4b2>] cfg80211_mlme_deauth+0x13c/0x28e [cfg80211] Oct 26 15:22:34 kernel: [<ffffffffa02c0f9a>] cfg80211_disconnect+0xb5/0x2f7 [cfg80211] Oct 26 15:22:34 kernel: [<ffffffffa02d901e>] cfg80211_mgd_wext_siwfreq+0xed/0x160 [cfg80211] Oct 26 15:22:34 kernel: [<ffffffffa02d8c81>] ? cfg80211_wext_freq+0x5f/0x5f [cfg80211] Oct 26 15:22:34 kernel: [<ffffffffa02d8cf7>] cfg80211_wext_siwfreq+0x76/0xf6 [cfg80211] Oct 26 15:22:34 kernel: [<ffffffff813a9809>] ioctl_standard_call+0x66/0x376 Oct 26 15:22:34 kernel: [<ffffffff813a9caa>] wext_handle_ioctl+0x102/0x16d Oct 26 15:22:34 kernel: [<ffffffff8130782b>] dev_ioctl+0x6bb/0x6de Oct 26 15:22:34 kernel: [<ffffffff81113adc>] ? handle_mm_fault+0xefc/0x13f9 Oct 26 15:22:34 kernel: [<ffffffff812d73d0>] sock_ioctl+0x230/0x23c Oct 26 15:22:34 kernel: [<ffffffff812d73d0>] ? sock_ioctl+0x230/0x23c Oct 26 15:22:34 kernel: [<ffffffff8115047d>] do_vfs_ioctl+0x458/0x4dc Oct 26 15:22:34 kernel: [<ffffffff813b3635>] ? retint_user+0x18/0x20 Oct 26 15:22:34 kernel: [<ffffffff8115a5fe>] ? __fget_light+0x4d/0x71 Oct 26 15:22:34 kernel: [<ffffffff81150544>] SyS_ioctl+0x43/0x61 Oct 26 15:22:34 kernel: [<ffffffff813b2b57>] entry_SYSCALL_64_fastpath+0x12/0x6f Oct 26 15:22:34 kernel: ---[ end trace 6a44e7f1588bdae7 ]--- Oct 26 15:22:34 kernel: wlp2s0: authenticate with 00:04:96:68:d7:60 Oct 26 15:22:34 kernel: wlp2s0: send auth to 00:04:96:68:d7:60 (try 1/3) Oct 26 15:22:34 kernel: wlp2s0: send auth to 00:04:96:68:d7:60 (try 2/3) Oct 26 15:22:34 kernel: wlp2s0: authenticated Oct 26 15:22:34 kernel: wlp2s0: associate with 00:04:96:68:d7:60 (try 1/3) Oct 26 15:22:34 kernel: wlp2s0: RX AssocResp from 00:04:96:68:d7:60 (capab=0x411 status=0 aid=4) Oct 26 15:22:34 kernel: wlp2s0: associated Oct 26 15:22:34 kernel: wlp2s0: deauthenticating from 00:04:96:68:d7:60 by local choice (Reason: 3=DEAUTH_LEAVING) Oct 26 15:22:34 dhclient[1011]: DHCPDISCOVER on wlp2s0 to 255.255.255.255 port 67 interval 8 Oct 26 15:22:37 kernel: wlp2s0: authenticate with 00:04:96:69:0d:80 Oct 26 15:22:37 kernel: wlp2s0: send auth to 00:04:96:69:0d:80 (try 1/3) Oct 26 15:22:37 kernel: wlp2s0: authenticated Oct 26 15:22:37 kernel: wlp2s0: associate with 00:04:96:69:0d:80 (try 1/3) Oct 26 15:22:37 kernel: wlp2s0: RX AssocResp from 00:04:96:69:0d:80 (capab=0x11 status=0 aid=29) Oct 26 15:22:37 kernel: wlp2s0: associated Oct 26 15:22:37 kernel: wlp2s0: deauthenticating from 00:04:96:69:0d:80 by local choice (Reason: 3=DEAUTH_LEAVING) Oct 26 15:22:40 kernel: wlp2s0: authenticate with 00:04:96:61:e9:f0 Oct 26 15:22:40 kernel: wlp2s0: send auth to 00:04:96:61:e9:f0 (try 1/3) Oct 26 15:22:40 kernel: wlp2s0: authenticated Oct 26 15:22:40 kernel: wlp2s0: associate with 00:04:96:61:e9:f0 (try 1/3) Oct 26 15:22:40 kernel: wlp2s0: RX AssocResp from 00:04:96:61:e9:f0 (capab=0x11 status=0 aid=19) Oct 26 15:22:40 kernel: wlp2s0: associated Oct 26 15:22:40 kernel: wlp2s0: deauthenticating from 00:04:96:61:e9:f0 by local choice (Reason: 3=DEAUTH_LEAVING) Oct 26 15:22:42 kernel: wlp2s0: authenticate with 00:04:96:62:10:e0 Oct 26 15:22:42 kernel: wlp2s0: send auth to 00:04:96:62:10:e0 (try 1/3) Oct 26 15:22:42 kernel: wlp2s0: authenticated Oct 26 15:22:42 kernel: wlp2s0: associate with 00:04:96:62:10:e0 (try 1/3) Oct 26 15:22:42 kernel: wlp2s0: RX AssocResp from 00:04:96:62:10:e0 (capab=0x411 status=0 aid=2) Oct 26 15:22:42 kernel: wlp2s0: associated Oct 26 15:22:42 kernel: wlp2s0: deauthenticating from 00:04:96:62:10:e0 by local choice (Reason: 3=DEAUTH_LEAVING) Oct 26 15:22:45 kernel: wlp2s0: authenticate with 00:04:96:61:bd:90 Oct 26 15:22:45 kernel: wlp2s0: send auth to 00:04:96:61:bd:90 (try 1/3) Oct 26 15:22:45 kernel: wlp2s0: authenticated Oct 26 15:22:45 kernel: wlp2s0: associate with 00:04:96:61:bd:90 (try 1/3) Oct 26 15:22:45 kernel: wlp2s0: RX AssocResp from 00:04:96:61:bd:90 (capab=0x111 status=0 aid=4) Oct 26 15:22:45 kernel: wlp2s0: associated Oct 26 15:22:45 kernel: wlp2s0: deauthenticating from 00:04:96:61:bd:90 by local choice (Reason: 3=DEAUTH_LEAVING) Oct 26 15:22:55 kernel: wlp2s0: authenticate with 00:04:96:69:0d:80 Oct 26 15:22:55 kernel: wlp2s0: send auth to 00:04:96:69:0d:80 (try 1/3) Oct 26 15:22:55 kernel: wlp2s0: authenticated Oct 26 15:22:55 kernel: wlp2s0: associate with 00:04:96:69:0d:80 (try 1/3) Oct 26 15:22:55 kernel: wlp2s0: RX AssocResp from 00:04:96:69:0d:80 (capab=0x11 status=0 aid=9) Oct 26 15:22:55 kernel: wlp2s0: associated Oct 26 15:22:55 kernel: wlp2s0: deauthenticating from 00:04:96:69:0d:80 by local choice (Reason: 3=DEAUTH_LEAVING) Oct 26 15:22:57 kernel: wlp2s0: authenticate with 00:04:96:61:ed:40 Oct 26 15:22:57 kernel: wlp2s0: send auth to 00:04:96:61:ed:40 (try 1/3) Oct 26 15:22:57 kernel: wlp2s0: authenticated Oct 26 15:22:57 kernel: wlp2s0: associate with 00:04:96:61:ed:40 (try 1/3) Oct 26 15:22:57 kernel: wlp2s0: RX AssocResp from 00:04:96:61:ed:40 (capab=0x11 status=0 aid=2) Oct 26 15:22:57 kernel: wlp2s0: associated Oct 26 15:22:57 kernel: wlp2s0: deauthenticating from 00:04:96:61:ed:40 by local choice (Reason: 3=DEAUTH_LEAVING) Oct 26 15:23:23 kernel: wlp2s0: authenticate with 00:04:96:69:0d:80 Oct 26 15:23:23 kernel: wlp2s0: send auth to 00:04:96:69:0d:80 (try 1/3) Oct 26 15:23:23 kernel: wlp2s0: authenticated Oct 26 15:23:23 kernel: wlp2s0: associate with 00:04:96:69:0d:80 (try 1/3) Oct 26 15:23:23 kernel: wlp2s0: RX AssocResp from 00:04:96:69:0d:80 (capab=0x11 status=0 aid=31) Oct 26 15:23:23 kernel: wlp2s0: associated Oct 26 15:23:23 kernel: wlp2s0: deauthenticating from 00:04:96:69:0d:80 by local choice (Reason: 3=DEAUTH_LEAVING) --- -ss -- To unsubscribe from this list: send the line "unsubscribe linux-wireless" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
