postlund / pyatv

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

Shairport-sync TimeoutError: no response to CSeq 0 (/info) #1822

Closed KuzmaTolyanuch closed 1 year ago

KuzmaTolyanuch commented 2 years ago

Describe the bug

Hi, I'm facing an issue when trying to play audio from HA to Shairport-sync devices. I have two devices with Shairport-sync installed (Rapsberry Pi 4B - Debian buster, Orange Pi Zero 2 - Debian Bullseye) and HA doesn't work with both. I was able to add device to HA, streaming from apple devices work fine. Streaming to other Airplay devices (Homepod, AirPort) from HA works fine as well. I tried to use multiple versions of Shairport-sync - stable, development, the error seems to be the same for all.

Error log

log

atvremote --debug -s 192.168.92.51 stream_file=http://192.168.100.100:8043/tol-utopiya.mp3
2022-08-11 09:34:28 DEBUG [pyatv.scripts]: Running with pyatv 0.10.3
2022-08-11 09:34:28 DEBUG [pyatv.support.knock]: Knocking at port 3689 on 192.168.92.51
2022-08-11 09:34:28 DEBUG [pyatv.support.knock]: Knocking at port 7000 on 192.168.92.51
2022-08-11 09:34:28 DEBUG [pyatv.support.knock]: Knocking at port 49152 on 192.168.92.51
2022-08-11 09:34:28 DEBUG [pyatv.support.knock]: Knocking at port 32498 on 192.168.92.51
2022-08-11 09:34:29 DEBUG [pyatv.core.scan]: Auto-discovered OrangePlay at 192.168.92.51:7000 via Protocol.AirPlay ({'srcvers': '366.0', 'deviceid': '02:42:c0:a8:5c:33', 'features': '0x405FCA00,0x1C340', 'flags': '0x4', 'protovers': '1.1', 'acl': '0', 'rsf': '0x0', 'fv': '4.1-dev-441-g6a2ba5fd-dirty', 'model': 'Shairport Sync', 'pi': 'ef4cf821-e043-46e4-b9fb-0b8f9a5f786d', 'gid': 'ef4cf821-e043-46e4-b9fb-0b8f9a5f786d', 'gcgl': '0', 'pk': '0e9248fda868e0d60064248e562d54ff3008b81769632361f16e34e494e5154d'})
2022-08-11 09:34:29 DEBUG [pyatv.core.scan]: Auto-discovered 0242C0A85C33@OrangePlay at 192.168.92.51:7000 via Protocol.RAOP ({'cn': '0,1', 'da': 'true', 'et': '0,4', 'ft': '0x405FCA00,0x1C340', 'fv': '4.1-dev-441-g6a2ba5fd-dirty', 'md': '2', 'am': 'Shairport Sync', 'sf': '0x4', 'tp': 'UDP', 'vn': '65537', 'vs': '366.0', 'pk': '0e9248fda868e0d60064248e562d54ff3008b81769632361f16e34e494e5154d'})
2022-08-11 09:34:29 INFO [pyatv.scripts.atvremote]: Auto-discovered OrangePlay at 192.168.92.51
2022-08-11 09:34:29 DEBUG [pyatv.core.facade]: Adding handler for protocol Protocol.AirPlay
2022-08-11 09:34:29 DEBUG [pyatv.protocols.airplay]: Remote control not supported by device
2022-08-11 09:34:29 DEBUG [pyatv.core.facade]: Adding handler for protocol Protocol.RAOP
2022-08-11 09:34:29 DEBUG [pyatv.core.facade]: Connecting to protocol: Protocol.AirPlay
2022-08-11 09:34:29 DEBUG [pyatv.core.facade]: Connected to protocol: Protocol.AirPlay
2022-08-11 09:34:29 DEBUG [pyatv.core.facade]: Connecting to protocol: Protocol.RAOP
2022-08-11 09:34:29 DEBUG [pyatv.core.facade]: Connected to protocol: Protocol.RAOP
2022-08-11 09:34:29 DEBUG [pyatv.core.facade]: Power management not supported by any protocols
2022-08-11 09:34:29 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-08-11 09:34:29 DEBUG [pyatv.support.http]: Connected to 192.168.92.51
2022-08-11 09:34:29 DEBUG [pyatv.protocols.raop.raop]: Initializing RTSP with encryption=EncryptionType.MFiSAP|Unencrypted, metadata=MetadataType.Progress
2022-08-11 09:34:29 DEBUG [pyatv.protocols.raop.raop]: Update play settings to 44100/2/16bit
2022-08-11 09:34:29 DEBUG [pyatv.protocols.raop.raop]: Local ports: control=39388, timing=40477
2022-08-11 09:34:29 DEBUG [pyatv.support.http]: Sending HTTP/1.1 message: b'GET /info HTTP/1.1\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 0\r\nDACP-ID: 804679E1A3281A6E\r\nActive-Remote: 3071325032\r\nClient-Instance: 804679E1A3281A6E\r\n\r\n'
2022-08-11 09:34:29 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 400 Bad Request\r\nServer: AirTunes/105.1\r\n\r\n'
2022-08-11 09:34:29 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=400, message='Bad Request', headers={'server': 'AirTunes/105.1'}, body=''):
2022-08-11 09:34:33 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-08-11 09:34:33 DEBUG [pyatv.scripts.atvremote]: Waiting for 0 remaining tasks
2022-08-11 09:34:33 DEBUG [pyatv.protocols.raop.raop]: Control connection lost (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/pyatv/support/rtsp.py", line 289, in exchange
    await self.requests[cseq][0].wait()
  File "/usr/local/lib/python3.10/asyncio/locks.py", line 214, 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.10/site-packages/pyatv/support/rtsp.py", line 288, in exchange
    async with async_timeout.timeout(4):
  File "/usr/local/lib/python3.10/site-packages/async_timeout/__init__.py", line 129, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.10/site-packages/async_timeout/__init__.py", line 212, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/pyatv/scripts/atvremote.py", line 717, in _run_application
    return await cli_handler(loop)
  File "/usr/local/lib/python3.10/site-packages/pyatv/scripts/atvremote.py", line 511, in cli_handler
    return await _handle_commands(args, config, loop)
  File "/usr/local/lib/python3.10/site-packages/pyatv/scripts/atvremote.py", line 612, in _handle_commands
    ret = await _handle_device_command(args, cmd, atv, loop)
  File "/usr/local/lib/python3.10/site-packages/pyatv/scripts/atvremote.py", line 660, in _handle_device_command
    return await _exec_command(atv.stream, cmd, True, *cmd_args)
  File "/usr/local/lib/python3.10/site-packages/pyatv/scripts/atvremote.py", line 683, in _exec_command
    value = await tmp(*args)
  File "/usr/local/lib/python3.10/site-packages/pyatv/core/facade.py", line 392, in stream_file
    await self.relay("stream_file")(file, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/pyatv/protocols/raop/__init__.py", line 352, in stream_file
    await client.initialize(self.core.service.properties)
  File "/usr/local/lib/python3.10/site-packages/pyatv/protocols/raop/raop.py", line 453, in initialize
    self._info.update(await self.rtsp.info())
  File "/usr/local/lib/python3.10/site-packages/pyatv/support/rtsp.py", line 101, in info
    device_info = await self.exchange(
  File "/usr/local/lib/python3.10/site-packages/pyatv/support/rtsp.py", line 292, in exchange
    raise TimeoutError(
TimeoutError: no response to CSeq 0 (/info)

>>> An error occurred, full stack trace above

How to reproduce the bug?

What is expected behavior?

playing audio should work fine

Operating System

Home Assistant - Rapsberry Pi 4B - Debian buster,

Shairport-sync 1 - Orange Pi Zero 2 - Debian Bullseye,

Shairport-sync 2 - Rapsberry Pi 4B - Debian buster

Python

3.10

pyatv

0.10.3

Device

Shairport-sync

Additional context

Home Assistant version 2022.8.2

KuzmaTolyanuch commented 2 years ago

Call service yaml works fine with other AirPlay devices

service: media_player.play_media
data:
  media_content_id: http://192.168.100.100:8043/tol-utopiya.mp3
  media_content_type: music
target:
  entity_id: media_player.orangeplay

HA log when call service failed

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/pyatv/support/rtsp.py", line 289, in exchange
    await self.requests[cseq][0].wait()
  File "/usr/local/lib/python3.10/asyncio/locks.py", line 214, 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.10/site-packages/pyatv/support/rtsp.py", line 288, in exchange
    async with async_timeout.timeout(4):
  File "/usr/local/lib/python3.10/site-packages/async_timeout/__init__.py", line 129, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.10/site-packages/async_timeout/__init__.py", line 212, in _do_exit
    raise asyncio.TimeoutError
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 199, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1713, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1750, in _execute_service
    await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 204, in handle_service
    await service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 676, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 930, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 713, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/apple_tv/media_player.py", line 298, in async_play_media
    await self.atv.stream.stream_file(media_id)
  File "/usr/local/lib/python3.10/site-packages/pyatv/core/facade.py", line 392, in stream_file
    await self.relay("stream_file")(file, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/pyatv/protocols/raop/__init__.py", line 352, in stream_file
    await client.initialize(self.core.service.properties)
  File "/usr/local/lib/python3.10/site-packages/pyatv/protocols/raop/raop.py", line 453, in initialize
    self._info.update(await self.rtsp.info())
  File "/usr/local/lib/python3.10/site-packages/pyatv/support/rtsp.py", line 101, in info
    device_info = await self.exchange(
  File "/usr/local/lib/python3.10/site-packages/pyatv/support/rtsp.py", line 292, in exchange
    raise TimeoutError(
TimeoutError: no response to CSeq 0 (/info)

atvremote debug log with raop

atvremote --debug -s 192.168.92.51 --scan-protocols raop stream_file=http://192.168.100.100:8043/tol-utopiya.mp3
2022-08-11 08:39:58 DEBUG [pyatv.scripts]: Running with pyatv 0.10.3
2022-08-11 08:39:58 DEBUG [pyatv.support.knock]: Knocking at port 3689 on 192.168.92.51
2022-08-11 08:39:58 DEBUG [pyatv.support.knock]: Knocking at port 7000 on 192.168.92.51
2022-08-11 08:39:58 DEBUG [pyatv.support.knock]: Knocking at port 49152 on 192.168.92.51
2022-08-11 08:39:58 DEBUG [pyatv.support.knock]: Knocking at port 32498 on 192.168.92.51
2022-08-11 08:39:59 DEBUG [pyatv.core.scan]: Auto-discovered 0242C0A85C33@OrangePlay at 192.168.92.51:7000 via Protocol.RAOP ({'cn': '0,1', 'da': 'true', 'et': '0,4', 'ft': '0x405FCA00,0x1C340', 'fv': '4.1-dev-441-g6a2ba5fd-dirty', 'md': '2', 'am': 'Shairport Sync', 'sf': '0x4', 'tp': 'UDP', 'vn': '65537', 'vs': '366.0', 'pk': '0e9248fda868e0d60064248e562d54ff3008b81769632361f16e34e494e5154d'})
2022-08-11 08:39:59 INFO [pyatv.scripts.atvremote]: Auto-discovered OrangePlay at 192.168.92.51
2022-08-11 08:39:59 DEBUG [pyatv.core.facade]: Adding handler for protocol Protocol.RAOP
2022-08-11 08:39:59 DEBUG [pyatv.core.facade]: Connecting to protocol: Protocol.RAOP
2022-08-11 08:39:59 DEBUG [pyatv.core.facade]: Connected to protocol: Protocol.RAOP
2022-08-11 08:39:59 DEBUG [pyatv.core.facade]: Power management not supported by any protocols
2022-08-11 08:39:59 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-08-11 08:39:59 DEBUG [pyatv.support.http]: Connected to 192.168.92.51
2022-08-11 08:39:59 DEBUG [pyatv.protocols.raop.raop]: Initializing RTSP with encryption=EncryptionType.MFiSAP|Unencrypted, metadata=MetadataType.Progress
2022-08-11 08:39:59 DEBUG [pyatv.protocols.raop.raop]: Update play settings to 44100/2/16bit
2022-08-11 08:39:59 DEBUG [pyatv.protocols.raop.raop]: Local ports: control=32968, timing=33846
2022-08-11 08:39:59 DEBUG [pyatv.support.http]: Sending HTTP/1.1 message: b'GET /info HTTP/1.1\r\nUser-Agent: AirPlay/540.31\r\nCSeq: 0\r\nDACP-ID: B2994A024C63247A\r\nActive-Remote: 1370728575\r\nClient-Instance: B2994A024C63247A\r\n\r\n'
2022-08-11 08:39:59 DEBUG [pyatv.support.http]: Received: b'RTSP/1.0 400 Bad Request\r\nServer: AirTunes/105.1\r\n\r\n'
2022-08-11 08:39:59 DEBUG [pyatv.support.http]: Got RTSP response: HttpResponse(protocol='RTSP', version='1.0', code=400, message='Bad Request', headers={'server': 'AirTunes/105.1'}, body=''):
2022-08-11 08:40:03 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-08-11 08:40:03 DEBUG [pyatv.scripts.atvremote]: Waiting for 0 remaining tasks
2022-08-11 08:40:03 DEBUG [pyatv.protocols.raop.raop]: Control connection lost (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/pyatv/support/rtsp.py", line 289, in exchange
    await self.requests[cseq][0].wait()
  File "/usr/local/lib/python3.10/asyncio/locks.py", line 214, 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.10/site-packages/pyatv/support/rtsp.py", line 288, in exchange
    async with async_timeout.timeout(4):
  File "/usr/local/lib/python3.10/site-packages/async_timeout/__init__.py", line 129, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.10/site-packages/async_timeout/__init__.py", line 212, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/pyatv/scripts/atvremote.py", line 717, in _run_application
    return await cli_handler(loop)
  File "/usr/local/lib/python3.10/site-packages/pyatv/scripts/atvremote.py", line 511, in cli_handler
    return await _handle_commands(args, config, loop)
  File "/usr/local/lib/python3.10/site-packages/pyatv/scripts/atvremote.py", line 612, in _handle_commands
    ret = await _handle_device_command(args, cmd, atv, loop)
  File "/usr/local/lib/python3.10/site-packages/pyatv/scripts/atvremote.py", line 660, in _handle_device_command
    return await _exec_command(atv.stream, cmd, True, *cmd_args)
  File "/usr/local/lib/python3.10/site-packages/pyatv/scripts/atvremote.py", line 683, in _exec_command
    value = await tmp(*args)
  File "/usr/local/lib/python3.10/site-packages/pyatv/core/facade.py", line 392, in stream_file
    await self.relay("stream_file")(file, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/pyatv/protocols/raop/__init__.py", line 352, in stream_file
    await client.initialize(self.core.service.properties)
  File "/usr/local/lib/python3.10/site-packages/pyatv/protocols/raop/raop.py", line 453, in initialize
    self._info.update(await self.rtsp.info())
  File "/usr/local/lib/python3.10/site-packages/pyatv/support/rtsp.py", line 101, in info
    device_info = await self.exchange(
  File "/usr/local/lib/python3.10/site-packages/pyatv/support/rtsp.py", line 292, in exchange
    raise TimeoutError(
TimeoutError: no response to CSeq 0 (/info)

>>> An error occurred, full stack trace above
KuzmaTolyanuch commented 2 years ago

Just checked pyatv v0.9.8 is working fine with shairport-sync devices. All newer versions (tested on 0.10.3, 0.10.2, 0.10.1, 0.10.0) have the same error

a1ex4 commented 1 year ago

Tested with current shairport-sync 4.2, the bug is happening since tag v0.10.0, because of the added HTTP_PROTOCOL in the info/exchange request.

When removing the protocol specification everything works as expected with shairport-sync 4.2