search

unfoldedcircle / feature-and-bug-tracker

Feature and bug tracker repository for Unfolded Circle products
21 stars 0 forks source link

Apple TV Integration timeout #87

Open eughenes opened 9 months ago

eughenes commented 9 months ago

Is there an existing issue for this?

Description

Starting the integration the remote discovers my 3 Apple TV, but it lists 5, a couple are listed twice with slightly different names (the correct ones are those with leading "ATV"). No matter which Apple TV device I select, all of them raise a Time Out error

How to Reproduce

  1. Go to Integrations & Docks
  2. Select Integrations
  3. Click +
  4. Select Apple TV integration and click Next
  5. Select one of the discovered Apple TVs and click Next Screenshot 2023-09-28 at 20 59 12 Screenshot 2023-09-28 at 20 57 48

Expected behavior

Should add the chosen Apple TV to the list of integrations

System version

1.2.1

What part of the system affected by the problem?

Integration

Additional context

No response

eughenes commented 9 months ago

I forgot to add that I tried to download the Apple TV integration log but it is empty

kennymc-c commented 9 months ago

I have the same timeout problem although only the two Apple TVs I own show up in the list. Even though there was nothing in the 'download logs from' drop-down menu to choose from I actually was able to download these core logs when I clicked on the download button. I tried to add the ATV serval times via the try again button.

2023-09-30 14:15:08.676055 +00:00   core    WARN    Error encountered while processing the incoming HTTP request: NotFound
2023-09-30 14:15:08.675082 +00:00   core    NOTICE  [uc_appletv_driver] StopDriver msg
2023-09-30 14:15:08.674003 +00:00   core    NOTICE  Stopping driver 'uc_appletv_driver': no more instances
2023-09-30 14:15:06.303713 +00:00   core    WARN    Error encountered while processing the incoming HTTP request: NotFound
2023-09-30 14:15:06.303063 +00:00   core    NOTICE  [uc_appletv_driver] StopDriver msg
2023-09-30 14:15:06.302295 +00:00   core    NOTICE  Stopping driver 'uc_appletv_driver': no more instances
2023-09-30 14:15:02.699108 +00:00   core    NOTICE  [uc_appletv_driver] Session state change: Disconnected
2023-09-30 14:15:02.664540 +00:00   core    NOTICE  [uc_appletv_driver] StopDriver msg
2023-09-30 14:15:02.658910 +00:00   core    NOTICE  Stopping driver 'uc_appletv_driver': no more instances
2023-09-30 14:14:02.656083 +00:00   core    ERROR   Ok(DriverSetupChange { event_type: Setup, state: Setup, error: None, require_user_action: None })
2023-09-30 14:14:01.294125 +00:00   core    ERROR   Ok(DriverSetupChange { event_type: Setup, state: WaitUserAction, error: None, require_user_action: Some(Input(SettingsPage { title: {"en": "Please choose your Apple TV"}, settings: [Setting { id: "choice", label: {"en": "Choose your Apple TV"}, field: Dropdown(Dropdown { value: Some("40FC6C78-E08D-4A6B-9CBC-37078152133E"), items: [DropdownItem { id: "40FC6C78-E08D-4A6B-9CBC-37078152133E", label: {"en": "Apple-TV Wohnzimmer TvOS 17.0"} }, DropdownItem { id: "D0:D2:B0:96:45:92", label: {"en": "Apple-TV Küche TvOS 17.0"} }] }) }] })) })
2023-09-30 14:13:56.211189 +00:00   core    ERROR   Ok(DriverSetupChange { event_type: Setup, state: Setup, error: None, require_user_action: None })
2023-09-30 14:13:56.205385 +00:00   core    NOTICE  Removed standby inhibitor: Integration setup: uc_appletv_driver
2023-09-30 14:13:56.202732 +00:00   core    ERROR   Error("missing field `api`", line: 0, column: 0)
2023-09-30 14:13:56.189678 +00:00   core    NOTICE  [uc_appletv_driver] SessionAuthenticated msg
2023-09-30 14:13:56.188472 +00:00   core    NOTICE  [uc_appletv_driver] Session state change: Authenticated
2023-09-30 14:13:56.182493 +00:00   core    NOTICE  [uc_appletv_driver] Session became active: sending get_driver_version, connect, subscribe_events
2023-09-30 14:13:56.178932 +00:00   core    NOTICE  [uc_appletv_driver] SessionAuthenticated msg
2023-09-30 14:13:56.177485 +00:00   core    NOTICE  [uc_appletv_driver] Session state change: Authenticated
2023-09-30 14:13:56.157964 +00:00   core    NOTICE  [uc_appletv_driver] Connected to: ws://127.0.0.1:8097
2023-09-30 14:13:56.147072 +00:00   core    WARN    Driver not connected to start setup flow, starting driver. State: Some(Idle)
2023-09-30 14:13:56.145938 +00:00   core    NOTICE  Added standby inhibitor: Integration setup: uc_appletv_driver
2023-09-30 14:13:47.263214 +00:00   core    WARN    Error encountered while processing the incoming HTTP request: NotFound
2023-09-30 14:13:47.262183 +00:00   core    NOTICE  [uc_appletv_driver] StopDriver msg
2023-09-30 14:13:47.260478 +00:00   core    NOTICE  Stopping driver 'uc_appletv_driver': no more instances
2023-09-30 14:13:28.732290 +00:00   core    NOTICE  [uc_appletv_driver] Session state change: Disconnected
2023-09-30 14:13:28.692380 +00:00   core    NOTICE  [uc_appletv_driver] StopDriver msg
2023-09-30 14:13:28.691283 +00:00   core    NOTICE  Stopping driver 'uc_appletv_driver': no more instances
2023-09-30 14:13:08.397165 +00:00   core    NOTICE  Changed battery status: 94% Charging, 4199mV, charger: true
2023-09-30 14:12:28.687581 +00:00   core    ERROR   Ok(DriverSetupChange { event_type: Setup, state: Setup, error: None, require_user_action: None })
2023-09-30 14:12:25.789882 +00:00   core    ERROR   Ok(DriverSetupChange { event_type: Setup, state: WaitUserAction, error: None, require_user_action: Some(Input(SettingsPage { title: {"en": "Please choose your Apple TV"}, settings: [Setting { id: "choice", label: {"en": "Choose your Apple TV"}, field: Dropdown(Dropdown { value: Some("40FC6C78-E08D-4A6B-9CBC-37078152133E"), items: [DropdownItem { id: "40FC6C78-E08D-4A6B-9CBC-37078152133E", label: {"en": "Apple-TV Wohnzimmer TvOS 17.0"} }, DropdownItem { id: "D0:D2:B0:96:45:92", label: {"en": "Apple-TV Küche TvOS 17.0"} }] }) }] })) })
2023-09-30 14:12:20.713211 +00:00   core    ERROR   Ok(DriverSetupChange { event_type: Setup, state: Setup, error: None, require_user_action: None })
2023-09-30 14:12:20.710274 +00:00   core    NOTICE  Removed standby inhibitor: Integration setup: uc_appletv_driver
2023-09-30 14:12:20.707898 +00:00   core    ERROR   Error("missing field `api`", line: 0, column: 0)
2023-09-30 14:12:20.693156 +00:00   core    NOTICE  [uc_appletv_driver] SessionAuthenticated msg
2023-09-30 14:12:20.691853 +00:00   core    NOTICE  [uc_appletv_driver] Session state change: Authenticated
2023-09-30 14:12:20.686109 +00:00   core    NOTICE  [uc_appletv_driver] Session became active: sending get_driver_version, connect, subscribe_events
2023-09-30 14:12:20.682888 +00:00   core    NOTICE  [uc_appletv_driver] SessionAuthenticated msg
2023-09-30 14:12:20.681713 +00:00   core    NOTICE  [uc_appletv_driver] Session state change: Authenticated
2023-09-30 14:12:20.660148 +00:00   core    NOTICE  [uc_appletv_driver] Connected to: ws://127.0.0.1:8097
2023-09-30 14:12:20.644853 +00:00   core    WARN    Driver not connected to start setup flow, starting driver. State: Some(Idle)
2023-09-30 14:12:20.642970 +00:00   core    NOTICE  Added standby inhibitor: Integration setup: uc_appletv_driver

I assume log times are in GMT and not matching the set time zone?

The browser console shows this error when I click on try again after the timeout ATVTimeoutConsole

martonborzak commented 9 months ago

Try this: select the Apple TV service, loglevel DEBUG and try to download the logs again.

kennymc-c commented 9 months ago

I can not select any service in the dropdown menu. Set priority to DEBUG but there doesn't seem to be any debug log entries. Also the same output via REST API /system/logs and priority 6:

2023-09-30 22:11:52.383159 +00:00   core    WARN    Error encountered while processing the incoming HTTP request: NotFound
2023-09-30 22:11:52.382490 +00:00   core    NOTICE  [uc_appletv_driver] StopDriver msg
2023-09-30 22:11:52.381800 +00:00   core    NOTICE  Stopping driver 'uc_appletv_driver': no more instances
2023-09-30 22:11:48.291937 +00:00   core    NOTICE  [uc_appletv_driver] Session state change: Disconnected
2023-09-30 22:11:48.257218 +00:00   core    NOTICE  [uc_appletv_driver] StopDriver msg
2023-09-30 22:11:48.251838 +00:00   core    NOTICE  Stopping driver 'uc_appletv_driver': no more instances
2023-09-30 22:10:48.245761 +00:00   core    ERROR   Ok(DriverSetupChange { event_type: Setup, state: Setup, error: None, require_user_action: None })
2023-09-30 22:10:38.783113 +00:00   core    ERROR   Ok(DriverSetupChange { event_type: Setup, state: WaitUserAction, error: None, require_user_action: Some(Input(SettingsPage { title: {"en": "Please choose your Apple TV"}, settings: [Setting { id: "choice", label: {"en": "Choose your Apple TV"}, field: Dropdown(Dropdown { value: Some("40FC6C78-E08D-4A6B-9CBC-37078152133E"), items: [DropdownItem { id: "40FC6C78-E08D-4A6B-9CBC-37078152133E", label: {"en": "Apple-TV Wohnzimmer TvOS 17.x"} }, DropdownItem { id: "D0:D2:B0:96:45:92", label: {"en": "Apple-TV Küche TvOS 17.0"} }] }) }] })) })
2023-09-30 22:10:33.699156 +00:00   core    ERROR   Ok(DriverSetupChange { event_type: Setup, state: Setup, error: None, require_user_action: None })
2023-09-30 22:10:33.693320 +00:00   core    NOTICE  Removed standby inhibitor: Integration setup: uc_appletv_driver
2023-09-30 22:10:33.690906 +00:00   core    ERROR   Error("missing field `api`", line: 0, column: 0)
2023-09-30 22:10:33.682868 +00:00   core    NOTICE  [uc_appletv_driver] SessionAuthenticated msg
2023-09-30 22:10:33.681922 +00:00   core    NOTICE  [uc_appletv_driver] Session state change: Authenticated
2023-09-30 22:10:33.673938 +00:00   core    NOTICE  [uc_appletv_driver] Session became active: sending get_driver_version, connect, subscribe_events
2023-09-30 22:10:33.670873 +00:00   core    NOTICE  [uc_appletv_driver] SessionAuthenticated msg
2023-09-30 22:10:33.668528 +00:00   core    NOTICE  [uc_appletv_driver] Session state change: Authenticated
2023-09-30 22:10:33.654989 +00:00   core    NOTICE  [uc_appletv_driver] Connected to: ws://127.0.0.1:8097
2023-09-30 22:10:33.640008 +00:00   core    WARN    Driver not connected to start setup flow, starting driver. State: Some(Idle)
kennymc-c commented 9 months ago

Ok, seems to be a Safari issue, in Chrome I can select the service and get a different log with priority DEBUG:

2023-09-30 22:11:48.300961 +00:00   intg-appletv    INFO    INFO:ucapi.api:WS: Client removed
2023-09-30 22:11:48.252880 +00:00   intg-appletv    INFO    DEBUG:ucapi.api:<-: {"kind":"event","msg":"abort_driver_setup","cat":"DEVICE","ts":"2023-09-30T22:11:48.245607879Z","msg_data":{"error":"TIMEOUT"}}
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO    pyatv.exceptions.PairingError: HTTP/1.1 method POST failed with code 400: Bad Request
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO      File "pyatv/support/__init__.py", line 78, in error_handler
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO      File "pyatv/protocols/airplay/pairing.py", line 63, in begin
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO      File "tv.py", line 126, in startPairing
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO      File "driver.py", line 217, in event_handler
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO      File "pyee/base.py", line 139, in _emit_handle_potential_error
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO      File "pyee/base.py", line 179, in emit
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO      File "pyee/asyncio.py", line 71, in callback
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO      File "asyncio/events.py", line 81, in _run
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO    Traceback (most recent call last):
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO    The above exception was the direct cause of the following exception:
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO    pyatv.exceptions.HttpError: HTTP/1.1 method POST failed with code 400: Bad Request
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO      File "pyatv/support/http.py", line 473, in send_and_receive
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO      File "pyatv/support/http.py", line 418, in post
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO      File "pyatv/protocols/airplay/auth/hap.py", line 51, in start_pairing
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO      File "pyatv/support/__init__.py", line 70, in error_handler
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO    Traceback (most recent call last):
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO    handle: <Handle AsyncIOEventEmitter._emit_run.<locals>.callback(<Task finishe...Bad Request')>) at pyee/asyncio.py:65>
2023-09-30 22:10:48.536430 +00:00   intg-appletv    INFO    ERROR:asyncio:Exception in callback AsyncIOEventEmitter._emit_run.<locals>.callback(<Task finishe...Bad Request')>) at pyee/asyncio.py:65
2023-09-30 22:10:48.482184 +00:00   intg-appletv    INFO    DEBUG:tv:Pairing started
2023-09-30 22:10:48.481166 +00:00   intg-appletv    INFO    DEBUG:__main__:Pairing process begin
2023-09-30 22:10:48.255175 +00:00   intg-appletv    INFO    client_session: <aiohttp.client.ClientSession object at 0x7f89217970>
2023-09-30 22:10:48.255175 +00:00   intg-appletv    INFO    ERROR:asyncio:Unclosed client session
2023-09-30 22:10:48.250033 +00:00   intg-appletv    INFO    DEBUG:__main__:Chosen Apple TV: 40FC6C78-E08D-4A6B-9CBC-37078152133E
2023-09-30 22:10:48.243725 +00:00   intg-appletv    INFO    DEBUG:ucapi.api:->: {"kind": "event", "msg": "driver_setup_change", "msg_data": {"event_type": "SETUP", "state": "SETUP"}, "cat": "DEVICE"}
2023-09-30 22:10:48.240519 +00:00   intg-appletv    INFO    DEBUG:ucapi.api:->: {"kind": "resp", "req_id": 8, "code": 200, "msg": "result", "msg_data": {}}
2023-09-30 22:10:48.234906 +00:00   intg-appletv    INFO    DEBUG:ucapi.api:<-: {"kind":"req","id":8,"msg":"set_driver_user_data","msg_data":{"input_values":{"choice":"40FC6C78-E08D-4A6B-9CBC-37078152133E"}}}
2023-09-30 22:10:38.776789 +00:00   intg-appletv    INFO    DEBUG:ucapi.api:->: {"kind": "event", "msg": "driver_setup_change", "msg_data": {"event_type": "SETUP", "state": "WAIT_USER_ACTION", "require_user_action": {"input": {"title": {"en": "Please choose your Apple TV"}, "settings": [{"field": {"dropdown": {"value": "40FC6C78-E08D-4A6B-9CBC-37078152133E", "items": [{"id": "40FC6C78-E08D-4A6B-9CBC-37078152133E", "label": {"en": "Apple-TV Wohnzimmer TvOS 17.x"}}, {"id": "D0:D2:B0:96:45:92", "label": {"en": "Apple-TV K\u00fcche TvOS 17.0"}}]}}, "id": "choice", "label": {"en": "Choose your Apple TV"}}]}}}, "cat": "DEVICE"}
2023-09-30 22:10:33.696805 +00:00   intg-appletv    INFO    DEBUG:__main__:Starting Apple TV discovery
2023-09-30 22:10:33.694626 +00:00   intg-appletv    INFO    DEBUG:ucapi.api:->: {"kind": "event", "msg": "driver_setup_change", "msg_data": {"event_type": "SETUP", "state": "SETUP"}, "cat": "DEVICE"}
2023-09-30 22:10:33.689262 +00:00   intg-appletv    INFO    DEBUG:ucapi.api:->: {"kind": "resp", "req_id": 7, "code": 200, "msg": "result", "msg_data": {}}
2023-09-30 22:10:33.687501 +00:00   intg-appletv    INFO    DEBUG:__main__:Starting driver setup
2023-09-30 22:10:33.685121 +00:00   intg-appletv    INFO    DEBUG:ucapi.api:<-: {"kind":"req","id":7,"msg":"setup_driver","msg_data":{"setup_data":{}}}
2023-09-30 22:10:33.680784 +00:00   intg-appletv    INFO    DEBUG:ucapi.api:->: {"kind": "event", "msg": "device_state", "msg_data": {"state": "CONNECTED"}, "cat": "DEVICE"}
2023-09-30 22:10:33.676328 +00:00   intg-appletv    INFO    DEBUG:ucapi.api:<-: {"id":6,"kind":"event","msg":"connect"}
2023-09-30 22:10:33.672771 +00:00   intg-appletv    INFO    DEBUG:ucapi.api:->: {"kind": "resp", "req_id": 5, "code": 200, "msg": "driver_version", "msg_data": {"name": "Apple TV", "version": {"api": "0.7.0", "driver": "0.11.1"}}}
2023-09-30 22:10:33.669901 +00:00   intg-appletv    INFO    DEBUG:ucapi.api:<-: {"id":5,"kind":"req","msg":"get_driver_version"}
2023-09-30 22:10:33.659199 +00:00   intg-appletv    INFO    DEBUG:ucapi.api:->: {"kind": "resp", "req_id": 0, "code": 200, "msg": "authentication", "msg_data": {}}
2023-09-30 22:10:33.659199 +00:00   intg-appletv    INFO    INFO:ucapi.api:WS: Client added
kennymc-c commented 9 months ago

Did a little search regarding that bad request 400 error and got it to work by changing the access setting on the Apple TV under Settings/AirPlay and HomeKit from same Home to same Network. Unfortunately this isn't mentioned anywhere during the integration setup process.

martonborzak commented 9 months ago

Thanks for the investigation @kennymc-c. Yes, this setting is required and we'll add this info to the initial setup screen.

eughenes commented 9 months ago

Thank you, I'll try with the Apple TV's correct settings asap

eughenes commented 9 months ago

I could add the integration, the instructions should also specify that the user should not set a password to connect to Apple TV as only the PIN method seems to be supported by the integration.

taw123 commented 8 months ago

To further clarify the matter(as someone who was ALSO bit by the difficulty adding the ATV integration)...

As @eughenes above also mentioned Password needs to be turned off for pairing BUT can be re-enabled after RC2 is paired. This turned out to be my problem again again there was no error message passed up (I can add debug logs if you really want but think this is well understood). Once I turned off pswd I was able to add with no problem, and then re-enabled password and integration continued to function.

Now to figure out what Entities from HomeAssistant RC2 will deal with in the integration (wish there was some documentation... In time I suppose, till then trial and error with some source code dives I suppose, maybe I'll throw a quick query out on Discord) but I digress...

eughenes commented 7 months ago

just for info, the other 2 listed devices were the HomePod minis, which I named like the Apple TVs in the same room, without the leading "ATV" in the name.

I also discovered that I can control just one of the Apple TVs, After running the integration and selecting one of the Apple TVs it asks twice for the PIN (I don't know if it is the intended behavior), and then It shows 2 of the Apple TV as entities to select (I guess because I actually controlled both of them during several tests). I can select both entities but it allows me to actually control just the one I input the PIN for. I wonder if the possibility of controlling multiple Apple TVs via the integration is on the roadmap or if it needs to be requested as an enhancement (I couldn't find it in the feature-and-bug-tracker repository).

kennymc-c commented 7 months ago

@eughenes I already created a FR for this https://github.com/unfoldedcircle/feature-and-bug-tracker/issues/118

zehnm commented 3 months ago

Fixed in the next release. Discovery now only considers Apple TV 4 and newer devices and supports multiple devices.