Dear all, here is a short status report on my experiences with: kernel 3.9.0 wpa_supplicant 1.0 hardware RTL191SEvB Debian/sid Short summary: broken to the degree that internet connection is impossible Sorry for the long mail, I tried to reduce to the essentials only. Contents: ========= 0) hardware and software description 1) during connection permanent break off 2) connection seems established according to kernel and NM, but nothing works 3) if connection is working, ping times are crazy and connection breaks down suddenly 4) conclusion 0) hardware and software description ==================================== Hardware: Lenovo Thinkpad Edge WLAN: 03:00.0 Network controller: Realtek Semiconductor Co., Ltd. RTL8191SEvB Wireless LAN Controller (rev 10) Subsystem: Realtek Semiconductor Co., Ltd. Device e020 Flags: bus master, fast devsel, latency 0, IRQ 17 I/O ports at 2000 [size=256] Memory at f0500000 (32-bit, non-prefetchable) [size=16K] Capabilities: [40] Power Management version 3 Capabilities: [50] MSI: Enable- Count=1/1 Maskable- 64bit+ Capabilities: [70] Express Legacy Endpoint, MSI 00 Capabilities: [100] Advanced Error Reporting Capabilities: [140] Virtual Channel Capabilities: [160] Device Serial Number 88-55-22-fe-ff-4c-e0-00 Kernel driver in use: rtl8192se Debian unstable up to date kernel 3.9.0 # wpa_supplicant -v wpa_supplicant v1.0 Copyright (c) 2003-2012, Jouni Malinen <j@xxxxx> and contributors Debian version: 1.0-3+b2 Please note: during all the following experiments at times two other computers (iPhone, WinXP) very connected without any problems (of course on different IPs). ad 1) during connection permanent break off ============================================ typical dmesg output: many times: May 8 20:54:59 tofuschnitzel NetworkManager[4878]: <info> (wlan0): supplicant interface state: disconnected -> scanning May 8 20:54:59 tofuschnitzel wpa_supplicant[5513]: wlan0: SME: Trying to authenticate with 00:3a:9d:b4:54:5a (SSID='norbujp' fr eq=2447 MHz) kernel: [19070.021021] wlan0: authenticate with 00:3a:9d:b4:54:5a NetworkManager[4878]: <info> (wlan0): supplicant interface state: scanning -> authenticating kernel: [19070.040313] wlan0: send auth to 00:3a:9d:b4:54:5a (try 1/3) kernel: [19070.144143] wlan0: send auth to 00:3a:9d:b4:54:5a (try 2/3) kernel: [19070.248113] wlan0: send auth to 00:3a:9d:b4:54:5a (try 3/3) wpa_supplicant[5513]: wlan0: Trying to associate with 00:3a:9d:b4:54:5a (SSID='norbujp' freq=2447 MHz) kernel: [19070.286906] wlan0: authenticated kernel: [19070.288224] wlan0: associate with 00:3a:9d:b4:54:5a (try 1/3) NetworkManager[4878]: <info> (wlan0): supplicant interface state: authenticating -> associating kernel: [19070.392185] wlan0: associate with 00:3a:9d:b4:54:5a (try 2/3) kernel: [19070.496204] wlan0: associate with 00:3a:9d:b4:54:5a (try 3/3) kernel: [19070.600253] wlan0: association with 00:3a:9d:b4:54:5a timed out NetworkManager[4878]: <info> (wlan0): supplicant interface state: associating -> disconnected after several of these I get one of the following: kernel: [19073.340075] wlan0: associated kernel: [19073.340155] cfg80211: Calling CRDA for country: JP NetworkManager[4878]: <info> (wlan0): supplicant interface state: associating -> 4-way handshake kernel: [19073.347635] cfg80211: Regulatory domain changed to country: JP kernel: [19073.347643] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp) kernel: [19073.347648] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm) kernel: [19073.347652] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz), (N/A, 2000 mBm) kernel: [19073.347656] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (N/A, 2000 mBm) ... dbus[4074]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper) dbus[4074]: [system] Successfully activated service 'org.freedesktop.PackageKit' kernel: [19077.405951] wlan0: deauthenticated from 00:3a:9d:b4:54:5a (Reason: 2) wpa_supplicant[5513]: wlan0: WPA: 4-Way Handshake failed - pre-shared key may be incorrect wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 kernel: [19077.416143] cfg80211: Calling CRDA to update world regulatory domain NetworkManager[4878]: <info> (wlan0): supplicant interface state: 4-way handshake -> disconnected NetworkManager[4878]: <info> Activation (wlan0/wireless): disconnected during association, asking for new key. but it is the correct key! Anyway, then the above game restarts ... sometimes, after many many many tries, the kernel/NM seems to believe it got a connection: 2) connection seems established according to kernel and NM, but nothing works ============================================================================= it starts as before, but then succeeds - in some way: wpa_supplicant[5513]: wlan0: WPA: Key negotiation completed with 00:3a:9d:b4:54:5a [PTK=CCMP GTK=CCMP] wpa_supplicant[5513]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:3a:9d:b4:54:5a completed (reauth) [id=0 id_str=] NetworkManager[4878]: <info> (wlan0): supplicant interface state: 4-way handshake -> completed NetworkManager[4878]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'norbujp'. NetworkManager[4878]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled. NetworkManager[4878]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started... NetworkManager[4878]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0] NetworkManager[4878]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds) NetworkManager[4878]: <info> dhclient started with pid 30807 NetworkManager[4878]: nm_utils_do_sysctl: assertion `path != NULL' failed NetworkManager[4878]: <info> Activation (wlan0) Beginning IP6 addrconf. NetworkManager[4878]: <warn> sysctl: failed to open '/proc/sys/net/ipv6/conf/wlan0/disable_ipv6': (2) No such file or directory NetworkManager[4878]: <warn> sysctl: failed to open '/proc/sys/net/ipv6/conf/wlan0/disable_ipv6': (2) No such file or directory NetworkManager[4878]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete. dhclient: Internet Systems Consortium DHCP Client 4.2.4 dhclient: Copyright 2004-2012 Internet Systems Consortium. dhclient: All rights reserved. dhclient: For info, please visit https://www.isc.org/software/dhcp/ dhclient: NetworkManager[4878]: <info> (wlan0): DHCPv4 state changed nbi -> preinit dhclient: Listening on LPF/wlan0/88:9f:fa:f9:07:28 dhclient: Sending on LPF/wlan0/88:9f:fa:f9:07:28 dhclient: Sending on Socket/fallback dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67 dhclient: DHCPACK from 192.168.0.1 dhclient: bound to 192.168.0.5 -- renewal in 37312 seconds. NetworkManager[4878]: <info> (wlan0): DHCPv4 state changed preinit -> reboot NetworkManager[4878]: <info> address 192.168.0.5 NetworkManager[4878]: <info> prefix 24 (255.255.255.0) NetworkManager[4878]: <info> gateway 192.168.0.1 NetworkManager[4878]: <info> nameserver '192.168.0.1' NetworkManager[4878]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Configure Commit) scheduled... NetworkManager[4878]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) started... NetworkManager[4878]: <info> (wlan0): device state change: ip-config -> secondaries (reason 'none') [70 90 0] NetworkManager[4878]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) complete. NetworkManager[4878]: <info> (wlan0): device state change: secondaries -> activated (reason 'none') [90 100 0] NetworkManager[4878]: <info> Policy set 'Auto norbujp' (wlan0) as default for IPv4 routing and DNS. NetworkManager[4878]: <info> Activation (wlan0) successful, device activated. dbus[4074]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper) dbus[4074]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher' ntpd[4779]: Listen normally on 5 wlan0 192.168.0.5 UDP 123 ntpd[4779]: peers refreshed nm-dispatcher.action: Script '/etc/NetworkManager/dispatcher.d/01ifupdown' took too long; killing it. May 8 20:45:22 tofuschnitzel NetworkManager[4878]: <warn> Dispatcher script timed out: Script '/etc/NetworkManager/dispatcher.d/01ifupdown' timed out. May 8 20:45:37 tofuschnitzel NetworkManager[4878]: <info> (wlan0): IP6 addrconf timed out or failed. May 8 20:45:37 tofuschnitzel NetworkManager[4878]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled... May 8 20:45:37 tofuschnitzel NetworkManager[4878]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) started... May 8 20:45:37 tofuschnitzel NetworkManager[4878]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) complete. But although both kernel as well as NM believe that all is fine: $ ifconfig wlan0 wlan0 Link encap:Ethernet HWaddr 88:9f:fa:f9:07:28 inet addr:192.168.0.5 Bcast:192.168.0.255 Mask:255.255.255.0 UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1 RX packets:205848 errors:0 dropped:0 overruns:0 frame:0 TX packets:4519 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:44049656 (42.0 MiB) TX bytes:750906 (733.3 KiB) $ iwconfig wlan0 wlan0 IEEE 802.11bgn ESSID:"norbujp" Mode:Managed Frequency:2.447 GHz Access Point: 00:3A:9D:B4:54:5A Bit Rate=150 Mb/s Tx-Power=20 dBm Retry long limit:7 RTS thr=2347 B Fragment thr:off Power Management:off Link Quality=70/70 Signal level=-35 dBm Rx invalid nwid:0 Rx invalid crypt:0 Rx invalid frag:0 Tx excessive retries:0 Invalid misc:6 Missed beacon:0 absolutely nothing works: Examples: [~] ping 192.168.0.1 PING 192.168.0.1 (192.168.0.1) 56(84) bytes of data. >From 192.168.0.5 icmp_seq=1 Destination Host Unreachable >From 192.168.0.5 icmp_seq=2 Destination Host Unreachable >From 192.168.0.5 icmp_seq=5 Destination Host Unreachable >From 192.168.0.5 icmp_seq=7 Destination Host Unreachable >From 192.168.0.5 icmp_seq=39 Destination Host Unreachable >From 192.168.0.5 icmp_seq=40 Destination Host Unreachable >From 192.168.0.5 icmp_seq=41 Destination Host Unreachable >From 192.168.0.5 icmp_seq=42 Destination Host Unreachable ... --- 192.168.0.1 ping statistics --- 88 packets transmitted, 0 received, +43 errors, 100% packet loss, time 87233ms pipe 4 absolutely nothing goes out - at least it seems so. Sometimes, though, whoever decided to speak to me, and pings started to get returned, but then ... 3) if connection is working, ping times are crazy and connection breaks down suddenly ===================================================================================== pinging my own gateway results in things like: 64 bytes from 192.168.0.1: icmp_req=35 ttl=255 time=119395 ms or >From 192.168.0.5 icmp_seq=118 Destination Host Unreachable >From 192.168.0.5 icmp_seq=119 Destination Host Unreachable >From 192.168.0.5 icmp_seq=120 Destination Host Unreachable 64 bytes from 192.168.0.1: icmp_req=31 ttl=255 time=91863 ms 64 bytes from 192.168.0.1: icmp_req=32 ttl=255 time=91151 ms >From 192.168.0.5 icmp_seq=121 Destination Host Unreachable >From 192.168.0.5 icmp_seq=122 Destination Host Unreachable or [~] ping 192.168.0.1 PING 192.168.0.1 (192.168.0.1) 56(84) bytes of data. 64 bytes from 192.168.0.1: icmp_req=3 ttl=255 time=44447 ms 64 bytes from 192.168.0.1: icmp_req=7 ttl=255 time=41123 ms 64 bytes from 192.168.0.1: icmp_req=11 ttl=255 time=55627 ms 64 bytes from 192.168.0.1: icmp_req=14 ttl=255 time=69027 ms 64 bytes from 192.168.0.1: icmp_req=15 ttl=255 time=68046 ms 64 bytes from 192.168.0.1: icmp_req=19 ttl=255 time=75636 ms 64 bytes from 192.168.0.1: icmp_req=24 ttl=255 time=109967 ms .... big up and down in ping times: 4 bytes from 192.168.0.1: icmp_req=442 ttl=255 time=1.51 ms 64 bytes from 192.168.0.1: icmp_req=443 ttl=255 time=1.61 ms 64 bytes from 192.168.0.1: icmp_req=444 ttl=255 time=2.77 ms 64 bytes from 192.168.0.1: icmp_req=445 ttl=255 time=37.0 ms 64 bytes from 192.168.0.1: icmp_req=446 ttl=255 time=1.53 ms 64 bytes from 192.168.0.1: icmp_req=447 ttl=255 time=469 ms 64 bytes from 192.168.0.1: icmp_req=448 ttl=255 time=116 ms 64 bytes from 192.168.0.1: icmp_req=449 ttl=255 time=1.73 ms 64 bytes from 192.168.0.1: icmp_req=450 ttl=255 time=1.58 ms 64 bytes from 192.168.0.1: icmp_req=451 ttl=255 time=6916 ms 64 bytes from 192.168.0.1: icmp_req=452 ttl=255 time=6632 ms 64 bytes from 192.168.0.1: icmp_req=453 ttl=255 time=5654 ms 64 bytes from 192.168.0.1: icmp_req=454 ttl=255 time=4716 ms 64 bytes from 192.168.0.1: icmp_req=455 ttl=255 time=3896 ms 64 bytes from 192.168.0.1: icmp_req=456 ttl=255 time=2897 ms 64 bytes from 192.168.0.1: icmp_req=457 ttl=255 time=1899 ms 64 bytes from 192.168.0.1: icmp_req=458 ttl=255 time=901 ms 64 bytes from 192.168.0.1: icmp_req=459 ttl=255 time=1.25 ms 64 bytes from 192.168.0.1: icmp_req=460 ttl=255 time=116 ms 64 bytes from 192.168.0.1: icmp_req=461 ttl=255 time=1.48 ms ... 64 bytes from 192.168.0.1: icmp_req=483 ttl=255 time=1.24 ms 64 bytes from 192.168.0.1: icmp_req=485 ttl=255 time=10910 ms 64 bytes from 192.168.0.1: icmp_req=486 ttl=255 time=9913 ms 64 bytes from 192.168.0.1: icmp_req=487 ttl=255 time=8913 ms 64 bytes from 192.168.0.1: icmp_req=488 ttl=255 time=7913 ms 64 bytes from 192.168.0.1: icmp_req=489 ttl=255 time=6913 ms ... 64 bytes from 192.168.0.1: icmp_req=494 ttl=255 time=1915 ms 64 bytes from 192.168.0.1: icmp_req=495 ttl=255 time=915 ms >From 192.168.0.5 icmp_seq=530 Destination Host Unreachable >From 192.168.0.5 icmp_seq=531 Destination Host Unreachable ... >From 192.168.0.5 icmp_seq=581 Destination Host Unreachable 64 bytes from 192.168.0.1: icmp_req=497 ttl=255 time=87064 ms >From 192.168.0.5 icmp_seq=582 Destination Host Unreachable ... >From 192.168.0.5 icmp_seq=598 Destination Host Unreachable 64 bytes from 192.168.0.1: icmp_req=498 ttl=255 time=105208 ms ping: sendmsg: No buffer space available >From 192.168.0.5 icmp_seq=623 Destination Host Unreachable ... Looking into the reasons why disconnects happen I see: [~] grep reason= /var/log/syslog May 8 20:43:57 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:44:04 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:45:02 tofuschnitzel kernel: [18472.914329] wlan0: deauthenticating from 00:3a:9d:b4:54:5a by local choice (reason=3) May 8 20:45:02 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:00:00:00:00:00 reason=3 May 8 20:47:34 tofuschnitzel kernel: [18624.597387] wlan0: deauthenticating from 00:3a:9d:b4:54:5a by local choice (reason=3) May 8 20:47:34 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:00:00:00:00:00 reason=3 May 8 20:48:27 tofuschnitzel kernel: [18677.928400] wlan0: deauthenticating from 00:3a:9d:b4:54:5a by local choice (reason=3) May 8 20:48:27 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:00:00:00:00:00 reason=3 May 8 20:48:36 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:48:52 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:49:15 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:49:25 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:49:41 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:49:50 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:49:57 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:53:20 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:53:30 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:53:51 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:54:01 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:54:27 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:54:45 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:55:07 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 20:55:36 tofuschnitzel kernel: [19106.844710] wlan0: deauthenticating from 00:3a:9d:b4:54:5a by local choice (reason=3) May 8 20:55:36 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=3 May 8 21:10:07 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 May 8 21:10:58 tofuschnitzel kernel: [20029.040231] wlan0: deauthenticating from 00:3a:9d:b4:54:5a by local choice (reason=3) May 8 21:10:58 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:00:00:00:00:00 reason=3 May 8 21:23:20 tofuschnitzel wpa_supplicant[5513]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:9d:b4:54:5a reason=2 My feeling is also that things like wpa_supplicant[5513]: wlan0: WPA: Key negotiation completed with 00:3a:9d:b4:54:5a [PTK=CCMP GTK=CCMP] have a strong effect on the actual connection. 4) conclusion ============= in the current state, that is release 3.9.0, but the same happened in earlier kernels, this driver and/or NM is completely useless at times. At times it just works, at times it does nothing. In this case, now the 5th day in series ... Norbert ------------------------------------------------------------------------ PREINING, Norbert http://www.preining.info JAIST, Japan TeX Live & Debian Developer DSA: 0x09C5B094 fp: 14DF 2E6C 0307 BE6D AD76 A9C0 D2BF 4AA3 09C5 B094 ------------------------------------------------------------------------ -- 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
