-- Logs begin at Thu 2019-02-14 10:11:58 UTC, end at Sat 2024-11-23 20:54:03 UTC. -- Nov 23 20:53:54 volumio-eddy ntpd[1195]: receive: Unexpected origin timestamp 0xeadc9dd6.819c32de does not match aorg 0000000000.00000000 from server@94.198.159.11 xmt 0xeaecbf62.d1b32f2c Nov 23 20:53:54 volumio-eddy ntpd[1195]: receive: Unexpected origin timestamp 0xeadc9dd6.81a0759b does not match aorg 0000000000.00000000 from server@86.80.166.233 xmt 0xeaecbf62.d213f4ca Nov 23 20:53:54 volumio-eddy ntpd[1195]: receive: Unexpected origin timestamp 0xeadc9dd6.819f4b49 does not match aorg 0000000000.00000000 from server@193.28.228.176 xmt 0xeaecbf62.d3624624 Nov 23 20:53:54 volumio-eddy systemd[1]: Starting Daily apt download activities... Nov 23 20:53:54 volumio-eddy systemd[1]: Starting Daily man-db regeneration... Nov 23 20:53:54 volumio-eddy ntpd[1195]: Soliciting pool server 213.239.154.12 Nov 23 20:53:54 volumio-eddy volumio[1230]: info: Discovery: adding 941b309f-3f40-4066-82ae-52a37fd351db Nov 23 20:53:54 volumio-eddy volumio[1230]: info: Discovery: Found device Volumio Eddy Nov 23 20:53:54 volumio-eddy volumio[1230]: info: CoreCommandRouter::volumioGetState Nov 23 20:53:54 volumio-eddy volumio[1230]: info: CorePlayQueue::getTrack 0 Nov 23 20:53:54 volumio-eddy volumio[1230]: info: Discovery: this is already registered, 941b309f-3f40-4066-82ae-52a37fd351db Nov 23 20:53:54 volumio-eddy volumio[1230]: info: Discovery: Found device Volumio Eddy Nov 23 20:53:54 volumio-eddy volumio[1230]: info: CoreCommandRouter::volumioGetState Nov 23 20:53:54 volumio-eddy volumio[1230]: info: CorePlayQueue::getTrack 0 Nov 23 20:53:54 volumio-eddy volumio[1230]: info: Volumio called home Nov 23 20:53:54 volumio-eddy volumio[1230]: info: MPD Permissions set Nov 23 20:53:54 volumio-eddy volumio[1230]: info: Spotify config file written Nov 23 20:53:54 volumio-eddy volumio[1230]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Nov 23 20:53:54 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 23 20:53:54 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 23 20:53:54 volumio-eddy ntpd[1195]: receive: Unexpected origin timestamp 0xeadc9dd6.8195ad08 does not match aorg 0000000000.00000000 from server@45.32.4.67 xmt 0xeaecbf62.e04333c4 Nov 23 20:53:54 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 23 20:53:54 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Nov 23 20:53:54 volumio-eddy sudo[1546]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 23 20:53:54 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 23 20:53:54 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 23 20:53:55 volumio-eddy sudo[1546]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 23 20:53:55 volumio-eddy systemd[1]: Started go-librespot Daemon. Nov 23 20:53:55 volumio-eddy sudo[1546]: pam_unix(sudo:session): session closed for user root Nov 23 20:53:55 volumio-eddy sudo[1568]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/hosts Nov 23 20:53:55 volumio-eddy systemd[1]: man-db.service: Succeeded. Nov 23 20:53:55 volumio-eddy systemd[1]: Started Daily man-db regeneration. Nov 23 20:53:55 volumio-eddy go-librespot[1570]: Librespot-go daemon starting... Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Discovery: A device disappeared from network Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Starting Shairport Sync Nov 23 20:53:55 volumio-eddy sudo[1568]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Starting Shairport Sync Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Starting Shairport Sync Nov 23 20:53:55 volumio-eddy sudo[1568]: pam_unix(sudo:session): session closed for user root Nov 23 20:53:55 volumio-eddy sudo[1583]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Discovery: A device disappeared from network Nov 23 20:53:55 volumio-eddy sudo[1587]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 23 20:53:55 volumio-eddy sudo[1592]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::volumioGetState Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CorePlayQueue::getTrack 0 Nov 23 20:53:55 volumio-eddy sudo[1583]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 23 20:53:55 volumio-eddy sudo[1587]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 23 20:53:55 volumio-eddy sudo[1592]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 23 20:53:55 volumio-eddy systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 23 20:53:55 volumio-eddy systemd[1]: shairport-sync.service: Succeeded. Nov 23 20:53:55 volumio-eddy systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 23 20:53:55 volumio-eddy go-librespot[1570]: time="2024-11-23T20:53:55Z" level=info msg="generated new device id: 10b9156a6cd0cc63b3316d38b7c094a4a1639db3" Nov 23 20:53:55 volumio-eddy systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Received Get System Info Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Discovery: Getting this device information Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::volumioGetState Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CorePlayQueue::getTrack 0 Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::volumioGetState Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CorePlayQueue::getTrack 0 Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::volumioGetVisibleSources Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::volumioGetState Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CorePlayQueue::getTrack 0 Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::volumioGetQueue Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreStateMachine::getQueue Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CorePlayQueue::getQueue Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Listing playlists Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Received Get System Info Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Discovery: Getting this device information Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::volumioGetState Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CorePlayQueue::getTrack 0 Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::volumioGetState Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CorePlayQueue::getTrack 0 Nov 23 20:53:55 volumio-eddy sudo[1583]: pam_unix(sudo:session): session closed for user root Nov 23 20:53:55 volumio-eddy systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 23 20:53:55 volumio-eddy systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Nov 23 20:53:55 volumio-eddy systemd[1]: shairport-sync.service: Succeeded. Nov 23 20:53:55 volumio-eddy systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 23 20:53:55 volumio-eddy systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 23 20:53:55 volumio-eddy sudo[1587]: pam_unix(sudo:session): session closed for user root Nov 23 20:53:55 volumio-eddy sudo[1592]: pam_unix(sudo:session): session closed for user root Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Successfully fixed Spotify hosts Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Shairport-Sync Started Nov 23 20:53:55 volumio-eddy volumio[1230]: Error adding Membership: Error: addMembership EINVAL Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Shairport-Sync Started Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Shairport-Sync Started Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Discovery: adding 941b309f-3f40-4066-82ae-52a37fd351db Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Discovery: Found device Volumio Eddy Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::volumioGetState Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CorePlayQueue::getTrack 0 Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Discovery: this is already registered, 941b309f-3f40-4066-82ae-52a37fd351db Nov 23 20:53:55 volumio-eddy volumio[1230]: info: Discovery: Found device Volumio Eddy Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CoreCommandRouter::volumioGetState Nov 23 20:53:55 volumio-eddy volumio[1230]: info: CorePlayQueue::getTrack 0 Nov 23 20:53:55 volumio-eddy ntpd[1195]: Soliciting pool server 185.45.112.121 Nov 23 20:53:55 volumio-eddy go-librespot[1570]: time="2024-11-23T20:53:55Z" 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-gew1.spotify.com:80]" Nov 23 20:53:55 volumio-eddy go-librespot[1570]: time="2024-11-23T20:53:55Z" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Nov 23 20:53:55 volumio-eddy go-librespot[1570]: time="2024-11-23T20:53:55Z" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Nov 23 20:53:55 volumio-eddy go-librespot[1570]: time="2024-11-23T20:53:55Z" level=debug msg="zeroconf server listening on port 36659" Nov 23 20:53:55 volumio-eddy systemd[1]: apt-daily.service: Succeeded. Nov 23 20:53:55 volumio-eddy systemd[1]: Started Daily apt download activities. Nov 23 20:53:55 volumio-eddy systemd[1]: Starting Daily apt upgrade and clean activities... Nov 23 20:53:56 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:56 volumio-eddy systemd[1]: apt-daily-upgrade.service: Succeeded. Nov 23 20:53:56 volumio-eddy systemd[1]: Started Daily apt upgrade and clean activities. Nov 23 20:53:56 volumio-eddy ntpd[1195]: Soliciting pool server 83.98.201.134 Nov 23 20:53:57 volumio-eddy mpd[1540]: Nov 23 20:53 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 23 20:53:57 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:57 volumio-eddy sudo[1466]: pam_unix(sudo:session): session closed for user root Nov 23 20:53:57 volumio-eddy systemd[1]: Started Music Player Daemon. Nov 23 20:53:57 volumio-eddy sudo[1443]: pam_unix(sudo:session): session closed for user root Nov 23 20:53:57 volumio-eddy volumio[1230]: error: updateQueue error: null Nov 23 20:53:57 volumio-eddy volumio[1230]: info: Completed starting Core Plugins Nov 23 20:53:57 volumio-eddy volumio[1230]: info: ------------------------------------------- Nov 23 20:53:57 volumio-eddy volumio[1230]: info: ----- MyVolumio plugins startup ---- Nov 23 20:53:57 volumio-eddy volumio[1230]: info: ------------------------------------------- Nov 23 20:53:57 volumio-eddy volumio[1230]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 23 20:53:57 volumio-eddy volumio[1230]: error: updateQueue error: null Nov 23 20:53:57 volumio-eddy volumio[1230]: info: MPD running with PID1540 Nov 23 20:53:57 volumio-eddy volumio[1230]: ,establishing connection Nov 23 20:53:57 volumio-eddy volumio[1230]: error: updateQueue error: null Nov 23 20:53:57 volumio-eddy ntpd[1195]: Soliciting pool server 5.255.124.190 Nov 23 20:53:58 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:58 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:58 volumio-eddy volumio-remote-updater[573]: [2024-11-23 20:53:58] [connect] Successful connection Nov 23 20:53:58 volumio-eddy volumio-remote-updater[573]: [2024-11-23 20:53:58] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1732395238 101 Nov 23 20:53:58 volumio-eddy volumio[1230]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 7 Nov 23 20:53:58 volumio-eddy volumio[1230]: info: go-librespot daemon successfully initialized Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:53:59 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:54:00 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:54:00 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:54:00 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:00Z" level=debug msg="obtained new client token: AACOz1qtLyqTI9NilJ47c4fO27aHrG388TVNWfSf34xA93fwoq4PPogcckjc82Zcmfch+nZJkYP+qmrh61FWrPiY7QtJlP8Pf84YspuT5x08W6qh8OsAoDcWiGQg2zRtdy2k/MNVvcXKLYLoAIJggGsCYc6mUGY95ZKw3R3SQKGYvhRSw8W1x64uOyBRTvZJJciaGyikNx2vDTR2hxJseKZ+AxAFWVQ3ctAQkkImi5b7Bk+EGzJKuFHeuZDtkw==" Nov 23 20:54:00 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:00Z" level=info msg="connected to ap-gew4.spotify.com:4070" Nov 23 20:54:00 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:00Z" level=debug msg="completed keyexchange" Nov 23 20:54:01 volumio-eddy volumio[1230]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: volumiokiosk-touch Engine version: 3 Transport: polling Total Clients: 8 Nov 23 20:54:01 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:54:01 volumio-eddy volumio[1230]: info: Initializing connection to go-librespot Websocket Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="new websocket client" Nov 23 20:54:01 volumio-eddy volumio[1230]: info: Connection to go-librespot Websocket established Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="completed challenge" Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="authenticated as eddygrefhorst" Nov 23 20:54:01 volumio-eddy sudo[1878]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 23 20:54:01 volumio-eddy sudo[1878]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 23 20:54:01 volumio-eddy sudo[1878]: pam_unix(sudo:session): session closed for user root Nov 23 20:54:01 volumio-eddy sudo[1880]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 23 20:54:01 volumio-eddy sudo[1884]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 23 20:54:01 volumio-eddy sudo[1880]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 23 20:54:01 volumio-eddy sudo[1884]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 23 20:54:01 volumio-eddy sudo[1880]: pam_unix(sudo:session): session closed for user root Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="authenticated as eddygrefhorst" Nov 23 20:54:01 volumio-eddy systemd[1]: Started UPnP Renderer front-end to MPD. Nov 23 20:54:01 volumio-eddy sudo[1884]: pam_unix(sudo:session): session closed for user root Nov 23 20:54:01 volumio-eddy volumio[1230]: info: Upmpdcli Daemon Started Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="dealer connection opened" Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=info msg="accepted zeroconf user eddygrefhorst from A52s van Eddy" Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="autoplay enabled: false" Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="received connection id: YzBhYjYwNDQtNGFlMi00ODAxLWFiY2YtYTU1MGJmYWZhY2ZiK2RlYWxlcit0Y3A6Ly8wYWNhNTkyMy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArRUQ2NzA5MzVDMjY3NDQ0MEFBNUZGNEM3M0EwRkVENjE3RDdDNzlENTIyMjlFOEZDRUQ1NjBDODlCMUVERDAwMQ==" Nov 23 20:54:01 volumio-eddy volumio[1903]: Generating RSA private key, 4096 bit long modulus (2 primes) Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="put connect state because NEW_DEVICE" Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="handling transfer player command from e64df141a49db5ad8888c7df6cb877d4d85aeefe" Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="resolved context of track" uri="spotify:artist:0dmPX6ovclgOy8WWJaFEUU" Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=trace msg="fetched new page 0 with 5 items (list: 5)" uri="spotify:artist:0dmPX6ovclgOy8WWJaFEUU" Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=trace msg="fetched new page 1 with 47 items (list: 52)" uri="spotify:artist:0dmPX6ovclgOy8WWJaFEUU" Nov 23 20:54:01 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:01Z" level=debug msg="loading track (paused: false, position: 109639ms)" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Nov 23 20:54:02 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=trace msg="emitting websocket event: will_play" Nov 23 20:54:02 volumio-eddy volumio[1230]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3VwLD5o1r0YBLkjUfgSEYg","play_origin":"free-tier-artist"}} Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="selected format OGG_VORBIS_320 (d844c96e6dcfd2beacd192a6e9f24d533229e911)" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="requested aes key for file d844c96e6dcfd2beacd192a6e9f24d533229e911, gid: 3VwLD5o1r0YBLkjUfgSEYg" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2863" Nov 23 20:54:02 volumio-eddy volumio[1230]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1878" Nov 23 20:54:02 volumio-eddy volumio[1230]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="fetched first chunk of 16, total size is 8217056 bytes" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Nov 23 20:54:02 volumio-eddy volumio[1903]: ..............++++ Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="fetched chunk 11/15, size: 524288" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="fetched chunk 8/15, size: 524288" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=trace msg="seek to 109639ms (diff: 78ms, samples: 4835079, bytes: 4227465)" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="fetched chunk 10/15, size: 524288" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="fetched chunk 9/15, size: 524288" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5011 us, period size = 221 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 99 frames" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="created new output device" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=info msg="loaded track \"Das Model\" (paused: false, position: 109639ms, duration: 219606ms, prefetched: false)" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=trace msg="scheduling prefetch in 80s" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=trace msg="emitting websocket event: metadata" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=trace msg="emitting websocket event: active" Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="sending successful reply for dealer request" Nov 23 20:54:02 volumio-eddy volumio[1230]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3VwLD5o1r0YBLkjUfgSEYg","name":"Das Model","artist_names":["Kraftwerk"],"album_name":"3-D Der Katalog (German Version)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e026f4cbe4000d08e065bca58e2","position":109639,"duration":219606,"release_date":"year:2017 month:5 day:26","track_number":15,"disc_number":1}} Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 23 20:54:02 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:02Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 23 20:54:02 volumio-eddy volumio[1230]: SPOTIFY: received: {"type":"active","data":null} Nov 23 20:54:02 volumio-eddy volumio[1230]: info: Aligning Spotify Volume to Volumio Volume Nov 23 20:54:02 volumio-eddy volumio[1230]: info: CoreCommandRouter::volumioGetState Nov 23 20:54:02 volumio-eddy volumio[1230]: info: CorePlayQueue::getTrack 0 Nov 23 20:54:03 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:03Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 23 20:54:03 volumio-eddy go-librespot[1570]: time="2024-11-23T20:54:03Z" level=trace msg="emitting websocket event: playing" Nov 23 20:54:03 volumio-eddy volumio[1230]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3VwLD5o1r0YBLkjUfgSEYg","play_origin":"free-tier-artist"}} Nov 23 20:54:03 volumio-eddy volumio[1230]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 23 20:54:03 volumio-eddy volumio[1230]: TypeError: Cannot read property 'service' of undefined Nov 23 20:54:03 volumio-eddy volumio[1230]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Nov 23 20:54:03 volumio-eddy volumio[1230]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) Nov 23 20:54:03 volumio-eddy volumio[1230]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Nov 23 20:54:03 volumio-eddy volumio[1230]: at WebSocket.emit (events.js:400:28) Nov 23 20:54:03 volumio-eddy volumio[1230]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Nov 23 20:54:03 volumio-eddy volumio[1230]: at Receiver.emit (events.js:400:28) Nov 23 20:54:03 volumio-eddy volumio[1230]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Nov 23 20:54:03 volumio-eddy volumio[1230]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Nov 23 20:54:03 volumio-eddy volumio[1230]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Nov 23 20:54:03 volumio-eddy volumio[1230]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Nov 23 20:54:03 volumio-eddy volumio[1230]: at writeOrBuffer (internal/streams/writable.js:358:12) Nov 23 20:54:03 volumio-eddy volumio[1230]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Nov 23 20:54:03 volumio-eddy volumio[1230]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Nov 23 20:54:03 volumio-eddy volumio[1230]: at Socket.emit (events.js:400:28) Nov 23 20:54:03 volumio-eddy volumio[1230]: at addChunk (internal/streams/readable.js:293:12) Nov 23 20:54:03 volumio-eddy volumio[1230]: at readableAddChunk (internal/streams/readable.js:267:9) Nov 23 20:54:03 volumio-eddy volumio[1230]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 23 20:54:03 volumio-eddy sudo[1943]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-23 20:53 Nov 23 20:54:03 volumio-eddy sudo[1943]: 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="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:19:36 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="tinkerboard" VOLUMIO_DEVICENAME="Asus Tinkerboard" VOLUMIO_HASH="43b87fbef9c19ede18711bdf23c439c5"