-
-
Notifications
You must be signed in to change notification settings - Fork 1k
Detect silently dropped WebSocket connections and retry until subscriptions are restored #7164
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from 1 commit
3bb142c
9423e90
75c4b99
60df276
2e636e4
d60e7a5
3a4e4b3
9960362
3bb983f
28c5d56
ea186d7
08e61d0
2e979bc
53f6b47
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -182,6 +182,9 @@ internal class WebSocketCoreImpl( | |
| @Volatile | ||
| private var pendingCloseReason: WebSocketState.Closed.Reason? = null | ||
|
|
||
| /** The running subscription restore loop, replaced on each closing so only one runs at a time. */ | ||
| private var reconnectJob: Job? = null | ||
|
|
||
| /** | ||
| * A [CompletableDeferred] that signals the establishment and authentication of a WebSocket connection. | ||
| * | ||
|
|
@@ -1036,38 +1039,65 @@ internal class WebSocketCoreImpl( | |
| val shouldAttemptReconnect = hasSubscriptions && wasActive | ||
|
|
||
| if (shouldAttemptReconnect && wsScope.isActive) { | ||
| // Delay before reconnect unless URL changed | ||
| if (closeReason != WebSocketState.Closed.Reason.CHANGED_URL) { | ||
| delay(DELAY_BEFORE_RECONNECT) | ||
| // A new closing takes over the restore loop with a fresh snapshot | ||
| reconnectJob?.cancel() | ||
| reconnectJob = wsScope.launch { | ||
| // Delay before reconnect unless URL changed | ||
| if (closeReason != WebSocketState.Closed.Reason.CHANGED_URL) { | ||
| delay(DELAY_BEFORE_RECONNECT) | ||
| } | ||
| reconnectSubscriptions() | ||
| } | ||
| reconnectSubscriptions() | ||
| } | ||
| } | ||
| } | ||
|
|
||
| private suspend fun reconnectSubscriptions() { | ||
| if (connect()) { | ||
| Timber.d("Resubscribing to active subscriptions...") | ||
| activeMessages.filterValues { it is ActiveMessage.Subscription }.entries | ||
| .forEach { (oldId, oldActiveMessage) -> | ||
| oldActiveMessage as ActiveMessage.Subscription | ||
| activeMessages.remove(oldId) | ||
|
|
||
| val response = sendMessage( | ||
| Command.WithAnswer.Subscription( | ||
| request = oldActiveMessage.request, | ||
| eventFlow = oldActiveMessage.eventFlow, | ||
| onEvent = oldActiveMessage.onEvent, | ||
| ), | ||
| ) | ||
| if (response == null || response.success != true) { | ||
| Timber.e("Issue re-registering subscription with ${oldActiveMessage.request}") | ||
| } | ||
| var toRestore: Set<Long> = activeMessages.filterValues { it is ActiveMessage.Subscription }.keys | ||
| while (toRestore.isNotEmpty()) { | ||
| if (connect()) { | ||
| toRestore = resubscribeActiveSubscriptions(toRestore) | ||
| if (toRestore.isEmpty()) return | ||
| Timber.w("${toRestore.size} subscriptions not restored, retrying in $DELAY_BEFORE_RECONNECT") | ||
| } else { | ||
| if (getConnectionState() == WebSocketState.ClosedAuth) { | ||
| Timber.e("Authentication failed, not retrying to resubscribe to active subscriptions") | ||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. When this happens the subscriptions stay in activeMessages but are never resubscribed. Even if auth is fixed later (a new token for instance), the next successful connection comes up with zero registrations on the server side and nothing restores them until the next socket closing. The more I look at this, the more I think the resubscription trigger belongs at the end of connect() rather than in the closing path: when a fresh connection is established and activeMessages still contains Subscription entries from a previous connection, start the restore job for them. Semantically it reads as "connect, then re-register anything left over from the previous connection". A fresh socket has no registrations by definition, so any tracked subscription at that point needs restoring. This matters especially because any sendMessage can theoretically reconnect the WebSocket (the worker's ping does this every 30s) and leave the subscriptions tracked but not subscribed. Note: it would need to launch the job (guarded by reconnectJob like today) rather than resubscribe inline: inline it would deadlock on connectedMutex and make unrelated sendMessage callers wait on the restoration. The closing-path loop would still be needed to actively retry while the server is unreachable; the connect() trigger would be the safety net for every other way a connection comes back. This is an idea to explore.
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
This makes logical sense. However, one of the reasons for putting it in the closing was to ensure a delay before retrying. Most connection failures are temporary due to a network change - immediately retrying will fail but a couple of seconds later there is a network again so it will work. The delay before attempting to setup a new connection should stay.
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I agree, I want to move only the logic of opening again the pending subscription out of this and directly in the connect path. I'm going to propose something within the PR |
||
| return | ||
| } | ||
| } else { | ||
| // TODO https://github.com/home-assistant/android/issues/5259 handle re-connection gracefully or terminates the flows | ||
| Timber.w("Unable to reconnect, cannot resubscribe to active subscriptions") | ||
| Timber.w( | ||
| "Unable to reconnect, retrying in $DELAY_BEFORE_RECONNECT to resubscribe to active subscriptions", | ||
| ) | ||
| } | ||
| delay(DELAY_BEFORE_RECONNECT) | ||
| // Subscriptions closed while waiting no longer need to be restored | ||
| toRestore = toRestore.filterTo(mutableSetOf()) { activeMessages[it] is ActiveMessage.Subscription } | ||
| } | ||
| } | ||
|
|
||
| /** @return the ids of the subscriptions that could not be restored and are kept for a retry */ | ||
| private suspend fun resubscribeActiveSubscriptions(oldIds: Set<Long>): Set<Long> { | ||
| Timber.d("Resubscribing to active subscriptions...") | ||
| val failed = mutableSetOf<Long>() | ||
| oldIds.forEach { oldId -> | ||
| val oldActiveMessage = activeMessages[oldId] as? ActiveMessage.Subscription ?: return@forEach | ||
|
|
||
| val response = sendMessage( | ||
| Command.WithAnswer.Subscription( | ||
| request = oldActiveMessage.request, | ||
| eventFlow = oldActiveMessage.eventFlow, | ||
| onEvent = oldActiveMessage.onEvent, | ||
| ), | ||
| ) | ||
| if (response == null || response.success != true) { | ||
| failed += oldId | ||
| // Drop the rejected attempt, the kept original is retried instead | ||
| response?.id?.let { activeMessages.remove(it) } | ||
| Timber.e("Issue re-registering subscription with ${oldActiveMessage.request}") | ||
| } else { | ||
| activeMessages.remove(oldId) | ||
| } | ||
| } | ||
|
markfrancisonly marked this conversation as resolved.
Outdated
|
||
| return failed | ||
| } | ||
|
|
||
| private fun URL.toWebSocketURL(): String { | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -1445,6 +1445,191 @@ misc | |
| } | ||
| } | ||
|
|
||
| @Test | ||
|
TimoPtr marked this conversation as resolved.
Outdated
|
||
| fun `Given an Active subscription When the server stays unavailable Then it retries until the server is back and resubscribes`() = runTest { | ||
| setupServer(backgroundScope = backgroundScope) | ||
| prepareAuthenticationAnswer() | ||
| assertTrue(webSocketCore.connect()) | ||
|
|
||
| mockResultSuccessForId(2) | ||
| val subscription = checkNotNull( | ||
| webSocketCore.subscribeTo<StateChangedEvent>( | ||
| SUBSCRIBE_TYPE_SUBSCRIBE_EVENTS, | ||
| mapOf("event_type" to "state_changed"), | ||
| ), | ||
| ) | ||
|
|
||
| subscription.test { | ||
| // The server becomes unavailable: the auth message cannot be sent anymore | ||
| every { mockConnection.send(match<String> { it.contains(""""type":"auth"""") }) } returns false | ||
| var connectionAttemptCount = 0 | ||
| every { mockOkHttpClient.newWebSocket(any(), any()) } answers { | ||
| connectionAttemptCount++ | ||
| mockConnection | ||
| } | ||
| closeConnection() | ||
|
|
||
| // The first attempt after the delay fails, the subscription is kept and retries continue | ||
| advanceTimeBy(11.seconds) | ||
| runCurrent() | ||
| assertTrue(connectionAttemptCount >= 1, "Should have attempted to reconnect") | ||
| advanceTimeBy(30.seconds) | ||
| runCurrent() | ||
| assertTrue(connectionAttemptCount >= 3, "Should keep retrying while the server is unavailable") | ||
| assertTrue( | ||
| webSocketCore.activeMessages.any { it.value is ActiveMessage.Subscription }, | ||
| "Subscription should still be tracked while retrying", | ||
| ) | ||
|
|
||
| // The server is back, the next retry reconnects and resubscribes with a new ID | ||
| prepareAuthenticationAnswer() | ||
| var resubscribeId: Long? = null | ||
| every { | ||
| mockConnection.send(match<String> { it.contains(""""type":"$SUBSCRIBE_TYPE_SUBSCRIBE_EVENTS"""") }) | ||
| } answers { | ||
| val id = checkNotNull(Regex(""""id":(\d+)""").find(firstArg<String>())?.groupValues?.get(1)?.toLong()) | ||
| resubscribeId = id | ||
| webSocketListener.onMessage( | ||
| mockConnection, | ||
| """{"id":$id,"type":"result","success":true,"result":{}}""", | ||
| ) | ||
| true | ||
| } | ||
| advanceTimeBy(11.seconds) | ||
| runCurrent() | ||
|
|
||
| val newId = checkNotNull(resubscribeId) { "Subscription should have been re-registered" } | ||
| assertNotEquals(2L, newId) | ||
| webSocketListener.onMessage( | ||
| mockConnection, | ||
| """{"id":$newId, "type":"event", "event":{"event_type":"state_changed", "time_fired":"2016-11-26T01:37:24.265429+00:00", "data": {"entity_id":"light.bed_light"}}}""", | ||
| ) | ||
| assertEquals("light.bed_light", awaitItem().entityId) | ||
| } | ||
| } | ||
|
|
||
| @Test | ||
| fun `Given a resubscription rejected on a live connection Then it is retried until restored`() = runTest { | ||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Reformulate to add |
||
| setupServer(backgroundScope = backgroundScope) | ||
| prepareAuthenticationAnswer() | ||
| assertTrue(webSocketCore.connect()) | ||
|
|
||
| mockResultSuccessForId(2) | ||
| val subscription = checkNotNull( | ||
| webSocketCore.subscribeTo<StateChangedEvent>( | ||
| SUBSCRIBE_TYPE_SUBSCRIBE_EVENTS, | ||
| mapOf("event_type" to "state_changed"), | ||
| ), | ||
| ) | ||
|
|
||
| subscription.test { | ||
| // The server rejects the first resubscription on the restored connection | ||
| var subscribeAttempts = 0 | ||
| var lastSubscribeId: Long? = null | ||
| every { | ||
| mockConnection.send(match<String> { it.contains(""""type":"$SUBSCRIBE_TYPE_SUBSCRIBE_EVENTS"""") }) | ||
| } answers { | ||
| val id = checkNotNull(Regex(""""id":(\d+)""").find(firstArg<String>())?.groupValues?.get(1)?.toLong()) | ||
| subscribeAttempts++ | ||
| lastSubscribeId = id | ||
| webSocketListener.onMessage( | ||
| mockConnection, | ||
| """{"id":$id,"type":"result","success":${subscribeAttempts > 1},"result":{}}""", | ||
| ) | ||
| true | ||
| } | ||
| closeConnection() | ||
|
|
||
| advanceTimeBy(11.seconds) | ||
| runCurrent() | ||
| assertEquals(1, subscribeAttempts, "First resubscription should have been attempted") | ||
| assertEquals( | ||
| 1, | ||
| webSocketCore.activeMessages.count { it.value is ActiveMessage.Subscription }, | ||
| "The rejected attempt should be dropped and the original kept for a retry", | ||
| ) | ||
|
|
||
| // The retry happens on the live connection without another disconnection | ||
| advanceTimeBy(11.seconds) | ||
| runCurrent() | ||
| assertEquals(2, subscribeAttempts, "The rejected subscription should have been retried") | ||
|
|
||
| val newId = checkNotNull(lastSubscribeId) | ||
| webSocketListener.onMessage( | ||
| mockConnection, | ||
| """{"id":$newId, "type":"event", "event":{"event_type":"state_changed", "time_fired":"2016-11-26T01:37:24.265429+00:00", "data": {"entity_id":"light.bed_light"}}}""", | ||
| ) | ||
| assertEquals("light.bed_light", awaitItem().entityId) | ||
| assertEquals( | ||
| 1, | ||
| webSocketCore.activeMessages.count { it.value is ActiveMessage.Subscription }, | ||
| "Only the restored subscription should remain", | ||
| ) | ||
| } | ||
| } | ||
|
|
||
| @Test | ||
| fun `Given a resubscription without acknowledgement When reconnecting again Then the subscription is restored`() = runTest { | ||
| setupServer(backgroundScope = backgroundScope) | ||
| prepareAuthenticationAnswer() | ||
| assertTrue(webSocketCore.connect()) | ||
|
|
||
| mockResultSuccessForId(2) | ||
| val subscription = checkNotNull( | ||
| webSocketCore.subscribeTo<StateChangedEvent>( | ||
| SUBSCRIBE_TYPE_SUBSCRIBE_EVENTS, | ||
| mapOf("event_type" to "state_changed"), | ||
| ), | ||
| ) | ||
|
|
||
| subscription.test { | ||
| // First reconnection: the subscribe request is sent but never acknowledged | ||
| every { | ||
| mockConnection.send(match<String> { it.contains(""""type":"$SUBSCRIBE_TYPE_SUBSCRIBE_EVENTS"""") }) | ||
| } returns true | ||
| closeConnection() | ||
| advanceTimeBy(11.seconds) | ||
| runCurrent() | ||
|
|
||
| // Once the answer times out the subscription must be kept for the next reconnection | ||
| advanceTimeBy(31.seconds) | ||
| runCurrent() | ||
| assertTrue( | ||
| webSocketCore.activeMessages.any { it.value is ActiveMessage.Subscription }, | ||
| "Subscription should be kept when the resubscription is not acknowledged", | ||
| ) | ||
|
|
||
| // Second reconnection: the subscribe request is acknowledged and events flow again | ||
| var resubscribeId: Long? = null | ||
| every { | ||
| mockConnection.send(match<String> { it.contains(""""type":"$SUBSCRIBE_TYPE_SUBSCRIBE_EVENTS"""") }) | ||
| } answers { | ||
| val id = checkNotNull(Regex(""""id":(\d+)""").find(firstArg<String>())?.groupValues?.get(1)?.toLong()) | ||
| resubscribeId = id | ||
| webSocketListener.onMessage( | ||
| mockConnection, | ||
| """{"id":$id,"type":"result","success":true,"result":{}}""", | ||
| ) | ||
| true | ||
| } | ||
| closeConnection() | ||
| advanceTimeBy(11.seconds) | ||
| runCurrent() | ||
|
|
||
| val newId = checkNotNull(resubscribeId) { "Subscription should have been re-registered" } | ||
| webSocketListener.onMessage( | ||
| mockConnection, | ||
| """{"id":$newId, "type":"event", "event":{"event_type":"state_changed", "time_fired":"2016-11-26T01:37:24.265429+00:00", "data": {"entity_id":"light.bed_light"}}}""", | ||
| ) | ||
| assertEquals("light.bed_light", awaitItem().entityId) | ||
| assertEquals( | ||
| 1, | ||
| webSocketCore.activeMessages.count { it.value is ActiveMessage.Subscription }, | ||
| "Only the acknowledged subscription should remain", | ||
| ) | ||
| } | ||
| } | ||
|
|
||
| @Test | ||
| fun `Given pending simple messages When connection closes during URL change Then they complete with exception`() = runTest { | ||
| val urlFlow = MutableStateFlow<UrlState>(UrlState.HasUrl("https://io.ha".toHttpUrlOrNull()?.toUrl())) | ||
|
|
||
Uh oh!
There was an error while loading. Please reload this page.