[Ovmsdev] v3 hardware disconnecting from v2 server

Sun Jan 28 10:32:30 HKT 2018

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

-------------- next part --------------
A non-text attachment was scrubbed...
Name: _-ovm-serverlogs.csv.bz2
Type: application/x-bzip
Size: 26756 bytes
Desc: not available
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20180128/e05be45e/attachment-0004.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: ovms_2018-01-26T04:46:05+00:00.log.bz2
Type: application/x-bzip
Size: 6063 bytes
Desc: not available
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20180128/e05be45e/attachment-0005.bin>