[Ovmsdev] time stands still?

Tue Mar 20 11:13:17 HKT 2018

> Any debugging to do before I reset it with today's bits?

Greg: Hang on 30 minutes or so. I’ve got some fixes (including a big one that I think is causing us many of these random issues). Just testing all the combinations at the moment, and then I will commit…

Regards, Mark.

> On 20 Mar 2018, at 10:30 AM, Greg D. <gregd2350 at gmail.com> wrote:
> 
> Hi folks,
> 
> I left last night's build running all night and had other distractions today, so just got around to looking at how it held up.  While it's still alive, the clock seems to have gotten stuck.  m.monotonic stands at 30389 Sec and holding, which was some time early this morning.  Oddly, the time command shows the correct UTC time.
> 
> Here's the last set of log messages.  Perhaps of interest is the last one (frame overflow), and the authentication failure before that.  
> 
> Any debugging to do before I reset it with today's bits?  None of the module commands work (complains about needing heap tracking and an updated esp-idf, both of which I thought I had done).
> 
> Greg
> 
> 
> W (29694436) simcom: 3 minutes since last MUX rx frame - assume MUX has failed
> I (29694436) gsm-ppp: Shutting down (soft)...
> I (29694436) time: Stopping SNTP client
> I (29694436) ovms-server-v2: Network is down, so disconnect network connection
> E (29694436) ovms-server-v2: Status: Error: Disconnected from OVMS Server V2
> I (29694446) gsm-nmea: Shutdown (direct)
> I (29694446) gsm-mux: Stop MUX
> I (29694446) simcom: Power Cycle
> I (29694496) webserver: Stopping Web Server
> I (29695446) simcom: State: Enter PoweringOn state
> I (29695446) simcom: Power Cycle
> I (29703436) simcom: State timeout, transition to 2
> I (29703436) simcom: State: Enter PoweringOn state
> I (29703436) simcom: Power Cycle
> I (29705966) gsm-ppp: StatusCallBack: User Interrupt
> I (29705966) gsm-ppp: PPP connection has been closed
> I (29709566) simcom: State: Enter PoweredOn state
> I (29729436) simcom: State: Enter MuxStart state
> I (29729436) gsm-mux: Start MUX
> I (29729446) gsm-mux: Channel #0 is open
> I (29729446) gsm-mux: Channel #1 is open
> I (29729456) gsm-mux: Channel #2 is open
> I (29729456) gsm-mux: Channel #3 is open
> I (29729466) gsm-mux: Channel #4 is open
> I (29730436) simcom: State: Enter NetWait state
> I (29734436) simcom: State: Enter NetStart state
> I (29735556) simcom: PPP Connection is ready to start
> I (29736436) simcom: State: Enter NetMode state
> I (29736436) gsm-ppp: Initialising...
> I (29739486) gsm-ppp: StatusCallBack: None
> I (29739486) gsm-ppp: status_cb: Connected
> I (29739486) gsm-ppp:    our_ipaddr  = 10.170.146.142
> I (29739486) gsm-ppp:    his_ipaddr  = 10.64.64.64
> I (29739486) gsm-ppp:    netmask     = 255.255.255.255
> I (29739486) gsm-ppp:    our6_ipaddr = ::
> I (29739486) netmanager: Set DNS#0 9.9.9.9
> I (29739486) netmanager: Set DNS#1 8.8.8.8
> I (29739496) netmanager: Interface priority is pp3 (10.170.146.142/255.255.255.255 <http://10.170.146.142/255.255.255.255> gateway 10.64.64.64)
> I (29739496) time: Starting SNTP client
> I (29739516) webserver: Launching Web Server
> I (29739556) ovms-server-v2: Network is up, so attempt network connection
> I (29739566) ovms-server-v2: Connection is tmc.openvehicles.com:6867 <http://tmc.openvehicles.com:6867/> ROADSTER_834/Gdbkt2017server
> I (29739566) ovms-server-v2: Status: Connecting...
> I (29740786) ovms-server-v2: Connection successful
> I (29740786) ovms-server-v2: Status: Logging in...
> I (29740786) ovms-server-v2: Sending server login: MP-C 0 hYmLdxeZxWCwkNgpup0zeB jl/Ifu5Hg8lq+S/PTc4uOQ== ROADSTER_834
> I (29741496) ovms-server-v2: Got server response: MP-S 0 LKP5Qi2E4PlFzPJ7mc4sWd +S88vnrZARs61sAzkivLTg==
> I (29741506) ovms-server-v2: Server token is LKP5Qi2E4PlFzPJ7mc4sWd and digest is +S88vnrZARs61sAzkivLTg==
> I (29741516) ovms-server-v2: Status: Server auth ok. Now priming crypto.
> I (29741516) ovms-server-v2: Shared secret key is LKP5Qi2E4PlFzPJ7mc4sWdhYmLdxeZxWCwkNgpup0zeB (44 bytes)
> I (29741516) ovms-server-v2: Status: OVMS V2 login successful, and crypto channel established
> I (29741526) ovms-server-v2: Incoming Msg: MP-0 Z0
> W (29922436) simcom: 3 minutes since last MUX rx frame - assume MUX has failed
> I (29922436) gsm-ppp: Shutting down (soft)...
> I (29922436) time: Stopping SNTP client
> I (29922436) ovms-server-v2: Network is down, so disconnect network connection
> E (29922436) ovms-server-v2: Status: Error: Disconnected from OVMS Server V2
> I (29922446) gsm-nmea: Shutdown (direct)
> I (29922446) gsm-mux: Stop MUX
> I (29922446) simcom: Power Cycle
> I (29922526) webserver: Stopping Web Server
> I (29923446) simcom: State: Enter PoweringOn state
> I (29923446) simcom: Power Cycle
> I (29931436) simcom: State timeout, transition to 2
> I (29931436) simcom: State: Enter PoweringOn state
> I (29931436) simcom: Power Cycle
> I (29933966) gsm-ppp: StatusCallBack: User Interrupt
> I (29933966) gsm-ppp: PPP connection has been closed
> I (29937576) simcom: State: Enter PoweredOn state
> I (29957456) simcom: State: Enter MuxStart state
> I (29957456) gsm-mux: Start MUX
> I (29957466) gsm-mux: Channel #0 is open
> I (29957476) gsm-mux: Channel #1 is open
> I (29957486) gsm-mux: Channel #2 is open
> I (29957486) gsm-mux: Channel #3 is open
> I (29957496) gsm-mux: Channel #4 is open
> I (29958436) simcom: State: Enter NetWait state
> I (29962436) simcom: State: Enter NetStart state
> I (29963596) simcom: PPP Connection is ready to start
> I (29964436) simcom: State: Enter NetMode state
> I (29964436) gsm-ppp: Initialising...
> I (29967466) gsm-ppp: StatusCallBack: None
> I (29967466) gsm-ppp: status_cb: Connected
> I (29967466) gsm-ppp:    our_ipaddr  = 10.170.146.142
> I (29967466) gsm-ppp:    his_ipaddr  = 10.64.64.64
> I (29967466) gsm-ppp:    netmask     = 255.255.255.255
> I (29967466) gsm-ppp:    our6_ipaddr = ::
> I (29967466) netmanager: Set DNS#0 9.9.9.9
> I (29967466) netmanager: Set DNS#1 8.8.8.8
> I (29967466) netmanager: Interface priority is pp3 (10.170.146.142/255.255.255.255 <http://10.170.146.142/255.255.255.255> gateway 10.64.64.64)
> I (29967466) time: Starting SNTP client
> I (29967486) webserver: Launching Web Server
> I (29967516) ovms-server-v2: Network is up, so attempt network connection
> I (29967516) ovms-server-v2: Connection is tmc.openvehicles.com:6867 <http://tmc.openvehicles.com:6867/> ROADSTER_834/Gdbkt2017server
> I (29967516) ovms-server-v2: Status: Connecting...
> I (29968586) ovms-server-v2: Connection successful
> I (29968596) ovms-server-v2: Status: Logging in...
> I (29968596) ovms-server-v2: Sending server login: MP-C 0 7xW8GUvco/C+bw2wbq8wMm MD0wjvyEyLxp/H+efl4NXg== ROADSTER_834
> I (29969286) ovms-server-v2: Got server response: MP-S 0 AkbsS/NHbhRCN9+tCeUsu5 K9o43t18dAbTMbHRWGwnJg==
> I (29969286) ovms-server-v2: Server token is AkbsS/NHbhRCN9+tCeUsu5 and digest is K9o43t18dAbTMbHRWGwnJg==
> I (29969296) ovms-server-v2: Status: Server auth ok. Now priming crypto.
> I (29969296) ovms-server-v2: Shared secret key is AkbsS/NHbhRCN9+tCeUsu57xW8GUvco/C+bw2wbq8wMm (44 bytes)
> I (29969296) ovms-server-v2: Status: OVMS V2 login successful, and crypto channel established
> I (29969316) ovms-server-v2: Incoming Msg: MP-0 Z0
> I (29970436) ovms-server-v2: Send MP-0 S45.0,K,0,0,stopped,standard,0,0,0,0,0,0,0,21,0,0,0,0,0.00,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,0.00,0
> I (29970436) ovms-server-v2: Send MP-0 D0,0,5,0,0,0,0,0,0,29970,0,0,0,0,0.236264,0,0,0,0,0
> I (29970436) ovms-server-v2: Send MP-0 F3.0.991-91-gffbc545/factory/main build (idf v3.1-dev-429-g7f6161cd) Mar 18 2018 22:02:28,,10,1,TR,
> W (30175436) simcom: 3 minutes since last MUX rx frame - assume MUX has failed
> I (30175436) gsm-ppp: Shutting down (soft)...
> I (30175436) time: Stopping SNTP client
> I (30175436) ovms-server-v2: Network is down, so disconnect network connection
> E (30175436) ovms-server-v2: Status: Error: Disconnected from OVMS Server V2
> I (30175446) gsm-nmea: Shutdown (direct)
> I (30175446) gsm-mux: Stop MUX
> I (30175446) simcom: Power Cycle
> I (30175576) webserver: Stopping Web Server
> I (30176446) simcom: State: Enter PoweringOn state
> I (30176446) simcom: Power Cycle
> I (30184436) simcom: State timeout, transition to 2
> I (30184436) simcom: State: Enter PoweringOn state
> I (30184436) simcom: Power Cycle
> I (30186966) gsm-ppp: StatusCallBack: User Interrupt
> I (30186966) gsm-ppp: PPP connection has been closed
> I (30190536) simcom: State: Enter PoweredOn state
> I (30210436) simcom: State: Enter MuxStart state
> I (30210436) gsm-mux: Start MUX
> I (30210446) gsm-mux: Channel #0 is open
> I (30210446) gsm-mux: Channel #1 is open
> I (30210456) gsm-mux: Channel #2 is open
> I (30210456) gsm-mux: Channel #3 is open
> I (30210466) gsm-mux: Channel #4 is open
> I (30211436) simcom: State: Enter NetWait state
> I (30215436) simcom: State: Enter NetStart state
> I (30216476) simcom: PPP Connection is ready to start
> I (30217436) simcom: State: Enter NetMode state
> I (30217436) gsm-ppp: Initialising...
> I (30289396) gsm-ppp: StatusCallBack: Authentication Failed
> E (30289396) gsm-ppp: status_cb: Failed authentication challenge
> I (30289396) gsm-ppp: Shutdown (via status callback)
> I (30289396) gsm-ppp: Attempting PPP reconnecting in 30 seconds...
> W (30398436) simcom: 3 minutes since last MUX rx frame - assume MUX has failed
> I (30398436) gsm-ppp: Shutting down (soft)...
> W (32631576) gsm-mux: Frame overflow (2048 bytes)
> OVMS> metric list v.b.soc
> v.b.soc                                  45%
> OVMS> metric set v.b.soc 23
> Metric set
> OVMS> 
> OVMS> network
> Interface#3: pp3 (ifup=1 linkup=0)
>   IPv4: 0.0.0.0/255.255.255.255 <http://0.0.0.0/255.255.255.255> gateway 0.0.0.0
> 
> Interface#2: ap2 (ifup=1 linkup=1)
>   IPv4: 192.168.4.1/255.255.255.0 <http://192.168.4.1/255.255.255.0> gateway 192.168.4.1
> 
> Interface#1: st1 (ifup=0 linkup=1)
>   IPv4: 0.0.0.0/0.0.0.0 <http://0.0.0.0/0.0.0.0> gateway 0.0.0.0
> 
> Interface#0: lo0 (ifup=1 linkup=1)
>   IPv4: 127.0.0.1/255.0.0.0 <http://127.0.0.1/255.0.0.0> gateway 127.0.0.1
> 
> DNS: 9.9.9.9 8.8.8.8
> 
> Default Interface: ap2 (192.168.4.1/255.255.255.0 <http://192.168.4.1/255.255.255.0> gateway 192.168.4.1)
> OVMS> simcom
> SIMCOM
>   Network Registration: RegisteredRoaming
>   State: NetMode
>   Ticker: 181
>   User Data: 0
> 
>   Mux
>     Status: up
>     Open Channels: 4
>     Framing Errors: 1533
>     Last RX frame: 181 sec(s) ago
>     RX frames: 9
>     TX frames: 27
> 
>   PPP
>     Not Connected
>     Last Error: Authentication Failed
> 
>   GPS
>     Status: disabled
>     Time: disabled
>     NMEA: GPS/GLONASS Not Connected
> OVMS> 
> 
> _______________________________________________
> OvmsDev mailing list
> OvmsDev at lists.teslaclub.hk
> http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.teslaclub.hk/pipermail/ovmsdev/attachments/20180320/43b928a7/attachment-0001.html>