[MQTT with MQTT Action] MQTT Binding will not connect with action installed

rkoshak commented 7 years ago

Discussion on the forum is here.

I can't say exactly which build this started. But it is a problem with 2.0.0 release.

Expected Behavior

When I have both the MQTT binding and MQTT Action installed I expect to be able to publish messages through the action and publish/subscribe messages with the MQTT binding.

Current Behavior

When the MQTT Action is installed the MQTT binding generates no Info level logging including the expected:

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

No messages published to topics subscribed to are received by OH. No messages published by the action are received by the broker. These were confirmed using mosquitto_sub.

Putting the binding into TRACE level the only logs generated by the binding are as follows:

2017-01-25 16:10:36.964 [mqtt                      ] - BundleEvent STARTING - org.openhab.binding.mqtt
2017-01-25 16:10:36.968 [MqttActivator             ] - MQTT binding has been started.
2017-01-25 16:10:36.971 [mqtt                      ] - BundleEvent STARTED - org.openhab.binding.mqtt
2017-01-25 16:10:37.604 [mqtt                      ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.mqtt.MqttBindingProvider}={component.name=org.openhab.binding.mqtt.genericbindingprovider, component.id=161, service.id=305, service.bundleid=193, service.scope=bundle} - org.openhab.binding.mqtt
2017-01-25 16:10:37.617 [MqttGenericBindingProvider] - Starting to load MQTT config for item vMBR_Temperature
2017-01-25 16:10:37.632 [MqttItemConfig            ] - Loaded MQTT config for item 'vMBR_Temperature' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.656 [MqttGenericBindingProvider] - Starting to load MQTT config for item vMBR_Humidity
2017-01-25 16:10:37.657 [MqttItemConfig            ] - Loaded MQTT config for item 'vMBR_Humidity' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.658 [MqttGenericBindingProvider] - Starting to load MQTT config for item vMBR_Light
2017-01-25 16:10:37.660 [MqttItemConfig            ] - Loaded MQTT config for item 'vMBR_Light' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.662 [MqttGenericBindingProvider] - Starting to load MQTT config for item vGarageOpener1
2017-01-25 16:10:37.664 [MqttItemConfig            ] - Loaded MQTT config for item 'vGarageOpener1' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.664 [MqttGenericBindingProvider] - Starting to load MQTT config for item vGarageOpener2
2017-01-25 16:10:37.668 [MqttItemConfig            ] - Loaded MQTT config for item 'vGarageOpener2' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.668 [MqttGenericBindingProvider] - Starting to load MQTT config for item vFrontDoor
2017-01-25 16:10:37.669 [MqttItemConfig            ] - Loaded MQTT config for item 'vFrontDoor' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.669 [MqttGenericBindingProvider] - Starting to load MQTT config for item vBackDoor
2017-01-25 16:10:37.670 [MqttItemConfig            ] - Loaded MQTT config for item 'vBackDoor' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.671 [MqttGenericBindingProvider] - Starting to load MQTT config for item vGarageDoor
2017-01-25 16:10:37.675 [MqttItemConfig            ] - Loaded MQTT config for item 'vGarageDoor' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.676 [MqttGenericBindingProvider] - Starting to load MQTT config for item vJennPhone_Cerberos_BT
2017-01-25 16:10:37.680 [MqttItemConfig            ] - Loaded MQTT config for item 'vJennPhone_Cerberos_BT' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.684 [MqttGenericBindingProvider] - Starting to load MQTT config for item vRichPhone_Cerberos_BT
2017-01-25 16:10:37.684 [MqttItemConfig            ] - Loaded MQTT config for item 'vRichPhone_Cerberos_BT' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.685 [MqttGenericBindingProvider] - Starting to load MQTT config for item vJennPhone_Hydra_BT
2017-01-25 16:10:37.686 [MqttItemConfig            ] - Loaded MQTT config for item 'vJennPhone_Hydra_BT' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.690 [MqttGenericBindingProvider] - Starting to load MQTT config for item vRichPhone_Hydra_BT
2017-01-25 16:10:37.691 [MqttItemConfig            ] - Loaded MQTT config for item 'vRichPhone_Hydra_BT' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.692 [MqttGenericBindingProvider] - Starting to load MQTT config for item vRichPhone_Chimera_BT
2017-01-25 16:10:37.692 [MqttItemConfig            ] - Loaded MQTT config for item 'vRichPhone_Chimera_BT' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.693 [MqttGenericBindingProvider] - Starting to load MQTT config for item vJennPhone_Chimera_BT
2017-01-25 16:10:37.693 [MqttItemConfig            ] - Loaded MQTT config for item 'vJennPhone_Chimera_BT' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.693 [MqttGenericBindingProvider] - Starting to load MQTT config for item vReelyActive_Cerberos
2017-01-25 16:10:37.694 [MqttItemConfig            ] - Loaded MQTT config for item 'vReelyActive_Cerberos' : 1 subscribers, 0 publishers
2017-01-25 16:10:37.695 [mqtt                      ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler}={event.topics=openhab/*, component.name=org.openhab.binding.mqtt.MqttItemBinding, component.id=163, service.id=307, service.bundleid=193, service.scope=bundle} - org.openhab.binding.mqtt
2017-01-25 16:10:37.704 [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=162, service.id=308, service.bundleid=193, service.scope=bundle} - org.openhab.binding.mqtt
2017-01-25 16:10:37.721 [MqttEventBusBinding       ] - MQTT: Activating event bus binding.
2017-01-25 16:10:37.724 [MqttEventBusBinding       ] - No mqtt-eventbus properties configured.

Uninstalling both the MQTT binding and the MQTT action and just reinstalling the MQTT binding causes the subscription Items to start receiving their messages again.

Possible Solution

Steps to Reproduce (for bugs)

Install and configure the MQTT Binding and MQTT Action
Configure Items to subscribe to topics
Configure rule to publish to topic using publish()
Generate message traffic
Confirm message traffic is being received by the broker
Confirm message traffic is not being received by OH
Confirm messages published by OH are not received by the broker

Context

For some time now MQTT has been central to my HA system. When I moved to OH2 I started using the MQTT action instead of MQTT outgoing Items. It worked for many months. I don't know exactly when it stopped working but it was within the past couple of weeks.

Your Environment

Version used: openHAB 2.0.0 Release Build with Release Build version of add-ons
Environment name and version (e.g. Chrome 39, node.js 5.4, Java 8, ...): Latest Docker Image from openhab/openhab on Docker Hub configured with --net==host
Operating System and version (desktop or mobile, Windows 10, Raspbian Jessie, ...): Latest version of docker running on Ubuntu 16.04 64-bit

9037568 commented 7 years ago

Since there have never been any functional changes to the MQTT action and the last functional changes to the MQTT binding were over a year ago... I'm guessing this is something in OH2/ESH.

9037568 commented 7 years ago

As a side note, the MQTT binding HAS no INFO level logging, so it can never produce any.

These two messages come from the IO transport:

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

watou commented 7 years ago

One issue I see with the MQTT action is that it defines a service.pid here and is acting as if it has a configuration in the code. It has no configuration -- all config is done in the MQTT transport service.

9037568 commented 7 years ago

The latest note in the community thread appears to indicate that uninstalling and then reinstalling the action fixed the problem.

@rkoshak, if you haven't tried this, can you check and report your results?

AngelosF commented 7 years ago

update: https://community.openhab.org/t/oh2-dont-even-try-to-connect-to-mqtt/31446/5 uninstalling and then re-installing the mqtt-action addon seems to be a viable workaround

carywin commented 6 years ago

While it's true that uninstalling the MQTT Action does permit the MQTT Binding to finish initialisation and connect to the broker, it's not a viable workaround because if the Action is reinstalled then the same issue will occur again next time OpenHAB is restarted. I'm on the SNAPSHOT build and this problem is still occurring for me, and since OpenHAB restarts several times a week, it's not feasible for me to have to manually intervene with uninstall/reinstall after every restart.

JueBag commented 6 years ago

Observed the same problem on OH2.3. DeInstall/ReInstall MQTT Action did resolve the actual problem. In order to log the different DEBUG messages when starting with and without MQTT ACtion installed I did log:set DEBUG for both the Action and the Binding. When starting now with the Action installed the problem did NOT show again. No update made between. Will continue to monitor and post updates.

9037568 commented 6 years ago

Anyone care to test this out? (@rkoshak @carywin @JueBag)

JueBag commented 6 years ago

Sorry, but I'm presently somewhat out off service due to personell reasons. I migth answer on threads but will not touch anything more sophisticated.

I'll get back on that.

erosenga commented 6 years ago

I seem to be having the same problem. OH2.3 works OK with MQTT binding alone. Adding MQTT action seems to break MQTT binding. Removing MQTT action returns system to functional state.

rsterrenburg commented 5 years ago

Any news on this issue? Having the same problems with latest OpenHAB 2.4 snapshot and MQTT 1.13 snapshot Binding and Action

openhab / openhab1-addons