<html><head><meta http-equiv="Content-Type" content="text/html; charset=utf-8"></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; line-break: after-white-space;" class="">Too damn reliable.<div class=""><br class=""></div><div class="">It has been three days since this last happened. Module has been in the car, rock solid, and no crashes/reboots for three days now. No watchdog timers fired.</div><div class=""><br class=""></div><div class="">Good grief.</div><div class=""><br class=""></div><div class="">Any ideas / suggestions as to how to repeat this issue, other than move to New Zealand (where Tom seems to get it fairly regularly)?</div><div class=""><br class=""></div><div class="">Regards, Mark.<br class=""><div><br class=""><blockquote type="cite" class=""><div class="">On 25 Mar 2018, at 3:54 PM, Mark Webb-Johnson <<a href="mailto:mark@webb-johnson.net" class="">mark@webb-johnson.net</a>> wrote:</div><br class="Apple-interchange-newline"><div class=""><meta http-equiv="Content-Type" content="text/html charset=utf-8" class=""><div style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space;" class=""><div class=""><br class=""></div><div class="">My car managed to repeat the issue with the task lockup I have seen occasionally. The symptom is that network connectivity fails and the async console becomes unresponsive when you issue a command to bring up/down wifi, simcom, etc.</div><div class=""><br class=""></div><div class="">The new housekeeping 10 minute ticker worked well for this, and stopped in the middle of the night:</div><div class=""><br class=""></div><blockquote style="margin: 0 0 0 40px; border: none; padding: 0px;" class=""><div class=""><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">…</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">I (134401020) housekeeping: Local time: Sat Mar 24 20:15:45 2018</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">I (135001020) housekeeping: Local time: Sat Mar 24 20:25:45 2018</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">I (135601020) housekeeping: Local time: Sat Mar 24 20:35:45 2018</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">I (136201020) housekeeping: Local time: Sat Mar 24 20:45:45 2018</span></font></div></div></blockquote><div class=""><br class=""></div><div class="">Looking at the logs after Sat Mar 24 20:45:45, I see:</div><div class=""><br class=""></div><blockquote style="margin: 0 0 0 40px; border: none; padding: 0px;" class=""><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">D (136543060) simcom: rx line ch=4 len=19 : +PPPD: DISCONNECTED<br class="">I (136543070) simcom: PPP Connection disconnected<br class="">I (136544020) simcom: Lost network connection (+PPP disconnect in NetMode)<br class="">I (136544020) simcom: State: Enter NetLoss state</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">...</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">I (136544030) gsm-ppp: Shutting down (hard)...<br class="">I (136544040) events: Signal(system.modem.down)<br class="">I (136544040) netmanager: Interface priority is st1 (x.y.z.212/255.255.248.0 gateway x.y.z.64)<br class="">I (136544050) events: Signal(network.modem.down)<br class="">I (136544050) netmanager: MODEM down (with WIFI client up): staying with WIFI client priority<br class="">I (136544060) events: Signal(network.interface.change)</span></font></div></blockquote><div class=""><br class=""></div><div class="">OK, so ppp went down (lost network connectivity), and WIFI client was up so we kept with that.</div><div class=""><br class=""></div><div class="">The GSM signal is still up (CREG), so we try to reconnect PPP:</div><div class=""><br class=""></div><blockquote style="margin: 0 0 0 40px; border: none; padding: 0px;" class=""><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">I (136558160) simcom: PPP Connection is ready to start<br class="">I (136559020) simcom: State: Enter NetMode state<br class="">I (136559020) gsm-ppp: Initialising..</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">...</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">D (136589180) simcom: rx line ch=4 len=8 : +CREG: 2<br class="">I (136589190) simcom: CREG Network Registration: Searching</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">...</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">D (136589250) simcom: rx line ch=4 len=8 : +CREG: 5^[[0m<br class="">^[[0;32mI (136589250) simcom: CREG Network Registration: RegisteredRoaming</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">...</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">D (136589320) simcom: rx line ch=4 len=8 : +CREG: 2^[[0m<br class="">^[[0;32mI (136589320) simcom: CREG Network Registration: Searching</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">...</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">D (136589380) simcom: rx line ch=4 len=8 : +CREG: 5^[[0m<br class="">^[[0;32mI (136589390) simcom: CREG Network Registration: RegisteredRoaming</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">...</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">D (136601690) simcom: rx line ch=3 len=8 : +CREG: 2^[[0m<br class="">^[[0;32mI (136601690) simcom: CREG Network Registration: Searching</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">...</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">D (136601780) simcom: rx line ch=3 len=8 : +CREG: 5^[[0m<br class="">^[[0;32mI (136601780) simcom: CREG Network Registration: RegisteredRoaming</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">...</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">V (136617440) gsm-ppp: tx: 7e ff 7d 23 c0 21 7d 25 7d 2c 7d 20 20 4e 6f 20 | ~.}#.!}%},} No <br class="">V (136617440) gsm-ppp: tx: 6e 65 74 77 6f 72 6b 20 70 72 6f 74 6f 63 6f 6c | network protocol<br class="">V (136617450) gsm-ppp: tx: 73 20 72 75 6e 6e 69 6e 67 4b 8f 7e | s runningK.~ <br class="">V (136617450) simcom: tx: f9 09 ff 59 7e ff 7d 23 c0 21 7d 25 7d 2c 7d 20 | ...Y~.}#.!}%},} <br class="">V (136617450) simcom: tx: 20 4e 6f 20 6e 65 74 77 6f 72 6b 20 70 72 6f 74 | No network prot<br class="">V (136617460) simcom: tx: 6f 63 6f 6c 73 20 72 75 6e 6e 69 6e 67 4b 8f 7e | ocols runningK.~<br class="">V (136617460) simcom: tx: a6 f9 | .. <br class="">V (136617490) simcom: rx: f9 09 ff 25 7e ff 7d 23 c0 21 7d 26 7d 2c 7d 20 | ...%~.}#.!}&},} <br class="">V (136617500) simcom: rx: 7d 24 8f 7d 3d 7e fb f9 | }$.}=~.. <br class="">V (136617510) gsm-mux: ProcessFrame(CHAN=2, ADDR=09, CTRL=ff, FCS=fb, LEN=24)<br class="">V (136617520) gsm-mux: ChanProcessFrame(CHAN=2, ADDR=09, CTRL=ff, LEN=21, IFP=3)<br class="">V (136617520) gsm-ppp: rx: 7e ff 7d 23 c0 21 7d 26 7d 2c 7d 20 7d 24 8f 7d | ~.}#.!}&},} }$.}<br class="">V (136617530) gsm-ppp: rx: 3d 7e | =~ <br class="">I (136617540) gsm-ppp: StatusCallBack: Connection Lost<br class="">E (136617540) gsm-ppp: status_cb: Connection lost<br class="">I (136617550) gsm-ppp: Shutdown (via status callback)<br class="">I (136617550) events: Signal(system.modem.down)<br class="">I (136617560) netmanager: Interface priority is st1 (x.y.z.212/255.255.248.0 gateway z.y.z.64)<br class="">I (136617560) gsm-ppp: Attempting PPP reconnecting in 30 seconds...</span></font></div></blockquote><div class=""><br class=""></div><div class="">So, while initialising PPP we’ve been told that the cellular network is down (CREG: 2). Then, it flaps up and down like a yoyo, until the PPP connect finally fails.</div><div class=""><br class=""></div><div class="">At this point, things go screwy. The simcom tells us the PPP is down, and then we lose the ability to transmit to the modem (or at least log those transmits):</div><div class=""><br class=""></div><blockquote style="margin: 0 0 0 40px; border: none; padding: 0px;" class=""><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">V (136618650) simcom: rx: 50 50 50 44 3a 20 44 49 53 43 4f 4e 4e 45 43 54 | PPPD: DISCONNECT<br class="">V (136618660) simcom: rx: 45 44 0d 0a d4 f9 f9 11 ff 2f 0d 0a 2b 50 50 50 | ED......./..+PPP<br class="">V (136618660) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=d4, LEN=29)<br class="">V (136618670) gsm-mux: ChanProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, LEN=26, IFP=3)<br class="">D (136618680) simcom: rx line ch=3 len=19 : +PPPD: DISCONNECTED<br class="">I (136618690) simcom: PPP Connection disconnected<br class="">V (136618690) simcom: rx: 44 3a 20 44 49 53 43 4f 4e 4e 45 43 54 45 44 0d | D: DISCONNECTED.<br class="">V (136618700) simcom: rx: 0a d9 f9 | ... <br class="">V (136618710) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=d9, LEN=29)<br class="">V (136618710) gsm-mux: ChanProcessFrame(CHAN=4, ADDR=11, CTRL=ff, LEN=26, IFP=3)<br class="">D (136618720) simcom: rx line ch=4 len=19 : +PPPD: DISCONNECTED<br class="">I (136618730) simcom: PPP Connection disconnected<br class="">I (136619020) simcom: Lost network connection (+PPP disconnect in NetMode)<br class="">I (136619020) simcom: State: Enter NetLoss state<br class="">V (136619030) simcom: tx: f9 0d ff 19 41 54 2b 43 47 41 54 54 3d 30 0d 0a | ....AT+CGATT=0..<br class="">V (136619030) simcom: tx: 14 f9 | .. <br class="">I (136619030) gsm-ppp: Shutting down (hard)...^[[0m<br class="">I (136619040) events: Signal(system.modem.down)^[[0m<br class="">I (136619040) netmanager: Interface priority is st1 (x.y.z.212/255.255.248.0 gateway x.y.z.64)<br class="">V (136632920) simcom: rx: f9 0d ff 0d 0d 0a 4f 4b 0d 0a 0f f9 | ......OK.... <br class="">V (153076210) simcom: rx: f9 09 ff 1d 0d 0a 2b 43 53 51 3a 20 31 2c 39 39 | ......+CSQ: 1,99<br class="">V (153076220) simcom: rx: 0d 0a d1 f9 f9 0d ff 1d 0d 0a 2b 43 53 51 3a 20 | ..........+CSQ: <br class="">V (153076220) simcom: rx: 31 2c 39 39 0d 0a 13 f9 f9 11 ff 1d 0d 0a 2b 43 | 1,99..........+C<br class="">V (153076230) simcom: rx: 53 51 3a 20 31 2c 39 39 0d 0a 1e f9 | SQ: 1,99.... <br class="">V (153202470) simcom: rx: f9 09 ff 1d 0d 0a 2b 43 53 51 3a 20 34 2c 39 39 | ......+CSQ: 4,99<br class="">V (153202480) simcom: rx: 0d 0a d1 f9 f9 0d ff 1d 0d 0a 2b 43 53 51 3a 20 | ..........+CSQ: <br class="">V (153202490) simcom: rx: 34 2c 39 39 0d 0a 13 f9 f9 11 ff 1d 0d 0a 2b 43 | 4,99..........+C<br class="">V (153202500) simcom: rx: 53 51 3a 20 34 2c 39 39 0d 0a 1e f9 | SQ: 4,99.... <br class="">V (179212720) simcom: rx: f9 09 ff 1d 0d 0a 2b 43 53 51 3a 20 30 2c 39 39 | ......+CSQ: 0,99<br class="">V (179212730) simcom: rx: 0d 0a d1 f9 f9 0d ff 1d 0d 0a 2b 43 53 51 3a 20 | ..........+CSQ: <br class="">V (179212730) simcom: rx: 30 2c 39 39 0d 0a 13 f9 f9 11 ff 1d 0d 0a 2b 43 | 0,99..........+C<br class="">V (179212740) simcom: rx: 53 51 3a 20 30 2c 39 39 0d 0a 1e f9 | SQ: 0,99.... <br class="">V (179242750) simcom: rx: f9 09 ff 1d 0d 0a 2b 43 53 51 3a 20 30 2c 39 39 | ......+CSQ: 0,99<br class="">V (179242760) simcom: rx: 0d 0a d1 f9 f9 0d ff 1d 0d 0a 2b 43 53 51 3a 20 | ..........+CSQ: <br class="">V (179242770) simcom: rx: 30 2c 39 39 0d 0a 13 f9 f9 11 ff 1d 0d 0a 2b 43 | 0,99..........+C<br class="">V (179242770) simcom: rx: 53 51 3a 20 30 2c 39 39 0d 0a 1e f9 | SQ: 0,99.... <br class="">V (179246100) simcom: rx: f9 09 ff 19 0d 0a 2b 43 52 45 47 3a 20 32 0d 0a | ......+CREG: 2..<br class="">V (179246110) simcom: rx: d6 f9 f9 0d ff 19 0d 0a 2b 43 52 45 47 3a 20 32 | ........+CREG: 2<br class="">V (179246110) simcom: rx: 0d 0a 14 f9 f9 11 ff 19 0d 0a 2b 43 52 45 47 3a | ..........+CREG:<br class="">V (179246120) simcom: rx: 20 32 0d 0a 19 f9 | 2.... <br class="">V (179251580) simcom: rx: f9 09 ff 1d 0d 0a 2b 43 53 51 3a 20 34 2c 39 39 | ......+CSQ: 4,99<br class="">V (179251590) simcom: rx: 0d 0a d1 f9 f9 0d ff 1d 0d 0a 2b 43 53 51 3a 20 | ..........+CSQ: <br class="">V (179251600) simcom: rx: 34 2c 39 39 0d 0a 13 f9 f9 11 ff 1d 0d 0a 2b 43 | 4,99..........+C<br class="">V (179251600) simcom: rx: 53 51 3a 20 34 2c 39 39 0d 0a 1e f9 | SQ: 4,99.... <br class="">I (179290100) wifi: bcn_timout,ap_probe_send_start<br class="">I (179292610) wifi: ap_probe_send over, resett wifi status to disassoc<br class="">I (179292610) wifi: state: run -> init (1)<br class="">I (179292620) wifi: pm stop, total sleep time: 0/138543477<br class="">I (179292620) wifi: n:13 0, o:13 0, ap:255 255, sta:13 0, prof:1</span></font></div></blockquote><div class=""><br class=""></div><div class="">The simcom itself seems to be up, and is giving us unsolicited notifications. Finally, the wifi stack falls over (bcn_timeout.ap_probe_sent).</div><div class=""><br class=""></div><div class="">This is very nasty, and I suspect will take some time to resolve. We can probably make it more stable by introducing a check for network loss, and requiring the network to be up and stable for N seconds before even attempting a reconnection; but I don’t think that addresses the core issue (which is most likely in the lwip ppp stack).</div><div class=""><br class=""></div><div class="">Code-wise, the simcom driver entering ‘NetLoss’ state calls m_ppp.Shutdown(true) (which issues the shutting down (hard) message). Our pppos driver issues the system.modem.down event (which causes netmanager to do it’s thing), and then calls ppapi_close(m_ppp, nocarrier). I suspect that never returns (but don’t know for sure).</div><div class=""><br class=""></div><div class="">The other workaround is to enable watchdog timers. I’m 99% certain this sort of lockup would mess up the idle tasks and those would pickup and fire a watchdog timer. So, I’ve gone ahead and committed code to enable the watchdog timers (2 minutes), and make that available as an OTA update:</div><div class=""><br class=""></div><blockquote style="margin: 0 0 0 40px; border: none; padding: 0px;" class=""><div class=""><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">OVMS# ota status</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">Firmware: 3.1.001/ota_0/main (build idf v3.1-dev-453-g0f978bcb Mar 25 2018 14:45:59)</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-size: 14px;" class="">Server Available: 3.1.001</span></font></div></div></blockquote><div class=""><br class=""></div><div class="">The module in my car is now running OTA, so I can verify the OTA update process is smooth (it seems so).</div><div class=""><br class=""></div><div class="">Regards, Mark.</div><div class=""><br class=""></div><div class=""><br class=""></div></div>_______________________________________________<br class="">OvmsDev mailing list<br class=""><a href="mailto:OvmsDev@lists.teslaclub.hk" class="">OvmsDev@lists.teslaclub.hk</a><br class="">http://lists.teslaclub.hk/mailman/listinfo/ovmsdev<br class=""></div></blockquote></div><br class=""></div></body></html>