Cannot play audio on a usb device

ayoubkhayatti commented 5 years ago

Hi,

I did setup shairport sync with an audio interface Scarlett 2i4 USB. The issue is that there is no audio. I can play audio directly on the raspberry pi 4 but no audio comes out when I play from my iPhone.

Here is the list of devices:

**** List of PLAYBACK Hardware Devices ****
card 0: ALSA [bcm2835 ALSA], device 0: bcm2835 ALSA [bcm2835 ALSA]
  Subdevices: 7/7
  Subdevice #0: subdevice #0
  Subdevice #1: subdevice #1
  Subdevice #2: subdevice #2
  Subdevice #3: subdevice #3
  Subdevice #4: subdevice #4
  Subdevice #5: subdevice #5
  Subdevice #6: subdevice #6
card 0: ALSA [bcm2835 ALSA], device 1: bcm2835 IEC958/HDMI [bcm2835 IEC958/HDMI]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: ALSA [bcm2835 ALSA], device 2: bcm2835 IEC958/HDMI1 [bcm2835 IEC958/HDMI1]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 1: USB [Scarlett 2i4 USB], device 0: USB Audio [USB Audio]
  Subdevices: 0/1
  Subdevice #0: subdevice #0

This is my config file:

general =
{
    volume_range_db = 60 ;
}
alsa =
{
    output_device = "hw:1"; 
    mixer_control_name = "PCM"; 
}
diagnostics =
{
    statistics = "yes"; 
    log_verbosity = 3; 
}

I changed these two lines in alsa.config:

defaults.ctl.card 1
defaults.pcm.card 1

Yet I keep seeing this error in the logs:

0.000101998 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 352 samples to alsa device.
0.005516437 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
0.000072943 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 352 samples to alsa device.
0.010900098 "player.c:2148" Player: packets out of sequence: expected: 9090, got: 9099, with ab_read: 9100 and ab_write: 9332.

Did anyone have a similar issue? can anyone help please?

mikebrady commented 5 years ago

Thanks for the post. Could you post two things please?

The output from:
```
$ shairport-sync -V
```
(That's an upper-case "V", BTW.)

The output from:

$ shairport-sync -h

At the end of the help message is a list of alsa output devices, something like this:

...
Settings and options for the audio backend "alsa":
-d output-device    set the output device, default is "default".
-c mixer-control    set the mixer control name, default is to use no mixer.
-m mixer-device     set the mixer device, default is the output device.
-i mixer-index      set the mixer index, default is 0.
hardware output devices:
  "hw:ALSA"
  "hw:Device"
  "hw:sndrpihifiberry"

It would be interesting to see these.

mikebrady commented 5 years ago

Are you certain the Scarlett 2i4 has a mixer named PCM? You can use alsamixer to explore the device and to see what mixers (and their names), if any, it has.

Also, there might be a clue in this message. The suggestion would be to explicitly set the output format to S32_LE in the configurations file at /etc/shairport-sync.conf:

    output_format = "S32_LE"; // can be "auto", "U8", "S8", "S16", "S16_LE", "S16_BE", "S24", "S24_LE", "S24_BE", "S24_3LE", "S24_3BE", "S32", "S32_LE" or "S32_BE" but the device must have the capability. Except where stated using (*LE or *BE), endianness matches that of the processor.

(Remember to uncomment the entry by removing the leading // as shown above.)

ayoubkhayatti commented 5 years ago

Hi @mikebrady ,

Thanks for the reply. Indeed Scarlett doesn't have a mixer as it alsamixer shows This sound device does not have any controls. So I commented mixer_control_name and enabled output_format to be what you mentioned.

I will put the full logs here, because there is too much happening and I don't know where it starts to break. But it says hw:1 is invalid!

Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.031608833 "shairport.c:1621" Started!
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.002012592 "shairport.c:1633" software version: "3.3.3-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000089408 "shairport.c:1639" log verbosity is 3.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000216481 "audio_alsa.c:1001" alsa: init() -- alsa_backend_state => abm_disconnected.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000054278 "audio_alsa.c:1018" alsa: alsa_maximum_stall_time of 0.200000 sec.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000124907 "audio_alsa.c:1303" alsa: disable_standby_mode is "never".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000051538 "audio_alsa.c:1305" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000045481 "audio_alsa.c:1307" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000420648 "audio_alsa.c:1346" alsa: output device name is "hw:1".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000460278 "shairport.c:1654" The processor is running little-endian.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000117704 "shairport.c:1687" disable resend requests is off.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000045333 "shairport.c:1690" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped d
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000042241 "shairport.c:1691" statistics_requester status is 1.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000039611 "shairport.c:1696" rtsp listening port is 5000.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000038166 "shairport.c:1697" udp base port is 6001.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000038686 "shairport.c:1698" udp port range is 10.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000038277 "shairport.c:1699" player name is "Raspberrypi".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000037186 "shairport.c:1700" backend is "(null)".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000297481 "shairport.c:1701" run_this_before_play_begins action is "(null)".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000057389 "shairport.c:1702" run_this_after_play_ends action is "(null)".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000039222 "shairport.c:1703" wait-cmd status is 0.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000038019 "shairport.c:1704" run_this_before_play_begins may return output is 0.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000040981 "shairport.c:1705" run_this_if_an_unfixable_error_is_detected action is "(null)".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000047722 "shairport.c:1706" run_this_before_entering_active_state action is  "(null)".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000039612 "shairport.c:1707" run_this_after_exiting_active_state action is  "(null)".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000038407 "shairport.c:1708" active_state_timeout is  10.000000 seconds.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000045981 "shairport.c:1709" mdns backend "(null)".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000038056 "shairport.c:1710" userSuppliedLatency is 0.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000037185 "shairport.c:1713" interpolation setting is "auto".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000038019 "shairport.c:1714" interpolation soxr_delay_threshold is 30.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000036852 "shairport.c:1715" resync time is 0.050000 seconds.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000054037 "shairport.c:1716" allow a session to be interrupted: 0.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000046296 "shairport.c:1717" busy timeout time is 120.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000046759 "shairport.c:1718" drift tolerance is 0.001995 seconds.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000056037 "shairport.c:1719" password is "(null)".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000047630 "shairport.c:1720" ignore_volume_control is 0.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000047870 "shairport.c:1724" volume_max_db is not set
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000039037 "shairport.c:1726" volume range in dB (zero means use the range specified by the mixer): 60.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000037630 "shairport.c:1729" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000038241 "shairport.c:1731" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000037685 "shairport.c:1732" disable_synchronization is 0.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000037666 "shairport.c:1733" use_mmap_if_available is 1.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000037778 "shairport.c:1735" output_format automatic selection is disabled.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000037797 "shairport.c:1737" output_format is "S32_LE".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000045370 "shairport.c:1739" output_rate automatic selection is enabled.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000037815 "shairport.c:1743" audio backend desired buffer length is 0.200000 seconds.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000038463 "shairport.c:1745" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000039555 "shairport.c:1746" audio backend latency offset is 0.000000 seconds.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000039574 "shairport.c:1748" audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000039574 "shairport.c:1749" zeroconf regtype is "_raop._tcp".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000053500 "shairport.c:1750" decoders_supported field is 1.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000040556 "shairport.c:1751" use_apple_decoder is 0.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000039407 "shairport.c:1752" alsa_use_hardware_mute is 0.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000041426 "shairport.c:1756" no special mdns service interface was requested.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000120297 "shairport.c:1760" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000054685 "shairport.c:1789" loudness is 0.
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.000044944 "shairport.c:1790" loudness reference level is -20.000000
Oct 28 17:07:06 raspberrypi shairport-sync[400]:          0.001282241 "audio_alsa.c:1940" keep_dac_busy is now "no"
Oct 28 17:07:07 raspberrypi shairport-sync[400]:          0.043055518 "mdns_avahi.c:205" avahi: service 'AF31192A3A11@Raspberrypi' group is not yet committed.
Oct 28 17:07:07 raspberrypi shairport-sync[400]:          0.006784167 "mdns_avahi.c:247" avahi: request to add "_raop._tcp" service without metadata
Oct 28 17:07:07 raspberrypi shairport-sync[400]:          0.002159704 "mdns_avahi.c:371" avahi_dacp_monitor_start Avahi DACP monitor successfully started
Oct 28 17:07:07 raspberrypi shairport-sync[400]:          0.007584426 "mdns_avahi.c:209" avahi: service 'AF31192A3A11@Raspberrypi' group is registering.
Oct 28 17:07:07 raspberrypi shairport-sync[400]:          0.000303870 "mdns_avahi.c:176" avahi: service 'AF31192A3A11@Raspberrypi' successfully added.
Oct 28 17:07:08 raspberrypi shairport-sync[400]:          1.440596277 "shairport.c:192" soxr_delay_index: 5.
Oct 28 17:07:08 raspberrypi shairport-sync[400]:          0.000061778 "shairport.c:199" "soxr" interpolation has been chosen.
Oct 28 17:08:18 raspberrypi shairport-sync[400]:         35.349136127 "rtsp.c:2683" Connection 1: new connection from 192.168.0.21:51108 to self at 192.168.0.60:5000.
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.003031241 "rtsp.c:2722" Successfully created RTSP receiver thread 1.
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000333703 "rtsp.c:532" RTSP Message Received: "OPTIONS * RTSP/1.0".
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000124519 "rtsp.c:562"     CSeq: 0.
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000051741 "rtsp.c:562"     DACP-ID: 850A9F113A46A994.
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000048259 "rtsp.c:562"     Active-Remote: 2758251862.
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000045722 "rtsp.c:562"     User-Agent: AirPlay/406.31.21.
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000051037 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "OPTIONS":
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000042815 "rtsp.c:463"   Type: "CSeq", content: "0"
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000040852 "rtsp.c:463"   Type: "DACP-ID", content: "850A9F113A46A994"
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000039555 "rtsp.c:463"   Type: "Active-Remote", content: "2758251862"
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000039278 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000045000 "rtsp.c:851" Connection 1: OPTIONS
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000042463 "rtsp.c:2409" Connection 1: RTSP Response:
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000038241 "rtsp.c:463"   Type: "CSeq", content: "0"
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000037444 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:18 raspberrypi shairport-sync[400]:          0.000037611 "rtsp.c:463"   Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER,
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          2.453795925 "rtsp.c:532" RTSP Message Received: "OPTIONS * RTSP/1.0".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000073352 "rtsp.c:562"     CSeq: 1.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000023240 "rtsp.c:562"     DACP-ID: 850A9F113A46A994.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019926 "rtsp.c:562"     Active-Remote: 2758251862.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018519 "rtsp.c:562"     User-Agent: AirPlay/406.31.21.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000022037 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "OPTIONS":
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018667 "rtsp.c:463"   Type: "CSeq", content: "1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017018 "rtsp.c:463"   Type: "DACP-ID", content: "850A9F113A46A994"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017278 "rtsp.c:463"   Type: "Active-Remote", content: "2758251862"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016463 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018555 "rtsp.c:851" Connection 1: OPTIONS
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017426 "rtsp.c:2409" Connection 1: RTSP Response:
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017185 "rtsp.c:463"   Type: "CSeq", content: "1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000015667 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000015889 "rtsp.c:463"   Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER,
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.010365648 "rtsp.c:532" RTSP Message Received: "OPTIONS * RTSP/1.0".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000056815 "rtsp.c:562"     Apple-Challenge: I2RKxxeAFkqKssD8hGHsBQ==.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019815 "rtsp.c:562"     CSeq: 2.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018555 "rtsp.c:562"     DACP-ID: 850A9F113A46A994.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017704 "rtsp.c:562"     Active-Remote: 2758251862.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018407 "rtsp.c:562"     User-Agent: AirPlay/406.31.21.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020482 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "OPTIONS":
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000026593 "rtsp.c:463"   Type: "Apple-Challenge", content: "I2RKxxeAFkqKssD8hGHsBQ=="
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016648 "rtsp.c:463"   Type: "CSeq", content: "2"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000015852 "rtsp.c:463"   Type: "DACP-ID", content: "850A9F113A46A994"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000015574 "rtsp.c:463"   Type: "Active-Remote", content: "2758251862"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000015388 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.018338815 "rtsp.c:851" Connection 1: OPTIONS
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000053556 "rtsp.c:2409" Connection 1: RTSP Response:
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018574 "rtsp.c:463"   Type: "Apple-Response", content: "pngL9foTSxWnIqkDqkGyYQ2Ay/azR8mzdbtkeX8y2RhZ+mUNNnV1jPOt6D1/kQ4Z
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000030389 "rtsp.c:463"   Type: "CSeq", content: "2"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018426 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016092 "rtsp.c:463"   Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER,
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.014241426 "rtsp.c:532" RTSP Message Received: "ANNOUNCE rtsp://192.168.0.60/10873050581000930071 RTSP/1.0".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000053945 "rtsp.c:562"     Content-Length: 658.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019703 "rtsp.c:562"     Content-Type: application/sdp.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017815 "rtsp.c:562"     CSeq: 3.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018297 "rtsp.c:562"     DACP-ID: 850A9F113A46A994.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019425 "rtsp.c:562"     Active-Remote: 2758251862.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017889 "rtsp.c:562"     User-Agent: AirPlay/406.31.21.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000205778 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "ANNOUNCE":
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000036204 "rtsp.c:463"   Type: "Content-Length", content: "658"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016907 "rtsp.c:463"   Type: "Content-Type", content: "application/sdp"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016574 "rtsp.c:463"   Type: "CSeq", content: "3"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000015760 "rtsp.c:463"   Type: "DACP-ID", content: "850A9F113A46A994"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016907 "rtsp.c:463"   Type: "Active-Remote", content: "2758251862"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016074 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000143296 "rtsp.c:1674" Connection 1: ANNOUNCE
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000023760 "common.c:1265" mutex_lock "&playing_conn_lock" at "rtsp.c:1682".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000028222 "common.c:1290" mutex_unlock "&playing_conn_lock" at "rtsp.c:1702".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017352 "rtsp.c:1729" Connection 1: ANNOUNCE has acquired play lock.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016592 "common.c:163" Resetting UDP Port Suggestion to 6001
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000143778 "rtsp.c:1831" Minimum latency 11025 specified
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000040241 "rtsp.c:1836" Maximum latency 88200 specified
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.021216759 "rtsp.c:1872" An ALAC stream has been detected.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000082333 "rtsp.c:1934" Play connection from user agent "AirPlay/406.31.21" on RTSP conversation thread 1.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000021908 "rtsp.c:1943" AirPlay version 406 detected.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017666 "rtsp.c:2409" Connection 1: RTSP Response:
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017056 "rtsp.c:463"   Type: "CSeq", content: "3"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017130 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.003969759 "rtsp.c:532" RTSP Message Received: "SETUP rtsp://192.168.0.60/10873050581000930071 RTSP/1.0".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000062259 "rtsp.c:562"     Transport: RTP/AVP/UDP;unicast;mode=record;timing_port=60229;control_port=53918.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000021074 "rtsp.c:562"     CSeq: 4.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018315 "rtsp.c:562"     DACP-ID: 850A9F113A46A994.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018407 "rtsp.c:562"     Active-Remote: 2758251862.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018371 "rtsp.c:562"     User-Agent: AirPlay/406.31.21.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020555 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "SETUP":
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000174352 "rtsp.c:463"   Type: "Transport", content: "RTP/AVP/UDP;unicast;mode=record;timing_port=60229;control_port=53918"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000021834 "rtsp.c:463"   Type: "CSeq", content: "4"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017000 "rtsp.c:463"   Type: "DACP-ID", content: "850A9F113A46A994"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016314 "rtsp.c:463"   Type: "Active-Remote", content: "2758251862"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000015926 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019722 "rtsp.c:913" Connection 1: SETUP
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019723 "common.c:1265" mutex_lock "&playing_conn_lock" at "rtsp.c:265".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000145074 "common.c:1290" mutex_unlock "&playing_conn_lock" at "rtsp.c:268".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000021370 "rtsp.c:920" Connection 1: SETUP -- Active-Remote string seen: "2758251862".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000032704 "rtsp.c:935" Connection 1: SETUP -- DACP-ID string seen: "850A9F113A46A994".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000022537 "rtp.c:944" rtp_setup: cport=53918 tport=60229.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000021296 "rtp.c:981" Connection 1: SETUP -- Connection from 192.168.0.21 to self at 192.168.0.60.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000359982 "rtp.c:1039" listening for audio, control and timing on ports 6003, 6001, 6002.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000043944 "rtsp.c:1000" Connection 1: SETUP DACP-ID "850A9F113A46A994" from 192.168.0.21 to 192.168.0.60 with UDP ports Con
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000056611 "rtsp.c:2409" Connection 1: RTSP Response:
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000021445 "rtsp.c:463"   Type: "CSeq", content: "4"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016481 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000130000 "rtsp.c:463"   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;tim
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000027574 "rtsp.c:463"   Type: "Session", content: "1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.003297074 "rtsp.c:532" RTSP Message Received: "RECORD rtsp://192.168.0.60/10873050581000930071 RTSP/1.0".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000202815 "rtsp.c:562"     CSeq: 5.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000028945 "rtsp.c:562"     DACP-ID: 850A9F113A46A994.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018463 "rtsp.c:562"     Active-Remote: 2758251862.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018092 "rtsp.c:562"     User-Agent: AirPlay/406.31.21.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020722 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "RECORD":
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000056611 "rtsp.c:2409" Connection 1: RTSP Response:
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000021445 "rtsp.c:463"   Type: "CSeq", content: "4"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016481 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000130000 "rtsp.c:463"   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;tim
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000027574 "rtsp.c:463"   Type: "Session", content: "1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.003297074 "rtsp.c:532" RTSP Message Received: "RECORD rtsp://192.168.0.60/10873050581000930071 RTSP/1.0".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000202815 "rtsp.c:562"     CSeq: 5.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000028945 "rtsp.c:562"     DACP-ID: 850A9F113A46A994.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018463 "rtsp.c:562"     Active-Remote: 2758251862.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018092 "rtsp.c:562"     User-Agent: AirPlay/406.31.21.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020722 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "RECORD":
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016963 "rtsp.c:463"   Type: "CSeq", content: "5"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000143389 "rtsp.c:463"   Type: "DACP-ID", content: "850A9F113A46A994"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018185 "rtsp.c:463"   Type: "Active-Remote", content: "2758251862"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016037 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018463 "rtsp.c:805" Connection 1: RECORD
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000029223 "common.c:1265" mutex_lock "&playing_conn_lock" at "rtsp.c:265".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000156185 "common.c:1290" mutex_unlock "&playing_conn_lock" at "rtsp.c:268".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000032592 "common.c:1265" mutex_lock "&activity_monitor_mutex" at "activity_monitor.c:115".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.005036111 "audio_alsa.c:463" Output written using MMAP
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000067149 "audio_alsa.c:487" *warning: audio_alsa: Channels count (2) not available for device "hw:1": Invalid argument
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000323592 "rtsp.c:2409" Connection 1: RTSP Response:
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000015537 "player.c:1667" No latency has (yet) been specified. Setting 88,200 (2 seconds) frames as a default.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000175334 "rtsp.c:463"   Type: "CSeq", content: "5"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000027592 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017111 "rtsp.c:463"   Type: "Audio-Latency", content: "11025"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.004296037 "rtsp.c:532" RTSP Message Received: "SET_PARAMETER rtsp://192.168.0.60/10873050581000930071 RTSP/1.0".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000064593 "rtsp.c:562"     Content-Length: 20.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020296 "rtsp.c:562"     Content-Type: text/parameters.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019297 "rtsp.c:562"     CSeq: 6.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019666 "rtsp.c:562"     DACP-ID: 850A9F113A46A994.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000021204 "rtsp.c:562"     Active-Remote: 2758251862.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000006685 "rtsp.c:562"     User-Agent: AirPlay/406.31.21.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000024037 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000011852 "player.c:1728" Output frame bytes is 8.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000212018 "rtsp.c:463"   Type: "Content-Length", content: "20"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000039463 "rtsp.c:463"   Type: "Content-Type", content: "text/parameters"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000004075 "player.c:1733" dac_buffer_queue_minimum_length is 5292 frames.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000013296 "rtsp.c:463"   Type: "CSeq", content: "6"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017407 "rtsp.c:463"   Type: "DACP-ID", content: "850A9F113A46A994"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000014334 "player.c:1826" Output bit depth is 32.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000002703 "rtsp.c:463"   Type: "Active-Remote", content: "2758251862"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020482 "player.c:1833" Dithering will be enabled because the output volume is being altered in software
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000047981 "audio_alsa.c:1410" audio_alsa start called.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000022815 "player.c:1899" sync error in milliseconds, net correction in ppm, corrections in ppm, total packets, missing pac
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000086148 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000031037 "rtsp.c:1583" Connection 1: SET_PARAMETER
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000039408 "common.c:1265" mutex_lock "&conn->volume_control_mutex" at "player.c:2730".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000033018 "player.c:2939" player_volume_without_notification: volume mode is 0, airplay volume is -15.000000, software_atte
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000030796 "common.c:1290" mutex_unlock "&conn->volume_control_mutex" at "player.c:2959".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019908 "rtsp.c:2409" Connection 1: RTSP Response:
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017722 "rtsp.c:463"   Type: "CSeq", content: "6"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000197333 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.001184612 "player.c:1951" Set initial volume to -15.000000.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000087444 "common.c:1265" mutex_lock "&conn->volume_control_mutex" at "player.c:2730".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000025352 "player.c:2939" player_volume_without_notification: volume mode is 0, airplay volume is -15.000000, software_atte
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000023500 "common.c:1290" mutex_unlock "&conn->volume_control_mutex" at "player.c:2959".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016611 "player.c:1954" Play begin
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.001123352 "mdns_avahi.c:94" resolve_callback: Service 'iTunes_Ctrl_850A9F113A46A994' of type '_dacp._tcp' in domain 'local'
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000054000 "mdns_avahi.c:100" resolve_callback: client dacp_id "850A9F113A46A994" dacp port: 51107.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.002387259 "rtsp.c:532" RTSP Message Received: "SET_PARAMETER rtsp://192.168.0.60/10873050581000930071 RTSP/1.0".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000063593 "rtsp.c:562"     Content-Length: 20.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019389 "rtsp.c:562"     Content-Type: text/parameters.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018759 "rtsp.c:562"     CSeq: 7.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017463 "rtsp.c:562"     DACP-ID: 850A9F113A46A994.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017518 "rtsp.c:562"     Active-Remote: 2758251862.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018222 "rtsp.c:562"     User-Agent: AirPlay/406.31.21.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000023019 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017963 "rtsp.c:463"   Type: "Content-Length", content: "20"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016630 "rtsp.c:463"   Type: "Content-Type", content: "text/parameters"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000167888 "rtsp.c:463"   Type: "CSeq", content: "7"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017352 "rtsp.c:463"   Type: "DACP-ID", content: "850A9F113A46A994"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016074 "rtsp.c:463"   Type: "Active-Remote", content: "2758251862"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016537 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000027537 "rtsp.c:1583" Connection 1: SET_PARAMETER
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000030926 "common.c:1265" mutex_lock "&conn->volume_control_mutex" at "player.c:2730".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000026334 "player.c:2939" player_volume_without_notification: volume mode is 0, airplay volume is -15.000000, software_atte
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000027296 "common.c:1290" mutex_unlock "&conn->volume_control_mutex" at "player.c:2959".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000120463 "rtsp.c:2409" Connection 1: RTSP Response:
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019167 "rtsp.c:463"   Type: "CSeq", content: "7"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000015944 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.039944407 "rtsp.c:532" RTSP Message Received: "FLUSH rtsp://192.168.0.60/10873050581000930071 RTSP/1.0".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000062500 "rtsp.c:562"     RTP-Info: seq=48518;rtptime=1667774407.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019815 "rtsp.c:562"     CSeq: 8.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017778 "rtsp.c:562"     DACP-ID: 850A9F113A46A994.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017704 "rtsp.c:562"     Active-Remote: 2758251862.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017703 "rtsp.c:562"     User-Agent: AirPlay/406.31.21.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020056 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "FLUSH":
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016685 "rtsp.c:463"   Type: "RTP-Info", content: "seq=48518;rtptime=1667774407"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016667 "rtsp.c:463"   Type: "CSeq", content: "8"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017315 "rtsp.c:463"   Type: "DACP-ID", content: "850A9F113A46A994"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017963 "rtsp.c:463"   Type: "Active-Remote", content: "2758251862"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017426 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000158129 "rtsp.c:879" Connection 1: FLUSH
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020463 "common.c:1265" mutex_lock "&playing_conn_lock" at "rtsp.c:265".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020741 "common.c:1290" mutex_unlock "&playing_conn_lock" at "rtsp.c:268".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000034722 "player.c:2981" player_flush
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018296 "player.c:2969" Flush requested up to 1667774407. It seems as if 0 is special.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019982 "common.c:1265" mutex_lock "&conn->flush_mutex" at "player.c:2970".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000104926 "common.c:1290" mutex_unlock "&conn->flush_mutex" at "player.c:2976".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000037111 "player.c:2977" Flush request made.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017241 "rtsp.c:2409" Connection 1: RTSP Response:
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000015981 "rtsp.c:463"   Type: "CSeq", content: "8"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017648 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.003655445 "common.c:1265" mutex_lock "&alsa_mutex" at "audio_alsa.c:1823".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000051481 "audio_alsa.c:1838" alsa: flush() -- called on a disconnected alsa backend
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018741 "common.c:1290" mutex_unlock "&alsa_mutex" at "audio_alsa.c:1839".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.020589852 "common.c:1265" mutex_lock "&conn->flush_mutex" at "player.c:474".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000158648 "common.c:1290" mutex_unlock "&conn->flush_mutex" at "player.c:477".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000021685 "player.c:499" syncing to seqno 48518.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000030408 "player.c:264" Hammerton Decoder used on encrypted audio.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.002635129 "audio_alsa.c:1733" alsa: do_open() -- output device already open.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000475408 "audio_alsa.c:1777" alsa: play() -- opened output device
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000396981 "audio_alsa.c:1782" alsa: play() -- alsa_backend_state => abm_playing
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000396259 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000417945 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.003722833 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000536241 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.004457907 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000489797 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.004901814 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000512315 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.004879241 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000485093 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.004914259 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000497907 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.001431315 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000516037 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.001420870 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000468019 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.001463259 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000502148 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.004830871 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000495333 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.004894722 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000487797 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.004901425 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000518352 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.004872315 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000493648 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.002434834 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000532055 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.001450574 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000481093 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.001436667 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000464481 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.004925963 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000500778 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.004897870 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000560445 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.004837055 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000479259 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.004961500 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000496426 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.003953760 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000494092 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.001412056 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000491889 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.001417814 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000566037 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.004854871 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000492555 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.004872648 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000567982 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.004830685 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000485445 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.004968055 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000557537 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.004248482 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000500833 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.001427426 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000571241 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.001438852 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000511407 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.004891055 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000496982 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.005000907 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000627630 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.004633574 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000317778 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.005102296 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000319537 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.005023926 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000298519 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.005084203 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000307834 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.005077203 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000348148 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.005031019 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000447593 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.004933426 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000308574 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.005073055 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000313019 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.005084944 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000296722 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.005070648 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000303278 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.005078741 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000302056 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.005095629 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.000308593 "audio_alsa.c:1695" alsa: error -77 ("File descriptor in bad state") writing 22050 samples to alsa device.
Oct 28 17:08:21 raspberrypi shairport-sync[400]:          0.005060981 "audio_alsa.c:1638" alsa: DAC in odd SND_PCM_STATE_* 0 prior to writing.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000021445 "rtsp.c:463"   Type: "CSeq", content: "4"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016481 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000130000 "rtsp.c:463"   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;tim
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000027574 "rtsp.c:463"   Type: "Session", content: "1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.003297074 "rtsp.c:532" RTSP Message Received: "RECORD rtsp://192.168.0.60/10873050581000930071 RTSP/1.0".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000202815 "rtsp.c:562"     CSeq: 5.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000028945 "rtsp.c:562"     DACP-ID: 850A9F113A46A994.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018463 "rtsp.c:562"     Active-Remote: 2758251862.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018092 "rtsp.c:562"     User-Agent: AirPlay/406.31.21.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020722 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "RECORD":
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016963 "rtsp.c:463"   Type: "CSeq", content: "5"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000143389 "rtsp.c:463"   Type: "DACP-ID", content: "850A9F113A46A994"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018185 "rtsp.c:463"   Type: "Active-Remote", content: "2758251862"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016037 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018463 "rtsp.c:805" Connection 1: RECORD
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000029223 "common.c:1265" mutex_lock "&playing_conn_lock" at "rtsp.c:265".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000156185 "common.c:1290" mutex_unlock "&playing_conn_lock" at "rtsp.c:268".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000032592 "common.c:1265" mutex_lock "&activity_monitor_mutex" at "activity_monitor.c:115".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.005036111 "audio_alsa.c:463" Output written using MMAP
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000067149 "audio_alsa.c:487" *warning: audio_alsa: Channels count (2) not available for device "hw:1": Invalid argument
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000323592 "rtsp.c:2409" Connection 1: RTSP Response:
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000015537 "player.c:1667" No latency has (yet) been specified. Setting 88,200 (2 seconds) frames as a default.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000175334 "rtsp.c:463"   Type: "CSeq", content: "5"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000027592 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017111 "rtsp.c:463"   Type: "Audio-Latency", content: "11025"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.004296037 "rtsp.c:532" RTSP Message Received: "SET_PARAMETER rtsp://192.168.0.60/10873050581000930071 RTSP/1.0".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000064593 "rtsp.c:562"     Content-Length: 20.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020296 "rtsp.c:562"     Content-Type: text/parameters.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019297 "rtsp.c:562"     CSeq: 6.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019666 "rtsp.c:562"     DACP-ID: 850A9F113A46A994.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000021204 "rtsp.c:562"     Active-Remote: 2758251862.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000006685 "rtsp.c:562"     User-Agent: AirPlay/406.31.21.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000024037 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000011852 "player.c:1728" Output frame bytes is 8.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000212018 "rtsp.c:463"   Type: "Content-Length", content: "20"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000039463 "rtsp.c:463"   Type: "Content-Type", content: "text/parameters"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000004075 "player.c:1733" dac_buffer_queue_minimum_length is 5292 frames.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000013296 "rtsp.c:463"   Type: "CSeq", content: "6"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017407 "rtsp.c:463"   Type: "DACP-ID", content: "850A9F113A46A994"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000014334 "player.c:1826" Output bit depth is 32.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000002703 "rtsp.c:463"   Type: "Active-Remote", content: "2758251862"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020482 "player.c:1833" Dithering will be enabled because the output volume is being altered in software
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000047981 "audio_alsa.c:1410" audio_alsa start called.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000022815 "player.c:1899" sync error in milliseconds, net correction in ppm, corrections in ppm, total packets, missing pac
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000086148 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000031037 "rtsp.c:1583" Connection 1: SET_PARAMETER
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000039408 "common.c:1265" mutex_lock "&conn->volume_control_mutex" at "player.c:2730".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000033018 "player.c:2939" player_volume_without_notification: volume mode is 0, airplay volume is -15.000000, software_atte
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000030796 "common.c:1290" mutex_unlock "&conn->volume_control_mutex" at "player.c:2959".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019908 "rtsp.c:2409" Connection 1: RTSP Response:
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017722 "rtsp.c:463"   Type: "CSeq", content: "6"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000197333 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.001184612 "player.c:1951" Set initial volume to -15.000000.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000087444 "common.c:1265" mutex_lock "&conn->volume_control_mutex" at "player.c:2730".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000025352 "player.c:2939" player_volume_without_notification: volume mode is 0, airplay volume is -15.000000, software_atte
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000023500 "common.c:1290" mutex_unlock "&conn->volume_control_mutex" at "player.c:2959".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016611 "player.c:1954" Play begin
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.001123352 "mdns_avahi.c:94" resolve_callback: Service 'iTunes_Ctrl_850A9F113A46A994' of type '_dacp._tcp' in domain 'local'
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000054000 "mdns_avahi.c:100" resolve_callback: client dacp_id "850A9F113A46A994" dacp port: 51107.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.002387259 "rtsp.c:532" RTSP Message Received: "SET_PARAMETER rtsp://192.168.0.60/10873050581000930071 RTSP/1.0".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000063593 "rtsp.c:562"     Content-Length: 20.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019389 "rtsp.c:562"     Content-Type: text/parameters.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018759 "rtsp.c:562"     CSeq: 7.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017463 "rtsp.c:562"     DACP-ID: 850A9F113A46A994.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017518 "rtsp.c:562"     Active-Remote: 2758251862.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018222 "rtsp.c:562"     User-Agent: AirPlay/406.31.21.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000023019 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017963 "rtsp.c:463"   Type: "Content-Length", content: "20"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016630 "rtsp.c:463"   Type: "Content-Type", content: "text/parameters"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000167888 "rtsp.c:463"   Type: "CSeq", content: "7"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017352 "rtsp.c:463"   Type: "DACP-ID", content: "850A9F113A46A994"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016074 "rtsp.c:463"   Type: "Active-Remote", content: "2758251862"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016537 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000027537 "rtsp.c:1583" Connection 1: SET_PARAMETER
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000030926 "common.c:1265" mutex_lock "&conn->volume_control_mutex" at "player.c:2730".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000026334 "player.c:2939" player_volume_without_notification: volume mode is 0, airplay volume is -15.000000, software_atte
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000027296 "common.c:1290" mutex_unlock "&conn->volume_control_mutex" at "player.c:2959".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000120463 "rtsp.c:2409" Connection 1: RTSP Response:
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019167 "rtsp.c:463"   Type: "CSeq", content: "7"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000015944 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.039944407 "rtsp.c:532" RTSP Message Received: "FLUSH rtsp://192.168.0.60/10873050581000930071 RTSP/1.0".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000062500 "rtsp.c:562"     RTP-Info: seq=48518;rtptime=1667774407.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019815 "rtsp.c:562"     CSeq: 8.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017778 "rtsp.c:562"     DACP-ID: 850A9F113A46A994.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017704 "rtsp.c:562"     Active-Remote: 2758251862.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017703 "rtsp.c:562"     User-Agent: AirPlay/406.31.21.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020056 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "FLUSH":
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016685 "rtsp.c:463"   Type: "RTP-Info", content: "seq=48518;rtptime=1667774407"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000016667 "rtsp.c:463"   Type: "CSeq", content: "8"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017315 "rtsp.c:463"   Type: "DACP-ID", content: "850A9F113A46A994"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017963 "rtsp.c:463"   Type: "Active-Remote", content: "2758251862"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017426 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000158129 "rtsp.c:879" Connection 1: FLUSH
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020463 "common.c:1265" mutex_lock "&playing_conn_lock" at "rtsp.c:265".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000020741 "common.c:1290" mutex_unlock "&playing_conn_lock" at "rtsp.c:268".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000034722 "player.c:2981" player_flush
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000018296 "player.c:2969" Flush requested up to 1667774407. It seems as if 0 is special.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000019982 "common.c:1265" mutex_lock "&conn->flush_mutex" at "player.c:2970".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000104926 "common.c:1290" mutex_unlock "&conn->flush_mutex" at "player.c:2976".
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000037111 "player.c:2977" Flush request made.
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017241 "rtsp.c:2409" Connection 1: RTSP Response:
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000015981 "rtsp.c:463"   Type: "CSeq", content: "8"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.000017648 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Oct 28 17:08:20 raspberrypi shairport-sync[400]:          0.003655445 "common.c:1265" mutex_lock "&alsa_mutex" at "audio_alsa.c:1823".

mikebrady commented 5 years ago

Thanks for the logs. A couple of observations.

A log verbosity of 2 or even 1 would be fine – 3 is giving too much detail.
The first sign of the problem is that Shairport Sync is unable to set the output device to have two channels.

You wrote that you can play audio from the Raspberry Pi 4 – could you post the command and any response please? It might help us to figure out what is going on.

ayoubkhayatti commented 5 years ago

Hi @mikebrady,

Thanks for the advice, I'll reduce the verbosity. I'm playing audio from Raspberry pi just using the web browser. So what I did is to select Scarlett by right clicking the sound icon on the bar then playing a video from youtube and that works (I did that to test that the audio actually works via Scarlett).

mikebrady commented 5 years ago

Thanks for the update. It looks like the Scarlett 2i4 is working in a mode that Shairport Sync can not use. For Shairport Sync, it must be configurable to 44,100 samples per second, interleaved stereo, 16, 24 or 32 bits per sample. Due to work commitments, it will be about ten days before I can get back to any of this. Meanwhile, does the GUI allow you to find out what mode the output device is running in? For example is the rate available?

ayoubkhayatti commented 5 years ago

Thanks a lot @mikebrady. no, neither GUI or alsamixer shows the output device mode. Later today, I'll try to install pulseAudio because it seems that it can get the sampling rate. I found this command: pactl list short sinks, will see if that will work.

ayoubkhayatti commented 5 years ago

I installed pluse audio and gave me this output:

pactl list short sinks
0   alsa_output.usb-Focusrite_Scarlett_2i4_USB-00.analog-surround-40    module-alsa-card.c  s32le 4ch 44100Hz   IDLE
1   alsa_output.platform-soc_audio.analog-mono  module-alsa-card.c  s16le 1ch 44100Hz   IDLE

so it is 44100!

Got some logs by just lowering the log level (maybe they make more sense now):

Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000112795 "rtsp.c:463"   Type: "Content-Length", content: "657"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000047259 "rtsp.c:463"   Type: "Content-Type", content: "application/sdp"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000043537 "rtsp.c:463"   Type: "CSeq", content: "3"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000041445 "rtsp.c:463"   Type: "DACP-ID", content: "EBE0603E5BD537F5"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000040296 "rtsp.c:463"   Type: "Active-Remote", content: "4184769503"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000039463 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.048978645 "rtsp.c:1934" Play connection from user agent "AirPlay/406.31.21" on RTSP conversation thread 1.
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000102147 "rtsp.c:1943" AirPlay version 406 detected.
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000044982 "rtsp.c:2409" Connection 1: RTSP Response:
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000041925 "rtsp.c:463"   Type: "CSeq", content: "3"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000040074 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.081471212 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "SETUP":
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000056315 "rtsp.c:463"   Type: "Transport", content: "RTP/AVP/UDP;unicast;mode=record;timing_port=49927;control_port=65305"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000019685 "rtsp.c:463"   Type: "CSeq", content: "4"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000016963 "rtsp.c:463"   Type: "DACP-ID", content: "EBE0603E5BD537F5"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000016185 "rtsp.c:463"   Type: "Active-Remote", content: "4184769503"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000015833 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000020333 "rtsp.c:920" Connection 1: SETUP -- Active-Remote string seen: "4184769503".
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000033723 "rtsp.c:935" Connection 1: SETUP -- DACP-ID string seen: "EBE0603E5BD537F5".
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000024685 "rtp.c:981" Connection 1: SETUP -- Connection from 192.168.0.21 to self at 192.168.0.60.
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000137814 "rtsp.c:1000" Connection 1: SETUP DACP-ID "EBE0603E5BD537F5" from 192.168.0.21 to 192.168.0.60 with UDP ports Contr
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000027389 "rtsp.c:2409" Connection 1: RTSP Response:
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000016370 "rtsp.c:463"   Type: "CSeq", content: "4"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000015296 "rtsp.c:463"   Type: "Server", content: "AirTunes/105.1"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000015389 "rtsp.c:463"   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timin
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000016111 "rtsp.c:463"   Type: "Session", content: "1"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.016441431 "rtsp.c:2366" Connection 1: Received an RTSP Packet of type "RECORD":
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000047944 "rtsp.c:463"   Type: "CSeq", content: "5"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000017370 "rtsp.c:463"   Type: "DACP-ID", content: "EBE0603E5BD537F5"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000016074 "rtsp.c:463"   Type: "Active-Remote", content: "4184769503"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000015556 "rtsp.c:463"   Type: "User-Agent", content: "AirPlay/406.31.21"
Nov 02 15:01:01 raspberrypi shairport-sync[423]:          0.000018759 "rtsp.c:805" Connection 1: RECORD

ayoubkhayatti commented 5 years ago

Why it tries to create something under home anyways? Also it seems that it doesn't like hw:1?

Nov 02 15:42:00 raspberrypi shairport-sync[435]: Failed to create secure directory (/home/shairport-sync/.config/pulse): No such file or directory
Nov 02 15:42:00 raspberrypi shairport-sync[435]:          0.015581482 "audio_alsa.c:487" *warning: audio_alsa: Channels count (2) not available for device "hw:1": Invalid argument

ayoubkhayatti commented 5 years ago

It's working now. so the way I've solved it is to select my usb device from GUI. Then I actually installed pulseAudio so I can get the sample rate of my usb device, that also changed my output when I enter alsamixer, now I actually pulseAudio there.

Then I changed my configuration for shairport-sync to the following:

//      output_device = "hw:1,0"; // the name of the alsa output device. Use "alsamixer" or "aplay" to find out the names of devices, mixers, etc.
//      mixer_control_name = "PCM"; // the name of the mixer to use to adjust output volume. If not specified, volume in adjusted in software.
//      mixer_device = "default"; // the mixer_device default is whatever the output_device is. Normally you wouldn't have to use this.
        output_rate = 44100; // can be "auto", 44100, 88200, 176400 or 352800, but the device must have the capability.
        output_format = "S32_LE"`

So I disabled output_device and mixer_control and enabled the output rate and format based on the output of pactl list short sinks. It's work notice that my alsa config specifies my usb device as default that might have contributed to the issue.

mikebrady commented 5 years ago

Thanks for the updates. As far as I can see, the following is the case:

The Scarlett 2i4 can operate at 44,100 FPS in mono or in four-channel mode only. It can not operate in stereo, hence Shairport Sync can not drive it via the usual alsa backend.
The PulseAudio subsystem can drive the Scarlett 2i4 and can offer a 44,100cinterfsce to Shairport Sync. Thus, if you use the Shairport Sync pa backend, then pulse audio can take care of converting to the appropriate format for the Scarlett device.
The PulseAudio subsystem seems to try to generate configuration files, but that’s nothing to do with Shairport Sync.
If you do use the pa backend, then none of the alsa settings have any significance.

Does that summarize it, do you think?

ayoubkhayatti commented 5 years ago

Hi @mikebrady,

That's a good summary and maybe Shairport Sync should recommend PulseAudio in cases like mine.

Thanks for you help, this thread can be closed.

mikebrady commented 5 years ago

Many thanks indeed.

mikebrady / shairport-sync

Cannot play audio on a usb device #923