Python process continually restarts

rhwood commented 6 months ago

Preconditions

[X] Requirements fulfilled
[X] The known issues did not answer my question
[X] The question has not been asked in the past or the answer does not satisfy me
[X] There is currently no other opened issue that matches my question
[X] I cannot find any answer to my question in GitHub discussions

Current Situation

After pairing (supposedly successfully), the python process keeps crashing with this error:

[17/03/2024, 12:35:22] [Apple TV Enhanced] [E] Bianca Castafiore (D0:03:4B:1A:2E:21): Unexpected atvremote response: 2024-03-17 12:35:20 ERROR [pyatv.protocols.airplay]: Failed to set up remote control channel

Logs

[17/03/2024, 12:07:51] [Apple TV Enhanced] [I] Platform: Finished initializing platform: Apple TV Enhanced
[17/03/2024, 12:07:51] [Apple TV Enhanced] [D] Platform: Executed didFinishLaunching callback
[17/03/2024, 12:07:51] [Apple TV Enhanced] [I] Update check: The update checker is configured to check for updates every 60 minutes, excluding betas. Auto updating is turned on.
[17/03/2024, 12:07:52] Homebridge v1.7.0 (HAP v0.11.1) (Apple TV Enhanced) is running on port 57689.
[17/03/2024, 12:07:52] [Apple TV Enhanced] [D] Update check: The latest AppleTV Enhanced version (excluding betas) is 1.3.0
[17/03/2024, 12:07:52] [Apple TV Enhanced] [I] Update check: You are using the latest version of AppleTV Enhanced (excluding betas): 1.3.0
[17/03/2024, 12:07:52] [Apple TV Enhanced] [D] Update check: Starting update check interval.
[17/03/2024, 12:07:52] [Apple TV Enhanced] [I] Python check: Starting python check.
[17/03/2024, 12:07:52] [Apple TV Enhanced] [I] Python check: plugin dir exists.
[17/03/2024, 12:07:52] [Apple TV Enhanced] [I] Python check: Python 3.11.2 is installed and supported by the plugin.
[17/03/2024, 12:07:52] [Apple TV Enhanced] [I] Python check: Virtual environment already exists.
[17/03/2024, 12:07:52] [Apple TV Enhanced] [I] Python check: Venv is using current system python version (3.11.2).
[17/03/2024, 12:07:55] [Apple TV Enhanced] [I] Python check: Venv pip version: 24.0
[17/03/2024, 12:07:55] [Apple TV Enhanced] [I] Python check: Checking if there is an update for venv pip ...
[17/03/2024, 12:07:55] [Apple TV Enhanced] [I] Python check: Venv pip is up-to-date
[17/03/2024, 12:07:58] [Apple TV Enhanced] [I] Python check: Python requirements are satisfied.
[17/03/2024, 12:07:58] [Apple TV Enhanced] [I] Python check: Finished
[17/03/2024, 12:07:58] [Apple TV Enhanced] [D] Platform: Setting the storage path of the PyATV instance to /var/lib/homebridge
[17/03/2024, 12:07:58] [Apple TV Enhanced] [D] CustomPyATVInstance: Set atvscript path to "/var/lib/homebridge/appletv-enhanced/.venv/bin/atvscript".
[17/03/2024, 12:07:58] [Apple TV Enhanced] [D] CustomPyATVInstance: Set atvremote path to "/var/lib/homebridge/appletv-enhanced/.venv/bin/atvremote".
[17/03/2024, 12:07:58] [Apple TV Enhanced] [I] Platform: Starting device discovery ...
[17/03/2024, 12:07:58] [Apple TV Enhanced] [D] Platform: Starting device discovery ...
[17/03/2024, 12:07:58] [Apple TV Enhanced] [V] CustomPyATVInstance: [node-pyatv][3O] /var/lib/homebridge/appletv-enhanced/.venv/bin/atvscript scan
[17/03/2024, 12:08:06] [Apple TV Enhanced] [V] CustomPyATVInstance: [node-pyatv][3O] stdout: {"result": "success", "datetime": "2024-03-17T12:08:06.314363-04:00", "devices": [{"name": "Hallway Sounds", "address": "192.168.1.213", "identifier": "00:22:6C:B5:98:A0", "all_identifiers": ["00:22:6C:B5:98:A0", "00226CB598A0"], "device_info": {"mac": "00:22:6C:B5:98:A0", "model": "Unknown", "model_str": "Onelink Safe Sound", "operating_system": "Unknown", "version": null}, "services": [{"protocol": "airplay", "port": 7000}, {"protocol": "raop", "port": 7000}]}, {"name": "Bianca Castafiore", "address": "192.168.1.222", "identifier": "563E0077-34A9-4DEC-A47D-7B1A3C655F17", "all_identifiers": ["1A06817F-23E2-44EE-97AB-B96E92E4CA16", "D0:03:4B:1A:2E:21", "D0034B1A2E21", "563E0077-34A9-4DEC-A47D-7B1A3C655F17"], "device_info": {"mac": "D0:03:4B:1A:2E:21", "model": "Gen4", "model_str": "Apple TV 4", "operating_system": "TvOS", "version": "17.4"}, "services": [{"protocol": "companion", "port": 49153}, {"protocol": "airplay", "port": 7000}, {"protocol": "raop", "port": 7000}, {"protocol": "mrp", "port": 49155}]}, {"name": "Igor Wagner", "address": "192.168.1.188", "identifier": "D4:90:9C:D0:71:E4", "all_identifiers": ["D4909CD071E4", "D4:90:9C:D0:71:E4"], "device_info": {"mac": "D4:90:9C:D0:71:E4", "model": "HomePod", "model_str": "HomePod", "operating_system": "TvOS", "version": "17.4"}, "services": [{"protocol": "companion", "port": 49159}, {"protocol": "raop", "port": 7000}, {"protocol": "airplay", "port": 7000}]}]}
[17/03/2024, 12:08:06] [Apple TV Enhanced] [V] CustomPyATVInstance: [node-pyatv][3O] /var/lib/homebridge/appletv-enhanced/.venv/bin/atvscript exited with code: 0
[17/03/2024, 12:08:06] [Apple TV Enhanced] [D] Platform: finished multicast device discovery
[17/03/2024, 12:08:06] [Apple TV Enhanced] [D] Platform: Found Apple TV Bianca Castafiore (D0:03:4B:1A:2E:21 / 192.168.1.222).
[17/03/2024, 12:08:06] [Apple TV Enhanced] [I] Platform: Adding Apple TV Bianca Castafiore (D0:03:4B:1A:2E:21)
[17/03/2024, 12:08:06] [Apple TV Enhanced] [D] Platform: Waiting for Apple TV Bianca Castafiore (D0:03:4B:1A:2E:21) to boot ...
[17/03/2024, 12:08:06] [Apple TV Enhanced] [D] Bianca Castafiore (D0:03:4B:1A:2E:21): Accessory Config: {"name":"Apple TV Enhanced","deviceStateDelay":0,"avadaKedavraAppAmount":15,"disableVolumeControlRemote":false,"setTopBox":false,"discover":{"multicast":true},"forceVenvRecreate":false,"logLevel":5,"updateCheckLevel":"stable","autoUpdate":"on","deviceSpecificOverrides":[{"overrideMediaTypes":false,"overrideDeviceStates":false,"overrideDeviceStateDelay":false,"deviceStateDelay":0,"overrideRemoteKeysAsSwitch":false,"overrideAvadaKedavraAppAmount":false,"avadaKedavraAppAmount":15,"overrideCustomInputURIs":false,"overrideDisableVolumeControlRemote":false,"disableVolumeControlRemote":false,"overrideSetTopBox":false,"setTopBox":false}],"platform":"AppleTVEnhanced"}
[17/03/2024, 12:08:06] [Apple TV Enhanced] [D] Bianca Castafiore (D0:03:4B:1A:2E:21): Loaded credentials: 40a320680a6dd6d502bab3770f0caa601c0227338ccb04ec5ee0c911a3d9c3f7:a17e78eaa0a91105d7625bd0b7a0a2ada829933efbc7e4c00bbb14990688b26e:31413036383137462d323345322d343445452d393741422d423936453932453443413136:31383235643466392d326533392d346665332d623130642d643134633730626431383536
[17/03/2024, 12:08:06] [Apple TV Enhanced] [I] Bianca Castafiore (D0:03:4B:1A:2E:21): verifying credentials ...
[17/03/2024, 12:08:06] [Apple TV Enhanced] [V] CustomPyATVInstance: [node-pyatv][4] /var/lib/homebridge/appletv-enhanced/.venv/bin/atvremote -s 192.168.1.222 -i 563E0077-34A9-4DEC-A47D-7B1A3C655F17 --airplay-credentials 40a320680a6dd6d502bab3770f0caa601c0227338ccb04ec5ee0c911a3d9c3f7:a17e78eaa0a91105d7625bd0b7a0a2ada829933efbc7e4c00bbb14990688b26e:31413036383137462d323345322d343445452d393741422d423936453932453443413136:31383235643466392d326533392d346665332d623130642d643134633730626431383536 --companion-credentials 40a320680a6dd6d502bab3770f0caa601c0227338ccb04ec5ee0c911a3d9c3f7:a17e78eaa0a91105d7625bd0b7a0a2ada829933efbc7e4c00bbb14990688b26e:31413036383137462d323345322d343445452d393741422d423936453932453443413136:31383235643466392d326533392d346665332d623130642d643134633730626431383536 app_list
[17/03/2024, 12:08:06] [Apple TV Enhanced] [D] Platform: Finished device discovery.
[17/03/2024, 12:08:10] [Apple TV Enhanced] [V] CustomPyATVInstance: [node-pyatv][4] stdout: 2024-03-17 12:08:10 ERROR [pyatv.protocols.airplay]: Failed to set up remote control channel
Traceback (most recent call last):
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/protocols/airplay/__init__.py", line 349, in _connect_rc
    await session.setup_remote_control()
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/protocols/airplay/ap2_session.py", line 79, in setup_remote_control
    await self._setup_event_channel(self.connection.remote_ip)
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/protocols/airplay/ap2_session.py", line 118, in _setup_event_channel
    resp = await self._setup(
           ^^^^^^^^^^^^^^^^^^
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/protocols/airplay/ap2_session.py", line 111, in _setup
    resp = await self.rtsp.setup(body=body)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/support/rtsp.py", line 176, in setup
    return await self.exchange("SETUP", headers=headers, body=body)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/support/rtsp.py", line 293, in exchange
    resp = await self.connection.send_and_receive(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/support/http.py", line 495, in send_and_receive
    raise exceptions.HttpError(
pyatv.exceptions.HttpError: RTSP/1.0 method SETUP failed with code 400: Bad Request
[17/03/2024, 12:08:10] [39m[Apple TV Enhanced] [V] CustomPyATVInstance: [node-pyatv][4] stdout: App: Sonic Racing (com.sega.kartios), App: TV (com.apple.TVWatchList), App: Photos (com.apple.TVPhotos), App: Disney+ (com.disney.disneyplus), App: Movies (com.apple.TVMovies), App: App Store (com.apple.TVAppStore), App: Podcasts (com.apple.podcasts), App: Music (com.apple.TVMusic), App: FloSports (tv.flosports.ott), App: Settings (com.apple.TVSettings), App: Prime Video (com.amazon.aiv.AIVApp), App: TV Shows (com.apple.TVShows), App: Computers (com.apple.TVHomeSharing), App: Search (com.apple.TVSearch), App: Netflix (com.netflix.Netflix), App: YouTube (com.google.ios.youtube), App: Fitness (com.apple.Fitness), App: Paramount+ (com.cbsvideo.app), App: Arcade (com.apple.Arcade)
[17/03/2024, 12:08:10] [Apple TV Enhanced] [V] CustomPyATVInstance: [node-pyatv][4] /var/lib/homebridge/appletv-enhanced/.venv/bin/atvremote exited with code: 0
[17/03/2024, 12:08:10] [Apple TV Enhanced] [E] Bianca Castafiore (D0:03:4B:1A:2E:21): Unexpected atvremote response: 2024-03-17 12:08:10 ERROR [pyatv.protocols.airplay]: Failed to set up remote control channel
Traceback (most recent call last):
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/protocols/airplay/__init__.py", line 349, in _connect_rc
    await session.setup_remote_control()
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/protocols/airplay/ap2_session.py", line 79, in setup_remote_control
    await self._setup_event_channel(self.connection.remote_ip)
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/protocols/airplay/ap2_session.py", line 118, in _setup_event_channel
    resp = await self._setup(
           ^^^^^^^^^^^^^^^^^^
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/protocols/airplay/ap2_session.py", line 111, in _setup
    resp = await self.rtsp.setup(body=body)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/support/rtsp.py", line 176, in setup
    return await self.exchange("SETUP", headers=headers, body=body)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/support/rtsp.py", line 293, in exchange
    resp = await self.connection.send_and_receive(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/support/http.py", line 495, in send_and_receive
    raise exceptions.HttpError(
pyatv.exceptions.HttpError: RTSP/1.0 method SETUP failed with code 400: Bad RequestApp: Sonic Racing (com.sega.kartios), App: TV (com.apple.TVWatchList), App: Photos (com.apple.TVPhotos), App: Disney+ (com.disney.disneyplus), App: Movies (com.apple.TVMovies), App: App Store (com.apple.TVAppStore), App: Podcasts (com.apple.podcasts), App: Music (com.apple.TVMusic), App: FloSports (tv.flosports.ott), App: Settings (com.apple.TVSettings), App: Prime Video (com.amazon.aiv.AIVApp), App: TV Shows (com.apple.TVShows), App: Computers (com.apple.TVHomeSharing), App: Search (com.apple.TVSearch), App: Netflix (com.netflix.Netflix), App: YouTube (com.google.ios.youtube), App: Fitness (com.apple.Fitness), App: Paramount+ (com.cbsvideo.app), App: Arcade (com.apple.Arcade)
[17/03/2024, 12:08:10] [Apple TV Enhanced] [E] Bianca Castafiore (D0:03:4B:1A:2E:21): Error: Unexpected atvremote response: 2024-03-17 12:08:10 ERROR [pyatv.protocols.airplay]: Failed to set up remote control channel
Traceback (most recent call last):
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/protocols/airplay/__init__.py", line 349, in _connect_rc
    await session.setup_remote_control()
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/protocols/airplay/ap2_session.py", line 79, in setup_remote_control
    await self._setup_event_channel(self.connection.remote_ip)
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/protocols/airplay/ap2_session.py", line 118, in _setup_event_channel
    resp = await self._setup(
           ^^^^^^^^^^^^^^^^^^
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/protocols/airplay/ap2_session.py", line 111, in _setup
    resp = await self.rtsp.setup(body=body)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/support/rtsp.py", line 176, in setup
    return await self.exchange("SETUP", headers=headers, body=body)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/support/rtsp.py", line 293, in exchange
    resp = await self.connection.send_and_receive(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/var/lib/homebridge/appletv-enhanced/.venv/lib/python3.11/site-packages/pyatv/support/http.py", line 495, in send_and_receive
    raise exceptions.HttpError(
pyatv.exceptions.HttpError: RTSP/1.0 method SETUP failed with code 400: Bad RequestApp: Sonic Racing (com.sega.kartios), App: TV (com.apple.TVWatchList), App: Photos (com.apple.TVPhotos), App: Disney+ (com.disney.disneyplus), App: Movies (com.apple.TVMovies), App: App Store (com.apple.TVAppStore), App: Podcasts (com.apple.podcasts), App: Music (com.apple.TVMusic), App: FloSports (tv.flosports.ott), App: Settings (com.apple.TVSettings), App: Prime Video (com.amazon.aiv.AIVApp), App: TV Shows (com.apple.TVShows), App: Computers (com.apple.TVHomeSharing), App: Search (com.apple.TVSearch), App: Netflix (com.netflix.Netflix), App: YouTube (com.google.ios.youtube), App: Fitness (com.apple.Fitness), App: Paramount+ (com.cbsvideo.app), App: Arcade (com.apple.Arcade)
    at V.<anonymous> (/var/lib/homebridge/node_modules/homebridge-appletv-enhanced/node_modules/@sebbo2002/node-pyatv/src/lib/device.ts:408:19)
    at Generator.next (<anonymous>)
    at o (/var/lib/homebridge/node_modules/homebridge-appletv-enhanced/node_modules/@sebbo2002/node-pyatv/dist/lib/index.cjs:1:627)
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
[17/03/2024, 12:08:10] [Apple TV Enhanced] Child bridge process ended
[17/03/2024, 12:08:10] [Apple TV Enhanced] Process Ended. Code: 1, Signal: null
[17/03/2024, 12:08:17] [Apple TV Enhanced] Restarting Process...

The above endlessly repeats. More complete logs at log level 5 are uploaded separately because GitHub wouldn't let me cut and paste the logs here.

Configuration

{
    "name": "Apple TV Enhanced",
    "deviceStateDelay": 0,
    "avadaKedavraAppAmount": 15,
    "disableVolumeControlRemote": false,
    "setTopBox": false,
    "discover": {
        "multicast": true
    },
    "forceVenvRecreate": false,
    "logLevel": 5,
    "updateCheckLevel": "stable",
    "autoUpdate": "on",
    "deviceSpecificOverrides": [
        {
            "overrideMediaTypes": false,
            "overrideDeviceStates": false,
            "overrideDeviceStateDelay": false,
            "deviceStateDelay": 0,
            "overrideRemoteKeysAsSwitch": false,
            "overrideAvadaKedavraAppAmount": false,
            "avadaKedavraAppAmount": 15,
            "overrideCustomInputURIs": false,
            "overrideDisableVolumeControlRemote": false,
            "disableVolumeControlRemote": false,
            "overrideSetTopBox": false,
            "setTopBox": false
        }
    ],
    "_bridge": {
        "username": "0E:B9:F7:DB:71:5B",
        "port": 57689
    },
    "platform": "AppleTVEnhanced"
}

Operating System

Linux

Operating System: Bits

64-bit

Operating System: Distribution

Debian GNU/Linux (as reported by the Homebridge Raspberry Pi Image)

Operating System: Distribution Version

12 (bookworm)

Docker

no

Docker Image

None

Docker Image Tag

No response

Homebridge Version

1.7.0

Homebridge Config UI Version

v4.55.1

Homebridge Storage Path

/var/lib/homebridge

Homebridge Apple TV Enhanced Version

1.3.0

Node Version

v20.11.1

NPM Version

10.2.4

Python Version

3.11.2

PIP Version

23.0.1

HDMI Hops

None -- Apple TV is directly connected

Audio Output

no

Same Subnet

yes

Additional Context

This is on a new installation performed today.

rhwood commented 6 months ago

homebridge.log.txt

github-actions[bot] commented 6 months ago

✔️ Have a coffee ☕

Your opened issue fulfills all requirements validated in the pre-checks 🎉

My master will take a look at the problem as soon as he has the time for it 🤖

Time to get a coffee ☕

maxileith commented 6 months ago

Could you please delete the file ./appletv-enhanced/D0034B1A2E21/credentials.txt and try again? You will have to repair your Apple TV.

It seems like there is an error when authenticating. Did not see this kind of error ever ...

If this does not help, I think we will be best of submiting an issue at the pyatv repository since the issue originiates from that dependency ...

rhwood commented 6 months ago

I’m currently traveling and will do once I return home.

github-actions[bot] commented 5 months ago

This issue is stale because it has been open for 14 days with no activity.

github-actions[bot] commented 5 months ago

This issue was closed because it has been inactive for 3 days since being marked as stale.

maxileith / homebridge-appletv-enhanced