Lags for first 15 seconds; stops playing within first 1-2 minutes (snapfifo)

zaneclaes commented 4 years ago

This is a re-opening of this issue.

I'm having the exact same problems — both the 15 second start lag, and the eventual cut-out of the audio feed. There also tends to be short brown-outs before the eventual total black-out about 2 minutes in. The main difference from the other thread is that my output is a pipe to a snapfifo, so definitely not speaker related.

general = {
  name = "Cabin";
  output_backend = "pipe";
}

pipe = {
  name = "/tmp/snapfifo-airplay";
  audio_backend_latency_offset = 0;
  audio_backend_buffer_desired_length = 44100;
};

... however, I should mention that shairport-sync is running in a docker container on Kubernetes, with the /tmp directory mounted from the host. I suppose this could theoretically cause some lag due to filesystem mounting, but that seems odd to me... it's a Ubuntu (18.04) machine with 16 GB of RAM and plenty of CPU headroom as well as a SSD.

I've also tried fiddling with lots of settings, including:

audio_backend_latency_offset (from 0 to -4410)
audio_backend_buffer_desired_length (from 1 to 88200)
drift_tolerance_in_seconds (0.010)
resync_threshold_in_seconds (0 and 0.010)
interpolation (basic and soxr)

I don't think it's ultimately a resyncing error because the logs seem to indicate no such need:

Successful Startup
sync error in milliseconds, total packets, missing packets, late packets, too late packets, resend requests, min buffer occupancy, max buffer occupancy
       0.0,        1003,      0,      0,      0,      0,   75,   93
       0.0,        2006,      0,      0,      0,      0,   74,   94
       0.0,        3009,      0,      0,      0,      0,   86,   93
       0.0,        4012,      0,      0,      0,      0,   86,   94
       0.0,        5015,      0,      0,      0,      0,   87,   93
       0.0,        6018,      0,      0,      0,      0,   87,   93
       0.0,        7021,      0,      0,      0,      0,   86,   93

mikebrady commented 4 years ago

Thanks for the report. Could you let us know what version of ShairportbSync you are using, please. Please refer to REPORTING ISSUES.md for more details.

The audio_backend_latency_offset and audio_backend_buffer_desired_length should have an effect, but the other settings relate to active syncing which is not done on a pipe output.

Some work has been done very recently on audio_backend_latency_offset and audio_backend_buffer_desired_length – it's in the development branch – but by the description, it is unlikely to be the problem.

mikebrady commented 4 years ago

I had a quick look at this, running Shairport Sync on a four-core Ubuntu 20.04 system with 64GB RAM and an SSD, as close as I could get to the system you report, but not in a docker container and not part of a snap setup. Long story short, it runs as expected.

So, if you wanted to experiment with Shairport Sync running independently, not part of a snap system, let me suggest you build the development version from here. Another user reported strange delays with a snap system – see #1005.

zaneclaes commented 4 years ago

Thanks for the reply; I apologize for missing the reporting issues file (friendly suggestion: turn it in to a Github issue template, which guarantees users cannot miss it).

I noticed that I was on version 3.1.7 so I just re-built my image off the master branch (3.3.6). However, for some reason this seemed to cause shairport-sync to stop outputting any logs at all to the console. It seemed the config file might have changed so I tried adding the diagnostics section instead of general, but still no dice. Nothing in /var/log or syslogs either. However, I can still test via Airplay and confirm that the bug still exists. FWIW, the log_verbosity=2 from 3.1.7 is at the end of this comment.

At this point I decided to try switching from an alpine to a debian Docker image. That went even worse: when I try to connect to the Airplay audio stream, suddenly logs do appear from shairport-sync... referencing ALSA for some reason, even though I did not compile it with alsa, and have no reference to alsa in my config (the rest of the shairport logs are still missing).

ALSA lib conf.c:4693:(_snd_config_evaluate) function snd_func_refer returned error: No such file or directory
ALSA lib conf.c:5181:(snd_config_expand) Evaluate error: No such file or directory
ALSA lib pcm.c:2642:(snd_pcm_open_noupdate) Unknown PCM default

The 3.1.7 logs:

pipe init
Pipename is "/tmp/snapfifo-airplay"
The processor is running little-endian.
Version: "3.1.7-OpenSSL-Avahi-ALSA-pipe-soxr-metadata-sysconfdir:/usr/local/etc"
statistics_requester status is 1.
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 "Cabin".
backend is "pipe".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
on-start returns output is 0.
mdns backend "avahi".
userSuppliedLatency is 0.
AirPlayLatency is -1.
iTunesLatency is -1.
forkedDaapdLatency is -1.
stuffing option is "1" (0-basic, 1-soxr).
resync time is 0.050000 seconds.
allow a session to be interrupted: 1.
busy timeout time is 60.
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 1.000000 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 "/usr/local/etc/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
metadata enabled is 0.
metadata pipename is "/tmp/shairport-sync-metadata".
metadata socket address is "(null)" port 0.
metadata socket packet size is "500".
get-coverart is 1.
loudness is 0.
loudness reference level is -20.000000
Successful Startup
avahi: avahi_register.
avahi: register_service.
avahi: service '0668597D3ED4@Cabin' group is not yet committed.
avahi: request to add "_raop._tcp" service without metadata
avahi: service '0668597D3ED4@Cabin' group is registering.
avahi: service '0668597D3ED4@Cabin' successfully added.
New RTSP connection from [fe80::b3:d261:e76e:46e2]:60736 to self at [fe80::610e:206:cf12:3bd3]:5000 on conversation thread 0.
Play connection from user agent "AirPlay/420.45" on RTSP conversation thread 0.
Active-Remote string seen: "174835608".
DACP-ID string seen: "AF8F71B50A5C861E".
User-Agent is AirPlay; selecting the AirPlay latency of -1 frames.
rtp_setup: cport=55235 tport=51475.
Set up play connection from fe80::b3:d261:e76e:46e2 to self at fe80::610e:206:cf12:3bd3 on RTSP conversation thread 0.
listening for audio, control and timing on ports 6001, 6002, 6003.
Output frame bytes is 4.
Audio receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Output bit depth is 16.
Dithering will be enabled because the output volume is being altered in software
Timing receiver -- Server RTP thread starting.
Timing sender thread starting.
sync error in milliseconds, total packets, missing packets, late packets, too late packets, resend requests, min buffer occupancy, max buffer occupancy
Set initial volume to -18.000000.
Using negotiated latency of 77175 frames and a static latency correction of 0
syncing to seqno 38675.
Hammerton Decoder used on encrypted audio.
       0.0,        1003,      0,      0,      0,      0,   88,   94
       0.0,        2006,      0,      0,      0,      0,   89,   93
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.3,    12992.7,    33619.0.
       0.0,        3009,      0,      0,      0,      0,   88,   94

zaneclaes commented 4 years ago

In attempts to remove Docker from the equation, I've now installed it directly on the Ubuntu server, following the instructions from the README. The bugs persist, namely:

No logs appear in the console
The audio cuts out

It seems the logs were likely moved to journalctl (so they're inaccessible from the docker container), and I can't figure out how to get the back in to stdout (I don't see it in the config file). In any case, when the audio cuts out there appears to be nothing sent to the fifo:

ls -la /tmp/snapfifo-airplay                                                                                                              
prw-rw-rw- 1 root root 0 May 24 10:05 /tmp/snapfifo-airplay

While shairport-sync is running and cut-out, if I simply cat ~/piano2.wav > /tmp/snapfifo-airplay I can hear the audio file being played. I can pause/play the Airplay source and snapcast can detect the Airplay state changes:

2020-05-24 16-23-32 [Info] (onStateChanged) onStateChanged (airplay): 1
2020-05-24 16-23-41 [Info] (onStateChanged) onStateChanged (airplay): 2

... but still no audio.

Combine that fact with the following logs, and it seems like shairport-sync is piping data, but somehow that data is not translating into working audio:

May 24 10:03:41 big-box shairport-sync[18385]:          0.000183102         0.000183102 "shairport.c:1636" Started!
May 24 10:03:41 big-box shairport-sync[18385]:          0.000325973         0.000142871 "shairport.c:1660" software version: "3.3.6-OpenSSL-Avahi-ALSA-pipe-soxr-metadata-sysconfdir:/etc"
May 24 10:03:41 big-box shairport-sync[18385]:          0.000338417         0.000012444 "shairport.c:1666" log verbosity is 2.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000345909         0.000007492 "audio_pipe.c:94" pipe init
May 24 10:03:41 big-box shairport-sync[18385]:          0.000360016         0.000014107 "audio_pipe.c:128" Pipename is "/tmp/snapfifo-airplay"
May 24 10:03:41 big-box shairport-sync[18385]:          0.000366815         0.000006799 "shairport.c:1681" The processor is running little-endian.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000372461         0.000005646 "shairport.c:1714" disable resend requests is off.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000377900         0.000005439 "shairport.c:1717" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000385100         0.000007200 "shairport.c:1718" statistics_requester status is 1.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000390487         0.000005387 "shairport.c:1723" rtsp listening port is 5000.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000395761         0.000005274 "shairport.c:1724" udp base port is 6001.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000401179         0.000005418 "shairport.c:1725" udp port range is 10.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000406448         0.000005269 "shairport.c:1726" player name is "Cabin".
May 24 10:03:41 big-box shairport-sync[18385]:          0.000411727         0.000005279 "shairport.c:1727" backend is "pipe".
May 24 10:03:41 big-box shairport-sync[18385]:          0.000417077         0.000005350 "shairport.c:1728" run_this_before_play_begins action is "(null)".
May 24 10:03:41 big-box shairport-sync[18385]:          0.000422341         0.000005264 "shairport.c:1729" run_this_after_play_ends action is "(null)".
May 24 10:03:41 big-box shairport-sync[18385]:          0.000427462         0.000005121 "shairport.c:1730" wait-cmd status is 0.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000433099         0.000005637 "shairport.c:1731" run_this_before_play_begins may return output is 0.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000438780         0.000005681 "shairport.c:1732" run_this_if_an_unfixable_error_is_detected action is "(null)".
May 24 10:03:41 big-box shairport-sync[18385]:          0.000444045         0.000005265 "shairport.c:1733" run_this_before_entering_active_state action is  "(null)".
May 24 10:03:41 big-box shairport-sync[18385]:          0.000449050         0.000005005 "shairport.c:1734" run_this_after_exiting_active_state action is  "(null)".
May 24 10:03:41 big-box shairport-sync[18385]:          0.000454303         0.000005253 "shairport.c:1735" active_state_timeout is  10.000000 seconds.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000461133         0.000006830 "shairport.c:1736" mdns backend "(null)".
May 24 10:03:41 big-box shairport-sync[18385]:          0.000466583         0.000005450 "shairport.c:1737" userSuppliedLatency is 0.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000472227         0.000005644 "shairport.c:1740" interpolation setting is "soxr".
May 24 10:03:41 big-box shairport-sync[18385]:          0.000477557         0.000005330 "shairport.c:1741" interpolation soxr_delay_threshold is 30.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000482821         0.000005264 "shairport.c:1742" resync time is 0.050000 seconds.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000488883         0.000006062 "shairport.c:1743" allow a session to be interrupted: 1.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000494112         0.000005229 "shairport.c:1744" busy timeout time is 60.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000499255         0.000005143 "shairport.c:1745" drift tolerance is 0.001995 seconds.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000504872         0.000005617 "shairport.c:1746" password is "(null)".
May 24 10:03:41 big-box shairport-sync[18385]:          0.000509978         0.000005106 "shairport.c:1747" ignore_volume_control is 0.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000515560         0.000005582 "shairport.c:1751" volume_max_db is not set
May 24 10:03:41 big-box shairport-sync[18385]:          0.000520815         0.000005255 "shairport.c:1753" volume range in dB (zero means use the range specified by the mixer): 0.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000526634         0.000005819 "shairport.c:1756" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000532417         0.000005783 "shairport.c:1758" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
May 24 10:03:41 big-box shairport-sync[18385]:          0.000537918         0.000005501 "shairport.c:1759" disable_synchronization is 0.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000548398         0.000010480 "shairport.c:1760" use_mmap_if_available is 1.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000553876         0.000005478 "shairport.c:1762" output_format automatic selection is enabled.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000559272         0.000005396 "shairport.c:1766" output_rate automatic selection is enabled.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000564549         0.000005277 "shairport.c:1770" audio backend desired buffer length is 1.000000 seconds.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000570189         0.000005640 "shairport.c:1772" audio_backend_buffer_interpolation_threshold_in_seconds is 0.000000 seconds.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000575749         0.000005560 "shairport.c:1773" audio backend latency offset is 0.000000 seconds.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000581364         0.000005615 "shairport.c:1775" audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000586846         0.000005482 "shairport.c:1776" zeroconf regtype is "_raop._tcp".
May 24 10:03:41 big-box shairport-sync[18385]:          0.000592159         0.000005313 "shairport.c:1777" decoders_supported field is 1.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000597282         0.000005123 "shairport.c:1778" use_apple_decoder is 0.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000602294         0.000005012 "shairport.c:1779" alsa_use_hardware_mute is 0.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000607637         0.000005343 "shairport.c:1783" no special mdns service interface was requested.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000625206         0.000017569 "shairport.c:1787" configuration file name "/mnt/k8s-nfs/home-audio-pvc-9bda300c-1374-44ae-b4cb-345bef315dab/config/shairport-sync.conf" resolves to "/mnt/k8s-nfs/home-audio-pvc-9bda300c-1374-44ae-b4cb-345bef315dab/config/shairport-sync.conf".
May 24 10:03:41 big-box shairport-sync[18385]:          0.000632078         0.000006872 "shairport.c:1793" metadata enabled is 1.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000637666         0.000005588 "shairport.c:1794" metadata pipename is "/tmp/shairport-sync-metadata".
May 24 10:03:41 big-box shairport-sync[18385]:          0.000643132         0.000005466 "shairport.c:1796" metadata socket address is "(null)" port 0.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000648601         0.000005469 "shairport.c:1797" metadata socket packet size is "500".
May 24 10:03:41 big-box shairport-sync[18385]:          0.000653944         0.000005343 "shairport.c:1798" get-coverart is 1.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000659221         0.000005277 "shairport.c:1816" loudness is 0.
May 24 10:03:41 big-box shairport-sync[18385]:          0.000664564         0.000005343 "shairport.c:1817" loudness reference level is -20.000000
May 24 10:03:41 big-box shairport-sync[18385]:          0.005297966         0.004633402 "mdns_avahi.c:205" avahi: service '0668597D3ED4@Cabin' group is not yet committed.
May 24 10:03:41 big-box shairport-sync[18385]:          0.006196290         0.000898324 "mdns_avahi.c:240" avahi: request to add "_raop._tcp" service with metadata
May 24 10:03:41 big-box shairport-sync[18385]:          0.007003383         0.000807093 "mdns_avahi.c:371" avahi_dacp_monitor_start Avahi DACP monitor successfully started
May 24 10:03:41 big-box shairport-sync[18385]:          0.007094268         0.000090885 "mdns_avahi.c:209" avahi: service '0668597D3ED4@Cabin' group is registering.
May 24 10:03:42 big-box shairport-sync[18385]:          0.879461594         0.872367326 "mdns_avahi.c:176" avahi: service '0668597D3ED4@Cabin' successfully added.
May 24 10:03:42 big-box shairport-sync[18385]:          1.501135656         0.621674062 "shairport.c:192" soxr_delay_index: 1.
May 24 10:03:45 big-box shairport-sync[18385]:          3.897618100         2.396482444 "rtsp.c:2707" Connection 1: new connection from [fe80::b3:d261:e76e:46e2]:63291 to self at [fe80::610e:206:cf12:3bd3]:5000.
May 24 10:03:45 big-box shairport-sync[18385]:          4.258736861         0.361118761 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "ANNOUNCE":
May 24 10:03:45 big-box shairport-sync[18385]:          4.258799444         0.000062583 "rtsp.c:464"   Type: "Content-Length", content: "663"
May 24 10:03:45 big-box shairport-sync[18385]:          4.258842925         0.000043481 "rtsp.c:464"   Type: "Content-Type", content: "application/sdp"
May 24 10:03:45 big-box shairport-sync[18385]:          4.258866909         0.000023984 "rtsp.c:464"   Type: "CSeq", content: "3"
May 24 10:03:45 big-box shairport-sync[18385]:          4.258887909         0.000021000 "rtsp.c:464"   Type: "DACP-ID", content: "256F087FFC3180B"
May 24 10:03:45 big-box shairport-sync[18385]:          4.258908870         0.000020961 "rtsp.c:464"   Type: "Active-Remote", content: "4042320104"
May 24 10:03:45 big-box shairport-sync[18385]:          4.258929152         0.000020282 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
May 24 10:03:45 big-box shairport-sync[18385]:          4.264557257         0.005628105 "rtsp.c:1936" Play connection from user agent "AirPlay/420.45" on RTSP conversation thread 1.
May 24 10:03:45 big-box shairport-sync[18385]:          4.264607598         0.000050341 "rtsp.c:1945" AirPlay version 420 detected.
May 24 10:03:45 big-box shairport-sync[18385]:          4.264668376         0.000060778 "rtsp.c:2416" Connection 1: RTSP Response:
May 24 10:03:45 big-box shairport-sync[18385]:          4.264694040         0.000025664 "rtsp.c:464"   Type: "CSeq", content: "3"
May 24 10:03:45 big-box shairport-sync[18385]:          4.264717539         0.000023499 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
May 24 10:03:45 big-box shairport-sync[18385]:          4.265958686         0.001241147 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "SETUP":
May 24 10:03:45 big-box shairport-sync[18385]:          4.266012191         0.000053505 "rtsp.c:464"   Type: "Transport", content: "RTP/AVP/UDP;unicast;mode=record;timing_port=62162;control_port=64074"
May 24 10:03:45 big-box shairport-sync[18385]:          4.266055166         0.000042975 "rtsp.c:464"   Type: "CSeq", content: "4"
May 24 10:03:45 big-box shairport-sync[18385]:          4.266079342         0.000024176 "rtsp.c:464"   Type: "DACP-ID", content: "256F087FFC3180B"
May 24 10:03:45 big-box shairport-sync[18385]:          4.266100890         0.000021548 "rtsp.c:464"   Type: "Active-Remote", content: "4042320104"
May 24 10:03:45 big-box shairport-sync[18385]:          4.266121207         0.000020317 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
May 24 10:03:45 big-box shairport-sync[18385]:          4.266147937         0.000026730 "rtsp.c:921" Connection 1: SETUP -- Active-Remote string seen: "4042320104".
May 24 10:03:45 big-box shairport-sync[18385]:          4.266191315         0.000043378 "rtsp.c:936" Connection 1: SETUP -- DACP-ID string seen: "256F087FFC3180B".
May 24 10:03:45 big-box shairport-sync[18385]:          4.266230178         0.000038863 "rtp.c:981" Connection 1: SETUP -- Connection from fe80::b3:d261:e76e:46e2 to self at fe80::610e:206:cf12:3bd3.
May 24 10:03:45 big-box shairport-sync[18385]:          4.266417037         0.000186859 "rtsp.c:1001" Connection 1: SETUP DACP-ID "256F087FFC3180B" from fe80::b3:d261:e76e:46e2 to fe80::610e:206:cf12:3bd3 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
May 24 10:03:45 big-box shairport-sync[18385]:          4.266453374         0.000036337 "rtsp.c:2416" Connection 1: RTSP Response:
May 24 10:03:45 big-box shairport-sync[18385]:          4.266476578         0.000023204 "rtsp.c:464"   Type: "CSeq", content: "4"
May 24 10:03:45 big-box shairport-sync[18385]:          4.266499975         0.000023397 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
May 24 10:03:45 big-box shairport-sync[18385]:          4.266521995         0.000022020 "rtsp.c:464"   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002;server_port=6003"
May 24 10:03:45 big-box shairport-sync[18385]:          4.266543062         0.000021067 "rtsp.c:464"   Type: "Session", content: "1"
May 24 10:03:45 big-box shairport-sync[18385]:          4.267941944         0.001398882 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "RECORD":
May 24 10:03:45 big-box shairport-sync[18385]:          4.267984419         0.000042475 "rtsp.c:464"   Type: "CSeq", content: "5"
May 24 10:03:45 big-box shairport-sync[18385]:          4.268007326         0.000022907 "rtsp.c:464"   Type: "DACP-ID", content: "256F087FFC3180B"
May 24 10:03:45 big-box shairport-sync[18385]:          4.268028373         0.000021047 "rtsp.c:464"   Type: "Active-Remote", content: "4042320104"
May 24 10:03:45 big-box shairport-sync[18385]:          4.268048745         0.000020372 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
May 24 10:03:45 big-box shairport-sync[18385]:          4.268072764         0.000024019 "rtsp.c:806" Connection 1: RECORD
May 24 10:03:45 big-box shairport-sync[18385]:          4.268098401         0.000025637 "activity_monitor.c:64" abeg
May 24 10:03:45 big-box shairport-sync[18385]:          4.268336509         0.000238108 "player.c:3042" pbeg
May 24 10:03:45 big-box shairport-sync[18385]:          4.268391208         0.000054699 "rtsp.c:2416" Connection 1: RTSP Response:
May 24 10:03:45 big-box shairport-sync[18385]:          4.268416391         0.000025183 "rtsp.c:464"   Type: "CSeq", content: "5"
May 24 10:03:45 big-box shairport-sync[18385]:          4.268437695         0.000021304 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
May 24 10:03:45 big-box shairport-sync[18385]:          4.268459367         0.000021672 "rtsp.c:464"   Type: "Audio-Latency", content: "11025"
May 24 10:03:45 big-box shairport-sync[18385]:          4.270505393         0.002046026 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
May 24 10:03:45 big-box shairport-sync[18385]:          4.270558880         0.000053487 "rtsp.c:464"   Type: "Content-Length", content: "20"
May 24 10:03:45 big-box shairport-sync[18385]:          4.270585011         0.000026131 "rtsp.c:464"   Type: "Content-Type", content: "text/parameters"
May 24 10:03:45 big-box shairport-sync[18385]:          4.270606336         0.000021325 "rtsp.c:464"   Type: "CSeq", content: "6"
May 24 10:03:45 big-box shairport-sync[18385]:          4.270626245         0.000019909 "rtsp.c:464"   Type: "DACP-ID", content: "256F087FFC3180B"
May 24 10:03:45 big-box shairport-sync[18385]:          4.270646255         0.000020010 "rtsp.c:464"   Type: "Active-Remote", content: "4042320104"
May 24 10:03:45 big-box shairport-sync[18385]:          4.270666027         0.000019772 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
May 24 10:03:45 big-box shairport-sync[18385]:          4.270735705         0.000069678 "loudness.c:47" Volume: -43.3 dB - Loudness gain @10Hz: 11.7 dB
May 24 10:03:45 big-box shairport-sync[18385]:          4.270795751         0.000060046 "player.c:2958" player_volume_without_notification: volume mode is 0, airplay volume is -20.000000, software_attenuation: -4333.500000, hardware_attenuation: 0.000000, muting is disabled.
May 24 10:03:45 big-box shairport-sync[18385]:          4.270830433         0.000034682 "rtsp.c:2416" Connection 1: RTSP Response:
May 24 10:03:45 big-box shairport-sync[18385]:          4.270851634         0.000021201 "rtsp.c:464"   Type: "CSeq", content: "6"
May 24 10:03:45 big-box shairport-sync[18385]:          4.270871827         0.000020193 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
May 24 10:03:45 big-box shairport-sync[18385]:          4.271320665         0.000448838 "player.c:1927" sync error in milliseconds, total packets, missing packets, late packets, too late packets, resend requests, min buffer occupancy, max buffer occupancy, source nominal frames per second, source actual frames per second, source clock drift in ppm, source clock drift sample count
May 24 10:03:45 big-box shairport-sync[18385]:          4.272583657         0.001262992 "player.c:1951" Set initial volume to -20.000000.
May 24 10:03:45 big-box shairport-sync[18385]:          4.272666973         0.000083316 "loudness.c:47" Volume: -43.3 dB - Loudness gain @10Hz: 11.7 dB
May 24 10:03:45 big-box shairport-sync[18385]:          4.272724178         0.000057205 "player.c:2958" player_volume_without_notification: volume mode is 0, airplay volume is -20.000000, software_attenuation: -4333.500000, hardware_attenuation: 0.000000, muting is disabled.
May 24 10:03:45 big-box shairport-sync[18385]:          4.272755953         0.000031775 "player.c:1954" Play begin
May 24 10:03:45 big-box shairport-sync[18385]:          4.278063951         0.005307998 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
May 24 10:03:45 big-box shairport-sync[18385]:          4.278126893         0.000062942 "rtsp.c:464"   Type: "RTP-Info", content: "rtptime=3062677521"
May 24 10:03:45 big-box shairport-sync[18385]:          4.278150538         0.000023645 "rtsp.c:464"   Type: "Content-Length", content: "0"
May 24 10:03:45 big-box shairport-sync[18385]:          4.278164195         0.000013657 "rtsp.c:464"   Type: "Content-Type", content: "image/none"
May 24 10:03:45 big-box shairport-sync[18385]:          4.278175848         0.000011653 "rtsp.c:464"   Type: "CSeq", content: "7"
May 24 10:03:45 big-box shairport-sync[18385]:          4.278186852         0.000011004 "rtsp.c:464"   Type: "DACP-ID", content: "256F087FFC3180B"
May 24 10:03:45 big-box shairport-sync[18385]:          4.278198219         0.000011367 "rtsp.c:464"   Type: "Active-Remote", content: "4042320104"
May 24 10:03:45 big-box shairport-sync[18385]:          4.278208849         0.000010630 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
May 24 10:03:45 big-box shairport-sync[18385]:          4.278237216         0.000028367 "rtsp.c:2416" Connection 1: RTSP Response:
May 24 10:03:45 big-box shairport-sync[18385]:          4.278257433         0.000020217 "rtsp.c:464"   Type: "CSeq", content: "7"
May 24 10:03:45 big-box shairport-sync[18385]:          4.278277249         0.000019816 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
May 24 10:03:45 big-box shairport-sync[18385]:          4.279033490         0.000756241 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
May 24 10:03:45 big-box shairport-sync[18385]:          4.279076339         0.000042849 "rtsp.c:464"   Type: "RTP-Info", content: "rtptime=3062677521"
May 24 10:03:45 big-box shairport-sync[18385]:          4.279092361         0.000016022 "rtsp.c:464"   Type: "Content-Length", content: "43"
May 24 10:03:45 big-box shairport-sync[18385]:          4.279104228         0.000011867 "rtsp.c:464"   Type: "Content-Type", content: "text/parameters"
May 24 10:03:45 big-box shairport-sync[18385]:          4.279115782         0.000011554 "rtsp.c:464"   Type: "CSeq", content: "8"
May 24 10:03:45 big-box shairport-sync[18385]:          4.279126717         0.000010935 "rtsp.c:464"   Type: "DACP-ID", content: "256F087FFC3180B"
May 24 10:03:45 big-box shairport-sync[18385]:          4.279138381         0.000011664 "rtsp.c:464"   Type: "Active-Remote", content: "4042320104"
May 24 10:03:45 big-box shairport-sync[18385]:          4.279149256         0.000010875 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
May 24 10:03:45 big-box shairport-sync[18385]:          4.279183236         0.000033980 "rtsp.c:2416" Connection 1: RTSP Response:
May 24 10:03:45 big-box shairport-sync[18385]:          4.279206238         0.000023002 "rtsp.c:464"   Type: "CSeq", content: "8"
May 24 10:03:45 big-box shairport-sync[18385]:          4.279225371         0.000019133 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
May 24 10:03:45 big-box shairport-sync[18385]:          4.280007939         0.000782568 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
May 24 10:03:45 big-box shairport-sync[18385]:          4.280055485         0.000047546 "rtsp.c:464"   Type: "RTP-Info", content: "rtptime=3062677521"
May 24 10:03:45 big-box shairport-sync[18385]:          4.280081360         0.000025875 "rtsp.c:464"   Type: "Content-Length", content: "196"
May 24 10:03:45 big-box shairport-sync[18385]:          4.280096140         0.000014780 "rtsp.c:464"   Type: "Content-Type", content: "application/x-dmap-tagged"
May 24 10:03:45 big-box shairport-sync[18385]:          4.280107536         0.000011396 "rtsp.c:464"   Type: "CSeq", content: "9"
May 24 10:03:45 big-box shairport-sync[18385]:          4.280118916         0.000011380 "rtsp.c:464"   Type: "DACP-ID", content: "256F087FFC3180B"
May 24 10:03:45 big-box shairport-sync[18385]:          4.280136708         0.000017792 "rtsp.c:464"   Type: "Active-Remote", content: "4042320104"
May 24 10:03:45 big-box shairport-sync[18385]:          4.280153838         0.000017130 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
May 24 10:03:45 big-box shairport-sync[18385]:          4.280190778         0.000036940 "rtsp.c:2416" Connection 1: RTSP Response:
May 24 10:03:45 big-box shairport-sync[18385]:          4.280211748         0.000020970 "rtsp.c:464"   Type: "CSeq", content: "9"
May 24 10:03:45 big-box shairport-sync[18385]:          4.280230659         0.000018911 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
May 24 10:03:45 big-box shairport-sync[18385]:          4.309183810         0.028953151 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "FLUSH":
May 24 10:03:45 big-box shairport-sync[18385]:          4.309243983         0.000060173 "rtsp.c:464"   Type: "RTP-Info", content: "seq=50859;rtptime=3062772541"
May 24 10:03:45 big-box shairport-sync[18385]:          4.309261551         0.000017568 "rtsp.c:464"   Type: "CSeq", content: "10"
May 24 10:03:45 big-box shairport-sync[18385]:          4.309274739         0.000013188 "rtsp.c:464"   Type: "DACP-ID", content: "256F087FFC3180B"
May 24 10:03:45 big-box shairport-sync[18385]:          4.309287072         0.000012333 "rtsp.c:464"   Type: "Active-Remote", content: "4042320104"
May 24 10:03:45 big-box shairport-sync[18385]:          4.309299755         0.000012683 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
May 24 10:03:45 big-box shairport-sync[18385]:          4.309334538         0.000034783 "rtsp.c:2416" Connection 1: RTSP Response:
May 24 10:03:45 big-box shairport-sync[18385]:          4.309356380         0.000021842 "rtsp.c:464"   Type: "CSeq", content: "10"
May 24 10:03:45 big-box shairport-sync[18385]:          4.309374487         0.000018107 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
May 24 10:03:45 big-box shairport-sync[18385]:          4.338510992         0.029136505 "player.c:264" Hammerton Decoder used on encrypted audio.
May 24 10:03:45 big-box shairport-sync[18385]:          4.339369740         0.000858748 "player.c:1016" pffr
May 24 10:03:45 big-box shairport-sync[18385]:          4.342275487         0.002905747 "player.c:1278" prsm
May 24 10:03:54 big-box shairport-sync[18385]:         13.306422504         8.964147017 "player.c:2726"       0.00,        1003,      0,      0,      0,      0,  120,  125,   44100.06,   44105.54,      0.00,     0
May 24 10:04:02 big-box shairport-sync[18385]:         21.311359265         8.004936761 "player.c:2726"       0.00,        2006,      0,      0,      0,      0,  119,  125,   44099.99,   44113.98,      0.00,     0
May 24 10:04:05 big-box shairport-sync[18385]:         24.288905498         2.977546233 "rtp.c:142" Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.7,    13008.5,    36586.0.
May 24 10:04:10 big-box shairport-sync[18385]:         29.320980016         5.032074518 "player.c:2726"       0.00,        3009,      0,      0,      0,      0,  119,  125,   44100.02,   44083.63,      0.00,     0
May 24 10:04:18 big-box shairport-sync[18385]:         37.325553834         8.004573818 "player.c:2726"       0.00,        4012,      0,      0,      0,      0,  120,  125,   44100.02,   44081.67,      0.00,     0
May 24 10:04:25 big-box shairport-sync[18385]:         44.238892741         6.913338907 "rtp.c:142" Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.4,    13010.8,    35901.0.
May 24 10:04:26 big-box shairport-sync[18385]:         45.329743549         1.090850808 "player.c:2726"       0.00,        5015,      0,      0,      0,      0,  120,  125,   44100.00,   44090.24,      0.00,     0
May 24 10:04:34 big-box shairport-sync[18385]:         53.339920263         8.010176714 "player.c:2726"       0.00,        6018,      0,      0,      0,      0,  120,  125,   44100.00,   44095.66,      0.00,     0
May 24 10:04:42 big-box shairport-sync[18385]:         61.344670636         8.004750373 "player.c:2726"       0.00,        7021,      0,      0,      0,      0,  120,  125,   44100.00,   44092.63,      0.00,     0
May 24 10:04:45 big-box shairport-sync[18385]:         64.218773083         2.874102447 "rtp.c:142" Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.6,    13005.7,    32101.0.

zaneclaes commented 4 years ago

Well I finally found the -u flag in the v3.3 release notes to fix logging. This breaking change does not appear to mentioned or documented anywhere else, and the examples were never updated (the main README still says that logs are "output to the console").

mikebrady commented 4 years ago

Thanks for the updates and thanks indeed for the suggestion about the issue template.

The mystery of the logs is that Shairport Sync now has an extra command-line option -u to redirect the logs to STDERR (this seemed necessary due to moving away from using libdaemon for logging). So something like $ shairport-sync -vu –statistics... There have been lots of changes since 3.1.7, so if you would be kind enough to try 3.3.6 again, or even better, the development branch, that would be great.

Is it possible that Shairport Sync does not have permission to write to /tmp? (There was no problem for me on Ubuntu 20.04 – I didn't have to do anything.)

I was testing it like this, running from the build directory (BTW, this is running in a VM):

$ ./shairport-sync -vvu –statistics -o pipe -- /tmp/sps

and in another window, I was running the following:

$ cat /tmp/sps | aplay -f cd

Here is what I got for running shairport-sync just now:

mike@ubuntu:~/shairport-sync$ ./shairport-sync -vvu --statistics -o pipe -- /tmp/sps
         0.000021436 "shairport.c:448" Looking for configuration file at full path "/etc/shairport-sync.conf"
         0.000373261 "shairport.c:1656" Started!
         0.000022865 "shairport.c:1680" software version: "3.3.7d6-OpenSSL-Avahi-ALSA-stdout-pipe-soxr-sysconfdir:/etc"
         0.000003445 "shairport.c:1686" log verbosity is 2.
         0.000062851 "audio_pipe.c:96" pipe init
         0.000051201 "audio_pipe.c:130" Pipename is "/tmp/sps"
         0.000023919 "shairport.c:1701" The processor is running little-endian.
         0.000005735 "shairport.c:1734" disable resend requests is off.
         0.000003127 "shairport.c:1735" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000004900 "shairport.c:1739" statistics_requester status is 1.
         0.000002627 "shairport.c:1744" rtsp listening port is 5000.
         0.000002407 "shairport.c:1745" udp base port is 6001.
         0.000002261 "shairport.c:1746" udp port range is 10.
         0.000002283 "shairport.c:1747" player name is "Ubuntu".
         0.000002418 "shairport.c:1748" backend is "pipe".
         0.000002402 "shairport.c:1749" run_this_before_play_begins action is "(null)".
         0.000002398 "shairport.c:1750" run_this_after_play_ends action is "(null)".
         0.000002763 "shairport.c:1751" wait-cmd status is 0.
         0.000003666 "shairport.c:1752" run_this_before_play_begins may return output is 0.
         0.000003548 "shairport.c:1753" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000002422 "shairport.c:1754" run_this_before_entering_active_state action is  "(null)".
         0.000003452 "shairport.c:1755" run_this_after_exiting_active_state action is  "(null)".
         0.000010192 "shairport.c:1756" active_state_timeout is  10.000000 seconds.
         0.000030483 "shairport.c:1757" mdns backend "(null)".
         0.000006895 "shairport.c:1758" userSuppliedLatency is 0.
         0.000002957 "shairport.c:1759" interpolation setting is "auto".
         0.000002380 "shairport.c:1762" interpolation soxr_delay_threshold is 30.
         0.000002199 "shairport.c:1763" resync time is 0.050000 seconds.
         0.000002441 "shairport.c:1764" allow a session to be interrupted: 0.
         0.000002629 "shairport.c:1765" busy timeout time is 120.
         0.000002589 "shairport.c:1766" drift tolerance is 0.001995 seconds.
         0.000002286 "shairport.c:1767" password is "(null)".
         0.000001796 "shairport.c:1768" ignore_volume_control is 0.
         0.000002662 "shairport.c:1772" volume_max_db is not set
         0.000002240 "shairport.c:1773" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000002148 "shairport.c:1775" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000001775 "shairport.c:1779" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000002270 "shairport.c:1781" disable_synchronization is 0.
         0.000001841 "shairport.c:1782" use_mmap_if_available is 1.
         0.000001505 "shairport.c:1783" output_format automatic selection is enabled.
         0.000002130 "shairport.c:1787" output_rate automatic selection is enabled.
         0.000001595 "shairport.c:1791" audio backend desired buffer length is 1.000000 seconds.
         0.000002265 "shairport.c:1793" audio_backend_buffer_interpolation_threshold_in_seconds is 0.000000 seconds.
         0.000002611 "shairport.c:1795" audio backend latency offset is 0.000000 seconds.
         0.000001669 "shairport.c:1797" audio backend silence lead-in time is "auto".
         0.000001458 "shairport.c:1801" zeroconf regtype is "_raop._tcp".
         0.000001603 "shairport.c:1802" decoders_supported field is 1.
         0.000001489 "shairport.c:1803" use_apple_decoder is 0.
         0.000001386 "shairport.c:1804" alsa_use_hardware_mute is 0.
         0.000001467 "shairport.c:1808" no special mdns service interface was requested.
         0.000005550 "shairport.c:1811" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000015237 "shairport.c:1841" loudness is 0.
         0.000003831 "shairport.c:1842" loudness reference level is -20.000000
         0.002424710 "mdns_avahi.c:207" avahi: service '3D945423F8E9@Ubuntu' group is not yet committed.
         0.000511503 "mdns_avahi.c:249" avahi: request to add "_raop._tcp" service without metadata
         0.000258645 "mdns_avahi.c:373" avahi_dacp_monitor_start Avahi DACP monitor successfully started
         0.000080314 "mdns_avahi.c:211" avahi: service '3D945423F8E9@Ubuntu' group is registering.
         0.928537739 "mdns_avahi.c:178" avahi: service '3D945423F8E9@Ubuntu' successfully added.
         0.002884358 "rtsp.c:2699" Connection 1: new connection from 192.168.50.12:51566 to self at 192.168.50.61:5000.
         0.000747763 "rtsp.c:2314" Connection 1: terminated.
         0.564671633 "shairport.c:192" soxr_delay_index: 0.
         0.000040707 "shairport.c:198" "soxr" interpolation has been chosen.
        46.096533669 "rtsp.c:2699" Connection 2: new connection from 192.168.50.12:51581 to self at 192.168.50.61:5000.
         0.000147712 "rtsp.c:2379" Connection 2: Received an RTSP Packet of type "ANNOUNCE":
         0.000019024 "rtsp.c:466"   Type: "CSeq", content: "1"
         0.000003595 "rtsp.c:466"   Type: "Content-Type", content: "application/sdp"
         0.000002560 "rtsp.c:466"   Type: "Content-Length", content: "572"
         0.000002340 "rtsp.c:466"   Type: "User-Agent", content: "Music/1.0.4 (Macintosh; OS X 10.15.4) AppleWebKit/609.1.20.111.8"
         0.000002589 "rtsp.c:466"   Type: "Client-Instance", content: "F18FE780B35CFD8D"
         0.000002418 "rtsp.c:466"   Type: "DACP-ID", content: "F18FE780B35CFD8D"
         0.000002397 "rtsp.c:466"   Type: "Active-Remote", content: "1844140950"
         0.003293384 "rtsp.c:1941" Play connection from user agent "Music/1.0.4 (Macintosh; OS X 10.15.4) AppleWebKit/609.1.20.111.8" on RTSP conversation thread 2.
         0.000024262 "rtsp.c:2424" Connection 2: RTSP Response:
         0.000004138 "rtsp.c:466"   Type: "CSeq", content: "1"
         0.000002935 "rtsp.c:466"   Type: "Server", content: "AirTunes/105.1"
         0.002014660 "rtsp.c:2379" Connection 2: Received an RTSP Packet of type "SETUP":
         0.000054415 "rtsp.c:466"   Type: "CSeq", content: "2"
         0.000012409 "rtsp.c:466"   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002"
         0.000008178 "rtsp.c:466"   Type: "User-Agent", content: "Music/1.0.4 (Macintosh; OS X 10.15.4) AppleWebKit/609.1.20.111.8"
         0.000007201 "rtsp.c:466"   Type: "Client-Instance", content: "F18FE780B35CFD8D"
         0.000006327 "rtsp.c:466"   Type: "DACP-ID", content: "F18FE780B35CFD8D"
         0.000006383 "rtsp.c:466"   Type: "Active-Remote", content: "1844140950"
         0.000009265 "rtsp.c:925" Connection 2: SETUP -- Active-Remote string seen: "1844140950".
         0.000007690 "rtsp.c:941" Connection 2: SETUP -- DACP-ID string seen: "F18FE780B35CFD8D".
         0.000009916 "rtp.c:934" Connection 2: SETUP -- Connection from 192.168.50.12 to self at 192.168.50.61.
         0.000066453 "rtsp.c:1002" Connection 2: SETUP DACP-ID "F18FE780B35CFD8D" from 192.168.50.12 to 192.168.50.61 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
         0.000029730 "rtsp.c:2424" Connection 2: RTSP Response:
         0.000008097 "rtsp.c:466"   Type: "CSeq", content: "2"
         0.000006134 "rtsp.c:466"   Type: "Server", content: "AirTunes/105.1"
         0.000005902 "rtsp.c:466"   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002;server_port=6003"
         0.000006898 "rtsp.c:466"   Type: "Session", content: "1"
         0.000347530 "rtsp.c:2379" Connection 2: Received an RTSP Packet of type "RECORD":
         0.000032041 "rtsp.c:466"   Type: "CSeq", content: "3"
         0.000009979 "rtsp.c:466"   Type: "Session", content: "1"
         0.000007334 "rtsp.c:466"   Type: "Range", content: "npt=0-"
         0.000006512 "rtsp.c:466"   Type: "RTP-Info", content: "seq=55140;rtptime=305903530"
         0.000006594 "rtsp.c:466"   Type: "User-Agent", content: "Music/1.0.4 (Macintosh; OS X 10.15.4) AppleWebKit/609.1.20.111.8"
         0.000010588 "rtsp.c:466"   Type: "Client-Instance", content: "F18FE780B35CFD8D"
         0.000007176 "rtsp.c:466"   Type: "DACP-ID", content: "F18FE780B35CFD8D"
         0.000006953 "rtsp.c:466"   Type: "Active-Remote", content: "1844140950"
         0.000011211 "rtsp.c:810" Connection 2: RECORD
         0.000088464 "rtsp.c:2424" Connection 2: RTSP Response:
         0.000022085 "rtsp.c:466"   Type: "CSeq", content: "3"
         0.000005824 "rtsp.c:466"   Type: "Server", content: "AirTunes/105.1"
         0.000004149 "rtsp.c:466"   Type: "Audio-Latency", content: "11025"
         0.000215216 "rtsp.c:2379" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
         0.000030911 "rtsp.c:466"   Type: "CSeq", content: "4"
         0.000008900 "rtsp.c:466"   Type: "Session", content: "1"
         0.000006601 "rtsp.c:466"   Type: "Content-Type", content: "text/parameters"
         0.000006169 "rtsp.c:466"   Type: "Content-Length", content: "19"
         0.000005892 "rtsp.c:466"   Type: "User-Agent", content: "Music/1.0.4 (Macintosh; OS X 10.15.4) AppleWebKit/609.1.20.111.8"
         0.000006892 "rtsp.c:466"   Type: "Client-Instance", content: "F18FE780B35CFD8D"
         0.000006709 "rtsp.c:466"   Type: "DACP-ID", content: "F18FE780B35CFD8D"
         0.000006385 "rtsp.c:466"   Type: "Active-Remote", content: "1844140950"
         0.000012545 "loudness.c:47" Volume: -4.2 dB - Loudness gain @10Hz: 0.0 dB
         0.000008650 "player.c:2964" player_volume_without_notification: volume mode is 0, airplay volume is -2.613331, software_attenuation: -419.439638, hardware_attenuation: 0.000000, muting is disabled.
         0.000010265 "rtsp.c:2424" Connection 2: RTSP Response:
         0.000006892 "rtsp.c:466"   Type: "CSeq", content: "4"
         0.000008400 "rtsp.c:466"   Type: "Server", content: "AirTunes/105.1"
         0.000406255 "rtsp.c:2379" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
         0.000031319 "rtsp.c:466"   Type: "CSeq", content: "5"
         0.000009836 "rtsp.c:466"   Type: "Session", content: "1"
         0.000007111 "rtsp.c:466"   Type: "Content-Type", content: "text/parameters"
         0.000006509 "rtsp.c:466"   Type: "Content-Length", content: "19"
         0.000006323 "rtsp.c:466"   Type: "User-Agent", content: "Music/1.0.4 (Macintosh; OS X 10.15.4) AppleWebKit/609.1.20.111.8"
         0.000022541 "rtsp.c:466"   Type: "Client-Instance", content: "F18FE780B35CFD8D"
         0.000011318 "rtsp.c:466"   Type: "DACP-ID", content: "F18FE780B35CFD8D"
         0.000007624 "rtsp.c:466"   Type: "Active-Remote", content: "1844140950"
         0.000012970 "loudness.c:47" Volume: -4.2 dB - Loudness gain @10Hz: 0.0 dB
         0.000009491 "player.c:2964" player_volume_without_notification: volume mode is 0, airplay volume is -2.613331, software_attenuation: -419.439638, hardware_attenuation: 0.000000, muting is disabled.
         0.000011851 "rtsp.c:2424" Connection 2: RTSP Response:
         0.000007779 "rtsp.c:466"   Type: "CSeq", content: "5"
         0.000004135 "rtsp.c:466"   Type: "Server", content: "AirTunes/105.1"
         0.000002522 "player.c:1930" total packets, missing packets, late packets, too late packets, resend requests, min buffer occupancy, max buffer occupancy, source nominal frames per second, source actual frames per second, source clock drift in ppm, source clock drift sample count
         0.000758492 "player.c:1964" Set initial volume to -2.613331.
         0.000041055 "loudness.c:47" Volume: -4.2 dB - Loudness gain @10Hz: 0.0 dB
         0.000006113 "player.c:2964" player_volume_without_notification: volume mode is 0, airplay volume is -2.613331, software_attenuation: -419.439638, hardware_attenuation: 0.000000, muting is disabled.
         0.000005573 "player.c:1967" Play begin
         0.007825658 "player.c:253" Hammerton Decoder used on encrypted audio.
         1.029793305 "player.c:639" request resend of 16 packets starting at seqno 55241.
         8.218796183 "player.c:2716"         1003,      0,     16,      0,      1,  157,  158,   44096.51,   44102.61,      0.00,     0
         8.012999819 "player.c:2716"         2006,      0,     16,      0,      1,  157,  157,   44096.51,   44056.34,      0.00,     0
         2.829308609 "rtp.c:127" Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8036.4,    18178.4,   912946.1.
         5.190518935 "player.c:2716"         3009,      0,     16,      0,      1,  156,  157,   44096.51,   44055.65,      0.00,     0
         8.010890745 "player.c:2716"         4012,      0,     16,      0,      1,  157,  157,   44096.51,   44060.96,      0.00,     0
         6.770989243 "rtp.c:127" Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7985.9,      477.2,     9309.1.
         1.236587319 "player.c:2716"         5015,      0,     16,      0,      1,  157,  157,   44096.51,   44067.31,      0.00,     0
         8.006115475 "player.c:2716"         6018,      0,     16,      0,      1,  157,  157,   44096.51,   44072.74,      0.00,     0
         8.005166473 "player.c:2716"         7021,      0,     16,      0,      1,  157,  158,   44096.51,   44077.30,      0.00,     0
         2.715089245 "rtp.c:127" Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.1,      474.2,    12257.0.
         5.290086943 "player.c:2716"         8024,      0,     16,      0,      1,  157,  157,   44096.51,   44080.14,      0.00,     0
         8.005881765 "player.c:2716"         9027,      0,     16,      0,      1,  157,  158,   44096.51,   44082.97,      0.00,     0
         6.664651861 "rtp.c:127" Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.7,      488.8,    12295.0.
         1.340114465 "player.c:2716"        10030,      0,     16,      0,      1,  157,  158,   44096.51,   44085.28,      0.00,     0
         3.138706918 "rtsp.c:2379" Connection 2: Received an RTSP Packet of type "FLUSH":
         0.000048439 "rtsp.c:466"   Type: "CSeq", content: "8"
         0.000007453 "rtsp.c:466"   Type: "Session", content: "1"
         0.000003202 "rtsp.c:466"   Type: "RTP-Info", content: "seq=186;rtptime=309628394"
         0.000002674 "rtsp.c:466"   Type: "User-Agent", content: "Music/1.0.4 (Macintosh; OS X 10.15.4) AppleWebKit/609.1.20.111.8"
         0.000002946 "rtsp.c:466"   Type: "Client-Instance", content: "F18FE780B35CFD8D"
         0.000002865 "rtsp.c:466"   Type: "DACP-ID", content: "F18FE780B35CFD8D"
         0.000002524 "rtsp.c:466"   Type: "Active-Remote", content: "1844140950"
         0.000049133 "rtsp.c:2424" Connection 2: RTSP Response:
         0.000027409 "rtsp.c:466"   Type: "CSeq", content: "8"
         0.000005357 "rtsp.c:466"   Type: "Server", content: "AirTunes/105.1"
        11.527642005 "rtsp.c:2379" Connection 2: Received an RTSP Packet of type "TEARDOWN":
         0.000032402 "rtsp.c:466"   Type: "CSeq", content: "9"
         0.000021794 "rtsp.c:466"   Type: "Session", content: "1"
         0.000002757 "rtsp.c:466"   Type: "User-Agent", content: "Music/1.0.4 (Macintosh; OS X 10.15.4) AppleWebKit/609.1.20.111.8"
         0.000002139 "rtsp.c:466"   Type: "Client-Instance", content: "F18FE780B35CFD8D"
         0.000001835 "rtsp.c:466"   Type: "DACP-ID", content: "F18FE780B35CFD8D"
         0.000001713 "rtsp.c:466"   Type: "Active-Remote", content: "1844140950"
         0.000002818 "rtsp.c:866" Connection 2: TEARDOWN
         0.000067835 "audio_pipe.c:92" Error flushing pipe when play stopped: "Invalid argument".
         0.000011539 "player.c:1608" Playback Stopped. Total playing time 00:01:36. Input: 44085.28 frames per second.
         0.000928080 "rtsp.c:2424" Connection 2: RTSP Response:
         0.000022396 "rtsp.c:466"   Type: "CSeq", content: "9"
         0.000002432 "rtsp.c:466"   Type: "Server", content: "AirTunes/105.1"
         0.000001913 "rtsp.c:466"   Type: "Connection", content: "close"
         2.000945129 "rtsp.c:2314" Connection 2: terminated.

and here is what came out on the aplay window:

mike@ubuntu:~/shairport-sync$ cat /tmp/sps | aplay -f cd
Playing raw data 'stdin' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo

(BTW, I'll remove that error flushing the pipe. It seemed like a good idea at the time...)

mikebrady commented 4 years ago

Well I finally found the -u flag in the v3.3 release notes to fix logging. This breaking change does not appear to mentioned or documented anywhere else, and the examples were never updated (the main README still says that logs are "output to the console").

Yikes, thanks. I'll fix it!

mikebrady commented 4 years ago

Just noticed that that the volume seems low in your logs, at -43.3 dB.

zaneclaes commented 4 years ago

😅I can only imagine how hard it is to maintain such a popular open-source project.

Good thought on the file permissions (I also noticed the root ownership), but I don't think that's it given that the audio does play for some time before cutting out. I tried deleting the fifo and letting it be recreated by my user with no change.

I had the volume intentionally low to stop annoying the others in the house while I tested ;)

I'm going to try using your exact commands and will report back.

zaneclaes commented 4 years ago

Okay, I recreated the problem with your setup:

cat /tmp/sps | aplay -f cd                                                                                                                 
Playing raw data 'stdin' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
underrun!!! (at least 637585.715 ms long)
underrun!!! (at least 213455.280 ms long)

The first underrun happened probably ~2 minutes after starting playing. It seems similar to the snapserver error (when the snapserver is consuming the fifo):

[Error] (PosixStream) Exception: end of file

edit shairport logs:

shairport-sync -vvu --statistics -o pipe -- /tmp/sps                                                                                   
         0.000023250 "shairport.c:435" Looking for configuration file at full path "/etc/shairport-sync.conf"
         0.000264261 "shairport.c:1636" Started!
         0.000010324 "shairport.c:1660" software version: "3.3.6-OpenSSL-Avahi-ALSA-pipe-soxr-metadata-sysconfdir:/etc"
         0.000003265 "shairport.c:1666" log verbosity is 2.
         0.000003473 "audio_pipe.c:94" pipe init
         0.000007192 "audio_pipe.c:128" Pipename is "/tmp/sps"
         0.000002593 "shairport.c:1681" The processor is running little-endian.
         0.000002559 "shairport.c:1714" disable resend requests is off.
         0.000002742 "shairport.c:1717" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000006740 "shairport.c:1718" statistics_requester status is 1.
         0.000003390 "shairport.c:1723" rtsp listening port is 5000.
         0.000003282 "shairport.c:1724" udp base port is 6001.
         0.000003688 "shairport.c:1725" udp port range is 10.
         0.000003298 "shairport.c:1726" player name is "Big-box".
         0.000003598 "shairport.c:1727" backend is "pipe".
         0.000003185 "shairport.c:1728" run_this_before_play_begins action is "(null)".
         0.000003490 "shairport.c:1729" run_this_after_play_ends action is "(null)".
         0.000003201 "shairport.c:1730" wait-cmd status is 0.
         0.000003243 "shairport.c:1731" run_this_before_play_begins may return output is 0.
         0.000003297 "shairport.c:1732" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000003203 "shairport.c:1733" run_this_before_entering_active_state action is  "(null)".
         0.000003052 "shairport.c:1734" run_this_after_exiting_active_state action is  "(null)".
         0.000003089 "shairport.c:1735" active_state_timeout is  10.000000 seconds.
         0.000004299 "shairport.c:1736" mdns backend "(null)".
         0.000003315 "shairport.c:1737" userSuppliedLatency is 0.
         0.000003118 "shairport.c:1740" interpolation setting is "auto".
         0.000003223 "shairport.c:1741" interpolation soxr_delay_threshold is 30.
         0.000003193 "shairport.c:1742" resync time is 0.050000 seconds.
         0.000003378 "shairport.c:1743" allow a session to be interrupted: 0.
         0.000003231 "shairport.c:1744" busy timeout time is 120.
         0.000003165 "shairport.c:1745" drift tolerance is 0.001995 seconds.
         0.000003496 "shairport.c:1746" password is "(null)".
         0.000003028 "shairport.c:1747" ignore_volume_control is 0.
         0.000003043 "shairport.c:1751" volume_max_db is not set
         0.000002972 "shairport.c:1753" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000003338 "shairport.c:1756" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000003500 "shairport.c:1758" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000003398 "shairport.c:1759" disable_synchronization is 0.
         0.000003060 "shairport.c:1760" use_mmap_if_available is 1.
         0.000003035 "shairport.c:1762" output_format automatic selection is enabled.
         0.000003255 "shairport.c:1766" output_rate automatic selection is enabled.
         0.000003265 "shairport.c:1770" audio backend desired buffer length is 1.000000 seconds.
         0.000003432 "shairport.c:1772" audio_backend_buffer_interpolation_threshold_in_seconds is 0.000000 seconds.
         0.000003370 "shairport.c:1773" audio backend latency offset is 0.000000 seconds.
         0.000003289 "shairport.c:1775" audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
         0.000003568 "shairport.c:1776" zeroconf regtype is "_raop._tcp".
         0.000003190 "shairport.c:1777" decoders_supported field is 1.
         0.000002998 "shairport.c:1778" use_apple_decoder is 0.
         0.000003163 "shairport.c:1779" alsa_use_hardware_mute is 0.
         0.000003124 "shairport.c:1783" no special mdns service interface was requested.
         0.000006125 "shairport.c:1787" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000003970 "shairport.c:1793" metadata enabled is 1.
         0.000003233 "shairport.c:1794" metadata pipename is "/tmp/shairport-sync-metadata".
         0.000003155 "shairport.c:1796" metadata socket address is "(null)" port 0.
         0.000003305 "shairport.c:1797" metadata socket packet size is "500".
         0.000003177 "shairport.c:1798" get-coverart is 1.
         0.000003225 "shairport.c:1816" loudness is 0.
         0.000003152 "shairport.c:1817" loudness reference level is -20.000000
         0.002177752 "mdns_avahi.c:205" avahi: service 'FE180177B52D@Big-box' group is not yet committed.
         0.000341524 "mdns_avahi.c:240" avahi: request to add "_raop._tcp" service with metadata
         0.000416653 "mdns_avahi.c:371" avahi_dacp_monitor_start Avahi DACP monitor successfully started
         0.000042132 "mdns_avahi.c:209" avahi: service 'FE180177B52D@Big-box' group is registering.
         0.938479165 "mdns_avahi.c:176" avahi: service 'FE180177B52D@Big-box' successfully added.
         0.558963639 "shairport.c:192" soxr_delay_index: 1.
         0.000021270 "shairport.c:199" "soxr" interpolation has been chosen.
         8.929814343 "rtsp.c:2707" Connection 1: new connection from [fe80::b3:d261:e76e:46e2]:53112 to self at [fe80::610e:206:cf12:3bd3]:5000.
         0.368982153 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "ANNOUNCE":
         0.000068325 "rtsp.c:464"   Type: "Content-Length", content: "663"
         0.000022109 "rtsp.c:464"   Type: "Content-Type", content: "application/sdp"
         0.000017478 "rtsp.c:464"   Type: "CSeq", content: "3"
         0.000012282 "rtsp.c:464"   Type: "DACP-ID", content: "772D918F53B615FB"
         0.000016412 "rtsp.c:464"   Type: "Active-Remote", content: "733864670"
         0.000015833 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
         0.004930571 "rtsp.c:1936" Play connection from user agent "AirPlay/420.45" on RTSP conversation thread 1.
         0.000033424 "rtsp.c:1945" AirPlay version 420 detected.
         0.000052426 "rtsp.c:2416" Connection 1: RTSP Response:
         0.000024988 "rtsp.c:464"   Type: "CSeq", content: "3"
         0.000015365 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
         0.000903666 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "SETUP":
         0.000038142 "rtsp.c:464"   Type: "Transport", content: "RTP/AVP/UDP;unicast;mode=record;timing_port=55215;control_port=62001"
         0.000012755 "rtsp.c:464"   Type: "CSeq", content: "4"
         0.000009222 "rtsp.c:464"   Type: "DACP-ID", content: "772D918F53B615FB"
         0.000009078 "rtsp.c:464"   Type: "Active-Remote", content: "733864670"
         0.000008386 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
         0.000012517 "rtsp.c:921" Connection 1: SETUP -- Active-Remote string seen: "733864670".
         0.000028974 "rtsp.c:936" Connection 1: SETUP -- DACP-ID string seen: "772D918F53B615FB".
         0.000039117 "rtp.c:981" Connection 1: SETUP -- Connection from fe80::b3:d261:e76e:46e2 to self at fe80::610e:206:cf12:3bd3.
         0.000200718 "rtsp.c:1001" Connection 1: SETUP DACP-ID "772D918F53B615FB" from fe80::b3:d261:e76e:46e2 to fe80::610e:206:cf12:3bd3 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
         0.000025551 "rtsp.c:2416" Connection 1: RTSP Response:
         0.000012672 "rtsp.c:464"   Type: "CSeq", content: "4"
         0.000016788 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
         0.000020410 "rtsp.c:464"   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002;server_port=6003"
         0.000021501 "rtsp.c:464"   Type: "Session", content: "1"
         0.000847446 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "RECORD":
         0.000085255 "rtsp.c:464"   Type: "CSeq", content: "5"
         0.000026421 "rtsp.c:464"   Type: "DACP-ID", content: "772D918F53B615FB"
         0.000021670 "rtsp.c:464"   Type: "Active-Remote", content: "733864670"
         0.000018731 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
         0.000025136 "rtsp.c:806" Connection 1: RECORD
         0.000022373 "activity_monitor.c:64" abeg
         0.000189432 "player.c:3042" pbeg
         0.000044162 "rtsp.c:2416" Connection 1: RTSP Response:
         0.000023615 "rtsp.c:464"   Type: "CSeq", content: "5"
         0.000018990 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
         0.000020774 "rtsp.c:464"   Type: "Audio-Latency", content: "11025"
         0.001013521 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000039040 "rtsp.c:464"   Type: "Content-Length", content: "20"
         0.000017251 "rtsp.c:464"   Type: "Content-Type", content: "text/parameters"
         0.000020229 "rtsp.c:464"   Type: "CSeq", content: "6"
         0.000018223 "rtsp.c:464"   Type: "DACP-ID", content: "772D918F53B615FB"
         0.000018729 "rtsp.c:464"   Type: "Active-Remote", content: "733864670"
         0.000019778 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
         0.000063819 "loudness.c:47" Volume: -43.3 dB - Loudness gain @10Hz: 11.7 dB
         0.000059265 "player.c:2958" player_volume_without_notification: volume mode is 0, airplay volume is -20.000000, software_attenuation: -4333.500000, hardware_attenuation: 0.000000, muting is disabled.
         0.000032406 "rtsp.c:2416" Connection 1: RTSP Response:
         0.000020564 "rtsp.c:464"   Type: "CSeq", content: "6"
         0.000020654 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
         0.001587390 "player.c:1927" sync error in milliseconds, total packets, missing packets, late packets, too late packets, resend requests, min buffer occupancy, max buffer occupancy, source nominal frames per second, source actual frames per second, source clock drift in ppm, source clock drift sample count
         0.001079993 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000048152 "rtsp.c:464"   Type: "RTP-Info", content: "rtptime=3821290831"
         0.000016404 "rtsp.c:464"   Type: "Content-Length", content: "0"
         0.000012693 "rtsp.c:464"   Type: "Content-Type", content: "image/none"
         0.000012194 "rtsp.c:464"   Type: "CSeq", content: "7"
         0.000012581 "rtsp.c:464"   Type: "DACP-ID", content: "772D918F53B615FB"
         0.000012507 "rtsp.c:464"   Type: "Active-Remote", content: "733864670"
         0.000013098 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
         0.000039400 "rtsp.c:2416" Connection 1: RTSP Response:
         0.000118010 "player.c:1951" Set initial volume to -20.000000.
         0.000028066 "rtsp.c:464"   Type: "CSeq", content: "7"
         0.000044599 "loudness.c:47" Volume: -43.3 dB - Loudness gain @10Hz: 11.7 dB
         0.000050172 "player.c:2958" player_volume_without_notification: volume mode is 0, airplay volume is -20.000000, software_attenuation: -4333.500000, hardware_attenuation: 0.000000, muting is disabled.
         0.000016026 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
         0.000039283 "player.c:1954" Play begin
         0.000785714 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000031250 "rtsp.c:464"   Type: "RTP-Info", content: "rtptime=3821290831"
         0.000013053 "rtsp.c:464"   Type: "Content-Length", content: "43"
         0.000011476 "rtsp.c:464"   Type: "Content-Type", content: "text/parameters"
         0.000011542 "rtsp.c:464"   Type: "CSeq", content: "8"
         0.000012358 "rtsp.c:464"   Type: "DACP-ID", content: "772D918F53B615FB"
         0.000011600 "rtsp.c:464"   Type: "Active-Remote", content: "733864670"
         0.000010980 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
         0.000032465 "rtsp.c:2416" Connection 1: RTSP Response:
         0.000018403 "rtsp.c:464"   Type: "CSeq", content: "8"
         0.000024539 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
         0.000630456 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
         0.000029029 "rtsp.c:464"   Type: "RTP-Info", content: "rtptime=3821290831"
         0.000017870 "rtsp.c:464"   Type: "Content-Length", content: "161"
         0.000017428 "rtsp.c:464"   Type: "Content-Type", content: "application/x-dmap-tagged"
         0.000015844 "rtsp.c:464"   Type: "CSeq", content: "9"
         0.000014281 "rtsp.c:464"   Type: "DACP-ID", content: "772D918F53B615FB"
         0.000011470 "rtsp.c:464"   Type: "Active-Remote", content: "733864670"
         0.000010895 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
         0.000030062 "rtsp.c:2416" Connection 1: RTSP Response:
         0.000011857 "rtsp.c:464"   Type: "CSeq", content: "9"
         0.000011133 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
         0.027500768 "rtsp.c:2373" Connection 1: Received an RTSP Packet of type "FLUSH":
         0.000023255 "rtsp.c:464"   Type: "RTP-Info", content: "seq=5106;rtptime=3821385854"
         0.000007132 "rtsp.c:464"   Type: "CSeq", content: "10"
         0.000007665 "rtsp.c:464"   Type: "DACP-ID", content: "772D918F53B615FB"
         0.000006847 "rtsp.c:464"   Type: "Active-Remote", content: "733864670"
         0.000006888 "rtsp.c:464"   Type: "User-Agent", content: "AirPlay/420.45"
         0.000017879 "rtsp.c:2416" Connection 1: RTSP Response:
         0.000006014 "rtsp.c:464"   Type: "CSeq", content: "10"
         0.000006207 "rtsp.c:464"   Type: "Server", content: "AirTunes/105.1"
         0.030253952 "player.c:264" Hammerton Decoder used on encrypted audio.
         0.000704027 "player.c:1016" pffr
         2.229020405 "player.c:1278" prsm
         0.140121744 "player.c:634" request resend of 184 packets starting at seqno 5204.
         0.270003695 "player.c:634" request resend of 12 packets starting at seqno 5376.
         7.964331090 "player.c:2726"       0.00,        1003,      0,    184,      0,      2,  288,  340,   44099.90,   44065.77,      0.00,     0
         8.000044407 "player.c:2726"       0.00,        2006,      0,    184,      0,      2,  298,  341,   44099.98,   44095.10,      0.00,     0
         2.816315859 "rtp.c:142" Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8567.8,    45692.7,  2200206.0.
         5.057901545 "player.c:2726"       0.00,        3009,      0,    184,      0,      2,  294,  341,   44099.97,   44100.14,      0.00,     0
         8.123106324 "player.c:2726"       0.00,        4012,      0,    189,      0,      4,  294,  341,   44100.00,   44094.00,      0.00,     0
         6.768649181 "rtp.c:142" Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.3,    13002.0,    34932.0.
         1.230293780 "player.c:2726"       0.00,        5015,      0,    193,      0,      7,  299,  341,   44099.98,   44100.39,      0.00,     0
         7.874263285 "player.c:2726"       0.00,        6018,      0,    193,      0,      7,  293,  341,   44099.99,   44094.86,      0.00,     0
         8.124604948 "player.c:2726"       0.00,        7021,      0,    193,      0,      7,  295,  340,   44099.99,   44098.43,      0.00,     0
         2.751697192 "rtp.c:142" Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.8,    13052.7,    37563.0.
         5.247958841 "player.c:2726"       0.00,        8024,      0,    193,      0,      7,  296,  338,   44100.00,   44093.83,      0.00,     0
         7.874563995 "player.c:2726"       0.00,        9027,      0,    193,      0,      7,  294,  340,   44099.99,   44097.01,      0.00,     0

zaneclaes commented 4 years ago

FWIW, the machine has plenty of headroom... I believe underruns imply a need for a bigger buffer though (?) Yet, I still experience the problem with a 5 second buffer.

zaneclaes commented 4 years ago

Well... I eventually "fixed" it by getting rid of the pipe and using stdout. The audio stream is MUCH more responsive (less than a second from pressing a button). I find this weird because I have 3 other streams into Snapcast, all of which use fifos without problem. This required stuffing both apps in the same Docker container, which other explorers can find here: https://github.com/zaneclaes/shaircast

mikebrady commented 4 years ago

Thanks for the update. So, for debugging purposes, if I was to use https://github.com/zaneclaes/aircast and change from the stdout backend to the pipe backend, would the problem return?

zaneclaes commented 4 years ago

Yes, that should be the case.

On Mon, May 25, 2020 at 1:47 AM Mike Brady notifications@github.com wrote:

Thanks for the update. So, for debugging purposes, if I was to use https://github.com/zaneclaes/aircast and change from the stdout backend to the pipe backend, would the problem return?

— You are receiving this because you modified the open/close state.

Reply to this email directly, view it on GitHub https://github.com/mikebrady/shairport-sync/issues/1009#issuecomment-633431671, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAP47VJ36WC5WK7EEPFDIMDRTIPC5ANCNFSM4NIPXUPA .

mikebrady commented 4 years ago

Just FYI, I've done some work on this, reported here over on #1005, which might be of interest.

Debugging Shairport Sync while in a Docker container should be easier and the code for writing to the audio pipe has been simplified and hopefully will be more responsive to error conditions.

zaneclaes commented 4 years ago

Thanks for the heads up! The stdout approach continues to work well for me, but I can do some testing if you want me to look into anything in particular.

mikebrady commented 4 years ago

If you got a chance, it would be great, thanks, but don't sweat. The difficulties you were having with the pipe output would be interesting. I am suspicious of SnapCast's handling of the metadata pipe in the other setup, so I just wonder if it might extend to its handling of the audio pipe. The handling of both of these has been simplified and possibly "standardised" in Shairport Sync now.

mikebrady / shairport-sync

Lags for first 15 seconds; stops playing within first 1-2 minutes (snapfifo) #1009