search

nibi79 / worxlandroid

openHAB Binding for Worx Landroid
57 stars 20 forks source link

HTTP protocol violation #62

Closed Scuby4ever closed 1 year ago

Scuby4ever commented 2 years ago

Hi, since some days I am experiencing the following error all the time in the log. Does anybody know if there were changes on the API ?

[ERROR] [ternal.webapi.WorxLandroidWebApiImpl] - Error connecting to Worx Landroid WebApi! Error = org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header

int5749 commented 2 years ago

Hi, sorry for late reply. Does this issue still exist on your end? I don't see this on my end.

mitch-geht-ab commented 2 years ago

Hi, have the same problem, but since "2022-01-13 00:41:35.335". Changed nothing on OH2. Have rebooted the whole systems, what fixed the problem for more or less 1h. Suspicious!

Have OH 2.5.12-1 running on Deb10. With following Binding: 2.5.3.202009031253 │ openHAB Add-ons :: Bundles :: WorxLandroid Binding

int5749 commented 2 years ago

Hi, I had some issues yesterday (which was Jan 13th) but they have been gone late afternoon, so I assume it was on Worx/Landroid End. All is working fine and Bridge is back online, but I'm on most latest Version openHAB 3.2.0 with OH 3 Binding installed. OH3 Binding is based on latest OH2.x Binding, "just" adopted. So there shouldn't be any difference. Anything else changed on your end?

mitch-geht-ab commented 2 years ago

Hi @int5749

Anything else changed on your end?

No, nothing. Haven't touched my OH2 setup for days.

Could it be, that Worx changed sth. in her API, makes it necessary to send a WWW-Auth Header at least once in a hour? Because restarting the server fixed it for 1h.

LandroidLastUpdateOnlineStatus, what is updated every refreshStatusInterval (120sec. in my config), worked for 1h and stopped then again. Obvious, after bridge issen't working anymore.

Or is the refreshStatusInterval with 120sec. to high?

2022-01-15 16:12:43.713 [ERROR] [id.internal.WorxLandroidMowerHandler] - RefreshStatusRunnable 20xxxxxxxxx: Unknown error
org.openhab.binding.worxlandroid.internal.webapi.WebApiException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
        at org.openhab.binding.worxlandroid.internal.webapi.request.WebApiRequest.callWebApi(WebApiRequest.java:122) ~[bundleFile:?]
        at org.openhab.binding.worxlandroid.internal.webapi.request.WebApiRequest.callWebApiGet(WebApiRequest.java:79) ~[bundleFile:?]
        at org.openhab.binding.worxlandroid.internal.webapi.request.ProductItemsRequest.call(ProductItemsRequest.java:46) ~[bundleFile:?]
        at org.openhab.binding.worxlandroid.internal.webapi.WorxLandroidWebApiImpl.retrieveUserDevices(WorxLandroidWebApiImpl.java:103) ~[bundleFile:?]
        at org.openhab.binding.worxlandroid.internal.WorxLandroidMowerHandler$1.run(WorxLandroidMowerHandler.java:108) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_161]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_161]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_161]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_161]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_161]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_161]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
Caused by: java.util.concurrent.ExecutionException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
        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.worxlandroid.internal.webapi.request.WebApiRequest.callWebApi(WebApiRequest.java:92) ~[bundleFile:?]
        ... 11 more
Caused by: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
        at org.eclipse.jetty.client.AuthenticationProtocolHandler$AuthenticationListener.onComplete(AuthenticationProtocolHandler.java:163) ~[?:?]
        at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:198) ~[?:?]
        at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:190) ~[?:?]
        at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:444) ~[?:?]
        at org.eclipse.jetty.client.HttpReceiver.responseSuccess(HttpReceiver.java:390) ~[?:?]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:316) ~[?:?]
        at org.eclipse.jetty.http.HttpParser.parseFields(HttpParser.java:1139) ~[?:?]
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1498) ~[?:?]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:172) ~[?:?]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:135) ~[?:?]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:73) ~[?:?]
        at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:133) ~[?:?]
        at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:154) ~[?:?]
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[?:?]
        at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:426) ~[?:?]
        at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:320) ~[?:?]
        at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:158) ~[?:?]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[?:?]
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) ~[?:?]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) ~[?:?]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) ~[?:?]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) ~[?:?]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) ~[?:?]
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) ~[?:?]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) ~[?:?]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) ~[?:?]
        ... 1 more
int5749 commented 2 years ago

No, Pollingintervall of 120 Sec. shall be fine. I do use

        refreshStatusInterval=120,
        pollingInterval=300

It's still cold outside, so Shaun is still offline and waiting in our garage ;-) But I just activated back on Bridge and Thing, will have a close look if something is going wrong there.

mitch-geht-ab commented 2 years ago

Have enabled TRACE log for worx binding. Stoped and restarted (bundle stop/start) the binding. Doesn't look better.

2022-01-16 09:50:10.875 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - AWS connection closed
2022-01-16 09:50:12.901 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/oauth/token
2022-01-16 09:50:13.354 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: {"token_type":"Bearer","expires_in":3600,"access_token":"***hidden for debug log***","refresh_token":"***hidden for debug log***"}
2022-01-16 09:50:13.355 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/users/me
2022-01-16 09:50:13.425 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: {"id":xxxxxxx,"email":"xxxxxxxx","name":"xxxxx","surname":"xxxxx","user_type":"customer","locale":"en","push_notifications":true,"location":null,"terms_of_use_agreed":true,"marketing_consent":false,"profiling_consent":false,"advertising_consent":null,"country_id":276,"mqtt_endpoint":"a1optpg91s0ydf-ats.iot.eu-west-1.amazonaws.com","actions_on_google_pin_code":null,"created_at":"2020-07-12 10:28:34","updated_at":"2020-07-22 10:10:31"}
2022-01-16 09:50:13.428 [INFO ] [d.internal.WorxLandroidBridgeHandler] - Start retrieving AWS certificate
2022-01-16 09:50:13.429 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/users/certificate
2022-01-16 09:50:13.618 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: {"id":xxxxxx,"pkcs12":"***hidden for debug log***","active":true,"created_at":"2020-07-12 10:59:29","updated_at":"2020-07-12 10:59:29"}
2022-01-16 09:50:13.627 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - AWS certificate loaded to keystore
2022-01-16 09:50:13.628 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - Try to connect to AWS...
2022-01-16 09:50:14.298 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - AWS connection success
2022-01-16 09:50:14.300 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/product-items
2022-01-16 09:50:14.332 [DEBUG] [id.internal.WorxLandroidMowerHandler] - Initializing WorxLandroidMowerHandler for serialNumber 'xxxxxxxxxxxxxxxxxxx'
2022-01-16 09:50:14.332 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/product-items
2022-01-16 09:50:14.381 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: [{"id":xxxxxxx,"product_id":49,"user_id":xxxxxxx,"serial_number":"xxxxxxxxxxxxxxxxxxx","mac_address":"xxxxxxxxxxx","name":"steve","locked":true,"firmware_version":3.26,"firmware_auto_upgrade":true,"push_notifications":true,"sim":null,"push_notifications_level":"notice","test":0,"iot_registered":true,"mqtt_registered":true,"pin_code":"xxxx","registered_at":"2020-07-12 00:00:00","online":false,...]
2022-01-16 09:50:14.383 [DEBUG] [rnal.discovery.MowerDiscoveryService] - Discovered a mower thing with ID 'xxxxxxxxxxxxxxxxxxx'
2022-01-16 09:50:14.461 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: [{"id":xxxxxxx,"product_id":49,"user_id":xxxxxxx,"serial_number":"xxxxxxxxxxxxxxxxxxx","mac_address":"xxxxxxxxxxx","name":"steve","locked":true,"firmware_version":3.26,"firmware_auto_upgrade":true,...]
2022-01-16 09:50:14.474 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/product-items/xxxxxxxxxxxxxxxxxxx/status
2022-01-16 09:50:14.548 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: {}
2022-01-16 09:50:14.549 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - subsribe to topic -> PRM100/xxxxxxxxxxx/commandOut
2022-01-16 09:50:14.551 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - publish topic -> PRM100/xxxxxxxxxxx/commandIn
2022-01-16 09:50:14.552 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - publish message -> {}
2022-01-16 09:50:14.558 [DEBUG] [orxlandroid.internal.mqtt.AWSMessage] - AWS message publishing succeeded
2022-01-16 09:50:14.561 [DEBUG] [id.internal.WorxLandroidMowerHandler] - Initialize thing: Steve::worxlandroid:mower:WorxAPI:xxxxxxxxxxxxxxxxxxx
2022-01-16 09:50:44.561 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/product-items
2022-01-16 09:50:44.659 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: [{"id":xxxxxxx,"product_id":49,"user_id":xxxxxxx,"serial_number":"xxxxxxxxxxxxxxxxxxx","mac_address":"xxxxxxxxxxx","name":"steve","locked":true,"firmware_version":3.26,"firmware_auto_upgrade":true,"push_notifications":true,"sim":null,"push_notifications_level":"notice","test":0,"iot_registered":true,"mqtt_registered":true,"pin_code":"xxxx","registered_at":"2020-07-12 00:00:00","online":false,...]
2022-01-16 09:51:14.561 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - publish topic -> PRM100/xxxxxxxxxxx/commandIn
2022-01-16 09:51:14.561 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - publish message -> {}
2022-01-16 09:51:14.564 [DEBUG] [orxlandroid.internal.mqtt.AWSMessage] - AWS message publishing succeeded
2022-01-16 09:52:35.236 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/product-items
2022-01-16 09:52:35.444 [ERROR] [id.internal.WorxLandroidMowerHandler] - RefreshStatusRunnable xxxxxxxxxxxxxxxxxxx: Unknown error
org.openhab.binding.worxlandroid.internal.webapi.WebApiException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
        at org.openhab.binding.worxlandroid.internal.webapi.request.WebApiRequest.callWebApi(WebApiRequest.java:122) ~[bundleFile:?]
        at org.openhab.binding.worxlandroid.internal.webapi.request.WebApiRequest.callWebApiGet(WebApiRequest.java:79) ~[bundleFile:?]
        at org.openhab.binding.worxlandroid.internal.webapi.request.ProductItemsRequest.call(ProductItemsRequest.java:46) ~[bundleFile:?]
        at org.openhab.binding.worxlandroid.internal.webapi.WorxLandroidWebApiImpl.retrieveUserDevices(WorxLandroidWebApiImpl.java:103) ~[bundleFile:?]
        at org.openhab.binding.worxlandroid.internal.WorxLandroidMowerHandler$1.run(WorxLandroidMowerHandler.java:108) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_161]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_161]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_161]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_161]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_161]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_161]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
Caused by: java.util.concurrent.ExecutionException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
        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.worxlandroid.internal.webapi.request.WebApiRequest.callWebApi(WebApiRequest.java:92) ~[bundleFile:?]
        ... 11 more
Caused by: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
        at org.eclipse.jetty.client.AuthenticationProtocolHandler$AuthenticationListener.onComplete(AuthenticationProtocolHandler.java:163) ~[?:?]
        at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:198) ~[?:?]
        at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:190) ~[?:?]
        at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:444) ~[?:?]
        at org.eclipse.jetty.client.HttpReceiver.responseSuccess(HttpReceiver.java:390) ~[?:?]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:316) ~[?:?]
        at org.eclipse.jetty.http.HttpParser.parseFields(HttpParser.java:1139) ~[?:?]
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1498) ~[?:?]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:172) ~[?:?]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:135) ~[?:?]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:73) ~[?:?]
        at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:133) ~[?:?]
        at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:154) ~[?:?]
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[?:?]
        at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:426) ~[?:?]
        at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:320) ~[?:?]
        at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:158) ~[?:?]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[?:?]
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) ~[?:?]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) ~[?:?]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) ~[?:?]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) ~[?:?]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) ~[?:?]
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) ~[?:?]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) ~[?:?]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) ~[?:?]
        ... 1 more

In generall the binding seeams working beacause of the API connect + dicovering mower + API response (with all my mower information) but RefreshStatusRunnable failed.

maybe @nibi79 has an idea?

unregister and reregister the mower isn't possible because off wintersleep. and logging the REQ, including the header, isn't possible, or is it?

BR mitch

int5749 commented 2 years ago

Please try to uninstall Binding reboot OH and than re-install Binding. I re-call this helps me once back in beginning of 2021.

Cheers Int5749

mitch-geht-ab @.***> schrieb am So. 16. Jan. 2022 um 10:11:

Have enabled TRACE log for worx binding. Stoped and restarted (bundle stop/start) the binding. Doesn't look better.

2022-01-16 09:50:10.875 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - AWS connection closed 2022-01-16 09:50:12.901 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/oauth/token 2022-01-16 https://api.worxlandroid.com/api/v2/oauth/token2022-01-16 09:50:13.354 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: {"token_type":"Bearer","expires_in":3600,"access_token":"hidden for debug log","refresh_token":"hidden for debug log"} 2022-01-16 09:50:13.355 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/users/me 2022-01-16 https://api.worxlandroid.com/api/v2/users/me2022-01-16 09:50:13.425 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: {"id":xxxxxxx,"email":"xxxxxxxx","name":"xxxxx","surname":"xxxxx","user_type":"customer","locale":"en","push_notifications":true,"location":null,"terms_of_use_agreed":true,"marketing_consent":false,"profiling_consent":false,"advertising_consent":null,"country_id":276,"mqtt_endpoint":"a1optpg91s0ydf-ats.iot.eu-west-1.amazonaws.com","actions_on_google_pin_code":null,"created_at":"2020-07-12 10:28:34","updated_at":"2020-07-22 10:10:31"} 2022-01-16 09:50:13.428 [INFO ] [d.internal.WorxLandroidBridgeHandler] - Start retrieving AWS certificate 2022-01-16 09:50:13.429 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/users/certificate 2022-01-16 https://api.worxlandroid.com/api/v2/users/certificate2022-01-16 09:50:13.618 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: {"id":xxxxxx,"pkcs12":"hidden for debug log","active":true,"created_at":"2020-07-12 10:59:29","updated_at":"2020-07-12 10:59:29"} 2022-01-16 09:50:13.627 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - AWS certificate loaded to keystore 2022-01-16 09:50:13.628 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - Try to connect to AWS... 2022-01-16 09:50:14.298 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - AWS connection success 2022-01-16 09:50:14.300 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/product-items 2022-01-16 https://api.worxlandroid.com/api/v2/product-items2022-01-16 09:50:14.332 [DEBUG] [id.internal.WorxLandroidMowerHandler] - Initializing WorxLandroidMowerHandler for serialNumber 'xxxxxxxxxxxxxxxxxxx' 2022-01-16 09:50:14.332 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/product-items 2022-01-16 https://api.worxlandroid.com/api/v2/product-items2022-01-16 09:50:14.381 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: [{"id":401256,"product_id":49,"user_id":xxxxxxx,"serial_number":"xxxxxxxxxxxxxxxxxxx","mac_address":"xxxxxxxxxxx","name":"steve","locked":true,"firmware_version":3.26,"firmware_auto_upgrade":true,"push_notifications":true,"sim":null,"push_notifications_level":"notice","test":0,"iot_registered":true,"mqtt_registered":true,"pin_code":"xxxx","registered_at":"2020-07-12 00:00:00","online":false,...] 2022-01-16 09:50:14.383 [DEBUG] [rnal.discovery.MowerDiscoveryService] - Discovered a mower thing with ID 'xxxxxxxxxxxxxxxxxxx' 2022-01-16 09:50:14.461 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: [{"id":401256,"product_id":49,"user_id":xxxxxxx,"serial_number":"xxxxxxxxxxxxxxxxxxx","mac_address":"xxxxxxxxxxx","name":"steve","locked":true,"firmware_version":3.26,"firmware_auto_upgrade":true,...] 2022-01-16 09:50:14.474 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/product-items/xxxxxxxxxxxxxxxxxxx/status 2022-01-16 https://api.worxlandroid.com/api/v2/product-items/xxxxxxxxxxxxxxxxxxx/status2022-01-16 09:50:14.548 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: {} 2022-01-16 09:50:14.549 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - subsribe to topic -> PRM100/xxxxxxxxxxx/commandOut 2022-01-16 09:50:14.551 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - publish topic -> PRM100/xxxxxxxxxxx/commandIn 2022-01-16 09:50:14.552 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - publish message -> {} 2022-01-16 09:50:14.558 [DEBUG] [orxlandroid.internal.mqtt.AWSMessage] - AWS message publishing succeeded 2022-01-16 09:50:14.561 [DEBUG] [id.internal.WorxLandroidMowerHandler] - Initialize thing: Steve::worxlandroid:mower:WorxAPI:xxxxxxxxxxxxxxxxxxx 2022-01-16 09:50:44.561 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/product-items 2022-01-16 https://api.worxlandroid.com/api/v2/product-items2022-01-16 09:50:44.659 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: [{"id":401256,"product_id":49,"user_id":xxxxxxx,"serial_number":"xxxxxxxxxxxxxxxxxxx","mac_address":"xxxxxxxxxxx","name":"steve","locked":true,"firmware_version":3.26,"firmware_auto_upgrade":true,"push_notifications":true,"sim":null,"push_notifications_level":"notice","test":0,"iot_registered":true,"mqtt_registered":true,"pin_code":"xxxx","registered_at":"2020-07-12 00:00:00","online":false,...] 2022-01-16 09:51:14.561 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - publish topic -> PRM100/xxxxxxxxxxx/commandIn 2022-01-16 09:51:14.561 [DEBUG] [d.internal.WorxLandroidBridgeHandler] - publish message -> {} 2022-01-16 09:51:14.564 [DEBUG] [orxlandroid.internal.mqtt.AWSMessage] - AWS message publishing succeeded 2022-01-16 09:52:35.236 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/product-items 2022-01-16 https://api.worxlandroid.com/api/v2/product-items2022-01-16 09:52:35.444 [ERROR] [id.internal.WorxLandroidMowerHandler] - RefreshStatusRunnable xxxxxxxxxxxxxxxxxxx: Unknown error org.openhab.binding.worxlandroid.internal.webapi.WebApiException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header at org.openhab.binding.worxlandroid.internal.webapi.request.WebApiRequest.callWebApi(WebApiRequest.java:122) ~[bundleFile:?] at org.openhab.binding.worxlandroid.internal.webapi.request.WebApiRequest.callWebApiGet(WebApiRequest.java:79) ~[bundleFile:?] at org.openhab.binding.worxlandroid.internal.webapi.request.ProductItemsRequest.call(ProductItemsRequest.java:46) ~[bundleFile:?] at org.openhab.binding.worxlandroid.internal.webapi.WorxLandroidWebApiImpl.retrieveUserDevices(WorxLandroidWebApiImpl.java:103) ~[bundleFile:?] at org.openhab.binding.worxlandroid.internal.WorxLandroidMowerHandler$1.run(WorxLandroidMowerHandler.java:108) [bundleFile:?] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_161] at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_161] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_161] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_161] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_161] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_161] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161] Caused by: java.util.concurrent.ExecutionException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header 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.worxlandroid.internal.webapi.request.WebApiRequest.callWebApi(WebApiRequest.java:92) ~[bundleFile:?] ... 11 more Caused by: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header at org.eclipse.jetty.client.AuthenticationProtocolHandler$AuthenticationListener.onComplete(AuthenticationProtocolHandler.java:163) ~[?:?] at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:198) ~[?:?] at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:190) ~[?:?] at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:444) ~[?:?] at org.eclipse.jetty.client.HttpReceiver.responseSuccess(HttpReceiver.java:390) ~[?:?] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:316) ~[?:?] at org.eclipse.jetty.http.HttpParser.parseFields(HttpParser.java:1139) ~[?:?] at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1498) ~[?:?] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:172) ~[?:?] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:135) ~[?:?] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:73) ~[?:?] at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:133) ~[?:?] at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:154) ~[?:?] at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[?:?] at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:426) ~[?:?] at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:320) ~[?:?] at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:158) ~[?:?] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[?:?] at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) ~[?:?] at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) ~[?:?] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) ~[?:?] at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) ~[?:?] ... 1 more

In generall the binding seeams working beacause of the API connect + dicovering mower + API response (with all my mower information) but RefreshStatusRunnable failed.

maybe @nibi79 https://github.com/nibi79 has an idea?

unregister and reregister the mower isn't possible because off wintersleep. and logging the REQ, including the header, isn't possible, or is it?

BR mitch

— Reply to this email directly, view it on GitHub https://github.com/nibi79/worxlandroid/issues/62#issuecomment-1013838164, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHQHDFKZHSLQBMFI7OD254TUWKDUPANCNFSM5AK5PUKQ . You are receiving this because you were mentioned.Message ID: @.***>

mitch-geht-ab commented 2 years ago

Hello again, back from the dead, my mower is on the green. Interestingly, Items/Channels like wifiQuality are updated without error, but every 3 Min (because of refreshStatusInterval=180) I got the 

2022-03-21 07:13:09.574 [ERROR] [id.internal.WorxLandroidMowerHandler] - RefreshStatusRunnable xxxxxxxxxxxxxxxxx: Unknown error
org.openhab.binding.worxlandroid.internal.webapi.WebApiException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header

error messages. Exactly 1h after install the binding and reactivating .things and .items file.

mitch-geht-ab commented 2 years ago

okay, tried a fresh debian 11 with fresh openhab 3.2.0-1 install Zulu Java... same problem. After 1h I got auth-header errors for the API calls.

root@debian:/tmp# cat /etc/os-release
PRETTY_NAME="Debian GNU/Linux 11 (bullseye)"
NAME="Debian GNU/Linux"
VERSION_ID="11"
VERSION="11 (bullseye)"
VERSION_CODENAME=bullseye
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"

root@debian:/tmp# cat /etc/apt/sources.list.d/openhab.list
deb https://openhab.jfrog.io/openhab/openhab-linuxpkg stable main

root@debian:/tmp# dpkg -l|grep openhab
ii  openhab                        3.2.0-1                        all          openhab
ii  openhab-addons                 3.2.0-1                        all          openhab-addons

root@debian:/tmp# dpkg -l|grep zulu
ii  zulu-repo                      1.0.0-3                        all          Azul Systems Zulu JDK new repository setup
ii  zulu11-ca-jre-headless         11.0.14.1-1                    amd64        Azul Zulu 11.54+25 (11.0.14.1-b1) CA Headless JRE
ii  zulu11-jre-headless            11.0.14.1-1                    amd64        Azul Zulu 11.54+25 (11.0.14.1-b1) Headless JRE

root@debian:/tmp# java -version
openjdk version "11.0.14.1" 2022-02-08 LTS
OpenJDK Runtime Environment Zulu11.54+25-CA (build 11.0.14.1+1-LTS)
OpenJDK 64-Bit Server VM Zulu11.54+25-CA (build 11.0.14.1+1-LTS, mixed mode)
root@debian:/tmp#

have installed the Worx Binding this way:

openhab> bundle:install https://github.com/nibi79/worxlandroid/releases/download/v3.0/org.openhab.binding.worxlandroid-3.0.0-SNAPSHOT.jar
Bundle ID: 238
openhab> bundle:start 238
openhab> list -s
START LEVEL 100 , List Threshold: 50
 ID ¦ State  ¦ Lvl ¦ Version               ¦ Symbolic name
----+--------+-----+-----------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 29 ¦ Active ¦  80 ¦ 2.12.5                ¦ com.fasterxml.jackson.core.jackson-annotations
...
238 ¦ Active ¦  80 ¦ 3.0.0.202012230711    ¦ org.openhab.binding.worxlandroid
openhab> log:set TRACE org.openhab.binding.worxlandroid

and configured the Worx Bridge and Mower via new WebUI + 2 Items (WifiQuality and LastUpdateOnlineStatus).

Last working call

2022-03-21 17:06:22.511 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/product-items
2022-03-21 17:06:22.737 [DEBUG] [nternal.webapi.request.WebApiRequest] - Worx Landroid WebApi Response: [{"id":xxxxxxx,"product_id":49,"user_id":xxxxx,"serial_number":"xxxxxxxxxxxxxxxxxx","mac_address":"xxxxxxxxxxx","name":"steve","locked":true,"firmware_version":3.26,"firmware_auto_upgrade":true,"push_notifications":true,"sim":null,"push_notifications_level":"notice","test":0,"...

60 seconds later (after ~1h)

2022-03-21 17:07:22.739 [DEBUG] [nternal.webapi.request.WebApiRequest] - URI: https://api.worxlandroid.com/api/v2/product-items
2022-03-21 17:07:22.947 [ERROR] [id.internal.WorxLandroidMowerHandler] - RefreshStatusRunnable 20193019840302820909: Unknown error
org.openhab.binding.worxlandroid.internal.webapi.WebApiException: org.eclipse.jetty.client.HttpResponseException: HTTP protocol violation: Authentication challenge without WWW-Authenticate header
        at org.openhab.binding.worxlandroid.internal.webapi.request.WebApiRequest.callWebApi(WebApiRequest.java:122) ~[bundleFile:?]
        at org.openhab.binding.worxlandroid.internal.webapi.request.WebApiRequest.callWebApiGet(WebApiRequest.java:79) ~[bundleFile:?]
...

Have also unregistered/unpaired the mower from my account an paired back. Nobody else with this problem? Can't imagine that this is related to my account.

Espacially a

bundle:stop 238
bundle:start 238

fix the problem (for 1h).

BR mitch

nibi79 commented 2 years ago

hi Mitch, sorry for the late reply. My mower works since Sunday without any problems again. I really have no idea what the problem could be. I had this error message when I used wrong credentials, which can not be with you. So perhaps you can change your password and give this a try... br

mitch-geht-ab commented 2 years ago

No luck with a new password (less complex, just alphanum).

Is there anything else I can enable for more debug logs?

mitch-geht-ab commented 2 years ago

Just for the record, after some debugging with mitmproxy, my problem is that my OAuth access_token has a lifetime of 3600s/1h and is not being refreshed after that time. So I got 401 unauth. after exactly 1h. I wonder why I'm the only one who is affected and why this is working for everyone else. Or isn't it? So, I tried to enrich @nibi79 binding code with check access_token lifetime before every API call and do, if necessary, a access_token refresh with the refresh_token. To my shame, I failed with compiling the binding original code, following the OH binding development howto. I fail because of the OH an EEA. So I can't test my refresh-token-code. Nevertheless, I have uploaded a PR #68 and hope that somebody could give me a hint to compile it myself or do it for me improve and test it.

BR Mitch

sihui62 commented 2 years ago

I wonder why I'm the only one who is affected and why this is working for everyone else. Or isn't it?

No, same problem here:

2022-03-26 15:55:48.719 [ERROR] [id.internal.WorxLandroidMowerHandler] - RefreshStatusRunnable 202130267201007910D0: Unknown error

Edit: I am currently on OH 3.3M2. The binding was working fine until I stored the mower in Nov 2021 with OH 3.1 stable. No single error message.

RolandRosenfeld commented 2 years ago

Also the same here with OH 3.1.1 and the v3.0 release of the binding. This was my first try in 2022 to use the binding (last year I was on OH 2). As you wrote, the RefershStatusRunnable ... Unknown error message appears exactly one hour after starting the binding. Except the error (every 5 minutes) the binding otherwise seems to work, at least the battery state is updated every 5 minutes.

nibi79 commented 2 years ago

Ok with my new OH installation I get this error too.

int5749 commented 2 years ago

That's weird. migrated recently to openHAB 3.3.0M2 and haven't had my Mower enabled, Binding was disabled over Winter. Today I did some gardening and also put Shaun to charge and to check if I can also reproduce this. First of all, accu was still at 100% after Winter, amazing!

I simply enabled thing in MainUI (while it's for sure configured in an *.things file) and Bridge went online without any issue. But there was no update to any item and when I tried to activate something, there was a huge error in log. For further analysis I removed org.openhab.binding.worxlandroid-3.0.0-SNAPSHOT.jar from AddOn folder and Landroid Bridge went offline. While I messed up my tmp folder, I restarted the whole System and copied back org.openhab.binding.worxlandroid-3.0.0-SNAPSHOT.jar to AddOn Folder Binding was installed, went online and items where updated right away. I also was able to enable mower schedule and to update and all is done without errors in log and is available/updated in Landroid APP at same time. Right now I'm not able to reproduce this issue :-/

nibi79 commented 2 years ago

the binding otherwise seems to work

Same with me. I get the error " Authentication challenge without WWW-Authenticate header" but the values are updated anyway. I have to look at this tomorrow.

mitch-geht-ab commented 2 years ago

the binding otherwise seems to work

yes, it's because the status updates are via mqtt and mqtt is authenticated via a x509 client cert., fetched at the begining from the HTTPS API. Not checked the expiration date of the x509 cert. And HTTPS API is authenticated via Bearer Token, which has a Lifetime of 3600sec.

I think Worx or AWS has changed sth. with Token Handling somewhere in Dec. 2021, where it happend to me the first time. Mower was stored in cellar and nothing changed on my OH Setup.

nibi79 commented 2 years ago

hi all,

here is a new beta version of the binding: https://github.com/nibi79/worxlandroid/releases/tag/v3.1-beta

This version integrates parts of the pull request of @mitch-geht-ab . Today I was not able to merge the code and fix some minor issues, so I will do this next week. That's why there is only a beta version today... and please give me feedback if the problem is solved or not.

@mitch-geht-ab thank you for your solution

int5749 commented 2 years ago

@nibi79 Loaded, installation without any issues and workig so far. Issues also was visible to me since yesterday most time (not always) when I pushed poll to refresh status. Let's see how it's going after some time.

nibi79 commented 2 years ago

@int5749 thank you for your fast feedback

sihui62 commented 2 years ago

Sorry, I am late to the party.

and workig so far.

Same here, no issues. Thx @nibi79

mitch-geht-ab commented 2 years ago

same here. no problems and also mitmproxy shows, after 1h a new access_token is requested. looking forward to your final binding ;) could you also backport it to oh2.5? haven't finaly migrated to oh3, until now ;)

int5749 commented 2 years ago

After reviewing my log I found various entries with "AWS connection failure" 2022-03-29 19:45:28.642 [WARN ] [d.internal.WorxLandroidBridgeHandler] - AWS connection failure

Nothing else but occurs several times during the day.

sirupflex commented 2 years ago

Thanks so much nibi79 and Mitch, just installed the binding's 3.1 beta (on OH3.2) and it works fine for me as well, the errors are gone as far as I can tell. Fantastic!