PICO W machine.reset() didn't work once

[JohnMTu]

I have weird situation, which normally works, but once it failed. And stacktrace and logs don't fit together... like if during sleep something happened...
(After manual trigger of machine.reboot() it reboots and how works normally - means it reboots automatically).

steps i found important from whole project with this issue:

1. connect wifi
2. try to dynamically load module, on exception log messsage, machine.reboot() and then write dots (reboot will kill them).

issue:
this time it didn't reboot, is just writing dots (which i write on 2 places in code) and after ctrl+c in stacktrace it looks like i'm still in wifi connect routine on time.sleep(1) call, but that one was finished already according to log entry which is in code 3 lines below that sleep....

it's all pretty confusing me...

code fragments:
wifi code:

def do_connect_wifi_as_client(ssid, psk):
    global sta_if, nodeName
    print('connecting to wifi AP', ssid)

    sta_if = network.WLAN(network.STA_IF)
    sta_if.active(True)
    time.sleep(1)
    
    if not sys.platform == 'rp2':
        sta_if.config(dhcp_hostname=nodeName) # na ESP32 hlasi OSError: TCP/IP IF Not Ready # na PICO: unknown config param
    if sys.platform == 'rp2':
        print('removing wifi power saving')
        sta_if.config(pm = 0xa11140)
    sta_if.connect(ssid, psk)

    attempt = 1
    last_wifi_status = 999
    while not sta_if.isconnected():
        attempt = attempt + 1
        print(".", end="")
        tmp = sta_if.status()
        if last_wifi_status != tmp:
            last_wifi_status = tmp
            print('wifi state:', last_wifi_status)
        time.sleep(1) ################################### this is line 83 ################

    print('')
    print('Network config:', sta_if.ifconfig())

    wifi_sta_reconnect_timer.init(period=10000, mode=Timer.PERIODIC, callback=lambda timer: check_and_reconnect_wifi_station(sta_if, ssid, psk))


def check_and_reconnect_wifi_station(sta_if2, ssid, psk):
    if sta_if == sta_if2 and sta_if.status() != 3:
        print('Reconnecting wifi, was in state', sta_if.status())
        sta_if.connect(ssid, psk)

        attempt = 1
        last_wifi_status = 999
        time.sleep(1)
        while not sta_if.isconnected() and attempt < 5:
            attempt = attempt + 1
            print(".", end="")
            tmp = sta_if.status()
            if last_wifi_status != tmp:
                last_wifi_status = tmp
                print('wifi state:', last_wifi_status)
            time.sleep(1)

        if sta_if.isconnected():
            print('wifi reconnected successfully')
        else:
            print('wifi reconnection failure')

piece of bootstrap code:

def reboot():
    machine.reset()
    while True:
        print('.', end='')


def runMain():
        try:
            dynamicallyLoadModule(bootDirectoryName, 'configMain')

            rtc.memory(b'')
        except Exception as e:
            logger.error('error boot from '+bootDirectoryName, e)
            if reminder:
                logger.info('setting remaining alternative configs to RTC mem: '+(reminder.decode("UTF-8")))
                rtc.memory(b'config:'+reminder)
            else:
                logger.info('no more alternative configs, clearing RTC mem')
                rtc.memory(b'')
            logger.info('rebooting due to previous error')
            reboot()

    print('---------------------------- FINISHED MAIN -------------------------------')


runMain()

log output:

---------------------------- RUNNING MAIN -------------------------------
RTC mem:  b'config:gpios'
Free memory before loading module  gpios . configMain : 156272
---------------------------- RUNNING module  gpios / configMain  ---------------                                                                                                                                                             ----------------
free memory: 153504 importing machine, time, esp, sys
free memory: 153280 importing config
Preparing config
current MAC:  28:cd:c1:05:99:13
Node name:  pico-testing
Running startup scripts
free memory: 150384
configuring wifi network
connecting to wifi AP jmi-svetla2
removing wifi power saving
.wifi state: 1
..
Network config: ('10.99.0.50', '255.255.255.0', '10.99.0.1', '8.8.8.8') <!-- log entry which is in code after place where stacktrace points to ...
free memory: 150304 importing script upload server
free memory: 144480
free memory: 144480
importing TCP Server
received cmd: off
error boot from gpios
> Traceback (most recent call last):
>   File "main.py", line 71, in runMain
>   File "main.py", line 13, in dynamicallyLoadModule
>   File "gpios/configMain.py", line 58, in <module>
>   File "gpios/tcpServer.py", line 29, in <module>
>   File "gpios/initPwm.py", line 193, in <module>
>   File "gpios/initPwm.py", line 165, in off
>   File "gpios/initPwm.py", line 47, in set_dalen_percent
> Exception: dutyPercent 96.5/96.5 is not allowed combination

no more alternative configs, clearing RTC mem
rebooting due to previous error                  <!-------- here was reboot expected, but it didn't...
................................................................................                                                                                                                                                             ..................................................................................................................................................................................................Traceback (mo                              st recent call last):
  File "main.py", line 89, in <module>
  File "main.py", line 71, in runMain
  File "main.py", line 13, in dynamicallyLoadModule
  File "gpios/configMain.py", line 47, in <module>
  File "gpios/config.py", line 34, in setupWifi
  File "gpios/config.py", line 83, in do_connect_wifi_as_client        <!-------- this sleep command, which is after marked log entry
KeyboardInterrupt:
MicroPython v1.19.1 on 2022-09-30; Raspberry Pi Pico W with RP2040
Type "help()" for more information.
>>>

[robert-hh]

There is no way that machine.reset() returns. Even if the internal call to reboot returns, it runs an endless loop with no output. In the other code you have two places which print dots. And the log shows that the device still responds to Keyboard interrupts. So it is in a kind of active waiting state. The fact the the keyboard interrupt stops at line 83 does not tell more than the code is still executing the while not sta_if.isconnected(): loop, and spends most of the time in sleep(1).
At which frequency are the dots printed? Slow or fast?
Do you use threading?

[JohnMTu]

i don't use threading, at least not directly.
I use

• wifi as client
• gpio as digital out and as pwm out.
• tcp server socket + select/poll.
• several Timers
• on few places also sleep
• reading files from flash.
• UDP as client (but it didn't get there in this case)
• interrupts on GPIO input for IR library (but it didn't get there in this case)

Wifi connect is not instant, so i added dots to see it's not frozen.
Code is migrated from ESP8266- there after call of machine.reset() are maybe 200 dots printed, before it gets really rebooted ...
Hence the dots.

Good question .. dots were slow. So it was code as seen in stacktrace .. but i don't understand how it get there 2nd time, as in console output we already saw log entry which is printed near the end of do_connect_wifi_as_client method.

And i tripple checked... that method is called only using callstack as seen in stacktrace.

Actually if it would be called another time, we would see in output another message produced by
print('connecting to wifi AP', ssid)
but it's there only once.

But we can see also message produced by
print('Network config:', sta_if.ifconfig())
... so there should be no way to get back to that sleep - where it was according to stacktrace...

Hence i'm confused.

And it all happend just once. Hundred+ times it rebooted as expected.

Background: On ESP8266 i used RTC to hold information, what to do "next".
E.g. first i have some decision logic checking GPIOs and based on that is loaded nothing or recovery or normal module. This is set to RTC memory and it's rebooted to free memory.
On boot if memory contains info, given module is loaded. And it may end up by other entry in RTC mem and another reboot...
Normal module is one, which does update of *.py files from raspberry pi server.
Gpio module is one, which contains real business logic for this module - after all previous ceremony.
After target module is loaded, RTC memory is cleared.
There is some more logic like fallbacks etc. Fragment of that is visible in last piece of code from initial post.

With RPI PICO i faked RTC memory with file ... it basically works, difference is, that on power outage it doens't start with "empty" memory, because file contains last info.

[JohnMTu]

btw, how is sleep implemented? I was somehow expecting my code will not trigger during sleep, but in fact callback behind timer is executed even if main thread is in sleep method (situation from other project).

Thinking if there might be something like kind of callback used internally by sleep method ... which got somehow triggered during reboot...

[robert-hh]

time.sleep() is just busy waiting with checking for events, that might have to be scheduled.

[jimmo]

There is no machine.sleep() but machine.idle() is what @robert-hh describes. For example, if your Python code is polling something:

while not something():
  machine.idle()

is the most power-efficient way to do this with the minimum latency.

time.sleep is implemented roughly equivalent to:

def sleep(ms):
  start = time.ticks_ms()
  while time.ticks_diff(time.ticks_ms(), start) < ms:
    run_scheduled_tasks()  # this runs soft interrupt handlers that may have been scheduled by hard interrupts (e.g. timers, pins)
    machine.idle()