[Solved] MQTT - OpenHab2 communication issue

Setup, Configuration and Use Beginners
, ,
1

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.

2

versus

use the same alias

1 Like
3

Sorry, Iā€™ve copied the item from the tutorial and not from my ā€œtest.itemsā€. I used the same alias.

4

do you have the MQTT Action Add-on installed?

1 Like
5

No, I will provide immediately.

6

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
7

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

8

whatā€™s the log entry?

1 Like
9

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ā€™

10

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
11

: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)

12

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
13

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

? 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
15

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

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
17

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"
    }
}
18

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
19

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
20

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

1 Like