search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.86k stars 3.58k forks source link

[mqtt.homeassistant] Thing status of ESPHome devices not working after OH restart. #12295

Closed TheNetStriker closed 11 months ago

TheNetStriker commented 2 years ago

Since one of the last updates (i guess it was the update from OH 3.1 to 3.2) the Thing status of my ESPHome devices is always OFFLINE. My devices are reporting the state correctly in the designated MQTT topic, but for some reason the state is not updated in OpenHab anymore. Only when I delete the Thing and re-add it, the Thing state works but only until I restart OpenHab.

I also tried to disable and re-enable the Things in the web interface and to stop and start the whole binding in the Karaf console, but that does not fix the problem.

I've also opened a thread in the community forum, but i did not get any replies: https://community.openhab.org/t/thing-status-not-working-anymore-on-esphome-devices-after-oh-3-2-update/133018

Update: I've just enabled trace logging for the MQTT binding and it seems that only the sensor topics are subscribed when OpenHab is starting. I cannot see the avty_t topic anywhere in the trace logs.

Expected Behavior

Thing state should represent the current state of the ESPHome device's availability MQTT topic.

Current Behavior

Thing state is always OFFLINE after a restart.

Steps to Reproduce (for Bugs)

Context

I have various rules that check if the ESPHome Things are online because they sometimes loose the Wifi connection. Those rules are currently not working because the state is not updated anymore.

Your Environment

OpenHab 3.2 Openhabian running on an Raspberry Pi 4 (4GB)

Logs

I always get the following logs during the OpenHab startup.

2022-02-07 22:51:57.541 [WARN ] [org.openhab.core.internal.common.WrappedScheduledExecutorService                                    ] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
    at org.openhab.binding.mqtt.generic.MqttChannelTypeProvider.derive(MqttChannelTypeProvider.java:132) ~[?:?]
    at org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery.publishResults(HomeAssistantDiscovery.java:204) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
2022-02-07 22:52:26.341 [WARN ] [org.openhab.core.internal.common.WrappedScheduledExecutorService                                    ] - Scheduled runnable ended with an exception: 
java.lang.IllegalArgumentException: Duplicate channels mqtt:homeassistant_5ccf7ff03cc4:4ce1d806:5ccf7ff03cc4:ESPbinary_5Fsensorwater_5Falert#sensor
    at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:152) ~[?:?]
    at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:144) ~[?:?]
    at org.openhab.core.thing.util.ThingHelper.addChannelsToThing(ThingHelper.java:105) ~[?:?]
    at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:292) ~[?:?]
    at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:1) ~[?:?]
    at org.openhab.binding.mqtt.generic.tools.DelayedBatchProcessing.run(DelayedBatchProcessing.java:110) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
2022-02-07 22:52:30.494 [WARN ] [org.openhab.core.internal.common.WrappedScheduledExecutorService                                    ] - Scheduled runnable ended with an exception: 
java.lang.IllegalArgumentException: Duplicate channels mqtt:homeassistant_5ccf7ff03cc4:4ce1d806:5ccf7ff03cc4:5ccf7ff03cc4_2Dwifisignal#sensor
    at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:152) ~[?:?]
    at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:144) ~[?:?]
    at org.openhab.core.thing.util.ThingHelper.addChannelsToThing(ThingHelper.java:105) ~[?:?]
    at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:292) ~[?:?]
    at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:1) ~[?:?]
    at org.openhab.binding.mqtt.generic.tools.DelayedBatchProcessing.run(DelayedBatchProcessing.java:110) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
2022-02-08 02:57:52.068 [WARN ] [org.openhab.core.internal.common.WrappedScheduledExecutorService                                    ] - Scheduled runnable ended with an exception: 
java.lang.IllegalArgumentException: Duplicate channels mqtt:homeassistant_68c63a94e011:4ce1d806:68c63a94e011:ESPbinary_5Fsensorwater_5Falert#sensor
    at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:152) ~[?:?]
    at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:144) ~[?:?]
    at org.openhab.core.thing.util.ThingHelper.addChannelsToThing(ThingHelper.java:105) ~[?:?]
    at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:292) ~[?:?]
    at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:1) ~[?:?]
    at org.openhab.binding.mqtt.generic.tools.DelayedBatchProcessing.run(DelayedBatchProcessing.java:110) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
2022-02-08 02:57:57.875 [WARN ] [org.openhab.core.internal.common.WrappedScheduledExecutorService                                    ] - Scheduled runnable ended with an exception: 
java.lang.IllegalArgumentException: Duplicate channels mqtt:homeassistant_68c63a94e011:4ce1d806:68c63a94e011:ESPbinary_5Fsensorwater_5Falert#sensor
    at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:152) ~[?:?]
    at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:144) ~[?:?]
    at org.openhab.core.thing.util.ThingHelper.addChannelsToThing(ThingHelper.java:105) ~[?:?]
    at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:292) ~[?:?]
    at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:1) ~[?:?]
    at org.openhab.binding.mqtt.generic.tools.DelayedBatchProcessing.run(DelayedBatchProcessing.java:110) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
2022-02-08 02:59:52.798 [WARN ] [org.openhab.core.internal.common.WrappedScheduledExecutorService                                    ] - Scheduled runnable ended with an exception: 
java.lang.IllegalArgumentException: Duplicate channels mqtt:homeassistant_68c63a94e011:4ce1d806:68c63a94e011:ESPbinary_5Fsensorwater_5Falert#sensor
    at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:152) ~[?:?]
    at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:144) ~[?:?]
    at org.openhab.core.thing.util.ThingHelper.addChannelsToThing(ThingHelper.java:105) ~[?:?]
    at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:292) ~[?:?]
    at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:1) ~[?:?]
    at org.openhab.binding.mqtt.generic.tools.DelayedBatchProcessing.run(DelayedBatchProcessing.java:110) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]

ESPHome Device config

esphome:
  name: sonoff01
  platform: ESP8266
  board: esp8285

wifi:
  use_address: 172.17.7.10
  networks:
    - ssid: "XXXXX"
      password: !secret PASSWORD

  # Enable fallback hotspot (captive portal) in case wifi connection fails
  ap:
    ssid: "Sonoff01 Fallback Hotspot"
    password: !secret CAPTIVE_PORTAL_PASSWORD

mqtt:
  broker: 172.17.2.21
  client_id: sonoff01
  discovery: True
  birth_message:
    topic: sonoff01/availability
    payload: online
  will_message:
    topic: sonoff01/availability
    payload: offline

api:
  password: !secret API_PASSWORD
  reboot_timeout: 0s

logger:

ota:
  password: !secret OTA_PASSWORD

binary_sensor:
  - platform: gpio
    name: "Button"
    id: button
    pin:
      number: GPIO0
      mode: INPUT_PULLUP
      inverted: True
    on_press:
      - switch.toggle: relay

switch:
  - platform: gpio
    name: "Relay"
    pin: GPIO12
    id: relay
  - platform: restart
    name: "Restart"
    id: reboot

sensor:
  - platform: wifi_signal
    name: "WiFi Signal"
    id: rssi
    update_interval: 60s
openhab-bot commented 2 years ago

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/thing-status-not-working-anymore-on-esphome-devices-after-oh-3-2-update/133018/2

TheNetStriker commented 2 years ago

Update: I was able to fix the errors in the log by simply deleting all the MQTT Things and add them again by hand. The Thing status on HomeAssistant Things now works better, but I still got some issues. After a restart some of the devices are now ONLINE. But some are in the state UNKNOWN and stay in this state, even if I change the MQTT topic. I found out that I can fix this issue by opening the Things in the main ui and just click on the save button. After that the state updates work until I restart OpenHab again.

I setup a development environment with the same thing json file and just changed the broker ip address. I can also see this problem in this development environment. After a few tests I found out that the method calculateThingStatus in the AbstractMQTTThingHandler gets called when I update the MQTT topic and it also sets the correct Thing state in the HomeAssistantThingHandler, but for some reason the status is not updated in the main ui. After clicking on the save button in the main ui the state updates correctly just as on my main OpenHab environment.

Any ideas why some of the Things now get stuck into this UNKNOWN state after a restart?

jimtng commented 2 years ago

Thing state should represent the current state of the ESPHome device's availability MQTT topic.

Is the availability topic from the ESPHome device retained?

TheNetStriker commented 2 years ago

@jimtng Yes, the availability topic is retained. It also work's for most device, only a few do not load the correct state after an OH restart. Saving the thing in the UI fixes the problem.

I guess the problem could be fixed in the current main build. If I test this in the development environment using the main build the state is loaded correctly. But I can only say for sure after the next version has been released and I can test this on my production environment.

flpaoli commented 2 years ago

I have a similar symptom after updating an esphome config and adding a new sensor. The previously existing topics start showing this duplicate channel error in the logs. openHabian with OH 3.1.1 in my case.

2022-03-05 16:53:27.597 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: java.lang.IllegalArgumentException: Duplicate channels mqtt:homeassistant_e8db84d0803f:2d1cd8ee67:e8db84d0803f:ESPswitchpool_5Fswitch#switch at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:152) ~[?:?] at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:144) ~[?:?] at org.openhab.core.thing.util.ThingHelper.addChannelsToThing(ThingHelper.java:105) ~[?:?] at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:292) ~[?:?] at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:1) ~[?:?] at org.openhab.binding.mqtt.generic.tools.DelayedBatchProcessing.run(DelayedBatchProcessing.java:110) ~[?:?] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?] at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] at java.lang.Thread.run(Thread.java:829) [?:?]

TheNetStriker commented 2 years ago

I've just tested this in the latest release 3.3 of OpenHab and this problem still exists on the same mqtt things. Any idea what could be the problem here?

phjr commented 2 years ago

I have the same problem (mqtt:homeassistants showing as offline and "duplicate channels" error in log), but I have also found a workaround. If some of my mqtt:homeassistant:* devices are showing as offline, I disable and immediately enable the broker thing. After several tries I always get all things online.

(From developer perspective this looks like a race condition.)

lolodomo commented 1 year ago

As there was a possible fix merged, is this issue still present in OH 3.4.x?

stale[bot] commented 1 year ago

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