Wednesday, 13 March 2013

Occidentalis WiFi Drop Problems

Further Update: A full installation based on 2013-02-09-wheezy-raspbian.img with samba, apache, Adafruit webIDE, etc. recovers from a network outage seamlessly both over a wired connection and wireless. Problem Solved!

Update: Ran blink with a 2013-02-09 Raspbian unmodified and the wireless was able to recover from a wireless drop. Ran rwspi with the Occidentalis distro updated as previously described and it doesn't recover from a wireless drop, but it recovers OK from a disconnected wired net connection on eth0, showing much the same sequence in the log -- thus the problem is wireless related.

The pi's lose their network connections when the wireless glitches and they fail to get it back. This has been happening every few days, apparently at random with the pi's attached to the Bell modem/router/wifi. I'm trying to figure out why. So now a test:

blink on BELL989 with keyboard and mouse and hdmi and ssh from imac
rwspi on BELL989 headless and ssh from imac
macbook on BELL989
imac on cable

depower and repower BELL989 at approx 17:06

The macbook shows loss of network at 17:05:49 and reconnection with no intervention by 17:07:03. The log looks nothing like the pi logs.

blink loses the connection at 17:05:52 then redetects the link beat by 17:06:43, but everything has run its course by then. /var/run/wpa_supplicant still exists as the directory created by root at boot time back at 13:11. The log looks just like the previous failures. Deleted the wpa_supplicant and the ifplugd.action script ran, but found no DHCP offers -- ran it again and it failed with the wpa_supplicant error again.


Mar 13 17:01:17 blink dbus[2195]: [system] Successfully activated service 'org.freedesktop.ConsoleKit'
Mar 13 17:05:52 blink ifplugd(wlan0)[1600]: Link beat lost.
Mar 13 17:06:03 blink ifplugd(wlan0)[1600]: Executing '/etc/ifplugd/ifplugd.action wlan0 down'.
Mar 13 17:06:03 blink dhclient: Internet Systems Consortium DHCP Client 4.2.2
Mar 13 17:06:03 blink ifplugd(wlan0)[1600]: client: Internet Systems Consortium DHCP Client 4.2.2
Mar 13 17:06:03 blink dhclient: Copyright 2004-2011 Internet Systems Consortium.
Mar 13 17:06:03 blink ifplugd(wlan0)[1600]: client: Copyright 2004-2011 Internet Systems Consortium.
Mar 13 17:06:03 blink dhclient: All rights reserved.
Mar 13 17:06:03 blink ifplugd(wlan0)[1600]: client: All rights reserved.
Mar 13 17:06:03 blink dhclient: For info, please visit https://www.isc.org/software/dhcp/
Mar 13 17:06:03 blink ifplugd(wlan0)[1600]: client: For info, please visit https://www.isc.org/software/dhcp/
Mar 13 17:06:04 blink dhclient: 
Mar 13 17:06:04 blink dhclient: Listening on LPF/wlan0/48:02:2a:6c:41:1b
Mar 13 17:06:04 blink ifplugd(wlan0)[1600]: client: Listening on LPF/wlan0/48:02:2a:6c:41:1b
Mar 13 17:06:04 blink dhclient: Sending on   LPF/wlan0/48:02:2a:6c:41:1b
Mar 13 17:06:04 blink ifplugd(wlan0)[1600]: client: Sending on   LPF/wlan0/48:02:2a:6c:41:1b
Mar 13 17:06:04 blink dhclient: Sending on   Socket/fallback
Mar 13 17:06:04 blink ifplugd(wlan0)[1600]: client: Sending on   Socket/fallback
Mar 13 17:06:04 blink dhclient: DHCPRELEASE on wlan0 to 192.168.2.1 port 67
Mar 13 17:06:04 blink ifplugd(wlan0)[1600]: client: DHCPRELEASE on wlan0 to 192.168.2.1 port 67
Mar 13 17:06:04 blink dhclient: suspect value in host_name option - discarded
Mar 13 17:06:04 blink ifplugd(wlan0)[1600]: client: suspect value in host_name option - discarded
Mar 13 17:06:04 blink ifplugd(wlan0)[1600]: client: Reloading /etc/samba/smb.conf: smbd only.
Mar 13 17:06:04 blink avahi-daemon[2222]: Withdrawing address record for 192.168.2.27 on wlan0.
Mar 13 17:06:04 blink avahi-daemon[2222]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.2.27.
Mar 13 17:06:04 blink avahi-daemon[2222]: Interface wlan0.IPv4 no longer relevant for mDNS.
Mar 13 17:06:04 blink ifplugd(wlan0)[1600]: Program executed successfully.
Mar 13 17:06:06 blink ntpd[2747]: Deleting interface #2 wlan0, 192.168.2.27#123, interface stats: received=312, sent=316, dropped=0, active_time=10144 secs
Mar 13 17:06:06 blink ntpd[2747]: 216.194.70.2 interface 192.168.2.27 -> (none)
Mar 13 17:06:06 blink ntpd[2747]: 192.95.20.208 interface 192.168.2.27 -> (none)
Mar 13 17:06:06 blink ntpd[2747]: 199.85.124.148 interface 192.168.2.27 -> (none)
Mar 13 17:06:06 blink ntpd[2747]: 192.75.12.11 interface 192.168.2.27 -> (none)
Mar 13 17:06:06 blink ntpd[2747]: peers refreshed
Mar 13 17:06:38 blink ifplugd(wlan0)[1600]: Link beat detected.
Mar 13 17:06:38 blink ifplugd(wlan0)[1600]: Executing '/etc/ifplugd/ifplugd.action wlan0 up'.
Mar 13 17:06:39 blink ifplugd(wlan0)[1600]: client: ioctl[SIOCSIWAP]: Operation not permitted
Mar 13 17:06:39 blink ifplugd(wlan0)[1600]: client: ioctl[SIOCSIWENCODEEXT]: Invalid argument
Mar 13 17:06:39 blink ifplugd(wlan0)[1600]: client: ioctl[SIOCSIWENCODEEXT]: Invalid argument
Mar 13 17:06:40 blink ifplugd(wlan0)[1600]: client: ioctl[SIOCSIWAP]: Operation not permitted
Mar 13 17:06:41 blink ifplugd(wlan0)[1600]: client: rfkill: Cannot open RFKILL control device
Mar 13 17:06:41 blink ifplugd(wlan0)[1600]: client: ctrl_iface exists and seems to be in use - cannot override it
Mar 13 17:06:41 blink ifplugd(wlan0)[1600]: client: Delete '/var/run/wpa_supplicant/wlan0' manually if it is not used anymore
Mar 13 17:06:41 blink ifplugd(wlan0)[1600]: client: Failed to initialize control interface '/var/run/wpa_supplicant'.
Mar 13 17:06:41 blink ifplugd(wlan0)[1600]: client: You may have another wpa_supplicant process already running or the file was
Mar 13 17:06:41 blink ifplugd(wlan0)[1600]: client: left by an unclean termination of wpa_supplicant in which case you will need
Mar 13 17:06:41 blink ifplugd(wlan0)[1600]: client: to manually remove this file before starting wpa_supplicant again.
Mar 13 17:06:41 blink ifplugd(wlan0)[1600]: client: Failed to bring up wlan0.
Mar 13 17:06:41 blink ifplugd(wlan0)[1600]: Program executed successfully.
Mar 13 17:06:42 blink ifplugd(wlan0)[1600]: Link beat lost.
Mar 13 17:06:43 blink ifplugd(wlan0)[1600]: Link beat detected.


sudo /etc/init.d/networking restart didn't work. Tried with stop and then start, but that didn't connect either. In each case the activity looked just like when it's booting, except it didn't get the DHCP offer. I wonder if it has to do with some of the network services like samba, the web ide and apache not getting shutdown?


Mar 13 17:36:13 blink ifplugd(wlan0)[1600]: Link beat lost.
Mar 13 17:36:19 blink ifplugd(wlan0)[1600]: Link beat detected.
Mar 13 17:36:31 blink ifplugd(wlan0)[1600]: Link beat lost.
Mar 13 17:36:34 blink ifplugd(wlan0)[1600]: Link beat detected.
Mar 13 17:36:47 blink ifplugd(wlan0)[1600]: Link beat lost.
Mar 13 17:36:51 blink ifplugd(wlan0)[1600]: Link beat detected.
Mar 13 17:37:03 blink ifplugd(wlan0)[1600]: Link beat lost.
Mar 13 17:37:06 blink ifplugd(wlan0)[1600]: Link beat detected.
Mar 13 17:37:17 blink dhclient: Internet Systems Consortium DHCP Client 4.2.2
Mar 13 17:37:17 blink dhclient: Copyright 2004-2011 Internet Systems Consortium.
Mar 13 17:37:17 blink dhclient: All rights reserved.
Mar 13 17:37:17 blink dhclient: For info, please visit https://www.isc.org/software/dhcp/
Mar 13 17:37:17 blink dhclient: 
Mar 13 17:37:18 blink ifplugd(wlan0)[1600]: Link beat lost.
Mar 13 17:37:18 blink dhclient: Listening on LPF/wlan0/48:02:2a:6c:41:1b
Mar 13 17:37:18 blink dhclient: Sending on   LPF/wlan0/48:02:2a:6c:41:1b
Mar 13 17:37:18 blink dhclient: Sending on   Socket/fallback
Mar 13 17:37:18 blink dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 6
Mar 13 17:37:19 blink ifplugd(wlan0)[1600]: Link beat detected.
Mar 13 17:37:24 blink dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 10
Mar 13 17:37:31 blink ifplugd(wlan0)[1600]: Link beat lost.
Mar 13 17:37:34 blink ifplugd(wlan0)[1600]: Link beat detected.
Mar 13 17:37:34 blink dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 21
Mar 13 17:37:46 blink ifplugd(wlan0)[1600]: Link beat lost.
Mar 13 17:37:48 blink ifplugd(wlan0)[1600]: Link beat detected.
Mar 13 17:37:55 blink dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 16
Mar 13 17:38:01 blink ifplugd(wlan0)[1600]: Link beat lost.
Mar 13 17:38:02 blink ifplugd(wlan0)[1600]: Link beat detected.
Mar 13 17:38:11 blink dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 8
Mar 13 17:38:15 blink ifplugd(wlan0)[1600]: Link beat lost.
Mar 13 17:38:18 blink ifplugd(wlan0)[1600]: Link beat detected.
Mar 13 17:38:20 blink dhclient: No DHCPOFFERS received.
Mar 13 17:38:20 blink dhclient: Unable to obtain a lease on first try.  Exiting.
Mar 13 17:38:31 blink ifplugd(wlan0)[1600]: Link beat lost.
Mar 13 17:38:34 blink ifplugd(wlan0)[1600]: Link beat detected.
Mar 13 17:38:47 blink ifplugd(wlan0)[1600]: Link beat lost.
Mar 13 17:38:50 blink ifplugd(wlan0)[1600]: Link beat detected.


rwspi loses the connection and is incognito.


Mar 13 17:05:52 rwspi ifplugd(wlan0)[1495]: Link beat lost.
Mar 13 17:06:02 rwspi ifplugd(wlan0)[1495]: Executing '/etc/ifplugd/ifplugd.action wlan0 down'.
Mar 13 17:06:02 rwspi dhclient: Internet Systems Consortium DHCP Client 4.2.2
Mar 13 17:06:02 rwspi ifplugd(wlan0)[1495]: client: Internet Systems Consortium DHCP Client 4.2.2
Mar 13 17:06:02 rwspi dhclient: Copyright 2004-2011 Internet Systems Consortium.
Mar 13 17:06:02 rwspi ifplugd(wlan0)[1495]: client: Copyright 2004-2011 Internet Systems Consortium.
Mar 13 17:06:02 rwspi dhclient: All rights reserved.
Mar 13 17:06:02 rwspi ifplugd(wlan0)[1495]: client: All rights reserved.
Mar 13 17:06:02 rwspi dhclient: For info, please visit https://www.isc.org/software/dhcp/
Mar 13 17:06:02 rwspi ifplugd(wlan0)[1495]: client: For info, please visit https://www.isc.org/software/dhcp/
Mar 13 17:06:02 rwspi dhclient: 
Mar 13 17:06:02 rwspi dhclient: Listening on LPF/wlan0/00:e0:4c:10:47:f1
Mar 13 17:06:02 rwspi ifplugd(wlan0)[1495]: client: Listening on LPF/wlan0/00:e0:4c:10:47:f1
Mar 13 17:06:02 rwspi dhclient: Sending on   LPF/wlan0/00:e0:4c:10:47:f1
Mar 13 17:06:02 rwspi ifplugd(wlan0)[1495]: client: Sending on   LPF/wlan0/00:e0:4c:10:47:f1
Mar 13 17:06:02 rwspi dhclient: Sending on   Socket/fallback
Mar 13 17:06:02 rwspi ifplugd(wlan0)[1495]: client: Sending on   Socket/fallback
Mar 13 17:06:02 rwspi dhclient: DHCPRELEASE on wlan0 to 192.168.2.1 port 67
Mar 13 17:06:02 rwspi ifplugd(wlan0)[1495]: client: DHCPRELEASE on wlan0 to 192.168.2.1 port 67
Mar 13 17:06:03 rwspi ifplugd(wlan0)[1495]: client: Reloading /etc/samba/smb.conf: smbd only.
Mar 13 17:06:03 rwspi avahi-daemon[2071]: Withdrawing address record for 192.168.2.24 on wlan0.
Mar 13 17:06:03 rwspi avahi-daemon[2071]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.2.24.
Mar 13 17:06:03 rwspi avahi-daemon[2071]: Interface wlan0.IPv4 no longer relevant for mDNS.
Mar 13 17:06:03 rwspi ifplugd(wlan0)[1495]: Program executed successfully.
Mar 13 17:06:05 rwspi ntpd[2801]: Deleting interface #2 wlan0, 192.168.2.24#123, interface stats: received=896, sent=904, dropped=0, active_time=152721 secs
Mar 13 17:06:05 rwspi ntpd[2801]: 208.79.216.225 interface 192.168.2.24 -> (none)
Mar 13 17:06:05 rwspi ntpd[2801]: 192.75.12.10 interface 192.168.2.24 -> (none)
Mar 13 17:06:05 rwspi ntpd[2801]: 199.19.167.36 interface 192.168.2.24 -> (none)
Mar 13 17:06:05 rwspi ntpd[2801]: 142.4.209.106 interface 192.168.2.24 -> (none)
Mar 13 17:06:05 rwspi ntpd[2801]: peers refreshed
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: Link beat detected.
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: Executing '/etc/ifplugd/ifplugd.action wlan0 up'.
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: client: ioctl[SIOCSIWAP]: Operation not permitted
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: client: ioctl[SIOCSIWENCODEEXT]: Invalid argument
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: client: ioctl[SIOCSIWENCODEEXT]: Invalid argument
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: client: ioctl[SIOCSIWAP]: Operation not permitted
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: client: rfkill: Cannot open RFKILL control device
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: client: ctrl_iface exists and seems to be in use - cannot override it
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: client: Delete '/var/run/wpa_supplicant/wlan0' manually if it is not used anymore
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: client: Failed to initialize control interface '/var/run/wpa_supplicant'.
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: client: You may have another wpa_supplicant process already running or the file was
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: client: left by an unclean termination of wpa_supplicant in which case you will need
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: client: to manually remove this file before starting wpa_supplicant again.
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: client: Failed to bring up wlan0.
Mar 13 17:06:45 rwspi ifplugd(wlan0)[1495]: Program executed successfully.
Mar 13 17:06:46 rwspi ifplugd(wlan0)[1495]: Link beat lost.
Mar 13 17:06:47 rwspi ifplugd(wlan0)[1495]: Link beat detected.


http://bradfortner.wordpress.com/2013/01/03/how-i-set-up-my-raspberry-pi-lesson-3-demystifing-wi-fi-setup-for-my-raspberry-pi/ doesn't cover it, but points out some useful commands.


sudo ifup wlan0 – wakes up wireless interface at wlan0
iwconfig – shows connected network interfaces

More about startup

man init
/etc/rc?.d
/etc/profile.d
/var/log/syslog