android icon indicating copy to clipboard operation
android copied to clipboard

Published 20 hours ago • verified publisher icon home-assistant

App continues receiving state change events while the screen is off after connectivity change

Open doug-hoffman opened this issue 2 years ago • 4 comments

Home Assistant Android version:

beta-2556-a6341251-full

Android version:

12

Phone model:

Pixel 6 Pro

Home Assistant version:

2022.8.1

Description of problem:

While the screen is turned off, I'm seeing state change events logged. Force closing app temporarily resolves.

Toggling cellular/wifi (to force a network change) and turning screen off within a few seconds sometimes triggers the issue.

Additional information:

Alternative trigger to #2750

Logs 
08-07 15:14:09.119 17801 22849 E WebSocketRepository: Websocket: onFailure
08-07 15:14:09.119 17801 22849 E WebSocketRepository: java.net.SocketException: Software caused connection abort
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at java.net.SocketInputStream.socketRead0(Native Method)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at java.net.SocketInputStream.socketRead(SocketInputStream.java:118)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at java.net.SocketInputStream.read(SocketInputStream.java:173)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at java.net.SocketInputStream.read(SocketInputStream.java:143)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at com.android.org.conscrypt.ConscryptEngineSocket.readFromSocket(ConscryptEngineSocket.java:945)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at com.android.org.conscrypt.ConscryptEngineSocket.processDataFromSocket(ConscryptEngineSocket.java:909)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at com.android.org.conscrypt.ConscryptEngineSocket.readUntilDataAvailable(ConscryptEngineSocket.java:824)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at com.android.org.conscrypt.ConscryptEngineSocket.read(ConscryptEngineSocket.java:797)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at okio.InputStreamSource.read(JvmOkio.kt:94)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at okio.AsyncTimeout.read(AsyncTimeout.kt:125)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at okio.RealBufferedSource.request(RealBufferedSource.kt:206)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at okio.RealBufferedSource.require(RealBufferedSource.kt:199)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at okio.RealBufferedSource.readByte(RealBufferedSource.kt:209)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.kt:119)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.kt:102)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at okhttp3.internal.ws.RealWebSocket.loopReader(RealWebSocket.kt:293)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at okhttp3.internal.ws.RealWebSocket.onResponse(RealWebSocket.kt:195)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at okhttp3.internal.connection.RealCall.run(RealCall.kt:519)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at java.util.concurrent.ThreadPoolExecutor.run(ThreadPoolExecutor.java:637)
08-07 15:14:09.119 17801 22849 E WebSocketRepository: at java.lang.Thread.run(Thread.java:1012)
08-07 15:14:09.125 17801 17801 E TemplateWidget: Unable to render template: {{ state_attr('sensor.status_report', 'report') }}
08-07 15:14:09.126 17801 17801 E TemplateWidget: Unable to render template: {{ state_attr('sensor.status_report', 'report') }}
08-07 15:14:10.823 17801 17801 D SensorReceiver: Received intent: android.net.wifi.WIFI_STATE_CHANGED
08-07 15:14:10.823 17801 17801 D SensorReceiver: Sensor wifi_state corresponding to received event android.net.wifi.WIFI_STATE_CHANGED is disabled, skipping sensors update
08-07 15:14:11.168 17801 17801 D SensorReceiver: Received intent: android.net.wifi.WIFI_STATE_CHANGED
08-07 15:14:11.169 17801 17801 D SensorReceiver: Sensor wifi_state corresponding to received event android.net.wifi.WIFI_STATE_CHANGED is disabled, skipping sensors update
08-07 15:14:11.434 17801 26923 D UrlRepository: localUrl is: false and usesInternalSsid is: false
08-07 15:14:11.435 17801 17855 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=b38d7fe0-143a-4ff2-a774-6ae872271102, tags={ io.homeassistant.companion.android.websocket.WebsocketManager } ]
08-07 15:14:14.240 17801 17801 D SensorReceiver: Received intent: android.net.wifi.STATE_CHANGE
08-07 15:14:14.241 17801 17801 D LastUpdate: Last update is android.net.wifi.STATE_CHANGE
08-07 15:14:14.251 17801 26923 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:14.252 17801 26923 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:14.265 17801 26923 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:14.266 17801 17828 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=455508ce-55d1-4b33-830e-8271d8d7e7db, tags={ io.homeassistant.companion.android.websocket.WebsocketManager } ]
08-07 15:14:14.267 17801 18106 E SensorReceiver: Error while getting core config to sync sensor status
08-07 15:14:14.267 17801 18106 D ActivitySM: Unregistering for activity updates.
08-07 15:14:14.268 17801 18106 D ActivitySM: Registering for activity updates.
08-07 15:14:14.323 17801 18106 D NextAlarm: Next alarm is scheduled by com.google.android.deskclock with trigger time 1659958200000
08-07 15:14:14.343 17801 18106 D SensorReceiver: Nothing to update
08-07 15:14:14.734 17801 17801 D SensorReceiver: Received intent: android.net.wifi.STATE_CHANGE
08-07 15:14:14.735 17801 17801 D LastUpdate: Last update is android.net.wifi.STATE_CHANGE
08-07 15:14:14.738 17801 18106 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:14.740 17801 18106 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:14.744 17801 18106 E SensorReceiver: Error while getting core config to sync sensor status
08-07 15:14:14.745 17801 18106 D ActivitySM: Unregistering for activity updates.
08-07 15:14:14.745 17801 18106 D ActivitySM: Registering for activity updates.
08-07 15:14:14.761 17801 26923 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:14.761 17801 17828 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=780544a7-dfe7-45a5-a2a7-a80dc2f1b89c, tags={ io.homeassistant.companion.android.websocket.WebsocketManager } ]
08-07 15:14:14.809 17801 17801 D SensorReceiver: Received intent: android.net.wifi.STATE_CHANGE
08-07 15:14:14.814 17801 17801 D LastUpdate: Last update is android.net.wifi.STATE_CHANGE
08-07 15:14:14.820 17801 17801 D SensorReceiver: Received intent: android.net.wifi.STATE_CHANGE
08-07 15:14:14.821 17801 17801 D LastUpdate: Last update is android.net.wifi.STATE_CHANGE
08-07 15:14:14.836 17801 18106 D NextAlarm: Next alarm is scheduled by com.google.android.deskclock with trigger time 1659958200000
08-07 15:14:14.855 17801 18106 D SensorReceiver: Nothing to update
08-07 15:14:14.889 17801 22985 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:14.891 17801 23752 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:14.891 17801 18212 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:14.892 17801 17854 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=01abfeb9-3745-4f74-b750-76c17372f47e, tags={ io.homeassistant.companion.android.websocket.WebsocketManager } ]
08-07 15:14:15.063 17801 18212 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:15.065 17801 22985 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:15.068 17801 18212 E SensorReceiver: Error while getting core config to sync sensor status
08-07 15:14:15.069 17801 22985 E SensorReceiver: Error while getting core config to sync sensor status
08-07 15:14:15.069 17801 18212 D ActivitySM: Unregistering for activity updates.
08-07 15:14:15.069 17801 18212 D ActivitySM: Registering for activity updates.
08-07 15:14:15.070 17801 22985 D ActivitySM: Unregistering for activity updates.
08-07 15:14:15.070 17801 22985 D ActivitySM: Registering for activity updates.
08-07 15:14:15.218 17801 18212 D NextAlarm: Next alarm is scheduled by com.google.android.deskclock with trigger time 1659958200000
08-07 15:14:15.221 17801 22985 D NextAlarm: Next alarm is scheduled by com.google.android.deskclock with trigger time 1659958200000
08-07 15:14:15.256 17801 18212 D SensorReceiver: Nothing to update
08-07 15:14:15.257 17801 22985 D SensorReceiver: Nothing to update
08-07 15:14:18.092 17801 17801 D SensorReceiver: Received intent: android.net.wifi.STATE_CHANGE
08-07 15:14:18.093 17801 17801 D LastUpdate: Last update is android.net.wifi.STATE_CHANGE
08-07 15:14:18.125 17801 17801 D SensorReceiver: Received intent: android.net.wifi.STATE_CHANGE
08-07 15:14:18.126 17801 17801 D LastUpdate: Last update is android.net.wifi.STATE_CHANGE
08-07 15:14:18.133 17801 22985 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:18.134 17801 18106 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:18.134 17801 18212 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:18.135 17801 22985 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:18.135 17801 17855 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=f085652d-8ba6-450b-b05b-e496638f0cc8, tags={ io.homeassistant.companion.android.websocket.WebsocketManager } ]
08-07 15:14:18.138 17801 18212 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:18.142 17801 18212 E SensorReceiver: Error while getting core config to sync sensor status
08-07 15:14:18.143 17801 18212 D ActivitySM: Unregistering for activity updates.
08-07 15:14:18.143 17801 18212 D ActivitySM: Registering for activity updates.
08-07 15:14:18.145 17801 22985 E SensorReceiver: Error while getting core config to sync sensor status
08-07 15:14:18.146 17801 22985 D ActivitySM: Unregistering for activity updates.
08-07 15:14:18.146 17801 22985 D ActivitySM: Registering for activity updates.
08-07 15:14:18.168 17801 17801 D LocBroadcastReceiver: Received location update.
08-07 15:14:18.170 17801 17801 D ForegrndServiceLauncher: Check if service HighAccuracyLocationService is running. Service running = false
08-07 15:14:18.170 17801 17801 D LocBroadcastReceiver: Last Location: 
08-07 15:14:18.170 17801 17801 D LocBroadcastReceiver: Coords:(x, y)
08-07 15:14:18.170 17801 17801 D LocBroadcastReceiver: Accuracy: 13.35
08-07 15:14:18.170 17801 17801 D LocBroadcastReceiver: Bearing: 0.0
08-07 15:14:18.170 17801 17801 D LocBroadcastReceiver: Begin evaluating if location update should be skipped
08-07 15:14:18.170 17801 17801 D LocBroadcastReceiver: Received location that is 35533 milliseconds old, 1659899622637 compared to 1659899658170 with source fused
08-07 15:14:18.178 17801 26923 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:18.188 17801 26923 E LocBroadcastReceiver: Could not update location.
08-07 15:14:18.272 17801 17801 D LocBroadcastReceiver: Received location update.
08-07 15:14:18.273 17801 17801 D ForegrndServiceLauncher: Check if service HighAccuracyLocationService is running. Service running = false
08-07 15:14:18.273 17801 17801 D LocBroadcastReceiver: Last Location: 
08-07 15:14:18.273 17801 17801 D LocBroadcastReceiver: Coords:(x, y)
08-07 15:14:18.273 17801 17801 D LocBroadcastReceiver: Accuracy: 13.35
08-07 15:14:18.273 17801 17801 D LocBroadcastReceiver: Bearing: 0.0
08-07 15:14:18.273 17801 17801 D LocBroadcastReceiver: Begin evaluating if location update should be skipped
08-07 15:14:18.273 17801 17801 D LocBroadcastReceiver: Received location that is 62 milliseconds old, 1659899658211 compared to 1659899658273 with source fused
08-07 15:14:18.273 17801 17801 D LocBroadcastReceiver: Duplicate location received, not sending to HA
08-07 15:14:18.421 17801 22985 D NextAlarm: Next alarm is scheduled by com.google.android.deskclock with trigger time 1659958200000
08-07 15:14:18.428 17801 18212 D NextAlarm: Next alarm is scheduled by com.google.android.deskclock with trigger time 1659958200000
08-07 15:14:18.502 17801 22985 D SensorReceiver: Nothing to update
08-07 15:14:18.512 17801 18212 D SensorReceiver: Nothing to update
08-07 15:14:19.123 17801 18212 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:19.123 17801 18212 D UrlRepository: Using external URL
08-07 15:14:19.124 17801 18212 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:19.124 17801 18212 D UrlRepository: Using external URL
08-07 15:14:19.196 17801 22849 D WebSocketRepository: Websocket: onOpen
08-07 15:14:19.199 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:19.199 17801 22849 D WebSocketRepository: Message number null received: {"type":"auth_required","ha_version":"2022.8.1"}
08-07 15:14:19.199 17801 18212 D WebSocketRepository: Auth Requested
08-07 15:14:19.203 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:19.203 17801 22849 D WebSocketRepository: Message number null received: {"type":"auth_ok","ha_version":"2022.8.1"}
08-07 15:14:19.203 17801 18212 D WebSocketRepository: Sending message 58: {type=subscribe_events, event_type=state_changed, id=58}
08-07 15:14:19.204 17801 18212 D WebSocketRepository: Message number 58 sent
08-07 15:14:19.211 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:19.211 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"result","success":true,"result":null}
08-07 15:14:19.763 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:19.764 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:19.764 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:19.764 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:19.764 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:19.765 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:19.765 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:19.765 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:19.775 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:19.779 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:19.782 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:19.785 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:20.299 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:20.300 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:20.301 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:20.301 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:20.302 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:20.302 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:20.302 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:20.303 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:20.309 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:20.311 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:20.314 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:20.316 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:20.316 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:20.317 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:20.318 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:20.318 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:20.318 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:20.318 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:20.318 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:20.318 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:20.326 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:20.330 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:20.333 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:20.336 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:21.327 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:21.328 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:21.328 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:21.328 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:21.328 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:21.328 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:21.329 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:21.329 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:21.330 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:21.330 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:21.336 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:21.341 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:21.342 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:21.342 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:21.342 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:21.342 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:21.342 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:21.345 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:21.350 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:21.352 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:21.354 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:21.357 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:21.359 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:21.361 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:21.906 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:21.907 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:21.919 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:22.387 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:22.388 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:22.388 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:22.388 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:22.388 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:22.388 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:22.388 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:22.389 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:22.396 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:22.402 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:22.405 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:22.410 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:22.722 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:22.723 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:22.733 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:22.884 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:22.884 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:22.894 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:24.039 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:24.040 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:24.041 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:24.041 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:24.153 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:24.159 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:24.209 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:24.210 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:24.210 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:24.211 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:24.222 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:24.225 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:24.795 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:24.796 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]
08-07 15:14:24.803 17801 17801 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:25.096 17801 17801 D ActivitySM: Received activity update.
08-07 15:14:25.098 17801 17801 D SensorReceiver: Received intent: android.intent.action.SCREEN_OFF
08-07 15:14:25.098 17801 17801 D SensorReceiver: Sensor is_interactive corresponding to received event android.intent.action.SCREEN_OFF is disabled, skipping sensors update
08-07 15:14:25.100 17801 17801 D ButtonWidget: Broadcast received: 
08-07 15:14:25.100 17801 17801 D ButtonWidget: Broadcast action: android.intent.action.SCREEN_OFF
08-07 15:14:25.100 17801 17801 D ButtonWidget: AppWidgetId: -1
08-07 15:14:25.102 17801 17801 D MediaPlayCtrlsWidget: Broadcast received: 
08-07 15:14:25.102 17801 17801 D MediaPlayCtrlsWidget: Broadcast action: android.intent.action.SCREEN_OFF
08-07 15:14:25.102 17801 17801 D MediaPlayCtrlsWidget: AppWidgetId: -1
08-07 15:14:25.104 17801 17831 D WebSocketRepository: Unsubscribing from state_changed
08-07 15:14:25.104 17801 17831 D WebSocketRepository: Sending message 59: {type=unsubscribe_events, subscription=57, id=59}
08-07 15:14:25.104 17801 17831 D WebSocketRepository: Message number 59 sent
08-07 15:14:25.121 17801 17831 D UrlRepository: localUrl is: false and usesInternalSsid is: true
08-07 15:14:25.122 17801 17855 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=22ebb032-da5b-4e6a-a6bd-76cb0f4b33d6, tags={ io.homeassistant.companion.android.websocket.WebsocketManager } ]
08-07 15:14:25.215 17801 22849 D WebSocketRepository: Websocket: onMessage (text)
08-07 15:14:25.216 17801 22849 D WebSocketRepository: Message number 58 received: {"id":58,"type":"event","event":{"event_type":"state_changed",[...]

doug-hoffman avatar Aug 07 '22 19:08 doug-hoffman

thanks for reporting another case for this!

dshokouhi avatar Aug 07 '22 19:08 dshokouhi

From my rough understanding of common/src/main/java/io/homeassistant/companion/android/common/data/websocket/impl/WebSocketRepositoryImpl.kt, it seems we're resubscribing if there is an active connection within 10 seconds:

        // If we still have flows flowing
        if ((eventSubscriptionFlow.any() || notificationFlow != null) && ioScope.isActive) {
            ioScope.launch {
                delay(10000)
                if (connect()) {
                    eventSubscriptionFlow.forEach { (eventType, _) ->
                        val resp = sendMessage(
                            mapOf(
                                "type" to "subscribe_events",
                                "event_type" to eventType
                            )
                        )
                        if (resp == null) {
                            Log.e(TAG, "Issue re-registering event subscriptions")
                        }
                    }

But when awaitClose {} gets executed later, response.id is going to be the original id from the old connection.

                eventSubscriptionFlow[eventType] = callbackFlow<T> {
                    eventSubscriptionProducerScope[eventType] = this as ProducerScope<Any>
                    awaitClose {
                        Log.d(TAG, "Unsubscribing from $eventType")
                        ioScope.launch {
                            sendMessage(
                                mapOf(
                                    "type" to "unsubscribe_events",
                                    "subscription" to response.id
                                )
                            )
                        }
                        eventSubscriptionProducerScope.remove(eventType)
                        eventSubscriptionFlow.remove(eventType)
                    }
                }.shareIn(ioScope, SharingStarted.WhileSubscribed())

doug-hoffman avatar Aug 07 '22 19:08 doug-hoffman

Ok made some more updates to the PR. I believe it is ready for testing now 🤞 . Would you be able to try the debug APK from to see if you can reproduce the issue still?

https://github.com/home-assistant/android/actions/runs/2828004224

dshokouhi avatar Aug 09 '22 19:08 dshokouhi

That fixed it. Thanks!

doug-hoffman avatar Aug 10 '22 13:08 doug-hoffman