Jun 09 16:24:00 volumio sudo[3045]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Mon, 09 Jun 2025 16:24:00 GMT#015' Jun 09 16:24:00 volumio sudo[3045]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 09 16:24:00 volumio setdatetime-helper.sh[3046]: Mon Jun 9 16:24:00 UTC 2025 Jun 09 16:24:00 volumio systemd-journald[474]: Time jumped backwards, rotating. Jun 09 16:24:00 volumio sudo[3045]: pam_unix(sudo:session): session closed for user root Jun 09 16:24:00 volumio setdatetime-helper.sh[3016]: Time synchronized successfully. Jun 09 16:24:00 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jun 09 16:24:00 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jun 09 16:24:01 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: networkfs , discoverShares Jun 09 16:24:01 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , browseForService Jun 09 16:24:02 volumio sudo[3075]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 09 16:24:02 volumio sudo[3075]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 09 16:24:02 volumio sudo[3075]: pam_unix(sudo:session): session closed for user root Jun 09 16:24:02 volumio sudo[3078]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 09 16:24:02 volumio sudo[3078]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 09 16:24:02 volumio sudo[3078]: pam_unix(sudo:session): session closed for user root Jun 09 16:24:02 volumio sudo[3083]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 09 16:24:02 volumio sudo[3085]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 09 16:24:02 volumio sudo[3085]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 09 16:24:02 volumio sudo[3083]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 09 16:24:02 volumio sudo[3083]: pam_unix(sudo:session): session closed for user root Jun 09 16:24:02 volumio sudo[3085]: pam_unix(sudo:session): session closed for user root Jun 09 16:24:02 volumio sudo[3091]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 09 16:24:02 volumio sudo[3091]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 09 16:24:02 volumio sudo[3091]: pam_unix(sudo:session): session closed for user root Jun 09 16:24:02 volumio volumio[1016]: info: Upmpdcli Daemon Started Jun 09 16:24:02 volumio sudo[3094]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 09 16:24:02 volumio sudo[3094]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 09 16:24:02 volumio sudo[3094]: pam_unix(sudo:session): session closed for user root Jun 09 16:24:02 volumio volumio[1016]: info: Upmpdcli Daemon Started Jun 09 16:24:02 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 09 16:24:02 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 09 16:24:02 volumio volumio[1016]: info: Executing SMB command: smbclient --no-pass --debuglevel=0 -L NAS.local. Jun 09 16:24:03 volumio nmbd[1002]: [2025/06/09 16:24:03.069860, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jun 09 16:24:03 volumio nmbd[1002]: Packet send failed to 169.254.255.255(138) ERRNO=Network is unreachable Jun 09 16:24:06 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 09 16:24:08 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 09 16:24:08 volumio volumio[1016]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Jun 09 16:24:08 volumio volumio[1016]: info: CoreCommandRouter::volumioGetState Jun 09 16:24:08 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:24:10 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 09 16:24:10 volumio volumio[1016]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jun 09 16:24:10 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jun 09 16:24:10 volumio volumio[1016]: info: Received Get System Version Jun 09 16:24:10 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 09 16:24:10 volumio volumio[1016]: info: Received Get System Info Jun 09 16:24:10 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 09 16:24:10 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 09 16:24:10 volumio volumio[1016]: info: Discovery: Getting this device information Jun 09 16:24:10 volumio volumio[1016]: info: CoreCommandRouter::volumioGetState Jun 09 16:24:10 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:24:10 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 09 16:24:10 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 09 16:24:13 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 09 16:24:13 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 09 16:24:13 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Jun 09 16:24:13 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jun 09 16:24:13 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jun 09 16:24:13 volumio volumio[1016]: info: CoreCommandRouter::volumioGetBrowseSources Jun 09 16:24:13 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 09 16:24:14 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 09 16:24:18 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 09 16:24:22 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 09 16:24:25 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: networkfs , addShare Jun 09 16:24:25 volumio volumio[1016]: info: Adding a new share Jun 09 16:24:25 volumio volumio[1016]: info: No correspondence found in configuration for share SERVER on IP 192.168.0.12 Jun 09 16:24:25 volumio volumio[1016]: info: Executing SMB command: smbclient --debuglevel=4 -L 192.168.0.12 -N Jun 09 16:24:25 volumio volumio[1016]: info: Error browsing device SERVER for shares: Command failed: smbclient --debuglevel=4 -L 192.168.0.12 -N Jun 09 16:24:25 volumio volumio[1016]: lp_load_ex: refreshing parameters Jun 09 16:24:25 volumio volumio[1016]: Initialising global parameters Jun 09 16:24:25 volumio volumio[1016]: Processing section "[global]" Jun 09 16:24:25 volumio volumio[1016]: doing parameter netbios name = Volumio Jun 09 16:24:25 volumio volumio[1016]: doing parameter server string = Volumio Audiophile Music Player Jun 09 16:24:25 volumio volumio[1016]: doing parameter workgroup = WORKGROUP Jun 09 16:24:25 volumio volumio[1016]: doing parameter security = user Jun 09 16:24:25 volumio volumio[1016]: doing parameter map to guest = Bad User Jun 09 16:24:25 volumio volumio[1016]: doing parameter encrypt passwords = yes Jun 09 16:24:25 volumio volumio[1016]: lpcfg_do_global_parameter: WARNING: The "encrypt passwords" option is deprecated Jun 09 16:24:25 volumio volumio[1016]: doing parameter wins support = yes Jun 09 16:24:25 volumio volumio[1016]: doing parameter local master = no Jun 09 16:24:25 volumio volumio[1016]: doing parameter preferred master = no Jun 09 16:24:25 volumio volumio[1016]: doing parameter os level = 30 Jun 09 16:24:25 volumio volumio[1016]: doing parameter fruit:model = AirPort Jun 09 16:24:25 volumio volumio[1016]: pm_process() returned Yes Jun 09 16:24:25 volumio volumio[1016]: added interface eth0 ip=172.16.0.202 bcast=172.16.0.255 netmask=255.255.255.0 Jun 09 16:24:25 volumio volumio[1016]: Client started (version 4.17.12-Debian). Jun 09 16:24:25 volumio volumio[1016]: Connecting to 192.168.0.12 at port 445 Jun 09 16:24:25 volumio volumio[1016]: session request ok Jun 09 16:24:25 volumio volumio[1016]: negotiated dialect[SMB3_11] against server[192.168.0.12] Jun 09 16:24:25 volumio volumio[1016]: GENSEC backend 'gssapi_spnego' registered Jun 09 16:24:25 volumio volumio[1016]: GENSEC backend 'gssapi_krb5' registered Jun 09 16:24:25 volumio volumio[1016]: GENSEC backend 'gssapi_krb5_sasl' registered Jun 09 16:24:25 volumio volumio[1016]: GENSEC backend 'spnego' registered Jun 09 16:24:25 volumio volumio[1016]: GENSEC backend 'schannel' registered Jun 09 16:24:25 volumio volumio[1016]: GENSEC backend 'ncalrpc_as_system' registered Jun 09 16:24:25 volumio volumio[1016]: GENSEC backend 'sasl-EXTERNAL' registered Jun 09 16:24:25 volumio volumio[1016]: GENSEC backend 'ntlmssp' registered Jun 09 16:24:25 volumio volumio[1016]: GENSEC backend 'ntlmssp_resume_ccache' registered Jun 09 16:24:25 volumio volumio[1016]: GENSEC backend 'http_basic' registered Jun 09 16:24:25 volumio volumio[1016]: GENSEC backend 'http_ntlm' registered Jun 09 16:24:25 volumio volumio[1016]: GENSEC backend 'http_negotiate' registered Jun 09 16:24:25 volumio volumio[1016]: GENSEC backend 'krb5' registered Jun 09 16:24:25 volumio volumio[1016]: GENSEC backend 'fake_gssapi_krb5' registered Jun 09 16:24:25 volumio volumio[1016]: Cannot do GSE to an IP address Jun 09 16:24:25 volumio volumio[1016]: Failed to start GENSEC client mech gse_krb5: NT_STATUS_INVALID_PARAMETER Jun 09 16:24:25 volumio volumio[1016]: Got challenge flags: Jun 09 16:24:25 volumio volumio[1016]: Got NTLMSSP neg_flags=0x628a8215 Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_UNICODE Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_REQUEST_TARGET Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_SIGN Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_NTLM Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_ALWAYS_SIGN Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_TARGET_TYPE_SERVER Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_EXTENDED_SESSIONSECURITY Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_TARGET_INFO Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_VERSION Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_128 Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_KEY_EXCH Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP: Set final flags: Jun 09 16:24:25 volumio volumio[1016]: Got NTLMSSP neg_flags=0x62008215 Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_UNICODE Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_REQUEST_TARGET Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_SIGN Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_NTLM Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_ALWAYS_SIGN Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_VERSION Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_128 Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_KEY_EXCH Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP Sign/Seal - Initialising with flags: Jun 09 16:24:25 volumio volumio[1016]: Got NTLMSSP neg_flags=0x62008215 Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_UNICODE Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_REQUEST_TARGET Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_SIGN Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_NTLM Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_ALWAYS_SIGN Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_VERSION Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_128 Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_KEY_EXCH Jun 09 16:24:25 volumio volumio[1016]: SPNEGO login failed: The attempted logon is invalid. This is either due to a bad username or authentication information. Jun 09 16:24:25 volumio volumio[1016]: Got challenge flags: Jun 09 16:24:25 volumio volumio[1016]: Got NTLMSSP neg_flags=0x628a8215 Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_UNICODE Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_REQUEST_TARGET Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_SIGN Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_NTLM Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_ALWAYS_SIGN Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_TARGET_TYPE_SERVER Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_EXTENDED_SESSIONSECURITY Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_TARGET_INFO Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_VERSION Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_128 Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_KEY_EXCH Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP: Set final flags: Jun 09 16:24:25 volumio volumio[1016]: Got NTLMSSP neg_flags=0x62008a15 Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_UNICODE Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_REQUEST_TARGET Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_SIGN Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_NTLM Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_ANONYMOUS Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_ALWAYS_SIGN Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_VERSION Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_128 Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_KEY_EXCH Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP Sign/Seal - Initialising with flags: Jun 09 16:24:25 volumio volumio[1016]: Got NTLMSSP neg_flags=0x62008a15 Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_UNICODE Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_REQUEST_TARGET Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_SIGN Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_NTLM Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_ANONYMOUS Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_ALWAYS_SIGN Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_VERSION Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_128 Jun 09 16:24:25 volumio volumio[1016]: NTLMSSP_NEGOTIATE_KEY_EXCH Jun 09 16:24:25 volumio volumio[1016]: SPNEGO login failed: {Access Denied} A process has requested access to an object but has not been granted those access rights. Jun 09 16:24:25 volumio volumio[1016]: info: Detected device SERVER with version null Jun 09 16:24:25 volumio sudo[3254]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.12/AUDIO /mnt/NAS/SERVER Jun 09 16:24:25 volumio sudo[3254]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 09 16:24:25 volumio kernel: netfs: FS-Cache loaded Jun 09 16:24:25 volumio kernel: Key type dns_resolver registered Jun 09 16:24:25 volumio kernel: Key type cifs.spnego registered Jun 09 16:24:25 volumio kernel: Key type cifs.idmap registered Jun 09 16:24:25 volumio kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Jun 09 16:24:25 volumio kernel: CIFS: Attempting to mount //192.168.0.12/AUDIO Jun 09 16:24:25 volumio kernel: CIFS: Status code returned 0xc0000022 STATUS_ACCESS_DENIED Jun 09 16:24:25 volumio kernel: CIFS: VFS: \\192.168.0.12 Send error in SessSetup = -13 Jun 09 16:24:25 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -13 Jun 09 16:24:25 volumio sudo[3254]: pam_unix(sudo:session): session closed for user root Jun 09 16:24:25 volumio volumio[1016]: info: Permission denied for SERVER on IP 192.168.0.12 Jun 09 16:24:26 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Jun 09 16:24:26 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 09 16:24:29 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. Jun 09 16:24:30 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 09 16:24:33 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: networkfs , editShare Jun 09 16:24:33 volumio volumio[1016]: info: Share SERVER successfully unmounted Jun 09 16:24:33 volumio sudo[3313]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=admin,password=Mercury1809!,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.12/AUDIO /mnt/NAS/SERVER Jun 09 16:24:33 volumio sudo[3313]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 09 16:24:33 volumio kernel: CIFS: Attempting to mount //192.168.0.12/AUDIO Jun 09 16:24:33 volumio sudo[3313]: pam_unix(sudo:session): session closed for user root Jun 09 16:24:33 volumio volumio[1016]: verbose: ControllerMpd::sendMpdCommand status Jun 09 16:24:33 volumio volumio[1016]: info: Jun 09 16:24:33 volumio volumio[1016]: ---------------------------- MPD announces state update: update Jun 09 16:24:33 volumio volumio[1016]: info: ControllerMpd::getState Jun 09 16:24:33 volumio volumio[1016]: verbose: ControllerMpd::sendMpdCommand status Jun 09 16:24:33 volumio volumio[1016]: verbose: ControllerMpd::sendMpdCommand status Jun 09 16:24:33 volumio volumio[1016]: info: Jun 09 16:24:33 volumio volumio[1016]: ---------------------------- MPD announces state update: update Jun 09 16:24:33 volumio volumio[1016]: info: ControllerMpd::getState Jun 09 16:24:33 volumio volumio[1016]: verbose: ControllerMpd::sendMpdCommand status Jun 09 16:24:33 volumio volumio[1016]: info: sendMpdCommand status took 0 milliseconds Jun 09 16:24:33 volumio volumio[1016]: info: sendMpdCommand status took 0 milliseconds Jun 09 16:24:33 volumio volumio[1016]: info: sendMpdCommand status took 0 milliseconds Jun 09 16:24:33 volumio volumio[1016]: info: sendMpdCommand status took 0 milliseconds Jun 09 16:24:33 volumio volumio[1016]: verbose: ControllerMpd::parseState Jun 09 16:24:33 volumio volumio[1016]: info: Command Router : Notfying DB Updatetrue Jun 09 16:24:33 volumio volumio[1016]: verbose: ControllerMpd::parseState Jun 09 16:24:33 volumio volumio[1016]: verbose: ControllerMpd::parseState Jun 09 16:24:33 volumio volumio[1016]: info: Command Router : Notfying DB Updatetrue Jun 09 16:24:33 volumio volumio[1016]: info: CoreCommandRouter::Close All Modals sent Jun 09 16:24:33 volumio volumio[1016]: verbose: ControllerMpd::parseState Jun 09 16:24:33 volumio volumio[1016]: info: ControllerMpd::pushState Jun 09 16:24:33 volumio volumio[1016]: info: CoreCommandRouter::servicePushState Jun 09 16:24:33 volumio volumio[1016]: info: CoreStateMachine::pushState Jun 09 16:24:33 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:24:33 volumio volumio[1016]: info: CoreCommandRouter::volumioPushState Jun 09 16:24:33 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:24:33 volumio volumio[1016]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Jun 09 16:24:33 volumio volumio[1016]: verbose: CURRENT POSITION 0 Jun 09 16:24:33 volumio volumio[1016]: info: CoreStateMachine::syncState stateService stop Jun 09 16:24:33 volumio volumio[1016]: info: CoreStateMachine::syncState currentStatus stop Jun 09 16:24:33 volumio volumio[1016]: info: CoreStateMachine::pushState Jun 09 16:24:33 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:24:33 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 09 16:24:33 volumio volumio[1016]: info: CoreCommandRouter::volumioPushState Jun 09 16:24:33 volumio volumio[1016]: info: No code Jun 09 16:24:33 volumio volumio[1016]: info: CoreStateMachine::pushState Jun 09 16:24:33 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:24:33 volumio volumio[1016]: info: CoreCommandRouter::volumioPushState Jun 09 16:24:33 volumio volumio[1016]: info: ControllerMpd::pushState Jun 09 16:24:33 volumio volumio[1016]: info: CoreCommandRouter::servicePushState Jun 09 16:24:33 volumio volumio[1016]: info: CoreStateMachine::pushState Jun 09 16:24:33 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:24:33 volumio volumio[1016]: info: CoreCommandRouter::volumioPushState Jun 09 16:24:33 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:24:33 volumio volumio[1016]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Jun 09 16:24:33 volumio volumio[1016]: verbose: CURRENT POSITION 0 Jun 09 16:24:33 volumio volumio[1016]: info: CoreStateMachine::syncState stateService stop Jun 09 16:24:33 volumio volumio[1016]: info: CoreStateMachine::syncState currentStatus stop Jun 09 16:24:33 volumio volumio[1016]: info: CoreStateMachine::pushState Jun 09 16:24:33 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:24:33 volumio volumio[1016]: info: CoreCommandRouter::volumioPushState Jun 09 16:24:33 volumio volumio[1016]: info: No code Jun 09 16:24:33 volumio volumio[1016]: info: CoreStateMachine::pushState Jun 09 16:24:33 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:24:33 volumio volumio[1016]: info: CoreCommandRouter::volumioPushState Jun 09 16:24:33 volumio volumio[1016]: info: ------------------------------ 102ms Jun 09 16:24:33 volumio volumio[1016]: info: ------------------------------ 102ms Jun 09 16:24:33 volumio volumio[1016]: info: [1749486273241] Database update started Jun 09 16:24:34 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Jun 09 16:24:34 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 09 16:24:38 volumio volumio[1016]: info: Disabling MyMusic plugin upnp_browser Jun 09 16:24:38 volumio volumio[1016]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesMedia Servers Jun 09 16:24:38 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 09 16:24:38 volumio volumio[1016]: info: Disabling plugin upnp_browser Jun 09 16:24:38 volumio volumio[1016]: info: Done. Jun 09 16:24:38 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 09 16:24:40 volumio volumio[1016]: info: Disabling MyMusic plugin airplay_emulation Jun 09 16:24:40 volumio volumio[1016]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesShairport-Sync Jun 09 16:24:40 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 09 16:24:40 volumio volumio[1016]: info: Disabling plugin airplay_emulation Jun 09 16:24:40 volumio volumio[1016]: info: Done. Jun 09 16:24:40 volumio sudo[3361]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop shairport-sync Jun 09 16:24:40 volumio sudo[3361]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 09 16:24:40 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jun 09 16:24:40 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jun 09 16:24:40 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 09 16:24:40 volumio systemd[1]: shairport-sync.service: Consumed 1.456s CPU time. Jun 09 16:24:40 volumio sudo[3361]: pam_unix(sudo:session): session closed for user root Jun 09 16:24:40 volumio volumio[1016]: info: Shairport-Sync Stopped Jun 09 16:24:41 volumio volumio[1016]: info: Disabling MyMusic plugin upnp Jun 09 16:24:41 volumio sudo[3366]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Jun 09 16:24:41 volumio sudo[3366]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 09 16:24:41 volumio systemd[1]: Stopping upmpdcli.service - UPnP Renderer front-end to MPD... Jun 09 16:24:41 volumio systemd[1]: upmpdcli.service: Deactivated successfully. Jun 09 16:24:41 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Jun 09 16:24:41 volumio sudo[3366]: pam_unix(sudo:session): session closed for user root Jun 09 16:24:41 volumio volumio[1016]: info: Disabling plugin upnp Jun 09 16:24:41 volumio volumio[1016]: info: Done. Jun 09 16:24:42 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 09 16:24:46 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 09 16:24:50 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 09 16:24:51 volumio volumio[1016]: info: Enabling MyMusic plugin metavolumio Jun 09 16:24:51 volumio volumio[1016]: info: [MyVolumio PluginManager] Enabling and starting plugin miscellanea metavolumio Jun 09 16:24:51 volumio volumio[1016]: info: [MyVolumio PluginManager] Plugin miscellanea metavolumio not in user plan, not enabling Jun 09 16:24:51 volumio volumio[1016]: info: Error: Plugin miscellanea metavolumio not in user plan, not enabling Jun 09 16:24:51 volumio volumio[1016]: error: Could not Enable MyMusic Plugin: Error Jun 09 16:24:54 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 09 16:24:58 volumio volumio[1016]: info: CoreCommandRouter::volumioGetState Jun 09 16:24:58 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:24:59 volumio volumio[1016]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/135.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::volumioGetState Jun 09 16:25:00 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:25:00 volumio volumio[1016]: info: Received Get System Info Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 09 16:25:00 volumio volumio[1016]: info: Discovery: Getting this device information Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::volumioGetState Jun 09 16:25:00 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::volumioGetState Jun 09 16:25:00 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::volumioGetVisibleSources Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::volumioGetState Jun 09 16:25:00 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::volumioGetState Jun 09 16:25:00 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 09 16:25:00 volumio volumio[1016]: info: Received Get System Info Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 09 16:25:00 volumio volumio[1016]: info: Discovery: Getting this device information Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::volumioGetState Jun 09 16:25:00 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::volumioGetState Jun 09 16:25:00 volumio volumio[1016]: info: CorePlayQueue::getTrack 0 Jun 09 16:25:00 volumio volumio[1016]: info: Listing playlists Jun 09 16:25:00 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 09 16:25:09 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 09 16:25:21 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Jun 09 16:25:21 volumio volumio[1016]: info: MyVolumio login type: Token Jun 09 16:25:22 volumio volumio[1016]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jun 09 16:25:22 volumio volumio[1016]: info: MyVolumio token set successfully Jun 09 16:25:22 volumio volumio[1016]: info: MYVOLUMIO: Adding device Jun 09 16:25:22 volumio volumio[1016]: info: MYVOLUMIO: Evaluating Server Jun 09 16:25:23 volumio volumio[1016]: info: MyVolumio Plan changed: premium Jun 09 16:25:23 volumio volumio[1016]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Jun 09 16:25:23 volumio volumio[1016]: info: Removing browser output: myVolumio user plan is not superstar Jun 09 16:25:23 volumio volumio[1016]: info: Removing audio output: Jun 09 16:25:23 volumio volumio[1016]: info: MYVOLUMIO: Adding device Jun 09 16:25:23 volumio volumio[1016]: info: MYVOLUMIO: Evaluating Server Jun 09 16:25:23 volumio volumio[1016]: info: Remote config written successfully Jun 09 16:25:23 volumio volumio[1016]: info: Starting Tunnel 1 Jun 09 16:25:23 volumio volumio[1016]: info: Starting Tunnel Connection Checker Jun 09 16:25:23 volumio volumio[1016]: info: MYVolumio Device enabled Jun 09 16:25:23 volumio volumio[1016]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Jun 09 16:25:23 volumio volumio[1016]: info: MyVolumio status changed Jun 09 16:25:23 volumio volumio[1016]: info: Streaming services startup Jun 09 16:25:23 volumio volumio[1016]: info: Starting Streaming Daemon Jun 09 16:25:23 volumio volumio[1016]: error: [MyVolumio PluginManager] Could not read cache file: ENOENT: no such file or directory, open '/data/myvolumio/cache.data' Jun 09 16:25:23 volumio sudo[3501]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 09 16:25:23 volumio sudo[3501]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 09 16:25:23 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Jun 09 16:25:23 volumio sudo[3501]: pam_unix(sudo:session): session closed for user root Jun 09 16:25:23 volumio volumio[1016]: error: Cannot start Volumio Streaming Daemon Jun 09 16:25:23 volumio volumio[1016]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 09 16:25:23 volumio volumio[1016]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 09 16:25:23 volumio dbus-daemon[755]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.42' (uid=0 pid=3504 comm="timedatectl show --property=NTPSynchronized --valu") Jun 09 16:25:23 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... Jun 09 16:25:23 volumio dbus-daemon[755]: [system] Successfully activated service 'org.freedesktop.timedate1' Jun 09 16:25:23 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. Jun 09 16:25:23 volumio setdatetime-helper.sh[3503]: Time is not synchronized. Attempting to sync... Jun 09 16:25:23 volumio volumio[1016]: info: Setting Geolocation for MyVolumio to eu3 Jun 09 16:25:23 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 09 16:25:23 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 09 16:25:23 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 09 16:25:23 volumio sudo[3513]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Mon, 09 Jun 2025 16:25:23 GMT#015' Jun 09 16:25:23 volumio sudo[3513]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 09 16:25:23 volumio setdatetime-helper.sh[3514]: Mon Jun 9 16:25:23 UTC 2025 Jun 09 16:25:23 volumio sudo[3513]: pam_unix(sudo:session): session closed for user root Jun 09 16:25:23 volumio systemd-journald[474]: Time jumped backwards, rotating. Jun 09 16:25:23 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jun 09 16:25:23 volumio setdatetime-helper.sh[3503]: Time synchronized successfully. Jun 09 16:25:23 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jun 09 16:25:23 volumio volumio[1016]: info: Setting Geolocation for MyVolumio to au1 Jun 09 16:25:23 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 09 16:25:23 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 09 16:25:23 volumio volumio[1016]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 09 16:25:23 volumio volumio[1016]: error: Failed to ping endpoint au1.myvolumio.org : unknown error Jun 09 16:25:23 volumio volumio[1016]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 09 16:25:23 volumio volumio[1016]: Error: Unable to resolve or reject the same promise twice Jun 09 16:25:23 volumio volumio[1016]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Jun 09 16:25:23 volumio volumio[1016]: at Socket. (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:32371) Jun 09 16:25:23 volumio volumio[1016]: at Socket.emit (node:events:514:28) Jun 09 16:25:23 volumio volumio[1016]: at addChunk (node:internal/streams/readable:343:12) Jun 09 16:25:23 volumio volumio[1016]: at readableAddChunk (node:internal/streams/readable:316:9) Jun 09 16:25:23 volumio volumio[1016]: at Readable.push (node:internal/streams/readable:253:10) Jun 09 16:25:23 volumio volumio[1016]: at Pipe.onStreamRead (node:internal/stream_base_commons:190:23) Jun 09 16:25:23 volumio volumio[1016]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 09 16:25:23 volumio sudo[3530]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-06-09 16:24' Jun 09 16:25:23 volumio sudo[3530]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="9c17cc34697ef689c9c9b64ea62ec0a8e386d7ce" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Jun 7 03:41:32 UTC 2025" VOLUMIO_VERSION="4.011" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="3d7d070df9925b1237bac9fe8beec51e"