Inconsitent logging with ESP8266 on 2024.5.0

DAVe3283 commented 3 months ago

The problem

Logging is not behaving correctly in ESPHome 2024.5.0 or newer (including the latest dev branch). Some debug messages do not print that should print, including when a sensor publishes a value to Home Assistant.

Cleaning build files and recompiling does not have an effect on behavior.

Reverting to ESPHome 2024.4.2 causes the device to work correctly again, with all debug messages printing to the log.

I run a nearly identical piece of hardware with an ESP32 instead of an ESP8266, and the behavior seems limited to the 8266.

Which version of ESPHome has the issue?

2024.5.0

What type of installation are you using?

Home Assistant Add-on

Which version of Home Assistant has the issue?

2024.5.4

What platform are you using?

ESP8266

Board

D1 Mini

Component causing the issue

No response

Example YAML snippet

substitutions:
  name: shed-haks
  friendly_name: Shed HAKS

packages:
  haks:
    url: https://PigLab.ReaperLegion.net/home-automation/hass/esphome/packages/haks.git
    files:
      - core.yaml
      - WiFi.yaml
      - BME280.yaml
      - PMS7003.yaml
      - OLED_US_kPa.yaml

api:
  encryption:
    key: !secret shed_haks_key

ota:
  password: !secret shed_haks_ota

wifi:
  ssid: !secret wifi_ssid
  password: !secret wifi_password
  domain: !secret domain
  ap:
    password: !secret shed_haks_ota

# Sunrise/sunset for OLED day/night mode (reduce burn-in)
sun:
  latitude: !secret latitude
  longitude: !secret longitude

Anything in the logs that might be useful for us?

No errors are shown in the logs for the ESP8266 or for Home Assistant. It is more notable that some debug messages are *not* present on 2024.5.0 that are (and should be) present on 2024.4.2:

[13:47:00][D][pmsx003:234]: Got PM1.0 Concentration: 0 µg/m^3, PM2.5 Concentration 0 µg/m^3, PM10.0 Concentration: 0 µg/m^3
[13:47:00][D][sensor:093]: 'Particulate Matter 1.0μm': Sending state 0.00000 µg/m³ with 0 decimals of accuracy
[13:47:00][D][sensor:093]: 'Particulate Matter 2.5μm': Sending state 0.00000 µg/m³ with 0 decimals of accuracy
[13:47:00][D][aqi.sensor:132]: Callback got PM2.5 state 0.000000, using 0.000000
[13:47:00][D][aqi.sensor:148]: PM2.5 calculated AQI 0.000000, using 0
[13:47:00][D][sensor:093]: 'Particulate Matter 10.0μm': Sending state 0.00000 µg/m³ with 0 decimals of accuracy
[13:47:00][D][aqi.sensor:159]: Callback got PM10.0 state 0.000000, using 0
[13:47:00][D][aqi.sensor:175]: PM10.0 calculated AQI 0.000000, using 0
[13:47:00][D][sensor:093]: 'Particulate Matter ≥0.3μm Count': Sending state 78.00000 /dL with 0 decimals of accuracy
[13:47:00][D][sensor:093]: 'Particulate Matter ≥0.5μm Count': Sending state 12.00000 /dL with 0 decimals of accuracy
[13:47:00][D][sensor:093]: 'Particulate Matter ≥1.0μm Count': Sending state 0.00000 /dL with 0 decimals of accuracy
[13:47:00][D][sensor:093]: 'Particulate Matter ≥2.5μm Count': Sending state 0.00000 /dL with 0 decimals of accuracy
[13:47:00][D][sensor:093]: 'Particulate Matter ≥5.0μm Count': Sending state 0.00000 /dL with 0 decimals of accuracy
[13:47:00][D][sensor:093]: 'Particulate Matter ≥10.0μm Count': Sending state 0.00000 /dL with 0 decimals of accuracy
[13:47:00][D][aqi.sensor:119]: Publishing max AQI 0 from sensor #1
[13:47:00][D][sensor:093]: 'AQI': Sending state 0.00000  with 0 decimals of accuracy

On 2024.5.0 the last 2 lines are not printed, yet the value will still publish to Home Assistant.

Additional information

Hardware is a home-made open source air quality sensor (HAKS) using this firmware.

z3liff commented 3 months ago

I can confirm the exact same behavior as detailed above.

DAVe3283 commented 2 months ago

Took some time to dig into this and I have some better info. I did verify that this only occurs on ESPHome 2024.5.0 or newer (most of my testing is on the dev branch).

Rebooting does NOT change the behavior as I initially thought. It is perfectly repeatable on a given firmware, either always working, or never working. The frequent rebooting was causing Home Assistant to get the initial bootup "Unknown" value, but it appears the value publishes exactly as it should if I let it run long enough.

The actual bug experienced appears to be the main loop() function of the custom component will run and work perfectly, but log messages will not output.

UNLESS... I add a delay to the function, anywhere. A delay (1) has no effect, and the log messages from the loop function don't print. However, a delay(30) causes the log messages to work as expected.

I was able to compile the firmware back-to-back with only that change, flashing back and forth between the 2, and verify the log messages only print with the delay of 30 ms.

Binary difference between working and non-working firmware:

The key value here is at offset 13B98. Per Ghidra, they both disassemble to movi.n (narrow move immediate) with the operand 0x1 (1 decimal) or 0x1e (30 decimal), indicating the only real change is the function parameter to delay(), as expected: I believe the remaining 2 differences are simply checksums (but if anyone knows for sure I would love to learn).

This strongly implies a bug in the logger, network code, or some other part of the ESPHome core. Simply changing the parameter passed to delay() should have absolutely no effect on if log messages print or not.

I do not know enough about the ESPHome core to debug further than this. This might be something @jesserockz or @bdraco need to look at. I would be happy to provide full source code or whatever I can to help, but I have exhausted my skill/knowledge at this point.

DAVe3283 commented 2 months ago

Flashed one of my ESP8266 devices to 2024.6.1 and this issue is not present, at least on the one device. I'll update a few more when I get a chance and see if they are also fixed.

esphome / issues