Skip to content
This repository has been archived by the owner on Sep 27, 2023. It is now read-only.

sliding_window_moving_average causes boot looping. #394

Closed
tomlut opened this issue Jan 15, 2019 · 33 comments
Closed

sliding_window_moving_average causes boot looping. #394

tomlut opened this issue Jan 15, 2019 · 33 comments

Comments

@tomlut
Copy link

tomlut commented Jan 15, 2019

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

Hassio 0.85.1, ESPhome 1.10.0
ESP (ESP32/ESP8266/Board/Sonoff):

ESP8266 (Wemos D1 mini)

Affected component:

https://esphomelib.com/esphomeyaml/components/sensor/index.html#sensor-filters

Description of problem:
Including the recommended configuration to bring back a windowed moving average causes validation errors:

  - platform: adc
    pin: A0
    name: "Master Bed Sensor"
    update_interval: 15s
    filters:
      - multiply: 3.25
      - sliding_window_moving_average:
sensor.adc: [source /config/esphomeyaml/master_bed.yaml:37]
  platform: adc
  pin: A0
  name: Master Bed Sensor
  update_interval: 15s
  filters:  [source /config/esphomeyaml/master_bed.yaml:42]
    - multiply: 3.25
    - [source /config/esphomeyaml/master_bed.yaml:43]
      
      expected a dictionary.
      sliding_window_moving_average: 

Including the full sliding window filter configuration causes boot looping:

  - platform: adc
    pin: A0
    name: "Master Bed Sensor"
    update_interval: 15s
    filters:
      - multiply: 3.25
      - sliding_window_moving_average:
          window_size: 15
          send_every: 15
[18:51:56] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[18:51:56]
[18:51:56]wdt reset
[18:51:56]load 0x4010f000, len 1384, room 16 
[18:51:56]tail 8
[18:51:56]chksum 0x2d
[18:51:56]csum 0x2d
[18:51:56]vbb28d4a3
[18:51:56]~ld
[18:51:56][I][logger:071]: Log initialized
[18:51:56][C][ota:461]: There have been 3 suspected unsuccessful boot attempts.
[18:51:56][I][application:053]: Running through setup()...
[18:51:56][D][binary_sensor:027]: 'Master Bed Sensor Status': Sending state OFF
[18:51:56][C][sensor.adc:028]: Setting up ADC 'Master Bed Sensor'...
[18:51:56][C][wifi:029]: Setting up WiFi...
[18:51:56][D][wifi:260]: Starting scan...

Removing the sliding window average configuration compiles and runs as expected. Though the sensor is not averaged (as is wanted):

  - platform: adc
    pin: A0
    name: "Master Bed Sensor"
    update_interval: 15s
    filters:
      - multiply: 3.25

Problem-relevant YAML-configuration entries:

PASTE YAML FILE HERE

As per descrition above.
Traceback (if applicable):


Additional information:

@OttoWinter
Copy link
Member

You're right about the first part, indeed only specifying sliding_window_moving_average: is invalid.

But with the configuration you gave here, I don't see any boot looping. The log you provided only contains the last part of the log, if it were to crash there would be a long stacktrace printed before that. I would need that stacktrace to debug this issue.

@tomlut
Copy link
Author

tomlut commented Jan 15, 2019

I'll give it another go tomorrow and post the full log. Getting late here now.

@tomlut
Copy link
Author

tomlut commented Jan 16, 2019

I tried updating to the following (clean build) OTA:

esphomeyaml:
  name: master_bed
  platform: ESP8266
  board: d1_mini

wifi:
  ssid: 'WAPLO'
  password: !secret wifi_pwd
  manual_ip:
    static_ip: 10.1.1.71
    gateway: 10.1.1.1
    subnet: 255.255.255.0

mqtt:
  discovery: true
  discovery_prefix: homeassistant
  broker: '10.1.1.100'
  username: !secret mqtt_usr
  password: !secret mqtt_pwd

logger:
  # level: WARN

ota:
  password: !secret esp_pwd

binary_sensor:
  - platform: status
    name: "Master Bed Sensor Status"

sensor:
  - platform: wifi_signal
    name: "Master Bed Sensor WiFi Signal"
    update_interval: 15s
    filters:
      - sliding_window_moving_average: {}

  - platform: adc
    pin: A0
    name: "Master Bed Sensor"
    update_interval: 4s
    filters:
      - multiply: 3.25
      - sliding_window_moving_average: {}

I can ping the device but I receive no sensor updates from it via the log or in HA. The device is shown as offline in ESPhome and the status is 'unavailable' in HA. I waited until the log terminated and a further 5 minutes for HA to show any sign of this sensor.

I removed the sliding window filters and tried re-uploading a clean build OTA. The ESP then correctly started logging to ESPhome and sending sensor readings again.

There really does seem to be something amiss with the sliding window average filter.

@tomlut
Copy link
Author

tomlut commented Jan 16, 2019

Update, to simplify things I tried removing the multiplication filter and the sliding average from the wifi sensor leaving just this sensor:

  - platform: adc
    pin: A0
    name: "Master Bed Sensor"
    update_interval: 4s
    filters:
      - sliding_window_moving_average: {}

Same problem. The ESP never publishes any mqtt messages. It can be seen as online by ESPhome and can be pinged and updated OTA. Removing the sliding window filter and re-flashing resumes normal operation.

@tomlut
Copy link
Author

tomlut commented Jan 17, 2019

I tried this using the exponential average instead.

  - platform: adc
    pin: A0
    name: "Master Bed Sensor"
    update_interval: 3s
    filters:
      - multiply: 3.25
      # - sliding_window_moving_average: {}
      - exponential_moving_average:
          alpha: 0.1
          send_every: 15

With this result:

[12:52:16]
[12:52:16] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[12:52:16]
[12:52:16]wdt reset
[12:52:16]load 0x4010f000, len 1384, room 16 
[12:52:16]tail 8
[12:52:16]chksum 0x2d
[12:52:16]csum 0x2d
[12:52:16]vbb28d4a3
[12:52:16]~ld
[12:52:16][E][ota:466]: Boot loop detected. Proceeding to safe mode.
[12:52:23][W][ota:136]: Last Boot was an unhandled reset, will proceed to safe mode in 0 restarts

Show Logs:

INFO Reading configuration...
INFO Starting log output from /dev/ttyUSB0 with baud rate 115200
[12:54:23][E][ota:485]: No OTA attempt made, restarting.
[12:54:23][W][wifi:727]: Event: Disconnected ssid='WAPLO' bssid=FC:EC:DA:38:94:62 reason='Association Leave'
[12:54:23]
[12:54:23] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[12:54:23]
[12:54:23]wdt reset
[12:54:23]load 0x4010f000, len 1384, room 16 
[12:54:23]tail 8
[12:54:23]chksum 0x2d
[12:54:23]csum 0x2d
[12:54:23]vbb28d4a3
[12:54:23]~ld
[12:54:32]
[12:54:32] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[12:54:32]
[12:54:32]wdt reset
[12:54:32]load 0x4010f000, len 1384, room 16 
[12:54:32]tail 8
[12:54:32]chksum 0x2d
[12:54:32]csum 0x2d
[12:54:32]vbb28d4a3
[12:54:32]~ld
[12:54:40]
[12:54:40] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[12:54:40]
[12:54:40]wdt reset
[12:54:40]load 0x4010f000, len 1384, room 16 
[12:54:40]tail 8
[12:54:40]chksum 0x2d
[12:54:40]csum 0x2d
[12:54:40]vbb28d4a3
[12:54:40]~ld
[12:54:49]
[12:54:49] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[12:54:49]
[12:54:49]wdt reset
[12:54:49]load 0x4010f000, len 1384, room 16 
[12:54:49]tail 8
[12:54:49]chksum 0x2d
[12:54:49]csum 0x2d
[12:54:49]vbb28d4a3
[12:54:49]~ld

@tomlut
Copy link
Author

tomlut commented Jan 17, 2019

I just tried a new Wemos D1 Mini board. Same result. Boot loops with sliding_window_moving_average: {}, for the A0 sensor, works fine without the filter.

@tomlut
Copy link
Author

tomlut commented Jan 17, 2019

PROGRESS!

I removed the wifi and status sensors. I could then use the filtered A0 sensor.

Adding either the wifi sensor or status sensor back into the configuration results in failure to connect to wifi and a watchdog time out / restart.

Removing the filter from the A0 sensor allows both the status and wifi sensor to be included.

Data and memory use when compiling does not seem to be the problem (about 50% and 30%).

I really like to be able to monitor the state of my sensors easily and this was working in the previous version (with built-in default filtering of sensors). Any chance you could investigate this Otto?

SUMMARY:
Working configs:

esphomeyaml:
  name: master_bed
  platform: ESP8266
  board: d1_mini

wifi:
  ssid: 'WAPLO'
  password: !secret wifi_pwd
  manual_ip:
    static_ip: 10.1.1.71
    gateway: 10.1.1.1
    subnet: 255.255.255.0

mqtt:
  discovery: true
  discovery_prefix: homeassistant
  broker: '10.1.1.100'
  username: !secret mqtt_usr
  password: !secret mqtt_pwd

logger:
  # level: WARN

ota:
  password: !secret esp_pwd

sensor:
  - platform: adc
    pin: A0
    name: "Master Bed Sensor"
    update_interval: 4s
    filters:
      - multiply: 3.25
      - sliding_window_moving_average:
          window_size: 15
          send_every: 15

OR

esphomeyaml:
  name: master_bed
  platform: ESP8266
  board: d1_mini

wifi:
  ssid: 'WAPLO'
  password: !secret wifi_pwd
  manual_ip:
    static_ip: 10.1.1.71
    gateway: 10.1.1.1
    subnet: 255.255.255.0

mqtt:
  discovery: true
  discovery_prefix: homeassistant
  broker: '10.1.1.100'
  username: !secret mqtt_usr
  password: !secret mqtt_pwd

logger:
  # level: WARN

ota:
  password: !secret esp_pwd

binary_sensor:
  - platform: status
    name: "Master Bed Sensor Status"

sensor:
  - platform: wifi_signal
    name: "Master Bed Sensor WiFi Signal"
    update_interval: 3min
    filters:
      - sliding_window_moving_average:
          window_size: 15
          send_every: 15

  - platform: adc
    pin: A0
    name: "Master Bed Sensor"
    update_interval: 60s

Configs that upload but fail to run:

esphomeyaml:
  name: master_bed
  platform: ESP8266
  board: d1_mini

wifi:
  ssid: 'WAPLO'
  password: !secret wifi_pwd
  manual_ip:
    static_ip: 10.1.1.71
    gateway: 10.1.1.1
    subnet: 255.255.255.0

mqtt:
  discovery: true
  discovery_prefix: homeassistant
  broker: '10.1.1.100'
  username: !secret mqtt_usr
  password: !secret mqtt_pwd

logger:
  # level: WARN

ota:
  password: !secret esp_pwd

sensor:
  - platform: wifi_signal
    name: "Master Bed Sensor WiFi Signal"
    update_interval: 3min
    filters:
      - sliding_window_moving_average:
          window_size: 15
          send_every: 15

  - platform: adc
    pin: A0
    name: "Master Bed Sensor"
    update_interval: 60s
    filters:
      - multiply: 3.25
      - sliding_window_moving_average:
          window_size: 15
          send_every: 15

OR

esphomeyaml:
  name: master_bed
  platform: ESP8266
  board: d1_mini

wifi:
  ssid: 'WAPLO'
  password: !secret wifi_pwd
  manual_ip:
    static_ip: 10.1.1.71
    gateway: 10.1.1.1
    subnet: 255.255.255.0

mqtt:
  discovery: true
  discovery_prefix: homeassistant
  broker: '10.1.1.100'
  username: !secret mqtt_usr
  password: !secret mqtt_pwd

logger:
  # level: WARN

ota:
  password: !secret esp_pwd

binary_sensor:
  - platform: status
    name: "Master Bed Sensor Status"

sensor:

  - platform: adc
    pin: A0
    name: "Master Bed Sensor"
    update_interval: 60s
    filters:
      - multiply: 3.25
      - sliding_window_moving_average:
          window_size: 15
          send_every: 15

@OttoWinter
Copy link
Member

@tomlut Ok so your logs provide some good info. Specifically, rst cause:4 means that there was a hardware WDT reset.

However, what is weird that nothing is displayed on boot. If the code would even reach the point where the moving average or anything else for that matter is initialized, the logs are set up.
And so I would except to see a line like Logs initialized! on each reboot. But that message is not there, so that means there's something fundamentally wrong with the ESP.
Do you have another ESP to check if it's something to do with the ESP?

I also tried your configuration files and was not able to replicate the issue.

@tomlut
Copy link
Author

tomlut commented Jan 18, 2019

Hi Otto, I have 4 new Wemos D1 minis on order. Should be a week or two away.

I did try it with another D1 mini and got similar results, though thinking about it now, failure to connect to wifi might have been a router / assigned static IP issue as I was using this D1 for another sensor previously (so MAC address mismatch in the router). Doing this test also absolutely trashed my HA mqtt integration (duplicate ids / no unique ids from device). Even stopping HA and removing the entries from the .storage files did not help. I ended up having to do a snapshot restore.

Next time I test this I will disable discovery.

Just FYI, I also tried from the command line on Windows with similar results

I’m reasonably sure it is not a faulty device as this was working with the previous version of ESPhome. Though your inability to reproduce the issue is worrying. What hardware device are you using to replicate this?

@OttoWinter
Copy link
Member

It was a wemos d1 mini as well. What's the most weird to me is the missing Logs initialized message, I cannot think of a reason why that would not show up.

@tomlut
Copy link
Author

tomlut commented Jan 18, 2019

Ok if you can use A0 with the filter and other sensors specified in my config on the same hardware then it has to be a problem with my D1 board. I’ve tried reinstalling the addon and using the alternate command line approach on a whole different platform (Windows) so that rules out a problem with my ESPhome installation.

I’ll dig out the other D1 and try again tomorrow - with discovery disabled and a correct static IP assignment.

Thanks for your time.

@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

I deleted all reference to my other (spare-ish) D1 mini from my router and uploaded this config:

esphomeyaml:
  name: test_d1_mini
  platform: ESP8266
  board: d1_mini

wifi:
  ssid: 'WAPLO'
  password: !secret wifi_pwd
  # manual_ip:
    # static_ip: 10.1.1.71
    # gateway: 10.1.1.1
    # subnet: 255.255.255.0

mqtt:
  # discovery: true
  # discovery_prefix: homeassistant
  broker: '10.1.1.100'
  username: !secret mqtt_usr
  password: !secret mqtt_pwd

logger:
  # level: WARN

ota:
  password: !secret esp_pwd

binary_sensor:
  - platform: status
    name: "D1 Test Sensor Status"

sensor:
  - platform: wifi_signal
    name: "D1 Test WiFi Signal"
    update_interval: 15s
    filters:
      - sliding_window_moving_average:
          window_size: 15
          send_every: 15

  - platform: adc
    pin: A0
    name: "D1 A0 Test Sensor"
    update_interval: 4s
    filters:
      - multiply: 3.25
      - sliding_window_moving_average:
          window_size: 15
          send_every: 15

And it works. No issue at all. Looks like my initial D1 mini must have an issue with flash memory at one of the higher addresses - assuming that putting back discovery or a static IP address is not going to reintroduce the fault. But I cant test that until I can remove the existing device integration from HA. EDIT: see next post

I will close this issue now but would appreciate guidance on how best to remove the master_bed sensor from my HA integration. I'll ask over on the HA community forums though, to prevent cluttering up your issues feed.

Link: https://community.home-assistant.io/t/how-to-remove-an-integrated-esp-device/92764

Thanks for your help Otto.

@tomlut tomlut closed this as completed Jan 19, 2019
@tomlut tomlut reopened this Jan 19, 2019
@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

Oh damn. Buoyed by the above success I decided to update anotehr ESP D1 mini. And immediately lost contact with it. The config:

esphomeyaml:
  name: lounge_dht
  platform: ESP8266
  board: d1_mini

wifi:
  ssid: 'WAPLO'
  password: !secret wifi_pwd
  manual_ip:
    static_ip: 10.1.1.75
    gateway: 10.1.1.1
    subnet: 255.255.255.0

mqtt:
  discovery: true
  discovery_prefix: homeassistant
  broker: '10.1.1.100'
  username: !secret mqtt_usr
  password: !secret mqtt_pwd

logger:
  # level: WARN

ota:
  password: !secret esp_pwd

binary_sensor:
  - platform: status
    name: "Lounge Room DHT Status"

sensor:
  - platform: wifi_signal
    name: "Lounge Room DHT WiFi Signal"
    update_interval: 15s
    filters:
      - sliding_window_moving_average:
          window_size: 15
          send_every: 15

  - platform: dht
    pin: D5
    model: DHT22
    update_interval: 15s
    temperature:
      name: "Lounge Room Temperature"
      filters:
        - sliding_window_moving_average:
            window_size: 15
            send_every: 15
    humidity:
      name: "Lounge Room Humidity"
      filters:
        - sliding_window_moving_average:
            window_size: 15
            send_every: 15

The log:

NFO Reading configuration...
INFO Starting log output from /dev/ttyUSB0 with baud rate 115200
[14:49:16][I][ota:154]: Boot seems successful, resetting boot loop counter.
[14:49:24][E][ota:485]: No OTA attempt made, restarting.
[14:49:24][I][helpers:277]: Forcing a reboot... Reason: 'ota-safe-mode'
[14:49:24][W][wifi:727]: Event: Disconnected ssid='WAPLO' bssid=FC:EC:DA:38:94:62 reason='Association Leave'
[14:49:24]
[14:49:24] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[14:49:24]
[14:49:24]wdt reset
[14:49:24]load 0x4010f000, len 1384, room 16 
[14:49:24]tail 8
[14:49:24]chksum 0x2d
[14:49:24]csum 0x2d
[14:49:24]vbb28d4a3
[14:49:24]~ld
[14:49:24][I][logger:071]: Log initialized
[14:49:24][C][ota:461]: There have been 0 suspected unsuccessful boot attempts.
[14:49:24][I][application:053]: Running through setup()...
[14:49:24][D][binary_sensor:027]: 'Lounge Room DHT Status': Sending state OFF
[14:49:24][C][sensor.dht:030]: Setting up DHT...
[14:49:24][C][wifi:029]: Setting up WiFi...
[14:49:24][D][wifi:260]: Starting scan...
[14:49:32]
[14:49:32] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[14:49:32]
[14:49:32]wdt reset
[14:49:32]load 0x4010f000, len 1384, room 16 
[14:49:32]tail 8
[14:49:32]chksum 0x2d
[14:49:32]csum 0x2d
[14:49:32]vbb28d4a3
[14:49:32]~ld
[14:49:32][I][logger:071]: Log initialized
[14:49:32][C][ota:461]: There have been 1 suspected unsuccessful boot attempts.
[14:49:32][I][application:053]: Running through setup()...
[14:49:32][D][binary_sensor:027]: 'Lounge Room DHT Status': Sending state OFF
[14:49:32][C][sensor.dht:030]: Setting up DHT...
[14:49:32][C][wifi:029]: Setting up WiFi...
[14:49:32][D][wifi:260]: Starting scan...
[14:49:41]
[14:49:41] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[14:49:41]
[14:49:41]wdt reset
[14:49:41]load 0x4010f000, len 1384, room 16 
[14:49:41]tail 8
[14:49:41]chksum 0x2d
[14:49:41]csum 0x2d
[14:49:41]vbb28d4a3
[14:49:41]~ld
[14:49:41][I][logger:071]: Log initialized
[14:49:41][C][ota:461]: There have been 2 suspected unsuccessful boot attempts.
[14:49:41][I][application:053]: Running through setup()...
[14:49:41][D][binary_sensor:027]: 'Lounge Room DHT Status': Sending state OFF
[14:49:41][C][sensor.dht:030]: Setting up DHT...
[14:49:41][C][wifi:029]: Setting up WiFi...
[14:49:41][D][wifi:260]: Starting scan...
[14:49:49]
[14:49:49] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[14:49:49]
[14:49:49]wdt reset
[14:49:49]load 0x4010f000, len 1384, room 16 
[14:49:49]tail 8
[14:49:49]chksum 0x2d
[14:49:49]csum 0x2d
[14:49:49]vbb28d4a3
[14:49:49]~ld
[14:49:49][I][logger:071]: Log initialized
[14:49:49][C][ota:461]: There have been 3 suspected unsuccessful boot attempts.
[14:49:49][I][application:053]: Running through setup()...
[14:49:49][D][binary_sensor:027]: 'Lounge Room DHT Status': Sending state OFF
[14:49:49][C][sensor.dht:030]: Setting up DHT...
[14:49:49][C][wifi:029]: Setting up WiFi...
[14:49:49][D][wifi:260]: Starting scan...
[14:49:58]
[14:49:58] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[14:49:58]
[14:49:58]wdt reset
[14:49:58]load 0x4010f000, len 1384, room 16 
[14:49:58]tail 8
[14:49:58]chksum 0x2d
[14:49:58]csum 0x2d
[14:49:58]vbb28d4a3
[14:49:58]~ld
[14:49:58][I][logger:071]: Log initialized
[14:49:58][C][ota:461]: There have been 4 suspected unsuccessful boot attempts.
[14:49:58][I][application:053]: Running through setup()...
[14:49:58][D][binary_sensor:027]: 'Lounge Room DHT Status': Sending state OFF
[14:49:58][C][sensor.dht:030]: Setting up DHT...
[14:49:58][C][wifi:029]: Setting up WiFi...
[14:49:58][D][wifi:260]: Starting scan...
[14:50:06]
[14:50:06] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[14:50:06]

@brandond
Copy link
Collaborator

FYI, you can't change the flash layout via OTA. It just re-uploads the new FW to a flash region just after the current sketch, and then overwrites it as it reboots. If you think that there might be some issue with your flash, you should hook it up to a UART and reflash it from there so that it can actually rewrite the flash map.

I had to do this to get extra space on my ESP8266s with 1M of flash after disabling the SPIFFS reservation. That was fun, especially for the smart bulbs and plugs that I'd glued back together...

@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

I'm currently erasing all trace of this config from the esphome folder and will start again from creating a new device and uploading via serial.

@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

It failed.

I am beginning to suspect it is not a problem with the D1 mini's but a problem associating with wifi. I'm about to run some more tests.

@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

Ok this is very odd. For the lounge room dht sensor D1:

I just deleted the static IP mapping from my router and removed the manual IP from the D1 mini config. No success after a re-upload via serial. It would still not connect to wifi with DHCP and looped.

I removed mqtt discovery from the D1 mini and re-uploaded - it worked.

I put back the manual IP and static mapping in my router - it worked.

I put back mqtt discovery - it failed.

Log for failed attempt:

Leaving...
Hard resetting via RTS pin...
INFO Successfully uploaded program.
INFO Starting log output from /dev/ttyUSB0 with baud rate 115200
[15:23:04]{$l��|�l�<���d��c|������s�c�c��gn�dg'���#�x��lrd;lx�o������l����#'�|�l���#��o'�d��l ���\033gnd`���'{���'�#���l�sۓo�c���l�cbc����d`���o��[I][logger:071]: Log initialized
[15:23:04][C][ota:461]: There have been 0 suspected unsuccessful boot attempts.
[15:23:04][I][application:053]: Running through setup()...
[15:23:04][D][binary_sensor:027]: 'Lounge Room DHT Status': Sending state OFF
[15:23:04][C][sensor.dht:030]: Setting up DHT...
[15:23:04][C][wifi:029]: Setting up WiFi...
[15:23:04][D][wifi:260]: Starting scan...
[15:23:12]
[15:23:12] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[15:23:12]
[15:23:12]wdt reset
[15:23:12]load 0x4010f000, len 1384, room 16 
[15:23:12]tail 8
[15:23:12]chksum 0x2d
[15:23:12]csum 0x2d
[15:23:12]vbb28d4a3
[15:23:12]~ld
[15:23:12][I][logger:071]: Log initialized
[15:23:12][C][ota:461]: There have been 1 suspected unsuccessful boot attempts.
[15:23:12][I][application:053]: Running through setup()...
[15:23:12][D][binary_sensor:027]: 'Lounge Room DHT Status': Sending state OFF
[15:23:12][C][sensor.dht:030]: Setting up DHT...
[15:23:12][C][wifi:029]: Setting up WiFi...
[15:23:12][D][wifi:260]: Starting scan...
[15:23:20]
[15:23:20] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[15:23:20]
[15:23:20]wdt reset
[15:23:20]load 0x4010f000, len 1384, room 16 
[15:23:20]tail 8
[15:23:20]chksum 0x2d
[15:23:20]csum 0x2d
[15:23:20]vbb28d4a3
[15:23:20]~ld
[15:23:20][I][logger:071]: Log initialized
[15:23:20][C][ota:461]: There have been 2 suspected unsuccessful boot attempts.
[15:23:20][I][application:053]: Running through setup()...
[15:23:20][D][binary_sensor:027]: 'Lounge Room DHT Status': Sending state OFF
[15:23:20][C][sensor.dht:030]: Setting up DHT...
[15:23:20][C][wifi:029]: Setting up WiFi...
[15:23:21][D][wifi:260]: Starting scan...

I took the mqtt discovery config out of my original problem child D1 - the master_bed sensor (and left in all the filtering and sensors that were causing trouble originally) - it connected to wifi and it did not boot loop and worked as expected.

I just noticed that the mqtt broker IP address in my configs is in single quotes (the component configuration example does not have these). Removing them did not change the situation.

I do not understand how having HA mqtt discovery on prevents wifi connection / causes watchdog reset if using sliding windowed averaging. This is driving me insane.

@brandond
Copy link
Collaborator

brandond commented Jan 19, 2019

Just out of curiosity, what happens if you set send_first_at: 15 on the sliding_window_moving_average filter?

@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

No change unfortunately. Serial upload of this config:

esphomeyaml:
  name: lounge_dht
  platform: ESP8266
  board: d1_mini

wifi:
  ssid: 'WAPLO'
  password: !secret wifi_pwd
  manual_ip:
    static_ip: 10.1.1.75
    gateway: 10.1.1.1
    subnet: 255.255.255.0

mqtt:
  discovery: true
  discovery_prefix: homeassistant
  broker: 10.1.1.100
  username: !secret mqtt_usr
  password: !secret mqtt_pwd

logger:
  # level: WARN

ota:
  password: !secret esp_pwd

binary_sensor:
  - platform: status
    name: "Lounge Room DHT Status"

sensor:
  - platform: wifi_signal
    name: "Lounge Room DHT WiFi Signal"
    update_interval: 15s
    filters:
      - sliding_window_moving_average:
          window_size: 15
          send_every: 15
          send_first_at: 15

  - platform: dht
    pin: D5
    model: DHT22
    update_interval: 15s
    temperature:
      name: "Lounge Room Temperature"
      filters:
        - sliding_window_moving_average:
            window_size: 15
            send_every: 15
            send_first_at: 15
    humidity:
      name: "Lounge Room Humidity"
      filters:
        - sliding_window_moving_average:
            window_size: 15
            send_every: 15
            send_first_at: 15

Results in:

Leaving...
Hard resetting via RTS pin...
INFO Successfully uploaded program.
INFO Starting log output from /dev/ttyUSB0 with baud rate 115200
[17:19:46]{ld��<�d�|�����l�b<ǃ����s�c�c��'o�l'o����c�p��${l{l8�g������$����c�g�|�$���c��ng�l��$`���\033go$`���n;Ǜ�'�b���l�{��g�c��$�bcb����l`���g��[I][logger:071]: Log initialized
[17:19:46][C][ota:461]: There have been 7 suspected unsuccessful boot attempts.
[17:19:46][I][application:053]: Running through setup()...
[17:19:46][D][binary_sensor:027]: 'Lounge Room DHT Status': Sending state OFF
[17:19:46][C][sensor.dht:030]: Setting up DHT...
[17:19:46][C][wifi:029]: Setting up WiFi...
[17:19:46][D][wifi:260]: Starting scan...
[17:19:54]
[17:19:54] ets Jan  8 2013,rst cause:4, boot mode:(3,6)
[17:19:54]
[17:19:54]wdt reset
[17:19:54]load 0x4010f000, len 1384, room 16 
[17:19:54]tail 8
[17:19:54]chksum 0x2d
[17:19:54]csum 0x2d
[17:19:54]vbb28d4a3
[17:19:54]~ld
[17:19:54][I][logger:071]: Log initialized
[17:19:54][C][ota:461]: There have been 8 suspected unsuccessful boot attempts.
[17:19:54][I][application:053]: Running through setup()...
[17:19:54][D][binary_sensor:027]: 'Lounge Room DHT Status': Sending state OFF
[17:19:54][C][sensor.dht:030]: Setting up DHT...
[17:19:54][C][wifi:029]: Setting up WiFi...
[17:19:54][D][wifi:260]: Starting scan...

Removing the mqtt discovery config results in a correctly operating board:

esphomeyaml:
  name: lounge_dht
  platform: ESP8266
  board: d1_mini

wifi:
  ssid: 'WAPLO'
  password: !secret wifi_pwd
  manual_ip:
    static_ip: 10.1.1.75
    gateway: 10.1.1.1
    subnet: 255.255.255.0

mqtt:
  # discovery: true
  # discovery_prefix: homeassistant
  broker: 10.1.1.100
  username: !secret mqtt_usr
  password: !secret mqtt_pwd

logger:
  # level: WARN

ota:
  password: !secret esp_pwd

binary_sensor:
  - platform: status
    name: "Lounge Room DHT Status"

sensor:
  - platform: wifi_signal
    name: "Lounge Room DHT WiFi Signal"
    update_interval: 15s
    filters:
      - sliding_window_moving_average:
          window_size: 15
          send_every: 15
          send_first_at: 15

  - platform: dht
    pin: D5
    model: DHT22
    update_interval: 15s
    temperature:
      name: "Lounge Room Temperature"
      filters:
        - sliding_window_moving_average:
            window_size: 15
            send_every: 15
            send_first_at: 15
    humidity:
      name: "Lounge Room Humidity"
      filters:
        - sliding_window_moving_average:
            window_size: 15
            send_every: 15
            send_first_at: 15
Leaving...
Hard resetting via RTS pin...
INFO Successfully uploaded program.
INFO Starting log output from /dev/ttyUSB0 with baud rate 115200
[17:24:53]{ld��<�l�|�����l�#|����\033�;�#��#��og�lng����c�p��${l{lp�'������l����#'�|�l����c��og�l��$`��\033�og�l`���gs���o�c��d�;��g�c��$�bcb����l ���o��[I][logger:071]: Log initialized
[17:24:53][C][ota:461]: There have been 0 suspected unsuccessful boot attempts.
[17:24:53][I][application:053]: Running through setup()...
[17:24:53][D][binary_sensor:027]: 'Lounge Room DHT Status': Sending state OFF
[17:24:53][C][sensor.dht:030]: Setting up DHT...
[17:24:53][C][wifi:029]: Setting up WiFi...
[17:24:53][D][wifi:260]: Starting scan...
[17:24:53][D][sensor.dht:066]: Got Temperature=23.9°C Humidity=66.9%
[17:24:59][D][wifi:275]: Found networks:
[17:24:59][I][wifi:308]: - 'WAPLO' (FC:EC:DA:38:94:62) ▂▄▆█
[17:24:59][D][wifi:309]:     Channel: 1
[17:24:59][D][wifi:310]:     RSSI: -25 dB
[17:24:59][D][wifi:312]: - 'Everything' (FE:EC:DA:38:94:62) ▂▄▆█
[17:24:59][D][wifi:312]: - 'Everything' (FE:EC:DA:38:4A:B3) ▂▄▆█
[17:24:59][D][wifi:312]: - 'WAPRU' (FC:EC:DA:38:84:68) ▂▄▆█
[17:24:59][D][wifi:312]: - 'Everything' (FE:EC:DA:38:84:68) ▂▄▆█
[17:24:59][D][wifi:312]: - 'WAPDI' (FC:EC:DA:38:4A:B3) ▂▄▆█
[17:24:59][D][wifi:312]: - 'INGLIS' (D4:6E:0E:6C:02:9B) ▂▄▆█
[17:24:59][I][wifi:179]: WiFi Connecting to 'WAPLO'...
[17:25:00][I][wifi:349]: WiFi connected!
[17:25:00][C][wifi:240]:   SSID: 'WAPLO'
[17:25:00][C][wifi:241]:   IP Address: 10.1.1.75
[17:25:00][C][wifi:243]:   BSSID: FC:EC:DA:38:94:62
[17:25:00][C][wifi:245]:   Hostname: 'lounge_dht'
[17:25:00][C][wifi:250]:   Signal strength: -35 dB ▂▄▆█
[17:25:00][C][wifi:251]:   Channel: 1
[17:25:00][C][wifi:252]:   Subnet: 255.255.255.0
[17:25:00][C][wifi:253]:   Gateway: 10.1.1.1
[17:25:00][C][wifi:254]:   DNS1: 0.0.0.0
[17:25:00][C][wifi:255]:   DNS2: 0.0.0.0
[17:25:00][C][ota:129]: Over-The-Air Updates:
[17:25:00][C][ota:130]:   Address: 10.1.1.75:8266
[17:25:00][C][ota:132]:   Using Password.
[17:25:00][C][mqtt.client:024]: Setting up MQTT...
[17:25:00][I][mqtt.client:170]: Connecting to MQTT...
[17:25:02][I][mqtt.client:209]: MQTT Connected!
[17:25:03][I][application:089]: setup() finished successfully!
[17:25:03][I][application:097]: You're running esphomelib v1.10.1 compiled on Jan 19 2019, 17:24:12
[17:25:03][C][wifi:341]: WiFi:
[17:25:03][C][wifi:240]:   SSID: 'WAPLO'
[17:25:03][C][wifi:241]:   IP Address: 10.1.1.75
[17:25:03][C][wifi:243]:   BSSID: FC:EC:DA:38:94:62
[17:25:03][C][wifi:245]:   Hostname: 'lounge_dht'
[17:25:03][C][wifi:250]:   Signal strength: -37 dB ▂▄▆█
[17:25:03][C][wifi:251]:   Channel: 1
[17:25:03][C][wifi:252]:   Subnet: 255.255.255.0
[17:25:03][C][wifi:253]:   Gateway: 10.1.1.1
[17:25:03][C][wifi:254]:   DNS1: 0.0.0.0
[17:25:03][C][wifi:255]:   DNS2: 0.0.0.0
[17:25:03][C][binary_sensor.status:046]: Status Binary Sensor 'Lounge Room DHT Status'
[17:25:03][C][binary_sensor.status:046]:   Device Class: 'connectivity'
[17:25:03][C][logger:099]: Logger:
[17:25:03][C][logger:100]:   Level: DEBUG
[17:25:03][C][logger:101]:   Log Baud Rate: 115200
[17:25:03][C][sensor.dht:035]: DHT:
[17:25:03][C][sensor.dht:036]:   Pin: GPIO14 (Mode: OUTPUT)
[17:25:03][C][sensor.dht:042]:   Model: DHT22 (or equivalent)
[17:25:03][C][sensor.dht:045]:   Update Interval: 15000 ms
[17:25:03][C][sensor.dht:047]:   Temperature 'Lounge Room Temperature'
[17:25:03][C][sensor.dht:047]:     Unit of Measurement: '°C'
[17:25:03][C][sensor.dht:047]:     Accuracy Decimals: 1
[17:25:03][C][sensor.dht:048]:   Humidity 'Lounge Room Humidity'
[17:25:03][C][sensor.dht:048]:     Unit of Measurement: '%'
[17:25:03][C][sensor.dht:048]:     Accuracy Decimals: 0
[17:25:03][C][sensor.dht:048]:     Icon: 'mdi:water-percent'
[17:25:03][C][sensor.wifi_signal:042]: WiFi Signal 'Lounge Room DHT WiFi Signal'
[17:25:03][C][sensor.wifi_signal:042]:   Unit of Measurement: 'dB'
[17:25:03][C][sensor.wifi_signal:042]:   Accuracy Decimals: 0
[17:25:03][C][sensor.wifi_signal:042]:   Icon: 'mdi:wifi'
[17:25:03][C][ota:129]: Over-The-Air Updates:
[17:25:03][C][ota:130]:   Address: 10.1.1.75:8266
[17:25:03][C][ota:132]:   Using Password.
[17:25:03][C][mqtt.client:058]: MQTT:
[17:25:03][C][mqtt.client:060]:   Server Address: 10.1.1.100:1883 (10.1.1.100)
[17:25:03][C][mqtt.client:061]:   Username: 'mqtt_user'
[17:25:03][C][mqtt.client:062]:   Client ID: 'lounge_dht-84f3eb3b770e'
[17:25:03][C][mqtt.client:064]:   Discovery prefix: 'homeassistant'
[17:25:03][C][mqtt.client:065]:   Discovery retain: YES
[17:25:03][C][mqtt.client:067]:   Topic Prefix: 'lounge_dht'
[17:25:03][C][mqtt.client:069]:   Log Topic: 'lounge_dht/debug'
[17:25:03][C][mqtt.client:072]:   Availability: 'lounge_dht/status'
[17:25:03][C][binary_sensor.mqtt:025]: MQTT Binary Sensor 'Lounge Room DHT Status':
[17:25:03][C][binary_sensor.mqtt:026]:   State Topic: 'lounge_dht/status'
[17:25:03][C][sensor.mqtt:029]: MQTT Sensor 'Lounge Room DHT WiFi Signal':
[17:25:03][C][sensor.mqtt:031]:   Expire After: 1125s
[17:25:03][C][sensor.mqtt:033]:   State Topic: 'lounge_dht/sensor/lounge_room_dht_wifi_signal/state'
[17:25:03][C][sensor.mqtt:029]: MQTT Sensor 'Lounge Room Temperature':
[17:25:03][C][sensor.mqtt:031]:   Expire After: 1125s
[17:25:03][C][sensor.mqtt:033]:   State Topic: 'lounge_dht/sensor/lounge_room_temperature/state'
[17:25:03][C][sensor.mqtt:029]: MQTT Sensor 'Lounge Room Humidity':
[17:25:03][C][sensor.mqtt:031]:   Expire After: 1125s
[17:25:03][C][sensor.mqtt:033]:   State Topic: 'lounge_dht/sensor/lounge_room_humidity/state'
[17:25:03][I][application:114]: Running through first loop()
[17:25:03][D][binary_sensor:027]: 'Lounge Room DHT Status': Sending state ON
[17:25:03][I][application:141]: First loop finished successfully!
[17:25:03][D][sensor.dht:066]: Got Temperature=24.2°C Humidity=51.3%
[17:25:18][D][sensor.dht:066]: Got Temperature=24.2°C Humidity=51.1%
[17:25:33][D][sensor.dht:066]: Got Temperature=24.2°C Humidity=51.1%
[17:25:48][D][sensor.dht:066]: Got Temperature=24.2°C Humidity=51.2%
[17:26:03][D][sensor.dht:066]: Got Temperature=24.2°C Humidity=51.3%
[17:26:18][D][sensor.dht:066]: Got Temperature=24.2°C Humidity=51.3%
[17:26:33][D][sensor.dht:066]: Got Temperature=24.1°C Humidity=51.3%
[17:26:48][D][sensor.dht:066]: Got Temperature=24.1°C Humidity=51.3%
[17:26:53][I][ota:154]: Boot seems successful, resetting boot loop counter.
[17:27:03][D][sensor.dht:066]: Got Temperature=24.1°C Humidity=51.4%
[17:27:18][D][sensor.dht:066]: Got Temperature=24.1°C Humidity=51.4%
[17:27:33][D][sensor.dht:066]: Got Temperature=24.1°C Humidity=51.5%
[17:27:48][D][sensor.dht:066]: Got Temperature=24.1°C Humidity=51.5%
[17:28:03][D][sensor.dht:066]: Got Temperature=24.0°C Humidity=51.4%
[17:28:18][D][sensor.dht:066]: Got Temperature=24.0°C Humidity=51.5%
[17:28:18][D][sensor.sensor:131]: 'Lounge Room Temperature': Sending state 24.11333 °C with 1 decimals of accuracy
[17:28:18][D][sensor.sensor:131]: 'Lounge Room Humidity': Sending state 52.36666 % with 0 decimals of accuracy
[17:28:28][D][sensor.sensor:131]: 'Lounge Room DHT WiFi Signal': Sending state -36.33333 dB with 0 decimals of accuracy

@brandond
Copy link
Collaborator

You see anything interesting if you set the log level to VERY_VERBOSE?

@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

Hang on this is even odder. If I dont define mqtt discovery are the defaults used?

discovery (Optional, boolean): If Home Assistant automatic discovery should be enabled. Defaults to True.

discovery_prefix (Optional, string): The prefix to use for Home Assistant’s MQTT discovery. Should not contain trailing slash. Defaults to homeassistant.

I'll give verbose a go.

@brandond
Copy link
Collaborator

Yeah, you only need to set the broker address (plus creds if required).

@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

So why when I actually define the defaults is it failing?

Unless it's a case sensitive problem?

true =/= True

@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

I don't believe it! That was the problem.

Last version, discovery: true worked. This version it has to be discovery: True

Let me try one more sensor update to be sure before closing.

@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

Nope. It was enabling very_verbose mode that actually fixed the problem. Ugh!

@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

This config, that failed (shown in post above) when using the default logger level:

esphomeyaml:
  name: lounge_dht
  platform: ESP8266
  board: d1_mini

wifi:
  ssid: 'WAPLO'
  password: !secret wifi_pwd
  manual_ip:
    static_ip: 10.1.1.75
    gateway: 10.1.1.1
    subnet: 255.255.255.0

mqtt:
  discovery: true
  discovery_prefix: homeassistant
  broker: 10.1.1.100
  username: !secret mqtt_usr
  password: !secret mqtt_pwd

logger:
#  level: WARN

ota:
  password: !secret esp_pwd

binary_sensor:
  - platform: status
    name: "Lounge Room DHT Status"

sensor:
  - platform: wifi_signal
    name: "Lounge Room DHT WiFi Signal"
    update_interval: 15s
    filters:
      - sliding_window_moving_average:
          window_size: 15
          send_every: 15
          send_first_at: 15

  - platform: dht
    pin: D5
    model: DHT22
    update_interval: 15s
    temperature:
      name: "Lounge Room Temperature"
      filters:
        - sliding_window_moving_average:
            window_size: 15
            send_every: 15
            send_first_at: 15
    humidity:
      name: "Lounge Room Humidity"
      filters:
        - sliding_window_moving_average:
            window_size: 15
            send_every: 15
            send_first_at: 15

Now successfully uploads and runs when the log level is set to very verbose:

Leaving...
Hard resetting via RTS pin...
INFO Successfully uploaded program.
INFO Starting log output from /dev/ttyUSB0 with baud rate 115200
[18:10:06];ld��<�l�|����$��c|����\033�{�c��c��'o�l'o����c�8��ds$s$8�g�����d����c�o�|�l���b��g'�d��l ��\033�o'�l`���gs���g�c��d�;��'�c��$�bc#�܏��$`���g��
[18:10:06]SDK:2.2.1(cfd48f3)/Core:2.4.2/lwIP:2.0.3(STABLE-2_0_3_RELEASE/glue:arduino-2.4.1-13-g163bb82)/BearSSL:6d1cefc
[18:10:06][I][logger:071]: Log initialized
[18:10:06][VV][preferences:034]: LOAD 32: valid=YES, 0=2348514816 1=726413156 (Type=669657188, CRC=726413156)
[18:10:06][C][ota:461]: There have been 0 suspected unsuccessful boot attempts.
[18:10:06][VV][preferences:048]: SAVE 32: 0=2348514817 1=2083253176 (Type=669657188, CRC=2083253176)
[18:10:06][VV][sensor.sensor:085]: Sensor(0x3fff5734)::add_filter(0x3fff5bb4)
[18:10:06][VV][sensor.filter:037]: Filter(0x3fff5bb4)::initialize(parent=0x3fff5734 next=0)
[18:10:06][VV][sensor.sensor:085]: Sensor(0x3fff590c)::add_filter(0x3fff5e1c)
[18:10:06][VV][sensor.filter:037]: Filter(0x3fff5e1c)::initialize(parent=0x3fff590c next=0)
[18:10:06][VV][sensor.sensor:085]: Sensor(0x3fff5974)::add_filter(0x3fff6084)
[18:10:06][VV][sensor.filter:037]: Filter(0x3fff6084)::initialize(parent=0x3fff5974 next=0)
[18:10:06][I][application:053]: Running through setup()...
[18:10:06][V][application:055]: Sorting components by setup priority...
[18:10:06][D][binary_sensor:027]: 'Lounge Room DHT Status': Sending state OFF
[18:10:06][C][sensor.dht:030]: Setting up DHT...
[18:10:06][VV][component:059]: set_interval(name='update', interval=15000, offset=4228)
[18:10:06][C][wifi:029]: Setting up WiFi...
[18:10:06][V][wifi:476]: Disabling AP.
[18:10:06]bcn 0
[18:10:06]del if1
[18:10:06]mode : sta(84:f3:eb:3b:77:0e)
[18:10:06][V][wifi:767]: Event: Changed Mode old=AP+STA new=STA
[18:10:06]wifi evt: 8
[18:10:06]sleep disable
[18:10:06][D][wifi:260]: Starting scan...
[18:10:06][VV][component:134]: Running interval 'update':0 with interval=15000 last_execution=4294948236 (now=210)
[18:10:06][VV][sensor.dht:167]: Data: Hum=0b0000001000000001, Temp=0b0000000011101011, Checksum=0b11101110
[18:10:06][D][sensor.dht:066]: Got Temperature=23.5°C Humidity=51.3%
[18:10:06][V][sensor.sensor:020]: 'Lounge Room Temperature': Received new state 23.500000
[18:10:06][VV][sensor.filter:022]: Filter(0x3fff5e1c)::input(23.500000)
[18:10:06][VV][sensor.filter:071]: SlidingWindowMovingAverageFilter(0x3fff5e1c)::new_value(23.500000) -> 23.500000
[18:10:06][V][sensor.sensor:020]: 'Lounge Room Humidity': Received new state 51.299999
[18:10:06][VV][sensor.filter:022]: Filter(0x3fff6084)::input(51.299999)
[18:10:06][VV][sensor.filter:071]: SlidingWindowMovingAverageFilter(0x3fff6084)::new_value(51.299999) -> 51.299999
[18:10:12]scandone
[18:10:12][D][wifi:275]: Found networks:
[18:10:12][I][wifi:308]: - 'WAPLO' (FC:EC:DA:38:94:62) ▂▄▆█
[18:10:12][D][wifi:309]:     Channel: 1
[18:10:12][D][wifi:310]:     RSSI: -25 dB
[18:10:12][D][wifi:312]: - 'Everything' (FE:EC:DA:38:94:62) ▂▄▆█
[18:10:12][D][wifi:312]: - 'Everything' (FE:EC:DA:38:84:68) ▂▄▆█
[18:10:12][D][wifi:312]: - 'WAPDI' (FC:EC:DA:38:4A:B3) ▂▄▆█
[18:10:12][D][wifi:312]: - 'WAPRU' (FC:EC:DA:38:84:68) ▂▄▆█
[18:10:12][D][wifi:312]: - 'Everything' (FE:EC:DA:38:4A:B3) ▂▄▆█
[18:10:12][D][wifi:312]: - 'INGLIS' (D4:6E:0E:6C:02:9B) ▂▄▆█
[18:10:12][I][wifi:179]: WiFi Connecting to 'WAPLO'...
[18:10:12][V][wifi:733]: Event: Changed AuthMode old=OPEN new=WPA2 PSK
[18:10:12]wifi evt: 2
[18:10:12]scandone
[18:10:13]state: 0 -> 2 (b0)
[18:10:13]state: 2 -> 3 (0)
[18:10:13]state: 3 -> 5 (10)
[18:10:13]add 0
[18:10:13]aid 20
[18:10:13]cnt 
[18:10:13]
[18:10:13]connected with WAPLO, channel 1
[18:10:13]ip:10.1.1.75,mask:255.255.255.0,gw:10.1.1.1
[18:10:13]ip:10.1.1.75,mask:255.255.255.0,gw:10.1.1.1
[18:10:13][V][wifi:718]: Event: Connected ssid='WAPLO' bssid=FC:EC:DA:38:94:62 channel=1
[18:10:13]wifi evt: 0
[18:10:13][V][wifi:739]: Event: Got IP static_ip=10.1.1.75 gateway=10.1.1.1 netmask=255.255.255.0
[18:10:13]wifi evt: 3
[18:10:13][I][wifi:349]: WiFi connected!
[18:10:13][C][wifi:240]:   SSID: 'WAPLO'
[18:10:13][C][wifi:241]:   IP Address: 10.1.1.75
[18:10:13][C][wifi:243]:   BSSID: FC:EC:DA:38:94:62
[18:10:13][C][wifi:245]:   Hostname: 'lounge_dht'
[18:10:13][C][wifi:250]:   Signal strength: -37 dB ▂▄▆█
[18:10:13][C][wifi:251]:   Channel: 1
[18:10:13][C][wifi:252]:   Subnet: 255.255.255.0
[18:10:13][C][wifi:253]:   Gateway: 10.1.1.1
[18:10:13][C][wifi:254]:   DNS1: 0.0.0.0
[18:10:13][C][wifi:255]:   DNS2: 0.0.0.0
[18:10:13][VV][component:059]: set_interval(name='update', interval=15000, offset=2128)
[18:10:13][C][ota:129]: Over-The-Air Updates:
[18:10:13][C][ota:130]:   Address: 10.1.1.75:8266
[18:10:13][C][ota:132]:   Using Password.
[18:10:13][C][mqtt.client:024]: Setting up MQTT...
[18:10:13][I][mqtt.client:170]: Connecting to MQTT...
[18:10:13][VV][component:134]: Running interval 'update':0 with interval=15000 last_execution=4294957750 (now=7615)
[18:10:13][V][sensor.sensor:020]: 'Lounge Room DHT WiFi Signal': Received new state -37.000000
[18:10:13][VV][sensor.filter:022]: Filter(0x3fff5bb4)::input(-37.000000)
[18:10:13][VV][sensor.filter:071]: SlidingWindowMovingAverageFilter(0x3fff5bb4)::new_value(-37.000000) -> -37.000000
[18:10:15][I][mqtt.client:209]: MQTT Connected!
[18:10:16][V][mqtt.client:382]: Publish(topic='lounge_dht/status' payload='online' retain=1)
[18:10:16][V][mqtt.component:066]: 'Lounge Room DHT Status': Sending discovery...
[18:10:16][V][mqtt.client:382]: Publish(topic='homeassistant/binary_sensor/lounge_dht/lounge_room_dht_status/config' payload='{"device_class":"connectivity","payload_on":"online","payload_off":"offline","name":"Lounge Room DHT Status","state_topic":"lounge_dht/status","unique_id":"ESPbinary_sensorlounge_room_dht_status","device":{"identifiers":"84f3eb3b770e","name":"lounge_dht","sw_version":"esphomelib v1.10.1 Jan 19 2019, 18:01:36","model":"PLATFORMIO_D1_MINI","manufacturer":"espressif"}}' retain=1)
[18:10:16][V][mqtt.component:066]: 'Lounge Room DHT WiFi Signal': Sending discovery...
[18:10:16][VV][sensor.filter:043]: Filter(0x3fff5bb4)::calculate_remaining_interval(15000) -> 225000
[18:10:16][VV][sensor.filter:043]: Filter(0x3fff5bb4)::calculate_remaining_interval(15000) -> 225000
[18:10:16][V][mqtt.client:382]: Publish(topic='homeassistant/sensor/lounge_dht/lounge_room_dht_wifi_signal/config' payload='{"unit_of_measurement":"dB","expire_after":1125,"icon":"mdi:wifi","name":"Lounge Room DHT WiFi Signal","state_topic":"lounge_dht/sensor/lounge_room_dht_wifi_signal/state","availability_topic":"lounge_dht/status","unique_id":"84f3eb3b770e-wifisignal","device":{"identifiers":"84f3eb3b770e","name":"lounge_dht","sw_version":"esphomelib v1.10.1 Jan 19 2019, 18:01:36","model":"PLATFORMIO_D1_MI
[18:10:16][V][mqtt.component:066]: 'Lounge Room Temperature': Sending discovery...
[18:10:16][VV][sensor.filter:043]: Filter(0x3fff5e1c)::calculate_remaining_interval(15000) -> 225000
[18:10:16][VV][sensor.filter:043]: Filter(0x3fff5e1c)::calculate_remaining_interval(15000) -> 225000
[18:10:16][V][mqtt.client:382]: Publish(topic='homeassistant/sensor/lounge_dht/lounge_room_temperature/config' payload='{"unit_of_measurement":"°C","expire_after":1125,"name":"Lounge Room Temperature","state_topic":"lounge_dht/sensor/lounge_room_temperature/state","availability_topic":"lounge_dht/status","unique_id":"ESPsensorlounge_room_temperature","device":{"identifiers":"84f3eb3b770e","name":"lounge_dht","sw_version":"esphomelib v1.10.1 Jan 19 2019, 18:01:36","model":"PLATFORMIO_D1_MINI","manufacturer":"
[18:10:16][V][mqtt.component:066]: 'Lounge Room Humidity': Sending discovery...
[18:10:16][VV][sensor.filter:043]: Filter(0x3fff6084)::calculate_remaining_interval(15000) -> 225000
[18:10:16][VV][sensor.filter:043]: Filter(0x3fff6084)::calculate_remaining_interval(15000) -> 225000
[18:10:16][V][mqtt.client:382]: Publish(topic='homeassistant/sensor/lounge_dht/lounge_room_humidity/config' payload='{"unit_of_measurement":"%","expire_after":1125,"icon":"mdi:water-percent","name":"Lounge Room Humidity","state_topic":"lounge_dht/sensor/lounge_room_humidity/state","availability_topic":"lounge_dht/status","unique_id":"ESPsensorlounge_room_humidity","device":{"identifiers":"84f3eb3b770e","name":"lounge_dht","sw_version":"esphomelib v1.10.1 Jan 19 2019, 18:01:36","model":"PLATFORMIO_D1_MINI","ma
[18:10:16][I][application:089]: setup() finished successfully!
[18:10:16][I][application:097]: You're running esphomelib v1.10.1 compiled on Jan 19 2019, 18:01:36
[18:10:16][C][wifi:341]: WiFi:
[18:10:16][C][wifi:240]:   SSID: 'WAPLO'
[18:10:16][C][wifi:241]:   IP Address: 10.1.1.75
[18:10:16][C][wifi:243]:   BSSID: FC:EC:DA:38:94:62
[18:10:16][C][wifi:245]:   Hostname: 'lounge_dht'
[18:10:16][C][wifi:250]:   Signal strength: -37 dB ▂▄▆█
[18:10:16][C][wifi:251]:   Channel: 1
[18:10:16][C][wifi:252]:   Subnet: 255.255.255.0
[18:10:16][C][wifi:253]:   Gateway: 10.1.1.1
[18:10:16][C][wifi:254]:   DNS1: 0.0.0.0
[18:10:16][C][wifi:255]:   DNS2: 0.0.0.0
[18:10:16][C][binary_sensor.status:046]: Status Binary Sensor 'Lounge Room DHT Status'
[18:10:16][C][binary_sensor.status:046]:   Device Class: 'connectivity'
[18:10:16][C][logger:099]: Logger:
[18:10:16][C][logger:100]:   Level: VERY_VERBOSE
[18:10:16][C][logger:101]:   Log Baud Rate: 115200
[18:10:16][C][sensor.dht:035]: DHT:
[18:10:16][C][sensor.dht:036]:   Pin: GPIO14 (Mode: OUTPUT)
[18:10:16][C][sensor.dht:042]:   Model: DHT22 (or equivalent)
[18:10:16][C][sensor.dht:045]:   Update Interval: 15000 ms
[18:10:16][C][sensor.dht:047]:   Temperature 'Lounge Room Temperature'
[18:10:16][C][sensor.dht:047]:     Unit of Measurement: '°C'
[18:10:16][C][sensor.dht:047]:     Accuracy Decimals: 1
[18:10:16][C][sensor.dht:048]:   Humidity 'Lounge Room Humidity'
[18:10:16][C][sensor.dht:048]:     Unit of Measurement: '%'
[18:10:16][C][sensor.dht:048]:     Accuracy Decimals: 0
[18:10:16][C][sensor.dht:048]:     Icon: 'mdi:water-percent'
[18:10:16][C][sensor.wifi_signal:042]: WiFi Signal 'Lounge Room DHT WiFi Signal'
[18:10:16][C][sensor.wifi_signal:042]:   Unit of Measurement: 'dB'
[18:10:16][C][sensor.wifi_signal:042]:   Accuracy Decimals: 0
[18:10:16][C][sensor.wifi_signal:042]:   Icon: 'mdi:wifi'
[18:10:16][V][sensor.wifi_signal:042]:   Unique ID: '84f3eb3b770e-wifisignal'
[18:10:16][C][ota:129]: Over-The-Air Updates:
[18:10:16][C][ota:130]:   Address: 10.1.1.75:8266
[18:10:16][C][ota:132]:   Using Password.
[18:10:16][C][mqtt.client:058]: MQTT:
[18:10:16][C][mqtt.client:060]:   Server Address: 10.1.1.100:1883 (10.1.1.100)
[18:10:16][C][mqtt.client:061]:   Username: 'mqtt_user'
[18:10:16][C][mqtt.client:062]:   Client ID: 'lounge_dht-84f3eb3b770e'
[18:10:16][C][mqtt.client:064]:   Discovery prefix: 'homeassistant'
[18:10:16][C][mqtt.client:065]:   Discovery retain: YES
[18:10:16][C][mqtt.client:067]:   Topic Prefix: 'lounge_dht'
[18:10:16][C][mqtt.client:069]:   Log Topic: 'lounge_dht/debug'
[18:10:16][C][mqtt.client:072]:   Availability: 'lounge_dht/status'
[18:10:16][C][binary_sensor.mqtt:025]: MQTT Binary Sensor 'Lounge Room DHT Status':
[18:10:16][C][binary_sensor.mqtt:026]:   State Topic: 'lounge_dht/status'
[18:10:16][C][sensor.mqtt:029]: MQTT Sensor 'Lounge Room DHT WiFi Signal':
[18:10:16][VV][sensor.filter:043]: Filter(0x3fff5bb4)::calculate_remaining_interval(15000) -> 225000
[18:10:16][VV][sensor.filter:043]: Filter(0x3fff5bb4)::calculate_remaining_interval(15000) -> 225000
[18:10:16][C][sensor.mqtt:031]:   Expire After: 1125s
[18:10:16][C][sensor.mqtt:033]:   State Topic: 'lounge_dht/sensor/lounge_room_dht_wifi_signal/state'
[18:10:16][C][sensor.mqtt:029]: MQTT Sensor 'Lounge Room Temperature':
[18:10:16][VV][sensor.filter:043]: Filter(0x3fff5e1c)::calculate_remaining_interval(15000) -> 225000
[18:10:16][VV][sensor.filter:043]: Filter(0x3fff5e1c)::calculate_remaining_interval(15000) -> 225000
[18:10:16][C][sensor.mqtt:031]:   Expire After: 1125s
[18:10:16][C][sensor.mqtt:033]:   State Topic: 'lounge_dht/sensor/lounge_room_temperature/state'
[18:10:16][C][sensor.mqtt:029]: MQTT Sensor 'Lounge Room Humidity':
[18:10:16][VV][sensor.filter:043]: Filter(0x3fff6084)::calculate_remaining_interval(15000) -> 225000
[18:10:16][VV][sensor.filter:043]: Filter(0x3fff6084)::calculate_remaining_interval(15000) -> 225000
[18:10:16][C][sensor.mqtt:031]:   Expire After: 1125s
[18:10:16][C][sensor.mqtt:033]:   State Topic: 'lounge_dht/sensor/lounge_room_humidity/state'
[18:10:16][I][application:114]: Running through first loop()
[18:10:16][D][binary_sensor:027]: 'Lounge Room DHT Status': Sending state ON
[18:10:16][I][application:141]: First loop finished successfully!
[18:10:16][VV][component:134]: Running interval 'update':0 with interval=15000 last_execution=4294963236 (now=10950)
[18:10:16][VV][sensor.dht:167]: Data: Hum=0b0000001000000000, Temp=0b0000000011101011, Checksum=0b11101101
[18:10:16][D][sensor.dht:066]: Got Temperature=23.5°C Humidity=51.2%
[18:10:16][V][sensor.sensor:020]: 'Lounge Room Temperature': Received new state 23.500000
[18:10:17][VV][sensor.filter:022]: Filter(0x3fff5e1c)::input(23.500000)
[18:10:17][VV][sensor.filter:071]: SlidingWindowMovingAverageFilter(0x3fff5e1c)::new_value(23.500000) -> 23.500000
[18:10:17][V][sensor.sensor:020]: 'Lounge Room Humidity': Received new state 51.200001
[18:10:17][VV][sensor.filter:022]: Filter(0x3fff6084)::input(51.200001)
[18:10:17][VV][sensor.filter:071]: SlidingWindowMovingAverageFilter(0x3fff6084)::new_value(51.200001) -> 51.250000
[18:10:23]pm open,type:0 0
[18:10:26][VV][component:134]: Running interval 'update':0 with interval=15000 last_execution=5454 (now=20469)
[18:10:26][V][sensor.sensor:020]: 'Lounge Room DHT WiFi Signal': Received new state -36.000000
[18:10:26][VV][sensor.filter:022]: Filter(0x3fff5bb4)::input(-36.000000)
[18:10:26][VV][sensor.filter:071]: SlidingWindowMovingAverageFilter(0x3fff5bb4)::new_value(-36.000000) -> -36.500000
[18:10:31][VV][component:134]: Running interval 'update':0 with interval=15000 last_execution=10940 (now=25946)
[18:10:31][VV][sensor.dht:167]: Data: Hum=0b0000001000000000, Temp=0b0000000011101011, Checksum=0b11101101
[18:10:31][D][sensor.dht:066]: Got Temperature=23.5°C Humidity=51.2%
[18:10:31][V][sensor.sensor:020]: 'Lounge Room Temperature': Received new state 23.500000
[18:10:31][VV][sensor.filter:022]: Filter(0x3fff5e1c)::input(23.500000)
[18:10:32][VV][sensor.filter:071]: SlidingWindowMovingAverageFilter(0x3fff5e1c)::new_value(23.500000) -> 23.500000
[18:10:32][V][sensor.sensor:020]: 'Lounge Room Humidity': Received new state 51.200001
[18:10:32][VV][sensor.filter:022]: Filter(0x3fff6084)::input(51.200001)
[18:10:32][VV][sensor.filter:071]: SlidingWindowMovingAverageFilter(0x3fff6084)::new_value(51.200001) -> 51.233334
[18:10:41][VV][component:134]: Running interval 'update':0 with interval=15000 last_execution=20454 (now=35460)
[18:10:41][V][sensor.sensor:020]: 'Lounge Room DHT WiFi Signal': Received new state -34.000000
[18:10:41][VV][sensor.filter:022]: Filter(0x3fff5bb4)::input(-34.000000)
[18:10:41][VV][sensor.filter:071]: SlidingWindowMovingAverageFilter(0x3fff5bb4)::new_value(-34.000000) -> -35.666668
[18:10:46][VV][component:134]: Running interval 'update':0 with interval=15000 last_execution=25940 (now=40956)
[18:10:46][VV][sensor.dht:167]: Data: Hum=0b0000001000000000, Temp=0b0000000011101011, Checksum=0b11101101
[18:10:47][D][sensor.dht:066]: Got Temperature=23.5°C Humidity=51.2%
[18:10:47][V][sensor.sensor:020]: 'Lounge Room Temperature': Received new state 23.500000
[18:10:47][VV][sensor.filter:022]: Filter(0x3fff5e1c)::input(23.500000)
[18:10:47][VV][sensor.filter:071]: SlidingWindowMovingAverageFilter(0x3fff5e1c)::new_value(23.500000) -> 23.500000
[18:10:47][V][sensor.sensor:020]: 'Lounge Room Humidity': Received new state 51.200001
[18:10:47][VV][sensor.filter:022]: Filter(0x3fff6084)::input(51.200001)
[18:10:47][VV][sensor.filter:071]: SlidingWindowMovingAverageFilter(0x3fff6084)::new_value(51.200001) -> 51.224998

I have no idea what is going on. I don't think it has anything to do with discovery or filtering. At a guess the framework for wifi on this new build could have some sort of race condition problem. But really I have no idea.

@brandond
Copy link
Collaborator

Honestly, I'm kinda surprised that it's trying to read the DHT at the same time wifi setup is going on. Seems to me like that component shouldn't start sampling until later. Sure seems like you're running into some weird race condition with the wifi scan + sensor poll going on at the same time. Maybe @OttoWinter will have some new idea with the additional information you've collected.

Just out of curiosity, does putting the DHT on a different pin change anything? I know on the ESP32s at least, some pins are shared with internal components. Not sure if that's a possibility for ESP8266s or not.

@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

If I'm being honest, at the moment it's too much hassle to change the DHT input and the fact that there was a problem with the A0 input on the other device tends to make me believe this is not the issue.

Also the fact that changing seemingly unrelated components (even just defining default options) and even altering the log level changes the fault to me says that there is a much deeper issue and changing the input could send me up another false path.

@brandond
Copy link
Collaborator

Oh right, this is ADC. There are a BUNCH of issues with reading the ADC while wifi is active.

One of those issues links to this page which says:

If sampling is done too often, then Wi-Fi connection is lost. This happens because we are competing for access to internal ADC with ESP's routines responsible for Wi-Fi management. The same ADC is used by ESP to calibrate Wi-Fi modem. Espressif ESP8266 FAQs document dated on 2016.08, provides us with related recommendations on ADC usage. On page 18/32 it specifies that with "Wi-Fi modem normally active" you may sample ADC at 1k samples/sec.

I am guessing that the ADC is used even more extensively during initial wifi setup and scanning. This suggests that setting fast_connect: true in the YAML wifi settings might improve the issue but honestly, it sounds like the ADC shouldn't be used at when wifi is particularly active; even if we are sampling at far less than 1khz there's still likely to be a lot of noise in the reading.

@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

Is an ADC call every 4 seconds too often though? The WDT seems to trip after about 8 seconds in the logs above.

Or more importantly, why does leaving the default mqtt discovery parameters alone alleviate the problem (with the same 4 sec sample frequency)?

Or setting the logging level == very_verbose? If anything this should make things worse.

I've kind of found a work around - don't define default mqtt discovery parameters - that seems to be working across every device I try it on. I've tried other boards that have I2C sensors rather than A0 or DHT22 sensors. All work as long as I just let the mqtt discovery defaults define themselves.

@OttoWinter
Copy link
Member

I agree this is a very deep issue. Most likely though it is in the closed source ESP SDK or even the silicon itself.

But even if there are the ADC issues you linked to:

a) they would only explain why it cannot connect, I don't think this could directly trigger the WDT
b) In the logs you gave us @tomlut, the last message is Starting scan.. - and the update interval doesn't seem to match the WDT reset. So no adc measurement is taking place during the error.
c) In this comment the error is appearing without the ADC, that is also unexpected.

And then comes the part that I cannot replicate this. I tried all of the configs above with a bunch of my own devices (nodemcu, wemos d1, sonoff, direct ESP8266 chip, etc) and could not replicate the behavior. Something truly weird is going on here :/ And I don't know how to find out what it really is.

@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

c) In this comment the error is appearing without the ADC, that is also unexpected.

That's because that particular device does not have an ADC sensor (unless the ADC is being used internally to measure the RSSI?).

And then comes the part that I cannot replicate this. I tried all of the configs above with a bunch of my own devices (nodemcu, wemos d1, sonoff, direct ESP8266 chip, etc) and could not replicate the behavior.

Did you include these config lines:

mqtt:
  discovery: true
  discovery_prefix: homeassistant

It's the common factor across all my D1 minis. Including these (superfluous) config parameters causes the boot looping for me (unless logging level is set to very verbose, then the config is not an issue). It does not matter what sensors I'm using, ADC, I2C, DTH, these lines seem to be the common factor in runtime failure.

Either way, thank you for taking the time to try to replicate the issue.

I may try setting discovery false when I get my next batch of D1 minis just see what happens. I learned today the perrils of using already discovered devices for testing. It was quite a chore to delete the duplicates from my HA integrations.

I'll close this for now as there is nothing concrete we can do, no rhyme or reason as to why it is happening and I have a workaround (dont include unneeded default discovery parameters).

Might be wise to keep it in mind for any future issues that are reported though.

@tomlut tomlut closed this as completed Jan 19, 2019
@tomlut
Copy link
Author

tomlut commented Jan 19, 2019

Also just FYI. I purchased all the Wemos D1 minis from the official Aliexpress store. These are not knock-off imitations.

@esphome esphome locked and limited conversation to collaborators Jun 24, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants