Track stops playing with CDSP Plugin ERROR: XRUN OCCURRED!

[Sehnsucht]

I listened to approx one hour of music when suddenly it stopped 5-10 mins into the fourth track, where each track was around 20 minutes long.

 /var/log/mpd/log contains over 2000 of these:

CDSP Plugin ERROR: XRUN OCCURRED!

I checked the flac file in Audacity and it looks fine.  Played it again and it's fine.  I've recently performed a fresh install of moOde 8.1.1 and I play purely local flac files from a USB attached hard drive. I use CamillaDSP with a fairly simple EQ (3 filters plus gain, on two channels).  I've never had this problem before using moOode/CamillaDSP on recent moOde v7/v8 and I've listened continously for much longer than an hour on this and previous installs.

I'm using a Pi 4 with 2gb ram, into an external DAC over USB.

Code:

pi@moode:/var/log/mpd $ moodeutl -l
20220702 142809 worker: --
20220702 142809 worker: -- Start moOde 8 series
20220702 142809 worker: --
20220702 142809 worker: Successfully daemonized
20220702 142811 worker: File check (OK)
20220702 142812 worker: Session vacuumed
20220702 142812 worker: Session loaded
20220702 142812 worker: Debug logging (OFF)
20220702 142812 worker: --
20220702 142812 worker: -- Audio debug
20220702 142812 worker: --
20220702 142812 worker: ALSA cards: (0:b1 | 1:Headphones | 2:E30 | 3:empty
20220702 142812 worker: MPD config: (2:E30 | mixer:(E30 ) | card:2)
20220702 142812 worker: ALSA mixer actual (E30 )
20220702 142812 worker: ALSA E30 volume set to (0%)
20220702 142812 worker: --
20220702 142812 worker: -- System
20220702 142812 worker: --
20220702 142813 worker: Host      (moode)
20220702 142813 worker: moOde     (8.1.1 2022-06-24)
20220702 142813 worker: RaspiOS   (11.3)
20220702 142813 worker: Kernel    (5.15.32-v8+ #1538)
20220702 142813 worker: Platform  (Pi-4B 1.1 2GB)
20220702 142813 worker: ARM arch  (aarch64, 64-bit)
20220702 142813 worker: MPD ver   (0.23.5)
20220702 142813 worker: CPU gov   (ondemand)
20220702 142813 worker: USB boot  (enabled)
20220702 142813 worker: File sys  (expanded)
20220702 142813 worker: HDMI port (Off)
20220702 142813 worker: Sys LED0  (On)
20220702 142813 worker: Sys LED1  (On)
20220702 142813 worker: --
20220702 142813 worker: -- Network
20220702 142813 worker: --
20220702 142813 worker: eth0 adapter exists
20220702 142813 worker: eth0 check for address (No)
20220702 142813 worker: IP addr (192.168.1.122)
20220702 142813 worker: Netmask (255.255.255.0)
20220702 142813 worker: Gateway (192.168.1.1)
20220702 142814 worker: Pri DNS (8.8.8.8)
20220702 142814 worker: Domain  ()
20220702 142814 worker: wlan0 adapter does not exist
20220702 142814 worker: --
20220702 142814 worker: -- Audio config
20220702 142814 worker: --
20220702 142814 worker: MPD conf update skipped (USB device)
20220702 142814 worker: ALSA card number (2)
20220702 142814 worker: MPD audio output (E30)
20220702 142814 worker: Audio formats (S32_LE, SPECIAL, DSD_U32_BE)
20220702 142814 worker: ALSA mixer name (E30 )
20220702 142814 worker: MPD mixer type (fixed 0dB)
20220702 142814 worker: Hdwr volume controller exists
20220702 142814 worker: Max ALSA volume (100%)
20220702 142814 worker: ALSA output mode (Default: plughw)
20220702 142814 worker: ALSA loopback (Off)
20220702 142814 worker: Reset renderer active flags
20220702 142814 worker: CamillaDSP (HD 660S Amir.yml)
20220702 142814 worker: --
20220702 142814 worker: -- MPD startup
20220702 142814 worker: --
20220702 142815 worker: MPD started
20220702 142815 worker: MPD accepting connections
20220702 142815 worker: MPD output 1 ALSA Default (On)
20220702 142815 worker: MPD output 2 ALSA Bluetooth (Off)
20220702 142815 worker: MPD output 3 HTTP Server (Off)
20220702 142815 worker: MPD crossfade (off)
20220702 142815 worker: MPD ignore CUE files (yes)
20220702 142815 worker: --
20220702 142815 worker: -- Music sources
20220702 142815 worker: --
20220702 142815 worker: USB source (USB4tbMusic)
20220702 142815 worker: NAS sources (none configured)
20220702 142815 worker: --
20220702 142815 worker: -- Feature availability
20220702 142815 worker: --
20220702 142815 worker: Source select (available)
20220702 142815 worker: Source select (source: MPD)
20220702 142816 worker: Source select (output: E30)
20220702 142816 worker: Bluetooth (available)
20220702 142816 worker: Airplay renderer (available)
20220702 142816 worker: Spotify renderer (available)
20220702 142816 worker: Squeezelite (available)
20220702 142816 worker: RoonBridge renderer (not installed)
20220702 142816 worker: Multiroom sender (available)
20220702 142816 worker: Multiroom receiver (available)
20220702 142816 worker: UPnP renderer (available)
20220702 142816 worker: DLNA server (available)
20220702 142816 worker: GPIO button handler (available)
20220702 142816 worker: Stream recorder (n/a)
20220702 142816 worker: --
20220702 142816 worker: -- Other
20220702 142816 worker: --
20220702 142816 worker: USB volume knob (Off)
20220702 142816 worker: USB auto-mounter (udisks-glue)
20220702 142816 worker: Saved MPD vol level (0)
20220702 142816 worker: Preamp volume level (0)
20220702 142816 worker: MPD volume level (0) restored
20220702 142816 worker: ALSA E30 volume (100%)
20220702 142816 worker: Auto-play (Off)
20220702 142816 worker: CoverView toggle (-off)
20220702 142816 worker: Maintenance interval (120 minutes)
20220702 142816 worker: Screen saver activation (Never)
20220702 142816 worker: Session permissions (OK)
20220702 142816 worker: Watchdog started
20220702 142816 worker: Ready

CamillaDSP EQ:

Code:

HD 660S Amir.yml
---
devices:
  adjust_period: 1
  capture:
    type: File
    channels: 2
    filename: /dev/stdin
    format: S32LE
  capture_samplerate: 44100
  chunksize: 4096
  enable_rate_adjust: false
  enable_resampling: true
  playback:
    type: Alsa
    channels: 2
    device: plughw:2,0
    format: S32LE
  queuelimit: 4
  rate_measure_interval: 1
  resampler_type: Synchronous
  samplerate: 96000
  silence_threshold: -100
  silence_timeout: 5
  stop_on_rate_change: false
  target_level: 2048
filters:
  0022 hz:
    parameters:
      freq: 22
      gain: 12
      q: 1
      type: Peaking
    type: Biquad
  3000 hz:
    parameters:
      freq: 3000
      gain: 3
      q: 2.500000
      type: Peaking
    type: Biquad
  5480 hz:
    parameters:
      freq: 5480
      gain: -3
      q: 5
      type: Peaking
    type: Biquad
  negative gain:
    parameters:
      gain: -10
      inverted: false
      mute: false
    type: Gain
pipeline:
- channel: 0
  names:
  - negative gain
  - 0022 hz
  - 3000 hz
  - 5480 hz
  type: Filter
- channel: 1
  names:
  - negative gain
  - 0022 hz
  - 3000 hz
  - 5480 hz
  type: Filter
...

[Tim Curtis]

The first challenge is to isolate the problem and then develop a test case that can be reproduced

- Can continuous playback be > one hour with other files?
- Same on 32-bit?

[Sehnsucht]

The first challenge is to isolate the problem and then develop a test case that can be reproduced

- Can continuous playback be > one hour with other files?
- Same on 32-bit?

I'll stick to testing on this 64-bit install.

btw: The timestamps are inconsistent in /var/log/mpd/log - some (those containing "INFO") are an hour early.  BST vs GMT maybe (I'm in the UK)?

It's repeatable.  I rebooted and played the same four tracks starting 7:29pm:

/var/log/mpd/log:

2022-07-02 18:29:37.096063 INFO [src/bin.rs:711] CamillaDSP version 1.0.0
2022-07-02 18:29:37.096165 INFO [src/bin.rs:712] Running on linux, aarch64
2022-07-02 18:29:37.195943 INFO [src/alsadevice.rs:156] Starting playback from Prepared state
Jul 02 19:51 : player: played "USB/USB4tbMusic/G1.flac"
Jul 02 20:13 : player: played "USB/USB4tbMusic/H1.flac"
Jul 02 20:34 : player: played "USB/USB4tbMusic/I1.flac"
CDSP Plugin ERROR: XRUN OCCURRED!

2212 of those in 5 mins then....

Jul 02 20:39 : output: Failed to flush filter on "ALSA Default" (alsa): snd_pcm_writei() failed: Broken pipe
2022-07-02 19:39:41.287130 INFO [src/bin.rs:420] Capture finished
2022-07-02 19:39:41.287342 INFO [src/bin.rs:410] Playback finished
Jul 02 20:39 : player: played "USB/USB4tbMusic/J1.flac"



I'll find another hour long album and see if I can repeat it.

[Sehnsucht]

The first challenge is to isolate the problem and then develop a test case that can be reproduced

- Can continuous playback be > one hour with other files?
- Same on 32-bit?

I'll stick to testing on this 64-bit install.

btw: The timestamps are inconsistent in  /var/log/mpd/log - some (those containing "INFO") are an hour early.  BST vs GMT maybe (I'm in the UK)?

It's repeatable.  I rebooted and played the same four tracks starting 7:29pm:

/var/log/mpd/log:

2022-07-02 18:29:37.096063 INFO [src/bin.rs:711] CamillaDSP version 1.0.0
2022-07-02 18:29:37.096165 INFO [src/bin.rs:712] Running on linux, aarch64
2022-07-02 18:29:37.195943 INFO [src/alsadevice.rs:156] Starting playback from Prepared state
Jul 02 19:51 : player: played "USB/USB4tbMusic/G1.flac"
Jul 02 20:13 : player: played "USB/USB4tbMusic/H1.flac"
Jul 02 20:34 : player: played "USB/USB4tbMusic/I1.flac"
CDSP Plugin ERROR: XRUN OCCURRED!

2212 of those in 5 mins then....

Jul 02 20:39 : output: Failed to flush filter on "ALSA Default" (alsa): snd_pcm_writei() failed: Broken pipe
2022-07-02 19:39:41.287130 INFO [src/bin.rs:420] Capture finished
2022-07-02 19:39:41.287342 INFO [src/bin.rs:410] Playback finished
Jul 02 20:39 : player: played "USB/USB4tbMusic/J1.flac"



I'll find another hour long album and see if I can repeat it.

Yep, a different album with shorter tracks - after ~90 mins it happens again.   I wasn't listening to it but the log shows that the attempt to play the album continues through the errors to the end of the album. 

I'll try the first album again (it fails quicker) and keep an eye on the buffer level in the CamillaDSP pipeline editor.  After that maybe I'll try playing with the chunksize and queue limit.

btw: in the pipeline editer page there's a "show log file" but clicking on that gives: "500 Internal Server Error Server got itself in trouble" (when the album is quite happily playing).

[Tim Curtis]

I'll add the "show log file" issue to the TODO list for upcoming 8.1.2 bug fix release.

Do you see "Config is not valid, Invalid filter 'ir_hpcf'..." in Pipeline Configuration section?

In the diyAudio Camilla thread there a posts regarding adjusting the chunk size.

[Sehnsucht]

Do you see "Config is not valid, Invalid filter 'ir_hpcf'..." in Pipeline Configuration section?

In the diyAudio Camilla thread there a posts regarding adjusting the chunk size.

Nope, "config is valid".  I changed to flat and back to mine, did check etc.  It's always valid.

Ok, after the current test is complete I'll try changing just chunk size.  I don't care about latency and I've got loads of spare ram...

Edit:

Failed again.
I was running htop and nothing unusual appeared when it happened. On the pipeline page it just changed the status to STALLED. Trying again with a larger chunk size. Going from 4096 to 4*4096 = 16384. Oddly, having done that, the "Capture Samplerate" which I think was a static 44100 before is now fluctutating between 48000, 44100 and being blank. (I'm listening to 44100 stereo CD rips).

Edit again:

Nope, that larger chunksize made no difference. I've read the docs about queuelimit but I don't understand them. Is the default 4 or 128? Is moOde using the alsa cdsp plugin? No idea. I'll try setting this to 1, then I'll try making it larger.

Edit again:

My first attempt at using queuelimit 1 (chunksize still 16384) failed (that is, the error didn't reproduce) but I notice that I accidentally selected "play tracks in random order" mode, and it reminded me that I've listened to music for much longer than an hour in any given day since the upgrade, but that I probably always listened to multiple, shorter albums, or paused/unpaused, skipped etc. So possibly the problem is specifically related to continous playback. But...like I said, I can't see anything like memory leaks, cpu usage increasing etc.

Edit again:

/var/log/mpd/log is empty and syslog only goes back a couple of hours. I'm going to try with the last v7 image.

[Sehnsucht]

Reverting to 7.6.1 has fixed my issue. It also fixes the samba problem I mentioned previously: https://moodeaudio.org/forum/showthread....7#pid40947

I don't have any spare SD cards to test two versions of moOde in parallel so I'm going to leave it there for now; I already spent several hours on this and I'm out of ideas. It doesn't seem like this problem would be very hard for interested parties to reproduce.

I posted about it on diyaudio and the CamillaDsp dev said "I looked in the link, and my guess is that there is an issue with the alsa_cdsp plugin. I don't know what version of that is used in moOde. Let's wait and see if anyone in the moOde forum has some idea first.".

[Tim Curtis]

We might need @bitlab to do a bit of investigation.

We are using alsa_cdsp plugin v1.1.0 (March 8) the latest version from the author @scripple
https://github.com/bitkeeper/alsa_cdsp

-Tim