Crashes consistently in asyncio.sleep or trying to run some other task

[krishnak]

I have a very simple program to debug this problem

async dosomething:
    While True:
      #do something NTP time query
      await asyncio.sleep(60)


async def main():
    esp.osdebug(0)
    gc.enable()
     # startup wlan.STA wlan.AP, connect to router and internet, code not provided
    asyncio.create_task(dosomething())  # donot await as this is non ending task 
    While True:
          gc.collect()
          Logger.Log(tag,gc.mem_free(),Logger.DEBUG)

        #low priority loop
        Logger.Log(tag," Crashing in sleep ",Logger.DEBUG)

        await asyncio.sleep(5)
        Logger.Log(tag,"No Crashing after sleep",Logger.DEBUG)
        #do some dummy check

the code crashes after around 5th or 6th iteration of the while loop - this is consistent, the last statement that gets printed is the one before sleep , I turned esp debug message and I am seeing some interrupt is causing it, the board doesn't even have any pins soldered, its a weimos D1 mini clone ESP8266 board, just connected and powered via USB.

After crashing and automatic rebooting for 4 or 5 times - sometimes the problem goes away. Sometimes it gets stuck in that mode and keep resetting.

Can you please let me know what is causing this interrupt which appears to be uncaught some where

Fatal exception 0(IllegalInstructionCause):
epc1=0x40107fce, epc2=0x00000000, epc3=0x00000000, excvaddr=0x00000000, depc=0x0�000000
 ets Jan  8 2013,rst cause:2, boot mode:(3,4)

load 0x40100000, len 32756, room 16 

Main  <DEBUG>  Crashing in sleep 
Fatal exception 4(Level1InterruptCause):
epc1=0x400005cb, epc2=0x00000000, epc3=0x00000000, excvaddr=0x00000000, depc=0x0�000000
 ets Jan  8 2013,rst cause:2, boot mode:(3,6)

[jimmo]

That's surprising... Which firmware are you using? (Can you send us the exact filename you flashed, or the commit number and board if you compiled yourself).

[krishnak]

I am using my own compiled code - however I haven't made any changes to the C code. Just my python code gets added to the modules folder.

The version I am using is from glenn's esp-now
https://github.com/micropython/micropython/tree/1f4484e7b3f6c304fec1b372be806940b5bbed61

the tag on my firmware prints v1.13-2306-g1f4484e7b-dirty even though it is stating v1.13 he said that it is up to date with the master

#6515 (comment)

[krishnak]

Just an update on this, the problem is reproduce-able in the code which I have attached. I have also attached the crash logs.

If I comment out the network connection part, then no crash occurs - I have not extensively tested out this but if no crash occurs with in first 60 seconds it is good to go mostly.

crashlog_code.zip

[krishnak]

I have tested this on a separate Node MCU clone V3 esp8266 board - it crashes exactly at the same place. Assuming the program was started from command prompt of REPL by importing the module, after crash you get the micropython command prompt. There are system resets occuring even in this stage when the actual program has terminated. (It occurs once in the micropython prompt)

It is more likely a code issue rather than hardware issue

[krishnak]

I am using a weimos D1 mini clone with ESP 8266 which has 4M flash

[peterhinch]

This does not make sense to me:

async dosomething:
    While True:
      #do something NTP time query
      await asyncio.sleep(60)

Shouldn't this read:

async def dosomething():
    While True:
      #do something NTP time query
      await asyncio.sleep(60)

[krishnak]

please ignore typos actual code attached in the message above unzip crashlog_code.zip

[krishnak]

I think I have isolated the issue, When the code wakes up from asynco.sleep it tries to call a variable inside a singleton class to check whether AP is still in use, I think this is causing some issue I was previously calling NetworkWrapper Instance.wlan_ap.isconnected() from inside the async def main.

I have replaced it with a direct call to if network.WLAN(network.AP_IF).isconnected():

    wlan_ap = network.WLAN(network.AP_IF)
    wlan_sta = network.WLAN(network.STA_IF)
    wlan_sta.active(False)

    tag = const('NetWorkWrapper')

    Logger =  None
    __shared_instance = 'switchboard'

    @staticmethod
    def getInstance():
        if NetworkWrapperClass.__shared_instance == 'switchboard':
            NetworkWrapperClass()
        return NetworkWrapperClass.__shared_instance


    def __init__(self):
        if NetworkWrapperClass.__shared_instance != 'switchboard':
            raise Exception("This class is a singleton class !")
        else:
            NetworkWrapperClass.__shared_instance = self

        self.Logger = LoggerClass.getInstance()
        self.factorysettingsFile = const('settings.dat')
        self.networksettingsFile = const('profiles.dat')

[jimmo]

@krishnak

Sorry I'm really confused -- what version of MicroPython are you actually running? 1.13 two years old there have been numerous fixes to asyncio since.

Can you replicate this issue with an official build from the downloads page of v1.19.1 ?

[krishnak]

@jimmo
Yes I am able to reproduce this with esp8266-20220618-v1.19.1.bin .

MicroPython v1.19.1 on 2022-06-18; ESP module with ESP8266
Type "help()" for more information.
>>> 
>>> repl
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
NameError: name 'repl' isn't defined
>>> import asynciocrashtest
(2022, 9, 20, 8, 22, 37, 1, 263)
state: 5 -> 0 (0)
rm 0
del if0
mode : softAP(ae:0b:fb:db:9f:ed)
mode : sta(ac:0b:fb:db:9f:ed) + softAP(ae:0b:fb:db:9f:ed)
#12 ets_task(4020f560, 28, 3fff9430, 10)
add if0
False
('0.0.0.0', '0.0.0.0', '0.0.0.0', '8.8.8.8')
31808
 Crashing in sleep 
(2022, 9, 20, 8, 22, 40, 1, 263)
scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 2
cnt 

connected with Sundara, channel 5
dhcp client start...
ip:192.168.1.10,mask:255.255.255.0,gw:192.168.1.1
('176.9.44.212', 123)
 Time Synchronised 
(2022, 9, 20, 8, 22, 50, 1, 263)
 Crashing after sleep 
True
False
30864
 Crashing in sleep 
(2022, 9, 20, 8, 22, 50, 1, 263)
 Crashing after sleep 
True
False
30816
 Crashing in sleep 
(2022, 9, 20, 8, 22, 55, 1, 263)
 Crashing after sleep 
True
False
30768
 Crashing in sleep 
(2022, 9, 20, 8, 22, 59, 1, 263)
Fatal exception 4(Level1InterruptCause):
�pc1=0x400005cb, epc2=0x00000000, epc3=0x00000000, excvaddr=0x00000000, depc=0x00000000
 ets Jan  8 2013,rst cause:2, boot mode:(3,0)

load 0x40100000, len 30720, room 16 
tail 0
chksum 0xba
load 0x3ffe8000, len 996, room 8 

Regarding the version number of Glenn - I too am confused as he says its some thing to do with git, so let us keep it aside.

I have included a single file which you can try running in your system to check whether it crashes. It crashes for me using your prebuilt esp8266 V 1.19.1 bin

Please change the SSID and password to working credentials

[krishnak]

@jimmo

`import uasyncio as asyncio
import uselect as select
import gc

import usocket as socket
import struct
from micropython import const
import machine
import utime
import esp
import network
print(utime.localtime())

gc.enable()
tzoffset = 19800
esp.osdebug(0)

async def RequestTimefromNtp(host='0.de.pool.ntp.org'):
        syncinterval = const(12*60*60)
        referencetime = const(3155673600)  # Reference time
        while True:
            try:
                NTP_QUERY = bytearray(48)
                NTP_QUERY[0] = 0x1b

                for i in range(5):
                    addr = socket.getaddrinfo(host, 123)[0][-1]
                    s = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
                    poller = select.poll()
                    poller.register(s,select.POLLIN)
                    print(addr)
                    s.sendto(NTP_QUERY, addr)
                    
                    if poller.poll(1000):  
                        msg = s.recv(48)
                        s.close()
                        t = struct.unpack("!I", msg[40:44])[0]
                        t -= referencetime
                        t+=tzoffset
                        tm = utime.localtime(t) 
                        tm = tm[0:3] + (0,) + tm[3:6] + (0,)
                        machine.RTC().datetime(tm)
                        print(" Time Synchronised ")
                        print(utime.localtime())
                        break         

            except Exception as e:
                print("Error setting system time "+str(e))
                await asyncio.sleep(1)
                continue
            await asyncio.sleep(syncinterval)



async def main():
    #if these lines <--- are commented no crash occurs 
    network.WLAN(network.STA_IF).active(False)
    await asyncio.sleep(1)
    network.WLAN(network.STA_IF).active(True)
    network.WLAN(network.AP_IF).active(True)
    await asyncio.sleep(1)
    network.WLAN(network.STA_IF).connect("your ssid","password")
    print(network.WLAN(network.STA_IF).isconnected())
    print(network.WLAN(network.STA_IF).ifconfig())
    asyncio.create_task(RequestTimefromNtp()) #don't wait
    while True:
            #gc.collect()

            print(gc.mem_free())

            #low priority loop
            print(" Crashing in sleep ")
            print(utime.localtime())
            await asyncio.sleep(5)
            print(" Crashing after sleep ")
            print(network.WLAN(network.STA_IF).isconnected()) #<---- wlan_sta = network.WLAN(network.STA_IF)

            print(network.WLAN(network.AP_IF).isconnected())  #<----wlan_ap = network.WLAN(network.AP_IF)

asyncio.run(main())
`

[krishnak]

@jimmo
I have done another test with this code - just so that we are not barking at the wrong tree. I just replaced asyncio.sleep and removed calls to async method.

I just sleep for 5 seconds with time.sleep(5) even that is crashing after few loops

So there is some interrupt or exception occurring in the firmware irrespective of what ever code is being executed, it so happens that I got stuck up with asyncio sleep.

I suspect without any proof that it could be the WLAN code, as if STA is inactive NO SUCH issue occurs

[krishnak]

@jimmo

I have observed the following if both STA and AP are active BUT if STA not connected to any SSID - then its all well

The #15 ets_task(4020f560, 28, 3fff9430, 10) probably is crashing occasionally resulting in mayhem?

I did a grep on the code and found ets_task function only in esp8266/ets_alt_task.c - who calls it?

[robert-hh]

Did you check for power problems? The ESP8266 can draw quite a bit of current when transmitting. The genuine Wemos D1 is fine, but clones may have problems in attempts to save a few cents. And at the price of a genuine Wemos D1, you do not need a clone.

[krishnak]

I can only buy what is available locally :) this issue also appears on a board claiming to be New NodeMCU V3. I suspect that the STA task to connect to the router crashes for whatever reason, but should be handled gracefully. I am too tired to test whether a bare metal C code is able to hold the WiFi connection without issues.

No transmission occurs, everything is idle when crash happens.

[krishnak]

I can give you some update on this and one of you can provide a possible cause.

Deductions so far:
Cause for Crash is NOT asyncio
Cause for crash is STA_IF being active

Suggestions received so far: Faulty power supply.

Further deductions :
It is NOT a power supply issue.

I have 3 ESP8266 boards and they are all different clones Weimos clone. Node MCU v3 clone and ESP01S.

ESP01s has no 3.3V regulator - others have AMS1117 chip printed

All of them crash after 30 seconds or so,when STA connection is active .

I tried to power these 3 (bypassing the boards 3.3v regulator) with another board which is a ESP 32 nodemcu which also has an AMS1117

So it failed everytime with STA turned on and if there is a SLEEP condition

Next I made one of the ESP8266 as a WiFi AP.

Now I connected the other ESP8266 to this using STA - EUREKA - No more crashes.

So there is something in the WiFi connection between ESP8266 and my router which is a b/g/n router, which performs some action at 30 seconds after a new connection which results in the STA task getting killed beyond redemption.

When the same ESP8266 connects to another ESP8266 its only 802.11/g connection at 54Mbps.

To test whether signal strength is the issue, I took the ESP8266 far away so that Rssi between ESP8266 were -71dB where as the router signal was more powerful at -45dB

So it appears that there is something in the code of the radio module causing it to crash with my router after 30 seconds.

[dpgeorge]

Does it only crash when connected to your router if there is a time.sleep() call in the code? Does it only crash during the sleep? Does it depend on the length on the sleep?

[krishnak]

I have tested it with the following code

                            utime.ticks_ms(), t) < 2 * 20000:
                            self.Logger.Log(self.tag,'Checking stablity of connection with %s...' % ssid,self.Logger.DEBUG)
                            await asyncio.sleep(0.5)

varying the sleep time between 0.5,1 and 40 seconds

With 0.5 and 1 - it crashes around 50th and 25th iteration of the while(not exactly it varies)
If I set it to 40 seconds (it crashes at some point in time before it wakes up

[krishnak]

If it crosses the 30 second mark - which it occasionally does, there are no further crashes.

[krishnak]

Just to be clear: It crashes around the 30 second mark after connection to the router with or without sleep in the code.

On REPL I just do

import network
network,WLAN(network.STA_IF).active(True)  # i set this to false in boot.py or else it will keep oncrashing as it tries to autconnect
network.WLAN(network.STA_IF).connect("ssid","pass")
network.WLAN(network.STA_IF).isconnected()  #

[krishnak]

I have connected the ESP8266 device to my mobile phone acting as a Hotspot - no crashes

This crash is very specific to my router connection. When I reconnect to my router - it crashes on around 30th ping.

After crash if I try reconnecting to my mobile phone - there are no crashes.

[krishnak]

With esp.osdebug(0)

when the EPS8266 connects to my router it prints out

network.WLAN(network.STA_IF).connect("router","12345343")

scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 2
cnt

Where as when it connects to my phone it prints aid 1, other than that everything is the same/

When I aid is 2 - it fails after 32 second

I found this information about a DOS bug in ESP8266 that can crash

Could you please check your device with esp.OSdebug(0) and let me know what gets printed for aid - when you connect to your routers

[robert-hh]

I have three boards ESP8266 set-up which just connect to an AP using the most recent version of the firmware. These are a WEMOS D1 Mini, a ESP01, and a semi-broken Adafruit Feather board (the CP2102 overheats due to an internal latch-up fault). No crash.

MicroPython v1.19.1-451-gbdbc44474 on 2022-09-28; ESP module with ESP8266

[krishnak]

As I mentioned in my previous messages, it is crashing only when it is connecting to my router, it can connect to my mobile phone or other ESP devices which act as WiFi hotspot without any issues. Having learnt about a Ddos bug present in ESP8266 SDK(refer links posted earlier) in the WiFi completion scenario, I assume that the router is sending some out of sequence messages which is triggering the behaviour similar to the DDoS vulnerability discovered.

[robert-hh]

The AP I used the the one in my LAN, used for all WiFi device here. But it's not the AP of the router.

[dpgeorge]

Thanks for testing with the latest ESP8266 RTOS SDK.

Unfortunately we can't use that SDK for MicroPython because it would require an almost full rewrite of the ESP8266 port. The best we can do instead is to update to the latest NONOS SDK, which might solve the problem.

[dpgeorge]

See this (closed) PR for an attempt to update ESP8266 to SDK 3: #4318