Build #1656 MQTT2

Olymp · August 10, 2019, 2:50am

After updating openHUB2 from Build # 1603 to Build # 1656, MQTT does not work

2019-08-10 10:34:37.706 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.mqtt.handler.BrokerHandler@518ef1aa': org.eclipse.paho.client.mqttv3.MqttConnectOptions.setHttpsHostnameVerificationEnabled(Z)V

java.lang.NoSuchMethodError: org.eclipse.paho.client.mqttv3.MqttConnectOptions.setHttpsHostnameVerificationEnabled(Z)V

	at org.eclipse.smarthome.io.transport.mqtt.MqttBrokerConnection.createMqttOptions(MqttBrokerConnection.java:635) ~[?:?]

	at org.eclipse.smarthome.io.transport.mqtt.MqttBrokerConnection.start(MqttBrokerConnection.java:720) ~[?:?]

	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.GeneratedMethodAccessor64.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:153) [133:org.openhab.core:2.5.0.201908052317]

	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.201908052317]

	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-08-10 10:34:37.753 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'mqtt:broker:v_mqtt': org.eclipse.paho.client.mqttv3.MqttConnectOptions.setHttpsHostnameVerificationEnabled(Z)V

java.lang.NoSuchMethodError: org.eclipse.paho.client.mqttv3.MqttConnectOptions.setHttpsHostnameVerificationEnabled(Z)V

	at org.eclipse.smarthome.io.transport.mqtt.MqttBrokerConnection.createMqttOptions(MqttBrokerConnection.java:635) ~[?:?]

	at org.eclipse.smarthome.io.transport.mqtt.MqttBrokerConnection.start(MqttBrokerConnection.java:720) ~[?:?]

	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.GeneratedMethodAccessor64.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:153) [133:org.openhab.core:2.5.0.201908052317]

	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.201908052317]

	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) [?:?]

Has something changed that I missed?

Bridge mqtt:broker:v_mqtt "Mosquitto" @ "Home" [ host="192.168.203.2", port=1974, secure=false, username="MQTT-logIn", password="MQTT-pasSw", clientID="v_oh" ] { .....

J-N-K · August 10, 2019, 5:57am

How did you upgrade?

michaeljoos · August 10, 2019, 9:08am

I did upgrade from 1655 to 1656 today and everything is working.

Olymp · August 12, 2019, 12:07am

ubuntu 18.04.3
apt update && apt dist-upgrade -y

Olymp · August 12, 2019, 12:09am

Today I will try from 1603 to the current

J-N-K · August 12, 2019, 4:48am

This looks like the old version of the paho library is still around.please check bundle -s | grep -i paho on the karaf console.

Seaside · August 13, 2019, 1:37pm

I have not been able to get mqtt2 to work in 2.5m2. Is it the same error?

openhab> bundle:list |grep -i pah
225 │ Active │  80 │ 1.2.1                 │ Paho MQTT Client
openhab>

J-N-K · August 13, 2019, 2:06pm

What is your error?

Seaside · August 13, 2019, 8:18pm

Solved by cleaning cach and tmp. Don’t know why mqtt failed, but it was silent so it was hard to understand what was going on.

Olymp · August 15, 2019, 1:49am

openhab> bundle:list -s | grep -i paho
202 x Active x  80 x 1.2.0                 x org.eclipse.paho.client.mqttv3
221 x Active x  80 x 1.2.1                 x org.eclipse.paho.client.mqttv3

Thank you very much, I understood the problem, deleted the extra library, it was in add-ons, for another binding, I will understand further!
When restarting openHAB2, I see the following in the logs (I cleaned the cache and pace, overloaded it several times), is this the norm ?:

2019-08-15 10:19:48.463 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:kitchen_stove_things tried updating channel rssi although the handler was already disposed.
2019-08-15 10:19:48.464 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:kitchen_stove_things tried updating channel uptime although the handler was already disposed.
2019-08-15 10:19:48.464 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:kitchen_stove_things tried updating channel state although the handler was already disposed.
2019-08-15 10:19:48.507 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:kitchen_stove_things tried updating channel current although the handler was already disposed.
2019-08-15 10:19:48.511 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:kitchen_stove_things tried updating channel total although the handler was already disposed.
2019-08-15 10:19:48.512 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:kitchen_stove_things tried updating channel voltage although the handler was already disposed.
2019-08-15 10:19:48.512 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:kitchen_stove_things tried updating channel app_power although the handler was already disposed.
2019-08-15 10:19:48.513 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:kitchen_stove_things tried updating channel yesterday although the handler was already disposed.
2019-08-15 10:19:48.513 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:kitchen_stove_things tried updating channel react_pwr although the handler was already disposed.
2019-08-15 10:19:48.514 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:kitchen_stove_things tried updating channel powerload although the handler was already disposed.
2019-08-15 10:19:48.519 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:kitchen_stove_things tried updating channel today although the handler was already disposed.
2019-08-15 10:19:50.497 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel state although the handler was already disposed.
2019-08-15 10:19:50.498 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel rssi although the handler was already disposed.
2019-08-15 10:19:50.498 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel uptime although the handler was already disposed.
2019-08-15 10:19:50.503 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel vcc although the handler was already disposed.
2019-08-15 10:19:50.544 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel today although the handler was already disposed.
2019-08-15 10:19:50.545 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel voltage although the handler was already disposed.
2019-08-15 10:19:50.545 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel yesterday although the handler was already disposed.
2019-08-15 10:19:50.546 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel react_pwr although the handler was already disposed.
2019-08-15 10:19:50.546 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel powerload although the handler was already disposed.
2019-08-15 10:19:50.547 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel app_power although the handler was already disposed.
2019-08-15 10:19:50.548 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel current although the handler was already disposed.
2019-08-15 10:19:50.548 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel total although the handler was already disposed.

J-N-K · August 15, 2019, 5:01am

Did you try restarting? This should not persist over restart. This should be fixed in the latest version, so I don‘t understand why this happens.

Olymp · August 15, 2019, 8:17am

Yes, it rebooted 10 times already, after each reboot in the log these warnings.
PS openHAB 2.5.0 Build #1661

J-N-K · August 15, 2019, 10:25am

There is something strange going on. Can you please move all things files to another directory and see if this still happens after a restart? I have never seen that. But I don’t use textual configuration.

Olymp · August 17, 2019, 12:28pm

rename mqtt.items → mqtt.items_
rename mqtt.things → mqtt.things_
restart openHAB2
no warnings
rename mqtt.things_ → mqtt.things
restart openHAB2

2019-08-17 19:53:59.620 [WARN ] [t.generic.ChannelStateTransformation] - Transformation service JSONPATH for pattern $.POWER not found!
2019-08-17 19:53:59.620 [WARN ] [ab.binding.mqtt.generic.ChannelState] - Command ‘{“Time”:“2019-08-17T12:53:58”,“Uptime”:“3T05:14:10”,“Vcc”:3.523,“SleepMode”:“Dynamic”,“Sleep”:50,“LoadAvg”:19,“POWER”:“OFF”,“Wifi”:{“AP”:1,“SSId”:“svm”,“BSSId”:“52:FF:20:40:1F:90”,“Channel”:11,“RSSI”:36,“LinkCount”:1,“Downtime”:“0T00:00:10”}}’ not supported by type ‘OnOffValue’: No enum constant org.eclipse.smarthome.core.library.types.OnOffType.{“Time”:“2019-08-17T12:53:58”,“Uptime”:“3T05:14:10”,“Vcc”:3.523,“SleepMode”:“Dynamic”,“Sleep”:50,“LoadAvg”:19,“POWER”:“OFF”,“Wifi”:{“AP”:1,“SSId”:“svm”,“BSSId”:“52:FF:20:40:1F:90”,“Channel”:11,“RSSI”:36,“LinkCount”:1,“Downtime”:“0T00:00:10”}}
2019-08-17 19:53:59.621 [WARN ] [t.generic.ChannelStateTransformation] - Transformation service JSONPATH for pattern $.Wifi.RSSI not found!
2019-08-17 19:53:59.622 [WARN ] [ab.binding.mqtt.generic.ChannelState] - Incoming payload ‘{“Time”:“2019-08-17T12:53:58”,“Uptime”:“3T05:14:10”,“Vcc”:3.523,“SleepMode”:“Dynamic”,“Sleep”:50,“LoadAvg”:19,“POWER”:“OFF”,“Wifi”:{“AP”:1,“SSId”:“svm”,“BSSId”:“52:FF:20:40:1F:90”,“Channel”:11,“RSSI”:36,“LinkCount”:1,“Downtime”:“0T00:00:10”}}’ not supported by type ‘NumberValue’

New transformation warnings added
6. reinstall JSONPath Transformation
7. restart OpenHAB2

With the transformation, everything is fine, warnings as in the first post.

PS cleared the cache, rebooted, now when you stop openHAB2, in the warning log about the transformation constantly:

2019-08-17 20:53:34.794 [WARN ] [t.generic.ChannelStateTransformation] - Transformation service JSONPATH for pattern $.Wifi.RSSI not found!
2019-08-17 20:53:34.795 [WARN ] [ab.binding.mqtt.generic.ChannelState] - Incoming payload '{"Time":"2019-08-17T20:53:33","Uptime":"4T01:37:16","Vcc":2.960,"Wifi":{"AP":1,"SSId":"svm","RSSI":100,"APMac":"52:FF:20:40:1F:90"}}' not supported by type 'NumberValue'
2019-08-17 20:53:34.796 [WARN ] [t.generic.ChannelStateTransformation] - Transformation service JSONPATH for pattern $.Uptime not found!
2019-08-17 20:53:34.796 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:thank_things tried updating channel uptime although the handler was already disposed.
2019-08-17 20:53:34.838 [WARN ] [t.generic.ChannelStateTransformation] - Transformation service JSONPATH for pattern $.Switch3 not found!
2019-08-17 20:53:34.839 [WARN ] [ab.binding.mqtt.generic.ChannelState] - Command '{"Time":"2019-08-17T20:53:33","Switch1":"ON","Switch2":"ON","Switch3":"ON","Switch4":"OFF","DS18B20":{"Temperature":16.0},"TempUnit":"C"}' not supported by type 'OnOffValue': No enum constant org.eclipse.smarthome.core.library.types.OnOffType.{"Time":"2019-08-17T20:53:33","Switch1":"ON","Switch2":"ON","Switch3":"ON","Switch4":"OFF","DS18B20":{"Temperature":16.0},"TempUnit":"C"}
2019-08-17 20:53:34.839 [WARN ] [t.generic.ChannelStateTransformation] - Transformation service JSONPATH for pattern $.Switch2 not found!

rossko57 · August 17, 2019, 1:21pm

Did you really mean “when you stop openhab” i.e. when it is shutting down services?

Olymp · August 18, 2019, 1:56am

service openhab2 stop
or
service openhab2 restart

2019-08-18 10:01:59.001 [INFO ] [io.openhabcloud.internal.CloudClient] - Shutting down openHAB Cloud service connection
2019-08-18 10:01:59.013 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = a3d09e49-047c-46d3-bb03-bdd2a90166bc, base URL = http://localhost:8080)
2019-08-18 10:01:59.107 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2019-08-18 10:01:59.797 [INFO ] [b.core.service.AbstractActiveService] - Expire Refresh Service has been shut down
2019-08-18 10:02:00.106 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:washer_light_things tried updating channel uptime although the handler was already disposed.
2019-08-18 10:02:00.108 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:washer_light_things tried updating channel rssi although the handler was already disposed.
2019-08-18 10:02:00.108 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:washer_light_things tried updating channel state although the handler was already disposed.
2019-08-18 10:02:05.241 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel state although the handler was already disposed.
2019-08-18 10:02:05.242 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel rssi although the handler was already disposed.
2019-08-18 10:02:05.242 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel uptime although the handler was already disposed.
2019-08-18 10:02:05.243 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel vcc although the handler was already disposed.
2019-08-18 10:02:05.251 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel today although the handler was already disposed.
2019-08-18 10:02:05.252 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel voltage although the handler was already disposed.
2019-08-18 10:02:05.252 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel yesterday although the handler was already disposed.
2019-08-18 10:02:05.253 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel react_pwr although the handler was already disposed.
2019-08-18 10:02:05.253 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel powerload although the handler was already disposed.
2019-08-18 10:02:05.254 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel app_power although the handler was already disposed.
2019-08-18 10:02:05.254 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel current although the handler was already disposed.
2019-08-18 10:02:05.255 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:v_mqtt:pump_water_things tried updating channel total although the handler was already disposed.
2019-08-18 10:02:05.270 [INFO ] [b.handler.EspMilightHubBridgeHandler] - Bridge dispose() called, disconnecting from the MQTT broker.
2019-08-18 10:02:09.076 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2019-08-18 10:02:09.105 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2019-08-18 10:02:09.125 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard

rossko57 · August 18, 2019, 2:09am

So you would like the binding to be stopped before the transformation services are stopped, to avoid getting the WARN messages at shutdown?

Olymp · August 18, 2019, 2:14am

Transformation warnings are not always available, as in the stop example above.
The warnings shown above are not displayed for all things and their quantity and the things themselves change from time to time.
At assembly 1603 this was not at all.

rossko57 · August 18, 2019, 10:43am

Yes, I would expect it depends what incoming MQTT messages arrive for processing after the shutdown has begun.
Perhaps the order of shutting down things has changed, perhaps the messages were suppressed before.