Openhab-addons: [Homematic] Variables not refreshing state from CCU

[McLive]

I now switched from CCU1 to 2 but still having issues with systemvariables.

I am able to change the state of a systemvariable and see the status on the homematic interface.

But after changing the systemvariable with an homematic programm, the documentation says I have to send an REFRESH command to any variable.

I have this item:

Switch Test "Test [%s]" { channel="homematic:GATEWAY-EXTRAS-FE7F373F:fe7f373f:GWE00000000:1#Systemvariable" }

and sent this command:

openhab> smarthome:send Test REFRESH
Command has been sent successfully.

This is the response I got:
2017-06-03 14:54:26.551 [DEBUG] [ematic.handler.HomematicThingHandler] - Received command 'REFRESH' for channel 'homematic:GATEWAY-EXTRAS-FE7F373F:fe7f373f:GWE00000000:1#Systemvariable' 2017-06-03 14:54:26.554 [DEBUG] [ematic.handler.HomematicThingHandler] - Refreshing GWE00000000:1#Systemvariable 2017-06-03 14:54:26.557 [DEBUG] [ommunicator.AbstractHomematicGateway] - Handling virtual datapoint 'RELOAD_FROM_GATEWAY' on gateway with id 'fe7f373f' 2017-06-03 14:54:26.559 [DEBUG] [ommunicator.AbstractHomematicGateway] - Triggering values reload for device 'GWE00000000' 2017-06-03 14:54:26.562 [DEBUG] [atic.type.HomematicTypeGeneratorImpl] - Generating ThingType for device 'GATEWAY-EXTRAS-FE7F373F' with 15 datapoints 2017-06-03 14:54:26.564 [DEBUG] [ematic.handler.HomematicThingHandler] - Initializing thing 'homematic:GATEWAY-EXTRAS-FE7F373F:fe7f373f:GWE00000000' from gateway 'fe7f373f' 2017-06-03 14:54:26.576 [DEBUG] [ematic.internal.misc.DelayedExecuter] - Delaying event for 2.0 seconds: 'GWE00000000:0#RELOAD_FROM_GATEWAY' 2017-06-03 14:54:28.582 [DEBUG] [ematic.internal.misc.DelayedExecuter] - Executing delayed event for 'GWE00000000:0#RELOAD_FROM_GATEWAY'

But it still shows the wrong state in my sitemap.

[MHerbst]

Are you using the latest snapshot build or an older version? Maybe it is just a problem of the item type. As far as I know a switch item understands only the values "ON" and "OFF".
You could also activate a the trace or even debug. Then the low shows more detailed information about the received data.

[McLive]

This is the version I use: 2.1.0.201705130723

The item type shouldn't be the problem as setting the state from my sitemap works fine:
```2017-06-03 16:10:39.292 [DEBUG] [ematic.handler.HomematicThingHandler] - Received command 'OFF' for channel 'homematic:GATEWAY-EXTRAS-FE7F373F:fe7f373f:GWE00000000:1#Systemvariable'
2017-06-03 16:10:39.294 [TRACE] [converter.type.AbstractTypeConverter] - Converting type OnOffType with value 'OFF' to BOOL value with OnOffTypeConverter for 'GWE00000000:1#Systemvariable'
2017-06-03 16:10:39.296 [DEBUG] [ommunicator.AbstractHomematicGateway] - Sending variable 'Systemvariable' with value 'false' to gateway with id 'fe7f373f'
2017-06-03 16:10:39.299 [TRACE] [tic.internal.communicator.CcuGateway] - TclRegaScript: Write('\n');
Write('')
object var_obj = dom.GetObject("Systemvariable");
if (var_obj) {
var_obj.State((false));
Write('true');
}
else {
Write('false');
}
Write('');
2017-06-03 16:10:39.338 [TRACE] [tic.internal.communicator.CcuGateway] - Result TclRegaScript:
true

Just getting the state with "REFRESH" doesn't work. 

The log I posted above already was the output after setting the log to trace. :/
```2017-06-03 16:13:13.464 [DEBUG] [ematic.handler.HomematicThingHandler] - Received command 'REFRESH' for channel 'homematic:GATEWAY-EXTRAS-FE7F373F:fe7f373f:GWE00000000:1#Systemvariable'
2017-06-03 16:13:13.478 [DEBUG] [ematic.handler.HomematicThingHandler] - Refreshing GWE00000000:1#Systemvariable
2017-06-03 16:13:13.481 [DEBUG] [ommunicator.AbstractHomematicGateway] - Handling virtual datapoint 'RELOAD_FROM_GATEWAY' on gateway with id 'fe7f373f'
2017-06-03 16:13:13.488 [DEBUG] [ommunicator.AbstractHomematicGateway] - Triggering values reload for device 'GWE00000000'
2017-06-03 16:13:13.498 [DEBUG] [atic.type.HomematicTypeGeneratorImpl] - Generating ThingType for device 'GATEWAY-EXTRAS-FE7F373F' with 15 datapoints
2017-06-03 16:13:13.509 [DEBUG] [ematic.handler.HomematicThingHandler] - Initializing thing 'homematic:GATEWAY-EXTRAS-FE7F373F:fe7f373f:GWE00000000' from gateway 'fe7f373f'
2017-06-03 16:13:13.523 [DEBUG] [ematic.internal.misc.DelayedExecuter] - Delaying event for 2.0 seconds: 'GWE00000000:0#RELOAD_FROM_GATEWAY'
2017-06-03 16:13:15.530 [DEBUG] [ematic.internal.misc.DelayedExecuter] - Executing delayed event for 'GWE00000000:0#RELOAD_FROM_GATEWAY'

No more after that

[McLive]

Does anyone have another idea or needs more logs?

[MHerbst]

I will probably find some time the next days and will try to reproduce and debug it.

But after changing the systemvariable with an homematic programm, the documentation says I have to send an REFRESH command to any variable.

Can you post the rule coding?

[McLive]

I will probably find some time the next days and will try to reproduce and debug it.

Awesome :+1:

Can you post the rule coding?

You mean the homematic program? I'm testing with these two simple programs

[MHerbst]

That's OK. In openHAB you only have the defined a switch and no additional rule coding? I think with these information I can try to create some tests.

[McLive]

Yeah right, just the switch linked to "Systemvariable"

I also have this item:

// Reload Systemvars Switch Reload_Variables {homematic="address=BidCoS-RF, channel=1, parameter=PRESS_SHORT, action=RELOAD_VARIABLES"}

But that's doing nothing

[MHerbst]

But that's doing nothing

This looks like openHAB 1.8 syntax. So it would not work ...

[McLive]

Yeah I also thought that so I tried to send the "REFRESH" command to that switch item linked to the Systemvariable.

[MHerbst]

I am able to reproduce the problem. The value of the variable is only updated if openHAB resp. the Homematic binding is restarted. It seems that the refresh command only tells the CCU to send current channel values. But the variable content has to be fetched by executing a script which seems to be executed only when then binding is initialized.

[McLive]

Good to know I'm not the only one having that problem. Is there a workaround to execute that script manually?

[MHerbst]

I don't think so. I think I can find a solution in the next days.

[McLive]

Ok awesome :)

[DoerrSt]

I just created an easy rule in the rule Editor which triggers the "Reload All From Gateway" button of the homematic-gateway-extras. If the rule starts I see in the logfiles that the devices are reloaded but not the variables.

[MHerbst]

@gerrieg Can you have a look at this problem? I have tried to debug it and found that the reload really does not load the current variable values. CcuGateway.loadVariables is only called when openHAB is started but not called if a reload is executed.
I was able to execute this method by modifying HomematicThingHandler.initialize (I simply added loadHomematicChannelValues(device.getChannel(1)) in line 80. But I did not find out how to set the new values (I ended up with an endless loop ...). Maybe I am totally on the wrong way. Or its a bit more complicated.

[gerrieg]

You have to send a REFRESH command to any variable to reload all variables, see README (Variables out of sync)

[MHerbst]

@gerrieg Tried it, but id does not work and @McLive has the same problem.
I have created a simple rule and tried the refresh again with this command: sendCommand(homematic_GATEWAY_EXTRAS_HM_hm_GWE00000000_1_Systemvariable, RefreshType.REFRESH)

This is the debug output:

2017-06-23 21:01:46.473 [INFO ] [arthome.event.ItemCommandEvent:43   ] - Item 'homematic_GATEWAY_EXTRAS_HM_hm_GWE00000000_1_Systemvariable' received command REFRESH
2017-06-23 21:01:46.473 [DEBUG] [.c.thing.internal.ThingManager:355  ] - Delegating command 'REFRESH' for item 'homematic_GATEWAY_EXTRAS_HM_hm_GWE00000000_1_Systemvariable' to handler for channel 'homematic:GATEWAY-EXTRAS-HM:hm:GWE00000000:1#Systemvariable'
2017-06-23 21:01:46.473 [DEBUG] [.o.b.h.h.HomematicThingHandler:150  ] - Received command 'REFRESH' for channel 'homematic:GATEWAY-EXTRAS-HM:hm:GWE00000000:1#Systemvariable'
2017-06-23 21:01:46.473 [DEBUG] [.o.b.h.h.HomematicThingHandler:156  ] - Refreshing GWE00000000:1#Systemvariable
2017-06-23 21:01:46.473 [DEBUG] [h.i.c.AbstractHomematicGateway:600  ] - Handling virtual datapoint 'RELOAD_FROM_GATEWAY' on gateway with id 'hm'
2017-06-23 21:01:46.473 [DEBUG] [h.i.c.AbstractHomematicGateway:550  ] - Triggering values reload for device 'GWE00000000'
2017-06-23 21:01:46.474 [DEBUG] [.o.b.h.h.HomematicThingHandler:82   ] - Initializing thing 'homematic:GATEWAY-EXTRAS-HM:hm:GWE00000000' from gateway 'hm'
2017-06-23 21:01:46.474 [DEBUG] [h.t.HomematicTypeGeneratorImpl:123  ] - Generating ThingType for device 'GATEWAY-EXTRAS-HM' with 15 datapoints
2017-06-23 21:01:46.474 [DEBUG] [o.o.b.h.i.misc.DelayedExecuter:38   ] - Delaying event for 2.0 seconds: 'GWE00000000:0#RELOAD_FROM_GATEWAY'
2017-06-23 21:01:46.632 [DEBUG] [.c.c.r.AbstractManagedProvider:135  ] - Updated element homematic:GATEWAY-EXTRAS-HM:hm:GWE00000000 in ManagedThingProvider.
2017-06-23 21:01:46.633 [INFO ] [rthome.event.ThingUpdatedEvent:43   ] - Thing 'homematic:GATEWAY-EXTRAS-HM:hm:GWE00000000' has been updated.
2017-06-23 21:01:48.474 [DEBUG] [o.o.b.h.i.misc.DelayedExecuter:50   ] - Executing delayed event for 'GWE00000000:0#RELOAD_FROM_GATEWAY'

As you can see no value was updated. I set a breakpoint in method CcuGateway.loadVariables and this method is only executed once when the binding is initialized.

[gerrieg]

Thank you for the info, i thought i've already implemented this feature but it's not there. Maybe i forgot to commit my changes 😕
OK, will do it ... again.

[gerrieg]

found the code, i moved it to another class some times ago 😊 Will try to fix it in the next days.

[MHerbst]

While stepping through the code I already thought that the problem has crept in because of reorganizing the code. Therefore I thought it would be better to leave the problem solution to you :-)

[gerrieg]

fixed with #2419

[McLive]

Finally I found some time to test this with the newest snapshot build.
But somehow with version 2.2.0, my homematic things stopped working and all are "UNINITIALIZED".

Any idea why this happens? 2.1.0 was working...

Startup log:
2017-11-22 20:01:05.406 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sprinkler.items' 2017-11-22 20:01:06.322 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist' 2017-11-22 20:01:12.747 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sprinkler.rules' 2017-11-22 20:01:18.287 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.sitemap' 2017-11-22 20:01:18.591 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.sitemap' 2017-11-22 20:01:18.630 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'aussenbereich.sitemap' 2017-11-22 20:01:25.322 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start 2017-11-22 20:01:29.523 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app 2017-11-22 20:01:30.249 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui 2017-11-22 20:01:30.967 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel 2017-11-22 20:01:50.072 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate command 'OFF' for item 'Irrigation_2' to handler for channel 'homematic:HM-LC-Sw4-DR:fe7f373f:LEQ0900848:1#STATE', because no handler is assigned. Maybe the binding is not installed or not propertly initialized. 2017-11-22 20:01:50.094 [INFO ] [se.smarthome.model.script.Irrigation] - System started, Turning off all Irrigations 2017-11-22 20:01:50.198 [INFO ] [se.smarthome.model.script.Irrigation] - System started, Turning off all Irrigations 2017-11-22 20:01:50.208 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate command 'OFF' for item 'Irrigation_1' to handler for channel 'homematic:HM-LC-Sw4-DR:fe7f373f:LEQ0900848:2#STATE', because no handler is assigned. Maybe the binding is not installed or not propertly initialized. 2017-11-22 20:01:50.220 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'OFF' for item 'Irrigation_2' to handler for channel 'homematic:HM-LC-Sw4-DR:fe7f373f:LEQ0900848:1#STATE', because no handler is assigned. Maybe the binding is not installed or not propertly initialized. 2017-11-22 20:01:50.231 [INFO ] [se.smarthome.model.script.Irrigation] - System started, Turning off all Irrigations 2017-11-22 20:01:50.266 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate command 'OFF' for item 'Irrigation_4' to handler for channel 'homematic:HM-LC-Sw4-DR:fe7f373f:LEQ0900848:4#STATE', because no handler is assigned. Maybe the binding is not installed or not propertly initialized. 2017-11-22 20:01:50.362 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'OFF' for item 'Irrigation_4' to handler for channel 'homematic:HM-LC-Sw4-DR:fe7f373f:LEQ0900848:4#STATE', because no handler is assigned. Maybe the binding is not installed or not propertly initialized. 2017-11-22 20:01:50.365 [INFO ] [se.smarthome.model.script.Irrigation] - System started, Turning off all Irrigations 2017-11-22 20:01:50.453 [INFO ] [se.smarthome.model.script.Irrigation] - System started, Turning off all Irrigations 2017-11-22 20:01:50.502 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'OFF' for item 'Irrigation_1' to handler for channel 'homematic:HM-LC-Sw4-DR:fe7f373f:LEQ0900848:2#STATE', because no handler is assigned. Maybe the binding is not installed or not propertly initialized. 2017-11-22 20:01:50.534 [INFO ] [se.smarthome.model.script.Irrigation] - System started, Turning off all Irrigations 2017-11-22 20:01:50.713 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate command 'OFF' for item 'Irrigation_3' to handler for channel 'homematic:HM-LC-Sw4-DR:fe7f373f:LEQ0900848:3#STATE', because no handler is assigned. Maybe the binding is not installed or not propertly initialized. 2017-11-22 20:01:50.730 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate command 'OFF' for item 'Irrigation_6' to handler for channel 'homematic:HM-LC-Sw4-DR:fe7f373f:LEQ0901275:2#STATE', because no handler is assigned. Maybe the binding is not installed or not propertly initialized. 2017-11-22 20:01:50.816 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate command 'OFF' for item 'Irrigation_5' to handler for channel 'homematic:HM-LC-Sw4-DR:fe7f373f:LEQ0901275:1#STATE', because no handler is assigned. Maybe the binding is not installed or not propertly initialized. 2017-11-22 20:01:51.083 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'OFF' for item 'Irrigation_3' to handler for channel 'homematic:HM-LC-Sw4-DR:fe7f373f:LEQ0900848:3#STATE', because no handler is assigned. Maybe the binding is not installed or not propertly initialized. 2017-11-22 20:01:51.517 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'OFF' for item 'Irrigation_6' to handler for channel 'homematic:HM-LC-Sw4-DR:fe7f373f:LEQ0901275:2#STATE', because no handler is assigned. Maybe the binding is not installed or not propertly initialized. 2017-11-22 20:01:51.535 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update 'OFF' for item 'Irrigation_5' to handler for channel 'homematic:HM-LC-Sw4-DR:fe7f373f:LEQ0901275:1#STATE', because no handler is assigned. Maybe the binding is not installed or not propertly initialized. 2017-11-22 20:01:51.796 [DEBUG] [org.openhab.binding.homematic ] - BundleEvent STARTING - org.openhab.binding.homematic 2017-11-22 20:01:51.969 [DEBUG] [org.openhab.binding.homematic ] - ServiceEvent REGISTERED - {org.openhab.binding.homematic.internal.type.HomematicThingTypeProvider, org.eclipse.smarthome.core.thing.binding.ThingTypeProvider}={component.name=org.openhab.binding.homematic.internal.type.HomematicThingTypeProviderImpl, component.id=165, service.id=295, service.bundleid=195, service.scope=bundle} - org.openhab.binding.homematic 2017-11-22 20:01:51.993 [DEBUG] [org.openhab.binding.homematic ] - ServiceEvent REGISTERED - {org.openhab.binding.homematic.internal.type.HomematicChannelTypeProvider, org.eclipse.smarthome.core.thing.type.ChannelTypeProvider}={component.name=org.openhab.binding.homematic.internal.type.HomematicChannelTypeProviderImpl, component.id=166, service.id=296, service.bundleid=195, service.scope=bundle} - org.openhab.binding.homematic 2017-11-22 20:01:52.029 [DEBUG] [org.openhab.binding.homematic ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.UpnpDiscoveryParticipant}={component.name=org.openhab.binding.homematic.internal.discovery.HomegearDiscoveryParticipant, component.id=168, service.id=297, service.bundleid=195, service.scope=bundle} - org.openhab.binding.homematic 2017-11-22 20:01:52.110 [DEBUG] [org.openhab.binding.homematic ] - ServiceEvent REGISTERED - {org.openhab.binding.homematic.internal.type.HomematicConfigDescriptionProvider, org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={component.name=org.openhab.binding.homematic.internal.type.HomematicConfigDescriptionProviderImpl, component.id=169, service.id=299, service.bundleid=195, service.scope=bundle} - org.openhab.binding.homematic 2017-11-22 20:01:52.138 [DEBUG] [org.openhab.binding.homematic ] - ServiceEvent REGISTERED - {org.openhab.binding.homematic.internal.type.HomematicTypeGenerator}={component.name=org.openhab.binding.homematic.internal.type.HomematicTypeGeneratorImpl, component.id=167, service.id=300, service.bundleid=195, service.scope=bundle} - org.openhab.binding.homematic 2017-11-22 20:01:52.493 [DEBUG] [org.openhab.binding.homematic ] - BundleEvent STARTED - org.openhab.binding.homematic 2017-11-22 20:01:54.808 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Starting and scheduling weatherJob with interval of 5 minutes`

Looks like it doesn't even start to me :/

[MHerbst]

There are some problems in the openHAB snapshots builds #1083 and higher. So maybe your problems are also caused by these problems. You could try the latest build #1098 (or higher).

[McLive]

Just wondering where I can find older snapshot builds. Jenkins doesn't have some for #1082 for example.