RT5370 WiFi cuts out after some hours, needs reboot?


49 posts   Page 1 of 2   1, 2
by jbeale » Sat Apr 13, 2013 9:09 pm
I'm using a Ralink RT5370 USB-WiFi module that works trouble-free for some time, between 6 hours and 2 days, and then it just cuts out and does not come back. If I reboot, everything is fine again. This is a R-Pi model A with 4-port hub, voltage levels are OK (TP1/TP2 = 4.9 V). I also have a keyboard and two FTDI serial ports on the hub. Any hints on what the problem might be, and/or how can I get it to reset on its own without needing a full reboot? I am using a fixed IP address, not DHCP. But previously I tried DHCP with the same behavior. Below is an example of the end of the /var/log/daemon.log after a cutout:

Code: Select all
Apr 13 03:34:34 rp3 wpa_supplicant[1637]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 13 04:34:26 rp3 wpa_supplicant[1637]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 13 05:34:18 rp3 wpa_supplicant[1637]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 13 06:34:10 rp3 wpa_supplicant[1637]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 13 07:34:02 rp3 wpa_supplicant[1637]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 13 08:33:54 rp3 wpa_supplicant[1637]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 13 09:33:47 rp3 wpa_supplicant[1637]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 13 10:33:38 rp3 wpa_supplicant[1637]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 13 11:33:30 rp3 wpa_supplicant[1637]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 13 12:24:24 rp3 wpa_supplicant[1637]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:23:69:c7:88:6c reason=4
Apr 13 12:24:25 rp3 ifplugd(wlan0)[1633]: Link beat lost.
Apr 13 12:24:25 rp3 wpa_supplicant[1637]: wlan0: SME: Trying to authenticate with 00:23:69:c7:88:6c (SSID='sb3z' freq=2412 MHz)
Apr 13 12:24:26 rp3 wpa_supplicant[1637]: wlan0: Trying to associate with 00:23:69:c7:88:6c (SSID='sb3z' freq=2412 MHz)
Apr 13 12:24:35 rp3 wpa_supplicant[1637]: wlan0: SME: Trying to authenticate with 00:23:69:c7:88:6c (SSID='sb3z' freq=2412 MHz)
Apr 13 12:24:35 rp3 ifplugd(wlan0)[1633]: Executing '/etc/ifplugd/ifplugd.action wlan0 down'.
Apr 13 12:24:35 rp3 wpa_supplicant[1637]: wlan0: Trying to associate with 00:23:69:c7:88:6c (SSID='sb3z' freq=2412 MHz)
Apr 13 12:24:35 rp3 wpa_supplicant[1637]: wlan0: CTRL-EVENT-TERMINATING - signal 15 received
Apr 13 12:24:35 rp3 ifplugd(wlan0)[1633]: Program executed successfully.
Apr 13 12:24:37 rp3 ntpd[2099]: Deleting interface #2 wlan0, 192.168.10.146#123, interface stats: received=1127, sent=1171, dropped=0, active_time=132048 secs
Apr 13 12:24:37 rp3 ntpd[2099]: 216.119.157.44 interface 192.168.10.146 -> (none)
Apr 13 12:24:37 rp3 ntpd[2099]: 209.236.69.170 interface 192.168.10.146 -> (none)
Apr 13 12:24:37 rp3 ntpd[2099]: 209.114.111.1 interface 192.168.10.146 -> (none)
Apr 13 12:24:37 rp3 ntpd[2099]: 199.102.46.73 interface 192.168.10.146 -> (none)
Apr 13 12:24:37 rp3 ntpd[2099]: peers refreshed
pi@rp3 ~ $ date
Sat Apr 13 14:04:28 PDT 2013
pi@rp3 ~ $ uname -a
Linux rp3 3.6.11+ #408 PREEMPT Wed Apr 10 20:33:39 BST 2013 armv6l GNU/Linux
pi@rp3 ~ $ lsusb
Bus 001 Device 002: ID 1a40:0101 Terminus Technology Inc. 4-Port HUB
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 003: ID 413c:2005 Dell Computer Corp. RT7D50 Keyboard
Bus 001 Device 004: ID 0403:6001 Future Technology Devices International, Ltd FT232 USB-Serial (UART) IC
Bus 001 Device 005: ID 148f:5370 Ralink Technology, Corp. RT5370 Wireless Adapter
Bus 001 Device 006: ID 0403:6001 Future Technology Devices International, Ltd FT232 USB-Serial (UART) IC

Last edited by jbeale on Sat Apr 13, 2013 9:49 pm, edited 1 time in total.
User avatar
Posts: 2038
Joined: Tue Nov 22, 2011 11:51 pm
by pluggy » Sat Apr 13, 2013 9:45 pm
I have

wireless-power off

in my /etc/network/interfaces file with my RT5570 adaptor. The adaptor has a power saving function and this apparently turns it off. It does the same trick as yours without it.
Don't judge Linux by the Pi.......
User avatar
Posts: 2493
Joined: Thu May 31, 2012 3:52 pm
Location: Barnoldswick, Lancashire,UK
by jbeale » Sat Apr 13, 2013 9:59 pm
pluggy wrote:I have
wireless-power off
in my /etc/network/interfaces file with my RT5570 adaptor. The adaptor has a power saving function and this apparently turns it off. It does the same trick as yours without it.

Ah, how very interesting! So the linux driver is apparently not compatible with the power-saving function, I gather. Would be nice if it was. Anyway I did not have that line in my 'interfaces' file, I will give this a try. I can see that the change did show up as "Power Management:off" from iwconfig.

Code: Select all
pi@rp3 /etc/network $ iwconfig
wlan0     IEEE 802.11bgn  ESSID:"sb3z"
          Mode:Managed  Frequency:2.412 GHz  Access Point: 00:23:69:C7:88:6C
          Bit Rate=54 Mb/s   Tx-Power=20 dBm
          Retry  long limit:7   RTS thr:off   Fragment thr:off
          Power Management:on
          Link Quality=61/70  Signal level=-49 dBm
          Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
          Tx excessive retries:46  Invalid misc:19   Missed beacon:0

(...changed /etc/network/interfaces file to include 'wireless-power off' and reboot...)

pi@rp3 ~ $ iwconfig
wlan0     IEEE 802.11bgn  ESSID:"sb3z"
          Mode:Managed  Frequency:2.412 GHz  Access Point: 00:23:69:C7:88:6C
          Bit Rate=18 Mb/s   Tx-Power=20 dBm
          Retry  long limit:7   RTS thr:off   Fragment thr:off
          Power Management:off
          Link Quality=63/70  Signal level=-47 dBm
          Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
          Tx excessive retries:0  Invalid misc:6   Missed beacon:0
User avatar
Posts: 2038
Joined: Tue Nov 22, 2011 11:51 pm
by M33P » Sat Apr 13, 2013 10:23 pm
jbeale wrote:I'm using a Ralink RT5370 USB-WiFi module that works trouble-free for some time, between 6 hours and 2 days, and then it just cuts out and does not come back. If I reboot, everything is fine again. This is a R-Pi model A with 4-port hub, voltage levels are OK (TP1/TP2 = 4.9 V). I also have a keyboard and two FTDI serial ports on the hub. Any hints on what the problem might be, and/or how can I get it to reset on its own without needing a full reboot? I am using a fixed IP address, not DHCP. But previously I tried DHCP with the same behavior. Below is an example of the end of the /var/log/daemon.log after a cutout:


jbeale wrote:Ah, how very interesting! So the linux driver is apparently not compatible with the power-saving function, I gather. Would be nice if it was. Anyway I did not have that line in my 'interfaces' file, I will give this a try. I can see that the change did show up as "Power Management:off" from iwconfig.


Known issue.

The dropout with power management enabled is due to a quirky deficiency in handling multiple URBs queued for a single device in the USB driver. Power management will typically wake a thread every 200-500ms which will activate/suspend the radio frontend of the wifi adapter - this causes a flurry of control transactions which under certain circumstances cause USB packets for the device to get "stuck" in the queue.

This behaviour is reproducible most easily on a Pi with no periodic endpoint devices attached (Ralink adapters are favourites because they have only bulk endpoints). Model As exacerbate the problem because of no ethernet chip/hub. Probably the reason you're not seeing this until several hours have passed is because your 4-port hub has an enabled periodic endpoint, but hubs typically have a polling period of several dozen milliseconds. Having multiple endpoints/transactions queued at once causes the stuck packets to get properly processed.
Posts: 199
Joined: Sun Sep 02, 2012 1:14 pm
by jbeale » Sat Apr 13, 2013 11:44 pm
Thanks for that detailed explanation. Known- Ok, but until now, not by me :-)
User avatar
Posts: 2038
Joined: Tue Nov 22, 2011 11:51 pm
by jbeale » Wed Apr 17, 2013 4:46 pm
As a followup, the RT5370 continues to cut out after about 24 hours despite turning off the power control feature. Same error message about "link beat lost" in /var/log/daemon.log file. Unplugging the USB device and then replugging restores the network, without any additional action. I'm not using DHCP in this setup, but maybe my router is doing something even with fixed IP addresses after 24 hours?

I guess I can do a hardware workaround involving a GPIO to a FET switching +5V USB power to the USB-Wifi device to reset it, when a chron job detects the network interface is down. Also, I have a different brand of WiFi device in the mail, maybe that will work better.
User avatar
Posts: 2038
Joined: Tue Nov 22, 2011 11:51 pm
by pjc123 » Wed Apr 17, 2013 8:07 pm
Is re-seating the wifi dongle the only way to reset it? Can you reset it in software as follows:

sudo ifdown wlan0
sudo ifup --force wlan0

If so, you can use a software workaround instead. I set up a script that checks if the network is active every 15 seconds (You could make it longer), and if not it runs the top two commands.
My Project Website:
http://www.flaminghellmet.com/
Posts: 910
Joined: Thu Mar 29, 2012 3:37 pm
by jbeale » Fri Apr 19, 2013 5:56 am
pjc123 wrote:sudo ifdown wlan0
sudo ifup --force wlan0

Link just dropped again after another day and a half, so I tried this. Yay, it works!
...although now I wonder why this isn't already done automatically, when the wifi link drops. Anyway, I'll put a cron job to do this in case of future trouble. For reference, my 'fixnet' script is below.

Code: Select all
#!/bin/sh
echo "Checking if wlan0 active..."

ifconfig wlan0 | grep "inet addr" >>/dev/null

if [ $? -eq  0 ]
then
  echo "Network active"
else
  echo "Network down, fixing..."
  sudo ifdown wlan0
  sudo ifup --force wlan0
fi
User avatar
Posts: 2038
Joined: Tue Nov 22, 2011 11:51 pm
by pjc123 » Fri Apr 19, 2013 12:26 pm
jbeale wrote:
pjc123 wrote:sudo ifdown wlan0
sudo ifup --force wlan0

Link just dropped again after another day and a half, so I tried this. Yay, it works!
...although now I wonder why this isn't already done automatically, when the wifi link drops. Anyway, I'll put a cron job to do this in case of future trouble. For reference, my 'fixnet' script is below.

Code: Select all
#!/bin/sh
echo "Checking if wlan0 active..."

ifconfig wlan0 | grep "inet addr" >>/dev/null

if [ $? -eq  0 ]
then
  echo "Network active"
else
  echo "Network down, fixing..."
  sudo ifdown wlan0
  sudo ifup --force wlan0
fi


I had originally looked at using the ifconfig command to test for a connection, but it did not reliably report back a valid connection, presumably due to the way my wifi was locked up and not working. But if ifconfig works for you then great. Also, my connection would never recover by itself. Switching to a ping test worked for me 100% of the time. I also noticed that on the Rev1 board I could use 1 ping, but the Rev2 required two pings to get a reliable response. I use my router to check the network connection, but you could use any valid reachable address. Here is the meat of my program:

Code: Select all
#!/bin/bash

# Which Interface do you want to check
wlan='wlan0'
# Which address do you want to ping to see if you can connect
pingip='192.168.2.1'

# Perform the network check and reset if necessary
/bin/ping -c 2 -I $wlan $pingip > /dev/null 2> /dev/null
if [ $? -ge 1 ] ; then
    echo "Network is DOWN.  Perform a reset."
    /sbin/ifdown $wlan
    sleep 5
    /sbin/ifup --force $wlan
else
    echo "Network is UP. Just exit the program."   
fi
My Project Website:
http://www.flaminghellmet.com/
Posts: 910
Joined: Thu Mar 29, 2012 3:37 pm
by pluggy » Fri Apr 19, 2013 1:03 pm
Make sure you're using the latest image or do the full apt-get update & apt-get upgrade.

It might be worth looking at rpi-update too, since the very latest firmware upgrades have improved the Pi's non too healthy USB implementation. If it breaks something else you didn't get it from me ;)
Don't judge Linux by the Pi.......
User avatar
Posts: 2493
Joined: Thu May 31, 2012 3:52 pm
Location: Barnoldswick, Lancashire,UK
by jbeale » Fri Apr 19, 2013 3:17 pm
My kernel is fairly recent...
Code: Select all
pi@rp3 ~ $ uname -a
Linux rp3 3.6.11+ #408 PREEMPT Wed Apr 10 20:33:39 BST 2013 armv6l GNU/Linux


By the way, the shell script I posted above works as expected when called from a login session, but for some reason seems to shut down /restart wlan0 every hour when it is run as a cron job, even when the network was already working ok.
User avatar
Posts: 2038
Joined: Tue Nov 22, 2011 11:51 pm
by pluggy » Fri Apr 19, 2013 3:45 pm
I have 2 Pi's running with RT5370 Wifi adaptors, both long term stable, one has the same version kernel as yours, one has the 'stock' #371 from the current image (no rpi-update). The one with the newer kernel is for the benefit of a USB webcam attached to it.

root@raspberrypi3:~# uptime
16:30:45 up 4 days, 17:58, 1 user, load average: 1.96, 1.27, 1.13
root@raspberrypi3:~# lsusb
Bus 001 Device 002: ID 0424:9512 Standard Microsystems Corp.
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 003: ID 0424:ec00 Standard Microsystems Corp.
Bus 001 Device 004: ID 148f:5370 Ralink Technology, Corp. RT5370 Wireless Adapter
Bus 001 Device 005: ID 0403:6001 Future Technology Devices International, Ltd FT232 USB-Serial (UART) IC
root@raspberrypi3:~# uname -a
Linux raspberrypi3 3.6.11+ #371 PREEMPT Thu Feb 7 16:31:35 GMT 2013 armv6l GNU/Linux

It doesn't have anything watching the wireless link.

You can have a look at what its doing at

http://pluggy.is-a-geek.com/index.html

It isn't all done by the one Pi, it has an Arduino and a another Pi helping it......
Don't judge Linux by the Pi.......
User avatar
Posts: 2493
Joined: Thu May 31, 2012 3:52 pm
Location: Barnoldswick, Lancashire,UK
by jbeale » Fri Apr 19, 2013 5:55 pm
Wow pluggy, that's a lot of data! Neat stuff.

By the way, if you intend that webpage to be viewed outside your LAN, I think the 192.168.x.x address hardcoded on the page will not work as intended. See also: http://en.wikipedia.org/wiki/Private_network

Code: Select all
<img alt="logo" src="http://192.168.1.248/camera.jpeg" /><img alt="background" src="eyetoy.jpg" />
User avatar
Posts: 2038
Joined: Tue Nov 22, 2011 11:51 pm
by jbeale » Thu Apr 25, 2013 5:40 am
To follow up on my original RT5370 WiFi problem, I had a workaround of running a process from cron to check the wifi link and restart if needed. But this was of course not fixing the original problem. According to /var/log/daemon.log the WiFi still dropped out several times a day (but often quickly restarting by itself).

Yesterday I pulled out the RT5370 and replaced it with a 0bda:8176 Realtek Semiconductor Corp. RTL8188CUS 802.11n WLAN Adapter that I got for $9 on ebay (package says "COMFAST" brand, with mostly Chinese text). This has now run over 24 hours without dropping out, so I think this will be my solution.

The ifconfig command shows that Ii have more dropped packets than received packets, but despite that the connection works and the ping times to my router seem ok.

Code: Select all
pi@rp3 ~ $ ifconfig wlan0
wlan0     Link encap:Ethernet  HWaddr 00:0f:13:32:0b:5d
          inet addr:192.168.10.146  Bcast:192.168.10.255  Mask:255.255.255.0
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:25889 errors:0 dropped:26354 overruns:0 frame:0
          TX packets:3941 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:8071791 (7.6 MiB)  TX bytes:2401414 (2.2 MiB)

--- 192.168.10.1 ping statistics ---
50 packets transmitted, 50 received, 0% packet loss, time 49082ms
rtt min/avg/max/mdev = 1.100/2.764/26.192/5.056 ms
User avatar
Posts: 2038
Joined: Tue Nov 22, 2011 11:51 pm
by M33P » Thu Apr 25, 2013 10:25 pm
Poking this thread because it is one of my test cases.

jbeale - can you retry usage of your RT5370 with the latest rpi-update kernel?
Posts: 199
Joined: Sun Sep 02, 2012 1:14 pm
by jbeale » Fri Apr 26, 2013 4:28 am
Ok, did rpi-update and reininstalled the RT5370. So far so good, but will need to wait a day or two before I can really compare; before there were usually 2 or 3 signal drops per 24 hours.

Code: Select all
pi@rp3 ~ $ lsusb
Bus 001 Device 002: ID 1a40:0101 Terminus Technology Inc. 4-Port HUB
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 003: ID 413c:2005 Dell Computer Corp. RT7D50 Keyboard
Bus 001 Device 004: ID 0403:6001 Future Technology Devices International, Ltd FT232 USB-Serial (UART) IC
Bus 001 Device 007: ID 148f:5370 Ralink Technology, Corp. RT5370 Wireless Adapter
Bus 001 Device 006: ID 0403:6001 Future Technology Devices International, Ltd FT232 USB-Serial (UART) IC
pi@rp3 ~ $ uname -a
Linux rp3 3.6.11+ #416 PREEMPT Mon Apr 22 21:58:42 BST 2013 armv6l GNU/Linux
pi@rp3 ~ $ ifconfig wlan0
wlan0     Link encap:Ethernet  HWaddr 00:0f:53:87:08:2a
          inet addr:192.168.10.146  Bcast:192.168.10.255  Mask:255.255.255.0
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:4539 errors:0 dropped:5 overruns:0 frame:0
          TX packets:693 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:1361314 (1.2 MiB)  TX bytes:228503 (223.1 KiB)
User avatar
Posts: 2038
Joined: Tue Nov 22, 2011 11:51 pm
by jbeale » Fri Apr 26, 2013 6:46 am
By the way, the RT5370 consistently shows 5 or 6% packet loss with a 10-minute 'ping' session (600 pings). The RTL8188CUS gives me 0% packet loss in the same circumstances.

Code: Select all
pi@rp3 ~ $ uname -a
Linux rp3 3.6.11+ #416 PREEMPT Mon Apr 22 21:58:42 BST 2013 armv6l GNU/Linux

Bus 001 Device 009: ID 148f:5370 Ralink Technology, Corp. RT5370 Wireless Adapter

--- 192.168.10.1 ping statistics ---
600 packets transmitted, 563 received, 6% packet loss, time 600070ms
rtt min/avg/max/mdev = 0.920/1.577/33.003/1.653 ms

--- 192.168.10.1 ping statistics ---
600 packets transmitted, 560 received, 6% packet loss, time 600084ms
rtt min/avg/max/mdev = 0.922/2.012/65.226/4.105 ms

Bus 001 Device 008: ID 0bda:8176 Realtek Semiconductor Corp. RTL8188CUS 802.11n WLAN Adapter

--- 192.168.10.1 ping statistics ---
600 packets transmitted, 600 received, 0% packet loss, time 599984ms
rtt min/avg/max/mdev = 1.088/3.421/113.773/7.494 ms

--- 192.168.10.1 ping statistics ---
600 packets transmitted, 600 received, 0% packet loss, time 599984ms
rtt min/avg/max/mdev = 1.087/3.340/90.509/7.091 ms

--- 192.168.10.1 ping statistics ---
600 packets transmitted, 600 received, 0% packet loss, time 599982ms
rtt min/avg/max/mdev = 1.056/2.599/67.723/4.808 ms

======
Bus 001 Device 009: ID 148f:5370 Ralink Technology, Corp. RT5370 Wireless Adapter

--- 192.168.10.1 ping statistics ---
600 packets transmitted, 568 received, 5% packet loss, time 600080ms
rtt min/avg/max/mdev = 0.941/1.748/30.918/2.087 ms
User avatar
Posts: 2038
Joined: Tue Nov 22, 2011 11:51 pm
by jbeale » Sat Apr 27, 2013 6:15 am
Ok, after 24 hours I am sorry to say that the April 22 kernel build does no better than before, as far as RT5370 WiFi dropouts go. Relevant section of /var/log/daemon.log copied below. It was fine for about 10 hours after first plugin, but then the dropouts started.

Code: Select all
Apr 25 23:53:30 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 00:53:22 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 01:53:14 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 02:53:06 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 03:52:58 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 04:52:50 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 05:52:42 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 06:52:34 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 07:52:26 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 08:52:18 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 09:17:47 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:23:69:c7:88:6c reason=4
Apr 26 09:17:47 rp3 ifplugd(wlan0)[3052]: Link beat lost.
Apr 26 09:17:48 rp3 wpa_supplicant[3076]: wlan0: SME: Trying to authenticate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 09:17:48 rp3 wpa_supplicant[3076]: wlan0: Trying to associate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 09:17:48 rp3 wpa_supplicant[3076]: wlan0: Associated with 00:23:69:c7:88:6c
Apr 26 09:17:48 rp3 ifplugd(wlan0)[3052]: Link beat detected.
Apr 26 09:17:49 rp3 wpa_supplicant[3076]: wlan0: WPA: Key negotiation completed with 00:23:69:c7:88:6c [PTK=CCMP GTK=TKIP]
Apr 26 09:17:49 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:23:69:c7:88:6c completed (reauth) [id=1 id_str=]
Apr 26 09:31:02 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:23:69:c7:88:6c reason=4
Apr 26 09:31:02 rp3 ifplugd(wlan0)[3052]: Link beat lost.
Apr 26 09:31:10 rp3 wpa_supplicant[3076]: wlan0: SME: Trying to authenticate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 09:31:10 rp3 wpa_supplicant[3076]: wlan0: Trying to associate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 09:31:10 rp3 wpa_supplicant[3076]: wlan0: Associated with 00:23:69:c7:88:6c
Apr 26 09:31:10 rp3 wpa_supplicant[3076]: wlan0: WPA: Key negotiation completed with 00:23:69:c7:88:6c [PTK=CCMP GTK=TKIP]
Apr 26 09:31:10 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:23:69:c7:88:6c completed (reauth) [id=1 id_str=]
Apr 26 09:31:11 rp3 ifplugd(wlan0)[3052]: Link beat detected.
Apr 26 09:39:21 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:23:69:c7:88:6c reason=4
Apr 26 09:39:21 rp3 ifplugd(wlan0)[3052]: Link beat lost.
Apr 26 09:39:22 rp3 wpa_supplicant[3076]: wlan0: SME: Trying to authenticate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 09:39:22 rp3 wpa_supplicant[3076]: wlan0: Trying to associate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 09:39:22 rp3 wpa_supplicant[3076]: wlan0: Associated with 00:23:69:c7:88:6c
Apr 26 09:39:23 rp3 wpa_supplicant[3076]: wlan0: WPA: Key negotiation completed with 00:23:69:c7:88:6c [PTK=CCMP GTK=TKIP]
Apr 26 09:39:23 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:23:69:c7:88:6c completed (reauth) [id=1 id_str=]
Apr 26 09:39:23 rp3 ifplugd(wlan0)[3052]: Link beat detected.
Apr 26 09:49:58 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:23:69:c7:88:6c reason=4
Apr 26 09:49:58 rp3 ifplugd(wlan0)[3052]: Link beat lost.
Apr 26 09:49:59 rp3 wpa_supplicant[3076]: wlan0: SME: Trying to authenticate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 09:49:59 rp3 wpa_supplicant[3076]: wlan0: Trying to associate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 09:49:59 rp3 wpa_supplicant[3076]: wlan0: Associated with 00:23:69:c7:88:6c
Apr 26 09:50:00 rp3 wpa_supplicant[3076]: wlan0: WPA: Key negotiation completed with 00:23:69:c7:88:6c [PTK=CCMP GTK=TKIP]
Apr 26 09:50:00 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:23:69:c7:88:6c completed (reauth) [id=1 id_str=]
Apr 26 09:50:00 rp3 ifplugd(wlan0)[3052]: Link beat detected.
Apr 26 09:52:10 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 10:52:02 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 11:37:05 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:23:69:c7:88:6c reason=4
Apr 26 11:37:05 rp3 ifplugd(wlan0)[3052]: Link beat lost.
Apr 26 11:37:06 rp3 wpa_supplicant[3076]: wlan0: SME: Trying to authenticate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 11:37:06 rp3 wpa_supplicant[3076]: wlan0: Trying to associate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 11:37:06 rp3 wpa_supplicant[3076]: wlan0: Associated with 00:23:69:c7:88:6c
Apr 26 11:37:07 rp3 wpa_supplicant[3076]: wlan0: WPA: Key negotiation completed with 00:23:69:c7:88:6c [PTK=CCMP GTK=TKIP]
Apr 26 11:37:07 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:23:69:c7:88:6c completed (reauth) [id=1 id_str=]
Apr 26 11:37:07 rp3 ifplugd(wlan0)[3052]: Link beat detected.
Apr 26 11:38:40 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:23:69:c7:88:6c reason=4
Apr 26 11:38:40 rp3 ifplugd(wlan0)[3052]: Link beat lost.
Apr 26 11:38:41 rp3 wpa_supplicant[3076]: wlan0: SME: Trying to authenticate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 11:38:41 rp3 wpa_supplicant[3076]: wlan0: Trying to associate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 11:38:41 rp3 wpa_supplicant[3076]: wlan0: Associated with 00:23:69:c7:88:6c
Apr 26 11:38:42 rp3 wpa_supplicant[3076]: wlan0: WPA: Key negotiation completed with 00:23:69:c7:88:6c [PTK=CCMP GTK=TKIP]
Apr 26 11:38:42 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:23:69:c7:88:6c completed (reauth) [id=1 id_str=]
Apr 26 11:38:42 rp3 ifplugd(wlan0)[3052]: Link beat detected.
Apr 26 11:51:54 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 12:13:13 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:23:69:c7:88:6c reason=4
Apr 26 12:13:13 rp3 ifplugd(wlan0)[3052]: Link beat lost.
Apr 26 12:13:14 rp3 wpa_supplicant[3076]: wlan0: SME: Trying to authenticate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 12:13:14 rp3 wpa_supplicant[3076]: wlan0: Trying to associate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 12:13:14 rp3 wpa_supplicant[3076]: wlan0: Associated with 00:23:69:c7:88:6c
Apr 26 12:13:14 rp3 ifplugd(wlan0)[3052]: Link beat detected.
Apr 26 12:13:15 rp3 wpa_supplicant[3076]: wlan0: WPA: Key negotiation completed with 00:23:69:c7:88:6c [PTK=CCMP GTK=TKIP]
Apr 26 12:13:15 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:23:69:c7:88:6c completed (reauth) [id=1 id_str=]
Apr 26 12:51:46 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 13:08:14 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:23:69:c7:88:6c reason=4
Apr 26 13:08:14 rp3 ifplugd(wlan0)[3052]: Link beat lost.
Apr 26 13:08:15 rp3 wpa_supplicant[3076]: wlan0: SME: Trying to authenticate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 13:08:15 rp3 wpa_supplicant[3076]: wlan0: Trying to associate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 13:08:15 rp3 wpa_supplicant[3076]: wlan0: Associated with 00:23:69:c7:88:6c
Apr 26 13:08:16 rp3 wpa_supplicant[3076]: wlan0: WPA: Key negotiation completed with 00:23:69:c7:88:6c [PTK=CCMP GTK=TKIP]
Apr 26 13:08:16 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:23:69:c7:88:6c completed (reauth) [id=1 id_str=]
Apr 26 13:08:16 rp3 ifplugd(wlan0)[3052]: Link beat detected.
Apr 26 13:51:38 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 14:51:30 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 15:51:22 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 16:47:55 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:23:69:c7:88:6c reason=4
Apr 26 16:47:55 rp3 ifplugd(wlan0)[3052]: Link beat lost.
Apr 26 16:47:56 rp3 wpa_supplicant[3076]: wlan0: SME: Trying to authenticate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 16:47:56 rp3 wpa_supplicant[3076]: wlan0: Trying to associate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 16:47:56 rp3 wpa_supplicant[3076]: wlan0: Associated with 00:23:69:c7:88:6c
Apr 26 16:47:57 rp3 wpa_supplicant[3076]: wlan0: WPA: Key negotiation completed with 00:23:69:c7:88:6c [PTK=CCMP GTK=TKIP]
Apr 26 16:47:57 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:23:69:c7:88:6c completed (reauth) [id=1 id_str=]
Apr 26 16:47:57 rp3 ifplugd(wlan0)[3052]: Link beat detected.
Apr 26 16:51:14 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 17:27:41 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:23:69:c7:88:6c reason=4
Apr 26 17:27:41 rp3 ifplugd(wlan0)[3052]: Link beat lost.
Apr 26 17:27:49 rp3 wpa_supplicant[3076]: wlan0: SME: Trying to authenticate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 17:27:49 rp3 wpa_supplicant[3076]: wlan0: Trying to associate with 00:23:69:c7:88:6c (SSID='plugh' freq=2412 MHz)
Apr 26 17:27:49 rp3 wpa_supplicant[3076]: wlan0: Associated with 00:23:69:c7:88:6c
Apr 26 17:27:49 rp3 wpa_supplicant[3076]: wlan0: WPA: Key negotiation completed with 00:23:69:c7:88:6c [PTK=CCMP GTK=TKIP]
Apr 26 17:27:49 rp3 wpa_supplicant[3076]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:23:69:c7:88:6c completed (reauth) [id=1 id_str=]
Apr 26 17:27:49 rp3 ifplugd(wlan0)[3052]: Link beat detected.
Apr 26 17:51:06 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 26 18:50:58 rp3 wpa_supplicant[3076]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]


Code: Select all
pi@rp3 ~ $ ifconfig wlan0
wlan0     Link encap:Ethernet  HWaddr 00:0f:53:87:08:2a
          inet addr:192.168.10.146  Bcast:192.168.10.255  Mask:255.255.255.0
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:83877 errors:0 dropped:18 overruns:0 frame:0
          TX packets:6209 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:28012728 (26.7 MiB)  TX bytes:2501639 (2.3 MiB)

pi@rp3 ~ $ uname -a
Linux rp3 3.6.11+ #416 PREEMPT Mon Apr 22 21:58:42 BST 2013 armv6l GNU/Linux
pi@rp3 ~ $ uptime
 23:14:51 up 1 day,  3:38,  2 users,  load average: 0.04, 0.05, 0.05
pi@rp3 ~ $ lsusb
Bus 001 Device 002: ID 1a40:0101 Terminus Technology Inc. 4-Port HUB
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 003: ID 413c:2005 Dell Computer Corp. RT7D50 Keyboard
Bus 001 Device 004: ID 0403:6001 Future Technology Devices International, Ltd FT232 USB-Serial (UART) IC
Bus 001 Device 009: ID 148f:5370 Ralink Technology, Corp. RT5370 Wireless Adapter
Bus 001 Device 006: ID 0403:6001 Future Technology Devices International, Ltd FT232 USB-Serial (UART) IC
User avatar
Posts: 2038
Joined: Tue Nov 22, 2011 11:51 pm
by M33P » Sat Apr 27, 2013 7:30 am
To be clear - is there any indication (with time/datestamp) when your script kicks the wlan interface back into operation?

What does dmesg say? (it should record both wlan association events and if anything really did break on the adapter)

Your deassociation reason code (4) is timeout due to inactivity. Is there nominally any activity on the wlan link?
Posts: 199
Joined: Sun Sep 02, 2012 1:14 pm
by jbeale » Sat Apr 27, 2013 3:14 pm
The only "intentional" wifi activity is a file upload every hour at 20 minutes past the hour, but 'ntpd' is always running in the background. My FixWifi script is run only once an hour, at 10 minutes past the hour. I did not see it become active in this case; each time the device dropped and then came back quickly on its own, so maybe it is not really a problem? But the other wifi adaptor I have, the RTL8188CUS ran for 24 hours under the same circumstances, without any such CTRL-EVENT-DISCONNECTED messages. Is it possible the RTL8188 is generating some keep-alive traffic all on its own, to prevent an inactivity timeout that would otherwise happen?

dmesg output is below.

Code: Select all
[13649.492957] usb 1-1.3: new high-speed USB device number 9 using dwc_otg
[13649.611189] usb 1-1.3: New USB device found, idVendor=148f, idProduct=5370
[13649.611218] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[13649.611234] usb 1-1.3: Product: 802.11 n WLAN
[13649.611267] usb 1-1.3: Manufacturer: Ralink
[13649.611283] usb 1-1.3: SerialNumber: 1.0
[13649.703002] usb 1-1.3: reset high-speed USB device number 9 using dwc_otg
[13649.839123] ieee80211 phy1: Selected rate control algorithm 'minstrel_ht'
[13649.846601] Registered led device: rt2800usb-phy1::radio
[13649.846773] Registered led device: rt2800usb-phy1::assoc
[13649.847104] Registered led device: rt2800usb-phy1::quality
[13653.084836] wlan0: authenticate with 00:23:69:c7:88:6c
[13653.144045] wlan0: direct probe to 00:23:69:c7:88:6c (try 1/3)
[13653.352946] wlan0: send auth to 00:23:69:c7:88:6c (try 2/3)
[13653.357231] wlan0: authenticated
[13653.402998] wlan0: associate with 00:23:69:c7:88:6c (try 1/3)
[13653.405720] wlan0: RX AssocResp from 00:23:69:c7:88:6c (capab=0x411 status=0 aid=2)
[13653.423842] wlan0: associated
[49290.927265] cfg80211: Calling CRDA to update world regulatory domain
[49292.467144] wlan0: authenticate with 00:23:69:c7:88:6c
[49292.551344] wlan0: send auth to 00:23:69:c7:88:6c (try 1/3)
[49292.553140] wlan0: authenticated
[49292.600435] wlan0: associate with 00:23:69:c7:88:6c (try 1/3)
[49292.607144] wlan0: RX AssocResp from 00:23:69:c7:88:6c (capab=0x411 status=0 aid=2)
[49292.626062] wlan0: associated
[50085.911911] cfg80211: Calling CRDA to update world regulatory domain
[50093.913309] wlan0: authenticate with 00:23:69:c7:88:6c
[50093.996982] wlan0: send auth to 00:23:69:c7:88:6c (try 1/3)
[50094.002339] wlan0: authenticated
[50094.046404] wlan0: associate with 00:23:69:c7:88:6c (try 1/3)
[50094.051035] wlan0: RX AssocResp from 00:23:69:c7:88:6c (capab=0x411 status=0 aid=2)
[50094.069727] wlan0: associated
[50584.887709] cfg80211: Calling CRDA for country: US
[50586.439178] wlan0: authenticate with 00:23:69:c7:88:6c
[50586.523310] wlan0: send auth to 00:23:69:c7:88:6c (try 1/3)
[50586.537407] wlan0: authenticated
[50586.582440] wlan0: associate with 00:23:69:c7:88:6c (try 1/3)
[50586.597743] wlan0: RX AssocResp from 00:23:69:c7:88:6c (capab=0x411 status=0 aid=2)
[50586.620798] wlan0: associated
[51221.949862] cfg80211: Calling CRDA to update world regulatory domain
[51223.489827] wlan0: authenticate with 00:23:69:c7:88:6c
[51223.574192] wlan0: send auth to 00:23:69:c7:88:6c (try 1/3)
[51223.575953] wlan0: authenticated
[51223.623275] wlan0: associate with 00:23:69:c7:88:6c (try 1/3)
[51223.627254] wlan0: RX AssocResp from 00:23:69:c7:88:6c (capab=0x411 status=0 aid=2)
[51223.645949] wlan0: associated
[57649.119142] cfg80211: Calling CRDA for country: US
[57650.657987] wlan0: authenticate with 00:23:69:c7:88:6c
[57650.742978] wlan0: send auth to 00:23:69:c7:88:6c (try 1/3)
[57650.751359] wlan0: authenticated
[57650.792032] wlan0: associate with 00:23:69:c7:88:6c (try 1/3)
[57650.803980] wlan0: RX AssocResp from 00:23:69:c7:88:6c (capab=0x411 status=0 aid=2)
[57650.823977] wlan0: associated
[57744.158134] cfg80211: Calling CRDA to update world regulatory domain
[57745.704796] wlan0: authenticate with 00:23:69:c7:88:6c
[57745.785888] wlan0: send auth to 00:23:69:c7:88:6c (try 1/3)
[57745.787837] wlan0: authenticated
[57745.835185] wlan0: associate with 00:23:69:c7:88:6c (try 1/3)
[57745.839828] wlan0: RX AssocResp from 00:23:69:c7:88:6c (capab=0x411 status=0 aid=2)
[57745.858201] wlan0: associated
[59817.190043] cfg80211: Calling CRDA to update world regulatory domain
[59818.729762] wlan0: authenticate with 00:23:69:c7:88:6c
[59818.813175] wlan0: send auth to 00:23:69:c7:88:6c (try 1/3)
[59818.828577] wlan0: authenticated
[59818.872597] wlan0: associate with 00:23:69:c7:88:6c (try 1/3)
[59818.882107] wlan0: RX AssocResp from 00:23:69:c7:88:6c (capab=0x411 status=0 aid=2)
[59818.900664] wlan0: associated
[63118.337474] cfg80211: Calling CRDA for country: US
[63119.876944] wlan0: authenticate with 00:23:69:c7:88:6c
[63119.962015] wlan0: send auth to 00:23:69:c7:88:6c (try 1/3)
[63119.963755] wlan0: authenticated
[63120.010420] wlan0: associate with 00:23:69:c7:88:6c (try 1/3)
[63120.014975] wlan0: RX AssocResp from 00:23:69:c7:88:6c (capab=0x411 status=0 aid=2)
[63120.033495] wlan0: associated
[76299.807199] cfg80211: Calling CRDA to update world regulatory domain
[76301.345885] wlan0: authenticate with 00:23:69:c7:88:6c
[76301.430843] wlan0: send auth to 00:23:69:c7:88:6c (try 1/3)
[76301.435024] wlan0: authenticated
[76301.479827] wlan0: associate with 00:23:69:c7:88:6c (try 1/3)
[76301.482825] wlan0: RX AssocResp from 00:23:69:c7:88:6c (capab=0x411 status=0 aid=2)
[76301.501587] wlan0: associated
[78685.803440] cfg80211: Calling CRDA to update world regulatory domain
[78693.803091] wlan0: authenticate with 00:23:69:c7:88:6c
[78693.887257] wlan0: send auth to 00:23:69:c7:88:6c (try 1/3)
[78693.889203] wlan0: authenticated
[78693.926517] wlan0: associate with 00:23:69:c7:88:6c (try 1/3)
[78693.929273] wlan0: RX AssocResp from 00:23:69:c7:88:6c (capab=0x411 status=0 aid=2)
[78693.946401] wlan0: associated
[88717.163117] cfg80211: Calling CRDA for country: US
[88718.704797] wlan0: authenticate with 00:23:69:c7:88:6c
[88718.789491] wlan0: send auth to 00:23:69:c7:88:6c (try 1/3)
[88718.793012] wlan0: authenticated
[88718.838485] wlan0: associate with 00:23:69:c7:88:6c (try 1/3)
[88718.841227] wlan0: RX AssocResp from 00:23:69:c7:88:6c (capab=0x411 status=0 aid=2)
[88718.859387] wlan0: associated
[128020.437509] cfg80211: Calling CRDA to update world regulatory domain
[128021.976163] wlan0: authenticate with 00:23:69:c7:88:6c
[128022.060656] wlan0: send auth to 00:23:69:c7:88:6c (try 1/3)
[128022.062896] wlan0: authenticated
[128022.109754] wlan0: associate with 00:23:69:c7:88:6c (try 1/3)
[128022.114024] wlan0: RX AssocResp from 00:23:69:c7:88:6c (capab=0x411 status=0 aid=2)
[128022.132656] wlan0: associated


..and by the way, why are the Rx and Tx data size so much different between the values reported from different tools?
ifconfig says "TX bytes:3904896 (3.7 MiB)" and ethtool says "tx_bytes: 421543". Is this total packet size vs payload data?

Code: Select all
pi@rp3:~$ ethtool -S wlan0
NIC statistics:
     rx_packets: 341820
     rx_bytes: 39742251
     wep_weak_iv_count: 0
     rx_duplicates: 15
     rx_fragments: 179472
     rx_dropped: 78
     tx_packets: 1077
     tx_bytes: 421543
     tx_fragments: 1077
     tx_filtered: 0
     tx_retry_failed: 22
     tx_retries: 235
     beacon_loss: 0
     sta_state: 4
     txrate: 1000000
     rxrate: 1000000
     signal: 210
     channel: 2412
     noise: 18446744073709551615
     ch_time: 1694406
     ch_time_busy: 1694406
     ch_time_ext_busy: 0
     ch_time_rx: 18446744073709551615
     ch_time_tx: 18446744073709551615
pi@rp3:~$ ifconfig wlan0
wlan0     Link encap:Ethernet  HWaddr 00:0f:53:87:08:2a
          inet addr:192.168.10.146  Bcast:192.168.10.255  Mask:255.255.255.0
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:133134 errors:0 dropped:31 overruns:0 frame:0
          TX packets:8461 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:44152571 (42.1 MiB)  TX bytes:3904896 (3.7 MiB)
User avatar
Posts: 2038
Joined: Tue Nov 22, 2011 11:51 pm
by M33P » Sun Apr 28, 2013 11:00 am
In your application, how are you using all the other USB devices (simultaneously/polling)? Can you test the 5370 in isolation (nothing else plugged in) and see if the same behaviour is exhibited?

Also can you do a lsusb -v output for the RTL8188CU adapter.
Posts: 199
Joined: Sun Sep 02, 2012 1:14 pm
by jbeale » Mon Apr 29, 2013 2:43 pm
THe two FTDI serial devices are never transferring data at the same time. One sends a line of text at a fixed interval, approximately 7 seconds. One line of text looks something like this:
Code: Select all
0.20,206468,206484,206483,11,2013-04-15 23:45:01.812240,+07.23116E+0

After that is done, a short bi-directional transaction occurs on the second FTDI device with maybe 20 characters of text returned, then both are quiet for another seven seconds. I'll shut down the logging, take out the FTDI parts and see what happens. 'lsusb -v' output for each adaptor in turn, is shown below.

Code: Select all

Bus 001 Device 009: ID 148f:5370 Ralink Technology, Corp. RT5370 Wireless Adapter
Couldn't open device, some information will be missing
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.00
  bDeviceClass            0 (Defined at Interface level)
  bDeviceSubClass         0
  bDeviceProtocol         0
  bMaxPacketSize0        64
  idVendor           0x148f Ralink Technology, Corp.
  idProduct          0x5370 RT5370 Wireless Adapter
  bcdDevice            1.01
  iManufacturer           1
  iProduct                2
  iSerial                 3
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength           67
    bNumInterfaces          1
    bConfigurationValue     1
    iConfiguration          0
    bmAttributes         0x80
      (Bus Powered)
    MaxPower              450mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           7
      bInterfaceClass       255 Vendor Specific Class
      bInterfaceSubClass    255 Vendor Specific Subclass
      bInterfaceProtocol    255 Vendor Specific Protocol
      iInterface              5
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x01  EP 1 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x02  EP 2 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x03  EP 3 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x04  EP 4 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x05  EP 5 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x06  EP 6 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0


Code: Select all
Bus 001 Device 010: ID 0bda:8176 Realtek Semiconductor Corp. RTL8188CUS 802.11n WLAN Adapter
Couldn't open device, some information will be missing
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.00
  bDeviceClass            0 (Defined at Interface level)
  bDeviceSubClass         0
  bDeviceProtocol         0
  bMaxPacketSize0        64
  idVendor           0x0bda Realtek Semiconductor Corp.
  idProduct          0x8176 RTL8188CUS 802.11n WLAN Adapter
  bcdDevice            2.00
  iManufacturer           1
  iProduct                2
  iSerial                 3
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength           46
    bNumInterfaces          1
    bConfigurationValue     1
    iConfiguration          0
    bmAttributes         0xa0
      (Bus Powered)
      Remote Wakeup
    MaxPower              500mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           4
      bInterfaceClass       255 Vendor Specific Class
      bInterfaceSubClass    255 Vendor Specific Subclass
      bInterfaceProtocol    255 Vendor Specific Protocol
      iInterface              0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x02  EP 2 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x03  EP 3 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x84  EP 4 IN
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0040  1x 64 bytes
        bInterval               1
User avatar
Posts: 2038
Joined: Tue Nov 22, 2011 11:51 pm
by Mr.Dave » Mon Apr 29, 2013 3:03 pm
I have the RT5370 WiFi adapter for my Pi running RaspBMC and it will stay connected for weeks at a time, so if it does drop out at some point it must be reconnecting on its own

Which I know it does because I can reboot the router and it will be connected next time I use it

Check RaspBMC wifi config to see how they are managing it
User avatar
Posts: 148
Joined: Sat Jun 30, 2012 6:59 pm
by jbeale » Tue Apr 30, 2013 4:41 am
Ok, so for what it's worth, the RT5370 wifi adaptor behaves the same even with no FTDI devices in the system. I took them out around 8 am this morning, and at 5:54 pm this afternoon I got the same CTRL-EVENT-DISCONNECTED as I saw before. The device reconnected on its own within a few seconds, before my FixWiFi script activated (that only runs once each hour, at 10 minutes past), so maybe this isn't really a problem. Just reporting it here in case it means something to anyone. The wifi is connected to a 4-port USB hub, with nothing else in it. I never get the DISCONNECTED message while using the RTL8188CUS device.

Code: Select all
Apr 29 08:42:44 rp3 wpa_supplicant[7555]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 29 09:42:36 rp3 wpa_supplicant[7555]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 29 10:42:28 rp3 wpa_supplicant[7555]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 29 11:42:20 rp3 wpa_supplicant[7555]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 29 12:42:12 rp3 wpa_supplicant[7555]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 29 13:42:04 rp3 wpa_supplicant[7555]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 29 14:41:56 rp3 wpa_supplicant[7555]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 29 15:41:48 rp3 wpa_supplicant[7555]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 29 16:41:40 rp3 wpa_supplicant[7555]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 29 17:41:32 rp3 wpa_supplicant[7555]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 29 17:54:30 rp3 wpa_supplicant[7555]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:23:69:c7:88:6c reason=4
Apr 29 17:54:30 rp3 ifplugd(wlan0)[7531]: Link beat lost.
Apr 29 17:54:31 rp3 wpa_supplicant[7555]: wlan0: SME: Trying to authenticate with 00:23:69:c7:88:6c (SSID='sb3z' freq=2412 MHz)
Apr 29 17:54:31 rp3 wpa_supplicant[7555]: wlan0: Trying to associate with 00:23:69:c7:88:6c (SSID='sb3z' freq=2412 MHz)
Apr 29 17:54:31 rp3 wpa_supplicant[7555]: wlan0: Associated with 00:23:69:c7:88:6c
Apr 29 17:54:31 rp3 wpa_supplicant[7555]: wlan0: WPA: Key negotiation completed with 00:23:69:c7:88:6c [PTK=CCMP GTK=TKIP]
Apr 29 17:54:31 rp3 wpa_supplicant[7555]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:23:69:c7:88:6c completed (reauth) [id=1 id_str=]
Apr 29 17:54:32 rp3 ifplugd(wlan0)[7531]: Link beat detected.
Apr 29 18:41:24 rp3 wpa_supplicant[7555]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 29 19:41:16 rp3 wpa_supplicant[7555]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]
Apr 29 20:41:08 rp3 wpa_supplicant[7555]: wlan0: WPA: Group rekeying completed with 00:23:69:c7:88:6c [GTK=TKIP]

Code: Select all
pi@rp3 ~ $ uname -a
Linux rp3 3.6.11+ #416 PREEMPT Mon Apr 22 21:58:42 BST 2013 armv6l GNU/Linux
pi@rp3 ~ $ lsusb
Bus 001 Device 002: ID 1a40:0101 Terminus Technology Inc. 4-Port HUB
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 011: ID 148f:5370 Ralink Technology, Corp. RT5370 Wireless Adapter
Last edited by jbeale on Thu May 02, 2013 8:54 pm, edited 1 time in total.
User avatar
Posts: 2038
Joined: Tue Nov 22, 2011 11:51 pm
by FreakHavoc » Thu May 02, 2013 7:05 pm
I have the same problem. Model A, Ralink 5370 adapter. Suddenly stops working, usually within 24 hours.

At least good that someone is trying to fix the problem, thanks to you for that :)
Posts: 39
Joined: Sun Dec 11, 2011 9:47 am