MQTT: Error starting broker connection (Not authorized to connect)

Hi,

I had openhab running nicely with multiple number items showing various data from various sources but every so often the Pi would simply stop working. I ran through the apt-getup dates etc procedures and the upgrades in the openhabian-config to see if this would resolve the hanging Pi but all it seems to have done is stop my item from working.

I’ve tried
uninstalling and installing the MQTT binding
Configuring mqtt.cfg to different brokers I have on the network
confirming the Pi can send and receive MQQT messages from mosquitto via SSH

The Log states
2017-05-31 21:21:07.073 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2017-05-31 21:21:07.075 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'emonpi’
2017-05-31 21:21:07.206 [ERROR] [penhab.io.transport.mqtt.MqttService] - Error starting broker connection
Not authorized to connect (5)
at org.eclipse.paho.client.mqttv3.internal.ExceptionHelper.createMqttException(ExceptionHelper.java:24)[183:org.openhab.io.transport.mqtt:1.9.0]
at org.eclipse.paho.client.mqttv3.internal.ClientState.notifyReceivedAck(ClientState.java:773)[183:org.openhab.io.transport.mqtt:1.9.0]
at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:110)[183:org.openhab.io.transport.mqtt:1.9.0]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]

But the authorisation used is totally correct. I can use the same credentials and connect from the same Pi to the same broker via SSH. I get the same authorisation error no matter what broker I try to connect to.

Anyone got any ideas?

Cheers

this could lead to a known issue with stale configs.

try the following:
stop OH2, fix your /etc/openhab2/services/mqtt.cfg, delete /var/lib/openhab2/config/org/openhab/mqtt.config, start OH2, check logs.

Thanks for the swift reply but how would I stop OH2? I’ve seen talk of scripts etc online, is there a command line I can do via SSH?

Cheers

sudo su
systemctl stop openhab2

first line with switch you to root so you don’t have to sudo everytime.

1 Like

OK, thats made no difference im afraid.

My log file from the time I shut OH down to a few minutes after it started (it doesn’t even mention connecting to the broker?;

2017-08-21 16:20:55.138 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2017-08-21 16:20:55.681 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Stopped HABmin servlet
2017-08-21 16:20:55.748 [ERROR] [org.openhab.persistence.rrd4j ] - [org.openhab.persistence.rrd4j.chartservlet(177)] The deactivate method has thrown an exception
java.lang.IllegalArgumentException: Alias [/rrdchart.png] was never registered
at org.ops4j.pax.web.service.internal.HttpServiceStarted.unregister(HttpServiceStarted.java:278)
at org.ops4j.pax.web.service.internal.HttpServiceProxy.unregister(HttpServiceProxy.java:77)
at org.openhab.persistence.rrd4j.internal.charts.RRD4jChartServlet.deactivate(RRD4jChartServlet.java:128)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_121]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_121]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_121]
at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_121]
at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:224)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:617)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:501)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:302)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:294)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:343)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.SingleComponentManager.deleteComponent(SingleComponentManager.java:152)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:813)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:787)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:579)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:706)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:523)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:452)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator.access$300(Activator.java:54)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:306)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.utils.extender.AbstractExtender$2.run(AbstractExtender.java:290)[32:org.apache.felix.scr:2.0.6]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_121]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_121]
at org.apache.felix.utils.extender.AbstractExtender.destroyExtension(AbstractExtender.java:312)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.utils.extender.AbstractExtender.bundleChanged(AbstractExtender.java:186)[32:org.apache.felix.scr:2.0.6]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.doStop(Module.java:624)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.decStartLevel(ModuleContainer.java:1623)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1542)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.SystemModule.stopWorker(SystemModule.java:248)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule.stopWorker(EquinoxBundle.java:144)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.doStop(Module.java:626)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:186)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule$1.run(EquinoxBundle.java:159)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
2017-08-21 16:20:55.823 [INFO ] [penhab.io.transport.mqtt.MqttService] - Stopping broker connection 'emonpi’
2017-08-21 16:20:55.842 [INFO ] [io.openhabcloud.internal.CloudClient] - Shutting down openHAB Cloud service connection
2017-08-21 16:20:55.902 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = 0c3f2263-0fc4-4a7f-8e33-f6d67e32ffb7, base URL = http://localhost:8080)
2017-08-21 16:20:56.040 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2017-08-21 16:20:56.134 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2017-08-21 16:20:56.213 [INFO ] [.dashboard.internal.DashboardService] - Stopped dashboard
2017-08-21 16:21:31.274 [INFO ] [sistence.rrd4j.internal.RRD4jService] - Removing invalid defintion component = null heartbeat = 0 min/max = 0.0/0.0 step = 0 0 archives(s) = [] 0 items(s) = []
2017-08-21 16:21:47.244 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Home.items’
2017-08-21 16:21:48.592 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist’
2017-08-21 16:21:53.809 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Presense detector.rules’
2017-08-21 16:21:55.191 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model ‘Presense detector.rules’ is either empty or cannot be parsed correctly!
2017-08-21 16:21:56.005 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model ‘Home.sitemap’, using it anyway:
Sitemap should contain either only frames or none at all
2017-08-21 16:21:56.020 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Home.sitemap’
2017-08-21 16:21:59.989 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://192.168.1.191:8080
2017-08-21 16:21:59.993 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://192.168.1.191:8443
2017-08-21 16:22:00.948 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-08-21 16:22:01.284 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-08-21 16:22:03.406 [ERROR] [4j.internal.charts.RRD4jChartServlet] - Error during servlet startup
org.osgi.service.http.NamespaceException: alias: ‘/rrdchart.png’ is already in use in this or another context
at org.ops4j.pax.web.service.spi.model.ServerModel.addServletModel(ServerModel.java:130)
at org.ops4j.pax.web.service.internal.HttpServiceStarted.registerServlet(HttpServiceStarted.java:213)
at org.ops4j.pax.web.service.internal.HttpServiceStarted.registerServlet(HttpServiceStarted.java:196)
at org.ops4j.pax.web.service.internal.HttpServiceStarted.registerServlet(HttpServiceStarted.java:180)
at org.ops4j.pax.web.service.internal.HttpServiceProxy.registerServlet(HttpServiceProxy.java:64)
at org.openhab.persistence.rrd4j.internal.charts.RRD4jChartServlet.activate(RRD4jChartServlet.java:118)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_121]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_121]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_121]
at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_121]
at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:224)
at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39)
at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:617)
at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:501)
at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:302)
at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:294)
at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:297)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:108)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:906)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:879)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:823)[32:org.apache.felix.scr:2.0.6]
at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_121]
at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at com.eclipsesource.jaxrs.publisher.internal.ResourceTracker.addingService(ResourceTracker.java:39)[10:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941)[org.osgi.core-6.0.0.jar:]
at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870)[org.osgi.core-6.0.0.jar:]
at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256)[org.osgi.core-6.0.0.jar:]
at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229)[org.osgi.core-6.0.0.jar:]
at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901)[org.osgi.core-6.0.0.jar:]
at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:886)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:873)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:940)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:740)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:674)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:429)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:657)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:341)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:403)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator.access$200(Activator.java:54)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:278)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:259)[32:org.apache.felix.scr:2.0.6]
at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:232)[32:org.apache.felix.scr:2.0.6]
at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482)[org.osgi.core-6.0.0.jar:]
at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415)[org.osgi.core-6.0.0.jar:]
at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232)[org.osgi.core-6.0.0.jar:]
at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444)[org.osgi.core-6.0.0.jar:]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.Module.start(Module.java:457)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1582)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1562)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1533)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1476)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
2017-08-21 16:22:03.897 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-08-21 16:22:04.036 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-08-21 16:22:06.589 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 0c3f2263-0fc4-4a7f-8e33-f6d67e32ffb7, base URL = http://localhost:8080)

One thing to note that might be important is that Im running openhabian, editing via the SmartHome Designer which is using a mounted windows folder to view the files structure they’ve created of bind mounts. I don’t know if that matters.

I carried out your instructions through SSH though and cfg file I edited was the same as the one I edit in SmartHome Designer. The Log File I view through the designer is called ‘openhab.log’. Is that the correct one?

yes, that’s the correct log file (by the way: enclose the logs in code fences to be easier to read).

It should :slight_smile:

You can try to increase the log level for the MQTT Binding from the openHAB console also:

log:set DEBUG org.openhab.binding.mqtt
log:set DEBUG org.openhab.io.transport.mqtt

From the console, you can also restart the MQTT Binding, so you don’t have to restart the entire OH2 service:

openhab> bundle:list -s |grep -i mqtt
200 │ Active   │  80 │ 1.11.0.201708190109    │ org.openhab.binding.mqtt
207 │ Active   │  80 │ 1.11.0.201708190109    │ org.openhab.io.transport.mqtt
openhab> bundle:restart 200

(note: your binding versions will differ. I am on a snapshot release)

OK, done all ut still no details about connecting to the broker

 2017-08-21 16:44:14.711 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STOPPED - org.openhab.binding.mqtt
2017-08-21 16:44:14.717 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STARTING - org.openhab.binding.mqtt
2017-08-21 16:44:14.720 [DEBUG] [.binding.mqtt.internal.MqttActivator] - MQTT binding has been started.
2017-08-21 16:44:14.893 [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=191, service.id=316, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 16:44:14.907 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'EmonSolarGen' : 1 subscribers, 0 publishers
2017-08-21 16:44:14.913 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'EmonExport' : 1 subscribers, 0 publishers
2017-08-21 16:44:14.916 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'EmonUseNow' : 1 subscribers, 0 publishers
2017-08-21 16:44:14.919 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'HWC1' : 1 subscribers, 0 publishers
2017-08-21 16:44:14.922 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'HWC2' : 1 subscribers, 0 publishers
2017-08-21 16:44:14.925 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'HWC3' : 1 subscribers, 0 publishers
2017-08-21 16:44:14.964 [DEBUG] [ng.mqtt.internal.MqttEventBusBinding] - MQTT: Activating event bus binding.
2017-08-21 16:44:14.974 [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=192, service.id=318, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 16:44:15.008 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler}={event.topics=openhab/*, component.name=org.openhab.binding.mqtt.MqttItemBinding, component.id=193, service.id=319, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 16:44:15.012 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STARTED - org.openhab.binding.mqtt

Do you have the MQTT Action addon installed?
If yes, uninstall it to see if this helps

Can you post the output of the following openHAB console commands:

bundle:list -s |grep -i mqtt
config:list "(service.pid=org.openhab.mqtt)"

The broker connection messages should come from org.openhab.io.transport.mqtt. Did you enable DEBUG on this also?

yes was an action addon installed, I’ve just deleted it via the Paper UI

186 | Active   |  80 | 1.10.0                 | openHAB MQTT Transport Bundle                          | org.openhab.io.transport.mqtt
192 | Active   |  80 | 1.10.0                 | openHAB MQTT Binding                                   | org.openhab.binding.mqtt

----------------------------------------------------------------
Pid:            org.openhab.mqtt
BundleLocation: mvn:org.openhab.io/org.openhab.io.transport.mqtt/1.10.0
Properties:
   emonpi.clientId = openhabian
   emonpi.pwd = emonpimqtt2016
   emonpi.url = tcp://192.168.1.180:1883
   emonpi.user = emonpi
   service.pid = org.openhab.mqtt
openhab>

Thank you

ok. your configs look good.

any logs in openhab.log regarding the connection to the broker? (from org.openhab.io.transport.mqtt)

There were some new lines about the host being unreachabe but I’ve corrected that now. They’ve never been there before and I can confirm the host is once again reachable from this Pi and others, as is the broker.

But still not from OH

just restarted the binding since sorting out the connection issue;

2017-08-21 17:13:00.834 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent UNREGISTERING - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.mqtt.MqttBindingProvider}={component.name=org.openhab.binding.mqtt.genericbindingprovider, component.id=191, service.id=316, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:13:00.854 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent UNREGISTERING - {org.osgi.service.event.EventHandler}={event.topics=openhab/*, component.name=org.openhab.binding.mqtt.MqttItemBinding, component.id=193, service.id=319, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:13:00.871 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent UNREGISTERING - {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=192, service.id=318, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:13:00.882 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STOPPING - org.openhab.binding.mqtt
2017-08-21 17:13:00.885 [DEBUG] [.binding.mqtt.internal.MqttActivator] - MQTT binding has been stopped.
2017-08-21 17:13:00.891 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STOPPED - org.openhab.binding.mqtt
2017-08-21 17:13:00.897 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STARTING - org.openhab.binding.mqtt
2017-08-21 17:13:00.899 [DEBUG] [.binding.mqtt.internal.MqttActivator] - MQTT binding has been started.
2017-08-21 17:13:00.937 [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=249, service.id=380, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:13:00.945 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'EmonSolarGen' : 1 subscribers, 0 publishers
2017-08-21 17:13:00.946 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'EmonExport' : 1 subscribers, 0 publishers
2017-08-21 17:13:00.948 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'EmonUseNow' : 1 subscribers, 0 publishers
2017-08-21 17:13:00.950 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'HWC1' : 1 subscribers, 0 publishers
2017-08-21 17:13:00.952 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'HWC2' : 1 subscribers, 0 publishers
2017-08-21 17:13:00.953 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'HWC3' : 1 subscribers, 0 publishers
2017-08-21 17:13:00.963 [DEBUG] [ng.mqtt.internal.MqttEventBusBinding] - MQTT: Activating event bus binding.
2017-08-21 17:13:00.967 [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=250, service.id=382, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:13:00.974 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler}={event.topics=openhab/*, component.name=org.openhab.binding.mqtt.MqttItemBinding, component.id=251, service.id=383, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:13:00.982 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STARTED - org.openhab.binding.mqtt

Just in case, there are my items which were working fine up until i updated things;

Number HWC1 "HWC Top [%.2f °C]" <temperature> (gHWC) {mqtt="<[emonpi:openhab/hwc/top:state:default]"}  
Number HWC2 "HWC Mid [%.2f °C]" <temperature> (gHWC) {mqtt="<[emonpi:openhab/hwc/middle:state:default]"}
Number HWC3 "HWC Bot [%.2f °C]" <temperature> (gHWC) {mqtt="<[emonpi:openhab/hwc/bottom:state:default]"}

And site map

Frame label="HWC Sensors" {
		//Text item=BedTemp valuecolor=[>25="orange",>15="green",>5="orange",<=5="blue"] 
		Text item=HWC1 valuecolor=[>50="red",>30="orange",>20="blue",<=5="black"]
		Text item=HWC2 valuecolor=[>50="red",>30="orange",>20="blue",<=5="black"]
		Text item=HWC3 valuecolor=[>50="red",>30="orange",>20="blue",<=5="black"]
	}

strange… i don’t see any log entries from org.openhab.io.transport.mqtt
did you put it in DEBUG mode from the console?

log:set DEBUG org.openhab.io.transport.mqtt

maybe… try re-installing the MQTT binding…?

Yup, in debug mode. Restarted the binding and got this in the log

2017-08-21 17:26:06.643 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent UNREGISTERING - {org.osgi.service.event.EventHandler}={event.topics=openhab/*, component.name=org.openhab.binding.mqtt.MqttItemBinding, component.id=251, service.id=383, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:26:06.675 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent UNREGISTERING - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.mqtt.MqttBindingProvider}={component.name=org.openhab.binding.mqtt.genericbindingprovider, component.id=249, service.id=380, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:26:06.700 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent UNREGISTERING - {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=250, service.id=382, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:26:06.707 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STOPPING - org.openhab.binding.mqtt
2017-08-21 17:26:06.709 [DEBUG] [.binding.mqtt.internal.MqttActivator] - MQTT binding has been stopped.
2017-08-21 17:26:06.713 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STOPPED - org.openhab.binding.mqtt
2017-08-21 17:26:06.717 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STARTING - org.openhab.binding.mqtt
2017-08-21 17:26:06.719 [DEBUG] [.binding.mqtt.internal.MqttActivator] - MQTT binding has been started.
2017-08-21 17:26:06.814 [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=252, service.id=384, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:26:06.838 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'EmonSolarGen' : 1 subscribers, 0 publishers
2017-08-21 17:26:06.843 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'EmonExport' : 1 subscribers, 0 publishers
2017-08-21 17:26:06.848 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'EmonUseNow' : 1 subscribers, 0 publishers
2017-08-21 17:26:06.852 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'HWC1' : 1 subscribers, 0 publishers
2017-08-21 17:26:06.857 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'HWC2' : 1 subscribers, 0 publishers
2017-08-21 17:26:06.862 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'HWC3' : 1 subscribers, 0 publishers
2017-08-21 17:26:06.909 [DEBUG] [ng.mqtt.internal.MqttEventBusBinding] - MQTT: Activating event bus binding.
2017-08-21 17:26:06.919 [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=253, service.id=386, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:26:06.952 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler}={event.topics=openhab/*, component.name=org.openhab.binding.mqtt.MqttItemBinding, component.id=254, service.id=387, service.bundleid=192, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:26:06.967 [DEBUG] [org.openhab.binding.mqtt            ] - BundleEvent STARTED - org.openhab.binding.mqtt

Nothing about transport errors.

Whats the quickest way to reinstall the binding? Just uninstall from paperUI and reinstall?

yup

hmmm… you can also try to restart the bundle itself (it seems that when you restart the Binding (192) which handles the configs, it doesn’t affect the transport (186) which handles the connections etc)

186 | Active   |  80 | 1.10.0                 | openHAB MQTT Transport Bundle                          | org.openhab.io.transport.mqtt
192 | Active   |  80 | 1.10.0                 | openHAB MQTT Binding                                   | org.openhab.binding.mqtt
bundle:restart 186

Whoop Whoop! she’s alive!

uninstalled and reinstalled the binding (which I had done previously too), set logs to debug and restarted the binding, got much more positive results and confirmed on the basic UI that data is flowing.

2017-08-21 17:32:32.350 [DEBUG] [org.openhab.io.transport.mqtt       ] - BundleEvent STOPPED - org.openhab.io.transport.mqtt
2017-08-21 17:32:32.372 [DEBUG] [penhab.io.transport.mqtt.MqttService] - Starting MQTT Service...
2017-08-21 17:32:32.389 [DEBUG] [org.openhab.binding.mqtt            ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler}={event.topics=openhab/*, component.name=org.openhab.binding.mqtt.MqttItemBinding, component.id=364, service.id=509, service.bundleid=193, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:32:32.391 [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=362, service.id=508, service.bundleid=193, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:32:32.400 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'EmonSolarGen' : 1 subscribers, 0 publishers
2017-08-21 17:32:32.402 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'EmonExport' : 1 subscribers, 0 publishers
2017-08-21 17:32:32.404 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'EmonUseNow' : 1 subscribers, 0 publishers
2017-08-21 17:32:32.406 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'HWC1' : 1 subscribers, 0 publishers
2017-08-21 17:32:32.408 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'HWC2' : 1 subscribers, 0 publishers
2017-08-21 17:32:32.411 [DEBUG] [binding.mqtt.internal.MqttItemConfig] - Loaded MQTT config for item 'HWC3' : 1 subscribers, 0 publishers
2017-08-21 17:32:32.417 [DEBUG] [ng.mqtt.internal.MqttEventBusBinding] - MQTT: Activating event bus binding.
2017-08-21 17:32:32.422 [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=363, service.id=511, service.bundleid=193, service.scope=bundle} - org.openhab.binding.mqtt
2017-08-21 17:32:32.424 [DEBUG] [org.openhab.io.transport.mqtt       ] - ServiceEvent REGISTERED - {org.openhab.io.transport.mqtt.MqttService, org.osgi.service.cm.ManagedService}={service.pid=org.openhab.mqtt, component.name=MQTT Connection Service, component.id=365, service.id=507, service.bundleid=194, service.scope=bundle} - org.openhab.io.transport.mqtt
2017-08-21 17:32:32.427 [DEBUG] [org.openhab.io.transport.mqtt       ] - BundleEvent STARTING - org.openhab.io.transport.mqtt
2017-08-21 17:32:32.429 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2017-08-21 17:32:32.434 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'emonpi'
2017-08-21 17:32:32.435 [DEBUG] [org.openhab.io.transport.mqtt       ] - BundleEvent STARTED - org.openhab.io.transport.mqtt
2017-08-21 17:32:32.436 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Creating new client for 'tcp://192.168.1.180:1883' using id 'openhabian' and file store '/var/lib/openhab2/tmp/emonpi'
2017-08-21 17:32:32.471 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Starting message consumer for broker 'emonpi' on topic 'emon/emonpi/power2'
2017-08-21 17:32:32.479 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Starting message consumer for broker 'emonpi' on topic 'emon/emonpi/power1'
2017-08-21 17:32:32.487 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Starting message consumer for broker 'emonpi' on topic 'emon/emonpi/power1pluspower2'
2017-08-21 17:32:32.494 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Starting message consumer for broker 'emonpi' on topic 'openhab/hwc/top'
2017-08-21 17:32:32.498 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Starting message consumer for broker 'emonpi' on topic 'openhab/hwc/middle'
2017-08-21 17:32:32.505 [DEBUG] [t.mqtt.internal.MqttBrokerConnection] - Starting message consumer for broker 'emonpi' on topic 'openhab/hwc/bottom'

Maybe the removal of that action and the reinstall did the trick aye?

Thank you so much for your time and help, I’d never have been able to do that without you. Next round is on me.

Cheers!

1 Like

:beers:

remember to lower the log levels to avoid log spam :slight_smile:

log:set WARN org.openhab.binding.mqtt
log:set WARN org.openhab.io.transport.mqtt

(or to INFO level)

1 Like

Roger roger, thank you

1 Like