search

esphome / issues

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

Dallas sensor not found (but it is) since 1.14.x #835

Closed hgregorian closed 3 years ago

hgregorian commented 4 years ago

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

Hass.io

ESP (ESP32/ESP8266, Board/Sonoff):

ESP8266, d1_mini

Affected component:

https://esphome.io/components/sensor/dallas.html

Description of problem: Since upgrading to 1.14.x, intermittently on boot, 'dallas' reports "Found no sensors!". Regardless of this message, the status LED of the ESP unit blinks quickly indicating a problem. When just the 'dallas' component is present, but no sensor config, the fast blinking LED ceases, as does the intermittent warning on boot.

Problem-relevant YAML-configuration entries:

globals:
  - id: throttle_current
    type: int
    restore_value: no
    initial_value: '0'

substitutions:
  devicename: esp_train_controller
  upper_devicename: Train Controller
  status_led_pin: D4

esphome:
  name: $devicename
  comment: "LGB Train Controller"
  platform: ESP8266
  board: d1_mini
  esp8266_restore_from_flash: false
  on_boot:
    then:
      - lambda: 'id(throttle_current) = 0;'
      - wait_until: mqtt.connected
      - mqtt.publish:
          topic: train/throttle/target
          payload: 0
      - mqtt.publish_json:
          topic: train/throttle/current
          payload: |-
            root["level"] = 0;

<<: !include common/common.yaml
<<: !include common/binary_sensors.yaml
# <<: !include common/logger.yaml
<<: !include common/mqtt.yaml

logger:
  level: VERBOSE

dallas:
  - pin: D5
    # update_interval: 60s

sensor:
  - !include common/sensor/uptime.yaml
  - !include common/sensor/wifi_signal.yaml
  - platform: dallas
    id: temperature
    address: 0x1301187A6AAEFF28
    name: "$upper_devicename Temperature"
    filters:
      - lambda: return x * (9.0/5.0) + 32.0;
    unit_of_measurement: "°F"

Logs (if applicable):

(I've omitted MQTT messages for the sake of brevity)

[13:17:10][I][app:100]: ESPHome version 1.14.2 compiled on Nov  9 2019, 13:14:37
[13:17:10][C][status_led:019]: Status LED:
[13:17:10][C][status_led:020]:   Pin: GPIO2 (Mode: OUTPUT, INVERTED)
[13:17:10][C][wifi:409]: WiFi:
[13:17:10][C][wifi:277]:   SSID: [redacted]
[13:17:10][C][wifi:278]:   IP Address: 172.16.10.25
[13:17:10][C][wifi:280]:   BSSID: [redacted]
[13:17:10][C][wifi:281]:   Hostname: 'esp_train_controller'
[13:17:10][C][wifi:285]:   Signal strength: -60 dB ▂▄▆█
[13:17:10][V][wifi:287]:   Priority: 0.0
[13:17:10][C][wifi:289]:   Channel: 6
[13:17:10][C][wifi:290]:   Subnet: 255.255.255.0
[13:17:10][C][wifi:291]:   Gateway: 172.16.10.1
[13:17:10][C][wifi:292]:   DNS1: 192.168.1.100
[13:17:10][C][wifi:293]:   DNS2: 192.168.1.1
[13:17:10][C][uptime.sensor:030]: Uptime Sensor 'esp_train_controller Uptime'
[13:17:11][C][uptime.sensor:030]:   Unit of Measurement: 's'
[13:17:11][C][uptime.sensor:030]:   Accuracy Decimals: 0
[13:17:11][C][uptime.sensor:030]:   Icon: 'mdi:timer'
[13:17:11][V][uptime.sensor:030]:   Unique ID: '84f3ebdcdd60-uptime'
[13:17:11][C][esp8266_pwm:022]: ESP8266 PWM:
[13:17:11][C][esp8266_pwm:023]:   Pin: GPIO4 (Mode: OUTPUT)
[13:17:11][C][esp8266_pwm:024]:   Frequency: 14000.0 Hz
[13:17:11][C][esp8266_pwm:025]:   Max Power: 97.0%
[13:17:11][C][esp8266_pwm:025]:   Min Power: 5.0%
[13:17:11][C][esp8266_pwm:022]: ESP8266 PWM:
[13:17:11][C][esp8266_pwm:023]:   Pin: GPIO5 (Mode: OUTPUT)
[13:17:11][C][esp8266_pwm:024]:   Frequency: 14000.0 Hz
[13:17:11][C][esp8266_pwm:025]:   Max Power: 97.0%
[13:17:11][C][esp8266_pwm:025]:   Min Power: 5.0%
[13:17:11][C][template.switch:058]: Template Switch 'Train Controller - Full Speed 60'
[13:17:11][C][template.switch:059]:   Restore State: NO
[13:17:11][C][template.switch:060]:   Optimistic: NO
[13:17:11][C][template.switch:058]: Template Switch 'Train Controller - Clockwise'
[13:17:11][C][template.switch:059]:   Restore State: NO
[13:17:11][C][template.switch:060]:   Optimistic: NO
[13:17:11][C][template.switch:058]: Template Switch 'Train Controller - Frequency Test'
[13:17:11][C][template.switch:059]:   Restore State: NO
[13:17:11][C][template.switch:060]:   Optimistic: NO
[13:17:11][C][template.switch:058]: Template Switch 'Train Controller - Counter Clockwise'
[13:17:11][C][template.switch:059]:   Restore State: NO
[13:17:11][C][template.switch:060]:   Optimistic: NO
[13:17:12][C][logger:175]: Logger:
[13:17:12][C][logger:176]:   Level: VERBOSE
[13:17:12][C][logger:177]:   Log Baud Rate: 115200
[13:17:12][C][logger:178]:   Hardware UART: UART0
[13:17:12][C][status:034]: Status Binary Sensor 'esp_train_controller Status'
[13:17:12][C][status:034]:   Device Class: 'connectivity'
[13:17:12][C][restart:021]: Restart Switch 'esp_train_controller restart'
[13:17:12][C][restart:021]:   Icon: 'mdi:restart'
[13:17:12][C][dallas.sensor:070]: DallasComponent:
[13:17:12][C][dallas.sensor:071]:   Pin: GPIO14 (Mode: INPUT)
[13:17:12][C][dallas.sensor:072]:   Update Interval: 60.0s
[13:17:12][W][dallas.sensor:075]:   Found no sensors!
[13:17:12][C][dallas.sensor:085]:   Device 'Train Controller Temperature'
[13:17:12][C][dallas.sensor:085]:     Unit of Measurement: '°F'
[13:17:12][C][dallas.sensor:085]:     Accuracy Decimals: 1
[13:17:13][C][dallas.sensor:085]:     Icon: 'mdi:thermometer'
[13:17:13][V][dallas.sensor:085]:     Unique ID: 'dallas-1301187A6AAEFF28'
[13:17:13][C][dallas.sensor:093]:     Address: 0x1301187A6AAEFF28
[13:17:13][C][dallas.sensor:094]:     Resolution: 12
[13:17:13][C][version.text_sensor:015]: Version Text Sensor 'esp_train_controller ESPHome Version'
[13:17:13][C][version.text_sensor:015]:   Icon: 'mdi:new-box'
[13:17:13][V][version.text_sensor:015]:   Unique ID: '84f3ebdcdd60-version'
[13:17:13][C][captive_portal:169]: Captive Portal:
[13:17:13][C][ota:029]: Over-The-Air Updates:
[13:17:13][C][ota:030]:   Address: esp_train_controller.local:8266
[13:17:13][C][api:095]: API Server:
[13:17:13][C][api:096]:   Address: esp_train_controller.local:6053
[13:17:13][C][wifi_info:009]: WifiInfo IPAddress 'esp_train_controller IP Address'
[13:17:13][V][wifi_info:009]:   Unique ID: '84f3ebdcdd60-wifiinfo-ip'
[13:17:13][C][wifi_signal.sensor:009]: WiFi Signal 'esp_train_controller WiFi Signal'
[13:17:13][C][wifi_signal.sensor:009]:   Unit of Measurement: 'dB'
[13:17:13][C][wifi_signal.sensor:009]:   Accuracy Decimals: 0
[13:17:13][C][wifi_signal.sensor:009]:   Icon: 'mdi:wifi'
[13:17:13][V][wifi_signal.sensor:009]:   Unique ID: '84f3ebdcdd60-wifisignal'
[13:17:13][C][wifi_info:010]: WifiInfo SSID 'esp_train_controller SSID'
[13:17:13][V][wifi_info:010]:   Unique ID: '84f3ebdcdd60-wifiinfo-ssid'
[13:17:13][C][wifi_info:011]: WifiInfo BSSID 'esp_train_controller BSSID'
[13:17:14][V][wifi_info:011]:   Unique ID: '84f3ebdcdd60-wifiinfo-bssid'
[13:17:43][V][sensor:013]: 'esp_train_controller Uptime': Received new state 55.702999
[13:17:43][D][sensor:092]: 'esp_train_controller Uptime': Sending state 55.70300 s with 0 decimals of accuracy
[13:17:48][D][dallas.sensor:148]: 'Train Controller Temperature': Got Temperature=35.4°C
[13:17:49][V][sensor:013]: 'Train Controller Temperature': Received new state 35.437500
[13:17:49][D][sensor:092]: 'Train Controller Temperature': Sending state 95.78750 °F with 1 decimals of accuracy
[13:18:43][V][sensor:013]: 'esp_train_controller Uptime': Received new state 115.704002
[13:18:43][D][sensor:092]: 'esp_train_controller Uptime': Sending state 115.70400 s with 0 decimals of accuracy

Additional information and things you've tried:

Removal of the 'dallas' sensor causes the warning to go away and the status LED to indicate normal function (off in this case). It should be noted that despite the log warning and fast blinking LED, temperature is in fact reported as expected and does not appear to be functioning any differently than it did in 1.13.x.

OttoWinter commented 4 years ago

There have been no changes to dallas integration since 1.13.x (and as far as I see even going back to 1.9.x)

You can try using the old arduino core version (maybe the ESP SDK has changed some internals), but I doubt that changes anything: arduino_version: 2.4.2

Regardless of this message, the status LED of the ESP unit blinks quickly indicating a problem.

Yes, status led is in error mode when a dallas sensor could not be found. That is correct.

It should be noted that despite the log warning and fast blinking LED, temperature is in fact reported as expected and does not appear to be functioning any differently than it did in 1.13.x.

That is correct - if you have specified the address of the device, the initial setup finding process is not needed and just a check to see if the sensor is there. This further indicates it's probably a problem with flaky wiring or some deeper reason with the ESP hardware.

hgregorian commented 4 years ago

Alright, thanks for your attention and confirming my assumptions.

Just for due diligence purposes (wiring/hardware issues that you eluded to), I did try another d1 mini unit in my setup (protoboard with dallas sensor and resistor soldered) and encountered the same issue. Then I used the original d1 mini in a new breadboard setup (same config); issue persisted. Repeated the process with another d1 mini (same config again); issue persisted.

I began to pair down the original config in an effort to pin down what could be causing the issue. I do have a number of sensors included as "common" configuration and by commenting any one of them out, the 'dallas' component no longer reports "Found no sensors!".

This is very confusing and doesn't make for a concise way to pinpoint a problem, but appears to be related to cumulative configuration.

I'm looking for guidance on what additional information I can provide.

UPDATE: I completely neglected to try arduino_version: 2.4.2 as initially suggested (I think because I wanted to discount wiring/hardware issues 😄 ) and this did in fact resolve the issue.

OttoWinter commented 4 years ago

A related issue has since come up that may explain it. And would explain why the SDK change would fix it.

Please see https://github.com/esphome/issues/issues/455#issuecomment-552976310 and try the fix there.

hgregorian commented 4 years ago

Bumped hassio esphome addon config to "dev" and restarted addon. Made changes as suggested (and removed arduino_version):

Relevant config (from validate)

substitutions:
  devicename: esp_train_controller
  upper_devicename: Train Controller
  status_led_pin: D4
esphome:
  name: esp_train_controller
  comment: LGB Train Controller
  platform: ESP8266
  board: d1_mini
  esp8266_restore_from_flash: false
  on_boot:
  - then:
    - lambda: !lambda |-
        id(throttle_current) = 0;
    - wait_until:
        condition:
          mqtt.connected: {}
    - mqtt.publish:
        topic: train/throttle/target
        payload: '0'
        retain: false
        qos: 0
    - mqtt.publish_json:
        topic: train/throttle/current
        payload: !lambda |-
          root["level"] = 0;
        retain: false
        qos: 0
    priority: 600.0
  includes: []
  arduino_version: espressif8266@2.2.3
  build_path: esp_train_controller
  libraries: []
  platformio_options: {}
  board_flash_mode: dout
globals:
- id: throttle_current
  type: int
  restore_value: false
  initial_value: '0'
wifi:
  output_power: 17.0
  ap:
    ssid: esp_train_controller
    password: !secret 'ap_wifi_password'
    ap_timeout: 1min
  reboot_timeout: 15min
  domain: .local
  power_save_mode: NONE
  fast_connect: false
  networks:
  - ssid: !secret 'wifi_ssid'
    password: !secret 'wifi_password'
    priority: 0.0
  use_address: esp_train_controller.local
captive_portal: {}
api:
  reboot_timeout: 15min
  password: ''
  port: 6053
ota:
  safe_mode: true
  password: ''
  port: 8266
status_led:
  pin:
    number: 2
    inverted: true
    mode: OUTPUT

Initial log output after flash

======================== [SUCCESS] Took 206.45 seconds ========================
INFO Successfully compiled program.
INFO Resolving IP address of esp_train_controller.local
INFO  -> 172.16.10.25
INFO Uploading /data/esp_train_controller/.pioenvs/esp_train_controller/firmware.bin (482304 bytes)
Uploading: [============================================================] 100% Done...

INFO Waiting for result...
INFO OTA successful
INFO Successfully uploaded program.
INFO Starting log output from esp_train_controller.local using esphome API
INFO Connecting to esp_train_controller.local:6053 (172.16.10.25)
WARNING Initial connection failed. The ESP might not be connected to WiFi yet (Error connecting to 172.16.10.25: [Errno 113] No route to host). Re-Trying in 1 seconds
INFO Connecting to esp_train_controller.local:6053 (172.16.10.25)
INFO Successfully connected to esp_train_controller.local
[07:51:49][I][mqtt:202]: MQTT Connected!
[07:51:50][I][app:058]: setup() finished successfully!
[07:51:50][D][sensor:092]: 'esp_train_controller WiFi Signal': Sending state -60.00000 dB with 0 decimals of accuracy
[07:51:50][D][binary_sensor:036]: 'esp_train_controller Status': Sending state ON
[07:51:50][D][text_sensor:015]: 'esp_train_controller IP Address': Sending state '172.16.10.25'
[07:51:50][D][text_sensor:015]: 'esp_train_controller SSID': Sending state 'IoT'
[07:51:50][D][text_sensor:015]: 'esp_train_controller BSSID': Sending state '66:D9:E7:F3:08:C6'
[07:51:50][I][app:100]: ESPHome version 1.15.0-dev compiled on Nov 14 2019, 07:48:57
[07:51:50][C][status_led:019]: Status LED:
[07:51:50][C][status_led:020]:   Pin: GPIO2 (Mode: OUTPUT, INVERTED)
[07:51:50][D][api:067]: Disconnecting Home Assistant 0.101.3 (192.168.1.55)
[07:51:50][C][wifi:415]: WiFi:
[07:51:50][C][wifi:283]:   SSID: [redacted]
[07:51:50][C][wifi:284]:   IP Address: 172.16.10.25
[07:51:50][C][wifi:286]:   BSSID: [redacted]
[07:51:50][C][wifi:287]:   Hostname: 'esp_train_controller'
[07:51:50][C][wifi:291]:   Signal strength: -60 dB ▂▄▆█
[07:51:50][C][wifi:295]:   Channel: 6
[07:51:50][C][wifi:296]:   Subnet: 255.255.255.0
[07:51:50][C][wifi:297]:   Gateway: 172.16.10.1
[07:51:50][C][wifi:298]:   DNS1: 192.168.1.100
[07:51:50][C][wifi:299]:   DNS2: 192.168.1.1
[07:51:50][D][sensor:092]: 'throttle_target': Sending state 0.00000  with 1 decimals of accuracy
[07:51:50][C][uptime.sensor:030]: Uptime Sensor 'esp_train_controller Uptime'
[07:51:50][C][uptime.sensor:030]:   Unit of Measurement: 's'
[07:51:50][C][uptime.sensor:030]:   Accuracy Decimals: 0
[07:51:50][C][uptime.sensor:030]:   Icon: 'mdi:timer'
[07:51:50][C][esp8266_pwm:022]: ESP8266 PWM:
[07:51:50][C][esp8266_pwm:023]:   Pin: GPIO4 (Mode: OUTPUT)
[07:51:50][C][esp8266_pwm:024]:   Frequency: 14000.0 Hz
[07:51:50][C][esp8266_pwm:025]:   Max Power: 97.0%
[07:51:50][C][esp8266_pwm:025]:   Min Power: 5.0%
[07:51:50][C][esp8266_pwm:022]: ESP8266 PWM:
[07:51:50][C][esp8266_pwm:023]:   Pin: GPIO5 (Mode: OUTPUT)
[07:51:50][C][esp8266_pwm:024]:   Frequency: 14000.0 Hz
[07:51:50][C][esp8266_pwm:025]:   Max Power: 97.0%
[07:51:50][C][esp8266_pwm:025]:   Min Power: 5.0%
[07:51:50][D][sensor:092]: 'throttle_target': Sending state 0.00000  with 1 decimals of accuracy
[07:51:50][C][template.switch:058]: Template Switch 'Train Controller - Full Speed 60'
[07:51:50][C][template.switch:059]:   Restore State: NO
[07:51:50][C][template.switch:060]:   Optimistic: NO
[07:51:50][C][template.switch:058]: Template Switch 'Train Controller - Clockwise'
[07:51:50][C][template.switch:059]:   Restore State: NO
[07:51:50][C][template.switch:060]:   Optimistic: NO
[07:51:50][C][template.switch:058]: Template Switch 'Train Controller - Frequency Test'
[07:51:50][C][template.switch:059]:   Restore State: NO
[07:51:50][C][template.switch:060]:   Optimistic: NO
[07:51:50][C][template.switch:058]: Template Switch 'Train Controller - Counter Clockwise'
[07:51:50][C][template.switch:059]:   Restore State: NO
[07:51:50][C][template.switch:060]:   Optimistic: NO
[07:51:51][C][logger:175]: Logger:
[07:51:51][C][logger:176]:   Level: DEBUG
[07:51:51][C][logger:177]:   Log Baud Rate: 115200
[07:51:51][C][logger:178]:   Hardware UART: UART0
[07:51:51][C][status:034]: Status Binary Sensor 'esp_train_controller Status'
[07:51:51][C][status:034]:   Device Class: 'connectivity'
[07:51:51][C][restart:021]: Restart Switch 'esp_train_controller restart'
[07:51:51][C][restart:021]:   Icon: 'mdi:restart'
[07:51:51][C][dallas.sensor:070]: DallasComponent:
[07:51:51][C][dallas.sensor:071]:   Pin: GPIO14 (Mode: INPUT)
[07:51:51][C][dallas.sensor:072]:   Update Interval: 60.0s
[07:51:51][W][dallas.sensor:075]:   Found no sensors!

Issue persists.

hgregorian commented 4 years ago

Re-tested since this change (https://github.com/esphome/esphome/pull/862) in the 1.14.3 release. Issue persists as anticipated.

brandond commented 4 years ago

The dallas sensor component only searches the one-wire bus once during setup. If there are issues at this time, the found_sensors vector will never get populated. Manually configured sensors don't rely on discovery in order to function correctly, so it doesn't affect them at all; the error is purely cosmetic.

I suspect that if you connect the device via USB and collect startup logs, you'll see some additional errors that you're not getting via API.

Just out of curiosity, how is the sensor wired in? I've had issues similar to this when powering my device off a regulator that didn't provide sufficient power at startup when the ESP is drawing a lot.

hgregorian commented 4 years ago

@brandond, the sensor is wired in normal mode (not parasitic) using a 4.7kΩ resistor, just like this:

Note that as stated, changing to arduino_version: 2.4.2 makes the startup "problem" go away.

I'll see about collecting info via USB later today.

brandond commented 4 years ago

Powering it off 3v3 uses the AM1117 as the regulator from 5v supply. You might try powering it via Vin, which is connected to the 5v rail from the USB plug. The device can use anything between 3.0 and 5.5v.

Not sure why changing the arduino version would make a difference, but I'm curious if changing the supply might resolve whatever issue is causing it to be flaky under newer arduino cores.

hgregorian commented 4 years ago

@brandond, sure, I'll give that a shot too, if for nothing else, another data point.

hgregorian commented 4 years ago

Issue persists with 5v powering the sensor. In this breadboard setup (I've taken the d1 mini out of its setup), I have it plugged in via FTDI (5v selected and measured) with all pins wired (as if I were to flash). Using ESPHome-Flasher, I can see what I believe are the startup logs. I've removed entries with 'wifi' and 'mqtt'. Is this what you're looking for? (doesn't look too insightful)

Using '/dev/cu.usbserial-00000000' as serial port.
Showing logs:
[19:57:07]r[19:57:07]SDK:2.2.1(cfd48f3)/Core:2.5.2=20502000/lwIP:STABLE-2_1_2_RELEASE/glue:1.1-7-g82abda3/BearSSL:a143020
[19:57:07][I][logger:156]: Log initialized
[19:57:07][C][status_led:014]: Setting up Status LED...
[19:57:07][VV][preferences:038]: LOAD 32: valid=YES, 0=0x00000001 1=0x42F4583F (Type=233825507, CRC=0x42F4583F)
[19:57:07][C][ota:364]: There have been 1 suspected unsuccessful boot attempts.
[19:57:07][VV][preferences:051]: SAVE 32: 0=0x00000002 1=0x13D89D5A (Type=233825507, CRC=0x13D89D5A)
[19:57:07][I][app:028]: Running through setup()...
[19:57:07][V][app:029]: Sorting components by setup priority...
[19:57:07][VV][scheduler:056]: set_interval(name='update', interval=60000, offset=22021)
[19:57:07][C][esp8266_pwm:017]: Setting up ESP8266 PWM Output...
[19:57:07][C][esp8266_pwm:017]: Setting up ESP8266 PWM Output...
[19:57:07][D][binary_sensor:034]: 'esp_train_controller Status': Sending initial state OFF
[19:57:07][C][dallas.sensor:032]: Setting up DallasComponent...
[19:57:07][VV][scheduler:056]: set_interval(name='update', interval=60000, offset=19876)
[19:57:07][D][text_sensor:015]: 'esp_train_controller ESPHome Version': Sending state '1.14.3 Nov 18 2019, 19:05:40'
[19:57:07][VV][preferences:038]: LOAD 0: valid=NO, 0=0xFFFFFFFF 1=0xFFFFFFFF (Type=3617682322, CRC=0xE74530B1)
[19:57:07]mode : sta(84:f3:eb:dc:dd:60)
[19:57:07]add if0
[19:57:07]sleep disable
[19:57:07][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=4294885497 (now=327)
[19:57:07][V][sensor:013]: 'esp_train_controller Uptime': Received new state 0.328000
[19:57:07][D][sensor:092]: 'esp_train_controller Uptime': Sending state 0.32800 s with 0 decimals of accuracy
[19:57:07][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=4294887674 (now=327)
[19:57:13]scandone
[19:57:14]scandone
[19:57:15]state: 0 -> 2 (b0)
[19:57:16]state: 2 -> 0 (2)
[19:57:16]STA disconnect: 2
[19:57:16]del if0
[19:57:16]usl
[19:57:16]mode : null
[19:57:16]mode : sta(84:f3:eb:dc:dd:60)
[19:57:16]add if0
[19:57:17]scandone
[19:57:18]state: 0 -> 2 (b0)
[19:57:19]state: 2 -> 0 (2)
[19:57:19]STA disconnect: 2
[19:57:19]del if0
[19:57:19]usl
[19:57:19]mode : null
[19:57:24]mode : sta(84:f3:eb:dc:dd:60)
[19:57:24]add if0
[19:57:30]scandone
[19:57:30]scandone
[19:57:31]state: 0 -> 2 (b0)
[19:57:32]state: 2 -> 0 (2)
[19:57:32]STA disconnect: 2
[19:57:32]del if0
[19:57:32]usl
[19:57:32]mode : null
[19:57:32]mode : sta(84:f3:eb:dc:dd:60)
[19:57:32]add if0
[19:57:33]scandone
[19:57:34]state: 0 -> 2 (b0)
[19:57:34]state: 2 -> 3 (0)
[19:57:34]state: 3 -> 5 (10)
[19:57:34]add 0
[19:57:34]aid 3
[19:57:34]cnt
[19:57:34]
[19:57:34]connected with IoT, channel 1
[19:57:34]dhcp client start...
[19:57:40]ip:172.16.10.25,mask:255.255.255.0,gw:172.16.10.1
[19:57:40][C][ota:029]: Over-The-Air Updates:
[19:57:40][C][ota:030]:   Address: esp_train_controller.local:8266
[19:57:40][C][api:022]: Setting up Home Assistant API server...
[19:57:41][VV][scheduler:056]: set_interval(name='update', interval=120000, offset=21823)
[19:57:41][VV][scheduler:025]: set_timeout(name='', timeout=0)
[19:57:41][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:41][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:41][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:41][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:41][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:41][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:41][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:41][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][I][app:058]: setup() finished successfully!
[19:57:42][VV][scheduler:131]: Running interval 'update' with interval=120000 last_execution=4294858896 (now=34842)
[19:57:42][V][sensor:013]: 'esp_train_controller WiFi Signal': Received new state -78.000000
[19:57:42][D][sensor:092]: 'esp_train_controller WiFi Signal': Sending state -78.00000 dB with 0 decimals of accuracy
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][VV][scheduler:131]: Running timeout '' with interval=0 last_execution=33737 (now=34842)
[19:57:42][V][sensor:013]: 'throttle_target': Received new state 0.000000
[19:57:42][D][sensor:092]: 'throttle_target': Sending state 0.00000  with 1 decimals of accuracy
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][D][text_sensor:015]: 'esp_train_controller IP Address': Sending state '172.16.10.25'
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][D][text_sensor:015]: 'esp_train_controller SSID': Sending state 'IoT'
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][D][text_sensor:015]: 'esp_train_controller BSSID': Sending state 'D6:FB:E4:71:89:BF'
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:42][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][V][app:076]: A component took a long time in a loop() cycle (1.08 s).
[19:57:43][V][app:077]: Components should block for at most 20-30ms in loop().
[19:57:43][I][app:100]: ESPHome version 1.14.3 compiled on Nov 18 2019, 19:05:40
[19:57:43][C][status_led:019]: Status LED:
[19:57:43][C][status_led:020]:   Pin: GPIO2 (Mode: OUTPUT, INVERTED)
[19:57:43][VV][scheduler:131]: Running timeout 'subscribe' with interval=1000 last_execution=34595 (now=35955)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:43][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44]pm open,type:0 0
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44][V][app:076]: A component took a long time in a loop() cycle (1.01 s).
[19:57:44][V][app:077]: Components should block for at most 20-30ms in loop().
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:44][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][V][app:076]: A component took a long time in a loop() cycle (1.09 s).
[19:57:45][V][app:077]: Components should block for at most 20-30ms in loop().
[19:57:45][C][uptime.sensor:030]: Uptime Sensor 'esp_train_controller Uptime'
[19:57:45][C][uptime.sensor:030]:   Unit of Measurement: 's'
[19:57:45][C][uptime.sensor:030]:   Accuracy Decimals: 0
[19:57:45][C][uptime.sensor:030]:   Icon: 'mdi:timer'
[19:57:45][V][uptime.sensor:030]:   Unique ID: '84f3ebdcdd60-uptime'
[19:57:45][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:45][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:46][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:46][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:46][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:46][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:46][VV][scheduler:025]: set_timeout(name='publish', timeout=1000)
[19:57:46][VV][scheduler:025]: set_timeout(name='', timeout=0)
[19:57:47][V][app:076]: A component took a long time in a loop() cycle (1.24 s).
[19:57:47][V][app:077]: Components should block for at most 20-30ms in loop().
[19:57:47][C][esp8266_pwm:022]: ESP8266 PWM:
[19:57:47][C][esp8266_pwm:023]:   Pin: GPIO4 (Mode: OUTPUT)
[19:57:47][C][esp8266_pwm:024]:   Frequency: 14000.0 Hz
[19:57:47][C][esp8266_pwm:025]:   Max Power: 97.0%
[19:57:47][C][esp8266_pwm:025]:   Min Power: 5.0%
[19:57:47][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=4294945497 (now=39471)
[19:57:47][V][sensor:013]: 'esp_train_controller Uptime': Received new state 39.500999
[19:57:47][D][sensor:092]: 'esp_train_controller Uptime': Sending state 39.50100 s with 0 decimals of accuracy
[19:57:47][VV][scheduler:131]: Running timeout '' with interval=0 last_execution=38756 (now=39471)
[19:57:47][V][sensor:013]: 'throttle_target': Received new state 0.000000
[19:57:47][D][sensor:092]: 'throttle_target': Sending state 0.00000  with 1 decimals of accuracy
[19:57:47][VV][scheduler:131]: Running timeout 'subscribe' with interval=1000 last_execution=38346 (now=39471)
[19:57:47][VV][scheduler:025]: set_timeout(name='subscribe', timeout=1000)
[19:57:47][V][app:076]: A component took a long time in a loop() cycle (0.66 s).
[19:57:47][V][app:077]: Components should block for at most 20-30ms in loop().
[19:57:47][C][esp8266_pwm:022]: ESP8266 PWM:
[19:57:47][C][esp8266_pwm:023]:   Pin: GPIO5 (Mode: OUTPUT)
[19:57:47][C][esp8266_pwm:024]:   Frequency: 14000.0 Hz
[19:57:47][C][esp8266_pwm:025]:   Max Power: 97.0%
[19:57:47][C][esp8266_pwm:025]:   Min Power: 5.0%
[19:57:47][VV][scheduler:131]: Running timeout 'publish' with interval=1000 last_execution=38639 (now=40163)
[19:57:47][C][template.switch:058]: Template Switch 'Train Controller - Full Speed 60'
[19:57:47][C][template.switch:059]:   Restore State: NO
[19:57:47][C][template.switch:060]:   Optimistic: NO
[19:57:47][C][template.switch:058]: Template Switch 'Train Controller - Clockwise'
[19:57:47][C][template.switch:059]:   Restore State: NO
[19:57:47][C][template.switch:060]:   Optimistic: NO
[19:57:47][C][template.switch:058]: Template Switch 'Train Controller - Frequency Test'
[19:57:47][C][template.switch:059]:   Restore State: NO
[19:57:47][C][template.switch:060]:   Optimistic: NO
[19:57:47][C][template.switch:058]: Template Switch 'Train Controller - Counter Clockwise'
[19:57:47][C][template.switch:059]:   Restore State: NO
[19:57:47][C][template.switch:060]:   Optimistic: NO
[19:57:48][VV][scheduler:131]: Running interval 'update' with interval=60000 last_execution=4294947674 (now=40378)
[19:57:48][VV][scheduler:131]: Running timeout 'subscribe' with interval=1000 last_execution=39629 (now=40650)
[19:57:48][C][logger:175]: Logger:
[19:57:48][C][logger:176]:   Level: VERY_VERBOSE
[19:57:48][C][logger:177]:   Log Baud Rate: 115200
[19:57:48][C][logger:178]:   Hardware UART: UART0
[19:57:48][C][status:034]: Status Binary Sensor 'esp_train_controller Status'
[19:57:48][C][status:034]:   Device Class: 'connectivity'
[19:57:48][C][restart:021]: Restart Switch 'esp_train_controller restart'
[19:57:48][C][restart:021]:   Icon: 'mdi:restart'
[19:57:48][C][dallas.sensor:070]: DallasComponent:
[19:57:48][C][dallas.sensor:071]:   Pin: GPIO0 (Mode: INPUT)
[19:57:48][C][dallas.sensor:072]:   Update Interval: 60.0s
[19:57:48][W][dallas.sensor:075]:   Found no sensors!
hgregorian commented 4 years ago

FWIW, I recently had the need to use a Sonoff SV with a temperature sensor (temporary stand-in until I could procure a limit switch for my furnace - worked great!). Identical setup as with the d1 mini with only a switch added for the onboard relay. The issue I originally opened this issue for was present until I used arduino_version: 2.4.2.

stale[bot] commented 3 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.