[Ovmsdev] UART frame errors / NMEA MUX channel usage

Wed Jan 18 22:25:31 HKT 2023

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:
>
>  1. disabling GPS doesn't change anything
>  2. splitting the status poll into two queries doesn't change anything
>  3. issuing a UART HW FIFO reset
>     (https://github.com/espressif/esp-idf/commit/5404252e803f5489a72119a3ad41b580f2881a2a)
>     doesn't change anything
>  4. explicitly setting the mode to standard UART doesn't change anything
>  5. performing a deep sleep instead of a standard reboot doesn't
>     change anything
>  6. 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.
>
>   * https://www.esp32.com/viewtopic.php?t=4701
>   * https://github.com/espressif/esp-idf/commit/5404252e803f5489a72119a3ad41b580f2881a2a
>   * https://github.com/espressif/esp-idf/commit/f482e9e54ce83e249e46f5ee082f6ffb61431339
>   * …some were lucky with this patch:
>     https://esp32.com/viewtopic.php?f=2&t=4725 …we are not.
>
>
>>     //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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20230118/f1700eb9/attachment-0001.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: uart_events.zip
Type: application/zip
Size: 26423 bytes
Desc: not available
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20230118/f1700eb9/attachment-0001.zip>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: OpenPGP_signature
Type: application/pgp-signature
Size: 203 bytes
Desc: OpenPGP digital signature
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20230118/f1700eb9/attachment-0001.sig>