-- Logs begin at Wed 2024-04-24 16:14:25 UTC, end at Wed 2024-05-01 15:56:31 UTC. -- May 01 15:55:02 volumio-namai wpa_supplicant[1063]: wlan0: Failed to initiate sched scan May 01 15:55:10 volumio-namai wpa_supplicant[1063]: wlan0: Failed to initiate sched scan May 01 15:55:17 volumio-namai wpa_supplicant[1063]: wlan0: Failed to initiate sched scan May 01 15:55:25 volumio-namai wpa_supplicant[1063]: wlan0: Failed to initiate sched scan May 01 15:55:33 volumio-namai wpa_supplicant[1063]: wlan0: Failed to initiate sched scan May 01 15:55:41 volumio-namai wpa_supplicant[1063]: wlan0: Failed to initiate sched scan May 01 15:55:49 volumio-namai wpa_supplicant[1063]: wlan0: Failed to initiate sched scan May 01 15:55:56 volumio-namai wpa_supplicant[1063]: wlan0: Failed to initiate sched scan May 01 15:56:02 volumio-namai volumio[1305]: info: CoreCommandRouter::volumioGetQueue May 01 15:56:02 volumio-namai volumio[1305]: info: CoreStateMachine::getQueue May 01 15:56:02 volumio-namai volumio[1305]: info: CorePlayQueue::getQueue May 01 15:56:04 volumio-namai wpa_supplicant[1063]: wlan0: Failed to initiate sched scan May 01 15:56:05 volumio-namai vtcs[1652]: [2024-05-01 15:56:05] [error] handle_read_frame error: asio.system:104 (Connection reset by peer) May 01 15:56:05 volumio-namai vtcs[1652]: [2024-05-01 15:56:05] [info] asio async_shutdown error: asio.system:32 (Broken pipe) May 01 15:56:05 volumio-namai volumio[1305]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 01 15:56:05 volumio-namai volumio[1305]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 01 15:56:05 volumio-namai volumio[1305]: info: Discovery: Getting this device information May 01 15:56:05 volumio-namai volumio[1305]: info: CoreCommandRouter::volumioGetState May 01 15:56:05 volumio-namai volumio[1305]: info: CoreCommandRouter::executeOnPlugin: network , getCachedPAddresses May 01 15:56:05 volumio-namai volumio[1305]: info: CoreCommandRouter::executeOnPlugin: system , getConf May 01 15:56:05 volumio-namai volumio[1305]: info: CoreCommandRouter::executeOnPlugin: system , getConf May 01 15:56:06 volumio-namai volumio[1305]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 01 15:56:06 volumio-namai volumio[1305]: info: CoreCommandRouter::executeOnPlugin: my_volumio , detectVolumioHardware May 01 15:56:06 volumio-namai volumio[1305]: xcb_connection_has_error() returned true May 01 15:56:08 volumio-namai volumio[1305]: info: Tunnel connection is inactive, restarting it May 01 15:56:08 volumio-namai volumio[1305]: info: Starting Tunnel 1 May 01 15:56:08 volumio-namai volumio[1305]: info: Starting Tunnel Connection Checker May 01 15:56:08 volumio-namai sudo[2276]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service May 01 15:56:08 volumio-namai sudo[2276]: pam_unix(sudo:session): session opened for user root by (uid=0) May 01 15:56:08 volumio-namai systemd[1]: Stopping MyVolumio SSH Tunnel... May 01 15:56:08 volumio-namai autossh[1567]: received signal to exit (15) May 01 15:56:08 volumio-namai systemd[1]: Starting MyVolumio SSH Tunnel... May 01 15:56:08 volumio-namai systemd[1]: Started MyVolumio SSH Tunnel. May 01 15:56:08 volumio-namai sudo[2276]: pam_unix(sudo:session): session closed for user root May 01 15:56:08 volumio-namai volumio[1305]: ------------------------------------ BT MESSAGE: BT STATUS: running May 01 15:56:08 volumio-namai volumio[1305]: BT PLUGIN MESSAGE: Playing: false May 01 15:56:08 volumio-namai volumio[1305]: BT PLUGIN MESSAGE: VOLATILE: tidalconnect May 01 15:56:08 volumio-namai volumio[1305]: BT PLUGIN MESSAGE: STATE:undefined May 01 15:56:08 volumio-namai volumio[1305]: ------------------------------------ BT MESSAGE: BT STATUS: waiting May 01 15:56:08 volumio-namai volumio[1305]: BT PLUGIN MESSAGE: Playing: false May 01 15:56:08 volumio-namai autossh[2285]: port set to 0, monitoring disabled May 01 15:56:08 volumio-namai autossh[2285]: starting ssh (count 1) May 01 15:56:08 volumio-namai autossh[2285]: ssh child pid is 2289 May 01 15:56:08 volumio-namai volumio[1305]: BT PLUGIN MESSAGE: VOLATILE: tidalconnect May 01 15:56:08 volumio-namai volumio[1305]: BT PLUGIN MESSAGE: STATE:undefined May 01 15:56:08 volumio-namai volumio[1305]: info: Remote SSH Started May 01 15:56:08 volumio-namai volumio[1305]: info: CoreCommandRouter::volumioGetState May 01 15:56:11 volumio-namai volumiossh-tunnel[2282]: Warning: Permanently added '[eu4.myvolumio.org]:2222,[167.172.103.77]:2222' (RSA) to the list of known hosts. May 01 15:56:12 volumio-namai wpa_supplicant[1063]: wlan0: Failed to initiate sched scan May 01 15:56:14 volumio-namai volumio[1305]: info: Downloading plugin at http://plugins.volumio.org/plugins/volumio/armhf/music_service/spop/spop.zip May 01 15:56:16 volumio-namai volumio[1305]: info: END DOWNLOAD: http://plugins.volumio.org/plugins/volumio/armhf/music_service/spop/spop.zip May 01 15:56:16 volumio-namai volumio[1305]: info: Folder /tmp/plugins removed May 01 15:56:17 volumio-namai volumio[1305]: info: Checking if plugin already exists May 01 15:56:17 volumio-namai volumio[1305]: info: Rename folder May 01 15:56:17 volumio-namai volumio[1305]: info: Folder /tmp/downloaded_plugin.zip removed May 01 15:56:17 volumio-namai volumio[1305]: info: Move to category May 01 15:56:19 volumio-namai volumio[1305]: info: Checking if install.sh is present May 01 15:56:19 volumio-namai volumio[1305]: info: Executing install.sh May 01 15:56:20 volumio-namai sudo[2342]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/music_service/spop/install.sh May 01 15:56:20 volumio-namai sudo[2342]: pam_unix(sudo:session): session opened for user root by (uid=0) May 01 15:56:20 volumio-namai volumio[1305]: info: Writing systemd unit May 01 15:56:20 volumio-namai sudo[2342]: pam_unix(sudo:session): session closed for user root May 01 15:56:20 volumio-namai volumio[1305]: info: Setting permissions May 01 15:56:20 volumio-namai wpa_supplicant[1063]: wlan0: Failed to initiate sched scan May 01 15:56:20 volumio-namai volumio[1305]: info: Writing startconnect unit May 01 15:56:20 volumio-namai volumio[1305]: Plugin install end detected on script May 01 15:56:20 volumio-namai volumio[1305]: info: Install script completed May 01 15:56:20 volumio-namai volumio[1305]: info: Adding reference to registry May 01 15:56:20 volumio-namai volumio[1305]: info: Done installing plugin. May 01 15:56:20 volumio-namai volumio[1305]: info: Folder /tmp/plugins removed May 01 15:56:20 volumio-namai volumio[1305]: info: Folder /tmp/downloaded_plugin.zip removed May 01 15:56:20 volumio-namai volumio[1305]: info: Folder /data/temp removed May 01 15:56:21 volumio-namai volumio[1305]: info: Enabling plugin spop May 01 15:56:21 volumio-namai volumio[1305]: info: Loading plugin "spop"... May 01 15:56:22 volumio-namai volumio[1305]: info: PLUGIN START: spop May 01 15:56:22 volumio-namai volumio[1305]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 01 15:56:22 volumio-namai volumio[1305]: [SpotifyConnect] Creating VLS config file May 01 15:56:22 volumio-namai volumio[1305]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 01 15:56:22 volumio-namai volumio[1305]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 01 15:56:22 volumio-namai volumio[1305]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 01 15:56:22 volumio-namai sudo[2362]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/hosts May 01 15:56:22 volumio-namai volumio[1305]: [SpotifyConnect] Starting metadata listener May 01 15:56:22 volumio-namai sudo[2362]: pam_unix(sudo:session): session opened for user root by (uid=0) May 01 15:56:22 volumio-namai sudo[2362]: pam_unix(sudo:session): session closed for user root May 01 15:56:22 volumio-namai sudo[2370]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volspotconnect.service May 01 15:56:22 volumio-namai sudo[2370]: pam_unix(sudo:session): session opened for user root by (uid=0) May 01 15:56:22 volumio-namai systemd[1]: Starting Volspotconnect2 Daemon... May 01 15:56:22 volumio-namai systemd[1]: Started Volspotconnect2 Daemon. May 01 15:56:22 volumio-namai sudo[2370]: pam_unix(sudo:session): session closed for user root May 01 15:56:22 volumio-namai volumio[2378]: vollibrespot v0.2.5 8922128 2022-05-31 (librespot 08d8bcc 2020-10-07) -- Built On 2022-07-11 May 01 15:56:22 volumio-namai volumio[2378]: Reading Config from "/tmp/volspotify.toml" May 01 15:56:22 volumio-namai volumio[2378]: [Vollibrespot] : Using Alsa backend with device: plughw:5 May 01 15:56:23 volumio-namai volumio[1305]: [SpotifyConnect] Vollibrespot Daemon service started! May 01 15:56:23 volumio-namai volumio[1305]: [Metrics] SpotifyConnect: 0s 115.43ms May 01 15:56:23 volumio-namai volumio[1305]: info: Done. May 01 15:56:23 volumio-namai volumio[1305]: info: Successfully fixed Spotify hosts May 01 15:56:23 volumio-namai volumio[2378]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Uncategorized, message: "No such device" } May 01 15:56:27 volumio-namai volumio[1305]: info: Checking Spotify Web API May 01 15:56:28 volumio-namai wpa_supplicant[1063]: wlan0: Failed to initiate sched scan May 01 15:56:29 volumio-namai volumio[2378]: [Vollibrespot] : Connecting to AP "ap-gew1.spotify.com:443" May 01 15:56:30 volumio-namai volumio[2378]: [Vollibrespot] : Authenticated as "93q7odrus0h7l6knee2glq0q7" ! May 01 15:56:30 volumio-namai volumio[2378]: [Vollibrespot] : Using alsa sink May 01 15:56:30 volumio-namai volumio[2378]: [Vollibrespot] : Metadata pipe established May 01 15:56:30 volumio-namai volumio[2378]: [Vollibrespot] : Country: "LT" May 01 15:56:30 volumio-namai volumio[2378]: [Vollibrespot] : Event: Volume { volume_to_mixer: 32768 } May 01 15:56:30 volumio-namai volumio[1305]: [SpotifyConnect] Volume Spotify: 50.000762951094835 Volumio: 50 May 01 15:56:31 volumio-namai volumio[2378]: [Vollibrespot] : Event: SessionActive { became_active_at: 1714578991105 } May 01 15:56:31 volumio-namai volumio[2378]: [Vollibrespot] : SessionActive! May 01 15:56:31 volumio-namai volumio[1305]: [SpotifyConnect] A connect session has begun May 01 15:56:31 volumio-namai volumio[1305]: info: Acquiring new spotify session May 01 15:56:31 volumio-namai volumio[1305]: info: CoreCommandRouter::volumioStop May 01 15:56:31 volumio-namai volumio[1305]: info: CoreStateMachine::stop May 01 15:56:31 volumio-namai volumio[1305]: info: CoreStateMachine::serviceStop May 01 15:56:31 volumio-namai volumio[1305]: info: CoreCommandRouter::serviceStop May 01 15:56:31 volumio-namai volumio[2378]: [Vollibrespot] : Fetching autoplay context uri May 01 15:56:31 volumio-namai volumio[2378]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 321554488295717880364504648136391137553, audio_type: Track } } May 01 15:56:31 volumio-namai volumio[2378]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 321554488295717880364504648136391137553, audio_type: Track } } May 01 15:56:31 volumio-namai volumio[1305]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 01 15:56:31 volumio-namai vtcs[1652]: [2024-05-01 15:56:31.112] [tisoc] [warning] [PlaybackControllerImpl.cpp:472] Illegal state:0 May 01 15:56:31 volumio-namai volumio[1305]: TypeError: Cannot read property 'then' of undefined May 01 15:56:31 volumio-namai volumio[1305]: at SpotConnEvents.SpotConn.on (/data/plugins/music_service/spop/index.js:2095:31) May 01 15:56:31 volumio-namai volumio[1305]: at emitNone (events.js:106:13) May 01 15:56:31 volumio-namai volumio[1305]: at SpotConnEvents.emit (events.js:208:7) May 01 15:56:31 volumio-namai volumio[1305]: at SpotConnEvents.parseData (/data/plugins/music_service/spop/SpotConnController.js:81:16) May 01 15:56:31 volumio-namai volumio[1305]: at Socket.SpotConnEvents._udpsource.on.msg (/data/plugins/music_service/spop/SpotConnController.js:15:12) May 01 15:56:31 volumio-namai volumio[1305]: at emitTwo (events.js:126:13) May 01 15:56:31 volumio-namai volumio[1305]: at Socket.emit (events.js:214:7) May 01 15:56:31 volumio-namai volumio[1305]: at UDP.onMessage [as onmessage] (dgram.js:659:8) May 01 15:56:31 volumio-namai volumio[1305]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 01 15:56:31 volumio-namai volumio[2378]: [Vollibrespot] : error 400 for uri hm://autoplay-enabled/query?uri=spotify:search:m%C4%97lynas+aut May 01 15:56:31 volumio-namai volumio[2378]: [Vollibrespot] : AutoplayError: MercuryError May 01 15:56:31 volumio-namai volumio[2378]: [Vollibrespot] : Event: GotToken { token: Token { access_token: "BQB6QI6Frzi64iMB6WJyiiaZi563xZpsuknoDIu7e7LKTl870GS1HihKV69yPW9o_RPDDMMopSlxCXJRu-c5WGJl-Rqo6ZbZ1vSZLPOOY37AOwE4wJnpEutbeUlVV5Awy7t8Kf2P0P26iMBLJYka5C4focm9MOZOcLu-RY2NHoa4jVJTvT8VlDs8TWdPGraiiNSEPLXNEGRVbmeMJo2uWWcHIg", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } } May 01 15:56:31 volumio-namai volumio[2378]: [Vollibrespot] : Loading with Spotify URI May 01 15:56:31 volumio-namai sudo[2417]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-05-01 15:55 May 01 15:56:31 volumio-namai sudo[2417]: 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"