-- Logs begin at Thu 2019-02-14 10:11:59 UTC, end at Fri 2024-05-10 19:42:39 UTC. -- May 10 19:42:24 volumio ntpd[733]: receive: Unexpected origin timestamp 0xe9a30710.69d7fecf does not match aorg 0000000000.00000000 from server@5.1.73.50 xmt 0xe9e8f720.9efec6e6 May 10 19:42:24 volumio ntpd[733]: receive: Unexpected origin timestamp 0xe9a30710.69c96831 does not match aorg 0000000000.00000000 from server@162.159.200.123 xmt 0xe9e8f720.9e7c3e21 May 10 19:42:24 volumio ntpd[733]: receive: Unexpected origin timestamp 0xe9a30710.69da430d does not match aorg 0000000000.00000000 from server@213.239.234.28 xmt 0xe9e8f720.9f67d8ff May 10 19:42:24 volumio ntpd[733]: receive: Unexpected origin timestamp 0xe9a30710.69d5a394 does not match aorg 0000000000.00000000 from server@176.9.90.88 xmt 0xe9e8f720.9f80b5d1 May 10 19:42:24 volumio ntpd[733]: receive: Unexpected origin timestamp 0xe9a30710.69e0d214 does not match aorg 0000000000.00000000 from server@194.95.183.208 xmt 0xe9e8f720.9fdef1c3 May 10 19:42:24 volumio ntpd[733]: receive: Unexpected origin timestamp 0xe9a30710.69d34e6e does not match aorg 0000000000.00000000 from server@80.153.195.191 xmt 0xe9e8f720.9fa139ca May 10 19:42:24 volumio systemd[1]: Starting Daily apt download activities... May 10 19:42:24 volumio ntpd[733]: receive: Unexpected origin timestamp 0xe9a30710.69dc6106 does not match aorg 0000000000.00000000 from server@161.97.164.152 xmt 0xe9e8f720.a797e47a May 10 19:42:27 volumio volumio[683]: info: Loading plugin "outputs"... May 10 19:42:27 volumio volumio[683]: info: Loading plugin "albumart"... May 10 19:42:28 volumio volumio[683]: info: Plugin example_plugin is not enabled May 10 19:42:28 volumio volumio[683]: info: Loading plugin "inputs"... May 10 19:42:28 volumio volumio[683]: info: Loading plugin "updater_comm"... May 10 19:42:28 volumio volumio[683]: info: Plugin mpdemulation is not enabled May 10 19:42:28 volumio volumio[683]: info: Loading plugin "rest_api"... May 10 19:42:28 volumio volumio[683]: info: Loading plugin "websocket"... May 10 19:42:28 volumio volumio[683]: info: Loading i18n strings for locale de May 10 19:42:28 volumio volumio[683]: Updating browse sources language May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::initPlayerControls May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 10 19:42:28 volumio volumio[683]: Express server listening on port 3000 May 10 19:42:28 volumio volumio[683]: [Metrics] WebUI: 13s 193.90ms May 10 19:42:28 volumio volumio[683]: info: CoreStateMachine::resetVolumioState May 10 19:42:28 volumio volumio[683]: info: CoreStateMachine::getcurrentVolume May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::volumioRetrievevolume May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 10 19:42:28 volumio volumio[683]: Forking 3 albumart workers May 10 19:42:28 volumio volumio[683]: info: MPD Permissions set May 10 19:42:28 volumio volumio[683]: info: MPD running with PID810 May 10 19:42:28 volumio volumio[683]: ,establishing connection May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 10 19:42:28 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:28 volumio volumio[683]: info: Reloading queue from file May 10 19:42:28 volumio volumio[683]: error: updateQueue error: null May 10 19:42:28 volumio volumio[683]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 10 19:42:28 volumio volumio[683]: info: VolumeController:: Volume=87 Mute =false May 10 19:42:28 volumio volumio[683]: info: CoreStateMachine::pushState May 10 19:42:29 volumio volumio[683]: info: CorePlayQueue::getTrack 0 May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::volumioPushState May 10 19:42:29 volumio volumio[683]: info: CoreStateMachine::updateTrackBlock May 10 19:42:29 volumio volumio[683]: info: CorePlayQueue::getTrackBlock May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::volumioRetrievevolume May 10 19:42:29 volumio volumio[683]: info: Setting Device type: Raspberry PI May 10 19:42:29 volumio volumio[683]: info: CoreStateMachine::setRepeat null single undefined May 10 19:42:29 volumio volumio[683]: info: CoreStateMachine::pushState May 10 19:42:29 volumio volumio[683]: info: CorePlayQueue::getTrack 0 May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::volumioPushState May 10 19:42:29 volumio volumio[683]: info: CoreStateMachine::setRandom null May 10 19:42:29 volumio volumio[683]: info: CoreStateMachine::pushState May 10 19:42:29 volumio volumio[683]: info: CorePlayQueue::getTrack 0 May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::volumioPushState May 10 19:42:29 volumio volumio[683]: info: mDNS: A device disapperared from network May 10 19:42:29 volumio volumio[683]: info: mDNS Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined May 10 19:42:29 volumio volumio[683]: error: updateQueue error: null May 10 19:42:29 volumio volumio[683]: info: Completed loading Core Plugins May 10 19:42:29 volumio volumio[683]: info: Preparing to generate the ALSA configuration file May 10 19:42:29 volumio volumio[683]: info: Discovery: adding cdc7bd78-a44b-4cad-8fce-588bcb8db153 May 10 19:42:29 volumio volumio[683]: info: mDNS: Found device Volumio May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::volumioGetState May 10 19:42:29 volumio volumio[683]: info: CorePlayQueue::getTrack 0 May 10 19:42:29 volumio volumio[683]: info: VolumeController:: Volume=87 Mute =false May 10 19:42:29 volumio volumio[683]: info: CoreStateMachine::pushState May 10 19:42:29 volumio volumio[683]: info: CorePlayQueue::getTrack 0 May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::volumioPushState May 10 19:42:29 volumio volumio[683]: info: Discovery: this is already registered, cdc7bd78-a44b-4cad-8fce-588bcb8db153 May 10 19:42:29 volumio volumio[683]: info: mDNS: Found device Volumio May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::volumioGetState May 10 19:42:29 volumio volumio[683]: info: CorePlayQueue::getTrack 0 May 10 19:42:29 volumio volumio[683]: info: Asound.conf file unchanged, so no further update is needed May 10 19:42:29 volumio volumio[683]: info: Output device has changed, restarting MPD May 10 19:42:29 volumio sudo[915]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 10 19:42:29 volumio sudo[915]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 19:42:29 volumio systemd[1]: apt-daily.service: Succeeded. May 10 19:42:29 volumio systemd[1]: Started Daily apt download activities. May 10 19:42:29 volumio systemd[1]: Starting Daily apt upgrade and clean activities... May 10 19:42:29 volumio volumio[683]: info: Output device has changed, restarting Shairport Sync May 10 19:42:29 volumio sudo[915]: pam_unix(sudo:session): session closed for user root May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 10 19:42:29 volumio sudo[919]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 10 19:42:29 volumio sudo[919]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 19:42:29 volumio systemd[1]: Stopping Music Player Daemon... May 10 19:42:29 volumio volumio[683]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 10 19:42:29 volumio volumio[683]: info: ___________ START PLUGINS ___________ May 10 19:42:29 volumio systemd[1]: mpd.service: Succeeded. May 10 19:42:29 volumio systemd[1]: Stopped Music Player Daemon. May 10 19:42:29 volumio systemd[1]: Starting Music Player Daemon... May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 10 19:42:29 volumio volumio[683]: info: [1715370149630] CoreMusicLibrary::Adding element Media Servers May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 10 19:42:29 volumio volumio[683]: Cannot find translation for sourceMedia Servers May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 10 19:42:29 volumio volumio[683]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:29 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 10 19:42:30 volumio volumio[683]: Starting albumart workers May 10 19:42:30 volumio volumio[683]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 10 19:42:30 volumio volumio[683]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 10 19:42:30 volumio volumio[683]: info: [1715370150059] CoreMusicLibrary::Adding element Last_100 May 10 19:42:30 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 10 19:42:30 volumio volumio[683]: Cannot find translation for sourceMedia Servers May 10 19:42:30 volumio volumio[683]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 10 19:42:30 volumio volumio[683]: info: [1715370150065] CoreMusicLibrary::Adding element Webradio May 10 19:42:30 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 10 19:42:30 volumio volumio[683]: Cannot find translation for sourceMedia Servers May 10 19:42:30 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 10 19:42:30 volumio volumio[683]: Starting albumart workers May 10 19:42:30 volumio volumio[683]: Starting albumart workers May 10 19:42:30 volumio volumio[683]: info: Creating Spotify config file May 10 19:42:30 volumio volumio[683]: info: Volumio Calling Home May 10 19:42:30 volumio volumio[683]: info: Completed starting Core Plugins May 10 19:42:30 volumio volumio[683]: info: ------------------------------------------- May 10 19:42:30 volumio volumio[683]: info: ----- MyVolumio plugins startup ---- May 10 19:42:30 volumio volumio[683]: info: ------------------------------------------- May 10 19:42:30 volumio volumio[683]: info: [MyVolumio PluginManager] Fetching plans data.... May 10 19:42:30 volumio volumio[683]: info: MPD Permissions set May 10 19:42:30 volumio volumio[683]: info: Volumio called home May 10 19:42:30 volumio volumio[683]: info: Spotify config file written May 10 19:42:30 volumio volumio[683]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 1 May 10 19:42:30 volumio sudo[955]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 10 19:42:30 volumio sudo[955]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 19:42:30 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:30 volumio systemd[1]: Started go-librespot Daemon. May 10 19:42:30 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:30 volumio go-librespot[960]: Librespot-go daemon starting... May 10 19:42:30 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:30 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:30 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:30 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:30 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:30 volumio sudo[955]: pam_unix(sudo:session): session closed for user root May 10 19:42:30 volumio sudo[958]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 10 19:42:30 volumio sudo[958]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 19:42:30 volumio sudo[958]: pam_unix(sudo:session): session closed for user root May 10 19:42:30 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 10 19:42:30 volumio volumio[683]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 19:42:30 volumio sudo[964]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 10 19:42:30 volumio sudo[964]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 19:42:30 volumio sudo[964]: pam_unix(sudo:session): session closed for user root May 10 19:42:31 volumio volumio[683]: info: Starting Shairport Sync May 10 19:42:31 volumio volumio[683]: info: Starting Shairport Sync May 10 19:42:31 volumio go-librespot[960]: time="2024-05-10T19:42:31Z" level=info msg="generated new device id: c86db0b09d2147129766004c798393ae6a3b182d" May 10 19:42:31 volumio volumio[683]: info: Starting Shairport Sync May 10 19:42:31 volumio mpd[947]: May 10 19:42 : exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 10 19:42:31 volumio mpd[947]: May 10 19:42 : exception: Input plugin 'tidal' is unavailable: No Tidal application token configured May 10 19:42:31 volumio mpd[947]: May 10 19:42 : exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured May 10 19:42:31 volumio systemd[1]: Started Music Player Daemon. May 10 19:42:31 volumio sudo[919]: pam_unix(sudo:session): session closed for user root May 10 19:42:31 volumio sudo[983]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 10 19:42:31 volumio sudo[983]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 19:42:31 volumio sudo[989]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 10 19:42:31 volumio sudo[995]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 10 19:42:31 volumio sudo[995]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 19:42:31 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 10 19:42:31 volumio systemd[1]: shairport-sync.service: Succeeded. May 10 19:42:31 volumio sudo[989]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 19:42:31 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 10 19:42:31 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 10 19:42:31 volumio sudo[983]: pam_unix(sudo:session): session closed for user root May 10 19:42:31 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 10 19:42:31 volumio systemd[1]: shairport-sync.service: Succeeded. May 10 19:42:31 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 10 19:42:31 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 10 19:42:31 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 10 19:42:31 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM May 10 19:42:31 volumio systemd[1]: shairport-sync.service: Succeeded. May 10 19:42:31 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 10 19:42:31 volumio sudo[995]: pam_unix(sudo:session): session closed for user root May 10 19:42:31 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 10 19:42:31 volumio sudo[989]: pam_unix(sudo:session): session closed for user root May 10 19:42:31 volumio volumio[683]: info: Shairport-Sync Started May 10 19:42:31 volumio volumio[683]: Error adding Membership: Error: addMembership EINVAL May 10 19:42:31 volumio volumio[683]: info: Shairport-Sync Started May 10 19:42:31 volumio volumio[683]: error: updateQueue error: null May 10 19:42:31 volumio sudo[1040]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 10 19:42:31 volumio sudo[1040]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 19:42:31 volumio volumio[683]: info: CoreCommandRouter::volumioGetState May 10 19:42:31 volumio volumio[683]: info: CorePlayQueue::getTrack 0 May 10 19:42:31 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. May 10 19:42:31 volumio systemd[1]: Started Daily apt upgrade and clean activities. May 10 19:42:31 volumio systemd[1]: Started UPnP Renderer front-end to MPD. May 10 19:42:31 volumio sudo[1040]: pam_unix(sudo:session): session closed for user root May 10 19:42:31 volumio volumio[683]: info: Upmpdcli Daemon Started May 10 19:42:32 volumio volumio[1048]: Generating RSA private key, 4096 bit long modulus (2 primes) May 10 19:42:32 volumio go-librespot[960]: time="2024-05-10T19:42:32Z" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" May 10 19:42:32 volumio go-librespot[960]: time="2024-05-10T19:42:32Z" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 10 19:42:32 volumio go-librespot[960]: time="2024-05-10T19:42:32Z" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 10 19:42:32 volumio go-librespot[960]: time="2024-05-10T19:42:32Z" level=debug msg="zeroconf server listening on port 43971" May 10 19:42:34 volumio volumio[683]: info: go-librespot daemon successfully initialized May 10 19:42:34 volumio go-librespot[960]: time="2024-05-10T19:42:34Z" level=debug msg="obtained new client token: AAC4+83OjiUyHCK0mDcHWBPK0hRnfpxBL7tRYykWp32d79B+WIhM7SmKz8UsRb0DJGSNXSYX8JetQqvWxPBTShE0yO8X0/N4CpPYcGk4GDL+rghx8j0PcGvhoUTXsno+OFf7j8l00/dLk/2i7XpJ8LazRKug9NtzTG78bEUR+SrpbKyIW7JQilbACod2JcF5SQ/iLxvbDyCB9iaYkolwavz2M7f6nCwVP83uoq63sGZ1KS8Tc/0o02PATmas" May 10 19:42:34 volumio go-librespot[960]: time="2024-05-10T19:42:34Z" level=debug msg="completed keyexchange" May 10 19:42:34 volumio go-librespot[960]: time="2024-05-10T19:42:34Z" level=debug msg="completed challenge" May 10 19:42:34 volumio go-librespot[960]: time="2024-05-10T19:42:34Z" level=debug msg="authenticated as 21wnqgu6rvuns4zudugmv3pni" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="authenticated as 21wnqgu6rvuns4zudugmv3pni" May 10 19:42:35 volumio systemd[1]: systemd-fsckd.service: Succeeded. May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="dealer connection opened" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=info msg="accepted zeroconf user 21wnqgu6rvuns4zudugmv3pni from iPhone" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="received connection id: NTMzZTViNzYtZjdhYy00NTFkLTljY2QtMGViOGIxOGFmZGFkK2RlYWxlcit0Y3A6Ly9nZXc0LWRlYWxlci1hLW1xcm4uZ2V3NC5zcG90aWZ5Lm5ldDo1NzAwK0JDNjY4OUEzREYyOTc3RUNFRkQwNkUwNEFGRjhCMkExQjBBNTI0MEFGOUY3NEM2MDJCRTAwMEVDNUY1OTAxRUM=" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="put connect state because NEW_DEVICE" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="handling transfer player command from abd52638d876e9d487739a43f8ef40a5d7baccbf" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="loading track spotify:track:4j8zZZWeP6Ijn5oKLlfelE (paused: false, position: 202536ms)" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=trace msg="emitting websocket event: will_play" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:4j8zZZWeP6Ijn5oKLlfelE" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="requested aes key for file 526fe0c1325d8e4444e2abf96c5fbef358b5a8bc, gid: 4j8zZZWeP6Ijn5oKLlfelE" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1511" May 10 19:42:35 volumio go-librespot[960]: time="2024-05-10T19:42:35Z" level=debug msg="fetched first chunk of 18, total size is 9135576 bytes" May 10 19:42:36 volumio go-librespot[960]: time="2024-05-10T19:42:36Z" level=debug msg="fetched chunk 1/17, size: 524288" May 10 19:42:36 volumio volumio-remote-updater[449]: [2024-05-10 19:42:36] [connect] Successful connection May 10 19:42:36 volumio volumio[683]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 2 May 10 19:42:36 volumio volumio-remote-updater[449]: [2024-05-10 19:42:36] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1715370156 101 May 10 19:42:36 volumio go-librespot[960]: time="2024-05-10T19:42:36Z" level=debug msg="fetched chunk 3/17, size: 524288" May 10 19:42:36 volumio go-librespot[960]: time="2024-05-10T19:42:36Z" level=debug msg="fetched chunk 17/17, size: 222680" May 10 19:42:36 volumio go-librespot[960]: time="2024-05-10T19:42:36Z" level=debug msg="fetched chunk 2/17, size: 524288" May 10 19:42:36 volumio go-librespot[960]: time="2024-05-10T19:42:36Z" level=trace msg="seek to 202536ms (diff: 80ms, samples: 8931837, bytes: 9049649)" May 10 19:42:36 volumio go-librespot[960]: time="2024-05-10T19:42:36Z" level=info msg="loaded track \"Schatzi schenk mir ein Foto\" (uri: spotify:track:4j8zZZWeP6Ijn5oKLlfelE, paused: false, position: 202536ms, duration: 204666ms)" May 10 19:42:36 volumio go-librespot[960]: time="2024-05-10T19:42:36Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 10 19:42:36 volumio go-librespot[960]: time="2024-05-10T19:42:36Z" level=trace msg="emitting websocket event: metadata" May 10 19:42:36 volumio go-librespot[960]: time="2024-05-10T19:42:36Z" level=trace msg="emitting websocket event: active" May 10 19:42:36 volumio go-librespot[960]: time="2024-05-10T19:42:36Z" level=debug msg="sending successful reply for delaer request" May 10 19:42:36 volumio go-librespot[960]: time="2024-05-10T19:42:36Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 10 19:42:36 volumio go-librespot[960]: time="2024-05-10T19:42:36Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 10 19:42:36 volumio go-librespot[960]: time="2024-05-10T19:42:36Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 10 19:42:36 volumio go-librespot[960]: time="2024-05-10T19:42:36Z" level=trace msg="emitting websocket event: playing" May 10 19:42:37 volumio volumio[683]: info: Initializing connection to go-librespot Websocket May 10 19:42:37 volumio go-librespot[960]: time="2024-05-10T19:42:37Z" level=debug msg="new websocket client" May 10 19:42:37 volumio volumio[683]: info: Connection to go-librespot Websocket established May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=trace msg="emitting websocket event: not_playing" May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=debug msg="loading track spotify:track:4j8zZZWeP6Ijn5oKLlfelE (paused: false, position: 0ms)" May 10 19:42:38 volumio volumio[683]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:4j8zZZWeP6Ijn5oKLlfelE","play_origin":"unknown"}} May 10 19:42:38 volumio volumio[683]: error: Failed to decode event: not_playing May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=trace msg="emitting websocket event: will_play" May 10 19:42:38 volumio volumio[683]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4j8zZZWeP6Ijn5oKLlfelE","play_origin":"unknown"}} May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:4j8zZZWeP6Ijn5oKLlfelE" May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=debug msg="requested aes key for file 526fe0c1325d8e4444e2abf96c5fbef358b5a8bc, gid: 4j8zZZWeP6Ijn5oKLlfelE" May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=debug msg="fetched first chunk of 18, total size is 9135576 bytes" May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=info msg="loaded track \"Schatzi schenk mir ein Foto\" (uri: spotify:track:4j8zZZWeP6Ijn5oKLlfelE, paused: false, position: 0ms, duration: 204666ms)" May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=trace msg="emitting websocket event: metadata" May 10 19:42:38 volumio volumio[683]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4j8zZZWeP6Ijn5oKLlfelE","name":"Schatzi schenk mir ein Foto","artist_names":["Mickie Krause"],"album_name":"Eins Plus Wie Immer","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0283c09e35e6b4a23947644956","position":0,"duration":204666}} May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=trace msg="emitting websocket event: playing" May 10 19:42:38 volumio volumio[683]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4j8zZZWeP6Ijn5oKLlfelE","play_origin":"unknown"}} May 10 19:42:38 volumio volumio[683]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 10 19:42:38 volumio volumio[683]: TypeError: Cannot read property 'service' of undefined May 10 19:42:38 volumio volumio[683]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:322:50) May 10 19:42:38 volumio volumio[683]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:248:18) May 10 19:42:38 volumio volumio[683]: at WebSocket.message (/data/plugins/music_service/spop/index.js:175:14) May 10 19:42:38 volumio volumio[683]: at WebSocket.emit (events.js:315:20) May 10 19:42:38 volumio volumio[683]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1192:20) May 10 19:42:38 volumio volumio[683]: at Receiver.emit (events.js:315:20) May 10 19:42:38 volumio volumio[683]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:560:14) May 10 19:42:38 volumio volumio[683]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:478:17) May 10 19:42:38 volumio volumio[683]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:22) May 10 19:42:38 volumio volumio[683]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:180:18 May 10 19:42:38 volumio volumio[683]: at internal/process/task_queues.js:149:7 May 10 19:42:38 volumio volumio[683]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) May 10 19:42:38 volumio volumio[683]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) May 10 19:42:38 volumio volumio[683]: at processTicksAndRejections (internal/process/task_queues.js:93:5) May 10 19:42:38 volumio volumio[683]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=debug msg="fetched chunk 1/17, size: 524288" May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=debug msg="fetched chunk 2/17, size: 524288" May 10 19:42:38 volumio go-librespot[960]: time="2024-05-10T19:42:38Z" level=debug msg="fetched chunk 3/17, size: 524288" May 10 19:42:39 volumio sudo[1075]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-05-10 19:41 May 10 19:42:39 volumio sudo[1075]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="543f2de901f774399af6eae9d76f06fe4162e5dd" VOLUMIO_FE_VERSION="175efecbf4f79404c553a8a73d0a8929ba9e68ab" VOLUMIO_FE3_VERSION="9cf29de04cd974cb1504bd8ef33d64f591b09aef" VOLUMIO_BE_VERSION="0bba7bb5721ae1c828390745b52735c56d7c014a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 13 Dec 2021 03:52:13 PM CET" VOLUMIO_VERSION="3.175" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="c1271baa6039839be7f5b1630f3422f4"