Msom WiFi isOn/isOff Functionality

We are using the msom with 6.2.0, our firmware turns WiFi on to scan wifi and then turns it off, until its time to scan again. When we turn on, we wait for isOn to return true, but sometimes it returns instantly, resulting in a failed wifi scan. Is there an alternate way to check if WiFi is ready to scan?

It's unclear whether isOn/isOff is returning an incorrect value (less likely) or that automatic connection management is changing the state of the interface in the background while you are trying to use it (a possibility).

Are you able to get trace level logs? Those might be helpful.

SerialLogHandler logHandler(LOG_LEVEL_TRACE);

I trigger the scan via cloud function, here are the trace logs:

0000049782 [app] INFO: BPM presence check
0000049810 [hal] TRACE: Abort: 00000001
0000049843 [hal] TRACE: Abort: 00000001
0000049868 [app] INFO: 0 v=-1.000000 s=-1.000000
0000049912 [hal] TRACE: Abort: 00000001
0000049941 [hal] TRACE: Abort: 00000001
0000049964 [app] INFO: 1 v=-1.000000 s=-1.000000
0000050006 [hal] TRACE: Abort: 00000001
0000050007 [hal] TRACE: Abort: 00000001
0000050009 [app] INFO: 2 v=-1.000000 s=-1.000000
0000050021 [hal] TRACE: Abort: 00000001
0000050022 [hal] TRACE: Abort: 00000001
0000050024 [app] INFO: 3 v=-1.000000 s=-1.000000
0000050036 [hal] TRACE: Abort: 00000001
0000050037 [hal] TRACE: Abort: 00000001
0000050039 [app] INFO: 4 v=-1.000000 s=-1.000000
0000050052 [app] INFO: Battery is not present
0000050257 [comm.coap] TRACE: Received CoAP message
0000050292 [comm.coap] TRACE: CON POST /f/test?wifi size=17 token=03 id=44620
0000050340 [comm.coap] TRACE: Sending CoAP message
0000050371 [comm.coap] TRACE: ACK 0.00  size=4 token= id=44620
0000050423 [app] INFO: Cloud Test Commanded: wifi
0000050460 [app] INFO: Dequeing test 2
0000050483 [comm.coap] TRACE: Sending CoAP message
0000050521 [comm.coap] TRACE: CON 2.04  size=10 token=03 id=16
0000050485 [app] INFO: Cloud test 2
0000050595 [app] INFO: Running test 2
0000050625 [app] INFO: Test 2 - Wifi Scan requested...
0000050676 [comm.coap] TRACE: Received CoAP message
0000050707 [comm.coap] TRACE: ACK 0.00  size=4 token= id=16
0000050704 [app] INFO: WiFi Thread running
0000050770 [app] INFO: WiFi Radio on
0000050771 [app] INFO: <<<< WIFI scan running >>>>
0000050771 [system.nm] TRACE: Request to power on interface 5
0000050865 [ncp.rltk.client] TRACE: NCP power state changed: 4
0000050866 [net.rltkncp] TRACE: NCP event 3
0000050867 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_UP
0000050880 [hal] INFO: rltk_wlan_set_netif_info: 0, 94:94:4a:05:1d:40
0000050894 [app] INFO: WiFi tuned on in 99ms, which is unusually quick
0000051014 [hal] INFO: WiFi on
0000051015 [ncp.rltk.client] TRACE: NCP power state changed: 2
0000051016 [net.rltkncp] TRACE: NCP event 3
0000051017 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000051018 [system.nm] TRACE: Interface 5 power state changed: UP
0000051020 [ncp.rltk.client] INFO: rltkOff
0000051330 [hal] INFO: WiFi off
0000051331 [ncp.rltk.client] INFO: rltkOff done
0000051332 [ncp.rltk.client] TRACE: NCP power state changed: 1
0000051333 [net.rltkncp] TRACE: NCP event 3
0000051334 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000051336 [system.nm] TRACE: Interface 5 power state changed: DOWN
0000051349 [hal] INFO: rltk_wlan_set_netif_info: 0, 94:94:4a:05:1d:40
0000051362 [app] INFO: Scanning WiFi...
0000051394 [app] INFO: Took 0 ms to find 0 valid wifi access points out of -210 total
0000051445 [app] INFO: WAPs.size=0
0000051483 [hal] INFO: WiFi on
0000051484 [ncp.rltk.client] TRACE: NCP power state changed: 2
0000051485 [net.rltkncp] TRACE: NCP event 3
0000051486 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000051487 [system.nm] TRACE: Interface 5 power state changed: UP
0000051490 [ncp.rltk.client] TRACE: NCP state changed: 1
0000051491 [net.rltkncp] TRACE: NCP event 1
0000051564 [app] INFO: WiFi Radio off
0000051590 [app] INFO: <<<< WIFI scan completed >>>>
0000051569 [system.nm] TRACE: Request to power off interface 5
0000051665 [ncp.rltk.client] TRACE: NCP power state changed: 3
0000051666 [net.rltkncp] TRACE: NCP event 3
0000051667 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
0000051668 [ncp.rltk.client] INFO: rltkOff
0000051627 [app] ERROR: Error in createNetworkScanMessage, code -1
0000051715 [app] INFO: Publish event MedShift/test_wifi
0000051757 [app] INFO: Publish data Error in createNetworkScanMessage, code -1
0000051812 [comm.coap] TRACE: Sending CoAP message
0000051842 [comm.coap] TRACE: CON POST /E/MedShift/test_wifi size=69 token= id=17
0000051977 [hal] INFO: WiFi off
0000051979 [ncp.rltk.client] INFO: rltkOff done
0000051980 [ncp.rltk.client] TRACE: NCP power state changed: 1
0000051981 [net.rltkncp] TRACE: NCP event 3
0000051982 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000051986 [system.nm] TRACE: Interface 5 power state changed: DOWN
0000051987 [ncp.rltk.client] TRACE: NCP state changed: 0
0000051988 [net.rltkncp] TRACE: NCP event 1
0000052052 [hal] TRACE: Abort: 00000001
0000052116 [comm.coap] TRACE: Received CoAP message
0000052147 [comm.coap] TRACE: ACK 0.00  size=4 token= id=17
0000062000 [app.ab1805] INFO: setWDT -1
0000062029 [app.ab1805] TRACE: watchdog set fourSecs=31 bResult=1
0000062054 [hal] TRACE: Abort: 00000001
0000065066 [app] INFO: BPM start
0000065116 [app] INFO: BPM toggle charge using 10ms
0000065170 [app] INFO: BPM delay after charge
0000080183 [app] INFO: BPM presence check
0000080215 [hal] TRACE: Abort: 00000001
0000080240 [hal] TRACE: Abort: 00000001
0000080268 [app] INFO: 0 v=-1.000000 s=-1.000000
0000080308 [hal] TRACE: Abort: 00000001
0000080337 [hal] TRACE: Abort: 00000001
0000080358 [app] INFO: 1 v=-1.000000 s=-1.000000
0000080399 [hal] TRACE: Abort: 00000001
0000080417 [hal] TRACE: Abort: 00000001
0000080449 [app] INFO: 2 v=-1.000000 s=-1.000000
0000080494 [hal] TRACE: Abort: 00000001
0000080515 [hal] TRACE: Abort: 00000001
0000080540 [app] INFO: 3 v=-1.000000 s=-1.000000
0000080584 [hal] TRACE: Abort: 00000001
0000080613 [hal] TRACE: Abort: 00000001
0000080639 [app] INFO: 4 v=-1.000000 s=-1.000000
0000080677 [app] INFO: Battery is not present
0000081060 [hal] TRACE: Abort: 00000001
0000091062 [hal] TRACE: Abort: 00000001
0000095722 [app] INFO: BPM start
0000095773 [app] INFO: BPM toggle charge using 10ms
0000095824 [app] INFO: BPM delay after charge

From these logs, it looks like a power cycle is sometimes used by the OS in WiFi.on and WiFi.isOff/isOn will return True of the immediate status, not the status of the entire WiFi.On process.

It looks like it turns on successfully.

0000050894 [app] INFO: WiFi tuned on in 99ms, which is unusually quick
0000051014 [hal] INFO: WiFi on
0000051015 [ncp.rltk.client] TRACE: NCP power state changed: 2
0000051016 [net.rltkncp] TRACE: NCP event 3
0000051017 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000051018 [system.nm] TRACE: Interface 5 power state changed: UP

Then it immediately turns back off again:

0000051020 [ncp.rltk.client] INFO: rltkOff
0000051330 [hal] INFO: WiFi off
0000051331 [ncp.rltk.client] INFO: rltkOff done
0000051332 [ncp.rltk.client] TRACE: NCP power state changed: 1
0000051333 [net.rltkncp] TRACE: NCP event 3
0000051334 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN

At that point, since the interface is off, so scanning won't return any results.

The next step is to try to debug if there are any code paths that turn WiFi off and add debugging statements to see if any of those are encountered.

Here is a minimal firmware that turns wifi off, waits and then turns wifi on, showing that that wifi.On calls turns on, off and on again. For 6.2.0

Looks like WiFi is actually on in less than 500ms, so I could wait that long + some safety or I could try to detect it power cycling, assuming it will power cycle at most once. I can do additional profiling to find startup time, but what would be nice if there was just a waitFor condition to let me know when a scan could be performed.

#include "Particle.h"

SYSTEM_MODE(SEMI_AUTOMATIC);
SYSTEM_THREAD(ENABLED);

SerialLogHandler logHandler(LOG_LEVEL_TRACE);

void myDelay(uint32_t timeMS) {
    uint32_t start = millis();
    while(millis() - start < timeMS) {
        Particle.process();
    }
}

void setup() {
    Serial.begin();
    while(!Serial.isConnected()) {
        Particle.process();
    }
    myDelay(500);

    Log.info("------------------------------- Turning WiFi off -------------------------------");
    WiFi.off();
    myDelay(10000);

    Log.info("------------------------------- Turning WiFi on -------------------------------");
    WiFi.on();
}

void loop() {
}

Here are the logs:

0000002427 [hal] TRACE: Abort: 00000001
0000002505 [hal] INFO: WiFi off
0000002513 [system.nm] INFO: State changed: NONE -> DISABLED
0000002527 [system.nm] TRACE: Interface 5 power state: DOWN
0000002541 [system.nm] TRACE: Interface 4 power state: UP
0000002575 [comm] INFO: channel inited
0000003093 [app] INFO: ------------------------------- Turning WiFi off -------------------------------
0000003116 [system.nm] TRACE: Request to power off interface 5
0000011433 [hal] TRACE: Abort: 00000001
0000013116 [app] INFO: ------------------------------- Turning WiFi on -------------------------------
0000013139 [system.nm] TRACE: Request to power on interface 5
0000013171 [ncp.rltk.client] TRACE: NCP power state changed: 4
0000013173 [net.rltkncp] TRACE: NCP event 3
0000013173 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_UP
0000013184 [hal] INFO: rltk_wlan_set_netif_info: 0, 94:94:4a:05:1d:40
0000013197 [system.nm] INFO: State changed: DISABLED -> IFACE_DOWN
0000013315 [hal] INFO: WiFi on
0000013316 [ncp.rltk.client] TRACE: NCP power state changed: 2
0000013317 [net.rltkncp] TRACE: NCP event 3
0000013318 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000013319 [system.nm] TRACE: Interface 5 power state changed: UP
0000013322 [ncp.rltk.client] INFO: rltkOff
0000013630 [hal] INFO: WiFi off
0000013631 [ncp.rltk.client] INFO: rltkOff done
0000013632 [ncp.rltk.client] TRACE: NCP power state changed: 1
0000013633 [net.rltkncp] TRACE: NCP event 3
0000013634 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000013636 [system.nm] TRACE: Interface 5 power state changed: DOWN
0000013647 [hal] INFO: rltk_wlan_set_netif_info: 0, 94:94:4a:05:1d:40
0000013777 [hal] INFO: WiFi on
0000013778 [ncp.rltk.client] TRACE: NCP power state changed: 2
0000013779 [net.rltkncp] TRACE: NCP event 3
0000013780 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000013781 [system.nm] TRACE: Interface 5 power state changed: UP
0000013784 [ncp.rltk.client] TRACE: NCP state changed: 1
0000013785 [net.rltkncp] TRACE: NCP event 1

Can you put in some debugging after you call WiFi.off() to see the state of isOff() during the 10 second delay, which should probably be at least 15 seconds.

It looks to me like the off is not complete, so when you turn it on, the off occurs at the same time as trying to turn it on.

The wifi module starts off, so there is no change in status of WiFi.isOff.

The status changes from 1 to 0 to 1 to 0 after WiFi.on. 1 being off, 0 being on.

0000002431 [hal] TRACE: Abort: 00000001
0000002528 [hal] INFO: WiFi off
0000002536 [system.nm] INFO: State changed: NONE -> DISABLED
0000002550 [system.nm] TRACE: Interface 5 power state: DOWN
0000002563 [system.nm] TRACE: Interface 4 power state: DOWN
0000002597 [comm] INFO: channel inited
0000002615 [app] INFO: status=1
0000003115 [app] INFO: ------------------------------- Turning WiFi off -------------------------------
0000003138 [app] INFO: first status=1
0000003147 [app] INFO: status=1
0000003147 [system.nm] TRACE: Request to power off interface 5
0000011437 [hal] TRACE: Abort: 00000001
0000021439 [hal] TRACE: Abort: 00000001
0000028147 [app] INFO: ------------------------------- Turning WiFi on -------------------------------
0000028169 [app] INFO: status=1
0000028170 [system.nm] TRACE: Request to power on interface 5
0000028202 [ncp.rltk.client] TRACE: NCP power state changed: 4
0000028203 [net.rltkncp] TRACE: NCP event 3
0000028204 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_UP
0000028214 [hal] INFO: rltk_wlan_set_netif_info: 0, 94:94:4a:05:1d:40
0000028227 [system.nm] INFO: State changed: DISABLED -> IFACE_DOWN
0000028227 [app] INFO: status=0
0000028346 [hal] INFO: WiFi on
0000028346 [ncp.rltk.client] TRACE: NCP power state changed: 2
0000028348 [net.rltkncp] TRACE: NCP event 3
0000028348 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000028350 [system.nm] TRACE: Interface 5 power state changed: UP
0000028351 [ncp.rltk.client] INFO: rltkOff
0000028661 [hal] INFO: WiFi off
0000028662 [ncp.rltk.client] INFO: rltkOff done
0000028662 [ncp.rltk.client] TRACE: NCP power state changed: 1
0000028663 [net.rltkncp] TRACE: NCP event 3
0000028664 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000028666 [system.nm] TRACE: Interface 5 power state changed: DOWN
0000028670 [app] INFO: status=1
0000028677 [hal] INFO: rltk_wlan_set_netif_info: 0, 94:94:4a:05:1d:40
0000028809 [hal] INFO: WiFi on
0000028811 [ncp.rltk.client] TRACE: NCP power state changed: 2
0000028812 [net.rltkncp] TRACE: NCP event 3
0000028813 [net.rltkncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000028814 [system.nm] TRACE: Interface 5 power state changed: UP
0000028816 [ncp.rltk.client] TRACE: NCP state changed: 1
0000028817 [net.rltkncp] TRACE: NCP event 1
0000028818 [app] INFO: status=0
0000031441 [hal] TRACE: Abort: 00000001
0000041443 [hal] TRACE: Abort: 00000001