openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.88k stars 3.59k forks source link

[CoolMasterNet] stopped working after 2.5.0M1 #7333

Closed dirkypower closed 4 years ago

dirkypower commented 4 years ago

Expected Behavior

I am currently using version 2.5.0M1 as it is the last version i have that works properly.

Current Behavior

The issue with the current binding 2.5.3 is that as soon as I try to change the status of an item linked to the HVAC, the HVAC thing goes offline and doesn’t respond no longer. see log below:

Possible Solution

I am not a programmer so I can not suggest a solution

Steps to Reproduce (for Bugs)

1) Installed addon 2) Added Coolmaternet Thing works fine thing goes online 3) Added HVAC Thing works as well and thing goes online. 4) Link Item to HVAC Thing error appears and thing goes offline and stays offlne

Context

Your Environment

Openhab 2.5.3 fresh installed with just this addon already shows the issue.

LOG: < 2020-04-08 13:26:31.479 [hingStatusInfoChangedEvent] - 'coolmasternet:controller:bcaa3fb6' changed from UNINITIALIZED to INITIALIZING 2020-04-08 13:26:31.528 [hingStatusInfoChangedEvent] - 'coolmasternet:controller:bcaa3fb6' changed from INITIALIZING to ONLINE 2020-04-08 13:26:46.637 [hingStatusInfoChangedEvent] - 'coolmasternet:hvac:8ad959b7' changed from UNINITIALIZED to INITIALIZING 2020-04-08 13:26:46.645 [hingStatusInfoChangedEvent] - 'coolmasternet:hvac:8ad959b7' changed from INITIALIZING to ONLINE 2020-04-08 13:28:41.437 [.ItemChannelLinkAddedEvent] - Link 'HVACSystem_Power-coolmasternet:hvac:8ad959b7:on' has been added. 2020-04-08 13:28:41.439 [hingStatusInfoChangedEvent] - 'coolmasternet:hvac:8ad959b7' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Could not connect to CoolMasterNet unit 192.168.0.10:10102

benalexau commented 4 years ago

Forum user "DP" first reported this bug. The same user made an earlier posting regarding issues with this addon that included the following stack trace clue:

2019-06-05 11:57:02.579 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NumberFormatException: null
    at java.math.BigDecimal.<init>(BigDecimal.java:494) ~[?:?]
    at java.math.BigDecimal.<init>(BigDecimal.java:383) ~[?:?]
    at java.math.BigDecimal.<init>(BigDecimal.java:806) ~[?:?]
    at org.eclipse.smarthome.core.library.types.DecimalType.<init>(DecimalType.java:57) ~[?:?]
    at org.openhab.binding.coolmasternet.internal.handler.HVACHandler.refresh(HVACHandler.java:119) ~[?:?]
    at org.openhab.binding.coolmasternet.internal.ControllerHandler.refreshHVACUnits(ControllerHandler.java:106) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:?]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
    at java.lang.Thread.run(Thread.java:748) [?:?]

Focusing on the stack trace, the relevant HVACHandler code is:

        String currentTemp = query("a");
        if (currentTemp != null) {
            updateState(CURRENT_TEMP, new DecimalType(currentTemp));
        }

As such there is no way the DecimalType constructor (and in turn BigDecimal(String)) is receiving null.

Using log:set TRACE org.openhab.binding.coolmasternet suggested the reason for the NumberFormatException:

2020-04-28 19:21:21.587 [TRACE] [masternet.internal.ControllerHandler] - Sending command 'query L4.000 a'
2020-04-28 19:21:21.692 [TRACE] [masternet.internal.ControllerHandler] - Read result '>24'
2020-04-28 19:21:21.692 [TRACE] [masternet.internal.ControllerHandler] - Read result 'OK'

As detailed in the CoolMasterNet ASCII I/F Programmer Reference Guide (PRG), the prompt character is >. The exception is caused because >24 is not a legal decimal number, and the exception shown was confirmed by the following test:

  @Test()
  public void format() {
    try {
      new DecimalType(">24");
    } catch (NumberFormatException nfe) {
      assertThat(nfe.getMessage(), is(null));
    }
  }

So the real question is why are we seeing the > prompt at all? After all, ControllerHandler.sendCommand(String) uses checkConnection() which is coded to clear the buffer before returning.

A closer inspection of sendCommand(String) found it is incorrectly handling the opening of a connection. When connecting to the telnet interface, the servers automatically sends a welcome > prompt. This method therefore has two bugs:

  1. It considers the buffer is empty by just checking it has no bytes available. This means if the server hasn't yet responded to the connection opening request, the buffer would indeed be empty at that moment. The method then sends a CRLF to solicit the prompt and wait for a > in reply. It considers a reply has been received to that prompt solicitation request because > does indeed arrive. However that > was from the original connection opening operation - not in response to the CRLF sent to solicit a prompt. The method then prematurely returns, believing the buffer empty, but a subsequent > arrives in response to the CRLF that sendCommand(..) had sent.
  2. The method assumes a > prompt would be followed with a CRLF (as per the code comment "Send a CRLF, expect a > prompt (and a CRLF) back"). Actually the > prompt does not have any characters following it, which can be seen if you telnet into the server.

While that can be fixed easily enough, the bigger issue is why does sending a command cause the thing to be considered offline? A look at HVACHandler.handleCommand(..) shows the thing is marked offline if its bridge is offline. Its bridge is offline if ControllerHandler.isConnected() returns false. In turn that method is considering a connection offline if the Socket.isClosed(). The use of a try-with-resources statement in ControllerHandler.sendCommand(..) is always resulting in the socket being closed as it duly releases those resources. The simplest solution is to introduce an UncloseableInputStream to prevent the underlying socket from being closed.

Finally ControllerHandler is routinely sending CRLF when the ASCII I/F PRG states only LF is required.

I have fixed all this locally and will test it further before submitting a PR.