Modem looses connection to cellular provider, (shutting down hard...)

Hi!

This is my first post here, So I thought I should go in swinging with a large one

First of all, I would like to express that I'm very greatful for such a wonderful product, the OVMS really tickle my inner nerd in a good way.

So, the reason for this post, is actually to share a pattern that I found during another fault finding activity that I had together with Michael over at Twizyforum.de - High cellular data usage/consumption, an issue that we most likely solved or at least found the cause of - bad wifi in my garage.

So back to the findings and the pattern that I wanted to share and hopefully also find a solution to: My modem "resets" with an interesting interval/duration between resets.

Below we have a table with the session logging from Hologram, and the LENGTH of these sessions "exactly" matches the duration of time between the log file of the OVMS for when the system performs a reset of the modem, below log file example from OVMS is just an example, so the date/time stamps do not match with the time stamps from Hologram.

OVMS events from log:

2023-02-03 17:45 :57.668 CET D (6766128) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ;+CPSI?;+COPS?
2023-02-03 17:46:27.668 CET D (6796128) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ;+CPSI?;+COPS?
2023-02-03 17:46:57.668 CET D (6826128) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ;+CPSI?;+COPS?
2023-02-03 17:47:27.668 CET D (6856128) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ;+CPSI?;+COPS?
2023-02-03 17:47:57.668 CET D (6886128) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ;+CPSI?;+COPS?
2023-02-03 17:48:27.668 CET D (6916128) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ;+CPSI?;+COPS?
2023-02-03 17:48:57.668 CET W (6946128) cellular: 3 minutes since last MUX rx frame - assume MUX has failed
2023-02-03 17:48:57.668 CET I (6946128) gsm-ppp: Shutting down (hard)...

Hologram session log:

START TIMESTAMP	END TIMESTAMP	LENGTH	Length Trimmed	BYTES
2023-02-08 8:40:38	2023-02-08 9:38:00	0:57:22	0:57	0 B
2023-02-08 7:43:16	2023-02-08 8:40:38	0:57:22	0:57	0 B
2023-02-08 4:51:28	2023-02-08 7:43:16	2:51:48	2:51	1.48 KB
2023-02-08 3:00:06	2023-02-08 4:51:28	1:51:22	1:51	0 B
2023-02-08 1:08:44	2023-02-08 3:00:06	1:51:22	1:51	0 B
2023-02-07 22:23:21	2023-02-08 1:08:43	2:45:22	2:45	0 B
2023-02-07 21:25:57	2023-02-07 22:23:21	0:57:24	0:57	0 B
2023-02-07 20:55:53	2023-02-07 21:25:12	0:29:19	0:29	0 B
2023-02-07 19:58:32	2023-02-07 20:55:53	0:57:21	0:57	0 B
2023-02-07 19:01:14	2023-02-07 19:58:31	0:57:17	0:57	0 B
2023-02-07 18:03:52	2023-02-07 19:01:14	0:57:22	0:57	0 B
2023-02-07 19:58:32	2023-02-07 20:55:53	0:57:21	0:57	0 B
2023-02-07 19:01:14	2023-02-07 19:58:31	0:57:17	0:57	0 B
2023-02-07 18:03:52	2023-02-07 19:01:14	0:57:22	0:57	0 B
2023-02-07 12:36:29	2023-02-07 18:03:52	5:27:23	5:27	0 B
2023-02-07 11:39:07	2023-02-07 12:36:29	0:57:22	0:57	0 B
2023-02-07 7:59:44	2023-02-07 11:39:07	3:39:23	3:39	0 B
2023-02-07 7:02:22	2023-02-07 7:59:44	0:57:22	0:57	0 B
2023-02-07 7:01:52	2023-02-07 7:01:57	0:00:05	0:00	0 B
2023-02-07 6:04:30	2023-02-07 7:01:52	0:57:22	0:57	0 B
2023-02-07 4:12:38	2023-02-07 6:04:24	1:51:46	1:51	0 B
2023-02-07 4:12:08	2023-02-07 4:12:13	0:00:05	0:00	0 B
2023-02-07 3:14:46	2023-02-07 4:12:08	0:57:22	0:57	0 B
2023-02-07 2:17:24	2023-02-07 3:14:46	0:57:22	0:57	0 B
2023-02-07 0:26:01	2023-02-07 2:17:24	1:51:23	1:51	0 B
2023-02-06 22:34:39	2023-02-07 0:26:01	1:51:22	1:51	0 B
2023-02-06 22:34:09	2023-02-06 22:34:15	0:00:06	0:00	0 B
2023-02-06 20:42:47	2023-02-06 22:34:09	1:51:22	1:51	0 B
2023-02-06 16:08:11	2023-02-06 20:42:47	4:34:36	4:34	816 B
2023-02-06 15:10:51	2023-02-06 16:08:11	0:57:20	0:57	0 B
2023-02-06 14:13:30	2023-02-06 15:10:51	0:57:21	0:57	0 B
2023-02-06 13:16:21	2023-02-06 14:13:30	0:57:09	0:57	0 B
2023-02-06 12:19:27	2023-02-06 13:16:21	0:56:54	0:56	0 B
2023-02-06 11:22:01	2023-02-06 12:19:21	0:57:20	0:57	0 B
2023-02-06 10:25:06	2023-02-06 11:22:01	0:56:55	0:56	0 B
2023-02-06 9:28:11	2023-02-06 10:25:06	0:56:55	0:56	0 B
2023-02-06 8:31:16	2023-02-06 9:28:11	0:56:55	0:56	0 B
2023-02-06 7:34:21	2023-02-06 8:31:16	0:56:55	0:56	0 B
2023-02-06 6:36:59	2023-02-06 7:34:21	0:57:22	0:57	0 B
2023-02-06 5:39:37	2023-02-06 6:36:59	0:57:22	0:57	0 B
2023-02-06 4:42:15	2023-02-06 5:39:37	0:57:22	0:57	0 B
2023-02-06 2:50:53	2023-02-06 4:42:15	1:51:22	1:51	0 B
2023-02-06 1:53:31	2023-02-06 2:50:53	0:57:22	0:57	0 B
2023-02-06 0:02:09	2023-02-06 1:53:31	1:51:22	1:51	0 B
2023-02-05 23:04:52	2023-02-06 0:02:09	0:57:17	0:57	0 B
2023-02-05 22:07:30	2023-02-05 23:04:52	0:57:22	0:57	0 B

Durations or intervals between resets in the data set above:

Length hh:mm	Frequency (how many times did the interval occur)
00:57	24
01:51	8
00:56	5
00:00	3
4:34	1

My setup:

OVMS V3.3
- OVMS MDM V3.3
- Firmware: 3.3.003-297-gae3bc7fd/ota_0/edge (build idf v3.3.4-849-g6e214dc335 Feb 4 2023 10:32:20)
  - Running an edge version by Dexter, specifically modified for trying to find the issue with the resets, but it's the same with main 3.3.003.
- Powered via USB-adapter 2.5A
Vehicle: Renault Twizy

OVMS MODULE SUMMARY

Module
Version: 3.3.003-297-gae3bc7fd/ota_0/edge (build idf v3.3.4-849-g6e214dc335 Feb 4 2023 10:32:20)
Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/3; MODEM SIM7600
12v: 0.0v

MODEM Status
Model: SIM7600
Network Registration: RegisteredRoaming
Provider: Telia Hologram
Signal: -73 dBm
Mode: LTE,Online
State: NetMode
Ticker: 1151
User Data: 0
UART:
FIFO overflows: 0
Buffer overflows: 0
Parity errors: 0
Frame errors: 0
Driver Buffer overflows: 0
Mux: Status up
Open Channels: 4
Framing Errors: 0
RX frames: 735
TX frames: 145
Last RX frame: 2 sec(s) ago
PPP: Connected on channel: #2
Connects: 1
GPS: Connected on channel: #1
Status: enabled
Time: enabled

Configuration
[auto]
dbc: no
egpio: no
ext12v: no
init: yes
modem: yes
obd2ecu:
ota: no
scripting: yes
server.v2: yes
server.v3: no
vehicle.type: RT
wifi.mode: apclient
wifi.ssid.ap: NHH456
wifi.ssid.client: LEDE
[can]
[dbc]
[egpio]
monitor.ports:
[http.plugin]
[http.server]
[locations]
[log]
file.enable: yes
file.path: /sd/logs/NHH456.log
level: info
level.cellular: debug
level.gsm-nmea: debug
level.gsm-ppp: info
level.netmanager: info
[modem]
apn: hologram
apn.password:
apn.user:
enable.gps: yes
enable.gpstime: yes
enable.net: yes
enable.sms: yes
pincode:
[module]
cfgversion: 2022121400
init: done
[network]
dns: 8.8.8.8 8.8.4.4
[notify]
report.trip.enable: yes
report.trip.minlength: 15
xrt.gps.log: -
[obd2ecu]
[obd2ecu.map]
[ota]
auto.allow.modem: no
auto.hour: 2
http.mru: https://ovms.dexters-web.de/firmware/ota/v3.3/edge/ovms3.bin
server: https://ovms.dexters-web.de/firmware/ota
tag: edge
[password]
module: **redacted**
server.v2: **redacted**
server.v3: **redacted**
[plugin]
[plugin.disabled]
[plugin.enabled]
[plugin.repos]
[power]
12v_shutdown_delay: 30
enabled: no
modemoff_delay: 96
wifioff_delay: 24
[pushover]
[sdcard]
[server.v2]
port:
server: ovms.dexters-web.de
tls: no
updatetime.connected: 120
updatetime.idle: 3600
[server.v3]
port:
server:
tls: no
topic.prefix:
updatetime.connected:
updatetime.idle:
user:
[ssh.info]
fingerprint: NBMMOzP3abQT82A7nQX1vZp2vpyOQTjkWPXqTE6GOwg
[ssh.keys]
[ssh.server]
key: **redacted**
[system.adc]
factor12v: 192.4
[tpms]
[usr]
[vehicle]
12v.alert: 12.1
12v.ref:
accel.smoothing: 4
batpwr.smoothing: 4
brakelight.basepwr: 0
brakelight.enable: no
brakelight.ignftbrk: no
brakelight.off: 0.7
brakelight.on: 1.3
brakelight.port: 1
id: NHH456
minsoc: 0
name:
stream: 0
timezone: CET-1CEST,M3.5.0,M10.5.0/3
timezone_region: Europe/Stockholm
units.distance: K
[wifi.ap]
NHH456: **redacted**
[wifi.ssid]
LEDE: **redacted**

REPORT ENDS

Sorry for the wall of text.. But It's hard to describe without much detail... guaranteed, I also missed out on sharing something important...

Anyways, many thanks in advance for any tips!

Kind regards,

Kristoffer

@Mark, adding another detail from Kristoffer's logs: all resets look the same and only need a single (!) power cycle to restart the modem. The modem is then identified in the same time as needed when started from the powered off state.

So this looks like the modem powers down by itself occasionally after some multiple of 55 minutes of uptime, and it does so without any message (i.e. no temperature or voltage warning received).

Complete RX loss & modem reset example:

2023-02-06 08:30:37.257 CET D (63028277) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ
2023-02-06 08:30:37.277 CET D (63028297) cellular: mux-rx-line #3: +CREG: 1,5
2023-02-06 08:30:37.277 CET D (63028297) cellular: mux-rx-line #3: +CGREG: 1,5
2023-02-06 08:30:37.277 CET D (63028297) cellular: mux-rx-line #3: +CEREG: 1,5
2023-02-06 08:30:37.277 CET D (63028297) cellular: mux-rx-line #3: +CCLK: "23/02/06,08:30:35+04"
2023-02-06 08:30:37.277 CET D (63028297) cellular: mux-rx-line #3: +CSQ: 16,99
2023-02-06 08:30:37.287 CET D (63028307) cellular: mux-rx-line #3: OK
2023-02-06 08:30:38.257 CET D (63029277) cellular: mux-tx #3: AT+CPSI?
2023-02-06 08:30:38.277 CET D (63029297) cellular: mux-rx-line #3: +CPSI: LTE,Online,240-01,0x0332,27847448,226,EUTRAN-BAND3,1471,4,4,-166,-1085,-711,8
2023-02-06 08:30:38.277 CET D (63029297) cellular: mux-rx-line #3: OK
2023-02-06 08:30:39.257 CET D (63030277) cellular: mux-tx #3: AT+COPS?
2023-02-06 08:30:39.267 CET D (63030287) cellular: mux-rx-line #3: +COPS: 0,0,"Telia Hologram",7
2023-02-06 08:30:39.277 CET D (63030297) cellular: mux-rx-line #3: OK
2023-02-06 08:31:01.647 CET D (63052667) cellular: mux-rx-line #3: +CSQ: 19,99
2023-02-06 08:31:01.647 CET I (63052667) cellular: Signal Quality is: 19 (-75 dBm)
2023-02-06 08:31:04.647 CET D (63055667) cellular: mux-rx-line #3: +CSQ: 16,99
2023-02-06 08:31:04.647 CET I (63055667) cellular: Signal Quality is: 16 (-81 dBm)
2023-02-06 08:31:07.257 CET D (63058277) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ
2023-02-06 08:31:08.257 CET D (63059277) cellular: mux-tx #3: AT+CPSI?
2023-02-06 08:31:09.257 CET D (63060277) cellular: mux-tx #3: AT+COPS?
2023-02-06 08:31:37.257 CET D (63088277) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ
2023-02-06 08:31:38.257 CET D (63089277) cellular: mux-tx #3: AT+CPSI?
2023-02-06 08:31:39.257 CET D (63090277) cellular: mux-tx #3: AT+COPS?
2023-02-06 08:32:07.257 CET D (63118277) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ
2023-02-06 08:32:08.257 CET D (63119277) cellular: mux-tx #3: AT+CPSI?
2023-02-06 08:32:09.257 CET D (63120277) cellular: mux-tx #3: AT+COPS?
2023-02-06 08:32:37.257 CET D (63148277) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ
2023-02-06 08:32:38.257 CET D (63149277) cellular: mux-tx #3: AT+CPSI?
2023-02-06 08:32:39.257 CET D (63150277) cellular: mux-tx #3: AT+COPS?
2023-02-06 08:33:07.257 CET D (63178277) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ
2023-02-06 08:33:08.257 CET D (63179277) cellular: mux-tx #3: AT+CPSI?
2023-02-06 08:33:09.257 CET D (63180277) cellular: mux-tx #3: AT+COPS?
2023-02-06 08:33:37.257 CET D (63208277) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ
2023-02-06 08:33:38.257 CET D (63209277) cellular: mux-tx #3: AT+CPSI?
2023-02-06 08:33:39.257 CET D (63210277) cellular: mux-tx #3: AT+COPS?
2023-02-06 08:34:07.257 CET W (63238277) cellular: 3 minutes since last MUX rx frame - assume MUX has failed
2023-02-06 08:34:07.257 CET I (63238277) gsm-ppp: Shutting down (hard)...
2023-02-06 08:34:07.257 CET I (63238277) gsm-ppp: StatusCallBack: User Interrupt
2023-02-06 08:34:07.257 CET I (63238277) gsm-ppp: PPP is shutdown
2023-02-06 08:34:07.257 CET D (63238277) cellular: mux-tx #4: AT+CGPSNMEA=0
2023-02-06 08:34:07.257 CET D (63238277) cellular: mux-tx #4: AT+CGPSINFOCFG=0
2023-02-06 08:34:07.257 CET I (63238277) netmanager: MODEM down (with WIFI client up): staying with WIFI client priority
2023-02-06 08:34:07.357 CET D (63238377) cellular: mux-tx #4: AT+CGPS=0
2023-02-06 08:34:07.357 CET I (63238377) gsm-nmea: Shutdown (direct)
2023-02-06 08:34:07.357 CET I (63238377) gsm-mux: Stop MUX
2023-02-06 08:34:07.357 CET I (63238377) SIM7600: Power Cycle (SIM7600) 2000ms
2023-02-06 08:34:09.357 CET D (63240377) cellular: State transition NetMode => PoweringOn
2023-02-06 08:34:09.357 CET I (63240377) cellular: State: Enter PoweringOn state
2023-02-06 08:34:09.357 CET D (63240377) cellular: Remove old 'SIM7600' modem driver
2023-02-06 08:34:09.357 CET I (63240377) cellular: Set modem driver to 'auto'
2023-02-06 08:34:09.357 CET I (63240377) cellular-modem-auto: Power Cycle 2000ms
2023-02-06 08:34:11.357 CET D (63242377) cellular: tx-cmd: AT
2023-02-06 08:34:11.357 CET D (63242377) cellular: tx-cmd: AT
2023-02-06 08:34:11.357 CET D (63242377) cellular: tx-cmd: AT
2023-02-06 08:34:11.357 CET D (63242377) cellular: tx-cmd: AT
2023-02-06 08:34:12.257 CET D (63243277) cellular: tx-cmd: AT
2023-02-06 08:34:13.257 CET D (63244277) cellular: tx-cmd: AT
2023-02-06 08:34:14.257 CET D (63245277) cellular: tx-cmd: AT
2023-02-06 08:34:15.257 CET D (63246277) cellular: tx-cmd: AT
2023-02-06 08:34:16.257 CET D (63247277) cellular: tx-cmd: AT
2023-02-06 08:34:17.257 CET D (63248277) cellular: tx-cmd: AT
2023-02-06 08:34:18.257 CET D (63249277) cellular: tx-cmd: AT
2023-02-06 08:34:19.257 CET D (63250277) cellular: tx-cmd: AT
2023-02-06 08:34:20.257 CET D (63251277) cellular: tx-cmd: AT
2023-02-06 08:34:21.257 CET D (63252277) cellular: tx-cmd: AT
2023-02-06 08:34:22.257 CET D (63253277) cellular: tx-cmd: AT
2023-02-06 08:34:23.257 CET D (63254277) cellular: tx-cmd: AT
2023-02-06 08:34:24.257 CET D (63255277) cellular: tx-cmd: AT
2023-02-06 08:34:25.057 CET I (63256077) cellular: State: Enter Identify state
2023-02-06 08:34:25.257 CET D (63256277) cellular: tx-cmd: AT+CGMM
2023-02-06 08:34:25.267 CET I (63256287) cellular: Identified cellular modem: SIM7600/Experimental support for SIMCOM SIM7600

Kristoffer also has the identical effect with two different providers.

My guess is some weird hardware fault with the modem.

Regards,
Michael