-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Sun 2025-07-06 16:31:39 CEST. -- Jul 06 16:31:32 filodiffusione systemd-timedated[1033]: Changed local time to Sun Jul 6 16:31:32 2025 Jul 06 16:31:32 filodiffusione sudo[1014]: pam_unix(sudo:session): session closed for user root Jul 06 16:31:32 filodiffusione volumio-time-update[613]: volumio-time-update-util: System time updated successfully. Jul 06 16:31:32 filodiffusione volumio[814]: info: Volumio Calling Home Jul 06 16:31:32 filodiffusione systemd[1]: Starting Daily apt download activities... Jul 06 16:31:32 filodiffusione systemd[1]: Started Volumio Time Update Utility. Jul 06 16:31:32 filodiffusione volumio[814]: info: Discovery: adding 79835671-9a19-4bd9-97ff-bffc4941ed34 Jul 06 16:31:32 filodiffusione volumio[814]: info: Discovery: Found device Filodiffusione Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::volumioGetState Jul 06 16:31:32 filodiffusione volumio[814]: info: CorePlayQueue::getTrack 0 Jul 06 16:31:32 filodiffusione ntpd[784]: Listen normally on 3 eth0 192.168.1.153:123 Jul 06 16:31:32 filodiffusione ntpd[784]: new interface(s) found: waking up resolver Jul 06 16:31:32 filodiffusione volumio[814]: info: MPD Permissions set Jul 06 16:31:32 filodiffusione volumio[814]: info: MPD Permissions set Jul 06 16:31:32 filodiffusione volumio[814]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 06 16:31:32 filodiffusione volumio[814]: info: No need to fix Spotify hosts Jul 06 16:31:32 filodiffusione volumio[814]: info: Spotify config file written Jul 06 16:31:32 filodiffusione sudo[1062]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 06 16:31:32 filodiffusione sudo[1062]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 06 16:31:32 filodiffusione volumio[814]: info: Volumio called home Jul 06 16:31:32 filodiffusione volumio[814]: info: Discovery: A device disappeared from network Jul 06 16:31:32 filodiffusione volumio[814]: info: Discovery: Device filodiffusione disappeared from network Jul 06 16:31:32 filodiffusione volumio[814]: info: Starting Shairport Sync Jul 06 16:31:32 filodiffusione volumio[814]: info: Starting Shairport Sync Jul 06 16:31:32 filodiffusione sudo[1067]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 06 16:31:32 filodiffusione sudo[1067]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 06 16:31:32 filodiffusione systemd[1]: Started go-librespot Daemon. Jul 06 16:31:32 filodiffusione sudo[1062]: pam_unix(sudo:session): session closed for user root Jul 06 16:31:32 filodiffusione volumio[814]: info: Starting Shairport Sync Jul 06 16:31:32 filodiffusione go-librespot[1070]: go-librespot daemon starting... Jul 06 16:31:32 filodiffusione systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 06 16:31:32 filodiffusione sudo[1071]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 06 16:31:32 filodiffusione sudo[1071]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 06 16:31:32 filodiffusione systemd[1]: shairport-sync.service: Succeeded. Jul 06 16:31:32 filodiffusione systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 06 16:31:32 filodiffusione systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 06 16:31:32 filodiffusione sudo[1074]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 06 16:31:32 filodiffusione sudo[1074]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 06 16:31:32 filodiffusione sudo[1067]: pam_unix(sudo:session): session closed for user root Jul 06 16:31:32 filodiffusione systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 06 16:31:32 filodiffusione systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Jul 06 16:31:32 filodiffusione systemd[1]: shairport-sync.service: Succeeded. Jul 06 16:31:32 filodiffusione systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 06 16:31:32 filodiffusione systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::volumioGetState Jul 06 16:31:32 filodiffusione sudo[1071]: pam_unix(sudo:session): session closed for user root Jul 06 16:31:32 filodiffusione volumio[814]: info: CorePlayQueue::getTrack 0 Jul 06 16:31:32 filodiffusione systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 06 16:31:32 filodiffusione systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Jul 06 16:31:32 filodiffusione systemd[1]: shairport-sync.service: Succeeded. Jul 06 16:31:32 filodiffusione systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 06 16:31:32 filodiffusione systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 06 16:31:32 filodiffusione sudo[1074]: pam_unix(sudo:session): session closed for user root Jul 06 16:31:32 filodiffusione volumio[814]: info: Shairport-Sync Started Jul 06 16:31:32 filodiffusione volumio[814]: Error adding Membership: Error: addMembership EINVAL Jul 06 16:31:32 filodiffusione volumio[814]: info: Shairport-Sync Started Jul 06 16:31:32 filodiffusione volumio[814]: info: Shairport-Sync Started Jul 06 16:31:32 filodiffusione volumio[814]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 06 16:31:32 filodiffusione volumio[814]: SPOTIFY: BQBbH894yClk1BgSGTy1ih3Q1P8G6KdGgZM7uMbx09vHC1t64cD1rlx7AImyYMEqKay4XPTz2G82y38sGkXvTkq6wi3-14VOyY4_W7gqwoLA8nLVgxUC-tpic2uMQoAE1OzhG1Rji2dHaFaINlOl865TjNnDueB_9e89BUT_c3n5uBQsr46_cOBd1P69sy6OF8sG-Yo1yFk8sg_YChZZBwsF7r3imJoOWNkM2BSeuttRNb5w9QtIDeNk3y8I8EyalwUQIBn0hDbvRJMbUkORKWsfYS3da3YFPTjUBLlP8-zTWbM Jul 06 16:31:32 filodiffusione volumio[814]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 06 16:31:32 filodiffusione volumio[814]: info: New Spotify access token = BQBbH894yClk1BgSGTy1ih3Q1P8G6KdGgZM7uMbx09vHC1t64cD1rlx7AImyYMEqKay4XPTz2G82y38sGkXvTkq6wi3-14VOyY4_W7gqwoLA8nLVgxUC-tpic2uMQoAE1OzhG1Rji2dHaFaINlOl865TjNnDueB_9e89BUT_c3n5uBQsr46_cOBd1P69sy6OF8sG-Yo1yFk8sg_YChZZBwsF7r3imJoOWNkM2BSeuttRNb5w9QtIDeNk3y8I8EyalwUQIBn0hDbvRJMbUkORKWsfYS3da3YFPTjUBLlP8-zTWbM Jul 06 16:31:32 filodiffusione volumio[814]: info: Spotify credentials grant success - running version from March 24, 2019 Jul 06 16:31:32 filodiffusione volumio[814]: info: Discovery: adding 79835671-9a19-4bd9-97ff-bffc4941ed34 Jul 06 16:31:32 filodiffusione volumio[814]: info: Discovery: Found device Filodiffusione Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::volumioGetState Jul 06 16:31:32 filodiffusione volumio[814]: info: CorePlayQueue::getTrack 0 Jul 06 16:31:32 filodiffusione mpd[1024]: Jul 06 16:31 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 06 16:31:32 filodiffusione systemd[1]: Started Music Player Daemon. Jul 06 16:31:32 filodiffusione sudo[983]: pam_unix(sudo:session): session closed for user root Jul 06 16:31:32 filodiffusione sudo[996]: pam_unix(sudo:session): session closed for user root Jul 06 16:31:32 filodiffusione volumio[814]: info: Completed starting Core Plugins Jul 06 16:31:32 filodiffusione volumio[814]: info: ------------------------------------------- Jul 06 16:31:32 filodiffusione volumio[814]: info: ----- MyVolumio plugins startup ---- Jul 06 16:31:32 filodiffusione volumio[814]: info: ------------------------------------------- Jul 06 16:31:32 filodiffusione volumio[814]: info: [MyVolumio PluginManager] Fetching plans data.... Jul 06 16:31:32 filodiffusione volumio[814]: info: MPD running with PID1024 Jul 06 16:31:32 filodiffusione volumio[814]: ,establishing connection Jul 06 16:31:32 filodiffusione volumio[814]: error: MPD error: The expression evaluated to a falsy value: Jul 06 16:31:32 filodiffusione volumio[814]: assert.ok(self.idling) Jul 06 16:31:32 filodiffusione volumio[814]: error: The expression evaluated to a falsy value: Jul 06 16:31:32 filodiffusione volumio[814]: assert.ok(self.idling) Jul 06 16:31:32 filodiffusione volumio[814]: error: MPD error: The expression evaluated to a falsy value: Jul 06 16:31:32 filodiffusione volumio[814]: assert.ok(self.idling) Jul 06 16:31:32 filodiffusione volumio[814]: error: The expression evaluated to a falsy value: Jul 06 16:31:32 filodiffusione volumio[814]: assert.ok(self.idling) Jul 06 16:31:32 filodiffusione volumio[814]: error: updateQueue error: null Jul 06 16:31:32 filodiffusione volumio[814]: SPOTIFY: User informations: {"country":"IT","display_name":"Gianfranco Raso","email":"gianfranco.raso@poste.it","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/216qbeuci6oqeirohkqjeqbty"},"followers":{"href":null,"total":4},"href":"https://api.spotify.com/v1/users/216qbeuci6oqeirohkqjeqbty","id":"216qbeuci6oqeirohkqjeqbty","images":[{"height":300,"url":"https://platform-lookaside.fbsbx.com/platform/profilepic/?asid=384879518318688&height=300&width=300&ext=1754379112&hash=AT-buYwywFwZ_hL3SJF-WGku","width":300},{"height":64,"url":"https://platform-lookaside.fbsbx.com/platform/profilepic/?asid=384879518318688&height=50&width=50&ext=1754379112&hash=AT9Roh1Mnvb0Dcy5H2f7GOOq","width":64}],"product":"premium","type":"user","uri":"spotify:user:216qbeuci6oqeirohkqjeqbty"} Jul 06 16:31:32 filodiffusione volumio[814]: info: Spotify Successfully logged in Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 06 16:31:32 filodiffusione volumio[814]: info: [1751812292908] CoreMusicLibrary::Adding element Spotify Jul 06 16:31:32 filodiffusione volumio[814]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 06 16:31:32 filodiffusione volumio[814]: Cannot find translation for source Spotify Jul 06 16:31:32 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:32+02:00" level=info msg="running go-librespot 0.2.0" Jul 06 16:31:32 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:32+02:00" level=debug msg="app state loaded" Jul 06 16:31:32 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:32+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 06 16:31:33 filodiffusione systemd[1]: apt-daily.service: Succeeded. Jul 06 16:31:33 filodiffusione systemd[1]: Started Daily apt download activities. Jul 06 16:31:33 filodiffusione systemd[1]: Starting Daily apt upgrade and clean activities... Jul 06 16:31:33 filodiffusione volumio[814]: info: New access token = BQCU1in7by9FUV9eswp08E6GP-dOXcG4O4OvgzAtzLrSqCbztHzntN_N-Xd5ROsSvpOaGMecUVdbepvrqFYei6P3yC5oo114-gHMnqlqw3-BZTLodHvPpsbVUU0JnZe-yqNUGf5Ujmhqd-siV-MB2n0MCoPkwhThc11_bHp0NhlQweNxbdbb9s8HEdmazQTCzcveWvOEsE3zKd_BXhzgpQ71SUoy-VxfMicklsJ4olqg2N-Snx67MjaKlZCFGH6tYzlaIJHIkJaulQ2uFDP0JBjYvhpH5Qj9FgVDWiW0d3yxzJw Jul 06 16:31:33 filodiffusione nmbd[726]: [2025/07/06 16:31:33.291337, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jul 06 16:31:33 filodiffusione systemd[1]: Started Samba NMB Daemon. Jul 06 16:31:33 filodiffusione nmbd[726]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Jul 06 16:31:33 filodiffusione systemd[1]: Starting Samba Winbind Daemon... Jul 06 16:31:33 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:33+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 06 16:31:33 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:33+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jul 06 16:31:33 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:33+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jul 06 16:31:33 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:33+02:00" level=info msg="zeroconf server listening on port 43643" Jul 06 16:31:33 filodiffusione volumio[814]: info: New access token = BQAZAFKrVwWMIAxgnDDzjJYAdJKPN-cbHf3M-zbJMQeyNsKSyHK9I6FiHIqMSORVdp-s4UwblPmruWlOF-O6MCE66RkuYZshiUSX_rgzmIfdKurzmjZckbh-xQiRPvnHJqHt61nM0c8tsijamIa2Ss6SMfe4imuVP1jLjjTooYU0ijiikg47QRrp0Uk2ewhrjKaAvdc0ohWxxjbqgosczLKmCpowhDVQ8_d98vhPg_kbuLSgL3DhgmWcFRgVINvCKUTtrir-CchgqkTtKN5FvCKyQW_tyA38fRnLJYGRQpmnKzE Jul 06 16:31:33 filodiffusione volumio[814]: info: New access token = BQCXhlmG1Sm4pESvRt4p04r_B75jq5eh0j7gJrqg9MGKXQNfHYkP0X11Lp2Z6tkjDxhncBP-oTVAUXHOAizfkT35o9IicuSd0PFrL9BbT8f2Nt9hPqih6WFJoLjizRxeXOHUKM3pAHAi4p-0zdQIqcL4R744LFuEH2ofk-CpLDLphcYf5gnJsGGaoB0YkjhzrF5Hngh0EyGw_YigtExBIOcxDTpEMx6lBDw45HuGGN9nDd9vyuHWI7p7CzWW2SR_G0A_yY4WwfxXTZiMLaGYawxFtTNnjSAashHP-A4HwxRlu7o Jul 06 16:31:33 filodiffusione winbindd[1161]: [2025/07/06 16:31:33.561929, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Jul 06 16:31:33 filodiffusione winbindd[1161]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Jul 06 16:31:33 filodiffusione systemd[1]: apt-daily-upgrade.service: Succeeded. Jul 06 16:31:33 filodiffusione systemd[1]: Started Daily apt upgrade and clean activities. Jul 06 16:31:33 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:33+02:00" level=debug msg="obtained new client token: AACnJc4WJPPAzCaQmTfdNjdqL9uaKNxcV2ag4SZ7jfc4JR/IxgjVWVFm7cNwYUR/B5pHL5g239rkIgnBt9I1eeXVOdRTd0JFYSJHRMt055lwnE8k7bekKXyJb7R+vu7VAQzwldPyUhq1E4sPGC9CcFwNoKPuzZ/jOUkfMVq8mu7GKen4POwv7fnZjanaty1+3usLQpLnz9bbw0fwFQhFCFrQDjn4zLgS/8lrZxrdGniC8xsTfsuwg8mGnvI=" Jul 06 16:31:33 filodiffusione winbindd[1161]: [2025/07/06 16:31:33.628523, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jul 06 16:31:33 filodiffusione winbindd[1161]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Jul 06 16:31:33 filodiffusione systemd[1]: Started Samba Winbind Daemon. Jul 06 16:31:33 filodiffusione systemd[1]: Starting Samba SMB Daemon... Jul 06 16:31:33 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:33+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 06 16:31:33 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:33+02:00" level=debug msg="completed keyexchange" Jul 06 16:31:33 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:33+02:00" level=debug msg="completed challenge" Jul 06 16:31:33 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:33+02:00" level=info msg="authenticated AP as 216qbeuci6oqeirohkqjeqbty" Jul 06 16:31:33 filodiffusione smbd[1190]: [2025/07/06 16:31:33.991980, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jul 06 16:31:33 filodiffusione systemd[1]: Started Samba SMB Daemon. Jul 06 16:31:33 filodiffusione smbd[1190]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Jul 06 16:31:33 filodiffusione systemd[1]: Reached target Multi-User System. Jul 06 16:31:33 filodiffusione systemd[1]: Reached target Graphical Interface. Jul 06 16:31:34 filodiffusione systemd[1]: Starting Update UTMP about System Runlevel Changes... Jul 06 16:31:34 filodiffusione systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jul 06 16:31:34 filodiffusione systemd[1]: Started Update UTMP about System Runlevel Changes. Jul 06 16:31:34 filodiffusione systemd[1]: Startup finished in 12.396s (kernel) + 16.821s (userspace) = 29.217s. Jul 06 16:31:34 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:34+02:00" level=info msg="authenticated Login5 as 216qbeuci6oqeirohkqjeqbty" Jul 06 16:31:34 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:34+02:00" level=debug msg="initializing zeroconf session, username: 216qbeuci6oqeirohkqjeqbty" Jul 06 16:31:34 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:34+02:00" level=debug msg="dealer connection opened" Jul 06 16:31:34 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:34+02:00" level=trace msg="starting accesspoint recv loop" Jul 06 16:31:34 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:34+02:00" level=trace msg="starting dealer recv loop" Jul 06 16:31:34 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:34+02:00" level=trace msg="received accesspoint ping" Jul 06 16:31:34 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:34+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 06 16:31:34 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:34+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 06 16:31:34 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:34+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 06 16:31:34 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:34+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 06 16:31:34 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:34+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 06 16:31:34 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:34+02:00" level=debug msg="received connection id: YzI5NDkwZWYtZDI1My00NzQzLTgzOGEtN2U5MmFkMWQ1NzgxK2RlYWxlcit0Y3A6Ly8wYWIxNTIyMS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMkM5REQ0MjcyQUQ2OTI0MkM0QjJBRkJENEQ2N0Q3OUI1NjI0NDUyNzQxNzJFNjA5ODk2ODY4QUEwQTcyNTk1MQ==" Jul 06 16:31:34 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:34+02:00" level=trace msg="received accesspoint pong ack" Jul 06 16:31:34 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:34+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 06 16:31:35 filodiffusione volumio[814]: info: go-librespot daemon successfully initialized Jul 06 16:31:37 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:37+02:00" level=debug msg="handling transfer player command from 68238803f92152b64ffbaab2dfabf53c6bcfc205" Jul 06 16:31:37 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:37+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:2arPbUnhxe4mRc8NrCJEuD" Jul 06 16:31:37 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:37+02:00" level=trace msg="fetched new page 0 with 283 items (list: 283)" uri="spotify:playlist:2arPbUnhxe4mRc8NrCJEuD" Jul 06 16:31:37 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:37+02:00" level=debug msg="loading track (paused: false, position: 77293ms)" uri="spotify:track:1rN9QoVxw5U7TJkyaUR8C1" Jul 06 16:31:37 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:37+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 06 16:31:37 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:37+02:00" level=trace msg="emitting websocket event: will_play" Jul 06 16:31:37 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:37+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jul 06 16:31:37 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:37+02:00" level=debug msg="selected format OGG_VORBIS_320 (340f84be9e4a9db175703075df30b6d7cd57c834)" uri="spotify:track:1rN9QoVxw5U7TJkyaUR8C1" Jul 06 16:31:37 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:37+02:00" level=debug msg="requested aes key for file 340f84be9e4a9db175703075df30b6d7cd57c834, gid: 1rN9QoVxw5U7TJkyaUR8C1" Jul 06 16:31:37 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:37+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2031" Jul 06 16:31:37 filodiffusione volumio[814]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jul 06 16:31:37 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:37+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1463" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="fetched first chunk of 18, total size is 9172044 bytes" uri="spotify:track:1rN9QoVxw5U7TJkyaUR8C1" Jul 06 16:31:38 filodiffusione volumio[814]: info: Volumio Network Manager: Network status updated: 1 Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:1rN9QoVxw5U7TJkyaUR8C1" Jul 06 16:31:38 filodiffusione sudo[1215]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 06 16:31:38 filodiffusione sudo[1215]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 06 16:31:38 filodiffusione sudo[1215]: pam_unix(sudo:session): session closed for user root Jul 06 16:31:38 filodiffusione sudo[1218]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 06 16:31:38 filodiffusione sudo[1218]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 06 16:31:38 filodiffusione sudo[1218]: pam_unix(sudo:session): session closed for user root Jul 06 16:31:38 filodiffusione volumio[814]: info: Initializing connection to go-librespot Websocket Jul 06 16:31:38 filodiffusione sudo[1221]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jul 06 16:31:38 filodiffusione sudo[1221]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="new websocket client" Jul 06 16:31:38 filodiffusione volumio[814]: info: Connection to go-librespot Websocket established Jul 06 16:31:38 filodiffusione systemd[1]: Started UPnP Renderer front-end to MPD. Jul 06 16:31:38 filodiffusione sudo[1221]: pam_unix(sudo:session): session closed for user root Jul 06 16:31:38 filodiffusione volumio[814]: info: Upmpdcli Daemon Started Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:1rN9QoVxw5U7TJkyaUR8C1" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="fetched chunk 8/17, size: 524288" uri="spotify:track:1rN9QoVxw5U7TJkyaUR8C1" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="fetched chunk 7/17, size: 524288" uri="spotify:track:1rN9QoVxw5U7TJkyaUR8C1" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="fetched chunk 5/17, size: 524288" uri="spotify:track:1rN9QoVxw5U7TJkyaUR8C1" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=trace msg="seek to 77293ms (diff: 170ms, samples: 3408621, bytes: 2925210)" uri="spotify:track:1rN9QoVxw5U7TJkyaUR8C1" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="created new output device" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="fetched chunk 6/17, size: 524288" uri="spotify:track:1rN9QoVxw5U7TJkyaUR8C1" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:1rN9QoVxw5U7TJkyaUR8C1" Jul 06 16:31:38 filodiffusione volumio[1223]: Generating RSA private key, 4096 bit long modulus (2 primes) Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=info msg="loaded track \"unravel\" (paused: false, position: 77293ms, duration: 238360ms, prefetched: false)" uri="spotify:track:1rN9QoVxw5U7TJkyaUR8C1" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=trace msg="scheduling prefetch in 131s" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=trace msg="emitting websocket event: metadata" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=trace msg="emitting websocket event: active" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="sending successful reply for dealer request" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 06 16:31:38 filodiffusione volumio[814]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1rN9QoVxw5U7TJkyaUR8C1","name":"unravel","artist_names":["TK from Ling tosite sigure"],"album_name":"Fantastic Magic","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b11c3ab5cb818192b7a61fdd","position":77293,"duration":238360,"release_date":"year:2014 month:8 day:27","track_number":2,"disc_number":1}} Jul 06 16:31:38 filodiffusione volumio[814]: SPOTIFY: received: {"type":"active","data":null} Jul 06 16:31:38 filodiffusione volumio[814]: info: Aligning Spotify Volume to Volumio Volume Jul 06 16:31:38 filodiffusione volumio[814]: info: CoreCommandRouter::volumioGetState Jul 06 16:31:38 filodiffusione volumio[814]: info: CorePlayQueue::getTrack 0 Jul 06 16:31:38 filodiffusione volumio[814]: info: Setting Spotify Volume from Volumio: 27 Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 06 16:31:38 filodiffusione go-librespot[1070]: time="2025-07-06T16:31:38+02:00" level=trace msg="emitting websocket event: playing" Jul 06 16:31:38 filodiffusione volumio[814]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1rN9QoVxw5U7TJkyaUR8C1","play_origin":"playlist"}} Jul 06 16:31:38 filodiffusione volumio[814]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 06 16:31:38 filodiffusione volumio[814]: TypeError: Cannot read property 'service' of undefined Jul 06 16:31:38 filodiffusione volumio[814]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:340:50) Jul 06 16:31:38 filodiffusione volumio[814]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:266:18) Jul 06 16:31:38 filodiffusione volumio[814]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14) Jul 06 16:31:38 filodiffusione volumio[814]: at WebSocket.emit (events.js:315:20) Jul 06 16:31:38 filodiffusione volumio[814]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jul 06 16:31:38 filodiffusione volumio[814]: at Receiver.emit (events.js:315:20) Jul 06 16:31:38 filodiffusione volumio[814]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jul 06 16:31:38 filodiffusione volumio[814]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jul 06 16:31:38 filodiffusione volumio[814]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jul 06 16:31:38 filodiffusione volumio[814]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jul 06 16:31:38 filodiffusione volumio[814]: at writeOrBuffer (internal/streams/writable.js:358:12) Jul 06 16:31:38 filodiffusione volumio[814]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Jul 06 16:31:38 filodiffusione volumio[814]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Jul 06 16:31:38 filodiffusione volumio[814]: at Socket.emit (events.js:315:20) Jul 06 16:31:38 filodiffusione volumio[814]: at addChunk (internal/streams/readable.js:309:12) Jul 06 16:31:38 filodiffusione volumio[814]: at readableAddChunk (internal/streams/readable.js:284:9) Jul 06 16:31:38 filodiffusione volumio[814]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 06 16:31:39 filodiffusione sudo[1248]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-06 16:30 Jul 06 16:31:39 filodiffusione sudo[1248]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="811ff8312d42f9da0260be1d353081a805678820" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 02 Jul 2025 04:07:25 PM CEST" VOLUMIO_VERSION="3.819" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3b9115b1943141a9d7186aa434f8f3c2"