esp-modem: AT command response truncated sometimes when in CMUX mode (IDFGH-12526)

doragasu commented 3 months ago

Answers checklist.

[X] I have read the documentation for esp-protocols components and the issue is not addressed there.
[X] I have updated my esp-protocols branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.

What component are you using? If you choose Other, provide details in More Information.

esp_modem

component version

master

IDF version.

v5.1.1

More Information.

I am using an MC60 modem with latest master, but with this PR applied (otherwise I cannot receive the GNSS data, as shown in the issue linked in the PR).

The program starts the modem and connects to a MQTT broker. While the connection is alive, it periodically requests GGA position data and link quality information. Most of the time it works, but sometimes the received GGA data is truncated.

When it works, the logs look as follows (position data has been replaced with X characters):

V (36575) command_lib: generic_get_string39.5768
V (36575) Send: 0x3fca6794   f9 09 ef 2d                                       |...-|
V (36575) Send: 0x3fcb5798   41 54 2b 51 47 4e 53 53  52 44 3d 22 4e 4d 45 41  |AT+QGNSSRD="NMEA|
V (36575) Send: 0x3fcb57a8   2f 47 47 41 22 0d                                 |/GGA".|
V (36575) Send: 0x3fca6798   e0 f9                                             |..|30
V (36585) CMUX Received: 0x3fca56b8   f9 09 ef ab 0d 0a 2b 51  47 4e 53 53 52 44 3a 20  |......+QGNSSRD: |
V (36585) CMUX Received: 0x3fca56c8   24 47 4e 47 47 41 2c 31  35 30 34 31 37 2e 30 30  |$GNGGA,150417.00|
V (36585) CMUX Received: 0x3fca56d8   30 2c XX XX XX XX XX XX  XX XX XX 2c XX 2c XX XX  |0,XXXXXXXXX,X,XX|
V (36585) CMUX Received: 0x3fca56e8   XX XX XX XX XX XX XX XX  2c XX 2c 31 2c 38 2c 31  |XXXXXXXX,X,1,8,1|
D (36585) CMUX: Payload frame: dlci:02 type:ef payload:85 available:60
V (36585) CMUX Received: 0x3fca56f8   2e 35 38 2c 37 34 34 2e  30 2c 4d 2c 35 31 2e 37  |.58,744.0,M,51.7|
V (36585) CMUX Received: 0x3fca5708   2c 4d 2c 2c 2a 3539.5768 39 0d  0a e4 f9                 |,M,,*59....|
D (36585) CMUX: Payload frame: dlci:02 type:ef payload:25 available:27
} (36585) command_lib: Token: {

V (36585) command_lib: Token: {+QGNSSRD: $GNGGA,150417.000,XXXXXXXXX,X,XXXXXXXXXX,X,1,8,1.58,744.0,M,51.7,M,,*59}

V (36685) CMUX Received: 0x3fca56b8   f9 09 ef 0d 0d 0a 4f 4b  0d 0a d8 f9              |......OK....|
D (36685) CMUX: Payload frame: dlci:02 type:ef payload:6 available:8
} (36685) command_lib: Token: {

V (36685) command_lib: Token: {OK}

I (36685) test_tsk: GNSS: +QGNSSRD: $GNGGA,150417.000,XXXXXXXXX,X,XXXXXXXXXX,X,1,8,1.58,744.0,M,51.7,M,,*59

And when it fails, it looks as follows:

V (32095) command_lib: generic_get_string
V (32095) Send: 0x3fca6794   f9 09 ef 2d                                       |...-|
V (32095) Send: 0x3fcb5798   41 54 2b 51 47 4e 53 53  52 44 3d 22 4e 4d 45 41  |AT+QGNSSRD="NMEA|
V (32095) Send: 0x3fcb57a8   2f 47 47 41 22 0d                                 |/GGA".|
V (32095) Send: 0x3fca6798   e0 f9                                             |..|
V (32105) CMUX Received: 0x3fca56b8   f9 09 ef 5b 0d 0a 2b 51  47 4e 53 53 52 44 3a 20  |...[..+QGNSSRD: |
V (32105) CMUX Received: 0x3fca56c8   24 47 4e 47 47 41 2c 31  35 30 34 31 32 2e 30 30  |$GNGGA,150412.00|
V (32105) CMUX Received: 0x3fca56d8   30 2c XX XX XX XX XX XX  XX XX XX 2c XX 2c XX XX  |0,XXXXXXXXX,X,XX|
V (32105) CMUX Received: 0x3fca56e8   XX 50 f9 f9 09 ef 51 XX  XX XX XX XX XX XX 2c XX  |XP....QXXXXXXX,X|
D (32105) CMUX: Payload frame: dlci:02 type:ef payload:45 available:60
} (32105) command_lib: Token: {

D (32105) CMUX: Payload frame: dlci:02 type:ef payload:40 available:9
V (32105) CMUX Received: 0x3fca56f8   2c 31 2c 38 2c 31 2e 35  38 2c 37 34 33 2e 38 2c  |,1,8,1.58,743.8,|
V (32105) CMUX Received: 0x3fca5708   4d 2c 35 31 2e 37 2c 4d  2c 2c 2a 35 41 0d 0a bd  |M,51.7,M,,*5A...|
V (32105) CMUX Received: 0x3fca5718   f9                                                |.|
D (32105) CMUX: Payload frame: dlci:02 type:ef payload:31 available:33
V (32105) command_lib: Token: {XXXXXXX,X,1,8,1.58,743.8,M,51.7,M,,*5A}

V (32205) CMUX Received: 0x3fca56b8   f9 09 ef 0d 0d 0a 4f 4b  0d 0a d8 f9              |......OK....|
D (32205) CMUX: Payload frame: dlci:02 type:ef payload:6 available:8
} (32205) command_lib: Token: {

V (32205) command_lib: Token: {OK}

I (32205) test_tsk: GNSS: XXXXXXX,W,1,8,1.58,743.8,M,51.7,M,,*5A

In this specific case, looks like the response is split, and between the two parts, there are these bytes: 50 f9 f9 09 ef 51.

Another failed example:

V (76776) command_lib: generic_get_string
V (76776) Send: 0x3fca73d4   f9 09 ef 2d                                       |...-|
V (76776) Send: 0x3fcb7b70   41 54 2b 51 47 4e 53 53  52 44 3d 22 4e 4d 45 41  |AT+QGNSSRD="NMEA|
V (76776) Send: 0x3fcb7b80   2f 47 47 41 22 0d                                 |/GGA".|
V (76776) Send: 0x3fca73d8   e0 f9                                             |..|
V (76786) CMUX Received: 0x3fca56b8   f9 09 ef a3 0d 0a 2b 51  47 4e 53 53 52 44 3a 20  |......+QGNSSRD: |
V (76786) CMUX Received: 0x3fca56c8   24 47 4e 47 47 41 2c 31  35 32 31 35 39 2e 30 30  |$GNGGA,152159.00|
V (76786) CMUX Received: 0x3fca56d8   30 2c XX XX XX XX XX XX  XX XX XX 2c XX 2c XX XX  |0,XXXXXXXXX,X,XX|
V (76786) CMUX Received: 0x3fca56e8   XX XX XX XX XX XX XX XX  2c XX 2c 31 2c 31 30 2c  |XXXXXXXX,X,1,10,|
D (76786) CMUX: Payload frame: dlci:02 type:ef payload:81 available:60
V (76786) CMUX Received: 0x3fca56f8   30 2e 38 30 2c 37 32 38  2e 39 2c 4d 2c 35 31 2e  |0.80,728.9,M,51.|
V (76786) CMUX Received: 0x3fca5708   37 2c 4d 2c 2c ea f9                              |7,M,,..|
D (76786) CMUX: Payload frame: dlci:02 type:ef payload:21 available:23
} (76786) command_lib: Token: {

V (76886) CMUX Received: 0x3fca56b8   f9 09 ef 0b 2a 36 35 0d  0a 3c f9 f9 09 ef 0d 0d  |....*65..<......|
V (76886) CMUX Received: 0x3fca56c8   0a 4f 4b 0d 0a d8 f9                              |.OK....|
D (76886) CMUX: Payload frame: dlci:02 type:ef payload:5 available:19
V (76886) command_lib: Token: {*65}

D (76886) CMUX: Payload frame: dlci:02 type:ef payload:6 available:8
} (76886) command_lib: Token: {

V (76886) command_lib: Token: {OK}

I (76886) test_tsk: GNSS: *65

I am not familiar with CMUX protocol but this one still looks a bit more "normal" than the previous one, still it fails and only the ending *65 is obtained.

What could be causing this issue?

david-cermak commented 3 months ago

Hi @doragasu

The issue is most probably caused by receiving the response into two separate CMUX frames. The modem library reuses UART buffer for CMUX processing, and cannot (easily) handle this case (again related to MC60, as the fix you applied -- https://github.com/espressif/esp-protocols/pull/540).

This configuration should resolve the problem: CONFIG_ESP_MODEM_USE_INFLATABLE_BUFFER_IF_NEEDED=y -- the downside is an extra allocation if the response comes in two pieces.

doragasu commented 3 months ago

Awesome, I'll test ASAP and see if it works

doragasu commented 3 months ago

It works great, thanks!

espressif / esp-protocols