esp-netif_lwip-ppp: Connection lost, without event IP_EVENT_PPP_GOT_IP (IDFGH-13514)

ezamp commented 3 weeks ago

Answers checklist.

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

General issue report

I'm getting _esp-netiflwip-ppp: Connection lost on SIM7028 module. From the logs, the module responds to the AT commands but when I switch it to the data mode I can't get IP and after a while it displays IP event 7 (IP_EVENT_PPP_LOST_IP). The APN and other configurations seem correct, and on the sim provider's portal I see that the PDP context is created correctly.

Log:

I (26) boot: ESP-IDF v5.3-dirty 2nd stage bootloader
I (27) boot: compile time Aug 20 2024 13:52:01
I (27) boot: Multicore bootloader
I (30) boot: chip revision: v0.2
I (34) boot.esp32s3: Boot SPI Speed : 80MHz
I (39) boot.esp32s3: SPI Mode       : DIO
I (43) boot.esp32s3: SPI Flash Size : 2MB
I (48) boot: Enabling RNG early entropy source...
I (54) boot: Partition Table:
I (57) boot: ## Label            Usage          Type ST Offset   Length
I (64) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (72) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (79) boot:  2 factory          factory app      00 00 00010000 00100000
I (87) boot: End of partition table
I (91) esp_image: segment 0: paddr=00010020 vaddr=3c040020 size=129ech ( 76268) map
I (113) esp_image: segment 1: paddr=00022a14 vaddr=3fc91d00 size=028f0h ( 10480) load
I (116) esp_image: segment 2: paddr=0002530c vaddr=40374000 size=0ad0ch ( 44300) load
I (129) esp_image: segment 3: paddr=00030020 vaddr=42000020 size=3a470h (238704) map
I (172) esp_image: segment 4: paddr=0006a498 vaddr=4037ed0c size=02fd4h ( 12244) load
I (181) boot: Loaded app from partition at offset 0x10000
I (181) boot: Disabling RNG early entropy source...
I (193) cpu_start: Multicore app
D (193) cpu_start: Pro cpu up
D (193) cpu_start: Starting app cpu, entry point is 0x40375198
0x40375198: call_start_cpu1 at /Users/emanuele/esp/v5.3/esp-idf/components/esp_system/port/cpu_start.c:195

D (0) cpu_start: App cpu up
D (203) clk: RTC_SLOW_CLK calibration value: 3543539
D (214) cpu_start: calling init function: 0x42002798 on core: 0
0x42002798: __esp_system_init_fn_init_efuse_check at /Users/emanuele/esp/v5.3/esp-idf/components/efuse/src/esp_efuse_startup.c:31

D (214) cpu_start: calling init function: 0x420028a0 on core: 0
0x420028a0: __esp_system_init_fn_init_show_cpu_freq at /Users/emanuele/esp/v5.3/esp-idf/components/esp_system/startup_funcs.c:58

I (215) cpu_start: Pro cpu start user code
I (219) cpu_start: cpu freq: 160000000 Hz
D (224) cpu_start: calling init function: 0x420026b8 on core: 0
0x420026b8: __esp_system_init_fn_init_show_app_info at /Users/emanuele/esp/v5.3/esp-idf/components/esp_app_format/esp_app_desc.c:104

I (230) app_init: Application information:
I (235) app_init: Project name:     nbTest
I (240) app_init: App version:      1
I (244) app_init: Compile time:     Aug 20 2024 13:51:59
I (250) app_init: ELF file SHA256:  00850e25c...
I (255) app_init: ESP-IDF:          v5.3-dirty
D (260) cpu_start: calling init function: 0x420027ac on core: 0
0x420027ac: __esp_system_init_fn_init_efuse_show_app_info at /Users/emanuele/esp/v5.3/esp-idf/components/efuse/src/esp_efuse_startup.c:41

I (266) efuse_init: Min chip rev:     v0.0
I (271) efuse_init: Max chip rev:     v0.99 
I (276) efuse_init: Chip rev:         v0.2
D (281) cpu_start: calling init function: 0x42004144 on core: 0
0x42004144: __esp_system_init_fn_init_heap at /Users/emanuele/esp/v5.3/esp-idf/components/heap/heap_caps_init.c:25

D (287) memory_layout: Checking 6 reserved memory ranges:
D (292) memory_layout: Reserved memory range 0x3fc84000 - 0x3fc91d00
D (299) memory_layout: Reserved memory range 0x3fc91d00 - 0x3fc958b0
D (305) memory_layout: Reserved memory range 0x3fceee34 - 0x3fcf0000
D (312) memory_layout: Reserved memory range 0x40374000 - 0x40381d00
0x40374000: _WindowOverflow4 at /Users/emanuele/esp/v5.3/esp-idf/components/xtensa/xtensa_vectors.S:2027

D (318) memory_layout: Reserved memory range 0x600fe000 - 0x600fe100
D (324) memory_layout: Reserved memory range 0x600fffe8 - 0x60100000
D (331) memory_layout: Building list of available memory regions:
D (337) memory_layout: Available memory region 0x3fc958b0 - 0x3fca0000
D (344) memory_layout: Available memory region 0x3fca0000 - 0x3fcb0000
D (350) memory_layout: Available memory region 0x3fcb0000 - 0x3fcc0000
D (357) memory_layout: Available memory region 0x3fcc0000 - 0x3fcd0000
D (363) memory_layout: Available memory region 0x3fcd0000 - 0x3fce0000
D (370) memory_layout: Available memory region 0x3fce0000 - 0x3fce9710
D (377) memory_layout: Available memory region 0x3fce9710 - 0x3fceee34
D (383) memory_layout: Available memory region 0x3fcf0000 - 0x3fcf8000
D (390) memory_layout: Available memory region 0x600fe100 - 0x600fffe8
I (396) heap_init: Initializing. RAM available for dynamic allocation:
D (404) heap_init: New heap initialised at 0x3fc958b0
I (409) heap_init: At 3FC958B0 len 00053E60 (335 KiB): RAM
I (415) heap_init: At 3FCE9710 len 00005724 (21 KiB): RAM
D (421) heap_init: New heap initialised at 0x3fcf0000
I (426) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
D (432) heap_init: New heap initialised at 0x600fe100
I (437) heap_init: At 600FE100 len 00001EE8 (7 KiB): RTCRAM
D (444) cpu_start: calling init function: 0x420069f4 on core: 0
0x420069f4: __esp_system_init_fn_esp_timer_init_nonos at /Users/emanuele/esp/v5.3/esp-idf/components/esp_timer/src/esp_timer_init.c:27

D (450) cpu_start: calling init function: 0x420062e0 on core: 0
0x420062e0: __esp_system_init_fn_init_newlib at /Users/emanuele/esp/v5.3/esp-idf/components/newlib/newlib_init.c:162

D (456) cpu_start: calling init function: 0x420028e8 on core: 0
0x420028e8: __esp_system_init_fn_init_brownout at /Users/emanuele/esp/v5.3/esp-idf/components/esp_system/startup_funcs.c:67

D (462) intr_alloc: Connected src 39 to int 1 (cpu 0)
D (467) cpu_start: calling init function: 0x420028f4 on core: 0
0x420028f4: __esp_system_init_fn_init_newlib_time at /Users/emanuele/esp/v5.3/esp-idf/components/esp_system/startup_funcs.c:81

D (473) cpu_start: calling init function: 0x4200774c on core: 0
0x4200774c: __esp_system_init_fn_init_vfs_uart at /Users/emanuele/esp/v5.3/esp-idf/components/esp_driver_uart/src/uart_vfs.c:1080

D (479) cpu_start: calling init function: 0x42009c70 on core: 0
0x42009c70: __esp_system_init_fn_init_vfs_usj_sec at /Users/emanuele/esp/v5.3/esp-idf/components/esp_driver_usb_serial_jtag/src/usb_serial_jtag_vfs.c:404

D (485) cpu_start: calling init function: 0x42009fd0 on core: 0
0x42009fd0: __esp_system_init_fn_init_vfs_console at /Users/emanuele/esp/v5.3/esp-idf/components/esp_vfs_console/vfs_console.c:222

D (491) cpu_start: calling init function: 0x42006344 on core: 0
0x42006344: __esp_system_init_fn_init_newlib_stdio at /Users/emanuele/esp/v5.3/esp-idf/components/newlib/newlib_init.c:207

D (497) cpu_start: calling init function: 0x420066e4 on core: 0
0x420066e4: __esp_system_init_fn_init_pthread at /Users/emanuele/esp/v5.3/esp-idf/components/pthread/pthread.c:76

D (503) cpu_start: calling init function: 0x42002934 on core: 0
0x42002934: __esp_system_init_fn_init_flash at /Users/emanuele/esp/v5.3/esp-idf/components/esp_system/startup_funcs.c:88

D (509) spi_flash: trying chip: issi
D (512) spi_flash: trying chip: gd
I (516) spi_flash: detected chip: gd
I (520) spi_flash: flash io: dio
W (524) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
D (537) cpu_start: calling init function: 0x420373d0 on core: 0
0x420373d0: __esp_system_init_fn_init_efuse at /Users/emanuele/esp/v5.3/esp-idf/components/efuse/src/esp_efuse_startup.c:137

D (543) cpu_start: calling init function: 0x420293bc
0x420293bc: _GLOBAL__sub_I__ZN17__eh_globals_init7_S_initE at /Users/brnomac003/.gitlab-runner/builds/qR2TxTby/0/idf/crosstool-NG/.build/xtensa-esp-elf/src/gcc/libstdc++-v3/libsupc++/eh_globals.cc:162

D (548) cpu_start: calling init function: 0x4202916c
0x4202916c: _GLOBAL__sub_I__ZN9__gnu_cxx9__freeresEv at /Users/brnomac003/.gitlab-runner/builds/qR2TxTby/0/idf/crosstool-NG/.build/xtensa-esp-elf/src/gcc/libstdc++-v3/libsupc++/eh_alloc.cc:462

D (553) C++ init: Setting C++ exception emergency pool to 0.
D (559) cpu_start: calling init function: 0x40378e78
0x40378e78: enable_timer_group0_for_calibration at /Users/emanuele/esp/v5.3/esp-idf/components/esp_hw_support/port/esp32s3/rtc_time.c:199

D (564) cpu_start: calling init function: 0x42003a38
0x42003a38: esp_ipc_init at /Users/emanuele/esp/v5.3/esp-idf/components/esp_system/esp_ipc.c:113

D (569) cpu_start: calling init function: 0x42002d3c
0x42002d3c: esp_reset_reason_init at /Users/emanuele/esp/v5.3/esp-idf/components/esp_system/port/soc/esp32s3/reset_reason.c:63

D (574) cpu_start: calling init function: 0x42004d14 on core: 0
0x42004d14: __esp_system_init_fn_esp_sleep_startup_init at /Users/emanuele/esp/v5.3/esp-idf/components/esp_hw_support/sleep_gpio.c:185

I (580) sleep: Configure to isolate all GPIO pins in sleep state
I (587) sleep: Enable automatic switching of GPIO sleep configuration
D (594) cpu_start: calling init function: 0x42002900 on core: 0
0x42002900: __esp_system_init_fn_init_apb_dma at /Users/emanuele/esp/v5.3/esp-idf/components/esp_system/startup_funcs.c:125

D (600) cpu_start: calling init function: 0x42009ac4 on core: 0
0x42009ac4: __esp_system_init_fn_usb_serial_jtag_conn_status_init at /Users/emanuele/esp/v5.3/esp-idf/components/esp_driver_usb_serial_jtag/src/usb_serial_jtag_connection_monitor.c:75

D (606) cpu_start: calling init function: 0x4200290c on core: 0
0x4200290c: __esp_system_init_fn_init_disable_rtc_wdt at /Users/emanuele/esp/v5.3/esp-idf/components/esp_system/startup_funcs.c:143

D (612) intr_alloc: Connected src 79 to int 2 (cpu 0)
D (617) app_start: Starting scheduler on CPU0
D (621) intr_alloc: Connected src 57 to int 3 (cpu 0)
D (621) intr_alloc: Connected src 80 to int 0 (cpu 1)
D (631) app_start: Starting scheduler on CPU1
D (631) intr_alloc: Connected src 58 to int 1 (cpu 1)
I (621) main_task: Started on CPU0
D (641) heap_init: New heap initialised at 0x3fce9710
D (641) intr_alloc: Connected src 52 to int 5 (cpu 0)
I (651) main_task: Calling app_main()
I (651) test: Main started...
D (661) esp_netif_lwip: LwIP stack has been initialized
D (661) esp_netif_lwip: esp-netif has been successfully initialized
D (671) event: running task for loop 0x3fc9adec
D (671) event: created task for loop 0x3fc9adec
D (681) event: created event loop 0x3fc9adec
I (681) test: End setup
D (691) esp_netif_lwip: check: remote, if=0x3fc98364 fn=0x42013020
0x42013020: esp_netif_new_api at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:690

D (691) esp_netif_objects: esp_netif_add_to_list_unsafe netif added successfully (total netifs: 1)
D (701) esp-netif_lwip-ppp: esp_netif_new_ppp: PPP connection created: 0x3fc9bfc0
D (711) esp-netif_lwip-ppp: Phase Dead
D (711) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (721) test: Initializing esp_modem for the NB-IoT module...
I (721) uart: queue free spaces: 30
D (731) intr_alloc: Connected src 28 to int 8 (cpu 0)
I (741) test: Signal quality: rssi=26, ber=0
I (751) test: imsi=901405108749214
D (751) command_lib: generic_command command ATE0

D (751) command_lib: Response: 
OK

D (751) command_lib: generic_command command AT+CGDCONT=1,"IP","iot.1nce.net"

D (831) command_lib: Response: 
OK

D (831) esp_netif_handlers: esp_netif action has started with netif0x3fc9bd8c from event_id=0
D (831) esp_netif_lwip: check: remote, if=0x3fc9bd8c fn=0x420132b4
0x420132b4: esp_netif_start_api at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1068

D (841) esp_netif_lwip: esp_netif_start_api 0x3fc9bd8c
D (851) esp-netif_lwip-ppp: esp_netif_start_ppp: Starting PPP connection: 0x3fc9bfc0
D (851) esp-netif_lwip-ppp: Phase Start
D (861) esp-netif_lwip-ppp: Phase Establish
D (861) esp_netif_lwip: check: local, if=0x3fc9bd8c fn=0x42013794
0x42013794: esp_netif_update_default_netif_lwip at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:317

D (871) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fc9bd8c
D (871) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (881) test: Waiting for IP address
D (60861) esp-netif_lwip-ppp: Phase Disconnect
D (60861) esp-netif_lwip-ppp: Phase Dead
I (60861) esp-netif_lwip-ppp: Connection lost
D (60861) event: running post IP_EVENT:7 with handler 0x4200a908 and context 0x3fc9bd38 on loop 0x3fc9adec
0x4200a908: on_ip_event at /Users/emanuele/Documents/Projects/nbTest/main/main.c:29

I (60871) test: IP event! 7
I (60871) test: Modem Disconnect from PPP Server
D (60881) event: running post IP_EVENT:7 with handler 0x420124dc and context 0x3fca0818 on loop 0x3fc9adec
0x420124dc: esp_netif_action_disconnected at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/esp_netif_handlers.c:83

D (60891) esp_netif_handlers: esp_netif action disconnected with netif0x3fc9bd8c from event_id=7
D (60901) esp_netif_lwip: check: remote, if=0x3fc9bd8c fn=0x42012d78
0x42012d78: esp_netif_down_api at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1673

D (60901) esp_netif_lwip: esp_netif_down_api esp_netif:0x3fc9bd8c
D (60911) esp_netif_lwip: esp_netif_internal_dhcpc_cb lwip-netif:0x3fc9be14
D (60911) esp_netif_lwip: check: local, if=0x3fc9bd8c fn=0x42013794
0x42013794: esp_netif_update_default_netif_lwip at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:317

D (60921) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fc9bd8c
D (60931) esp_netif_lwip: call api in lwip: ret=0x0, give sem

My code:

#include <stdio.h>
#include <string.h>
#include "freertos/FreeRTOS.h"
#include "freertos/event_groups.h"
#include "esp_netif.h"
#include "esp_netif_ppp.h"
#include "mqtt_client.h"
#include "esp_log.h"
#include "esp_modem_api.h"

static const char *TAG = "test";
static EventGroupHandle_t event_group = NULL;
static const int CONNECT_BIT = BIT0;
static const int GOT_DATA_BIT = BIT2;

static void on_ppp_changed(void *arg, esp_event_base_t event_base,
                           int32_t event_id, void *event_data)
{
    ESP_LOGI(TAG, "PPP state changed event %" PRIu32, event_id);
    if (event_id == NETIF_PPP_ERRORUSER) {
        /* User interrupted event from esp-netif */
        esp_netif_t **p_netif = event_data;
        ESP_LOGI(TAG, "User interrupted event from netif:%p", *p_netif);
    }
}

static void on_ip_event(void *arg, esp_event_base_t event_base,
                        int32_t event_id, void *event_data)
{
    ESP_LOGI(TAG, "IP event! %" PRIu32, event_id);
    if (event_id == IP_EVENT_PPP_GOT_IP) {
        esp_netif_dns_info_t dns_info;

        ip_event_got_ip_t *event = (ip_event_got_ip_t *)event_data;
        esp_netif_t *netif = event->esp_netif;

        ESP_LOGI(TAG, "Modem Connect to PPP Server");
        ESP_LOGI(TAG, "~~~~~~~~~~~~~~");
        ESP_LOGI(TAG, "IP          : " IPSTR, IP2STR(&event->ip_info.ip));
        ESP_LOGI(TAG, "Netmask     : " IPSTR, IP2STR(&event->ip_info.netmask));
        ESP_LOGI(TAG, "Gateway     : " IPSTR, IP2STR(&event->ip_info.gw));
        esp_netif_get_dns_info(netif, 0, &dns_info);
        ESP_LOGI(TAG, "Name Server1: " IPSTR, IP2STR(&dns_info.ip.u_addr.ip4));
        esp_netif_get_dns_info(netif, 1, &dns_info);
        ESP_LOGI(TAG, "Name Server2: " IPSTR, IP2STR(&dns_info.ip.u_addr.ip4));
        ESP_LOGI(TAG, "~~~~~~~~~~~~~~");
        xEventGroupSetBits(event_group, CONNECT_BIT);

        ESP_LOGI(TAG, "GOT ip event!!!");
    } else if (event_id == IP_EVENT_PPP_LOST_IP) {
        ESP_LOGI(TAG, "Modem Disconnect from PPP Server");
    } else if (event_id == IP_EVENT_GOT_IP6) {
        ESP_LOGI(TAG, "GOT IPv6 event!");

        ip_event_got_ip6_t *event = (ip_event_got_ip6_t *)event_data;
        ESP_LOGI(TAG, "Got IPv6 address " IPV6STR, IPV62STR(event->ip6_info.ip));
    }
}

void app_main(void)
{
    ESP_LOGI(TAG, "Main started...");

    /* Init and register system/core components */
    ESP_ERROR_CHECK(esp_netif_init());
    ESP_ERROR_CHECK(esp_event_loop_create_default());
    ESP_ERROR_CHECK(esp_event_handler_register(IP_EVENT, ESP_EVENT_ANY_ID, &on_ip_event, NULL));
    ESP_ERROR_CHECK(esp_event_handler_register(NETIF_PPP_STATUS, ESP_EVENT_ANY_ID, &on_ppp_changed, NULL));

    ESP_LOGI(TAG, "End setup");

     /* Configure the PPP netif */
    esp_modem_dce_config_t dce_config = ESP_MODEM_DCE_DEFAULT_CONFIG("iot.1nce.net");
    esp_netif_config_t netif_ppp_config = ESP_NETIF_DEFAULT_PPP();
    esp_netif_t *esp_netif = esp_netif_new(&netif_ppp_config);
    assert(esp_netif);

    event_group = xEventGroupCreate();

    esp_modem_dte_config_t dte_config = ESP_MODEM_DTE_DEFAULT_CONFIG();
    /* setup UART specific configuration based on kconfig options */
    dte_config.uart_config.tx_io_num = 5;
    dte_config.uart_config.rx_io_num = 6;
    //dte_config.uart_config.rts_io_num = CONFIG_EXAMPLE_MODEM_UART_RTS_PIN;
    //dte_config.uart_config.cts_io_num = CONFIG_EXAMPLE_MODEM_UART_CTS_PIN;
    dte_config.uart_config.flow_control = ESP_MODEM_FLOW_CONTROL_NONE;
    dte_config.uart_config.rx_buffer_size = 4096;//1024;
    dte_config.uart_config.tx_buffer_size = 2048;//512;
    dte_config.uart_config.event_queue_size = 30;
    dte_config.task_stack_size = 4096;//2048;
    dte_config.task_priority = 5;
    dte_config.dte_buffer_size = 1024 / 2;

    ESP_LOGI(TAG, "Initializing esp_modem for the NB-IoT module...");
    //esp_modem_dce_t *dce = esp_modem_new_dev(ESP_MODEM_DCE_SIM7600, &dte_config, &dce_config, esp_netif);
    esp_modem_dce_t *dce = esp_modem_new_dev(ESP_MODEM_DCE_CUSTOM, &dte_config, &dce_config, esp_netif);

    assert(dce);

    xEventGroupClearBits(event_group, CONNECT_BIT | GOT_DATA_BIT);

    int rssi, ber;
    esp_err_t err = esp_modem_get_signal_quality(dce, &rssi, &ber);
    if (err != ESP_OK) {
        ESP_LOGE(TAG, "esp_modem_get_signal_quality failed with %d %s", err, esp_err_to_name(err));
        return;
    }
    ESP_LOGI(TAG, "Signal quality: rssi=%d, ber=%d", rssi, ber);

    char imsi[100];
    err = esp_modem_get_imsi(dce, &imsi);
    if (err != ESP_OK) {
        ESP_LOGE(TAG, "esp_modem_get_imsi failed with %d %s", err, esp_err_to_name(err));
        return;
    }
    ESP_LOGI(TAG, "imsi=%s", imsi);

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

    // Wait for IP address 
    ESP_LOGI(TAG, "Waiting for IP address");
    xEventGroupWaitBits(event_group, CONNECT_BIT, pdFALSE, pdFALSE, portMAX_DELAY);
}

Thanks

david-cermak commented 3 weeks ago

Hi @ezamp

Could you please enable CONFIG_LWIP_PPP_DEBUG_ON and share the log for us to check the IPCP negotiation?

ezamp commented 3 weeks ago

Hi @david-cermak

Thanks for your reply, I enabled _CONFIG_LWIP_PPP_DEBUGON but I don't see difference in the log. Now the log level is configured to DEBUG.

Log:

[...]
I (683) test: End setup
D (693) esp_netif_lwip: check: remote, if=0x3fc98364 fn=0x42013158
0x42013158: esp_netif_new_api at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:690

D (693) esp_netif_objects: esp_netif_add_to_list_unsafe netif added successfully (total netifs: 1)
D (703) esp-netif_lwip-ppp: esp_netif_new_ppp: PPP connection created: 0x3fc9bfc0
D (713) esp-netif_lwip-ppp: Phase Dead
D (713) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (723) test: Initializing esp_modem for the NB-IoT module...
I (723) uart: queue free spaces: 30
D (733) intr_alloc: Connected src 28 to int 8 (cpu 0)
I (743) test: Signal quality: rssi=22, ber=0
I (753) test: imsi=901405108749214
D (753) command_lib: generic_command command ATE0

D (753) command_lib: Response: 
OK

D (753) command_lib: generic_command command AT+CGDCONT=1,"IP","iot.1nce.net"

D (953) command_lib: Response: 
OK

D (963) esp_netif_handlers: esp_netif action has started with netif0x3fc9bd8c from event_id=0
D (973) esp_netif_lwip: check: remote, if=0x3fc9bd8c fn=0x420133ec
0x420133ec: esp_netif_start_api at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1068

D (973) esp_netif_lwip: esp_netif_start_api 0x3fc9bd8c
D (983) esp-netif_lwip-ppp: esp_netif_start_ppp: Starting PPP connection: 0x3fc9bfc0
D (993) esp-netif_lwip-ppp: Phase Start
D (993) esp-netif_lwip-ppp: Phase Establish
D (993) esp_netif_lwip: check: local, if=0x3fc9bd8c fn=0x420138cc
0x420138cc: esp_netif_update_default_netif_lwip at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:317

D (1003) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fc9bd8c
D (1013) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (1013) test: Waiting for IP address
D (60993) esp-netif_lwip-ppp: Phase Disconnect
D (60993) esp-netif_lwip-ppp: Phase Dead
I (60993) esp-netif_lwip-ppp: Connection lost
D (60993) event: running post IP_EVENT:7 with handler 0x4200aa2c and context 0x3fc9bd38 on loop 0x3fc9adec
0x4200aa2c: on_ip_event at /Users/emanuele/Documents/Projects/nbTest/main/main.c:29

I (61003) test: IP event! 7
I (61003) test: Modem Disconnect from PPP Server
D (61013) event: running post IP_EVENT:7 with handler 0x42012614 and context 0x3fca0818 on loop 0x3fc9adec
0x42012614: esp_netif_action_disconnected at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/esp_netif_handlers.c:83

D (61023) esp_netif_handlers: esp_netif action disconnected with netif0x3fc9bd8c from event_id=7
D (61033) esp_netif_lwip: check: remote, if=0x3fc9bd8c fn=0x42012eb0
0x42012eb0: esp_netif_down_api at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1673

D (61033) esp_netif_lwip: esp_netif_down_api esp_netif:0x3fc9bd8c
D (61043) esp_netif_lwip: esp_netif_internal_dhcpc_cb lwip-netif:0x3fc9be14
D (61043) esp_netif_lwip: check: local, if=0x3fc9bd8c fn=0x420138cc
0x420138cc: esp_netif_update_default_netif_lwip at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:317

D (61053) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fc9bd8c
D (61063) esp_netif_lwip: call api in lwip: ret=0x0, give sem

david-cermak commented 3 weeks ago

oh, sorry, forgot about the CONFIG_LWIP_DEBUG, this needs to be enabled, too, to propagate the logs from the liwp.

ezamp commented 3 weeks ago

Okay, now I see the logs

I (5760) test: Signal quality: rssi=99, ber=99
I (5770) test: imsi=901405108749214
D (5770) command_lib: generic_command command ATE0

D (5780) command_lib: Response: 
OK

D (5780) command_lib: generic_command command AT+CGDCONT=1,"IP","iot.1nce.net"

D (5870) command_lib: Response: 
OK

D (5870) command_lib: generic_command command ATD*99#

D (5870) command_lib: Response: 
ERROR

D (5870) command_lib: generic_command command ATO

D (5880) command_lib: Response: 
ERROR

D (5880) esp_netif_handlers: esp_netif action has started with netif0x3fc9bd8c from event_id=0
D (5890) esp_netif_lwip: check: remote, if=0x3fc9bd8c fn=0x42013684
0x42013684: esp_netif_start_api at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1068

D (5900) esp_netif_lwip: esp_netif_start_api 0x3fc9bd8c
D (5900) esp-netif_lwip-ppp: esp_netif_start_ppp: Starting PPP connection: 0x3fc9bfc0
ppp_connect[1]: holdoff=0
ppp phase changed[1]: phase=3
D (5910) esp-netif_lwip-ppp: Phase Start
pppos_connect: unit 1: connecting
ppp_start[1]
ppp phase changed[1]: phase=6
D (5930) esp-netif_lwip-ppp: Phase Establish
pppos_send_config[1]: out_accm=FF FF FF FF
ppp_send_config[1]
pppos_recv_config[1]: in_accm=FF FF FF FF
ppp_recv_config[1]
ppp: auth protocols: PAP=0
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd5b8b5af> <pcomp> <accomp>]
pppos_write[1]: len=24
ppp_start[1]: finished
D (5950) esp_netif_lwip: check: local, if=0x3fc9bd8c fn=0x42013b64
0x42013b64: esp_netif_update_default_netif_lwip at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:317

D (5960) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fc9bd8c
D (5970) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (5970) test: Waiting for IP address
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd5b8b5af> <pcomp> <accomp>]
pppos_write[1]: len=24
pppos_input[1]: got 21 bytes
pppos_input[1]: Dropping ACCM char <13>
pppos_input[1]: Dropping ACCM char <10>
pppos_input[1]: Dropping ACCM char <13>
pppos_input[1]: Dropping ACCM char <10>
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd5b8b5af> <pcomp> <accomp>]
pppos_write[1]: len=24
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd5b8b5af> <pcomp> <accomp>]
pppos_write[1]: len=24
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd5b8b5af> <pcomp> <accomp>]
pppos_write[1]: len=24
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd5b8b5af> <pcomp> <accomp>]
pppos_write[1]: len=24
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd5b8b5af> <pcomp> <accomp>]
pppos_write[1]: len=24
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd5b8b5af> <pcomp> <accomp>]
pppos_write[1]: len=24
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd5b8b5af> <pcomp> <accomp>]
pppos_write[1]: len=24
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd5b8b5af> <pcomp> <accomp>]
pppos_write[1]: len=24
LCP: timeout sending Config-Requests
ppp phase changed[1]: phase=12
D (65950) esp-netif_lwip-ppp: Phase Disconnect
Connection terminated.
ppp_link_terminated[1]
ppp_link_end[1]
ppp phase changed[1]: phase=0
D (65950) esp-netif_lwip-ppp: Phase Dead
I (65960) esp-netif_lwip-ppp: Connection lost
D (65960) event: running post IP_EVENT:7 with handler 0x4200ac74 and context 0x3fc9bd38 on loop 0x3fc9adec
0x4200ac74: on_ip_event at /Users/emanuele/Documents/Projects/nbTest/main/main.c:29

ppp_link_terminated[1]: finished.
I (65970) test: IP event! 7
I (65980) test: Modem Disconnect from PPP Server
D (65980) event: running post IP_EVENT:7 with handler 0x420128ac and context 0x3fca0818 on loop 0x3fc9adec
0x420128ac: esp_netif_action_disconnected at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/esp_netif_handlers.c:83

D (65990) esp_netif_handlers: esp_netif action disconnected with netif0x3fc9bd8c from event_id=7
D (66000) esp_netif_lwip: check: remote, if=0x3fc9bd8c fn=0x42013148
0x42013148: esp_netif_down_api at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1673

D (66010) esp_netif_lwip: esp_netif_down_api esp_netif:0x3fc9bd8c
D (66010) esp_netif_lwip: esp_netif_internal_dhcpc_cb lwip-netif:0x3fc9be14
D (66020) esp_netif_lwip: check: local, if=0x3fc9bd8c fn=0x42013b64
0x42013b64: esp_netif_update_default_netif_lwip at /Users/emanuele/esp/v5.3/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:317

D (66030) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fc9bd8c
D (66030) esp_netif_lwip: call api in lwip: ret=0x0, give sem

david-cermak commented 3 weeks ago

The PPP negotiation doesn't work, since the modem is still in the text mode:

pppos_input[1]: Dropping ACCM char <13>
pppos_input[1]: Dropping ACCM char <10>

Also, it rejected the dial-up command for some reason:

D (5870) command_lib: generic_command command ATD*99#

D (5870) command_lib: Response: 
ERROR

I haven't noticed these lines in the previous log...

ezamp commented 3 weeks ago

The SIM7028 module does not implement the ATD*99# command.

david-cermak commented 2 weeks ago

The SIM7028 module does not implement the ATD*99# command.

Oh, sorry, this device does not really seem to support PPP connection. Not possible to acquire an IP after PPPoS handshake then. You'd need to use AT commands only to connect to internet, it seems. Looking at the socket TCP/IP commands, they look similar to those of SIMCOM/SIM7600, so you can check this example: https://github.com/espressif/esp-protocols/tree/master/components/esp_modem/examples/modem_tcp_client it uses AT commands (might need to create/update them per your device specs) to bring the esp_netif connection and enables using IDF protocol libraries (which might be useful in some cases)

espressif / esp-protocols

esp-netif_lwip-ppp: Connection lost, without event IP_EVENT_PPP_GOT_IP (IDFGH-13514) #637

Answers checklist.

General issue report