[Ovmsdev] OVMS going comatose
Mark Webb-Johnson
mark at webb-johnson.net
Tue Mar 30 13:49:47 HKT 2021
If it helps, here is a recent one from my test module:
I (44109193) ovms-server-v2: Send MP-0 S0,K,0,0.00,stopped,standard,0,0,0,0,0,0,0,21,0,0,0,0,0.00,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,0.00,0,0.00,0.00
I (44109193) ovms-server-v2: Send MP-0 D0,0,5,0,0,0,0,0,0,310502,0,0,0,0,0,0,12.6,0,0,0,0
W (44202193) ovms-server-v2: Detected stale connection (issue #241), restarting network
I (44202193) esp32wifi: Restart
I (44202193) esp32wifi: Powering up WIFI driver
I (44202213) wifi:wifi driver task: 3ffde34c, prio:23, stack:3584, core=0
I (44202213) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (44202213) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (44202233) wifi:wifi firmware version: 30f9e79
I (44202233) wifi:config NVS flash:I (44202243) gsm-ppp: GsmPPPOS_StatusCallback: User Interrupt
I (44202243) gsm-ppp: GsmPPPOS_StatusCallback: PPPERR_USER PPP connection has been closed
…
I (44202243) cellular-modem-auto: Restart
I (44202243) cellular: State: Enter PowerOffOn state
I (44202243) gsm-ppp: Shutting down (hard)...
I (44202243) gsm-ppp: StatusCallBack: User Interrupt
V (44202253) ovms-server-v2: OvmsServerV2MongooseCallback(MG_EV_CLOSE)
I (44202253) ovms-server-v2: Status: Disconnected
I (44202263) gsm-ppp: PPP is shutdown
I (44202263) gsm-mux: Stop MUX
I (44202263) cellular-modem-auto: Power Cycle
…
I (44204263) netmanager: DoSafePrioritiseAndIndicate: start
I (44204263) netmanager: DoSafePrioritiseAndIndicate: none
I (44204273) netmanager: DoSafePrioritiseAndIndicate: start
I (44204273) netmanager: DoSafePrioritiseAndIndicate: none
…
I (44267803) gsm-ppp: GsmPPPOS_StatusCallback: None
I (44267813) netmanager: DoSafePrioritiseAndIndicate: start
I (44267813) netmanager: DoSafePrioritiseAndIndicate: connected modem
I (44267813) netmanager: DoSafePrioritiseAndIndicate: interface 0x3ffdf3b0
I (44267823) netmanager: DoSafePrioritiseAndIndicate: name pp2
I (44267833) netmanager: DoSafePrioritiseAndIndicate: end
I (44267803) gsm-ppp: StatusCallBack: None
I (44267813) gsm-ppp: status_cb: Connected
…
I (44269193) ovms-server-v2: Connection is api.openvehicles.com:6870 (redacted)
I (44269193) ovms-server-v2: Status: Connecting...
I (44269573) events: Signal(server.v2.connecting)
V (44287823) ovms-server-v2: OvmsServerV2MongooseCallback(MG_EV_CONNECT=113)
W (44287823) ovms-server-v2: Connection failed
E (44287823) ovms-server-v2: Status: Error: Connection failed
…
(Repeat many times)
…
I (47714543) events: Signal(server.v2.waitreconnect)
V (47714553) ovms-server-v2: OvmsServerV2MongooseCallback(MG_EV_CLOSE)
I (47714563) ovms-server-v2: Status: Disconnected
I (47714563) events: Signal(server.v2.waitreconnect)
I (47774193) ovms-server-v2: Connection is api.openvehicles.com:6870 (redacted)
I (47774193) ovms-server-v2: Status: Connecting...
I (47774263) events: Signal(server.v2.connecting)
W (47814193) ovms-duktape: DuktapeDispatch: msg type 3 lost, queue full
W (47815193) ovms-duktape: DuktapeDispatch: msg type 3 lost, queue full
W (47816193) ovms-duktape: DuktapeDispatch: msg type 3 lost, queue full
W (47817193) ovms-duktape: DuktapeDispatch: msg type 3 lost, queue full
…
W (47835193) ovms-duktape: DuktapeDispatch: msg type 3 lost, queue full
W (47836193) ovms-duktape: DuktapeDispatch: msg type 3 lost, queue full
E (47837193) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (47837193) task_wdt: - IDLE1 (CPU 1)
E (47837193) task_wdt: Tasks currently running:
E (47837193) task_wdt: CPU 0: IDLE0
E (47837193) task_wdt: CPU 1: OVMS Console
E (47837193) task_wdt: Aborting.
abort() was called at PC 0x400e85a4 on core 0
ELF file SHA256: a810b0dbae83e330
Backtrace: 0x4008e58e:0x3ffb0690 0x4008e829:0x3ffb06b0 0x400e85a4:0x3ffb06d0 0x4008406a:0x3ffb06f0
The backtrace is in the watchdog system.
I don’t think this is the same problem I am having. But it does seem that the "Detected stale connection (issue #241), restarting network” system doesn’t work properly.
Regards, Mark.
> On 29 Mar 2021, at 11:26 PM, Stephen Casner <casner at acm.org> wrote:
>
> Michael,
>
> It seems the NetMan loop is not endless, just long, since the two
> events I've reported look very similar but the WDT did not occur in
> the one I reported from the file log and in both cases normal
> operation resumed. Actually, almost normal. In one case I found that
> ssh connection attempts timed out although telnet worked, so I had to
> reboot again. I don't recall encountering that situation before.
>
> -- Steve
>
> On Mon, 29 Mar 2021, Michael Balzer wrote:
>
>> Steve,
>>
>> that might be the first real clue about the WDT issue, possibly in combination
>> with Mark's finding of a corrupted netif list.
>>
>> Maybe the NetMan task was running some endless loop due to an unclean modem
>> (ppp) shutdown?
>>
>> A modem reboot is currently necessary once in a while when the modem gets
>> stuck. We should investigate the shutdown sequence if that happens with a
>> connection in use.
>>
>> Regards,
>> Michael
>>
>>
>> Am 29.03.21 um 02:37 schrieb Stephen Casner:
>>> On Sun, 28 Mar 2021, Stephen Casner wrote:
>>>> BTW, I did also get a WDT error after resetting on the previous lockup
>>>> (before file logging), and after the reset this time there was a hang
>>>> that did not last long enough to trigget the WDT. Log segment below.
>>> I just remembered that I still had the log output from the USB console
>>> for the previous lockup where the WDT error occured. Both began after
>>> "simcom: Power Cycle". Log segment below.
>>>
>>> -- Steve
>>>
>>> I (31990) simcom: State timeout, transition to 2
>>> I (31990) simcom: State: Enter PoweringOn state
>>> I (31990) simcom: Power Cycle
>>> W (32660) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> I (32670) webserver: HTTP GET /cfg/logging
>>> W (34820) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (36940) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> I (38900) simcom: State: Enter PoweredOn state
>>> W (41220) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (43420) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (43430) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> resolved, 72 drops
>>> W (45560) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (45570) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> resolved, 8 drops
>>> W (47740) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (47750) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> resolved, 7 drops
>>> W (48990) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (49870) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (49880) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> resolved, 9 drops
>>> W (49990) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (50990) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (50990) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (51930) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (51940) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> resolved, 11 drops
>>> W (51990) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (52990) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (53990) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (54050) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> resolved, 11 drops
>>> W (54060) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (54990) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (55000) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (55990) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (56140) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (56150) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> resolved, 12 drops
>>> W (56990) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (57990) script: DuktapeDispatch: msg type 3 lost, queue full
>>> I (57990) simcom: State: Enter MuxStart state
>>> I (58000) gsm-mux: Start MUX
>>> W (58000) script: DuktapeDispatch: msg type 3 lost, queue full
>>> I (58000) gsm-mux: Channel #0 is open
>>> I (58010) gsm-mux: Channel #1 is open
>>> I (58020) gsm-mux: Channel #2 is open
>>> I (58020) gsm-mux: Channel #3 is open
>>> I (58030) gsm-mux: Channel #4 is open
>>> W (58220) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (58240) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> resolved, 18 drops
>>> I (58990) simcom: State: Enter NetWait state
>>> W (58990) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (59000) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (59990) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (60350) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detectedE (75150) task_wdt: Task watchdog got triggered. The following tasks
>>> did not reset the watchdog in time:
>>> E (75150) task_wdt: - OVMS DukTape (CPU 1)
>>> E (75150) task_wdt: Tasks currently running:
>>> E (75150) task_wdt: CPU 0: IDLE0
>>> E (75150) task_wdt: CPU 1: OVMS NetMan
>>>
>>> W (60370) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> resolved, 13 drops
>>> I (62480) webserver: HTTP POST /cfg/logging
>>> W (62480) webserver: HandleLogin: auth failure for username 'admin'
>>> W (62490) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (62510) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> resolved, 7 drops
>>> W (64550) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (66670) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (66690) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> resolved, 17 drops
>>> W (68760) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (68770) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> resolved, 7 drops
>>> I (70880) webserver: HTTP POST /cfg/logging
>>> I (70890) webserver: HandleLogin: 'admin' logged in, sid 847393266b07789
>>> W (70900) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> W (73060) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> I (75070) webserver: HTTP GET /menu
>>> W (75100) websocket: WebSocketHandler[0x3f84b22c]: job queue overflow
>>> detected
>>> I (75110) webserver: HTTP GET /cfg/logging
>>> OVMS#
>>> W (87900) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (87910) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (87910) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (87910) script: DuktapeDispatch: msg type 2 lost, queue full
>>> W (87920) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (87920) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (87930) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (87940) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (87940) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (87950) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (87960) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (87960) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (87970) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (87970) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (87980) script: DuktapeDispatch: msg type 3 lost, queue full
>>> I (87980) simcom: CREG Network Registration: RegisteredRoaming
>>> W (87990) script: DuktapeDispatch: msg type 3 lost, queue full
>>> I (87990) simcom: State: Enter NetStart state
>>> W (88000) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88000) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88010) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88020) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88020) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88030) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88030) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88040) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88040) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88050) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88050) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88060) script: DuktapeDispatch: msg type 3 lost, queue full
>>> I (88060) simcom: PPP Connection is ready to start
>>> I (88060) simcom: State: Enter NetMode state
>>> I (88060) gsm-ppp: Initialising...
>>> W (88070) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88080) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88080) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88090) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88100) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88110) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88120) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88130) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88130) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88140) script: DuktapeDispatch: msg type 3 lost, queue full
>>> W (88150) websocket: WebSocketHandler[0x3f84b154]: job queue overflow
>>> detected
>>> W (88150) websocket: WebSocketHandler[0x3f84b3ac]: job queue overflow
>>> detected
>>> W (88170) websocket: WebSocketHandler[0x3f84b3ac]: job queue overflow
>>> resolved, 32 drops
>>> W (88590) websocket: WebSocketHandler[0x3f84b154]: job queue overflow
>>> resolved, 35 drops
>>> I (90870) gsm-ppp: StatusCallBack: None
>>> I (90870) gsm-ppp: status_cb: Connected
>>> I (90870) gsm-ppp: our_ipaddr = 10.170.41.247
>>> I (90870) gsm-ppp: his_ipaddr = 10.64.64.64
>>> I (90870) gsm-ppp: netmask = 255.255.255.255
>>> I (90870) gsm-ppp: DNS#0 = 212.9.0.135
>>> I (90870) gsm-ppp: DNS#1 = 212.9.0.136
>>> I (90870) gsm-ppp: our6_ipaddr = ::
>>> I (90880) netmanager: MODEM up (with WIFI client up): staying with WIFI
>>> client priority
>>> _______________________________________________
>>> OvmsDev mailing list
>>> OvmsDev at lists.openvehicles.com
>>> http://lists.openvehicles.com/mailman/listinfo/ovmsdev
>>
>> --
>> Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
>> Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
> _______________________________________________
> OvmsDev mailing list
> OvmsDev at lists.openvehicles.com
> http://lists.openvehicles.com/mailman/listinfo/ovmsdev
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20210330/f1536993/attachment-0001.htm>
More information about the OvmsDev
mailing list