[PROBLEM] Spotify unreachable after DAC input change

[tdubb]

TL: DR Spotify Connect becomes unreachable after the input of my DAC is changed away from the USB (RPi input) when connected to Spotify or if I try to connect to when the input is not USB.

Hey All, I'm trying to identify/diagnose an issue I have come across in moOde while using Spotify Connect. I am not sure if this issue is at the librespot or moOde itselt. I do know that I am fairly ignorant at debugging software issues.

Setup:
Raspi: Pi-4B 1.5 2GB
Audio: SMSL USB AUDIO
moOde 8.1.2
Source: Spotify Connect
DAC: S.M.S.L. DO100 connected through USB

Issue:
If DAC is set to input other than USB (RPi connection), Spotify Connect "errors out". At this point, the moOde Spotify Connect device is no longer available.

Steps to reproduce:
DAC set to USB, Spotify not connected to moOde:

1. Connect Spotify to moOde Connect device.
   
2. Change input on DAC away from USB 
   -->Spotify pauses and disconnects from moOde 
   
3. Change input on DAC back to USB (as if I am going to listen to music again)
   

DAC set to input other than USB, Spotify not connected to moOde:

1. Connect Spotify to moOde Connect device.
   --> Spotify does not connect to moOde.
   

At this point, in either mode, moOde is no longer available to connect to from Spotify, even if the DAC is set back to the USB input.

Workarounds:
Avoiding the issue:

• Verify that DAC is set to USB input before connecting Spotify.
  
• Disconnecting from moOde Spotify device before changing DAC input.
  

Resetting the issue:

• Click "disconnect" from the "Spotify Active" screen of the moOde web ui.
  
• Restart RPi
  

It appears that the player handles this with the internal player when playing internet radio stations.

[Tim Curtis]

IIRC none of the renderers are able to recover from loss of their USB audio output. MPD can generally recover but in my experience it's not 100% reliable.

Also be aware that there is a significant risk that when a USB audio connection goes away while a renderer is connected to moOde that ALSA volume is left at 0dB 100% volume :-0

[tdubb]

Is this something that can be detected and the renderer reset?

[Tim Curtis]

If you still had to restart the Pi after clicking Disconnect it would suggest that a soft "renderer restart" doesn't resolve the issue after the USB audio link is restored by Linux.

It's really the application itself i.e., librespot, shairport-sync, etc., that has to be able to gracefully handle the scenario where the audio interface goes away.

[tdubb]

If you still had to restart the Pi after clicking Disconnect it would suggest that a soft "renderer restart" doesn't resolve the issue after the USB audio link is restored by Linux.

The Pi doesn't need a restart, just to log onto the web ui and click Disconnect has fixed it every time. A Pi restart also resolves the issue, but not necessary. 

It's really the application itself i.e., librespot, shairport-sync, etc., that has to be able to gracefully handle the scenario where the audio interface goes away.

How would I go about capturing logs, specifically for librespot to report a bug/feature request? Steps are very repeatable. Maybe @roderickvd can shed some light? Thanks.

[Tim Curtis]

You have to run moOde's librespot command from the cmd line.

Follow steps starting with this post
https://moodeaudio.org/forum/showthread....9#pid42459

[tdubb]

As you expected. If I change the DAC's input (remove the audio device), I get:

Code:

[2022-08-31T22:09:38Z WARN  librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EIO: I/O error'
[2022-08-31T22:09:38Z ERROR librespot_playback::player] Audio Sink Error On Write: <AlsaSink> ALSA function 'snd_pcm_recover' failed with error 'EIO: I/O error'
pi@moode:~ $

If I try to connect to the Spotify device when the USB audio is not there, i get:

Code:

[2022-08-31T22:07:05Z TRACE librespot_playback::player] == Starting sink ==
ALSA lib pcm_hw.c:1829:(_snd_pcm_hw_open) Invalid value for card
[2022-08-31T22:07:05Z ERROR librespot_playback::player] Audio Sink Error Connection Refused: <AlsaSink> Device _audioout May be Invalid, Busy, or Already in Use, ALSA function 'snd_pcm_open' failed with error 'ENOENT: No such file or directory'
pi@moode:~ $

I noticed that if librespot is run and killed from the command line, even though it says it is being killed "gracefully".

Code:

[2022-08-31T23:06:05Z INFO  librespot::player_event_handler] Running ["/var/local/www/commandw/spotevent.sh"] with environment variables {"POSITION_MS": "5", "PLAYER_EVENT": "paused", "TRACK_ID": "4USztpjKZRDx6XQmxWZkDN", "DURATION_MS": "301693"}
amixer: Unable to find simple control 'PCM',0

^C[2022-08-31T23:06:15Z INFO  librespot] Gracefully shutting down
pi@moode:~ $

In all of these modes, librespot is dying and not sending events or messages back to spotevent.sh, so moode stays stuck thinking it is playing Spotify. This may lead to more philisophical questions:

• Should librespot, or other renderers announce when they are shutting down? What about if something external kills it for some reason?
  
• Should moode track the renderers (processes) it has spun up? If they have gone away, should they be restarted?
  

[Tim Curtis]

As you expected. If I change the DAC's input (remove the audio device), I get:

Code:

[2022-08-31T22:09:38Z WARN  librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function 'snd_pcm_writei' failed with error 'EIO: I/O error'
[2022-08-31T22:09:38Z ERROR librespot_playback::player] Audio Sink Error On Write: <AlsaSink> ALSA function 'snd_pcm_recover' failed with error 'EIO: I/O error'
pi@moode:~ $

If I try to connect to the Spotify device when the USB audio is not there, i get:

Code:

[2022-08-31T22:07:05Z TRACE librespot_playback::player] == Starting sink ==
ALSA lib pcm_hw.c:1829:(_snd_pcm_hw_open) Invalid value for card
[2022-08-31T22:07:05Z ERROR librespot_playback::player] Audio Sink Error Connection Refused: <AlsaSink> Device _audioout May be Invalid, Busy, or Already in Use, ALSA function 'snd_pcm_open' failed with error 'ENOENT: No such file or directory'
pi@moode:~ $

I noticed that if librespot is run and killed from the command line, even though it says it is being killed "gracefully".

Code:

[2022-08-31T23:06:05Z INFO  librespot::player_event_handler] Running ["/var/local/www/commandw/spotevent.sh"] with environment variables {"POSITION_MS": "5", "PLAYER_EVENT": "paused", "TRACK_ID": "4USztpjKZRDx6XQmxWZkDN", "DURATION_MS": "301693"}
amixer: Unable to find simple control 'PCM',0

^C[2022-08-31T23:06:15Z INFO  librespot] Gracefully shutting down
pi@moode:~ $

In all of these modes, librespot is dying and not sending events or messages back to spotevent.sh, so moode stays stuck thinking it is playing Spotify. This may lead to more philisophical questions:

• Should librespot, or other renderers announce when they are shutting down? What about if something external kills it for some reason?
  
• Should moode track the renderers (processes) it has spun up? If they have gone away, should they be restarted?
  

Ideally the app should not abort or hang when the audio interface goes away but instead it should clean up it's side of the interface and then wait for a "play" command. When that happens it should try to open the interface and then either start playing or go back into the cleanup and wait state.

[roderickvd]

If you file this on our librespot GitHub repository here: https://github.com/librespot-org/librespot/issues someone may want take a look at it. Don't forget to include those logs, they're very helpful and quite necessary.

Edit: indeed librespot assumes that once it opens a playback device, it will remain there, and might today not try to gracefully reconnect. I think the case of DAC input switching, with the DAC turning off USB when on another interface, is a fair one.

[tdubb]

If you file this on our librespot GitHub repository here: https://github.com/librespot-org/librespot/issues someone may want take a look at it. Don't forget to include those logs, they're very helpful and quite necessary.

Sounds good. https://github.com/librespot-org/librespot/issues/1057