Regards, Mark.

On 14 Feb 2018, at 1:57 PM, Mark Webb-Johnson <mark@webb-johnson.net> wrote:

It seems that around 4045393 in the logs the simcom driver thinks it is in mux mode, but the modem is not. The modem is just transmitting raw AT commands, not framed in gsm-mux.

The gsm-mux framing starts with a f9 and ends with a checksum then f9 again. Like this:

V (119553) gsm-ppp: tx: 7e 21 45 00 00 7a 00 34 00 00 ff 06 08 58 64 66 | ~!E..z.4.....Xdf
V (119553) gsm-ppp: tx: 46 1c bc 8a 4b e5 fa 3c 1a d3 00 00 2f 84 b9 bc | F...K..<..../...
V (119553) gsm-ppp: tx: 8d 1c 50 18 16 2a 31 ce 00 00 31 78 4b 44 45 79 | ..P..*1...1xKDEy
V (119553) gsm-ppp: tx: 35 5a 35 6e 4b 35 66 35 2b 62 70 56 6a 52 2b 34 | 5Z5nK5f5+bpVjR+4
V (119553) gsm-ppp: tx: 59 49 44 62 44 68 6c 63 66 72 47 54 50 44 45 56 | YIDbDhlcfrGTPDEV
V (119553) gsm-ppp: tx: 2b 65 42 59 78 4d 49 41 31 4c 42 77 4d 52 45 7a | +eBYxMIA1LBwMREz
V (119553) gsm-ppp: tx: 79 36 44 74 76 2b 58 56 41 36 61 51 58 51 36 46 | y6Dtv+XVA6aQXQ6F
V (119553) gsm-ppp: tx: 73 49 42 4e 4c 59 48 41 3d 3d 0d 0a bd aa 7e | sIBNLYHA==....~
V (119553) simcom: tx: f9 09 ff ff 7e 21 45 00 00 7a 00 34 00 00 ff 06 | ....~!E..z.4....
V (119553) simcom: tx: 08 58 64 66 46 1c bc 8a 4b e5 fa 3c 1a d3 00 00 | .XdfF...K..<....
V (119553) simcom: tx: 2f 84 b9 bc 8d 1c 50 18 16 2a 31 ce 00 00 31 78 | /.....P..*1...1x
V (119553) simcom: tx: 4b 44 45 79 35 5a 35 6e 4b 35 66 35 2b 62 70 56 | KDEy5Z5nK5f5+bpV
V (119553) simcom: tx: 6a 52 2b 34 59 49 44 62 44 68 6c 63 66 72 47 54 | jR+4YIDbDhlcfrGT
V (119553) simcom: tx: 50 44 45 56 2b 65 42 59 78 4d 49 41 31 4c 42 77 | PDEV+eBYxMIA1LBw
V (119553) simcom: tx: 4d 52 45 7a 79 36 44 74 76 2b 58 56 41 36 61 51 | MREzy6Dtv+XVA6aQ
V (119553) simcom: tx: 58 51 36 46 73 49 42 4e 4c 59 48 41 3d 3d 0d 0a | XQ6FsIBNLYHA==..
V (119553) simcom: tx: bd aa 7e 9a f9 | ..~..

There was a network disconnection around 552393, recovered well. Another at 2080493, also recovered well.

But then around 2666343 we lose gms mux framing.

V (2666333) simcom: rx: 14 f9 f9 11 ff 19 0d 0a 2b 43 52 45 47 3a 20 32 | ........+CREG: 2
V (2666333) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=14, LEN=18)
V (2666333) gsm-mux: ChanProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, LEN=15, IFP=3)
D (2666333) simcom: rx line ch=3 len=8 : +CREG: 2
I (2666343) simcom: CREG Network Registration: Searching
V (2666343) simcom: rx: 0d 0a 19 f9 | ....
V (2666343) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff, FCS=19, LEN=18)
V (2666343) gsm-mux: ChanProcessFrame(CHAN=4, ADDR=11, CTRL=ff, LEN=15, IFP=3)
D (2666343) simcom: rx line ch=4 len=8 : +CREG: 2
I (2666393) simcom: Lost network connection (NetworkRegistration in NetMode)
I (2666393) simcom: State: Enter NetLoss state
V (2666393) simcom: tx: f9 0d ff 19 41 54 2b 43 47 41 54 54 3d 30 0d 0a | ....AT+CGATT=0..
V (2666393) simcom: tx: 14 f9 | ..
I (2666393) gsm-ppp: Shutting down (hard)...
I (2666393) ovms-server-v2: Network is reconfigured, so disconnect network connection
E (2666393) ovms-server-v2: Status: Error: Disconnected from OVMS Server V2
I (2666403) gsm-ppp: StatusCallBack: User Interrupt
I (2666403) gsm-ppp: PPP connection has been closed
V (2666493) simcom: rx: f9 0d ff 0d 0d 0a 4f 4b 0d 0a 0f f9 | ......OK....
V (2666503) simcom: rx: f9 0d ff 1f 0d 0a 2b 43 53 51 3a 20 33 31 2c 39 | ......+CSQ: 31,9
V (2666503) simcom: rx: 39 0d 0a f0 f9 f9 11 ff 1f 0d 0a 2b 43 53 51 3a | 9..........+CSQ:
V (2666503) simcom: rx: 20 33 31 2c 39 39 0d 0a fd f9 f9 0d ff 19 0d 0a | 31,99..........
V (2666503) simcom: rx: 2b 43 52 45 47 3a 20 31 0d 0a 14 f9 f9 11 ff 19 | +CREG: 1........
V (2666503) simcom: rx: 0d 0a 2b 43 52 45 47 3a 20 31 0d 0a 19 f9 | ..+CREG: 1....
V (2666513) simcom: rx: f9 09 ff 23 7e ff 7d 23 c0 21 7d 25 7d 32 7d 20 | ...#~.}#.!}%}2}
V (2666513) simcom: rx: 7d 24 cc ad 7e 1f f9 f9 0d ff 2f 0d 0a 2b 50 50 | }$..~...../..+PP
V (2666513) simcom: rx: 50 44 3a 20 44 49 53 43 4f 4e 4e 45 43 54 45 44 | PD: DISCONNECTED
V (2666513) simcom: rx: 0d 0a d4 f9 f9 11 ff 2f 0d 0a 2b 50 50 50 44 3a | ......./..+PPPD:
V (2666513) simcom: rx: 20 44 49 53 43 4f 4e 4e 45 43 54 45 44 0d 0a d9 | DISCONNECTED...
V (2666513) simcom: rx: f9 | .
V (2666703) mongoose: mg_close_conn 44002356 0x3ffe8230 2048 8201
V (2666703) mongoose: mg_socket_if_destroy 1754 nc=0x3ffe8230 sock=8201 flags=800
V (2666703) mongoose: mg_call 3806 0x3ffe8230 user ev=5 ev_data=0x0 flags=2048 rmbl=0 smbl=0
V (2666703) ovms-server-v2: OvmsServerV2MongooseCallback(MG_EV_CLOSE)
V (2666713) mongoose: mg_call 4587 0x3ffe8230 after user flags=2048 rmbl=0 smbl=0
V (2666723) mongoose: mg_mgr_free 12130 0x3ffb71f8
OVMS > gytdercvghnjm=k',.=uigyryr6 ,kjbuhygb vg bV (2667003) simcom: rx: f9 0d ff 1d 0d 0a 2b 43 53 51 3a 20 30 2c 39 39 | ......+CSQ: 0,99
V (2667003) simcom: rx: 0d 0a 13 f9 f9 11 ff 1d 0d 0a 2b 43 53 51 3a 20 | ..........+CSQ:
V (2667013) simcom: rx: 30 2c 39 39 0d 0a 1e f9 | 0,99....
OVMS > gytdercvghnjm=k',.=uigyryr6 ,kjbuhygb vg bV (2669253) simcom: rx: f9 0d ff 1f 0d 0a 2b 43 53 51 3a 20 31 35 2c 39 | ......+CSQ: 15,9
V (2669263) simcom: rx: 39 0d 0a f0 f9 f9 11 ff 1f 0d 0a 2b 43 53 51 3a | 9..........+CSQ:
V (2669263) simcom: rx: 20 31 35 2c 39 39 0d 0a fd f9 f9 0d ff 19 0d 0a | 15,99..........
V (2669263) simcom: rx: 2b 43 52 45 47 3a 20 32 0d 0a 14 f9 f9 11 ff 19 | +CREG: 2........
V (2669263) simcom: rx: 0d 0a 2b 43 52 45 47 3a 20 32 0d 0a 19 f9 | ..+CREG: 2....
OVMS > gytdercvghnjm=k',.=uigyryr6 ,kjbuhygb vg bV (2669503) simcom: rx: f9 09 ff 25 7e ff 7d 23 c0 21 7d 25 7d 33 7d 20 | ...%~.}#.!}%}3}
V (2669503) simcom: rx: 7d 24 7d 30 f7 7e fb f9 | }$}0.~..
OVMS > gytdercvghnjm=k',.=uigyryr6 ,kjbuhygb vg bV (2670013) simcom: rx: f9 0d ff 1f 0d 0a 2b 43 53 51 3a 20 31 32 2c 39 | ......+CSQ: 12,9
V (2670013) simcom: rx: 39 0d 0a f0 f9 f9 11 ff 1f 0d 0a 2b 43 53 51 3a | 9..........+CSQ:
V (2670013) simcom: rx: 20 31 32 2c 39 39 0d 0a fd f9 | 12,99....

The gsm-mux seems no longer able to decode the incoming frames. It seems to recover for a while, but then the mux fails completely around 2705413:

V (2695413) simcom: rx: f9 0d ff 9f 0d 0a 2b 43 52 45 47 3a 20 31 2c 32 | ......+CREG: 1,2
V (2695423) simcom: rx: 0d 0a 0d 0a 2b 43 43 4c 4b 3a 20 22 31 38 2f 30 | ....+CCLK: "18/0
V (2695423) simcom: rx: 32 2f 30 39 2c 31 37 3a 34 39 3a 34 39 2b 35 32 | 2/09,17:49:49+52
V (2695423) simcom: rx: 22 0d 0a 0d 0a 2b 43 53 51 3a 20 30 2c 39 39 0d | "....+CSQ: 0,99.
V (2695423) simcom: rx: 0a 0d 0a 2b 43 4f 50 53 3a 20 30 0d 0a 0d 0a 4f | ...+COPS: 0....O
V (2695423) simcom: rx: 4b 0d 0a 10 f9 | K....
V (2695423) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, FCS=10, LEN=85)
V (2695423) gsm-mux: ChanProcessFrame(CHAN=3, ADDR=0d, CTRL=ff, LEN=82, IFP=3)
D (2695423) simcom: rx line ch=3 len=10 : +CREG: 1,2
D (2695423) simcom: rx line ch=3 len=29 : +CCLK: "18/02/09,17:49:49+52"
D (2695423) simcom: rx line ch=3 len=10 : +CSQ: 0,99
D (2695423) simcom: rx line ch=3 len=8 : +COPS: 0
D (2695423) simcom: rx line ch=3 len=2 : OK
OVMS > gytdercvghnjm=k',.=uigyryr6 ,kjbuhygb vg bV (2703403) simcom: rx: 0d 0a 53 54 41 52 54 0d 0a | ..START..
OVMS > gytdercvghnjm=k',.=uigyryr6 ,kjbuhygb vg bV (2705393) simcom: tx: f9 0d ff 3b 41 54 2b 43 52 45 47 3f 3b 2b 43 43 | ...;AT+CREG?;+CC
V (2705393) simcom: tx: 4c 4b 3f 3b 2b 43 53 51 3b 2b 43 4f 50 53 3f 0d | LK?;+CSQ;+COPS?.
V (2705393) simcom: tx: 0a cf f9 | ...
V (2705403) simcom: rx: 41 54 2b 43 52 45 47 3f 3b 2b 43 43 4c 4b 3f 3b | AT+CREG?;+CCLK?;
V (2705403) simcom: rx: 2b 43 53 51 3b 2b 43 4f 50 53 3f 0d | +CSQ;+COPS?.
V (2705413) simcom: rx: 0d 0a 2b 43 52 45 47 3a 20 30 2c 32 0d 0a 0d 0a | ..+CREG: 0,2....
V (2705413) simcom: rx: 2b 43 43 4c 4b 3a 20 22 31 38 2f 30 32 2f 30 39 | +CCLK: "18/02/09
V (2705413) simcom: rx: 2c 31 37 3a 34 39 3a 35 39 2b 35 32 22 0d 0a 0d | ,17:49:59+52"...
V (2705413) simcom: rx: 0a 2b 43 53 51 3a 20 30 2c 39 39 0d 0a 0d 0a 45 | .+CSQ: 0,99....E
V (2705413) simcom: rx: 52 52 4f 52 0d 0a | RROR..
OVMS > gytdercvghnjm=k',.=uigyryr6 ,kjbuhygb vg bV (2706283) simcom: rx: 0d 0a 2b 43 50 49 4e 3a 20 52 45 41 44 59 0d 0a | ..+CPIN: READY..
V (2706283) simcom: rx: 0d 0a 4f 50 4c 20 55 50 44 41 54 49 4e 47 0d 0a | ..OPL UPDATING..
V (2706293) simcom: rx: 0d 0a 50 4e 4e 20 55 50 44 41 54 49 4e 47 0d 0a | ..PNN UPDATING..
OVMS > gytdercvghnjm=k',.=uigyryr6 ,kjbuhygb vg bV (2707863) simcom: rx: 0d 0a 53 4d 53 20 44 4f 4e 45 0d 0a | ..SMS DONE..
OVMS > gytdercvghnjm=k',.=uigyryr6 ,kjbuhygb vg bV (2711073) simcom: rx: 0d 0a 43 41 4c 4c 20 52 45 41 44 59 0d 0a 0d 0a | ..CALL READY....
V (2711073) simcom: rx: 50 42 20 44 4f 4e 45 0d 0a | PB DONE..
OVMS > gytdercvghnjm=k',.=uigyryr6 ,kjbuhygb vg bV (2715393) simcom: tx: f9 0d ff 3b 41 54 2b 43 52 45 47 3f 3b 2b 43 43 | ...;AT+CREG?;+CC
V (2715393) simcom: tx: 4c 4b 3f 3b 2b 43 53 51 3b 2b 43 4f 50 53 3f 0d | LK?;+CSQ;+COPS?.
V (2715393) simcom: tx: 0a cf f9 | ...
V (2715403) simcom: rx: 41 54 2b 43 52 45 47 3f 3b 2b 43 43 4c 4b 3f 3b | AT+CREG?;+CCLK?;
V (2715403) simcom: rx: 2b 43 53 51 3b 2b 43 4f 50 53 3f 0d | +CSQ;+COPS?.
V (2715413) simcom: rx: 0d 0a 2b 43 52 45 47 3a 20 30 2c 31 0d 0a 0d 0a | ..+CREG: 0,1....
V (2715423) simcom: rx: 2b 43 43 4c 4b 3a 20 22 31 38 2f 30 32 2f 30 39 | +CCLK: "18/02/09
V (2715423) simcom: rx: 2c 31 37 3a 35 30 3a 31 30 2b 35 32 22 0d 0a 0d | ,17:50:10+52"...
V (2715423) simcom: rx: 0a 2b 43 53 51 3a 20 35 2c 39 39 0d 0a 0d 0a 2b | .+CSQ: 5,99....+
V (2715423) simcom: rx: 43 4f 50 53 3a 20 30 2c 30 2c 22 32 64 65 67 72 | COPS: 0,0,"2degr
V (2715423) simcom: rx: 65 65 73 22 2c 32 0d 0a 0d 0a 4f 4b 0d 0a | ees",2....OK..
OVMS > gytdercvghnjm=k',.=uigyryr6 ,kjbuhygb vg bV (2725393) simcom: tx: f9 0d ff 3b 41 54 2b 43 52 45 47 3f 3b 2b 43 43 | ...;AT+CREG?;+CC
V (2725393) simcom: tx: 4c 4b 3f 3b 2b 43 53 51 3b 2b 43 4f 50 53 3f 0d | LK?;+CSQ;+COPS?.
V (2725393) simcom: tx: 0a cf f9 | ...
V (2725413) simcom: rx: 41 54 2b 43 52 45 47 3f 3b 2b 43 43 4c 4b 3f 3b | AT+CREG?;+CCLK?;
V (2725413) simcom: rx: 2b 43 53 51 3b 2b 43 4f 50 53 3f 0d | +CSQ;+COPS?.
V (2725463) simcom: rx: 0d 0a 2b 43 52 45 47 3a 20 30 2c 31 0d 0a 0d 0a | ..+CREG: 0,1....
V (2725473) simcom: rx: 2b 43 43 4c 4b 3a 20 22 31 38 2f 30 32 2f 30 39 | +CCLK: "18/02/09
V (2725473) simcom: rx: 2c 31 37 3a 35 30 3a 32 30 2b 35 32 22 0d 0a 0d | ,17:50:20+52"...
V (2725473) simcom: rx: 0a 2b 43 53 51 3a 20 35 2c 39 39 0d 0a 0d 0a 2b | .+CSQ: 5,99....+
V (2725473) simcom: rx: 43 4f 50 53 3a 20 30 2c 30 2c 22 32 64 65 67 72 | COPS: 0,0,"2degr
V (2725473) simcom: rx: 65 65 73 22 2c 32 0d 0a 0d 0a 4f 4b 0d 0a | ees",2....OK..

That looks like a reboot of the modem (around the time ERROR is received from the modem).

From that point on, we think we are in mux mode, and the modem doesn’t. Not surprised that nothing works. A modem power on/off would probably fix it, but nothing in the current software detects that situation.

I think what I’ll do is add a timeout in mux mode. Or a ping style frame (I’ll have to see what the spec allows). Then we can detect that mux has failed, and go through a reset cycle if that happens.

Regards, Mark.

On 12 Feb 2018, at 6:35 PM, Tom Parker <tom@carrott.org> wrote:

On 06/02/18 12:42, Tom Parker wrote:

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.

Attached is another log file. Here the server v2 code and the simcom noticed that it was disconnected which I haven't seen before, but the simcom never reconnected.

See the attached file for the earlier and later messages, the AT+CREG?... loop quoted below went on for about 15 minutes without reconnecting, and doing a power simcom off followed by on did not make it reconnect. Pressing the button made it connect straight away. I believe I was stationary when power cycling and then resetting the whole module.

Why is "simcom: rx line" not always sometimes printed? If you look further back and forward in the log you'll see it decoding most of the AT command responses. Is this the simcom response parser? It looks like the AT+CREG?... are being sent but sometimes the results aren't be interpreted, so the simcom code doesn't know it is connected?

+CSQ: 1,99 suggests there is very low signal? That might explain the disconnections. My antenna is poor (a wifi rubber ducky with an RP-SMA adapter, I could switch to a proper antenna too but then my problem might go away and we wouldn't be able to collect debug information). After the reboot the signal quality was only +CSQ: 2,99 and it reconnected fine.

OVMS > V (4235393) simcom: tx: f9 0d ff 3b 41 54 2b 43 52 45 47 3f 3b 2b 43 43 | ...;AT+CREG?;+CC
V (4235393) simcom: tx: 4c 4b 3f 3b 2b 43 53 51 3b 2b 43 4f 50 53 3f 0d | LK?;+CSQ;+COPS?.
V (4235393) simcom: tx: 0a cf f9                                        | ...
V (4235403) simcom: rx: 41 54 2b 43 52 45 47 3f 3b 2b 43 43 4c 4b 3f 3b | AT+CREG?;+CCLK?;
V (4235403) simcom: rx: 2b 43 53 51 3b 2b 43 4f 50 53 3f 0d             | +CSQ;+COPS?.
V (4235413) simcom: rx: 0d 0a 2b 43 52 45 47 3a 20 30 2c 31 0d 0a 0d 0a | ..+CREG: 0,1....
V (4235413) simcom: rx: 2b 43 43 4c 4b 3a 20 22 31 38 2f 30 32 2f 30 39 | +CCLK: "18/02/09
V (4235413) simcom: rx: 2c 31 38 3a 31 35 3a 33 30 2b 35 32 22 0d 0a 0d | ,18:15:30+52"...
V (4235413) simcom: rx: 0a 2b 43 53 51 3a 20 30 2c 39 39 0d 0a 0d 0a 2b | .+CSQ: 0,99....+
V (4235413) simcom: rx: 43 4f 50 53 3a 20 30 2c 30 2c 22 32 64 65 67 72 | COPS: 0,0,"2degr
V (4235413) simcom: rx: 65 65 73 22 2c 32 0d 0a 0d 0a 4f 4b 0d 0a       | ees",2....OK..
OVMS > simcom statusV (4245393) simcom: tx: f9 0d ff 3b 41 54 2b 43 52 45 47 3f 3b 2b 43 43 | ...;AT+CREG?;+CC
V (4245393) simcom: tx: 4c 4b 3f 3b 2b 43 53 51 3b 2b 43 4f 50 53 3f 0d | LK?;+CSQ;+COPS?.
V (4245393) simcom: tx: 0a cf f9                                        | ...
V (4245423) simcom: rx: 41 54 2b 43 52 45 47 3f 3b 2b 43 43 4c 4b 3f 3b | AT+CREG?;+CCLK?;
V (4245423) simcom: rx: 2b 43 53 51 3b 2b 43 4f 50 53 3f 0d             | +CSQ;+COPS?.
V (4245463) simcom: rx: 0d 0a 2b 43 52 45 47 3a 20 30 2c 31 0d 0a 0d 0a | ..+CREG: 0,1....
V (4245463) simcom: rx: 2b 43 43 4c 4b 3a 20 22 31 38 2f 30 32 2f 30 39 | +CCLK: "18/02/09
V (4245463) simcom: rx: 2c 31 38 3a 31 35 3a 34 30 2b 35 32 22 0d 0a 0d | ,18:15:40+52"...
V (4245473) simcom: rx: 0a 2b 43 53 51 3a 20 31 2c 39 39 0d 0a 0d 0a 2b | .+CSQ: 1,99....+
V (4245473) simcom: rx: 43 4f 50 53 3a 20 30 2c 30 2c 22 32 64 65 67 72 | COPS: 0,0,"2degr
V (4245473) simcom: rx: 65 65 73 22 2c 32 0d 0a 0d 0a 4f 4b 0d 0a       | ees",2....OK..
OVMS > simcom status
SIMCOM
Network Registration: Searching
State: NetWait
Ticker: 1570
User Data: 0
Mux Open Channels: 4
PPP Not Connected
PPP Last Error: User Interrupt
GPS: disabled
GPS time: disabled
NMEA (GPS/GLONASS) Not Connected
OVMS > server v2 status
Error: Disconnected from OVMS Server V2

<ovms_2018-02-09T03_56_08+0000.log.bz2>_______________________________________________
OvmsDev mailing list
OvmsDev@lists.teslaclub.hk
http://lists.teslaclub.hk/mailman/listinfo/ovmsdev

_______________________________________________
OvmsDev mailing list
OvmsDev@lists.teslaclub.hk
http://lists.teslaclub.hk/mailman/listinfo/ovmsdev