[danfossairunit] All channels updated to zero

[jlaur]

Once in while this happens:

2021-09-01 18:44:46.984 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Main_ManualFanSpeed' changed from 10 to 0
2021-09-01 18:44:46.990 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Main_ExtractFanSpeed' changed from 2660 to 0
2021-09-01 18:44:46.991 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Main_SupplyFanSpeed' changed from 2091 to 0
2021-09-01 18:44:46.993 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Main_ExtractFanStep' changed from 88 to 0
2021-09-01 18:44:46.995 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Main_SupplyFanStep' changed from 63 to 0
2021-09-01 18:44:46.996 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Main_Boost' changed from ON to OFF
2021-09-01 18:44:46.998 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Main_NightCooling' changed from ON to OFF
2021-09-01 18:44:46.999 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_RoomTemperature' changed from 24.5 °C to 0 °C
2021-09-01 18:44:47.001 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_OutdoorTemperature' changed from 19.7 °C to 0 °C
2021-09-01 18:44:47.003 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Humidity' changed from 57.6 % to UNDEF
2021-09-01 18:44:47.004 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Recuperator_Bypass' changed from ON to OFF
2021-09-01 18:44:47.006 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Recuperator_SupplyAirTemperature' changed from 20.9 °C to 0 °C
2021-09-01 18:44:47.007 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Recuperator_ExtractAirTemperature' changed from 26.3 °C to 0 °C
2021-09-01 18:44:47.009 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Recuperator_ExhaustAirTemperature' changed from 23.8 °C to 0 °C
2021-09-01 18:44:47.011 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Service_RemainingFilterLife' changed from 8.235294342041016 to 0.0

All values are set to 0. I have a rule for sending me a push notification when DanfossHRV_Service_RemainingFilterLife is changed to a value less than 10%, so this is something I’ll notice and take action upon. These have been my ways to mitigate:

• Wait it out. Sometimes it happens when I’m sleeping or working, so I’ll not react in a timely manner, and when I attend to it, problem already resolved itself.
• Other times it has helped to restart the binding.
• A few times I have restarted the unit to fix the issue.
• Restarting the unit felt too aggressive, so I also tried pulling the Ethernet cable from my switch and put it back. Also seemed to resolve it.

I don't know if this happens due to:

• Air unit actually providing all these zero values (in which case solution might be some kind of validation).
• Communication problem not handled well. If connection is lost and temporarily can't be reestablished, thing should probably be marked offline. See [squeezebox] Map player connection state to thing status #10778
• Some other bug in the binding.

Expected Behavior

When values are not available for whatever reason, they should not be updated. If connection to air unit is lost, thing should be marked as offline.

Current Behavior

All channels are updated to 0 which is clearly invalid. This breaks graphs, statistics, calculations etc. based on persistence.

I don't know the reason yet, and also the frequency seems to inconsistent. In August 2021 it happened for me 5 times:

• 2021-08-08 04:44:43'
• 2021-08-11 21:14:55
• 2021-08-15 04:45:00
• 2021-08-19 20:54:40
• 2021-08-23 20:44:41

On January 1st 2021 it also happened, and then didn't happen again until May 29th, so almost five month straight. Lately it does seem to have gotten worse for me though.

Possible Solution

I'm currently testing this change in DanfossAirUnitCommunicationController method sendRequestInternal:

        int bytesRead = localInputStream.read(result, 0, 63);
        if (bytesRead < 63) {
            throw new IOException(String.format("Error reading from stream, read returned %d", bytesRead));
        }

Original version:

        // noinspection ResultOfMethodCallIgnored
        localInputStream.read(result, 0, 63);

Steps to Reproduce

I have not managed to reproduce it, so for now just monitoring. Luckily it happened today after I added some additional logging in the binding:

DanfossAirUnit.java:

    public QuantityType<Dimensionless> getHumidity() throws IOException, UnexpectedResponseValueException {
        byte responseByte = getByte(REGISTER_1_READ, HUMIDITY);
        BigDecimal value = BigDecimal.valueOf(asPercentByte(responseByte));
        if (responseByte == 0x00) {
            throw new UnexpectedResponseValueException("Invalid humidity - value is zero");
        }
        return new QuantityType<>(value.setScale(1, RoundingMode.HALF_UP), Units.PERCENT);
    }

This didn't happen. Actually, explanation is very likely because I was not logging debug-level information, and this exception is caught by handler and logged as debug. This seems to be even a stronger case when seeing also that value went to UNDEF:

catch (UnexpectedResponseValueException e) {
                updateState(channel.getGroup().getGroupName(), channel.getChannelName(), UnDefType.UNDEF);
                logger.debug(
                        "Cannot update channel {}: an unexpected or invalid response has been received from the air unit: {}",
                        channel.getChannelName(), e.getMessage());
 }

This behaviour changed actually with this change. Previously:

2021-08-11 21:14:54.872 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Humidity' changed from 57.6 to 0.0
But now:

2021-09-01 18:44:47.003 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Humidity' changed from 57.6 % to UNDEF

DanfossAirUnitCommunicationController.java:

    public synchronized byte[] sendRobustRequest(byte[] operation, byte[] register, byte[] value) throws IOException {
        connect();
        byte[] request = new byte[4 + value.length];
        System.arraycopy(operation, 0, request, 0, 2);
        System.arraycopy(register, 0, request, 2, 2);
        System.arraycopy(value, 0, request, 4, value.length);
        try {
            return sendRequestInternal(request);
        } catch (IOException ioe) {
            // retry once if there was connection problem
            logger.warn("Connection lost, attempting to reconnect. {}", ioe.getMessage());
            disconnect();
            connect();
            return sendRequestInternal(request);
        }
    }

This didn't happen either. Same class (last few lines):

    private synchronized byte[] sendRequestInternal(byte[] request) throws IOException {
        OutputStream localOutputStream = this.outputStream;

        if (localOutputStream == null) {
            throw new IOException(
                    String.format("Output stream is null while sending request: %s", Arrays.toString(request)));
        }
        localOutputStream.write(request);
        localOutputStream.flush();

        byte[] result = new byte[63];
        InputStream localInputStream = this.inputStream;
        if (localInputStream == null) {
            throw new IOException(
                    String.format("Input stream is null while sending request: %s", Arrays.toString(request)));
        }
        // noinspection ResultOfMethodCallIgnored
        int bytesRead = localInputStream.read(result, 0, 63);
        if (bytesRead < 63) {
            logger.warn("Number of bytes read: {}", bytesRead);
        }

        return result;
    }

This just happened a few days ago at the same time as a lot of other bindings struggled, so appeared to be some network disruption that needed to be handled:

==> /var/log/openhab/openhab.log <==
2021-09-13 20:03:19.403 [WARN ] [anfossAirUnitCommunicationController] - Number of bytes read: -1
2021-09-13 20:03:19.407 [WARN ] [anfossAirUnitCommunicationController] - Number of bytes read: -1
2021-09-13 20:03:19.410 [WARN ] [anfossAirUnitCommunicationController] - Number of bytes read: -1
==> /var/log/openhab/events.log <==
2021-09-13 20:03:19.415 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Main_ManualFanSpeed' changed from 10 to 0
==> /var/log/openhab/openhab.log <==
2021-09-13 20:03:19.416 [WARN ] [anfossAirUnitCommunicationController] - Number of bytes read: -1
2021-09-13 20:03:19.420 [WARN ] [anfossAirUnitCommunicationController] - Number of bytes read: -1
2021-09-13 20:03:19.424 [WARN ] [anfossAirUnitCommunicationController] - Number of bytes read: -1
==> /var/log/openhab/events.log <==
2021-09-13 20:03:19.425 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Main_ExtractFanSpeed' changed from 2433 to 0

etc.

[openhab-bot]

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/danfossairunit-handling-of-lost-connection/125539/2

[jlaur]

Suggested solution has now been tested for some time, and today had it triggered and confirmed:

2021-09-21 07:05:05.050 [WARN ] [anfossAirUnitCommunicationController] - Connection lost, attempting to reconnect. Error reading from stream, read returned -1
2021-09-21 07:05:05.521 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Main_ExtractFanSpeed' changed from 2430 to 2421
2021-09-21 07:05:05.523 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Main_SupplyFanSpeed' changed from 1900 to 1912
2021-09-21 07:05:05.545 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Humidity' changed from 58.4 % to 60 %
2021-09-21 07:05:05.549 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DanfossHRV_Recuperator_SupplyAirTemperature' changed from 22.1 °C to 22.3 °C

So it works even better than anticipated. I had hoped that it would be able to gracefully handle an unrecoverable issue without updating all channels to zero. But in this scenario it was simply a lost connection, so completely recoverable. Caller:

        try {
            return sendRequestInternal(request);
        } catch (IOException ioe) {
            // retry once if there was connection problem
            disconnect();
            connect();
            return sendRequestInternal(request);
        }

So two issues fixed:

• No longer updates all channels to zero after connection loss.
• When connection cannot be reestablished, updates all channels to Undefined instead of zero values, i.e. without breaking graphs etc.

The logged error ""Connection lost, attempting to reconnect. " is from the test code as shown somewhere in description, so nothing would be logged when just applying the fix.