Unable to get network interface while using CMUX mode (IDFGH-8297) #140

RaD · 2022-09-13T14:40:59Z

[1/2] espressif/esp_modem (0.1.21)
[2/2] idf (4.4.1)

For the code:

    {
        int rssi, ber;
        err = esp_modem_get_signal_quality(dce, &rssi, &ber);
        if (err != ESP_OK) {
            ESP_LOGI(TAGI, "esp_modem_get_signal_quality failed with %d", err);
        }
        ESP_LOGI(TAGI, "Signal quality: rssi=%d, ber=%d", rssi, ber);
    }
    {
        int volt, bcs, bcl;
        err = esp_modem_get_battery_status(dce, &volt, &bcs, &bcl);
        if (err != ESP_OK) {
            ESP_LOGI(TAGI, "esp_modem_get_battery_status failed with %d", err);
        }
        ESP_LOGI(TAGI, "Battery status: volt=%d, bcs=%d, bcl=%d", volt, bcs, bcl);
    }

    // err = esp_modem_set_mode(dce, ESP_MODEM_MODE_DATA);
    // if (err != ESP_OK) {
    //     ESP_LOGE(TAGI, "esp_modem_set_mode(ESP_MODEM_MODE_DATA) failed with %d", err);
    //     return;
    // }
    err = esp_modem_set_mode(dce, ESP_MODEM_MODE_CMUX);
    if (err != ESP_OK) {
        ESP_LOGE(TAGI, "esp_modem_set_mode(ESP_MODEM_MODE_CMUX) failed with %d", err);
        return;
    }

I got:

I (21693) INET: Initializing esp_modem for the SIM800 module...
I (21733) INET: Operator[3584]: MTS
I (21743) INET: Signal quality: rssi=18, ber=0
I (21743) INET: Battery status: volt=4070, bcs=0, bcl=83
D (21753) command_lib: generic_command command AT+CMUX=0

D (21753) command_lib: Response:
OK


D (21853) CMUX: Payload frame: dlci:00 type:73 payload:0 available:2
D (21863) CMUX: Payload frame: dlci:01 type:73 payload:0 available:12
D (21863) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
E (22883) INET: esp_modem_set_mode(ESP_MODEM_MODE_CMUX) failed with -1
D (22883) INET: Wait for IP settings...

If I uncomment the DATA mode block and comment CMUX block, then I can use network. But I need CMUX mode, huh...

The text was updated successfully, but these errors were encountered:

david-cermak · 2022-09-14T12:00:31Z

@RaD Could you please share the verbose logs? it should print the entire CMUX payload, so I can see what's wrong. It looks like the problem in CMUX protocol rather than anything else if the DATA mode work correctly.

I (21693) INET: Initializing esp_modem for the SIM800 module...

Are you really using SIM800 or did you only setup the component to use this config?

RaD · 2022-09-14T18:01:05Z

@david-cermak , I use SIM800L on Xinyuan LilyGo-T-Call-SIM800 board.

Here is a verbose output:

V (21336) command_lib: get_signal_quality
V (21336) command_lib: generic_get_string
} (21346) command_lib: Token: {

V (21346) command_lib: Token: {+CSQ: 21,0}

} (21346) command_lib: Token: {

V (21356) command_lib: Token: {OK}

I (21356) INET: Signal quality: rssi=21, ber=0
V (21356) command_lib: get_battery_status
V (21366) command_lib: generic_get_string
} (21376) command_lib: Token: {

V (21376) command_lib: Token: {+CBC: 0,84,4076}

} (21376) command_lib: Token: {

V (21376) command_lib: Token: {OK}

I (21386) INET: Battery status: volt=4076, bcs=0, bcl=84
V (21386) command_lib: set_cmux
V (21396) command_lib: generic_command_common
V (21396) command_lib: generic_command
D (21406) command_lib: generic_command command AT+CMUX=0

D (21406) command_lib: Response:
OK


V (21516) CMUX Received: 0x3ffbc584   f9 03 73 01 d7 f9                                 |..s...|
D (21516) CMUX: Payload frame: dlci:00 type:73 payload:0 available:2
V (21526) CMUX Received: 0x3ffbc584   f9 07 73 01 15 f9 f9 01  ef 09 e3 05 07 0d 9a f9  |..s.............|
D (21526) CMUX: Payload frame: dlci:01 type:73 payload:0 available:12
D (21536) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
E (22546) INET: esp_modem_set_mode(ESP_MODEM_MODE_CMUX) failed with -1
D (22546) INET: Wait for IP settings...

RaD · 2022-09-14T19:21:16Z

Maybe this would helpful:

I (21246) INET: ATI: SIM800 R14.18
I (21456) INET: CMUX=?: +CMUX: (0),(0),(1-6),(16-1510),(1-255),(0-100),(2-255),(1-255),
I (21496) INET: CMUX?: +CMUX: 0,0,5,127,10,3,30,10,2

It fails here: https://github.com/espressif/esp-protocols/blob/master/components/esp_modem/src/esp_modem_cmux.cpp#L385

RaD · 2022-09-15T10:50:13Z

V (21628) CMUX Received: 0x3ffbc584   f9 03 73 01 d7 f9                                 |..s...|
D (21628) CMUX: Payload frame: dlci:00 type:73 payload:0 available:2
W (21628) CMUX DATA AVAILABLE: type=73 len=0, dlci=0
D (21638) CMUX DATA AVAILABLE: notify the initial SABM command
V (21648) CMUX Received: 0x3ffbc584   f9 07 73 01 15 f9 f9 01  ef 09 e3 05 07 0d 9a f9  |..s.............|
D (21648) CMUX: Payload frame: dlci:01 type:73 payload:0 available:12
W (21658) CMUX DATA AVAILABLE: type=73 len=0, dlci=1
D (21668) CMUX DATA AVAILABLE: notify the initial SABM command
D (21668) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
V (21678) CMUX DATA AVAILABLE: 0x3ffbc58e   e3 05 07 0d                                       |....|
W (21688) CMUX DATA AVAILABLE: type=ef len=4, dlci=0
D (21688) CMUX DATA AVAILABLE: notify the internal DISC command
W (21698) CMUX DATA AVAILABLE: type=ef len=0, dlci=0
D (21698) CMUX DATA AVAILABLE: no data
E (22708) INET: esp_modem_set_mode(ESP_MODEM_MODE_CMUX) failed with -1

david-cermak · 2022-09-15T11:22:19Z

@RaD Thanks so much for sharing the debug logs!
I can see that the device acknowledges the control SABM as well as the SABM of the first virtual terminal, but refuses opening the second virtual terminal by sending DISC onto the control terminal.
The reason is probably that your device requires sending Modem Status Command (MSC) immediately after opening a virtual terminal. This is what I found in SIM800 Series_Multiplexer_Application Note_V1.01:

MSC shall be sent prior to any user data after a creation of a DLC

I'll try to add the MSC command to see if it helps and won't cause trouble for other devices.

david-cermak · 2022-09-15T12:00:01Z

Added the MSC frame to the initial sequence in
WIP-esp_modem-CMUX-Add-MSC-just-after-SABM-for-SIM80.patch.txt

Could you please check if this helps with the mode switching for your device? If so, I'd add some logic around it and post a PR.

RaD · 2022-09-15T13:40:22Z

V (13128) command_lib: set_cmux
V (13128) command_lib: generic_command_common
V (13138) command_lib: generic_command
D (13138) command_lib: generic_command command AT+CMUX=0

D (13148) command_lib: Response:
OK


V (13248) CMUX Received: 0x3ffbc584   f9 03 73 01 d7 f9                                 |..s...|
D (13248) CMUX: Payload frame: dlci:00 type:73 payload:0 available:2
V (13258) CMUX Received: 0x3ffbc584   f9 07 73 01 15 f9 f9 01  ef 09 e3 05 07 0d 9a f9  |..s.............|
D (13258) CMUX: Payload frame: dlci:01 type:73 payload:0 available:12
D (13268) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
V (13428) CMUX Received: 0x3ffbc584   f9 05 ef 4f 0d 0a 2a 50  53 55 54 54 5a 3a 20 32  |...O..*PSUTTZ: 2|
V (13428) CMUX Received: 0x3ffbc594   30 32 32 2c 39 2c 31 35  2c 31 33 2c 33 38 2c 34  |022,9,15,13,38,4|
V (13428) CMUX Received: 0x3ffbc5a4   35 2c 22 2b 31 32 22 2c  30 0d 0a cc f9 f9 05 ef  |5,"+12",0.......|
V (13438) CMUX Received: 0x3ffbc5b4   15 0d 0a 44 53 54 3a 20  30 0d 0a 4d f9 f9 05 ef  |...DST: 0..M....|
D (13448) CMUX: Payload frame: dlci:01 type:ef payload:39 available:60
D (13458) CMUX: Payload frame: dlci:01 type:ef payload:10 available:15
V (13468) CMUX Received: 0x3ffbc584   5f 0d 0a 2b 43 49 45 56  3a 20 31 30 2c 22 32 35  |_..+CIEV: 10,"25|
V (13478) CMUX Received: 0x3ffbc594   30 30 31 22 2c 22 4d 54  53 20 52 55 53 22 2c 22  |001","MTS RUS","|
V (13488) CMUX Received: 0x3ffbc5a4   4d 54 53 20 52 55 53 22  2c 20 30 2c 20 30 0d 0a  |MTS RUS", 0, 0..|
V (13498) CMUX Received: 0x3ffbc5b4   d0 f9                                             |..|
D (13498) CMUX: Payload frame: dlci:01 type:ef payload:47 available:49
E (14368) INET: esp_modem_set_mode(ESP_MODEM_MODE_CMUX) failed with -1

RaD · 2022-09-15T13:55:36Z

Can you create a branch with fixes that I need to check, it is more convinient, than patch. I just don't remember how to apply them and I have some ESP_LOG* in the sources of modem.

After applying your patch:

V (14228) command_lib: set_cmux
V (14228) command_lib: generic_command_common
V (14238) command_lib: generic_command
D (14238) command_lib: generic_command command AT+CMUX=0

D (14248) command_lib: Response:
OK


I (14348) cmux: SABM 0
V (14348) CMUX Received: 0x3ffbc584   f9 03 73 01 d7 f9                                 |..s...|
D (14348) CMUX: Payload frame: dlci:00 type:73 payload:0 available:2
I (14358) cmux: MSC 0
V (14358) CMUX Received: 0x3ffbc584   f9 01 ef 09 e1 05 03 0d  9a f9                    |..........|
D (14368) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
I (14458) cmux: SABM 1
V (14458) CMUX Received: 0x3ffbc584   f9 07 73 01 15 f9 f9 01  ef 09 e3 05 07 0d 9a f9  |..s.............|
D (14458) CMUX: Payload frame: dlci:01 type:73 payload:0 available:12
D (14468) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
E (15478) INET: esp_modem_set_mode(ESP_MODEM_MODE_CMUX) failed with -1

david-cermak · 2022-09-15T14:23:43Z

Can you create a branch with fixes...

created #142

Could you please give it one more try? Saw that I've sent the MSC's also for the control term, which we shouldn't have...

RaD · 2022-09-15T14:34:58Z

I do all until success, no problem )

RaD · 2022-09-15T14:42:20Z

I (19258) cmux: SABM 0
V (19258) CMUX Received: 0x3ffbc584   f9 03 73 01 d7 f9                                 |..s...|
D (19258) CMUX: Payload frame: dlci:00 type:73 payload:0 available:2
I (19368) cmux: SABM 1
V (19368) CMUX Received: 0x3ffbc584   f9 07 73 01 15 f9 f9 01  ef 09 e3 05 07 0d 9a f9  |..s.............|
D (19368) CMUX: Payload frame: dlci:01 type:73 payload:0 available:12
D (19378) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
E (20388) INET: esp_modem_set_mode(ESP_MODEM_MODE_CMUX) failed with -1

RaD · 2022-09-15T18:08:21Z

I have logged out SABM transmit data:

I (19788) cmux: SABM 0
V (19788) CMUX SABM: 0x3ffb1370   f9 03 3f 01 1c f9                                 |..?...|
V (19788) CMUX Received: 0x3ffbc584   f9 03 73 01 d7 f9                                 |..s...|
D (19788) CMUX: Payload frame: dlci:00 type:73 payload:0 available:2
I (19898) cmux: SABM 1
V (19898) CMUX SABM: 0x3ffb1370   f9 07 3f 01 de f9                                 |..?...|
V (19898) CMUX Received: 0x3ffbc584   f9 07 73 01 15 f9 f9 01  ef 09 e3 05 07 0d 9a f9  |..s.............|
D (19908) CMUX: Payload frame: dlci:01 type:73 payload:0 available:12
D (19908) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
E (20928) INET: esp_modem_set_mode(ESP_MODEM_MODE_CMUX) failed with -1

It looks like there is MSC response but we did no MSC request, hm.

david-cermak · 2022-09-15T18:30:41Z

weird, I would expect we should get the second (dlci=1) SABM acked as shown previously in #140 (comment) but that never comes. Nothing has changed in that respect on my patch-branch , as the first MSC request should only come after it.

It looks like there is MSC response but we did no MSC request, hm.

I think it's the disconnection message from the control term, showing that something was wrong...

I guess I would have to play with a real SIM800L to see what's wrong.

RaD · 2022-09-15T18:41:44Z

here is more info:

I (11348) cmux: SABM 0
V (11348) CMUX SABM: 0x3ffb1380   f9 03 3f 01 1c f9                                 |..?...|
V (11348) CMUX Received: 0x3ffbc584   f9 03 73 01 d7 f9                                 |..s...|
W (11348) CMUX: State: 0
D (11358) CMux: on_init
D (11358) CMux: on_header
D (11358) CMUX: Payload frame: dlci:00 type:73 payload:0 available:2
D (11368) CMux: on_footer
I (11468) cmux: SABM 1
V (11468) CMUX SABM: 0x3ffb1380   f9 07 3f 01 de f9                                 |..?...|
V (11468) CMUX Received: 0x3ffbc584   f9 07 73 01 15 f9 f9 01  ef 09 e3 05 07 0d 9a f9  |..s.............|
W (11478) CMUX: State: 0
D (11478) CMux: on_init
D (11478) CMux: on_header
D (11478) CMUX: Payload frame: dlci:01 type:73 payload:0 available:12
D (11488) CMux: on_footer
D (11488) CMux: on_init
D (11498) CMux: on_header
D (11498) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
D (11498) CMux: on_footer
E (12518) INET: esp_modem_set_mode(ESP_MODEM_MODE_CMUX) failed with -1
D (12518) INET: Wait for IP settings...
V (13268) CMUX Received: 0x3ffbc584   f9 05 ef 4f 0d 0a 2a 50  53 55 54 54 5a 3a 20 32  |...O..*PSUTTZ: 2|
V (13268) CMUX Received: 0x3ffbc594   30 32 32 2c 39 2c 31 35  2c 31 38 2c 33 39 2c 31  |022,9,15,18,39,1|
V (13278) CMUX Received: 0x3ffbc5a4   35 2c 22 2b 31 32 22 2c  30 0d 0a cc f9 f9 05 ef  |5,"+12",0.......|
V (13288) CMUX Received: 0x3ffbc5b4   15 0d 0a 44 53 54 3a 20  30 0d 0a 4d f9 f9 05 ef  |...DST: 0..M....|
W (13298) CMUX: State: 0
D (13298) CMux: on_init
D (13298) CMux: on_header
D (13308) CMUX: Payload frame: dlci:01 type:ef payload:39 available:60
D (13308) CMux: on_footer
D (13318) CMux: on_init
D (13318) CMux: on_header
D (13318) CMUX: Payload frame: dlci:01 type:ef payload:10 available:15
D (13328) CMux: on_footer
D (13328) CMux: on_init
D (13328) CMux: on_header
V (13338) CMUX Received: 0x3ffbc584   5f 0d 0a 2b 43 49 45 56  3a 20 31 30 2c 22 32 35  |_..+CIEV: 10,"25|
V (13348) CMUX Received: 0x3ffbc594   30 30 31 22 2c 22 4d 54  53 20 52 55 53 22 2c 22  |001","MTS RUS","|
V (13358) CMUX Received: 0x3ffbc5a4   4d 54 53 20 52 55 53 22  2c 20 30 2c 20 30 0d 0a  |MTS RUS", 0, 0..|
V (13368) CMUX Received: 0x3ffbc5b4   d0 f9                                             |..|
W (13368) CMUX: State: 1
D (13378) CMux: on_header
D (13378) CMUX: Payload frame: dlci:01 type:ef payload:47 available:49
D (13388) CMux: on_footer

Pay attention that this output is much similar to https://manualzz.com/download/9010415
Not to SIM800L Multiplexer Nore. It is strange...

RaD · 2022-09-15T18:57:19Z

What is about this?

>F9 01 EF 0B E1 07 07 0C 01 79 F9(data sent to module, should be sent in time, it’s better to send this data as soon as receiving UA frame)

RaD · 2022-09-15T19:34:35Z

It was not helpful:

I (8838) cmux: SABM 0
V (8838) CMUX SABM: 0x3ffb1380   f9 03 3f 01 1c f9                                 |..?...|
V (8838) CMUX Received: 0x3ffbc584   f9 03 73 01 d7 f9                                 |..s...|
W (8838) CMUX: State: 0
D (8848) CMux: on_init
D (8848) CMux: on_header
D (8848) CMUX: Payload frame: dlci:00 type:73 payload:0 available:2
D (8858) CMux: on_footer
I (8958) cmux: SABM 1
V (8958) CMUX SABM: 0x3ffb1380   f9 07 3f 01 de f9                                 |..?...|
V (8958) CMUX Received: 0x3ffbc584   f9 07 73 01 15 f9 f9 01  ef 09 e3 05 07 0d 9a f9  |..s.............|
W (8958) CMUX: State: 0
D (8968) CMux: on_init
I (8968) cmux: SABM CONFIRM 1
V (8968) CMUX SABM CONFIRM: 0x3ffbc1a0   f9 01 ff 0b e1 07 07 0c  01 79 f9                 |.........y.|
D (8978) CMux: on_header
D (8988) CMUX: Payload frame: dlci:01 type:73 payload:0 available:12
D (8988) CMux: on_footer
D (8998) CMux: on_init
D (8998) CMux: on_header
D (8998) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
D (9008) CMux: on_footer
V (9278) CMUX Received: 0x3ffbc584   f9 05 ef 1d 0d 0a 43 61  6c 6c 20 52 65 61 64 79  |......Call Ready|
V (9278) CMUX Received: 0x3ffbc594   0d 0a 43 f9                                       |..C.|
W (9288) CMUX: State: 0
D (9288) CMux: on_init
D (9298) CMux: on_header
D (9298) CMUX: Payload frame: dlci:01 type:ef payload:14 available:16
D (9308) CMux: on_footer
V (9628) CMUX Received: 0x3ffbc584   f9 05 ef 1b 0d 0a 53 4d  53 20 52 65 61 64 79 0d  |......SMS Ready.|
V (9628) CMUX Received: 0x3ffbc594   0a a7 f9                                          |...|
W (9638) CMUX: State: 0
D (9638) CMux: on_init
D (9638) CMux: on_header
D (9648) CMUX: Payload frame: dlci:01 type:ef payload:13 available:15
D (9648) CMux: on_footer
V (13968) CMUX Received: 0x3ffbc584   f9 05 ef 4f 0d 0a 2a 50  53 55 54 54 5a 3a 20 32  |...O..*PSUTTZ: 2|
V (13968) CMUX Received: 0x3ffbc594   30 32 32 2c 39 2c 31 35  2c 31 39 2c 33 33 2c 35  |022,9,15,19,33,5|
V (13978) CMUX Received: 0x3ffbc5a4   30 2c 22 2b 31 32 22 2c  30 0d 0a cc f9 f9 05 ef  |0,"+12",0.......|
V (13988) CMUX Received: 0x3ffbc5b4   15 0d 0a 44 53 54 3a 20  30 0d 0a 4d f9 f9 05 ef  |...DST: 0..M....|
W (13998) CMUX: State: 0
D (13998) CMux: on_init
D (14008) CMux: on_header
D (14008) CMUX: Payload frame: dlci:01 type:ef payload:39 available:60
D (14008) CMux: on_footer
D (14018) CMux: on_init
D (14018) CMux: on_header
D (14018) CMUX: Payload frame: dlci:01 type:ef payload:10 available:15
D (14028) CMux: on_footer
D (14028) CMux: on_init
D (14028) CMux: on_header
V (14038) CMUX Received: 0x3ffbc584   5f 0d 0a 2b 43 49 45 56  3a 20 31 30 2c 22 32 35  |_..+CIEV: 10,"25|
V (14048) CMUX Received: 0x3ffbc594   30 30 31 22 2c 22 4d 54  53 20 52 55 53 22 2c 22  |001","MTS RUS","|
V (14058) CMUX Received: 0x3ffbc5a4   4d 54 53 20 52 55 53 22  2c 20 30 2c 20 30 0d 0a  |MTS RUS", 0, 0..|
V (14068) CMUX Received: 0x3ffbc5b4   d0 f9                                             |..|
W (14068) CMUX: State: 1
D (14078) CMux: on_header
D (14078) CMUX: Payload frame: dlci:01 type:ef payload:47 available:49
D (14088) CMux: on_footer
E (19168) INET: esp_modem_set_mode(ESP_MODEM_MODE_CMUX) failed with -1

RaD · 2022-09-16T06:15:50Z

I am on @ruslanpopov (telegram) and can make tests online...

RaD · 2022-09-16T12:07:18Z

It run once successfully!

No need to send MSC! No need to send SABM confirm frame!

Timing matters! It works only in verbose mode!

Otherwise it gets confused with DISC frame and causes trouble when entering CMUX mode (if device sends MSC requests) Closes espressif#140

david-cermak · 2022-09-16T14:21:12Z

I think I found the issue. It's a simple race condition, as the MSC frame could be interpreted as DISC and (if coming before notifying the SABM reply) destroy the CMUX entry sequence. Posted another update to the PR.

RaD · 2022-09-16T16:55:16Z

But if I exit from verbose logs the following is not reproducing:

I (3677) SIM800L: Initialization OK
D (3677) esp_netif_objects: esp_netif_add_to_list 0x3ffb90b0
D (3677) esp_netif_objects: esp_netif_add_to_list netif added successfully (total netifs: 1)
D (3687) esp-netif_lwip-ppp: esp_netif_new_ppp: PPP connection created: 0x3ffb9318
I (3687) INET: Initializing esp_modem for the SIM800 module...
I (3697) uart: queue free spaces: 30
V (3697) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (3697) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (3697) intr_alloc: Connected src 36 to int 13 (cpu 0)
V (8727) command_lib: set_cmux
V (8727) command_lib: generic_command_common
V (8727) command_lib: generic_command
D (8727) command_lib: generic_command command AT+CMUX=0

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


I (8837) cmux: SABM 0
V (8837) CMUX MSC: 0x3ffb13c0   f9 03 3f 01 1c f9                                 |..?...|
V (8837) CMUX Received: 0x3ffbc524   f9 03 73 01 d7 f9                                 |..s...|
D (8837) CMUX: Payload frame: dlci:00 type:73 payload:0 available:2
I (8947) cmux: SABM 1
V (8947) CMUX MSC: 0x3ffb13c0   f9 07 3f 01 de f9                                 |..?...|
V (8947) CMUX Received: 0x3ffbc524   f9 07 73 01 15 f9 f9 01  ef 09 e3 05 07 0d 9a f9  |..s.............|
D (8947) CMUX: Payload frame: dlci:01 type:73 payload:0 available:12
D (8957) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
I (9067) cmux: SABM 2
V (9067) CMUX MSC: 0x3ffb13c0   f9 0b 3f 01 59 f9                                 |..?.Y.|
V (9067) CMUX Received: 0x3ffbc524   f9 0b 73 01 92 f9 f9 01  ef 09 e3 05 0b 0d 9a f9  |..s.............|
D (9067) CMUX: Payload frame: dlci:02 type:73 payload:0 available:12
D (9077) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
V (9187) command_lib: set_echo
V (9187) command_lib: generic_command_common
V (9187) command_lib: generic_command
D (9187) command_lib: generic_command command ATE0

V (9187) Send: 0x3ffb10f0   f9 05 ef 0b                                       |....|
V (9197) CMUX Received: 0x3ffbc524   f9 05 ef 0b 41 54 45 30  0d bb f9 f9 05 ef 0d 0d  |....ATE0........|
V (9207) Send: 0x3ffb1408   41 54 45 30 0d                                    |ATE0.|
V (9217) CMUX Received: 0x3ffbc534   0a 4f 4b 0d 0a 5f f9                              |.OK.._.|
D (9217) CMUX: Payload frame: dlci:01 type:ef payload:5 available:19
V (9227) Send: 0x3ffb10f4   bb f9                                             |..|
D (9237) CMUX: Payload frame: dlci:01 type:ef payload:6 available:8
D (9247) command_lib: Response:
OK


V (9247) command_lib: set_pdp_context
V (9247) command_lib: generic_command_common
V (9257) command_lib: generic_command
D (9257) command_lib: generic_command command AT+CGDCONT=1,"IP","internet"

V (9267) Send: 0x3ffb10f0   f9 05 ef 3b                                       |...;|
V (9277) Send: 0x3ffbc9f4   41 54 2b 43 47 44 43 4f  4e 54 3d 31 2c 22 49 50  |AT+CGDCONT=1,"IP|
V (9277) CMUX Received: 0x3ffbc524   f9 05 ef 0d 0d 0a 4f 4b  0d 0a 5f f9              |......OK.._.|
V (9287) Send: 0x3ffbca04   22 2c 22 69 6e 74 65 72  6e 65 74 22 0d           |","internet".|
D (9297) CMUX: Payload frame: dlci:01 type:ef payload:6 available:8
V (9307) Send: 0x3ffb10f4   9f f9                                             |..|
D (9317) command_lib: Response:
OK


V (9317) CMUX Received: 0x3ffbc524   f9 05 ef 1d 0d 0a 43 61  6c 6c 20 52 65 61 64 79  |......Call Ready|
V (9327) command_lib: set_data_mode_sim8xx
V (9327) command_lib: generic_command
V (9337) CMUX Received: 0x3ffbc534   0d 0a 43 f9 f9 09 ef 1d  0d 0a 43 61 6c 6c 20 52  |..C.......Call R|
D (9347) command_lib: generic_command command ATD*99#

V (9347) Send: 0x3ffb1180   f9 05 ef 11                                       |....|
V (9357) CMUX Received: 0x3ffbc544   65 61 64 79 0d 0a c4 f9                           |eady....|
V (9367) Send: 0x3ffb1418   41 54 44 2a 39 39 23 0d                           |ATD*99#.|
D (9377) CMUX: Payload frame: dlci:01 type:ef payload:14 available:36
V (9387) Send: 0x3ffb1184   4a f9                                             |J.|
D (9377) command_lib: Response:
Call Ready


D (9397) CMUX: Payload frame: dlci:02 type:ef payload:14 available:16
V (9397) CMUX Received: 0x3ffbc524   f9 05 ef 17 0d 0a 43 4f  4e 4e 45 43 54 0d 0a ae  |......CONNECT...|
V (9407) CMUX Received: 0x3ffbc534   f9 f9 01 ef 09 e3 05 07  8d 9a f9                 |...........|
D (9417) CMUX: Payload frame: dlci:01 type:ef payload:11 available:23
D (9427) command_lib: Response:
CONNECT


D (9427) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
D (9437) esp_netif_handlers: esp_netif action has started with netif0x3ffb90b0 from event_id=0
D (9447) esp-netif_lwip-ppp: esp_netif_start_ppp: Starting PPP connection: 0x3ffb9318
D (9457) esp_netif_lwip: check: remote, if=0x3ffb90b0 fn=0x400f573c

D (9457) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffb90b0
V (9467) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3ffb90b0
D (9477) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (9477) INET: Wait for IP settings...
V (9647) CMUX Received: 0x3ffbc524   f9 09 ef 1b 0d 0a 53 4d  53 20 52 65 61 64 79 0d  |......SMS Ready.|
V (9647) CMUX Received: 0x3ffbc534   0a 20 f9                                          |. .|
D (9647) CMUX: Payload frame: dlci:02 type:ef payload:13 available:15
V (10367) CMUX Received: 0x3ffbc524   f9 05 ef 57 7e ff 7d 23  c0 21 7d 21 7d 21 7d 20  |...W~.}#.!}!}!} |
V (10367) CMUX Received: 0x3ffbc534   7d 32 7d 22 7d 26 7d 20  7d 2a 7d 20 7d 20 7d 23  |}2}"}&} }*} } }#|
V (10367) CMUX Received: 0x3ffbc544   7d 24 c0 23 7d 27 7d 22  7d 28 7d 22 55 83 7e de  |}$.#}'}"}(}"U.~.|
V (10377) CMUX Received: 0x3ffbc554   f9                                                |.|
D (10387) CMUX: Payload frame: dlci:01 type:ef payload:43 available:45
V (10397) Send: 0x3ffb4510   f9 05 ef 2f                                       |.../|
V (10407) Send: 0x3ffc5210   7e ff 7d 23 c0 21 7d 24  7d 21 7d 20 7d 28 7d 23  |~.}#.!}$}!} }(}#|
V (10417) Send: 0x3ffc5220   7d 24 c0 23 2c d4 7e                              |}$.#,.~|
V (10417) Send: 0x3ffb4514   84 f9                                             |..|
V (10427) CMUX Received: 0x3ffbc524   f9 05 ef 4b 7e ff 7d 23  c0 21 7d 21 7d 22 7d 20  |...K~.}#.!}!}"} |
V (10437) CMUX Received: 0x3ffbc534   7d 2e 7d 22 7d 26 7d 20  7d 2a 7d 20 7d 20 7d 27  |}.}"}&} }*} } }'|
V (10447) CMUX Received: 0x3ffbc544   7d 22 7d 28 7d 22 d0 d3  7e cb f9                 |}"}(}"..~..|
D (10457) CMUX: Payload frame: dlci:01 type:ef payload:37 available:39
V (10467) Send: 0x3ffb4510   f9 05 ef 4b                                       |...K|
V (10467) Send: 0x3ffc5210   7e ff 7d 23 c0 21 7d 22  7d 22 7d 20 7d 2e 7d 22  |~.}#.!}"}"} }.}"|
V (10477) Send: 0x3ffc5220   7d 26 7d 20 7d 2a 7d 20  7d 20 7d 27 7d 22 7d 28  |}&} }*} } }'}"}(|
V (10487) Send: 0x3ffc5230   7d 22 ee 50 7e                                    |}".P~|
V (10497) Send: 0x3ffb4514   cb f9                                             |..|
V (15457) Send: 0x3ffb45b0   f9 05 ef 5f                                       |..._|
V (15457) Send: 0x3ffbd000   7e ff 7d 23 c0 21 7d 21  7d 21 7d 20 7d 34 7d 22  |~.}#.!}!}!} }4}"|
V (15457) Send: 0x3ffbd010   7d 26 7d 20 7d 20 7d 20  7d 20 7d 25 7d 26 87 c9  |}&} } } } }%}&..|
V (15467) Send: 0x3ffbd020   7d 36 7d 2d 7d 27 7d 22  7d 28 7d 22 df 60 7e     |}6}-}'}"}(}".`~|
V (15477) Send: 0x3ffb45b4   d0 f9                                             |..|
V (15487) CMUX Received: 0x3ffbc524   f9 05 ef 3b 7e ff 7d 23  c0 21 7d 23 7d 21 7d 20  |...;~.}#.!}#}!} |
V (15497) CMUX Received: 0x3ffbc534   7d 2a 7d 22 7d 26 7d 20  7d 2a 7d 20 7d 20 6c 50  |}*}"}&} }*} } lP|
V (15507) CMUX Received: 0x3ffbc544   7e 9f f9                                          |~..|
D (15517) CMUX: Payload frame: dlci:01 type:ef payload:29 available:31
V (15517) Send: 0x3ffb4520   f9 05 ef 5f                                       |..._|
V (15527) Send: 0x3ffc5210   7e ff 7d 23 c0 21 7d 21  7d 22 7d 20 7d 34 7d 22  |~.}#.!}!}"} }4}"|
V (15537) Send: 0x3ffc5220   7d 26 7d 20 7d 2a 7d 20  7d 20 7d 25 7d 26 87 c9  |}&} }*} } }%}&..|
V (15547) Send: 0x3ffc5230   7d 36 7d 2d 7d 27 7d 22  7d 28 7d 22 27 fb 7e     |}6}-}'}"}(}"'.~|
V (15557) Send: 0x3ffb4524   d0 f9                                             |..|
V (15557) CMUX Received: 0x3ffbc524   f9 05 ef 5f 7e ff 7d 23  c0 21 7d 22 7d 22 7d 20  |..._~.}#.!}"}"} |
V (15567) CMUX Received: 0x3ffbc534   7d 34 7d 22 7d 26 7d 20  7d 2a 7d 20 7d 20 7d 25  |}4}"}&} }*} } }%|
V (15577) CMUX Received: 0x3ffbc544   7d 26 87 c9 7d 36 7d 2d  7d 27 7d 22 7d 28 7d 22  |}&..}6}-}'}"}(}"|
V (15587) CMUX Received: 0x3ffbc554   cc 92 7e d0 f9 f9 05 ef  21 7e 80 21 01 01 00 0a  |..~.....!~.!....|
V (15597) CMUX Received: 0x3ffbc564   03 06 c0 a8 fe fe 48 cc  7e 6e f9                 |......H.~n.|
D (15607) CMUX: Payload frame: dlci:01 type:ef payload:47 available:71
V (15617) Send: 0x3ffb4440   f9 05 ef 49                                       |...I|
V (15627) Send: 0x3ffc5210   7e ff 03 80 21 01 01 00  1c 02 06 00 2d 0f 01 03  |~...!.......-...|
V (15637) Send: 0x3ffc5220   06 00 00 00 00 81 06 00  00 00 00 83 06 00 00 00  |................|
V (15637) Send: 0x3ffc5230   00 55 15 7e                                       |.U.~|
V (15647) Send: 0x3ffb4444   28 f9                                             |(.|
D (15657) CMUX: Payload frame: dlci:01 type:ef payload:16 available:18
V (15667) Send: 0x3ffb4510   f9 05 ef 25                                       |...%|
V (15667) Send: 0x3ffc5210   7e ff 03 80 21 02 01 00  0a 03 06 c0 a8 fe fe 5f  |~...!.........._|
V (15677) Send: 0x3ffc5220   56 7e                                             |V~|
V (15687) Send: 0x3ffb4514   69 f9                                             |i.|
V (15697) CMUX Received: 0x3ffbc524   f9 05 ef 21 7e 80 21 04  01 00 0a 02 06 00 2d 0f  |...!~.!.......-.|
V (15707) CMUX Received: 0x3ffbc534   01 f8 30 7e 6e f9                                 |..0~n.|
D (15717) CMUX: Payload frame: dlci:01 type:ef payload:16 available:18
V (15727) Send: 0x3ffb4520   f9 05 ef 3d                                       |...=|
V (15727) Send: 0x3ffc5210   7e ff 03 80 21 01 02 00  16 03 06 00 00 00 00 81  |~...!...........|
V (15737) Send: 0x3ffc5220   06 00 00 00 00 83 06 00  00 00 00 da 82 7e        |.............~|
V (15747) Send: 0x3ffb4524   7b f9                                             |{.|
V (21277) CMUX Received: 0x3ffbc524   f9 05 ef 39 7e 80 21 03  02 00 16 03 06 64 75 a0  |...9~.!......du.|
V (21277) CMUX Received: 0x3ffbc534   8d 81 06 d5 57 8e 54 83  06 d5 57 8e 55 c4 53 7e  |....W.T...W.U.S~|
V (21287) CMUX Received: 0x3ffbc544   7c f9                                             ||.|
D (21297) CMUX: Payload frame: dlci:01 type:ef payload:28 available:30
V (21307) Send: 0x3ffb4520   f9 05 ef 3d                                       |...=|
V (21307) Send: 0x3ffc5210   7e ff 03 80 21 01 03 00  16 03 06 64 75 a0 8d 81  |~...!......du...|
V (21317) Send: 0x3ffc5220   06 d5 57 8e 54 83 06 d5  57 8e 55 63 ae 7e        |..W.T...W.Uc.~|
V (21327) Send: 0x3ffb4524   7b f9                                             |{.|
V (21337) CMUX Received: 0x3ffbc524   f9 05 ef 39 7e 80 21 02  03 00 16 03 06 64 75 a0  |...9~.!......du.|
V (21347) CMUX Received: 0x3ffbc534   8d 81 06 d5 57 8e 54 83  06 d5 57 8e 55 f5 cd 7e  |....W.T...W.U..~|
V (21357) CMUX Received: 0x3ffbc544   7c f9                                             ||.|
D (21367) CMUX: Payload frame: dlci:01 type:ef payload:28 available:30
I (21367) esp-netif_lwip-ppp: Connected
I (21377) esp-netif_lwip-ppp: Name Server1: 213.87.142.84
I (21377) esp-netif_lwip-ppp: Name Server2: 213.87.142.85
D (21387) event: running post IP_EVENT:6 with handler 0x400d8b6c and context 0x3ffba5a0 on loop 0x3ffb4a5c
D (21397) INET: IP event: 6
I (21397) INET: Got IP address over PPP
I (21407) INET: ~~~~~~~~~~~~~~
I (21407) INET: IP          : 100.117.160.141
I (21417) INET: Netmask     : 255.255.255.255
I (21417) INET: Gateway     : 192.168.254.254
I (21427) INET: Name Server1: 213.87.142.84
I (21427) INET: Name Server2: 213.87.142.85
I (21437) INET: ~~~~~~~~~~~~~~

RaD · 2022-09-16T17:21:03Z

Worked patch:

diff -uNr managed_components/espressif__esp_modem/src/esp_modem_cmux.cpp managed_components_works/espressif__esp_modem/src/esp_modem_cmux.cpp
--- managed_components/espressif__esp_modem/src/esp_modem_cmux.cpp	2022-09-14 15:47:05.000000000 +0300
+++ managed_components_works/espressif__esp_modem/src/esp_modem_cmux.cpp	2022-09-16 20:18:48.000000000 +0300
@@ -95,6 +95,7 @@

 void CMux::send_sabm(size_t i)
 {
+    ESP_LOGD("CMUX", "SABM %d", i);
     uint8_t frame[6];
     frame[0] = SOF_MARKER;
     frame[1] = (i << 2) | 0x3;
@@ -103,6 +104,7 @@
     frame[4] = 0xFF - fcs_crc(frame);
     frame[5] = SOF_MARKER;
     term->write(frame, 6);
+    ESP_LOG_BUFFER_HEXDUMP("CMUX SABM", frame, sizeof(frame), ESP_LOG_VERBOSE);
 }


@@ -143,6 +145,10 @@
 #endif
         }
     } else if ((type&FT_UIH) == FT_UIH && dlci == 0) { // notify the internal DISC command
+        if (len > 0 && (data[0] & 0xE1) == 0xE1) {
+            // Not a DISC, ignore (MSC frame)
+            return;
+        }
         Scoped<Lock> l(lock);
         sabm_ack = dlci;
     }
@@ -385,6 +391,7 @@
                 return false;
             }
         }
+        usleep(100'000);
     }
     return true;
 }

Also pay attention on 5 seconds delay before launching AT+CMUX=0...

BTW, how to send and receive commands and their answers in CMUX mode? ;)

david-cermak · 2022-09-16T17:22:33Z

But if I exit from verbose logs the following is not reproducing:

Are you saying that after applying the latest fix 72a603f, you're getting the IP address correctly? But this works only when full verbose logging is enabled (once you lower verbosity, it just fails with no message whatsoever)? Is that correct?

RaD · 2022-09-16T17:23:08Z

The patch above works even in DEBUG mode.
Tested on 0.1.22

david-cermak · 2022-09-16T17:24:12Z

oh, I see, a delay here and there fixes the issue, too.

RaD · 2022-09-16T17:24:50Z

Waiting for 0.1.23 )

RaD · 2022-09-16T18:35:02Z

Made some tests, it is not very stable

RaD · 2022-09-17T00:14:38Z

V (8708) command_lib: set_cmux
V (8708) command_lib: generic_command_common
V (8708) command_lib: generic_command
D (8708) command_lib: generic_command command AT+CMUX=0

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


W (8818) CMUX: SABM 0
V (8818) CMUX SABM: 0x3ffb13c0   f9 03 3f 01 1c f9                                 |..?...|
V (8818) CMUX Received: 0x3ffbc4dc   f9 03 73 01 d7 f9                                 |..s...|
D (8818) CMUX: Payload frame: dlci:00 type:73 payload:0 available:2
W (8928) CMUX: SABM 1
V (8928) CMUX SABM: 0x3ffb13c0   f9 07 3f 01 de f9                                 |..?...|
V (8928) CMUX Received: 0x3ffbc4dc   f9 07 73 01 15 f9 f9 01  ef 09 e3 05 07 0d 9a f9  |..s.............|
D (8938) CMUX: Payload frame: dlci:01 type:73 payload:0 available:12
D (8938) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
W (9048) CMUX: SABM 2
V (9048) CMUX SABM: 0x3ffb13c0   f9 0b 3f 01 59 f9                                 |..?.Y.|
V (9048) CMUX Received: 0x3ffbc4dc   f9 0b 73 01 92 f9 f9 01  ef 09 e3 05 0b 0d 9a f9  |..s.............|
D (9058) CMUX: Payload frame: dlci:02 type:73 payload:0 available:12
D (9058) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
V (9168) command_lib: set_echo
V (9168) command_lib: generic_command_common
V (9168) command_lib: generic_command
D (9168) command_lib: generic_command command ATE0

V (9168) Send: 0x3ffb10f0   f9 05 ef 0b                                       |....|
V (9178) CMUX Received: 0x3ffbc4dc   f9 05 ef 0b 41 54 45 30  0d bb f9 f9 05 ef 0d 0d  |....ATE0........|
V (9188) Send: 0x3ffb1408   41 54 45 30 0d                                    |ATE0.|
V (9198) CMUX Received: 0x3ffbc4ec   0a 4f 4b 0d 0a 5f f9                              |.OK.._.|
D (9198) CMUX: Payload frame: dlci:01 type:ef payload:5 available:19
V (9208) Send: 0x3ffb10f4   bb f9                                             |..|
D (9218) CMUX: Payload frame: dlci:01 type:ef payload:6 available:8
D (9228) command_lib: Response:
OK


V (9228) command_lib: set_pdp_context
V (9228) command_lib: generic_command_common
V (9238) command_lib: generic_command
D (9238) command_lib: generic_command command AT+CGDCONT=1,"IP","internet"

V (9248) Send: 0x3ffb10f0   f9 05 ef 3b                                       |...;|
V (9258) Send: 0x3ffbc9ac   41 54 2b 43 47 44 43 4f  4e 54 3d 31 2c 22 49 50  |AT+CGDCONT=1,"IP|
V (9258) CMUX Received: 0x3ffbc4dc   f9 05 ef 0d 0d 0a 4f 4b  0d 0a 5f f9              |......OK.._.|
V (9268) Send: 0x3ffbc9bc   22 2c 22 69 6e 74 65 72  6e 65 74 22 0d           |","internet".|
D (9278) CMUX: Payload frame: dlci:01 type:ef payload:6 available:8
V (9288) Send: 0x3ffb10f4   9f f9                                             |..|
D (9298) command_lib: Response:
OK


V (9298) CMUX Received: 0x3ffbc4dc   f9 05 ef 1d 0d 0a 43 61  6c 6c 20 52 65 61 64 79  |......Call Ready|
V (9308) command_lib: set_data_mode_sim8xx
V (9308) command_lib: generic_command
V (9318) CMUX Received: 0x3ffbc4ec   0d 0a 43 f9 f9 09 ef 1d  0d 0a 43 61 6c 6c 20 52  |..C.......Call R|
D (9328) command_lib: generic_command command ATD*99#

V (9328) Send: 0x3ffb1180   f9 05 ef 11                                       |....|
V (9338) CMUX Received: 0x3ffbc4fc   65 61 64 79 0d 0a c4 f9                           |eady....|
V (9348) Send: 0x3ffb1418   41 54 44 2a 39 39 23 0d                           |ATD*99#.|
D (9358) CMUX: Payload frame: dlci:01 type:ef payload:14 available:36
V (9368) Send: 0x3ffb1184   4a f9                                             |J.|
D (9368) command_lib: Response:
Call Ready


D (9378) CMUX: Payload frame: dlci:02 type:ef payload:14 available:16
V (9378) CMUX Received: 0x3ffbc4dc   f9 05 ef 17 0d 0a 43 4f  4e 4e 45 43 54 0d 0a ae  |......CONNECT...|
V (9388) CMUX Received: 0x3ffbc4ec   f9 f9 01 ef 09 e3 05 07  8d 9a f9                 |...........|
D (9398) CMUX: Payload frame: dlci:01 type:ef payload:11 available:23
D (9408) command_lib: Response:
CONNECT


D (9408) CMUX: Payload frame: dlci:00 type:ef payload:4 available:6
D (9418) esp_netif_handlers: esp_netif action has started with netif0x3ffb9068 from event_id=0
D (9428) esp-netif_lwip-ppp: esp_netif_start_ppp: Starting PPP connection: 0x3ffb92d0
D (9438) esp_netif_lwip: check: remote, if=0x3ffb9068 fn=0x400f58a8

D (9438) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffb9068
V (9448) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3ffb9068
D (9458) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (9458) INET: Wait for IP settings...
V (9618) CMUX Received: 0x3ffbc4dc   f9 09 ef 1b 0d 0a 53 4d  53 20 52 65 61 64 79 0d  |......SMS Ready.|
V (9618) CMUX Received: 0x3ffbc4ec   0a 20 f9                                          |. .|
D (9628) CMUX: Payload frame: dlci:02 type:ef payload:13 available:15
V (10338) CMUX Received: 0x3ffbc4dc   f9 05 ef 57 7e ff 7d 23  c0 21 7d 21 7d 21 7d 20  |...W~.}#.!}!}!} |
V (10338) CMUX Received: 0x3ffbc4ec   7d 32 7d 22 7d 26 7d 20  7d 2a 7d 20 7d 20 7d 23  |}2}"}&} }*} } }#|
V (10348) CMUX Received: 0x3ffbc4fc   7d 24 c0 23 7d 27 7d 22  7d 28 7d 22 55 83 7e de  |}$.#}'}"}(}"U.~.|
V (10358) CMUX Received: 0x3ffbc50c   f9                                                |.|
D (10368) CMUX: Payload frame: dlci:01 type:ef payload:43 available:45
V (10368) Send: 0x3ffb44d0   f9 05 ef 2f                                       |.../|
V (10378) Send: 0x3ffc5090   7e ff 7d 23 c0 21 7d 24  7d 21 7d 20 7d 28 7d 23  |~.}#.!}$}!} }(}#|
V (10388) Send: 0x3ffc50a0   7d 24 c0 23 2c d4 7e                              |}$.#,.~|
V (10398) Send: 0x3ffb44d4   84 f9                                             |..|
V (10408) CMUX Received: 0x3ffbc4dc   f9 05 ef 4b 7e ff 7d 23  c0 21 7d 21 7d 22 7d 20  |...K~.}#.!}!}"} |
V (10418) CMUX Received: 0x3ffbc4ec   7d 2e 7d 22 7d 26 7d 20  7d 2a 7d 20 7d 20 7d 27  |}.}"}&} }*} } }'|
V (10418) CMUX Received: 0x3ffbc4fc   7d 22 7d 28 7d 22 d0 d3  7e cb f9                 |}"}(}"..~..|
D (10428) CMUX: Payload frame: dlci:01 type:ef payload:37 available:39
V (10438) Send: 0x3ffb44d0   f9 05 ef 4b                                       |...K|
V (10448) Send: 0x3ffc5090   7e ff 7d 23 c0 21 7d 22  7d 22 7d 20 7d 2e 7d 22  |~.}#.!}"}"} }.}"|
V (10458) Send: 0x3ffc50a0   7d 26 7d 20 7d 2a 7d 20  7d 20 7d 27 7d 22 7d 28  |}&} }*} } }'}"}(|
V (10468) Send: 0x3ffc50b0   7d 22 ee 50 7e                                    |}".P~|
V (10468) Send: 0x3ffb44d4   cb f9                                             |..|
rror: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x4008a9a4: 01553014 80d95e81 53501033
Core  0 register dump:
PC      : 0x4008a9ab  PS      : 0x00060031  A0      : 0x80084c26  A1      : 0x3ffbe4b0
A2      : 0x3ff60000  A3      : 0x00000000  A4      : 0x00000258  A5      : 0x20000000
A6      : 0x00000000  A7      : 0x00000000  A8      : 0x9fffffff  A9      : 0x3ffb1f10
A10     : 0x00000000  A11     : 0x00000000  A12     : 0x00000014  A13     : 0x3ffb14a0
A14     : 0x3ffbe6e8  A15     : 0xffffffff  SAR     : 0x00000000  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000
Core  0 was running in ISR context:
EPC1    : 0x400d3bc3  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x00000000


Backtrace:0x4008a9a8:0x3ffbe4b00x40084c23:0x3ffbe4d0 0x40084c01:0x3ffbe4f0 0x4008848c:0x3ffbe510 0x40086ccb:0x3ffbe530 0x40086a25:0x3ffbe550 0x40082e46:0x3ffbe560 0x40141e43:0x3ffb1ed0 0x400f3823:0x3ffb1ef0 0x40088145:0x3ffb1f10 0x400898d1:0x3ffb1f30

david-cermak · 2022-09-19T06:59:31Z

Could you please decode the addresses in the backtrace below?

As described here:
https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-guides/tools/idf-monitor.html#automatic-address-decoding (interested in numbers starting with 0x4_______)

...-addr2line -pfiaC -e build/PROJECT.elf ADDRESS

Otherwise it gets confused with DISC frame and causes trouble when entering CMUX mode (if device sends MSC requests) Closes espressif#140

RaD · 2022-09-20T06:31:40Z

0x4008a9a4: mwdt_ll_config_stage atesp-idf-v4.4.1/components/hal/esp32/include/hal/mwdt_ll.h:93
 (inlined by) wdt_hal_config_stage at esp-idf-v4.4.1/components/hal/wdt_hal_iram.c:121

0x4008a9ab: mwdt_ll_config_stage at esp-idf-v4.4.1/components/hal/esp32/include/hal/mwdt_ll.h:93
 (inlined by) wdt_hal_config_stage at esp-idf-v4.4.1/components/hal/wdt_hal_iram.c:121

0x400d3bc3: uart_ll_tx_break at esp-idf-v4.4.1/components/hal/esp32/include/hal/uart_ll.h:462
 (inlined by) uart_hal_tx_break at esp-idf-v4.4.1/components/hal/uart_hal_iram.c:30

RaD · 2022-09-20T07:00:43Z

Applied your patch! It looks like the problem is solved ;)

RaD · 2022-09-20T08:25:33Z

10 successful starts of 10 tries, great!

RaD · 2022-09-22T12:02:52Z

Will you bump the component version?

RaD · 2022-09-25T13:38:02Z

There is a problem when the verbose mode was disabled:

E (14835) INET: esp_modem_set_mode(ESP_MODEM_MODE_CMUX) failed!

RaD · 2022-09-25T13:56:56Z

The solution:

        if (i > 0) {    // wait for each virtual terminal to settle MSC (no need for control term, DLCI=0)
            usleep(500'000);
        }

Output:

I (5665) SIM800L: Initialization OK
I (5665) INET: Initializing esp_modem for the SIM800 module...
I (5665) uart: queue free spaces: 30
I (10665) INET: ATI: SIM800 R14.18
I (10665) INET: IMSI: xxxx
I (10675) INET: IMEI: yyyy
I (13185) INET: Operator[500]: MTS
I (13195) INET: Signal quality: rssi=12, ber=0
I (13195) INET: Battery status: volt=4032, bcs=0, bcl=79
I (13195) INET: Caller ID detection enabled
I (21355) esp-netif_lwip-ppp: Connected
I (21355) esp-netif_lwip-ppp: Name Server1: 213.87.142.84
I (21355) esp-netif_lwip-ppp: Name Server2: 213.87.142.85
I (21355) INET: Got IP address over PPP
I (21365) INET: ~~~~~~~~~~~~~~
I (21365) INET: IP          : 100.116.199.128
I (21365) INET: Netmask     : 255.255.255.255
I (21375) INET: Gateway     : 192.168.254.254
I (21385) INET: Name Server1: 213.87.142.84
I (21385) INET: Name Server2: 213.87.142.85
I (21385) INET: ~~~~~~~~~~~~~~

RaD · 2022-09-26T08:52:19Z

It is funny, but 500'000 is too long for verbose. It failed again.
For info level 500'000 is good, but bad for verbose level.

david-cermak · 2022-09-30T08:37:31Z

It is funny, but 500'000 is too long for verbose. It failed again. For info level 500'000 is good, but bad for verbose level.

Alright, I'll make it a config option. Seems like it also depends on devices, and we don't want to wait second(s) to switch modes on other devices.

Otherwise it gets confused with DISC frame and causes trouble when entering CMUX mode (if device sends MSC requests) Closes espressif#140

espressif-bot added the Status: Opened label Sep 13, 2022

github-actions bot changed the title ~~Unable to get network interface while using CMUX mode~~ Unable to get network interface while using CMUX mode (IDFGH-8297) Sep 13, 2022

espressif-bot added Status: In Progress and removed Status: Opened labels Sep 16, 2022

david-cermak added a commit to david-cermak/esp-protocols that referenced this issue Sep 16, 2022

fix(esp_modem): CMUX to ignore MSC frames

72a603f

Otherwise it gets confused with DISC frame and causes trouble when entering CMUX mode (if device sends MSC requests) Closes espressif#140

david-cermak added a commit to david-cermak/esp-protocols that referenced this issue Sep 20, 2022

fix(esp_modem): CMUX to ignore MSC frames

2606b71

Otherwise it gets confused with DISC frame and causes trouble when entering CMUX mode (if device sends MSC requests) Closes espressif#140

espressif-bot added Status: Reviewing and removed Status: In Progress labels Sep 20, 2022

david-cermak added a commit to david-cermak/esp-protocols that referenced this issue Sep 30, 2022

fix(esp_modem): CMUX to ignore MSC frames

9bd62a9

Otherwise it gets confused with DISC frame and causes trouble when entering CMUX mode (if device sends MSC requests) Closes espressif#140

david-cermak mentioned this issue Sep 30, 2022

(esp_modem): Fix switching to CMUX mode for devices that send MSCs #142

Merged

david-cermak closed this as completed in ce175df Oct 17, 2022

espressif-bot added Resolution: Done and removed Status: Reviewing labels Oct 19, 2022

gabsuren pushed a commit to gabsuren/esp-protocols-1 that referenced this issue Oct 31, 2022

fix(esp_modem): CMUX to ignore MSC frames

dbef3d0

Otherwise it gets confused with DISC frame and causes trouble when entering CMUX mode (if device sends MSC requests) Closes espressif#140

jgus mentioned this issue Dec 4, 2022

cmux_example: Failed to configure multiplexed command mode... exiting (IDFGH-8886) #187

Closed

morgana2313 mentioned this issue Oct 17, 2024

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

Closed

3 tasks

Unable to get network interface while using CMUX mode (IDFGH-8297) #140

Unable to get network interface while using CMUX mode (IDFGH-8297) #140

Comments

RaD commented Sep 13, 2022

david-cermak commented Sep 14, 2022

RaD commented Sep 14, 2022

RaD commented Sep 14, 2022 • edited Loading

RaD commented Sep 15, 2022

david-cermak commented Sep 15, 2022

david-cermak commented Sep 15, 2022

RaD commented Sep 15, 2022

RaD commented Sep 15, 2022

david-cermak commented Sep 15, 2022

RaD commented Sep 15, 2022

RaD commented Sep 15, 2022

RaD commented Sep 15, 2022

david-cermak commented Sep 15, 2022

RaD commented Sep 15, 2022

RaD commented Sep 15, 2022

RaD commented Sep 15, 2022

RaD commented Sep 16, 2022

RaD commented Sep 16, 2022 • edited Loading

david-cermak commented Sep 16, 2022

RaD commented Sep 16, 2022

RaD commented Sep 16, 2022

david-cermak commented Sep 16, 2022

RaD commented Sep 16, 2022 • edited Loading

david-cermak commented Sep 16, 2022

RaD commented Sep 16, 2022

RaD commented Sep 16, 2022

RaD commented Sep 17, 2022

david-cermak commented Sep 19, 2022

RaD commented Sep 20, 2022 • edited Loading

RaD commented Sep 20, 2022

RaD commented Sep 20, 2022

RaD commented Sep 22, 2022

RaD commented Sep 25, 2022

RaD commented Sep 25, 2022 • edited Loading

RaD commented Sep 26, 2022

david-cermak commented Sep 30, 2022

RaD commented Sep 14, 2022 •

edited

Loading

RaD commented Sep 16, 2022 •

edited

Loading

RaD commented Sep 16, 2022 •

edited

Loading

RaD commented Sep 20, 2022 •

edited

Loading

RaD commented Sep 25, 2022 •

edited

Loading