search

esphome / issues

Issue Tracker for ESPHome
https://esphome.io/
292 stars 36 forks source link

WT32-eth01 ethernet and bluetooth incompatibility: [Errno 111] Connect call failed #4671

Open clau-bucur opened 1 year ago

clau-bucur commented 1 year ago

The problem

If I enable both ethernet and a bluetooth component (like esp32_ble_tracker or bluetooth_proxy), the device becomes unavailable. It shows online, I can upload firmware, but no sensors are imported and log is not available.

Once the bluetooth components are removed, the device becomes available and log is shown as expected.

Which version of ESPHome has the issue?

2023.6.4

What type of installation are you using?

Home Assistant Add-on

Which version of Home Assistant has the issue?

2023.7.1

What platform are you using?

ESP32-IDF

Board

WT32-eth01

Component causing the issue

ethernet

Example YAML snippet

esphome:
  name: "bleproxyeth"
  friendly_name: BLE Proxy ETH

esp32:
  board: esp-wrover-kit
  framework:
    type: esp-idf

# Enable logging
logger:

ethernet:
  type: LAN8720
  mdc_pin: GPIO23
  mdio_pin: GPIO18
  clk_mode: GPIO0_IN
  phy_addr: 1
  power_pin: GPIO16
  use_address: 10.100.2.52

# Enable Home Assistant API
api:

ota:

esp32_ble_tracker:
  scan_parameters:
    interval: 1100ms
    window: 1100ms
    active: true

bluetooth_proxy:
  active: true

Anything in the logs that might be useful for us?

Once bluetooth components are removed, the device is reachable again.

INFO ESPHome 2023.6.4
INFO Reading configuration /config/esphome/ble-proxy-eth.yaml...
INFO Starting log output from 10.100.2.52 using esphome API
INFO Successfully connected to 10.100.2.52
[16:46:41][I][app:102]: ESPHome version 2023.6.4 compiled on Jul  7 2023, 16:45:21
[16:46:41][I][app:104]: Project esphome.bluetooth-proxy version 1.0
[16:46:41][C][logger:301]: Logger:
[16:46:41][C][logger:302]:   Level: DEBUG
[16:46:41][C][logger:303]:   Log Baud Rate: 115200
[16:46:41][C][logger:305]:   Hardware UART: UART0
[16:46:41][C][ethernet:179]: Ethernet:
[16:46:41][C][ethernet:306]:   IP Address: 10.100.2.52
[16:46:41][C][ethernet:307]:   Hostname: 'bleproxyeth'
[16:46:41][C][ethernet:308]:   Subnet: 255.255.255.0
[16:46:41][C][ethernet:309]:   Gateway: 10.100.2.254
[16:46:41][C][ethernet:318]:   DNS1: 10.100.0.1
[16:46:41][C][ethernet:319]:   DNS2: 0.0.0.0
[16:46:41][C][ethernet:327]:   MAC Address: 0C:B8:15:4D:08:A7
[16:46:41][C][ethernet:332]:   Is Full Duplex: YES
[16:46:41][C][ethernet:337]:   Link Speed: 100
[16:46:41][C][ethernet:182]:   Power Pin: 16
[16:46:41][C][ethernet:184]:   MDC Pin: 23
[16:46:41][C][ethernet:185]:   MDIO Pin: 18
[16:46:41][C][ethernet:186]:   Type: LAN8720
[16:46:41][C][ethernet:187]:   PHY addr: 1
[16:46:41][C][mdns:112]: mDNS:
[16:46:41][C][mdns:113]:   Hostname: bleproxyeth
[16:46:41][C][ota:093]: Over-The-Air Updates:
[16:46:41][C][ota:094]:   Address: 10.100.2.52:3232
[16:46:41][C][api:138]: API Server:
[16:46:41][C][api:139]:   Address: 10.100.2.52:6053
[16:46:41][C][api:143]:   Using noise encryption: NO

Additional information

It shows online in ESPHome dashboard. image

But log not reachable, and device does not appear in Home Assistant discovery. image

randybb commented 1 year ago

Can you get log from that device? Because this is not very helpful. I have only olimex esp32-poe-iso with the same eth phy and it works just fine with ble proxy/tracker. esphome mcu's and HA are in the same network so I can fully rely on mDNS.

clau-bucur commented 1 year ago

I'm trying now to get the logs via MQTT, let's see if that works. Do you have some other suggestion? As I can't connect to the log from the ESPHome dashboard.

clau-bucur commented 1 year ago

As suspected, once bluetooth is enabled the MQTT component is not dumping data also. I disabled bluetooth and I had MQTT logs, then I re-enabled bluetooth and uploaded the firmware. You can see here the logs, before rebooting with bluetooth enabled. After it rebooted, the MQTT status remained offline for this device, and no more log entries appeared.

[I][ethernet:361]: Powering down ethernet PHY
07/07/2023 8:52:04 PM(-0.05 seconds) 
[D][esp-idf:000]: I (143972) MQTT_CLIENT: Client asked to disconnect

07/07/2023 8:52:04 PM(-0 seconds) 
[D][esp32.preferences:143]: Saving 1 preferences to flash: 0 cached, 1 written, 0 failed
07/07/2023 8:52:04 PM(-0 seconds) 
[D][esp32.preferences:114]: Saving 1 preferences to flash...
07/07/2023 8:52:04 PM(-0.05 seconds) 
[I][app:134]: Rebooting safely...
07/07/2023 8:52:04 PM(-0.1 seconds) 
[I][ota:349]: OTA update finished!
07/07/2023 8:52:04 PM(-0.11 seconds) 
[D][esp-idf:000]: I (143741) esp_image: segment 4: paddr=002e1f4c vaddr=40088a00 size=1013ch ( 65852) 

07/07/2023 8:52:04 PM(-0.27 seconds) 
[D][esp-idf:000]: I (143457) esp_image: segment 3: paddr=00210020 vaddr=400d0020 size=d1f24h (859940) map

07/07/2023 8:52:04 PM(-0 seconds) 
[D][esp-idf:000]: I (143440) esp_image: segment 2: paddr=00207618 vaddr=40080000 size=08a00h ( 35328) 

07/07/2023 8:52:04 PM(-0.05 seconds) 
[D][esp-idf:000]: I (143427) esp_image: segment 1: paddr=002026a8 vaddr=3ffbdb60 size=04f68h ( 20328) 

07/07/2023 8:52:04 PM(-0.05 seconds) 
[D][esp-idf:000]: I (143355) esp_image: segment 0: paddr=001d0020 vaddr=3f400020 size=32680h (206464) map

07/07/2023 8:52:04 PM(-0.05 seconds) 
[D][esp-idf:000]: I (143326) esp_image: segment 4: paddr=002e1f4c vaddr=40088a00 size=1013ch ( 65852) 

07/07/2023 8:52:03 PM(-0.26 seconds) 
[D][esp-idf:000]: I (143042) esp_image: segment 3: paddr=00210020 vaddr=400d0020 size=d1f24h (859940) map

07/07/2023 8:52:03 PM(-0 seconds) 
[D][esp-idf:000]: I (143025) esp_image: segment 2: paddr=00207618 vaddr=40080000 size=08a00h ( 35328) 

07/07/2023 8:52:03 PM(-0.06 seconds) 
[D][esp-idf:000]: I (143013) esp_image: segment 1: paddr=002026a8 vaddr=3ffbdb60 size=04f68h ( 20328) 

07/07/2023 8:52:03 PM(-0.08 seconds) 
[D][esp-idf:000]: I (142939) esp_image: segment 0: paddr=001d0020 vaddr=3f400020 size=32680h (206464) map

07/07/2023 8:52:03 PM(-0.39 seconds) 
[D][ota:316]: OTA in progress: 90.6%
07/07/2023 8:52:02 PM(-1.02 seconds) 
[D][ota:316]: OTA in progress: 68.1%
07/07/2023 8:52:01 PM(-1 seconds) 
[D][ota:316]: OTA in progress: 45.5%
07/07/2023 8:52:00 PM(-1 seconds) 
[D][ota:316]: OTA in progress: 22.8%
07/07/2023 8:51:59 PM(-1 seconds) 
[D][ota:316]: OTA in progress: 0.1%
07/07/2023 8:51:55 PM(-4.19 seconds) 
[D][ota:147]: Starting OTA Update from 10.100.2.1...

BTW, I'm on the same network myself with HA and the device, so that's not it.

randybb commented 1 year ago

Can you get logs from uart?

If everything is on the same network, then use_address: (the dashboard uses it as the device address when mDNS is not available) is not needed.

clau-bucur commented 1 year ago

Not easy getting the logs because it simply does not output anything. I added a 5 second timer to log something but it's not showing up.

At some point I left the log console open and I had this, but I was not able to reproduce it yet.

I (466) esp_image: segment 4: paddr=000f1074 vaddr=40080758 size=17f78h ( 98168) load
I (519) boot: Loaded app from partition at offset 0x10000
I (519) boot: Disabling RNG early entropy source...
I (530) cpu_start: Pro cpu up.
I (531) cpu_start: Starting app cpu, entry point is 0x4008226c
I (517) cpu_start: App cpu up.
I (547) cpu_start: Pro cpu start user code
I (547) cpu_start: cpu freq: 160000000
I (547) cpu_start: Application information:
I (552) cpu_start: Project name:     bleproxyethtest
I (557) cpu_start: App version:      2023.6.4
I (562) cpu_start: Compile time:     Jul  9 2023 23:22:29
I (568) cpu_start: ELF file SHA256:  242aeef5548f17cb...
I (574) cpu_start: ESP-IDF:          4.4.4
I (579) heap_init: Initializing. RAM available for dynamic allocation:
I (586) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (592) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (598) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (605) heap_init: At 3FFC9CC0 len 00016340 (88 KiB): DRAM
I (611) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (617) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (624) heap_init: At 400986D0 len 00007930 (30 KiB): IRAM
I (631) spi_flash: detected chip: generic
I (635) spi_flash: flash io: dio
I (640) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
[I][logger:262]: Log initialized
[C][ota:469]: There have been 9 suspected unsuccessful boot attempts.
[D][esp32.preferences:114]: Saving 1 preferences to flash...
[D][esp32.preferences:143]: Saving 1 preferences to flash: 0 cached, 1 written, 0 failed
[I][app:029]: Running through setup()...
[C][esp32_ble:027]: Setting up BLE...
[D][esp-idf:000]: I (1108) BTDM_INIT: BT controller compile version [8020d24]

[D][esp-idf:000]: I (1111) system_api: Base MAC address is not set

[D][esp-idf:000]: I (1121) system_api: read default base MAC address from EFUSE

[D][esp-idf:000]: I (1134) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07

[D][esp-idf:000]: W (1141) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration

Brownout detector was triggered

ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_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:0x3fff0030,len:6660
load:0x40078000,len:14944
ho 0 tail 12 room 4
load:0x40080400,len:3816
entry 0x40080698
I (29) boot: ESP-IDF 4.4.4 2nd stage bootloader
I (29) boot: compile time 22:55:26
I (29) boot: chip revision: v1.0
I (32) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (39) boot.esp32: SPI Speed      : 40MHz
I (44) boot.esp32: SPI Mode       : DIO
I (48) boot.esp32: SPI Flash Size : 4MB
I (53) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (62) boot: ## Label            Usage          Type ST Offset   Length
I (69) boot:  0 otadata          OTA data         01 00 00009000 00002000
I (76) boot:  1 phy_init         RF data          01 01 0000b000 00001000
I (84) boot:  2 app0             OTA app          00 10 00010000 001c0000
I (91) boot:  3 app1             OTA app          00 11 001d0000 001c0000
I (99) boot:  4 nvs              WiFi data        01 02 00390000 0006d000
I (106) boot: End of partition table
I (111) boot_comm: chip revision: 1, min. application chip revision: 0
I (118) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=2a9a8h (174504) map
I (189) esp_image: segment 1: paddr=0003a9d0 vaddr=3ffbdb60 size=04ee8h ( 20200) load
I (198) esp_image: segment 2: paddr=0003f8c0 vaddr=40080000 size=00758h (  1880) load
I (199) esp_image: segment 3: paddr=00040020 vaddr=400d0020 size=b104ch (725068) map
I (466) esp_image: segment 4: paddr=000f1074 vaddr=40080758 size=17f78h ( 98168) load
I (519) boot: Loaded app from partition at offset 0x10000
I (519) boot: Disabling RNG early entropy source...
I (530) cpu_start: Pro cpu up.
I (531) cpu_start: Starting app cpu, entry point is 0x4008226c
I (517) cpu_start: App cpu up.
I (547) cpu_start: Pro cpu start user code
I (547) cpu_start: cpu freq: 160000000
I (547) cpu_start: Application information:
I (552) cpu_start: Project name:     bleproxyethtest
I (557) cpu_start: App version:      2023.6.4
I (562) cpu_start: Compile time:     Jul  9 2023 23:22:29
I (568) cpu_start: ELF file SHA256:  242aeef5548f17cb...
I (574) cpu_start: ESP-IDF:          4.4.4
I (579) heap_init: Initializing. RAM available for dynamic allocation:
I (586) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (592) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (598) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (605) heap_init: At 3FFC9CC0 len 00016340 (88 KiB): DRAM
I (611) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (617) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (624) heap_init: At 400986D0 len 00007930 (30 KiB): IRAM
I (631) spi_flash: detected chip: generic
I (635) spi_flash: flash io: dio
I (640) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.

Let me know if this is helpful in any way.

I have this code on the device. When I leave bluetooth active, I have no log on UART. Once I remove bluetooth, I get the "I'm alive" output.

substitutions:
  name: bleproxyethtest
  friendly_name: BLE Proxy ETH TEST

esphome:
  name: ${name}
  friendly_name: ${friendly_name}

esp32:
  board: esp32doit-devkit-v1
  framework:
    type: esp-idf

ethernet:
  type: LAN8720
  mdc_pin: GPIO23
  mdio_pin: GPIO18
  clk_mode: GPIO0_IN
  phy_addr: 1
  power_pin: GPIO16

api:
logger:
ota:

# esp32_ble_tracker:
#   scan_parameters:
#     interval: 1100ms
#     window: 1100ms
#     active: true

# bluetooth_proxy:
#   active: true

interval:
  - interval: 5s
    then:
      - logger.log: I'm alive
randybb commented 1 year ago

"Brownout detector was triggered" => system voltage is below threshold, so your PSU is not providing enough power.

clau-bucur commented 1 year ago

Sorry for the delay. I have changed the PSU to a 10A one. Back then it was powered directly from the FT232 adapter (though I don't see why it won't be enough).

I have another set of logs and a recording of what I've done. First I enabled only ethernet and I was able to get the logs via the network. Secondly I enabled bluetooth and was unable to connect to logs via the network so I connected via UART.

Entire log file: ble-proxy-eth-test_logs.txt

It reboots in a cycle:

ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_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:0x3fff0030,len:6660
load:0x40078000,len:14944
ho 0 tail 12 room 4
load:0x40080400,len:3816
entry 0x40080698
I (29) boot: ESP-IDF 4.4.4 2nd stage bootloader
I (29) boot: compile time 11:54:13
I (29) boot: chip revision: v1.0
I (32) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (39) boot.esp32: SPI Speed      : 40MHz
I (44) boot.esp32: SPI Mode       : DIO
I (48) boot.esp32: SPI Flash Size : 4MB
I (53) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (62) boot: ## Label            Usage          Type ST Offset   Length
I (69) boot:  0 otadata          OTA data         01 00 00009000 00002000
I (76) boot:  1 phy_init         RF data          01 01 0000b000 00001000
I (84) boot:  2 app0             OTA app          00 10 00010000 001c0000
I (91) boot:  3 app1             OTA app          00 11 001d0000 001c0000
I (99) boot:  4 nvs              WiFi data        01 02 00390000 0006d000
I (106) boot: End of partition table
I (111) boot_comm: chip revision: 1, min. application chip revision: 0
I (118) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=2a8f0h (174320) map
I (189) esp_image: segment 1: paddr=0003a918 vaddr=3ffb0000 size=04ee8h ( 20200) load
I (198) esp_image: segment 2: paddr=0003f808 vaddr=40080000 size=00810h (  2064) load
I (199) esp_image: segment 3: paddr=00040020 vaddr=400d0020 size=b0ad4h (723668) map
I (465) esp_image: segment 4: paddr=000f0afc vaddr=40080810 size=17ec0h ( 97984) load
I (518) boot: Loaded app from partition at offset 0x10000
I (518) boot: Disabling RNG early entropy source...
I (530) cpu_start: Pro cpu up.
I (530) cpu_start: Starting app cpu, entry point is 0x4008226c
I (516) cpu_start: App cpu up.
I (546) cpu_start: Pro cpu start user code
I (546) cpu_start: cpu freq: 160000000
I (547) cpu_start: Application information:
I (551) cpu_start: Project name:     bleproxyethtest
I (557) cpu_start: App version:      2023.7.0
I (562) cpu_start: Compile time:     Jul 21 2023 11:59:25
I (568) cpu_start: ELF file SHA256:  4cf9a12d18804268...
I (574) cpu_start: ESP-IDF:          4.4.4

assert failed: s_prepare_reserved_regions memory_layout_utils.c:100 (reserved[i + 1].start > reserved[i].start)

Backtrace: 0x40082ba6:0x3ffe3390 0x40090c51:0x3ffe33b0 0x40095cd1:0x3ffe33d0 0x4012b1ce:0x3ffe34f0 0x4012adee:0x3ffe3850 0x40128e3f:0x3ffe3c00 0x40082535:0x3ffe3c40 0x40079494:0x3ffe3c80 |<-CORRUPTED

ELF file SHA256: 4cf9a12d18804268

Rebooting...

WT32-eth01

clau-bucur commented 1 year ago

@randybb do you have some time to take a look?

randybb commented 1 year ago

Hm, I have missed that.

Wondering why it is acting co strange - when ble is enabled why "via the network" changes to "wirelessly".

Since it ends with some weird crash, you can try "clean build files" and ideally flash it from that device which is running esphome dashboard? And don't forget to disconnect GPIO0 after flashing via UART.

ammgws commented 8 months ago

@clau-bucur Did you end up resolving this?

clau-bucur commented 8 months ago

@ammgws Unfortunatelly no. I also did not had time to follow-up on @randybb's suggestions. But that would not help for sure as I experienced the issue with more than one boards and with clean builds, etc.

henfri commented 5 months ago

Hello,

in my case it was a problem of memory availability, I think. At least after removing the logger it worked.

Best regards, Hendrik