[Ovmsdev] v3 hardware disconnecting from v2 server

Tue Feb 6 07:42:14 HKT 2018

On 04/02/18 15:33, Tom Parker wrote:
> I haven't yet had a chance to reproduce the original disconnection 
> problem and see if stopping and starting the v2 server connection helps.

It does not help. I've seen a stack overflow during server v2 stop, but 
the backtrace didn't make any sense so I think I might have run 
addr2line on the wrong binary.

I've also seen the server v2 stop work. Below we see the server v2 
sending messages to the server which are not being received. I restarted 
the server v2 and then it noticed that it could not connect. Then I 
tried restarting the simcom and that didn't restore network 
connectivity. Only when I reset it with the button did it reconnect. 
I've tried this simcom power cycle to restore connectivity several times 
and it's never worked once it's in this bad state.

It feels like the simcom state machine has a bug where it thinks that it 
is connected but actually it isn't, so it never reconnects. This bug 
appears to persist over simcom power cycles. I've now got verbose 
logging turned on and I've removed modemmanager on my data logging 
laptop so hopefully I'll have some more information about the cause.

I (3929403) ovms-server-v2: Send MP-0 F3.0.0/factory/main build (idf 
v3.1-dev-217-g5bf85d0) Feb  4 2018 02:36:19,,2,1,NL,2degrees
OVMS > I (3961393) ovms-server-v2: Send MP-0 
S35,K,0,0,stopped,standard,29,0,0,0,0,0,13,21,0,0,0,0,62.23,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,373.00,94
OVMS > I (3990393) ovms-server-v2: Send MP-0 
S35,K,0,0,stopped,standard,29,0,0,0,0,0,13,21,0,0,0,0,62.23,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,371.00,94
I (3990393) ovms-server-v2: Send MP-0 
D128,0,5,0,0,27,0,0,49,3990,22,1,1,1,13.0385,0,0,128,0,0
I (3990403) ovms-server-v2: Send MP-0 L0,0,0,0,0,0,49,0,0,0,0
OVMS > I (4051393) ovms-server-v2: Send MP-0 
S34,K,0,0,stopped,standard,29,0,0,0,0,0,13,21,0,0,0,0,62.23,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,370.00,94
I (4051393) ovms-server-v2: Send MP-0 
D128,0,5,0,0,27,0,0,17,4051,22,1,1,1,12.9945,0,0,128,0,0
I (4051403) ovms-server-v2: Send MP-0 L0,0,0,0,0,0,17,0,0,0,0
OVMS > simcom status
SIMCOM
   Network Registration: RegisteredHome
   State: NetMode
   Ticker: 618
   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
OVMS > simcom      server v2 stop
Stopping OVMS Server V2 connection (oscv2)
OVMS > E (4104393) ovms-server-v2: Status: Error: Disconnected from OVMS 
Server V2
OVMS > server v2 start
Launching OVMS Server V2 connection (oscv2)
OVMS > I (4108553) ovms-server-v2: Status: Starting
I (4108553) ovms-server-v2: OVMS Server v2 running
I (4108553) ovms-server-v2: Connection is ovms.dexters-web.de:6867 
NZLV3/Iekei2ae
I (4108553) ovms-server-v2: Status: Connecting...
OVMS > W (4119433) ovms-server-v2: Connection failed
E (4119443) ovms-server-v2: Status: Error: Disconnected from OVMS Server V2
OVMS > simocom      com power off
Unrecognised command
OVMS > power simcom off
Power mode of simcom is now off
OVMS > I (4139133) simcom: State: Enter PoweringOff state
I (4139133) gsm-ppp: Shutting down (soft)...
I (4139133) ovms-server-v2: Network is reconfigured, so disconnect 
network connection
I (4139153) gsm-nmea: Shutdown (direct)
I (4139153) simcom: Power Cycle
OVMS > I (4149393) simcom: State timeout, transition to 1
I (4149393) simcom: State: Enter CheckPowerOff state
OVMS > I (4151153) gsm-ppp: StatusCallBack: User Interrupt
I (4151153) gsm-ppp: PPP connection has been closed
OVMS > D (4160393) simcom: tx scmd ch=0 len=4   : AT||
OVMS > D (4161393) simcom: tx scmd ch=0 len=4   : AT||
OVMS > D (4162393) simcom: tx scmd ch=0 len=4   : AT||
OVMS > D (4163393) simcom: tx scmd ch=0 len=4   : AT||
OVMS > D (4164393) simcom: tx scmd ch=0 len=4   : AT||
I (4164393) simcom: State timeout, transition to 13
I (4164393) simcom: State: Enter PoweredOff state
OVMS > simnc  cmpower simcom off  n
Power mode of simcom is now on
OVMS > I (4178943) simcom: State: Enter PoweringOn state
I (4178943) simcom: Power Cycle
D (4179393) simcom: tx scmd ch=0 len=4   : AT||
OVMS > D (4180393) simcom: tx scmd ch=0 len=4   : AT||
OVMS > D (4181393) simcom: tx scmd ch=0 len=4   : AT||
OVMS > D (4182393) simcom: tx scmd ch=0 len=4   : AT||
OVMS > D (4183393) simcom: tx scmd ch=0 len=4   : AT||
OVMS > D (4184393) simcom: tx scmd ch=0 len=4   : AT||
OVMS > I (4184883) simcom: State: Enter PoweredOn state
OVMS > D (4188213) simcom: rx line ch=0 len=12  : +CPIN: READY
D (4188213) simcom: rx line ch=0 len=12  : OPL UPDATING
D (4188213) simcom: rx line ch=0 len=12  : PNN UPDATING
OVMS > D (4189783) simcom: rx line ch=0 len=8   : SMS DONE
OVMS > D (4192823) simcom: rx line ch=0 len=10  : CALL READY
D (4192823) simcom: rx line ch=0 len=7   : PB DONE
OVMS > D (4194393) simcom: tx scmd ch=0 len=103 : 
AT+CPIN?;+CREG=1;+CTZU=1;+CTZR=1;+CLIP=1;+CMGF=1;+CNMI=1,2,0,0,0;+CSDH=1;+CMEE=2;+CSQ;+AUTOCSQ=1,1;E0||
D (4194453) simcom: rx line ch=0 len=101 : 
AT+CPIN?;+CREG=1;+CTZU=1;+CTZR=1;+CLIP=1;+CMGF=1;+CNMI=1,2,0,0,0;+CSDH=1;+CMEE=2;+CSQ;+AUTOCSQ=1,1;E0
D (4194533) simcom: rx line ch=0 len=12  : +CPIN: READY
D (4194533) simcom: rx line ch=0 len=10  : +CSQ: 6,99
D (4194543) simcom: rx line ch=0 len=2   : OK
OVMS > D (4196393) simcom: tx scmd ch=0 len=16  : AT+CGMR;+ICCID||
D (4196463) simcom: rx line ch=0 len=23  : +CGMR: 35316B10SIM5360E
D (4196463) simcom: rx line ch=0 len=27  : +ICCID: 8964240002011263238
D (4196463) simcom: rx line ch=0 len=2   : OK
OVMS > D (4199393) simcom: tx scmd ch=0 len=8   : AT+COPS?
OVMS > D (4200393) simcom: tx scmd ch=0 len=20  : AT+CMUXSRVPORT=3,1||
D (4200393) simcom: rx line ch=0 len=5   : ERROR
OVMS > D (4201393) simcom: tx scmd ch=0 len=20  : AT+CMUXSRVPORT=2,1||
D (4201403) simcom: rx line ch=0 len=2   : OK
OVMS > D (4202393) simcom: tx scmd ch=0 len=20  : AT+CMUXSRVPORT=1,1||
D (4202403) simcom: rx line ch=0 len=2   : OK
OVMS > D (4203393) simcom: tx scmd ch=0 len=20  : AT+CMUXSRVPORT=0,5||
D (4203423) simcom: rx line ch=0 len=2   : OK
OVMS > D (4204393) simcom: tx scmd ch=0 len=11  : AT+CMUX=0||
D (4204403) simcom: rx line ch=0 len=2   : OK
I (4204403) simcom: State: Enter MuxStart state
I (4204403) gsm-mux: Start MUX
I (4204413) gsm-mux: Channel #0 is open
I (4204423) gsm-mux: Channel #1 is open
I (4204423) gsm-mux: Channel #2 is open
I (4204433) gsm-mux: Channel #3 is open
I (4204443) gsm-mux: Channel #4 is open
OVMS > D (4234413) simcom: rx line ch=3 len=10  : +CREG: 1,1
D (4234423) simcom: rx line ch=3 len=29  : +CCLK: "18/02/05,16:46:44+52"
D (4234423) simcom: rx line ch=3 len=10  : +CSQ: 6,99
D (4234423) simcom: rx line ch=3 len=23  : +COPS: 0,0,"2degrees",2
D (4234423) simcom: rx line ch=3 len=2   : OK
OVMS > D (4264413) simcom: rx line ch=3 len=10  : +CREG: 1,1
D (4264413) simcom: rx line ch=3 len=29  : +CCLK: "18/02/05,16:47:14+52"
D (4264413) simcom: rx line ch=3 len=10  : +CSQ: 6,99
D (4264413) simcom: rx line ch=3 len=23  : +COPS: 0,0,"2degrees",2
D (4264413) simcom: rx line ch=3 len=2   : OK