Monday 16 December 2013

RaspberryPi Wifi: Slow To Connect

I've just wasted 20 hours of my life trying get wifi to work on a Raspberry Pi.


All I had to do was follow a previous post, and it should have worked straight away. But life's not like that!


The cause of my problem was rather unexpected, and the solution couldn't have been easier.

The Problem


I followed my previous method to the letter, once again using the popular Edimax wifi dongle plugged into the lower USB socket on a RaspberryPi. My checks revealed that the dongle was listed, the driver had loaded, and it was working as a transceiver, but it just wouldn't associate with my access point.

Now in my defense, I was nursing a tooth-ache all weekend, so my brain was more fogged than usual. Anyway, I headed off down the road of swapping bits: dongles, RaspberryPi, wifi routers and SD cards (with differing Raspbian versions).

With a second Netgear router setup as a test unit, I was also able to disable security, try other security options and fiddle with a few miscellaneous settings.

Searching the Net


I also did a lot of searching on the net, but mostly found confused people being fed with mis-information. Quite a few sites seemed to suggest that you needed a lot more in the wpa_supplicant.conf file than just the access point (ESSID) and your pass-phrase key.

There were also suggestions that the Edimax wifi dongle Power Management feature should be turned off, and that the driver should be rebuilt from source.

At this stage, the checks I was doing involved using ping and iwlist while making changes to /etc/network/interfaces and /etc/wpa_supplicant/wpa_supplicant.conf files.

As mentioned in my previous post, if you use:-

 sudo iwlist wlan0 scan

...and you see local access points in the output, its a pretty good indication that your wifi dongle & driver are OK.

If you do a loop-back ping:-

 ping 127.0.0.1

...and it fails, this could indicate a problem in the /etc/network/interfaces file.

Check that the first two lines of this file are:-

 auto lo
 iface lo inet loopback


...and if this is working, you can be sure the interfaces file is being read.

If you do a network ping, using the IP address of your router, for example:-

 ping 192.168.0.1

...and this fails, then you are not connected to your network.

Or you can use:-

 iwconfig

...which will either show your ESSID or say "unassociated" somewhere in the output.

Time For Tea!


But my break-through came as a result of making (yet another) cup of tea.

Yes tea, the solution to many of Britains problems.

Having left my laptop Ping-ing the non-responsive RaspberryPi, I was surprised when I returned with a cuppa to find the RPi was now connected to my test network.

So I rebooted a few times, leaving the RPi to run until I could see it had associated with my router. I recorded the time taken from loading the desktop to being ping-able: 2m 10s, 50s, 1m 10s, 3m 25s, 35s, 15m....what the hell is going on?

I tried the RPi again on the home wifi, but it wouldn't connect, no matter how long I left it.

So the next step was to take a look at the RaspberryPi System log.
Within it there were several lines like this:-

Nov 24 17:10:42 raspberrypi wpa_supplicant[1715]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:1e:2a:1f:23:de reason=0
Nov 24 17:10:44 raspberrypi wpa_supplicant[1715]: wlan0: Trying to associate with 00:1e:2a:1f:23:de (SSID='LINUX LIVES HERE' freq=2457 MHz)
Nov 24 17:10:44 raspberrypi wpa_supplicant[1715]: wlan0: Association request to the driver failed


...before eventually connecting:-

Nov 24 17:11:25 raspberrypi wpa_supplicant[1715]: wlan0: Associated with 00:1e:2a:1f:23:de
Nov 24 17:11:26 raspberrypi wpa_supplicant[1715]: wlan0: WPA: Key negotiation completed with 00:1e:2a:1f:23:de [PTK=CCMP GTK=CCMP]
Nov 24 17:11:26 raspberrypi wpa_supplicant[1715]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:1e:2a:1f:23:de completed (auth) [id=0 id_str=]
Nov 24 17:11:26 raspberrypi ifplugd(wlan0)[1656]: Link beat detected.
Nov 24 17:11:26 raspberrypi wpa_action: WPA_IFACE=wlan0 WPA_ACTION=CONNECTED
Nov 24 17:11:26 raspberrypi wpa_action: WPA_ID=0 WPA_ID_STR= WPA_CTRL_DIR=/var/run/wpa_supplicant
Nov 24 17:11:26 raspberrypi wpa_action: ifup wlan0=default
Nov 24 17:11:26 raspberrypi ifplugd(wlan0)[1656]: Executing '/etc/ifplugd/ifplugd.action wlan0 up'.
Nov 24 17:11:26 raspberrypi ifplugd(wlan0)[1656]: client: /sbin/ifup: interface wlan0 already configured
Nov 24 17:11:26 raspberrypi ifplugd(wlan0)[1656]: Program executed successfully.
Nov 24 17:11:26 raspberrypi dhclient: Internet Systems Consortium DHCP Client 4.2.2
Nov 24 17:11:26 raspberrypi dhclient: Copyright 2004-2011 Internet Systems Consortium.
Nov 24 17:11:26 raspberrypi dhclient: All rights reserved.
Nov 24 17:11:26 raspberrypi dhclient: For info, please visit https://www.isc.org/software/dhcp/
Nov 24 17:11:26 raspberrypi dhclient:
Nov 24 17:11:26 raspberrypi dhclient: Listening on LPF/wlan0/80:1f:02:af:5b:2f
Nov 24 17:11:26 raspberrypi dhclient: Sending on   LPF/wlan0/80:1f:02:af:5b:2f
Nov 24 17:11:26 raspberrypi dhclient: Sending on   Socket/fallback
Nov 24 17:11:26 raspberrypi dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 6
Nov 24 17:11:26 raspberrypi dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Nov 24 17:11:26 raspberrypi dhclient: DHCPOFFER from 192.168.0.1
Nov 24 17:11:26 raspberrypi dhclient: DHCPACK from 192.168.0.1
Nov 24 17:11:27 raspberrypi dhclient: bound to 192.168.0.2 -- renewal in 36237 seconds.
Nov 24 17:11:28 raspberrypi wpa_action: creating sendsigs omission pidfile: /run/sendsigs.omit.d/wpasupplicant.wpa_supplicant.wlan0.pid
Nov 24 17:11:28 raspberrypi wpa_action: bssid=00:1e:2a:1f:23:de
Nov 24 17:11:28 raspberrypi wpa_action: ssid=LINUX LIVES HERE
Nov 24 17:11:28 raspberrypi wpa_action: id=0
Nov 24 17:11:28 raspberrypi wpa_action: mode=station
Nov 24 17:11:28 raspberrypi wpa_action: pairwise_cipher=CCMP
Nov 24 17:11:28 raspberrypi wpa_action: group_cipher=CCMP
Nov 24 17:11:28 raspberrypi wpa_action: key_mgmt=WPA2-PSK
Nov 24 17:11:28 raspberrypi wpa_action: wpa_state=COMPLETED
Nov 24 17:11:28 raspberrypi wpa_action: ip_address=192.168.0.2
Nov 24 17:11:28 raspberrypi wpa_action: address=80:1f:02:af:5b:2f


...wouldn't it be nice to be able to read these logs and have an idea what it all means?

You may notice in amongst this stuff: "reason=0"  ...which may mean "Reserved" or "Unspecified reason" depending upon who you believe.

Anyway, I was now convinced that the problem was external rather than internal.

The RaspberryPi working area that I had selected was in an alcove in the lounge, with the test router and a wireless phone dangerously close to the RPi.

I wondered whether the router/RPi signal levels could have been too high causing some kind of over-load resulting in bad packets. And there was a danger that the wireless phone could be chucking out all sorts of crap. So I moved the test router a few feet away and put the phone on the other side of the room.

Still no joy. Time for another cup of tea.

That Eureka Moment


I started thinking about the neighbours video sender, which I'd "discovered" a few years ago when trying to use a wireless cctv camera. Both of these devices were also in the same frequency band as our wireless network. Then the penny dropped.

I went back to the RaspberryPi and ran:-

 sudo iwlist wlan0 scan

In the output were details of the neighbours wifi, safely running on channel 1 (I normally use 13 to minimise problems).  But what was of interest was the level: 100/100
So our neighbours router must be in their alcove, just inches away, with maybe only 10" of brickwork between us!

I moved the RasperryPi test rig into another room, powered up, and the RPi connected to the network straight away, while the system was still booting!

What an idiot I am! (Its sad to have to confess that I originally studied telecommunications at college, so this should have occurred to me sooner).

Conclusion


I suspect that the strong signal from the neighbours wifi router was interfering with the RPi. Although iwlist scan could capture enough sensible data to report on the other access points within range, there may have been too much corruption for a successful association.

I would have expected the error message in system log to have said something like "Association request has timed out" instead of just "Association request to the driver failed" because corrupted packets should have been resent a few times....but maybe that's not how it works!

Like many people, I check the channel and level of local access points and select a channel for my wifi which is as far away as possible from the strongest neighbouring access point signal.

I wrote this wifi scanner app in Gambas a few years ago

And I now know that there is an alcove in the corner of my lounge which is wifi dead zone.

But its worth remembering that the 2.4GHz band is open for use to all sorts of devices including: video senders, BlueTooth, cctv cameras, cordless phones, Industrial/medical/scientific devices, microwave ovens & so on.

None of these signals show up on a computers wifi scanner. So unless you have a general receiver you wont detect them, but they could have an impact on your system data rate.

3 comments:

  1. Absolutly amazing!!!! I got exactly your same issue and after read your post, I moved the PI in another room and wow!!! it works perfectly good!
    Thanks to your post now I'm able to go ahead with my project!
    Without the time you spent to write down this post probably I was still struggling with this silly issue!! :)

    ReplyDelete
    Replies
    1. I'm surprised that anyone else has had this problem, because your system must be very close to your neighbours access point to create this condition. But I'm very pleased that this post has been useful to you.

      Delete
    2. This comment has been removed by a blog administrator.

      Delete