-- Logs begin at Fri 2024-04-05 17:50:38 JST, end at Mon 2024-04-08 13:53:29 JST. -- Apr 08 13:52:25 primo volumio[6002]: verbose: New Socket.io Connection to 192.168.3.4 from 192.168.3.31 UA: unknown Total Clients: 7 Apr 08 13:52:25 primo volumio[6002]: info: CoreCommandRouter::volumioGetState Apr 08 13:52:25 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 08 13:52:25 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 08 13:52:25 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 08 13:52:25 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 08 13:52:25 primo volumio[6002]: info: Discovery: Getting this device information Apr 08 13:52:25 primo volumio[6002]: info: CoreCommandRouter::volumioGetState Apr 08 13:52:25 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 08 13:52:28 primo sudo[29235]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 08 13:52:28 primo sudo[29235]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 08 13:52:28 primo sudo[29235]: pam_unix(sudo:session): session closed for user root Apr 08 13:52:28 primo sudo[29239]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 08 13:52:28 primo sudo[29239]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 08 13:52:28 primo sudo[29239]: pam_unix(sudo:session): session closed for user root Apr 08 13:52:28 primo volumio[6002]: verbose: New Socket.io Connection to 192.168.3.4 from 192.168.3.31 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_4_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 8 Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::volumioGetVisibleSources Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::volumioGetState Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 08 13:52:28 primo volumio[6002]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Apr 08 13:52:28 primo volumio[6002]: info: Received Get System Info Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 08 13:52:28 primo volumio[6002]: info: Discovery: Getting this device information Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::volumioGetState Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::volumioGetState Apr 08 13:52:28 primo volumio[6002]: info: Listing playlists Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 08 13:52:28 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 08 13:52:30 primo volumio[6002]: info: Received Get System Info Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 08 13:52:30 primo volumio[6002]: info: Discovery: Getting this device information Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::volumioGetState Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 08 13:52:30 primo volumio[6002]: No protocol specified Apr 08 13:52:30 primo volumio[6002]: xcb_connection_has_error() returned true Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Apr 08 13:52:30 primo volumio[6002]: No protocol specified Apr 08 13:52:30 primo volumio[6002]: xcb_connection_has_error() returned true Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: raat , getAdditionalUiSection Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 08 13:52:30 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 08 13:52:31 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 08 13:52:31 primo volumio[6002]: info: Received Get System Info Apr 08 13:52:31 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 08 13:52:31 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 08 13:52:31 primo volumio[6002]: info: Discovery: Getting this device information Apr 08 13:52:31 primo volumio[6002]: info: CoreCommandRouter::volumioGetState Apr 08 13:52:31 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 08 13:52:33 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 08 13:52:33 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 08 13:52:47 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 08 13:52:47 primo volumio[6002]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Apr 08 13:52:47 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Apr 08 13:52:47 primo volumio[6002]: info: Received Get System Version Apr 08 13:52:47 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 08 13:52:47 primo volumio[6002]: info: Received Get System Info Apr 08 13:52:47 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 08 13:52:47 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 08 13:52:47 primo volumio[6002]: info: Discovery: Getting this device information Apr 08 13:52:47 primo volumio[6002]: info: CoreCommandRouter::volumioGetState Apr 08 13:52:47 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 08 13:53:08 primo volumio[6002]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/spop/primo2rev2/buster/armhf Apr 08 13:53:10 primo volumio[6002]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/spop/primo2rev2/buster/armhf Apr 08 13:53:10 primo volumio[6002]: info: Folder /tmp/plugins removed Apr 08 13:53:11 primo volumio[6002]: info: Check plugin dependencies Apr 08 13:53:11 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 08 13:53:11 primo volumio[6002]: info: Checking if plugin already exists Apr 08 13:53:11 primo volumio[6002]: info: Rename folder Apr 08 13:53:11 primo volumio[6002]: info: Folder /tmp/downloaded_plugin.zip removed Apr 08 13:53:11 primo volumio[6002]: info: Move to category Apr 08 13:53:12 primo volumio[6002]: info: Checking if install.sh is present Apr 08 13:53:12 primo volumio[6002]: info: Executing install.sh Apr 08 13:53:12 primo sudo[29263]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/music_service/spop/install.sh Apr 08 13:53:12 primo sudo[29263]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 08 13:53:12 primo volumio[6002]: info: Installing Go-librespot Apr 08 13:53:12 primo volumio[6002]: info: Checking old vollibrespot installs Apr 08 13:53:12 primo systemd[1]: Reloading. Apr 08 13:53:13 primo systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Apr 08 13:53:13 primo systemd[1]: serial-getty@ttyS0.service: Current command vanished from the unit file, execution of the command list won't be resumed. Apr 08 13:53:13 primo volumio[6002]: info: Dowloading daemon Apr 08 13:53:16 primo volumio[6002]: info: Creating Start Script Apr 08 13:53:16 primo systemd[1]: Reloading. Apr 08 13:53:16 primo systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Apr 08 13:53:17 primo sudo[29263]: pam_unix(sudo:session): session closed for user root Apr 08 13:53:17 primo volumio[6002]: Plugin install end detected on script Apr 08 13:53:17 primo volumio[6002]: info: Install script completed Apr 08 13:53:17 primo volumio[6002]: info: Adding reference to registry Apr 08 13:53:17 primo volumio[6002]: info: Done installing plugin. Apr 08 13:53:17 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 08 13:53:17 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 08 13:53:17 primo volumio[6002]: info: Folder /tmp/plugins removed Apr 08 13:53:17 primo volumio[6002]: info: Folder /tmp/downloaded_plugin.zip removed Apr 08 13:53:17 primo volumio[6002]: info: Folder /data/temp removed Apr 08 13:53:18 primo volumio[6002]: info: Enabling plugin spop Apr 08 13:53:18 primo volumio[6002]: info: Loading plugin "spop"... Apr 08 13:53:19 primo volumio[6002]: info: PLUGIN START: spop Apr 08 13:53:19 primo volumio[6002]: info: Creating Spotify config file Apr 08 13:53:19 primo volumio[6002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 08 13:53:19 primo volumio[6002]: info: Done. Apr 08 13:53:20 primo volumio[6002]: info: Spotify config file written Apr 08 13:53:20 primo sudo[29337]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 08 13:53:20 primo sudo[29337]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 08 13:53:20 primo systemd[1]: Started go-librespot Daemon. Apr 08 13:53:20 primo sudo[29337]: pam_unix(sudo:session): session closed for user root Apr 08 13:53:20 primo go-librespot[29340]: Librespot-go daemon starting... Apr 08 13:53:20 primo go-librespot[29340]: time="2024-04-08T13:53:20+09:00" level=info msg="generated new device id: ed00ffe1a8d2affa9df3a6a36d2473d1272e7ba2" Apr 08 13:53:20 primo go-librespot[29340]: time="2024-04-08T13:53:20+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 08 13:53:20 primo go-librespot[29340]: time="2024-04-08T13:53:20+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 08 13:53:20 primo go-librespot[29340]: time="2024-04-08T13:53:20+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 08 13:53:20 primo go-librespot[29340]: time="2024-04-08T13:53:20+09:00" level=debug msg="zeroconf server listening on port 38093" Apr 08 13:53:23 primo volumio[6002]: info: go-librespot daemon successfully initialized Apr 08 13:53:25 primo go-librespot[29340]: time="2024-04-08T13:53:25+09:00" level=debug msg="obtained new client token: AAAWj8DItESC+c/7zJ1odNRGzXMNUVb/2nA1Vzt+QwvFLEVm21T1rsF89Xz83o4kFzDb8zwzJNCebXsFER7NbBEOiLFBKwpjNwnw5GXNnqeqs7GPCTQ2jEPrUX7HcAABk/G9xqDT4luo8LrpGuwBTaAyo4Fd8ojI7GVoEiAv1Ige1iPpBkpa5bN4aCmg4/XkF7SgSslNWm7EMU6Q91QKK9SPFASHHSnccfnomzq550tz5LaEM1Gvbp2n0o7Kh7IG" Apr 08 13:53:25 primo go-librespot[29340]: time="2024-04-08T13:53:25+09:00" level=debug msg="completed keyexchange" Apr 08 13:53:26 primo volumio[6002]: info: Initializing connection to go-librespot Websocket Apr 08 13:53:26 primo go-librespot[29340]: time="2024-04-08T13:53:26+09:00" level=debug msg="completed challenge" Apr 08 13:53:26 primo go-librespot[29340]: time="2024-04-08T13:53:26+09:00" level=debug msg="new websocket client" Apr 08 13:53:26 primo volumio[6002]: info: Connection to go-librespot Websocket established Apr 08 13:53:26 primo go-librespot[29340]: time="2024-04-08T13:53:26+09:00" level=debug msg="authenticated as vnojua62isnz5bd92ozvc1jbt" Apr 08 13:53:26 primo go-librespot[29340]: time="2024-04-08T13:53:26+09:00" level=debug msg="authenticated as vnojua62isnz5bd92ozvc1jbt" Apr 08 13:53:26 primo go-librespot[29340]: time="2024-04-08T13:53:26+09:00" level=debug msg="dealer connection opened" Apr 08 13:53:26 primo go-librespot[29340]: time="2024-04-08T13:53:26+09:00" level=info msg="accepted zeroconf user vnojua62isnz5bd92ozvc1jbt from iPhone" Apr 08 13:53:26 primo go-librespot[29340]: time="2024-04-08T13:53:26+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 08 13:53:26 primo go-librespot[29340]: time="2024-04-08T13:53:26+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 08 13:53:26 primo go-librespot[29340]: time="2024-04-08T13:53:26+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 08 13:53:26 primo go-librespot[29340]: time="2024-04-08T13:53:26+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 08 13:53:26 primo go-librespot[29340]: time="2024-04-08T13:53:26+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" Apr 08 13:53:26 primo go-librespot[29340]: time="2024-04-08T13:53:26+09:00" level=debug msg="received connection id: ZjJlYjcwZmUtOTI1OC00ZjdhLThhMzItNjFlOWRiZWU3MjE4K2RlYWxlcit0Y3A6Ly9nYWUyLWRlYWxlci1hLXgxbWwuZ2FlMi5zcG90aWZ5Lm5ldDo1NzAwKzYyNThBRjJCRDA0RDZGMzFFQkE5RDI1N0Y4MzUxNTUyN0E2MjVGNzE3REMyMEI1MjVERUMxRUVCRjE4Q0IyRkE=" Apr 08 13:53:26 primo go-librespot[29340]: time="2024-04-08T13:53:26+09:00" level=debug msg="put connect state because NEW_DEVICE" Apr 08 13:53:27 primo go-librespot[29340]: time="2024-04-08T13:53:27+09:00" level=debug msg="handling transfer player command from 155a25510dc3a3e8879a497ae713f14708b7b45d" Apr 08 13:53:27 primo go-librespot[29340]: time="2024-04-08T13:53:27+09:00" level=trace msg="fetched new page 0 with 105 items (list: 105)" Apr 08 13:53:27 primo go-librespot[29340]: time="2024-04-08T13:53:27+09:00" level=debug msg="shuffled context with seed 17082779270404808050 (len: 105, keep: 1)" Apr 08 13:53:27 primo go-librespot[29340]: time="2024-04-08T13:53:27+09:00" level=debug msg="loading track spotify:track:3tWnflKLgpCq3sKmHP64Ep (paused: true, position: 192716ms)" Apr 08 13:53:27 primo go-librespot[29340]: time="2024-04-08T13:53:27+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 08 13:53:27 primo go-librespot[29340]: time="2024-04-08T13:53:27+09:00" level=trace msg="emitting websocket event: will_play" Apr 08 13:53:27 primo volumio[6002]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3tWnflKLgpCq3sKmHP64Ep","play_origin":"playlist/ondemand"}} Apr 08 13:53:27 primo go-librespot[29340]: time="2024-04-08T13:53:27+09:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:3tWnflKLgpCq3sKmHP64Ep" Apr 08 13:53:27 primo go-librespot[29340]: time="2024-04-08T13:53:27+09:00" level=debug msg="requested aes key for file e6a0233455dfa6620be212dc34f09b48ec037ffe, gid: 3tWnflKLgpCq3sKmHP64Ep" Apr 08 13:53:27 primo go-librespot[29340]: time="2024-04-08T13:53:27+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Apr 08 13:53:27 primo go-librespot[29340]: time="2024-04-08T13:53:27+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1356" Apr 08 13:53:27 primo go-librespot[29340]: time="2024-04-08T13:53:27+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1597" Apr 08 13:53:27 primo go-librespot[29340]: time="2024-04-08T13:53:27+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1576" Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="fetched first chunk of 28, total size is 14437772 bytes" Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="fetched chunk 1/27, size: 524288" Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="fetched chunk 2/27, size: 524288" Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="fetched chunk 3/27, size: 524288" Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="fetched chunk 17/27, size: 524288" Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=trace msg="seek to 192716ms (diff: 104ms, samples: 8498775, bytes: 9296562)" Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="fetched chunk 18/27, size: 524288" Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="fetched chunk 19/27, size: 524288" Apr 08 13:53:28 primo kernel: aml_spdif_open Apr 08 13:53:28 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:spdif@0 Apr 08 13:53:28 primo go-librespot[29340]: ALSA lib /home/pi/volumio-alsa-plugin/src/pcm_volumioswitch.c:257:(_snd_pcm_volumioswitch_hw_params) PCM volumioMultiRoomServer has buffer size 65536, but target_pcm volumioOutput has buffer size 32768 Apr 08 13:53:28 primo go-librespot[29340]: ALSA lib /home/pi/volumio-alsa-plugin/src/pcm_volumioswitch.c:268:(_snd_pcm_volumioswitch_hw_params) PCM volumioMultiRoomServer has buffer size 65536, but target_pcm volumioOutput has buffer size 32768 Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=info msg="loaded track \"Ritmos Flamenco\" (uri: spotify:track:3tWnflKLgpCq3sKmHP64Ep, paused: true, position: 192716ms, duration: 303480ms)" Apr 08 13:53:28 primo kernel: set normal 512 fs /4 fs Apr 08 13:53:28 primo kernel: set spdifout clk:5644800, mpll:22579200 Apr 08 13:53:28 primo kernel: get spdifout clk:5644797, mpll:22579186 Apr 08 13:53:28 primo kernel: aml_dai_set_spdif_fmt , fmt 0x4000 Apr 08 13:53:28 primo kernel: set normal 512 fs /4 fs Apr 08 13:53:28 primo kernel: set spdifout clk:5644800, mpll:22579200 Apr 08 13:53:28 primo kernel: get spdifout clk:5644797, mpll:22579186 Apr 08 13:53:28 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Apr 08 13:53:28 primo kernel: aml_spdif_fifo_ctrl, bit depth:24, frddr type:4, toddr:type:4 Apr 08 13:53:28 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Apr 08 13:53:28 primo kernel: aml_spdif_fifo_ctrl, bit depth:24, frddr type:4, toddr:type:4 Apr 08 13:53:28 primo kernel: spdif_a keep clk continuous Apr 08 13:53:28 primo kernel: aml_spdif_close Apr 08 13:53:28 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:spdif@0 Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=trace msg="emitting websocket event: metadata" Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=trace msg="emitting websocket event: active" Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="sending successful reply for delaer request" Apr 08 13:53:28 primo volumio[6002]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3tWnflKLgpCq3sKmHP64Ep","name":"Ritmos Flamenco","artist_names":["Armik"],"album_name":"The Best of Armik","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02500e401378b8478f22a37d5b","position":192716,"duration":303480,"release_date":"year:2003 month:8 day:15","track_number":12,"disc_number":1}} Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 08 13:53:28 primo volumio[6002]: SPOTIFY: received: {"type":"active","data":null} Apr 08 13:53:28 primo volumio[6002]: info: Aligning Spotify Volume to Volumio Volume Apr 08 13:53:28 primo volumio[6002]: info: CoreCommandRouter::volumioGetState Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=trace msg="emitting websocket event: paused" Apr 08 13:53:28 primo volumio[6002]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3tWnflKLgpCq3sKmHP64Ep","play_origin":"playlist/ondemand"}} Apr 08 13:53:28 primo volumio[6002]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 08 13:53:28 primo volumio[6002]: TypeError: Cannot read property 'service' of undefined Apr 08 13:53:28 primo volumio[6002]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Apr 08 13:53:28 primo volumio[6002]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Apr 08 13:53:28 primo volumio[6002]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Apr 08 13:53:28 primo volumio[6002]: at WebSocket.emit (events.js:400:28) Apr 08 13:53:28 primo volumio[6002]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Apr 08 13:53:28 primo volumio[6002]: at Receiver.emit (events.js:400:28) Apr 08 13:53:28 primo volumio[6002]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Apr 08 13:53:28 primo volumio[6002]: at internal/process/task_queues.js:141:7 Apr 08 13:53:28 primo volumio[6002]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Apr 08 13:53:28 primo volumio[6002]: at AsyncResource.runMicrotask (internal/process/task_queues.js:138:8) Apr 08 13:53:28 primo volumio[6002]: at runMicrotasks () Apr 08 13:53:28 primo volumio[6002]: at processTicksAndRejections (internal/process/task_queues.js:95:5) Apr 08 13:53:28 primo volumio[6002]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1580" Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 08 13:53:28 primo go-librespot[29340]: time="2024-04-08T13:53:28+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1576" Apr 08 13:53:29 primo go-librespot[29340]: time="2024-04-08T13:53:29+09:00" level=debug msg="fetched chunk 20/27, size: 524288" Apr 08 13:53:29 primo sudo[29423]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-08 13:52 Apr 08 13:53:29 primo sudo[29423]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="e831866afe2db61aee9333a8f5ba9d9fd36609c7" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="primo2rev2" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sun 18 Feb 2024 12:01:04 PM CET" VOLUMIO_VERSION="3.629" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Primo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo" VOLUMIO_HASH="728189e850980f21ef569472434ec23d"