-- Logs begin at Mon 2024-08-26 15:21:24 +07, end at Fri 2024-08-30 22:22:57 +07. --
Aug 30 22:21:03 volumio volumio[23969]: error: Plugin system_controller system failed to complete 'onVolumioStart' in a timely fashion
Aug 30 22:21:03 volumio volumio[23969]: info: Preparing to generate the ALSA configuration file
Aug 30 22:21:03 volumio volumio[23969]: info: Asound.conf file unchanged, so no further update is needed
Aug 30 22:21:03 volumio volumio[23969]: info: Output device has changed, restarting MPD
Aug 30 22:21:03 volumio sudo[24151]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Aug 30 22:21:03 volumio volumio[23969]: info: Output device has changed, restarting Shairport Sync
Aug 30 22:21:03 volumio sudo[24151]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:21:03 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:03 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:03 volumio sudo[24151]: pam_unix(sudo:session): session closed for user root
Aug 30 22:21:03 volumio sudo[24153]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Aug 30 22:21:03 volumio sudo[24153]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:21:03 volumio systemd[1]: Stopping Music Player Daemon...
Aug 30 22:21:03 volumio volumio[23969]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Aug 30 22:21:03 volumio volumio[23969]: info: ___________ START PLUGINS ___________
Aug 30 22:21:03 volumio volumio[23969]: info: ControllerMpd::onStart: Initializing MPD
Aug 30 22:21:03 volumio volumio[23969]: info: Creating MPD Configuration file
Aug 30 22:21:03 volumio systemd[1]: mpd.service: Succeeded.
Aug 30 22:21:03 volumio systemd[1]: Stopped Music Player Daemon.
Aug 30 22:21:03 volumio sudo[24160]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Aug 30 22:21:03 volumio sudo[24160]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:21:03 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Aug 30 22:21:03 volumio sudo[24160]: pam_unix(sudo:session): session closed for user root
Aug 30 22:21:03 volumio volumio[23969]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Aug 30 22:21:04 volumio volumio[23969]: info: [1725031264000] CoreMusicLibrary::Adding element Media Servers
Aug 30 22:21:04 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Aug 30 22:21:04 volumio sudo[24162]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Aug 30 22:21:04 volumio sudo[24162]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:21:04 volumio systemd[1]: Starting Music Player Daemon...
Aug 30 22:21:04 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM
Aug 30 22:21:04 volumio systemd[1]: mpd.service: Succeeded.
Aug 30 22:21:04 volumio systemd[1]: Stopped Music Player Daemon.
Aug 30 22:21:04 volumio systemd[1]: Starting Music Player Daemon...
Aug 30 22:21:04 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:04 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:04 volumio volumio[23969]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Aug 30 22:21:04 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:04 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:04 volumio volumio[23969]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Aug 30 22:21:04 volumio volumio[23969]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Aug 30 22:21:04 volumio volumio[23969]: info: [1725031264299] CoreMusicLibrary::Adding element Last_100
Aug 30 22:21:04 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Aug 30 22:21:04 volumio volumio[23969]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Aug 30 22:21:04 volumio volumio[23969]: info: [1725031264306] CoreMusicLibrary::Adding element Webradio
Aug 30 22:21:04 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Aug 30 22:21:04 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Aug 30 22:21:04 volumio volumio[23969]: info: Creating Spotify config file
Aug 30 22:21:04 volumio volumio[23969]: info: Volumio Calling Home
Aug 30 22:21:04 volumio volumio[23969]: info: MPD Permissions set
Aug 30 22:21:04 volumio volumio[23969]: info: MPD Permissions set
Aug 30 22:21:04 volumio volumio[23969]: info: Spotify config file written
Aug 30 22:21:04 volumio sudo[24178]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Aug 30 22:21:04 volumio sudo[24178]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:21:05 volumio systemd[1]: Stopping go-librespot Daemon...
Aug 30 22:21:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM
Aug 30 22:21:05 volumio systemd[1]: go-librespot-daemon.service: Succeeded.
Aug 30 22:21:05 volumio systemd[1]: Stopped go-librespot Daemon.
Aug 30 22:21:05 volumio systemd[1]: Started go-librespot Daemon.
Aug 30 22:21:05 volumio go-librespot[24180]: Librespot-go daemon starting...
Aug 30 22:21:05 volumio sudo[24178]: pam_unix(sudo:session): session closed for user root
Aug 30 22:21:05 volumio go-librespot[24180]: time="2024-08-30T22:21:05+07:00" level=info msg="generated new device id: fb869bef6b34945ca3a4098868affffa3d18dd7e"
Aug 30 22:21:05 volumio go-librespot[24180]: time="2024-08-30T22:21:05+07:00" level=debug msg="stored credentials found for n2ksou2st5zcra3f47zugosz9"
Aug 30 22:21:05 volumio volumio[23969]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 13
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:05 volumio volumio[23969]: info: Volumio called home
Aug 30 22:21:05 volumio go-librespot[24180]: time="2024-08-30T22:21:05+07:00" level=debug msg="obtained new client token: AAAOfWXZSlJS/hH8sTky1KfuxdlxHtWOjbd6pu5SNNj5rPzHJgz5yAkj6VwnC70ueyKsLtrK5Tb9FZEoFUGHFSwa97AalUhyjI8atEP51RC7c2nEPw3KxEYpbckkAvUVYOAH2E3Ejuwnc6ZKmPUZj4OC7Bz07OMbk9aIoIbJHJQryjCm6VZao6koHYMyGzZ+KbFX8Zw/NnstPWzj5iCziOBhjtsETE/OC7dQufGjNcCSM9NtWer4EwHXfmcvpg=="
Aug 30 22:21:05 volumio volumio[23969]: info: Starting Shairport Sync
Aug 30 22:21:05 volumio volumio[23969]: info: Starting Shairport Sync
Aug 30 22:21:05 volumio volumio[23969]: info: Starting Shairport Sync
Aug 30 22:21:06 volumio sudo[24198]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Aug 30 22:21:06 volumio sudo[24198]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:21:06 volumio sudo[24203]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Aug 30 22:21:06 volumio sudo[24203]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:21:06 volumio sudo[24200]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Aug 30 22:21:06 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver...
Aug 30 22:21:06 volumio sudo[24200]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:21:06 volumio systemd[1]: shairport-sync.service: Succeeded.
Aug 30 22:21:06 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver.
Aug 30 22:21:06 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
Aug 30 22:21:06 volumio sudo[24198]: pam_unix(sudo:session): session closed for user root
Aug 30 22:21:06 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver...
Aug 30 22:21:06 volumio systemd[1]: shairport-sync.service: Succeeded.
Aug 30 22:21:06 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver.
Aug 30 22:21:06 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
Aug 30 22:21:06 volumio go-librespot[24180]: time="2024-08-30T22:21:06+07:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]"
Aug 30 22:21:06 volumio sudo[24203]: pam_unix(sudo:session): session closed for user root
Aug 30 22:21:06 volumio sudo[24200]: pam_unix(sudo:session): session closed for user root
Aug 30 22:21:06 volumio mpd[24166]: Aug 30 22:21 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Aug 30 22:21:06 volumio volumio[23969]: info: Shairport-Sync Started
Aug 30 22:21:06 volumio volumio[23969]: Error adding Membership: Error: addMembership EINVAL
Aug 30 22:21:06 volumio volumio[23969]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Aug 30 22:21:06 volumio volumio[23969]: SPOTIFY: BQC_l6eMsdAvOZYu36zbO7lbHJpC3eSAzbLJw-yZLr5C9KTInODdF8p-N5eIOrVYnLzeyFq2F5QCDFifimGKYUWa-psZpGAl3lAf0_QFobLmP5g1aavEWBXfe5ugn59WOaO2E1s6sokQ1WAOnB9h7MhsznphW4dn901GsHMurgJUTGdANO9ZO8-byIliBPUaawPrG3TBVFm04T18DJ0Z2GVv7OCfb1X5fg-S9A2i0mUQQWM--s6mguda6vI0AgV67cqykKg44bNUrN_4ITfFpAq8pw
Aug 30 22:21:06 volumio volumio[23969]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Aug 30 22:21:06 volumio volumio[23969]: info: New Spotify access token = BQC_l6eMsdAvOZYu36zbO7lbHJpC3eSAzbLJw-yZLr5C9KTInODdF8p-N5eIOrVYnLzeyFq2F5QCDFifimGKYUWa-psZpGAl3lAf0_QFobLmP5g1aavEWBXfe5ugn59WOaO2E1s6sokQ1WAOnB9h7MhsznphW4dn901GsHMurgJUTGdANO9ZO8-byIliBPUaawPrG3TBVFm04T18DJ0Z2GVv7OCfb1X5fg-S9A2i0mUQQWM--s6mguda6vI0AgV67cqykKg44bNUrN_4ITfFpAq8pw
Aug 30 22:21:06 volumio volumio[23969]: info: Spotify credentials grant success - running version from March 24, 2019
Aug 30 22:21:06 volumio volumio[23969]: info: Shairport-Sync Started
Aug 30 22:21:06 volumio volumio[23969]: info: Shairport-Sync Started
Aug 30 22:21:06 volumio go-librespot[24180]: time="2024-08-30T22:21:06+07:00" level=debug msg="completed keyexchange"
Aug 30 22:21:06 volumio volumio[23969]: info: CoreCommandRouter::volumioGetState
Aug 30 22:21:06 volumio volumio[23969]: info: CorePlayQueue::getTrack 0
Aug 30 22:21:06 volumio volumio[23969]: SPOTIFY: User informations: {"display_name":"anton","external_urls":{"spotify":"https://open.spotify.com/user/n2ksou2st5zcra3f47zugosz9"},"href":"https://api.spotify.com/v1/users/n2ksou2st5zcra3f47zugosz9","id":"n2ksou2st5zcra3f47zugosz9","images":[],"type":"user","uri":"spotify:user:n2ksou2st5zcra3f47zugosz9","followers":{"href":null,"total":0},"country":"TR","product":"premium","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"anton.a.agafonov@gmail.com"}
Aug 30 22:21:06 volumio volumio[23969]: info: Spotify Successfully logged in
Aug 30 22:21:06 volumio volumio[23969]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Aug 30 22:21:06 volumio volumio[23969]: info: [1725031266979] CoreMusicLibrary::Adding element Spotify
Aug 30 22:21:06 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Aug 30 22:21:06 volumio volumio[23969]: Cannot find translation for source Spotify
Aug 30 22:21:07 volumio go-librespot[24180]: time="2024-08-30T22:21:07+07:00" level=debug msg="completed challenge"
Aug 30 22:21:07 volumio go-librespot[24180]: time="2024-08-30T22:21:07+07:00" level=debug msg="authenticated as n2ksou2st5zcra3f47zugosz9"
Aug 30 22:21:07 volumio volumio[23969]: error: An error occurred while listing Spotify featured playlists WebapiRegularError: An error occurred while communicating with Spotify's Web API.
Aug 30 22:21:07 volumio volumio[23969]: Details: Spotify is unavailable in this country.
Aug 30 22:21:07 volumio volumio[23969]: info: An error occurred while getting Spotify ROOT Discover Folders:
Aug 30 22:21:07 volumio volumio[23969]: error: An error occurred while listing Spotify categories WebapiRegularError: An error occurred while communicating with Spotify's Web API.
Aug 30 22:21:07 volumio volumio[23969]: Details: Spotify is unavailable in this country.
Aug 30 22:21:07 volumio volumio[23969]: error: An error occurred while listing Spotify new albums WebapiRegularError: An error occurred while communicating with Spotify's Web API.
Aug 30 22:21:07 volumio volumio[23969]: Details: Spotify is unavailable in this country.
Aug 30 22:21:07 volumio systemd[1]: Started Music Player Daemon.
Aug 30 22:21:07 volumio sudo[24153]: pam_unix(sudo:session): session closed for user root
Aug 30 22:21:07 volumio sudo[24162]: pam_unix(sudo:session): session closed for user root
Aug 30 22:21:07 volumio volumio[23969]: info: Completed starting Core Plugins
Aug 30 22:21:07 volumio volumio[23969]: info: -------------------------------------------
Aug 30 22:21:07 volumio volumio[23969]: info: ----- MyVolumio plugins startup ----
Aug 30 22:21:07 volumio volumio[23969]: info: -------------------------------------------
Aug 30 22:21:07 volumio volumio[23969]: info: [MyVolumio PluginManager] Fetching plans data....
Aug 30 22:21:07 volumio go-librespot[24180]: time="2024-08-30T22:21:07+07:00" level=debug msg="authenticated as n2ksou2st5zcra3f47zugosz9"
Aug 30 22:21:07 volumio go-librespot[24180]: time="2024-08-30T22:21:07+07:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Aug 30 22:21:07 volumio volumio[23969]: error: MPD error: The expression evaluated to a falsy value:
Aug 30 22:21:07 volumio volumio[23969]: assert.ok(self.idling)
Aug 30 22:21:07 volumio volumio[23969]: error: The expression evaluated to a falsy value:
Aug 30 22:21:07 volumio volumio[23969]: assert.ok(self.idling)
Aug 30 22:21:07 volumio volumio[23969]: info: MPD running with PID24166
Aug 30 22:21:07 volumio volumio[23969]: ,establishing connection
Aug 30 22:21:07 volumio volumio[23969]: error: updateQueue error: null
Aug 30 22:21:07 volumio volumio[23969]: error: updateQueue error: null
Aug 30 22:21:07 volumio go-librespot[24180]: time="2024-08-30T22:21:07+07:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]"
Aug 30 22:21:08 volumio go-librespot[24180]: time="2024-08-30T22:21:08+07:00" level=debug msg="dealer connection opened"
Aug 30 22:21:08 volumio go-librespot[24180]: time="2024-08-30T22:21:08+07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336"
Aug 30 22:21:08 volumio go-librespot[24180]: time="2024-08-30T22:21:08+07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2"
Aug 30 22:21:08 volumio go-librespot[24180]: time="2024-08-30T22:21:08+07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17"
Aug 30 22:21:08 volumio go-librespot[24180]: time="2024-08-30T22:21:08+07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0"
Aug 30 22:21:08 volumio go-librespot[24180]: time="2024-08-30T22:21:08+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513"
Aug 30 22:21:08 volumio go-librespot[24180]: time="2024-08-30T22:21:08+07:00" level=debug msg="received connection id: OTRlODdiMGYtODVlNy00ZWUzLWJjYWUtNTFiYWViYzFhYzI3K2RlYWxlcit0Y3A6Ly8wYWNhNDAxNi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArN0Q0REMwQkNEQjZFOUU0MzRGQjBDQzY3NDIxQjg5RjA3RTQwMzYwRUQ3N0Y3OTc1QUQ3Q0IxNzI4N0RENUVCOQ=="
Aug 30 22:21:08 volumio go-librespot[24180]: time="2024-08-30T22:21:08+07:00" level=debug msg="put connect state because NEW_DEVICE"
Aug 30 22:21:08 volumio volumio[23969]: info: go-librespot daemon successfully initialized
Aug 30 22:21:11 volumio volumio[23969]: info: Initializing connection to go-librespot Websocket
Aug 30 22:21:11 volumio go-librespot[24180]: time="2024-08-30T22:21:11+07:00" level=debug msg="new websocket client"
Aug 30 22:21:11 volumio volumio[23969]: info: Connection to go-librespot Websocket established
Aug 30 22:21:13 volumio volumio[23969]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory
Aug 30 22:21:14 volumio volumio[23969]: info: Getting Spotify volume
Aug 30 22:21:15 volumio volumio[23969]: info: Spotify volume: 100
Aug 30 22:21:15 volumio volumio[23969]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 14
Aug 30 22:21:17 volumio volumio[23969]: info: CoreCommandRouter::volumioGetState
Aug 30 22:21:17 volumio volumio[23969]: info: CorePlayQueue::getTrack 0
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Aug 30 22:21:25 volumio volumio[23969]: info: Adding plugin bluetooth to MyMusic Plugins
Aug 30 22:21:25 volumio volumio[23969]: info: Adding plugin multiroom to MyMusic Plugins
Aug 30 22:21:25 volumio volumio[23969]: info: Adding plugin metavolumio to MyMusic Plugins
Aug 30 22:21:25 volumio volumio[23969]: info: Adding plugin cd_controller to MyMusic Plugins
Aug 30 22:21:25 volumio volumio[23969]: info: Adding plugin smart_inputs to MyMusic Plugins
Aug 30 22:21:25 volumio volumio[23969]: info: Adding plugin tidalconnect to MyMusic Plugins
Aug 30 22:21:25 volumio volumio[23969]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Aug 30 22:21:27 volumio volumio[23969]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Aug 30 22:21:27 volumio volumio[23969]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Aug 30 22:21:27 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:27 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:27 volumio volumio[23969]: info: Starting MyVolumio Remote Streaming Endpoints
Aug 30 22:21:27 volumio volumio[23969]: info: MyVolumio login type: Token
Aug 30 22:21:27 volumio volumio[23969]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Aug 30 22:21:27 volumio volumio[23969]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Aug 30 22:21:29 volumio volumio[23969]: info: Starting Streaming Service Transparent Proxy
Aug 30 22:21:29 volumio volumio[23969]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Aug 30 22:21:29 volumio volumio[23969]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Aug 30 22:21:29 volumio volumio[23969]: info: Streaming services startup
Aug 30 22:21:29 volumio volumio[23969]: info: Starting Streaming Daemon
Aug 30 22:21:29 volumio sudo[24223]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Aug 30 22:21:29 volumio sudo[24223]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:21:29 volumio sudo[24223]: pam_unix(sudo:session): session closed for user root
Aug 30 22:21:29 volumio volumio[23969]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Aug 30 22:21:29 volumio volumio[23969]: error: Cannot start Volumio Streaming Daemon
Aug 30 22:21:29 volumio volumio[23969]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Aug 30 22:21:29 volumio volumio[23969]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Aug 30 22:21:30 volumio volumio[23969]: error: MyVolumio Custom Token format not valid, refreshing it
Aug 30 22:21:31 volumio volumio[23969]: info: MyVolumio login type: Token
Aug 30 22:21:31 volumio volumio[23969]: STREAMING PROXY: Starting server on port 3245
Aug 30 22:21:31 volumio volumio[23969]: Node JS runtime: 14
Aug 30 22:21:32 volumio volumio[23969]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Aug 30 22:21:33 volumio volumio[23969]: info: MyVolumio token set successfully
Aug 30 22:21:33 volumio volumio[23969]: info: MYVOLUMIO: Adding device
Aug 30 22:21:33 volumio volumio[23969]: info: MYVOLUMIO: Evaluating Server
Aug 30 22:21:34 volumio volumio[23969]: info: MyVolumio status changed
Aug 30 22:21:34 volumio volumio[23969]: info: Streaming services startup
Aug 30 22:21:34 volumio volumio[23969]: info: Starting Streaming Daemon
Aug 30 22:21:34 volumio volumio[23969]: info: Removing browser output: myVolumio user plan is not superstar
Aug 30 22:21:34 volumio volumio[23969]: info: Removing audio output:
Aug 30 22:21:34 volumio volumio[23969]: info: Stoppping Tunnel 1
Aug 30 22:21:34 volumio sudo[24268]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Aug 30 22:21:34 volumio sudo[24268]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:21:34 volumio sudo[24268]: pam_unix(sudo:session): session closed for user root
Aug 30 22:21:34 volumio sudo[24280]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Aug 30 22:21:34 volumio sudo[24280]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:21:34 volumio volumio[23969]: error: Cannot start Volumio Streaming Daemon
Aug 30 22:21:34 volumio volumio[23969]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Aug 30 22:21:34 volumio volumio[23969]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Aug 30 22:21:34 volumio sudo[24280]: pam_unix(sudo:session): session closed for user root
Aug 30 22:21:34 volumio volumio[23969]: info: Remote SSH Stopped
Aug 30 22:21:34 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Aug 30 22:21:34 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:34 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Aug 30 22:21:34 volumio volumio-remote-updater[520]: No test mode
Aug 30 22:21:34 volumio volumio-remote-updater[520]: No alpha test mode
Aug 30 22:21:34 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled
Aug 30 22:21:35 volumio volumio[23969]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"FIXES
- Improved translations
- Fix for controlling Volumio device from another one
- Fix for slow playback on RPi5 with HifiBerry DAC
- Improved speed for default albumart
- Fix for HifiBerry DAC detection
- Fix for Supersearch bar on Iphone
- Fix for Network connection on Wizard
NEW ADDITIONS
- Facility for third party UIs
","title":"Update v3.742","updateavailable":true}
Aug 30 22:21:35 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache
Aug 30 22:21:35 volumio volumio[23969]: info: Setting Geolocation for MyVolumio to eu6
Aug 30 22:21:35 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:35 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:35 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:36 volumio volumio[23969]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Aug 30 22:21:36 volumio volumio[23969]: info: Updating MyVolumio device info
Aug 30 22:21:36 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:36 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:36 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:37 volumio volumio[23969]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Aug 30 22:21:40 volumio volumio[23969]: info: MYVOLUMIO: Adding device
Aug 30 22:21:40 volumio volumio[23969]: info: MYVOLUMIO: Evaluating Server
Aug 30 22:21:41 volumio volumio[23969]: info: Setting Geolocation for MyVolumio to eu7
Aug 30 22:21:41 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:42 volumio volumio[23969]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Aug 30 22:21:42 volumio volumio[23969]: info: Updating MyVolumio device info
Aug 30 22:21:42 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:42 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Aug 30 22:21:42 volumio volumio[23969]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 15
Aug 30 22:21:42 volumio volumio[23969]: info: CoreCommandRouter::volumioGetState
Aug 30 22:21:42 volumio volumio[23969]: info: CorePlayQueue::getTrack 0
Aug 30 22:21:43 volumio volumio[23969]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Aug 30 22:21:47 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:47 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:47 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam
Aug 30 22:21:47 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam
Aug 30 22:21:47 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Aug 30 22:21:47 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject
Aug 30 22:21:47 volumio volumio[23969]: info: CoreCommandRouter::volumioGetBrowseSources
Aug 30 22:21:47 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Aug 30 22:21:49 volumio volumio[23969]: error: MyVolumio Plugin failed to authenticate in a timely fashion
Aug 30 22:21:49 volumio volumio[23969]: info: Completed starting MyVolumio Plugin
Aug 30 22:21:49 volumio volumio[23969]: info: BOOT COMPLETED
Aug 30 22:21:49 volumio volumio[23969]: [Metrics] CommandRouter: 84s 359.17ms
Aug 30 22:21:49 volumio volumio[23969]: info: CoreCommandRouter::volumiosetStartupVolume
Aug 30 22:21:49 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:21:49 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:21:49 volumio volumio[23969]: info: CoreCommandRouter::Close All Modals sent
Aug 30 22:21:49 volumio volumio[23969]: info: CoreCommandRouter::Close All Modals sent
Aug 30 22:21:49 volumio kernel: bcm2835-i2s 3f203000.i2s: I2S SYNC error!
Aug 30 22:21:50 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable
Aug 30 22:21:50 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
Aug 30 22:21:50 volumio volumio[23969]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect
Aug 30 22:22:04 volumio volumio[23969]: info: CoreCommandRouter::volumioReplaceandPlayItems
Aug 30 22:22:04 volumio volumio[23969]: info: CoreStateMachine::ClearQueue
Aug 30 22:22:04 volumio volumio[23969]: info: CoreStateMachine::stop
Aug 30 22:22:04 volumio volumio[23969]: info: CoreStateMachine::setConsumeUpdateService undefined
Aug 30 22:22:04 volumio volumio[23969]: info: CorePlayQueue::clearPlayQueue
Aug 30 22:22:04 volumio volumio[23969]: info: CorePlayQueue::saveQueue
Aug 30 22:22:04 volumio volumio[23969]: info: CoreCommandRouter::volumioPushQueue
Aug 30 22:22:04 volumio volumio[23969]: info: CoreStateMachine::addQueueItems
Aug 30 22:22:04 volumio volumio[23969]: info: CorePlayQueue::addQueueItems
Aug 30 22:22:04 volumio volumio[23969]: info: Preload queue cleared
Aug 30 22:22:04 volumio volumio[23969]: info: Adding Item to queue: music-library/NAS/Новый_том/Eddie Higgins Quintet - A Handful Of Stars - 2009
Aug 30 22:22:04 volumio volumio[23969]: info: Exploding uri music-library/NAS/Новый_том/Eddie Higgins Quintet - A Handful Of Stars - 2009 in service mpd
Aug 30 22:22:04 volumio volumio[23969]: info: ALBUMART /albumart?cacheid=59&web=/A%20Handful%20of%20Stars/extralarge&path=%2Fmnt%2FNAS%2F%D0%9D%D0%BE%D0%B2%D1%8B%D0%B9_%D1%82%D0%BE%D0%BC%2FEddie%20Higgins%20Quintet%20-%20A%20Handful%20Of%20Stars%20-%202009%2FA%20Handful%20of%20Stars.cue&metadata=false
Aug 30 22:22:04 volumio volumio[23969]: info: URI /mnt/NAS/Новый_том/Eddie Higgins Quintet - A Handful Of Stars - 2009/A Handful of Stars.cue
Aug 30 22:22:04 volumio volumio[23969]: info: ALBUMART /albumart?cacheid=59&web=/A%20Handful%20of%20Stars/extralarge&path=%2Fmnt%2FNAS%2F%D0%9D%D0%BE%D0%B2%D1%8B%D0%B9_%D1%82%D0%BE%D0%BC%2FEddie%20Higgins%20Quintet%20-%20A%20Handful%20Of%20Stars%20-%202009%2FA%20Handful%20of%20Stars.cue&metadata=false
Aug 30 22:22:04 volumio volumio[23969]: info: URI /mnt/NAS/Новый_том/Eddie Higgins Quintet - A Handful Of Stars - 2009/A Handful of Stars.cue
Aug 30 22:22:04 volumio volumio[23969]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Aug 30 22:22:04 volumio volumio[23969]: Error: Unable to resolve or reject the same promise twice
Aug 30 22:22:04 volumio volumio[23969]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43)
Aug 30 22:22:04 volumio volumio[23969]: at /volumio/app/plugins/music_service/mpd/index.js:2568:21
Aug 30 22:22:04 volumio volumio[23969]: at MpdClient.handleMessage (/volumio/app/plugins/music_service/mpd/lib/mpd.js:77:3)
Aug 30 22:22:04 volumio volumio[23969]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:68:12)
Aug 30 22:22:04 volumio volumio[23969]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:12)
Aug 30 22:22:04 volumio volumio[23969]: at Socket.emit (events.js:315:20)
Aug 30 22:22:04 volumio volumio[23969]: at addChunk (internal/streams/readable.js:309:12)
Aug 30 22:22:04 volumio volumio[23969]: at readableAddChunk (internal/streams/readable.js:280:11)
Aug 30 22:22:04 volumio volumio[23969]: at Socket.Readable.push (internal/streams/readable.js:223:10)
Aug 30 22:22:04 volumio volumio[23969]: at Pipe.onStreamRead (internal/stream_base_commons.js:188:23)
Aug 30 22:22:04 volumio volumio[23969]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Aug 30 22:22:05 volumio sudo[24322]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-30 22:21
Aug 30 22:22:05 volumio sudo[24322]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:05 volumio sudo[24322]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:05 volumio go-librespot[24180]: time="2024-08-30T22:22:05+07:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF"
Aug 30 22:22:05 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE
Aug 30 22:22:05 volumio volumio-remote-updater[520]: [2024-08-30 22:22:05] [error] handle_read_frame error: websocketpp.transport:7 (End of File)
Aug 30 22:22:05 volumio volumio-remote-updater[520]: [2024-08-30 22:22:05] [disconnect] Disconnect close local:[1006,End of File] remote:[1006]
Aug 30 22:22:05 volumio systemd[1]: volumio.service: Failed with result 'exit-code'.
Aug 30 22:22:05 volumio systemd[1]: Started dynamicswap service.
Aug 30 22:22:05 volumio systemd[1]: dynamicswap.service: Succeeded.
Aug 30 22:22:05 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart.
Aug 30 22:22:05 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 18.
Aug 30 22:22:05 volumio systemd[1]: Started dynamicswap service.
Aug 30 22:22:05 volumio systemd[1]: Stopped Volumio Backend Module.
Aug 30 22:22:05 volumio systemd[1]: Started Volumio Backend Module.
Aug 30 22:22:05 volumio systemd[1]: dynamicswap.service: Succeeded.
Aug 30 22:22:09 volumio volumio[24333]: info: -------------------------------------------
Aug 30 22:22:09 volumio volumio[24333]: info: ----- Volumio3 ----
Aug 30 22:22:09 volumio volumio[24333]: info: -------------------------------------------
Aug 30 22:22:09 volumio volumio[24333]: info: ----- System startup ----
Aug 30 22:22:09 volumio volumio[24333]: info: -------------------------------------------
Aug 30 22:22:10 volumio volumio[24333]: info: MYVOLUMIO Environment detected
Aug 30 22:22:10 volumio volumio-remote-updater[520]: [2024-08-30 22:22:10] [connect] Successful connection
Aug 30 22:22:10 volumio volumio[24333]: info: Plugin folders cleanup
Aug 30 22:22:10 volumio volumio[24333]: info: Scanning into folder /volumio/app/plugins/
Aug 30 22:22:10 volumio volumio[24333]: info: Scanning category audio_interface
Aug 30 22:22:10 volumio volumio[24333]: info: Scanning category miscellanea
Aug 30 22:22:10 volumio volumio[24333]: info: Scanning category music_service
Aug 30 22:22:10 volumio volumio[24333]: info: Scanning category plugins.json
Aug 30 22:22:10 volumio volumio[24333]: info: Scanning category system_controller
Aug 30 22:22:10 volumio volumio[24333]: info: Scanning category user_interface
Aug 30 22:22:10 volumio volumio[24333]: info: Scanning into folder /data/plugins/
Aug 30 22:22:10 volumio volumio[24333]: info: Scanning category music_service
Aug 30 22:22:10 volumio volumio[24333]: info: Plugin folders cleanup completed
Aug 30 22:22:10 volumio volumio[24333]: info: -------------------------------------------
Aug 30 22:22:10 volumio volumio[24333]: info: ----- Core plugins startup ----
Aug 30 22:22:10 volumio volumio[24333]: info: -------------------------------------------
Aug 30 22:22:10 volumio volumio[24333]: info: Loading plugins from folder /volumio/app/plugins/
Aug 30 22:22:10 volumio volumio[24333]: info: Adding plugin upnp to MyMusic Plugins
Aug 30 22:22:10 volumio volumio[24333]: info: Adding plugin airplay_emulation to MyMusic Plugins
Aug 30 22:22:10 volumio volumio[24333]: info: Adding plugin upnp_browser to MyMusic Plugins
Aug 30 22:22:10 volumio volumio[24333]: info: Loading plugins from folder /data/plugins/
Aug 30 22:22:10 volumio volumio[24333]: info: Loading plugin "system"...
Aug 30 22:22:10 volumio volumio[24333]: info: Loading plugin "appearance"...
Aug 30 22:22:12 volumio volumio[24333]: info: Loading plugin "network"...
Aug 30 22:22:12 volumio volumio[24333]: info: Refreshing Cached IP Addresses
Aug 30 22:22:12 volumio sudo[24359]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Aug 30 22:22:12 volumio sudo[24359]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:12 volumio volumio[24333]: info: Loading plugin "services"...
Aug 30 22:22:12 volumio sudo[24361]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Aug 30 22:22:12 volumio sudo[24361]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:12 volumio sudo[24359]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:12 volumio volumio[24333]: info: Loading plugin "alsa_controller"...
Aug 30 22:22:12 volumio sudo[24361]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:12 volumio sudo[24364]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
Aug 30 22:22:12 volumio sudo[24364]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:12 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Aug 30 22:22:12 volumio volumio[24333]: info: Loading plugin "wizard"...
Aug 30 22:22:12 volumio volumio[24333]: info: Loading plugin "networkfs"...
Aug 30 22:22:12 volumio volumio[24333]: info: Cannot mount NAS ADATA_HC500 at system boot, trial number 1 ,retrying in 5 seconds
Aug 30 22:22:12 volumio volumio[24333]: info: Starting Udev Watcher for removable devices
Aug 30 22:22:12 volumio sudo[24370]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=WORKGROUP,password=WORKGROUP,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.1/Новый том /mnt/NAS/Новый_том
Aug 30 22:22:12 volumio sudo[24370]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:12 volumio volumio[24333]: info: Ignoring mount for partition: boot
Aug 30 22:22:12 volumio volumio[24333]: info: Ignoring mount for partition: volumio
Aug 30 22:22:12 volumio volumio[24333]: info: Ignoring mount for partition: volumio_data
Aug 30 22:22:12 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Aug 30 22:22:12 volumio volumio[24333]: info: Loading plugin "volumio_command_line_client"...
Aug 30 22:22:12 volumio kernel: CIFS: Attempting to mount \\192.168.1.1\Новый том
Aug 30 22:22:12 volumio sudo[24370]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:13 volumio volumio[24333]: info: Loading plugin "upnp"...
Aug 30 22:22:13 volumio volumio[24333]: info: [1725031333009] Starting Upmpd Daemon
Aug 30 22:22:13 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Aug 30 22:22:13 volumio volumio[24333]: info: Loading plugin "my_music"...
Aug 30 22:22:13 volumio volumio[24333]: info: Loading plugin "mpd"...
Aug 30 22:22:13 volumio sudo[24364]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:13 volumio volumio[24333]: info: Loading plugin "upnp_browser"...
Aug 30 22:22:14 volumio volumio[24333]: info: Loading plugin "alarm-clock"...
Aug 30 22:22:14 volumio volumio[24333]: info: Loading plugin "airplay_emulation"...
Aug 30 22:22:14 volumio volumio[24333]: info: Starting Shairport Sync
Aug 30 22:22:14 volumio volumio[24333]: info: Loading plugin "last_100"...
Aug 30 22:22:14 volumio volumio[24333]: info: Loading plugin "webradio"...
Aug 30 22:22:14 volumio volumio[24333]: info: Loading plugin "i2s_dacs"...
Aug 30 22:22:14 volumio volumio[24333]: info: Loading plugin "volumiodiscovery"...
Aug 30 22:22:14 volumio volumio[24333]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Aug 30 22:22:14 volumio volumio[24333]: *** WARNING *** Please fix your application to use the native API of Avahi!
Aug 30 22:22:14 volumio volumio[24333]: *** WARNING *** For more information see
Aug 30 22:22:14 volumio node[24333]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Aug 30 22:22:14 volumio volumio[24333]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Aug 30 22:22:14 volumio volumio[24333]: *** WARNING *** Please fix your application to use the native API of Avahi!
Aug 30 22:22:14 volumio volumio[24333]: *** WARNING *** For more information see
Aug 30 22:22:14 volumio node[24333]: *** WARNING *** Please fix your application to use the native API of Avahi!
Aug 30 22:22:14 volumio node[24333]: *** WARNING *** For more information see
Aug 30 22:22:14 volumio node[24333]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Aug 30 22:22:14 volumio node[24333]: *** WARNING *** Please fix your application to use the native API of Avahi!
Aug 30 22:22:14 volumio node[24333]: *** WARNING *** For more information see
Aug 30 22:22:14 volumio volumio[24333]: info: Applying required configuration parameters for plugin volumiodiscovery
Aug 30 22:22:14 volumio volumio[24333]: info: Discovery: Started advertising with name: Volumio
Aug 30 22:22:14 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Aug 30 22:22:14 volumio volumio[24333]: info: Loading plugin "spop"...
Aug 30 22:22:16 volumio volumio[24333]: info: Loading plugin "outputs"...
Aug 30 22:22:16 volumio volumio[24333]: info: Loading plugin "albumart"...
Aug 30 22:22:16 volumio volumio[24333]: info: Plugin example_plugin is not enabled
Aug 30 22:22:16 volumio volumio[24333]: info: Loading plugin "inputs"...
Aug 30 22:22:16 volumio volumio[24333]: info: Loading plugin "updater_comm"...
Aug 30 22:22:17 volumio volumio[24333]: info: Plugin mpdemulation is not enabled
Aug 30 22:22:17 volumio volumio[24333]: info: Loading plugin "rest_api"...
Aug 30 22:22:17 volumio volumio[24333]: info: Loading plugin "websocket"...
Aug 30 22:22:17 volumio volumio[24333]: info: Loading i18n strings for locale en
Aug 30 22:22:17 volumio volumio[24333]: Updating browse sources language
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::initPlayerControls
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Aug 30 22:22:17 volumio volumio[24333]: Express server listening on port 3000
Aug 30 22:22:17 volumio volumio[24333]: [Metrics] WebUI: 9s 450.40ms
Aug 30 22:22:17 volumio volumio[24333]: info: CoreStateMachine::resetVolumioState
Aug 30 22:22:17 volumio volumio[24333]: info: CoreStateMachine::getcurrentVolume
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::volumioRetrievevolume
Aug 30 22:22:17 volumio volumio[24333]: info: CoreStateMachine::pushState
Aug 30 22:22:17 volumio volumio[24333]: info: CorePlayQueue::getTrack 0
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Aug 30 22:22:17 volumio volumio[24333]: Forking 3 albumart workers
Aug 30 22:22:17 volumio volumio[24333]: info: CoreCommandRouter::volumioPushState
Aug 30 22:22:17 volumio volumio[24333]: info: Cannot mount NAS Новый_том at system boot, trial number 1 ,retrying in 5 seconds
Aug 30 22:22:17 volumio volumio[24333]: verbose: New Socket.io Connection to 192.168.1.99 from 192.168.1.34 UA: Mozilla/5.0 (Linux; Android 8.1.0; 16 Build/OPM1.171019.026; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/128.0.6613.99 Mobile Safari/537.36 Total Clients: 1
Aug 30 22:22:18 volumio volumio[24333]: verbose: New Socket.io Connection to 192.168.1.99 from 192.168.1.34 UA: Mozilla/5.0 (Linux; Android 8.1.0; 16 Build/OPM1.171019.026; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/128.0.6613.99 Mobile Safari/537.36 Total Clients: 2
Aug 30 22:22:18 volumio volumio[24333]: verbose: New Socket.io Connection to 192.168.1.99 from 192.168.1.34 UA: Mozilla/5.0 (Linux; Android 8.1.0; 16 Build/OPM1.171019.026; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/128.0.6613.99 Mobile Safari/537.36 Total Clients: 3
Aug 30 22:22:18 volumio volumio[24333]: verbose: New Socket.io Connection to 192.168.1.99 from 192.168.1.34 UA: Mozilla/5.0 (Linux; Android 8.1.0; 16 Build/OPM1.171019.026; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/128.0.6613.99 Mobile Safari/537.36 Total Clients: 4
Aug 30 22:22:18 volumio volumio[24333]: verbose: New Socket.io Connection to 192.168.1.99 from 192.168.1.34 UA: Mozilla/5.0 (Linux; Android 8.1.0; 16 Build/OPM1.171019.026; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/128.0.6613.99 Mobile Safari/537.36 Total Clients: 5
Aug 30 22:22:18 volumio volumio[24333]: verbose: New Socket.io Connection to 192.168.1.99 from 192.168.1.34 UA: Mozilla/5.0 (Linux; Android 8.1.0; 16 Build/OPM1.171019.026; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/128.0.6613.99 Mobile Safari/537.36 Total Clients: 6
Aug 30 22:22:18 volumio volumio[24333]: info: Cannot mount NAS ADATA_HC500 at system boot, trial number 2 ,retrying in 5 seconds
Aug 30 22:22:18 volumio volumio[24333]: verbose: New Socket.io Connection to 192.168.1.99 from 192.168.1.34 UA: Mozilla/5.0 (Linux; Android 8.1.0; 16 Build/OPM1.171019.026; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/128.0.6613.99 Mobile Safari/537.36 Total Clients: 7
Aug 30 22:22:18 volumio volumio[24333]: verbose: New Socket.io Connection to 192.168.1.99 from 192.168.1.34 UA: Mozilla/5.0 (Linux; Android 8.1.0; 16 Build/OPM1.171019.026; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/128.0.6613.99 Mobile Safari/537.36 Total Clients: 8
Aug 30 22:22:18 volumio volumio[24333]: verbose: New Socket.io Connection to 192.168.1.99 from 192.168.1.34 UA: Mozilla/5.0 (Linux; Android 8.1.0; 16 Build/OPM1.171019.026; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/128.0.6613.99 Mobile Safari/537.36 Total Clients: 9
Aug 30 22:22:18 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:22:18 volumio volumio[24333]: info: Cannot read play queue from file
Aug 30 22:22:18 volumio volumio[24333]: verbose: New Socket.io Connection to 192.168.1.99 from 192.168.1.34 UA: Mozilla/5.0 (Linux; Android 8.1.0; 16 Build/OPM1.171019.026; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/128.0.6613.99 Mobile Safari/537.36 Total Clients: 10
Aug 30 22:22:18 volumio volumio[24333]: info: CoreStateMachine::setRepeat null single undefined
Aug 30 22:22:18 volumio volumio[24333]: info: CoreStateMachine::pushState
Aug 30 22:22:18 volumio volumio[24333]: info: CorePlayQueue::getTrack 0
Aug 30 22:22:18 volumio volumio[24333]: info: CoreCommandRouter::volumioPushState
Aug 30 22:22:18 volumio volumio[24333]: info: CoreStateMachine::setRandom null
Aug 30 22:22:18 volumio volumio[24333]: info: CoreStateMachine::pushState
Aug 30 22:22:18 volumio volumio[24333]: info: CorePlayQueue::getTrack 0
Aug 30 22:22:18 volumio volumio[24333]: info: CoreCommandRouter::volumioPushState
Aug 30 22:22:18 volumio volumio[24333]: info: Setting Device type: Raspberry PI
Aug 30 22:22:18 volumio volumio[24333]: info: Discovery: adding af59d152-9ef7-4394-a4cc-ca7d22370147
Aug 30 22:22:18 volumio volumio[24333]: info: Discovery: Found device Volumio
Aug 30 22:22:18 volumio volumio[24333]: info: CoreCommandRouter::volumioGetState
Aug 30 22:22:18 volumio volumio[24333]: info: CorePlayQueue::getTrack 0
Aug 30 22:22:18 volumio volumio[24333]: info: Discovery: this is already registered, af59d152-9ef7-4394-a4cc-ca7d22370147
Aug 30 22:22:18 volumio volumio[24333]: info: Discovery: Found device Volumio
Aug 30 22:22:18 volumio volumio[24333]: info: CoreCommandRouter::volumioGetState
Aug 30 22:22:18 volumio volumio[24333]: info: CorePlayQueue::getTrack 0
Aug 30 22:22:18 volumio volumio[24333]: verbose: New Socket.io Connection to 192.168.1.99 from 192.168.1.34 UA: Mozilla/5.0 (Linux; Android 8.1.0; 16 Build/OPM1.171019.026; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/128.0.6613.99 Mobile Safari/537.36 Total Clients: 11
Aug 30 22:22:18 volumio volumio[24333]: info: CoreCommandRouter::volumioGetState
Aug 30 22:22:18 volumio volumio[24333]: info: CorePlayQueue::getTrack 0
Aug 30 22:22:19 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Aug 30 22:22:19 volumio volumio[24333]: info: Listing playlists
Aug 30 22:22:19 volumio volumio[24333]: info: CoreCommandRouter::volumioGetVisibleSources
Aug 30 22:22:19 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Aug 30 22:22:19 volumio volumio[24333]: info: CoreCommandRouter::volumioGetQueue
Aug 30 22:22:19 volumio volumio[24333]: info: CoreStateMachine::getQueue
Aug 30 22:22:19 volumio volumio[24333]: info: CorePlayQueue::getQueue
Aug 30 22:22:19 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Aug 30 22:22:19 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Aug 30 22:22:19 volumio volumio[24333]: info: Discovery: Getting this device information
Aug 30 22:22:19 volumio volumio[24333]: info: CoreCommandRouter::volumioGetState
Aug 30 22:22:19 volumio volumio[24333]: info: CorePlayQueue::getTrack 0
Aug 30 22:22:19 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Aug 30 22:22:19 volumio volumio[24333]: verbose: New Socket.io Connection to 192.168.1.99:3000 from 192.168.1.34 UA: Dart/3.4 (dart:io) Total Clients: 12
Aug 30 22:22:19 volumio volumio[24333]: info: CoreCommandRouter::volumioGetState
Aug 30 22:22:19 volumio volumio[24333]: info: CorePlayQueue::getTrack 0
Aug 30 22:22:19 volumio volumio[24333]: Starting albumart workers
Aug 30 22:22:19 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard
Aug 30 22:22:19 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
Aug 30 22:22:19 volumio volumio[24333]: Starting albumart workers
Aug 30 22:22:19 volumio volumio[24333]: Starting albumart workers
Aug 30 22:22:22 volumio sudo[24438]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=WORKGROUP,password=WORKGROUP,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.1/Новый том /mnt/NAS/Новый_том
Aug 30 22:22:22 volumio sudo[24438]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:22 volumio kernel: CIFS: Attempting to mount \\192.168.1.1\Новый том
Aug 30 22:22:22 volumio sudo[24438]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:22 volumio volumio[24333]: info: Cannot mount NAS Новый_том at system boot, trial number 2 ,retrying in 5 seconds
Aug 30 22:22:23 volumio sudo[24443]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Aug 30 22:22:23 volumio sudo[24443]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:23 volumio sudo[24443]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:23 volumio sudo[24445]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Aug 30 22:22:23 volumio sudo[24445]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:23 volumio sudo[24445]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:23 volumio volumio-remote-updater[520]: [2024-08-30 22:22:23] [connect] Successful connection
Aug 30 22:22:23 volumio volumio-remote-updater[520]: [2024-08-30 22:22:23] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1725031343 101
Aug 30 22:22:23 volumio sudo[24449]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Aug 30 22:22:23 volumio sudo[24449]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:23 volumio volumio[24333]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 13
Aug 30 22:22:23 volumio volumio[24333]: info: Cannot mount NAS ADATA_HC500 at system boot, trial number 3 ,retrying in 5 seconds
Aug 30 22:22:23 volumio sudo[24449]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:23 volumio volumio[24333]: info: Upmpdcli Daemon Started
Aug 30 22:22:23 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Aug 30 22:22:23 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Aug 30 22:22:23 volumio volumio[24333]: info: Discovery: Getting this device information
Aug 30 22:22:23 volumio volumio[24333]: info: CoreCommandRouter::volumioGetState
Aug 30 22:22:23 volumio volumio[24333]: info: CorePlayQueue::getTrack 0
Aug 30 22:22:23 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Aug 30 22:22:28 volumio sudo[24453]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=WORKGROUP,password=WORKGROUP,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.1/Новый том /mnt/NAS/Новый_том
Aug 30 22:22:28 volumio sudo[24453]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:28 volumio kernel: CIFS: Attempting to mount \\192.168.1.1\Новый том
Aug 30 22:22:28 volumio sudo[24453]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:28 volumio volumio[24333]: info: Cannot mount NAS Новый_том at system boot, trial number 3 ,retrying in 5 seconds
Aug 30 22:22:28 volumio volumio[24333]: info: Cannot mount NAS ADATA_HC500 at system boot, trial number 4 ,retrying in 5 seconds
Aug 30 22:22:31 volumio volumio[24333]: info: Preload queue cleared
Aug 30 22:22:31 volumio volumio[24333]: info: CoreCommandRouter::volumioReplaceandPlayItems
Aug 30 22:22:31 volumio volumio[24333]: info: CoreStateMachine::ClearQueue
Aug 30 22:22:31 volumio volumio[24333]: info: CoreStateMachine::stop
Aug 30 22:22:31 volumio volumio[24333]: info: CoreStateMachine::setConsumeUpdateService undefined
Aug 30 22:22:31 volumio volumio[24333]: info: CorePlayQueue::clearPlayQueue
Aug 30 22:22:31 volumio volumio[24333]: info: CorePlayQueue::saveQueue
Aug 30 22:22:31 volumio volumio[24333]: info: CoreCommandRouter::volumioPushQueue
Aug 30 22:22:31 volumio volumio[24333]: info: CoreStateMachine::addQueueItems
Aug 30 22:22:31 volumio volumio[24333]: info: CorePlayQueue::addQueueItems
Aug 30 22:22:31 volumio volumio[24333]: info: Preload queue cleared
Aug 30 22:22:31 volumio volumio[24333]: info: Adding Item to queue: music-library/NAS/Новый_том/Eddie Higgins Quintet - A Handful Of Stars - 2009
Aug 30 22:22:31 volumio volumio[24333]: info: Exploding uri music-library/NAS/Новый_том/Eddie Higgins Quintet - A Handful Of Stars - 2009 in service mpd
Aug 30 22:22:31 volumio volumio[24333]: error: Failed to stat '/mnt/NAS/Новый_том/Eddie Higgins Quintet - A Handful Of Stars - 2009'
Aug 30 22:22:31 volumio volumio[24333]: info: CoreCommandRouter::volumioPushQueue
Aug 30 22:22:31 volumio volumio[24333]: info: CorePlayQueue::saveQueue
Aug 30 22:22:31 volumio volumio[24333]: info: CoreStateMachine::updateTrackBlock
Aug 30 22:22:31 volumio volumio[24333]: info: CorePlayQueue::getTrackBlock
Aug 30 22:22:31 volumio volumio[24333]: info: CoreCommandRouter::volumioPlay
Aug 30 22:22:31 volumio volumio[24333]: info: CoreStateMachine::play index 0
Aug 30 22:22:31 volumio volumio[24333]: info: CoreStateMachine::setConsumeUpdateService undefined
Aug 30 22:22:31 volumio volumio[24333]: info: CoreStateMachine::stop
Aug 30 22:22:31 volumio volumio[24333]: info: CoreStateMachine::setConsumeUpdateService undefined
Aug 30 22:22:31 volumio volumio[24333]: info: CoreStateMachine::play index undefined
Aug 30 22:22:31 volumio volumio[24333]: info: CoreStateMachine::setConsumeUpdateService undefined
Aug 30 22:22:31 volumio volumio[24333]: info: CorePlayQueue::getTrack 0
Aug 30 22:22:33 volumio sudo[24458]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=WORKGROUP,password=WORKGROUP,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.1/Новый том /mnt/NAS/Новый_том
Aug 30 22:22:33 volumio sudo[24458]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:33 volumio volumio[24333]: info: Cannot mount NAS at system boot, trial number 4 ,stopping
Aug 30 22:22:33 volumio kernel: CIFS: Attempting to mount \\192.168.1.1\Новый том
Aug 30 22:22:33 volumio sudo[24458]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:33 volumio volumio[24333]: info: Cannot mount NAS Новый_том at system boot, trial number 4 ,retrying in 5 seconds
Aug 30 22:22:38 volumio sudo[24501]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=WORKGROUP,password=WORKGROUP,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.1/Новый том /mnt/NAS/Новый_том
Aug 30 22:22:38 volumio sudo[24501]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:38 volumio kernel: CIFS: Attempting to mount \\192.168.1.1\Новый том
Aug 30 22:22:38 volumio sudo[24501]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:38 volumio volumio[24333]: info: Cannot mount NAS at system boot, trial number 4 ,stopping
Aug 30 22:22:42 volumio go-librespot[24180]: time="2024-08-30T22:22:42+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 250"
Aug 30 22:22:42 volumio go-librespot[24180]: time="2024-08-30T22:22:42+07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update
Aug 30 22:22:45 volumio go-librespot[24180]: time="2024-08-30T22:22:45+07:00" level=debug msg="handling transfer player command from 014aaf798abec099cb36bca77a9d11fe407d076c"
Aug 30 22:22:46 volumio go-librespot[24180]: time="2024-08-30T22:22:46+07:00" level=debug msg="loading track spotify:track:6bjpmghStgfcmTsqsG6Yb6 (paused: false, position: 13519ms)"
Aug 30 22:22:46 volumio go-librespot[24180]: time="2024-08-30T22:22:46+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Aug 30 22:22:46 volumio go-librespot[24180]: time="2024-08-30T22:22:46+07:00" level=trace msg="emitting websocket event: will_play"
Aug 30 22:22:46 volumio go-librespot[24180]: time="2024-08-30T22:22:46+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241"
Aug 30 22:22:46 volumio go-librespot[24180]: time="2024-08-30T22:22:46+07:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:6bjpmghStgfcmTsqsG6Yb6"
Aug 30 22:22:46 volumio go-librespot[24180]: time="2024-08-30T22:22:46+07:00" level=debug msg="requested aes key for file 7b6a4a8f9e1c93d22d572e6fe40f7aac6bd1d7ae, gid: 6bjpmghStgfcmTsqsG6Yb6"
Aug 30 22:22:46 volumio go-librespot[24180]: time="2024-08-30T22:22:46+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1380"
Aug 30 22:22:46 volumio go-librespot[24180]: time="2024-08-30T22:22:46+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1144"
Aug 30 22:22:46 volumio go-librespot[24180]: time="2024-08-30T22:22:46+07:00" level=debug msg="fetched first chunk of 13, total size is 6457682 bytes"
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=debug msg="fetched chunk 1/12, size: 524288"
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=trace msg="seek to 13519ms (diff: 97ms, samples: 596187, bytes: 541459)"
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=info msg="loaded track \"Zero Sum\" (uri: spotify:track:6bjpmghStgfcmTsqsG6Yb6, paused: false, position: 13519ms, duration: 167733ms)"
Aug 30 22:22:47 volumio kernel: bcm2835-i2s 3f203000.i2s: I2S SYNC error!
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=debug msg="fetched chunk 3/12, size: 524288"
Aug 30 22:22:47 volumio volumio[24333]: error: Plugin system_controller system failed to complete 'onVolumioStart' in a timely fashion
Aug 30 22:22:47 volumio volumio[24333]: info: Preparing to generate the ALSA configuration file
Aug 30 22:22:47 volumio volumio[24333]: info: Asound.conf file unchanged, so no further update is needed
Aug 30 22:22:47 volumio volumio[24333]: info: Output device has changed, restarting MPD
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=debug msg="fetched chunk 2/12, size: 524288"
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=trace msg="emitting websocket event: metadata"
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=trace msg="emitting websocket event: active"
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=debug msg="sending successful reply for delaer request"
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=debug msg="fetched chunk 4/12, size: 524288"
Aug 30 22:22:47 volumio sudo[24508]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Aug 30 22:22:47 volumio sudo[24508]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:47 volumio volumio[24333]: info: Output device has changed, restarting Shairport Sync
Aug 30 22:22:47 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:47 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:22:47 volumio sudo[24508]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:47 volumio sudo[24511]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Aug 30 22:22:47 volumio sudo[24511]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:47 volumio systemd[1]: Stopping Music Player Daemon...
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=trace msg="emitting websocket event: playing"
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Aug 30 22:22:47 volumio volumio[24333]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Aug 30 22:22:47 volumio volumio[24333]: info: ___________ START PLUGINS ___________
Aug 30 22:22:47 volumio volumio[24333]: info: ControllerMpd::onStart: Initializing MPD
Aug 30 22:22:47 volumio volumio[24333]: info: Creating MPD Configuration file
Aug 30 22:22:47 volumio systemd[1]: mpd.service: Succeeded.
Aug 30 22:22:47 volumio systemd[1]: Stopped Music Player Daemon.
Aug 30 22:22:47 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Aug 30 22:22:47 volumio volumio[24333]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Aug 30 22:22:47 volumio volumio[24333]: info: [1725031367682] CoreMusicLibrary::Adding element Media Servers
Aug 30 22:22:47 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Aug 30 22:22:47 volumio sudo[24517]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Aug 30 22:22:47 volumio sudo[24517]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:47 volumio systemd[1]: Starting Music Player Daemon...
Aug 30 22:22:47 volumio sudo[24519]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Aug 30 22:22:47 volumio sudo[24519]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:47 volumio sudo[24517]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:47 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:47 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=debug msg="put connect state inactive"
Aug 30 22:22:47 volumio go-librespot[24180]: time="2024-08-30T22:22:47+07:00" level=trace msg="emitting websocket event: inactive"
Aug 30 22:22:47 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM
Aug 30 22:22:47 volumio systemd[1]: mpd.service: Succeeded.
Aug 30 22:22:47 volumio systemd[1]: Stopped Music Player Daemon.
Aug 30 22:22:47 volumio systemd[1]: Starting Music Player Daemon...
Aug 30 22:22:47 volumio volumio[24333]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Aug 30 22:22:47 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:47 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:22:47 volumio volumio[24333]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Aug 30 22:22:47 volumio volumio[24333]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Aug 30 22:22:47 volumio volumio[24333]: info: [1725031367988] CoreMusicLibrary::Adding element Last_100
Aug 30 22:22:47 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Aug 30 22:22:47 volumio volumio[24333]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Aug 30 22:22:47 volumio volumio[24333]: info: [1725031367996] CoreMusicLibrary::Adding element Webradio
Aug 30 22:22:47 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Aug 30 22:22:48 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Aug 30 22:22:48 volumio volumio[24333]: info: Creating Spotify config file
Aug 30 22:22:48 volumio volumio[24333]: info: Volumio Calling Home
Aug 30 22:22:48 volumio volumio[24333]: info: MPD Permissions set
Aug 30 22:22:48 volumio volumio[24333]: info: MPD Permissions set
Aug 30 22:22:48 volumio volumio[24333]: info: Spotify config file written
Aug 30 22:22:48 volumio sudo[24534]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Aug 30 22:22:48 volumio sudo[24534]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:48 volumio systemd[1]: Stopping go-librespot Daemon...
Aug 30 22:22:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM
Aug 30 22:22:48 volumio systemd[1]: go-librespot-daemon.service: Succeeded.
Aug 30 22:22:48 volumio systemd[1]: Stopped go-librespot Daemon.
Aug 30 22:22:48 volumio systemd[1]: Started go-librespot Daemon.
Aug 30 22:22:48 volumio sudo[24534]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:48 volumio go-librespot[24536]: Librespot-go daemon starting...
Aug 30 22:22:48 volumio go-librespot[24536]: time="2024-08-30T22:22:48+07:00" level=info msg="generated new device id: 933ec3badc980016ad86cd0428d4975b0ba44ac8"
Aug 30 22:22:48 volumio go-librespot[24536]: time="2024-08-30T22:22:48+07:00" level=debug msg="stored credentials found for n2ksou2st5zcra3f47zugosz9"
Aug 30 22:22:48 volumio volumio[24333]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 14
Aug 30 22:22:48 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:48 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:48 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:48 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:48 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:48 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:48 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:48 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:49 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:22:49 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:49 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:49 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:49 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:49 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:49 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:49 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:49 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:49 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:49 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 30 22:22:49 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 30 22:22:49 volumio volumio[24333]: info: Volumio called home
Aug 30 22:22:49 volumio volumio[24333]: info: Starting Shairport Sync
Aug 30 22:22:49 volumio go-librespot[24536]: time="2024-08-30T22:22:49+07:00" level=debug msg="obtained new client token: AAAOHRUDh7FvDx+W/pQnrmAdI+Z7ZNexFS5SQrcVfNQ+msEZJzSjWEJR9Cf3R+3EWrqgiwtiLWuRG8+4sHRs4y+8imJo1ZeBVRy+/mW4JJoiCFJ9J+FT9sv8nFRW7QJRf7MEAWezkykQ87NndfKi+er2zSDIFhdpP0QntY5J/h84aS19y1Z7EiIA/em5ItjixL9i/2OmXjgbfU0PRPKpRjU8weC/JzPgrZ3eixnsI8E0A0xaTNzylO8gKDXfmQ=="
Aug 30 22:22:49 volumio volumio[24333]: info: Starting Shairport Sync
Aug 30 22:22:49 volumio volumio[24333]: info: Starting Shairport Sync
Aug 30 22:22:49 volumio sudo[24554]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Aug 30 22:22:49 volumio sudo[24554]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:49 volumio sudo[24556]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Aug 30 22:22:49 volumio sudo[24556]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:49 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver...
Aug 30 22:22:49 volumio systemd[1]: shairport-sync.service: Succeeded.
Aug 30 22:22:49 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver.
Aug 30 22:22:49 volumio sudo[24559]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Aug 30 22:22:49 volumio sudo[24559]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 30 22:22:49 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
Aug 30 22:22:49 volumio sudo[24554]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:49 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver...
Aug 30 22:22:49 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM
Aug 30 22:22:49 volumio systemd[1]: shairport-sync.service: Succeeded.
Aug 30 22:22:49 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver.
Aug 30 22:22:49 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
Aug 30 22:22:49 volumio sudo[24556]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:49 volumio go-librespot[24536]: time="2024-08-30T22:22:49+07:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]"
Aug 30 22:22:49 volumio sudo[24559]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:50 volumio volumio[24333]: info: Shairport-Sync Started
Aug 30 22:22:50 volumio volumio[24333]: Error adding Membership: Error: addMembership EINVAL
Aug 30 22:22:50 volumio volumio[24333]: info: Shairport-Sync Started
Aug 30 22:22:50 volumio volumio[24333]: info: Shairport-Sync Started
Aug 30 22:22:50 volumio volumio[24333]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Aug 30 22:22:50 volumio volumio[24333]: SPOTIFY: BQDiWeUXpPObtzn91nHuTXvgONEMNxfIzVeR-roE9z_MxfkBUiYl9bE9sJj3r2xyxM02muHNuOcE25fncG5GJLmR6D7bHtYcyZkYpIa29PWurJ2PaB9AwKZCitrab11r5Rm_tkxi4yErmCTVquUc7Mb9Ata6HYa1jLUqMth4IW175EDLLe_aK3g4pKPQ2vcl8nLKEJ06d_aQYUKxDPmqyniUxxDs-OTL_DMZrAKxtCmFEmrO0-J-t6FsufNuqHahP4KvLRjJHv8WDkGgZFUnpRUHpg
Aug 30 22:22:50 volumio volumio[24333]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Aug 30 22:22:50 volumio volumio[24333]: info: New Spotify access token = BQDiWeUXpPObtzn91nHuTXvgONEMNxfIzVeR-roE9z_MxfkBUiYl9bE9sJj3r2xyxM02muHNuOcE25fncG5GJLmR6D7bHtYcyZkYpIa29PWurJ2PaB9AwKZCitrab11r5Rm_tkxi4yErmCTVquUc7Mb9Ata6HYa1jLUqMth4IW175EDLLe_aK3g4pKPQ2vcl8nLKEJ06d_aQYUKxDPmqyniUxxDs-OTL_DMZrAKxtCmFEmrO0-J-t6FsufNuqHahP4KvLRjJHv8WDkGgZFUnpRUHpg
Aug 30 22:22:50 volumio volumio[24333]: info: Spotify credentials grant success - running version from March 24, 2019
Aug 30 22:22:50 volumio go-librespot[24536]: time="2024-08-30T22:22:50+07:00" level=debug msg="completed keyexchange"
Aug 30 22:22:50 volumio mpd[24524]: Aug 30 22:22 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Aug 30 22:22:50 volumio volumio[24333]: info: CoreCommandRouter::volumioGetState
Aug 30 22:22:50 volumio volumio[24333]: info: CorePlayQueue::getTrack 0
Aug 30 22:22:50 volumio volumio[24333]: SPOTIFY: User informations: {"display_name":"anton","external_urls":{"spotify":"https://open.spotify.com/user/n2ksou2st5zcra3f47zugosz9"},"href":"https://api.spotify.com/v1/users/n2ksou2st5zcra3f47zugosz9","id":"n2ksou2st5zcra3f47zugosz9","images":[],"type":"user","uri":"spotify:user:n2ksou2st5zcra3f47zugosz9","followers":{"href":null,"total":0},"country":"TR","product":"premium","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"anton.a.agafonov@gmail.com"}
Aug 30 22:22:50 volumio volumio[24333]: info: Spotify Successfully logged in
Aug 30 22:22:50 volumio volumio[24333]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Aug 30 22:22:50 volumio volumio[24333]: info: [1725031370642] CoreMusicLibrary::Adding element Spotify
Aug 30 22:22:50 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Aug 30 22:22:50 volumio volumio[24333]: Cannot find translation for source Spotify
Aug 30 22:22:50 volumio go-librespot[24536]: time="2024-08-30T22:22:50+07:00" level=debug msg="completed challenge"
Aug 30 22:22:50 volumio go-librespot[24536]: time="2024-08-30T22:22:50+07:00" level=debug msg="authenticated as n2ksou2st5zcra3f47zugosz9"
Aug 30 22:22:50 volumio volumio[24333]: error: An error occurred while listing Spotify new albums WebapiRegularError: An error occurred while communicating with Spotify's Web API.
Aug 30 22:22:50 volumio volumio[24333]: Details: Spotify is unavailable in this country.
Aug 30 22:22:50 volumio volumio[24333]: info: An error occurred while getting Spotify ROOT Discover Folders:
Aug 30 22:22:51 volumio volumio[24333]: error: An error occurred while listing Spotify featured playlists WebapiRegularError: An error occurred while communicating with Spotify's Web API.
Aug 30 22:22:51 volumio volumio[24333]: Details: Spotify is unavailable in this country.
Aug 30 22:22:51 volumio volumio[24333]: error: An error occurred while listing Spotify categories WebapiRegularError: An error occurred while communicating with Spotify's Web API.
Aug 30 22:22:51 volumio volumio[24333]: Details: Spotify is unavailable in this country.
Aug 30 22:22:51 volumio go-librespot[24536]: time="2024-08-30T22:22:51+07:00" level=debug msg="authenticated as n2ksou2st5zcra3f47zugosz9"
Aug 30 22:22:51 volumio go-librespot[24536]: time="2024-08-30T22:22:51+07:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]"
Aug 30 22:22:51 volumio go-librespot[24536]: time="2024-08-30T22:22:51+07:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Aug 30 22:22:51 volumio systemd[1]: Started Music Player Daemon.
Aug 30 22:22:51 volumio sudo[24511]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:51 volumio sudo[24519]: pam_unix(sudo:session): session closed for user root
Aug 30 22:22:51 volumio volumio[24333]: info: Completed starting Core Plugins
Aug 30 22:22:51 volumio volumio[24333]: info: -------------------------------------------
Aug 30 22:22:51 volumio volumio[24333]: info: ----- MyVolumio plugins startup ----
Aug 30 22:22:51 volumio volumio[24333]: info: -------------------------------------------
Aug 30 22:22:51 volumio volumio[24333]: info: [MyVolumio PluginManager] Fetching plans data....
Aug 30 22:22:51 volumio go-librespot[24536]: time="2024-08-30T22:22:51+07:00" level=debug msg="dealer connection opened"
Aug 30 22:22:51 volumio go-librespot[24536]: time="2024-08-30T22:22:51+07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336"
Aug 30 22:22:51 volumio go-librespot[24536]: time="2024-08-30T22:22:51+07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2"
Aug 30 22:22:51 volumio go-librespot[24536]: time="2024-08-30T22:22:51+07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17"
Aug 30 22:22:51 volumio go-librespot[24536]: time="2024-08-30T22:22:51+07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0"
Aug 30 22:22:51 volumio go-librespot[24536]: time="2024-08-30T22:22:51+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513"
Aug 30 22:22:51 volumio go-librespot[24536]: time="2024-08-30T22:22:51+07:00" level=debug msg="received connection id: ZGVjZDhkNjctNmNiNS00ODNlLWI5MjEtZDc3NDBkMjE0OGRlK2RlYWxlcit0Y3A6Ly8wYWNhNDA5MC5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArNzA1MEVEMDU0M0FEOThGOTlBMTUzM0UyNDBGMDQ3M0Y3MjFFQzI0QkQzOEREQzI3Mjc5ODlCMEI2Nzg2RkM2MQ=="
Aug 30 22:22:51 volumio volumio[24333]: error: MPD error: The expression evaluated to a falsy value:
Aug 30 22:22:51 volumio volumio[24333]: assert.ok(self.idling)
Aug 30 22:22:51 volumio volumio[24333]: error: The expression evaluated to a falsy value:
Aug 30 22:22:51 volumio volumio[24333]: assert.ok(self.idling)
Aug 30 22:22:51 volumio volumio[24333]: error: updateQueue error: null
Aug 30 22:22:51 volumio volumio[24333]: info: MPD running with PID24524
Aug 30 22:22:51 volumio volumio[24333]: ,establishing connection
Aug 30 22:22:51 volumio volumio[24333]: error: updateQueue error: null
Aug 30 22:22:52 volumio go-librespot[24536]: time="2024-08-30T22:22:52+07:00" level=debug msg="put connect state because NEW_DEVICE"
Aug 30 22:22:52 volumio volumio[24333]: info: go-librespot daemon successfully initialized
Aug 30 22:22:53 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Aug 30 22:22:53 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Aug 30 22:22:53 volumio volumio[24333]: info: Discovery: Getting this device information
Aug 30 22:22:53 volumio volumio[24333]: info: CoreCommandRouter::volumioGetState
Aug 30 22:22:53 volumio volumio[24333]: info: CorePlayQueue::getTrack 0
Aug 30 22:22:53 volumio volumio[24333]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Aug 30 22:22:55 volumio go-librespot[24536]: time="2024-08-30T22:22:55+07:00" level=debug msg="handling transfer player command from 014aaf798abec099cb36bca77a9d11fe407d076c"
Aug 30 22:22:55 volumio go-librespot[24536]: time="2024-08-30T22:22:55+07:00" level=debug msg="loading track spotify:track:6bjpmghStgfcmTsqsG6Yb6 (paused: false, position: 22817ms)"
Aug 30 22:22:55 volumio volumio[24333]: info: Initializing connection to go-librespot Websocket
Aug 30 22:22:55 volumio go-librespot[24536]: time="2024-08-30T22:22:55+07:00" level=debug msg="new websocket client"
Aug 30 22:22:55 volumio volumio[24333]: info: Connection to go-librespot Websocket established
Aug 30 22:22:55 volumio go-librespot[24536]: time="2024-08-30T22:22:55+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Aug 30 22:22:55 volumio go-librespot[24536]: time="2024-08-30T22:22:55+07:00" level=trace msg="emitting websocket event: will_play"
Aug 30 22:22:55 volumio volumio[24333]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6bjpmghStgfcmTsqsG6Yb6","play_origin":"playlist"}}
Aug 30 22:22:55 volumio go-librespot[24536]: time="2024-08-30T22:22:55+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1144"
Aug 30 22:22:55 volumio go-librespot[24536]: time="2024-08-30T22:22:55+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241"
Aug 30 22:22:55 volumio go-librespot[24536]: time="2024-08-30T22:22:55+07:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:6bjpmghStgfcmTsqsG6Yb6"
Aug 30 22:22:55 volumio go-librespot[24536]: time="2024-08-30T22:22:55+07:00" level=debug msg="requested aes key for file 7b6a4a8f9e1c93d22d572e6fe40f7aac6bd1d7ae, gid: 6bjpmghStgfcmTsqsG6Yb6"
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=debug msg="fetched first chunk of 13, total size is 6457682 bytes"
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=debug msg="fetched chunk 1/12, size: 524288"
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=trace msg="seek to 22817ms (diff: 98ms, samples: 1006229, bytes: 899780)"
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=info msg="loaded track \"Zero Sum\" (uri: spotify:track:6bjpmghStgfcmTsqsG6Yb6, paused: false, position: 22817ms, duration: 167733ms)"
Aug 30 22:22:56 volumio kernel: bcm2835-i2s 3f203000.i2s: I2S SYNC error!
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=debug msg="fetched chunk 2/12, size: 524288"
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=trace msg="emitting websocket event: metadata"
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=trace msg="emitting websocket event: active"
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=debug msg="sending successful reply for delaer request"
Aug 30 22:22:56 volumio volumio[24333]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6bjpmghStgfcmTsqsG6Yb6","name":"Zero Sum","artist_names":["The Smile"],"album_name":"Foreign Spies / Zero Sum","album_cover_url":"https://i.scdn.co/image/ab67616d00001e026c9a0977d8b292b1b06a18b7","position":22817,"duration":167733}}
Aug 30 22:22:56 volumio volumio[24333]: SPOTIFY: received: {"type":"active","data":null}
Aug 30 22:22:56 volumio volumio[24333]: info: Aligning Spotify Volume to Volumio Volume
Aug 30 22:22:56 volumio volumio[24333]: info: CoreCommandRouter::volumioGetState
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update
Aug 30 22:22:56 volumio volumio[24333]: info: CorePlayQueue::getTrack 0
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=debug msg="fetched chunk 4/12, size: 524288"
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=debug msg="fetched chunk 3/12, size: 524288"
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Aug 30 22:22:56 volumio go-librespot[24536]: time="2024-08-30T22:22:56+07:00" level=trace msg="emitting websocket event: playing"
Aug 30 22:22:56 volumio volumio[24333]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6bjpmghStgfcmTsqsG6Yb6","play_origin":"playlist"}}
Aug 30 22:22:56 volumio volumio[24333]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Aug 30 22:22:56 volumio volumio[24333]: TypeError: Cannot read property 'service' of undefined
Aug 30 22:22:56 volumio volumio[24333]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:322:50)
Aug 30 22:22:56 volumio volumio[24333]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:248:18)
Aug 30 22:22:56 volumio volumio[24333]: at WebSocket.message (/data/plugins/music_service/spop/index.js:175:14)
Aug 30 22:22:56 volumio volumio[24333]: at WebSocket.emit (events.js:315:20)
Aug 30 22:22:56 volumio volumio[24333]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1192:20)
Aug 30 22:22:56 volumio volumio[24333]: at Receiver.emit (events.js:315:20)
Aug 30 22:22:56 volumio volumio[24333]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:560:14)
Aug 30 22:22:56 volumio volumio[24333]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:478:17)
Aug 30 22:22:56 volumio volumio[24333]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:22)
Aug 30 22:22:56 volumio volumio[24333]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:180:18
Aug 30 22:22:56 volumio volumio[24333]: at internal/process/task_queues.js:149:7
Aug 30 22:22:56 volumio volumio[24333]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9)
Aug 30 22:22:56 volumio volumio[24333]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8)
Aug 30 22:22:56 volumio volumio[24333]: at processTicksAndRejections (internal/process/task_queues.js:93:5)
Aug 30 22:22:56 volumio volumio[24333]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Aug 30 22:22:57 volumio sudo[24585]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-30 22:21
Aug 30 22:22:57 volumio sudo[24585]: 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="7f9f1bf001add7a8b19a4516e3c74ef598b2730d"
VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71"
VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1"
VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET"
VOLUMIO_VERSION="3.631"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"