search

postlund / pyatv

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

TimeoutError: no response to CSeq 0 #1576

Open malosaa opened 2 years ago

malosaa commented 2 years ago

Describe the bug

Using home assistant last version. 2021.12.7

Well when i go to the device and test the tts, i get this error. I don't even know why

regards

Error log

Logger: homeassistant.components.websocket_api.http.connection
Source: custom_components/apple_tv/media_player.py:286
Integration: Home Assistant WebSocket API (documentation, issues)
First occurred: 12:15:12 (3 occurrences)
Last logged: 12:20:15

[140632704872848] no response to CSeq 0 (/info)
[140632215484160] no response to CSeq 0 (/info)
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/locks.py", line 226, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 492, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/rtsp.py", line 281, in exchange
    await asyncio.wait_for(self.requests[cseq][0].wait(), 4)
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 494, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

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

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 185, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1530, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/components/tts/__init__.py", line 200, in async_say_handle
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1530, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 209, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 663, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 896, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 700, in _handle_entity_call
    await result
  File "/config/custom_components/apple_tv/media_player.py", line 286, in async_play_media
    await self.atv.stream.stream_file(media_id)
  File "/usr/local/lib/python3.9/site-packages/pyatv/core/facade.py", line 382, in stream_file
    await self.relay("stream_file")(file, **kwargs)
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/raop/__init__.py", line 331, in stream_file
    await client.initialize(self.service.properties)
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/raop/raop.py", line 450, in initialize
    self._info.update(await self.rtsp.info())
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/rtsp.py", line 98, in info
    device_info = await self.exchange("GET", "/info", allow_error=True)
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/rtsp.py", line 284, in exchange
    raise TimeoutError(
TimeoutError: no response to CSeq 0 (/info)

How to reproduce the bug?

I don't know

What is expected behavior?

It should normally work.

Operating System

HASS OS 7.0

Python

Other

pyatv

0.9.8 v2.2.0 in hass

Device

Apple tv aircast device 3.0

Additional context

no

postlund commented 2 years ago

Hate you tried removing and adding the device again? What do you mean by "Apple tv aircast device 3.0" by the way? What kind of device is that?

malosaa commented 2 years ago

Hate you tried removing and adding the device again? What do you mean by "Apple tv aircast device 3.0" by the way? What kind of device is that?

Its an aircast device, it supports apple airplay. i used all the time with homeseer. There was an same plugin like this one.

Yes i did remove and re-add it still that issue..

malosaa commented 2 years ago

image

image

type of the device ez-cast

postlund commented 2 years ago

That is certainly an issue at least. Would be great if you would set up an environment so you can run and make changes to pyatv, I think we need to debug it from there. I'm not sure what OS you are running on your desktop? You will need python and git so you can clone the code. Then it's one of these:

https://pyatv.dev/internals/#setting-up-a-new-environment

The output of running atvremote --debug scan is of big interest. Then you should be able to stream a file like this:

atvremote --debug -s <ip of device> stream_file=https://file-examples-com.github.io/uploads/2017/11/file_example_MP3_1MG.mp3

Hopefully this should reproduce the error you get. At this stage we can start modifying the code a bit to see what happens.

When you used homeseer, did you have to perform any pairing or did it just work out-of-the-box?

malosaa commented 2 years ago

Well the OS im running is windows 10 But home assistant is running from virtualbox using HASS OS 7.0 When i did use Home-Seer there was an plug-in From Spud, when i started it it detected the device, just like your script. and then i could use my tts installed on my windows to talk to the device. It did discover and i could directly use it.

pyatv does discover it, but the pairing failed, but says it does ignore it. I don't know how to debug in home assistant running from virtualbox

ill try to create an environment on windows 10 now

That is certainly an issue at least. Would be great if you would set up an environment so you can run and make changes to pyatv, I think we need to debug it from there. I'm not sure what OS you are running on your desktop? You will need python and git so you can clone the code. Then it's one of these:

https://pyatv.dev/internals/#setting-up-a-new-environment

The output of running atvremote --debug scan is of big interest. Then you should be able to stream a file like this:

atvremote --debug -s <ip of device> stream_file=https://file-examples-com.github.io/uploads/2017/11/file_example_MP3_1MG.mp3

Hopefully this should reproduce the error you get. At this stage we can start modifying the code a bit to see what happens.

When you used homeseer, did you have to perform any pairing or did it just work out-of-the-box?

malosaa commented 2 years ago

@postlund

here the output.

$ atvremote --debug -s 192.168.1.15 stream_file=https://file-examples-com.github.io/uploads/2017/11/file_example_MP3_1MG
.mp3
2022-01-02 16:39:02 DEBUG [pyatv.scripts]: Running with pyatv 0.9.8
2022-01-02 16:39:02 DEBUG [pyatv.support.knock]: Knocking at port 3689 on 192.168.1.15
2022-01-02 16:39:02 DEBUG [pyatv.support.knock]: Knocking at port 7000 on 192.168.1.15
2022-01-02 16:39:02 DEBUG [pyatv.support.knock]: Knocking at port 49152 on 192.168.1.15
2022-01-02 16:39:02 DEBUG [pyatv.support.knock]: Knocking at port 32498 on 192.168.1.15
2022-01-02 16:39:03 DEBUG [pyatv.core.scan]: Auto-discovered LivingroomSpeaker at 192.168.1.15:7000 via Protocol.AirPlay ({'deviceid': '56:E4:BD:D2:18:D3', 'features': '0x0A7FCE40', 'flags': '0x4', 'rmodel': 'EZAir1,1', 'model': 'AppleTV3,2', 'srcvers': '220.68', 'vv': '2', 'pk': '978bb5a35fa53037ff73b7b25994614a3c19896152031221ce2a91b2eed8be9a', 'pi': 'b08f5a79-db29-4384-b456-a4784d9e6055'})
2022-01-02 16:39:03 DEBUG [pyatv.core.scan]: Auto-discovered 56E4BDD218D3@LivingroomSpeaker at 192.168.1.15:47000 via Protocol.RAOP ({'cn': '0,1,3', 'da': 'true', 'et': '0,3,5', 'ft': '0x0A7FCE40', 'md': '0,1,2', 'tp': 'UDP', 'vn': '65537', 'vs': '220.68', 'rmodel': 'EZAir1,1', 'am': 'AppleTV3,2', 'vv': '2', 'sf': '0x4', 'pk': '978bb5a35fa53037ff73b7b25994614a3c19896152031221ce2a91b2eed8be9a'})
2022-01-02 16:39:03 INFO [pyatv.scripts.atvremote]: Auto-discovered LivingroomSpeaker at 192.168.1.15
2022-01-02 16:39:03 DEBUG [pyatv.core.facade]: Adding handler for protocol Protocol.AirPlay
2022-01-02 16:39:03 DEBUG [pyatv.protocols.airplay]: Remote control not supported by device
2022-01-02 16:39:03 DEBUG [pyatv.core.facade]: Adding handler for protocol Protocol.RAOP
2022-01-02 16:39:03 DEBUG [pyatv.core.facade]: Connecting to protocol: Protocol.AirPlay
2022-01-02 16:39:03 DEBUG [pyatv.core.facade]: Connected to protocol: Protocol.AirPlay
2022-01-02 16:39:03 DEBUG [pyatv.core.facade]: Connecting to protocol: Protocol.RAOP
2022-01-02 16:39:03 DEBUG [pyatv.core.facade]: Connected to protocol: Protocol.RAOP
2022-01-02 16:39:03 DEBUG [pyatv.core.facade]: Power management not supported by any protocols
2022-01-02 16:39:03 DEBUG [pyatv.core.facade]: Takeover (<class 'pyatv.interface.Audio'>, <class 'pyatv.interface.Metadata'>, <class 'pyatv.interface.PushUpdater'>, <class 'pyatv.interface.RemoteControl'>) by Protocol.RAOP
2022-01-02 16:39:03 DEBUG [pyatv.support.http]: Connected to 192.168.1.15
2022-01-02 16:39:03 DEBUG [pyatv.protocols.raop.raop]: Initializing RTSP with encryption=EncryptionType.FairPlaySAPv25|FairPlay|Unencrypted, metadata=MetadataType.Progress|Artwork|Text
2022-01-02 16:39:03 DEBUG [pyatv.protocols.raop.raop]: Update play settings to 44100/2/16bit
2022-01-02 16:39:03 DEBUG [pyatv.protocols.raop.raop]: Local ports: control=59902, timing=59903
2022-01-02 16:39:03 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'GET /info RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 0\r\nDACP-ID: CED899DA8AD3EA7E\r\nActive-Remote: 524954479\r\nClient-Instance: CED899DA8AD3EA7E\r\n\r\n'
2022-01-02 16:39:03 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 01 Jan 1970 00:03:26 +0000\r\nContent-Length: 819\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/220.68\r\n\r\n'
2022-01-02 16:39:03 DEBUG [pyatv.support.http]: Not enough data to decode message
2022-01-02 16:39:03 DEBUG [pyatv.support.http]: Received: b'bplist00\xdf\x10\x0f\x01\x03\x05\x07\t\x0b\x0c\x0e\x10\x12\x13\x15\x1f(*\x02\x04\x06\x08\n\n\r\x0f\x11\x11\x14\x16 )+RpkO\x10 \x97\x8b\xb5\xa3_\xa507\xffs\xb7\xb2Y\x94aJ<\x19\x89aR\x03\x12!\xce*\x91\xb2\xee\xd8\xbe\x9a\xa0TnameXApple TVRvv\x10\x02[statusFlags\x10\x04_\x10\x11keepAliveLowPower\x10\x01_\x10\x18keepAliveSendStatsAsBodyRpi_\x10$b08f5a79-db29-4384-b456-a4784d9e6055]sourceVersionV220.68XdeviceID_\x10\x1156:E4:BD:D2:18:D3ZmacAddressUmodelZAppleTV3,2\\audioFormats\xa2\x17\x1d\xd3\x18\x1a\x1b\x19\x19\x1c_\x10\x11audioInputFormats\x12\x03\xff\xff\xfc_\x10\x12audioOutputFormatsTtype\x10d\xd3\x18\x1a\x1b\x19\x19\x1e\x10e^audioLatencies\xa2!\'\xd4"$&\x1b#%%\x1cYaudioTypeWdefault_\x10\x12inputLatencyMicros\x08_\x10\x13outputLatencyMicros\xd4"$&\x1b#%%\x1eXfeatures\x12\n\x7f\xce@Xdisplays\xa1,\xdb-/123456(9:.0%%%0.78%;Vheight\x11\x02\xd0Uwidth\x11\x05\x00Xrotation]widthPhysical^heightPhysical[widthPixels\\heightPixels[refreshRate\x10\x1e\x10\x0e[overscannedTuuid_\x10$436b945b-14fe-40e5-80ef-6332f8f05c57\x00\x08\x00)\x00,\x00P\x00U\x00^\x00a\x00c\x00o\x00q\x00\x85\x00\x87\x00\xa2\x00\xa5\x00\xcc\x00\xda\x00\xe1\x00\xea\x00\xfe\x01\t\x01\x0f\x01\x1a\x01\'\x01*\x011\x01E\x01J\x01_\x01d\x01f\x01m\x01o\x01~\x01\x81\x01\x8a\x01\x94\x01\x9c\x01\xb1\x01\xb2\x01\xc8\x01\xd1\x01\xda\x01\xdf\x01\xe8\x01\xea\x02\x01\x02\x08\x02\x0b\x02\x11\x02\x14\x02\x1d\x02+\x02:\x02F\x02S\x02_\x02a\x02c\x02o\x02t\x00\x00\x00\x00\x00\x00\x02\x01\x00\x00\x00\x00\x00\x00\x00<\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x02\x9b'
2022-01-02 16:39:03 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Thu, 01 Jan 1970 00:03:26 +0000', 'content-length': '819', 'content-type': 'application/x-apple-binary-plist', 'server': 'AirTunes/220.68'}, body=b'bplist00\xdf\x10\x0f\x01\x03\x05\x07\t\x0b\x0c\x0e\x10\x12\x13\x15\x1f(*\x02\x04\x06\x08\n\n\r\x0f\x11\x11\x14\x16 )+RpkO\x10 \x97\x8b\xb5\xa3_\xa507\xffs\xb7\xb2Y\x94aJ<\x19\x89aR\x03\x12!\xce*\x91\xb2\xee\xd8\xbe\x9a\xa0TnameXApple TVRvv\x10\x02[statusFlags\x10\x04_\x10\x11keepAliveLowPower\x10\x01_\x10\x18keepAliveSendStatsAsBodyRpi_\x10$b08f5a79-db29-4384-b456-a4784d9e6055]sourceVersionV220.68XdeviceID_\x10\x1156:E4:BD:D2:18:D3ZmacAddressUmodelZAppleTV3,2\\audioFormats\xa2\x17\x1d\xd3\x18\x1a\x1b\x19\x19\x1c_\x10\x11audioInputFormats\x12\x03\xff\xff\xfc_\x10\x12audioOutputFormatsTtype\x10d\xd3\x18\x1a\x1b\x19\x19\x1e\x10e^audioLatencies\xa2!\'\xd4"$&\x1b#%%\x1cYaudioTypeWdefault_\x10\x12inputLatencyMicros\x08_\x10\x13outputLatencyMicros\xd4"$&\x1b#%%\x1eXfeatures\x12\n\x7f\xce@Xdisplays\xa1,\xdb-/123456(9:.0%%%0.78%;Vheight\x11\x02\xd0Uwidth\x11\x05\x00Xrotation]widthPhysical^heightPhysical[widthPixels\\heightPixels[refreshRate\x10\x1e\x10\x0e[overscannedTuuid_\x10$436b945b-14fe-40e5-80ef-6332f8f05c57\x00\x08\x00)\x00,\x00P\x00U\x00^\x00a\x00c\x00o\x00q\x00\x85\x00\x87\x00\xa2\x00\xa5\x00\xcc\x00\xda\x00\xe1\x00\xea\x00\xfe\x01\t\x01\x0f\x01\x1a\x01\'\x01*\x011\x01E\x01J\x01_\x01d\x01f\x01m\x01o\x01~\x01\x81\x01\x8a\x01\x94\x01\x9c\x01\xb1\x01\xb2\x01\xc8\x01\xd1\x01\xda\x01\xdf\x01\xe8\x01\xea\x02\x01\x02\x08\x02\x0b\x02\x11\x02\x14\x02\x1d\x02+\x02:\x02F\x02S\x02_\x02a\x02c\x02o\x02t\x00\x00\x00\x00\x00\x00\x02\x01\x00\x00\x00\x00\x00\x00\x00<\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x02\x9b'):
2022-01-02 16:39:07 DEBUG [pyatv.core.facade]: Release (<class 'pyatv.interface.Audio'>, <class 'pyatv.interface.Metadata'>, <class 'pyatv.interface.PushUpdater'>, <class 'pyatv.interface.RemoteControl'>) by Protocol.RAOP
2022-01-02 16:39:07 DEBUG [pyatv.scripts.atvremote]: Waiting for 0 remaining tasks
2022-01-02 16:39:07 DEBUG [pyatv.protocols.raop.raop]: Control connection lost (None)
Traceback (most recent call last):
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.2544.0_x64__qbz5n2kfra8p0\lib\asyncio\locks.py", line 226, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.2544.0_x64__qbz5n2kfra8p0\lib\asyncio\tasks.py", line 492, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

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

Traceback (most recent call last):
  File "c:\users\31683\pyatv\pyatv\support\rtsp.py", line 281, in exchange
    await asyncio.wait_for(self.requests[cseq][0].wait(), 4)
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.2544.0_x64__qbz5n2kfra8p0\lib\asyncio\tasks.py", line 494, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

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

Traceback (most recent call last):
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 719, in _run_application
    return await cli_handler(loop)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 513, in cli_handler
    return await _handle_commands(args, config, loop)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 614, in _handle_commands
    ret = await _handle_device_command(args, cmd, atv, loop)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 662, in _handle_device_command
    return await _exec_command(atv.stream, cmd, True, *cmd_args)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 685, in _exec_command
    value = await tmp(*args)
  File "c:\users\31683\pyatv\pyatv\core\facade.py", line 382, in stream_file
    await self.relay("stream_file")(file, **kwargs)
  File "c:\users\31683\pyatv\pyatv\protocols\raop\__init__.py", line 348, in stream_file
    await client.initialize(self.core.service.properties)
  File "c:\users\31683\pyatv\pyatv\protocols\raop\raop.py", line 453, in initialize
    self._info.update(await self.rtsp.info())
  File "c:\users\31683\pyatv\pyatv\support\rtsp.py", line 98, in info
    device_info = await self.exchange("GET", "/info", allow_error=True)
  File "c:\users\31683\pyatv\pyatv\support\rtsp.py", line 284, in exchange
    raise TimeoutError(
TimeoutError: no response to CSeq 0 (/info)

>>> An error occurred, full stack trace above
(venv)
malosaa commented 2 years ago

here the debug in homeseer

1-02-2022 17:16:58
Legacy-Plugin/Script
FL
*** other data found ***
1-02-2022 17:16:58
Legacy-Plugin/Script
FL-NL
*** other data found ***
1-02-2022 17:16:51
Legacy-Plugin
AirplaySpeak
DEBUG TIMING EXCEPTIONA blocking operation was interrupted by a call to WSACancelBlockingCall
1-02-2022 17:16:51
Legacy-Plugin
AirplaySpeak
DEBUG TEARDOWN rtsp://192.168.1.12/0064890166 RTSP/1.0 CSeq: 6 Session: DEADBEEF User-Agent: iTunes/7.6.2 ( Windows;N;) Client-Instance: 7CE0587F9DEE83B9
1-02-2022 17:16:51
Legacy-Plugin
AirplaySpeak
DEBUG Server, AirTunes/220.68
1-02-2022 17:16:51
Legacy-Plugin
AirplaySpeak
DEBUG Date, Thu, 01 Jan 1970 00:41:15 +0000
1-02-2022 17:16:51
Legacy-Plugin
AirplaySpeak
DEBUG CSeq, 5
1-02-2022 17:16:51
Legacy-Plugin
AirplaySpeak
DEBUG FLUSH rtsp://192.168.1.12/0064890166 RTSP/1.0 CSeq: 5 Session: DEADBEEF RTP-Info: seq=8109;rtptime=173734 User-Agent: iTunes/7.6.2 ( Windows;N;) Client-Instance: 7CE0587F9DEE83B9
1-02-2022 17:16:51
Legacy-Plugin
AirplaySpeak
DEBUG 21 Speaker.OnCheckStatusTimerEvent() gets the lock
1-02-2022 17:16:51
Legacy-Plugin
AirplaySpeak
DEBUG 21 Speaker.OnCheckStatusTimerEvent()
1-02-2022 17:16:51
Legacy-Plugin
AirplaySpeak
DEBUG 17 Speaker.OnQueueEnd() gets the lock
1-02-2022 17:16:51
Legacy-Plugin
AirplaySpeak
DEBUG 17 Speaker.OnQueueEnd()
1-02-2022 17:16:50
Legacy-Plugin
AirplaySpeak
DEBUG 20 Speaker.OnCheckStatusTimerEvent() gets the lock
1-02-2022 17:16:50
Legacy-Plugin
AirplaySpeak
DEBUG 20 Speaker.OnCheckStatusTimerEvent()
1-02-2022 17:16:49
Legacy-Plugin
AirplaySpeak
DEBUG 21 Speaker.OnCheckStatusTimerEvent() gets the lock
1-02-2022 17:16:49
Legacy-Plugin
AirplaySpeak
DEBUG 21 Speaker.OnCheckStatusTimerEvent()
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG 19 Speaker.AfterSend()
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG 19 Speaker.SendSample() gets lock
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG 19 Speaker.SendSample()
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG 19 Speaker.BeforeSend()
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG Server, AirTunes/220.68
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG Date, Thu, 01 Jan 1970 00:41:12 +0000
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG CSeq, 4
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG SET_PARAMETER rtsp://192.168.1.12/0064890166 RTSP/1.0 CSeq: 4 Session: DEADBEEF Content-Type: text/parameters Content-Length: 18 User-Agent: iTunes/7.6.2 ( Windows;N;) Client-Instance: 7CE0587F9DEE83B9 volume: 0.000000
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG Audio-Latency, 2205
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG Audio-Jack-Status, connected; type=analog
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG Server, AirTunes/220.68
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG Date, Thu, 01 Jan 1970 00:41:12 +0000
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG CSeq, 3
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG RECORD rtsp://192.168.1.12/0064890166 RTSP/1.0 CSeq: 3 Session: DEADBEEF Range: npt=0- RTP-Info: seq=7761;rtptime=51238 User-Agent: iTunes/7.6.2 ( Windows;N;) Client-Instance: 7CE0587F9DEE83B9
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG Transport, RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=63305;timing_port=63304;server_port=55677
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG Session, DEADBEEF
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG Date, Thu, 01 Jan 1970 00:41:12 +0000
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG Audio-Jack-Status, connected; type=analog
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG CSeq, 2
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG Server, AirTunes/220.68
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG SETUP rtsp://192.168.1.12/0064890166 RTSP/1.0 CSeq: 2 Transport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=63305;timing_port=63304 User-Agent: iTunes/7.6.2 ( Windows;N;) Client-Instance: 7CE0587F9DEE83B9
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG Audio-Jack-Status, connected; type=analog
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG Server, AirTunes/220.68
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG Date, Thu, 01 Jan 1970 00:41:11 +0000
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG CSeq, 1
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG ANNOUNCE rtsp://192.168.1.12/0064890166 RTSP/1.0 CSeq: 1 Content-Type: application/sdp Content-Length: 182 User-Agent: iTunes/7.6.2 ( Windows;N;) Client-Instance: 7CE0587F9DEE83B9 v=0 o=iTunes 0064890166 0 IN IP4 192.168.1.12 s=iTunes c=IN IP4 192.168.1.15 t=0 0 m=audio 0 RTP/AVP 96 a=rtpmap:96 AppleLossless a=fmtp:96 352 0 16 40 10 14 2 255 0 0 44100
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG 19 Speaker.Reset() gets the lock
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
DEBUG 19 Speaker.Reset()
1-02-2022 17:16:48
Legacy-Plugin
AirplaySpeak
INFO (LivingroomSpeaker): this is a test
1-02-2022 17:16:47
HomeSeer
Event
Event Trigger "Tracking New Event - 16"
1-02-2022 17:16:47
HomeSeer
Event
Event Tracking New Event - 16 triggered by the event page 'Run' button.
postlund commented 2 years ago

@malosaa Thank you, that's great to compare! The first thing that I would like you to try is to just comment (or remove) line 453 in file pyatv/protocols/raop/raop.py and try again.

malosaa commented 2 years ago

@malosaa Thank you, that's great to compare! The first thing that I would like you to try is to just comment (or remove) line 453 in file pyatv/protocols/raop/raop.py and try again.

I can't find that folder. only this folder

image

postlund commented 2 years ago

Did you clone the repo with git clone or did you install with pip install?

malosaa commented 2 years ago

aah stupid me,

yes it works for a few seconds and than no sound.

regards

malosaa commented 2 years ago

a bit of the log it works for a bit.

i always used it for small messages, no music. regards

.000474)
2022-01-02 18:51:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 23730 (13.377596 vs 13.377886 => -0.000289)
2022-01-02 18:51:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 23741 (13.465397 vs 13.471093 => -0.005696)
2022-01-02 18:51:57 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=2833776640, RtpTime=661734, Sec=2208988817, SyncPacket=80d400070009168083aa7e91a8e80000000a18e6)
2022-01-02 18:51:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 23753 (13.561179 vs 13.563901 => -0.002722)
2022-01-02 18:51:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 23757 (13.593107 vs 13.593353 => -0.000247)
2022-01-02 18:51:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 23761 (13.625034 vs 13.628826 => -0.003792)
2022-01-02 18:51:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 23765 (13.656961 vs 13.657600 => -0.000639)
2022-01-02 18:51:57 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (670 frames behind)
2022-01-02 18:51:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 23769 (13.696871 vs 13.708021 => -0.011150)
2022-01-02 18:51:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 23771 (13.704853 vs 13.710457 => -0.005604)
2022-01-02 18:51:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 23772 (13.712834 vs 13.716912 => -0.004078)
2022-01-02 18:51:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 23780 (13.776689 vs 13.781755 => -0.005065)
2022-01-02 18:51:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 23788 (13.840544 vs 13.844591 => -0.004047)
postlund commented 2 years ago

Ok, it might have to do with buffering or something. I know the time resolution on Windows isn't great, so it can fail sometimes because of that as well. If you download the file (or take one you already have) and just pass the local path to stream_file=, does it work? In case it does, you could try to extract the URL to one of the files generated by TTS in Home Assistant. You can quite easily get that by going to Developer Tools->Events, enter call_service into the box and press "Listen". Now, open another tab with Home Assistant and try TTS (doesn't matter which media player you use). Now you can check back in the first tab and you should see an event for the to media_player.play_media service call. It will have an address attached to it, should hopefully be pretty easy to spot.

malosaa commented 2 years ago

Ok, it might have to do with buffering or something. I know the time resolution on Windows isn't great, so it can fail sometimes because of that as well. If you download the file (or take one you already have) and just pass the local path to stream_file=, does it work? In case it does, you could try to extract the URL to one of the files generated by TTS in Home Assistant. You can quite easily get that by going to Developer Tools->Events, enter call_service into the box and press "Listen". Now, open another tab with Home Assistant and try TTS (doesn't matter which media player you use). Now you can check back in the first tab and you should see an event for the to media_player.play_media service call. It will have an address attached to it, should hopefully be pretty easy to spot.

{ "event_type": "call_service", "data": { "domain": "tts", "service": "google_translate_say", "service_data": { "entity_id": "media_player.livingroomspeaker", "message": "hellpppp" } }, "origin": "LOCAL", "time_fired": "2022-01-02T18:50:01.788275+00:00", "context": { "id": "c2a0d94b87efd8e05ac535ca77aaae2c", "parent_id": null, "user_id": "2abdc50dfbb34dbd908171084e09368c" } }

postlund commented 2 years ago

That's the wrong service, there should be one for play_media (in the media_player domain).

malosaa commented 2 years ago

That's the wrong service, there should be one for play_media (in the media_player domain). sorry pasted the wrong one 

{
"event_type": "call_service",
"data": {
"domain": "media_player",
"service": "play_media",
"service_data": {
"media_content_id": "https://192.168.1.25:8123/api/tts_proxy/fe39b5a0752ee506f6d948dac288f402a594c179_en_-_google_translate.mp3",
"media_content_type": "music",
"entity_id": [
"media_player.livingroomspeaker"
]
}
},
"origin": "LOCAL",
"time_fired": "2022-01-02T18:52:13.811949+00:00",
"context": {
"id": "c2a0d94b87efd8e05ac535ca77aaae2c",
"parent_id": null,
"user_id": "2abdc50dfbb34dbd908171084e09368c"
}
}
malosaa commented 2 years ago

well i did notice when i test this with the test environment and change the url to : https://192.168.1.25:8123/api/tts_proxy/fe39b5a0752ee506f6d948dac288f402a594c179_en_-_google_translate.mp3 i get a ssl error, i need to use the domain.duckdns.org:8123 to work

also the string from media comes very late in the call_service section

postlund commented 2 years ago

Yeah, might be the case you need to change domain. It's not a very uncommon problem that the certificate does not work with local addresses. But if you used that address with stream_file=, does anything work or do you get any interesting log prints?

malosaa commented 2 years ago

i don't know how to change that it connect to my domain. right now if i try with homeassistant it doesnt work.

malosaa commented 2 years ago

@postlund

well i change it but still doesnt work trough homeassistant but the link works trough my test environment 


{
    "event_type": "call_service",
    "data": {
        "domain": "media_player",
        "service": "play_media",
        "service_data": {
            "media_content_id": "https://XXXXXXXX.duckdns.org:8123/api/tts_proxy/6ebed167c27fdc830c5a591fc1a112ea8cec7801_en_-_google_translate.mp3",
            "media_content_type": "music",
            "entity_id": [
                "media_player.livingroomspeaker"
            ]
        }
    },
    "origin": "LOCAL",
    "time_fired": "2022-01-02T21:29:02.204403+00:00",
    "context": {
        "id": "33101e80de92895e130e2ba31923f4b8",
        "parent_id": null,
        "user_id": "2abdc50dfbb34dbd908171084e09368c"
    }
}

the error 


Logger: homeassistant.components.websocket_api.http.connection
Source: custom_components/apple_tv/media_player.py:286
Integration: Home Assistant WebSocket API (documentation, issues)
First occurred: 22:27:22 (2 occurrences)
Last logged: 22:29:06

[139643822594992] no response to CSeq 0 (/info)
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/locks.py", line 226, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 492, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/rtsp.py", line 281, in exchange
    await asyncio.wait_for(self.requests[cseq][0].wait(), 4)
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 494, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

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

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 185, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1530, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/components/tts/__init__.py", line 200, in async_say_handle
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1530, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 209, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 663, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 896, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 700, in _handle_entity_call
    await result
  File "/config/custom_components/apple_tv/media_player.py", line 286, in async_play_media
    await self.atv.stream.stream_file(media_id)
  File "/usr/local/lib/python3.9/site-packages/pyatv/core/facade.py", line 382, in stream_file
    await self.relay("stream_file")(file, **kwargs)
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/raop/__init__.py", line 331, in stream_file
    await client.initialize(self.service.properties)
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/raop/raop.py", line 450, in initialize
    self._info.update(await self.rtsp.info())
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/rtsp.py", line 98, in info
    device_info = await self.exchange("GET", "/info", allow_error=True)
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/rtsp.py", line 284, in exchange
    raise TimeoutError(
TimeoutError: no response to CSeq 0 (/info)
postlund commented 2 years ago

You can't run it via home assistant because of the bug you manually corrected, so you need to use atvremote like before:

atvremote --debug -a <ip> stream_file=https://yourdomain.com:8123/api/tts_proxy/fe39b5a0752ee506f6d948dac288f402a594c179_en_-_google_translate.mp3
malosaa commented 2 years ago

is there a way now that i can use it with my events/automations in homeassistant ?

regards

postlund commented 2 years ago

Not right now, I need to fix this in pyatv and make a release first. But can you confirm that it works?

malosaa commented 2 years ago

yes, when i do it manually yes.

postlund commented 2 years ago

Thanks for acknowledging that! 👍 The problem I'm having now is to identify if /info or /server-info is to be used. Not 100% certain yet. But I suspect the former is always present on AP2 devices and the latter on AP1 devices.

In the same file and place you changed before (line 453, raop.py), can you try adding this:

print("OPTIONS:", await self.rtsp.exchange("GET", "/server-info"))

Then run this again:

atvremote -s <ip> stream_file=https://yourdomain.com:8123/api/tts_proxy/fe39b5a0752ee506f6d948dac288f402a594c179_en_-_google_translate.mp3

Then let me know what you get.

malosaa commented 2 years ago

n the same file and place you changed before (line 453, raop.py), can you try adding this:

sorry for the late response ill test now

malosaa commented 2 years ago 
$ atvremote --debug -s 192.168.1.54 stream_file=https://file-examples-com.github.io/uploads/2017/11/file_example_MP3_1MG.mp3
2022-01-11 16:50:02 DEBUG [pyatv.scripts]: Running with pyatv 0.9.8
2022-01-11 16:50:02 DEBUG [pyatv.support.knock]: Knocking at port 3689 on 192.168.1.54
2022-01-11 16:50:02 DEBUG [pyatv.support.knock]: Knocking at port 7000 on 192.168.1.54
2022-01-11 16:50:02 DEBUG [pyatv.support.knock]: Knocking at port 49152 on 192.168.1.54
2022-01-11 16:50:02 DEBUG [pyatv.support.knock]: Knocking at port 32498 on 192.168.1.54
2022-01-11 16:50:03 DEBUG [pyatv.core.scan]: Auto-discovered LivingroomSpeaker at 192.168.1.54:7000 via Protocol.AirPlay ({'deviceid': '56:E4:BD:D2:18:D3', 'features': '0x0A7FCE40', 'flags': '0x4', 'rmodel': 'EZAir1,1', 'model': 'AppleTV3,2', 'srcvers': '220.68', 'vv': '2', 'pk': '978bb5a35fa53037ff73b7b25994614a3c19896152031221ce2a91b2eed8be9a', 'pi': 'b08f5a79-db29-4384-b456-a4784d9e6055'})
2022-01-11 16:50:03 DEBUG [pyatv.core.scan]: Auto-discovered 56E4BDD218D3@LivingroomSpeaker at 192.168.1.54:47000 via Protocol.RAOP ({'cn': '0,1,3', 'da': 'true', 'et': '0,3,5', 'ft': '0x0A7FCE40', 'md': '0,1,2', 'tp': 'UDP', 'vn': '65537', 'vs': '220.68', 'rmodel': 'EZAir1,1', 'am': 'AppleTV3,2', 'vv': '2', 'sf': '0x4', 'pk': '978bb5a35fa53037ff73b7b25994614a3c19896152031221ce2a91b2eed8be9a'})
2022-01-11 16:50:03 INFO [pyatv.scripts.atvremote]: Auto-discovered LivingroomSpeaker at 192.168.1.54
2022-01-11 16:50:03 DEBUG [pyatv.core.facade]: Adding handler for protocol Protocol.AirPlay
2022-01-11 16:50:03 DEBUG [pyatv.protocols.airplay]: Remote control not supported by device
2022-01-11 16:50:03 DEBUG [pyatv.core.facade]: Adding handler for protocol Protocol.RAOP
2022-01-11 16:50:03 DEBUG [pyatv.core.facade]: Connecting to protocol: Protocol.AirPlay
2022-01-11 16:50:03 DEBUG [pyatv.core.facade]: Connected to protocol: Protocol.AirPlay
2022-01-11 16:50:03 DEBUG [pyatv.core.facade]: Connecting to protocol: Protocol.RAOP
2022-01-11 16:50:03 DEBUG [pyatv.core.facade]: Connected to protocol: Protocol.RAOP
2022-01-11 16:50:03 DEBUG [pyatv.core.facade]: Power management not supported by any protocols
2022-01-11 16:50:03 DEBUG [pyatv.core.facade]: Takeover (<class 'pyatv.interface.Audio'>, <class 'pyatv.interface.Metadata'>, <class 'pyatv.interface.PushUpdater'>, <class 'pyatv.interface.RemoteControl'>) by Protocol.RAOP
2022-01-11 16:50:03 DEBUG [pyatv.support.http]: Connected to 192.168.1.54
2022-01-11 16:50:03 DEBUG [pyatv.protocols.raop.raop]: Initializing RTSP with encryption=EncryptionType.FairPlaySAPv25|FairPlay|Unencrypted, metadata=MetadataType.Progress|Artwork|Text
2022-01-11 16:50:03 DEBUG [pyatv.protocols.raop.raop]: Update play settings to 44100/2/16bit
2022-01-11 16:50:03 DEBUG [pyatv.protocols.raop.raop]: Local ports: control=51746, timing=51747
2022-01-11 16:50:03 DEBUG [pyatv.protocols.raop.raop]: Updated info parameters to: {}
2022-01-11 16:50:03 DEBUG [pyatv.protocols.airplay.auth]: Setting up new AirPlay Pair-Verify procedure with type AuthenticationType.Null
2022-01-11 16:50:03 DEBUG [pyatv.protocols.airplay.auth]: Performing null Pair-Verify
2022-01-11 16:50:03 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'ANNOUNCE rtsp://192.168.1.84/3570144115 RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nContent-Type: application/sdp\r\nContent-Length: 182\r\nCSeq: 0\r\nDACP-ID: 29000FB84C8E68AD\r\nActive-Remote: 278836045\r\nClient-Instance: 29000FB84C8E68AD\r\n\r\nv=0\r\no=iTunes 3570144115 0 IN IP4 192.168.1.84\r\ns=iTunes\r\nc=IN IP4 192.168.1.54\r\nt=0 0\r\nm=audio 0 RTP/AVP 96\r\na=rtpmap:96 AppleLossless\r\na=fmtp:96 352 0 16 40 10 14 2 255 0 0 44100\r\n'
2022-01-11 16:50:03 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 01 Jan 1970 00:17:24 +0000\r\nAudio-Jack-Status: connected; type=analog\r\nServer: AirTunes/220.68\r\nCSeq: 0\r\n\r\n'
2022-01-11 16:50:03 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Thu, 01 Jan 1970 00:17:24 +0000', 'audio-jack-status': 'connected; type=analog', 'server': 'AirTunes/220.68', 'cseq': '0'}, body=''):
2022-01-11 16:50:03 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'SETUP rtsp://192.168.1.84/3570144115 RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 1\r\nDACP-ID: 29000FB84C8E68AD\r\nActive-Remote: 278836045\r\nClient-Instance: 29000FB84C8E68AD\r\nTransport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=51746;timing_port=51747\r\n\r\n'
2022-01-11 16:50:03 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 01 Jan 1970 00:17:24 +0000\r\nTransport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=51746;timing_port=51747;server_port=45016\r\nSession: DEADBEEF\r\nAudio-Jack-Status: connected; type=analog\r\nServer: AirTunes/220.68\r\nCSeq: 1\r\n\r\n'
2022-01-11 16:50:03 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Thu, 01 Jan 1970 00:17:24 +0000', 'transport': 'RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=51746;timing_port=51747;server_port=45016', 'session': 'DEADBEEF', 'audio-jack-status': 'connected; type=analog', 'server': 'AirTunes/220.68', 'cseq': '1'}, body=''):
2022-01-11 16:50:03 DEBUG [pyatv.protocols.raop.raop]: Remote ports: control=51746, timing=51747, server=45016
2022-01-11 16:50:03 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'GET /server-info RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 2\r\nDACP-ID: 29000FB84C8E68AD\r\nActive-Remote: 278836045\r\nClient-Instance: 29000FB84C8E68AD\r\n\r\n'
2022-01-11 16:50:07 DEBUG [pyatv.core.facade]: Release (<class 'pyatv.interface.Audio'>, <class 'pyatv.interface.Metadata'>, <class 'pyatv.interface.PushUpdater'>, <class 'pyatv.interface.RemoteControl'>) by Protocol.RAOP
2022-01-11 16:50:07 DEBUG [pyatv.scripts.atvremote]: Waiting for 0 remaining tasks
2022-01-11 16:50:07 DEBUG [pyatv.protocols.raop.raop]: Control connection lost (None)
Traceback (most recent call last):
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.2544.0_x64__qbz5n2kfra8p0\lib\asyncio\locks.py", line 226, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.2544.0_x64__qbz5n2kfra8p0\lib\asyncio\tasks.py", line 492, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

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

Traceback (most recent call last):
  File "c:\users\31683\pyatv\pyatv\support\http.py", line 388, in send_and_receive
    await asyncio.wait_for(event.wait(), timeout=4)
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.2544.0_x64__qbz5n2kfra8p0\lib\asyncio\tasks.py", line 494, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

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

Traceback (most recent call last):
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 719, in _run_application
    return await cli_handler(loop)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 513, in cli_handler
    return await _handle_commands(args, config, loop)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 614, in _handle_commands
    ret = await _handle_device_command(args, cmd, atv, loop)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 662, in _handle_device_command
    return await _exec_command(atv.stream, cmd, True, *cmd_args)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 685, in _exec_command
    value = await tmp(*args)
  File "c:\users\31683\pyatv\pyatv\core\facade.py", line 382, in stream_file
    await self.relay("stream_file")(file, **kwargs)
  File "c:\users\31683\pyatv\pyatv\protocols\raop\__init__.py", line 348, in stream_file
    await client.initialize(self.core.service.properties)
  File "c:\users\31683\pyatv\pyatv\protocols\raop\raop.py", line 459, in initialize
    print("OPTIONS:", await self.rtsp.exchange("GET", "/server-info"))
  File "c:\users\31683\pyatv\pyatv\support\rtsp.py", line 258, in exchange
    resp = await self.connection.send_and_receive(
  File "c:\users\31683\pyatv\pyatv\support\http.py", line 391, in send_and_receive
    raise TimeoutError(f"no response to {method} {uri} ({protocol})") from ex
TimeoutError: no response to GET /server-info (RTSP/1.0)

>>> An error occurred, full stack trace above
(venv)
malosaa commented 2 years ago

withoyt that line it works normal 

        # Set up the streaming session
        await self._setup_session()
        print("OPTIONS:", await self.rtsp.exchange("GET", "/server-info"))
malosaa commented 2 years ago

FOr example i use this atvremote --debug -s 192.168.1.54 stream_file=https://www.myinstants.com/media/sounds/epic.mp3

it plays normal but when i add this line print("OPTIONS:", await self.rtsp.exchange("GET", "/server-info")) it stops with an error

postlund commented 2 years ago

What is the output to:

print("OPTIONS:", await self.rtsp.exchange("OPTIONS", "*"))
malosaa commented 2 years ago

What is the output to:

print("OPTIONS:", await self.rtsp.exchange("OPTIONS", "*"))
$ atvremote -s 192.168.1.54 stream_file=https://www.myinstants.com/media/sounds/epic.mp3
OPTIONS: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Thu, 01 Jan 1970 19:20:58 +0000', 'public': 'ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER, POST, GET', 'server': 'AirTunes/220.68', 'cseq': '0'}, body='')
(venv)
postlund commented 2 years ago

Humm, that is very unfortunate. So both /server-info and /info times out and it also reports to support GET commands... Question is why it times out and does not respond to the commands. Maybe it is picky about the protocol version being HTTP? Can you try if http://192.168.1.54:47000/info or http://192.168.1.54:47000/server-info times out, if a file is returned or simply results in 404?

malosaa commented 2 years ago

Humm, that is very unfortunate. So both /server-info and /info times out and it also reports to support GET commands... Question is why it times out and does not respond to the commands. Maybe it is picky about the protocol version being HTTP? Can you try if http://192.168.1.54:47000/info or http://192.168.1.54:47000/server-info times out, if a file is returned or simply results in 404?

hi, it does not time out, it actually plays the file normally. regards

postlund commented 2 years ago

The problem is that I need some way to determine if I can fetch /server-info or /info to support both devices that either do support any of those commands or not. I cannot just remove that check as that breaks functionality. That is why I need to know if any of the addresses above works (and all the testing generally). I can't solve this until I have a proper solution to this.

malosaa commented 2 years ago

on both links i get ERR_EMPTY_RESPONSE, don't know why http://192.168.1.54:47000/info or http://192.168.1.54:47000/server-info

on homeseer i get this log, when debugged. https://github.com/postlund/pyatv/issues/1576#issuecomment-1003740027

the device is an ezcast m7 http://192.168.1.54/websetting.html

malosaa commented 2 years ago

here also the full debug log with your commands

$ atvremote --debug -s 192.168.1.54 stream_file=https://www.myinstants.com/media/sounds/epic.mp3
2022-01-12 15:17:51 DEBUG [pyatv.scripts]: Running with pyatv 0.9.8
2022-01-12 15:17:51 DEBUG [pyatv.support.knock]: Knocking at port 3689 on 192.168.1.54
2022-01-12 15:17:51 DEBUG [pyatv.support.knock]: Knocking at port 7000 on 192.168.1.54
2022-01-12 15:17:51 DEBUG [pyatv.support.knock]: Knocking at port 49152 on 192.168.1.54
2022-01-12 15:17:51 DEBUG [pyatv.support.knock]: Knocking at port 32498 on 192.168.1.54
2022-01-12 15:17:52 DEBUG [pyatv.core.scan]: Auto-discovered LivingroomSpeaker at 192.168.1.54:7000 via Protocol.AirPlay ({'deviceid': '56:E4:BD:D2:18:D3', 'features': '0x0A7FCE40', 'flags': '0x4', 'rmodel': 'EZAir1,1', 'model': 'AppleTV3,2', 'srcvers': '220.68', 'vv': '2', 'pk': '978bb5a35fa53037ff73b7b25994614a3c19896152031221ce2a91b2eed8be9a', 'pi': 'b08f5a79-db29-4384-b456-a4784d9e6055'})
2022-01-12 15:17:52 DEBUG [pyatv.core.scan]: Auto-discovered 56E4BDD218D3@LivingroomSpeaker at 192.168.1.54:47000 via Protocol.RAOP ({'cn': '0,1,3', 'da': 'true', 'et': '0,3,5', 'ft': '0x0A7FCE40', 'md': '0,1,2', 'tp': 'UDP', 'vn': '65537', 'vs': '220.68', 'rmodel': 'EZAir1,1', 'am': 'AppleTV3,2', 'vv': '2', 'sf': '0x4', 'pk': '978bb5a35fa53037ff73b7b25994614a3c19896152031221ce2a91b2eed8be9a'})
2022-01-12 15:17:52 INFO [pyatv.scripts.atvremote]: Auto-discovered LivingroomSpeaker at 192.168.1.54
2022-01-12 15:17:52 DEBUG [pyatv.core.facade]: Adding handler for protocol Protocol.AirPlay
2022-01-12 15:17:52 DEBUG [pyatv.protocols.airplay]: Remote control not supported by device
2022-01-12 15:17:52 DEBUG [pyatv.core.facade]: Adding handler for protocol Protocol.RAOP
2022-01-12 15:17:52 DEBUG [pyatv.core.facade]: Connecting to protocol: Protocol.AirPlay
2022-01-12 15:17:52 DEBUG [pyatv.core.facade]: Connected to protocol: Protocol.AirPlay
2022-01-12 15:17:52 DEBUG [pyatv.core.facade]: Connecting to protocol: Protocol.RAOP
2022-01-12 15:17:52 DEBUG [pyatv.core.facade]: Connected to protocol: Protocol.RAOP
2022-01-12 15:17:52 DEBUG [pyatv.core.facade]: Power management not supported by any protocols
2022-01-12 15:17:52 DEBUG [pyatv.core.facade]: Takeover (<class 'pyatv.interface.Audio'>, <class 'pyatv.interface.Metadata'>, <class 'pyatv.interface.PushUpdater'>, <class 'pyatv.interface.RemoteControl'>) by Protocol.RAOP
2022-01-12 15:17:52 DEBUG [pyatv.support.http]: Connected to 192.168.1.54
2022-01-12 15:17:52 DEBUG [pyatv.protocols.raop.raop]: Initializing RTSP with encryption=EncryptionType.FairPlaySAPv25|FairPlay|Unencrypted, metadata=MetadataType.Progress|Artwork|Text
2022-01-12 15:17:52 DEBUG [pyatv.protocols.raop.raop]: Update play settings to 44100/2/16bit
2022-01-12 15:17:52 DEBUG [pyatv.protocols.raop.raop]: Local ports: control=55265, timing=55266
2022-01-12 15:17:52 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'OPTIONS * RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 0\r\nDACP-ID: 272B3B54F5501B24\r\nActive-Remote: 622972739\r\nClient-Instance: 272B3B54F5501B24\r\n\r\n'
2022-01-12 15:17:52 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 01 Jan 1970 22:45:14 +0000\r\nPublic: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER, POST, GET\r\nServer: AirTunes/220.68\r\nCSeq: 0\r\n\r\n'
2022-01-12 15:17:52 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Thu, 01 Jan 1970 22:45:14 +0000', 'public': 'ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER, POST, GET', 'server': 'AirTunes/220.68', 'cseq': '0'}, body=''):
OPTIONS: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Thu, 01 Jan 1970 22:45:14 +0000', 'public': 'ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER, POST, GET', 'server': 'AirTunes/220.68', 'cseq': '0'}, body='')
2022-01-12 15:17:52 DEBUG [pyatv.protocols.raop.raop]: Updated info parameters to: {}
2022-01-12 15:17:52 DEBUG [pyatv.protocols.airplay.auth]: Setting up new AirPlay Pair-Verify procedure with type AuthenticationType.Null
2022-01-12 15:17:52 DEBUG [pyatv.protocols.airplay.auth]: Performing null Pair-Verify
2022-01-12 15:17:52 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'ANNOUNCE rtsp://192.168.1.84/366228931 RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nContent-Type: application/sdp\r\nContent-Length: 181\r\nCSeq: 1\r\nDACP-ID: 272B3B54F5501B24\r\nActive-Remote: 622972739\r\nClient-Instance: 272B3B54F5501B24\r\n\r\nv=0\r\no=iTunes 366228931 0 IN IP4 192.168.1.84\r\ns=iTunes\r\nc=IN IP4 192.168.1.54\r\nt=0 0\r\nm=audio 0 RTP/AVP 96\r\na=rtpmap:96 AppleLossless\r\na=fmtp:96 352 0 16 40 10 14 2 255 0 0 44100\r\n'
2022-01-12 15:17:52 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 01 Jan 1970 22:45:14 +0000\r\nAudio-Jack-Status: connected; type=analog\r\nServer: AirTunes/220.68\r\nCSeq: 1\r\n\r\n'
2022-01-12 15:17:52 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Thu, 01 Jan 1970 22:45:14 +0000', 'audio-jack-status': 'connected; type=analog', 'server': 'AirTunes/220.68', 'cseq': '1'}, body=''):
2022-01-12 15:17:52 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'SETUP rtsp://192.168.1.84/366228931 RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 2\r\nDACP-ID: 272B3B54F5501B24\r\nActive-Remote: 622972739\r\nClient-Instance: 272B3B54F5501B24\r\nTransport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=55265;timing_port=55266\r\n\r\n'
2022-01-12 15:17:52 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 01 Jan 1970 22:45:14 +0000\r\nTransport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=55265;timing_port=55266;server_port=51507\r\nSession: DEADBEEF\r\nAudio-Jack-Status: connected; type=analog\r\nServer: AirTunes/220.68\r\nCSeq: 2\r\n\r\n'
2022-01-12 15:17:52 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Thu, 01 Jan 1970 22:45:14 +0000', 'transport': 'RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=55265;timing_port=55266;server_port=51507', 'session': 'DEADBEEF', 'audio-jack-status': 'connected; type=analog', 'server': 'AirTunes/220.68', 'cseq': '2'}, body=''):
2022-01-12 15:17:52 DEBUG [pyatv.protocols.raop.raop]: Remote ports: control=55265, timing=55266, server=51507
2022-01-12 15:17:52 DEBUG [pyatv.protocols.raop]: Seeking not supported by source, not loading metadata
2022-01-12 15:17:52 DEBUG [urllib3.connectionpool]: Starting new HTTPS connection (1): www.myinstants.com:443
2022-01-12 15:17:52 DEBUG [urllib3.connectionpool]: https://www.myinstants.com:443 "GET /media/sounds/epic.mp3 HTTP/1.1" 200 272092
2022-01-12 15:17:53 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'SET_PARAMETER rtsp://192.168.1.84/366228931 RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nContent-Type: text/parameters\r\nContent-Length: 13\r\nCSeq: 3\r\nDACP-ID: 272B3B54F5501B24\r\nActive-Remote: 622972739\r\nClient-Instance: 272B3B54F5501B24\r\n\r\nvolume: -20.1'
2022-01-12 15:17:53 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 01 Jan 1970 22:45:15 +0000\r\nServer: AirTunes/220.68\r\nCSeq: 3\r\n\r\n'
2022-01-12 15:17:53 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Thu, 01 Jan 1970 22:45:15 +0000', 'server': 'AirTunes/220.68', 'cseq': '3'}, body=''):
2022-01-12 15:17:53 DEBUG [pyatv.core.protocol]: Dispatching message with type UpdatedState.Volume to <bound method RaopAudio._volume_changed of <pyatv.protocols.raop.RaopAudio object at 0x000002944ECB5E80>>
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop]: Protocol RAOP changed volume to 33.000000
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Starting periodic sync task
2022-01-12 15:17:53 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'SET_PARAMETER rtsp://192.168.1.84/366228931 RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nContent-Type: text/parameters\r\nContent-Length: 27\r\nCSeq: 4\r\nDACP-ID: 272B3B54F5501B24\r\nActive-Remote: 622972739\r\nClient-Instance: 272B3B54F5501B24\r\n\r\nprogress: 66150/66150/66150'
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=801767424, RtpTime=66150, Sec=2208988803, SyncPacket=90d400070000000083aa7e832fca000000010266)
2022-01-12 15:17:53 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 01 Jan 1970 22:45:15 +0000\r\nServer: AirTunes/220.68\r\nCSeq: 4\r\n\r\n'
2022-01-12 15:17:53 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Thu, 01 Jan 1970 22:45:15 +0000', 'server': 'AirTunes/220.68', 'cseq': '4'}, body=''):
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Playing with metadata: AudioMetadata(title='Streaming with pyatv', artist='pyatv', album='RAOP', duration=0.0)
2022-01-12 15:17:53 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'SET_PARAMETER rtsp://192.168.1.84/366228931 RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nContent-Type: application/x-dmap-tagged\r\nContent-Length: 61\r\nCSeq: 5\r\nDACP-ID: 272B3B54F5501B24\r\nActive-Remote: 622972739\r\nClient-Instance: 272B3B54F5501B24\r\nSession: DEADBEEF\r\nRTP-Info: seq=25629;rtptime=66150\r\n\r\nmlit\x00\x00\x005minm\x00\x00\x00\x14Streaming with pyatvasal\x00\x00\x00\x04RAOPasar\x00\x00\x00\x05pyatv'
2022-01-12 15:17:53 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 01 Jan 1970 22:45:15 +0000\r\nServer: AirTunes/220.68\r\nCSeq: 5\r\n\r\n'
2022-01-12 15:17:53 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Thu, 01 Jan 1970 22:45:15 +0000', 'server': 'AirTunes/220.68', 'cseq': '5'}, body=''):
2022-01-12 15:17:53 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: 272B3B54F5501B24\r\nActive-Remote: 622972739\r\nClient-Instance: 272B3B54F5501B24\r\n\r\n'
2022-01-12 15:17:53 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 01 Jan 1970 22:45:15 +0000\r\nContent-Length: 0\r\nServer: AirTunes/220.68\r\nCSeq: 6\r\n\r\n'
2022-01-12 15:17:53 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Thu, 01 Jan 1970 22:45:15 +0000', 'content-length': '0', 'server': 'AirTunes/220.68', 'cseq': '6'}, body=''):
2022-01-12 15:17:53 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'RECORD rtsp://192.168.1.84/366228931 RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 7\r\nDACP-ID: 272B3B54F5501B24\r\nActive-Remote: 622972739\r\nClient-Instance: 272B3B54F5501B24\r\nRange: npt=0-\r\nSession: DEADBEEF\r\nRTP-Info: seq=25629;rtptime=66150\r\n\r\n'
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Starting keep-alive task
2022-01-12 15:17:53 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 01 Jan 1970 22:45:15 +0000\r\nAudio-Latency: 2205\r\nAudio-Jack-Status: connected; type=analog\r\nServer: AirTunes/220.68\r\nCSeq: 7\r\n\r\n'
2022-01-12 15:17:53 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Thu, 01 Jan 1970 22:45:15 +0000', 'audio-latency': '2205', 'audio-jack-status': 'connected; type=analog', 'server': 'AirTunes/220.68', 'cseq': '7'}, body=''):
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25631 (0.031927 vs 0.037603 => -0.005676)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25632 (0.039909 vs 0.040694 => -0.000785)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25639 (0.095782 vs 0.099171 => -0.003388)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25643 (0.127710 vs 0.130609 => -0.002899)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25647 (0.159637 vs 0.164442 => -0.004804)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Compensating with 2 packets (754 frames behind)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25648 (0.183583 vs 0.191102 => -0.007519)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25651 (0.191565 vs 0.194484 => -0.002919)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25652 (0.199546 vs 0.199756 => -0.000209)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (371 frames behind)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25656 (0.239456 vs 0.241363 => -0.001907)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25672 (0.359184 vs 0.365276 => -0.006092)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (408 frames behind)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25673 (0.375147 vs 0.381530 => -0.006383)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25675 (0.383129 vs 0.385297 => -0.002168)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25684 (0.454966 vs 0.459961 => -0.004995)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25690 (0.502857 vs 0.506994 => -0.004137)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25696 (0.550748 vs 0.554404 => -0.003656)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (448 frames behind)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25701 (0.598639 vs 0.603759 => -0.005119)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25703 (0.606621 vs 0.608740 => -0.002118)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (380 frames behind)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25709 (0.662494 vs 0.666321 => -0.003826)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25711 (0.670476 vs 0.671154 => -0.000678)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25717 (0.718367 vs 0.724525 => -0.006158)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25718 (0.726349 vs 0.727783 => -0.001434)
2022-01-12 15:17:53 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25723 (0.766259 vs 0.771184 => -0.004925)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25724 (0.774240 vs 0.779549 => -0.005308)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25725 (0.782222 vs 0.782668 => -0.000446)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (416 frames behind)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25730 (0.830113 vs 0.832949 => -0.002836)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25735 (0.862041 vs 0.862948 => -0.000908)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=243531776, RtpTime=104518, Sec=2208988804, SyncPacket=80d40007000095e083aa7e840e84000000019846)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25739 (0.893968 vs 0.894032 => -0.000063)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25747 (0.957823 vs 0.965213 => -0.007389)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25748 (0.965805 vs 0.968352 => -0.002548)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 1.003976s (current frames: 44352, expected: 44275)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25760 (1.061587 vs 1.067738 => -0.006151)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25761 (1.069569 vs 1.070991 => -0.001422)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25766 (1.109478 vs 1.114825 => -0.005347)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25767 (1.117460 vs 1.122779 => -0.005319)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25768 (1.125442 vs 1.126603 => -0.001161)
2022-01-12 15:17:54 WARNING [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25769 (1.133424 vs 1.135708 => -0.002284)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (603 frames behind)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25775 (1.189297 vs 1.198347 => -0.009050)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25777 (1.197279 vs 1.202709 => -0.005430)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25778 (1.205261 vs 1.207474 => -0.002213)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25783 (1.245170 vs 1.251904 => -0.006734)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25784 (1.253152 vs 1.253169 => -0.000017)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25791 (1.309025 vs 1.315012 => -0.005987)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25799 (1.372880 vs 1.378947 => -0.006067)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25800 (1.380862 vs 1.382446 => -0.001584)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25805 (1.420771 vs 1.423954 => -0.003183)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25809 (1.452698 vs 1.454416 => -0.001717)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25813 (1.484626 vs 1.487054 => -0.002428)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (430 frames behind)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25818 (1.532517 vs 1.537224 => -0.004707)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25820 (1.540499 vs 1.542077 => -0.001579)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25827 (1.596372 vs 1.596654 => -0.000282)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25832 (1.636281 vs 1.643807 => -0.007526)
2022-01-12 15:17:54 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25833 (1.644263 vs 1.647243 => -0.002980)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=233832448, RtpTime=148518, Sec=2208988805, SyncPacket=80d40007000141c083aa7e850df0000000024426)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (459 frames behind)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25863 (1.891701 vs 1.897144 => -0.005443)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25865 (1.899683 vs 1.901775 => -0.002093)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (1267 frames behind)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25871 (1.971519 vs 1.996658 => -0.025139)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Compensating with 2 packets (970 frames behind)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25875 (1.995465 vs 2.007291 => -0.011826)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25878 (2.003447 vs 2.009187 => -0.005741)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 1.006823s (current frames: 88704, expected: 88676)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25879 (2.011429 vs 2.012161 => -0.000732)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (472 frames behind)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25920 (2.346667 vs 2.352521 => -0.005854)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25922 (2.354649 vs 2.357439 => -0.002791)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (393 frames behind)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25928 (2.410522 vs 2.416861 => -0.006340)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25930 (2.418503 vs 2.421062 => -0.002559)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25940 (2.498322 vs 2.503939 => -0.005617)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25941 (2.506304 vs 2.507357 => -0.001053)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (472 frames behind)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25959 (2.657959 vs 2.664302 => -0.006343)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25961 (2.665941 vs 2.668191 => -0.002250)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25966 (2.705850 vs 2.708173 => -0.002323)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25967 (2.713832 vs 2.716372 => -0.002540)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25972 (2.753741 vs 2.755361 => -0.001620)
2022-01-12 15:17:55 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25973 (2.761723 vs 2.763548 => -0.001824)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=189792256, RtpTime=192166, Sec=2208988806, SyncPacket=80d400070001ec4083aa7e860b5000000002eea6)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 25986 (2.865488 vs 2.866324 => -0.000836)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Compensating with 2 packets (734 frames behind)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26000 (2.993197 vs 2.997826 => -0.004629)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 0.991701s (current frames: 133056, expected: 132410)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26007 (3.033107 vs 3.034980 => -0.001873)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26012 (3.073016 vs 3.080911 => -0.007895)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26013 (3.080998 vs 3.083678 => -0.002681)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26018 (3.120907 vs 3.127793 => -0.006886)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26019 (3.128889 vs 3.130472 => -0.001584)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26024 (3.168798 vs 3.174844 => -0.006045)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26025 (3.176780 vs 3.177467 => -0.000687)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26036 (3.264580 vs 3.267883 => -0.003303)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26044 (3.328435 vs 3.330742 => -0.002307)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (443 frames behind)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26049 (3.376327 vs 3.382053 => -0.005727)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26051 (3.384308 vs 3.385738 => -0.001429)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26056 (3.424218 vs 3.426225 => -0.002008)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26057 (3.432200 vs 3.434229 => -0.002030)
2022-01-12 15:17:56 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26099 (3.767438 vs 3.769758 => -0.002320)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (408 frames behind)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26104 (3.815329 vs 3.820311 => -0.004983)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26106 (3.823311 vs 3.823937 => -0.000626)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=180027392, RtpTime=236166, Sec=2208988807, SyncPacket=80d400070002982083aa7e870abb000000039a86)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26111 (3.863220 vs 3.868805 => -0.005585)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26112 (3.871202 vs 3.872930 => -0.001729)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26113 (3.879184 vs 3.883795 => -0.004612)
2022-01-12 15:17:57 WARNING [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26114 (3.887166 vs 3.887235 => -0.000069)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (658 frames behind)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26123 (3.966984 vs 3.979343 => -0.012358)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26125 (3.974966 vs 3.981614 => -0.006648)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26126 (3.982948 vs 3.983565 => -0.000617)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26127 (3.990930 vs 3.991464 => -0.000534)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 1.015708s (current frames: 177408, expected: 177203)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26134 (4.046803 vs 4.048675 => -0.001872)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26138 (4.078730 vs 4.080513 => -0.001783)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (679 frames behind)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26142 (4.118639 vs 4.136257 => -0.017617)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (489 frames behind)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26144 (4.134603 vs 4.139188 => -0.004585)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26158 (4.238367 vs 4.238498 => -0.000130)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26163 (4.278277 vs 4.285443 => -0.007167)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26164 (4.286259 vs 4.289025 => -0.002766)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26173 (4.358095 vs 4.361870 => -0.003774)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (450 frames behind)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26182 (4.437914 vs 4.442649 => -0.004735)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26184 (4.445896 vs 4.446770 => -0.000874)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26189 (4.485805 vs 4.487554 => -0.001749)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (1275 frames behind)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26194 (4.549660 vs 4.557844 => -0.008184)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26198 (4.557642 vs 4.559547 => -0.001905)
2022-01-12 15:17:57 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26202 (4.589569 vs 4.595904 => -0.006335)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26234 (4.844989 vs 4.848161 => -0.003172)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=170328064, RtpTime=280166, Sec=2208988808, SyncPacket=80d400070003440083aa7e880a27000000044666)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26240 (4.892880 vs 4.894397 => -0.001517)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26241 (4.900862 vs 4.902868 => -0.002006)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26246 (4.940771 vs 4.940954 => -0.000183)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26247 (4.948753 vs 4.948986 => -0.000233)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26249 (4.964717 vs 4.967486 => -0.002770)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26250 (4.972698 vs 4.976078 => -0.003380)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 1.013973s (current frames: 221760, expected: 221919)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26257 (5.028571 vs 5.032627 => -0.004056)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26265 (5.092426 vs 5.094006 => -0.001580)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26269 (5.124354 vs 5.125533 => -0.001179)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26273 (5.156281 vs 5.157897 => -0.001616)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26277 (5.188209 vs 5.189304 => -0.001095)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26289 (5.283991 vs 5.285172 => -0.001181)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26295 (5.331882 vs 5.332313 => -0.000431)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26300 (5.371791 vs 5.375428 => -0.003636)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26301 (5.379773 vs 5.382240 => -0.002467)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (394 frames behind)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26307 (5.435646 vs 5.441436 => -0.005790)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26309 (5.443628 vs 5.444783 => -0.001155)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (442 frames behind)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26315 (5.499501 vs 5.504888 => -0.005386)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26317 (5.507483 vs 5.509369 => -0.001886)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26318 (5.515465 vs 5.516544 => -0.001079)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26331 (5.619229 vs 5.624598 => -0.005369)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26337 (5.667120 vs 5.670869 => -0.003749)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26345 (5.730975 vs 5.733701 => -0.002726)
2022-01-12 15:17:58 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26349 (5.762902 vs 5.766505 => -0.003603)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26353 (5.794830 vs 5.796716 => -0.001886)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26357 (5.826757 vs 5.827573 => -0.000815)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=160563200, RtpTime=324166, Sec=2208988809, SyncPacket=80d400070003efe083aa7e89099200000004f246)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26361 (5.858685 vs 5.859989 => -0.001305)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (1130 frames behind)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26372 (5.970431 vs 5.985211 => -0.014780)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (438 frames behind)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26376 (5.986395 vs 5.994311 => -0.007916)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26378 (5.994376 vs 5.999595 => -0.005218)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 0.997841s (current frames: 266112, expected: 265924)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26390 (6.090159 vs 6.090509 => -0.000350)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26394 (6.122086 vs 6.123264 => -0.001177)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (372 frames behind)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26399 (6.169977 vs 6.174113 => -0.004136)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26401 (6.177959 vs 6.178025 => -0.000066)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26406 (6.217868 vs 6.218374 => -0.000505)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26407 (6.225850 vs 6.226548 => -0.000697)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26415 (6.289705 vs 6.296064 => -0.006358)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26416 (6.297687 vs 6.299201 => -0.001514)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (447 frames behind)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26430 (6.417415 vs 6.422721 => -0.005306)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26432 (6.425397 vs 6.427657 => -0.002260)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26439 (6.481270 vs 6.483225 => -0.001955)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26444 (6.521179 vs 6.528954 => -0.007775)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26445 (6.529161 vs 6.532707 => -0.003546)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (489 frames behind)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26463 (6.680816 vs 6.687111 => -0.006295)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26465 (6.688798 vs 6.692613 => -0.003815)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26466 (6.696780 vs 6.702598 => -0.005818)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26467 (6.704762 vs 6.706683 => -0.001921)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26473 (6.752653 vs 6.760519 => -0.007866)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26474 (6.760635 vs 6.763616 => -0.002981)
2022-01-12 15:17:59 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26475 (6.768617 vs 6.769215 => -0.000598)
2022-01-12 15:18:00 WARNING [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26476 (6.776599 vs 6.777199 => -0.000600)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Compensating with 2 packets (787 frames behind)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26481 (6.832472 vs 6.839844 => -0.007373)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (408 frames behind)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26484 (6.848435 vs 6.851480 => -0.003045)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=185139200, RtpTime=368518, Sec=2208988810, SyncPacket=80d4000700049d2083aa7e8a0b09000000059f86)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26493 (6.912290 vs 6.916820 => -0.004529)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Compensating with 2 packets (1019 frames behind)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26497 (6.960181 vs 6.988493 => -0.028312)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Compensating with 2 packets (996 frames behind)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26500 (6.984127 vs 6.993348 => -0.009221)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26503 (6.992109 vs 6.994978 => -0.002869)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 0.998298s (current frames: 310464, expected: 309949)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26511 (7.055964 vs 7.058310 => -0.002346)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26515 (7.087891 vs 7.087993 => -0.000102)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26523 (7.151746 vs 7.153161 => -0.001415)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (378 frames behind)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26528 (7.199637 vs 7.202840 => -0.003203)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26536 (7.255510 vs 7.263368 => -0.007857)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26537 (7.263492 vs 7.271284 => -0.007792)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26538 (7.271474 vs 7.274367 => -0.002893)
2022-01-12 15:18:00 WARNING [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26539 (7.279456 vs 7.282794 => -0.003339)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26548 (7.351293 vs 7.356628 => -0.005335)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26549 (7.359274 vs 7.360826 => -0.001552)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26550 (7.367256 vs 7.368619 => -0.001363)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26560 (7.447075 vs 7.449742 => -0.002667)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26568 (7.510930 vs 7.514571 => -0.003641)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26569 (7.518912 vs 7.519370 => -0.000458)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26573 (7.550839 vs 7.557807 => -0.006968)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26574 (7.558821 vs 7.560718 => -0.001897)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26585 (7.646621 vs 7.650884 => -0.004263)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26589 (7.678549 vs 7.682622 => -0.004073)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26597 (7.742404 vs 7.743871 => -0.001468)
2022-01-12 15:18:00 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26601 (7.774331 vs 7.775953 => -0.001621)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26605 (7.806259 vs 7.807545 => -0.001287)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26609 (7.838186 vs 7.838546 => -0.000360)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=209649664, RtpTime=412870, Sec=2208988811, SyncPacket=80d4000700054a6083aa7e8b0c7f000000064cc6)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26613 (7.870113 vs 7.872416 => -0.002302)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26620 (7.925986 vs 7.932679 => -0.006693)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26621 (7.933968 vs 7.936213 => -0.002244)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26625 (7.965896 vs 7.968458 => -0.002562)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26630 (8.005805 vs 8.009773 => -0.003968)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 1.012637s (current frames: 354816, expected: 354606)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26638 (8.069660 vs 8.073197 => -0.003538)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26642 (8.101587 vs 8.105233 => -0.003646)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26646 (8.133515 vs 8.136469 => -0.002954)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26650 (8.165442 vs 8.168570 => -0.003127)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26654 (8.197370 vs 8.199348 => -0.001978)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26658 (8.229297 vs 8.231389 => -0.002092)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26662 (8.261224 vs 8.266407 => -0.005183)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26667 (8.301134 vs 8.307793 => -0.006659)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26668 (8.309116 vs 8.309183 => -0.000068)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26679 (8.396916 vs 8.402256 => -0.005340)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26687 (8.460771 vs 8.465674 => -0.004903)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26695 (8.524626 vs 8.527995 => -0.003370)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26699 (8.556553 vs 8.559048 => -0.002495)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26703 (8.588481 vs 8.590173 => -0.001692)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26707 (8.620408 vs 8.621079 => -0.000671)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26711 (8.652336 vs 8.652359 => -0.000023)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26722 (8.740136 vs 8.748034 => -0.007898)
2022-01-12 15:18:01 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26723 (8.748118 vs 8.751072 => -0.002954)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26738 (8.867846 vs 8.871676 => -0.003830)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=268500992, RtpTime=457574, Sec=2208988812, SyncPacket=80d400070005f90083aa7e8c100100000006fb66)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26746 (8.931701 vs 8.934673 => -0.002972)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26753 (8.987574 vs 8.995070 => -0.007497)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26754 (8.995556 vs 8.996579 => -0.001024)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26759 (9.035465 vs 9.042102 => -0.006638)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26760 (9.043447 vs 9.046541 => -0.003094)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 1.009616s (current frames: 399168, expected: 399130)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26761 (9.051429 vs 9.051431 => -0.000002)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26773 (9.147211 vs 9.151862 => -0.004651)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26774 (9.155193 vs 9.155929 => -0.000737)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26779 (9.195102 vs 9.199479 => -0.004377)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26780 (9.203084 vs 9.208367 => -0.005283)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26781 (9.211066 vs 9.212146 => -0.001080)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (377 frames behind)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26786 (9.258957 vs 9.260635 => -0.001678)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26791 (9.290884 vs 9.290959 => -0.000075)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.audio_source]: HTTP streaming ended
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26806 (9.410612 vs 9.417868 => -0.007256)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26807 (9.418594 vs 9.420345 => -0.001750)
2022-01-12 15:18:02 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (358 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26812 (9.466485 vs 11.845450 => -2.378965)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (104848 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26814 (9.498413 vs 11.859634 => -2.361221)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (104220 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26818 (9.530340 vs 11.872060 => -2.341719)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (102962 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26822 (9.562268 vs 11.875638 => -2.313370)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (101728 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26826 (9.594195 vs 11.879532 => -2.285337)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (100526 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26830 (9.626122 vs 11.884580 => -2.258458)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (99293 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26834 (9.658050 vs 11.888172 => -2.230122)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (98058 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26838 (9.689977 vs 11.892877 => -2.202900)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (96862 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26842 (9.721905 vs 11.898235 => -2.176330)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (95679 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26846 (9.753832 vs 11.901930 => -2.148098)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (94431 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26850 (9.785760 vs 11.906010 => -2.120250)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (93212 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26854 (9.817687 vs 11.912046 => -2.094359)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (92111 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26858 (9.849615 vs 11.919747 => -2.070133)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (90995 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26862 (9.881542 vs 11.924837 => -2.043295)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (89814 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26866 (9.913469 vs 11.928620 => -2.015151)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (88584 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26870 (9.945397 vs 11.933641 => -1.988244)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (87381 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26874 (9.977324 vs 11.937238 => -1.959914)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (86152 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26878 (10.009252 vs 11.943533 => -1.934282)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (85034 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26882 (10.041179 vs 11.949235 => -1.908056)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (83856 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Sent 45056 frames in 2.902895s (current frames: 444224, expected: 527148)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26886 (10.073107 vs 11.955872 => -1.882766)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (82734 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26890 (10.105034 vs 11.960133 => -1.855099)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (81505 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26894 (10.136961 vs 11.964470 => -1.827508)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (80313 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26898 (10.168889 vs 11.968618 => -1.799729)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (79595 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26902 (10.200816 vs 11.989428 => -1.788612)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (79186 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26906 (10.232744 vs 12.010099 => -1.777356)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (78265 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26910 (10.264671 vs 12.021397 => -1.756726)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (77178 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26914 (10.296599 vs 12.025231 => -1.728633)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (75931 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26918 (10.328526 vs 12.029266 => -1.700740)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (74742 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26922 (10.360454 vs 12.036311 => -1.675857)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (73608 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26926 (10.392381 vs 12.039875 => -1.647494)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (72357 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26930 (10.424308 vs 12.043760 => -1.619451)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (71116 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26934 (10.456236 vs 12.048672 => -1.592436)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (70044 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26938 (10.488163 vs 12.055908 => -1.567744)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (68834 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26942 (10.520091 vs 12.059359 => -1.539269)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (67576 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26946 (10.552018 vs 12.063315 => -1.511296)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (66477 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26950 (10.583946 vs 12.070526 => -1.486580)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (65254 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26954 (10.615873 vs 12.073949 => -1.458076)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (64000 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26958 (10.647800 vs 12.077706 => -1.429906)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (62772 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26962 (10.679728 vs 12.085954 => -1.406226)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (61722 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26966 (10.711655 vs 12.090186 => -1.378530)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (60486 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26970 (10.743583 vs 12.093559 => -1.349976)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (59384 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26974 (10.775510 vs 12.101531 => -1.326020)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (58223 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26978 (10.807438 vs 12.106237 => -1.298799)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (56974 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26982 (10.839365 vs 12.110591 => -1.271226)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (55859 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26986 (10.871293 vs 12.118572 => -1.247279)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (54710 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26990 (10.903220 vs 12.122267 => -1.219047)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (53458 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26994 (10.935147 vs 12.126272 => -1.191125)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (52331 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 26998 (10.967075 vs 12.133798 => -1.166723)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (51159 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27002 (10.999002 vs 12.137732 => -1.138730)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (49932 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27006 (11.030930 vs 12.141708 => -1.110778)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (48762 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27010 (11.062857 vs 12.148908 => -1.086050)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (47602 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Sent 45056 frames in 0.199526s (current frames: 489280, expected: 535947)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27014 (11.094785 vs 12.153220 => -1.058435)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (46379 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27018 (11.126712 vs 12.156761 => -1.030048)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (45117 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27022 (11.158639 vs 12.163172 => -1.004532)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (44052 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27026 (11.190567 vs 12.168414 => -0.977847)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (42816 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27030 (11.222494 vs 12.172093 => -0.949599)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (41574 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27034 (11.254422 vs 12.177184 => -0.922762)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (40451 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27038 (11.286349 vs 12.183697 => -0.897347)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (39274 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27042 (11.318277 vs 12.187611 => -0.869335)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (38029 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27046 (11.350204 vs 12.192275 => -0.842071)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (36843 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27050 (11.382132 vs 12.196209 => -0.814077)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (35643 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27054 (11.414059 vs 12.201005 => -0.786946)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (34401 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27058 (11.445986 vs 12.204484 => -0.758498)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (33139 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27062 (11.477914 vs 12.208863 => -0.730949)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (32098 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27066 (11.509841 vs 12.217004 => -0.707163)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (30881 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27070 (11.541769 vs 12.220926 => -0.679157)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (29710 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27074 (11.573696 vs 12.226623 => -0.652927)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (28499 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27078 (11.605624 vs 12.231096 => -0.625472)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (27293 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27082 (11.637551 vs 12.234941 => -0.597390)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (26035 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27086 (11.669478 vs 12.239430 => -0.569951)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (24855 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27090 (11.701406 vs 12.243472 => -0.542067)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (23597 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27094 (11.733333 vs 12.247647 => -0.514314)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (22387 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27098 (11.765261 vs 12.251376 => -0.486115)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (21127 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27102 (11.797188 vs 12.257066 => -0.459878)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (19981 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27106 (11.829116 vs 12.260645 => -0.431529)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (18741 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27110 (11.861043 vs 12.265450 => -0.404407)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (17533 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27114 (11.892971 vs 12.269260 => -0.376289)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (16377 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27118 (11.924898 vs 12.275113 => -0.350215)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (15147 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27122 (11.956825 vs 12.278795 => -0.321969)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (13933 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27126 (11.988753 vs 12.283743 => -0.294991)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (12728 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27130 (12.020680 vs 12.289936 => -0.269256)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (11571 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27134 (12.052608 vs 12.293437 => -0.240829)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (10310 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27138 (12.084535 vs 12.297395 => -0.212860)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (9097 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Sent 45056 frames in 0.148701s (current frames: 534336, expected: 542505)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27142 (12.116463 vs 12.303423 => -0.186960)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (8140 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27146 (12.148390 vs 12.311822 => -0.163432)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (6932 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27150 (12.180317 vs 12.317056 => -0.136738)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (5825 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27154 (12.212245 vs 12.322932 => -0.110687)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (4581 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27158 (12.244172 vs 12.326489 => -0.082317)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (3322 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27162 (12.276100 vs 12.329918 => -0.053818)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (2125 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27166 (12.308027 vs 12.336863 => -0.028836)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 2 packets (994 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27170 (12.331973 vs 12.340323 => -0.008350)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27173 (12.339955 vs 12.341299 => -0.001344)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=2296184832, RtpTime=610694, Sec=2208988815, SyncPacket=80d4000700084f2083aa7e8f88dd000000095186)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27184 (12.427755 vs 12.428599 => -0.000844)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27188 (12.459683 vs 12.461201 => -0.001518)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (366 frames behind)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27193 (12.507574 vs 12.511815 => -0.004242)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27199 (12.547483 vs 12.554672 => -0.007189)
2022-01-12 15:18:05 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27200 (12.555465 vs 12.557061 => -0.001596)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (1324 frames behind)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27250 (12.978503 vs 13.002713 => -0.024209)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Compensating with 2 packets (799 frames behind)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27254 (13.002449 vs 13.007633 => -0.005184)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27257 (13.010431 vs 13.014484 => -0.004054)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27262 (13.050340 vs 13.057592 => -0.007252)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27263 (13.058322 vs 13.058835 => -0.000513)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 0.818113s (current frames: 578688, expected: 578583)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=2252144640, RtpTime=654342, Sec=2208988816, SyncPacket=80d400070008f9a083aa7e90863d00000009fc06)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (493 frames behind)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27311 (13.449433 vs 13.456103 => -0.006670)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27313 (13.457415 vs 13.461029 => -0.003614)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27314 (13.465397 vs 13.470150 => -0.004754)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27315 (13.473379 vs 13.473739 => -0.000361)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (392 frames behind)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27321 (13.529252 vs 13.534429 => -0.005177)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27323 (13.537234 vs 13.538235 => -0.001001)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (359 frames behind)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27329 (13.593107 vs 13.597162 => -0.004055)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27331 (13.601088 vs 13.601355 => -0.000266)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27344 (13.704853 vs 13.705191 => -0.000339)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27349 (13.744762 vs 13.750053 => -0.005291)
2022-01-12 15:18:06 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27350 (13.752744 vs 13.753164 => -0.000421)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (469 frames behind)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27356 (13.808617 vs 13.814523 => -0.005906)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27358 (13.816599 vs 13.819797 => -0.003198)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27359 (13.824580 vs 13.827933 => -0.003352)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27365 (13.872472 vs 13.873617 => -0.001145)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (360 frames behind)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27370 (13.920363 vs 13.923942 => -0.003579)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27372 (13.928345 vs 13.928591 => -0.000247)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (560 frames behind)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27378 (13.984218 vs 13.995491 => -0.011274)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27380 (13.992200 vs 13.999474 => -0.007274)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27381 (14.000181 vs 14.004979 => -0.004797)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27386 (14.040091 vs 14.045029 => -0.004939)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27394 (14.103946 vs 14.106917 => -0.002971)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 0.991162s (current frames: 623040, expected: 622294)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27398 (14.135873 vs 14.138254 => -0.002381)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27402 (14.167800 vs 14.168793 => -0.000993)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27406 (14.199728 vs 14.200398 => -0.000670)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (430 frames behind)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27411 (14.247619 vs 14.253285 => -0.005666)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27413 (14.255601 vs 14.257568 => -0.001967)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (405 frames behind)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27419 (14.311474 vs 14.321259 => -0.009785)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27421 (14.319456 vs 14.325260 => -0.005805)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Compensating with 3 packets (1061 frames behind)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27422 (14.351383 vs 14.357496 => -0.006113)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27426 (14.359365 vs 14.359919 => -0.000554)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=2379546624, RtpTime=699750, Sec=2208988817, SyncPacket=80d400070009ab0083aa7e918dd50000000aad66)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27437 (14.447166 vs 14.452012 => -0.004847)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27445 (14.511020 vs 14.515044 => -0.004023)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27449 (14.542948 vs 14.545656 => -0.002708)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (408 frames behind)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27454 (14.590839 vs 14.593506 => -0.002667)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27459 (14.622766 vs 14.623595 => -0.000829)
2022-01-12 15:18:07 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27470 (14.710567 vs 14.716536 => -0.005969)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27478 (14.774422 vs 14.778450 => -0.004028)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27482 (14.806349 vs 14.808820 => -0.002470)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27486 (14.838277 vs 14.841206 => -0.002930)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27490 (14.870204 vs 14.872985 => -0.002781)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27494 (14.902132 vs 14.902912 => -0.000781)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27498 (14.934059 vs 14.935062 => -0.001003)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (360 frames behind)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27502 (14.973968 vs 14.978679 => -0.004711)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27511 (15.037823 vs 15.042641 => -0.004818)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27519 (15.101678 vs 15.105213 => -0.003535)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 1.024769s (current frames: 667392, expected: 667486)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27523 (15.133605 vs 15.136216 => -0.002611)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27527 (15.165533 vs 15.167377 => -0.001844)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27531 (15.197460 vs 15.198513 => -0.001053)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27539 (15.261315 vs 15.262497 => -0.001182)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27544 (15.301224 vs 15.308939 => -0.007715)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27545 (15.309206 vs 15.312127 => -0.002920)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=2335506432, RtpTime=743398, Sec=2208988818, SyncPacket=80d40007000a558083aa7e928b350000000b57e6)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (452 frames behind)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27552 (15.373061 vs 15.379041 => -0.005980)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27554 (15.381043 vs 15.382602 => -0.001559)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27555 (15.389025 vs 15.392490 => -0.003465)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (516 frames behind)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27573 (15.540680 vs 15.548059 => -0.007379)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27575 (15.548662 vs 15.553067 => -0.004405)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27576 (15.556644 vs 15.557357 => -0.000713)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (416 frames behind)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27583 (15.620499 vs 15.626322 => -0.005823)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27585 (15.628481 vs 15.629696 => -0.001215)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (370 frames behind)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27591 (15.684354 vs 15.689018 => -0.004664)
2022-01-12 15:18:08 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27598 (15.732245 vs 15.732864 => -0.000619)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27603 (15.772154 vs 15.779578 => -0.007424)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27604 (15.780136 vs 15.782628 => -0.002492)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27611 (15.836009 vs 15.842353 => -0.006344)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27612 (15.843991 vs 15.846080 => -0.002090)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27630 (15.987664 vs 15.990662 => -0.002998)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (522 frames behind)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27631 (16.003628 vs 16.010229 => -0.006601)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27633 (16.011610 vs 16.016443 => -0.004833)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (405 frames behind)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27638 (16.059501 vs 16.062086 => -0.002585)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27643 (16.091429 vs 16.093249 => -0.001821)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27647 (16.123356 vs 16.123773 => -0.000417)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 0.990693s (current frames: 711744, expected: 711176)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=2394357760, RtpTime=788102, Sec=2208988819, SyncPacket=80d40007000b042083aa7e938eb70000000c0686)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (497 frames behind)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27695 (16.514467 vs 16.521370 => -0.006903)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27697 (16.522449 vs 16.525301 => -0.002852)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (500 frames behind)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27703 (16.578322 vs 16.589968 => -0.011646)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (353 frames behind)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27705 (16.594286 vs 16.599167 => -0.004881)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27707 (16.602268 vs 16.603406 => -0.001139)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (373 frames behind)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27713 (16.658141 vs 16.663017 => -0.004876)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27715 (16.666122 vs 16.666690 => -0.000568)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27721 (16.714014 vs 16.720977 => -0.006964)
2022-01-12 15:18:09 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27722 (16.721995 vs 16.725544 => -0.003549)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27729 (16.777868 vs 16.783433 => -0.005565)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27730 (16.785850 vs 16.787296 => -0.001446)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27735 (16.825760 vs 16.830933 => -0.005174)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27736 (16.833741 vs 16.838633 => -0.004891)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27737 (16.841723 vs 16.842462 => -0.000739)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (506 frames behind)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27742 (16.889615 vs 16.897494 => -0.007879)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27744 (16.897596 vs 16.901525 => -0.003929)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27745 (16.905578 vs 16.905820 => -0.000242)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (651 frames behind)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27754 (16.985397 vs 16.995789 => -0.010392)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (387 frames behind)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27756 (17.001361 vs 17.007771 => -0.006411)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27758 (17.009342 vs 17.010033 => -0.000690)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27762 (17.041270 vs 17.048181 => -0.006911)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27763 (17.049252 vs 17.049474 => -0.000222)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27770 (17.105125 vs 17.108804 => -0.003679)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27774 (17.137052 vs 17.140697 => -0.003645)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 1.015574s (current frames: 756096, expected: 755962)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27782 (17.200907 vs 17.204068 => -0.003161)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27790 (17.264762 vs 17.266817 => -0.002055)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (387 frames behind)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27795 (17.312653 vs 17.315858 => -0.003205)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27797 (17.320635 vs 17.320814 => -0.000179)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=2316042240, RtpTime=831398, Sec=2208988820, SyncPacket=80d40007000bad4083aa7e948a0c0000000cafa6)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27802 (17.360544 vs 17.362290 => -0.001746)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27807 (17.400454 vs 17.407931 => -0.007477)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27808 (17.408435 vs 17.410494 => -0.002059)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (496 frames behind)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27830 (17.592018 vs 17.598203 => -0.006184)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27832 (17.600000 vs 17.603384 => -0.003384)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (472 frames behind)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27838 (17.655873 vs 17.661729 => -0.005856)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27840 (17.663855 vs 17.666131 => -0.002276)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (432 frames behind)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27846 (17.719728 vs 17.724624 => -0.004896)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27848 (17.727710 vs 17.729782 => -0.002073)
2022-01-12 15:18:10 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27849 (17.735692 vs 17.737666 => -0.001974)
2022-01-12 15:18:11 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27855 (17.783583 vs 17.785443 => -0.001860)
2022-01-12 15:18:11 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27860 (17.823492 vs 17.830371 => -0.006879)
2022-01-12 15:18:11 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27861 (17.831474 vs 17.833147 => -0.001673)
2022-01-12 15:18:11 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (688 frames behind)
2022-01-12 15:18:11 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27879 (17.983129 vs 18.012710 => -0.029580)
2022-01-12 15:18:11 DEBUG [pyatv.protocols.raop.raop]: Compensating with 2 packets (1032 frames behind)
2022-01-12 15:18:11 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27881 (18.007075 vs 18.023257 => -0.016182)
2022-01-12 15:18:11 DEBUG [pyatv.protocols.raop.raop]: Compensating with 1 packets (475 frames behind)
2022-01-12 15:18:11 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27884 (18.023039 vs 18.028330 => -0.005291)
2022-01-12 15:18:11 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27890 (18.062948 vs 18.063921 => -0.000973)
2022-01-12 15:18:11 DEBUG [pyatv.protocols.raop.raop]: Too slow to keep up for seqno 27894 (18.094875 vs 18.095574 => -0.000699)
2022-01-12 15:18:11 DEBUG [pyatv.protocols.raop.raop]: Sent 44352 frames in 0.987034s (current frames: 800448, expected: 799491)
2022-01-12 15:18:11 DEBUG [pyatv.protocols.raop.raop]: Sending sync packet (Frac=2340552704, RtpTime=875750, Sec=2208988821, SyncPacket=80d40007000c5a8083aa7e958b820000000d5ce6)
2022-01-12 15:18:11 DEBUG [pyatv.protocols.raop.raop]: Audio finished sending in 18.446810s
2022-01-12 15:18:11 DEBUG [pyatv.support.http]: Sending RTSP/1.0 message: b'TEARDOWN rtsp://192.168.1.84/366228931 RTSP/1.0\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 8\r\nDACP-ID: 272B3B54F5501B24\r\nActive-Remote: 622972739\r\nClient-Instance: 272B3B54F5501B24\r\nSession: DEADBEEF\r\n\r\n'
2022-01-12 15:18:11 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 200 OK\r\nDate: Thu, 01 Jan 1970 22:45:33 +0000\r\nConnection: close\r\nServer: AirTunes/220.68\r\nCSeq: 8\r\n\r\n'
2022-01-12 15:18:11 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Thu, 01 Jan 1970 22:45:33 +0000', 'connection': 'close', 'server': 'AirTunes/220.68', 'cseq': '8'}, body=''):
2022-01-12 15:18:11 DEBUG [pyatv.core.facade]: Release (<class 'pyatv.interface.Audio'>, <class 'pyatv.interface.Metadata'>, <class 'pyatv.interface.PushUpdater'>, <class 'pyatv.interface.RemoteControl'>) by Protocol.RAOP
postlund commented 2 years ago

Empty response sounds good in this case (homeseer does not fetch this file so we don't see this error there). So, hopefully the final change I need you to verify is changing the same line as before to this again:

print("INFO:", await self.rtsp.exchange("GET", "/info"))

But also open pyatv/support/rtsp.py and make this change at line 261:

protocol="HTTP/1.0",

Basically change RTSP to HTTP and then try again. Hopefully the command will fail with an error now instead of timeout. This might break streaming but that's ok.

malosaa commented 2 years ago

Empty response sounds good in this case (homeseer does not fetch this file so we don't see this error there). So, hopefully the final change I need you to verify is changing the same line as before to this again:

print("INFO:", await self.rtsp.exchange("GET", "/info"))

But also open pyatv/support/rtsp.py and make this change at line 261:

protocol="HTTP/1.0",

Basically change RTSP to HTTP and then try again. Hopefully the command will fail with an error now instead of timeout. This might break streaming but that's ok.

When i change line 261 in rtsp.py it still shows this : HttpResponse(protocol='RTSP') for some reason it stays rtsp and no http protocol

and when changing to print("INFO:", await self.rtsp.exchange("GET", "/info")) i get error 

$ atvremote -s 192.168.1.54 stream_file=https://www.myinstants.com/media/sounds/epic.mp3
Traceback (most recent call last):
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.2544.0_x64__qbz5n2kfra8p0\lib\asyncio\locks.py", line 226, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.2544.0_x64__qbz5n2kfra8p0\lib\asyncio\tasks.py", line 492, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

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

Traceback (most recent call last):
  File "c:\users\31683\pyatv\pyatv\support\rtsp.py", line 281, in exchange
    await asyncio.wait_for(self.requests[cseq][0].wait(), 4)
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.2544.0_x64__qbz5n2kfra8p0\lib\asyncio\tasks.py", line 494, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

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

Traceback (most recent call last):
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 719, in _run_application
    return await cli_handler(loop)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 513, in cli_handler
    return await _handle_commands(args, config, loop)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 614, in _handle_commands
    ret = await _handle_device_command(args, cmd, atv, loop)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 662, in _handle_device_command
    return await _exec_command(atv.stream, cmd, True, *cmd_args)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 685, in _exec_command
    value = await tmp(*args)
  File "c:\users\31683\pyatv\pyatv\core\facade.py", line 382, in stream_file
    await self.relay("stream_file")(file, **kwargs)
  File "c:\users\31683\pyatv\pyatv\protocols\raop\__init__.py", line 348, in stream_file
    await client.initialize(self.core.service.properties)
  File "c:\users\31683\pyatv\pyatv\protocols\raop\raop.py", line 454, in initialize
    print("INFO:", await self.rtsp.exchange("GET", "/info"))
  File "c:\users\31683\pyatv\pyatv\support\rtsp.py", line 284, in exchange
    raise TimeoutError(
TimeoutError: no response to CSeq 0 (/info)

>>> An error occurred, full stack trace above
(venv)
Samantha@LAPTOP-QNI7CTOT MINGW64 ~/pyatv (master)
$ atvremote -s 192.168.1.54 stream_file=https://www.myinstants.com/media/sounds/epic.mp3
OPTIONS: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Fri, 02 Jan 1970 16:35:31 +0000', 'public': 'ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER, POST, GET', 'server': 'AirTunes/220.68', 'cseq': '0'}, body='')
(venv)
Samantha@LAPTOP-QNI7CTOT MINGW64 ~/pyatv (master)
$ atvremote -s 192.168.1.54 stream_file=https://www.myinstants.com/media/sounds/epic.mp3
OPTIONS: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'date': 'Fri, 02 Jan 1970 16:38:35 +0000', 'public': 'ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER, POST, GET', 'server': 'AirTunes/220.68', 'cseq': '0'}, body='')
(venv)
Samantha@LAPTOP-QNI7CTOT MINGW64 ~/pyatv (master)
$ atvremote -s 192.168.1.54 stream_file=https://www.myinstants.com/media/sounds/epic.mp3
Traceback (most recent call last):
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.2544.0_x64__qbz5n2kfra8p0\lib\asyncio\locks.py", line 226, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.2544.0_x64__qbz5n2kfra8p0\lib\asyncio\tasks.py", line 492, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

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

Traceback (most recent call last):
  File "c:\users\31683\pyatv\pyatv\support\rtsp.py", line 281, in exchange
    await asyncio.wait_for(self.requests[cseq][0].wait(), 4)
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.2544.0_x64__qbz5n2kfra8p0\lib\asyncio\tasks.py", line 494, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

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

Traceback (most recent call last):
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 719, in _run_application
    return await cli_handler(loop)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 513, in cli_handler
    return await _handle_commands(args, config, loop)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 614, in _handle_commands
    ret = await _handle_device_command(args, cmd, atv, loop)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 662, in _handle_device_command
    return await _exec_command(atv.stream, cmd, True, *cmd_args)
  File "c:\users\31683\pyatv\pyatv\scripts\atvremote.py", line 685, in _exec_command
    value = await tmp(*args)
  File "c:\users\31683\pyatv\pyatv\core\facade.py", line 382, in stream_file
    await self.relay("stream_file")(file, **kwargs)
  File "c:\users\31683\pyatv\pyatv\protocols\raop\__init__.py", line 348, in stream_file
    await client.initialize(self.core.service.properties)
  File "c:\users\31683\pyatv\pyatv\protocols\raop\raop.py", line 454, in initialize
    print("INFO:", await self.rtsp.exchange("GET", "/info"))
  File "c:\users\31683\pyatv\pyatv\support\rtsp.py", line 284, in exchange
    raise TimeoutError(
TimeoutError: no response to CSeq 0 (/info)
postlund commented 2 years ago

That is still so weird. Let's try a regular client. What happens if you run this snippet:

import aiohttp
import asyncio

async def main():
    async with aiohttp.ClientSession() as session:
        async with session.get("http://192.168.1.54:47000/info") as resp:
            print(resp)

asyncio.run(main())
malosaa commented 2 years ago

yeah it is,

how do i run this, and where do i need to place it

regards

postlund commented 2 years ago

Save it as a file somewhere, e.g. foobar.py and then run python3 foobar.py. You need aiohttp, so if you run it the same way you ran atvremote before you should be fine (same virtual environment or what you are using).

malosaa commented 2 years ago

Save it as a file somewhere, e.g. foobar.py and then run python3 foobar.py. You need aiohttp, so if you run it the same way you ran atvremote before you should be fine (same virtual environment or what you are using).

i put it in that environment, and aiohttp is already satisfied, but still cant find the package.. its in \pyatv\venv\Lib\site-packages Cant get it to work 

$ python3 test.py
Traceback (most recent call last):
  File "C:\Users\31683\pyatv\pyatv\test.py", line 1, in <module>
    import aiohttp
ModuleNotFoundError: No module named 'aiohttp'
(venv)
$ pip show aiohttp
Name: aiohttp
Version: 3.8.1
Summary: Async http client/server framework (asyncio)
Home-page: https://github.com/aio-libs/aiohttp
Author:
Author-email:
License: Apache 2
Location: c:\users\31683\pyatv\venv\lib\site-packages
Requires: multidict, charset-normalizer, yarl, frozenlist, aiosignal, attrs, async-timeout
Required-by: pytest-aiohttp, pyatv
(venv)
postlund commented 2 years ago

That's strange. If you try installing it (pip install aiohttp), does that make any difference?

malosaa commented 2 years ago

st.py

hi, sorry for the late reply.

when i do that it says its already satisfied when i use pip show :

pytest-aiohttp is the snippet we created to run.

when i run python3 test.py (thats the snippet)

$ python3 test.py
Traceback (most recent call last):
  File "C:\Users\31683\pyatv\pyatv\test.py", line 1, in <module>
    import aiohttp
ModuleNotFoundError: No module named 'aiohttp'
(venv)

$ pip show aiohttp
Name: aiohttp
Version: 3.8.1
Summary: Async http client/server framework (asyncio)
Home-page: https://github.com/aio-libs/aiohttp
Author:
Author-email:
License: Apache 2
Location: c:\users\31683\pyatv\venv\lib\site-packages
Requires: attrs, frozenlist, multidict, yarl, charset-normalizer, aiosignal, async-timeout
Required-by: pytest-aiohttp, pyatv
(venv)
postlund commented 2 years ago

Shouldn't make any difference, but is it the same if you run with just python and not python3?

malosaa commented 2 years ago

Shouldn't make any difference, but is it the same if you run with just python and not python3?

i recreated the environment, and it worked, bud sadly i get a http error the client is still on 192.168.1.54 and i can access it

$ python test.py
Traceback (most recent call last):
  File "C:\Users\31683\pyatv\venv\lib\site-packages\aiohttp\client_reqrep.py", line 898, in start
    message, payload = await protocol.read()  # type: ignore[union-attr]
  File "C:\Users\31683\pyatv\venv\lib\site-packages\aiohttp\streams.py", line 616, in read
    await self._waiter
  File "C:\Users\31683\pyatv\venv\lib\site-packages\aiohttp\client_proto.py", line 213, in data_received
    messages, upgraded, tail = self._parser.feed_data(data)
  File "aiohttp\_http_parser.pyx", line 551, in aiohttp._http_parser.HttpParser.feed_data
aiohttp.http_exceptions.BadHttpMessage: 400, message='Expected HTTP/'

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

Traceback (most recent call last):
  File "C:\Users\31683\pyatv\pyatv\test.py", line 9, in <module>
    asyncio.run(main())
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.2544.0_x64__qbz5n2kfra8p0\lib\asyncio\runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "C:\Program Files\WindowsApps\PythonSoftwareFoundation.Python.3.9_3.9.2544.0_x64__qbz5n2kfra8p0\lib\asyncio\base_events.py", line 642, in run_until_complete
    return future.result()
  File "C:\Users\31683\pyatv\pyatv\test.py", line 6, in main
    async with session.get("http://192.168.1.54:47000/info") as resp:
  File "C:\Users\31683\pyatv\venv\lib\site-packages\aiohttp\client.py", line 1138, in __aenter__
    self._resp = await self._coro
  File "C:\Users\31683\pyatv\venv\lib\site-packages\aiohttp\client.py", line 559, in _request
    await resp.start(conn)
  File "C:\Users\31683\pyatv\venv\lib\site-packages\aiohttp\client_reqrep.py", line 900, in start
    raise ClientResponseError(
aiohttp.client_exceptions.ClientResponseError: 400, message='Expected HTTP/', url=URL('http://192.168.1.54:47000/info')
(venv)
malosaa commented 2 years ago

i scanned the ports,

7000 =afs3-file server 80 = http 5000 upnp 7001 afs3 callback 7100 font-service

postlund commented 2 years ago

That error is exactly what I needed to see, I think I can come up with a solution now.

postlund commented 2 years ago

@malosaa Before moving on, can you try if #1616 works for you?

malosaa commented 2 years ago

That error is exactly what I needed to see, I think I can come up with a solution now.

thanks lets hope you cn fix it

regards