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

job · October 15, 2018, 5:46pm

@gerrieg, could you name some logger to put in trace mode to find more information about this problem?

I am unable to put the whole binding in trace, as soon as i do that, the pi slows down too much.

gerrieg · October 16, 2018, 3:18pm

To narrow this down, please try this:
Set these loglevels in the karaf console

log:set DEBUG org.eclipse.smarthome.binding.homematic
log:set TRACE org.eclipse.smarthome.binding.homematic.internal.communicator.AbstractHomematicGateway

and then do a restart.
In the logfile, there is now a trace for each device that starts with ‘Generating ThingType for device …’ with all the channels and datapoints beeing loaded from the gateway and generated for openHab.

If you have a device with the ‘Channel not found …’ warning, check if the datapoint is in the logfile for that device.

If not, the gateway does not send the datapoint metadata via api, but sends events.
if yes, check what openHab knows about that device. Open this rest url and check the result if the datapoint is available for that device:
http://[OPENHAB_URL:OPENHAB_PORT]/rest/things/{thingUID}
- if not, there is a problem generating the metadata
- if yes, there is another problem

job · October 16, 2018, 9:50pm

Thank you.

I set the log level and restarted.

So far it looks good (or bad, depending on view). No “Channel not found for datapoint”. I let it run for a few hours.

Mirko_Gerke · October 24, 2018, 10:23am

I’m seeing the same error for couple of my homematic sensors (connected to an up-to-date CCU2). One of them is a HM-Sec-SCo working smoothly at the CCU2 but resulting in “Channel not found for datapoint” when its state changes.

I changed the loggers according to @gerrieg last post.

“Generating ThingType for device …” only happens as follows:
(HM-Sec-SCo is not mentioned)

2018-10-24 12:07:53.185 [DEBUG] [rnal.type.HomematicTypeGeneratorImpl] - Generating ThingType for device 'HmIP-STH' with 1167 datapoints

2018-10-24 12:07:56.060 [DEBUG] [rnal.type.HomematicTypeGeneratorImpl] - Generating ThingType for device 'HmIP-WRC6' with 68 datapoints

2018-10-24 12:07:59.459 [DEBUG] [rnal.type.HomematicTypeGeneratorImpl] - Generating ThingType for device 'HMIP-PSM' with 442 datapoints

2018-10-24 12:08:07.016 [DEBUG] [rnal.type.HomematicTypeGeneratorImpl] - Generating ThingType for device 'HM-LC-Bl1-SM' with 389 datapoints

2018-10-24 12:08:07.188 [DEBUG] [rnal.type.HomematicTypeGeneratorImpl] - Generating ThingType for device 'GATEWAY-EXTRAS-CCU' with 10 datapoints

The log for the not working sensor during restart and after the first status change looks like this:

2018-10-24 12:08:07.465 [hingStatusInfoChangedEvent] - 'homematic:HM-Sec-SCo:ccu:MEQ0184635' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2018-10-24 12:08:07.621 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Integer) value '0' for 'MEQ0184635:0#RSSI_DEVICE' from gateway with id 'ccu'

2018-10-24 12:08:07.624 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Integer) value '-36' for 'MEQ0184635:0#RSSI_PEER' from gateway with id 'ccu'

2018-10-24 12:08:15.583 [DEBUG] [ommunicator.AbstractHomematicGateway] - Loading values for channel HmChannel[number=0,type=MAINTENANCE,initialized=false] of device 'MEQ0184635'

2018-10-24 12:08:15.748 [DEBUG] [ematic.handler.HomematicThingHandler] - Initializing thing 'homematic:HM-Sec-SCo:ccu:MEQ0184635' from gateway 'ccu'

2018-10-24 12:08:15.749 [DEBUG] [ommunicator.AbstractHomematicGateway] - Loading values for channel HmChannel[number=-1,type=HM-Sec-SCo,initialized=false] of device 'MEQ0184635'

2018-10-24 12:08:15.751 [hingStatusInfoChangedEvent] - 'homematic:HM-Sec-SCo:ccu:MEQ0184635' changed from INITIALIZING to ONLINE

2018-10-24 12:08:15.756 [DEBUG] [ommunicator.AbstractHomematicGateway] - Loading values for channel HmChannel[number=1,type=SHUTTER_CONTACT,initialized=false] of device 'MEQ0184635'

2018-10-24 12:08:16.484 [me.event.ThingUpdatedEvent] - Thing 'homematic:HM-Sec-SCo:ccu:MEQ0184635' has been updated.

2018-10-24 12:12:19.859 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Boolean) value 'true' for 'MEQ0184635:1#STATE' from gateway with id 'ccu'

2018-10-24 12:12:19.861 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0184635:1#STATE'

2018-10-24 12:12:19.864 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0184635:1#LOWBAT' from gateway with id 'ccu'

2018-10-24 12:12:19.866 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0184635:1#LOWBAT'

2018-10-24 12:12:25.000 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0184635:1#STATE' from gateway with id 'ccu'

2018-10-24 12:12:25.004 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0184635:1#STATE'

2018-10-24 12:12:25.008 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Boolean) value 'false' for 'MEQ0184635:1#LOWBAT' from gateway with id 'ccu'

2018-10-24 12:12:25.012 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint 'MEQ0184635:1#LOWBAT'

And here’s what the rest-call returns:

{"status":"UNINITIALIZED","statusDetail":"BRIDGE_UNINITIALIZED"},"editable":true,"label":"EG_WOHNZIMMER_KONTAKT_TERRASSE","bridgeUID":"homematic:bridge:LEQ0395803","configuration":{"HMP_-1_CYCLIC_INFO_MSG":true,"HMP_1_EVENT_DELAYTIME":0.0,"HMP_-1_TRANSMIT_DEV_TRY_MAX":6,"HMP_1_TRANSMIT_TRY_MAX":6,"HMP_1_AES_ACTIVE":true,"HMP_-1_SABOTAGE_MSG":true,"HMP_-1_LOCAL_RESET_DISABLE":false,"HMP_1_MSG_FOR_POS_B":"OPEN","HMP_1_MSG_FOR_POS_A":"CLOSED"},"properties":{"serialNumber":"MEQ0184635","modelId":"HM-Sec-SCo","vendor":"eQ-3 AG","aesKey":"0","firmwareVersion":"1.0","batteryType":"1x AAA/Micro/LR03"},"UID":"homematic:HM-Sec-SCo:LEQ0395803:MEQ0184635","thingTypeUID":"homematic:HM-Sec-SCo","channels":[]}

Is there anything I can do?

Thanks
Mirko

gerrieg · October 24, 2018, 1:54pm

@Mirko_Gerke
What i see is a wrong bridgeUID for this device: homematic:bridge:LEQ0395803. This should be homematic:bridge:ccu

Do you use things files or PaperUI?

job · October 24, 2018, 2:10pm

After a week i did not find a single channel not found for datapoint warning in my logs.

The only change i did, was setting the log level as @gerrieg suggested. I am using things and items files. This is according to my opinion a clear indication that this is a timing problem and no general problem.

I will now set the binding back to warn level, but keep the abstract gateway at trace and restart.

lars_francke · December 29, 2018, 9:44pm

I have the same issue every once in a while and am trying to debug as well.

If you @gerrieg have a few minutes to explain that’d be great.

I see that the issue is that getChannel returns null which is the case because my devices don’t have any channels at all (as also seen in the log examples above). So I’m trying to see where setChannels in ThingImpl is being set.

I assumed that the doInitializeInBackground method in HomematicThingHandler is responsible for that but I have not yet seen that in any stack trace at all.

Instead I see it being called from GenericThingProvider (lazyRetryRunnable) but I don’t know where that comes from.

Now to my question: I’d like to add some more debugging to the homematic binding and I was able to build the smarthome project using Maven. Unfortunately I have no idea at all how to now use my new snapshot build. Can anyone give me any hints on how to deploy which files in which way?

gerrieg · December 31, 2018, 8:19am

Copy the new jar to the addons folder. Then, in the Karaf console write

bundle:list | grep Homematic

You should see 2 Versions of the binding and one active. For the next commands, use the ID.

bundle:stop ID_OLD_VERSION
bundle:uninstall ID_OLD_VERSION

bundle:start ID_NEW_VERSION

Then restart openHab.

lars_francke · January 3, 2019, 7:04pm

Happy new year and thank you very much @gerrieg. I know what to do the next time it occurs now.

jensilein · January 14, 2019, 10:35pm

Hello Gerhard, I’m running OpenHab 2.2 with homematic binding to a RaspBerryMatic. Some days ago I updated my RaspBerryMatic from a quite old version to the latest version. Since that day I get a lot of error messages “Channel not found for datapoint …” in my openhab.log. How can I solve the problem? Is there a new or updated homematic binding available that I can install to eleminate these error messages? If yes, where can I get it from and how to perform the update process? Or is there another workaround that you can propose to me? Thank you very much in advance for your help.

OzZy_HH · January 15, 2019, 4:10pm

Unfortunately since my upgrade to version 2.4 I experience this error very often. I have to restart OH multiple times to get my setup in a working state. Does it help to provide debug logs? I’m using a RPi3 and docker on Raspbian Stretch

mbronk · February 4, 2019, 8:28pm

I am encountering this issue quite frequently on my setup, and while I am sadly not available at this moment to help debug this further, I hope the following details may help someone to get a more stable repro (in my case, the issue manifests itself every 2-3 days).
I am running: OH 2.4.0(stable) + Homegear 0.7.34-2678 on an Odroid C1 with an almost-read-only setup (all the logging and most part of configuration redirected to ramfs). This means I use quite a few logrotate scripts (triggering on log size) which also do:

reload Homegear service after its logs rotation,

/var/log/homegear/*.log /var/log/homegear/*.err {
    missingok
    rotate 1
    compress
    delaycompress
    notifempty
    size 1M
    create 644 homegear homegear
    sharedscripts
    postrotate
    service homegear reload > /dev/null
    endscript
}

restart Openhab after its logs rotation

/opt/openhab2/userdata/logs/*.log {
    missingok
    rotate 1
    compress
    delaycompress
    notifempty
    size 1M
    create 640 openhab openhab
    sharedscripts
    postrotate
    service openhab2 restart > /dev/null
    endscript
}

Quite frequently, I get either of the 2 error conditions:

some Homematic things end up in UNITIALIZED (BRIDGE_UNINTIALIZED) state, while others using the same bridge are ONLINE (the bridge also is).
all the things seem to be ONLINE, though no actual data is received, and the log is flooded by Channel not found for datapoint errors

Condition #2 is more nasty, as it is not detectible from the UI, and only visible in the logs (or when items start lingering in a stale state for a while).
This started happening to me after migration from OH 2.3, but I changed quite a lot of things in my setup, so multiple conditions may have caused it.
Workaround that brings my system back to life is touching the .things file (I even have a rule for it ).

–
All in all, to a naked eye this appears to be a timing issue indeed. If getting a stable repro is of issue, I hope trying to loop-reload Homegear while OH is running may help trace it.

Will try to collect more useful info once I find some time for it.

flohei · July 30, 2019, 8:04pm

I’m seeing the exact same behavior as @mbronk. I can also confirm that touching my homematic.things file seems to help. Sometimes I need to do it twice.

One additional detail that might help in our investigation: For me this only happens for my HomeMatic IP devices. Regular devices seem never to be affected.

chill.kroete · September 24, 2019, 3:39am

Hi,

I am facing the same issue with “Channel not found for datapoint”. While everything was working fine, suddenly the warnings showed up and my thermostats failed to set their temperature.
Setting the log level did not change anything:

2019-09-23 22:37:37.496 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Integer) value '0' for 'OEQ2636958:4#PARTY_STOP_TIME' from gateway with id 'ccu'

2019-09-23 22:37:37.511 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint ‘OEQ2636958:4#PARTY_STOP_TIME’
2019-09-23 22:37:37.530 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Integer) value ‘1’ for ‘OEQ2636958:4#PARTY_STOP_DAY’ from gateway with id ‘ccu’
2019-09-23 22:37:37.563 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint ‘OEQ2636958:4#PARTY_STOP_DAY’
2019-09-23 22:37:37.589 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Integer) value ‘1’ for ‘OEQ2636958:4#PARTY_STOP_MONTH’ from gateway with id ‘ccu’
2019-09-23 22:37:37.604 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint ‘OEQ2636958:4#PARTY_STOP_MONTH’
2019-09-23 22:37:37.629 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Integer) value ‘0’ for ‘OEQ2636958:4#PARTY_STOP_YEAR’ from gateway with id ‘ccu’
2019-09-23 22:37:37.646 [WARN ] [ematic.handler.HomematicThingHandler] - Channel not found for datapoint ‘OEQ2636958:4#PARTY_STOP_YEAR’
2019-09-23 22:37:38.610 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (String) value ‘3014F711A0001F98A9AABBDA’ for ‘CENTRAL:0#PONG’ from gateway with id ‘ccu’
2019-09-23 22:37:38.625 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (String) value ‘3014F711A0001F98A9AABBDA’ for ‘CENTRAL:0#PONG’ from gateway with id ‘3014F711A0001F98A9AABBDA’
2019-09-23 22:37:51.782 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (String) value ‘ccu’ for ‘CENTRAL:0#PONG’ from gateway with id ‘3014F711A0001F98A9AABBDA’
2019-09-23 22:37:51.803 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (String) value ‘ccu’ for ‘CENTRAL:0#PONG’ from gateway with id ‘ccu’
2019-09-23 22:37:52.601 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Integer) value ‘1’ for ‘OEQ2636589:4#CONTROL_MODE’ from gateway with id ‘3014F711A0001F98A9AABBDA’

I also tried what has been suggested here Cleaning up the startup process / renaming rules (windows possible) (the prefered variant).

Is there anything else I can try? Can I provide any additional information?

Flole · October 18, 2019, 4:39pm

I am seeing this on Bidcos based devices aswell.

mbronk · June 11, 2020, 11:48am

Has there been any progress on this issue?

I am still seeing the Channel not found for datapoint warnings intermittently and my things stop updating (now at OH:2.5.5 + Homegear: 0.7.45-3101).
It does look like a timing/threading issue to me… each time it seems to only affect a few HM-CC-RT-DN devices from the set I have. Which one gets affected, seems completely random (btw. they all look perfectly OK the whole time in Homegear). Restarting Openhab multiple times (or reloading things file) seems to help (at least for some time), but the errors come back after the server is running for a longer while.

Unfortunately, when this happens, there is no way I know of*, to programmatically detect this, so that it can be auto-recovered from using a rule… so is very annoying
* - other than inspecting LastUpdate of items or having a log parsing rule (ugh!)

BTW. Unsure if it matters, though FYI - I am using a purely things file-based configuration (e.g. the JSON DB gets wiped each time I upgrade OpenHab).

There used to be a simmilar issues reported here: https://github.com/openhab/openhab-addons/issues/3010 and here: https://github.com/openhab/openhab-addons/issues/1825
@gerrieg - Can you please advise if they are related? Would it help if we move this conversation into a proper github issue?

What would be the next steps to get it fixed?

MHerbst · June 11, 2020, 12:07pm

I have also got several HM-CC-RT-DN but have never seen any error messages regaridng this device.
But I am using Raspberrymatic and not Homegear, so maybe this problem has to do with Homegear.

Can you give us some more information about your installation:

on what kind of machine openHAB is installed?
where is Homegear running? Is it installed on the same machine
is always the same channel affected or does it also change randomly?
can you post the exact error message?

It would help if you could enable trace and then post all relevant messages from openhab.log that have been looged before the error message.

mbronk · June 11, 2020, 12:45pm

Hello @MHerbst,
I have no data to support it, but I am open to the hypothesis that the issue might very well be triggered by Homegear (I am sure it has some quirks to it - some I had to manually work around, to get OH/Homegear work with Winmatic window opener ).

Though, even if Homegear is the trigger… given restarting Openhab without touching Homegear does help - I claim it is Openhab which needs a bugfix At the very least - it is now unable to recover from an intermittent issue (assuming it was Homegear’s fault).

To your questions:

It is an Odroid C1 board running Ubuntu 18.04.4 LTS. This is my custom setup/install with (almost)read-only filesystem (most of the data sits in ramdisk) - particularily: not using Openhabian / using text based configuration for everything.

Yes - running on localhost. Here’s my bridge config:

Bridge homematic:bridge:homegear [ gatewayAddress="127.0.0.1", type="auto", callbackHost="127.0.0.1", rfPort="2001" ]

It is always all the channels I have configured for a particular device (typically 1-2 devices out of 4 HM-CC-RT-DN’s behave like this)

See below - 2 log 'entries' (**click to expand**)

2020-06-11 10:34:57.243 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:0#RSSI_DEVICE'
2020-06-11 10:34:57.246 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:0#RSSI'
2020-06-11 10:34:57.249 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:0#SIGNAL_STRENGTH'
2020-06-11 10:34:57.255 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:0#LOWBAT'
2020-06-11 10:34:57.263 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#ACTUAL_TEMPERATURE'
2020-06-11 10:34:57.267 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#BATTERY_STATE'
2020-06-11 10:34:57.271 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#BOOST_STATE'
2020-06-11 10:34:57.275 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#CONTROL_MODE'
2020-06-11 10:34:57.279 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#FAULT_REPORTING'
2020-06-11 10:34:57.283 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#PARTY_START_TIME'
2020-06-11 10:34:57.287 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#SET_TEMPERATURE'
2020-06-11 10:34:57.290 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#VALVE_STATE'
2020-06-11 10:37:11.801 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:0#RSSI_DEVICE'
2020-06-11 10:37:11.810 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:0#RSSI'
2020-06-11 10:37:11.814 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:0#SIGNAL_STRENGTH'
2020-06-11 10:37:11.820 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:0#LOWBAT'
2020-06-11 10:37:11.829 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#ACTUAL_TEMPERATURE'
2020-06-11 10:37:11.835 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#BATTERY_STATE'
2020-06-11 10:37:11.842 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#BOOST_STATE'
2020-06-11 10:37:11.848 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#CONTROL_MODE'
2020-06-11 10:37:11.853 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#FAULT_REPORTING'
2020-06-11 10:37:11.858 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#PARTY_START_TIME'
2020-06-11 10:37:11.863 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#SET_TEMPERATURE'
2020-06-11 10:37:11.869 [WARN ] [ternal.handler.HomematicThingHandler] - Channel not found for datapoint 'KEQ0573507:4#VALVE_STATE'

Note it is logged as a WARN - and there’s no error in the PaperUI/HabMin - the devices just stop updating. Also, the WARNs flood the logs when this happens (I am stipulating a WARN is produced each time the device sends a channel update)

Unfortunately, the issue is intermittent, with no known trigger I know of. Since my setup is logging to a ramdisk, I cannot leave it enabled on TRACE for any period longer than sub-minutes, as it overflows too quickly and logrotate doesn’t keep up. I’ll need to redo my whole setup to be able to capture more logging (not impossible, but very time consumung).

And my take is, there are 2 issues:

For this issue happening (condition unknown)
For the binding not recovering, once it has happened.

Logs are certainly critical for #1, but perhaps we can work with what we have for for #2 ? I think @lars_francke might have been on to something with the getChannel() returning NULLs.

Since others are also seeing this issue - perhaps someone can provide a decent log trace?

MHerbst · June 11, 2020, 5:57pm

This is really a strang thing. Either openHAB “forgot” the thing definition and the channels or for some reason the device id has changed. I think, I can enhance the warning log message to print some more information.

job · June 11, 2020, 6:32pm

Not really.

With using thing files the Homematic Binding queries the channels on every restart and creates the thing with the queried channels. Sometimes the binding does not collect all channels and when data for these channels arrives the “Channel not found for datapoint” error is triggered.

If you use JsonDB the thing is only created once, if channels are missing, these are missing forever (until you delete and recreate the thing from the Inbox). Data for missing channels triggers the warning.

The real problem occurs when the devices are queried and the due to some communication hickup some channels are missing. “Channel not found for datapoint” is just the symptom, not the problem.

I have given up on this problem long time ago and moved all critical heating related stuff one layer down to Homegear & Node-Blue.

The best solution would be to create the channel if data arrives, but i do not know if the information is sufficent to create the channel.

This happens more often with devices with massive amounts of channels (radiator thermostat and wall thermostat) but i have also seen this with wall mounted motion detectors or switches.