-- Logs begin at Fri 2024-08-23 15:21:33 UTC, end at Fri 2024-10-04 14:16:33 UTC. -- Oct 04 14:15:04 volumio volumio[1057]: info: Tunnel connection is inactive, restarting it Oct 04 14:15:04 volumio volumio[1057]: info: Starting Tunnel 1 Oct 04 14:15:04 volumio volumio[1057]: info: Starting Tunnel Connection Checker Oct 04 14:15:05 volumio sudo[8604]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Oct 04 14:15:05 volumio sudo[8604]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 14:15:05 volumio systemd[1]: Stopping MyVolumio SSH Tunnel... Oct 04 14:15:05 volumio autossh[8162]: received signal to exit (15) Oct 04 14:15:05 volumio volumio[1057]: ------------------------------------ BT MESSAGE: BT STATUS: running Oct 04 14:15:05 volumio volumio[1057]: BT PLUGIN MESSAGE: Playing: false Oct 04 14:15:05 volumio volumio[1057]: BT PLUGIN MESSAGE: VOLATILE: undefined Oct 04 14:15:05 volumio volumio[1057]: BT PLUGIN MESSAGE: STATE:undefined Oct 04 14:15:05 volumio volumio[1057]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Oct 04 14:15:05 volumio volumio[1057]: BT PLUGIN MESSAGE: Playing: false Oct 04 14:15:05 volumio volumio[1057]: BT PLUGIN MESSAGE: VOLATILE: undefined Oct 04 14:15:05 volumio volumio[1057]: BT PLUGIN MESSAGE: STATE:undefined Oct 04 14:15:05 volumio systemd[1]: Starting MyVolumio SSH Tunnel... Oct 04 14:15:05 volumio systemd[1]: Started MyVolumio SSH Tunnel. Oct 04 14:15:05 volumio sudo[8604]: pam_unix(sudo:session): session closed for user root Oct 04 14:15:05 volumio volumio[1057]: info: Remote SSH Started Oct 04 14:15:05 volumio autossh[8612]: port set to 0, monitoring disabled Oct 04 14:15:05 volumio autossh[8612]: starting ssh (count 1) Oct 04 14:15:05 volumio autossh[8612]: ssh child pid is 8617 Oct 04 14:15:05 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:05 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Oct 04 14:15:14 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:14 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Oct 04 14:15:14 volumio volumio[1057]: verbose: STATE SERVICE {"status":"pause","service":"tidalconnect","title":"Man in the Long Black Coat","artist":"Bob Dylan","album":"Oh Mercy","albumart":"https://resources.tidal.com/images/23e30b7c/84da/4a50/99df/4efcf2fbfe95/1280x1280.jpg","uri":"","icon":"fa fa-spinner","trackType":"tidal","seek":18947,"duration":273,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"1411200","channels":2,"random":false,"repeat":false,"repeatSingle":false,"stream":false,"repeatMode":"all"} Oct 04 14:15:14 volumio volumio[1057]: verbose: CURRENT POSITION 0 Oct 04 14:15:14 volumio volumio[1057]: info: CoreStateMachine::syncState stateService pause Oct 04 14:15:14 volumio volumio[1057]: info: CoreStateMachine::syncState currentStatus stop Oct 04 14:15:14 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:14 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Oct 04 14:15:14 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:14 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:17 volumio volumio[1057]: info: PlaybackInactive Oct 04 14:15:17 volumio volumio[1057]: info: Device Session is_active: true Oct 04 14:15:17 volumio volumio[1057]: info: DeviceInactive Oct 04 14:15:17 volumio volumio[1057]: info: Relinquishing Volumio State Oct 04 14:15:17 volumio volumio[1057]: verbose: UNSET VOLATILE Oct 04 14:15:17 volumio volumio[1057]: info: CoreStateMachine::resetVolumioState Oct 04 14:15:17 volumio volumio[1057]: info: CoreStateMachine::getcurrentVolume Oct 04 14:15:17 volumio volumio[1057]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 14:15:17 volumio vtcs[1624]: [2024-10-04 14:15:17] [info] asio async_shutdown error: asio.misc:2 (End of file) Oct 04 14:15:17 volumio volumio[1057]: info: VolumeController:: Volume=100 Mute =false Oct 04 14:15:17 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:17 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Oct 04 14:15:17 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:17 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:17 volumio volumio[1057]: info: CoreStateMachine::updateTrackBlock Oct 04 14:15:17 volumio volumio[1057]: info: CorePlayQueue::getTrackBlock Oct 04 14:15:17 volumio volumio[1057]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 14:15:18 volumio volumio[1057]: info: VolumeController:: Volume=100 Mute =false Oct 04 14:15:18 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:18 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Oct 04 14:15:18 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:18 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:19 volumio wpa_supplicant[930]: wlan0: WPA: Group rekeying completed with 44:4e:6d:17:32:06 [GTK=CCMP] Oct 04 14:15:22 volumio volumio[8543]: [Vollibrespot] : Connecting to AP "ap-gew4.spotify.com:443" Oct 04 14:15:22 volumio volumio[8543]: [Vollibrespot] : Authenticated as "1gk8mgjtslrohy1b0bizzl3za" ! Oct 04 14:15:22 volumio volumio[8543]: [Vollibrespot] : Setting up new mixer: card:hw:2 mixer:DAC index:0 Oct 04 14:15:22 volumio volumio[8543]: [Vollibrespot] : Alsa Mixer info min: 0 (MilliBel(-9999999)[dB]) -- max: 240 (MilliBel(0)[dB]) HW: true Oct 04 14:15:22 volumio volumio[8543]: [Vollibrespot] : Using alsa sink Oct 04 14:15:22 volumio volumio[8543]: [Vollibrespot] : Metadata pipe established Oct 04 14:15:22 volumio volumio[8543]: [Vollibrespot] : Country: "DE" Oct 04 14:15:22 volumio volumio[8543]: [Vollibrespot] : Event: Volume { volume_to_mixer: 0 } Oct 04 14:15:22 volumio volumio[1057]: [SpotifyConnect] 0 Oct 04 14:15:22 volumio volumio[1057]: [SpotifyConnect] Volume: Spotify:0 Volumio: 0 Oct 04 14:15:22 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:22 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Oct 04 14:15:22 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:22 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:23 volumio volumio[8543]: [Vollibrespot] : Fetching autoplay context uri Oct 04 14:15:23 volumio volumio[8543]: [Vollibrespot] : Event: SessionActive { became_active_at: 1728051323324 } Oct 04 14:15:23 volumio volumio[8543]: [Vollibrespot] : SessionActive! Oct 04 14:15:23 volumio volumio[8543]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 253226767921418438364300463522807601691, audio_type: Track } } Oct 04 14:15:23 volumio volumio[8543]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 253226767921418438364300463522807601691, audio_type: Track } } Oct 04 14:15:23 volumio volumio[8543]: [Vollibrespot] : error 400 for uri hm://autoplay-enabled/query?uri=spotify:search:bob+dylan+lon Oct 04 14:15:23 volumio volumio[8543]: [Vollibrespot] : AutoplayError: MercuryError Oct 04 14:15:23 volumio volumio[8543]: [Vollibrespot] : Event: GotToken { token: Token { access_token: "BQCw-qx-Tx9IqU0o3P7fpClgceW8vnL9QS3h8AeJBhAk14VDo7HeLKxDO7Q1SfkCoK1WOD-npxhdHWs8ByQAOitdXMX1uuTCGfjuscil8rWBDhOTZTPkjVcop7odbZ6zlwDFrxqYh4moYDCzjppoaroRswH6caDfMLr8raQxJIin1q8ba6192lmPfRP9aHmtX-R-D6UHmGcXeoDNNIMJuHvuzLZG7nZbLg", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } } Oct 04 14:15:23 volumio volumio[8543]: [Vollibrespot] : Loading with Spotify URI Oct 04 14:15:23 volumio volumio[8543]: [Vollibrespot] : (273200 ms) loaded Oct 04 14:15:23 volumio volumio[8543]: [Vollibrespot] : Event: SinkActive Oct 04 14:15:24 volumio volumio[1057]: [SpotifyConnect] A connect session has begun Oct 04 14:15:24 volumio volumio[1057]: [SpotifyConnect] Device palyback is active! Oct 04 14:15:24 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:24 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Oct 04 14:15:24 volumio volumio[1057]: [SpotifyConnect] Currently active: mpd Oct 04 14:15:24 volumio volumio[1057]: [SpotifyConnect] Stopping currently active service Oct 04 14:15:24 volumio volumio[1057]: info: CoreCommandRouter::volumioStop Oct 04 14:15:24 volumio volumio[1057]: info: CoreStateMachine::stop Oct 04 14:15:24 volumio volumio[1057]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 04 14:15:24 volumio volumio[1057]: verbose: UNSET VOLATILE Oct 04 14:15:24 volumio volumio[1057]: [SpotifyConnect] Vollibrespot Active Oct 04 14:15:24 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:24 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Oct 04 14:15:24 volumio volumio[1057]: [SpotifyConnect] Currently active: mpd Oct 04 14:15:24 volumio volumio[1057]: [SpotifyConnect] Setting Volatile state to Volspotconnect2 Oct 04 14:15:24 volumio volumio[1057]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 04 14:15:24 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:24 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:24 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:24 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:24 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:24 volumio volumio[1057]: [SpotifyConnect] Currently active: volspotconnect2 Oct 04 14:15:24 volumio volumio[1057]: [SpotifyConnect] Pushing new state :: true Oct 04 14:15:24 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:24 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:24 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:24 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:24 volumio volumio[1057]: [SpotifyConnect] BQCw-qx-Tx9IqU0o3P7fpClgceW8vnL9QS3h8AeJBhAk14VDo7HeLKxDO7Q1SfkCoK1WOD-npxhdHWs8ByQAOitdXMX1uuTCGfjuscil8rWBDhOTZTPkjVcop7odbZ6zlwDFrxqYh4moYDCzjppoaroRswH6caDfMLr8raQxJIin1q8ba6192lmPfRP9aHmtX-R-D6UHmGcXeoDNNIMJuHvuzLZG7nZbLg Oct 04 14:15:24 volumio volumio[1057]: [SpotifyConnect] Sink acquired Oct 04 14:15:24 volumio volumio[1057]: [SpotifyConnect] Sink acquired Oct 04 14:15:24 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:24 volumio volumio[1057]: [SpotifyConnect] Currently active: volspotconnect2 Oct 04 14:15:24 volumio volumio[1057]: [SpotifyConnect] Pushing new state :: true Oct 04 14:15:24 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:24 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:24 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:24 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:25 volumio volumio[8543]: [Vollibrespot] : Event: Seek { position_ms: 66465 } Oct 04 14:15:25 volumio volumio[8543]: [Vollibrespot] : Event: Pause { track_id: SpotifyId { id: 253226767921418438364300463522807601691, audio_type: Track }, position_ms: 66465 } Oct 04 14:15:25 volumio volumiossh-tunnel[8610]: Warning: Permanently added '[eu4.myvolumio.org]:2222,[167.172.103.77]:2222' (RSA) to the list of known hosts. Oct 04 14:15:26 volumio volumio[8543]: [Vollibrespot] : Event: SinkInactive Oct 04 14:15:26 volumio volumio[8543]: [Vollibrespot] : Event: PlaybackStopped { track_id: SpotifyId { id: 253226767921418438364300463522807601691, audio_type: Track } } Oct 04 14:15:27 volumio volumio[8543]: [Vollibrespot] : Event: Seek { position_ms: 0 } Oct 04 14:15:27 volumio volumio[8543]: [Vollibrespot] : Event: PlaybackStopped { track_id: SpotifyId { id: 253226767921418438364300463522807601691, audio_type: Track } } Oct 04 14:15:27 volumio volumio[8543]: [Vollibrespot] : Event: Play { track_id: SpotifyId { id: 253226767921418438364300463522807601691, audio_type: Track }, position_ms: 0 } Oct 04 14:15:28 volumio volumio[8543]: [Vollibrespot] : Event: SinkActive Oct 04 14:15:29 volumio volumio[1057]: [SpotifyConnect] 66465 Oct 04 14:15:29 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:29 volumio volumio[1057]: [SpotifyConnect] Currently active: volspotconnect2 Oct 04 14:15:29 volumio volumio[1057]: [SpotifyConnect] Pushing new state :: true Oct 04 14:15:29 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:29 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:29 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:29 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:29 volumio volumio[1057]: [SpotifyConnect] pause Oct 04 14:15:29 volumio volumio[1057]: [SpotifyConnect] Man in the Long Black Coat Oct 04 14:15:29 volumio volumio[1057]: [SpotifyConnect] Pushing metadata Oct 04 14:15:29 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:29 volumio volumio[1057]: [SpotifyConnect] Currently active: volspotconnect2 Oct 04 14:15:29 volumio volumio[1057]: [SpotifyConnect] Pushing new state :: true Oct 04 14:15:29 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:29 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:29 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:29 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] Sink released Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:30 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] Device palyback is inactive Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] Device is paused Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] 0 Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] Currently active: volspotconnect2 Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] Pushing new state :: true Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:30 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] Device palyback is inactive Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] Device is paused Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] play Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] Man in the Long Black Coat Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] Pushing metadata Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] Currently active: volspotconnect2 Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] Pushing new state :: true Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:30 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] Sink acquired Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] Currently active: volspotconnect2 Oct 04 14:15:30 volumio volumio[1057]: [SpotifyConnect] Pushing new state :: true Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:30 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:30 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:36 volumio volumio[1057]: info: touch_display: Setting screensaver timeout to 0 seconds. Oct 04 14:15:36 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:36 volumio volumio[1057]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Oct 04 14:15:37 volumio volumio[1057]: (node:1057) UnhandledPromiseRejectionWarning Oct 04 14:15:37 volumio volumio[1057]: (node:1057) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1) Oct 04 14:15:37 volumio volumio[1057]: (node:1057) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code. Oct 04 14:15:37 volumio volumio[1057]: info: touch_display: Setting screensaver timeout to 0 seconds. Oct 04 14:15:37 volumio volumio[1057]: info: touch_display: Setting screensaver timeout to 120 seconds. Oct 04 14:15:37 volumio volumio[1057]: info: touch_display: Setting screensaver timeout to 0 seconds. Oct 04 14:15:46 volumio volumio[8543]: [Vollibrespot] : Event: Pause { track_id: SpotifyId { id: 253226767921418438364300463522807601691, audio_type: Track }, position_ms: 18424 } Oct 04 14:15:46 volumio volumio[1057]: [SpotifyConnect] pause Oct 04 14:15:46 volumio volumio[1057]: [SpotifyConnect] Man in the Long Black Coat Oct 04 14:15:46 volumio volumio[1057]: [SpotifyConnect] Pushing metadata Oct 04 14:15:46 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:46 volumio volumio[1057]: [SpotifyConnect] Currently active: volspotconnect2 Oct 04 14:15:46 volumio volumio[1057]: [SpotifyConnect] Pushing new state :: true Oct 04 14:15:46 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:46 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:46 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:46 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:46 volumio volumio[8543]: [Vollibrespot] : Event: SinkInactive Oct 04 14:15:46 volumio volumio[8543]: [Vollibrespot] : Event: PlaybackStopped { track_id: SpotifyId { id: 253226767921418438364300463522807601691, audio_type: Track } } Oct 04 14:15:47 volumio volumio[1057]: [SpotifyConnect] Sink released Oct 04 14:15:47 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:47 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:47 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:47 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:48 volumio volumio[1057]: [SpotifyConnect] Device palyback is inactive Oct 04 14:15:48 volumio volumio[1057]: [SpotifyConnect] Device is paused Oct 04 14:15:49 volumio volumio[8543]: [Vollibrespot] : Event: SessionInactive { became_inactive_at: 1728051349052 } Oct 04 14:15:49 volumio volumio[8543]: [Vollibrespot] : Event: PlaybackStopped { track_id: SpotifyId { id: 253226767921418438364300463522807601691, audio_type: Track } } Oct 04 14:15:49 volumio volumio[1057]: [SpotifyConnect] Connect Session has ended Oct 04 14:15:49 volumio volumio[1057]: [SpotifyConnect] Relinquishing Volumio State Oct 04 14:15:49 volumio volumio[1057]: verbose: UNSET VOLATILE Oct 04 14:15:49 volumio volumio[1057]: [SpotifyConnect] unSetVolatile called Oct 04 14:15:49 volumio volumio[1057]: [SpotifyConnect] Relinquishing Volumio State to another service Oct 04 14:15:49 volumio volumio[1057]: [SpotifyConnect] Received stop Oct 04 14:15:49 volumio volumio[1057]: info: CoreStateMachine::resetVolumioState Oct 04 14:15:49 volumio volumio[1057]: info: CoreStateMachine::getcurrentVolume Oct 04 14:15:49 volumio volumio[1057]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 14:15:49 volumio volumio[1057]: [SpotifyConnect] Device palyback is inactive Oct 04 14:15:49 volumio volumio[1057]: [SpotifyConnect] Device is paused Oct 04 14:15:49 volumio volumio[1057]: info: touch_display: Setting screensaver timeout to 120 seconds. Oct 04 14:15:49 volumio volumio[1057]: info: VolumeController:: Volume=100 Mute =false Oct 04 14:15:49 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:49 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Oct 04 14:15:49 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:49 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:49 volumio volumio[1057]: info: CoreStateMachine::updateTrackBlock Oct 04 14:15:49 volumio volumio[1057]: info: CorePlayQueue::getTrackBlock Oct 04 14:15:49 volumio volumio[1057]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 14:15:49 volumio volumio[8543]: [Vollibrespot] : Pause Oct 04 14:15:50 volumio volumio[1057]: [SpotifyConnect] Pause Oct 04 14:15:50 volumio volumio[1057]: info: VolumeController:: Volume=100 Mute =false Oct 04 14:15:50 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:50 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Oct 04 14:15:50 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:50 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:57 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:57 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Oct 04 14:15:57 volumio volumio[1057]: info: Currently active: mpd Oct 04 14:15:57 volumio volumio[1057]: info: Stopping currently active service Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::volumioStop Oct 04 14:15:57 volumio volumio[1057]: info: CoreStateMachine::stop Oct 04 14:15:57 volumio volumio[1057]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 04 14:15:57 volumio volumio[1057]: verbose: UNSET VOLATILE Oct 04 14:15:57 volumio volumio[1057]: info: TidalConnect Active Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:15:57 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Oct 04 14:15:57 volumio volumio[1057]: info: Currently active: mpd Oct 04 14:15:57 volumio volumio[1057]: info: Setting Volatile state to tidalconnect Oct 04 14:15:57 volumio volumio[1057]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:57 volumio vtcs[1624]: [2024-10-04 14:15:57.499] [tisoc] [warning] [PlaybackControllerImpl.cpp:472] Illegal state:1 Oct 04 14:15:57 volumio volumio[1057]: info: Pushing metadata Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:15:57 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:16:00 volumio vtcs[1624]: [2024-10-04 14:16:00.162] [tisoc] [warning] [logger.cpp:22] [audio_worker.cpp:326] Attempting to initialize a decoder without initial data! Oct 04 14:16:00 volumio vtcs[1624]: VTCS: PCM: plughw:2,0 RATE: 44100 FORMAT: S16_LE CHANNELS: 2 PERIODSIZE: 4096 BUFFERSIZE: 32768 Oct 04 14:16:02 volumio volumio[1057]: info: Pushing metadata Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:16:02 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:16:08 volumio volumio[1057]: info: touch_display: Setting screensaver timeout to 0 seconds. Oct 04 14:16:29 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Oct 04 14:16:29 volumio volumio[1057]: info: CoreStateMachine::pushState Oct 04 14:16:29 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Oct 04 14:16:29 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 14:16:30 volumio volumio[1057]: info: touch_display: Setting screensaver timeout to 120 seconds. Oct 04 14:16:33 volumio volumio[8543]: [Vollibrespot] : Event: SessionActive { became_active_at: 1728051393066 } Oct 04 14:16:33 volumio volumio[8543]: [Vollibrespot] : SessionActive! Oct 04 14:16:33 volumio volumio[8543]: [Vollibrespot] : Fetching autoplay context uri Oct 04 14:16:33 volumio volumio[8543]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 253226767921418438364300463522807601691, audio_type: Track } } Oct 04 14:16:33 volumio volumio[8543]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 253226767921418438364300463522807601691, audio_type: Track } } Oct 04 14:16:33 volumio volumio[1057]: [SpotifyConnect] A connect session has begun Oct 04 14:16:33 volumio volumio[8543]: [Vollibrespot] : error 400 for uri hm://autoplay-enabled/query?uri=spotify:search:bob+dylan+lon Oct 04 14:16:33 volumio volumio[8543]: [Vollibrespot] : AutoplayError: MercuryError Oct 04 14:16:33 volumio volumio[8543]: [Vollibrespot] : Loading with Spotify URI Oct 04 14:16:33 volumio volumio[8543]: [Vollibrespot] : Event: GotToken { token: Token { access_token: "BQDG0HxcEpkIdMxoZKhcZKdm2k1hKOn-HKRiv3wZK-uR4hN1apDL-v6aURgLZuJzf7WRGPiAi6l1hTsMWepoQn_vBZq92T5bubGjIGKCFZbP7tJImQrOcVZ6K2kvfUK55X6c10E99tdgwbmUXlfi9P-SYwJ2h-9MUsiN4ooFR6-QJTcAIBr4hDV52mDyvuvFBx-MOciiHgl39ZUgRsDRAmcUrel_VC7TuQ", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } } Oct 04 14:16:33 volumio volumio[1057]: [SpotifyConnect] Device palyback is active! Oct 04 14:16:33 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Oct 04 14:16:33 volumio volumio[1057]: [SpotifyConnect] Currently active: tidalconnect Oct 04 14:16:33 volumio volumio[1057]: [SpotifyConnect] Stopping currently active service Oct 04 14:16:33 volumio volumio[1057]: info: CoreCommandRouter::volumioStop Oct 04 14:16:33 volumio volumio[1057]: info: CoreStateMachine::stop Oct 04 14:16:33 volumio volumio[1057]: info: CoreStateMachine::serviceStop Oct 04 14:16:33 volumio volumio[1057]: info: CoreCommandRouter::serviceStop Oct 04 14:16:33 volumio volumio[1057]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 04 14:16:33 volumio volumio[1057]: TypeError: Cannot read property 'then' of undefined Oct 04 14:16:33 volumio volumio[1057]: at SpotConnEvents.SpotConn.on (/data/plugins/music_service/volspotconnect2/index.js:143:23) Oct 04 14:16:33 volumio volumio[1057]: at emitNone (events.js:106:13) Oct 04 14:16:33 volumio volumio[1057]: at SpotConnEvents.emit (events.js:208:7) Oct 04 14:16:33 volumio volumio[1057]: at SpotConnEvents.parseData (/data/plugins/music_service/volspotconnect2/SpotConnController.js:73:16) Oct 04 14:16:33 volumio volumio[1057]: at Socket.SpotConnEvents._udpsource.on.msg (/data/plugins/music_service/volspotconnect2/SpotConnController.js:15:12) Oct 04 14:16:33 volumio volumio[1057]: at emitTwo (events.js:126:13) Oct 04 14:16:33 volumio volumio[1057]: at Socket.emit (events.js:214:7) Oct 04 14:16:33 volumio volumio[1057]: at UDP.onMessage [as onmessage] (dgram.js:659:8) Oct 04 14:16:33 volumio volumio[1057]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 04 14:16:33 volumio vtcs[1624]: [2024-10-04 14:16:33] [info] asio async_shutdown error: asio.misc:2 (End of file) Oct 04 14:16:33 volumio volumio[8543]: [Vollibrespot] : (273200 ms) loaded Oct 04 14:16:33 volumio volumio[8543]: [Vollibrespot] : Event: PlaybackStopped { track_id: SpotifyId { id: 253226767921418438364300463522807601691, audio_type: Track } } Oct 04 14:16:33 volumio sudo[8834]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-04 14:15 Oct 04 14:16:33 volumio sudo[8834]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 8 (jessie)" NAME="Raspbian GNU/Linux" VERSION_ID="8" VERSION="8 (jessie)" 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="dd2a4339faaeb892c7f467e7dc8d424aefb0bd03" VOLUMIO_FE_VERSION="958dedc0edff114f244fa9acc70cf53089d9e5ae" VOLUMIO_BE_VERSION="fd3e37ffec12db034ec93f94dbc26e5495d5b91a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed Oct 6 12:34:49 CEST 2021" VOLUMIO_VERSION="2.917" VOLUMIO_HARDWARE="pi" VOLUMIO_HASH="98c8f08c531a6f0456f17ab17795e35f"