Homematic Binding: "Channel not found for datapoint" errors for definitely existing channels

0xMUHAHA · April 5, 2017, 7:38pm

Hello!

I have just updated to the latest snapshot (version via apt-cache: 2.1.0~20170331113737-1) and experience Channel not found for datapoint errors. Others have already experienced the same problem and I already tried the solutions here and here. Before the update my openHAB version was version 2.0 (the release version).

I tried (everything via Paper UI, no *.thing-files involved):

just deleting every Homematic thing and the bridge (recreation with same thing ids) and
then deleting all things and use new thing ids for recreation

However, errors like in the log below still occur:

21:24:31.608 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0863007:0#RSSI_DEVICE'
21:24:31.616 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0863007:0#RSSI'
21:24:31.621 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0863007:0#SIGNAL_STRENGTH'
21:24:31.629 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value '35.0' for 'MEQ0863007:2#ACTUAL_HUMIDITY' from gateway with id 'xxxx'
21:24:31.633 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0863007:2#ACTUAL_HUMIDITY'
21:24:31.640 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value '23.9' for 'MEQ0863007:2#ACTUAL_TEMPERATURE' from gateway with id 'xxxx'
21:24:31.644 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0863007:2#ACTUAL_TEMPERATURE'
21:24:31.648 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value '4.5' for 'MEQ0863007:2#SET_TEMPERATURE' from gateway with id 'xxxx'
21:24:31.654 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0863007:2#SET_TEMPERATURE'
21:24:51.607 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '-52' for 'MEQ0863007:0#RSSI_DEVICE' from gateway with id 'xxxx'
21:24:51.611 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0863007:0#RSSI_DEVICE'
21:24:51.615 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0863007:0#RSSI'
21:24:51.620 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0863007:0#SIGNAL_STRENGTH'
21:24:51.629 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '35' for 'MEQ0863007:1#HUMIDITY' from gateway with id 'xxxx'
21:24:51.633 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0863007:1#HUMIDITY'
21:24:51.636 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value '23.9' for 'MEQ0863007:1#TEMPERATURE' from gateway with id 'xxxx'
21:24:51.641 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0863007:1#TEMPERATURE'

The device in question is a wireless wall thermostat, so it definitely has the humidity and temperature datapoints. I am not sure if a log with TRACE-level output would help, but I could post one if necessary.

gerrieg · April 6, 2017, 6:35am

The Homematic Binding dynamically adds all the Homematic channels and datapoints at startup to OH2. In the 2.1 version, i’ve implemented some more virtual datapoints. It seems, that the Thing and Channel config is saved by PaperUI and does not match anymore with the new (2.1) Thing/Channels.

It’s better to use things files, i never had this problem with them.

0xMUHAHA · April 6, 2017, 11:19am

Hi!

Thanks for your response!

Using thing-files is not a problem for me as almost everything I have except homematic is configured in such files… but actually, the point of openHAB2 and Paper UI was to ease configuration without touching config files in the first place as far as I know.

0xMUHAHA · April 9, 2017, 4:34pm

@gerrieg

Okay, I have removed the things from Paper UI and re-added them via one *.things-file. The problem persists, so I would assume that this is definitely not a Paper UI-Problem.

Interestingly, the binding complains about the devices not being present at the gateway first and then finds it after some time. This does not happen for all devices, but it looks like that if this happens, this device is then subject to these datapoint errors.

Log file:

18:22:29.771 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'homematic:HG-HM-Sec-SCo:default:MEQ0907189' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR): Device with address 'MEQ0907189' not found on gateway 'default'
...
18:22:33.290 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'homematic:HG-HM-Sec-SCo:default:MEQ0907189' changed from OFFLINE (CONFIGURATION_ERROR): Device with address 'MEQ0907189' not found on gateway 'default' to ONLINE
18:22:33.292 [DEBUG] [ternal.communicator.HomematicGateway] - Loading values for channel HmChannel[number=7,type=SWITCH_TRANSMIT,initialized=false] of device 'MEQ0864289'
18:22:33.299 [DEBUG] [ternal.communicator.HomematicGateway] - Loading values for channel HmChannel[number=1,type=SHUTTER_CONTACT,initialized=false] of device 'MEQ0907189'
18:22:33.361 [DEBUG] [ematic.handler.HomematicThingHandler] - Initializing thing 'homematic:HG-HM-Sec-SCo:default:MEQ0907189' from gateway 'default'
18:22:33.373 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'homematic:HG-HM-Sec-SCo:default:MEQ0907189' has been updated.
18:22:33.380 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'homematic:HG-HM-Sec-SCo:default:MEQ0907189' has been updated.

Part of my things-file:

Bridge homematic:bridge:default [gatewayAddress="127.0.0.1", callbackHost="127.0.0.1"] 
{
	  Thing HG-HM-Sec-SCo			MEQ0907189 "Description"
}

Edit: to clarify, this does not just only happen with datapoints like RSSI or LOWBAT, but for my wireless wall thermostats with the temperature and humidity datapoints as well.

In the meantime I also tried restarting openHAB, but that does not resolve the problem. Newer snapshots are not yet available on testing, so it seems like I am on the latest snapshot version at the time of writing.

gerrieg · April 10, 2017, 4:03pm

Hmmm, then i need a full startup TRACE log please, see docs

0xMUHAHA · April 10, 2017, 5:55pm

Hello!

Here is the link to the logfile: https://drive.google.com/open?id=0B_DNas072orBNUhlWUlWOG9BUWM.

gerrieg · April 11, 2017, 3:27pm

looks good, can’t see any problem. Can you please post the result from:

http://[URL]:[PORT]/rest/things/homematic%3AHG-HM-Sec-SCo%3Adefault%3AMEQ0907189

0xMUHAHA · April 11, 2017, 6:46pm

Thanks for your response!

The output of your REST-call is as follows:

{
  "statusInfo": {
    "status": "ONLINE",
    "statusDetail": "NONE"
  },
  "label": "WohnungstÃ¼r",
  "bridgeUID": "homematic:bridge:default",
  "configuration": {
    "HMP_1_EVENT_DELAYTIME": 0.0,
    "HMP_1_AES_ACTIVE": true,
    "HMP_1_TRANSMIT_TRY_MAX": 6,
    "HMP_1_MSG_FOR_POS_B": "OPEN",
    "HMP_0_TRANSMIT_DEV_TRY_MAX": 6,
    "HMP_0_CYCLIC_INFO_MSG": true,
    "HMP_1_MSG_FOR_POS_A": "CLOSED",
    "HMP_0_ROAMING": false,
    "HMP_0_LOCAL_RESET_DISABLE": false,
    "HMP_0_SABOTAGE_MSG": true
  },
  "properties": {
    "firmwareVersion": "1.0",
    "batteryType": "1x AAA/Micro/LR03"
  },
  "UID": "homematic:HG-HM-Sec-SCo:default:MEQ0907189",
  "thingTypeUID": "homematic:HG-HM-Sec-SCo",
  "channels": []
}

gerrieg · April 12, 2017, 12:51pm

This looks as if OH does not have all the channel types the homematic binding generates. But in the logfile, the binding generates these channel types.

I have no idea, the only way to find it out is that i can access your homegear instance. Would it be possible? I’m testing only the binding startup, i don’t switch or change something.

0xMUHAHA · April 12, 2017, 3:57pm

Hi!

I just realized that also wall switches and window switches do not work (see log at the end of the post).

So this means the problem may be homegear? Should not be a problem. However, if it is easier for you I also could send you a dump of the homegear database for example.

17:49:06.747 [TRACE] [nicator.server.BinRpcCallbackHandler] - Event BinRpcMessage: system.multicall()
[
	{
		methodName=event
		params=
		[
			RF-default
			LTK0050475:0
			RSSI_DEVICE
			-69
		]
	}
]

17:49:06.757 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '-69' for 'LTK0050475:0#RSSI_DEVICE' from gateway with id 'default'
17:49:06.763 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'LTK0050475:0#RSSI_DEVICE'
17:49:06.767 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'LTK0050475:0#RSSI'
17:49:06.771 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'LTK0050475:0#SIGNAL_STRENGTH'
17:49:06.840 [TRACE] [nicator.server.BinRpcCallbackHandler] - Event BinRpcMessage: system.multicall()
[
	{
		methodName=event
		params=
		[
			RF-default
			LTK0050475:1
			INSTALL_TEST
			true
		]
	}
	{
		methodName=event
		params=
		[
			RF-default
			LTK0050475:1
			PRESS_SHORT
			true
		]
	}
]

17:49:06.846 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'true' for 'LTK0050475:1#INSTALL_TEST' from gateway with id 'default'
17:49:06.849 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'LTK0050475:1#INSTALL_TEST'
17:49:06.857 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'true' for 'LTK0050475:1#PRESS_SHORT' from gateway with id 'default'
17:49:06.861 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'LTK0050475:1#PRESS_SHORT'
17:49:06.864 [DEBUG] [ematic.internal.misc.DelayedExecuter] - Delaying event for 2.0 seconds: 'LTK0050475:1#PRESS_SHORT'
17:49:08.817 [TRACE] [nicator.server.BinRpcCallbackHandler] - Event BinRpcMessage: system.multicall()
[
	{
		methodName=event
		params=
		[
			RF-default
			MEQ0907189:0
			RSSI_DEVICE
			-58
		]
	}
]

17:49:08.819 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value '-58' for 'MEQ0907189:0#RSSI_DEVICE' from gateway with id 'default'
17:49:08.824 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0907189:0#RSSI_DEVICE'
17:49:08.828 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0907189:0#RSSI'
17:49:08.832 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0907189:0#SIGNAL_STRENGTH'
17:49:08.868 [DEBUG] [ematic.internal.misc.DelayedExecuter] - Executing delayed event for 'LTK0050475:1#PRESS_SHORT'
17:49:08.878 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'LTK0050475:1#PRESS_SHORT'
17:49:08.911 [TRACE] [nicator.server.BinRpcCallbackHandler] - Event BinRpcMessage: system.multicall()
[
	{
		methodName=event
		params=
		[
			RF-default
			MEQ0907189:1
			LOWBAT
			false
		]
	}
	{
		methodName=event
		params=
		[
			RF-default
			MEQ0907189:1
			STATE
			true
		]
	}
]

17:49:08.913 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0907189:1#LOWBAT' from gateway with id 'default'
17:49:08.916 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0907189:1#LOWBAT'
17:49:08.919 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'true' for 'MEQ0907189:1#STATE' from gateway with id 'default'
17:49:08.926 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0907189:1#STATE'
17:49:10.431 [TRACE] [nicator.server.BinRpcCallbackHandler] - Event BinRpcMessage: system.multicall()
[
	{
		methodName=event
		params=
		[
			RF-default
			MEQ0907189:1
			LOWBAT
			false
		]
	}
	{
		methodName=event
		params=
		[
			RF-default
			MEQ0907189:1
			STATE
			false
		]
	}
]

17:49:10.433 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0907189:1#LOWBAT' from gateway with id 'default'
17:49:10.437 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0907189:1#LOWBAT'
17:49:10.443 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0907189:1#STATE' from gateway with id 'default'
17:49:10.449 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0907189:1#STATE'

gerrieg · April 13, 2017, 5:50am

Yes, a dump is much easier, i always think of a CCU
Just send me a private message

0xMUHAHA · April 17, 2017, 8:03am

Topic update for anybody having the same problem: after some investigation with gerrieg, current state is that it is not Homegear’s fault and even reinstalling Homegear and OpenHAB did not yet resolve the problem.

falkena · April 23, 2017, 5:19pm

Hi everybody,

it seems, that the error is device independend. I have this problem with thremostats:

>     18:06:05.365 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...4:0#RSSI_DEVICE'
>     18:06:05.368 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...4:0#RSSI'
>     18:06:05.370 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...4:0#SIGNAL_STRENGTH'
>     18:06:05.399 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...4:4#ACTUAL_TEMPERATURE'
>     18:06:05.402 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...4:4#BATTERY_STATE'
>     18:06:05.405 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...4:4#BOOST_STATE'
>     18:06:05.408 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...4:4#CONTROL_MODE'
>     18:06:05.411 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...4:4#FAULT_REPORTING'
>     18:06:05.413 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...4:4#PARTY_START_TIME'
>     18:06:05.416 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...4:4#SET_TEMPERATURE'
>     18:06:05.418 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...4:4#VALVE_STATE'
>     18:06:22.105 [INFO ] [marthome.event.ItemStateChangedEvent] - Today changed from 2017-04-23T18:05:22.056+0200 to 2017-04-23T18:06:22.056+0200
>     18:07:06.787 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...5:0#RSSI_DEVICE'
>     18:07:06.791 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...5:0#RSSI'
>     18:07:06.793 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...5:0#SIGNAL_STRENGTH'
>     18:07:06.810 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...5:4#ACTUAL_TEMPERATURE'
>     18:07:06.813 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...5:4#BATTERY_STATE'
>     18:07:06.816 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...5:4#BOOST_STATE'
>     18:07:06.818 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...5:4#CONTROL_MODE'
>     18:07:06.821 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...5:4#FAULT_REPORTING'
>     18:07:06.824 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...5:4#PARTY_START_TIME'
>     18:07:06.827 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...5:4#SET_TEMPERATURE'
>     18:07:06.830 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'NEQ...5:4#VALVE_STATE'

Thermostats are configured vie *.things file. And i’m using homegear.
Restarting openHAB results in the same error. Sometimes for one, sometimes for another thermostat.
Last restart produced errors for both. I’ve tried to clear the cache without any success.

Kind regards,

Alexander

0xMUHAHA · April 23, 2017, 8:02pm

Hey!

I had a conversion with @gerrieg about that… It seems to be a timing issue at startup, and I sometimes have it for one device, at next startup for another or sometimes even for none of my devices. Cleanly setting up homegear or even OpenHAB2 did not work. In some testing with gerrieg we could confirm that if you setup OpenHAB2 on e.g. a PC (something that is faster than a RasperryPi in my case) that indeed the errors vanish.

falkena · April 23, 2017, 8:13pm

HI,

i’m running OH2 on Raspberry also. I took a look into source code. Thing - initialize method try to update configuration from another thread. May be the problem reside here. And update configuration should be syncronized.

BTW. I got the same problem on my 6 year old laptop, not tried on newer one

Thanks and kind regards,

Alexander

falkena · April 30, 2017, 8:37pm

Hi @0xMUHAHA, @gerrieg

played a little bit around this bug. Error seems to go away, if i remove

scheduler.execute(new Runnable() {  ...});

calls in

HomematicBridgeHandler::initialize()

and

HomematicThingHandler::initialize()

Now i have a lot of

No event since 2822 seconds from gateway 'homegear', restarting RPC server
No event since 2882 seconds from gateway 'homegear', restarting RPC server

messages. Maybe it helps.

Greetings,

Alexander

0xMUHAHA · May 3, 2017, 6:19pm

Hello Alexander!

Thanks for letting me know!
Gerhard sent me a debug version before he went on holidays fixing this issue (but fortunately not in every case), but I am glad that you found out what may be the issue.

Maybe this helps in fixing this one and for all, but I haven’t tried so far as I am glad that the system keeps running without any other problems for the moment being

Greetings,
Wolfgang

falkena · May 3, 2017, 7:22pm

Hi Wolfgang,

i found the reason, why i had RPC server errors: callbackHost was wrong in Homegear bridge.
I’ve copied the configuration from Raspberry to my Laptop for better debugging and forgot to change it.

Seems to run so far. I’ll test it a little bit longer now.

Greetings,

Alexander

gerrieg · May 7, 2017, 8:55am

@falkena
These threads were also my first idea.

Seems to be a timing issue in the framework itself. I removed the thread in the BridgeHandler and @0xMUHAHA confirmed that it works now.

falkena · May 7, 2017, 11:27am

Hi @gerrieg,

i think i got it. Simply removing a thread in BridgeHandler worked not stable. I’ll test it on my Raspberry today. And, if the test was successful, i will make a PR to your homematic branch today. It should be tested on CCU also: i’ve Homegeear only. If it works @Kai should be happy with a solution

EDIT: PR is open: https://github.com/gerrieg/openhab2-addons/pull/3

Kind regards,

Alexander