Homematic binding not receiving updates

I know there have been a few threads on this, so in some sense this is a repeat. However, I also see all of those closed as resolved, I’ve just upgraded to 3.3 and have the problem still.

I’ve had this problem on and off for some time (refer ), but at that time believed it to be network related. I’ve now a) got a stable network, and b) have diagnostics that show it’s not network related.

I have 3 Raspberry PIs, one is my Openhab, and two are CCUs (one has Homegear only, one has Homegear + piVCCU, with HMIP devices connected to the piVCCU). My equipment is mostly Max radiator valves and thermostats, with a single HMIP radiator valve, and a single HMIP thermostat.

I have only just entered heating season again here in NZ, so the problem could have started happening more frequently any time over the summer (in the last 6 months), but realistically I suspect is related to the introduction of the piVCCU somehow. Having said that, it could equally be a version upgrade on any of the software.

The symptoms are that I restart my openhab, and I am receiving updates from the homematic equipment. After some (quite short) period of time, I stop receiving updates on some equipment. Which equipment seems random, but in recent days predominately equipment connected to the pi that runs only homegear.

Today I pushed the binding into TRACE mode. I have a full log from restarting the binding, but I don’t believe it shows a lot of interesting things - I can share if it’s needed. The relevant sections show:

  1. On the homegear log - the radiator valve moving to 0% open
  2. On the openhab side - the homematic binding receiving the message from homegear including the radiator valve change

What I can’t show via the logs (but can see in the UI) is that the valve state did not actually change at all - it remained as it was prior to the update.

I then stopped and started the bridge that connects to that homegear via the openhab UI. The valve state immediately updated to the correct value of zero.

The logs don’t show all of this - it’s the logs combined with seeing the UI. And there are no errors that look relevant in the log at that point in time - it seems to be just silently failing.

Logs are attached from homegear and from openhab, both truncated to a limited set of lines to make finding things easier. The valve id is MEQ1344574, the relevant message comes in at 19:05:05.
trunc_openhab.log (12.3 KB)
short_homegear.log (10.1 KB)

What other information or diagnostics can I provide? Are there things in core openhab that could stop the item from being updated? The item itself is defined in a standard way:

Number ExhibitionValve "Exhibition Valve [%d %%]" (valveExhibition, DeviceValves) { channel="homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1344574:1#VALVE_STATE" }

Hi Paul,

the openhab.log contains several messages about connection problems to port 2001 while using BinRpcMessage:

2022-05-29 19:05:23.146 [DEBUG] [nal.communicator.client.BinRpcClient] - BinRpcMessage socket failure, sending message again 3/3

BinRpcMessage is only used for the communication with Homegear. This means OH has got a problem with the connection to Homegear. Maybe this is caused because piVCCU and Homegear are running on the same machine. If both are trying to listen on port 2001 this will cause problems.

Thanks Martin.

I’m not sure the piVCCU would cause that problem, for two reasons:

  1. The Homegear and piVCCU are on different IP addresses, as the piVCCU runs in a container (lxc). It’s on IP 192.168.1.99, where the core pi that service runs on is on 192.168.1.17 (wlan) or 192.168.1.96 (wired). It’s definitely a funky setup due to the installation of piVCCU, which required a wired connection it didn’t used to have, but I don’t see anything obviously that would cause the two ports to conflict

  2. The device that is giving the difficulty is not connected to that homegear instance, they’re connected to the other pi, which only runs Homegear (no piVCCU), and only has a wlan, so only 1 IP address.

However, as you say, there is definitely an error in the log. The address “VBC7844222” in the log looks to correspond to the homegear instance on the pi that has the CCU also on it. It reports connecting via 192.168.1.99, so the wired connection.

I did wire that ethernet myself, so I guess it’s plausible the wired connection itself is flaky. But the syslog on the pi doesn’t report any networking errors, just regular DHCP every couple of hours for both the wlan and the wired connection.

Is there anything else that could cause the socket failures? I could force to the IP address of the wlan instead. (It does make me wonder whether homegear would listen on both wlan and wired…I assume it must, as I didn’t configure otherwise, I expected it would be on the wlan as it was running for a couple years before I added the wired connection).

I agree with you that the cause of the configuration error is not the port usage.

Here are a few possible causes I can think of:

  • firewall configuration: is ist possible the the port is blocked somewhere?
  • container configuration: if a “CCU” is running in a container you must make sure that the ports are correctly mapped. I remember some problems with docker containers.
  • WLAN on Raspberry: I had lots of problems with the Raspberry Wifi. It was quite unstable and as far as I remember I event had problems with the statically defined IP address. Therefore my CCU Raspi (with Raspberrymatic) and the OH Raspi are connected via cable.

The whole connection handling in OH was modified for OH 3.1 and again for 3.2. I don’t know whether anybody has used it with Homegear (HG ist the only “CCU” that needs BinRPC protocol). Therefore, I cannot completely rule out the possibility that the cause is in the add-on itself.

I suspect that error message is a red herring - it’s not on the device we’re looking at. I’ve changed from the wired IP address to the wlan IP address, and haven’t seen it recur since, so I suspect it was some sort of glitch on the wired lan. Which is weird. But I’m not convinced it’s relevant. I did have some other configuration issues on the new HMIP device - the valve state has moved to being called LEVEL, and is now a dimmer rather than a number. I fixed that as well.

Ignoring all that, I’ve completed a more thorough diagnostic run this morning. In short I think it’s clear that my items are only updating with the changed value upon a restart of the openhab, or of the binding, or of the bridge, or of the specific thing.

I have a complete log from openhab restart through to turning off the TRACE (but it’s large).

The steps here are:

  1. Restart openhab

  2. 12:11PM Stop the binding, turn on trace, start the binding (as per debugging and tracing here: openhab-addons/bundles/org.openhab.binding.homematic at main · openhab/openhab-addons · GitHub)

  3. Screenshot the state of the “Setpoint” variable at 12:11pm:

  4. Change the temperature manually on the device MEQ1354719. Change it to 22 degrees

  5. At 12:14:34 in the log, you can see the setpoint update to 22 degrees in the log for MEQ1354719

  6. At 12:15:20 screenshot, the value is not updated in the linked setpoint field:

  7. Stop and start the bridge using the UI circa 12:1548

  8. 12:16:10 the UI is updated (post bridge restart)

I then completed a similar series of steps, but only restarting the individual radiator thing, rather than the whole bridge, with the same result.

  1. 12:17:00 change setpoint manually on the device to 18.5 degrees

  2. In log at 12:18:52 the change is visible

  3. Screenshot 12:19:30 - no update yet:

  4. 12:19:50 Stop and start the thing manually (visible in log)

  5. Screenshot - data now updated

Now, this is a very large log with lots of things that look interesting to me…but I really don’t know what I’m looking for. I don’t see any obvious errors or gotchas around the time that the updates come through, and I can see it claiming to update the channel (for example at 12:19:53.028). Honestly it looks to me like the update posted from the add-on to openhab, and then openhab for some reason decided to ignore it. But I don’t know enough about the architecture.

Any suggestions for further diagnostics?

Thanks,
openhab.log.gz.txt (292.4 KB)

As an interim, I’ve created the following workaround. Posting here because I’ve seen a few people with similar problems (often for different reasons), and they might be interested in a workaround whilst they work through the issues.

rule "Cycle valve things every 15 minutes to grab updates"
when 
  Time cron "47 */13 * * * ?" 
then
  if ( swInitialisationDone.state == NULL || swInitialisationDone.state != ON ){
    logInfo( 'devices', 'Not running valve cycle - initialisation not done')
  } else {
    logInfo( 'devices', "Cycling all devices - this should be removed when binding is fixed")
    val thingList = newArrayList(
      'homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1344264',  // Boot
      'homematic:HG-BC-RT-TRX-CyG-3:4BCAAC30-44F5-BBDE-DF54-27D1B87DCE09:MEQ1344704',  // Caity
      'homematic:HG-BC-RT-TRX-CyG-3:4BCAAC30-44F5-BBDE-DF54-27D1B87DCE09:LEQ1131072',  // DayBed
      'homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354719',  // Dining
      'homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354716',  // Dog
      'homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1344574',  // Exhibition
      'homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1344632',  // Jess
      'homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1344573',  // Kitchen
      'homematic:HG-BC-RT-TRX-CyG-3:4BCAAC30-44F5-BBDE-DF54-27D1B87DCE09:MEQ1354634',  // Loggia
      'homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354474',  // Lounge
      'homematic:HmIP-eTRV-2:3014F711A000041D89B5530C:000A1D89A6A4E5', // Master Window
      'homematic:HG-BC-RT-TRX-CyG-3:4BCAAC30-44F5-BBDE-DF54-27D1B87DCE09:MEQ1354628',  // Study
      'homematic:HG-BC-TC-C-WM-4:F6B89899-2A5B-533A-A2EC-A308C51F07EF:MEQ0856945',  // Wall Lounge
      'homematic:HmIP-WTH-2:3014F711A000041D89B5530C:000A9D89B934FB'   // Wall Master
    )
    
    thingList.forEach[ thing | 
        var String url = "http://<username>:<password>@raspberrypi2:8080/rest/things/" + thing + '/enable'
        logInfo( ' devices', url )
        sendHttpPutRequest(url, "text/plain", "false" )    // disable
        Thread::sleep(1000)
        sendHttpPutRequest(url, "text/plain", "true" )     // enable
      ]
  }  
end

Ignoring all that, I’ve completed a more thorough diagnostic run this morning. In short I think it’s clear that my items are only updating with the changed value upon a restart of the openhab, or of the binding, or of the bridge, or of the specific thing.

If openHAB does not get events from a CCU (or Homegear) than the first thing would be to check the firewall settings. All ports configured as xmlCallbackPort resp. binCallPort (for Homegear) must be open.

I have seen from the log that you have configured three gateways:

2022-05-30 12:11:06.475 [DEBUG] [ernal.handler.HomematicBridgeHandler] - HomematicConfig[gatewayAddress=192.168.1.13,callbackHost=192.168.1.15,xmlCallbackPort=9125,binCallbackPort=9126,gatewayType=auto,rfPort=2001,wiredPort=2000,hmIpPort=2010,cuxdPort=8701,groupPort=9292,timeout=15,discoveryTimeToLive=-1,installModeDuration=60,socketMaxAlive=900]
2022-05-30 12:11:06.479 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 2001):
<?xml version="1.0" encoding="ISO-8859-1"?>
<methodCall><methodName>getDeviceDescription</methodName>
<params><param><value>BidCoS-RF</value></param></params></methodCall>
2022-05-30 12:11:06.499 [DEBUG] [ernal.handler.HomematicBridgeHandler] - HomematicConfig[gatewayAddress=192.168.1.96,callbackHost=192.168.1.15,xmlCallbackPort=9127,binCallbackPort=9128,gatewayType=auto,rfPort=2001,wiredPort=2000,hmIpPort=2010,cuxdPort=8701,groupPort=9292,timeout=15,discoveryTimeToLive=-1,installModeDuration=60,socketMaxAlive=900]
2022-05-30 12:11:06.501 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 2001):
<?xml version="1.0" encoding="ISO-8859-1"?>
<methodCall><methodName>getDeviceDescription</methodName>
<params><param><value>BidCoS-RF</value></param></params></methodCall>
2022-05-30 12:11:06.546 [DEBUG] [ernal.handler.HomematicBridgeHandler] - HomematicConfig[gatewayAddress=192.168.1.99,callbackHost=192.168.1.15,xmlCallbackPort=9129,binCallbackPort=9130,gatewayType=auto,rfPort=2001,wiredPort=2000,hmIpPort=2010,cuxdPort=8701,groupPort=9292,timeout=15,discoveryTimeToLive=-1,installModeDuration=60,socketMaxAlive=900]

Please make sure that the Gateway, where the HmIP devices are configured, uses the correct port to send update events to openHAB.

But openHAB is getting the events, I can see them arriving in the openHAB log. The updates aren’t, however, arriving on the UI unless I stop and start the thing, presumably because it isn’t updating the channel.

For example:

2022-05-30 12:14:34.102 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Double) value '19.0' for 'MEQ0856945:1#SET_TEMPERATURE' from gateway with id 'F6B89899-2A5B-533A-A2EC-A308C51F07EF'
.......
                methodName=event
                params=
                [
                        45bd3a92-d909-4ae2-b810-64a1df03cbca
                        MEQ1354719:1
                        SET_TEMPERATURE
                        22.0
                ]
......
2022-05-30 12:14:34.170 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Double) value '22.0' for 'MEQ1354719:1#SET_TEMPERATURE' from gateway with id 'F6B89899-2A5B-533A-A2EC-A308C51F07EF'

So my question is why it’s not updating into the UI / the linked field from which all my rules run. The add-on log shows the value arriving (in both instances - at 12:14:34 and again at 12:18:52), but it doesn’t update into openHAB itself.

Interestingly, looking at it again this morning to extract for this comment, it isn’t actually updating the channel, it’s just arriving and then nothing happens. With the second log entry at 12:18:52 you can see it didn’t update the channel until I disabled and reenabled the thing:

                methodName=event
                params=
                [
                        5535563e-0087-4dc9-94bd-968a4335c72b
                        MEQ1354719:1
                        SET_TEMPERATURE
                        18.5
                ]
....
2022-05-30 12:18:52.502 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Double) value '18.5' for 'MEQ1354719:1#SET_TEMPERATURE' from gateway with id 'F6B89899-2A5B-533A-A2EC-A308C51F07EF'
....
2022-05-30 12:19:52.956 [DEBUG] [ternal.handler.HomematicThingHandler] - Initializing thing 'homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354719' from gateway 'F6B89899-2A5B-533A-A2EC-A308C51F07EF'
....
2022-05-30 12:19:53.028 [DEBUG] [ternal.handler.HomematicThingHandler] - Updating channel 'homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354719:1#SET_TEMPERATURE' from thing id 'MEQ1354719'
2022-05-30 12:19:53.030 [DEBUG] [converter.type.AbstractTypeConverter] - Converting datapoint 'MEQ1354719:1#SET_TEMPERATURE' (dpType='FLOAT', dpUnit='°C', dpValue='18.5') with QuantityTypeConverter

Is there some state or other behaviour that could cause it to receive the updates but to not update the channel?

In terms of ports and firewalls.

  1. The data is arriving as a push from the Homegear, so it must be connecting to the correct port at the openHAB end
  2. OpenHAB is able to obtain the data when I stop and start the thing, so it must be able to connect to Homegear and Homegear must be listening on the correct port
  3. I have no internal firewalls and everything is on the same network (no transits other than from wifi to wired)
  4. The Homegear it’s communicating with has nothing else of note running on it - no piVCCU or other function

I guess it’s possible that the piVCCU on the second raspberry pi is somehow causing a state problem. I don’t see anything in the logs that indicate that, and when I use my workaround script all the data arrives for every device - so all the connectivity must be in place. I also believe I had a similar problem prior to installing the piVCCU - I’ve always had “stuck” devices but have never been able to recreate. It is now reliably stuck most of the time - but it feels like that’s just a more frequent occurrence of a behaviour I’ve had for a while.

Arguably I’m no longer seeing any pro-active updates at all any more - I’m only getting updates when I stop and start the thing. So perhaps there’s something systemically misconfigured or broken that only stops the pub/sub from working. But that seems weird when I can actually see the data in the openHAB log - so it’s arriving but not being processed.

Sorry, there was a misunderstanding on my side.

How did you define things and items? In Main UI or as text files?
If you are using textual definitions, please post thing and item definitions. Maybe the channels are not correctly connected to their items.

If you are using text files you could try to define an additional item in Main UI and test whether this item is updated correctly.

The things are via the main ui. The items are via a text file, this specific item is defined as follows:

/* Dining */
Group valveDining "Dining" <none> (zoneDevicesLiving, Devices, DevicesValves)
Number DiningSetpoint "Dining Current Setpoint [%.1f °C]" <temperature> (valveDining, DeviceSetpoints, InitSetpoints)  { channel="homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354719:1#SET_TEMPERATURE" }
Switch DiningBattery "Dining Battery" <battery> (valveDining, DeviceBatteries) { channel="homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354719:0#LOWBAT" }
Number DiningTemp "Dining Temp [%.1f °C]" <temperature> (valveDining, DeviceTemps) { channel="homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354719:1#ACTUAL_TEMPERATURE" }
Number DiningValve "Dining Valve [%d %%]" (valveDining, DeviceValves) { channel="homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354719:1#VALVE_STATE" }
Number DiningSignalStrength "Dining Signal Strength [%d]" <signal> (valveDining, DeviceSignalStrength) { channel="homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354719:0#SIGNAL_STRENGTH" }
Number DiningDecalTime "Dining Decalcification Time [%d]" <clock> (valveDining, DeviceDecalTime) { channel="homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354719:1#DECALCIFICATION_TIME" }
Number DiningDecalWeekday "Dining Decalcification Day [%d]" <clock> (valveDining, DeviceDecalWeekday) { channel="homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354719:1#DECALCIFICATION_WEEKDAY" }
Switch DiningOn "Dining On" (valveDining, DeviceOn, Switches, InitSwitchesOn)
Number DiningValveAdjustor "Dining Room Valve Adjustor [%d %%]" (valveDining, DeviceValveAdjustors) 
Number DiningAdjustedValve "Dining Room Adjusted Valve [%d %%]" (valveDining, DeviceAdjustedValves) 

I presume this config is working for two reasons:

  1. When I restart the thing the data flows through to the item (so it must be connected)
  2. In the main UI, it shows the thing as being correctly connected:

I’m going to be out of town for a couple of days, and can try defining a new item via the UI then, but I don’t see why that would make a difference given those points.

Are you absolutely sure about the channel UID? Did you copy that from the UI or did you create the Items via VSCode by using auto create feature from openHAB plugin?

Please be aware that the Item type (at least for tempoerature) should be Number:temperature, not Number

Thanks Udo.

I copied from the UI, it works when I stop/start the thing, and it shows in the UI as being linked. I think it is correctly linked for those reasons.

What difference would it give if I define as Number:temperature? The other fields (such as the valve state) also have the same problem, so I presume this isn’t the problem, but I could be wrong.

Overall, my suspicion is that there’s something going wrong in the internals. I can see the data flowing through in the log “Receiving new value”, but not updating in the UI. Then after a disable/enable on the individual thing, I can see it updating the channel, and it appears in the UI “Updating channel” and “Converting datapoint”.

From this I would conclude that:

  1. The item must be correctly linked. If it was incorrectly linked it would never update, rather than updating only after a disable/enable on the thing

  2. It probably isn’t any sort of networking issue, as the data is actually arriving and reported as such in the log.

I’ll grant that perhaps the item is somehow incorrectly linked such that it only works after a disable/enable. I’m not aware of what would be wrong to cause that, but it’s possible. I’m not sure how I’d diagnose that though, so open to any ideas on tests or configuration I could try.

I’ll also grant that the networking could be an issue if the design is such that it receives data, but needs some sort of acknowledgement before it processes the data. If that’s the case, then perhaps that acknowledgement is failing, but not writing any information about that failure in the log. If that’s a possibility, then I’m happy to look at the networking - again, I’m interested in what diagnostic steps or configuration I’d try so as to resolve that.

Beyond that, it really looks to me like some sort of stall in the processing. So it’s received the update, but perhaps it’s putting it in a queue that’s getting stuck, or it’s waiting for some other event or timer that’s never happening. But I know nothing about the internals to know what has to happen to move from “data was received” (in the log) to “channel was updated”.

2022-05-30 12:18:52.502 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Double) value '18.5' for 'MEQ1354719:1#SET_TEMPERATURE' from gateway with id 'F6B89899-2A5B-533A-A2EC-A308C51F07EF'
....
2022-05-30 12:19:52.956 [DEBUG] [ternal.handler.HomematicThingHandler] - Initializing thing 'homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354719' from gateway 'F6B89899-2A5B-533A-A2EC-A308C51F07EF'
....
2022-05-30 12:19:53.028 [DEBUG] [ternal.handler.HomematicThingHandler] - Updating channel 'homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354719:1#SET_TEMPERATURE' from thing id 'MEQ1354719'
2022-05-30 12:19:53.030 [DEBUG] [converter.type.AbstractTypeConverter] - Converting datapoint 'MEQ1354719:1#SET_TEMPERATURE' (dpType='FLOAT', dpUnit='°C', dpValue='18.5') with QuantityTypeConverter

I can remember that there was a problem if it is not defined as Number:temperature. Therefore it is generally better to set it.
Regarding the VALVE_STATE, it seems that it is not Number but a String (I have a similar device and the channel is defined as String). Please check the definition in Main UI (it may be different for your device). This could explain why this item is also not updated.

I agree with you that it can be an internal problem. Your installation contain three bridges and in addition one of them uses BinRPC protocol. There can be a problems with the “event routing” and the event received from the CCU is not correctly routed to the correct Thing/Channel.

I can also remember an internal problem in OH were some wrong definitions were store in the OH configuration files (JSONDB). Everything looked fine in Main UI but items were not updated.

I have to look into the code of the binding. Maybe I can see a possible reason or have which additional traces could help.

Thanks very much Martin.

I’ll check when I’m home, but my recollection is that the HMIP devices have VALVE_STATE as a string, and you need to use LEVEL instead (which is a dimmer). So I think I’ve checked that already, I’ll recheck tonight.

On the number:temperature, I’ll make that change. I’ve had this installation since openhab 1, and that isn’t a change that I’d had to make when I moved to OH2 or to OH3, and it definitely worked for a while. But no harm in changing it. Are there any of the other data types that may be problematic? Is there a place I can get a list of them…or do I perhaps just have to match exactly the data type that the UI reports for each field?

I can see that the two temperatures (setpoint and actual) are defined as Number:Temperature. The valve state is a dimensionless number - I’m assuming I don’t need to specify it as Dimensionless in the config?

OK, I’ve spent the time to rework everything to use Number:Temperature, and therefore all rules to use QuantityType for working variables, and then some of the tricks and tips from this thread: Working with Number:Temperature Items in rules. This was all substantially harder than I imagined, so posting the link and detail for others who may find this thread and need to do the same thing.

Having done that, I’m still seeing a number of devices not updating. Interestingly, at the moment all the devices that are not updating are connected to one Homegear instance - the one that doesn’t have the piVCCU on it. I’m not sure if that’s coincidence that one is working and one not, or whether actually the thermostats with problems have always been the ones on that same device. I think I recall having problems with thermostats on the other Homegear, but I will monitor to understand.

I will now do some more diagnosis, and potentially run a reboot cycle on everything once I’m certain it’s stable from the data type changes.

And, final update, because I’m a bit stumped. I ran a full reboot cycle. One of the bridges the updates flow automatically - I have logs that show:

  1. Change the thermostat setting manually on the thermostat
  2. Data arrives via the bridge, visible in the openhab log
  3. Data updated to the channel, and to the associated items

This all flows automatically.

Devices on the other bridge:

  1. Change thermostat setting manually on the thermostat
  2. Data arrives via the bridge, visible in the log
  3. Data never updates to the channel, no errors or other information logged
  4. Disable then enable the thing
  5. Data updated to the channel, log entries very similar to the log entries for point 3 above

I see no differences in the bridge configuration. The physical devices are the same model. The configuration of items etc appears the same (and all this configuration was originally done by copy and paste).

Things I might surmise:

  1. It appears to be all items connected to one particular bridge. Therefore it’s unlikely to be item configuration or channel configuration or thing configuration - if so then I’d expect one or two individual items or channels to not work, not all the channels on a single bridge
  2. The item and thing configuration must be mostly right, because the disable/enable cycle leads to the data flowing. If the UID or channel name or other setting was wrong, then it would never work rather than only working sometimes
  3. It feels like it’s unlikely to be a state issue on the bridge. Because I rebooted and one bridge is working, the other isn’t, that doesn’t seem like a transient state issue. I’m less confident on this though - it could be something about that bridge that consistently drives it into some erroneous state
  4. It’s unlikely to be Homegear configuration, both because one works and one doesn’t, and because the data is actually flowing to Openhab and is visible in the trace log. So it needs to be some interaction at the Openhab end (although I’m not ruling out something in the Homegear configuration or state that leads to a problem at the Openhab end).

My best guess is that there’s something (configuration, timing, settings) that is triggering an error in Openhab. The code may be silently failing, or perhaps is going down an unexpected branch condition that results in the data not being processed.

Looking closely at the log files, for the valve that works, the log looks like this:

2022-06-02 16:54:50.472 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Double) value '23.0' for 'LEQ1131072:1#ACTUAL_TEMPERATURE' from gateway with id '4BCAAC30-44F5-BBDE-
DF54-27D1B87DCE09'
2022-06-02 16:54:50.477 [DEBUG] [converter.type.AbstractTypeConverter] - Converting datapoint 'LEQ1131072:1#ACTUAL_TEMPERATURE' (dpType='FLOAT', dpUnit='°C', dpValue='23.0') with Quantity
TypeConverter
2022-06-02 16:54:50.488 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Integer) value '1' for 'LEQ1131072:1#CONTROL_MODE' from gateway with id '4BCAAC30-44F5-BBDE-DF54-27D
1B87DCE09'
2022-06-02 16:54:50.494 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Boolean) value 'false' for 'LEQ1131072:1#LOCKED' from gateway with id '4BCAAC30-44F5-BBDE-DF54-27D1B
87DCE09'
2022-06-02 16:54:50.499 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Double) value '19.0' for 'LEQ1131072:1#SET_TEMPERATURE' from gateway with id '4BCAAC30-44F5-BBDE-DF5
4-27D1B87DCE09'
2022-06-02 16:54:50.504 [DEBUG] [converter.type.AbstractTypeConverter] - Converting datapoint 'LEQ1131072:1#SET_TEMPERATURE' (dpType='FLOAT', dpUnit='°C', dpValue='19.0') with QuantityTyp
eConverter
2022-06-02 16:54:50.515 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Integer) value '0' for 'LEQ1131072:1#VALVE_STATE' from gateway with id '4BCAAC30-44F5-BBDE-DF54-27D1
B87DCE09'
2022-06-02 16:54:50.518 [DEBUG] [converter.type.AbstractTypeConverter] - Converting datapoint 'LEQ1131072:1#VALVE_STATE' (dpType='INTEGER', dpUnit='%', dpValue='0') with QuantityTypeConve
rter

The valve that doesn’t work, the log looks like this:

2022-05-30 12:18:52.496 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Double) value '20.4' for 'MEQ1354719:1#ACTUAL_TEMPERATURE' from gateway with id 'F6B89899-2A5B-533A-A2EC-A308C51F07EF'
2022-05-30 12:18:52.498 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Integer) value '1' for 'MEQ1354719:1#CONTROL_MODE' from gateway with id 'F6B89899-2A5B-533A-A2EC-A308C51F07EF'
2022-05-30 12:18:52.500 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Boolean) value 'false' for 'MEQ1354719:1#LOCKED' from gateway with id 'F6B89899-2A5B-533A-A2EC-A308C51F07EF'
2022-05-30 12:18:52.502 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Double) value '18.5' for 'MEQ1354719:1#SET_TEMPERATURE' from gateway with id 'F6B89899-2A5B-533A-A2EC-A308C51F07EF'
2022-05-30 12:18:52.504 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Integer) value '30' for 'MEQ1354719:1#VALVE_STATE' from gateway with id 'F6B89899-2A5B-533A-A2EC-A308C51F07EF'

The difference seems to be that it’s not invoking the “converting datapoint” pathway. And the associated logic seems to be in or driven from the AbstractHomematicGateway, and an earlier log entry indicates we’re in the BinRpcMessage logic.

Looking in the AbstractHomeGateway.java at line 738 I see what could be relevant. There’s an

if (initialised){

that looks to be the only non-trivial branch condition prior to processing. In a perfect world I think we’d have

else { 
  logger.debug("Not initialized therefore not processing'", dpInfo);
}

I can also see:

} catch (HomematicClientException | IOException ex) {
    // ignore
}

Again, in a perfect world we’d have:

} catch (HomematicClientException | IOException ex) {
    logger.debug("IOException silently suppressed'", ex);
}

I don’t have a development environment, nor the skills, to make and test the changes unfortunately, but I think this could take us some way towards understanding what’s happening.

If it’s the initialised status that’s the cause of the problem, then presumably if I disable and enable the thing I should see initialisation messages, and potentially an error that tells me it’s not getting initialised.

In the log I see:

2022-06-02 18:04:46.470 [DEBUG] [ommunicator.AbstractHomematicGateway] - Loading values for channel HmChannel[number=4,initialized=false] of device 'MEQ1354719'

but I believe that to be an initialised status on the channel, not on the gateway as a whole - and I believe the check at line 738 is checking initialised status on the gateway.

When I restart the gateway it is clearly in the loadAllDeviceMetadata method, as I see log entries such as Loading metadata for device (line 385) and Loading channel (line 392). Again, there is no trace logging that tells us we reached the end and set the initialised status. It would be nice to add or around line 431:

        }
        initialized = true;
        logger.debug("Gateway initialization completed for gateway '{}'", id);
    }

That’s probably as far as I can go without a dev environment or the ability to run a debugger - but those extra trace statements would potentially give us the smoking gun as to what’s going on (and assist debugging in the future if other people have similar issues).

OK, a bit of a learning curve, but I have a dev environment running and am able to make code changes to debug what’s happening. And after tracing all the way through, I can see that:

  1. The gateway is initialised, and is processing the update
  2. It is calling dp.setValue at line 740-ish in AbstractHomematicGateway.java
  3. It is correctly getting to handleVirtualDatapointEvent, and the conversion (and presumably datapoint update) happens before then
  4. In HomematicBridgeHandler.java it returns a null thing from getThing(). And that’s because the UID it generates is different from the real UID of the thing
  5. In turn that’s because the UID for the thing is “homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1354719”, but the gateway it’s connected to has a UID of “homematic:bridge:F6B89899-2A5B-533A-A2EC-A308C51F07EF”. The generated UID inside onStateUpdated uses this UID - so it generates “homematic:HG-BC-RT-TRX-CyG-3:F6B89899-2A5B-533A-A2EC-A308C51F07EF:MEQ1354719”, which then isn’t found because the real thing doesn’t have that UID.

All the things were created from the inbox, so it’s an interesting muddle that they’re in. I presume it’s just cruft left over from having upgraded this system multiple times over the years (openhab1->2->3 etc), something must have tied itself in knots.

I have deleted the gateway and all the things, and recreated them from the inbox. They have created with the correct UID. It looks like all my data is now updating dynamically as it would be expected to.

So, a lot of messing around to come to the conclusion that the thing id in the configuration didn’t match the real derived thing id. What’s weird is that it seemed happy to update when the thing was restarted, so it must have had enough information to find it on restart, but not enough information to find it when information was pushed over the pub/sub.

If someone were so inclined, this situation could be detected in future by placing an else clause on the null check:

    public void onStateUpdated(HmDatapoint dp) {
        Thing hmThing = getThing().getThing(UidUtils.generateThingUID(dp.getChannel().getDevice(), getThing()));
        if (hmThing != null) {
            final ThingStatus status = hmThing.getStatus();
            if (status == ThingStatus.ONLINE || status == ThingStatus.OFFLINE) {
                HomematicThingHandler thingHandler = (HomematicThingHandler) hmThing.getHandler();
                if (thingHandler != null) {
                    thingHandler.updateDatapointState(dp);
                }
            }
        } else {
            logger.debug("Thing not found for thing uid '{}'", UidUtils.generateThingUID(dp.getChannel().getDevice(), getThing()));
        }
    }

Thanks very much to everyone for the assistance and pointers.

1 Like

Good to hear that you could solve the problem. When I switched from 2.5 to 3.1deleted my existing configuration and started with a completely fresh installation. Quite a lot of work but but it probably saved me from a few problems :-).

Thanks for your proposal for the code improvement. Sounds like a good idea and I can add it to the code.

1 Like