How could logging cause an apparent hardware issue

While working on a way to temporarily disable deep sleep on this weight sensor I suddenly began experiencing what appeared to be a hardware issue. The device wouldn’t boot (apparently) with the data & clock lines attached for the hx711. I tried different ESPs, including a new hx711 breakout and it always did the same thing. If I disconnected the data & clock lines it would boot fine but as soon as the hx711 became available it would freeze. I’m guessing it appeared to not boot when it was connected from the start because as soon as it got a value it would hang.

Since swapping essentially all the hardware did nothing I started to look at the code and just eliminate things that weren’t critical. I had most recently added the two sections to log the actual state of the prevent_deep_sleep helper because I wanted to be sure it was coming through. I didn’t immediately connect that addition with the new issue so it was a while before I considered removing it.

But, sure enough, that was it. Removing those three lines from the two sections brought the thing back to life. So, I’m really curious what was going on that would make the ESP hang when it go to that part in the code. The code compiled just fine.

mqtt:
  broker: mqtt

deep_sleep:
  id: deep_sleep_1
  run_duration: 90s
  sleep_duration: 360min
    
# Example configuration entry
sensor:
  - platform: hx711
    name: "Tank Weight"
    dout_pin: GPIO5
    clk_pin: GPIO4
    gain: 128
    update_interval: 1s
    filters:
      - sliding_window_moving_average: 
          window_size: 10
          send_every: 10
      - calibrate_linear:
          - 240400 -> 0
          - 282580 -> 60
    unit_of_measurement: oz
    on_value:
      - then:
          mqtt.publish: 
            topic: sensor/co2_tank_weight
            payload: !lambda "return to_string(x);"
      - then:
          if:
            condition:
              binary_sensor.is_on: prevent_deep_sleep
            then:
              - logger.log: 'Disabling sleep, per prevent_deep_sleep'
              - logger.log:    # This was the problem.. and the next two lines
                  format: 'Prevent Deep Sleep is: %s '
                  args: [id(prevent_deep_sleep).state]
              - deep_sleep.prevent: deep_sleep_1
            else:
              - logger.log: 'Sleep is allowed'
              - logger.log:  # This was the problem.. and the next two lines
                  format: 'Prevent Deep Sleep is: %s'
                  args: [id(prevent_deep_sleep).state]
              - deep_sleep.allow: deep_sleep_1
        #- deep_sleep.enter:
        #    id: deep_sleep_1
        #    sleep_duration: 5min     

binary_sensor:
  - platform: homeassistant
    id: prevent_deep_sleep
    name: Prevent Deep Sleep
    entity_id: input_boolean.prevent_deep_sleep

I am not sure on how quotation marks work in every situation in YAML, but the example in the docs have it like this:

                  format: "Prevent Deep Sleep is: %s"
                  args: ['id(prevent_deep_sleep).state']

Thanks for that. Testing on my backup hardware, changing to " in the format and wrapping the args with ’ did not have an impact. :frowning: Hangs in the same spot.

It is just a “uneducated” guess, so do not expect too much. :wink:

1 Like

Is it possible there’s a circular dependency? If I start with the data line detached it says waiting for hx711 to become ready. Once it is attached, it hangs, but it should be jumping into the on value section. If the prevent deep sleep isn’t yet initialized, maybe that call to get the state is also hanging waiting for it to initialize… and it never does because it gets stuck before it does.

Could reordering the prevent deep sleep binary sensor section before the sensor actually change something?

Maybe it is not a circular dependency, but rather a timing issue.
Your automation is running each second and the sensor is probably faster to get its value than it is to get values from HA, so the prevent_deep_sleep might not be set in the first run.
I am not sure if it is possible but try to set a default value until it is pulled from HA or add a long delay to your automation to see if that enables the ESP to get the value from HA and continue.

Timing may be it. I moved the toggling of deep sleep into the on_state event of the binary sensor. It boots fine, even with the logging still intact. What I don’t see is the state of that binary sensor ever coming up. My guess is that it takes longer to set up than the system is up before sleep is triggered… testing a longer runtime now.

5 minutes seems like plenty of time. I didn’t wait longer but I’m pretty sure this binary sensor just isn’t working at all. I reduced that section to the below and the sensor never seems to connect with homeassistant at all. Toggling it in the UI has no impact on the logs of the ESP. :confused:

This has worked in the past… not sure what changed. I tried making the id and the entity_id more unique just in case they were colliding somehow.

binary_sensor:
  - platform: homeassistant
    id: my_prevent_deep_sleep
    name: Prevent Deep Sleep
    entity_id: input_boolean.prevent_deep_sleep

OK - my flashing of different ESPs with the same “device” seems to have gotten the API keys out of sync or something. I deleted and re-added it and things are a little better. Will revert my changes to see if that was the actual issue.

Binary Sensor is now working as intended, without the format/args logging. I re-added that to the binary senor on_state event and it appears to be resatrting when I toggle it?? Is there something just inherently wrong with that logging method?

binary_sensor:
  - platform: homeassistant
    id: my_prevent_deep_sleep
    name: Prevent Deep Sleep
    entity_id: input_boolean.prevent_deep_sleep
    on_state: 
      then:
        if:
          condition:
            binary_sensor.is_on: my_prevent_deep_sleep
          then:
            - logger.log: 'Disabling sleep, per prevent_deep_sleep'
            - logger.log:
               format: "Prevent Deep Sleep is: %s"
               args: ['id(my_prevent_deep_sleep).state']
            - deep_sleep.prevent: deep_sleep_1
          else:
            - logger.log: 'Sleep is allowed'
            - logger.log:
                format: "Prevent Deep Sleep is: %s"
                args: ['id(my_prevent_deep_sleep).state']
            - deep_sleep.allow: deep_sleep_1     

Logs…

[16:01:21][D][hx711:031]: 'Tank Weight': Got value 1239
[16:01:26][D][hx711:031]: 'Tank Weight': Got value 1258
[16:01:26][D][homeassistant.binary_sensor:026]: 'input_boolean.prevent_deep_sleep': Got state ON
WARNING co2-tank-scale @ 192.168.10.98: Connection error occurred: [Errno 104] Connection reset by peer
INFO Processing unexpected disconnect from ESPHome API for co2-tank-scale @ 192.168.10.98
WARNING Disconnected from API
INFO Successfully connected to co2-tank-scale @ 192.168.10.98 in 0.003s
INFO Successful handshake with co2-tank-scale @ 192.168.10.98 in 2.607s
[16:01:51][D][hx711:031]: 'Tank Weight': Got value 1249
[16:01:56][D][hx711:031]: 'Tank Weight': Got value 1257
[16:02:01][D][api:102]: Accepted 10.1.100.94
[16:02:01][W][component:237]: Component api took a long time for an operation (288 ms).
[16:02:01][W][component:238]: Components should block for at most 30 ms.
[16:02:01][D][hx711:031]: 'Tank Weight': Got value 1262
[16:02:02][D][api.connection:1375]: ESPHome Logs 2024.7.3 (10.1.100.94): Connected successfully
[16:02:06][D][hx711:031]: 'Tank Weight': Got value 1257
[16:02:09][D][homeassistant.binary_sensor:026]: 'input_boolean.prevent_deep_sleep': Got state ON
WARNING co2-tank-scale @ 192.168.10.98: Connection error occurred: [Errno 104] Connection reset by peer
INFO Processing unexpected disconnect from ESPHome API for co2-tank-scale @ 192.168.10.98
WARNING Disconnected from API
INFO Successfully connected to co2-tank-scale @ 192.168.10.98 in 0.003s
INFO Successful handshake with co2-tank-scale @ 192.168.10.98 in 2.377s
[16:02:34][D][hx711:031]: 'Tank Weight': Got value 1248

Solved. Good grief this seems like it should get caught by the compiler but I’m sure there’s a reason why not (maybe?)

prevent_deep_sleep is a bool. My format was %s (string) - I was hoping for True/False or Off/On. I tried adding c_str() to the end of state to convert and that failed to compile. I tried using %B which is apparently a newer format string option but it also didn’t compile. So I just used %d and it all works as intended, just returns 0 or 1.

EDIT: More info since this isn’t documented anywhere… There are three macros that would also be great to know in this instance. ONOFF(), TRUEFALSE(), and YESNO()

When you wrap your state with those, it will return a string according to the boolean value 0/1. Then you can use the %s without a runtime exception.

[16:16:22][D][api.connection:1375]: Home Assistant 2024.8.2 (192.168.10.63): Connected successfully
[16:16:23][D][homeassistant.binary_sensor:026]: 'input_boolean.prevent_deep_sleep': Got state OFF
[16:16:23][D][binary_sensor:034]: 'Prevent Deep Sleep': Sending initial state OFF
[16:16:24][D][hx711:031]: 'Tank Weight': Got value 1258
[16:16:27][D][homeassistant.binary_sensor:026]: 'input_boolean.prevent_deep_sleep': Got state ON
[16:16:27][D][binary_sensor:036]: 'Prevent Deep Sleep': Sending state ON
[16:16:27][D][main:336]: Disabling sleep, per prevent_deep_sleep
[16:16:27][D][main:339]: Prevent Deep Sleep is: 1
[16:16:29][D][hx711:031]: 'Tank Weight': Got value 1240
[16:16:34][D][hx711:031]: 'Tank Weight': Got value 1249