Gardena Binding throws connection errors and seems to break some bindings

Add-ons Bindings
1

After one or two days Gardena binding drops connection due to a timeout and seems to reconnect after some minutes. Then it queries gardena stuff and drops connection again. This behavior repeats after some minutes. When this happens some bindings (Kodi, exec) stop working.

Log excerpt:

2022-10-18 16:02:59.451 [TRACE] [rdena.internal.GardenaSmartWebSocket] - Sending ping (Gardena_Account-My Garden)
2022-10-18 16:02:59.498 [TRACE] [rdena.internal.GardenaSmartWebSocket] - Pong received (Gardena_Account-My Garden)
2022-10-18 16:04:05.473 [INFO ] [org.openhab.core.model.script.Test  ] - Kodi Wohnzimmer OFFLINE
2022-10-18 16:05:29.515 [DEBUG] [rdena.internal.GardenaSmartWebSocket] - Gardena Webservice error (Gardena_Account-My Garden)
org.eclipse.jetty.websocket.api.CloseException: java.util.concurrent.TimeoutException: Idle timeout expired: 150010/150000 ms
	at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onReadTimeout(AbstractWebSocketConnection.java:564) ~[?:?]
	at org.eclipse.jetty.io.AbstractConnection.onFillInterestedFailed(AbstractConnection.java:172) ~[?:?]
	at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillInterestedFailed(AbstractWebSocketConnection.java:539) ~[?:?]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.failed(AbstractConnection.java:317) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.onFail(FillInterest.java:140) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillableFail(SslConnection.java:591) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection.onFillInterestedFailed(SslConnection.java:419) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$2.failed(SslConnection.java:170) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.onFail(FillInterest.java:140) ~[?:?]
	at org.eclipse.jetty.io.AbstractEndPoint.onIdleExpired(AbstractEndPoint.java:407) ~[?:?]
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) ~[?:?]
	at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [?:?]
	at java.util.concurrent.FutureTask.run(Unknown Source) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
	at java.lang.Thread.run(Unknown Source) [?:?]
Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 150010/150000 ms
	... 8 more
2022-10-18 16:05:29.515 [INFO ] [ng.gardena.internal.GardenaSmartImpl] - Restarting GardenaSmart Webservice (Gardena_Account-My Garden)
2022-10-18 16:05:29.515 [DEBUG] [rdena.internal.GardenaSmartWebSocket] - Closing Gardena Webservice (Gardena_Account-My Garden)
2022-10-18 16:05:32.531 [TRACE] [ng.gardena.internal.GardenaSmartImpl] - >>> POST https://api.smart.gardena.dev/v1/websocket, data: {"data":{"id":"wsreq-f6e76a6e-a94a-4f9a-bd1d-fd3140002b08","type":"WEBSOCKET","attributes":{"locationId":"f6e76a6e-a94a-4f9a-bd1d-fd3140002b08"}}}
2022-10-18 16:05:32.531 [DEBUG] [ng.gardena.internal.GardenaSmartImpl] - Gardena API token valid
2022-10-18 16:05:32.531 [DEBUG] [ng.gardena.internal.GardenaSmartImpl] - Token expiration: accessToken: 2022-10-19T07:37:31.922166900+02:00[Europe/Berlin], refreshToken: 2022-10-28T07:36:42.922166900+02:00[Europe/Berlin]
2022-10-18 16:05:33.046 [TRACE] [ng.gardena.internal.GardenaSmartImpl] - <<< status:201, {"data":{"id":"cd03463b-c53a-479f-abc6-ea9883ab8e00","type":"WEBSOCKET","attributes":{"validity":10,"url":"wss://ws-iapi.smart.gardena.dev/v1?auth=AQIDAHh1xv34zg4SXXwt0VuklW2lTBuEFVUaFOVFe1NziiQDMQGtnlpSEvfXkEENfSyb_Pl3AAAAfjB8BgkqhkiG9w0BBwagbzBtAgEAMGgGCSqGSIb3DQEHATAeBglghkgBZQMEAS4wEQQMYYVpdrLwJu-PzW5dAgEQgDvFWW5GGBfCPmDalMbmsgrGzdpQLege9orIu2Xc-v4Oa7QEOvsnf3mjsJfADHTGWc0_qAVcrJZejd5_gw%3D%3D%3Aeh5ReTmq4wJ68cTRj-Vv_Mg8ZVQBCB3eKiNZL49qLFqlUrlblvvFJVkk1tBrw70pF8xU9uCRAviyjMuRaNcQV5Kw7BK-d5D0-0jTaeQuQ2d3RBRL5fGu2mTewgt9BtRIk9eHlw1ZYiFz4sayUAOwtUG6WEtuTJh60AcEVx2xv7VnGYoQeSWRb1qW9LXhjeg97Fi8j_1yBU5WjVIcZ2ZURgVChj3hJHb4fRcsEUpyoTYBaTTT2h2k2jnIuNvdUomrhzlEYGA9momuKjqQK4Ab00FX3RDmIa63gG_ZFTTaNnXsGToJmmylLXAenTJF-MA-ZAqi3K1rQaTp-eOTN8HSjngCbyiqGv-3zuwrTDTNCkDAnDrAR4xHgvPXXzYVEMq8DOU2euKblawYj6iSDZJDOUWNwhExP8dNx4luDj1fYBonXcvGplsyauP7GGTHCL0wHjhuLirSreRibzZtByVWhzkH_BuxFQn_BGN89x03tn_38TUAKRSGzbrDmhdSQultzQanSLwPnr4pRaJS2XEvLOb1atYUqtq-uSucoi-twHFYBCcNd_zqlgN4Z44410ELYE8OIJRvHqsj3q0NCl45f31UHqoeIgN8FqeO6ihmJKkyHA3Js7GLtCSOehCcsFri17Vs9pmwRDfuVQhmWiiujsr8vwifl6ddViUKlCeJNG1YIz64fFCaj1efnbHz_DItWpDK-Qp-XbLUhZaAZqp7OXXCW53Gh5ivasGFudnZOHNhibdbFhUV4q-Wx1pJBNiE0MCPtPvTEH-ndnXUchQnjP9yp7IizLbzokqos0jYq5eUP48QDMsP6d1KpRuNWwzHDJdz5qjHE7lJLAYY8FJ6H9Jzt4oWeLv3Nbk1MC-1UtachPGVWCq_FCqFq5_mt6w878nhcO9Efb7O8Z-1xBD2zJmcnLTWGfuU2VVFukADQhHvyXqdKQ1VBoMKJiGVA2ruSLcIZuVndW77v1QuqrDCzX_qUOg0no5s3CR3GhvSDAuf5PdAtjiJRe_QxY6Gr88wApQcGX9croFjLpKfrMF0TlI_LCXC7TbekXpJR96Vcz8P3jeBDR-DdYq6eC9RY2hkajlESouGnOsGYgZWa6eVFWuR2XZgxY_X-uK1VbTxcbe_ChY0B0YzGVH1flWsxYpnIgbhyI07I9NQfxlZRaXHGO7SL_tPu4RT3QwPbTstGdGBhnOW_Z--37FWtC4ohETy8Q5DIV7QMEB4QJsfeGLR3AlTFbQTSpxGR3IQVBhxWkI9SLBHbLjsRSLgPhO4MpaaIQ_Nsi0dsVr6Ef1JXvSfKH8P-a1STxw4a99c-c6W2YCyeJX3AHzajvluOf7ygMIHSiYStfYpBpN3Kw7CWvbVghQkMVmtS6k5EHfOeDmCMA9Q4QTpLIoG-BqmFI_v8mtHSv68Y857qNjGD9_jkJpjO54mskWo-ary8INGX5jS6UKrD0TyiNGHNI2sCGnQeiIVBXnrgje93hIGzDkc6XCzPXhxLpkeO6m5EApGdDLSER3rlvcAnc7kZuo2mWAce3HLd9cmJz4R3PCK6wngRnOXbs5rFBIrDx9izQ-PJnzWuf4dk3eGEkYw0pzPBmE2O5iVutMVY9zdpIkYy_HZSaZjuX4ZO8IeCuQT7sXsqHwXprEtZ7vlDTsKU38qbA1HHrUxGvdiA2aBvT8h03qwxEqaLMGFTqAsDXBKLIILK3Rt1zo62lTZ_9I-55deRNEmF1T0pKyPjMZT3g%3D%3D%3AZELWTpvzayY3A3wh"}}}
2022-10-18 16:05:33.046 [DEBUG] [rdena.internal.GardenaSmartWebSocket] - Reconnecting to Gardena Webservice (Gardena_Account-My Garden)
2022-10-18 16:05:33.328 [DEBUG] [rdena.internal.GardenaSmartWebSocket] - Connected to Gardena Webservice (Gardena_Account-My Garden)
2022-10-18 16:05:33.328 [DEBUG] [rdena.internal.GardenaSmartWebSocket] - Connection to Gardena Webservice was closed (Gardena_Account-My Garden): code: 1001, reason: java.util.concurrent.TimeoutException: Idle timeout expired: 150010/150000 ms
2022-10-18 16:05:33.328 [INFO ] [ng.gardena.internal.GardenaSmartImpl] - Restarting GardenaSmart Webservice (Gardena_Account-My Garden)
2022-10-18 16:05:33.328 [DEBUG] [rdena.internal.GardenaSmartWebSocket] - Closing Gardena Webservice (Gardena_Account-My Garden)
2022-10-18 16:05:33.390 [DEBUG] [rdena.internal.GardenaSmartWebSocket] - Connection to Gardena Webservice was closed (Gardena_Account-My Garden): code: 1000, reason: null
2022-10-18 16:05:36.331 [TRACE] [ng.gardena.internal.GardenaSmartImpl] - >>> POST https://api.smart.gardena.dev/v1/websocket, data: {"data":{"id":"wsreq-f6e76a6e-a94a-4f9a-bd1d-fd3140002b08","type":"WEBSOCKET","attributes":{"locationId":"f6e76a6e-a94a-4f9a-bd1d-fd3140002b08"}}}
2022-10-18 16:05:36.331 [DEBUG] [ng.gardena.internal.GardenaSmartImpl] - Gardena API token valid
2022-10-18 16:05:36.331 [DEBUG] [ng.gardena.internal.GardenaSmartImpl] - Token expiration: accessToken: 2022-10-19T07:37:31.922166900+02:00[Europe/Berlin], refreshToken: 2022-10-28T07:36:42.922166900+02:00[Europe/Berlin]
2022-10-18 16:05:36.659 [TRACE] [ng.gardena.internal.GardenaSmartImpl] - <<< status:201, {"data":{"id":"28bedc10-b905-470b-b3cd-be7b2517abbd","type":"WEBSOCKET","attributes":{"validity":10,"url":"wss://ws-iapi.smart.gardena.dev/v1?auth=AQIDAHh1xv34zg4SXXwt0VuklW2lTBuEFVUaFOVFe1NziiQDMQEIK7fYHGf9EjavL1n4ZvTOAAAAfjB8BgkqhkiG9w0BBwagbzBtAgEAMGgGCSqGSIb3DQEHATAeBglghkgBZQMEAS4wEQQM1HWlrq-5xVu9OmPpAgEQgDtirTZGcXwMXmZatVgSQGiDHlYqUfvcWv2fx1iDbqU7JCIoa8d94dcN06amFQ8WznLn9OpY99gQsKaYJA%3D%3D%3AdxXGvbWDVYfzU8clcJXKHCeEwSGSbghE5zdMZicjR9mSNVCsNsPrB6vB2iKJj1gUVzSC1RE2wGodp1r3UoLetpOZTRYKA4hc8qytjctlqEIwQp5k_RSlJsSbtjnKW1sKKbNOlVv9Z-ii-ARdXoNBAnRQrtNlwq7qimftCCmAdzi90OkuRs3bCjIHOrwAgnQzXaFRhznjQlOBwCW2wmxSvA-t9zTBrpRGd6sJE2N2y0QcxaYdHuWAJm3REz8yEMtfO8QeewY5Efd8vfSx8nAcDljNP7i6sV68qq9U20vCHtCsMm6U-18bvCoZ1W9Bxhe0ZUT6_lxEC415dHsuVXN_v6HFyxZeHdgq1ZgCmINs7IjneXXQlXmvT9947Y7BAU25xrxfpTsnc_z1Wti_evMeM0P4bZjVJ3MKD1oGa3tzl-7wxPghjNxIDdbHehoKqy4vvH9FwM0w6bjTDKWqYD_YyP1S57Btx5zM9YdRSSWl-klU4Y8wv4hI5osPin4bSmmmho_mov6dbJKCYidfX7LuMlfI4WECs43vNBDB03qonC8FBs2tg2hIbjM2oCkf-FIBx9DFWdGYZOrp-96P1BfSHyqKIbqc28ILW4DjyTkuePMFi0cQvT2lEpWOjHbU-8j_Awq4S5_x-cV_qWzv0h7nlcUtaY5O2gYsLP2sdlONMwMRxRixuKIM59gh8faArDfLNeuFpQOq0FGzYnjgtf9hzhCoJOZUtO5Elc1Ti86pBDzqJL6hY3Wb0BQJkYbhAsIYgEMG2jCI7PQJa1VxCC6aYIhVJakUhbI3Lg_sE7Zlv81_6pBVHap5u1U-7WYOuSjc2IjHR6SEGbBEba9s2rlnvgTKoQPL7hAeSfSM8R1X4lQg2LLIIDPxXjFDawq2Qnls_qq0kwdRV91mhC74ODsy7KUEOeJc_ARRSkKtx11fSFrL3YuC44lQVUegshRMHuw3Kj5en0MXpDFETU-BW00kGNkh1Kd32dMVKVCNVFFiZscLdrpEb3QJ4OeJ-Sc6msd8FFOIPJZUDX0H38KQ7AvXgWLWgoB3h1gROPk1kQd0CkrCG5l0pJQxx4SodGT0Hpm-a1lFKh47QW2au3a-PPMxfrSB9Cnc8WVvsGscp61f274ItrxbUBqg29PJp35F5CEpihJ85jKJitls-I73HOBMUNw8IIq7JDknl6KklXm1VIMbRgDfhYnigprup9_eoa89XEVgsP5o6lPnBg79Ih7OYG0ziWC47XG3a3eIVTvbCnbaVYmCgPn8KQDSw9QY2nnrBHk9MNwRm7erKIg6J-ns3DjTLun_ALQw0Tmpj4KqpwbmclpAyhdVARVtTvYPebdgSpfd_Kg0CHtyezSbFmFAIHoXNmwfZYgery0imGRjHKMHlylv8Qw8cZ1OroE1yNUje7DooFvBqIQNF-fwyoxsJxq6UUbyV0CGmFVMN9qVzYACZrL6BKlFgAZFEMjkDPAUWELj8QsMmNjJpsi30wzEEYBMiNvLK2Kxrs5Y2rbTwRtNrGckSdqpth0pdcMMjPH0GFQTOl0x6Q5c6ORfE_0eAD4C6R-rGqAfSrOeP7uuWDUD1voqOYF9thhO4s3zWud5efYAunz3-_BYdyrMqWUlFw0Rvgynf8M82Ww8vJMxbSkHMdh3uusW7WYUSpAybK5lrek0n1go5KDowQ9CIuT3SiEBOh3h9jEpTXH0C7pX55gdthqu7TvBVZ3TrmxZorOTuttWrqM5dA%3D%3D%3AoS79-vRPmZHUHvvT"}}}
2022-10-18 16:05:36.659 [DEBUG] [rdena.internal.GardenaSmartWebSocket] - Reconnecting to Gardena Webservice (Gardena_Account-My Garden)
2022-10-18 16:05:36.846 [DEBUG] [rdena.internal.GardenaSmartWebSocket] - Connected to Gardena Webservice (Gardena_Account-My Garden)
2022-10-18 16:05:37.924 [TRACE] [rdena.internal.GardenaSmartWebSocket] - <<< event (Gardena_Account-My Garden): {"id":"f6e76a6e-a94a-4f9a-bd1d-fd3140002b08","type":"LOCATION","relationships":{"devices":{"data":[{"id":"c6773f14-d19a-48d4-8db4-179679923202","type":"DEVICE"},{"id":"d873f9cd-befd-466c-a7a3-c025f153df3b","type":"DEVICE"}]}},"attributes":{"name":"GARDENA smart Garden"}}
2022-10-18 16:05:37.924 [TRACE] [rdena.internal.GardenaSmartWebSocket] - <<< event (Gardena_Account-My Garden): {"id":"c6773f14-d19a-48d4-8db4-179679923202","type":"DEVICE","relationships":{"location":{"data":{"id":"f6e76a6e-a94a-4f9a-bd1d-fd3140002b08","type":"LOCATION"}},"services":{"data":[{"id":"c6773f14-d19a-48d4-8db4-179679923202","type":"VALVE_SET"},{"id":"c6773f14-d19a-48d4-8db4-179679923202:1","type":"VALVE"},{"id":"c6773f14-d19a-48d4-8db4-179679923202:2","type":"VALVE"},{"id":"c6773f14-d19a-48d4-8db4-179679923202:3","type":"VALVE"},{"id":"c6773f14-d19a-48d4-8db4-179679923202:4","type":"VALVE"},{"id":"c6773f14-d19a-48d4-8db4-179679923202:5","type":"VALVE"},{"id":"c6773f14-d19a-48d4-8db4-179679923202:6","type":"VALVE"},{"id":"c6773f14-d19a-48d4-8db4-179679923202","type":"COMMON"}]}}}
2022-10-18 16:05:37.924 [TRACE] [rdena.internal.GardenaSmartWebSocket] - <<< event (Gardena_Account-My Garden): {"id":"d873f9cd-befd-466c-a7a3-c025f153df3b","type":"DEVICE","relationships":{"location":{"data":{"id":"f6e76a6e-a94a-4f9a-bd1d-fd3140002b08","type":"LOCATION"}},"services":{"data":[{"id":"d873f9cd-befd-466c-a7a3-c025f153df3b","type":"SENSOR"},{"id":"d873f9cd-befd-466c-a7a3-c025f153df3b","type":"COMMON"}]}}}
2022-10-18 16:05:37.940 [TRACE] [rdena.internal.GardenaSmartWebSocket] - <<< event (Gardena_Account-My Garden): {"id":"c6773f14-d19a-48d4-8db4-179679923202","type":"VALVE_SET","relationships":{"device":{"data":{"id":"c6773f14-d19a-48d4-8db4-179679923202","type":"DEVICE"}}},"attributes":{"state":{"value":"OK","timestamp":"2022-09-13T14:47:06.188+00:00"},"lastErrorCode":{"value":"NO_MESSAGE","timestamp":"2022-09-13T14:47:06.188+00:00"}}}
2022-10-18 16:05:37.971 [TRACE] [rdena.internal.GardenaSmartWebSocket] - <<< event (Gardena_Account-My Garden): {"id":"c6773f14-d19a-48d4-8db4-179679923202:1","type":"VALVE","relationships":{"device":{"data":{"id":"c6773f14-d19a-48d4-8db4-179679923202","type":"DEVICE"}}},"attributes":{"name":{"value":"BV Seite"},"activity":{"value":"CLOSED","timestamp":"2022-10-16T05:32:02.989+00:00"},"state":{"value":"OK","timestamp":"2022-10-10T19:06:08.082+00:00"},"lastErrorCode":{"value":"NO_MESSAGE","timestamp":"2022-10-10T19:06:08.082+00:00"}}}
2022-10-18 16:05:37.987 [TRACE] [rdena.internal.GardenaSmartWebSocket] - <<< event (Gardena_Account-My Garden): {"id":"c6773f14-d19a-48d4-8db4-179679923202:2","type":"VALVE","relationships":{"device":{"data":{"id":"c6773f14-d19a-48d4-8db4-179679923202","type":"DEVICE"}}},"attributes":{"name":{"value":"BV Wiese"},"activity":{"value":"CLOSED","timestamp":"2022-10-16T05:32:04.714+00:00"},"state":{"value":"OK","timestamp":"2022-10-15T18:25:37.164+00:00"},"lastErrorCode":{"value":"NO_MESSAGE","timestamp":"2022-10-15T18:25:37.164+00:00"}}}
2022-10-18 16:05:37.987 [TRACE] [rdena.internal.GardenaSmartWebSocket] - <<< event (Gardena_Account-My Garden): {"id":"c6773f14-d19a-48d4-8db4-179679923202:3","type":"VALVE","relationships":{"device":{"data":{"id":"c6773f14-d19a-48d4-8db4-179679923202","type":"DEVICE"}}},"attributes":{"name":{"value":"BV links"},"activity":{"value":"CLOSED","timestamp":"2022-10-16T05:32:03.855+00:00"},"state":{"value":"OK","timestamp":"2022-10-15T18:00:22.082+00:00"},"lastErrorCode":{"value":"NO_MESSAGE","timestamp":"2022-10-15T18:00:22.082+00:00"}}}
2022-10-18 16:05:38.018 [TRACE] [rdena.internal.GardenaSmartWebSocket] - <<< event (Gardena_Account-My Garden): {"id":"c6773f14-d19a-48d4-8db4-179679923202:4","type":"VALVE","relationships":{"device":{"data":{"id":"c6773f14-d19a-48d4-8db4-179679923202","type":"DEVICE"}}},"attributes":{"name":{"value":"BV DripSystem"},"activity":{"value":"CLOSED","timestamp":"2022-10-16T05:32:05.599+00:00"},"state":{"value":"OK","timestamp":"2022-10-10T18:50:53.071+00:00"},"lastErrorCode":{"value":"NO_MESSAGE","timestamp":"2022-10-10T18:50:53.071+00:00"}}}
2022-10-18 16:05:38.018 [TRACE] [rdena.internal.GardenaSmartWebSocket] - <<< event (Gardena_Account-My Garden): {"id":"c6773f14-d19a-48d4-8db4-179679923202:5","type":"VALVE","relationships":{"device":{"data":{"id":"c6773f14-d19a-48d4-8db4-179679923202","type":"DEVICE"}}},"attributes":{"name":{"value":"BV Vorgarten"},"activity":{"value":"CLOSED","timestamp":"2022-10-16T05:32:02.110+00:00"},"state":{"value":"OK","timestamp":"2022-10-10T19:21:23.009+00:00"},"lastErrorCode":{"value":"NO_MESSAGE","timestamp":"2022-10-10T19:21:23.009+00:00"}}}
2022-10-18 16:05:38.034 [TRACE] [rdena.internal.GardenaSmartWebSocket] - <<< event (Gardena_Account-My Garden): {"id":"c6773f14-d19a-48d4-8db4-179679923202:6","type":"VALVE","relationships":{"device":{"data":{"id":"c6773f14-d19a-48d4-8db4-179679923202","type":"DEVICE"}}},"attributes":{"name":{"value":"Valve 6"},"activity":{"value":"CLOSED","timestamp":"2022-09-13T14:47:05.701+00:00"},"state":{"value":"UNAVAILABLE","timestamp":"2022-09-13T14:47:07.449+00:00"},"lastErrorCode":{"value":"NO_MESSAGE","timestamp":"2022-09-13T14:47:05.896+00:00"}}}
2022-10-18 16:05:38.065 [TRACE] [rdena.internal.GardenaSmartWebSocket] - <<< event (Gardena_Account-My Garden): {"id":"c6773f14-d19a-48d4-8db4-179679923202","type":"COMMON","relationships":{"device":{"data":{"id":"c6773f14-d19a-48d4-8db4-179679923202","type":"DEVICE"}}},"attributes":{"name":{"value":"Beregnungssteuerung"},"batteryState":{"value":"NO_BATTERY"},"rfLinkLevel":{"value":80,"timestamp":"2022-10-18T13:29:43.996+00:00"},"serial":{"value":"00063502"},"modelType":{"value":"GARDENA smart Irrigation Control"},"rfLinkState":{"value":"ONLINE"}}}
2022-10-18 16:05:38.096 [TRACE] [rdena.internal.GardenaSmartWebSocket] - <<< event (Gardena_Account-My Garden): {"id":"d873f9cd-befd-466c-a7a3-c025f153df3b","type":"SENSOR","relationships":{"device":{"data":{"id":"d873f9cd-befd-466c-a7a3-c025f153df3b","type":"DEVICE"}}},"attributes":{"soilHumidity":{"value":70,"timestamp":"2022-10-18T13:26:41.701+00:00"},"soilTemperature":{"value":16,"timestamp":"2022-10-18T13:26:41.900+00:00"}}}
2022-10-18 16:05:38.112 [TRACE] [rdena.internal.GardenaSmartWebSocket] - <<< event (Gardena_Account-My Garden): {"id":"d873f9cd-befd-466c-a7a3-c025f153df3b","type":"COMMON","relationships":{"device":{"data":{"id":"d873f9cd-befd-466c-a7a3-c025f153df3b","type":"DEVICE"}}},"attributes":{"name":{"value":"Feuchtesensor"},"batteryLevel":{"value":83,"timestamp":"2022-10-02T20:26:19.586+00:00"},"batteryState":{"value":"OK","timestamp":"2022-10-02T20:26:19.586+00:00"},"rfLinkLevel":{"value":50,"timestamp":"2022-10-18T13:26:41.868+00:00"},"serial":{"value":"00089857"},"modelType":{"value":"GARDENA smart Sensor"},"rfLinkState":{"value":"ONLINE"}}}
2022-10-18 16:08:08.121 [DEBUG] [rdena.internal.GardenaSmartWebSocket] - Gardena Webservice error (Gardena_Account-My Garden)
org.eclipse.jetty.websocket.api.CloseException: java.util.concurrent.TimeoutException: Idle timeout expired: 150003/150000 ms
	at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onReadTimeout(AbstractWebSocketConnection.java:564) ~[?:?]
	at org.eclipse.jetty.io.AbstractConnection.onFillInterestedFailed(AbstractConnection.java:172) ~[?:?]
	at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillInterestedFailed(AbstractWebSocketConnection.java:539) ~[?:?]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.failed(AbstractConnection.java:317) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.onFail(FillInterest.java:140) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillableFail(SslConnection.java:591) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection.onFillInterestedFailed(SslConnection.java:419) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$2.failed(SslConnection.java:170) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.onFail(FillInterest.java:140) ~[?:?]
	at org.eclipse.jetty.io.AbstractEndPoint.onIdleExpired(AbstractEndPoint.java:407) ~[?:?]
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) ~[?:?]
	at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [?:?]
	at java.util.concurrent.FutureTask.run(Unknown Source) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
	at java.lang.Thread.run(Unknown Source) [?:?]
Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 150003/150000 ms
	... 8 more
2022-10-18 16:08:08.121 [INFO ] [ng.gardena.internal.GardenaSmartImpl] - Restarting GardenaSmart Webservice (Gardena_Account-My Garden)
2022-10-18 16:08:08.121 [DEBUG] [rdena.internal.GardenaSmartWebSocket] - Closing Gardena Webservice (Gardena_Account-My Garden)
2022-10-18 16:08:11.122 [TRACE] [ng.gardena.internal.GardenaSmartImpl] - >>> POST https://api.smart.gardena.dev/v1/websocket, data: {"data":{"id":"wsreq-f6e76a6e-a94a-4f9a-bd1d-fd3140002b08","type":"WEBSOCKET","attributes":{"locationId":"f6e76a6e-a94a-4f9a-bd1d-fd3140002b08"}}}
2022-10-18 16:08:11.122 [DEBUG] [ng.gardena.internal.GardenaSmartImpl] - Gardena API token valid

After restarting openhab service, all is working fine until one or two days, then the same error shows up.

openHAB 3.4.0.M2 on Windows Server 2019

Any hints, how to solve these connection errors?
Many thanks in advance, Thomas

2

Can you please be more specific? e.g. logs from those bindings?

3

Hi Andrew!

Thanks for responding to this topic!

First I try to explain my findings:

In my OH3 setup there are some exec binding items linked to some computers showing the computers on/off status, respectively power them on or off.

Another binding used is the kodi binding, which only is used to represent the on/off status of a kodi multimedia software installed on a different computer.

Beside these bindings I use the gardena binding to integrate a gardena smart gateway with 5 valves and a gardena humidity sensor.

First I noticed the kodi and exec binding not working anymore, which could be resolved by a restart of the OH3 service. These failures occurred every 1 or 2 days, so I tried to narrow this down. The exec binding, as far as I know, has no option to set the log level to trace or debug, but it has a channel which stores the last execution time of the exec item and when the problems occur the exec item run command did not fire anymore.

I do not know, if the kodi binding has a trace or debug option, but it stopped to update the status of the kodi software and always showed a communication error, as if kodi would not run, even it was running.

When the problem occurred and I looked at the logs, I saw the gardena binding restarting the communication with the gardena server every 2 or three minutes. So I removed the gardena binding from OH3 the other bindings worked for 7 days without problem. After reinstalling the gardena binding I activated debug and trace logging and found logged gardena webservice errors due to a timeout (see attached openhab log at 2022-10-18 16:08:08.121). After that error the gardena binding seems to try to reconnect approx… every 2 minutes. It connects, queries all item states and errors again.

Please take a look at the attached log files and tell me, if you can guess ort see what’s going wrong here.

Regards, Thomas

events.log (86.1 KB)

(Attachment openhab.log is missing)

5

Unfortunately, new users aren’t allowed to upload files.

I could not attach the logs when responding per mail, because they were to big.

I tried to zip them but zip files get rejected as attachment.

So I zipped the logs to logs.zip and renamed the file to logs.log. Please rename to logs.zip and unpack the logs to read.

Thank you again, Thomas

logs.log (209 KB)

6

@hajeth I am investigating, but it may take some time; it’s hard to see how a potential error in one binding could cause another one to break; but it may be due to interaction with the OH core shared HTTP client; however that is just a guess…

7

The issue seems to be related to the timeout exceptions of the Gardena binding.

Now here OH is working for three days and when I look on the log files there are no timeout errors and the other problematic bindings are working again. All logs I retrieved in OH error states showed this timeouts and the Gardena binding never recovered till OH was restarted.

Do you know, why these timeouts occur and why the Gardena binding seems to hang in this “loop” till OH is restarted?

@AndrewFG If I can do anything to assist you, let me know.

8

Short answer: no …

9

Either that, or maybe thread pool exhaustion?

10

Agreed. And either way, it will be immensely impossible to debug / fix :wink:

11

After 4 days the error occured again, so i did further tests, but not sure if this helps to narrow down anything.
Gardena Binding: timeout error occured, from then this error was logged all 2 or three minutes
at this time:
Kodi binding sees running Kodi instances offline
Exec binding does not execute commands anymore
Network binding does not update the state of network devices anymore

I did a thread count when all was working and when the error occured with no significant difference.

I tried to restart the bindings via console and gardena binding hung on initializing.
The other problematic bindings were online after a restart but did not work anymore.

After restarting OH3, all was working as expected

12

Found this thread while investigating why my GardenaSmart web service restarts each 2-3 minute. Reading the post, I possibly also see that this affects annother binding (in my case the RFXCOM-binding stops working now and then without any obvious reason, from having run rock solid for years).
I will however not jump to any conclusions yet before I’ve investigated behaviour and logs in more depth, keep you posted if I find some proof supporting the suspicion that seemingly non-related problems actually are correlated.

13

When it seems there are no updates anymore and other bindings are also blocked. In general it means the binding thread pool is blocked. possibly on a deadlock. To get the thread info you can issue the following command on the Console :

threads --monitors --locks

This will give a list of threads and hopefully gives an insight in what threads are blocked.

2 Likes
14

^
@hajeth if you get the same error again, could you please post the list of threads as mentioned above?

@hajeth can you also please tell us the value of the connectionTimeout configuration parameter of your bridge?

15

As @hilbrand surmises, the problem may be due to a lock up of the OH threadpool.

The Gardena binding opens a websocket to the server with a maximum idle timeout of 150 seconds (150000 mS), which is what you see in your original crash dump posted above, but this timeout should NEVER occur since the binding has a scheduled task to send a refresh ping to the server every 120 seconds. Therefore this error means that the OH thread pool is not firing the refresh ping task.

THEREFORE I am now wondering if the fault is actually NOT in the Gardena binding. Instead I wonder if one of your other bindings is locking up the OH threadpool?

i.e. maybe it is not the Gardena causing the other bindings to fail, but rather one of the other bindings causing the Gardena to fail.

This hypothesis would explain why I do not see your issue on my system. As I don’t have any of the other bindings that you mention.

You may need to try disabling each of the suspicious bindings in turn, to try to eliminate which is really causing the error…

EDIT: so can you please post a full list of all the bindings in your system? Even the ones which are apparently working OK, because even if they do work OK, they may be coincidentally locking up the OH threadPool.

EDIT2: do you by any chance have any OH unofficial bindings, or SNAPSHOT bindings installed?

16

Why should it not occur? The scheduler does not kill the task when it runs beyond the time the next scheduled task should run. It just waits for it to finish, and then will run the next task. Or am I not understanding what you mean?

17

I think so :wink:

The Gardena binding opens a WebSocket connection to the remote server. The WebSocket has an idle timeout of 150 seconds, so if there is no traffic within 150 seconds the crash that the OP mentions will occur. However to prevent such idle time out, the binding has a scheduled task that runs every 120 seconds and sends a ping to the server (and the server replies with a pong). So normally the scheduled task prevents the idle timeout from triggering. But if OH does not fire the scheduled task, the idle timeout does occur (and crashes the binding, which admittedly it should not do…)

EDIT: this is how it should look on a working system (ping/pong every 120 seconds, so no Idle timeout after 150 seconds…)

2022-10-27 19:18:12.795 [DEBUG] [ternal.handler.GardenaAccountHandler] - Initializing Gardena account 'e7bdbc22aa'
...
2022-10-27 19:19:15.031 [TRACE] [rdena.internal.GardenaSmartWebSocket] - Sending ping (e7bdbc22aa-My Garden)
2022-10-27 19:19:15.075 [TRACE] [rdena.internal.GardenaSmartWebSocket] - Pong received (e7bdbc22aa-My Garden)
...
2022-10-27 19:21:15.036 [TRACE] [rdena.internal.GardenaSmartWebSocket] - Sending ping (e7bdbc22aa-My Garden)
2022-10-27 19:21:15.075 [TRACE] [rdena.internal.GardenaSmartWebSocket] - Pong received (e7bdbc22aa-My Garden)
18

@hajeth from your original logs, I am pretty sure that it is your Kodi binding which is causing the problem. See log excerpt below.

2022-10-18 15:58:59.474 [TRACE] [rdena.internal.GardenaSmartWebSocket] - Pong received (Gardena_Account-My Garden)
2022-10-18 16:00:59.439 [TRACE] [rdena.internal.GardenaSmartWebSocket] - Sending ping (Gardena_Account-My Garden)
2022-10-18 16:00:59.486 [TRACE] [rdena.internal.GardenaSmartWebSocket] - Pong received (Gardena_Account-My Garden)
2022-10-18 16:02:59.451 [TRACE] [rdena.internal.GardenaSmartWebSocket] - Sending ping (Gardena_Account-My Garden)
2022-10-18 16:02:59.498 [TRACE] [rdena.internal.GardenaSmartWebSocket] - Pong received (Gardena_Account-My Garden)
2022-10-18 16:04:05.473 [INFO ] [org.openhab.core.model.script.Test  ] - Kodi Wohnzimmer OFFLINE
2022-10-18 16:05:29.515 [DEBUG] [rdena.internal.GardenaSmartWebSocket] - Gardena Webservice error (Gardena_Account-My Garden)
org.eclipse.jetty.websocket.api.CloseException: java.util.concurrent.TimeoutException: Idle timeout expired: 150010/150000 ms
	at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onReadTimeout(AbstractWebSocketConnection.java:564) ~[?:?]
	at org.eclipse.jetty.io.AbstractConnection.onFillInterestedFailed(AbstractConnection.java:172) ~[?:?]
	at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillInterestedFailed(AbstractWebSocketConnection.java:539) ~[?:?]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.failed(AbstractConnection.java:317) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.onFail(FillInterest.java:140) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillableFail(SslConnection.java:591) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection.onFillInterestedFailed(SslConnection.java:419) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection$2.failed(SslConnection.java:170) ~[?:?]
	at org.eclipse.jetty.io.FillInterest.onFail(FillInterest.java:140) ~[?:?]
	at org.eclipse.jetty.io.AbstractEndPoint.onIdleExpired(AbstractEndPoint.java:407) ~[?:?]
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) ~[?:?]
	at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [?:?]
	at java.util.concurrent.FutureTask.run(Unknown Source) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
	at java.lang.Thread.run(Unknown Source) [?:?]
Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 150010/150000 ms
	... 8 more
2022-10-18 16:05:29.515 [INFO ] [ng.gardena.internal.GardenaSmartImpl] - Restarting GardenaSmart Webservice (Gardena_Account-My Garden)
2022-10-18 16:05:29.515 [DEBUG] [rdena.internal.GardenaSmartWebSocket] - Closing Gardena Webservice (Gardena_Account-My Garden)
19

I am away for some days and will be back at Saturday.
I asume the error is occuring til Saturday, because i restarted OH 3 days ago.

I will check for locked threads.
The timeout setting of the gardena binding should be at default - i do not remember tonhave changed this, but will check at Saturday.

@AndrewFG: Not sure, if the problem relies to the Kodi Binding. The line of the log you mentioned only states, that the device running Kodi was shut down. Other logs at the time of gardena binding timeouts did not show anything from Kodi binding.

Meanwhile I tried to set all related bindings to tracelogging, maybe this brings up some nes.

20

@hajeth the essence of the problem is the above three lines.

  • 16:02:59 : OH core scheduler starts the Gardena binding ping/pong task
  • 16:04:05 : Kodi binding goes offline
  • 16:04:59 : OH core scheduler FAILS to start the Gardena ping/pong task
  • 16:05:29 : websocket connection times out due to lack of ping/pong
21

I know what you mean, but i did not see any log entry from the Kodi binding other times the Gardena binding showed the timeouts. In the log you got there was an entry of the Kodi binding before the error occured. But other times, the ping/pong timed out(=other logs from other days the error occured), there was no entry from Kodi binding before the connection timed out. Now I’m collecting trace logs of the Kodi binding too, i will keep you informed, when i am back tomorrow.