search

openhab / openhab-addons

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

[senechome] Data no longer refreshed if malformed JSON received #10025

Closed ralfellner closed 3 years ago

ralfellner commented 3 years ago

Expected Behavior

The binding refreshes data from Senec in the next poll cycle if an Exception occurred.

Current Behavior

The job that performs the data refresh terminates in some situations (e.g., malformed JSON received):

[WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
com.google.gson.JsonSyntaxException: com.google.gson.stream.MalformedJsonException: Unterminated object at line 1 column 2350 path $.PM1OBJ1.null
        at com.google.gson.Gson.fromJson(Gson.java:903) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:853) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:802) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:774) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeApi.getStatistics(SenecHomeApi.java:82) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refreshState(SenecHomeHandler.java:123) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.refreshValue(ExpiringCache.java:101) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.getValue(ExpiringCache.java:72) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refresh(SenecHomeHandler.java:118) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: com.google.gson.stream.MalformedJsonException: Unterminated object at line 1 column 2350 path $.PM1OBJ1.null
        at com.google.gson.stream.JsonReader.syntaxError(JsonReader.java:1568) ~[?:?]
        at com.google.gson.stream.JsonReader.doPeek(JsonReader.java:491) ~[?:?]
        at com.google.gson.stream.JsonReader.hasNext(JsonReader.java:414) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:214) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(ReflectiveTypeAdapterFactory.java:129) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:220) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:888) ~[?:?]
        ... 14 more

If such an error occurred, data from Senec is no longer refreshed. This happens about once a week on my installation. Some other types of Exception seem to be already handled correctly, e.g. java.net.SocketTimeoutException:

[WARN ] [.senechome.internal.SenecHomeHandler] - Error refreshing source 'senechome:senechome:pvbattery'
java.util.concurrent.ExecutionException: java.net.SocketTimeoutException: Connect Timeout
        at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:685) ~[bundleFile:9.4.20.v20190813]
        at org.openhab.binding.senechome.internal.SenecHomeApi.getStatistics(SenecHomeApi.java:79) ~[bundleFile:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refreshState(SenecHomeHandler.java:123) [bundleFile:?]
        at org.openhab.core.cache.ExpiringCache.refreshValue(ExpiringCache.java:101) [bundleFile:?]
        at org.openhab.core.cache.ExpiringCache.getValue(ExpiringCache.java:72) [bundleFile:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refresh(SenecHomeHandler.java:118) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: java.net.SocketTimeoutException: Connect Timeout
        at org.eclipse.jetty.io.ManagedSelector$Connect.run(ManagedSelector.java:802) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        ... 3 more

Possible Solution

The Exception types thrown by gson probably just need to be added to the catch clause in:

https://github.com/openhab/openhab-addons/blob/51ea77f0228d373cabfaaeeeafd332c29af9e864/bundles/org.openhab.binding.senechome/src/main/java/org/openhab/binding/senechome/internal/SenecHomeHandler.java#L279

Steps to Reproduce (for Bugs)

Point Senec Home binding to a webserver that delivers a malformed JSON.

Your Environment

OpenHAB 3.0.1 running in Docker on Ubuntu 20.04 (AMD64). Senec Home V2.1

querdenker2k commented 3 years ago

Same problem here:

2021-02-23 04:23:38.858 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
com.google.gson.JsonSyntaxException: com.google.gson.stream.MalformedJsonException: Expected ':' at line 1 column 2887 path $.STATISTIC.L
        at com.google.gson.Gson.fromJson(Gson.java:903) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:853) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:802) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:774) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeApi.getStatistics(SenecHomeApi.java:82) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refreshState(SenecHomeHandler.java:123) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.refreshValue(ExpiringCache.java:101) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.getValue(ExpiringCache.java:72) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refresh(SenecHomeHandler.java:118) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: com.google.gson.stream.MalformedJsonException: Expected ':' at line 1 column 2887 path $.STATISTIC.L
        at com.google.gson.stream.JsonReader.syntaxError(JsonReader.java:1568) ~[?:?]
        at com.google.gson.stream.JsonReader.doPeek(JsonReader.java:530) ~[?:?]
        at com.google.gson.stream.JsonReader.skipValue(JsonReader.java:1232) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:218) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(ReflectiveTypeAdapterFactory.java:129) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:220) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:888) ~[?:?]
        ... 14 more

Would fix it on my own, but the guide for developing with intelliJ isn't working. @KorbinianP: Can you fix this please.

KorbinianP commented 3 years ago

Hello, I will have a look into asap, but I can't promise an eta. Tnx for putting my name, I did not get any notification for the first Bug Message. @querdenker2k How often does this happen for you? Cheers

querdenker2k commented 3 years ago

Not that often. Maybe every two months. Happened again today (25.2.)

KorbinianP commented 3 years ago

Thats Interesting. I changed the code like this: https://github.com/KorbinianP/openhab-addons/blob/5c03195ba668d6da3e704ce187cad276b3f41a20/bundles/org.openhab.binding.senechome/src/main/java/org/openhab/binding/senechome/internal/SenecHomeHandler.java#L282-L283

But I only get the error message

[ERROR] /mnt/d/Korbinian/Github/openhab-addons/bundles/org.openhab.binding.senechome/src/main/java/org/openhab/binding/senechome/internal/SenecHomeHandler.java:[282,95] The exception java.net.SocketTimeoutException is already caught by the alternative java.io.IOException [ERROR] /mnt/d/Korbinian/Github/openhab-addons/bundles/org.openhab.binding.senechome/src/main/java/org/openhab/binding/senechome/internal/SenecHomeHandler.java:[283,19] The exception com.google.gson.stream.MalformedJsonException is already caught by the alternative java.io.IOException

I don't really understand why it is caught by IOException, but still resulting in an unstable environment.

KorbinianP commented 3 years ago

@ralfellner @querdenker2k

What do you think, should I add some sort of counter to the catch block so that the item doesn't go immediately offline? But only after 3 consecutive tries?

https://github.com/KorbinianP/openhab-addons/blob/183cb791ccdcf4743b9ac9fb7fe5baffe41b6d09/bundles/org.openhab.binding.senechome/src/main/java/org/openhab/binding/senechome/internal/SenecHomeHandler.java#L282-L290

Here the Jar to test: org.openhab.binding.senechome-3.1.0-SNAPSHOT.jar.zip

Cheers

querdenker2k commented 3 years ago

I will install this tomorrow. Could you please print the json string in the failure case. I do not know why the json is corrupted and maybe it's for longer than 3 request (3 seconds). I would like to have a better failure detection but I don't have a better idea now.

KorbinianP commented 3 years ago

@querdenker2k That sounds like a good plan. I would also like to understand a bit more. I did implement now a print, the result should look like this: https://github.com/KorbinianP/openhab-addons/blob/d98135f84f0585fd29f453152eb2eef62e0018dd/bundles/org.openhab.binding.senechome/src/main/java/org/openhab/binding/senechome/internal/SenecHomeHandler.java#L284

2021-02-28 18:39:33.273 [WARN ] [.senechome.internal.SenecHomeHandler] - Faulty response: SenecHomeResponse [limitation=SenecHomePower [powerLimitation=u3_00000064], energy=SenecHomeEnergy [homePowerConsumption=fl_451E3085, inverterPowerGeneration=fl_3F9D0E57, batteryPower=fl_C51FCA63, batteryFuelCharge=fl_4283F7CF, batteryState=u8_10, batteryVoltagefl_42567BE7], grid=SenecHomeGrid [currentGridValue=fl_C1DB0A3D, gridVoltagePerPhase= [Ljava.lang.String;@46854539, currentGridCurrentPerPhase= [Ljava.lang.String;@76f5fd99, currentGridPowerPerPhase= [Ljava.lang.String;@4c6a1b70, currentGridFrequency=fl_42480A3D], statistics=SenecHomeStatistics [liveBatCharge=fl_4367A734, liveBatDischarge= fl_43671111, liveGridImport= fl_456BD0BF, liveGridExport= fl_43196100]]

Here the file: org.openhab.binding.senechome-3.1.0-SNAPSHOT.jar.zip

Cheers

querdenker2k commented 3 years ago

It happend again, but this is the result in the logfile:

2021-03-03 11:39:19.910 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refreshState(SenecHomeHandler.java:284) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.refreshValue(ExpiringCache.java:101) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.getValue(ExpiringCache.java:72) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refresh(SenecHomeHandler.java:120) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]

Don't know how this can happen (The NPE at this place). Could you print out the unserialized data.

ralfellner commented 3 years ago

@querdenker2k @KorbinianP

Thank you very much for having a look into this issue. Unfortunately, I think the lasted change will not help to debug the problem.

In line 126 the response is previously initialized to null. If the retrieval of the response fails, it will remain null.
https://github.com/KorbinianP/openhab-addons/blob/d98135f84f0585fd29f453152eb2eef62e0018dd/bundles/org.openhab.binding.senechome/src/main/java/org/openhab/binding/senechome/internal/SenecHomeHandler.java#L126

Trying to print the response in the catch block will then lead to the above NullPointerException. https://github.com/KorbinianP/openhab-addons/blob/d98135f84f0585fd29f453152eb2eef62e0018dd/bundles/org.openhab.binding.senechome/src/main/java/org/openhab/binding/senechome/internal/SenecHomeHandler.java#L284

I think you really need to print out the unserialized data in SenecHomeApi in an additional try-catch block around line 82: https://github.com/KorbinianP/openhab-addons/blob/183cb791ccdcf4743b9ac9fb7fe5baffe41b6d09/bundles/org.openhab.binding.senechome/src/main/java/org/openhab/binding/senechome/internal/SenecHomeApi.java#L82

Best regards

KorbinianP commented 3 years ago

Hello @ralfellner

You are absolutely right. Wrong place for a print. I created a new Version: https://github.com/KorbinianP/openhab-addons/blob/aec0c9c83f38f55126c4a85fe23fbf34e9655036/bundles/org.openhab.binding.senechome/src/main/java/org/openhab/binding/senechome/internal/SenecHomeApi.java#L79-L101

Here the Jar: org.openhab.binding.senechome-3.1.0-SNAPSHOT.jar.zip @querdenker2k @ralfellner could you test again?

The log will look something like this:

[WARN ] [ding.senechome.internal.SenecHomeApi] - Issue with getting response [WARN ] [ding.senechome.internal.SenecHomeApi] - location: http://192.168.178.122 [WARN ] [ding.senechome.internal.SenecHomeApi] - request: HttpRequest[POST / HTTP/1.1]@45ac1240 [WARN ] [ding.senechome.internal.SenecHomeApi] - request.getHeaders: Accept-Encoding: gzip User-Agent: Jetty/9.4.20.v20190813 Accept: application/json Content-Type: application/x-www-form-urlencoded Host: 192.168.178.122 Content-Length: 50

[WARN ] [ding.senechome.internal.SenecHomeApi] - response: HttpContentResponse[HTTP/1.0 200 OK - 3497 bytes] [WARN ] [ding.senechome.internal.SenecHomeApi] - response.getHeaders: Content-Type: application/json; charset=UTF-8

[WARN ] [ding.senechome.internal.SenecHomeApi] - response.getContentAsString: {"PV1":{"ERROR_STATE_INT":["u3_00000000","u3_00000000"],"INTERNAL_INV_ERROR_TEXT":["st_120:ENS HW isolation conditions,16:ENS HW isolation","st_37:ENS Line connection wrong"],"INTERNAL_INV_ERR_STATE_VALID":["u8_01","u8_01"],"INTERNAL_INV_STATE":["u8_02","u8_02"],"INTERNAL_MD_AVAIL":["u8_01","u8_01"],"INTERNAL_MD_MANUFACTURER":["st_Senec","st_Senec"],"INTERNAL_MD_MODEL":["st_V3 LV","st_V3 HV"],"INTERNAL_MD_SERIAL":["st_767272FK007607880006","st_765856FB007183650011"],"INTERNAL_MD_VERSION":["st_HMI: 3.15.32 PU: 4.1.89 BDC: 5.4.4","st_HMI: 3.11.20 PU: 3.6.1"],"INTERNAL_PV_AVAIL":"u8_02","INVMODEL":["st","st_","st_END_OF_ARRAY"],"INVSERIAL":["st","st_","st_END_OF_ARRAY"],"INV_VERSIONS":["st_HMI: 3.15.32 PU: 4.1.89","st_HMI: 3.11.20 PU: 3.6.1","st_END_OF_ARRAY"],"MPP_AVAIL":"u8_03","MPP_CUR":["fl_415526EA","fl_00000000","fl_40A3E76D"],"MPP_POWER":["fl_45973327","fl_00000000","fl_44AC2BE0"],"MPP_VOL":["fl_43B557AF","fl_437597D0","fl_4385BC8C"],"POWER_RATIO":"u3_00000064","POWER_RATIO_L1":"u3_00000064","POWER_RATIO_L2":"u3_00000064","POWER_RATIO_L3":"u3_00000064","PV_MISSING":"u8_03","P_TOTAL":"fl_C5C23E1F","STATE_INT":["u3_00000110","u3_00000110"],"TYPE":"u8_A0"},"ENERGY":{"CAPTESTMODULE":["fl_00000000","fl_00000000","fl_00000000","fl_00000000"],"GUI_BAT_DATA_COLLECTED":"u8_01","GUI_BAT_DATA_CURRENT":"fl_424028F6","GUI_BAT_DATA_FUEL_CHARGE":"fl_41BDB43A","GUI_BAT_DATA_POWER":"fl_45183F6E","GUI_BAT_DATA_VOLTAGE":"fl_424AD3F8","GUI_BOOSTING_INFO":"u8_00","GUI_CAP_TEST_STATE":"u8_00","GUI_CHARGING_INFO":"u8_01","GUI_GRID_POW":"fl_C53FA000","GUI_HOUSE_POW":"fl_44327340","GUI_INIT_CHARGE_START":"u8_00","GUI_INIT_CHARGE_STOP":"u8_00","GUI_INVERTER_POWER":"fl_45C23E1F","GUI_TEST_CHARGE_STAT":"u8_00","GUI_TEST_DISCHARGE_STAT":"u8_00","INIT_CHARGE_ACK":"u8_00","INIT_CHARGE_DIFF_VOLTAGE":"fl_00000000","INIT_CHARGE_MAX_CURRENT":"fl_00000000","INIT_CHARGE_MAX_VOLTAGE":"fl_00000000","INIT_CHARGE_MIN_VOLTAGE":"fl_00000000","INIT_CHARGE_RERUN":"u8_00","INIT_CHARGE_RUNNING":"u8_00","INIT_CHARGE_STATE":"u8_00","INIT_CHARGE_TIMER":"u6_0000000000000000","INIT_DISCHARGE_MAX_CURRENT":"fl_00000000","LI_STORAGE_MODE_RUNNING":"u8_00","LI_STORAGE_MODE_START":"u8_00","LI_STORAGE_MODE_STOP":"u8_00","OFFPEAK_DURATION":"u1_0000","OFFPEAK_POWER":"fl_00000000","OFFPEAK_RUNNING":"u8_00","OFFPEAK_TARGET":"u8_64","SAFE_CHARGE_FORCE":"u8_00","SAFE_CHARGE_PROHIBIT":"u8_00","SAFE_CHARGE_RUNNING":"u8_00","STAT_HOURS_OF_OPERATION":"u3_00000A9A","STAT_LIMITED_NET_SKEW":"u8_00","STAT_STATE":"u8_0E","STAT_STATE_DECODE":"u8_0E","ZERO_EXPORT":"u8_00"},"PM1OBJ1":{"ADR":"u8_01","ENABLED":"u8_01","FREQ":"fl_4247F5C2","I_AC":["fl_410F3333","fl_409E6666","fl_3F68F5C2"],"P_AC":["fl_C501D666","fl_C48B10A4","fl_42F7DC29"],"P_TOTAL":"fl_C53FA000","U_AC":["fl_43683333","fl_436A0000","fl_43683333"]},"STATISTIC":{"CURRENT_STATE":"u1_000E","LIVE_BAT_CHARGE":"fl_43846C7B","LIVE_BAT_CHARGE_MASTER":"fl_43846C7B","LIVE_BAT_DISCHARGE":"fl_4385E8D8","LIVE_BAT_DISCHARGE_MASTER":"fl_4385E8D8","LIVE_GRID_EXPORT":"fl_434FCEA4","LIVE_GRID_IMPORT":"fl_456E0530","LIVE_HOUSE_CONS":"fl_458BC9EE","LIVE_PU_ENERGY":["fl_00000000","fl_00000000","fl_00000000","fl_00000000","fl_00000000","fl_00000000"],"LIVE_PV_GEN":"fl_44597079","LIVE_WB_ENERGY":["u6_0000000000000000","u6_0000000000000000","u6_0000000000000000","u6_0000000000000000"],"MEASURE_TIME":"i3_6040B33B","STAT_SUM_E_PU":["u6_0000000000000000","u6_0000000000000000","u6_0000000000000000","u6_0000000000000000","u6_0000000000000000","u6_0000000000000000"]}}

Cheers

querdenker2k commented 3 years ago

I think i forgot to restart openhab. It happens again (but with the old logging). This is the result

2021-03-09 23:32:48.104 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
com.google.gson.JsonSyntaxException: com.google.gson.stream.MalformedJsonException: Unterminated array at line 1 column 1009 path $.ENERGY.CAPTESTMODULE[0]
        at com.google.gson.Gson.fromJson(Gson.java:903) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:853) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:802) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:774) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeApi.getStatistics(SenecHomeApi.java:82) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refreshState(SenecHomeHandler.java:126) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.refreshValue(ExpiringCache.java:101) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.getValue(ExpiringCache.java:72) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refresh(SenecHomeHandler.java:120) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: com.google.gson.stream.MalformedJsonException: Unterminated array at line 1 column 1009 path $.ENERGY.CAPTESTMODULE[0]
        at com.google.gson.stream.JsonReader.syntaxError(JsonReader.java:1568) ~[?:?]
        at com.google.gson.stream.JsonReader.doPeek(JsonReader.java:476) ~[?:?]
        at com.google.gson.stream.JsonReader.skipValue(JsonReader.java:1232) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:218) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(ReflectiveTypeAdapterFactory.java:129) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:220) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:888) ~[?:?]
        ... 14 more
KorbinianP commented 3 years ago

Hello @querdenker2k Sadly this doesn't help. Please check in your log (http://:9001/) that the updated jar is installed. I had with OH2.4 the issue that it only took the jar after I uninstalled the binding. Not sure if this is still the way in 3.0.

With my SENEC.Home V3 hybrid duo I did never face this issue, so that bug seems to be fixed by SENEC. I wonder if I should catch the JsonSyntaxException and only print a warning without setting the device to offline ever. Then we would drop one received frame and would continue with the next one.

What do you think?

Cheers

querdenker2k commented 3 years ago

I restarted Openhab. I think latest next week I will have the error again. Let us wait...

querdenker2k commented 3 years ago

Ok, happened again, but no logging

2021-03-19 05:35:27.182 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
com.google.gson.JsonSyntaxException: com.google.gson.stream.MalformedJsonException: Unterminated array at line 1 column 2887 path $.STATISTIC.LIVE_PU_ENERGY[3]
        at com.google.gson.Gson.fromJson(Gson.java:903) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:853) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:802) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:774) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeApi.getStatistics(SenecHomeApi.java:83) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refreshState(SenecHomeHandler.java:126) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.refreshValue(ExpiringCache.java:101) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.getValue(ExpiringCache.java:72) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refresh(SenecHomeHandler.java:120) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: com.google.gson.stream.MalformedJsonException: Unterminated array at line 1 column 2887 path $.STATISTIC.LIVE_PU_ENERGY[3]
        at com.google.gson.stream.JsonReader.syntaxError(JsonReader.java:1568) ~[?:?]
        at com.google.gson.stream.JsonReader.doPeek(JsonReader.java:476) ~[?:?]
        at com.google.gson.stream.JsonReader.skipValue(JsonReader.java:1232) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:218) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(ReflectiveTypeAdapterFactory.java:129) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:220) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:888) ~[?:?]
        ... 14 more

Senec Addon is the correct version

openhab> bundle:list | grep Senec
281 x Active x  80 x 3.1.0.202103041018      x openHAB Add-ons :: Bundles :: SenecHome Binding

Don't know why the logging isn't working. I have a Senec Home V2.1 1ph / Lithium, but i hadn't the problem before. The error started 3/4 month ago. Ok for now i think catching the MalformedJsonException is a good idea and maybe with the error-counter.

querdenker2k commented 3 years ago

Happened again, i restarted just the binding without openhab and there is more logging, but not the expected :(

2021-03-22 22:53:53.639 [WARN ] [ding.senechome.internal.SenecHomeApi] - Issue with getting SenecHomeResponse
2021-03-22 22:53:53.639 [WARN ] [ding.senechome.internal.SenecHomeApi] - location: http://192.168.1.227
2021-03-22 22:53:53.640 [WARN ] [ding.senechome.internal.SenecHomeApi] - request: HttpRequest[POST  HTTP/1.1]@60789ea7
2021-03-22 22:53:53.640 [WARN ] [ding.senechome.internal.SenecHomeApi] - request.getHeaders: Accept-Encoding: gzip
User-Agent: Jetty/9.4.20.v20190813
Accept: application/json
Content-Type: application/x-www-form-urlencoded

2021-03-22 22:53:53.640 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
        at org.openhab.binding.senechome.internal.SenecHomeApi.getStatistics(SenecHomeApi.java:93) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refreshState(SenecHomeHandler.java:126) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.refreshValue(ExpiringCache.java:101) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.getValue(ExpiringCache.java:72) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refresh(SenecHomeHandler.java:120) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
KorbinianP commented 3 years ago

@querdenker2k Thank you for the second log, it helps at least a little.

My header of a working transmit:

[WARN ] [ding.senechome.internal.SenecHomeApi] - request.getHeaders: Accept-Encoding: gzip
User-Agent: Jetty/9.4.20.v20190813
Accept: application/json
Content-Type: application/x-www-form-urlencoded
Host: 192.168.178.122
Content-Length: 50

Your header of a not working transmit:

[WARN ] [ding.senechome.internal.SenecHomeApi] - request.getHeaders: Accept-Encoding: gzip
User-Agent: Jetty/9.4.20.v20190813
Accept: application/json
Content-Type: application/x-www-form-urlencoded

Looks to me that there is no content! Also the NullPointerExeption happens at the line logger.warn("response: {}", response.toString());, so the response seems really to be null.

Sadly this is another error like last time, where you posted 2021-03-09 23:32:48.104 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: com.google.gson.JsonSyntaxException: com.google.gson.stream.MalformedJsonException: Unterminated array at line 1 column 1009 path $.ENERGY.CAPTESTMODULE[0]

There the transmit was interrupted as it sounds.

Could you post one more log once it happens again?

Cheers

querdenker2k commented 3 years ago

One more failure:

2021-03-26 14:23:49.456 [WARN ] [ding.senechome.internal.SenecHomeApi] - Issue with getting SenecHomeResponse
2021-03-26 14:23:49.457 [WARN ] [ding.senechome.internal.SenecHomeApi] - location: http://192.168.1.227
2021-03-26 14:23:49.457 [WARN ] [ding.senechome.internal.SenecHomeApi] - request: HttpRequest[POST  HTTP/1.1]@999d31d
2021-03-26 14:23:49.457 [WARN ] [ding.senechome.internal.SenecHomeApi] - request.getHeaders: Accept-Encoding: gzip
User-Agent: Jetty/9.4.20.v20190813
Accept: application/json
Content-Type: application/x-www-form-urlencoded

2021-03-26 14:23:49.457 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.NullPointerException: null
        at org.openhab.binding.senechome.internal.SenecHomeApi.getStatistics(SenecHomeApi.java:93) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refreshState(SenecHomeHandler.java:126) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.refreshValue(ExpiringCache.java:101) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.getValue(ExpiringCache.java:72) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refresh(SenecHomeHandler.java:120) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]

Same error as last time. Yes i am wondering that the response object is null and not an exception is thrown. Strange API.

querdenker2k commented 3 years ago

I restarted just the binding and this is the next error

2021-03-29 10:09:42.029 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
com.google.gson.JsonSyntaxException: com.google.gson.stream.MalformedJsonException: Unterminated array at line 1 column 1009 path $.ENERGY.CAPTESTMODULE[0]
        at com.google.gson.Gson.fromJson(Gson.java:903) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:853) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:802) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:774) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeApi.getStatistics(SenecHomeApi.java:83) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refreshState(SenecHomeHandler.java:126) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.refreshValue(ExpiringCache.java:101) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.getValue(ExpiringCache.java:72) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refresh(SenecHomeHandler.java:120) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: com.google.gson.stream.MalformedJsonException: Unterminated array at line 1 column 1009 path $.ENERGY.CAPTESTMODULE[0]
        at com.google.gson.stream.JsonReader.syntaxError(JsonReader.java:1568) ~[?:?]
        at com.google.gson.stream.JsonReader.doPeek(JsonReader.java:476) ~[?:?]
        at com.google.gson.stream.JsonReader.skipValue(JsonReader.java:1232) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:218) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(ReflectiveTypeAdapterFactory.java:129) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:220) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:888) ~[?:?]
        ... 14 more

I don't know what openhab is doing. It seems to be an old version because the other logging output is missing.

Puddingkuchen commented 3 years ago

SENEC.Home V3 hybrid duo I am getting this error aswell. 

18:30:04.796 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
com.google.gson.JsonSyntaxException: com.google.gson.stream.MalformedJsonException: Unterminated object at line 1 column 1009 path $.PV1.null
        at com.google.gson.Gson.fromJson(Gson.java:903) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:853) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:802) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:774) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeApi.getStatistics(SenecHomeApi.java:83) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refreshState(SenecHomeHandler.java:126) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.refreshValue(ExpiringCache.java:101) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.getValue(ExpiringCache.java:72) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refresh(SenecHomeHandler.java:120) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: com.google.gson.stream.MalformedJsonException: Unterminated object at line 1 column 1009 path $.PV1.null
        at com.google.gson.stream.JsonReader.syntaxError(JsonReader.java:1568) ~[?:?]
        at com.google.gson.stream.JsonReader.doPeek(JsonReader.java:491) ~[?:?]
        at com.google.gson.stream.JsonReader.hasNext(JsonReader.java:414) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:214) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(ReflectiveTypeAdapterFactory.java:129) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:220) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:888) ~[?:?]
        ... 14 more

Currently its only taking ~2 minutes until it breaks again.

It looks like the try catch block in SenecHomeHandler.java is not catching the com.google.gson.stream.MalformedJsonException.

KorbinianP commented 3 years ago

Hello @Puddingkuchen,

Strange, you have the same device as I have, SENEC.Home V3 hybrid duo. And for me this never happened. What SW Versions is yours running? For me:

REVISION MCU: 0806 REVISION MCU-BL: 954 REVISION NPU-REGS: 08 REVISION NPU-IMAGE: 2004 REVISION GUI: 0954 REVISION HMI: 3.15.32 REVISION PU: 4.1.89 REVISION BDC: 5.4.4

Are you running OpenHAB3? And did you install my test jar? Can be found above, 4. March. https://github.com/openhab/openhab-addons/issues/10025#issuecomment-790822861

The MalformedJsonException is catched by my test code (The exception com.google.gson.stream.MalformedJsonException is already caught by the alternative java.io.IOException).

Link to my test code: https://github.com/KorbinianP/openhab-addons/blob/aec0c9c83f38f55126c4a85fe23fbf34e9655036/bundles/org.openhab.binding.senechome/src/main/java/org/openhab/binding/senechome/internal/SenecHomeApi.java#L79-L101

So if the gson.fromJson() throws an MalformedJsonException, the catch (IOException | InterruptedException | TimeoutException | ExecutionException e) should do the job, catch the exception and print then the response plus getContentAsString. As in your case the response seems to have a (malformed) content.

Cheers,

Korbinian

Puddingkuchen commented 3 years ago

Hey @KorbinianP, yes same Versions

REVISION MCU: 0806 REVISION MCU-BL: 954 REVISION NPU-REGS: 08 REVISION NPU-IMAGE: 2004 REVISION GUI: 0954 REVISION HMI: 3.15.32 REVISION PU: 4.1.89 REVISION BDC: 5.4.4

I had it running on a 2.5 installation where it keeps failing. Bundle version 2.5.12. But testing it on a new 3.0.1 installation right now with your updated bundle.

241 │ Active │ 80 │ 3.1.0.202103041018 │ openHAB Add-ons :: Bundles :: SenecHome Binding

Still getting these errors:

2021-04-16 19:32:16.459 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
com.google.gson.JsonSyntaxException: com.google.gson.stream.MalformedJsonException: Expected ':' at line 1 column 1009 path $.PV1.PV_MISS
        at com.google.gson.Gson.fromJson(Gson.java:947) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:897) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:846) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:817) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeApi.getStatistics(SenecHomeApi.java:83) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refreshState(SenecHomeHandler.java:126) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.refreshValue(ExpiringCache.java:101) ~[?:?]
        at org.openhab.core.cache.ExpiringCache.getValue(ExpiringCache.java:72) ~[?:?]
        at org.openhab.binding.senechome.internal.SenecHomeHandler.refresh(SenecHomeHandler.java:120) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: com.google.gson.stream.MalformedJsonException: Expected ':' at line 1 column 1009 path $.PV1.PV_MISS
        at com.google.gson.stream.JsonReader.syntaxError(JsonReader.java:1564) ~[?:?]
        at com.google.gson.stream.JsonReader.doPeek(JsonReader.java:531) ~[?:?]
        at com.google.gson.stream.JsonReader.skipValue(JsonReader.java:1233) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:220) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(ReflectiveTypeAdapterFactory.java:131) ~[?:?]
        at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:222) ~[?:?]
        at com.google.gson.Gson.fromJson(Gson.java:932) ~[?:?]
        ... 14 more

Well path $.PV1.null changed to _path $.PV1.PVMISS.

KorbinianP commented 3 years ago

Hello @Puddingkuchen , could we have a chat / call somewhen this/next weekend? You get the error quite quick, I would like to understand some things. Maybe we can do a debug session? Cheers

KorbinianP commented 3 years ago

Hello,

can this Issue be closed after the Pull request got merged? Cheers, Korbinian

ralfellner commented 3 years ago

Hello @KorbinianP,

thanks for merging the fix. The issue can be closed.

Best regards, Ralf