search

esphome / issues

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

Home Assistant disconnects after switching a switch group #794

Closed S-Przybylski closed 4 years ago

S-Przybylski commented 4 years ago

Operating environment/Installation (Hass.io/Docker/pip/etc.): Home assistant Home Assistant 0.102.0.dev20191101 (Docker) on Raspi 3B ESPHOME 1.14.0b5 on Docker

ESP (ESP32/ESP8266, Board/Sonoff): Wemos D1 mini with attached 4 x pcf8574 and 2 x mcp23008

Affected component: Native HA api

Description of problem: If i switch a whole switch group to "on" (or to "off") using the group switch within HA web interface, the esp executes the switch command, but after some seconds the connection disconnects and the esp log shows the entry:

[17:51:26][D][api:067]: Disconnecting Home Assistant 0.102.0.dev20191101 (10.x.x.x)
[17:51:32][D][api.connection:578]: Client 'Home Assistant 0.102.0.dev20191101 (10.x.x.x)' connected successfully!

The esphome device was added in HA using the standard HA native method without any modification. MQTT on esp is not configured also no web interface. There are no automations or functions in place; only a simple basic configuration with pcf8574 switches/sensors and mcp23008 switches/sensors.

The disconnect can be reproduced if the group switch is pressed again or serveral individual switches are pressed in a fast sequence.

Problem-relevant YAML-configuration entries:

esphome:
  name: test
  platform: ESP8266
  board: d1_mini
wifi:
  ssid: "test"
  password: "test"
  fast_connect: true
#debug:
# Enable logging
logger:
#  level: debug
# Enable Home Assistant API
api:
  password: "pw"
ota:
  password: "pw"
i2c:
  sda: 4
  scl: 5
  scan: True
  - id: 'pcf8574_hub3'
    address: 0x24
    pcf8575: False
switch:
  - platform: gpio
    name: "pcf8574_3_0"
    pin:
      pcf8574: pcf8574_hub3
        number: 0
        mode: OUTPUT
      inverted: True
  - platform: gpio
    name: "pcf8574_3_1"
    pin:
      pcf8574: pcf8574_hub3
      number: 1
      mode: OUTPUT
      inverted: True
  - platform: gpio
    name: "pcf8574_3_2"
    pin:
      pcf8574: pcf8574_hub3
      number: 2
      mode: OUTPUT
      inverted: True
...

switch

glmnet commented 4 years ago

Thanks for the feedback. Did you find this causing a major downtime (per logs seems to be 6 seconds), or any other issue caused by this? A release is scheduled soon and it might ship with this issue, but if this only applies to a group switch toggled and it recovers quickly by itself, it doesn't seems like a big concern.

S-Przybylski commented 4 years ago

Its about 5-7 seconds. The problem is that all sensors are set to 'unavailable' and the states are updated. I am with you that this is not realy an issue, because i personally do not use that method in practice. On the other hand, i also saw that behaviour if i manually change the status of some switches fastly... And at the end you can see, that not all status updates are transmitted correctly. You can also see that if you press the group switch several times fastly: Some of the outputs are on while others are off then...

For me its vital that HA with ESPHOME don't forget any switch change even the connection is disturbed for 5 seconds...

brandond commented 4 years ago

Do you have UART logs from the device? I almost wonder if the relays are drawing too much current when they all switch at once and are causing the device to reboot.

glmnet commented 4 years ago

It comes back too quickly for a reboot

glmnet commented 4 years ago

I was once instructed to enable more verbose logging to troubleshoot an api issue.

Please enable debug logging in HA (see logger section) and post what HA is sending to the ESP.

OttoWinter commented 4 years ago

@glmnet 5-7 seconds can be reboot I think - if the device has good wifi coverage and connect works fast.

But this will definitely required UART logs - from here it's hard to tell.

S-Przybylski commented 4 years ago

I use optocoupler devices without any load on the output side (only status leds) - a german vendor board. For it seems that the device doesn't restart: While i playing with the group switch, a ping is alway accurate (no drop out). Also there is no blink of the blue light. If i normaly restart the device i always see that light blink for a short time. Also the running esp log do not show any restart.

Test environment: 3 x 8 outputs (8 mcp23008, 16 pcf8574); 3 x 8 inputs (8 mcp23008, 16 pcf8574) Test case: At 11:35:05 - Pressed group switch in HA (put all 24 outputs off) I noticed that not all outputs are set to off: pcf8574_4_1 and pcf8574_4_2 remain in on! I assume that a loss of the esp-connection leads to the wrong behaviour.

Log file of the esp:

INFO Reading configuration /config/testesp.yaml...
INFO Generating C++ source...
INFO Compiling app...
INFO Running:  platformio run -d /config/test
Processing test (board: d1_mini; framework: arduino; platform: espressif8266@2.2.3)
--------------------------------------------------------------------------------
HARDWARE: ESP8266 80MHz, 80KB RAM, 4MB Flash
Dependency Graph
|-- <ESPAsyncTCP-esphome> 1.2.2
|   |-- <ESP8266WiFi> 1.0
|-- <ESP8266WiFi> 1.0
|-- <ESP8266mDNS> 1.2
|   |-- <ESP8266WiFi> 1.0
|-- <Wire> 1.0
Compiling .pioenvs/test/src/esphome/components/debug/debug_component.cpp.o
Compiling .pioenvs/test/src/main.cpp.o
Linking .pioenvs/test/firmware.elf
Retrieving maximum program size .pioenvs/test/firmware.elf
Checking size .pioenvs/test/firmware.elf
Building .pioenvs/test/firmware.bin
DATA:    [=====     ]  45.7% (used 37424 bytes from 81920 bytes)
PROGRAM: [====      ]  38.1% (used 398156 bytes from 1044464 bytes)
Creating BIN file ".pioenvs/test/firmware.bin" using ".pioenvs/test/firmware.elf"
========================= [SUCCESS] Took 18.83 seconds =========================
INFO Successfully compiled program.
INFO Resolving IP address of test.local
INFO Address in use when adding 169.254.180.45 to multicast group, it is expected to happen on some systems
INFO  -> 10.xxx.xxx.xxx
INFO Uploading /config/test/.pioenvs/test/firmware.bin (402304 bytes)
Uploading: [============================================================] 100% Done...

INFO Waiting for result...
INFO OTA successful
INFO Successfully uploaded program.
INFO Starting log output from test.local using esphome API
INFO Address in use when adding 169.254.180.45 to multicast group, it is expected to happen on some systems
WARNING Error resolving IP address of test.local. Is it connected to WiFi?
WARNING (If this error persists, please set a static IP address: https://esphome.io/components/wifi.html#manual-ips)
WARNING Initial connection failed. The ESP might not be connected to WiFi yet (Error resolving IP address: Error resolving address with mDNS: Did not respond. Maybe the device is offline., [Errno -2] Name or service not known). Re-Trying in 1 seconds
INFO Address in use when adding 169.254.180.45 to multicast group, it is expected to happen on some systems
INFO Connecting to test.local:6053 (10.x.x.x)
INFO Successfully connected to test.local
[11:28:26][I][app:100]: ESPHome version 1.14.0b5 compiled on Nov  2 2019, 11:27:52
[11:28:26][C][wifi:409]: WiFi:
[11:28:26][C][wifi:277]:   SSID:

[redacted]
[11:28:26][C][wifi:278]:   IP Address: 10.x.x.x
[11:28:26][C][wifi:280]:   BSSID: 

[redacted]
[11:28:26][C][wifi:281]:   Hostname: 'test'
[11:28:26][C][wifi:285]:   Signal strength: -65 dB ▂▄▆█
[11:28:26][C][wifi:289]:   Channel: 6
[11:28:26][C][wifi:290]:   Subnet: 255.255.255.0
[11:28:26][C][wifi:291]:   Gateway: 10.x.x.1
[11:28:26][C][wifi:292]:   DNS1: 10.x.x.1
[11:28:26][C][wifi:293]:   DNS2: (IP unset)
[11:28:26][C][i2c:028]: I2C Bus:
[11:28:26][C][i2c:029]:   SDA Pin: GPIO4
[11:28:26][C][i2c:030]:   SCL Pin: GPIO5
[11:28:26][C][i2c:031]:   Frequency: 50000 Hz
[11:28:26][I][i2c:033]: Scanning i2c bus for active devices...
[11:28:26][I][i2c:040]: Found i2c device at address 0x20
[11:28:26][I][i2c:040]: Found i2c device at address 0x21
[11:28:26][I][i2c:040]: Found i2c device at address 0x24
[11:28:26][I][i2c:040]: Found i2c device at address 0x25
[11:28:26][I][i2c:040]: Found i2c device at address 0x27
[11:28:26][I][i2c:040]: Found i2c device at address 0x38
[11:28:26][C][pcf8574:021]: PCF8574:
[11:28:26][C][pcf8574:022]:   Address: 0x27
[11:28:26][C][pcf8574:023]:   Is PCF8575: NO
[11:28:26][C][pcf8574:021]: PCF8574:
[11:28:26][C][pcf8574:022]:   Address: 0x38
[11:28:26][C][pcf8574:023]:   Is PCF8575: NO
[11:28:26][C][pcf8574:021]: PCF8574:
[11:28:26][C][pcf8574:022]:   Address: 0x24
[11:28:26][C][pcf8574:023]:   Is PCF8575: NO
[11:28:26][C][pcf8574:021]: PCF8574:
[11:28:26][C][pcf8574:022]:   Address: 0x25
[11:28:26][C][pcf8574:023]:   Is PCF8575: NO
[11:28:26][C][switch.gpio:042]: GPIO Switch 'pcf8574_3_0'
[11:28:26][C][switch.gpio:043]:   Pin: GPIO0 (Mode: OUTPUT, INVERTED)
[11:28:26][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:26][C][switch.gpio:042]: GPIO Switch 'pcf8574_3_1'
[11:28:26][C][switch.gpio:043]:   Pin: GPIO1 (Mode: OUTPUT, INVERTED)
[11:28:26][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:26][C][switch.gpio:042]: GPIO Switch 'pcf8574_3_2'
[11:28:26][C][switch.gpio:043]:   Pin: GPIO2 (Mode: OUTPUT, INVERTED)
[11:28:26][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:26][C][switch.gpio:042]: GPIO Switch 'pcf8574_3_3'
[11:28:26][C][switch.gpio:043]:   Pin: GPIO3 (Mode: OUTPUT, INVERTED)
[11:28:26][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:26][C][switch.gpio:042]: GPIO Switch 'pcf8574_3_4'
[11:28:26][C][switch.gpio:043]:   Pin: GPIO4 (Mode: OUTPUT, INVERTED)
[11:28:26][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:26][C][switch.gpio:042]: GPIO Switch 'pcf8574_3_5'
[11:28:26][C][switch.gpio:043]:   Pin: GPIO5 (Mode: OUTPUT, INVERTED)
[11:28:26][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:26][C][switch.gpio:042]: GPIO Switch 'pcf8574_3_6'
[11:28:26][C][switch.gpio:043]:   Pin: GPIO6 (Mode: OUTPUT, INVERTED)
[11:28:26][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:26][C][switch.gpio:042]: GPIO Switch 'pcf8574_3_7'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO7 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'pcf8574_4_0'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO0 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'pcf8574_4_1'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO1 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'pcf8574_4_2'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO2 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'pcf8574_4_3'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO3 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'pcf8574_4_4'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO4 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'pcf8574_4_5'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO5 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'pcf8574_4_6'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO6 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'pcf8574_4_7'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO7 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'MCP23008_1_0'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO0 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'MCP23008_1_1'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO1 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'MCP23008_1_2'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO2 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'MCP23008_1_3'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO3 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'MCP23008_1_4'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO4 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'MCP23008_1_5'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO5 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'MCP23008_1_6'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO6 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][switch.gpio:042]: GPIO Switch 'MCP23008_1_7'
[11:28:27][C][switch.gpio:043]:   Pin: GPIO7 (Mode: OUTPUT, INVERTED)
[11:28:27][C][switch.gpio:059]:   Restore Mode: Restore (Defaults to OFF)
[11:28:27][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_1_0'
[11:28:27][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:27][C][gpio.binary_sensor:016]:   Pin: GPIO0 (Mode: INPUT)
[11:28:27][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_1_1'
[11:28:27][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:27][C][gpio.binary_sensor:016]:   Pin: GPIO1 (Mode: INPUT)
[11:28:27][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_1_2'
[11:28:27][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:27][C][gpio.binary_sensor:016]:   Pin: GPIO2 (Mode: INPUT)
[11:28:27][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_1_3'
[11:28:27][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:27][C][gpio.binary_sensor:016]:   Pin: GPIO3 (Mode: INPUT)
[11:28:27][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_1_4'
[11:28:27][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:27][C][gpio.binary_sensor:016]:   Pin: GPIO4 (Mode: INPUT)
[11:28:27][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_1_5'
[11:28:27][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:27][C][gpio.binary_sensor:016]:   Pin: GPIO5 (Mode: INPUT)
[11:28:27][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_1_6'
[11:28:27][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:27][C][gpio.binary_sensor:016]:   Pin: GPIO6 (Mode: INPUT)
[11:28:27][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_1_7'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'safety'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO7 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_2_0'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO0 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_2_1'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO1 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_2_2'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO2 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_2_3'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO3 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_2_4'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO4 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_2_5'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO5 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_2_6'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO6 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'pcf8574_2_7'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'safety'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO7 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'MCP23008_2_0'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO0 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'MCP23008_2_1'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO1 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'MCP23008_2_2'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO2 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'MCP23008_2_3'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO3 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'MCP23008_2_4'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO4 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'MCP23008_2_5'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO5 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'MCP23008_2_6'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO6 (Mode: INPUT)
[11:28:28][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'MCP23008_2_7'
[11:28:28][C][gpio.binary_sensor:015]:   Device Class: 'opening'
[11:28:28][C][gpio.binary_sensor:016]:   Pin: GPIO7 (Mode: INPUT)
[11:28:30][C][logger:175]: Logger:
[11:28:30][C][logger:176]:   Level: DEBUG
[11:28:30][C][logger:177]:   Log Baud Rate: 115200
[11:28:30][C][logger:178]:   Hardware UART: UART0
[11:28:30][C][ota:029]: Over-The-Air Updates:
[11:28:30][C][ota:030]:   Address: test.local:8266
[11:28:30][C][ota:032]:   Using Password.
[11:28:30][C][api:095]: API Server:
[11:28:30][C][api:096]:   Address: test.local:6053
[11:28:30][C][wifi_signal.sensor:009]: WiFi Signal 'WiFi_signal_test'
[11:28:30][C][wifi_signal.sensor:009]:   Unit of Measurement: 'dB'
[11:28:30][C][wifi_signal.sensor:009]:   Accuracy Decimals: 0
[11:28:30][C][wifi_signal.sensor:009]:   Icon: 'mdi:wifi'
[11:28:30][D][debug:023]: ESPHome version 1.14.0b5
[11:28:30][D][debug:025]: Free Heap Size: 21912 bytes
[11:28:30][D][debug:053]: Flash Chip: Size=4096kB Speed=40MHz Mode=DOUT
[11:28:30][D][debug:190]: Chip ID: 0x0053D5CD
[11:28:30][D][debug:191]: SDK Version: 2.2.1(cfd48f3)
[11:28:30][D][debug:192]: Core Version: 2_5_2
[11:28:30][D][debug:193]: Boot Version=6 Mode=1
[11:28:30][D][debug:194]: CPU Frequency: 80
[11:28:30][D][debug:195]: Flash Chip ID=0x00164020
[11:28:30][D][debug:196]: Reset Reason: Software/System restart
[11:28:30][D][debug:197]: Reset Info: Fatal exception:0 flag:4 (SOFT_RESTART) epc1:0x00000000 epc2:0x00000000 epc3:0x00000000 excvaddr:0x00000000 depc:0x00000000
[11:29:01][D][sensor:092]: 'WiFi_signal_test': Sending state -61.00000 dB with 0 decimals of accuracy
[11:30:01][D][sensor:092]: 'WiFi_signal_test': Sending state -62.00000 dB with 0 decimals of accuracy
[11:30:19][I][ota:046]: Boot seems successful, resetting boot loop counter.
[11:31:01][D][sensor:092]: 'WiFi_signal_test': Sending state -62.00000 dB with 0 decimals of accuracy
[11:32:01][D][sensor:092]: 'WiFi_signal_test': Sending state -63.00000 dB with 0 decimals of accuracy
[11:33:01][D][sensor:092]: 'WiFi_signal_test': Sending state -62.00000 dB with 0 decimals of accuracy
[11:33:05][D][switch:025]: 'pcf8574_4_3' Turning OFF.
[11:33:05][D][switch:045]: 'pcf8574_4_3': Sending state OFF
[11:33:05][D][switch:025]: 'pcf8574_4_4' Turning OFF.
[11:33:05][D][switch:045]: 'pcf8574_4_4': Sending state OFF
[11:33:05][D][switch:025]: 'pcf8574_4_5' Turning OFF.
[11:33:05][D][switch:045]: 'pcf8574_4_5': Sending state OFF
[11:33:05][D][switch:025]: 'pcf8574_4_6' Turning OFF.
[11:33:05][D][switch:045]: 'pcf8574_4_6': Sending state OFF
[11:33:05][D][switch:025]: 'pcf8574_4_7' Turning OFF.
[11:33:05][D][switch:045]: 'pcf8574_4_7': Sending state OFF
[11:33:05][D][switch:025]: 'MCP23008_1_0' Turning OFF.
[11:33:05][D][switch:045]: 'MCP23008_1_0': Sending state OFF
[11:33:05][D][switch:025]: 'MCP23008_1_1' Turning OFF.
[11:33:05][D][switch:045]: 'MCP23008_1_1': Sending state OFF
[11:33:05][D][switch:025]: 'MCP23008_1_2' Turning OFF.
[11:33:05][D][switch:045]: 'MCP23008_1_2': Sending state OFF
[11:33:05][D][switch:025]: 'MCP23008_1_3' Turning OFF.
[11:33:05][D][switch:045]: 'MCP23008_1_3': Sending state OFF
[11:33:05][D][switch:025]: 'MCP23008_1_4' Turning OFF.
[11:33:05][D][switch:045]: 'MCP23008_1_4': Sending state OFF
[11:33:05][D][switch:025]: 'MCP23008_1_5' Turning OFF.
[11:33:05][D][switch:045]: 'MCP23008_1_5': Sending state OFF
[11:33:05](Message skipped because it was too big to fit in TCP buffer - This is only cosmetic)
[11:33:05][D][switch:045]: 'MCP23008_1_6': Sending state OFF
[11:33:05](Message skipped because it was too big to fit in TCP buffer - This is only cosmetic)
[11:33:05][D][switch:045]: 'MCP23008_1_7': Sending state OFF
[11:33:05][D][switch:025]: 'pcf8574_3_0' Turning OFF.
[11:33:05][D][switch:045]: 'pcf8574_3_0': Sending state OFF
[11:33:05][D][switch:025]: 'pcf8574_3_1' Turning OFF.
[11:33:05][D][switch:045]: 'pcf8574_3_1': Sending state OFF
[11:33:05][D][switch:025]: 'pcf8574_3_2' Turning OFF.
[11:33:05][D][switch:045]: 'pcf8574_3_2': Sending state OFF
[11:33:05][D][switch:025]: 'pcf8574_3_3' Turning OFF.
[11:33:05](Message skipped because it was too big to fit in TCP buffer - This is only cosmetic)
[11:33:05][D][switch:025]: 'pcf8574_3_4' Turning OFF.
[11:33:05][D][switch:045]: 'pcf8574_3_4': Sending state OFF
[11:33:05][D][switch:025]: 'pcf8574_3_5' Turning OFF.
[11:33:05][D][switch:045]: 'pcf8574_3_5': Sending state OFF
[11:33:05][D][switch:025]: 'pcf8574_3_6' Turning OFF.
[11:33:05][D][switch:045]: 'pcf8574_3_6': Sending state OFF
[11:33:05][D][switch:025]: 'pcf8574_3_7' Turning OFF.
[11:33:05][D][switch:045]: 'pcf8574_3_7': Sending state OFF
[11:33:05](Message skipped because it was too big to fit in TCP buffer - This is only cosmetic)
[11:33:05](Message skipped because it was too big to fit in TCP buffer - This is only cosmetic)
[11:33:05][D][api:067]: Disconnecting Home Assistant 0.102.0.dev20191101 (10.x.x.y)
[11:33:11][D][api.connection:578]: Client 'Home Assistant 0.102.0.dev20191101 (10.x.x.y)' connected successfully!
[11:34:01][D][sensor:092]: 'WiFi_signal_test': Sending state -61.00000 dB with 0 decimals of accuracy
S-Przybylski commented 4 years ago

Could somebody support me in setting up the correct debug parameter (selective debugging) in ha ?

S-Przybylski commented 4 years ago

I tired a debug log and found the following error:

2019-11-02 12:07:07 INFO (MainThread) [aioesphomeapi.connection] test.local: Error while reading incoming messages: Invalid protobuf message: Truncated message.
2019-11-02 12:07:07 DEBUG (MainThread) [aioesphomeapi.connection] test.local: Closed socket
2019-11-02 12:07:07 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for test.local

HA Logfile: Action at 12:07:07 ha_debug.log

glmnet commented 4 years ago

So the api communication is complaining of bad info from ESPHome.

Looks like a bug in the esp side. I believe next step will be logging using serial because you’ll need to increase log verbosity on the esp.

You’ll need to send information near the disconnection event only. I have no pcf to try to replicate. Maybe standard gpio will fail too.

S-Przybylski commented 4 years ago

At 15:37:30-31 i press the group switch button, then the connection was closed

Logfile see: log.txt

Logfile extract:

[15:37:31][V][app:076]: A component took a long time in a loop() cycle (0.29 s).
[15:37:31][V][app:077]: Components should block for at most 20-30ms in loop().
...
[15:37:32][V][app:076]: A component took a long time in a loop() cycle (0.79 s).
[15:37:32][V][app:077]: Components should block for at most 20-30ms in loop().
[15:37:33][VV][api.service:250]: on_ping_request: PingRequest {}
[15:37:33][VV][api.service:035]: send_ping_response: PingResponse {}
[15:37:38][D][api:067]: Disconnecting Home Assistant 0.101.2 (10.x.x.x)
[15:37:43][VV][api.service:222]: on_hello_request: HelloRequest {
[15:37:43]  client_info: 'Home Assistant 0.101.2'
S-Przybylski commented 4 years ago

I have used the following logging:

debug:

# Enable logging
logger:
  level: very_verbose
  logs:
    i2c: debug
S-Przybylski commented 4 years ago

I made some test with different group sizes in HA:

  1. Up to 7 switches in one group are working without any exception!
  2. 8 and more switches lead to disconnection most of the time if the group switch is changed

Its fully independent, which kind of switches are conducted (i have mixed pcf from different boards and also used some of my mcp23008 board)!

brandond commented 4 years ago

The error says that the protobuf message is truncated. I haven't looked at the native api stuff much but it sounds like it's filling a buffer somewhere due to too many events firing all at once.

OttoWinter commented 4 years ago

@brandond @S-Przybylski Re "truncated": I guess that just means that the connection was closed prematurely (upon sending a ping request). Protobuf itself does not know where a message ends, that's encoded as a varint at the start of the packet.

[15:37:31][V][app:076]: A component took a long time in a loop() cycle (0.29 s).
[15:37:31][V][app:077]: Components should block for at most 20-30ms in loop().

This looks like the problem. Is that only while switching or constantly appearing in the logs? Are you using any custom components? Please post a list of all components you're using. One of them is blocking the main thread, which is causing pings to time out.

S-Przybylski commented 4 years ago

Dear @OttoWinter my konfiguration is a test installation. The esp 8266 connects these components using i2c:

The message appears only if i toogle the group switch of the outputs (switches) in HA.

OttoWinter commented 4 years ago

Hmm, maybe it has to do with the i2c speed. If all output pins are switched, then it would require 16+8 i2c writes with 16*2+8 bytes (320 bits) of data. Even if that would include a lot of overhead for i2c address etc, I don't think that can get a problem at 50kHz (default i2c rate).

Maybe try a higher i2c frequency setting - otherwise I don't really know what it is. But from the logs it's pretty clear that it's related to the main thread being stopped for almost a second.

S-Przybylski commented 4 years ago

Today i made some tests! It seems that the error depends on timing issues. Here are my Results:

Details - Test cases:

  1. Logging to: very_verbose (except for i2c: debug) AND Console logging via WLAN! Played with i2c frequency from 50 to 200kHz - 24 outputs need at least 2 seconds for setting (frequency independend) Result: Works without issues (one or two times i got a timeout!) I always saw loop notifications, but no disconnect! Examples: 22:39:25][V][app:076]: A component took a long time in a loop() cycle (1.66 s). [22:41:23][V][app:076]: A component took a long time in a loop() cycle (1.67 s). [22:41:56][V][app:076]: A component took a long time in a loop() cycle (3.04 s). ...

  2. Logging to: very_verbose (except for i2c: debug) AND Console logging via /dev/ttyUSB0 Played with i2c frequency from 50 to 200kHz - 24 outputs need at least 2 seconds for setting (frequency independend) Result: Always disconnects at each group switch!!!! /dev/ttyUSB0 (USB2.0-Serial): INFO Reading configuration /config/test.yaml... INFO Starting log output from /dev/ttyUSB0 with baud rate 115200 ... [23:13:03][V][app:076]: A component took a long time in a loop() cycle (0.69 s). [23:13:03][V][app:077]: Components should block for at most 20-30ms in loop(). [23:13:06][VV][api.service:250]: on_ping_request: PingRequest {} [23:13:06][VV][api.service:035]: send_ping_response: PingResponse {} [23:13:11][D][api:067]: Disconnecting Home Assistant 0.101.2 (10.x.x.x) [23:13:11][VV][api.service:222]: on_hello_request: HelloRequest { [23:13:11] client_info: 'Home Assistant 0.101.2' [23:13:11]} [23:13:11][V][api.connection:562]: Hello from client: 'Home Assistant 0.101.2 (10.x.x.x)' [23:13:11][VV][api.service:010]: send_hello_response: HelloResponse { [23:13:11] api_version_major: 1 [23:13:11] api_version_minor: 3 [23:13:11] server_info: 'test (esphome v1.14.0)' [23:13:11]} [23:13:11][VV][api.service:229]: on_connect_request: ConnectRequest { [23:13:11] password: 'iotcentral' [23:13:11]} [23:13:11][D][api.connection:578]: Client 'Home Assistant 0.101.2 (10.x.x.x)' connected successfully! [23:13:11][VV][api.service:015]: send_connect_response: ConnectResponse { ...

  3. Logging to: debug (only!!!) AND Console logging via WLAN Played with i2c frequency 50 and 200kHz - 24 outputs need at least 0.5 seconds for setting (frequency independend) Result: Disconnects at nearly each group switch!!!!

  4. Logging to: debug (only!!!) AND Console logging via /dev/ttyUSB0 Played with i2c frequency 50 and 200kHz - 24 outputs need at least 0.5 seconds for setting (frequency independend) Result: Always disconnects at each group switch!!!!

OttoWinter commented 4 years ago

I guess that makes sense, in very verbose mode the log message packets also serve as ping responses. Good to knoe the symtpom can be solved that way.

However the underlying issue is still not clear to me. I don't understand how swichting many switches at a time could lead to the main loop getting slowed down that much.

I think I will try to replicate this with gpio switches. If it also appears there then it must be something in the API layer, otherwise it would be due to i2c/pcf/mcp.

S-Przybylski commented 4 years ago

I reduced the scope of the test case to only one attached pcf8574 with 8 outputs: I got disconnects:

Interessting that logging "info" is more affected than "debug" ...

S-Przybylski commented 4 years ago

Dear @OttoWinter sorry i forgot to tell you: Some days before i made a test with a simple configuration with ony one mcp23008 output module (8 pins output). The behaviour is the same.

Therefore i think the problem is not related to mcp23008 or pcf8574 drivers.

S-Przybylski commented 4 years ago

Dear @OttoWinter, today i tried to involve only esp8266 gpio outputs without any additional configuration! The unavailability of the switches after pressing several times the group switch button in HA is the same. Therefore i think its related to the core and/or the connection between esphome and HA and not to i2c, mcp23008 or pcf8574!

Part of my configuration (Used D0 up to D7): switch:

glmnet commented 4 years ago

Closing this as discussion follows on #877