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

Unable to reach ESP32 modules with v1.14.2 #816

Closed
DasBootU96 opened this issue Nov 4, 2019 · 26 comments
Closed

Unable to reach ESP32 modules with v1.14.2 #816

DasBootU96 opened this issue Nov 4, 2019 · 26 comments

Comments

@DasBootU96
Copy link

DasBootU96 commented Nov 4, 2019

Operating environment/Installation (Hass.io/Docker/pip/etc.):

Hassio 0.101.2 with ESPHome addon 1.14.2

ESP (ESP32/ESP8266, Board/Sonoff):

ESP32 - esp32doit-devkit-v1
Affected component:

mdns - https://esphome.io/guides/faq.html?highlight=mdns

Description of problem:
After uploading 1.14.2 to ESP32 (DoIt DevKit v1.0) modules, ESPHome Dashboard shows module as offline, I can no longer reach its webpage or upload new builds and there is no mdns entry for it in Chrome’s mdns browser app (running on same subnet). Current workaround is using fixed IPs.

After uploading 1.14.2 to ESP8266 (Wemos D1 mini or ESP01) modules have no problem and I can see an mdns entry.

Existing ESP32 modules still running 1.13.6 have no problem and I can see an mdns entry.

Problem-relevant YAML-configuration entries:

esphome:
  name: esp32test
  platform: ESP32
  board: esp32doit-devkit-v1

wifi:
  ssid: "WIFIAP"
  password: "password"

  # Enable fallback hotspot (captive portal) in case wifi connection fails
  ap:
    ssid: "Esp32Test Fallback Hotspot"
    password: "wGmReCrulAVP"

captive_portal:

# Enable logging
logger:
  level: VERY_VERBOSE


# Enable Home Assistant API
api:

ota:

time:
  - platform: homeassistant
    id: homeassistant_time
    
web_server:
  port: 80

status_led:
  pin:
    number: GPIO2

sensor:
  - platform: uptime
    name: Uptime Sensor

  - platform: wifi_signal
    name: "WiFi Signal Sensor"
    update_interval: 60s

binary_sensor:
  - platform: status
    name: "Status"

text_sensor:
  - platform: wifi_info
    ip_address:
      name: ESP IP Address
    ssid:
      name: ESP Connected SSID
    bssid:
      name: ESP Connected BSSID

Logs (if applicable):

Leaving...
Hard Resetting...
Done! Flashing is complete!

Showing logs:
[13:36:40]ets Jun  8 2016 00:22:57
[13:36:40]
[13:36:40]rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[13:36:40]configsip: 0, SPIWP:0xee
[13:36:40]clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
[13:36:40]mode:DIO, clock div:2
[13:36:40]load:0x3fff0018,len:4
[13:36:40]load:0x3fff001c,len:952
[13:36:40]load:0x40078000,len:6084
[13:36:40]load:0x40080000,len:7944
[13:36:40]entry 0x40080310
[13:36:40][I][logger:156]: Log initialized
[13:36:40][C][status_led:014]: Setting up Status LED...
[13:36:40][V][preferences:256]: nvs_get_blob('0'): ESP_ERR_NVS_NOT_FOUND - the key might not be set yet
[13:36:40][C][ota:364]: There have been 0 suspected unsuccessful boot attempts.
[13:36:40][VV][preferences:051]: SAVE 0: 0=0x00000001 1=0x42F4583F (Type=233825507, CRC=0x42F4583F)
[13:36:40][I][app:028]: Running through setup()...
[13:36:40][V][app:029]: Sorting components by setup priority...
[13:36:40][VV][scheduler:056]: set_interval(name='update', interval=60000, offset=28796)
[13:36:40][D][binary_sensor:034]: 'Status': Sending initial state OFF
[13:36:40][VV][scheduler:056]: set_interval(name='', interval=900000, offset=81399)
[13:36:40][V][preferences:256]: nvs_get_blob('1'): ESP_ERR_NVS_NOT_FOUND - the key might not be set yet
[13:36:40][C][wifi:033]: Setting up WiFi...
[13:36:40][V][wifi_esp32:033]: Enabling STA.
[13:36:40][VV][esp-idf:000]: I (132) wifi: wifi driver task: 3ffb5b10, prio:23, stack:3584, core=0
[13:36:40][VV][esp-idf:000]: I (446) wifi: wifi firmware version: 7997e4b
[13:36:40][VV][esp-idf:000]: I (447) wifi: config NVS flash: enabled
[13:36:40][VV][esp-idf:000]: I (448) wifi: config nano formating: disabled
[13:36:40][VV][esp-idf:000]: I (455) wifi: Init dynamic tx buffer num: 32
[13:36:41][VV][esp-idf:000]: I (462) wifi: Init data frame dynamic rx buffer num: 32
[13:36:41][VV][esp-idf:000]: I (469) wifi: Init management frame dynamic rx buffer num: 32
[13:36:41][VV][esp-idf:000]: I (477) wifi: Init management short buffer num: 32
[13:36:41][VV][esp-idf:000]: I (485) wifi: Init static rx buffer size: 1600
[13:36:41][VV][esp-idf:000]: I (492) wifi: Init static rx buffer num: 16
[13:36:41][VV][esp-idf:000]: I (498) wifi: Init dynamic rx buffer num: 32
[13:36:41][VV][esp-idf:000]: I (670) wifi: mode : softAP (24:6f:28:29:b9:31)
[13:36:41][VV][esp-idf:000]: I (671) wifi: Total power save buffer number: 16
[13:36:41][VV][esp-idf:000]: I (673) wifi: Init max length of beacon: 752/752
[13:36:41][VV][esp-idf:000]: I (680) wifi: Init max length of beacon: 752/752
[13:36:41][D][WiFiGeneric.cpp:337] _eventCallback(): Event: 0 - WIFI_READY
[13:36:41][D][WiFiGeneric.cpp:337] _eventCallback(): Event: 14 - AP_STOP
[13:36:41][V][wifi_esp32:349]: Event: WiFi AP start
[13:36:41][V][wifi_esp32:298]: Event: WiFi ready
[13:36:41][VV][esp-idf:000]: I (708) wifi: mode : sta (24:6f:28:29:b9:30)
[13:36:41][D][WiFiGeneric.cpp:337] _eventCallback(): Event: 2 - STA_START
[13:36:41][V][wifi_esp32:307]: Event: WiFi STA start
[13:36:41][D][WiFiGeneric.cpp:337] _eventCallback(): Event: 2 - STA_START
[13:36:41][VV][esp-idf:000]: I (730) wifi: Set ps type: 1
[13:36:41]
[13:36:41][D][wifi:298]: Starting scan...
[13:36:41][VV][scheduler:131]: Running interval '' with interval=900000 last_execution=4293986002 (now=455)
[13:36:41][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=4294878591 (now=455)
[13:36:41][V][sensor:013]: 'Uptime Sensor': Received new state 0.471000
[13:36:41][D][sensor:092]: 'Uptime Sensor': Sending state 0.47100 s with 0 decimals of accuracy
[13:36:43][D][WiFiGeneric.cpp:337] _eventCallback(): Event: 1 - SCAN_DONE
[13:36:43][V][wifi_esp32:303]: Event: WiFi Scan Done status=0 number=6 scan_id=128
[13:36:43][D][wifi:313]: Found networks:
[13:36:43][I][wifi:359]: - 'WIFIAP' (BA:69:F4:xx:xx:xx) ▂▄▆█
[13:36:43][D][wifi:360]:     Channel: 7
[13:36:43][D][wifi:361]:     RSSI: -53 dB
[13:36:43][D][wifi:363]: - 'WIFIAP' (B8:69:F4:xx:xx:xx) ▂▄▆█
[13:36:43][D][wifi:363]: - 'WIFIAP1' (00:14:7F:xx:xx:xx) ▂▄▆█
[13:36:43][D][wifi:363]: - 'WIFIAP2' (00:1D:AA:xx:xx:xx) ▂▄▆█
[13:36:43][D][wifi:363]: - 'WIFIAP3' (AC:22:05xx:xx:xx) ▂▄▆█
[13:36:43][D][wifi:363]: - 'WIFIAP4' (88:03:55:xx:xx:xx) ▂▄▆█
[13:36:43][I][wifi:187]: WiFi Connecting to 'WIFIAP'...
[13:36:43][V][wifi:189]: Connection Params:
[13:36:43][V][wifi:190]:   SSID: 'WIFIAP'
[13:36:43][V][wifi:193]:   BSSID: BA:69:F4:xx:xx:xx
[13:36:43][V][wifi:197]:   Password: 'password'
[13:36:43][V][wifi:199]:   Channel: 7
[13:36:43][V][wifi:209]:   Using DHCP IP
[13:36:43][V][wifi:211]:   Hidden: NO
[13:36:43][VV][esp-idf:000]: I (2855) wifi: n:7 2, o:1 0, ap:255 255, sta:7 2, prof:1
[13:36:44][VV][esp-idf:000]: I (3589) wifi: state: init -> auth (b0)
[13:36:44][VV][esp-idf:000]: I (3600) wifi: state: auth -> assoc (0)
[13:36:44][VV][esp-idf:000]: I (3608) wifi: state: assoc -> run (10)
[13:36:44][VV][esp-idf:000]: I (3621) wifi: connected with WIFIAP, channel 7, 40D
[13:36:44][VV][esp-idf:000]: I (3621) wifi: pm start, type: 1
[13:36:44]
[13:36:44][D][WiFiGeneric.cpp:337] _eventCallback(): Event: 4 - STA_CONNECTED
[13:36:44][V][wifi_esp32:320]: Event: Connected ssid='WIFIAP' bssid=BA:69:F4:xx:xx:xx channel=7, authmode=WPA2 PSK
[13:36:44][D][WiFiGeneric.cpp:337] _eventCallback(): Event: 7 - STA_GOT_IP
[13:36:44][D][WiFiGeneric.cpp:381] _eventCallback(): STA IP: 10.0.30.112, MASK: 255.255.255.0, GW: 10.0.30.1
[13:36:44][V][wifi_esp32:341]: Event: Got IP static_ip=10.0.30.112 gateway=10.0.30.1
[13:36:44][I][wifi:417]: WiFi Connected!
[13:36:44][C][wifi:277]:   SSID: 'WIFIAP'
[13:36:44][C][wifi:278]:   IP Address: 10.0.30.112
[13:36:44][C][wifi:280]:   BSSID: BA:69:F4:xx:xx:xx
[13:36:44][C][wifi:281]:   Hostname: 'esp32test'
[13:36:44][C][wifi:285]:   Signal strength: -48 dB ▂▄▆█
[13:36:44][V][wifi:287]:   Priority: 0.0
[13:36:44][C][wifi:289]:   Channel: 7
[13:36:44][C][wifi:290]:   Subnet: 255.255.255.0
[13:36:44][C][wifi:291]:   Gateway: 10.0.30.1
[13:36:44][C][wifi:292]:   DNS1: 10.0.0.10
[13:36:44][C][wifi:293]:   DNS2: 0.0.0.0
[13:36:44][D][wifi:426]: Disabling AP...
[13:36:44][C][web_server:064]: Setting up web server...
[13:36:44][VV][scheduler:056]: set_interval(name='', interval=10000, offset=3829)
[13:36:44][C][ota:029]: Over-The-Air Updates:
[13:36:44][C][ota:030]:   Address: esp32test.local:3232
[13:36:44][C][api:022]: Setting up Home Assistant API server...
[13:36:44][VV][scheduler:056]: set_interval(name='update', interval=60000, offset=2024)
[13:36:44][I][app:058]: setup() finished successfully!
[13:36:44][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=4294957428 (now=3995)
[13:36:44][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=4294909255 (now=3995)
[13:36:44][V][sensor:013]: 'WiFi Signal Sensor': Received new state -48.000000
[13:36:44][D][sensor:092]: 'WiFi Signal Sensor': Sending state -48.00000 dB with 0 decimals of accuracy
[13:36:44][D][text_sensor:015]: 'ESP IP Address': Sending state '10.0.30.112'
[13:36:44][D][text_sensor:015]: 'ESP Connected SSID': Sending state 'WIFIAP'
[13:36:44][D][text_sensor:015]: 'ESP Connected BSSID': Sending state 'BA:69:F4:xx:xx:xx'
[13:36:44][I][app:100]: ESPHome version 1.14.2 compiled on Nov  4 2019, 13:32:29
[13:36:44][C][status_led:019]: Status LED:
[13:36:44][C][status_led:020]:   Pin: GPIO2 (Mode: OUTPUT)
[13:36:44][C][wifi:409]: WiFi:
[13:36:44][C][wifi:277]:   SSID: 'WIFIAP'
[13:36:44][C][wifi:278]:   IP Address: 10.0.30.112
[13:36:44][C][wifi:280]:   BSSID: BA:69:F4:xx:xx:xx
[13:36:44][C][wifi:281]:   Hostname: 'esp32test'
[13:36:44][C][wifi:285]:   Signal strength: -48 dB ▂▄▆█
[13:36:44][V][wifi:287]:   Priority: 0.0
[13:36:44][C][wifi:289]:   Channel: 7
[13:36:44][C][wifi:290]:   Subnet: 255.255.255.0
[13:36:44][C][wifi:291]:   Gateway: 10.0.30.1
[13:36:44][C][wifi:292]:   DNS1: 10.0.0.10
[13:36:44][C][wifi:293]:   DNS2: 0.0.0.0
[13:36:44][C][uptime.sensor:030]: Uptime Sensor 'Uptime Sensor'
[13:36:44][C][uptime.sensor:030]:   Unit of Measurement: 's'
[13:36:44][C][uptime.sensor:030]:   Accuracy Decimals: 0
[13:36:44][C][uptime.sensor:030]:   Icon: 'mdi:timer'
[13:36:44][V][uptime.sensor:030]:   Unique ID: '246f2829b930-uptime'
[13:36:44][C][logger:175]: Logger:
[13:36:44][C][logger:176]:   Level: VERY_VERBOSE
[13:36:45][C][logger:177]:   Log Baud Rate: 115200
[13:36:45][C][logger:178]:   Hardware UART: UART0
[13:36:45][C][status:034]: Status Binary Sensor 'Status'
[13:36:45][C][status:034]:   Device Class: 'connectivity'
[13:36:45][C][homeassistant.time:010]: Home Assistant Time:
[13:36:45][C][homeassistant.time:011]:   Timezone: 'CET-1CEST-2,M3.5.0/2,M10.4.0/3'
[13:36:45][C][captive_portal:169]: Captive Portal:
[13:36:45][C][web_server:120]: Web Server:
[13:36:45][C][web_server:121]:   Address: esp32test.local:80
[13:36:45][C][ota:029]: Over-The-Air Updates:
[13:36:45][C][ota:030]:   Address: esp32test.local:3232
[13:36:45][C][api:095]: API Server:
[13:36:45][C][api:096]:   Address: esp32test.local:6053
[13:36:45][C][wifi_signal.sensor:009]: WiFi Signal 'WiFi Signal Sensor'
[13:36:45][C][wifi_signal.sensor:009]:   Unit of Measurement: 'dB'
[13:36:45][C][wifi_signal.sensor:009]:   Accuracy Decimals: 0
[13:36:45][C][wifi_signal.sensor:009]:   Icon: 'mdi:wifi'
[13:36:45][V][wifi_signal.sensor:009]:   Unique ID: '246f2829b930-wifisignal'
[13:36:45][C][wifi_info:009]: WifiInfo IPAddress 'ESP IP Address'
[13:36:45][V][wifi_info:009]:   Unique ID: '246f2829b930-wifiinfo-ip'
[13:36:45][C][wifi_info:010]: WifiInfo SSID 'ESP Connected SSID'
[13:36:45][V][wifi_info:010]:   Unique ID: '246f2829b930-wifiinfo-ssid'
[13:36:45][C][wifi_info:011]: WifiInfo BSSID 'ESP Connected BSSID'
[13:36:45][V][wifi_info:011]:   Unique ID: '246f2829b930-wifiinfo-bssid'
[13:36:50][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=132 (now=10135)
[13:37:00][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=10132 (now=20132)
[13:37:10][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=20132 (now=30134)
[13:37:12][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=4294938591 (now=31295)
[13:37:12][V][sensor:013]: 'Uptime Sensor': Received new state 31.295000
[13:37:12][D][sensor:092]: 'Uptime Sensor': Sending state 31.29500 s with 0 decimals of accuracy
[13:37:20][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=30132 (now=40136)
[13:37:30][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=40132 (now=50132)
[13:37:40][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=50132 (now=60133)
[13:37:42][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=1959 (now=61959)
[13:37:42][V][sensor:013]: 'WiFi Signal Sensor': Received new state -47.000000
[13:37:42][D][sensor:092]: 'WiFi Signal Sensor': Sending state -47.00000 dB with 0 decimals of accuracy
[13:37:50][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=60132 (now=70132)
[13:38:00][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=70132 (now=80132)
[13:38:10][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=80132 (now=90132)
[13:38:12][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=31295 (now=91295)
[13:38:12][V][sensor:013]: 'Uptime Sensor': Received new state 91.294998
[13:38:12][D][sensor:092]: 'Uptime Sensor': Sending state 91.29500 s with 0 decimals of accuracy
[13:38:20][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=90132 (now=100134)
[13:38:30][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=100132 (now=110132)
[13:38:40][I][ota:046]: Boot seems successful, resetting boot loop counter.
[13:38:40][VV][preferences:051]: SAVE 0: 0=0x00000000 1=0x0DEFE4E3 (Type=233825507, CRC=0x0DEFE4E3)
[13:38:40][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=110132 (now=120132)
[13:38:42][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=61959 (now=121959)
[13:38:42][V][sensor:013]: 'WiFi Signal Sensor': Received new state -47.000000
[13:38:42][D][sensor:092]: 'WiFi Signal Sensor': Sending state -47.00000 dB with 0 decimals of accuracy
[13:38:50][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=120132 (now=130132)
[13:39:00][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=130132 (now=140132)
[13:39:10][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=140132 (now=150132)
[13:39:12][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=91295 (now=151295)
[13:39:12][V][sensor:013]: 'Uptime Sensor': Received new state 151.294998
[13:39:12][D][sensor:092]: 'Uptime Sensor': Sending state 151.29500 s with 0 decimals of accuracy
[13:39:20][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=150132 (now=160135)
[13:39:30][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=160132 (now=170132)
[13:39:40][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=170132 (now=180132)
[13:39:42][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=121959 (now=181963)
[13:39:42][V][sensor:013]: 'WiFi Signal Sensor': Received new state -48.000000
[13:39:42][D][sensor:092]: 'WiFi Signal Sensor': Sending state -48.00000 dB with 0 decimals of accuracy
[13:39:50][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=180132 (now=190132)
[13:40:00][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=190132 (now=200132)
[13:40:10][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=200132 (now=210132)
[13:40:12][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=151295 (now=211295)
[13:40:12][V][sensor:013]: 'Uptime Sensor': Received new state 211.294998
[13:40:12][D][sensor:092]: 'Uptime Sensor': Sending state 211.29500 s with 0 decimals of accuracy
[13:40:20][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=210132 (now=220137)
[13:40:30][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=220132 (now=230133)
[13:40:40][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=230132 (now=240132)
[13:40:42][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=181959 (now=241961)
[13:40:42][V][sensor:013]: 'WiFi Signal Sensor': Received new state -48.000000
[13:40:42][D][sensor:092]: 'WiFi Signal Sensor': Sending state -48.00000 dB with 0 decimals of accuracy
[13:40:50][W][AsyncTCP.cpp:950] _poll(): rx timeout 4
[13:40:50][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=240132 (now=250134)
[13:41:00][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=250132 (now=260134)
[13:41:10][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=260132 (now=270134)
[13:41:12][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=211295 (now=271295)
[13:41:12][V][sensor:013]: 'Uptime Sensor': Received new state 271.298004
[13:41:12][D][sensor:092]: 'Uptime Sensor': Sending state 271.29800 s with 0 decimals of accuracy
[13:41:20][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=270132 (now=280132)
[13:41:30][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=280132 (now=290132)
[13:41:40][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=290132 (now=300132)
[13:41:42][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=241959 (now=301959)
[13:41:42][V][sensor:013]: 'WiFi Signal Sensor': Received new state -48.000000
[13:41:42][D][sensor:092]: 'WiFi Signal Sensor': Sending state -48.00000 dB with 0 decimals of accuracy
[13:41:50][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=300132 (now=310132)
[13:42:00][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=310132 (now=320132)
[13:42:10][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=320132 (now=330132)
[13:42:12][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=271295 (now=331297)
[13:42:12][V][sensor:013]: 'Uptime Sensor': Received new state 331.299988
[13:42:12][D][sensor:092]: 'Uptime Sensor': Sending state 331.29999 s with 0 decimals of accuracy
[13:42:20][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=330132 (now=340139)
[13:42:30][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=340132 (now=350137)
[13:42:40][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=350132 (now=360136)
[13:42:42][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=301959 (now=361960)
[13:42:42][V][sensor:013]: 'WiFi Signal Sensor': Received new state -48.000000
[13:42:42][D][sensor:092]: 'WiFi Signal Sensor': Sending state -48.00000 dB with 0 decimals of accuracy
[13:42:50][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=360132 (now=370132)
[13:43:00][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=370132 (now=380132)
[13:43:10][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=380132 (now=390132)
[13:43:12][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=331295 (now=391298)
[13:43:12][V][sensor:013]: 'Uptime Sensor': Received new state 391.300995
[13:43:12][D][sensor:092]: 'Uptime Sensor': Sending state 391.30099 s with 0 decimals of accuracy

Additional information and things you've tried:

Using fixed IPs.

@OttoWinter
Copy link
Member

Thanks for providing detailed logs and the note about mDNS.

It sounds reasonable that mDNS might be the problem here. If it doesn't work, nothing will connect.

I remember two code changes that could cause this:

  1. arduino framework version was updated. Please try the same with arduino_version: 1.0.2 in your core-config to use the esp-idf version from 1.13.6

  2. The mDNS initialization timing changed - If I remember correctly it's now initialized after the WiFi interface is started. Maybe that has something to do with it, though I'm using ESP32s with mDNS everywhere and have not had this problem.

@DasBootU96
Copy link
Author

OK, it is just weird and some others have reported similar issues here and here.

About this log entry:

[13:36:44][V][wifi_esp32:341]: Event: Got IP static_ip=10.0.30.112 gateway=10.0.30.1

It mentions static_ip, but DHCP is used and is therefore confusing to me. Is it a red herring?

I should add that if I refresh Chrome’s mdns browser app often enough, I do see the v1.14.2 ESP32 mdns entries albeit very briefly whereas the v1.14.2 ESP8266 mdns entries and v1.13.6 ESP32 mdns entries are always visible.

@OttoWinter
Copy link
Member

It mentions static_ip, but DHCP is used and is therefore confusing to me. Is it a red herring?

No. After DHCP negotiation it's essentially the same as using a static IP - the log line shows that it got a valid IP from the DHCP server.

I should add that if I refresh Chrome’s mdns browser app often enough, I do see the v1.14.2 ESP32 mdns entries albeit very briefly

That's odd. The mDNS records have a TTL of around 2min, so if the extension should leave them there for at least 2min no matter what happens

@DasBootU96
Copy link
Author

Added arduino_version:

esphome:
  name: esp32test
  platform: ESP32
  board: esp32doit-devkit-v1
  arduino_version: 1.0.2

but no change in resolving the hostname and no mdns entry in the mdns browser app. Also tried another brand keyesstudio ESP32, but same behaviour as the DoIt board.

Are there other options to try?

@OttoWinter OttoWinter added this to the 1.14.x milestone Nov 5, 2019
@dgtal1

This comment has been minimized.

@DasBootU96
Copy link
Author

Not sure if this will help, but I use a Mikrotik 962UiGS-5HacT2HnT capable of packet sniffing. This is a Wireshark capture from two ESP32 nodes ESPHome Issue 816.zip.

Node1 - 10.0.30.110 - 3C:71:BF:F1:EA:14 - ESPHome 1.13.6
Esp32test - 10.0.30.112 - 24:6F:28:29:B9:30 - ESPHome 1.14.2

hassio - 10.0.30.10

Mdns for both appear the same, but have never dealt with mdns before.

@OttoWinter
Copy link
Member

OttoWinter commented Nov 6, 2019

Thanks for supplying detailed packet logs @DasBootU96! I had a look at them with wireshark and could not find anything.

  • both .110 and .112 are initially sending 3 mDNS packets announcing their presence (all of which arrive intact).
  • They both periodically retransmit their original mDNS packet as cache flush packets - all fine there too.

What's missing is any device sending mDNS requests to the device - if HA or some other ESPHome client is on the network and trying to connect, they would be sending mDNS queries to which the ESP would respond. But that might be due to filtering the PCAP file.


I tried an ESP32 with my own setup here and can't reproduce the issue.

You also tried the arduino_version: 1.0.2 already and that didn't give any results - so there are two things left that could explain it:

  • A change in WiFi connection logic here - highly unlikely that it would manifest itself in this way IMO.
  • captive_portal being active - Maybe the AP messes up the mDNS source address in some way. I tried reproducing that too, but found no problem. Could you try without captive_portal and wifi AP enabled?

Edit: For reference, there's also #810 open with semi-similar symptoms. But I also doubt it's related because the ESP32/ESP8266 wifi and mDNS code is very different - they wouldn't happen at the same time with the same symptoms.

@Spirituss

This comment has been minimized.

@OttoWinter
Copy link
Member

@Spirituss That's a different issue -> #824

@DasBootU96
Copy link
Author

DasBootU96 commented Nov 7, 2019

Tried without captive_portal and wifi AP enabled like so:

wifi:
  ssid: "WIFIAP"
  password: "password"

  # Enable fallback hotspot (captive portal) in case wifi connection fails
  ap:
    ssid: "Esp32Test Fallback Hotspot"
    password: "wGmReCrulAVP"

# captive_portal:

No difference. Also, a few existing ESP32 nodes were upgraded from 1.13.6 to 1.14.2 and do not have fallback hotspot since as this is a new feature, but do have the same problem with mdns resolving.

Previous Wireshark captures were filtered to two ESP32 MAC addresses only, I've attached new captures. Captured starts, then in ESPHome Dashboard, clicked 'show logs' for these two nodes:

Node1 - 10.0.30.110 - 3C:71:BF:F1:EA:14 - ESPHome 1.13.6
Esp32test - 10.0.30.112 - 24:6F:28:29:B9:30 - ESPHome 1.14.2

Once ESPHome logs show, Wireshark capture was stopped. For node Esp32test it took many retries and eventually showed logs after more than 2 minutes. For Node1 it took no retries and log showed after seconds.

Here are Wireshark logs:
Capture node1 + esp32test - ESPHome Issue 816.zip.

Packet filtered on hassio (Pi4) and all ESPHome node MAC addreses only. You may notice other, excluded traffic. Of note are:
10.0.30.99 - W10VM with Wireshark + Chrome webpage opened Hassio front-end
10.0.30.1 - Pfsense router
10.0.30.254 - Mikrotik Wifi AP

issue #810 does have very, very similar symptoms, but for me three ESPHome 1.14.2 ESP8266 nodes work perfectly and have no issues resolving. Though I have never tested ESP8285.

Hope this helps.

@mikkaat

This comment has been minimized.

@Gooman-rus
Copy link

I have the same issue: after updating to 1.14.2 from 1.13.6 I have issue with devices: can't connect to them in order to read logs or for the OTA updates. This forces me to downgrading to 1.13.6.

@OttoWinter
Copy link
Member

@mikkaat @Gooman-rus Please confirm what you're facing is really an mDNS issue and not a more general disconnect issue. Please post what symptoms you're seeing, especially with @mikkaat I believe it is a case of #824

@Gooman-rus
Copy link

Gooman-rus commented Nov 8, 2019

@mikkaat @Gooman-rus Please confirm what you're facing is really an mDNS issue and not a more general disconnect issue. Please post what symptoms you're seeing, especially with @mikkaat I believe it is a case of #824

I don't use BLE tracker or other Bluetooth related things. My hardware is ESP32 and Waveshare E-ink display. I use this display in order to show data from homassistant. After updating to 1.14.2 I could not connect to my device via "show logs" button. It said that it can't determine IP of my device.
After restart my device stopped to show any data from homeassistant. Also it appeared as Offline in ESPHome page.
Also after updating to 1.14.2 ESPHome stopped to connect (via "show logs" button) to smart socket Blitzwolf with firmware v. 1.13.6. But homeassistant still had an ability to receive data from the socket. By the way, the socket also appeared as Offline on the ESPHome devices page.

Now I have used a homeassistant snapshot in order to downgrade ESPHome to 1.13.6. Also it forced me to manually install 1.13.6 firmware to my ESP32. And not it works very well.

@DasBootU96
Copy link
Author

DasBootU96 commented Nov 10, 2019

Update:
Used an old Netgear WNDR3700v1 and installed DD-WRT in gateway mode. Moved the Hassio (Pi4) wired connection to it, changed WiFi SSID + password to the same as I was using, then disabled to original WiFi SSID of the same name.

Now mdns entries for ESPHome ESP32 nodes v1.14.2 are all visible and remain visible in Chrome's mdns browser. In the ESPHome Dashboard, show logs using the .local name works fine and I can update new builds to ESP32 nodes v1.14.2 using the .local name without issues or delays.

However, opening any ESPHome node (v1.13.6 or v1.14.2 ESP8266/ESP32) webpage does not work via mdns .local (tried Chrome and Opera while on the same subnet as the nodes and Hassio), open webpage via its IP is fine. Also a few ESP32 nodes v1.14.2 have become unavailable which is easily resolved by deleting and adding again.

Had the same webpage .local issue with the mDNS_Web_Server.ino Arduino example sketch on any of Espressif's ESP32 Arduino cores v1.0.1 through v1.0.4 regardless if I used MDNS.addService("http", "tcp", 80); or MDNS.addService("_http", "_tcp", 80);.

FWIW: the original setup used Mikrotik 962UiGS-5HacT2HnT connected to a VLAN trunk and the Wifi connections for IOT Wifi and regular Wifi traffic were separated via a tag configured in Mikrotiks config on different VLANs with their own SSIDs. PFsense takes care of routing. Wired Hassio (Pi4) was connected to the same VLAN as the IOT Wifi network. All worked fine until the ESPHome v1.14.2 mdns resolving issues.

It seems ESPHome ESP32 nodes v1.14.2 and VLANs don't play well toghether, but unsure what to exactly make of all this yet... Hope it helps.

@mikkaat

This comment has been minimized.

@OttoWinter
Copy link
Member

@DasBootU96 Thanks for the update. Yeah it might be due to the router. First assumption would of course be that an update changed the mDNS format and the router does not accept that format. But the packet captures you supplied looked fine - all valid mDNS packets. Also there were no major changes to esp-idf mDNS lately, so I don't think it's related to that.

If it's the router and VLAN I would just say it's an issue with some network component in the chain not being happy with mDNS format. Since mDNS is sadly quite flaky anyway (from the protocol itself), I don't think there's much that can be done.

@OttoWinter
Copy link
Member

I'm going to close this issue because I think it's due to some other/upstream issue. If there's more clear evidence showing that ESPHome is involved please re-open or create a new issue linking here.

@fribse

This comment has been minimized.

@OttoWinter
Copy link
Member

SONOFF Basic, POW2, RF 433 Bridge, and quite a few of self-built ESP8266

all those are ESP8266s. This issue refers to ESP32s. That's also part of the issue with resolving this - people post their symptoms all across several threads, and it gets really hard to understand what's related to what issue etc.

You're probably looking for #838

@brandond
Copy link

the original setup used Mikrotik 962UiGS-5HacT2HnT connected to a VLAN trunk and the Wifi connections for IOT Wifi and regular Wifi traffic were separated via a tag configured in Mikrotiks config on different VLANs with their own SSIDs. PFsense takes care of routing.

The M in MDNS stands for multicast. It doesn't route across subnets, so if the devices are on a different vlan and subnet than your server it wont work unless you run a MDNS repeater with an interface on each network.

That doesn't explain the drops, so there may be other issues, but I would definitely try to troubleshoot MDNS separately from the connectivity issues.

@DasBootU96
Copy link
Author

Thanks, I'm aware mdns does not route across subnets.

To clarify: Hassio, all ESP nodes and the system used to run Chromes mdns browser app are all on the same IOT VLAN subnet.

Yet I experience missing mdns entries for ESP32 v1.14.x, while ESP8266 v1.14.x and ESP32 v1.13.6 node mdns entries are always visible.

@mikkaat

This comment has been minimized.

@OttoWinter
Copy link
Member

OttoWinter commented Nov 12, 2019

@mikkaat From your initial report, it's related to esp32_ble_tracker. See #824 for that.

@DasBootU96 You see, from my perspective what I see is mDNS fails suddenly with 1.14.x, but there was no change to mDNS in that version - the only change was the SDK version, which you've ruled out by setting arduino_version to the old default.

And from the packet captures (which is the best truth we're going to get on this issue), there are also no visible issues - if there were, we would see them there.

Next, some of the other things mentioned here have also been ruled out. You don't have BLE enabled (as in @mikkaat's issue), you don't have an ESP8266 (which is using totally different code) as with @fribse.

Adding to that, I can't replicate this issue. I've tried a bunch of setups with ESP32s and mDNS names with various names, but all work just fine.

The only conclusion I can come to is that mDNS is not working well together with your router.

I don't know what the real problem is, but with my time working with mDNS I also know that it doesn't make much sense exploring why mDNS does/doesn't work. mDNS itself is not that complex of a protocol, but some routers just don't like certain mDNS packets for whatever reason.

@DasBootU96
Copy link
Author

DasBootU96 commented Nov 12, 2019

So I just changed Mikrotiks wireless interface setting Multicast Helper: full and now all mdns entries (yes, ESP32 with v1.14.2 too) are visible, 'show logs' work without any delay, I can upload new builds without problem and all ESP nodes show online in the dashboard.

Here is what the Mikrotik manual says about Multicast Helper:

multicast-helper (default \| disabled \| full; Default: default)

When set to full multicast packets will be sent with unicast destination MAC address, resolving multicast problem on wireless link. 
This option should be enabled only on access point, clients should be configured in station-bridge mode. Available starting from v5.15.

* disabled - disables the helper and sends multicast packets with multicast destination MAC addresses
* full - all multicast packet mac address are changed to unicast mac addresses prior sending them out
* default - default choice that currently is set to disabled. Value can be changed in future releases.

Previously its was left as default which was: default...and according to the manual that means it was disabled. For completeness sake, I was running routerOS 6.44.3 when this issue showed up, this evening upgraded to 6.45.7, then finally started messing with routerOS Multicast settings.

Thanks @OttoWinter and all others, yet I still do not know exactly why this change is required for v1.14.x while v1.13.6 was working fine without this change. Then again I'm not a hardcore networking guy.

Hope this helps others with similar issues.

Edit: I should have added that opening any EspHome nodes webpage by its .local/ url does not work for some reason, only works when typing in its ip. I have yet to figure that out, but it is minor for me.

@mikkaat
Copy link

mikkaat commented Nov 12, 2019

@OttoWinter thank you, I have been running those settings for about 3 hours now with no drops.

@lock lock bot locked and limited conversation to collaborators Nov 19, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

8 participants