iCloud SSL issue again

Hawkeye · January 30, 2020, 11:58am

The binding stores the retrieved certificate in {OPENHAB}/userdata/tmp/fmipmobile.crt

Bredmich · January 30, 2020, 12:01pm

Here´s the certificate my binding currently uses.
And it was changed just 5 minutes after the first refresh from installing the new snapshot build.

2020-01-30 12:44:35.203 [WARN ] [l.handler.ICloudAccountBridgeHandler] - SSL exception during handshake, attempting to refresh certificate automatically
2020-01-30 12:49:36.897 [WARN ] [l.handler.ICloudAccountBridgeHandler] - SSL exception during handshake, attempting to refresh certificate automatically

Certificate

Hawkeye · January 30, 2020, 12:06pm

The certificate you posted seems to match the one that @rkrisi added last. If you increase the logging level, you should see it reporting errors when connecting. I did notice going back through the code though, that it updates the certificate on any IOException, not just an SSLHandshakeException. This means that it could be updating the certificate unintended when the server is unavailable. I’ll update this in code, thanks for giving me a hint!

Edit: hmm I remember now, the reason I put in the IOException is because the SSLHandshakeException is buried 3 layers deep in the IOException. Let me think about this for a while…

Hawkeye · January 30, 2020, 12:56pm

@Bredmich

I updated the code so that it should only update the certificate on SSLHanshakeException occurring. Can you check with this snapshot? https://drive.google.com/file/d/1z_lb-4CSEOhnan3wi8nym1pZepjnXAGU/view?usp=sharing

Update: this has been removed for security reasons

Bredmich · January 30, 2020, 1:00pm

Installed and log switched to TRACE let´s see if and what happens.
Thanks!

Edit:
New errors

2020-01-30 15:34:30.721 [WARN ] [l.handler.ICloudAccountBridgeHandler] - Unable to refresh device data

java.io.IOException: java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@1d25e1c::DecryptedEndPoint@d53cd1{fmipmobile.icloud.com/17.248.177.165:443<->/192.168.2.10:36696,CLOSED,fill=-,flush=C,to=3/0}

	at org.openhab.binding.icloud.internal.ICloudConnection.callApi(ICloudConnection.java:89) ~[?:?]

	at org.openhab.binding.icloud.internal.ICloudConnection.requestDeviceStatusJSON(ICloudConnection.java:70) ~[?:?]

	at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.requestStatus(ICloudAccountBridgeHandler.java:109) ~[?:?]

	at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.lambda$0(ICloudAccountBridgeHandler.java:100) ~[?:?]

	at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.refreshData(ICloudAccountBridgeHandler.java:196) ~[?:?]

Caused by: java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@1d25e1c::DecryptedEndPoint@d53cd1{fmipmobile.icloud.com/17.248.177.165:443<->/192.168.2.10:36696,CLOSED,fill=-,flush=C,to=3/0}

Caused by: java.io.EOFException: HttpConnectionOverHTTP@1d25e1c::DecryptedEndPoint@d53cd1{fmipmobile.icloud.com/17.248.177.165:443<->/192.168.2.10:36696,CLOSED,fill=-,flush=C,to=3/0}

2020-01-30 15:34:30.743 [hingStatusInfoChangedEvent] - 'icloud:account:openHAB' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@1d25e1c::DecryptedEndPoint@d53cd1{fmipmobile.icloud.com/17.248.177.165:443<->/192.168.2.10:36696,CLOSED,fill=-,flush=C,to=3/0}

Bredmich · January 30, 2020, 3:38pm

Ok it´s still throwing errors…

2020-01-30 16:34:45.738 [WARN ] [l.handler.ICloudAccountBridgeHandler] - Unable to refresh device data

java.io.IOException: java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@1515a76::DecryptedEndPoint@1acfe75{fmipmobile.icloud.com/17.248.146.205:443<->/192.168.2.10:34916,CLOSED,fill=-,flush=C,to=1/0}

	at org.eclipse.smarthome.io.net.http.HttpUtil.executeUrlAndGetReponse(HttpUtil.java:259) ~[?:?]

	at org.eclipse.smarthome.io.net.http.HttpUtil.executeUrl(HttpUtil.java:156) ~[?:?]

	at org.eclipse.smarthome.io.net.http.HttpUtil.executeUrl(HttpUtil.java:131) ~[?:?]

	at org.eclipse.smarthome.io.net.http.HttpRequestBuilder.getContentAsString(HttpRequestBuilder.java:135) ~[?:?]

	at org.openhab.binding.icloud.internal.ICloudConnection.callApi(ICloudConnection.java:89) ~[?:?]

	at org.openhab.binding.icloud.internal.ICloudConnection.requestDeviceStatusJSON(ICloudConnection.java:70) ~[?:?]

	at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.requestStatus(ICloudAccountBridgeHandler.java:109) ~[?:?]

	at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.lambda$0(ICloudAccountBridgeHandler.java:100) ~[?:?]

	at org.eclipse.smarthome.core.cache.ExpiringCache.refreshValue(ExpiringCache.java:101) ~[?:?]

	at org.eclipse.smarthome.core.cache.ExpiringCache.getValue(ExpiringCache.java:72) ~[?:?]

	at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.refreshData(ICloudAccountBridgeHandler.java:196) ~[?:?]

	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_222]

	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_222]

	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]

	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_222]

	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]

	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]

	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]

Caused by: java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@1515a76::DecryptedEndPoint@1acfe75{fmipmobile.icloud.com/17.248.146.205:443<->/192.168.2.10:34916,CLOSED,fill=-,flush=C,to=1/0}

	at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[?:?]

	at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[?:?]

	at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:685) ~[?:?]

	at org.eclipse.smarthome.io.net.http.HttpUtil.executeUrlAndGetReponse(HttpUtil.java:250) ~[?:?]

	... 17 more

Caused by: java.io.EOFException: HttpConnectionOverHTTP@1515a76::DecryptedEndPoint@1acfe75{fmipmobile.icloud.com/17.248.146.205:443<->/192.168.2.10:34916,CLOSED,fill=-,flush=C,to=1/0}

	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.earlyEOF(HttpReceiverOverHTTP.java:335) ~[?:?]

	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1526) ~[?:?]

	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.shutdown(HttpReceiverOverHTTP.java:209) ~[?:?]

	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:147) ~[?:?]

	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$1.run(SslConnection.java:143) ~[?:?]

	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

==> /var/log/openhab2/events.log <==

2020-01-30 16:34:45.790 [hingStatusInfoChangedEvent] - 'icloud:account:openHAB' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@1515a76::DecryptedEndPoint@1acfe75{fmipmobile.icloud.com/17.248.146.205:443<->/192.168.2.10:34916,CLOSED,fill=-,flush=C,to=1/0}

Hawkeye · January 30, 2020, 4:09pm

Yeah that’s not a certificate problem I believe. Can you let me know if it’s able to recover over time?

Bredmich · January 30, 2020, 4:21pm

Yes it´s recovering after some minutes.
The downtime is mostly no longer than 5 minutes.
I didn´t had this issues before.

Hawkeye · January 30, 2020, 4:31pm

If it’s occurring regularly, can you check to see if you have the same error with @rkrisi his snapshot? I don’t believe this is related to my change to be honest

Bredmich · January 30, 2020, 4:39pm

The behavior started with the snapshot builds to address the current certificate problems.
With the latest binding before 20.January i had no problems with repeating downtimes.

My iCloud account is configured with refreshTimeInMinutes=5

Hawkeye · January 30, 2020, 5:03pm

Hmm thanks for the update, I’ll investigate. If anybody has more insights on this (@rkrisi?) please shout

Hawkeye · January 30, 2020, 5:56pm

@Bredmich what version of Java are you running on?

JensH · January 30, 2020, 5:57pm

Saw crazy thing in PaperUi today: I have got iCloud Binding two times.

Under Configuration: iCloud Binding icloud Partrik Gfeller ==> So this one is installed
Under Bindings: icloud (all lower case) to Install

Are there two? Or is there a small mistake in Snapshot?

How to deinstall iCloud Binding now to test your actual Snapshot?

Bredmich · January 30, 2020, 5:59pm

[18:58:46] openhabian@openHAB4:~$ java -version
openjdk version "1.8.0_222"
OpenJDK Runtime Environment (Zulu8.40.0.178-CA-linux_aarch32hf) (build 1.8.0_222-b178)
OpenJDK Client VM (Zulu8.40.0.178-CA-linux_aarch32hf) (build 25.222-b178, mixed mode, Evaluation)

rkrisi · January 30, 2020, 7:14pm

Remove the old one.

rkrisi · January 30, 2020, 7:15pm

I don’t know it seems working for me. However during the night it also stopped for me once and it didn’t recovered. I will see the logs what happened there and why these errors pop up to users…

rkrisi · January 30, 2020, 7:18pm

I think this is not related to the binding and the new changes. I got this error every time. Sometimes more sometimes less. Basically this API sometimes don’t respond that’s why this happens.
@Hawkeye I think a solution for this might be that the binding should retry in case of errors like this, right after when this error happens. Right now you have to wait refreshTime to try again…

Hawkeye · January 30, 2020, 8:22pm

Actually, I’m suspicious if it has something to do with concurrent access corrupting the non-thread safe HttpConnection. I’m willing to investigate a bit more when I have the time (bit busy atm), but it may be better to do this under a separate pull request.

NCO · January 30, 2020, 8:32pm

Works for me.
Thanks!

rkrisi · January 30, 2020, 8:47pm

It might be. I can’t remember that clearly but when I did the previous fix (when a html object was returned instead of the json - which indicated that the server can’t respond) I also saw that sometimes the connection times out… I increased the timeout a little bit, but that didn’t helped so I also might think that just Apple limits the resources to this API - I think this might be used by other 3rd parties - which not in “partnership” with Apple.