Improve SIM7600 power on and power cycle

[drc38]

@dexterbg @leres appreciate if you can test on your modules, it is working consistently on mine to recover from a module fault.

[dexterbg]

Crash recovery only works on my test module when GPS was up & running at crash time.

With GPS disabled, it still keeps looping in the power detection state cycle:

I (513) cellular: Initialising CELLULAR (4600)
I (544) SIM7600: Registering SIM7600 modem driver (4650)
V (1659) cellular: Starting modem task
I (1869) cellular: Set modem driver to 'SIM7600'
I (1879) cellular: State: Enter PoweringOn state
I (1889) SIM7600: Power On (SIM7600) 500ms
D (13429) cellular: tx-cmd: AT
I (13439) cellular: State: Enter PoweredOn state
D (23429) cellular: tx-cmd: AT+CPIN?;+CREG=1;+CGREG=1;+CEREG=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
W (23429) cellular: UART frame error
W (23429) cellular: UART frame error
W (23429) cellular: UART frame error
W (23429) cellular: UART frame error
W (23429) cellular: UART frame error
W (23439) cellular: UART frame error
W (23439) cellular: UART frame error
W (23439) cellular: UART frame error
W (23439) cellular: UART frame error
W (23439) cellular: UART frame error
W (23439) cellular: UART frame error
W (23439) cellular: UART frame error
W (23439) cellular: UART frame error
W (23439) cellular: UART frame error
D (25429) cellular: tx-cmd: AT+CGMR;+ICCID
D (33429) cellular: tx-cmd: AT+CMUX=0;+CATR=6
W (33429) cellular: UART frame error
D (73429) cellular: State timeout PoweredOn => PoweringOn
I (73429) cellular: State: Enter PoweringOn state
I (73429) SIM7600: Power On (SIM7600) 500ms
D (84429) cellular: tx-cmd: AT
I (84439) cellular: State: Enter PoweredOn state
D (94429) cellular: tx-cmd: AT+CPIN?;+CREG=1;+CGREG=1;+CEREG=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
W (94429) cellular: UART frame error
W (94429) cellular: UART frame error
W (94439) cellular: UART frame error
W (94439) cellular: UART frame error
W (94439) cellular: UART frame error
W (94439) cellular: UART frame error
W (94439) cellular: UART frame error
W (94439) cellular: UART frame error
W (94439) cellular: UART frame error
D (96429) cellular: tx-cmd: AT+CGMR;+ICCID
D (104429) cellular: tx-cmd: AT+CMUX=0;+CATR=6
D (144429) cellular: State timeout PoweredOn => PoweringOn
I (144429) cellular: State: Enter PoweringOn state
I (144429) SIM7600: Power On (SIM7600) 500ms
D (155429) cellular: tx-cmd: AT
I (155439) cellular: State: Enter PoweredOn state
D (165429) cellular: tx-cmd: AT+CPIN?;+CREG=1;+CGREG=1;+CEREG=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
W (165439) cellular: UART frame error
D (167429) cellular: tx-cmd: AT+CGMR;+ICCID
W (167429) cellular: UART frame error
D (175429) cellular: tx-cmd: AT+CMUX=0;+CATR=6
D (215429) cellular: State timeout PoweredOn => PoweringOn
I (215429) cellular: State: Enter PoweringOn state
I (215429) SIM7600: Power On (SIM7600) 500ms
D (226429) cellular: tx-cmd: AT
I (226439) cellular: State: Enter PoweredOn state
D (236429) cellular: tx-cmd: AT+CPIN?;+CREG=1;+CGREG=1;+CEREG=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
W (236439) cellular: UART frame error
W (236439) cellular: UART frame error
D (238429) cellular: tx-cmd: AT+CGMR;+ICCID
D (246429) cellular: tx-cmd: AT+CMUX=0;+CATR=6
D (286429) cellular: State timeout PoweredOn => PoweringOn
I (286429) cellular: State: Enter PoweringOn state
I (286429) SIM7600: Power On (SIM7600) 500ms
D (297429) cellular: tx-cmd: AT
I (297439) cellular: State: Enter PoweredOn state
D (307429) cellular: tx-cmd: AT+CPIN?;+CREG=1;+CGREG=1;+CEREG=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
W (307439) cellular: UART frame error
D (309429) cellular: tx-cmd: AT+CGMR;+ICCID
D (317429) cellular: tx-cmd: AT+CMUX=0;+CATR=6
D (357429) cellular: State timeout PoweredOn => PoweringOn
I (357429) cellular: State: Enter PoweringOn state
I (357429) SIM7600: Power On (SIM7600) 500ms
D (368429) cellular: tx-cmd: AT
I (368439) cellular: State: Enter PoweredOn state
D (378429) cellular: tx-cmd: AT+CPIN?;+CREG=1;+CGREG=1;+CEREG=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
W (378439) cellular: UART frame error
W (378439) cellular: UART frame error
D (380429) cellular: tx-cmd: AT+CGMR;+ICCID
D (388429) cellular: tx-cmd: AT+CMUX=0;+CATR=6
…etc…

An explicit power cellular off works from this state, and a power cellular on after that as well.

[drc38]

Thanks Michael, do you know why the uart frame error is not picked up in the PoweringOn state? If it was then it would result in transitioning to PowerOffOn which should clear/reset the module.

[dexterbg]

UART frame errors are no indication you can rely on. They may or may not occur in case of an unresponsive modem, and they also may frequently occur during normal operation. The reason these occur so often sometimes still isn't clear, another ESP32 hardware bug cannot be ruled out. The modem task only logs & counts these, so we can potentially some day figure out why they occur and how to avoid them.

If you'd like to dig deeper, read:

• http://lists.openvehicles.com/pipermail/ovmsdev/2023-January/016061.html
• SIMCOM: Reset modem when framing is lost #350

[drc38]

Is there any reason the RX buffer is not flushed on a framing error?

If the above log is an indication of an unresponsive modem I'm interested in how it passes the PoweringOn state?

Is there any way to capture the RX following the AT command?

[dexterbg]

Flushing the RX buffer does not help, even performing an UART reset does not help to stop the frame errors.

RX lines are logged as cellular: mux-rx-line … at level debug. If you want to see the char data, you need to add a log output regardless of HasLine() returning true, e.g. in modem::StandardIncomingHandler().

See my previous logs on other boot sequences. Running your latest change, this is a cold boot with GPS disabled:

I (495) cellular: Initialising CELLULAR (4600)
I (502) cellular-modem-factory: Initialising CELLULAR MODEM Factory (4601)
I (527) SIM7600: Registering SIM7600 modem driver (4650)
I (1621) peripherals:   CELLULAR MODEM
V (1641) cellular: Starting modem task
I (1851) cellular: Set modem driver to 'SIM7600'
I (1861) cellular: State: Enter PoweringOn state
I (1871) SIM7600: Power On (SIM7600) 500ms
Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/3; MODEM SIM7600
I (6411) netmanager: WIFI client up (with MODEM down): starting network with WIFI client
D (13411) cellular: tx-cmd: AT
D (14411) cellular: tx-cmd: AT
I (15401) cellular: State: Enter PoweredOn state
D (24411) cellular: tx-cmd: AT+CPIN?;+CREG=1;+CGREG=1;+CEREG=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
D (24441) cellular: mux-rx-line #0: �MAT+CPIN?;+CREG=1;+CGREG=1;+CEREG=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
D (24441) cellular: mux-rx-line #0: +CPIN: READY
D (24441) cellular: mux-rx-line #0: +CSQ: 18,0
D (24441) cellular: Signal Quality is: 18 (-77 dBm)
D (24451) cellular: mux-rx-line #0: OK
D (26411) cellular: tx-cmd: AT+CGMR;+ICCID
D (26431) cellular: mux-rx-line #0: +CGMR: LE20B03SIM7600M21-A
D (26431) cellular: mux-rx-line #0: +ICCID: *****************
D (26431) cellular: mux-rx-line #0: OK
D (34411) cellular: tx-cmd: AT+CMUX=0;+CATR=6
D (34421) cellular: mux-rx-line #0: OK
I (34421) cellular: State: Enter MuxStart state
V (34421) cellular: Starting MUX
W (34441) cellular: UART frame error
D (35411) cellular: State transition MuxStart => NetWait
I (35411) cellular: State: Enter NetWait state
D (45411) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ
D (45431) cellular: mux-rx-line #3: +CREG: 1,5
I (45431) cellular: Network Registration status: RegisteredRoaming
D (45431) cellular: mux-rx-line #3: +CGREG: 1,5
D (45431) cellular: mux-rx-line #3: +CEREG: 1,4
D (45431) cellular: mux-rx-line #3: +CCLK: "23/11/12,10:33:42+04"
D (45431) cellular: mux-rx-line #3: +CSQ: 18,0
D (45431) cellular: mux-rx-line #3: OK
D (46411) cellular: mux-tx #3: AT+CPSI?
D (46411) cellular: State transition NetWait => NetStart
I (46411) cellular: State: Enter NetStart state
D (46431) cellular: mux-rx-line #3: +CPSI: GSM,Online,262-02,0x011f,1161,5 EGSM 900,-71,0,0-0
I (46431) cellular: Network Mode: GSM,Online
D (46431) cellular: mux-rx-line #3: OK
D (47411) cellular: Netstart AT+CGDCONT=1,"IP","hologram";+CGDATA="PPP",1
D (47461) cellular: mux-rx-line #2: CONNECT 115200
I (47461) cellular: PPP Connection is ready to start
D (48411) cellular: State transition NetStart => NetMode
I (48411) cellular: State: Enter NetMode state
V (48411) cellular: Launching PPP
V (48411) cellular: Starting PPP
W (48441) cellular: UART frame error
W (48441) cellular: UART frame error
W (48441) cellular: UART frame error
W (48461) cellular: UART frame error
W (48491) cellular: UART frame error
W (48491) cellular: UART frame error
W (48491) cellular: UART frame error
W (48511) cellular: UART frame error
W (48531) cellular: UART frame error
W (48531) cellular: UART frame error
W (48531) cellular: UART frame error
W (48531) cellular: UART frame error
I (48551) netmanager: MODEM up (with WIFI client up): staying with WIFI client priority

And a regular reboot from here, still GPS disabled:

module reset
D (590411) cellular: mux-tx #3: AT+COPS?
D (590431) cellular: mux-rx-line #3: +COPS: 0,0,"vodafone.de Hologram",7
D (590431) cellular: mux-rx-line #3: OK
I (618141) cellular: State: Enter PoweringOff state
V (618141) cellular: Stopping PPP
I (618151) SIM7600: Power Off (SIM7600) 3000ms
I (618151) netmanager: WIFI client down (with MODEM up): reconfigured for MODEM priority
I (618411) netmanager: MODEM down (with WIFI client down): network connectivity has been lost
D (637411) cellular: State timeout PoweringOff => CheckPowerOff
I (637411) cellular: State: Enter CheckPowerOff state
I (637411) SIM7600: Power Off (SIM7600) 3000ms
D (648411) cellular: tx-cmd: AT
D (649411) cellular: tx-cmd: AT
D (650411) cellular: tx-cmd: AT
D (651411) cellular: tx-cmd: AT
D (652411) cellular: tx-cmd: AT
D (652411) cellular: State timeout CheckPowerOff => PoweredOff
I (652411) cellular: State: Enter PoweredOff state
V (652411) cellular: Stopping MUX
D (652411) cellular: UART shutdown
I (508) cellular: Initialising CELLULAR (4600)
I (514) cellular-modem-factory: Initialising CELLULAR MODEM Factory (4601)
I (539) SIM7600: Registering SIM7600 modem driver (4650)
I (1714) peripherals:   CELLULAR MODEM
V (1734) cellular: Starting modem task
I (1944) cellular: Set modem driver to 'SIM7600'
I (1954) cellular: State: Enter PoweringOn state
I (1964) SIM7600: Power On (SIM7600) 500ms
Hardware: OVMS WIFI BLE BT cores=2 rev=ESP32/3; MODEM SIM7600
I (6424) netmanager: WIFI client up (with MODEM down): starting network with WIFI client
D (13424) cellular: tx-cmd: AT
D (14424) cellular: tx-cmd: AT
D (15424) cellular: tx-cmd: AT
D (16424) cellular: tx-cmd: AT
D (17424) cellular: tx-cmd: AT
D (18424) cellular: tx-cmd: AT
D (19424) cellular: tx-cmd: AT
I (19444) cellular: State: Enter PoweredOn state
D (29424) cellular: tx-cmd: AT+CPIN?;+CREG=1;+CGREG=1;+CEREG=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
D (29454) cellular: mux-rx-line #0: AT+CPIN?;+CREG=1;+CGREG=1;+CEREG=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
D (29454) cellular: mux-rx-line #0: +CPIN: READY
D (29454) cellular: mux-rx-line #0: +CSQ: 19,0
D (29454) cellular: Signal Quality is: 19 (-75 dBm)
D (29464) cellular: mux-rx-line #0: OK
D (31424) cellular: tx-cmd: AT+CGMR;+ICCID
D (31434) cellular: mux-rx-line #0: +CGMR: LE20B03SIM7600M21-A
D (31444) cellular: mux-rx-line #0: +ICCID: ***************
D (31444) cellular: mux-rx-line #0: OK
D (39424) cellular: tx-cmd: AT+CMUX=0;+CATR=6
D (39434) cellular: mux-rx-line #0: OK
I (39434) cellular: State: Enter MuxStart state
V (39434) cellular: Starting MUX
D (40424) cellular: State transition MuxStart => NetWait
I (40424) cellular: State: Enter NetWait state
D (50424) cellular: mux-tx #3: AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ
D (50444) cellular: mux-rx-line #3: +CREG: 1,5
I (50444) cellular: Network Registration status: RegisteredRoaming
D (50454) cellular: mux-rx-line #3: +CGREG: 1,5
D (50454) cellular: mux-rx-line #3: +CEREG: 1,4
D (50454) cellular: mux-rx-line #3: +CCLK: "23/11/12,10:44:44+04"
D (50454) cellular: mux-rx-line #3: +CSQ: 19,0
D (50454) cellular: mux-rx-line #3: OK
D (51424) cellular: mux-tx #3: AT+CPSI?
D (51424) cellular: State transition NetWait => NetStart
I (51424) cellular: State: Enter NetStart state
D (51444) cellular: mux-rx-line #3: +CPSI: GSM,Online,262-02,0x011f,1161,5 EGSM 900,-71,0,0-0
I (51444) cellular: Network Mode: GSM,Online
D (51444) cellular: mux-rx-line #3: OK
D (52424) cellular: Netstart AT+CGDCONT=1,"IP","hologram";+CGDATA="PPP",1
D (52474) cellular: mux-rx-line #2: CONNECT 115200
I (52474) cellular: PPP Connection is ready to start
D (53424) cellular: State transition NetStart => NetMode
I (53424) cellular: State: Enter NetMode state
V (53424) cellular: Launching PPP
V (53424) cellular: Starting PPP
I (53564) netmanager: MODEM up (with WIFI client up): staying with WIFI client priority

Also an example of how random the UART frame errors are; not a single one on that reboot.

[drc38]

An explicit power cellular off works from this state, and a power cellular on after that as well.

Given the above works is it sensible to always power off the modem on a restart (or crash restart), before powering it on?

[dexterbg]

Yes, and that is exactly what the general (driver auto detect) code does. You cannot assume a specific modem state on a reboot. Even if you introduce a new persistent variable in the boot object for the last modem state, that can as well get lost or corrupted by a crash. That's why the general code does a series of modem power switches until it gets a response.

[drc38]

I've added a backstop PowerCycle if the modem gets stuck in the PoweredOn state. I think it would also be worth amending AutoInit so the modem starts in a known off state:

void modem::AutoInit()
  {
  SetPowerMode(Off);
  if (MyConfig.GetParamValueBool("auto", "modem", false))
    SetPowerMode(On);
  }

[dexterbg]

Good news is, it does recover now. Bad news is, it needs much longer than with the default (autodetect) scheme:

• driver auto: 2 minutes until PPP connect
• driver SIM7600: >5 minutes until PPP connect

This has been consistent over multiple tests.

Regarding your proposed AutoInit() modification: SetPowerMode() is an asynchronous state change request, requesting a power off-on sequence doesn't work like this. Also, AutoInit() isn't the perfect place, as a manual power on of the modem after a crash can have the same issue.

But you inspired me to try using PowerOffOn instead of PoweringOn in SetPowerMode(). That state request actually implements a proper power off-on sequence taking care of doing power switches until it detects the modem becoming responsive, so should work from any previous modem power state.

And indeed, that seems to work on both modem models. It also seems to yield ~30 seconds shorter crash recovery times on both (down to 80-90 seconds), without hurting regular power-on times too bad (still 50-60 seconds), regardless of GPS status.

That is, these results are based on introducing this change to the master state before merging the SIM7600 changes. With your latest changes in this branch, recovery time with driver SIM7600 and GPS enabled rise to 110-120 seconds.

So I suggest testing this in more detail, and probably reverting the SIM7600 changes in favor for this, if you don't find any caveats. It could additionally be beneficial to make use of the Unknown power state on boot to differentiate between known and unknown power states.

Diff:

--- a/vehicle/OVMS.V3/components/ovms_cellular/src/ovms_cellular.cpp
+++ b/vehicle/OVMS.V3/components/ovms_cellular/src/ovms_cellular.cpp
@@ -340,7 +340,9 @@ void modem::SetPowerMode(PowerMode powermode)
     case Sleep:
     case DeepSleep:
       if ((original!=On)&&(original!=Sleep)&&(original!=DeepSleep))
-        SendSetState1(PoweringOn); // We are not in the task, so queue the state change
+        SendSetState1(PowerOffOn); // We are not in the task, so queue the state change
+        // We don't know the actual power state of the modem, it can be still powered on
+        // after a crash. PowerOffOn initiates a power cycle, which works in any case.
       break;
 
     case Off:

@leres Maybe you can give this a try as well?

@markwj Any objections / further ideas?

Regards,
Michael

[drc38]

Thanks Michael, good to see the PowerOffOn noticeably improves crash recovery time, depending on which way the others want to go I have pushed some tweaks to improve the crash recovery time for the SIM7600 driver. In general, my preference is to try and match the hardware specification sheet as closely as possible, on the basis you hope they have rigorously tested the timings and found them to be most reliable/cause least issues.

[dexterbg]

I've been using the PowerOffOn change for a while without issues, so I've just pushed that into master.

As written above, recovery time still is worse with the SIM7600 modifications, so I'll keep this PR unmerged for now.