[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

• [X] 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.

[github-actions[bot]]

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.

[janprzy]

The issue seems to appear less frequently than it used to, but it's still there.

I did some further investigating, but I couldn't find anything new unfortunately. It can be provoked by pressing the play/pause button repeatedly. The error message is sometimes unable to stop and sometimes unable to flush.

[amandasystems]

I gave up and bought an AirPlay speaker instead, but someone should try the latest FreeBSD 14.1, which does list improved audio drivers. Who knows, something may have been shaken up to avoid the bug.

[mikebrady]

Fair enough. As a matter of interest, did you think of using a Linux, by any chance?

[amandasystems]

Yes, but this was a multipurpose machine that I wanted to use mostly as a NAS, so FreeBSD made sense (and still does).

[mikebrady]

Thanks!

[janprzy]

I just installed FreeBSD 14.1 and it still happens. I listened to an entire album and shairport-sync crashed after each of the first three songs, then it worked for the rest.

[mikebrady]

Thanks for the report. I do have a few ideas, if you'd be willing to try them out? I can push them into a new development branch in the next few days...

[janprzy]

Sure!

[mikebrady]

Thanks. I’ll post here when I’ve pushed the experimental update.

[mikebrady]

Okay, so an update has just been pushed to the development branch with some revisions to the sndio backend. It seems very solid here, but then it's been very hard to get it to misbehave in the past. Whenever you got a chance to try it out and report back, it would be appreciated.

[janprzy]

Thanks, I think that fixed it. I'm getting some errors saying sndio: output device is not open for delay! and sndio: flush: not running., but I listened to two entire albums and shairport-sync did not crash once.

I think this issue can be closed.

[mikebrady]

Thanks for your information. In your tests, were you using AirPlay 2 or classic AirPlay?

Those messages are informational — they don’t signify an error.

[janprzy]

I was using AirPlay 2