Repeated WDT crashes after upgrade to 3.3 with 4G
I installed version 3.3.001-285 from edge on my OVMS v3.1 unit before replacing the 3G modem with a 4G modem. Upon rebooting with the unit still on the bench I noticed that the unit was crashing every three minutes with a watchdog timeout: I (112275) gsm-mux: Start MUX I (112285) gsm-mux: Channel #0 is open I (112295) gsm-mux: Channel #1 is open I (112305) gsm-mux: Channel #2 is open I (112315) gsm-mux: Channel #3 is open I (112325) gsm-mux: Channel #4 is open I (113265) cellular: State: Enter NetWait state I (122265) housekeeping: System considered stable (RAM: 8b=81540-82392 32b=12344 SPI=3454300-3456824) I (122505) webserver: HTTP GET / I (122535) webserver: HTTP GET /apple-touch-icon.png I (122555) webserver: HTTP GET /status I (123265) ovms-server-v2: Send MP-0 h1,0,*-OVM-DebugCrash,0,2592000,3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30),2,Crash,12,12,2,0,abort(),0,,0x4008ddca 0x4008e065 0x400e9608 0x40084176 ,6,Task watchdog,ticker.1,esp32wifi,0,IDLE0,OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600 I (123295) cellular: Network Registration status: RegisteredRoaming I (123295) cellular: Network Provider is: AT&T Hologram I (123595) ovms-server-v2: Incoming Msg: MP-0 h1 I (124265) cellular: State: Enter NetStart state I (129845) webserver: HTTP POST /status I (129845) webserver: HandleLogin: 'admin' logged in, sid c3bb26091e718ad I (129875) webserver: HTTP GET /status I (130035) webserver: HTTP GET /menu W (178175) websocket: WebSocketHandler[0x3f8b19f0]: job queue overflow detected OVMS> E (185265) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time: E (185265) task_wdt: - IDLE0 (CPU 0) E (185265) task_wdt: Tasks currently running: E (185265) task_wdt: CPU 0: Tmr Svc E (185265) task_wdt: CPU 1: IDLE1 E (185265) task_wdt: Aborting. abort() was called at PC 0x400e9608 on core 0 ELF file SHA256: 2d4b51699f53abce Backtrace: 0x4008ddca:0x3ffb0aa0 0x4008e065:0x3ffb0ac0 0x400e9608:0x3ffb0ae0 0x40084176:0x3ffb0b00 Rebooting... I was hoping that when I put the module back into the car with all the right inputs on its data cable that this problem would not continue, but sad to say the crashes remain the same. I have not heard about this issue for others who have upgraded to 3.3 and 4G. Any suggestions? Here are a couple of examples of the boot status: auge1> ssh ovms Welcome to the Open Vehicle Monitoring System (OVMS) - SSH Console Firmware: 3.3.001-285-g601f2a70/ota_1/edge Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600 OVMS# boot Last boot was 152 second(s) ago Time at boot: 2022-03-02 14:29:11 PST This is reset #1 since last power cycle Detected boot reason: EarlyCrash (12/12) Reset reason: Task watchdog (6) Crash counters: 1 total, 1 early Last crash: abort() was called on core 0 Backtrace: 0x4008ddca 0x4008e065 0x400e9608 0x40084176 Event: ticker.1@esp32wifi 0 secs WDT tasks: IDLE0 Version: 3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30) Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600 OVMS# packet_write_wait: Connection to 192.168.1.74 port 22: Broken pipe auge2> ssh ovms Welcome to the Open Vehicle Monitoring System (OVMS) - SSH Console Firmware: 3.3.001-285-g601f2a70/ota_1/edge Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1 OVMS# boot Last boot was 76 second(s) ago Time at boot: 2022-03-02 14:32:18 PST This is reset #2 since last power cycle Detected boot reason: Crash (12/12) Reset reason: Task watchdog (6) Crash counters: 2 total, 0 early Last crash: abort() was called on core 0 Backtrace: 0x4008ddca 0x4008e065 0x400e9608 0x40084176 Event: ticker.1@esp32wifi 0 secs WDT tasks: IDLE0 Version: 3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30) Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1 OVMS# OVMS# packet_write_wait: Connection to 192.168.1.74 port 22: Broken pipe -- Steve
This looks very much like what I'm seeing. My new 3.3 module and 3.3 modem hasn't worked with 4G. It was crashing over and over again until I disabled the modem from autostarting. Then it takes several minutes before I get a crash. But it always happens for me. I'm attaching a screen shot of my modue windows after the crash. I note that WDT: IDLE0 looks very much like what Steve is seeing. Jeff On 3/2/2022 2:55 PM, Stephen Casner wrote:
I installed version 3.3.001-285 from edge on my OVMS v3.1 unit before replacing the 3G modem with a 4G modem. Upon rebooting with the unit still on the bench I noticed that the unit was crashing every three minutes with a watchdog timeout:
I (112275) gsm-mux: Start MUX I (112285) gsm-mux: Channel #0 is open I (112295) gsm-mux: Channel #1 is open I (112305) gsm-mux: Channel #2 is open I (112315) gsm-mux: Channel #3 is open I (112325) gsm-mux: Channel #4 is open I (113265) cellular: State: Enter NetWait state I (122265) housekeeping: System considered stable (RAM: 8b=81540-82392 32b=12344 SPI=3454300-3456824) I (122505) webserver: HTTP GET / I (122535) webserver: HTTP GET /apple-touch-icon.png I (122555) webserver: HTTP GET /status I (123265) ovms-server-v2: Send MP-0 h1,0,*-OVM-DebugCrash,0,2592000,3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30),2,Crash,12,12,2,0,abort(),0,,0x4008ddca 0x4008e065 0x400e9608 0x40084176 ,6,Task watchdog,ticker.1,esp32wifi,0,IDLE0,OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600 I (123295) cellular: Network Registration status: RegisteredRoaming I (123295) cellular: Network Provider is: AT&T Hologram I (123595) ovms-server-v2: Incoming Msg: MP-0 h1 I (124265) cellular: State: Enter NetStart state I (129845) webserver: HTTP POST /status I (129845) webserver: HandleLogin: 'admin' logged in, sid c3bb26091e718ad I (129875) webserver: HTTP GET /status I (130035) webserver: HTTP GET /menu W (178175) websocket: WebSocketHandler[0x3f8b19f0]: job queue overflow detected OVMS> E (185265) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time: E (185265) task_wdt: - IDLE0 (CPU 0) E (185265) task_wdt: Tasks currently running: E (185265) task_wdt: CPU 0: Tmr Svc E (185265) task_wdt: CPU 1: IDLE1 E (185265) task_wdt: Aborting. abort() was called at PC 0x400e9608 on core 0
ELF file SHA256: 2d4b51699f53abce
Backtrace: 0x4008ddca:0x3ffb0aa0 0x4008e065:0x3ffb0ac0 0x400e9608:0x3ffb0ae0 0x40084176:0x3ffb0b00
Rebooting...
I was hoping that when I put the module back into the car with all the right inputs on its data cable that this problem would not continue, but sad to say the crashes remain the same. I have not heard about this issue for others who have upgraded to 3.3 and 4G. Any suggestions?
Here are a couple of examples of the boot status:
auge1> ssh ovms
Welcome to the Open Vehicle Monitoring System (OVMS) - SSH Console Firmware: 3.3.001-285-g601f2a70/ota_1/edge Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600
OVMS# boot Last boot was 152 second(s) ago Time at boot: 2022-03-02 14:29:11 PST This is reset #1 since last power cycle Detected boot reason: EarlyCrash (12/12) Reset reason: Task watchdog (6) Crash counters: 1 total, 1 early
Last crash: abort() was called on core 0 Backtrace: 0x4008ddca 0x4008e065 0x400e9608 0x40084176 Event: ticker.1@esp32wifi 0 secs WDT tasks: IDLE0 Version: 3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30)
Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600 OVMS# packet_write_wait: Connection to 192.168.1.74 port 22: Broken pipe auge2> ssh ovms
Welcome to the Open Vehicle Monitoring System (OVMS) - SSH Console Firmware: 3.3.001-285-g601f2a70/ota_1/edge Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1
OVMS# boot Last boot was 76 second(s) ago Time at boot: 2022-03-02 14:32:18 PST This is reset #2 since last power cycle Detected boot reason: Crash (12/12) Reset reason: Task watchdog (6) Crash counters: 2 total, 0 early
Last crash: abort() was called on core 0 Backtrace: 0x4008ddca 0x4008e065 0x400e9608 0x40084176 Event: ticker.1@esp32wifi 0 secs WDT tasks: IDLE0 Version: 3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30)
Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1 OVMS# OVMS# packet_write_wait: Connection to 192.168.1.74 port 22: Broken pipe
-- Steve _______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev
"cellular setstate PoweredOff" stopped the crashes. So it appears that something in the 4G modem support is running away. -- Steve On Wed, 2 Mar 2022, Stephen Casner wrote:
I installed version 3.3.001-285 from edge on my OVMS v3.1 unit before replacing the 3G modem with a 4G modem. Upon rebooting with the unit still on the bench I noticed that the unit was crashing every three minutes with a watchdog timeout:
I (112275) gsm-mux: Start MUX I (112285) gsm-mux: Channel #0 is open I (112295) gsm-mux: Channel #1 is open I (112305) gsm-mux: Channel #2 is open I (112315) gsm-mux: Channel #3 is open I (112325) gsm-mux: Channel #4 is open I (113265) cellular: State: Enter NetWait state I (122265) housekeeping: System considered stable (RAM: 8b=81540-82392 32b=12344 SPI=3454300-3456824) I (122505) webserver: HTTP GET / I (122535) webserver: HTTP GET /apple-touch-icon.png I (122555) webserver: HTTP GET /status I (123265) ovms-server-v2: Send MP-0 h1,0,*-OVM-DebugCrash,0,2592000,3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30),2,Crash,12,12,2,0,abort(),0,,0x4008ddca 0x4008e065 0x400e9608 0x40084176 ,6,Task watchdog,ticker.1,esp32wifi,0,IDLE0,OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600 I (123295) cellular: Network Registration status: RegisteredRoaming I (123295) cellular: Network Provider is: AT&T Hologram I (123595) ovms-server-v2: Incoming Msg: MP-0 h1 I (124265) cellular: State: Enter NetStart state I (129845) webserver: HTTP POST /status I (129845) webserver: HandleLogin: 'admin' logged in, sid c3bb26091e718ad I (129875) webserver: HTTP GET /status I (130035) webserver: HTTP GET /menu W (178175) websocket: WebSocketHandler[0x3f8b19f0]: job queue overflow detected OVMS> E (185265) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time: E (185265) task_wdt: - IDLE0 (CPU 0) E (185265) task_wdt: Tasks currently running: E (185265) task_wdt: CPU 0: Tmr Svc E (185265) task_wdt: CPU 1: IDLE1 E (185265) task_wdt: Aborting. abort() was called at PC 0x400e9608 on core 0
ELF file SHA256: 2d4b51699f53abce
Backtrace: 0x4008ddca:0x3ffb0aa0 0x4008e065:0x3ffb0ac0 0x400e9608:0x3ffb0ae0 0x40084176:0x3ffb0b00
Rebooting...
I was hoping that when I put the module back into the car with all the right inputs on its data cable that this problem would not continue, but sad to say the crashes remain the same. I have not heard about this issue for others who have upgraded to 3.3 and 4G. Any suggestions?
Here are a couple of examples of the boot status:
auge1> ssh ovms
Welcome to the Open Vehicle Monitoring System (OVMS) - SSH Console Firmware: 3.3.001-285-g601f2a70/ota_1/edge Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600
OVMS# boot Last boot was 152 second(s) ago Time at boot: 2022-03-02 14:29:11 PST This is reset #1 since last power cycle Detected boot reason: EarlyCrash (12/12) Reset reason: Task watchdog (6) Crash counters: 1 total, 1 early
Last crash: abort() was called on core 0 Backtrace: 0x4008ddca 0x4008e065 0x400e9608 0x40084176 Event: ticker.1@esp32wifi 0 secs WDT tasks: IDLE0 Version: 3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30)
Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600 OVMS# packet_write_wait: Connection to 192.168.1.74 port 22: Broken pipe auge2> ssh ovms
Welcome to the Open Vehicle Monitoring System (OVMS) - SSH Console Firmware: 3.3.001-285-g601f2a70/ota_1/edge Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1
OVMS# boot Last boot was 76 second(s) ago Time at boot: 2022-03-02 14:32:18 PST This is reset #2 since last power cycle Detected boot reason: Crash (12/12) Reset reason: Task watchdog (6) Crash counters: 2 total, 0 early
Last crash: abort() was called on core 0 Backtrace: 0x4008ddca 0x4008e065 0x400e9608 0x40084176 Event: ticker.1@esp32wifi 0 secs WDT tasks: IDLE0 Version: 3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30)
Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1 OVMS# OVMS# packet_write_wait: Connection to 192.168.1.74 port 22: Broken pipe
-- Steve
Can you try to get a debug log for the cellular system?
On 3 Mar 2022, at 12:43 PM, Stephen Casner <casner@acm.org> wrote:
"cellular setstate PoweredOff" stopped the crashes. So it appears that something in the 4G modem support is running away.
-- Steve
On Wed, 2 Mar 2022, Stephen Casner wrote:
I installed version 3.3.001-285 from edge on my OVMS v3.1 unit before replacing the 3G modem with a 4G modem. Upon rebooting with the unit still on the bench I noticed that the unit was crashing every three minutes with a watchdog timeout:
I (112275) gsm-mux: Start MUX I (112285) gsm-mux: Channel #0 is open I (112295) gsm-mux: Channel #1 is open I (112305) gsm-mux: Channel #2 is open I (112315) gsm-mux: Channel #3 is open I (112325) gsm-mux: Channel #4 is open I (113265) cellular: State: Enter NetWait state I (122265) housekeeping: System considered stable (RAM: 8b=81540-82392 32b=12344 SPI=3454300-3456824) I (122505) webserver: HTTP GET / I (122535) webserver: HTTP GET /apple-touch-icon.png I (122555) webserver: HTTP GET /status I (123265) ovms-server-v2: Send MP-0 h1,0,*-OVM-DebugCrash,0,2592000,3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30),2,Crash,12,12,2,0,abort(),0,,0x4008ddca 0x4008e065 0x400e9608 0x40084176 ,6,Task watchdog,ticker.1,esp32wifi,0,IDLE0,OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600 I (123295) cellular: Network Registration status: RegisteredRoaming I (123295) cellular: Network Provider is: AT&T Hologram I (123595) ovms-server-v2: Incoming Msg: MP-0 h1 I (124265) cellular: State: Enter NetStart state I (129845) webserver: HTTP POST /status I (129845) webserver: HandleLogin: 'admin' logged in, sid c3bb26091e718ad I (129875) webserver: HTTP GET /status I (130035) webserver: HTTP GET /menu W (178175) websocket: WebSocketHandler[0x3f8b19f0]: job queue overflow detected OVMS> E (185265) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time: E (185265) task_wdt: - IDLE0 (CPU 0) E (185265) task_wdt: Tasks currently running: E (185265) task_wdt: CPU 0: Tmr Svc E (185265) task_wdt: CPU 1: IDLE1 E (185265) task_wdt: Aborting. abort() was called at PC 0x400e9608 on core 0
ELF file SHA256: 2d4b51699f53abce
Backtrace: 0x4008ddca:0x3ffb0aa0 0x4008e065:0x3ffb0ac0 0x400e9608:0x3ffb0ae0 0x40084176:0x3ffb0b00
Rebooting...
I was hoping that when I put the module back into the car with all the right inputs on its data cable that this problem would not continue, but sad to say the crashes remain the same. I have not heard about this issue for others who have upgraded to 3.3 and 4G. Any suggestions?
Here are a couple of examples of the boot status:
auge1> ssh ovms
Welcome to the Open Vehicle Monitoring System (OVMS) - SSH Console Firmware: 3.3.001-285-g601f2a70/ota_1/edge Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600
OVMS# boot Last boot was 152 second(s) ago Time at boot: 2022-03-02 14:29:11 PST This is reset #1 since last power cycle Detected boot reason: EarlyCrash (12/12) Reset reason: Task watchdog (6) Crash counters: 1 total, 1 early
Last crash: abort() was called on core 0 Backtrace: 0x4008ddca 0x4008e065 0x400e9608 0x40084176 Event: ticker.1@esp32wifi 0 secs WDT tasks: IDLE0 Version: 3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30)
Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600 OVMS# packet_write_wait: Connection to 192.168.1.74 port 22: Broken pipe auge2> ssh ovms
Welcome to the Open Vehicle Monitoring System (OVMS) - SSH Console Firmware: 3.3.001-285-g601f2a70/ota_1/edge Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1
OVMS# boot Last boot was 76 second(s) ago Time at boot: 2022-03-02 14:32:18 PST This is reset #2 since last power cycle Detected boot reason: Crash (12/12) Reset reason: Task watchdog (6) Crash counters: 2 total, 0 early
Last crash: abort() was called on core 0 Backtrace: 0x4008ddca 0x4008e065 0x400e9608 0x40084176 Event: ticker.1@esp32wifi 0 secs WDT tasks: IDLE0 Version: 3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30)
Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/1 OVMS# OVMS# packet_write_wait: Connection to 192.168.1.74 port 22: Broken pipe
-- Steve
OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev
I thought I would just try again to turn on the 4G modem... This is my log from the webserver command to start the modem. Just less than 2 minutes before crash. Jeff Anton 2022-03-03 14:35:07.014 PST I (93805104) webserver: HTTP POST /api/execute 2022-03-03 14:35:07.024 PST I (93805114) webcommand: HttpCommandStream[0x3f8b2544]: 3527736 bytes free, executing: power cellular on 2022-03-03 14:35:07.024 PST I (93805114) cellular: Set modem driver to 'auto' 2022-03-03 14:35:07.024 PST I (93805114) cellular: State: Enter PoweringOn state 2022-03-03 14:35:07.034 PST I (93805124) cellular-modem-auto: Power Cycle 2000ms 2022-03-03 14:35:07.414 PST I (93805504) webserver: HTTP POST /api/execute 2022-03-03 14:35:07.414 PST I (93805504) webcommand: HttpCommandStream[0x3f8b22e8]: 3531492 bytes free, executing: cellular status 2022-03-03 14:35:11.044 PST I (93809134) ovms-server-v2: Send MP-0 S84.0,M,65535,127.00,done,,196,162,32,0,0,30,7,4,-1,0,0,0,178.72,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,0.00,81,0.00,0.00,1.00,0.0 2022-03-03 14:35:11.044 PST I (93809134) ovms-server-v2: Send MP-0 D72,8,4,31,30,20,1225,702246,0,86523,37,0,0,0,11.92,0,12.6,0,31,0,0 2022-03-03 14:35:11.054 PST I (93809144) ovms-server-v2: Send MP-0 L37.830540,-122.244446,226,56,1,1,0.0,1225,0,0.395,0,0,0,0,,0,0,0 2022-03-03 14:35:11.054 PST I (93809144) ovms-server-v2: Send MP-0 F3.3.001-33-g58d01654/factory/main (build idf v3.3.4-848-g1ff5e24b1 Dec 27 2021 00:03:08),5yjre1a12a1001026,23,1,TR1N,Crete,-1,-1 2022-03-03 14:35:24.664 PST I (93822754) cellular: State: Enter Identify state 2022-03-03 14:35:25.054 PST I (93823144) cellular: Identified cellular modem: SIM7600/Experimental support for SIMCOM SIM7600 2022-03-03 14:35:25.054 PST I (93823144) cellular: Set modem driver to 'SIM7600' 2022-03-03 14:35:25.054 PST I (93823144) cellular: State: Enter PoweredOn state 2022-03-03 14:35:25.314 PST I (93823404) webserver: HTTP POST /api/execute 2022-03-03 14:35:25.324 PST I (93823414) webcommand: HttpCommandStream[0x3f8b22e8]: 3527732 bytes free, executing: cellular status 2022-03-03 14:35:35.084 PST I (93833174) cellular: Signal Quality is: 17 (-79 dBm) 2022-03-03 14:35:45.054 PST I (93843144) cellular: State: Enter MuxStart state 2022-03-03 14:35:45.054 PST I (93843144) gsm-mux: Start MUX 2022-03-03 14:35:45.064 PST I (93843154) gsm-mux: Channel #0 is open 2022-03-03 14:35:45.074 PST I (93843164) gsm-mux: Channel #1 is open 2022-03-03 14:35:45.084 PST I (93843174) gsm-mux: Channel #2 is open 2022-03-03 14:35:45.094 PST I (93843184) gsm-mux: Channel #3 is open 2022-03-03 14:35:45.104 PST I (93843194) gsm-mux: Channel #4 is open 2022-03-03 14:35:45.214 PST I (93843304) webserver: HTTP POST /api/execute 2022-03-03 14:35:45.214 PST I (93843304) webcommand: HttpCommandStream[0x3f8b22e8]: 3516696 bytes free, executing: cellular status 2022-03-03 14:35:46.044 PST I (93844134) cellular: State: Enter NetWait state 2022-03-03 14:35:46.304 PST I (93844394) webserver: HTTP POST /api/execute 2022-03-03 14:35:46.304 PST I (93844394) webcommand: HttpCommandStream[0x3f8b1460]: 3516484 bytes free, executing: cellular status 2022-03-03 14:35:56.064 PST I (93854154) cellular: Network Registration status: RegisteredRoaming 2022-03-03 14:35:56.074 PST I (93854164) cellular: Network Provider is: T-Mobile Hologram 2022-03-03 14:35:57.044 PST I (93855134) cellular: State: Enter NetStart state 2022-03-03 14:35:57.244 PST I (93855334) webserver: HTTP POST /api/execute 2022-03-03 14:35:57.254 PST I (93855344) webcommand: HttpCommandStream[0x3f8b55a0]: 3517712 bytes free, executing: cellular status 2022-03-03 14:35:58.114 PST I (93856204) cellular: PPP Connection is ready to start 2022-03-03 14:36:11.384 PST I (93869474) ovms-server-v2: Incoming Msg: MP-0 AFA 2022-03-03 14:36:11.394 PST I (93869484) ovms-server-v2: Send MP-0 a 2022-03-03 14:36:43.034 PST I (93901134) housekeeping: 2022-03-03 14:36:42 PST (RAM: 8b=75872-77524 32b=10160) 2022-03-03 14:37:09.046 PST I (8126) command: OpenLogfile: now logging to file '/sd/log' On 3/3/22 05:15, Mark Webb-Johnson wrote:
Can you try to get a debug log for the cellular system?
On 3 Mar 2022, at 12:43 PM, Stephen Casner <casner@acm.org> wrote:
"cellular setstate PoweredOff" stopped the crashes. So it appears that something in the 4G modem support is running away.
-- Steve
On Thu, 3 Mar 2022, Mark Webb-Johnson wrote:
Can you try to get a debug log for the cellular system?
Inline below. This is with cellular, gsm-mux and SIM7600 set to debug. Any other useful tags? Looks like it dies not long after entering NetStart state. -- Steve 2022-03-03 17:08:45.249 PST I (547059) cellular: Set modem driver to 'auto' 2022-03-03 17:08:45.249 PST I (547059) cellular: State: Enter PowerOffOn state 2022-03-03 17:08:45.249 PST I (547059) cellular-modem-auto: Power Cycle 2000ms 2022-03-03 17:08:47.539 PST D (549349) cellular: State timeout PowerOffOn => PoweringOn 2022-03-03 17:08:47.539 PST I (549349) cellular: State: Enter PoweringOn state 2022-03-03 17:08:47.539 PST I (549349) cellular-modem-auto: Power Cycle 4000ms 2022-03-03 17:08:51.539 PST D (553349) cellular: tx-cmd: AT 2022-03-03 17:08:51.539 PST D (553349) cellular: tx-cmd: AT 2022-03-03 17:08:51.539 PST D (553349) cellular: tx-cmd: AT 2022-03-03 17:08:51.539 PST D (553349) cellular: tx-cmd: AT 2022-03-03 17:08:52.539 PST D (554349) cellular: tx-cmd: AT 2022-03-03 17:08:53.539 PST D (555349) cellular: tx-cmd: AT 2022-03-03 17:08:54.539 PST D (556349) cellular: tx-cmd: AT 2022-03-03 17:08:55.539 PST D (557349) cellular: tx-cmd: AT 2022-03-03 17:08:56.539 PST D (558349) cellular: tx-cmd: AT 2022-03-03 17:08:57.539 PST D (559349) cellular: tx-cmd: AT 2022-03-03 17:08:58.539 PST D (560349) cellular: tx-cmd: AT 2022-03-03 17:08:59.539 PST D (561349) cellular: tx-cmd: AT 2022-03-03 17:09:00.539 PST D (562349) cellular: tx-cmd: AT 2022-03-03 17:09:01.539 PST D (563349) cellular: tx-cmd: AT 2022-03-03 17:09:02.539 PST D (564349) cellular: tx-cmd: AT 2022-03-03 17:09:02.979 PST I (564789) cellular: State: Enter Identify state 2022-03-03 17:09:03.539 PST D (565349) cellular: tx-cmd: AT+CGMM 2022-03-03 17:09:03.549 PST I (565359) cellular: Identified cellular modem: SIM7600/Experimental support for SIMCOM SIM7600 2022-03-03 17:09:03.549 PST D (565359) cellular: Remove old 'auto' modem driver 2022-03-03 17:09:03.549 PST I (565359) cellular: Set modem driver to 'SIM7600' 2022-03-03 17:09:03.549 PST I (565359) cellular: State: Enter PoweredOn state 2022-03-03 17:09:13.539 PST D (575349) cellular: tx-cmd: AT+CPIN?;+CREG=1;+CTZU=1;+CTZR=1;+CLIP=1;+CMGF=1;+CNMI=1,2,0,0,0;+CSDH=1;+CMEE=2;+CSQ;+AUTOCSQ=1,1;E0;S0=0 2022-03-03 17:09:13.569 PST D (575379) cellular: mux-rx-line #0: AT+CPIN?;+CREG=1;+CTZU=1;+CTZR=1;+CLIP=1;+CMGF=1;+CNMI=1,2,0,0,0;+CSDH=1;+CMEE=2;+CSQ;+AUTOCSQ=1,1;E0;S0=0 2022-03-03 17:09:13.569 PST D (575379) cellular: mux-rx-line #0: +CPIN: READY 2022-03-03 17:09:13.569 PST D (575379) cellular: mux-rx-line #0: +CSQ: 13,99 2022-03-03 17:09:13.579 PST I (575389) cellular: Signal Quality is: 13 (-87 dBm) 2022-03-03 17:09:15.539 PST D (577349) cellular: tx-cmd: AT+CGMR;+ICCID 2022-03-03 17:09:15.559 PST D (577369) cellular: mux-rx-line #0: +CGMR: LE20B03SIM7600M21-A 2022-03-03 17:09:15.559 PST D (577369) cellular: mux-rx-line #0: +ICCID: 8944501805175416178 2022-03-03 17:09:23.539 PST D (585349) cellular: tx-cmd: AT+CMUX=0 2022-03-03 17:09:23.549 PST I (585359) cellular: State: Enter MuxStart state 2022-03-03 17:09:23.549 PST I (585359) gsm-mux: Start MUX 2022-03-03 17:09:23.559 PST I (585369) gsm-mux: Channel #0 is open 2022-03-03 17:09:23.569 PST I (585379) gsm-mux: Channel #1 is open 2022-03-03 17:09:23.579 PST I (585389) gsm-mux: Channel #2 is open 2022-03-03 17:09:23.589 PST I (585399) gsm-mux: Channel #3 is open 2022-03-03 17:09:23.599 PST I (585409) gsm-mux: Channel #4 is open 2022-03-03 17:09:24.539 PST D (586349) cellular: State transition MuxStart => NetWait 2022-03-03 17:09:24.539 PST I (586349) cellular: State: Enter NetWait state 2022-03-03 17:09:34.539 PST D (596349) cellular: mux-tx #3: AT+CREG?;+CCLK?;+CSQ;+COPS? 2022-03-03 17:09:34.569 PST D (596379) cellular: mux-rx-line #3: +CREG: 1,5 2022-03-03 17:09:34.569 PST I (596379) cellular: Network Registration status: RegisteredRoaming 2022-03-03 17:09:34.569 PST D (596379) cellular: mux-rx-line #3: +CCLK: "22/03/03,17:09:32-32" 2022-03-03 17:09:34.569 PST D (596379) cellular: mux-rx-line #3: +CSQ: 13,99 2022-03-03 17:09:34.569 PST D (596379) cellular: mux-rx-line #3: +COPS: 0,0,"AT&T Hologram",2 2022-03-03 17:09:34.569 PST I (596379) cellular: Network Provider is: AT&T Hologram 2022-03-03 17:09:35.539 PST D (597349) cellular: State transition NetWait => NetStart 2022-03-03 17:09:35.539 PST I (597349) cellular: State: Enter NetStart state 2022-03-03 17:09:40.549 PST I (602359) housekeeping: 2022-03-03 17:09:39 PST (RAM: 8b=78500-79076 32b=12344 SPI=3439196-3442228) 2022-03-03 17:09:48.539 PST I (610349) ovms-server-v2: Send MP-0 S78.0,M,65535,127.00,done,standard,164,138,17,0,0,140,7,4,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,1.00,0.0 2022-03-03 17:09:48.539 PST I (610349) ovms-server-v2: Send MP-0 D64,0,5,19,17,17,512,625508,0,95954,19,0,0,0,11.54,0,12.6,0,19,0,0 2022-03-03 17:09:48.549 PST I (610359) ovms-server-v2: Send MP-0 L37.346333,-122.037285,80,54,1,1,0.0,512,0,0.393,0,0,0,0,,0,0,0 2022-03-03 17:09:48.549 PST I (610359) ovms-server-v2: Send MP-0 F3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30),5YJRE11B181000033,30,0,TR1N,Revelstoke,-1,-1,OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600 2022-03-03 17:10:47.479 PST I (9639) command: OpenLogfile: now logging to file '/sd/crash.log'
Steve, Jeff, I have noticed you running '3.3.001-285’. Can you try with the standard ‘3.3.001’ that was released a while ago? You can get it from: http://api.openvehicles.com/firmware/ota/v3.3/main/ovms3.bin <http://api.openvehicles.com/firmware/ota/v3.3/main/ovms3.bin> or http://api.openvehicles.com/firmware/ota/v3.2/edge/3.3.001.ovms3.bin <http://api.openvehicles.com/firmware/ota/v3.2/edge/3.3.001.ovms3.bin> I wonder if something is broken in the latest edge? P.S. I think that in general we may be confusing people here. The firmware/ota/<X> directory is for those version <X> mainboards. So /v3.1/, /v3.2/ or /v3.3/. The idea is that we can then have different build settings (sdkconfig) for different base hardware (in particular esp32 revision) and make improvements. At the moment v3.1 and v3.2 are symlinked together (on api.openvehicles.com <http://api.openvehicles.com/>) as ESP32 is the same. Regards, Mark
On 4 Mar 2022, at 9:17 AM, Stephen Casner <casner@acm.org> wrote:
On Thu, 3 Mar 2022, Mark Webb-Johnson wrote:
Can you try to get a debug log for the cellular system?
Inline below. This is with cellular, gsm-mux and SIM7600 set to debug. Any other useful tags? Looks like it dies not long after entering NetStart state.
-- Steve
2022-03-03 17:08:45.249 PST I (547059) cellular: Set modem driver to 'auto' 2022-03-03 17:08:45.249 PST I (547059) cellular: State: Enter PowerOffOn state 2022-03-03 17:08:45.249 PST I (547059) cellular-modem-auto: Power Cycle 2000ms 2022-03-03 17:08:47.539 PST D (549349) cellular: State timeout PowerOffOn => PoweringOn 2022-03-03 17:08:47.539 PST I (549349) cellular: State: Enter PoweringOn state 2022-03-03 17:08:47.539 PST I (549349) cellular-modem-auto: Power Cycle 4000ms 2022-03-03 17:08:51.539 PST D (553349) cellular: tx-cmd: AT 2022-03-03 17:08:51.539 PST D (553349) cellular: tx-cmd: AT 2022-03-03 17:08:51.539 PST D (553349) cellular: tx-cmd: AT 2022-03-03 17:08:51.539 PST D (553349) cellular: tx-cmd: AT 2022-03-03 17:08:52.539 PST D (554349) cellular: tx-cmd: AT 2022-03-03 17:08:53.539 PST D (555349) cellular: tx-cmd: AT 2022-03-03 17:08:54.539 PST D (556349) cellular: tx-cmd: AT 2022-03-03 17:08:55.539 PST D (557349) cellular: tx-cmd: AT 2022-03-03 17:08:56.539 PST D (558349) cellular: tx-cmd: AT 2022-03-03 17:08:57.539 PST D (559349) cellular: tx-cmd: AT 2022-03-03 17:08:58.539 PST D (560349) cellular: tx-cmd: AT 2022-03-03 17:08:59.539 PST D (561349) cellular: tx-cmd: AT 2022-03-03 17:09:00.539 PST D (562349) cellular: tx-cmd: AT 2022-03-03 17:09:01.539 PST D (563349) cellular: tx-cmd: AT 2022-03-03 17:09:02.539 PST D (564349) cellular: tx-cmd: AT 2022-03-03 17:09:02.979 PST I (564789) cellular: State: Enter Identify state 2022-03-03 17:09:03.539 PST D (565349) cellular: tx-cmd: AT+CGMM 2022-03-03 17:09:03.549 PST I (565359) cellular: Identified cellular modem: SIM7600/Experimental support for SIMCOM SIM7600 2022-03-03 17:09:03.549 PST D (565359) cellular: Remove old 'auto' modem driver 2022-03-03 17:09:03.549 PST I (565359) cellular: Set modem driver to 'SIM7600' 2022-03-03 17:09:03.549 PST I (565359) cellular: State: Enter PoweredOn state 2022-03-03 17:09:13.539 PST D (575349) cellular: tx-cmd: AT+CPIN?;+CREG=1;+CTZU=1;+CTZR=1;+CLIP=1;+CMGF=1;+CNMI=1,2,0,0,0;+CSDH=1;+CMEE=2;+CSQ;+AUTOCSQ=1,1;E0;S0=0 2022-03-03 17:09:13.569 PST D (575379) cellular: mux-rx-line #0: AT+CPIN?;+CREG=1;+CTZU=1;+CTZR=1;+CLIP=1;+CMGF=1;+CNMI=1,2,0,0,0;+CSDH=1;+CMEE=2;+CSQ;+AUTOCSQ=1,1;E0;S0=0 2022-03-03 17:09:13.569 PST D (575379) cellular: mux-rx-line #0: +CPIN: READY 2022-03-03 17:09:13.569 PST D (575379) cellular: mux-rx-line #0: +CSQ: 13,99 2022-03-03 17:09:13.579 PST I (575389) cellular: Signal Quality is: 13 (-87 dBm) 2022-03-03 17:09:15.539 PST D (577349) cellular: tx-cmd: AT+CGMR;+ICCID 2022-03-03 17:09:15.559 PST D (577369) cellular: mux-rx-line #0: +CGMR: LE20B03SIM7600M21-A 2022-03-03 17:09:15.559 PST D (577369) cellular: mux-rx-line #0: +ICCID: 8944501805175416178 2022-03-03 17:09:23.539 PST D (585349) cellular: tx-cmd: AT+CMUX=0 2022-03-03 17:09:23.549 PST I (585359) cellular: State: Enter MuxStart state 2022-03-03 17:09:23.549 PST I (585359) gsm-mux: Start MUX 2022-03-03 17:09:23.559 PST I (585369) gsm-mux: Channel #0 is open 2022-03-03 17:09:23.569 PST I (585379) gsm-mux: Channel #1 is open 2022-03-03 17:09:23.579 PST I (585389) gsm-mux: Channel #2 is open 2022-03-03 17:09:23.589 PST I (585399) gsm-mux: Channel #3 is open 2022-03-03 17:09:23.599 PST I (585409) gsm-mux: Channel #4 is open 2022-03-03 17:09:24.539 PST D (586349) cellular: State transition MuxStart => NetWait 2022-03-03 17:09:24.539 PST I (586349) cellular: State: Enter NetWait state 2022-03-03 17:09:34.539 PST D (596349) cellular: mux-tx #3: AT+CREG?;+CCLK?;+CSQ;+COPS? 2022-03-03 17:09:34.569 PST D (596379) cellular: mux-rx-line #3: +CREG: 1,5 2022-03-03 17:09:34.569 PST I (596379) cellular: Network Registration status: RegisteredRoaming 2022-03-03 17:09:34.569 PST D (596379) cellular: mux-rx-line #3: +CCLK: "22/03/03,17:09:32-32" 2022-03-03 17:09:34.569 PST D (596379) cellular: mux-rx-line #3: +CSQ: 13,99 2022-03-03 17:09:34.569 PST D (596379) cellular: mux-rx-line #3: +COPS: 0,0,"AT&T Hologram",2 2022-03-03 17:09:34.569 PST I (596379) cellular: Network Provider is: AT&T Hologram 2022-03-03 17:09:35.539 PST D (597349) cellular: State transition NetWait => NetStart 2022-03-03 17:09:35.539 PST I (597349) cellular: State: Enter NetStart state 2022-03-03 17:09:40.549 PST I (602359) housekeeping: 2022-03-03 17:09:39 PST (RAM: 8b=78500-79076 32b=12344 SPI=3439196-3442228) 2022-03-03 17:09:48.539 PST I (610349) ovms-server-v2: Send MP-0 S78.0,M,65535,127.00,done,standard,164,138,17,0,0,140,7,4,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,1.00,0.0 2022-03-03 17:09:48.539 PST I (610349) ovms-server-v2: Send MP-0 D64,0,5,19,17,17,512,625508,0,95954,19,0,0,0,11.54,0,12.6,0,19,0,0 2022-03-03 17:09:48.549 PST I (610359) ovms-server-v2: Send MP-0 L37.346333,-122.037285,80,54,1,1,0.0,512,0,0.393,0,0,0,0,,0,0,0 2022-03-03 17:09:48.549 PST I (610359) ovms-server-v2: Send MP-0 F3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30),5YJRE11B181000033,30,0,TR1N,Revelstoke,-1,-1,OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600 2022-03-03 17:10:47.479 PST I (9639) command: OpenLogfile: now logging to file '/sd/crash.log' _______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev
Mark, Before installing the 4G modem onto my v3.1 main board I just switched the version tag from main to edge (because I thought that was what was needed to get the new 3.3 code) and then did "Flash from web". That resulted in the the 3.3.001-285. I have now flashed with the URL you suggested: http://api.openvehicles.com/firmware/ota/v3.2/edge/3.3.001.ovms3.bin The result was still the same crash: OVMS# boot Last boot was 56 second(s) ago Time at boot: 2022-03-03 22:10:40 PST This is reset #39 since last power cycle Detected boot reason: Crash (12/12) Reset reason: Task watchdog (6) Crash counters: 1 total, 0 early Last crash: abort() was called on core 0 Backtrace: 0x4008e676 0x4008e911 0x400e938c 0x40084152 Event: ticker.1@esp32wifi 0 secs WDT tasks: IDLE0 Version: 3.3.001/ota_0/edge (build idf v3.3.4-848-g1ff5e24b1 Nov 22 2021 09:58:29) -- Steve On Fri, 4 Mar 2022, Mark Webb-Johnson wrote:
Steve, Jeff,
I have noticed you running '3.3.001-285'. Can you try with the standard '3.3.001' that was released a while ago? You can get it from:
http://api.openvehicles.com/firmware/ota/v3.3/main/ovms3.bin <http://api.openvehicles.com/firmware/ota/v3.3/main/ovms3.bin>
or
http://api.openvehicles.com/firmware/ota/v3.2/edge/3.3.001.ovms3.bin <http://api.openvehicles.com/firmware/ota/v3.2/edge/3.3.001.ovms3.bin>
I wonder if something is broken in the latest edge?
P.S. I think that in general we may be confusing people here. The firmware/ota/<X> directory is for those version <X> mainboards. So /v3.1/, /v3.2/ or /v3.3/. The idea is that we can then have different build settings (sdkconfig) for different base hardware (in particular esp32 revision) and make improvements. At the moment v3.1 and v3.2 are symlinked together (on api.openvehicles.com <http://api.openvehicles.com/>) as ESP32 is the same.
Regards, Mark
On 4 Mar 2022, at 9:17 AM, Stephen Casner <casner@acm.org> wrote:
On Thu, 3 Mar 2022, Mark Webb-Johnson wrote:
Can you try to get a debug log for the cellular system?
Inline below. This is with cellular, gsm-mux and SIM7600 set to debug. Any other useful tags? Looks like it dies not long after entering NetStart state.
-- Steve
Anyone else got any ideas? A few users in USA reporting this, but we’ve got hundreds of users elsewhere now and I haven’t heard this from anyone else. Looking at the api.openvehicles.com <http://api.openvehicles.com/> server logs, there are three users showing this today. I am seeing: abort(),0,,0x4008e676 0x4008e911 0x400e938c 0x40084152 ,6,Task watchdog,,,0,IDLE0 abort(),0,,0x4008e676 0x4008e911 0x400e938c 0x40084152 ,6,Task watchdog,ticker.1,esp32wifi,0,IDLE0 abort(),0,,0x4008ddca 0x4008e065 0x400e9608 0x40084176 ,6,Task watchdog,,,0,IDLE0,OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600 @Steve can you try to get a debug log for the ‘gsm-ppp’ tag? That is the most complex part (with interactions with lwip tasks for tcp/ip), and most likely culprit. Regards, Mark.
On 4 Mar 2022, at 2:15 PM, Stephen Casner <casner@acm.org> wrote:
Mark,
Before installing the 4G modem onto my v3.1 main board I just switched the version tag from main to edge (because I thought that was what was needed to get the new 3.3 code) and then did "Flash from web". That resulted in the the 3.3.001-285.
I have now flashed with the URL you suggested:
http://api.openvehicles.com/firmware/ota/v3.2/edge/3.3.001.ovms3.bin
The result was still the same crash:
OVMS# boot Last boot was 56 second(s) ago Time at boot: 2022-03-03 22:10:40 PST This is reset #39 since last power cycle Detected boot reason: Crash (12/12) Reset reason: Task watchdog (6) Crash counters: 1 total, 0 early
Last crash: abort() was called on core 0 Backtrace: 0x4008e676 0x4008e911 0x400e938c 0x40084152 Event: ticker.1@esp32wifi 0 secs WDT tasks: IDLE0 Version: 3.3.001/ota_0/edge (build idf v3.3.4-848-g1ff5e24b1 Nov 22 2021 09:58:29)
-- Steve
On Fri, 4 Mar 2022, Mark Webb-Johnson wrote:
Steve, Jeff,
I have noticed you running '3.3.001-285'. Can you try with the standard '3.3.001' that was released a while ago? You can get it from:
http://api.openvehicles.com/firmware/ota/v3.3/main/ovms3.bin <http://api.openvehicles.com/firmware/ota/v3.3/main/ovms3.bin>
or
http://api.openvehicles.com/firmware/ota/v3.2/edge/3.3.001.ovms3.bin <http://api.openvehicles.com/firmware/ota/v3.2/edge/3.3.001.ovms3.bin>
I wonder if something is broken in the latest edge?
P.S. I think that in general we may be confusing people here. The firmware/ota/<X> directory is for those version <X> mainboards. So /v3.1/, /v3.2/ or /v3.3/. The idea is that we can then have different build settings (sdkconfig) for different base hardware (in particular esp32 revision) and make improvements. At the moment v3.1 and v3.2 are symlinked together (on api.openvehicles.com <http://api.openvehicles.com/>) as ESP32 is the same.
Regards, Mark
On 4 Mar 2022, at 9:17 AM, Stephen Casner <casner@acm.org> wrote:
On Thu, 3 Mar 2022, Mark Webb-Johnson wrote:
Can you try to get a debug log for the cellular system?
Inline below. This is with cellular, gsm-mux and SIM7600 set to debug. Any other useful tags? Looks like it dies not long after entering NetStart state.
-- Steve
OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev
On Fri, 4 Mar 2022, Mark Webb-Johnson wrote:
@Steve can you try to get a debug log for the 'gsm-ppp' tag? That is the most complex part (with interactions with lwip tasks for tcp/ip), and most likely culprit.
Included below, but there were no messages at all with tag gsm-ppp. Should it be something else? -- Steve 2022-03-03 23:03:15.217 PST I (3154617) cellular: Set modem driver to 'auto' 2022-03-03 23:03:15.217 PST I (3154617) cellular: State: Enter PowerOffOn state 2022-03-03 23:03:15.217 PST I (3154617) cellular-modem-auto: Power Cycle 2000ms 2022-03-03 23:03:17.937 PST D (3157337) cellular: State timeout PowerOffOn => PoweringOn 2022-03-03 23:03:17.937 PST I (3157337) cellular: State: Enter PoweringOn state 2022-03-03 23:03:17.937 PST I (3157337) cellular-modem-auto: Power Cycle 4000ms 2022-03-03 23:03:21.937 PST D (3161337) cellular: tx-cmd: AT 2022-03-03 23:03:21.937 PST D (3161337) cellular: tx-cmd: AT 2022-03-03 23:03:21.937 PST D (3161337) cellular: tx-cmd: AT 2022-03-03 23:03:21.937 PST D (3161337) cellular: tx-cmd: AT 2022-03-03 23:03:22.937 PST D (3162337) cellular: tx-cmd: AT 2022-03-03 23:03:23.937 PST D (3163337) cellular: tx-cmd: AT 2022-03-03 23:03:24.937 PST D (3164337) cellular: tx-cmd: AT 2022-03-03 23:03:25.937 PST D (3165337) cellular: tx-cmd: AT 2022-03-03 23:03:26.937 PST D (3166337) cellular: tx-cmd: AT 2022-03-03 23:03:27.937 PST D (3167337) cellular: tx-cmd: AT 2022-03-03 23:03:27.937 PST I (3167337) ovms-server-v2: Send MP-0 S78.0,M,65535,127.00,done,standard,164,138,17,0,0,140,7,4,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,1.00,0.0 2022-03-03 23:03:27.937 PST I (3167337) ovms-server-v2: Send MP-0 D64,0,5,19,17,17,512,625508,0,117153,19,0,0,0,11.5,0,12.6,0,19,0,0 2022-03-03 23:03:27.947 PST I (3167347) ovms-server-v2: Send MP-0 L37.346313,-122.037300,208,49,1,1,0.0,512,0,0.000,0,0,0,0,,0,0,0 2022-03-03 23:03:27.947 PST I (3167347) ovms-server-v2: Send MP-0 F3.3.001/ota_0/edge (build idf v3.3.4-848-g1ff5e24b1 Nov 22 2021 09:58:29),5YJRE11B181000033,29,1,TR1N,Revelstoke,-1,-1 2022-03-03 23:03:28.937 PST D (3168337) cellular: tx-cmd: AT 2022-03-03 23:03:29.937 PST D (3169337) cellular: tx-cmd: AT 2022-03-03 23:03:30.937 PST D (3170337) cellular: tx-cmd: AT 2022-03-03 23:03:31.937 PST D (3171337) cellular: tx-cmd: AT 2022-03-03 23:03:32.937 PST D (3172337) cellular: tx-cmd: AT 2022-03-03 23:03:32.977 PST I (3172377) cellular: State: Enter Identify state 2022-03-03 23:03:33.937 PST D (3173337) cellular: tx-cmd: AT+CGMM 2022-03-03 23:03:33.947 PST I (3173347) cellular: Identified cellular modem: SIM7600/Experimental support for SIMCOM SIM7600 2022-03-03 23:03:33.947 PST D (3173347) cellular: Remove old 'auto' modem driver 2022-03-03 23:03:33.947 PST I (3173347) cellular: Set modem driver to 'SIM7600' 2022-03-03 23:03:33.947 PST I (3173347) cellular: State: Enter PoweredOn state 2022-03-03 23:03:43.937 PST D (3183337) cellular: tx-cmd: AT+CPIN?;+CREG=1;+CTZU=1;+CTZR=1;+CLIP=1;+CMGF=1;+CNMI=1,2,0,0,0;+CSDH=1;+CMEE=2;+CSQ;+AUTOCSQ=1,1;E0;S0=0 2022-03-03 23:03:43.967 PST D (3183367) cellular: mux-rx-line #0: AT+CPIN?;+CREG=1;+CTZU=1;+CTZR=1;+CLIP=1;+CMGF=1;+CNMI=1,2,0,0,0;+CSDH=1;+CMEE=2;+CSQ;+AUTOCSQ=1,1;E0;S0=0 2022-03-03 23:03:43.967 PST D (3183367) cellular: mux-rx-line #0: +CPIN: READY 2022-03-03 23:03:43.967 PST D (3183367) cellular: mux-rx-line #0: +CSQ: 12,99 2022-03-03 23:03:43.967 PST I (3183367) cellular: Signal Quality is: 12 (-89 dBm) 2022-03-03 23:03:45.937 PST D (3185337) cellular: tx-cmd: AT+CGMR;+ICCID 2022-03-03 23:03:45.957 PST D (3185357) cellular: mux-rx-line #0: +CGMR: LE20B03SIM7600M21-A 2022-03-03 23:03:45.957 PST D (3185357) cellular: mux-rx-line #0: +ICCID: 8944501805175416178 2022-03-03 23:03:53.937 PST D (3193337) cellular: tx-cmd: AT+CMUX=0 2022-03-03 23:03:53.947 PST I (3193347) cellular: State: Enter MuxStart state 2022-03-03 23:03:53.947 PST I (3193347) gsm-mux: Start MUX 2022-03-03 23:03:53.957 PST I (3193357) gsm-mux: Channel #0 is open 2022-03-03 23:03:53.967 PST I (3193367) gsm-mux: Channel #1 is open 2022-03-03 23:03:53.977 PST I (3193377) gsm-mux: Channel #2 is open 2022-03-03 23:03:53.987 PST I (3193387) gsm-mux: Channel #3 is open 2022-03-03 23:03:53.997 PST I (3193397) gsm-mux: Channel #4 is open 2022-03-03 23:03:54.937 PST D (3194337) cellular: State transition MuxStart => NetWait 2022-03-03 23:03:54.937 PST I (3194337) cellular: State: Enter NetWait state 2022-03-03 23:04:04.937 PST D (3204337) cellular: mux-tx #3: AT+CREG?;+CCLK?;+CSQ;+COPS? 2022-03-03 23:04:04.967 PST D (3204367) cellular: mux-rx-line #3: +CREG: 1,5 2022-03-03 23:04:04.967 PST I (3204367) cellular: Network Registration status: RegisteredRoaming 2022-03-03 23:04:04.967 PST D (3204367) cellular: mux-rx-line #3: +CCLK: "22/03/03,23:04:02-32" 2022-03-03 23:04:04.967 PST D (3204367) cellular: mux-rx-line #3: +CSQ: 12,99 2022-03-03 23:04:04.967 PST D (3204367) cellular: mux-rx-line #3: +COPS: 0,0,"AT&T Hologram",2 2022-03-03 23:04:04.967 PST I (3204367) cellular: Network Provider is: AT&T Hologram 2022-03-03 23:05:15.687 PST I (8637) command: OpenLogfile: now logging to file '/sd/crash.log'
On 3/3/22 22:51, Mark Webb-Johnson wrote:
Anyone else got any ideas? A few users in USA reporting this, but we’ve got hundreds of users elsewhere now and I haven’t heard this from anyone else.
I've been playing around with the new v3.3 hardware I put in my Corvette. So far I haven't been able to crash it. I had been running my FreeBSD built 3.3.001-285-g601f2a70 but booted the v3.3 edge version about an hour ago. The things that pop out at me are that both Jeff and Stephen have roadsters and I think that means neither are using the simcom gps, right? Hah! I set my vehicle type to roadster and turned off gps and gps time and got a crash within a few minutes of rebooting. Craig
Well, that’s a hypothesis… Can you try a few more times, with gps on and off, to see if it is repeatable? Regards, Mark.
On 4 Mar 2022, at 3:18 PM, Craig Leres <leres@xse.com> wrote:
On 3/3/22 22:51, Mark Webb-Johnson wrote:
Anyone else got any ideas? A few users in USA reporting this, but we’ve got hundreds of users elsewhere now and I haven’t heard this from anyone else.
I've been playing around with the new v3.3 hardware I put in my Corvette. So far I haven't been able to crash it. I had been running my FreeBSD built 3.3.001-285-g601f2a70 but booted the v3.3 edge version about an hour ago.
The things that pop out at me are that both Jeff and Stephen have roadsters and I think that means neither are using the simcom gps, right? Hah! I set my vehicle type to roadster and turned off gps and gps time and got a crash within a few minutes of rebooting.
Craig
On 3/3/22 23:21, Mark Webb-Johnson wrote:
Well, that’s a hypothesis…
Can you try a few more times, with gps on and off, to see if it is repeatable?
I've seen at least 4 crashes, the most recently 2 with my FreeBSD built ovms-3.3.001-285-g601f2a70-dirty, vehicle set to C6 and the only difference from what I was using is GPS+GPS-time off. Looks like a watchdog timeout (last two crashes were the same). Craig ice 133 % ./backtrace.sh 0x400891af 0x40089449 0x400e8950 0x40083dde + xtensa-esp32-elf-addr2line -e build/ovms3.elf 0x400891af 0x40089449 0x400e8950 0x40083dde /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/task_wdt.c:274 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/freertos/xtensa_vectors.S:1154
I woke from sleep thinking "interrupt storm." Craig's observation makes me wonder... Does the gps system produce interrupts which are not handled properly when gps is turned off. Unhandled interrupts might get constantly repeated causing the IDLE tasks to starve? Jeff On 3/3/22 23:30, Craig Leres wrote:
On 3/3/22 23:21, Mark Webb-Johnson wrote:
Well, that’s a hypothesis…
Can you try a few more times, with gps on and off, to see if it is repeatable?
I've seen at least 4 crashes, the most recently 2 with my FreeBSD built ovms-3.3.001-285-g601f2a70-dirty, vehicle set to C6 and the only difference from what I was using is GPS+GPS-time off.
Looks like a watchdog timeout (last two crashes were the same).
Craig
ice 133 % ./backtrace.sh 0x400891af 0x40089449 0x400e8950 0x40083dde + xtensa-esp32-elf-addr2line -e build/ovms3.elf 0x400891af 0x40089449 0x400e8950 0x40083dde /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/task_wdt.c:274
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/freertos/xtensa_vectors.S:1154
_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev
On 3/3/22 23:18, Craig Leres wrote:
The things that pop out at me are that both Jeff and Stephen have roadsters and I think that means neither are using the simcom gps, right? Hah! I set my vehicle type to roadster and turned off gps and gps time and got a crash within a few minutes of rebooting.
I think gps off is the key; I put my vehicle type back to C6 and it still crashes within 3 minutes. Craig
Mark, there really seems to be some issue with -285. To help in tracking down release correlating issues I've just added another hourly developer report on my server: https://dexters-web.de/f/firmware/developer/crashreport-overview.csv That's basically the same source as… https://dexters-web.de/f/firmware/developer/crashreport.csv …just with reduced detail and more strict grouping. Regards, Michael crashreport.csv: SELECT LEFT(h_data, INSTR(h_data,'/')-1) AS firmware_version, SUBSTRING_INDEX(SUBSTRING_INDEX(m_msg, ',', 5), ',', -1) AS car_type, COUNT(DISTINCT c.vehicleid) AS vehicle_count, COUNT(*) AS crashtype_count, CONVERT_TZ(MAX(h_timestamp),'+00:00','SYSTEM') AS last_time, IF(LENGTH(h_data) - LENGTH(REPLACE(h_data, ',', '')) >= 12, SUBSTRING_INDEX(SUBSTRING_INDEX(h_data,',',13),',',-1), '') AS resetreason_name, SUBSTRING_INDEX(SUBSTRING_INDEX(h_data,',',8),',',-1) AS crashtype, SUBSTRING_INDEX(SUBSTRING_INDEX(h_data,',',9),',',-1) AS crashcore, IF(LENGTH(h_data) - LENGTH(REPLACE(h_data, ',', '')) >= 13, SUBSTRING_INDEX(SUBSTRING_INDEX(h_data,',',14),',',-1), '') AS curr_event_name, IF(LENGTH(h_data) - LENGTH(REPLACE(h_data, ',', '')) >= 13, SUBSTRING_INDEX(SUBSTRING_INDEX(h_data,',',15),',',-1), '') AS curr_event_handler, IF(LENGTH(h_data) - LENGTH(REPLACE(h_data, ',', '')) >= 13, SUBSTRING_INDEX(SUBSTRING_INDEX(h_data,',',16),',',-1), '') AS curr_event_runtime, IF(LENGTH(h_data) - LENGTH(REPLACE(h_data, ',', '')) >= 13, SUBSTRING_INDEX(SUBSTRING_INDEX(h_data,',',17),',',-1), '') AS wdt_tasknames, SUBSTRING_INDEX(SUBSTRING_INDEX(h_data,',',11),',',-1) AS backtrace, SUBSTRING_INDEX(SUBSTRING_INDEX(h_data,',',10),',',-1) AS registers, IF(LENGTH(h_data) - LENGTH(REPLACE(h_data, ',', '')) >= 17, SUBSTRING_INDEX(SUBSTRING_INDEX(h_data,',',18),',',-1), '') AS hardware_info FROM ovms_historicalmessages h JOIN ovms_carmessages c ON ( c.vehicleid = h.vehicleid AND m_code = 'F' ) WHERE h_recordtype = '*-OVM-DebugCrash' AND h_data LIKE '%build idf%' AND h_timestamp >= NOW() - INTERVAL 10 DAY GROUP BY firmware_version, car_type, resetreason_name, backtrace, curr_event_name, wdt_tasknames ORDER BY firmware_version, car_type, last_time crashreport-overview.csv: SELECT SUBSTRING_INDEX(SUBSTRING_INDEX(m_msg, ',', 5), ',', -1) AS car_type, LEFT(h_data, INSTR(h_data,'/')-1) AS firmware_version, IF(LENGTH(h_data) - LENGTH(REPLACE(h_data, ',', '')) >= 17, SUBSTRING_INDEX(SUBSTRING_INDEX(h_data,',',18),',',-1), '') AS hardware_info, IF(LENGTH(h_data) - LENGTH(REPLACE(h_data, ',', '')) >= 12, SUBSTRING_INDEX(SUBSTRING_INDEX(h_data,',',13),',',-1), '') AS resetreason_name, SUBSTRING_INDEX(SUBSTRING_INDEX(h_data,',',8),',',-1) AS crashtype, SUBSTRING_INDEX(SUBSTRING_INDEX(h_data,',',9),',',-1) AS crashcore, COUNT(DISTINCT c.vehicleid) AS vehicle_count, COUNT(*) AS crashtype_count, CONVERT_TZ(MAX(h_timestamp),'+00:00','SYSTEM') AS last_time FROM ovms_historicalmessages h JOIN ovms_carmessages c ON ( c.vehicleid = h.vehicleid AND m_code = 'F' ) WHERE h_recordtype = '*-OVM-DebugCrash' AND h_data LIKE '%build idf%' AND h_timestamp >= NOW() - INTERVAL 10 DAY GROUP BY car_type, firmware_version, hardware_info, resetreason_name, crashtype, crashcore ORDER BY car_type, firmware_version, hardware_info, resetreason_name, crashtype, crashcore Am 04.03.22 um 06:55 schrieb Mark Webb-Johnson:
Steve, Jeff,
I have noticed you running '3.3.001-285’. Can you try with the standard ‘3.3.001’ that was released a while ago? You can get it from:
http://api.openvehicles.com/firmware/ota/v3.3/main/ovms3.bin
or
http://api.openvehicles.com/firmware/ota/v3.2/edge/3.3.001.ovms3.bin
I wonder if something is broken in the latest edge?
P.S. I think that in general we may be confusing people here. The firmware/ota/<X> directory is for those version <X> mainboards. So /v3.1/, /v3.2/ or /v3.3/. The idea is that we can then have different build settings (sdkconfig) for different base hardware (in particular esp32 revision) and make improvements. At the moment v3.1 and v3.2 are symlinked together (on api.openvehicles.com <http://api.openvehicles.com>) as ESP32 is the same.
Regards, Mark
On 4 Mar 2022, at 9:17 AM, Stephen Casner <casner@acm.org> wrote:
On Thu, 3 Mar 2022, Mark Webb-Johnson wrote:
Can you try to get a debug log for the cellular system?
Inline below. This is with cellular, gsm-mux and SIM7600 set to debug. Any other useful tags? Looks like it dies not long after entering NetStart state.
-- Steve
2022-03-03 17:08:45.249 PST I (547059) cellular: Set modem driver to 'auto' 2022-03-03 17:08:45.249 PST I (547059) cellular: State: Enter PowerOffOn state 2022-03-03 17:08:45.249 PST I (547059) cellular-modem-auto: Power Cycle 2000ms 2022-03-03 17:08:47.539 PST D (549349) cellular: State timeout PowerOffOn => PoweringOn 2022-03-03 17:08:47.539 PST I (549349) cellular: State: Enter PoweringOn state 2022-03-03 17:08:47.539 PST I (549349) cellular-modem-auto: Power Cycle 4000ms 2022-03-03 17:08:51.539 PST D (553349) cellular: tx-cmd: AT 2022-03-03 17:08:51.539 PST D (553349) cellular: tx-cmd: AT 2022-03-03 17:08:51.539 PST D (553349) cellular: tx-cmd: AT 2022-03-03 17:08:51.539 PST D (553349) cellular: tx-cmd: AT 2022-03-03 17:08:52.539 PST D (554349) cellular: tx-cmd: AT 2022-03-03 17:08:53.539 PST D (555349) cellular: tx-cmd: AT 2022-03-03 17:08:54.539 PST D (556349) cellular: tx-cmd: AT 2022-03-03 17:08:55.539 PST D (557349) cellular: tx-cmd: AT 2022-03-03 17:08:56.539 PST D (558349) cellular: tx-cmd: AT 2022-03-03 17:08:57.539 PST D (559349) cellular: tx-cmd: AT 2022-03-03 17:08:58.539 PST D (560349) cellular: tx-cmd: AT 2022-03-03 17:08:59.539 PST D (561349) cellular: tx-cmd: AT 2022-03-03 17:09:00.539 PST D (562349) cellular: tx-cmd: AT 2022-03-03 17:09:01.539 PST D (563349) cellular: tx-cmd: AT 2022-03-03 17:09:02.539 PST D (564349) cellular: tx-cmd: AT 2022-03-03 17:09:02.979 PST I (564789) cellular: State: Enter Identify state 2022-03-03 17:09:03.539 PST D (565349) cellular: tx-cmd: AT+CGMM 2022-03-03 17:09:03.549 PST I (565359) cellular: Identified cellular modem: SIM7600/Experimental support for SIMCOM SIM7600 2022-03-03 17:09:03.549 PST D (565359) cellular: Remove old 'auto' modem driver 2022-03-03 17:09:03.549 PST I (565359) cellular: Set modem driver to 'SIM7600' 2022-03-03 17:09:03.549 PST I (565359) cellular: State: Enter PoweredOn state 2022-03-03 17:09:13.539 PST D (575349) cellular: tx-cmd: AT+CPIN?;+CREG=1;+CTZU=1;+CTZR=1;+CLIP=1;+CMGF=1;+CNMI=1,2,0,0,0;+CSDH=1;+CMEE=2;+CSQ;+AUTOCSQ=1,1;E0;S0=0 2022-03-03 17:09:13.569 PST D (575379) cellular: mux-rx-line #0: AT+CPIN?;+CREG=1;+CTZU=1;+CTZR=1;+CLIP=1;+CMGF=1;+CNMI=1,2,0,0,0;+CSDH=1;+CMEE=2;+CSQ;+AUTOCSQ=1,1;E0;S0=0 2022-03-03 17:09:13.569 PST D (575379) cellular: mux-rx-line #0: +CPIN: READY 2022-03-03 17:09:13.569 PST D (575379) cellular: mux-rx-line #0: +CSQ: 13,99 2022-03-03 17:09:13.579 PST I (575389) cellular: Signal Quality is: 13 (-87 dBm) 2022-03-03 17:09:15.539 PST D (577349) cellular: tx-cmd: AT+CGMR;+ICCID 2022-03-03 17:09:15.559 PST D (577369) cellular: mux-rx-line #0: +CGMR: LE20B03SIM7600M21-A 2022-03-03 17:09:15.559 PST D (577369) cellular: mux-rx-line #0: +ICCID: 8944501805175416178 2022-03-03 17:09:23.539 PST D (585349) cellular: tx-cmd: AT+CMUX=0 2022-03-03 17:09:23.549 PST I (585359) cellular: State: Enter MuxStart state 2022-03-03 17:09:23.549 PST I (585359) gsm-mux: Start MUX 2022-03-03 17:09:23.559 PST I (585369) gsm-mux: Channel #0 is open 2022-03-03 17:09:23.569 PST I (585379) gsm-mux: Channel #1 is open 2022-03-03 17:09:23.579 PST I (585389) gsm-mux: Channel #2 is open 2022-03-03 17:09:23.589 PST I (585399) gsm-mux: Channel #3 is open 2022-03-03 17:09:23.599 PST I (585409) gsm-mux: Channel #4 is open 2022-03-03 17:09:24.539 PST D (586349) cellular: State transition MuxStart => NetWait 2022-03-03 17:09:24.539 PST I (586349) cellular: State: Enter NetWait state 2022-03-03 17:09:34.539 PST D (596349) cellular: mux-tx #3: AT+CREG?;+CCLK?;+CSQ;+COPS? 2022-03-03 17:09:34.569 PST D (596379) cellular: mux-rx-line #3: +CREG: 1,5 2022-03-03 17:09:34.569 PST I (596379) cellular: Network Registration status: RegisteredRoaming 2022-03-03 17:09:34.569 PST D (596379) cellular: mux-rx-line #3: +CCLK: "22/03/03,17:09:32-32" 2022-03-03 17:09:34.569 PST D (596379) cellular: mux-rx-line #3: +CSQ: 13,99 2022-03-03 17:09:34.569 PST D (596379) cellular: mux-rx-line #3: +COPS: 0,0,"AT&T Hologram",2 2022-03-03 17:09:34.569 PST I (596379) cellular: Network Provider is: AT&T Hologram 2022-03-03 17:09:35.539 PST D (597349) cellular: State transition NetWait => NetStart 2022-03-03 17:09:35.539 PST I (597349) cellular: State: Enter NetStart state 2022-03-03 17:09:40.549 PST I (602359) housekeeping: 2022-03-03 17:09:39 PST (RAM: 8b=78500-79076 32b=12344 SPI=3439196-3442228) 2022-03-03 17:09:48.539 PST I (610349) ovms-server-v2: Send MP-0 S78.0,M,65535,127.00,done,standard,164,138,17,0,0,140,7,4,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,1.00,0.0 2022-03-03 17:09:48.539 PST I (610349) ovms-server-v2: Send MP-0 D64,0,5,19,17,17,512,625508,0,95954,19,0,0,0,11.54,0,12.6,0,19,0,0 2022-03-03 17:09:48.549 PST I (610359) ovms-server-v2: Send MP-0 L37.346333,-122.037285,80,54,1,1,0.0,512,0,0.393,0,0,0,0,,0,0,0 2022-03-03 17:09:48.549 PST I (610359) ovms-server-v2: Send MP-0 F3.3.001-285-g601f2a70/ota_1/edge (build idf v3.3.4-848-g1ff5e24b1 Feb 20 2022 00:04:30),5YJRE11B181000033,30,0,TR1N,Revelstoke,-1,-1,OVMS WIFI BLE BT cores=2 rev=ESP32/1; MODEM SIM7600 2022-03-03 17:10:47.479 PST I (9639) command: OpenLogfile: now logging to file '/sd/crash.log' _______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev
_______________________________________________ OvmsDev mailing list OvmsDev@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
On 3/3/22 21:55, Mark Webb-Johnson wrote:
Steve, Jeff,
I have noticed you running '3.3.001-285’. Can you try with the standard ‘3.3.001’ that was released a while ago? You can get it from:
http://api.openvehicles.com/firmware/ota/v3.3/main/ovms3.bin
or
http://api.openvehicles.com/firmware/ota/v3.2/edge/3.3.001.ovms3.bin
I wonder if something is broken in the latest edge?
P.S. I think that in general we may be confusing people here. The firmware/ota/<X> directory is for those version <X> mainboards. So /v3.1/, /v3.2/ or /v3.3/. The idea is that we can then have different build settings (sdkconfig) for different base hardware (in particular esp32 revision) and make improvements. At the moment v3.1 and v3.2 are symlinked together (on api.openvehicles.com <http://api.openvehicles.com>) as ESP32 is the same.
Regards, Mark
So I've tried every combination.... GPS off always crashes with all versions I've tried. Version/Build w/o GPS w/ GPS 3.3.001-285-g601f2a70/ota_0/main (build idf v3.3.4-848-g1ff5e24b1) (edge) crash PPP comes up 3.3.001/ota_1/main (build idf v3.3.4-848-g1ff5e24b1) (above link v3.3/main/ovms3.bin) crash/slow to connect/crash PPP comes up factory/main/3.3.001-33-g58d01654 crash PPP comes up Jeff
Craig, thanks for the diagnosis. I've just tried the experiment of turning on GPS for OVMS in my Roadster with no antenna attached. As in the tests Jeff just reported, that appears to avoid the crash. Since the Roadster has its own GPS, I'm not sure what effects will result from enabling the modem GPS. -- Steve
One more data point; I turned GPS off on my dev module (v3.1 board with a sim7600A running 3.3.001-285-g601f2a70-dirty) and it started crashing. Has anyone outside the US tried this? Craig ice 12 % ./backtrace.sh 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 + xtensa-esp32-elf-addr2line -e build/ovms3.elf 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/task_wdt.c:274 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/freertos/xtensa_vectors.S:1154 # esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c 733 734 void _esp_error_check_failed_without_abort(esp_err_t rc, const char *file, int line, const char *function, const char *expression) 735 { 736 esp_error_check_failed_print("ESP_ERROR_CHECK_WITHOUT_ABORT", rc, file, line, function, expression); 737 }
I've tried to reproduce this with my old 3.2 & hand soldered 3.3 dev module, with different vehicle modules and modem GPS disabled. Results: - the vehicle module is irrelevant - 3.2 (SIM5360E) runs without issues (had this running over night) - 3.3 (SIM7600G) consistently crashes by the TWDT within a couple of minutes after modem init This is caused by the modem task hogging core 0 as soon as the PPP connection is up: I (87161) cellular: Identified cellular modem: SIM7600/Experimental support for SIMCOM SIM7600 D (87161) cellular: Remove old 'auto' modem driver I (87161) cellular: Set modem driver to 'SIM7600' I (87161) cellular: State: Enter PoweredOn state OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 188 0 524288 1 5 0% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80136 0 79300 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 98% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 97% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1404 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1040 1 18 0% 18/ 0 *3FFD34E0 20 Blk OVMS Cellular 652 2396 4096 5848 0 0 0 20 0% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 848 2688 10240 356 12100 15960 1 5 1% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0 … I (118171) cellular: Network Registration status: RegisteredRoaming D (118181) cellular: mux-rx-line #3: +CCLK: "22/03/05,08:22:23+04" D (118181) cellular: mux-rx-line #3: +CSQ: 24,0 D (118181) cellular: mux-rx-line #3: +COPS: 0,0,"vodafone.de Hologram",0 I (118181) cellular: Network Provider is: vodafone.de Hologram D (119151) cellular: State transition NetWait => NetStart I (119151) cellular: State: Enter NetStart state D (120151) cellular: Netstart AT+CGDCONT=1,"IP","hologram";+CGDATA="PPP",1 V (120191) gsm-mux: ProcessFrame(CHAN=0, ADDR=01, CTRL=ef, FCS=79, LEN=11) V (120201) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=fb, LEN=24) D (120201) cellular: mux-rx-line #2: CONNECT 115200 *I (120201) cellular: PPP Connection is ready to start* V (120751) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 284 0 524308 1 5 1% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80280 0 79680 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 79% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 95% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1452 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1044 1 18 0% 18/ 0 *3FFD34E0 20 Rdy OVMS Cellular 876 2716 4096 6116 0 10440 0 20 19% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 848 2688 10240 356 12100 15960 1 5 3% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0 I (122161) housekeeping: System considered stable (RAM: 8b=64256-64760 32b=184 SPI=3362168-3374964) D (122231) ovms-duktape: Duktape: Compacting DukTape memory done in 60 ms I (123151) ovms-server-v2: Send MP-0 h1,0,*-OVM-DebugCrash,0,2592000,3.3.001-285-g601f2a70/factory/edge (build idf v3.3.4-848-g1ff5e24b1b Feb 22 2022 20:57:41),1,EarlyCrash,12,12,1,1,abort(),0,,0x4008ddca 0x4008e06 5 0x400e88b8 0x40084176 ,6,Task watchdog,,,0,IDLE0,OVMS WIFI BLE BT cores=2 rev=ESP32/3; MODEM SIM7600 I (123361) ovms-server-v2: Incoming Msg: MP-0 h1 OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 188 0 524288 1 5 0% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80136 0 79300 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 0% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 95% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1452 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1044 1 18 0% 18/ 0 *3FFD34E0 20 Rdy OVMS Cellular 876 2716 4096 6116 0 10440 0 20 98% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 880 2688 10240 356 12100 15960 1 5 4% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0 … OVMS# E (181151) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time: E (181151) task_wdt: - IDLE0 (CPU 0) E (181151) task_wdt: Tasks currently running: E (181151) task_wdt: CPU 0: Tmr Svc E (181151) task_wdt: CPU 1: IDLE1 E (181151) task_wdt: Aborting. No other log messages. Am 04.03.22 um 17:08 schrieb Jeff Anton:
I woke from sleep thinking "interrupt storm."
Craig's observation makes me wonder... Does the gps system produce interrupts which are not handled properly when gps is turned off. Unhandled interrupts might get constantly repeated causing the IDLE tasks to starve?
I think that may be the case. Maybe the NMEA MUX channel gets continuous input from the 7600 when GPS is disabled? Regards, Michael Am 04.03.22 um 23:15 schrieb Craig Leres:
One more data point; I turned GPS off on my dev module (v3.1 board with a sim7600A running 3.3.001-285-g601f2a70-dirty) and it started crashing.
Has anyone outside the US tried this?
Craig
ice 12 % ./backtrace.sh 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 + xtensa-esp32-elf-addr2line -e build/ovms3.elf 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/task_wdt.c:274
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/freertos/xtensa_vectors.S:1154
# esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c 733 734 void _esp_error_check_failed_without_abort(esp_err_t rc, const char *file, int line, const char *function, const char *expression) 735 { 736 esp_error_check_failed_print("ESP_ERROR_CHECK_WITHOUT_ABORT", rc, file, line, function, expression); 737 }
_______________________________________________ OvmsDev mailing list OvmsDev@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
Another theory: I found Mark's comment in the SIM7600 driver NMEA startup: // We need to do this a little differently from the standard, as SIM7600 // may start GPS on power up, and doesn't like us using CGPS=1,1 when // it is already on. So workaround is to first CGPS=0. IOW, the SIM7600 may have GPS enabled by default, possibly also sending NMEA sentences, if not explicitly switched off. BTW, that also explains the difficulties in booting a 3.3 module from USB… :-/ a) We don't switch off GPS if GPS is disabled. b) I just tried switching off GPS manually after a GPS-enabled startup, and the modem still continued to send NMEA sentences: OVMS# cellular cmd AT+CGPS=0 MODEM command has been sent. … D (475190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 V (475190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=c1, LEN=31) V (475190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=cc, LEN=31) V (475190) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=60, LEN=32) D (475190) gsm-nmea: Incoming GNS: $GNGNS,,,,,,NNN,,,,,,*1D V (475190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=25, LEN=32) V (475190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=28, LEN=32) V (480180) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=84, LEN=31) D (480190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 … OVMS# cellular cmd AT+CGPSNMEA=0 MODEM command has been sent. D (505190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 V (505190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=c1, LEN=31) V (505190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=cc, LEN=31) V (505190) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=60, LEN=32) D (505190) gsm-nmea: Incoming GNS: $GNGNS,,,,,,NNN,,,,,,*1D V (505190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=25, LEN=32) V (505190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=28, LEN=32) V (510180) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=84, LEN=31) D (510190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 … So without us starting the NMEA subsystem, is it possible these transmissions are still there, filling up some MUX buffer? Regards, Michael Am 05.03.22 um 08:33 schrieb Michael Balzer:
I've tried to reproduce this with my old 3.2 & hand soldered 3.3 dev module, with different vehicle modules and modem GPS disabled.
Results: - the vehicle module is irrelevant - 3.2 (SIM5360E) runs without issues (had this running over night) - 3.3 (SIM7600G) consistently crashes by the TWDT within a couple of minutes after modem init
This is caused by the modem task hogging core 0 as soon as the PPP connection is up:
I (87161) cellular: Identified cellular modem: SIM7600/Experimental support for SIMCOM SIM7600 D (87161) cellular: Remove old 'auto' modem driver I (87161) cellular: Set modem driver to 'SIM7600' I (87161) cellular: State: Enter PoweredOn state OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 188 0 524288 1 5 0% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80136 0 79300 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 98% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 97% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1404 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1040 1 18 0% 18/ 0 *3FFD34E0 20 Blk OVMS Cellular 652 2396 4096 5848 0 0 0 20 0% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 848 2688 10240 356 12100 15960 1 5 1% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0
…
I (118171) cellular: Network Registration status: RegisteredRoaming D (118181) cellular: mux-rx-line #3: +CCLK: "22/03/05,08:22:23+04" D (118181) cellular: mux-rx-line #3: +CSQ: 24,0 D (118181) cellular: mux-rx-line #3: +COPS: 0,0,"vodafone.de Hologram",0 I (118181) cellular: Network Provider is: vodafone.de Hologram D (119151) cellular: State transition NetWait => NetStart I (119151) cellular: State: Enter NetStart state D (120151) cellular: Netstart AT+CGDCONT=1,"IP","hologram";+CGDATA="PPP",1 V (120191) gsm-mux: ProcessFrame(CHAN=0, ADDR=01, CTRL=ef, FCS=79, LEN=11) V (120201) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=fb, LEN=24) D (120201) cellular: mux-rx-line #2: CONNECT 115200 *I (120201) cellular: PPP Connection is ready to start* V (120751) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 284 0 524308 1 5 1% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80280 0 79680 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 79% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 95% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1452 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1044 1 18 0% 18/ 0 *3FFD34E0 20 Rdy OVMS Cellular 876 2716 4096 6116 0 10440 0 20 19% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 848 2688 10240 356 12100 15960 1 5 3% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0 I (122161) housekeeping: System considered stable (RAM: 8b=64256-64760 32b=184 SPI=3362168-3374964) D (122231) ovms-duktape: Duktape: Compacting DukTape memory done in 60 ms I (123151) ovms-server-v2: Send MP-0 h1,0,*-OVM-DebugCrash,0,2592000,3.3.001-285-g601f2a70/factory/edge (build idf v3.3.4-848-g1ff5e24b1b Feb 22 2022 20:57:41),1,EarlyCrash,12,12,1,1,abort(),0,,0x4008ddca 0x4008e06 5 0x400e88b8 0x40084176 ,6,Task watchdog,,,0,IDLE0,OVMS WIFI BLE BT cores=2 rev=ESP32/3; MODEM SIM7600 I (123361) ovms-server-v2: Incoming Msg: MP-0 h1 OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 188 0 524288 1 5 0% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80136 0 79300 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 0% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 95% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1452 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1044 1 18 0% 18/ 0 *3FFD34E0 20 Rdy OVMS Cellular 876 2716 4096 6116 0 10440 0 20 98% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 880 2688 10240 356 12100 15960 1 5 4% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0
…
OVMS# E (181151) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time: E (181151) task_wdt: - IDLE0 (CPU 0) E (181151) task_wdt: Tasks currently running: E (181151) task_wdt: CPU 0: Tmr Svc E (181151) task_wdt: CPU 1: IDLE1 E (181151) task_wdt: Aborting.
No other log messages.
Am 04.03.22 um 17:08 schrieb Jeff Anton:
I woke from sleep thinking "interrupt storm."
Craig's observation makes me wonder... Does the gps system produce interrupts which are not handled properly when gps is turned off. Unhandled interrupts might get constantly repeated causing the IDLE tasks to starve?
I think that may be the case. Maybe the NMEA MUX channel gets continuous input from the 7600 when GPS is disabled?
Regards, Michael
Am 04.03.22 um 23:15 schrieb Craig Leres:
One more data point; I turned GPS off on my dev module (v3.1 board with a sim7600A running 3.3.001-285-g601f2a70-dirty) and it started crashing.
Has anyone outside the US tried this?
Craig
ice 12 % ./backtrace.sh 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 + xtensa-esp32-elf-addr2line -e build/ovms3.elf 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/task_wdt.c:274
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/freertos/xtensa_vectors.S:1154
# esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c 733 734 void _esp_error_check_failed_without_abort(esp_err_t rc, const char *file, int line, const char *function, const char *expression) 735 { 736 esp_error_check_failed_print("ESP_ERROR_CHECK_WITHOUT_ABORT", rc, file, line, function, expression); 737 }
_______________________________________________ OvmsDev mailing list OvmsDev@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@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
I've now tried starting the NMEA channel without actually sending any GPS init commands (also no +CGPS=0). That inhibits the crashes, although apparently no NMEA sentences are coming in. The only communication on MUX channel 1 (NMEA) are some initial frames: balzer@leela:~/ovms/v3> grep -A1 CHAN=1 minicom.log V (26168) gsm-mux: ProcessFrame(CHAN=1, ADDR=07, CTRL=73, FCS=15, LEN=6) I (26168) gsm-mux: Channel #1 is open -- V (32568) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) V (32568) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=d1, LEN=20) -- V (32938) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (32938) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=32, LEN=21) -- V (36948) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) V (36948) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=d1, LEN=20) -- V (38968) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (38968) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=32, LEN=21) -- V (42638) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (42638) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f0, LEN=21) -- V (44988) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (44988) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f0, LEN=21) Unrelated to this issue, but possibly to the framing errors: I've also removed the NMEA log filter from modem::StandardLineHandler() and found after normal GPS startup, the NMEA sentences always come in three times via three MUX channels – additionally to channel 1 on channels 3 & 4: V (130148) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=bf, LEN=78) D (130148) gsm-nmea: Incoming RMC: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130158) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=fa, LEN=78) D (130158) cellular: mux-rx-line #3: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130158) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=f7, LEN=78) D (130158) cellular: mux-rx-line #4: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130168) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b1, LEN=82) D (130168) gsm-nmea: Incoming GNS: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60 V (130178) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f4, LEN=82) D (130178) cellular: mux-rx-line #3: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60 V (130178) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=f9, LEN=82) D (130178) cellular: mux-rx-line #4: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60 I don't know if that's intended behaviour or can be changed, but I suspect this to add unnecessary load to the serial communication. Regards, Michael Am 05.03.22 um 09:02 schrieb Michael Balzer:
Another theory: I found Mark's comment in the SIM7600 driver NMEA startup:
// We need to do this a little differently from the standard, as SIM7600 // may start GPS on power up, and doesn't like us using CGPS=1,1 when // it is already on. So workaround is to first CGPS=0.
IOW, the SIM7600 may have GPS enabled by default, possibly also sending NMEA sentences, if not explicitly switched off.
BTW, that also explains the difficulties in booting a 3.3 module from USB… :-/
a) We don't switch off GPS if GPS is disabled.
b) I just tried switching off GPS manually after a GPS-enabled startup, and the modem still continued to send NMEA sentences:
OVMS# cellular cmd AT+CGPS=0 MODEM command has been sent. … D (475190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 V (475190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=c1, LEN=31) V (475190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=cc, LEN=31) V (475190) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=60, LEN=32) D (475190) gsm-nmea: Incoming GNS: $GNGNS,,,,,,NNN,,,,,,*1D V (475190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=25, LEN=32) V (475190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=28, LEN=32) V (480180) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=84, LEN=31) D (480190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 … OVMS# cellular cmd AT+CGPSNMEA=0 MODEM command has been sent. D (505190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 V (505190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=c1, LEN=31) V (505190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=cc, LEN=31) V (505190) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=60, LEN=32) D (505190) gsm-nmea: Incoming GNS: $GNGNS,,,,,,NNN,,,,,,*1D V (505190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=25, LEN=32) V (505190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=28, LEN=32) V (510180) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=84, LEN=31) D (510190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 …
So without us starting the NMEA subsystem, is it possible these transmissions are still there, filling up some MUX buffer?
Regards, Michael
Am 05.03.22 um 08:33 schrieb Michael Balzer:
I've tried to reproduce this with my old 3.2 & hand soldered 3.3 dev module, with different vehicle modules and modem GPS disabled.
Results: - the vehicle module is irrelevant - 3.2 (SIM5360E) runs without issues (had this running over night) - 3.3 (SIM7600G) consistently crashes by the TWDT within a couple of minutes after modem init
This is caused by the modem task hogging core 0 as soon as the PPP connection is up:
I (87161) cellular: Identified cellular modem: SIM7600/Experimental support for SIMCOM SIM7600 D (87161) cellular: Remove old 'auto' modem driver I (87161) cellular: Set modem driver to 'SIM7600' I (87161) cellular: State: Enter PoweredOn state OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 188 0 524288 1 5 0% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80136 0 79300 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 98% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 97% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1404 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1040 1 18 0% 18/ 0 *3FFD34E0 20 Blk OVMS Cellular 652 2396 4096 5848 0 0 0 20 0% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 848 2688 10240 356 12100 15960 1 5 1% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0
…
I (118171) cellular: Network Registration status: RegisteredRoaming D (118181) cellular: mux-rx-line #3: +CCLK: "22/03/05,08:22:23+04" D (118181) cellular: mux-rx-line #3: +CSQ: 24,0 D (118181) cellular: mux-rx-line #3: +COPS: 0,0,"vodafone.de Hologram",0 I (118181) cellular: Network Provider is: vodafone.de Hologram D (119151) cellular: State transition NetWait => NetStart I (119151) cellular: State: Enter NetStart state D (120151) cellular: Netstart AT+CGDCONT=1,"IP","hologram";+CGDATA="PPP",1 V (120191) gsm-mux: ProcessFrame(CHAN=0, ADDR=01, CTRL=ef, FCS=79, LEN=11) V (120201) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=fb, LEN=24) D (120201) cellular: mux-rx-line #2: CONNECT 115200 *I (120201) cellular: PPP Connection is ready to start* V (120751) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 284 0 524308 1 5 1% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80280 0 79680 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 79% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 95% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1452 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1044 1 18 0% 18/ 0 *3FFD34E0 20 Rdy OVMS Cellular 876 2716 4096 6116 0 10440 0 20 19% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 848 2688 10240 356 12100 15960 1 5 3% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0 I (122161) housekeeping: System considered stable (RAM: 8b=64256-64760 32b=184 SPI=3362168-3374964) D (122231) ovms-duktape: Duktape: Compacting DukTape memory done in 60 ms I (123151) ovms-server-v2: Send MP-0 h1,0,*-OVM-DebugCrash,0,2592000,3.3.001-285-g601f2a70/factory/edge (build idf v3.3.4-848-g1ff5e24b1b Feb 22 2022 20:57:41),1,EarlyCrash,12,12,1,1,abort(),0,,0x4008ddca 0x4008e06 5 0x400e88b8 0x40084176 ,6,Task watchdog,,,0,IDLE0,OVMS WIFI BLE BT cores=2 rev=ESP32/3; MODEM SIM7600 I (123361) ovms-server-v2: Incoming Msg: MP-0 h1 OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 188 0 524288 1 5 0% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80136 0 79300 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 0% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 95% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1452 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1044 1 18 0% 18/ 0 *3FFD34E0 20 Rdy OVMS Cellular 876 2716 4096 6116 0 10440 0 20 98% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 880 2688 10240 356 12100 15960 1 5 4% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0
…
OVMS# E (181151) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time: E (181151) task_wdt: - IDLE0 (CPU 0) E (181151) task_wdt: Tasks currently running: E (181151) task_wdt: CPU 0: Tmr Svc E (181151) task_wdt: CPU 1: IDLE1 E (181151) task_wdt: Aborting.
No other log messages.
Am 04.03.22 um 17:08 schrieb Jeff Anton:
I woke from sleep thinking "interrupt storm."
Craig's observation makes me wonder... Does the gps system produce interrupts which are not handled properly when gps is turned off. Unhandled interrupts might get constantly repeated causing the IDLE tasks to starve?
I think that may be the case. Maybe the NMEA MUX channel gets continuous input from the 7600 when GPS is disabled?
Regards, Michael
Am 04.03.22 um 23:15 schrieb Craig Leres:
One more data point; I turned GPS off on my dev module (v3.1 board with a sim7600A running 3.3.001-285-g601f2a70-dirty) and it started crashing.
Has anyone outside the US tried this?
Craig
ice 12 % ./backtrace.sh 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 + xtensa-esp32-elf-addr2line -e build/ovms3.elf 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/task_wdt.c:274
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/freertos/xtensa_vectors.S:1154
# esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c 733 734 void _esp_error_check_failed_without_abort(esp_err_t rc, const char *file, int line, const char *function, const char *expression) 735 { 736 esp_error_check_failed_print("ESP_ERROR_CHECK_WITHOUT_ABORT", rc, file, line, function, expression); 737 }
_______________________________________________ OvmsDev mailing list OvmsDev@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@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@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
I've found & fixed the bug: there was an endless loop in modem::IncomingMuxData() when the NMEA channel had not been created. → https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/commit/a6e5... Regards, Michael Am 05.03.22 um 11:21 schrieb Michael Balzer:
I've now tried starting the NMEA channel without actually sending any GPS init commands (also no +CGPS=0).
That inhibits the crashes, although apparently no NMEA sentences are coming in. The only communication on MUX channel 1 (NMEA) are some initial frames:
balzer@leela:~/ovms/v3> grep -A1 CHAN=1 minicom.log V (26168) gsm-mux: ProcessFrame(CHAN=1, ADDR=07, CTRL=73, FCS=15, LEN=6) I (26168) gsm-mux: Channel #1 is open -- V (32568) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) V (32568) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=d1, LEN=20) -- V (32938) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (32938) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=32, LEN=21) -- V (36948) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) V (36948) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=d1, LEN=20) -- V (38968) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (38968) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=32, LEN=21) -- V (42638) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (42638) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f0, LEN=21) -- V (44988) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (44988) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f0, LEN=21)
Unrelated to this issue, but possibly to the framing errors: I've also removed the NMEA log filter from modem::StandardLineHandler() and found after normal GPS startup, the NMEA sentences always come in three times via three MUX channels – additionally to channel 1 on channels 3 & 4:
V (130148) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=bf, LEN=78) D (130148) gsm-nmea: Incoming RMC: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130158) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=fa, LEN=78) D (130158) cellular: mux-rx-line #3: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130158) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=f7, LEN=78) D (130158) cellular: mux-rx-line #4: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130168) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b1, LEN=82) D (130168) gsm-nmea: Incoming GNS: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60 V (130178) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f4, LEN=82) D (130178) cellular: mux-rx-line #3: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60 V (130178) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=f9, LEN=82) D (130178) cellular: mux-rx-line #4: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60
I don't know if that's intended behaviour or can be changed, but I suspect this to add unnecessary load to the serial communication.
Regards, Michael
Am 05.03.22 um 09:02 schrieb Michael Balzer:
Another theory: I found Mark's comment in the SIM7600 driver NMEA startup:
// We need to do this a little differently from the standard, as SIM7600 // may start GPS on power up, and doesn't like us using CGPS=1,1 when // it is already on. So workaround is to first CGPS=0.
IOW, the SIM7600 may have GPS enabled by default, possibly also sending NMEA sentences, if not explicitly switched off.
BTW, that also explains the difficulties in booting a 3.3 module from USB… :-/
a) We don't switch off GPS if GPS is disabled.
b) I just tried switching off GPS manually after a GPS-enabled startup, and the modem still continued to send NMEA sentences:
OVMS# cellular cmd AT+CGPS=0 MODEM command has been sent. … D (475190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 V (475190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=c1, LEN=31) V (475190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=cc, LEN=31) V (475190) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=60, LEN=32) D (475190) gsm-nmea: Incoming GNS: $GNGNS,,,,,,NNN,,,,,,*1D V (475190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=25, LEN=32) V (475190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=28, LEN=32) V (480180) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=84, LEN=31) D (480190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 … OVMS# cellular cmd AT+CGPSNMEA=0 MODEM command has been sent. D (505190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 V (505190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=c1, LEN=31) V (505190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=cc, LEN=31) V (505190) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=60, LEN=32) D (505190) gsm-nmea: Incoming GNS: $GNGNS,,,,,,NNN,,,,,,*1D V (505190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=25, LEN=32) V (505190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=28, LEN=32) V (510180) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=84, LEN=31) D (510190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 …
So without us starting the NMEA subsystem, is it possible these transmissions are still there, filling up some MUX buffer?
Regards, Michael
Am 05.03.22 um 08:33 schrieb Michael Balzer:
I've tried to reproduce this with my old 3.2 & hand soldered 3.3 dev module, with different vehicle modules and modem GPS disabled.
Results: - the vehicle module is irrelevant - 3.2 (SIM5360E) runs without issues (had this running over night) - 3.3 (SIM7600G) consistently crashes by the TWDT within a couple of minutes after modem init
This is caused by the modem task hogging core 0 as soon as the PPP connection is up:
I (87161) cellular: Identified cellular modem: SIM7600/Experimental support for SIMCOM SIM7600 D (87161) cellular: Remove old 'auto' modem driver I (87161) cellular: Set modem driver to 'SIM7600' I (87161) cellular: State: Enter PoweredOn state OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 188 0 524288 1 5 0% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80136 0 79300 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 98% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 97% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1404 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1040 1 18 0% 18/ 0 *3FFD34E0 20 Blk OVMS Cellular 652 2396 4096 5848 0 0 0 20 0% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 848 2688 10240 356 12100 15960 1 5 1% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0
…
I (118171) cellular: Network Registration status: RegisteredRoaming D (118181) cellular: mux-rx-line #3: +CCLK: "22/03/05,08:22:23+04" D (118181) cellular: mux-rx-line #3: +CSQ: 24,0 D (118181) cellular: mux-rx-line #3: +COPS: 0,0,"vodafone.de Hologram",0 I (118181) cellular: Network Provider is: vodafone.de Hologram D (119151) cellular: State transition NetWait => NetStart I (119151) cellular: State: Enter NetStart state D (120151) cellular: Netstart AT+CGDCONT=1,"IP","hologram";+CGDATA="PPP",1 V (120191) gsm-mux: ProcessFrame(CHAN=0, ADDR=01, CTRL=ef, FCS=79, LEN=11) V (120201) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=fb, LEN=24) D (120201) cellular: mux-rx-line #2: CONNECT 115200 *I (120201) cellular: PPP Connection is ready to start* V (120751) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 284 0 524308 1 5 1% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80280 0 79680 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 79% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 95% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1452 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1044 1 18 0% 18/ 0 *3FFD34E0 20 Rdy OVMS Cellular 876 2716 4096 6116 0 10440 0 20 19% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 848 2688 10240 356 12100 15960 1 5 3% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0 I (122161) housekeeping: System considered stable (RAM: 8b=64256-64760 32b=184 SPI=3362168-3374964) D (122231) ovms-duktape: Duktape: Compacting DukTape memory done in 60 ms I (123151) ovms-server-v2: Send MP-0 h1,0,*-OVM-DebugCrash,0,2592000,3.3.001-285-g601f2a70/factory/edge (build idf v3.3.4-848-g1ff5e24b1b Feb 22 2022 20:57:41),1,EarlyCrash,12,12,1,1,abort(),0,,0x4008ddca 0x4008e06 5 0x400e88b8 0x40084176 ,6,Task watchdog,,,0,IDLE0,OVMS WIFI BLE BT cores=2 rev=ESP32/3; MODEM SIM7600 I (123361) ovms-server-v2: Incoming Msg: MP-0 h1 OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 188 0 524288 1 5 0% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80136 0 79300 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 0% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 95% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1452 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1044 1 18 0% 18/ 0 *3FFD34E0 20 Rdy OVMS Cellular 876 2716 4096 6116 0 10440 0 20 98% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 880 2688 10240 356 12100 15960 1 5 4% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0
…
OVMS# E (181151) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time: E (181151) task_wdt: - IDLE0 (CPU 0) E (181151) task_wdt: Tasks currently running: E (181151) task_wdt: CPU 0: Tmr Svc E (181151) task_wdt: CPU 1: IDLE1 E (181151) task_wdt: Aborting.
No other log messages.
Am 04.03.22 um 17:08 schrieb Jeff Anton:
I woke from sleep thinking "interrupt storm."
Craig's observation makes me wonder... Does the gps system produce interrupts which are not handled properly when gps is turned off. Unhandled interrupts might get constantly repeated causing the IDLE tasks to starve?
I think that may be the case. Maybe the NMEA MUX channel gets continuous input from the 7600 when GPS is disabled?
Regards, Michael
Am 04.03.22 um 23:15 schrieb Craig Leres:
One more data point; I turned GPS off on my dev module (v3.1 board with a sim7600A running 3.3.001-285-g601f2a70-dirty) and it started crashing.
Has anyone outside the US tried this?
Craig
ice 12 % ./backtrace.sh 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 + xtensa-esp32-elf-addr2line -e build/ovms3.elf 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/task_wdt.c:274
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/freertos/xtensa_vectors.S:1154
# esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c 733 734 void _esp_error_check_failed_without_abort(esp_err_t rc, const char *file, int line, const char *function, const char *expression) 735 { 736 esp_error_check_failed_print("ESP_ERROR_CHECK_WITHOUT_ABORT", rc, file, line, function, expression); 737 }
_______________________________________________ OvmsDev mailing list OvmsDev@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@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@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@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
Nice catch. I had reviewed that code section this afternoon, but missed it. Shall we make a 3.3.002 and push it to EAP? Regards, Mark
On 6 Mar 2022, at 5:58 PM, Michael Balzer <dexter@expeedo.de> wrote:
I've found & fixed the bug: there was an endless loop in modem::IncomingMuxData() when the NMEA channel had not been created.
→ https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/commit/a6e5...
Regards, Michael
Am 05.03.22 um 11:21 schrieb Michael Balzer:
I've now tried starting the NMEA channel without actually sending any GPS init commands (also no +CGPS=0).
That inhibits the crashes, although apparently no NMEA sentences are coming in. The only communication on MUX channel 1 (NMEA) are some initial frames:
balzer@leela:~/ovms/v3> grep -A1 CHAN=1 minicom.log V (26168) gsm-mux: ProcessFrame(CHAN=1, ADDR=07, CTRL=73, FCS=15, LEN=6) I (26168) gsm-mux: Channel #1 is open -- V (32568) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) V (32568) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=d1, LEN=20) -- V (32938) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (32938) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=32, LEN=21) -- V (36948) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) V (36948) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=d1, LEN=20) -- V (38968) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (38968) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=32, LEN=21) -- V (42638) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (42638) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f0, LEN=21) -- V (44988) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (44988) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f0, LEN=21)
Unrelated to this issue, but possibly to the framing errors: I've also removed the NMEA log filter from modem::StandardLineHandler() and found after normal GPS startup, the NMEA sentences always come in three times via three MUX channels – additionally to channel 1 on channels 3 & 4:
V (130148) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=bf, LEN=78) D (130148) gsm-nmea: Incoming RMC: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130158) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=fa, LEN=78) D (130158) cellular: mux-rx-line #3: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130158) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=f7, LEN=78) D (130158) cellular: mux-rx-line #4: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130168) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b1, LEN=82) D (130168) gsm-nmea: Incoming GNS: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60 V (130178) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f4, LEN=82) D (130178) cellular: mux-rx-line #3: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60 V (130178) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=f9, LEN=82) D (130178) cellular: mux-rx-line #4: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60
I don't know if that's intended behaviour or can be changed, but I suspect this to add unnecessary load to the serial communication.
Regards, Michael
Am 05.03.22 um 09:02 schrieb Michael Balzer:
Another theory: I found Mark's comment in the SIM7600 driver NMEA startup:
// We need to do this a little differently from the standard, as SIM7600 // may start GPS on power up, and doesn't like us using CGPS=1,1 when // it is already on. So workaround is to first CGPS=0.
IOW, the SIM7600 may have GPS enabled by default, possibly also sending NMEA sentences, if not explicitly switched off.
BTW, that also explains the difficulties in booting a 3.3 module from USB… :-/
a) We don't switch off GPS if GPS is disabled.
b) I just tried switching off GPS manually after a GPS-enabled startup, and the modem still continued to send NMEA sentences:
OVMS# cellular cmd AT+CGPS=0 MODEM command has been sent. … D (475190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 V (475190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=c1, LEN=31) V (475190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=cc, LEN=31) V (475190) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=60, LEN=32) D (475190) gsm-nmea: Incoming GNS: $GNGNS,,,,,,NNN,,,,,,*1D V (475190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=25, LEN=32) V (475190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=28, LEN=32) V (480180) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=84, LEN=31) D (480190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 … OVMS# cellular cmd AT+CGPSNMEA=0 MODEM command has been sent. D (505190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 V (505190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=c1, LEN=31) V (505190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=cc, LEN=31) V (505190) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=60, LEN=32) D (505190) gsm-nmea: Incoming GNS: $GNGNS,,,,,,NNN,,,,,,*1D V (505190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=25, LEN=32) V (505190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=28, LEN=32) V (510180) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=84, LEN=31) D (510190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 …
So without us starting the NMEA subsystem, is it possible these transmissions are still there, filling up some MUX buffer?
Regards, Michael
Am 05.03.22 um 08:33 schrieb Michael Balzer:
I've tried to reproduce this with my old 3.2 & hand soldered 3.3 dev module, with different vehicle modules and modem GPS disabled.
Results: - the vehicle module is irrelevant - 3.2 (SIM5360E) runs without issues (had this running over night) - 3.3 (SIM7600G) consistently crashes by the TWDT within a couple of minutes after modem init
This is caused by the modem task hogging core 0 as soon as the PPP connection is up:
I (87161) cellular: Identified cellular modem: SIM7600/Experimental support for SIMCOM SIM7600 D (87161) cellular: Remove old 'auto' modem driver I (87161) cellular: Set modem driver to 'SIM7600' I (87161) cellular: State: Enter PoweredOn state OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 188 0 524288 1 5 0% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80136 0 79300 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 98% 0/ 0 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 97% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1404 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1040 1 18 0% 18/ 0 3FFD34E0 20 Blk OVMS Cellular 652 2396 4096 5848 0 0 0 20 0% 20/ 0 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 848 2688 10240 356 12100 15960 1 5 1% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0
…
I (118171) cellular: Network Registration status: RegisteredRoaming D (118181) cellular: mux-rx-line #3: +CCLK: "22/03/05,08:22:23+04" D (118181) cellular: mux-rx-line #3: +CSQ: 24,0 D (118181) cellular: mux-rx-line #3: +COPS: 0,0,"vodafone.de Hologram",0 I (118181) cellular: Network Provider is: vodafone.de Hologram D (119151) cellular: State transition NetWait => NetStart I (119151) cellular: State: Enter NetStart state D (120151) cellular: Netstart AT+CGDCONT=1,"IP","hologram";+CGDATA="PPP",1 V (120191) gsm-mux: ProcessFrame(CHAN=0, ADDR=01, CTRL=ef, FCS=79, LEN=11) V (120201) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=fb, LEN=24) D (120201) cellular: mux-rx-line #2: CONNECT 115200 I (120201) cellular: PPP Connection is ready to start V (120751) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 284 0 524308 1 5 1% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80280 0 79680 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 79% 0/ 0 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 95% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1452 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1044 1 18 0% 18/ 0 3FFD34E0 20 Rdy OVMS Cellular 876 2716 4096 6116 0 10440 0 20 19% 20/ 0 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 848 2688 10240 356 12100 15960 1 5 3% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0 I (122161) housekeeping: System considered stable (RAM: 8b=64256-64760 32b=184 SPI=3362168-3374964) D (122231) ovms-duktape: Duktape: Compacting DukTape memory done in 60 ms I (123151) ovms-server-v2: Send MP-0 h1,0,*-OVM-DebugCrash,0,2592000,3.3.001-285-g601f2a70/factory/edge (build idf v3.3.4-848-g1ff5e24b1b Feb 22 2022 20:57:41),1,EarlyCrash,12,12,1,1,abort(),0,,0x4008ddca 0x4008e06 5 0x400e88b8 0x40084176 ,6,Task watchdog,,,0,IDLE0,OVMS WIFI BLE BT cores=2 rev=ESP32/3; MODEM SIM7600 I (123361) ovms-server-v2: Incoming Msg: MP-0 h1 OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 188 0 524288 1 5 0% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80136 0 79300 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 0% 0/ 0 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 95% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1452 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1044 1 18 0% 18/ 0 3FFD34E0 20 Rdy OVMS Cellular 876 2716 4096 6116 0 10440 0 20 98% 20/ 0 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 880 2688 10240 356 12100 15960 1 5 4% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0
…
OVMS# E (181151) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time: E (181151) task_wdt: - IDLE0 (CPU 0) E (181151) task_wdt: Tasks currently running: E (181151) task_wdt: CPU 0: Tmr Svc E (181151) task_wdt: CPU 1: IDLE1 E (181151) task_wdt: Aborting.
No other log messages.
Am 04.03.22 um 17:08 schrieb Jeff Anton:
I woke from sleep thinking "interrupt storm."
Craig's observation makes me wonder... Does the gps system produce interrupts which are not handled properly when gps is turned off. Unhandled interrupts might get constantly repeated causing the IDLE tasks to starve?
I think that may be the case. Maybe the NMEA MUX channel gets continuous input from the 7600 when GPS is disabled?
Regards, Michael
Am 04.03.22 um 23:15 schrieb Craig Leres:
One more data point; I turned GPS off on my dev module (v3.1 board with a sim7600A running 3.3.001-285-g601f2a70-dirty) and it started crashing.
Has anyone outside the US tried this?
Craig
ice 12 % ./backtrace.sh 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 + xtensa-esp32-elf-addr2line -e build/ovms3.elf 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/task_wdt.c:274 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/freertos/xtensa_vectors.S:1154
# esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c 733 734 void _esp_error_check_failed_without_abort(esp_err_t rc, const char *file, int line, const char *function, const char *expression) 735 { 736 esp_error_check_failed_print("ESP_ERROR_CHECK_WITHOUT_ABORT", rc, file, line, function, expression); 737 }
_______________________________________________ OvmsDev mailing list OvmsDev@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@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@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@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@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev
Yes. Regards, Michael Am 06.03.22 um 15:28 schrieb Mark Webb-Johnson:
Nice catch. I had reviewed that code section this afternoon, but missed it.
Shall we make a 3.3.002 and push it to EAP?
Regards, Mark
On 6 Mar 2022, at 5:58 PM, Michael Balzer <dexter@expeedo.de> wrote:
I've found & fixed the bug: there was an endless loop in modem::IncomingMuxData() when the NMEA channel had not been created.
→ https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/commit/a6e5...
Regards, Michael
Am 05.03.22 um 11:21 schrieb Michael Balzer:
I've now tried starting the NMEA channel without actually sending any GPS init commands (also no +CGPS=0).
That inhibits the crashes, although apparently no NMEA sentences are coming in. The only communication on MUX channel 1 (NMEA) are some initial frames:
balzer@leela:~/ovms/v3> grep -A1 CHAN=1 minicom.log V (26168) gsm-mux: ProcessFrame(CHAN=1, ADDR=07, CTRL=73, FCS=15, LEN=6) I (26168) gsm-mux: Channel #1 is open -- V (32568) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) V (32568) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=d1, LEN=20) -- V (32938) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (32938) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=32, LEN=21) -- V (36948) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) V (36948) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=d1, LEN=20) -- V (38968) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (38968) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=32, LEN=21) -- V (42638) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (42638) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f0, LEN=21) -- V (44988) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (44988) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f0, LEN=21)
Unrelated to this issue, but possibly to the framing errors: I've also removed the NMEA log filter from modem::StandardLineHandler() and found after normal GPS startup, the NMEA sentences always come in three times via three MUX channels – additionally to channel 1 on channels 3 & 4:
V (130148) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=bf, LEN=78) D (130148) gsm-nmea: Incoming RMC: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130158) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=fa, LEN=78) D (130158) cellular: mux-rx-line #3: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130158) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=f7, LEN=78) D (130158) cellular: mux-rx-line #4: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130168) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b1, LEN=82) D (130168) gsm-nmea: Incoming GNS: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60 V (130178) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f4, LEN=82) D (130178) cellular: mux-rx-line #3: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60 V (130178) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=f9, LEN=82) D (130178) cellular: mux-rx-line #4: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60
I don't know if that's intended behaviour or can be changed, but I suspect this to add unnecessary load to the serial communication.
Regards, Michael
Am 05.03.22 um 09:02 schrieb Michael Balzer:
Another theory: I found Mark's comment in the SIM7600 driver NMEA startup:
// We need to do this a little differently from the standard, as SIM7600 // may start GPS on power up, and doesn't like us using CGPS=1,1 when // it is already on. So workaround is to first CGPS=0.
IOW, the SIM7600 may have GPS enabled by default, possibly also sending NMEA sentences, if not explicitly switched off.
BTW, that also explains the difficulties in booting a 3.3 module from USB… :-/
a) We don't switch off GPS if GPS is disabled.
b) I just tried switching off GPS manually after a GPS-enabled startup, and the modem still continued to send NMEA sentences:
OVMS# cellular cmd AT+CGPS=0 MODEM command has been sent. … D (475190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 V (475190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=c1, LEN=31) V (475190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=cc, LEN=31) V (475190) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=60, LEN=32) D (475190) gsm-nmea: Incoming GNS: $GNGNS,,,,,,NNN,,,,,,*1D V (475190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=25, LEN=32) V (475190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=28, LEN=32) V (480180) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=84, LEN=31) D (480190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 … OVMS# cellular cmd AT+CGPSNMEA=0 MODEM command has been sent. D (505190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 V (505190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=c1, LEN=31) V (505190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=cc, LEN=31) V (505190) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=60, LEN=32) D (505190) gsm-nmea: Incoming GNS: $GNGNS,,,,,,NNN,,,,,,*1D V (505190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=25, LEN=32) V (505190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=28, LEN=32) V (510180) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=84, LEN=31) D (510190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 …
So without us starting the NMEA subsystem, is it possible these transmissions are still there, filling up some MUX buffer?
Regards, Michael
Am 05.03.22 um 08:33 schrieb Michael Balzer:
I've tried to reproduce this with my old 3.2 & hand soldered 3.3 dev module, with different vehicle modules and modem GPS disabled.
Results: - the vehicle module is irrelevant - 3.2 (SIM5360E) runs without issues (had this running over night) - 3.3 (SIM7600G) consistently crashes by the TWDT within a couple of minutes after modem init
This is caused by the modem task hogging core 0 as soon as the PPP connection is up:
I (87161) cellular: Identified cellular modem: SIM7600/Experimental support for SIMCOM SIM7600 D (87161) cellular: Remove old 'auto' modem driver I (87161) cellular: Set modem driver to 'SIM7600' I (87161) cellular: State: Enter PoweredOn state OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 188 0 524288 1 5 0% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80136 0 79300 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 98% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 97% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1404 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1040 1 18 0% 18/ 0 *3FFD34E0 20 Blk OVMS Cellular 652 2396 4096 5848 0 0 0 20 0% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 848 2688 10240 356 12100 15960 1 5 1% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0
…
I (118171) cellular: Network Registration status: RegisteredRoaming D (118181) cellular: mux-rx-line #3: +CCLK: "22/03/05,08:22:23+04" D (118181) cellular: mux-rx-line #3: +CSQ: 24,0 D (118181) cellular: mux-rx-line #3: +COPS: 0,0,"vodafone.de Hologram",0 I (118181) cellular: Network Provider is: vodafone.de Hologram D (119151) cellular: State transition NetWait => NetStart I (119151) cellular: State: Enter NetStart state D (120151) cellular: Netstart AT+CGDCONT=1,"IP","hologram";+CGDATA="PPP",1 V (120191) gsm-mux: ProcessFrame(CHAN=0, ADDR=01, CTRL=ef, FCS=79, LEN=11) V (120201) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=fb, LEN=24) D (120201) cellular: mux-rx-line #2: CONNECT 115200 *I (120201) cellular: PPP Connection is ready to start* V (120751) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 284 0 524308 1 5 1% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80280 0 79680 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 79% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 95% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1452 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1044 1 18 0% 18/ 0 *3FFD34E0 20 Rdy OVMS Cellular 876 2716 4096 6116 0 10440 0 20 19% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 848 2688 10240 356 12100 15960 1 5 3% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0 I (122161) housekeeping: System considered stable (RAM: 8b=64256-64760 32b=184 SPI=3362168-3374964) D (122231) ovms-duktape: Duktape: Compacting DukTape memory done in 60 ms I (123151) ovms-server-v2: Send MP-0 h1,0,*-OVM-DebugCrash,0,2592000,3.3.001-285-g601f2a70/factory/edge (build idf v3.3.4-848-g1ff5e24b1b Feb 22 2022 20:57:41),1,EarlyCrash,12,12,1,1,abort(),0,,0x4008ddca 0x4008e06 5 0x400e88b8 0x40084176 ,6,Task watchdog,,,0,IDLE0,OVMS WIFI BLE BT cores=2 rev=ESP32/3; MODEM SIM7600 I (123361) ovms-server-v2: Incoming Msg: MP-0 h1 OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 188 0 524288 1 5 0% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80136 0 79300 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 0% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 95% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1452 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1044 1 18 0% 18/ 0 *3FFD34E0 20 Rdy OVMS Cellular 876 2716 4096 6116 0 10440 0 20 98% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 880 2688 10240 356 12100 15960 1 5 4% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0
…
OVMS# E (181151) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time: E (181151) task_wdt: - IDLE0 (CPU 0) E (181151) task_wdt: Tasks currently running: E (181151) task_wdt: CPU 0: Tmr Svc E (181151) task_wdt: CPU 1: IDLE1 E (181151) task_wdt: Aborting.
No other log messages.
Am 04.03.22 um 17:08 schrieb Jeff Anton:
I woke from sleep thinking "interrupt storm."
Craig's observation makes me wonder... Does the gps system produce interrupts which are not handled properly when gps is turned off. Unhandled interrupts might get constantly repeated causing the IDLE tasks to starve?
I think that may be the case. Maybe the NMEA MUX channel gets continuous input from the 7600 when GPS is disabled?
Regards, Michael
Am 04.03.22 um 23:15 schrieb Craig Leres:
One more data point; I turned GPS off on my dev module (v3.1 board with a sim7600A running 3.3.001-285-g601f2a70-dirty) and it started crashing.
Has anyone outside the US tried this?
Craig
ice 12 % ./backtrace.sh 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 + xtensa-esp32-elf-addr2line -e build/ovms3.elf 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/task_wdt.c:274
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/freertos/xtensa_vectors.S:1154
# esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c 733 734 void _esp_error_check_failed_without_abort(esp_err_t rc, const char *file, int line, const char *function, const char *expression) 735 { 736 esp_error_check_failed_print("ESP_ERROR_CHECK_WITHOUT_ABORT", rc, file, line, function, expression); 737 }
_______________________________________________ OvmsDev mailing list OvmsDev@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@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@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@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@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev
_______________________________________________ OvmsDev mailing list OvmsDev@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
I flashed edge just now and it's working on my Roadster w/o GPS! Firmware: 3.3.001-286-ga6e5b9ab/ota_1/main (build idf v3.3.4-848-g1ff5e24b1 Mar 7 2022 00:04:15) MODEM Status Model: SIM7600 Network Registration: RegisteredRoaming Provider: T-Mobile Hologram Signal: -85 dBm Mode: State: NetMode Mux: Status up PPP: Connected on channel: #2 GPS: Not running On 3/6/22 01:58, Michael Balzer wrote:
I've found & fixed the bug: there was an endless loop in modem::IncomingMuxData() when the NMEA channel had not been created.
→ https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/commit/a6e5...
Regards, Michael
Am 05.03.22 um 11:21 schrieb Michael Balzer:
I've now tried starting the NMEA channel without actually sending any GPS init commands (also no +CGPS=0).
That inhibits the crashes, although apparently no NMEA sentences are coming in. The only communication on MUX channel 1 (NMEA) are some initial frames:
balzer@leela:~/ovms/v3> grep -A1 CHAN=1 minicom.log V (26168) gsm-mux: ProcessFrame(CHAN=1, ADDR=07, CTRL=73, FCS=15, LEN=6) I (26168) gsm-mux: Channel #1 is open -- V (32568) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) V (32568) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=d1, LEN=20) -- V (32938) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (32938) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=32, LEN=21) -- V (36948) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) V (36948) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=d1, LEN=20) -- V (38968) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (38968) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=32, LEN=21) -- V (42638) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (42638) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f0, LEN=21) -- V (44988) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b5, LEN=21) V (44988) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f0, LEN=21)
Unrelated to this issue, but possibly to the framing errors: I've also removed the NMEA log filter from modem::StandardLineHandler() and found after normal GPS startup, the NMEA sentences always come in three times via three MUX channels – additionally to channel 1 on channels 3 & 4:
V (130148) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=bf, LEN=78) D (130148) gsm-nmea: Incoming RMC: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130158) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=fa, LEN=78) D (130158) cellular: mux-rx-line #3: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130158) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=f7, LEN=78) D (130158) cellular: mux-rx-line #4: $GPRMC,095314.00,A,xxxx.139928,N,xxxx.391626,E,0.0,,050322,0.9,W,A*06 V (130168) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=b1, LEN=82) D (130168) gsm-nmea: Incoming GNS: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60 V (130178) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=f4, LEN=82) D (130178) cellular: mux-rx-line #3: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60 V (130178) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=f9, LEN=82) D (130178) cellular: mux-rx-line #4: $GNGNS,095314.00,xxxx.139928,N,xxxx.391626,E,AAN,16,0.7,327.9,47.0,,,V*60
I don't know if that's intended behaviour or can be changed, but I suspect this to add unnecessary load to the serial communication.
Regards, Michael
Am 05.03.22 um 09:02 schrieb Michael Balzer:
Another theory: I found Mark's comment in the SIM7600 driver NMEA startup:
// We need to do this a little differently from the standard, as SIM7600 // may start GPS on power up, and doesn't like us using CGPS=1,1 when // it is already on. So workaround is to first CGPS=0.
IOW, the SIM7600 may have GPS enabled by default, possibly also sending NMEA sentences, if not explicitly switched off.
BTW, that also explains the difficulties in booting a 3.3 module from USB… :-/
a) We don't switch off GPS if GPS is disabled.
b) I just tried switching off GPS manually after a GPS-enabled startup, and the modem still continued to send NMEA sentences:
OVMS# cellular cmd AT+CGPS=0 MODEM command has been sent. … D (475190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 V (475190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=c1, LEN=31) V (475190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=cc, LEN=31) V (475190) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=60, LEN=32) D (475190) gsm-nmea: Incoming GNS: $GNGNS,,,,,,NNN,,,,,,*1D V (475190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=25, LEN=32) V (475190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=28, LEN=32) V (480180) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=84, LEN=31) D (480190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 … OVMS# cellular cmd AT+CGPSNMEA=0 MODEM command has been sent. D (505190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 V (505190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=c1, LEN=31) V (505190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=cc, LEN=31) V (505190) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=60, LEN=32) D (505190) gsm-nmea: Incoming GNS: $GNGNS,,,,,,NNN,,,,,,*1D V (505190) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=25, LEN=32) V (505190) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=28, LEN=32) V (510180) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=84, LEN=31) D (510190) gsm-nmea: Incoming RMC: $GPRMC,,V,,,,,,,,,,N*53 …
So without us starting the NMEA subsystem, is it possible these transmissions are still there, filling up some MUX buffer?
Regards, Michael
Am 05.03.22 um 08:33 schrieb Michael Balzer:
I've tried to reproduce this with my old 3.2 & hand soldered 3.3 dev module, with different vehicle modules and modem GPS disabled.
Results: - the vehicle module is irrelevant - 3.2 (SIM5360E) runs without issues (had this running over night) - 3.3 (SIM7600G) consistently crashes by the TWDT within a couple of minutes after modem init
This is caused by the modem task hogging core 0 as soon as the PPP connection is up:
I (87161) cellular: Identified cellular modem: SIM7600/Experimental support for SIMCOM SIM7600 D (87161) cellular: Remove old 'auto' modem driver I (87161) cellular: Set modem driver to 'SIM7600' I (87161) cellular: State: Enter PoweredOn state OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 188 0 524288 1 5 0% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80136 0 79300 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 98% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 97% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1404 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1040 1 18 0% 18/ 0 *3FFD34E0 20 Blk OVMS Cellular 652 2396 4096 5848 0 0 0 20 0% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 848 2688 10240 356 12100 15960 1 5 1% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0
…
I (118171) cellular: Network Registration status: RegisteredRoaming D (118181) cellular: mux-rx-line #3: +CCLK: "22/03/05,08:22:23+04" D (118181) cellular: mux-rx-line #3: +CSQ: 24,0 D (118181) cellular: mux-rx-line #3: +COPS: 0,0,"vodafone.de Hologram",0 I (118181) cellular: Network Provider is: vodafone.de Hologram D (119151) cellular: State transition NetWait => NetStart I (119151) cellular: State: Enter NetStart state D (120151) cellular: Netstart AT+CGDCONT=1,"IP","hologram";+CGDATA="PPP",1 V (120191) gsm-mux: ProcessFrame(CHAN=0, ADDR=01, CTRL=ef, FCS=79, LEN=11) V (120201) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=fb, LEN=24) D (120201) cellular: mux-rx-line #2: CONNECT 115200 *I (120201) cellular: PPP Connection is ready to start* V (120751) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff, FCS=56, LEN=20) OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 284 0 524308 1 5 1% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80280 0 79680 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 79% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 95% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1452 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1044 1 18 0% 18/ 0 *3FFD34E0 20 Rdy OVMS Cellular 876 2716 4096 6116 0 10440 0 20 19% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 848 2688 10240 356 12100 15960 1 5 3% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0 I (122161) housekeeping: System considered stable (RAM: 8b=64256-64760 32b=184 SPI=3362168-3374964) D (122231) ovms-duktape: Duktape: Compacting DukTape memory done in 60 ms I (123151) ovms-server-v2: Send MP-0 h1,0,*-OVM-DebugCrash,0,2592000,3.3.001-285-g601f2a70/factory/edge (build idf v3.3.4-848-g1ff5e24b1b Feb 22 2022 20:57:41),1,EarlyCrash,12,12,1,1,abort(),0,,0x4008ddca 0x4008e06 5 0x400e88b8 0x40084176 ,6,Task watchdog,,,0,IDLE0,OVMS WIFI BLE BT cores=2 rev=ESP32/3; MODEM SIM7600 I (123361) ovms-server-v2: Incoming Msg: MP-0 h1 OVMS# mo ta Number of Tasks = 18 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU% BPR/MH 3FFAFB88 1 Blk esp_timer 436 708 4096 41648 644 44544 0 22 0% 22/ 0 3FFC2BD8 2 Blk OVMS DukTape 500 9252 12288 188 0 524288 1 5 0% 5/ 0 3FFC46B4 3 Blk eventTask 480 2032 4608 108 0 0 0 20 0% 20/ 0 3FFC6B38 4 Blk OVMS Events 484 3204 8192 80136 0 79300 1 8 1% 8/ 0 3FFC9C30 5 Blk OVMS CanRx 476 1996 4096 3240 0 50556 0 23 0% 23/ 0 3FFCAA2C 6 Blk ipc0 424 504 1024 7804 0 0 0 24 0% 24/ 0 3FFCB030 7 Blk ipc1 428 524 1024 120 0 0 1 24 0% 24/ 0 *3FFCCEA0 10 Rdy IDLE0 412 508 1024 0 0 0 0 0 0% 0/ 0* 3FFCD438 11 Rdy IDLE1 404 580 1024 0 0 0 1 0 95% 0/ 0 3FFCE1D0 12 Blk Tmr Svc 380 1452 3072 124 0 0 0 20 0% 20/ 0 3FFCC308 17 Blk tiT 532 2036 3072 924 0 1044 1 18 0% 18/ 0 *3FFD34E0 20 Rdy OVMS Cellular 876 2716 4096 6116 0 10440 0 20 98% 20/ 0* 3FFD656C 21 Blk wifi 472 2840 3584 38080 0 5632 0 22 1% 22/ 1 3FFE3244 22 Blk OVMS Vehicle 496 496 8192 0 0 0 1 10 0% 10/ 0 3FFE7BD4 23 Rdy OVMS Console 880 2688 10240 356 12100 15960 1 5 4% 5/ 1 3FFEA5A0 24 Blk OVMS NetMan 908 2684 10240 832 0 2152 1 5 0% 5/ 0 3FFEBBDC 25 Blk mdns 504 2200 4096 104 0 4 0 1 0% 1/ 0 3FFEFDC8 26 Blk OVMS FileLog 580 1524 3072 36 0 0 1 2 0% 2/ 0
…
OVMS# E (181151) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time: E (181151) task_wdt: - IDLE0 (CPU 0) E (181151) task_wdt: Tasks currently running: E (181151) task_wdt: CPU 0: Tmr Svc E (181151) task_wdt: CPU 1: IDLE1 E (181151) task_wdt: Aborting.
No other log messages.
Am 04.03.22 um 17:08 schrieb Jeff Anton:
I woke from sleep thinking "interrupt storm."
Craig's observation makes me wonder... Does the gps system produce interrupts which are not handled properly when gps is turned off. Unhandled interrupts might get constantly repeated causing the IDLE tasks to starve?
I think that may be the case. Maybe the NMEA MUX channel gets continuous input from the 7600 when GPS is disabled?
Regards, Michael
Am 04.03.22 um 23:15 schrieb Craig Leres:
One more data point; I turned GPS off on my dev module (v3.1 board with a sim7600A running 3.3.001-285-g601f2a70-dirty) and it started crashing.
Has anyone outside the US tried this?
Craig
ice 12 % ./backtrace.sh 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 + xtensa-esp32-elf-addr2line -e build/ovms3.elf 0x400891af:0x3ffb0690 0x40089449:0x3ffb06b0 0x400e8950:0x3ffb06d0 0x40083dde:0x3ffb06f0 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/task_wdt.c:274
/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/freertos/xtensa_vectors.S:1154
# esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c 733 734 void _esp_error_check_failed_without_abort(esp_err_t rc, const char *file, int line, const char *function, const char *expression) 735 { 736 esp_error_check_failed_print("ESP_ERROR_CHECK_WITHOUT_ABORT", rc, file, line, function, expression); 737 }
_______________________________________________ OvmsDev mailing list OvmsDev@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@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@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@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@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev
participants (5)
-
Craig Leres -
Jeff Anton -
Mark Webb-Johnson -
Michael Balzer -
Stephen Casner