Slow wifi network connection on reboot

breboulet commented 3 years ago

Hi Dave,

First of all, thank you so much for this project and the very nice doc, website, binaries and co you've put in place. That's really great!

I'm running into the following issue: it takes about 3min after the Pi has rebooted to hide the hotspot and connect to my (previously paired/known) wifi network. When there's no comitup and the Pi is configured with stock wpa_supplicant it only takes a few seconds to connect to wifi after reboot.

Here are the steps to reproduce:

Flashed a Raspberry Pi 4 with your latest comitup-lite image (image_2021-04-12-Comitup-lite.zip)
Booted
Connected to comitup hotspot with my iPhone
Input my wifi creds
Connected. Everything's happy.
Reboot
Notice hotspot comes up almost right away (where it probably shouldn't at all since a known wifi network is available)
Wait for 3min
Hotspot goes away and the Pi finally connects to Wifi network

Following is the output of /var/log/comitup.log with log levels set to DEBUG in comitup.py

2021-04-14 17:46:43,505 - comitup - INFO - Starting comitup
2021-04-14 17:46:43,511 - comitup - DEBUG - {'id': '6467'}
2021-04-14 17:46:43,623 - comitup - DEBUG - stopping comitup-web.service web service
2021-04-14 17:46:43,630 - comitup - DEBUG - web service is 
2021-04-14 17:46:43,631 - comitup - INFO - using SSID: comitup-6
2021-04-14 17:46:43,632 - comitup - DEBUG - Calling nm.GetDevices()
2021-04-14 17:46:43,680 - comitup - DEBUG - nmm - Setting primary listener for <NetworkManager.Wireless object at 0xb5518870>
2021-04-14 17:46:43,680 - comitup - DEBUG - Getting specific device for path
2021-04-14 17:46:43,681 - comitup - DEBUG - Listener is type='signal',path='/org/freedesktop/NetworkManager/Devices/3',interface='org.freedesktop.NetworkManager.Device',member='StateChanged'
2021-04-14 17:46:43,682 - comitup - DEBUG - nmm - Setting 2nd listener for <NetworkManager.Wireless object at 0xb5518870>
2021-04-14 17:46:43,683 - comitup - DEBUG - Getting specific device for path
2021-04-14 17:46:43,684 - comitup - DEBUG - Listener is type='signal',path='/org/freedesktop/NetworkManager/Devices/3',interface='org.freedesktop.NetworkManager.Device',member='StateChanged'
2021-04-14 17:46:43,684 - comitup - DEBUG - states: Calling nm.get_connection_by_ssid()
2021-04-14 17:46:43,685 - comitup - DEBUG - Calling nm.ListConnections()
2021-04-14 17:46:43,718 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:46:43,718 - comitup - DEBUG - Not in cache
2021-04-14 17:46:43,722 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:46:43,722 - comitup - DEBUG - Not in cache
2021-04-14 17:46:43,748 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:46:43,748 - comitup - DEBUG - Not in cache
2021-04-14 17:46:43,752 - comitup - DEBUG - Got an exception, returning None, get_ssid_from_connection
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 156, in get_ssid_from_connection
    return settings['802-11-wireless']['ssid']
KeyError: '802-11-wireless'
2021-04-14 17:46:43,755 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:46:43,755 - comitup - DEBUG - Not in cache
2021-04-14 17:46:43,759 - comitup - DEBUG - Got an exception, returning None, get_ssid_from_connection
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 156, in get_ssid_from_connection
    return settings['802-11-wireless']['ssid']
KeyError: '802-11-wireless'
2021-04-14 17:46:43,760 - comitup - DEBUG - Calling nm.ListConnections()
2021-04-14 17:46:43,779 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:46:43,779 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:46:43,780 - comitup - DEBUG - Got an exception, returning None, get_ssid_from_connection
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 156, in get_ssid_from_connection
    return settings['802-11-wireless']['ssid']
KeyError: '802-11-wireless'
2021-04-14 17:46:43,780 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:46:43,780 - comitup - DEBUG - Got an exception, returning None, get_ssid_from_connection
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 156, in get_ssid_from_connection
    return settings['802-11-wireless']['ssid']
KeyError: '802-11-wireless'
2021-04-14 17:46:43,781 - comitup - DEBUG - Calling nm.AddConnection()
2021-04-14 17:46:43,802 - comitup - INFO - Setting state to HOTSPOT
2021-04-14 17:46:43,804 - comitup - INFO - Activating hotspot
2021-04-14 17:46:43,804 - comitup - DEBUG - states: Calling nm.get_active_ssid()
2021-04-14 17:46:43,805 - comitup - DEBUG - Getting Connection settings
2021-04-14 17:46:43,805 - comitup - DEBUG - Got an exception, returning None, get_active_ssid
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 138, in get_active_ssid
    return get_device_settings(device)['802-11-wireless']['ssid']
  File "/usr/share/comitup/comitup/nm.py", line 133, in get_device_settings
    return get_connection_settings(connection.Connection)
AttributeError: 'NoneType' object has no attribute 'Connection'
2021-04-14 17:46:43,806 - comitup - DEBUG - Connecting to comitup-6
2021-04-14 17:46:43,806 - comitup - DEBUG - states: Calling nm.activate_connection_by_ssid()
2021-04-14 17:46:43,806 - comitup - DEBUG - Calling nm.ListConnections()
2021-04-14 17:46:43,831 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:46:43,831 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:46:43,831 - comitup - DEBUG - Got an exception, returning None, get_ssid_from_connection
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 156, in get_ssid_from_connection
    return settings['802-11-wireless']['ssid']
KeyError: '802-11-wireless'
2021-04-14 17:46:43,831 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:46:43,832 - comitup - DEBUG - Got an exception, returning None, get_ssid_from_connection
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 156, in get_ssid_from_connection
    return settings['802-11-wireless']['ssid']
KeyError: '802-11-wireless'
2021-04-14 17:46:43,832 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:46:43,832 - comitup - DEBUG - Not in cache
2021-04-14 17:46:43,836 - comitup - DEBUG - Calling nm.ActivateConnection()
2021-04-14 17:46:44,376 - comitup - DEBUG - Running iptables commands for HOTSPOT
2021-04-14 17:46:44,780 - comitup - DEBUG - Done with iptables commands for HOTSPOT
2021-04-14 17:46:44,786 - comitup - DEBUG - nmm - primary state 40
2021-04-14 17:46:44,786 - comitup - DEBUG - nmm - secondary state 40
2021-04-14 17:46:44,787 - comitup - DEBUG - nmm - primary state 50
2021-04-14 17:46:44,787 - comitup - DEBUG - nmm - secondary state 50
2021-04-14 17:46:44,787 - comitup - DEBUG - nmm - primary state 70
2021-04-14 17:46:44,787 - comitup - DEBUG - nmm - secondary state 70
2021-04-14 17:46:44,821 - comitup - DEBUG - Got an exception, returning None, get_active_ip
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 143, in get_active_ip
    return device.Ip4Config.Addresses[0][0]
AttributeError: 'NoneType' object has no attribute 'Addresses'
2021-04-14 17:46:44,839 - comitup - DEBUG - {'id': '6467'}
2021-04-14 17:46:44,868 - comitup - DEBUG - Got an exception, returning None, get_active_ip
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 143, in get_active_ip
    return device.Ip4Config.Addresses[0][0]
AttributeError: 'NoneType' object has no attribute 'Addresses'
2021-04-14 17:46:44,885 - comitup - DEBUG - {'id': '6467'}
2021-04-14 17:46:44,888 - comitup - DEBUG - nmm - primary pass
2021-04-14 17:46:44,888 - comitup - DEBUG - nmm - secondary pass
2021-04-14 17:46:44,888 - comitup - DEBUG - nmm - primary state 90
2021-04-14 17:46:44,889 - comitup - DEBUG - nmm - secondary state 90
2021-04-14 17:46:44,916 - comitup - DEBUG - Got an exception, returning None, get_active_ip
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 143, in get_active_ip
    return device.Ip4Config.Addresses[0][0]
AttributeError: 'NoneType' object has no attribute 'Addresses'
2021-04-14 17:46:44,934 - comitup - DEBUG - {'id': '6467'}
2021-04-14 17:46:44,962 - comitup - DEBUG - Got an exception, returning None, get_active_ip
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 143, in get_active_ip
    return device.Ip4Config.Addresses[0][0]
AttributeError: 'NoneType' object has no attribute 'Addresses'
2021-04-14 17:46:44,980 - comitup - DEBUG - {'id': '6467'}
2021-04-14 17:46:44,982 - comitup - DEBUG - nmm - primary pass
2021-04-14 17:46:44,983 - comitup - DEBUG - nmm - secondary pass
2021-04-14 17:46:44,983 - comitup - DEBUG - starting comitup-web.service web service
2021-04-14 17:46:44,993 - comitup - DEBUG - Running dnsmasq using /usr/share/comitup/dns/dns-hotspot.conf
2021-04-14 17:46:45,022 - comitup - DEBUG - starting comitup-web.service web service
2021-04-14 17:46:45,030 - comitup - DEBUG - Running dnsmasq using /usr/share/comitup/dns/dns-hotspot.conf
2021-04-14 17:46:45,167 - comitup - DEBUG - starting comitup-web.service web service
2021-04-14 17:46:45,175 - comitup - DEBUG - Running dnsmasq using /usr/share/comitup/dns/dns-hotspot.conf
2021-04-14 17:46:45,313 - comitup - DEBUG - starting comitup-web.service web service
2021-04-14 17:46:45,321 - comitup - DEBUG - Running dnsmasq using /usr/share/comitup/dns/dns-hotspot.conf
2021-04-14 17:46:45,815 - comitup - DEBUG - Getting device list from 'iw'
2021-04-14 17:46:45,863 - comitup - DEBUG - Getting AP list from 'iw' dev wlan0
2021-04-14 17:49:43,905 - comitup - DEBUG - Getting device list from 'iw'
2021-04-14 17:49:43,956 - comitup - DEBUG - Getting iw station dump
2021-04-14 17:49:43,981 - comitup - DEBUG - Periodic connection attempt
2021-04-14 17:49:43,982 - comitup - DEBUG - states: Calling nm.get_candidate_connections()
2021-04-14 17:49:43,982 - comitup - DEBUG - Calling nm.ListConnections()
2021-04-14 17:49:44,032 - comitup - DEBUG - Getting settings 2
2021-04-14 17:49:44,032 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:49:44,032 - comitup - DEBUG - Getting settings 2
2021-04-14 17:49:44,032 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:49:44,033 - comitup - DEBUG - Got an exception, returning None, get_ssid_from_connection
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 156, in get_ssid_from_connection
    return settings['802-11-wireless']['ssid']
KeyError: '802-11-wireless'
2021-04-14 17:49:44,033 - comitup - DEBUG - Getting settings 2
2021-04-14 17:49:44,034 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:49:44,034 - comitup - DEBUG - Got an exception, returning None, get_ssid_from_connection
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 156, in get_ssid_from_connection
    return settings['802-11-wireless']['ssid']
KeyError: '802-11-wireless'
2021-04-14 17:49:44,034 - comitup - DEBUG - Getting settings 2
2021-04-14 17:49:44,034 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:49:44,035 - comitup - DEBUG - candidates: ['Frontier5920']
2021-04-14 17:49:44,037 - comitup - DEBUG - Kicking wpa on wlan0
2021-04-14 17:49:44,530 - comitup - INFO - Setting state to CONNECTING
2021-04-14 17:49:44,538 - comitup - DEBUG - states: Calling nm.disconnect()
2021-04-14 17:49:44,538 - comitup - DEBUG - Calling disconnect
2021-04-14 17:49:44,559 - comitup - INFO - Attempting connection to Frontier5920
2021-04-14 17:49:44,559 - comitup - DEBUG - Connecting to Frontier5920
2021-04-14 17:49:44,560 - comitup - DEBUG - states: Calling nm.activate_connection_by_ssid()
2021-04-14 17:49:44,560 - comitup - DEBUG - Calling nm.ListConnections()
2021-04-14 17:49:46,270 - comitup - DEBUG - Calling GetSettings
2021-04-14 17:49:46,270 - comitup - DEBUG - Calling nm.ActivateConnection()
2021-04-14 17:49:46,811 - comitup - DEBUG - stopping comitup-web.service web service
2021-04-14 17:49:46,830 - comitup - DEBUG - Running dnsmasq using 
2021-04-14 17:49:46,832 - comitup - DEBUG - nmm - primary state 110
2021-04-14 17:49:46,832 - comitup - DEBUG - nmm - secondary state 110
2021-04-14 17:49:46,832 - comitup - DEBUG - nmm - primary state 30
2021-04-14 17:49:46,832 - comitup - DEBUG - nmm - secondary state 30
2021-04-14 17:49:46,833 - comitup - DEBUG - nmm - primary state 40
2021-04-14 17:49:46,833 - comitup - DEBUG - nmm - secondary state 40
2021-04-14 17:49:46,833 - comitup - DEBUG - nmm - primary state 50
2021-04-14 17:49:46,833 - comitup - DEBUG - nmm - secondary state 50
2021-04-14 17:49:46,834 - comitup - DEBUG - nmm - primary state 60
2021-04-14 17:49:46,834 - comitup - DEBUG - nmm - secondary state 60
2021-04-14 17:49:46,834 - comitup - DEBUG - nmm - primary state 40
2021-04-14 17:49:46,834 - comitup - DEBUG - nmm - secondary state 40
2021-04-14 17:49:46,834 - comitup - DEBUG - nmm - primary state 50
2021-04-14 17:49:46,835 - comitup - DEBUG - nmm - secondary state 50
2021-04-14 17:49:52,103 - comitup - DEBUG - nmm - primary state 70
2021-04-14 17:49:52,104 - comitup - DEBUG - nmm - secondary state 70
2021-04-14 17:49:52,500 - comitup - DEBUG - Got an exception, returning None, get_active_ip
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 143, in get_active_ip
    return device.Ip4Config.Addresses[0][0]
AttributeError: 'NoneType' object has no attribute 'Addresses'
2021-04-14 17:49:52,525 - comitup - DEBUG - {'id': '6467'}
2021-04-14 17:49:52,562 - comitup - DEBUG - Got an exception, returning None, get_active_ip
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 143, in get_active_ip
    return device.Ip4Config.Addresses[0][0]
AttributeError: 'NoneType' object has no attribute 'Addresses'
2021-04-14 17:49:52,584 - comitup - DEBUG - {'id': '6467'}
2021-04-14 17:49:52,614 - comitup - DEBUG - Got an exception, returning None, get_active_ip
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 143, in get_active_ip
    return device.Ip4Config.Addresses[0][0]
AttributeError: 'NoneType' object has no attribute 'Addresses'
2021-04-14 17:49:52,632 - comitup - DEBUG - {'id': '6467'}
2021-04-14 17:49:52,635 - comitup - DEBUG - nmm - primary pass
2021-04-14 17:49:52,635 - comitup - DEBUG - nmm - secondary pass
2021-04-14 17:49:52,635 - comitup - DEBUG - nmm - primary state 90
2021-04-14 17:49:52,636 - comitup - DEBUG - nmm - secondary state 90
2021-04-14 17:49:52,664 - comitup - DEBUG - Got an exception, returning None, get_active_ip
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 143, in get_active_ip
    return device.Ip4Config.Addresses[0][0]
AttributeError: 'NoneType' object has no attribute 'Addresses'
2021-04-14 17:49:52,681 - comitup - DEBUG - {'id': '6467'}
2021-04-14 17:49:52,710 - comitup - DEBUG - Got an exception, returning None, get_active_ip
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 143, in get_active_ip
    return device.Ip4Config.Addresses[0][0]
AttributeError: 'NoneType' object has no attribute 'Addresses'
2021-04-14 17:49:52,727 - comitup - DEBUG - {'id': '6467'}
2021-04-14 17:49:52,758 - comitup - DEBUG - Got an exception, returning None, get_active_ip
Traceback (most recent call last):
  File "/usr/share/comitup/comitup/nm.py", line 61, in wrapper
    return fp(*args, **kwargs)
  File "/usr/share/comitup/comitup/nm.py", line 143, in get_active_ip
    return device.Ip4Config.Addresses[0][0]
AttributeError: 'NoneType' object has no attribute 'Addresses'
2021-04-14 17:49:52,775 - comitup - DEBUG - {'id': '6467'}
2021-04-14 17:49:52,777 - comitup - DEBUG - nmm - primary pass
2021-04-14 17:49:52,778 - comitup - DEBUG - nmm - secondary pass
2021-04-14 17:49:52,778 - comitup - DEBUG - Connection successful
2021-04-14 17:49:52,781 - comitup - DEBUG - Connection successful
2021-04-14 17:49:52,784 - comitup - DEBUG - Connection successful
2021-04-14 17:49:52,787 - comitup - DEBUG - Connection successful
2021-04-14 17:49:52,790 - comitup - INFO - Setting state to CONNECTED
2021-04-14 17:49:52,792 - comitup - DEBUG - Running iptables commands for CONNECTED
2021-04-14 17:49:52,857 - comitup - DEBUG - Done with iptables commands for CONNECTED
2021-04-14 17:49:52,861 - comitup - INFO - Setting state to CONNECTED
2021-04-14 17:49:52,862 - comitup - DEBUG - Running iptables commands for CONNECTED
2021-04-14 17:49:52,925 - comitup - DEBUG - Done with iptables commands for CONNECTED
2021-04-14 17:49:52,929 - comitup - INFO - Setting state to CONNECTED
2021-04-14 17:49:52,931 - comitup - DEBUG - Running iptables commands for CONNECTED
2021-04-14 17:49:52,994 - comitup - DEBUG - Done with iptables commands for CONNECTED
2021-04-14 17:49:52,998 - comitup - INFO - Setting state to CONNECTED
2021-04-14 17:49:52,999 - comitup - DEBUG - Running iptables commands for CONNECTED
2021-04-14 17:49:53,062 - comitup - DEBUG - Done with iptables commands for CONNECTED`

I've noticed a bunch of exceptions, not sure if it's normal and/or related to that delay. Also notice the jump inbetween 17:46:xx and 17:49:xx, almost like it's sleeping for 3min. Is there anything I could do (configuration or otherwise) to reduce that delay?

Thanks and Regards, Bastien

davesteele commented 3 years ago

Yes, the initial connection attempt after reboot is (very) often failing, and the next retry is 3 minutes later. It seems that NetworkManager is just not ready for the request yet. Comitup should either wait longer on boot, or cut the timeout way down after the initial try.

The exception following a log message saying "Got an exception, returning None" is normal behavior.

davesteele commented 3 years ago

I added a 5 second timeout to the start of Comitup - no effect.

Adding a second WiFi device - works flawlessly.

There is a known issue of NetworkManager being not great at identifying a list of available Access Points using a WiFi adapter which is itself an active AP. Comitup can mitigate this by using multiple WiFi adapters, if available, to compile the list.

Possible solutions:

Add a USB WiFi adapter as a second WiFi interface. Use the enable_appliance_mode parameter, if desired, to keep Comitup from bridging across the devices.
Rework Comitup to not depend on the NetworkManager-generated list to determine which connections to attempt.

davesteele commented 3 years ago

If you are in a position to do this, could you upgrade to the latest states.py in the main branch, and see if it works better?

davesteele commented 3 years ago

Fixed in 1.20

breboulet commented 3 years ago

I just tried 1.20 and everything works flawlessly! I even tried to power cycle my router, I saw the hotspot coming up, then going away automatically when wifi was back up. Sir, you rock! Many thanks, Bastien

davesteele / comitup

Slow wifi network connection on reboot #161