search

postlund / pyatv

A client library for Apple TV and AirPlay devices
https://pyatv.dev
MIT License
891 stars 100 forks source link

push updates is broken when seeking media #1934

Open dgrnbrg opened 1 year ago

dgrnbrg commented 1 year ago

Describe the bug

I have discovered that push updates gives incorrect information when seeking media on another source. I have reproduced this on Disney Plus & Netflix. I discovered this initially through the home assistant integration, and then I reproduced it using pyatv on the command line.

Error log

There is no error, it is a silent corruption.

How to reproduce the bug?

Use atvscript --id ... --airplay-credentials ... push_updates in one terminal. Use atvremote --id ... --airplay-credentials ... playing in another terminal.

Start to play a show on Disney Plus. You can see that atvscript shows that playback has begun, and it shows the correct position. You can also run atvremote and see that it shows the correct position.

Next, using the apple TV remote or home assistant integration, seek to a new position. Pause & unpause the show. You can see that atvremote shows the correct & updated position. However, although atvscript will have got push updates for the playing/paused state, it will have the old position plus the duration of playback since seeking.

What is expected behavior?

The pushed updates should register the new position after seeking.

Operating System

macOS & homeassistant haos

Python

3.6

pyatv

0.10.3

Device

Apple TV 4k OS 16.3.1

Additional context

I will investigate more to see if I can identify a line of code to change.

dgrnbrg commented 1 year ago

I think that I have identified that this is due to the MRP state only getting elapsedTime and elapsedTimeTimestamp updated at initialization. They do not get updated with subsequent events.

It seems like they appear in the playbackQueue field of the SET_STATE_MESSAGE, but they do not appear in subsequent messages.

mschwartz commented 1 year ago

I reported this already. It's a bit weirder than you describe.

If I pause a show, say for 5 minutes, the playback position appears to be ahead by 5 minutes. It shouldn't move at all!

Of course, scrubbing screws it all up, too.

My fix has been to monitor deviceState and restart my pyatv program whenever it changes. But it's a hack!

mschwartz commented 1 year ago

https://github.com/postlund/pyatv/issues/1875 - Odd pause/play behavior

postlund commented 1 year ago

I made some changes on master, would be great if you could re-test with that. Otherwise, some logs and time marks (what you did when so I can correlate to the logs) would help a lot!

mschwartz commented 1 year ago

I’m using master.

What are the steps to produce the logs? I assume you want to see them from my program?

postlund commented 1 year ago

I assume you updated to master from a few hours ago (I merged it today)? You can use atvremote -s <ip> --airplay-credentials <creds> --debug push_updates more or less.

mschwartz commented 1 year ago

I’m not seeing the behavior in all apps on the ATV. YouTube has worked as expected, for example. I don’t think many of the others did work. It’s been months since I saw the bug…. My workaround is to exit and restart the pyatv <—> MQTT program when device state changes.

I can remove this code and retry with master and see if it works now. Also, there have been a handful of tvOS updates since my hack.

The thing is, Apple’s Remote app and the built in controls in the operating systems never showed the problem.

mschwartz commented 1 year ago

Reproduced it!

2023-06-15 16:33:51 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=20008edcf89a48ac20b66a598a54198f0cd7427d57c4ad0587ca8b21257e0919d6e3d03ed52460cfadd742ae3d305b307ec4)
  Media type: Video
Device state: Playing
       Title: Alias
       Album: Season 1
    Position: 0/3978s (0.0%)
      Repeat: Off
     Shuffle: Off
--------------------
2023-06-15 16:33:53 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 9 (AirPlay:192.168.100.17)
2023-06-15 16:33:53 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 12\r\nDACP-ID: 98D81FB67E2FDD10\r\nActive-Remote: 2258864119\r\nClient-Instance: 98D81FB67E2FDD10\r\n\r\n'
2023-06-15 16:33:53 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 16:33:53 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 12\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 16:33:53 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 16:33:53 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '12'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 16:33:53 DEBUG [pyatv.core.protocol]: Got heartbeat 9 (AirPlay:192.168.100.17)
2023-06-15 16:33:55 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 10 (AirPlay:192.168.100.17)
2023-06-15 16:33:55 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 13\r\nDACP-ID: 98D81FB67E2FDD10\r\nActive-Remote: 2258864119\r\nClient-Instance: 98D81FB67E2FDD10\r\n\r\n'
2023-06-15 16:33:55 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 16:33:55 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 13\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 16:33:55 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 16:33:55 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '13'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 16:33:55 DEBUG [pyatv.core.protocol]: Got heartbeat 10 (AirPlay:192.168.100.17)
2023-06-15 16:33:57 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 11 (AirPlay:192.168.100.17)
2023-06-15 16:33:57 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 14\r\nDACP-ID: 98D81FB67E2FDD10\r\nActive-Remote: 2258864119\r\nClient-Instance: 98D81FB67E2FDD10\r\n\r\n'
2023-06-15 16:33:57 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 16:33:57 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 14\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 16:33:57 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 16:33:57 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '14'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 16:33:57 DEBUG [pyatv.core.protocol]: Got heartbeat 11 (AirPlay:192.168.100.17)
2023-06-15 16:33:58 DEBUG [pyatv.auth.hap_channel]: Received data (Data=2000cb6a21835ccd693cdb41758f30dfdc8385356e06f2074fa69c849387d5e3d881f5834d90bba14817f797f95f32028d62e900e313a3c51d192eeb15d88e3bc2ef9d73090c184c4d62a81d5834daa33d162319b94e90e0b3e48cc773288376763782c9067a243217b0f5fb7f6077cb3d0d83c7a966dd73cb226df1da67e52f969282ff967758ee280cc8ef6441b29d1bcecb43ec95a942f6bc02ecd80156553ad53be2b364b6bccfde1157b868ead9ef792eba8bbe19723379636a4f0e54500138cb65e9f97e49322f303376a336d0ba0a70f6b0b379e95b82216cfb4b57a5a3aad824e3014b1632ba298006ca6068111161d5f7856367a3c36948a99a4...)
2023-06-15 16:33:58 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: SET_STATE_MESSAGE
[setStateMessage] {
  playbackState: Paused
  playbackQueueCapabilities {
  }
  playerPath {
    origin {
      displayName: "Apple\302\240TV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 267
      bundleIdentifier: "com.apple.TVHomeSharing"
    }
    player {
      identifier: "avkit-28DCC845-56A9-4B8D-9979-3CB0873609FB"
      displayName: "player-1"
      6: 0
    }
  }
  playbackStateTimestamp: 708539638.097361
}
uniqueIdentifier: "5E27A861-5997-4BFE-87B9-FEF1AEAA09CD"
2023-06-15 16:33:58 DEBUG [pyatv.core.protocol]: Dispatching message with type 4 to <bound method PlayerStateManager._handle_set_state of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f607a12a7f0>>
2023-06-15 16:33:58 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=2000efe148eeccd578d3d5b86714354fb19023b415a2571e867e023fd35b1278e0fffeb184c5577ed7d565d7d0d678660aca)
  Media type: Video
Device state: Paused
       Title: Alias
       Album: Season 1
    Position: 0/3978s (0.0%)
      Repeat: Off
     Shuffle: Off
--------------------
2023-06-15 16:33:59 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 12 (AirPlay:192.168.100.17)
2023-06-15 16:33:59 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 15\r\nDACP-ID: 98D81FB67E2FDD10\r\nActive-Remote: 2258864119\r\nClient-Instance: 98D81FB67E2FDD10\r\n\r\n'
2023-06-15 16:33:59 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 16:33:59 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 15\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 16:33:59 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 16:33:59 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '15'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 16:33:59 DEBUG [pyatv.core.protocol]: Got heartbeat 12 (AirPlay:192.168.100.17)
2023-06-15 16:34:01 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 13 (AirPlay:192.168.100.17)
2023-06-15 16:34:01 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 16\r\nDACP-ID: 98D81FB67E2FDD10\r\nActive-Remote: 2258864119\r\nClient-Instance: 98D81FB67E2FDD10\r\n\r\n'
2023-06-15 16:34:01 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 16:34:01 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 16\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 16:34:01 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 16:34:01 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '16'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 16:34:01 DEBUG [pyatv.core.protocol]: Got heartbeat 13 (AirPlay:192.168.100.17)
2023-06-15 16:34:03 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 14 (AirPlay:192.168.100.17)
2023-06-15 16:34:03 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 17\r\nDACP-ID: 98D81FB67E2FDD10\r\nActive-Remote: 2258864119\r\nClient-Instance: 98D81FB67E2FDD10\r\n\r\n'
2023-06-15 16:34:03 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 16:34:03 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 17\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 16:34:03 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 16:34:03 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '17'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 16:34:03 DEBUG [pyatv.core.protocol]: Got heartbeat 14 (AirPlay:192.168.100.17)
2023-06-15 16:34:05 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 15 (AirPlay:192.168.100.17)
2023-06-15 16:34:05 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 18\r\nDACP-ID: 98D81FB67E2FDD10\r\nActive-Remote: 2258864119\r\nClient-Instance: 98D81FB67E2FDD10\r\n\r\n'
2023-06-15 16:34:05 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 16:34:05 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 18\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 16:34:05 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 16:34:05 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '18'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 16:34:05 DEBUG [pyatv.core.protocol]: Got heartbeat 15 (AirPlay:192.168.100.17)
2023-06-15 16:34:07 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 16 (AirPlay:192.168.100.17)
2023-06-15 16:34:07 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 19\r\nDACP-ID: 98D81FB67E2FDD10\r\nActive-Remote: 2258864119\r\nClient-Instance: 98D81FB67E2FDD10\r\n\r\n'
2023-06-15 16:34:07 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 16:34:07 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 19\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 16:34:07 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 16:34:07 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '19'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 16:34:07 DEBUG [pyatv.core.protocol]: Got heartbeat 16 (AirPlay:192.168.100.17)
2023-06-15 16:34:08 DEBUG [pyatv.auth.hap_channel]: Received data (Data=2000d0d61075b2f83eab33b988ad126e42da79646df2990cc0418ba6daaff62b8992f4d9b57a6d48316e8c89b304b6bb3116e90035a4345e0735fb9a3f6593e274c4a135e46d3728a3095bfe451f9dc621d7db12e2d1d87d38bfbf127edba35dde4fea23f1078a434f3776a69ad72481358e394b827ddd8c55c87a8d7df6212bf705dd2aaaba8a98200d037bc0168226f33ace2252187fb5e1365612c29f3109f161b53a67c596dcbb6dc5d4ffde061ac73e72c6155846a409bd71fd107fbba912a90b11b9f184fd41b486575e8135b0d4db0af33d100d68749043f3fd4db85c64592bbcaaa0687fdde0a8668d457860651da3f4ddc6e967bf4caa4035cd2...)
2023-06-15 16:34:08 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: SET_STATE_MESSAGE
[setStateMessage] {
  playbackState: Playing
  playbackQueueCapabilities {
  }
  playerPath {
    origin {
      displayName: "Apple\302\240TV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 267
      bundleIdentifier: "com.apple.TVHomeSharing"
    }
    player {
      identifier: "avkit-28DCC845-56A9-4B8D-9979-3CB0873609FB"
      displayName: "player-1"
      6: 0
    }
  }
  playbackStateTimestamp: 708539647.629708
}
uniqueIdentifier: "ECA29BB5-A13F-4D8D-8994-9D508F1E85DB"
2023-06-15 16:34:08 DEBUG [pyatv.core.protocol]: Dispatching message with type 4 to <bound method PlayerStateManager._handle_set_state of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f607a12a7f0>>
2023-06-15 16:34:08 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=2000f37816330422d66d3e2ed0f10510e8f8c84de0ae83e22246e9210741e474b74ec1b17b1d3e90fd9ceea216dcfd805e6c)
  Media type: Video
Device state: Playing
       Title: Alias
       Album: Season 1
    Position: 16/3978s (0.4%).       <<<<<<<<<<<<<<<<<<<<
      Repeat: Off
     Shuffle: Off
--------------------
2023-06-15 16:34:09 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 17 (AirPlay:192.168.100.17)
2023-06-15 16:34:09 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 20\r\nDACP-ID: 98D81FB67E2FDD10\r\nActive-Remote: 2258864119\r\nClient-Instance: 98D81FB67E2FDD10\r\n\r\n'

If you look at the trace, I started playing the TV show Alias. At position 6 seconds (as shown on the Apple TV), I paused it and counted to 10. Then pushed play. In the trace, it shows position is 16 instead of 6. The Apple TV displays it as 6 seconds, 7 seconds, etc.... as it resumed playing.

I didn't try to scrub the video, but that has been obviously worse than this case. I think the bug is identical, the same cause.

postlund commented 1 year ago

I understand the behavior from this and it matches how it's implemented. Can you include a little bit more of the log from earlier (I need the initial messages for metadata to what you are watching) and also message that comes after. I assume an additional update comes soon after the last one in your log? Or is it the last one seen here?

mschwartz commented 1 year ago

This bit seems wrong, too:

uniqueIdentifier: "5E27A861-5997-4BFE-87B9-FEF1AEAA09CD"
2023-06-15 16:33:58 DEBUG [pyatv.core.protocol]: Dispatching message with type 4 to <bound method PlayerStateManager._handle_set_state of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f607a12a7f0>>
2023-06-15 16:33:58 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=2000efe148eeccd578d3d5b86714354fb19023b415a2571e867e023fd35b1278e0fffeb184c5577ed7d565d7d0d678660aca)
  Media type: Video
Device state: Paused
       Title: Alias
       Album: Season 1
    Position: 0/3978s (0.0%)
      Repeat: Off
     Shuffle: Off

The position shouldn't be 0, it should be 6, right?

mschwartz commented 1 year ago

OK, recapturing a log.

mschwartz commented 1 year ago 
 mschwartz@nuc1  ~  atvremote -s 192.168.100.17 --airplay-credentials 060ebb767e780ddc21e74f56fec233697ff154ace425bb416054f0a60d44a626:7764b0b44b76f6c96f5c6dd00e265107d2d8066055939aa7a3b74da46309af30:32343236343330412d424141362d343346362d383844382d304644383242374539464533:39626231356131392d336631322d343336342d383165322d303834363864383833373534 --debug push_updates

2023-06-15 17:13:48 DEBUG [pyatv.scripts]: Running with pyatv 0.12.1
2023-06-15 17:13:48 DEBUG [pyatv.support.knock]: Knocking at port 3689 on 192.168.100.17
2023-06-15 17:13:48 DEBUG [pyatv.support.knock]: Knocking at port 7000 on 192.168.100.17
2023-06-15 17:13:48 DEBUG [pyatv.support.knock]: Knocking at port 49152 on 192.168.100.17
2023-06-15 17:13:48 DEBUG [pyatv.support.knock]: Knocking at port 32498 on 192.168.100.17
2023-06-15 17:13:48 DEBUG [pyatv.core.scan]: Auto-discovered THEATER at 192.168.100.17:49153 via Protocol.Companion ({'rpmac': '1', 'rphn': 'f0bc9840bf5e', 'rpfl': '0xB67A2', 'rpha': '7b13cbe7d562', 'rpmd': 'AppleTV11,1', 'rpvr': '440.10', 'rpad': '43ddd520a629', 'rphi': '61aa0ac83368', 'rpba': 'EF:B9:9C:93:6A:DC', 'rpmrtid': '2426430A-BAA6-43F6-88D8-0FD82B7E9FE3'})
2023-06-15 17:13:48 DEBUG [pyatv.core.scan]: Auto-discovered THEATER at 192.168.100.17:7000 via Protocol.AirPlay ({'acl': '0', 'btaddr': '00:00:00:00:00:00', 'deviceid': '58:D3:49:EE:6F:D2', 'fex': '1d9/St5/FbwooQQ', 'features': '0x4A7FDFD5,0xBC157FDE', 'flags': '0x18644', 'gid': 'ACE6B766-D297-42F8-87F4-126EB1AD2FC6', 'igl': '1', 'gcgl': '1', 'model': 'AppleTV11,1', 'protovers': '1.1', 'pi': 'f1783640-7115-423e-886a-b61050a7b0c7', 'psi': '2426430A-BAA6-43F6-88D8-0FD82B7E9FE3', 'pk': '14a763c3ed3d09a0ecaa2592f0d9c927160210659010a014dcf38f6a82adf82c', 'srcvers': '690.7.1', 'osvers': '16.5', 'vv': '2'})
2023-06-15 17:13:48 DEBUG [pyatv.core.scan]: Auto-discovered 58D349EE6FD2@THEATER at 192.168.100.17:7000 via Protocol.RAOP ({'cn': '0,1,2,3', 'da': 'true', 'et': '0,3,5', 'ft': '0x4A7FDFD5,0xBC157FDE', 'sf': '0x18644', 'md': '0,1,2', 'am': 'AppleTV11,1', 'pk': '14a763c3ed3d09a0ecaa2592f0d9c927160210659010a014dcf38f6a82adf82c', 'tp': 'UDP', 'vn': '65537', 'vs': '690.7.1', 'ov': '16.5', 'vv': '2'})
2023-06-15 17:13:48 INFO [pyatv.scripts.atvremote]: Auto-discovered THEATER at 192.168.100.17
2023-06-15 17:13:48 DEBUG [pyatv.core.facade]: Adding handler for protocol Protocol.AirPlay
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay]: Remote control channel is supported
2023-06-15 17:13:48 DEBUG [pyatv.core.facade]: Adding handler for protocol Protocol.MRP
2023-06-15 17:13:48 DEBUG [pyatv.protocols.companion]: Not adding Companion as credentials are missing
2023-06-15 17:13:48 DEBUG [pyatv.core.facade]: Adding handler for protocol Protocol.MRP
2023-06-15 17:13:48 DEBUG [pyatv.core.facade]: Adding handler for protocol Protocol.RAOP
2023-06-15 17:13:48 DEBUG [pyatv.core.facade]: Connecting to protocol: Protocol.AirPlay
2023-06-15 17:13:48 DEBUG [pyatv.core.facade]: Connected to protocol: Protocol.AirPlay
2023-06-15 17:13:48 DEBUG [pyatv.core.facade]: Connecting to protocol: Protocol.MRP
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.ap2_session]: Setting up remote connection to 192.168.100.17:7000
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Connected to 192.168.100.17
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.auth]: Setting up new AirPlay Pair-Verify procedure with type AuthenticationType.HAP
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Sending HTTP/1.1 message: b"POST /pair-verify HTTP/1.1\r\nContent-Length: 37\r\nUser-Agent: AirPlay/320.20\r\nConnection: keep-alive\r\nX-Apple-HKP: 3\r\nContent-Type: application/octet-stream\r\n\r\n\x06\x01\x01\x03 )\xc3\x0f\xc0L d:mU?\xf6\xb3\xe0|\xd3\xb3q\xb0\x84\x85X\x1d\xd6\x1a\xe2{\x0eO'5\x11"
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Received: b"HTTP/1.1 200 OK\r\nDate: Thu, 15 Jun 2023 17:13:48 GMT\r\nContent-Length: 159\r\nContent-Type: application/octet-stream\r\nServer: AirTunes/690.7.1\r\n\r\n\x05x\x00\x92g\x1bA\x08\x1eL\xf0n\x98\x7f\x8c\x00\xcf\x15\x00\xc1\xdb\t\x1aHH{\xe7\x11\xf3R!\xc8\xa3X\x1a\xf1\xec\xfe}\xb4\x9e\xd1\xab\x89j\x80h\x9c\xd6\xd1\xc8Ox\xabV\xb1\xdc\xb2\xcb\x93\xeb7\xa2\xc1\x13\x8d\xc3\xa8\xd3\xc9\xda0\xeav\xec\xd5\xd9\xe8\n+P\xda[\x1f\x15\xb6pQ\xd0\xd2L?\xb3\xc8=\xf7rV\xc3$\xde,\xa4A\x07I'\xa5\xf3*y5e\x91K\xcar2\x81\xa0\x99\x9b\x06\x01\x02\x03 \xab\xca\x9d\x9a\x02\x12\x15\x81\xd1\x98(\x16>8\x108\xb0\xdb\x08\xb5\xa9M\x1a\x18K\x83H\x08Ok\x87q"
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Got HTTP response: HttpResponse(protocol='HTTP', version='1.1', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:13:48 GMT', 'Content-Length': '159', 'Content-Type': 'application/octet-stream', 'Server': 'AirTunes/690.7.1'}, body=b"\x05x\x00\x92g\x1bA\x08\x1eL\xf0n\x98\x7f\x8c\x00\xcf\x15\x00\xc1\xdb\t\x1aHH{\xe7\x11\xf3R!\xc8\xa3X\x1a\xf1\xec\xfe}\xb4\x9e\xd1\xab\x89j\x80h\x9c\xd6\xd1\xc8Ox\xabV\xb1\xdc\xb2\xcb\x93\xeb7\xa2\xc1\x13\x8d\xc3\xa8\xd3\xc9\xda0\xeav\xec\xd5\xd9\xe8\n+P\xda[\x1f\x15\xb6pQ\xd0\xd2L?\xb3\xc8=\xf7rV\xc3$\xde,\xa4A\x07I'\xa5\xf3*y5e\x91K\xcar2\x81\xa0\x99\x9b\x06\x01\x02\x03 \xab\xca\x9d\x9a\x02\x12\x15\x81\xd1\x98(\x16>8\x108\xb0\xdb\x08\xb5\xa9M\x1a\x18K\x83H\x08Ok\x87q"):
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.auth.hap]: Device (Encrypted=0092671b41081e4cf06e987f8c00cf1500c1db091a48487be711f35221c8a3581af1ecfe7db49ed1ab896a80689cd6d1c84f78ab56b1dcb2cb93eb37a2c1138dc3a8d3c9da30ea76ecd5d9e80a2b50da5b1f15b67051d0d24c3fb3c83df77256c324de2ca441074927a5f32a793565914bca723281a0999b, Public=060ebb767e780ddc21e74f56fec233697ff154ace425bb416054f0a60d44a626)
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Sending HTTP/1.1 message: b"POST /pair-verify HTTP/1.1\r\nContent-Length: 125\r\nUser-Agent: AirPlay/320.20\r\nConnection: keep-alive\r\nX-Apple-HKP: 3\r\nContent-Type: application/octet-stream\r\n\r\n\x06\x01\x03\x05x\x00\xbdS(P\\\xbb\x83\x8a\xd2{\xf9[\xae#]\xd4,\xf2=\xe4e\xd72i\xb9\xe1\xce\xb4\xa8\x83e\xdb\xb4\x0e\xe6\xff\xd6\x96\x86\xb9\x9a\xe0\xfe|]\x89\xd3V\x19r\xf4\xedD\xd5\x84\xda\x0e(H\xeb.\xf3\xf7\x8d\xce/\x8a\x06\xa5gk\xdd!\x89\xdc\xad\xc7\xdf\x19\xb7[\x7f\x05\xf0\xf5h\xa4\xd3\x19\xd5\xaeR\x1b]0\x1c1'l\xa1T\xec\xa2Wfy\xaa\x88i\x91,s\x00\x95\xc3\x15q\xb2H"
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Received: b'HTTP/1.1 200 OK\r\nDate: Thu, 15 Jun 2023 17:13:48 GMT\r\nContent-Length: 3\r\nContent-Type: application/octet-stream\r\nServer: AirTunes/690.7.1\r\n\r\n\x06\x01\x04'
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Got HTTP response: HttpResponse(protocol='HTTP', version='1.1', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:13:48 GMT', 'Content-Length': '3', 'Content-Type': 'application/octet-stream', 'Server': 'AirTunes/690.7.1'}, body=b'\x06\x01\x04'):
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_srp]: Keys (Input=fd1e43de3a5742466b4ffa7aca6f450c984f93d33d63db065e6516c7455fc777, Output=82fe83b34e3b1a3ce82c6ba620e0df64780578fe2d4840d25520ddc92f130292)
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'SETUP rtsp://192.168.0.40/2714536191 RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nContent-Length: 367\r\nCSeq: 0\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\nContent-Type: application/x-apple-binary-plist\r\n\r\nbplist00\xdb\x01\x02\x03\x04\x05\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f\x10\x11\x12\x13\x14\x15\x16XdeviceID_\x10\x13isRemoteControlOnlyZmacAddressUmodelTname^osBuildVersionVosNameYosVersion[sessionUUID]sourceVersion^timingProtocol_\x10\x11FF:EE:DD:CC:BB:AA\t_\x10\x11AA:BB:CC:DD:EE:FFZiPhone10,6UpyatvU18G82YiPhone OSV14.7.1_\x10$5B850E29-AE2D-437E-A0D2-2CE83B1CEF3CV550.10TNone\x00\x08\x00\x1f\x00(\x00>\x00I\x00O\x00T\x00c\x00j\x00t\x00\x80\x00\x8e\x00\x9d\x00\xb1\x00\xb2\x00\xc6\x00\xd1\x00\xd7\x00\xdd\x00\xe7\x00\xee\x01\x15\x01\x1c\x00\x00\x00\x00\x00\x00\x02\x01\x00\x00\x00\x00\x00\x00\x00\x17\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01!'
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:13:48 GMT\r\nContent-Length: 59\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 0\r\n\r\nbplist00\xd1\x01\x02YeventPort\x11\xc5\x15\x08\x0b\x15\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x18'
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:13:48 GMT', 'Content-Length': '59', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '0'}, body=b'bplist00\xd1\x01\x02YeventPort\x11\xc5\x15\x08\x0b\x15\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x18'):
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_srp]: Keys (Input=06efb2c52d7b2e64e95ef5d4f334994f3f2ff76958b9d6d3829970275afd6dbc, Output=55bc5b26d7d8a4988be026a676bdbf85085e5c5baababf4a683c9781b2843814)
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Connected to 192.168.100.17:50453
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'RECORD rtsp://192.168.0.40/2714536191 RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 1\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:13:48 GMT\r\nContent-Length: 0\r\nAudio-Latency: 0\r\nServer: AirTunes/690.7.1\r\nCSeq: 1\r\n\r\n'
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:13:48 GMT', 'Content-Length': '0', 'Audio-Latency': '0', 'Server': 'AirTunes/690.7.1', 'CSeq': '1'}, body=''):
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'SETUP rtsp://192.168.0.40/2714536191 RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nContent-Length: 298\r\nCSeq: 2\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\nContent-Type: application/x-apple-binary-plist\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa1\x03\xd7\x04\x05\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f\x10\x11YchannelID^clientTypeUUIDZclientUUID[controlTypeTseedTtype_\x10\x14wantsDedicatedSocket_\x10$A4771890-849F-4FBC-9246-2D6026FA9CBB_\x10$1910A70F-DBC0-4242-AF95-115DB30604E1_\x10$0E4675C3-00CF-494F-818A-EBD151F8C119\x10\x02\x134_;t\x89R\xac/\x10\x82\t\x08\x0b\x13\x15$.=HTY^u\x9c\xc3\xea\xec\xf5\xf7\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x12\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xf8'
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Received data (Data=0004fc409cd3e7e294551403c7345286c2d8c0198461e28b71578e2379d96b1f7cf71468f777a3fd82d4144445700b18853505063b5c2d9256267cdd5efdd6887f19e7b5b1f46515ae240a4d3c3ab88b94657b972525896e539151f38900f22e87189894fce3d7651663f56be565fbb4e5619f3881b863595e53edd51ca809ebc5ba0e091f317aa5e284d69e700d57114b2f3bf2868e4fdc6ed36e833a788ca9763678387c173c5e1ca830075f0a47038761f0704320fcb288ad22c3fb955f1f86b66b66abdbc7f68c5e361f6357658fd5dc0dc70b39d8a601bd7ab169e30958db233a8ea2c6566dcae59cee3f8596cc87944b5cdf59846a910f984d90f90...)
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.channels]: Got message on event channel: HttpRequest(method='POST', path='/command', protocol='RTSP', version='1.0', headers={'CSeq': '0', 'Content-Length': '1505', 'Content-Type': 'application/x-apple-binary-plist'}, body=b'bplist00\xd2\x01\x02\x03\x04TtypeUvalueZupdateInfo\xdf\x10\x19\x05\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f\x10\x11\x12\x13\x14\x15\x16\x17\x18\x19\x1a\x1b\x1c\x1d\x1e\x1f &,\'./0123&5678\':;CDEFGSpsiRvv_\x10\x14playbackCapabilities_\x10\x15canRecordScreenStream[statusFlags_\x10\x18keepAliveSendStatsAsBodyTname_\x10\x0fprotocolVersion_\x10\x11volumeControlType]senderAddressXdeviceIDRpi^screenDemoMode]initialVolumeZfeaturesExZtxtAirPlay]sourceVersion_\x10\x16hasUDPMirroringSupportUmodel_\x10\x10supportedFormatsRpkZmacAddress^osBuildVersion_\x10\x15receiverHDRCapabilityXfeatures_\x10$2426430A-BAA6-43F6-88D8-0FD82B7E9FE3\x10\x02\xd5!"#$%&\'\'\'\'_\x10\x12supportsOfflineHLS_\x10\x1dsupportsUIForAudioOnlyContent_\x10\x15supportsInterstitials_\x10\x15supportsFPSSecureStop_\x10!supportsAirPlayVideoWithSharePlay\x08\t\t\t\t\x08\x12\x00\x01\x86D\tWTHEATERS1.1\x10\x04_\x10\x12192.168.0.40:40438_\x10\x1158:D3:49:EE:6F:D2_\x10$f1783640-7115-423e-886a-b61050a7b0c7\x08#\x00\x00\x00\x00\x00\x00\x00\x00_\x10\x0f1d9/St5/FbwooQQO\x11\x01\x87\x05acl=0\x18btaddr=00:00:00:00:00:00\x1adeviceid=58:D3:49:EE:6F:D2\x13fex=1d9/St5/FbwooQQ\x1efeatures=0x4A7FDFD5,0xBC157FDE\rflags=0x18644(gid=ACE6B766-D297-42F8-87F4-126EB1AD2FC6\x05igl=1\x06gcgl=1\x11model=AppleTV11,1\rprotovers=1.1\'pi=f1783640-7115-423e-886a-b61050a7b0c7(psi=2426430A-BAA6-43F6-88D8-0FD82B7E9FE3Cpk=14a763c3ed3d09a0ecaa2592f0d9c927160210659010a014dcf38f6a82adf82c\x0fsrcvers=690.7.1\x0bosvers=16.5\x04vv=2W690.7.1\t[AppleTV11,1\xd4<=>?@AAB_\x10\x15lowLatencyAudioStream\\screenStream[audioStream\\bufferStream\x10\x00\x12\x01D\x08\x00\x137\xc0\x01\x80\x00\xe0\x00\x00O\x10 \x14\xa7c\xc3\xed=\t\xa0\xec\xaa%\x92\xf0\xd9\xc9\'\x16\x02\x10e\x90\x10\xa0\x14\xdc\xf3\x8fj\x82\xad\xf8,_\x10\x1158:D3:49:EE:6F:D2V20L563T4k60\x13\xbc\x15\x7f\xdeJ\x7f\xdf\xd5\x00\x08\x00\r\x00\x12\x00\x18\x00#\x00X\x00\\\x00_\x00v\x00\x8e\x00\x9a\x00\xb5\x00\xba\x00\xcc\x00\xe0\x00\xee\x00\xf7\x00\xfa\x01\t\x01\x17\x01"\x01-\x01;\x01T\x01Z\x01m\x01p\x01{\x01\x8a\x01\xa2\x01\xab\x01\xd2\x01\xd4\x01\xdf\x01\xf4\x02\x14\x02,\x02D\x02h\x02i\x02j\x02k\x02l\x02m\x02n\x02s\x02t\x02|\x02\x80\x02\x82\x02\x97\x02\xab\x02\xd2\x02\xd3\x02\xdc\x02\xee\x04y\x04\x81\x04\x82\x04\x8e\x04\x97\x04\xaf\x04\xbc\x04\xc8\x04\xd5\x04\xd7\x04\xdc\x04\xe5\x05\x08\x05\x1c\x05#\x05(\x00\x00\x00\x00\x00\x00\x02\x01\x00\x00\x00\x00\x00\x00\x00H\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x051')
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=5b0090cb0fd6184d76cb310a39f7b75b3d3ac393e5f4266ab769e271f82198d5eb77ba4178da0f1c1144de95aee53cbb09adb0b18395dd5e0ba6ce71654db30c130cacc08ca492ff6a1df72b8b27d8b247b3edcfc24ba02f4b3e50e0ec9d2f62cebaf375ea2c53a2843d25565c)
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:13:48 GMT\r\nContent-Length: 100\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 2\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa1\x03\xd3\x04\x05\x06\x07\x08\tTtypeXstreamIDXdataPort\x10\x82\x10\x01\x11\xc5\x16\x08\x0b\x13\x15\x1c!*357\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00:'
2023-06-15 17:13:48 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:13:48 GMT', 'Content-Length': '100', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '2'}, body=b'bplist00\xd1\x01\x02Wstreams\xa1\x03\xd3\x04\x05\x06\x07\x08\tTtypeXstreamIDXdataPort\x10\x82\x10\x01\x11\xc5\x16\x08\x0b\x13\x15\x1c!*357\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00:'):
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_srp]: Keys (Input=19d93b12ca9d88ba1646a8426ec3aabba4d7291533c251a0584ec05c501187da, Output=6f40fa2f67735e68e89a59c18d9666c90cb2588ada2770f81430dda212951961)
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Connected to 192.168.100.17:50454
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=3c01d03f636ae28650cb42843fc4c0d3ee8f61e1f31e6ae4826f8a000360ccbb337fe00a1ad583042f5a9652c0697e2cbc840cbe192b23115ef26043c6b19a78f245a5f790cc61c19cac95e523ebd2b613f275b17dcd6996c5c1ac0bb89affb428e9ab07884af24a994aa6c58eb22013654e775682b74a373906d80ded2252326627e0ab589d418a4a1f7593e9b72cc29bbf875c7076d7665b6cb37d76bac68f6a984affac57bf32068769963e98c439065e5f7ce25d4d04f2193af889fa29307ff82df654a1bf2d074d6c21b8d7bf49c042655ac7e110d6a9e32480e47521984a3d552f026296d0b996070404b1aaf928d1251e2450a3f8e5b34449e280a...)
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: >> Send: Protobuf: type: DEVICE_INFO_MESSAGE
identifier: "07262CD1-76CD-428E-A361-78D64B1664AA"
errorCode: NoError
[deviceInfoMessage] {
  uniqueIdentifier: "dc0894a4-4e06-4823-a419-6e207a872efd"
  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
}
uniqueIdentifier: "55ECFA69-907B-4354-A91D-9120BBF992D2"
2023-06-15 17:13:48 DEBUG [pyatv.core.protocol]: Starting heartbeat loop (AirPlay:192.168.100.17)
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Received data (Data=20002e60440d788be2d7d7a8df376dbaf2ceea125a903331b64c974e80f7a494978e1d3c23ad332b79d1de17ac6743e9e7fd2a0047d6c8c7ada1b359a3c9504e9e7b72fb332fe2a9b5233de788dc7cab149763dc3498d79106c5f9e6f06b71c9a35f77d630a24bc10168dbff5ff0)
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Received data (Data=20005e1e730c93efaf9f0a07c4abe2db1eb45cf29699451450bdeea464dea093dd8b607d0ac24eb8a820fdf18f8c29a8e06a5702f8d5e4799b669f992284bd27bd230d2a9b0b7b299cbd0c0c32db511adeab93ba7b72aa4edb6dd600748c7e8b0cf0e6a65f7cd34ce924efd30159b2a3c175fc9fab193eb77b1b3c68c77611515ee45e5ba762d615d4f0232a72e5c58f9da445874b01506e6407901d3cb2a10415e2e4ff04bab2e11b87537293a804f4bde61340f18ef4905938219b96850d770c1dbb1389f8dbce0d4a648dcea5d18ba864880898b47fea250643a1733c48ff190731b69627fd3a63235a9f1c939d06bfa70ca2182c4bbee95c5421d401b...)
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: DEVICE_INFO_MESSAGE
identifier: "07262CD1-76CD-428E-A361-78D64B1664AA"
[deviceInfoMessage] {
  uniqueIdentifier: "2426430A-BAA6-43F6-88D8-0FD82B7E9FE3"
  name: "THEATER"
  localizedModelName: "Apple\302\240TV"
  systemBuildVersion: "20L563"
  applicationBundleIdentifier: "com.apple.mediaremoted"
  protocolVersion: 1
  lastSupportedMessageType: 130
  supportsSystemPairing: true
  allowsPairing: true
  systemMediaApplication: "com.apple.TVMusic"
  supportsACL: true
  supportsSharedQueue: true
  supportsExtendedMotion: true
  sharedQueueVersion: 3
  deviceUID: "2426430A-BAA6-43F6-88D8-0FD82B7E9FE3"
  managedConfigDeviceID: "58:d3:49:ee:6f:d2"
  deviceClass: AppleTV
  logicalDeviceCount: 1
  isProxyGroupPlayer: false
  groupUID: "ACE6B766-D297-42F8-87F4-126EB1AD2FC6"
  isGroupLeader: true
  isAirplayActive: false
  systemPodcastApplication: "com.apple.podcasts"
  senderDefaultGroupUID: "ACE6B766-D297-42F8-87F4-126EB1AD2FC6"
  airplayReceivers: "TVAirPlay"
  clusterType: 0
  isClusterAware: true
  modelID: "AppleTV11,1"
  supportsMultiplayer: false
  routingContextID: "577E1BCA-2D9B-41C2-A8F8-C515CE8072D4"
  airPlayGroupID: "ACE6B766-D297-42F8-87F4-126EB1AD2FC6"
  systemBooksApplication: "com.apple.TVBooks"
  parentGroupContainsDiscoverableGroupLeader: 0
  groupContainsDiscoverableGroupLeader: 1
  lastKnownClusterType: 2
}
uniqueIdentifier: "615F0B5F-309B-4036-97EA-B57EC97DF946"
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=200009a5758157db88e0a5a372a89691598971ffbfa32ffcfc5db26557910ba1bbe15d24293335bccc9551f1c4ed1251eb43)
2023-06-15 17:13:48 DEBUG [pyatv.core.protocol]: Dispatching message with type 15 to <bound method MrpPower._update_power_state of <pyatv.protocols.mrp.MrpPower object at 0x7f4c26a0f910>>
2023-06-15 17:13:48 DEBUG [pyatv.core.protocol]: Dispatching message with type 15 to <bound method MrpAudio._update_output_devices of <pyatv.protocols.mrp.MrpAudio object at 0x7f4c26a0f970>>
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=9300a51a842ebc807eb7b2ad6df38e01597fb73fd1f7a605aeffc0d0d65cdae98604e66b3099af45e126c61ffc656419346286fc6199c7540c55bf827dab0e05770b68abeedc6a1277dea89347fae80293329159ffbeadd56f7d844b4b2b1778ebd02187b2997e9ad46da70098d6c65b07773e7cdaf26610067a2f5bcdb72653ca6288e0170053348fdd0cd43f8faf4c16f46d9baa29b090d120354f321c8680f49ed7a1e4)
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: >> Send: Protobuf: type: SET_CONNECTION_STATE_MESSAGE
errorCode: NoError
[setConnectionStateMessage] {
  state: Connected
}
uniqueIdentifier: "BA2469C0-8977-4504-BEF1-89C8A4A22161"
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=c1000ca449a66918b19372f617b2fb2f24cf30f561fc6a52bbebc000b25b9c90eadb08c8483ef0a4680f58d9e6c3157a3f71d168d34773136f49ff55a4e7932ae87f1a5ca98ada20aee0f086f68b97fc81a13c49a32796f868acc5f0381166533a6acb509e3f1f40a4b01262c9735f54001538d444b1cbca831d91d11eaacb68f786885a5bbd0463bc27838c7ee8619f059e616b74770867d78b44b65feeebf517e2782d09b46276851ded40668d5b62f6cc34af55e643ae01e2c381f185d4c632f1a09ba4e8137d04ce0ef07331d6160c1ad5)
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: >> Send: Protobuf: type: CLIENT_UPDATES_CONFIG_MESSAGE
identifier: "53713229-FA73-4FDC-A81E-5DBD72119070"
errorCode: NoError
[clientUpdatesConfigMessage] {
  artworkUpdates: true
  nowPlayingUpdates: false
  volumeUpdates: true
  keyboardUpdates: true
  outputDeviceUpdates: true
}
uniqueIdentifier: "CC5F7673-1C91-44B5-9728-98154180E94B"
2023-06-15 17:13:48 DEBUG [pyatv.core.protocol]: Dispatching message with type UpdatedState.OutputDevices to <bound method FacadeAudio._output_devices_changed of <pyatv.core.facade.FacadeAudio object at 0x7f4c26a0f130>>
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Received data (Data=2000feeaa2db2a94c1b7011d3248f0c76e249d0532eba8327646c2f31a0e175653b19c4d556e57d215d8a19052f9d21430842a002eb3f20324a36026f637a3231114ce3e81fa95db652dd7304f2fd6228dc0bb3c1fdf49469bb44a93bd6d6253a14178052286db11c1ad7ee498342000287af5307b621e87bbbaf78b7ac554b227df070ed26c35fa4ce11be80e7d6f77163fb16927ce30cd732538774e275b342a006a194cf08e176cd4ec80b120b84c5dbb683a9375aea7e2d362f5cad20fe6cde5c02d8fd90bc17449a2a13cb5fafa6050027bd86426b8e1afae3c)
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Received data (Data=200067782bd55068a0ab592258b066aaa3997c652a978ee1a205ab29a8487e458e36a1c49f5fefa457478f63c988b8a053be)
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.channels]: Not enough data on data channel (has 32, expects 3548)
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Received data (Data=bc0d0353f10b5af1b2ab4c1eae4009c709a8db7950fb9b483e5a0a34e62d69f5b977389ab02c9601d0e0e14ce8864814c9f1e8187286bb2bb4858523b4062a10bbab650fadfc8a3dac57e01709c013af8feacefa85522b166e3bc6fa4fceb01869e18cf5bd33fa1073aff9827ea9b1eb536fca156916105ef654ced37c03b8defa766efa9d969022c44403d5439a2d07efc1b4ff14e84558e52a270daef7204fb96fcc08e68dab381e3a1df8b1168ed9f13d0a39619670141241e0318d7ffba5733550166788cc8912e3f4cfc499d0f00982f1195133bd32acafba3307562a7e63184b4075ad4a5096ef8e228141dc7fc14ed0338c82b1e41e6d845f0f768...)
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: UPDATE_OUTPUT_DEVICE_MESSAGE
[updateOutputDeviceMessage] {
  outputDevices {
    name: "THEATER"
    uniqueIdentifier: "2426430A-BAA6-43F6-88D8-0FD82B7E9FE3"
    canAccessRemoteAssets: false
    isRemoteControllable: false
    isGroupLeader: false
    isGroupable: true
    deviceType: Wired
    deviceSubType: HDMI
    modelSpecificInfoData: "bplist00\324\001\002\003\004\005\006\007\nX$versionY$archiverT$topX$objects\022\000\001\206\240_\020\017NSKeyedArchiver...
    isLocalDevice: false
    supportsExternalScreen: false
    requiresAuthorization: true
    sourceInfo {
      routingContextUID: "577E1BCA-2D9B-41C2-A8F8-C515CE8072D4"
      multipleBuiltInDevices: false
    }
    isDeviceGroupable: true
    canRelayCommunicationChannel: false
    isProxyGroupPlayer: false
    canAccessAppleMusic: false
    canAccessiCloudMusicLibrary: false
    groupContainsGroupLeader: false
    supportsBufferedAirPlay: false
    canPlayEncryptedProgressiveDownloadAssets: true
    canFetchMediaDataFromSender: true
    resentsOptimizedUserInterfaceWhenPlayingFetchedAudioOnlyAssets: true
    isAirPlayReceiverSessionActive: false
    parentGroupContainsDiscoverableLeader: false
    isAddedToHomeKit: false
    supportsHAP: false
    usingJSONProtocol: false
    clusterType: 0
    primaryUID: "2426430A-BAA6-43F6-88D8-0FD82B7E9FE3"
    configuredClusterSize: 0
    producesLowFidelityAudio: false
    45: 0
    47: "AVOutputDeviceBluetoothListeningModeNormal"
    48: 0
    50: 18446744073709551615
    52: 1
    56: 1
    57: 1
    59: 0
    60: 0
    67: 0
  }
  clusterAwareOutputDevices {
    name: "THEATER"
    uniqueIdentifier: "2426430A-BAA6-43F6-88D8-0FD82B7E9FE3"
    canAccessRemoteAssets: false
    isRemoteControllable: false
    isGroupLeader: false
    isGroupable: true
    deviceType: Wired
    deviceSubType: HDMI
    modelSpecificInfoData: "bplist00\324\001\002\003\004\005\006\007\nX$versionY$archiverT$topX$objects\022\000\001\206\240_\020\017NSKeyedArchiver...
    isLocalDevice: false
    supportsExternalScreen: false
    requiresAuthorization: true
    sourceInfo {
      routingContextUID: "577E1BCA-2D9B-41C2-A8F8-C515CE8072D4"
      multipleBuiltInDevices: false
    }
    isDeviceGroupable: true
    canRelayCommunicationChannel: false
    isProxyGroupPlayer: false
    canAccessAppleMusic: false
    canAccessiCloudMusicLibrary: false
    groupContainsGroupLeader: false
    supportsBufferedAirPlay: false
    canPlayEncryptedProgressiveDownloadAssets: true
    canFetchMediaDataFromSender: true
    resentsOptimizedUserInterfaceWhenPlayingFetchedAudioOnlyAssets: true
    isAirPlayReceiverSessionActive: false
    parentGroupContainsDiscoverableLeader: false
    isAddedToHomeKit: false
    supportsHAP: false
    usingJSONProtocol: false
    clusterType: 0
    primaryUID: "2426430A-BAA6-43F6-88D8-0FD82B7E9FE3"
    configuredClusterSize: 0
    producesLowFidelityAudio: false
    45: 0
    47: "AVOutputDeviceBluetoothListeningModeNormal"
    48: 0
    50: 18446744073709551615
    52: 1
    56: 1
    57: 1
    59: 0
    60: 0
    67: 0
  }
}
uniqueIdentifier: "E38CACA2-86F1-41AC-9F29-4845E1DCD483"
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: VOLUME_CONTROL_AVAILABILITY_MESSAGE
[volumeControlAvailabilityMessage] {
  volumeControlAvailable: true
  volumeCapabilities: Relative
}
uniqueIdentifier: "06EEA413-5BAE-4EDC-8052-CE8F85218543"
2023-06-15 17:13:48 DEBUG [pyatv.core.protocol]: Dispatching message with type 17 to <bound method MrpAudio._volume_control_availability of <pyatv.protocols.mrp.MrpAudio object at 0x7f4c26a0f970>>
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: SET_DEFAULT_SUPPORTED_COMMANDS_MESSAGE
[setDefaultSupportedCommandsMessage] {
  supportedCommands {
    supportedCommands {
      command: PreloadedPlaybackSession
      enabled: true
      supportedPlaybackSessionTypes: "com.apple.MediaPlaybackCore.playbackSession-v4.5.opack:subscription:cloudLibrary:7776798"
      supportedPlaybackSessionTypes: "com.apple.MediaPlaybackCore.playbackSession-v4.opack:subscription:cloudLibrary:7776798"
      supportedPlaybackSessionTypes: "com.apple.MediaPlaybackCore.playbackSession-v3.opack:subscription:cloudLibrary:7776798"
    }
    supportedCommands {
      command: SetPlaybackSession
      enabled: true
      supportedPlaybackSessionTypes: "com.apple.MediaPlaybackCore.playbackSession-v4.5.opack:subscription:cloudLibrary:7776798"
      supportedPlaybackSessionTypes: "com.apple.MediaPlaybackCore.playbackSession-v4.opack:subscription:cloudLibrary:7776798"
      supportedPlaybackSessionTypes: "com.apple.MediaPlaybackCore.playbackSession-v3.opack:subscription:cloudLibrary:7776798"
    }
    supportedCommands {
      command: PrepareForSetQueue
      enabled: true
    }
    supportedCommands {
      command: SetPlaybackQueue
      enabled: true
      supportedPlaybackQueueTypes: 7
      supportedPlaybackQueueTypes: 3
      supportedPlaybackQueueTypes: 6
      supportedPlaybackQueueTypes: 2
      supportedPlaybackQueueTypes: 5
      supportedPlaybackQueueTypes: 1
      supportedPlaybackQueueTypes: 8
      supportedCustomQueueIdentifiers: "com.apple.music.playbackqueue.radio"
      supportedCustomQueueIdentifiers: "com.apple.music.playbackqueue.tracklist"
      supportedCustomQueueIdentifiers: "com.apple.MediaPlaybackCore.playbackContextArchive-v1.opack"
      supportedCustomQueueIdentifiers: "com.apple.mediaplayer.playbackcontext"
    }
    supportedCommands {
      command: Play
      enabled: true
    }
  }
  displayID: "com.apple.TVMusic"
  playbackQueueCapabilities {
  }
  playerPath {
    client {
      bundleIdentifier: "com.apple.TVMusic"
    }
  }
}
uniqueIdentifier: "0F49A63B-6CD4-45D8-92C4-202860715E9D"
2023-06-15 17:13:48 DEBUG [pyatv.core.protocol]: Dispatching message with type 72 to <bound method PlayerStateManager._handle_set_default_supported_commands of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f4c26a0f7f0>>
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: SET_DEFAULT_SUPPORTED_COMMANDS_MESSAGE
[setDefaultSupportedCommandsMessage] {
  supportedCommands {
    supportedCommands {
      command: Play
      enabled: true
    }
    supportedCommands {
      command: SetPlaybackQueue
      enabled: true
      supportedPlaybackQueueTypes: 3
      supportedPlaybackQueueTypes: 6
      supportedPlaybackQueueTypes: 2
      supportedPlaybackQueueTypes: 5
      supportedPlaybackQueueTypes: 1
    }
    supportedCommands {
      command: SetPlaybackSession
      enabled: true
      supportedPlaybackSessionTypes: "com.apple.podcasts.MTPlaybackQueueController.GenericQueue"
      currentPlaybackSessionTypes: "com.apple.podcasts.MTPlaybackQueueController.GenericQueue"
    }
  }
  displayID: "com.apple.podcasts"
  playbackQueueCapabilities {
  }
  playerPath {
    client {
      bundleIdentifier: "com.apple.podcasts"
    }
  }
}
uniqueIdentifier: "9DBF63E4-92C6-4E3B-A04E-7EFFDAE6D645"
2023-06-15 17:13:48 DEBUG [pyatv.core.protocol]: Dispatching message with type 72 to <bound method PlayerStateManager._handle_set_default_supported_commands of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f4c26a0f7f0>>
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: ORIGIN_CLIENT_PROPERTIES_MESSAGE
uniqueIdentifier: "79F3DBDE-5FD7-4AFF-80A8-7DE9A34B369F"
[originClientPropertiesMessage] {
  lastPlayingTimestamp: 708541994.300683
}
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: UPDATE_CLIENT_MESSAGE
[updateClientMessage] {
  client {
    processIdentifier: 154
    bundleIdentifier: "com.apple.TVAirPlay"
    processUserIdentifier: 501
    displayName: "AirPlay"
  }
}
uniqueIdentifier: "A57659BD-D960-4631-B44A-4E50A513C2F8"
2023-06-15 17:13:48 DEBUG [pyatv.core.protocol]: Dispatching message with type 55 to <bound method PlayerStateManager._handle_update_client of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f4c26a0f7f0>>
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: SET_STATE_MESSAGE
[setStateMessage] {
  supportedCommands {
    supportedCommands {
      command: Play
      enabled: true
    }
    supportedCommands {
      command: Pause
      enabled: true
    }
    supportedCommands {
      command: TogglePlayPause
      enabled: true
    }
    supportedCommands {
      command: Stop
      enabled: true
    }
    supportedCommands {
      command: NextTrack
      enabled: true
    }
    supportedCommands {
      command: PreviousTrack
      enabled: true
    }
    supportedCommands {
      command: BeginFastForward
      enabled: true
    }
    supportedCommands {
      command: EndFastForward
      enabled: true
    }
    supportedCommands {
      command: BeginRewind
      enabled: true
    }
    supportedCommands {
      command: EndRewind
      enabled: true
    }
    supportedCommands {
      command: AdvanceRepeatMode
      enabled: true
    }
    supportedCommands {
      command: AdvanceShuffleMode
      enabled: true
    }
    supportedCommands {
      command: SeekToPlaybackPosition
      enabled: true
    }
  }
  displayName: "AirPlay"
  playbackState: Paused
  playbackQueueCapabilities {
  }
  playerPath {
    origin {
      displayName: "Apple\302\240TV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 154
      bundleIdentifier: "com.apple.TVAirPlay"
    }
    player {
      identifier: "MediaRemote-DefaultPlayer"
      displayName: "Default Player"
      6: 0
    }
  }
  playbackStateTimestamp: 708306459.396794
}
uniqueIdentifier: "5D977A29-6CEC-4BFD-A1D7-CAEC875D045D"
2023-06-15 17:13:48 DEBUG [pyatv.core.protocol]: Dispatching message with type 4 to <bound method PlayerStateManager._handle_set_state of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f4c26a0f7f0>>
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: PLAYER_CLIENT_PROPERTIES_MESSAGE
uniqueIdentifier: "4D3E8A66-190B-4509-B86D-D77DE1B28C09"
[playerClientPropertiesMessage] {
  playerPath {
    origin {
      displayName: "Apple\302\240TV"
      identifier: 1280262988
      5: 1
    }
    client {
      processIdentifier: 154
      bundleIdentifier: "com.apple.TVAirPlay"
      processUserIdentifier: 501
      displayName: "AirPlay"
    }
    player {
      identifier: "MediaRemote-DefaultPlayer"
      displayName: "Default Player"
      6: 0
    }
  }
  lastPlayingTimestamp: -63114076800.0
}
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: UPDATE_CLIENT_MESSAGE
[updateClientMessage] {
  client {
    processIdentifier: 599
    bundleIdentifier: "com.google.ios.youtube"
    processUserIdentifier: 501
    displayName: "YouTube"
  }
}
uniqueIdentifier: "E3940B13-2B93-4CAD-A591-0DB9D1235D74"
2023-06-15 17:13:48 DEBUG [pyatv.core.protocol]: Dispatching message with type 55 to <bound method PlayerStateManager._handle_update_client of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f4c26a0f7f0>>
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: SET_STATE_MESSAGE
[setStateMessage] {
  supportedCommands {
    supportedCommands {
      command: SeekToPlaybackPosition
      canScrub: 0
    }
    supportedCommands {
      command: SkipBackward
      preferredIntervals: 10.0
    }
    supportedCommands {
      command: SkipForward
      preferredIntervals: 10.0
    }
    supportedCommands {
      command: PreviousTrack
    }
    supportedCommands {
      command: NextTrack
    }
    supportedCommands {
      command: Pause
    }
    supportedCommands {
      command: Play
    }
  }
  displayName: "YouTube"
  playbackState: Paused
  playbackQueueCapabilities {
  }
  playerPath {
    origin {
      displayName: "Apple\302\240TV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 599
      bundleIdentifier: "com.google.ios.youtube"
    }
    player {
      identifier: "MediaRemote-DefaultPlayer"
      displayName: "Default Player"
      6: 0
    }
  }
  playbackStateTimestamp: 708541994.299052
}
uniqueIdentifier: "4776781A-57ED-4B36-8F94-6A98811A723C"
2023-06-15 17:13:48 DEBUG [pyatv.core.protocol]: Dispatching message with type 4 to <bound method PlayerStateManager._handle_set_state of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f4c26a0f7f0>>
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: PLAYER_CLIENT_PROPERTIES_MESSAGE
uniqueIdentifier: "E333FE03-17D5-422E-B975-1138C9181911"
[playerClientPropertiesMessage] {
  playerPath {
    origin {
      displayName: "Apple\302\240TV"
      identifier: 1280262988
      5: 1
    }
    client {
      processIdentifier: 599
      bundleIdentifier: "com.google.ios.youtube"
      processUserIdentifier: 501
      displayName: "YouTube"
    }
    player {
      identifier: "MediaRemote-DefaultPlayer"
      displayName: "Default Player"
      6: 0
    }
  }
  lastPlayingTimestamp: 708541994.299207
}
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: VOLUME_CONTROL_CAPABILITIES_DID_CHANGE_MESSAGE
[volumeControlCapabilitiesDidChangeMessage] {
  capabilities {
    volumeControlAvailable: true
    volumeCapabilities: Relative
  }
  outputDeviceUID: "2426430A-BAA6-43F6-88D8-0FD82B7E9FE3"
}
uniqueIdentifier: "C7E19061-010D-410B-9C51-59C2DE591C50"
2023-06-15 17:13:48 DEBUG [pyatv.core.protocol]: Dispatching message with type 64 to <bound method MrpAudio._volume_control_changed of <pyatv.protocols.mrp.MrpAudio object at 0x7f4c26a0f970>>
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: UNKNOWN_MESSAGE
identifier: "53713229-FA73-4FDC-A81E-5DBD72119070"
uniqueIdentifier: "D2BFBC16-5C70-4461-85E6-D42168D627B7"
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=20002863b1caf752a26a4c3a2b1c4daf017ebb1c7699308b0343c3f56fe7b104dea43a86e8f2d771f998b4e15ca0abec7ea9)
2023-06-15 17:13:48 DEBUG [pyatv.protocols.mrp]: Volume control availability changed to True
2023-06-15 17:13:48 DEBUG [pyatv.protocols.mrp]: Volume control availability changed to True
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=b40014355dbb489a07c236363002427abd11c5570b7d618a7353b926ec15bbbea839e649795072bb145a3a563931ca9ab5bae7476b2dba812bb4bbbc575910bb8e6fd85df099a27202cad3f4eaeba287009801ed4948a51d4aa029d8920f1261fa7f72f9fce166da72711cefa8157348b787fd68fefd2ad0012d2f3ff25fc7631a4e70663bf1060fb98da93a450a04ff61b152a6bd87fe2de5ca3ec70efb6890a7cfdf04571d1f819867baac39be38b189ade3c36103ed24e0fadefb318c0ebc1df95268c371)
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: >> Send: Protobuf: type: GET_KEYBOARD_SESSION_MESSAGE
identifier: "7A5B028F-BA25-4626-8A7C-DDC007984E75"
errorCode: NoError
uniqueIdentifier: "F2C90D60-BFF2-4252-989E-DAFCB98D9382"
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Received data (Data=2000d9899b5afcfbf2f4689bdc19e5b068da8615c30f2ac86d3816eb41463083f281ab5c0a61d0a0723d6e62b9031701941c2a007b389b20a82a88543852b470aefd87eef9c00cd40ce4e9f8c2694699b18fb8dede5bc978246fd8591b840bca9f52445836bb5ce67697e968f805)
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Received data (Data=20001932cf5fb8171ffa20327356ad8b1cfcb3b2ef763b7e0eec204949e3b0fbce29c0e1b5a8d7b0f9cf6371ea59c3c1aebda900f65228a494a366f74b1769f51789c3181728394ec02f564656a238627c3f60e283e2e0000ec50327f3edeee6563f16277bba161bca6994c6adc89e8b306badf7742e6d4090d2cf40fd87034e41b5a2feaa91028eec8cbe78bcc9b5f86fb649ec660dfce46e0fff7afe978c911cb2250266641d8931acc402762d4b7e7f0f0a3d39d6538ad325f109f34b3f38512f67d42761b9217a7a313ee2778662d1ddc4020e55a3e4a1d5db7563313bf397e030d02b94225c8bae48096b)
2023-06-15 17:13:48 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: KEYBOARD_MESSAGE
identifier: "7A5B028F-BA25-4626-8A7C-DDC007984E75"
[keyboardMessage] {
  state: Unknown
  attributes {
    inputTraits {
      autocapitalizationType: None
      keyboardType: Default
      returnKeyType: Default
      enablesReturnKeyAutomatically: false
      secureTextEntry: false
      validTextRangeLocation: 0
      validTextRangeLength: 0
    }
  }
}
uniqueIdentifier: "9FE35575-DB69-4B33-A908-E5179AC6072F"
2023-06-15 17:13:48 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=20007a1b60021a4a089f53863a333104ccb72208932d504f86e43075ab244263d302fc80431b8935799ae7e5034d5d6f0d8a)
2023-06-15 17:13:48 DEBUG [pyatv.core.facade]: Connected to protocol: Protocol.MRP
2023-06-15 17:13:48 DEBUG [pyatv.core.facade]: Protocol Protocol.MRP already set up, ignoring
2023-06-15 17:13:48 DEBUG [pyatv.core.facade]: Connecting to protocol: Protocol.RAOP
2023-06-15 17:13:48 DEBUG [pyatv.core.facade]: Connected to protocol: Protocol.RAOP
Press ENTER to stop
  Media type: Unknown
Device state: Idle
      Repeat: Off
     Shuffle: Off
--------------------
2023-06-15 17:13:50 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 0 (AirPlay:192.168.100.17)
2023-06-15 17:13:50 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 3\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:13:50 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:13:50 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 3\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:13:50 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:13:50 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '3'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:13:50 DEBUG [pyatv.core.protocol]: Got heartbeat 0 (AirPlay:192.168.100.17)
2023-06-15 17:13:52 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 1 (AirPlay:192.168.100.17)
2023-06-15 17:13:52 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 4\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:13:52 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:13:52 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 4\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:13:52 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:13:52 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '4'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:13:52 DEBUG [pyatv.core.protocol]: Got heartbeat 1 (AirPlay:192.168.100.17)
2023-06-15 17:13:54 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 2 (AirPlay:192.168.100.17)
2023-06-15 17:13:54 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 5\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:13:54 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:13:54 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 5\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:13:54 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:13:54 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '5'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:13:54 DEBUG [pyatv.core.protocol]: Got heartbeat 2 (AirPlay:192.168.100.17)
2023-06-15 17:13:55 DEBUG [pyatv.auth.hap_channel]: Received data (Data=2000c51685a487e7fbeba2fdceddfb3aa0d9e6584aa58f9ed71503e2991920728a3dabc190bc65070643bd4deefe05671e7cd200d6dd34413cb0ab0d153e59e1a93cdaaecf98880fb0215f3443cca9099620936b5afe809c57b0a482e9fcda30e1afb9d5a122ee245d62bef4f22185021e21eda268fdaa09e830b20024ae3036bac25fbb340cb41d56d13be82da90c6a5a37a33e3aac668b8d6bd041a7551acd40d8d041aa61bdeec04766aa9fff67c1d839f5ae1db5e936a65ea1e94e5e31f1e71a718a235a761b91cea66164fec38ec5e83241e2cd1cc332bcbfd61e476d09f0191050e1e3430e0e2858be63027da4018580a56bc01a4af67494a96de93...)
2023-06-15 17:13:55 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: SET_NOW_PLAYING_PLAYER_MESSAGE
[setNowPlayingPlayerMessage] {
  playerPath {
    origin {
      displayName: "Apple\302\240TV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 612
      bundleIdentifier: "com.apple.TVHomeSharing"
    }
    player {
      identifier: "MediaRemote-DefaultPlayer"
      displayName: "Default Player"
      6: 0
    }
  }
}
uniqueIdentifier: "FDC35BED-30BF-41D8-A15B-A26CE00FAEAB"
2023-06-15 17:13:55 DEBUG [pyatv.core.protocol]: Dispatching message with type 47 to <bound method PlayerStateManager._handle_set_now_playing_player of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f4c26a0f7f0>>
2023-06-15 17:13:55 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=200023ce79ba37810041c09836806b6a6292ab91c2fbcecc64443b15037b7ce0a29c30587facea6a4027e3b202c7413d1a76)
2023-06-15 17:13:55 DEBUG [pyatv.protocols.mrp.player_state]: Active player is now MediaRemote-DefaultPlayer (Default Player)
2023-06-15 17:13:55 DEBUG [pyatv.auth.hap_channel]: Received data (Data=20008197aa5dfe604dfcdad0a1c4702249cede2a5389204b86c59218c5ac26c4c75db1cef8bbb5f8bcbc2a4dd06f312d4e6a8d00c81ad20f2c1ce433a175d0425e48179e590c3e31fb74ab5cced572d3c6b5a3bfefb6f79f849dbfc0d3273c8f870d19979e5a91d3b5d61d4d1dd319271cd225344d4683e0b732592d267c62e9cc76976e8c5279cba83ff57b1291680c98bb46c35bd5ef7e10cd7b622a1508ae6681b44b8dada54a69121724153cec4baa83205ea41888a4852b8cd088d79dd0ea98f9bc947d76ab4c4dd9408852316014)
2023-06-15 17:13:55 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: SET_NOW_PLAYING_CLIENT_MESSAGE
[setNowPlayingClientMessage] {
  client {
    processIdentifier: 612
    bundleIdentifier: "com.apple.TVHomeSharing"
  }
}
uniqueIdentifier: "325F9DB3-4B09-45FF-88E0-121D8BA6A100"
2023-06-15 17:13:55 DEBUG [pyatv.core.protocol]: Dispatching message with type 46 to <bound method PlayerStateManager._handle_set_now_playing_client of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f4c26a0f7f0>>
2023-06-15 17:13:55 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=2000bf170f72ab568e6644eeced8e044c09f7d9bdbe1c338bd82303ef247d08ba9c3a9ced283a4ac9096479932ef08c1e20b)
2023-06-15 17:13:55 DEBUG [pyatv.protocols.mrp.player_state]: Active client is now com.apple.TVHomeSharing
2023-06-15 17:13:55 DEBUG [pyatv.auth.hap_channel]: Received data (Data=20005003ce565531b18a995de2ccee7973dfb4d4db7e43178d5a13942037953b82aeb836580e9d602b0c0043c509cdac394bde007d9837990ca5de84dedf5dc22060cab7bc54f5ee5d7bfe3a7ba7f83619e6336088a795b9df6083a38dcb3f4550bf057ccf94b775ef945a4a9d9a85946ca8262cff36deda2f242174ab7ea86e2229e1537c9e3ee20240fcf48c9042adc1e75599bd426b34e3a3a972b685f86f41c5d4b6990645329dd0964723b1c5e3e9c1ce111709136c000085a8c418d282f388d615cfc71db0ba3ac1bbe4a4b09668224ad667d8fda0cc5365332b69d4b7641e810fd9c12264bf6968aa19a39ce62b9b2c4849cac774da76e6239782d...)
2023-06-15 17:13:55 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: SET_STATE_MESSAGE
[setStateMessage] {
  playbackState: Paused
  playbackQueueCapabilities {
  }
  playerPath {
    origin {
      displayName: "Apple\302\240TV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 612
      bundleIdentifier: "com.apple.TVHomeSharing"
    }
    player {
      identifier: "MediaRemote-DefaultPlayer"
      displayName: "Default Player"
      6: 0
    }
  }
  playbackStateTimestamp: 708542035.132251
}
uniqueIdentifier: "53BF0A2D-2E27-49AE-B165-179220B906EB"
2023-06-15 17:13:55 DEBUG [pyatv.core.protocol]: Dispatching message with type 4 to <bound method PlayerStateManager._handle_set_state of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f4c26a0f7f0>>
2023-06-15 17:13:55 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=20004b2899a37535d621e5aa5a2722d66a2a18e844ff4e5a6580a31d208a13fbe6e9cafb42020130668a9a58dec61cabe7e1)
2023-06-15 17:13:56 DEBUG [pyatv.auth.hap_channel]: Received data (Data=2000d2ea13c7757f6c0af4cded6252bafaa5a2d0b0c3923081e56088dae4d885604aa4ffa1b721f8e71d13cc34bca65b5999dd006574c11d562e8f6952580839f6a2f6a5366115ae0912ccc49640dd6205e5f9a28048dffe8b58f5c7dce6fa1f34d2e44c6c09455b886f00720331a39d3aca2d6f3e140392bbdca61bd895134484d3d96f5b80b7bb5657ce9c0dd81898fb16c6840b857156c54040e3cad6b267458778c3de620c9f12f0fdca070812711031b1bbc6ab6f3eb793f2d34c72f700b677aef3d1efb6d072b85fa75210092a1ea111b152bd2ded02875250e71b835e8a75d4edb6ee8da955586c971ef7d81b5c45450649453d6ddd9707a60148f...)
2023-06-15 17:13:56 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: SET_NOW_PLAYING_PLAYER_MESSAGE
[setNowPlayingPlayerMessage] {
  playerPath {
    origin {
      displayName: "Apple\302\240TV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 612
      bundleIdentifier: "com.apple.TVHomeSharing"
    }
    player {
      identifier: "avkit-A5FC8EE6-F366-495C-8C1D-15CD529F88E1"
      displayName: "player-1"
      6: 0
    }
  }
}
uniqueIdentifier: "8B38545C-F760-4AEB-A513-6EE1EB140A94"
2023-06-15 17:13:56 DEBUG [pyatv.core.protocol]: Dispatching message with type 47 to <bound method PlayerStateManager._handle_set_now_playing_player of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f4c26a0f7f0>>
2023-06-15 17:13:56 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=2000beb241450e33987227ae894f90bb162e5b9685b5cd3fcb521a3d9bbdc0f7c7ca780a9484154f143101465627f44af074)
2023-06-15 17:13:56 DEBUG [pyatv.protocols.mrp.player_state]: Active player is now avkit-A5FC8EE6-F366-495C-8C1D-15CD529F88E1 (player-1)
2023-06-15 17:13:56 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 3 (AirPlay:192.168.100.17)
2023-06-15 17:13:56 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 6\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:13:56 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:13:56 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 6\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:13:56 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:13:56 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '6'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:13:56 DEBUG [pyatv.core.protocol]: Got heartbeat 3 (AirPlay:192.168.100.17)
2023-06-15 17:13:56 DEBUG [pyatv.auth.hap_channel]: Received data (Data=200003c09e48f654adf4e431f5a6eb633de73dbd8a1da0beb398892e4e73934941b41243e3ab1d7f39585d9bef3d962da6ea110631adab71f5fba2b473f7d64bf213987094c0921885bb5825ecd639a2bb1510aa44bbe092bae19ef8a3cce6b2abe1d75cf3cf9b8556cc0ef2a32f9991a9e12936a2826f29c4d68dc13ffaa264ae8f4632515e6f34d3258431d03c99347ca27358bc57e5f53caf560fa6b6560374f048f8094abec9d2b9556333a6e510f49db850ae5ebf9749e6dc856b4610752b6f0ac2a4a84a094772a49116cbc8cc0b2a336fefaba7703813e2b6281506614f9ccf8fb5bad219b865297bf0b810b98faba1d0b1fa94922a0154f441144...)
2023-06-15 17:13:56 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: UPDATE_PLAYER_MESSAGE
uniqueIdentifier: "9BF8E0B3-F6C6-46B7-96A6-262D82C648E7"
62 {
  1 {
    1 {
      2 {
        8: 6220773742091202672
      }
      3: 1280262988
    }
    2 {
      1: 612
      2: "com.apple.TVHomeSharing"
    }
    3 {
      1: "avkit-A5FC8EE6-F366-495C-8C1D-15CD529F88E1"
      2: "player-1"
      6: 0
    }
  }
}
2023-06-15 17:13:56 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: SET_STATE_MESSAGE
[setStateMessage] {
  supportedCommands {
    supportedCommands {
      command: PreviousInContext
      enabled: true
    }
    supportedCommands {
      command: NextInContext
      enabled: true
    }
    supportedCommands {
      command: DisableLanguageOption
      enabled: true
    }
    supportedCommands {
      command: EnableLanguageOption
      enabled: true
    }
    supportedCommands {
      command: SeekToPlaybackPosition
      enabled: true
      canScrub: 0
    }
    supportedCommands {
      command: ChangePlaybackRate
      enabled: true
      supportedRates: -96.0
      supportedRates: -48.0
      supportedRates: -24.0
      supportedRates: -8.0
      supportedRates: 8.0
      supportedRates: 24.0
      supportedRates: 48.0
      supportedRates: 96.0
    }
    supportedCommands {
      command: SkipBackward
      enabled: true
      preferredIntervals: 10.0
    }
    supportedCommands {
      command: SkipForward
      enabled: true
      preferredIntervals: 10.0
    }
    supportedCommands {
      command: BeginRewind
      enabled: true
    }
    supportedCommands {
      command: EndRewind
      enabled: true
    }
    supportedCommands {
      command: BeginFastForward
      enabled: true
    }
    supportedCommands {
      command: EndFastForward
      enabled: true
    }
    supportedCommands {
      command: Stop
      enabled: true
    }
    supportedCommands {
      command: TogglePlayPause
      enabled: true
    }
    supportedCommands {
      command: Pause
      enabled: true
    }
    supportedCommands {
      command: Play
      enabled: true
    }
  }
  playbackQueue {
    location: 0
    contentItems {
      identifier: "com.apple.avkit.612.d5c481ab"
      metadata {
        title: "The Big Bang Theory"
        albumName: "Season 2"
        duration: 1311.185
        artworkAvailable: true
        infoAvailable: true
        languageOptionsAvailable: true
        numberOfSections: 0
        elapsedTime: -0.097600499
        isAlwaysLive: false
        playbackRate: 1.0
        mediaType: Video
        nowPlayingInfoData: "bplist00\324\001\002\003\004\005\006\007\nX$versionY$archiverT$topX$objects\022\000\001\206\240_\020\017NSKeyedArchive...
        elapsedTimeTimestamp: 708542036.790195
        inferredTimestamp: 708542036.194688
        legacyUniqueIdentifier: -708542037
      }
      availableLanguageOptions {
        allowEmptySelection: false
        languageOptions {
          type: 0
          languageTag: "en-US"
          characteristics: "public.main-program-content"
          displayName: "English (US)"
          identifier: "-en-US-English (US)"
        }
      }
      availableLanguageOptions {
        allowEmptySelection: true
        languageOptions {
          type: 1
          languageTag: "__AUTO__"
        }
        languageOptions {
          type: 1
          languageTag: "en-US"
          characteristics: "public.main-program-content"
          characteristics: "public.accessibility.transcribes-spoken-dialog"
          characteristics: "public.accessibility.describes-music-and-sound"
          displayName: "English (US) CC"
          identifier: "-en-US-English (US) CC"
        }
      }
      currentLanguageOptions {
        type: 0
        languageTag: "en-US"
        characteristics: "public.main-program-content"
        displayName: "English (US)"
        identifier: "-en-US-English (US)"
      }
      currentLanguageOptions {
        type: 1
        languageTag: "__AUTO__"
      }
    }
    requestId: "PlaybackQueueInvalidation-4EFE2ECB-C254-478E-B651-E68FBF4A1F7B"
    resolvedPlayerPath {
      origin {
        displayName: "Apple\302\240TV"
        identifier: 1280262988
        5: 1
      }
      client {
        processIdentifier: 612
        bundleIdentifier: "com.apple.TVHomeSharing"
      }
      player {
        identifier: "avkit-A5FC8EE6-F366-495C-8C1D-15CD529F88E1"
        displayName: "player-1"
        5: 1013
        6: 0
      }
    }
  }
  playbackState: Playing
  playbackQueueCapabilities {
    requestByRange: true
  }
  playerPath {
    origin {
      displayName: "Apple\302\240TV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 612
      bundleIdentifier: "com.apple.TVHomeSharing"
    }
    player {
      identifier: "avkit-A5FC8EE6-F366-495C-8C1D-15CD529F88E1"
      displayName: "player-1"
      6: 0
    }
  }
  playbackStateTimestamp: 708542036.272855
}
uniqueIdentifier: "A777C654-EA63-4820-B896-89FD2D1628C9"
2023-06-15 17:13:56 DEBUG [pyatv.core.protocol]: Dispatching message with type 4 to <bound method PlayerStateManager._handle_set_state of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f4c26a0f7f0>>
2023-06-15 17:13:56 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=200008b1e7b8292d488edc266c3a67d2357f28ed9542a1a0f194c98d113a6e6d796d1ab8db7f028a36236fa52e846aa8ca22)
  Media type: Video
Device state: Playing
       Title: The Big Bang Theory
       Album: Season 2
    Position: 0/1311s (0.0%)
      Repeat: Off
     Shuffle: Off
--------------------
2023-06-15 17:13:58 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 4 (AirPlay:192.168.100.17)
2023-06-15 17:13:58 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 7\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:13:58 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:13:58 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 7\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:13:58 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:13:58 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '7'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:13:58 DEBUG [pyatv.core.protocol]: Got heartbeat 4 (AirPlay:192.168.100.17)
2023-06-15 17:14:00 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 5 (AirPlay:192.168.100.17)
2023-06-15 17:14:00 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 8\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:14:00 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:14:00 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 8\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:14:00 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:14:00 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '8'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:14:00 DEBUG [pyatv.core.protocol]: Got heartbeat 5 (AirPlay:192.168.100.17)
2023-06-15 17:14:02 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 6 (AirPlay:192.168.100.17)
2023-06-15 17:14:02 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 9\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:14:02 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:14:02 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 9\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:14:02 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:14:02 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '9'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:14:02 DEBUG [pyatv.core.protocol]: Got heartbeat 6 (AirPlay:192.168.100.17)
2023-06-15 17:14:04 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 7 (AirPlay:192.168.100.17)
2023-06-15 17:14:04 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 10\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:14:04 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:14:04 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 10\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:14:04 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:14:04 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '10'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:14:04 DEBUG [pyatv.core.protocol]: Got heartbeat 7 (AirPlay:192.168.100.17)
2023-06-15 17:14:04 DEBUG [pyatv.auth.hap_channel]: Received data (Data=2000028e8e5a3764d23d75d507dce08fb2420813f00c2e73634fed29c4729a55e2440da9891c614aac8ad6d4e0f071fa0467e9004552cc9c9fa1a366c7c3c0325f5025819fe7fc990777965b60a6173c0c1c1f1ef4037d51ae8720dea58cbb589e89719759992644b0d35a15f52501e1d9321c9e7fd69a25b3627d2adffb08247012fa7d38b96b19286a8f1679f89ce95b32eff6d240ad2cafcdb474b0f1718e9f5f75f72f48ab383451f8990202c2305b2c96395a1f5ac7fa127ad66d4c70ad5fe431e6cfa1818f3bd726ef516b572dd1e57a6cd825aeb4959f971e506072c2173ee14cd4ddee7437c92d0bb2bf50a75e9e756aed35943123be9b63ecfdc...)
2023-06-15 17:14:04 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: SET_STATE_MESSAGE
[setStateMessage] {
  playbackState: Paused
  playbackQueueCapabilities {
  }
  playerPath {
    origin {
      displayName: "Apple\302\240TV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 612
      bundleIdentifier: "com.apple.TVHomeSharing"
    }
    player {
      identifier: "avkit-A5FC8EE6-F366-495C-8C1D-15CD529F88E1"
      displayName: "player-1"
      6: 0
    }
  }
  playbackStateTimestamp: 708542043.593797
}
uniqueIdentifier: "EE7ADBC8-8E4B-4465-99D8-244A1F4CDABC"
2023-06-15 17:14:04 DEBUG [pyatv.core.protocol]: Dispatching message with type 4 to <bound method PlayerStateManager._handle_set_state of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f4c26a0f7f0>>
2023-06-15 17:14:04 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=200092457316e679ca0356bb361b9a3d165ab444182632b00cfea9cd5853390e6bbbc0a58a56ad741992825019c47c54b963)
  Media type: Video
Device state: Paused
       Title: The Big Bang Theory
       Album: Season 2
    Position: 0/1311s (0.0%)
      Repeat: Off
     Shuffle: Off
--------------------
2023-06-15 17:14:06 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 8 (AirPlay:192.168.100.17)
2023-06-15 17:14:06 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 11\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:14:06 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:14:06 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 11\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:14:06 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:14:06 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '11'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:14:06 DEBUG [pyatv.core.protocol]: Got heartbeat 8 (AirPlay:192.168.100.17)
2023-06-15 17:14:08 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 9 (AirPlay:192.168.100.17)
2023-06-15 17:14:08 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 12\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:14:08 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:14:08 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 12\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:14:08 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:14:08 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '12'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:14:08 DEBUG [pyatv.core.protocol]: Got heartbeat 9 (AirPlay:192.168.100.17)
2023-06-15 17:14:10 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 10 (AirPlay:192.168.100.17)
2023-06-15 17:14:10 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 13\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:14:10 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:14:10 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 13\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:14:10 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:14:10 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '13'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:14:10 DEBUG [pyatv.core.protocol]: Got heartbeat 10 (AirPlay:192.168.100.17)
2023-06-15 17:14:12 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 11 (AirPlay:192.168.100.17)
2023-06-15 17:14:12 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 14\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:14:12 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:14:12 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 14\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:14:12 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:14:12 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '14'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:14:12 DEBUG [pyatv.core.protocol]: Got heartbeat 11 (AirPlay:192.168.100.17)
2023-06-15 17:14:13 DEBUG [pyatv.auth.hap_channel]: Received data (Data=2000f39fecebb750d4144d4b44e24f4bbccda3f518e557dde788fed52132831def5edac969427a96f65bd311bee22d75dcd9e9004c23f9e349338f1765d7278560f3327ce31944ea82f591c990e475b8037c35dfb8f06756cbf036d27e6d9ab0682cf62ccc8e260d8f853b3a76bf6c5c69fe283794b70a2d2fc57ccba8c0b37a2f8360210940693159c102894f1b98a9ff73c10422d674b07f7560d947e1920b55118a014d0af0e45b4428d4bf9a5c18af4787e426a58afb85885e85f124b76859ae670fff950ecc92220f7f9e915c796f5caa46a69a01e7ebd18feff85d58e0360e7e6d6925a8ec434bb58c9806738c95989c3f6e6cf52692118f95ba7bf...)
2023-06-15 17:14:13 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: SET_STATE_MESSAGE
[setStateMessage] {
  playbackState: Playing
  playbackQueueCapabilities {
  }
  playerPath {
    origin {
      displayName: "Apple\302\240TV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 612
      bundleIdentifier: "com.apple.TVHomeSharing"
    }
    player {
      identifier: "avkit-A5FC8EE6-F366-495C-8C1D-15CD529F88E1"
      displayName: "player-1"
      6: 0
    }
  }
  playbackStateTimestamp: 708542052.281206
}
uniqueIdentifier: "94156FA3-DB1D-413F-B2F0-C4DD3059C84E"
2023-06-15 17:14:13 DEBUG [pyatv.core.protocol]: Dispatching message with type 4 to <bound method PlayerStateManager._handle_set_state of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f4c26a0f7f0>>
2023-06-15 17:14:13 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=2000a6895d698b476051f92b5115bcf4874d6745bb39df1b37eb3c4848b39bb0b5170494950da760728663beeaaab7eb2cb9)
  Media type: Video
Device state: Playing
       Title: The Big Bang Theory
       Album: Season 2
    Position: 16/1311s (1.2%)
      Repeat: Off
     Shuffle: Off
--------------------
2023-06-15 17:14:14 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 12 (AirPlay:192.168.100.17)
2023-06-15 17:14:14 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 15\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:14:14 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:14:14 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 15\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:14:14 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:14:14 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '15'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:14:14 DEBUG [pyatv.core.protocol]: Got heartbeat 12 (AirPlay:192.168.100.17)
2023-06-15 17:14:16 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 13 (AirPlay:192.168.100.17)
2023-06-15 17:14:16 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 16\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:14:16 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:14:16 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 16\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:14:16 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:14:16 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '16'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:14:16 DEBUG [pyatv.core.protocol]: Got heartbeat 13 (AirPlay:192.168.100.17)
2023-06-15 17:14:17 DEBUG [pyatv.auth.hap_channel]: Received data (Data=2000d468a74a1527ee144835469119609e6e58b2941dfcf57f6ddc49389c627d22f006ecc1cf9943a5f95e8ffc76b75e43e5e900f61eb02c2a7929fbc690b756556621d8c579a55acfb99800ebcc27d25d70dec5c68f843251a2f8a4b7687e1c631109f92a73015ef0fb51b988ab82e912cce9f6b0a4d30a3168af830fbfa817cebd5f1b67f9d1c7c2da5a6ba91eaf590e62720a779c88883b846d5c4305012b060da28199325ceb1a496e58874f9539000c6745a01aaa2cc5ea2cd8e268234a737ae2b4e03f47746345cca07330bf275a1264b657fd6578b1bc25a90a831e2da0a78cb272a411f221fb41134fd800e11be4fa385a68e8ef2403849a44f7c...)
2023-06-15 17:14:17 DEBUG [pyatv.protocols.airplay.mrp_connection]: << Receive: Protobuf: type: SET_STATE_MESSAGE
[setStateMessage] {
  playbackState: Paused
  playbackQueueCapabilities {
  }
  playerPath {
    origin {
      displayName: "Apple\302\240TV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 612
      bundleIdentifier: "com.apple.TVHomeSharing"
    }
    player {
      identifier: "avkit-A5FC8EE6-F366-495C-8C1D-15CD529F88E1"
      displayName: "player-1"
      6: 0
    }
  }
  playbackStateTimestamp: 708542056.843543
}
uniqueIdentifier: "E3BF8ACB-BBA7-4F85-B0F1-299DD50DD16A"
2023-06-15 17:14:17 DEBUG [pyatv.core.protocol]: Dispatching message with type 4 to <bound method PlayerStateManager._handle_set_state of <pyatv.protocols.mrp.player_state.PlayerStateManager object at 0x7f4c26a0f7f0>>
2023-06-15 17:14:17 DEBUG [pyatv.auth.hap_channel]: Sending data (Encrypted=2000a4d878a5a3b954d45656f2ec5922cdbdbbe9f299e84ca7dffa418665ed7ca1e81ac9ddc1204edb7c91e897d33ed34ebd)
  Media type: Video
Device state: Paused
       Title: The Big Bang Theory
       Album: Season 2
    Position: 0/1311s (0.0%)
      Repeat: Off
     Shuffle: Off
--------------------
2023-06-15 17:14:18 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 14 (AirPlay:192.168.100.17)
2023-06-15 17:14:18 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 17\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:14:18 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:14:18 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 17\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:14:18 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:14:18 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '17'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:14:18 DEBUG [pyatv.core.protocol]: Got heartbeat 14 (AirPlay:192.168.100.17)
2023-06-15 17:14:20 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 15 (AirPlay:192.168.100.17)
2023-06-15 17:14:20 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'POST /feedback RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 18\r\nDACP-ID: 71FAFE32F242BACE\r\nActive-Remote: 1459133526\r\nClient-Instance: 71FAFE32F242BACE\r\n\r\n'
2023-06-15 17:14:20 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 15 Jun 2023 17:14:20 GMT\r\nContent-Length: 55\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/690.7.1\r\nCSeq: 18\r\n\r\nbplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'
2023-06-15 17:14:20 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Thu, 15 Jun 2023 17:14:20 GMT', 'Content-Length': '55', 'Content-Type': 'application/x-apple-binary-plist', 'Server': 'AirTunes/690.7.1', 'CSeq': '18'}, body=b'bplist00\xd1\x01\x02Wstreams\xa0\x08\x0b\x13\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x14'):
2023-06-15 17:14:20 DEBUG [pyatv.core.protocol]: Got heartbeat 15 (AirPlay:192.168.100.17)
2023-06-15 17:14:22 DEBUG [pyatv.core.protocol]: Sending periodic heartbeat 16 (AirPlay:192.168.100.17)
mschwartz commented 1 year ago

This is the entire log.

I did basically the same steps. I let it play until 6 seconds. Then pause. Then count to 10. Then play.

What I'm seeing in the log is that at pause time, it shows position at 0 instead of at 6. And when it resumes playing, position is at 16 instead of 6 - off by the 10 seconds I counted while paused.

mschwartz commented 1 year ago

I don't see this behavior when playing YouTube videos. This is playing a TV Show I paid for and downloaded to my Mac and am watching via the Computers App on the ATV. Streaming my library from the disk on the Mac to the ATV.

postlund commented 1 year ago

Interesting. I think it must have to do with playbackStateTimestamp somehow, but I'm not entirely sure yet. What I can see is this:

Initial SET_STATE: 708542036.272855
"Pause" SET_STATE: 708542043.593797
"Play" SET_STATE:  708542043.593797

Difference between initial and pause is ~7.3s and it's exactly the same timestamp when going from paused to play. You mentioned you waited 6s before pressing pause, could 7.3s correct?

mschwartz commented 1 year ago

I t was ~6 seconds in. It may have taken a second to actually pause. Sure…

mschwartz commented 1 year ago

You have no way to reproduce this?

mschwartz commented 1 year ago

FWIW, this control doesn’t have a problem with incorrect position..

image
postlund commented 1 year ago

I can't seem to get my home sharing to work unfortunately, no.

The bug is on my end, it has more to do with me not understanding how this works than anything else tbh.

mschwartz commented 1 year ago

I’m ok with my hack for now. Hopefully it will come to you, what the bug is.

I really do appreciate your efforts and the software!

mschwartz commented 11 months ago

@postlund new problem, related.

I'm seeing playback position at 0 for the first ~30 to 60 seconds of playback, and then it starts. The playback position stays about that amount of time behind. That is, if I "up" on the remote, I see 5:00, but I'm seeing 4:00 as position from pyatv. This is new, I think, with the latest tvOS update. Version 17.2.

I have 2 Apple TVs. One is previous generation (64G) and one is the generation before that (32G). There seems to be some discrepancy in the behavior of the two, at least before 17.2.

For example, on the 32G model, I see position not updating until I quickly hit pause/play on the remote.

I'm using master branch.

mschwartz commented 11 months ago

Additionally, when using the Spectrum app to watch live TV, the position is not moving where it used to before the update. This may be a bug in the Spectrum App, but it seems related with the whole position issues.

mschwartz commented 10 months ago

@postlund I am quite sure the problem seems to be with Linux hosted containers or even running outside of containers.

What I am seeing is for the first 1:30 or so of playing anything - youtube, TV+, etc., I am seeing position in playing set to 0. At the 1:30 mark, position starts counting from 1, 2, 3... When I pause the video, the position jumps to the correct position. When I continue playing, it goes back to ~1:30 behind again.

I see this with atvscript, too.

If I run atvscript with watch -n 1 atvscript -s myhost --all-the-credentials playing I see the time off by the 1:30 and stays at 0 for the first 1:30.

If I run the watch command on linux, it's bad. If I run it on macos, it works correctly. If I run it in a docker container on macos, it is bad again. This is because docker containers run in a Linux VM on MacOS.

I've tried both master and the latest released tag. --net=host is required or it won't connect to the apple tvs.

Any feedback or trick to fix this?

mschwartz commented 9 months ago

FYI, I came up with a hack-ish fix that mostly works.

In my server code, I keep a "last_position" variable. When the device state goes "paused", the last_position is set - the position value retrieved via the API when the device is paused is correct (the only time it is). Since I am polling 1/sec, I just update the last_position and send that to my clients. It's the value I want, 99% of the time. It does get out of sync some of the time (like when YouTube automatically moves to the next video it never goes into paused state). The way to sync it up is to hit pause on my remote.

In case someone else has a need for this kind of fix.

dgrnbrg commented 9 months ago

I would love to see this propagate through here to home assistant; it’d be really valuable there! On Feb 1, 2024 at 1:10 PM -0500, Michael Schwartz @.***>, wrote:

FYI, I came up with a hack-ish fix that mostly works. In my server code, I keep a "last_position" variable. When the device state goes "paused", the last_position is set - the position value retrieved via the API when the device is paused is correct (the only time it is). Since I am polling 1/sec, I just update the last_position and send that to my clients. It's the value I want, 99% of the time. It does get out of sync some of the time (like when YouTube automatically moves to the next video it never goes into paused state). The way to sync it up is to hit pause on my remote. In case someone else has a need for this kind of fix. — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you authored the thread.Message ID: @.***>

mschwartz commented 9 months ago

I think this started with recent tvOS updates. My code was working fine before, and hasn’t changed in months.

The Apple Remote apps and built in controls (to iPad and iPhone) do work.

I’m not sure what’s specifically changed. I don’t see any pattern to how far off position gets - it’s not consistent. I haven’t looked at pyatv sources to see if he handles positions differently when paused or playing.

The protocols are reverse engineered and maybe pyatv isn’t doing the right thing 100% of the time. Maybe Apple had a bug they fixed…