modem_tcp_client example in esp_modem library is not working with SIM7600G-H and ESP32-S3 (IDFGH-11018)

[msivanesancq]

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.

General issue report

I compiled the modem_tcp_client example and seeing no mqtt publish to the cloud.
I did following modifications those are mandatory for my use case.

1. serial port pins are modified to have UART communication up and running.
2. I changed the correct APN and sdkconfig.
3. loop back URL address to correct ip as shown below.
   mqtt_config.broker.address.uri = "mqtts://137.135.83.217";

The debug logs are available here:

I (882) main_task: Calling app_main()
D (892) esp_netif_lwip: LwIP stack has been initialized
D (892) esp_netif_lwip: esp-netif has been successfully initialized
D (902) event: running task for loop 0x3fc9d7d4loc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (942) intr_alloc: Connected src 28 to int 17 (cpu 0)
V (942) command_lib: sync
V (942) command_lib: generic_command_common
V (952) command_lib: generic_command
D (952) command_lib: generic_command command AT


D (1052) command_lib: Response:

OK



D (1052) sock_dce: Modem in sync
V (1052) command_lib: set_echo
V (1052) command_lib: generic_command_common
V (1052) command_lib: generic_command
D (1062) command_lib: generic_command command ATE0


D (1162) command_lib: Response:

OK



V (1162) command_lib: set_pdp_context
V (1162) command_lib: generic_command_common
V (1162) command_lib: generic_command
D (1162) command_lib: generic_command command AT+CGDCONT=1,"IP","iot.1nce.net"


D (1292) command_lib: Response:

OK



D (1292) sock_dce: PDP configured
V (1292) sock_commands: net_open
V (1292) command_lib: generic_get_string
V (1292) command_lib: generic_get_string
V (1402) command_lib: Token: {
}

V (1402) command_lib: Token: {+NETOPEN: 1}

V (1402) command_lib: Token: {
}

V (1402) command_lib: Token: {OK}

V (1402) sock_commands: +NETOPEN: 1
D (1402) sock_commands: Already there
V (1412) command_lib: generic_command
D (1412) command_lib: generic_command command AT+CIPRXGET=1


D (1512) command_lib: Response:

OK



D (1512) sock_dce: Network opened
V (1512) command_lib: generic_get_string
V (1512) command_lib: generic_get_string
V (1622) command_lib: Token: {
}

V (1622) command_lib: Token: {+IPADDR: 10.223.166.7}

V (1622) command_lib: Token: {
}

V (1622) command_lib: Token: {OK}

I (1632) sock_dce: Got IP +IPADDR: 10.223.166.7
I (1632) sock_dce: Socket created
I (1642) sock_dce: Socket bound, port 8883
D (1642) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (1652) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (1652) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (1662) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (1672) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (1682) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (1682) mqtt_client: MQTT client_id=ESP32_66AD88
D (1692) event: created event loop 0x3fca1144
D (1692) mqtt_client: Core selection disabled
D (1702) event: running post MQTT_EVENTS:7 with handler 0x4200a440 and context 0x3fca1a74 on loop 0x3fca1144
D (1712) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=7
I (1712) modem_client: MQTT other event id: 7
D (1722) esp-tls: host:137.135.83.217: strlen 14
D (1722) esp-tls: [sock=55] Resolved IPv4 address: 137.135.83.217
D (1732) esp-tls: [sock=55] Connecting to server. HOST: 137.135.83.217, Port: 8883
E (1742) esp-tls: [sock=55] connect() error: Host is unreachable
E (1752) esp-tls: Failed to open new connection
E (1752) transport_base: Failed to open a new connection
E (1762) mqtt_client: Error transport connect
D (1762) event: running post MQTT_EVENTS:0 with handler 0x4200a440 and context 0x3fca1a74 on loop 0x3fca1144
D (1772) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=0
I (1782) modem_client: MQTT_EVENT_ERROR
D (1782) mqtt_client: Reconnect after 10000 ms
D (1792) event: running post MQTT_EVENTS:2 with handler 0x4200a440 and context 0x3fca1a74 on loop 0x3fca1144
D (1802) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=2
I (1812) modem_client: MQTT_EVENT_DISCONNECTED
V (1812) sock_commands: tcp_close
V (1812) command_lib: generic_command
D (1822) command_lib: generic_command command AT+CIPCLOSE=0


D (1842) command_lib: Response:

+CIPCLOSE: 0,4



ERROR



V (1962) sock_dce: 0x3fca054c   0d 0a 4f 4b 0d 0a                                 |..OK..|
D (1962) sock_commands: response

OK


V (2242) sock_dce: 0x3fca054c   0d 0a 2b 43 49 50 4f 50  45 4e 3a 20 30 2c 30 0d  |..+CIPOPEN: 0,0.|
V (2242) sock_dce: 0x3fca055c   0a                                                |.|
D (2242) sock_commands: response

+CIPOPEN: 0,0


I (2252) sock_commands: Connected!
V (2452) modem_client: ...performing
V (2962) modem_client: ...performing
V (3472) modem_client: ...performing
V (3982) modem_client: ...performing
V (4492) modem_client: ...performing
V (5002) modem_client: ...performing
V (5512) modem_client: ...performing
V (6022) modem_client: ...performing
V (6532) modem_client: ...performing
V (7042) modem_client: ...performing
V (7552) modem_client: ...performing
V (8062) modem_client: ...performing
V (8572) modem_client: ...performing
V (9082) modem_client: ...performing
V (9592) modem_client: ...performing
V (10102) modem_client: ...performing
V (10612) modem_client: ...performing
V (11122) modem_client: ...performing
V (11632) modem_client: ...performing
D (11812) mqtt_client: Reconnecting...
D (11812) event: running post MQTT_EVENTS:7 with handler 0x4200a440 and context 0x3fca1a74 on loop 0x3fca1144
D (11812) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=7
I (11822) modem_client: MQTT other event id: 7
D (11822) esp-tls: host:137.135.83.217: strlen 14
D (11832) esp-tls: [sock=55] Resolved IPv4 address: 137.135.83.217
D (11832) esp-tls: [sock=55] Connecting to server. HOST: 137.135.83.217, Port: 8883
E (11842) esp-tls: [sock=55] connect() error: Host is unreachable
E (11852) esp-tls: Failed to open new connection
E (11852) transport_base: Failed to open a new connection
E (11862) mqtt_client: Error transport connect
D (11862) event: running post MQTT_EVENTS:0 with handler 0x4200a440 and context 0x3fca1a74 on loop 0x3fca1144
D (11872) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=0
I (11882) modem_client: MQTT_EVENT_ERROR
D (11892) mqtt_client: Reconnect after 10000 ms
D (11892) event: running post MQTT_EVENTS:2 with handler 0x4200a440 and context 0x3fca1a74 on loop 0x3fca1144
D (11902) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=2
I (11912) modem_client: MQTT_EVENT_DISCONNECTED
V (12142) modem_client: ...performing
V (12652) modem_client: ...performing
V (13162) modem_client: ...performing
V (13672) modem_client: ...performing
V (14182) modem_client: ...performing
V (14692) modem_client: ...performing
V (15202) modem_client: ...performing
V (15712) modem_client: ...performing
V (16222) modem_client: ...performing
V (16732) modem_client: ...performing
V (17242) modem_client: ...performing
V (17752) modem_client: ...performing
V (18262) modem_client: ...performing
V (18772) modem_client: ...performing
V (19282) modem_client: ...performing
V (19792) modem_client: ...performing
V (20302) modem_client: ...performing
V (20812) modem_client: ...performing
V (21322) modem_client: ...performing
V (21832) modem_client: ...performing
D (21912) mqtt_client: Reconnecting...
D (21912) event: running post MQTT_EVENTS:7 with handler 0x4200a440 and context 0x3fca1a74 on loop 0x3fca1144
D (21912) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=7
I (21922) modem_client: MQTT other event id: 7
D (21922) esp-tls: host:137.135.83.217: strlen 14
D (21932) esp-tls: [sock=55] Resolved IPv4 address: 137.135.83.217
D (21932) esp-tls: [sock=55] Connecting to server. HOST: 137.135.83.217, Port: 8883
E (21942) esp-tls: [sock=55] connect() error: Host is unreachable
E (21952) esp-tls: Failed to open new connection
E (21952) transport_base: Failed to open a new connection
E (21962) mqtt_client: Error transport connect
D (21962) event: running post MQTT_EVENTS:0 with handler 0x4200a440 and context 0x3fca1a74 on loop 0x3fca1144
D (21972) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=0
I (21982) modem_client: MQTT_EVENT_ERROR
D (21992) mqtt_client: Reconnect after 10000 ms
D (21992) event: running post MQTT_EVENTS:2 with handler 0x4200a440 and context 0x3fca1a74 on loop 0x3fca1144
D (22002) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=2
I (22012) modem_client: MQTT_EVENT_DISCONNECTED
V (22342) modem_client: ...performing
V (22852) modem_client: ...performing
V (23362) modem_client: ...performing
V (23872) modem_client: ...performing
V (24382) modem_client: ...performing
V (24892) modem_client: ...performing
V (25402) modem_client: ...performing
V (25912) modem_client: ...performing
V (26422) modem_client: ...performing
V (26932) modem_client: ...performing
V (27442) modem_client: ...performing
V (27952) modem_client: ...performing
V (28462) modem_client: ...performing
V (28972) modem_client: ...performing
V (29482) modem_client: ...performing
V (29992) modem_client: ...performing
V (30502) modem_client: ...performing
V (31012) modem_client: ...performing
V (31522) modem_client: ...performing

D (32012) mqtt_client: Reconnecting...
D (32012) event: running post MQTT_EVENTS:7 with handler 0x4200a440 and context 0x3fca1a74 on loop 0x3fca1144
D (32012) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=7
I (32022) modem_client: MQTT other event id: 7
D (32022) esp-tls: host:137.135.83.217: strlen 14
D (32032) esp-tls: [sock=55] Resolved IPv4 address: 137.135.83.217
D (32032) esp-tls: [sock=55] Connecting to server. HOST: 137.135.83.217, Port: 8883
E (32042) esp-tls: [sock=55] connect() error: Host is unreachable
E (32052) esp-tls: Failed to open new connection
E (32052) transport_base: Failed to open a new connection
E (32062) mqtt_client: Error transport connect
D (32062) event: running post MQTT_EVENTS:0 with handler 0x4200a440 and context 0x3fca1a74 on loop 0x3fca1144
D (32072) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=0
I (32082) modem_client: MQTT_EVENT_ERROR
D (32092) mqtt_client: Reconnect after 10000 ms
D (32092) event: running post MQTT_EVENTS:2 with handler 0x4200a440 and context 0x3fca1a74 on loop 0x3fca1144
D (32102) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=2
I (32112) modem_client: MQTT_EVENT_DISCONNECTED
V (32112) modem_client: ...performing
V (32632) modem_client: ...performing
V (33142) modem_client: ...performing
V (33652) modem_client: ...performing
V (34162) modem_client: ...performing
V (34672) modem_client: ...performing
V (35182) modem_client: ...performing

[david-cermak]

loop back URL address to correct ip as shown below.

Need to keep the loopback address here. Update the BROKER_URL only, please

(I'll move it to Kconfig option to make it clear)
if you need the mqtts, just change the scheme:

esp-protocols/components/esp_modem/examples/modem_tcp_client/main/modem_client.cpp

Line 120 in 6c7259f

mqtt_config.broker.address.uri = "mqtt://" BROKER_URL;

---

TL;DR;

In the default config (CONFIG_EXAMPLE_CUSTOM_TCP_TRANSPORT=n), we have the MQTT client (or any other protocol library) to connect to the lwip's localhost address. That way, we're able to connect to this localhost internally and retransmit everything using AT commands.

The other config (CONFIG_EXAMPLE_CUSTOM_TCP_TRANSPORT=y) uses custom tcp_transport, where we let the MQTT client connect directly to the endpoint, injecting custom transport that would also resend everything using AT commands. This config is not fully supported, as it needs this mqtt commit which hasn't been integrated into IDF, yet.

[msivanesancq]

Hi David, thank you for the response and I will test this soon and get back to you shortly.
But I have an extra question which is, I would like to use esp-tls with digital signing for having tls communication over esp-modem.
Can you please confirm this usage of esp-tls with esp-modem? Thank you

[david-cermak]

Using esp-tls should work normally with esp_modem, especially when the library creates a dedicated network interface (pp0). This is the case for all the examples, except for this one: modem_tcp_client, which is using AT commands to connect to network.
(but that should work too, in the default config. It won't work with custom transport though, since the tcp_transport component sits on top of esp-tls)

[msivanesancq]

Using esp-tls should work normally with esp_modem, especially when the library creates a dedicated network interface (pp0). This is the case for all the examples, except for this one: modem_tcp_client, which is using AT commands to connect to network. (but that should work too, in the default config. It won't work with custom transport though, since the tcp_transport component sits on top of esp-tls)

I tried the example from here : https://github.com/david-cermak/esp-protocols/tree/master/components/esp_modem/examples/modem_tcp_client
But it is not working the basic MQTT publish. See the log below.
I (372) app_start: Starting scheduler on CPU0
I (377) app_start: Starting scheduler on CPU1
I (377) main_task: Started on CPU0
I (387) main_task: Calling app_main()
I (387) uart: queue free spaces: 30
I (1077) sock_dce: Got IP +IPADDR: 10.223.166.7
I (1087) sock_dce: Socket created
I (1087) sock_dce: Socket bound, port 1883
I (1087) modem_client: MQTT other event id: 7
E (1097) esp-tls-mbedtls: No server verification option set in esp_tls_cfg_t structure. Check esp_tls API reference
E (1097) esp-tls-mbedtls: Failed to set client configurations, returned [0x8017] (ESP_ERR_MBEDTLS_SSL_SETUP_FAILED)
E (1117) esp-tls: create_ssl_handle failed
E (1117) esp-tls: Failed to open new connection
E (1127) transport_base: Failed to open a new connection
E (1127) mqtt_client: Error transport connect
I (1137) modem_client: MQTT_EVENT_ERROR
I (1137) modem_client: MQTT_EVENT_DISCONNECTED
E (2387) sock_dce: Failed to get idle
E (2487) modem_client: Loop exit.. retrying
I (11147) modem_client: MQTT other event id: 7
E (11147) esp-tls-mbedtls: No server verification option set in esp_tls_cfg_t structure. Check esp_tls API reference
E (11147) esp-tls-mbedtls: Failed to set client configurations, returned [0x8017] (ESP_ERR_MBEDTLS_SSL_SETUP_FAILED)
E (11157) esp-tls: create_ssl_handle failed
E (11167) esp-tls: Failed to open new connection
E (11167) transport_base: Failed to open a new connection
E (11177) mqtt_client: Error transport connect
I (11177) modem_client: MQTT_EVENT_ERROR
I (11187) modem_client: MQTT_EVENT_DISCONNECTED
I (26187) modem_client: MQTT other event id: 7
E (33477) sock_dce: Failed obtain an IP address
E (33477) modem_client: Failed to reinit network
I (33477) main_task: Returned from app_main()
E (36197) esp-tls: [sock=55] select() timeout
E (36197) esp-tls: Failed to open new connection
E (36197) transport_base: Failed to open a new connection
E (36197) mqtt_client: Error transport connect
I (36207) modem_client: MQTT_EVENT_ERROR
I (36207) modem_client: MQTT_EVENT_DISCONNECTED
I (46217) modem_client: MQTT other event id: 7
E (56227) esp-tls: [sock=55] select() timeout
E (56227) esp-tls: Failed to open new connection
E (56227) transport_base: Failed to open a new connection
E (56227) mqtt_client: Error transport connect
I (56237) modem_client: MQTT_EVENT_ERROR
I (56237) modem_client: MQTT_EVENT_DISCONNECTED
I (66247) modem_client: MQTT other event id: 7
E (76257) esp-tls: [sock=55] select() timeout
E (76257) esp-tls: Failed to open new connection
E (76257) transport_base: Failed to open a new connection
E (76257) mqtt_client: Error transport connect
I (76267) modem_client: MQTT_EVENT_ERROR
I (76267) modem_client: MQTT_EVENT_DISCONNECTED
I (86277) modem_client: MQTT other event id: 7
E (96287) esp-tls: [sock=55] select() timeout
E (96287) esp-tls: Failed to open new connection
E (96287) transport_base: Failed to open a new connection
E (96287) mqtt_client: Error transport connect
I (96297) modem_client: MQTT_EVENT_ERROR
I (96297) modem_client: MQTT_EVENT_DISCONNECTED
I (106307) modem_client: MQTT other event id: 7
E (116317) esp-tls: [sock=55] select() timeout
E (116317) esp-tls: Failed to open new connection
E (116317) transport_base: Failed to open a new connection
E (116317) mqtt_client: Error transport connect
I (116327) modem_client: MQTT_EVENT_ERROR
I (116327) modem_client: MQTT_EVENT_DISCONNECTED
I (126337) modem_client: MQTT other event id: 7
E (136347) esp-tls: [sock=55] select() timeout
E (136347) esp-tls: Failed to open new connection
E (136347) transport_base: Failed to open a new connection

[msivanesancq]

Also the latest esp-protocol(https://github.com/espressif/esp-protocols/tree/master/components/esp_modem/examples/modem_tcp_client) is giving below failure:

`I (817) app_start: Starting scheduler on CPU0
V (822) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (822) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x402
D (822) intr_alloc: Connected src 57 to int 12 (cpu 0)
V (822) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (832) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E
D (832) intr_alloc: Connected src 80 to int 2 (cpu 1)
I (842) app_start: Starting scheduler on CPU1
V (842) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (852) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x402
D (862) intr_alloc: Connected src 58 to int 3 (cpu 1)
I (822) main_task: Started on CPU0
D (872) heap_init: New heap initialised at 0x3fce9710
V (872) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (882) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (892) intr_alloc: Connected src 52 to int 13 (cpu 0)
I (892) main_task: Calling app_main()
D (902) esp_netif_lwip: LwIP stack has been initialized
D (902) esp_netif_lwip: esp-netif has been successfully initialized
D (912) event: running task for loop 0x3fca1fe4
D (912) event: created task for loop 0x3fca1fe4
D (922) event: created event loop 0x3fca1fe4
I (922) uart: queue free spaces: 30
V (932) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (932) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (942) intr_alloc: Connected src 28 to int 17 (cpu 0)
V (952) command_lib: sync
V (952) command_lib: generic_command_common
V (952) command_lib: generic_command
D (962) command_lib: generic_command command AT

V (2462) command_lib: sync
V (2462) command_lib: generic_command_common
V (2462) command_lib: generic_command
D (2462) command_lib: generic_command command AT

V (3962) command_lib: sync
V (3962) command_lib: generic_command_common
V (3962) command_lib: generic_command
D (3962) command_lib: generic_command command AT

V (5462) command_lib: sync
V (5462) command_lib: generic_command_common
V (5462) command_lib: generic_command
D (5462) command_lib: generic_command command AT

V (6962) command_lib: sync
V (6962) command_lib: generic_command_common
V (6962) command_lib: generic_command
D (6962) command_lib: generic_command command AT

V (8462) command_lib: sync
V (8462) command_lib: generic_command_common
V (8462) command_lib: generic_command
D (8462) command_lib: generic_command command AT

V (9962) command_lib: sync
V (9962) command_lib: generic_command_common
V (9962) command_lib: generic_command
D (9962) command_lib: generic_command command AT

E (10462) sock_dce: Failed to sync up
E (10462) modem_client: Failed to setup network
V (10462) intr_alloc: esp_intr_free: Disabling int, killing handler
I (10462) main_task: Returned from app_main()`

[david-cermak]

E (1097) esp-tls-mbedtls: No server verification option set in esp_tls_cfg_t structure. Check esp_tls API reference

You'll have to configure server's certificate or enable:

CONFIG_ESP_TLS_INSECURE=y
CONFIG_ESP_TLS_SKIP_SERVER_CERT_VERIFY=y

in esp-tls to allow for TLS handshake without verification (only for testing)

The second error just tells you, that the modem doesn't respond to the initial AT commands -- check wires, restart modem, etc...

I'd suggest starting with a simple example first, e.g. with pppos_client and after you're familiar with this library, IDF and connection to your device you can get back to this example.

[msivanesancq]

Hi,
Please refer the log output after enabling insecure ESP-TLS:
`I (818) app_start: Starting scheduler on CPU0
V (823) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (823) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x402
D (823) intr_alloc: Connected src 57 to int 12 (cpu 0)
V (823) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (833) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E
D (833) intr_alloc: Connected src 80 to int 2 (cpu 1)
I (843) app_start: Starting scheduler on CPU1
V (843) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (853) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x402
D (863) intr_alloc: Connected src 58 to int 3 (cpu 1)
I (823) main_task: Started on CPU0
D (873) heap_init: New heap initialised at 0x3fce9710
V (873) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (883) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (893) intr_alloc: Connected src 52 to int 13 (cpu 0)
I (893) main_task: Calling app_main()
D (903) esp_netif_lwip: LwIP stack has been initialized
D (903) esp_netif_lwip: esp-netif has been successfully initialized
D (913) event: running task for loop 0x3fca0a84
D (913) event: created task for loop 0x3fca0a84
D (923) event: created event loop 0x3fca0a84
I (923) uart: queue free spaces: 30
V (933) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (933) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (943) intr_alloc: Connected src 28 to int 17 (cpu 0)
V (953) command_lib: sync
V (953) command_lib: generic_command_common
V (953) command_lib: generic_command
D (963) command_lib: generic_command command AT

D (1063) command_lib: Response:

OK

D (1063) sock_dce: Modem in sync
V (1063) command_lib: set_echo
V (1063) command_lib: generic_command_common
V (1063) command_lib: generic_command
D (1073) command_lib: generic_command command ATE0

D (1173) command_lib: Response:

OK

V (1173) command_lib: set_pdp_context
V (1173) command_lib: generic_command_common
V (1173) command_lib: generic_command
D (1173) command_lib: generic_command command AT+CGDCONT=1,"IP","iot.1nce.net"

D (1313) command_lib: Response:

OK

D (1313) sock_dce: PDP configured
V (1313) sock_commands: net_open
V (1313) command_lib: generic_get_string
V (1313) command_lib: generic_get_string
V (1423) command_lib: Token: {
}

V (1423) command_lib: Token: {+NETOPEN: 1}

V (1423) command_lib: Token: {
}

V (1423) command_lib: Token: {OK}

V (1423) sock_commands: +NETOPEN: 1
D (1433) sock_commands: Already there
V (1433) command_lib: generic_command
D (1433) command_lib: generic_command command AT+CIPRXGET=1

D (1533) command_lib: Response:

OK

D (1533) sock_dce: Network opened
V (1533) command_lib: generic_get_string
V (1533) command_lib: generic_get_string
V (1643) command_lib: Token: {
}

V (1643) command_lib: Token: {+IPADDR: 10.223.166.7}

V (1643) command_lib: Token: {
}

V (1643) command_lib: Token: {OK}

I (1653) sock_dce: Got IP +IPADDR: 10.223.166.7
I (1653) sock_dce: Socket created
I (1663) sock_dce: Socket bound, port 1883
D (1663) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (1673) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (1683) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (1683) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (1693) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (1703) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (1703) mqtt_client: MQTT client_id=ESP32_66AD88
D (1713) event: created event loop 0x3fca4400
D (1713) mqtt_client: Core selection disabled
D (1723) event: running post MQTT_EVENTS:7 with handler 0x42009ebc and context 0x3fca4d40 on loop 0x3fca4400
D (1733) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=7
I (1743) modem_client: MQTT other event id: 7
D (1743) esp-tls: host:mqtt.eclipseprojects.io: strlen 23
E (1753) esp-tls: couldn't get hostname for :mqtt.eclipseprojects.io: getaddrinfo() returns 202, addrinfo=0x0
E (1763) esp-tls: Failed to open new connection
E (1763) transport_base: Failed to open a new connection
E (1773) mqtt_client: Error transport connect
D (1773) event: running post MQTT_EVENTS:0 with handler 0x42009ebc and context 0x3fca4d40 on loop 0x3fca4400
D (1783) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=0
I (1793) modem_client: MQTT_EVENT_ERROR
D (1803) mqtt_client: Reconnect after 10000 ms
D (1803) event: running post MQTT_EVENTS:2 with handler 0x42009ebc and context 0x3fca4d40 on loop 0x3fca4400
D (1813) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=2
I (1823) modem_client: MQTT_EVENT_DISCONNECTED
V (1823) sock_commands: tcp_close
V (1833) command_lib: generic_command
D (1833) command_lib: generic_command command AT+CIPCLOSE=0

D (1863) command_lib: Response:

+CIPCLOSE: 0,4

ERROR

V (1963) partition: Loading the partition table
V (1963) mmap: actual_mapped_len is 0x10000
V (1963) calculated md5: 0x3fc9e1e8 f4 ad 4f 45 38 56 4b 5d 74 35 b6 2c 75 b6 95 24 |..OE8VK]t5.,u..$|
V (1963) stored md5: 0x3c0a8070 f4 ad 4f 45 38 56 4b 5d 74 35 b6 2c 75 b6 95 24 |..OE8VK]t5.,u..$|
V (1973) partition: Partition table MD5 verified
V (1983) sock_dce: 0x3fca37fc 0d 0a 4f 4b 0d 0a |..OK..|
D (1993) sock_commands: response

OK

D (2013) nvs: nvs_open_from_partition ql_storage 0
D (2013) nvs: nvs_get_str_or_blob /.ql/esk.pem
D (2013) nvs: nvs_close 1

1. FFFFFFFFFFFFFFFF
2. FFFFFFFFFFFFFFFF
3. mbedtls_pk_get_type = 2
   D (2023) gdma: new group (0) at 0x3fca7250
   D (2023) gdma: new pair (0,0) at 0x3fca70b8
   D (2033) gdma: new tx channel (0,0) at 0x3fca71b4
   D (2033) gdma: new rx channel (0,0) at 0x3fca7294
   D (2043) gdma: tx channel (0,0), (1:32) bytes aligned, burst enabled
   D (2043) gdma: rx channel (0,0), (1:32) bytes aligned, burst disabled
   D (2053) nvs: nvs_open_from_partition ql_storage 0
   D (2053) nvs: nvs_get_str_or_blob /.ql/dsk.pem
   D (2063) nvs: nvs_close 2
   [E][./components/quarklink-client/src/platform_specific/esp32idf.c:141] ql_nvm_read(): File: /.ql/dsk.pem does not exist
   Device ID = 3fc8435dbfe40b2bebcb04749146fdd623fdff46ba3e2e8efe84c3e9a6108829
   V (2373) sock_dce: 0x3fca37fc 0d 0a 2b 43 49 50 4f 50 45 4e 3a 20 30 2c 30 0d |..+CIPOPEN: 0,0.|
   V (2373) sock_dce: 0x3fca380c 0a |.|
   D (2383) sock_commands: response

+CIPOPEN: 0,0

I (2393) sock_commands: Connected!
V (2593) modem_client: ...performing
V (3103) modem_client: ...performing
V (3613) modem_client: ...performing
V (4123) modem_client: ...performing
V (4633) modem_client: ...performing
V (5143) modem_client: ...performing
V (5653) modem_client: ...performing
V (6163) modem_client: ...performing
V (6673) modem_client: ...performing
V (7183) modem_client: ...performing
V (7693) modem_client: ...performing
V (8203) modem_client: ...performing
V (8713) modem_client: ...performing
V (9223) modem_client: ...performing
V (9733) modem_client: ...performing
V (10243) modem_client: ...performing
V (10753) modem_client: ...performing
V (11263) modem_client: ...performing
V (11773) modem_client: ...performing
D (11823) mqtt_client: Reconnecting...
D (11823) event: running post MQTT_EVENTS:7 with handler 0x42009ebc and context 0x3fca4d40 on loop 0x3fca4400
D (11823) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=7
I (11833) modem_client: MQTT other event id: 7
D (11833) esp-tls: host:mqtt.eclipseprojects.io: strlen 23
E (11843) esp-tls: couldn't get hostname for :mqtt.eclipseprojects.io: getaddrinfo() returns 202, addrinfo=0x0
E (11853) esp-tls: Failed to open new connection
E (11853) transport_base: Failed to open a new connection
E (11863) mqtt_client: Error transport connect
D (11863) event: running post MQTT_EVENTS:0 with handler 0x42009ebc and context 0x3fca4d40 on loop 0x3fca4400
D (11873) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=0
I (11883) modem_client: MQTT_EVENT_ERROR
D (11893) mqtt_client: Reconnect after 10000 ms
D (11893) event: running post MQTT_EVENTS:2 with handler 0x42009ebc and context 0x3fca4d40 on loop 0x3fca4400
D (11903) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=2
I (11913) modem_client: MQTT_EVENT_DISCONNECTED
V (12283) modem_client: ...performing
V (12793) modem_client: ...performing
V (13303) modem_client: ...performing
V (13813) modem_client: ...performing
V (14323) modem_client: ...performing
V (14833) modem_client: ...performing
V (15343) modem_client: ...performing
V (15853) modem_client: ...performing
V (16363) modem_client: ...performing
V (16873) modem_client: ...performing
V (17383) modem_client: ...performing
V (17893) modem_client: ...performing
V (18403) modem_client: ...performing
V (18913) modem_client: ...performing
V (19423) modem_client: ...performing
V (19933) modem_client: ...performing
V (20443) modem_client: ...performing
V (20953) modem_client: ...performing
V (21463) modem_client: ...performing
D (21913) mqtt_client: Reconnecting...
D (21913) event: running post MQTT_EVENTS:7 with handler 0x42009ebc and context 0x3fca4d40 on loop 0x3fca4400
D (21913) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=7
I (21923) modem_client: MQTT other event id: 7
D (21923) esp-tls: host:mqtt.eclipseprojects.io: strlen 23
E (21933) esp-tls: couldn't get hostname for :mqtt.eclipseprojects.io: getaddrinfo() returns 202, addrinfo=0x0
E (21943) esp-tls: Failed to open new connection
E (21943) transport_base: Failed to open a new connection
E (21953) mqtt_client: Error transport connect
D (21953) event: running post MQTT_EVENTS:0 with handler 0x42009ebc and context 0x3fca4d40 on loop 0x3fca4400
D (21963) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=0
I (21973) modem_client: MQTT_EVENT_ERROR
D (21983) mqtt_client: Reconnect after 10000 ms
D (21983) event: running post MQTT_EVENTS:2 with handler 0x42009ebc and context 0x3fca4d40 on loop 0x3fca4400
D (21993) modem_client: Event dispatched from event loop base=MQTT_EVENTS, event_id=2
I (22003) modem_client: MQTT_EVENT_DISCONNECTED
V (22003) modem_client: ...performing
V (22523) modem_client: ...performing
V (23033) modem_client: ...performing
V (23543) modem_client: ...performing
V (24053) modem_client: ...performing
V (24563) modem_client: ...performing
V (25073) modem_client: ...performing
V (25583) modem_client: ...performing
V (26093) modem_client: ...performing
V (26603) modem_client: ...performing
V (27113) modem_client: ...performing
V (27623) modem_client: ...performing
V (28133) modem_client: ...performing
V (28643) modem_client: ...performing
V (29153) modem_client: ...performing
V (29663) modem_client: ...performing
V (30173) modem_client: ...performing
V (30683) modem_client: ...performing
V (31193) modem_client: ...performing
V (31703) modem_client: ...performing`

Regarding the modem is not responsive issue, I dont suspect that on HW side issue as it is working with other program. It is only failing with latest esp-modem library. I will debug further and update if I find something new.

[msivanesancq]

Hi regarding the AT OK issue I debugged with oscilloscope and saw the the signal back and forth in the UART. Any idea to solve this proble?

By the way I tested the pppos_client example and it is working as expected.
I (253) cpu_start: Multicore app
I (254) cpu_start: Pro cpu up.
I (254) cpu_start: Starting app cpu, entry point is 0x403754f4
I (0) cpu_start: App cpu up.
I (272) cpu_start: Pro cpu start user code
I (272) cpu_start: cpu freq: 160000000 Hz
I (272) cpu_start: Application information:
I (275) cpu_start: Project name: pppos_client
I (280) cpu_start: App version: mdns-v1.2.1-dirty
I (286) cpu_start: Compile time: Sep 12 2023 14:09:09
I (292) cpu_start: ELF file SHA256: 84bada24db5893f6...
I (298) cpu_start: ESP-IDF: v5.1-rc1-36-g4bc762621d-dirty
I (305) cpu_start: Min chip rev: v0.0
I (310) cpu_start: Max chip rev: v0.99
I (315) cpu_start: Chip rev: v0.2
I (319) heap_init: Initializing. RAM available for dynamic allocation:
I (327) heap_init: At 3FC9C128 len 0004D5E8 (309 KiB): DRAM
I (333) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (339) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (346) heap_init: At 600FE010 len 00001FF0 (7 KiB): RTCRAM
I (353) spi_flash: detected chip: generic
I (357) spi_flash: flash io: dio
W (360) spi_flash: Detected size(16384k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (374) sleep: Configure to isolate all GPIO pins in sleep state
I (381) sleep: Enable automatic switching of GPIO sleep configuration
I (388) app_start: Starting scheduler on CPU0
I (393) app_start: Starting scheduler on CPU1
I (393) main_task: Started on CPU0
I (403) main_task: Calling app_main()
I (413) pppos_example: Initializing esp_modem for the SIM7600 module...
I (413) uart: queue free spaces: 30
I (433) pppos_example: Signal quality: rssi=27, ber=99
I (513) pppos_example: Waiting for IP address
I (603) pppos_example: Modem Connect to PPP Server
I (603) pppos_example: ~~~~~~~~~~~~~~
I (603) pppos_example: IP : 10.223.166.7
I (613) pppos_example: Netmask : 255.255.255.255
I (613) esp-netif_lwip-ppp: Connected
I (613) pppos_example: Gateway : 10.64.64.64
I (623) pppos_example: Name Server1: 8.8.8.8
I (633) pppos_example: Name Server2: 8.8.4.4
I (633) pppos_example: ~~~~~~~~~~~~~~
I (643) pppos_example: GOT ip event!!!
I (643) pppos_example: PPP state changed event 0
I (653) pppos_example: MQTT other event id: 7
I (653) pppos_example: Waiting for MQTT data
I (1343) pppos_example: MQTT_EVENT_CONNECTED
I (1353) pppos_example: sent subscribe successful, msg_id=54097
I (1533) pppos_example: MQTT_EVENT_SUBSCRIBED, msg_id=54097
I (1533) pppos_example: sent publish successful, msg_id=0
I (1713) pppos_example: MQTT_EVENT_DATA
TOPIC=/topic/esp-pppos

DATA=esp32-pppos

I (1903) esp-netif_lwip-ppp: User interrupt
I (1903) pppos_example: PPP state changed event 5
I (1903) pppos_example: User interrupted event from netif:0x3fca8ddc
I (1913) esp_modem_netif: PPP state changed event 5
I (3083) pppos_example: IMSI=901405103839798

But when I try to call esp-tls it is failing and throwing the error below:
E (3223) esp-tls: couldn't get hostname for :cqtest.quarklink.io: getaddrinfo() returns 202, addrinfo=0x0
E (3233) esp-tls: Failed to open new connection

[msivanesancq]

Hi all, I think there is a bug on this function(file: esp_modem_dte.cpp) which does not have primary_term->read(buffer.data.get(), buffer.size - buffer.consumed); Can you please correct this?
And returning command_cb.result; also seems wrong.
command_result DTE::command(const std::string &command, got_line_cb got_line, uint32_t time_ms, const char separator)
{
Scoped l1(internal_lock);
command_cb.set(got_line, separator);
primary_term->write((uint8_t *)command.c_str(), command.length());
command_cb.wait_for_line(time_ms);
command_cb.set(nullptr);
primary_term->read(buffer.data.get(), buffer.size - buffer.consumed);
buffer.consumed = 0;
#ifdef CONFIG_ESP_MODEM_USE_INFLATABLE_BUFFER_IF_NEEDED
inflatable.deflate();
#endif
return command_cb.result;
}

[msivanesancq]

I think there are 2 more issues on the function command_result DTE::command(const std::string &command, got_line_cb got_line, uint32_t time_ms, const char separator).

1. return command_cb.result; is not correct. It must return based on buffer result.
2. command_cb.wait_for_line(time_ms); This line makes the delay for all the time regardless of the reception of the response. Fos ex: set_pdp_context() has a delay of 150000 and it is introducing 150000msec of delay even the response is being received.

I modified the function as below:

command_result DTE::command(const std::string &command, got_line_cb got_line, uint32_t time_ms, const char separator)
{
Scoped l1(internal_lock);
command_cb.set(got_line, separator);
primary_term->write((uint8_t )command.c_str(), command.length());
command_cb.wait_for_line(time_ms);
command_cb.set(nullptr);
primary_term->read(buffer.data.get(), buffer.size - buffer.consumed);
printf("%s\n", (char)buffer.data.get());
buffer.consumed = 0;
#ifdef CONFIG_ESP_MODEM_USE_INFLATABLE_BUFFER_IF_NEEDED
inflatable.deflate();
#endif
return command_result::OK;//command_cb.result;
}

Then now I am getting below output. Basically net_open() is failing. Any idea to solve this?

I (813) main_task: Started on CPU0
D (863) heap_init: New heap initialised at 0x3fce9710
V (863) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (873) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (883) intr_alloc: Connected src 52 to int 13 (cpu 0)
I (883) main_task: Calling app_main()
D (893) esp_netif_lwip: LwIP stack has been initialized
D (893) esp_netif_lwip: esp-netif has been successfully initialized
D (903) event: running task for loop 0x3fc9d834
D (903) event: created task for loop 0x3fc9d834
D (913) event: created event loop 0x3fc9d834
I (913) uart: queue free spaces: 30
V (923) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (923) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (933) intr_alloc: Connected src 28 to int 17 (cpu 0)
V (943) command_lib: sync
V (943) command_lib: generic_command_common
V (943) command_lib: generic_command
D (953) command_lib: generic_command command AT

AT

OK

D (1453) sock_dce: Modem in sync
V (1453) command_lib: set_echo
V (1453) command_lib: generic_command_common
V (1453) command_lib: generic_command
D (1453) command_lib: generic_command command ATE0

ATE0

OK

V (1953) command_lib: set_pdp_context
V (1953) command_lib: generic_command_common
V (1953) command_lib: generic_command
D (1953) command_lib: generic_command command AT+CGDCONT=1,"IP","iot.1nce.net"

OK

OK

D (3453) sock_dce: PDP configured
V (3453) sock_commands: net_open
V (3453) command_lib: generic_get_string
V (3453) command_lib: generic_get_string

+NETOPEN: 0

OK

V (4453) sock_commands:
V (4453) sock_commands: net_close
V (4453) command_lib: generic_command
D (4453) command_lib: generic_command command AT+NETCLOSE

+NETCLOSE: 2

ERROR

V (35453) sock_commands: net_open
V (35453) command_lib: generic_get_string
V (35453) command_lib: generic_get_string

+NETOPEN: 0

OK

OR

V (36453) sock_commands:
V (36453) sock_commands: net_close
V (36453) command_lib: generic_command
D (36453) command_lib: generic_command command AT+NETCLOSE

+NETCLOSE: 2

ERROR

V (67453) sock_commands: net_open
V (67453) command_lib: generic_get_string
V (67453) command_lib: generic_get_string

+NETOPEN: 0

OK

OR

V (68453) sock_commands:
V (68453) sock_commands: net_close
V (68453) command_lib: generic_command
D (68453) command_lib: generic_command command AT+NETCLOSE

+NETCLOSE: 2

ERROR

V (99453) sock_commands: net_open
V (99453) command_lib: generic_get_string
V (99453) command_lib: generic_get_string

+NETOPEN: 0

OK

OR

V (100453) sock_commands:
V (100453) sock_commands: net_close
V (100453) command_lib: generic_command
D (100453) command_lib: generic_command command AT+NETCLOSE

+NETCLOSE: 2

ERROR

V (131453) sock_commands: net_open
V (131453) command_lib: generic_get_string
V (131453) command_lib: generic_get_string

+NETOPEN: 0

OK

OR

V (132453) sock_commands:
V (132453) sock_commands: net_close
V (132453) command_lib: generic_command
D (132453) command_lib: generic_command command AT+NETCLOSE

+NETCLOSE: 2

ERROR

V (163453) sock_commands: net_open
V (163453) command_lib: generic_get_string
V (163453) command_lib: generic_get_string

+NETOPEN: 0

OK

OR

V (164453) sock_commands:
V (164453) sock_commands: net_close
V (164453) command_lib: generic_command
D (164453) command_lib: generic_command command AT+NETCLOSE

+NETCLOSE: 2

ERROR

V (195453) sock_commands: net_open
V (195453) command_lib: generic_get_string
V (195453) command_lib: generic_get_string

+NETOPEN: 0

OK

OR

V (196453) sock_commands:
E (196453) sock_dce: Failed to open network
E (196453) modem_client: Failed to setup network
V (196453) intr_alloc: esp_intr_free: Disabling int, killing handler
I (196463) main_task: Returned from app_main()

[msivanesancq]

Any updates on this?

[david-cermak]

There's indeed a bug, introduced by the recent modem refactors. It's missing a callback reset upon removal of our custom AT command processing in this example:
A quick fix is to:

--- a/components/esp_modem/src/esp_modem_dte.cpp
+++ b/components/esp_modem/src/esp_modem_dte.cpp
@@ -313,6 +313,7 @@ void DTE::on_read(got_line_cb on_read_cb)
     if (on_read_cb == nullptr) {
         primary_term->set_read_cb(nullptr);
         internal_lock.unlock();
+        set_command_callbacks();
         return;
     }
     internal_lock.lock();

It's also possible to fix it in the example, directly by calling set_read_cb() instead:

--- a/components/esp_modem/examples/modem_tcp_client/main/sock_dce.cpp
+++ b/components/esp_modem/examples/modem_tcp_client/main/sock_dce.cpp
@@ -104,7 +104,7 @@ void DCE::close_sock()
         close(sock);
         sock = -1;
     }
-    dte->on_read(nullptr);
+    dte->set_read_cb(nullptr);
     const int retries = 5;
     int i = 0;
     while (net_close() != esp_modem::command_result::OK) {
@@ -224,15 +224,15 @@ void DCE::start_listening(int port)
 
 bool DCE::connect(std::string host, int port)
 {
-    dte->on_read(nullptr);
+    dte->set_read_cb(nullptr);
     tcp_close();
-    dte->on_read([this](uint8_t *data, size_t len) {
+    dte->set_read_cb([this](uint8_t *data, size_t len) {
         this->perform_at(data, len);
-        return esp_modem::command_result::TIMEOUT;
+        return true;
     });
     if (!at.start_connecting(host, port)) {
         ESP_LOGE(TAG, "Unable to start connecting");
-        dte->on_read(nullptr);
+        dte->set_read_cb(nullptr);
         return false;
     }
     state = status::CONNECTING;
@@ -247,7 +247,7 @@ bool DCE::init()
     data_ready_fd = eventfd(0, EFD_SUPPORT_ISR);
     assert(data_ready_fd > 0);
 
-    dte->on_read(nullptr);
+    dte->set_read_cb(nullptr);
     const int retries = 5;
     int i = 0;
     while (sync() != esp_modem::command_result::OK) {

Sorry for the inconvenience, this example is still a bit WIP (we don't run it in the CI).

I'll create a PR and add some docs to this example.