Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

esp_modem simple_cmux_client doesn't work with SIM7670G (IDFGH-13823) #669

Closed
3 tasks done
morgana2313 opened this issue Oct 5, 2024 · 33 comments
Closed
3 tasks done

Comments

@morgana2313
Copy link

morgana2313 commented Oct 5, 2024

Answers checklist.

  • I have read the documentation for esp-protocols components and the issue is not addressed there.
  • I have updated my esp-protocols branch (master or release) to the latest version and checked that the issue is present there.
  • 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

v1.1.0

IDF version.

v5.3.1-244-g4d0db7045d

More Information.

The simple_cmux_client doesn't work: Failed to configure multiplexed command mode... exiting. Using printf statements I found that cmux_term->init() in DTE::setup_cmux() returns false because of a timeout in CMux::init().

I'm using a LilyGo LilyGo T SIM7670G S3 board and added some code to reset and PWR the SIM7670G. The same code + uart config works with pppos_client and get an ip number. If I skip the dce->set_mode code the correct Operator name is displayed; so the uart is configured correctly.

  • Manufacturer: SIMCOM INCORPORATED
  • Model: SIM7670G-MNGV
  • Revision: V1.9.01

BTW: I think this issue category should be named "Issue: Installation, build or bug report"

@espressif-bot espressif-bot added the Status: Opened Issue is new label Oct 5, 2024
@github-actions github-actions bot changed the title esp_modem simple_cmux_client doesn't work with SIM7600 esp_modem simple_cmux_client doesn't work with SIM7600 (IDFGH-13823) Oct 5, 2024
@david-cermak
Copy link
Collaborator

Hi @morgana2313

I currently don't have any SIM7670 device with me, but the CMUX related command should work the same way as 7600 or 7672, which have been tested with cmux protocol.

Could you please enable verbose level and share the log when you're setting up the connection? I'm mainly interested in the raw cmux protocol data.

There're also some CMUX related options in the component Kconfig. This one could be relevant for the initial setup:

config ESP_MODEM_CMUX_DELAY_AFTER_DLCI_SETUP
int "Delay in ms to wait before creating another virtual terminal"
default 0
help
Some devices might need a pause before sending SABM command that creates
virtual terminal. This delay applies only to establishing a CMUX mode.
The typical reason for failing SABM request without a delay is that
some devices (SIM800) send MSC requests just after opening a new DLCI.

(you can try to set it to say 250ms and see if it helps)

@morgana2313
Copy link
Author

morgana2313 commented Oct 17, 2024

Hello David,

Thank you for your response!

CONFIG_ESP_MODEM_CMUX_DELAY_AFTER_DLCI_SETUP=250 (or 1000) does not make any difference.

Here is the verbose log:

I (227) main_task: Calling app_main()
D (227) event: running task for loop 0x3fc9f0fc
D (227) event: created task for loop 0x3fc9f0fc
D (227) event: created event loop 0x3fc9f0fc
D (227) esp_netif_lwip: LwIP stack has been initialized
D (227) esp_netif_lwip: esp-netif has been successfully initialized
I (227) cmux_example: Pull down MODEM_RESET_PIN:17 for 0.1 second.
I (1427) cmux_example: Pull up MODEM_PWR_PIN:18 for 0.1 second.
I (1727) cmux_example: RX:10 TX:11
I (1727) uart: queue free spaces: 30
V (1727) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1727) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1727) intr_alloc: Connected src 28 to int 5 (cpu 0)
D (1727) esp_netif_lwip: check: remote, if=0x3fc9d390 fn=0x4203aa44
--- 0x4203aa44: esp_netif_new_api at ~/esp/esp-idf-5.3/components/esp_netif/lwip/esp_netif_lwip.c:711

V (1727) esp_netif_objects: esp_netif_add_to_list_unsafe 0x3fca4648
D (1727) esp_netif_objects: esp_netif_add_to_list_unsafe netif added successfully (total netifs: 1)
D (1727) esp-netif_lwip-ppp: esp_netif_new_ppp: PPP connection created: 0x3fca487c
D (1727) esp-netif_lwip-ppp: Phase Dead
D (1727) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (1727) cmux_example: not set_flow_control, because 2-wire mode active.
V (1727) command_lib: set_cmux
V (1727) command_lib: generic_command_common
V (1727) command_lib: generic_command
D (1727) command_lib: generic_command command AT+CMUX=0

D (1737) command_lib: Response: AT+CMUX=0
O

D (1737) command_lib: Response: AT+CMUX=0
OK


V (1837) CMUX Received: 0x3fca43a4   f9 03 3f 01 1c f9                                 |..?...|
W (1837) CMUX: Restarting CMUX state machine (reason: 3)
I (1837) CMUX: Protocol recovered
E (2857) cmux_example: Failed to configure multiplexed command mode... exiting
V (2857) intr_alloc: esp_intr_free: Disabling int, killing handler
I (2857) main_task: Returned from app_main()

Searching for the bytestring f9 03 3f 01 1c f9 leads to:

Relevant config:

grep MODEM sdkconfig
# CONFIG_EXAMPLE_MODEM_DEVICE_SIM800 is not set
# CONFIG_EXAMPLE_MODEM_DEVICE_BG96 is not set
# CONFIG_EXAMPLE_MODEM_DEVICE_SIM7000 is not set
# CONFIG_EXAMPLE_MODEM_DEVICE_SIM7070 is not set
# CONFIG_EXAMPLE_MODEM_DEVICE_SIM7070_GNSS is not set
CONFIG_EXAMPLE_MODEM_DEVICE_SIM7600=y
CONFIG_EXAMPLE_MODEM_PPP_APN="internet"
CONFIG_EXAMPLE_MODEM_UART_TX_PIN=11
CONFIG_EXAMPLE_MODEM_UART_RX_PIN=10
CONFIG_EXAMPLE_MODEM_UART_RTS_PIN=27
CONFIG_EXAMPLE_MODEM_UART_CTS_PIN=23
CONFIG_ESP_MODEM_CMUX_DEFRAGMENT_PAYLOAD=y
# CONFIG_ESP_MODEM_USE_INFLATABLE_BUFFER_IF_NEEDED is not set
CONFIG_ESP_MODEM_CMUX_DELAY_AFTER_DLCI_SETUP=250
# CONFIG_ESP_MODEM_CMUX_USE_SHORT_PAYLOADS_ONLY is not set
# CONFIG_ESP_MODEM_ADD_CUSTOM_MODULE is not set
CONFIG_ESP_MODEM_C_API_STR_MAX=128
# CONFIG_ESP_MODEM_URC_HANDLER is not set

@morgana2313
Copy link
Author

I think that the code in data_available to ignore (MSC frame) is not reached because payload_start=nullptr, so data = buffer.get() is used.

BTW: the esp_modem/examples/modem_console doesn't support CONFIG_ESP_CONSOLE_USB_SERIAL_JTAG:

diff --git a/components/esp_modem/examples/modem_console/main/modem_console_main.cpp b/components/esp_modem/examples/modem_console/main/modem_console_main.cpp
index ac4b8f6..65fc899 100644
--- a/components/esp_modem/examples/modem_console/main/modem_console_main.cpp
+++ b/components/esp_modem/examples/modem_console/main/modem_console_main.cpp

@@ -205,8 +256,21 @@ extern "C" void app_main(void)

     // init console REPL environment
     esp_console_repl_config_t repl_config = ESP_CONSOLE_REPL_CONFIG_DEFAULT();
+
+#if defined(CONFIG_ESP_CONSOLE_UART_DEFAULT) || defined(CONFIG_ESP_CONSOLE_UART_CUSTOM)
     esp_console_dev_uart_config_t uart_config = ESP_CONSOLE_DEV_UART_CONFIG_DEFAULT();
     ESP_ERROR_CHECK(esp_console_new_repl_uart(&uart_config, &repl_config, &s_repl));
+#elif defined(CONFIG_ESP_CONSOLE_USB_CDC)
+    esp_console_dev_usb_cdc_config_t hw_config = ESP_CONSOLE_DEV_CDC_CONFIG_DEFAULT();
+    ESP_ERROR_CHECK(esp_console_new_repl_usb_cdc(&hw_config, &repl_config, &s_repl));
+#elif defined(CONFIG_ESP_CONSOLE_USB_SERIAL_JTAG)
+    esp_console_dev_usb_serial_jtag_config_t hw_config = ESP_CONSOLE_DEV_USB_SERIAL_JTAG_CONFIG_DEFAULT();
+    ESP_ERROR_CHECK(esp_console_new_repl_usb_serial_jtag(&hw_config, &repl_config, &s_repl));
+#else
+#error Unsupported console type
+#endif
+
+

     switch (esp_sleep_get_wakeup_cause()) {
     case ESP_SLEEP_WAKEUP_TIMER:

@david-cermak
Copy link
Collaborator

Thanks for testing this again and sharing the logs!

F9 03 3F 01 1C F9 -DLCI = 0, SABM CMD, POLL BIT=1

Right, the device seems to send SABM CMD (requests), rather then acknowledges our requests (esp_modem sends SABM commands to initiate the cmux mode)

It looks like the problem could either be a conflict of roles (both parties are trying to be the initiator, not the module), or some low level protocol mismatch.

Could you please try to send the CMUX AT command and check what the device sends after the OK answer? (you can use the modem console, type cmd AT+CMUX=0 and wait for the response -- you can use a logic analyzer or just add a debug log in the UART read function:

--- a/components/esp_modem/src/esp_modem_uart.cpp
+++ b/components/esp_modem/src/esp_modem_uart.cpp
@@ -175,7 +175,9 @@ int UartTerminal::read(uint8_t *data, size_t len)
     uart_get_buffered_data_len(uart.port, &length);
     length = std::min(len, length);
     if (length > 0) {
-        return uart_read_bytes(uart.port, data, length, portMAX_DELAY);
+        int read_len = uart_read_bytes(uart.port, data, length, portMAX_DELAY);
+        ESP_LOG_BUFFER_HEXDUMP("read", data, read_len, ESP_LOG_INFO);
+        return read_len;
     }
     return 0;

In case you won't see any data on UART after the OK\r\n reply, this is likely some CMUX protocol issue. Also looks similar to the issue we had some time ago: #507
you can apply the two patches I posted here and test again:

(applying the first one would likely help overcome the protocol error in the log:

W (1837) CMUX: Restarting CMUX state machine (reason: 3)

protocol_mismatch_reason::UNEXPECTED_HEADER)

@david-cermak
Copy link
Collaborator

BTW: the esp_modem/examples/modem_console doesn't support CONFIG_ESP_CONSOLE_USB_SERIAL_JTAG:

Thanks for bringing this up! if you feel like fixing it yourself, we'll be happy to accept your PR, btw:-)

@morgana2313 morgana2313 changed the title esp_modem simple_cmux_client doesn't work with SIM7600 (IDFGH-13823) esp_modem simple_cmux_client doesn't work with SIM7670G (IDFGH-13823) Oct 24, 2024
@morgana2313
Copy link
Author

morgana2313 commented Oct 24, 2024

I've added all three patches. I've disabled the ESP_LOG_BUFFER_HEXDUMP in esp_modem_uart.cpp and added a TX one in UartTerminal::write.

I would expect that cmd AT+CMUX=0 would switch the SIM7670G modem into CMUX mode (and would not respond to AT commands any more) but it does!

After set_mode CMUX the esp sends a couple of CMUX SABM Framesf9 03 3f 01 1c f9 which are echo'd by the modem. I suspect the ATE0 command failed because of these SABM Frames prefix.

If I turn off echo mode (ATE0) there is no CMUX data from the modem.

esp> cmd AT
I (13861) modem_console: Sending command AT with timeout 1000
I (13861) TX: 0x3fca6d20   41 54 0d                                          |AT.|
I (13871) RX: 0x3fca5520   41 54 0d 0d 0a 4f 4b 0d  0a                       |AT...OK..|
I (13871) modem_console: AT
OK

esp> cmd AT+CMUX=0
I (21501) modem_console: Sending command AT+CMUX=0 with timeout 1000
I (21501) TX: 0x3fca6d20   41 54 2b 43 4d 55 58 3d  30 0d                    |AT+CMUX=0.|
I (21511) RX: 0x3fca5520   41 54 2b 43 4d 55 58 3d  30 0d 0d 0a 4f 4b 0d 0a  |AT+CMUX=0...OK..|
I (21511) modem_console: AT+CMUX=0
OK

esp> cmd AT
I (24761) modem_console: Sending command AT with timeout 1000
I (24761) TX: 0x3fca6d20   41 54 0d                                          |AT.|
I (24761) RX: 0x3fca5520   41 54 0d 0d 0a 4f 4b 0d  0a                       |AT...OK..|
I (24771) modem_console: AT
OK

esp> set_mode CMUX
I (27541) modem_console: Switching to CMUX name...
I (27541) TX: 0x3fca6c2c   41 54 2b 43 4d 55 58 3d  30 0d                    |AT+CMUX=0.|
I (27541) RX: 0x3fca5520   41 54 2b 43 4d 55 58 3d  30 0d 0d 0a 4f 4b 0d 0a  |AT+CMUX=0...OK..|
I (28041) TX: 0x3fca6bc0   f9 03 3f 01 1c f9                                 |..?...|
I (28041) RX: 0x3fca5520   f9 03 3f 01 1c f9                                 |..?...|
I (28051) TX: 0x3fca6bc0   f9 07 3f 01 de f9                                 |..?...|
I (28051) RX: 0x3fca5520   f9 07 3f 01 de f9                                 |..?...|
I (28061) TX: 0x3fca6bc0   f9 0b 3f 01 59 f9                                 |..?.Y.|
I (28061) RX: 0x3fca5520   f9 0b 3f 01 59 f9                                 |..?.Y.|
I (28321) TX: 0x3fca69c4   f9 05 ef 0b                                       |....|
I (28321) TX: 0x3fca6bec   41 54 45 30 0d                                    |ATE0.|
I (28321) TX: 0x3fca69c8   bb f9                                             |..|
I (28321) RX: 0x3fca5520   f9 05 ef 0b 41 54 45 30  0d bb f9                 |....ATE0...|
I (28321) RX: 0x3fca5520   0d 0a 45 52 52 4f 52 0d  0a                       |..ERROR..|
W (28321) CMUX: Restarting CMUX state machine (reason: 0)
E (28821) modem_console: Failed to set the desired mode
Command returned non-zero error code: 0x1 (ERROR)

Then I started a new session (+modem reset) to get esp_modem out of CMUX mode:

esp> cmd ATE0
I (6111) modem_console: Sending command ATE0 with timeout 1000
I (6111) TX: 0x3fca6d20   41 54 45 30 0d                                    |ATE0.|
I (6111) RX: 0x3fca5520   41 54 45 30 0d 0d 0a 4f  4b 0d 0a                 |ATE0...OK..|
I (6111) modem_console: ATE0
OK

esp> cmd AT+CMUX=0
I (18231) modem_console: Sending command AT+CMUX=0 with timeout 1000
I (18231) TX: 0x3fca6d20   41 54 2b 43 4d 55 58 3d  30 0d                    |AT+CMUX=0.|
I (18231) RX: 0x3fca5520   0d 0a 4f 4b 0d 0a                                 |..OK..|
I (18231) modem_console: 
OK

esp> cmd AT
I (21261) modem_console: Sending command AT with timeout 1000
I (21261) TX: 0x3fca6d20   41 54 0d                                          |AT.|
I (21261) RX: 0x3fca5520   0d 0a 4f 4b 0d 0a                                 |..OK..|
I (21261) modem_console: 
OK

esp> set_mode CMUX
I (26611) modem_console: Switching to CMUX name...
I (26611) TX: 0x3fca6c2c   41 54 2b 43 4d 55 58 3d  30 0d                    |AT+CMUX=0.|
I (26611) RX: 0x3fca5520   0d 0a 4f 4b 0d 0a                                 |..OK..|
I (27111) TX: 0x3fca6bc0   f9 03 3f 01 1c f9                                 |..?...|
E (28131) modem_console: Failed to set the desired mode
Command returned non-zero error code: 0x1 (ERROR)
esp> 

My logic analyser connected to the TX/RX ports confirms this:

Screenshot 2024-10-24 at 15 35 27

I think it's very weird that thd SIM7670G doesn't send any CMUX frames, but keeps responding to AT commands.

I've found a couple of curious hints:

  1. LilyGo github: "SIM7672G and SIM7670G are exactly the same" suggesting that the SIM7670G may not be a SIM76XX but a SIM767XX.
  2. The 2374_SIM767XM5A_M
    Firmware Release Note
    mentions a document called "SIM767XX Series_CMUX_USER_GUIDE. docx"
  3. https://simcom.ee/documents/SIM900/SIM900_Multiplexer%20User%20Manual_Application%20Note_V1.3.pdf says in §3.1: "Host need quickly send the establish DLC0 frame otherwise the client will exit MUX state."

@david-cermak
Copy link
Collaborator

Thanks for your extensive testing and investigation!
Unfortunately I don't have any SIM767x device with me, Have tested with SIM7600 and A7672, they both work the same on CMUX level and SIM800, which works a bit differently, but still compliant with this library. Then there are some devices (like in the linked issue), which we could make work with this lib, but that would violate the spec. And then, there's this SIM7000 which doesn't support CMUX at all. Looks like the SIM7670G would be just another one on the list.

Firmware Release Note mentions a document called "SIM767XX Series_CMUX_USER_GUIDE. docx"

Also seen some references to that "user guide", but couldn't find one.

"Host need quickly send the establish DLC0 frame otherwise the client will exit MUX state."

I'm afraid that's related to a different device, but still, we're sending the SABM's immediately after getting the OK from AT+CMUX (CONFIG_ESP_MODEM_CMUX_DELAY_AFTER_DLCI_SETUP is 0 by default)

@morgana2313
Copy link
Author

morgana2313 commented Oct 25, 2024

I tried set_mode CMUX also on a LilyGo T-A7670E/G/SA. Here the output is as expected (see below). My conclusion is that CMUX in the SIM7670G chip is broken. I'll open an issue with Lilygo and SIMCOM:

<wait for the modem to boot = the red LED next to the modem chip to start blinking>

esp> cmd AT
I (23894) modem_console: Sending command AT with timeout 1000
I (23894) TX: 0x3ffbe690   41 54 0d                                          |AT.|
I (23914) RX: 0x3ffbca28   0d 0a 2a 41 54 52 45 41  44 59 3a 20 31 0d 0a 0d  |..*ATREADY: 1...|
I (23914) RX: 0x3ffbca38   0a 2b 43 50 49 4e 3a 20  52 45 41 44 59 0d 0a 0d  |.+CPIN: READY...|
I (23924) RX: 0x3ffbca48   0a 53 4d 53 20 44 4f 4e  45 0d 0a 0d 0a 2b 43 47  |.SMS DONE....+CG|
I (23934) RX: 0x3ffbca58   45 56 3a 20 45 50 53 20  50 44 4e 20 41 43 54 20  |EV: EPS PDN ACT |
I (23944) RX: 0x3ffbca68   31 0d 0a 0d 0a 50 42 20  44 4f 4e 45 0d 0a 41 54  |1....PB DONE..AT|
I (23954) RX: 0x3ffbca78   0d 0d 0a 4f 4b 0d 0a                              |...OK..|
I (23964) modem_console: 
*ATREADY: 1

+CPIN: READY

SMS DONE

+CGEV: EPS PDN ACT 1

PB DONE
AT
OK

esp> cmd ATE0
I (35934) modem_console: Sending command ATE0 with timeout 1000
I (35934) TX: 0x3ffbe690   41 54 45 30 0d                                    |ATE0.|
I (35954) RX: 0x3ffbca28   41 54 45 30 0d 0d 0a 4f  4b 0d 0a                 |ATE0...OK..|
I (35964) modem_console: ATE0
OK

esp> cmd ATI
I (592234) modem_console: Sending command ATI with timeout 1000
I (592234) TX: 0x3ffbe524   f9 09 ef 09                                       |....|
I (592244) TX: 0x3ffbe690   41 54 49 0d                                       |ATI.|
I (592244) TX: 0x3ffbe528   df f9                                             |..|
I (592264) RX: 0x3ffbca28   f9 09 ef 09 41 54 49 0d  df f9 f9 09 ef d7 0d 0a  |....ATI.........|
I (592264) RX: 0x3ffbca38   4d 61 6e 75 66 61 63 74  75 72 65 72 3a 20 53 49  |Manufacturer: SI|
I (592274) RX: 0x3ffbca48   4d 43 4f 4d 20 49 4e 43  4f 52 50 4f 52 41 54 45  |MCOM INCORPORATE|
I (592294) RX: 0x3ffbca58   44 0d 0a 4d 6f 64 65 6c  3a 20 41 37 36 37 30 45  |D..Model: A7670E|
I (592294) RX: 0x3ffbca68   2d 46 41 53 45 0d 0a 52  65 76 69 73 69 6f 6e 3a  |-FASE..Revision:|
I (592304) RX: 0x3ffbca78   20 41 37 36 37 30 4d 37  5f 56 31 2e 31 31 2e 31  | A7670M7_V1.11.1|
I (592314) RX: 0x3ffbca88   0d 0a 49 4d 45 49 3a 20  38 36 37 32 35 35 30 37  |..IMEI: 86725507|
I (592324) RX: 0x3ffbca98   39 37 37 36 30 38 36 0d  0a b9 f9                 |9776086....|
I (592334) modem_console: 
Manufacturer: SIMCOM INCORPORATED
Model: A7670E-FASE
Revision: A7670M7_V1.11.1
IMEI: 867255079776086

esp> cmd AT
I (40254) modem_console: Sending command AT with timeout 1000
I (40254) TX: 0x3ffbe690   41 54 0d                                          |AT.|
I (40274) RX: 0x3ffbca28   0d 0a 4f 4b 0d 0a                                 |..OK..|
I (40274) modem_console: 
OK

esp> set_mode CMUX
I (49364) modem_console: Switching to CMUX name...
I (49364) TX: 0x3ffbe59c   41 54 2b 43 4d 55 58 3d  30 0d                    |AT+CMUX=0.|
I (49374) RX: 0x3ffbca28   0d 0a 4f 4b 0d 0a                                 |..OK..|
I (49884) TX: 0x3ffbe530   f9 03 3f 01 1c f9                                 |..?...|
I (49884) RX: 0x3ffbca28   f9 03 73 01 d7 f9                                 |..s...|
I (49904) TX: 0x3ffbe530   f9 07 3f 01 de f9                                 |..?...|
I (49904) RX: 0x3ffbca28   f9 07 73 01 15 f9                                 |..s...|
I (49924) TX: 0x3ffbe530   f9 0b 3f 01 59 f9                                 |..?.Y.|
I (49924) RX: 0x3ffbca28   f9 0b 73 01 92 f9                                 |..s...|
I (49944) TX: 0x3ffbe334   f9 05 ef 0b                                       |....|
I (49944) TX: 0x3ffbe55c   41 54 45 30 0d                                    |ATE0.|
I (49954) TX: 0x3ffbe338   bb f9                                             |..|
I (49964) RX: 0x3ffbca28   f9 05 ef 0b 41 54 45 30  0d bb f9 f9 05 ef 0d 0d  |....ATE0........|
I (49964) RX: 0x3ffbca38   0a 4f 4b 0d 0a 5f f9                              |.OK.._.|
I (49984) TX: 0x3ffbe2a4   f9 05 ef 3b                                       |...;|
I (49984) TX: 0x3ffbfed4   41 54 2b 43 47 44 43 4f  4e 54 3d 31 2c 22 49 50  |AT+CGDCONT=1,"IP|
I (49994) TX: 0x3ffbfee4   22 2c 22 69 6e 74 65 72  6e 65 74 22 0d           |","internet".|
I (50004) TX: 0x3ffbe2a8   9f f9                                             |..|
I (50014) RX: 0x3ffbca28   f9 05 ef 0d 0d 0a 4f 4b  0d 0a 5f f9              |......OK.._.|
I (50024) TX: 0x3ffbe374   f9 05 ef 11                                       |....|
I (50034) TX: 0x3ffbe574   41 54 44 2a 39 39 23 0d                           |ATD*99#.|
I (50034) TX: 0x3ffbe378   4a f9                                             |J.|
I (50124) RX: 0x3ffbca28   f9 05 ef 25 0d 0a 43 4f  4e 4e 45 43 54 20 31 31  |...%..CONNECT 11|
I (50124) RX: 0x3ffbca38   35 32 30 30 0d 0a 69 f9                           |5200..i.|
I (50134) TX: 0x3ffb80c4   f9 05 ef 5d                                       |...]|
I (50144) TX: 0x3ffc04e4   7e ff 7d 23 c0 21 7d 21  7d 21 7d 20 7d 34 7d 22  |~.}#.!}!}!} }4}"|
I (50154) TX: 0x3ffc04f4   7d 26 7d 20 7d 20 7d 20  7d 20 7d 25 7d 26 e1 ee  |}&} } } } }%}&..|
I (50164) TX: 0x3ffc0504   4a 7d 2d 7d 27 7d 22 7d  28 7d 22 61 7b 7e        |J}-}'}"}(}"a{~|
I (50164) TX: 0x3ffb80c8   33 f9                                             |3.|
I (50174) modem_console: OK
I (50184) RX: 0x3ffbca28   f9 05 ef 69 7e ff 7d 23  c0 21 7d 21 7d 21 7d 20  |...i~.}#.!}!}!} |
I (50194) RX: 0x3ffbca38   7d 38 7d 22 7d 26 7d 20  7d 20 7d 20 7d 20 7d 23  |}8}"}&} } } } }#|
I (50204) RX: 0x3ffbca48   7d 24 c0 23 7d 25 7d 26  55 bc 9d 7d 37 7d 27 7d  |}$.#}%}&U..}7}'}|                                                                                                                                                                      
I (50214) RX: 0x3ffbca58   22 7d 28 7d 22 ac 85 7e  10 f9 f9 05 ef 5f 7e ff  |"}(}"..~....._~.|
I (50224) TX: 0x3ffb8124   f9 05 ef 2f                                       |.../|
I (50224) RX: 0x3ffbca68   7d 23 c0 21 7d 22 7d 21  7d 20 7d 34 7d 22 7d 26  |}#.!}"}!} }4}"}&|
I (50234) TX: 0x3ffc0af8   7e ff 7d 23 c0 21 7d 24  7d 21 7d 20 7d 28 7d 23  |~.}#.!}$}!} }(}#| 
I (50244) RX: 0x3ffbca78   7d 20 7d 20 7d 20 7d 20  7d 25 7d 26 e1 ee 4a 7d  |} } } } }%}&..J}|
I (50254) TX: 0x3ffc0b08   7d 24 c0 23 2c d4 7e                              |}$.#,.~|
I (50254) RX: 0x3ffbca88   2d 7d 27 7d 22 7d 28 7d  22 8a 7d 32 7e d0 f9     |-}'}"}(}".}2~..|
I (50264) TX: 0x3ffb8128   84 f9                                             |..|
I (50284) RX: 0x3ffbca28   f9 05 ef 5d 7e ff 7d 23  c0 21 7d 21 7d 22 7d 20  |...]~.}#.!}!}"} |
I (50294) RX: 0x3ffbca38   7d 34 7d 22 7d 26 7d 20  7d 20 7d 20 7d 20 7d 25  |}4}"}&} } } } }%|
I (50304) RX: 0x3ffbca48   7d 26 4d 43 6e d6 7d 27  7d 22 7d 28 7d 22 7d 3d  |}&MCn.}'}"}(}"}=|
I (50314) RX: 0x3ffbca58   66 7e 33 f9                                       |f~3.|
I (50324) TX: 0x3ffb8124   f9 05 ef 5d                                       |...]|
I (50334) TX: 0x3ffc0af8   7e ff 7d 23 c0 21 7d 22  7d 22 7d 20 7d 34 7d 22  |~.}#.!}"}"} }4}"|
I (50334) TX: 0x3ffc0b08   7d 26 7d 20 7d 20 7d 20  7d 20 7d 25 7d 26 4d 43  |}&} } } } }%}&MC|
I (50344) TX: 0x3ffc0b18   6e d6 7d 27 7d 22 7d 28  7d 22 f6 7d 2f 7e        |n.}'}"}(}".}/~|
I (50354) TX: 0x3ffb8128   33 f9                                             |3.|
I (50374) TX: 0x3ffb8044   f9 05 ef 49                                       |...I|
I (50374) TX: 0x3ffc0af8   7e ff 03 80 21 01 01 00  1c 02 06 00 2d 0f 01 03  |~...!.......-...|
I (50384) TX: 0x3ffc0b08   06 00 00 00 00 81 06 00  00 00 00 83 06 00 00 00  |................|
I (50394) TX: 0x3ffc0b18   00 55 15 7e                                       |.U.~|
I (50394) TX: 0x3ffb8048   28 f9                                             |(.|
I (50414) RX: 0x3ffbca28   f9 05 ef 15 7e 80 21 01  00 00 04 67 c3 7e 4d f9  |....~.!....g.~M.|
I (50414) RX: 0x3ffbca38   f9 05 ef 21 7e 80 21 04  01 00 0a 02 06 00 2d 0f  |...!~.!.......-.|
I (50434) RX: 0x3ffbca48   01 f8 30 7e 6e f9                                 |..0~n.|
I (50444) TX: 0x3ffb8124   f9 05 ef 25                                       |...%|
I (50444) TX: 0x3ffc0af8   7e ff 03 80 21 03 00 00  0a 03 06 00 00 00 00 a0  |~...!...........|
I (50454) TX: 0x3ffc0b08   3d 7e                                             |=~|
I (50454) TX: 0x3ffb8128   69 f9                                             |i.|
I (50474) TX: 0x3ffb8134   f9 05 ef 3d                                       |...=|
I (50484) TX: 0x3ffc0af8   7e ff 03 80 21 01 02 00  16 03 06 00 00 00 00 81  |~...!...........|
I (50484) TX: 0x3ffc0b08   06 00 00 00 00 83 06 00  00 00 00 da 82 7e        |.............~|
I (50494) TX: 0x3ffb8138   7b f9                                             |{.|
I (50514) RX: 0x3ffbca28   f9 05 ef 15 7e 80 21 01  01 00 04 bb 99 7e 4d f9  |....~.!......~M.|
I (50514) RX: 0x3ffbca38   f9 05 ef 39 7e 80 21 03  02 00 16 03 06 64 74 56  |...9~.!......dtV|
I (50534) RX: 0x3ffbca48   a6 81 06 c2 97 e4 22 83  06 c2 97 e4 02 20 9d 7e  |......"...... .~|
I (50544) RX: 0x3ffbca58   7c f9                                             ||.|
I (50544) TX: 0x3ffb8124   f9 05 ef 19                                       |....|
I (50554) TX: 0x3ffc0af8   7e ff 03 80 21 02 01 00  04 cd 92 7e              |~...!......~|
I (50554) TX: 0x3ffb8128   44 f9                                             |D.|
I (50574) TX: 0x3ffb8134   f9 05 ef 3d                                       |...=|
I (50584) TX: 0x3ffc110c   7e ff 03 80 21 01 03 00  16 03 06 64 74 56 a6 81  |~...!......dtV..|
I (50584) TX: 0x3ffc111c   06 c2 97 e4 22 83 06 c2  97 e4 02 87 60 7e        |....".......`~|
I (50594) TX: 0x3ffb8138   7b f9                                             |{.|
I (50614) RX: 0x3ffbca28   f9 05 ef 39 7e 80 21 02  03 00 16 03 06 64 74 56  |...9~.!......dtV|
I (50614) RX: 0x3ffbca38   a6 81 06 c2 97 e4 22 83  06 c2 97 e4 02 11 03 7e  |......"........~|
I (50634) RX: 0x3ffbca48   7c f9                                             ||.|
I (50644) esp-netif_lwip-ppp: Connected
esp> 
esp> ping 8.8.8.8
I (57774) TX: 0x3ffb80e4   f9 05 ef c7                                       |....|
I (57774) TX: 0x3ffc0d68   7e 21 45 00 00 5c 00 00  00 00 40 01 af 77 64 74  |~!E..\[email protected]|
I (57784) TX: 0x3ffc0d78   56 a6 08 08 08 08 08 00  f2 c9 f8 09 01 00 41 42  |V.............AB|
I (57784) TX: 0x3ffc0d88   43 44 45 46 47 48 49 4a  4b 4c 4d 4e 4f 50 51 52  |CDEFGHIJKLMNOPQR|
                                                                                                                                                                      I (57794) TX: 0x3ffc0d98   53 54 55 56 57 58 59 5a  5b 5c 5d 5e 5f 60 61 62  |STUVWXYZ[\]^_`ab|
I (57804) TX: 0x3ffc0da8   63 64 65 66 67 68 69 6a  6b 6c 6d 6e 6f 70 71 72  |cdefghijklmnopqr|
I (57824) TX: 0x3ffc0db8   73 74 75 76 77 78 79 7a  7b 7c 7d 5d 7d 5e 7f 80  |stuvwxyz{|}]}^..|
I (57824) TX: 0x3ffc0dc8   bb db 7e                                          |..~|
esp> I (57844) TX: 0x3ffb80e8   22 f9                                             |".|
I (58014) RX: 0x3ffbca28   f9 05 ef c7 7e 21 45 00  00 5c 00 00 00 00 3a 01  |....~!E..\....:.|
I (58014) RX: 0x3ffbca38   b5 77 08 08 08 08 64 74  56 a6 00 00 fa c9 f8 09  |.w....dtV.......|
I (58034) RX: 0x3ffbca48   01 00 41 42 43 44 45 46  47 48 49 4a 4b 4c 4d 4e  |..ABCDEFGHIJKLMN|
I (58044) RX: 0x3ffbca58   4f 50 51 52 53 54 55 56  57 58 59 5a 5b 5c 5d 5e  |OPQRSTUVWXYZ[\]^|
I (58044) RX: 0x3ffbca68   5f 60 61 62 63 64 65 66  67 68 69 6a 6b 6c 6d 6e  |_`abcdefghijklmn|
I (58054) RX: 0x3ffbca78   6f 70 71 72 73 74 75 76  77 78 79 7a 7b 7c 7d 5d  |opqrstuvwxyz{|}]|
I (58064) RX: 0x3ffbca88   7d 5e 7f 80 dd 99 7e 22  f9                       |}^....~".|
I (58074) modem_console_ping: 64 bytes from 8.8.8.8 icmp_seq=1 ttl=58 time=219 ms

I (58764) TX: 0x3ffb80e4   f9 05 ef c7                                       |....|
I (58764) TX: 0x3ffc1378   7e 21 45 00 00 5c 00 01  00 00 40 01 af 76 64 74  |~!E..\[email protected]|
I (58774) TX: 0x3ffc1388   56 a6 08 08 08 08 08 00  f1 c9 f8 09 02 00 41 42  |V.............AB|
I (58774) TX: 0x3ffc1398   43 44 45 46 47 48 49 4a  4b 4c 4d 4e 4f 50 51 52  |CDEFGHIJKLMNOPQR|
I (58784) TX: 0x3ffc13a8   53 54 55 56 57 58 59 5a  5b 5c 5d 5e 5f 60 61 62  |STUVWXYZ[\]^_`ab|
I (58804) TX: 0x3ffc13b8   63 64 65 66 67 68 69 6a  6b 6c 6d 6e 6f 70 71 72  |cdefghijklmnopqr|
I (58814) TX: 0x3ffc13c8   73 74 75 76 77 78 79 7a  7b 7c 7d 5d 7d 5e 7f 80  |stuvwxyz{|}]}^..|
I (58814) TX: 0x3ffc13d8   1c a2 7e                                          |..~|
I (58824) TX: 0x3ffb80e8   22 f9                                             |".|
I (58884) RX: 0x3ffbca28   f9 05 ef c7 7e 21 45 00  00 5c 00 00 00 00 3a 01  |....~!E..\....:.|
I (58884) RX: 0x3ffbca38   b5 77 08 08 08 08 64 74  56 a6 00 00 f9 c9 f8 09  |.w....dtV.......|
I (58894) RX: 0x3ffbca48   02 00 41 42 43 44 45 46  47 48 49 4a 4b 4c 4d 4e  |..ABCDEFGHIJKLMN|
I (58914) RX: 0x3ffbca58   4f 50 51 52 53 54 55 56  57 58 59 5a 5b 5c 5d 5e  |OPQRSTUVWXYZ[\]^|
I (58914) RX: 0x3ffbca68   5f 60 61 62 63 64 65 66  67 68 69 6a 6b 6c 6d 6e  |_`abcdefghijklmn|
I (58924) RX: 0x3ffbca78   6f 70 71 72 73 74 75 76  77 78 79 7a 7b 7c 7d 5d  |opqrstuvwxyz{|}]|
I (58934) RX: 0x3ffbca88   7d 5e 7f 80 da 54 7e 22  f9                       |}^...T~".|
I (58944) modem_console_ping: 64 bytes from 8.8.8.8 icmp_seq=2 ttl=58 time=100 ms

I (59764) TX: 0x3ffb80e4   f9 05 ef c7                                       |....|
I (59764) TX: 0x3ffc1378   7e 21 45 00 00 5c 00 02  00 00 40 01 af 75 64 74  |~!E..\[email protected]|
I (59774) TX: 0x3ffc1388   56 a6 08 08 08 08 08 00  f0 c9 f8 09 03 00 41 42  |V.............AB|
I (59774) TX: 0x3ffc1398   43 44 45 46 47 48 49 4a  4b 4c 4d 4e 4f 50 51 52  |CDEFGHIJKLMNOPQR|
I (59784) TX: 0x3ffc13a8   53 54 55 56 57 58 59 5a  5b 5c 5d 5e 5f 60 61 62  |STUVWXYZ[\]^_`ab|
I (59804) TX: 0x3ffc13b8   63 64 65 66 67 68 69 6a  6b 6c 6d 6e 6f 70 71 72  |cdefghijklmnopqr|
I (59814) TX: 0x3ffc13c8   73 74 75 76 77 78 79 7a  7b 7c 7d 5d 7d 5e 7f 80  |stuvwxyz{|}]}^..|
I (59814) TX: 0x3ffc13d8   1f cb 7e                                          |..~|
I (59824) TX: 0x3ffb80e8   22 f9                                             |".|
I (59864) RX: 0x3ffbca28   f9 05 ef c7 7e 21 45 00  00 5c 00 00 00 00 3a 01  |....~!E..\....:.|
I (59874) RX: 0x3ffbca38   b5 77 08 08 08 08 64 74  56 a6 00 00 f8 c9 f8 09  |.w....dtV.......|
I (59884) RX: 0x3ffbca48   03 00 41 42 43 44 45 46  47 48 49 4a 4b 4c 4d 4e  |..ABCDEFGHIJKLMN|
I (59894) RX: 0x3ffbca58   4f 50 51 52 53 54 55 56  57 58 59 5a 5b 5c 5d 5e  |OPQRSTUVWXYZ[\]^|
I (59894) RX: 0x3ffbca68   5f 60 61 62 63 64 65 66  67 68 69 6a 6b 6c 6d 6e  |_`abcdefghijklmn|
I (59914) RX: 0x3ffbca78   6f 70 71 72 73 74 75 76  77 78 79 7a 7b 7c 7d 5d  |opqrstuvwxyz{|}]|
I (59924) RX: 0x3ffbca88   7d 5e 7f 80 28 e8 7e 22  f9                       |}^..(.~".|
I (59924) modem_console_ping: 64 bytes from 8.8.8.8 icmp_seq=3 ttl=58 time=85 ms

I (60764) TX: 0x3ffb80e4   f9 05 ef c7                                       |....|
I (60764) TX: 0x3ffc1378   7e 21 45 00 00 5c 00 03  00 00 40 01 af 74 64 74  |~!E..\[email protected]|
I (60774) TX: 0x3ffc1388   56 a6 08 08 08 08 08 00  ef c9 f8 09 04 00 41 42  |V.............AB|
I (60774) TX: 0x3ffc1398   43 44 45 46 47 48 49 4a  4b 4c 4d 4e 4f 50 51 52  |CDEFGHIJKLMNOPQR|
I (60784) TX: 0x3ffc13a8   53 54 55 56 57 58 59 5a  5b 5c 5d 5e 5f 60 61 62  |STUVWXYZ[\]^_`ab|
I (60804) TX: 0x3ffc13b8   63 64 65 66 67 68 69 6a  6b 6c 6d 6e 6f 70 71 72  |cdefghijklmnopqr|
I (60814) TX: 0x3ffc13c8   73 74 75 76 77 78 79 7a  7b 7c 7d 5d 7d 5e 7f 80  |stuvwxyz{|}]}^..|
I (60814) TX: 0x3ffc13d8   bf 7a 7e                                          |.z~|
I (60824) TX: 0x3ffb80e8   22 f9                                             |".|
I (60874) RX: 0x3ffbca28   f9 05 ef c7 7e 21 45 00  00 5c 00 00 00 00 3a 01  |....~!E..\....:.|
I (60874) RX: 0x3ffbca38   b5 77 08 08 08 08 64 74  56 a6 00 00 f7 c9 f8 09  |.w....dtV.......|
I (60884) RX: 0x3ffbca48   04 00 41 42 43 44 45 46  47 48 49 4a 4b 4c 4d 4e  |..ABCDEFGHIJKLMN|
I (60894) RX: 0x3ffbca58   4f 50 51 52 53 54 55 56  57 58 59 5a 5b 5c 5d 5e  |OPQRSTUVWXYZ[\]^|
I (60894) RX: 0x3ffbca68   5f 60 61 62 63 64 65 66  67 68 69 6a 6b 6c 6d 6e  |_`abcdefghijklmn|
I (60914) RX: 0x3ffbca78   6f 70 71 72 73 74 75 76  77 78 79 7a 7b 7c 7d 5d  |opqrstuvwxyz{|}]|
I (60924) RX: 0x3ffbca88   7d 5e 7f 80 91 27 7e 22  f9                       |}^...'~".|
I (60924) modem_console_ping: 64 bytes from 8.8.8.8 icmp_seq=4 ttl=58 time=87 ms

I (61764) TX: 0x3ffb80e4   f9 05 ef c7                                       |....|
I (61764) TX: 0x3ffc1378   7e 21 45 00 00 5c 00 04  00 00 40 01 af 73 64 74  |~!E..\[email protected]|
I (61774) TX: 0x3ffc1388   56 a6 08 08 08 08 08 00  ee c9 f8 09 05 00 41 42  |V.............AB|
I (61774) TX: 0x3ffc1398   43 44 45 46 47 48 49 4a  4b 4c 4d 4e 4f 50 51 52  |CDEFGHIJKLMNOPQR|
I (61784) TX: 0x3ffc13a8   53 54 55 56 57 58 59 5a  5b 5c 5d 5e 5f 60 61 62  |STUVWXYZ[\]^_`ab|
I (61804) TX: 0x3ffc13b8   63 64 65 66 67 68 69 6a  6b 6c 6d 6e 6f 70 71 72  |cdefghijklmnopqr|
I (61814) TX: 0x3ffc13c8   73 74 75 76 77 78 79 7a  7b 7c 7d 5d 7d 5e 7f 80  |stuvwxyz{|}]}^..|
I (61814) TX: 0x3ffc13d8   1e d1 7e                                          |..~|
I (61824) TX: 0x3ffb80e8   22 f9                                             |".|
I (61874) RX: 0x3ffbca28   f9 05 ef c7 7e 21 45 00  00 5c 00 00 00 00 3a 01  |....~!E..\....:.|
I (61884) RX: 0x3ffbca38   b5 77 08 08 08 08 64 74  56 a6 00 00 f6 c9 f8 09  |.w....dtV.......|
I (61894) RX: 0x3ffbca48   05 00 41 42 43 44 45 46  47 48 49 4a 4b 4c 4d 4e  |..ABCDEFGHIJKLMN|
I (61904) RX: 0x3ffbca58   4f 50 51 52 53 54 55 56  57 58 59 5a 5b 5c 5d 5e  |OPQRSTUVWXYZ[\]^|
I (61904) RX: 0x3ffbca68   5f 60 61 62 63 64 65 66  67 68 69 6a 6b 6c 6d 6e  |_`abcdefghijklmn|
I (61914) RX: 0x3ffbca78   6f 70 71 72 73 74 75 76  77 78 79 7a 7b 7c 7d 5d  |opqrstuvwxyz{|}]|
I (61934) RX: 0x3ffbca88   7d 5e 7f 80 63 9b 7e 22  f9                       |}^..c.~".|
I (61934) modem_console_ping: 64 bytes from 8.8.8.8 icmp_seq=5 ttl=58 time=95 ms

I (62764) modem_console_ping: 
--- 8.8.8.8 ping statistics ---
I (62764) modem_console_ping: 5 packets transmitted, 5 received, 0 packet loss, time 586ms

esp> cmd AT

I (415014) modem_console: Sending command AT with timeout 1000
I (415014) TX: 0x3ffbe524   f9 09 ef 07                                       |....|
I (415024) TX: 0x3ffbe690   41 54 0d                                          |AT.|
I (415034) TX: 0x3ffbe528   35 f9                                             |5.|
I (415044) RX: 0x3ffbca28   f9 09 ef 07 41 54 0d 35  f9 f9 09 ef 0d 0d 0a 4f  |....AT.5.......O|
I (415054) RX: 0x3ffbca38   4b 0d 0a d8 f9                                    |K....|
I (415064) modem_console: 
OK

esp> 

@morgana2313
Copy link
Author

morgana2313 commented Oct 28, 2024

Two commits were added to the LilyGo ticket containing:

  1. The SIM767XX Series_CMUX_USER_GUIDE
  2. A rar file containing generic SIMCOM windows + linux CMUX software.
 Attributes      Size    Packed Ratio    Date    Time   Checksum  Name
----------- ---------  -------- ----- ---------- -----  --------  ----
    ..A....     86528     29238  33%  2018-03-01 06:50  4D1CCD6F  CMUX_V1.01/cmuxapp/cmuxapp-201803011435-f0d7c110/cmuxapp.exe
    ..A....    414507    389385  93%  2018-03-01 06:51  C981D4CE  CMUX_V1.01/cmuxapp/cmuxapp-201803011435-f0d7c110/doc/CMUXAPP_USER_GUIDE.pdf
    ..A....     27648     12630  45%  2017-12-08 15:44  6E39218A  CMUX_V1.01/cmuxapp/cmuxapp-201803011435-f0d7c110/imageformats/qico.dll
    ..A....    967680    403714  41%  2017-12-08 15:44  587B3EF6  CMUX_V1.01/cmuxapp/cmuxapp-201803011435-f0d7c110/platforms/qwindows.dll
    ..A....   4641280   1647201  35%  2017-12-08 15:41  B45B70C4  CMUX_V1.01/cmuxapp/cmuxapp-201803011435-f0d7c110/Qt5Core.dll
    ..A....   5019136   1284178  25%  2017-12-08 15:42  CF7F5562  CMUX_V1.01/cmuxapp/cmuxapp-201803011435-f0d7c110/Qt5Gui.dll
    ..A....     61952     23319  37%  2017-12-08 15:44  0C5FB497  CMUX_V1.01/cmuxapp/cmuxapp-201803011435-f0d7c110/Qt5SerialPort.dll
    ..A....   4433920   1604987  36%  2017-12-08 15:43  7B61DF33  CMUX_V1.01/cmuxapp/cmuxapp-201803011435-f0d7c110/Qt5Widgets.dll
    ..A....    261544    226843  86%  2017-07-13 08:26  E6DE96F5  CMUX_V1.01/cmuxapp/Setup_com0com_v3.0.0.0_W7_x64_signed.exe
    ..A....     20350     20350 100%  2024-02-23 11:37  4D47A460  CMUX_V1.01/gsmMuxLinuxAndroid.rar
    ..A....      1338      1338 100%  2024-01-15 06:55  62FBF651  CMUX_V1.01/ppp.rar
    ..A....   1391945   1177817  84%  2024-06-18 09:06  28378779  CMUX_V1.01/SIM767XX and A76XX Series_CMUX_USER_GUIDE_V1.01.pdf
    ...D...         0         0   0%  2024-06-18 08:45  00000000  CMUX_V1.01/cmuxapp/cmuxapp-201803011435-f0d7c110/doc
    ...D...         0         0   0%  2024-06-18 08:45  00000000  CMUX_V1.01/cmuxapp/cmuxapp-201803011435-f0d7c110/imageformats
    ...D...         0         0   0%  2024-06-18 08:45  00000000  CMUX_V1.01/cmuxapp/cmuxapp-201803011435-f0d7c110/platforms
    ...D...         0         0   0%  2024-06-18 08:45  00000000  CMUX_V1.01/cmuxapp/cmuxapp-201803011435-f0d7c110
    ...D...         0         0   0%  2024-06-18 08:45  00000000  CMUX_V1.01/cmuxapp
    ...D...         0         0   0%  2024-06-18 09:11  00000000  CMUX_V1.01
----------- ---------  -------- ----- ---------- -----  --------  ----
             17327828   6821000  39%                              18

@morgana2313
Copy link
Author

With this windows (!) software CMUX appears to work with the SIM7670G on a LilyGo T-SIM7670G s3, so it should be possible to analyse this further and see what the windows driver is doing differently.

@david-cermak
Copy link
Collaborator

Nice, thanks for sharing! Noticed there's also a source in plain C (for linux) called gsm0710, suggesting it complies with standard CMUX spec.
Skimmed through the pdf and the only difference I noticed is that they use AT+CMUX=0,0,5,1500 instead of just the default AT+CMUX=0. (and they establish 3 virtual terminals).
Could you please check you can setup CMUX mode when using this command AT+CMUX=0,0,5,1500 ?

@morgana2313
Copy link
Author

morgana2313 commented Oct 29, 2024

We noticed AT+CMUX=0,0,5,1500 too, but doesn't seem to make much of a difference used in esp_modem.
Using the Windows software we did notice a multiple second delay between the AT+CMUX=0,0,5,1500 and the CMUX sabm dataframes, we'll experiment with that. We'll make a log of the RX/TX data from the windows CMUX.

Some other questions:

  1. Allthough esp_modem_command_library.cpp:set_cmux() parses the OK/ERROR reply of the modem, the command_result returned seems to be ignored by the calling function. I have some trouble identifying the calling function however in the layers of functions and abstractions.

  2. CMux::init sends send_sab for channels 0..2. CMux::data_available checks if the sabm_frame (frame[2] = FT_UA | PF = 0x73) but also explicitly allows (frame[2] = FT_SABM | PF = 0x3f) which could be a replied echo of the frame just sent by send_sabm() to set sabm_ack = dlci.

  3. ConsoleCommands have a limited reply buffer. Where could a check be added to see of the response was complete? Again I have som trouble understanding the layers of functions and abstractions.

@david-cermak
Copy link
Collaborator

  1. It's ignored right here:

device->set_mode(modem_mode::CMUX_MODE); // switch the device into CMUX mode

I'd noticed this bug some times ago, but refrained from fixin it, finding it useful to enter CMUX mode while in CMUX already (AT command would fail, but the subsequent CMUX request(s) would re-enter CMUX). But I'll fix it in the end, after merging #612

  1. The logic's okay IMO, as the SAMB gets acked only here:

} else if (data == nullptr && type == (FT_UA | PF) && len == 0) { // notify the initial SABM command
Scoped<Lock> l(lock);
sabm_ack = dlci;

(and your experiments suggest so, as you saw SABM request echo's but CMUX entry failed on missing SABM replies)

  1. There's no limit, if you're using std::string which can grow if needed, for example this:

const ConsoleCommand GetOperatorName("get_operator_name", "reads the operator name", no_args, [&](ConsoleCommand * c) {
std::string operator_name;
int act;
ESP_LOGI(TAG, "Reading operator name...");
CHECK_ERR(dce->get_operator_name(operator_name, act), ESP_LOGI(TAG, "OK. Operator name: %s", operator_name.c_str()));
});

shouldn't have any reply buffer limit.

Where could a check be added to see of the response was complete?

just checking the expected pattern, for ConsoleCommand class, you can do it manually with a lambda:

CHECK_ERR(dce->command(cmd, [&](uint8_t *data, size_t len) {
std::string response((char *) data, len);
ESP_LOGI(TAG, "%s", response.c_str());
if (pattern.empty() || response.find(pattern) != std::string::npos) {
return command_result::OK;
}
if (response.find(pattern) != std::string::npos) {
return command_result::OK;
}
return command_result::TIMEOUT;
}, timeout),);

@morgana2313
Copy link
Author

  1. I' sorry, I'll update my repo. In my version 0e0cbd6 this line reads:
    } else if (data == nullptr && (type == (FT_UA | PF) || type == 0x3f) && len == 0) { // notify the initial SABM command
  1. On commands with a reply longer than 64 bytes the last part of the reply is not shown, but is displayed in the next cmd call:
esp> cmd ATI
I (194061) modem_console: Sending command ATI with timeout 1000
I (194061) TX: 0x3fca6d40   41 54 49 0d                                       |ATI.|
I (194071) RX: 0x3fca5540   0d 0a 4d 61 6e 75 66 61  63 74 75 72 65 72 3a 20  |..Manufacturer: |
I (194071) RX: 0x3fca5550   53 49 4d 43 4f 4d 20 49  4e 43 4f 52 50 4f 52 41  |SIMCOM INCORPORA|
I (194071) RX: 0x3fca5560   54 45 44 0d 0a 4d 6f 64  65 6c 3a 20 53 49 4d 37  |TED..Model: SIM7|
I (194071) RX: 0x3fca5570   36 37 30 47 2d 4d 4e 47  56 0d 0a 52 65 76 69 73  |670G-MNGV..Revis|
I (194071) modem_console: 
Manufacturer: SIMCOM INCORPORATED
Model: SIM7670G-MNGV
Revis
esp> cmd AT
I (196561) modem_console: Sending command AT with timeout 1000
I (196561) TX: 0x3fca6d40   41 54 0d                                          |AT.|
I (196561) RX: 0x3fca5540   69 6f 6e 3a 20 56 31 2e  39 2e 30 31 0d 0a 49 4d  |ion: V1.9.01..IM|
I (196561) RX: 0x3fca5550   45 49 3a 20 38 36 34 36  34 33 30 36 30 30 33 31  |EI: 864643060031|
I (196561) RX: 0x3fca5560   37 31 35 0d 0a 0d 0a 4f  4b 0d 0a 0d 0a 4f 4b 0d  |715....OK....OK.|
I (196561) RX: 0x3fca5570   0a                                                |.|
I (196561) modem_console: ion: V1.9.01
IMEI: 864643060031715

OK

OK

esp> 

@david-cermak
Copy link
Collaborator

Ad 3)

if (pattern.empty() || response.find(pattern) != std::string::npos) {
return command_result::OK;
}

if the pattern is empty, we just print out the first chunk are return command_result::OK
you can try:

esp> cmd ATI -p OK

or help for more details

esp> cmd -h

cmd(STR1, nullptr, nullptr, "<command>", "AT command to send to the modem"),
timeout(INT0, "t", "timeout", "<timeout>", "command timeout"),
pattern(STR0, "p", "pattern", "<pattern>", "command response to wait for"),
no_cr(LIT0, "n", "no-cr", "do not add trailing CR to the command") {}

@morgana2313
Copy link
Author

With the windows software LilyGo provided CMUX doesn't work with the default SIM767XM5A_B01V03_231207 firmware. However after a upgrade to SIM767XM5_B03V02_240914 CMUX works with windows.

Tomorrow I'll try it with esp_modem.

@morgana2313
Copy link
Author

With modem firmware SIM767XM5_B03V02_240914 or SIM767XM5_B04V01_241010 CMUX works with the SIM7670G. However after sending the sabm Unnumbered Acknowlegdement it sends a QCRDY message that causes a Restarting CMUX state machine (reason: 4). See log below.

esp> set_mode CMUX
I (22051) modem_console: Switching to CMUX name...
I (22051) esp_modem_dce_module.hpp: set_mode: 4
I (22051) TX: 0x3fca75cc   41 54 2b 43 4d 55 58 3d  30 0d                    |AT+CMUX=0.|
I (22061) RX: 0x3fca5edc   41 54 2b 43 4d 55 58 3d  30 0d 0d 0a 4f 4b 0d 0a  |AT+CMUX=0...OK..|
I (22161) esp_modem_cmux.cpp:CMux::init: send_sabm 0
I (22161) TX: 0x3fca7570   f9 03 3f 01 1c f9                                 |..?...|
I (22161) RX: 0x3fca5edc   f9 03 73 01 d7 f9                                 |..s...|
I (22161) esp_modem_cmux.cpp:CMux::data_available: sabm_ack=0
I (22171) esp_modem_cmux.cpp:CMux::init: send_sabm 1
I (22171) TX: 0x3fca7570   f9 07 3f 01 de f9                                 |..?...|
I (22171) RX: 0x3fca5edc   f9 07 73 01 15 f9                                 |..s...|
I (22171) esp_modem_cmux.cpp:CMux::data_available: sabm_ack=1
I (22171) RX: 0x3fca5edc   f9 07 73 01 15 f9                                 |..s...|
I (22171) esp_modem_cmux.cpp:CMux::data_available: sabm_ack=1
I (22171) RX: 0x3fca5edc   f9 07 ef 13 0d 0a 51 43  52 44 59 0d 0a c8 f9     |......QCRDY....|
W (22171) CMUX: Restarting CMUX state machine (reason: 4)
I (22171) CMUX: Protocol recovered
I (22181) esp_modem_cmux.cpp:CMux::init: send_sabm 2
I (22181) TX: 0x3fca7570   f9 0b 3f 01 59 f9                                 |..?.Y.|
I (22181) RX: 0x3fca5edc   f9 0b 73 01 92 f9                                 |..s...|
I (22181) esp_modem_cmux.cpp:CMux::data_available: sabm_ack=2
I (22181) RX: 0x3fca5edc   f9 0b 73 01 92 f9                                 |..s...|
I (22181) esp_modem_cmux.cpp:CMux::data_available: sabm_ack=2
I (22181) RX: 0x3fca5edc   f9 0b ef 13 0d 0a 51 43  52 44 59 0d 0a 4f f9     |......QCRDY..O.|
W (22181) CMUX: Restarting CMUX state machine (reason: 4)
I (22181) CMUX: Protocol recovered
I (22191) TX: 0x3fca7374   f9 05 ef 0b                                       |....|
I (22191) TX: 0x3fca759c   41 54 45 30 0d                                    |ATE0.|
I (22191) TX: 0x3fca7378   bb f9                                             |..|
I (22191) RX: 0x3fca5edc   f9 07 ef 0b 41 54 45 30  0d da f9                 |....ATE0...|
I (22191) RX: 0x3fca5edc   f9 07 ef 0d 0d 0a 4f 4b  0d 0a 3e f9              |......OK..>.|
I (22191) TX: 0x3fca72e4   f9 05 ef 3b                                       |...;|
I (22191) TX: 0x3fca8fd4   41 54 2b 43 47 44 43 4f  4e 54 3d 31 2c 22 49 50  |AT+CGDCONT=1,"IP|
I (22191) TX: 0x3fca8fe4   22 2c 22 69 6e 74 65 72  6e 65 74 22 0d           |","internet".|
I (22191) TX: 0x3fca72e8   9f f9                                             |..|
I (22251) RX: 0x3fca5edc   f9 07 ef 0d 0d 0a 4f 4b  0d 0a 3e f9              |......OK..>.|
I (22251) esp_modem_dce_module.hpp: set_mode: 2
I (22251) TX: 0x3fca7424   f9 05 ef 11                                       |....|
I (22251) TX: 0x3fca755c   41 54 44 2a 39 39 23 0d                           |ATD*99#.|
I (22251) TX: 0x3fca7428   4a f9                                             |J.|
I (22261) RX: 0x3fca5edc   f9 07 ef 17 0d 0a 43 4f  4e 4e 45 43 54 0d 0a cf  |......CONNECT...|
I (22261) RX: 0x3fca5eec   f9                                                |.|
I (22261) TX: 0x3fca1424   f9 05 ef 5d                                       |...]|
I (22261) TX: 0x3fca95e4   7e ff 7d 23 c0 21 7d 21  7d 21 7d 20 7d 34 7d 22  |~.}#.!}!}!} }4}"|
I (22261) TX: 0x3fca95f4   7d 26 7d 20 7d 20 7d 20  7d 20 7d 25 7d 26 79 85  |}&} } } } }%}&y.|
I (22261) TX: 0x3fca9604   d5 8f 7d 27 7d 22 7d 28  7d 22 7d 26 f2 7e        |..}'}"}(}"}&.~|
I (22261) TX: 0x3fca1428   33 f9                                             |3.|
I (22261) modem_console: OK
I (22271) RX: 0x3fca5edc   f9 07 ef 6b 7e ff 7d 23  c0 21 7d 21 7d 21 7d 20  |...k~.}#.!}!}!} |
I (22271) RX: 0x3fca5eec   7d 39 7d 22 7d 26 7d 20  7d 20 7d 20 7d 20 7d 23  |}9}"}&} } } } }#|
I (22271) RX: 0x3fca5efc   7d 25 c2 23 7d 25 7d 25  7d 26 46 fb 6b 8e 7d 27  |}%.#}%}%}&F.k.}'|
I (22271) RX: 0x3fca5f0c   7d 22 7d 28 7d 22 64 8d  7e 92 f9                 |}"}(}"d.~..|
I (22281) TX: 0x3fca1484   f9 05 ef 33                                       |...3|
I (22281) TX: 0x3fca9bf8   7e ff 7d 23 c0 21 7d 24  7d 21 7d 20 7d 29 7d 23  |~.}#.!}$}!} })}#|
I (22281) TX: 0x3fca9c08   7d 25 c2 23 7d 25 47 e1  7e                       |}%.#}%G.~|
I (22281) TX: 0x3fca1488   91 f9                                             |..|
I (22281) RX: 0x3fca5edc   f9 07 ef 59 ff 7d 23 c0  21 7d 22 7d 21 7d 20 7d  |...Y.}#.!}"}!} }|
I (22281) RX: 0x3fca5eec   34 7d 22 7d 26 7d 20 7d  20 7d 20 7d 20 7d 25 7d  |4}"}&} } } } }%}|
I (22281) RX: 0x3fca5efc   26 79 85 d5 8f 7d 27 7d  22 7d 28 7d 22 ed 9b 7e  |&y...}'}"}(}"..~|
I (22281) RX: 0x3fca5f0c   55 f9                                             |U.|
                                                                                                                                                                                                        I (22291) RX: 0x3fca5edc   f9 07 ef 5b ff 7d 23 c0  21 7d 21 7d 22 7d 20 7d  |...[.}#.!}!}"} }|
I (22291) RX: 0x3fca5eec   34 7d 22 7d 26 7d 20 7d  20 7d 20 7d 20 7d 25 7d  |4}"}&} } } } }%}|
I (22291) RX: 0x3fca5efc   26 46 fb 6b 8e 7d 27 7d  22 7d 28 7d 22 7d 2f 74  |&F.k.}'}"}(}"}/t|
I (22291) RX: 0x3fca5f0c   7e b6 f9                                          |~..|
I (22291) TX: 0x3fca1484   f9 05 ef 5d                                       |...]|
I (22291) TX: 0x3fca9bf8   7e ff 7d 23 c0 21 7d 22  7d 22 7d 20 7d 34 7d 22  |~.}#.!}"}"} }4}"|
I (22291) TX: 0x3fca9c08   7d 26 7d 20 7d 20 7d 20  7d 20 7d 25 7d 26 46 fb  |}&} } } } }%}&F.|
I (22291) TX: 0x3fca9c18   6b 8e 7d 27 7d 22 7d 28  7d 22 e4 7d 3d 7e        |k.}'}"}(}".}=~|
I (22291) TX: 0x3fca1488   33 f9                                             |3.|
I (22291) TX: 0x3fca13a4   f9 05 ef 49                                       |...I|
I (22291) TX: 0x3fca9bf8   7e ff 03 80 21 01 01 00  1c 02 06 00 2d 0f 01 03  |~...!.......-...|
I (22291) TX: 0x3fca9c08   06 00 00 00 00 81 06 00  00 00 00 83 06 00 00 00  |................|
I (22291) TX: 0x3fca9c18   00 55 15 7e                                       |.U.~|
I (22291) TX: 0x3fca13a8   28 f9                                             |(.|
esp> I (22301) RX: 0x3fca5edc   f9 07 ef 17 ff 03 80 21  01 01 00 04 00 b7 7e cf  |.......!......~.|
I (22301) RX: 0x3fca5eec   f9                                                |.|
I (22311) TX: 0x3fca1484   f9 05 ef 25                                       |...%|
I (22311) TX: 0x3fca9bf8   7e ff 03 80 21 03 01 00  0a 03 06 00 00 00 00 5d  |~...!..........]|
I (22311) TX: 0x3fca9c08   70 7e                                             |p~|
I (22311) TX: 0x3fca1488   69 f9                                             |i.|
I (22311) RX: 0x3fca5edc   f9 07 ef 23 ff 03 80 21  04 01 00 0a 02 06 00 2d  |...#...!.......-|
I (22311) RX: 0x3fca5eec   0f 01 86 de 7e ec f9                              |....~..|
I (22311) TX: 0x3fca1494   f9 05 ef 3d                                       |...=|
I (22311) TX: 0x3fca9bf8   7e ff 03 80 21 01 02 00  16 03 06 00 00 00 00 81  |~...!...........|
I (22311) TX: 0x3fca9c08   06 00 00 00 00 83 06 00  00 00 00 da 82 7e        |.............~|
I (22311) TX: 0x3fca1498   7b f9                                             |{.|
I (22311) RX: 0x3fca5edc   f9 07 ef 17 ff 03 80 21  01 02 00 04 64 58 7e cf  |.......!....dX~.|
I (22311) RX: 0x3fca5eec   f9                                                |.|
I (22311) TX: 0x3fca1484   f9 05 ef 1b                                       |....|
I (22311) TX: 0x3fca9bf8   7e ff 03 80 21 02 02 00  04 a9 7d 5d 7e           |~...!.....}]~|
I (22311) TX: 0x3fca1488   a7 f9                                             |..|
I (22321) RX: 0x3fca5edc   f9 07 ef 3b ff 03 80 21  03 02 00 16 03 06 64 70  |...;...!......dp|
I (22321) RX: 0x3fca5eec   1b 58 81 06 c2 97 e4 02  83 06 c2 97 e4 22 22 3c  |.X...........""<|
I (22321) RX: 0x3fca5efc   7e fe f9                                          |~..|
I (22321) TX: 0x3fca1494   f9 05 ef 3d                                       |...=|
I (22321) TX: 0x3fca9bf8   7e ff 03 80 21 01 03 00  16 03 06 64 70 1b 58 81  |~...!......dp.X.|
I (22321) TX: 0x3fca9c08   06 c2 97 e4 02 83 06 c2  97 e4 22 e5 51 7e        |..........".Q~|
I (22321) TX: 0x3fca1498   7b f9                                             |{.|
I (22331) RX: 0x3fca5edc   f9 07 ef 3b ff 03 80 21  02 03 00 16 03 06 64 70  |...;...!......dp|
I (22331) RX: 0x3fca5eec   1b 58 81 06 c2 97 e4 02  83 06 c2 97 e4 22 13 a2  |.X..........."..|
I (22331) RX: 0x3fca5efc   7e fe f9                                          |~..|
I (22331) esp-netif_lwip-ppp: Connected

@david-cermak
Copy link
Collaborator

@morgana2313 sorry for not responding timely, have you resolved this issue?

I was just about to look into it, as it seemed like we're almost there. Only looks like the device's sending the actual data before we initialize the CMUX completely. This change should fix the warnings:

--- a/components/esp_modem/src/esp_modem_cmux.cpp
+++ b/components/esp_modem/src/esp_modem_cmux.cpp
@@ -123,7 +123,12 @@ bool CMux::data_available(uint8_t *data, size_t len)
 {
     if (data && (type & FT_UIH) == FT_UIH && len > 0 && dlci > 0) { // valid payload on a virtual term
         int virtual_term = dlci - 1;
-        if (virtual_term < MAX_TERMINALS_NUM && read_cb[virtual_term]) {
+        if (virtual_term < MAX_TERMINALS_NUM) {
+            if (read_cb[virtual_term] == nullptr) {
+                // ignore all virtual terminal's data before
+                ESP_LOG_BUFFER_HEXDUMP("CMUX Rx before init", data, len, ESP_LOG_DEBUG);
+                return true;
+            }
             // Post partial data (or defragment to post on CMUX footer)
 #ifdef DEFRAGMENT_CMUX_PAYLOAD

@morgana2313
Copy link
Author

No Problem! I managed to detect the QCRDY message, but don't see how to avoid the warning.

This fix doesn't either:

esp> set_mode CMUX
I (5781) modem_console: Switching to CMUX name...
I (5781) esp_modem_dce_module.hpp: set_mode: 4
I (5781) TX: 0x3fca76fc   41 54 2b 43 4d 55 58 3d  30 0d                    |AT+CMUX=0.|
I (5781) RX: 0x3fca6000   41 54 2b 43 4d 55 58 3d  30 0d 0d 0a 4f 4b 0d 0a  |AT+CMUX=0...OK..|
I (5881) TX: 0x3fca76a0   f9 03 3f 01 1c f9                                 |..?...|
I (5881) RX: 0x3fca6000   f9 03 73 01 d7 f9                                 |..s...|
I (5891) TX: 0x3fca76a0   f9 07 3f 01 de f9                                 |..?...|
I (5891) RX: 0x3fca6000   f9 07 73 01 15 f9                                 |..s...|
I (5891) RX: 0x3fca6000   f9 07 73 01 15 f9                                 |..s...|
I (5891) RX: 0x3fca6000   f9 07 ef 13 0d 0a 51 43  52 44 59 0d 0a c8 f9     |......QCRDY....|
I (5891) DA: len:9 MAX_TERMINALS_NUM:2 read_cb[virtual_term=0]0x3fca8fd0
I (5891) DA: 0x3fca6004   0d 0a 51 43 52 44 59 0d  0a                       |..QCRDY..|
I (5891) QC: 0x3fca5b30   0d 0a 51 43 52 44 59 0d  0a                       |..QCRDY..|
I (5891) DA: Ignored QCRDY
W (5891) CMUX: Restarting CMUX state machine (reason: 4)
I (5891) CMUX: Protocol recovered
I (5901) TX: 0x3fca76a0   f9 0b 3f 01 59 f9                                 |..?.Y.|
I (5901) RX: 0x3fca6000   f9 0b 73 01 92 f9                                 |..s...|
I (5901) RX: 0x3fca6000   f9 0b 73 01 92 f9                                 |..s...|
I (5901) RX: 0x3fca6000   f9 0b ef 13 0d 0a 51 43  52 44 59 0d 0a 4f f9     |......QCRDY..O.|
I (5901) DA: len:9 MAX_TERMINALS_NUM:2 read_cb[virtual_term=1]0x3fca8fe0
I (5901) DA: 0x3fca6004   0d 0a 51 43 52 44 59 0d  0a                       |..QCRDY..|
I (5901) QC: 0x3fca5b30   0d 0a 51 43 52 44 59 0d  0a                       |..QCRDY..|
I (5901) DA: Ignored QCRDY
W (5901) CMUX: Restarting CMUX state machine (reason: 4)
I (5901) CMUX: Protocol recovered
I (5911) TX: 0x3fca74a4   f9 05 ef 0b                                       |....|
I (5911) TX: 0x3fca76cc   41 54 45 30 0d                                    |ATE0.|
I (5911) TX: 0x3fca74a8   bb f9                                             |..|
I (5911) RX: 0x3fca6000   f9 07 ef 0b 41 54 45 30  0d da f9                 |....ATE0...|
diff --git a/components/esp_modem/src/esp_modem_cmux.cpp b/components/esp_modem/src/esp_modem_cmux.cpp
index 9179101..39e824e 100644
--- a/components/esp_modem/src/esp_modem_cmux.cpp
+++ b/components/esp_modem/src/esp_modem_cmux.cpp
@@ -121,12 +121,29 @@ struct CMux::CMuxFrame {

 bool CMux::data_available(uint8_t *data, size_t len)
 {
     if (data && (type & FT_UIH) == FT_UIH && len > 0 && dlci > 0) { // valid payload on a virtual term
         int virtual_term = dlci - 1;
-        if (virtual_term < MAX_TERMINALS_NUM && read_cb[virtual_term]) {
+        // if (virtual_term < MAX_TERMINALS_NUM && read_cb[virtual_term]) {
+
+        ESP_LOGI("DA","len:%d MAX_TERMINALS_NUM:%d read_cb[virtual_term=%d]%p", len, MAX_TERMINALS_NUM, virtual_term, (void*) &read_cb[virtual_term]);
+        ESP_LOG_BUFFER_HEXDUMP("DA", data, len, ESP_LOG_INFO);
+
+        const char QCRDY[10] = "\r\nQCRDY\r\n";
+        ESP_LOG_BUFFER_HEXDUMP("QC", QCRDY, 9, ESP_LOG_INFO);
+        if ((len == 9) && (strncmp((char *) data, QCRDY, std::min((size_t) 9, len)) == 0)) {
+            ESP_LOGI("DA","Ignored QCRDY");
+            return false;
+        }
+
+        if (virtual_term < MAX_TERMINALS_NUM) {
+            if (read_cb[virtual_term] == nullptr) {
+                // ignore all virtual terminal's data before
+                ESP_LOG_BUFFER_HEXDUMP("CMUX Rx before init", data, len, ESP_LOG_DEBUG);
+                return true;
+            }
             // Post partial data (or defragment to post on CMUX footer)
 #ifdef DEFRAGMENT_CMUX_PAYLOAD
             if (payload_start == nullptr) {

I experience another problem; after a day or so using a CMUX connection the modem loses it's connection. I have some questions:

  1. How is CMUX supposed to handle this?
  2. How can I (automatically) reestablish (ATD*99#) the connection?
  3. I imagine the modem can drop CMUX mode and fall back to normal command mode. Does the esp_modem CMUX code detect this and also stop / restart CMUX?

I'm considering how to debug this pronlem to see what's going on...

@morgana2313 morgana2313 reopened this Nov 25, 2024
@david-cermak
Copy link
Collaborator

Need to return true here:

        ESP_LOG_BUFFER_HEXDUMP("QC", QCRDY, 9, ESP_LOG_INFO);
        if ((len == 9) && (strncmp((char *) data, QCRDY, std::min((size_t) 9, len)) == 0)) {
            ESP_LOGI("DA","Ignored QCRDY");
            return true;
        }

This is causing the warning IMO, but I don't understand why the patch posted here didn't work. Note that (void*) &read_cb[virtual_term] takes a pointer to the member variable, which is always true (as long as cmux handle is active), could you just cast it to boolean and log?

... %d",  read_cb[virtual_term] ? 1: 0);

I experience another problem; after a day or so using a CMUX connection the modem loses it's connection. I have some questions:

This works the same way as standard command and data mode, there's no auto retry. need to be performed on application layer with backoff/retry and checking connections. you can enable PPP keep alive and perhaps TCP keepalive or some means to periodically check connectivity. There're also two events, IP lost event from netif and connection drop from PPP.

I imagine the modem can drop CMUX mode and fall back to normal command mode. Does the esp_modem CMUX code detect this and also stop / restart CMUX?

This is device specific, but most devices drop the connection on CMUX exit. It's also possible to use CMUX manual modes and deal with modes on each virtual terminal separately.

@morgana2313
Copy link
Author

Ah, I was having a but of trouble understanding how to work with std::function.
But return true doesn't cause CMux to ignore the incoming data?

I removed my return after DA: Ignored QCRDY:

esp> set_mode CMUX
I (75911) modem_console: Switching to CMUX name...
I (75911) esp_modem_dce_module.hpp: set_mode: 4
I (75911) TX: 0x3fca76bc   41 54 2b 43 4d 55 58 3d  30 0d                    |AT+CMUX=0.|
I (75921) RX: 0x3fca5fc0   41 54 2b 43 4d 55 58 3d  30 0d 0d 0a 4f 4b 0d 0a  |AT+CMUX=0...OK..|
I (76021) TX: 0x3fca7660   f9 03 3f 01 1c f9                                 |..?...|
I (76021) RX: 0x3fca5fc0   f9 03 73 01 d7 f9                                 |..s...|
I (76031) TX: 0x3fca7660   f9 07 3f 01 de f9                                 |..?...|
I (76031) RX: 0x3fca5fc0   f9 07 73 01 15 f9                                 |..s...|
I (76031) RX: 0x3fca5fc0   f9 07 73 01 15 f9                                 |..s...|
I (76031) RX: 0x3fca5fc0   f9 07 ef 13 0d 0a 51 43  52 44 59 0d 0a c8 f9     |......QCRDY....|
I (76031) DA: len:9 MAX_TERMINALS_NUM:2 read_cb[virtual_term=0]:0
I (76031) DA: 0x3fca5fc4   0d 0a 51 43 52 44 59 0d  0a                       |..QCRDY..|
I (76031) DA: Ignored QCRDY
I (76031) DB: len:9 MAX_TERMINALS_NUM:2 read_cb[virtual_term=0]:0
I (76031) CMUX Rx before init: 0x3fca5fc4   0d 0a 51 43 52 44 59 0d  0a                       |..QCRDY..|
W (76031) CMUX: Restarting CMUX state machine (reason: 4)
I (76041) TX: 0x3fca7660   f9 0b 3f 01 59 f9                                 |..?.Y.|
I (76041) RX: 0x3fca5fc0   f9 0b 73 01 92 f9                                 |..s...|
I (76041) RX: 0x3fca5fc0   f9 0b 73 01 92 f9                                 |..s...|
I (76041) RX: 0x3fca5fc0   f9 0b ef 13 0d 0a 51 43  52 44 59 0d 0a 4f f9     |......QCRDY..O.|
I (76041) DA: len:9 MAX_TERMINALS_NUM:2 read_cb[virtual_term=1]:0
I (76041) DA: 0x3fca5fc4   0d 0a 51 43 52 44 59 0d  0a                       |..QCRDY..|
I (76041) DA: Ignored QCRDY
I (76041) DB: len:9 MAX_TERMINALS_NUM:2 read_cb[virtual_term=1]:0
I (76041) CMUX Rx before init: 0x3fca5fc4   0d 0a 51 43 52 44 59 0d  0a                       |..QCRDY..|
W (76041) CMUX: Restarting CMUX state machine (reason: 4)
I (76051) TX: 0x3fca7464   f9 05 ef 0b                                       |....|
I (76051) TX: 0x3fca768c   41 54 45 30 0d                                    |ATE0.|
I (76051) TX: 0x3fca7468   bb f9                                             |..|
I (76051) RX: 0x3fca5fc0   f9 07 ef 0b 41 54 45 30  0d da f9                 |....ATE0...|

@morgana2313
Copy link
Author

morgana2313 commented Nov 26, 2024

There're also two events, IP lost event from netif and connection drop from PPP.

Can I just drop the CMUX instance and create a new one? Or tickle the existing instance into restarting?
Can you give me a hint how this should work? I'll try to add it in a PR to the simple_cmux_client.

This is device specific, but most devices drop the connection on CMUX exit. It's also possible to use CMUX manual modes and deal with modes on each virtual terminal separately.

Shouldn't Cmux detect it's not receiving any sabm packets anymore and stop at some point? I see endless repetitions of Restarting CMUX state machine.

@david-cermak
Copy link
Collaborator

But return true doesn't cause CMux to ignore the incoming data?

It should, this:

W (76031) CMUX: Restarting CMUX state machine (reason: 4)

means protocol_mismatch_reason::UNEXPECTED_DATA, which is only set if data_available() callback returns false (by returning true, we silently ignore the mismatch)

The problem is that this needs to be ignored around the CMUX footer:

diff --git a/components/esp_modem/src/esp_modem_cmux.cpp b/components/esp_modem/src/esp_modem_cmux.cpp
index c47e13b9..1612b727 100644
--- a/components/esp_modem/src/esp_modem_cmux.cpp
+++ b/components/esp_modem/src/esp_modem_cmux.cpp
@@ -142,7 +142,12 @@ bool CMux::data_available(uint8_t *data, size_t len)
         sabm_ack = dlci;
     } else if (data == nullptr && dlci > 0) {
         int virtual_term = dlci - 1;
-        if (virtual_term < MAX_TERMINALS_NUM && read_cb[virtual_term]) {
+        if (virtual_term < MAX_TERMINALS_NUM) {
+            if (read_cb[virtual_term] == nullptr) {
+                // ignore all virtual terminal's data before
+                ESP_LOG_BUFFER_HEXDUMP("CMUX Rx before init (footer)", data, len, ESP_LOG_DEBUG);
+                return true;
+            }
 #ifdef DEFRAGMENT_CMUX_PAYLOAD
             read_cb[virtual_term](payload_start, total_payload_size);
 #endif

These two changes should remove the warnings.

Can I just drop the CMUX instance and create a new one? Or tickle the existing instance into restarting?
Can you give me a hint how this should work? I'll try to add it in a PR to the simple_cmux_client.

CMUX exit is already part of that example, does it work for you?

Shouldn't Cmux detect it's not receiving any sabm packets anymore and stop at some point? I see endless repetitions of Restarting CMUX state machine.

I would need to see the logs. Haven't seen a device that sends SABM's periodically, but that's still possible I think. I'm also using SAMB frames to detect modes, maybe they could be used to implement some keepalive mechanism?

@morgana2313
Copy link
Author

Yes, that did it; no more Restarting CMUX state machine messages.
But strangely the CMUX Rx before init (footer) code isn't reached, so the difference in the if condition is the reason?

esp> set_mode CMUX
I (11937) modem_console: Switching to CMUX name...
I (11937) esp_modem_dce_module.hpp: set_mode: 4
I (11937) TX: 0x3fca6f8c   41 54 2b 43 4d 55 58 3d  30 0d                    |AT+CMUX=0.|
I (11947) RX: 0x3fca5890   41 54 2b 43 4d 55 58 3d  30 0d 0d 0a 4f 4b 0d 0a  |AT+CMUX=0...OK..|
I (12047) DTE::set_mod: current_mode: 0 new_mode: 4
I (12047) TX: 0x3fca6f20   f9 03 3f 01 1c f9                                 |..?...|
I (12047) RX: 0x3fca5890   f9 03 73 01 d7 f9                                 |..s...|
I (12057) TX: 0x3fca6f20   f9 07 3f 01 de f9                                 |..?...|
I (12057) RX: 0x3fca5890   f9 07 73 01 15 f9                                 |..s...|
I (12057) RX: 0x3fca5890   f9 07 73 01 15 f9                                 |..s...|
I (12057) RX: 0x3fca5890   f9 07 ef 13 0d 0a 51 43  52 44 59 0d 0a c8 f9     |......QCRDY....|
I (12057) CMUX Rx before init: 0x3fca5894   0d 0a 51 43 52 44 59 0d  0a                       |..QCRDY..|
I (12067) TX: 0x3fca6f20   f9 0b 3f 01 59 f9                                 |..?.Y.|
I (12067) RX: 0x3fca5890   f9 0b 73 01 92 f9                                 |..s...|
I (12067) RX: 0x3fca5890   f9 0b 73 01 92 f9                                 |..s...|
I (12067) RX: 0x3fca5890   f9 0b ef 13 0d 0a 51 43  52 44 59 0d 0a 4f f9     |......QCRDY..O.|
I (12067) CMUX Rx before init: 0x3fca5894   0d 0a 51 43 52 44 59 0d  0a                       |..QCRDY..|
I (12077) TX: 0x3fca6d34   f9 05 ef 0b                                       |....|
I (12077) TX: 0x3fca6f5c   41 54 45 30 0d                                    |ATE0.|
I (12077) TX: 0x3fca6d38   bb f9                                             |..|
I (12077) RX: 0x3fca5890   f9 07 ef 0b 41 54 45 30  0d da f9                 |....ATE0...|
I (12077) RX: 0x3fca5890   f9 07 ef 0d 0d 0a 4f 4b  0d 0a 3e f9              |......OK..>.|
diff --git a/components/esp_modem/src/esp_modem_cmux.cpp b/components/esp_modem/src/esp_modem_cmux.cpp
index 9179101..201b987 100644
--- a/components/esp_modem/src/esp_modem_cmux.cpp
+++ b/components/esp_modem/src/esp_modem_cmux.cpp
@@ -121,12 +121,17 @@ struct CMux::CMuxFrame {

 bool CMux::data_available(uint8_t *data, size_t len)
 {

     if (data && (type & FT_UIH) == FT_UIH && len > 0 && dlci > 0) { // valid payload on a virtual term
         int virtual_term = dlci - 1;
-        if (virtual_term < MAX_TERMINALS_NUM && read_cb[virtual_term]) {
+
+        if (virtual_term < MAX_TERMINALS_NUM) {
+            if (read_cb[virtual_term] == nullptr) {
+                // ignore all virtual terminal's data before
+                ESP_LOG_BUFFER_HEXDUMP("CMUX Rx before init", data, len, ESP_LOG_INFO);
+                return true;
+            }
             // Post partial data (or defragment to post on CMUX footer)
 #ifdef DEFRAGMENT_CMUX_PAYLOAD
             if (payload_start == nullptr) {
@@ -146,15 +151,25 @@ bool CMux::data_available(uint8_t *data, size_t len)
     } else if (data == nullptr && dlci > 0) {
         int virtual_term = dlci - 1;
+        #ifdef skip
         if (virtual_term < MAX_TERMINALS_NUM && read_cb[virtual_term]) {
+        #else
+        if (virtual_term < MAX_TERMINALS_NUM) {
+            if (read_cb[virtual_term] == nullptr) {
+                // ignore all virtual terminal's data before
+                ESP_LOG_BUFFER_HEXDUMP("CMUX Rx before init (footer)", data, len, ESP_LOG_INFO);
+                return true;
+            }
+        #endif
 #ifdef DEFRAGMENT_CMUX_PAYLOAD
             read_cb[virtual_term](payload_start, total_payload_size);
 #endif

CMUX exit is already part of that example, does it work for you?

You mean the part with CONFIG_EXAMPLE_CLOSE_CMUX_AT_END?
Perhaps that's the base, but I assume it should be triggered by IP lost event from netif or connection drop from PPP?

I've setup a wat to log the problem with the lost connection. Now I have to wait until it occurs.

@david-cermak
Copy link
Collaborator

But strangely the CMUX Rx before init (footer) code isn't reached, so the difference in the if condition is the reason?

the reason is that on the "footer" side we log data which is null -- sorry, just blindly copied the previous condition. here we should do something like:

        if (virtual_term < MAX_TERMINALS_NUM) {
            if (read_cb[virtual_term] == nullptr) {
                // ignore all virtual terminal's data before
                ESP_LOGD("CMUX Rx before init (footer)", "payload of this frame has been ignored");
                return true;
            }

Perhaps that's the base, but I assume it should be triggered by IP lost event from netif or connection drop from PPP?

agree, just referencing another example (as this is more like a system level, it doens't belong to esp-modem) https://github.com/espressif/esp-protocols/blob/master/examples/esp_netif/multiple_netifs/main/ppp_connect_esp_modem.c

I've setup a wat to log the problem with the lost connection. Now I have to wait until it occurs.

I usually disconnect the antenna to simulate this event.

@morgana2313
Copy link
Author

Ah, of course, your're absolutely right:

I (93452) esp_modem_dce_module.hpp: set_mode: 4
I (93462) TX: 0x3fca6f7c   41 54 2b 43 4d 55 58 3d  30 0d                    |AT+CMUX=0.|
I (93462) RX: 0x3fca588c   41 54 2b 43 4d 55 58 3d  30 0d 0d 0a 4f 4b 0d 0a  |AT+CMUX=0...OK..|
I (93562) DTE::set_mod: current_mode: 1 new_mode: 4
I (93562) TX: 0x3fca6f10   f9 03 3f 01 1c f9                                 |..?...|
I (93562) RX: 0x3fca588c   f9 03 73 01 d7 f9                                 |..s...|
I (93572) TX: 0x3fca6f10   f9 07 3f 01 de f9                                 |..?...|
I (93572) RX: 0x3fca588c   f9 07 73 01 15 f9                                 |..s...|
I (93572) RX: 0x3fca588c   f9 07 73 01 15 f9                                 |..s...|
I (93572) RX: 0x3fca588c   f9 07 ef 13 0d 0a 51 43  52 44 59 0d 0a c8 f9     |......QCRDY....|
I (93572) CMUX Rx before init: 0x3fca5890   0d 0a 51 43 52 44 59 0d  0a                       |..QCRDY..|
I (93582) TX: 0x3fca6f10   f9 0b 3f 01 59 f9                                 |..?.Y.|
I (93582) RX: 0x3fca588c   f9 0b 73 01 92 f9                                 |..s...|
I (93582) RX: 0x3fca588c   f9 0b 73 01 92 f9                                 |..s...|
I (93582) RX: 0x3fca588c   f9 0b ef 13 0d 0a 51 43  52 44 59 0d 0a 4f f9     |......QCRDY..O.|
I (93582) CMUX Rx before init: 0x3fca5890   0d 0a 51 43 52 44 59 0d  0a                       |..QCRDY..|
I (93592) TX: 0x3fca6d24   f9 05 ef 0b                                       |....|
I (93592) TX: 0x3fca6f4c   41 54 45 30 0d                                    |ATE0.|
I (93592) TX: 0x3fca6d28   bb f9                                             |..|
I (93592) RX: 0x3fca588c   f9 07 ef 0d 0d 0a 4f 4b  0d 0a 3e f9              |......OK..>.|

@morgana2313
Copy link
Author

morgana2313 commented Nov 27, 2024

What categoric reasons are there for a non-functioning CMUX ip uplink?

  1. set_mode(CMUX) fails (ppp_connect_esp_modem.c)
  2. IP_EVENT_PPP_LOST_IP
  3. modem dropped out of CMUX mode. (detected by CMUX/sabm keepalive check?)

I think in all cases a way to re-establish the IP link is:

  1. Increasing delay (backoff).
  2. Make sure the dte and dce (modem) are both in command mode; dte->exit_cmux() dce->set_command_mode()
  3. set_mode CMUX to switch both to CMUX mode.

Do you agree?

@morgana2313
Copy link
Author

Here is the log of a moment when the ip uplink stopped functioning; a PPP Disconnect happend:

I (72199882) icmp_echo: 64 bytes from 8.8.8.8 icmp_seq=7220 ttl=116 time=68 ms
I (72202842) TX: 0x3fca0e84   f9 05 ef 21                                       |...!|
I (72202842) TX: 0x3fcaa4b4   7e ff 03 c0 21 09 02 00  08 50 ed 76 89 15 c7 7e  |~...!....P.v...~|
I (72202842) TX: 0x3fca0e88   6e f9                                             |n.|
I (72202842) RX: 0x3fca588c   f9 07 ef 21 7e ff 03 c0  21 0a 02 00 08 70 f1 53  |...!~...!....p.S|
I (72202842) RX: 0x3fca589c   70 65 d5 7e 0f f9                                 |pe.~..|
I (72205842) TX: 0x3fca0e84   f9 05 ef 21                                       |...!|
I (72205842) TX: 0x3fcaa4b4   7e ff 03 c0 21 09 03 00  08 50 ed 76 89 c0 58 7e  |~...!....P.v..X~|
I (72205842) TX: 0x3fca0e88   6e f9                                             |n.|
I (72205842) RX: 0x3fca588c   f9 07 ef 21 7e ff 03 c0  21 0a 03 00 08 70 f1 53  |...!~...!....p.S|
I (72205842) RX: 0x3fca589c   70 b0 4a 7e 0f f9                                 |p.J~..|
I (72208842) TX: 0x3fca0e84   f9 05 ef 21                                       |...!|
I (72208842) TX: 0x3fcaa4b4   7e ff 03 c0 21 09 04 00  08 50 ed 76 89 d8 9f 7e  |~...!....P.v...~|
I (72208842) TX: 0x3fca0e88   6e f9                                             |n.|
I (72208842) RX: 0x3fca588c   f9 07 ef 21 7e ff 03 c0  21 0a 04 00 08 70 f1 53  |...!~...!....p.S|
I (72208842) RX: 0x3fca589c   70 a8 8d 7e 0f f9                                 |p..~..|
I (72209812) TX: 0x3fca0df4   f9 05 ef c7                                       |....|
I (72209812) TX: 0x3fca9eb4   7e 21 45 00 00 5c 1c 34  00 00 40 01 2e 93 0a 44  |~!E..\[email protected]|
I (72209812) TX: 0x3fca9ec4   15 87 08 08 08 08 08 00  02 1d b4 9a 35 1c 41 42  |............5.AB|
I (72209812) TX: 0x3fca9ed4   43 44 45 46 47 48 49 4a  4b 4c 4d 4e 4f 50 51 52  |CDEFGHIJKLMNOPQR|
I (72209812) TX: 0x3fca9ee4   53 54 55 56 57 58 59 5a  5b 5c 5d 5e 5f 60 61 62  |STUVWXYZ[\]^_`ab|
I (72209812) TX: 0x3fca9ef4   63 64 65 66 67 68 69 6a  6b 6c 6d 6e 6f 70 71 72  |cdefghijklmnopqr|
I (72209812) TX: 0x3fca9f04   73 74 75 76 77 78 79 7a  7b 7c 7d 5d 7d 5e 7f 80  |stuvwxyz{|}]}^..|
I (72209812) TX: 0x3fca9f14   16 41 7e                                          |.A~|
I (72209812) TX: 0x3fca0df8   22 f9                                             |".|
I (72209952) RX: 0x3fca588c   f9 07 ef 3b 7e ff 7d 23  c0 21 7d 25 7d 23 7d 20  |...;~.}#.!}%}#} |
I (72209952) RX: 0x3fca589c   7d 30 55 73 65 72 20 72  65 71 75 65 73 74 79 7b  |}0User requesty{|
I (72209952) RX: 0x3fca58ac   7e fe f9                                          |~..|
I (72209952) TX: 0x3fca0e44   f9 05 ef 23                                       |...#|
I (72209952) TX: 0x3fcaaab4   7e ff 7d 23 c0 21 7d 26  7d 23 7d 20 7d 24 48 57  |~.}#.!}&}#} }$HW|
I (72209952) TX: 0x3fcaaac4   7e                                                |~|
I (72209952) TX: 0x3fca0e48   8d f9                                             |..|
I (72209962) RX: 0x3fca588c   f9 07 ef 2f 0d 0a 2b 50  50 50 44 3a 20 44 49 53  |.../..+PPPD: DIS|
I (72209962) RX: 0x3fca589c   43 4f 4e 4e 45 43 54 45  44 0d 0a e5 f9           |CONNECTED....|
I (72209962) RX: 0x3fca588c   f9 07 ef 1d 0d 0a 4e 4f  20 43 41 52 52 49 45 52  |......NO CARRIER|
I (72209962) RX: 0x3fca589c   0d 0a 22 f9                                       |..".|
I (72209972) RX: 0x3fca588c   f9 0b ef 2f 0d 0a 2b 50  50 50 44 3a 20 44 49 53  |.../..+PPPD: DIS|
I (72209972) RX: 0x3fca589c   43 4f 4e 4e 45 43 54 45  44 0d 0a 62 f9           |CONNECTED..b.|
I (72210022) RX: 0x3fca588c   f9 0b ef 1d 0d 0a 4e 4f  20 43 41 52 52 49 45 52  |......NO CARRIER|
I (72210022) RX: 0x3fca589c   0d 0a a5 f9                                       |....|
I (72210812) icmp_echo: From 8.8.8.8 icmp_seq=7221 timeout
I (72215952) esp-netif_lwip-ppp: Connection lost
E (72219812) ping_sock: send error=0
I (72220812) icmp_echo: From 8.8.8.8 icmp_seq=7222 timeout
E (72229812) ping_sock: send error=0
I (72230812) icmp_echo: From 8.8.8.8 icmp_seq=7223 timeout

@david-cermak
Copy link
Collaborator

What categoric reasons are there for a non-functioning CMUX ip uplink?

I wouldn't say non-functioning CMUX, rather non-functioning PPP, as it's the PPP session that would get dropped, CMUX just creates virtual terminals. (not important if the session is closed on virtual or a real physical terminal).

modem dropped out of CMUX mode. (detected by CMUX/sabm keepalive check?)

I'd rather use PPP keepalive (LCP timeouts) here.

But I do agree overall with potential reasons and actions you mentioned above.

I (72210022) RX: 0x3fca588c   f9 0b ef 1d 0d 0a 4e 4f  20 43 41 52 52 49 45 52  |......NO CARRIER|
I (72210022) RX: 0x3fca589c   0d 0a a5 f9                                       |....|
I (72210812) icmp_echo: From 8.8.8.8 icmp_seq=7221 timeout
I (72215952) esp-netif_lwip-ppp: Connection lost
```
If I read correctly you're getting the event after ~5 seconds, is it fast enough? Since I can also see the PPP session is closed cleanly by the modem, so we should be able to detect it sooner. You can try to enable the PPP transition events?

@morgana2313
Copy link
Author

morgana2313 commented Dec 4, 2024

I'd rather use PPP keepalive (LCP timeouts) here.

I enabled these:

CONFIG_LWIP_ENABLE_LCP_ECHO=y
CONFIG_LWIP_LCP_ECHOINTERVAL=3
CONFIG_LWIP_LCP_MAXECHOFAILS=3
LWIP_PPP_NOTIFY_PHASE_SUPPORT=y

You can try to enable the PPP transition events?

Like CONFIG_PPP_NOTIFY_PHASE_SUPPORT=y and NETIF_PPP_STATUS event handler like in pppos_client?

I (115875) icmp: 64 bytes from 8.8.8.8 icmp_seq=12 ttl=57 time=76 ms
I (125895) sn_modem: PPP state event (265) Phase: Network
I (125895) sn_modem: PPP state event (262) Phase: Establish
E (125895) transport_base: poll_read select error 113, errno = Software caused connection abort, fd = 55
I (126805) icmp: From 8.8.8.8 icmp_seq=13 timeout
I (131895) sn_modem: PPP state event (268) Phase: Disconnect
I (131895) sn_modem: PPP state event (256) Phase: Dead
I (131895) esp-netif_lwip-ppp: Connection lost
I (131895) PPP_DEF: disconnected ip: 0.0.0.0
I (132895) esp-netif_lwip-ppp: User interrupt
I (132895) sn_modem: PPP state event (5) User interrupt
I (132895) esp_modem_netif: PPP state changed event 5
I (132895) DTE::set_mode: current_mode: 4 new_mode: 1
E (135805) ping_sock: send error=0
I (136805) icmp: From 8.8.8.8 icmp_seq=14 timeout

@morgana2313
Copy link
Author

morgana2313 commented Dec 5, 2024

AT+COPS=2 followed by AT+COPS=0 also disrupts the ppp link.

I think I got a functioning ppp watchdog with minimal but adequate actions. In pseudo code:

static void on_ppp_changed(void *arg, esp_event_base_t event_base, int32_t event_id, void *event_data){
    last_ppp_status = event_id;
}

#define WATCHDOG_TRY_INTERVAL 60 * NSEC_PER_SEC
#define WATCHDOG_MODEM_OK_TIMEOUT 2 * WD_INTERVAL + (5 * NSEC_PER_SEC)

cmux_task {
    esp_event_handler_register(NETIF_PPP_STATUS, ESP_EVENT_ANY_ID, &on_ppp_changed, NULL);
    reset_hq_init_cmux(); // simple_cmux_exanple
    int32_t prev_ppp_status = last_ppp_status;

    while(true){
        if (dce->get_signal_quality(rssi, ber) == command_result::OK){
        } else {
            last_modem_ok_nsec = uptime_nsec();
            if (rssi < 99){
                // connected to network.
                int32_t ppp_status = last_ppp_status; 
                if ((ppp_status != NETIF_PPP_PHASE_RUNNING) && (ppp_status == prev_ppp_status)){
                    ESP_LOGE(TAG, "PPP not OK; restart CMUX");
                    set_mode(COMMAND_MODE);
                    set_mode(CMUX_MODE);
                } else 
                { // test (http) connection.
                    elapsed_nsec = now_nsec - last_watchdog_try_fetch_nsec;
                    if (elapsed_nsec > WATCHDOG_TRY_INTERVAL) 
                        fetch_watchdog_url(); // updates last_watchdog_try_fetch_nsec 
                }
                prev_ppp_status =  ppp_status;
            } else ESP_LOGI(TAG,"Waiting for network signal.");
        } else 
        { // no communication with modem => modem dropped out of cmux mode?
            elapsed_nsec = now_nsec - last_modem_ok_nsec;
            ESP_LOGI(TAG,"Modem not responding: %.1f", elapsed_nsec / 1e9);
            if (elapsed_nsec > WATCHDOG_MODEM_OK_TIMEOUT) {
                ESP_LOGE(TAG,"WATCHDOG_MODEM_OK_TIMEOUT => reset_init_cmux");
                vTaskDelay(pdMS_TO_TICKS(1 * MSEC_PER_SEC));
                reset_init_cmux(); // includes mode => cmd => cmux
                last_modem_ok_nsec = now_nsec;
            }
        }

        elapsed_nsec = now_nsec - last_watchdog_fetch_ok_nsec;
        #define WATCHDOG_FETCH_TIMEOUT 600 * NSEC_PER_SEC
        if (elapsed_nsec > WATCHDOG_FETCH_TIMEOUT) {
            ESP_LOGE(TAG,"WATCHDOG_FETCH_TIMEOUT => esp_restart");
            vTaskDelay(pdMS_TO_TICKS(1 * MSEC_PER_SEC));
            esp_restart();
        }
        vTaskDelay(pdMS_TO_TICKS(WD_INTERVAL * MSEC_PER_SEC));
    }
}

@david-cermak
Copy link
Collaborator

I think I got a functioning ppp watchdog with minimal but adequate actions. In pseudo code:

Nice, thanks for sharing!

Do you think you can make it a real example (with the real actual code) and post a PR? I'll have to test it with various devices so would take some time to accept, but would be really helpful?

@morgana2313
Copy link
Author

I see two reasons for the no communication with modem state: the modem switching to a different baudrate or dropping cmux. Both may be caused by a reset to the modem. Having established there is no communication there is no point in waiting for the 10s timeout on asking the modem to stop the cmux mode.

How can I tell CMUX to just stop without informing the modem? Or set the timeout lower?

david-cermak added a commit to david-cermak/esp-protocols that referenced this issue Dec 10, 2024
1.3.0
Features
- Add mode detection to the example (18f196f)
- Support for pausing network in C-API (1db83cd)
- Add support for pausing netif (247f168, espressif#699)
Bug Fixes
- Minor cleanup of pppos example (5e92990)
- Fix PPP mode detection to accept LCP/conf (c989c6a)
- Refine mode switch data->command (8b6ea33, espressif#692)
- Detect serial ports properly (0cb59ff)
- Fix CMUX enter to ignore URC before transition (1284f66, espressif#669)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants