adafruit / circuitpython

CircuitPython - a Python implementation for teaching coding with microcontrollers
https://circuitpython.org
Other
4.09k stars 1.21k forks source link

ESP32-S2 coming out of deep sleep with POWERON status #4025

Closed jfabernathy closed 3 years ago

jfabernathy commented 3 years ago

Now that I'm using a Debug Build of CP 6.1.0 RC I'm collecting a lot of data. My program is collecting temp and humidity data on a once per minute basis, and deep sleeps the reset of the time. I found that I get as many as 36 exits from deep sleep with the DSLEEP status, but too many are POWERON status. I first noticed this when my alarm.memory counter was getting reset to zero.

I have 2 logs: one is the Debug UART and the other is the normal UART on pins 5/6. My program log shows the code handles the exceptions like no WIFI connection correctly without resetting the MCU.

Since a program coming out of deep sleep has to work as if it was coming out of Reset, the code works, but the NVM counter is reset. I'm still chasing a problem where the MCU just stops sending data after 10-24 hours. But this error is found usually in less than 5 minutes. Metro-uart.log screenlog.log I've posted the code and logs also in the forum. Not sure where stuff goes.

code.txt

jfabernathy commented 3 years ago

BTW, I've tested this on 2 different ESP32-S2

dhalbert commented 3 years ago

You don't need to post in the forum too, if you're posting here. This looks more like an issue than a support question.

jfabernathy commented 3 years ago

Thanks for the explanation. I posted first in the forum, then the more I thought about it,, the more I thought it was an issue that was out of my program's control. That's when I posted here.

jfabernathy commented 3 years ago

I did confirm that this happens with the official 6.1.0-rc.1 .uf2 and not just my debug build. The default .uf2 includes the boot state of PowerOn or DSLEEP in the Debug UART output which I capture to a file. From a practical matter my program has run for about 24 hrs posting data to NodeRed without any noticeable lost of reading. It's hard to see if only 1 minute reading is missing in a 24 hr period. For now it's a good thing I really don't need the alarm.memory loop counter since is rarely goes 10-15 passes without resetting.

tannewt commented 3 years ago

@jfabernathy How are you powering the board? That is weird you are seeing a mix of poweron and dsleep reasons.

jfabernathy commented 3 years ago

The board where I'm capturing the UART logs is powered by a Lipoly 2200mah battery. I recharge with a 12v barrel connector power supply. I wanted to eliminate the USB C being connected. You of course see none of this if you are connected to a Laptop because it only simulates deep sleep. Every time it starts up with DSLEEP indicated the counter is not reset. When it shows PowerON, the counter is reset. This is not unique to a particular board, I have the issue on both my ESP32 s2 Metros.

jfabernathy commented 3 years ago

I don't know if all this is connected to the real problem I was chasing, but I found this issue with resetting my Alarm.memory counter when I was setting up diagnostic counters looking for why the system board would just stop running. No flashing LED or any indication of life except for the power LED. But I found this problem first.

tannewt commented 3 years ago

Do you still have the issue when the 12v connector is connected? This sounds like it might be an issue with the reset reason.

jfabernathy commented 3 years ago

I usually plug in the 12V connector while the board is in deep sleep. It has no effect on what I see. I've also used a USB power adapter and that also works correctly. I've tried to trap all the exceptions. Early on I'd find the board flashing a bunch of LEDs and not running. I had to assume it had broken to REPL. Once I finally found a good way to trap everything it would run for as much as 3 days before it would stop. No LEDs except power. I was hoping to trap that error with all the UART logging. The exiting Deep Sleep with PowerON status happens regardless of being on battery, 5v, or 12v. I now have a battery monitor on the I2C bus and I also record the voltage and % charged. So I can correlate that. Let me know if you want more logs or the latest code.py.

jfabernathy commented 3 years ago

In an effort to product a test version of this program that still shows the bug but can be run without my server, I created a new code.py that is a combination of a simple http aio example and my code. I included the alarm.memory counter that gets reset randomly and my UART program output and Debug UART output. On a Raspberry PI 4 I used 2 sessions of screen with the logging turned on. code (copy).txt

dhalbert commented 3 years ago

The reset of the alarm.sleep_memory contents would indicate either a power glitch or maybe a hard reset, as discussed. This sounds like some kind of software bug. But does it make any difference if you power the board for long periods with an AC adapter instead of the battery?

jfabernathy commented 3 years ago

Before I recently received my Adafruit lipoly batteries, I used the USB-C power adapter I have from my Samsung S8 which is a Fast Charge higher current adapter. I re-hooked that this morning to eliminate the batteries as a cause. My memory is that I've seen this issue with the USB-C powered but not connected for serial comm. But I'm old and I don't trust my memory from a week ago. So I'm retesting now. I'll update when I have data. It should not take more than 45 minutes. I've never seen the counter go about 45.

jfabernathy commented 3 years ago

That didn't take long. With the USB-C connected to a AC power adapter. It failed after 7 loops. Here's the sequence most recently logged.

USB C powered plugged in while sleeping after loop counter incremented to 5 After incremented to 6, the next loop had PowerON status and counter was back to 1. Made it to 3 before resetting on next loop. only made it to 2 then reset, only made it to 3 then reset, made it to 7 before reset.

jfabernathy commented 3 years ago

new data, I wanted to see if this was WiFi related. I commented out anything to do with setting up a WiFi connection or using AIO. It still resets to loop counter occasionally, I'm going to make a simple program that just does alarm counter increments and see if it still fails and if not look to see if this is the amount of time that the system is in deep sleep

jfabernathy commented 3 years ago

Here's the latest. Not WiFi related! I ran the code.py below with a deep sleep timer of 10 seconds and I let it get into the 90s before I reset. I had no Poweron status except the one immediately after reset. When I changed to deep sleep timer to 60 seconds I started to see a large number of Poweron status exiting DeepSleep. I'm going to start playing with the alarm timer interval to see where it's stable and where it starts to reset the MCU,

import busio
import board
import alarm
import time

def alarm_deepSleep(how_long):
    time_alarm = alarm.time.TimeAlarm(monotonic_time=time.monotonic() + how_long)
    alarm.exit_and_deep_sleep_until_alarms(time_alarm)

def debug_log(msg):
    uart.write(bytearray("\n\r" + msg))
    print(msg)

uart = busio.UART(board.TX, board.RX, baudrate=115200)

loop_count = alarm.sleep_memory[5] | alarm.sleep_memory[6] << 8
loop_count += 1
alarm.sleep_memory[6] = loop_count >> 8
alarm.sleep_memory[5] = loop_count & 255

debug_log("Loop count = " + str(loop_count))

debug_log("Just posted data, now into deep sleep!\n\n")
# Create an alarm that will trigger 60 seconds from now to awake from deep sleep
alarm_deepSleep(10)

[code.txt](https://github.com/adafruit/circuitpython/files/5852490/code.txt)
tannewt commented 3 years ago

Thanks for all of the investigation @jfabernathy! Sounds like you are closing in on the issue.

jfabernathy commented 3 years ago

is there a spec on how long you should be able to deep sleep?

dhalbert commented 3 years ago

My original sample program when I wrote https://learn.adafruit.com/deep-sleep-with-circuitpython/sleep-memory did not have this problem, and I was not sleeping that long. I let it run for dozens of cycles. See the example there. So something may have changed. 10-20 seconds should be fine, and not too low.

jfabernathy commented 3 years ago

I'm doing a 30 second deep sleep test now. once it gets to >255, I'll be happy. I want a one minute sample rate on my temperature readings. So since 60 seconds will not work reliably, I may have to sleep 30 seconds and only post data every other time thru the loop. I'm surprised that 60 seconds is a problem. That sounds like a issue, especially since the battery voltage is good. Must be an internal MCU issue or drain on a power rail.

dhalbert commented 3 years ago

We deep-sleep for anywhere from 10 seconds to 24 hours, and it could be longer. All should work. It's a bug if you can't.

jfabernathy commented 3 years ago

My 30 second deep sleep did not work. I saw 10-15 Poweron statuses in the last hour. I'm going back to 10 seconds and let it run overnight and keep it on USB C power

jfabernathy commented 3 years ago

I'm reading the Espressif docs and see that the UART can be set to wake of the ESP32s2. Could CP has something set or unset that could be allowing UART noise, etc. to be interfering here? Or maybe touch?? https://docs.espressif.com/projects/esp-idf/en/latest/esp32s2/api-reference/system/sleep_modes.html

dhalbert commented 3 years ago

We are only enabling the wakeups corresponding to the alarms being set. The API is straightforward.

I will try to duplicate this within a few days. We are somewhat swamped at the moment, sorry.

jfabernathy commented 3 years ago

I have eliminated the UART as the problem. I went back to my original logging program and removed all UART usage. Only a few prints remain but since the USB-C is not connected they go nowhere. All UART cables are removed. I am logging the loop counter as one of my NodeRed data items and that is getting reset on both Metros. In the last 6 hours, most the counters got to 6-10 before resetting. All of my temperature, humidity, and battery parameters all looked good.

So I have a couple of Feather ESP32 Huzzahs coming in today or tomorrow and will switch over to those for my logging project using Arduino IDE. I'll have to ability to do more testing, but only if you request it. I've run out of ideas of what to try.

jfabernathy commented 3 years ago

FYI, I updated the UF2 to 6.2.0 beta 0 and the libs to the latest, and the results are the same. The good news is the system continues to collect and post data regardless of PowerOn or DSLEEP exit. This is not an issue for me but the NVM in alarm.memory would be useless.

tannewt commented 3 years ago

@igrr Have you seen any issues with 4.2 coming out of sleep as PowerOn when actually woken from deep sleep?

igrr commented 3 years ago

There has been one report of this: https://github.com/espressif/esp-idf/issues/6179. We haven't been able to reproduce this reliably. If you have a device where this happens, please try disabling the brownout detector in menuconfig and see if there is any difference in the behavior.

tannewt commented 3 years ago

@jfabernathy do you want to try checking the brownout settings? I'm not sure if it's on or not.

jfabernathy commented 3 years ago

@tannewt Not sure where in CircuitPython you would set brownout settings?

tannewt commented 3 years ago

You can get to menuconfig by doing make BOARD=<board name> menuconfig. It should be in the menu there somewhere. (Make sure you build the board once before running menuconfig and then clean after you do. It's a bit finicky.)

jfabernathy commented 3 years ago

oh no!, this sounds like I need to setup to build CP again, which is what hosed my Linux system last time. I might not be able to help you then on this part. BTW, I got my ESP32 Feather in Monday and quickly installed my Arduino version of my app and it's working flawlessly. I put in the loopcount test for NVM and it worked perfectly for 12 hours before I stopped. i'll probably use the Meto ESP32S2 for CP playing where deep sleep is not needed until this and other issues with WiFi get fixed, Not critical for me at this time.

jfabernathy commented 3 years ago

@tannewt I got lucky. The system where I originally built the debug build of CP was undisturbed so I just did a git pull on the CP git directory and it update to 6.2.0-beta 1. So which program do you want me to test, the minimal one that only increments NVM and deep sleeps?

jfabernathy commented 3 years ago

brownout was enabled at the first voltage setting, I think 2.44

dhalbert commented 3 years ago

Try with CONFIG_ESP32S2_BROWNOUT_DET disabled (you are probably already going to do that). The 2.44V is interesting: if it's that problem, it's not that we're triggering too easily.

jfabernathy commented 3 years ago

@dhalbert is CONFIG_EPS32S2_BROWNOUT_DET disable in the build with menuconfig?

jfabernathy commented 3 years ago

Here's what I changed in menuconfig: → Component config → ESP32S2-specific I disabled Hardware brownout detect & reset. It was enabled previously and set to 2.44 in the submenu Then after disabling I built the .uf2 to test

dhalbert commented 3 years ago

To test this, you can just set

CONFIG_ESP32S2_BROWNOUT_DET=n

in ports/esp32s2/esp-idf-config/sdkconfig.defaults. I checked this by putting an #error in esp-idf/components/esp32s2/cpu_start.c:

#if CONFIG_ESP32S2_BROWNOUT_DET
#error BROWNOUT_DET on    <--------- addded
    esp_brownout_init();
#endif

I didn't bother to use the menuconfig "GUI".

jfabernathy commented 3 years ago

I'm hoping what I did still achieves the goal. I now have that firmware.uf2 installed in my ESP32S2 Metro

I'm running my simplified deep sleep and increment counter test, powered by a USB power brick and posting the loop count to UART on pins 5/6. I'll try the test with a 10 second deep sleep first and see how high I get, then use a 60 second. code:

import busio
import board
import alarm
import time

def alarm_deepSleep(how_long):
    time_alarm = alarm.time.TimeAlarm(monotonic_time=time.monotonic() + how_long)
    alarm.exit_and_deep_sleep_until_alarms(time_alarm)

def debug_log(msg):
    uart.write(bytearray("\n\r" + msg))
    print(msg)

uart = busio.UART(board.TX, board.RX, baudrate=115200)

loop_count = alarm.sleep_memory[5] | alarm.sleep_memory[6] << 8
loop_count += 1
alarm.sleep_memory[6] = loop_count >> 8
alarm.sleep_memory[5] = loop_count & 255

debug_log("Loop count = " + str(loop_count))

debug_log("Just posted data, now into deep sleep!\n\n")
# Create an alarm that will trigger 10 seconds from now to awake from deep sleep
alarm_deepSleep(10)
jfabernathy commented 3 years ago

The brownout enabled may have been causing the issue. I ran the 10 minute loop of the program above until it reached 125. I then changed it to 60 minutes and hooked the board up to power from the barrel connector and I have my Raspberry Pi 4 logging the Debug UART port and also the UART on pins 5/6.

I just checked and we are up to 25 minute/loops without a PowerON exit from deep sleep. All exits from deep sleep have been with been with DSLEEP status.

I'll keep this running until it fails or it goes for several days.

Jim A

tannewt commented 3 years ago

@jfabernathy Thanks! @igrr it does seem related to the brown out detector.

jfabernathy commented 3 years ago

@tannewt One more post before happy hour. (us retirees can start happy hour anytime we want) My increment and deep sleep test has worked without PowerON problems for over 261 minutes. That's higher by a lot from what I remember.
I also put the new firmware.uf2 onto my other Metro that is setup for remote temperature humidity logging. That system post everything via mosquitto/ nodered to an influxDB database. I include the alarm.memory loop counter in that posting. It up to 130 right now. So the brownout reset is a major suspect to my problem.

jfabernathy commented 3 years ago

FYI, over 24 hours continuous without any resets. Both boards under test running fine. I'll report in on Monday

jfabernathy commented 3 years ago

Well it's been 3.6 days without issues and I need to re-purpose this board. Do you think this Brownout Reset disable will go into the normal release for both Metro ESP32S2 and Magtag?

dhalbert commented 3 years ago

@igrr Seems like we should disable brownout. Do you think we only need to do so before deep-sleeping, or should we disable it all the time? Thanks.

igrr commented 3 years ago

My colleague has pointed to this forum post that suggests clearing the "Brownout reset enable" bit before entering deep sleep: https://www.esp32.com/viewtopic.php?f=13&t=19208#p71084.

I'm going to submit this change for IDF master and release/v4.2 branches, so that esp_deep_sleep_start disables BOD reset automatically. In the meantime, please try to add this workaround in your app before calling esp_deep_sleep_start.

jfabernathy commented 3 years ago

FYI, I've been running a Metro ESP32-S2 for 5 days with the BOD disabled. I have a WDT setup to catch any issues that hang the application or system software. It's been working flawlessly. Zero issues.