[Solved] MQTT - OpenHab2 communication issue

Platform information:

  • Hardware: Raspberry Pi 3B+ (rPi3B+)
  • OS: Raspbian 8 (Jessie)
  • Java Runtime Environment: Zulu Java Platform (OpenJDK 1.8.0_152)
  • openHAB version: 2

Issue:
I have Mosquitto (broker and client) installed on the Raspberry that host openHAB 2 (as a package), MQTT binding installed and OH1.x compatibilty = true on the dashboard.

I have tested the MQTT broker with the following command:

service mosquitto status
ps -ef | grep mosq
netstat -tln | grep 1883

And it seems that everything is working cause the broker is on LISTEN on 1883 port.
In fact, as a Test, I have used MyMQTT from my phone (Android) to send the message “Hi Rasp.” on the topic “test_1” to the the MQTT Broker and responded with:

mosquitto_pub -d -t test_1 -m “Hi Phone.”

And everything works fine. I can read the message from the phone on the Raspberry and viceversa.

But I can’t communicate with openHAB.

I state that I have followed this tutorial: MQTT Binding (v1.11) Getting Started 101
I’ve tested the connection of the MQTT client to my Broker.
I’ve installed the MQTT Binding (binding-mqtt1) through Paper UI.
I’ve configured the binding setting in the file “$OPENHAB_CONF/services/mqtt.cfg” this way:

pid:org.openhab.mqtt
oh2broker.url=tcp://localhost:1883
oh2broker.clientId=openhab2rpi3
oh2broker.user=openhabpi
oh2broker.pwd=password

And that work because checking the log I get:

MQTT Service initialization completed.
Starting MQTT Broker connection ‘oh2broker’

I’ve define the “$OPENHAB_CONF/items/test.items” as the tutorial told:

Switch MQTT_Test “Testing…” { mqtt="<[oh2broker:testing/mqtt/topic:state:default], > [oh2broker:testing/mqtt/back-topic:command:*:default]" }

But unfortunately, when I publish MQTT Message with content “ON” to Topic “testing/mqtt/topic/“ from MyMQTT, I have an issue.

The openHAB log give me this message:

[WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn’t post update for ‘MQTT_Test’

I tried to reinstall Mosquitto, reconfigure the broker, and use MQTTLens on Chrome as client but nothing to do.
I’ve changed oh2broker.url=tcp://localhost:1883 with oh2broker.url=tcp://192.168.1.254:1883 because the static IP of the raspberry is 192.168.1.254 but if I do that I only see

MQTT Service initialization completed.
Starting MQTT Broker connection ‘oh2broker’

nothing else.

versus

use the same alias

1 Like

Sorry, I’ve copied the item from the tutorial and not from my “test.items”. I used the same alias.

do you have the MQTT Action Add-on installed?

1 Like

No, I will provide immediately.

you shouldn’t :slight_smile:
there is a bug that creates a conflict between the MQTT Binding and the MQTT Action (same config pid), so don’t install the Action :slight_smile:

can you publish a new mqtt message (from MyMQTT) with 1 (instead of ON) payload to check what happens?

1 Like

Oh, ok :smile:
Tried with 1 (instead of ON) but nothing change.

what’s the log entry?

1 Like

Same message:

2018-11-22 21:31:44.283 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn’t post update for ‘MQTT_Test’

this is strange… your comms are fine
you can publish and subscribe
but the message that arrives in OH2 is somehow processed as NULL…
what is the corresponding entry in events.log?

1 Like

:scream:

I’ve tried many “ON” publish, and in the events.log I get:

2018-11-22 20:55:50.966 [vent.ItemStateChangedEvent] - MQTT_Test changed from NULL to ON

But I get it only one time and before my last publish, the last log is signed on 21:31 (and since 21:31 I’ve made like 4 publish)

does the Item publish anything to the broker when you send a command to it (toggle it from a sitemap)

you can try to enable debug log level using the console to see if something more comes up

log:set DEBUG org.openhab.binding.mqtt
1 Like

I can’t use log:set because I don’t have karaf :persevere:

I have made a demo.sitemap, switched the item 4 time on BASIC UI, and checked the log in the openhab log and this is the result:

2018-11-22 22:02:46.279 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.sitemap'

2018-11-22 22:02:46.341 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'demo.sitemap'

2018-11-22 22:03:42.359 [WARN ] [basic.internal.render.SwitchRenderer] - Cannot determine item type of 'MQTTEST'

org.eclipse.smarthome.core.items.ItemNotFoundException: Item 'MQTTEST' could not be found in the item registry

at org.eclipse.smarthome.core.internal.items.ItemRegistryImpl.getItem(ItemRegistryImpl.java:70) [109:org.eclipse.smarthome.core:0.10.0.b1]

at org.eclipse.smarthome.ui.internal.items.ItemUIRegistryImpl.getItem(ItemUIRegistryImpl.java:724) [155:org.eclipse.smarthome.ui:0.10.0.b1]

at org.eclipse.smarthome.ui.basic.internal.render.SwitchRenderer.renderWidget(SwitchRenderer.java:55) [217:org.eclipse.smarthome.ui.basic:0.10.0.b1]

at org.eclipse.smarthome.ui.basic.internal.render.PageRenderer.renderWidget(PageRenderer.java:172) [217:org.eclipse.smarthome.ui.basic:0.10.0.b1]

at org.eclipse.smarthome.ui.basic.internal.render.PageRenderer.processChildren(PageRenderer.java:137) [217:org.eclipse.smarthome.ui.basic:0.10.0.b1]

at org.eclipse.smarthome.ui.basic.internal.render.PageRenderer.processChildren(PageRenderer.java:158) [217:org.eclipse.smarthome.ui.basic:0.10.0.b1]

at org.eclipse.smarthome.ui.basic.internal.render.PageRenderer.processPage(PageRenderer.java:100) [217:org.eclipse.smarthome.ui.basic:0.10.0.b1]

at org.eclipse.smarthome.ui.basic.internal.servlet.WebAppServlet.service(WebAppServlet.java:159) [217:org.eclipse.smarthome.ui.basic:0.10.0.b1]

at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848) [88:org.eclipse.jetty.servlet:9.3.22.v20171030]

at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584) [88:org.eclipse.jetty.servlet:9.3.22.v20171030]

at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [191:org.ops4j.pax.web.pax-web-jetty:6.0.7]

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [85:org.eclipse.jetty.security:9.3.22.v20171030]

at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:284) [191:org.ops4j.pax.web.pax-web-jetty:6.0.7]

at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) [88:org.eclipse.jetty.servlet:9.3.22.v20171030]

at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [191:org.ops4j.pax.web.pax-web-jetty:6.0.7]

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.server.Server.handle(Server.java:534) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283) [79:org.eclipse.jetty.io:9.3.22.v20171030]

at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108) [79:org.eclipse.jetty.io:9.3.22.v20171030]

at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [79:org.eclipse.jetty.io:9.3.22.v20171030]

at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [90:org.eclipse.jetty.util:9.3.22.v20171030]

at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [90:org.eclipse.jetty.util:9.3.22.v20171030]

at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [90:org.eclipse.jetty.util:9.3.22.v20171030]

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [90:org.eclipse.jetty.util:9.3.22.v20171030]

at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [90:org.eclipse.jetty.util:9.3.22.v20171030]

at java.lang.Thread.run(Thread.java:748) [?:?]

2018-11-22 22:03:42.369 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'MQTTEST' for widget org.eclipse.smarthome.model.sitemap.Switch

2018-11-22 22:03:42.372 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Switch

2018-11-22 22:03:42.375 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'MQTTEST' for widget org.eclipse.smarthome.model.sitemap.Switch

2018-11-22 22:03:42.379 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'MQTTEST' for widget org.eclipse.smarthome.model.sitemap.Switch

2018-11-22 22:03:42.381 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'MQTTEST' for widget org.eclipse.smarthome.model.sitemap.Switch

2018-11-22 22:03:44.190 [INFO ] [rest.core.internal.item.ItemResource] - Received HTTP POST request at 'items/MQTTEST' for the unknown item 'MQTTEST'.

2018-11-22 22:03:46.131 [INFO ] [rest.core.internal.item.ItemResource] - Received HTTP POST request at 'items/MQTTEST' for the unknown item 'MQTTEST'.

2018-11-22 22:03:48.123 [INFO ] [rest.core.internal.item.ItemResource] - Received HTTP POST request at 'items/MQTTEST' for the unknown item 'MQTTEST'.

? what do you have ?
which version of openHAB 2 are you running? (2.2 , 2.3, other?)

Your demo.sitemap has a reference to MQTTEST instead of MQTT_Test

1 Like

I don’t have nothing, i use only linux command via SSH.

openHAB 2.2.0 Release Build

Changed and the result is:

2018-11-22 22:27:13.690 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'demo.sitemap'

2018-11-22 22:27:25.407 [WARN ] [basic.internal.render.SwitchRenderer] - Cannot determine item type of 'MQTT_TEST'

org.eclipse.smarthome.core.items.ItemNotFoundException: Item 'MQTT_TEST' could not be found in the item registry

at org.eclipse.smarthome.core.internal.items.ItemRegistryImpl.getItem(ItemRegistryImpl.java:70) [109:org.eclipse.smarthome.core:0.10.0.b1]

at org.eclipse.smarthome.ui.internal.items.ItemUIRegistryImpl.getItem(ItemUIRegistryImpl.java:724) [155:org.eclipse.smarthome.ui:0.10.0.b1]

at org.eclipse.smarthome.ui.basic.internal.render.SwitchRenderer.renderWidget(SwitchRenderer.java:55) [217:org.eclipse.smarthome.ui.basic:0.10.0.b1]

at org.eclipse.smarthome.ui.basic.internal.render.PageRenderer.renderWidget(PageRenderer.java:172) [217:org.eclipse.smarthome.ui.basic:0.10.0.b1]

at org.eclipse.smarthome.ui.basic.internal.render.PageRenderer.processChildren(PageRenderer.java:137) [217:org.eclipse.smarthome.ui.basic:0.10.0.b1]

at org.eclipse.smarthome.ui.basic.internal.render.PageRenderer.processChildren(PageRenderer.java:158) [217:org.eclipse.smarthome.ui.basic:0.10.0.b1]

at org.eclipse.smarthome.ui.basic.internal.render.PageRenderer.processPage(PageRenderer.java:100) [217:org.eclipse.smarthome.ui.basic:0.10.0.b1]

at org.eclipse.smarthome.ui.basic.internal.servlet.WebAppServlet.service(WebAppServlet.java:159) [217:org.eclipse.smarthome.ui.basic:0.10.0.b1]

at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848) [88:org.eclipse.jetty.servlet:9.3.22.v20171030]

at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584) [88:org.eclipse.jetty.servlet:9.3.22.v20171030]

at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [191:org.ops4j.pax.web.pax-web-jetty:6.0.7]

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [85:org.eclipse.jetty.security:9.3.22.v20171030]

at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:284) [191:org.ops4j.pax.web.pax-web-jetty:6.0.7]

at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) [88:org.eclipse.jetty.servlet:9.3.22.v20171030]

at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [191:org.ops4j.pax.web.pax-web-jetty:6.0.7]

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.server.Server.handle(Server.java:534) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [87:org.eclipse.jetty.server:9.3.22.v20171030]

at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283) [79:org.eclipse.jetty.io:9.3.22.v20171030]

at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108) [79:org.eclipse.jetty.io:9.3.22.v20171030]

at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [79:org.eclipse.jetty.io:9.3.22.v20171030]

at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [90:org.eclipse.jetty.util:9.3.22.v20171030]

at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [90:org.eclipse.jetty.util:9.3.22.v20171030]

at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [90:org.eclipse.jetty.util:9.3.22.v20171030]

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [90:org.eclipse.jetty.util:9.3.22.v20171030]

at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [90:org.eclipse.jetty.util:9.3.22.v20171030]

at java.lang.Thread.run(Thread.java:748) [?:?]

2018-11-22 22:27:25.419 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'MQTT_TEST' for widget org.eclipse.smarthome.model.sitemap.Switch

2018-11-22 22:27:25.423 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Switch

2018-11-22 22:27:25.427 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'MQTT_TEST' for widget org.eclipse.smarthome.model.sitemap.Switch

2018-11-22 22:27:25.431 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'MQTT_TEST' for widget org.eclipse.smarthome.model.sitemap.Switch

2018-11-22 22:27:25.435 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'MQTT_TEST' for widget org.eclipse.smarthome.model.sitemap.Switch

2018-11-22 22:27:27.003 [INFO ] [rest.core.internal.item.ItemResource] - Received HTTP POST request at 'items/MQTT_TEST' for the unknown item 'MQTT_TEST'.

2018-11-22 22:27:28.058 [INFO ] [rest.core.internal.item.ItemResource] - Received HTTP POST request at 'items/MQTT_TEST' for the unknown item 'MQTT_TEST'.

2018-11-22 22:27:31.054 [INFO ] [rest.core.internal.item.ItemResource] - Received HTTP POST request at 'items/MQTT_TEST' for the unknown item 'MQTT_TEST'.

OH2.2 is based on Karaf as the core engine.

read the console docs entry on how to use the console.

post your sitemap and your item configs please using: How to use code fences

1 Like

My bad, I will read the docs :sweat:

Thanks for the advice! :smile:
I unfortunately did not see the icons because of a bug caused by MacOS Mojave in Dark Mode (reported).

Items config:


Switch MQTT_Test "Testing..." { mqtt="<[oh2broker:testing/mqtt/topic:state:default], >[oh2broker:testing/mqtt/back-topic:command:*:default]" }
// ^-- Item Type              ^-- Item linked Channel
//         ^-- Item Name              ^-- Inbound MQTT configuration              ^-- Outbound MQTT configuration
//                   ^-- Item Label

Sitemaps config:

sitemap demo label="TEST" {
    Frame label="MQTT" {
        Switch item=MQTT_TEST icon="light"
    }
}

try:

Switch item=MQTT_Test icon="light"

I don’t remember sitemaps to be so strict with case but you never know… :slight_smile:

1 Like

On openhab.log i don’t have any input, on events.log i get:

2018-11-22 23:01:30.773 [ome.event.ItemCommandEvent] - Item 'MQTT_Test' received command ON
2018-11-22 23:01:30.799 [vent.ItemStateChangedEvent] - MQTT_Test changed from OFF to ON
2018-11-22 23:01:34.437 [ome.event.ItemCommandEvent] - Item 'MQTT_Test' received command OFF
2018-11-22 23:01:34.453 [vent.ItemStateChangedEvent] - MQTT_Test changed from ON to OFF
2018-11-22 23:02:41.683 [ome.event.ItemCommandEvent] - Item 'MQTT_Test' received command ON
2018-11-22 23:02:41.704 [vent.ItemStateChangedEvent] - MQTT_Test changed from OFF to ON

this is due to you toggling the switch on the sitemap or due to incoming mqtt messages?

1 Like