search

esphome / issues

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

MQTT Inoperative on 1.13.0-dev? #301

Closed mtl010957 closed 5 years ago

mtl010957 commented 5 years ago

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

pip install on Ubuntu 19.04

ESP (ESP32/ESP8266, Board/Sonoff):

Adafruit Huzzah ESP8266

Affected component:

MQTT

Description of problem: MQTT seems to be inoperative on latest 1.13.0-dev builds. API works as expected. No logging indicating any problem with the MQTT, and the exact same configuration works properly in 1.12.2.

Problem-relevant YAML-configuration entries:


***Main yaml config:***

substitutions:
  devicename: ah03_th
  upper_devicename: AH03_TH

esphome: !include adafruit_huzzah/device.yaml
wifi: !include connection/wifi.yaml
mqtt: !include connection/mqtt.yaml
# Enable logging
logger: !include base/logger.yaml
# Enable Home Assistant API
api:
ota:
# Enable remote restart from HA
switch: !include adafruit_huzzah/switch.yaml
# Need I2C bus for sensors
i2c: !include connection/i2c.yaml
# SHT31-D Temperature and Humidity
sensor: !include sensor/sht3x_d.yaml
# Blue LED (either output+light or status_led, not both)
output: !include adafruit_huzzah/output.yaml
light: !include adafruit_huzzah/light.yaml
#status_led: !include adafruit_huzzah/status_led.yaml
# Flash Button
binary_sensor: !include adafruit_huzzah/binary_sensor.yaml

***The included MQTT config mqtt.yaml:***
broker: !secret mqtt_broker
username: !secret mqtt_username
password: !secret mqtt_password

Traceback (if applicable):

***Here's the log output from the ESP:***
INFO Reading configuration...
INFO Starting log output from ah03_th.local using esphome API
INFO Connecting to ah03_th.local:6053 (192.168.13.200)
INFO Successfully connected to ah03_th.local
[21:49:52][I][app:063]: esphome-core version 1.13.0-dev compiled on May  6 2019, 21:24:47
[21:49:52][C][wifi:368]: WiFi:
[21:49:52][C][wifi:250]:   SSID: 

[redacted]
[21:49:52][C][wifi:251]:   IP Address: 192.168.13.200
[21:49:52][C][wifi:253]:   BSSID: 

[redacted]
[21:49:52][C][wifi:254]:   Hostname: 'ah03_th'
[21:49:52][C][wifi:258]:   Signal strength: -78 dB ▂▄▆█
[21:49:52][C][wifi:259]:   Channel: 9
[21:49:52][C][wifi:260]:   Subnet: 255.255.255.0
[21:49:52][C][wifi:261]:   Gateway: 192.168.13.1
[21:49:52][C][wifi:262]:   DNS1: 75.75.75.75
[21:49:52][C][wifi:263]:   DNS2: 75.75.76.76
[21:49:52][C][i2c:028]: I2C Bus:
[21:49:52][C][i2c:029]:   SDA Pin: GPIO4
[21:49:52][C][i2c:030]:   SCL Pin: GPIO5
[21:49:52][C][i2c:031]:   Frequency: 10000 Hz
[21:49:52][I][i2c:033]: Scanning i2c bus for active devices...
[21:49:52][I][i2c:040]: Found i2c device at address 0x44
[21:49:52][C][something.something:022]: ESP8266 PWM:
[21:49:52][C][something.something:023]:   Pin: GPIO2 (Mode: OUTPUT, INVERTED)
[21:49:52][C][something.something:024]:   Frequency: 1000.0 Hz
[21:49:52][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'AH03_TH Button'
[21:49:52][C][gpio.binary_sensor:016]:   Pin: GPIO0 (Mode: INPUT_PULLUP, INVERTED)
[21:49:52][C][logger:137]: Logger:
[21:49:52][C][logger:138]:   Level: DEBUG
[21:49:52][C][logger:139]:   Log Baud Rate: 115200
[21:49:52][C][logger:140]:   Hardware UART: UART0
[21:49:52][C][light:161]: Light 'AH03_TH Blue LED'
[21:49:52][C][light:163]:   Default Transition Length: 1.0s
[21:49:52][C][light:164]:   Gamma Correct: 2.80
[21:49:52][C][restart:021]: Restart Switch 'AH03_TH Restart'
[21:49:52][C][restart:021]:   Icon: 'mdi:restart'
[21:49:52][C][sht3xd:034]: SHT3xD:
[21:49:52][C][sht3xd:035]:   Address: 0x44
[21:49:52][C][sht3xd:039]:   Update Interval: 10.0s
[21:49:52](Message skipped because it was too big to fit in TCP buffer - This is only cosmetic)
[21:49:52](Message skipped because it was too big to fit in TCP buffer - This is only cosmetic)
[21:49:52](Message skipped because it was too big to fit in TCP buffer - This is only cosmetic)
[21:49:52][C][sht3xd:041]:     Icon: 'mdi:thermometer'
[21:49:52][C][sht3xd:042]:   Humidity 'AH03_TH Humidity'
[21:49:52][C][sht3xd:042]:     Unit of Measurement: '%'
[21:49:52][C][sht3xd:042]:     Accuracy Decimals: 1
[21:49:52][C][sht3xd:042]:     Icon: 'mdi:water-percent'
[21:49:52][C][ota:030]: Over-The-Air Updates:
[21:49:52][C][ota:031]:   Address: ah03_th.local:8266
[21:49:52][C][api:102]: API Server:
[21:49:52][C][api:103]:   Address: ah03_th.local:6053
[21:49:52][C][mqtt.switch:038]: MQTT Switch 'AH03_TH Restart': 
[21:49:52][C][mqtt.switch:039]:   State Topic: 'ah03_th/switch/ah03_th_restart/state'
[21:49:52][C][mqtt.switch:039]:   Command Topic: 'ah03_th/switch/ah03_th_restart/command'
[21:49:52][C][mqtt.binary_sensor:018]: MQTT Binary Sensor 'AH03_TH Button':
[21:49:52][C][mqtt.binary_sensor:019]:   State Topic: 'ah03_th/binary_sensor/ah03_th_button/state'
[21:49:52][C][mqtt.light:053]: MQTT Light 'AH03_TH Blue LED':
[21:49:52][C][mqtt.light:054]:   State Topic: 'ah03_th/light/ah03_th_blue_led/state'
[21:49:52][C][mqtt.light:054]:   Command Topic: 'ah03_th/light/ah03_th_blue_led/command'
[21:49:52][C][mqtt.sensor:024]: MQTT Sensor 'AH03_TH Temperature':
[21:49:52][C][mqtt.sensor:026]:   Expire After: 600s
[21:49:52][C][mqtt.sensor:028]:   State Topic: 'ah03_th/sensor/ah03_th_temperature/state'
[21:49:52][C][mqtt.sensor:024]: MQTT Sensor 'AH03_TH Humidity':
[21:49:52][C][mqtt.sensor:026]:   Expire After: 600s
[21:49:52][C][mqtt.sensor:028]:   State Topic: 'ah03_th/sensor/ah03_th_humidity/state'
[21:49:53][D][sht3xd:059]: Got temperature=24.08°C humidity=45.08%

Additional information and things you've tried: I've tried to reduce the configuration to just the minimum required to test the MQTT part, but it still fails to send any MQTT messages out to the broker. I've tried with the api: entry commented out, the only way to get any logging is through USB in that case, nothing comes out by MQTT. Never any compiler errors logged, everything seems normal during he build and flashing steps.

mtl010957 commented 5 years ago

I just noticed that there are no MQTT connection messages at all in the log, appears that there is never any attempt to connect. Normally there should be messages like:

[22:29:08][C][mqtt.client:027]: Setting up MQTT...
[22:29:08][D][mqtt.client:114]: Resolving MQTT broker IP address...
[22:29:09][D][mqtt.client:147]: Resolved broker IP address to 98.209.92.57
[22:29:09][I][mqtt.client:173]: Connecting to MQTT...
[22:29:09][I][mqtt.client:213]: MQTT Connected!
OttoWinter commented 5 years ago

@mtl010957 Yeah the dev branch is broken in a few places right now after a big refactor. MQTT could well also be affected. As for the logs, if possible provide USB logs. The MQTT connection attempt log messages you see could be even before the native API logs connect - only over USB you can make sure they will show up.

mtl010957 commented 5 years ago

Here's the USB log from a complete build and upload cycle, with the api: commented out so just the MQTT should be active:

INFO Reading configuration...
INFO Generating C++ source...
INFO Compiling app...
INFO Running:  platformio run -d git/esphome_config/ah03_th
Processing ah03_th (framework: arduino; platform: espressif8266@1.8.0; board: huzzah)
--------------------------------------------------------------------------------
Warning! Library `{'requirements': None, 'name': 'Update'}` has not been found in PlatformIO Registry.
You can ignore this message, if `{'requirements': None, 'name': 'Update'}` is a built-in library (included in framework, SDK). E.g., SPI, Wire, etc.
Verbose mode can be enabled via `-v, --verbose` option
CONFIGURATION: https://docs.platformio.org/page/boards/espressif8266/huzzah.html
PLATFORM: Espressif 8266 > Adafruit HUZZAH ESP8266
HARDWARE: ESP8266 80MHz 80KB RAM (4MB Flash)
Library Dependency Finder -> http://bit.ly/configure-pio-ldf
LDF MODES: FINDER(chain) COMPATIBILITY(soft)
Collected 29 compatible libraries
Scanning dependencies...
Dependency Graph
|-- <ArduinoJson-esphomelib> 5.13.3
|-- <AsyncMqttClient> 0.8.2
|   |-- <ESPAsyncTCP> 1.2.0
|   |   |-- <ESP8266WiFi> 1.0
|-- <ESP8266WiFi> 1.0
|-- <ESP8266mDNS>
|   |-- <ESP8266WiFi> 1.0
|-- <Wire> 1.0
Retrieving maximum program size .pioenvs/ah03_th/firmware.elf
Checking size .pioenvs/ah03_th/firmware.elf
Memory Usage -> http://bit.ly/pio-memory-usage
DATA:    [====      ]  40.1% (used 32824 bytes from 81920 bytes)
PROGRAM: [====      ]  36.1% (used 376940 bytes from 1044464 bytes)
========================= [SUCCESS] Took 1.25 seconds =========================
INFO Successfully compiled program.
INFO Running:  esptool.py --before default_reset --after hard_reset --chip esp8266 --port /dev/ttyUSB1 write_flash 0x0 git/esphome_config/ah03_th/.pioenvs/ah03_th/firmware.bin
esptool.py v2.6
Serial port /dev/ttyUSB1
Connecting....
Chip is ESP8266EX
Features: WiFi
MAC: 5c:cf:7f:15:1f:f1
Uploading stub...
Running stub...
Stub running...
Configuring flash size...
Auto-detected Flash size: 4MB
Compressed 381088 bytes to 259761...
Wrote 381088 bytes (259761 compressed) at 0x00000000 in 23.0 seconds (effective 132.3 kbit/s)...
Hash of data verified.

Leaving...
Hard resetting via RTS pin...
INFO Successfully uploaded program.
INFO Starting log output from /dev/ttyUSB1 with baud rate 115200
<some garbled stuff from the reset>
[09:31:38][C][ota:365]: There have been 2 suspected unsuccessful boot attempts.
[09:31:38][I][app:027]: Running through setup()...
[09:31:38][C][something.something:017]: Setting up ESP8266 PWM Output...
[09:31:38][D][binary_sensor:033]: 'AH03_TH Button': Sending state OFF
[09:31:38][C][light:094]: Setting up light 'AH03_TH Blue LED'...
[09:31:38][D][light:248]: 'AH03_TH Blue LED' Setting:
[09:31:38][D][light:261]:   Brightness: 100%
[09:31:38][C][sht3xd:019]: Setting up SHT3xD...
[09:31:38][C][wifi:029]: Setting up WiFi...
[09:31:38][D][wifi:268]: Starting scan...
[09:31:38][D][sht3xd:059]: Got temperature=19.24°C humidity=46.45%
[09:31:38][D][sensor:093]: 'AH03_TH Temperature': Sending state 19.23743 °C with 1 decimals of accuracy
[09:31:38][D][sensor:093]: 'AH03_TH Humidity': Sending state 46.44694 % with 1 decimals of accuracy
[09:31:43][D][wifi:283]: Found networks:
[09:31:43][I][wifi:318]: - 'animals' 

[redacted]▂▄▆█
[09:31:43][D][wifi:319]:     Channel: 9
[09:31:43][D][wifi:320]:     RSSI: -71 dB
[09:31:44][D][wifi:322]: - 

[redacted] 

[redacted]▂▄▆█
[09:31:44][D][wifi:322]: - 

[redacted] 

[redacted]▂▄▆█
[09:31:44][D][wifi:322]: - 

[redacted] 

[redacted]▂▄▆█
[09:31:44][D][wifi:322]: - 

[redacted] 

[redacted]▂▄▆█
[09:31:44][D][wifi:322]: - 

[redacted] 

[redacted]▂▄▆█
[09:31:44][I][wifi:164]: WiFi Connecting to 'animals'...
[09:31:46][W][wifi:396]: Error while connecting to network.
[09:31:46][W][wifi:426]: Restarting WiFi adapter...
[09:31:46][I][wifi:164]: WiFi Connecting to 'animals'...
[09:31:46][I][wifi:376]: WiFi connected!
[09:31:46][C][wifi:250]:   SSID: 

[redacted]
[09:31:46][C][wifi:251]:   IP Address: 192.168.13.200
[09:31:46][C][wifi:253]:   BSSID: 

[redacted]
[09:31:46][C][wifi:254]:   Hostname: 'ah03_th'
[09:31:46][C][wifi:258]:   Signal strength: -73 dB ▂▄▆█
[09:31:46][C][wifi:259]:   Channel: 9
[09:31:46][C][wifi:260]:   Subnet: 255.255.255.0
[09:31:46][C][wifi:261]:   Gateway: 192.168.13.1
[09:31:46][C][wifi:262]:   DNS1: 75.75.75.75
[09:31:46][C][wifi:263]:   DNS2: 75.75.76.76
[09:31:46][C][ota:030]: Over-The-Air Updates:
[09:31:46][C][ota:031]:   Address: ah03_th.local:8266
[09:31:46][W][ota:037]: Last Boot was an unhandled reset, will proceed to safe mode in 8 restarts
[09:31:46][I][app:059]: setup() finished successfully!
[09:31:46][I][app:063]: esphome-core version 1.13.0-dev compiled on May  7 2019, 09:28:32
[09:31:46][C][wifi:368]: WiFi:
[09:31:46][C][wifi:250]:   SSID: 

[redacted]
[09:31:47][C][wifi:251]:   IP Address: 192.168.13.200
[09:31:47][C][wifi:253]:   BSSID: 

[redacted]
[09:31:47][C][wifi:254]:   Hostname: 'ah03_th'
[09:31:47][C][wifi:258]:   Signal strength: -73 dB ▂▄▆█
[09:31:47][C][wifi:259]:   Channel: 9
[09:31:47][C][wifi:260]:   Subnet: 255.255.255.0
[09:31:47][C][wifi:261]:   Gateway: 192.168.13.1
[09:31:47][C][wifi:262]:   DNS1: 75.75.75.75
[09:31:47][C][wifi:263]:   DNS2: 75.75.76.76
[09:31:47][C][i2c:028]: I2C Bus:
[09:31:47][C][i2c:029]:   SDA Pin: GPIO4
[09:31:47][C][i2c:030]:   SCL Pin: GPIO5
[09:31:47][C][i2c:031]:   Frequency: 10000 Hz
[09:31:47][I][i2c:033]: Scanning i2c bus for active devices...
[09:31:47][I][i2c:040]: Found i2c device at address 0x44
[09:31:47][C][something.something:022]: ESP8266 PWM:
[09:31:47][C][something.something:023]:   Pin: GPIO2 (Mode: OUTPUT, INVERTED)
[09:31:47][C][something.something:024]:   Frequency: 1000.0 Hz
[09:31:47][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'AH03_TH Button'
[09:31:47][C][gpio.binary_sensor:016]:   Pin: GPIO0 (Mode: INPUT_PULLUP, INVERTED)
[09:31:47][C][logger:137]: Logger:
[09:31:47][C][logger:138]:   Level: DEBUG
[09:31:47][C][logger:139]:   Log Baud Rate: 115200
[09:31:47][C][logger:140]:   Hardware UART: UART0
[09:31:47][C][light:161]: Light 'AH03_TH Blue LED'
[09:31:47][C][light:163]:   Default Transition Length: 1.0s
[09:31:47][C][light:164]:   Gamma Correct: 2.80
[09:31:47][C][restart:021]: Restart Switch 'AH03_TH Restart'
[09:31:47][C][restart:021]:   Icon: 'mdi:restart'
[09:31:47][C][sht3xd:034]: SHT3xD:
[09:31:47][C][sht3xd:035]:   Address: 0x44
[09:31:47][C][sht3xd:039]:   Update Interval: 10.0s
[09:31:47][C][sht3xd:041]:   Temperature 'AH03_TH Temperature'
[09:31:47][C][sht3xd:041]:     Unit of Measurement: '°C'
[09:31:47][C][sht3xd:041]:     Accuracy Decimals: 1
[09:31:47][C][sht3xd:041]:     Icon: 'mdi:thermometer'
[09:31:47][C][sht3xd:042]:   Humidity 'AH03_TH Humidity'
[09:31:47][C][sht3xd:042]:     Unit of Measurement: '%'
[09:31:47][C][sht3xd:042]:     Accuracy Decimals: 1
[09:31:47][C][sht3xd:042]:     Icon: 'mdi:water-percent'
[09:31:47][C][ota:030]: Over-The-Air Updates:
[09:31:47][C][ota:031]:   Address: ah03_th.local:8266
[09:31:47][W][ota:037]: Last Boot was an unhandled reset, will proceed to safe mode in 8 restarts
[09:31:47][C][mqtt.switch:038]: MQTT Switch 'AH03_TH Restart': 
[09:31:47][C][mqtt.switch:039]:   State Topic: 'ah03_th/switch/ah03_th_restart/state'
[09:31:47][C][mqtt.switch:039]:   Command Topic: 'ah03_th/switch/ah03_th_restart/command'
[09:31:47][C][mqtt.binary_sensor:018]: MQTT Binary Sensor 'AH03_TH Button':
[09:31:47][C][mqtt.binary_sensor:019]:   State Topic: 'ah03_th/binary_sensor/ah03_th_button/state'
[09:31:47][C][mqtt.light:053]: MQTT Light 'AH03_TH Blue LED':
[09:31:47][C][mqtt.light:054]:   State Topic: 'ah03_th/light/ah03_th_blue_led/state'
[09:31:47][C][mqtt.light:054]:   Command Topic: 'ah03_th/light/ah03_th_blue_led/command'
[09:31:47][C][mqtt.sensor:024]: MQTT Sensor 'AH03_TH Temperature':
[09:31:47][C][mqtt.sensor:026]:   Expire After: 600s
[09:31:47][C][mqtt.sensor:028]:   State Topic: 'ah03_th/sensor/ah03_th_temperature/state'
[09:31:47][C][mqtt.sensor:024]: MQTT Sensor 'AH03_TH Humidity':
[09:31:47][C][mqtt.sensor:026]:   Expire After: 600s
[09:31:47][C][mqtt.sensor:028]:   State Topic: 'ah03_th/sensor/ah03_th_humidity/state'
[09:31:47][D][sht3xd:059]: Got temperature=19.22°C humidity=46.67%
[09:31:57][D][sht3xd:059]: Got temperature=19.18°C humidity=46.98%
[09:31:57][D][sensor:093]: 'AH03_TH Humidity': Sending state 46.97795 % with 1 decimals of accuracy
[09:32:07][D][sht3xd:059]: Got temperature=19.20°C humidity=46.99%
[09:32:17][D][sht3xd:059]: Got temperature=19.15°C humidity=47.00%
[09:32:27][D][sht3xd:059]: Got temperature=19.18°C humidity=47.09%
[09:32:37][D][sht3xd:059]: Got temperature=19.17°C humidity=47.00%
[09:32:47][D][sht3xd:059]: Got temperature=19.15°C humidity=46.82%
[09:32:57][D][sht3xd:059]: Got temperature=19.18°C humidity=47.69%
[09:32:57][D][sensor:093]: 'AH03_TH Humidity': Sending state 47.68750 % with 1 decimals of accuracy
[09:33:07][D][sht3xd:059]: Got temperature=19.15°C humidity=47.42%
[09:33:17][D][sht3xd:059]: Got temperature=19.17°C humidity=47.20%
[09:33:27][D][sht3xd:059]: Got temperature=19.14°C humidity=47.04%
[09:33:27][D][sensor:093]: 'AH03_TH Humidity': Sending state 47.04356 % with 1 decimals of accuracy
[09:33:37][D][sht3xd:059]: Got temperature=19.18°C humidity=46.94%
[09:33:38][I][ota:047]: Boot seems successful, resetting boot loop counter.
[09:33:47][D][sht3xd:059]: Got temperature=19.18°C humidity=46.93%
[09:33:57][D][sht3xd:059]: Got temperature=19.18°C humidity=47.01%
[09:34:07][D][sht3xd:059]: Got temperature=19.21°C humidity=47.10%
[09:34:17][D][sht3xd:059]: Got temperature=19.24°C humidity=47.00%
[09:34:27][D][sht3xd:059]: Got temperature=19.22°C humidity=46.85%
[09:34:37][D][sht3xd:059]: Got temperature=19.24°C humidity=46.75%
[09:34:47][D][sht3xd:059]: Got temperature=19.27°C humidity=46.84%

Still no sign of the MQTT startup messages here. Although the messages indicate that we're sending state as expected there's never anything showing up at the MQTT broker.

I'm impressed with the progress on the refactoring so far, and I'm happy to help in any way I can. I'll continue to try to debug this, please give me any pointers on the best way to proceed.

Thanks.

mtl010957 commented 5 years ago

I've found the issue but not sure how to correct it. The generated main.cpp file needs to have a line like this:

  App.register_component(mqtt_mqttclientcomponent);

Once I added that line MQTT started working correctly. I'll continue to look for how to get the code generation to product the line properly, let me know if you have a pointer to where the correction should be done.