search

mikebrady / shairport-sync

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

Segmentation fault on playback #681

Closed kowalcj0 closed 6 years ago

kowalcj0 commented 6 years ago

Hi,

Every time I'm trying to play audio via shairport-sync it crashes.

my setup is:

PS. AirAudio works just fine with Shairport 1.1.1-23-gd65b8e8.

Today I've compiled latest available version of shairport-sync

./configure --with-alsa --with-stdout --with-pipe --with-avahi --with-ssl=openssl --with-soxr --with-metadata --with-systemd  --sysconfdir=/etc

$ shairport-sync -V
3.2RC1-OpenSSL-Avahi-ALSA-stdout-pipe-soxr-metadata-sysconfdir:/etc
$ aplay -l
**** List of PLAYBACK Hardware Devices ****
card 0: sndrpihifiberry [snd_rpi_hifiberry_dacplus], device 0: HiFiBerry DAC+ Pro HiFi pcm512x-hifi-0 []
  Subdevices: 1/1
  Subdevice #0: subdevice #0

Here's the config: /etc/shairport-sync.conf

general =
{
    name = "mpdAirPort";
    interpolation = "basic"; 
    output_backend = "alsa"; 
    mdns_backend = "avahi"; 
    playback_mode = "stereo";
};

sessioncontrol = 
{
    run_this_before_play_begins = "/usr/bin/mpc stop -q";
    wait_for_completion = "yes";
    allow_session_interruption = "yes";
};

alsa =
{
  output_device = "snd_rpi_hifiberry_dacplus";
};

diagnostics =
{
    log_verbosity = 3; // "0" means no debug verbosity, "3" is most verbose.
};
$ shairport-sync -vvv
Looking for configuration file at full path "/etc/shairport-sync.conf"
alsa output device name is "snd_rpi_hifiberry_dacplus".
The processor is running little-endian.
Version: "3.2RC1-OpenSSL-Avahi-ALSA-stdout-pipe-soxr-metadata-sysconfdir:/etc"
statistics_requester status is 0.
daemon status is 0.
deamon pid file is "/var/run/shairport-sync/shairport-sync.pid".
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
player name is "mpdAirPort".
backend is "alsa".
on-start action is "/usr/bin/mpc stop -q".
on-stop action is "(null)".
wait-cmd status is 1.
on-start returns output is 0.
mdns backend "avahi".
userSuppliedLatency is 0.
stuffing option is "0" (0-basic, 1-soxr).
resync time is 0.050000 seconds.
allow a session to be interrupted: 1.
busy timeout time is 120.
drift tolerance is 0.001995 seconds.
password is "(null)".
ignore_volume_control is 0.
volume_max_db is not set
playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
disable_synchronization is 0.
use_mmap_if_available is 1.
output_rate is 44100.
output_format is 3 (0-unknown, 1-S8, 2-U8, 3-S16, 4-S24, 5-S24_3LE, 6-S24_3BE, 7-S32).
audio backend desired buffer length is 0.150000 seconds.
audio backend latency offset is 0.000000 seconds.
audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
volume range in dB (zero means use the range specified by the mixer): 0.
zeroconf regtype is "_raop._tcp".
decoders_supported field is 1.
use_apple_decoder is 0.
alsa_use_playback_switch_for_mute is 0.
no special mdns service interface was requested.
configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
metadata enabled is 0.
metadata pipename is "(null)".
metadata socket address is "(null)" port 0.
metadata socket packet size is "500".
get-coverart is 0.
loudness is 0.
loudness reference level is -20.000000
disable resend requests is 0 -- non-zero means "yes"
avahi: service '179B25B577D0@mpdAirPort' group is not yet committed.
avahi: request to add "_raop._tcp" service without metadata
avahi: service '179B25B577D0@mpdAirPort' group is registering.
avahi: service '179B25B577D0@mpdAirPort' successfully added.

// here's the part when I start playing the audio

New RTSP connection from 192.168.1.120:55736 to self at 192.168.1.112:5000 on conversation thread 1.
Successfully created RTSP receiver thread 1.
    Apple-Challenge: 9OsoWRfxJXoQpz7n0dUqyg.
    CSeq: 1.
    Client-Instance: 312FCC4E482163E7.
    Content-Length: 572.
    Content-Type: application/sdp.
    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4.
RTSP thread 1 received an RTSP Packet of type "ANNOUNCE":
  Type: "Apple-Challenge", content: "9OsoWRfxJXoQpz7n0dUqyg"
  Type: "CSeq", content: "1"
  Type: "Client-Instance", content: "312FCC4E482163E7"
  Type: "Content-Length", content: "572"
  Type: "Content-Type", content: "application/sdp"
  Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
Connection 1: ANNOUNCE
RTSP conversation thread 1 has acquired play lock.
Play connection from user agent "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4" on RTSP conversation thread 1.
RTSP thread 1: RTSP Response:
  Type: "Apple-Response", content: "yBcF3sKtwKOiA3hN/WzFXcBki/p5/JHdlB2rWXgLAcZw7tiandMRIOCr6UvJcZusvNmELdxrWV9OpSRmHNuxDPs5kZ34zlX3y5Wy46SwqclZS0fh1MkfVG+rOYVgn2ga5oZ0MiNMWC6Peunj97X1RxVOt053Mi4692NyGZxxlE0kOyyRlB9fkKzvY9JixKo1QGUUVVXiUzCQlgCJZwmz2p1eac/YVe9zJLTk6/lgqAKA4IEUIbiThJOcYt6gALeHkffEQDF/T2/Vly2RzOiM7nGxCO88b+bKqK7r1E7HN8bNRbVEFxca+e+R1zegP0DL2Ih6HAjVg3ObH6wXNDJfMQ"
  Type: "CSeq", content: "1"
  Type: "Server", content: "AirTunes/105.1"
    CSeq: 2.
    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.
    Client-Instance: 312FCC4E482163E7.
RTSP thread 1 received an RTSP Packet of type "SETUP":
  Type: "CSeq", content: "2"
  Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
  Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002"
  Type: "Client-Instance", content: "312FCC4E482163E7"
Connection 1: SETUP
rtp_setup: cport=6001 tport=6002.
Set up play connection from 192.168.1.120 to self at 192.168.1.112 on RTSP conversation thread 1.
listening for audio, control and timing on ports 6001, 6002, 6003.
RTSP thread 1: RTSP Response:
  Type: "CSeq", content: "2"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6002;timing_port=6003;server_port=6001"
  Type: "Session", content: "1"
    RTP-Info: seq=4287;rtptime=370383.
    CSeq: 3.
    Client-Instance: 312FCC4E482163E7.
    Session: 1.
    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4.
    Range: npt=0-.
RTSP thread 1 received an RTSP Packet of type "RECORD":
  Type: "RTP-Info", content: "seq=4287;rtptime=370383"
  Type: "CSeq", content: "3"
  Type: "Client-Instance", content: "312FCC4E482163E7"
  Type: "Session", content: "1"
  Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
  Type: "Range", content: "npt=0-"
Connection 1: RECORD
pbeg
No latency has (yet) been specified. Setting 88,200 (2 seconds) frames as a default.
Flush requested up to 370382. It seems as if 0 is special.
RTSP thread 1: RTSP Response:
  Type: "CSeq", content: "3"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Audio-Latency", content: "11025"
Output frame bytes is 4.
Control receiver -- Server RTP thread starting.
Timing receiver -- Server RTP thread starting.
Output bit depth is 16.
Segmentation fault

I'd be grateful for any help Cheers

mikebrady commented 6 years ago

Thanks for the report. A few quick questions / clarifications please: does this crash happen if you don’t have an on-start action? Does it happen if you don’t allow a session to be interrupted? Finally, does AirAudio have a non-root mode, even if limited? Thanks.

[Update] I see that AirAudio runs in a non-root mode for demonstration, so I'll try that. There is no need to bother with the other stuff for the present, thanks.

mikebrady commented 6 years ago

Okay, the cause has been found and fixed. The problem is that AirAudio does not provide certain information in the messages it exchanges with Shairport Sync and this was causing Shairport Sync to crash. Fixed in the development version and in 3.2RC2. I'd be grateful if you would try it out. Thanks for the report.

kowalcj0 commented 6 years ago

WOW! That was a lightning fast response and fix! Thanks a lot! Will try it out later today.

mikebrady commented 6 years ago

Super, thanks.

mikebrady commented 6 years ago

BTW, there's more to be done with how Shairport Sync's new D-Bus interface handles metadata coming from AirAudio, but that will take longer...

kowalcj0 commented 6 years ago

Couldn't wait with testing. I works yet the playback isn't smooth as I'm getting a lot of popping noises Here's what the logs say:

Apr 11 12:38:15 mpd shairport-sync[5636]: Play frame 25800.
Apr 11 12:38:16 mpd shairport-sync[5636]: Play frame 25900.
Apr 11 12:38:16 mpd shairport-sync[5636]: CSeq: 20.
Apr 11 12:38:16 mpd shairport-sync[5636]: Client-Instance: 7E15C15A9B8E387D.
Apr 11 12:38:16 mpd shairport-sync[5636]: Session: 1.
Apr 11 12:38:16 mpd shairport-sync[5636]: User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4.
Apr 11 12:38:16 mpd shairport-sync[5636]: RTSP thread 1 received an RTSP Packet of type "OPTIONS":
Apr 11 12:38:16 mpd shairport-sync[5636]: Type: "CSeq", content: "20"
Apr 11 12:38:16 mpd shairport-sync[5636]: Type: "Client-Instance", content: "7E15C15A9B8E387D"
Apr 11 12:38:16 mpd shairport-sync[5636]: Type: "Session", content: "1"
Apr 11 12:38:16 mpd shairport-sync[5636]: Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
Apr 11 12:38:16 mpd shairport-sync[5636]: Connection 1: OPTIONS
Apr 11 12:38:16 mpd shairport-sync[5636]: RTSP thread 1: RTSP Response:
Apr 11 12:38:16 mpd shairport-sync[5636]: Type: "CSeq", content: "20"
Apr 11 12:38:16 mpd shairport-sync[5636]: Type: "Server", content: "AirTunes/105.1"
Apr 11 12:38:16 mpd shairport-sync[5636]: Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
Apr 11 12:38:16 mpd shairport-sync[5636]: Play frame 26000.
Apr 11 12:38:17 mpd shairport-sync[5636]: Play frame 26100.
Apr 11 12:38:17 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 32081.
Apr 11 12:38:17 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 32094.
Apr 11 12:38:18 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:18 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:18 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 32139.
Apr 11 12:38:18 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:18 mpd shairport-sync[5636]: Play frame 26200.
Apr 11 12:38:19 mpd shairport-sync[5636]: Play frame 26300.
Apr 11 12:38:20 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 32378.
Apr 11 12:38:20 mpd shairport-sync[5636]: Play frame 26400.
Apr 11 12:38:20 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:20 mpd shairport-sync[5636]: Play frame 26500.
Apr 11 12:38:21 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 32488.
Apr 11 12:38:21 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 32500.
Apr 11 12:38:21 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:21 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 32524.
Apr 11 12:38:21 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:21 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:21 mpd shairport-sync[5636]: Play frame 26600.
Apr 11 12:38:22 mpd shairport-sync[5636]: Play frame 26700.
Apr 11 12:38:23 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 32755.
Apr 11 12:38:23 mpd shairport-sync[5636]: Play frame 26800.
Apr 11 12:38:23 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:23 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 32797.
Apr 11 12:38:23 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 32802.
Apr 11 12:38:23 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:23 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:23 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 32852.
Apr 11 12:38:24 mpd shairport-sync[5636]: Play frame 26900.
Apr 11 12:38:24 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:24 mpd shairport-sync[5636]: Play frame 27000.
Apr 11 12:38:25 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 32991.
Apr 11 12:38:25 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:25 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 33076.
Apr 11 12:38:25 mpd shairport-sync[5636]: Play frame 27100.
Apr 11 12:38:25 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:26 mpd shairport-sync[5636]: Play frame 27200.
Apr 11 12:38:26 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 33185.
Apr 11 12:38:26 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 33187.
Apr 11 12:38:26 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 33207.
Apr 11 12:38:26 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:26 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:26 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:27 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 33243.
Apr 11 12:38:27 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:27 mpd shairport-sync[5636]: Play frame 27300.
Apr 11 12:38:27 mpd shairport-sync[5636]: requesting resend of 1 packets starting at 33285.
Apr 11 12:38:27 mpd shairport-sync[5636]: Player has a supplied silent frame.
Apr 11 12:38:28 mpd shairport-sync[5636]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8046.6,    15015.5,   492201.0.

What might be causing those silent frames and packet resending requests?

mikebrady commented 6 years ago

Thanks. It looks like some of the packets of audio samples (sometimes called "frames") are being lost. Shairport Sync is requesting retransmission of them but it looks like it isn't getting them, so it is replacing them with frames containing just silence -- this is probably coming across as popping.

A thing to do is to enable statistics in Shairport Sync; it gives an idea of the number of frames that are being lost. I'd be interested in seeing that, BTW, and I'll try it on my own setup later this evening. I'd like to check to see if the frames are being retransmitted in some unusual fashion.

mikebrady commented 6 years ago

It may also be that the packets are indeed being retransmitted but are arriving too late to be used. The statistics may show that...

kowalcj0 commented 6 years ago

Should we close this issue or wait until you'll have a look into it?

mikebrady commented 6 years ago

I think this issue should be closed, as it's fixed. But I will have a look at the missing frames issue in the next few days, possibly even tonight.

mikebrady commented 6 years ago

So, I had a look at this missing frames issue. AFAIKT AirAudio isn't responding to the requests for resends -- nothing is coming back on any port. I [think I have] set a message to AirAudio through their help desk, so let's see what their response is. If you felt like sending them another message, that would be great.

kowalcj0 commented 6 years ago

Will do. Many thanks

funtax commented 6 years ago

Hi everyone!

I already responded @mikebrady with the following information:

AirAudio does support the resend-method of the AirPlay-protocol!

In very early versions (in 2013) this was missing, but since ~2014 it's working well.

You should see resend-requests made to AirAudio inside the "logcat"-output of your Android, somethink like "Resend-request for seqNum...". You might filter for "AirAudio".

Are you using a hardcoded default http-port (eg. 6001), or are you using the one assigned + reported by AirAudio as the "control"-port inside the SETUP-section?

final String transport = "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port="

In your logs above, I see that AirAudio sends port control-port 6001 & timing-port 6002 to shairport-sync, but reports different ports.. pretty sure this is correct, but maybe this might be an issue:

Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
  Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;**control_port=6001;timing_port=6002**"
  Type: "Client-Instance", content: "312FCC4E482163E7"
Connection 1: SETUP
rtp_setup: cport=6001 tport=6002.
Set up play connection from 192.168.1.120 to self at 192.168.1.112 on RTSP conversation thread 1.
listening for audio, **control** and timing on ports 6001, **6002**, 6003.
RTSP thread 1: RTSP Response:
  Type: "CSeq", content: "2"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6002;timing_port=6003;server_port=6001"
  Type: "Session", content: "1"

But I assume AirAudio is correctly using them:

        this.serverAddress = new InetSocketAddress(getAddress(),
                Integer.parseInt(props.get("server_port")));

        if (props.containsKey("timing_port")) {
            this.timingAddress = new InetSocketAddress(getAddress(),
                    Integer.parseInt(props.get("timing_port")));
        } else {
            this.timingAddress = new InetSocketAddress(getAddress(),
                    Integer.parseInt(props.get("event_port")));
        }
        this.controlAddress = new InetSocketAddress(getAddress(),
                Integer.parseInt(props.get("control_port")));

Now I had a look into the code and fond the following, this might be the problem with shairport-sync:

When AirAudio receives a resend-request on its control-port, it loops through its list of connected AirPlay-sinks and check if the "socketAddress" of the UDP-packet matches the control-address, reported by the AirPlay-sink:

for (AirPlaySink sink : sinks) {
                               --->>> if (packet.getSocketAddress().equals(
                                        sink.getControlAddress())) {  <<<---

                                    for (int i = 0; i < missedPackets; i++) 
....

I'm no more aware of this section as it's untouched for years meanwhile - but maybe the "socketAddress" is the sent UDP-packet in the resend-request is not the one, reported by shairport-sync?

Sorry, I haven't touched this section for years as it's afaik working stable with all official AirPlay-receivers.

mikebrady commented 6 years ago

Many thanks for your reply. I'll have a close look at it over the next few days. By the way, I did check that the resend requests made by Shairport Sync are responded to by iTunes, AirPlay, etc., and they are. So it's a mystery!

[Update] Your suggestion is intriguing, and I'll have a really close look at it tonight.

mikebrady commented 6 years ago

So, I had a look at this, and I don't think your reasoning is correct, I'm afraid.

In the sequence of log messages you quote:

Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
  Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;**control_port=6001;timing_port=6002**"
  Type: "Client-Instance", content: "312FCC4E482163E7"
Connection 1: SETUP
rtp_setup: cport=6001 tport=6002.
Set up play connection from 192.168.1.120 to self at 192.168.1.112 on RTSP conversation thread 1.
listening for audio, **control** and timing on ports 6001, **6002**, 6003.
RTSP thread 1: RTSP Response:
  Type: "CSeq", content: "2"
  Type: "Server", content: "AirTunes/105.1"
  Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6002;timing_port=6003;server_port=6001"
  Type: "Session", content: "1"

The line that begins "User-Agent" is coming from AirAudio, saying that is is using port 6001 as a control port and 6002 as a timing port. The response indicates that Shairport Sync is reporting back that it's using port 6002 on its own machine to listen for control packets from AirAudio and similarly it's using local port 6003 to listen for timing information. In any case, I changed the code to use the same ports on the local Shairport Sync machine as AirAudio is using on the Android phone. It makes no difference -- you'll see the log of requests but no responses.

./shairport-sync -vvv
Looking for configuration file at full path "/etc/shairport-sync.conf"
         0.002498619|alsa output device name is "hw:0".
         0.000351142|Open Mixer
         0.000330621|Mixer device name is "hw:0".
         0.008128974|Mixer Control name is "PCM".
         0.000704524|Lowest dB value is a mute
         0.000415568|Hardware mixer has dB volume from -102.380000 to 4.000000.
         0.000525359|The processor is running little-endian.
         0.000831918|Version: "3.2d38-mbedTLS-Avahi-ALSA-pa-dummy-stdout-pipe-soxr-metadata-dbus-mpris-sysconfdir:/etc"
         0.000746294|statistics_requester status is 0.
         0.000656608|daemon status is 0.
         0.000749731|deamon pid file is "/var/run/shairport-sync/shairport-sync.pid".
         0.000714524|rtsp listening port is 5000.
         0.000817387|udp base port is 6001.
         0.000580202|udp port range is 100.
         0.000648899|player name is "Raspberrypi3w".
         0.000418016|backend is "(null)".
         0.000461662|on-start action is "(null)".
         0.000432756|on-stop action is "(null)".
         0.000690669|wait-cmd status is 0.
         0.000869470|on-start returns output is 0.
         0.000546192|mdns backend "(null)".
         0.000602754|userSuppliedLatency is 0.
         0.000481453|stuffing option is "0" (0-basic, 1-soxr).
         0.000362600|resync time is 0.050000 seconds.
         0.000265362|allow a session to be interrupted: 1.
         0.000440047|busy timeout time is 120.
         0.001058687|drift tolerance is 0.010000 seconds.
         0.000824105|password is "(null)".
         0.000416090|ignore_volume_control is 0.
         0.000412183|volume_max_db is not set
         0.000705461|playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000501297|disable_synchronization is 0.
         0.000901188|use_mmap_if_available is 1.
         0.000348746|output_rate is 44100.
         0.000037499|output_format is 3 (0-unknown, 1-S8, 2-U8, 3-S16, 4-S24, 5-S24_3LE, 6-S24_3BE, 7-S32).
         0.000030521|audio backend desired buffer length is 0.150000 seconds.
         0.000033281|audio backend latency offset is 0.000000 seconds.
         0.000033177|audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
         0.000033280|volume range in dB (zero means use the range specified by the mixer): 50.
         0.000030729|zeroconf regtype is "_raop._tcp".
         0.000027500|decoders_supported field is 1.
         0.000026979|use_apple_decoder is 0.
         0.000026875|alsa_use_playback_switch_for_mute is 0.
         0.000027812|no special mdns service interface was requested.
         0.000079999|configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000036770|metadata enabled is 1.
         0.000028073|metadata pipename is "/tmp/shairport-sync-metadata".
         0.000028646|metadata socket address is "(null)" port 0.
         0.000029062|metadata socket packet size is "500".
         0.000027708|get-coverart is 1.
         0.000026145|loudness is 0.
         0.000025625|loudness reference level is -20.000000
         0.000033281|disable resend requests is 0 -- non-zero means "yes"
         0.000988375|setting dacp_server_active and advanced_dacp_server_active to 0 with an update flag value of 0
         0.018473966|avahi: service '605B2B5EEB50@Raspberrypi3w' group is not yet committed.
         0.003764647|*warning: Could not acquire a Shairport Sync native D-Bus interface "org.gnome.ShairportSync.i20601" on the system bus.
         0.000063645|avahi: request to add "_raop._tcp" service with metadata
         0.001888886|*warning: Could not acquire an MPRIS interface named "org.mpris.MediaPlayer2.ShairportSync.i20601" on the system bus.
         0.000083697|avahi: service '605B2B5EEB50@Raspberrypi3w' group is registering.
         0.840269073|avahi: service '605B2B5EEB50@Raspberrypi3w' successfully added.
         0.009948017|New RTSP connection from 192.168.50.62:54497 to self at 192.168.50.109:5000 on conversation thread 1.
         0.001025093|Successfully created RTSP receiver thread 1.         0.000108020|    CSeq: 1.
         0.000341090|    User-Agent: iTunes/12.7.4 (Macintosh; OS X 10.13.4) (dt:1).
         0.000039687|    Client-Instance: F18FE780B35CFD8D.
         0.000034323|    DACP-ID: F18FE780B35CFD8D.
         0.000041457|    Active-Remote: 24052017.
         0.000038125|RTSP thread 1 received an RTSP Packet of type "OPTIONS":
         0.000032552|  Type: "CSeq", content: "1"
         0.000028385|  Type: "User-Agent", content: "iTunes/12.7.4 (Macintosh; OS X 10.13.4) (dt:1)"
         0.000031302|  Type: "Client-Instance", content: "F18FE780B35CFD8D"
         0.000030364|  Type: "DACP-ID", content: "F18FE780B35CFD8D"
         0.000029166|  Type: "Active-Remote", content: "24052017"
         0.000037135|Connection 1: OPTIONS
         0.000032448|RTSP thread 1: RTSP Response:
         0.000028437|  Type: "CSeq", content: "1"
         0.000027604|  Type: "Server", content: "AirTunes/105.1"
         0.000028958|  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"

         0.004515107|RTSP conversation thread 1 -- connection closed.
         0.000042708|Synchronously terminate playing thread of RTSP conversation thread 1.
         0.000044791|player thread of RTSP conversation 1 is already deleted.
         0.000031614|Successful termination of playing thread of RTSP conversation thread 1.
         0.000031250|Request termination of RTSP conversation thread 1.
         0.000119530|RTSP conversation thread 1 terminated.
         8.192287293|found RTSP connection thread 1 in a non-running state.
         0.000130988|RTSP connection thread 1 deleted...
         0.000126457|New RTSP connection from 192.168.50.83:44097 to self at 192.168.50.109:5000 on conversation thread 2.
         0.000147915|Successfully created RTSP receiver thread 2.
         0.006193266|    Apple-Challenge: cqWGOicK0+XWQro24xrkuQ.
         0.000049375|    CSeq: 1.
         0.000034791|    Client-Instance: 3FA8DA89333FCA4C.
         0.000034844|    Content-Length: 573.
         0.000032708|    Content-Type: application/sdp.
         0.000032499|    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4.
         0.000074062|RTSP thread 2 received an RTSP Packet of type "ANNOUNCE":
         0.000032187|  Type: "Apple-Challenge", content: "cqWGOicK0+XWQro24xrkuQ"
         0.000031146|  Type: "CSeq", content: "1"
         0.000024739|  Type: "Client-Instance", content: "3FA8DA89333FCA4C"
         0.000026250|  Type: "Content-Length", content: "573"
         0.000024531|  Type: "Content-Type", content: "application/sdp"
         0.000029426|  Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
         0.114617561|Connection 2: ANNOUNCE
         0.000045520|RTSP conversation thread 2 has acquired play lock.
         0.069861639|Play connection from user agent "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4" on RTSP conversation thread 2.
         0.000057916|RTSP thread 2: RTSP Response:
         0.000017656|  Type: "Apple-Response", content: "YlkCdpzuhe2eZ6ENylIZTLwFxv5G9LMjv/dDoF5adnw6QxfBNbLB8LLnHXbdvzTvnmMVJLhUPb3MxLHkgWJTfI9QbZm8s36EDFDokpRZlXPw+Q+Kq8fP9OjDGF0Auw1G/bRa4AMFsN2PUCoDSMwqcn2b2Vbkd/DiBzz6+mRcDNBRqRbsGNxU059hgHtArHXsN0fTaQeL6aH9JdoyXlGb0GsxPo8F4Qp/Ia53inatQ2QWX05gTSwVpTVxk2kJdNKB4Obmd/V8oFnnC9wOK51uTUbeeF7syn1QS5/dCmnwyeQPYlbv5eIGAsXdzgOayGGu1HmmkW3NiXwOu+fUwYctvw"
         0.000026094|  Type: "CSeq", content: "1"
         0.000014531|  Type: "Server", content: "AirTunes/105.1"
         0.015068326|    CSeq: 2.
         0.000025885|    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4.
         0.000021094|    Transport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002.
         0.000018541|    Client-Instance: 3FA8DA89333FCA4C.
         0.000016615|RTSP thread 2 received an RTSP Packet of type "SETUP":
         0.000015364|  Type: "CSeq", content: "2"
         0.000012240|  Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
         0.000014531|  Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002"
         0.000014323|  Type: "Client-Instance", content: "3FA8DA89333FCA4C"
         0.000018229|Connection 2: SETUP
         0.000015312|Note: no Active-Remote information  the SETUP Record.
         0.000013385|Note: no DACP-ID string information in the SETUP Record.
         0.000018385|rtp_setup: cport=6001 tport=6002.
         0.000020625|Set up play connection from 192.168.50.83 to self at 192.168.50.109 on RTSP conversation thread 2.
         0.000118541|listening for audio, control and timing on ports 6003, 6001, 6002.
         0.000036978|RTSP thread 2: RTSP Response:
         0.000015990|  Type: "CSeq", content: "2"
         0.000012604|  Type: "Server", content: "AirTunes/105.1"
         0.000014791|  Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002;server_port=6003"
         0.000014792|  Type: "Session", content: "1"
         0.049231498|    RTP-Info: seq=4022;rtptime=359856.
         0.000050103|    CSeq: 3.
         0.000033750|    Client-Instance: 3FA8DA89333FCA4C.
         0.000033125|    Session: 1.
         0.000031458|    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4.
         0.000035312|    Range: npt=0-.
         0.000030052|RTSP thread 2 received an RTSP Packet of type "RECORD":
         0.000028489|  Type: "RTP-Info", content: "seq=4022;rtptime=359856"
         0.000025989|  Type: "CSeq", content: "3"
         0.000024323|  Type: "Client-Instance", content: "3FA8DA89333FCA4C"
         0.000030833|  Type: "Session", content: "1"
         0.000027760|  Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
         0.000028333|  Type: "Range", content: "npt=0-"
         0.000032343|Connection 2: RECORD
         0.000029375|pbeg
         0.000302809|No latency has (yet) been specified. Setting 88,200 (2 seconds) frames as a default.
         0.000022708|Flush requested up to 359855. It seems as if 0 is special.
         0.000090051|RTSP thread 2: RTSP Response:
         0.000031615|  Type: "CSeq", content: "3"
         0.000029010|  Type: "Server", content: "AirTunes/105.1"
         0.000028177|  Type: "Audio-Latency", content: "11025"
         0.003763500|Output frame bytes is 4.
         0.000434787|Audio receiver -- Server RTP thread starting.
         0.000031927|Control receiver -- Server RTP thread starting.
         0.000102551|Timing receiver -- Server RTP thread starting.
         0.000067499|Output bit depth is 16.
         0.000174894|Timing sender thread starting.
         0.000068906|set_dacp_server_information set IP to "192.168.50.83" and DACP id to "".
         0.000256039|A null or zero-length DACP-ID string was provided for monitoring -- nothing done.
         0.000190362|MH Client IP set to: "192.168.50.83"
         0.000181925|set_dacp_server_information set active-remote id to 0.
         0.000214685|Set initial volume to -18.000000.
         0.000090260|Open Mixer
         0.000080103|Mixer device name is "hw:0".
         0.000667233|Mixer Control name is "PCM".
         0.000163696|Setting volume db to -1550.000000.
         0.000051510|Open Mixer
         0.000031874|Mixer device name is "hw:0".
         0.000355048|Mixer Control name is "PCM".
         0.000483849|Open Mixer
         0.000114583|Mixer device name is "hw:0".
         0.000391818|Mixer Control name is "PCM".
         0.004213444|DACP connect failed with errno 111.
         0.000112395|Unexpected return code 496 from dacp_get_client_volume.
         0.044070199|    RTP-Info: rtptime=359856.
         0.000044948|    CSeq: 4.
         0.000034166|    Client-Instance: 3FA8DA89333FCA4C.
         0.000029896|    Content-Length: 61.
         0.000028489|    Content-Type: application/x-dmap-tagged.
         0.000036250|    Session: 1.
         0.000029895|    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4.
         0.086710207|RTSP thread 2 received an RTSP Packet of type "SET_PARAMETER":
         0.000057343|  Type: "RTP-Info", content: "rtptime=359856"
         0.000030833|  Type: "CSeq", content: "4"
         0.000029374|  Type: "Client-Instance", content: "3FA8DA89333FCA4C"
         0.000030052|  Type: "Content-Length", content: "61"
         0.000028594|  Type: "Content-Type", content: "application/x-dmap-tagged"
         0.000030312|  Type: "Session", content: "1"
         0.000028281|  Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
         0.000043333|Connection 2: SET_PARAMETER
         0.000031718|received metadata tags in SET_PARAMETER request.
         0.000044895|RTSP thread 2: RTSP Response:
         0.000032083|  Type: "CSeq", content: "4"
         0.000030417|  Type: "Server", content: "AirTunes/105.1"
         0.000018645|MH Metadata stream processing start.
         0.000116874|MH Artist name set to: "AirAudio"
         0.000056614|MH Album name set to: "LGE Nexus 5"
         0.000053802|MH Track name set to: "Live Audio"
         0.000053541|Asked to release non-existent track metadata
         0.000034583|Release track metadata after dacp server goes inactive.
         0.000032551|MH Metadata stream processing end.
         0.044476862|    CSeq: 5.
         0.000048958|    Client-Instance: 3FA8DA89333FCA4C.
         0.000035156|    Content-Length: 20.
         0.000031875|    Content-Type: text/parameters.
         0.000032031|    Session: 1.
         0.000030885|    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4.
         0.000038905|RTSP thread 2 received an RTSP Packet of type "SET_PARAMETER":
         0.000033021|  Type: "CSeq", content: "5"
         0.000027500|  Type: "Client-Instance", content: "3FA8DA89333FCA4C"
         0.000029895|  Type: "Content-Length", content: "20"
         0.000027812|  Type: "Content-Type", content: "text/parameters"
         0.000026042|  Type: "Session", content: "1"
         0.000028593|  Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
         0.000042031|Connection 2: SET_PARAMETER
         0.000090676|Open Mixer
         0.000037708|Mixer device name is "hw:0".
         0.000514317|Mixer Control name is "PCM".
         0.000149686|Setting volume db to -1100.000000.
         0.000043906|Open Mixer
         0.000030364|Mixer device name is "hw:0".
         0.000364528|Mixer Control name is "PCM".
         0.000143904|RTSP thread 2: RTSP Response:
         0.000035417|  Type: "CSeq", content: "5"
         0.000030885|  Type: "Server", content: "AirTunes/105.1"
         0.004894270|DACP connect failed with errno 111.
         0.000104894|Unexpected return code 496 from dacp_get_client_volume.
         0.021148157|New latency detected: 131285, sync latency: 120260, minimum latency: 0, maximum latency: 0, fixed offset: 11025.
         0.018571673|    CSeq: 6.
         0.000039792|    Session: 1.
         0.000034999|    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4.
         0.000033021|    Client-Instance: 3FA8DA89333FCA4C.
         0.000033124|RTSP thread 2 received an RTSP Packet of type "OPTIONS":
         0.000032865|  Type: "CSeq", content: "6"
         0.000028020|  Type: "Session", content: "1"
         0.000026094|  Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
         0.000027603|  Type: "Client-Instance", content: "3FA8DA89333FCA4C"
         0.000034219|Connection 2: OPTIONS
         0.000028177|RTSP thread 2: RTSP Response:
         0.000028958|  Type: "CSeq", content: "6"
         0.000024791|  Type: "Server", content: "AirTunes/105.1"
         0.000025052|  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
         0.044267958|syncing to seqno 4022.
         0.000100103|Hammerton Decoder used on encrypted audio.
         0.000188904|pffr
         0.001414151|Output written using MMAP
         0.000555515|PCM handle name = 'hw:0'
         0.000039635|alsa device parameters:
         0.000039896|  access type = MMAP_INTERLEAVED
         0.000073488|  format = 'S16_LE' (Signed 16 bit Little Endian)
         0.000095989|  subformat = 'STD' (Standard)
         0.000076510|  number of channels = 2
         0.000092134|  number of significant bits = 16
         0.000076249|  rate = 44100 frames per second (precisely).
         0.000070937|  precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
         0.000051249|  period_time = 5804 us (>).
         0.000034375|  period_size = 256 frames (precisely).
         0.000057656|  buffer_time = 743038 us (>).
         0.000033333|  buffer_size = 32768 frames (>).
         0.000033385|  periods_per_buffer = 128 (precisely).
         0.000030937|Setting volume db to -1100.000000.
         0.000038854|Open Mixer
         0.000032291|Mixer device name is "hw:0".
         0.000478953|Mixer Control name is "PCM".
         0.098383049|    RTP-Info: rtptime=367248.
         0.000079634|    CSeq: 7.
         0.000034948|    Client-Instance: 3FA8DA89333FCA4C.
         0.000034166|    Content-Length: 64437.
         0.000033021|    Content-Type: image/jpeg.
         0.000032864|    Session: 1.
         0.000033958|    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4.
         0.041439239|RTSP thread 2 received an RTSP Packet of type "SET_PARAMETER":
         0.000088749|  Type: "RTP-Info", content: "rtptime=367248"
         0.000032447|  Type: "CSeq", content: "7"
         0.000025573|  Type: "Client-Instance", content: "3FA8DA89333FCA4C"
         0.000026927|  Type: "Content-Length", content: "64437"
         0.000025104|  Type: "Content-Type", content: "image/jpeg"
         0.000025833|  Type: "Session", content: "1"
         0.000024635|  Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
         0.000048228|Connection 2: SET_PARAMETER
         0.000051406|RTSP thread 2: RTSP Response:
         0.000032552|  Type: "CSeq", content: "7"
         0.000028437|  Type: "Server", content: "AirTunes/105.1"
         0.000229112|MH Picture received, length 64437 bytes.
         0.001333527|Release track metadata after dacp server goes inactive.
         0.635473273|    CSeq: 8.
         0.000090572|    Client-Instance: 3FA8DA89333FCA4C.
         0.000037604|    Content-Length: 20.
         0.000032968|    Content-Type: text/parameters.
         0.000031771|    Session: 1.
         0.000031666|    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4.
         0.000042812|RTSP thread 2 received an RTSP Packet of type "SET_PARAMETER":
         0.000037135|  Type: "CSeq", content: "8"
         0.000027188|  Type: "Client-Instance", content: "3FA8DA89333FCA4C"
         0.000026510|  Type: "Content-Length", content: "20"
         0.000024583|  Type: "Content-Type", content: "text/parameters"
         0.000025729|  Type: "Session", content: "1"
         0.000023958|  Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
         0.000042343|Connection 2: SET_PARAMETER
         0.000044999|Open Mixer
         0.000030261|Mixer device name is "hw:0".
         0.000518796|Mixer Control name is "PCM".
         0.000098853|Setting volume db to -1100.000000.
         0.000042760|Open Mixer
         0.000027864|Mixer device name is "hw:0".
         0.000347913|Mixer Control name is "PCM".
         0.000116666|RTSP thread 2: RTSP Response:
         0.000034322|  Type: "CSeq", content: "8"
         0.000029896|  Type: "Server", content: "AirTunes/105.1"
         0.007137162|DACP connect failed with errno 111.
         0.000097811|Unexpected return code 496 from dacp_get_client_volume.
         2.018054444|prsm
         9.256546422|requesting resend of 1 packets starting at 5218.
         0.230586201|Player has a supplied silent frame.
         1.804769155|requesting resend of 1 packets starting at 5472.
         0.000331559|requesting resend of 1 packets starting at 5473.
         0.233567992|Player has a supplied silent frame.
         0.000212446|Player has a supplied silent frame.
         0.573470457|    CSeq: 9.
         0.000115936|    Session: 1.
         0.000037188|    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4.
         0.000035364|    Client-Instance: 3FA8DA89333FCA4C.
         0.000030051|RTSP thread 2 received an RTSP Packet of type "OPTIONS":
         0.000032292|  Type: "CSeq", content: "9"
         0.000024583|  Type: "Session", content: "1"
         0.000029218|  Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
         0.000028958|  Type: "Client-Instance", content: "3FA8DA89333FCA4C"
         0.000037396|Connection 2: OPTIONS
         0.000029479|RTSP thread 2: RTSP Response:
         0.000024895|  Type: "CSeq", content: "9"
         0.000023594|  Type: "Server", content: "AirTunes/105.1"
         0.000026979|  Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
         1.734967152|requesting resend of 1 packets starting at 5791.
         0.020907690|requesting resend of 1 packets starting at 5794.
         0.005058748|requesting resend of 1 packets starting at 5795.
         0.211405732|Player has a supplied silent frame.
         0.009502188|Player has a supplied silent frame.
         0.000126509|Player has a supplied silent frame.
         0.316921986|requesting resend of 1 packets starting at 5863.
         0.000357444|requesting resend of 1 packets starting at 5864.
         0.236311608|Player has a supplied silent frame.
         0.000145155|Player has a supplied silent frame.
         1.659794894|requesting resend of 1 packets starting at 6101.
         0.239045381|Player has a supplied silent frame.
         0.612281705|Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.5,    12672.0,   157477.0.
         4.169349552|requesting resend of 1 packets starting at 6729.
         0.237687427|Player has a supplied silent frame.
         1.189076243|requesting resend of 1 packets starting at 6908.
         0.096994732|requesting resend of 1 packets starting at 6920.
         0.143053972|Player has a supplied silent frame.
         0.089477729|Player has a supplied silent frame.
         1.045634567|    CSeq: 10.
         0.000091145|    Session: 1.
         0.000045937|    User-Agent: iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4.
         0.000038594|    Client-Instance: 3FA8DA89333FCA4C.
         0.000034218|RTSP thread 2 received an RTSP Packet of type "TEARDOWN":
         0.000036822|  Type: "CSeq", content: "10"
         0.000027917|  Type: "Session", content: "1"
         0.000027864|  Type: "User-Agent", content: "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4"
         0.000032291|  Type: "Client-Instance", content: "3FA8DA89333FCA4C"
         0.000041042|Connection 2: TEARDOWN
         0.000031145|TEARDOWN: synchronously terminating the player thread of RTSP conversation thread 2 (2).
         0.000100155|Open Mixer
         0.000060364|Mixer device name is "hw:0".
         0.000632025|Mixer Control name is "PCM".
         0.000887386|Shut down audio, control and timing threads
         0.000123019|Control RTP thread interrupted. terminating.
         0.000295414|Audio receiver -- Server RTP thread interrupted. terminating.
         0.000118436|Timing thread interrupted. terminating.
         0.000415569|Wait for timer requester to exit.
         0.002702574|rtp_timing_sender thread interrupted. terminating.
         0.000211404|Closed and terminated timer requester thread.
         0.000036927|Timing RTP thread terminated.
         0.000219008|timing thread joined
         0.000049895|audio thread joined
         0.000046927|control thread joined
         0.001086811|Player thread exit on RTSP conversation thread 2.
         0.000253331|pend
         0.000055885|TEARDOWN: successful termination of playing thread of RTSP conversation thread 2.
         0.000036353|RTSP thread 2: RTSP Response:
         0.000026563|  Type: "CSeq", content: "10"
         0.000031926|  Type: "Server", content: "AirTunes/105.1"
         0.000031198|  Type: "Connection", content: "close"
         0.016733256|RTSP conversation thread 2 -- connection closed.
         0.000046041|Synchronously terminate playing thread of RTSP conversation thread 2.
         0.000033333|player thread of RTSP conversation 2 is already deleted.
         0.000031563|Successful termination of playing thread of RTSP conversation thread 2.
         0.000031249|Request termination of RTSP conversation thread 2.
         0.000085728|Unlocking play lock on RTSP conversation thread 2.
         0.000031510|RTSP conversation thread 2 terminated.

It's a real puzzle.

funtax commented 6 years ago

Hey @mikebrady,

thanks for the analysis.

I'm currently under high work but of course interested in solving this as AirAudio is a passion of mine. I'm working under Windows and haven't right now a VM around.. can you tell me if there's a "Docker"-way to run shairport-sync?

Otherwise I will try to setup it on my PI somehow in the next days and check AirAudio through the debugger.

Also, is there an easy way to force the resend-requests from shairport-sync? While implementing the resend-feature years ago, I had to drop the audio-packets inside AirAudio to force the resend-request :-)

mikebrady commented 6 years ago

Thanks @funtax. I'n not familiar with the use of Docker for this, so it's probably more trouble than it's worth right now. The Pi is the easiest route, IMHO. If you give me a few days, I can put some code in Shairport Sync to request resends in some kind of limited pseudo random way. There's no rush, and thanks for your interest.

mikebrady commented 6 years ago

Hello again. I added a feature to the development branch -- an extra diagnostic configuration entry called drop_this_fraction_of_audio_packets. With this set to 0.01 (i.e. 1%), here are two logs with log verbosity set to 1, the first of iTunes and the second of AirAudio:

This is iTunes:

pi@raspberrypi3w:~/shairport-sync $ ./shairport-sync -v
         0.002288363|alsa output device name is "hw:0".
         0.007196753|Lowest dB value is a mute
         0.000080103|Hardware mixer has dB volume from -102.380000 to 4.000000.
         0.000095624|Version: "3.2d39-mbedTLS-Avahi-ALSA-sysconfdir:/etc"
         0.000034895|statistics_requester status is 0.
         0.000047656|daemon status is 0.
         0.000054948|deamon pid file is "/var/run/shairport-sync/shairport-sync.pid".
         0.000031874|rtsp listening port is 5000.
         0.000026458|udp base port is 6001.
         0.000051146|udp port range is 100.
         0.000040416|player name is "Raspberrypi3w".
         0.000033125|backend is "(null)".
         0.000076561|on-start action is "(null)".
         0.000029115|on-stop action is "(null)".
         0.000052291|wait-cmd status is 0.
         0.000039583|on-start returns output is 0.
         0.000026041|mdns backend "(null)".
         0.000053906|stuffing option is "0" (0-basic, 1-soxr).
         0.000029427|resync time is 0.050000 seconds.
         0.000047760|allow a session to be interrupted: 1.
         0.000042499|busy timeout time is 120.
         0.000026823|drift tolerance is 0.010000 seconds.
         0.000058020|password is "(null)".
         0.000028490|ignore_volume_control is 0.
         0.000056874|volume_max_db is not set
         0.000029427|playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000063176|disable_synchronization is 0.
         0.000029896|use_mmap_if_available is 1.
         0.000026458|output_rate is 44100.
         0.000061874|output_format is 3 (0-unknown, 1-S8, 2-U8, 3-S16, 4-S24, 5-S24_3LE, 6-S24_3BE, 7-S32).
         0.000034792|audio backend desired buffer length is 0.150000 seconds.
         0.000030833|audio backend latency offset is 0.000000 seconds.
         0.000030051|audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
         0.000035313|volume range in dB (zero means use the range specified by the mixer): 50.
         0.000030260|zeroconf regtype is "_raop._tcp".
         0.000026197|decoders_supported field is 1.
         0.000026979|use_apple_decoder is 0.
         0.000027917|alsa_use_playback_switch_for_mute is 0.
         0.000027760|no special mdns service interface was requested.
         0.000063124|configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000037552|loudness is 0.
         0.000027916|loudness reference level is -20.000000
         0.000032396|disable resend requests is off.
         0.000026406|diagnostic_drop_packet_fraction is 0.010000. A value of 0.0 means no packets will be dropped deliberately.
         0.820315181|avahi: service '605B2B5EEB50@Raspberrypi3w' successfully added.
        21.377084696|requesting resend of 1 packets starting at 58418.
         0.001814253|Audio Port -- Retransmitted Audio Data Packet 58418 received.
         0.380991078|requesting resend of 1 packets starting at 58466.
         0.002768410|Audio Port -- Retransmitted Audio Data Packet 58466 received.
         0.005337188|requesting resend of 1 packets starting at 58467.
         0.001969303|Audio Port -- Retransmitted Audio Data Packet 58467 received.
         0.979693835|requesting resend of 1 packets starting at 58590.
         0.002079824|Audio Port -- Retransmitted Audio Data Packet 58590 received.
         0.358006666|requesting resend of 1 packets starting at 58635.
         0.003943087|Audio Port -- Retransmitted Audio Data Packet 58635 received.
         0.905613099|requesting resend of 1 packets starting at 58749.
         0.001758316|Audio Port -- Retransmitted Audio Data Packet 58749 received.
         0.191960003|requesting resend of 1 packets starting at 58773.
         0.003238458|Audio Port -- Retransmitted Audio Data Packet 58773 received.
         0.496781876|requesting resend of 1 packets starting at 58836.
         0.002505653|Audio Port -- Retransmitted Audio Data Packet 58836 received.
         2.448727378|requesting resend of 1 packets starting at 59143.
         0.001797587|Audio Port -- Retransmitted Audio Data Packet 59143 received.
         1.379208430|requesting resend of 1 packets starting at 59316.
         0.001888419|Audio Port -- Retransmitted Audio Data Packet 59316 received.
         0.445111286|requesting resend of 1 packets starting at 59372.
         0.001919304|Audio Port -- Retransmitted Audio Data Packet 59372 received.
         0.541025246|requesting resend of 1 packets starting at 59440.
         0.002035762|Audio Port -- Retransmitted Audio Data Packet 59440 received.
         0.509090662|requesting resend of 1 packets starting at 59504.
         0.001709879|Audio Port -- Retransmitted Audio Data Packet 59504 received.
         0.069700935|requesting resend of 1 packets starting at 59513.
         0.003393144|Audio Port -- Retransmitted Audio Data Packet 59513 received.
         0.172368997|requesting resend of 1 packets starting at 59535.
         0.001920606|Audio Port -- Retransmitted Audio Data Packet 59535 received.
         0.540843634|requesting resend of 1 packets starting at 59603.
         0.002084042|Audio Port -- Retransmitted Audio Data Packet 59603 received.
         0.524741759|requesting resend of 1 packets starting at 59669.
         0.001862899|Audio Port -- Retransmitted Audio Data Packet 59669 received.
         1.283300093|requesting resend of 1 packets starting at 59830.
         0.001816962|Audio Port -- Retransmitted Audio Data Packet 59830 received.
         1.131772352|requesting resend of 1 packets starting at 59972.
         0.001900137|Audio Port -- Retransmitted Audio Data Packet 59972 received.
         1.737805090|requesting resend of 1 packets starting at 60190.
         0.001869825|Audio Port -- Retransmitted Audio Data Packet 60190 received.
         0.549359332|requesting resend of 1 packets starting at 60259.
         0.002045397|Audio Port -- Retransmitted Audio Data Packet 60259 received.
         1.139119155|requesting resend of 1 packets starting at 60402.
         0.001866023|Audio Port -- Retransmitted Audio Data Packet 60402 received.
         0.078448871|requesting resend of 1 packets starting at 60412.
         0.001835503|Audio Port -- Retransmitted Audio Data Packet 60412 received.
         0.237611590|requesting resend of 1 packets starting at 60442.
         0.001821232|Audio Port -- Retransmitted Audio Data Packet 60442 received.
         0.484385225|requesting resend of 1 packets starting at 60503.
         0.001877534|Audio Port -- Retransmitted Audio Data Packet 60503 received.

and now, from AirAudio:

pi@raspberrypi3w:~/shairport-sync $ ./shairport-sync -v
         0.002258208|alsa output device name is "hw:0".
         0.006997431|Lowest dB value is a mute
         0.000079895|Hardware mixer has dB volume from -102.380000 to 4.000000.
         0.000092187|Version: "3.2d39-mbedTLS-Avahi-ALSA-sysconfdir:/etc"
         0.000035312|statistics_requester status is 0.
         0.000030052|daemon status is 0.
         0.000055156|deamon pid file is "/var/run/shairport-sync/shairport-sync.pid".
         0.000086718|rtsp listening port is 5000.
         0.000067395|udp base port is 6001.
         0.000065832|udp port range is 100.
         0.000064219|player name is "Raspberrypi3w".
         0.000063541|backend is "(null)".
         0.000047760|on-start action is "(null)".
         0.000063280|on-stop action is "(null)".
         0.000103541|wait-cmd status is 0.
         0.000063905|on-start returns output is 0.
         0.000063489|mdns backend "(null)".
         0.000063385|stuffing option is "0" (0-basic, 1-soxr).
         0.000064479|resync time is 0.050000 seconds.
         0.000066926|allow a session to be interrupted: 1.
         0.000065052|busy timeout time is 120.
         0.000063332|drift tolerance is 0.010000 seconds.
         0.000052604|password is "(null)".
         0.000028177|ignore_volume_control is 0.
         0.000028645|volume_max_db is not set
         0.000025990|playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000031301|disable_synchronization is 0.
         0.000027709|use_mmap_if_available is 1.
         0.000027655|output_rate is 44100.
         0.000026875|output_format is 3 (0-unknown, 1-S8, 2-U8, 3-S16, 4-S24, 5-S24_3LE, 6-S24_3BE, 7-S32).
         0.000031198|audio backend desired buffer length is 0.150000 seconds.
         0.000030729|audio backend latency offset is 0.000000 seconds.
         0.000030572|audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
         0.000032917|volume range in dB (zero means use the range specified by the mixer): 50.
         0.000030833|zeroconf regtype is "_raop._tcp".
         0.000027135|decoders_supported field is 1.
         0.000027604|use_apple_decoder is 0.
         0.000026822|alsa_use_playback_switch_for_mute is 0.
         0.000027761|no special mdns service interface was requested.
         0.000087134|configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000074374|loudness is 0.
         0.000065781|loudness reference level is -20.000000
         0.000071093|disable resend requests is off.
         0.000063489|diagnostic_drop_packet_fraction is 0.010000. A value of 0.0 means no packets will be dropped deliberately.
         0.989202175|avahi: service '605B2B5EEB50@Raspberrypi3w' successfully added.
        11.000249067|A null or zero-length DACP-ID string was provided for monitoring -- nothing done.
         3.125850137|Player has a supplied silent frame.
         0.000534058|Player has a supplied silent frame.
         0.024064921|Player has a supplied silent frame.
         0.000120936|Player has a supplied silent frame.
         0.023969246|Player: packets out of sequence: expected: 4, got: 5387, with ab_read: 5388 and ab_write: 5742.
         0.000189946|Player has a supplied silent frame.
         0.000131249|Player has a supplied silent frame.
         0.000144686|Player has a supplied silent frame.
         0.000097134|Player has a supplied silent frame.
         0.000099635|Player has a supplied silent frame.
         0.000131040|Player has a supplied silent frame.
         0.051719600|requesting resend of 1 packets starting at 5426.
         0.000142186|Player has a supplied silent frame.
         0.259936683|Player has a supplied silent frame.
         0.143231416|requesting resend of 1 packets starting at 5474.
         0.011963060|requesting resend of 1 packets starting at 5475.
         0.236027177|Player has a supplied silent frame.
         0.000148905|Player has a supplied silent frame.
         0.727232803|requesting resend of 1 packets starting at 5598.
         0.242971953|Player has a supplied silent frame.
         0.117806767|requesting resend of 1 packets starting at 5643.
         0.242674248|Player has a supplied silent frame.
         0.699891299|requesting resend of 1 packets starting at 5760.
         0.197123441|requesting resend of 1 packets starting at 5784.
         0.042305994|Player has a supplied silent frame.
         0.189265289|Player has a supplied silent frame.
         0.267571922|requesting resend of 1 packets starting at 5848.
         0.239680006|Player has a supplied silent frame.
         0.993895618|requesting resend of 1 packets starting at 6002.
         0.002933357|requesting resend of 1 packets starting at 6003.
         0.011729052|requesting resend of 1 packets starting at 6004.
         0.009761832|requesting resend of 1 packets starting at 6005.
         0.001664151|requesting resend of 1 packets starting at 6006.
         0.011000049|requesting resend of 1 packets starting at 6007.
         0.045113153|requesting resend of 1 packets starting at 6013.
         0.012012956|requesting resend of 1 packets starting at 6014.
         0.009281264|requesting resend of 1 packets starting at 6015.
         0.011683219|requesting resend of 1 packets starting at 6016.
         0.000226092|requesting resend of 1 packets starting at 6017.
         0.005924317|requesting resend of 1 packets starting at 6018.
         0.010941976|requesting resend of 1 packets starting at 6019.
         0.010936665|requesting resend of 1 packets starting at 6020.
         0.010931924|requesting resend of 1 packets starting at 6021.
         0.000224894|requesting resend of 1 packets starting at 6022.
         0.010948018|requesting resend of 1 packets starting at 6023.
         0.010942081|requesting resend of 1 packets starting at 6024.
         0.011019007|requesting resend of 1 packets starting at 6025.
         0.000282497|requesting resend of 1 packets starting at 6026.
         0.005868328|requesting resend of 1 packets starting at 6027.
         0.012042487|requesting resend of 1 packets starting at 6028.
         0.010951872|requesting resend of 1 packets starting at 6029.
         0.010934373|requesting resend of 1 packets starting at 6030.
         0.000215154|requesting resend of 1 packets starting at 6031.
         0.010942602|requesting resend of 1 packets starting at 6032.
         0.000217654|requesting resend of 1 packets starting at 6033.
         0.000068593|Player has a supplied silent frame.
         0.000146092|requesting resend of 1 packets starting at 6034.
         0.000133072|Player has a supplied silent frame.
         0.000139425|requesting resend of 1 packets starting at 6035.
         0.000097656|Player has a supplied silent frame.
         0.000138123|requesting resend of 1 packets starting at 6036.
         0.000083281|Player has a supplied silent frame.
         0.000133488|requesting resend of 1 packets starting at 6037.
         0.000111718|Player has a supplied silent frame.
         0.000144946|requesting resend of 1 packets starting at 6038.
         0.000121249|Player has a supplied silent frame.
         0.053715622|requesting resend of 1 packets starting at 6039.
         0.010169797|requesting resend of 1 packets starting at 6040.
         0.001862482|requesting resend of 1 packets starting at 6041.
         0.015097873|requesting resend of 1 packets starting at 6042.
         0.000424163|requesting resend of 1 packets starting at 6043.
         0.000755513|requesting resend of 1 packets starting at 6044.
         0.000154634|Player has a supplied silent frame.
         0.000178384|Player has a supplied silent frame.
         0.000245154|Player has a supplied silent frame.
         0.000255414|Player has a supplied silent frame.
         0.000576192|Player has a supplied silent frame.
         0.000186821|Player has a supplied silent frame.
         0.000541505|Player has a supplied silent frame.
         0.000237758|Player has a supplied silent frame.
         0.000465256|Player has a supplied silent frame.
         0.000385205|Player has a supplied silent frame.
         0.000141821|Player has a supplied silent frame.
         0.000297914|Player has a supplied silent frame.
         0.000245987|Player has a supplied silent frame.
         0.000160363|Player has a supplied silent frame.
         0.000164634|Player has a supplied silent frame.
         0.000174165|Player has a supplied silent frame.
         0.000278591|Player has a supplied silent frame.
         0.000143957|Player has a supplied silent frame.
         0.000160051|Player has a supplied silent frame.
         0.000138071|Player has a supplied silent frame.
         0.000136197|Player has a supplied silent frame.
         0.000121301|Player has a supplied silent frame.
         0.000134582|Player has a supplied silent frame.
         0.000120988|Player has a supplied silent frame.
         0.000097395|Player has a supplied silent frame.
         0.000121092|Player has a supplied silent frame.
         0.000095989|Player has a supplied silent frame.
         0.000119686|Player has a supplied silent frame.
         0.000096770|Player has a supplied silent frame.
         0.000119791|Player has a supplied silent frame.
         0.000168071|Player has a supplied silent frame.
         0.000211613|Player has a supplied silent frame.
         1.236073047|requesting resend of 1 packets starting at 6197.

Let's hope this is useful...

funtax commented 6 years ago

Many thanks @mikebrady for the logs. I will try to setup shairport-sync in the next time and check what's going on on AirAudio's side :)

mikebrady commented 6 years ago

Thanks @funtax. If you use the development branch (recommended!), the messages have changed slightly and you need to set the debug verbosity to 2, rather than 1 above. From the command line, that would correspond to: $shairport-sync -vv rather than $shairport-sync -v.

funtax commented 6 years ago

Hey @mikebrady, I just flashed Raspbian, cloned shairport-sync & switched to the development-branch. To avoid try & error as I'm not familar with configure etc., can you please tell me how to activate the drop_this_fraction_of_audio_packets?

./configure --with-alsa --with-avahi --with-ssl=openssl --with-systemd --with-metadata

I didn't even find this setting in your commit https://github.com/mikebrady/shairport-sync/commit/70c72821c9373ceb6d17b4e524b2abf53f0d073d

Cheers from Germany, have a good night!

mikebrady commented 6 years ago

Hi Martin. Greetings from Dublin.

If you have done the full installation using the ./configure... arguments shown above, and have performed the $ sudo make install step, a sample configuration file will be installed at /usr/local/etc/shairport-sync.conf. At the end of the configuration file is a diagnostics section. You should set it up as follows (you'll need superuser privileges):

// Diagnostic settings. These are for diagnostic and debugging only. Normally you should leave them commented out
diagnostics =
{
//      disable_resend_requests = "yes"; // set this to yes to stop Shairport Sync from requesting the retransmission of missing packets. Default is "no".
//      statistics = "no"; // set to "yes" to print statistics in the log
      log_verbosity = 2; // "0" means no debug verbosity, "3" is most verbose.
//      log_show_time_since_startup = "no"; // set this to yes if you want the time since startup in the debug message -- seconds down to nanoseconds
      log_show_time_since_last_message = "yes"; // set this to yes if you want the time since the last debug message in the debug message -- seconds down to nanoseconds
      drop_this_fraction_of_audio_packets = 0.01; // use this to simulate a noisy network where this fraction of UDP packets are lost in transmission. E.g. a value of 0.001 would mean an average of 1% of packets are lost. Audio packets only.

Make sure you enable the shairport-sync service and reboot. Alternatively, if you want to run it from the command line, make sure the service is disabled and shairport-sync is not already running, and just enter:

$ shairport-sync -vv

The setting is asking for 1% of all UDP packets to be dropped, including audio, control and timing (in spite of what the comment says). It's quite a lot, so you should see lots of messages in the log. This is what I'm getting just now from an iTunes source:

         …
         0.133270610|Dropping audio packet 20860 to simulate a bad connection.
         0.013514893|Dropping audio packet 20861 to simulate a bad connection.
         0.322266247|New latency detected: 99577, sync latency: 88552, minimum latency: 0, maximum latency: 0, fixed offset: 11025.
         0.003444035|PCM handle name = 'hw:1'
         0.000188175|alsa device parameters:
         0.000109843|  access type = MMAP_INTERLEAVED
         0.000724838|  format = 'S16_LE' (Signed 16 bit Little Endian)
         0.000171249|  subformat = 'STD' (Standard)
         0.000232863|  number of channels = 2
         0.000163696|  number of significant bits = 16
         0.000087395|  rate = 44100 frames per second (precisely).
         0.000095364|  precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
         0.000100833|  period_time = 5804 us (>).
         0.000075989|  period_size = 256 frames (precisely).
         0.000102655|  buffer_time = 5944308 us (>).
         0.000073072|  buffer_size = 262144 frames (>).
         0.000075937|  periods_per_buffer = 1024 (precisely).
         0.521132117|Dropping audio packet 20979 to simulate a bad connection.
         0.343682899|Dropping audio packet 21022 to simulate a bad connection.
         0.007331453|requesting resend of 1 packets starting at 20860.
         0.001892849|Audio Receiver -- Retransmitted Audio Data Packet 20860 received.
         0.000159322|requesting resend of 1 packets starting at 20861.
         0.054041550|requesting resend of 1 packets starting at 21022.
         0.001765455|Audio Receiver -- Retransmitted Audio Data Packet 21022 received.
         0.054024050|requesting resend of 1 packets starting at 20812.
         0.001925350|Audio Receiver -- Retransmitted Audio Data Packet 20812 received.
         0.093657225|requesting resend of 1 packets starting at 20979.
         0.002105400|Audio Receiver -- Retransmitted Audio Data Packet 20979 received.
         0.047995245|requesting resend of 1 packets starting at 20861.
         0.001987953|Audio Receiver -- Retransmitted Audio Data Packet 20861 received.
         0.387941557|Dropping audio packet 21127 to simulate a bad connection.
         0.190715987|Dropping audio packet 21151 to simulate a bad connection.
         0.055886327|requesting resend of 1 packets starting at 21127.
         0.002356336|Audio Receiver -- Retransmitted Audio Data Packet 21127 received.
         0.098423020|requesting resend of 1 packets starting at 21151.
         0.001980193|Audio Receiver -- Retransmitted Audio Data Packet 21151 received.
         0.221429441|Dropping audio packet 21210 to simulate a bad connection.
         0.247215537|requesting resend of 1 packets starting at 21210.
         0.004785483|Audio Receiver -- Retransmitted Audio Data Packet 21210 received.
         0.720925420|Dropping audio packet 21515 to simulate a bad connection.
         0.246948403|requesting resend of 1 packets starting at 21515.
         0.002012276|Audio Receiver -- Retransmitted Audio Data Packet 21515 received.
         0.013890046|Dropping audio packet 21684 to simulate a bad connection.
         0.246270960|requesting resend of 1 packets starting at 21684.
         0.002014202|Audio Receiver -- Retransmitted Audio Data Packet 21684 received.
         0.182560581|Dropping audio packet 21738 to simulate a bad connection.
         0.247546053|requesting resend of 1 packets starting at 21738.
         0.003027215|Audio Receiver -- Retransmitted Audio Data Packet 21738 received.
         0.260426055|Dropping audio packet 21802 to simulate a bad connection.
         0.177532442|requesting resend of 1 packets starting at 21802.
         0.002016338|Audio Receiver -- Retransmitted Audio Data Packet 21802 received.
         0.245031594|Dropping audio packet 21864 to simulate a bad connection.
         0.072843014|Dropping audio packet 21873 to simulate a bad connection.
         0.174935589|Dropping audio packet 21895 to simulate a bad connection.
         0.008021811|requesting resend of 1 packets starting at 21864.
         0.001953109|Audio Receiver -- Retransmitted Audio Data Packet 21864 received.
         0.062096330|requesting resend of 1 packets starting at 21873.
         0.002199253|Audio Receiver -- Retransmitted Audio Data Packet 21873 received.
         0.173329194|requesting resend of 1 packets starting at 21895.
         0.002063369|Audio Receiver -- Retransmitted Audio Data Packet 21895 received.
         0.140352009|Dropping audio packet 21957 to simulate a bad connection.
         0.246835276|requesting resend of 1 packets starting at 21957.
         0.004474756|Audio Receiver -- Retransmitted Audio Data Packet 21957 received.
         0.267682975|Dropping audio packet 22022 to simulate a bad connection.
         0.247740634|requesting resend of 1 packets starting at 22022.
         0.002397272|Audio Receiver -- Retransmitted Audio Data Packet 22022 received.
         0.910626609|Dropping audio packet 22181 to simulate a bad connection.
         0.137407240|requesting resend of 1 packets starting at 22181.
         0.005504852|Audio Receiver -- Retransmitted Audio Data Packet 22181 received.
         0.873315132|Dropping audio packet 22322 to simulate a bad connection.
         0.243569831|requesting resend of 1 packets starting at 22322.
         …
         0.005824902|Audio Receiver -- Retransmitted Audio Data Packet 22322 received.
          0.809719569|Connection 2: TEARDOWN
         0.001213376|Shut down audio, control and timing threads
         0.015751332|timing thread joined
         0.000534267|audio thread joined
         0.000267237|control thread joined
         0.001586342|Player thread exit on RTSP conversation thread 2.
         0.000513173|pend
         1.817076093|RTSP conversation thread 2 terminated.

Any problems, please let us know!

funtax commented 6 years ago

Got it, thank you @mikebrady .

mikebrady commented 6 years ago

Thanks. If Shairport Sync needs updating, please let us know!

mikebrady commented 6 years ago

By heaven, I think I've found it. @funtax -- AirAudio is more selective than iTunes about where the request comes from. Shairport Sync has been sending the requests via the audio connection, and iTunes, etc. always responds, but AirAudio does not.

When I send via the control port, AirAudio seems to work. I'm still checking, but I'll report back when I know more.

mikebrady commented 6 years ago

Yes indeed, this seems to resolve the problem!

mikebrady commented 6 years ago

It's just as you advised earlier, thanks.

funtax commented 6 years ago

Oh @mikebrady, yes, the control-port is used to handle the resend-requests (see https://nto.github.io/AirPlay.html#audio-rtpstreams).. hehe and now github just updated with your answer :)

mikebrady commented 6 years ago

Yikes, I think I will go into a corner and cry... :)

funtax commented 6 years ago

Hehe, you can imagine how I cried while implementing this into AirAudio 👍 Happy coding, at least I have now a running instance of shairport-sync on my PI :D

mikebrady commented 6 years ago

Haha yes. Well, many thanks for your help, and your patience. I'll push out an updated development branch in a few minutes and another release candidate, probably tomorrow.

mikebrady commented 6 years ago

Development version 3.2d41 is up with this fix, making Shairport Sync work properly with AirAudio. @kowalcj0, if you'd be kind enough to update to it (see UPDATING.md) and let us know if it's working for you, that would be great. Thanks to @kowalcj0 and @funtax for identifying this!

funtax commented 6 years ago

You're most welcome!

kowalcj0 commented 6 years ago

It's the best example of cooperation I've seen so far. Thank you guys for this fantastic work!!! I'll update it later today and test it!

kowalcj0 commented 6 years ago

@mikebrady & @funtax I just compiled shairport-sync off the master branch and it works flawlessly with AirAudio. Some packets are being retransmitted but there are no silent frames logged and thus there are no popping noises. Once again I'd like to say thank you to both of you!

PS. your software drives this network player https://github.com/kowalcj0/diy-nap :)

mikebrady commented 6 years ago

Thanks again for checking. That’s an impressive piece of work!