04-26-2023, 08:25 PM
@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.
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
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.
Good luck finding a clue!
Regards,
Kent
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 kPlayStatusStopAt 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 cacheTo 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
