amazonechocontrol takes a very long time to refresh data

[ccutrer]

upwards of 60s for me, which is painful because it holds a mutex on the connection the entire time, and it calls REFRESH synchronously when any channel is linked, meaning it takes many minutes to fully load my echo items file.

examples stack trace from openhab-cli console's thread:list:

    at java.base@11.0.15/java.lang.Thread.sleep(Native Method)
    at org.smarthomej.binding.amazonechocontrol.internal.connection.Connection.makeRequest(Connection.java:518)
    at org.smarthomej.binding.amazonechocontrol.internal.connection.Connection.makeRequestAndReturnString(Connection.java:383)
    at org.smarthomej.binding.amazonechocontrol.internal.connection.Connection.makeRequestAndReturnString(Connection.java:378)
    at org.smarthomej.binding.amazonechocontrol.internal.connection.Connection.getPlayer(Connection.java:901)
    at org.smarthomej.binding.amazonechocontrol.internal.handler.EchoHandler.updateState(EchoHandler.java:895)
    at org.smarthomej.binding.amazonechocontrol.internal.handler.EchoHandler.lambda$2(EchoHandler.java:632)
    at org.smarthomej.binding.amazonechocontrol.internal.handler.EchoHandler$$Lambda$2855/0x000000010218f040.run(Unknown Source)
    at org.smarthomej.binding.amazonechocontrol.internal.handler.EchoHandler.handleCommand(EchoHandler.java:639)
    at org.openhab.core.thing.binding.BaseThingHandler.channelLinked(BaseThingHandler.java:178)
    at org.openhab.core.thing.internal.ChannelLinkNotifier.lambda$3(ChannelLinkNotifier.java:72)
    at org.openhab.core.thing.internal.ChannelLinkNotifier$$Lambda$960/0x0000000100e9f040.accept(Unknown Source)
    at org.openhab.core.thing.internal.ChannelLinkNotifier.call(ChannelLinkNotifier.java:96)
    at org.openhab.core.thing.internal.ChannelLinkNotifier.added(ChannelLinkNotifier.java:72)
    at org.openhab.core.thing.internal.ChannelLinkNotifier.added(ChannelLinkNotifier.java:1)
    at org.openhab.core.common.registry.AbstractRegistry.notifyListeners(AbstractRegistry.java:367)
    at org.openhab.core.common.registry.AbstractRegistry.notifyListenersAboutAddedElement(AbstractRegistry.java:400)
    at org.openhab.core.thing.link.ItemChannelLinkRegistry.notifyListenersAboutAddedElement(ItemChannelLinkRegistry.java:138)
    at org.openhab.core.thing.link.ItemChannelLinkRegistry.notifyListenersAboutAddedElement(ItemChannelLinkRegistry.java:1)
    at org.openhab.core.common.registry.AbstractRegistry.added(AbstractRegistry.java:175)
    at org.openhab.core.common.registry.AbstractRegistry.added(AbstractRegistry.java:1)
    at org.openhab.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:60)
    at org.openhab.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:79)
    at org.openhab.core.common.registry.AbstractProvider.notifyListenersAboutAddedElement(AbstractProvider.java:83)

plus 4 threads looking like this:

"OH-thingHandler-2" Id=735 in BLOCKED on lock=java.lang.Object@619cedf7
     owned by OH-thingHandler-5 Id=742
    at org.smarthomej.binding.amazonechocontrol.internal.handler.AccountHandler.checkData(AccountHandler.java:464)
    at org.smarthomej.binding.amazonechocontrol.internal.handler.AccountHandler$$Lambda$1237/0x0000000101132040.run(Unknown Source)
    at java.base@11.0.15/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base@11.0.15/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base@11.0.15/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
    at java.base@11.0.15/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base@11.0.15/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.15/java.lang.Thread.run(Thread.java:829)

I enabled trace logging, and found the slowest lines, isolating to just them (serial numbers redacted, but changed to placeholders to see repeated requests):

2022-07-20 15:40:07.998 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=A&deviceType=A27VEYGQBW3YR5&screenWidth=1440
2022-07-20 15:40:10.274 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=A&deviceType=A27VEYGQBW3YR5&screenWidth=1440
2022-07-20 15:40:12.507 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=A&deviceType=A27VEYGQBW3YR5&screenWidth=1440
2022-07-20 15:40:14.748 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=A&deviceType=A27VEYGQBW3YR5&screenWidth=1440
2022-07-20 15:40:18.354 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=B&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:40:20.594 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=B&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:40:22.834 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=B&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:40:25.130 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=B&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:40:29.275 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=C&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:40:31.563 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=C&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:40:33.818 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=C&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:40:36.104 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=C&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:40:40.119 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=D&deviceType=A2U21SRK4QGSE1&screenWidth=1440
2022-07-20 15:40:42.401 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=D&deviceType=A2U21SRK4QGSE1&screenWidth=1440
2022-07-20 15:40:44.584 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=D&deviceType=A2U21SRK4QGSE1&screenWidth=1440
2022-07-20 15:40:46.832 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=D&deviceType=A2U21SRK4QGSE1&screenWidth=1440
2022-07-20 15:40:48.705 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=E&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:40:50.958 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=E&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:40:53.190 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=E&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:40:55.431 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=E&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:40:56.305 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=F&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:40:58.605 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=F&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:41:00.873 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=F&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440
2022-07-20 15:41:03.113 [DEBUG] [ntrol.internal.connection.Connection] - Retry call to https://alexa.amazon.com/api/np/player?deviceSerialNumber=F&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440

additional context around one of those calls:

2022-07-20 15:41:03.114 [DEBUG] [ntrol.internal.connection.Connection] - Request to url 'https://alexa.amazon.com/api/np/player?deviceSerialNumber=F&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440' fails:
org.smarthomej.binding.amazonechocontrol.internal.ConnectionException: GET url 'https://alexa.amazon.com/api/np/player?deviceSerialNumber=F&deviceType=A2H4LV5GIZ1JFT&screenWidth=1440' failed with code 400: Bad Request
        at org.smarthomej.binding.amazonechocontrol.internal.connection.Connection.makeRequest(Connection.java:515) ~[?:?]
        at org.smarthomej.binding.amazonechocontrol.internal.connection.Connection.makeRequestAndReturnString(Connection.java:383) ~[?:?]
        at org.smarthomej.binding.amazonechocontrol.internal.connection.Connection.makeRequestAndReturnString(Connection.java:378) ~[?:?]
        at org.smarthomej.binding.amazonechocontrol.internal.connection.Connection.getPlayer(Connection.java:901) ~[?:?]
        at org.smarthomej.binding.amazonechocontrol.internal.handler.EchoHandler.updateState(EchoHandler.java:895) ~[?:?]
        at org.smarthomej.binding.amazonechocontrol.internal.handler.AccountHandler.refreshData(AccountHandler.java:586) ~[?:?]
        at org.smarthomej.binding.amazonechocontrol.internal.handler.AccountHandler.checkData(AccountHandler.java:472) ~[?:?]
        at org.smarthomej.binding.amazonechocontrol.internal.handler.AccountHandler.setConnection(AccountHandler.java:429) ~[?:?]
        at org.smarthomej.binding.amazonechocontrol.internal.handler.AccountHandler.checkLogin(AccountHandler.java:393) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]
2022-07-20 15:41:03.115 [INFO ] [control.internal.handler.EchoHandler] - Failed to get player queue

I was curious, so I logged in to alexa.amazon.com with my browser, then went to the Now Playing page, and noticed that some background requests also fail with a 400. The response body as recording my browser:

{
    "message": null
}

and the response headers:

HTTP/1.1 400 Bad Request
Content-Type: application/json
Via: 1.1 ed42e29cddf5cc10b8ba8ca7b99004ce.cloudfront.net (CloudFront)
Date: Wed, 20 Jul 2022 21:42:31 GMT
Content-Length: 16
Connection: keep-alive
Vary: Content-Type,Accept-Encoding,X-Amzn-CDN-Cache,X-Amzn-AX-Treatment,User-Agent
X-Amz-Cf-Id: <redacted>
x-amzn-ErrorType: ExpiredPlayQueueException:http://internal.amazon.com/coral/com.amazon.dee.web.coral.model/
Server: Server
X-Amz-Cf-Pop: SLC50-C1
x-amz-rid: <redacted>
Permissions-Policy: interest-cohort=()
x-amzn-error: QUEUE_EXPIRED
x-amzn-RequestId: 643d12e8-7bd9-4cd8-afa1-10f46edc43fd
X-Cache: Error from cloudfront

[ccutrer]

I think ideally I'd like to see two things happen - first, recognize that x-amzn-error: QUEUE_EXPIRED response and don't bother retrying. second, override BaseThingHandler.channelLinked to do a "soft" refresh - only refresh if it's been a while

[J-N-K]

Please change the 3rd party add-on service to https://download.smarthomej.org/addons.json|https://download.smarthomej.org/addons-beta.json, uninstall the binding and install the "Develop" version. I have added code to check for the queue error and prevent retries in that case and also a cache for plain GET requests.

[ccutrer]

👍 much better. It now only takes 14s to create all of my items

[J-N-K]

Unfortunately I found an issue with the refresh after command which is also by-passed. I have created a new version, can you check if that also works?

[ccutrer]

yes, it still seems to be working