Closed VirtualWolf closed 3 years ago
mikebrady
commented
3 years ago That’s a mystery alright. The output device is “default”; I wonder if it is possible that it’s no longer pointing to the correct output device or is faulty in some way.
If you do $ shairport-sync -h, you should get a list of the real hardware output devices. Try setting the output to one of them?
mikebrady
commented
3 years ago If you have PulseAudio installed, there is a good chance that the alsa default device is in fact a pseudo device that actually takes audio into the PulseAudio system. Is that the case here?
VirtualWolf
commented
3 years ago No dice, I'm afraid. shairport-sync -h returned this at the bottom:
hardware output devices:
"hw:sndrpijustboomd"So I updated shairport-sync.conf (it contains nothing else but these lines):
alsa =
{
output_device = "hw:sndrpijustboomd"
}And PulseAudio isn't installed at all it seems:
[pi@fourbee:~]$ which pactl
[pi@fourbee:~]$ dpkg -s pulseaudio
dpkg-query: package 'pulseaudio' is not installed and no information is available
Use dpkg --info (= dpkg-deb --info) to examine archive files.[pi@fourbee:~]$ shairport-sync -vv -u
0.000233312 "shairport.c:461" looking for configuration file at full path "/etc/shairport-sync.conf"
0.000653122 "shairport.c:1729" Started!
0.000170720 "shairport.c:1756" software version: "3.3.8rc2-alac-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
0.000173480 "shairport.c:1762" log verbosity is 2.
0.000161794 "audio_alsa.c:998" alsa: init() -- alsa_backend_state => abm_disconnected.
0.000296237 "audio_alsa.c:1015" alsa: alsa_maximum_stall_time of 0.200000 sec.
0.000642900 "audio_alsa.c:1302" alsa: disable_standby_mode is "never".
0.000150406 "audio_alsa.c:1304" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
0.000100054 "audio_alsa.c:1306" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
0.000376033 "audio_alsa.c:1345" alsa: output device name is "hw:sndrpijustboomd".
0.000339959 "shairport.c:1777" The processor is running little-endian.
0.000061073 "shairport.c:1810" disable resend requests is off.
0.000098295 "shairport.c:1814" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
0.000101406 "shairport.c:1815" statistics_requester status is 0.
0.000096740 "shairport.c:1820" rtsp listening port is 5000.
0.000105610 "shairport.c:1821" udp base port is 6001.
0.000094684 "shairport.c:1822" udp port range is 10.
0.000093999 "shairport.c:1823" player name is "Fourbee".
0.000094369 "shairport.c:1824" backend is "alsa".
0.000095425 "shairport.c:1825" run_this_before_play_begins action is "(null)".
0.000095869 "shairport.c:1826" run_this_after_play_ends action is "(null)".
0.000103499 "shairport.c:1827" wait-cmd status is 0.
0.000095406 "shairport.c:1828" run_this_before_play_begins may return output is 0.
0.000095036 "shairport.c:1829" run_this_if_an_unfixable_error_is_detected action is "(null)".
0.000096295 "shairport.c:1830" run_this_before_entering_active_state action is "(null)".
0.000094925 "shairport.c:1831" run_this_after_exiting_active_state action is "(null)".
0.000094925 "shairport.c:1832" active_state_timeout is 10.000000 seconds.
0.000108888 "shairport.c:1833" mdns backend "(null)".
0.000095536 "shairport.c:1834" userSuppliedLatency is 0.
0.000154294 "shairport.c:1837" interpolation setting is "auto".
0.000055944 "audio_alsa.c:1943" keep_dac_busy is now "no"
0.000325663 "shairport.c:1838" interpolation soxr_delay_threshold is 30.
0.000395699 "shairport.c:1839" resync time is 0.050000 seconds.
0.000048222 "shairport.c:1840" allow a session to be interrupted: 0.
0.000040814 "shairport.c:1841" busy timeout time is 120.
0.000037518 "shairport.c:1842" drift tolerance is 0.001995 seconds.
0.000038222 "shairport.c:1843" password is "(null)".
0.000040518 "shairport.c:1844" ignore_volume_control is 0.
0.000200701 "shairport.c:1848" volume_max_db is not set
0.000045537 "shairport.c:1850" volume range in dB (zero means use the range specified by the mixer): 0.
0.000243738 "shairport.c:1854" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
0.000200275 "shairport.c:1856" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
0.000198998 "shairport.c:1857" disable_synchronization is 0.
0.000197257 "shairport.c:1858" use_mmap_if_available is 1.
0.000238886 "shairport.c:1860" output_format automatic selection is enabled.
0.000195405 "shairport.c:1864" output_rate automatic selection is enabled.
0.000203701 "shairport.c:1868" audio backend desired buffer length is 0.200000 seconds.
0.000117351 "shairport.c:1870" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
0.000269311 "shairport.c:1871" audio backend latency offset is 0.000000 seconds.
0.000128666 "shairport.c:1873" audio backend silence lead-in time is "auto".
0.000109239 "shairport.c:1877" zeroconf regtype is "_raop._tcp".
0.000127221 "shairport.c:1878" decoders_supported field is 3.
0.000136813 "shairport.c:1879" use_apple_decoder is 1.
0.000097795 "shairport.c:1880" alsa_use_hardware_mute is 0.
0.000095814 "shairport.c:1884" no special mdns service interface was requested.
0.000173942 "shairport.c:1888" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
0.000093647 "shairport.c:1917" loudness is 0.
0.000040518 "shairport.c:1918" loudness reference level is -20.000000
0.011660012 "mdns_avahi.c:209" avahi: service 'F92AD404701A@Fourbee' group is not yet committed.
0.002724116 "mdns_avahi.c:251" avahi: request to add "_raop._tcp" service without metadata
0.002000477 "mdns_avahi.c:375" avahi_dacp_monitor_start Avahi DACP monitor successfully started
0.000466105 "mdns_avahi.c:213" avahi: service 'F92AD404701A@Fourbee' group is registering.
0.905280031 "mdns_avahi.c:180" avahi: service 'F92AD404701A@Fourbee' successfully added.
0.579465566 "shairport.c:194" soxr_delay_index: 3.
0.000084647 "shairport.c:201" "soxr" interpolation has been chosen.121.924080112 "rtsp.c:2997" Connection 1: new connection from [<IPv6 address of iPhone>]:60494 to self at [<IPv6 address of Raspberry Pi>]:5000.
7.493362476 "rtsp.c:2661" Connection 1: Received an RTSP Packet of type "ANNOUNCE":
0.000146739 "rtsp.c:507" Type: "Content-Length", content: "696"
0.000090814 "rtsp.c:507" Type: "Content-Type", content: "application/sdp"
0.000192664 "rtsp.c:507" Type: "CSeq", content: "4"
0.000286348 "rtsp.c:507" Type: "DACP-ID", content: "F14BD33FB5605B90"
0.000083759 "rtsp.c:507" Type: "Active-Remote", content: "625179279"
0.000489809 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.024098470 "rtsp.c:2223" Play connection from user agent "AirPlay/530.6" on RTSP conversation thread 1.
0.000119295 "rtsp.c:2232" AirPlay version 530 detected.
0.000087258 "rtsp.c:2704" Connection 1: RTSP Response:
0.000540512 "rtsp.c:507" Type: "CSeq", content: "4"
0.000094592 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.007224672 "rtsp.c:2661" Connection 1: Received an RTSP Packet of type "SETUP":
0.000101036 "rtsp.c:507" Type: "Transport", content: "RTP/AVP/UDP;unicast;mode=record;timing_port=49407;control_port=64058"
0.000086333 "rtsp.c:507" Type: "CSeq", content: "5"
0.000067869 "rtsp.c:507" Type: "DACP-ID", content: "F14BD33FB5605B90"
0.000034629 "rtsp.c:507" Type: "Active-Remote", content: "625179279"
0.000031944 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.000037574 "rtsp.c:976" Connection 1: SETUP -- Active-Remote string seen: "625179279".
0.000065684 "rtsp.c:995" Connection 1: SETUP -- DACP-ID string seen: "F14BD33FB5605B90".
0.000053389 "rtp.c:968" Connection 1: SETUP -- Connection from <IPv6 address of iPhone> to self at <IPv6 address of Raspberry Pi>.
0.000163572 "rtsp.c:1062" Connection 1: SETUP DACP-ID "F14BD33FB5605B90" from <IPv6 address of iPhone> to <IPv6 address of Raspberry Pi> with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
0.000044999 "rtsp.c:2704" Connection 1: RTSP Response:
0.000078073 "rtsp.c:507" Type: "CSeq", content: "5"
0.000082018 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.000080480 "rtsp.c:507" Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002;server_port=6003"
0.000083999 "rtsp.c:507" Type: "Session", content: "1"
0.007435411 "rtsp.c:2661" Connection 1: Received an RTSP Packet of type "RECORD":
0.000099073 "rtsp.c:507" Type: "CSeq", content: "6"
0.000084166 "rtsp.c:507" Type: "DACP-ID", content: "F14BD33FB5605B90"
0.000098054 "rtsp.c:507" Type: "Active-Remote", content: "625179279"
0.000082444 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.000084184 "rtsp.c:855" Connection 1: RECORD
0.008976355 "audio_alsa.c:529" alsa: output format chosen is "S32".
0.000104351 "audio_alsa.c:569" alsa: output speed chosen is 44100.
0.030761539 "audio_alsa.c:1492" alsa: update timestamps available
0.000039148 "audio_alsa.c:226" alsa: precision delay timing is available.
0.000017222 "audio_alsa.c:721" alsa: precision timing selected for "auto" mode
0.000016333 "audio_alsa.c:738" PCM handle name = 'hw:sndrpijustboomd'
0.000015407 "audio_alsa.c:752" alsa device parameters:
0.000019129 "audio_alsa.c:755" access type = MMAP_INTERLEAVED
0.000020945 "audio_alsa.c:759" format = 'S32_LE' (Signed 32 bit Little Endian)
0.000021184 "audio_alsa.c:763" subformat = 'STD' (Standard)
0.000018241 "audio_alsa.c:766" number of channels = 2
0.000017092 "audio_alsa.c:769" number of significant bits = 32
0.000017074 "audio_alsa.c:777" rate = 44100 frames per second (precisely).
0.000017667 "audio_alsa.c:786" precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
0.000022833 "audio_alsa.c:799" period_time = 5804 us (>).
0.000017574 "audio_alsa.c:809" period_size = 256 frames (precisely).
0.000017685 "audio_alsa.c:825" buffer_time = 1486077 us (>).
0.000016185 "audio_alsa.c:838" buffer_size = 65536 frames (>).
0.000016981 "audio_alsa.c:848" periods_per_buffer = 256 (precisely).
0.000015833 "audio_alsa.c:1816" alsa: prepare() -- opened output device
0.000038296 "audio_alsa.c:1965" alsa: alsa_buffer_monitor_thread_code() -- closing the output device
0.000096702 "rtsp.c:2704" Connection 1: RTSP Response:
0.000021130 "rtsp.c:507" Type: "CSeq", content: "6"
0.000015055 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.000014130 "rtsp.c:507" Type: "Audio-Latency", content: "11025"
0.005927392 "player.c:2004" Set initial volume to -18.000000.
0.000103424 "loudness.c:47" Volume: -37.6 dB - Loudness gain @10Hz: 8.8 dB
0.000023963 "player.c:3051" player_volume_without_notification: volume mode is 0, airplay volume is -18.000000, software_attenuation: -3755.700000, hardware_attenuation: 0.000000, muting is disabled.
0.000024296 "player.c:2007" Play begin
0.000574734 "audio_alsa.c:1754" alsa: do_close() -- closing alsa handle
0.000945359 "audio_alsa.c:1968" alsa: alsa_buffer_monitor_thread_code() -- alsa_backend_state => abm_disconnected
0.003108611 "rtsp.c:2661" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
0.000039944 "rtsp.c:507" Type: "Content-Length", content: "20"
0.000019185 "rtsp.c:507" Type: "Content-Type", content: "text/parameters"
0.000016055 "rtsp.c:507" Type: "CSeq", content: "7"
0.000014981 "rtsp.c:507" Type: "DACP-ID", content: "F14BD33FB5605B90"
0.000015982 "rtsp.c:507" Type: "Active-Remote", content: "625179279"
0.000014740 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.000045240 "loudness.c:47" Volume: -43.3 dB - Loudness gain @10Hz: 11.7 dB
0.000022296 "player.c:3051" 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.000022296 "rtsp.c:2704" Connection 1: RTSP Response:
0.000015704 "rtsp.c:507" Type: "CSeq", content: "7"
0.000014629 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.036401435 "player.c:238" Apple ALAC Decoder used on encrypted audio.
0.000480994 "player.c:1110" first_packet_time set for frame 2395701290.
0.000782102 "rtsp.c:2661" Connection 1: Received an RTSP Packet of type "FLUSH":
0.000029796 "rtsp.c:507" Type: "RTP-Info", content: "seq=62033;rtptime=2395701290"
0.000017925 "rtsp.c:507" Type: "CSeq", content: "8"
0.000018704 "rtsp.c:507" Type: "DACP-ID", content: "F14BD33FB5605B90"
0.000015111 "rtsp.c:507" Type: "Active-Remote", content: "625179279"
0.000015333 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.000029814 "player.c:3078" do_flush: flush to 2395701290.
0.000022519 "rtsp.c:2704" Connection 1: RTSP Response:
0.000014592 "rtsp.c:507" Type: "CSeq", content: "8"
0.000015685 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.021149006 "rtsp.c:2661" Connection 1: Received an RTSP Packet of type "FLUSH":
0.000035463 "rtsp.c:507" Type: "RTP-Info", content: "seq=62035;rtptime=2395707826"
0.000015499 "rtsp.c:507" Type: "CSeq", content: "9"
0.000013722 "rtsp.c:507" Type: "DACP-ID", content: "F14BD33FB5605B90"
0.000013760 "rtsp.c:507" Type: "Active-Remote", content: "625179279"
0.000013388 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.000021444 "player.c:3078" do_flush: flush to 2395707826.
0.000021648 "rtsp.c:2704" Connection 1: RTSP Response:
0.000013982 "rtsp.c:507" Type: "CSeq", content: "9"
0.000013537 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.002929853 "audio_alsa.c:721" alsa: precision timing selected for "auto" mode
0.000041518 "audio_alsa.c:1780" alsa: play() -- opened output device
0.000021463 "audio_alsa.c:1785" alsa: play() -- alsa_backend_state => abm_playing
0.000417625 "audio_alsa.c:1836" alsa: flush() -- closing the output device
0.006708530 "audio_alsa.c:1754" alsa: do_close() -- closing alsa handle
0.000866509 "audio_alsa.c:1838" alsa: flush() -- alsa_backend_state => abm_disconnected.
0.000040110 "player.c:945" flush request: flush output device.
0.000017389 "player.c:997" flush request: flush frame 2395707826 pending -- buffer contains 704 frames, from 2395701290 to 2395701993
0.000017574 "player.c:1020" flush request: flush done.
0.000130665 "player.c:997" flush request: flush frame 2395707826 pending -- buffer contains 704 frames, from 2395702314 to 2395703017
0.000022037 "player.c:1020" flush request: flush done.
0.010725556 "player.c:997" flush request: flush frame 2395707826 pending -- buffer contains 352 frames, from 2395703018 to 2395703369
0.000022556 "player.c:1020" flush request: flush done.
0.000155887 "player.c:997" flush request: flush frame 2395707826 pending -- buffer contains 704 frames, from 2395703370 to 2395704073
0.000019240 "player.c:1020" flush request: flush done.
0.023166889 "player.c:997" flush request: flush frame 2395707826 pending -- buffer contains 352 frames, from 2395704074 to 2395704425
0.000205683 "player.c:1020" flush request: flush done.
0.000154646 "player.c:997" flush request: flush frame 2395707826 pending -- buffer contains 704 frames, from 2395704426 to 2395705129
0.000095110 "player.c:1020" flush request: flush done.
0.022335788 "player.c:997" flush request: flush frame 2395707826 pending -- buffer contains 352 frames, from 2395705130 to 2395705481
0.000024611 "player.c:1020" flush request: flush done.
0.000399514 "player.c:997" flush request: flush frame 2395707826 pending -- buffer contains 704 frames, from 2395705482 to 2395706185
0.000065388 "player.c:1020" flush request: flush done.
0.023523144 "player.c:997" flush request: flush frame 2395707826 pending -- buffer contains 352 frames, from 2395706186 to 2395706537
0.000067425 "player.c:1020" flush request: flush done.
0.000369829 "player.c:997" flush request: flush frame 2395707826 pending -- buffer contains 704 frames, from 2395706538 to 2395707241
0.000064296 "player.c:1020" flush request: flush done.
0.021823942 "player.c:997" flush request: flush frame 2395707826 pending -- buffer contains 352 frames, from 2395707242 to 2395707593
0.000161109 "player.c:1020" flush request: flush done.
0.000231108 "player.c:989" flush request: flush frame 2395707826 active -- buffer contains 704 frames, from 2395707594 to 2395708297
0.000045926 "player.c:1020" flush request: flush done.
0.000042425 "player.c:1029" flush request: request dropped.
0.022509657 "player.c:1110" first_packet_time set for frame 2395708298.
0.025207531 "audio_alsa.c:721" alsa: precision timing selected for "auto" mode
0.000063907 "audio_alsa.c:1780" alsa: play() -- opened output device
0.000040573 "audio_alsa.c:1785" alsa: play() -- alsa_backend_state => abm_playing
0.080210706 "player.c:1175" Change in estimated first_packet_time: -0.6035 milliseconds.
1.783537390 "player.c:2288" first frame sync error (positive --> late): -3 frames, -0.068 mS at 44100 frames per second output.
0.000085851 "player.c:2305" final sync adjustment: 11 silent frames added with a bias of 8 frames.
5.122507928 "rtsp.c:2661" Connection 1: Received an RTSP Packet of type "TEARDOWN":
0.000076648 "rtsp.c:507" Type: "CSeq", content: "13"
0.000038981 "rtsp.c:507" Type: "DACP-ID", content: "F14BD33FB5605B90"
0.000046332 "rtsp.c:507" Type: "Active-Remote", content: "625179279"
0.000040055 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.000046722 "rtsp.c:911" Connection 1: TEARDOWN
0.000181757 "audio_alsa.c:1836" alsa: flush() -- closing the output device
0.009220501 "audio_alsa.c:1754" alsa: do_close() -- closing alsa handle
0.002166844 "audio_alsa.c:1838" alsa: flush() -- alsa_backend_state => abm_disconnected.
0.001737905 "rtsp.c:2704" Connection 1: RTSP Response:
0.000056259 "rtsp.c:507" Type: "CSeq", content: "13"
0.000052462 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.000039611 "rtsp.c:507" Type: "Connection", content: "close"
0.010808907 "rtsp.c:2595" Connection 1: terminated.
3.772847540 "rtsp.c:2997" Connection 2: new connection from [<IPv6 address of iPhone>]:60495 to self at [<IPv6 address of Raspberry Pi>]:5000.
0.047820667 "rtsp.c:2661" Connection 2: Received an RTSP Packet of type "ANNOUNCE":
0.000130776 "rtsp.c:507" Type: "Content-Length", content: "696"
0.000045314 "rtsp.c:507" Type: "Content-Type", content: "application/sdp"
0.000039629 "rtsp.c:507" Type: "CSeq", content: "3"
0.000038870 "rtsp.c:507" Type: "DACP-ID", content: "F14BD33FB5605B90"
0.000038074 "rtsp.c:507" Type: "Active-Remote", content: "625179279"
0.000126720 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.021049803 "rtsp.c:2223" Play connection from user agent "AirPlay/530.6" on RTSP conversation thread 2.
0.000043074 "rtsp.c:2232" AirPlay version 530 detected.
0.000033944 "rtsp.c:2704" Connection 2: RTSP Response:
0.000026666 "rtsp.c:507" Type: "CSeq", content: "3"
0.000025982 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.007611427 "rtsp.c:2661" Connection 2: Received an RTSP Packet of type "SETUP":
0.000036314 "rtsp.c:507" Type: "Transport", content: "RTP/AVP/UDP;unicast;mode=record;timing_port=63916;control_port=50307"
0.000027537 "rtsp.c:507" Type: "CSeq", content: "4"
0.000024722 "rtsp.c:507" Type: "DACP-ID", content: "F14BD33FB5605B90"
0.000026444 "rtsp.c:507" Type: "Active-Remote", content: "625179279"
0.000024611 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.000031333 "rtsp.c:976" Connection 2: SETUP -- Active-Remote string seen: "625179279".
0.000098776 "rtsp.c:995" Connection 2: SETUP -- DACP-ID string seen: "F14BD33FB5605B90".
0.000082647 "rtp.c:968" Connection 2: SETUP -- Connection from <IPv6 address of iPhone> to self at <IPv6 address of Raspberry Pi>.
0.000162998 "rtsp.c:1062" Connection 2: SETUP DACP-ID "F14BD33FB5605B90" from <IPv6 address of iPhone> to <IPv6 address of Raspberry Pi> with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
0.000076685 "rtsp.c:2704" Connection 2: RTSP Response:
0.000065684 "rtsp.c:507" Type: "CSeq", content: "4"
0.000058518 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.000063055 "rtsp.c:507" Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002;server_port=6003"
0.000065462 "rtsp.c:507" Type: "Session", content: "1"
0.005947725 "rtsp.c:2661" Connection 2: Received an RTSP Packet of type "RECORD":
0.000076054 "rtsp.c:507" Type: "CSeq", content: "5"
0.000064944 "rtsp.c:507" Type: "DACP-ID", content: "F14BD33FB5605B90"
0.000081962 "rtsp.c:507" Type: "Active-Remote", content: "625179279"
0.000063481 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.000066925 "rtsp.c:855" Connection 2: RECORD
0.001906014 "audio_alsa.c:529" alsa: output format chosen is "S32".
0.000113295 "audio_alsa.c:569" alsa: output speed chosen is 44100.
0.026094743 "audio_alsa.c:721" alsa: precision timing selected for "auto" mode
0.000097091 "audio_alsa.c:1816" alsa: prepare() -- opened output device
0.000087017 "audio_alsa.c:1965" alsa: alsa_buffer_monitor_thread_code() -- closing the output device
0.000171850 "rtsp.c:2704" Connection 2: RTSP Response:
0.000074277 "rtsp.c:507" Type: "CSeq", content: "5"
0.000064907 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.000064036 "rtsp.c:507" Type: "Audio-Latency", content: "11025"
0.002828151 "player.c:2004" Set initial volume to -20.000000.
0.000239479 "loudness.c:47" Volume: -43.3 dB - Loudness gain @10Hz: 11.7 dB
0.000040610 "player.c:3051" 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.000169184 "player.c:2007" Play begin
0.004510297 "audio_alsa.c:1754" alsa: do_close() -- closing alsa handle
0.001370873 "audio_alsa.c:1968" alsa: alsa_buffer_monitor_thread_code() -- alsa_backend_state => abm_disconnected
0.023331683 "player.c:238" Apple ALAC Decoder used on encrypted audio.
0.000282811 "player.c:1110" first_packet_time set for frame 3294319241.
0.002046272 "rtsp.c:2661" Connection 2: Received an RTSP Packet of type "FLUSH":
0.000043129 "rtsp.c:507" Type: "RTP-Info", content: "seq=18828;rtptime=3294319241"
0.000027648 "rtsp.c:507" Type: "CSeq", content: "6"
0.000026000 "rtsp.c:507" Type: "DACP-ID", content: "F14BD33FB5605B90"
0.000025573 "rtsp.c:507" Type: "Active-Remote", content: "625179279"
0.000025093 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.000035388 "player.c:3078" do_flush: flush to 3294319241.
0.000035629 "rtsp.c:2704" Connection 2: RTSP Response:
0.000025185 "rtsp.c:507" Type: "CSeq", content: "6"
0.000024444 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.027303580 "audio_alsa.c:721" alsa: precision timing selected for "auto" mode
0.000053592 "audio_alsa.c:1780" alsa: play() -- opened output device
0.000195498 "audio_alsa.c:1785" alsa: play() -- alsa_backend_state => abm_playing
0.000804360 "audio_alsa.c:1836" alsa: flush() -- closing the output device
0.007922183 "audio_alsa.c:1754" alsa: do_close() -- closing alsa handle
0.001567000 "audio_alsa.c:1838" alsa: flush() -- alsa_backend_state => abm_disconnected.
0.000040074 "player.c:945" flush request: flush output device.
0.000153109 "player.c:1005" flush request: flush frame 3294319241 expired -- buffer contains 704 frames, from 3294319241 to 3294319944
0.000152498 "player.c:1029" flush request: request dropped.
0.000168498 "player.c:1252" Unexpected response to getting dac delay: 19.
<Another 500-odd of this same line repeated>
0.001496482 "player.c:1181" Gone past starting time by 1002147 nanoseconds.
0.030436413 "audio_alsa.c:721" alsa: precision timing selected for "auto" mode
0.000064369 "audio_alsa.c:1780" alsa: play() -- opened output device
0.000035037 "audio_alsa.c:1785" alsa: play() -- alsa_backend_state => abm_playing
0.002167863 "player.c:2288" first frame sync error (positive --> late): 1391 frames, 31.542 mS at 44100 frames per second output.
4.121562237 "rtsp.c:2661" Connection 2: Received an RTSP Packet of type "FLUSH":
0.000060814 "rtsp.c:507" Type: "RTP-Info", content: "seq=19601;rtptime=3294597137"
0.000053148 "rtsp.c:507" Type: "CSeq", content: "10"
0.000036666 "rtsp.c:507" Type: "DACP-ID", content: "F14BD33FB5605B90"
0.000033296 "rtsp.c:507" Type: "Active-Remote", content: "625179279"
0.000031963 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.000042851 "player.c:3078" do_flush: flush to 3294597137.
0.000044537 "rtsp.c:2704" Connection 2: RTSP Response:
0.000031888 "rtsp.c:507" Type: "CSeq", content: "10"
0.000031389 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.000617585 "audio_alsa.c:1836" alsa: flush() -- closing the output device
0.008680358 "audio_alsa.c:1754" alsa: do_close() -- closing alsa handle
0.001923292 "audio_alsa.c:1838" alsa: flush() -- alsa_backend_state => abm_disconnected.
0.000136591 "player.c:945" flush request: flush output device.
0.000134721 "player.c:997" flush request: flush frame 3294597137 pending -- buffer contains 80896 frames, from 3294511433 to 3294592328
0.000193516 "player.c:1020" flush request: flush done.
0.011188588 "player.c:997" flush request: flush frame 3294597137 pending -- buffer contains 1056 frames, from 3294592329 to 3294593384
0.000102406 "player.c:1020" flush request: flush done.
0.023507699 "player.c:997" flush request: flush frame 3294597137 pending -- buffer contains 1056 frames, from 3294593385 to 3294594440
0.000103203 "player.c:1020" flush request: flush done.
0.023092056 "player.c:997" flush request: flush frame 3294597137 pending -- buffer contains 1056 frames, from 3294594441 to 3294595496
0.000102387 "player.c:1020" flush request: flush done.
0.023506088 "player.c:997" flush request: flush frame 3294597137 pending -- buffer contains 352 frames, from 3294595497 to 3294595848
0.000098647 "player.c:1020" flush request: flush done.
0.001439390 "player.c:997" flush request: flush frame 3294597137 pending -- buffer contains 704 frames, from 3294595849 to 3294596552
0.000098499 "player.c:1020" flush request: flush done.
0.022790856 "player.c:989" flush request: flush frame 3294597137 active -- buffer contains 1056 frames, from 3294596553 to 3294597608
0.000053629 "player.c:1020" flush request: flush done.
0.000045685 "player.c:1029" flush request: request dropped.
0.021662221 "player.c:1110" first_packet_time set for frame 3294597609.
0.033142120 "audio_alsa.c:721" alsa: precision timing selected for "auto" mode
0.000063222 "audio_alsa.c:1780" alsa: play() -- opened output device
0.000035240 "audio_alsa.c:1785" alsa: play() -- alsa_backend_state => abm_playing
1.545018276 "player.c:1175" Change in estimated first_packet_time: -0.0060 milliseconds.
5.411934553 "rtsp.c:2661" Connection 2: Received an RTSP Packet of type "TEARDOWN":
0.000077925 "rtsp.c:507" Type: "CSeq", content: "14"
0.000056481 "rtsp.c:507" Type: "DACP-ID", content: "F14BD33FB5605B90"
0.000039018 "rtsp.c:507" Type: "Active-Remote", content: "625179279"
0.000038148 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.000045666 "rtsp.c:911" Connection 2: TEARDOWN
0.000333329 "audio_alsa.c:1836" alsa: flush() -- closing the output device
0.009212149 "audio_alsa.c:1754" alsa: do_close() -- closing alsa handle
0.002156029 "audio_alsa.c:1838" alsa: flush() -- alsa_backend_state => abm_disconnected.
0.001685239 "rtsp.c:2704" Connection 2: RTSP Response:
0.000060574 "rtsp.c:507" Type: "CSeq", content: "14"
0.000038536 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.000038222 "rtsp.c:507" Type: "Connection", content: "close"
0.008815339 "rtsp.c:2595" Connection 2: terminated.The double-playback there is because I hit play on the iPhone and it started and then immediately stopped again. I pressed it a second time and it started playing.
mikebrady
commented
3 years ago Thanks. It’s a real puzzle. I notice that Shairport Sync didn’t pick up the built-in DAC as an output device, so I guess you have disabled it in the /boot/config.txt file? If so, and this is a long shot, would it be worth reinstating it to the way is was before, but with the JustBoom overlay activated as well? (FYI, I never disable the built-in audio stuff on a Pi.)
The last part of my /boot/config.txt file is:
# Additional overlays and parameters are documented /boot/overlays/README
# Enable audio (loads snd_bcm2835)
dtparam=audio=on
[pi4]
# Enable DRM VC4 V3D driver on top of the dispmanx display stack
dtoverlay=vc4-fkms-v3d
max_framebuffers=2
[all]
#dtoverlay=vc4-fkms-v3d
gpu_mem=16Besides, it would be nice to have the default audio to check against.
mikebrady
commented
3 years ago Just looking at your log, what is very odd is this sequence:
0.000169184 "player.c:2007" Play begin
0.004510297 "audio_alsa.c:1754" alsa: do_close() -- closing alsa handle
0.001370873 "audio_alsa.c:1968" alsa: alsa_buffer_monitor_thread_code() -- alsa_backend_state => abm_disconnectedSomething is persuading Shairport Sync to close the link to the output device very shortly after attempting to start to play. Here is what happens on a Pi4 on the built-in DAC:
0.000024254 "player.c:2007" Play begin
0.016453725 "rtsp.c:2661" Connection 1: Received an RTSP Packet of type "SET_PARAMETER":
0.000052950 "rtsp.c:507" Type: "Content-Length", content: "20"
0.000039435 "rtsp.c:507" Type: "Content-Type", content: "text/parameters"
0.000065466 "rtsp.c:507" Type: "CSeq", content: "7"
0.000017366 "rtsp.c:507" Type: "DACP-ID", content: "FE378CFB29E8354B"
0.000064929 "rtsp.c:507" Type: "Active-Remote", content: "1187847416"
0.000017311 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"As you can see, it’s not trying to close the device. If you could set the verbosity to -vvv, and just capture and paste the section around the Play begin message (it’s very verbose, so a small extract will be fine!), if might reveal something.
VirtualWolf
commented
3 years ago Re-enabling the built-in DAC audio overlay with dtparam=audio-on doesn't result in any change to shairplay-sync but it does stop the JustBoom from outputting any sound! I tested with a headphone cable plugged directly into the built-in jack on the Pi and it's the same behaviour as with the JustBoom... speaker-test works fine, but I get no audio from shairplay-sync.
Just for good measure I disabled the JustBoom overlay and left only the built-in DAC enabled, but it made no difference:
# Enable audio (loads snd_bcm2835)
dtparam=audio=on
#dtparam=audio=off
#dtoverlay=justboom-dacSnippet from around Play begin as requested. :) This is with the JustBoom disabled as above, a headphone cable plugged into the Pi directly, and speaker-test outputting sound correctly, with shairport-sync -h reporting hw:Headphones as one of the output devices, and with that set as the output_device in /etc/shairport-sync.conf.
0.000042037 "rtsp.c:580" RTSP Message Received: "RECORD rtsp://<IPv6 address of Pi>/11526935010440528956 RTSP/1.0".
0.000040000 "rtsp.c:610" CSeq: 5.
0.000035241 "rtsp.c:610" DACP-ID: F4541326FF3F1785.
0.000034851 "rtsp.c:610" Active-Remote: 2267485019.
0.000034222 "rtsp.c:610" User-Agent: AirPlay/530.6.
0.000035297 "rtsp.c:475" msg_init message 12
0.000037055 "rtsp.c:2661" Connection 1: Received an RTSP Packet of type "RECORD":
0.000036370 "rtsp.c:507" Type: "CSeq", content: "5"
0.000032815 "rtsp.c:507" Type: "DACP-ID", content: "F4541326FF3F1785"
0.000030815 "rtsp.c:507" Type: "Active-Remote", content: "2267485019"
0.000034222 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.000032203 "rtsp.c:855" Connection 1: RECORD
0.000034093 "common.c:1390" mutex_lock "&playing_conn_lock" at "rtsp.c:304".
0.000040203 "common.c:1413" mutex_unlock "&playing_conn_lock" at "rtsp.c:307".
0.000036796 "common.c:1390" mutex_lock "&activity_monitor_mutex" at "activity_monitor.c:115".
0.004150909 "audio_alsa.c:462" Output written using MMAP
0.000115407 "audio_alsa.c:529" alsa: output format chosen is "S16".
0.000085666 "audio_alsa.c:569" alsa: output speed chosen is 44100.
0.001510123 "audio_alsa.c:1492" alsa: update timestamps available
0.000053926 "audio_alsa.c:226" alsa: precision delay timing is available.
0.000034092 "audio_alsa.c:721" alsa: precision timing selected for "auto" mode
0.000073259 "audio_alsa.c:738" PCM handle name = 'hw:Headphones'
0.000035889 "audio_alsa.c:752" alsa device parameters:
0.000038704 "audio_alsa.c:755" access type = MMAP_INTERLEAVED
0.000079277 "audio_alsa.c:759" format = 'S16_LE' (Signed 16 bit Little Endian)
0.000044444 "audio_alsa.c:763" subformat = 'STD' (Standard)
0.000036685 "audio_alsa.c:766" number of channels = 2
0.000073389 "audio_alsa.c:769" number of significant bits = 16
0.000038055 "audio_alsa.c:777" rate = 44100 frames per second (precisely).
0.000036445 "audio_alsa.c:786" precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
0.000083703 "audio_alsa.c:799" period_time = 10068 us (>).
0.000038352 "audio_alsa.c:809" period_size = 444 frames (precisely).
0.000039925 "audio_alsa.c:825" buffer_time = 743038 us (>).
0.000043371 "audio_alsa.c:838" buffer_size = 32768 frames (>).
0.000035703 "audio_alsa.c:851" periods_per_buffer = 73 (>).
0.000035611 "audio_alsa.c:1816" alsa: prepare() -- opened output device
0.000073426 "audio_alsa.c:1965" alsa: alsa_buffer_monitor_thread_code() -- closing the output device
0.000154869 "rtsp.c:2704" Connection 1: RTSP Response:
0.000023796 "rtsp.c:507" Type: "CSeq", content: "5"
0.000019482 "player.c:1720" No latency has (yet) been specified. Setting 88,200 (2 seconds) frames as a default.
0.000032907 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.000091018 "rtsp.c:507" Type: "Audio-Latency", content: "11025"
0.000111352 "rtsp.c:556" msg_free freed message 12
0.000042703 "rtsp.c:556" msg_free freed message 11
======= do_close message here =======
0.004858276 "audio_alsa.c:1754" alsa: do_close() -- closing alsa handle
0.000402535 "audio_alsa.c:1968" alsa: alsa_buffer_monitor_thread_code() -- alsa_backend_state => abm_disconnected
0.004941220 "player.c:1781" Output frame bytes is 4.
0.000061500 "player.c:1786" dac_buffer_queue_minimum_length is 5292 frames.
0.000089259 "player.c:1881" Output bit depth is 16.
0.000035074 "player.c:1888" Dithering will be enabled because the output volume is being altered in software
0.000034629 "audio_alsa.c:1408" audio_alsa start called.
0.000488591 "rtp.c:419" Sync packet received before we got a timing packet back.
0.003155653 "player.c:2004" Set initial volume to -18.000000.
0.000040981 "common.c:1390" mutex_lock "&conn->volume_control_mutex" at "player.c:2841".
0.000054148 "loudness.c:47" Volume: -37.6 dB - Loudness gain @10Hz: 8.8 dB
0.000021408 "player.c:3051" player_volume_without_notification: volume mode is 0, airplay volume is -18.000000, software_attenuation: -3755.700000, hardware_attenuation: 0.000000, muting is disabled.
0.000022629 "common.c:1413" mutex_unlock "&conn->volume_control_mutex" at "player.c:3068".
======= Play begin message here =======
0.000040759 "player.c:2007" Play begin
0.003227505 "mdns_avahi.c:94" resolve_callback: Service 'iTunes_Ctrl_F4541326FF3F1785' of type '_dacp._tcp' in domain 'local':
0.000033333 "mdns_avahi.c:102" resolve_callback: client dacp_id "F4541326FF3F1785" dacp port: 61981.
0.000374554 "rtp.c:628" clock synchronisation request: return time is 6.377 milliseconds.
0.000166500 "rtp.c:811" not enough samples to estimate drift -- remaining at 0.00 ppm.
0.000400516 "mdns_avahi.c:94" resolve_callback: Service 'iTunes_Ctrl_A91F855C3958A5A5' of type '_dacp._tcp' in domain 'local':
0.000544406 "mdns_avahi.c:94" resolve_callback: Service 'iTunes_Ctrl_F4541326FF3F1785' of type '_dacp._tcp' in domain 'local':
0.000053388 "mdns_avahi.c:102" resolve_callback: client dacp_id "F4541326FF3F1785" dacp port: 61981.
0.000701682 "mdns_avahi.c:94" resolve_callback: Service 'iTunes_Ctrl_A91F855C3958A5A5' of type '_dacp._tcp' in domain 'local':
0.014316588 "player.c:466" syncing to seqno 58479.
0.000085667 "rtsp.c:475" msg_init message 13
0.000024351 "rtsp.c:580" RTSP Message Received: "FLUSH rtsp://<IPv6 address of Pi>/11526935010440528956 RTSP/1.0".
0.000023167 "rtsp.c:610" RTP-Info: seq=58479;rtptime=268834461.
0.000016759 "rtsp.c:610" CSeq: 6.
0.000017259 "rtsp.c:610" DACP-ID: F4541326FF3F1785.
0.000019260 "rtsp.c:610" Active-Remote: 2267485019.
0.000019036 "rtsp.c:610" User-Agent: AirPlay/530.6.
0.000017760 "rtsp.c:475" msg_init message 14
0.000016037 "rtsp.c:2661" Connection 1: Received an RTSP Packet of type "FLUSH":
0.000015574 "rtsp.c:507" Type: "RTP-Info", content: "seq=58479;rtptime=268834461"
0.000015240 "rtsp.c:507" Type: "CSeq", content: "6"
0.000018185 "rtsp.c:507" Type: "DACP-ID", content: "F4541326FF3F1785"
0.000015778 "rtsp.c:507" Type: "Active-Remote", content: "2267485019"
0.000014704 "rtsp.c:507" Type: "User-Agent", content: "AirPlay/530.6"
0.000018129 "rtsp.c:930" Connection 1: FLUSH
0.000179536 "player.c:238" Apple ALAC Decoder used on encrypted audio.
0.000017685 "common.c:1390" mutex_lock "&playing_conn_lock" at "rtsp.c:304".
0.000088389 "common.c:1413" mutex_unlock "&playing_conn_lock" at "rtsp.c:307".
0.000026241 "player.c:3087" player_flush
0.000016537 "player.c:3078" do_flush: flush to 268834461.
0.000016814 "common.c:1390" mutex_lock "&conn->flush_mutex" at "player.c:3079".
0.000018871 "common.c:1413" mutex_unlock "&conn->flush_mutex" at "player.c:3083".
0.000014925 "rtsp.c:2704" Connection 1: RTSP Response:
0.000003537 "rtsp.c:507" Type: "CSeq", content: "6"
0.000017315 "rtsp.c:507" Type: "Server", content: "AirTunes/105.1"
0.000010278 "common.c:1390" mutex_lock "&alsa_mutex" at "audio_alsa.c:1826".
0.000043333 "audio_alsa.c:1841" alsa: flush() -- called on a disconnected alsa backend
0.000006315 "rtsp.c:556" msg_free freed message 14
0.000018000 "common.c:1413" mutex_unlock "&alsa_mutex" at "audio_alsa.c:1842".
0.000019907 "player.c:945" flush request: flush output device.
0.000019741 "player.c:1005" flush request: flush frame 268834461 expired -- buffer contains 352 frames, from 268834461 to 268834812
0.000019093 "player.c:1029" flush request: request dropped.
0.000023407 "rtsp.c:556" msg_free freed message 13
0.285741477 "rtp.c:628" clock synchronisation request: return time is 9.101 milliseconds.
0.000064777 "rtp.c:811" not enough samples to estimate drift -- remaining at 0.00 ppm.
0.296955026 "rtp.c:628" clock synchronisation request: return time is 5.966 milliseconds.
0.000196592 "rtp.c:811" not enough samples to estimate drift -- remaining at 0.00 ppm.Thanks for all the investigations. Just to clarify — is the log for playing to the built-in DAC? I notice that Shairport Sync doesn’t try to close the link to the DAC. In fact, it looks like it should be working, presuming the output level is high enough (check with alsamixer). Was that the case (sorry for being a bit dense here)?
VirtualWolf
commented
3 years ago OH MY GOD I AM SUCH A DICKHEAD. 🤦🏻♀️
In fact, it looks like it should be working, presuming the output level is high enough (check with
alsamixer)
This made me realise I should check the damn volume on my iPhone (it always sits at 100% when I'm playing to shairport-sync), and guess what happened... it'd reset itself down to about a third which it turns out is way too quiet to register anything when playing back through shairport-sync and my speakers. Cranked it back to 100% and everything is working fine.
brb, going to crawl into a hole in embarrassment. I'm so sorry for wasting your time. 😔
mikebrady
commented
3 years ago Haha, no worries. I liked your blog, BTW. Some interesting ideas there.
VirtualWolf
commented
3 years ago Cheers! 😊
I've been using shairport-sync for literally years with no problems, my current setup is a Raspberry Pi 4B with a JustBoom DAC HAT attached. I was playing music from my iPhone this evening, one of my alarms went off on the phone which interrupted the playback to shairport-sync as normal, but ever since then, I can't get any audio output whatsoever from shairport-sync from any of my devices! (iPhone 11 Pro and 11" iPad Pro both running latest iOS/iPadOS, and MacBook Air running latest macOS).
Whatever device it is I'm sending audio from says it's playing, but no audio comes through.
speakertestoutputs audio via the DAC HAT correctly, so that part of things is working. I've totally removed shairport-sync and all its configuration files and rebooted and recompiled and reinstalled, all to no avail. It was compiled with./configure --sysconfdir=/etc --with-alsa --with-soxr --with-avahi --with-ssl=openssl --with-systemd --with-apple-alac.It seems similar to what @brunophilipe was describing in #1090, and I'm utterly baffled as to what's gone wrong here! Any and all help is greatly appreciated. :)
Verbose startup logs
Connection and playback logs