search

hifiberry / hifiberry-os

Linux distribution optimized for audio playback
MIT License
997 stars 125 forks source link

Sound sources are blocking another playback #315

Closed dmnc-net closed 2 years ago

dmnc-net commented 2 years ago

Describe the bug Sound sources are blocking another playback

HiFiBerryOS version 20211105

HiFiBerry sound card AMP2

To Reproduce Steps to reproduce the behavior:

  1. Vollibrespot is playing, trying to play some TTS (text-to-speech) from HomeAssistant thru DLNA without success.
  2. Pausing Spotify playback, trying TTS again with success.
  3. Nothing is playing, trying to play again on Spotify, without success.
  4. The only option to play with other sources (not just Spotify Connect) is to disable DLNA (re-enabling is possible but one can't use it).

Expected behavior The more aggressive takeover of the sound card.

Logs

  1. Vollibrespot is playing, trying to play some TTS from HomeAssistant thru DLNA without success: 
    Dec 13 11:36:08 hifiberry /bin/cat[22598]: pause-all gmediarender (22403): process 21575/vollibres still using the sound card
Dec 13 11:36:08 hifiberry /bin/cat[22613]: pause-all gmediarender (22403): process 21575/vollibres still using the sound card
Dec 13 11:36:08 hifiberry python3[22577]: /opt/hifiberry/bin/pause-all: line 159: syntax error near unexpected token `('
Dec 13 11:36:08 hifiberry python3[22577]: /opt/hifiberry/bin/pause-all: line 159: `echo ""pause-all $PLAYER ($PPID): $DATE1 pause_process done, but playback still active"  | systemd-cat'
  2. Pausing Spotify playback, trying TTS again with success: 
    Dec 13 11:38:05 hifiberry /bin/cat[22693]: pause-all gmediarender (22403): requested pause, but is already using sound card, ignoring
Dec 13 11:38:05 hifiberry gmediarender[22403]: cannot set NULL uri
Dec 13 11:38:05 hifiberry kernel: pcm512x 1-004d: No SCLK, using BCLK: -2
Dec 13 11:38:06 hifiberry python3[353]: WARNING: controller - Metadata without artist, album or title - what's wrong here? [dlna, playing] None: Home Assistant (None) None
Dec 13 11:38:06 hifiberry beocreate2[748]: Source 'dlna' has activated.
Dec 13 11:38:06 hifiberry python3[353]: INFO: http_post - posted metadata update to http://127.0.0.1:80/sources/metadata ({'artist': None, 'title': dbus.String('Home Assistant', variant_level=1), 'albumArtist': None, 'albumTitle': None, 'artUrl': None, 'externalArtUrl': None, 'discNumber': None, 'tracknumber': None, 'playerName': 'dlna', 'playerState': 'playing', 'streamUrl': None, 'playCount': None, 'mbid': None, 'artistmbid': None, 'albummbid': None, 'loved': None, 'wiki': None, 'loveSupported': False, 'tags': [], 'skipped': False, 'host_uuid': None, 'releaseDate': None, 'trackid': None, 'hifiberry_cover_found': False, 'duration': 0, 'time': 0, 'position': 0, 'positionupdate': 1639391886.5285308, 'trackId': None})
Dec 13 11:38:07 hifiberry beocreate2[748]: Source 'dlna' has deactivated.
Dec 13 11:38:07 hifiberry python3[353]: INFO: http_post - posted metadata update to http://127.0.0.1:80/sources/metadata ({'artist': None, 'title': dbus.String('Home Assistant', variant_level=1), 'albumArtist': None, 'albumTitle': None, 'artUrl': None, 'externalArtUrl': None, 'discNumber': None, 'tracknumber': None, 'playerName': 'dlna', 'playerState': 'stopped', 'streamUrl': None, 'playCount': None, 'mbid': None, 'artistmbid': None, 'albummbid': None, 'loved': None, 'wiki': None, 'loveSupported': False, 'tags': [], 'skipped': False, 'host_uuid': None, 'releaseDate': None, 'trackid': None, 'hifiberry_cover_found': False, 'duration': 0, 'time': 0, 'position': 0, 'positionupdate': 1639391887.5967958, 'trackId': None})
  3. Nothing is playing, trying to play again on Spotify, without success. 
    Dec 13 11:42:47 hifiberry systemd[1]: spotify.service: Scheduled restart job, restart counter is at 5.
Dec 13 11:42:47 hifiberry systemd[1]: Stopped Vollibrespot.
Dec 13 11:42:47 hifiberry systemd[1]: Starting Vollibrespot...
Dec 13 11:42:47 hifiberry vollibrespot[23176]: vollibrespot v0.2.2 UNKNOWN UNKNOWN (librespot 1a224a3 2020-10-25) -- Built On 2021-11-05
Dec 13 11:42:47 hifiberry vollibrespot[23176]: Reading Config from "/etc/vollibrespot.conf"
Dec 13 11:42:47 hifiberry vollibrespot[23176]: [Vollibrespot] : Using Alsa backend with device: default
Dec 13 11:42:48 hifiberry restore-volume[23179]: alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock PLL:0' : Device or resource busy
Dec 13 11:42:48 hifiberry restore-volume[23179]: alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock DSP:0' : Device or resource busy
Dec 13 11:42:48 hifiberry restore-volume[23179]: alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock DAC:0' : Device or resource busy
Dec 13 11:42:48 hifiberry restore-volume[23183]: Simple mixer control 'Softvol',0
Dec 13 11:42:48 hifiberry restore-volume[23183]:   Capabilities: volume
Dec 13 11:42:48 hifiberry restore-volume[23183]:   Playback channels: Front Left - Front Right
Dec 13 11:42:48 hifiberry restore-volume[23183]:   Capture channels: Front Left - Front Right
Dec 13 11:42:48 hifiberry restore-volume[23183]:   Limits: 0 - 255
Dec 13 11:42:48 hifiberry restore-volume[23183]:   Front Left: 255 [100%]
Dec 13 11:42:48 hifiberry restore-volume[23183]:   Front Right: 255 [100%]
Dec 13 11:42:48 hifiberry systemd[1]: Started Vollibrespot.
Dec 13 11:42:53 hifiberry vollibrespot[23176]: [Vollibrespot] : Connecting to AP "104.199.65.124:443"
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Authenticated as "dmnc_net" !
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Setting up new mixer: card:hw:0 mixer:Digital index:0
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Alsa Mixer info min: 0 (MilliBel(-9999999)[dB]) -- max: 207 (MilliBel(0)[dB]) HW: true
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Using alsa sink
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Metadata pipe established
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Country: "CZ"
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Event: Volume { volume_to_mixer: 32767 }
Dec 13 11:42:54 hifiberry python3[353]: ERROR: vollibrespot - Don't know what to do with vollibrespot v0.2.2
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Fetching autoplay context uri
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Event: SessionActive { became_active_at: 1639392174351 }
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : SessionActive!
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: xxx, audio_type: Track } }
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: xxx, audio_type: Track } }
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Autoplay uri resolved to <"spotify:station:track:4Umy8mk1bBdWYoxKB8354f">
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Resolving uri "spotify:station:track:4Umy8mk1bBdWYoxKB8354f"
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Loading <Asdfmovie6 Song> with Spotify URI <spotify:track:4Umy8mk1bBdWYoxKB8354f>
Dec 13 11:42:54 hifiberry vollibrespot[23176]: [Vollibrespot] : Event: GotToken { token: Token { access_token: "xxx", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } }
Dec 13 11:42:54 hifiberry python3[353]: INFO: vollibrespot - got access_token update
Dec 13 11:42:54 hifiberry beocreate2[748]: Source 'spotify' has activated.
...
Dec 13 11:42:55 hifiberry vollibrespot[23176]: [Vollibrespot] : <Asdfmovie6 Song> (126666 ms) loaded
Dec 13 11:42:56 hifiberry /bin/cat[23221]: pause-all vollibrespot (23176): process 22403/gmediaren still using the sound card
Dec 13 11:42:56 hifiberry /bin/cat[23236]: pause-all vollibrespot (23176): process 22403/gmediaren still using the sound card
Dec 13 11:42:56 hifiberry vollibrespot[23176]: [Vollibrespot] : couldn't stop other players using pause-all
Dec 13 11:42:56 hifiberry vollibrespot[23176]: [Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy'
Dec 13 11:42:56 hifiberry vollibrespot[23176]: [Vollibrespot] : Could not start audio: Alsa error: PCM open failed
Dec 13 11:42:57 hifiberry /bin/cat[23258]: pause-all vollibrespot (23176): process 22403/gmediaren still using the sound card
Dec 13 11:42:57 hifiberry /bin/cat[23273]: pause-all vollibrespot (23176): process 22403/gmediaren still using the sound card
Dec 13 11:42:57 hifiberry vollibrespot[23176]: [Vollibrespot] : couldn't stop other players using pause-all
Dec 13 11:42:57 hifiberry vollibrespot[23176]: [Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy'
Dec 13 11:42:57 hifiberry vollibrespot[23176]: [Vollibrespot] : Could not start audio: Alsa error: PCM open failed
Dec 13 11:42:58 hifiberry /bin/cat[23295]: pause-all vollibrespot (23176): process 22403/gmediaren still using the sound card
Dec 13 11:42:58 hifiberry /bin/cat[23310]: pause-all vollibrespot (23176): process 22403/gmediaren still using the sound card
Dec 13 11:42:58 hifiberry vollibrespot[23176]: [Vollibrespot] : couldn't stop other players using pause-all
Dec 13 11:42:58 hifiberry vollibrespot[23176]: [Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy'
Dec 13 11:42:58 hifiberry vollibrespot[23176]: [Vollibrespot] : Could not start audio: Alsa error: PCM open failed
Dec 13 11:42:58 hifiberry vollibrespot[23176]: thread '<unnamed>' panicked at 'called `Option::unwrap()` on a `None` value', /home/matuschd/buildroot-3/host/share/cargo/git/checkouts/librespot-e4d7c35a023053af/1a224a3/playback/src/audio_backend/alsa.rs:138:35
Dec 13 11:42:58 hifiberry vollibrespot[23176]: stack backtrace:
Dec 13 11:42:58 hifiberry vollibrespot[23176]:    0:   0x9cc770 - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:    1:   0x9f1b20 - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:    2:   0x9c4b98 - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:    3:   0x9cef28 - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:    4:   0x9ce8c0 - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:    5:   0x9cf588 - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:    6:   0x9cf0cc - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:    7:   0x9cccec - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:    8:   0x9cf04c - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:    9:   0x49a6ac - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:   10:   0x49a608 - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:   11:   0x5de294 - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:   12:   0x5bb444 - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:   13:   0x4db770 - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:   14:   0x4c75a8 - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:   15:   0x4ed220 - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:   16:   0x4f810c - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:   17:   0x4e7324 - <unknown>
Dec 13 11:42:58 hifiberry vollibrespot[23176]:   18:   0x9d5cf8 - <unknown>

Additional context In multiuser (family, incl. non-experienced users) and/or multisource environment (Spotify Connect, HomeAssistant - DLNA for automations, Internet Radio, etc.) this is a deal-breaking behavior.

I found some similarities in #314 and #312

hifiberry commented 2 years ago

Duplicate of https://github.com/hifiberry/hifiberry-os/issues/312

dmnc-net commented 2 years ago

As a quick fix, just remove one of the double-quotes at the beginning of line 159 in /opt/hifberry/bin/pause-all

The quick fix mentioned in #312 solved just 1/2 of problems:

  1. when playing on Spotify, HA/DLNA will interrupt the playback ... ✅
  2. but I can't resume playback on Spotify (or any other source) because GMediaRender is still blocking the sound card
  3. I still have to disable/enable DLNA source in the UI
Dec 13 20:33:32 hifiberry /bin/cat[32010]: pause-all vollibrespot (31885): process 31539/gmediaren still using the sound card
Dec 13 20:33:33 hifiberry /bin/cat[32025]: pause-all vollibrespot (31885): process 31539/gmediaren still using the sound card
Dec 13 20:33:33 hifiberry /bin/cat[32027]: pause-all vollibrespot (31885): 20211213-203332 pause_process done, but playback still active

@hifiberry please re-value this issue, is it really just a duplicate of #312?