[mqtt] Changes in .things file do not come into effect

englishman-hu commented 4 years ago

Expected Behavior

Changes made to .things file take into effect after saving the file.

Current Behavior

Changing the mqtt topics in a channel definition of a thing within a .things file does not change the actual behaviour. The log shows that the model for the .things file has been refreshed. Messages received in "old" command topic still trigger updates while messages received in "new" does not. Updates are still sent to "old" state topic. Restarting OH or saving the .things file under different name brings the changes into effect.

Steps to Reproduce (for Bugs)

There is an existing thing&channel with state and command topics defined. Messages received in command topic triggers updates and updates are sent to state topic as expected.
Edit the .things file and make changes to the state an/or command topic of a channel, then save the .things file.
Send messages to the "old" and "new" command topics.
Check messages sent on updates in the "old" and "new" state topics.

Your Environment

Version used: 2.4.0 Release, 2.5.0.M2 Milestone, 2.5.0.M3 Milestone (docker images)
Operating System and version: ubuntu 18LTS, docker

udo1toni commented 4 years ago

Restarting the bundle will also suffice.

davidgraeff commented 4 years ago

2.4.0 Release

Yes that bug is clearly communicated in all kind of changelogs and even in the mqtt readme itself.

2.5.0.M2 Milestone

To be honest. I don't believe that you have tested this version, intentional or unintentionally (maybe started the wrong version?). The bug has been fixed in here and confirmed to be resolved in the forum by many people.

Please reopen if this still applies to the newest version of openHAB.

cweitkamp commented 4 years ago

FTR: This has been fixed in https://github.com/openhab/openhab-core/pull/1058.

englishman-hu commented 4 years ago

Guys, I see some contradiction between @davidgraeff and @cweitkamp comment (having been fixed in 2.5.0M2 and core#1058). Nevertheless, I have just gave it another try with the recently released 2.5.0M4 and 2.5.0 snapshot build 1731 and the issue still persists in both.

@davidgraeff , since you closed it I cannot re-open, so I'm asking you to to do so.

See below a console log of a clear reproduction of the issue:

openhab@bay:~$ # show the environment
openhab@bay:~$ date
Sun Oct 20 19:08:49 CEST 2019
openhab@bay:~$ ./start-openhab
9c1796120475889401a2c11c0a62519388355792826d0b26318b713a4c79296f
openhab@bay:~$ docker ps
CONTAINER ID        IMAGE                            COMMAND                  CREATED             STATUS              PORTS               NAMES
9c1796120475        openhab/openhab:2.5.0-snapshot   "/entrypoint.sh gosu…"   20 seconds ago      Up 17 seconds                           openhab
openhab@bay:~$ cat openhab/conf/things/mqtt5.things
Thing mqtt:topic:flock32 (mqtt:broker:hub)  {
Channels:
  Type switch : testled "test led" [ stateTopic="/home/flock32/status/relay1", transformationPattern="MAP:onoff.map", commandTopic="/home/flock32/command/relay1", on="1", off="0"]
}
openhab@bay:~$ # things working as expected
openhab@bay:~$ mosquitto_sub -h hub -v -t /home/flock32/command/#
/home/flock32/command/relay1 1
/home/flock32/command/relay1 0
^C
openhab@bay:~$ # make change to topics and confirm it has been read
openhab@bay:~$ sed -i 's/relay1/relay2/g' openhab/conf/things/mqtt5.things
openhab@bay:~$ cat openhab/conf/things/mqtt5.things
Thing mqtt:topic:flock32 (mqtt:broker:hub)  {
Channels:
  Type switch : testled "test led" [ stateTopic="/home/flock32/status/relay2", transformationPattern="MAP:onoff.map", commandTopic="/home/flock32/command/relay2", on="1", off="0"]
}
openhab@bay:~$ grep mqtt..t openhab/userdata/logs/openhab.log
2019-10-20 19:09:29.312 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt5.things'
2019-10-20 19:10:41.272 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'mqtt5.things'
openhab@bay:~$ # ...and show the mqtt messages still being sent to the outdated topic
openhab@bay:~$ mosquitto_sub -h hub -v -t /home/flock32/command/#
/home/flock32/command/relay1 1
/home/flock32/command/relay1 0
^C
openhab@bay:~$ # renaming the config file brings the changes into effect
openhab@bay:~$ mv openhab/conf/things/mqtt5.things openhab/conf/things/mqtt6.things
openhab@bay:~$ grep mqtt..t openhab/userdata/logs/openhab.log
2019-10-20 19:09:29.312 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt5.things'
2019-10-20 19:10:41.272 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'mqtt5.things'
2019-10-20 19:12:14.084 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt6.things'
openhab@bay:~$ mosquitto_sub -h hub -v -t /home/flock32/command/#
/home/flock32/command/relay2 1
/home/flock32/command/relay2 0
^C
openhab@bay:~$

davidgraeff commented 4 years ago

since you closed it I cannot re-open, so I'm asking you to to do so.

I think the OP should be able to reopen an issue. Anyway I have re-opened it.

The thing is: Each time you edit a file with an mqtt thing, the addon will stop and unsubscribe from everything related to that thing and re-initialize itself. Especially the configuration is re-read and only new command topics should be used. The observed behaviour is indeed unexpected.

cweitkamp commented 4 years ago

@englishman-hu Could you please enable logging: log:set TRACE org.eclipse.smarthome.model.thing? I am interested in the logs when the thing file is refreshed after you are doing your sed magic.

englishman-hu commented 4 years ago

@cweitkamp here you go, the same exercise with the logging set as advised

openhab@bay:~$ rm openhab/userdata/logs/openhab.log
openhab@bay:~$ ./start-openhab
0b96ed76ff62020fa5c9afb8faa7c62b0d708811996eec1a21da7daeed34f457
openhab@bay:~$ docker exec -it openhab /openhab/runtime/bin/client log:set TRACE org.eclipse.smarthome.model.thing
Logging in as openhab
openhab@bay:~$ cat openhab/conf/things/mqtt5.things
Thing mqtt:topic:flock32 (mqtt:broker:hub)  {
Channels:
  Type switch : testled "test led" [ stateTopic="/home/flock32/status/relay1", transformationPattern="MAP:onoff.map", commandTopic="/home/flock32/command/relay1", on="1", off="0"]
}
openhab@bay:~$ sed -i 's/relay1/relay2/g' openhab/conf/things/mqtt5.things
openhab@bay:~$ cat openhab/conf/things/mqtt5.things
Thing mqtt:topic:flock32 (mqtt:broker:hub)  {
Channels:
  Type switch : testled "test led" [ stateTopic="/home/flock32/status/relay2", transformationPattern="MAP:onoff.map", commandTopic="/home/flock32/command/relay2", on="1", off="0"]
}
openhab@bay:~$ cat openhab/userdata/logs/openhab.log
2019-10-21 10:33:39.200 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test1.items'
2019-10-21 10:33:39.337 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.items'
2019-10-21 10:33:39.646 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2019-10-21 10:33:39.665 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'jdbc.persist'
2019-10-21 10:33:40.142 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.sitemap'
2019-10-21 10:33:40.170 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test1.sitemap'
2019-10-21 10:33:40.332 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt5.things'
2019-10-21 10:33:40.363 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt-bridge.things'
2019-10-21 10:33:47.117 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.rules'
2019-10-21 10:33:47.347 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2019-10-21 10:33:47.396 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.script'
2019-10-21 10:33:47.984 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.42.236:8080
2019-10-21 10:33:47.985 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.42.236:8443
2019-10-21 10:33:49.348 [ERROR] [vider.AbstractResourceBundleProvider] - [Module Type] java.lang.IllegalArgumentException: The type must not be null!

org.openhab.core.automation.parser.ParsingException: [Module Type] java.lang.IllegalArgumentException: The type must not be null!

        at org.openhab.core.automation.internal.parser.gson.ModuleTypeGSONParser.parse(ModuleTypeGSONParser.java:61) ~[248:org.openhab.core.automation:2.5.0.201910200303]
        at org.openhab.core.automation.internal.provider.AbstractResourceBundleProvider.parseData(AbstractResourceBundleProvider.java:468) [248:org.openhab.core.automation:2.5.0.201910200303]
        at org.openhab.core.automation.internal.provider.AbstractResourceBundleProvider.processAutomationProvider(AbstractResourceBundleProvider.java:272) [248:org.openhab.core.automation:2.5.0.201910200303]
        at org.openhab.core.automation.internal.provider.AutomationResourceBundlesEventQueue.processBundleChanged(AutomationResourceBundlesEventQueue.java:218) [248:org.openhab.core.automation:2.5.0.201910200303]
        at org.openhab.core.automation.internal.provider.AutomationResourceBundlesEventQueue.run(AutomationResourceBundlesEventQueue.java:120) [248:org.openhab.core.automation:2.5.0.201910200303]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2019-10-21 10:33:49.672 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'hub' with clientid paho9569339571506817 and file store '/openhab/userdata/mqtt/hub'
2019-10-21 10:33:50.184 [INFO ] [io.hueemulation.internal.ConfigStore] - Hue Emulation pairing disabled
2019-10-21 10:33:50.676 [WARN ] [ulation.internal.HueEmulationService] - The UPnP Server service has not been started!
2019-10-21 10:33:50.681 [INFO ] [ulation.internal.HueEmulationService] - Hue Emulation service available under /api
2019-10-21 10:33:51.019 [INFO ] [ueemulation.internal.upnp.UpnpServer] - Hue Emulation UPNP server started on 127.0.0.1:8080
2019-10-21 10:33:51.056 [INFO ] [ulation.internal.HueEmulationService] - Hue Emulation service available under /api
2019-10-21 10:33:51.113 [INFO ] [ueemulation.internal.upnp.UpnpServer] - Hue Emulation UPNP server started on 192.168.42.236:8080
2019-10-21 10:33:51.624 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2019-10-21 10:33:51.669 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2019-10-21 10:35:57.641 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:bridge:097EC6B0F03A' to inbox.
2019-10-21 10:35:59.525 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'mqtt5.things'
2019-10-21 10:35:59.528 [DEBUG] [.thing.internal.GenericThingProvider] - Read things from model 'mqtt5.things'
2019-10-21 10:35:59.536 [TRACE] [.thing.internal.GenericThingProvider] - Creating thing for type 'mqtt:topic' with UID 'mqtt:topic:flock32.
2019-10-21 10:35:59.536 [TRACE] [.thing.internal.GenericThingProvider] - Creating thing from specific ThingHandlerFactory org.openhab.binding.mqtt.generic.internal.MqttThingHandlerFactory@69fdbf32 for thingType mqtt:topic
openhab@bay:~$

jostein1989 commented 4 years ago

I am running OpenHab 2.5 M4 on a PI4 installed with Openhabian 1.5. It does not suffice to reboot the bundle. I have tried bundle:stop - bundle:start and bundle:restart without any luck. But when I run sudo reboot, everything works after reboot.

cweitkamp commented 4 years ago

@englishman-hu I tried to reproduce your error in my development environment. I added a kodi.things file for Kodi binding containing a Channel configuration:

Thing kodi:kodi:myKody "Kodi" [ipAddress="XXX.XXX.XXX.XXX"] {
    Channels:
        Type shownotification : error-notification [
            title="openHAB - Error",
            icon="error"
        ]
}

and replaced the title via sed (sed -i.bak 's/openHAB - Error/openHAB - Error Notification/g' things/kodi.things) command. Everything worked fine. I neither had to restart the binding nor openHAB to take the new configuration into account. I found another way to prove if the configuration is applied in OHC - a call to the REST API.

May I ask you to repeat your test with openHAB 2.5 M5? Enter the following URL to your browser before and after your changes? The output will show your thing and all channels including their configuration:

http://<YOUR_OPENHAB_IP>/rest/things/mqtt:topic:flock32

englishman-hu commented 4 years ago

@cweitkamp I've just given 2.5M5 a try. No luck, the issue persists. See below the console output, with the rest API responses included, showing the old configuration after the changes contrary to the log...

openhab@bay:~$ ./start-openhab
a631be05822481c3e83a26ccc8c8816bfa28af5b19e6ac206cb7d9d52d9e2545
openhab@bay:~$ docker ps
CONTAINER ID        IMAGE                      COMMAND                  CREATED              STATUS              PORTS               NAMES
a631be058224        openhab/openhab:2.5.0.M5   "/entrypoint.sh gosu…"   About a minute ago   Up About a minute                       openhab
openhab@bay:~$ docker exec -it openhab /openhab/runtime/bin/client log:set TRACE org.eclipse.smarthome.model.thing
Logging in as openhab
Password:
openhab@bay:~$ cat openhab/conf/things/mqtt5.things
Thing mqtt:topic:flock32 (mqtt:broker:hub)  {
Channels:
  Type switch : testled "test led" [ stateTopic="/home/flock32/status/relay3", transformationPattern="MAP:onoff.map", commandTopic="/home/flock32/command/relay3", on="1", off="0"]
}
openhab@bay:~$ mosquitto_sub -h hub -v -t /home/flock32/command/#
/home/flock32/command/relay3 1
/home/flock32/command/relay3 0
^C
openhab@bay:~$ curl http://bay:8080/rest/things/mqtt:topic:flock32
{"statusInfo":{"status":"ONLINE","statusDetail":"NONE"},"editable":false,"label":"Generic MQTT Thing","bridgeUID":"mqtt:broker:hub","configuration":{},"properties":{},"UID":"mqtt:topic:flock32","thingTypeUID":"mqtt:topic","channels":[{"linkedItems":["testLed"],"uid":"mqtt:topic:flock32:testled","id":"testled","channelTypeUID":"mqtt:switch","itemType":"Switch","kind":"STATE","label":"test led","defaultTags":[],"properties":{},"configuration":{"retained":false,"postCommand":false,"formatBeforePublish":"%s","commandTopic":"/home/flock32/command/relay3","stateTopic":"/home/flock32/status/relay3","transformationPattern":"MAP:onoff.map","off":"0","on":"1"}}]}
openhab@bay:~$ sed -i 's/relay3/relay4/g' openhab/conf/things/mqtt5.things
openhab@bay:~$ cat openhab/conf/things/mqtt5.things
Thing mqtt:topic:flock32 (mqtt:broker:hub)  {
Channels:
  Type switch : testled "test led" [ stateTopic="/home/flock32/status/relay4", transformationPattern="MAP:onoff.map", commandTopic="/home/flock32/command/relay4", on="1", off="0"]
}
openhab@bay:~$ mosquitto_sub -h hub -v -t /home/flock32/command/#
/home/flock32/command/relay3 1
/home/flock32/command/relay3 0
^C
openhab@bay:~$ curl http://bay:8080/rest/things/mqtt:topic:flock32
{"statusInfo":{"status":"ONLINE","statusDetail":"NONE"},"editable":false,"label":"Generic MQTT Thing","bridgeUID":"mqtt:broker:hub","configuration":{},"properties":{},"UID":"mqtt:topic:flock32","thingTypeUID":"mqtt:topic","channels":[{"linkedItems":["testLed"],"uid":"mqtt:topic:flock32:testled","id":"testled","channelTypeUID":"mqtt:switch","itemType":"Switch","kind":"STATE","label":"test led","defaultTags":[],"properties":{},"configuration":{"retained":false,"postCommand":false,"formatBeforePublish":"%s","commandTopic":"/home/flock32/command/relay3","stateTopic":"/home/flock32/status/relay3","transformationPattern":"MAP:onoff.map","off":"0","on":"1"}}]}
openhab@bay:~$ cat openhab/userdata/logs/openhab.log
2019-11-20 23:45:13.423 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test1.items'
2019-11-20 23:45:13.566 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.items'
2019-11-20 23:45:13.879 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2019-11-20 23:45:13.894 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'jdbc.persist'
2019-11-20 23:45:14.332 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.sitemap'
2019-11-20 23:45:14.358 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test1.sitemap'
2019-11-20 23:45:14.518 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt5.things'
2019-11-20 23:45:14.530 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt-bridge.things'
2019-11-20 23:45:14.547 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.things'
2019-11-20 23:45:16.429 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.script'
2019-11-20 23:45:16.504 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2019-11-20 23:45:21.217 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.rules'
2019-11-20 23:45:21.999 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.42.236:8080
2019-11-20 23:45:22.000 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.42.236:8443
2019-11-20 23:45:23.521 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:home
2019-11-20 23:45:23.594 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:sun:home every 60 seconds
2019-11-20 23:45:23.704 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:home
2019-11-20 23:45:23.725 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:home
2019-11-20 23:45:23.771 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:moon:home every 60 seconds
2019-11-20 23:45:23.823 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:home
2019-11-20 23:45:23.841 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:sun:home every 60 seconds
2019-11-20 23:45:23.853 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:moon:home every 60 seconds
2019-11-20 23:45:24.635 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'hub' with clientid a2a60c2f-1a1f-441d-ac90-703a468167ae
2019-11-20 23:45:24.931 [INFO ] [io.hueemulation.internal.ConfigStore] - Hue Emulation pairing disabled
2019-11-20 23:45:25.394 [WARN ] [ulation.internal.HueEmulationService] - The UPnP Server service has not been started!
2019-11-20 23:45:25.396 [INFO ] [ulation.internal.HueEmulationService] - Hue Emulation service available under /api
2019-11-20 23:45:25.796 [INFO ] [ueemulation.internal.upnp.UpnpServer] - Hue Emulation UPNP server started on 127.0.0.1:8080
2019-11-20 23:45:25.889 [INFO ] [ulation.internal.HueEmulationService] - Hue Emulation service available under /api
2019-11-20 23:45:25.989 [INFO ] [ueemulation.internal.upnp.UpnpServer] - Hue Emulation UPNP server started on 192.168.42.236:8080
2019-11-20 23:45:26.670 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2019-11-20 23:45:26.751 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2019-11-20 23:47:40.006 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:bridge:097EC6B0F03A' to inbox.
2019-11-20 23:49:35.412 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'mqtt5.things'
2019-11-20 23:49:35.417 [DEBUG] [.thing.internal.GenericThingProvider] - Read things from model 'mqtt5.things'
2019-11-20 23:49:35.418 [TRACE] [.thing.internal.GenericThingProvider] - Creating thing for type 'mqtt:topic' with UID 'mqtt:topic:flock32.
2019-11-20 23:49:35.419 [TRACE] [.thing.internal.GenericThingProvider] - Creating thing from specific ThingHandlerFactory org.openhab.binding.mqtt.generic.internal.MqttThingHandlerFactory@49cbf940 for thingType mqtt:topic
openhab@bay:~$

jimtng commented 4 years ago

I can confirm that this bug still exists in 2.5M5. I've been experiencing this bug for a while, since 2.5M2, M3, M4, M5 e.g. https://community.openhab.org/t/things-reload/75979

To test, try set up an MQTT thing, like this:

Thing mqtt:topic:mosquitto:my_light "My Light" (mqtt:broker:mosquitto) {
    Channels:
        Type dimmer : dimmer "Dimmer"       [ stateTopic="stat/my_light/RESULT", transformationPattern="JSONPATH:$.Dimmer", commandTopic="cmnd/my_light/Dimmer" ]
}

Set up an item for it

Dimmer MyDimmer { channel="mqtt:topic:mosquitto:my_light:dimmer" }

Then publish an MQTT message to deliberately trigger some errors (so you can see that if the change had taken place, the errors would go away). Note the deliberately missing "Dimmer" in the json, which will cause the transformation to issue a warning in the log

mosquitto_pub -t stat/my_light/RESULT -m '{"something": "blah"}'

You will see this error:

Executing the JSONPATH-transformation failed: Invalid path '$.Dimmer'

Then change the .things file by adding something in the transformation pattern

Thing mqtt:topic:mosquitto:my_light "My Light" (mqtt:broker:mosquitto) {
    Channels:
        Type dimmer : dimmer "Dimmer"       [ stateTopic="stat/my_light/RESULT", transformationPattern="REGEX:(.*Dimmer.*)∩JSONPATH:$.Dimmer", commandTopic="cmnd/my_light/Dimmer" ]
}

Then publish the same MQTT message. Without restarting openHAB, the errors will remain even after saving the new changes on the .things file. This indicates that the change did not take effect without restarting openHAB.

Now try restarting OpenHAB, the errors will go away.

The expected behaviour is that the change should take effect without having to restart OpenHAB.

englishman-hu commented 4 years ago

Just gave a try to 2.5M6 - and the issue persists.

englishman-hu commented 4 years ago

...and it's still there in 2.5RC1

englishman-hu commented 4 years ago

...so is in both the 2.5 final and 3.0.0#1780

bdgit commented 4 years ago

Happy I found this thread as I've been looking into it the last few days. I believe I'm experiencing the same issue. Here is a little history:

Ran openHABian for years (2.5.2 for some time now)
I put one thing per things file. The majority of my things are using the MQTT Binding (these are the only ones I've tested this with)
Updating a thing file would instantly refresh and the results would be seen (ie Changing a channels label or stateTopic)
Recently started migrating many services to docker (openhab, mosquitto, and frontail included; in separate containers)
Followed documentation for container startup using 2.5.2
Copied files from old openHABian conf and userdata. Set ownership to openhab:openhab.
Initial start issues were fixed by stopping, clearing cache+tmp, and restarting
This is when I noticed the issue. (From this point forward, in a thing file, I've been updating the label of a channel to test.)
I upgraded the openhab container to 2.5.9. The issue still exists.
I noticed these early in startup: ---- [WARN ] [org.apache.felix.fileinstall ] - /usr/share/openhab2/addons does not exist, please create it. ---- [ERROR] [org.apache.felix.fileinstall ] - Cannot create folder /var/lib/openhab2/tmp/bundles. Is the folder write-protected? ---- [ERROR] [org.apache.felix.configadmin ] - [org.osgi.service.cm.ManagedServiceFactory, id=38, bundle=10/mvn:org.apache.felix/org.apache.felix.fileinstall/3.6.4]: Unexpected problem updating configuration org.apache.felix.fileinstall.d72d6a6e-1b9e-4476-99ef-db4f1c5522ba
After a bit of searching and no real findings, I decided to update the docker start command to include volumes for each of these (with openhab:openhab as the owner).
The errors are gone now (right/wrong/related/other... I don't know)
The issue still exists.

chrismast commented 4 years ago

Similar to @bdgit good that I found this thread. I am running OpenHAB 2.5.8 (openHabian install) since a while, managing all things, items etc. via files and VSCode (as to me it is easier than PaperUI). Updating my mqtt.things always resulted in changes being applied right away. Started today a re-do of my things naming convention and suddenly I get issues with things changes not being applied, hence i.e. light bulbs would not work etc.. Only a openhab restart solved it for me (for now), but every time I do a change, I would need to restart again. Maybe not to critical at the moment as I defined all of my mqtt devices with all topics available, but a bit cumbersome if you want to run testing etc. Is there any solution to this besides the usual answer I found "use PaperUI for .things"?

definable commented 3 years ago

Just experienced the same with OH 3.0.0.m1 Added things and items manually in the configuration file. It did not work, no error in the logs. After restart of OH it was ok.

TheFou commented 3 years ago

Hi, I don't know if it's related, but I have a similar issue, and managed to diagnose a little, both on OH 2.5.8 and 2.5.10 in a Docker container.

I have a Sonoff Mini with a tasmota firmware. I defined a rule stating that when the Power state of this module changes, it should replicate the same state to some TP-Link HS110 plugs. It works like a charm, until some point where it doesn't anymore. So I put mosquitto in debug logging mode to see what happens.

What I found is that, when doing any change to my .things file (even unrelated to MQTT bridge / things), OH reloads it, then restarts the MQTT broker connection with a new clientID. So far so good, working as intended I guess. No error message in openhab.log.

However, I can see in mosquitto logs that OH unsubscribes to all previously subscribed topics, but it then only subscribes back to default topics with its new clientID, ignoring the needed topics defined in my things channel definition.

Here is the MQTT part of my .things file :

Bridge mqtt:broker:myMQTTBroker [ host="MYHOST", secure=false ]
{
    Thing topic SonoffMini01 "Sonoff_Mini_01" {
    Channels:
        Type switch : PowerSwitch [stateTopic="stat/tasmota_544A7A/POWER", commandTopic="cmnd/tasmota_544A7A/Power"]
        Type string : Version [stateTopic="stat/tasmota_544A7A/STATUS2", transformationPattern="JSONPATH:$.StatusFWR.Version"]
    }
}

And mosquitto log when saving my modified .things file :

2020-10-31 04:10:34: Received UNSUBSCRIBE from 27047f04-2bf0-4a0b-8c14-1243b332a38c
2020-10-31 04:10:34:    stat/tasmota_544A7A/POWER
2020-10-31 04:10:34: Sending UNSUBACK to 27047f04-2bf0-4a0b-8c14-1243b332a38c
2020-10-31 04:10:34: Received UNSUBSCRIBE from 27047f04-2bf0-4a0b-8c14-1243b332a38c
2020-10-31 04:10:34:    stat/tasmota_544A7A/STATUS2
2020-10-31 04:10:34: Sending UNSUBACK to 27047f04-2bf0-4a0b-8c14-1243b332a38c
2020-10-31 04:10:34: Received UNSUBSCRIBE from 27047f04-2bf0-4a0b-8c14-1243b332a38c
2020-10-31 04:10:34:    homeassistant/#
2020-10-31 04:10:34: Sending UNSUBACK to 27047f04-2bf0-4a0b-8c14-1243b332a38c
2020-10-31 04:10:34: Received UNSUBSCRIBE from 27047f04-2bf0-4a0b-8c14-1243b332a38c
2020-10-31 04:10:34:    +/+/$homie
2020-10-31 04:10:34: Sending UNSUBACK to 27047f04-2bf0-4a0b-8c14-1243b332a38c
2020-10-31 04:10:34: Received DISCONNECT from 27047f04-2bf0-4a0b-8c14-1243b332a38c
2020-10-31 04:10:34: No will message specified.
2020-10-31 04:10:34: Sending CONNACK to 8f5c9c8b-7e29-4dcf-becd-3c3cd2b1983a (0, 0)
2020-10-31 04:10:34: Received SUBSCRIBE from 8f5c9c8b-7e29-4dcf-becd-3c3cd2b1983a
2020-10-31 04:10:34:    homeassistant/# (QoS 1)
2020-10-31 04:10:34: Sending SUBACK to 8f5c9c8b-7e29-4dcf-becd-3c3cd2b1983a
2020-10-31 04:10:34: Received SUBSCRIBE from 8f5c9c8b-7e29-4dcf-becd-3c3cd2b1983a
2020-10-31 04:10:34:    +/+/$homie (QoS 1)
2020-10-31 04:10:34: Sending SUBACK to 8f5c9c8b-7e29-4dcf-becd-3c3cd2b1983a
2020-10-31 04:10:36: Received PINGREQ from DVES_544A7A
2020-10-31 04:10:36: Sending PINGRESP to DVES_544A7A
2020-10-31 04:11:06: Received PINGREQ from DVES_544A7A
2020-10-31 04:11:06: Sending PINGRESP to DVES_544A7A

After that, no matter how many times I modify my .things file, it never subscribes back to my thing topics. The only way to make it work again is to restart OH.

Hope it can help. If it is not related to this issue, please tell me and I'll create a new one. Thanks for your help.

TheFou commented 3 years ago

Hi, I just upgraded to Milestone2, and checked the behavior. I can confirm that my issue is gone, OH subscribes back to the needed topics correctly.

Here is the mosquitto.log :

2020-11-16 02:33:34: Received UNSUBSCRIBE from 378a1b99-140d-4205-9d7b-a3eced271282
2020-11-16 02:33:34:    stat/tasmota_544A7A/POWER
2020-11-16 02:33:34: Sending UNSUBACK to 378a1b99-140d-4205-9d7b-a3eced271282
2020-11-16 02:33:34: Received UNSUBSCRIBE from 378a1b99-140d-4205-9d7b-a3eced271282
2020-11-16 02:33:34:    stat/tasmota_544A7A/STATUS2
2020-11-16 02:33:34: Sending UNSUBACK to 378a1b99-140d-4205-9d7b-a3eced271282
2020-11-16 02:33:34: Received UNSUBSCRIBE from 378a1b99-140d-4205-9d7b-a3eced271282
2020-11-16 02:33:34:    homeassistant/#
2020-11-16 02:33:34: Sending UNSUBACK to 378a1b99-140d-4205-9d7b-a3eced271282
2020-11-16 02:33:34: Received UNSUBSCRIBE from 378a1b99-140d-4205-9d7b-a3eced271282
2020-11-16 02:33:34:    +/+/$homie
2020-11-16 02:33:34: Sending UNSUBACK to 378a1b99-140d-4205-9d7b-a3eced271282
2020-11-16 02:33:34: Received DISCONNECT from 378a1b99-140d-4205-9d7b-a3eced271282
2020-11-16 02:33:34: No will message specified.
2020-11-16 02:33:34: Sending CONNACK to 4bab1682-ea5b-4ed6-9c71-5fbe6bc07267 (0, 0)
2020-11-16 02:33:34: Received SUBSCRIBE from 4bab1682-ea5b-4ed6-9c71-5fbe6bc07267
2020-11-16 02:33:34:    homeassistant/# (QoS 1)
2020-11-16 02:33:34: Sending SUBACK to 4bab1682-ea5b-4ed6-9c71-5fbe6bc07267
2020-11-16 02:33:34: Received SUBSCRIBE from 4bab1682-ea5b-4ed6-9c71-5fbe6bc07267
2020-11-16 02:33:34:    +/+/$homie (QoS 1)
2020-11-16 02:33:34: Sending SUBACK to 4bab1682-ea5b-4ed6-9c71-5fbe6bc07267
2020-11-16 02:33:34: Received SUBSCRIBE from 4bab1682-ea5b-4ed6-9c71-5fbe6bc07267
2020-11-16 02:33:34:    stat/tasmota_544A7A/POWER (QoS 1)
2020-11-16 02:33:34: Sending SUBACK to 4bab1682-ea5b-4ed6-9c71-5fbe6bc07267
2020-11-16 02:33:34: Received SUBSCRIBE from 4bab1682-ea5b-4ed6-9c71-5fbe6bc07267
2020-11-16 02:33:34:    stat/tasmota_544A7A/STATUS2 (QoS 1)
2020-11-16 02:33:34: Sending SUBACK to 4bab1682-ea5b-4ed6-9c71-5fbe6bc07267
2020-11-16 02:33:57: Received PINGREQ from DVES_544A7A
2020-11-16 02:33:57: Sending PINGRESP to DVES_544A7A

Thanks for correcting this @jochen314

openhab-bot commented 3 years ago

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/mqtt-item-update-and-mqtt-things-file/70782/17

hmerk commented 3 years ago

solved

openhab / openhab-addons