[fronius] Transfer Timeout is not handled correctly (no new values until openhab restart) #

[ChristianHeinz71]

When running a while, the binding stops working and is not refreshing any value any more. A java.lang.NullPointerException was thrown. This issue is similar to #3556 but has a different callstack / root cause.

Output from logfile:

2018-07-12 00:22:08.382 [DEBUG] [nius.handler.FroniusBaseThingHandler] - Value retrieved for channel 'inverterdatachannelpac' was null. Can't update.
2018-07-12 00:22:08.395 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception
java.lang.NullPointerException: null
        at org.openhab.binding.fronius.handler.FroniusSymoInverterHandler.getValue(FroniusSymoInverterHandler.java:86) ~[?:?]
        at org.openhab.binding.fronius.handler.FroniusBaseThingHandler.updateChannel(FroniusBaseThingHandler.java:99) ~[?:?]
        at org.openhab.binding.fronius.handler.FroniusBaseThingHandler.updateChannels(FroniusBaseThingHandler.java:85) ~[?:?]
        at org.openhab.binding.fronius.handler.FroniusSymoInverterHandler.refresh(FroniusSymoInverterHandler.java:58) ~[?:?]
        at org.openhab.binding.fronius.handler.FroniusBridgeHandler.lambda$0(FroniusBridgeHandler.java:109) ~[?:?]
        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) [?:?]

After enabling debug mode for the binding I got the following response data with a transfer timeout issue and empty data node:

2018-07-19 23:14:29.898 [DEBUG] [s.handler.FroniusSymoInverterHandler] - URL = http://192.168.2.76/solar_api/v1/GetInverterRealtimeData.cgi?Scope=Device&DeviceId=1&DataCollection=CommonInverterData
2018-07-19 23:14:34.376 [DEBUG] [s.handler.FroniusSymoInverterHandler] - aqiResponse = {
   "Body" : {
      "Data" : {}
   },
   "Head" : {
      "RequestArguments" : {
         "DataCollection" : "CommonInverterData",
         "DeviceClass" : "Inverter",
         "DeviceId" : "1",
         "Scope" : "Device"
      },
      "Status" : {
         "Code" : 8,
         "Reason" : "Transfer timeout.",
         "UserMessage" : ""
      },
      "Timestamp" : "2018-07-19T23:14:32+02:00"
   }
}

Expected Behavior

No Crash while reading data from Fronius which is incomplete or has an error response.

Current Behavior

NullPointerException appears in case of "Transfer timeout". after that, the binding don't update values and seems to be crashed (openhab needs to be restarted)

Possible Solution

Check if the body and data node is not null:

        if (inverterRealtimeResponse == null) || (inverterRealtimeResponse.getBody() == null || inverterRealtimeResponse.getBody().getData() == null)  {
            return null;
        }

Steps to Reproduce (for Bugs)

1. Run for a while (didn't run for a whole day)
2. Maybe it is needed, that P_PV gets null, if no sun is shining and PV production stops

Context

Your Environment

• Version used: 2.4.0-SNAPSHOT (#1310)
• Operating System and version: Raspbian

[theKBro]

I have the same issue!

Your Environment

• Version used: 2.4.0-SNAPSHOT (#1310)
• Operating System and version: Windows 10

[benschi11]

Save issue here (i guess - the first line of the stack trace has moved from 86 to 87).

2018-08-05 20:32:33.616 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception
java.lang.NullPointerException: null
    at org.openhab.binding.fronius.handler.FroniusSymoInverterHandler.getValue(FroniusSymoInverterHandler.java:87) ~[?:?]
    at org.openhab.binding.fronius.handler.FroniusBaseThingHandler.updateChannel(FroniusBaseThingHandler.java:99) ~[?:?]
    at org.openhab.binding.fronius.handler.FroniusBaseThingHandler.updateChannels(FroniusBaseThingHandler.java:85) ~[?:?]
    at org.openhab.binding.fronius.handler.FroniusSymoInverterHandler.refresh(FroniusSymoInverterHandler.java:58) ~[?:?]
    at org.openhab.binding.fronius.handler.FroniusBridgeHandler.lambda$0(FroniusBridgeHandler.java:109) ~[?:?]
    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) [?:?]

Your Environment

• Version used: openHAB 2.4.0~20180802110936-1 (Build #1325)
• Fronius Binding Version: 2.4.0.201808020834

[ChristianHeinz71]

Unfortunately, the issue is still there, the Fronius binding is Not Working. I am using this bugfix in my OH Installation and it works fine.

[kaikreuzer]

So could any of you (@Hilbrand, @benschi11 & @ChristianHeinz71) simply come up with a PR to finally fix it?

[benschi11]

I think the problem will be fixed once the PR (https://github.com/openhab/openhab2-addons/pull/3828) is merged. I currently have no dev tools installed on my pc.

[kaikreuzer]

Ah, right, thanks - I wasn't aware of that PR. Looks as if we are waiting for @trokohl to incorporate @Hilbrand's comments then.

[trokohl]

oh, I overlooked the hints. I took they over.

[kaikreuzer]

Fixed by #3828.