Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Plug becomes "unavailable" a few times a day #9

Open
wilsongoode opened this issue Nov 22, 2022 · 56 comments
Open

Plug becomes "unavailable" a few times a day #9

wilsongoode opened this issue Nov 22, 2022 · 56 comments

Comments

@wilsongoode
Copy link

I bought a 4-pack of these plugs and adopted them all with ESPHome Dashboard running in Docker on my Raspberry Pi. Home Assistant is running in another Docker container on the same Pi.

After resolving some initial struggles getting used to ESPHome and configuring the an appropriate 2.4GHz network at one end of my house for one plug, they have been working very responsively with two exceptions. Two of the plugs will occasionally show up as "Unavailable" in Home Assistant, leading to them being unable to be controlled through Home Assistant (or via automations). Sometimes they will resolve themselves after a few minutes, sometimes they will be "unavailable" until I physically remove them from the outlet and plug them back in, rebooting them. When they are "unavailable" in Home Assistant, they are also not available at their own web server.

Is this an issue that others have experienced?

What steps can I take to debug this issue on my end or potentially resolve it?

Thanks,
Wilson

@bkaufx
Copy link

bkaufx commented Nov 23, 2022

Just a few thoughts for debugging:

  • maybe add a wifi signal strength sensor and see if there are any issues showing there: https://esphome.io/components/sensor/wifi_signal.html
  • leave logs open in the dashboard for a while and see if you can catch it saying anything interesting right before going unavailable.
  • check the uptime after it comes back from going unavailable on its own and see if the uptime reset.

I haven't heard other complaints like this really. I can send a couple replacements if you email brian@kaufha.com.

@epelz
Copy link

epelz commented Dec 11, 2022

I'm also seeing this behavior, though the plug always resolves itself (by restarting). It's somewhat inconsistent in frequency - sometimes every 10-15 minutes, sometimes every few hours.

I was able to capture logs in the dashboard right before it went unavailable. Looks like there's some kind of memory issue or leak, so after some time the device restarts.

[09:04:16][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 118.76974 V with 1 decimals of accuracy
[09:04:26][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:04:26][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:04:26][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:04:26][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 117.56132 V with 1 decimals of accuracy
[09:04:26][E][json:034]: Could not allocate memory for JSON document! Requested 416 bytes, largest free heap block: 416 bytes
[09:04:36][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:04:36][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:04:36][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:04:36][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 118.33532 V with 1 decimals of accuracy
[09:04:46][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:04:46][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:04:46][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:04:46][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 118.33532 V with 1 decimals of accuracy
[09:04:56][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:04:56][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:04:56][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:04:56][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 117.90408 V with 1 decimals of accuracy
[09:04:56][E][json:034]: Could not allocate memory for JSON document! Requested 272 bytes, largest free heap block: 272 bytes
[09:04:56][D][sensor:126]: 'Cat Food Feeder Uptime': Sending state 2328.90088 s with 0 decimals of accuracy
[09:05:06][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:05:06][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:05:06][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:05:06][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 117.90408 V with 1 decimals of accuracy
[09:05:16][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:05:16][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:05:16][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:05:16][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 117.64682 V with 1 decimals of accuracy
[09:05:26][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:05:26][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:05:26][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:05:26][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 117.90408 V with 1 decimals of accuracy
[09:05:26][E][json:034]: Could not allocate memory for JSON document! Requested 272 bytes, largest free heap block: 272 bytes
[09:05:36][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:05:36][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:05:36][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:05:36][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 118.33532 V with 1 decimals of accuracy
[09:05:36][E][json:034]: Could not allocate memory for JSON document! Requested 272 bytes, largest free heap block: 272 bytes
[09:05:46][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:05:46][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:05:46][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:05:46][E][json:034]: Could not allocate memory for JSON document! Requested 416 bytes, largest free heap block: 416 bytes
[09:05:46][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 118.33532 V with 1 decimals of accuracy
[09:05:56][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:05:56][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:05:56][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:05:56][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 117.99006 V with 1 decimals of accuracy
[09:05:56][E][json:034]: Could not allocate memory for JSON document! Requested 328 bytes, largest free heap block: 328 bytes
[09:05:56][D][sensor:126]: 'Cat Food Feeder Uptime': Sending state 2388.90210 s with 0 decimals of accuracy
[09:06:06][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:06:06][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:06:06][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:06:06][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 117.90408 V with 1 decimals of accuracy
[09:06:06][E][json:034]: Could not allocate memory for JSON document! Requested 272 bytes, largest free heap block: 272 bytes
[09:06:16][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:06:16][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:06:16][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:06:16][E][json:034]: Could not allocate memory for JSON document! Requested 352 bytes, largest free heap block: 352 bytes
[09:06:16][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 117.90408 V with 1 decimals of accuracy
[09:06:16][E][json:034]: Could not allocate memory for JSON document! Requested 184 bytes, largest free heap block: 184 bytes
[09:06:26][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:06:26][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:06:26][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:06:26][E][json:034]: Could not allocate memory for JSON document! Requested 312 bytes, largest free heap block: 312 bytes
[09:06:26][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 117.90408 V with 1 decimals of accuracy
[09:06:36][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:06:36][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:06:36][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:06:36][E][json:034]: Could not allocate memory for JSON document! Requested 432 bytes, largest free heap block: 432 bytes
[09:06:36][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 117.56132 V with 1 decimals of accuracy
[09:06:36][E][json:034]: Could not allocate memory for JSON document! Requested 280 bytes, largest free heap block: 280 bytes
[09:06:46][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
INFO 192.168.20.37: Ping timed out!
INFO Disconnected from ESPHome API for 192.168.20.37
WARNING Disconnected from API
INFO Successfully connected to 192.168.20.37
[09:07:10][D][light:035]: 'Cat Food Feeder Blue LED' Setting:
[09:07:10][D][light:035]: 'Cat Food Feeder Red LED' Setting:
[09:07:12][D][api:102]: Accepted 192.168.10.200
[09:07:12][D][api.connection:917]: Home Assistant 2022.12.0 (192.168.10.200): Connected successfully
[09:07:12][D][time:044]: Synchronized time: 2022-12-11 09:07:12

Here's my ESPHome configuration. I'm running the latest version of kauf-plug.yaml (compiled this morning)

substitutions:
  name: "kauf-cat-food"
  friendly_name: Cat Food Feeder
packages:
  Kauf.PLF10: github://KaufHA/PLF10/kauf-plug.yaml
esphome:
  name: ${name}
  name_add_mac_suffix: false


wifi:
  ssid: !secret wifi_ssid
  password: !secret wifi_password
  manual_ip: <...>

time:
  - platform: homeassistant
    on_time:
      - seconds: 0
        minutes: 0
        hours: 07
        then:
          - if:
              condition:
                switch.is_on: relay
              then:
                - switch.turn_off: relay
                - delay: 5min
          - switch.turn_on: relay
          - delay: 5min
          - switch.turn_off: relay

Does this seem like an issue with my specific plug, or something to debug on my end with ESPHome?

@bkaufx
Copy link

bkaufx commented Dec 11, 2022

Can you add debug sensors in your local yaml and see if you can see free heap memory slowly reducing over time? Could be a memory leak I guess. I haven't seen this reported as a widespread problem so not sure if there is global issue or just you.

The example config entry here should work:
https://esphome.io/components/debug.html

@bkaufx
Copy link

bkaufx commented Dec 11, 2022

After you add debug, it should show some debug info on boot as well. Let me know what that says. Edit: after it crashes not after you just update the yaml and it reboots to update.

@bkaufx
Copy link

bkaufx commented Dec 11, 2022

I have a plug running your exact yaml with the debug info added, so I'll let you know what I see. It's on a unit connected to serial logging as well so I may get more info that way.

@epelz
Copy link

epelz commented Dec 11, 2022

Thank you for the quick help on this!

Well, this isn't what I expected to see:

Looks like free heap memory is not reducing over time.
image
(I jumped too soon to a memory leak)

Within ~10 minutes I hit another crash. Here's the boot log:

[09:55:47][D][sensor:126]: 'Heap Free': Sending state 7416.00000 B with 0 decimals of accuracy
[09:55:47][D][sensor:126]: 'Heap Max Block': Sending state 3264.00000 B with 0 decimals of accuracy
[09:55:47][D][sensor:126]: 'Heap Fragmentation': Sending state 42.00000 % with 1 decimals of accuracy
[09:55:47][D][sensor:126]: 'Loop Time': Sending state 38.00000 ms with 0 decimals of accuracy
[09:55:48][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:55:49][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:55:49][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:55:49][E][json:034]: Could not allocate memory for JSON document! Requested 344 bytes, largest free heap block: 344 bytes
[09:55:49][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 118.33532 V with 1 decimals of accuracy
[09:55:49][E][json:034]: Could not allocate memory for JSON document! Requested 344 bytes, largest free heap block: 344 bytes
[09:55:52][D][sensor:126]: 'Heap Free': Sending state 7096.00000 B with 0 decimals of accuracy
INFO 192.168.20.37: Ping timed out!
INFO Disconnected from ESPHome API for 192.168.20.37
WARNING Disconnected from API
INFO Successfully connected to 192.168.20.37
[09:56:13][C][template.select:072]: Template Select 'Cat Food Feeder Boot State'
[09:56:13][C][template.select:072]:   Icon: 'mdi:restart-alert'
[09:56:13][C][template.select:073]:   Update Interval: 60.0s
[09:56:13][C][template.select:076]:   Optimistic: YES
[09:56:13][C][template.select:077]:   Initial Option: Restore Power Off State
[09:56:13][C][template.select:078]:   Restore Value: YES
[09:56:13][C][gpio.binary_sensor:015]: GPIO Binary Sensor 'Cat Food Feeder Button'
[09:56:13][C][gpio.binary_sensor:016]:   Pin: GPIO13
[09:56:13][C][switch.gpio:088]: GPIO Switch 'Cat Food Feeder'
[09:56:13][C][switch.gpio:110]:   Restore Mode: restore defaults to OFF
[09:56:13][C][switch.gpio:034]:   Pin: GPIO4
[09:56:13][C][template.switch:088]: Template Switch 'Cat Food Feeder No HASS'
[09:56:13][C][template.switch:090]:   Icon: 'mdi:toggle-switch-off-outline'
[09:56:13][C][template.switch:110]:   Restore Mode: restore defaults to OFF
[09:56:13][C][template.switch:059]:   Restore State: YES
[09:56:13][C][template.switch:060]:   Optimistic: YES
[09:56:13][C][light:118]: Light 'Cat Food Feeder Blue LED'
[09:56:13][C][light:120]:   Default Transition Length: 0.0s
[09:56:13][C][light:121]:   Gamma Correct: 2.80
[09:56:13][D][light:035]: 'Cat Food Feeder Blue LED' Setting:
[09:56:13][D][light:035]: 'Cat Food Feeder Red LED' Setting:
[09:56:13][C][light:118]: Light 'Cat Food Feeder Red LED'
[09:56:13][C][light:120]:   Default Transition Length: 0.0s
[09:56:13][C][light:121]:   Gamma Correct: 2.80
[09:56:13][C][restart.button:017]: Restart Button 'Cat Food Feeder Restart Firmware'
[09:56:13][C][homeassistant.time:010]: Home Assistant Time:
[09:56:13][C][homeassistant.time:011]:   Timezone: 'PST8PDT,M3.2.0,M11.1.0'
[09:56:13][C][homeassistant.time:010]: Home Assistant Time:
[09:56:13][C][homeassistant.time:011]:   Timezone: 'PST8PDT,M3.2.0,M11.1.0'
[09:56:13][C][kauf_hlw8012:058]: Kauf HLW8012:
[09:56:13][C][kauf_hlw8012:059]:   SEL Pin: GPIO12
[09:56:13][C][kauf_hlw8012:060]:   CF Pin: GPIO5
[09:56:13][C][kauf_hlw8012:061]:   CF1 Pin: GPIO14
[09:56:13][C][kauf_hlw8012:062]:   Current resistor: 1.0 mΩ
[09:56:13][C][kauf_hlw8012:063]:   Voltage Divider: 2401.0
[09:56:13][C][kauf_hlw8012:064]:   Update Interval: 10.0s
[09:56:13][C][kauf_hlw8012:065]:   Voltage 'Cat Food Feeder Voltage'
[09:56:13][C][kauf_hlw8012:065]:     Device Class: 'voltage'
[09:56:13][C][kauf_hlw8012:065]:     State Class: 'measurement'
[09:56:13][C][kauf_hlw8012:065]:     Unit of Measurement: 'V'
[09:56:13][C][kauf_hlw8012:065]:     Accuracy Decimals: 1
[09:56:13][C][kauf_hlw8012:066]:   Current 'Cat Food Feeder Current'
[09:56:13][C][kauf_hlw8012:066]:     Device Class: 'current'
[09:56:13][C][kauf_hlw8012:066]:     State Class: 'measurement'
[09:56:13][C][kauf_hlw8012:066]:     Unit of Measurement: 'A'
[09:56:13][C][kauf_hlw8012:066]:     Accuracy Decimals: 2
[09:56:13][C][kauf_hlw8012:067]:   Power 'Cat Food Feeder Power'
[09:56:13][C][kauf_hlw8012:067]:     Device Class: 'power'
[09:56:13][C][kauf_hlw8012:067]:     State Class: 'measurement'
[09:56:13][C][kauf_hlw8012:067]:     Unit of Measurement: 'W'
[09:56:13][C][kauf_hlw8012:067]:     Accuracy Decimals: 1
[09:56:13][C][total_daily_energy:030]: Total Daily Energy 'Cat Food Feeder Total Daily Energy'
[09:56:13][C][total_daily_energy:030]:   Device Class: 'energy'
[09:56:13][C][total_daily_energy:030]:   State Class: 'total_increasing'
[09:56:13][C][total_daily_energy:030]:   Unit of Measurement: 'kWh'
[09:56:13][C][total_daily_energy:030]:   Accuracy Decimals: 3
[09:56:13][C][captive_portal:114]: Captive Portal:
[09:56:13][C][web_server:162]: Web Server:
[09:56:13][C][web_server:163]:   Address: 192.168.20.37:80
[09:56:13][C][mdns:103]: mDNS:
[09:56:13][C][mdns:104]:   Hostname: kauf-cat-food
[09:56:13][C][ota:095]: Over-The-Air Updates:
[09:56:13][C][ota:096]:   Address: 192.168.20.37:8266
[09:56:13][C][api:138]: API Server:
[09:56:13][C][api:139]:   Address: 192.168.20.37:6053
[09:56:13][C][api:143]:   Using noise encryption: NO
[09:56:13][C][wifi_info:009]: WifiInfo IPAddress 'Cat Food Feeder IP Address'
[09:56:13][C][debug:049]: Debug component:
[09:56:14][C][debug:051]:   Device info 'Device Info'
[09:56:14][C][debug:054]:   Free space on heap 'Heap Free'
[09:56:14][C][debug:054]:     State Class: ''
[09:56:14][C][debug:054]:     Unit of Measurement: 'B'
[09:56:14][C][debug:054]:     Accuracy Decimals: 0
[09:56:14][C][debug:054]:     Icon: 'mdi:counter'
[09:56:14][C][debug:055]:   Largest free heap block 'Heap Max Block'
[09:56:14][C][debug:055]:     State Class: ''
[09:56:14][C][debug:055]:     Unit of Measurement: 'B'
[09:56:14][C][debug:055]:     Accuracy Decimals: 0
[09:56:14][C][debug:055]:     Icon: 'mdi:counter'
[09:56:14][C][debug:057]:   Heap fragmentation 'Heap Fragmentation'
[09:56:14][C][debug:057]:     State Class: ''
[09:56:14][C][debug:057]:     Unit of Measurement: '%'
[09:56:14][C][debug:057]:     Accuracy Decimals: 1
[09:56:14][C][debug:057]:     Icon: 'mdi:counter'
[09:56:14][D][debug:061]: ESPHome version 2022.11.5
[09:56:14][D][debug:065]: Free Heap Size: 7240 bytes
[09:56:14][D][debug:093]: Flash Chip: Size=1024kB Speed=40MHz Mode=DOUT
[09:56:14][D][debug:250]: Chip ID: 0x000A1366
[09:56:14][D][debug:251]: SDK Version: 2.2.2-dev(38a443e)
[09:56:14][D][debug:252]: Core Version: 3.0.2
[09:56:14][D][debug:253]: Boot Version=31 Mode=1
[09:56:14][D][debug:254]: CPU Frequency: 80
[09:56:14][D][debug:255]: Flash Chip ID=0x0014605E
[09:56:14][D][debug:256]: Reset Reason: Exception
[09:56:14][D][debug:257]: Reset Info: Fatal exception:29 flag:2 (Exception) epc1:0x4000df64 epc2:0x00000000 epc3:0x00000000 excvaddr:0x00000000 depc:0x00000000
[09:56:14][D][text_sensor:067]: 'Device Info': Sending state '2022.11.5|Flash: 1024kB Speed:40MHz Mode:DOUT|Chip: 0x000a1366|SDK: 2.2.2-dev(38a443e)|Core: 3.0.2|Boot: 31|Mode: 1|CPU: 80|Flash: 0x0014605e|Reset: Exception|Fatal exception:29 flag:2 (Exception) epc1:0x4000df64 epc2:0x00000000 epc3:0x00000000 excvaddr:0'
[09:56:14][D][sensor:126]: 'Heap Free': Sending state 9792.00000 B with 0 decimals of accuracy
[09:56:14][D][sensor:126]: 'Heap Max Block': Sending state 6896.00000 B with 0 decimals of accuracy
[09:56:14][D][sensor:126]: 'Heap Fragmentation': Sending state 19.00000 % with 1 decimals of accuracy
[09:56:14][D][sensor:126]: 'Loop Time': Sending state 18496.00000 ms with 0 decimals of accuracy
[09:56:18][D][api:102]: Accepted 192.168.10.200
[09:56:18][D][api.connection:917]: Home Assistant 2022.12.0 (192.168.10.200): Connected successfully
[09:56:18][D][time:044]: Synchronized time: 2022-12-11 09:56:18
[09:56:19][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[09:56:19][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00001 kWh with 3 decimals of accuracy
[09:56:19][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[09:56:19][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 118.33532 V with 1 decimals of accuracy
[09:56:19][D][debug:289]: Free Heap Size: 1920 bytes
[09:56:19][D][sensor:126]: 'Heap Free': Sending state 8000.00000 B with 0 decimals of accuracy
[09:56:19][D][sensor:126]: 'Heap Max Block': Sending state 4016.00000 B with 0 decimals of accuracy
[09:56:19][D][sensor:126]: 'Heap Fragmentation': Sending state 41.00000 % with 1 decimals of accuracy
[09:56:19][D][sensor:126]: 'Loop Time': Sending state 52.00000 ms with 0 decimals of accuracy
[09:56:24][D][sensor:126]: 'Heap Free': Sending state 7560.00000 B with 0 decimals of accuracy
[09:56:24][D][sensor:126]: 'Heap Max Block': Sending state 3512.00000 B with 0 decimals of accuracy
[09:56:24][D][sensor:126]: 'Heap Fragmentation': Sending state 54.00000 % with 1 decimals of accuracy
[09:56:24][E][json:034]: Could not allocate memory for JSON document! Requested 360 bytes, largest free heap block: 360 bytes

The fatal exception seems interesting. I'm new to ESP, but it seems like it's trying to write to protected memory:
https://stackoverflow.com/questions/34483956/esp8266-exception-29

Also, immediately after restarting, it starts hitting the "could not allocate memory" issue. Anecdotally I'm seeing these statements even more often now after adding the debug logging. I don't remember seeing this a day or two ago (upon first boot or a while after).
Edit: Interestingly, right after boot, it was hitting this error. But ~15 min later (with no restart), it no longer seems to be hitting that issue. So it's not continuous.

(I'm new to ESPHome, so hoping I'm not just doing something wrong here. I'm wondering why this seems to be increasing in frequency. Is there some kind of device-level storage I need to clear out (because of multiple OTA updates)? Or does this point to something outside of the ESPHome software side?)

@bkaufx
Copy link

bkaufx commented Dec 11, 2022

My heap size was super stable for about an hour. Looking into the JSON messages, it seems like something that only happens when the web server on the plug is accessed, so I tried doing that and the plug crashed with out of memory error.

[12:35:47][D][sensor:126]: 'Heap Fragmentation': Sending state 18.00000 % with 1 decimals of accuracy
[12:35:47][D][sensor:126]: 'Loop Time': Sending state 43.00000 ms with 0 decimals of accuracy
[12:35:47][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[12:35:47][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00000 kWh with 3 decimals of accuracy
[12:35:47][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[12:35:47][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 123.29601 V with 1 decimals of accuracy
[12:35:52][D][sensor:126]: 'Heap Free': Sending state 9224.00000 B with 0 decimals of accuracy
[12:35:52][D][sensor:126]: 'Heap Max Block': Sending state 4704.00000 B with 0 decimals of accuracy
[12:35:52][D][sensor:126]: 'Heap Fragmentation': Sending state 18.00000 % with 1 decimals of accuracy
[12:35:52][D][sensor:126]: 'Loop Time': Sending state 51.00000 ms with 0 decimals of accuracy
[12:35:57][D][sensor:126]: 'Heap Free': Sending state 9224.00000 B with 0 decimals of accuracy
[12:35:57][D][sensor:126]: 'Heap Max Block': Sending state 4704.00000 B with 0 decimals of accuracy
[12:35:57][D][sensor:126]: 'Heap Fragmentation': Sending state 18.00000 % with 1 decimals of accuracy
[12:35:57][D][sensor:126]: 'Loop Time': Sending state 43.00000 ms with 0 decimals of accuracy
[12:35:57][D][sensor:126]: 'Cat Food Feeder Power': Sending state 0.00000 W with 1 decimals of accuracy
[12:35:57][D][sensor:126]: 'Cat Food Feeder Total Daily Energy': Sending state 0.00000 kWh with 3 decimals of accuracy
[12:35:57][D][sensor:126]: 'Cat Food Feeder Current': Sending state 0.00000 A with 2 decimals of accuracy
[12:35:57][D][sensor:126]: 'Cat Food Feeder Voltage': Sending state 122.82793 V with 1 decimals of accuracy
[12:36:01][E][json:034]: Could not allocate memory for JSON document! Requested 184 bytes, largest free heap block: 184 bytes
[12:36:01][D][debug:289]: Free Heap Size: 888 bytes
[12:36:01][E][json:034]: Could not allocate memory for JSON document! Requested 248 bytes, largest free heap block: 248 bytes
[12:36:01][D][debug:289]: Free Heap Size: 360 bytes
[12:36:01][E][json:034]: Could not allocate memory for JSON document! Requested 120 bytes, largest free heap block: 120 bytes
[12:36:01]
[12:36:01]User exception (panic/abort/assert)
[12:36:01]--------------- CUT HERE FOR EXCEPTION DECODER ---------------
[12:36:01]
[12:36:01]Unhandled C++ exception: OOM
[12:36:01]
[12:36:01]>>>stack>>>
←[33mWARNING Found stack trace! Trying to decode it←[0m
[12:36:01]

@bkaufx
Copy link

bkaufx commented Dec 11, 2022

Here's where the JSON messages come from:
https://github.com/esphome/esphome/blob/dev/esphome/components/json/json_util.cpp

And that gets called from:
Stock ESPHome: https://github.com/esphome/esphome/blob/dev/esphome/components/web_server/web_server.cpp
KAUF version: https://github.com/KaufHA/common/blob/main/components/web_server/web_server.cpp

The weird thing is why this would be randomly happening on your plug. Are you using the HTTP API?

@epelz
Copy link

epelz commented Dec 11, 2022

Ah, that would explain why this is happening more frequently this morning (since I was accessing the web server). I'm not using the HTTP API - just Home Assistant.

Strangely, the past two nights the plug restarted multiple times, hours after I stopped using my computer. It's possible I left a browser open that caused it. I can monitor again tonight and see if it reproduces. Maybe the heap allocation is a red herring? I'll keep on the debug sensors, and also add the wifi sensors you mentioned above, in case this is actually network related.

Thanks for your help! I'll update again if I learn anything new.

@epelz
Copy link

epelz commented Dec 13, 2022

Okay, an update from today:

Good news: it didn't crash as early! This is probably because I didn't continually checking the web interface. It lasted over 24 hours before crashing.

However, then it crashed a few times in a row, starting a few hours ago. Every time had the same reason in the "device info" logged to home assistant:

2022.11.5|Flash: 1024kB Speed:40MHz Mode:DOUT|Chip: 0x000a1366|SDK: 2.2.2-dev(38a443e)|Core: 3.0.2|Boot: 31|Mode: 1|CPU: 80|Flash: 0x0014605e|Reset: Software Watchdog|Fatal exception:4 flag:3 (Software Watchdog) epc1:0x4026b4fa epc2:0x00000000 epc3:0x0000

I don't see anything interesting in the heap, heap free, heap fragmentation, or wifi stats logged to home assistant. "Loop time" seems to spike to 18000ms right before one of the crashes.

Any idea what could be happening?
(I'll keep doing some research into this error code, in case it's something on my side. Edit: I'll try increasing the reboot_timeout to see if it's network related.)

@bkaufx
Copy link

bkaufx commented Dec 14, 2022

From what I'm seeing, this really seems to be an issue with the web server / json. I may just have so many entities and other info being sent it's reaching the limits of the heap. I'm going to have to do some debugging within the web_server and json components to see what's happening in there in more detail.

When I ran using a more stock yaml, the plug was super stable with the web server open and refreshing, but it crashed pretty quick when I opened up the web server in two tabs at once and refreshed.

Let me know what you see separate from the web server / json stuff. You indicated you were seeing this when you weren't using the web server, so if a cause can be narrowed down that would be helpful.

In the meantime you might try using the minimal yaml instead of the normal one. Let me know if you need help replicating the settings.

https://github.com/KaufHA/PLF10/blob/main/kauf-plug-minimal.yaml

@bkaufx
Copy link

bkaufx commented Dec 14, 2022

Another idea instead of switching to the minimal yaml would be to disable the webserver by setting a substitution disable_webserver: "true". That should keep the webserver from setting up and creating that crazy json structure I'm sending. The webserver will be disabled in that case. Be interesting to see how stable the plug is with the webserver disabled in this way.

Edited to add quotes around true in substitution.

@epelz
Copy link

epelz commented Dec 15, 2022

Thanks for the continued help on this!

Since my last comment, I made a few changes:

  • Disabled the webserver
  • Increased reboot_timeout to 30m (on both the HA API and Wifi components)
  • Switched back to using DHCP, rather than passing a static_ip

So far, it seems like one of these changes did the trick! I'm at over 46 hours of uptime so far (no crashes).

I'm hopeful this means I'm all set! I don't actually need the webserver enabled, the HA controls are more than sufficient for me. Happy to try to debug further if it's helpful, though.

@bkaufx
Copy link

bkaufx commented Dec 15, 2022

Thanks for the info. I'm sure the issue is the web server. Keep me posted if you learn anything else.

@birdwing
Copy link

Yeah I just got the plug I. Yesterday, it's my first esphome device and I am super excited😁
I am seeing this same thing with the plug becoming randomly unavailable in home assistant.

The device website takes forever to load after a restart, once it does become responsive. I have a static IP set on the device along with a DHCP reservation.

I will turn off the webserver and report back in a little bit. It was happening every few hours to every few minutes.

The longer the device is on the shorter time exists between crashes.

@birdwing
Copy link

Just putting this here in case anyone else runs into the same issue I just did. After adding the disabled web server substitution, and attempting to upload it through ESP home, it kept failing on the upload due to a timeout error. Apparently the plug was disconnecting from the Wi-Fi so often at that point that I couldn't even upload the newly compiled firmware. Unplugging and plugging the device back into restart it fix that issue.

I now have the web server disabled and I will report back whether or not that is fixed. The issue with it timing out 👍

@birdwing
Copy link

birdwing commented Dec 15, 2022

Well this response was sooner than expected...
The device is still becoming unavailable every couple of minutes, even right after restarting it after the new firmware change was made to disable the web server, I will try and see if I can get some log output at some point tomorrow so it can be easier to diagnose.

@bkaufx
Copy link

bkaufx commented Dec 15, 2022

Thanks for the info and any logs you can provide would definitely be helpful.

Can you completely remove the webserver and see if that helps?

Edited to add what I would recommend you do to remove the webserver component completely:

1: download kauf-plug.yaml into your esphome config directory.

2: edit that downloaded kauf-plug.yaml file to remove the web server as follows (comment it out):

# https://esphome.io/components/web_server.html
# web_server:
#   local: true
#   disable: $disable_webserver

3: edit your device yaml to use that downloaded version as follows:

packages:
#  kauf.plf10: github://KaufHA/PLF10/kauf-plug.yaml
  kauf.plf10: !include kauf-plug.yaml

Here was the original option:

In order to do that you need to remove the package from your yaml (these lines):

packages:
  kauf.plf10: github://KaufHA/PLF10/kauf-plug.yaml

And then copy and paste the entire kauf-plug-yaml file into your yaml:

https://raw.githubusercontent.com/KaufHA/PLF10/main/kauf-plug.yaml

And then remove the webserver section (these lines):

# https://esphome.io/components/web_server.html
web_server:
  local: true
  disable: $disable_webserver

@birdwing
Copy link

I can give that a try at some point tomorrow. I noticed that after about an hour the issue seems to have stopped. so I want to give it some time to see if it comes back up.

Also, when I added the disabled web server substitution

disable_webserver: true

it threw an error that it was expecting a string but it received a bool so I had to send true as a string.

disable_webserver:"true"

Is that correct?

@bkaufx
Copy link

bkaufx commented Dec 16, 2022

Yea, it needs to be a string. Sorry I forgot that when I typed it in my response earlier. I'll edit it so no one else gets confused.

I tried kauf-plug-lite.yaml intead of kauf-plug.yaml (thereby eliminating use of custom components) and I'm basically having the same crashing experience. So, it doesn't appear to be anything wonky I've done in the custom components but rather something in the yaml file.

@birdwing
Copy link

Okay. Since my knee jerk reaction after disabling the webserver and seeing the issue continue, I stopped and waited.

Disabling the webserver and uploading the change to the device does not fix the issue. However after I noticed it was still happening I performed a firmware restart (through the button provided as an entity). After that the issue stopped.

My device has been up over 12 hours without issue.

So it seems like whatever is happening sticks around even after a new compiled firmware is uploaded to the device, and only a restart clears it up.

@alexfranke
Copy link
Contributor

alexfranke commented Dec 31, 2022

I'm also beginning to notice this behavior. With a set of four plugs, none modified except for uploading Firmware version 2.00(u), one appears to have become very unstable (the graph showing current has a bunch of breaks in it), but I didn't notice it until the Christmas tree didn't turn on automatically this morning. My first thought was signal strength, so I like the idea of including signal strength along with the other diagnostic data.

When checking the plug over http, I noticed unusual uptimes, though, too -- 1255374s, (unavailable), 9527s, 5139s, which means that at least two of the others restarted on their own very recently. (I set them all up around the same time a couple weeks ago.) No idea why these might have restarted, but I will try to keep an eye on them. Probably coincidences, but here are a couple things I noticed: (1) The one that's been up consistently for two weeks is only used as a power monitor -- it has no automation that turns it off and on. (2) The one that's apparently gotten really flakey is the only one with a MAC address that starts with 98 (as opposed to 3C).

I haven't had time to experiment yet, apart from unplugging and replugging the one that is apparently unstable, and that didn't seem to help much. In fact it doesn't appear to be coming back online at all now. In the image, the green line is the flakey one, and the purple one is controlled in a similar way (on/off automations) -- you can see what I mean by the breaks in the line.

New to HA but please let me know if there's anything I can do to help figure this out. (I will try the ideas in this thread hopefully next weekend.)

image

@birdwing
Copy link

The plug worked great since my last update, then randomly about 3 days ago it started acting up again.

I still have the webserver off.

There was an update available today so I went ahead and updated and restarted the firmware. I then managed to catch some of the logs where the device kept becoming unavailable every couple minutes.

The device is not throwing any error messages at all, it is just timing out and disconnecting. The logs I have show it timing out about three times and then finally staying on with the mention of some type of boot loop.

[14:27:00][I][ota:115]: Boot seems successful, resetting boot loop counter.

Full logs below.

INFO Reading configuration /config/esphome/christmas-lights.yaml...
INFO Detected timezone 'America/New_York'
INFO Starting log output from christmas-lights.local using esphome API
INFO Successfully connected to christmas-lights.local
[14:21:42][I][app:102]: ESPHome version 2022.12.3 compiled on Dec 31 2022, 14:14:07
[14:21:46][I][app:104]: Project Kauf.PLF10 version 2.02(y)
[14:21:46][C][wifi:566]: WiFi:
[14:21:46][C][wifi:424]:   Local MAC: 3C:61:05:F7:04:61
[14:21:46][C][wifi:425]:   SSID: [redacted]
[14:21:46][C][wifi:426]:   IP Address: 10.0.0.20
[14:21:46][C][wifi:427]:   BSSID: [redacted]
[14:21:46][C][wifi:429]:   Hostname: 'christmas-lights'
[14:21:46][C][wifi:431]:   Signal strength: -64 dB ▂▄▆█
[14:21:46][C][wifi:435]:   Channel: 9
[14:21:46][C][wifi:436]:   Subnet: 255.255.255.0
[14:21:46][C][wifi:437]:   Gateway: 10.0.0.1
[14:21:46][C][wifi:438]:   DNS1: 10.0.0.41
[14:21:46][C][wifi:439]:   DNS2: 10.0.0.41
[14:21:48][C][logger:293]: Logger:
[14:21:48][C][logger:294]:   Level: DEBUG
[14:21:48][C][logger:295]:   Log Baud Rate: 115200
[14:21:48][C][logger:296]:   Hardware UART: UART0
[14:21:48][C][template.binary_sensor:018]: Template Binary Sensor 'Christmas Lights Device In Use'
[14:21:48][C][esp8266_pwm:022]: ESP8266 PWM:
[14:21:48][C][esp8266_pwm:023]:   Pin: GPIO2
[14:21:48][C][esp8266_pwm:024]:   Frequency: 200.0 Hz
[14:21:48][C][esp8266_pwm:025]:   Inverted: YES
[14:21:48][C][esp8266_pwm:022]: ESP8266 PWM:
[14:21:48][C][esp8266_pwm:023]:   Pin: GPIO0
[14:21:48][C][esp8266_pwm:024]:   Frequency: 200.0 Hz
[14:21:48][C][esp8266_pwm:025]:   Inverted: YES
[14:21:48][C][uptime.sensor:031]: Uptime Sensor 'Christmas Lights Uptime'
[14:21:48][C][uptime.sensor:031]:   Device Class: 'duration'
[14:21:48][C][uptime.sensor:031]:   State Class: 'total_increasing'
[14:21:48][C][uptime.sensor:031]:   Unit of Measurement: 's'
[14:21:48][C][uptime.sensor:031]:   Accuracy Decimals: 0
[14:21:48][C][uptime.sensor:031]:   Icon: 'mdi:timer-outline'
[14:21:48][C][template.sensor:023]: Template Sensor 'Christmas Lights Button Press Duration'
[14:21:48][C][template.sensor:023]:   State Class: ''
[14:21:48][C][template.sensor:023]:   Unit of Measurement: 'ms'
[14:21:57][C][template.sensor:023]:   Accuracy Decimals: 1
[14:21:57][C][template.sensor:023]:   Icon: 'mdi:timer-outline'
[14:21:57][C][template.sensor:024]:   Update Interval: 60.0s
[14:21:57][C][template.number:057]: Template Number 'Christmas Lights Use Threshold'
[14:21:57][C][template.number:057]:   Unit of Measurement: 'Watt(s)'
[14:21:57][C][template.number:058]:   Optimistic: YES
[14:21:57][C][template.number:059]:   Update Interval: 60.0s
[14:21:57][C][template.number:057]: Template Number 'Christmas Lights Scale Power'
[14:21:57][C][template.number:057]:   Unit of Measurement: '%'
[14:21:57][C][template.number:058]:   Optimistic: YES
INFO christmas-lights.local: Ping timed out!
INFO Disconnected from ESPHome API for christmas-lights.local
WARNING Disconnected from API
INFO Successfully connected to christmas-lights.local
[14:22:12][D][light:035]: 'Christmas Lights Blue LED' Setting:
INFO christmas-lights.local: Ping timed out!
INFO Disconnected from ESPHome API for christmas-lights.local
WARNING Disconnected from API
INFO Successfully connected to christmas-lights.local
[14:22:40][W][api.connection:081]: Home Assistant 2022.12.8 (10.0.0.41): Connection reset
[14:22:40][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:22:40][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:22:40][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:22:40][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.94440 V with 1 decimals of accuracy
[14:22:41][D][sensor:126]: 'Christmas Lights Uptime': Sending state 40.77500 s with 0 decimals of accuracy
[14:22:50][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:22:50][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:22:50][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:22:50][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.85700 V with 1 decimals of accuracy
[14:22:51][D][api:102]: Accepted 10.0.0.41
[14:22:51][D][api.connection:918]: Home Assistant 2022.12.8 (10.0.0.41): Connected successfully
[14:22:51][D][time:044]: Synchronized time: 2022-12-31 14:22:51
[14:23:00][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:23:00][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:23:00][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:23:00][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.85700 V with 1 decimals of accuracy
[14:23:10][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
INFO christmas-lights.local: Ping timed out!
INFO Disconnected from ESPHome API for christmas-lights.local
WARNING Disconnected from API
INFO Successfully connected to christmas-lights.local
[14:23:33][D][api:102]: Accepted 10.0.0.41
[14:23:33][D][api.connection:918]: Home Assistant 2022.12.8 (10.0.0.41): Connected successfully
[14:23:35][W][api.connection:083]: Home Assistant 2022.12.8 (10.0.0.41): Connection closed
[14:23:37][D][api:102]: Accepted 10.0.0.41
[14:23:40][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:23:40][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:23:40][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:23:41][D][sensor:126]: 'Christmas Lights Uptime': Sending state 100.77500 s with 0 decimals of accuracy
[14:23:44][W][api.connection:081]: ESPHome Logs 2022.12.3 (10.0.0.41): Connection reset
[14:23:44][D][api.connection:918]: Home Assistant 2022.12.8 (10.0.0.41): Connected successfully
[14:23:44][D][time:044]: Synchronized time: 2022-12-31 14:23:44
[14:23:50][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:23:55][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:23:55][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:23:55][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.94440 V with 1 decimals of accuracy
[14:24:00][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:24:00][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:24:00][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:24:00][D][sensor:126]: 'Christmas Lights Voltage': Sending state 119.29527 V with 1 decimals of accuracy
[14:24:10][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:24:10][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:24:10][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:24:10][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.94440 V with 1 decimals of accuracy
[14:24:20][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:24:20][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:24:20][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:24:20][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.94440 V with 1 decimals of accuracy
[14:24:30][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:24:30][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:24:30][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:24:30][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.42194 V with 1 decimals of accuracy
[14:24:40][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:24:40][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:24:40][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:24:40][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.50870 V with 1 decimals of accuracy
[14:24:41][D][sensor:126]: 'Christmas Lights Uptime': Sending state 160.77600 s with 0 decimals of accuracy
[14:24:50][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:24:50][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:24:50][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:24:50][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.85700 V with 1 decimals of accuracy
[14:25:00][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:25:00][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:25:00][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:25:00][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.50870 V with 1 decimals of accuracy
[14:25:10][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:25:10][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:25:10][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:25:10][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.50870 V with 1 decimals of accuracy
[14:25:20][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:25:20][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:25:20][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:25:20][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.50870 V with 1 decimals of accuracy
[14:25:30][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:25:30][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:25:30][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:25:30][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.33532 V with 1 decimals of accuracy
[14:25:40][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:25:40][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:25:40][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:25:40][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.50870 V with 1 decimals of accuracy
[14:25:41][D][sensor:126]: 'Christmas Lights Uptime': Sending state 220.77600 s with 0 decimals of accuracy
[14:25:50][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:25:50][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:25:50][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:25:50][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.50870 V with 1 decimals of accuracy
[14:26:00][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:26:00][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:26:00][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:26:00][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.50870 V with 1 decimals of accuracy
[14:26:10][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:26:10][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:26:10][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:26:10][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.85700 V with 1 decimals of accuracy
[14:26:20][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:26:20][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:26:20][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:26:20][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.85700 V with 1 decimals of accuracy
[14:26:30][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:26:30][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:26:30][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:26:30][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.24881 V with 1 decimals of accuracy
[14:26:40][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:26:40][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:26:40][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:26:40][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.50870 V with 1 decimals of accuracy
[14:26:41][D][sensor:126]: 'Christmas Lights Uptime': Sending state 280.77499 s with 0 decimals of accuracy
[14:26:50][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:26:50][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:26:50][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:26:50][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.50870 V with 1 decimals of accuracy
[14:27:00][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:27:00][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:27:00][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:27:00][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.50870 V with 1 decimals of accuracy
[14:27:00][I][ota:115]: Boot seems successful, resetting boot loop counter.
[14:27:10][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:27:10][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:27:10][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:27:10][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.50870 V with 1 decimals of accuracy
[14:27:20][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:27:20][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:27:20][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:27:20][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.50870 V with 1 decimals of accuracy
[14:27:30][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:27:30][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:27:30][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:27:30][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.50870 V with 1 decimals of accuracy
[14:27:40][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:27:41][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:27:41][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:27:41][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.50870 V with 1 decimals of accuracy
[14:27:41][D][sensor:126]: 'Christmas Lights Uptime': Sending state 340.77499 s with 0 decimals of accuracy
[14:27:50][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:27:50][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:27:50][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:27:50][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.94440 V with 1 decimals of accuracy
[14:28:00][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:28:00][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:28:00][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:28:00][D][sensor:126]: 'Christmas Lights Voltage': Sending state 119.38331 V with 1 decimals of accuracy
[14:28:10][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:28:10][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:28:10][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:28:10][D][sensor:126]: 'Christmas Lights Voltage': Sending state 119.29527 V with 1 decimals of accuracy
[14:28:20][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:28:20][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:28:20][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:28:20][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.94440 V with 1 decimals of accuracy
[14:28:30][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:28:30][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:28:30][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:28:30][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.85700 V with 1 decimals of accuracy
[14:28:40][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:28:40][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:28:40][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:28:40][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.94440 V with 1 decimals of accuracy
[14:28:41][D][sensor:126]: 'Christmas Lights Uptime': Sending state 400.77499 s with 0 decimals of accuracy
[14:28:50][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:28:50][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:28:50][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:28:50][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.85700 V with 1 decimals of accuracy
[14:29:00][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:29:00][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:29:00][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:29:00][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.33532 V with 1 decimals of accuracy
[14:29:10][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:29:10][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:29:10][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:29:10][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.94440 V with 1 decimals of accuracy
[14:29:20][D][sensor:126]: 'Christmas Lights Power': Sending state 0.00000 W with 1 decimals of accuracy
[14:29:20][D][sensor:126]: 'Christmas Lights Total Daily Energy': Sending state 0.15158 kWh with 3 decimals of accuracy
[14:29:20][D][sensor:126]: 'Christmas Lights Current': Sending state 0.00000 A with 2 decimals of accuracy
[14:29:20][D][sensor:126]: 'Christmas Lights Voltage': Sending state 118.94440 V with 1 decimals of accuracy

I will say, that after updating and restarting the firmware, after it's initial funny business and that message about the boot looking successful resetting boot loop counter; the device does appear to be working again. It seems like something happens to trigger a boot loop in the device and it can't get out of it until a firmware restart and then it still takes some time to get out of it.

@birdwing
Copy link

birdwing commented Jan 1, 2023

It has started acting up again.
I cannot seem to find any error messages or causes for this.

@birdwing
Copy link

birdwing commented Jan 1, 2023

Wait...

Why do you have the plug set to restart itself every 15 minutes?

Line 459 of kauf-plug.yaml

@alexfranke
Copy link
Contributor

Why do you have the plug set to restart itself every 15 minutes?

Line 459 of kauf-plug.yaml

new to this, but I believe this is the timeout in ESPHome that will cause the device to reboot when there's no client connected (for this amount of time), so if HA is connected to the API, then this timeout doesn't come into play.

@alexfranke
Copy link
Contributor

I moved mine right next to the router yesterday and it's since been stable so far/ (Not very useful at this location, but stable nonetheless... I have my fingers crossed.) So I wonder if this is just a really fragile API connection causing this behavior. @birdwing have you done any testing around that?

@birdwing
Copy link

birdwing commented Jan 1, 2023

@alexfranke I have not done any testing around that.
I did think that maybe the timeout to determine if the device is connected might be a bit low, making the API " fragile"

But I don't think that's an issue with this plug itself. I might dig into the home assistant documentation, or the ESP home documentation to see if there are any settings related to timeout.

I will be moving the plug closer to the Wi-Fi router because it's permanent home will be only a few feet away from it, however, it was working fine at its current location for weeks until it just randomly started misbehaving again. Nothing has changed with the network and the signal strength on the device is the same now as it was during the weeks it was working.

@birdwing
Copy link

birdwing commented Jan 1, 2023

I may try decreasing the monitoring update interval .
If it is an issue with the time out in home assistant or ESP home, decreasing the interval may keep the device connected.

If it's an issue with the plug itself, then that should cause it to disconnect more often due to the timeout issue on the plugs API, in which case increasing that interval should fix the problem.

@bkaufx
Copy link

bkaufx commented Jan 1, 2023

The reboot timeout is the default behavior of ESPHome. I've thought about disabling it by default as it's confused people more than anything. If you turn on the No HASS switch, rebooting timeout will be disabled. If this timeout were occuring, I believe you would see a message in the logs on the web interface or ESPhome dashboard.

I'm going to create some additional yaml files for debug purposes. If anyone has any ideas for test yamls let me know. One's just going to be kauf-plug.yaml with no web server. In another I'm going to implement all config entities as substitutions just to cut the number of entities way down.

Has anyone tried kauf-plug-lite.yaml and still had this problem? Has anyone removed the web server completely, not just disabled via substitution?

@bkaufx
Copy link

bkaufx commented Jan 1, 2023

To compile a firmware with the web server completely omitted, you can change the packages: line to the following. This will completely remove the web server and captive portal so they aren't even compiled in (the substitution still compiles in the web server, it just disables it from running).

packages:
  kauf.plf10: github://KaufHA/PLF10/test-yamls/kauf-plug-no-webserver.yaml

On my end, the only way I'm getting the plugs to crash is opening up multiple web browser tabs at once connected to the same plug. So I still highly suspect web server is causing issues.

@birdwing
Copy link

birdwing commented Jan 1, 2023

I didn't try the lite version, but I did try minimal. Still had the same issue.

@alexfranke
Copy link
Contributor

alexfranke commented Jan 1, 2023

was working fine at its current location for weeks until it just randomly started misbehaving again. Nothing has changed with the network and the signal strength on the device

Good point. Possibly the same here, actually -- it was working fine for weeks in the same location with no symptoms until I noticed it didn't switch on automatically the other day. Maybe I was just lucky for the first few weeks and the automation occurred only while it happened to be connected, but that seems a bit unlikely after seeing how often it was actually disconnected when I looked into it. @birdwing

Interestingly, I also can't get it to take an OTA firmware update to 2.02 either -- it just resets the browser connection and does nothing. Also it apparently rebooted itself again 1.5 hours ago (before the firmware update attempt). Weird...

Has anyone tried kauf-plug-lite.yaml and still had this problem? Has anyone removed the web server completely, not just disabled via substitution?

I'm brand new to a lot of these technologies and still fumbling my way through them (haven't gotten an ota update to work yet with esphome.exe), but I'm going to take another stab at this probably tomorrow. If it stays connected all day in its currently location, I'll move it back to the Christmas tree and see if it starts disconnecting again. Then I'll try kauf-plug-lite.yaml first and let you know how it goes. @bkaufx

oh -- and happy new year!

@bkaufx
Copy link

bkaufx commented Jan 1, 2023

@birdwing Weird that the minimal yaml would have issues. Did you try disabling reboot timeout by turning on the No HASS switch or by editing the yaml?

@bkaufx
Copy link

bkaufx commented Jan 1, 2023

I have a new plug model that should be in stock in the next week. If everyone in this thread will email me their address to brian@kaufha.com I'll send everyone one of the new plugs to try out different hardware.

@bkaufx
Copy link

bkaufx commented Jan 1, 2023

All options entities can be removed by using the following packages section:

packages:
  kauf.plf10: github://KaufHA/PLF10/test-yamls/kauf-plug-no-options.yaml

Options can be set using these substitutions:

  # API Reboot Timeout.  Defaults to off now.  ESPHome default is 15 min.
  sub_api_reboot_timeout: 0s

  # Button Debounce Time.
  sub_debounce_time: "100ms"

  # Power Monitoring Update Interval
  sub_update_interval: 10s

  # Scale variables, scales power monitoring sensors.
  sub_scale_power:   "1.0"
  sub_scale_current: "1.0"
  sub_scale_voltage: "1.0"

  # default boot up behavior of relay
  # https://esphome.io/components/switch/gpio.html?highlight=restore_mode
  sub_restore_mode: RESTORE_DEFAULT_ON

@birdwing
Copy link

birdwing commented Jan 1, 2023

@birdwing Weird that the minimal yaml would have issues. Did you try disabling reboot timeout by turning on the No HASS switch or by editing the yaml?

I am using HA though.
Would turning no Hass on cause issue?

@birdwing
Copy link

birdwing commented Jan 1, 2023

I have a new plug model that should be in stock in the next week. If everyone in this thread will email me their address to brian@kaufha.com I'll send everyone one of the new plugs to try out different hardware.

Just sent you an email 👍

@birdwing
Copy link

birdwing commented Jan 2, 2023

I switched to the /kauf-plug-no-webserver.yaml file.
Everything seemed fine for about an hour then the device went unavailable again.

It seems to happen less often without the webserver installed, but it still happens 2-3 times an hour (a big improvement over every 2 minutes)

Before changing the file I did also try setting no hass to true, but that made no difference at all.

Also changing the monitoring update interval didn't appear to make a difference either.

@alexfranke
Copy link
Contributor

alexfranke commented Jan 2, 2023

Here's some more data for my symptomatic device: (sorry so wordy -- hoping there's something in here that's helpful)

  • Plugged in near the router, with nothing plugged into it
    • Stable for about 24 hours
    • Then it rebooted itself (uptime started over) with no intervention
    • At about the same time as the reboot, HA reported (Error connecting to [ip] [Errno 113] Connect call failed. I don't know if this was right before it rebooted or because it was rebooting.
    • Stable again for another 6 hours
  • At this point I moved it back to its original location, plugged it in and plugged nothing into it.
    • Connected immediately and stable for about 2 hours
  • Then I plugged an LED light string into it.
    • plf10 became "unavailable" in HA and the web server stopped responding at its IP address
    • Device LEDs were alternating blue/red, which I interpreted as power/no connection
    • Stayed this way for about 20 minutes.
    • Unplugged the LED light string
    • Same state for another 10 minutes or so
  • Unplugged plf10 from the wall, plugged the light string back into it, then plugged the kauf plug back into the wall
    • Red LED blinking for about 5 minutes, still unavailable/not responding on port 80
  • Unplugged from wall again, unplugged light string, and after a couple of minutes plugged the plf10 back into the wall (with nothing plugged into it)
    • Connected right away to HA and stayed connected for about 10 minutes
    • Plugged light string back into it, and I could control it for about a minute before it disconnected and became unavailable in HA again.
    • LED blinking blue/red again
    • I'll leave it in this state for an hour or so and see if it can successfully connect again

Next I'll try it with a different load just in case that has something to do with it. The light string I'm currently using draws about 275mA btw.

Let me know if there's anything in particular you'd like me to test around before I try to change the yaml -- for example, I could try same load with a different plf10, same load same plf closer to router, etc, but I'm flying blind as to what might be useful to you.

@alexfranke
Copy link
Contributor

Some more data -- it appears to become unstable when currently is flowing through it. I still need to test it with a different load. Here's the "uptime" graph for the past 24 hours along with a description of what happened.

image

A - (from previous message) plugged the PLF10 into the wall with nothing plugged into it, and it connected right away.
B - Plugged an LED light string into it (20 min later). The relay was open. I used HA to close the relay and turn on the light string. It almost immediately became "unavailable" again. After a new minutes I used the button on the PLF10 to turn the lisght strip off again, and that worked fine.
C - About 40 minutes later, it started showing up again in this graph, with an initial value of 1412, suggesting that it had been up but just not connected for about half that time. There were no other automations that triggered this overnight and it was stable.
D - 6:00 am automation triggered the outlet to turn on (and the light string did turn on). The last data point recorded here is at 06:03:27, so after about 3.5 minutes it had apparently gone unavailable again.
E - at 8:38 it reappears with no intervention. The initial value is 8322 (139 min), which suggests to me that it was up but not connected since about 6:19 am. At some point between D and H the relay opened on its own (the light string turned off), but I don't know when.
F - at 9:30, the line breaks again.
G - at 9:57, it reappears with an initial value of 692, suggesting that it was up but not connected since 9:45.
H - At 10:08 I realized that the plug had turned off on its own, and I turned it on again using HA. It immediately went unavailable in HA (the UI switch wouldn't even stay on, though the PLF10 did close the relay and turn the lights on). Interestingly the line has been flat here since then.

Here's the other weird thing: Literally every time, right before the line breaks, there's a decimal value recorded that's less than the previously recorded value -- sometimes just a bit lower, and sometimes quite a bit lower. For example this weird decimal value when ten seconds prior it was a nice integer 24392.

image

@alexfranke
Copy link
Contributor

Could it be the LED light string that's causing the problem? I'm starting to think that it is...

  • I updated the firmware to show 2.02 including signal strength. Same problem in same location with same light string. Signal strength isn't great (in the 70's) but it operates fine with nothing's plugged into it.
  • I tried it in the same location with a lamp instead of the LED light string, and it stayed connected all night.
  • I plugged the LED light string into the outlet below the kauf plug thinking there might be causing interference on the line and it didn't immediately disconnect.
  • I plugged the LED light string back into the kauf plug, and within a minute it disconnected again -- been disconnected for a couple hours now.

Plus, @birdwing looks like he was also working with Christmas lights...

Presumably there's some isolation in the hardware, but knowing if this is even plausible is pretty much above my pay grade, I'm afraid... :/

@birdwing
Copy link

birdwing commented Jan 4, 2023

@alexfranke My Christmas Lights were old incandescent bulbs. 😉

I had the same issue moving the plug to my soundbar.(using it so home assistant knows when its on, for use with my broadlink remote)

I also don't think LED light strings can cause electrical interference any differently than other electrical devices.
Especially how low energy they are.

The lamp you plugged in, depending on the type of bulb, may have still drawn less power than the LED string however. Perhaps it has to do with how much power is being drawn.

If you plug in something that pulls more power in than the LED light string, do you see the same issue?

Perhaps there is electrical interference being created when power moves through the plug at or above a certain threshold.

@bkaufx
Copy link

bkaufx commented Jan 4, 2023

Do you guys remember having this issue before firmware v2.02?

If not, it might be interesting to try reverting back to the stock HLW8012 component by adding this to your config yaml:

external_components:
  - source:
      type: git
      url: https://github.com/esphome/esphome
    components: [hlw8012]

@alexfranke
Copy link
Contributor

alexfranke commented Jan 4, 2023

Do you guys remember having this issue before firmware v2.02?

Most of my testing was with v2.00 and I reconfirmed the behavor with 2.02 starting yesterday. @bkaufx

I'm still suspecting some kind of interference caused by this particular string of lights. It was up continuously for about 24 hours (22 with nothing plugged in, and 2 hrs with a 75W incandescent plugged in, testing @birdwing 's theory). I plugged the string lights back into it, and it's now rebooted itself twice in the last 20 minutes -- both times reporting a weird floating point value for uptime right before restarting.

image

@alexfranke
Copy link
Contributor

seems like my issue has to be some sort of EMI... The original 33W LED string seems to be the only one that's acting up regularly, at least with 2-5 hour long tests.

image

@birdwing
Copy link

birdwing commented Jan 5, 2023

Do you guys remember having this issue before firmware v2.02?

If not, it might be interesting to try reverting back to the stock HLW8012 component by adding this to your config yaml:

external_components:
  - source:
      type: git
      url: https://github.com/esphome/esphome
    components: [hlw8012]

I got my plug after 2.02 was released so I never had anything older than that.

@alexfranke
Copy link
Contributor

Well, so much for that idea... This time it started acting up again with no intervention after working properly 19 hours straight, the last 12 of those hours in the OFF state and with nothing plugged in. For the last three hours it's been restarting over and over again, but at least remaining connected. This is really starting to test my tenacity. :/ I'd love to be able to figure out what's going on here but I'm beginning to suspect that might not ever happen. Now I'm thinking it's two different issues.

image

@bkaufx
Copy link

bkaufx commented Jan 6, 2023

Does this seem to be a problem for only one plug or do all plugs act the same way?

@alexfranke
Copy link
Contributor

alexfranke commented Jan 6, 2023

Does this seem to be a problem for only one plug or do all plugs act the same way?

It varies. Best I can tell:

  • No.1 has been rock solid the whole time (currently 20 days straight),
  • No.2 is the one I've been working with here -- lots of periods of "unavailable" and reboots that don't always correlate
  • No.3 & No.4 have random reboots, sometimes more frequent, but don't appear to become "unavailable" apart from when rebooting

Here are the uptime histories for the past 12 or so days (as far back as I could go).
image

@birdwing
Copy link

birdwing commented Jan 8, 2023

@alexfranke

What are the Watt/voltage history for the plugs?
I wonder if there is a correlation.

@bkaufx
I have noticed significantly less issues since I have moved the plug to the sound bar, instead of the Christmas lights. The plug will work for a between 14 and 20 hours, then the issue will reappear for about an hour or two and then it'll work again without issue. If I reboot the plug during those couple hours when the issues starts, it immediately begins working again.

@alexfranke
Copy link
Contributor

What are the Watt/voltage history for the plugs?
I wonder if there is a correlation.

No, there's no correlation there.

The lights are coming off the tree today so I'll be able to do some more different kinds of testing.

Just now I noticed a lot of errors in the log produced by the devices website (json string allocation errors) and the site doesn't render all its UI elements.

[json:043] | Could not allocate memory for JSON document! Overflowed largest free heap block: X bytes

...where X is either 8, 16, 32, 64, or (interestingly) 40.

So my current theory is admittedly pretty convoluted: When the WiFi signal isn't awesome (e.g. >60) or a channel or plugged-in appliance is too noisy, the ESP8266 is prone to disconnect and scans and/or connects with slower and/or more power-hungry protocol, which may cause brown-outs -- or repeatedly (while scanning or connecting) runs some code with a memory leak that doesn't manifest itself until later when something overflows and causes it to restart.

...more testing later.

@alexfranke
Copy link
Contributor

Btw this was actually with a different plug (one that was previously restarting ransomly but NOT disconnecting), so that's partly why I'm thinking this is related to signal strength and/or the actual light strings. I thought the part highlighted in green was interesting -- when the plug had both restarted and reconnected at about 3:00 pm yesterday, the voltage readings were a lot noisier than before until the switch was turned off. This symptom didn't repeat itself from 1-2 today with the same amount of current, but by that time the plug had restarted at least once (at about midnight) and disconnected a few times.

This is the plug that's currently still throwing the JSON memory allocation errors. I'm waiting to see if that's a sign that it's going to shut itself off or disconnect.

image

@alexfranke
Copy link
Contributor

I have another update on this, and now I'm totally confused. Once I got the lights off the tree last weekend, I tested the symptomatic plug close to the router with the same LED strings to try to isolate network connectivity as a contributing cause, and it seemed a lot more stable. So then I added some diagnostics (memory, signal strength, physical network mode, etc), reflashed the symptomatic plug, and put it back in its original location (other side of the house) with the same (original/symptomatic) light string. The only thing different this time was that the lights weren't on the tree and I had reflashed the device -- and it's only rebooted itself once in the past 40 hours with no sign of becoming "unavailable" during that time.

I guess the other difference is that in its symptomatic state, I had I originally upgraded to v2.00 using the device's website, and I most recently reflashed it using esphome OTA. (I actually wasn't able to reflash it using the website at all - the website would just hang when I tried.)

Maybe this was all just a bad firmware update?

@birdwing
Copy link

Have to say, thank you for sending the new hardware. I absolutely love the re-design. It's slightly thinner which makes it easier to use on my power strip behind the TV. The new hardware was also way more responsive for some reason. It booted quicker and connected to my network much faster than the older plug. After almost a week not a single issue with it.

I will say as well, since moving the old plug to the soundbar rather than the Christmas lights, I have had much fewer issues with it. Haven't had any in the last week. When removing the christmas lights I did also re-flash the device (to change the name of it). And went back to the default kauf-plug.yaml file. I am still using disable_webserver: "true"

@coonce
Copy link

coonce commented Mar 18, 2023

Adding power_save_mode: high to the wifi: section of my yaml has cleared up this issue for me. It seems counter-intuitive to add more sleep since it appears to be sleeping too much; plus the default for esp8266 is none. 🤷‍♂️ But it looks like there is an issue with sleep mode on esp8266 being mislabeled.

BTW, I also set fast_connect: false and disable_webserver: "true". I have 4 plugs (two plf10, two plf12) which had the problem and all have been solid since flashing.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants