-- Logs begin at Thu 2024-05-02 12:51:27 CEST, end at Thu 2024-05-02 13:43:24 CEST. -- May 02 13:42:00 volumio-office volumio[13050]: SPOTIFY: SETTING SPOTIFY VOLUME 35 May 02 13:42:00 volumio-office volumio[13050]: info: Sending Spotify command with payload to local API: /player/volume May 02 13:42:00 volumio-office go-librespot[13256]: time="2024-05-02T13:42:00+02:00" level=debug msg="update volume to 22937/65535" May 02 13:42:00 volumio-office volumio[13050]: info: Remote config written successfully May 02 13:42:00 volumio-office volumio[13050]: info: Starting Tunnel 1 May 02 13:42:00 volumio-office volumio[13050]: info: Starting Tunnel Connection Checker May 02 13:42:00 volumio-office volumio[13050]: info: Completed starting MyVolumio Plugin May 02 13:42:00 volumio-office go-librespot[13256]: time="2024-05-02T13:42:00+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 02 13:42:00 volumio-office go-librespot[13256]: time="2024-05-02T13:42:00+02:00" level=trace msg="emitting websocket event: volume" May 02 13:42:00 volumio-office volumio[13050]: SPOTIFY: received: {"type":"volume","data":{"value":35,"max":100}} May 02 13:42:00 volumio-office volumio[13050]: SPOTIFY: RECEIVED SPOTIFY VOLUME 35 May 02 13:42:00 volumio-office volumio[13050]: info: MYVolumio Device enabled May 02 13:42:00 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... May 02 13:42:00 volumio-office volumio[13050]: info: MyVolumio status changed May 02 13:42:00 volumio-office volumio[13050]: info: Streaming services startup May 02 13:42:00 volumio-office volumio[13050]: info: Starting Streaming Daemon May 02 13:42:00 volumio-office volumio[13050]: info: Setting Geolocation for MyVolumio to eu7 May 02 13:42:00 volumio-office sudo[13425]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 02 13:42:00 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:00 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:00 volumio-office sudo[13425]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:00 volumio-office sudo[13425]: pam_unix(sudo:session): session closed for user root May 02 13:42:00 volumio-office volumio[13050]: error: Cannot start Volumio Streaming Daemon May 02 13:42:00 volumio-office volumio[13050]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service May 02 13:42:00 volumio-office volumio[13050]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. May 02 13:42:00 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid May 02 13:42:00 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... May 02 13:42:00 volumio-office volumio[13050]: info: [1714650120771] Starting BluetoothController May 02 13:42:00 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... May 02 13:42:01 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom May 02 13:42:01 volumio-office sudo[13441]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom May 02 13:42:01 volumio-office sudo[13441]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:01 volumio-office sudo[13441]: pam_unix(sudo:session): session closed for user root May 02 13:42:01 volumio-office volumio[13050]: /bin/mkdir: cannot create directory ‘/tmp/hls’: File exists May 02 13:42:01 volumio-office volumio[13050]: info: MRS: MultiRoom plugin initialized May 02 13:42:01 volumio-office volumio[13050]: info: MRS: STOPPING SNAPCLIENT May 02 13:42:01 volumio-office volumio[13050]: info: MRS: Snap server stop May 02 13:42:01 volumio-office sudo[13457]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient May 02 13:42:01 volumio-office sudo[13457]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:01 volumio-office volumio[13050]: info: MRS: STOPPING volumioStreaming May 02 13:42:01 volumio-office sudo[13457]: pam_unix(sudo:session): session closed for user root May 02 13:42:01 volumio-office sudo[13460]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver May 02 13:42:01 volumio-office sudo[13460]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:01 volumio-office sudo[13460]: pam_unix(sudo:session): session closed for user root May 02 13:42:01 volumio-office sudo[13463]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming May 02 13:42:01 volumio-office sudo[13463]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:01 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... May 02 13:42:01 volumio-office sudo[13463]: pam_unix(sudo:session): session closed for user root May 02 13:42:01 volumio-office sudo[13466]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* May 02 13:42:01 volumio-office sudo[13466]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:01 volumio-office sudo[13466]: pam_unix(sudo:session): session closed for user root May 02 13:42:01 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... May 02 13:42:01 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... May 02 13:42:01 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... May 02 13:42:01 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... May 02 13:42:01 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio May 02 13:42:01 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Loading plugin "tidal"... May 02 13:42:01 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... May 02 13:42:01 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... May 02 13:42:01 volumio-office volumio[13050]: info: Preparing to generate the ALSA configuration file May 02 13:42:01 volumio-office volumio[13050]: info: Updating MyVolumio device info May 02 13:42:01 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:01 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:01 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:01 volumio-office volumio[13050]: info: Setting Geolocation for MyVolumio to eu6 May 02 13:42:01 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:01 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:01 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:01 volumio-office volumio[13050]: info: MRS: Removed streaming files May 02 13:42:01 volumio-office volumio[13050]: info: MRS: volumioStreaming STOPPED May 02 13:42:01 volumio-office volumio[13050]: info: MRS: SNAPSERVER STOPPED May 02 13:42:01 volumio-office volumio[13050]: info: MRS: SNAPCLIENT STOPPED May 02 13:42:01 volumio-office volumio[13050]: info: Asound.conf file unchanged, so no further update is needed May 02 13:42:01 volumio-office volumio[13050]: info: Output device has changed, restarting MPD May 02 13:42:01 volumio-office sudo[13469]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 02 13:42:01 volumio-office sudo[13469]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:01 volumio-office sudo[13469]: pam_unix(sudo:session): session closed for user root May 02 13:42:02 volumio-office volumio[13050]: info: Output device has changed, restarting Shairport Sync May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:02 volumio-office sudo[13472]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 02 13:42:02 volumio-office sudo[13472]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:02 volumio-office systemd[1]: Stopping Music Player Daemon... May 02 13:42:02 volumio-office volumio[13050]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 02 13:42:02 volumio-office volumio[13050]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 02 13:42:02 volumio-office systemd[1]: mpd.service: Succeeded. May 02 13:42:02 volumio-office systemd[1]: Stopped Music Player Daemon. May 02 13:42:02 volumio-office systemd[1]: Starting Music Player Daemon... May 02 13:42:02 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 02 13:42:02 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom May 02 13:42:02 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Plugin multiroom disabled by user. Not starting May 02 13:42:02 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio May 02 13:42:02 volumio-office volumio[13050]: info: Adding METAVOLUMIO REST API Endpoints May 02 13:42:02 volumio-office volumio[13050]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio May 02 13:42:02 volumio-office volumio[13050]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio May 02 13:42:02 volumio-office volumio[13050]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio May 02 13:42:02 volumio-office volumio[13050]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio May 02 13:42:02 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui May 02 13:42:02 volumio-office volumio[13050]: info: Adding Manifest REST API Endpoints May 02 13:42:02 volumio-office volumio[13050]: info: Adding manifestui REST Endpoint for plugin: miscellanea/manifestui May 02 13:42:02 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller May 02 13:42:02 volumio-office volumio[13050]: info: Preparing CD Folders May 02 13:42:02 volumio-office volumio[13050]: info: Adding CD REST API Endpoints May 02 13:42:02 volumio-office volumio[13050]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller May 02 13:42:02 volumio-office volumio[13050]: info: Starting UDEV Watcher for CD May 02 13:42:02 volumio-office sudo[13481]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/hciconfig hci0 name Volumio-Office May 02 13:42:02 volumio-office sudo[13481]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:02 volumio-office volumio[13050]: info: Detecting CD presence with UDEV May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices May 02 13:42:02 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs May 02 13:42:02 volumio-office volumio[13050]: info: Adding inputs REST Endpoints May 02 13:42:02 volumio-office volumio[13050]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs May 02 13:42:02 volumio-office volumio[13050]: info: Scanning Audio Inputs May 02 13:42:02 volumio-office volumio[13050]: info: Checking against Known Cards name May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 02 13:42:02 volumio-office volumio[13050]: info: [1714650122229] CoreMusicLibrary::Adding element HD-Audio Generic May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 02 13:42:02 volumio-office volumio[13050]: Cannot find translation for source Mixcloud May 02 13:42:02 volumio-office volumio[13050]: Cannot find translation for source SoundCloud May 02 13:42:02 volumio-office volumio[13050]: Cannot find translation for source YouTube Music May 02 13:42:02 volumio-office volumio[13050]: Cannot find translation for source Spotify May 02 13:42:02 volumio-office volumio[13050]: Cannot find translation for source HD-Audio Generic May 02 13:42:02 volumio-office sudo[13481]: pam_unix(sudo:session): session closed for user root May 02 13:42:02 volumio-office volumio[13050]: info: Checking against Known Cards name May 02 13:42:02 volumio-office volumio[13050]: info: Checking against Known Cards name May 02 13:42:02 volumio-office volumio[13050]: info: Adding Server instance for streaming May 02 13:42:02 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio May 02 13:42:02 volumio-office volumio[13050]: error: Hi Res Audio Failed Login: Missing Login Data May 02 13:42:02 volumio-office volumio[13050]: info: Adding HIGHRESAUDIO REST API Endpoints May 02 13:42:02 volumio-office volumio[13050]: info: Adding getStreamUrlhi_res_audio REST Endpoint for plugin: music_service/hi_res_audio May 02 13:42:02 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal May 02 13:42:02 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz May 02 13:42:02 volumio-office volumio[13050]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect May 02 13:42:02 volumio-office volumio[13050]: info: Stopping AccessToken refresher cron May 02 13:42:02 volumio-office sudo[13488]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 02 13:42:02 volumio-office sudo[13488]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:02 volumio-office systemd[1]: Stopping Volumio Tidal Connect Service... May 02 13:42:02 volumio-office systemd[1]: vtcs.service: Main process exited, code=killed, status=15/TERM May 02 13:42:02 volumio-office systemd[1]: vtcs.service: Succeeded. May 02 13:42:02 volumio-office systemd[1]: Stopped Volumio Tidal Connect Service. May 02 13:42:02 volumio-office sudo[13488]: pam_unix(sudo:session): session closed for user root May 02 13:42:02 volumio-office volumio[13050]: info: AccessToken refresher cron started May 02 13:42:02 volumio-office volumio[13050]: info: Stopping AccessToken refresher cron for QOBUZ May 02 13:42:02 volumio-office volumio[13050]: info: AccessToken refresher cron started for QOBUZ May 02 13:42:02 volumio-office volumio[13050]: info: Adding TIDAL REST API Endpoints May 02 13:42:02 volumio-office volumio[13050]: info: Adding getStreamUrltidal REST Endpoint for plugin: music_service/tidal May 02 13:42:02 volumio-office volumio[13050]: info: Adding QOBUZ REST API Endpoints May 02 13:42:02 volumio-office volumio[13050]: info: Adding getStreamUrlqobuz REST Endpoint for plugin: music_service/qobuz May 02 13:42:02 volumio-office volumio[13050]: info: Bluetooth name changed to Volumio-Office May 02 13:42:02 volumio-office volumio[13050]: info: MPD Permissions set May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 02 13:42:02 volumio-office volumio[13050]: info: Starting Shairport Sync May 02 13:42:02 volumio-office sudo[13498]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 02 13:42:02 volumio-office sudo[13498]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:02 volumio-office systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 02 13:42:02 volumio-office systemd[1]: shairport-sync.service: Succeeded. May 02 13:42:02 volumio-office systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 02 13:42:02 volumio-office systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 02 13:42:02 volumio-office sudo[13498]: pam_unix(sudo:session): session closed for user root May 02 13:42:02 volumio-office volumio[13050]: info: Shairport-Sync Started May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:02 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:02 volumio-office volumio[13050]: info: Successfully Updated MyVolumio device May 02 13:42:02 volumio-office volumio[13050]: info: Listing playlists May 02 13:42:02 volumio-office volumio[13050]: info: Listing playlists May 02 13:42:02 volumio-office volumio[13050]: info: Updating MyVolumio device info May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:02 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:03 volumio-office volumio[13050]: info: Successfully Added MyVolumio device May 02 13:42:03 volumio-office mpd[13477]: May 02 13:42 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 02 13:42:03 volumio-office systemd[1]: Started Music Player Daemon. May 02 13:42:03 volumio-office sudo[13472]: pam_unix(sudo:session): session closed for user root May 02 13:42:03 volumio-office volumio[13050]: error: updateQueue error: null May 02 13:42:03 volumio-office volumio[13050]: info: Successfully Added MyVolumio device May 02 13:42:03 volumio-office volumio[13050]: info: Successfully Updated MyVolumio device May 02 13:42:05 volumio-office sudo[13521]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service May 02 13:42:05 volumio-office sudo[13521]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:05 volumio-office autossh[11076]: received signal to exit (15) May 02 13:42:05 volumio-office systemd[1]: Stopping MyVolumio SSH Tunnel... May 02 13:42:05 volumio-office systemd[1]: sshtunnel.service: Main process exited, code=killed, status=15/TERM May 02 13:42:05 volumio-office systemd[1]: sshtunnel.service: Succeeded. May 02 13:42:05 volumio-office systemd[1]: Stopped MyVolumio SSH Tunnel. May 02 13:42:05 volumio-office sudo[13524]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service May 02 13:42:05 volumio-office sudo[13524]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:05 volumio-office systemd[1]: Started MyVolumio SSH Tunnel. May 02 13:42:05 volumio-office sudo[13521]: pam_unix(sudo:session): session closed for user root May 02 13:42:05 volumio-office sudo[13524]: pam_unix(sudo:session): session closed for user root May 02 13:42:05 volumio-office autossh[13527]: port set to 0, monitoring disabled May 02 13:42:05 volumio-office autossh[13527]: starting ssh (count 1) May 02 13:42:05 volumio-office autossh[13527]: ssh child pid is 13530 May 02 13:42:05 volumio-office volumio[13050]: info: Remote SSH Started May 02 13:42:05 volumio-office volumio[13050]: info: TidalConnect service stoped! May 02 13:42:05 volumio-office volumiossh-tunnel[13525]: Warning: Permanently added '[eu6.myvolumio.org]:2222,[207.154.233.230]:2222' (RSA) to the list of known hosts. May 02 13:42:05 volumio-office volumio[13050]: info: Volumio BT Module successfully started May 02 13:42:05 volumio-office volumio[13050]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 7 May 02 13:42:05 volumio-office volumio[13050]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 02 13:42:05 volumio-office volumio[13050]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect May 02 13:42:05 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:05 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:05 volumio-office sudo[13540]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service May 02 13:42:05 volumio-office sudo[13540]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:05 volumio-office systemd[1]: Started Volumio Tidal Connect Service. May 02 13:42:05 volumio-office sudo[13540]: pam_unix(sudo:session): session closed for user root May 02 13:42:05 volumio-office volumio[13050]: info: Executing endpoint tc_getconfig May 02 13:42:05 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig May 02 13:42:05 volumio-office vtcs[13542]: STARTING TidalConnect services, version: 1.3.0.19 May 02 13:42:05 volumio-office vtcs[13542]: STARTED TidalConnect services. May 02 13:42:05 volumio-office volumio[13050]: info: Executing endpoint tc_connect May 02 13:42:05 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect May 02 13:42:05 volumio-office volumio[13050]: info: Connecting to TidalConnect May 02 13:42:05 volumio-office volumio[13050]: info: CoreCommandRouter::servicePushState May 02 13:42:05 volumio-office volumio[13050]: info: CoreStateMachine::pushState May 02 13:42:05 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:05 volumio-office volumio[13050]: info: CoreCommandRouter::volumioPushState May 02 13:42:05 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:05 volumio-office volumio[13050]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received tidalconnect May 02 13:42:05 volumio-office volumio[13050]: info: CoreCommandRouter::servicePushState May 02 13:42:05 volumio-office volumio[13050]: info: CoreStateMachine::pushState May 02 13:42:05 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:05 volumio-office volumio[13050]: info: CoreCommandRouter::volumioPushState May 02 13:42:05 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:05 volumio-office volumio[13050]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received tidalconnect May 02 13:42:05 volumio-office volumio[13050]: info: [ASDebug] CurState: stop PrevState: stop May 02 13:42:05 volumio-office volumio[13050]: info: [ASDebug] CurState: stop PrevState: stop May 02 13:42:05 volumio-office volumio[13050]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 May 02 13:42:05 volumio-office volumio[13050]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 May 02 13:42:08 volumio-office volumio[13050]: info: TidalConnect service started! May 02 13:42:08 volumio-office volumio[13050]: info: BOOT COMPLETED May 02 13:42:08 volumio-office volumio[13050]: [Metrics] CommandRouter: 26s 564.92ms May 02 13:42:08 volumio-office volumio[13050]: info: CoreCommandRouter::volumiosetStartupVolume May 02 13:42:08 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 02 13:42:08 volumio-office volumio[13050]: info: VolumeController:: Setting startup Volume 35 May 02 13:42:08 volumio-office volumio[13050]: info: VolumeController::SetAlsaVolume35 May 02 13:42:08 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:08 volumio-office volumio[13050]: info: CoreCommandRouter::Close All Modals sent May 02 13:42:08 volumio-office volumio[13050]: info: CoreCommandRouter::Close All Modals sent May 02 13:42:08 volumio-office volumio[13050]: info: CoreStateMachine::pushState May 02 13:42:08 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:08 volumio-office volumio[13050]: info: CoreCommandRouter::volumioPushState May 02 13:42:08 volumio-office volumio[13050]: info: [ASDebug] CurState: stop PrevState: stop May 02 13:42:08 volumio-office volumio[13050]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 May 02 13:42:09 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable May 02 13:42:09 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 02 13:42:09 volumio-office volumio[13050]: xcb_connection_has_error() returned true May 02 13:42:09 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect May 02 13:42:10 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:10 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:12 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 02 13:42:12 volumio-office volumio[13050]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 May 02 13:42:12 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:12 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:12 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:12 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:13 volumio-office sudo[13626]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 02 13:42:13 volumio-office sudo[13626]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:13 volumio-office sudo[13626]: pam_unix(sudo:session): session closed for user root May 02 13:42:13 volumio-office sudo[13629]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 02 13:42:13 volumio-office sudo[13629]: pam_unix(sudo:session): session opened for user root by (uid=0) May 02 13:42:13 volumio-office sudo[13629]: pam_unix(sudo:session): session closed for user root May 02 13:42:13 volumio-office volumio[13050]: verbose: New Socket.io Connection to 192.168.1.101 from 192.168.1.235 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36 Total Clients: 8 May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetVisibleSources May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:13 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 02 13:42:13 volumio-office volumio[13050]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom May 02 13:42:13 volumio-office volumio[13050]: info: Received Get System Info May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 02 13:42:13 volumio-office volumio[13050]: info: Discovery: Getting this device information May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:13 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:13 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:13 volumio-office volumio[13050]: info: Listing playlists May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 02 13:42:13 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 02 13:42:14 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:14 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:14 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 02 13:42:14 volumio-office volumio[13050]: info: Received Get System Info May 02 13:42:14 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 02 13:42:14 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 02 13:42:14 volumio-office volumio[13050]: info: Discovery: Getting this device information May 02 13:42:14 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:14 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:14 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 02 13:42:15 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 02 13:42:15 volumio-office volumio[13050]: info: Received Get System Info May 02 13:42:15 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 02 13:42:15 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 02 13:42:15 volumio-office volumio[13050]: info: Discovery: Getting this device information May 02 13:42:15 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:15 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:15 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 02 13:42:16 volumio-office volumio[13050]: info: Executing endpoint metavolumio May 02 13:42:16 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 02 13:42:16 volumio-office volumio[13050]: info: Executing endpoint metavolumio May 02 13:42:16 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 02 13:42:16 volumio-office volumio[13050]: info: Executing endpoint metavolumio May 02 13:42:16 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 02 13:42:16 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 02 13:42:16 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 02 13:42:17 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 02 13:42:17 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 02 13:42:17 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 02 13:42:17 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 02 13:42:17 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 02 13:42:17 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam May 02 13:42:17 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 02 13:42:17 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject May 02 13:42:17 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetBrowseSources May 02 13:42:17 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 02 13:42:17 volumio-office volumio-remote-updater[590]: No test mode May 02 13:42:17 volumio-office volumio-remote-updater[590]: No alpha test mode May 02 13:42:17 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled May 02 13:42:17 volumio-office volumio[13050]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} May 02 13:42:17 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache May 02 13:42:18 volumio-office volumio[13050]: info: CoreCommandRouter::getUIConfigOnPlugin May 02 13:42:18 volumio-office volumio[13050]: info: [ASDebug] Setting UI defaults May 02 13:42:18 volumio-office volumio[13050]: info: [ASDebug] Port: 24 May 02 13:42:18 volumio-office volumio[13050]: info: [ASDebug] Inverted: false May 02 13:42:18 volumio-office volumio[13050]: info: [ASDebug] Latched: false May 02 13:42:18 volumio-office volumio[13050]: info: [ASDebug] On pulse width: 500 May 02 13:42:18 volumio-office volumio[13050]: info: [ASDebug] Off pulse width: 500 May 02 13:42:22 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:22 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:22 volumio-office volumio[13050]: info: Listing playlists May 02 13:42:22 volumio-office volumio[13050]: info: Listing playlists May 02 13:42:31 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 02 13:42:31 volumio-office volumio[13050]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 02 13:42:31 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 02 13:42:31 volumio-office volumio[13050]: info: Received Get System Version May 02 13:42:31 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 02 13:42:31 volumio-office volumio[13050]: info: Received Get System Info May 02 13:42:31 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 02 13:42:31 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 02 13:42:31 volumio-office volumio[13050]: info: Discovery: Getting this device information May 02 13:42:31 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:31 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:31 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 02 13:42:31 volumio-office nmbd[777]: [2024/05/02 13:42:31.307842, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) May 02 13:42:31 volumio-office nmbd[777]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.1.101 for name WORKGROUP<1d>. May 02 13:42:31 volumio-office nmbd[777]: This response was from IP 192.168.1.242, reporting an IP address of 192.168.1.242. May 02 13:42:32 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:32 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:42 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:42 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:42:42 volumio-office volumio[13050]: info: Listing playlists May 02 13:42:42 volumio-office volumio[13050]: info: Listing playlists May 02 13:42:49 volumio-office go-librespot[13256]: time="2024-05-02T13:42:49+02:00" level=error msg="did not receive last pong from dealer, 30s passed" May 02 13:42:49 volumio-office go-librespot[13256]: time="2024-05-02T13:42:49+02:00" level=error msg="failed receiving dealer message" error="failed to get reader: received close frame: status = StatusServiceRestart and reason = \"\"" May 02 13:42:49 volumio-office go-librespot[13256]: time="2024-05-02T13:42:49+02:00" level=debug msg="re-established dealer connection" May 02 13:42:49 volumio-office go-librespot[13256]: time="2024-05-02T13:42:49+02:00" level=debug msg="received connection id: YmI0YjJkMDgtMjA2Yi00NTRlLWExNDMtMDc5ODIzNjVjODBkK2RlYWxlcit0Y3A6Ly9ndWMzLWRlYWxlci1hLXc2cmsuZ3VjMy5zcG90aWZ5Lm5ldDo1NzAwK0RGNzA2MDQ2RDFCNjgxODRGRTdCQkU5REFGNTVBQUUwOEQwMjJBMzgwNTgwNUMwM0E0OTI4NDkwNTQ2MkIyQTk=" May 02 13:42:49 volumio-office go-librespot[13256]: time="2024-05-02T13:42:49+02:00" level=debug msg="put connect state because NEW_DEVICE" May 02 13:42:52 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:42:52 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:43:02 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:43:02 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:43:02 volumio-office volumio[13050]: info: Listing playlists May 02 13:43:02 volumio-office volumio[13050]: info: Listing playlists May 02 13:43:03 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:43:03 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:43:05 volumio-office volumio[13050]: info: CoreCommandRouter::volumioPlay May 02 13:43:05 volumio-office volumio[13050]: info: CoreStateMachine::play index undefined May 02 13:43:05 volumio-office volumio[13050]: info: CoreStateMachine::setConsumeUpdateService undefined May 02 13:43:05 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:43:05 volumio-office volumio[13050]: info: CoreStateMachine::startPlaybackTimer May 02 13:43:05 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:43:05 volumio-office volumio[13050]: info: [1714650185663] ControllerSpotify::clearAddPlayTrack May 02 13:43:05 volumio-office volumio[13050]: info: Sending Spotify command with payload to local API: /player/play May 02 13:43:05 volumio-office go-librespot[13256]: time="2024-05-02T13:43:05+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" May 02 13:43:05 volumio-office go-librespot[13256]: time="2024-05-02T13:43:05+02:00" level=debug msg="loading track spotify:track:3TYp5qxohTWMynJ2SNvgHJ (paused: false, position: 0ms)" May 02 13:43:05 volumio-office go-librespot[13256]: time="2024-05-02T13:43:05+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 02 13:43:05 volumio-office go-librespot[13256]: time="2024-05-02T13:43:05+02:00" level=trace msg="emitting websocket event: will_play" May 02 13:43:05 volumio-office volumio[13050]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3TYp5qxohTWMynJ2SNvgHJ","play_origin":"go-librespot"}} May 02 13:43:05 volumio-office go-librespot[13256]: time="2024-05-02T13:43:05+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:3TYp5qxohTWMynJ2SNvgHJ" May 02 13:43:05 volumio-office go-librespot[13256]: time="2024-05-02T13:43:05+02:00" level=debug msg="requested aes key for file 0935efc170ed98cd17148df8676811e5508a9802, gid: 3TYp5qxohTWMynJ2SNvgHJ" May 02 13:43:05 volumio-office go-librespot[13256]: time="2024-05-02T13:43:05+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 02 13:43:06 volumio-office volumio[13050]: info: Executing endpoint metavolumio May 02 13:43:06 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 02 13:43:06 volumio-office volumio[13050]: info: Executing endpoint metavolumio May 02 13:43:06 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 02 13:43:06 volumio-office volumio[13050]: info: Executing endpoint metavolumio May 02 13:43:06 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 02 13:43:06 volumio-office go-librespot[13256]: time="2024-05-02T13:43:06+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 02 13:43:06 volumio-office go-librespot[13256]: time="2024-05-02T13:43:06+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 02 13:43:06 volumio-office go-librespot[13256]: time="2024-05-02T13:43:06+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" May 02 13:43:06 volumio-office go-librespot[13256]: time="2024-05-02T13:43:06+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2839" May 02 13:43:06 volumio-office go-librespot[13256]: time="2024-05-02T13:43:06+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1972" May 02 13:43:06 volumio-office go-librespot[13256]: time="2024-05-02T13:43:06+02:00" level=debug msg="fetched first chunk of 43, total size is 22377528 bytes" May 02 13:43:06 volumio-office go-librespot[13256]: time="2024-05-02T13:43:06+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" May 02 13:43:06 volumio-office go-librespot[13256]: time="2024-05-02T13:43:06+02:00" level=info msg="loaded track \"Gole Sahra\" (uri: spotify:track:3TYp5qxohTWMynJ2SNvgHJ, paused: false, position: 0ms, duration: 503040ms)" May 02 13:43:07 volumio-office go-librespot[13256]: time="2024-05-02T13:43:07+02:00" level=debug msg="fetched chunk 1/42, size: 524288" May 02 13:43:07 volumio-office go-librespot[13256]: time="2024-05-02T13:43:07+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 02 13:43:07 volumio-office go-librespot[13256]: time="2024-05-02T13:43:07+02:00" level=trace msg="emitting websocket event: metadata" May 02 13:43:07 volumio-office volumio[13050]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3TYp5qxohTWMynJ2SNvgHJ","name":"Gole Sahra","artist_names":["Jerry Spoon","Ben \u0026 Vincent"],"album_name":"Gole Sahra","album_cover_url":"https://i.scdn.co/image/ab67616d00001e025c384de003e4445680560584","position":0,"duration":503040,"release_date":"year:2022 month:11 day:25","track_number":1,"disc_number":1}} May 02 13:43:07 volumio-office go-librespot[13256]: time="2024-05-02T13:43:07+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 02 13:43:07 volumio-office go-librespot[13256]: time="2024-05-02T13:43:07+02:00" level=trace msg="emitting websocket event: playing" May 02 13:43:07 volumio-office volumio[13050]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3TYp5qxohTWMynJ2SNvgHJ","play_origin":"go-librespot"}} May 02 13:43:07 volumio-office volumio[13050]: SPOTIFY: PUSH STATE SPOTIFY May 02 13:43:07 volumio-office volumio[13050]: SPOTIFY: {"status":"play","service":"spop","title":"Gole Sahra","artist":"Jerry Spoon, Ben & Vincent","album":"Gole Sahra","albumart":"https://i.scdn.co/image/ab67616d00001e025c384de003e4445680560584","uri":"spotify:track:3TYp5qxohTWMynJ2SNvgHJ","trackType":"spotify","seek":0,"duration":503,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 02 13:43:07 volumio-office volumio[13050]: info: CoreCommandRouter::servicePushState May 02 13:43:07 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:43:07 volumio-office volumio[13050]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Gole Sahra","artist":"Jerry Spoon, Ben & Vincent","album":"Gole Sahra","albumart":"https://i.scdn.co/image/ab67616d00001e025c384de003e4445680560584","uri":"spotify:track:3TYp5qxohTWMynJ2SNvgHJ","trackType":"spotify","seek":0,"duration":503,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 02 13:43:07 volumio-office volumio[13050]: verbose: CURRENT POSITION 0 May 02 13:43:07 volumio-office volumio[13050]: info: CoreStateMachine::syncState stateService play May 02 13:43:07 volumio-office volumio[13050]: info: CoreStateMachine::syncState currentStatus stop May 02 13:43:07 volumio-office go-librespot[13256]: time="2024-05-02T13:43:07+02:00" level=debug msg="fetched chunk 3/42, size: 524288" May 02 13:43:07 volumio-office go-librespot[13256]: time="2024-05-02T13:43:07+02:00" level=debug msg="fetched chunk 2/42, size: 524288" May 02 13:43:07 volumio-office volumio[13050]: SPOTIFY: PUSH STATE SPOTIFY May 02 13:43:07 volumio-office volumio[13050]: SPOTIFY: {"status":"play","service":"spop","title":"Gole Sahra","artist":"Jerry Spoon, Ben & Vincent","album":"Gole Sahra","albumart":"https://i.scdn.co/image/ab67616d00001e025c384de003e4445680560584","uri":"spotify:track:3TYp5qxohTWMynJ2SNvgHJ","trackType":"spotify","seek":0,"duration":503,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 02 13:43:07 volumio-office volumio[13050]: info: CoreCommandRouter::servicePushState May 02 13:43:07 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:43:07 volumio-office volumio[13050]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Gole Sahra","artist":"Jerry Spoon, Ben & Vincent","album":"Gole Sahra","albumart":"https://i.scdn.co/image/ab67616d00001e025c384de003e4445680560584","uri":"spotify:track:3TYp5qxohTWMynJ2SNvgHJ","trackType":"spotify","seek":0,"duration":503,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 02 13:43:07 volumio-office volumio[13050]: verbose: CURRENT POSITION 0 May 02 13:43:07 volumio-office volumio[13050]: info: CoreStateMachine::syncState stateService play May 02 13:43:07 volumio-office volumio[13050]: info: CoreStateMachine::syncState currentStatus play May 02 13:43:07 volumio-office volumio[13050]: info: Received an update from plugin. extracting info from payload May 02 13:43:07 volumio-office volumio[13050]: info: CoreStateMachine::pushState May 02 13:43:07 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:43:07 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 02 13:43:07 volumio-office volumio[13050]: info: CoreCommandRouter::volumioPushState May 02 13:43:07 volumio-office volumio[13050]: info: CoreStateMachine::pushState May 02 13:43:07 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:43:07 volumio-office volumio[13050]: info: CoreCommandRouter::volumioPushState May 02 13:43:07 volumio-office volumio[13050]: info: [ASDebug] CurState: play PrevState: stop May 02 13:43:07 volumio-office volumio[13050]: info: [ASDebug] Togle GPIO: ON May 02 13:43:07 volumio-office volumio[13050]: info: [ASDebug] CurState: play PrevState: play May 02 13:43:07 volumio-office volumio[13050]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 May 02 13:43:07 volumio-office volumio[13050]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 May 02 13:43:08 volumio-office volumio[13050]: info: CoreCommandRouter::volumioPause May 02 13:43:08 volumio-office volumio[13050]: info: CoreStateMachine::pause May 02 13:43:08 volumio-office volumio[13050]: info: CoreStateMachine::stPlaybackTimer May 02 13:43:08 volumio-office volumio[13050]: info: CoreStateMachine::servicePause May 02 13:43:08 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:43:08 volumio-office volumio[13050]: info: CoreCommandRouter::servicePause May 02 13:43:08 volumio-office volumio[13050]: info: Spotify Received pause May 02 13:43:08 volumio-office volumio[13050]: SPOTIFY: SPOTIFY PAUSE May 02 13:43:08 volumio-office volumio[13050]: SPOTIFY: {"status":"play","position":0,"title":"Gole Sahra","artist":"Jerry Spoon","album":"Gole Sahra","albumart":"https://i.scdn.co/image/ab67616d0000b2735c384de003e4445680560584","uri":"spotify:track:3TYp5qxohTWMynJ2SNvgHJ","trackType":"spotify","codec":"ogg","seek":0,"duration":503,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":true,"repeat":null,"repeatSingle":false,"consume":false,"volume":35,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 02 13:43:08 volumio-office volumio[13050]: info: Sending Spotify command to local API: /player/pause May 02 13:43:08 volumio-office go-librespot[13256]: time="2024-05-02T13:43:08+02:00" level=debug msg="pause track at 1564ms" May 02 13:43:08 volumio-office go-librespot[13256]: time="2024-05-02T13:43:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 02 13:43:08 volumio-office go-librespot[13256]: time="2024-05-02T13:43:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 02 13:43:08 volumio-office go-librespot[13256]: time="2024-05-02T13:43:08+02:00" level=trace msg="emitting websocket event: paused" May 02 13:43:08 volumio-office volumio[13050]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3TYp5qxohTWMynJ2SNvgHJ","play_origin":"go-librespot"}} May 02 13:43:08 volumio-office volumio[13050]: SPOTIFY: PUSH STATE SPOTIFY May 02 13:43:08 volumio-office volumio[13050]: SPOTIFY: {"status":"pause","service":"spop","title":"Gole Sahra","artist":"Jerry Spoon, Ben & Vincent","album":"Gole Sahra","albumart":"https://i.scdn.co/image/ab67616d00001e025c384de003e4445680560584","uri":"spotify:track:3TYp5qxohTWMynJ2SNvgHJ","trackType":"spotify","seek":1000,"duration":503,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 02 13:43:08 volumio-office volumio[13050]: info: CoreCommandRouter::servicePushState May 02 13:43:08 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:43:08 volumio-office volumio[13050]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Gole Sahra","artist":"Jerry Spoon, Ben & Vincent","album":"Gole Sahra","albumart":"https://i.scdn.co/image/ab67616d00001e025c384de003e4445680560584","uri":"spotify:track:3TYp5qxohTWMynJ2SNvgHJ","trackType":"spotify","seek":1000,"duration":503,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 02 13:43:08 volumio-office volumio[13050]: verbose: CURRENT POSITION 0 May 02 13:43:08 volumio-office volumio[13050]: info: CoreStateMachine::syncState stateService pause May 02 13:43:08 volumio-office volumio[13050]: info: CoreStateMachine::syncState currentStatus pause May 02 13:43:08 volumio-office volumio[13050]: info: CoreStateMachine::pushState May 02 13:43:08 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:43:08 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 02 13:43:08 volumio-office volumio[13050]: info: CoreCommandRouter::volumioPushState May 02 13:43:08 volumio-office volumio[13050]: info: CoreStateMachine::stPlaybackTimer May 02 13:43:08 volumio-office volumio[13050]: info: [ASDebug] CurState: pause PrevState: play May 02 13:43:08 volumio-office volumio[13050]: info: [ASDebug] InitTimeout - Amp off in: 3000 ms May 02 13:43:08 volumio-office volumio[13050]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 May 02 13:43:11 volumio-office volumio[13050]: info: [ASDebug] Togle GPIO: OFF May 02 13:43:12 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:43:12 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:43:13 volumio-office volumio[13050]: error: Failed request for metavolumio API May 02 13:43:13 volumio-office volumio[13050]: error: Failed request for metavolumio API May 02 13:43:13 volumio-office volumio[13050]: error: Failed request for metavolumio API May 02 13:43:19 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 02 13:43:19 volumio-office volumio[13050]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 02 13:43:22 volumio-office volumio[13050]: info: CoreCommandRouter::volumioGetState May 02 13:43:22 volumio-office volumio[13050]: info: CorePlayQueue::getTrack 0 May 02 13:43:22 volumio-office volumio[13050]: info: Listing playlists May 02 13:43:22 volumio-office volumio[13050]: info: Listing playlists May 02 13:43:24 volumio-office volumio[13050]: info: [ASDebug] Port: 24 May 02 13:43:24 volumio-office volumio[13050]: info: [ASDebug] Inverted: false May 02 13:43:24 volumio-office volumio[13050]: info: [ASDebug] Delay: 3000 May 02 13:43:24 volumio-office volumio[13050]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 02 13:43:24 volumio-office volumio[13050]: TypeError: self.shutdown.isOpen is not a function May 02 13:43:24 volumio-office volumio[13050]: at AmpSwitchController.freeHardware (/data/plugins/miscellanea/ampswitch/index.js:233:21) May 02 13:43:24 volumio-office volumio[13050]: at AmpSwitchController.onStop (/data/plugins/miscellanea/ampswitch/index.js:84:8) May 02 13:43:24 volumio-office volumio[13050]: at PluginManager.stopPlugin (/volumio/app/pluginmanager.js:460:30) May 02 13:43:24 volumio-office volumio[13050]: at PluginManager.disableAndStopPlugin (/volumio/app/pluginmanager.js:1883:8) May 02 13:43:24 volumio-office volumio[13050]: at CoreCommandRouter.disableAndStopPlugin (/volumio/app/index.js:1531:29) May 02 13:43:24 volumio-office volumio[13050]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1356:47) May 02 13:43:24 volumio-office volumio[13050]: at Socket.emit (events.js:400:28) May 02 13:43:24 volumio-office volumio[13050]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 May 02 13:43:24 volumio-office volumio[13050]: at processTicksAndRejections (internal/process/task_queues.js:77:11) May 02 13:43:24 volumio-office volumio[13050]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 02 13:43:24 volumio-office sudo[14102]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-05-02 13:42 May 02 13:43:24 volumio-office sudo[14102]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="7b9cb4a8b52fb7148a38d6ac651c1c29e09bb92c" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="b1dcc17f6d31bf91f0abd3c3fa57506d1e0d2b6b" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 01 Mar 2024 08:52:33 PM CET" VOLUMIO_VERSION="3.634" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="93edfc70711724967af109c0a39fa069"