mikebrady / shairport-sync

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

two iphones switch, shairport-sync process aborted #160

Closed feihualuomeng closed 5 years ago

feihualuomeng commented 9 years ago

when i enable " allow_session_interruption = "yes" ", it will the shairtport-sync process aborted for two iphones switch

mikebrady commented 9 years ago

Thanks for the report. If I understand correctly, you are reporting that Shairport Sync aborted when one iPhone interrupted another. Is that correct? Can you cause it to happen consistently? If so, I'd be very interested to know how.

feihualuomeng commented 9 years ago

yes, you understand correctly. olny one iphone interrupted another, have no any other action

feihualuomeng commented 8 years ago

shairpot-sync version is 2.6, and output device is alsa

mikebrady commented 8 years ago

Had a look at this, and it may take quite a while to fix. It doesn't seem to be part of the AirPlay protocol to allow a session to be interrupted by the receiver. When it does happen, the sender seems to register it as a fault. In any case, for the present, it's best to avoid this by setting allow_session_interruption = "no"

mikebrady commented 8 years ago

Hi there. I've made a little headway on this – it's in the development branch. It's a lot more stable, and I'd be interested in your views.

PeterPablo commented 8 years ago

I will test tomorrow and report back. Thank you!

PeterPablo commented 8 years ago

This does not work for me. Irrespective of my stuttering playback, I can not interrupt the session, if first I play using AirAudio and then try to switch to my laptop. Playback from my smartphone continues, though the Mac shows, that it connected?! A repeated test lead to an access violation:

pi@rpi2 ~ $ shairport-sync -vv
Looking for the configuration file "/etc/shairport-sync.conf".
Looking for configuration file at full path "/etc/shairport-sync.conf"
audio_alsa init called.
Output device name is "hw:0".
Open Mixer
Lowest dB value is a mute.
Can't get dB value corresponding to a "volume" of 1.
Hardware mixer has dB volume from -103.000000 to 0.000000.
Has mute ability.
startup
The processor is running little-endian.
statistics_requester status is 1.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "my Shairport Sync".
Audio Output name is "alsa".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
mdns backend "(null)".
userSuppliedLatency is 0.
AirPlayLatency is -1.
iTunesLatency is -1.
forkedDaapdLatency is -1.
stuffing option is "0".
resync time is 0.
allow a session to be interrupted: 1.
busy timeout time is 1.
tolerance is 1800 frames.
password is "(null)".
ignore_volume_control is 0.
audio backend desired buffer length is 41000.
audio backend latency offset is 0.
volume range in dB (zero means use the range specified by the mixer): 0.
configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
avahi: avahi_register.
avahi: register_service.
Avahi without metadata
culling threads.
New RTSP connection on port 5000
Play connection from user agent "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4".
User-Agent is iTunes 10 or better, (actual version is 11); selecting the iTunes latency of -1 frames.
rtp_setup: cport=6001 tport=6002.
Connection from IPv4: 192.168.1.2:40620
listening for audio, control and timing on ports 6001, 6002, 6003.
audio_alsa start called.
Audio receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Timing receiver -- Server RTP thread starting.
Timing sender thread starting.
audio_alsa flush called.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: 0.000000

audio_alsa mute called.
Setting volume db to 0.000000.
syncing to seqno 6673.
Open Mixer
Setting volume db to 0.000000.
RTP: Packets out of sequence: expected: 6745, got 6715.
RTP: Packets out of sequence: expected: 6716, got 6717.
RTP: Packets out of sequence: expected: 6726, got 6727.
RTP: Packets out of sequence: expected: 6732, got 6733.
RTP: Packets out of sequence: expected: 6737, got 6738.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: 0.000000

audio_alsa mute called.
Setting volume db to 0.000000.
RTP: Packets out of sequence: expected: 6856, got 6852.
RTP: Packets out of sequence: expected: 7335, got 7332.
RTP: Packets out of sequence: expected: 7338, got 7336.
RTP: Packets out of sequence: expected: 7380, got 7377.
RTP: Packets out of sequence: expected: 7522, got 7520.
RTP: Packets out of sequence: expected: 7541, got 7539.
RTP: Packets out of sequence: expected: 7570, got 7568.
RTP: Packets out of sequence: expected: 7586, got 7584.
RTP: Packets out of sequence: expected: 7776, got 7773.
RTP: Packets out of sequence: expected: 7803, got 7798.
RTP: Packets out of sequence: expected: 7805, got 7804.
RTP: Packets out of sequence: expected: 7805, got 7798.
RTP: Packets out of sequence: expected: 7952, got 7950.
RTP: Packets out of sequence: expected: 8041, got 8039.
RTP: Packets out of sequence: expected: 8053, got 8044.
RTP: Packets out of sequence: expected: 8110, got 8108.
RTP: Packets out of sequence: expected: 8116, got 8111.
culling threads.
New RTSP connection on port 5000
RTSP shutdown requested.
Closing down RTSP conversation thread...
audio_alsa stop called.
audio_alsa flush called.
Shut down audio, control and timing threads
Audio receiver -- Server RTP thread interrupted. terminating.Timing thread interrupted. terminating.
Control RTP thread interrupted. terminating.

rtp_timing_sender thread interrupted. terminating.
Closed and terminated timer requester thread.
Timing RTP thread terminated.
timing thread joined
audio thread joined
control thread joined
Player thread exit
shutting down RTP thread
RTSP conversation thread terminated.
Try to get the player now
Play connection from user agent "AirPlay/250.10".
Active-Remote string seen: "3221007986".
User-Agent is AirPlay; selecting the AirPlay latency of -1 frames.
rtp_setup: cport=53500 tport=64411.
Connection from IPv4: 192.168.1.9:62787
listening for audio, control and timing on ports 6001, 6002, 6003.
audio_alsa start called.
Audio receiver -- Server RTP thread starting.
syncing to seqno 8380.
Control receiver -- Server RTP thread starting.
audio_alsa flush called.
Timing receiver -- Server RTP thread starting.
Timing sender thread starting.
syncing to seqno 8381.
FIXME: unhandled prediction type on channel 1: 4
FIXME: unhandled prediction type on channel 2: 7
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -20.000000

audio_alsa mute called.
Setting volume db to -4635.000000.
FIXME: Not enough space if the output buffer for audio frame - E3.
Output from alac_decode is smaller than expected. Encrypted = 1.
Bad audio packet detected and discarded.
FIXME: Not enough space if the output buffer for audio frame - E3.
Output from alac_decode is smaller than expected. Encrypted = 1.
Bad audio packet detected and discarded.
RTP: Packets out of sequence: expected: 8388, got 8386.
FIXME: Not enough space if the output buffer for audio frame - E3.
Output from alac_decode is smaller than expected. Encrypted = 1.
Bad audio packet detected and discarded.
FIXME: Not enough space if the output buffer for audio frame - E2.
Output from alac_decode is smaller than expected. Encrypted = 1.
Bad audio packet detected and discarded.
RTP: Packets out of sequence: expected: 8396, got 56095.
Open Mixer
Setting volume db to -4635.000000.
RTP: Packets out of sequence: expected: 56103, got 8396.
RTP: Packets out of sequence: expected: 8399, got 56103.
RTP: Packets out of sequence: expected: 56108, got 8399.
RTP: Packets out of sequence: expected: 8404, got 8402.
FIXME: unhandled prediction type on channel 1: 15
FIXME: unhandled prediction type on channel 2: 9
FIXME: unhandled prediction type on channel 1: 5
FIXME: unhandled prediction type on channel 2: 9
RTP: Packets out of sequence: expected: 8411, got 56108.
RTP: Packets out of sequence: expected: 56122, got 8411.
RTP: Packets out of sequence: expected: 8414, got 56122.
RTP: Packets out of sequence: expected: 56123, got 8414.
RTP: Packets out of sequence: expected: 8415, got 56123.
RTP: Packets out of sequence: expected: 56127, got 8415.
FIXME: Not enough space if the output buffer for audio frame - E2.
Output from alac_decode is smaller than expected. Encrypted = 1.
Bad audio packet detected and discarded.
FIXME: unhandled prediction type for compressed case: 1
FIXME: unhandled prediction type on channel 1: 8
FIXME: unhandled prediction type on channel 2: 14
Output from alac_decode is smaller than expected. Encrypted = 1.
Bad audio packet detected and discarded.
RTP: Packets out of sequence: expected: 8423, got 56127.
RTP: Packets out of sequence: expected: 56129, got 8423.
Output from alac_decode is smaller than expected. Encrypted = 1.
Bad audio packet detected and discarded.
RTP: Packets out of sequence: expected: 8425, got 56129.
RTP: Packets out of sequence: expected: 56134, got 8425.
FIXME: unhandled prediction type on channel 2: 4
FIXME: Not enough space if the output buffer for audio frame - E2.
Output from alac_decode is smaller than expected. Encrypted = 1.
Bad audio packet detected and discarded.
RTP: Packets out of sequence: expected: 8428, got 56134.
RTP: Packets out of sequence: expected: 56136, got 8428.
RTP: Packets out of sequence: expected: 8429, got 56136.
RTP: Packets out of sequence: expected: 56138, got 56136.
RTP: Packets out of sequence: expected: 56138, got 8429.
RTP: Packets out of sequence: expected: 8430, got 56138.
RTP: Packets out of sequence: expected: 56141, got 8430.
FIXME: unhandled prediction type on channel 1: 15
FIXME: unhandled prediction type on channel 2: 13
Output from alac_decode is smaller than expected. Encrypted = 1.
Bad audio packet detected and discarded.
FIXME: Not enough space if the output buffer for audio frame - E2.
Output from alac_decode is smaller than expected. Encrypted = 1.
Bad audio packet detected and discarded.
Speicherzugriffsfehler

The switch from first playback on the Laptop to the smartphone works (I ended the connection of the smartphone at the end of the log manually):

shairport-sync -vv
Looking for the configuration file "/etc/shairport-sync.conf".
Looking for configuration file at full path "/etc/shairport-sync.conf"
audio_alsa init called.
Output device name is "hw:0".
Open Mixer
Lowest dB value is a mute.
Can't get dB value corresponding to a "volume" of 1.
Hardware mixer has dB volume from -103.000000 to 0.000000.
Has mute ability.
startup
The processor is running little-endian.
statistics_requester status is 1.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "my Shairport Sync".
Audio Output name is "alsa".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
mdns backend "(null)".
userSuppliedLatency is 0.
AirPlayLatency is -1.
iTunesLatency is -1.
forkedDaapdLatency is -1.
stuffing option is "0".
resync time is 0.
allow a session to be interrupted: 1.
busy timeout time is 1.
tolerance is 1800 frames.
password is "(null)".
ignore_volume_control is 0.
audio backend desired buffer length is 41000.
audio backend latency offset is 0.
volume range in dB (zero means use the range specified by the mixer): 0.
configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
avahi: avahi_register.
avahi: register_service.
Avahi without metadata
culling threads.
New RTSP connection on port 5000
Play connection from user agent "AirPlay/250.10".
Active-Remote string seen: "2547443379".
User-Agent is AirPlay; selecting the AirPlay latency of -1 frames.
rtp_setup: cport=50419 tport=53567.
Connection from IPv4: 192.168.1.9:62765
listening for audio, control and timing on ports 6001, 6002, 6003.
audio_alsa start called.
Audio receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Timing receiver -- Server RTP thread starting.
Timing sender thread starting.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -20.000000

audio_alsa mute called.
Setting volume db to -4635.000000.
syncing to seqno 39394.
Open Mixer
Setting volume db to -4635.000000.
RTP: Packets out of sequence: expected: 39683, got 39680.
RTP: Packets out of sequence: expected: 39897, got 39895.
RTP: Packets out of sequence: expected: 39901, got 39898.
RTP: Packets out of sequence: expected: 39920, got 39917.
RTP: Packets out of sequence: expected: 39919, got 39920.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -18.750000

audio_alsa mute called.
Setting volume db to -4248.750000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -16.875000

audio_alsa mute called.
Setting volume db to -3669.375000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -15.000000

audio_alsa mute called.
Setting volume db to -3090.000000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -13.125000

audio_alsa mute called.
Setting volume db to -2510.625000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -11.250000

audio_alsa mute called.
Setting volume db to -1931.250000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -9.375000

audio_alsa mute called.
Setting volume db to -1609.375000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -7.500000

audio_alsa mute called.
Setting volume db to -1287.500000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -5.625000

audio_alsa mute called.
Setting volume db to -965.625000.
RTP: Packets out of sequence: expected: 40611, got 40609.
RTP: Packets out of sequence: expected: 40644, got 40643.
RTP: Packets out of sequence: expected: 40646, got 40645.
RTP: Packets out of sequence: expected: 40879, got 40877.
RTP: Packets out of sequence: expected: 40935, got 40933.
RTP: Packets out of sequence: expected: 40956, got 40957.
requesting resend of 1 packets starting at 40956.
RTP: Packets out of sequence: expected: 41036, got 41034.
RTP: Packets out of sequence: expected: 41074, got 41072.
RTP: Packets out of sequence: expected: 41251, got 41248.
RTP: Packets out of sequence: expected: 41251, got 41248.
RTP: Packets out of sequence: expected: 41266, got 41262.
RTP: Packets out of sequence: expected: 41266, got 41262.
RTP: Packets out of sequence: expected: 41420, got 41417.
RTP: Packets out of sequence: expected: 41487, got 41485.
RTP: Packets out of sequence: expected: 41754, got 41752.
RTP: Packets out of sequence: expected: 42073, got 42071.
culling threads.
New RTSP connection on port 5000
RTP: Packets out of sequence: expected: 42322, got 42321.
RTSP shutdown requested.
Closing down RTSP conversation thread...
audio_alsa stop called.
audio_alsa flush called.
RTP: Packets out of sequence: expected: 42390, got 42387.
Shut down audio, control and timing threads
Timing thread interrupted. terminating.
Audio receiver -- Server RTP thread interrupted. terminating.rtp_timing_sender thread interrupted. terminating.
Control RTP thread interrupted. terminating.

Closed and terminated timer requester thread.
Timing RTP thread terminated.
timing thread joined
audio thread joined
control thread joined
Player thread exit
shutting down RTP thread
RTSP conversation thread terminated.
Try to get the player now
Play connection from user agent "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4".
User-Agent is iTunes 10 or better, (actual version is 11); selecting the iTunes latency of -1 frames.
rtp_setup: cport=6001 tport=6002.
Connection from IPv4: 192.168.1.2:40186
listening for audio, control and timing on ports 6001, 6002, 6003.
audio_alsa start called.
Audio receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Timing receiver -- Server RTP thread starting.
Timing sender thread starting.
audio_alsa flush called.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: 0.000000

audio_alsa mute called.
Setting volume db to 0.000000.
syncing to seqno 5758.
Open Mixer
Setting volume db to 0.000000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: 0.000000

audio_alsa mute called.
Setting volume db to 0.000000.
RTP: Packets out of sequence: expected: 5957, got 5955.
RTP: Packets out of sequence: expected: 5957, got 5955.
RTP: Packets out of sequence: expected: 5962, got 5960.
RTP: Packets out of sequence: expected: 6061, got 6059.
RTP: Packets out of sequence: expected: 6339, got 6337.
RTP: Packets out of sequence: expected: 6529, got 6526.
RTP: Packets out of sequence: expected: 6551, got 6548.
RTP: Packets out of sequence: expected: 7157, got 7155.
RTP: Packets out of sequence: expected: 7240, got 7238.
RTP: Packets out of sequence: expected: 7667, got 7664.
RTP: Packets out of sequence: expected: 7678, got 7679.
RTP: Packets out of sequence: expected: 7737, got 7736.
RTP: Packets out of sequence: expected: 7739, got 7737.
RTP: Packets out of sequence: expected: 7745, got 7743.
requesting resend of 1 packets starting at 7678.
RTP: Packets out of sequence: expected: 7793, got 7791.
requesting resend of 1 packets starting at 7678.
requesting resend of 1 packets starting at 7678.
requesting resend of 1 packets starting at 7678.
RTP: Packets out of sequence: expected: 7919, got 7917.
RTP: Packets out of sequence: expected: 7919, got 7917.
RTP: Packets out of sequence: expected: 8049, got 8047.
RTP: Packets out of sequence: expected: 8049, got 8047.
RTP: Packets out of sequence: expected: 8167, got 8165.
Aliasing of buffer index -- reset.
RTP: Packets out of sequence: expected: 8282, got 8280.
RTP: Packets out of sequence: expected: 8325, got 8323.
RTP: Packets out of sequence: expected: 8336, got 8334.
Player: packets out of sequence: expected: 7678, got: 8190, sync error: 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 writing 352 samples in play() Broken pipe.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
RTP: Packets out of sequence: expected: 8419, got 8417.
RTP: Packets out of sequence: expected: 8440, got 8438.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
RTP: Packets out of sequence: expected: 8694, got 8691.
RTP: Packets out of sequence: expected: 9135, got 9131.
RTP: Packets out of sequence: expected: 9207, got 9205.
RTP: Packets out of sequence: expected: 9268, got 9266.
RTP: Packets out of sequence: expected: 9287, got 9285.
RTP: Packets out of sequence: expected: 9664, got 9662.
RTP: Packets out of sequence: expected: 9699, got 9697.
RTP: Packets out of sequence: expected: 9742, got 9739.
RTP: Packets out of sequence: expected: 9758, got 9756.
RTP: Packets out of sequence: expected: 9777, got 9774.
RTP: Packets out of sequence: expected: 9846, got 9844.
RTP: Packets out of sequence: expected: 9886, got 9885.
RTP: Packets out of sequence: expected: 9912, got 9913.
requesting resend of 1 packets starting at 9912.
RTP: Packets out of sequence: expected: 10038, got 10036.
RTP: Packets out of sequence: expected: 10038, got 10036.
requesting resend of 1 packets starting at 9912.
requesting resend of 1 packets starting at 9912.
requesting resend of 1 packets starting at 9912.
RTP: Packets out of sequence: expected: 10100, got 10098.
RTP: Packets out of sequence: expected: 10129, got 10127.
RTP: Packets out of sequence: expected: 10193, got 10191.
RTP: Packets out of sequence: expected: 10343, got 10341.
RTP: Packets out of sequence: expected: 10342, got 10343.
Aliasing of buffer index -- reset.
RTP: Packets out of sequence: expected: 10431, got 10429.
RTP: Packets out of sequence: expected: 10436, got 10433.
RTSP shutdown requested.
Closing down RTSP conversation thread...
audio_alsa stop called.
audio_alsa flush called.
Shut down audio, control and timing threads
Audio receiver -- Server RTP thread interrupted. terminating.
Control RTP thread interrupted. terminating.
Timing thread interrupted. terminating.
rtp_timing_sender thread interrupted. terminating.
Closed and terminated timer requester thread.
Timing RTP thread terminated.
timing thread joined
audio thread joined
control thread joined
Player thread exit
shutting down RTP thread
RTSP conversation thread terminated.

Playback using shairport by abrasive

Playback works without stutter and I can interrupt in both directions:

pi@rpi2 ~ $ sudo nice -n -15 ~/bin/shairport/shairport -b 400 -vv
Starting Shairport 1.1.1-23-gd65b8e8
Bound to address 0.0.0.0
Bound to address ::
avahi: avahi_register
avahi: register_service
Listening for connections.
culling threads.
new RTSP connection
received request: OPTIONS * RTSP/1.0
    Apple-Challenge: lzS6DAgAf7JR0vhA2WO8hw==
    CSeq: 0
    DACP-ID: 920EE5BF3DBDDB3C
    Active-Remote: 1695996411
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    Apple-Response: izYzdpvEdc5HJTnZ5ySOvSuoFyhgr5H7pmwt5gPHOz1AsIkPQmCtg+mvH04Niduou04udcePQYe4SBaLFqHyu0ciLOrQ8rQqa7Rs3PFtiPwYRGQcM59eo4YVfwcP2wJowofkD+PA9qDqh8+Kl+zAPuPMaMdYi91LFhm5ywcM90j3dJvQfeulQLNx9UVwhA5pepwv2ccdOvJSyZSo4IbPpBmAmOesVQltzogyD3TP5ZoeWy1VLEB+5ArXK8LQIJ2T+2+VG348Wl5jve3GeW+lVrg7SARsrZ8+N1Z8SERRQcVqZR/xYQQMFLjU/QXokoTcSPKD+aLrCh+HdUtY4WdYjQ
    CSeq: 0
    Audio-Jack-Status: connected; type=analog
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER
received request: ANNOUNCE rtsp://192.168.1.43/13309268397336055416 RTSP/1.0
    Content-Length: 642
    Content-Type: application/sdp
    CSeq: 1
    DACP-ID: 920EE5BF3DBDDB3C
    Active-Remote: 1695996411
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 1
    Audio-Jack-Status: connected; type=analog
received request: SETUP rtsp://192.168.1.43/13309268397336055416 RTSP/1.0
    Transport: RTP/AVP/UDP;unicast;mode=record;timing_port=63096;control_port=54874
    CSeq: 2
    DACP-ID: 920EE5BF3DBDDB3C
    Active-Remote: 1695996411
    User-Agent: AirPlay/250.10
rtp_setup: cport=54874 tport=63096
rtp listening on port 49945
sending response: RTSP/1.0 200 OK
    CSeq: 2
    Audio-Jack-Status: connected; type=analog
    Transport: RTP/AVP/UDP;unicast;mode=record;server_port=49945;control_port=49945;timing_port=49945
    Session: 1
received request: RECORD rtsp://192.168.1.43/13309268397336055416 RTSP/1.0
    CSeq: 3
    DACP-ID: 920EE5BF3DBDDB3C
    Active-Remote: 1695996411
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 3
    Audio-Jack-Status: connected; type=analog
syncing to first seqno 4052
received request: SET_PARAMETER rtsp://192.168.1.43/13309268397336055416 RTSP/1.0
    Content-Length: 20
    Content-Type: text/parameters
    CSeq: 4
    DACP-ID: 920EE5BF3DBDDB3C
    Active-Remote: 1695996411
    User-Agent: AirPlay/250.10
SET_PARAMETER Content-Type: text/parameters
received parameters in SET_PARAMETER request
volume: -20.000000
sending response: RTSP/1.0 200 OK
    CSeq: 4
    Audio-Jack-Status: connected; type=analog
received request: OPTIONS * RTSP/1.0
    CSeq: 5
    DACP-ID: 920EE5BF3DBDDB3C
    Active-Remote: 1695996411
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 5
    Audio-Jack-Status: connected; type=analog
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER
buffering over. starting play
received request: OPTIONS * RTSP/1.0
    CSeq: 6
    DACP-ID: 920EE5BF3DBDDB3C
    Active-Remote: 1695996411
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 6
    Audio-Jack-Status: connected; type=analog
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER
received request: OPTIONS * RTSP/1.0
    CSeq: 7
    DACP-ID: 920EE5BF3DBDDB3C
    Active-Remote: 1695996411
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 7
    Audio-Jack-Status: connected; type=analog
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER
received request: OPTIONS * RTSP/1.0
    CSeq: 8
    DACP-ID: 920EE5BF3DBDDB3C
    Active-Remote: 1695996411
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 8
    Audio-Jack-Status: connected; type=analog
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER
culling threads.
new RTSP connection
received request: ANNOUNCE rtsp://192.168.1.43/1505144957 RTSP/1.0
    Apple-Challenge: rW2C6c9N887atE/9Cr2ABw
    CSeq: 11
    Client-Instance: 0E327FB0F8B6A97E
    Content-Length: 569
    Content-Type: application/sdp
    Session: 1
    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4
received request: OPTIONS * RTSP/1.0
    CSeq: 9
    DACP-ID: 920EE5BF3DBDDB3C
    Active-Remote: 1695996411
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 9
    Audio-Jack-Status: connected; type=analog
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER
sending response: RTSP/1.0 200 OK
    Apple-Response: wJHAo7IFE3n6s+SWD8C0H2boPLgQabVJBYxsMLygp8SL0FNqTCTsDZz2aC5lbMyU11M7SM9qt2eQXfTAi+pAJp9wmqzBjXdrFB4mNxHS8WIOkCMrIAzgB+sH3HrGySrA3lqxnGskP6EK4byI9nL6jBlAYzej/5K7jHLq0fPkTwi5iSqpTwuIirX48N39nHgM+nU3i3VEM6LAPhWst0nhqhdFV7t3ExBE1Ihjm58dIAA9VcHwYygKflzV0PXmt/4fEwtuCfZ4hoAq91P+k2bSTC5TQtrXbOFBwk88o23IWIMwxOSko6XoViUj1Xm18RrDWTvYaj6BE7Z70/hiosD+CA
    CSeq: 11
    Audio-Jack-Status: connected; type=analog
received request: SETUP rtsp://192.168.1.43/1505144957 RTSP/1.0
    CSeq: 12
    Client-Instance: 0E327FB0F8B6A97E
    Session: 1
    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4
    Transport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002
shutting down playing thread
RTSP shutdown requested
closing RTSP connection
shutting down RTP thread
RTP thread interrupted. terminating.
terminating RTSP thread
rtp_setup: cport=6001 tport=6002
rtp listening on port 38536
sending response: RTSP/1.0 200 OK
    CSeq: 12
    Audio-Jack-Status: connected; type=analog
    Transport: RTP/AVP/UDP;unicast;mode=record;server_port=38536;control_port=38536;timing_port=38536
    Session: 1
received request: RECORD rtsp://192.168.1.43/1505144957 RTSP/1.0
    RTP-Info: seq=2557;rtptime=381613
    CSeq: 13
    Client-Instance: 0E327FB0F8B6A97E
    Session: 1
    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4
    Range: npt=0-
sending response: RTSP/1.0 200 OK
    CSeq: 13
    Audio-Jack-Status: connected; type=analog
received request: SET_PARAMETER rtsp://192.168.1.43/1505144957 RTSP/1.0
    RTP-Info: rtptime=381613
    CSeq: 14
    Client-Instance: 0E327FB0F8B6A97E
    Content-Length: 60
    Content-Type: application/x-dmap-tagged
    Session: 1
    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4
SET_PARAMETER Content-Type: application/x-dmap-tagged
received metadata tags in SET_PARAMETER request
Tag: asar   Content: Marek Hemmann
META Artist: Marek Hemmann
Tag: asal   Content: Gemini Ep
META Album: Gemini Ep
Tag: minm   Content: Gemini
META Title: Gemini
sending response: RTSP/1.0 200 OK
    CSeq: 14
    Audio-Jack-Status: connected; type=analog
received request: SET_PARAMETER rtsp://192.168.1.43/1505144957 RTSP/1.0
    CSeq: 15
    Client-Instance: 0E327FB0F8B6A97E
    Content-Length: 18
    Content-Type: text/parameters
    Session: 1
    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4
SET_PARAMETER Content-Type: text/parameters
received parameters in SET_PARAMETER request
volume: 0.000000
sending response: RTSP/1.0 200 OK
    CSeq: 15
    Audio-Jack-Status: connected; type=analog
received request: SET_PARAMETER rtsp://192.168.1.43/1505144957 RTSP/1.0
    RTP-Info: rtptime=381613
    CSeq: 16
    Client-Instance: 0E327FB0F8B6A97E
    Content-Length: 84604
    Content-Type: image/jpeg
    Session: 1
    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4
SET_PARAMETER Content-Type: image/jpeg
received image in SET_PARAMETER request
sending response: RTSP/1.0 200 OK
    CSeq: 16
    Audio-Jack-Status: connected; type=analog
syncing to first seqno 09FD
received request: SET_PARAMETER rtsp://192.168.1.43/1505144957 RTSP/1.0
    RTP-Info: rtptime=393581
    CSeq: 17
    Client-Instance: 0E327FB0F8B6A97E
    Content-Length: 60
    Content-Type: application/x-dmap-tagged
    Session: 1
    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4
SET_PARAMETER Content-Type: application/x-dmap-tagged
received metadata tags in SET_PARAMETER request
Tag: asar   Content: Marek Hemmann
META Artist: Marek Hemmann
Tag: asal   Content: Gemini Ep
META Album: Gemini Ep
Tag: minm   Content: Gemini
META Title: Gemini
sending response: RTSP/1.0 200 OK
    CSeq: 17
    Audio-Jack-Status: connected; type=analog
received request: SET_PARAMETER rtsp://192.168.1.43/1505144957 RTSP/1.0
    CSeq: 18
    Client-Instance: 0E327FB0F8B6A97E
    Content-Length: 18
    Content-Type: text/parameters
    Session: 1
    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4
SET_PARAMETER Content-Type: text/parameters
received parameters in SET_PARAMETER request
volume: 0.000000
sending response: RTSP/1.0 200 OK
    CSeq: 18
    Audio-Jack-Status: connected; type=analog
received request: SET_PARAMETER rtsp://192.168.1.43/1505144957 RTSP/1.0
    RTP-Info: rtptime=420333
    CSeq: 19
    Client-Instance: 0E327FB0F8B6A97E
    Content-Length: 84604
    Content-Type: image/jpeg
    Session: 1
    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4
SET_PARAMETER Content-Type: image/jpeg
received image in SET_PARAMETER request
sending response: RTSP/1.0 200 OK
    CSeq: 19
    Audio-Jack-Status: connected; type=analog
buffering over. starting play
culling threads.
one joined
new RTSP connection
received request: OPTIONS * RTSP/1.0
    Apple-Challenge: P9MkTZbkCAjfs1/lER7waQ==
    CSeq: 0
    DACP-ID: 22252189EEF9A28E
    Active-Remote: 2693686338
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    Apple-Response: NjzJDCNGNXe+pAOvf/bCz5Rwk79XDnDvzIMGH6oZ8HQmgMJ6w3qtuKtDjmkgw+SsxIsMgn4iMR1HqlwLiOE61u02jBwNMlJrGIk4HmkLn3EBGyZe1eEU3UkQY1TI3DKeFodKVqlsV29IYpPaTuYKnYV68x7S9IsSa+1ku+HfHUrGX5yqwZhn5uWam5lLaFDOAkApQi2/KnpZys+MzWI2YVuBfHnlPcgQOj3Spr1NRHWSlnhxbhYi5vCfpWm6FSgiPLZvZZjh+CV2xMPIGGATqKSiEPEJGhMQKNUTNQeDqoNDw9YJrPewSQrWsLrxh8s344/164jiVb6CQotTAPspTQ
    CSeq: 0
    Audio-Jack-Status: connected; type=analog
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER
received request: ANNOUNCE rtsp://192.168.1.43/5101064844027579340 RTSP/1.0
    Content-Length: 641
    Content-Type: application/sdp
    CSeq: 1
    DACP-ID: 22252189EEF9A28E
    Active-Remote: 2693686338
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 1
    Audio-Jack-Status: connected; type=analog
received request: SETUP rtsp://192.168.1.43/5101064844027579340 RTSP/1.0
    Transport: RTP/AVP/UDP;unicast;mode=record;timing_port=61836;control_port=56605
    CSeq: 2
    DACP-ID: 22252189EEF9A28E
    Active-Remote: 2693686338
    User-Agent: AirPlay/250.10
shutting down playing thread
RTSP shutdown requested
closing RTSP connection
shutting down RTP thread
RTP thread interrupted. terminating.
terminating RTSP thread
rtp_setup: cport=56605 tport=61836
rtp listening on port 36465
sending response: RTSP/1.0 200 OK
    CSeq: 2
    Audio-Jack-Status: connected; type=analog
    Transport: RTP/AVP/UDP;unicast;mode=record;server_port=36465;control_port=36465;timing_port=36465
    Session: 1
received request: RECORD rtsp://192.168.1.43/5101064844027579340 RTSP/1.0
    CSeq: 3
    DACP-ID: 22252189EEF9A28E
    Active-Remote: 2693686338
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 3
    Audio-Jack-Status: connected; type=analog
received request: SET_PARAMETER rtsp://192.168.1.43/5101064844027579340 RTSP/1.0
    Content-Length: 20
    Content-Type: text/parameters
    CSeq: 4
    DACP-ID: 22252189EEF9A28E
    Active-Remote: 2693686338
    User-Agent: AirPlay/250.10
SET_PARAMETER Content-Type: text/parameters
received parameters in SET_PARAMETER request
volume: -20.000000
sending response: RTSP/1.0 200 OK
    CSeq: 4
    Audio-Jack-Status: connected; type=analog
syncing to first seqno FF1F
requesting resend on 3 packets (FF5A:FF5C)
requesting resend on 1 packets (FFBC:FFBC)
received request: OPTIONS * RTSP/1.0
    CSeq: 5
    DACP-ID: 22252189EEF9A28E
    Active-Remote: 2693686338
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 5
    Audio-Jack-Status: connected; type=analog
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER
buffering over. starting play
received request: OPTIONS * RTSP/1.0
    CSeq: 6
    DACP-ID: 22252189EEF9A28E
    Active-Remote: 2693686338
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 6
    Audio-Jack-Status: connected; type=analog
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER
requesting resend on 1 packets (0197:0197)
received request: OPTIONS * RTSP/1.0
    CSeq: 7
    DACP-ID: 22252189EEF9A28E
    Active-Remote: 2693686338
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 7
    Audio-Jack-Status: connected; type=analog
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER
requesting resend on 1 packets (0233:0233)
received request: OPTIONS * RTSP/1.0
    CSeq: 8
    DACP-ID: 22252189EEF9A28E
    Active-Remote: 2693686338
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 8
    Audio-Jack-Status: connected; type=analog
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER
received request: OPTIONS * RTSP/1.0
    CSeq: 9
    DACP-ID: 22252189EEF9A28E
    Active-Remote: 2693686338
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 9
    Audio-Jack-Status: connected; type=analog
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER
established desired fill of 392.740000 frames, so output chain buffered about 7.260000 frames
---------
received request: OPTIONS * RTSP/1.0
    CSeq: 10
    DACP-ID: 22252189EEF9A28E
    Active-Remote: 2693686338
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 10
    Audio-Jack-Status: connected; type=analog
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER
requesting resend on 1 packets (04DF:04DF)
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
requesting resend on 3 packets (0563:0565)
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
+++++++++
received request: OPTIONS * RTSP/1.0
    CSeq: 11
    DACP-ID: 22252189EEF9A28E
    Active-Remote: 2693686338
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 11
    Audio-Jack-Status: connected; type=analog
    Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER
+++++++++
received request: TEARDOWN rtsp://192.168.1.43/5101064844027579340 RTSP/1.0
    CSeq: 12
    DACP-ID: 22252189EEF9A28E
    Active-Remote: 2693686338
    User-Agent: AirPlay/250.10
sending response: RTSP/1.0 200 OK
    CSeq: 12
    Audio-Jack-Status: connected; type=analog
    Connection: close
RTSP shutdown requested
closing RTSP connection
shutting down RTP thread
RTP thread interrupted. terminating.
terminating RTSP thread
^CShutting down...
avahi: avahi_unregister

Observation

The old shairport by abrasive works just fine with minimal configuration effort (I only specified the buffer length to 400 and started the process with a very low niceness level). I observe no stuttering sound and am able to interrupt the sources.

Shairport-sync unfortunately struggles with playback. I tried many combinations of buffer lengths, resynchronization, etc. to no avail. The Packets out of sequence message sticks out -- might there be a regression in filling the buffer, compared to shairport? When increasing the loglevel to vvv I get many (!!!) audio_alsa play called. and audio_alsa delay called. messages. Moreover interrupting still does not work as hoped.

When looking at the output of the shairport-sync process, I get the impression that the expected package often is off by only 1 to 5 packages. Isn't it feasible to bring the received packages into order during reception and before playback? (Sorry, my naive assumption is that the buffer should be filled irrespective of the order). For completeness, here a couple of minutes playback from the laptop that went (surprisingly) without stutter:

pi@rpi2 ~ $ sudo nice -n -10 shairport-sync -vv
Looking for the configuration file "/etc/shairport-sync.conf".
Looking for configuration file at full path "/etc/shairport-sync.conf"
audio_alsa init called.
Output device name is "hw:0".
Open Mixer
Lowest dB value is a mute.
Can't get dB value corresponding to a "volume" of 1.
Hardware mixer has dB volume from -103.000000 to 0.000000.
Has mute ability.
startup
The processor is running little-endian.
statistics_requester status is 1.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "my Shairport Sync".
Audio Output name is "alsa".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
mdns backend "(null)".
userSuppliedLatency is 0.
AirPlayLatency is -1.
iTunesLatency is -1.
forkedDaapdLatency is -1.
stuffing option is "0".
resync time is 0.
allow a session to be interrupted: 1.
busy timeout time is 1.
tolerance is 1800 frames.
password is "(null)".
ignore_volume_control is 0.
audio backend desired buffer length is 41000.
audio backend latency offset is 0.
volume range in dB (zero means use the range specified by the mixer): 0.
configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
avahi: avahi_register.
avahi: register_service.
Avahi without metadata
culling threads.
New RTSP connection on port 5000
Play connection from user agent "AirPlay/250.10".
Active-Remote string seen: "2100161272".
User-Agent is AirPlay; selecting the AirPlay latency of -1 frames.
rtp_setup: cport=54469 tport=59578.
Connection from IPv4: 192.168.1.9:62923
listening for audio, control and timing on ports 6001, 6002, 6003.
audio_alsa start called.
Audio receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Timing receiver -- Server RTP thread starting.
Timing sender thread starting.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -20.000000

audio_alsa mute called.
Setting volume db to -4635.000000.
syncing to seqno 62240.
Open Mixer
Setting volume db to -4635.000000.
RTP: Packets out of sequence: expected: 62676, got 62666.
RTP: Packets out of sequence: expected: 62702, got 62700.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -18.750000

audio_alsa mute called.
Setting volume db to -4248.750000.
RTP: Packets out of sequence: expected: 62840, got 62839.
RTP: Packets out of sequence: expected: 62842, got 62841.
RTP: Packets out of sequence: expected: 62847, got 62846.
RTP: Packets out of sequence: expected: 62849, got 62848.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -16.875000

audio_alsa mute called.
Setting volume db to -3669.375000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -15.000000

audio_alsa mute called.
Setting volume db to -3090.000000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -13.125000

audio_alsa mute called.
Setting volume db to -2510.625000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -11.250000

audio_alsa mute called.
Setting volume db to -1931.250000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -9.375000

audio_alsa mute called.
Setting volume db to -1609.375000.
RTP: Packets out of sequence: expected: 63021, got 63019.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -7.500000

audio_alsa mute called.
Setting volume db to -1287.500000.
RTP: Packets out of sequence: expected: 63067, got 63064.
RTP: Packets out of sequence: expected: 63066, got 63067.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -5.625000

audio_alsa mute called.
Setting volume db to -965.625000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -3.750000

audio_alsa mute called.
Setting volume db to -643.750000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -1.875000

audio_alsa mute called.
Setting volume db to -321.875000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: 0.000000

audio_alsa mute called.
Setting volume db to 0.000000.
RTP: Packets out of sequence: expected: 63157, got 63154.
RTP: Packets out of sequence: expected: 63155, got 63157.
RTP: Packets out of sequence: expected: 63172, got 63169.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: -1.875000

audio_alsa mute called.
Setting volume db to -321.875000.
RTP: Packets out of sequence: expected: 63371, got 63368.
RTP: Packets out of sequence: expected: 63370, got 63371.
RTP: Packets out of sequence: expected: 63424, got 63420.
RTP: Packets out of sequence: expected: 63421, got 63422.
RTP: Packets out of sequence: expected: 63423, got 63424.
RTP: Packets out of sequence: expected: 63642, got 63639.
RTP: Packets out of sequence: expected: 63834, got 63832.
RTP: Packets out of sequence: expected: 63848, got 63846.
RTP: Packets out of sequence: expected: 63984, got 63981.
RTP: Packets out of sequence: expected: 64002, got 63999.
RTP: Packets out of sequence: expected: 64085, got 64082.
RTP: Packets out of sequence: expected: 64258, got 64256.
RTP: Packets out of sequence: expected: 64292, got 64290.
RTP: Packets out of sequence: expected: 64420, got 64417.
RTP: Packets out of sequence: expected: 64423, got 64421.
RTP: Packets out of sequence: expected: 64477, got 64473.
RTP: Packets out of sequence: expected: 64477, got 64473.
RTP: Packets out of sequence: expected: 64626, got 64623.
RTP: Packets out of sequence: expected: 64923, got 64920.
RTP: Packets out of sequence: expected: 64928, got 64924.
RTP: Packets out of sequence: expected: 64964, got 64962.
RTP: Packets out of sequence: expected: 65032, got 65029.
RTP: Packets out of sequence: expected: 65032, got 65029.
RTP: Packets out of sequence: expected: 65051, got 65049.
RTP: Packets out of sequence: expected: 65134, got 65131.
RTP: Packets out of sequence: expected: 65348, got 65345.
RTP: Packets out of sequence: expected: 65346, got 65347.
RTP: Packets out of sequence: expected: 65392, got 65390.
RTP: Packets out of sequence: expected: 101, got 98.
RTP: Packets out of sequence: expected: 101, got 98.
RTP: Packets out of sequence: expected: 128, got 124.
RTP: Packets out of sequence: expected: 128, got 124.
RTP: Packets out of sequence: expected: 203, got 200.
RTP: Packets out of sequence: expected: 260, got 257.
RTP: Packets out of sequence: expected: 293, got 290.
RTP: Packets out of sequence: expected: 334, got 332.
RTP: Packets out of sequence: expected: 432, got 430.
RTP: Packets out of sequence: expected: 448, got 446.
RTP: Packets out of sequence: expected: 560, got 558.
Sync error: -235.0 (frames); net correction: 0.0 (ppm); corrections: 0.0 (ppm); missing packets 0; late packets 119; too late packets 0; resend requests 0; min DAC queue size 4450, min and max buffer occupancy 120 and 228.
RTP: Packets out of sequence: expected: 781, got 782.
requesting resend of 1 packets starting at 781.
RTP: Packets out of sequence: expected: 865, got 862.
RTP: Packets out of sequence: expected: 880, got 876.
RTP: Packets out of sequence: expected: 955, got 952.
RTP: Packets out of sequence: expected: 954, got 955.
RTP: Packets out of sequence: expected: 1008, got 1004.
RTP: Packets out of sequence: expected: 1161, got 1158.
RTP: Packets out of sequence: expected: 1181, got 1177.
RTP: Packets out of sequence: expected: 1207, got 1203.
RTP: Packets out of sequence: expected: 1300, got 1298.
RTP: Packets out of sequence: expected: 1352, got 1350.
RTP: Packets out of sequence: expected: 1376, got 1372.
RTP: Packets out of sequence: expected: 1413, got 1410.
RTP: Packets out of sequence: expected: 1413, got 1410.
RTP: Packets out of sequence: expected: 1413, got 1410.
RTP: Packets out of sequence: expected: 1466, got 1462.
RTP: Packets out of sequence: expected: 1511, got 1510.
RTP: Packets out of sequence: expected: 1579, got 1576.
RTP: Packets out of sequence: expected: 1579, got 1576.
RTP: Packets out of sequence: expected: 1589, got 1587.
RTP: Packets out of sequence: expected: 1594, got 1590.
RTP: Packets out of sequence: expected: 1592, got 1594.
RTP: Packets out of sequence: expected: 1601, got 1598.
RTP: Packets out of sequence: expected: 1613, got 1609.
RTP: Packets out of sequence: expected: 1777, got 1775.
RTP: Packets out of sequence: expected: 1973, got 1970.
RTP: Packets out of sequence: expected: 2128, got 2125.
RTP: Packets out of sequence: expected: 2202, got 2200.
RTP: Packets out of sequence: expected: 2330, got 2329.
RTP: Packets out of sequence: expected: 2356, got 2354.
RTP: Packets out of sequence: expected: 2488, got 2485.
RTP: Packets out of sequence: expected: 2487, got 2488.
RTP: Packets out of sequence: expected: 2526, got 2523.
RTP: Packets out of sequence: expected: 2586, got 2583.
RTP: Packets out of sequence: expected: 2624, got 2621.
RTP: Packets out of sequence: expected: 2773, got 2771.
RTP: Packets out of sequence: expected: 2811, got 2809.
RTP: Packets out of sequence: expected: 2973, got 2971.
RTP: Packets out of sequence: expected: 3067, got 3066.
RTP: Packets out of sequence: expected: 3108, got 3106.
RTP: Packets out of sequence: expected: 3189, got 3188.
RTP: Packets out of sequence: expected: 3200, got 3202.
requesting resend of 1 packets starting at 3200.
requesting resend of 1 packets starting at 3201.
RTP: Packets out of sequence: expected: 3293, got 3290.
RTP: Packets out of sequence: expected: 3570, got 3568.
RTP: Packets out of sequence: expected: 3620, got 3617.
RTP: Packets out of sequence: expected: 3623, got 3621.
RTP: Packets out of sequence: expected: 3656, got 3654.
RTP: Packets out of sequence: expected: 3829, got 3827.
RTP: Packets out of sequence: expected: 4014, got 4011.
RTP: Packets out of sequence: expected: 4059, got 4056.
RTP: Packets out of sequence: expected: 4254, got 4252.
Sync error: -314.6 (frames); net correction: 0.0 (ppm); corrections: 0.0 (ppm); missing packets 0; late packets 241; too late packets 0; resend requests 3; min DAC queue size 40082, min and max buffer occupancy 71 and 137.
RTP: Packets out of sequence: expected: 4529, got 4526.
RTP: Packets out of sequence: expected: 4598, got 4599.
requesting resend of 1 packets starting at 4598.
RTP: Packets out of sequence: expected: 4882, got 4879.
RTP: Packets out of sequence: expected: 4987, got 4985.
RTP: Packets out of sequence: expected: 5051, got 5048.
RTP: Packets out of sequence: expected: 5049, got 5051.
RTP: Packets out of sequence: expected: 5066, got 5064.
RTP: Packets out of sequence: expected: 5229, got 5225.
RTP: Packets out of sequence: expected: 5417, got 5418.
requesting resend of 1 packets starting at 5417.
RTP: Packets out of sequence: expected: 5521, got 5522.
requesting resend of 1 packets starting at 5521.
RTP: Packets out of sequence: expected: 5851, got 5849.
RTP: Packets out of sequence: expected: 5856, got 5853.
RTP: Packets out of sequence: expected: 6040, got 6038.
RTP: Packets out of sequence: expected: 6055, got 6051.
RTP: Packets out of sequence: expected: 6078, got 6075.
RTP: Packets out of sequence: expected: 6088, got 6086.
RTP: Packets out of sequence: expected: 6112, got 6108.
RTP: Packets out of sequence: expected: 6168, got 6165.
RTP: Packets out of sequence: expected: 6167, got 6168.
RTP: Packets out of sequence: expected: 6321, got 6319.
RTP: Packets out of sequence: expected: 6356, got 6353.
RTP: Packets out of sequence: expected: 6468, got 6469.
requesting resend of 1 packets starting at 6468.
RTP: Packets out of sequence: expected: 6555, got 6552.
RTP: Packets out of sequence: expected: 6656, got 6654.
RTP: Packets out of sequence: expected: 6656, got 6654.
RTP: Packets out of sequence: expected: 6686, got 6684.
RTP: Packets out of sequence: expected: 6705, got 6703.
RTP: Packets out of sequence: expected: 6743, got 6739.
RTP: Packets out of sequence: expected: 6833, got 6830.
RTP: Packets out of sequence: expected: 6833, got 6830.
RTP: Packets out of sequence: expected: 6874, got 6872.
RTP: Packets out of sequence: expected: 7006, got 7003.
RTP: Packets out of sequence: expected: 7035, got 7033.
RTP: Packets out of sequence: expected: 7044, got 7041.
RTP: Packets out of sequence: expected: 7043, got 7044.
RTP: Packets out of sequence: expected: 7239, got 7236.
RTP: Packets out of sequence: expected: 7272, got 7270.
RTP: Packets out of sequence: expected: 7296, got 7292.
RTP: Packets out of sequence: expected: 7310, got 7307.
RTP: Packets out of sequence: expected: 7309, got 7310.
RTP: Packets out of sequence: expected: 7453, got 7451.
RTP: Packets out of sequence: expected: 7533, got 7531.
RTP: Packets out of sequence: expected: 7573, got 7571.
RTP: Packets out of sequence: expected: 7578, got 7574.
RTP: Packets out of sequence: expected: 7645, got 7641.
RTP: Packets out of sequence: expected: 7668, got 7665.
RTP: Packets out of sequence: expected: 7675, got 7672.
RTP: Packets out of sequence: expected: 7690, got 7686.
RTP: Packets out of sequence: expected: 7776, got 7777.
requesting resend of 1 packets starting at 7776.
RTP: Packets out of sequence: expected: 7863, got 7859.
RTP: Packets out of sequence: expected: 7861, got 7863.
RTP: Packets out of sequence: expected: 7972, got 7970.
Sync error: -344.2 (frames); net correction: 0.0 (ppm); corrections: 0.0 (ppm); missing packets 0; late packets 357; too late packets 0; resend requests 8; min DAC queue size 40138, min and max buffer occupancy 68 and 137.
RTP: Packets out of sequence: expected: 8250, got 8246.
RTP: Packets out of sequence: expected: 8250, got 8246.
RTP: Packets out of sequence: expected: 8250, got 8246.
RTP: Packets out of sequence: expected: 8362, got 8360.
RTP: Packets out of sequence: expected: 8378, got 8374.
RTP: Packets out of sequence: expected: 8376, got 8378.
RTP: Packets out of sequence: expected: 8411, got 8409.
RTP: Packets out of sequence: expected: 8442, got 8438.
RTP: Packets out of sequence: expected: 8513, got 8510.
RTP: Packets out of sequence: expected: 8562, got 8560.
RTP: Packets out of sequence: expected: 8670, got 8668.
RTP: Packets out of sequence: expected: 8679, got 8676.
RTP: Packets out of sequence: expected: 8912, got 8908.
RTP: Packets out of sequence: expected: 8919, got 8917.
RTP: Packets out of sequence: expected: 8971, got 8969.
RTP: Packets out of sequence: expected: 9111, got 9107.
RTP: Packets out of sequence: expected: 9185, got 9186.
requesting resend of 1 packets starting at 9185.
RTP: Packets out of sequence: expected: 9400, got 9397.
RTP: Packets out of sequence: expected: 9412, got 9410.
RTP: Packets out of sequence: expected: 9509, got 9506.
RTP: Packets out of sequence: expected: 9508, got 9509.
RTP: Packets out of sequence: expected: 9671, got 9667.
RTP: Packets out of sequence: expected: 9802, got 9800.
RTP: Packets out of sequence: expected: 9840, got 9838.
RTP: Packets out of sequence: expected: 9949, got 9945.
RTP: Packets out of sequence: expected: 10043, got 10041.
RTP: Packets out of sequence: expected: 10088, got 10086.
RTP: Packets out of sequence: expected: 10242, got 10239.
RTP: Packets out of sequence: expected: 10241, got 10242.
RTP: Packets out of sequence: expected: 10388, got 10386.
RTP: Packets out of sequence: expected: 10388, got 10386.
RTP: Packets out of sequence: expected: 10388, got 10386.
RTP: Packets out of sequence: expected: 10528, got 10525.
RTP: Packets out of sequence: expected: 10561, got 10559.
RTP: Packets out of sequence: expected: 10784, got 10782.
RTP: Packets out of sequence: expected: 10986, got 10984.
RTP: Packets out of sequence: expected: 10993, got 10991.
RTP: Packets out of sequence: expected: 11000, got 10998.
RTP: Packets out of sequence: expected: 11133, got 11129.
RTP: Packets out of sequence: expected: 11131, got 11133.
RTP: Packets out of sequence: expected: 11149, got 11152.
RTP: Packets out of sequence: expected: 11216, got 11212.
RTP: Packets out of sequence: expected: 11213, got 11214.
RTP: Packets out of sequence: expected: 11215, got 11216.
requesting resend of 1 packets starting at 11149.
requesting resend of 1 packets starting at 11150.
requesting resend of 1 packets starting at 11151.
RTP: Packets out of sequence: expected: 11399, got 11397.
RTP: Packets out of sequence: expected: 11584, got 11581.
RTP: Packets out of sequence: expected: 11588, got 11585.
RTP: Packets out of sequence: expected: 11588, got 11585.
RTP: Packets out of sequence: expected: 11764, got 11762.
RTP: Packets out of sequence: expected: 11816, got 11814.
Sync error: -392.9 (frames); net correction: 0.0 (ppm); corrections: 0.0 (ppm); missing packets 0; late packets 468; too late packets 0; resend requests 12; min DAC queue size 39938, min and max buffer occupancy 68 and 137.
RTP: Packets out of sequence: expected: 11918, got 11916.
RTP: Packets out of sequence: expected: 11997, got 11995.
RTP: Packets out of sequence: expected: 12023, got 12021.
RTP: Packets out of sequence: expected: 12068, got 12066.
RTP: Packets out of sequence: expected: 12106, got 12104.
RTP: Packets out of sequence: expected: 12158, got 12156.
RTP: Packets out of sequence: expected: 12200, got 12197.
RTP: Packets out of sequence: expected: 12199, got 12200.
RTP: Packets out of sequence: expected: 12252, got 12250.
RTP: Packets out of sequence: expected: 12293, got 12291.
RTP: Packets out of sequence: expected: 12328, got 12326.
RTP: Packets out of sequence: expected: 12395, got 12393.
RTP: Packets out of sequence: expected: 12433, got 12430.
RTP: Packets out of sequence: expected: 12501, got 12498.
RTP: Packets out of sequence: expected: 12592, got 12588.
RTP: Packets out of sequence: expected: 12590, got 12592.
RTP: Packets out of sequence: expected: 12763, got 12761.
RTP: Packets out of sequence: expected: 12836, got 12833.
RTP: Packets out of sequence: expected: 12835, got 12836.
RTP: Packets out of sequence: expected: 12841, got 12842.
requesting resend of 1 packets starting at 12841.
RTP: Packets out of sequence: expected: 12940, got 12937.
RTP: Packets out of sequence: expected: 13245, got 13243.
RTP: Packets out of sequence: expected: 13256, got 13254.
RTP: Packets out of sequence: expected: 13268, got 13265.
RTP: Packets out of sequence: expected: 13354, got 13352.
RTP: Packets out of sequence: expected: 13358, got 13355.
RTP: Packets out of sequence: expected: 13361, got 13359.
RTP: Packets out of sequence: expected: 13531, got 13529.
RTP: Packets out of sequence: expected: 13557, got 13554.
RTP: Packets out of sequence: expected: 13565, got 13561.
RTP: Packets out of sequence: expected: 13565, got 13561.
RTP: Packets out of sequence: expected: 13611, got 13612.
requesting resend of 1 packets starting at 13611.
RTP: Packets out of sequence: expected: 13786, got 13784.
RTP: Packets out of sequence: expected: 13861, got 13859.
RTP: Packets out of sequence: expected: 13911, got 13907.
RTP: Packets out of sequence: expected: 13944, got 13941.
RTP: Packets out of sequence: expected: 14100, got 14101.
requesting resend of 1 packets starting at 14100.
RTP: Packets out of sequence: expected: 14184, got 14185.
requesting resend of 1 packets starting at 14184.
RTP: Packets out of sequence: expected: 14263, got 14261.
RTP: Packets out of sequence: expected: 14433, got 14430.
RTP: Packets out of sequence: expected: 14474, got 14472.
RTP: Packets out of sequence: expected: 14583, got 14580.
RTP: Packets out of sequence: expected: 14640, got 14637.
RTP: Packets out of sequence: expected: 14640, got 14637.
RTP: Packets out of sequence: expected: 14725, got 14723.
RTP: Packets out of sequence: expected: 14733, got 14731.
RTP: Packets out of sequence: expected: 14782, got 14780.
RTP: Packets out of sequence: expected: 14839, got 14840.
requesting resend of 1 packets starting at 14839.
RTP: Packets out of sequence: expected: 14962, got 14960.
RTP: Packets out of sequence: expected: 15008, got 15005.
RTP: Packets out of sequence: expected: 15006, got 15007.
RTP: Packets out of sequence: expected: 15020, got 15021.
requesting resend of 1 packets starting at 15020.
RTP: Packets out of sequence: expected: 15389, got 15392.
RTP: Packets out of sequence: expected: 15415, got 15418.
requesting resend of 1 packets starting at 15415.
requesting resend of 1 packets starting at 15416.
requesting resend of 1 packets starting at 15417.
requesting resend of 1 packets starting at 15389.
requesting resend of 1 packets starting at 15390.
requesting resend of 1 packets starting at 15391.
RTP: Packets out of sequence: expected: 15527, got 15523.
Sync error: -441.7 (frames); net correction: 0.0 (ppm); corrections: 0.0 (ppm); missing packets 0; late packets 585; too late packets 0; resend requests 24; min DAC queue size 39570, min and max buffer occupancy 68 and 138.
RTP: Packets out of sequence: expected: 15651, got 15655.
requesting resend of 1 packets starting at 15652.
requesting resend of 1 packets starting at 15653.
requesting resend of 1 packets starting at 15654.
RTP: Packets out of sequence: expected: 15751, got 15749.
RTP: Packets out of sequence: expected: 15755, got 15753.
requesting resend of 1 packets starting at 15651.
RTP: Packets out of sequence: expected: 15755, got 15753.
RTP: Packets out of sequence: expected: 15786, got 15783.
RTP: Packets out of sequence: expected: 15925, got 15922.
RTP: Packets out of sequence: expected: 15926, got 15927.
requesting resend of 1 packets starting at 15926.
RTP: Packets out of sequence: expected: 16139, got 16137.
RTP: Packets out of sequence: expected: 16161, got 16159.
RTP: Packets out of sequence: expected: 16235, got 16233.
RTP: Packets out of sequence: expected: 16260, got 16259.
RTP: Packets out of sequence: expected: 16331, got 16329.
RTP: Packets out of sequence: expected: 16331, got 16329.
RTP: Packets out of sequence: expected: 16466, got 16464.
RTP: Packets out of sequence: expected: 16471, got 16470.
RTP: Packets out of sequence: expected: 16473, got 16472.
RTP: Packets out of sequence: expected: 16573, got 16572.
RTP: Packets out of sequence: expected: 16576, got 16574.
RTP: Packets out of sequence: expected: 16635, got 16633.
RTP: Packets out of sequence: expected: 16759, got 16757.
RTP: Packets out of sequence: expected: 16770, got 16767.
RTP: Packets out of sequence: expected: 16789, got 16787.
RTP: Packets out of sequence: expected: 16887, got 16884.
RTP: Packets out of sequence: expected: 16898, got 16895.
RTP: Packets out of sequence: expected: 16912, got 16913.
requesting resend of 1 packets starting at 16912.
RTP: Packets out of sequence: expected: 17086, got 17083.
RTP: Packets out of sequence: expected: 17109, got 17107.
RTP: Packets out of sequence: expected: 17131, got 17129.
RTP: Packets out of sequence: expected: 17188, got 17186.
RTP: Packets out of sequence: expected: 17503, got 17500.
RTP: Packets out of sequence: expected: 17549, got 17548.
RTP: Packets out of sequence: expected: 17684, got 17682.
RTP: Packets out of sequence: expected: 17924, got 17922.
RTP: Packets out of sequence: expected: 17940, got 17938.
RTP: Packets out of sequence: expected: 18071, got 18069.
RTP: Packets out of sequence: expected: 18120, got 18117.
RTP: Packets out of sequence: expected: 18123, got 18121.
RTP: Packets out of sequence: expected: 18123, got 18121.
RTP: Packets out of sequence: expected: 18126, got 18128.
requesting resend of 1 packets starting at 18126.
requesting resend of 1 packets starting at 18127.
RTP: Packets out of sequence: expected: 18225, got 18222.
RTP: Packets out of sequence: expected: 18292, got 18290.
RTP: Packets out of sequence: expected: 18315, got 18312.
RTP: Packets out of sequence: expected: 18385, got 18386.
requesting resend of 1 packets starting at 18385.
RTP: Packets out of sequence: expected: 18462, got 18459.
RTP: Packets out of sequence: expected: 18496, got 18492.
RTP: Packets out of sequence: expected: 18507, got 18508.
requesting resend of 1 packets starting at 18507.
RTP: Packets out of sequence: expected: 18590, got 18588.
RTP: Packets out of sequence: expected: 18605, got 18601.
RTP: Packets out of sequence: expected: 18616, got 18613.
RTP: Packets out of sequence: expected: 18725, got 18722.
RTP: Packets out of sequence: expected: 18724, got 18725.
RTP: Packets out of sequence: expected: 18754, got 18755.
RTP: Packets out of sequence: expected: 18774, got 18777.
requesting resend of 1 packets starting at 18774.
requesting resend of 1 packets starting at 18775.
requesting resend of 1 packets starting at 18776.
requesting resend of 1 packets starting at 18754.
RTP: Packets out of sequence: expected: 18894, got 18891.
RTP: Packets out of sequence: expected: 18992, got 18990.
RTP: Packets out of sequence: expected: 19067, got 19066.
RTP: Packets out of sequence: expected: 19089, got 19087.
RTP: Packets out of sequence: expected: 19112, got 19109.
RTP: Packets out of sequence: expected: 19111, got 19109.
RTP: Packets out of sequence: expected: 19131, got 19128.
RTP: Packets out of sequence: expected: 19195, got 19194.
RTP: Packets out of sequence: expected: 19236, got 19233.
RTP: Packets out of sequence: expected: 19235, got 19233.
RTP: Packets out of sequence: expected: 19235, got 19236.
RTP: Packets out of sequence: expected: 19259, got 19260.
RTP: Packets out of sequence: expected: 19330, got 19327.
requesting resend of 1 packets starting at 19259.
Sync error: -476.9 (frames); net correction: 0.0 (ppm); corrections: 0.0 (ppm); missing packets 0; late packets 723; too late packets 0; resend requests 39; min DAC queue size 39746, min and max buffer occupancy 67 and 137.
RTP: Packets out of sequence: expected: 19409, got 19406.
RTP: Packets out of sequence: expected: 19544, got 19541.
RTP: Packets out of sequence: expected: 19564, got 19566.
requesting resend of 1 packets starting at 19564.
requesting resend of 1 packets starting at 19565.
RTP: Packets out of sequence: expected: 19649, got 19647.
RTP: Packets out of sequence: expected: 19770, got 19766.
RTP: Packets out of sequence: expected: 19781, got 19778.
RTP: Packets out of sequence: expected: 19796, got 19793.
RTP: Packets out of sequence: expected: 19838, got 19841.
requesting resend of 1 packets starting at 19838.
requesting resend of 1 packets starting at 19839.
requesting resend of 1 packets starting at 19840.
RTP: Packets out of sequence: expected: 19981, got 19982.
requesting resend of 1 packets starting at 19981.
RTP: Packets out of sequence: expected: 20199, got 20202.
RTP: Packets out of sequence: expected: 20211, got 20203.
RTP: Packets out of sequence: expected: 20205, got 20211.
RTP: Packets out of sequence: expected: 20221, got 20213.
requesting resend of 1 packets starting at 20200.
requesting resend of 1 packets starting at 20201.
requesting resend of 1 packets starting at 20199.
RTP: Packets out of sequence: expected: 20311, got 20307.
RTP: Packets out of sequence: expected: 20311, got 20307.
RTP: Packets out of sequence: expected: 20312, got 20315.
requesting resend of 1 packets starting at 20312.
requesting resend of 1 packets starting at 20313.
requesting resend of 1 packets starting at 20314.
RTSP shutdown requested.
Closing down RTSP conversation thread...
audio_alsa stop called.
audio_alsa flush called.
Shut down audio, control and timing threads
Audio receiver -- Server RTP thread interrupted. terminating.Control RTP thread interrupted. terminating.
Timing thread interrupted. terminating.
rtp_timing_sender thread interrupted. terminating.

Closed and terminated timer requester thread.
Timing RTP thread terminated.
timing thread joined
audio thread joined
control thread joined
Player thread exit
shutting down RTP thread
RTSP conversation thread terminated.

Same configuration but playback from smartphone with strong stutter:

pi@rpi2 ~ $ sudo nice -n -10 shairport-sync -vv
Looking for the configuration file "/etc/shairport-sync.conf".
Looking for configuration file at full path "/etc/shairport-sync.conf"
audio_alsa init called.
Output device name is "hw:0".
Open Mixer
Lowest dB value is a mute.
Can't get dB value corresponding to a "volume" of 1.
Hardware mixer has dB volume from -103.000000 to 0.000000.
Has mute ability.
startup
The processor is running little-endian.
statistics_requester status is 1.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "my Shairport Sync".
Audio Output name is "alsa".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
mdns backend "(null)".
userSuppliedLatency is 0.
AirPlayLatency is -1.
iTunesLatency is -1.
forkedDaapdLatency is -1.
stuffing option is "0".
resync time is 0.
allow a session to be interrupted: 1.
busy timeout time is 1.
tolerance is 1800 frames.
password is "(null)".
ignore_volume_control is 0.
audio backend desired buffer length is 41000.
audio backend latency offset is 0.
volume range in dB (zero means use the range specified by the mixer): 0.
configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
avahi: avahi_register.
avahi: register_service.
Avahi without metadata
culling threads.
New RTSP connection on port 5000
Play connection from user agent "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4".
User-Agent is iTunes 10 or better, (actual version is 11); selecting the iTunes latency of -1 frames.
rtp_setup: cport=6001 tport=6002.
Connection from IPv4: 192.168.1.2:51446
listening for audio, control and timing on ports 6001, 6002, 6003.
audio_alsa start called.
Audio receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Timing receiver -- Server RTP thread starting.
Timing sender thread starting.
audio_alsa flush called.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: 0.000000

audio_alsa mute called.
Setting volume db to 0.000000.
syncing to seqno 7331.
Open Mixer
Setting volume db to 0.000000.
SET_PARAMETER Content-Type:"text/parameters".
received parameters in SET_PARAMETER request.
volume: 0.000000

audio_alsa mute called.
Setting volume db to 0.000000.
RTP: Packets out of sequence: expected: 7614, got 7612.
RTP: Packets out of sequence: expected: 7669, got 7665.
RTP: Packets out of sequence: expected: 7688, got 7686.
RTP: Packets out of sequence: expected: 7688, got 7686.
RTP: Packets out of sequence: expected: 7857, got 7855.
RTP: Packets out of sequence: expected: 8006, got 8004.
RTP: Packets out of sequence: expected: 8154, got 8152.
RTP: Packets out of sequence: expected: 8383, got 8374.
RTP: Packets out of sequence: expected: 8390, got 8389.
RTP: Packets out of sequence: expected: 8444, got 8438.
RTP: Packets out of sequence: expected: 8487, got 8485.
RTP: Packets out of sequence: expected: 8527, got 8525.
RTP: Packets out of sequence: expected: 8583, got 8581.
RTP: Packets out of sequence: expected: 8701, got 8697.
RTP: Packets out of sequence: expected: 8704, got 8702.
RTP: Packets out of sequence: expected: 8737, got 8739.
requesting resend of 1 packets starting at 8737.
requesting resend of 1 packets starting at 8738.
requesting resend of 1 packets starting at 8737.
requesting resend of 1 packets starting at 8738.
requesting resend of 1 packets starting at 8737.
requesting resend of 1 packets starting at 8738.
requesting resend of 1 packets starting at 8737.
requesting resend of 1 packets starting at 8738.
RTP: Packets out of sequence: expected: 8968, got 8966.
RTP: Packets out of sequence: expected: 8968, got 8966.
Aliasing of buffer index -- reset.
RTP: Packets out of sequence: expected: 9276, got 9273.
RTP: Packets out of sequence: expected: 9300, got 9292.
RTP: Packets out of sequence: expected: 9396, got 9394.
Player: packets out of sequence: expected: 8737, got: 9249, sync error: 0 frames.
RTP: Packets out of sequence: expected: 9418, got 9416.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
RTP: Packets out of sequence: expected: 9468, got 9466.
RTP: Packets out of sequence: expected: 9482, got 9480.
RTP: Packets out of sequence: expected: 9482, got 9480.
RTP: Packets out of sequence: expected: 9533, got 9536.
requesting resend of 1 packets starting at 9533.
requesting resend of 1 packets starting at 9534.
requesting resend of 1 packets starting at 9535.
RTP: Packets out of sequence: expected: 9661, got 9659.
requesting resend of 1 packets starting at 9533.
requesting resend of 1 packets starting at 9534.
requesting resend of 1 packets starting at 9535.
requesting resend of 1 packets starting at 9533.
requesting resend of 1 packets starting at 9534.
requesting resend of 1 packets starting at 9535.
requesting resend of 1 packets starting at 9533.
requesting resend of 1 packets starting at 9534.
requesting resend of 1 packets starting at 9535.
RTP: Packets out of sequence: expected: 9695, got 9693.
RTP: Packets out of sequence: expected: 9694, got 9695.
Aliasing of buffer index -- reset.
RTP: Packets out of sequence: expected: 10048, got 10049.
Player: packets out of sequence: expected: 9533, got: 10045, sync error: 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 writing 352 samples in play() Broken pipe.
RTP: Packets out of sequence: expected: 10392, got 10388.
RTP: Packets out of sequence: expected: 10399, got 10396.
RTP: Packets out of sequence: expected: 10449, got 10447.
Aliasing of buffer index -- reset.
RTP: Packets out of sequence: expected: 10658, got 10655.
RTP: Packets out of sequence: expected: 10716, got 10714.
RTP: Packets out of sequence: expected: 10722, got 10720.
Player: packets out of sequence: expected: 10048, got: 10560, sync error: 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
RTP: Packets out of sequence: expected: 10836, got 10834.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
RTP: Packets out of sequence: expected: 10951, got 10947.
RTP: Packets out of sequence: expected: 10960, got 10957.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
RTP: Packets out of sequence: expected: 11003, got 11001.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
Error -32 in delay(): Broken pipe. Delay reported is 0 frames.
RTP: Packets out of sequence: expected: 11088, got 11089.
requesting resend of 1 packets starting at 11088.
requesting resend of 1 packets starting at 11088.
requesting resend of 1 packets starting at 11088.
requesting resend of 1 packets starting at 11088.
RTP: Packets out of sequence: expected: 11268, got 11269.
RTP: Packets out of sequence: expected: 11370, got 11371.
RTSP shutdown requested.
Closing down RTSP conversation thread...
audio_alsa stop called.
audio_alsa flush called.
Shut down audio, control and timing threads
Control RTP thread interrupted. terminating.
Audio receiver -- Server RTP thread interrupted. terminating.
Timing thread interrupted. terminating.
rtp_timing_sender thread interrupted. terminating.
Closed and terminated timer requester thread.
Timing RTP thread terminated.
timing thread joined
audio thread joined
control thread joined
Player thread exit
shutting down RTP thread
RTSP conversation thread terminated.

Hopefully the wealth of log files helps narrowing the issue down.

Thanks a lot in advance! (Smooth playback from shairport-sync is the last thing missing from me being happy with my raspi setup :-) )

mikebrady commented 8 years ago

Thanks for all this. It seems you might have found that the WiFi is at least partly responsible for the stuttering, which is considerable progress. As to the problems you've identified, let me quote some of your comments and give replies below:

This does not work for me. Irrespective of my stuttering playback, I can not interrupt the session, if first I play using AirAudio and then try to switch to my laptop. Playback from my smartphone continues, though the Mac shows, that it connected?! A repeated test lead to an access violation

There are lots of FIXME messages coming from the Apple Lossless decoder (in alac.c), as if it's seeing corrupted packets. I need to figure out how, perhaps, to stop the packets being corrupted and/or make the decoder more robust in its handling of corrupt packets. I suspect that this is what's causing the crash of Shairport Sync. TBH I've been reluctant to mess with the decoder code because it's such a great piece of code, but I might have to do something about those "FIXME" situations...

The old shairport by abrasive works just fine with minimal configuration effort (I only specified the buffer length to 400 and started the process with a very low niceness level). I observe no stuttering sound and am able to interrupt the sources.

Shairport-sync unfortunately struggles with playback. I tried many combinations of buffer lengths, resynchronization, etc. to no avail. The Packets out of sequence message sticks out -- might there be a regression in filling the buffer, compared to shairport? When increasing the loglevel to vvv I get many (!!!) audio_alsa play called. and audio_alsa delay called. messages. Moreover interrupting still does not work as hoped.

When looking at the output of the shairport-sync process, I get the impression that the expected package often is off by only 1 to 5 packages. Isn't it feasible to bring the received packages into order during reception and before playback? (Sorry, my naive assumption is that the buffer should be filled irrespective of the order).

Taking the last item first, Shairport Sync waits for 16 more packets before deciding that an absent packet is "missing" and requesting a resend.

The "RTP: Packets out of sequence:" message means that packets are being received out of order before they are placed in a buffer that puts them into order. This is generally harmless, as you point out.

The "Player: packets out of sequence:" message means that packets are about to be played that are out of sequence coming from the buffer – this is bad. Notice that the difference between sequence numbers is often 512, which is the number of packets the buffer has slots for.

Resend requests are noted in the log separately, as you can see. So your "naive assumption" is completely right.

The audio_alsa… messages are just diagnostic, and there should be lots of them.

One of the differences between Shairport and Shairport Sync is that the audio port chosen in Shairport is unspecified, and therefore tends to be different each time, whereas Shairport Sync attempts to use the same port — 6001 — each time. I wonder if it is therefore possible that the two sources could be writing to the same port at the same time, potentially corrupting the stream and causing the FIXME problems. If this was true, then reverting Shairport Sync's port selection mechanism to be like the original Shairport mechanism would ameliorate the issue. That can be done by setting the udp_port_base setting to 0.

PeterPablo commented 8 years ago

Setting udp_port_base=0; indeed makes switching between laptop and phone work repeatedly in both directions! Thank you for the hint! Apart I am still struggling with my wifi. hmm...

mikebrady commented 8 years ago

Thanks for the update – it's good that the work-around works. All I have to do now is figure out how to deal with the problem directly.

Can't help you with the WiFi, though...

joerg-krause commented 8 years ago

I observed that shairport-sync tends to stutter a lot more if started with a low niceness level, e.g -15. However, running shairport-sync with a niceness of -1 works just fine.

I guess for low-powered devices a low niceness eats to much cpu cycles, so that other processes like wifi or alsa becomes a bottleneck.

mikebrady commented 7 years ago

Hi there. I have pushed a number of updates to the development branch aimed at improving the stability of Shairport Sync in those rare (!) situations where there are problems. So far, the changes seem to be effective. I've been running a system where a session is interruptible by another – i.e. one of the causes of instability reported here – and it seems really pretty stable. If you were interested to try it out, I'd be glad to hear of your experiences.

mikebrady commented 7 years ago

Hello again. There are still some coding practices that need to be cleaned up that might be causing problems. I'll come back here when they are fixed.

mikebrady commented 5 years ago

I'm pretty sure this has finally been fixed. Please open a new issue if necessary.