I've modified one of the IDF examples to talk to our modem and do
regular restarts and found this:
The test application shows no frame errors, regardless of the number
of resets if performs.
But: if I first flash the OVMS, do a "module reset", then flash
& run the test application, all without power interruption, the
test application suddenly also shows the frame errors &
corrupted characters:
I (13868) TX_TASK: Wrote 39 bytes
W (13868) uart_events: uart frame error
W (13868) uart_events: uart frame error
W (13868) uart_events: uart frame error
I (13868) uart_events: [UART DATA]: 3: «í
I also found out it doesn't matter if I do the reset in software or
by pushing S1. The effect remains until the next cold boot.
So it seems something we do (some hardware configuration) has a side
effect that persists over resets and begins interfering with the
UART after the first reset. I thought maybe we have some bug in our
UART driver setup, and fixed some issues I found, but that didn't
help. My next suspect was the SD card, but excluding that didn't
change anything.
Espressif are aware of the UART not resetting properly, there are
multiple open issue tickets, but there has been no progress for
about two years on this.
But the effect only showing after a full OVMS boot means there might
be a workaround. Attached is the test application, in case anyone
wants to experiment with this.
Regards,
Michael
PS: as a side benefit from my investigation, I also found out how to
get the SIMCOM 7600 to only send NMEA sentences on one MUX channel
(→ commit 8f49ecab01617414c89b1e3ffa70c79e0115fe95).
Am 09.09.22 um 21:00 schrieb Michael
Balzer:
Regarding the UART frame errors:
- disabling GPS doesn't change anything
- splitting the status poll into two queries doesn't change
anything
- issuing a UART HW FIFO reset
(https://github.com/espressif/esp-idf/commit/5404252e803f5489a72119a3ad41b580f2881a2a)
doesn't change anything
- explicitly setting the mode to standard UART doesn't change
anything
- performing a deep sleep instead of a standard reboot doesn't
change anything
- brute force writing a cycle of all 1's and all 0's twice to
the full UART1 register range before driver init doesn't
change anything
Apparently, the ESP32 UART has some kind of hardware flaw leading
to an ESP32 reset actually not doing a full UART reset.
//Due to hardware issue, we can not
use fifo_rst to reset uart fifo.
//See description about UART_TXFIFO_RST and UART_RXFIFO_RST
in <<esp32_technical_reference_manual>> v2.6 or
later.
There is apparently no method to perform a full UART HW reset, at
least I haven't found one. It seems this is an issue we cannot fix
(in software).
But I now don't think this is a new issue, and this also affects
modules quite differently, no idea depending on what
circumstances: on the current run, my car module has lots of FIFO
overflows & quite some MUX framing errors, but not a single
UART frame error.
IOW, I don't think we should let that block the release.
Regards,
Michael
Am 09.09.22 um 14:23 schrieb Michael
Balzer:
A related issue -- I remember wanting to ask this before: why do
we receive all NMEA sentences three times / on three MUX
channels?
Apparently they come in on channels 1, 3 and 4 -- stumbled
across this again because this now leads to these also being
added to a cellular command response:
OVMS# cell cmd AT+CMUX?
+CMUX: 0,0,5,118,0,0,600
OK
$GPRMC,114516.00,A,xxx.139223,N,xxx.391678,E,0.0,,090922,0.9,W,A*07
$GNGNS,114516.00,xxx.139223,N,xxx.391678,E,AAN,11,1.0,324.4,47.0,,,V*68
V (3388221) gsm-mux: ProcessFrame(CHAN=1,
ADDR=05, CTRL=ff, FCS=bf, LEN=78)
D (3388231) gsm-nmea: Incoming RMC:
$GPRMC,114516.00,A,xxx.139223,N,xxx.391678,E,0.0,,090922,0.9,W,A*07
V (3388231) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=fa, LEN=78)
V (3388231) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f7, LEN=78)
V (3388241) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff,
FCS=b1, LEN=82)
D (3388241) gsm-nmea: Incoming GNS:
$GNGNS,114516.00,xxx.139223,N,xxx.391678,E,AAN,11,1.0,324.4,47.0,,,V*68
V (3388251) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=f4, LEN=82)
V (3388261) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f9, LEN=82)
V (3393221) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff,
FCS=bf, LEN=78)
D (3393231) gsm-nmea: Incoming RMC:
$GPRMC,114521.00,A,xxx.139223,N,xxx.391676,E,0.0,,090922,0.9,W,A*0D
V (3393231) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=fa, LEN=78)
V (3393231) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f7, LEN=78)
V (3393241) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff,
FCS=b1, LEN=82)
D (3393241) gsm-nmea: Incoming GNS:
$GNGNS,114521.00,xxx.139223,N,xxx.391676,E,AAN,11,1.0,324.4,47.0,,,V*62
V (3393251) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=f4, LEN=82)
V (3393261) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f9, LEN=82)
This also produces a lot of unnecessary stress on the ESP's RX
buffer, doesn't it?
Channel 1 is the dedicated NMEA channel, 3 is POLL and 4 is CMD.
I don't see why channels 3 & 4 are used for these by the
modem, but I also cannot find any command meant to configure
this.
Any idea on this?
Regards,
Michael
Am 09.09.22 um 13:14 schrieb
Michael Balzer:
Mark,
(am I the only one experiencing this?)
I've had multiple times of temporarily frozen modem
communication over the last days on my car module. That's new,
so I think we should try to fix that before releasing.
On my bench module there's a clear correlation between the
extended status query and the frame errors. It's also not
related to the NMEA messages, I've checked that, they come at
another second.
Log excerpts below.
With frame errors responses also occasionally get corrupted,
e.g.
D (204251) cellular: mux-rx-line #3:
Hologram",7
I think the extended status responses now very often cause an
overflow on the RX buffer when coming in together. Solution
could be to split the queries and distribute over 2-3 seconds.
I don't know if that will also fix the strange cold/warm boot
difference with this, but maybe that's simply because the
modem is faster with getting back to the network after a
reboot, so the status responses become large quickly.
Regards,
Michael
D (204211) cellular: mux-tx #3:
AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ;+CPSI?;+COPS?
W (204251) gsm-mux: Frame error: EOF mismatch (CHAN=55,
ADDR=df, CTRL=ff, FCS=35, LEN=133)
V (204251) gsm-mux: Frame dump: f9 df ff ff bf bf dd ff f9
0d ff af 0d 0a 2b 43 | ..............+C
V (204251) gsm-mux: Frame dump: 50 53 49 3a 20 4c 54 45 2c
4f 6e 6c 69 6e 65 2c | PSI: LTE,Online,
V (204251) gsm-mux: Frame dump: 32 36 32 2d 30 32 2c 30 78
42 30 46 35 2c 31 33 | 262-02,0xB0F5,13
V (204251) gsm-mux: Frame dump: 31 37 39 34 31 32 2c 34 34
38 2c 45 55 54 52 41 | 179412,448,EUTRA
V (204251) gsm-mux: Frame dump: 4e 2d 42 41 4e 44 31 2c 31
30 30 2c 34 2c 34 2c | N-BAND1,100,4,4,
V (204251) gsm-mux: Frame dump: 2d 39 32 2c 2d 31 31 35 32
2c 2d 38 37 35 2c 31 | -92,-1152,-875,1
V (204251) gsm-mux: Frame dump: 34 0d 0a 34 f9 f9 0d ff ed
0d 0a 2b 43 52 45 47 | 4..4.......+CREG
V (204251) gsm-mux: Frame dump: 3a 20 31 2c 35 0d 0a 0d 0a
2b 43 47 52 45 47 3a | : 1,5....+CGREG:
V (204251) gsm-mux: Frame dump: 20 31 2c 35
0d | 1,5.
V (204251) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=da, LEN=25)
D (204251) cellular: mux-rx-line #3: Hologram",7
V (208231) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff,
FCS=bf, LEN=78)
V (208241) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=fa, LEN=78)
V (208251) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f7, LEN=78)
V (208251) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff,
FCS=b1, LEN=82)
V (208271) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=f4, LEN=82)
…
V (233271) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=f4, LEN=82)
V (233271) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f9, LEN=82)
D (234211) cellular: mux-tx #3:
AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ;+CPSI?;+COPS?
W (234211) cellular: UART frame error
W (234211) cellular: UART frame error
W (234211) cellular: UART frame error
W (234211) cellular: UART frame error
W (234231) gsm-mux: Frame error: EOF mismatch (CHAN=63,
ADDR=ff, CTRL=ea, FCS=2c, LEN=53)
V (234231) gsm-mux: Frame dump: f9 ff ea 5f ff b7 ff fd ff
b9 df fd bf f9 ff fd | ..._............
V (234231) gsm-mux: Frame dump: fb ff f9 f9 a9 f9 0d ff af
0d 0a 2b 43 50 53 49 | ...........+CPSI
V (234231) gsm-mux: Frame dump: 3a 20 4c 54 45 2c 4f 6e 6c
69 6e 65 2c 32 36 32 | : LTE,Online,262
V (234231) gsm-mux: Frame dump: 2d 30 32 2c
30 | -02,0
V (234241) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=a7, LEN=124)
D (234241) cellular: mux-rx-line #3: +CREG: 1,5
D (234241) cellular: mux-rx-line #3: +CGREG: 1,5
D (234241) cellular: mux-rx-line #3: +CEREG: 1,5
D (234241) cellular: mux-rx-line #3: +CCLK:
"22/09/09,12:52:41+08"
D (234241) cellular: mux-rx-line #3: +CSQ: 13,99
V (234241) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=da, LEN=25)
D (234251) cellular: mux-rx-line #3: +COPS: 0,0,"vodafone.de
Hologram",7
V (238231) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff,
FCS=bf, LEN=78)
V (238241) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=fa, LEN=78)
…
V (293251) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f7, LEN=78)
V (293251) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff,
FCS=b1, LEN=82)
V (293271) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=f4, LEN=82)
V (293271) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f9, LEN=82)
D (294211) cellular: mux-tx #3:
AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ;+CPSI?;+COPS?
W (294211) cellular: UART frame error
W (294211) cellular: UART frame error
W (294211) cellular: UART frame error
W (294241) gsm-mux: Frame error: EOF mismatch (CHAN=59,
ADDR=ef, CTRL=db, FCS=2b, LEN=117)
V (294241) gsm-mux: Frame dump: f9 ef db df ef df f7 cb f9
ff ff db 7f fd ff ff | ................
V (294241) gsm-mux: Frame dump: f9 0d ff af 0d 0a 2b 43 50
53 49 3a 20 4c 54 45 | ......+CPSI: LTE
V (294241) gsm-mux: Frame dump: 2c 4f 6e 6c 69 6e 65 2c 32
36 32 2d 30 32 2c 30 | ,Online,262-02,0
V (294241) gsm-mux: Frame dump: 78 42 30 46 35 2c 31 33 31
37 39 34 31 32 2c 34 | xB0F5,13179412,4
V (294241) gsm-mux: Frame dump: 34 38 2c 45 55 54 52 41 4e
2d 42 41 4e 44 31 2c | 48,EUTRAN-BAND1,
V (294241) gsm-mux: Frame dump: 31 30 30 2c 34 2c 34 2c 2d
39 36 2c 2d 31 31 35 | 100,4,4,-96,-115
V (294241) gsm-mux: Frame dump: 35 2c 2d 38 37 33 2c 31 34
0d 0a 34 f9 f9 0d ff | 5,-873,14..4....
V (294241) gsm-mux: Frame dump: ed 0d 0a 2b
43 | ...+C
V (294251) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=da, LEN=25)
D (294251) cellular: mux-rx-line #3: Hologram",7
V (298231) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff,
FCS=bf, LEN=78)
V (298241) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=fa, LEN=78)
V (298241) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f7, LEN=78)
V (298251) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff,
FCS=b1, LEN=82)
V (298261) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=f4, LEN=82)
V (298271) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f9, LEN=82)
…
V (323251) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f7, LEN=78)
V (323261) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff,
FCS=b1, LEN=82)
V (323271) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=f4, LEN=82)
V (323271) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f9, LEN=82)
D (324211) cellular: mux-tx #3:
AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ;+CPSI?;+COPS?
W (324231) gsm-mux: Frame error: EOF mismatch (CHAN=29,
ADDR=77, CTRL=fb, FCS=45, LEN=125)
V (324231) gsm-mux: Frame dump: f9 77 fb ef 5f ff bb ed fb
bb db ff b7 fb cf ff | .w.._...........
V (324231) gsm-mux: Frame dump: bf d9 ff bb f9 0d ff b1 0d
0a 2b 43 50 53 49 3a | ..........+CPSI:
V (324231) gsm-mux: Frame dump: 20 4c 54 45 2c 4f 6e 6c 69
6e 65 2c 32 36 32 2d | LTE,Online,262-
V (324231) gsm-mux: Frame dump: 30 32 2c 30 78 42 30 46 35
2c 31 33 31 37 39 34 | 02,0xB0F5,131794
V (324231) gsm-mux: Frame dump: 31 32 2c 34 34 38 2c 45 55
54 52 41 4e 2d 42 41 | 12,448,EUTRAN-BA
V (324241) gsm-mux: Frame dump: 4e 44 31 2c 31 30 30 2c 34
2c 34 2c 2d 31 30 39 | ND1,100,4,4,-109
V (324241) gsm-mux: Frame dump: 2c 2d 31 31 36 36 2c 2d 38
37 34 2c 31 31 0d 0a | ,-1166,-874,11..
V (324241) gsm-mux: Frame dump: c2 f9 f9 0d ff ed 0d 0a 2b
43 52 45 47 | ........+CREG
V (324241) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=da, LEN=25)
D (324241) cellular: mux-rx-line #3: Hologram",7
V (328231) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff,
FCS=bf, LEN=78)
V (328241) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=fa, LEN=78)
V (328251) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f7, LEN=78)
…
V (353251) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f7, LEN=78)
V (353251) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff,
FCS=b1, LEN=82)
V (353271) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=f4, LEN=82)
V (353271) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f9, LEN=82)
D (354211) cellular: mux-tx #3:
AT+CREG?;+CGREG?;+CEREG?;+CCLK?;+CSQ;+CPSI?;+COPS?
W (354211) cellular: UART frame error
W (354211) cellular: UART frame error
W (354211) cellular: UART frame error
W (354211) cellular: UART frame error
V (354231) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=34, LEN=93)
D (354231) cellular: mux-rx-line #3: +CPSI:
LTE,Online,262-02,0xB0F5,13179412,448,EUTRAN-BAND1,100,4,4,-122,-1184,-874,9
V (354241) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=a7, LEN=124)
D (354241) cellular: mux-rx-line #3: +CREG: 1,5
D (354241) cellular: mux-rx-line #3: +CGREG: 1,5
D (354241) cellular: mux-rx-line #3: +CEREG: 1,5
D (354241) cellular: mux-rx-line #3: +CCLK:
"22/09/09,12:54:41+08"
D (354251) cellular: mux-rx-line #3: +CSQ: 13,99
V (354251) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=da, LEN=25)
D (354251) cellular: mux-rx-line #3: +COPS: 0,0,"vodafone.de
Hologram",7
V (358231) gsm-mux: ProcessFrame(CHAN=1, ADDR=05, CTRL=ff,
FCS=bf, LEN=78)
V (358241) gsm-mux: ProcessFrame(CHAN=3, ADDR=0d, CTRL=ff,
FCS=fa, LEN=78)
V (358251) gsm-mux: ProcessFrame(CHAN=4, ADDR=11, CTRL=ff,
FCS=f7, LEN=78)
--
Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
Fon 02333 / 833 5735 * Handy 0176 / 206 989 26