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

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

waitz_sebastian · May 11, 2017, 8:04am

Just came accross this issue when updating to lastest snapshot version and got loads of “Channel not found for datapoint” messages in my log. Mainly the RSSI and SIGNAL_STRENGTH points for all devices.
I’m using a normal CCU2.
Is it really required to migrate to homematic.things file setup? Till now I used the discovery functionality via PaperUI.
Is there any migration guidline? Something like sed’ing some PaperUI created config files, spitting the .things file config?
That would help a lot to setup the things file.

falkena · May 12, 2017, 7:55pm

Hi @gerrieg,

built and test currently your last Pull-Request. It seems work so far. Only one thing. I get a lot of

2017-05-12 21:50:37.707 [INFO ] [ommunicator.AbstractHomematicGateway] - No event since 943 seconds from gateway 'homegear', restarting RPC server

messages now. After server restart device values will be updated. Tried to debug, but got no clue about the possible reason.

Any idea?

Thanks and kind regards,

Alexander

gerrieg · May 13, 2017, 8:40am

Hi @falkena

Which server did you restart? OH or Homegear?
Hmm, no idea, my last changes should have no influence on it. Can you reproduce this or was it unique?

falkena · May 13, 2017, 8:50am

Hi @gerrieg,

I’m running homegear. The error is reproducible. Got a little bit more clue. The

 serverSocket.accept()

in

BinRpcNetworkService::run()

throws an exception. I’ve not found any call to

getRpcCallbackURL

too. Hope it helps.

EDIT: INFO occures on both 2.0.0 release and 2.1.0 snapshot.

Thank you and kind regards,

Alexander