Android TV loses connection after wake from sleep - Internal Server Error

[Yezariael75]

Is there an existing issue for this?

• I have searched the existing issues

Description

I added Nvidia Shield over Android TV integration. Works fine but if remote goes to sleep and wakes up connection to network is lost. Only solution is to reboot the device.

How to Reproduce

1. Add Android TV integration with Nvidia Shield
2. Start activity for Nvidia Shield (Plex)
3. Wait until remote goes to sleep
4. press a button - connection lost and does no get established again until reboot of device -> Message "Internal Server Error"

I assume the android tv integration crashes in the background?

Expected behavior

Remote wakes up and establishes connection, can be used as before sleep.

System version

1.1.1

What part of the system affected by the problem?

Integration

Additional context

No response

[vistalba]

I run into the same issue. Also nVidia Shield. Quite annoying.

[splattner]

not sure if I see the same issue here. I was able to add my Android TV and initially it worked and I could use it. But then suddenly, it stopped.
Not seeing anything in the log:

2023-09-11 12:58:07.792542 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:->: {"kind": "resp", "req_id": 109, "code": 200, "msg": "result", "msg_data": {}}
2023-09-11 12:58:07.787115 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:<-: {"kind":"req","id":109,"msg":"entity_command","msg_data":{"cmd_id":"cursor_up","entity_id":"D4F8292E8A2C","entity_type":"media_player"}}
2023-09-11 12:58:07.332477 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:->: {"kind": "resp", "req_id": 108, "code": 200, "msg": "result", "msg_data": {}}
2023-09-11 12:58:07.326893 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:<-: {"kind":"req","id":108,"msg":"entity_command","msg_data":{"cmd_id":"cursor_down","entity_id":"D4F8292E8A2C","entity_type":"media_player"}}
2023-09-11 12:58:06.647171 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:->: {"kind": "resp", "req_id": 107, "code": 200, "msg": "result", "msg_data": {}}
2023-09-11 12:58:06.641784 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:<-: {"kind":"req","id":107,"msg":"entity_command","msg_data":{"cmd_id":"cursor_down","entity_id":"D4F8292E8A2C","entity_type":"media_player"}}
2023-09-11 12:58:06.176987 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:->: {"kind": "resp", "req_id": 106, "code": 200, "msg": "result", "msg_data": {}}
2023-09-11 12:58:06.171262 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:<-: {"kind":"req","id":106,"msg":"entity_command","msg_data":{"cmd_id":"cursor_left","entity_id":"D4F8292E8A2C","entity_type":"media_player"}}
2023-09-11 12:58:05.508621 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:->: {"kind": "resp", "req_id": 105, "code": 200, "msg": "result", "msg_data": {}}

Rebooting the remote, also helped.

[martonborzak]

not sure if I see the same issue here. I was able to add my Android TV and initially it worked and I could use it. But then suddenly, it stopped. Not seeing anything in the log:

2023-09-11 12:58:07.792542 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:->: {"kind": "resp", "req_id": 109, "code": 200, "msg": "result", "msg_data": {}}
2023-09-11 12:58:07.787115 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:<-: {"kind":"req","id":109,"msg":"entity_command","msg_data":{"cmd_id":"cursor_up","entity_id":"D4F8292E8A2C","entity_type":"media_player"}}
2023-09-11 12:58:07.332477 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:->: {"kind": "resp", "req_id": 108, "code": 200, "msg": "result", "msg_data": {}}
2023-09-11 12:58:07.326893 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:<-: {"kind":"req","id":108,"msg":"entity_command","msg_data":{"cmd_id":"cursor_down","entity_id":"D4F8292E8A2C","entity_type":"media_player"}}
2023-09-11 12:58:06.647171 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:->: {"kind": "resp", "req_id": 107, "code": 200, "msg": "result", "msg_data": {}}
2023-09-11 12:58:06.641784 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:<-: {"kind":"req","id":107,"msg":"entity_command","msg_data":{"cmd_id":"cursor_down","entity_id":"D4F8292E8A2C","entity_type":"media_player"}}
2023-09-11 12:58:06.176987 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:->: {"kind": "resp", "req_id": 106, "code": 200, "msg": "result", "msg_data": {}}
2023-09-11 12:58:06.171262 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:<-: {"kind":"req","id":106,"msg":"entity_command","msg_data":{"cmd_id":"cursor_left","entity_id":"D4F8292E8A2C","entity_type":"media_player"}}
2023-09-11 12:58:05.508621 +00:00	intg-androidtv	INFO	DEBUG:ucapi.api:->: {"kind": "resp", "req_id": 105, "code": 200, "msg": "result", "msg_data": {}}

Rebooting the remote, also helped.

Could you please upload logs for the Core service as well when you see this issue? Does it happen after wakeup?

[splattner]

Nothing special there 🤔

2023-09-11 13:01:44.641620 +00:00	core	NOTICE	[uc.main.3ffd1dcd-c75e-4062-9e5a-cb127d0d01c9] activity finished
2023-09-11 13:01:44.631424 +00:00	core	NOTICE	[uc.main.3ffd1dcd-c75e-4062-9e5a-cb127d0d01c9] started activity with timeout of 30s
2023-09-11 13:01:27.948520 +00:00	core	NOTICE	Setting button backlight to: 50%
2023-09-11 13:00:38.600669 +00:00	core	NOTICE	Setting button backlight to: 0%
2023-09-11 13:00:07.603638 +00:00	core	NOTICE	Setting button backlight to: 0%
2023-09-11 12:59:00.819214 +00:00	core	NOTICE	Setting button backlight to: 50%
2023-09-11 12:58:39.594664 +00:00	core	NOTICE	Setting button backlight to: 0%
2023-09-11 12:58:25.394299 +00:00	core	NOTICE	Contacting OTA server for dock update check
2023-09-11 12:58:25.316307 +00:00	core	NOTICE	Check OTA server for dock firmware update: UC-Dock-8C4B14AA7884
2023-09-11 12:56:58.818043 +00:00	core	NOTICE	Changed battery status: 70% Discharging, 3831mV, charger: false
2023-09-11 12:56:12.479010 +00:00	core	NOTICE	Setting button backlight to: 50%
2023-09-11 12:55:45.601932 +00:00	core	NOTICE	Setting button backlight to: 0%
2023-09-11 12:55:40.951151 +00:00	core	NOTICE	Ignoring invalid service name: intg-androidtv%2Cintg-appletv%2Cintg-bangolufsen%2Cintg-homeassistant%2Cintg-philipshue%2Ccore%2Cui%2Ccustom-ui%2Cwifi%2Cbt
2023-09-11 12:55:23.203450 +00:00	core	NOTICE	Contacting OTA server for dock update check
2023-09-11 12:55:23.133912 +00:00	core	NOTICE	Check OTA server for dock firmware update: UC-Dock-8C4B14AA7884
2023-09-11 12:54:52.787158 +00:00	core	NOTICE	[uc.main.3ffd1dcd-c75e-4062-9e5a-cb127d0d01c9] activity finished
2023-09-11 12:54:52.783074 +00:00	core	NOTICE	[uc.main.3ffd1dcd-c75e-4062-9e5a-cb127d0d01c9] started activity with timeout of 30s
2023-09-11 12:54:36.447254 +00:00	core	NOTICE	Contacting OTA server for dock update check
2023-09-11 12:54:36.384774 +00:00	core	NOTICE	Check OTA server for dock firmware update: UC-Dock-8C4B14AA7884
2023-09-11 12:54:21.954196 +00:00	core	NOTICE	Contacting OTA server for dock update check
2023-09-11 12:54:21.881136 +00:00	core	NOTICE	Check OTA server for dock firmware update: UC-Dock-8C4B14AA7884
2023-09-11 12:54:16.363177 +00:00	core	NOTICE	Setting button backlight to: 50%
2023-09-11 12:52:22.601048 +00:00	core	NOTICE	Setting button backlight to: 0%
2023-09-11 12:51:52.566939 +00:00	core	NOTICE	TODO implement activity button mapping
2023-09-11 12:51:51.601459 +00:00	core	NOTICE	Setting button backlight to: 0%
2023-09-11 12:51:19.967430 +00:00	core	NOTICE	[uc.main.9ad2e351-7ce4-4899-9242-05be83070468] activity finished
2023-09-11 12:51:19.958146 +00:00	core	NOTICE	[uc.main.9ad2e351-7ce4-4899-9242-05be83070468] started activity with timeout of 30s
2023-09-11 12:51:16.955417 +00:00	core	NOTICE	[uc_androidtv_driver.main] Waiting for available entities with request id: 56
2023-09-11 12:51:10.519571 +00:00	core	NOTICE	[uc_androidtv_driver.main] Waiting for available entities with request id: 55
2023-09-11 12:51:06.879002 +00:00	core	NOTICE	[hass.main] Waiting for available entities with request id: 11
2023-09-11 12:51:04.197381 +00:00	core	NOTICE	[hass.main] Waiting for available entities with request id: 10
2023-09-11 12:50:47.638122 +00:00	core	NOTICE	Setting button backlight to: 50%
2023-09-11 12:50:28.478487 +00:00	core	NOTICE	Changed battery status: 71% Discharging, 3862mV, charger: false
2023-09-11 12:46:49.605840 +00:00	core	NOTICE	Setting button backlight to: 0%
2023-09-11 12:46:18.592648 +00:00	core	NOTICE	Setting button backlight to: 0%
2023-09-11 12:45:40.305052 +00:00	core	NOTICE	Setting button backlight to: 50%
2023-09-11 12:45:32.607533 +00:00	core	NOTICE	Setting button backlight to: 0%
2023-09-11 12:44:56.802165 +00:00	core	NOTICE	Contacting OTA server for dock update check
2023-09-11 12:44:56.726083 +00:00	core	NOTICE	Check OTA server for dock firmware update: UC-Dock-8C4B14AA7884
2023-09-11 12:44:11.434673 +00:00	core	NOTICE	[uc.main.9ad2e351-7ce4-4899-9242-05be83070468] activity finished
2023-09-11 12:44:11.430164 +00:00	core	NOTICE	[uc.main.9ad2e351-7ce4-4899-9242-05be83070468] started activity with timeout of 30s
2023-09-11 12:44:03.615075 +00:00	core	NOTICE	Setting button backlight to: 50%
2023-09-11 12:43:03.099679 +00:00	core	NOTICE	Changed battery status: 72% Discharging, 3874mV, charger: false
2023-09-11 12:42:08.464154 +00:00	core	NOTICE	Sent get_entity_states: Ok(())
2023-09-11 12:42:05.740603 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] SessionAuthenticated msg
2023-09-11 12:42:05.739452 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Session state change: Authenticated
2023-09-11 12:42:05.669294 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Connected to: ws://192.168.10.240:946/
2023-09-11 12:42:05.664959 +00:00	core	WARN	[UC-Dock-8C4B14AA7884] Can't handle dock TryReconnect command in state: Connecting
2023-09-11 12:42:05.662227 +00:00	core	WARN	[UC-Dock-8C4B14AA7884] No transition for: state=Connecting, event=TryReconnect
2023-09-11 12:42:05.620109 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] WiFi connected: connecting dock
2023-09-11 12:42:05.617667 +00:00	core	NOTICE	WiFi connected: starting all external drivers
2023-09-11 12:42:05.616280 +00:00	core	NOTICE	Event: CONNECTED
2023-09-11 12:42:05.167688 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Reconnecting in: 500ms
2023-09-11 12:42:05.166260 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] on_session_disconnected: ClientDisconnect
2023-09-11 12:42:05.165243 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Session state change: Disconnected
2023-09-11 12:42:05.159292 +00:00	core	ERROR	[UC-Dock-8C4B14AA7884] Websocket server heartbeat failed, disconnecting!
2023-09-11 12:41:54.257245 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] SessionAuthenticated msg
2023-09-11 12:41:54.256059 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Session state change: Authenticated
2023-09-11 12:41:51.606821 +00:00	core	NOTICE	Setting button backlight to: 0%
2023-09-11 12:41:47.151221 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Connected to: ws://192.168.10.240:946/
2023-09-11 12:41:41.766525 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Reconnecting in: 1.853s
2023-09-11 12:41:41.765186 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] on_session_disconnected: ClientDisconnect
2023-09-11 12:41:41.764235 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Session state change: Disconnected
2023-09-11 12:41:41.758282 +00:00	core	ERROR	[UC-Dock-8C4B14AA7884] Websocket server heartbeat failed, disconnecting!
2023-09-11 12:41:29.768557 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Resolved uc-dock-8c4b14aa7884.local: 192.168.10.240
2023-09-11 12:41:29.759972 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Resolving: uc-dock-8c4b14aa7884.local
2023-09-11 12:41:29.757842 +00:00	core	NOTICE	Dock URL not resolved, trying service name
2023-09-11 12:41:29.751548 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Connected to: ws://UC-Dock-8C4B14AA7884.local:946
2023-09-11 12:41:24.358424 +00:00	core	NOTICE	Dock URL not resolved, trying service name
2023-09-11 12:41:22.931029 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Reconnecting in: 1.426s
2023-09-11 12:41:22.925589 +00:00	core	ERROR	[UC-Dock-8C4B14AA7884] Error connecting to dock: TimedOut
2023-09-11 12:41:21.594619 +00:00	core	NOTICE	Setting button backlight to: 0%
2023-09-11 12:41:11.828222 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Reconnecting in: 1.097s
2023-09-11 12:41:11.826639 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] on_session_disconnected: ClientDisconnect
2023-09-11 12:41:11.825556 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Session state change: Disconnected
2023-09-11 12:41:11.822972 +00:00	core	ERROR	[UC-Dock-8C4B14AA7884] Websocket server heartbeat failed, disconnecting!
2023-09-11 12:40:59.825096 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Resolved uc-dock-8c4b14aa7884.local: 192.168.10.240
2023-09-11 12:40:59.820255 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Resolving: uc-dock-8c4b14aa7884.local
2023-09-11 12:40:59.818824 +00:00	core	NOTICE	Dock URL not resolved, trying service name
2023-09-11 12:40:59.815081 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Connected to: ws://UC-Dock-8C4B14AA7884.local:946
2023-09-11 12:40:59.473184 +00:00	core	NOTICE	Dock URL not resolved, trying service name
2023-09-11 12:40:58.630355 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Reconnecting in: 844ms
2023-09-11 12:40:58.626270 +00:00	core	ERROR	[UC-Dock-8C4B14AA7884] Error connecting to dock: ServiceUnavailable("Failed to connect to host: Failed resolving hostname: failed to lookup address information: Temporary failure in name resolution")
2023-09-11 12:40:50.966657 +00:00	core	NOTICE	Dock URL not resolved, trying service name
2023-09-11 12:40:50.316582 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Reconnecting in: 650ms
2023-09-11 12:40:50.314029 +00:00	core	ERROR	[UC-Dock-8C4B14AA7884] Error connecting to dock: ServiceUnavailable("Failed to connect to host: Network is unreachable (os error 101)")
2023-09-11 12:40:49.809462 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Reconnecting in: 500ms
2023-09-11 12:40:49.809022 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] on_session_disconnected: ClientDisconnect
2023-09-11 12:40:49.808627 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Session state change: Disconnected
2023-09-11 12:40:49.807909 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] Force stopping actor
2023-09-11 12:40:49.710163 +00:00	core	WARN	[UC-Dock-8C4B14AA7884] Can't handle dock ConnectCmd command in state: Active
2023-09-11 12:40:49.709494 +00:00	core	WARN	[UC-Dock-8C4B14AA7884] No transition for: state=Active, event=ConnectCmd
2023-09-11 12:40:49.709289 +00:00	core	WARN	[UC-Dock-8C4B14AA7884] Old connection is still open, closing it
2023-09-11 12:40:49.708750 +00:00	core	NOTICE	[UC-Dock-8C4B14AA7884] WiFi connected: connecting dock
2023-09-11 12:40:49.708326 +00:00	core	NOTICE	WiFi connected: starting all external drivers
2023-09-11 12:40:49.708126 +00:00	core	NOTICE	Event: CONNECTED

and right now, after sleep and wake up, I see no problem. I'll keep oberving, and maybee someone else has a Core Log with more

[Yezariael75]

Where can I get the core log?

[splattner]

Where can I get the core log?

in the webconfigurator -> settings -> Development -> logs

[Yezariael75]

Here is the "internal server error". After restarting the remote it works again like it should.

2023-09-11 21:41:31.552080 +00:00 core NOTICE Setting button backlight to: 0%
2023-09-11 21:41:25.551601 +00:00 core NOTICE Changed battery status: 30% Charging, 3936mV, charger: true
2023-09-11 21:41:15.541773 +00:00 core NOTICE Changed battery status: 30% Discharging, 3735mV, charger: true
2023-09-11 21:41:11.650729 +00:00 core ERROR [uc.main.d4aee80b-638f-42f3-8a88-6fdf3dd64034] error executing activity command uc_androidtv_driver.main.00044BB4FC57:media_player.off (ignore error: false): Internal Server Error
2023-09-11 21:41:11.341920 +00:00 core NOTICE [uc.main.d4aee80b-638f-42f3-8a88-6fdf3dd64034] started activity with timeout of 30s
2023-09-11 21:40:55.915513 +00:00 core ERROR [uc.main.d4aee80b-638f-42f3-8a88-6fdf3dd64034] error executing activity command uc_androidtv_driver.main.00044BB4FC57:media_player.on (ignore error: false): Internal Server Error
2023-09-11 21:40:55.272552 +00:00 core NOTICE [uc.main.d4aee80b-638f-42f3-8a88-6fdf3dd64034] started activity with timeout of 30s
2023-09-11 21:40:50.526892 +00:00 core NOTICE Changed battery status: 30% Discharging, 3777mV, charger: false
2023-09-11 21:40:48.727791 +00:00 core NOTICE Setting button backlight to: 50%
2023-09-11 21:39:18.554138 +00:00 core NOTICE Setting button backlight to: 0%
2023-09-11 21:39:09.959594 +00:00 core ERROR Error encountered while processing the incoming HTTP request: AuthError("Authentication error")
2023-09-11 21:39:09.954387 +00:00 core ERROR Error encountered while processing the incoming HTTP request: AuthError("Authentication error")
2023-09-11 21:39:02.551790 +00:00 core NOTICE Setting button backlight to: 0%
2023-09-11 21:39:00.429749 +00:00 core NOTICE Changed battery status: 30% Charging, 3943mV, charger: true
2023-09-11 21:38:50.421353 +00:00 core NOTICE Changed battery status: 30% Discharging, 3745mV, charger: true
2023-09-11 21:38:45.550281 +00:00 core NOTICE Closing connection with code Policy: Authentication timeout
2023-09-11 21:38:40.413261 +00:00 core NOTICE Changed battery status: 30% Discharging, 3754mV, charger: false
2023-09-11 21:38:35.410431 +00:00 core NOTICE Changed battery status: 30% Not charging, 3950mV, charger: false
2023-09-11 21:38:34.609558 +00:00 core NOTICE Setting button backlight to: 50%
2023-09-11 21:38:16.021306 +00:00 core NOTICE No session state has been found for a valid session key, creating a new empty session.
2023-09-11 21:38:15.854202 +00:00 core ERROR Error encountered while processing the incoming HTTP request: AuthError("Authentication error")
2023-09-11 21:38:15.850005 +00:00 core NOTICE No session state has been found for a valid session key, creating a new empty session.
2023-09-11 21:37:45.367389 +00:00 core NOTICE Changed battery status: 30% Charging, 3950mV, charger: true
2023-09-11 21:34:35.204427 +00:00 core NOTICE Changed battery status: 29% Charging, 3948mV, charger: true

[smarthomesydney]

@martonborzak I have this error also and am using nVidia Shield pro also.
Let me know if you need additional logs.