Device OS just powered down my Electron due to network connection process failure

Firmware
1

I’m just sitting here at work and noticed the LCD on my test device reset.

Opened up the serial debug monitor and it would appear as though Particle Device OS just “powered down” the Electron as part of a cloud connection error handler algorithm.

Here are relevant lines of debug output:

-/0103262632 [comm.protocol] INFO: rcv'd message type=13
[Mon Jun 04 13:19:21.060 2018] |\0103263126 [app.hubProperties] INFO: used 61 bytes cell data
[Mon Jun 04 13:19:21.561 2018] -/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\0103318351 [app.hubProperties] INFO: used 61 bytes cell data
[Mon Jun 04 13:20:16.781 2018] -/|0103319133 [comm.protocol] INFO: rcv'd message type=13
[Mon Jun 04 13:20:17.534 2018] \0103319375 [app.hubProperties] INFO: used 61 bytes cell data
[Mon Jun 04 13:20:17.785 2018] -/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\0103374591 [app.hubProperties] INFO: used 61 bytes cell data
[Mon Jun 04 13:21:13.007 2018] -/|\-/|\-/|\-/|\-/|\0103379629 [app.hubProperties] INFO: used 61 bytes cell data
[Mon Jun 04 13:21:18.028 2018] -/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\0103391672 [app.hubProperties] INFO: used 61 bytes cell data
[Mon Jun 04 13:21:30.076 2018] -/|\-/|\-/0103394128 [system] INFO: DHCP fail, ARM_WLAN_WD 5
[Mon Jun 04 13:21:32.420 2018] 0103394129 [app.main] WARN: Network status change:
[Mon Jun 04 13:21:32.586 2018] |0103394358 [comm.protocol] ERROR: Event loop error 18
[Mon Jun 04 13:21:32.651 2018] 0103394358 [system] WARN: Communication loop error, closing cloud socket
[Mon Jun 04 13:21:32.837 2018] \-/|\-/0103396160 [system] WARN: Resetting WLAN due to WLAN_WD_TO()
[Mon Jun 04 13:21:34.453 2018] 0103396161 [app.main] WARN: Network status change:
[Mon Jun 04 13:21:34.594 2018] |\0103399241 [app.main] WARN: Latency: cell data update | 2584
[Mon Jun 04 13:21:37.632 2018] 0103399341 [system] INFO: Network Connect: !SPARK_WLAN_STARTED
[Mon Jun 04 13:21:37.632 2018] 0103399341 [system] INFO: ready(): 0; connecting(): 0; listening(): 0; WLAN_SMART_CONFIG_START: 0
[Mon Jun 04 13:21:37.673 2018] 0103399382 [app.pubRegistry] INFO: Filing PUBSTATUS_NACK entry
[Mon Jun 04 13:21:37.684 2018] 0103399393 [app.jazaPublish] INFO: Publishing hub/warn : "734,10, JazaHub_NA , app.main , Latency: cell data update | 2584 , 103399241 , 1528129291 , 1073 , 29 , develop"
[Mon Jun 04 13:21:37.688 2018] 0103399397 [app.main] WARN: Network status change:
[Mon Jun 04 13:21:37.689 2018] 0103399397 [app.main] WARN: Network status change:
[Mon Jun 04 13:21:37.689 2018] 0103399397 [app.main] WARN: powering_off
[Mon Jun 04 13:21:37.695 2018] 0103399403 [app.main] WARN: Network status change:
[Mon Jun 04 13:21:37.695 2018] 0103399403 [app.main] WARN: off
[Mon Jun 04 13:21:37.700 2018] 0103399408 [app.main] WARN: Network status change:
[Mon Jun 04 13:21:37.700 2018] 0103399408 [app.main] WARN: powering_on
[Mon Jun 04 13:21:40.783 2018] 0103402492 [system] INFO: Sim Ready
[Mon Jun 04 13:21:40.784 2018] 0103402492 [system] INFO: ARM_WLAN_WD 1
[Mon Jun 04 13:22:09.450 2018] 2000
[Mon Jun 04 13:22:10.450 2018] 1000
[Mon Jun 04 13:22:12.749 2018] 2000
[Mon Jun 04 13:22:13.748 2018] 1000
[Mon Jun 04 13:22:14.748 2018] GO!!!
[Mon Jun 04 13:22:14.748 2018] 0000003059 [app.reboot] TRACE: System.resetReason() == 40  |  System.resetReasonData() == 0
[Mon Jun 04 13:22:14.748 2018] last_watchdog_enabled_status == TRUE
[Mon Jun 04 13:22:14.749 2018] last_watchdog_pat_cold_millis == 340891915
[Mon Jun 04 13:22:14.749 2018] millis_at_runtime_start == 340889187
[Mon Jun 04 13:22:14.750 2018] 0000003060 [app.reboot] WARN: (line 433) - REBOOT:  POWERDOWN
[Mon Jun 04 13:22:14.750 2018] ========================================
[Mon Jun 04 13:22:14.750 2018] =============setup() start==============
[Mon Jun 04 13:22:14.750 2018] ========================================
[Mon Jun 04 13:22:14.756 2018] ========================================
[Mon Jun 04 13:22:14.757 2018] ==============RUNTIME INFO==============
[Mon Jun 04 13:22:14.757 2018] ========================================
[Mon Jun 04 13:22:14.757 2018] 0000003068 [app.main] INFO: Tatu, Juni 4, 2018 at  4:21 PM (UTC)
[Mon Jun 04 13:22:14.759 2018] 0000003068 [app.main] INFO: SysVersion: 0.6.1
[Mon Jun 04 13:22:14.759 2018] 0000003069 [app.main] INFO: ProdBranch: develop
[Mon Jun 04 13:22:14.761 2018] 0000003069 [app.main] INFO: cold boot = FALSE
[Mon Jun 04 13:22:14.761 2018] 0000003069 [app.main] INFO: RESET REASON: POWERDOWN:
[Mon Jun 04 13:22:14.761 2018] 0000003070 [app.main] INFO: lastRunTimeMillis = 0
[Mon Jun 04 13:22:14.761 2018] 0000003070 [app.main] INFO: coldMillis: 340892257
[Mon Jun 04 13:22:14.761 2018] 0000003070 [app.main] INFO: num_resets_today = 1
[Mon Jun 04 13:22:14.761 2018] 0000003070 [app.main] INFO: num_watchdog_resets_today = 0
[Mon Jun 04 13:22:14.761 2018] 0000003071 [app.main] INFO: Safe mode = FALSE
[Mon Jun 04 13:22:14.761 2018] 0000003071 [app.main] INFO: Safe mode type = 0
[Mon Jun 04 13:22:14.761 2018] 0000003071 [app.main] INFO: last_safe_mode_publish_cold_millis = 0

On the subsequent runtime Device OS blocked my code for over 30 seconds at which point the external hardware watchdog that I have installed on my product reset the system due to lack of servicing. Again the debug messaging from Particle Device OS looks the same:

[Mon Jun 04 13:24:26.800 2018] 0000135113 [system] INFO: Cloud: connecting
[Mon Jun 04 13:24:26.801 2018] 0000135114 [app.main] WARN: Cloud status change:
[Mon Jun 04 13:24:26.801 2018] 0000135114 [app.main] WARN: connecting
[Mon Jun 04 13:24:26.812 2018] -/0000135505 [system] INFO: Resolved host 260032000c51343334363138.udp.particle.io to 54.175.126.153
[Mon Jun 04 13:24:27.285 2018] 0000135597 [system] INFO: Cloud socket connected
[Mon Jun 04 13:24:27.285 2018] 0000135597 [system] INFO: Starting handshake: presense_announce=0
[Mon Jun 04 13:24:27.286 2018] 0000135597 [comm.protocol.handshake] INFO: Establish secure connection
[Mon Jun 04 13:24:27.314 2018] 0000135627 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=2
[Mon Jun 04 13:24:27.315 2018] |\-/|\-/|\-/|\-/|\-/|\-/|\-/|0000142899 [comm.protocol.handshake] INFO: Sending HELLO message
[Mon Jun 04 13:24:34.613 2018] \-0000143231 [comm.protocol.handshake] INFO: Handshake completed
[Mon Jun 04 13:24:34.920 2018] 0000143231 [system] INFO: Send spark/device/claim/code event
[Mon Jun 04 13:24:35.116 2018] /0000143449 [system] INFO: Send spark/hardware/max_binary event
[Mon Jun 04 13:24:35.352 2018] 0000143665 [system] INFO: Send spark/device/last_reset event
[Mon Jun 04 13:24:35.368 2018] |0000143879 [system] INFO: Send subscriptions
[Mon Jun 04 13:24:35.618 2018] \-/0000144517 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
[Mon Jun 04 13:24:36.205 2018] 0000144517 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
[Mon Jun 04 13:24:36.206 2018] 0000144519 [comm] INFO: Sending TIME request
[Mon Jun 04 13:24:36.371 2018] |0000144773 [comm.protocol] INFO: rcv'd message type=13
[Mon Jun 04 13:24:36.461 2018] 0000144773 [system] INFO: Cloud connected
[Mon Jun 04 13:24:36.462 2018] 0000144774 [app.main] WARN: Cloud status change:
[Mon Jun 04 13:24:36.462 2018] 0000144774 [app.main] WARN: connected
[Mon Jun 04 13:24:36.504 2018] 0000144817 [comm.protocol] INFO: rcv'd message type=13
[Mon Jun 04 13:24:36.622 2018] \0000144959 [comm.protocol] INFO: rcv'd message type=13
[Mon Jun 04 13:24:36.788 2018] 0000145101 [comm.protocol] INFO: rcv'd message type=13
[Mon Jun 04 13:24:36.873 2018] -0000145243 [comm.protocol] INFO: rcv'd message type=13
[Mon Jun 04 13:24:37.098 2018] 0000145411 [comm.protocol] INFO: Sending S describe message
[Mon Jun 04 13:24:37.124 2018] /|0000145721 [comm.protocol] INFO: rcv'd message type=1
[Mon Jun 04 13:24:37.552 2018] 0000145865 [comm.protocol] INFO: rcv'd message type=13
[Mon Jun 04 13:24:37.626 2018] \0000146007 [comm.protocol] INFO: Received TIME response: 1528129474
[Mon Jun 04 13:24:37.695 2018] 0000146008 [app.main] TRACE: System time changed: sync
[Mon Jun 04 13:24:37.696 2018] 0000146007 [comm.protocol] INFO: rcv'd message type=12
[Mon Jun 04 13:24:37.839 2018] 0000146151 [comm.protocol] INFO: Sending A describe message
[Mon Jun 04 13:24:37.877 2018] -/0000146465 [comm.protocol] INFO: rcv'd message type=1
[Mon Jun 04 13:24:38.380 2018] |\-/|\-/|\-/|\-0000150252 [comm.protocol] INFO: rcv'd message type=8
[Mon Jun 04 13:24:41.939 2018] 0000150252 [app.network] INFO: JazaHub_Name = "JazaHub_NA"
[Mon Jun 04 13:24:42.081 2018] 0000150394 [comm.protocol] INFO: rcv'd message type=13
[Mon Jun 04 13:24:42.188 2018] /|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|0000162023 [app.pubRegistry] INFO: Filing PUBSTATUS_NACK entry
[Mon Jun 04 13:24:53.721 2018] 0000162034 [app.jazaPublish] INFO: Publishing hub/event/reset-reason : "735,JazaHub_NA , POWERDOWN , 1528129489 ,  161878 , 13 , 1"
[Mon Jun 04 13:24:53.973 2018] 0000162285 [app.myParticle] INFO: Publish blocked for 222030 us
[Mon Jun 04 13:24:54.019 2018] 0000162332 [app.hubProperties] INFO: used 146 bytes cell data
[Mon Jun 04 13:24:54.021 2018] \-0000162657 [comm.protocol] INFO: rcv'd message type=13
[Mon Jun 04 13:24:54.524 2018] /|0000163337 [app.hubProperties] INFO: used 61 bytes cell data
[Mon Jun 04 13:24:55.025 2018] \-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|0000218398 [app.hubProperties] INFO: used 61 bytes cell data
[Mon Jun 04 13:25:50.263 2018] \0000218740 [comm.protocol] INFO: rcv'd message type=13
[Mon Jun 04 13:25:50.513 2018] -/|0000219389 [app.hubProperties] INFO: used 61 bytes cell data
[Mon Jun 04 13:25:51.265 2018] \-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/0000274455 [app.hubProperties] INFO: used 61 bytes cell data
[Mon Jun 04 13:26:46.280 2018] |\-/|\-/|\-/|\-/0000278515 [app.hubProperties] INFO: used 61 bytes cell data
[Mon Jun 04 13:26:50.295 2018] |\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/|\-/0000287468 [app.hubProperties] INFO: used 61 bytes cell data
[Mon Jun 04 13:26:59.331 2018] |\-/|\-/|\-/|0000290738 [system] INFO: DHCP fail, ARM_WLAN_WD 5
[Mon Jun 04 13:27:02.424 2018] 0000290739 [app.main] WARN: Network status change:
[Mon Jun 04 13:27:02.594 2018] \0000290968 [comm.protocol] ERROR: Event loop error 18
[Mon Jun 04 13:27:02.653 2018] 0000290968 [system] WARN: Communication loop error, closing cloud socket
[Mon Jun 04 13:27:02.845 2018] -/|\-/|0000292770 [system] WARN: Resetting WLAN due to WLAN_WD_TO()
[Mon Jun 04 13:27:04.456 2018] 0000292771 [app.main] WARN: Network status change:
[Mon Jun 04 13:27:04.603 2018] \-/0000298912 [app.main] WARN: Latency: cell data update | 5467
[Mon Jun 04 13:27:10.697 2018] 0000299012 [system] INFO: Network Connect: !SPARK_WLAN_STARTED
[Mon Jun 04 13:27:10.699 2018] 0000299012 [system] INFO: ready(): 0; connecting(): 0; listening(): 0; WLAN_SMART_CONFIG_START: 0
[Mon Jun 04 13:27:10.770 2018] 0000299085 [app.pubRegistry] INFO: Filing PUBSTATUS_NACK entry
[Mon Jun 04 13:27:10.781 2018] 0000299096 [app.jazaPublish] INFO: Publishing hub/warn : "736,10, JazaHub_NA , app.main , Latency: cell data update | 5467 , 298912 , 1528129621 , 1073 , 29 , develop"
[Mon Jun 04 13:27:10.785 2018] 0000299100 [app.main] WARN: Network status change:
[Mon Jun 04 13:27:10.787 2018] 0000299100 [app.main] WARN: Network status change:
[Mon Jun 04 13:27:10.787 2018] 0000299101 [app.main] WARN: powering_off
[Mon Jun 04 13:27:10.791 2018] 0000299106 [app.main] WARN: Network status change:
[Mon Jun 04 13:27:10.792 2018] 0000299106 [app.main] WARN: off
[Mon Jun 04 13:27:10.796 2018] 0000299111 [app.main] WARN: Network status change:
[Mon Jun 04 13:27:10.797 2018] 0000299112 [app.main] WARN: powering_on
[Mon Jun 04 13:27:13.848 2018] 0000302163 [system] INFO: Sim Ready
[Mon Jun 04 13:27:13.848 2018] 0000302163 [system] INFO: ARM_WLAN_WD 1
[Mon Jun 04 13:27:42.760 2018] 2000
[Mon Jun 04 13:27:43.760 2018] 1000
[Mon Jun 04 13:27:44.761 2018] GO!!!
[Mon Jun 04 13:27:44.761 2018] 0000003059 [app.reboot] TRACE: System.resetReason() == 20  |  System.resetReasonData() == 0
[Mon Jun 04 13:27:44.761 2018] last_watchdog_enabled_status == TRUE
[Mon Jun 04 13:27:44.763 2018] last_watchdog_pat_cold_millis == 341188276
[Mon Jun 04 13:27:44.763 2018] millis_at_runtime_start == 341182632
[Mon Jun 04 13:27:44.763 2018] 0000003060 [app.reboot] WARN: (line 433) - REBOOT:  HARDWARE WATCHDOG
[Mon Jun 04 13:27:44.763 2018] ========================================
[Mon Jun 04 13:27:44.763 2018] =============setup() start==============
[Mon Jun 04 13:27:44.763 2018] ========================================
[Mon Jun 04 13:27:44.768 2018] ========================================
[Mon Jun 04 13:27:44.770 2018] ==============RUNTIME INFO==============
[Mon Jun 04 13:27:44.770 2018] ========================================
[Mon Jun 04 13:27:44.770 2018] 0000003068 [app.main] INFO: Tatu, Juni 4, 2018 at  4:27 PM (UTC)
[Mon Jun 04 13:27:44.771 2018] 0000003068 [app.main] INFO: SysVersion: 0.6.1
[Mon Jun 04 13:27:44.771 2018] 0000003069 [app.main] INFO: ProdBranch: develop
[Mon Jun 04 13:27:44.771 2018] 0000003069 [app.main] INFO: cold boot = FALSE
[Mon Jun 04 13:27:44.771 2018] 0000003069 [app.main] INFO: RESET REASON: HARDWARE WATCHDOG:
[Mon Jun 04 13:27:44.771 2018] 0000003070 [app.main] INFO: lastRunTimeMillis = 0
[Mon Jun 04 13:27:44.773 2018] 0000003070 [app.main] INFO: coldMillis: 341185702
[Mon Jun 04 13:27:44.773 2018] 0000003070 [app.main] INFO: num_resets_today = 2
[Mon Jun 04 13:27:44.773 2018] 0000003071 [app.main] INFO: num_watchdog_resets_today = 1
[Mon Jun 04 13:27:44.773 2018] 0000003071 [app.main] INFO: Safe mode = FALSE
[Mon Jun 04 13:27:44.773 2018] 0000003071 [app.main] INFO: Safe mode type = 0
[Mon Jun 04 13:27:44.774 2018] 0000003072 [app.main] INFO: last_safe_mode_publish_cold_millis = 0

A few things:

  • Does Device OS autonomously reset the Electron as part of an attempt to recover from network connection errors?
  • If a runtime starts with a reset code of type RESET_REASON_POWER_DOWN, yet the SRAM was not re-initialized, does that indicate a bug in Particle Device OS or does it perhaps imply that the modem powering back on cause an anomaly of some sort?
2

The entire Electron should not reset when the connection fails. When the WARN: Resetting WLAN due to WLAN_WD_TO occurs the modem is powered down, but the rest of the device should continue to run.

That is interesting that you’re getting a RESET_REASON_POWER_DOWN. At least on the Photon retained memory is retained way past where the processor stops running. It lasts for about 30 seconds. So there certainly could be a case where the STM32 powers down but retained memory is still alive, I think.

But then again, maybe not on the Electron, since VBAT is tied to 3V3, it’s equally possible retained memory should be cleared immediately, like if you ground VBAT on a Photon, which would mean I have no idea why you’d see power down with retained memory preserved.

3

@rickkas7, isn't exactly that the reason why retained memory will not be cleared on the Electron, unless you disconnect/drain the LiPo (or remove the 0Ohm bridge 3v3-VBAT) and wait for the caps to discharge?

Or do I just misread the interjection "maybe not on the Electron, since VBAT is tied to 3V3" and you actually mean ".... all that .... - but not on the Electron"

4

Hello there. Did you get any more insights regarding this behaviour?

I am experiencing something similar (frequent POWER_DOWN resets) with an electron which happens to have frequent disconnects.
Thanks in advance