-- 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"