esp-modem next step : ppp auth ? (IDFGH-12496)

dannybackx commented 3 months ago

Answers checklist.

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

General issue report

My SIM card provider wants me to set username + password. In the example Kconfig files, there are variables like EXAMPLE_MODEM_PPP_AUTH_USERNAME but none of the examples seem to use this. So how should I set these ? I'm staring at this section of pppos_client_main.c and I'm guessing it should go here somewhere, but ..

    esp_modem_dce_config_t dce_config = ESP_MODEM_DCE_DEFAULT_CONFIG(CONFIG_EXAMPLE_MODEM_PPP_APN);
    esp_netif_config_t netif_ppp_config = ESP_NETIF_DEFAULT_PPP();
    esp_netif_t *esp_netif = esp_netif_new(&netif_ppp_config);

dannybackx commented 3 months ago

Ah, found esp_netif_ppp_set_auth() somewhere, but it doesn't seem to make a difference.

See https://sourceforge.net/p/lilygo-t-sim-7080-s3/code/HEAD/tree/trunk/modem1/main/pppos_client_main.c

Current output :

I (01:31:12.185) main_task: Started on CPU0
I (01:31:12.195) main_task: Calling app_main()
I (01:31:12.197) gpio: GPIO[15]| InputEn: 1| OutputEn: 1| OpenDrain: 1| Pullup: 0| Pulldown: 0| Intr:0 
I (01:31:12.205) gpio: GPIO[7]| InputEn: 1| OutputEn: 1| OpenDrain: 1| Pullup: 0| Pulldown: 0| Intr:0 
I (01:31:12.215) AXP2101: Implemented using built-in read and write methods (Use higher version >= 5.0 API)
I (01:31:12.226) AXP2101: Init PMU SUCCESS!
I (01:31:12.235) AXP2101: DCDC=======================================================================
I (01:31:12.240) AXP2101: DC1  : +   Voltage:3300 mV
I (01:31:12.246) AXP2101: DC3  : +   Voltage:3000 mV (modem)
I (01:31:12.252) AXP2101: ALDO=======================================================================
I (01:31:12.262) AXP2101: BLDO=======================================================================
I (01:31:12.272) AXP2101: BLDO1: +   Voltage:3300 mV (level converter)
I (01:31:12.279) AXP2101: BLDO2: +   Voltage:3300 mV (gps)
I (01:31:12.285) AXP2101: CPUSLDO====================================================================
I (01:31:12.295) AXP2101: DLDO=======================================================================
I (01:31:12.305) AXP2101: ===========================================================================
I (01:31:12.321) pppos_example: PPP auth set
I (01:31:12.322) pppos_example: Initializing esp_modem for the SIM7070 module...
I (01:31:12.328) uart: queue free spaces: 30
I (01:31:12.334) gpio: GPIO[41]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (01:31:12.343) pppos_example: Trigger modem ..
I (01:31:13.540) pppos_example: Wait for 5s ..
I (01:31:18.540) pppos_example: Check for modem ..
I (01:31:19.244) pppos_example: modem_init ok
I (01:31:19.244) pppos_example: Didn't set any flow control
I (01:31:20.294) pppos_example: Signal quality: rssi=99, ber=99
I (01:31:20.306) pppos_example: esp_modem_set_mode(ESP_MODEM_MODE_DATA) ok
I (01:31:20.307) pppos_example: Waiting for IP address
I (01:31:26.340) esp-netif_lwip-ppp: Connection lost
I (01:31:26.341) pppos_example: Modem Disconnect from PPP Server

dannybackx commented 3 months ago

With logs set to verbose, two stack overflows appeared to happen which previously went undetected. After fixing that, I see this (note still same output as above with logs set to Info) :

I (00:02:36.537) AXP2101: Implemented using built-in read and write methods (Use higher version >= 5.0 API)
I (00:02:36.549) AXP2101: Init PMU SUCCESS!
I (00:02:36.558) AXP2101: DCDC=======================================================================
I (00:02:36.563) AXP2101: DC1  : +   Voltage:3300 mV
I (00:02:36.569) AXP2101: DC3  : +   Voltage:3000 mV (modem)
I (00:02:36.575) AXP2101: ALDO=======================================================================
I (00:02:36.585) AXP2101: BLDO=======================================================================
I (00:02:36.595) AXP2101: BLDO1: +   Voltage:3300 mV (level converter)
I (00:02:36.602) AXP2101: BLDO2: +   Voltage:3300 mV (gps)
I (00:02:36.608) AXP2101: CPUSLDO====================================================================
I (00:02:36.618) AXP2101: DLDO=======================================================================
I (00:02:36.628) AXP2101: ===========================================================================
D (00:02:36.644) esp_netif_lwip: check: remote, if=0x3fca1f20 fn=0x4201c59c
0x4201c59c: esp_netif_new_api at /home/danny/src/github/esp32/esp-idf-v5.2.1/components/esp_netif/lwip/esp_netif_lwip.c:690

V (00:02:36.645) esp_netif_objects: esp_netif_add_to_list_unsafe 0x3fca6628
D (00:02:36.651) esp_netif_objects: esp_netif_add_to_list_unsafe netif added successfully (total netifs: 1)
D (00:02:36.661) lwip: netif: netmask of interface  set to 255.255.255.255

D (00:02:36.668) lwip: netif: added interface pp IP
D (00:02:36.673) lwip:  addr 
D (00:02:36.676) lwip: 0.0.0.0
D (00:02:36.679) lwip:  netmask 
D (00:02:36.683) lwip: 255.255.255.255
D (00:02:36.687) lwip:  gw 
D (00:02:36.689) lwip: 0.0.0.0
D (00:02:36.693) lwip: 

D (00:02:36.695) lwip: ppp phase changed[1]: phase=0

D (00:02:36.700) esp-netif_lwip-ppp: esp_netif_new_ppp: PPP connection created: 0x3fca67a8
D (00:02:36.709) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (00:02:36.715) esp_netif_lwip: check: remote, if=0x3fca6628 fn=0x4201cdc0
0x4201cdc0: esp_netif_ppp_set_auth_api at /home/danny/src/github/esp32/esp-idf-v5.2.1/components/esp_netif/lwip/esp_netif_lwip.c:2503

D (00:02:36.722) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (00:02:36.729) pppos_example: PPP auth set
I (00:02:36.734) pppos_example: Initializing esp_modem for the SIM7070 module...
I (00:02:36.743) uart: queue free spaces: 30
V (1160) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1160) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1170) intr_alloc: Connected src 28 to int 17 (cpu 0)
I (00:02:36.767) gpio: GPIO[41]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (00:02:36.777) pppos_example: Trigger modem ..
I (00:02:37.976) pppos_example: Wait for 13s ..
I (00:02:50.976) pppos_example: Check for modem ..
V (00:02:50.976) command_lib: sync
V (00:02:50.976) command_lib: generic_command_common
V (00:02:50.979) command_lib: generic_command
D (00:02:50.983) command_lib: generic_command command AT

V (00:02:51.686) command_lib: sync
V (00:02:51.686) command_lib: generic_command_common
V (00:02:51.687) command_lib: generic_command
D (00:02:51.688) command_lib: generic_command command AT

D (00:02:51.698) command_lib: Response: AT
OK

I (00:02:51.699) pppos_example: modem_init ok
I (00:02:51.704) pppos_example: Didn't set any flow control
V (00:02:51.710) command_lib: read_pin
V (00:02:51.714) command_lib: generic_get_string
V (00:02:51.724) command_lib: Token: {AT+CPIN?}

V (00:02:51.724) command_lib: Token: {+CPIN: SIM PIN}

} (00:02:51.729) command_lib: Token: {

V (00:02:51.733) command_lib: Token: {OK}

V (00:02:51.737) command_lib: set_pin
V (00:02:51.741) command_lib: generic_command_common
V (00:02:51.746) command_lib: generic_command
D (00:02:51.750) command_lib: generic_command command AT+CPIN=1111

D (00:02:51.802) command_lib: Response: AT+CPIN=1111
OK

V (00:02:52.796) command_lib: get_signal_quality
V (00:02:52.796) command_lib: generic_get_string
} (00:02:52.801) command_lib: Token: {

V (00:02:52.801) command_lib: Token: {+CPIN: READY}

} (00:02:52.804) command_lib: Token: {

V (00:02:52.808) command_lib: Token: {SMS Ready}

V (00:02:52.813) command_lib: Token: {AT+CSQ}

V (00:02:52.817) command_lib: Token: {+CSQ: 99,99}

} (00:02:52.822) command_lib: Token: {

V (00:02:52.827) command_lib: Token: {OK}

I (00:02:52.831) pppos_example: Signal quality: rssi=99, ber=99
V (00:02:52.838) command_lib: set_echo
V (00:02:52.841) command_lib: generic_command_common
V (00:02:52.846) command_lib: generic_command
D (00:02:52.851) command_lib: generic_command command ATE0

D (00:02:52.859) command_lib: Response: ATE0
OK

V (00:02:52.862) command_lib: set_pdp_context
V (00:02:52.866) command_lib: generic_command_common
V (00:02:52.871) command_lib: generic_command
D (00:02:52.876) command_lib: generic_command command AT+CGDCONT=1,"IP","web.be"

D (00:02:52.890) command_lib: Response: 
OK

V (00:02:52.891) command_lib: set_data_mode_alt
V (00:02:52.893) command_lib: generic_command
D (00:02:52.897) command_lib: generic_command command ATD*99##

D (00:02:52.907) command_lib: Response: 
CONNECT 150000000

D (00:02:52.910) esp_netif_handlers: esp_netif action has started with netif0x3fca6628 from event_id=0
D (00:02:52.919) esp_netif_lwip: check: remote, if=0x3fca6628 fn=0x4201c868
0x4201c868: esp_netif_start_api at /home/danny/src/github/esp32/esp-idf-v5.2.1/components/esp_netif/lwip/esp_netif_lwip.c:1068

D (00:02:52.926) esp_netif_lwip: esp_netif_start_api 0x3fca6628
D (00:02:52.932) esp-netif_lwip-ppp: esp_netif_start_ppp: Starting PPP connection: 0x3fca67a8
D (00:02:52.941) lwip: ppp_connect[1]: holdoff=0

D (00:02:52.946) lwip: ppp phase changed[1]: phase=3

D (00:02:52.951) lwip: pppos_connect: unit 1: connecting

D (00:02:52.956) lwip: ppp_start[1]

D (00:02:52.960) lwip: ppp phase changed[1]: phase=6

D (00:02:52.965) lwip: pppos_send_config[1]: out_accm=FF FF FF FF

D (00:02:52.972) lwip: ppp_send_config[1]

D (00:02:52.976) lwip: pppos_recv_config[1]: in_accm=FF FF FF FF

D (00:02:52.982) lwip: ppp_recv_config[1]

D (00:02:52.986) lwip: ppp: auth protocols:
D (00:02:52.991) lwip:  PAP=1
D (00:02:52.994) lwip:  CHAP=0 CHAP_MD5=0
D (00:02:52.998) lwip:  CHAP_MS=0 CHAP_MS2=0
D (00:02:53.002) lwip: 

D (00:02:53.005) lwip: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xf46360ed> <pcomp> <accomp>]

D (00:02:53.014) lwip: pppos_write[1]: len=24

D (00:02:53.019) lwip: ppp_start[1]: finished

D (00:02:53.023) esp_netif_lwip: check: local, if=0x3fca6628 fn=0x4201d050
0x4201d050: esp_netif_update_default_netif_lwip at /home/danny/src/github/esp32/esp-idf-v5.2.1/components/esp_netif/lwip/esp_netif_lwip.c:316

D (00:02:53.030) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fca6628
V (00:02:53.038) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3fca6628
D (00:02:53.045) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (00:02:53.051) lwip: pppos_input[1]: got 64 bytes

D (00:02:53.057) lwip: rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0xd00eff08> <pcomp> <accomp>]

D (00:02:53.067) lwip: sent [LCP ConfNak id=0x0 <auth pap>]

D (00:02:53.073) lwip: pppos_write[1]: len=12

D (00:02:53.077) lwip: pppos_input[1]: got 36 bytes

D (00:02:53.083) lwip: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xf46360ed> <pcomp> <accomp>]

D (00:02:53.092) lwip: pppos_input[1]: got 53 bytes

D (00:02:53.097) lwip: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <auth pap> <magic 0xd00eff08> <pcomp> <accomp>]

D (00:02:53.107) lwip: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <auth pap> <magic 0xd00eff08> <pcomp> <accomp>]

D (00:02:53.118) lwip: pppos_write[1]: len=28

D (00:02:53.122) lwip: netif_set_mtu[1]: mtu=1500

D (00:02:53.127) lwip: pppos_send_config[1]: out_accm=0 0 0 0

D (00:02:53.133) lwip: ppp_send_config[1]

D (00:02:53.137) lwip: pppos_recv_config[1]: in_accm=0 0 0 0

D (00:02:53.143) lwip: ppp_recv_config[1]

D (00:02:53.147) lwip: ppp phase changed[1]: phase=7

D (00:02:53.153) lwip: sent [PAP AuthReq id=0x1 user="web" password="web"]

D (00:02:53.160) lwip: pppos_write[1]: len=16

D (00:02:53.164) lwip: pppos_input[1]: got 23 bytes

D (00:02:53.170) lwip: rcvd [LCP DiscReq id=0x2 magic=0xd00eff08]

D (00:02:53.176) lwip: pppos_input[1]: got 11 bytes

D (00:02:53.181) lwip: rcvd [PAP AuthAck id=0x1 ""]

D (00:02:53.186) lwip: PAP authentication succeeded

D (00:02:53.191) lwip: ppp phase changed[1]: phase=9

D (00:02:53.196) lwip: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]

D (00:02:53.208) lwip: pppos_write[1]: len=32

I (00:02:53.212) pppos_example: esp_modem_set_mode(ESP_MODEM_MODE_DATA) ok
D (00:02:53.213) lwip: pppos_input[1]: got 17 bytes

D (00:02:53.225) lwip: rcvd [LCP TermReq id=0x3]

D (00:02:53.229) lwip: LCP terminated by peer

D (00:02:53.234) lwip: ppp phase changed[1]: phase=6

D (00:02:53.239) lwip: pppos_send_config[1]: out_accm=FF FF FF FF

D (00:02:53.246) lwip: ppp_send_config[1]

D (00:02:53.250) lwip: pppos_recv_config[1]: in_accm=0 0 0 0

D (00:02:53.256) lwip: ppp_recv_config[1]

D (00:02:53.260) lwip: sent [LCP TermAck id=0x3]

D (00:02:53.265) lwip: pppos_write[1]: len=8

D (00:02:53.269) lwip: pppos_input[1]: got 14 bytes

I (00:02:53.275) pppos_example: Waiting for IP address
D (00:02:58.367) lwip: pppos_input[1]: got 49 bytes

D (00:02:59.256) lwip: ppp phase changed[1]: phase=12

D (00:02:59.256) lwip: Connection terminated.

D (00:02:59.257) lwip: ppp_link_terminated[1]

D (00:02:59.260) lwip: ppp_link_end[1]

D (00:02:59.264) lwip: ppp phase changed[1]: phase=0

I (00:02:59.269) esp-netif_lwip-ppp: Connection lost
D (00:02:59.275) event: running post IP_EVENT:7 with handler 0x4200a070 and context 0x3fca6164 on loop 0x3fca5218
0x4200a070: on_ip_event at /home/danny/src/esp-idf/gsm/modem1/main/pppos_client_main.c:59

D (00:02:59.281) lwip: ppp_link_terminated[1]: finished.

D (00:02:59.285) pppos_example: IP event! 7
I (00:02:59.295) pppos_example: Modem Disconnect from PPP Server
D (00:02:59.301) event: running post IP_EVENT:7 with handler 0x4201bc6c and context 0x3fca9e7c on loop 0x3fca5218
0x4201bc6c: esp_netif_action_disconnected at /home/danny/src/github/esp32/esp-idf-v5.2.1/components/esp_netif/esp_netif_handlers.c:83

D (00:02:59.312) esp_netif_handlers: esp_netif action disconnected with netif0x3fca6628 from event_id=7
D (00:02:59.321) esp_netif_lwip: check: remote, if=0x3fca6628 fn=0x4201ccb8
0x4201ccb8: esp_netif_down_api at /home/danny/src/github/esp32/esp-idf-v5.2.1/components/esp_netif/lwip/esp_netif_lwip.c:1673

D (00:02:59.328) esp_netif_lwip: esp_netif_down_api esp_netif:0x3fca6628
D (00:02:59.335) lwip: netif: netmask of interface pp set to 0.0.0.0

D (00:02:59.341) esp_netif_lwip: esp_netif_internal_dhcpc_cb lwip-netif:0x3fca66ac
D (00:02:59.349) esp_netif_lwip: check: local, if=0x3fca6628 fn=0x4201d050
0x4201d050: esp_netif_update_default_netif_lwip at /home/danny/src/github/esp32/esp-idf-v5.2.1/components/esp_netif/lwip/esp_netif_lwip.c:316

D (00:02:59.356) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fca6628
V (00:02:59.364) esp_netif_objects: esp_netif_next_unsafe 0x0
V (00:02:59.369) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3fca6628
V (00:02:59.376) esp_netif_objects: esp_netif_next_unsafe 0x3fca6628
D (00:02:59.383) esp_netif_lwip: call api in lwip: ret=0x0, give sem

How do I debug further ?

dannybackx commented 3 months ago

Ok, looks like I also needed a loop to wait on good signal quality.

The initial wait (which the sim7080g docs describe as 12 seconds after triggering it with pin 39) doesn't work well for me yet. After flashing the ESP the initial run basically never works, after rebooting it (Ctrl-T Ctrl-R) it does seem to work.

This piece of code :

  /*
   * Note there's a transistor between ESP pin 41 and SIM7080G pin 39 (as in the reference design)
   * so 1 actually pulls pin 39 down.
   */
  ESP_LOGI(TAG, "Trigger modem ..");

  gpio_set_level((gpio_num_t)41, 0);
  vTaskDelay(pdMS_TO_TICKS(100));       // was 100ms
  gpio_set_level((gpio_num_t)41, 1);
  vTaskDelay(pdMS_TO_TICKS(1000));
  gpio_set_level((gpio_num_t)41, 0);
  vTaskDelay(pdMS_TO_TICKS(100));       // was 100ms

  // Now, according to the doc, wait for 12s before the modem is on
  static int modem_wait_seconds = 13;
  ESP_LOGI(TAG, "Wait for %ds ..", modem_wait_seconds);
  vTaskDelay(pdMS_TO_TICKS(1000 * modem_wait_seconds));

  ESP_LOGI(TAG, "Check for modem ..");
  esp_err_t e;
  for (int i=0; i<10; i++) {
    e = esp_modem_sync(dce);
    if (e == ESP_OK)
      return e;
    vTaskDelay(pdMS_TO_TICKS(200));
  }

Any clues on how to make it reliable ?

david-cermak commented 3 months ago

Hi @dannybackx

I'm sorry we cannot help with the initial sequence. It's out of the scope of this library and very much dependent on the actual device and needs. The routine from this example seems to generally work for me and for people based on what I hear (also works for reconnection)

https://github.com/espressif/esp-protocols/blob/f26f2f88c2c6a3b38e816f79c22d250b9739fe3f/examples/esp_netif/multiple_netifs/main/ppp_connect_esp_modem.c#L54C1-L94C1

but again, should be adjusted to the actual application needs.

dannybackx commented 3 months ago

Understandable, thanks for providing input anyway. Please note I hadn't found the example you provide before, it might be worth pointing to that repo from the esp-modem component.

Meanwhile I found a solution, I think (see below) - do the described startup sequence twice with 2s waits surrounding it. Not the 12s mentioned in the doc.

So for me this successfully starts the modem on a LilyGo T-SIM7080-S3

I (16:24:43.839) pppos_example: Wait for 2s ..
I (16:24:45.842) pppos_example: Trigger modem ..
I (16:24:47.042) pppos_example: Wait for 2s ..
I (16:24:49.042) pppos_example: Trigger modem ..
I (16:24:50.242) pppos_example: Wait for 2s ..
I (16:24:52.242) pppos_example: Check for modem ..
I (16:24:52.846) pppos_example: modem_init: success after iteration 1
I (16:24:52.847) pppos_example: modem_init ok

static int      modem_wait_seconds      =   2;  // Before starting the loop of retries
static int      modem_count_retries     =  50;  // How many attempts in the retry loop
static int              modem_retry_ms  = 100;  // Wait time (in ms) between retries

  // Let's wait before we trigger the modem
  ESP_LOGI(TAG, "Wait for %ds ..", modem_wait_seconds);
  vTaskDelay(pdMS_TO_TICKS(1000 * modem_wait_seconds));

  /*
   * Note there's a transistor between ESP pin 41 and SIM7080G pin 39 (as in the reference design)
   * so 1 actually pulls pin 39 down.
   */
  ESP_LOGI(TAG, "Trigger modem ..");

  gpio_set_level((gpio_num_t)41, 0);
  vTaskDelay(pdMS_TO_TICKS(100));
  gpio_set_level((gpio_num_t)41, 1);
  vTaskDelay(pdMS_TO_TICKS(1000));
  gpio_set_level((gpio_num_t)41, 0);
  vTaskDelay(pdMS_TO_TICKS(100));

  // Now, according to the doc, wait for 12s before the modem is on
  ESP_LOGI(TAG, "Wait for %ds ..", modem_wait_seconds);
  vTaskDelay(pdMS_TO_TICKS(1000 * modem_wait_seconds));

  ESP_LOGI(TAG, "Trigger modem ..");

  gpio_set_level((gpio_num_t)41, 0);
  vTaskDelay(pdMS_TO_TICKS(100));
  gpio_set_level((gpio_num_t)41, 1);
  vTaskDelay(pdMS_TO_TICKS(1000));
  gpio_set_level((gpio_num_t)41, 0);
  vTaskDelay(pdMS_TO_TICKS(100));

  ESP_LOGI(TAG, "Wait for %ds ..", modem_wait_seconds);
  vTaskDelay(pdMS_TO_TICKS(1000 * modem_wait_seconds));

  ESP_LOGI(TAG, "Check for modem ..");
  esp_err_t e;
  for (int i=0; i<modem_count_retries; i++) {
    e = esp_modem_sync(dce);
    if (e == ESP_OK) {
      ESP_LOGI(TAG, "%s: success after iteration %d", __FUNCTION__, i);
      return e;
    }
    vTaskDelay(pdMS_TO_TICKS(modem_retry_ms));
  }

espressif / esp-protocols

esp-modem next step : ppp auth ? (IDFGH-12496) #542

Answers checklist.

General issue report