[Ovmsdev] Another incident

[Chris Box]

Hi,

It's happened again. Yesterday while driving the Leaf lost drive mode, 
forcing pulling over. I couldn't reengage gear until I had disconnected 
the 12v battery.

Looking at the evidence today, the incident can't be explained by 
writing random bytes in CommandWakeup(), nor by having the wrong timing. 
It actually suggests that OVMS locked up ten minutes before the car was 
impacted.

Here's what happened.

13:15 to 13:17 I drove off from home, but forgot an item so quickly 
returned back there.

The sd log records this activity just fine, and the last entries before 
the suspected hang were these:

2025-02-07 13:19:59.174 GMT D (93751944) events: Signal(vehicle.asleep)
2025-02-07 13:22:29.184 GMT I (93901954) housekeeping: 2025-02-07 
13:22:28 GMT (RAM: 8b=79028-81980 32b=12560 SPI=3262992-3285432)

There should have been the next housekeeping message at 13:27:29 but 
none was recorded on the sd. Log flushes are configured to occur after 
30 seconds.

The last MQTT metric update my server received was around 13:27:50. This 
showed it was connected to home wifi.

At 13:28 I unlocked the car, started it and drove off without noticing 
anything unusual. None of this activity appears in the log.

During the drive there should have been a connection via Hologram to my 
server, but none was received.

Ten minutes later at 13:38 I was driving when a yellow warning light 
came on and the car moved to neutral. Essentially the same symptoms as 
in January: turning off and on would not clear the fault; it couldn't 
detect brake status meaning it told me to press brake pedal when I 
already was. Also showed I-key system error.

As I was stranded I used the only option I knew of to clear the fault, 
and I disconnected the 12v battery. On restoring power and dismissing 
the fault notice, it was happy to drive.

The log shows this cold start SNTP was at 13:44. On returning home, 
unfortunately 'boot status' says nothing about a crash, presumably 
because any information was lost when I pulled power.

So it seems there is some mechanism by which OVMS can lock up, without 
watchdog oversight. And that ten minutes later it can do something that 
becomes a critical issue for the car systems.

Chris

Relevant log entries below, all part of the same file. 1970 follows 
immediately after 13:22:29.184.

2025-02-07 13:17:50.184 GMT D (93622984) vehicle-poll: Pollers: Queue 
SetState()
2025-02-07 13:17:50.184 GMT D (93622984) vehicle-poll: Pollers: 
PollState(0)
2025-02-07 13:17:50.184 GMT D (93622984) events: Signal(vehicle.off)
2025-02-07 13:17:51.144 GMT D (93623944) events: 
Signal(vehicle.aux.12v.charging.dip)
2025-02-07 13:17:53.144 GMT D (93625944) events: 
Signal(vehicle.aux.12v.dip)
2025-02-07 13:17:54.824 GMT E (93627624) can: can2: intr=15711227 
rxpkt=15730955 txpkt=100 errflags=0x22401c02 rxerr=0 txerr=0 rxinval=0 
rxovr=0 txovr=0 txdelay=0 txfail=0 wdgreset=0 errreset=0 txqueue=0
2025-02-07 13:17:56.754 GMT D (93629554) events: Signal(vehicle.locked)
2025-02-07 13:17:59.744 GMT E (93632544) can: can2: intr=15716706 
rxpkt=15736447 txpkt=100 errflags=0x23401c01 rxerr=0 txerr=0 rxinval=0 
rxovr=0 txovr=0 txdelay=0 txfail=0 wdgreset=0 errreset=0 txqueue=0
2025-02-07 13:18:09.144 GMT D (93641944) events: 
Signal(vehicle.charge.12v.stop)
2025-02-07 13:18:10.144 GMT I (93642944) powermgmt: No longer charging 
12V battery..
2025-02-07 13:18:33.174 GMT D (93665944) events: 
Signal(vehicle.aux.12v.normal)
2025-02-07 13:18:33.764 GMT E (93666534) can: can2: intr=15754521 
rxpkt=15774368 txpkt=100 errflags=0x22401c02 rxerr=0 txerr=0 rxinval=0 
rxovr=0 txovr=0 txdelay=0 txfail=0 wdgreset=0 errreset=0 txqueue=0
2025-02-07 13:18:45.174 GMT I (93677944) ovms-server-v3: Connection is 
<redacted>
2025-02-07 13:18:45.174 GMT I (93677944) ovms-server-v3: Status: 
Connecting...
2025-02-07 13:18:45.224 GMT D (93677994) events: 
Signal(server.v3.connecting)
2025-02-07 13:18:48.624 GMT I (93681394) ovms-server-v3: Connection 
successful
2025-02-07 13:18:48.644 GMT I (93681414) ovms-server-v3: Status: OVMS V3 
MQTT login successful
2025-02-07 13:18:48.644 GMT D (93681414) events: 
Signal(server.v3.connected)
2025-02-07 13:18:49.174 GMT I (93681944) ovms-server-v3: Subscribe to 
MQTT topics
2025-02-07 13:18:49.174 GMT I (93681944) ovms-server-v3: Transmit all 
metrics
2025-02-07 13:18:49.464 GMT I (93682234) ovms-server-v3: Subscription 
acknowledged
2025-02-07 13:19:59.174 GMT D (93751944) events: Signal(vehicle.asleep)
2025-02-07 13:22:29.184 GMT I (93901954) housekeeping: 2025-02-07 
13:22:28 GMT (RAM: 8b=79028-81980 32b=12560 SPI=3262992-3285432)
1970-01-01 00:00:08.424 GMT I (7994) command: OpenLogfile: now logging 
to file '/sd/logs/log'
1970-01-01 00:00:13.474 GMT D (13034) events: Signal(system.event)
1970-01-01 00:00:13.474 GMT D (13034) events: 
Signal(system.wifi.scan.done)
1970-01-01 00:00:19.424 GMT I (18984) cellular: State: Enter Identify 
state
1970-01-01 00:00:19.434 GMT I (18994) cellular: Identified cellular 
modem: SIM7600/Experimental support for SIMCOM SIM7600
1970-01-01 00:00:19.434 GMT I (18994) cellular: Set modem driver to 
'SIM7600'
1970-01-01 00:00:19.434 GMT I (18994) cellular: State: Enter PoweredOn 
state
1970-01-01 00:00:19.424 GMT D (18994) events: 
Signal(system.modem.installed)
1970-01-01 00:00:19.434 GMT D (19004) events: 
Signal(system.modem.poweredon)
1970-01-01 00:00:23.474 GMT D (23034) events: Signal(system.event)
1970-01-01 00:00:23.474 GMT D (23034) events: 
Signal(system.wifi.scan.done)
1970-01-01 00:00:33.474 GMT D (33034) events: Signal(system.event)
1970-01-01 00:00:33.474 GMT D (33034) events: 
Signal(system.wifi.scan.done)
1970-01-01 00:00:39.434 GMT I (38994) cellular: State: Enter MuxStart 
state
1970-01-01 00:00:39.444 GMT I (39004) gsm-mux: Start MUX
1970-01-01 00:00:39.444 GMT D (39004) events: 
Signal(system.modem.muxstart)
1970-01-01 00:00:39.444 GMT I (39014) gsm-mux: Channel #0 is open
1970-01-01 00:00:39.464 GMT I (39024) gsm-mux: Channel #1 is open
1970-01-01 00:00:39.464 GMT I (39024) gsm-mux: Channel #2 is open
1970-01-01 00:00:39.474 GMT I (39034) gsm-mux: Channel #3 is open
1970-01-01 00:00:39.484 GMT I (39044) gsm-mux: Channel #4 is open
1970-01-01 00:00:40.414 GMT I (39984) cellular: State: Enter NetWait 
state
1970-01-01 00:00:40.414 GMT D (39984) events: 
Signal(system.modem.netwait)
1970-01-01 00:00:43.474 GMT D (43034) events: Signal(system.event)
1970-01-01 00:00:43.474 GMT D (43034) events: 
Signal(system.wifi.scan.done)
1970-01-01 00:00:46.054 GMT D (45624) events: Signal(vehicle.awake)
1970-01-01 00:00:50.444 GMT I (50014) cellular: Network Registration 
status: RegisteredRoaming
1970-01-01 00:00:51.414 GMT I (50984) cellular: State: Enter NetStart 
state
1970-01-01 00:00:51.434 GMT D (50994) events: 
Signal(vehicle.aux.12v.blip)
1970-01-01 00:00:51.434 GMT D (50994) events: 
Signal(system.modem.netstart)
1970-01-01 00:00:51.444 GMT D (51004) events: 
Signal(vehicle.charge.12v.start)
1970-01-01 00:00:51.434 GMT I (51004) cellular: Network Mode: LTE,Online
1970-01-01 00:00:52.414 GMT I (51984) powermgmt: Charging 12V battery..
1970-01-01 00:00:52.464 GMT I (52034) cellular: PPP Connection is ready 
to start
1970-01-01 00:00:53.424 GMT I (52984) cellular: State: Enter NetMode 
state
1970-01-01 00:00:53.424 GMT I (52984) gsm-ppp: Initialising...
1970-01-01 00:00:53.434 GMT D (52994) events: 
Signal(system.modem.netmode)
1970-01-01 00:00:53.484 GMT D (53044) events: Signal(system.event)
1970-01-01 00:00:53.484 GMT D (53044) events: 
Signal(system.wifi.scan.done)
1970-01-01 00:00:53.594 GMT I (53154) gsm-ppp: StatusCallBack: None
1970-01-01 00:00:53.594 GMT I (53154) gsm-ppp: status_cb: Connected
1970-01-01 00:00:53.594 GMT I (53154) gsm-ppp:    our_ipaddr  = 
100.83.212.151
1970-01-01 00:00:53.594 GMT I (53154) gsm-ppp:    his_ipaddr  = 
10.64.64.64
1970-01-01 00:00:53.594 GMT I (53154) gsm-ppp:    netmask     = 
255.255.255.255
1970-01-01 00:00:53.594 GMT I (53154) gsm-ppp:    DNS#0       = 8.8.8.8
1970-01-01 00:00:53.584 GMT I (53154) gsm-ppp:    DNS#1       = 8.8.4.4
1970-01-01 00:00:53.594 GMT I (53154) gsm-ppp:    our6_ipaddr = ::
1970-01-01 00:00:53.594 GMT D (53154) events: 
Signal(network.interface.up)
1970-01-01 00:00:53.604 GMT D (53164) events: Signal(system.modem.gotip)
1970-01-01 00:00:53.604 GMT I (53164) netmanager: Interface priority is 
pp2 (100.83.212.151/255.255.255.255 gateway 10.64.64.64)
1970-01-01 00:00:53.604 GMT I (53164) netmanager: Set DNS#2 0.0.0.0
1970-01-01 00:00:53.594 GMT I (53164) netmanager: MODEM up (with WIFI 
client down): starting network with MODEM
1970-01-01 00:00:53.594 GMT D (53164) events: Signal(network.modem.up)
1970-01-01 00:00:53.594 GMT D (53164) events: Signal(network.up)
1970-01-01 00:00:53.604 GMT I (53174) time: Starting SNTP client
1970-01-01 00:00:53.604 GMT D (53174) events: 
Signal(network.interface.change)
1970-01-01 00:00:53.614 GMT D (53174) events: Signal(network.mgr.init)
1970-01-01 00:00:53.614 GMT I (53174) webserver: Launching Web Server
2025-02-07 13:44:08.584 GMT I (53184) webserver: Binding to port 80 
(http)
2025-02-07 13:44:08.584 GMT I (53184) ssh: Launching SSH Server
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20250208/c8b413f6/attachment-0001.htm>