search

esphome / issues

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

Displaying current time leads to disconnects #768

Closed 7h30n3 closed 4 years ago

7h30n3 commented 5 years ago

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

Windows 10 Python 3.7.4 (tags/v3.7.4:e09359112e, Jul 8 2019, 20:34:20) [MSC v.1916 64 bit (AMD64)] on win32

ESP (ESP32/ESP8266, Board/Sonoff):

ESP8266 (NodeMCUv2)

Affected component:

https://esphome.io/components/time.html https://esphome.io/components/display/index.html

Description of problem:

The ESP8266 randomly disconnects from home assistant, the wifi_strength component shows a RSSI of 31dB and the htu21d sensor shows NaN or unavailable. All other ESPHome clients I have (without display) don't show this behavior. First I thought it got something to do with power_save_mode, then the time-component, but it turns out it's the following part:

      - id: page3
        lambda: |-
          it.strftime(2, 5, id(logisoso_26), "%H:%M:%S", id(time_hass).now());
          it.line(0, 46, 127, 46);
          it.strftime(27, 48, id(arial_14), "%d.%m.%Y", id(time_hass).now());

grafik

As you can see in the image if I comment out this part everything is fine and I got the RSSI highlighted in yellow. With the part I got many disconnects and a RSSI auf 31dB.

I use Version: 1.14.0b2, but it didn't work with 1.13.6 either.

Problem-relevant YAML-configuration entries:

esphome:
  name: sh1106_si7021
  platform: ESP8266
  board: nodemcuv2

api:

wifi:
  ssid: 'wirelessnetwork'
  password: 'secret'
  power_save_mode: high

# Enable logging
logger:
  level: verbose

i2c:

ota:

spi:
  clk_pin: 14
  mosi_pin: 13

sensor:
  - platform: wifi_signal
    name: "SH1106 Si7021 - RSSI"
    filters:
        - delta: 2.0

  - platform: htu21d
    temperature:
      filters:
        - delta: 0.4
        - offset: -5.2
      name: "SH1106 Si7021 - Temperature"
      unit_of_measurement: "°C"
      id: temperature
    humidity:
      filters:
        - delta: 1.2
        - offset: 4.0
      name: "SH1106 Si7021 - Humidity"
      accuracy_decimals: 1
      unit_of_measurement: "%"
      id: humidity
    update_interval: 60s

time:
  - platform: homeassistant
    id: time_hass

font:
  - file: "sh1106_si7021_dependencies/arial.ttf"
    id: arial_14
    size: 14
    glyphs:
    - "]"
    - "["
    - T
    - e
    - m
    - p 
    - r
    - a
    - t
    - u
    - L
    - f
    - c
    - h
    - "."
    - ":"
    - 1
    - 2
    - 3
    - 4
    - 5
    - 6
    - 7
    - 8
    - 9
    - 0
    - " "
    - "°"
    - C
    - "%"

  - file: "sh1106_si7021_dependencies/Logisoso.ttf"
    id: logisoso_42
    size: 62

  - file: "sh1106_si7021_dependencies/Logisoso.ttf"
    id: logisoso_26
    size: 39

display:
  - platform: ssd1306_spi
    model: "SH1106 128x64"
    brightness: 60%
    cs_pin: 15
    dc_pin: 0
    reset_pin: 2
    id: my_display
    pages:
      - id: page1
        lambda: |-
          it.printf(15, 23, id(logisoso_42), "%.1f", id(temperature).state);
          it.line(0, 46, 127, 46);
          it.print(13, 48, id(arial_14), "Temperatur [°C]");
      - id: page2
        lambda: |-
          it.printf(15, 23, id(logisoso_42), "%.1f", id(humidity).state);
          it.line(0, 46, 127, 46);
          it.print(16, 48, id(arial_14), "Luftfeuchte [%]");
      - id: page3
        lambda: |-
          it.strftime(2, 5, id(logisoso_26), "%H:%M:%S", id(time_hass).now());
          it.line(0, 46, 127, 46);
          it.strftime(27, 48, id(arial_14), "%d.%m.%Y", id(time_hass).now());

interval:
  - interval: 3s
    then:
      - display.page.show_next: my_display
      - component.update: my_display

Logs (if applicable):

PASTE DEBUG LOG HERE

Additional information and things you've tried:

brandond commented 5 years ago

Collect the log files via serial, please. Sounds like it's crashing and restarting.

OttoWinter commented 5 years ago

  1. This loos like another case of https://github.com/esphome/issues/issues/455 to me. Yes crashing might be an option too like @brandond mentioned, but then it would probably be consistent and not happen.

  2. please try without power_save_mode option again, it was suggested for some time that it could be of influence, but it that didn't appear to be the case anymore as of a few versions ago and that tio has been removed from thr faq.

  3. the positive rssi value is ingeresting. In general, RSSI is defined as the logarithm of a ratio (and therefore should be <0 at all times). Looking at the esp8266 sdk 31 stands for an error, probably because the rssi sensor published the state while wifi was still connecting.

  4. An issue might be if your text writes over the edge of the display - I don't remember if there are checks to prevent users from accessing the display buffer out kd range (if, then for performance reasons). Try printing a static text instead.

7h30n3 commented 5 years ago

I would like to test it all, but I made a mistake. I set log_level: very_verbose and now the ESP doesn't respond anymore and I can't flash a new firmware. Port busy... I got the error: "The semaphore timeout period has expired.", but I managed to fix this thanks to this: https://stackoverflow.com/questions/13999439/the-semaphore-timeout-period-has-expired-error-for-usb-connection?noredirect=1&lq=1

So tonight I can test your suggestions.

OttoWinter commented 5 years ago

You can also just push the boot button on your ESP32 (or hold GPIO0 low) while plugging the device into USB. It will enter the bootloader mode and not run any code (and can't kill the USB bus)

7h30n3 commented 5 years ago

Here is a short log with one disconnect.

INFO Starting log output from 192.168.1.41 using esphome API
INFO Connecting to 192.168.1.41:6053 (192.168.1.41)
INFO Successfully connected to 192.168.1.41
[23:18:58][I][app:100]: esphome version 1.14.0b2 compiled on Oct 24 2019, 08:43:03
[23:18:58][C][wifi:409]: WiFi:
[23:18:58][C][wifi:277]:   SSID: 'wirelessnetwork'
[23:18:58][C][wifi:278]:   IP Address: 192.168.1.41
[23:18:58][C][wifi:281]:   Hostname: 'sh1106_si7021'
[23:18:58][C][wifi:285]:   Signal strength: -62 dB ▂▄▆█
[23:18:58][V][wifi:287]:   Priority: -446.0
[23:18:58][C][wifi:289]:   Channel: 6
[23:18:58][C][wifi:290]:   Subnet: 255.255.255.0
[23:18:58][C][wifi:291]:   Gateway: 192.168.1.1
[23:18:58][C][wifi:292]:   DNS1: (IP unset)
[23:18:58][C][wifi:293]:   DNS2: (IP unset)
[23:18:58][C][i2c:028]: I2C Bus:
[23:18:58][C][i2c:029]:   SDA Pin: GPIO4
[23:18:58][C][i2c:030]:   SCL Pin: GPIO5
[23:18:58][C][i2c:031]:   Frequency: 50000 Hz
[23:18:58][I][i2c:033]: Scanning i2c bus for active devices...
[23:18:58][I][i2c:040]: Found i2c device at address 0x40
[23:18:58][C][spi:079]: SPI bus:
[23:18:58][C][spi:080]:   CLK Pin: GPIO14 (Mode: OUTPUT)
[23:18:58][C][spi:082]:   MOSI Pin: GPIO13 (Mode: OUTPUT)
[23:18:58][C][spi:083]:   Using HW SPI: NO
[23:18:58][C][logger:175]: Logger:
[23:18:58][C][logger:176]:   Level: VERBOSE
[23:18:58][C][logger:177]:   Log Baud Rate: 115200
[23:18:58][C][logger:178]:   Hardware UART: UART0
[23:18:58][C][htu21d:027]: HTU21D:
[23:18:58][C][htu21d:028]:   Address: 0x40
[23:18:58][C][htu21d:032]:   Update Interval: 60.0s
[23:18:58][C][htu21d:033]:   Temperature 'SH1106 Si7021 - Temperature'
[23:18:58][C][htu21d:033]:     Unit of Measurement: '°C'
[23:19:00][C][htu21d:033]:     Accuracy Decimals: 1
[23:19:00][C][htu21d:033]:     Icon: 'mdi:thermometer'
[23:19:00][C][htu21d:034]:   Humidity 'SH1106 Si7021 - Humidity'
[23:19:00][C][htu21d:034]:     Unit of Measurement: '%'
[23:19:00][C][htu21d:034]:     Accuracy Decimals: 1
[23:19:00][C][htu21d:034]:     Icon: 'mdi:water-percent'
[23:19:00][C][homeassistant.time:010]: Home Assistant Time:
[23:19:00][C][homeassistant.time:011]:   Timezone: 'CET-1CEST-2,M3.5.0/2,M10.4.0/3'
[23:19:00](Message skipped because it was too big to fit in TCP buffer - This is only cosmetic)
[23:19:00](Message skipped because it was too big to fit in TCP buffer - This is only cosmetic)
[23:19:00](Message skipped because it was too big to fit in TCP buffer - This is only cosmetic)
[23:19:00](Message skipped because it was too big to fit in TCP buffer - This is only cosmetic)
[23:19:00](Message skipped because it was too big to fit in TCP buffer - This is only cosmetic)
[23:19:00](Message skipped because it was too big to fit in TCP buffer - This is only cosmetic)
[23:19:25][D][htu21d:052]: Got Temperature=24.1°C Humidity=67.5%
[23:19:25][V][sensor:013]: 'SH1106 Si7021 - Temperature': Received new state 24.107246
[23:19:25][V][sensor:013]: 'SH1106 Si7021 - Humidity': Received new state 67.471069
[23:19:48][V][sensor:013]: 'SH1106 Si7021 - RSSI': Received new state -62.000000
[23:20:25][D][htu21d:052]: Got Temperature=24.1°C Humidity=67.5%
[23:20:25][V][sensor:013]: 'SH1106 Si7021 - Temperature': Received new state 24.085800
[23:20:25][V][sensor:013]: 'SH1106 Si7021 - Humidity': Received new state 67.493958
ERROR Error while reading incoming messages: Error while receiving data: [WinError 10038] Ein Vorgang bezog sich auf ein Objekt, das kein Socket ist
WARNING Disconnected from API: Timeout while waiting for message response!
INFO Connecting to 192.168.1.41:6053 (192.168.1.41)
WARNING Couldn't connect to API (Error connecting to 192.168.1.41: timed out). Trying to reconnect in 1 seconds
INFO Connecting to 192.168.1.41:6053 (192.168.1.41)
INFO Successfully connected to 192.168.1.41
[23:21:00][V][api.connection:562]: Hello from client: 'Home Assistant 0.100.2 (192.168.1.148)'
[23:21:00][D][api.connection:578]: Client 'Home Assistant 0.100.2 (192.168.1.148)' connected successfully!
[23:21:00][D][time:029]: Synchronized time: Thu Oct 24 23:21:01 2019
OttoWinter commented 5 years ago

now the same over usb please - the network logs obviously aren't much help because they don't show during the actual error.

7h30n3 commented 5 years ago

You are right. Here we go:

[D][htu21d:052]: Got Temperature=24.2°C Humidity=67.3%
[V][sensor:013]: 'SH1106 Si7021 - Temperature': Received new state 24.214500
[D][sensor:092]: 'SH1106 Si7021 - Temperature': Sending state 19.01450 °C with 1 decimals of accuracy
[V][sensor:013]: 'SH1106 Si7021 - Humidity': Received new state 67.310852
[D][sensor:092]: 'SH1106 Si7021 - Humidity': Sending state 71.31085 % with 1 decimals of accuracy
bcn_timout,ap_probe_send_start
ap_probe_send over, rest wifi status to disassoc
state: 5 -> 0 (1)
rm 0
pm close 7
[W][wifi_esp8266:334]: Event: Disconnected ssid='wirelessnetwork'  reason='Beacon Timeout'
wifi evt: 1
STA disconnect: 200
[W][wifi:094]: WiFi Connection lost... Reconnecting...
[W][wifi:482]: Restarting WiFi adapter...
[V][wifi_esp8266:035]: Disabling STA.
del if0
usl
mode : null
[V][wifi_esp8266:372]: Event: Changed Mode old=STA new=OFF
wifi evt: 8
[V][api.connection:667]: Error: Disconnecting Home Assistant 0.100.2 (192.168.1.148)
[D][api:067]: Disconnecting Home Assistant 0.100.2 (192.168.1.148)
[D][wifi:298]: Starting scan...
[V][wifi_esp8266:033]: Enabling STA.
mode : sta(60:01:94:0e:a7:97)
ip:192.168.1.41,mask:255.255.255.0,gw:192.168.1.1
add if0
[V][wifi_esp8266:372]: Event: Changed Mode old=OFF new=STA
wifi evt: 8
scandone
[D][wifi:313]: Found networks:
[I][wifi:359]: - 'wirelessnetwork' () ▂▄▆█
[D][wifi:360]:     Channel: 6
[D][wifi:361]:     RSSI: -60 dB
[I][wifi:187]: WiFi Connecting to 'wirelessnetwork'...
[V][wifi:189]: Connection Params:
[V][wifi:190]:   SSID: 'wirelessnetwork'
[V][wifi:193]:   BSSID: 
[V][wifi:197]:   Password: 'secret'
[V][wifi:199]:   Channel: 6
[V][wifi:207]:   Manual IP: Static IP=192.168.1.41 Gateway=192.168.1.1 Subnet=255.255.255.0 DNS1=(IP unset) DNS2=(IP unset)
[V][wifi:211]:   Hidden: NO
[V][app:076]: A component took a long time in a loop() cycle (0.52 s).
[V][app:077]: Components should block for at most 20-30ms in loop().
scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 7
cnt 
[V][sensor:013]: 'SH1106 Si7021 - RSSI': Received new state 31.000000
[D][sensor:092]: 'SH1106 Si7021 - RSSI': Sending state 31.00000 dB with 0 decimals of accuracy

connected with wireless, channel 6
ip:192.168.1.41,mask:255.255.255.0,gw:192.168.1.1
[V][wifi_esp8266:325]: Event: Connected ssid='wirelessnetwork'  channel=6
wifi evt: 0
[V][wifi_esp8266:346]: Event: Got IP static_ip=192.168.1.41 gateway=192.168.1.1 netmask=255.255.255.0
wifi evt: 3
[I][wifi:417]: WiFi Connected!
[C][wifi:277]:   SSID: 'wirelessnetwork'
[C][wifi:278]:   IP Address: 192.168.1.41
[C][wifi:280]:   BSSID: 
[C][wifi:281]:   Hostname: 'sh1106_si7021'
[C][wifi:285]:   Signal strength: -63 dB ▂▄▆█
[V][wifi:287]:   Priority: -1.0
[C][wifi:289]:   Channel: 6
[C][wifi:290]:   Subnet: 255.255.255.0
[C][wifi:291]:   Gateway: 192.168.1.1
[C][wifi:292]:   DNS1: (IP unset)
[C][wifi:293]:   DNS2: (IP unset)
[V][api.connection:562]: Hello from client: 'Home Assistant 0.100.2 (192.168.1.148)'
[D][api.connection:578]: Client 'Home Assistant 0.100.2 (192.168.1.148)' connected successfully!
[D][time:029]: Synchronized time: Thu Oct 24 23:38:41 2019
pm open,type:2 0
bcn_timout,ap_probe_send_start
ap_probe_send over, rest wifi status to disassoc
state: 5 -> 0 (1)
rm 0
pm close 7
[W][wifi_esp8266:334]: Event: Disconnected ssid='wirelessnetwork'  reason='Beacon Timeout'
wifi evt: 1
STA disconnect: 200
[W][wifi:094]: WiFi Connection lost... Reconnecting...
[W][wifi:482]: Restarting WiFi adapter...
[V][wifi_esp8266:035]: Disabling STA.
del if0
usl
mode : null
[V][wifi_esp8266:372]: Event: Changed Mode old=STA new=OFF
wifi evt: 8
[V][api.connection:667]: Error: Disconnecting Home Assistant 0.100.2 (192.168.1.148)
[D][api:067]: Disconnecting Home Assistant 0.100.2 (192.168.1.148)
[D][wifi:298]: Starting scan...
[V][wifi_esp8266:033]: Enabling STA.
mode : sta(60:01:94:0e:a7:97)
ip:192.168.1.41,mask:255.255.255.0,gw:192.168.1.1
add if0
[V][wifi_esp8266:372]: Event: Changed Mode old=OFF new=STA
wifi evt: 8

EDIT: So I did a few more tests and I came to the conclusion that it got to do something with power_save_mode with displaying the time making it worse.

Can someone use my yaml from above a can test it, too? You actually don't have to have a display connected, if you don't have one lying around.

OttoWinter commented 5 years ago

ap_probe_send over, rest wifi status to disassoc certainly is due to the power_save_mode: high (more info here: https://github.com/esp8266/Arduino/issues/5083). Please use the default setting again, and if still experiencing the issue post logs again.

7h30n3 commented 5 years ago

It some further testing and I'm pretty sure that it's `power_save_mode: high'. I set it to 'none' for now and hope that someone will find a solution for that problem. The only thing that's bugging me is the fact, that another ESP8266 of mine with an BME280+TSL2591 attached doesn't show that behaviour, at least not that extreme.

Is it possible to manage the wifi connection manually? Simply put:

on_value_change:
    -then:
       -wifi.connect
...
OttoWinter commented 4 years ago

I set it to 'none' for now and hope that someone will find a solution for that problem.

That's the reason none is the default, it's more stable. The issue for that is somewhere in espressif's codebase (it's not even clear what this option really does).

Is it possible to manage the wifi connection manually? Simply put:

No, but that should not be necessary. It will reconnect if it disconnects.

no-response[bot] commented 4 years ago

This issue has been automatically closed because there has been no response to our request for more information from the original author. With only the information that is currently in the issue, we don't have enough information to take action. Please reach out if you have or find the answers we need so that we can investigate further.