[Problem]: Crash when pausing: sndio: unable to flush

[janprzy]

What happened?

Hi,

I'm running shairport-sync 4.3.2 on Freebsd 13.

Often when pausing the audio, or when the next song starts, shairport-sync will crash and the error message sndio: unable to flush is written to the log. It doesn't happen every time, but it is reproducible by pressing play/pause repeatedly.

Log verbosity is set to 2. I hope I captured all the relevant parts of the log.

Relevant log output

0.000042188 "rtsp.c:5313"   No Content Plist. Content length: 0.
           0.004376962 "rtsp.c:5252" Connection 3: Received an RTSP Packet of type "SET_PARAMETER":
           0.000053922 "rtsp.c:5253"   Type: "RTP-Info", content: "rtptime=2137419097"
           0.000041071 "rtsp.c:5253"   Type: "Content-Length", content: "43"
           0.000041071 "rtsp.c:5253"   Type: "Content-Type", content: "text/parameters"
           0.000040791 "rtsp.c:5253"   Type: "CSeq", content: "282"
           0.000040791 "rtsp.c:5253"   Type: "DACP-ID", content: "479EE4425B18152F"
           0.000040792 "rtsp.c:5253"   Type: "Active-Remote", content: "3096929787"
           0.000040791 "rtsp.c:5253"   Type: "User-Agent", content: "AirPlay/745.13.4"
           0.000041071 "rtsp.c:5253"   No Content Plist. Content length: 43.
           0.000066216 "rtsp.c:5312" Connection 3: RTSP Response:
           0.000043864 "rtsp.c:5313"   Response Code: 200.
           0.000041630 "rtsp.c:5313"   Type: "CSeq", content: "282"
           0.000041629 "rtsp.c:5313"   Type: "Server", content: "AirTunes/366.0"
           0.000041909 "rtsp.c:5313"   No Content Plist. Content length: 0.
           0.045100080 "rtsp.c:5252" Connection 3: Received an RTSP Packet of type "SETRATEANCHORTI":
           0.000054481 "rtsp.c:5253"   Type: "Content-Length", content: "53"
           0.000041350 "rtsp.c:5253"   Type: "Content-Type", content: "application/x-apple-binary-plist"
           0.000041630 "rtsp.c:5253"   Type: "CSeq", content: "283"
           0.000041070 "rtsp.c:5253"   Type: "DACP-ID", content: "479EE4425B18152F"
           0.000041350 "rtsp.c:5253"   Type: "Active-Remote", content: "3096929787"
           0.000047497 "rtsp.c:5253"   Type: "User-Agent", content: "AirPlay/745.13.4"
           0.000053643 "rtsp.c:5253"   Content Plist (as XML):
  --
  <?xml version="1.0" encoding="UTF-8"?>
  <!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
  <plist version="1.0">
  <dict>
          <key>rate</key>
          <integer>0</integer>
  </dict>
  </plist>
  --
           0.000056717 "ptp-utilities.c:223" Send control message to NQPTP: "/nqptp P"
           0.000101140 "rtsp.c:2017" Connection 3: Pause playing.
           0.000059511 "rtp.c:1322" Connection 3: Clear anchor information.
           0.000057834 "rtsp.c:2025" Connection 3: Stop the output backend.
           0.000048614 "rtsp.c:5312" Connection 3: RTSP Response:
           0.000042188 "rtsp.c:5313"   Response Code: 200.
           0.000040792 "rtsp.c:5313"   Type: "CSeq", content: "283"
           0.000041070 "rtsp.c:5313"   Type: "Server", content: "AirTunes/366.0"
           0.000041351 "rtsp.c:5313"   No Content Plist. Content length: 0.
           0.000819737 "rtp.c:2473" Play stopped.
           0.000078509 "audio_sndio.c:288" *fatal error: sndio: unable to flush
           0.000114272 "shairport.c:1728" emergency exit
           0.000083538 "rtsp.c:5415" rtsp_listen_loop_cleanup_handler called.
           0.000087170 "rtsp.c:531" Connection 3: cancelled.
           0.000307053 "rtsp.c:5069" Connection 3: PTP stream rtsp_conversation_thread_func_cleanup_function called.
           0.000054481 "player.c:3645" Connection 3: player_stop.
           0.003339857 "shairport.c:1470" default metadata_pipename is "/tmp/shairport-sync-metadata".
           0.000564093 "shairport.c:2253" Startup in AirPlay 2 mode, with features 0x405fca00,0x1c340 on device

System Information.

Odroid H2

Configuration Information.

0.003332872 "shairport.c:1470" default metadata_pipename is "/tmp/shairport-sync-metadata".
         0.000286936 "shairport.c:2113" >> Display Config Start.
         0.005961675 "shairport.c:2113" 
         0.000063142 "shairport.c:2113" From "uname -a":
         0.000042468 "shairport.c:2113"  FreeBSD bsdnas.j-p.space 13.2-RELEASE-p4 FreeBSD 13.2-RELEASE-p4 GENERIC amd64
         0.008533482 "shairport.c:2113" 
         0.000091361 "shairport.c:2113" From /etc/os-release:
         0.000045541 "shairport.c:2113"  FreeBSD 13.2-RELEASE-p5
         0.006467375 "shairport.c:2113" 
         0.000058114 "shairport.c:2113" Shairport Sync Version String:
         0.000041629 "shairport.c:2113"  4.3.2-AirPlay2-smi10-libdaemon-OpenSSL-Avahi-sndio-stdout-pipe-soxr-metadata-sysconfdir:/usr/local/etc
         0.000044144 "shairport.c:2113" 
         0.000039674 "shairport.c:2113" Command Line:
         0.000039953 "shairport.c:2113"  shairport-sync --displayConfig
         0.000137461 "shairport.c:2113" 
         0.000042468 "shairport.c:2113" Configuration File:
         0.000039394 "shairport.c:2113"  /usr/local/etc/shairport-sync.conf
         0.000039395 "shairport.c:2113" 
         0.000316831 "shairport.c:2113" Configuration File Settings:
         0.000053643 "shairport.c:2113"  general : 
         0.000041071 "shairport.c:2113"  {
         0.000039673 "shairport.c:2113"    name = "Stereoanlage";
         0.000039954 "shairport.c:2113"  };
         0.000038835 "shairport.c:2113"  diagnostics : 
         0.000039394 "shairport.c:2113"  {
         0.000039115 "shairport.c:2113"    log_output_to = "/var/log/shairport-sync.log";
         0.000039395 "shairport.c:2113"    log_verbosity = 2;
         0.000039115 "shairport.c:2113"  };
         0.000039115 "shairport.c:2113" 
         0.000038556 "shairport.c:2113" >> Display Config End.
         0.000039394 "shairport.c:2115" >> Goodbye!
         0.000063143 "shairport.c:1588" exit function called...
         0.000042188 "shairport.c:1598" Stopping the activity monitor.
         0.000043585 "shairport.c:1600" Stopping the activity monitor done.
         0.000040791 "shairport.c:1640" Stopping metadata
         0.000040792 "shairport.c:1642" Stopping metadata done
         0.000053364 "shairport.c:1720" normal exit

PulseAudio or PipeWire installed?

• Check if your system uses a Sound Server.

How did you install Shairport Sync?

A package manager (apt, apt install, yum, pkg, etc.)

Check previous issues

• Confirm

[mikebrady]

Thanks for the post. It looks like an error is coming back from the FreeBSD sndio library and Shairport Sync is responding to it. We don't know what the cause of the error is -- maybe it is not serious. Let me take a look and perhaps allow Shairport Sync to ignore that sndio error.

[mikebrady]

Hmm, if the error occurs, it must be considered serious: "Once an error occurs, all functions taking a sio_hdl argument, except sio_close() and sio_eof(), stop working (i.e. always return 0)."

So, modifying the flush code (as follows) so that is does nothing might be an interesting experiment. The code, in audio_sndio.c is:

static void flush() {
  // pthread_mutex_lock(&sndio_mutex);
  pthread_cleanup_debug_mutex_lock(&sndio_mutex, 1000, 1);
  if (!sio_stop(hdl) || !sio_start(hdl))
    die("sndio: unable to flush");
  written = played = 0;
  // pthread_mutex_unlock(&sndio_mutex);
  pthread_cleanup_pop(1); // unlock the mutex
}

Replacing it with:

static void flush() {
}

Would make it do nothing.

[janprzy]

I just tried that, but it didn't work unfortunately. Now I get sndio: unable to stop:

     0.000062025 "ptp-utilities.c:223" Send control message to NQPTP: "/nqptp P"
     0.000117066 "rtsp.c:2017" Connection 1: Pause playing.
     0.000062304 "rtp.c:1322" Connection 1: Clear anchor information.
     0.000081303 "rtsp.c:2025" Connection 1: Stop the output backend.
     0.000050850 "audio_sndio.c:249" *fatal error: sndio: unable to stop
     0.000191384 "shairport.c:1728" emergency exit
     0.000355387 "rtsp.c:5415" rtsp_listen_loop_cleanup_handler called.
     0.000070128 "rtsp.c:531" Connection 1: cancelled.

I will try to investigate what's causing the error in sndio.

[klemensn]

I saw sndio: unable to flush/stop once or twice with 4.3.2 on OpenBSD/amd64 7.4-current as well, haven't looked into it (yet).

[amandasystems]

I can confirm that this happens to me on FreeBSD 14.0-RELEASE too, and also happens when changing tracks or fast-forwarding/backwarding (essentially any time the buffer is flushed, it seems). The problem disappears if I switch to AirPlay 1.

[mikebrady]

I can confirm that this happens to me on FreeBSD 14.0-RELEASE too, and also happens when changing tracks or fast-forwarding/backwarding (essentially any time the buffer is flushed, it seems). The problem disappears if I switch to AirPlay 1.

Thanks @amandasystems -- this is interesting. The same audio backend is used for AirPlay 2 and AirPlay 1. However, I think AirPlay 2 starts and stops audio streams much more frequently than AirPlay 1, possibly giving rise to the circumstances that cause the sndio problem more often.

[amandasystems]

Interesting! I’ll try to provoke it on AirPlay 1 too.

[amandasystems]

Update: I tried my damnedest but I couldn't trigger it.

[mikebrady]

Thanks for your efforts and for the update. I'll keep trying to figure out if something is happening inadvertently in Shairport Sync.

[amandasystems]

My intuition says race condition of some kind, or possibly bad cleanup, but I have no familiarity with any of this so it's 100% gut feeling.