New to MQTT and OH, trouble getting the binding down

Setup, Configuration and Use Runtime
1

Hello, I’m new to openHAB, started with OH2, and new to MQTT. I have mosquitto installed on the same rPi as OH2. I am able to publish readings from a DHT-22 sensor wired to a ESP-12E to the mosquitto server under the topic openhab/humidor/temperature and openhab/humidor/humidity. It publishes about every 3 or 4 minutes, but I want to lower that to hourly for battery operation once I get everything working. Currently I am passing in characters rounded to the nearest whole number. I am unable to view this information from a sitemap homeTest. I have been reading and tweaking with it for hours now and I feel like I am going backwards. Update: I apparently had it working at some point, I went to another computer where I had the sitemap pulled up from a day or two ago and saw both the temperature and humidity. I have no idea what my mqtt.items looked like at the time it was working. I know when I had the page pulled up at first it read no values, so I think I gave up and then the next day started working on it again with my laptop. It takes so much longer for the values to show up in the sitemap compared to when the message shows up on the queue; it has to be over 20 minutes or I would have seen it working when it was working.

Here is output from mosquitto_sub -t “#” -v
openhab/humidor/temperature 67
openhab/humidor/humidity 86

mosquitto_sub -t "openhab/humidor/temperature"
67
mosquitto_sub -t "openhab/humidor/humidity"
86

Here are the uncommented plines from mqtt.cfg
mosquitto.url=tcp://localhost:1883
mosquitto.clientId=openhab2

I originally set the mqtt-eventbus.cfg, but realized that my settings were incorrect and that I didn’t think I wanted it set. I commented out my changes and then deleted the config from Karaf. I verified that the mqtt-eventbus.cfg did not show back up after restarting OH2.

openhab> config:property-list
mosquitto.clientId = openhab2
mosquitto.url = tcp://localhost:1883
service.pid = org.openhab.mqtt

I have set DEBUG to logging for org.openhab.binding.mqtt and org.openhab.mqtt.

Here is my mqtt log:

openhab> log:tail | grep mqtt
19:32:24.424 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt.items’
19:35:38.402 [DEBUG] [org.openhab.binding.mqtt ] - BundleEvent INSTALLED - org.openhab.binding.mqtt
19:35:41.797 [DEBUG] [org.openhab.binding.mqtt ] - BundleEvent RESOLVED - org.openhab.binding.mqtt
19:35:44.820 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
19:35:44.863 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mosquitto’
19:35:45.674 [DEBUG] [org.openhab.binding.mqtt ] - BundleEvent STARTING - org.openhab.binding.mqtt
19:35:45.768 [DEBUG] [.binding.mqtt.internal.MqttActivator] - MQTT binding has been started.
19:35:46.444 [DEBUG] [ng.mqtt.internal.MqttEventBusBinding] - MQTT: Activating event bus binding.
19:35:46.546 [DEBUG] [org.openhab.binding.mqtt ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/, service.pid=org.openhab.mqtt-eventbus, component.name=org.openhab.binding.mqtt.eventbus, component.id=151, service.id=274, service.bundleid=177, service.scope=bundle} - org.openhab.binding.mqtt
19:35:46.836 [DEBUG] [org.openhab.binding.mqtt ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler}={event.topics=openhab/, component.name=org.openhab.binding.mqtt.MqttItemBinding, component.id=152, service.id=276, service.bundleid=177, service.scope=bundle} - org.openhab.binding.mqtt
19:35:47.226 [DEBUG] [org.openhab.binding.mqtt ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.mqtt.MqttBindingProvider}={component.name=org.openhab.binding.mqtt.genericbindingprovider, component.id=153, service.id=275, service.bundleid=177, service.scope=bundle} - org.openhab.binding.mqtt
19:35:47.392 [DEBUG] [org.openhab.binding.mqtt ] - BundleEvent STARTED - org.openhab.binding.mqtt
19:35:47.488 [INFO ] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-mqtt’
19:35:47.538 [INFO ] [smarthome.event.ExtensionEvent ] - Extension ‘binding-mqtt’ has been installed.

Here are my items:

 Group Humidor_Hum_Temp
 Number Humidor_Temp (Humidor_Hum_Temp) <temperature> {mqtt="<[mosquitto:openhab/humidor/temperature:state:default]"}
Number Humidor_Hum (Humidor_Hum_Temp) <water> {mqtt="<[mosquitto:openhab/humidor/humidity:state:default]"}

And the portion of my sitemap:
Frame label=“Humidor” {
Text label=“temperature” item=Humidor_Temp icon="temperature"
Text label=“humidity” item=Humidor_Hum icon=“water”
}

At one point last night the temperature seemed to be working but I have messed around with the mqtt.items file a lot and I seem to have broken it. Humidity never worked. I think I had something like this under temperature when it worked, but I had to leave the sitemap open for over 10 minutes before it would show up:
Number Humidor_Temp "Temperature [%.1f]" (Humidor_Hum_Temp) <temperature> {mqtt="<[mosquitto:openhab/humidor/temperature:state:default]"}

When I load the sitemap I receive this in the log:
22:13:25.266 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Text
22:13:25.280 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Text
22:13:25.303 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item ‘Humidor_Hum’ for widget org.eclipse.smarthome.model.sitemap.Text
22:13:25.325 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item ‘Humidor_Hum’ for widget org.eclipse.smarthome.model.sitemap.Text
22:13:25.344 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item ‘Humidor_Hum’ for widget org.eclipse.smarthome.model.sitemap.Text

And when I edit the mqtt.items I receive this:
22:13:43.407 [INFO ] [smarthome.event.ItemRemovedEvent ] - Item ‘Humidor_Hum_Temp’ has been removed.
22:13:43.457 [INFO ] [smarthome.event.ItemRemovedEvent ] - Item ‘Humidor_Temp’ has been removed.
22:13:43.598 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt.items’
22:13:43.687 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model ‘mqtt.items’

Here is an excerpt from my mosquitto log, I think most of the time when openhab2 disconnected it was due to a service restart. The last one I had not restarted the service in a while.
1481224120: New client connected from 127.0.0.1 as openhab2 (c1, k60).
1481225095: Socket error on client openhab2, disconnecting.
1481225145: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1481225747: New connection from 127.0.0.1 on port 1883.
1481225747: New client connected from 127.0.0.1 as openhab2 (c1, k60).
1481226947: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1481228748: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1481230549: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1481232350: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1481233955: New connection from ::1 on port 1883.
1481233955: New client connected from ::1 as mosqsub/21228-openhab (c1, k60).
1481234033: Socket error on client mosqsub/21228-openhab, disconnecting.
1481234062: New connection from ::1 on port 1883.
1481234062: New client connected from ::1 as mosqsub/21268-openhab (c1, k60).
1481234085: New connection from ::1 on port 1883.
1481234085: New client connected from ::1 as mosqsub/21274-openhab (c1, k60).
1481234151: Socket error on client mosqsub/21274-openhab, disconnecting.

2

OK, you have proven that your device is successfully publishing. That is a good step.

There is a WHOLE bunch of stuff that has to happen between the MQTT Binding and the sitemap. Furthermore, if you are running Beta4 there is a known bug that causes the sitemap to not update values unless you manually refresh the page.

In short, don’t use the sitemap for debugging.

Instead, look at events.log. This will tell you that the MQTT binding is receiving the event and publishing it on the event bus. If you see the numbers here you know that your config is working and your Items are right so the problem is with the sitemap. If not you have narrowed the problem down to one of two areas, config and Items.

That is correct, you don’t need eventbus here.

This log is a bit concerning because it is talking about the event bus starting. I’m not sure if this is an old log or you somehow still have the event bus configured.

What you for sure should see in the openhab.log when OH starts up is

MQTT Service initialization completed.
Starting MQTT broker connection 'mosquitto'

Both of these lines are INFO level logs. At the same time you should be seeing the New client connected from 127.0.0.1 as openhab2 statement.

The fact that you see that line above implies that your mqtt.cfg is correct.

These look OK to me.

This error means that Humidor_Hum does not exist. Check your .items file and make sure the names exactly match. Look for syntax errors on your .items file. One stray character can make it so OH is unable to load any of the items after that erronious character.

You should use Designer which will catch and tell you about these sorts of errors as you type.

Periodic disconnects, so long as it reconnects shortly thereafter, are not something I’d be concerned about.

1 Like
3

Thank you for your response @rlkoshak !

I am currently troubleshooting how to get eclipse smarthome designer to launch on my Windows system; if I fail I can use my Ubuntu laptop and try it there. I copied from the item Humidor_Hum and pasted it into the sitemap again in vim, and backspaced up to the temperature line to make sure I did not have any stray windows CRLFs or whatnot.
My item is: Number Humidor_Hum (Humidor_Hum_Temp) {mqtt="<[mosquitto:openhab/humidor/humidity

I still get the following message from the sitemap:
00:27:49.259 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Text
00:27:49.282 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Text
00:27:49.296 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item ‘Humidor_Hum’ for widget org.eclipse.smarthome.model.sitemap.Text
00:27:49.323 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item ‘Humidor_Hum’ for widget org.eclipse.smarthome.model.sitemap.Text
00:27:49.347 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item ‘Humidor_Hum’ for widget org.eclipse.smarthome.model.sitemap.Text

This log is a bit concerning because it is talking about the event bus starting. I’m not sure if this is an old log or you somehow still have the event bus configured.

Does the log in Karaf reset every time the service resets? I just restarted the service and here is the new grep for mqtt:
00:20:33.685 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘mqtt.items’
00:21:36.784 [DEBUG] [org.openhab.binding.mqtt ] - BundleEvent STARTING - org.openhab.binding.mqtt
00:21:36.915 [DEBUG] [.binding.mqtt.internal.MqttActivator] - MQTT binding has been started.
00:21:36.942 [DEBUG] [org.openhab.binding.mqtt ] - BundleEvent STARTED - org.openhab.binding.mqtt
00:21:41.783 [DEBUG] [ng.mqtt.internal.MqttEventBusBinding] - MQTT: Activating event bus binding.
00:21:41.971 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
00:21:41.943 [DEBUG] [org.openhab.binding.mqtt ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/, service.pid=org.openhab.mqtt-eventbus, component.name=org.openhab.binding.mqtt.eventbus, component.id=140, service.id=264, service.bundleid=177, service.scope=bundle} - org.openhab.binding.mqtt
00:21:42.038 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection ‘mosquitto’
00:21:42.737 [DEBUG] [org.openhab.binding.mqtt ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler}={event.topics=openhab/, component.name=org.openhab.binding.mqtt.MqttItemBinding, component.id=141, service.id=266, service.bundleid=177, service.scope=bundle} - org.openhab.binding.mqtt
00:21:42.977 [DEBUG] [org.openhab.binding.mqtt ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.mqtt.MqttBindingProvider}={component.name=org.openhab.binding.mqtt.genericbindingprovider, component.id=142, service.id=265, service.bundleid=177, service.scope=bundle} - org.openhab.binding.mqtt

Below is my events.log after watching dozens of new temp/hum readings. I guess I am not receiving any events?
pi@openhab:/var/log/openhab2 $ cat events.log | grep mqtt
2016-12-07 01:31:58.125 [ExtensionEvent ] - Extension ‘binding-mqtt’ has been installed.
2016-12-08 19:35:47.538 [ExtensionEvent ] - Extension ‘binding-mqtt’ has been installed.

4

I got eclipse smarthome working and opened my mqtt.items file. It turns it that it did not like my <temperature> and <water> entries in the item, but I can handle those at the sitemap. I now see in events.log where my Humidor_Temp and Humidor_Hum changed from NULL to 64 and 77 respectively!!! I even saw where humidity changed from 77 to 76 :smile:

I opened my sitemap in designer as well and it showed some errors, but after changing them and refreshing the sitemap a few times I am still no longer showing the value. If I can get rrd4j persistence working for the group, then I don’t really care about the individual numbers though.

So thanks @rlkoshak for helping me troubleshoot my items!

5

Bingo, the values are still not showing up in the sitemap, but the graph is working great!! Thanks!

chrome_2016-12-08_20-14-26.png1317×533 36.2 KB

6

Order does matter when defining the item. You can’t put the icon before the label or after the group. I didn’t notice you had the group and icon backwards the first time around. This is why Designer is so important.

You probably have a syntax error on the sitemap too. Order matters there as well.

7

Thanks for continuing to work with me. Here is my sitemap, the order is the same as my Paper_Light_Power and kwh which are working well. It all checks out on designer as well.

sitemap homeTest label="Home Test" {
	Frame label="Paper Light" {
		Switch item=Paper_Light icon="switch"
		Text icon="heating" label="Power" item=Paper_Light_Power
		Text icon="heating" label="kWh" item=Paper_Light_kwh
	}
	Frame label="Office" {
		Switch item=Plant_Light icon="switch"
	}
	Frame label="Outside Lights" {
		Switch item=Outside_Lights icon="switch"
	}
	Frame label="Paper Light Energy Chart" {
		//change period to 4h for 4 hours, D for 1 day, 3D for 3 days, W for 1 Week, 3W for 3 weeks...
		Chart item=Paper_Light_Power period=4h  refresh=10000
		}
	Frame label="Humidor" {
        Text icon="temperature" label="Temp" item=Humidor_Temp
		Text icon="water" label="Humidity" item=Humidor_Hum
    }
    Frame label="Humidor Chart" {
    	Chart item=Humidor_Hum_Temp period=4h refresh=300
    }
}
8

You are missing the part of the label that tells it to print the Item’s state.

"Humidity [%d%%]"
"Temperature [%d °C]"

Look at the demo items and sitemap, the docs, and examples for more on how to do state formatting.

The above will print the state rounded to the nearest integer. %.1f will print it as a floating point number with one decimal place. %s just prints it as is.

Without [%s] or some other proper letter or letters (e.g. formatting date times, the state of the item doesn’t get printed.

9

That was it, thanks @rlkoshak, I thought it was more for formatting because I didn’t need it on my z-wave sensor. Thanks again!

chrome_2016-12-08_20-47-27.png1310×518 40 KB