iCloud Binding Crashing - 2.5

delid4ve · January 9, 2020, 7:58am

iCloud binding runs for some time then stops working and no longer updates:

2020-01-09 05:25:59.777 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $
at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:224) ~[?:?]
at com.google.gson.Gson.fromJson(Gson.java:888) ~[?:?]
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.icloud.internal.ICloudDeviceInformationParser.parse(ICloudDeviceInformationParser.java:30) ~[?:?]
at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.refreshData(ICloudAccountBridgeHandler.java:152) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_201]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[?:1.8.0_201]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_201]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[?:1.8.0_201]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_201]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_201]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
Caused by: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $
at com.google.gson.stream.JsonReader.beginObject(JsonReader.java:385) ~[?:?]
at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:213) ~[?:?]
... 13 more
2020-01-09 05:25:59.833 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $
at     com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:224) ~[?:?]
at com.google.gson.Gson.fromJson(Gson.java:888) ~[?:?]
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.icloud.internal.ICloudDeviceInformationParser.parse(ICloudDeviceInformationParser.java:30) ~[?:?]
at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.refreshData(ICloudAccountBridgeHandler.java:152) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_201]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[?:1.8.0_201]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_201]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[?:1.8.0_201]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_201]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_201]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
Caused by: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $
at com.google.gson.stream.JsonReader.beginObject(JsonReader.java:385) ~[?:?]
at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:213) ~[?:?]
... 13 more

H102 · January 9, 2020, 2:24pm

I didn’t see any related issue on github but do you use a rule with any iCloud item?

delid4ve · January 9, 2020, 2:39pm

@H102 I do use a rule yes with the location for geofencing.
It’s quite a complex rule too.
Going to create a new item tonight, update it when location is changed (as a proxy item)
Then fire the main rule off this to see if it makes a difference

H102 · January 9, 2020, 2:42pm

Sounds like a plan.

You could also comment out the rule for a few day to verify if it’s the issue then address as needed.

delid4ve · January 9, 2020, 2:43pm

It’s definitely the rule, have tested today

H102 · January 9, 2020, 2:44pm

The log tells where the issue is.

Expected BEGIN_OBJECT but was STRING at line 1 column 1 path

delid4ve · January 9, 2020, 2:45pm

Surely that’s the first character?

@H102 My rule if you can spot any errors that could be causing… just strange it works for some time…

rule "David Location" when Item iPhoneDavidLocation changed then
if (DavidRegion.state == NULL) {
DavidRegion.postUpdate(1)
DavidDistance.postUpdate(1)
DavidDirection.postUpdate("Stationary") }
else {
val PointType DavidLocation = iPhoneDavidLocation.state as PointType
val Number distance = DavidLocation.distanceFrom(Home.state as PointType).intValue()
var Number Region
var String Direction

if (distance > -1 ) {Region = 1}
if (distance > 49 ) {Region = 2}
if (distance > 99 ) {Region = 3}
if (distance > 499 ) {Region = 4}
if (distance > 999 ) {Region = 5}
if (distance > 1999 ) {Region = 6}
if (distance > 3999 ) {Region = 7}

if (Region < DavidRegion.state) {Direction = "In"} 
else if (Region > DavidRegion.state) {Direction = "Out"}
else {Direction = "Stationary"}

if (Region == 1) {DavidHome.postUpdate(ON) HomeMode.postUpdate(ON)}
else {DavidHome.postUpdate(OFF)}

if (Region < 5 && DavidRegion.state > 4 && JodieHome.state == ON) {
    KitchenAlexaTTSVolume.sendCommand(8)
    KitchenAlexaTTS.sendCommand('Put the kettle on dave is nearly home')}

if (Region > 1 && JodieHome.state == OFF) {HomeMode.postUpdate(OFF)}

DavidRegion.postUpdate(Region)
DavidDistance.postUpdate(distance)
DavidDirection.postUpdate(Direction)
}
end

H102 · January 9, 2020, 2:54pm

By the description yes.

Try moving the first line like below:

rule "David Location" 
when 
    Item iPhoneDavidLocation changed 
then
    if (DavidRegion.state == NULL) {
        DavidRegion.postUpdate(1)
        DavidDistance.postUpdate(1)
        DavidDirection.postUpdate("Stationary") }

Just a guess as everything else looks ok. OH and rules can be quirky at times so it’s worth a shot.

delid4ve · January 10, 2020, 7:01am

@H102 Nope, proxy item and it still fell over. 7 hours later

Have opened an issue on git

vossivossi · January 17, 2020, 3:04pm

I have exactly the same problem here, after a couple of days the phone location is no longer updated every 5 minutes and I see the same error in the logs.
However the manual refresh still works, so the binding itself still seems to work but the scheduling of the autoupdate of the devices is down.
Maybe I try a rule to trigger the refresh every 5 minutes as a workaround until the bug gets fixed.

vossivossi · January 17, 2020, 3:35pm

Ok, a simple rule is doing the job now as a workaround:

rule "iPhone Refresh"
    when Time cron "0 0/5 * 1/1 * ? *"			 
     then
       sendCommand(iPhone_Refresh, REFRESH)
     end

icsat · January 17, 2020, 8:15pm

Hello,

same issue here. Are you sure it’s a problem with executing a rule?
I had the icloud-binding running on this system since 4th of January without any problems. Last Sunday and Monday I did some moderate changes to the rule. Since Wednesday I am discovering the problems. As you already described the binding stops updating after running a random time without issues (Maybe a “Unable to refresh device data” once in a while). I am not sure when I did the update from 2.5.0 to 2.5.1 and so I don’t know if this might be related to the issue. Wich release are you running? Forcing a manual refresh as suggested as workaround does not seem to work for me.

HW: Raspberry Pi 4 Model B Rev 1.1 4GB
System: Openhabian 1.5
openHAB: 2.5.1-2 (Release Build)
icloud-binding: 2.5.1

I started the system yesterday around 10:10pm and got some “Unable to refresh device data”-errors around 11:50pm, 1:30am, 2:10pm. The last successful update was at 2:32am. At 2:35am I got the “Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $”-error three times and no more updates for the icloud items/things from that point. Paper UI shows the icloud accounts and devices online, but there are no more updates on the items. The binding is showing as “Active” on the console. If restart the binding from the console every thing recovers and I get updates for my icloud-items for another couple of hours.

I did not try to deinstall and reinstall the icloud-binding, yet. Nor did I set the trace-level to debug so far.

2020-01-17 02:32:35.550 [smarthome.event.ItemStateChangedEvent             ] - XX_XX_AD_DC_iCloud_LocationLastUpdate changed from 2020-01-17T02:26:34.235+0100 to 2020-01-17T02:29:35.237+0100

2020-01-16 22:09:41.135 [INFO ] [.smarthome.model.core.internal.ModelRepositoryImpl] - Loading model 'icloud.items'
2020-01-16 22:09:42.806 [INFO ] [.smarthome.model.core.internal.ModelRepositoryImpl] - Loading model 'icloud.things'
2020-01-16 22:18:50.472 [INFO ] [.smarthome.model.core.internal.ModelRepositoryImpl] - Loading model 'icloud.rules'

2020-01-16 23:49:37.728 [WARN ] [icloud.internal.handler.ICloudAccountBridgeHandler] - Unable to refresh device data
java.io.IOException: java.util.concurrent.TimeoutException: Total timeout 10000 ms elapsed
	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:88) ~[?:?]
	at org.openhab.binding.icloud.internal.ICloudConnection.requestDeviceStatusJSON(ICloudConnection.java:69) ~[?:?]
	at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.lambda$0(ICloudAccountBridgeHandler.java:88) ~[?:?]
	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:145) ~[?:?]
	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.TimeoutException: Total timeout 10000 ms elapsed
	at org.eclipse.jetty.client.TimeoutCompleteListener.onTimeoutExpired(TimeoutCompleteListener.java:51) ~[?:?]
	at org.eclipse.jetty.client.TimeoutCompleteListener.schedule(TimeoutCompleteListener.java:73) ~[?:?]
	at org.eclipse.jetty.client.HttpChannel.send(HttpChannel.java:126) ~[?:?]
	at org.eclipse.jetty.client.HttpConnection.send(HttpConnection.java:201) ~[?:?]
	at org.eclipse.jetty.client.http.HttpConnectionOverHTTP$Delegate.send(HttpConnectionOverHTTP.java:252) ~[?:?]
	at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.send(HttpConnectionOverHTTP.java:121) ~[?:?]
	at org.eclipse.jetty.client.http.HttpDestinationOverHTTP.send(HttpDestinationOverHTTP.java:38) ~[?:?]
	at org.eclipse.jetty.client.HttpDestination.process(HttpDestination.java:346) ~[?:?]
	at org.eclipse.jetty.client.HttpDestination.process(HttpDestination.java:304) ~[?:?]
	at org.eclipse.jetty.client.HttpDestination.send(HttpDestination.java:294) ~[?:?]
	at org.eclipse.jetty.client.HttpDestination.succeeded(HttpDestination.java:228) ~[?:?]
	at org.eclipse.jetty.client.AbstractConnectionPool.proceed(AbstractConnectionPool.java:153) ~[?:?]
	at org.eclipse.jetty.client.AbstractConnectionPool$1.succeeded(AbstractConnectionPool.java:131) ~[?:?]
	at org.eclipse.jetty.client.AbstractConnectionPool$1.succeeded(AbstractConnectionPool.java:123) ~[?:?]
	at org.eclipse.jetty.util.Promise$Wrapper.succeeded(Promise.java:130) ~[?:?]
	at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onOpen(HttpConnectionOverHTTP.java:129) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslConnection.onOpen(SslConnection.java:282) ~[?:?]
	at org.eclipse.jetty.io.SelectorManager.connectionOpened(SelectorManager.java:324) ~[?:?]
	at org.eclipse.jetty.io.ManagedSelector.createEndPoint(ManagedSelector.java:270) ~[?:?]
	at org.eclipse.jetty.io.ManagedSelector.access$1900(ManagedSelector.java:61) ~[?:?]
	at org.eclipse.jetty.io.ManagedSelector$CreateEndPoint.run(ManagedSelector.java:923) ~[?:?]
	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
2020-01-17 01:30:48.302 [WARN ] [icloud.internal.handler.ICloudAccountBridgeHandler] - Unable to refresh device data
java.io.IOException: java.util.concurrent.TimeoutException: Total timeout 10000 ms elapsed
	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:88) ~[?:?]
	at org.openhab.binding.icloud.internal.ICloudConnection.requestDeviceStatusJSON(ICloudConnection.java:69) ~[?:?]
	at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.lambda$0(ICloudAccountBridgeHandler.java:88) ~[?:?]
	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:145) ~[?:?]
	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.TimeoutException: Total timeout 10000 ms elapsed
	at org.eclipse.jetty.client.HttpDestination$TimeoutTask.onTimeoutExpired(HttpDestination.java:529) ~[?:?]
	at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:282) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_222]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_222]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_222]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[?:1.8.0_222]
	... 3 more
2020-01-17 02:11:07.381 [WARN ] [icloud.internal.handler.ICloudAccountBridgeHandler] - Unable to refresh device data
java.io.IOException: java.util.concurrent.TimeoutException: Total timeout 10000 ms elapsed
	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:88) ~[?:?]
	at org.openhab.binding.icloud.internal.ICloudConnection.requestDeviceStatusJSON(ICloudConnection.java:69) ~[?:?]
	at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.lambda$0(ICloudAccountBridgeHandler.java:88) ~[?:?]
	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:145) ~[?:?]
	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.TimeoutException: Total timeout 10000 ms elapsed
	at org.eclipse.jetty.client.HttpDestination$TimeoutTask.onTimeoutExpired(HttpDestination.java:529) ~[?:?]
	at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:282) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_222]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_222]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_222]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[?:1.8.0_222]
	... 3 more

2020-01-17 02:32:35.550 [smarthome.event.ItemStateChangedEvent             ] - XX_XX_AD_DC_iCloud_LocationLastUpdate changed from 2020-01-17T02:26:34.235+0100 to 2020-01-17T02:29:35.237+0100

2020-01-17 02:35:30.541 [WARN ] [re.internal.common.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $
	at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:224) ~[?:?]
	at com.google.gson.Gson.fromJson(Gson.java:888) ~[?:?]
	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.icloud.internal.ICloudDeviceInformationParser.parse(ICloudDeviceInformationParser.java:30) ~[?:?]
	at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.refreshData(ICloudAccountBridgeHandler.java:152) ~[?:?]
	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.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $
	at com.google.gson.stream.JsonReader.beginObject(JsonReader.java:385) ~[?:?]
	at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:213) ~[?:?]
	... 13 more
2020-01-17 02:35:35.622 [WARN ] [re.internal.common.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $
	at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:224) ~[?:?]
	at com.google.gson.Gson.fromJson(Gson.java:888) ~[?:?]
	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.icloud.internal.ICloudDeviceInformationParser.parse(ICloudDeviceInformationParser.java:30) ~[?:?]
	at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.refreshData(ICloudAccountBridgeHandler.java:152) ~[?:?]
	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.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $
	at com.google.gson.stream.JsonReader.beginObject(JsonReader.java:385) ~[?:?]
	at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:213) ~[?:?]
	... 13 more
2020-01-17 02:36:11.621 [WARN ] [re.internal.common.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $
	at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:224) ~[?:?]
	at com.google.gson.Gson.fromJson(Gson.java:888) ~[?:?]
	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.icloud.internal.ICloudDeviceInformationParser.parse(ICloudDeviceInformationParser.java:30) ~[?:?]
	at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.refreshData(ICloudAccountBridgeHandler.java:152) ~[?:?]
	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.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $
	at com.google.gson.stream.JsonReader.beginObject(JsonReader.java:385) ~[?:?]
	at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:213) ~[?:?]
	... 13 more

openhab> bundle:list | grep -i icloud                                                                                                                                               
243 │ Active │  80 │ 2.5.1                   │ openHAB Add-ons :: Bundles :: iCloud Binding
openhab> bundle:restart 243

2020-01-17 05:39:00.627 [smarthome.event.ItemStateChangedEvent             ] - XX_XX_AD_DC_iCloud_LocationLastUpdate changed from 2020-01-17T05:33:21.154+0100 to 2020-01-17T05:36:20.742+0100

delid4ve · January 17, 2020, 10:37pm

I haven’t tested the workaround yet.
Now I’m understanding a little behind the scenes it seems that the response is not handled by the binding (a new error code from Apple maybe?)
Need to run in debug to find the cause
I’m on 2.5 not 2.5.1 so it’s not that

rkrisi · January 18, 2020, 10:40am

I have the same issue.
Tried running in debug mode, but it doesn’t seemed to return any information when it stopped updating…
Really annoying

2020-01-18 04:57:12.346 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $
	at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:224) ~[?:?]
	at com.google.gson.Gson.fromJson(Gson.java:888) ~[?:?]
	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.icloud.internal.ICloudDeviceInformationParser.parse(ICloudDeviceInformationParser.java:30) ~[?:?]
	at org.openhab.binding.icloud.internal.handler.ICloudAccountBridgeHandler.refreshData(ICloudAccountBridgeHandler.java:152) ~[?:?]
	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.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $
	at com.google.gson.stream.JsonReader.beginObject(JsonReader.java:385) ~[?:?]
	at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:213) ~[?:?]
	... 13 more

Only this…

Looking at the code, TRACE logging should be better here. It looks like the returned json is wrong and not handled there. Looking into this.

rkrisi · January 18, 2020, 7:02pm

Ok, so this is returned when it stops updating:

json: <!DOCTYPE html>
<html>
<body>
<h1>Service Unavailable</h1>
</body>
</html>

Pretty straighforward that this is not a json and should be handled to skip these updates.
~~I will try to make a quick fix for this.~~

I have made a quick fix for this, I’m testing it now. If anyone want to test, let me know. Once I tested it (and get a same service unavailable response and it will survive it) I’ll make a PR for this.

delid4ve · January 19, 2020, 7:21am

@rkrisi
Have you also noticed that the location resfresh channel is also the whatever the refresh time is behind…
So if it’s set at 5 minutes and it updates at 0830 it will show 0825?
While someone’s here that knows what they’re looking at…

rkrisi · January 19, 2020, 2:23pm

Yes I also have this…
And basically not only the date is 5 min earlier but all data seems to be approx. 5 min earlier. I don’t know how this API works, and as I know this is a reverse engineered API, so there is no proper documentation for it. So my assumption is:

If you try the manual refresh on a device, it will also work the same. It will not ask the device for a new status, basically it will just refresh the data from the server (where the phone pushed it’s current information a few mins earlier). I will also add some notice about this to the README, because lot of users think that the refresh Switch will give them an up to date, precise location…
So I think this is what happens at a “normal” refresh by the binding. The phones push it’s location and everything to the cloud (at a 5 min interval) and the binding will only poll this data from the cloud. So the binding can not request this data directly from the phone.

icsat · January 19, 2020, 3:16pm

I was wrong about the workaround. Manual refresh works. I just made a mistake using it.

rkrisi · January 19, 2020, 11:51pm

Here is a version which fixes the issue:
https://openhab.jfrog.io/openhab/libs-pullrequest-local/org/openhab/addons/bundles/org.openhab.binding.icloud/2.5.2-SNAPSHOT/org.openhab.binding.icloud-2.5.2-SNAPSHOT.jar

delid4ve · January 20, 2020, 7:13am

The data is ‘exactly’ the refresh interval behind.
My thoughts are the binding sends the refresh command to the api which triggers the phone to report its location to iCloud (this obviously takes a second), but it doesn’t wait long enough for a new response, instead it reports the last one
Reckon it needs a ‘while loop’ in there somewhere