Playback fails and Roon begins eating queue

Support
1

Here’s a fun one that has never before popped up for me (at least in this context).

Roon Core
Ubuntu 16.04.10
Local USB3 drive array holds music
RoonServer 1.2 Build 165

Playback Device
Ubuntu 16.04.10
RoonBridge 1.0 Build 40
DAC is a dCS Debussy connected via USB

Just swapped out the DAC yesterday, but with the prior DAC in this setup this thing has been rock-solid reliable over hundreds of hours of play (including the very same playlist that generated this error).

Queue was loaded with approximately 100 tracks at mixed sample rates (anything from 16/44 to DSD to 24/192). Tracks are shuffled so there’s typically a sample rate change with each track.

Queue had been playing for about an hour when playback “held” at the end of a track. Roon still thought it was playing, but it didn’t advance past the end of the track. After several minutes in that state the track advanced, but none of the subsequent tracks started playing. Roon ultimately started skipping through the queue.

Checked the logs and found:

Core

12/16 11:31:54 Trace: [prebuffer] ready 149940/441000 (34%) @ 0/334 sec
12/16 11:31:54 Info: [zoneplayer/base] Queueing: /roon/main/Jazz/Horace Parlan/[XRCD] Speakin' My Piece-01/07-Rastus.aif
12/16 11:31:54 Info: [zoneplayer/base] Open result (Queueing): Result[Status=Success]
12/16 11:31:54 Trace: [prebuffer] ready 149940/441000 (34%) @ 0/409 sec
12/16 11:31:54 Trace: [transport/raatclient] GOT [95] {"message":"RAAT__OUTPUT_PLUGIN_STATUS_FORMAT_NOT_SUPPORTED","status":"UnexpectedError"}
12/16 11:31:54 Warn: [zoneplayer/raat] failed to setup any endpoints..giving up
12/16 11:31:54 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Inactive
Elements:
------------------------------------------------------------

12/16 11:31:54 Warn: Track Stopped Due to Error
12/16 11:31:54 Info: [zoneplayer/base] Playing: /roon/main/Jazz/Horace Parlan/[XRCD] Speakin' My Piece-01/07-Rastus.aif
12/16 11:31:54 Info: [zoneplayer/base]     Open Result (Playing):Result[Status=Success]
12/16 11:31:54 Info: [zoneplayer/base] Starting playback
12/16 11:31:54 Trace: [zoneplayer/raat] StartStream StreamFormat(channels=2, bitspersample=16, samplerate=44100, isdts=False streamid=637903922
12/16 11:31:54 Trace: [transport/raatclient] SENT [96]{"request":"setup","format":{"sample_type":"pcm","sample_rate":44100,"bits_per_sample":16,"channels":2}}
12/16 11:31:54 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Aiff 44100/16/2 BitRate=1411 Quality=Lossless
    Raat Device=dCS Debussy USB Audio 2
    Output OutputType=Local_Alsa Quality=Lossless
------------------------------------------------------------

12/16 11:31:54 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Aiff 44100/16/2 BitRate=1411 Quality=Lossless
    Raat Device=dCS Debussy USB Audio 2
    Output OutputType=Local_Alsa Quality=Lossless
------------------------------------------------------------

12/16 11:31:54 Info: [zoneplayer/base] Queueing: /roon/main/_New/SACDs/Dave Brubeck/Time Out [SACD]/05. Kathy's Waltz.dsf

Bridge:

12/16 11:31:53 Trace: [RAAT::dCS Debussy USB Audio 2] alsa output setup: format is pcm 44100/16/2
12/16 11:31:53 Trace: [RAAT::dCS Debussy USB Audio 2] opening [hw:CARD=d2,DEV=0] 44100/16/2
12/16 11:31:53 Trace: [RAAT::dCS Debussy USB Audio 2] prefer larger samples = 0
12/16 11:31:53 Trace: [RAAT::dCS Debussy USB Audio 2] [ALSA] [hw:CARD=d2,DEV=0] using hw pcmformat S32_LE bitspersample 16
12/16 11:31:53 Trace: [RAAT::dCS Debussy USB Audio 2] [ALSA] [hw:CARD=d2,DEV=0] Requesting 2 periods
12/16 11:31:53 Trace: [RAAT::dCS Debussy USB Audio 2] [ALSA] [hw:CARD=d2,DEV=0] Requesting 1764 frames/buffer (882 frames/period)
12/16 11:31:53 Trace: [RAAT::dCS Debussy USB Audio 2] [ALSA] [hw:CARD=d2,DEV=0] Initialized with 2 periods with 882 frames/period and 1764 frames/buffer
12/16 11:31:54 Error: [RAAT::dCS Debussy USB Audio 2] error in snd_pcm_hw_params: Input/output error (-5)
12/16 11:31:54 Warn: [RAAT::dCS Debussy USB Audio 2] [lua@0x7ff51c01c5e8] [172.25.50.20:35255]  setup failed: RAAT__OUTPUT_PLUGIN_STATUS_FORMAT_NOT_SUPPORTED
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] [lua@0x7ff51c01c5e8] [172.25.50.20:35255]  SENT [94] {"message":"RAAT__OUTPUT_PLUGIN_STATUS_FORMAT_NOT_SUPPORTED","status":"UnexpectedError"}
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] [lua@0x7ff51c01c5e8] [172.25.50.20:35255]  GOT [95] {"request":"setup","format":{"sample_type":"pcm","sample_rate":44100,"bits_per_sample":16,"channels":2}}
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] alsa output setup: format is pcm 44100/16/2
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] opening [hw:CARD=d2,DEV=0] 44100/16/2
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] prefer larger samples = 0
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] [ALSA] [hw:CARD=d2,DEV=0] using hw pcmformat S32_LE bitspersample 16
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] [ALSA] [hw:CARD=d2,DEV=0] Requesting 2 periods
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] [ALSA] [hw:CARD=d2,DEV=0] Requesting 1764 frames/buffer (882 frames/period)
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] [ALSA] [hw:CARD=d2,DEV=0] Initialized with 2 periods with 882 frames/period and 1764 frames/buffer
12/16 11:31:54 Error: [RAAT::dCS Debussy USB Audio 2] error in snd_pcm_hw_params: Input/output error (-5)
12/16 11:31:54 Warn: [RAAT::dCS Debussy USB Audio 2] [lua@0x7ff51c01c5e8] [172.25.50.20:35255]  setup failed: RAAT__OUTPUT_PLUGIN_STATUS_FORMAT_NOT_SUPPORTED
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] [lua@0x7ff51c01c5e8] [172.25.50.20:35255]  SENT [95] {"message":"RAAT__OUTPUT_PLUGIN_STATUS_FORMAT_NOT_SUPPORTED","status":"UnexpectedError"}
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] [lua@0x7ff51c01c5e8] [172.25.50.20:35255]  GOT [96] {"request":"setup","format":{"
sample_type":"pcm","sample_rate":44100,"bits_per_sample":16,"channels":2}}
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] alsa output setup: format is pcm 44100/16/2
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] opening [hw:CARD=d2,DEV=0] 44100/16/212/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] prefer larger samples = 0
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] [ALSA] [hw:CARD=d2,DEV=0] using hw pcmformat S32_LE bitspersample 16
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] [ALSA] [hw:CARD=d2,DEV=0] Requesting 2 periods12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] [ALSA] [hw:CARD=d2,DEV=0] Requesting 1764 frames/buffer (882 frames/period)
12/16 11:31:54 Trace: [RAAT::dCS Debussy USB Audio 2] [ALSA] [hw:CARD=d2,DEV=0] Initialized with 2 periods with 882 frames/period and 1764 frames/buffer
12/16 11:31:55 Error: [RAAT::dCS Debussy USB Audio 2] error in snd_pcm_hw_params: Input/output error (-5)

I’ve set aside copies of the full logs for @support review if needed.

2

Andrew, do you have to power the DCS off and then back on to restore the connection?

3

Hi Tony,

When this happened (twice now) I ended up rebooting the bridge (init 6) and everything came back normally. In both cases I didn’t have the ability to do any troubleshooting as I needed to get the system playing again.

I’m fairly certain I have a way to force the failure so I plan to do more troubleshooting this week. Today was the first day that I could get a few minutes to go through the system logs and it appears that the failure is happening at the driver level.

Are you seeing the same issue with a dCS DAC? If so, which model?

4

I am seeing it with a PS Audio DirectStream DAC:

blob.jpg999×159 79.2 KB

5

Any chance you’re seeing these errors in the system logs:

Dec 17 13:21:22 roon-eabox kernel: [80248.264285] xhci_hcd 0000:01:00.0: Stopped the command ring failed, maybe the host is dead
Dec 17 13:21:22 roon-eabox kernel: [80248.294530] xhci_hcd 0000:01:00.0: Host not halted after 16000 microseconds.
kernel: [80248.294546] xhci_hcd 0000:01:00.0: Abort command ring failed
kernel: [80248.294649] xhci_hcd 0000:01:00.0: HC died; cleaning up
kernel: [80248.294816] xhci_hcd 0000:01:00.0: Timeout while waiting for configure endpoint command
kernel: [80248.294831] usb 5-1: Not enough bandwidth for altsetting 0
kernel: [80248.294845] usb 5-1: USB disconnect, device number 2
kernel: [80248.296211] usb 5-1: 1:1: usb_set_interface failed (-19)
kernel: [80248.396431] usb 5-1: 1:1: usb_set_interface failed (-19)

In my case the track in question (where playback hangs) is DSD64 and the next track in the queue is 16/44. In both failures I was playing the same playlist and it failed at exactly the same spot.

I’ve only been able to do a little bit of research on the errors, but some evidence points to an issue with the xhci driver having some issues when USB2 devices are connected to USB3 ports. I need to dig in and figure out how to either disable xhci (USB3) on this port (SOtM PCIe card) or to force the kernel into ehci mode on it.

6

The Antipodes server is in another person’s system. I didn’t look at the system log. I’ll see if I can get access again to recreate the problem and look at the Roon Ready log and system journal as well as the Roon Server log. In this case Roon Server and Roon Ready are both running on the Antipodes.

7

The more I dig into this one the more it looks like this is an issue with the linux xhci driver. Many who have reported similar issues have fixed the problem by disabling xhci in the BIOS (which also would kill USB3 support for all ports). I did find one mention of being able to force a controller into USB2 mode, but haven’t tried that yet and won’t be able to until tomorrow.

For me losing USB 3 isn’t an issue as this machine is an endpoint only, but I can see it be a major bummer on the Antipodes (especially if it’s running as the server)!

8

I found this but I haven’t tried it.

9

Yep, same one I found. I verified that the command functions, but I’m accessing all of this remotely so I can’t test until I’m in the store tomorrow. Also working on building a kernel with xhci support removed to see if that does anything. Unfortunately, it’s not a module that I can blacklist in the standard Ubuntu kernel.

10

Well, in this case removing xhci support from the kernel only resulted in the SOtM card not being recognized. I’m currently testing with the hack that Daniel posted above.

One thing that I did notice which is different with this DAC is the fact that it creates additional devices on the bus:

/:  Bus 05.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/2p, 480M
    |__ Port 1: Dev 2, If 0, Class=Audio, Driver=snd-usb-audio, 480M
    |__ Port 1: Dev 2, If 1, Class=Audio, Driver=snd-usb-audio, 480M
    |__ Port 1: Dev 2, If 2, Class=Human Interface Device, Driver=usbhid, 480M

The Debussy allows you to use the IR remote to feed playback commands to the computer (play/pause, skip, etc) and it does this by creating a separate HID device (basically a keyboard) on the same bus. I do wonder if there’s some kind of conflict here (although I can’t imagine what that would be).

Does the PSA DAC have the same?

11

This is what we see in dmesg when the DAC disconnects and Roon starts skipping tracks:

The (-71) message then continues ad infinitum until the DAC is restarted.

12

This is essentially the same scenario that I’ve been seeing and based on the research that I’ve done there appears to be a known issue (but apparently no known plan to fix) with certain USB2 devices connected to a USB3 bus.

In addition there appear to be some known issues with the TI TUSB73x0 support in the linux driver. This is the chipset used in the SOtM PCIe card.

One workaround appears to be turning off xhci support and that forces the USB controllers into USB2 mode with fallback to the ehci driver. To that end I’ve tried the following:

Remove xhci from the kernel: This worked for the on-board (Intel Q87) ports, but resulted in the SOtM card not being identified at all.

Force the individual controller into USB2 mode (using instructions from the link above): This appears to be controller-specific as it had no impact whatsoever on the SOtM card, but did successfully roll the Intel controllers back to USB2. Did a full register dump of both controllers (before and after) and there was no change on the SOtM card whereas the Intel controllers showed a different IRQ mapping and were registered with ehci.

I still need to test the DAC using one of the onboard ports in both USB3 and USB2 mode in order to see if this is generic to the xhci driver or specific to the TI chipset. I also need to look into disabling xhci in the BIOS, but my guess is that will result in the SOtM card not being seen.

The Debussy is due for an update to its USB receiver in the new year and I’m hoping that this will be the ultimate fix for the problem.

13

At this point I’m convinced that this is an issue with the xhci driver’s support for the TUSB73x0 card. I’ve been running the same configuration using one of the internal (Intel) ports and have had no issues whatsoever. There do appear to be some issues with the TI chipset that need special attention in the driver and they haven’t been addressed to date.

Too bad as the SOtM card is excellent, but it would appear that the combination of that card, linux and the dCS Debussy wasn’t meant to happen.

Oh well, my dCS Network Bridge is supposed to arrive this week so I’m not going to sweat it anymore :slight_smile: