Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

esp-idf dhcp client gives different ip each time we boot, arduino-esp32 does not #2182

Closed
korstiaanS opened this issue Jul 11, 2018 · 18 comments

Comments

@korstiaanS
Copy link

Hi,

We have the following problem:

ESP32 compiled with latest esp-idf on certain networks gets from the dhcp server each time we boot another ip address.
When we compile with latest arduino-esp32 with all the same hardware it runs fine and we get always the same ip -> like it should be.

Other facts:

  • DHCP client with esp-idf takes >5 sec. to get the ip. Compiled with arduino < 1 sec.
  • DHCP client on my home network works fine in both cases. (fast and always same IP). It only occurs on certain networks. (in our case our company network). I understand that it is not on all networks (like yours?) but why does the same hardware works fine on our network when it is compiled with the arduino-esp32. It means that there is a kind of incompability between these 2; esp-idf and our cisco infrastructure. Something that is fixed on the arduino-esp32.
  • See also github espressif/arduino-esp32 : issue # 1000 - Get new IP address each time the ESP32 gets started/reboot. They HAD that problem too! It seems to be fixed somewhere?
  • When compiled with esp-idf our DHCP server shows BAD_ADDRESS
    First boot
    1
    After second boot:
    2
    After third boot:
    3
    This is not happening with arduino-esp32.

I also added the 2 test projects, 1 for esp-idf and 1 for arduino-esp32:
simple_wifi.zip
WiFiClient.zip

This is the generated output from arduino (all tested with the same hardware):

FIRST BOOT:

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0018,len:4
load:0x3fff001c,len:808
load:0x40078000,len:6084
load:0x40080000,len:6696
entry 0x400802e4

Connecting to ATS E-Paper
..
WiFi connected
IP address: 
10.0.12.11

SECOND BOOT:

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0018,len:4
load:0x3fff001c,len:808
load:0x40078000,len:6084
load:0x40080000,len:6696
entry 0x400802e4


Connecting to ATS E-Paper
..
WiFi connected
IP address: 
10.0.12.11

THIRD BOOT:

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0018,len:4
load:0x3fff001c,len:808
load:0x40078000,len:6084
load:0x40080000,len:6696
entry 0x400802e4


Connecting to ATS E-Paper
..
WiFi connected
IP address: 
10.0.12.11

Each time same IP.
This is the output from esp-idf:

FIRST BOOT:

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5716
load:0x40078000,len:7684
ho 0 tail 12 room 4
load:0x40080000,len:7392
0x40080000: _iram_start at /Users/skor/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

entry 0x4008039c
0x4008039c: _UserExceptionVector at ??:?

I (30) boot: ESP-IDF v3.2-dev-144-g6ee3cf67 2nd stage bootloader
I (30) boot: compile time 15:14:08
I (32) boot: Enabling RNG early entropy source...
I (36) boot: SPI Speed      : 40MHz
I (40) boot: SPI Mode       : DIO
I (44) boot: SPI Flash Size : 8MB
I (48) boot: Partition Table:
I (52) boot: ## Label            Usage          Type ST Offset   Length
I (59) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (66) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (74) boot:  2 factory          factory app      00 00 00010000 00100000
I (81) boot: End of partition table
I (86) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x11734 ( 71476) map
I (120) esp_image: segment 1: paddr=0x0002175c vaddr=0x3ffb0000 size=0x034d8 ( 13528) load
I (125) esp_image: segment 2: paddr=0x00024c3c vaddr=0x3ffb34d8 size=0x00000 (     0) load
I (126) esp_image: segment 3: paddr=0x00024c44 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _iram_start at /Users/skor/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

I (136) esp_image: segment 4: paddr=0x0002504c vaddr=0x40080400 size=0x0afc4 ( 44996) load
I (163) esp_image: segment 5: paddr=0x00030018 vaddr=0x400d0018 size=0x61214 (397844) map
0x400d0018: _stext at ??:?

I (302) esp_image: segment 6: paddr=0x00091234 vaddr=0x4008b3c4 size=0x04fb4 ( 20404) load
0x4008b3c4: xQueueGenericReceive at /Users/skor/esp/esp-idf/components/freertos/queue.c:2037

I (311) esp_image: segment 7: paddr=0x000961f0 vaddr=0x400c0000 size=0x00000 (     0) load
I (312) esp_image: segment 8: paddr=0x000961f8 vaddr=0x50000000 size=0x00000 (     0) load
I (328) boot: Loaded app from partition at offset 0x10000
I (328) boot: Disabling RNG early entropy source...
I (330) cpu_start: Pro cpu up.
I (333) cpu_start: Starting app cpu, entry point is 0x40080fcc
0x40080fcc: call_start_cpu1 at /Users/skor/esp/esp-idf/components/esp32/cpu_start.c:225

I (0) cpu_start: App cpu up.
I (344) heap_init: Initializing. RAM available for dynamic allocation:
I (351) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (357) heap_init: At 3FFB94B8 len 00026B48 (154 KiB): DRAM
I (363) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (369) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (376) heap_init: At 40090378 len 0000FC88 (63 KiB): IRAM
I (382) cpu_start: Pro cpu start user code
I (65) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (112) simple wifi: ESP_WIFI_MODE_STA
I (112) wifi: wifi driver task: 3ffc0788, prio:23, stack:3584, core=0
I (112) wifi: wifi firmware version: 771f1dc
I (122) wifi: config NVS flash: enabled
I (122) wifi: config nano formating: disabled
I (122) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (132) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (162) wifi: Init dynamic tx buffer num: 32
I (162) wifi: Init data frame dynamic rx buffer num: 32
I (162) wifi: Init management frame dynamic rx buffer num: 32
I (172) wifi: Init static rx buffer size: 1600
I (172) wifi: Init static rx buffer num: 10
I (172) wifi: Init dynamic rx buffer num: 32
I (252) phy: phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 0
I (262) wifi: mode : sta (30:ae:a4:50:16:34)
I (262) simple wifi: wifi_init_sta finished.
I (262) simple wifi: connect to ap
I (382) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (1362) wifi: state: init -> auth (b0)
I (1372) wifi: state: auth -> assoc (0)
I (1382) wifi: state: assoc -> run (10)
I (1402) wifi: connected with ATS E-Paper, channel 1
I (1412) wifi: pm start, type: 1

I (12072) event: sta ip: 10.0.12.12, mask: 255.255.255.0, gw: 10.0.12.1
I (12072) simple wifi: got ip:10.0.12.12

SECOND BOOT:

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5716
load:0x40078000,len:7684
ho 0 tail 12 room 4
load:0x40080000,len:7392
0x40080000: _iram_start at /Users/skor/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

entry 0x4008039c
0x4008039c: _UserExceptionVector at ??:?

I (30) boot: ESP-IDF v3.2-dev-144-g6ee3cf67 2nd stage bootloader
I (30) boot: compile time 15:14:08
I (32) boot: Enabling RNG early entropy source...
I (36) boot: SPI Speed      : 40MHz
I (40) boot: SPI Mode       : DIO
I (44) boot: SPI Flash Size : 8MB
I (48) boot: Partition Table:
I (52) boot: ## Label            Usage          Type ST Offset   Length
I (59) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (66) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (74) boot:  2 factory          factory app      00 00 00010000 00100000
I (81) boot: End of partition table
I (86) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x11734 ( 71476) map
I (120) esp_image: segment 1: paddr=0x0002175c vaddr=0x3ffb0000 size=0x034d8 ( 13528) load
I (125) esp_image: segment 2: paddr=0x00024c3c vaddr=0x3ffb34d8 size=0x00000 (     0) load
I (126) esp_image: segment 3: paddr=0x00024c44 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _iram_start at /Users/skor/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

I (136) esp_image: segment 4: paddr=0x0002504c vaddr=0x40080400 size=0x0afc4 ( 44996) load
I (163) esp_image: segment 5: paddr=0x00030018 vaddr=0x400d0018 size=0x61214 (397844) map
0x400d0018: _stext at ??:?

I (302) esp_image: segment 6: paddr=0x00091234 vaddr=0x4008b3c4 size=0x04fb4 ( 20404) load
0x4008b3c4: xQueueGenericReceive at /Users/skor/esp/esp-idf/components/freertos/queue.c:2037

I (311) esp_image: segment 7: paddr=0x000961f0 vaddr=0x400c0000 size=0x00000 (     0) load
I (311) esp_image: segment 8: paddr=0x000961f8 vaddr=0x50000000 size=0x00000 (     0) load
I (328) boot: Loaded app from partition at offset 0x10000
I (328) boot: Disabling RNG early entropy source...
I (330) cpu_start: Pro cpu up.
I (333) cpu_start: Starting app cpu, entry point is 0x40080fcc
0x40080fcc: call_start_cpu1 at /Users/skor/esp/esp-idf/components/esp32/cpu_start.c:225

I (0) cpu_start: App cpu up.
I (344) heap_init: Initializing. RAM available for dynamic allocation:
I (351) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (357) heap_init: At 3FFB94B8 len 00026B48 (154 KiB): DRAM
I (363) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (369) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (376) heap_init: At 40090378 len 0000FC88 (63 KiB): IRAM
I (382) cpu_start: Pro cpu start user code
I (64) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (113) simple wifi: ESP_WIFI_MODE_STA
I (123) wifi: wifi driver task: 3ffc0704, prio:23, stack:3584, core=0
I (123) wifi: wifi firmware version: 771f1dc
I (123) wifi: config NVS flash: enabled
I (123) wifi: config nano formating: disabled
I (123) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (133) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (163) wifi: Init dynamic tx buffer num: 32
I (163) wifi: Init data frame dynamic rx buffer num: 32
I (163) wifi: Init management frame dynamic rx buffer num: 32
I (173) wifi: Init static rx buffer size: 1600
I (173) wifi: Init static rx buffer num: 10
I (183) wifi: Init dynamic rx buffer num: 32
I (263) phy: phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 0
I (263) wifi: mode : sta (30:ae:a4:50:16:34)
I (263) simple wifi: wifi_init_sta finished.
I (263) simple wifi: connect to ap
I (383) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (1363) wifi: state: init -> auth (b0)
I (1373) wifi: state: auth -> assoc (0)
I (1373) wifi: state: assoc -> run (10)
I (1393) wifi: connected with ATS E-Paper, channel 1
I (1403) wifi: pm start, type: 1

I (12073) event: sta ip: 10.0.12.13, mask: 255.255.255.0, gw: 10.0.12.1
I (12073) simple wifi: got ip:10.0.12.13

THIRD BOOT:

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5716
load:0x40078000,len:7684
ho 0 tail 12 room 4
load:0x40080000,len:7392
0x40080000: _iram_start at /Users/skor/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

entry 0x4008039c
0x4008039c: _UserExceptionVector at ??:?

I (30) boot: ESP-IDF v3.2-dev-144-g6ee3cf67 2nd stage bootloader
I (30) boot: compile time 15:14:08
I (32) boot: Enabling RNG early entropy source...
I (36) boot: SPI Speed      : 40MHz
I (40) boot: SPI Mode       : DIO
I (44) boot: SPI Flash Size : 8MB
I (48) boot: Partition Table:
I (52) boot: ## Label            Usage          Type ST Offset   Length
I (59) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (66) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (74) boot:  2 factory          factory app      00 00 00010000 00100000
I (81) boot: End of partition table
I (86) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x11734 ( 71476) map
I (120) esp_image: segment 1: paddr=0x0002175c vaddr=0x3ffb0000 size=0x034d8 ( 13528) load
I (125) esp_image: segment 2: paddr=0x00024c3c vaddr=0x3ffb34d8 size=0x00000 (     0) load
I (126) esp_image: segment 3: paddr=0x00024c44 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _iram_start at /Users/skor/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

I (136) esp_image: segment 4: paddr=0x0002504c vaddr=0x40080400 size=0x0afc4 ( 44996) load
I (163) esp_image: segment 5: paddr=0x00030018 vaddr=0x400d0018 size=0x61214 (397844) map
0x400d0018: _stext at ??:?

I (302) esp_image: segment 6: paddr=0x00091234 vaddr=0x4008b3c4 size=0x04fb4 ( 20404) load
0x4008b3c4: xQueueGenericReceive at /Users/skor/esp/esp-idf/components/freertos/queue.c:2037

I (311) esp_image: segment 7: paddr=0x000961f0 vaddr=0x400c0000 size=0x00000 (     0) load
I (311) esp_image: segment 8: paddr=0x000961f8 vaddr=0x50000000 size=0x00000 (     0) load
I (328) boot: Loaded app from partition at offset 0x10000
I (328) boot: Disabling RNG early entropy source...
I (330) cpu_start: Pro cpu up.
I (333) cpu_start: Starting app cpu, entry point is 0x40080fcc
0x40080fcc: call_start_cpu1 at /Users/skor/esp/esp-idf/components/esp32/cpu_start.c:225

I (0) cpu_start: App cpu up.
I (344) heap_init: Initializing. RAM available for dynamic allocation:
I (351) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (357) heap_init: At 3FFB94B8 len 00026B48 (154 KiB): DRAM
I (363) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (369) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (376) heap_init: At 40090378 len 0000FC88 (63 KiB): IRAM
I (382) cpu_start: Pro cpu start user code
I (64) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (113) simple wifi: ESP_WIFI_MODE_STA
I (123) wifi: wifi driver task: 3ffc0704, prio:23, stack:3584, core=0
I (123) wifi: wifi firmware version: 771f1dc
I (123) wifi: config NVS flash: enabled
I (123) wifi: config nano formating: disabled
I (123) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (133) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (163) wifi: Init dynamic tx buffer num: 32
I (163) wifi: Init data frame dynamic rx buffer num: 32
I (163) wifi: Init management frame dynamic rx buffer num: 32
I (173) wifi: Init static rx buffer size: 1600
I (173) wifi: Init static rx buffer num: 10
I (183) wifi: Init dynamic rx buffer num: 32
I (263) phy: phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 0
I (263) wifi: mode : sta (30:ae:a4:50:16:34)
I (263) simple wifi: wifi_init_sta finished.
I (263) simple wifi: connect to ap
I (383) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (1363) wifi: state: init -> auth (b0)
I (1373) wifi: state: auth -> assoc (0)
I (1373) wifi: state: assoc -> run (10)
I (1393) wifi: connected with ATS E-Paper, channel 1
I (1403) wifi: pm start, type: 1

I (12073) event: sta ip: 10.0.12.13, mask: 255.255.255.0, gw: 10.0.12.1
I (12073) simple wifi: got ip:10.0.12.13
ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5716
load:0x40078000,len:7684
ho 0 tail 12 room 4
load:0x40080000,len:7392
0x40080000: _iram_start at /Users/skor/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

entry 0x4008039c
0x4008039c: _UserExceptionVector at ??:?

I (30) boot: ESP-IDF v3.2-dev-144-g6ee3cf67 2nd stage bootloader
I (30) boot: compile time 15:14:08
I (32) boot: Enabling RNG early entropy source...
I (36) boot: SPI Speed      : 40MHz
I (40) boot: SPI Mode       : DIO
I (44) boot: SPI Flash Size : 8MB
I (48) boot: Partition Table:
I (52) boot: ## Label            Usage          Type ST Offset   Length
I (59) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (66) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (74) boot:  2 factory          factory app      00 00 00010000 00100000
I (81) boot: End of partition table
I (86) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x11734 ( 71476) map
I (120) esp_image: segment 1: paddr=0x0002175c vaddr=0x3ffb0000 size=0x034d8 ( 13528) load
I (125) esp_image: segment 2: paddr=0x00024c3c vaddr=0x3ffb34d8 size=0x00000 (     0) load
I (126) esp_image: segment 3: paddr=0x00024c44 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _iram_start at /Users/skor/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

I (136) esp_image: segment 4: paddr=0x0002504c vaddr=0x40080400 size=0x0afc4 ( 44996) load
I (163) esp_image: segment 5: paddr=0x00030018 vaddr=0x400d0018 size=0x61214 (397844) map
0x400d0018: _stext at ??:?

I (302) esp_image: segment 6: paddr=0x00091234 vaddr=0x4008b3c4 size=0x04fb4 ( 20404) load
0x4008b3c4: xQueueGenericReceive at /Users/skor/esp/esp-idf/components/freertos/queue.c:2037

I (311) esp_image: segment 7: paddr=0x000961f0 vaddr=0x400c0000 size=0x00000 (     0) load
I (312) esp_image: segment 8: paddr=0x000961f8 vaddr=0x50000000 size=0x00000 (     0) load
I (328) boot: Loaded app from partition at offset 0x10000
I (328) boot: Disabling RNG early entropy source...
I (330) cpu_start: Pro cpu up.
I (333) cpu_start: Starting app cpu, entry point is 0x40080fcc
0x40080fcc: call_start_cpu1 at /Users/skor/esp/esp-idf/components/esp32/cpu_start.c:225

I (0) cpu_start: App cpu up.
I (344) heap_init: Initializing. RAM available for dynamic allocation:
I (351) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (357) heap_init: At 3FFB94B8 len 00026B48 (154 KiB): DRAM
I (363) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (369) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (376) heap_init: At 40090378 len 0000FC88 (63 KiB): IRAM
I (382) cpu_start: Pro cpu start user code
I (65) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (89) simple wifi: ESP_WIFI_MODE_STA
I (89) wifi: wifi driver task: 3ffc0788, prio:23, stack:3584, core=0
I (89) wifi: wifi firmware version: 771f1dc
I (89) wifi: config NVS flash: enabled
I (99) wifi: config nano formating: disabled
I (99) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (109) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (139) wifi: Init dynamic tx buffer num: 32
I (139) wifi: Init data frame dynamic rx buffer num: 32
I (139) wifi: Init management frame dynamic rx buffer num: 32
I (139) wifi: Init static rx buffer size: 1600
I (149) wifi: Init static rx buffer num: 10
I (149) wifi: Init dynamic rx buffer num: 32
I (229) phy: phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 0
I (229) wifi: mode : sta (30:ae:a4:50:16:34)
I (229) simple wifi: wifi_init_sta finished.
I (239) simple wifi: connect to ap
I (359) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (1339) wifi: state: init -> auth (b0)
I (1339) wifi: state: auth -> assoc (0)
I (1349) wifi: state: assoc -> run (10)
I (1369) wifi: connected with ATS E-Paper, channel 1
I (1379) wifi: pm start, type: 1

I (12049) event: sta ip: 10.0.12.14, mask: 255.255.255.0, gw: 10.0.12.1
I (12049) simple wifi: got ip:10.0.12.14

Please help to get this fixed!
Korstiaan

@korstiaanS
Copy link
Author

The logs on for the good version (arduino compile) shows on the dhcp server: (only renew)

arduino

The bad version (esp-idf) shows: (assign - renew)

esp-idf

@me-no-dev
Copy link
Member

me-no-dev commented Jul 11, 2018

@korstiaanS please try the following two functions (replace them in your code) and since you have a reliable way to reproduce it (I could not) I would ask you to please try and figure out which line/order of items is triggering it. The two functions are a simplified version of WiFi.connect(ssid, pass)

static esp_err_t event_handler(void *ctx, system_event_t *event)
{
    switch(event->event_id) {
    case SYSTEM_EVENT_STA_GOT_IP:
        ESP_LOGI(TAG, "got ip:%s",
                 ip4addr_ntoa(&event->event_info.got_ip.ip_info.ip));
        xEventGroupSetBits(wifi_event_group, WIFI_CONNECTED_BIT);
        break;
    case SYSTEM_EVENT_STA_DISCONNECTED:
        ESP_LOGW(TAG, "disconnected: %u",
                 event->event_info.disconnected.reason);
        esp_wifi_connect();
        xEventGroupClearBits(wifi_event_group, WIFI_CONNECTED_BIT);
        break;
    default:
        break;
    }
    return ESP_OK;
}

void wifi_init_sta(){
    wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT();

    wifi_config_t conf;
    memset(&conf, 0, sizeof(wifi_config_t));
    strcpy((char*)(conf.sta.ssid), EXAMPLE_ESP_WIFI_SSID);
    strcpy((char*)(conf.sta.password), EXAMPLE_ESP_WIFI_PASS);

    wifi_event_group = xEventGroupCreate();
    ESP_ERROR_CHECK(esp_event_loop_init(event_handler, NULL));
    tcpip_adapter_init();
    ESP_ERROR_CHECK(esp_wifi_init(&cfg));
    ESP_ERROR_CHECK(esp_wifi_start());
    ESP_ERROR_CHECK(esp_wifi_set_mode(WIFI_MODE_STA));
    ESP_ERROR_CHECK(esp_wifi_set_config(WIFI_IF_STA, &conf));

    esp_err_t err = tcpip_adapter_dhcpc_start(TCPIP_ADAPTER_IF_STA);
    if(err == ESP_ERR_TCPIP_ADAPTER_DHCPC_START_FAILED){
        ESP_ERROR_CHECK(err);
    }

    ESP_ERROR_CHECK(esp_wifi_connect());
    ESP_LOGI(TAG, "wifi_init_sta finished.");
    ESP_LOGI(TAG, "connect to ap");
}

@korstiaanS
Copy link
Author

Hi,

Same result.
Output:

First boot:

I (0) cpu_start: App cpu up.
I (344) heap_init: Initializing. RAM available for dynamic allocation:
I (351) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (357) heap_init: At 3FFB94B8 len 00026B48 (154 KiB): DRAM
I (363) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (370) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (376) heap_init: At 40090378 len 0000FC88 (63 KiB): IRAM
I (382) cpu_start: Pro cpu start user code
I (65) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (113) simple wifi: ESP_WIFI_MODE_STA
I (123) wifi: wifi driver task: 3ffc0704, prio:23, stack:3584, core=0
I (123) wifi: wifi firmware version: 771f1dc
I (123) wifi: config NVS flash: enabled
I (123) wifi: config nano formating: disabled
I (123) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (133) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (163) wifi: Init dynamic tx buffer num: 32
I (163) wifi: Init data frame dynamic rx buffer num: 32
I (163) wifi: Init management frame dynamic rx buffer num: 32
I (173) wifi: Init static rx buffer size: 1600
I (173) wifi: Init static rx buffer num: 10
I (183) wifi: Init dynamic rx buffer num: 32
I (243) phy: phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 0
I (243) wifi: mode : sta (30:ae:a4:50:16:34)
I (263) simple wifi: wifi_init_sta finished.
I (263) simple wifi: connect to ap
I (383) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (1373) wifi: state: init -> auth (b0)
I (1373) wifi: state: auth -> assoc (0)
I (1373) wifi: state: assoc -> run (10)
I (1413) wifi: connected with ATS E-Paper, channel 1
I (1413) wifi: pm start, type: 1

I (12083) event: sta ip: 10.0.12.12, mask: 255.255.255.0, gw: 10.0.12.1
I (12083) simple wifi: got ip:10.0.12.12

Second boot:

I (0) cpu_start: App cpu up.
I (344) heap_init: Initializing. RAM available for dynamic allocation:
I (351) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (357) heap_init: At 3FFB94B8 len 00026B48 (154 KiB): DRAM
I (363) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (370) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (376) heap_init: At 40090378 len 0000FC88 (63 KiB): IRAM
I (382) cpu_start: Pro cpu start user code
I (65) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (89) simple wifi: ESP_WIFI_MODE_STA
I (89) wifi: wifi driver task: 3ffc0704, prio:23, stack:3584, core=0
I (89) wifi: wifi firmware version: 771f1dc
I (89) wifi: config NVS flash: enabled
I (99) wifi: config nano formating: disabled
I (99) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (109) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (139) wifi: Init dynamic tx buffer num: 32
I (139) wifi: Init data frame dynamic rx buffer num: 32
I (139) wifi: Init management frame dynamic rx buffer num: 32
I (139) wifi: Init static rx buffer size: 1600
I (149) wifi: Init static rx buffer num: 10
I (149) wifi: Init dynamic rx buffer num: 32
I (219) phy: phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 0
I (219) wifi: mode : sta (30:ae:a4:50:16:34)
I (239) simple wifi: wifi_init_sta finished.
I (239) simple wifi: connect to ap
I (359) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (1339) wifi: state: init -> auth (b0)
I (1359) wifi: state: auth -> assoc (0)
I (1359) wifi: state: assoc -> run (10)
I (1379) wifi: connected with ATS E-Paper, channel 1
I (1509) wifi: pm start, type: 1

I (12069) event: sta ip: 10.0.12.13, mask: 255.255.255.0, gw: 10.0.12.1
I (12069) simple wifi: got ip:10.0.12.13

@me-no-dev
Copy link
Member

OK, new idea :) since it looks like the only difference left. Arduino spins a task from app_main and does everything in that task. Can you test that? The code otherwise is 1:1 what Arduino executes when starting STA

@korstiaanS
Copy link
Author

void wifi_task(void *_args) {
    wifi_init_sta();
    while (1) {
        vTaskDelay(1000 / portTICK_PERIOD_MS);
    }
}

void app_main()
{
    //Initialize NVS
    esp_err_t ret = nvs_flash_init();
    if (ret == ESP_ERR_NVS_NO_FREE_PAGES) {
      ESP_ERROR_CHECK(nvs_flash_erase());
      ret = nvs_flash_init();
    }
    ESP_ERROR_CHECK(ret);
    ESP_LOGI(TAG, "ESP_WIFI_MODE_STA");
    xTaskCreate(wifi_task, "Wifi task", 2048, NULL, 2, NULL);
}

No.
Same result; slow and new ip.
wifi_init_sta() is being called from within a task.
Anyway, I'm coming from a project with Espressif/Homekit on gitlab (using the SDK from Espressif/Homekit) and I think it is in a task there as well.

@korstiaanS
Copy link
Author

Has nothing to do with esp but they had simular problems.
Look at the last 2 posts. Can maybe of help?

http://forums.netduino.com/index.php?/topic/614-dhcp-getting-different-ip-address-each-time-i-restart/

@me-no-dev
Copy link
Member

OK Then... maybe there is something in menuconfig causing this issue? Can you try Arduino's sdkconfig and see if there are any differences (there are some DHCP/ARP options in menuconfig).
Arduino's sdkconfig is here: https://github.com/espressif/arduino-esp32/blob/master/tools/sdk/sdkconfig

@korstiaanS
Copy link
Author

(Yes, parameters. I asked this already on the Homekit issues that it might be a parameter...)

Hi, yes, I found it!
If I change parameter CONFIG_LWIP_DHCP_DOES_ARP_CHECK (it calls DHCP: Perform ARP check on any offered address in the menuconfig) from yes to no it works!
DHCP is quick and I get the same IP every time!
So, defaults between arduino-esp32 and esp-idf are not the same.
So, this is the conflicting parameter in our situation?

Solved?

@me-no-dev
Copy link
Member

Yes :) it just took a couple of back and fourth to figure out what could be it. I will ask the default value to be changed to no. And now we will know what could be the reason for the future.

Thanks @korstiaanS for sticking with it and helping debug the issue!

@korstiaanS
Copy link
Author

Thank you for helping solving this problem!
We can continue now with our Homekit (and other) ESP projects.

PS: Espressif/ESP is for me one of best inventions of the last decade. Congrats to all of you for bringing such beautifull products.

@me-no-dev
Copy link
Member

Closing this now as resolved :) ping us back if we can help with anything else

@negativekelvin
Copy link
Contributor

negativekelvin commented Jul 13, 2018

So is there something on the network that is actually replying to the arp request saying the IP is in use?

Maybe this: http://lwip.100.n7.nabble.com/broken-DHCP-ARP-interaction-tp22638p22739.html

@me-no-dev
Copy link
Member

some routers/ap are reported to reply on behalf of the client, so that is probably what is happening.

@negativekelvin
Copy link
Contributor

Note that the lwIP DHCP code does not notice that the ARP response contains its own MAC address in all fields; it simply acts on it.

This sounds fixable

@tynx
Copy link

tynx commented Oct 1, 2018

I use arduino-esp32 and it worked flawlessly until recently, where I did notice that on networks with ARP-caching that DHCP it is not working.

Took me quite some time to figure out why LWIP DECLINES an ACKd IP.

@me-no-dev Wouldn't it be possible to do an MAC-address check (e.g. check if it's own address), so that IF routers/APs reply on behalf of the client, the DHCP still works? Or is there a technical reasoning why this isn't happening/done?

To me: It absolutely makes no sense, especially in cases like mine, where I quite regularly reboot the ESP32 because of battery-saving.

@me-no-dev
Copy link
Member

@tynx can you please take tcpdump of the exchange? We recently updated LwIP to 2.0.3 and I guess that the issue is a result of that. A dump can help trace the packet through the code :)

@tynx
Copy link

tynx commented Oct 2, 2018

image

So I went into the code and saw that only this line can be the reason for it:
https://github.com/espressif/esp-lwip/blob/3b88e84f9b05e76a1ad96e6650a795df74af23aa/src/core/ipv4/dhcp.c#L980

At least if you trust the search-engine of github.

So it has to be in dhcp_arp_reply
https://github.com/espressif/esp-lwip/blob/3b88e84f9b05e76a1ad96e6650a795df74af23aa/src/core/ipv4/dhcp.c#L963

and if I understand the code correctly we do a check if the IP is already used in the network. If another device uses that IP it will respond to the ARP-request leading to LWIP to decline the ACKd IP.

The fun part is, that this is not an issue, as LWIP will not respond to an ARP request from itself, so no worries there. But if an AP/station/network-component answers on behalf of the client (which seems to be a feature called ARP-caching?) then the LWIP declines the IP because an ARP-Reply with the MAC of itself.

As far as I can tell it would be possible to do an MAC-address comparison (does not equal) on line https://github.com/espressif/esp-lwip/blob/3b88e84f9b05e76a1ad96e6650a795df74af23aa/src/core/ipv4/dhcp.c#L976 and the problem should be gone. But I might be wrong? If you want I can try to implement it and do a PR?

@negativekelvin
Copy link
Contributor

negativekelvin commented Oct 2, 2018

You should probably do the filtering in etharp_input

https://gist.github.com/negativekelvin/0373847ebc5d47bd14baee7f21423f86/revisions

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants