SOLVED: Remote OpenHab Question/Issue with Federated Docker OH3-OH2

It was suggested that I start a new thread for this issue as it may be specific to my use of Dockers for OH.

I’ve been using theRemote OpenHab Binding for almost a week now and have been generally impressed with its functionality. However, I have noticed an issue that continues to plague its use in my setup. I am trying to link my OH2 2.5.9 setup with OH3 M3. Both are running in Dockers on the same UnRaid server on the same subnet (br0) with unique IPs and ports set to 8080. OH2 has been working flawlessly for almost 2 yrs now. I have an extensive ISY/Insteon installation that OH2 automates and for which there is no OH3 binding as of today. I am able to link OH3 to OH2 and control OH2 Things/Items from OH3. However any changes made to Items using OH2 are not reflected in my linked Items in OH3. Going the other direction OH3 to OH2 works fine and changes are properly reflected in both OH2 and OH3. My understanding is that the binding is bi-directional, but in my setup it appears to only be OH3 -> OH2, not OH2-> OH3. If I restart OH3 then changes made in OH2 prior to the restart seem to be reflected, but no real time updates seem to happen. This issue seems to affect dimmer type switches mostly. Simple ON/Off switches seem to get updated correctly most of the time.

Any ideas what I may be doing wrong.

1 Like

As usual, some concrete data are expected to give a chance to help you:

  1. Your item definition in OH2
  2. Your item definition in OH3
  3. Your logs (events) on OH2 showing what item command is handled and what item state is changed
  4. Your log (events) on OH3 showing what tem state is changed (in your case I understand there is no item state changed, so just confirm it with logs)
  5. The DEBUG logs of the Remote openHAB binding: if your item state is not updated, I am sure the binding will log the reason
2 Likes

Thanks for taking time to respond to my question. My Items are created using text based files. For this exercise/example to demonstrate the issue I am using a dimmer for fireplace lighting. The Item declaration is the same for both OH2 and OH3.

OH 2 Item:

Dimmer v2A35C71FireplaceLoadLevel "Fireplace Lighting"  <screen>  (Group_HabPanel_Dashboard, PubItems_CMD, gLighting, gFamilyRoom) ["WallSwitch"]

OH3 Item:

Dimmer v2A35C71FireplaceLoadLevel "Fireplace Lighting"  <screen>  (Group_HabPanel_Dashboard, PubItems_CMD, gLighting, gFamilyRoom) ["WallSwitch"]

When Issuing a command from OH2 to adjust the Fireplace Light I see these events in the OH2.events log Turning it OFF from 73% state then turning on to 73% state.

2020-11-29 12:33:10.909 [vent.ItemStateChangedEvent] - v2A35C71FireplaceLoadLevel changed from 73 to 0
2020-11-29 12:33:20.923 [vent.ItemStateChangedEvent] - v2A35C71FireplaceLoadLevel changed from 0 to 73

The corresponding OH2.log entry is

2020-11-29 12:33:10.901 [TRACE] [sy.internal.IsyWebSocketSubscription] - Parsing message: [<?xml version="1.0"?><Event seqnum="260" sid="uuid:1462"><control>DOF</control><action>0</action><node>2A 35 C7 1</node><eventInfo></eventInfo></Event>]
2020-11-29 12:33:10.902 [DEBUG] [sy.internal.IsyWebSocketSubscription] - Node '2A 35 C7 1' got control message 'DOF' action '0'
2020-11-29 12:33:10.903 [DEBUG] [binding.isy.handler.IsyBridgeHandler] - onModelChanged called, control: DOF, action: 0, var event: null
2020-11-29 12:33:10.903 [TRACE] [binding.isy.handler.IsyBridgeHandler] - find thing handler for address: 2A 35 C7 1
2020-11-29 12:33:10.904 [TRACE] [binding.isy.handler.IsyBridgeHandler] - Find thing for address: 2A 35 C7
2020-11-29 12:33:10.904 [TRACE] [binding.isy.handler.IsyBridgeHandler] - address: 2A 35 C7
2020-11-29 12:33:10.904 [DEBUG] [binding.isy.handler.IsyDeviceHandler] - handleUpdate called, control: DOF , action: 0 , node:2A 35 C7 1
2020-11-29 12:33:10.905 [TRACE] [sy.internal.IsyWebSocketSubscription] - Parsing message: [<?xml version="1.0"?><Event seqnum="261" sid="uuid:1462"><control>ST</control><action>0</action><node>2A 35 C7 1</node><eventInfo></eventInfo></Event>]
2020-11-29 12:33:10.906 [DEBUG] [sy.internal.IsyWebSocketSubscription] - Node '2A 35 C7 1' got control message 'ST' action '0'
2020-11-29 12:33:10.906 [DEBUG] [binding.isy.handler.IsyBridgeHandler] - onModelChanged called, control: ST, action: 0, var event: null
2020-11-29 12:33:10.907 [TRACE] [binding.isy.handler.IsyBridgeHandler] - find thing handler for address: 2A 35 C7 1
2020-11-29 12:33:10.907 [TRACE] [binding.isy.handler.IsyBridgeHandler] - Find thing for address: 2A 35 C7
2020-11-29 12:33:10.908 [TRACE] [binding.isy.handler.IsyBridgeHandler] - address: 2A 35 C7
2020-11-29 12:33:10.908 [DEBUG] [binding.isy.handler.IsyDeviceHandler] - handleUpdate called, control: ST , action: 0 , node:2A 35 C7 1
2020-11-29 12:33:10.909 [TRACE] [sy.internal.IsyWebSocketSubscription] - Parsing message: [<?xml version="1.0"?><Event seqnum="262" sid="uuid:1462"><control>_1</control><action>3</action><node></node><eventInfo>[  2A 35 C7 1]      DOF   0</eventInfo></Event>]
2020-11-29 12:33:10.909 [DEBUG] [pdb.internal.MapDBPersistenceService] - store called for v2A35C71FireplaceLoadLevel
2020-11-29 12:33:10.909 [DEBUG] [sy.internal.IsyWebSocketSubscription] - Node 'n/a' got control message '_1' action '3'
2020-11-29 12:33:10.910 [TRACE] [sy.internal.IsyWebSocketSubscription] - Parsing message: [<?xml version="1.0"?><Event seqnum="263" sid="uuid:1462"><control>_1</control><action>3</action><node></node><eventInfo>[  2A 35 C7 1]       ST   0</eventInfo></Event>]
2020-11-29 12:33:10.911 [DEBUG] [pdb.internal.MapDBPersistenceService] - Stored 'v2A35C71FireplaceLoadLevel' with state '0' in mapdb database
2020-11-29 12:33:10.911 [DEBUG] [sy.internal.IsyWebSocketSubscription] - Node 'n/a' got control message '_1' action '3'

2020-11-29 12:33:20.915 [TRACE] [sy.internal.IsyWebSocketSubscription] - Parsing message: [<?xml version="1.0"?><Event seqnum="264" sid="uuid:1462"><control>DON</control><action>0</action><node>2A 35 C7 1</node><eventInfo></eventInfo></Event>]
2020-11-29 12:33:20.917 [DEBUG] [sy.internal.IsyWebSocketSubscription] - Node '2A 35 C7 1' got control message 'DON' action '0'
2020-11-29 12:33:20.917 [DEBUG] [binding.isy.handler.IsyBridgeHandler] - onModelChanged called, control: DON, action: 0, var event: null
2020-11-29 12:33:20.918 [TRACE] [binding.isy.handler.IsyBridgeHandler] - find thing handler for address: 2A 35 C7 1
2020-11-29 12:33:20.918 [TRACE] [binding.isy.handler.IsyBridgeHandler] - Find thing for address: 2A 35 C7
2020-11-29 12:33:20.918 [TRACE] [binding.isy.handler.IsyBridgeHandler] - address: 2A 35 C7
2020-11-29 12:33:20.919 [DEBUG] [binding.isy.handler.IsyDeviceHandler] - handleUpdate called, control: DON , action: 0 , node:2A 35 C7 1
2020-11-29 12:33:20.919 [TRACE] [sy.internal.IsyWebSocketSubscription] - Parsing message: [<?xml version="1.0"?><Event seqnum="265" sid="uuid:1462"><control>ST</control><action>188</action><node>2A 35 C7 1</node><eventInfo></eventInfo></Event>]
2020-11-29 12:33:20.920 [DEBUG] [sy.internal.IsyWebSocketSubscription] - Node '2A 35 C7 1' got control message 'ST' action '188'
2020-11-29 12:33:20.920 [DEBUG] [binding.isy.handler.IsyBridgeHandler] - onModelChanged called, control: ST, action: 188, var event: null
2020-11-29 12:33:20.921 [TRACE] [binding.isy.handler.IsyBridgeHandler] - find thing handler for address: 2A 35 C7 1
2020-11-29 12:33:20.921 [TRACE] [binding.isy.handler.IsyBridgeHandler] - Find thing for address: 2A 35 C7
2020-11-29 12:33:20.921 [TRACE] [binding.isy.handler.IsyBridgeHandler] - address: 2A 35 C7
2020-11-29 12:33:20.921 [DEBUG] [binding.isy.handler.IsyDeviceHandler] - handleUpdate called, control: ST , action: 188 , node:2A 35 C7 1
2020-11-29 12:33:20.922 [TRACE] [sy.internal.IsyWebSocketSubscription] - Parsing message: [<?xml version="1.0"?><Event seqnum="266" sid="uuid:1462"><control>_1</control><action>3</action><node></node><eventInfo>[  2A 35 C7 1]      DON   0</eventInfo></Event>]
2020-11-29 12:33:20.922 [DEBUG] [sy.internal.IsyWebSocketSubscription] - Node 'n/a' got control message '_1' action '3'
2020-11-29 12:33:20.923 [DEBUG] [pdb.internal.MapDBPersistenceService] - store called for v2A35C71FireplaceLoadLevel
2020-11-29 12:33:20.923 [TRACE] [sy.internal.IsyWebSocketSubscription] - Parsing message: [<?xml version="1.0"?><Event seqnum="267" sid="uuid:1462"><control>_1</control><action>3</action><node></node><eventInfo>[  2A 35 C7 1]       ST 188</eventInfo></Event>]
2020-11-29 12:33:20.924 [DEBUG] [sy.internal.IsyWebSocketSubscription] - Node 'n/a' got control message '_1' action '3'
2020-11-29 12:33:20.924 [DEBUG] [pdb.internal.MapDBPersistenceService] - Stored 'v2A35C71FireplaceLoadLevel' with state '73' in mapdb database

The OH3.events.log I’m not seeing an entry it is set to INFO just like the OH2
OH3.Log is

020-11-29 12:33:10.909 [TRACE] [nternal.rest.RemoteopenhabRestClient] - Received event name message date {"topic":"smarthome/items/v2A35C71FireplaceLoadLevel/state","payload":"{\"type\":\"OnOff\",\"value\":\"OFF\"}","type":"ItemStateEvent"}
2020-11-29 12:33:10.910 [DEBUG] [l.handler.RemoteopenhabBridgeHandler] - Unexpected value type OnOff for item v2A35C71FireplaceLoadLevel
2020-11-29 12:33:10.910 [TRACE] [nternal.rest.RemoteopenhabRestClient] - Received event name message date {"topic":"smarthome/items/v2A35C71FireplaceLoadLevel/statechanged","payload":"{\"type\":\"Percent\",\"value\":\"0\",\"oldType\":\"Percent\",\"oldValue\":\"73\"}","type":"ItemStateChangedEvent"}
2020-11-29 12:33:10.910 [TRACE] [nternal.rest.RemoteopenhabRestClient] - Ignored event type ItemStateChangedEvent for topic smarthome/items/v2A35C71FireplaceLoadLevel/statechanged

2020-11-29 12:33:20.923 [TRACE] [nternal.rest.RemoteopenhabRestClient] - Received event name message date {"topic":"smarthome/items/v2A35C71FireplaceLoadLevel/state","payload":"{\"type\":\"Percent\",\"value\":\"73\"}","type":"ItemStateEvent"}
2020-11-29 12:33:20.924 [DEBUG] [l.handler.RemoteopenhabBridgeHandler] - updateState remoteopenhab:server:openhab25x:v2A35C71FireplaceLoadLevel with 73
2020-11-29 12:33:20.924 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=openhab] {topic=openhab/items/v2A35C71FireplaceLoadLevel/state, source=remoteopenhab:server:openhab25x:v2A35C71FireplaceLoadLevel, type=ItemStateEvent, payload={"type":"Percent","value":"73"}, timestamp=1606671200924}
2020-11-29 12:33:20.924 [TRACE] [nternal.rest.RemoteopenhabRestClient] - Received event name message date {"topic":"smarthome/items/v2A35C71FireplaceLoadLevel/statechanged","payload":"{\"type\":\"Percent\",\"value\":\"73\",\"oldType\":\"Percent\",\"oldValue\":\"0\"}","type":"ItemStateChangedEvent"}
2020-11-29 12:33:20.924 [TRACE] [nternal.rest.RemoteopenhabRestClient] - Ignored event type ItemStateChangedEvent for topic smarthome/items/v2A35C71FireplaceLoadLevel/statechanged
2020-11-29 12:33:20.925 [TRACE] [ab.core.internal.items.ExpireManager] - Received '73' for item v2A35C71FireplaceLoadLevel

Just to put a final point on this, if I change the state of the Fireplace Light from OH3 I do get an event in the OH3events.log as shown below, and the light dims as expected.

2020-11-29 12:58:47.127 [ome.event.ItemCommandEvent] - Item 'v2A35C71FireplaceLoadLevel' received command 20
2020-11-29 12:58:47.156 [vent.ItemStateChangedEvent] - Item 'v2A35C71FireplaceLoadLevel' changed from 73 to 20

Thanks again for taking a look a this.

Ok, first we can see that the second command (0 to 73) is correctly handled.
The problem is the first one, the state is changed from 73 to 0 on OH2 and the received event by the binding is of type OnOff with value OFF rather than a Percent with value 0. I don’t understand why.
I have two ideas:

  1. Maybe there was an additional ItemStateChangedEvent published with percent 0 but I am not listening to ItemStateChangedEvent. Maybe I should.
  2. Or maybe I should accept OnOff type and the core framework will probably finally convert it to percent 0.

I will try to reproduce your issue with any dimmer item.

But the solution might be my idea 2.

From my limited testing its seems that not only is OFF not captured properly, but any decrease in setting from a high state to lower state is not properly synced when OH2 initiates the change. If OH3 initiates the change then things seem to work as expected. Also it seems that any change made by OH2 after the initial state is not properly captured/reflected in OH3 whether it is an increase or decrease.

Where is the code of this Isy binding ? I don"t find it. It is not an official OH2/OH3 binding ?
I would be curious to see if the binding is sending an OFF state or a 0% state. Normally it should send a 0% in case the channel expects a Dimmer.

By the way, I can see in your log that an ItemStateChangedEvent with 0% is published. So I believe I have to handle these events too in addition to ItemStateEvent events. I just hope it will not trigger rules twice in OH3 instance. I will have to check that too.

Can I ask you to open a Github issue with a copy/paste of your message containing all detailed and helpful information ?

Yes. I have now opened a github issue. The ISY/Insteon binding is from the marketplace, but the source code is on github. I believe this is the link to GitHub source https://github.com/HentschelT/openhab2-addons/search?q=ISY+binding and another [https://github.com/HentschelT/openhab2-addons/blob/master/addons/binding/org.openhab.binding.isy/src/main/java/org/openhab/binding/isy/discovery/IsyRestDiscoveryService.java#L96. The marketplace binding I am using is a version for 2.4. I believe there is a version that is v2.3 but they are almost identical I have no idea why neither of these bindings were never merged because they both work flawlessly in 2.4 and 2.5.x.

1 Like

Normally I should have fixed your problem:

Thank you for the update and for your effort and support of OpenHAB.

Did the changes make it into M5 or do we need to wait for M6? I didn’t see this issue listed in the release notes as being fixed

Unfortunately not.
But my fix was only proposed yesterday and, as everybody, maintainers have a life.
I tried to push this morning but there were finally only a low activity today.
So we have to be patient.
I am sure it will be included in RC1 next Sunday, even earlier if you use snapshots.

No worries. Just curious. Thanks for your help.

The fix is now merged. Should be available in the next valid snapshot.

2 Likes

SOLVED: Snapshot 2061 does indeed seem to fixed the issue with ISY/Insteon devices communications bi-directionally between OH2 and OH3. Thanks @Lolodomo for the fix and your effort.

1 Like

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.