MQTT 2 Handler Initialize Errorq

jrieder · October 12, 2019, 9:27pm

Platform information:
- Hardware: x86/KVM-VM/8GB RAM
- OS: Ubuntu18.04
- Java Runtime Environment: java version “1.8.0_201”
  Java™ SE Runtime Environment (build 1.8.0_201-b09)
  Java HotSpot™ 64-Bit Server VM (build 25.201-b09, mixed mode)
- openHAB version: 2.5.0.M2
Issue of the topic:
Since some time (unfortunately I cannot say definitely if this issue started after the upgrade to 2.5.0.M2 - but this is my current assumption) I get an error on the ThingHandler.initialize() method when MQTT Broker is initialized:

2019-10-12 22:42:19.610 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.mqtt.handler.BrokerHandler@33d297e7': null

Immediately followed by:

2019-10-12 22:42:19.623 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'mqtt:broker:mqttbrokerhs1anew': null
 java.lang.NullPointerException: null

See details in full log below.

PaperUI shows the following, the Broker thing is offline and non-initialized

MQTT Broker: Homeserver1a Mosquitto

MQTT Broker
A connection to a MQTT broker
Status: UNINITIALIZED - HANDLER_INITIALIZING_ERROR

MQTT Broker is defined in text file - was working well since some months already - no change on this Broker definition or on other MQTT Things (see definitions below)

All MQTT2 things are uninitialized in PaperUI and show the following (as example - all other things show the same error):

raspiPellet1 SensorReporter

Generic MQTT Thing

You need a configured Broker first. Dynamically add channels of various types to this Thing. Link different MQTT topics to each channel.

Status: UNINITIALIZED - BRIDGE_UNINITIALIZED

Conclusio is that MQTT Broker Thing and all other MQTT things are uninitialized in PaperUI (and do not update/work as expected).
Later on in the logs another exception occurs regarding jdbc - but I’m not sure if this is related to the issue.

MQTT Bridge configuration:

Bridge mqtt:broker:mqttbrokerhs1anew "MQTT Broker: Homeserver1a Mosquitto"
[
    host="XXXXXXXXX",
    port=1883,
    secure=false,
    username="XXXXX",
    password="XXXXXXXX",
    qos=2,
    retain=true,
    clientID="XXXXXXXX",
    keepAlive=120000,
    reconnectTime=60000,
    lwtMessage="OpenHab2_MQTT_Binding_v2.4_FAILED",
    lwtQos=2,
    lwtTopic="/status/openhab"
]

Thing definitions (example, lot more things are defined):


Thing mqtt:topic:mqttbrokerhs1anew:thinghomeserver1aSensorReporter "homeserver1a SensorReporter" (mqtt:broker:mqttbrokerhs1anew) @ "Virtual_Server_HS1" 
{
	Channels:
		Type string : channelheartbeatdatetime "SensorReporterHeartbeat DateTime"
			[
				stateTopic="/status/heartbeat/homeserver1a"
 			]
		Type number : channelheartbeatmilliseconds "SensorReporterHeartbeat Milliseconds"
			[
				stateTopic="/status/heartbeat_num/homeserver1a"
			]
}


Thing mqtt:topic:mqttbrokerhs1anew:thingraspiPellet1SensorReporter "raspiPellet1 SensorReporter" (mqtt:broker:mqttbrokerhs1anew) @ "Pellet_Oven_Controller" 
{
	Channels:
		Type string : channelheartbeatdatetime "SensorReporterHeartbeat DateTime"
			[
				stateTopic="/status/heartbeat/raspiPellet1"
			]
		Type number : channelheartbeatmilliseconds "SensorReporterHeartbeat Milliseconds"
			[
				stateTopic="/status/heartbeat_num/raspiPellet1"
			]
}

MQTT configuration from karaf:

openhab> bundle:list |grep MQ
219 x Active x  80 x 1.2.1                 x Paho MQTT Client
224 x Active x  80 x 1.14.0.M2             x openHAB MQTT Binding
225 x Active x  80 x 2.5.0.M2              x openHAB Add-ons :: Bundles :: MQTT Broker Binding
226 x Active x  81 x 2.5.0.M2              x openHAB Add-ons :: Bundles :: MQTT Things and Channels
227 x Active x  82 x 2.5.0.M2              x openHAB Add-ons :: Bundles :: MQTT HomeAssistant Convention
228 x Active x  82 x 2.5.0.M2              x openHAB Add-ons :: Bundles :: MQTT Homie Convention
234 x Active x  80 x 2.5.0.M2              x openHAB Core :: Bundles :: MQTT Transport
241 x Active x  80 x 1.14.0.M2             x openHAB MQTT Transport Bundle

openhab.log during startup:

> 2019-10-12 22:42:19.019 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STARTING - org.openhab.binding.mqtt
2019-10-12 22:42:19.021 [DEBUG] [.binding.mqtt.internal.MqttActivator] - MQTT binding has been started.
2019-10-12 22:42:19.022 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STARTED - org.openhab.binding.mqtt
2019-10-12 22:42:19.033 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STARTING - org.openhab.binding.mqtt
2019-10-12 22:42:19.034 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STARTED - org.openhab.binding.mqtt
2019-10-12 22:42:19.171 [INFO ] [b.core.service.AbstractActiveService] - Expire Refresh Service has been started
2019-10-12 22:42:19.190 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been started
2019-10-12 22:42:19.464 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory, org.openhab.binding.mqtt.discovery.MQTTTopicDiscoveryService}={service.id=351, service.bundleid=225, service.scope=bundle, component.name=org.openhab.binding.mqtt.internal.MqttBrokerHandlerFactory, component.id=197} - org.openhab.binding.mqtt
2019-10-12 22:42:19.504 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingActions}={service.id=352, service.bundleid=225, service.scope=singleton} - org.openhab.binding.mqtt
2019-10-12 22:42:19.609 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:abb3cf0a
2019-10-12 22:42:19.610 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.mqtt.handler.BrokerHandler@33d297e7': null
java.lang.NullPointerException: null
	at org.eclipse.paho.client.mqttv3.internal.MqttPersistentData.<init>(MqttPersistentData.java:63) ~[?:?]
	at org.eclipse.paho.client.mqttv3.persist.MqttDefaultFilePersistence.get(MqttDefaultFilePersistence.java:219) ~[?:?]
	at org.eclipse.paho.client.mqttv3.internal.ClientState.restoreState(ClientState.java:342) ~[?:?]
	at org.eclipse.paho.client.mqttv3.internal.ClientState.<init>(ClientState.java:172) ~[?:?]
	at org.eclipse.paho.client.mqttv3.internal.ClientComms.<init>(ClientComms.java:108) ~[?:?]
	at org.eclipse.paho.client.mqttv3.MqttAsyncClient.<init>(MqttAsyncClient.java:470) ~[?:?]
	at org.eclipse.paho.client.mqttv3.MqttAsyncClient.<init>(MqttAsyncClient.java:320) ~[?:?]
	at org.eclipse.paho.client.mqttv3.MqttAsyncClient.<init>(MqttAsyncClient.java:315) ~[?:?]
	at org.eclipse.smarthome.io.transport.mqtt.MqttBrokerConnection.createClient(MqttBrokerConnection.java:751) ~[?:?]
	at org.eclipse.smarthome.io.transport.mqtt.MqttBrokerConnection.start(MqttBrokerConnection.java:707) ~[?:?]
	at org.openhab.binding.mqtt.handler.AbstractBrokerHandler.initialize(AbstractBrokerHandler.java:108) ~[?:?]
	at org.openhab.binding.mqtt.handler.BrokerHandler.initialize(BrokerHandler.java:232) ~[?:?]
	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:152) [133:org.openhab.core:2.5.0.M2]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M2]
	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-10-12 22:42:19.623 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'mqtt:broker:mqttbrokerhs1anew': null
java.lang.NullPointerException: null
	at org.eclipse.paho.client.mqttv3.internal.MqttPersistentData.<init>(MqttPersistentData.java:63) ~[?:?]
	at org.eclipse.paho.client.mqttv3.persist.MqttDefaultFilePersistence.get(MqttDefaultFilePersistence.java:219) ~[?:?]
	at org.eclipse.paho.client.mqttv3.internal.ClientState.restoreState(ClientState.java:342) ~[?:?]
	at org.eclipse.paho.client.mqttv3.internal.ClientState.<init>(ClientState.java:172) ~[?:?]
	at org.eclipse.paho.client.mqttv3.internal.ClientComms.<init>(ClientComms.java:108) ~[?:?]
	at org.eclipse.paho.client.mqttv3.MqttAsyncClient.<init>(MqttAsyncClient.java:470) ~[?:?]
	at org.eclipse.paho.client.mqttv3.MqttAsyncClient.<init>(MqttAsyncClient.java:320) ~[?:?]
	at org.eclipse.paho.client.mqttv3.MqttAsyncClient.<init>(MqttAsyncClient.java:315) ~[?:?]
	at org.eclipse.smarthome.io.transport.mqtt.MqttBrokerConnection.createClient(MqttBrokerConnection.java:751) ~[?:?]
	at org.eclipse.smarthome.io.transport.mqtt.MqttBrokerConnection.start(MqttBrokerConnection.java:707) ~[?:?]
	at org.openhab.binding.mqtt.handler.AbstractBrokerHandler.initialize(AbstractBrokerHandler.java:108) ~[?:?]
	at org.openhab.binding.mqtt.handler.BrokerHandler.initialize(BrokerHandler.java:232) ~[?:?]
	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:152) [133:org.openhab.core:2.5.0.M2]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M2]
	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-10-12 22:42:19.641 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=353, service.bundleid=225, service.scope=bundle, component.name=org.openhab.binding.mqtt.internal.discovery.MqttServiceDiscoveryService, component.id=198} - org.openhab.binding.mqtt
2019-10-12 22:42:19.641 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=353, service.bundleid=225, service.scope=bundle, component.name=org.openhab.binding.mqtt.internal.discovery.MqttServiceDiscoveryService, component.id=198} - org.openhab.binding.mqtt
2
....
...
2019-10-12 22:42:20.063 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.mqtt.MqttBindingProvider}={service.id=370, service.bundleid=224, service.scope=bundle, component.name=org.openhab.binding.mqtt.genericbindingprovider, component.id=194} - org.openhab.binding.mqtt
2019-10-12 22:42:20.066 [TRACE] [.internal.MqttGenericBindingProvider] - Starting to load MQTT config for item Tarif1_Energy_Plus
2019-10-12 22:42:20.068 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2019-10-12 22:42:20.068 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mqttbrokerhs1a'
2019-10-12 22:42:20.075 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'Tarif1_Energy_Plus' : 1 subscribers, 0 publishers

....
....
2019-10-12 22:42:20.433 [TRACE] [.internal.MqttGenericBindingProvider] - Starting to load MQTT config for item Tarif1_Energy_Minus
2019-10-12 22:42:20.435 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'Tarif1_Energy_Minus' : 1 subscribers, 0 publishers
2019-10-12 22:42:20.436 [TRACE] [.internal.MqttGenericBindingProvider] - Starting to load MQTT config for item InstantVoltageL1
2019-10-12 22:42:20.436 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'InstantVoltageL1' : 1 subscribers, 0 publishers
2019-10-12 22:42:20.439 [TRACE] [.internal.MqttGenericBindingProvider] - Starting to load MQTT config for item InstantVoltageL2
2019-10-12 22:42:20.440 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'InstantVoltageL2' : 1 subscribers, 0 publishers
2019-10-12 22:42:20.441 [TRACE] [.internal.MqttGenericBindingProvider] - Starting to load MQTT config for item InstantVoltageL3
2019-10-12 22:42:20.442 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'InstantVoltageL3' : 1 subscribers, 0 publishers
2

...... plus a  lot  more of these lines for all items ......

2019-10-12 22:42:20.492 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler}={service.id=372, service.bundleid=224, service.scope=bundle, event.topics=openhab/*, component.name=org.openhab.binding.mqtt.MqttItemBinding, component.id=196} - org.openhab.binding.mqtt

......

2019-10-12 22:42:20.498 [DEBUG] [ng.mqtt.internal.MqttEventBusBinding] - MQTT: Activating event bus binding.
2019-10-12 22:42:20.499 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={service.id=373, service.bundleid=224, service.scope=bundle, event.topics=openhab/*, service.pid=org.openhab.mqtt-eventbus, component.name=org.openhab.binding.mqtt.eventbus, component.id=195} - org.openhab.binding.mqtt
2019-10-12 22:42:20.500 [DEBUG] [ng.mqtt.internal.MqttEventBusBinding] - Initializing MQTT Event Bus Binding
2019-10-12 22:42:20.501 [TRACE] [ng.mqtt.internal.MqttEventBusBinding] - No topic defined for Event Bus State Publisher
2019-10-12 22:42:20.501 [TRACE] [ng.mqtt.internal.MqttEventBusBinding] - No topic defined for Event Bus State Subscriber
2019-10-12 22:42:20.502 [TRACE] [ng.mqtt.internal.MqttEventBusBinding] - No topic defined for Event Bus Command Publisher
2019-10-12 22:42:20.502 [TRACE] [ng.mqtt.internal.MqttEventBusBinding] - No topic defined for Event Bus Command Subscriber
2019-10-12 22:42:20.503 [DEBUG] [ng.mqtt.internal.MqttEventBusBinding] - MQTT Event Bus Binding initialization completed.


.......

2019-10-12 22:42:20.538 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::openConnection: Driver is available::Yank setupDataSource
2019-10-12 22:42:20.556 [WARN ] [.zaxxer.hikari.util.DriverDataSource] - Registered driver with driverClassName=com.mysql.jdbc.Driver was not found, trying direct instantiation.
2019-10-12 22:42:21.035 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'QueryablePersistenceService.query()' on 'org.openhab.core.persistence.internal.QueryablePersistenceServiceDelegate@36e366c1': java.lang.String cannot be cast to java.sql.Timestamp
java.lang.ClassCastException: java.lang.String cannot be cast to java.sql.Timestamp
	at org.openhab.persistence.jdbc.db.JdbcBaseDAO.objectAsLong(JdbcBaseDAO.java:531) ~[?:?]
	at org.openhab.persistence.jdbc.db.JdbcBaseDAO.getState(JdbcBaseDAO.java:504) ~[?:?]
	at org.openhab.persistence.jdbc.db.JdbcBaseDAO.doGetHistItemFilterQuery(JdbcBaseDAO.java:348) ~[?:?]
	at org.openhab.persistence.jdbc.internal.JdbcMapper.getHistItemFilterQuery(JdbcMapper.java:158) ~[?:?]
	at org.openhab.persistence.jdbc.internal.JdbcPersistenceService.query(JdbcPersistenceService.java:205) ~[?:?]
	at org.openhab.core.persistence.internal.QueryablePersistenceServiceDelegate.query(QueryablePersistenceServiceDelegate.java:51) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor78.invoke(Unknown Source) ~[?:?]
	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:152) [133:org.openhab.core:2.5.0.M2]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M2]
	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-10-12 22:42:21.039 [ERROR] [ence.internal.PersistenceManagerImpl] - Exception occurred while querying persistence service 'jdbc': java.lang.String cannot be cast to java.sql.Timestamp
java.lang.ClassCastException: java.lang.String cannot be cast to java.sql.Timestamp
	at org.openhab.persistence.jdbc.db.JdbcBaseDAO.objectAsLong(JdbcBaseDAO.java:531) ~[?:?]
	at org.openhab.persistence.jdbc.db.JdbcBaseDAO.getState(JdbcBaseDAO.java:504) ~[?:?]
	at org.openhab.persistence.jdbc.db.JdbcBaseDAO.doGetHistItemFilterQuery(JdbcBaseDAO.java:348) ~[?:?]
	at org.openhab.persistence.jdbc.internal.JdbcMapper.getHistItemFilterQuery(JdbcMapper.java:158) ~[?:?]
	at org.openhab.persistence.jdbc.internal.JdbcPersistenceService.query(JdbcPersistenceService.java:205) ~[?:?]
	at org.openhab.core.persistence.internal.QueryablePersistenceServiceDelegate.query(QueryablePersistenceServiceDelegate.java:51) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor78.invoke(Unknown Source) ~[?:?]
	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:152) [133:org.openhab.core:2.5.0.M2]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M2]
	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-10-12 22:42:21.977 [DEBUG] [org.openhab.binding.mqtt.generic    ] - BundleEvent STARTING - org.openhab.binding.mqtt.generic
2019-10-12 22:42:21.979 [DEBUG] [org.openhab.binding.mqtt.generic    ] - BundleEvent STARTED - org.openhab.binding.mqtt.generic
2019-10-12 22:42:21.996 [DEBUG] [org.openhab.binding.mqtt.generic    ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.mqtt.generic.MqttChannelStateDescriptionProvider}={service.id=434, service.bundleid=226, service.scope=bundle, component.name=org.openhab.binding.mqtt.generic.MqttChannelStateDescriptionProvider, component.id=277} - org.openhab.binding.mqtt.generic
2019-10-12 22:42:22.005 [DEBUG] [org.openhab.binding.mqtt.generic    ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.ChannelTypeProvider, org.eclipse.smarthome.core.thing.type.ChannelGroupTypeProvider, org.openhab.binding.mqtt.generic.MqttChannelTypeProvider}={service.id=435, service.bundleid=226, service.scope=bundle, component.name=org.openhab.binding.mqtt.generic.MqttChannelTypeProvider, component.id=278} - org.openhab.binding.mqtt.generic
2019-10-12 22:42:22.010 [DEBUG] [org.openhab.binding.mqtt.generic    ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=436, service.bundleid=226, service.scope=bundle, component.name=org.openhab.binding.mqtt.generic.internal.MqttThingHandlerFactory, component.id=279} - org.openhab.binding.mqtt.generic
2019-10-12 22:42:22.012 [DEBUG] [g.openhab.binding.mqtt.homeassistant] - BundleEvent STARTING - org.openhab.binding.mqtt.homeassistant
2019-10-12 22:42:22.013 [DEBUG] [g.openhab.binding.mqtt.homeassistant] - BundleEvent STARTED - org.openhab.binding.mqtt.homeassistant
2019-10-12 22:42:22.026 [DEBUG] [g.openhab.binding.mqtt.homeassistant] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=437, service.bundleid=227, service.scope=bundle, component.name=org.openhab.binding.mqtt.homeassistant.generic.internal.MqttThingHandlerFactory, component.id=280} - org.openhab.binding.mqtt.homeassistant
2019-10-12 22:42:22.042 [DEBUG] [g.openhab.binding.mqtt.homeassistant] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=438, service.bundleid=227, service.scope=bundle, component.name=org.openhab.binding.mqtt.homeassistant.internal.discovery.HomeAssistantDiscovery, component.id=281} - org.openhab.binding.mqtt.homeassistant
2019-10-12 22:42:22.048 [DEBUG] [org.openhab.binding.mqtt.homie      ] - BundleEvent STARTING - org.openhab.binding.mqtt.homie
2019-10-12 22:42:22.049 [DEBUG] [org.openhab.binding.mqtt.homie      ] - BundleEvent STARTED - org.openhab.binding.mqtt.homie
2019-10-12 22:42:22.068 [DEBUG] [org.openhab.binding.mqtt.homie      ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=439, service.bundleid=228, service.scope=bundle, component.name=org.openhab.binding.mqtt.homie.generic.internal.MqttThingHandlerFactory, component.id=282} - org.openhab.binding.mqtt.homie
2019-10-12 22:42:22.072 [DEBUG] [org.openhab.binding.mqtt.homie      ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=440, service.bundleid=228, service.scope=bundle, component.name=org.openhab.binding.mqtt.homie.internal.discovery.Homie300Discovery, component.id=283} - org.openhab.binding.mqtt.homie
2019-10-12 22:42:27.924 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel enocean:temperatureHumiditySensor:1538dbc7:humidity
2019-10-12 22:42:27.928 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel enocean:temperatureHumiditySensor:1538dbc7:humidity
2019-10-12 22:42:27.929 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel enocean:temperatureHumiditySensor:1538dbc7:humidity
2019-10-12 22:42:27.930 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel enocean:temperatureHumiditySensor:1538dbc7:humidity
2019-10-12 22:42:27.931 [TRACE] [.MqttChannelStateDescriptionProvider] - Providing state description for channel enocean:temperatureHumiditySensor:1538dbc7:humidity

.......

I do not really know where to start debugging - as everything worked for months now. And the error message is not helpful (at least for me ).

Does anybody know about this mqtt handler initialization error and what could be done to solve it?
Many thanks!

Udo_Hartmann · October 12, 2019, 9:47pm

As a first suggestion, please reduce the Bridge configuration to the absolute minimum.

Bridge mqtt:broker:mqttbrokerhs1anew "MQTT Broker: Homeserver1a Mosquitto"
[
    host="XXXXXXXXX",
//    port=1883,
//    secure=false,
    username="XXXXX",
    password="XXXXXXXX",
//    qos=2,
//    retain=true,
//    clientID="XXXXXXXX",
//    keepAlive=120000,
//    reconnectTime=60000,
//    lwtMessage="OpenHab2_MQTT_Binding_v2.4_FAILED",
//    lwtQos=2,
//    lwtTopic="/status/openhab"
]

Please consider to shorten the label, too. Try not to use the colon.

Please be aware that you may need to restart the mqtt bundle to take effect when changing the configuration, as there was an issue about openHAB not reloading thing configuration correctly after changes (I don’t know if that was already fixed in 2.5M2).

broliyoung · October 12, 2019, 9:48pm

Try to delete the persistence file of the mqtt binding and restart

jrieder · October 13, 2019, 1:27pm

Thanks for the suggestion. I identified two issues which lead to this exception:

clientID must not have an underscore character “_” within the string. So

clientID="OpenHab2hs1av2"

is working, while

clientID="OpenHab2_hs1a_v2"

is causing an exception.

last will config parameters also cause an expection (I did not try all different combinations, but some). As soon as I had one of the “lwt…” parameters included the exception occurred.

Seems to me like some kind of regression - I’m not in the position to say safely from which SW or in which version - but could be from 2.5.0.M2 onwards - as in Openhab 2.4 as well in some former 2.5.0 Stream the original Bridge configuration worked well.

So with the following config it is working again:

Bridge mqtt:broker:mqttbrokerhs1anew "MQTT Broker: Homeserver1a Mosquitto"
[
    host="XXXX",
    port=1883,
    secure=false,
    username="XXXXX",
    password="XXXXX",
    qos=2,
    retain=true,
    clientID="OpenHab2hs1av2",
    keepAlive=120000,
    reconnectTime=60000
    //lwtMessage="OpenHab2_MQTT_Binding_v2.4_FAILED",
    //lwtQos=2,
    //lwtTopic="/status/openhab"
]

Funny enough that I do have underscore characters in the password string - and this is working as expected still.

jrieder · October 13, 2019, 1:29pm

Regarding this suggestion - sorry - but where do I find the persistence file for the MQTT binding? If you mean the MQTT persistence service - this I do not use - at least not by purpose