hang on "unable_to_cancel_play_session"

[chrisjshull]

an unrecoverable error, "unable_to_cancel_play_session", has been detected.

shairport-sync -V 3.3.5-libdaemon-OpenSSL-dns_sd-ao-pa-stdout-pipe-soxr-metadata-sysconfdir:/usr/local/etc/shairport-sync

macOS 10.13.6

[chrisjshull]

Has happened to me several times. Happy to pull other diagnostic info - just let me know what to do.

[mikebrady]

Thanks for the post. That's an unusual configuration. The error message means a watchdog timer timed out, tried to cancel a play session and failed. Just FYI, on a Linux system running into an ALSA back end, it is invariably caused by a hardware problem – typically an I2S DAC locks up and the whole machine need to be restarted.

I'm guessing that it's not a hardware problem here, more a problem caused by insufficient testing of the configuration.

So, for a start, can you tell me what back end you were outputting through please? Was it ao/pa/pipe, etc.?

Can you cause it to happen at will? (That would be great.) Also, can you say how you built it – it would save me a lot of time to know that.

[chrisjshull]

I just installed through homebrew. brew install shairport-sync

Which I believe now uses pulseaudio by default.

When I run into this I can kill the process and start it up again - no machine reboot needed.

[mikebrady]

Thanks. I'll give it a try.

[chrisjshull]

I turned up the verbosity, here's what I got in logs:

...
       123.200839533 "rtsp.c:297" Connection 7: As Yeats almost said, "Too long a silence / can make a stone of the heart".
         4.019930883 "rtsp.c:306" *warning: an unrecoverable error, "unable_to_cancel_play_session", has been detected.
     52122.140624050 "rtp.c:537" Error 65 using send-to to the timing socket: "No route to host".
         3.009631852 "rtp.c:537" Error 64 using send-to to the timing socket: "Host is down".
         3.003748645 "rtp.c:537" Error 64 using send-to to the timing socket: "Host is down".
         3.007109662 "rtp.c:537" Error 64 using send-to to the timing socket: "Host is down".
         3.003980501 "rtp.c:537" Error 64 using send-to to the timing socket: "Host is down".
         3.010088699 "rtp.c:537" Error 64 using send-to to the timing socket: "Host is down".
         3.010079230 "rtp.c:537" Error 64 using send-to to the timing socket: "Host is down".
     16500.321950321 "rtsp.c:1692" Connection 9 ANNOUNCE is waiting for connection 7 to shut down.
         3.208398975 "rtsp.c:1955" Connection 9: ANNOUNCE failed because another connection is already playing.

[mikebrady]

That’s interesting, thanks. Let me thing and see if there is the potential for a hang there...

[chrisjshull]

I switched to the "ao" backend and the same thing happened

...
         1.644523921 "player.c:1603" Playback Stopped. Total playing time 00:04:44. Input: 44102.90 frames per second.
         0.312293323 "rtsp.c:1000" Connection 3: SETUP DACP-ID "778FC497BF35EDF8" from fe80::18ed:4b01:6d85:1ffa to fe80::f2:c99:e5a1:c627 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
         0.007277080 "player.c:1927" sync error in milliseconds, total packets, missing packets, late packets, too late packets, resend requests, min buffer occupancy, max buffer occupancy, source nominal frames per second, source actual frames per second, source clock drift in ppm, source clock drift sample count
       120.365286959 "rtsp.c:297" Connection 3: As Yeats almost said, "Too long a silence / can make a stone of the heart".
         4.011013058 "rtsp.c:306" *warning: an unrecoverable error, "unable_to_cancel_play_session", has been detected.
       179.250252030 "rtsp.c:1692" Connection 4 ANNOUNCE is waiting for connection 3 to shut down.
         3.129842285 "rtsp.c:1955" Connection 4: ANNOUNCE failed because another connection is already playing.

[mikebrady]

Thanks. Can I ask, was there anything between the player.c:1297 and the RTSP.c:297? IOW, did you remove anything from the log?

[chrisjshull]

Nope - only from the top of the log at the "..."

[hhsk-dev]

hello, this problem happens to me also, but mostly when scrubbing in iina player on osx. if i restart client everything works, but dies again after 3-5 skips in iina player.

[mikebrady]

Thanks for the report. Do you have a way to make it happen 100% (or nearly) of the time?

[hhsk-dev]

yes i have a way to make it happen 100% of the time. you just need to skip a frame, and when shairport tries to sync audio fails to disconect previous connection.

 0.000013164 "shairport.c:1795" loudness reference level is -20.000000
         3.686632762 "rtsp.c:1000" Connection 1: SETUP DACP-ID "A1E15AD3E804B312" from fe80::103a:f35:8bd6:b4fc to fe80::8f8:68ff:fe28:40ad with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
         0.011948450 "player.c:1899" sync error in milliseconds, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy, source nominal frames per second, source actual frames per second, output frames per second, source clock drift in ppm, source clock drift sample count, rough calculated correction in ppm
         7.381302881 "player.c:1603" Playback Stopped. Total playing time 00:00:07. Input: 0.00 frames per second.
         3.559207586 "rtsp.c:1000" Connection 2: SETUP DACP-ID "A1E15AD3E804B312" from fe80::103a:f35:8bd6:b4fc to fe80::8f8:68ff:fe28:40ad with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
         0.010803236 "player.c:1899" sync error in milliseconds, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy, source nominal frames per second, source actual frames per second, output frames per second, source clock drift in ppm, source clock drift sample count, rough calculated correction in ppm
         7.742419649 "player.c:1603" Playback Stopped. Total playing time 00:00:07. Input: 0.00 frames per second.
         0.269035672 "rtsp.c:1000" Connection 3: SETUP DACP-ID "A1E15AD3E804B312" from fe80::103a:f35:8bd6:b4fc to fe80::8f8:68ff:fe28:40ad with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
         0.028060630 "player.c:1899" sync error in milliseconds, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy, source nominal frames per second, source actual frames per second, output frames per second, source clock drift in ppm, source clock drift sample count, rough calculated correction in ppm
       120.088778278 "rtsp.c:297" Connection 3: As Yeats almost said, "Too long a silence / can make a stone of the heart".
         4.008845169 "rtsp.c:306" *warning: an unrecoverable error, "unable_to_cancel_play_session", has been detected.
        31.129191183 "rtsp.c:1692" Connection 4 ANNOUNCE is waiting for connection 3 to shut down.
         3.106097773 "rtsp.c:1955" Connection 4: ANNOUNCE failed because another connection is already playing.

[Nobiel]

Same issue here on Raspberry Pi. Randomly crashes with this message. I airplay audio from macOS to Ubuntu Mate for Raspberry Pi through pulseaudio backend.

[mcurcio]

If it helps, I am hitting the same issue running on OSX with the pipe backend. It fails basically every time, which means that one client can connect after the server starts, but then no clients can connect until the server is restarted.

[github-actions[bot]]

This issue has been inactive for 60 days so will be closed 7 days from now. To prevent this, please remove the "stale" label or post a comment.

[ghost]

hello @mikebrady, i realize this is an older issue, but i'd like to report i’m still experiencing something similar while running shairport-sync on macOS 12.5 (21G72) via brew (3.3.9) or from a local build off master (f73dc935b51e52b93c1a9c4adcd6c3d540fcaafa).

for me i can trigger this issue consistently by:

1. connecting to shairport-sync and playing some audio. in my case my client is Apple Music off iOS. this works fine, i get audio to play.
2. disconnecting client
3. reconnecting to shairport-sync. at this point, audio never resumes
4. disconnecting, after at which point i eventually get the *warning: an unrecoverable error, "unable_to_cancel_play_session", has been detected. msg in the shairport-sync logs.

below is some verbose output from my local build off master. if there is any other output i can share let me know!

         0.000111307 "shairport.c:461" looking for configuration file at full path "/usr/local/etc/shairport-sync/shairport-sync.conf"
         0.000387221 "shairport.c:1729" Started!
         0.000011467 "shairport.c:1756" software version: "3.3.9-libdaemon-OpenSSL-dns_sd-ao-pa-stdout-pipe-soxr-metadata-sysconfdir:/usr/local/etc"
         0.000004305 "shairport.c:1762" log verbosity is 2.
         0.037418347 "shairport.c:1777" The processor is running little-endian.
         0.000011468 "shairport.c:1810" disable resend requests is off.
         0.000003028 "shairport.c:1814" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000003026 "shairport.c:1815" statistics_requester status is 0.
         0.000002233 "shairport.c:1817" daemon status is 0.
         0.000003007 "shairport.c:1818" daemon pid file path is "/var/run/shairport-sync/shairport-sync.pid".
         0.000002406 "shairport.c:1820" rtsp listening port is 5000.
         0.000002183 "shairport.c:1821" udp base port is 6001.
         0.000002068 "shairport.c:1822" udp port range is 10.
         0.000003137 "shairport.c:1823" player name is "Bob.local".
         0.000002267 "shairport.c:1824" backend is "ao".
         0.000002127 "shairport.c:1825" run_this_before_play_begins action is "(null)".
         0.000002311 "shairport.c:1826" run_this_after_play_ends action is "(null)".
         0.000002066 "shairport.c:1827" wait-cmd status is 0.
         0.000002054 "shairport.c:1828" run_this_before_play_begins may return output is 0.
         0.000002634 "shairport.c:1829" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000002381 "shairport.c:1830" run_this_before_entering_active_state action is  "(null)".
         0.000002138 "shairport.c:1831" run_this_after_exiting_active_state action is  "(null)".
         0.000002121 "shairport.c:1832" active_state_timeout is  10.000000 seconds.
         0.000002361 "shairport.c:1833" mdns backend "(null)".
         0.000002099 "shairport.c:1834" userSuppliedLatency is 0.
         0.000021256 "shairport.c:1837" interpolation setting is "auto".
         0.000006763 "shairport.c:1838" interpolation soxr_delay_threshold is 30.
         0.000002879 "shairport.c:1839" resync time is 0.050000 seconds.
         0.000002510 "shairport.c:1840" allow a session to be interrupted: 1.
         0.000002304 "shairport.c:1841" busy timeout time is 120.
         0.000002786 "shairport.c:1842" drift tolerance is 0.001995 seconds.
         0.000002858 "shairport.c:1843" password is "(null)".
         0.000002217 "shairport.c:1844" ignore_volume_control is 0.
         0.000002120 "shairport.c:1848" volume_max_db is not set
         0.000002073 "shairport.c:1850" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000002508 "shairport.c:1854" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000002391 "shairport.c:1856" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000002735 "shairport.c:1857" disable_synchronization is 0.
         0.000002228 "shairport.c:1858" use_mmap_if_available is 1.
         0.000002005 "shairport.c:1860" output_format automatic selection is enabled.
         0.000002218 "shairport.c:1864" output_rate automatic selection is enabled.
         0.000002137 "shairport.c:1868" audio backend desired buffer length is 1.000000 seconds.
         0.000002375 "shairport.c:1870" audio_backend_buffer_interpolation_threshold_in_seconds is 0.000000 seconds.
         0.000002474 "shairport.c:1871" audio backend latency offset is 0.000000 seconds.
         0.000002530 "shairport.c:1873" audio backend silence lead-in time is "auto".
         0.000002262 "shairport.c:1877" zeroconf regtype is "_raop._tcp".
         0.000002116 "shairport.c:1878" decoders_supported field is 1.
         0.000002001 "shairport.c:1879" use_apple_decoder is 0.
         0.000002066 "shairport.c:1880" alsa_use_hardware_mute is 0.
         0.000002039 "shairport.c:1884" no special mdns service interface was requested.
         0.000027822 "shairport.c:1888" configuration file name "/usr/local/etc/shairport-sync/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync/shairport-sync.conf".
         0.000004184 "shairport.c:1894" metadata enabled is 1.
         0.000002134 "shairport.c:1895" metadata pipename is "/tmp/shairport-sync-metadata".
         0.000002137 "shairport.c:1897" metadata socket address is "(null)" port 0.
         0.000002195 "shairport.c:1898" metadata socket packet size is "500".
         0.000002104 "shairport.c:1899" get-coverart is 1.
         0.000002050 "shairport.c:1917" loudness is 0.
         0.000002059 "shairport.c:1918" loudness reference level is -20.000000
         0.000032371 "rtsp.c:1665" metadata pipe name is "/tmp/shairport-sync-metadata".
         0.000081928 "rtsp.c:158" Creating metadata queue "pipe".
         0.000001766 "rtsp.c:158" Creating metadata queue "multicast".
         1.500377617 "shairport.c:194" soxr_delay_index: 0.
         0.000013820 "shairport.c:201" "soxr" interpolation has been chosen.
         2.098953465 "rtsp.c:2999" Connection 1: new connection from [fe80::c0c:ebf4:2b51:e77b]:50332 to self at [fe80::1021:605c:123f:728d]:5000.
         2.595866689 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "ANNOUNCE":
         0.000036921 "rtsp.c:507"   Type: "Content-Length", content: "667"
         0.000009678 "rtsp.c:507"   Type: "Content-Type", content: "application/sdp"
         0.000007367 "rtsp.c:507"   Type: "CSeq", content: "4"
         0.000006884 "rtsp.c:507"   Type: "DACP-ID", content: "EEA16D7B22598EE8"
         0.000006638 "rtsp.c:507"   Type: "Active-Remote", content: "2534371807"
         0.000006523 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.003676964 "rtsp.c:2225" Play connection from user agent "AirPlay/620.8.2" on RTSP conversation thread 1.
         0.000015098 "rtsp.c:2234" AirPlay version 620 detected.
         0.000012026 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000004066 "rtsp.c:507"   Type: "CSeq", content: "4"
         0.000003727 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.004792144 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SETUP":
         0.000025431 "rtsp.c:507"   Type: "Transport", content: "RTP/AVP/UDP;unicast;mode=record;timing_port=62741;control_port=50427"
         0.000006455 "rtsp.c:507"   Type: "CSeq", content: "5"
         0.000005047 "rtsp.c:507"   Type: "DACP-ID", content: "EEA16D7B22598EE8"
         0.000004752 "rtsp.c:507"   Type: "Active-Remote", content: "2534371807"
         0.000004339 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000007232 "rtsp.c:976" Connection 1: SETUP -- Active-Remote string seen: "2534371807".
         0.000016347 "rtsp.c:995" Connection 1: SETUP -- DACP-ID string seen: "EEA16D7B22598EE8".
         0.000021973 "rtp.c:968" Connection 1: SETUP -- Connection from fe80::c0c:ebf4:2b51:e77b to self at fe80::1021:605c:123f:728d.
         0.000143260 "rtsp.c:1062" Connection 1: SETUP DACP-ID "EEA16D7B22598EE8" from fe80::c0c:ebf4:2b51:e77b to fe80::1021:605c:123f:728d with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
         0.000013732 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000004855 "rtsp.c:507"   Type: "CSeq", content: "5"
         0.000006420 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000005016 "rtsp.c:507"   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002;server_port=6003"
         0.000005229 "rtsp.c:507"   Type: "Session", content: "1"
         0.004152250 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "RECORD":
         0.000036407 "rtsp.c:507"   Type: "CSeq", content: "6"
         0.000009401 "rtsp.c:507"   Type: "DACP-ID", content: "EEA16D7B22598EE8"
         0.000007723 "rtsp.c:507"   Type: "Active-Remote", content: "2534371807"
         0.000006784 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000009489 "rtsp.c:855" Connection 1: RECORD
         0.000029227 "activity_monitor.c:64" abeg
         0.000085242 "player.c:3120" pbeg
         0.000017187 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000008223 "rtsp.c:507"   Type: "CSeq", content: "6"
         0.000006909 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000007009 "rtsp.c:507"   Type: "Audio-Latency", content: "11025"
         0.000288431 "player.c:2004" Set initial volume to -18.000000.
         0.000049895 "loudness.c:47" Volume: -37.6 dB - Loudness gain @10Hz: 8.8 dB
         0.000028690 "player.c:3051" player_volume_without_notification: volume mode is 0, airplay volume is -18.000000, software_attenuation: -3755.700000, hardware_attenuation: 0.000000, muting is disabled.
         0.000016394 "player.c:2007" Play begin
         0.007257245 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000024685 "rtsp.c:507"   Type: "Content-Length", content: "20"
         0.000005985 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000004965 "rtsp.c:507"   Type: "CSeq", content: "7"
         0.000004680 "rtsp.c:507"   Type: "DACP-ID", content: "EEA16D7B22598EE8"
         0.000004661 "rtsp.c:507"   Type: "Active-Remote", content: "2534371807"
         0.000004196 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000013464 "loudness.c:47" Volume: -43.3 dB - Loudness gain @10Hz: 11.7 dB
         0.000021502 "player.c:3051" player_volume_without_notification: volume mode is 0, airplay volume is -20.000000, software_attenuation: -4333.500000, hardware_attenuation: 0.000000, muting is disabled.
         0.000008105 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000004744 "rtsp.c:507"   Type: "CSeq", content: "7"
         0.000004315 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.033552753 "player.c:247" Hammerton Decoder used on encrypted audio.
         0.000052823 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "FLUSH":
         0.000024378 "rtsp.c:507"   Type: "RTP-Info", content: "seq=60336;rtptime=4141443155"
         0.000008805 "rtsp.c:507"   Type: "CSeq", content: "8"
         0.000008058 "rtsp.c:507"   Type: "DACP-ID", content: "EEA16D7B22598EE8"
         0.000007216 "rtsp.c:507"   Type: "Active-Remote", content: "2534371807"
         0.000007518 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000011362 "player.c:3078" do_flush: flush to 4141443155.
         0.000000498 "player.c:1068" pffr
         0.000013781 "player.c:3090" pfls
         0.000051420 "player.c:1110" first_packet_time set for frame 4141443155.
         0.000073208 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000024700 "rtsp.c:507"   Type: "CSeq", content: "8"
         0.000009918 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         1.820538634 "player.c:1287" prsm
         0.000313548 "player.c:1005" flush request: flush frame 4141443155 expired -- buffer contains 2464 frames, from 4141443155 to 4141445618
         0.000027033 "player.c:1029" flush request: request dropped.
         0.318485770 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000037771 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=4141437675"
         0.000009602 "rtsp.c:507"   Type: "Content-Length", content: "69706"
         0.000007651 "rtsp.c:507"   Type: "Content-Type", content: "image/jpeg"
         0.000007028 "rtsp.c:507"   Type: "CSeq", content: "9"
         0.000006931 "rtsp.c:507"   Type: "DACP-ID", content: "EEA16D7B22598EE8"
         0.000006885 "rtsp.c:507"   Type: "Active-Remote", content: "2534371807"
         0.000006554 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000028962 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000008002 "rtsp.c:507"   Type: "CSeq", content: "9"
         0.000006935 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.014113745 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000036590 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=4141449995"
         0.000009185 "rtsp.c:507"   Type: "Content-Length", content: "43"
         0.000007625 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000006978 "rtsp.c:507"   Type: "CSeq", content: "11"
         0.000006929 "rtsp.c:507"   Type: "DACP-ID", content: "EEA16D7B22598EE8"
         0.000006674 "rtsp.c:507"   Type: "Active-Remote", content: "2534371807"
         0.000006335 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000027234 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000008020 "rtsp.c:507"   Type: "CSeq", content: "11"
         0.000006789 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.005317471 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000025269 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=4141451051"
         0.000005954 "rtsp.c:507"   Type: "Content-Length", content: "227"
         0.000004842 "rtsp.c:507"   Type: "Content-Type", content: "application/x-dmap-tagged"
         0.000004620 "rtsp.c:507"   Type: "CSeq", content: "12"
         0.000004745 "rtsp.c:507"   Type: "DACP-ID", content: "EEA16D7B22598EE8"
         0.000004487 "rtsp.c:507"   Type: "Active-Remote", content: "2534371807"
         0.000004263 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000021376 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000005247 "rtsp.c:507"   Type: "CSeq", content: "12"
         0.000004343 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         2.108202617 "rtsp.c:2663" Connection 1: Received an RTSP Packet of type "TEARDOWN":
         0.000035327 "rtsp.c:507"   Type: "CSeq", content: "14"
         0.000009715 "rtsp.c:507"   Type: "DACP-ID", content: "EEA16D7B22598EE8"
         0.000007710 "rtsp.c:507"   Type: "Active-Remote", content: "2534371807"
         0.000006998 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000009616 "rtsp.c:911" Connection 1: TEARDOWN
         0.000628081 "player.c:3146" pend
         0.000067215 "rtsp.c:2706" Connection 1: RTSP Response:
         0.000007091 "rtsp.c:507"   Type: "CSeq", content: "14"
         0.000030992 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000020632 "rtsp.c:507"   Type: "Connection", content: "close"
         0.006884253 "rtsp.c:2597" Connection 1: terminated.
         2.407321251 "rtsp.c:2999" Connection 2: new connection from [fe80::c0c:ebf4:2b51:e77b]:50335 to self at [fe80::1021:605c:123f:728d]:5000.
         0.325191618 "rtsp.c:2663" Connection 2: Received an RTSP Packet of type "ANNOUNCE":
         0.000036427 "rtsp.c:507"   Type: "Content-Length", content: "669"
         0.000009451 "rtsp.c:507"   Type: "Content-Type", content: "application/sdp"
         0.000007093 "rtsp.c:507"   Type: "CSeq", content: "4"
         0.000007148 "rtsp.c:507"   Type: "DACP-ID", content: "7BB80911F9BBF69F"
         0.000006653 "rtsp.c:507"   Type: "Active-Remote", content: "1374170425"
         0.000006257 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.003477936 "rtsp.c:2225" Play connection from user agent "AirPlay/620.8.2" on RTSP conversation thread 2.
         0.000011387 "rtsp.c:2234" AirPlay version 620 detected.
         0.000012260 "rtsp.c:2706" Connection 2: RTSP Response:
         0.000003982 "rtsp.c:507"   Type: "CSeq", content: "4"
         0.000003685 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.006630958 "rtsp.c:2663" Connection 2: Received an RTSP Packet of type "SETUP":
         0.000036370 "rtsp.c:507"   Type: "Transport", content: "RTP/AVP/UDP;unicast;mode=record;timing_port=64654;control_port=53570"
         0.000009924 "rtsp.c:507"   Type: "CSeq", content: "5"
         0.000007662 "rtsp.c:507"   Type: "DACP-ID", content: "7BB80911F9BBF69F"
         0.000007236 "rtsp.c:507"   Type: "Active-Remote", content: "1374170425"
         0.000006665 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000010261 "rtsp.c:976" Connection 2: SETUP -- Active-Remote string seen: "1374170425".
         0.000023367 "rtsp.c:995" Connection 2: SETUP -- DACP-ID string seen: "7BB80911F9BBF69F".
         0.000015974 "rtp.c:968" Connection 2: SETUP -- Connection from fe80::c0c:ebf4:2b51:e77b to self at fe80::1021:605c:123f:728d.
         0.000200332 "rtsp.c:1062" Connection 2: SETUP DACP-ID "7BB80911F9BBF69F" from fe80::c0c:ebf4:2b51:e77b to fe80::1021:605c:123f:728d with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
         0.000017689 "rtsp.c:2706" Connection 2: RTSP Response:
         0.000016530 "rtsp.c:507"   Type: "CSeq", content: "5"
         0.000010755 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000007126 "rtsp.c:507"   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002;server_port=6003"
         0.000008395 "rtsp.c:507"   Type: "Session", content: "1"
         0.008099912 "rtsp.c:2663" Connection 2: Received an RTSP Packet of type "RECORD":
         0.000035523 "rtsp.c:507"   Type: "CSeq", content: "6"
         0.000009739 "rtsp.c:507"   Type: "DACP-ID", content: "7BB80911F9BBF69F"
         0.000007665 "rtsp.c:507"   Type: "Active-Remote", content: "1374170425"
         0.000006913 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000009517 "rtsp.c:855" Connection 2: RECORD
         0.000088980 "player.c:3120" pbeg
         0.000021833 "rtsp.c:2706" Connection 2: RTSP Response:
         0.000008119 "rtsp.c:507"   Type: "CSeq", content: "6"
         0.000007085 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000006873 "rtsp.c:507"   Type: "Audio-Latency", content: "11025"
         0.000277412 "player.c:2004" Set initial volume to -20.000000.
         0.000063717 "loudness.c:47" Volume: -43.3 dB - Loudness gain @10Hz: 11.7 dB
         0.000019674 "player.c:3051" player_volume_without_notification: volume mode is 0, airplay volume is -20.000000, software_attenuation: -4333.500000, hardware_attenuation: 0.000000, muting is disabled.
         0.000008934 "player.c:2007" Play begin
         0.008505578 "rtsp.c:2663" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
         0.000011796 "rtsp.c:507"   Type: "Content-Length", content: "20"
         0.000004235 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000003475 "rtsp.c:507"   Type: "CSeq", content: "7"
         0.000003099 "rtsp.c:507"   Type: "DACP-ID", content: "7BB80911F9BBF69F"
         0.000003151 "rtsp.c:507"   Type: "Active-Remote", content: "1374170425"
         0.000002994 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000008521 "loudness.c:47" Volume: -43.3 dB - Loudness gain @10Hz: 11.7 dB
         0.000011544 "player.c:3051" player_volume_without_notification: volume mode is 0, airplay volume is -20.000000, software_attenuation: -4333.500000, hardware_attenuation: 0.000000, muting is disabled.
         0.000005872 "rtsp.c:2706" Connection 2: RTSP Response:
         0.000003303 "rtsp.c:507"   Type: "CSeq", content: "7"
         0.000003039 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.033150372 "player.c:247" Hammerton Decoder used on encrypted audio.
         0.000053422 "player.c:1068" pffr
         0.000025969 "player.c:1110" first_packet_time set for frame 2479028689.
         0.008394347 "rtsp.c:2663" Connection 2: Received an RTSP Packet of type "FLUSH":
         0.000034559 "rtsp.c:507"   Type: "RTP-Info", content: "seq=20817;rtptime=2479028689"
         0.000023649 "rtsp.c:507"   Type: "CSeq", content: "8"
         0.000007518 "rtsp.c:507"   Type: "DACP-ID", content: "7BB80911F9BBF69F"
         0.000007368 "rtsp.c:507"   Type: "Active-Remote", content: "1374170425"
         0.000006415 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000011056 "player.c:3078" do_flush: flush to 2479028689.
         0.000013804 "player.c:3090" pfls
         0.000021636 "rtsp.c:2706" Connection 2: RTSP Response:
         0.000007293 "rtsp.c:507"   Type: "CSeq", content: "8"
         0.000006793 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         2.089580564 "rtsp.c:2663" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
         0.000037695 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=2479025321"
         0.000009915 "rtsp.c:507"   Type: "Content-Length", content: "69706"
         0.000007846 "rtsp.c:507"   Type: "Content-Type", content: "image/jpeg"
         0.000006982 "rtsp.c:507"   Type: "CSeq", content: "9"
         0.000006886 "rtsp.c:507"   Type: "DACP-ID", content: "7BB80911F9BBF69F"
         0.000007058 "rtsp.c:507"   Type: "Active-Remote", content: "1374170425"
         0.000006623 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000029441 "rtsp.c:2706" Connection 2: RTSP Response:
         0.000007926 "rtsp.c:507"   Type: "CSeq", content: "9"
         0.000006595 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.016292090 "rtsp.c:2663" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
         0.000025444 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=2479033417"
         0.000006229 "rtsp.c:507"   Type: "Content-Length", content: "43"
         0.000004941 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000004401 "rtsp.c:507"   Type: "CSeq", content: "11"
         0.000004303 "rtsp.c:507"   Type: "DACP-ID", content: "7BB80911F9BBF69F"
         0.000004349 "rtsp.c:507"   Type: "Active-Remote", content: "1374170425"
         0.000004184 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000018486 "rtsp.c:2706" Connection 2: RTSP Response:
         0.000004921 "rtsp.c:507"   Type: "CSeq", content: "11"
         0.000004269 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.006920158 "rtsp.c:2663" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
         0.000037703 "rtsp.c:507"   Type: "RTP-Info", content: "rtptime=2479034473"
         0.000009546 "rtsp.c:507"   Type: "Content-Length", content: "227"
         0.000007855 "rtsp.c:507"   Type: "Content-Type", content: "application/x-dmap-tagged"
         0.000007049 "rtsp.c:507"   Type: "CSeq", content: "12"
         0.000007331 "rtsp.c:507"   Type: "DACP-ID", content: "7BB80911F9BBF69F"
         0.000007116 "rtsp.c:507"   Type: "Active-Remote", content: "1374170425"
         0.000006437 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000030079 "rtsp.c:2706" Connection 2: RTSP Response:
         0.000010535 "rtsp.c:507"   Type: "CSeq", content: "12"
         0.000007190 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         1.441202753 "rtsp.c:2663" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
         0.000035051 "rtsp.c:507"   Type: "Content-Length", content: "20"
         0.000009599 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000007587 "rtsp.c:507"   Type: "CSeq", content: "13"
         0.000007283 "rtsp.c:507"   Type: "DACP-ID", content: "7BB80911F9BBF69F"
         0.000006920 "rtsp.c:507"   Type: "Active-Remote", content: "1374170425"
         0.000006944 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000020647 "loudness.c:47" Volume: -37.9 dB - Loudness gain @10Hz: 9.0 dB
         0.000030014 "player.c:3051" player_volume_without_notification: volume mode is 0, airplay volume is -18.125000, software_attenuation: -3791.812500, hardware_attenuation: 0.000000, muting is disabled.
         0.000012747 "rtsp.c:2706" Connection 2: RTSP Response:
         0.000007215 "rtsp.c:507"   Type: "CSeq", content: "13"
         0.000006596 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.776868208 "rtsp.c:2663" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
         0.000034335 "rtsp.c:507"   Type: "Content-Length", content: "20"
         0.000009244 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000007798 "rtsp.c:507"   Type: "CSeq", content: "15"
         0.000007187 "rtsp.c:507"   Type: "DACP-ID", content: "7BB80911F9BBF69F"
         0.000006900 "rtsp.c:507"   Type: "Active-Remote", content: "1374170425"
         0.000006942 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000020554 "loudness.c:47" Volume: -32.5 dB - Loudness gain @10Hz: 6.3 dB
         0.000028509 "player.c:3051" player_volume_without_notification: volume mode is 0, airplay volume is -16.250000, software_attenuation: -3250.125000, hardware_attenuation: 0.000000, muting is disabled.
         0.000012250 "rtsp.c:2706" Connection 2: RTSP Response:
         0.000007658 "rtsp.c:507"   Type: "CSeq", content: "15"
         0.000006991 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.179707672 "rtsp.c:2663" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
         0.000038918 "rtsp.c:507"   Type: "Content-Length", content: "20"
         0.000009287 "rtsp.c:507"   Type: "Content-Type", content: "text/parameters"
         0.000007693 "rtsp.c:507"   Type: "CSeq", content: "16"
         0.000007036 "rtsp.c:507"   Type: "DACP-ID", content: "7BB80911F9BBF69F"
         0.000006867 "rtsp.c:507"   Type: "Active-Remote", content: "1374170425"
         0.000006423 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000020952 "loudness.c:47" Volume: -27.1 dB - Loudness gain @10Hz: 3.5 dB
         0.000027438 "player.c:3051" player_volume_without_notification: volume mode is 0, airplay volume is -14.374999, software_attenuation: -2708.437224, hardware_attenuation: 0.000000, muting is disabled.
         0.000012292 "rtsp.c:2706" Connection 2: RTSP Response:
         0.000007304 "rtsp.c:507"   Type: "CSeq", content: "16"
         0.000009187 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         2.047852095 "rtsp.c:2663" Connection 2: Received an RTSP Packet of type "TEARDOWN":
         0.000034920 "rtsp.c:507"   Type: "CSeq", content: "18"
         0.000009836 "rtsp.c:507"   Type: "DACP-ID", content: "7BB80911F9BBF69F"
         0.000008021 "rtsp.c:507"   Type: "Active-Remote", content: "1374170425"
         0.000006792 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/620.8.2"
         0.000008792 "rtsp.c:911" Connection 2: TEARDOWN
        13.723300484 "rtp.c:821" Time ping turnaround time: 497169348 ns -- it looks like a timing ping was lost.
        53.962276616 "rtp.c:821" Time ping turnaround time: 412615667 ns -- it looks like a timing ping was lost.
        45.541476138 "rtsp.c:338" Connection 2: As Yeats almost said, "Too long a silence / can make a stone of the heart".
         5.006374272 "rtsp.c:347" *warning: an unrecoverable error, "unable_to_cancel_play_session", has been detected.

[mikebrady]

Thanks for the report. I'll see if I can reproduce it!

[laverite]

oops meant to use my personal gh account for https://github.com/mikebrady/shairport-sync/issues/950#issuecomment-1200500766. anyway, just an update i don't seem to have the same issue using the pipe or jack backends. so seems like it might be specific to ao.

[mikebrady]

[Update -- please see below first.] Hi there. Would you be in a position to build from the development branch? I've made some experimental changes to the libao driver (audio_ao.c) in the development branch that just might make it behave better, but am not in a position to test it on MacOS until next week. If you can, I could post a replacement for audio_ao.c here and you might be able to try it sooner. FWIW, it works well running in Linux in a VM.

[mikebrady]

Just looking at the "Default Driver Detector" section of the libao documentation on this page, and I see that by default libao would select a PulseAudio driver in preference to other possibilities. It seems to me that this would be adding needless complexity to the audio processing chain (and may indeed be running into the same problem as reported above, where the Shairport Sync backends to PulseAudio directly. So I wonder what would happen if you chose the macosx driver explicitly. If you can run Shairport Sync from the command line, something like this might work:

$ shairport-sync -o ao -v -- -d macosx

On the Linux VM, I got much better results when I explicitly selected the alsa driver like this:

$ shairport-sync -o ao -v -- -d alsa

[laverite]

hi @mikebrady thanks for taking the time to look into this further.

If you can run Shairport Sync from the command line, something like this might work:

$ shairport-sync -o ao -v -- -d macosx

just tried that, but unfortunately, even when passing in the macosx driver option i get the same behavior as before:

1.500815181 "shairport.c:201" "soxr" interpolation has been chosen.
10.289528929 "rtsp.c:1062" Connection 1: SETUP DACP-ID "E3DA74F869C94575" from fe80::42e:795d:52e9:dc30 to fe80::859:d97b:ee08:535f with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
11.928883482 "rtsp.c:1062" Connection 2: SETUP DACP-ID "49D9EFA93CEE9FFA" from fe80::42e:795d:52e9:dc30 to fe80::859:d97b:ee08:535f with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
62.089160705 "rtp.c:821" Time ping turnaround time: 206402600 ns -- it looks like a timing ping was lost.
18.026059973 "rtp.c:821" Time ping turnaround time: 220373681 ns -- it looks like a timing ping was lost.
39.788548550 "rtsp.c:338" Connection 2: As Yeats almost said, "Too long a silence / can make a stone of the heart".
4.004724515 "rtsp.c:347" *warning: an unrecoverable error, "unable_to_cancel_play_session", has been detected.

Would you be in a position to build from the development branch?

i tried building off development before originally posting here but wasn't able to on macOS. well actually, that's not entirely true. i was able to compile development on macOS after adding a few extra includes for <net/if.h> and friends. but while the resulting build seemed to start fine, my client was never able to connect even though shairport-sync was visible to my client.

more than happy to try anything else to help debug this further!

[mikebrady]

Okay, thanks. I think the best thing is for me to try this next week and see where I get to, to save a lot of messing around. Thanks again.

[mikebrady]

Hello again. A few updates have been made to the development branch. It now builds properly on a Mac with brew and has an updated libao backend that seems much more stable.

Actually, you can use the updated libao backend with the master branch. To try it, simply copy the text out of the development branch into the master branch of audio_ao.c (which contains the libao backend) and comment out line 182 to look like this:

//              .stats = NULL,

If you got a chance to try it out and report back, that would be great.

[laverite]

hey mike. just tried out both development and master with and without the ao changes from development. both compile fine on macOS and run much better with the ao backend. this is great! thank you so much for all the updates. 🍻

i was lightly following along to the changes in ao and for my own learning, how did you figure out that closing and re-opening the the driver would help out here?

[mikebrady]

Thanks for the update, and I'm glad it seems to be working.

i was lightly following along to the changes in ao and for my own learning, how did you figure out that closing and re-opening the the driver would help out here?

It was a bit of guesswork. The libao library doesn't seem to be very widely used, but there are very few complaints about it, so it seems likely that it works well enough. However, I think there is a bug somewhere in the libao system (maybe the macosx driver) and this new approach is a workaround.

The Shairport Sync ("SPS") libao backend followed the sample code pretty closely. However, the sample code could be interpreted as closing the device as soon as there was nothing more to play, whereas the the SPS backend would leave the device open for long periods without anything to play. So it was worth a try to close the device as soon as there was nothing more to play. So far, so good.

[laverite]

ahh, nice guesswork! I was wondering about the various backend differences. jack is nice because it lets you do custom routing pretty easily. but I haven't quite learned the material differences between libao and soundio for example. in any case thanks again for all your generous work you've put into this project!