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:
- Change the thermostat setting manually on the thermostat
- Data arrives via the bridge, visible in the openhab log
- Data updated to the channel, and to the associated items
This all flows automatically.
Devices on the other bridge:
- Change thermostat setting manually on the thermostat
- Data arrives via the bridge, visible in the log
- Data never updates to the channel, no errors or other information logged
- Disable then enable the thing
- 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:
- 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
- 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
- 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
- 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).
