smarthome icon indicating copy to clipboard operation
smarthome copied to clipboard

Published 20 hours ago • verified publisher icon eclipse-archived

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

Open euphi opened this issue 6 years ago • 50 comments

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 avatar Jan 09 '19 11:01 euphi

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.

euphi avatar Jan 09 '19 13:01 euphi

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..

halo779 avatar Jan 10 '19 09:01 halo779

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.

euphi avatar Jan 10 '19 12:01 euphi

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 avatar Jan 11 '19 03:01 halo779

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.

halo779 avatar Jan 11 '19 04:01 halo779

@davidgraeff fyi

kaikreuzer avatar Jan 11 '19 07:01 kaikreuzer

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
  1. 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:

  • After a restart the item values are not updated anymore
  • The $state value (of the thing) is still watched and updated
  • There is no problem when I configure a "Generic MQTT Thing" instead and bind each and every node value to a channel
Bridge mqtt:broker:mosquitto [ host="localhost", secure=false ]
{
    Thing topic generic-mifloara {
    Channels:
		Type number : Dracaena#light "Dracaena-light" [ stateTopic="homie/mifloramqtt/Dracaena/light" ]
		Type number : Dracaena#moisture "Dracaena-moisture" [ stateTopic="homie/mifloramqtt/Dracaena/moisture" ]
		Type number : Dracaena#temperature "Dracaena-temperature" [ stateTopic="homie/mifloramqtt/Dracaena/temperature" ]
		Type number : Dracaena#battery "Dracaena-battery" [ stateTopic="homie/mifloramqtt/Dracaena/battery" ]
		Type number : Dracaena#conductivity "Dracaena-conductivity" [ stateTopic="homie/mifloramqtt/Dracaena/conductivity" ]
    }
}
  • I've found the following workarounds:
    • Removing and adding the Thing again
    • Deleting all the (retained) messages in the MQTT Broker and then let my script add ALL the (retained) nodes again the values are updated again

My Env (openhabian-pi)

  • Tested it with openhab 2.4
  • Tested it with openhab 2.5-SNAPSHOT
  • Tested it using the mosquitto broker
  • Tested it using the embedded broker
  • I made sure that I don't use dashes in the names (see: https://github.com/eclipse/smarthome/issues/6784)
  • 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)

pavax avatar Jan 12 '19 08:01 pavax

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

fischerman avatar Jan 12 '19 22:01 fischerman

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,

  • Fresh install of OpenHab 2.4 Stable on an Ubuntu Server VM
  • Embedded MQTT Broker (Although I have tested with mosquitto and have the same result)

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 !

spafrost avatar Jan 13 '19 13:01 spafrost

@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>
  1. Make sure that your script/homie device adds all the nodes and values again by publishing all messages again to the broker
  2. Check that the values are now again updated and keep updating

pavax avatar Jan 13 '19 14:01 pavax

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.

davidgraeff avatar Jan 13 '19 17:01 davidgraeff

@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

pavax avatar Jan 13 '19 17:01 pavax

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

davidgraeff avatar Jan 13 '19 17:01 davidgraeff

@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);
            });
        }
    }

pavax avatar Jan 13 '19 17:01 pavax

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.

davidgraeff avatar Jan 13 '19 17:01 davidgraeff

Is there a workaround available?

ddecockbe avatar Jan 19 '19 18:01 ddecockbe

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!

enricogallesio avatar Jan 25 '19 19:01 enricogallesio

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.

davidgraeff avatar Jan 25 '19 20:01 davidgraeff

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.

ddecockbe avatar Jan 25 '19 20:01 ddecockbe

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.

davidgraeff avatar Jan 25 '19 20:01 davidgraeff

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

ddecockbe avatar Jan 25 '19 20:01 ddecockbe

@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

pavax avatar Jan 25 '19 23:01 pavax

Hi @pavax, thanks!

I will try that and will keep you updated!

ddecockbe avatar Jan 26 '19 08:01 ddecockbe

@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).

davidgraeff avatar Jan 26 '19 09:01 davidgraeff

@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 avatar Jan 27 '19 01:01 pavax

@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.

ddecockbe avatar Jan 27 '19 08:01 ddecockbe

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 avatar Jan 27 '19 22:01 euphi

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.

euphi avatar Jan 27 '19 22:01 euphi

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.

davidgraeff avatar Jan 27 '19 22:01 davidgraeff

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 avatar Jan 27 '19 23:01 euphi