[Ovmsdev] v3 hardware disconnecting from v2 server

Mon Jan 29 08:07:49 HKT 2018

I don’t think we currently have any ping / timeout support in the v2 server module. We did that in ovms v2, and certainly need it in the new system. That should deal with things at the tcp/ip level. It seems our LWIP code supports TCP keepalive, and the server code definitely enables that. Perhaps we need to enable it on the client side too?

The bigger issue is the PPP level, and I’m not sure how to reliably detect issues there. Also not sure if the issue you are seeing is at the TCP server connection level, or low level PPP transport. Do you know if you restart the v2 server module, but leave the simcom connection as it is, does that resolve it?

Regards, Mark

> On 28 Jan 2018, at 10:32 AM, Tom Parker <tom at carrott.org> wrote:
> 
> Hi,
> 
> I've been struggling for some time with intermittent disconnections from the v2 server. I've switched from hologram to a local cellular provider's sim card, to match my v2 hardware which is very stable and the problem persists. With the car stationary, the connection seems very solid, but on the move, it usually disconnects within half an hour.
> 
> I'm running 98169d8862db2bbc4bea14d013883f26ee6afb4e (from 2018-01-19) with idf 5bf85d06d8c402fe30ecb1bf9c09d5e69b923b2f and xtensa-esp32-elf-linux64-1.22.0-80-g6c4433a-5.2.0.tar.gz.
> 
> I tried logging to the sdcard and on my desk powered by USB that seemed to work well, but it didn't work very well (only a few lines logged to the sdcard and then the whole system seemed to crash) when powered from the OBD2 port. I haven't tried to debug that.
> 
> With the sdcard logging turned off, and logging with minicom I can get good diagnostics. It would appear that the v3 hardware thinks it is still connected and continues to send data, but the v2 server thinks the client has disconnected.
> 
> I've got ovms logs which have regular lines quoting the local time from the modem, and server logs from the dexters-web server which I think are not UTC. Anyway, 05:47 in the server log corresponds to 17:47 in the ovms v3 log.
> 
> The relevant lines of the logs are below. On the server log the ovms v3 hardware client is #72 and then #94. We can see the client sent and the server received S messages at :47:15 and :47:32. The client sent more messages that were not received by the server, more than I've transcribed here (full log attached). The server recorded a disconnect at :48:29, but the client recorded the transmission of messages in it's log for minutes after that. I did a simcom status command which reports that everything is connected, and then I pressed the button to reboot the module. The server records a new connection at :54:07 and the messages logged as transmitted on the client start to correspond with the messages logged as received on the server start again.
> 
> Thoughts on how to proceed?
> 
> Another oddity not shown here but included in the full logs is that the client sent a lot of D messages shortly after reconnecting.
> 
> Server Log:
> 
> 2018-01-26 05:47:15,36664,'#72 C rx msg S 90,K,0,0,stopped,standard,76,0,0,0,0,0,13,21,0,0,0,0,63.36,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,392.00,96'
> 2018-01-26 05:47:15,36665,'#72 C rx msg D 128,0,5,0,0,33,0,0,0,79663,32,1,1,1,12.9231,0,0,128,0,0'
> 2018-01-26 05:47:15,36666,'#72 C rx msg L 0,0,0,0,0,0,0,0,0,0,0'
> 2018-01-26 05:47:15,36667,'#72 C rx msg F 3.0.0/factory/main build (idf v3.1-dev-217-g5bf85d0) Jan 20 2018 00:49:15,,6,1,NL,2degrees'
> 2018-01-26 05:47:32,36717,'#72 C rx msg S 90,K,0,0,stopped,standard,76,0,0,0,0,0,13,21,0,0,0,0,63.36,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,387.00,96'
> 2018-01-26 05:48:29,36926,'#72 C got error: Connection reset by peer'
> 2018-01-26 05:50:08,37206,'#93 A got login'
> 2018-01-26 05:51:24,37485,'#36 A rx msg A '
> 2018-01-26 05:52:53,37742,'#93 A got error: Broken pipe'
> 2018-01-26 05:52:54,37745,'#72 A got login'
> 2018-01-26 05:54:07,37937,'#94 C got login'
> 2018-01-26 05:54:13,37957,'#94 C rx msg S 87,K,0,0,stopped,standard,73,0,0,0,0,0,13,21,0,0,0,0,0.00,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,385.50,0'
> 2018-01-26 05:54:13,37958,'#94 C rx msg D 128,0,5,0,0,33,0,0,104,59,28,1,0,0,13.011,0,0,128,0,0'
> 2018-01-26 05:54:13,37959,'#94 C rx msg L 0,0,0,0,0,0,104,0,0,0,0'
> 2018-01-26 05:54:13,37960,'#94 C rx msg W 0,0,0,0,0,0,0,0,0'
> 2018-01-26 05:54:13,37961,'#94 C rx msg F 3.0.0/factory/main build (idf v3.1-dev-217-g5bf85d0) Jan 20 2018 00:49:15,,1,1,NL,2degrees'
> 2018-01-26 05:54:15,37964,'#94 C rx msg D 128,0,5,0,0,33,0,0,104,60,28,1,0,0,13.011,0,0,128,0,0'
> 2018-01-26 05:54:15,37965,'#94 C rx msg D 128,0,5,0,0,33,0,0,104,61,28,1,0,0,13.011,0,0,128,0,0'
> 
> Serial Console Log:
> 
> OVMS > I (79663340) ovms-server-v2: Send MP-0 S90,K,0,0,stopped,standard,76,0,0,0,0,0,13,21,0,0,0,0,63.36,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,392.00,96
> I (79663340) ovms-server-v2: Send MP-0 D128,0,5,0,0,33,0,0,0,79663,32,1,1,1,12.9231,0,0,128,0,0
> I (79663340) ovms-server-v2: Send MP-0 L0,0,0,0,0,0,0,0,0,0,0
> I (79663350) ovms-server-v2: Send MP-0 F3.0.0/factory/main build (idf v3.1-dev-217-g5bf85d0) Jan 20 2018 00:49:15,,6,1,NL,2degrees
> OVMS > D (79665360) simcom: rx line ch=3 len=11  : +CSQ: 10,99
> D (79665360) simcom: rx line ch=4 len=11  : +CSQ: 10,99
> OVMS > D (79674380) simcom: rx line ch=3 len=11  : +CSQ: 13,99
> D (79674390) simcom: rx line ch=4 len=11  : +CSQ: 13,99
> OVMS > D (79678420) simcom: rx line ch=3 len=10  : +CREG: 1,1
> D (79678420) simcom: rx line ch=3 len=29  : +CCLK: "18/01/26,17:47:26+52"
> D (79678420) simcom: rx line ch=3 len=11  : +CSQ: 13,99
> D (79678420) simcom: rx line ch=3 len=23  : +COPS: 0,0,"2degrees",2
> D (79678420) simcom: rx line ch=3 len=2   : OK
> OVMS > I (79681340) ovms-server-v2: Send MP-0 S90,K,0,0,stopped,standard,76,0,0,0,0,0,13,21,0,0,0,0,63.36,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,387.00,96
> OVMS > D (79683370) simcom: rx line ch=3 len=10  : +CSQ: 9,99
> D (79683370) simcom: rx line ch=4 len=10  : +CSQ: 9,99
> OVMS > D (79692410) simcom: rx line ch=3 len=10  : +CSQ: 3,99
> D (79692420) simcom: rx line ch=4 len=10  : +CSQ: 3,99
> OVMS > D (79708420) simcom: rx line ch=3 len=10  : +CREG: 1,1
> D (79708420) simcom: rx line ch=3 len=29  : +CCLK: "18/01/26,17:47:56+52"
> D (79708420) simcom: rx line ch=3 len=10  : +CSQ: 3,99
> D (79708420) simcom: rx line ch=3 len=23  : +COPS: 0,0,"2degrees",2
> D (79708420) simcom: rx line ch=3 len=2   : OK
> OVMS > D (79713470) simcom: rx line ch=3 len=10  : +CSQ: 7,99
> D (79713470) simcom: rx line ch=4 len=10  : +CSQ: 7,99
> OVMS > D (79716420) simcom: rx line ch=3 len=10  : +CSQ: 0,99
> D (79716420) simcom: rx line ch=4 len=10  : +CSQ: 0,99
> OVMS > I (79724340) ovms-server-v2: Send MP-0 S90,K,0,0,stopped,standard,76,0,0,0,0,0,13,21,0,0,0,0,63.36,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,392.00,96
> I (79724340) ovms-server-v2: Send MP-0 D128,0,5,0,0,33,0,0,55,79724,30,1,1,1,13.022,0,0,128,0,0
> I (79724350) ovms-server-v2: Send MP-0 L0,0,0,0,0,0,55,0,0,0,0
> I (79724350) ovms-server-v2: Send MP-0 F3.0.0/factory/main build (idf v3.1-dev-217-g5bf85d0) Jan 20 2018 00:49:15,,0,1,NL,2degrees
> OVMS > D (79738360) simcom: rx line ch=3 len=10  : +CREG: 1,1
> D (79738360) simcom: rx line ch=3 len=29  : +CCLK: "18/01/26,17:48:26+52"
> D (79738360) simcom: rx line ch=3 len=10  : +CSQ: 0,99
> D (79738360) simcom: rx line ch=3 len=23  : +COPS: 0,0,"2degrees",2
> D (79738360) simcom: rx line ch=3 len=2   : OK
> OVMS > D (79740490) simcom: rx line ch=3 len=10  : +CSQ: 4,99
> D (79740500) simcom: rx line ch=4 len=10  : +CSQ: 4,99
> OVMS > I (79741340) ovms-server-v2: Send MP-0 S90,K,0,0,stopped,standard,76,0,0,0,0,0,13,21,0,0,0,0,63.36,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,388.50,96
> OVMS > D (79764490) simcom: rx line ch=3 len=10  : +CSQ: 7,99
> D (79764490) simcom: rx line ch=4 len=10  : +CSQ: 7,99
> OVMS > D (79768360) simcom: rx line ch=3 len=10  : +CREG: 1,1
> D (79768360) simcom: rx line ch=3 len=29  : +CCLK: "18/01/26,17:48:56+52"
> D (79768360) simcom: rx line ch=3 len=10  : +CSQ: 7,99
> D (79768360) simcom: rx line ch=3 len=23  : +COPS: 0,0,"2degrees",2
> D (79768360) simcom: rx line ch=3 len=2   : OK
> OVMS > D (79773490) simcom: rx line ch=3 len=10  : +CSQ: 3,99
> D (79773500) simcom: rx line ch=4 len=10  : +CSQ: 3,99
> OVMS > D (79779500) simcom: rx line ch=3 len=10  : +CSQ: 7,99
> D (79779500) simcom: rx line ch=4 len=10  : +CSQ: 7,99
> OVMS > I (79785340) ovms-server-v2: Send MP-0 S89,K,0,0,stopped,standard,75,0,0,0,0,0,13,21,0,0,0,0,63.36,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,378.00,96
> ...
> OVMS > simcom status
> SIMCOM
>   Network Registration: RegisteredHome
>   State: NetMode
>   Ticker: 25111
>   User Data: 0
>   Mux Open Channels: 4
>   PPP Connected on channel: #2
>   PPP Last Error: None
>   GPS: disabled
>   GPS time: disabled
>   NMEA (GPS/GLONASS) Not Connected
> ...
> I rebooted the module and it did the normal connection dance
> ...
> D (48359) simcom: rx line ch=3 len=29  : +CCLK: "18/01/26,17:53:57+52"
> ...
> I (57609) ovms-server-v2: Status: Connecting...
> OVMS > I (58219) ovms-server-v2: Connection successful
> I (58219) ovms-server-v2: Status: Logging in...
> I (58219) ovms-server-v2: Sending server login: MP-C 0 pwLSijW/3qAZ6z0LOBHbGS rnkkhqHUA6zeZqLx1q1Tow== NZLV3
> OVMS > I (58889) ovms-server-v2: Got server response: MP-S 0 QTjRAp8ZQPJQV1UXnepldQ w1vWpIrRR9+eot9z3uslgw==
> I (58889) ovms-server-v2: Server token is QTjRAp8ZQPJQV1UXnepldQ and digest is w1vWpIrRR9+eot9z3uslgw==
> I (58899) ovms-server-v2: Status: Server auth ok. Now priming crypto.
> I (58899) ovms-server-v2: Shared secret key is QTjRAp8ZQPJQV1UXnepldQpwLSijW/3qAZ6z0LOBHbGS (44 bytes)
> I (58899) ovms-server-v2: Status: OVMS V2 login successful, and crypto channel established
> OVMS > I (59189) ovms-server-v2: Incoming Msg: MP-0 Z4
> I (59189) ovms-server-v2: One or more peers have connected
> I (59339) ovms-server-v2: Send MP-0 S87,K,0,0,stopped,standard,73,0,0,0,0,0,13,21,0,0,0,0,0.00,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,385.50,0
> 
> <_-ovm-serverlogs.csv.bz2><ovms_2018-01-26T04:46:05+00:00.log.bz2>_______________________________________________
> OvmsDev mailing list
> OvmsDev at lists.teslaclub.hk
> http://lists.teslaclub.hk/mailman/listinfo/ovmsdev