wifi-connect - wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Product support
1

Hi team Balena,

I am getting error messages every second in the journalctl logs that say: wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1. I am running two containers both accessing the dbus, one is the wifi-connect provided by you guys, and the other is an container that just executes a start script and then sleeps forever.

The issue appears to be intermittent, when I first booted the device it appeared. When I restarted the device it had gone. I have just restarted the containers separately with a bit of time between each, it seemed fine. Then I restarted both containers as quickly as possible and it has reoccured again. I have now restarted the containers again and canā€™t get it to stop. I have also tried stopping all the containers, other than the supervisor built into Balena, and the errors are still appearing.

I am on an Orange pi Zero using the Balena os.

version: '2.1'

    services:
        api:
            build: ./api
            labels:
                io.balena.features.dbus: '1'
                io.balena.features.supervisor-api: '1'
            cap_add:
                - NET_ADMIN
            environment:
                DBUS_SYSTEM_BUS_ADDRESS: "unix:path=/host/run/dbus/system_bus_socket"

        wifi-connect:
            build: ./wifi-connect
            network_mode: "host"
            labels:
                io.balena.features.dbus: '1'
            cap_add:
                - NET_ADMIN
            environment:
                DBUS_SYSTEM_BUS_ADDRESS: "unix:path=/host/run/dbus/system_bus_socket"

The wifi-connect container is built as standard, and the api container is built with:

FROM balenalib/%%RESIN_MACHINE_NAME%%-debian-python

## INSTALLS

RUN install_packages libdbus-glib-1-dev libgirepository1.0-dev && \
    python3 -m pip install --no-cache-dir python-networkmanager==2.1 && \
    apt-get purge --auto-remove libdbus-glib-1-dev libgirepository1.0-dev -y

RUN python3 -m pip install --no-cache-dir flask==1.1.2 requests==2.24.0

WORKDIR /app

COPY scripts .

## WRAP-UP

CMD ["bash", "start.sh"]

Logs:

   Oct 06 14:16:35 lb a7c48f95c1c8[814]: [22B blob data]
    Oct 06 14:16:35 lb a7c48f95c1c8[814]: [91B blob data]
    Oct 06 14:16:35 lb NetworkManager[801]: <info>  [1601993795.8050] audit: op="connection-delete" uuid="396e5ce5-626c-49a2-af4d-14c93830094b" name="Learners-Block" pid=1574 uid=0 result="success"
    Oct 06 14:16:35 lb a7c48f95c1c8[814]: [19B blob data]
    Oct 06 14:16:36 lb a7c48f95c1c8[814]: [174B blob data]
    Oct 06 14:16:36 lb a7c48f95c1c8[814]: [25B blob data]
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.0583] device (wlan0): Activation: starting connection 'Learners-Block' (eb40440a-fc4d-4ead-adcf-e02708d94744)
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.0594] audit: op="connection-add-activate" uuid="eb40440a-fc4d-4ead-adcf-e02708d94744" name="Learners-Block" pid=1574 uid=0 result="success"
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.0654] device (wlan0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.0848] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.0891] device (wlan0): Activation: (wifi) connection 'Learners-Block' requires no security.  No secrets needed.
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.0901] Config: added 'ssid' value 'Learners-Block'
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.0902] Config: added 'mode' value '2'
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.0903] Config: added 'frequency' value '2412'
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.0904] Config: added 'freq_list' value '2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472 2484'
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.0905] Config: added 'key_mgmt' value 'NONE'
    Oct 06 14:16:36 lb wpa_supplicant[836]: Note: nl80211 driver interface is not designed to be used with ap_scan=2; this can result in connection failures
    Oct 06 14:16:36 lb kernel: ieee80211 phy0: changing interface type; new type=3(2), p2p=0(0)
    Oct 06 14:16:36 lb kernel: ieee80211 phy0: !!! vif_id=0
    Oct 06 14:16:36 lb kernel: ieee80211 phy0: Interface ID:0 of type:3 added
    Oct 06 14:16:36 lb kernel: ieee80211 phy0: vif 0, configuring tx
    Oct 06 14:16:36 lb kernel: ieee80211 phy0: vif 0, configuring tx
    Oct 06 14:16:36 lb kernel: ieee80211 phy0: vif 0, configuring tx
    Oct 06 14:16:36 lb kernel: ieee80211 phy0: vif 0, configuring tx
    Oct 06 14:16:36 lb kernel: ieee80211 phy0: ignore IEEE80211_CONF_CHANGE_MONITOR (0)IEEE80211_CONF_CHANGE_IDLE (1)
    Oct 06 14:16:36 lb kernel: ieee80211 phy0: Freq 2412 (wsm ch: 1).
    Oct 06 14:16:36 lb wpa_supplicant[836]: Using interface wlan0 with hwaddr 12:42:70:5b:85:ff and ssid "Learners-Block"
    Oct 06 14:16:36 lb wpa_supplicant[836]: Device is trying to offload WPS Probe Response while not supporting this
    Oct 06 14:16:36 lb wpa_supplicant[836]: wlan0: interface state UNINITIALIZED->ENABLED
    Oct 06 14:16:36 lb wpa_supplicant[836]: wlan0: AP-ENABLED
    Oct 06 14:16:36 lb wpa_supplicant[836]: wlan0: CTRL-EVENT-CONNECTED - Connection to 12:42:70:5b:85:ff completed [id=0 id_str=]
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.1282] device (wlan0): supplicant interface state: ready -> completed
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.1285] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Started Wi-Fi Hotspot "Learners-Block"
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.1295] device (wlan0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
    Oct 06 14:16:36 lb wpa_supplicant[836]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1
    Oct 06 14:16:36 lb kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
    Oct 06 14:16:36 lb kernel: ieee80211 phy0: vif 0, configuring tx
    Oct 06 14:16:36 lb kernel: ieee80211 phy0: vif 0, configuring tx
    Oct 06 14:16:36 lb kernel: ieee80211 phy0: vif 0, configuring tx
    Oct 06 14:16:36 lb kernel: ieee80211 phy0: vif 0, configuring tx
    Oct 06 14:16:36 lb avahi-daemon[802]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::8ce1:c4be:4eb3:f445.
    Oct 06 14:16:36 lb avahi-daemon[802]: New relevant interface wlan0.IPv6 for mDNS.
    Oct 06 14:16:36 lb avahi-daemon[802]: Registering new address record for fe80::8ce1:c4be:4eb3:f445 on wlan0.*.
    Oct 06 14:16:36 lb avahi-daemon[802]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.42.1.
    Oct 06 14:16:36 lb avahi-daemon[802]: New relevant interface wlan0.IPv4 for mDNS.
    Oct 06 14:16:36 lb avahi-daemon[802]: Registering new address record for 192.168.42.1 on wlan0.IPv4.
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.1449] device (wlan0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
    Oct 06 14:16:36 lb dbus-daemon[747]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.4' (uid=0 pid=801 comm="/usr/sbin/NetworkManager --no-daemon ")
    Oct 06 14:16:36 lb dbus-daemon[747]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.2344] device (wlan0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.2362] device (wlan0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
    Oct 06 14:16:36 lb NetworkManager[801]: <info>  [1601993796.2469] device (wlan0): Activation: successful, device activated.
    Oct 06 14:16:36 lb nm-dispatcher[1577]: resin-ntp-config: Found config.json in /mnt/boot/config.json .
    Oct 06 14:16:36 lb nm-dispatcher[1577]: 200 OK
    Oct 06 14:16:37 lb a7c48f95c1c8[814]: [38B blob data]
    Oct 06 14:16:37 lb a7c48f95c1c8[814]: [42B blob data]
    Oct 06 14:16:37 lb 	[836]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1
    Oct 06 14:16:38 lb wpa_supplicant[836]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1
    Oct 06 14:16:39 lb wpa_supplicant[836]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1
    Oct 06 14:16:40 lb wpa_supplicant[836]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1
    Oct 06 14:16:41 lb wpa_supplicant[836]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1
    Oct 06 14:16:41 lb resin-supervisor[1316]: [info]    Supervisor v11.9.9 starting up...
    Oct 06 14:16:41 lb a9a33d49bc65[814]: [info]    Supervisor v11.9.9 starting up...
    Oct 06 14:16:42 lb wpa_supplicant[836]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1
    Oct 06 14:16:42 lb a9a33d49bc65[814]: [info]    Setting host to discoverable
    Oct 06 14:16:42 lb resin-supervisor[1316]: [info]    Setting host to discoverable
    Oct 06 14:16:42 lb a9a33d49bc65[814]: [warn]    Invalid firewall mode: . Reverting to state: off
    Oct 06 14:16:42 lb resin-supervisor[1316]: [warn]    Invalid firewall mode: . Reverting to state: off
    Oct 06 14:16:42 lb a9a33d49bc65[814]: [info]    šŸ”„ Applying firewall mode: off
    Oct 06 14:16:42 lb resin-supervisor[1316]: [info]    šŸ”„ Applying firewall mode: off
    Oct 06 14:16:42 lb a9a33d49bc65[814]: [debug]   Starting logging infrastructure
    Oct 06 14:16:42 lb resin-supervisor[1316]: [debug]   Starting logging infrastructure
    Oct 06 14:16:42 lb a9a33d49bc65[814]: [info]    Starting firewall
    Oct 06 14:16:42 lb resin-supervisor[1316]: [info]    Starting firewall
    Oct 06 14:16:43 lb a9a33d49bc65[814]: [success] šŸ”„ Firewall mode applied
    Oct 06 14:16:43 lb resin-supervisor[1316]: [success] šŸ”„ Firewall mode applied
    Oct 06 14:16:43 lb resin-supervisor[1316]: [debug]   Starting api binder
    Oct 06 14:16:43 lb a9a33d49bc65[814]: [debug]   Starting api binder
    Oct 06 14:16:43 lb a9a33d49bc65[814]: [debug]   Unmanaged mode is set, skipping API client initialization
    Oct 06 14:16:43 lb resin-supervisor[1316]: [debug]   Unmanaged mode is set, skipping API client initialization
    Oct 06 14:16:43 lb wpa_supplicant[836]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1
    Oct 06 14:16:43 lb a9a33d49bc65[814]: [event]   Event: Supervisor start {}
    Oct 06 14:16:43 lb resin-supervisor[1316]: [event]   Event: Supervisor start {}
    Oct 06 14:16:43 lb a9a33d49bc65[814]: [debug]   Performing database cleanup for container log timestamps
    Oct 06 14:16:43 lb resin-supervisor[1316]: [debug]   Performing database cleanup for container log timestamps
    Oct 06 14:16:44 lb wpa_supplicant[836]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1
    Oct 06 14:16:44 lb a9a33d49bc65[814]: [info]    Starting up in unmanaged mode, activating local mode
    Oct 06 14:16:44 lb resin-supervisor[1316]: [info]    Starting up in unmanaged mode, activating local mode
    Oct 06 14:16:44 lb resin-supervisor[1316]: [info]    Switching logging backend to LocalLogBackend
    Oct 06 14:16:44 lb a9a33d49bc65[814]: [info]    Switching logging backend to LocalLogBackend
    Oct 06 14:16:44 lb a9a33d49bc65[814]: [warn]    Invalid firewall mode: . Reverting to state: off
    Oct 06 14:16:44 lb resin-supervisor[1316]: [warn]    Invalid firewall mode: . Reverting to state: off
    Oct 06 14:16:44 lb resin-supervisor[1316]: [info]    šŸ”„ Applying firewall mode: off
    Oct 06 14:16:44 lb a9a33d49bc65[814]: [info]    šŸ”„ Applying firewall mode: off
    Oct 06 14:16:44 lb a9a33d49bc65[814]: [debug]   Connectivity check enabled: true
    Oct 06 14:16:44 lb resin-supervisor[1316]: [debug]   Connectivity check enabled: true
    Oct 06 14:16:44 lb a9a33d49bc65[814]: [debug]   No API endpoint specified, skipping connectivity check
    Oct 06 14:16:44 lb resin-supervisor[1316]: [debug]   No API endpoint specified, skipping connectivity check
    Oct 06 14:16:44 lb resin-supervisor[1316]: [debug]   Starting periodic check for IP addresses
    Oct 06 14:16:44 lb a9a33d49bc65[814]: [debug]   Starting periodic check for IP addresses
    Oct 06 14:16:44 lb a9a33d49bc65[814]: [info]    Reporting initial state, supervisor version and API info
    Oct 06 14:16:44 lb resin-supervisor[1316]: [info]    Reporting initial state, supervisor version and API info
5

And I am accessing it through Ethernet, the wifi connect isnā€™t used.

Also running as local mode with balena push.

7

@@os user is having similar problem as seen in the forum thread above. Can you take a look? Meanwhile, Iā€™ll ask to provide diagnostics logs.

8

Sorry, this meant to be a private message. Iā€™ve pinged os team to take a look.

9

Could you please provide the device diagnostics snapshot file from the ā€œdevice diagnosticsā€ tab on the ā€œdiagnosticsā€ page of the dashboard (after running the diagnostics)?

11

Not sure what this is. Presumably something related to Balena web based control panel? I am using a local image build with balena push, itā€™s not connected to to the balena system.

12

Hi,
Can you also clarify the balenaOS version that you are running?
Also, other than the log thatā€™s printed, is there any other issue with the device running that only occurs in the case that you are getting those TRL-EVENT-SCAN-FAILED logs?

Kind regards,
Thodoris

15 
ID="balena-os"

NAME="balenaOS"

VERSION="2.53.9+rev1"

VERSION_ID="2.53.9+rev1"

PRETTY_NAME="balenaOS 2.53.9+rev1"

MACHINE="orange-pi-zero"

VARIANT="Development"

VARIANT_ID="dev"

META_BALENA_VERSION="2.53.9"

RESIN_BOARD_REV="f3f7539"

META_RESIN_REV="1a10689"

SLUG="orange-pi-zero"

Not quite sure I fully understand your final question.

16

Let me clarify that.
You are reporting that those error logs get printed every second, but is there any other issue that you are facing with the device while the logs show up?
You also mentioned that you are using ethernet. If you disconnect the ethernet cable, does wifi-connect works properly?

17

It appeared to take a while to connect to the device as a wifi hotspot, but I have been able to connect with my phone and browse the device as normal, despite the messages still appearing every second.

Can still SSH into the device through the ethernet too.

The device was running ok, no errors, then I did a quick consecutive restart of the two containers and the errors reoccured. Here are the logs for the period.

Oct 08 18:20:21 lb 977dc814ee15[824]: [debug] Container log timestamp flush complete

Oct 08 18:20:22 lb 977dc814ee15[824]: [api] GET /v1/healthy 200 - 49.601 ms

Oct 08 18:20:22 lb resin-supervisor[1512]: [api] GET /v1/healthy 200 - 49.601 ms

Oct 08 18:22:01 lb balenad[824]: time="2020-10-08T18:22:01.503240199Z" level=info msg="Container c1eca41ce42d427536201ade53eb5d2704fe53b7c10854ec6710e834a1824e09 failed to exit within 10 seconds of signal 15 - using the force"

Oct 08 18:22:05 lb balenad[824]: time="2020-10-08T18:22:05.801781279Z" level=info msg="shim reaped" id=c1eca41ce42d427536201ade53eb5d2704fe53b7c10854ec6710e834a1824e09

Oct 08 18:22:05 lb balenad[824]: time="2020-10-08T18:22:05.805402376Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"

Oct 08 18:22:10 lb 977dc814ee15[824]: [event] Event: Service exit {"service":{"appId":1,"serviceId":2,"serviceName":"wifi-connect","releaseId":1}}

Oct 08 18:22:10 lb resin-supervisor[1512]: [event] Event: Service exit {"service":{"appId":1,"serviceId":2,"serviceName":"wifi-connect","releaseId":1}}

Oct 08 18:22:16 lb balenad[824]: time="2020-10-08T18:22:16.517903692Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/16f886b106e28c7e7b60051823e213f7b28e8031f7dfd5476b7ffc6212855fa1.sock debug=false pid=5102

Oct 08 18:22:19 lb 977dc814ee15[824]: [event] Event: Service restart {"service":{"appId":1,"serviceId":2,"serviceName":"wifi-connect","releaseId":1}}

Oct 08 18:22:19 lb resin-supervisor[1512]: [event] Event: Service restart {"service":{"appId":1,"serviceId":2,"serviceName":"wifi-connect","releaseId":1}}

Oct 08 18:22:31 lb balenad[824]: time="2020-10-08T18:22:31.472865802Z" level=info msg="Container 4bd542f2fcaf5bca8f9ef752f9072842454d98e364c534dfa878c2924a68bb2d failed to exit within 10 seconds of signal 15 - using the force"

Oct 08 18:22:33 lb c1eca41ce42d[824]: [22B blob data]

Oct 08 18:22:33 lb c1eca41ce42d[824]: [91B blob data]

Oct 08 18:22:33 lb NetworkManager[812]: <info> [1602181353.3063] device (wlan0): state change: activated -> deactivating (reason 'connection-removed', sys-iface-state: 'managed')

Oct 08 18:22:33 lb NetworkManager[812]: <info> [1602181353.3354] audit: op="connection-delete" uuid="acf97bb1-9dbe-4be7-abdf-01d345566707" name="Learners-Block" pid=5259 uid=0 result="success"

Oct 08 18:22:33 lb dbus-daemon[752]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.4' (uid=0 pid=812 comm="/usr/sbin/NetworkManager --no-daemon ")

Oct 08 18:22:33 lb systemd[1]: **Failed to trim compat systemd cgroup /system.slice/docker-4bd542f2fcaf5bca8f9ef752f9072842454d98e364c534dfa878c2924a68bb2d.scope: Device or resource busy**

Oct 08 18:22:33 lb dbus-daemon[752]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'

Oct 08 18:22:33 lb wpa_supplicant[848]: wlan0: interface state ENABLED->DISABLED

Oct 08 18:22:33 lb wpa_supplicant[848]: wlan0: AP-DISABLED

Oct 08 18:22:33 lb kernel: ieee80211 phy0: ignore IEEE80211_CONF_CHANGE_MONITOR (0)IEEE80211_CONF_CHANGE_IDLE (1)

Oct 08 18:22:33 lb kernel: ieee80211 phy0: changing interface type; new type=2(3), p2p=0(0)

Oct 08 18:22:33 lb kernel: **ieee80211 phy0: !!! vif_id=0**

Oct 08 18:22:33 lb kernel: ieee80211 phy0: Interface ID:0 of type:2 added

Oct 08 18:22:33 lb kernel: ieee80211 phy0: vif 0, configuring tx

Oct 08 18:22:33 lb kernel: ieee80211 phy0: vif 0, configuring tx

Oct 08 18:22:33 lb kernel: ieee80211 phy0: vif 0, configuring tx

Oct 08 18:22:33 lb kernel: ieee80211 phy0: vif 0, configuring tx

Oct 08 18:22:33 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-DISCONNECTED bssid=12:42:70:5b:85:ff reason=3 locally_generated=1

Oct 08 18:22:33 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD

Oct 08 18:22:33 lb NetworkManager[812]: <info> [1602181353.7710] device (wlan0): supplicant interface state: completed -> disconnected

Oct 08 18:22:33 lb NetworkManager[812]: <info> [1602181353.7717] device (wlan0): state change: deactivating -> disconnected (reason 'connection-removed', sys-iface-state: 'managed')

Oct 08 18:22:33 lb avahi-daemon[814]: Withdrawing address record for fe80::ef16:48d7:cd7f:ed12 on wlan0.

Oct 08 18:22:33 lb avahi-daemon[814]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::ef16:48d7:cd7f:ed12.

Oct 08 18:22:33 lb avahi-daemon[814]: Interface wlan0.IPv6 no longer relevant for mDNS.

Oct 08 18:22:33 lb avahi-daemon[814]: Withdrawing address record for 192.168.42.1 on wlan0.

Oct 08 18:22:33 lb avahi-daemon[814]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.42.1.

Oct 08 18:22:33 lb avahi-daemon[814]: Interface wlan0.IPv4 no longer relevant for mDNS.

Oct 08 18:22:34 lb c1eca41ce42d[824]: [19B blob data]

Oct 08 18:22:35 lb c1eca41ce42d[824]: [192B blob data]

Oct 08 18:22:35 lb c1eca41ce42d[824]: [25B blob data]

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.2570] device (wlan0): Activation: starting connection 'Learners-Block' (5a81089f-dbd4-451a-abf9-87d597d21244)

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.2576] audit: op="connection-add-activate" uuid="5a81089f-dbd4-451a-abf9-87d597d21244" name="Learners-Block" pid=5259 uid=0 result="success"

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.2615] device (wlan0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.3064] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.3141] device (wlan0): Activation: (wifi) connection 'Learners-Block' requires no security. No secrets needed.

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.3159] Config: added 'ssid' value 'Learners-Block'

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.3161] Config: added 'mode' value '2'

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.3162] Config: added 'frequency' value '2412'

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.3163] Config: added 'freq_list' value '2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472 2484'

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.3164] Config: added 'key_mgmt' value 'NONE'

Oct 08 18:22:35 lb wpa_supplicant[848]: Note: nl80211 driver interface is not designed to be used with ap_scan=2; this can result in connection failures

Oct 08 18:22:35 lb kernel: ieee80211 phy0: changing interface type; new type=3(2), p2p=0(0)

Oct 08 18:22:35 lb kernel: **ieee80211 phy0: !!! vif_id=0**

Oct 08 18:22:35 lb kernel: ieee80211 phy0: Interface ID:0 of type:3 added

Oct 08 18:22:35 lb kernel: ieee80211 phy0: vif 0, configuring tx

Oct 08 18:22:35 lb kernel: ieee80211 phy0: vif 0, configuring tx

Oct 08 18:22:35 lb kernel: ieee80211 phy0: vif 0, configuring tx

Oct 08 18:22:35 lb kernel: ieee80211 phy0: vif 0, configuring tx

Oct 08 18:22:35 lb wpa_supplicant[848]: Using interface wlan0 with hwaddr 12:42:70:5b:85:ff and ssid "Learners-Block"

Oct 08 18:22:35 lb wpa_supplicant[848]: Device is trying to offload WPS Probe Response while not supporting this

Oct 08 18:22:35 lb kernel: ieee80211 phy0: ignore IEEE80211_CONF_CHANGE_MONITOR (0)IEEE80211_CONF_CHANGE_IDLE (1)

Oct 08 18:22:35 lb wpa_supplicant[848]: wlan0: interface state UNINITIALIZED->ENABLED

Oct 08 18:22:35 lb wpa_supplicant[848]: wlan0: AP-ENABLED

Oct 08 18:22:35 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-CONNECTED - Connection to 12:42:70:5b:85:ff completed [id=0 id_str=]

Oct 08 18:22:35 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:35 lb kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready

Oct 08 18:22:35 lb kernel: ieee80211 phy0: vif 0, configuring tx

Oct 08 18:22:35 lb kernel: ieee80211 phy0: vif 0, configuring tx

Oct 08 18:22:35 lb kernel: ieee80211 phy0: vif 0, configuring tx

Oct 08 18:22:35 lb kernel: ieee80211 phy0: vif 0, configuring tx

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.3930] device (wlan0): supplicant interface state: disconnected -> completed

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.3932] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Started Wi-Fi Hotspot "Learners-Block"

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.3988] device (wlan0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')

Oct 08 18:22:35 lb avahi-daemon[814]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::b60b:571f:26e2:70ba.

Oct 08 18:22:35 lb avahi-daemon[814]: New relevant interface wlan0.IPv6 for mDNS.

Oct 08 18:22:35 lb avahi-daemon[814]: Registering new address record for fe80::b60b:571f:26e2:70ba on wlan0.*.

Oct 08 18:22:35 lb avahi-daemon[814]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.42.1.

Oct 08 18:22:35 lb avahi-daemon[814]: New relevant interface wlan0.IPv4 for mDNS.

Oct 08 18:22:35 lb avahi-daemon[814]: Registering new address record for 192.168.42.1 on wlan0.IPv4.

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.4159] device (wlan0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.4427] device (wlan0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.4504] device (wlan0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')

Oct 08 18:22:35 lb NetworkManager[812]: <info> [1602181355.4637] device (wlan0): Activation: successful, device activated.

Oct 08 18:22:36 lb nm-dispatcher[5265]: resin-ntp-config: Found config.json in /mnt/boot/config.json .

Oct 08 18:22:36 lb nm-dispatcher[5265]: 200 OK

Oct 08 18:22:36 lb c1eca41ce42d[824]: [38B blob data]

Oct 08 18:22:36 lb c1eca41ce42d[824]: [42B blob data]

Oct 08 18:22:36 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:37 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:38 lb balenad[824]: time="2020-10-08T18:22:38.037643983Z" level=info msg="shim reaped" id=4bd542f2fcaf5bca8f9ef752f9072842454d98e364c534dfa878c2924a68bb2d

Oct 08 18:22:38 lb balenad[824]: time="2020-10-08T18:22:38.048239652Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"

Oct 08 18:22:38 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:38 lb kernel: vetha3a5279: renamed from eth0

Oct 08 18:22:38 lb kernel: br-b3917a75692e: port 1(vethe485b83) entered disabled state

Oct 08 18:22:38 lb systemd-udevd[5428]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.

Oct 08 18:22:38 lb systemd-udevd[5428]: Using default interface naming scheme 'v240'.

Oct 08 18:22:38 lb NetworkManager[812]: <info> [1602181358.7837] manager: (vetha3a5279): new Veth device (/org/freedesktop/NetworkManager/Devices/15)

Oct 08 18:22:39 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:40 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:40 lb avahi-daemon[814]: Interface vethe485b83.IPv6 no longer relevant for mDNS.

Oct 08 18:22:40 lb avahi-daemon[814]: Leaving mDNS multicast group on interface vethe485b83.IPv6 with address fe80::143c:5cff:fef4:2a05.

Oct 08 18:22:40 lb kernel: br-b3917a75692e: port 1(vethe485b83) entered disabled state

Oct 08 18:22:40 lb kernel: device vethe485b83 left promiscuous mode

Oct 08 18:22:40 lb kernel: br-b3917a75692e: port 1(vethe485b83) entered disabled state

Oct 08 18:22:40 lb avahi-daemon[814]: Withdrawing address record for fe80::143c:5cff:fef4:2a05 on vethe485b83.

Oct 08 18:22:40 lb NetworkManager[812]: <info> [1602181360.5825] device (vethe485b83): released from master device br-b3917a75692e

Oct 08 18:22:41 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:42 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:43 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:44 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:45 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:46 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:47 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:47 lb kernel: veth15ebfa2: renamed from eth1

Oct 08 18:22:47 lb systemd-udevd[5433]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.

Oct 08 18:22:47 lb kernel: supervisor0: port 1(veth624d2f2) entered disabled state

Oct 08 18:22:47 lb systemd-udevd[5433]: Using default interface naming scheme 'v240'.

Oct 08 18:22:47 lb NetworkManager[812]: <info> [1602181367.6408] manager: (veth15ebfa2): new Veth device (/org/freedesktop/NetworkManager/Devices/16)

Oct 08 18:22:48 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:49 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:50 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:51 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:52 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:53 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:54 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:55 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:55 lb avahi-daemon[814]: Interface veth624d2f2.IPv6 no longer relevant for mDNS.

Oct 08 18:22:55 lb avahi-daemon[814]: Leaving mDNS multicast group on interface veth624d2f2.IPv6 with address fe80::6488:13ff:fea6:ce6c.

Oct 08 18:22:55 lb kernel: supervisor0: port 1(veth624d2f2) entered disabled state

Oct 08 18:22:55 lb kernel: device veth624d2f2 left promiscuous mode

Oct 08 18:22:55 lb kernel: supervisor0: port 1(veth624d2f2) entered disabled state

Oct 08 18:22:55 lb avahi-daemon[814]: Withdrawing address record for fe80::6488:13ff:fea6:ce6c on veth624d2f2.

Oct 08 18:22:55 lb NetworkManager[812]: <info> [1602181375.7855] device (veth624d2f2): released from master device supervisor0

Oct 08 18:22:56 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:57 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:58 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:22:59 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:00 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:01 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:02 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:03 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:04 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:05 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:06 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:07 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:08 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:09 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:10 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:11 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:12 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:13 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:13 lb 977dc814ee15[824]: [event] Event: Service exit {"service":{"appId":1,"serviceId":1,"serviceName":"api","releaseId":1}}

Oct 08 18:23:13 lb resin-supervisor[1512]: [event] Event: Service exit {"service":{"appId":1,"serviceId":1,"serviceName":"api","releaseId":1}}

Oct 08 18:23:14 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:15 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:16 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:17 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:18 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:19 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:19 lb kernel: br-b3917a75692e: port 1(vethd64c641) entered blocking state

Oct 08 18:23:19 lb kernel: br-b3917a75692e: port 1(vethd64c641) entered disabled state

Oct 08 18:23:19 lb kernel: device vethd64c641 entered promiscuous mode

Oct 08 18:23:19 lb systemd-udevd[5560]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.

Oct 08 18:23:19 lb systemd-udevd[5559]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.

Oct 08 18:23:19 lb systemd-udevd[5559]: Using default interface naming scheme 'v240'.

Oct 08 18:23:19 lb systemd-udevd[5560]: Using default interface naming scheme 'v240'.

Oct 08 18:23:19 lb systemd-udevd[5559]: **Could not generate persistent MAC address for vethd200df6: No such file or directory**

Oct 08 18:23:19 lb systemd-udevd[5560]: **Could not generate persistent MAC address for vethd64c641: No such file or directory**

Oct 08 18:23:19 lb NetworkManager[812]: <info> [1602181399.7574] manager: (vethd200df6): new Veth device (/org/freedesktop/NetworkManager/Devices/17)

Oct 08 18:23:19 lb NetworkManager[812]: <info> [1602181399.7668] manager: (vethd64c641): new Veth device (/org/freedesktop/NetworkManager/Devices/18)

Oct 08 18:23:20 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:21 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:22 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:23 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:24 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:25 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:26 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:27 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:28 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:29 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:30 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:31 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:32 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:33 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:34 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:35 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:35 lb kernel: supervisor0: port 1(veth31a612e) entered blocking state

Oct 08 18:23:35 lb kernel: supervisor0: port 1(veth31a612e) entered disabled state

Oct 08 18:23:35 lb kernel: device veth31a612e entered promiscuous mode

Oct 08 18:23:35 lb systemd-udevd[5566]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.

Oct 08 18:23:35 lb systemd-udevd[5566]: Using default interface naming scheme 'v240'.

Oct 08 18:23:35 lb systemd-udevd[5566]: **Could not generate persistent MAC address for veth31a612e: No such file or directory**

Oct 08 18:23:35 lb NetworkManager[812]: <info> [1602181415.8322] manager: (vethda40960): new Veth device (/org/freedesktop/NetworkManager/Devices/19)

Oct 08 18:23:35 lb systemd-udevd[5565]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.

Oct 08 18:23:35 lb systemd-udevd[5565]: Using default interface naming scheme 'v240'.

Oct 08 18:23:35 lb systemd-udevd[5565]: **Could not generate persistent MAC address for vethda40960: No such file or directory**

Oct 08 18:23:35 lb NetworkManager[812]: <info> [1602181415.8465] manager: (veth31a612e): new Veth device (/org/freedesktop/NetworkManager/Devices/20)

Oct 08 18:23:36 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:37 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:38 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:39 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:40 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:41 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:42 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:43 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:44 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:45 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:46 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:47 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:48 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:49 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:50 lb balenad[824]: time="2020-10-08T18:23:50.203924458Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/ec1bf6e35db6eac9d04f366143f502a29a1581e55e91df506b9187f5110750d6.sock debug=false pid=5668

Oct 08 18:23:50 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:51 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:52 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:53 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:53 lb balenad[824]: time="2020-10-08T18:23:53.713953231Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/b7d468753028e7d1136c3242795eb2dc40f468bac13a22471963b515f04bd69f.sock debug=false pid=5722

Oct 08 18:23:54 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:55 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:55 lb kernel: eth0: renamed from vethd200df6

Oct 08 18:23:55 lb kernel: IPv6: ADDRCONF(NETDEV_CHANGE): vethd64c641: link becomes ready

Oct 08 18:23:55 lb kernel: br-b3917a75692e: port 1(vethd64c641) entered blocking state

Oct 08 18:23:55 lb kernel: br-b3917a75692e: port 1(vethd64c641) entered forwarding state

Oct 08 18:23:55 lb NetworkManager[812]: <info> [1602181435.9166] device (vethd64c641): carrier: link connected

Oct 08 18:23:56 lb balenad[824]: time="2020-10-08T18:23:56.449779626Z" level=info msg="shim reaped" id=3c105ca4b9fd32b652538e78ee50655286df3aa7aab8215527905547be7f188a

Oct 08 18:23:56 lb balenad[824]: time="2020-10-08T18:23:56.490454961Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"

Oct 08 18:23:56 lb kernel: eth1: renamed from vethda40960

Oct 08 18:23:56 lb kernel: IPv6: ADDRCONF(NETDEV_CHANGE): veth31a612e: link becomes ready

Oct 08 18:23:56 lb kernel: supervisor0: port 1(veth31a612e) entered blocking state

Oct 08 18:23:56 lb kernel: supervisor0: port 1(veth31a612e) entered forwarding state

Oct 08 18:23:56 lb NetworkManager[812]: <info> [1602181436.5781] device (veth31a612e): carrier: link connected

Oct 08 18:23:56 lb NetworkManager[812]: <info> [1602181436.5809] device (supervisor0): carrier: link connected

Oct 08 18:23:56 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:57 lb avahi-daemon[814]: Joining mDNS multicast group on interface vethd64c641.IPv6 with address fe80::dc05:d2ff:fe8d:8908.

Oct 08 18:23:57 lb avahi-daemon[814]: New relevant interface vethd64c641.IPv6 for mDNS.

Oct 08 18:23:57 lb avahi-daemon[814]: Registering new address record for fe80::dc05:d2ff:fe8d:8908 on vethd64c641.*.

Oct 08 18:23:57 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:57 lb avahi-daemon[814]: Joining mDNS multicast group on interface veth31a612e.IPv6 with address fe80::b0b0:22ff:fec7:a2a8.

Oct 08 18:23:57 lb avahi-daemon[814]: New relevant interface veth31a612e.IPv6 for mDNS.

Oct 08 18:23:57 lb avahi-daemon[814]: Registering new address record for fe80::b0b0:22ff:fec7:a2a8 on veth31a612e.*.

Oct 08 18:23:58 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:23:59 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:24:00 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:24:01 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:24:02 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:24:03 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:24:04 lb resin-supervisor[1512]: [event] Event: Service restart {"service":{"appId":1,"serviceId":1,"serviceName":"api","releaseId":1}}

Oct 08 18:24:04 lb 977dc814ee15[824]: [event] Event: Service restart {"service":{"appId":1,"serviceId":1,"serviceName":"api","releaseId":1}}

Oct 08 18:24:04 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:24:05 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:24:06 lb systemd-tmpfiles[5848]: **[/etc/tmpfiles.d/openvpn.conf:1] Line references path below legacy directory /var/run/, updating /var/run/openvpn ā†’ /run/openvpn; please update the tmpfiles.d/ drop-in file accordingly.**

Oct 08 18:24:06 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:24:06 lb sh[5849]: Getting image name and tag...

Oct 08 18:24:06 lb sh[5849]: No supervisor configuration found from API or required variables not set. Using arguments for image and tag.

Oct 08 18:24:06 lb sh[5849]: Set based on arguments image=balena/armv7hf-supervisor and tag=v11.9.9.

Oct 08 18:24:06 lb sh[5849]: Getting image id...

Oct 08 18:24:07 lb sh[5849]: Supervisor balena/armv7hf-supervisor:v11.9.9 already downloaded.

Oct 08 18:24:07 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

Oct 08 18:24:08 lb wpa_supplicant[848]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1

The error continues to echo every second with no other updates after this.

18

And now a new scenario. This time I rebooted the device. It loaded all the containers, and I have it a few minutes to full load. I checked the journalctl logs and everything was fine.

I then did a restart of the wifi-connect container, and just the wifi-connect container. The error messages then started appearing every second. It appears therefore the quick restart of the two containers is unrelated, it is just an intermittent occurring issue when restarting the wifi-connect container.

Here are the logs from that instance:

Oct 08 18:42:45 lb balenad[817]: time="2020-10-08T18:42:45.108313205Z" level=info msg="Container c1eca41ce42d427536201ade53eb5d2704fe53b7c10854ec6710e834a1824e09 failed to exit within 10 seconds of signal 15 - using the force"
Oct 08 18:42:47 lb balenad[817]: time="2020-10-08T18:42:47.000366030Z" level=info msg="shim reaped" id=c1eca41ce42d427536201ade53eb5d2704fe53b7c10854ec6710e834a1824e09
Oct 08 18:42:47 lb balenad[817]: time="2020-10-08T18:42:47.005509638Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Oct 08 18:42:47 lb resin-supervisor[1441]: [event]   Event: Service exit {"service":{"appId":1,"serviceId":2,"serviceName":"wifi-connect","releaseId":1}}
Oct 08 18:42:47 lb f5d1d2cec3b6[817]: [event]   Event: Service exit {"service":{"appId":1,"serviceId":2,"serviceName":"wifi-connect","releaseId":1}}
Oct 08 18:42:47 lb balenad[817]: time="2020-10-08T18:42:47.814550045Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/16f886b106e28c7e7b60051823e213f7b28e8031f7dfd5476b7ffc6212855fa1.sock debug=false pid=2027
Oct 08 18:42:50 lb f5d1d2cec3b6[817]: [event]   Event: Service restart {"service":{"appId":1,"serviceId":2,"serviceName":"wifi-connect","releaseId":1}}
Oct 08 18:42:50 lb resin-supervisor[1441]: [event]   Event: Service restart {"service":{"appId":1,"serviceId":2,"serviceName":"wifi-connect","releaseId":1}}
Oct 08 18:43:04 lb c1eca41ce42d[817]: [22B blob data]
Oct 08 18:43:04 lb c1eca41ce42d[817]: [91B blob data]
Oct 08 18:43:04 lb NetworkManager[804]: <info>  [1602182584.6602] device (wlan0): state change: activated -> deactivating (reason 'connection-removed', sys-iface-state: 'managed')
Oct 08 18:43:04 lb dbus-daemon[764]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.4' (uid=0 pid=804 comm="/usr/sbin/NetworkManager --no-daemon ")
Oct 08 18:43:04 lb NetworkManager[804]: <info>  [1602182584.6883] audit: op="connection-delete" uuid="71ab5e5a-ed14-4b7c-8a24-350fe837c3d2" name="Learners-Block" pid=2160 uid=0 result="success"
Oct 08 18:43:04 lb dbus-daemon[764]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Oct 08 18:43:04 lb wpa_supplicant[841]: wlan0: interface state ENABLED->DISABLED
Oct 08 18:43:04 lb wpa_supplicant[841]: wlan0: AP-DISABLED
Oct 08 18:43:04 lb kernel: ieee80211 phy0: ignore IEEE80211_CONF_CHANGE_MONITOR (0)IEEE80211_CONF_CHANGE_IDLE (1)
Oct 08 18:43:04 lb kernel: ieee80211 phy0: changing interface type; new type=2(3), p2p=0(0)
Oct 08 18:43:04 lb kernel: ieee80211 phy0: !!! vif_id=0
Oct 08 18:43:04 lb kernel: ieee80211 phy0: Interface ID:0 of type:2 added
Oct 08 18:43:04 lb kernel: ieee80211 phy0: vif 0, configuring tx
Oct 08 18:43:04 lb kernel: ieee80211 phy0: vif 0, configuring tx
Oct 08 18:43:04 lb kernel: ieee80211 phy0: vif 0, configuring tx
Oct 08 18:43:04 lb kernel: ieee80211 phy0: vif 0, configuring tx
Oct 08 18:43:04 lb wpa_supplicant[841]: wlan0: CTRL-EVENT-DISCONNECTED bssid=12:42:70:5b:85:ff reason=3 locally_generated=1
Oct 08 18:43:04 lb wpa_supplicant[841]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Oct 08 18:43:04 lb NetworkManager[804]: <info>  [1602182584.7887] device (wlan0): supplicant interface state: completed -> disconnected
Oct 08 18:43:04 lb NetworkManager[804]: <info>  [1602182584.7897] device (wlan0): state change: deactivating -> disconnected (reason 'connection-removed', sys-iface-state: 'managed')
Oct 08 18:43:04 lb avahi-daemon[806]: Withdrawing address record for fe80::1398:1ba6:bf61:ec5a on wlan0.
Oct 08 18:43:04 lb avahi-daemon[806]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::1398:1ba6:bf61:ec5a.
Oct 08 18:43:04 lb avahi-daemon[806]: Interface wlan0.IPv6 no longer relevant for mDNS.
Oct 08 18:43:04 lb avahi-daemon[806]: Withdrawing address record for 192.168.42.1 on wlan0.
Oct 08 18:43:04 lb avahi-daemon[806]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.42.1.
Oct 08 18:43:04 lb avahi-daemon[806]: Interface wlan0.IPv4 no longer relevant for mDNS.
Oct 08 18:43:04 lb c1eca41ce42d[817]: [19B blob data]
Oct 08 18:43:06 lb c1eca41ce42d[817]: [190B blob data]
Oct 08 18:43:06 lb c1eca41ce42d[817]: [25B blob data]
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.1850] device (wlan0): Activation: starting connection 'Learners-Block' (a1ef194a-9971-4bdf-bbbb-b579ef451d67)
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.1856] audit: op="connection-add-activate" uuid="a1ef194a-9971-4bdf-bbbb-b579ef451d67" name="Learners-Block" pid=2160 uid=0 result="success"
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.1882] device (wlan0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.2117] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.2176] device (wlan0): Activation: (wifi) connection 'Learners-Block' requires no security.  No secrets needed.
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.2186] Config: added 'ssid' value 'Learners-Block'
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.2188] Config: added 'mode' value '2'
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.2189] Config: added 'frequency' value '2412'
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.2189] Config: added 'freq_list' value '2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472 2484'
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.2190] Config: added 'key_mgmt' value 'NONE'
Oct 08 18:43:06 lb wpa_supplicant[841]: Note: nl80211 driver interface is not designed to be used with ap_scan=2; this can result in connection failures
Oct 08 18:43:06 lb wpa_supplicant[841]: Using interface wlan0 with hwaddr 12:42:70:5b:85:ff and ssid "Learners-Block"
Oct 08 18:43:06 lb wpa_supplicant[841]: Device is trying to offload WPS Probe Response while not supporting this
Oct 08 18:43:06 lb kernel: ieee80211 phy0: changing interface type; new type=3(2), p2p=0(0)
Oct 08 18:43:06 lb kernel: ieee80211 phy0: !!! vif_id=0
Oct 08 18:43:06 lb kernel: ieee80211 phy0: Interface ID:0 of type:3 added
Oct 08 18:43:06 lb kernel: ieee80211 phy0: vif 0, configuring tx
Oct 08 18:43:06 lb kernel: ieee80211 phy0: vif 0, configuring tx
Oct 08 18:43:06 lb kernel: ieee80211 phy0: vif 0, configuring tx
Oct 08 18:43:06 lb kernel: ieee80211 phy0: vif 0, configuring tx
Oct 08 18:43:06 lb kernel: ieee80211 phy0: ignore IEEE80211_CONF_CHANGE_MONITOR (0)IEEE80211_CONF_CHANGE_IDLE (1)
Oct 08 18:43:06 lb wpa_supplicant[841]: wlan0: interface state UNINITIALIZED->ENABLED
Oct 08 18:43:06 lb kernel: ieee80211 phy0: vif 0, configuring tx
Oct 08 18:43:06 lb kernel: ieee80211 phy0: vif 0, configuring tx
Oct 08 18:43:06 lb kernel: ieee80211 phy0: vif 0, configuring tx
Oct 08 18:43:06 lb kernel: ieee80211 phy0: vif 0, configuring tx
Oct 08 18:43:06 lb kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Oct 08 18:43:06 lb wpa_supplicant[841]: wlan0: AP-ENABLED
Oct 08 18:43:06 lb wpa_supplicant[841]: wlan0: CTRL-EVENT-CONNECTED - Connection to 12:42:70:5b:85:ff completed [id=0 id_str=]
Oct 08 18:43:06 lb wpa_supplicant[841]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.3201] device (wlan0): supplicant interface state: disconnected -> completed
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.3204] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Started Wi-Fi Hotspot "Learners-Block"
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.3216] device (wlan0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Oct 08 18:43:06 lb avahi-daemon[806]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::72fa:b4b6:c69e:74de.
Oct 08 18:43:06 lb avahi-daemon[806]: New relevant interface wlan0.IPv6 for mDNS.
Oct 08 18:43:06 lb avahi-daemon[806]: Registering new address record for fe80::72fa:b4b6:c69e:74de on wlan0.*.
Oct 08 18:43:06 lb avahi-daemon[806]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.42.1.
Oct 08 18:43:06 lb avahi-daemon[806]: New relevant interface wlan0.IPv4 for mDNS.
Oct 08 18:43:06 lb avahi-daemon[806]: Registering new address record for 192.168.42.1 on wlan0.IPv4.
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.3552] device (wlan0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.3719] device (wlan0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.3737] device (wlan0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Oct 08 18:43:06 lb NetworkManager[804]: <info>  [1602182586.3927] device (wlan0): Activation: successful, device activated.
Oct 08 18:43:06 lb nm-dispatcher[2167]: resin-ntp-config: Found config.json in /mnt/boot/config.json .
Oct 08 18:43:06 lb nm-dispatcher[2167]: 200 OK
Oct 08 18:43:07 lb c1eca41ce42d[817]: [38B blob data]
Oct 08 18:43:07 lb c1eca41ce42d[817]: [42B blob data]
Oct 08 18:43:07 lb wpa_supplicant[841]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1
Oct 08 18:43:08 lb wpa_supplicant[841]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1
Oct 08 18:43:09 lb wpa_supplicant[841]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1
Oct 08 18:43:10 lb wpa_supplicant[841]: wlan0: CTRL-EVENT-SCAN-FAILED ret=-95 retry=1
23

Hi there ā€“ thanks very kindly for the additional information. At this point, it appears that you are probably experiencing some of the problems people have encountered previously with the Orange Pi Zeroā€™s wifi chipset (XR819). My understanding is that other models of the Orange Pi Zero (Plus, Plus Two) have chosen different WiFi chipsets to address this problem, but I donā€™t have this hardware and canā€™t verify their performance.

f you are not seeing degraded performance, there is not a lot we can do in this case, as we need to wait for updated kernel versions with improved drivers (assuming that the drivers are the source of the underlying problem, and not the hardware itself).

Thanks, and please let us know if thereā€™s anything else we can do to help.

All the best,
Hugh

25

Thanks for the info.

One other error on the same device I have noticed appearing in the journalctl logs, may be unrelated but wanted to add in just in case:

Oct 09 08:55:16 lb sshd[1893]: **error: Could not load host key: /etc/ssh/hostkeys/ssh_host_dsa_key**

I started a wifi-connect container as a python version of the Debian image. In the container I tried installing something with pip and get the following:

pip3 install requests

WARNING: Retrying (Retry(total=4, connect=None, read=None, redirect=None, status=None)) after connection broken by 'SSLError(SSLError(9, '[X509] PEM lib (_ssl.c:4263)'))': /simple/requests/

WARNING: Retrying (Retry(total=3, connect=None, read=None, redirect=None, status=None)) after connection broken by 'SSLError(SSLError(9, '[X509] PEM lib (_ssl.c:4263)'))': /simple/requests/

WARNING: Retrying (Retry(total=2, connect=None, read=None, redirect=None, status=None)) after connection broken by 'SSLError(SSLError(9, '[X509] PEM lib (_ssl.c:4263)'))': /simple/requests/

WARNING: Retrying (Retry(total=1, connect=None, read=None, redirect=None, status=None)) after connection broken by 'SSLError(SSLError(9, '[X509] PEM lib (_ssl.c:4263)'))': /simple/requests/

WARNING: Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'SSLError(SSLError(9, '[X509] PEM lib (_ssl.c:4263)'))': /simple/requests/

Could not fetch URL https://pypi.org/simple/requests/: There was a problem confirming the ssl certificate: HTTPSConnectionPool(host='pypi.org', port=443): Max retries exceeded with url: /simple/requests/ (Caused by SSLError(SSLError(9, '[X509] PEM lib (_ssl.c:4263)'))) - skipping

ERROR: Could not find a version that satisfies the requirement requests (from versions: none)

ERROR: No matching distribution found for requests

Looking at the directory it is point to on the OS it doesnā€™t appear to exist:

root@lb:/etc/ssh/hostkeys# ls -lah
total 9.0K
drwxr-xr-x 2 root root 1.0K Jan  1  1970 .
drwxr-xr-x 3 root root 1.0K Aug 10 13:47 ..
-rw------- 1 root root  505 Jan  1  1970 ssh_host_ecdsa_key
-rw-r--r-- 1 root root  176 Jan  1  1970 ssh_host_ecdsa_key.pub
-rw------- 1 root root  411 Jan  1  1970 ssh_host_ed25519_key
-rw-r--r-- 1 root root   96 Jan  1  1970 ssh_host_ed25519_key.pub
-rw------- 1 root root 1.8K Jan  1  1970 ssh_host_rsa_key
-rw-r--r-- 1 root root  396 Jan  1  1970 ssh_host_rsa_key.pub
26

Hello there,

In the output of ls -lah the date looks off. Itā€™s showing epoch date (Jan 1 1970) instead of the current date. Could you please check what date command outputs on device?

Seems like the deviceā€™s internal clock has drifted off. Then this caused the connection errors you show as the certificates stop working because of wrong date. Iā€™m not sure if the original issue with wifi-connect caused the date issue here or something else is off. Could you check if the device reaches to NTP servers fine?
Here are networking requirements: https://www.balena.io/docs/reference/OS/network/2.x/#network-requirements

Cheersā€¦

28

Good eye, I missed that.

Yes, the date is set correctly, and the device is plugged directly into my home internet router with an ethernet cable.

root@lb:~# date
Fri Oct  9 13:01:56 UTC 2020
root@lb:~# cd /etc/ssh/hostkeys
root@lb:/etc/ssh/hostkeys# ls -lah
total 9.0K
drwxr-xr-x 2 root root 1.0K Jan  1  1970 .
drwxr-xr-x 3 root root 1.0K Aug 10 13:47 ..
-rw------- 1 root root  505 Jan  1  1970 ssh_host_ecdsa_key
-rw-r--r-- 1 root root  176 Jan  1  1970 ssh_host_ecdsa_key.pub
-rw------- 1 root root  411 Jan  1  1970 ssh_host_ed25519_key
-rw-r--r-- 1 root root   96 Jan  1  1970 ssh_host_ed25519_key.pub
-rw------- 1 root root 1.8K Jan  1  1970 ssh_host_rsa_key
-rw-r--r-- 1 root root  396 Jan  1  1970 ssh_host_rsa_key.pub

root@lb:/etc/ssh/hostkeys# ping google.com
PING google.com (216.58.204.46): 56 data bytes

64 bytes from 216.58.204.46: seq=0 ttl=115 time=19.194 ms

root@lb:/etc/ssh/hostkeys# ping 0.resinio.pool.ntp.org

PING 0.resinio.pool.ntp.org (185.57.191.229): 56 data bytes

64 bytes from 185.57.191.229: seq=0 ttl=41 time=31.215 ms
37

Iā€™ve been talking to my teammate about this certificate error. Could not load host key: /etc/ssh/hostkeys/ssh_host_dsa_key is apparently harmless. At least it should not cause that certificate problem. The host keys are generated at first boot, the epoch timestamp could happen if the device defaults to epoch time and SSH started before time sync was complete.

Since the date command returns the correct date now, could you try running pip command once more now?
Letā€™s see if it fails again.

39

I have rebuilt since then, and no longer getting the issues. It is a minor concern if unrelated to the CTRL-EVENT-SCAN-FAILED issue so happy to leave it and see if it reoccurs.

Fingers crossed for some firmware changes to resolve the CTRL-EVENT-SCAN-FAILED issues, they are a log killer.

40

Thatā€™s great, thanks for the heads up.

42

Some additional yet likely related information here. This error occurs and then both wifi and ethernet is dropped. Only a restart of the device brings it back up again.

Oct 19 15:36:42 lb balenad[826]: time="2020-10-19T15:36:42.515471770Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Oct 19 15:37:33 lb NetworkManager[815]: <info>  [1603121853.8638] device (wlan0): Activation: starting connection 'lb' (fd5ca4e5-5d22-4d98-ab32-f6205f07f345)
Oct 19 15:37:33 lb NetworkManager[815]: <info>  [1603121853.8643] audit: op="connection-add-activate" uuid="fd5ca4e5-5d22-4d98-ab32-f6205f07f345" name="lb" pid=6084 uid=0 result="success"
Oct 19 15:37:33 lb NetworkManager[815]: <info>  [1603121853.8673] device (wlan0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Oct 19 15:37:33 lb NetworkManager[815]: <info>  [1603121853.8839] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Oct 19 15:37:33 lb NetworkManager[815]: <info>  [1603121853.8896] device (wlan0): Activation: (wifi) connection 'lb' requires no security.  No secrets needed.
Oct 19 15:37:33 lb NetworkManager[815]: <info>  [1603121853.8908] Config: added 'ssid' value 'lb'
Oct 19 15:37:33 lb NetworkManager[815]: <info>  [1603121853.8910] Config: added 'mode' value '2'
Oct 19 15:37:33 lb NetworkManager[815]: <info>  [1603121853.8912] Config: added 'frequency' value '2412'
Oct 19 15:37:33 lb NetworkManager[815]: <info>  [1603121853.8912] Config: added 'freq_list' value '2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472 2484'
Oct 19 15:37:33 lb NetworkManager[815]: <info>  [1603121853.8914] Config: added 'key_mgmt' value 'NONE'
Oct 19 15:37:33 lb wpa_supplicant[847]: Note: nl80211 driver interface is not designed to be used with ap_scan=2; this can result in connection failures
Oct 19 15:37:33 lb kernel: ieee80211 phy0: changing interface type; new type=3(2), p2p=0(0)
Oct 19 15:37:33 lb kernel: ieee80211 phy0: !!! vif_id=0
Oct 19 15:37:33 lb kernel: ieee80211 phy0: Interface ID:0 of type:3 added
Oct 19 15:37:35 lb kernel: xradio_wlan mmc1:0001:1: ***CMD timeout!>>> 0x0006 (16), buf_use=1, bh_state=0
Oct 19 15:37:35 lb kernel: ------------[ cut here ]------------
Oct 19 15:37:35 lb kernel: WARNING: CPU: 2 PID: 847 at /usr/src/debug/xradio/0.1-r0/git/sta.c:1913 xradio_vif_setup+0x4d8/0x4dc [xradio_wlan]
Oct 19 15:37:36 lb kernel: Modules linked in: ip6t_REJECT nf_reject_ipv6 ip6table_filter ipt_REJECT nf_reject_ipv4 xt_state xt_MASQUERADE nf_conntrack_netlink nfnetlink br_netfilter xt_owner xradio_wlan(O) mac80211 cfg80211 libarc4
Oct 19 15:37:36 lb kernel: CPU: 2 PID: 847 Comm: wpa_supplicant Tainted: G           O      5.4.18 #1
Oct 19 15:37:36 lb kernel: Hardware name: Allwinner sun8i Family
Oct 19 15:37:36 lb kernel: [<c010f098>] (unwind_backtrace) from [<c010b63c>] (show_stack+0x10/0x14)
Oct 19 15:37:36 lb kernel: [<c010b63c>] (show_stack) from [<c07b9c1c>] (dump_stack+0x94/0xa8)
Oct 19 15:37:36 lb kernel: [<c07b9c1c>] (dump_stack) from [<c01282cc>] (__warn+0xbc/0xd8)
Oct 19 15:37:36 lb kernel: [<c01282cc>] (__warn) from [<c012834c>] (warn_slowpath_fmt+0x64/0xc4)
Oct 19 15:37:36 lb kernel: [<c012834c>] (warn_slowpath_fmt) from [<bf0e64d8>] (xradio_vif_setup+0x4d8/0x4dc [xradio_wlan])
Oct 19 15:37:36 lb kernel: [<bf0e64d8>] (xradio_vif_setup [xradio_wlan]) from [<bf0e67a0>] (xradio_add_interface+0x250/0x2e4 [xradio_wlan])
Oct 19 15:37:36 lb kernel: [<bf0e67a0>] (xradio_add_interface [xradio_wlan]) from [<bf069b58>] (ieee80211_if_change_type+0x14c/0x2b8 [mac80211])
Oct 19 15:37:36 lb kernel: [<bf069b58>] (ieee80211_if_change_type [mac80211]) from [<bf06ee38>] (ieee80211_change_iface+0x20/0x84 [mac80211])
Oct 19 15:37:36 lb kernel: [<bf06ee38>] (ieee80211_change_iface [mac80211]) from [<bf00d254>] (cfg80211_change_iface+0xa0/0x2ec [cfg80211])
Oct 19 15:37:36 lb kernel: [<bf00d254>] (cfg80211_change_iface [cfg80211]) from [<bf0305c0>] (nl80211_set_interface+0x138/0x230 [cfg80211])
Oct 19 15:37:36 lb kernel: [<bf0305c0>] (nl80211_set_interface [cfg80211]) from [<c0662fd4>] (genl_rcv_msg+0x220/0x490)
45

Hi, just trying to understand, as this sounds to me like a new issue:

  • There was the issue of frequent ā€œwlan0: CTRL-EVENT-SCAN-FAILEDā€ log messages which unhelpfully fill up the logs, but which were believed to be harmless (the device was maintaining network connectivity despite the messages).
  • There was the log message ā€œerror: Could not load host key: /etc/ssh/hostkeys/ssh_host_dsa_keyā€ which was believed to be harmless (the ssh_host_dsa_key file is not required).
  • There was the pip install error ā€œCould not fetch URL https://pypi.org/simple/requests/: There was a problem confirming the ssl certificate: [ā€¦] (Caused by SSLError(SSLError(9, ā€˜[X509] PEM lib (_ssl.c:4263)ā€™))) - skippingā€ which was caused by the device date/time being incorrect, and was fixed by updating the date/time.

None of the above were causing the network connection to fail, right? The latest described issue, however, causes both wifi and ethernet to drop, requiring a device reboot. It this an accurate description?

1 Like