Build #1656 MQTT2

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" ] { .....

How did you upgrade?

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

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

Today I will try from 1603 to the current

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

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>            

What is your error?

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.

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.

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.

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

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.

  1. rename mqtt.items -> mqtt.items_

  2. rename mqtt.things -> mqtt.things_

  3. restart openHAB2
    no warnings

  4. rename mqtt.things_ -> mqtt.things

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

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

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

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

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.

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.