[Problem]: Buffered_read issue

[a-eukarya]

What happened?

Hi Mike Brady,

I hope this isn’t spamming issue reports. I’d like to report some unusual behavior I’ve been observing.

The main issue is that shairport-sync repeatedly logs “buffered_read: waiting for x bytes,” which results either in complete playback failure or 5–15 seconds of silence.
This only seems to happen during control actions such as skipping tracks, switching to another song, or occasionally pausing.

When this issue does not occur, all playback controls (including track skipping) work normally and without any noticeable delay.

Interestingly, the issue does not occur when AirPlay is active on multiple outputs simultaneously at all. For example, if I start playback to a HomePod FIRST and then add shairport-sync as an additional AirPlay target, shairport-sync plays reliably without dropouts or skips (not vice versa).

I’ve tried adjusting various shairport-sync.conf settings and rebooting network devices, but none made a noticeable difference. I couldn’t find an identical report, though some open issues seem to show partially similar symptoms. It may possibly be related to OS 26.

Please let me know if logs or further testing would be helpful.

Relevant log output

Jan 03 23:08:57   shairport-sync[612]:          0.000106354 "rtsp.c:1841"   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>13000069</integer>
                                                    <key>flushUntilTS</key>
                                                    <integer>1034737188</integer>
                                            </dict>
                                            </plist>
                                            --
Jan 03 23:08:57   shairport-sync[612]:          0.000072292 "rtsp.c:1852" Can't find a flushFromSeq
Jan 03 23:08:57   shairport-sync[612]:          0.000041302 "rtsp.c:1864" Can't find a flushFromTS
Jan 03 23:08:57   shairport-sync[612]:          0.000039948 "rtsp.c:1877" flushUntilSeq is 13000069.
Jan 03 23:08:57   shairport-sync[612]:          0.000038958 "rtsp.c:1885" flushUntilTS is 1034737188.
Jan 03 23:08:57   shairport-sync[612]:          0.000039792 "rtsp.c:1932" Immediate Flush Requested
Jan 03 23:08:57   shairport-sync[612]:          0.018720625 "rtp.c:2445" Flush requested.
Jan 03 23:08:57   shairport-sync[612]:          0.000122917 "rtp.c:2451"   untilTS:         1034737188
Jan 03 23:08:57   shairport-sync[612]:          0.000042604 "rtp.c:2452"   untilSeq:        13000069
Jan 03 23:08:57   shairport-sync[612]:          0.000039218 "rtp.c:2453" --
Jan 03 23:08:57   shairport-sync[612]:          0.000047605 "rtp.c:2454"   currentTS_Start: 1029238308
Jan 03 23:08:57   shairport-sync[612]:          0.000037291 "rtp.c:2456"   framesInBuffer:  1024
Jan 03 23:08:57   shairport-sync[612]:          0.000037032 "rtp.c:2458"   currentTS_End:   1029239332
Jan 03 23:08:57   shairport-sync[612]:          0.000036562 "rtp.c:2459"   currentSeq:      12994699
Jan 03 23:08:57   shairport-sync[612]:          0.000083438 "rtp.c:2523" Immediate Buffered Audio Flush Started.
Jan 03 23:08:57   shairport-sync[612]:          0.000441510 "rtp.c:1968" buffered_read: waiting for 305 bytes.
Jan 03 23:08:57   shairport-sync[612]:          0.004396354 "rtsp.c:2558" Connection 67: POST /audioMode Content-Length 64
Jan 03 23:08:57   shairport-sync[612]:          0.000100677 "rtsp.c:2560"   Type: "Content-Length", content: "64"
Jan 03 23:08:57   shairport-sync[612]:          0.000042136 "rtsp.c:2560"   Type: "Content-Type", content: "application/x-apple-binary-plist"
Jan 03 23:08:57   shairport-sync[612]:          0.000040989 "rtsp.c:2560"   Type: "CSeq", content: "30"
Jan 03 23:08:57   shairport-sync[612]:          0.000038073 "rtsp.c:2560"   Type: "User-Agent", content: "AirPlay/925.5.1"
Jan 03 23:08:57   shairport-sync[612]:          0.000084844 "rtsp.c:2560"   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>audioMode</key>
                                                    <string>default</string>
                                            </dict>
                                            </plist>
                                            --
Jan 03 23:08:57   shairport-sync[612]:          0.413014427 "rtp.c:1968" buffered_read: waiting for 69 bytes.
Jan 03 23:08:57   shairport-sync[612]:          0.000242552 "rtp.c:1968" buffered_read: waiting for 287 bytes.
Jan 03 23:08:57   shairport-sync[612]:          0.000407292 "rtp.c:1968" buffered_read: waiting for 545 bytes.
Jan 03 23:08:57   shairport-sync[612]:          0.001817187 "rtp.c:1968" buffered_read: waiting for 480 bytes.
Jan 03 23:08:57   shairport-sync[612]:          0.000834479 "rtp.c:1968" buffered_read: waiting for 290 bytes.
Jan 03 23:08:57   shairport-sync[612]:          0.101394584 "rtsp.c:1970" networkTimeTimelineID "80b989c830880008".
Jan 03 23:08:57   shairport-sync[612]:          0.000138281 "rtsp.c:1975" anchor networkTimeSecs is 21585.
Jan 03 23:08:57   shairport-sync[612]:          0.000057864 "rtsp.c:1980" anchor networkTimeFrac is 05554605176821645312.
Jan 03 23:08:57   shairport-sync[612]:          0.000040730 "rtsp.c:1991" anchorTimeNanoseconds looks like 21585301115749.
Jan 03 23:08:57   shairport-sync[612]:          0.000041822 "rtp.c:1274" set_ptp_anchor_info: clock: 80b989c830880008, rtptime: 4032754673, networktime: 13a1b8349365.
Jan 03 23:08:57   shairport-sync[612]:          0.000050625 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp B"
Jan 03 23:08:57   shairport-sync[612]:          0.000874948 "rtsp.c:2018" Connection 67: Start playing, with anchor clock 80b989c830880008.
Jan 03 23:08:57   shairport-sync[612]:          0.022880782 "rtp.c:1406" Connection 67: NQPTP master clock 80b989c830880008.
Jan 03 23:08:58   shairport-sync[612]:          0.937795000 "rtp.c:2494" Play started.
Jan 03 23:08:58   shairport-sync[612]:          0.000762969 "rtp.c:1968" buffered_read: waiting for 205 bytes.
Jan 03 23:08:58   shairport-sync[612]:          0.000666093 "rtp.c:1968" buffered_read: waiting for 457 bytes.
Jan 03 23:08:58   shairport-sync[612]:          0.000445678 "rtp.c:1968" buffered_read: waiting for 121 bytes.
Jan 03 23:08:58   shairport-sync[612]:          0.000206406 "rtp.c:1968" buffered_read: waiting for 15 bytes.
Jan 03 23:08:59   shairport-sync[612]:          0.816815000 "rtp.c:1968" buffered_read: waiting for 484 bytes.
Jan 03 23:08:59   shairport-sync[612]:          0.000684687 "rtp.c:1968" buffered_read: waiting for 35 bytes.
Jan 03 23:08:59   shairport-sync[612]:          0.000264635 "rtp.c:1968" buffered_read: waiting for 489 bytes.
Jan 03 23:08:59   shairport-sync[612]:          0.000220573 "rtp.c:1968" buffered_read: waiting for 279 bytes.
Jan 03 23:08:59   shairport-sync[612]:          0.000358230 "rtp.c:1968" buffered_read: waiting for 45 bytes.
Jan 03 23:08:59   shairport-sync[612]:          0.000145052 "rtp.c:1968" buffered_read: waiting for 452 bytes.
Jan 03 23:08:59   shairport-sync[612]:          0.000327291 "rtp.c:1968" buffered_read: waiting for 621 bytes.
Jan 03 23:08:59   shairport-sync[612]:          0.000270469 "rtp.c:1968" buffered_read: waiting for 437 bytes.
Jan 03 23:08:59   shairport-sync[612]:          0.000108594 "rtp.c:1968" buffered_read: waiting for 262 bytes.
Jan 03 23:09:00   shairport-sync[612]:          1.260590156 "rtp.c:1968" buffered_read: waiting for 468 bytes.
Jan 03 23:09:00   shairport-sync[612]:          0.000798854 "rtp.c:1968" buffered_read: waiting for 248 bytes.
Jan 03 23:09:00   shairport-sync[612]:          0.000363750 "rtp.c:1968" buffered_read: waiting for 227 bytes.
Jan 03 23:09:00   shairport-sync[612]:          0.000344323 "rtp.c:1968" buffered_read: waiting for 408 bytes.
Jan 03 23:09:00   shairport-sync[612]:          0.000150937 "rtp.c:1968" buffered_read: waiting for 379 bytes.
Jan 03 23:09:00   shairport-sync[612]:          0.000376615 "rtp.c:1968" buffered_read: waiting for 327 bytes.
Jan 03 23:09:00   shairport-sync[612]:          0.000267656 "rtp.c:1968" buffered_read: waiting for 232 bytes.
Jan 03 23:09:01   shairport-sync[612]:          0.815912708 "rtp.c:1968" buffered_read: waiting for 163 bytes.
Jan 03 23:09:01   shairport-sync[612]:          0.001158385 "rtp.c:1968" buffered_read: waiting for 100 bytes.
Jan 03 23:09:01   shairport-sync[612]:          0.001060782 "rtp.c:1968" buffered_read: waiting for 321 bytes.
Jan 03 23:09:01   shairport-sync[612]:          0.000272448 "rtp.c:1968" buffered_read: waiting for 404 bytes.
Jan 03 23:09:02   shairport-sync[612]:          1.258634009 "rtp.c:1968" buffered_read: waiting for 349 bytes.
Jan 03 23:09:02   shairport-sync[612]:          0.000644375 "rtp.c:1968" buffered_read: waiting for 77 bytes.
Jan 03 23:09:02   shairport-sync[612]:          0.000502813 "rtp.c:1968" buffered_read: waiting for 353 bytes.
Jan 03 23:09:02   shairport-sync[612]:          0.000305312 "rtp.c:1968" buffered_read: waiting for 313 bytes.
Jan 03 23:09:02   shairport-sync[612]:          0.000223750 "rtp.c:1968" buffered_read: waiting for 479 bytes.
Jan 03 23:09:02   shairport-sync[612]:          0.000387813 "rtp.c:1968" buffered_read: waiting for 527 bytes.
Jan 03 23:09:02   shairport-sync[612]:          0.000222187 "rtp.c:1968" buffered_read: waiting for 817 bytes.
Jan 03 23:09:02   shairport-sync[612]:          0.000222605 "rtp.c:1968" buffered_read: waiting for 180 bytes.
Jan 03 23:09:03   shairport-sync[612]:          0.818823697 "rtp.c:1968" buffered_read: waiting for 569 bytes.
Jan 03 23:09:03   shairport-sync[612]:          0.000737604 "rtp.c:1968" buffered_read: waiting for 17 bytes.
Jan 03 23:09:03   shairport-sync[612]:          0.000382084 "rtp.c:1968" buffered_read: waiting for 499 bytes.
Jan 03 23:09:03   shairport-sync[612]:          0.000373906 "rtp.c:1968" buffered_read: waiting for 389 bytes.
Jan 03 23:09:03   shairport-sync[612]:          0.000189323 "rtp.c:1968" buffered_read: waiting for 614 bytes.
Jan 03 23:09:03   shairport-sync[612]:          0.000141771 "rtp.c:1968" buffered_read: waiting for 689 bytes.
Jan 03 23:09:03   shairport-sync[612]:          0.000141562 "rtp.c:1968" buffered_read: waiting for 20 bytes.
Jan 03 23:09:03   shairport-sync[612]:          0.000155990 "rtp.c:1968" buffered_read: waiting for 93 bytes.
Jan 03 23:09:03   shairport-sync[612]:          0.000146979 "rtp.c:1968" buffered_read: waiting for 136 bytes.
Jan 03 23:09:05   shairport-sync[612]:          1.257239322 "rtp.c:1968" buffered_read: waiting for 641 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000386980 "rtp.c:1968" buffered_read: waiting for 741 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000292604 "rtp.c:1968" buffered_read: waiting for 358 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000268750 "rtp.c:1968" buffered_read: waiting for 690 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000613489 "rtp.c:1968" buffered_read: waiting for 395 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000246980 "rtp.c:1968" buffered_read: waiting for 15 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000307447 "rtp.c:1968" buffered_read: waiting for 684 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000223698 "rtp.c:1968" buffered_read: waiting for 194 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.839957917 "rtp.c:1968" buffered_read: waiting for 705 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000603593 "rtp.c:1968" buffered_read: waiting for 545 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000250730 "rtp.c:1968" buffered_read: waiting for 71 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000214895 "rtp.c:1968" buffered_read: waiting for 217 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000213178 "rtp.c:1968" buffered_read: waiting for 619 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000399218 "rtp.c:1968" buffered_read: waiting for 473 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000218334 "rtp.c:1968" buffered_read: waiting for 618 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000273020 "rtp.c:1968" buffered_read: waiting for 639 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.000124688 "rtp.c:1968" buffered_read: waiting for 84 bytes.
Jan 03 23:09:05   shairport-sync[612]:          0.018715208 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp P"
Jan 03 23:09:05   shairport-sync[612]:          0.000925990 "rtsp.c:2028" Connection 67: Pause playing.
Jan 03 23:09:05   shairport-sync[612]:          0.000125000 "rtp.c:1322" Connection 67: Clear anchor information.
Jan 03 23:09:05   shairport-sync[612]:          0.000088750 "rtsp.c:2036" Connection 67: Stop the output backend.
Jan 03 23:09:05   shairport-sync[612]:          0.024827760 "rtp.c:1428" Connection 67: Awaiting clock anchor information.
Jan 03 23:09:06   shairport-sync[612]:          0.772893125 "rtp.c:2484" Play stopped.
Jan 03 23:09:06   shairport-sync[612]:          0.000354844 "rtp.c:1968" buffered_read: waiting for 495 bytes.
Jan 03 23:09:06   shairport-sync[612]:          0.000382239 "rtp.c:1968" buffered_read: waiting for 335 bytes.
Jan 03 23:09:06   shairport-sync[612]:          0.000155886 "rtp.c:1968" buffered_read: waiting for 661 bytes.
Jan 03 23:09:06   shairport-sync[612]:          0.000880052 "rtp.c:1968" buffered_read: waiting for 269 bytes.
Jan 03 23:09:06   shairport-sync[612]:          0.000330937 "rtp.c:1968" buffered_read: waiting for 609 bytes.
Jan 03 23:09:06   shairport-sync[612]:          0.000182292 "rtp.c:1968" buffered_read: waiting for 480 bytes.
Jan 03 23:09:06   shairport-sync[612]:          0.000231667 "rtp.c:1968" buffered_read: waiting for 34 bytes.
Jan 03 23:09:06   shairport-sync[612]:          0.000185520 "rtp.c:1968" buffered_read: waiting for 383 bytes.
Jan 03 23:09:06   shairport-sync[612]:          0.000307136 "rtp.c:1968" buffered_read: waiting for 455 bytes.
Jan 03 23:09:07   shairport-sync[612]:          1.271237968 "rtp.c:1968" buffered_read: waiting for 701 bytes.
Jan 03 23:09:07   shairport-sync[612]:          0.000280104 "rtp.c:1968" buffered_read: waiting for 436 bytes.
Jan 03 23:09:07   shairport-sync[612]:          0.000158802 "rtp.c:1968" buffered_read: waiting for 625 bytes.
Jan 03 23:09:07   shairport-sync[612]:          0.000806980 "rtp.c:1968" buffered_read: waiting for 748 bytes.
Jan 03 23:09:07   shairport-sync[612]:          0.000179479 "rtp.c:1968" buffered_read: waiting for 388 bytes.
Jan 03 23:09:07   shairport-sync[612]:          0.000145416 "rtp.c:1968" buffered_read: waiting for 753 bytes.
Jan 03 23:09:07   shairport-sync[612]:          0.000238959 "rtp.c:1968" buffered_read: waiting for 347 bytes.
Jan 03 23:09:07   shairport-sync[612]:          0.000134791 "rtp.c:1968" buffered_read: waiting for 528 bytes.
Jan 03 23:09:07   shairport-sync[612]:          0.000695105 "rtp.c:1968" buffered_read: waiting for 225 bytes.
Jan 03 23:09:07   shairport-sync[612]:          0.000234010 "rtp.c:1968" buffered_read: waiting for 523 bytes.
Jan 03 23:09:07   shairport-sync[612]:          0.000191042 "rtp.c:1968" buffered_read: waiting for 733 bytes.
Jan 03 23:09:08   shairport-sync[612]:          0.816658489 "rtp.c:1968" buffered_read: waiting for 30 bytes.
Jan 03 23:09:08   shairport-sync[612]:          0.000461094 "rtp.c:1968" buffered_read: waiting for 629 bytes.
Jan 03 23:09:08   shairport-sync[612]:          0.000604166 "rtp.c:1968" buffered_read: waiting for 803 bytes.
Jan 03 23:09:08   shairport-sync[612]:          0.001405677 "rtp.c:1968" buffered_read: waiting for 700 bytes.
Jan 03 23:09:10   shairport-sync[612]:          1.275410000 "rtp.c:1968" buffered_read: waiting for 699 bytes.
Jan 03 23:09:10   shairport-sync[612]:          0.000266979 "rtp.c:1968" buffered_read: waiting for 211 bytes.
Jan 03 23:09:10   shairport-sync[612]:          0.002709219 "rtp.c:1968" buffered_read: waiting for 139 bytes.
Jan 03 23:09:10   shairport-sync[612]:          0.815133229 "rtp.c:1968" buffered_read: waiting for 495 bytes.
Jan 03 23:09:10   shairport-sync[612]:          0.000963802 "rtp.c:1968" buffered_read: waiting for 543 bytes.
Jan 03 23:09:10   shairport-sync[612]:          0.000532448 "rtp.c:1968" buffered_read: waiting for 269 bytes.
Jan 03 23:09:10   shairport-sync[612]:          0.000451093 "rtp.c:1968" buffered_read: waiting for 164 bytes.
Jan 03 23:09:10   shairport-sync[612]:          0.000160886 "rtp.c:1968" buffered_read: waiting for 272 bytes.
Jan 03 23:09:10   shairport-sync[612]:          0.000127917 "rtp.c:1968" buffered_read: waiting for 478 bytes.
Jan 03 23:09:12   shairport-sync[612]:          1.276313541 "rtp.c:1968" buffered_read: waiting for 654 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000265885 "rtp.c:1968" buffered_read: waiting for 43 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000509896 "rtp.c:1968" buffered_read: waiting for 610 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000174635 "rtp.c:1968" buffered_read: waiting for 70 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000440052 "rtp.c:1968" buffered_read: waiting for 743 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000163125 "rtp.c:1968" buffered_read: waiting for 262 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000135417 "rtp.c:1968" buffered_read: waiting for 331 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000192448 "rtp.c:1968" buffered_read: waiting for 390 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000144115 "rtp.c:1968" buffered_read: waiting for 748 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000165156 "rtp.c:1968" buffered_read: waiting for 116 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000445885 "rtp.c:1968" buffered_read: waiting for 236 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.816667448 "rtp.c:1968" buffered_read: waiting for 451 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000465417 "rtp.c:1968" buffered_read: waiting for 316 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000369791 "rtp.c:1968" buffered_read: waiting for 72 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000323282 "rtp.c:1968" buffered_read: waiting for 862 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000189791 "rtp.c:1968" buffered_read: waiting for 290 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000244688 "rtp.c:1968" buffered_read: waiting for 335 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000137812 "rtp.c:1968" buffered_read: waiting for 598 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000139896 "rtp.c:1968" buffered_read: waiting for 26 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000157865 "rtp.c:1968" buffered_read: waiting for 281 bytes.
Jan 03 23:09:12   shairport-sync[612]:          0.000204948 "rtp.c:1968" buffered_read: waiting for 523 bytes.
Jan 03 23:09:14   shairport-sync[612]:          1.276439218 "rtp.c:1968" buffered_read: waiting for 758 bytes.
Jan 03 23:09:14   shairport-sync[612]:          0.000531354 "rtp.c:1968" buffered_read: waiting for 39 bytes.
Jan 03 23:09:14   shairport-sync[612]:          0.000302292 "rtp.c:1968" buffered_read: waiting for 7 bytes.
Jan 03 23:09:14   shairport-sync[612]:          0.000599427 "rtp.c:1968" buffered_read: waiting for 146 bytes.
Jan 03 23:09:14   shairport-sync[612]:          0.000281458 "rtp.c:1968" buffered_read: waiting for 320 bytes.
Jan 03 23:09:14   shairport-sync[612]:          0.000176563 "rtp.c:1968" buffered_read: waiting for 66 bytes.
Jan 03 23:09:14   shairport-sync[612]:          0.000261562 "rtp.c:1968" buffered_read: waiting for 458 bytes.
Jan 03 23:09:14   shairport-sync[612]:          0.000091615 "rtp.c:1968" buffered_read: waiting for 738 bytes.
Jan 03 23:09:14   shairport-sync[612]:          0.000222135 "rtp.c:1968" buffered_read: waiting for 127 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.817429218 "rtp.c:1968" buffered_read: waiting for 547 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000253490 "rtp.c:1968" buffered_read: waiting for 98 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000246198 "rtp.c:1968" buffered_read: waiting for 437 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000233229 "rtp.c:1968" buffered_read: waiting for 619 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000330365 "rtp.c:1968" buffered_read: waiting for 169 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000234010 "rtp.c:1968" buffered_read: waiting for 665 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000345521 "rtp.c:1968" buffered_read: waiting for 559 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000151458 "rtp.c:1968" buffered_read: waiting for 136 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000311302 "rtp.c:1968" buffered_read: waiting for 334 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000298021 "rtp.c:1968" buffered_read: waiting for 832 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.813635781 "activity_monitor.c:84" aend
Jan 03 23:09:15   shairport-sync[612]:          0.000189531 "rtp.c:1968" buffered_read: waiting for 293 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000533437 "rtp.c:1968" buffered_read: waiting for 326 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000317552 "rtp.c:1968" buffered_read: waiting for 533 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000285938 "rtp.c:1968" buffered_read: waiting for 119 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000252760 "rtp.c:1968" buffered_read: waiting for 662 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000188490 "rtp.c:1968" buffered_read: waiting for 28 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000074792 "rtp.c:1968" buffered_read: waiting for 221 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000126718 "rtp.c:1968" buffered_read: waiting for 377 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.000168334 "rtp.c:1968" buffered_read: waiting for 573 bytes.
Jan 03 23:09:15   shairport-sync[612]:          0.003407188 "activity_monitor.c:163" am_state: am_inactive
Jan 03 23:09:16   shairport-sync[612]:          0.304750625 "rtsp.c:2749" Connection 67: TEARDOWN 2 PTP stream.
Jan 03 23:09:16   shairport-sync[612]:          0.000136562 "rtsp.c:2751" TEARDOWN:
Jan 03 23:09:16   shairport-sync[612]:          0.000044167 "rtsp.c:2751"   Type: "Content-Length", content: "84"
Jan 03 23:09:16   shairport-sync[612]:          0.000039531 "rtsp.c:2751"   Type: "Content-Type", content: "application/x-apple-binary-plist"
Jan 03 23:09:16   shairport-sync[612]:          0.000039948 "rtsp.c:2751"   Type: "CSeq", content: "48"
Jan 03 23:09:16   shairport-sync[612]:          0.000038177 "rtsp.c:2751"   Type: "User-Agent", content: "AirPlay/925.5.1"
Jan 03 23:09:16   shairport-sync[612]:          0.000149115 "rtsp.c:2751"   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>
                                            --
Jan 03 23:09:16   shairport-sync[612]:          0.000079583 "rtsp.c:2760" Connection 67: TEARDOWN PTP stream -- close the stream.
Jan 03 23:09:16   shairport-sync[612]:          0.000042344 "player.c:3655" Connection 67: player_stop.
Jan 03 23:09:16   shairport-sync[612]:          0.000450260 "player.c:1827" Cancelling AP2 timing, control and audio threads...
Jan 03 23:09:16   shairport-sync[612]:          0.000069011 "player.c:1836" Connection 67: Delete Buffered Audio Stream thread
Jan 03 23:09:16   shairport-sync[612]:          0.000935625 "rtp.c:2010" Buffered TCP Reader Thread Exit via Cleanup.
Jan 03 23:09:16   shairport-sync[612]:          0.000550781 "rtp.c:2183" Buffered Audio Receiver Cleanup Start.
Jan 03 23:09:16   shairport-sync[612]:          0.000207552 "rtp.c:2186" Connection 67: TCP Buffered Audio port closed: 39527.
Jan 03 23:09:16   shairport-sync[612]:          0.000058958 "rtp.c:2189" Buffered Audio Receiver Cleanup Done.
Jan 03 23:09:16   shairport-sync[612]:          0.000414948 "player.c:1844" Connection 0: Delete AirPlay 2 Control thread
Jan 03 23:09:16   shairport-sync[612]:          0.000409636 "rtp.c:1633" Connection 67: AP2 Control Receiver Cleanup.
Jan 03 23:09:16   shairport-sync[612]:          0.000198281 "rtp.c:1635" Connection 67: UDP control port 59040 closed.
Jan 03 23:09:16   shairport-sync[612]:          0.000245625 "rtp.c:1322" Connection 67: Clear anchor information.
Jan 03 23:09:16   shairport-sync[612]:          0.001015104 "player.c:432" 11264 buffers allocated, 11264 buffers released.
Jan 03 23:09:16   shairport-sync[612]:          0.000087396 "player.c:1897" Connection 67: player terminated.
Jan 03 23:09:16   shairport-sync[612]:          0.000358854 "player.c:3670" Connection 67: player_stop successful.
Jan 03 23:09:16   shairport-sync[612]:          0.000077083 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp E"
Jan 03 23:09:16   shairport-sync[612]:          0.001067865 "rtsp.c:2765" Connection 67: TEARDOWN PTP stream -- close the stream complete
Jan 03 23:09:45   shairport-sync[612]:         29.796558895 "rtsp.c:671" One active connection.
Jan 03 23:27:23   shairport-sync[612]:       1057.099999076 "rtsp.c:2880" Connection 67: SETUP (AirPlay 2)
Jan 03 23:27:23   shairport-sync[612]:          0.000247083 "rtsp.c:3223" Connection 67: SETUP on PTP stream. A "streams" array has been found
Jan 03 23:27:23   shairport-sync[612]:          0.000056250 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp B"
Jan 03 23:27:23   shairport-sync[612]:          0.001029635 "rtsp.c:3251" Connection 67: UDP control port opened: 46574.
Jan 03 23:27:23   shairport-sync[612]:          0.000300782 "rtsp.c:3270" Connection 67: SETUP AP2 no Active-Remote information  the SETUP Record.
Jan 03 23:27:23   shairport-sync[612]:          0.000058593 "rtsp.c:3289" Connection 67: SETUP AP2 doesn't include DACP-ID string information.
Jan 03 23:27:23   shairport-sync[612]:          0.000052917 "rtsp.c:3304" Connection 67. AP2 Realtime Audio Stream.
Jan 03 23:27:23   shairport-sync[612]:          0.000040573 "rtsp.c:3305" Realtime Audio Stream SETUP incoming message
Jan 03 23:27:23   shairport-sync[612]:          0.000038021 "rtsp.c:3305"   Type: "Content-Length", content: "350"
Jan 03 23:27:23   shairport-sync[612]:          0.000040104 "rtsp.c:3305"   Type: "Content-Type", content: "application/x-apple-binary-plist"
Jan 03 23:27:23   shairport-sync[612]:          0.000043385 "rtsp.c:3305"   Type: "CSeq", content: "255"
Jan 03 23:27:23   shairport-sync[612]:          0.000037865 "rtsp.c:3305"   Type: "User-Agent", content: "AirPlay/925.5.1"

System Information.

Raspberry Pi 3B with Debian 12 PiOS lite (64bit)
Wired ethernet

Configuration Information.

eukarya@EKRP3B:~ $ shairport-sync --displayConfig
         0.003668386 "shairport.c:1474" default metadata_pipename is "/tmp/shairport-sync-metadata".
         0.000594270 "shairport.c:2133" >> Display Config Start.
         0.008149740 "shairport.c:2133" 
         0.000181771 "shairport.c:2133" From "uname -a":
         0.000143906 "shairport.c:2133"  Linux username 6.12.47+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.12.47-1+rpt1~bookworm (2025-09-16) aarch64 GNU/Linux
         0.023817396 "shairport.c:2133" 
         0.000297864 "shairport.c:2133" From /etc/os-release:
         0.000108803 "shairport.c:2133"  Debian GNU/Linux 12 (bookworm)
         0.009905156 "shairport.c:2133" 
         0.000184166 "shairport.c:2133" From /sys/firmware/devicetree/base/model:
         0.000088646 "shairport.c:2133"  Raspberry Pi 3 Model B Rev 1.2
         0.000180625 "shairport.c:2133" 
         0.000087396 "shairport.c:2133" Shairport Sync Version String:
         0.000080104 "shairport.c:2133"  4.3.7-5-g3c8ceb7c-AirPlay2-smi10-OpenSSL-Avahi-ALSA-soxr-metadata-mqtt-sysconfdir:/etc
         0.000107136 "shairport.c:2133" 
         0.000087135 "shairport.c:2133" Command Line:
         0.000086146 "shairport.c:2133"  shairport-sync --displayConfig
         0.000240573 "shairport.c:2133" 
         0.000092708 "shairport.c:2133" Configuration File:
         0.000079844 "shairport.c:2133"  /etc/shairport-sync.conf
         0.000081510 "shairport.c:2133" 
         0.000603802 "shairport.c:2133" Configuration File Settings:
         0.000090261 "shairport.c:2133"  general : 
         0.000030260 "shairport.c:2133"  {
         0.000034479 "shairport.c:2133"    name = "Klipsh R12";
         0.000024740 "shairport.c:2133"    playback_mode = "reverse stereo";
         0.000044583 "shairport.c:2133"    volume_range_db = 30;
         0.000026407 "shairport.c:2133"    default_airplay_volume = -25.0;
         0.000024531 "shairport.c:2133"    audio_backend_buffer_desired_length_in_seconds = 0.9;
         0.000024739 "shairport.c:2133"  };
         0.000022032 "shairport.c:2133"  alsa : 
         0.000022291 "shairport.c:2133"  {
         0.000021980 "shairport.c:2133"    output_device = "hw:Audio";
         0.000103177 "shairport.c:2133"    mixer_control_name = "PCM";
         0.000028125 "shairport.c:2133"    output_rate = 44100;
         0.000024010 "shairport.c:2133"    output_format = "S16";
         0.000023490 "shairport.c:2133"    period_size = 1024;
         0.000022916 "shairport.c:2133"    buffer_size = 8192;
         0.000022657 "shairport.c:2133"    disable_standby_mode = "always";
         0.000022812 "shairport.c:2133"  };
         0.000021406 "shairport.c:2133"  pw : 
         0.000021719 "shairport.c:2133"  {
         0.000020990 "shairport.c:2133"  };
         0.000021510 "shairport.c:2133"  diagnostics : 
         0.000022031 "shairport.c:2133"  {
         0.000021563 "shairport.c:2133"    log_verbosity = 2;
         0.000023021 "shairport.c:2133"  };
         0.000022031 "shairport.c:2133" 
         0.000020833 "shairport.c:2133" >> Display Config End.

PulseAudio or PipeWire installed?

• Check if your system uses a Sound Server.

How did you install Shairport Sync?

Homebrew for Mac

Check previous issues

• Confirm

[mikebrady]

Thanks for the report. What would be useful is to change over to the development version.

The problem is that Shairport Sync goes silent while waiting for audio data. This could for two general reasons: the audio has been lost, or it was never provided.

The audio could be lost because Shairport Sync has mistakenly flushed it, and that is something that has been worked on recently. The development version incorporates all the fixes we know about, hence the suggestion to change over to it.

However, there are some situation where the audio just doesn't seem to be supplied -- please see here for a discussion.

So, the thing to do, if you'd be kind enough, is to move to the development version and see what happens.

[a-eukarya]

Thank you for your suggestion to try the development version.
Unfortunately, the issue still persists on the current dev 5.0 branch.
Also checked the thread you mentioned. Source I'm currently using is Apple Music subscription based music, lossless disabled.
I hope this information is useful for further development of this amazing project.

Version I tried:
shairport-sync -V 5.0-dev-154-g3746c82f-AirPlay2-smi10-OpenSSL-Avahi-ALSA-soxr-metadata-sysconfdir:/etc

Log 1 - Showing the same "buffered_read". This section repeats for about 30 seconds, until iPhone gives up and disconnects.

--
<?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>sr</key>
                        <real>48000</real>
                </dict>
        </array>
</dict>
</plist>
--
         0.005813806 "utilities/buffered_read.c:53" buffered_read: signalled with 1428 bytes after waiting.
         0.000330834 "utilities/buffered_read.c:45" buffered_read: buffer empty -- waiting for 610 bytes.
         0.000868490 "utilities/buffered_read.c:53" buffered_read: signalled with 5524 bytes after waiting.
         0.000360886 "utilities/buffered_read.c:45" buffered_read: buffer empty -- waiting for 500 bytes.
         0.000950574 "utilities/buffered_read.c:53" buffered_read: signalled with 20480 bytes after waiting.
         0.000354427 "utilities/buffered_read.c:45" buffered_read: buffer empty -- waiting for 384 bytes.
         0.009672508 "utilities/buffered_read.c:147" recv of up to 4096 bytes with an buffer empty.
         0.000196198 "utilities/buffered_read.c:53" buffered_read: signalled with 2556 bytes after waiting.
         0.000145729 "utilities/buffered_read.c:45" buffered_read: buffer empty -- waiting for 51 bytes.
         1.262700669 "utilities/buffered_read.c:53" buffered_read: signalled with 1428 bytes after waiting.
         0.000154271 "utilities/buffered_read.c:45" buffered_read: buffer empty -- waiting for 137 bytes.
         0.001067344 "utilities/buffered_read.c:53" buffered_read: signalled with 1428 bytes after waiting.
         0.000299740 "utilities/buffered_read.c:45" buffered_read: buffer empty -- waiting for 186 bytes.
         0.000880991 "utilities/buffered_read.c:53" buffered_read: signalled with 4096 bytes after waiting.
         0.000203854 "utilities/buffered_read.c:45" buffered_read: buffer empty -- waiting for 88 bytes.
         0.000957136 "utilities/buffered_read.c:53" buffered_read: signalled with 8192 bytes after waiting.
         0.000185469 "utilities/buffered_read.c:45" buffered_read: buffer empty -- waiting for 486 bytes.
         0.000956824 "utilities/buffered_read.c:53" buffered_read: signalled with 8192 bytes after waiting.
         0.000188281 "utilities/buffered_read.c:45" buffered_read: buffer empty -- waiting for 281 bytes.
         0.000941824 "utilities/buffered_read.c:53" buffered_read: signalled with 4096 bytes after waiting.
         0.000217448 "utilities/buffered_read.c:45" buffered_read: buffer empty -- waiting for 476 bytes.
         0.000920521 "utilities/buffered_read.c:53" buffered_read: signalled with 2556 bytes after waiting.
         0.000076875 "utilities/buffered_read.c:45" buffered_read: buffer empty -- waiting for 10 bytes.
         0.735551510 "rtsp.c:5090" Connection 1: (PTP stream) received an RTSP Packet of type "POST":
         0.000176146 "rtsp.c:5093"   Type: "CSeq", content: "101"
         0.000102656 "rtsp.c:5093"   Type: "User-Agent", content: "AirPlay/925.5.1"
         0.000081667 "rtsp.c:5093"   No Content Plist. Content length: 0.
         0.000294479 "rtsp.c:5154" Connection 1: (PTP stream) RTSP response:
         0.000033229 "rtsp.c:5156"   Response Code: 200.
         0.000024167 "rtsp.c:5156"   Type: "CSeq", content: "101"
         0.000023021 "rtsp.c:5156"   Type: "Server", content: "AirTunes/366.0"
         0.000022968 "rtsp.c:5156"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000256042 "rtsp.c:5156"   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>sr</key>
                        <real>48000</real>
                </dict>
        </array>
</dict>
</plist>--
<?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>sr</key>
                        <real>48000</real>
                </dict>
        </array>
</dict>
</plist>

Log 2 – This may be the flush error you mentioned. It occurs every time a new song starts. This behavior is completely independent of the issue observed in Log 1.

         1.501422944 "shairport.c:281" "soxr" interpolation has been chosen.
         3.768429531 "player.c:999" Channel Mapping: | 0 ("FL") <- FL | 1 ("FR") <- FR |
        16.051876275 "ap2_buffered_audio_processor.c:343" immediate flush may have escaped its endpoint! Seq_no is 541187, conn->ap2_immediate_flush_until_sequence_number is 540643.
        14.400057662 "ap2_buffered_audio_processor.c:343" immediate flush may have escaped its endpoint! Seq_no is 547679, conn->ap2_immediate_flush_until_sequence_number is 547088.
        41.880832086 "ap2_buffered_audio_processor.c:343" immediate flush may have escaped its endpoint! Seq_no is 555468, conn->ap2_immediate_flush_until_sequence_number is 555045.
       165.540956784 "ap2_buffered_audio_processor.c:343" immediate flush may have escaped its endpoint! Seq_no is 569057, conn->ap2_immediate_flush_until_sequence_number is 569046.

[mikebrady]

Very interesting, thanks. I’d like to try to replicate this if possible, especially the log 2 stuff. Are you using a playlist? If so, could you share it please? And have you enabled or permitted AutoMix and Shuffle?

[mikebrady]

Actually, I am able to generate some anomalies myself, thanks to your guidance. So I won't be needing more information just now.

[a-eukarya]

Oh, great! Just so you know, I wasn’t testing with a playlist, and I didn’t have Automix on. But I did have shuffle enabled. The album I was using was “This is…Icona Pop” from the Icona Pop album. Cheers!

[mikebrady]

So, I've been experimenting with this. Right now, I'm on a rather slow internet connection -- 10 megabits per second with a ping time of 40 to 100 milliseconds, and it's pretty easy to cause this problem. However, the problem seems to be that the audio for the "missing' track actually isn't there. That is, it hasn't been sent by the source. But if the "missing" track is allowed the time to complete, the next track's data starts appearing and play resumes.

So, would you characterise your internet connection as slow?

[a-eukarya]

Hi, I tested my setup as well.
Bandwidth does not appear to be the limiting factor. On a Raspberry Pi 3B, peak download speed is ~80 Mbps. The rest of the LAN is Gigabit and stable.

Ping characteristics are more interesting.
Any wired connection to/from the Pi is very stable, never exceeding 0.7 ms.
However, connections involving Wi-Fi show sudden spikes. From the Pi to Wi-Fi clients, I observe spikes up to ~110 ms.
Pi to iPhone: typically 2 to 6 ms, but spikes up to ~110 ms
Pi to Mac: typically 2 to 6 ms, spikes up to ~70 ms

So while overall bandwidth is fine, the network does show irregular ping spikes on Wi-Fi. I assume this has something to do with the AWDL, but wasn't able to resolve it by changing Wi-Fi channel settings.

[mikebrady]

Thanks. The whole thing makes no sense to me at the moment.

[a-eukarya]

Haha, I see! Fingers crossed someone can crack this one soon. I’ll keep you posted as I gather more info to help out. Thanks, mikebrady!