mopidy run in docker on armhf hangs with 100% CPU usage

[mczerski]

I have a armhf armbian bullseye system with mopidy in docker. It was WORKING with gst-plugin-spotify v0.9.1.
After the issue described here happend I had to upgrade gst-plugin-spotify to v0.13.1. Now it is NOT WORKING. I can go to web interface, select spotify song to play and hit play, but after that mopidy process goes 100% CPU and nothing else happens. Anyone has the same issue ?
I created the minimal deockerfile (below):
Dockerfile:

FROM arm32v7/debian:bullseye-slim

RUN apt update && \
    apt install -y \
        mopidy \
        python3-pip

RUN pip install \
    mopidy \
    mopidy-spotify==5.0.0a2 \
    Mopidy-MusicBox-Webclient

COPY gst-plugin-spotify_0.13.1-1_armhf.deb /
RUN dpkg -i /gst-plugin-spotify_0.13.1-1_armhf.deb

COPY mopidy.conf /etc/mopidy/
RUN mkdir -p /var/lib/mopidy/spotify/credentials-cache/
COPY credentials.json /var/lib/mopidy/spotify/credentials-cache/

CMD ["mopidy", "--config", "/etc/mopidy/mopidy.conf"]

mopidy.conf:

[http]
enabled = true
hostname = 0.0.0.0

[spotify]
enabled = true
username = XXX
password = XXX
client_id = XXX
client_secret = XXX
allow_cache = false

docker build --network=host -t test-mopidy-spotify .
docker run -d --rm --network host --name test-mopidy-spotify test-mopidy-spotify

[kingosticks]

Can you provide a log ?

[mczerski]

nothing important in mopidy logs.
In gstreamer logs, with GST_DEBUG=3,spotify:6, after playing the song:

0:00:28.190274119     8  0x15607a0 DEBUG        spotifyaudiosrc audio/spotify/src/spotifyaudiosrc/imp.rs:354:<gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer::subclass::uri_handler::URIHandlerImpl>::set_uri:<source> set URI: spotify:track:71fSn6OIF7HnCbgCzOBqpj
0:00:28.197646613     8 0xf1605380 DEBUG        spotifyaudiosrc audio/spotify/src/common.rs:144:gstspotify::common::Settings::connect_session::{{closure}}:<source> reuse cached credentials for user xzgfvdc9r165xst3txjd0zzua
0:00:28.199231912     8  0x14e4370 WARN                    alsa conf.c:5200:snd_config_expand: alsalib error: Unknown parameters {AES0 0x02 AES1 0x82 AES2 0x00 AES3 0x02}
0:00:28.199311787     8  0x14e4370 WARN                    alsa pcm.c:2660:snd_pcm_open_noupdate: alsalib error: Unknown PCM default:{AES0 0x02 AES1 0x82 AES2 0x00 AES3 0x02}

[mczerski]

also i'm watching cpu usage with htop. it shows that most of the usage is RED - Kernel threads

[kingosticks]

And non-spotify tracks don't have this issue? Do they still have the alsa param errors?

[mczerski]

local files are working and produce such log

0:00:19.831573348     8  0x10fa7a0 WARN                 basesrc gstbasesrc.c:3688:gst_base_src_start_complete:<source> pad not activated yet
0:00:19.837045208     8  0x10fa7a0 WARN                 basesrc gstbasesrc.c:3688:gst_base_src_start_complete:<source> pad not activated yet
0:00:19.849541519     8  0x107e370 WARN                    alsa conf.c:5200:snd_config_expand: alsalib error: Unknown parameters {AES0 0x02 AES1 0x82 AES2 0x00 AES3 0x02}
0:00:19.849691269     8  0x107e370 WARN                    alsa pcm.c:2660:snd_pcm_open_noupdate: alsalib error: Unknown PCM default:{AES0 0x02 AES1 0x82 AES2 0x00 AES3 0x02}
0:00:19.869566657     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TCMP' to GStreamer tag
0:00:19.869673616     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TMED' to GStreamer tag
0:00:19.869730491     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TLAN' to GStreamer tag
0:00:19.869759492     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TDOR' to GStreamer tag
0:00:19.869785325     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'USLT' to GStreamer tag
0:00:19.869937492     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TIPL' to GStreamer tag
0:00:19.869970909     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TXXX' to GStreamer tag
0:00:19.870002826     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:213:gst_tag_from_id3_user_tag: Cannot map ID3v2 user tag 'Script' of type 'TXXX' to GStreamer tag
0:00:19.870073868     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TXXX' to GStreamer tag
0:00:19.870097076     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:213:gst_tag_from_id3_user_tag: Cannot map ID3v2 user tag 'ASIN' of type 'TXXX' to GStreamer tag
0:00:19.870124993     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TXXX' to GStreamer tag
0:00:19.870192910     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:213:gst_tag_from_id3_user_tag: Cannot map ID3v2 user tag 'Artist Credit' of type 'TXXX' to GStreamer tag
0:00:19.870246827     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TXXX' to GStreamer tag
0:00:19.870269994     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:213:gst_tag_from_id3_user_tag: Cannot map ID3v2 user tag 'ALBUMARTISTSORT' of type 'TXXX' to GStreamer tag
0:00:19.870435495     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TXXX' to GStreamer tag
0:00:19.870463912     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:213:gst_tag_from_id3_user_tag: Cannot map ID3v2 user tag 'Album Artist Credit' of type 'TXXX' to GStreamer tag
0:00:19.870514287     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TXXX' to GStreamer tag
0:00:19.870538662     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:213:gst_tag_from_id3_user_tag: Cannot map ID3v2 user tag 'MusicBrainz Album Status' of type 'TXXX' to GStreamer tag
0:00:19.870589746     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TXXX' to GStreamer tag
0:00:19.870614912     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:213:gst_tag_from_id3_user_tag: Cannot map ID3v2 user tag 'MusicBrainz Album Type' of type 'TXXX' to GStreamer tag
0:00:19.870644996     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TXXX' to GStreamer tag
0:00:19.870667454     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:213:gst_tag_from_id3_user_tag: Cannot map ID3v2 user tag 'MusicBrainz Album Release Country' of type 'TXXX' to GStreamer tag
0:00:19.870770746     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TXXX' to GStreamer tag
0:00:19.870937414     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'UFID' to GStreamer tag
0:00:19.870981706     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TXXX' to GStreamer tag
0:00:19.871013748     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TXXX' to GStreamer tag
0:00:19.871043873     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TXXX' to GStreamer tag
0:00:19.871075373     8 0xf2a056c0 FIXME                  id3v2 gstid3tag.c:141:gst_tag_from_id3_tag: Cannot map ID3v2 tag 'TXXX' to GStreamer tag
0:00:19.935132641     8 0xf2009598 WARN         audio-resampler audio-resampler.c:274:convert_taps_gint16_c: can't find exact taps
0:00:19.941701465     8 0xf2a5cc58 WARN                    alsa pcm_hw.c:1359:snd_pcm_hw_get_chmap: alsalib error: Cannot read Channel Map ctl

[mczerski]

I added htop and gdb to docker image to track down what is going on, while the CPU goes 100% this is the state:
htop:

gdb:

(gdb) c
Continuing.
^C
Thread 1 "mopidy" received signal SIGINT, Interrupt.
[Switching to Thread 0xf71ae310 (LWP 1)]
__libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
46	in ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S
(gdb) info thread
  Id   Target Id                                    Frame 
* 1    Thread 0xf71ae310 (LWP 1) "mopidy"           __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  2    Thread 0xf47ba460 (LWP 10) "gmain"           __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  3    Thread 0xf3dff460 (LWP 11) "mopidy"          __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  4    Thread 0xf33ff460 (LWP 12) "mopidy"          __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  5    Thread 0xf29ff460 (LWP 13) "mopidy"          __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  6    Thread 0xf1fff460 (LWP 14) "mopidy"          __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  7    Thread 0xf15ff460 (LWP 15) "mopidy"          __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  8    Thread 0xf0bff460 (LWP 16) "mopidy"          __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  9    Thread 0xef7fe460 (LWP 24) "mopidy"          __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  10   Thread 0xeeffd460 (LWP 25) "mopidy"          __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  11   Thread 0xee7fc460 (LWP 26) "mopidy"          __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:47
  14   Thread 0xeffff460 (LWP 44) "mopidy"          0xed64d908 in ?? () from /usr/lib/arm-linux-gnueabihf/gstreamer-1.0/libgstspotify.so
  15   Thread 0xed431460 (LWP 45) "source:src"      __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  16   Thread 0xecc30460 (LWP 46) "tokio-runtime-w" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:47
  17   Thread 0xec9d6460 (LWP 47) "source:src"      syscall () at ../sysdeps/unix/sysv/linux/arm/syscall.S:37
(gdb) thread 14
[Switching to thread 14 (Thread 0xeffff460 (LWP 44))]
#0  0xed64d908 in ?? () from /usr/lib/arm-linux-gnueabihf/gstreamer-1.0/libgstspotify.so
(gdb) bt
#0  0xed64d908 in ?? () from /usr/lib/arm-linux-gnueabihf/gstreamer-1.0/libgstspotify.so
#1  0x00000000 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) 

``

[mczerski]

I can reproduce the issue with gst-launch command.

First something that works (http stream):

# gst-launch-1.0 playbin uri=http://mp3.polskieradio.pl:8900/
Setting pipeline to PAUSED ...
Pipeline is PREROLLING ...
Got context from element 'source': gst.soup.session=context, session=(SoupSession)NULL, force=(boolean)false;
Redistribute latency...
Pipeline is PREROLLED ...
Prerolled, waiting for buffering to finish...
Setting pipeline to PLAYING ...
New clock: GstAudioSinkClock

and spotify that hangs with 100% CPU usage:

# gst-launch-1.0 playbin uri=spotify:track:3i3P1mGpV9eRlfKccjDjwi?username=$USERNAME\&password=$PASSWORD
Setting pipeline to PAUSED ...
Pipeline is PREROLLING ...

On the other armhf system, without docker:

# gst-launch-1.0 playbin uri=spotify:track:3i3P1mGpV9eRlfKccjDjwi?username=$USERNAME\&password=$PASSWORD
Setting pipeline to PAUSED ...
Pipeline is PREROLLING ...
ERROR: from element /GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin0/GstSpotifyAudioSrc:source: Could not get/set settings from/on resource.
Additional debug info:
audio/spotify/src/spotifyaudiosrc/imp.rs(280): <gstspotify::spotifyaudiosrc::imp::SpotifyAudioSrc as gstreamer_base::subclass::push_src::PushSrcImpl>::create (): /GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin0/GstSpotifyAudioSrc:source:
Permission denied { Login failed with reason: Bad credentials }
ERROR: pipeline doesn't want to preroll.
Setting pipeline to NULL ...
ERROR: from element /GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin0/GstSpotifyAudioSrc:source: Internal data stream error.
Additional debug info:
../libs/gst/base/gstbasesrc.c(3127): gst_base_src_loop (): /GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin0/GstSpotifyAudioSrc:source:
streaming stopped, reason error (-5)
ERROR: pipeline doesn't want to preroll.
Freeing pipeline ...

This does not hang and fails with credentials issue as expected.

[mczerski]

and log with GST_DEBUG=5:
log.txt

after launching the command this is the part of log that keeps repeating endlessly:

0:00:00.405050467 15195 0xac544200 DEBUG                  query gstquery.c:679:gst_query_new_custom: creating new query 0xac611120 position
0:00:00.405152633 15195 0xac544200 DEBUG       GST_ELEMENT_PADS gstelement.c:2051:gst_element_query: send query on element playbin0
0:00:00.405217675 15195 0xac544200 DEBUG                    bin gstbin.c:4337:gst_bin_query:<playbin0> Sending query 0xac611120 (type position) to sink children
0:00:00.405304300 15195 0xac544200 DEBUG             GST_STATES gstbin.c:1996:bin_element_is_sink:<playbin0> child uridecodebin0 is not sink
0:00:00.405341549 15195 0xac544200 DEBUG             GST_STATES gstbin.c:1996:bin_element_is_sink:<playbin0> child playsink is sink
0:00:00.405371383 15195 0xac544200 DEBUG       GST_ELEMENT_PADS gstelement.c:2051:gst_element_query: send query on element playsink
0:00:00.405408883 15195 0xac544200 DEBUG                    bin gstbin.c:4337:gst_bin_query:<playsink> Sending query 0xac611120 (type position) to sink children
0:00:00.405441424 15195 0xac544200 DEBUG             GST_STATES gstbin.c:1996:bin_element_is_sink:<playsink> child streamsynchronizer0 is not sink
0:00:00.405479841 15195 0xac544200 DEBUG                    bin gstbin.c:4360:gst_bin_query:<playsink> query 0xac611120 result 0
0:00:00.405518049 15195 0xac544200 DEBUG                    bin gstbin.c:4360:gst_bin_query:<playbin0> query 0xac611120 result 0