search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.03k stars 567 forks source link

3.2RC10 hangs with Synology AudioStation/5.2 [Fixed] #710

Closed joerg-krause closed 5 years ago

joerg-krause commented 6 years ago

Hi, while version 3.1.7 is running fine with my Synology NAS (Audio Station 6.4.1-3322) the latest 3.2RC10 and the development branch are not.

This is the log for 3.2RC10:

New RTSP connection from 192.168.1.118:58661 to self at 192.168.1.136:5000 on conversation thread 1.
Successfully created RTSP receiver thread 1.
    CSeq: 1.
    User-Agent: AudioStation/5.2 (Synology).
    Client-Instance: 00113288927D6015.
    DACP-ID: 00113288927D6015.
    Active-Remote: 0000000000006015.
RTSP thread 1 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "1"
  Type: "User-Agent", content: "AudioStation/5.2 (Synology)"
  Type: "Client-Instance", content: "00113288927D6015"
  Type: "DACP-ID", content: "00113288927D6015"
  Type: "Active-Remote", content: "0000000000006015"
Connection 1: OPTIONS
RTSP thread 1: RTSP Response:
  Type: "CSeq", content: "1"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
    CSeq: 2.
    User-Agent: AudioStation/5.2 (Synology).
    Client-Instance: 00113288927D6015.
    DACP-ID: 00113288927D6015.
    Active-Remote: 0000000000006015.
    Content-Length: 184.
    Content-Type: application/sdp.
RTSP thread 1 received an RTSP Packet of type "ANNOUNCE":
  Type: "CSeq", content: "2"
  Type: "User-Agent", content: "AudioStation/5.2 (Synology)"
  Type: "Client-Instance", content: "00113288927D6015"
  Type: "DACP-ID", content: "00113288927D6015"
  Type: "Active-Remote", content: "0000000000006015"
  Type: "Content-Length", content: "184"
  Type: "Content-Type", content: "application/sdp"
Connection 1: ANNOUNCE
RTSP conversation thread 1 has acquired play lock.
Play connection from user agent "AudioStation/5.2 (Synology)" on RTSP conversation thread 1.
RTSP thread 1: RTSP Response:
  Type: "CSeq", content: "2"
  Type: "Server", content: "AirTunes/105.1"
rtsp_read_request_response_read_error 104: "Connection reset by peer".
Synchronously terminate playing thread of RTSP conversation thread 1.
player thread of RTSP conversation 1 is already deleted.
Successful termination of playing thread of RTSP conversation thread 1.
Request termination of RTSP conversation thread 1.
Unlocking play lock on RTSP conversation thread 1.
RTSP conversation thread 1 terminated.

This is the log for version 3.1.7:

New RTSP connection from 192.168.1.118:58899 to self at 192.168.1.136:5000 on conversation thread 0.
Successfully created RTSP receiver thread 0.
    CSeq: 1.
    User-Agent: AudioStation/5.2 (Synology).
    Client-Instance: 00113288927D6013.
    DACP-ID: 00113288927D6013.
    Active-Remote: 0000000000006013.
RTSP thread 0 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "1"
  Type: "User-Agent", content: "AudioStation/5.2 (Synology)"
  Type: "Client-Instance", content: "00113288927D6013"
  Type: "DACP-ID", content: "00113288927D6013"
  Type: "Active-Remote", content: "0000000000006013"
Connection 0: OPTIONS
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "1"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
    CSeq: 2.
    User-Agent: AudioStation/5.2 (Synology).
    Client-Instance: 00113288927D6013.
    DACP-ID: 00113288927D6013.
    Active-Remote: 0000000000006013.
    Content-Length: 183.
    Content-Type: application/sdp.
RTSP thread 0 received an RTSP Packet of type "ANNOUNCE":
  Type: "CSeq", content: "2"
  Type: "User-Agent", content: "AudioStation/5.2 (Synology)"
  Type: "Client-Instance", content: "00113288927D6013"
  Type: "DACP-ID", content: "00113288927D6013"
  Type: "Active-Remote", content: "0000000000006013"
  Type: "Content-Length", content: "183"
  Type: "Content-Type", content: "application/sdp"
Connection 0: ANNOUNCE
RTSP conversation thread 0 has acquired play lock.
Play connection from user agent "AudioStation/5.2 (Synology)" on RTSP conversation thread 0.
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "2"
  Type: "Server", content: "AirTunes/105.1"
    CSeq: 3.
    User-Agent: AudioStation/5.2 (Synology).
    Client-Instance: 00113288927D6013.
    DACP-ID: 00113288927D6013.
    Active-Remote: 0000000000006013.
    Transport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002.
RTSP thread 0 received an RTSP Packet of type "SETUP":
  Type: "CSeq", content: "3"
  Type: "User-Agent", content: "AudioStation/5.2 (Synology)"
  Type: "Client-Instance", content: "00113288927D6013"
  Type: "DACP-ID", content: "00113288927D6013"
  Type: "Active-Remote", content: "0000000000006013"
  Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002"
Connection 0: SETUP
Active-Remote string seen: "0000000000006013".
DACP-ID string seen: "00113288927D6013".
Unrecognised User-Agent. Using latency of -1 frames.
rtp_setup: cport=6001 tport=6002.
Set up play connection from 192.168.1.118 to self at 192.168.1.136 on RTSP conversation thread 0.
listening for audio, control and timing on ports 6001, 6002, 6003.
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "3"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6002;timing_port=6003;server_port=6001"
  Type: "Session", content: "1"
    CSeq: 4.
    User-Agent: AudioStation/5.2 (Synology).
    Client-Instance: 00113288927D6013.
    DACP-ID: 00113288927D6013.
    Active-Remote: 0000000000006013.
    Session: 1.
    Range: npt=0.
    RTP-Info: seq=5164;rtptime=558448417.
RTSP thread 0 received an RTSP Packet of type "RECORD":
  Type: "CSeq", content: "4"
  Type: "User-Agent", content: "AudioStation/5.2 (Synology)"
  Type: "Client-Instance", content: "00113288927D6013"
  Type: "DACP-ID", content: "00113288927D6013"
  Type: "Active-Remote", content: "0000000000006013"
  Type: "Session", content: "1"
  Type: "Range", content: "npt=0"
  Type: "RTP-Info", content: "seq=5164;rtptime=558448417"
Connection 0: RECORD
Flush requested up to 558448416. It seems as if 0 is special.
Output frame bytes is 4.
Output bit depth is 16.
Dithering will be enabled because the output volume is being altered in software
Timing receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Audio receiver -- Server RTP thread starting.
Timing sender thread starting.
Set initial volume to -18.000000.
Setting volume db to -1989.000000.
Open Mixer
Mixer device name is "softvol".
Mixer Control name is "Master".
(Browser) NEW: service 'iTunes_Ctrl_00113288927D6015' of type '_dacp._tcp' in domain 'local'.
(Browser) NEW: service 'iTunes_Ctrl_00113288927D6014' of type '_dacp._tcp' in domain 'local'.
(Browser) NEW: service 'iTunes_Ctrl_00113288927D6013' of type '_dacp._tcp' in domain 'local'.
(Browser) NEW: service 'iTunes_Ctrl_00113288927D6012' of type '_dacp._tcp' in domain 'local'.
(Browser) NEW: service 'iTunes_Ctrl_00113288927D6011' of type '_dacp._tcp' in domain 'local'.
(Browser) NEW: service 'iTunes_Ctrl_3A1B6204342A289B' of type '_dacp._tcp' in domain 'local'.
Client's DACP port: 6013.
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "4"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Audio-Latency", content: "11025"
    CSeq: 5.
    User-Agent: AudioStation/5.2 (Synology).
    Client-Instance: 00113288927D6013.
    DACP-ID: 00113288927D6013.
    Active-Remote: 0000000000006013.
    Session: 1.
    Content-Type: text/parameters.
    Content-Length: 19.
RTSP thread 0 received an RTSP Packet of type "SET_PARAMETER":
  Type: "CSeq", content: "5"
  Type: "User-Agent", content: "AudioStation/5.2 (Synology)"
  Type: "Client-Instance", content: "00113288927D6013"
  Type: "DACP-ID", content: "00113288927D6013"
  Type: "Active-Remote", content: "0000000000006013"
  Type: "Session", content: "1"
  Type: "Content-Type", content: "text/parameters"
  Type: "Content-Length", content: "19"
Connection 0: SET_PARAMETER
AirPlay request to set volume to: -7.800000.
Setting volume db to -663.000016.
Open Mixer
Mixer device name is "softvol".
Mixer Control name is "Master".
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "5"
  Type: "Server", content: "AirTunes/105.1"
    CSeq: 6.
    User-Agent: AudioStation/5.2 (Synology).
    Client-Instance: 00113288927D6013.
    DACP-ID: 00113288927D6013.
    Active-Remote: 0000000000006013.
    Session: 1.
    Content-Type: application/x-dmap-tagged.
    Content-Length: 101.
    RTP-Info: rtptime=558448417.
RTSP thread 0 received an RTSP Packet of type "SET_PARAMETER":
  Type: "CSeq", content: "6"
  Type: "User-Agent", content: "AudioStation/5.2 (Synology)"
  Type: "Client-Instance", content: "00113288927D6013"
  Type: "DACP-ID", content: "00113288927D6013"
  Type: "Active-Remote", content: "0000000000006013"
  Type: "Session", content: "1"
  Type: "Content-Type", content: "application/x-dmap-tagged"
  Type: "Content-Length", content: "101"
  Type: "RTP-Info", content: "rtptime=558448417"
Connection 0: SET_PARAMETER
received metadata tags in SET_PARAMETER request.
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "6"
  Type: "Server", content: "AirTunes/105.1"
    CSeq: 7.
    User-Agent: AudioStation/5.2 (Synology).
    Client-Instance: 00113288927D6013.
    DACP-ID: 00113288927D6013.
    Active-Remote: 0000000000006013.
    Session: 1.
    Content-Type: image/none.
    Content-Length: 0.
    RTP-Info: rtptime=558448417.
RTSP thread 0 received an RTSP Packet of type "SET_PARAMETER":
  Type: "CSeq", content: "7"
  Type: "User-Agent", content: "AudioStation/5.2 (Synology)"
  Type: "Client-Instance", content: "00113288927D6013"
  Type: "DACP-ID", content: "00113288927D6013"
  Type: "Active-Remote", content: "0000000000006013"
  Type: "Session", content: "1"
  Type: "Content-Type", content: "image/none"
  Type: "Content-Length", content: "0"
  Type: "RTP-Info", content: "rtptime=558448417"
Connection 0: SET_PARAMETER
Ignore received picture item (include_cover_art = no).
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "7"
  Type: "Server", content: "AirTunes/105.1"
    CSeq: 8.
    User-Agent: AudioStation/5.2 (Synology).
    Client-Instance: 00113288927D6013.
    DACP-ID: 00113288927D6013.
    Active-Remote: 0000000000006013.
    Session: 1.
    Content-Type: text/parameters.
    Content-Length: 39.
    RTP-Info: rtptime=558448417.
RTSP thread 0 received an RTSP Packet of type "SET_PARAMETER":
  Type: "CSeq", content: "8"
  Type: "User-Agent", content: "AudioStation/5.2 (Synology)"
  Type: "Client-Instance", content: "00113288927D6013"
  Type: "DACP-ID", content: "00113288927D6013"
  Type: "Active-Remote", content: "0000000000006013"
  Type: "Session", content: "1"
  Type: "Content-Type", content: "text/parameters"
  Type: "Content-Length", content: "39"
  Type: "RTP-Info", content: "rtptime=558448417"
Connection 0: SET_PARAMETER
RTSP thread 0: RTSP Response:
  Type: "CSeq", content: "8"
  Type: "Server", content: "AirTunes/105.1"
Using negotiated latency of 88200 frames and a static latency correction of 0
syncing to seqno 5163.
Hammerton Decoder used on unencrypted audio.
Output written using MMAP
PCM handle name = 'softvol'
alsa device parameters:
  access type = MMAP_INTERLEAVED
  format = 'S16_LE' (Signed 16 bit Little Endian)
  subformat = 'STD' (Standard)
  number of channels = 2
  number of significant bits = 16
  rate = 44100 frames per second (precisely).
  precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
  period_time = 11609 us (>).
  period_size = 512 frames (precisely).
  buffer_time = 371519 us (>).
  buffer_size = 16384 frames (>).
  periods_per_buffer = 32 (precisely).
Setting volume db to -663.000016.
Using negotiated latency of 93702 frames and a static latency correction of 0
Using negotiated latency of 99296 frames and a static latency correction of 0
Using negotiated latency of 104922 frames and a static latency correction of 0
New RTSP connection from 192.168.1.139:54143 to self at 192.168.1.136:5000 on conversation thread 1.
Successfully created RTSP receiver thread 1.
    CSeq: 0.
    DACP-ID: 3A1B6204342A289B.
    Active-Remote: 2244155809.
    User-Agent: AirPlay/366.64.
RTSP thread 1 received an RTSP Packet of type "OPTIONS":
  Type: "CSeq", content: "0"
  Type: "DACP-ID", content: "3A1B6204342A289B"
  Type: "Active-Remote", content: "2244155809"
  Type: "User-Agent", content: "AirPlay/366.64"
Connection 1: OPTIONS
RTSP thread 1: RTSP Response:
  Type: "CSeq", content: "0"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
    Apple-Challenge: OaqbxvO2Kv115miNCogZkw==.
    CSeq: 1.
    DACP-ID: 3A1B6204342A289B.
    Active-Remote: 2244155809.
    User-Agent: AirPlay/366.64.
RTSP thread 1 received an RTSP Packet of type "OPTIONS":
  Type: "Apple-Challenge", content: "OaqbxvO2Kv115miNCogZkw=="
  Type: "CSeq", content: "1"
  Type: "DACP-ID", content: "3A1B6204342A289B"
  Type: "Active-Remote", content: "2244155809"
  Type: "User-Agent", content: "AirPlay/366.64"
Connection 1: OPTIONS
RTSP thread 1: RTSP Response:
  Type: "Apple-Response", content: "XW9woh3KFhnE33G31DurEYsIVo+QN2d4R7Sih+TJY/daujlOsOR6pBSI/LVoZmZNO4D9cdcLcWEdvuqWRxW0lxjEzt0Zu1M6Cz/3AWkC55b1aCtXPkwzymMFWg9pPIQPGgP8g1I7OZ4NC1dPRH9EGtqj+v7E/TAT03mLMDc2kYKSwPK7wF2o0EuJ2ku5eOAeReNceK92tklk+Bc/Kq39+zp1lnEZYfby9lWQ2vm7hvyVjOfGtsYwNU4/lHYjGl8o+8kjtHLSyUv8i0P1T8hJb4oy2ilGK9EIGrx1cVcBunSP4xgwFqlAkRnPhqkLw9MbaDem4cIbP/UTNi4K7JRBnw"
  Type: "CSeq", content: "1"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
    Content-Length: 641.
    Content-Type: application/sdp.
    CSeq: 2.
    DACP-ID: 3A1B6204342A289B.
    Active-Remote: 2244155809.
    User-Agent: AirPlay/366.64.
RTSP thread 1 received an RTSP Packet of type "ANNOUNCE":
  Type: "Content-Length", content: "641"
  Type: "Content-Type", content: "application/sdp"
  Type: "CSeq", content: "2"
  Type: "DACP-ID", content: "3A1B6204342A289B"
  Type: "Active-Remote", content: "2244155809"
  Type: "User-Agent", content: "AirPlay/366.64"
Connection 1: ANNOUNCE
RTSP Conversation thread 0 already playing when asked by thread 1.
ANNOUNCE failed to get the player
Already playing.
RTSP thread 1: RTSP Response:
  Type: "CSeq", content: "2"
  Type: "Server", content: "AirTunes/105.1"
RTSP conversation thread 1 -- connection closed.
Synchronously terminate playing thread of RTSP conversation thread 1.
player thread of RTSP conversation 1 is already deleted.
Successful termination of playing thread of RTSP conversation thread 1.
Request termination of RTSP conversation thread 1.
RTSP conversation thread 1 terminated.
Using negotiated latency of 110543 frames and a static latency correction of 0
Using negotiated latency of 108576 frames and a static latency correction of 0
(Browser) REMOVE: service 'iTunes_Ctrl_3A1B6204342A289B' of type '_dacp._tcp' in domain 'local'.
Using negotiated latency of 114221 frames and a static latency correction of 0
Using negotiated latency of 112713 frames and a static latency correction of 0
Using negotiated latency of 111298 frames and a static latency correction of 0
Using negotiated latency of 109830 frames and a static latency correction of 0
Using negotiated latency of 115443 frames and a static latency correction of 0
Using negotiated latency of 112260 frames and a static latency correction of 0
Using negotiated latency of 110778 frames and a static latency correction of 0
Using negotiated latency of 109339 frames and a static latency correction of 0
    CSeq: 9.
    User-Agent: AudioStation/5.2 (Synology).
    Client-Instance: 00113288927D6013.
    DACP-ID: 00113288927D6013.
    Active-Remote: 0000000000006013.
    Session: 1.
    Content-Type: text/parameters.
    Content-Length: 20.
joerg-krause commented 6 years ago

git bisect tells that the issue was introduced in commit 66e29394c16b148a1841ed08e2e240ab7a5951ce.

mikebrady commented 6 years ago

Thanks. Let me have a look.

mikebrady commented 6 years ago

Hi Jörg-Krause. Are you certain about which commit the issue was introduced? (Sorry to ask, and all that...)

joerg-krause commented 6 years ago

Yes, I am certain. It has something to do with the response message created here: https://github.com/mikebrady/shairport-sync/commit/66e29394c16b148a1841ed08e2e240ab7a5951ce#diff-a6bfd8a1968c58b74be027f51f369b8eR648 and here: https://github.com/mikebrady/shairport-sync/commit/66e29394c16b148a1841ed08e2e240ab7a5951ce#diff-a6bfd8a1968c58b74be027f51f369b8eR656. If I revert the write() calls to the previous version it runs fine. Further investigation tomorrow.

mikebrady commented 6 years ago

Thanks -- I had kind of reached the same conclusion myself. Not sure why -- perhaps the Synology software expects the entire packet to be sent in one piece. I might push an update in the development branch if I get the time.

mikebrady commented 6 years ago

So, I've modified that code to fill up the buffer in its entirety before outputting it, and pushed it out in the development branch, just in case my idea is right. If you got an opportunity, would you be kind enough to try it please? It works just the same on my standard tests, but I don't have a Synology system, I'm afraid.

joerg-krause commented 6 years ago

I can confirm that the development branch works :smile: Many thanks!

mikebrady commented 6 years ago

Great — it does seem to me as if it’s a workaround for a bug in the Synology software. But it’s good that it’s fixed. I’ll be putting out another RC early next week with this and another important fix in it.

joerg-krause commented 6 years ago

Thanks! What is the other important fix?

mikebrady commented 6 years ago

If you have a look in #653, around here, it’s a bug that manifested itself under (I believe) poor networking conditions. Exactly how poor, I don’t yet know, but I was never able to cause the bug to be activated.

mikebrady commented 6 years ago

By the way, Jörg-Krause, thanks for your fantastic detective work — it made tracking down the likely cause very much simpler.

joerg-krause commented 6 years ago

You're welcome!