tvOS 15: "A problem occurred while pairing protocol MRP. It will be ignored."

[Smiggel]

I updated my Apple TV 4K to tvOS 15 (19J5268r). I noticed that since then the Apple TV can not be paired anymore during the first step en first pincode.

I get to see the error: A problem occurred while pairing protocol MRP. It will be ignored.

The pincode for Airplay does show on the Apple TV and I can complete that step. However, after doing the second pincode the message pops up in HA: The configuration for this device is incomplete. Try to add it again.

This I can see in the logs:

Logger: custom_components.apple_tv.config_flow Source: custom_components/apple_tv/config_flow.py:280 Integration: Apple TV First occurred: 17:24:27 (4 occurrences) Last logged: 17:24:52

Authentication problem Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/pyatv/support/init.py", line 31, in error_handler return await func(*args, **kwargs) File "/usr/local/lib/python3.8/site-packages/pyatv/airplay/auth.py", line 48, in finish_authentication await self._send_plist( File "/usr/local/lib/python3.8/site-packages/pyatv/airplay/auth.py", line 69, in _send_plist raise AuthenticationError("{0} failed with code {1}".format(step, code)) pyatv.exceptions.AuthenticationError: step2 failed with code 500

The above exception was the direct cause of the following exception:

Traceback (most recent call last): File "/config/custom_components/apple_tv/config_flow.py", line 280, in async_step_pair_with_pin await self.pairing.finish() File "/usr/local/lib/python3.8/site-packages/pyatv/airplay/pairing.py", line 68, in finish await error_handler( File "/usr/local/lib/python3.8/site-packages/pyatv/support/init.py", line 39, in error_handler raise fallback(str(ex)) from ex pyatv.exceptions.PairingError: step2 failed with code 500

[postlund]

Is this with the new 4K or the old one? I've heard about the new one not working, but once upgraded to tvOS beta it started working however. Would be interesting to see a complete log. Can you try pairing with atvremote directly and provide me a log? For instance:

atvremote -s <ip> --debug --protocol mrp pair 

https://pyatv.dev/documentation/#installing-pyatv

As this is still beta, I won't put that much energy into this as Apple tend to break stuff I their betas from time to time. Might be the case here too.

[postlund]

And also, not being able to pair AirPlay seems to be recurring now. A few people have reported that. I might have to consider implementing HAP base authentication instead of the legacy one used now, it likely works better. I'll keep that as an improvement story.

[BVGorp]

I have an old Apple TV 4k and upgraded it to tvos15. Noticed that the entities were not updating anymore and decided to remove the config and add the integration again and noticed above issue too.

Log:

atvremote -s 172.16.11.5 --debug --protocol mrp pair
2021-06-23 23:43:52 DEBUG [pyatv.support.knock]: Knocking at ports [3689, 7000, 49152, 32498] on 172.16.11.5
2021-06-23 23:43:52 DEBUG [pyatv.support.scan]: Auto-discovered AppleTV BVGorp at 172.16.11.5:49152 (Protocol.Companion)
2021-06-23 23:43:52 DEBUG [pyatv.support.scan]: Auto-discovered AppleTV BVGorp at 172.16.11.5:7000 (Protocol.AirPlay)
2021-06-23 23:43:52 DEBUG [pyatv.support.scan]: Auto-discovered AppleTV BVGorp at 172.16.11.5:7000 (Protocol.RAOP)
2021-06-23 23:43:52 DEBUG [pyatv.support.scan]: Auto-discovered AppleTV BVGorp at 172.16.11.5:50516 (Protocol.MRP)
2021-06-23 23:43:52 DEBUG [pyatv.mrp.connection]: Connection made to device
2021-06-23 23:43:52 DEBUG [pyatv.support.net]: Configured keep-alive on <socket.socket fd=6, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('172.16.11.4', 56150), raddr=('172.16.11.5', 50516)> (Linux)
2021-06-23 23:43:52 DEBUG [pyatv.mrp.connection]: 172.16.11.4:56150<->172.16.11.5:50516  Connection established
2021-06-23 23:43:52 DEBUG [pyatv.mrp.connection]: 172.16.11.4:56150<->172.16.11.5:50516 >> Send (Data=080f122439464631453331362d314236332d343939412d384535362d3244303545313735313639452000a20183010a2465626133336536622d633165342d343235352d386232362d333565343735633964353862120570796174761a066950686f6e6522063138413339332a12636f6d2e6170706c652e545652656d6f746532063334342e32383801406c480150016211636f6d2e6170706c652e54564d75736963680170017801880102a80101b00101)
2021-06-23 23:43:52 DEBUG [pyatv.mrp.connection]: 172.16.11.4:56150<->172.16.11.5:50516 >> Send: Protobuf: type: DEVICE_INFO_MESSAGE
identifier: "9FF1E316-1B63-499A-8E56-2D05E175169E"
errorCode: NoError
[deviceInfoMessage] {
  uniqueIdentifier: "eba33e6b-c1e4-4255-8b26-35e475c9d58b"
  name: "pyatv"
  localizedModelName: "iPhone"
  systemBuildVersion: "18A393"
  applicationBundleIdentifier: "com.apple.TVRemote"
  applicationBundleVersion: "344.28"
  protocolVersion: 1
  lastSupportedMessageType: 108
  supportsSystemPairing: true
  allowsPairing: true
  systemMediaApplication: "com.apple.TVMusic"
  supportsACL: true
  supportsSharedQueue: true
  supportsExtendedMotion: true
  sharedQueueVersion: 2
  deviceClass: iPhone
  logicalDeviceCount: 1
}
2021-06-23 23:43:57 DEBUG [pyatv.mrp.connection]: 172.16.11.4:56150<->172.16.11.5:50516  Closing connection
2021-06-23 23:43:57 ERROR [root]: Pairing failed
Traceback (most recent call last):
  File "/opt/pyatv_venv/lib/python3.6/site-packages/pyatv/support/__init__.py", line 33, in error_handler
    return await func(*args, **kwargs)
  File "/opt/pyatv_venv/lib/python3.6/site-packages/pyatv/mrp/auth.py", line 39, in start_pairing
    await self.protocol.start(skip_initial_messages=True)
  File "/opt/pyatv_venv/lib/python3.6/site-packages/pyatv/mrp/protocol.py", line 129, in start
    self.device_info = await self.send_and_receive(msg)
  File "/opt/pyatv_venv/lib/python3.6/site-packages/pyatv/mrp/protocol.py", line 216, in send_and_receive
    return await self._receive(identifier, timeout)
  File "/opt/pyatv_venv/lib/python3.6/site-packages/pyatv/mrp/protocol.py", line 224, in _receive
    await asyncio.wait_for(semaphore.acquire(), timeout)
  File "/usr/lib/python3.6/asyncio/tasks.py", line 362, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/opt/pyatv_venv/lib/python3.6/site-packages/pyatv/scripts/atvremote.py", line 174, in pair
    await self._perform_pairing(pairing)
  File "/opt/pyatv_venv/lib/python3.6/site-packages/pyatv/scripts/atvremote.py", line 184, in _perform_pairing
    await pairing.begin()
  File "/opt/pyatv_venv/lib/python3.6/site-packages/pyatv/mrp/pairing.py", line 44, in begin
    self.pairing_procedure.start_pairing, exceptions.PairingError
  File "/opt/pyatv_venv/lib/python3.6/site-packages/pyatv/support/__init__.py", line 35, in error_handler
    raise exceptions.ConnectionFailedError(str(ex)) from ex
pyatv.exceptions.ConnectionFailedError
2021-06-23 23:43:57 DEBUG [pyatv.mrp.connection]: 172.16.11.4:56150<->172.16.11.5:50516  Closing connection
2021-06-23 23:43:57 DEBUG [pyatv.mrp.connection]: 172.16.11.4:56150<->172.16.11.5:50516  Disconnected from device: None
2021-06-23 23:43:57 DEBUG [pyatv.mrp.connection]: 172.16.11.4:56150<->172.16.11.5:50516  Closing connection

[Smiggel]

Is this with the new 4K or the old one? I've heard about the new one not working, but once upgraded to tvOS beta it started working however. Would be interesting to see a complete log. Can you try pairing with atvremote directly and provide me a log? For instance:

atvremote -s <ip> --debug --protocol mrp pair 

https://pyatv.dev/documentation/#installing-pyatv

As this is still beta, I won't put that much energy into this as Apple tend to break stuff I their betas from time to time. Might be the case here too.

I have the first 4K gen Apple TV. So, the old one. :-)

I will give the command a try later today, when I figured out where I have to execute it.

[postlund]

One interesting thing to check: does the iOS Remote app (not the action center widget)? If it works, does it still work if you remove the device and add it again?

[BVGorp]

The remote app does not work anymore on iOS15. When you try to open the app, it doesn't open and gives a popup to use the action center widget. I don't have a iOS14.x device atm

[postlund]

That's... interesting. Are they deprecating MRP already? I assume you used the app named Remote and not iTunes Remote, right? Has the action center widget received any new features in iOS 15, like showing state, or is it the same? Maybe they are just relying on metadata pushed via Companion (what you see in the media player widget in action center) and use the remote widget as a complement for navigation. Makes sense in some way as it integrates the remote functionality more tightly into iOS, but kinda feel like they are dropping some functionality with that. We'll see what happens I guess.

[Smiggel]

Is this with the new 4K or the old one? I've heard about the new one not working, but once upgraded to tvOS beta it started working however. Would be interesting to see a complete log. Can you try pairing with atvremote directly and provide me a log? For instance:

atvremote -s <ip> --debug --protocol mrp pair 

https://pyatv.dev/documentation/#installing-pyatv As this is still beta, I won't put that much energy into this as Apple tend to break stuff I their betas from time to time. Might be the case here too.

I have the first 4K gen Apple TV. So, the old one. :-)

I will give the command a try later today, when I figured out where I have to execute it.

Where do I execute this command? I keep getting the error "command not found: atvremote"

[postlund]

Where do I execute this command? I keep getting the error "command not found: atvremote"

You need to install pyatv to get that command. Any computer on the same network as your Apple TV will do. Same for operating system (Linux, Windows or macOS at least). Instructions are in the link above, assuming you have python installed.

[notabene00]

Control center remote widget looks like this in iOS15b2: atvremote -s 192.168.1.10 --debug --protocol mrp pair command results into

2021-06-25 14:11:47 DEBUG: Knocking at ports [3689, 7000, 49152, 32498] on 192.168.1.10
2021-06-25 14:11:47 DEBUG: Auto-discovered Гостиная at 192.168.1.10:49153 (Protocol.MRP)
2021-06-25 14:11:47 DEBUG: Auto-discovered Гостиная at 192.168.1.10:7000 (Protocol.AirPlay)
2021-06-25 14:11:47 DEBUG: Connection made to device
2021-06-25 14:11:47 DEBUG: Configured keep-alive on <asyncio.TransportSocket fd=6, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.104', 64856), raddr=('192.168.1.10', 49153)> (Darwin)
2021-06-25 14:11:47 DEBUG: 192.168.1.104:64856<->192.168.1.10:49153  Connection established
2021-06-25 14:11:47 DEBUG: 192.168.1.104:64856<->192.168.1.10:49153 >> Send (Data=080f122436314646414341362d353343392d343733322d423238392d3844443134413838343038392000a20183010a2434373762366366622d323966312d346437362d383632632d633461396431346134303864120570796174761a066950686f6e6522063138413339332a12636f6d2e6170706c652e545652656d6f746532063334342e32383801406c480150016211636f6d2e6170706c652e54564d75736963680170017801880102a80101b00101)
2021-06-25 14:11:47 DEBUG: 192.168.1.104:64856<->192.168.1.10:49153 >> Send: Protobuf: type: DEVICE_INFO_MESSAGE
identifier: "61FFACA6-53C9-4732-B289-8DD14A884089"
errorCode: NoError
[deviceInfoMessage] {
  uniqueIdentifier: "477b6cfb-29f1-4d76-862c-c4a9d14a408d"
  name: "pyatv"
  localizedModelName: "iPhone"
  systemBuildVersion: "18A393"
  applicationBundleIdentifier: "com.apple.TVRemote"
  applicationBundleVersion: "344.28"
  protocolVersion: 1
  lastSupportedMessageType: 108
  supportsSystemPairing: true
  allowsPairing: true
  systemMediaApplication: "com.apple.TVMusic"
  supportsACL: true
  supportsSharedQueue: true
  supportsExtendedMotion: true
  sharedQueueVersion: 2
  deviceClass: iPhone
  logicalDeviceCount: 1
}

then hangs. No request for code on TV screen.

[Smiggel]

Here is the output (removed the identifiers).

2021-06-29 13:38:16 DEBUG [pyatv.support.knock]: Knocking at ports [3689, 7000, 49152, 32498] on 192.168.0.40 2021-06-29 13:38:16 DEBUG [pyatv.support.scan]: Auto-discovered Slaapkamer at 192.168.0.40:49152 (Protocol.Companion) 2021-06-29 13:38:16 DEBUG [pyatv.support.scan]: Auto-discovered Slaapkamer at 192.168.0.40:49153 (Protocol.MRP) 2021-06-29 13:38:16 DEBUG [pyatv.support.scan]: Auto-discovered Slaapkamer at 192.168.0.40:7000 (Protocol.AirPlay) 2021-06-29 13:38:16 DEBUG [pyatv.support.scan]: Auto-discovered Slaapkamer at 192.168.0.40:7000 (Protocol.RAOP) 2021-06-29 13:38:16 DEBUG [pyatv.mrp.connection]: Connection made to device 2021-06-29 13:38:16 DEBUG [pyatv.support.net]: Configured keep-alive on <asyncio.TransportSocket fd=6, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.0.68', 62450), raddr=('192.168.0.40', 49153)> (Darwin) 2021-06-29 13:38:16 DEBUG [pyatv.mrp.connection]: 192.168.0.68:62450<->192.168.0.40:49153 Connection established 2021-06-29 13:38:16 DEBUG [pyatv.mrp.connection]: 192.168.0.68:62450<->192.168.0.40:49153 >> Send (Data=080f122439454434343537362d324639372d344234342d383133422d3045383334463739463337302000a20183010a2433386536636163642d376264302d346532652d626331652d356231643033306436623565120570796174761a066950686f6e6522063138413339332a12636f6d2e6170706c652e545652656d6f746532063334342e32383801406c480150016211636f6d2e6170706c652e54564d75736963680170017801880102a80101b00101) 2021-06-29 13:38:16 DEBUG [pyatv.mrp.connection]: 192.168.0.68:62450<->192.168.0.40:49153 >> Send: Protobuf: type: DEVICE_INFO_MESSAGE identifier: "-----" errorCode: NoError [deviceInfoMessage] { uniqueIdentifier: "-----" name: "pyatv" localizedModelName: "iPhone" systemBuildVersion: "18A393" applicationBundleIdentifier: "com.apple.TVRemote" applicationBundleVersion: "344.28" protocolVersion: 1 lastSupportedMessageType: 108 supportsSystemPairing: true allowsPairing: true systemMediaApplication: "com.apple.TVMusic" supportsACL: true supportsSharedQueue: true supportsExtendedMotion: true sharedQueueVersion: 2 deviceClass: iPhone logicalDeviceCount: 1 } 2021-06-29 13:38:21 DEBUG [pyatv.mrp.connection]: 192.168.0.68:62450<->192.168.0.40:49153 Closing connection 2021-06-29 13:38:21 ERROR [root]: Pairing failed Traceback (most recent call last): File "/usr/local/Cellar/python@3.9/3.9.1_8/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/locks.py", line 413, in acquire await fut asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "/usr/local/Cellar/python@3.9/3.9.1_8/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/tasks.py", line 489, in wait_for fut.result() asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last): File "/Users/Peter/pyatv_venv/lib/python3.9/site-packages/pyatv/support/init.py", line 33, in error_handler return await func(*args, **kwargs) File "/Users/Peter/pyatv_venv/lib/python3.9/site-packages/pyatv/mrp/auth.py", line 39, in start_pairing await self.protocol.start(skip_initial_messages=True) File "/Users/Peter/pyatv_venv/lib/python3.9/site-packages/pyatv/mrp/protocol.py", line 129, in start self.device_info = await self.send_and_receive(msg) File "/Users/Peter/pyatv_venv/lib/python3.9/site-packages/pyatv/mrp/protocol.py", line 216, in send_and_receive return await self._receive(identifier, timeout) File "/Users/Peter/pyatv_venv/lib/python3.9/site-packages/pyatv/mrp/protocol.py", line 224, in _receive await asyncio.wait_for(semaphore.acquire(), timeout) File "/usr/local/Cellar/python@3.9/3.9.1_8/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/tasks.py", line 491, in wait_for raise exceptions.TimeoutError() from exc asyncio.exceptions.TimeoutError

The above exception was the direct cause of the following exception:

Traceback (most recent call last): File "/Users/Peter/pyatv_venv/lib/python3.9/site-packages/pyatv/scripts/atvremote.py", line 174, in pair await self._perform_pairing(pairing) File "/Users/Peter/pyatv_venv/lib/python3.9/site-packages/pyatv/scripts/atvremote.py", line 184, in _perform_pairing await pairing.begin() File "/Users/Peter/pyatv_venv/lib/python3.9/site-packages/pyatv/mrp/pairing.py", line 43, in begin return await error_handler( File "/Users/Peter/pyatv_venv/lib/python3.9/site-packages/pyatv/support/init.py", line 35, in error_handler raise exceptions.ConnectionFailedError(str(ex)) from ex pyatv.exceptions.ConnectionFailedError 2021-06-29 13:38:21 DEBUG [pyatv.mrp.connection]: 192.168.0.68:62450<->192.168.0.40:49153 Closing connection 2021-06-29 13:38:21 DEBUG [pyatv.mrp.connection]: 192.168.0.68:62450<->192.168.0.40:49153 Disconnected from device: None 2021-06-29 13:38:21 DEBUG [pyatv.mrp.connection]: 192.168.0.68:62450<->192.168.0.40:49153 Closing connection

[postlund]

Looks to me like the device isn't responding to the initial message. Would be interesting to know if the same problem exists when using an iOS 14.x device (I.e, does the Remote app still work). Based on earlier inquiries, it probably won't and apple is removing support for MRP. In the end, that would mean that a lot more effort needs to be put into Companion.

[Smiggel]

Looks to me like the device isn't responding to the initial message. Would be interesting to know if the same problem exists when using an iOS 14.x device (I.e, does the Remote app still work). Based on earlier inquiries, it probably won't and apple is removing support for MRP. In the end, that would mean that a lot more effort needs to be put into Companion.

The problems started to occur here, after upgrading to 15.x. Before that it worked fine, but then again it was already paired a long time ago.

[notabene00]

Would be interesting to know if the same problem exists when using an iOS 14.x device (I.e, does the Remote app still work)

Remote inside of iOS 14 iPhone's control center works fine with tvOS 15 Apple TV

[postlund]

Would be interesting to know if the same problem exists when using an iOS 14.x device (I.e, does the Remote app still work)

Remote inside of iOS 14 iPhone's control center works fine with tvOS 15 Apple TV

Control center uses the companion protocol, not MRP. That's why it works. MRP was used in in control center up until iOS 13 (or 12?) I think, then they switched.

[notabene00]

Well. So what should I try to help to clear up what's going on there?

[postlund]

Unless the Remote app starts working again (on an older version of iOS for instance), so we can sniff the traffic and see what changed, then we're stuck with getting the companion protocol up in shape to eventually replace MRP.

[gislis2]

Unless the Remote app starts working again (on an older version of iOS for instance), so we can sniff the traffic and see what changed, then we're stuck with getting the companion protocol up in shape to eventually replace MRP.

I might have an iOS 12 or 13 device at work. If so I'll try it and report back tomorrow with results

[oxplot]

I can confirm that my iPhone remote (under control center) on iOS 15 connects to tvOS 15 over Companion port (49153) instead of MRP. I've got packet dumps if anyone needs it.

EDIT:

Looks like the current atvremote --protocol companion pair and the iOS remote send different initial messages:

iOS remote: 0500002fe1435f70649128060101032086dc74d4494a09104856abeab9ebb178c2d1bf1044f5cbdb79eba9e37c504611190101
atvremote:  03000013e2435f706476000100060101455f7077547909

[postlund]

@oxplot That is as expected, no further package dumps needed as for now at least.

That also looks as expected. Message type 05 is "pair setup" (PS), which is used to set up new credentials whilst 05 is "pair verify" (PV), used to verify existing credentials and derive encryption keys for a new session. The normal flow is that the client tries to verify any credentials it has since earlier, before issuing PS. In pyatv, I always issue PS when pairing and PV when connecting no matter what. Should not be a problem. Do you have any other issue when using the companion protocol?

[oxplot]

@postlund oh, I get the same error as @BVGorp.

[postlund]

@oxplot Right, that is because of MRP and not Companion. Kinda lost track of the main topic here... I believe that Companion still works fine and I need to try to implement corresponding functionality in Companion to get things working again (unless the MRP service starts working again). I'm on that at least.

[oxplot]

In case it's useful, I get the following error when trying Companion pairing:

$ atvremote --protocol companion -n 'Lounge TV' pair
2021-07-14 04:25:09 ERROR [root]: Pairing failed
Traceback (most recent call last):
  File "/home/mike/tmp/venv/lib/python3.9/site-packages/pyatv/support/__init__.py", line 33, in error_handler
    return await func(*args, **kwargs)
  File "/home/mike/tmp/venv/lib/python3.9/site-packages/pyatv/companion/auth.py", line 63, in start_pairing
    pairing_data = _get_pairing_data(resp)
  File "/home/mike/tmp/venv/lib/python3.9/site-packages/pyatv/companion/auth.py", line 24, in _get_pairing_data
    raise exceptions.AuthenticationError("no pairing data in message")
pyatv.exceptions.AuthenticationError: no pairing data in message

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/mike/tmp/venv/lib/python3.9/site-packages/pyatv/scripts/atvremote.py", line 174, in pair
    await self._perform_pairing(pairing)
  File "/home/mike/tmp/venv/lib/python3.9/site-packages/pyatv/scripts/atvremote.py", line 184, in _perform_pairing
    await pairing.begin()
  File "/home/mike/tmp/venv/lib/python3.9/site-packages/pyatv/companion/pairing.py", line 52, in begin
    await error_handler(
  File "/home/mike/tmp/venv/lib/python3.9/site-packages/pyatv/support/__init__.py", line 41, in error_handler
    raise fallback(str(ex)) from ex
pyatv.exceptions.PairingError: no pairing data in message

[postlund]

@oxplot That is indeed interesting! Can you run that again but include --debug as well?

[oxplot]

@postlund oh I see what's happening. I remember flicking on some restriction somewhere in some settings:

$ atvremote --debug --protocol companion -n 'Lounge TV' pair
2021-07-14 06:23:26 DEBUG [pyatv.support.net]: Binding on *:5353
2021-07-14 06:23:26 DEBUG [pyatv.support.net]: Binding on 127.0.0.1:0
2021-07-14 06:23:26 DEBUG [pyatv.support.net]: Binding on 192.168.2.41:0
2021-07-14 06:23:26 DEBUG [pyatv.support.net]: Binding on 192.168.122.1:0
2021-07-14 06:23:26 DEBUG [pyatv.support.net]: Binding on 172.17.0.1:0
2021-07-14 06:23:26 DEBUG [pyatv.support.net]: Binding on 10.48.132.1:0
2021-07-14 06:23:29 DEBUG [pyatv.support.scan]: Auto-discovered Lounge Left Speaker at 192.168.2.58:7000 (Protocol.AirPlay)
2021-07-14 06:23:29 DEBUG [pyatv.support.scan]: Auto-discovered Lounge Left Speaker at 192.168.2.58:7000 (Protocol.RAOP)
2021-07-14 06:23:29 DEBUG [pyatv.support.scan]: Auto-discovered Lounge Left Speaker at 192.168.2.58:49152 (Protocol.Companion)
2021-07-14 06:23:29 DEBUG [pyatv.support.scan]: Auto-discovered Lounge TV at 192.168.2.57:49152 (Protocol.MRP)
2021-07-14 06:23:29 DEBUG [pyatv.support.scan]: Auto-discovered Lounge TV at 192.168.2.57:49153 (Protocol.Companion)
2021-07-14 06:23:29 DEBUG [pyatv.support.scan]: Auto-discovered Lounge TV at 192.168.2.57:7000 (Protocol.AirPlay)
2021-07-14 06:23:29 DEBUG [pyatv.support.scan]: Auto-discovered Lounge TV at 192.168.2.57:7000 (Protocol.RAOP)
2021-07-14 06:23:29 DEBUG [pyatv.support.scan]: Auto-discovered Lounge Right Speaker at 192.168.2.51:7000 (Protocol.AirPlay)
2021-07-14 06:23:29 DEBUG [pyatv.support.scan]: Auto-discovered Lounge Right Speaker at 192.168.2.51:7000 (Protocol.RAOP)
2021-07-14 06:23:29 DEBUG [pyatv.support.scan]: Auto-discovered Lounge Right Speaker at 192.168.2.51:49152 (Protocol.Companion)
2021-07-14 06:23:29 DEBUG [pyatv.support.scan]: Auto-discovered iPad at 192.168.2.50:52607 (Protocol.Companion)
2021-07-14 06:23:29 DEBUG [pyatv.companion.pairing]: Start pairing Companion
2021-07-14 06:23:29 DEBUG [pyatv.companion.connection]: Connected to companion device 192.168.2.57:49153
2021-07-14 06:23:29 DEBUG [pyatv.companion.protocol]: Companion credentials: None
2021-07-14 06:23:29 DEBUG [pyatv.companion.protocol]: Send OPACK: {'_pd': b'\x00\x01\x00\x06\x01\x01', '_pwTy': 1}
2021-07-14 06:23:29 DEBUG [pyatv.companion.connection]: >> Send data (Data=e2435f706476000100060101455f7077547909, FrameType=03)
2021-07-14 06:23:29 DEBUG [pyatv.companion.connection]: Received data (Data=04000028e2435f65633188e5435f656d5b4e6f6e2d686f6d6520616363657373206e6f7420616c6c6f776564)
2021-07-14 06:23:29 DEBUG [pyatv.companion.connection]: Recv data (Data=04000028e2435f65633188e5435f656d5b4e6f6e2d686f6d6520616363657373206e6f7420616c6c6f776564)
2021-07-14 06:23:29 DEBUG [pyatv.companion.protocol]: Receive OPACK: {'_ec': 58760, '_em': 'Non-home access not allowed'}
2021-07-14 06:23:29 ERROR [root]: Pairing failed
Traceback (most recent call last):
  File "/home/mike/tmp/venv/lib/python3.9/site-packages/pyatv/support/__init__.py", line 33, in error_handler
    return await func(*args, **kwargs)
  File "/home/mike/tmp/venv/lib/python3.9/site-packages/pyatv/companion/auth.py", line 63, in start_pairing
    pairing_data = _get_pairing_data(resp)
  File "/home/mike/tmp/venv/lib/python3.9/site-packages/pyatv/companion/auth.py", line 24, in _get_pairing_data
    raise exceptions.AuthenticationError("no pairing data in message")
pyatv.exceptions.AuthenticationError: no pairing data in message

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/mike/tmp/venv/lib/python3.9/site-packages/pyatv/scripts/atvremote.py", line 174, in pair
    await self._perform_pairing(pairing)
  File "/home/mike/tmp/venv/lib/python3.9/site-packages/pyatv/scripts/atvremote.py", line 184, in _perform_pairing
    await pairing.begin()
  File "/home/mike/tmp/venv/lib/python3.9/site-packages/pyatv/companion/pairing.py", line 52, in begin
    await error_handler(
  File "/home/mike/tmp/venv/lib/python3.9/site-packages/pyatv/support/__init__.py", line 41, in error_handler
    raise fallback(str(ex)) from ex
pyatv.exceptions.PairingError: no pairing data in message
2021-07-14 06:23:29 DEBUG [pyatv.companion.connection]: Closing connection
2021-07-14 06:23:29 DEBUG [pyatv.companion.connection]: Connection lost to remote device: None

will look for that setting and re-run the pairing again.

[postlund]

Yeah, that definitely sounds like it! Should be added to the FAQ or so once you've found it, to help others 👍

[postlund]

I opened #1210 to improve the error message situation a bit. Will implement it when I have some time.

[oxplot]

OK, the Companion pairing works now after I allowed access from the same WiFi network, and not just the users belonging to the Apple Home. Although, running any commands (e.g. turn_off) ignores the --protocol=companion and tries to use MRP which obviously fails.

[postlund]

@oxplot Where is that setting located?

I realized that problem as well, so I made it possible to scan for specific protocols. As companion doesn't have a unique id we can use, another protocol that has one (like AirPlay) must be added as well:

atvremote -s ip --scan-protocols companion,airplay --companion-credentials xxx turn_off

Hope that works (you need to run from master to get this).

[oxplot]

@postlund

and here's the output of the command you posted on master:

$ git rev-parse HEAD
bdaf12a448daeb430013ca5a2702e35e0fbd3f35
$ atvremote --debug -s 192.168.2.57 --scan-protocols companion,airplay --companion-credentials xxx:xxx:xxx:xxx turn_off
2021-07-20 12:44:11 DEBUG [pyatv.support.knock]: Knocking at ports [3689, 7000, 49152, 32498] on 192.168.2.57
2021-07-20 12:44:11 DEBUG [pyatv.support.scan]: Auto-discovered Lounge TV at 192.168.2.57:49153 via Protocol.Companion ({'rpmac': '2', 'rphn': '0db8852909ab', 'rpfl': '0xB6782', 'rpha': '81293fa443eb', 'rpmd': 'AppleTV11,1', 'rpvr': '300.56', 'rpad': 'a148c38c5c6b', 'rphi': 'db1935087fe2', 'rpba': '11:03:AE:BF:59:8B', 'rpmrtid': '51F9F01D-BD50-44B6-AB2B-E70D043F4B36'})
2021-07-20 12:44:11 DEBUG [pyatv.support.scan]: Auto-discovered Lounge TV at 192.168.2.57:7000 via Protocol.AirPlay ({'acl': '0', 'btaddr': '58:D3:49:EA:0E:55', 'deviceid': '58:D3:49:E9:3B:82', 'fex': '1d9/St5/Fbw', 'features': '0x4A7FDFD5,0xBC157FDE', 'flags': '0x18644', 'gid': '45EE8938-2CDE-4291-B05E-568CADAD7FC0', 'igl': '1', 'gcgl': '1', 'model': 'AppleTV11,1', 'protovers': '1.1', 'pi': 'ce895475-1870-4861-a148-fa06346fde9b', 'psi': '51F9F01D-BD50-44B6-AB2B-E70D043F4B36', 'pk': 'e88b266050c28b2206d48275e373eb72fb2c1f03c133a54810d0da2c49ea44bb', 'srcvers': '566.15.1', 'osvers': '15.0', 'vv': '2'})
2021-07-20 12:44:11 INFO [root]: Auto-discovered Lounge TV at 192.168.2.57
2021-07-20 12:44:11 DEBUG [pyatv]: Adding protocol Protocol.Companion
2021-07-20 12:44:11 DEBUG [pyatv.airplay]: No AirPlay credentials loaded
2021-07-20 12:44:11 DEBUG [pyatv]: Adding protocol Protocol.AirPlay
NOTE: Push updates are not supported in this configuration
2021-07-20 12:44:11 DEBUG [pyatv.companion]: Connect to Companion from API
2021-07-20 12:44:11 DEBUG [pyatv.companion.connection]: Connected to companion device 192.168.2.57:49153
2021-07-20 12:44:11 DEBUG [pyatv.companion.protocol]: Companion credentials: xxx:xxx:xxx:xxx
2021-07-20 12:44:11 DEBUG [pyatv.companion.protocol]: Send OPACK: {'_pd': b'\x06\x01\x01\x03 \xd9U\xb0\xdf\x8a\xffF\xfd\x19\xd59Hj\xd3\xfb2\xc6\xd0\xfb\xb6w\x10R\xb1\x08\xdc\x1d\xfdi\x8a\xa5\x0c', '_auTy': 4}
2021-07-20 12:44:11 DEBUG [pyatv.companion.connection]: >> Send data (Data=e2435f706491250601010320d955b0df8aff46fd19d539486ad3fb32c6d0fbb6771052b108dc1dfd698aa50c455f617554790c, FrameType=05)
2021-07-20 12:44:11 DEBUG [pyatv.companion.connection]: Received data (Data=060000a6e1435f7064919f0578a75d998d670dfe478fa6e4e02e48b351d4c283dcab999db6ccc74f507a60e281e2ef77a3b99d2dd5d58c74121c56c9ef5351fa8bb2ce35eb96d2f568b97152014433421b53bf4ed23ea10158c7b6e531dfea9173eeb181ea798c8b754e9630055076604f475939ee87ffda2988708a55a0f173cc4eb8cf7106010203207bce874d37c83d23a592e1659afd3b16bc7e2d28eccaba1b2bd7e074174d0c10)
2021-07-20 12:44:11 DEBUG [pyatv.companion.connection]: Recv data (Data=060000a6e1435f7064919f0578a75d998d670dfe478fa6e4e02e48b351d4c283dcab999db6ccc74f507a60e281e2ef77a3b99d2dd5d58c74121c56c9ef5351fa8bb2ce35eb96d2f568b97152014433421b53bf4ed23ea10158c7b6e531dfea9173eeb181ea798c8b754e9630055076604f475939ee87ffda2988708a55a0f173cc4eb8cf7106010203207bce874d37c83d23a592e1659afd3b16bc7e2d28eccaba1b2bd7e074174d0c10)
2021-07-20 12:44:11 DEBUG [pyatv.companion.protocol]: Receive OPACK: {'_pd': b'\x05x\xa7]\x99\x8dg\r\xfeG\x8f\xa6\xe4\xe0.H\xb3Q\xd4\xc2\x83\xdc\xab\x99\x9d\xb6\xcc\xc7OPz`\xe2\x81\xe2\xefw\xa3\xb9\x9d-\xd5\xd5\x8ct\x12\x1cV\xc9\xefSQ\xfa\x8b\xb2\xce5\xeb\x96\xd2\xf5h\xb9qR\x01D3B\x1bS\xbfN\xd2>\xa1\x01X\xc7\xb6\xe51\xdf\xea\x91s\xee\xb1\x81\xeay\x8c\x8buN\x960\x05Pv`OGY9\xee\x87\xff\xda)\x88p\x8aU\xa0\xf1s\xccN\xb8\xcfq\x06\x01\x02\x03 {\xce\x87M7\xc8=#\xa5\x92\xe1e\x9a\xfd;\x16\xbc~-(\xec\xca\xba\x1b+\xd7\xe0t\x17M\x0c\x10'}
2021-07-20 12:44:11 DEBUG [pyatv.companion.auth]: Device (Encrypted=a75d998d670dfe478fa6e4e02e48b351d4c283dcab999db6ccc74f507a60e281e2ef77a3b99d2dd5d58c74121c56c9ef5351fa8bb2ce35eb96d2f568b97152014433421b53bf4ed23ea10158c7b6e531dfea9173eeb181ea798c8b754e9630055076604f475939ee87ffda2988708a55a0f173cc4eb8cf71, Public=xxx)
2021-07-20 12:44:11 DEBUG [pyatv.companion.protocol]: Send OPACK: {'_pd': b'\x06\x01\x03\x05x\xbc"\xfe\xac\x18f\x00\xa4*.n\x82r\xa9rvMp\xc2g\xabx\xee\xe6U\xf8\xa6#\x12Sg\xab\x14k\x80\x84\xac\xaa\x8cX6\xec\xee`\xf8b`g+\x1f\x1d\xe8"\xad\x8c\xc7\xb4\x06\xacd\x80\xe1"\x86\x06P\xb2d\x02\xd7\xccRr\xcd\xe5$GGg\xfeS\xd0\xac\xe4\xd7Cw\xfc\xa8R\x02\xeai\xcf\x171|.[\t\x94\xbar\x94\x81\x03\xd4\x7ft\xeb\x95\xb7\xc96;\xf3}\xdfD\xc6'}
2021-07-20 12:44:11 DEBUG [pyatv.companion.connection]: >> Send data (Data=e1435f7064917d0601030578bc22feac186600a42a2e6e8272a972764d70c267ab78eee655f8a623125367ab146b8084acaa8c5836ecee60f86260672b1f1de822ad8cc7b406ac6480e122860650b26402d7cc5272cde524474767fe53d0ace4d74377fca85202ea69cf17317c2e5b0994ba72948103d47f74eb95b7c9363bf37ddf44c6, FrameType=06)
2021-07-20 12:44:11 DEBUG [pyatv.companion.connection]: Received data (Data=06000009e1435f706473060104)
2021-07-20 12:44:11 DEBUG [pyatv.companion.connection]: Recv data (Data=06000009e1435f706473060104)
2021-07-20 12:44:11 DEBUG [pyatv.companion.protocol]: Receive OPACK: {'_pd': b'\x06\x01\x04'}
2021-07-20 12:44:11 DEBUG [pyatv.support.hap_srp]: Keys (Input=84999eccada26934f7930739a81c311107ecc4016d9640f6aa6ee00965147252, Output=45db819df2be47df1a3e077328ba2e6625f97938ce8b7451bdc99d390a2931f8)
2021-07-20 12:44:11 DEBUG [pyatv.companion.protocol]: Send OPACK: {'_i': '_sessionStart', '_x': 12356, '_t': '2', '_c': {'_srvT': 'com.apple.tvremoteservices', '_sid': 129352063}}
2021-07-20 12:44:11 DEBUG [pyatv.companion.connection]: >> Send data (Data=e4425f694d5f73657373696f6e5374617274425f78314430425f744132425f63e2455f737276545a636f6d2e6170706c652e747672656d6f74657365727669636573445f736964327fc1b507, FrameType=08)
2021-07-20 12:44:11 DEBUG [pyatv.companion.connection]: >> Send (Encrypted=2fd67a56cd0f6d192dc2487259150354a75490a0b66959b3f7595b13fef2fafe2d97afee257b4694c7f0f4dc9339e925a146537118e57bbe8a88b28c356c7bc47c59ee984e83169fa42da45cedd7a7e38beed3baa52720cf1d62f0c2, Header=0800005c)
2021-07-20 12:44:11 DEBUG [pyatv.companion.connection]: Received data (Data=080000570a7a4d3e4938c0163e7a5efaf4c3d7c2fe7962645de78babdfad44ea219697755e03464779c2951335fd583522591579691b5258554a0ea5e20df6a1b3976ee1e1342ab665afbbddfe1ed190cc5f144976bd8c0508a646)
2021-07-20 12:44:11 DEBUG [pyatv.companion.connection]: Recv data (Data=080000570a7a4d3e4938c0163e7a5efaf4c3d7c2fe7962645de78babdfad44ea219697755e03464779c2951335fd583522591579691b5258554a0ea5e20df6a1b3976ee1e1342ab665afbbddfe1ed190cc5f144976bd8c0508a646)
2021-07-20 12:44:11 DEBUG [pyatv.companion.connection]: << Receive data (Decrypted=e6425f78314430435f656d58556e737570706f7274656420736572766963652074797065435f65633203eafeff435f65644d52504572726f72446f6d61696e425f63e0425f740b, Header=08000057)
2021-07-20 12:44:11 DEBUG [pyatv.companion.protocol]: Receive OPACK: {'_x': 12356, '_em': 'Unsupported service type', '_ec': 4294896131, '_ed': 'RPErrorDomain', '_c': {}, '_t': 3}
Traceback (most recent call last):
  File "/home/mike/tmp/pyatv/venv/lib/python3.9/site-packages/pyatv-0.8.1-py3.9.egg/pyatv/scripts/atvremote.py", line 708, in _run_application
    return await cli_handler(loop)
  File "/home/mike/tmp/pyatv/venv/lib/python3.9/site-packages/pyatv-0.8.1-py3.9.egg/pyatv/scripts/atvremote.py", line 497, in cli_handler
    return await _handle_commands(args, config, loop)
  File "/home/mike/tmp/pyatv/venv/lib/python3.9/site-packages/pyatv-0.8.1-py3.9.egg/pyatv/scripts/atvremote.py", line 606, in _handle_commands
    ret = await _handle_device_command(args, cmd, atv, loop)
  File "/home/mike/tmp/pyatv/venv/lib/python3.9/site-packages/pyatv-0.8.1-py3.9.egg/pyatv/scripts/atvremote.py", line 641, in _handle_device_command
    return await _exec_command(atv.power, cmd, True, *cmd_args)
  File "/home/mike/tmp/pyatv/venv/lib/python3.9/site-packages/pyatv-0.8.1-py3.9.egg/pyatv/scripts/atvremote.py", line 674, in _exec_command
    value = await tmp(*args)
  File "/home/mike/tmp/pyatv/venv/lib/python3.9/site-packages/pyatv-0.8.1-py3.9.egg/pyatv/support/facade.py", line 308, in turn_off
    await self.relay("turn_off", priority=self.OVERRIDE_PRIORITIES)(
  File "/home/mike/tmp/pyatv/venv/lib/python3.9/site-packages/pyatv-0.8.1-py3.9.egg/pyatv/companion/__init__.py", line 247, in turn_off
    await self.api.sleep()
  File "/home/mike/tmp/pyatv/venv/lib/python3.9/site-packages/pyatv-0.8.1-py3.9.egg/pyatv/companion/__init__.py", line 168, in sleep
    await self._hid_command(False, HidCommand.Sleep)
  File "/home/mike/tmp/pyatv/venv/lib/python3.9/site-packages/pyatv-0.8.1-py3.9.egg/pyatv/companion/__init__.py", line 175, in _hid_command
    await self._send_command(
  File "/home/mike/tmp/pyatv/venv/lib/python3.9/site-packages/pyatv-0.8.1-py3.9.egg/pyatv/companion/__init__.py", line 127, in _send_command
    await self._connect()
  File "/home/mike/tmp/pyatv/venv/lib/python3.9/site-packages/pyatv-0.8.1-py3.9.egg/pyatv/companion/__init__.py", line 115, in _connect
    await self._session_start()
  File "/home/mike/tmp/pyatv/venv/lib/python3.9/site-packages/pyatv-0.8.1-py3.9.egg/pyatv/companion/__init__.py", line 150, in _session_start
    resp = await self._send_command(
  File "/home/mike/tmp/pyatv/venv/lib/python3.9/site-packages/pyatv-0.8.1-py3.9.egg/pyatv/companion/__init__.py", line 132, in _send_command
    resp = await self._protocol.exchange_opack(
  File "/home/mike/tmp/pyatv/venv/lib/python3.9/site-packages/pyatv-0.8.1-py3.9.egg/pyatv/companion/protocol.py", line 84, in exchange_opack
    raise exceptions.ProtocolError(f"Command failed: {unpacked_object['_em']}")
pyatv.exceptions.ProtocolError: Command failed: Unsupported service type

>>> An error occurred, full stack trace above

[oxplot]

@postlund

[postlund]

@oxplot Interesting! Apple must have removed that service then. Do you by any chance have access to a Mac and some time to try a few things?

[oxplot]

Do you by any chance have access to a Mac and some time to try a few things?

Sure

[postlund]

@oxplot Thanks, this will help a lot! First you need to enable development mode on your Apple TV. I think the first part (about pairing) here should work:

https://www.programmersought.com/article/13675638712/

Might be named "Organizer" or something similar in Xcode if you can't find it. Once enabled, your device should appear in the list to the left in "System Messages" (macOS bundled app). You can select it and enable streaming to see that it works. Filter on the "rapportd" process (just write rapportd, press enter and then you can pick Process in the list from the little arrow). Once this is set up, stop streaming and clear the view.

Now, start Shortcuts on an iOS device and create a new shortcut. Select Apps and Apple TV. Start streaming events again in System messages. Back I Shortcuts, select the "Open app" shortcut and make sure to bring up the list of installed apps on the device. Now you can stop streaming events in System messages. You don't need to start any apps or finish the shortcut, it's only important that you start streaming events before returning the app list in order to set up a new session so we get the correct stuff in the log. You can also start streaming events earlier if you like, I just prefer to "keep it close in time" to the thing I'm interested in, to minimize what ends up in the log list.

At this point, move over to System messages again and look for a line containing FetchLaunchableApplicationsEvent. I'm interested in a few lines around that, maybe +-20 lines or so. The list supports regular copy, so you can just select and copy. Shouldn't be anything sensitive in there (apple usually filter that), but I'd recommend that you send the output by email to me for privacy reasons. You have the email in my profile. If you can't find that line, maybe the changed the API. In that case, you can just send the entire list and I'll try to make sense out of it.

[oxplot]

Unfortunately, I can't get the list of TV apps on my Shortcut iOS app, on either iOS 15 Beta or 14 (I get a Open App on Apple TV was unable to get the list of apps from TV. Make sure your Apple TV is running the latest software). I assume it's an issue with the tvOS Beta. I captured the logs anyway:

default 14:20:48.260889+1000    bluetoothd  Le [0x40]: time  40, coex   0, rssi -78, tx [S=  0:F=  0], rx [S=  0:F=  0], 1M {rx 0, tx 0}, 2M {rx 0, tx 0}
default 14:20:48.298579+1000    rapportd    Update client from assistantd:32
default 14:20:48.304893+1000    mediaserverd    0x58d349e93b820008: added audio timestamps (17372160, 8998080000) from 0x58d349e93b820008.0 using time pair (374920000000, 8998080000). {260000000, 6240000} holdover NO
default 14:20:48.564544+1000    mediaserverd    0x58d349e93b820008: added audio timestamps (17384640, 9004320000) from 0x58d349e93b820008.0 using time pair (375180000000, 9004320000). {260000000, 6240000} holdover NO
default 14:20:48.640146+1000    kernel  tcp_timers: tcp_output() returned 0 with retransmission timer disabled for 49175 > 57687 in state 4, reset timer to 961
default 14:20:48.824363+1000    mediaserverd    0x58d349e93b820008: added audio timestamps (17397120, 9010560000) from 0x58d349e93b820008.0 using time pair (375440000000, 9010560000). {260000000, 6240000} holdover NO
default 14:20:48.844494+1000    kernel  tcp_timers: tcp_output() returned 0 with retransmission timer disabled for 49175 > 57687 in state 4, reset timer to 521
default 14:20:48.846265+1000    mDNSResponder   Received Goodbye packet for cached record - name: <mask.hash: 'DM9eTs4UMmPinb7Wdhk7Ow=='>, type: PTR, last time received: 2021-07-23 14:20:46.081+1000, interface: en1, source address: <mask.hash: '499Bo/zbAyXsWtv1aExeBQ=='>, RDATA domain if PTR: <mask.hash: 'xgvlWNJkXJd/nENxslHnBg=='>
default 14:20:48.846489+1000    mDNSResponder   Received Goodbye packet for cached record - name: <mask.hash: 'CDfedL97+lyM3EY1BkbdBg=='>, type: TXT, last time received: 2021-07-23 14:20:46.082+1000, interface: en1, source address: <mask.hash: '499Bo/zbAyXsWtv1aExeBQ=='>, RDATA domain if PTR: <mask.hash: (null)>
default 14:20:48.922055+1000    rapportd    40: Received event ID '_interest', XID 0xD8BED5FB, 1 keys, from 3b2c4992ab0d
default 14:20:48.995981+1000    rapportd    40: Received event ID '_interest', XID 0xD8BED5FC, 1 keys, from 3b2c4992ab0d
default 14:20:48.996480+1000    rapportd    Interest register remote: Peer 3b2c4992ab0d, EventID _iMC (1 total)
default 14:20:48.996642+1000    rapportd    MediaRemote changes start
default 14:20:48.996784+1000    rapportd    MediaRemote supported commands get
default 14:20:48.996948+1000    rapportd    Request: supportedCommands<615F8674-7CBF-409C-8325-EFBEA954DAD4> for origin-(null)-0/client--0/player-(null)
default 14:20:48.997514+1000    rapportd    Request: resolvePlayerPath<7544F900-B841-484A-83D0-2FB8A9E81FCD> for origin-(null)-0/client--0/player-(null)
default 14:20:48.998560+1000    rapportd    Volume control available initial PB: no
default 14:20:48.998933+1000    rapportd    Volume control available initial: MR no
default 14:20:48.999262+1000    rapportd    40: Received requestID '_mcc', XID 0x704BA8AC, 1 keys, from 3b2c4992ab0d
default 14:20:49.000360+1000    rapportd    Command <GetCaptionSetting>, { "_mcc" : 12, }
default 14:20:49.002041+1000    rapportd    Response: resolvePlayerPath<7544F900-B841-484A-83D0-2FB8A9E81FCD> returned <origin-Lounge TV-1280262988/client-(null)/player-(null)> for origin-(null)-0/client--0/player-(null) in 0.0040 seconds
default 14:20:49.003846+1000    rapportd    MediaCaptionGet: ForcedOnly
default 14:20:49.004004+1000    rapportd    40: Send response XID 0x704BA8AC, <9729aa0dacdabc28eaccc8a465fffdc2> (39 bytes) on link type WiFi, 0/0x0 noErr
default 14:20:49.004333+1000    rapportd    Response: supportedCommands<615F8674-7CBF-409C-8325-EFBEA954DAD4> returned <0 commands> for origin-Lounge TV-1280262988/client-(null)/player-(null) in 0.0078 seconds
default 14:20:49.004801+1000    rapportd    MediaRemote supported commands got: 0 items
default 14:20:49.005096+1000    rapportd    40: Received requestID '_touchStart', XID 0x704BA8AD, 3 keys, from 3b2c4992ab0d
default 14:20:49.005390+1000    rapportd    Touch start: { "_height" : 1000.000000, "_tFl" : 0, "_width" : 1000.000000, }
default 14:20:49.005673+1000    rapportd    40: Send response XID 0x704BA8AD, <61d3f94d78c178520f6bad7f9dadb5b7> (37 bytes) on link type WiFi, 0/0x0 noErr
default 14:20:49.006220+1000    rapportd    40: Received requestID '_tiStart', XID 0x704BA8AE, 0 keys, from 3b2c4992ab0d
default 14:20:49.006480+1000    rapportd    TextInput start: ID '3b2c4992ab0d', Request {}, Response {} (0 bytes)
default 14:20:49.006625+1000    rapportd    40: Send response XID 0x704BA8AE, <8195a003a2b4f0bc55c51db5c46af1c9> (33 bytes) on link type WiFi, 0/0x0 noErr
default 14:20:49.013607+1000    rapportd    40: Received requestID 'FetchLaunchableApplicationsEvent', XID 0x704BA8AF, 1 keys, from 3b2c4992ab0d
default 14:20:49.018513+1000    rapportd    40: ### Sending response XID 0x704BA8AF, error: kNotHandledErr (No request handler)
default 14:20:49.018630+1000    rapportd    40: Send response XID 0x704BA8AF, <e23736c3d5ff885add7703077d9897c3> (81 bytes) on link type WiFi, -6714/0xFFFFE5C6 kNotHandledErr
default 14:20:49.084521+1000    mediaserverd    0x58d349e93b820008: added audio timestamps (17409600, 9016800000) from 0x58d349e93b820008.0 using time pair (375700000000, 9016800000). {260000000, 6240000} holdover NO
default 14:20:49.183980+1000    corercd __CECIOCECInterfaceReceiveCallback length=1, init/dest=4, type=00, context=0x0000000104E08C30
default 14:20:49.184143+1000    corercd RX: TV -> Playback Device 1: <Polling Message>
default 14:20:49.264619+1000    bluetoothd  Le [0x40]: time  41, coex   0, rssi -78, tx [S=  0:F=  0], rx [S=  0:F=  0], 1M {rx 0, tx 0}, 2M {rx 0, tx 0}
default 14:20:49.344772+1000    mediaserverd    0x58d349e93b820008: added audio timestamps (17422080, 9023040000) from 0x58d349e93b820008.0 using time pair (375960000000, 9023040000). {260000000, 6240000} holdover NO
default 14:20:49.487387+1000    kernel  [WiFiTimeSync] Stats: ErrClockID[000000.000000000, 0], ErrInvalidTS[000000.000000000, 0], ErrTimeLineFilterState[000000.000000000, 0], ErrGPIOToMsgDiffGT5s[000000.000000000, 0], ErrNoTimestamps[000000.000000000, 0], ErrTxIONotFreed[000000.000000000, 0]
default 14:20:49.598922+1000    kernel  tcp_timers: tcp_output() returned 0 with retransmission timer disabled for 49175 > 57687 in state 4, reset timer to 1054
default 14:20:49.604415+1000    mediaserverd    0x58d349e93b820008: added audio timestamps (17434560, 9029280000) from 0x58d349e93b820008.0 using time pair (376220000000, 9029280000). {260000000, 6240000} holdover NO
default 14:20:49.864566+1000    mediaserverd    0x58d349e93b820008: added audio timestamps (17447040, 9035520000) from 0x58d349e93b820008.0 using time pair (376480000000, 9035520000). {260000000, 6240000} holdover NO
default 14:20:49.945979+1000    mDNSResponder   [R30->Q0] DNSServiceBrowse(<mask.hash: 'DM9eTs4UMmPinb7Wdhk7Ow=='>, PTR) RESULT RMV interface 9: <mask.hash: 'VV1lRRIPmEi314cIGq+m+Q=='>
default 14:20:49.947069+1000    rapportd    CLink: Lost CUBonjourDevice C9:BB:97:8B:2A:2C, 'iPad'
default 14:20:49.947273+1000    mDNSResponder   [R328] DNSServiceQueryRecord(404000, 9, <mask.hash: 'xgvlWNJkXJd/nENxslHnBg=='>, TXT) STOP PID[76](rapportd)
default 14:20:49.947415+1000    rapportd    Bonjour unauth peer lost <C9:BB:97:8B:2A:2C>: CUBonjourDevice C9:BB:97:8B:2A:2C, 'iPad'
default 14:20:49.947984+1000    mDNSResponder   mDNS_StopQuery_internal: NumAllInterfaceRecords 70 NumAllInterfaceQuestions 31 <mask.hash: 'xgvlWNJkXJd/nENxslHnBg=='> (TXT)
default 14:20:49.979149+1000    mediaserverd    <<<< IQ-CA >>>> piqca_gmstats_dump: FIQCA(0x121017800) client pid 254, timebase rate: 1.00, layer time: 148.814 s, host: 376.625 s, diff: 227.811 s; iq unconsumed: 6, min: 148.949, max: 149.116; preventsDisplaySleep: NO
default 14:20:49.979587+1000    mediaserverd    <<<< IQ-CA >>>> piqca_gmstats_dump: FIQCA(0x121017800) recent frames: enqueued: 181, displayed: 180, dropped: 0, flushed: 0, evicted: 0, >16ms late: 0
default 14:20:49.979747+1000    mediaserverd    <<<< IQ-CA >>>> piqca_gmstats_dump: FIQCA(0x121017800) most recently enqueued:
Enqueued Pixel Buffer:[xv0, 3840 x 2160 [
{PTS: 149.049 s, enqueued at: host 376.433 s (media 148.622 s)},
{PTS: 149.016 s, enqueued at: host 376.560 s (media 148.750 s)},
{PTS: 149.116 s, enqueued at: host 376.565 s (media 148.755 s)},
{PTS: 149.082 s, enqueued at: host 376.571 s (media 148.760 s)},
]
default 14:20:49.979892+1000    mediaserverd    <<<< IQ-CA >>>> piqca_gmstats_dump: FIQCA(0x121017800) most recently displayed:
DisplaySize: 3840.000000 x 2160.000000 [
{PTS: 148.715 s, sampled at: 376.425 s, displayed at: 148.720 s, on glass for: 16.683 ms},
{PTS: 148.749 s, sampled at: 376.458 s, displayed at: 148.753 s, on glass for: 16.683 ms},
{PTS: 148.782 s, sampled at: 376.491 s, displayed at: 148.786 s, on glass for: 16.683 ms},
{PTS: 148.815 s, sampled at: 376.525 s, displayed at: 148.820 s, on glass for: 16.683 ms},
]
default 14:20:50.124308+1000    mediaserverd    0x58d349e93b820008: added audio timestamps (17459520, 9041760000) from 0x58d349e93b820008.0 using time pair (376740000000, 9041760000). {260000000, 6240000} holdover NO
error   14:20:50.131386+1000    wpantund    NCP => <private><private>
error   14:20:50.134541+1000    wpantund    NCP => <private><private>
default 14:20:50.261125+1000    kernel  tcp_timers: tcp_output() returned 0 with retransmission timer disabled for 49175 > 57687 in state 4, reset timer to 990
default 14:20:50.269167+1000    bluetoothd  Le [0x40]: time  41, coex   0, rssi   0, tx [S=  0:F=  0], rx [S=  0:F=  0], 1M {rx 0, tx 0}, 2M {rx 0, tx 0}
default 14:20:50.384325+1000    mediaserverd    0x58d349e93b820008: added audio timestamps (17472000, 9048000000) from 0x58d349e93b820008.0 using time pair (377000000000, 9048000000). {260000000, 6240000} holdover NO
default 14:20:50.633533+1000    kernel  tcp_timers: tcp_output() returned 0 with retransmission timer disabled for 49175 > 57687 in state 4, reset timer to 699
default 14:20:50.644296+1000    mediaserverd    0x58d349e93b820008: added audio timestamps (17484480, 9054240000) from 0x58d349e93b820008.0 using time pair (377260000000, 9054240000). {260000000, 6240000} holdover NO
default 14:20:50.684828+1000    mediaserverd    <<<< VMC >>>> vmc2GMFigLogDumpStats: VMC(0x12101b200): client pid 254; timebase time: 149.520 s rate: 1.00. recent stats: cfq empty: 2 times; frames decoded: 181, dropped: 0; decode: mean 0.011 s, max: 0.016 s, enhancement blocked: mean 0.000 s, max: 0.000 s; codec service tier: 0.
default 14:20:50.685267+1000    mediaserverd    <<<< VMC >>>> vmc2GMFigLogDumpStats: VMC(0x12101b200):Snapshots:

[oxplot]

I can confirm that in the latest tvOS beta, the issue in my previous comment is resolved, and now I can launch apps, play media, etc.

[postlund]

Thank you @oxplot for confirming that! Always nice when they actually didn't change anything.

[postlund]

After countless amount of hours, I've managed to figure out how it works in tvOS 15 and onwards. Wrote about it here: https://github.com/postlund/pyatv/issues/1255#issuecomment-902228770

🍻 😎

[reffr]

@oxplot I updated to the latest beta but cannot get it to work. Is there something else I need to do?

[postlund]

Beta testers will be needed soon-ish, see https://github.com/postlund/pyatv/issues/1255#issuecomment-903647784 for details.

[Airey001]

if you need more testers i can help out!

[postlund]

@Airey001 PR ready in #1263 for testing!

[postlund]

As everything is merged to master now, I guess this issue is sort-of done. I need to finish off the 0.9.0 release and bump it into Home Assistant. A few things remain but I'm getting close.

[clipse2004]

Hi, I use hassio and wanted to update via terminal the "masters" but fails miniaudio.

The easiest thing would be to wait until you have applied the update right?

[postlund]

@clipse2004 What error are you getting more exactly?

[clipse2004]

When i try to installiert via Terminal? here my log:

pip3 install --upgrade git+https://github.com/postlund/pyatv.git Collecting git+https://github.com/postlund/pyatv.git Cloning https://github.com/postlund/pyatv.git to /tmp/pip-req-build-qv6x3o8d Running command git clone -q https://github.com/postlund/pyatv.git /tmp/pip-req-build-qv6x3o8d Installing build dependencies ... done Getting requirements to build wheel ... done Installing backend dependencies ... done Preparing wheel metadata ... done Collecting netifaces>=0.10.0 Downloading netifaces-0.11.0.tar.gz (30 kB) Collecting srptools>=0.2.0 Downloading srptools-1.0.1-py2.py3-none-any.whl (13 kB) Collecting mediafile>=0.8.0 Downloading mediafile-0.8.0-py3-none-any.whl (21 kB) Requirement already satisfied: aiohttp<5,>=3.1.0 in /usr/lib/python3.9/site-packages (from pyatv==0.8.2) (3.7.4.post0) Collecting miniaudio>=1.44 Downloading miniaudio-1.44.tar.gz (524 kB) |████████████████████████████████| 524 kB 4.4 MB/s ERROR: Command errored out with exit status 1: command: /usr/bin/python3 -c 'import sys, setuptools, tokenize; sys.argv[0] = '"'"'/tmp/pip-install-piq91huy/miniaudio_66bfbb489aa14346ae206e61ce26bb24/setup.py'"'"'; file='"'"'/tmp/pip-install-piq91huy/miniaudio_66bfbb489aa14346ae206e61ce26bb24/setup.py'"'"';f=getattr(tokenize, '"'"'open'"'"', open)(file);code=f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, file, '"'"'exec'"'"'))' egg_info --egg-base /tmp/pip-pip-egg-info-d35hfoj5 cwd: /tmp/pip-install-piq91huy/miniaudio_66bfbb489aa14346ae206e61ce26bb24/ Complete output (77 lines): WARNING: The wheel package is not available. ERROR: Command errored out with exit status 1: command: /usr/bin/python3 -u -c 'import sys, setuptools, tokenize; sys.argv[0] = '"'"'/tmp/pip-wheel-qp9mt24k/cffi_9a4a34a151b844f1ba55e74ef951b9bc/setup.py'"'"'; file='"'"'/tmp/pip-wheel-qp9mt24k/cffi_9a4a34a151b844f1ba55e74ef951b9bc/setup.py'"'"';f=getattr(tokenize, '"'"'open'"'"', open)(file);code=f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, file, '"'"'exec'"'"'))' bdist_wheel -d /tmp/pip-wheel-d1llnpdc cwd: /tmp/pip-wheel-qp9mt24k/cffi_9a4a34a151b844f1ba55e74ef951b9bc/ Complete output (39 lines): Package libffi was not found in the pkg-config search path. Perhaps you should add the directory containing libffi.pc' to the PKG_CONFIG_PATH environment variable Package 'libffi', required by 'virtual:world', not found Package libffi was not found in the pkg-config search path. Perhaps you should add the directory containinglibffi.pc' to the PKG_CONFIG_PATH environment variable Package 'libffi', required by 'virtual:world', not found Package libffi was not found in the pkg-config search path. Perhaps you should add the directory containing libffi.pc' to the PKG_CONFIG_PATH environment variable Package 'libffi', required by 'virtual:world', not found Package libffi was not found in the pkg-config search path. Perhaps you should add the directory containinglibffi.pc' to the PKG_CONFIG_PATH environment variable Package 'libffi', required by 'virtual:world', not found Package libffi was not found in the pkg-config search path. Perhaps you should add the directory containing `libffi.pc' to the PKG_CONFIG_PATH environment variable Package 'libffi', required by 'virtual:world', not found

      No working compiler found, or bogus compiler options passed to
      the compiler from Python's standard "distutils" module.  See
      the error messages above.  Likely, the problem is not related
      to CFFI but generic to the setup.py of any Python package that
      tries to compile C code.  (Hints: on OS/X 10.8, for errors about
      -mno-fused-madd see http://stackoverflow.com/questions/22313407/
      Otherwise, see https://wiki.python.org/moin/CompLangPython or
      the IRC channel #python on irc.libera.chat.)

      Trying to continue anyway.  If you are trying to install CFFI from
      a build done in a different context, you can ignore this warning.

  usage: setup.py [global_opts] cmd1 [cmd1_opts] [cmd2 [cmd2_opts] ...]
     or: setup.py --help [cmd1 cmd2 ...]
     or: setup.py --help-commands
     or: setup.py cmd --help

  error: invalid command 'bdist_wheel'
  ----------------------------------------
  ERROR: Failed building wheel for cffi
ERROR: Failed to build one or more wheels
Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/setuptools/installer.py", line 75, in fetch_build_egg
    subprocess.check_call(cmd)
  File "/usr/lib/python3.9/subprocess.py", line 373, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['/usr/bin/python3', '-m', 'pip', '--disable-pip-version-check', 'wheel', '--no-deps', '-w', '/tmp/tmpgiv6vp5z', '--quiet', 'cffi>=1.12.0']' returned non-zero exit status 1.

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "/tmp/pip-install-piq91huy/miniaudio_66bfbb489aa14346ae206e61ce26bb24/setup.py", line 20, in <module>
    setup(
  File "/usr/lib/python3.9/site-packages/setuptools/__init__.py", line 152, in setup
    _install_setup_requires(attrs)
  File "/usr/lib/python3.9/site-packages/setuptools/__init__.py", line 147, in _install_setup_requires
    dist.fetch_build_eggs(dist.setup_requires)
  File "/usr/lib/python3.9/site-packages/setuptools/dist.py", line 686, in fetch_build_eggs
    resolved_dists = pkg_resources.working_set.resolve(
  File "/usr/lib/python3.9/site-packages/pkg_resources/__init__.py", line 766, in resolve
    dist = best[req.key] = env.best_match(
  File "/usr/lib/python3.9/site-packages/pkg_resources/__init__.py", line 1051, in best_match
    return self.obtain(req, installer)
  File "/usr/lib/python3.9/site-packages/pkg_resources/__init__.py", line 1063, in obtain
    return installer(requirement)
  File "/usr/lib/python3.9/site-packages/setuptools/dist.py", line 745, in fetch_build_egg
    return fetch_build_egg(self, req)
  File "/usr/lib/python3.9/site-packages/setuptools/installer.py", line 77, in fetch_build_egg
    raise DistutilsError(str(e)) from e
distutils.errors.DistutilsError: Command '['/usr/bin/python3', '-m', 'pip', '--disable-pip-version-check', 'wheel', '--no-deps', '-w', '/tmp/tmpgiv6vp5z', '--quiet', 'cffi>=1.12.0']' returned non-zero exit status 1.
----------------------------------------

WARNING: Discarding https://files.pythonhosted.org/packages/87/e5/7d8fcaba04f8d7d851f0300a4269da03c084beb7e69bde87520b35069068/miniaudio-1.44.tar.gz#sha256=4edd08a9b5a9ceb570a06cda9844f453cf3f0145bb4a19828df8f04ecfdf9993 (from https://pypi.org/simple/miniaudio/). Command errored out with exit status 1: python setup.py egg_info Check the logs for full command output. ERROR: Could not find a version that satisfies the requirement miniaudio>=1.44 (from pyatv) ERROR: No matching distribution found for miniaudio>=1.44 `

[postlund]

Run pip install wheel and try again, should hopefully solve that.

[clipse2004]

Nope now i geht this Error:

RROR: Could not find a version that satisfies the requirement miniaudio>=1.44 (from pyatv) ERROR: No matching distribution found for miniaudio>=1.44

when i try pip3 install miniaudio-1.44

always Same Error :/

[Airey001]

yeah i have the same problem i looked and the errors up and found some comments made by fenec that you can't build if you are using their os/docker setup as they don't have things like gcc and python-dev part of their images. so we might have to manuall install a few extra stuff to get it to manualy build and install

[postlund]

As far as I know, they have their own wheel cache with binaries they build themselves. So assuming everything is set up correctly, Home Assistant shall download and install their binaries (assuming it is available for the platform you are installing on).