Closed microfx closed 2 years ago
Thanks for the report. I’ll take a look.
A log verbosity of 2 is fine — 3 is too verbose. It would be great if you could find a way to cause this fault reliably.
It happens if I interact / do too much (like watching short video clips) – just now I watched a movie and used the 10-seconds-back seeking button on my iPhone to control Apple TV running a movie – twice or more
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.005655468 "audio_jack.c:389" audio_occupancy_now is 22093.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.005278542 "audio_jack.c:389" audio_occupancy_now is 21837.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.009628281 "audio_jack.c:389" audio_occupancy_now is 22346.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.004901198 "audio_jack.c:389" audio_occupancy_now is 22090.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.011841667 "audio_jack.c:389" audio_occupancy_now is 22342.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.004497240 "audio_jack.c:389" audio_occupancy_now is 22214.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.001827447 "rtsp.c:1839" anchor rate 0x0000000000000000.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000455521 "rtsp.c:1848" Connection 18: Stop playing.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.001503229 "audio_jack.c:372" Only the consumer can safely flush a lock-free ringbuffer. Asking the process callback to do it...
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.025514740 "rtsp.c:1053" FLUSHBUFFERED request
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000311979 "rtsp.c:1058" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>flushUntilSeq</key>
<integer>10483443</integer>
<key>flushUntilTS</key>
<integer>337330047</integer>
</dict>
</plist>
--
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000139844 "rtsp.c:1683" Can't find a flushFromSeq
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000088385 "rtsp.c:1695" Can't find a flushFromTS
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000074740 "rtsp.c:1708" flushUntilSeq is 10483443.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000069844 "rtsp.c:1716" flushUntilTS is 337330047.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000082135 "rtsp.c:1763" Immediate Flush Requested
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.001006667 "rtp.c:2401" Flush requested.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000169687 "rtp.c:2407" untilTS: 337330047
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000076719 "rtp.c:2408" untilSeq: 10483443
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000070625 "rtp.c:2409" --
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000070625 "rtp.c:2410" currentTS_Start: 336934495
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000071250 "rtp.c:2412" framesInBuffer: 1312
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000068906 "rtp.c:2414" currentTS_End: 336935807
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000073334 "rtp.c:2415" currentSeq: 10483057
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000316198 "audio_jack.c:372" Only the consumer can safely flush a lock-free ringbuffer. Asking the process callback to do it...
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000130520 "rtp.c:2458" Immediate Buffered Audio Flush Started.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.043632084 "rtsp.c:1053" TEARDOWN:
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000362239 "rtsp.c:1058" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>streams</key>
<array>
<dict>
<key>streamID</key>
<integer>0</integer>
<key>type</key>
<integer>103</integer>
</dict>
</array>
</dict>
</plist>
--
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000179896 "rtsp.c:2504" Connection 18: TEARDOWN a PTP stream.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000463177 "player.c:1662" Cancelling AP2 timing, control and audio threads...
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000148073 "player.c:1671" Connection 18: Delete Buffered Audio Stream thread
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.002216875 "rtp.c:1972" Buffered TCP Reader Thread Exit via Cleanup.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.002617552 "rtp.c:2143" Buffered Audio Receiver Cleanup Start.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000328802 "rtp.c:2147" Connection 18: TCP Buffered Audio port closed: 33705.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000153750 "rtp.c:2149" Buffered Audio Receiver Cleanup Done.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000606302 "player.c:1679" Connection 18: Delete AirPlay 2 Control thread
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000453125 "rtp.c:1633" Connection 18: AP2 Control Receiver Cleanup.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000854844 "rtp.c:1636" Connection 18: UDP control port 37269 closed.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000446771 "rtp.c:1331" Connection 18: Clear anchor information.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.001018073 "player.c:1734" Connection 18: player terminated.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.001099791 "player.c:3314" pend
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000307709 "rtsp.c:2508" Connection 18: TEARDOWN phase one complete
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.149491719 "rtsp.c:2622" Connection 18: SETUP (AirPlay 2)
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000653958 "rtsp.c:2900" Connection 18: SETUP on PTP stream. A "streams" array has been found
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000410364 "rtsp.c:2919" Connection 18: UDP control port opened: 52858.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.002567240 "rtsp.c:3031" Connection 18. AP2 Buffered Audio Stream.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000225000 "rtsp.c:1053" Buffered Audio Stream SETUP incoming message
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.001742760 "rtsp.c:1058" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>streams</key>
<array>
<dict>
<key>audioMode</key>
<string>default</string>
<key>ct</key>
<integer>4</integer>
<key>streamConnectionID</key>
<integer>-8837764365093158351</integer>
<key>spf</key>
<integer>1024</integer>
<key>shk</key>
<data>
IXE0ede6mmoB0j8yBNCn0MNO5Jyuzb/aeboAbbqfZv8=
</data>
<key>type</key>
<integer>103</integer>
<key>supportsDynamicStreamID</key>
<true/>
<key>audioFormat</key>
<integer>4194304</integer>
</dict>
</array>
</dict>
</plist>
--
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000336980 "rtsp.c:3049" Connection 18: TCP Buffered Audio port opened: 42119.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.001868489 "player.c:3288" pbeg
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.001066823 "rtsp.c:1053" SETUP response
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000466667 "rtsp.c:1058" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>streams</key>
<array>
<dict>
<key>type</key>
<integer>103</integer>
<key>dataPort</key>
<integer>42119</integer>
<key>audioBufferSize</key>
<integer>8388608</integer>
<key>controlPort</key>
<integer>52858</integer>
</dict>
</array>
</dict>
</plist>
--
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000927708 "rtsp.c:1388" Responding with content of length 131
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.010759063 "rtp.c:1492" Connection 18: No clock anchor information.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.059748541 "player.c:2092" Set initial volume to -14.625000.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.001385573 "player.c:3145" Software attenuation set to -2780.662500, i.e 2667.771819 out of 65,536, for airplay volume of -14.625000
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000196615 "loudness.c:47" Volume: -27.8 dB - Loudness gain @10Hz: 3.9 dB
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000261927 "player.c:3189" player_volume_without_notification: volume mode is 0, airplay volume is -14.625000, software_attenuation: -2780.662500, hardware_attenuation: 0.000000, muting is disabled.
Mar 18 22:11:36 MiCROLABS-P3 shairport-sync[15249]: 0.000156146 "player.c:2095" Play begin
Mar 18 22:11:56 MiCROLABS-P3 shairport-sync[15249]: 19.945151763 "activity_monitor.c:91" aend
Mar 18 22:11:56 MiCROLABS-P3 shairport-sync[15249]: 0.002898489 "activity_monitor.c:172" am_state: am_inactive
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 65.736626850 "rtsp.c:1053" TEARDOWN:
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.000383282 "rtsp.c:1058" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict/>
</plist>
--
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.001332552 "player.c:1662" Cancelling AP2 timing, control and audio threads...
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.000278437 "player.c:1671" Connection 18: Delete Buffered Audio Stream thread
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.002197865 "rtp.c:1972" Buffered TCP Reader Thread Exit via Cleanup.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.001304427 "rtp.c:2143" Buffered Audio Receiver Cleanup Start.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.000601458 "rtp.c:2147" Connection 18: TCP Buffered Audio port closed: 42119.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.000161615 "rtp.c:2149" Buffered Audio Receiver Cleanup Done.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.000968750 "player.c:1679" Connection 18: Delete AirPlay 2 Control thread
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.000721823 "rtp.c:1633" Connection 18: AP2 Control Receiver Cleanup.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.000435677 "rtp.c:1636" Connection 18: UDP control port 52858 closed.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.000703385 "rtp.c:1331" Connection 18: Clear anchor information.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.011374115 "player.c:1734" Connection 18: player terminated.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.001136354 "player.c:3314" pend
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.001027448 "rtsp.c:2453" Connection 18: TEARDOWN a PTP stream connection.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.000202604 "rtsp.c:2455" Connection 18: TEARDOWN Delete Event Thread.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.001465208 "rtp.c:1571" Connection 18: AP2 Event Receiver Cleanup.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.001376980 "rtsp.c:2461" Connection 18: TEARDOWN Close Event Socket.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.000400520 "rtsp.c:2466" Connection 18: closing TCP event port 33145.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.003309896 "rtsp.c:2479" Connection 18: TEARDOWN mdns_update on PTP stream.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.005679740 "rtsp.c:529" Connection 18: release play lock.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.001150052 "rtsp.c:533" Connection 18: release play lock.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.000125885 "rtsp.c:2512" Connection 18: TEARDOWN phase two complete
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.004862344 "rtsp.c:4666" Connection 18: rtsp_conversation_thread_func_cleanup_function called.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.000224427 "rtsp.c:2453" Connection 18: TEARDOWN a PTP stream connection.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.000108906 "rtsp.c:2461" Connection 18: TEARDOWN Close Event Socket.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.001343959 "rtsp.c:2479" Connection 18: TEARDOWN mdns_update on PTP stream.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.007578177 "rtsp.c:529" Connection 18: release play lock.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.000534791 "rtsp.c:4698" Connection 18: terminating connection from fdc5:1cf1:79d1:0:41:2d8f:fbdd:ce5e:49648 to self at fdc5:1cf1:79d1:0:bddd:efb7:b776:f850:7000.
Mar 18 22:13:02 MiCROLABS-P3 shairport-sync[15249]: 0.001918803 "rtsp.c:4755" Connection 18: Closed.
Mar 18 22:13:03 MiCROLABS-P3 shairport-sync[15249]: 0.995609895 "mdns_avahi.c:154" (Browser) REMOVE: service 'iTunes_Ctrl_9ABFA27B77F0EEE8' of type '_dacp._tcp' in domain 'local'.
Mar 18 22:13:03 MiCROLABS-P3 shairport-sync[15249]: 0.000827708 "dacp.c:467" dacp_monitor_port_update_callback with Remote ID "9ABFA27B77F0EEE8", target ID "9ABFA27B77F0EEE8" and port number 0.
Mar 18 22:13:03 MiCROLABS-P3 shairport-sync[15249]: 0.001088959 "mdns_avahi.c:154" (Browser) REMOVE: service 'iTunes_Ctrl_9ABFA27B77F0EEE8' of type '_dacp._tcp' in domain 'local'.
Mar 18 22:13:03 MiCROLABS-P3 shairport-sync[15249]: 0.000195364 "dacp.c:467" dacp_monitor_port_update_callback with Remote ID "9ABFA27B77F0EEE8", target ID "9ABFA27B77F0EEE8" and port number 0.
Mar 18 22:13:52 MiCROLABS-P3 shairport-sync[15249]: 48.983115086 "rtsp.c:730" Connection 18: deleted in cleanup.
maybe some of this helps?
Thanks. Just for clarity, am I correct in understanding that the log above was for a successful exit, and not for a crash? It looks okay to me. (It is useful though!)
yeah, no crash – but I was unable to get sound back - video didn't playback anymore - freeze until I deselected SPS as destination in ATV (and went to bed...). And btw the script also doesn't get triggered.
Am 18.03.2022 um 22:56 schrieb Mike Brady @.***>:
Thanks. Just for clarity, am I correct in understanding that the log above was for a successful exit, and not for a crash? It looks okay to me.
— Reply to this email directly, view it on GitHub, or unsubscribe. Triage notifications on the go with GitHub Mobile for iOS or Android. You are receiving this because you authored the thread.
Trying to provoke this while watching journal's output ... looks exactly like my last post. And of course it doesn't happen right now – I will post again with more useful logs when it actually happens.
Playing some MP3 from inside iCloud Drive now worked to provoke this – but I can't see any errors in the log
Mar 19 14:14:51 MiCROLABS-P3 shairport-sync[19238]: 0.004453854 "audio_jack.c:389" audio_occupancy_now is 21622.
Mar 19 14:14:51 MiCROLABS-P3 shairport-sync[19238]: 0.003465312 "audio_jack.c:389" audio_occupancy_now is 22387.
Mar 19 14:14:51 MiCROLABS-P3 shairport-sync[19238]: 0.003717344 "rtsp.c:1839" anchor rate 0x0000000000000000.
Mar 19 14:14:51 MiCROLABS-P3 shairport-sync[19238]: 0.000246198 "rtsp.c:1848" Connection 1: Stop playing.
Mar 19 14:14:51 MiCROLABS-P3 shairport-sync[19238]: 0.000649114 "audio_jack.c:372" Only the consumer can safely flush a lock-free ringbuffer. Asking the process callback to do it...
Mar 19 14:14:51 MiCROLABS-P3 shairport-sync[19238]: 0.002125261 "audio_jack.c:389" audio_occupancy_now is 22131.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.271305937 "rtsp.c:1053" TEARDOWN:
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000375886 "rtsp.c:1058" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>streams</key>
<array>
<dict>
<key>streamID</key>
<integer>0</integer>
<key>type</key>
<integer>103</integer>
</dict>
</array>
</dict>
</plist>
--
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000184896 "rtsp.c:2504" Connection 1: TEARDOWN a PTP stream.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000508385 "player.c:1662" Cancelling AP2 timing, control and audio threads...
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000127500 "player.c:1671" Connection 1: Delete Buffered Audio Stream thread
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.002758490 "rtp.c:1972" Buffered TCP Reader Thread Exit via Cleanup.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.004132291 "rtp.c:2143" Buffered Audio Receiver Cleanup Start.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000372344 "rtp.c:2147" Connection 1: TCP Buffered Audio port closed: 56851.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000114011 "rtp.c:2149" Buffered Audio Receiver Cleanup Done.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000852968 "player.c:1679" Connection 1: Delete AirPlay 2 Control thread
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.001867032 "rtp.c:1633" Connection 1: AP2 Control Receiver Cleanup.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000328802 "rtp.c:1636" Connection 1: UDP control port 55005 closed.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000368698 "rtp.c:1331" Connection 1: Clear anchor information.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.001129218 "player.c:1734" Connection 1: player terminated.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.003686042 "player.c:3314" pend
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000325208 "rtsp.c:2508" Connection 1: TEARDOWN phase one complete
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.019892032 "rtsp.c:2622" Connection 1: SETUP (AirPlay 2)
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000358697 "rtsp.c:2900" Connection 1: SETUP on PTP stream. A "streams" array has been found
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000246042 "rtsp.c:2919" Connection 1: UDP control port opened: 36282.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000988386 "rtsp.c:3031" Connection 1. AP2 Buffered Audio Stream.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000150989 "rtsp.c:1053" Buffered Audio Stream SETUP incoming message
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000326979 "rtsp.c:1058" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>streams</key>
<array>
<dict>
<key>audioMode</key>
<string>default</string>
<key>ct</key>
<integer>4</integer>
<key>streamConnectionID</key>
<integer>8583881891892579306</integer>
<key>spf</key>
<integer>1024</integer>
<key>shk</key>
<data>
Sou/4mRqDbilxrXFWYd0lzFjZaFfiXKvOSjkBle3UAc=
</data>
<key>supportsDynamicStreamID</key>
<true/>
<key>audioFormat</key>
<integer>4194304</integer>
<key>clientID</key>
<string>com.apple.quicklook.extension.previewUI</string>
<key>type</key>
<integer>103</integer>
</dict>
</array>
</dict>
</plist>
--
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000534688 "rtsp.c:3049" Connection 1: TCP Buffered Audio port opened: 33189.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000988177 "player.c:3288" pbeg
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.001706614 "rtsp.c:1053" SETUP response
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000380625 "rtsp.c:1058" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>streams</key>
<array>
<dict>
<key>type</key>
<integer>103</integer>
<key>dataPort</key>
<integer>33189</integer>
<key>audioBufferSize</key>
<integer>8388608</integer>
<key>controlPort</key>
<integer>36282</integer>
</dict>
</array>
</dict>
</plist>
--
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000155625 "rtsp.c:1388" Responding with content of length 131
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.006754740 "rtp.c:1492" Connection 1: No clock anchor information.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000289427 "player.c:2092" Set initial volume to -9.913922.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000223438 "player.c:3145" Software attenuation set to -1591.184531, i.e 10492.709888 out of 65,536, for airplay volume of -9.913922
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000115989 "loudness.c:47" Volume: -15.9 dB - Loudness gain @10Hz: 0.0 dB
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.000332031 "player.c:3189" player_volume_without_notification: volume mode is 0, airplay volume is -9.913922, software_attenuation: -1591.184531, hardware_attenuation: 0.000000, muting is disabled.
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.001006198 "player.c:2095" Play begin
Mar 19 14:15:12 MiCROLABS-P3 shairport-sync[19238]: 20.004195982 "activity_monitor.c:91" aend
Mar 19 14:15:12 MiCROLABS-P3 shairport-sync[19238]: 0.001487709 "activity_monitor.c:172" am_state: am_inactive
...hmm besides this? Connection 1: No clock anchor information.
Nothing plays anymore (playhead not moving).
seeking with Apple TV in a movie right now (the first 5-10 skipping through timeline are usually working)
io_jack.c:389" audio_occupancy_now is 21484.
Mar 19 20:13:24 MiCROLABS-P3 shairport-sync[19238]: 0.006027552 "audio_jack.c:389" audio_occupancy_now is 21228.
Mar 19 20:13:24 MiCROLABS-P3 shairport-sync[19238]: 0.011973125 "audio_jack.c:389" audio_occupancy_now is 21480.
Mar 19 20:13:24 MiCROLABS-P3 shairport-sync[19238]: 0.005209427 "audio_jack.c:389" audio_occupancy_now is 21224.
Mar 19 20:13:24 MiCROLABS-P3 shairport-sync[19238]: 0.002360365 "rtsp.c:1839" anchor rate 0x0000000000000000.
Mar 19 20:13:24 MiCROLABS-P3 shairport-sync[19238]: 0.000223021 "rtsp.c:1848" Connection 13: Stop playing.
Mar 19 20:13:24 MiCROLABS-P3 shairport-sync[19238]: 0.000873177 "audio_jack.c:372" Only the consumer can safely flush a lock-free ringbuffer. Asking the process callback to do it...
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 14.670928223 "rtsp.c:1053" FLUSHBUFFERED request
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000334219 "rtsp.c:1058" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>flushUntilSeq</key>
<integer>6917789</integer>
<key>flushUntilTS</key>
<integer>4153268505</integer>
</dict>
</plist>
--
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000137396 "rtsp.c:1683" Can't find a flushFromSeq
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000077500 "rtsp.c:1695" Can't find a flushFromTS
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000063385 "rtsp.c:1708" flushUntilSeq is 6917789.
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000060625 "rtsp.c:1716" flushUntilTS is 4153268505.
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000074219 "rtsp.c:1763" Immediate Flush Requested
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000616458 "rtp.c:2401" Flush requested.
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000127344 "rtp.c:2407" untilTS: 4153268505
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000071927 "rtp.c:2408" untilSeq: 6917789
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000061458 "rtp.c:2409" --
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000063230 "rtp.c:2410" currentTS_Start: 4152871577
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000064323 "rtp.c:2412" framesInBuffer: 640
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000537864 "rtp.c:2414" currentTS_End: 4152872217
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000126511 "rtp.c:2415" currentSeq: 6917401
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000152760 "audio_jack.c:372" Only the consumer can safely flush a lock-free ringbuffer. Asking the process callback to do it...
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000077708 "rtp.c:2458" Immediate Buffered Audio Flush Started.
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.046695313 "rtsp.c:1053" TEARDOWN:
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.002675677 "rtsp.c:1058" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>streams</key>
<array>
<dict>
<key>streamID</key>
<integer>0</integer>
<key>type</key>
<integer>103</integer>
</dict>
</array>
</dict>
</plist>
--
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000248229 "rtsp.c:2504" Connection 13: TEARDOWN a PTP stream.
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.001027656 "player.c:1662" Cancelling AP2 timing, control and audio threads...
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000166615 "player.c:1671" Connection 13: Delete Buffered Audio Stream thread
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.001482500 "rtp.c:1972" Buffered TCP Reader Thread Exit via Cleanup.
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.002424062 "rtp.c:2143" Buffered Audio Receiver Cleanup Start.
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000489532 "rtp.c:2147" Connection 13: TCP Buffered Audio port closed: 48495.
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000133854 "rtp.c:2149" Buffered Audio Receiver Cleanup Done.
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000619687 "player.c:1679" Connection 13: Delete AirPlay 2 Control thread
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.001602813 "rtp.c:1633" Connection 13: AP2 Control Receiver Cleanup.
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000464323 "rtp.c:1636" Connection 13: UDP control port 39240 closed.
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.001713698 "rtp.c:1331" Connection 13: Clear anchor information.
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.001535781 "player.c:1734" Connection 13: player terminated.
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000768489 "player.c:3314" pend
Mar 19 20:13:39 MiCROLABS-P3 shairport-sync[19238]: 0.000278230 "rtsp.c:2508" Connection 13: TEARDOWN phase one complete
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 2.515726405 "rtsp.c:2622" Connection 13: SETUP (AirPlay 2)
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.004465364 "rtsp.c:2900" Connection 13: SETUP on PTP stream. A "streams" array has been found
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.000449063 "rtsp.c:2919" Connection 13: UDP control port opened: 39104.
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.005213646 "rtsp.c:3031" Connection 13. AP2 Buffered Audio Stream.
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.000259427 "rtsp.c:1053" Buffered Audio Stream SETUP incoming message
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.003755104 "rtsp.c:1058" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>streams</key>
<array>
<dict>
<key>audioMode</key>
<string>default</string>
<key>ct</key>
<integer>4</integer>
<key>streamConnectionID</key>
<integer>-5706519206798866631</integer>
<key>spf</key>
<integer>1024</integer>
<key>shk</key>
<data>
+74nYKD+CanMboaxV8Ci3L4qW5nKzzaUloQSP83aiFo=
</data>
<key>type</key>
<integer>103</integer>
<key>supportsDynamicStreamID</key>
<true/>
<key>audioFormat</key>
<integer>4194304</integer>
</dict>
</array>
</dict>
</plist>
--
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.000533177 "rtsp.c:3049" Connection 13: TCP Buffered Audio port opened: 37733.
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.000935417 "player.c:3288" pbeg
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.001287448 "rtsp.c:1053" SETUP response
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.000501406 "rtsp.c:1058" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>streams</key>
<array>
<dict>
<key>type</key>
<integer>103</integer>
<key>dataPort</key>
<integer>37733</integer>
<key>audioBufferSize</key>
<integer>8388608</integer>
<key>controlPort</key>
<integer>39104</integer>
</dict>
</array>
</dict>
</plist>
--
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.000209844 "rtsp.c:1388" Responding with content of length 131
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.004304739 "player.c:2092" Set initial volume to -15.000000.
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.000583438 "player.c:3145" Software attenuation set to -2889.000000, i.e 2354.940456 out of 65,536, for airplay volume of -15.000000
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.000202239 "loudness.c:47" Volume: -28.9 dB - Loudness gain @10Hz: 4.4 dB
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.000539167 "player.c:3189" player_volume_without_notification: volume mode is 0, airplay volume is -15.000000, software_attenuation: -2889.000000, hardware_attenuation: 0.000000, muting is disabled.
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.000214792 "player.c:2095" Play begin
Mar 19 20:13:42 MiCROLABS-P3 shairport-sync[19238]: 0.002353177 "rtp.c:1492" Connection 13: No clock anchor information.
Mar 19 20:14:02 MiCROLABS-P3 shairport-sync[19238]: 20.013576190 "activity_monitor.c:91" aend
Mar 19 20:14:02 MiCROLABS-P3 shairport-sync[19238]: 0.002108594 "activity_monitor.c:172" am_state: am_inactive
yeah, no crash – but I was unable to get sound back - video didn't playback anymore - freeze until I deselected SPS as destination in ATV (and went to bed...). And btw the script also doesn't get triggered.
And "the script" is the
run_this_after_exiting_active_state = "/bin/bash /usr/local/bin/webhook_airplay_stop_script.sh"; // make sure the application has executable permission. If it's a script, include the shebang (#!/bin/...) on the first line
script?
Many thanks for your detective work! That message:
Mar 19 14:14:52 MiCROLABS-P3 shairport-sync[19238]: 0.006754740 "rtp.c:1492" Connection 1: No clock anchor information.
is intriguing.
indeed.
Sadly I have more sad news. Amazon Prime is again not working at all on ATV and Youtube with TV connect doesn‘t work either. Should I grab some more logs?
The script works btw perfectly when everything else works — maybe let’s ignore that issue for now.
Should I try rebuilding both packets (SPS + NTPthing) again?
Thanks. The Amazon Prime and YouTube issues may well be different issues. It seems that both have been working on different forms of content protection, e.g. see here, so it may be a content protection thing.
The significance of the fact that the script didn't work is that it may be that the thread it is called from didn't execute because it hung up somewhere -- so it's another clue, thanks.
Unfortunately, it'll be about three weeks before I am back at a location where I have access to an ATV. I haven't been able to provoke any of these problems without it.
Meantime, if you could ensure you're on the latest of everything, it would make any logs you can generate (yes please!) much more useful.
If you have time (next week or so?), it would be great if we could work on more logs together. It's still a lot of struggle / restarting SPS / reconnecting / seeking in time to reestablish working audio.
This issue has been inactive for 45 days so will be closed 7 days from now. To prevent this, please remove the "stale" label or post a comment.
noooo :)
Yikes, apologies for neglecting this.
There have been quite a few updates in the past few weeks to NQPTP and Shairport Sync, including one to stop duplicate script launching.
So, first question: do the problems persist when everything is updated? Also, what computer are you using? Have you looked at its loading, whether it gets bogged down by the Jack Audio interface?
haha no worries! All good!
I just thought about it yesterday when it happened again - and I realized it happens not too often anymore. Can't remember when I last updated - maybe a month ago.
Will update tomorrow, try to reproduce and report back!
This issue has been inactive for 45 days so will be closed 7 days from now. To prevent this, please remove the "stale" label or post a comment.
Using jack audio as backend.
It works for a few videos but like the 3rd or fourth is always not sending any audio anymore (video freezes). Also with music from time to time. Then SPS either crashes or I need to reconnect.
Which loglevel should I use best? 3? It spams too much sync buffer information without much more information. I am running SPS under a different user (jack) – I read this is not good ... but otherwise I'm unable to connect to jack which runs under the user jack as a system service.
Any clues are welcome!