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/5404252e803f5489a72119a3ad41b580...) 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/5404252e803f5489a72119a3ad41b580... * https://github.com/espressif/esp-idf/commit/f482e9e54ce83e249e46f5ee082f6ffb... * …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