search

mikebrady / shairport-sync

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

[Problem]: shairport-sync crashes on play if launched as a services, but works fine otherwise #1827

Closed mchccc closed 5 months ago

mchccc commented 7 months ago

What happened?

Just as the title says, shairport-sync works fine if launched manually from a terminal, but crashes as soon as something tries to connect when it's running as a service.

I have an external USB DAC connected to a raspberry 3, which works fine with raspotify.

The output below is before and after trying to play something; attached below is also verbose output from a sysctl run, which looks exactly the same as the one from a manual run (compared with diff).

Thank you

Relevant log output

pi@raspberry3:~ $ sudo systemctl status shairport-sync
● shairport-sync.service - Shairport Sync - AirPlay Audio Receiver
     Loaded: loaded (/lib/systemd/system/shairport-sync.service; enabled; vendor preset: enabled)
     Active: active (running) since Sat 2024-03-16 11:35:50 CET; 5s ago
   Main PID: 990 (shairport-sync)
      Tasks: 5 (limit: 779)
        CPU: 1.674s
     CGroup: /system.slice/shairport-sync.service
             └─990 /usr/local/bin/shairport-sync --log-to-syslog

Mar 16 11:35:50 raspberry3 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
pi@raspberry3:~ $ sudo systemctl status shairport-sync
● shairport-sync.service - Shairport Sync - AirPlay Audio Receiver
     Loaded: loaded (/lib/systemd/system/shairport-sync.service; enabled; vendor preset: enabled)
     Active: inactive (dead) since Sat 2024-03-16 11:36:05 CET; 4s ago
    Process: 990 ExecStart=/usr/local/bin/shairport-sync --log-to-syslog (code=exited, status=0/SUCCESS)
   Main PID: 990 (code=exited, status=0/SUCCESS)
        CPU: 1.958s

Mar 16 11:35:50 raspberry3 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
Mar 16 11:36:05 raspberry3 shairport-sync[990]: fatal error: An unrecoverable error, "output_device_error_19", has been detected. Doing an emergency exit, as no run_this_if_an_unfixable_error_is_detected program.
Mar 16 11:36:05 raspberry3 systemd[1]: shairport-sync.service: Succeeded.
Mar 16 11:36:05 raspberry3 systemd[1]: shairport-sync.service: Consumed 1.958s CPU time.

--- verbose output ---

Mar 16 11:43:43 raspberry3 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.002468802 "shairport.c:2252" Startup in AirPlay 2 mode, with features 0x405c4a00,0x1c340 on device "b8:27:eb:f9:77:a0".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000309323 "shairport.c:2291" Version String: "4.3.2-2-g165431a8-AirPlay2-smi10-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000036562 "shairport.c:2310" Command Line: "/usr/local/bin/shairport-sync --log-to-syslog -v".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000448438 "shairport.c:2346" Log Verbosity is 1.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000070625 "audio_alsa.c:1021" alsa: alsa_maximum_stall_time of 0.200000 sec.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000062812 "audio_alsa.c:1310" alsa: disable_standby_mode is "never".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000026771 "audio_alsa.c:1314" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000026979 "audio_alsa.c:1316" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000051042 "audio_alsa.c:1356" alsa: output device name is "default".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000280156 "shairport.c:2394" disable_resend_requests is off.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000035782 "shairport.c:2395" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000030364 "shairport.c:2399" statistics_requester status is 0.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000029427 "shairport.c:2404" rtsp listening port is 7000.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000026927 "shairport.c:2405" udp base port is 6001.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000025990 "shairport.c:2406" udp port range is 10.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000026510 "shairport.c:2407" player name is "Raspberry3".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000031094 "shairport.c:2408" backend is "alsa".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000026979 "shairport.c:2409" run_this_before_play_begins action is "(null)".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000031719 "shairport.c:2410" run_this_after_play_ends action is "(null)".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000026510 "shairport.c:2411" wait-cmd status is 0.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000025678 "shairport.c:2412" run_this_before_play_begins may return output is 0.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000032708 "shairport.c:2413" run_this_if_an_unfixable_error_is_detected action is "(null)".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000027448 "shairport.c:2415" run_this_before_entering_active_state action is  "(null)".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000026666 "shairport.c:2417" run_this_after_exiting_active_state action is  "(null)".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000026146 "shairport.c:2419" active_state_timeout is  10.000000 seconds.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000030782 "shairport.c:2420" mdns backend "(null)".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000026979 "shairport.c:2422" interpolation setting is "auto".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000026979 "shairport.c:2426" interpolation soxr_delay_threshold is 30000000.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000026771 "shairport.c:2427" resync time is 0.050000 seconds.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000026771 "shairport.c:2428" resync recovery time is 0.100000 seconds.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000028125 "shairport.c:2429" allow a session to be interrupted: 0.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000025989 "shairport.c:2430" busy timeout time is 0.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000031094 "shairport.c:2431" drift tolerance is 0.002000 seconds.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000027604 "shairport.c:2432" password is "(null)".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000031146 "shairport.c:2433" default airplay volume is: -24.000000.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000028906 "shairport.c:2434" high threshold airplay volume is: -16.000000.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000028438 "shairport.c:2436" check for higher-than-threshold volume for new play session is disabled.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000025833 "shairport.c:2442" ignore_volume_control is 0.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000026198 "shairport.c:2446" volume_max_db is not set
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000032917 "shairport.c:2447" volume range in dB (zero means use the range specified by the mixer): 0.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000027187 "shairport.c:2449" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000025885 "shairport.c:2453" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000025782 "shairport.c:2455" disable_synchronization is 0.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000080260 "shairport.c:2456" use_mmap_if_available is 1.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000030521 "shairport.c:2457" output_format automatic selection is enabled.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000029687 "shairport.c:2461" output_rate automatic selection is enabled.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000029584 "shairport.c:2465" audio backend desired buffer length is 0.200000 seconds.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000030625 "shairport.c:2467" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000043437 "shairport.c:2469" audio backend latency offset is 0.000000 seconds.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000031563 "shairport.c:2471" audio backend silence lead-in time is "auto".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000033802 "shairport.c:2475" zeroconf regtype is "_raop._tcp".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000029010 "shairport.c:2476" decoders_supported field is 1.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000029011 "shairport.c:2477" use_apple_decoder is 0.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000029010 "shairport.c:2478" alsa_use_hardware_mute is 0.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000036927 "shairport.c:2482" no special mdns service interface was requested.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000055625 "shairport.c:2485" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000032448 "shairport.c:2515" loudness is 0.
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000029375 "shairport.c:2516" loudness reference level is -20.000000
Mar 16 11:43:43 raspberry3 shairport-sync:          0.000765313 "shairport.c:2643" NQPTP is online.
Mar 16 11:43:45 raspberry3 shairport-sync:          1.502237812 "shairport.c:255" "soxr" interpolation has been chosen.
Mar 16 11:44:48 raspberry3 shairport-sync:         63.461858621 "rtsp.c:2902" Connection 1: AP2 PTP connection from fddb:2077:aff0:0:ca0:a122:1ead:abf4:62506 ("M1ProMacBookPro") to self at fddb:2077:aff0::138:7000.
Mar 16 11:44:49 raspberry3 shairport-sync:          0.256536094 "rtsp.c:3258" Connection 1: SETUP AP2 no Active-Remote information  the SETUP Record.
Mar 16 11:44:49 raspberry3 shairport-sync:          0.000098906 "rtsp.c:3277" Connection 1: SETUP AP2 doesn't include DACP-ID string information.
Mar 16 11:44:49 raspberry3 shairport-sync:          0.000043438 "rtsp.c:3292" Connection 1. AP2 Realtime Audio Stream.
Mar 16 11:44:49 raspberry3 shairport-sync:          0.064885572 "audio_alsa.c:178" *fatal error: An unrecoverable error, "output_device_error_19", has been detected. Doing an emergency exit, as no run_this_if_an_unfixable_error_is_detected program.
Mar 16 11:44:49 raspberry3 shairport-sync:          0.000835053 "rtsp.c:531" Connection 1: cancelled.
Mar 16 11:44:49 raspberry3 kernel: [ 1359.484474] hdmi-audio-codec hdmi-audio-codec.0.auto: ASoC: error at snd_soc_dai_startup on i2s-hifi: -19
Mar 16 11:44:49 raspberry3 kernel: [ 1359.484622]  MAI: soc_pcm_open() failed (-19)
Mar 16 11:44:49 raspberry3 shairport-sync:          0.004412656 "rtsp.c:542" Connection 1: joined.
Mar 16 11:44:49 raspberry3 shairport-sync:          0.000634739 "shairport.c:1728" emergency exit
Mar 16 11:44:49 raspberry3 systemd[1]: shairport-sync.service: Succeeded.

System Information.

pi@raspberry3:~ $ librespot -d ?
[...]
    Device:

        sysdefault:CARD=DAC

    Description:

        USB Audio DAC, USB Audio
        Default Audio Device

    Supported Format & Sample Rate Combinations:

        Format: S16   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
        Format: S24   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
        Format: S24_3 Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
        Format: S32   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
        Format: F32   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
        Format: F64   Sample Rate(s): 44.1kHz, 48kHz, 88.2kHz, 96kHz
[...]

Configuration Information.

pi@raspberry3:~ $ shairport-sync --displayConfig
>> Display Config Start.

From "uname -a":
 Linux raspberry3 5.15.74-v8+ #1595 SMP PREEMPT Wed Oct 26 11:07:24 BST 2022 aarch64 GNU/Linux

From /etc/os-release:
 Debian GNU/Linux 11 (bullseye)

From /sys/firmware/devicetree/base/model:
 Raspberry Pi 3 Model B Rev 1.2

Shairport Sync Version String:
 4.3.2-2-g165431a8-AirPlay2-smi10-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc

Command Line:
 shairport-sync --displayConfig

Configuration File:
 /etc/shairport-sync.conf

Configuration File Settings:
 pw : 
 {
 };

>> Display Config End.
>> Goodbye!

PulseAudio or PipeWire installed?

How did you install Shairport Sync?

Built from source

Check previous issues

mikebrady commented 7 months ago

Thanks for the post. This isn't exactly a crash -- Shairport Sync is exiting because it received an error 19 when trying to access the output device -- Error 19 means "No Such Device", so for some reason, the device is not accessible. You have not specified the output device in the configuration file, so it may be that Shairport Sync is trying to access whatever the default alsa device is. It might be better to specify the device rather than rely on a default. Use $ shairport-sync -h to get a list of possible devices, though this is a bit crude and may not be completely accurate. A tool called sps-alsa-explore might help you to get more specific and reliable information.

mchccc commented 7 months ago

Thank you very much,

it seems that shairport-sync sees the card correctly

    hardware output devices:
      "hw:DAC"
      "hw:vc4hdmi"

and the output of sps-alsa-explore also looks fine

pi@raspberry3:~/sps-alsa-explore $ ./sps-alsa-explore 
> Device Full Name:    "hw:DAC"
  Short Name:          "hw:0"
  This device seems suitable for use with Shairport Sync.
  Possible mixers:     "PCM",0                 Range: 128.00 dB
  The following rate and format would be chosen by Shairport Sync in "auto" mode:
     Rate              Format
     44100             S16_LE

> Device Full Name:    "hw:vc4hdmi"
  Short Name:          "hw:1"
  This device can not be accessed and so can not be checked.
  (Does it need to be configured or connected?)

Why would it work when launched manually but not when running as a service? And how would I go about setting the card in the configuration file?

Thank you

github-actions[bot] commented 5 months ago

This issue has been inactive for 28 days so will be closed 7 days from now. To prevent this, please remove the "stale" label or post a comment.

mchccc commented 5 months ago

I still haven't solved this :/

mikebrady commented 5 months ago

Thanks. One of the suggestions was:

It might be better to specify the device rather than rely on a default.

Did you happen to try that? Maybe specify hw:DAC as the output_device in the alsa stanza of the configuration file.

mchccc commented 5 months ago

Hey what do you know, that worked great! :D

Thank you, sorry I didn't know how to fix the config file, it was smooth!