Raspbian WiFi bounces regularly on Raspbian in console mode

[bls]

This is a follow-on to topic https://www.raspberrypi.org/forums/view ... 6&t=233847. I am posting as a new topic because it is a slightly different issue and demonstrates a Raspbian bug. If you are experience wlan0 'carrier lost' messages on Raspbian Stretch, this may be of interest.

Environment

• Raspberry Pi 3B
• Raspbian Stretch (have tried both 2018-11-13-full and 2018-06-27-raspbian-stretch)
• WiFi wpa_supplicant fully configured, and WiFi operational

Scenario

• Raspbian boots to graphical desktop, everything works as expected.
• Then use raspi-config to reconfigure to boot to console, and reboot (no other changes)
• With no graphical desktop, WiFi bounces approximately every 6-10 minutes with 'carrier lost', and then comes back online.

I'm very curious to hear if others seeing the wlan0 'carrier down' errors are using a graphical desktop or boot to console.

Analysis

Graphical mode

• The directory /tmp/dhcpcd-pi exists, owned by pi/pi, with 2 sockets in it:libdhcpcd-wpa-<pid>.0 and libdhcpcd-wpa-<pid>.1. The pid is that of lxpanel. lsof indicates that gmain, gdbus, and menu-cached also access these sockets. lsof doesn't show dhcpcd or wpa_supplicant accessing these sockets, so I'm not yet clear how this is all wired up. I'm hoping that someone on the Raspbian team can shed some light on this!
• I found the following in the wpa_supplicant log when booted in graphical desktop.

  Code: Select all

  Feb 18 11:12:47: CTRL_IFACE monitor attached /tmp/dhcpcd-pi/libdhcpcd-wpa-963.3\x00
  Feb 18 11:12:47: wlan0: Control interface command 'STATUS'
  Feb 18 11:12:47: EAPOL: EAP Session-Id not available
  Feb 18 11:12:47: wlan0: Control interface command 'BSS 0'
  Feb 18 11:12:47: wlan0: Control interface command 'BSS 1'
  Feb 18 11:12:47: wlan0: Control interface command 'BSS 2'
  Feb 18 11:12:47: wlan0: Control interface command 'BSS 3'
  Feb 18 11:12:47: wlan0: Control interface command 'BSS 4'
  Feb 18 11:12:47: wlan0: Control interface command 'BSS 5'
  Feb 18 11:12:47: wlan0: Control interface command 'BSS 6'
  Feb 18 11:12:47: wlan0: Control interface command 'BSS 7'
  Feb 18 11:12:47: wlan0: Control interface command 'BSS 8'
  Feb 18 11:12:47: wlan0: Control interface command 'BSS 9'
  Feb 18 11:12:47: wlan0: Control interface command 'BSS 10'
  Feb 18 11:12:47: wlan0: Control interface command 'BSS 11'
  Feb 18 11:12:47: wlan0: Control interface command 'STATUS'
  

Console mode

• the directory /tmp/dhcpcd-pi does not exist
• The wpa_supplicant log (at the same point in the log). Note that the CTRL_IFACE message from the graphical desktop scenario is nowhere to be found. Instead, it looks like the SSIDs are flushed from the wpa_supplicant cache, and then eventually followed by a WiFi disconnect event. See the end of this message for the corresponding journalctl log entries for this disconnect. The wpa_bss_flush_by_age messages appear about 3 minutes after wlan0 is put online, initially, and after each bounce.

  Code: Select all

  Feb 17 20:23:15: EAPOL: disable timer tick
  Feb 17 20:26:23: wlan0: BSS: Remove id 0 BSSID 4c:01:43:69:21:1f SSID 'OurFiNotYourFi' due to wpa_bss_flush_by_age
  Feb 17 20:26:23: wlan0: BSS: Remove id 2 BSSID 4c:01:43:65:49:f6 SSID 'BennLiz' due to wpa_bss_flush_by_age
  Feb 17 20:26:23: wlan0: BSS: Remove id 3 BSSID 4c:01:43:65:49:f3 SSID '91b55' due to wpa_bss_flush_by_age
  Feb 17 20:26:23: wlan0: BSS: Remove id 4 BSSID 4c:01:43:65:49:ff SSID 'OurFiNotYourFi' due to wpa_bss_flush_by_age
  Feb 17 20:26:23: wlan0: BSS: Remove id 5 BSSID 4c:01:43:64:5f:ff SSID 'OurFiNotYourFi' due to wpa_bss_flush_by_age
  Feb 17 20:26:23: wlan0: BSS: Remove id 6 BSSID 4c:01:43:64:5f:f6 SSID 'BennLiz' due to wpa_bss_flush_by_age
  Feb 17 20:26:23: wlan0: BSS: Remove id 7 BSSID a0:63:91:cc:43:3b SSID 'Chapman' due to wpa_bss_flush_by_age
  Feb 17 20:26:23: wlan0: BSS: Remove id 8 BSSID 44:1c:12:02:4c:01 SSID 'Comcast Box' due to wpa_bss_flush_by_age
  Feb 17 20:26:23: wlan0: BSS: Remove id 9 BSSID 00:1f:90:e4:cf:97 SSID '30CL0' due to wpa_bss_flush_by_age
  Feb 17 20:26:23: wlan0: BSS: Remove id 10 BSSID 4c:01:43:65:49:f9 SSID '' due to wpa_bss_flush_by_age
  Feb 17 20:26:23: wlan0: BSS: Remove id 11 BSSID 44:1c:12:02:4c:03 SSID 'xfinitywifi' due to wpa_bss_flush_by_age
  Feb 17 20:29:00: nl80211: Event message available
  Feb 17 20:29:00: nl80211: Ignored event (cmd=48) for foreign interface (ifindex 3 wdev 0x0)
  Feb 17 20:29:00: nl80211: Drv Event 48 (NL80211_CMD_DISCONNECT) received for wlan0
  Feb 17 20:29:00: nl80211: Disconnect event
  Feb 17 20:29:00: wlan0: Event DEAUTH (12) received
  Feb 17 20:29:00: wlan0: Deauthentication notification
  Feb 17 20:29:00: wlan0:  * reason 0 (locally generated)
  Feb 17 20:29:00: Deauthentication frame IE(s) - hexdump(len=0): [NULL]
  Feb 17 20:29:00: wlan0: CTRL-EVENT-DISCONNECTED bssid=4c:01:43:69:21:16 reason=0 locally_generated=1
  Feb 17 20:29:00: wlan0: Auto connect enabled: try to reconnect (wps=0/0 wpa_state=9)
  Feb 17 20:29:00: wlan0: Setting scan request: 0.100000 sec
  Feb 17 20:29:00: Added BSSID 4c:01:43:69:21:16 into blacklist
  Feb 17 20:29:00: wlan0: Blacklist count 1 --> request scan in 100 ms
  Feb 17 20:29:00: wlan0: Ignore new scan request for 0.100000 sec since an earlier request is scheduled to trigger sooner
  Feb 17 20:29:00: TDLS: Remove peers on disassociation
  Feb 17 20:29:00: wlan0: WPA: Clear old PMK and PTK
  Feb 17 20:29:00: wlan0: Disconnect event - remove keys
  Feb 17 20:29:00: wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=(nil) key_idx=0 set_tx=0 seq_len=0 key_len=0
  Feb 17 20:29:00: wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=(nil) key_idx=1 set_tx=0 seq_len=0 key_len=0
  Feb 17 20:29:00: wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=0x194b978 key_idx=0 set_tx=0 seq_len=0 key_len=0
  Feb 17 20:29:00:    addr=4c:01:43:69:21:16
  Feb 17 20:29:00: wlan0: State: COMPLETED -> DISCONNECTED
  

• In this scenario, as I mentioned, the Wifi bounces. A typical journalctl entry is shown at the end of this message.

I also tried Stretch 2018-06-27, which exhibited the same behavior: worked with graphical desktop, WiFi bounces regularly with console.

lxpanel, gmain, gdbus, and/or menu-cached are doing something that makes Wifi operate correctly, and whatever that is is not being done in console mode. This strikes me as problematic, since WiFi without the full graphical Raspbian interface should work reliably, shouldn't it?

This is what a typical bounce looks like in the systemd journal

Code: Select all

Feb 17 20:29:00 rpi31 dhcpcd[508]: wlan0: carrier lost
Feb 17 20:29:00 rpi31 dhcpcd[508]: wlan0: deleting address fe80::f574:788:2dd9:a9cd
Feb 17 20:29:00 rpi31 avahi-daemon[351]: Withdrawing address record for fe80::f574:788:2dd9:a9cd on wlan0.
Feb 17 20:29:00 rpi31 avahi-daemon[351]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::f574:788:2dd9:a9cd.
Feb 17 20:29:00 rpi31 avahi-daemon[351]: Interface wlan0.IPv6 no longer relevant for mDNS.
Feb 17 20:29:01 rpi31 dhcpcd[508]: wlan0: deleting default route via 192.168.92.1
Feb 17 20:29:01 rpi31 dhcpcd[508]: wlan0: deleting route to 192.168.92.0/24
Feb 17 20:29:01 rpi31 avahi-daemon[351]: Withdrawing address record for 192.168.92.198 on wlan0.
Feb 17 20:29:01 rpi31 avahi-daemon[351]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.92.198.
Feb 17 20:29:01 rpi31 avahi-daemon[351]: Interface wlan0.IPv4 no longer relevant for mDNS.
Feb 17 20:29:01 rpi31 dhcpcd[508]: wlan0: carrier acquired
Feb 17 20:29:01 rpi31 dhcpcd[508]: wlan0: IAID eb:b4:d3:c1
Feb 17 20:29:01 rpi31 dhcpcd[508]: wlan0: adding address fe80::f574:788:2dd9:a9cd
Feb 17 20:29:01 rpi31 dhcpcd[508]: wlan0: soliciting an IPv6 router
Feb 17 20:29:02 rpi31 dhcpcd[508]: wlan0: rebinding lease of 192.168.92.198
Feb 17 20:29:02 rpi31 dhcpcd[508]: wlan0: probing address 192.168.92.198/24
Feb 17 20:29:03 rpi31 avahi-daemon[351]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::f574:788:2dd9:a9cd.
Feb 17 20:29:03 rpi31 avahi-daemon[351]: New relevant interface wlan0.IPv6 for mDNS.
Feb 17 20:29:03 rpi31 avahi-daemon[351]: Registering new address record for fe80::f574:788:2dd9:a9cd on wlan0.*.
Feb 17 20:29:07 rpi31 dhcpcd[508]: wlan0: leased 192.168.92.198 for 86400 seconds
Feb 17 20:29:07 rpi31 avahi-daemon[351]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.92.198.
Feb 17 20:29:07 rpi31 avahi-daemon[351]: New relevant interface wlan0.IPv4 for mDNS.
Feb 17 20:29:07 rpi31 dhcpcd[508]: wlan0: adding route to 192.168.92.0/24
Feb 17 20:29:07 rpi31 avahi-daemon[351]: Registering new address record for 192.168.92.198 on wlan0.IPv4.
Feb 17 20:29:07 rpi31 dhcpcd[508]: wlan0: adding default route via 192.168.92.1
Feb 17 20:29:15 rpi31 dhcpcd[508]: wlan0: no IPv6 Routers available
Feb 17 20:34:59 rpi31 dhcpcd[508]: wlan0: carrier lost

[Andyroo]

I know this may seem a strange question but do you see this if you have the Ethernet cable plugged in?

I had a similar error on a 3B last year but it went away when I plugged it in to a switch. I had two Pi addresses and was monitoring the WiFi and it did not drop for weeks in this case compared to daily with only WiFi.

I do know this was on a late Jessie build and seem to think it went away with a Stretch install but cannot remember as we where moving house at the time

[bls]

Not a strange question at all, and I should have mentioned this as well. Thanks for the reminder! I tested both scenarios, cable in and cable out, and the bounce behavior was the same in both scenarios.

[bls]

I've learned enough about wpa_supplicant to (almost) be dangerous, and have identified a solution. I don't understand what the root cause is, but here are the details. Hope that this helps others who run into this issue.

As mentioned in the base note, wlan0 carrier is lost every few minutes (seems to be somewhere around 6, but I have seen it inexplicably be 10-15 as well) on my systems that are NOT running LXDE. When this happens, dhcpcd shortly thereafter reports 'carrier acquired' and the network is brought back online in about 5 seconds. In other words, the network temporarily glitches, and there is some spam in the system log. Other than that, not a huge issue, except, of course, for network-dependent services.

I didn't like the noise in the system log or my network glitching, so decided to run this into the ground.

There are several notes around the internet suggesting that power_save could be the culprit (iw wlan0 set power_save off). I tested this, but it did not resolve the issue.

Upon deeper examination, I found that one of the items the BSS <ssid> wpa_supplicant command displayed was its cache age, and when the age hit around 350-ish (determined via watch wpa_cli -l wlan0 bss <ssid>), the wlan0 carrier would be lost.

Looking at the wpa debug output, I found that lxpanel was sending SCAN and BSS commands to wpa_supplicant every minute. I assume that this is done in order to offer a current set of wireless networks to the user. It turns out that the SCAN command also resets the cache age of all the SSIDs. This explains why the carrier lost messages were not seen with LXDE, and also indicated the solution: Cause SCANs to happen on a regular basis (e.g., every 2 minutes).

I found some promising wpa_supplicant.conf configuration entries. The wpa_supplicant log indicated that they were properly scanned, but none of them resolved the issue.

• bss_expiration_age=<number> and bss_expiration_scan_count=<number>.
• autoscan=periodic:<number>. I thought this would cause a SCAN to be done automatically and regularly, but no joy.

Since I wasn't able to convince wpa_supplicant to stop aging out entries or autoscan by itself, I created a service to do it. Presto! No more wlan0 carrier lost messages.

Here are the script and .service file:

wpaping: Put this script in /usr/local/bin

Code: Select all

#!/bin/bash
#
# Loop forever doing wpa_cli SCAN commands
#

sleeptime=120  # number of seconds to sleep. 2 minutes (120 seconds) is a good value

while [ 1 ];
do
    wpa_cli -i wlan0 scan
    sleep $sleeptime
done

wpaping.service: Put this service definition file in /lib/systemd/system and issue the following 3 commands:

Code: Select all

systemctl daemon-reload; systemctl enable wpaping.service; systemctl start wpaping.service

Code: Select all

[Unit]
Description=WPA Supplicant pinger
Requires=network-online.target

[Service]
ExecStart=/usr/local/bin/wpaping
User=root
StandardInput=null
StandardOutput=null
StandardError=null
Restart=on-failure

[Install]
WantedBy=multi-user.target

This wpa_supplicant/dhcpcd behavior seems pretty broken to me. I'm surprised that nobody else has run into it since Raspbian Stretch was released. Am I the only person using Raspbian 2018-11-18 without LXDE?

[Andyroo]

Congratulations - amazed at your digging skills

I’ve got two zero w boxes running headless with no issues built straight from the lite image and one 3B in command line mode (i.e. I have to startx if needed). None of these have a keyboard or mouse present.

I do have a spare SD card at the mo that’s blank - if you want me to run a build and test this weekend let me know but expect to give me dumb user level instructions

[bls]

Thanks, Andyroo, I guess my years of working on a variety of operating systems has given me good diagnostic/debug/hackaround skills

It would be interesting to have someone else clearly demonstrate the issue in a sanitized environment. Not too difficult to do: 1) Install Stretch Lite or Stretch Full on an SD card. 1a) Boot up, configure WiFi and verify that you can connect. 2) If Stretch Full, use raspi-config to change Boot Options | Desktop/CLI to boot to Console rather than Desktop. 3) Reboot. 4) Watch the journal log (journalctl -f) to see if you get the wlan0 carrier lost message after 6-10 minutes, and then every 6-10 minutes thereafter. 5) If you get the error, install and start my hackaround service, and the wlan0 carrier lost messages should disappear.

[Andyroo]

Will do - I’ve only got IP v4 here at the mo but maybe able to test 4 and 6 for you if I can work out what EE is doing on their router (or first line phone can tell me) to stop 6 working

Off to bed now though

[bertlea]

Interesting! I also found that loss wlan0 carrier every 5 to 11 minutes last year when I troubleshoot my Pi-zero-W “lost connection” issue. The “lost connection” issue was due to a configuration mistake but the root of cause should be this regular carrier lost. Hope there will be a fix in the future without the need to run a user script to scan wlan0 every 2 minutes.

[bls]

bertlea, absolutely agree about hoping for a future fix for this. The workaround described here is a total hack, although it does solve the problem. I'm going to figure out how to post a Raspbian bug so that it formally gets into the development team and is tracked to resolution.

[bertlea]

@bls, I just checked my other Pi that are running over wifi, and I found: Only my Pi-Zero W running Stretch got this problem, my Pi-3B running Stretch do not have this issue. Also, I have another Pi-Zero W running Jessie do not have this issue.

[bls]

@bertlea can you clarify whether your devices are running with LXDE desktop or console? Thanks

Oh, and I believe that this is a Stretch problem, where it appears that the WiFi management was significantly modified.

[Andyroo]

Just set up the following:

1) Pi Zero WH - has a InkyPhat fitted but no software for this loaded
2) Power supply no issue (3.4A output with very thick cables )
3) IP v4 and IP v6 router issuing DHCP and DNS
4) Clean download of Stretch Lite from here (SHA checked)
5) New 16Gb SD card (Class 10 A1) burnt using Etcher with verification on
6) SSH enabled via ssh.txt in /boot
7) WiFi enabled via wpa_supplicant.conf in /boot

Pi booted fine and I've ssh'd in and changed its password.

So far the only things in the journal are as follows:

Code: Select all

-- Logs begin at Thu 2016-11-03 17:16:43 GMT. --
Feb 23 01:37:53 raspberrypi systemd[577]: Listening on GnuPG cryptographic agent (access for web browsers).
Feb 23 01:37:53 raspberrypi systemd[577]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Feb 23 01:37:53 raspberrypi systemd[577]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Feb 23 01:37:53 raspberrypi systemd[577]: Reached target Sockets.
Feb 23 01:37:53 raspberrypi systemd[577]: Reached target Timers.
Feb 23 01:37:53 raspberrypi systemd[577]: Reached target Basic System.
Feb 23 01:37:53 raspberrypi systemd[577]: Reached target Default.
Feb 23 01:37:53 raspberrypi systemd[577]: Startup finished in 146ms.
Feb 23 01:37:53 raspberrypi systemd[1]: Started User Manager for UID 1000.
Feb 23 01:38:42 raspberrypi passwd[613]: pam_unix(passwd:chauthtok): password changed for pi
Feb 23 01:48:34 raspberrypi systemd[1]: Starting Cleanup of Temporary Directories...
Feb 23 01:48:34 raspberrypi systemd[1]: Started Cleanup of Temporary Directories.

I'll leave it running for a little more before bed - just watching a set of armour being made

[bls]

@Andyroo (and future posters on this topic): Please specify whether you are running with LXDE, a graphical environment with a non-LXDE Window Manager, or booting to console mode. Based on my understanding, the key differentiator is whether LXDE, and specifically, lxpanel, are running, so please provide this critical detail. Thanks.

[Andyroo]

@Andyroo (and future posters on this topic): Please specify whether you are running with LXDE, a graphical environment with a non-LXDE Window Manager, or booting to console mode. Based on my understanding, the key differentiator is whether LXDE, and specifically, lxpanel, are running, so please provide this critical detail. Thanks.

Will do - I am running Lite though so thats without desktop but to play safe I forced log-in direct to console mode

No drops overnight - just doing a reboot onto a WiFi network with a bit more traffic and if thats OK this afternoon I'll do an update / upgrade.

[Andyroo]

Nothing after 10 minutes or so except for one pair of messages:

Code: Select all

Feb 23 11:17:32 raspberrypi kernel: random: crng init done
Feb 23 11:17:32 raspberrypi kernel: random: 7 urandom warning(s) missed due to ratelimiting

I'll have a Google and increase the rate limiting if the WiFi drops this afternoon.

Plan then is to do an apt update / upgrade and see if that makes any difference.

[ShiftPlusOne]

Added a note to self to investigate this issue
https://github.com/RPi-Distro/repo/issues/127

[bls]

Added a note to self to investigate this issue
https://github.com/RPi-Distro/repo/issues/127

Thanks, ShiftPlusOne! Let me know if there's anything I can do to assist.

[Andyroo]

Well I had a clear afternoon with no errors reported on the Pi.

I've done an update and upgrade about 25 minutes ago and all has been stable so far.

I think the error I'm seeing is tied into the random number generator and no keyboard / mouse being attached at the mo - I'll leave the box running for a couple of hours headless then get the keyboard / mouse back on it.

[Andyroo]

Not seeing any errors today at all

Could it be the security between the Pi and AP?

My wpa_supplicant.conf is really minimal:

Code: Select all

ctrl_interface=DIR=/var/run/wpa_supplicant GROUP=netdev
update_config=1
country=GB

network={
	ssid="EE Router"
	psk="Three words at random"
}

I'll leave it running tonight and if you want me to try anything else let me know and I'll set it up before I go out tomorrow.

[bls]

@Andyroo, are you checking the system log (journalctl) for "wlan0 carrier lost" messages?

[Andyroo]

@Andyroo, are you checking the system log (journalctl) for "wlan0 carrier lost" messages?

I am indeed - there are no errors like this for the WiFi at all this weekend. I have checked every line of the output by hand (around 5-600 lines) each time covering times between posts or to the start of the log.

I've pulled the InkyPhat off now and will leave it running while I am out so this will be:
1) Stretch lite on a Pi Zero WH v1.1
2) raspi-config set to boot to command line mode
3) Full update / upgrade applied using apt
4) WiFi connected to IP v4 and IP v6 on the same AP as other devices - reasonable traffic (inc Amazon Prime streaming) using wpa_supplicant as previous
5) USB keyboard attached via passive converter cable
6) No other hardware attached to the Pi (sorry - I need the monitor)
7) SSH enabled via text at start up
8) Power via 5V 3.1 Amp supply

The router has reported a drop in internet connection around 18 hours ago but the local WLAN kept up fine (i.e. I did not have to reboot the router) and this made no difference to the Pi.

[bls]

Very strange. I found this quite repeatable on an Pi3B and Pi3B+, and have tested against two different wireless routers.

Could you do one more thing? Once the network is up and running, do 'watch -d wpa_cli -i wlan0 bss <yourssid>' on a terminal (local console, ssh, or vnc). There is a field called "age=". On my system (without my wpaping service) it runs up to 360 and resets to 0. When it resets to 0 there is a wlan0 carrier lost message in the journalctl log. (With the wpaping service, it runs up to 120 and resets.) What is the highest that your age= gets to? Thanks.

[Andyroo]

Log was still clear of WAN messages all this afternoon - I can free up a 3B in a couple of days if that will help (I've got to get the Zero set up and into a case tomorrow so loose that for testing PM Monday) or could send this SD card over to you if you want to try my image. I do not have a 3B+ that I can get hold of for a few weeks and am banned from buying a new Pi this month by my good lady (and I am a chicken - so do not ask me to 'sneak' one in).

The only other things that may be different here:

1) The DHCP lease time is only 8 hours - happy to change that if needed - it was set low when I was getting line faults and EE support where getting desperate...
2) I am using 'Mode 2' on the router - I have no idea what the latter means and so far first line support at EE cannot tell me... It's supposed to enable older devices (2.4Ghz) to connect better (its fixed my Prime streaming issue) with a side effect of reducing the signal range. I can set Mode 1 (default) back in the middle of the week when I get the B free if we are still struggling.

I'll set the watch going next for you once I've had a cup of tea (well I am in England and an ex Steampunk so NOTHING stops a cuppa).

[Andyroo]

I'm feeling a lot older than you - my age is currently 24252 and climbing

[bls]

Wow, that's really strange, @Andyroo. Without the wpaping.service enabled, mine rolls over to zero (and flaps wlan0) at 360 seconds, or 5 minutes.

I don't have a PiZero to do any testing with. Does it have a different wlan chip than the Pi3B/Pi3B+ that could account for this?