Problem: Spotify playing slow - Printable Version

[PROBLEM] Spotify playing slow - Printable Version

+- Moode Forum (https://moodeaudio.org/forum)
+-- Forum: moOde audio player (https://moodeaudio.org/forum/forumdisplay.php?fid=3)
+--- Forum: Support (https://moodeaudio.org/forum/forumdisplay.php?fid=7)
+--- Thread: [PROBLEM] Spotify playing slow (/showthread.php?tid=5540)

Pages: 1 2

Spotify playing slow - vondewall - 04-25-2023

Anyone else experiencing problems with Spotify streaming in Moode? All of a sudden it plays slower. Not much but slow enough for it to be noticeable.
I am running Moode latest version on a RPI3.
Suggestion on to solve this is appreciated!

RE: Spotify playing slow - the_bertrum - 04-25-2023

I've not noticed any thing like that myself. If you begin playing on another device (your phone for example) then switch to moOde does it slow then mid stream as it were?

RE: Spotify playing slow - DRONE7 - 04-25-2023

How about some info as to your DAC etc...? as there are no other post on this issue it may be hardware.

Reboot and post the startup log.

moodeutl -l

RE: Spotify playing slow - vondewall - 04-25-2023

(04-25-2023, 08:07 AM)DRONE7 Wrote: How about some info as to your DAC etc...? as there are no other post on this issue it may be hardware.

Reboot and post the startup log.

moodeutl -l

Hi, I have a Hifiberry Digi2 PRO
I will post the log when I get home

RE: Spotify playing slow - vondewall - 04-25-2023

(04-25-2023, 06:31 AM)the_bertrum Wrote: I've not noticed any thing like that myself. If you begin playing on another device (your phone for example) then switch to moOde does it slow then mid stream as it were?

Yes that’s correct. And the problem started after I did a new install of Moode

RE: Spotify playing slow - the_bertrum - 04-26-2023

(04-25-2023, 05:29 PM)vondewall Wrote:
(04-25-2023, 06:31 AM)the_bertrum Wrote: I've not noticed any thing like that myself. If you begin playing on another device (your phone for example) then switch to moOde does it slow then mid stream as it were?

Yes that’s correct. And the problem started after I did a new install of Moode

I've just done the same test myself to me sure I hadn't just missed it and I definitely don't see the issue in my set up. Can you also please post the spotify renderer settings you are using when you post the startup log?

Thanks.

RE: Spotify playing slow - vondewall - 04-26-2023

(04-25-2023, 02:18 AM)vondewall Wrote: Anyone else experiencing problems with Spotify streaming in Moode? All of a sudden it plays slower. Not much but slow enough for it to be noticeable.
I am running Moode latest version on a RPI3.
Suggestion on to solve this is appreciated!

Code:
20230426 174049 worker: --

20230426 174049 worker: -- Start moOde 8 series

20230426 174049 worker: --

20230426 174049 worker: Successfully daemonized

20230426 174049 worker: Waiting for Linux startup...

20230426 174108 worker: Linux startup complete

20230426 174108 worker: Boot config backed up

20230426 174113 worker: File check (OK)

20230426 174115 worker: Session vacuumed

20230426 174115 worker: Session loaded

20230426 174115 worker: Debug logging (ON)

20230426 174115 worker: --

20230426 174115 worker: -- Audio debug

20230426 174115 worker: --

20230426 174115 worker: ALSA cards: (0:sndrpihifiberry | 1:Plus | 2:empty | 3:empty

20230426 174115 worker: MPD config: (0:hifiberry-digi | mixer:(none) | card:0)

20230426 174115 worker: ALSA mixer actual (none)

20230426 174115 worker: ALSA volume (none)

20230426 174115 worker: --

20230426 174115 worker: -- System

20230426 174115 worker: --

20230426 174117 worker: Host      (moode1)

20230426 174117 worker: Hardware  (Pi-3B+ 1.3 1GB)

20230426 174117 worker: moOde     (8.3.2 2023-04-21)

20230426 174117 worker: RaspiOS   (11.5)

20230426 174117 worker: Kernel    (6.1.21-v8+ #1642)

20230426 174117 worker: Procarch  (aarch64, 64-bit)

20230426 174117 worker: MPD ver   (0.23.12)

20230426 174117 worker: CPU gov   (ondemand)

20230426 174117 worker: Userid    (pi)

20230426 174117 worker: Homedir   (/home/pi)

20230426 174118 worker: USB boot  (enabled)

20230426 174118 worker: File sys  (expanded)

20230426 174118 worker: HDMI port (Off)

20230426 174118 worker: Sys LED0  (On)

20230426 174118 worker: Sys LED1  (On)

20230426 174118 worker: --

20230426 174118 worker: -- Network

20230426 174118 worker: --

20230426 174118 worker: eth0 adapter exists

20230426 174118 worker: eth0 address check (Off)

20230426 174118 worker: IP addr (192.168.2.43)

20230426 174118 worker: Netmask (255.255.255.0)

20230426 174118 worker: Gateway (192.168.2.1)

20230426 174118 worker: Pri DNS (192.168.2.1)

20230426 174118 worker: Domain  ()

20230426 174119 worker: wlan0 adapter exists

20230426 174119 worker: wlan0 country (SE)

20230426 174119 worker: wlan0 configured SSID (Full fart)

20230426 174119 worker: wlan0 SSID alternates (None)

20230426 174119 worker: wlan0 router mode (Off)

20230426 174119 worker: wlan0 address check (up to 90 secs)

20230426 174119 worker: wlan0 check 1 for IP address

20230426 174121 worker: wlan0 check 2 for IP address

20230426 174123 worker: wlan0 check 3 for IP address

20230426 174125 worker: wlan0 check 4 for IP address

20230426 174127 worker: wlan0 check 5 for IP address

20230426 174129 worker: wlan0 check 6 for IP address

20230426 174131 worker: wlan0 check 7 for IP address

20230426 174133 worker: wlan0 check 8 for IP address

20230426 174135 worker: wlan0 check 9 for IP address

20230426 174137 worker: wlan0 check 10 for IP address

20230426 174139 worker: wlan0 check 11 for IP address

20230426 174141 worker: wlan0 check 12 for IP address

20230426 174143 worker: wlan0 check 13 for IP address

20230426 174145 worker: wlan0 check 14 for IP address

20230426 174147 worker: wlan0 check 15 for IP address

20230426 174149 worker: wlan0 check 16 for IP address

20230426 174152 worker: wlan0 check 17 for IP address

20230426 174154 worker: wlan0 check 18 for IP address

20230426 174156 worker: wlan0 check 19 for IP address

20230426 174158 worker: wlan0 check 20 for IP address

20230426 174200 worker: wlan0 check 21 for IP address

20230426 174202 worker: wlan0 check 22 for IP address

20230426 174204 worker: wlan0 check 23 for IP address

20230426 174206 worker: wlan0 check 24 for IP address

20230426 174208 worker: wlan0 check 25 for IP address

20230426 174210 worker: wlan0 check 26 for IP address

20230426 174212 worker: wlan0 check 27 for IP address

20230426 174214 worker: wlan0 check 28 for IP address

20230426 174216 worker: wlan0 check 29 for IP address

20230426 174218 worker: wlan0 check 30 for IP address

20230426 174220 worker: wlan0 check 31 for IP address

20230426 174222 worker: wlan0 check 32 for IP address

20230426 174224 worker: wlan0 check 33 for IP address

20230426 174227 worker: wlan0 check 34 for IP address

20230426 174229 worker: wlan0 check 35 for IP address

20230426 174231 worker: wlan0 check 36 for IP address

20230426 174233 worker: wlan0 check 37 for IP address

20230426 174235 worker: wlan0 check 38 for IP address

20230426 174237 worker: wlan0 check 39 for IP address

20230426 174239 worker: wlan0 check 40 for IP address

20230426 174241 worker: wlan0 check 41 for IP address

20230426 174243 worker: wlan0 check 42 for IP address

20230426 174245 worker: wlan0 check 43 for IP address

20230426 174247 worker: wlan0 check 44 for IP address

20230426 174249 worker: wlan0 check 45 for IP address

20230426 174251 worker: wlan0 address not assigned

20230426 174251 worker: wlan0 AP mode not activated, eth0 active but Router mode is Off

20230426 174251 worker: wlan0 address not assigned

20230426 174251 worker: --

20230426 174251 worker: -- Software update

20230426 174251 worker: --

20230426 174251 worker: Automatic check (On)

20230426 174251 worker: Checking for available update...

20230426 174252 worker: Software is up to date

20230426 174252 worker: --

20230426 174252 worker: -- Audio config

20230426 174252 worker: --

20230426 174252 worker: MPD conf updated

20230426 174252 worker: ALSA card number (0)

20230426 174252 worker: MPD audio output (None)

20230426 174252 worker: Audio formats (S16_LE, S24_LE)

20230426 174252 worker: ALSA mixer name (none)

20230426 174252 worker: MPD mixer type (software)

20230426 174253 worker: Hdwr volume controller not detected

20230426 174253 worker: ALSA output mode (Default: plughw)

20230426 174253 worker: ALSA loopback (Off)

20230426 174253 worker: Reset renderer active flags

20230426 174253 worker: CamillaDSP configuration (off)

20230426 174253 worker: CamillaDSP volume sync   (off)

20230426 174253 worker: CamillaDSP volume range  (60)

20230426 174253 worker: --

20230426 174253 worker: -- File sharing

20230426 174253 worker: --

20230426 174254 worker: SMB file sharing (Off)

20230426 174254 worker: NFS file sharing (On)

20230426 174254 worker: --

20230426 174254 worker: -- MPD startup

20230426 174254 worker: --

20230426 174255 worker: MPD started

20230426 174255 worker: MPD accepting connections

20230426 174255 worker: MPD output 1 ALSA Default (On)

20230426 174255 worker: MPD output 2 ALSA Bluetooth (Off)

20230426 174255 worker: MPD output 3 HTTP Server (Off)

20230426 174255 worker: MPD crossfade (off)

20230426 174255 worker: MPD ignore CUE files (yes)

20230426 174255 worker: --

20230426 174255 worker: -- Music sources

20230426 174255 worker: --

20230426 174255 worker: USB sources

20230426 174255 worker: No drives found

20230426 174255 worker: NAS sources

20230426 174255 worker: Musik

20230426 174256 worker: Mount (mount -t nfs -o soft,timeo=10,retrans=1,ro,nolock "192.168.2.59:/volume1/Musik" "/mnt/NAS/Musik")

20230426 174256 worker: Mount all submitted

20230426 174256 worker: --

20230426 174256 worker: -- Feature availability

20230426 174256 worker: --

20230426 174256 worker: Input select (available)

20230426 174256 worker: Input (MPD)

20230426 174256 worker: Output (hifiberry-digi)

20230426 174256 worker: Bluetooth (available)

20230426 174256 startAirPlay(): (/usr/bin/shairport-sync -vv -a "Moode1 Airplay" -- -d _audioout > /var/log/shairport-sync.log 2>&1 &)

20230426 174256 worker: AirPlay renderer (available: started)

20230426 174256 startSpotify(): (librespot --name "Moode1 Spotify" --bitrate 160 --format S16 --ap-port 13561  --mixer softvol --initial-volume 0 --volume-ctrl log --volume-range 60 --cache /var/local/www/spotify_cache --disable-audio-cache --backend alsa --device "_audioout" --onevent /var/local/www/commandw/spotevent.sh > /dev/null 2>&1 &)

20230426 174256 worker: Spotify renderer (available: started)

20230426 174256 worker: Squeezelite (available)

20230426 174256 worker: RoonBridge renderer (not installed)

20230426 174256 worker: Multiroom sender (available)

20230426 174256 worker: Multiroom receiver (available)

20230426 174256 worker: UPnP renderer (available: started)

20230426 174256 worker: DLNA server (available)

20230426 174256 worker: GPIO button handler (available)

20230426 174256 worker: Stream recorder (available: not installed)

20230426 174256 worker: HTTPS-Only mode (n/a)

20230426 174256 worker: --

20230426 174256 worker: -- Other

20230426 174256 worker: --

20230426 174256 worker: USB volume knob (Off)

20230426 174256 worker: Shellinabox SSH started

20230426 174256 worker: USB auto-mounter (udisks-glue)

20230426 174256 worker: Saved MPD vol level (0)

20230426 174256 worker: Preamp volume level (0)

20230426 174257 worker: MPD volume level (0) restored

20230426 174257 worker: ALSA volume level (None)

20230426 174257 worker: Auto-play (Off)

20230426 174258 worker: LocalUI (Off)

20230426 174258 worker: Automatic CoverView (Off)

20230426 174258 worker: On-screen keyboard (Off)

20230426 174258 worker: Library scope (all)

20230426 174258 worker: View reset to playback

20230426 174258 worker: Maintenance interval (360 minutes)

20230426 174258 worker: Screen saver activation (Never)

20230426 174258 phpSession(get_status): status=PHP_SESSION_ACTIVE

20230426 174258 worker: Session permissions (OK)

20230426 174258 worker: --

20230426 174258 worker: -- Startup complete 

20230426 174258 worker: --

20230426 174258 worker: Mount monitor (started)

20230426 174258 worker: Watchdog monitor (started)

20230426 174258 worker: Ready

20230426 174258 waitWorker(): Start (sys-config, w_active=1)

20230426 174258 waitWorker(): Start (sys-config, w_active=1)

20230426 174259 waitWorker(): Start (sys-config, w_active=1)

20230426 174259 waitWorker(): Wait  (1)

20230426 174259 waitWorker(): Wait  (1)

20230426 174300 waitWorker(): Wait  (1)

20230426 174300 waitWorker(): Wait  (2)

20230426 174300 waitWorker(): Wait  (2)

20230426 174301 waitWorker(): Wait  (2)

20230426 174301 worker: Job clearsyslogs

20230426 174301 waitWorker(): Wait  (3)

20230426 174301 waitWorker(): End   (sys-config, w_active=0)

20230426 174301 waitWorker(): Wait  (3)

20230426 174301 waitWorker(): End   (sys-config, w_active=0)

20230426 174302 waitWorker(): Wait  (3)

20230426 174302 waitWorker(): End   (sys-config, w_active=0)

20230426 174302 waitWorker(): Start (sys-config, w_active=0)

20230426 174302 waitWorker(): End   (sys-config, w_active=0)

RE: Spotify playing slow - TheOldPresbyope - 04-26-2023

@vondewall

I just tried to repo with the Spotify app on my iPad and moOde 8.3.1 running on an RPi3A with USB output. I accepted all the default settings for tthe Spotify renderer.

Like @the_bertrum I haven't noticed a slowdown when I switch the Spotify "current device" between the iPad and the moOde player.

You might try invoking librespot in verbose reporting mode and looking to see if there's any messages that look relevant. [Truth in advertising: I don't know what "smoking gun" message to look for.]

Here, for example, is a session where I first killed the running instances of librespot, then manually invoked it from the command line with the same options moOde uses plus the verbose option. [Note- adding the verbose option could also be done by hand-editing the file /var/www/inc/renderer.php but I dislike doing that for a quick-n-dirty test.]

I'm experimenting on a player with hostname m832p3a. To make this more readable I inserted shell comment lines and blank lines after the fact. I obfuscated the authentication token which appears in three places.

Code:
# check the Spotify renderer has been enabled and is running in moOde

pi@m832p3a:~ $ ps aux|grep -m 1 librespot

root     2063374  0.0  1.0  12352  4632 ?        S    15:40   0:00 sudo librespot --name m832p3a Spotify --bitrate 160 --format S16 --ap-port 13561 --mixer softvol --initial-volume 0 --volume-ctrl log --volume-range 60 --cache /var/local/www/spotify_cache --disable-audio-cache --backend alsa --device _audioout --onevent /var/local/www/commandw/spotevent.sh

pi@m832p3a:~ $

# kill the running instances

pi@m832p3a:~ $ sudo killall librespot

pi@m832p3a:~ $

# copy the invocation portion of the ps output above and append --verbose

#hit enter when done editing the line

pi@m832p3a:~ $ sudo librespot --name m832p3a Spotify --bitrate 160 --format S16 --ap-port 13561 --mixer softvol --initial-volume 0 --volume-ctrl log --volume-range 60 --cache /var/local/www/spotify_cache --disable-audio-cache --backend alsa --device _audioout --onevent /var/local/www/commandw/spotevent.sh --verbose

[2023-04-26T19:49:29Z INFO  librespot] librespot 0.4.2 22f8aed (Built on 2022-08-18, Build ID: LQ4hikXT, Profile: release)

[2023-04-26T19:49:29Z TRACE librespot] Command line argument(s):

[2023-04-26T19:49:29Z TRACE librespot]         name "m832p3a"

[2023-04-26T19:49:29Z TRACE librespot]         bitrate "160"

[2023-04-26T19:49:29Z TRACE librespot]         format "S16"

[2023-04-26T19:49:29Z TRACE librespot]         ap-port "13561"

[2023-04-26T19:49:29Z TRACE librespot]         mixer "softvol"

[2023-04-26T19:49:29Z TRACE librespot]         initial-volume "0"

[2023-04-26T19:49:29Z TRACE librespot]         volume-ctrl "log"

[2023-04-26T19:49:29Z TRACE librespot]         volume-range "60"

[2023-04-26T19:49:29Z TRACE librespot]         cache "/var/local/www/spotify_cache"

[2023-04-26T19:49:29Z TRACE librespot]         disable-audio-cache

[2023-04-26T19:49:29Z TRACE librespot]         backend "alsa"

[2023-04-26T19:49:29Z TRACE librespot]         device "_audioout"

[2023-04-26T19:49:29Z TRACE librespot]         onevent "/var/local/www/commandw/spotevent.sh"

[2023-04-26T19:49:29Z TRACE librespot]         verbose

[2023-04-26T19:49:29Z TRACE librespot] Using cached credentials.

[2023-04-26T19:49:29Z DEBUG librespot_discovery::server] Zeroconf server listening on 0.0.0.0:35283

[2023-04-26T19:49:29Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:4070

[2023-04-26T19:49:29Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:443

[2023-04-26T19:49:29Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:80

[2023-04-26T19:49:29Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443

[2023-04-26T19:49:29Z WARN  librespot_core::apresolve] Failed to resolve Access Point: Unable to resolve any viable access points.

[2023-04-26T19:49:29Z WARN  librespot_core::apresolve] Using fallback "ap.spotify.com:443"

[2023-04-26T19:49:29Z INFO  librespot_core::session] Connecting to AP "ap.spotify.com:443"

[2023-04-26T19:49:30Z INFO  librespot_core::session] Authenticated as "xxxxxxxxxxxxxxxxxxxxxxxxx" !

[2023-04-26T19:49:30Z DEBUG librespot_core::session] new Session[0]

[2023-04-26T19:49:30Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)

[2023-04-26T19:49:30Z DEBUG librespot_connect::spirc] new Spirc[0]

[2023-04-26T19:49:30Z DEBUG librespot_connect::spirc] canonical_username: xxxxxxxxxxxxxxxxxxxxxxxxx

[2023-04-26T19:49:30Z DEBUG librespot::component] new MercuryManager

[2023-04-26T19:49:30Z DEBUG librespot_playback::player] new Player[0]

[2023-04-26T19:49:30Z INFO  librespot_playback::convert] Converting with ditherer: tpdf

[2023-04-26T19:49:30Z INFO  librespot_playback::audio_backend::alsa] Using AlsaSink with format: S16

[2023-04-26T19:49:30Z DEBUG librespot_playback::player] command=AddEventSender

[2023-04-26T19:49:30Z DEBUG librespot_playback::player] command=VolumeSet(0)

[2023-04-26T19:49:30Z INFO  librespot::player_event_handler] Running ["/var/local/www/commandw/spotevent.sh"] with environment variables {"PLAYER_EVENT": "volume_set", "VOLUME": "0"}

[2023-04-26T19:49:30Z DEBUG librespot_core::session] Session[0] strong=3 weak=2

[2023-04-26T19:49:30Z INFO  librespot_core::session] Country: "US"

[2023-04-26T19:49:30Z DEBUG librespot_core::mercury] subscribed uri=hm://remote/user/xxxxxxxxxxxxxxxxxxxxxxxxxx/ count=0

[2023-04-26T19:49:30Z DEBUG librespot_connect::spirc] kMessageTypeNotify "iPad" ca1cc6b093358f429465ecd9d8e30675fd969999 1058874520 1682538570121 kPlayStatusStop

[2023-04-26T19:49:30Z DEBUG librespot_connect::spirc] kMessageTypeNotify "Living Room" c6885b99aa7fa98242e84f6070c43c4ffd0687df 1058874520 1682538570121 kPlayStatusStop

At this point, librespot is running and outputting its messages directly to the command line. If you were so inclined, you could instead redirect the output to a log file.

If i start playing a track in Spotify on the iPad and then switch the "current device" to m832p3a I see the following output on the command line

Code:
2023-04-26T20:01:01Z DEBUG librespot_connect::spirc] kMessageTypeNotify "iPad" ca1cc6b093358f429465ecd9d8e30675fd969999 1059565993 1682539261594 kPlayStatusStop

[2023-04-26T20:01:07Z DEBUG librespot_connect::spirc] kMessageTypeLoad "iPad" ca1cc6b093358f429465ecd9d8e30675fd969999 1059571542 1682539261594 kPlayStatusPlay

[2023-04-26T20:01:07Z DEBUG librespot_connect::spirc] State: context_uri: "spotify:album:2EtkrLObwfJ8cdgbJXz2lP" index: 1 position_ms: 11346 status: kPlayStatusPlay position_measured_at: 1682539267214 context_description: "" shuffle: false repeat: false playing_from_fallback: true row: 0 playing_track_index: 1 track {gid: "5S\367l\374\230OF\253-Q\337\024\272U\264"} track {gid: "\257\310\214\240\306*E\241\224^\275ckF\221\025"} track {gid: "\234n\2229\036\333GP\237\336x\337\355\244}9"} track {gid: "\312\310\350\332[;Ga\267\205>\030\0056 h"} track {gid: "9,\005+~\356A\374\267\343!@\255^\225="} track {gid: "\320\271\324,\370\326F!\255Q\026Ki\316\t\n"} track {gid: "\002\274h+^\251B;\202\227z{p\"q\'"} track {gid: "\376{t\274\302\352J\207\202\216r)\356\270\036\366"} track {gid: "\230\273\342\007K\377I9\274tX\341\002Zy@"} track {gid: "\202\036D\331I\023C\255\254|\005\361\222QF\322"} track {gid: "\317x\251\013\351\027L\221\212\352\n9%0\2619"}

[2023-04-26T20:01:07Z DEBUG librespot_connect::spirc] Frame has 11 tracks

[2023-04-26T20:01:07Z DEBUG librespot_playback::player] command=SetAutoNormaliseAsAlbum(true)

[2023-04-26T20:01:07Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 233656210909246892452980145102841614613, audio_type: Track }, true, 11346)

[2023-04-26T20:01:07Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]

[2023-04-26T20:01:07Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]

[2023-04-26T20:01:07Z INFO  librespot::player_event_handler] Running ["/var/local/www/commandw/spotevent.sh"] with environment variables {"TRACK_ID": "5lHj7Xo7htqIZhniKW2t7v", "PLAYER_EVENT": "started"}

[2023-04-26T20:01:07Z INFO  librespot_playback::player] Loading <Giant Steps> with Spotify URI <spotify:track:5lHj7Xo7htqIZhniKW2t7v>

[2023-04-26T20:01:07Z DEBUG librespot_audio::fetch] Downloading file 52cd4908ee9d0ef50cc4656175f465a88a8baaf1

[2023-04-26T20:01:07Z DEBUG librespot::component] new ChannelManager

[2023-04-26T20:01:07Z DEBUG librespot::component] new AudioKeyManager

[2023-04-26T20:01:08Z INFO  librespot_playback::player] <Giant Steps> (473973 ms) loaded

[2023-04-26T20:01:08Z TRACE librespot_playback::player] == Starting sink ==

[2023-04-26T20:01:08Z TRACE librespot_playback::audio_backend::alsa] Desired Frames per Buffer: 22050

[2023-04-26T20:01:08Z TRACE librespot_playback::audio_backend::alsa] Desired Frames per Period: 5512

[2023-04-26T20:01:08Z TRACE librespot_playback::audio_backend::alsa] Actual Frames per Buffer: 22050

[2023-04-26T20:01:08Z TRACE librespot_playback::audio_backend::alsa] Actual Frames per Period: 5512

[2023-04-26T20:01:08Z TRACE librespot_playback::audio_backend::alsa] Period Buffer size in bytes: 22048

[2023-04-26T20:01:08Z TRACE librespot_playback::audio_backend::alsa] Period Buffer capacity: 22048

[2023-04-26T20:01:08Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]

[2023-04-26T20:01:08Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay

[2023-04-26T20:01:08Z INFO  librespot::player_event_handler] Running ["/var/local/www/commandw/spotevent.sh"] with environment variables {"POSITION_MS": "11345", "PLAYER_EVENT": "playing", "TRACK_ID": "5lHj7Xo7htqIZhniKW2t7v", "DURATION_MS": "473973"}

[2023-04-26T20:01:19Z DEBUG librespot_audio::fetch] File 52cd4908ee9d0ef50cc4656175f465a88a8baaf1 complete, saving to cache

To restore moOde to normal operation, fiirst kill the invocation with a CTRL-C, then use moodeutl to restart the renderers, and close the window.

Code:
^C[2023-04-26T20:07:47Z INFO  librespot] Gracefully shutting down

[2023-04-26T20:07:47Z DEBUG librespot_connect::spirc] drop Spirc[0]

[2023-04-26T20:07:47Z DEBUG librespot_playback::player] Shutting down player thread ...

[2023-04-26T20:07:47Z DEBUG librespot_playback::player] command=Stop

[2023-04-26T20:07:47Z TRACE librespot_playback::player] == Stopping sink ==

[2023-04-26T20:07:48Z DEBUG librespot_playback::player] drop PlayerInternal[0]

[2023-04-26T20:07:48Z DEBUG librespot_playback::player] PlayerInternal thread finished.

[2023-04-26T20:07:48Z DEBUG librespot_core::session] drop Session[0]

[2023-04-26T20:07:48Z DEBUG librespot::component] drop AudioKeyManager

[2023-04-26T20:07:48Z DEBUG librespot::component] drop ChannelManager

[2023-04-26T20:07:48Z DEBUG librespot::component] drop MercuryManager

[2023-04-26T20:07:48Z DEBUG librespot_core::session] drop Dispatch

pi@m832p3a:~ $ moodeutl -r

Servers restarted

pi@m832p3a:~ $

Good luck finding a clue!

Regards,
Kent

RE: Spotify playing slow - Nutul - 04-26-2023

Hi,

totally newbie on the topic, as I don't use Spotify.

From what I understand, when you switch the renderer to be moOde's librespot, what happens is that your phone tells librespot to start streaming from a certain URI, hence your phone gets out of the way, and librespot carries things out. Right?

If not right, of course, ignore the following.

So here's what I'd do:

1. open Spotify on your desktop/laptop PC
2. open Spotify on your phone
3. play something on your phone's Spotify app
4. from your phone's Spotify player, chose your desktop as the renderer

Does the audio play slow(er) on your desktop too?

It shouldn't, of course, but it shouldn't happen for moOde too, so...

RE: Spotify playing slow - the_bertrum - 04-27-2023

(04-26-2023, 03:52 PM)vondewall Wrote:
(04-25-2023, 02:18 AM)vondewall Wrote: Anyone else experiencing problems with Spotify streaming in Moode? All of a sudden it plays slower. Not much but slow enough for it to be noticeable.
I am running Moode latest version on a RPI3.
Suggestion on to solve this is appreciated!
Code:
20230426 174049 worker: -- 20230426 174049 worker: -- Start moOde 8 series 20230426 174049 worker: -- 20230426 174049 worker: Successfully daemonized 20230426 174049 worker: Waiting for Linux startup... 20230426 174108 worker: Linux startup complete 20230426 174108 worker: Boot config backed up 20230426 174113 worker: File check (OK) 20230426 174115 worker: Session vacuumed 20230426 174115 worker: Session loaded 20230426 174115 worker: Debug logging (ON) 20230426 174115 worker: -- 20230426 174115 worker: -- Audio debug 20230426 174115 worker: -- 20230426 174115 worker: ALSA cards: (0:sndrpihifiberry | 1:Plus | 2:empty | 3:empty 20230426 174115 worker: MPD config: (0:hifiberry-digi | mixer:(none) | card:0) 20230426 174115 worker: ALSA mixer actual (none) 20230426 174115 worker: ALSA volume (none) 20230426 174115 worker: -- 20230426 174115 worker: -- System 20230426 174115 worker: -- 20230426 174117 worker: Host (moode1) 20230426 174117 worker: Hardware (Pi-3B+ 1.3 1GB) 20230426 174117 worker: moOde (8.3.2 2023-04-21) 20230426 174117 worker: RaspiOS (11.5) 20230426 174117 worker: Kernel (6.1.21-v8+ #1642) 20230426 174117 worker: Procarch (aarch64, 64-bit) 20230426 174117 worker: MPD ver (0.23.12) 20230426 174117 worker: CPU gov (ondemand) 20230426 174117 worker: Userid (pi) 20230426 174117 worker: Homedir (/home/pi) 20230426 174118 worker: USB boot (enabled) 20230426 174118 worker: File sys (expanded) 20230426 174118 worker: HDMI port (Off) 20230426 174118 worker: Sys LED0 (On) 20230426 174118 worker: Sys LED1 (On) 20230426 174118 worker: -- 20230426 174118 worker: -- Network 20230426 174118 worker: -- 20230426 174118 worker: eth0 adapter exists 20230426 174118 worker: eth0 address check (Off) 20230426 174118 worker: IP addr (192.168.2.43) 20230426 174118 worker: Netmask (255.255.255.0) 20230426 174118 worker: Gateway (192.168.2.1) 20230426 174118 worker: Pri DNS (192.168.2.1) 20230426 174118 worker: Domain () 20230426 174119 worker: wlan0 adapter exists 20230426 174119 worker: wlan0 country (SE) 20230426 174119 worker: wlan0 configured SSID (Full fart) 20230426 174119 worker: wlan0 SSID alternates (None) 20230426 174119 worker: wlan0 router mode (Off) 20230426 174119 worker: wlan0 address check (up to 90 secs) 20230426 174119 worker: wlan0 check 1 for IP address 20230426 174121 worker: wlan0 check 2 for IP address 20230426 174123 worker: wlan0 check 3 for IP address 20230426 174125 worker: wlan0 check 4 for IP address 20230426 174127 worker: wlan0 check 5 for IP address 20230426 174129 worker: wlan0 check 6 for IP address 20230426 174131 worker: wlan0 check 7 for IP address 20230426 174133 worker: wlan0 check 8 for IP address 20230426 174135 worker: wlan0 check 9 for IP address 20230426 174137 worker: wlan0 check 10 for IP address 20230426 174139 worker: wlan0 check 11 for IP address 20230426 174141 worker: wlan0 check 12 for IP address 20230426 174143 worker: wlan0 check 13 for IP address 20230426 174145 worker: wlan0 check 14 for IP address 20230426 174147 worker: wlan0 check 15 for IP address 20230426 174149 worker: wlan0 check 16 for IP address 20230426 174152 worker: wlan0 check 17 for IP address 20230426 174154 worker: wlan0 check 18 for IP address 20230426 174156 worker: wlan0 check 19 for IP address 20230426 174158 worker: wlan0 check 20 for IP address 20230426 174200 worker: wlan0 check 21 for IP address 20230426 174202 worker: wlan0 check 22 for IP address 20230426 174204 worker: wlan0 check 23 for IP address 20230426 174206 worker: wlan0 check 24 for IP address 20230426 174208 worker: wlan0 check 25 for IP address 20230426 174210 worker: wlan0 check 26 for IP address 20230426 174212 worker: wlan0 check 27 for IP address 20230426 174214 worker: wlan0 check 28 for IP address 20230426 174216 worker: wlan0 check 29 for IP address 20230426 174218 worker: wlan0 check 30 for IP address 20230426 174220 worker: wlan0 check 31 for IP address 20230426 174222 worker: wlan0 check 32 for IP address 20230426 174224 worker: wlan0 check 33 for IP address 20230426 174227 worker: wlan0 check 34 for IP address 20230426 174229 worker: wlan0 check 35 for IP address 20230426 174231 worker: wlan0 check 36 for IP address 20230426 174233 worker: wlan0 check 37 for IP address 20230426 174235 worker: wlan0 check 38 for IP address 20230426 174237 worker: wlan0 check 39 for IP address 20230426 174239 worker: wlan0 check 40 for IP address 20230426 174241 worker: wlan0 check 41 for IP address 20230426 174243 worker: wlan0 check 42 for IP address 20230426 174245 worker: wlan0 check 43 for IP address 20230426 174247 worker: wlan0 check 44 for IP address 20230426 174249 worker: wlan0 check 45 for IP address 20230426 174251 worker: wlan0 address not assigned 20230426 174251 worker: wlan0 AP mode not activated, eth0 active but Router mode is Off 20230426 174251 worker: wlan0 address not assigned 20230426 174251 worker: -- 20230426 174251 worker: -- Software update 20230426 174251 worker: -- 20230426 174251 worker: Automatic check (On) 20230426 174251 worker: Checking for available update... 20230426 174252 worker: Software is up to date 20230426 174252 worker: -- 20230426 174252 worker: -- Audio config 20230426 174252 worker: -- 20230426 174252 worker: MPD conf updated 20230426 174252 worker: ALSA card number (0) 20230426 174252 worker: MPD audio output (None) 20230426 174252 worker: Audio formats (S16_LE, S24_LE) 20230426 174252 worker: ALSA mixer name (none) 20230426 174252 worker: MPD mixer type (software) 20230426 174253 worker: Hdwr volume controller not detected 20230426 174253 worker: ALSA output mode (Default: plughw) 20230426 174253 worker: ALSA loopback (Off) 20230426 174253 worker: Reset renderer active flags 20230426 174253 worker: CamillaDSP configuration (off) 20230426 174253 worker: CamillaDSP volume sync (off) 20230426 174253 worker: CamillaDSP volume range (60) 20230426 174253 worker: -- 20230426 174253 worker: -- File sharing 20230426 174253 worker: -- 20230426 174254 worker: SMB file sharing (Off) 20230426 174254 worker: NFS file sharing (On) 20230426 174254 worker: -- 20230426 174254 worker: -- MPD startup 20230426 174254 worker: -- 20230426 174255 worker: MPD started 20230426 174255 worker: MPD accepting connections 20230426 174255 worker: MPD output 1 ALSA Default (On) 20230426 174255 worker: MPD output 2 ALSA Bluetooth (Off) 20230426 174255 worker: MPD output 3 HTTP Server (Off) 20230426 174255 worker: MPD crossfade (off) 20230426 174255 worker: MPD ignore CUE files (yes) 20230426 174255 worker: -- 20230426 174255 worker: -- Music sources 20230426 174255 worker: -- 20230426 174255 worker: USB sources 20230426 174255 worker: No drives found 20230426 174255 worker: NAS sources 20230426 174255 worker: Musik 20230426 174256 worker: Mount (mount -t nfs -o soft,timeo=10,retrans=1,ro,nolock "192.168.2.59:/volume1/Musik" "/mnt/NAS/Musik") 20230426 174256 worker: Mount all submitted 20230426 174256 worker: -- 20230426 174256 worker: -- Feature availability 20230426 174256 worker: -- 20230426 174256 worker: Input select (available) 20230426 174256 worker: Input (MPD) 20230426 174256 worker: Output (hifiberry-digi) 20230426 174256 worker: Bluetooth (available) 20230426 174256 startAirPlay(): (/usr/bin/shairport-sync -vv -a "Moode1 Airplay" -- -d _audioout > /var/log/shairport-sync.log 2>&1 &) 20230426 174256 worker: AirPlay renderer (available: started) 20230426 174256 startSpotify(): (librespot --name "Moode1 Spotify" --bitrate 160 --format S16 --ap-port 13561 --mixer softvol --initial-volume 0 --volume-ctrl log --volume-range 60 --cache /var/local/www/spotify_cache --disable-audio-cache --backend alsa --device "_audioout" --onevent /var/local/www/commandw/spotevent.sh > /dev/null 2>&1 &) 20230426 174256 worker: Spotify renderer (available: started) 20230426 174256 worker: Squeezelite (available) 20230426 174256 worker: RoonBridge renderer (not installed) 20230426 174256 worker: Multiroom sender (available) 20230426 174256 worker: Multiroom receiver (available) 20230426 174256 worker: UPnP renderer (available: started) 20230426 174256 worker: DLNA server (available) 20230426 174256 worker: GPIO button handler (available) 20230426 174256 worker: Stream recorder (available: not installed) 20230426 174256 worker: HTTPS-Only mode (n/a) 20230426 174256 worker: -- 20230426 174256 worker: -- Other 20230426 174256 worker: -- 20230426 174256 worker: USB volume knob (Off) 20230426 174256 worker: Shellinabox SSH started 20230426 174256 worker: USB auto-mounter (udisks-glue) 20230426 174256 worker: Saved MPD vol level (0) 20230426 174256 worker: Preamp volume level (0) 20230426 174257 worker: MPD volume level (0) restored 20230426 174257 worker: ALSA volume level (None) 20230426 174257 worker: Auto-play (Off) 20230426 174258 worker: LocalUI (Off) 20230426 174258 worker: Automatic CoverView (Off) 20230426 174258 worker: On-screen keyboard (Off) 20230426 174258 worker: Library scope (all) 20230426 174258 worker: View reset to playback 20230426 174258 worker: Maintenance interval (360 minutes) 20230426 174258 worker: Screen saver activation (Never) 20230426 174258 phpSession(get_status): status=PHP_SESSION_ACTIVE 20230426 174258 worker: Session permissions (OK) 20230426 174258 worker: -- 20230426 174258 worker: -- Startup complete 20230426 174258 worker: -- 20230426 174258 worker: Mount monitor (started) 20230426 174258 worker: Watchdog monitor (started) 20230426 174258 worker: Ready 20230426 174258 waitWorker(): Start (sys-config, w_active=1) 20230426 174258 waitWorker(): Start (sys-config, w_active=1) 20230426 174259 waitWorker(): Start (sys-config, w_active=1) 20230426 174259 waitWorker(): Wait (1) 20230426 174259 waitWorker(): Wait (1) 20230426 174300 waitWorker(): Wait (1) 20230426 174300 waitWorker(): Wait (2) 20230426 174300 waitWorker(): Wait (2) 20230426 174301 waitWorker(): Wait (2) 20230426 174301 worker: Job clearsyslogs 20230426 174301 waitWorker(): Wait (3) 20230426 174301 waitWorker(): End (sys-config, w_active=0) 20230426 174301 waitWorker(): Wait (3) 20230426 174301 waitWorker(): End (sys-config, w_active=0) 20230426 174302 waitWorker(): Wait (3) 20230426 174302 waitWorker(): End (sys-config, w_active=0) 20230426 174302 waitWorker(): Start (sys-config, w_active=0) 20230426 174302 waitWorker(): End (sys-config, w_active=0)

I see these in your log:

Code:
20230426 174256 startAirPlay(): (/usr/bin/shairport-sync -vv -a "Moode1 Airplay" -- -d _audioout > /var/log/shairport-sync.log 2>&1 &)

20230426 174256 worker: AirPlay renderer (available: started)

20230426 174256 startSpotify(): (librespot --name "Moode1 Spotify" --bitrate 160 --format S16 --ap-port 13561  --mixer softvol --initial-volume 0 --volume-ctrl log --volume-range 60 --cache /var/local/www/spotify_cache --disable-audio-cache --backend alsa --device "_audioout" --onevent /var/local/www/commandw/spotevent.sh > /dev/null 2>&1 &)

20230426 174256 worker: Spotify renderer (available: started)

Those startSpotify() lines don't appear in my startup log. Have you modified something?