openHAB2 IHC binding

Pauli Anttila · May 19, 2018

Update 12.3.2019:

Binding has been merged to openHAB main repository and will available in 2.5 version. Before that, new version can be found from official openHAB snapshot builds.

Before official add-on documentation page is updated, binding documentation can found here.

NOTE. If you have used older beta versions of the binding, beware that there has been some breaking changes lately:

Controller address parameter is not anymore ip, but hostname
"-channel" suffix is removed from channel types. E.g. switch-channel is just switch.

###########################################################################################################################

Even openHAB 1 IHC binding has been rock solid for many years, I finally decided to port the binding to support openHAB 2 features.

Latest version: https://openhab.jfrog.io/openhab/libs-pullrequest-local/org/openhab/binding/org.openhab.binding.ihc/2.4.0-SNAPSHOT/

Documentation link

Some improvements / features:

By default, binding create channels automatically from project file (currently all dataline_inputs, dataline_outputs, airlink_inputs, airlink_outputs and resource_temperature).
Auto creation can be disabled, and channels can be created manually (then all resource id's are supported).
Support both Paper UI and thing files configuration.
Channels for basic controller information (state, SW and HW version, controller uptime, etc).
Trigger channels support (button short press, long press and extra long press).
Support multiple controllers (those who have e.g. two controllers environment).

Kandersen · December 3, 2018

3 timer siden, Pauli Anttila skrev:

Could you enable logs with trace level and try to reproduce the issue?

Easy to reproduce..
Restart Openhab, and it no longers receives any value changes from the controller.

This is from my main Rpi using the same controller and the same resource ID.

2018-12-03 18:38:30.385 [ome.event.ItemCommandEvent] - Item 'koekken_vasklys_niv' received command 36
2018-12-03 18:38:30.390 [vent.ItemStateChangedEvent] - koekken_vasklys_niv changed from 30 to 36

This is tracelog from the the second rpi with the latest ihc binding:
ihc tracelog.rar

Remember, it´s the same resource ID, so this should have resulted in the item changing from 30 to 36 on the second Rpi using the latest binding. It doesn´t. Actually, it doesn´t even update the values at all. Not untill I disable the binding from PaperUI and Enable it again. THen it starts update.
This is a screenshot from BasicUI right now (the second Rpi with the latest binding), before I disable the binding in PaperUI:

Now I disable the binding in PaperUI and enable it again:

2018-12-03 18:52:05.491 [hingStatusInfoChangedEvent] - 'ihc:controller:elko' changed from ONLINE to UNINITIALIZED
2018-12-03 18:52:09.823 [hingStatusInfoChangedEvent] - 'ihc:controller:elko' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)

2018-12-03 18:52:55.443 [me.event.ThingUpdatedEvent] - Thing 'ihc:controller:elko' has been updated.
2018-12-03 18:52:56.144 [vent.ItemStateChangedEvent] - ControllerUpTime changed from 669281.808 to 670295.524
2018-12-03 18:52:56.163 [hingStatusInfoChangedEvent] - 'ihc:controller:elko' changed from OFFLINE (BRIDGE_OFFLINE): Initializing communication to the IHC / ELKO controller to ONLINE
2018-12-03 18:52:56.173 [vent.ItemStateChangedEvent] - ControllerDateTime changed from 2018-12-03T16:36:54.000+0100 to 2018-12-03T16:53:48.000+0100
2018-12-03 18:52:56.759 [vent.ItemStateChangedEvent] - koekkenTelestat4a changed from NULL to OFF
2018-12-03 18:52:56.767 [vent.ItemStateChangedEvent] - SoveTemperature changed from NULL to 22.40
2018-12-03 18:52:56.769 [vent.ItemStateChangedEvent] - koekkenVask changed from NULL to 31
2018-12-03 18:52:56.773 [vent.ItemStateChangedEvent] - koekkenTemperature changed from NULL to 23.80

All I did was disable and enable after having restartet openhab.

Pauli Anttila · December 3, 2018

@Kandersen, IHC binding orders resource ID updates from controller only for channels which are linked to items. Some reason IHC binding doesn't get all channelLinked events (only 3) from openHAB.

2018-12-03 18:35:57.331 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - channelLinked: ihc:controller:elko:controllerState
2018-12-03 18:35:57.340 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - channelLinked: ihc:controller:elko:controllerTime
2018-12-03 18:35:57.339 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - channelLinked: ihc:controller:elko:controllerUptime

So, reason not seem to be in the binding itself but openhab/smarthome core.

Kandersen · December 4, 2018

But how come it works when I disable and then enable the thing (the controller)?

Pauli Anttila · December 4, 2018

6 hours ago, Kandersen said:

But how come it works when I disable and then enable the thing (the controller)?

Well, you log didn't contain information about that, but I assume that reason is that when you enable and disable the thing, all openHAB core features are up and running (which might not be the case when start the whole system). Could you send log which contains both full startup and then thing restart? Most of the bindings are not interested the channel linked events, so if there is a problem, it might not have influence to other bindings. If my interpretation is correct, we should make a bug report about it.

Kandersen · December 4, 2018

4 timer siden, Pauli Anttila skrev:

Well, you log didn't contain information about that, but I assume that reason is that when you enable and disable the thing, all openHAB core features are up and running (which might not be the case when start the whole system). Could you send log which contains both full startup and then thing restart? Most of the bindings are not interested the channel linked events, so if there is a problem, it might not have influence to other bindings. If my interpretation is correct, we should make a bug report about it.

Here you go. A new log with a full TRACE for start up, and disable/enable.

ihc tracelog2.rar

Mind you, I´m running openHab 2.4 Milestone (M7) on a Rpi 3B with apt-get hasslefree openHab.

Pauli Anttila · December 4, 2018

Quote

2018-12-04 20:40:29.043 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - channelLinked: ihc:controller:elko:controllerUptime
2018-12-04 20:40:29.043 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - channelLinked: ihc:controller:elko:controllerState
2018-12-04 20:40:29.047 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - channelLinked: ihc:controller:elko:controllerTime

2018-12-04 20:41:32.718 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - channelLinked: ihc:controller:elko:controllerState
2018-12-04 20:41:32.742 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - channelLinked: ihc:controller:elko:temperature6145300
2018-12-04 20:41:32.737 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - channelLinked: ihc:controller:elko:controllerTime
2018-12-04 20:41:32.756 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - channelLinked: ihc:controller:elko:controllerUptime
2018-12-04 20:41:32.773 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - channelLinked: ihc:controller:elko:temperature11011604
2018-12-04 20:41:32.780 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - channelLinked: ihc:controller:elko:output13957725
2018-12-04 20:41:32.780 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - channelLinked: ihc:controller:elko:output6512219

It seems to be exactly like I predicted. Some reason binding didn't get channel linked events for all items in start up. After disable/enable, binding receive more (all?) channel linked events like it should.

Kandersen · December 4, 2018

So whats up, openhab, binding, both combination?

Pauli Anttila · December 6, 2018

@Kandersen, could try this version https://www.dropbox.com/s/2i4bgpeii8qzixp/org.openhab.binding.ihc_2.4.0.201812061319.jar?dl=0

Please, rerun your test with trace logs (full start + enable/disable) and send logs to me, so I can also verify if this solve the problem on your environment.

Kandersen · December 6, 2018

5 minutter siden, Pauli Anttila skrev:

@Kandersen, could try this version https://www.dropbox.com/s/2i4bgpeii8qzixp/org.openhab.binding.ihc_2.4.0.201812061319.jar?dl=0

Please, rerun your test with trace logs (full start + enable/disable) and send logs to me, so I can also verify if this solve the problem on your environment.

Will give it a try tonight.. I saw Kai´s respons in the openhab community. I wonder how this would explain the differences between your Macbook setup and my Rpi setup.
Anyway - We´ll se tonight

Pauli Anttila · December 6, 2018

6 minutes ago, Kandersen said:

I wonder how this would explain the differences between your Macbook setup and my Rpi setup

It's a timing issue. My MacBook have more processor cores and much more faster than Rpi, so bindings and core bundles startup orders are different.

Kandersen · December 6, 2018

20 minutter siden, Pauli Anttila skrev:

so bindings and core bundles startup orders are different.

Hmm I thought it always was the same order.

Kandersen · December 6, 2018

7 timer siden, Pauli Anttila skrev:

@Kandersen, could try this version https://www.dropbox.com/s/2i4bgpeii8qzixp/org.openhab.binding.ihc_2.4.0.201812061319.jar?dl=0

Please, rerun your test with trace logs (full start + enable/disable) and send logs to me, so I can also verify if this solve the problem on your environment.

I get an error when openhab tries to load this binding:

2018-12-06 20:08:05.854 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel

2018-12-06 20:08:05.928 [INFO ] [ebuilder.internal.HomeBuilderServlet] - Started Home Builder at /homebuilder

2018-12-06 20:08:06.334 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Copenhagen'.

2018-12-06 20:08:06.341 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'da_DK'.

2018-12-06 20:08:14.014 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ihc.items'

2018-12-06 20:08:17.708 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007

2018-12-06 20:08:18.308 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ihc.sitemap'

2018-12-06 20:08:18.680 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ihc.things'

==> /var/log/openhab2/events.log <==

2018-12-06 20:08:18.967 [.ItemChannelLinkAddedEvent] - Link 'koekkenVask-ihc:controller:elko:output13957725' has been added.

2018-12-06 20:08:18.970 [.ItemChannelLinkAddedEvent] - Link 'ControllerState-ihc:controller:elko:controllerState' has been added.

2018-12-06 20:08:18.976 [.ItemChannelLinkAddedEvent] - Link 'SoveTemperature-ihc:controller:elko:temperature6145300' has been added.

2018-12-06 20:08:18.979 [.ItemChannelLinkAddedEvent] - Link 'ControllerDateTime-ihc:controller:elko:controllerTime' has been added.

2018-12-06 20:08:18.982 [.ItemChannelLinkAddedEvent] - Link 'koekkenTemperature-ihc:controller:elko:temperature11011604' has been added.

2018-12-06 20:08:18.984 [.ItemChannelLinkAddedEvent] - Link 'ControllerUpTime-ihc:controller:elko:controllerUptime' has been added.

2018-12-06 20:08:18.987 [.ItemChannelLinkAddedEvent] - Link 'koekkenTelestat4a-ihc:controller:elko:output6512219' has been added.

2018-12-06 20:08:19.116 [hingStatusInfoChangedEvent] - 'ihc:controller:elko' changed from UNINITIALIZED to INITIALIZING

==> /var/log/openhab2/openhab.log <==

2018-12-06 20:08:19.152 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.ihc.internal.handler.IhcHandler@e13727': null

java.lang.NullPointerException: null

at org.openhab.binding.ihc.internal.handler.IhcHandler.lambda$2(IhcHandler.java:176) ~[?:?]

at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:174) ~[?:?]

at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193) ~[?:?]

at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175) ~[?:?]

at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1382) ~[?:?]

at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481) ~[?:?]

at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471) ~[?:?]

at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708) ~[?:?]

at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:?]

at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499) ~[?:?]

at org.openhab.binding.ihc.internal.handler.IhcHandler.initialize(IhcHandler.java:176) ~[?:?]

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]

at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]

at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh240M7]

at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh240M7]

at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]

at java.lang.Thread.run(Thread.java:748) [?:?]

==> /var/log/openhab2/events.log <==

2018-12-06 20:08:19.192 [hingStatusInfoChangedEvent] - 'ihc:controller:elko' changed from INITIALIZING to UNINITIALIZED (HANDLER_INITIALIZING_ERROR)

==> /var/log/openhab2/openhab.log <==

2018-12-06 20:08:19.183 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'ihc:controller:elko': null