search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.29k stars 574 forks source link

Audio out-of-sync when streaming from macOS Sierra #380

Closed wilchak closed 8 years ago

wilchak commented 8 years ago

I've noticed that since upgrading to Sierra, the audio is always 2 seconds behind the video when I play files in VLC and mpv. However, the audio IS in sync when playing from QuickTime. It's not clear if QT is doing something right and the other two are doing it wrong. But both VLC and mpv worked fine in El Capitan.

This started happening in the Sierra Public Beta and I thought it was an Apple bug that might get fixed, but it's still happening in the general release. I have not tested other video player apps besides VLC and mpv.

I'm not sure how best I can help you diagnose this issue, but what I've done to start is put log_verbosity=3 and send you two dumps, captured from about 20-40 seconds of streaming each:

Log when playing from mpv:

Sep 28 21:16:10 raspberrypi shairport-sync[5359]: volume range in dB (zero means use the range specified by the mixer): 0. Sep 28 21:16:10 raspberrypi shairport-sync[5359]: zeroconf regtype is "_raop._tcp". Sep 28 21:16:10 raspberrypi shairport-sync[5359]: configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf". Sep 28 21:16:10 raspberrypi shairport-sync[5359]: Successful Startup Sep 28 21:16:10 raspberrypi shairport-sync[5359]: avahi: avahi_register. Sep 28 21:16:10 raspberrypi shairport-sync[5359]: avahi: register_service. Sep 28 21:16:10 raspberrypi shairport-sync[5359]: avahi: service 'E44CB0D660BB@Big Stereo' group is not yet commited. Sep 28 21:16:10 raspberrypi shairport-sync[5359]: avahi: request to add "_raop._tcp" service without metadata Sep 28 21:16:10 raspberrypi shairport-sync[5359]: avahi: service 'E44CB0D660BB@Big Stereo' group is registering. Sep 28 21:16:11 raspberrypi shairport-sync[5359]: avahi: service 'E44CB0D660BB@Big Stereo' successfully added. Sep 28 21:17:47 raspberrypi shairport-sync[5359]: New RTSP connection from 192.168.18.51:58530 to self at 192.168.18.30:5000. Sep 28 21:17:48 raspberrypi shairport-sync[5359]: CSeq: 0. Sep 28 21:17:48 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:17:48 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:17:48 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:17:48 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:17:48 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "0" Sep 28 21:17:48 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:17:48 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:17:48 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:17:48 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:17:48 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "0" Sep 28 21:17:48 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:17:48 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: CSeq: 1. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "1" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "1" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Apple-Challenge: UZ+xV4QBAF8TkMHUj+0HzA==. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: CSeq: 2. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "Apple-Challenge", content: "UZ+xV4QBAF8TkMHUj+0HzA==" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "2" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "Apple-Response", content: "HQ0vOXCs5ssPVriqCYEJurda/My3ZB800gKjI0Uf/ZpvValZyhlm9NBZLsHWGfBEB02B+GJfPHaJg+fv9IHeGdLGdEvfKa8XvdZqUqVpVNM3UeMeGm9ae2C5gLfRdIciWEZpjJPXPPVNecu/2ESiv74KeuUQx0/gUCxItA4r51ElWSXPxXTo8b/kXrxG5Q9ifopNrhyZA+1m/UHCt7HAsdFjtkCDQ9Z1JxCjafzlCyqarL6pwtQP+Q6rE2PTebVEgoe7Yk2hYHiMKf0E9My/2qPCDFifF5S/k3zhr3HZQTwha9ebI2P6aF0zdCDgD53c3TaTpNoe7qbXy5CiPkrUFA" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "2" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Content-Length: 640. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Content-Type: application/sdp. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: CSeq: 3. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:01 raspberrypi shairport-sync[5359]: RTSP Packet received of type "ANNOUNCE": Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "Content-Length", content: "640" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "Content-Type", content: "application/sdp" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "3" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:01 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Play connection from user agent "AirPlay/301.43.2". Sep 28 21:18:02 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "3" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Transport: RTP/AVP/UDP;unicast;mode=record;timing_port=62545;control_port=62776. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: CSeq: 4. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: RTSP Packet received of type "SETUP": Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "Transport", content: "RTP/AVP/UDP;unicast;mode=record;timing_port=62545;control_port=62776" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "4" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Active-Remote string seen: "1589781961". Sep 28 21:18:02 raspberrypi shairport-sync[5359]: User-Agent is AirPlay; selecting the AirPlay latency of -1 frames. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: rtp_setup: cport=62776 tport=62545. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Set up play connection from 192.168.18.51 to self at 192.168.18.30. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: listening for audio, control and timing on ports 6001, 6002, 6003. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "4" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6002;timing_port=6003;server_port=6001" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "Session", content: "1" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Timing receiver -- Server RTP thread starting. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: sync error in frames, 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 Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Control receiver -- Server RTP thread starting. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Audio receiver -- Server RTP thread starting. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Timing sender thread starting. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: CSeq: 5. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: RTSP Packet received of type "RECORD": Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "5" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "5" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "Audio-Latency", content: "11025" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Content-Length: 20. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Content-Type: text/parameters. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: CSeq: 6. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: RTSP Packet received of type "SET_PARAMETER": Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "Content-Length", content: "20" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "Content-Type", content: "text/parameters" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "6" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: volume: -18.061800 Sep 28 21:18:02 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "6" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:02 raspberrypi shairport-sync[5359]: syncing to seqno 14824. Sep 28 21:18:02 raspberrypi shairport-sync[5359]: PCM handle name = 'hw:1,0' Sep 28 21:18:02 raspberrypi shairport-sync[5359]: alsa device parameters: Sep 28 21:18:02 raspberrypi shairport-sync[5359]: access type = RW_INTERLEAVED Sep 28 21:18:02 raspberrypi shairport-sync[5359]: format = 'S16_LE' (Signed 16 bit Little Endian) Sep 28 21:18:02 raspberrypi shairport-sync[5359]: subformat = 'STD' (Standard) Sep 28 21:18:02 raspberrypi shairport-sync[5359]: number of channels = 2 Sep 28 21:18:02 raspberrypi shairport-sync[5359]: number of significant bits = 16 Sep 28 21:18:02 raspberrypi shairport-sync[5359]: rate = 44100 frames per second (precisely). Sep 28 21:18:02 raspberrypi shairport-sync[5359]: precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512). Sep 28 21:18:02 raspberrypi shairport-sync[5359]: period_time = 5804 us (>). Sep 28 21:18:02 raspberrypi shairport-sync[5359]: period_size = 256 frames (precisely). Sep 28 21:18:02 raspberrypi shairport-sync[5359]: buffer_time = 5944308 us (>). Sep 28 21:18:02 raspberrypi shairport-sync[5359]: buffer_size = 262144 frames (>). Sep 28 21:18:02 raspberrypi shairport-sync[5359]: periods_per_buffer = 1024 (precisely). Sep 28 21:18:02 raspberrypi shairport-sync[5359]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:18:02 raspberrypi shairport-sync[5359]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:18:02 raspberrypi shairport-sync[5359]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:18:02 raspberrypi shairport-sync[5359]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:18:02 raspberrypi shairport-sync[5359]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4415 Sep 28 21:18:03 raspberrypi shairport-sync[5359]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:18:03 raspberrypi shairport-sync[5359]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:18:03 raspberrypi shairport-sync[5359]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:18:04 raspberrypi shairport-sync[5359]: CSeq: 7. Sep 28 21:18:04 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:04 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:04 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:04 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:04 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "7" Sep 28 21:18:04 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:04 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:04 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:04 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:04 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "7" Sep 28 21:18:04 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:04 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:06 raspberrypi shairport-sync[5359]: CSeq: 8. Sep 28 21:18:06 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:06 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:06 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:06 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:06 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "8" Sep 28 21:18:06 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:06 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:06 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:06 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:06 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "8" Sep 28 21:18:06 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:06 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:08 raspberrypi shairport-sync[5359]: CSeq: 9. Sep 28 21:18:08 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:08 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:08 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:08 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:08 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "9" Sep 28 21:18:08 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:08 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:08 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:08 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:08 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "9" Sep 28 21:18:08 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:08 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:10 raspberrypi shairport-sync[5359]: CSeq: 10. Sep 28 21:18:10 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:10 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:10 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:10 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:10 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "10" Sep 28 21:18:10 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:10 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:10 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:10 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:10 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "10" Sep 28 21:18:10 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:10 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:12 raspberrypi shairport-sync[5359]: CSeq: 11. Sep 28 21:18:12 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:12 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:12 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:12 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:12 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "11" Sep 28 21:18:12 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:12 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:12 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:12 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:12 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "11" Sep 28 21:18:12 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:12 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:14 raspberrypi shairport-sync[5359]: CSeq: 12. Sep 28 21:18:14 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:14 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:14 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:14 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:14 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "12" Sep 28 21:18:14 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:14 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:14 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:14 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:14 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "12" Sep 28 21:18:14 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:14 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:16 raspberrypi shairport-sync[5359]: CSeq: 13. Sep 28 21:18:16 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:16 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:16 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:16 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:16 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "13" Sep 28 21:18:16 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:16 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:16 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:16 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:16 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "13" Sep 28 21:18:16 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:16 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:18 raspberrypi shairport-sync[5359]: CSeq: 14. Sep 28 21:18:18 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:18 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:18 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:18 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:18 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "14" Sep 28 21:18:18 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:18 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:18 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:18 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:18 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "14" Sep 28 21:18:18 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:18 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:20 raspberrypi shairport-sync[5359]: CSeq: 15. Sep 28 21:18:20 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:20 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:20 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:20 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:20 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "15" Sep 28 21:18:20 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:20 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:20 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:20 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:20 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "15" Sep 28 21:18:20 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:20 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:21 raspberrypi shairport-sync[5359]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 7980.2, 12467.1, 32021.0. Sep 28 21:18:22 raspberrypi shairport-sync[5359]: CSeq: 16. Sep 28 21:18:22 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:22 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:22 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:22 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:22 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "16" Sep 28 21:18:22 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:22 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:22 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:22 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:22 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "16" Sep 28 21:18:22 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:22 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:24 raspberrypi shairport-sync[5359]: CSeq: 17. Sep 28 21:18:24 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:24 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:24 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:24 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:24 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "17" Sep 28 21:18:24 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:24 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:24 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:24 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:24 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "17" Sep 28 21:18:24 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:24 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:26 raspberrypi shairport-sync[5359]: CSeq: 18. Sep 28 21:18:26 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:26 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:26 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:26 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:26 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "18" Sep 28 21:18:26 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:26 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:26 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:26 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:26 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "18" Sep 28 21:18:26 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:26 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:28 raspberrypi shairport-sync[5359]: CSeq: 19. Sep 28 21:18:28 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:28 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:28 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:28 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:28 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "19" Sep 28 21:18:28 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:28 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:28 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:28 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:28 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "19" Sep 28 21:18:28 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:28 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:30 raspberrypi shairport-sync[5359]: CSeq: 20. Sep 28 21:18:30 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:30 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:30 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:30 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:30 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "20" Sep 28 21:18:30 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:30 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:30 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:30 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:30 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "20" Sep 28 21:18:30 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:30 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:32 raspberrypi shairport-sync[5359]: CSeq: 21. Sep 28 21:18:32 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:32 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:32 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:32 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:32 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "21" Sep 28 21:18:32 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:32 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:32 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:32 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:32 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "21" Sep 28 21:18:32 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:32 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:33 raspberrypi shairport-sync[5359]: -25.2, 0.0, 0.0, 3758, 0, 0, 0, 0, 4309, 226, 233 Sep 28 21:18:34 raspberrypi shairport-sync[5359]: CSeq: 22. Sep 28 21:18:34 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:34 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:34 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:34 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:34 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "22" Sep 28 21:18:34 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:34 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:34 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:34 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:34 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "22" Sep 28 21:18:34 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:34 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:36 raspberrypi shairport-sync[5359]: CSeq: 23. Sep 28 21:18:36 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:36 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:36 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:36 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:36 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "23" Sep 28 21:18:36 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:36 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:36 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:36 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:36 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "23" Sep 28 21:18:36 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:36 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:38 raspberrypi shairport-sync[5359]: CSeq: 24. Sep 28 21:18:38 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:38 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:38 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:38 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:38 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "24" Sep 28 21:18:38 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:38 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:38 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:38 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:38 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "24" Sep 28 21:18:38 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:38 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:40 raspberrypi shairport-sync[5359]: CSeq: 25. Sep 28 21:18:40 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:40 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:40 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:40 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:40 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "25" Sep 28 21:18:40 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:40 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:40 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:40 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:40 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "25" Sep 28 21:18:40 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:40 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:41 raspberrypi shairport-sync[5359]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 7980.4, 12371.7, 31111.0. Sep 28 21:18:42 raspberrypi shairport-sync[5359]: CSeq: 26. Sep 28 21:18:42 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:42 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:42 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:42 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:42 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "26" Sep 28 21:18:42 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:42 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:42 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:42 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:42 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "26" Sep 28 21:18:42 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:42 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:44 raspberrypi shairport-sync[5359]: CSeq: 27. Sep 28 21:18:44 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:44 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:44 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:44 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:44 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "27" Sep 28 21:18:44 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:44 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:44 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:44 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:44 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "27" Sep 28 21:18:44 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:44 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:46 raspberrypi shairport-sync[5359]: CSeq: 28. Sep 28 21:18:46 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:46 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:46 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:46 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:46 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "28" Sep 28 21:18:46 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:46 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:46 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:46 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:46 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "28" Sep 28 21:18:46 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:46 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:48 raspberrypi shairport-sync[5359]: CSeq: 29. Sep 28 21:18:48 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:48 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:48 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:48 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:48 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "29" Sep 28 21:18:48 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:48 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:48 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:48 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:48 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "29" Sep 28 21:18:48 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:48 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:50 raspberrypi shairport-sync[5359]: CSeq: 30. Sep 28 21:18:50 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:50 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:50 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:50 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:50 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "30" Sep 28 21:18:50 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:50 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:50 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:50 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:50 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "30" Sep 28 21:18:50 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:50 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:52 raspberrypi shairport-sync[5359]: CSeq: 31. Sep 28 21:18:52 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:52 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:52 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:52 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:52 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "31" Sep 28 21:18:52 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:52 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:52 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:52 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:52 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "31" Sep 28 21:18:52 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:52 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:54 raspberrypi shairport-sync[5359]: CSeq: 32. Sep 28 21:18:54 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:54 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:54 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:54 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:54 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "32" Sep 28 21:18:54 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:54 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:54 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:54 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:54 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "32" Sep 28 21:18:54 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:54 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:56 raspberrypi shairport-sync[5359]: CSeq: 33. Sep 28 21:18:56 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:56 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:56 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:56 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:56 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "33" Sep 28 21:18:56 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:56 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:56 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:56 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:56 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "33" Sep 28 21:18:56 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:56 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:18:58 raspberrypi shairport-sync[5359]: CSeq: 34. Sep 28 21:18:58 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:18:58 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:18:58 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:18:58 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:18:58 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "34" Sep 28 21:18:58 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:18:58 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:18:58 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:18:58 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:18:58 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "34" Sep 28 21:18:58 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:18:58 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:19:00 raspberrypi shairport-sync[5359]: CSeq: 35. Sep 28 21:19:00 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:19:00 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:19:00 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:19:00 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:19:00 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "35" Sep 28 21:19:00 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:19:00 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:19:00 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:19:00 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:19:00 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "35" Sep 28 21:19:00 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:19:00 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:19:01 raspberrypi shairport-sync[5359]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 7979.6, 12297.3, 36398.0. Sep 28 21:19:02 raspberrypi shairport-sync[5359]: CSeq: 36. Sep 28 21:19:02 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:19:02 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:19:02 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:19:02 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:19:02 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "36" Sep 28 21:19:02 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:19:02 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:19:02 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:19:02 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:19:02 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "36" Sep 28 21:19:02 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:19:02 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:19:03 raspberrypi shairport-sync[5359]: -52.6, 24.2, 24.2, 7516, 0, 0, 0, 0, 6061, 226, 231 Sep 28 21:19:04 raspberrypi shairport-sync[5359]: CSeq: 37. Sep 28 21:19:04 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:19:04 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:19:04 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:19:04 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:19:04 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "37" Sep 28 21:19:04 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:19:04 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:19:04 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:19:04 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:19:04 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "37" Sep 28 21:19:04 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:19:04 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:19:06 raspberrypi shairport-sync[5359]: CSeq: 38. Sep 28 21:19:06 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:19:06 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:19:06 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:19:06 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:19:06 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "38" Sep 28 21:19:06 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:19:06 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:19:06 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:19:06 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:19:06 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "38" Sep 28 21:19:06 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:19:06 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:19:08 raspberrypi shairport-sync[5359]: CSeq: 39. Sep 28 21:19:08 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:19:08 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:19:08 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:19:08 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:19:08 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "39" Sep 28 21:19:08 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:19:08 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:19:08 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:19:08 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:19:08 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "39" Sep 28 21:19:08 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:19:08 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:19:10 raspberrypi shairport-sync[5359]: CSeq: 40. Sep 28 21:19:10 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:19:10 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:19:10 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:19:10 raspberrypi shairport-sync[5359]: RTSP Packet received of type "OPTIONS": Sep 28 21:19:10 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "40" Sep 28 21:19:10 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:19:10 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:19:10 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:19:10 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:19:10 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "40" Sep 28 21:19:10 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:19:10 raspberrypi shairport-sync[5359]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:19:12 raspberrypi shairport-sync[5359]: CSeq: 41. Sep 28 21:19:12 raspberrypi shairport-sync[5359]: DACP-ID: A5F347844B85E03A. Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Active-Remote: 1589781961. Sep 28 21:19:12 raspberrypi shairport-sync[5359]: User-Agent: AirPlay/301.43.2. Sep 28 21:19:12 raspberrypi shairport-sync[5359]: RTSP Packet received of type "TEARDOWN": Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "41" Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Type: "DACP-ID", content: "A5F347844B85E03A" Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Type: "Active-Remote", content: "1589781961" Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:19:12 raspberrypi shairport-sync[5359]: RTSP Response: Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Type: "CSeq", content: "41" Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Type: "Connection", content: "close" Sep 28 21:19:12 raspberrypi shairport-sync[5359]: RTSP shutdown requested. Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Closing down RTSP conversation thread... Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Playback Stopped. Total playing time 00:01:10 Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Shut down audio, control and timing threads Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Control RTP thread interrupted. terminating. Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Timing thread interrupted. terminating. Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Audio receiver -- Server RTP thread interrupted. terminating. Sep 28 21:19:12 raspberrypi shairport-sync[5359]: rtp_timing_sender thread interrupted. terminating. Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Closed and terminated timer requester thread. Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Timing RTP thread terminated. Sep 28 21:19:12 raspberrypi shairport-sync[5359]: timing thread joined Sep 28 21:19:12 raspberrypi shairport-sync[5359]: audio thread joined Sep 28 21:19:12 raspberrypi shairport-sync[5359]: control thread joined Sep 28 21:19:12 raspberrypi shairport-sync[5359]: Player thread exit Sep 28 21:19:12 raspberrypi shairport-sync[5359]: shutting down RTP thread Sep 28 21:19:12 raspberrypi shairport-sync[5359]: RTSP conversation thread terminated.

Log when playing from QuickTime:

Sep 28 21:27:22 raspberrypi shairport-sync[5477]: volume range in dB (zero means use the range specified by the mixer): 0. Sep 28 21:27:22 raspberrypi shairport-sync[5477]: zeroconf regtype is "_raop._tcp". Sep 28 21:27:22 raspberrypi shairport-sync[5477]: configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf". Sep 28 21:27:22 raspberrypi shairport-sync[5477]: Successful Startup Sep 28 21:27:22 raspberrypi shairport-sync[5477]: avahi: avahi_register. Sep 28 21:27:22 raspberrypi shairport-sync[5477]: avahi: register_service. Sep 28 21:27:22 raspberrypi shairport-sync[5477]: avahi: service 'E44CB0D660BB@Big Stereo' group is not yet commited. Sep 28 21:27:22 raspberrypi shairport-sync[5477]: avahi: request to add "_raop._tcp" service without metadata Sep 28 21:27:22 raspberrypi shairport-sync[5477]: avahi: service 'E44CB0D660BB@Big Stereo' group is registering. Sep 28 21:27:23 raspberrypi shairport-sync[5477]: avahi: service 'E44CB0D660BB@Big Stereo' successfully added. Sep 28 21:27:27 raspberrypi shairport-sync[5477]: New RTSP connection from 192.168.18.51:58577 to self at 192.168.18.30:5000. Sep 28 21:27:27 raspberrypi shairport-sync[5477]: CSeq: 0. Sep 28 21:27:27 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:27 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:27 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:27 raspberrypi shairport-sync[5477]: RTSP Packet received of type "OPTIONS": Sep 28 21:27:27 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "0" Sep 28 21:27:27 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:27 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:27 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:27 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:27 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "0" Sep 28 21:27:27 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:27 raspberrypi shairport-sync[5477]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: CSeq: 1. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: RTSP Packet received of type "OPTIONS": Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "1" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "1" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Apple-Challenge: 1C0H5Is47k14NDITJuaKMg==. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: CSeq: 2. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: RTSP Packet received of type "OPTIONS": Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Apple-Challenge", content: "1C0H5Is47k14NDITJuaKMg==" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "2" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Apple-Response", content: "Edr7bIUD9erTNnIJjUjvIJFJC2Y1d7rdY7cKA81R+ItktmCubkxP4hTYD9lKmgXOquZqa+D+TuHvtpCSwXJQMPxAKItM0iPwgP/xtp1FKTUiAl3a9TeYhSxJTV1ttoJ68CSdGyw7crg43vx09PRjour1pEUI3i9mNu2+By2t7qfjo1dJil92c32EaHdrkEN3BPFrhjcvb5GHKzIr8a2Qz/Z1Cjpm907TaPxp+wKHK17phl7D9TwyPlGup+LrwgV564yjWRxRuBRHJkamkxCRtTUkZVX6WAZOtgIT+tJqImpujbgYtWFX/7njNBD1StMkdyxsUVYkKTNKvgVeQu95hg" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "2" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Content-Length: 640. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Content-Type: application/sdp. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: CSeq: 3. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: RTSP Packet received of type "ANNOUNCE": Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Content-Length", content: "640" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Content-Type", content: "application/sdp" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "3" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Play connection from user agent "AirPlay/301.43.2". Sep 28 21:27:37 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "3" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Transport: RTP/AVP/UDP;unicast;mode=record;timing_port=58867;control_port=63690. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: CSeq: 4. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: RTSP Packet received of type "SETUP": Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Transport", content: "RTP/AVP/UDP;unicast;mode=record;timing_port=58867;control_port=63690" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "4" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Active-Remote string seen: "2070366383". Sep 28 21:27:37 raspberrypi shairport-sync[5477]: User-Agent is AirPlay; selecting the AirPlay latency of -1 frames. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: rtp_setup: cport=63690 tport=58867. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Set up play connection from 192.168.18.51 to self at 192.168.18.30. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: listening for audio, control and timing on ports 6001, 6002, 6003. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "4" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6002;timing_port=6003;server_port=6001" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Session", content: "1" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Control receiver -- Server RTP thread starting. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Audio receiver -- Server RTP thread starting. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: sync error in frames, 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 Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Timing receiver -- Server RTP thread starting. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Timing sender thread starting. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: CSeq: 5. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: RTSP Packet received of type "RECORD": Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "5" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "5" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Audio-Latency", content: "11025" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Content-Length: 20. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Content-Type: text/parameters. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: CSeq: 6. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: RTSP Packet received of type "SET_PARAMETER": Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Content-Length", content: "20" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Content-Type", content: "text/parameters" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "6" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: volume: -12.041201 Sep 28 21:27:37 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "6" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:37 raspberrypi shairport-sync[5477]: syncing to seqno 42591. Sep 28 21:27:37 raspberrypi shairport-sync[5477]: PCM handle name = 'hw:1,0' Sep 28 21:27:37 raspberrypi shairport-sync[5477]: alsa device parameters: Sep 28 21:27:37 raspberrypi shairport-sync[5477]: access type = RW_INTERLEAVED Sep 28 21:27:37 raspberrypi shairport-sync[5477]: format = 'S16_LE' (Signed 16 bit Little Endian) Sep 28 21:27:37 raspberrypi shairport-sync[5477]: subformat = 'STD' (Standard) Sep 28 21:27:37 raspberrypi shairport-sync[5477]: number of channels = 2 Sep 28 21:27:37 raspberrypi shairport-sync[5477]: number of significant bits = 16 Sep 28 21:27:37 raspberrypi shairport-sync[5477]: rate = 44100 frames per second (precisely). Sep 28 21:27:37 raspberrypi shairport-sync[5477]: precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512). Sep 28 21:27:37 raspberrypi shairport-sync[5477]: period_time = 5804 us (>). Sep 28 21:27:37 raspberrypi shairport-sync[5477]: period_size = 256 frames (precisely). Sep 28 21:27:37 raspberrypi shairport-sync[5477]: buffer_time = 5944308 us (>). Sep 28 21:27:37 raspberrypi shairport-sync[5477]: buffer_size = 262144 frames (>). Sep 28 21:27:37 raspberrypi shairport-sync[5477]: periods_per_buffer = 1024 (precisely). Sep 28 21:27:37 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:27:37 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4411 Sep 28 21:27:37 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:27:37 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:27:37 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4417 Sep 28 21:27:37 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:27:37 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:27:38 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4415 Sep 28 21:27:38 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:27:38 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:27:38 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:27:38 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4411 Sep 28 21:27:38 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:27:38 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:27:38 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4415 Sep 28 21:27:38 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:27:39 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:27:39 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Sep 28 21:27:39 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4415 Sep 28 21:27:39 raspberrypi shairport-sync[5477]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4415 Sep 28 21:27:39 raspberrypi shairport-sync[5477]: CSeq: 7. Sep 28 21:27:39 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:39 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:39 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:39 raspberrypi shairport-sync[5477]: RTSP Packet received of type "OPTIONS": Sep 28 21:27:39 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "7" Sep 28 21:27:39 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:39 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:39 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:39 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:39 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "7" Sep 28 21:27:39 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:39 raspberrypi shairport-sync[5477]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:27:41 raspberrypi shairport-sync[5477]: CSeq: 8. Sep 28 21:27:41 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:41 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:41 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:41 raspberrypi shairport-sync[5477]: RTSP Packet received of type "OPTIONS": Sep 28 21:27:41 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "8" Sep 28 21:27:41 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:41 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:41 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:41 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:41 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "8" Sep 28 21:27:41 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:41 raspberrypi shairport-sync[5477]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:27:43 raspberrypi shairport-sync[5477]: CSeq: 9. Sep 28 21:27:43 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:43 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:43 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:43 raspberrypi shairport-sync[5477]: RTSP Packet received of type "OPTIONS": Sep 28 21:27:43 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "9" Sep 28 21:27:43 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:43 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:43 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:43 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:43 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "9" Sep 28 21:27:43 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:43 raspberrypi shairport-sync[5477]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:27:45 raspberrypi shairport-sync[5477]: CSeq: 10. Sep 28 21:27:45 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:45 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:45 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:45 raspberrypi shairport-sync[5477]: RTSP Packet received of type "OPTIONS": Sep 28 21:27:45 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "10" Sep 28 21:27:45 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:45 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:45 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:45 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:45 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "10" Sep 28 21:27:45 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:45 raspberrypi shairport-sync[5477]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:27:47 raspberrypi shairport-sync[5477]: CSeq: 11. Sep 28 21:27:47 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:47 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:47 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:47 raspberrypi shairport-sync[5477]: RTSP Packet received of type "OPTIONS": Sep 28 21:27:47 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "11" Sep 28 21:27:47 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:47 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:47 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:47 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:47 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "11" Sep 28 21:27:47 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:47 raspberrypi shairport-sync[5477]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:27:49 raspberrypi shairport-sync[5477]: CSeq: 12. Sep 28 21:27:49 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:49 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:49 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:49 raspberrypi shairport-sync[5477]: RTSP Packet received of type "OPTIONS": Sep 28 21:27:49 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "12" Sep 28 21:27:49 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:49 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:49 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:49 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:49 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "12" Sep 28 21:27:49 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:49 raspberrypi shairport-sync[5477]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:27:51 raspberrypi shairport-sync[5477]: CSeq: 13. Sep 28 21:27:51 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:51 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:51 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:51 raspberrypi shairport-sync[5477]: RTSP Packet received of type "OPTIONS": Sep 28 21:27:51 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "13" Sep 28 21:27:51 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:51 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:51 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:51 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:51 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "13" Sep 28 21:27:51 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:51 raspberrypi shairport-sync[5477]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:27:53 raspberrypi shairport-sync[5477]: CSeq: 14. Sep 28 21:27:53 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:53 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:53 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:53 raspberrypi shairport-sync[5477]: RTSP Packet received of type "OPTIONS": Sep 28 21:27:53 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "14" Sep 28 21:27:53 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:53 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:53 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:53 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:53 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "14" Sep 28 21:27:53 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:53 raspberrypi shairport-sync[5477]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:27:55 raspberrypi shairport-sync[5477]: CSeq: 15. Sep 28 21:27:55 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:55 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:55 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:55 raspberrypi shairport-sync[5477]: RTSP Packet received of type "OPTIONS": Sep 28 21:27:55 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "15" Sep 28 21:27:55 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:55 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:55 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:55 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:55 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "15" Sep 28 21:27:55 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:55 raspberrypi shairport-sync[5477]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:27:57 raspberrypi shairport-sync[5477]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 7992.1, 12795.3, 31494.0. Sep 28 21:27:57 raspberrypi shairport-sync[5477]: CSeq: 16. Sep 28 21:27:57 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:57 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:57 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:57 raspberrypi shairport-sync[5477]: RTSP Packet received of type "OPTIONS": Sep 28 21:27:57 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "16" Sep 28 21:27:57 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:57 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:57 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:57 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:57 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "16" Sep 28 21:27:57 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:57 raspberrypi shairport-sync[5477]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER" Sep 28 21:27:58 raspberrypi shairport-sync[5477]: CSeq: 17. Sep 28 21:27:58 raspberrypi shairport-sync[5477]: DACP-ID: 1FF53827F9295D56. Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Active-Remote: 2070366383. Sep 28 21:27:58 raspberrypi shairport-sync[5477]: User-Agent: AirPlay/301.43.2. Sep 28 21:27:58 raspberrypi shairport-sync[5477]: RTSP Packet received of type "TEARDOWN": Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "17" Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Type: "DACP-ID", content: "1FF53827F9295D56" Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Type: "Active-Remote", content: "2070366383" Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Type: "User-Agent", content: "AirPlay/301.43.2" Sep 28 21:27:58 raspberrypi shairport-sync[5477]: RTSP Response: Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Type: "CSeq", content: "17" Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Type: "Server", content: "AirTunes/105.1" Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Type: "Connection", content: "close" Sep 28 21:27:58 raspberrypi shairport-sync[5477]: RTSP shutdown requested. Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Closing down RTSP conversation thread... Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Playback Stopped. Total playing time 00:00:21 Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Shut down audio, control and timing threads Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Timing thread interrupted. terminating. Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Control RTP thread interrupted. terminating. Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Audio receiver -- Server RTP thread interrupted. terminating. Sep 28 21:27:58 raspberrypi shairport-sync[5477]: rtp_timing_sender thread interrupted. terminating. Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Closed and terminated timer requester thread. Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Timing RTP thread terminated. Sep 28 21:27:58 raspberrypi shairport-sync[5477]: timing thread joined Sep 28 21:27:58 raspberrypi shairport-sync[5477]: audio thread joined Sep 28 21:27:58 raspberrypi shairport-sync[5477]: control thread joined Sep 28 21:27:58 raspberrypi shairport-sync[5477]: Player thread exit Sep 28 21:27:58 raspberrypi shairport-sync[5477]: shutting down RTP thread Sep 28 21:27:58 raspberrypi shairport-sync[5477]: RTSP conversation thread terminated.

Any thoughts?

mikebrady commented 8 years ago

Thanks for the report, Andrew, but I don't think this is a bug.

Here is my explanation: AirPlay audio is generally delayed by two seconds, as you've noticed. Quicktime and iTunes delay video for two seconds so that it's in phase with the delayed audio. To do the same thing in VLC (2.2.4), the "Track Synchronisation" window's "Audio track synchronization" value is set to -2.0. This brings the audio and video into sync. I haven't used mpv, so I can't comment on it, but I'd guess it has something similar.

Does this seem reasonable?

wilchak commented 8 years ago

Thanks for the reply. Yes, I've been using that Track Synchronisation feature in VLC to workaround this, however, it's not an option for other video sources (Netflix through the browser, etc).

Like I said, the strange thing was that ALL of these sources synced fine when running on an El Capitan system.

I actually just went and tested Netflix playback on a Sierra system to a real Apple TV, and it was basically in sync. So my feeling is there's something that shairplay-sync is doing differently from the official implementation as it interacts with Sierra.

mikebrady commented 8 years ago

I should have added that Safari and Chrome delay the video track of some (most?) movies so that they play in sync with the delayed audio too. Here's an example: https://www.youtube.com/watch?v=1SfZJQ7cXV4. Playing videos (including Netflix, AFAIR) on an iPod with audio on Shairport Sync is synced too. Haven't tried Netflix on a Mac.

wilchak commented 8 years ago

Yep, so Chrome on Mac is out of sync when playing that YouTube video, with the same -2s delay as Netflix. I also tried playing YouTube through Safari, and it's out of sync too.

I'm not convinced that the logic to delay video is an application-level thing. I think the system-level AirPlay virtual audio device is supposed to just keep track of the timing on both ends and adjust accordingly to account for the 2 second buffer. Does that sound right to you? It doesn't make sense to me that every app would have to re-implement its own code to detect it's attached to an AirPlay audio device and adjust its output if so.

mikebrady commented 8 years ago

Just to be clear – in case we are at cross purposes – I'm on an iMac with a fully up-to-date macOS Sierra. The audio and video are automatically synced on Chrome, Safari, iTunes and Quicktime Player, and it appears to be done by delaying the video by two seconds so that it appears at the same time as the audio comes out of the AirPlay device.

If they are out of sync for you, then just ensure to select the airplay device as the sound output before starting playback or while playback is paused; if you change audio output to the AirPlay device without pausing the movie, the browser won't delay the video properly.

I'm watching a movie right now on Safari with this setup.

Curiously, another poster is reporting a similar issue at #382.

Finally, I think that this delaying the video trick actually is implemented separately by each application – I remember when it come first to iTunes and Quicktime Player, then to Chrome and now to Safari. It doesn't work for every YouTube video though; I suspect some movies are packaged so that you can't easily separate the audio and video tracks, but that's just speculation.

wilchak commented 8 years ago

Just to be clarify: all the scenarios where the audio is out of sync are when streaming to a shairport-sync device. When I repeat the exact same tests to an AppleTV, the audio is always in sync, no matter if I select the AirPlay audio device before launching Chrome/VLC, or right in the middle of playback.

mikebrady commented 8 years ago

Thanks. A quick question for clarification: are you sending the audio to the AppleTV and watching the video on the Mac?

wilchak commented 8 years ago

Yep, that's correct. Changing only the audio output device via the volume menu bar icon.

mikebrady commented 8 years ago

Thanks. I am absolutely mystified by this, because at my end, everything is working properly and is unchanged from El Capitan. For the record I'm testing on a Late 2009 iMac, a 2013 Mac Pro, a 2014 MacBook Pro, a 12" iPad Pro, an iPhone 6, Raspberry Pi 3, 2 and 1, a C.H.I.P, a TPLink 740N, Ubuntu 16.04 in VMWare Fusion. Also an AppleTV 3 and a (second generation?) Airport Express that is 802.11n-compatible.

Would you be kind enough to do a logging run with the verbosity set to 2, enable statistics and list the entire log, especially the start. It does not have to go on long, maybe a couple of minutes maximum.

wilchak commented 8 years ago

Okey doke. Here's what I did to produce this log: set log_verbosity=2, rebooted Raspberry Pi, selected AirPlay device from Mac volume icon, played a video in mpv for 2 minutes, quit mpv, played a YouTube video in Chrome for 2 minutes, closed tab.

Other possibly-relevant details: Mac and RPi are both connected to network via Ethernet, RPi is connected to a USB DAC, RPi is running Raspbian that's fully current according to apt-get.

Thanks for your help tracking this down.....

Oct 05 20:17:35 raspberrypi systemd[1]: Starting ShairportSync AirTunes receiver... Oct 05 20:17:35 raspberrypi systemd[1]: Started ShairportSync AirTunes receiver. Oct 05 20:17:35 raspberrypi shairport-sync[423]: Output device name is "hw:1,0". Oct 05 20:17:35 raspberrypi shairport-sync[423]: The processor is running little-endian. Oct 05 20:17:35 raspberrypi shairport-sync[423]: Version: "2.8.4.3-OpenSSL-Avahi-ALSA" Oct 05 20:17:35 raspberrypi shairport-sync[423]: statistics_requester status is 1. Oct 05 20:17:35 raspberrypi shairport-sync[423]: daemon status is 0. Oct 05 20:17:35 raspberrypi shairport-sync[423]: rtsp listening port is 5000. Oct 05 20:17:35 raspberrypi shairport-sync[423]: udp base port is 6001. Oct 05 20:17:35 raspberrypi shairport-sync[423]: udp port range is 100. Oct 05 20:17:35 raspberrypi shairport-sync[423]: Shairport Sync player name is "Big Stereo". Oct 05 20:17:35 raspberrypi shairport-sync[423]: Audio Output name is "(null)". Oct 05 20:17:35 raspberrypi shairport-sync[423]: on-start action is "(null)". Oct 05 20:17:35 raspberrypi shairport-sync[423]: on-stop action is "(null)". Oct 05 20:17:35 raspberrypi shairport-sync[423]: wait-cmd status is 0. Oct 05 20:17:35 raspberrypi shairport-sync[423]: mdns backend "(null)". Oct 05 20:17:35 raspberrypi shairport-sync[423]: userSuppliedLatency is 0. Oct 05 20:17:35 raspberrypi shairport-sync[423]: AirPlayLatency is -1. Oct 05 20:17:35 raspberrypi shairport-sync[423]: iTunesLatency is -1. Oct 05 20:17:35 raspberrypi shairport-sync[423]: forkedDaapdLatency is -1. Oct 05 20:17:35 raspberrypi shairport-sync[423]: stuffing option is "0" (0-basic, 1-soxr). Oct 05 20:17:35 raspberrypi shairport-sync[423]: resync time is 2205. Oct 05 20:17:35 raspberrypi shairport-sync[423]: allow a session to be interrupted: 0. Oct 05 20:17:35 raspberrypi shairport-sync[423]: busy timeout time is 120. Oct 05 20:17:35 raspberrypi shairport-sync[423]: drift tolerance is 88 frames. Oct 05 20:17:35 raspberrypi shairport-sync[423]: password is "(null)". Oct 05 20:17:35 raspberrypi shairport-sync[423]: ignore_volume_control is 0. Oct 05 20:17:35 raspberrypi shairport-sync[423]: playback_mode is 0 (0-stereo, 1-mono). Oct 05 20:17:35 raspberrypi shairport-sync[423]: disable_synchronization is 0. Oct 05 20:17:35 raspberrypi shairport-sync[423]: audio backend desired buffer length is 6615. Oct 05 20:17:35 raspberrypi shairport-sync[423]: audio backend latency offset is 0. Oct 05 20:17:35 raspberrypi shairport-sync[423]: volume range in dB (zero means use the range specified by the mixer): 0. Oct 05 20:17:35 raspberrypi shairport-sync[423]: zeroconf regtype is "_raop._tcp". Oct 05 20:17:35 raspberrypi shairport-sync[423]: configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf". Oct 05 20:17:35 raspberrypi shairport-sync[423]: Successful Startup Oct 05 20:17:35 raspberrypi shairport-sync[423]: avahi: avahi_register. Oct 05 20:17:35 raspberrypi shairport-sync[423]: avahi: register_service. Oct 05 20:17:35 raspberrypi shairport-sync[423]: avahi: service 'E44CB0D660BB@Big Stereo' group is not yet commited. Oct 05 20:17:35 raspberrypi shairport-sync[423]: avahi: request to add "_raop._tcp" service without metadata Oct 05 20:17:35 raspberrypi shairport-sync[423]: avahi: service 'E44CB0D660BB@Big Stereo' group is registering. Oct 05 20:17:35 raspberrypi shairport-sync[423]: avahi: service 'E44CB0D660BB@Big Stereo' successfully added. Oct 05 20:19:06 raspberrypi shairport-sync[423]: New RTSP connection from 192.168.18.50:52502 to self at 192.168.18.30:5000. Oct 05 20:19:10 raspberrypi shairport-sync[423]: Play connection from user agent "AirPlay/301.43.2". Oct 05 20:19:10 raspberrypi shairport-sync[423]: Active-Remote string seen: "367163296". Oct 05 20:19:10 raspberrypi shairport-sync[423]: User-Agent is AirPlay; selecting the AirPlay latency of -1 frames. Oct 05 20:19:10 raspberrypi shairport-sync[423]: rtp_setup: cport=55770 tport=63720. Oct 05 20:19:10 raspberrypi shairport-sync[423]: Set up play connection from 192.168.18.50 to self at 192.168.18.30. Oct 05 20:19:10 raspberrypi shairport-sync[423]: listening for audio, control and timing on ports 6001, 6002, 6003. Oct 05 20:19:10 raspberrypi shairport-sync[423]: Audio receiver -- Server RTP thread starting. Oct 05 20:19:10 raspberrypi shairport-sync[423]: Control receiver -- Server RTP thread starting. Oct 05 20:19:10 raspberrypi shairport-sync[423]: sync error in frames, 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 Oct 05 20:19:10 raspberrypi shairport-sync[423]: Timing receiver -- Server RTP thread starting. Oct 05 20:19:10 raspberrypi shairport-sync[423]: Timing sender thread starting. Oct 05 20:19:10 raspberrypi shairport-sync[423]: volume: -7.180439 Oct 05 20:19:10 raspberrypi shairport-sync[423]: syncing to seqno 63588. Oct 05 20:19:10 raspberrypi shairport-sync[423]: PCM handle name = 'hw:1,0' Oct 05 20:19:10 raspberrypi shairport-sync[423]: alsa device parameters: Oct 05 20:19:10 raspberrypi shairport-sync[423]: access type = RW_INTERLEAVED Oct 05 20:19:10 raspberrypi shairport-sync[423]: format = 'S16_LE' (Signed 16 bit Little Endian) Oct 05 20:19:10 raspberrypi shairport-sync[423]: subformat = 'STD' (Standard) Oct 05 20:19:10 raspberrypi shairport-sync[423]: number of channels = 2 Oct 05 20:19:10 raspberrypi shairport-sync[423]: number of significant bits = 16 Oct 05 20:19:10 raspberrypi shairport-sync[423]: rate = 44100 frames per second (precisely). Oct 05 20:19:10 raspberrypi shairport-sync[423]: precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512). Oct 05 20:19:10 raspberrypi shairport-sync[423]: period_time = 5804 us (>). Oct 05 20:19:10 raspberrypi shairport-sync[423]: period_size = 256 frames (precisely). Oct 05 20:19:10 raspberrypi shairport-sync[423]: buffer_time = 5944308 us (>). Oct 05 20:19:10 raspberrypi shairport-sync[423]: buffer_size = 262144 frames (>). Oct 05 20:19:10 raspberrypi shairport-sync[423]: periods_per_buffer = 1024 (precisely). Oct 05 20:19:10 raspberrypi shairport-sync[423]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Oct 05 20:19:10 raspberrypi shairport-sync[423]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Oct 05 20:19:11 raspberrypi shairport-sync[423]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4415 Oct 05 20:19:32 raspberrypi shairport-sync[423]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 8688.2, 14513.9, 89577.0. Oct 05 20:19:42 raspberrypi shairport-sync[423]: -23.5, 0.0, 0.0, 3758, 0, 236, 0, 281, 4784, 218, 234 Oct 05 20:19:52 raspberrypi shairport-sync[423]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 8233.4, 13157.6, 88120.0. Oct 05 20:20:12 raspberrypi shairport-sync[423]: -31.5, 24.2, 24.2, 7516, 0, 394, 0, 453, 6052, 219, 230 Oct 05 20:20:13 raspberrypi shairport-sync[423]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 8289.7, 13316.7, 61689.0. Oct 05 20:20:34 raspberrypi shairport-sync[423]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 8353.2, 13465.1, 61798.0. Oct 05 20:20:42 raspberrypi shairport-sync[423]: -28.0, 12.9, 12.9, 11274, 0, 562, 0, 641, 6067, 218, 230 Oct 05 20:20:55 raspberrypi shairport-sync[423]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 8447.3, 13779.4, 88409.0. Oct 05 20:21:12 raspberrypi shairport-sync[423]: -41.6, 6.0, 6.0, 15032, 0, 768, 0, 863, 6055, 219, 230 Oct 05 20:21:13 raspberrypi shairport-sync[423]: RTSP shutdown requested. Oct 05 20:21:13 raspberrypi shairport-sync[423]: Closing down RTSP conversation thread... Oct 05 20:21:13 raspberrypi shairport-sync[423]: Playback Stopped. Total playing time 00:02:03 Oct 05 20:21:13 raspberrypi shairport-sync[423]: Shut down audio, control and timing threads Oct 05 20:21:13 raspberrypi shairport-sync[423]: Audio receiver -- Server RTP thread interrupted. terminating. Oct 05 20:21:13 raspberrypi shairport-sync[423]: Timing thread interrupted. terminating. Oct 05 20:21:13 raspberrypi shairport-sync[423]: Control RTP thread interrupted. terminating.rtp_timing_sender thread interrupted. terminating. Oct 05 20:21:13 raspberrypi shairport-sync[423]: Closed and terminated timer requester thread. Oct 05 20:21:13 raspberrypi shairport-sync[423]: Timing RTP thread terminated. Oct 05 20:21:13 raspberrypi shairport-sync[423]: timing thread joined Oct 05 20:21:13 raspberrypi shairport-sync[423]: audio thread joined Oct 05 20:21:13 raspberrypi shairport-sync[423]: control thread joined Oct 05 20:21:13 raspberrypi shairport-sync[423]: Player thread exit Oct 05 20:21:13 raspberrypi shairport-sync[423]: shutting down RTP thread Oct 05 20:21:13 raspberrypi shairport-sync[423]: RTSP conversation thread terminated. Oct 05 20:21:29 raspberrypi shairport-sync[423]: New RTSP connection from 192.168.18.50:52833 to self at 192.168.18.30:5000. Oct 05 20:21:30 raspberrypi shairport-sync[423]: Play connection from user agent "AirPlay/301.43.2". Oct 05 20:21:30 raspberrypi shairport-sync[423]: Active-Remote string seen: "367163296". Oct 05 20:21:30 raspberrypi shairport-sync[423]: User-Agent is AirPlay; selecting the AirPlay latency of -1 frames. Oct 05 20:21:30 raspberrypi shairport-sync[423]: rtp_setup: cport=59636 tport=58339. Oct 05 20:21:30 raspberrypi shairport-sync[423]: Set up play connection from 192.168.18.50 to self at 192.168.18.30. Oct 05 20:21:30 raspberrypi shairport-sync[423]: listening for audio, control and timing on ports 6001, 6002, 6003. Oct 05 20:21:30 raspberrypi shairport-sync[423]: Audio receiver -- Server RTP thread starting. Oct 05 20:21:30 raspberrypi shairport-sync[423]: sync error in frames, 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 occupancyTiming receiver -- Server RTP thread starting. Oct 05 20:21:30 raspberrypi shairport-sync[423]: Control receiver -- Server RTP thread starting. Oct 05 20:21:30 raspberrypi shairport-sync[423]: Timing sender thread starting. Oct 05 20:21:30 raspberrypi shairport-sync[423]: volume: -7.180439 Oct 05 20:21:30 raspberrypi shairport-sync[423]: syncing to seqno 27632. Oct 05 20:21:30 raspberrypi shairport-sync[423]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Oct 05 20:21:30 raspberrypi shairport-sync[423]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Oct 05 20:21:31 raspberrypi shairport-sync[423]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Oct 05 20:21:31 raspberrypi shairport-sync[423]: frame size (fs) < 0 with max_dac_delay of 4410 and dac_delay of 4416 Oct 05 20:21:51 raspberrypi shairport-sync[423]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 8304.7, 13467.5, 60739.0. Oct 05 20:22:02 raspberrypi shairport-sync[423]: 10.3, 0.0, 0.0, 3758, 0, 144, 0, 145, 4336, 221, 231 Oct 05 20:22:12 raspberrypi shairport-sync[423]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 8302.4, 13451.0, 89149.0. Oct 05 20:22:32 raspberrypi shairport-sync[423]: 18.2, -3.0, 3.0, 7516, 0, 269, 0, 273, 6084, 217, 231 Oct 05 20:22:32 raspberrypi shairport-sync[423]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 8219.9, 13222.7, 61628.0. Oct 05 20:22:53 raspberrypi shairport-sync[423]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 8113.0, 12843.6, 89104.0. Oct 05 20:23:02 raspberrypi shairport-sync[423]: 9.7, 52.2, 55.2, 11274, 0, 341, 0, 351, 6051, 217, 230 Oct 05 20:23:13 raspberrypi shairport-sync[423]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 8171.7, 12898.6, 61157.0. Oct 05 20:23:32 raspberrypi shairport-sync[423]: 39.2, -8.3, 8.3, 15032, 0, 501, 0, 529, 6121, 217, 229 Oct 05 20:23:34 raspberrypi shairport-sync[423]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 8386.5, 13325.0, 89710.0. Oct 05 20:23:34 raspberrypi shairport-sync[423]: RTSP shutdown requested. Oct 05 20:23:34 raspberrypi shairport-sync[423]: Closing down RTSP conversation thread... Oct 05 20:23:34 raspberrypi shairport-sync[423]: Playback Stopped. Total playing time 00:02:04 Oct 05 20:23:34 raspberrypi shairport-sync[423]: Shut down audio, control and timing threads Oct 05 20:23:34 raspberrypi shairport-sync[423]: Control RTP thread interrupted. terminating. Oct 05 20:23:34 raspberrypi shairport-sync[423]: Timing thread interrupted. terminating. Oct 05 20:23:34 raspberrypi shairport-sync[423]: Audio receiver -- Server RTP thread interrupted. terminating. Oct 05 20:23:34 raspberrypi shairport-sync[423]: rtp_timing_sender thread interrupted. terminating. Oct 05 20:23:34 raspberrypi shairport-sync[423]: Closed and terminated timer requester thread. Oct 05 20:23:34 raspberrypi shairport-sync[423]: Timing RTP thread terminated. Oct 05 20:23:34 raspberrypi shairport-sync[423]: timing thread joined Oct 05 20:23:34 raspberrypi shairport-sync[423]: audio thread joined Oct 05 20:23:34 raspberrypi shairport-sync[423]: control thread joined Oct 05 20:23:34 raspberrypi shairport-sync[423]: Player thread exit Oct 05 20:23:34 raspberrypi shairport-sync[423]: shutting down RTP thread Oct 05 20:23:34 raspberrypi shairport-sync[423]: RTSP conversation thread terminated.

mikebrady commented 8 years ago

Thanks for that. I notice a couple of things, but I don't think they are all that important.

One is that the version is a little out of date. The thing is, none of the subsequent changes would have any effect on this issue.

The second thing I notice is that there is a high rate of resend requests, but no actually late packets, so no big deal there. Also the standard deviation of the packet intervals is rather high, but again, I can't see how it's relevant. I'll do a similar thing here and post the results...

mikebrady commented 8 years ago

Okay, so I updated Chrome and now that the two-second gap has appeared! It wasn't there before, so it looks like a change (a "regression" perhaps) in Chrome.

Safari continues to work properly though, i.e. the sound is delayed by two seconds and the video is delayed by Safari to keep video and audio synced. (Playing e.g. https://www.youtube.com/watch?v=-NQmLUqakxQ.)

Here is a log extract from a MacPro fully updated to macOS Sierra (and now with a fully updated updated Chrome!) over Ethernet to a Raspberry Pi B (original model). The version of Shairport Sync is 3.0, so it has a few extra features but the timing and so on should be the same. Note though that some values are now in seconds and milliseconds rather than frames. That Standard Deviation is just a high as in your case, but it's much lower IIRC when the source is iTunes, though I'm going to have to check that again).

Oct 06 17:13:45 pioneer shairport-sync[13265]: Output device name is "hw:1".
Oct 06 17:13:45 pioneer shairport-sync[13265]: The processor is running little-endian.
Oct 06 17:13:45 pioneer shairport-sync[13265]: Version: "3.0d16-OpenSSL-Avahi-ALSA-ao-pulse-dummy-stdout-pipe-soxr-metadata-sysconfdir:/etc"
Oct 06 17:13:45 pioneer shairport-sync[13265]: statistics_requester status is 1.
Oct 06 17:13:45 pioneer shairport-sync[13265]: daemon status is 0.
Oct 06 17:13:45 pioneer shairport-sync[13265]: rtsp listening port is 5000.
Oct 06 17:13:45 pioneer shairport-sync[13265]: udp base port is 6001.
Oct 06 17:13:45 pioneer shairport-sync[13265]: udp port range is 100.
Oct 06 17:13:45 pioneer shairport-sync[13265]: Shairport Sync player name is "Pioneer".
Oct 06 17:13:45 pioneer shairport-sync[13265]: Audio Output name is "(null)".
Oct 06 17:13:45 pioneer shairport-sync[13265]: on-start action is "(null)".
Oct 06 17:13:45 pioneer shairport-sync[13265]: on-stop action is "(null)".
Oct 06 17:13:45 pioneer shairport-sync[13265]: wait-cmd status is 0.
Oct 06 17:13:45 pioneer shairport-sync[13265]: mdns backend "(null)".
Oct 06 17:13:45 pioneer shairport-sync[13265]: userSuppliedLatency is 0.
Oct 06 17:13:45 pioneer shairport-sync[13265]: AirPlayLatency is -1.
Oct 06 17:13:45 pioneer shairport-sync[13265]: iTunesLatency is -1.
Oct 06 17:13:45 pioneer shairport-sync[13265]: forkedDaapdLatency is -1.
Oct 06 17:13:45 pioneer shairport-sync[13265]: stuffing option is "0" (0-basic, 1-soxr).
Oct 06 17:13:45 pioneer shairport-sync[13265]: resync time is 0.050000 seconds.
Oct 06 17:13:45 pioneer shairport-sync[13265]: allow a session to be interrupted: 0.
Oct 06 17:13:45 pioneer shairport-sync[13265]: busy timeout time is 120.
Oct 06 17:13:45 pioneer shairport-sync[13265]: drift tolerance is 0.002000 seconds.
Oct 06 17:13:45 pioneer shairport-sync[13265]: password is "(null)".
Oct 06 17:13:45 pioneer shairport-sync[13265]: ignore_volume_control is 0.
Oct 06 17:13:45 pioneer shairport-sync[13265]: playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
Oct 06 17:13:45 pioneer shairport-sync[13265]: disable_synchronization is 0.
Oct 06 17:13:45 pioneer shairport-sync[13265]: use_mmap_if_available is 1.
Oct 06 17:13:45 pioneer shairport-sync[13265]: output_rate is 44100.
Oct 06 17:13:45 pioneer shairport-sync[13265]: output_format is 3 (0-unknown, 1-S8, 2-U8, 3-S16, 4-S24, 5-S24_3LE, 6-S24_3BE, 7-S32).
Oct 06 17:13:45 pioneer shairport-sync[13265]: audio backend desired buffer length is 0.150000 seconds.
Oct 06 17:13:45 pioneer shairport-sync[13265]: audio backend latency offset is 0.000000 seconds.
Oct 06 17:13:45 pioneer shairport-sync[13265]: volume range in dB (zero means use the range specified by the mixer): 0.
Oct 06 17:13:45 pioneer shairport-sync[13265]: zeroconf regtype is "_raop._tcp".
Oct 06 17:13:45 pioneer shairport-sync[13265]: decoders_supported field is 3.
Oct 06 17:13:45 pioneer shairport-sync[13265]: use_apple_decoder is 0.
Oct 06 17:13:45 pioneer shairport-sync[13265]: configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
Oct 06 17:13:45 pioneer shairport-sync[13265]: metdata enabled is 0.
Oct 06 17:13:45 pioneer shairport-sync[13265]: metadata pipename is "(null)".
Oct 06 17:13:45 pioneer shairport-sync[13265]: metadata socket address is "(null)" port 0.
Oct 06 17:13:45 pioneer shairport-sync[13265]: metadata socket packet size is "500".
Oct 06 17:13:45 pioneer shairport-sync[13265]: get-coverart is 0.
Oct 06 17:13:45 pioneer shairport-sync[13265]: Successful Startup
Oct 06 17:13:45 pioneer shairport-sync[13265]: avahi: avahi_register.
Oct 06 17:13:45 pioneer shairport-sync[13265]: avahi: register_service.
Oct 06 17:13:46 pioneer shairport-sync[13265]: avahi: service 'F13E3963C962@Pioneer' group is not yet commited.
Oct 06 17:13:46 pioneer shairport-sync[13265]: avahi: request to add "_raop._tcp" service without metadata
Oct 06 17:13:46 pioneer shairport-sync[13265]: avahi: service 'F13E3963C962@Pioneer' group is registering.
Oct 06 17:13:46 pioneer shairport-sync[13265]: avahi: service 'F13E3963C962@Pioneer' successfully added.

Chrome:
Oct 06 17:15:34 pioneer shairport-sync[13265]: New RTSP connection from 192.168.2.1:60113 to self at 192.168.2.7:5000.
Oct 06 17:15:35 pioneer shairport-sync[13265]: Play connection from user agent "AirPlay/301.43.2".
Oct 06 17:15:35 pioneer shairport-sync[13265]: Active-Remote string seen: "4178425492".
Oct 06 17:15:35 pioneer shairport-sync[13265]: DACP-ID string seen: "603B6BD3E97A9DE2".
Oct 06 17:15:35 pioneer shairport-sync[13265]: User-Agent is AirPlay; selecting the AirPlay latency of -1 frames.
Oct 06 17:15:35 pioneer shairport-sync[13265]: rtp_setup: cport=57597 tport=60467.
Oct 06 17:15:35 pioneer shairport-sync[13265]: Set up play connection from 192.168.2.1 to self at 192.168.2.7.
Oct 06 17:15:35 pioneer shairport-sync[13265]: listening for audio, control and timing on ports 6001, 6002, 6003.
Oct 06 17:15:35 pioneer shairport-sync[13265]: Output sample ratio is 1.
Oct 06 17:15:35 pioneer shairport-sync[13265]: Output frame bytes is 4.
Oct 06 17:15:35 pioneer shairport-sync[13265]: Output bit depth is 16.
Oct 06 17:15:35 pioneer shairport-sync[13265]: Dithering will be enabled the output volume is being altered in software
Oct 06 17:15:35 pioneer shairport-sync[13265]: 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
Oct 06 17:15:35 pioneer shairport-sync[13265]: volume: -18.061800
Oct 06 17:15:35 pioneer shairport-sync[13265]: Timing receiver -- Server RTP thread starting.
Oct 06 17:15:35 pioneer shairport-sync[13265]: Control receiver -- Server RTP thread starting.
Oct 06 17:15:35 pioneer shairport-sync[13265]: Audio receiver -- Server RTP thread starting.
Oct 06 17:15:35 pioneer shairport-sync[13265]: Timing sender thread starting.
Oct 06 17:15:35 pioneer shairport-sync[13265]: syncing to seqno 37122.
Oct 06 17:15:35 pioneer shairport-sync[13265]: Output sample ratio is 1
Oct 06 17:15:46 pioneer shairport-sync[13265]: volume: -24.082401
Oct 06 17:15:55 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.7,    12061.6,    37167.0.
Oct 06 17:16:06 pioneer shairport-sync[13265]: 0.6,       0.0,       0.0,        3758,      0,      0,      0,      0,   4920,  223,  230
Oct 06 17:16:15 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.1,    12066.5,    29961.0.
Oct 06 17:16:35 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7987.0,    12064.5,    30023.0.
Oct 06 17:16:36 pioneer shairport-sync[13265]: 1.7,     -18.1,      18.1,        7516,      0,      0,      0,      0,   6192,  223,  230
Oct 06 17:16:54 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7964.4,    12048.1,    29992.0.
Oct 06 17:17:06 pioneer shairport-sync[13265]: 1.9,     -41.6,      41.6,       11274,      0,      0,      0,      0,   6149,  224,  230
Oct 06 17:17:14 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.1,    12059.9,    30053.0.
Oct 06 17:17:34 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7986.8,    12049.2,    30164.0.
Oct 06 17:17:36 pioneer shairport-sync[13265]: 1.9,     -41.6,      41.6,       15032,      0,      0,      0,      0,   6219,  224,  230
Oct 06 17:17:54 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.6,    12003.4,    30159.0.
Oct 06 17:18:06 pioneer shairport-sync[13265]: 1.9,     -40.8,      40.8,       18790,      0,      0,      0,      0,   6220,  224,  230
Oct 06 17:18:14 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.1,    12024.2,    30313.0.
Oct 06 17:18:34 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.2,    12048.4,    29899.0.
Oct 06 17:18:36 pioneer shairport-sync[13265]: 1.9,     -43.1,      43.1,       22548,      0,      0,      0,      0,   6221,  224,  230
Oct 06 17:18:50 pioneer shairport-sync[13265]: RTSP shutdown requested.
Oct 06 17:18:50 pioneer shairport-sync[13265]: Closing down RTSP conversation thread...
Oct 06 17:18:50 pioneer shairport-sync[13265]: Playback Stopped. Total playing time 00:03:15
Oct 06 17:18:51 pioneer shairport-sync[13265]: Shut down audio, control and timing threads
Oct 06 17:18:51 pioneer shairport-sync[13265]: Audio receiver -- Server RTP thread interrupted. terminating.
Oct 06 17:18:51 pioneer shairport-sync[13265]: Control RTP thread interrupted. terminating.
Oct 06 17:18:51 pioneer shairport-sync[13265]: Timing thread interrupted. terminating.
Oct 06 17:18:51 pioneer shairport-sync[13265]: rtp_timing_sender thread interrupted. terminating.
Oct 06 17:18:51 pioneer shairport-sync[13265]: Closed and terminated timer requester thread.
Oct 06 17:18:51 pioneer shairport-sync[13265]: Timing RTP thread terminated.
Oct 06 17:18:51 pioneer shairport-sync[13265]: timing thread joined
Oct 06 17:18:51 pioneer shairport-sync[13265]: audio thread joined
Oct 06 17:18:51 pioneer shairport-sync[13265]: control thread joined
Oct 06 17:18:51 pioneer shairport-sync[13265]: Player thread exit
Oct 06 17:18:51 pioneer shairport-sync[13265]: shutting down RTP thread
Oct 06 17:18:51 pioneer shairport-sync[13265]: RTSP conversation thread terminated.

Safari:
Oct 06 17:19:59 pioneer shairport-sync[13265]: New RTSP connection from 192.168.2.1:60165 to self at 192.168.2.7:5000.
Oct 06 17:19:59 pioneer shairport-sync[13265]: Play connection from user agent "AirPlay/301.43.2".
Oct 06 17:19:59 pioneer shairport-sync[13265]: Active-Remote string seen: "4178425492".
Oct 06 17:19:59 pioneer shairport-sync[13265]: DACP-ID string seen: "603B6BD3E97A9DE2".
Oct 06 17:19:59 pioneer shairport-sync[13265]: User-Agent is AirPlay; selecting the AirPlay latency of -1 frames.
Oct 06 17:19:59 pioneer shairport-sync[13265]: rtp_setup: cport=49554 tport=64284.
Oct 06 17:19:59 pioneer shairport-sync[13265]: Set up play connection from 192.168.2.1 to self at 192.168.2.7.
Oct 06 17:19:59 pioneer shairport-sync[13265]: listening for audio, control and timing on ports 6001, 6002, 6003.
Oct 06 17:19:59 pioneer shairport-sync[13265]: volume: -24.082401
Oct 06 17:19:59 pioneer shairport-sync[13265]: Output sample ratio is 1.
Oct 06 17:19:59 pioneer shairport-sync[13265]: Output frame bytes is 4.
Oct 06 17:19:59 pioneer shairport-sync[13265]: Output bit depth is 16.
Oct 06 17:19:59 pioneer shairport-sync[13265]: Dithering will be enabled the output volume is being altered in software
Oct 06 17:19:59 pioneer shairport-sync[13265]: 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
Oct 06 17:19:59 pioneer shairport-sync[13265]: Timing receiver -- Server RTP thread starting.
Oct 06 17:19:59 pioneer shairport-sync[13265]: Control receiver -- Server RTP thread starting.
Oct 06 17:19:59 pioneer shairport-sync[13265]: Audio receiver -- Server RTP thread starting.
Oct 06 17:19:59 pioneer shairport-sync[13265]: Timing sender thread starting.
Oct 06 17:19:59 pioneer shairport-sync[13265]: syncing to seqno 65101.
Oct 06 17:19:59 pioneer shairport-sync[13265]: Output sample ratio is 1
Oct 06 17:20:19 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.8,    12013.3,    30086.0.
Oct 06 17:20:31 pioneer shairport-sync[13265]: 0.6,       0.0,       0.0,        3758,      0,      0,      0,      0,   4572,  226,  233
Oct 06 17:20:39 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.5,    12041.8,    29233.0.
Oct 06 17:20:59 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.5,    12057.8,    31523.0.
Oct 06 17:21:01 pioneer shairport-sync[13265]: 1.7,     -18.1,      18.1,        7516,      0,      0,      0,      0,   6196,  227,  230
Oct 06 17:21:19 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.0,    12057.3,    30378.0.
Oct 06 17:21:31 pioneer shairport-sync[13265]: 1.9,     -36.3,      36.3,       11274,      0,      0,      0,      0,   6220,  226,  230
Oct 06 17:21:39 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7976.8,    12051.0,    31528.0.
Oct 06 17:21:59 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.6,    12044.0,    29228.0.
Oct 06 17:22:01 pioneer shairport-sync[13265]: 1.9,     -46.1,      46.1,       15032,      0,      0,      0,      0,   6191,  226,  230
Oct 06 17:22:19 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.7,    12051.6,    31502.0.
Oct 06 17:22:31 pioneer shairport-sync[13265]: 1.9,     -43.1,      43.1,       18790,      0,      0,      0,      0,   6220,  226,  230
Oct 06 17:22:39 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7986.6,    12064.3,    29041.0.
Oct 06 17:22:59 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.8,    12052.8,    29184.0.
Oct 06 17:23:01 pioneer shairport-sync[13265]: 1.9,     -40.1,      40.1,       22548,      0,      0,      0,      0,   6220,  226,  230
Oct 06 17:23:19 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.8,    11992.2,    29219.0.
Oct 06 17:23:31 pioneer shairport-sync[13265]: 1.9,     -43.8,      43.8,       26306,      0,      0,      0,      0,   6220,  227,  230
Oct 06 17:23:39 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.1,    12000.2,    29057.0.
Oct 06 17:23:59 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.4,    12040.4,    29119.0.
Oct 06 17:24:01 pioneer shairport-sync[13265]: 1.9,     -40.8,      40.8,       30064,      0,      0,      0,      0,   6216,  227,  230
Oct 06 17:24:19 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.7,    12061.7,    30225.0.
Oct 06 17:24:31 pioneer shairport-sync[13265]: 1.9,     -43.8,      43.8,       33822,      0,      0,      0,      0,   6221,  226,  230
Oct 06 17:24:39 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.8,    12046.9,    31593.0.
Oct 06 17:24:59 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7986.2,    12049.3,    28978.0.
Oct 06 17:25:01 pioneer shairport-sync[13265]: 1.9,     -40.8,      40.8,       37580,      0,      0,      0,      0,   6221,  225,  230
Oct 06 17:25:19 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.3,    12052.4,    30420.0.
Oct 06 17:25:31 pioneer shairport-sync[13265]: 1.9,     -41.6,      41.6,       41338,      0,      0,      0,      0,   6216,  227,  230
Oct 06 17:25:39 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.8,    12042.3,    30522.0.
Oct 06 17:25:59 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.6,    12049.9,    29080.0.
Oct 06 17:26:01 pioneer shairport-sync[13265]: 1.9,     -40.1,      40.1,       45096,      0,      0,      0,      0,   6220,  226,  230
Oct 06 17:26:19 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.5,    12044.0,    41716.0.
Oct 06 17:26:31 pioneer shairport-sync[13265]: 1.9,     -41.6,      41.6,       48854,      0,      0,      0,      0,   6216,  225,  230
Oct 06 17:26:39 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7986.8,    11988.1,    29437.0.
Oct 06 17:26:58 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.8,    12003.1,    29133.0.
Oct 06 17:27:01 pioneer shairport-sync[13265]: 1.9,     -43.8,      43.8,       52612,      0,      0,      0,      0,   6218,  226,  230
Oct 06 17:27:18 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.3,    12067.6,    29150.0.
Oct 06 17:27:31 pioneer shairport-sync[13265]: 1.9,     -40.8,      40.8,       56370,      0,      0,      0,      0,   6220,  227,  230
Oct 06 17:27:38 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.0,    12082.1,    29077.0.
Oct 06 17:27:58 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.3,    12080.2,    29072.0.
Oct 06 17:28:01 pioneer shairport-sync[13265]: 1.9,     -40.8,      40.8,       60128,      0,      0,      0,      0,   6213,  227,  230
Oct 06 17:28:18 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.6,    12079.1,    30191.0.
Oct 06 17:28:31 pioneer shairport-sync[13265]: 1.9,     -41.6,      41.6,       63886,      0,      0,      0,      0,   6198,  226,  230
Oct 06 17:28:38 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.8,    12052.8,    31552.0.
Oct 06 17:28:58 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7986.5,    12078.1,    29209.0.
Oct 06 17:29:01 pioneer shairport-sync[13265]: 1.9,     -42.3,      42.3,       67644,      0,      0,      0,      0,   6219,  225,  230
Oct 06 17:29:18 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.2,    12076.8,    29055.0.
Oct 06 17:29:31 pioneer shairport-sync[13265]: 1.9,     -42.3,      42.3,       71402,      0,      0,      0,      0,   6215,  227,  230
Oct 06 17:29:38 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.6,    12066.7,    29428.0.
Oct 06 17:29:58 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.1,    12015.4,    29191.0.
Oct 06 17:30:01 pioneer shairport-sync[13265]: 1.9,     -41.6,      41.6,       75160,      0,      0,      0,      0,   6219,  227,  230
Oct 06 17:30:18 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.4,    12020.3,    29250.0.
Oct 06 17:30:31 pioneer shairport-sync[13265]: 1.9,     -41.6,      41.6,       78918,      0,      0,      0,      0,   6217,  227,  230
Oct 06 17:30:38 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7986.5,    12090.6,    29915.0.
Oct 06 17:30:58 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.7,    12074.3,    29163.0.
Oct 06 17:31:01 pioneer shairport-sync[13265]: 1.9,     -40.8,      40.8,       82676,      0,      0,      0,      0,   6218,  226,  230
Oct 06 17:31:18 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7986.5,    12066.2,    29639.0.
Oct 06 17:31:31 pioneer shairport-sync[13265]: 1.9,     -43.1,      43.1,       86434,      0,      0,      0,      0,   6203,  225,  230
Oct 06 17:31:38 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.2,    12078.2,    31272.0.
Oct 06 17:31:58 pioneer shairport-sync[13265]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.9,    12064.6,    29530.0.
Oct 06 17:32:01 pioneer shairport-sync[13265]: 1.9,     -42.3,      42.3,       90192,      0,      0,      0,      0,   6217,  226,  230
wilchak commented 8 years ago

Interesting. I'm happy to install the latest shairport-sync release to test, but like you I didn't think that would be a factor because I didn't see any commits that seemed relevant. What are your results when playing from VLC or mpv?

mikebrady commented 8 years ago

One other odd thing about your setup is the average interval between packets. Each packet is 352 audio frames, so they should arrive every 352/44,100 of a second, i.e. every 7.98186 milliseconds. The log shows a consistently different time, more like 8.1 or 8.2 milliseconds. That's measured at the RPi end. I don't know the significance of it, to be honest. Maybe it's associated somehow with the missing packets...

mikebrady commented 8 years ago

Playing from VLC, just updated to 2.2.4, I need to set the "Audio track synchronisation" to -2.0. Again, this isn't a surprise to me. Playing the same video in Quicktime Player, the video is delayed by two seconds automagically, so it's in sync with the audio. Also trying the "Quicklook" feature, the same thing – video delayed by two seconds to sync with the audio.

mikebrady commented 8 years ago

I don't think any of the changes in Shairport Sync 3 are relevant to this issue, TBH.

wilchak commented 8 years ago

FWIW, I just tried playing a video from inside iTunes, and it was in sync. ¯(ツ)/¯

mikebrady commented 8 years ago

Okay to close this?

mikebrady commented 8 years ago

Feel free to reopen this if necessary.