[Ovmsdev] v3 hardware disconnecting from v2 server

Sun Jan 28 17:59:47 HKT 2018

I've begun working on the webserver and noticed something that may be correlated to this: sockets don't get closed when losing the connection. The effect is
visible on both web and telnet server (ssh not tested). To reproduce, switch the Wifi network with an open connection, the port will not be available until timeout.

Regards,
Michael

Am 28.01.2018 um 03:32 schrieb Tom Parker:
> 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
>
>
>
> _______________________________________________
> OvmsDev mailing list
> OvmsDev at lists.teslaclub.hk
> http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

-- 
Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20180128/66037424/attachment.htm>