search

eclipse-archived / smarthome

Eclipse SmartHome™ project
https://www.eclipse.org/smarthome/
Eclipse Public License 2.0
866 stars 782 forks source link

[MQTT-Binding / Homie]: No communication possible with Homie-Thing after restart #6828

Open euphi opened 5 years ago

euphi commented 5 years ago

My Homie-V3 test device was auto-discovered correctly and working fine (I manually linked the newly created items). However, after restart, the device is "Online", but communication is ignored by Openhab and any attempt to change state of settable properties results in error:

10:44:46.664 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'Lab_Log_Loglevel' received command WARNING
10:44:46.704 [INFO ] [arthome.event.ItemStatePredictedEvent] - Lab_Log_Loglevel predicted to become WARNING
10:44:46.739 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:cf9ca1aa:lab_thermo' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): No connection or readOnly channel!

Restart of the Homie device

10:47:00.724 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:cf9ca1aa:lab_thermo' changed from OFFLINE (GONE): Device did not send heartbeat in time to ONLINE (CONFIGURATION_PENDING)
10:47:00.874 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:cf9ca1aa:lab_thermo' changed from ONLINE (CONFIGURATION_PENDING) to ONLINE
10:54:25.145 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'Lab_Log_EnableDisableLogToSerialInterface' received command OFF
10:54:25.202 [INFO ] [arthome.event.ItemStatePredictedEvent] - Lab_Log_EnableDisableLogToSerialInterface predicted to become OFF
10:54:25.264 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:cf9ca1aa:lab_thermo' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): No connection or readOnly channel!
10:54:25.293 [INFO ] [smarthome.event.ItemStateChangedEvent] - Lab_Log_EnableDisableLogToSerialInterface changed from ON to OFF

No messages are sent to the MQTT broker by openhab, received messages are ignored.

Please note that the device is treated as online, as long as no command is sent to it. (If it disconnects or is "lost" this is also correctly detected by Openhab)

Also, the channels are no longer configurable after Openhab was restarted once after the Thing and its channels were auto-discovered. Just after auto-discovery it was possible to edit the channel configuration:

Screenshot of PaperUI ("Edit-Pen" missing for channels (same behaviour if device is still seen as "online"): image

Screenshot of PaperUI Control (no dropdown with valid Enum values for Loglevel):

image

PS: A manually added MQTT thing (Homie-2.0, so not auto-discoverable) works fine.

PPS: See also #6823 - this issue happend before the first retart of Openhab after the Homie-Thing was added.

PPPS: For completness, log of MQTT communication:

homie/lab_thermo/$state lost
homie/lab_thermo/$state init
homie/lab_thermo/$homie 3.0.1
homie/lab_thermo/$name Lab
homie/lab_thermo/$mac A0:20:A6:21:D0:53
homie/lab_thermo/$localip 192.168.0.155
homie/lab_thermo/$nodes Sensor,Log
homie/lab_thermo/$stats uptime
homie/lab_thermo/$stats/interval 0
homie/lab_thermo/$fw/name Test-Homie-V3
homie/lab_thermo/$fw/version 0.1.1
homie/lab_thermo/$fw/checksum 85594e520a110816a7a791f9c1b8f60d
homie/lab_thermo/$implementation esp8266
homie/lab_thermo/$implementation/config {"name":"Lab","device_id":"lab_thermo","wifi":{"ssid":"IA216"},"mqtt":{"host":"192.168.0.220","port":1883,"base_topic":"homie/","auth":false},"ota":{"enabled":true},"settings":{}}
homie/lab_thermo/$implementation/version 3.0.0
homie/lab_thermo/$implementation/ota/enabled true
homie/lab_thermo/Sensor/$name Sensor (Temperatur & Luftfeuchte)
homie/lab_thermo/Sensor/$type sensor_t_h
homie/lab_thermo/Sensor/$properties degrees,relH
homie/lab_thermo/Sensor/degrees/$name Temperatur
homie/lab_thermo/Sensor/degrees/$datatype float
homie/lab_thermo/Sensor/degrees/$unit °C
homie/lab_thermo/Sensor/degrees/$format -50:100
homie/lab_thermo/Sensor/relH/$name relative Luftfeuchte
homie/lab_thermo/Sensor/relH/$datatype float
homie/lab_thermo/Sensor/relH/$unit %
homie/lab_thermo/Sensor/relH/$format 0:100
homie/lab_thermo/Log/$name Logger
homie/lab_thermo/Log/$type Logger
homie/lab_thermo/Log/$properties Level,LogSerial
homie/lab_thermo/Log/Level/$name Loglevel
homie/lab_thermo/Log/Level/$settable true
homie/lab_thermo/Log/Level/$datatype enum
homie/lab_thermo/Log/Level/$format DEBUG,INFO,WARNING,ERROR,CRITICAL
homie/lab_thermo/Log/LogSerial/$name enable/disable log to serial interface
homie/lab_thermo/Log/LogSerial/$settable true
homie/lab_thermo/Log/LogSerial/$datatype boolean
homie/lab_thermo/$state ready
homie/lab_thermo/Log/ERROR/SensorNode Cannot read humidity on I2C
homie/lab_thermo/Sensor/relH 0
homie/lab_thermo/Log/ERROR/SensorNode Cannot read temperature on I2C
homie/lab_thermo/Sensor/degrees 15.00
homie/lab_thermo/$stats/signal 10
homie/lab_thermo/$stats/uptime 27
euphi commented 5 years ago

I was able to reproduce the issue:

  1. Deleted the thing
  2. Restarted Homie
  3. Homie-Thing was in Inbox
  4. Added Thing
  5. --> Thing was automatically linked to still existing channels (I don't think it is good that the channels were not deleted, but in this case it was useful).
  6. Channels and linked items were updated correctly
  7. It was possible to change settable Items in PaperUI (also the valid Enumeration Values where offered in a drop-down).
  8. Channels were still not editable (so I also couldn't see the details).
  9. Restart Openhab
  10. Channels/Items were no longer updated
  11. In Thing configuration the "Edit Channel"-Pen was visible but nothing happened when clicked
  12. When trying to update a settable Items, the same error as mentioned in the first post appeared ?!

Logging with DEBUG for MQTT Binding did not show anything other than in first post.

halo779 commented 5 years ago

I've also been having this one.

https://community.openhab.org/t/influxdb-openhab2-stops-storing-data-after-reboot/63123 Initially i thought it to be influxdb persistence. but nope

Replication is even easier than already listed.

Add a homie v3 device. Let it send a message or two to confirm working. Edit thing, add a location Let it send a few more message, will no longer show.

Same responses as rebooting openhab.

Glad to see others are at least having this, i've been pulling my hair out trying to work out what i've configured wrong..

euphi commented 5 years ago

Next try:

  1. I deleted my linked items and then the Thing.
  2. I restarted openhab
  3. Thing was discoverd again and added.
  4. I created links to new Items.
  5. Items were updated correctly.
  6. No changes were done to thing configuration. Reboot.
  7. --> Items are no longer updated.

Only relevant loginfo after startup seems to be OK

13:24:02.908 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:cf9ca1aa:lab_thermo' changed from OFFLINE (BRIDGE_OFFLINE) to OFFLINE (COMMUNICATION_ERROR): java.lang.Exception: Did not receive mandatory topic value: homie/lab_thermo/$homie                                                                                                                                                                                                                              
13:24:02.993 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:cf9ca1aa:lab_thermo' changed from OFFLINE (COMMUNICATION_ERROR): java.lang.Exception: Did not receive mandatory topic value: homie/lab_thermo/$homie to ONLINE                                                                                                                                                                                                                                                
13:24:03.084 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:topic:homie_leg_heizung' changed from OFFLINE (BRIDGE_OFFLINE) to OFFLINE (COMMUNICATION_ERROR): Did not receive all required topics
13:24:03.913 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:topic:homie_leg_heizung' changed from OFFLINE (COMMUNICATION_ERROR): Did not receive all required topics to ONLINE

homie_leg_heizung is a Homie V2.0 devices and is manually configured as Generic MQTT Thing and works correctly.

halo779 commented 5 years ago

Have tested this with Snapshot Version: 2.5.0-SNAPSHOT (#1493)

Issue happens there too. Since 2.4 there were a few MQTT related fixes so wondered if they may have resolved the issue. Unfortunately not.

halo779 commented 5 years ago

Also backtested all the way to the first test release that had the mqtt 2 bindings

2.4.0~M4-1

issue exists there too.

kaikreuzer commented 5 years ago

@davidgraeff fyi

pavax commented 5 years ago

Same problem here. I'm working to update the miflora-mqtt-daemon (https://github.com/pavax/miflora-mqtt-daemon/blob/master/miflora-mqtt-daemon.py) to follow the homie 3.0 specification. The device is discovered and there is no problem adding the thing. Every time a value is updated in the MQTT Broker the corresponding channel receives it and updates the linked Item. But as it was mentioned after a restart that update behaviour is broken.

With regards to the relevant behaviour of my script:

  1. it publishes the nodes according to the homie 3.0 specifications 
    homie/mifloramqtt/$fw/name miflora-firmware
homie/mifloramqtt/$fw/version 3.1.9
homie/mifloramqtt/$homie 3.0
homie/mifloramqtt/$name mifloramqtt
homie/mifloramqtt/$state ready
homie/mifloramqtt/$nodes Dracaena
homie/mifloramqtt/Dracaena/conductivity/$name conductivity
homie/mifloramqtt/Dracaena/conductivity/$settable false
homie/mifloramqtt/Dracaena/conductivity/$unit µS/cm
homie/mifloramqtt/Dracaena/conductivity/$datatype integer
homie/mifloramqtt/Dracaena/conductivity/$format 0:*
homie/mifloramqtt/Dracaena/conductivity/$retained true
homie/mifloramqtt/Dracaena/moisture/$name moisture
homie/mifloramqtt/Dracaena/moisture/$settable false
homie/mifloramqtt/Dracaena/moisture/$unit %
homie/mifloramqtt/Dracaena/moisture/$datatype integer
homie/mifloramqtt/Dracaena/moisture/$format 0:100
homie/mifloramqtt/Dracaena/moisture/$retained true
homie/mifloramqtt/Dracaena/battery/$name battery
homie/mifloramqtt/Dracaena/battery/$settable false
homie/mifloramqtt/Dracaena/battery/$unit %
homie/mifloramqtt/Dracaena/battery/$datatype integer
homie/mifloramqtt/Dracaena/battery/$format 0:100
homie/mifloramqtt/Dracaena/battery/$retained true
homie/mifloramqtt/Dracaena/light/$name light
homie/mifloramqtt/Dracaena/light/$settable false
homie/mifloramqtt/Dracaena/light/$unit lux
homie/mifloramqtt/Dracaena/light/$datatype integer
homie/mifloramqtt/Dracaena/light/$format 0:50000
homie/mifloramqtt/Dracaena/light/$retained true
homie/mifloramqtt/Dracaena/temperature/$name temperature
homie/mifloramqtt/Dracaena/temperature/$settable false
homie/mifloramqtt/Dracaena/temperature/$unit °C
homie/mifloramqtt/Dracaena/temperature/$datatype float
homie/mifloramqtt/Dracaena/temperature/$format *
homie/mifloramqtt/Dracaena/temperature/$retained true
homie/mifloramqtt/Dracaena/$name Dracaena
homie/mifloramqtt/Dracaena/$type miflora
homie/mifloramqtt/Dracaena/$properties battery,conductivity,light,moisture,temperature
  2. in given time interval it publishes the values of the nodes 
    homie/mifloramqtt/Dracaena/temperature 20.4
homie/mifloramqtt/Dracaena/battery 99
homie/mifloramqtt/Dracaena/light 179
homie/mifloramqtt/Dracaena/moisture 39

My observations:

My Env (openhabian-pi)

fischerman commented 5 years ago

I've noticed something similar with trigger channels (which toggle a switch item). Every time a Homie device goes offline and back online again I observe one more toggle per trigger. If I restart OpenHab I still get Homie device updates but the trigger channel stays silent. Only tested on 2.4

https://community.openhab.org/t/mqtt-homie-trigger-channel-silent-after-reboot/63489

spafrost commented 5 years ago

I have been pulling my hair out with this one, having just moved a couple of devices to Homie & the new MQTT 2.4 binding, and have been resetting, rebuilding and reflashing everything for a couple of days to find out where I messed up - so glad I am not the only one!

I have a,

Homie devices are (with 3x Homie 3.0), 


- **b4e62d23c915** -  DIY Smart Thermostat ( couple of control channels & couple of reporting channels) 
- **6001944c84e5** - An always on Temperature probe based on an ESP8266 with a single timer based temperature report 
- **ecfabc27291d** - An ESP-01 with DHT11 shield that deep sleeps and reports every 5 minutes

I am seeing the same behaviour as above, when freshly added all devices work until OpenHab is restarted at which point all my temperature reports go to NaN and stay that way despite normal MQTT traffic. I have noticed however, that the "control" channels still work, so toggling switches in OpenHab sends out the required MQTT command, and the Homie devices respond - but my temperatures and configuration "readback" that the Homie devices transmit periodically are ignored.

Again, removing and re-adding the devices cause them to start working again until OpenHab is restarted.

I have trimmed down my logs during startup (removed the Tradfri lights 250~ item status updates) , 


                          __  _____    ____
  ____  ____  ___  ____  / / / /   |  / __ )
 / __ \/ __ \/ _ \/ __ \/ /_/ / /| | / __  |
/ /_/ / /_/ /  __/ / / / __  / ___ |/ /_/ /
\____/ .___/\___/_/ /_/_/ /_/_/  |_/_____/
    /_/                        2.4.0
                               Release Build

Hit '<tab>' for a list of available commands
and '[cmd] --help' for help on a specific command.
Hit '<ctrl-d>' or type 'system:shutdown' or 'logout' to shutdown openHAB.

log:tail
openhab> log:tail
13:15:19.840 [INFO ] [mebuilder.internal.HomeBuilderServlet] - Started Home Builder at /homebuilder
13:15:19.964 [INFO ] [bpanel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
13:15:23.627 [INFO ] [.io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = [REDACTED], base URL = http://localhost:8080)
...
13:15:32.267 [INFO ] [rthome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
...
13:15:32.789 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HVAC.sitemap'
...
13:15:33.489 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'Control_LivingRoom_ControlOverride_Thermostat-mqtt:homie300:embedded-mqtt-broker:b4e62d23c915:mode#mode' has been added.
13:15:33.495 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'Control_LivingRoom_HeatCall_Thermostat-mqtt:homie300:embedded-mqtt-broker:b4e62d23c915:boiler#call' has been added.
13:15:33.495 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'Value_LivingRoom_Temperature_Thermostat-mqtt:homie300:embedded-mqtt-broker:b4e62d23c915:temperature#degrees' has been added.
13:15:33.497 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'Control_LivingRoom_Calibration_Thermostat-mqtt:homie300:embedded-mqtt-broker:b4e62d23c915:calib#calibration' has been added.
13:15:33.503 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'Value_Portable_Temperature_RedESPDHT-mqtt:homie300:embedded-mqtt-broker:ecfabc27291d:temperature#degrees' has been added.
13:15:33.504 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'Control_LivingRoom_MoTD_Thermostat-mqtt:homie300:embedded-mqtt-broker:b4e62d23c915:motd#message' has been added.
13:15:33.506 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'Value_Portable_HeadIndex_RedESPDH-mqtt:homie300:embedded-mqtt-broker:ecfabc27291d:heatindex#heatindex' has been added.
13:15:33.507 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'Control_LivingRoom_SetPoint_Thermostat-mqtt:homie300:embedded-mqtt-broker:b4e62d23c915:setpoint#setpoint' has been added.
13:15:33.508 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'Control_LivingRoom_TimeSync_Thermostat-mqtt:homie300:embedded-mqtt-broker:b4e62d23c915:time#time' has been added.
13:15:33.510 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'Value_Portable_Humidity_RedESPDHT-mqtt:homie300:embedded-mqtt-broker:ecfabc27291d:humidity#humidity' has been added.
13:15:33.511 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'Value_Portable_Temperature_Spocka-mqtt:homie300:embedded-mqtt-broker:6001944c84e5:temperature#degrees' has been added.
...
13:15:34.910 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:b4e62d23c915' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
13:15:34.914 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:ecfabc27291d' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
13:15:34.918 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:6001944c84e5' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
13:15:35.388 [INFO ] [i.dashboard.internal.DashboardService] - Started Dashboard at http://IP:8080
13:15:35.390 [INFO ] [i.dashboard.internal.DashboardService] - Started Dashboard at https://IP
 [INFO ] [marthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
...
13:15:36.796 [WARN ] [er.internal.EmbeddedBrokerServiceImpl] - Embedded broker offline - Reason unknown
13:15:36.960 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '127.0.0.1' with clientid embedded-mqtt-broker and file store '/var/lib/openhab2/mqtt/127.0.0.1'
13:15:37.063 [WARN ] [.moquette.spi.impl.SessionsRepository] - Session does not exist. CId=embedded-mqtt-broker
13:15:37.067 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:systemBroker:embedded-mqtt-broker' changed from UNINITIALIZED to INITIALIZING
13:15:37.080 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:systemBroker:embedded-mqtt-broker' changed from INITIALIZING to ONLINE
13:15:37.117 [WARN ] [.moquette.spi.impl.SessionsRepository] - Session does not exist. CId=embedded-mqtt-broker
13:15:37.131 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:b4e62d23c915' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
13:15:37.132 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:6001944c84e5' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
13:15:37.133 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:ecfabc27291d' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
13:15:37.438 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:b4e62d23c915' changed from INITIALIZING to OFFLINE (COMMUNICATION_ERROR): java.lang.Exception: Did not receive mandatory topic value: homie/b4e62d23c915/$homie
13:15:37.447 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:6001944c84e5' changed from INITIALIZING to OFFLINE (COMMUNICATION_ERROR): java.lang.Exception: Did not receive mandatory topic value: homie/6001944c84e5/$homie
13:15:37.464 [INFO ] [smarthome.event.ItemStateChangedEvent] - Control_LivingRoom_HeatCall_Thermostat changed from NULL to UNDEF
13:15:37.468 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:ecfabc27291d' changed from INITIALIZING to OFFLINE (COMMUNICATION_ERROR): java.lang.Exception: Did not receive mandatory topic value: homie/ecfabc27291d/$homie
13:15:37.483 [INFO ] [smarthome.event.ItemStateChangedEvent] - Value_LivingRoom_Temperature_Thermostat changed from NULL to UNDEF
13:15:37.484 [INFO ] [smarthome.event.ItemStateChangedEvent] - Control_LivingRoom_SetPoint_Thermostat changed from NULL to UNDEF
13:15:37.486 [INFO ] [smarthome.event.ItemStateChangedEvent] - Value_Portable_Temperature_Spocka changed from NULL to UNDEF
13:15:37.487 [INFO ] [smarthome.event.ItemStateChangedEvent] - Value_Portable_HeadIndex_RedESPDH changed from NULL to UNDEF
13:15:37.489 [INFO ] [smarthome.event.ItemStateChangedEvent] - Value_Portable_Humidity_RedESPDHT changed from NULL to UNDEF
13:15:37.489 [INFO ] [smarthome.event.ItemStateChangedEvent] - Control_LivingRoom_MoTD_Thermostat changed from NULL to UNDEF
13:15:37.491 [INFO ] [smarthome.event.ItemStateChangedEvent] - Value_Portable_Temperature_RedESPDHT changed from NULL to UNDEF
13:15:37.492 [INFO ] [smarthome.event.ItemStateChangedEvent] - Control_LivingRoom_ControlOverride_Thermostat changed from NULL to UNDEF
13:15:37.494 [INFO ] [smarthome.event.ItemStateChangedEvent] - Control_LivingRoom_Calibration_Thermostat changed from NULL to UNDEF
13:15:37.495 [INFO ] [smarthome.event.ItemStateChangedEvent] - Control_LivingRoom_TimeSync_Thermostat changed from NULL to UNDEF
...
13:15:39.943 [WARN ] [.moquette.spi.impl.SessionsRepository] - Session does not exist. CId=ESP8266 Client
13:15:39.948 [WARN ] [.moquette.spi.impl.SessionsRepository] - Session does not exist. CId=ESP8266 Client
13:15:55.822 [WARN ] [.moquette.spi.impl.SessionsRepository] - Session does not exist. CId=Homie-b4e62d23c915
13:15:55.825 [WARN ] [.moquette.spi.impl.SessionsRepository] - Session does not exist. CId=Homie-b4e62d23c915
13:15:55.887 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:b4e62d23c915' changed from OFFLINE (COMMUNICATION_ERROR): java.lang.Exception: Did not receive mandatory topic value: homie/b4e62d23c915/$homie to ONLINE (CONFIGURATION_PENDING)
13:15:55.997 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:b4e62d23c915' changed from ONLINE (CONFIGURATION_PENDING) to ONLINE
13:15:56.527 [WARN ] [.moquette.spi.impl.SessionsRepository] - Session does not exist. CId=Homie-6001944c84e5
13:15:56.529 [WARN ] [.moquette.spi.impl.SessionsRepository] - Session does not exist. CId=Homie-6001944c84e5
13:15:56.569 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:6001944c84e5' changed from OFFLINE (COMMUNICATION_ERROR): java.lang.Exception: Did not receive mandatory topic value: homie/6001944c84e5/$homie to ONLINE (CONFIGURATION_PENDING)
13:15:56.594 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:6001944c84e5' changed from ONLINE (CONFIGURATION_PENDING) to ONLINE
13:16:27.008 [WARN ] [.moquette.spi.impl.SessionsRepository] - Session does not exist. CId=Homie-ecfabc27291d
13:16:27.015 [WARN ] [.moquette.spi.impl.SessionsRepository] - Session does not exist. CId=Homie-ecfabc27291d
13:16:27.034 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:ecfabc27291d' changed from OFFLINE (COMMUNICATION_ERROR): java.lang.Exception: Did not receive mandatory topic value: homie/ecfabc27291d/$homie to ONLINE (CONFIGURATION_PENDING)
13:16:27.071 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:ecfabc27291d' changed from ONLINE (CONFIGURATION_PENDING) to ONLINE
13:16:27.342 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mqtt:homie300:embedded-mqtt-broker:ecfabc27291d' changed from ONLINE to ONLINE (DUTY_CYCLE)

I am a very out of practice dev, so I am going to do a little hunting around - but my first thought is that this might be related to the startup order, as I can see a couple of warnings popping up above before the broker comes online - although that could be completely normal for all i know !

pavax commented 5 years ago

@spafrost I can relate to your frustration - it took me also a couple of days and multiple re-installs to realise that the problem can not only be on my side but that there has to be some bug in openhab/eclipse-smarthome.

Since we've established that removing and adding the thing again is one way to get around that problem it might be useful if someone else can confirm the second workaround that I've encountered.

  1. Add the MQTT-Homie Thing and Link the Items
  2. Restart the openhab-service
  3. Check that the values are not updated anymore (should show NaN in the control panel)
  4. Stop your script/home device from publishing further messages
  5. Delete all the retained messages in your broker (e.g using the following script based on mosquitto client and assuming the default port 1883 is used) 
    #!/bin/sh
echo "cleaning " $1 " :: usage: cleanmqtt <host>"
mosquitto_sub -h $1 -t "#" -v | while read line _; do mosquitto_pub -h $1 -t "$line" -r -n; done
    ./delete_mqtt_messages.sh <Broker-Hostname/IP>
  6. Make sure that your script/homie device adds all the nodes and values again by publishing all messages again to the broker
  7. Check that the values are now again updated and keep updating
davidgraeff commented 5 years ago

Could you guys please also try out to disable a Thing and re-enable it again? (Possible via the console / rest / Paper UI)

I have no straight explanation for this behaviour to be honest. The homie code shares a lot with the generic mqtt Thing code and those Things work also on start-up.

pavax commented 5 years ago

@davidgraeff I disabled and re-enabled the Thing using Paper-UI.

... then I published a new value: mosquitto_pub -h openhabianpi -p 1883 -t homie/mifloramqtt/Dracaena/light -m "18" -r

... the values is still not changed for the MQTT-Home Thing (it is changed for the MQTT-Generic-Thing but I disabled it for this test-scenario)

Log-Viewer output (disabling the generic-mqtt-thing, disabling the homie-thing, re-enabling the homie thing)

2019-01-13 18:30:17.176 [hingStatusInfoChangedEvent] - 'mqtt:topic:mosquitto:generic-mifloara' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)

2019-01-13 18:30:27.662 [hingStatusInfoChangedEvent] - 'mqtt:homie300:mosquitto:mifloramqtt' changed from ONLINE to UNINITIALIZED

2019-01-13 18:30:27.673 [hingStatusInfoChangedEvent] - 'mqtt:homie300:mosquitto:mifloramqtt' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)

2019-01-13 18:30:33.827 [hingStatusInfoChangedEvent] - 'mqtt:homie300:mosquitto:mifloramqtt' changed from UNINITIALIZED (DISABLED) to INITIALIZING

==> /var/log/openhab2/openhab.log <==

2019-01-13 18:30:33.835 [DEBUG] [nternal.convention.homie300.Property] - Cannot convert * to a number

2019-01-13 18:30:33.861 [DEBUG] [nternal.convention.homie300.Property] - Cannot convert * to a number

2019-01-13 18:30:33.882 [DEBUG] [nternal.convention.homie300.Property] - Cannot convert * to a number

2019-01-13 18:30:33.905 [DEBUG] [nternal.convention.homie300.Property] - Cannot convert * to a number

2019-01-13 18:30:33.922 [DEBUG] [nternal.convention.homie300.Property] - Cannot convert * to a number

==> /var/log/openhab2/events.log <==

2019-01-13 18:30:33.940 [hingStatusInfoChangedEvent] - 'mqtt:homie300:mosquitto:mifloramqtt' changed from INITIALIZING to ONLINE
davidgraeff commented 5 years ago

Alright, thanks. I think I know where it fails then.

pavax commented 5 years ago

@davidgraeff dunno if it helps you but what is weird that I never get to see the log-entry: homie device {} fully attached after I restart the openhab-serivice. Only after I re-attach the thing or as I mentioned remove all the retained messages. So to me it looks like that the following startChannels-callback is not invoked after a restart.

HomieThingHandler.java

 @Override
    public void accept(@Nullable List<Object> t) {
        if (!device.isInitialized()) {
            return;
        }

        List<Channel> channels = device.nodes().stream().flatMap(n -> n.properties.stream())
                .map(prop -> prop.getChannel()).collect(Collectors.toList());
        updateThing(editThing().withChannels(channels).build());
        updateProperty(MqttBindingConstants.HOMIE_PROPERTY_VERSION, device.attributes.homie);

        final MqttBrokerConnection connection = this.connection;
        if (connection != null) {
            device.startChannels(connection, scheduler, attributeReceiveTimeout, this).thenRun(() -> {
                logger.trace("Homie device {} fully attached", device.attributes.name);
            });
        }
    }
davidgraeff commented 5 years ago

Exactly. The culprit is in https://github.com/eclipse/smarthome/blob/master/extensions/binding/org.eclipse.smarthome.binding.mqtt.generic/src/main/java/org/eclipse/smarthome/binding/mqtt/generic/internal/convention/homie300/Device.java#L234

    public void initialize(String baseTopic, String deviceID, List<Channel> channels) {
        this.topic = baseTopic + "/" + deviceID;
        this.deviceID = deviceID;
        nodes.clear();
        for (Channel channel : channels) {
            final String nodeID = channel.getUID().getGroupId();
            final String propertyID = channel.getUID().getIdWithoutGroup();
            if (nodeID == null) {
                continue;
            }
            Node node = nodes.get(nodeID);
            if (node == null) {
                node = createNode(nodeID);
                node.nodeRestoredFromConfig();
                nodes.put(nodeID, node);
            }
            // Restores the properties attribute object via the channels configuration.
            Property property = node.createProperty(propertyID,
                    channel.getConfiguration().as(PropertyAttributes.class));
            property.createChannelFromAttribute();

            node.properties.put(propertyID, property);
        }
    }

openHAB knows about the Things/channels from its loaded configuration. This method recreates the internal Node/Property structure. But the re-subscribing to the property values is not performed apparently.

ddecockbe commented 5 years ago

Is there a workaround available?

enricogallesio commented 5 years ago

hey! I have the same issue with my auto discovered homie compliant mqtt's. I'm a beginner with openhab, I have a fresh openhabian on raspberry and after spending some time to make all my DIY mqtt sensors homie conventions compliant, and after making sure they worked, I casually rebooted and suddenly all of the readings in paper ui give NaN.

Any way to fix this or at least to make a workaround automatically executed at startup? thank you in advance!

davidgraeff commented 5 years ago

There is unfortunately no workaround, at the same time I cannot work on mqtt for the next weeks. Busy with the Paper UI NG design study in my free time already.

ddecockbe commented 5 years ago

Hi David,

I understand you're already sacrificing your free time to another project and I appreciate the work you have done so far. It's just a pity you promoted to switch to homie on Smart Home Day while it's not yet working. The auto-discovery was amazing, so I was a fan of this solution as soon as I discovered it, but we end up with a broken system at this point. I will investigate if I can fix this issue, but it will cost me a lot more time because I'm missing a log of background information.

davidgraeff commented 5 years ago

switch to homie on Smart Home Day while it's not yet working.

I worked perfectly. But some people contributed already and at some point it broke. My fault was that I didn't contribute a test case to catch that error in the first place, I think.

It's tough times at the moment to contribute, because of all those package movements.

ddecockbe commented 5 years ago

Ok, David, sorry for blaming. I will see if I can find a reason why it's broken.

pavax commented 5 years ago

@ddecockbe I've been playing around with that issue as well.... It took me quite a while to setup a openhab eclipse IDE in order to debug that issue. I narrowed the problem down the the following lines that I changed (see here: https://github.com/pavax/openhab2-addons/pull/1/files).

PS: I'm aware that the openhab2-addons is a different repository (I haven't figured yet out how to clone the smarthome repository into the openhab-eclipse IDE and deploy the correct plugins) also I haven't yet run the unit tests

ddecockbe commented 5 years ago

Hi @pavax, thanks!

I will try that and will keep you updated!

davidgraeff commented 5 years ago

@pavax That's a perfect fix. Please open a pull request to openhab2-addons (you are on the right repository, this one here will be soon discontinued).

pavax commented 5 years ago

@davidgraeff Thx - I'll open a PR asap (it took me a bit longer since I stumbled across another bug+fix which I pushed as well to my branch) - I'd like to create some unit tests as well and ideally get the confirmation that these fixes work from someone else that patched the bundles.

@ddecockbe If you find the time I'd appreciate if you could either checkout my branch and build the modules: org.openhab.binding.mqtt and org.openhab.binding.mqtt.generic or if you want (and trust me :) you can download the patched jars here: https://uploadfiles.io/f0g2v, https://uploadfiles.io/b32je

How did I install the patched bundles on my openhabian-pi?

openhab> bundle:list | grep MQTT
219 │ Active   │  80 │ 1.2.0                  │ Paho MQTT Client
223 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome MQTT Transport Bundle
245 │ Active   │  80 │ 2.5.0.201901270036     │ MQTT Thing Binding
246 │ Active   │  80 │ 2.5.0.201901270038     │ MQTT Binding
ddecockbe commented 5 years ago

@pavax I took the risk to trust you ;). I installed the jars and the are working fine here. I restarted openhab and all my homie items came back as they should. Thanks a lot! I can now further 'homie'-fy my home-brew sensors.

euphi commented 5 years ago

I also tested the jars. The one device that was configured as Homie Thing seems to reconnect the channels correctly after restart.

However, some (not all) legacy MQTT devices DID NOT!

So Items linked to their channels were not updated.

After opening on channel of an affected Thing and Saving it (no change), all channels of this thing now work ok again.

I don't have logs of startup, but some logs of the moment a channel was reconfigured:

23:17:10.686 [DEBUG] [c.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_kitchen:rgb1
23:17:10.732 [DEBUG] [c.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_kitchen:rgb2
23:17:10.770 [DEBUG] [c.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_kitchen:white
23:17:10.822 [DEBUG] [c.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_kitchen:sens_temp
23:17:10.887 [DEBUG] [c.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_kitchen:sens_hum
23:17:10.909 [DEBUG] [c.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_kitchen:wifi
23:17:10.941 [DEBUG] [generic.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_kitchen:white to topic: homie/kueche/LED/w
23:17:10.980 [INFO ] [smarthome.event.ItemStateEvent       ] - kueche_led_W updated to 0
23:17:10.973 [DEBUG] [generic.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_kitchen:rgb2 to topic: homie/kueche/LED2/c
23:17:11.021 [DEBUG] [generic.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_kitchen:rgb1 to topic: homie/kueche/LED/c
23:17:11.044 [DEBUG] [generic.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_kitchen:sens_hum to topic: homie/kueche/Sensor/rel%
23:17:11.090 [DEBUG] [generic.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_kitchen:sens_temp to topic: homie/kueche/Sensor/degrees
23:17:11.091 [INFO ] [smarthome.event.ItemStateEvent       ] - kueche_humidity updated to 55.64
23:17:11.122 [DEBUG] [generic.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_kitchen:wifi to topic: homie/kueche/$stats/signal
23:17:11.166 [INFO ] [smarthome.event.ItemStateChangedEvent] - kueche_humidity changed from 62.95 to 55.64
23:17:11.264 [INFO ] [home.event.GroupItemStateChangedEvent] - gHumidity changed from 45.73 to 43.90 through kueche_humidity                                                                                                                
23:17:11.337 [INFO ] [smarthome.event.ItemStateEvent       ] - kueche_temp updated to 20.94                                                                                                                                                 
23:17:11.369 [INFO ] [home.event.GroupItemStateChangedEvent] - gTemperature changed from 22.57 to 22.52 through kueche_temp                                                                                                                 
23:17:11.548 [INFO ] [smarthome.event.RuleStatusInfoEvent  ] - f631c203-d760-44c9-8ec7-e55336f04b23 updated: RUNNING                                                                                                                        
23:17:11.562 [INFO ] [smarthome.event.ItemStateChangedEvent] - kueche_temp changed from 21.29 °C to 20.94 °C                                                                                                                                
23:17:11.591 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'mqtt:topic:homie_leg_kitchen' has been updated.                                                                                                                       
23:17:11.613 [INFO ] [smarthome.event.ItemStateEvent       ] - kueche_signal updated to 30                                                                                                                                                  
23:17:11.632 [INFO ] [smarthome.event.ItemStateChangedEvent] - kueche_signal changed from 34 to 30
euphi commented 5 years ago

Found some logs/exceptions just after startup:

2019-01-27 19:12:37.878 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.mqtt.generic.internal.handler.HomieThingHandler@aeff7f': Label for a Cha
java.lang.IllegalArgumentException: Label for a ChannelType must not be empty.
        at org.eclipse.smarthome.core.thing.internal.type.AbstractChannelTypeBuilder.<init>(AbstractChannelTypeBuilder.java:52) ~[?:?]
        at org.eclipse.smarthome.core.thing.internal.type.StateChannelTypeBuilderImpl.<init>(StateChannelTypeBuilderImpl.java:40) ~[?:?]
        at org.eclipse.smarthome.core.thing.type.ChannelTypeBuilder.state(ChannelTypeBuilder.java:94) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Property.createChannelType(Property.java:135) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Property.createChannelFromAttribute(Property.java:210) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Device.initialize(Device.java:211) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.handler.HomieThingHandler.initialize(HomieThingHandler.java:102) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [102:org.eclipse.smarthome.core:0.10.0.oh240]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [102:org.eclipse.smarthome.core:0.10.0.oh240]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2019-01-27 19:12:37.964 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_heizung:hzg_out_1
2019-01-27 19:12:37.947 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:test_rollershutter:rshut1
2019-01-27 19:12:37.936 [DEBUG] [c.internal.handler.HomieThingHandler] - About to stop Homie device null
2019-01-27 19:12:38.097 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_heizung:hzg_out_2
2019-01-27 19:12:37.915 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.mqtt.generic.internal.handler.HomieThingHandler@1b14232': 1
java.lang.ArrayIndexOutOfBoundsException: 1
        at org.eclipse.smarthome.core.thing.ChannelUID.getIdWithoutGroup(ChannelUID.java:151) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Device.initialize(Device.java:198) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.handler.HomieThingHandler.initialize(HomieThingHandler.java:102) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [102:org.eclipse.smarthome.core:0.10.0.oh240]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [102:org.eclipse.smarthome.core:0.10.0.oh240]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2019-01-27 19:12:38.351 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:85039ce9:alert
2019-01-27 19:12:38.101 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'mqtt:homie300:cf9ca1aa:thermo_ian': Label for a ChannelType must not be empty.
java.lang.IllegalArgumentException: Label for a ChannelType must not be empty.
        at org.eclipse.smarthome.core.thing.internal.type.AbstractChannelTypeBuilder.<init>(AbstractChannelTypeBuilder.java:52) ~[?:?]
        at org.eclipse.smarthome.core.thing.internal.type.StateChannelTypeBuilderImpl.<init>(StateChannelTypeBuilderImpl.java:40) ~[?:?]
        at org.eclipse.smarthome.core.thing.type.ChannelTypeBuilder.state(ChannelTypeBuilder.java:94) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Property.createChannelType(Property.java:135) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Property.createChannelFromAttribute(Property.java:210) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Device.initialize(Device.java:211) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.handler.HomieThingHandler.initialize(HomieThingHandler.java:102) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [102:org.eclipse.smarthome.core:0.10.0.oh240]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [102:org.eclipse.smarthome.core:0.10.0.oh240]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2019-01-27 19:12:38.355 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:78e01be4:sens_temp
2019-01-27 19:12:38.288 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'mqtt:homie300:cf9ca1aa:lab_thermo': 1
java.lang.ArrayIndexOutOfBoundsException: 1
        at org.eclipse.smarthome.core.thing.ChannelUID.getIdWithoutGroup(ChannelUID.java:151) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Device.initialize(Device.java:198) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.handler.HomieThingHandler.initialize(HomieThingHandler.java:102) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [102:org.eclipse.smarthome.core:0.10.0.oh240]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [102:org.eclipse.smarthome.core:0.10.0.oh240]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2019-01-27 19:12:38.276 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '192.168.0.220' with clientid paho1490139038251690 and file store '/var/lib/openhab2/mqtt/192.168.0.220'
2019-01-27 19:12:38.267 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_heizung:hzg_out_3
2019-01-27 19:12:38.954 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_heizung:hzg_out_4
2019-01-27 19:12:38.954 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:78e01be4:sens_hum
2019-01-27 19:12:38.963 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:85039ce9:warning
2019-01-27 19:12:38.986 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_heizung:hzg_out_5
2019-01-27 19:12:38.991 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:85039ce9:notification
2019-01-27 19:12:39.007 [DEBUG] [c.internal.handler.HomieThingHandler] - About to initialize Homie device null
2019-01-27 19:12:39.033 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:85039ce9:time
2019-01-27 19:12:39.032 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:78e01be4:led1
2019-01-27 19:12:39.056 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:78e01be4:led2
2019-01-27 19:12:39.033 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_heizung:hzg_out_6
2019-01-27 19:12:39.217 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:78e01be4:contact0
2019-01-27 19:12:39.224 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:78e01be4:contact1
2019-01-27 19:12:39.213 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_heizung:hzg_out_7
2019-01-27 19:12:39.242 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:78e01be4:wifi
2019-01-27 19:12:39.250 [DEBUG] [c.internal.handler.HomieThingHandler] - About to stop Homie device null
2019-01-27 19:12:39.261 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_kitchen:rgb1
2019-01-27 19:12:39.300 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_heizung:hzg_out_8
2019-01-27 19:12:39.332 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_kitchen:rgb2
2019-01-27 19:12:39.345 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_heizung:hzg_out_9
2019-01-27 19:12:39.373 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_heizung:hzg_out_10
2019-01-27 19:12:39.402 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_kitchen:white
2019-01-27 19:12:39.357 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_wz_temp:sens_temp
2019-01-27 19:12:39.428 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_kitchen:sens_temp
2019-01-27 19:12:39.433 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_heizung:hzg_out_12
2019-01-27 19:12:39.438 [DEBUG] [c.internal.handler.HomieThingHandler] - About to initialize Homie device null
2019-01-27 19:12:39.429 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_aldoni:led1
2019-01-27 19:12:39.424 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_wz_temp:sens_hum
2019-01-27 19:12:39.468 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_kitchen:sens_hum
2019-01-27 19:12:39.498 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_wz_temp:set_temp
2019-01-27 19:12:39.511 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_kitchen:wifi
2019-01-27 19:12:39.525 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_wz_temp:mode
2019-01-27 19:12:39.496 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_aldoni:led2
2019-01-27 19:12:39.569 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_aldoni:sens_temp
2019-01-27 19:12:39.603 [DEBUG] [c.internal.handler.HomieThingHandler] - About to start Homie device null
2019-01-27 19:12:39.627 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_aldoni:sens_hum
2019-01-27 19:12:39.664 [DEBUG] [.MqttChannelStateDescriptionProvider] - Adding state description for channel mqtt:topic:homie_leg_aldoni:wifi
2019-01-27 19:12:39.852 [DEBUG] [c.internal.handler.HomieThingHandler] - About to start Homie device null
2019-01-27 19:12:40.470 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_heizung:hzg_out_6 to topic: homie/hzgctrl/Relais/in_6
2019-01-27 19:12:40.506 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:test_rollershutter:rshut1 to topic: homie/lab_rshut/shutter1/state
2019-01-27 19:12:40.665 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_heizung:hzg_out_7 to topic: homie/hzgctrl/Relais/in_7
2019-01-27 19:12:40.715 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_heizung:hzg_out_10 to topic: homie/hzgctrl/Relais/in_10
2019-01-27 19:12:40.775 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_heizung:hzg_out_8 to topic: homie/hzgctrl/Relais/in_8
2019-01-27 19:12:40.886 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_heizung:hzg_out_9 to topic: homie/hzgctrl/Relais/in_9
2019-01-27 19:12:40.924 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_heizung:hzg_out_2 to topic: homie/hzgctrl/Relais/in_2
2019-01-27 19:12:41.330 [DEBUG] [c.internal.handler.HomieThingHandler] - About to start Homie device null
2019-01-27 19:12:41.348 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_heizung:hzg_out_3 to topic: homie/hzgctrl/Relais/in_3
2019-01-27 19:12:41.552 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_heizung:hzg_out_4 to topic: homie/hzgctrl/Relais/in_4
2019-01-27 19:12:41.651 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_heizung:hzg_out_5 to topic: homie/hzgctrl/Relais/in_5
2019-01-27 19:12:41.763 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_heizung:hzg_out_12 to topic: homie/hzgctrl/Relais/in_12
2019-01-27 19:12:41.841 [DEBUG] [c.internal.handler.HomieThingHandler] - About to start Homie device null
2019-01-27 19:12:41.859 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_heizung:hzg_out_1 to topic: homie/hzgctrl/Relais/in_1
2019-01-27 19:12:41.996 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_aldoni:led1 to topic: homie/thermo_AldoniOG/LED/c
2019-01-27 19:12:42.122 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_aldoni:led2 to topic: homie/thermo_AldoniOG/LED2/c
2019-01-27 19:12:42.222 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_aldoni:sens_hum to topic: homie/thermo_AldoniOG/Sensor/rel%
2019-01-27 19:12:42.301 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_aldoni:sens_temp to topic: homie/thermo_AldoniOG/Sensor/degrees
2019-01-27 19:12:42.435 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_aldoni:wifi to topic: homie/thermo_AldoniOG/$stats/signal
2019-01-27 19:12:43.131 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:78e01be4:wifi to topic: homie/sz/$stats/signal
2019-01-27 19:12:43.772 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:78e01be4:contact0 to topic: homie/sz/Input/pin_0
2019-01-27 19:12:43.821 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:78e01be4:sens_temp to topic: homie/sz/Sensor/degrees
2019-01-27 19:12:43.853 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:78e01be4:sens_hum to topic: homie/sz/Sensor/rel%
2019-01-27 19:12:43.920 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:78e01be4:led2 to topic: homie/sz/LED_W2/w
2019-01-27 19:12:43.961 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:78e01be4:led1 to topic: homie/sz/LED_W1/w
2019-01-27 19:12:44.005 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:78e01be4:contact1 to topic: homie/sz/Input/pin_1
2019-01-27 19:12:44.132 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_kitchen:white to topic: homie/kueche/LED/w
2019-01-27 19:12:44.190 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_kitchen:rgb2 to topic: homie/kueche/LED2/c
2019-01-27 19:12:44.279 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_kitchen:rgb1 to topic: homie/kueche/LED/c
2019-01-27 19:12:44.332 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_kitchen:sens_hum to topic: homie/kueche/Sensor/rel%
2019-01-27 19:12:44.378 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_kitchen:sens_temp to topic: homie/kueche/Sensor/degrees
2019-01-27 19:12:44.418 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_kitchen:wifi to topic: homie/kueche/$stats/signal
2019-01-27 19:12:44.665 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_wz_temp:sens_hum to topic: homie/wz_thermo/Sensor/rel%
2019-01-27 19:12:44.702 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_wz_temp:set_temp to topic: homie/wz_thermo/Thermostat/SetTemp
2019-01-27 19:12:44.760 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_wz_temp:sens_temp to topic: homie/wz_thermo/Sensor/degrees
2019-01-27 19:12:44.864 [WARN ] [l.mapping.AbstractMqttAttributeClass] - Could not assign value [Log, Relais[]] to field public java.lang.String[] org.openhab.binding.mqtt.generic.internal.convention.homie300.DeviceAttributes.nodes
java.lang.IllegalArgumentException: ID segment 'homie_LAB_hzgctrl_Relais[]' contains invalid characters. Each segment of the ID must match the pattern [A-Za-z0-9_-]*.
        at org.eclipse.smarthome.core.common.AbstractUID.validateSegment(AbstractUID.java:97) ~[?:?]
        at org.eclipse.smarthome.core.common.AbstractUID.<init>(AbstractUID.java:75) ~[?:?]
        at org.eclipse.smarthome.core.common.AbstractUID.<init>(AbstractUID.java:58) ~[?:?]
        at org.eclipse.smarthome.core.thing.UID.<init>(UID.java:57) ~[?:?]
        at org.eclipse.smarthome.core.thing.type.ChannelGroupTypeUID.<init>(ChannelGroupTypeUID.java:40) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Node.<init>(Node.java:72) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Device.createNode(Device.java:228) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.tools.ChildMap.lambda$2(ChildMap.java:89) ~[?:?]
        at java.util.stream.Collectors.lambda$toMap$58(Collectors.java:1321) ~[?:?]
        at java.util.stream.ReduceOps$3ReducingSink.accept(ReduceOps.java:169) ~[?:?]
        at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175) ~[?:?]
        at java.util.HashMap$KeySpliterator.forEachRemaining(HashMap.java:1553) ~[?:?]
        at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481) ~[?:?]
        at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471) ~[?:?]
        at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708) ~[?:?]
        at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:?]
        at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.tools.ChildMap.apply(ChildMap.java:89) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Device.applyNodes(Device.java:263) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Device.attributesReceived(Device.java:123) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Device.attributeChanged(Device.java:278) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.mapping.AbstractMqttAttributeClass.fieldChanged(AbstractMqttAttributeClass.java:309) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.mapping.SubscribeFieldToMQTTtopic.processMessage(SubscribeFieldToMQTTtopic.java:155) ~[?:?]
        at org.eclipse.smarthome.io.transport.mqtt.internal.ClientCallback.lambda$3(ClientCallback.java:90) ~[?:?]
        at java.util.ArrayList.forEach(ArrayList.java:1257) [?:?]
        at org.eclipse.smarthome.io.transport.mqtt.internal.ClientCallback.messageArrived(ClientCallback.java:90) [216:org.eclipse.smarthome.io.transport.mqtt:0.10.0.oh240]
        at org.eclipse.paho.client.mqttv3.internal.CommsCallback.deliverMessage(CommsCallback.java:499) [212:org.eclipse.paho.client.mqttv3:1.2.0]
        at org.eclipse.paho.client.mqttv3.internal.CommsCallback.handleMessage(CommsCallback.java:402) [212:org.eclipse.paho.client.mqttv3:1.2.0]
        at org.eclipse.paho.client.mqttv3.internal.CommsCallback.run(CommsCallback.java:206) [212:org.eclipse.paho.client.mqttv3:1.2.0]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2019-01-27 19:12:45.633 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_wz_temp:mode to topic: homie/wz_thermo/Thermostat/Mode
2019-01-27 19:12:46.118 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_aldoni:sens_hum to topic: homie/thermo_AldoniOG/Sensor/rel%
2019-01-27 19:12:46.169 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_aldoni:sens_temp to topic: homie/thermo_AldoniOG/Sensor/degrees
2019-01-27 19:12:46.226 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:topic:homie_leg_aldoni:wifi to topic: homie/thermo_AldoniOG/$stats/signal
2019-01-27 19:12:46.533 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:homie300:cf9ca1aa:lab_rshut:Log#Level to topic: homie/lab_rshut/Log/Level
2019-01-27 19:12:46.653 [WARN ] [l.mapping.AbstractMqttAttributeClass] - Could not assign value Heizungscontroller to field public java.lang.String org.openhab.binding.mqtt.generic.internal.convention.homie300.DeviceAttributes.name
java.lang.IllegalArgumentException: ID segment 'homie_LAB_hzgctrl_Relais[]' contains invalid characters. Each segment of the ID must match the pattern [A-Za-z0-9_-]*.
        at org.eclipse.smarthome.core.common.AbstractUID.validateSegment(AbstractUID.java:97) ~[?:?]
        at org.eclipse.smarthome.core.common.AbstractUID.<init>(AbstractUID.java:75) ~[?:?]
        at org.eclipse.smarthome.core.common.AbstractUID.<init>(AbstractUID.java:58) ~[?:?]
        at org.eclipse.smarthome.core.thing.UID.<init>(UID.java:57) ~[?:?]
        at org.eclipse.smarthome.core.thing.type.ChannelGroupTypeUID.<init>(ChannelGroupTypeUID.java:40) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Node.<init>(Node.java:72) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Device.createNode(Device.java:228) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.tools.ChildMap.lambda$2(ChildMap.java:89) ~[?:?]
        at java.util.stream.Collectors.lambda$toMap$58(Collectors.java:1321) ~[?:?]
        at java.util.stream.ReduceOps$3ReducingSink.accept(ReduceOps.java:169) ~[?:?]
        at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175) ~[?:?]
        at java.util.HashMap$KeySpliterator.forEachRemaining(HashMap.java:1553) ~[?:?]
        at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481) ~[?:?]
        at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471) ~[?:?]
        at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708) ~[?:?]
        at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:?]
        at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.tools.ChildMap.apply(ChildMap.java:89) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Device.applyNodes(Device.java:263) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Device.attributesReceived(Device.java:123) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.convention.homie300.Device.attributeChanged(Device.java:278) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.mapping.AbstractMqttAttributeClass.fieldChanged(AbstractMqttAttributeClass.java:309) ~[?:?]
        at org.openhab.binding.mqtt.generic.internal.mapping.SubscribeFieldToMQTTtopic.processMessage(SubscribeFieldToMQTTtopic.java:155) ~[?:?]
        at org.eclipse.smarthome.io.transport.mqtt.internal.ClientCallback.lambda$3(ClientCallback.java:90) ~[?:?]
        at java.util.ArrayList.forEach(ArrayList.java:1257) [?:?]
        at org.eclipse.smarthome.io.transport.mqtt.internal.ClientCallback.messageArrived(ClientCallback.java:90) [216:org.eclipse.smarthome.io.transport.mqtt:0.10.0.oh240]
        at org.eclipse.paho.client.mqttv3.internal.CommsCallback.deliverMessage(CommsCallback.java:499) [212:org.eclipse.paho.client.mqttv3:1.2.0]
        at org.eclipse.paho.client.mqttv3.internal.CommsCallback.handleMessage(CommsCallback.java:402) [212:org.eclipse.paho.client.mqttv3:1.2.0]
        at org.eclipse.paho.client.mqttv3.internal.CommsCallback.run(CommsCallback.java:206) [212:org.eclipse.paho.client.mqttv3:1.2.0]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2019-01-27 19:12:47.421 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:homie300:cf9ca1aa:lab_rshut:Log#LogSerial to topic: homie/lab_rshut/Log/LogSerial
2019-01-27 19:12:47.456 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:homie300:cf9ca1aa:lab_rshut:shutter1#auto-learn to topic: homie/lab_rshut/shutter1/auto-learn
2019-01-27 19:12:47.507 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:homie300:cf9ca1aa:lab_rshut:shutter1#moving to topic: homie/lab_rshut/shutter1/moving
2019-01-27 19:12:47.546 [WARN ] [eneric.internal.generic.ChannelState] - Command 'DOWN' not supported by type 'TextValue': Value DOWN not within range

2019-01-27 19:12:47.583 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:homie300:cf9ca1aa:lab_rshut:shutter1#state to topic: homie/lab_rshut/shutter1/state
2019-01-27 19:12:47.695 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:homie300:cf9ca1aa:lab_rshut:shutter2#auto-learn to topic: homie/lab_rshut/shutter2/auto-learn
2019-01-27 19:12:47.724 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:homie300:cf9ca1aa:lab_rshut:shutter2#moving to topic: homie/lab_rshut/shutter2/moving
2019-01-27 19:12:47.763 [DEBUG] [eneric.internal.generic.ChannelState] - Subscribed channel mqtt:homie300:cf9ca1aa:lab_rshut:shutter2#state to topic: homie/lab_rshut/shutter2/state
2019-01-27 19:12:48.175 [DEBUG] [c.internal.handler.HomieThingHandler] - Homie device HomieRollershutter fully attached
2019-01-27 19:13:07.936 [INFO ] [tomation.jsr223.jython.startup_delay] - Complete

The channels seem to be updated after this, but a little bit later the following happens and channels are no longer updated.


2019-01-27 19:47:41.285 [DEBUG] [c.internal.handler.HomieThingHandler] - About to stop Homie device null
2019-01-27 19:47:59.184 [DEBUG] [c.internal.handler.HomieThingHandler] - About to stop Homie device HomieBME280
2019-01-27 19:48:04.425 [DEBUG] [c.internal.handler.HomieThingHandler] - About to stop Homie device null
2019-01-27 19:48:10.412 [DEBUG] [c.internal.handler.HomieThingHandler] - About to stop Homie device HomieRollershutter

The devices HomieRollershutter and HomieBME280 are offline (in another network), so this may be ok to stop them? (But why half an hour after restart?)

I don't know which devices are "null"? Some of the "disconnected" legacy devices where using Homie convention 3.0, some not.

davidgraeff commented 5 years ago

So Items linked to their channels were not updated.

You mean the Generic Thing?

java.lang.IllegalArgumentException: ID segment 'homie_LAB_hzgctrl_Relais[]'

Uih. That looks bad. I already noticed that I do not sanitize mqtt topics before using them as openHAB channels. So dashes, brackets and all kind of other non latin characters will cause problems atm.

And yes the code is absolutely lost if no $name has been send in time, which might explain the java.lang.IllegalArgumentException: Label for a ChannelType must not be empty..

(But why half an hour after restart?)

That depends on the heartbeat and last will publishing setting of your broker.

euphi commented 5 years ago

So Items linked to their channels were not updated.

You mean the Generic Thing?

Yes. These devices are all Homie devices, but some to version 2 of the convention, some to version 3.

java.lang.IllegalArgumentException: ID segment 'homie_LAB_hzgctrl_Relais[]'

Uih. That looks bad. I already noticed that I do not sanitize mqtt topics before using them as openHAB channels. So dashes, brackets and all kind of other non latin characters will cause problems atm. Ok. I know that Node Arrays are not yet supported, but this is actually the device of my array usecase... ;-)

And yes the code is absolutely lost if no $name has been send in time, which might explain the java.lang.IllegalArgumentException: Label for a ChannelType must not be empty..

All the $names have been stored as retained message, so they should be available. Maybe its a timing issue? My openhab instance is running on an old arm h7 dual-cpu. Startup of Openhab takes several minutes.

euphi commented 5 years ago

Regarding the "no longer updated" channels. Most devices were affected, including all "homie convention 3.0.1" devices and some 2.0.0 devices:

ian@pc:~$ mosquitto_sub -v -h cubietruck -t homie/+/\$homie
homie/kueche/$homie 2.0.0                <----- channels/items not updated after 30min
homie/thermo_ian/$homie 3.0.1   <-- device I tested the binding with. Was OK as Homie Thing. After deleting it and configuring it as generic MQTT Thing, one of the channel was working only for some minutes? Other channel are ok. The "lost channel" started working again, after reconfiguring the Channel. (Deletion/Reconfiguration was after the other devices lost communication).
homie/thermo_AldoniOG/$homie 2.0.0 <----- channels/items not updated after 30min
homie/balkctrl2/$homie 2.0.0 <----- don't know (sensor error, so no updates sent)
homie/hzgctrl/$homie 2.0.0 <----- OK (no sensors connected, but commands handled correctly incl. feedback)
homie/wz_thermo/$homie 2.0.0 <----- OK
homie/ian_led/$homie 2.0.0 <----- channels/items not updated after 30min
homie/sz/$homie 2.0.0 <----- channels/items not updated after 30min

homie/lab_thermo/$homie 3.0.1 <----- offline, but retained
homie/lab_rshut/$homie 3.0.1 <----- offline, but retained
homie/lab_bme280/$homie 3.0.1  <----- offline, but retained
homie/LAB_hzgctrl/$homie 3.0.1 <----- offline, but retained
homie/wz_led/$homie 3.0.1 <---- offline, but retained
davidgraeff commented 5 years ago

Startup of Openhab takes several minutes.

I know, it's time for a different input file format. XText based files (.thing/.item/.rule) are slow as hell. I don't know if you were part of that heated discussion in the OH forum.

All the $names have been stored as retained message, so they should be available.

I have a ridiculously short wait time only (200ms), I was surprised when I saw that recently. So that could be the problem. Really sad that we have no "done" signal in the MQTT protocol for a topic tree transmission.

Oh and very important: Increase the limit of retained messages in mosquitto. A lot of users had problems. The default seem to be very low.

pavax commented 5 years ago

So Items linked to their channels were not updated.

strange.... I didn't change anything that should interfere with the Generic-Thing Handler :/ However since I used the master branch it could be that since the release of OH 2.4 other changes have been merged that could cause side-effects... Could it be, that the Generic-Thing Channel is not being updated when at the same time there is also a Homie-Thing Channel defined for the same Topic?

With regards to the"Label for a ChannelType must not be empty" as already confirmed by @davidgraeff the timeout to parse the full tree is defined here: https://github.com/openhab/openhab2-addons/blob/master/addons/binding/org.openhab.binding.mqtt.generic/src/main/java/org/openhab/binding/mqtt/generic/internal/MqttThingHandlerFactory.java#L98

I set the mosquitto value: max_queued_messages 0 (see: https://community.openhab.org/t/mqtt-homie-implementation-some-properties-remain-in-dummy-state/62379/7)

euphi commented 5 years ago

Could it be, that the Generic-Thing Channel is not being updated when at the same time there is also a Homie-Thing Channel defined for the same Topic?

My devices where all configured as "Generic MQTT Thing" only. The corresponding Homie Thing has been deleted from Inbox. Furthermore, some of the affected Things where Homie 2.0.0 devices, so have not been auto-discovered at all.

RayBa82 commented 5 years ago

I tried the latest jars from @pavax and the subsribing after restarting openhab works now. But after a reboot all property information is lost (like unit and format). Temperatures are shown without unit and Enum values cannot be chosen anymore.

I would really apreciate if anybody could look into this. At the moment there is no real working homie implementation in openhab except you never restart it.

davidgraeff commented 5 years ago

FYI: I do not plan on fixing any MQTT issues for the next weeks to come until the Eclipse Smarthome merge back has finished completely and openhab2-addons has been migrated to the pure maven build system.

RayBa82 commented 5 years ago

Totally understandable.

I tried setting up the openHAB IDE, which works, but adding the mqqt addons to the launch runtime just gives errors and they dont show up on localhost. The total project is a mess and there is no tutorial how to properly set it up (seems like additional committers have to spend a week to get started, or just are not welcome for openHAB), but that has already been the case before the ESH project was closed.

But i would suggest to remove the homie support from release notes to 2.4.0 and from the blog post announcement, because it is just broken and not usable.

davidgraeff commented 5 years ago

But i would suggest to remove the homie support from release notes to 2.4.0 and from the blog post announcement, because it is just broken and not usable.

I can understand you as well, but if we really want to act like this then we should shutdown the entire homepage until the merge is done, because not much is working at all right now. But trust me there are people working on fixing and adapting the build system. And it is for the better in the end.

BasvanH commented 5 years ago

Offtopic: @euphi , looking at your topic start your homie mqtt device project 'lab_thermo' holds code which could help me understand Arduino and the Homie library better and could boost my learning curve. Are you willing to share this code/project with me/public?

joernnilsson commented 5 years ago

I just want to give a thumbs up for the effort put into resolving this. I was in the process of analyzing the code to fix it myself when you posted the diff, so you saved me some time :+1:

Works perfectly on my setup, with several Homie 3 devices.

euphi commented 5 years ago

@BasvanH: You can have a look at https://github.com/euphi/ESP_HomieBME280Node or https://github.com/euphi/HomieNodeCollection/tree/develop-v3

9a4gl commented 5 years ago

Is this fix already in ubuntu packages ? I am having same/similar problems, so guess not. When it is planned to have release with this fix ?

Also, I have noticed that added homie device stops refreshing values after some time (cca 1 day). Is that also caused by same bug ?

davidgraeff commented 5 years ago

This is the wrong repository. Eclipse smarthome is not used for openHAB anymore. There is a fix in the openHAB repository, yes.

9a4gl commented 5 years ago

Ah, I am running 2.4.0 and just realized openhab updates are not so often. Even a 2.5.0.M1 milestone version is almost two months old and does not contain a fix. Only way to get fixed version is running snapshot version, hope fix will be released until I move all my devices to homie 3.0.

euphi commented 5 years ago

BTW: The #develop-v3 branch of Homie-ESP8266 implementation now supports ESP32, too. It also seems quite stable, so please test and write bug reports in case of problems.

dakhnod commented 5 years ago

@davidgraeff Thx - I'll open a PR asap (it took me a bit longer since I stumbled across another bug+fix which I pushed as well to my branch) - I'd like to create some unit tests as well and ideally get the confirmation that these fixes work from someone else that patched the bundles.

@ddecockbe If you find the time I'd appreciate if you could either checkout my branch and build the modules: org.openhab.binding.mqtt and org.openhab.binding.mqtt.generic or if you want (and trust me :) you can download the patched jars here: https://uploadfiles.io/f0g2v, https://uploadfiles.io/b32je

How did I install the patched bundles on my openhabian-pi?

* Login to the `openhab-cli console`

* remove the old bindings `bundle:uninstall org.eclipse.smarthome.binding.mqtt.generic` and  `bundle:uninstall org.eclipse.smarthome.binding.mqtt`

* Place the patched jars into the openhab addons folder: eg: `./usr/share/openhab2/addons/`

* check in the  `openhab-cli console` that the new bundles (version 2.5.0.2019....)  have been installed
openhab> bundle:list | grep MQTT
219 │ Active   │  80 │ 1.2.0                  │ Paho MQTT Client
223 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome MQTT Transport Bundle
245 │ Active   │  80 │ 2.5.0.201901270036     │ MQTT Thing Binding
246 │ Active   │  80 │ 2.5.0.201901270038     │ MQTT Binding

@pavax would you mind reposting the compiled jars? Yours seem to be deleted....

davidgraeff commented 5 years ago

Because an OH 2.5 release is imminent I'm closing this Issue now :) I just noticed that this is an Eclipse Smarthome Issue and I have no access in this repo. Not closing then, but please everybody: Do not post here anymore.

dakhnod commented 5 years ago

Is there a release date?

TilmanGuenther commented 5 years ago

I've just started having this exact problem. Has it been solved? Is there a workaround? I'm running all the latest stable releases. Autodiscovery of Homie devices works and If I manually send them commands over console they respond and subscribing in console works too. It's really frustrating as just a couple days ago all my homie v3 devices were working perfectly.

dakhnod commented 5 years ago

I've just started having this exact problem. Has it been solved? Is there a workaround? I'm running all the latest stable releases. Autodiscovery of Homie devices works and If I manually send them commands over console they respond and subscribing in console works too. It's really frustrating as just a couple days ago all my homie v3 devices were working perfectly.

updating to the latest nightly helped me...