-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Fri 2024-04-12 20:08:20 CEST. -- Apr 12 20:07:08 badkamer volumio[820]: info: CoreCommandRouter::volumioGetState Apr 12 20:07:18 badkamer volumio[820]: info: CoreCommandRouter::volumioGetState Apr 12 20:07:35 badkamer sudo[580]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/systemctl stop volumio.service Apr 12 20:07:35 badkamer sudo[580]: pam_unix(sudo:session): session opened for user root by volumio(uid=0) Apr 12 20:07:35 badkamer systemd[1]: Stopping Volumio Backend Module... Apr 12 20:07:35 badkamer kernel: bcm2835_audio bcm2835_audio: failed to close VCHI service connection (status=1) Apr 12 20:07:35 badkamer volumio-remote-updater[504]: [2024-04-12 20:07:35] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Apr 12 20:07:35 badkamer volumio-remote-updater[504]: [2024-04-12 20:07:35] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Apr 12 20:07:35 badkamer go-librespot[30193]: time="2024-04-12T20:07:35+02:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Apr 12 20:07:35 badkamer systemd[1]: volumio.service: Main process exited, code=killed, status=15/TERM Apr 12 20:07:35 badkamer systemd[1]: volumio.service: Succeeded. Apr 12 20:07:35 badkamer systemd[1]: Stopped Volumio Backend Module. Apr 12 20:07:35 badkamer sudo[580]: pam_unix(sudo:session): session closed for user root Apr 12 20:07:35 badkamer sudo[583]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/systemctl start volumio.service Apr 12 20:07:35 badkamer sudo[583]: pam_unix(sudo:session): session opened for user root by volumio(uid=0) Apr 12 20:07:35 badkamer systemd[1]: Started dynamicswap service. Apr 12 20:07:35 badkamer systemd[1]: Started Volumio Backend Module. Apr 12 20:07:35 badkamer sudo[583]: pam_unix(sudo:session): session closed for user root Apr 12 20:07:35 badkamer systemd[1]: dynamicswap.service: Succeeded. Apr 12 20:07:37 badkamer volumio[587]: info: ------------------------------------------- Apr 12 20:07:37 badkamer volumio[587]: info: ----- Volumio3 ---- Apr 12 20:07:37 badkamer volumio[587]: info: ------------------------------------------- Apr 12 20:07:37 badkamer volumio[587]: info: ----- System startup ---- Apr 12 20:07:37 badkamer volumio[587]: info: ------------------------------------------- Apr 12 20:07:38 badkamer volumio[587]: info: MYVOLUMIO Environment detected Apr 12 20:07:38 badkamer volumio[587]: info: Plugin folders cleanup Apr 12 20:07:38 badkamer volumio[587]: info: Scanning into folder /volumio/app/plugins/ Apr 12 20:07:38 badkamer volumio[587]: info: Scanning category audio_interface Apr 12 20:07:38 badkamer volumio[587]: info: Scanning category miscellanea Apr 12 20:07:38 badkamer volumio[587]: info: Scanning category music_service Apr 12 20:07:38 badkamer volumio[587]: info: Scanning category plugins.json Apr 12 20:07:38 badkamer volumio[587]: info: Scanning category system_controller Apr 12 20:07:38 badkamer volumio[587]: info: Scanning category user_interface Apr 12 20:07:38 badkamer volumio[587]: info: Scanning into folder /data/plugins/ Apr 12 20:07:38 badkamer volumio[587]: info: Scanning category audio_interface Apr 12 20:07:38 badkamer volumio[587]: info: Scanning category music_service Apr 12 20:07:38 badkamer volumio[587]: info: Plugin folders cleanup completed Apr 12 20:07:38 badkamer volumio[587]: info: ------------------------------------------- Apr 12 20:07:38 badkamer volumio[587]: info: ----- Core plugins startup ---- Apr 12 20:07:38 badkamer volumio[587]: info: ------------------------------------------- Apr 12 20:07:38 badkamer volumio[587]: info: Loading plugins from folder /volumio/app/plugins/ Apr 12 20:07:38 badkamer volumio[587]: info: Adding plugin upnp to MyMusic Plugins Apr 12 20:07:38 badkamer volumio[587]: info: Adding plugin airplay_emulation to MyMusic Plugins Apr 12 20:07:38 badkamer volumio[587]: info: Adding plugin upnp_browser to MyMusic Plugins Apr 12 20:07:38 badkamer volumio[587]: info: Loading plugins from folder /data/plugins/ Apr 12 20:07:38 badkamer volumio[587]: info: Loading plugin "system"... Apr 12 20:07:38 badkamer volumio[587]: info: Loading plugin "appearance"... Apr 12 20:07:39 badkamer volumio[587]: info: Loading plugin "network"... Apr 12 20:07:39 badkamer volumio[587]: info: Refreshing Cached IP Addresses Apr 12 20:07:39 badkamer sudo[662]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 12 20:07:39 badkamer sudo[662]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:07:39 badkamer sudo[662]: pam_unix(sudo:session): session closed for user root Apr 12 20:07:39 badkamer sudo[664]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 12 20:07:39 badkamer volumio[587]: info: Loading plugin "services"... Apr 12 20:07:39 badkamer sudo[664]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:07:39 badkamer volumio[587]: info: Loading plugin "alsa_controller"... Apr 12 20:07:39 badkamer sudo[664]: pam_unix(sudo:session): session closed for user root Apr 12 20:07:39 badkamer sudo[668]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Apr 12 20:07:39 badkamer sudo[668]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:07:39 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 12 20:07:39 badkamer volumio[587]: info: Loading plugin "wizard"... Apr 12 20:07:39 badkamer volumio[587]: info: Loading plugin "networkfs"... Apr 12 20:07:39 badkamer volumio[587]: info: Starting Udev Watcher for removable devices Apr 12 20:07:39 badkamer volumio[587]: info: Ignoring mount for partition: boot Apr 12 20:07:39 badkamer volumio[587]: info: Ignoring mount for partition: volumio Apr 12 20:07:39 badkamer volumio[587]: info: Ignoring mount for partition: volumio_data Apr 12 20:07:39 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 12 20:07:39 badkamer volumio[587]: info: Loading plugin "volumio_command_line_client"... Apr 12 20:07:39 badkamer volumio[587]: info: Plugin upnp is not enabled Apr 12 20:07:39 badkamer volumio[587]: info: Loading plugin "my_music"... Apr 12 20:07:39 badkamer volumio[587]: info: Loading plugin "mpd"... Apr 12 20:07:40 badkamer volumio[587]: info: Plugin upnp_browser is not enabled Apr 12 20:07:40 badkamer volumio[587]: info: Loading plugin "alarm-clock"... Apr 12 20:07:40 badkamer volumio[587]: info: Loading plugin "airplay_emulation"... Apr 12 20:07:40 badkamer volumio[587]: info: Starting Shairport Sync Apr 12 20:07:40 badkamer volumio[587]: info: Loading plugin "last_100"... Apr 12 20:07:40 badkamer volumio[587]: info: Loading plugin "webradio"... Apr 12 20:07:40 badkamer volumio[587]: info: Loading plugin "i2s_dacs"... Apr 12 20:07:40 badkamer volumio[587]: info: I2S DAC not set, start Auto-detection Apr 12 20:07:40 badkamer volumio[587]: info: Loading plugin "volumiodiscovery"... Apr 12 20:07:40 badkamer volumio[587]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 12 20:07:40 badkamer volumio[587]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 12 20:07:40 badkamer volumio[587]: *** WARNING *** For more information see Apr 12 20:07:40 badkamer volumio[587]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 12 20:07:40 badkamer node[587]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 12 20:07:40 badkamer volumio[587]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 12 20:07:40 badkamer volumio[587]: *** WARNING *** For more information see Apr 12 20:07:40 badkamer node[587]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 12 20:07:40 badkamer node[587]: *** WARNING *** For more information see Apr 12 20:07:40 badkamer node[587]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 12 20:07:40 badkamer node[587]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 12 20:07:40 badkamer node[587]: *** WARNING *** For more information see Apr 12 20:07:40 badkamer volumio[587]: info: Applying required configuration parameters for plugin volumiodiscovery Apr 12 20:07:40 badkamer volumio[587]: info: Discovery: Started advertising with name: Badkamer Apr 12 20:07:40 badkamer volumio-remote-updater[504]: [2024-04-12 20:07:40] [connect] Successful connection Apr 12 20:07:40 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 12 20:07:40 badkamer volumio[587]: info: Loading plugin "spop"... Apr 12 20:07:40 badkamer sudo[668]: pam_unix(sudo:session): session closed for user root Apr 12 20:07:41 badkamer volumio[587]: info: Loading plugin "outputs"... Apr 12 20:07:41 badkamer volumio[587]: info: Loading plugin "albumart"... Apr 12 20:07:41 badkamer volumio[587]: info: Plugin example_plugin is not enabled Apr 12 20:07:41 badkamer volumio[587]: info: Loading plugin "inputs"... Apr 12 20:07:41 badkamer volumio[587]: info: Loading plugin "updater_comm"... Apr 12 20:07:41 badkamer volumio[587]: info: Plugin mpdemulation is not enabled Apr 12 20:07:41 badkamer volumio[587]: info: Loading plugin "rest_api"... Apr 12 20:07:41 badkamer volumio[587]: info: Loading plugin "websocket"... Apr 12 20:07:41 badkamer volumio[587]: info: Loading plugin "fusiondsp"... Apr 12 20:07:42 badkamer volumio[587]: Forking 3 albumart workers Apr 12 20:07:42 badkamer volumio[587]: info: Applying required configuration parameters for plugin fusiondsp Apr 12 20:07:42 badkamer volumio[587]: info: Loading i18n strings for locale nl Apr 12 20:07:42 badkamer volumio[587]: Updating browse sources language Apr 12 20:07:42 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 12 20:07:42 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 12 20:07:42 badkamer volumio[587]: info: CoreCommandRouter::initPlayerControls Apr 12 20:07:42 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:07:42 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:07:42 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:07:42 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:07:42 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:07:42 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:07:42 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:07:42 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:07:42 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 12 20:07:42 badkamer volumio[587]: Express server listening on port 3000 Apr 12 20:07:42 badkamer volumio[587]: [Metrics] WebUI: 5s 758.88ms Apr 12 20:07:42 badkamer volumio[587]: info: CoreStateMachine::resetVolumioState Apr 12 20:07:42 badkamer volumio[587]: info: CoreStateMachine::getcurrentVolume Apr 12 20:07:42 badkamer volumio[587]: info: CoreCommandRouter::volumioRetrievevolume Apr 12 20:07:42 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 20:07:42 badkamer volumio[587]: verbose: New Socket.io Connection to 192.168.0.253 from 192.168.0.228 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36 Total Clients: 1 Apr 12 20:07:43 badkamer volumio-remote-updater[504]: [2024-04-12 20:07:43] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1712945260 101 Apr 12 20:07:43 badkamer volumio[587]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 2 Apr 12 20:07:43 badkamer volumio[587]: verbose: New Socket.io Connection to 192.168.0.253 from 192.168.0.228 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36 Total Clients: 3 Apr 12 20:07:43 badkamer volumio[587]: verbose: New Socket.io Connection to 192.168.0.253:3000 from 192.168.0.254 UA: node-XMLHttpRequest Total Clients: 4 Apr 12 20:07:43 badkamer volumio[587]: info: CoreCommandRouter::volumioGetState Apr 12 20:07:43 badkamer volumio[587]: info: CorePlayQueue::getTrack 0 Apr 12 20:07:43 badkamer volumio[587]: info: Reloading queue from file Apr 12 20:07:43 badkamer volumio[587]: info: VolumeController:: Volume=44 Mute =false Apr 12 20:07:43 badkamer volumio[587]: info: CoreStateMachine::pushState Apr 12 20:07:43 badkamer volumio[587]: info: CorePlayQueue::getTrack 0 Apr 12 20:07:43 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 20:07:43 badkamer volumio[587]: info: CoreCommandRouter::volumioPushState Apr 12 20:07:43 badkamer volumio[587]: info: CoreStateMachine::updateTrackBlock Apr 12 20:07:43 badkamer volumio[587]: info: CorePlayQueue::getTrackBlock Apr 12 20:07:43 badkamer volumio[587]: info: CoreCommandRouter::volumioRetrievevolume Apr 12 20:07:43 badkamer volumio[587]: Starting albumart workers Apr 12 20:07:43 badkamer volumio[587]: Starting albumart workers Apr 12 20:07:43 badkamer volumio[587]: info: Setting Device type: Raspberry PI Apr 12 20:07:43 badkamer volumio[587]: info: CoreStateMachine::setRepeat null single undefined Apr 12 20:07:43 badkamer volumio[587]: info: CoreStateMachine::pushState Apr 12 20:07:43 badkamer volumio[587]: info: CorePlayQueue::getTrack 0 Apr 12 20:07:43 badkamer volumio[587]: info: CoreCommandRouter::volumioPushState Apr 12 20:07:43 badkamer volumio[587]: info: CoreStateMachine::setRandom null Apr 12 20:07:43 badkamer volumio[587]: info: CoreStateMachine::pushState Apr 12 20:07:43 badkamer volumio[587]: info: CorePlayQueue::getTrack 0 Apr 12 20:07:43 badkamer volumio[587]: info: CoreCommandRouter::volumioPushState Apr 12 20:07:43 badkamer volumio[587]: info: Discovery: adding ca1e79c3-843a-4bff-89ba-7436a862d7e5 Apr 12 20:07:43 badkamer volumio[587]: info: Discovery: Found device Versterker Apr 12 20:07:43 badkamer volumio[587]: Starting albumart workers Apr 12 20:07:43 badkamer volumio[587]: info: Discovery: Connecting to remote: 192.168.0.254 Apr 12 20:07:43 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Apr 12 20:07:43 badkamer volumio[587]: info: CoreCommandRouter::volumioGetState Apr 12 20:07:43 badkamer volumio[587]: info: CorePlayQueue::getTrack 0 Apr 12 20:07:43 badkamer volumio[587]: info: Discovery: adding 6c5bd8de-8264-40cd-a810-150d93a6a8d3 Apr 12 20:07:43 badkamer volumio[587]: info: Discovery: Found device Badkamer Apr 12 20:07:43 badkamer volumio[587]: info: CoreCommandRouter::volumioGetState Apr 12 20:07:43 badkamer volumio[587]: info: CorePlayQueue::getTrack 0 Apr 12 20:07:43 badkamer volumio[587]: info: VolumeController:: Volume=44 Mute =false Apr 12 20:07:43 badkamer volumio[587]: info: CoreStateMachine::pushState Apr 12 20:07:43 badkamer volumio[587]: info: CorePlayQueue::getTrack 0 Apr 12 20:07:43 badkamer volumio[587]: info: CoreCommandRouter::volumioPushState Apr 12 20:07:43 badkamer volumio[587]: info: Discovery: Connected to remote: 192.168.0.254 Apr 12 20:07:53 badkamer volumio[587]: info: CoreCommandRouter::volumioGetState Apr 12 20:07:53 badkamer volumio[587]: info: CorePlayQueue::getTrack 0 Apr 12 20:07:55 badkamer go-librespot[30193]: time="2024-04-12T20:07:55+02:00" level=debug msg="handling transfer player command from e41e6e21657a3e547616abf732378a36c228c3e2" Apr 12 20:07:55 badkamer go-librespot[30193]: time="2024-04-12T20:07:55+02:00" level=trace msg="fetched new page 0 with 35 items (list: 35)" Apr 12 20:07:55 badkamer go-librespot[30193]: time="2024-04-12T20:07:55+02:00" level=debug msg="shuffled context with seed 8338342994377961816 (len: 35, keep: 10)" Apr 12 20:07:55 badkamer go-librespot[30193]: time="2024-04-12T20:07:55+02:00" level=debug msg="loading track spotify:track:6tGCxVJPo7iIydUVHOjVbM (paused: false, position: 2534ms)" Apr 12 20:07:55 badkamer go-librespot[30193]: time="2024-04-12T20:07:55+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 12 20:07:55 badkamer go-librespot[30193]: time="2024-04-12T20:07:55+02:00" level=trace msg="emitting websocket event: will_play" Apr 12 20:07:55 badkamer go-librespot[30193]: time="2024-04-12T20:07:55+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:6tGCxVJPo7iIydUVHOjVbM" Apr 12 20:07:55 badkamer go-librespot[30193]: time="2024-04-12T20:07:55+02:00" level=debug msg="requested aes key for file cbca793c1205cdd6c14a103807f764821c1b872e, gid: 6tGCxVJPo7iIydUVHOjVbM" Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=debug msg="fetched first chunk of 18, total size is 9046756 bytes" Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=trace msg="seek to 2534ms (diff: 138ms, samples: 111749, bytes: 87159)" Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=info msg="loaded track \"Falling Apart\" (uri: spotify:track:6tGCxVJPo7iIydUVHOjVbM, paused: false, position: 2534ms, duration: 206616ms)" Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=debug msg="fetched chunk 1/17, size: 524288" Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=trace msg="emitting websocket event: metadata" Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=trace msg="emitting websocket event: active" Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=debug msg="sending successful reply for delaer request" Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=trace msg="emitting websocket event: playing" Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=debug msg="fetched chunk 2/17, size: 524288" Apr 12 20:07:56 badkamer go-librespot[30193]: time="2024-04-12T20:07:56+02:00" level=debug msg="fetched chunk 3/17, size: 524288" Apr 12 20:07:58 badkamer volumio[587]: info: Getting Push Notification urls Apr 12 20:07:58 badkamer volumio[587]: info: Adding Push Notification url Apr 12 20:08:06 badkamer go-librespot[30193]: time="2024-04-12T20:08:06+02:00" level=debug msg="update volume to 32767/65535" Apr 12 20:08:07 badkamer go-librespot[30193]: time="2024-04-12T20:08:07+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 12 20:08:07 badkamer go-librespot[30193]: time="2024-04-12T20:08:07+02:00" level=trace msg="emitting websocket event: volume" Apr 12 20:08:07 badkamer go-librespot[30193]: time="2024-04-12T20:08:07+02:00" level=debug msg="update volume to 36699/65535" Apr 12 20:08:07 badkamer go-librespot[30193]: time="2024-04-12T20:08:07+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 12 20:08:07 badkamer go-librespot[30193]: time="2024-04-12T20:08:07+02:00" level=trace msg="emitting websocket event: volume" Apr 12 20:08:08 badkamer go-librespot[30193]: time="2024-04-12T20:08:08+02:00" level=debug msg="update volume to 32767/65535" Apr 12 20:08:08 badkamer go-librespot[30193]: time="2024-04-12T20:08:08+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 12 20:08:08 badkamer go-librespot[30193]: time="2024-04-12T20:08:08+02:00" level=trace msg="emitting websocket event: volume" Apr 12 20:08:08 badkamer go-librespot[30193]: time="2024-04-12T20:08:08+02:00" level=debug msg="update volume to 36699/65535" Apr 12 20:08:09 badkamer go-librespot[30193]: time="2024-04-12T20:08:09+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 12 20:08:09 badkamer go-librespot[30193]: time="2024-04-12T20:08:09+02:00" level=trace msg="emitting websocket event: volume" Apr 12 20:08:12 badkamer volumio[587]: error: Plugin system_controller system failed to complete 'onVolumioStart' in a timely fashion Apr 12 20:08:12 badkamer volumio[587]: info: Preparing to generate the ALSA configuration file Apr 12 20:08:12 badkamer volumio[587]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Apr 12 20:08:12 badkamer volumio[587]: info: Reading ALSA contributions from plugins. Apr 12 20:08:12 badkamer volumio[587]: info: Asound.conf file unchanged, so no further update is needed Apr 12 20:08:12 badkamer volumio[587]: info: Output device has changed, restarting MPD Apr 12 20:08:12 badkamer sudo[751]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 12 20:08:12 badkamer volumio[587]: info: Output device has changed, restarting Shairport Sync Apr 12 20:08:12 badkamer sudo[751]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:08:12 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:12 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 20:08:12 badkamer sudo[751]: pam_unix(sudo:session): session closed for user root Apr 12 20:08:12 badkamer sudo[753]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 12 20:08:12 badkamer sudo[753]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:08:12 badkamer systemd[1]: Stopping Music Player Daemon... Apr 12 20:08:12 badkamer systemd[1]: mpd.service: Succeeded. Apr 12 20:08:12 badkamer systemd[1]: Stopped Music Player Daemon. Apr 12 20:08:12 badkamer volumio[587]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 12 20:08:12 badkamer volumio[587]: info: ___________ START PLUGINS ___________ Apr 12 20:08:12 badkamer volumio[587]: info: ControllerMpd::onStart: Initializing MPD Apr 12 20:08:12 badkamer volumio[587]: info: Creating MPD Configuration file Apr 12 20:08:12 badkamer sudo[762]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 12 20:08:12 badkamer sudo[762]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:08:12 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:12 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 20:08:12 badkamer sudo[762]: pam_unix(sudo:session): session closed for user root Apr 12 20:08:12 badkamer systemd[1]: Starting Music Player Daemon... Apr 12 20:08:12 badkamer sudo[767]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 12 20:08:12 badkamer sudo[767]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:08:12 badkamer systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Apr 12 20:08:12 badkamer systemd[1]: mpd.service: Succeeded. Apr 12 20:08:12 badkamer systemd[1]: Stopped Music Player Daemon. Apr 12 20:08:12 badkamer systemd[1]: Starting Music Player Daemon... Apr 12 20:08:12 badkamer volumio[587]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 12 20:08:12 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:12 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 20:08:12 badkamer volumio[587]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 12 20:08:12 badkamer volumio[587]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 12 20:08:12 badkamer volumio[587]: info: [1712945292768] CoreMusicLibrary::Adding element Last_100 Apr 12 20:08:12 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 12 20:08:12 badkamer volumio[587]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 12 20:08:12 badkamer volumio[587]: info: [1712945292780] CoreMusicLibrary::Adding element Webradio Apr 12 20:08:12 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 12 20:08:12 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 12 20:08:12 badkamer volumio[587]: info: Creating Spotify config file Apr 12 20:08:12 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:12 badkamer go-librespot[30193]: time="2024-04-12T20:08:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Apr 12 20:08:12 badkamer volumio[587]: info: Loading i18n strings for locale nl Apr 12 20:08:12 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Apr 12 20:08:12 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:12 badkamer volumio[587]: info: FusionDsp - mixtype--------------------- Hardware Apr 12 20:08:12 badkamer volumio[587]: info: Volumio Calling Home Apr 12 20:08:12 badkamer go-librespot[30193]: time="2024-04-12T20:08:12+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 12 20:08:12 badkamer volumio[587]: info: Preparing to generate the ALSA configuration file Apr 12 20:08:13 badkamer volumio[587]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Apr 12 20:08:13 badkamer volumio[587]: info: Reading ALSA contributions from plugins. Apr 12 20:08:13 badkamer volumio[587]: info: MPD Permissions set Apr 12 20:08:13 badkamer volumio[587]: info: MPD Permissions set Apr 12 20:08:13 badkamer volumio[587]: info: Spotify config file written Apr 12 20:08:13 badkamer volumio[587]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Apr 12 20:08:13 badkamer volumio[587]: info: Volumio called home Apr 12 20:08:13 badkamer sudo[781]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 12 20:08:13 badkamer sudo[781]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer systemd[1]: Stopping go-librespot Daemon... Apr 12 20:08:13 badkamer systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Apr 12 20:08:13 badkamer systemd[1]: go-librespot-daemon.service: Succeeded. Apr 12 20:08:13 badkamer systemd[1]: Stopped go-librespot Daemon. Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer systemd[1]: Started go-librespot Daemon. Apr 12 20:08:13 badkamer go-librespot[784]: Librespot-go daemon starting... Apr 12 20:08:13 badkamer sudo[781]: pam_unix(sudo:session): session closed for user root Apr 12 20:08:13 badkamer go-librespot[784]: time="2024-04-12T20:08:13+02:00" level=info msg="generated new device id: aa2db1f42557b28c19b6f0abc88f03a27be30461" Apr 12 20:08:13 badkamer go-librespot[784]: time="2024-04-12T20:08:13+02:00" level=debug msg="stored credentials found for jx616n9bbgb1ojonzhjwb27gh" Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: Starting Shairport Sync Apr 12 20:08:13 badkamer volumio[587]: info: Starting Shairport Sync Apr 12 20:08:13 badkamer sudo[799]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 12 20:08:13 badkamer volumio[587]: info: Starting Shairport Sync Apr 12 20:08:13 badkamer sudo[799]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:08:13 badkamer systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 12 20:08:13 badkamer systemd[1]: shairport-sync.service: Succeeded. Apr 12 20:08:13 badkamer systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 12 20:08:13 badkamer sudo[802]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 12 20:08:13 badkamer sudo[802]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:08:13 badkamer sudo[804]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 12 20:08:13 badkamer systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 12 20:08:13 badkamer volumio[587]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 12 20:08:13 badkamer volumio[587]: SPOTIFY: BQBVPrP0tcHP0FQ1HXa9oduSDal22U9p-P3miKFkcJj6Oq6Xu6j4oAQQ7z8FiHrxAiGxU-xcIl_h4tUqpynEU4FeSxt5qMc6NYYDrLOhJqSvVZ3VC7APnbZRsTVW3jy82hXh7yqhHCVB_l1CgPRyXb-tY6sILdOykGd7bPcRsRRnBIct0dBEtCa6bNN9Mz0QxPp4Z8WqpJcJaBIQyiiyhHlYe1PjPsCS2XaLZZohp3YydygpydAOyQu4HoNmM0abc57WZaM Apr 12 20:08:13 badkamer volumio[587]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 12 20:08:13 badkamer volumio[587]: info: New Spotify access token = BQBVPrP0tcHP0FQ1HXa9oduSDal22U9p-P3miKFkcJj6Oq6Xu6j4oAQQ7z8FiHrxAiGxU-xcIl_h4tUqpynEU4FeSxt5qMc6NYYDrLOhJqSvVZ3VC7APnbZRsTVW3jy82hXh7yqhHCVB_l1CgPRyXb-tY6sILdOykGd7bPcRsRRnBIct0dBEtCa6bNN9Mz0QxPp4Z8WqpJcJaBIQyiiyhHlYe1PjPsCS2XaLZZohp3YydygpydAOyQu4HoNmM0abc57WZaM Apr 12 20:08:13 badkamer volumio[587]: info: Spotify credentials grant success - running version from March 24, 2019 Apr 12 20:08:13 badkamer sudo[799]: pam_unix(sudo:session): session closed for user root Apr 12 20:08:13 badkamer systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 12 20:08:13 badkamer systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Apr 12 20:08:13 badkamer systemd[1]: shairport-sync.service: Succeeded. Apr 12 20:08:13 badkamer sudo[804]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:08:13 badkamer systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 12 20:08:13 badkamer systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 12 20:08:13 badkamer sudo[802]: pam_unix(sudo:session): session closed for user root Apr 12 20:08:13 badkamer systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 12 20:08:13 badkamer systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Apr 12 20:08:13 badkamer systemd[1]: shairport-sync.service: Succeeded. Apr 12 20:08:13 badkamer systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 12 20:08:13 badkamer volumio[587]: info: Asound.conf file unchanged, so no further update is needed Apr 12 20:08:13 badkamer volumio[587]: info: Output device has changed, restarting MPD Apr 12 20:08:13 badkamer systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 12 20:08:13 badkamer sudo[804]: pam_unix(sudo:session): session closed for user root Apr 12 20:08:13 badkamer go-librespot[784]: time="2024-04-12T20:08:13+02:00" level=debug msg="obtained new client token: AADbtQ8NP0GbNGN/p31hXBymkoyObjuSAd2Kzqk6SXWEDXzluUE30VDPpdRbazZjVVjJqrMi2tL8XG/G+G31LwotuAq+SUzEbQEBztonZ2gslqM3IHHI3ml9N07uaUb4/DOUXjV3JuY7n+YxkXbu0vbjwXJPtUfMKemwIi7V8HEKEym1ySqEq9qeSzG10VGDkrdMXcsjIlTmYKjRT2r3wX5UcgD7uBHwpyv2/ziIw4Ia6ceIIQ6lP2lv56oK5Yb1" Apr 12 20:08:13 badkamer volumio[587]: info: Output device has changed, restarting Shairport Sync Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 20:08:13 badkamer sudo[812]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 12 20:08:13 badkamer sudo[812]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:08:13 badkamer sudo[812]: pam_unix(sudo:session): session closed for user root Apr 12 20:08:13 badkamer sudo[817]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 12 20:08:13 badkamer sudo[817]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:08:13 badkamer go-librespot[784]: time="2024-04-12T20:08:13+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Apr 12 20:08:13 badkamer volumio[587]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 12 20:08:13 badkamer systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Apr 12 20:08:13 badkamer systemd[1]: mpd.service: Succeeded. Apr 12 20:08:13 badkamer systemd[1]: Stopped Music Player Daemon. Apr 12 20:08:13 badkamer volumio[587]: info: Shairport-Sync Started Apr 12 20:08:13 badkamer volumio[587]: Error adding Membership: Error: addMembership EINVAL Apr 12 20:08:13 badkamer volumio[587]: info: Shairport-Sync Started Apr 12 20:08:13 badkamer volumio[587]: info: MPD Permissions set Apr 12 20:08:13 badkamer volumio[587]: info: Shairport-Sync Started Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::volumioGetState Apr 12 20:08:13 badkamer volumio[587]: info: CorePlayQueue::getTrack 0 Apr 12 20:08:13 badkamer go-librespot[784]: time="2024-04-12T20:08:13+02:00" level=debug msg="completed keyexchange" Apr 12 20:08:13 badkamer systemd[1]: Starting Music Player Daemon... Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:13 badkamer volumio[587]: info: Starting Shairport Sync Apr 12 20:08:13 badkamer volumio[587]: SPOTIFY: User informations: {"display_name":"Jelmer","external_urls":{"spotify":"https://open.spotify.com/user/jx616n9bbgb1ojonzhjwb27gh"},"href":"https://api.spotify.com/v1/users/jx616n9bbgb1ojonzhjwb27gh","id":"jx616n9bbgb1ojonzhjwb27gh","images":[],"type":"user","uri":"spotify:user:jx616n9bbgb1ojonzhjwb27gh","followers":{"href":null,"total":0},"country":"NL","product":"premium","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"jelmerbrand@outlook.com"} Apr 12 20:08:13 badkamer volumio[587]: info: Spotify Successfully logged in Apr 12 20:08:13 badkamer sudo[832]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 12 20:08:13 badkamer sudo[832]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 12 20:08:13 badkamer volumio[587]: info: [1712945293983] CoreMusicLibrary::Adding element Spotify Apr 12 20:08:13 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 12 20:08:13 badkamer volumio[587]: Cannot find translation for source Spotify Apr 12 20:08:14 badkamer systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 12 20:08:14 badkamer systemd[1]: shairport-sync.service: Succeeded. Apr 12 20:08:14 badkamer systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 12 20:08:14 badkamer volumio[587]: info: CoreCommandRouter::volumioGetState Apr 12 20:08:14 badkamer volumio[587]: info: CorePlayQueue::getTrack 0 Apr 12 20:08:14 badkamer systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 12 20:08:14 badkamer sudo[832]: pam_unix(sudo:session): session closed for user root Apr 12 20:08:14 badkamer volumio[587]: info: Shairport-Sync Started Apr 12 20:08:14 badkamer go-librespot[784]: time="2024-04-12T20:08:14+02:00" level=debug msg="completed challenge" Apr 12 20:08:14 badkamer go-librespot[784]: time="2024-04-12T20:08:14+02:00" level=debug msg="authenticated as jx616n9bbgb1ojonzhjwb27gh" Apr 12 20:08:14 badkamer go-librespot[784]: time="2024-04-12T20:08:14+02:00" level=debug msg="authenticated as jx616n9bbgb1ojonzhjwb27gh" Apr 12 20:08:14 badkamer go-librespot[784]: time="2024-04-12T20:08:14+02:00" 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]" Apr 12 20:08:14 badkamer go-librespot[784]: time="2024-04-12T20:08:14+02:00" 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]" Apr 12 20:08:14 badkamer go-librespot[784]: time="2024-04-12T20:08:14+02:00" level=debug msg="dealer connection opened" Apr 12 20:08:14 badkamer go-librespot[784]: time="2024-04-12T20:08:14+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 12 20:08:14 badkamer go-librespot[784]: time="2024-04-12T20:08:14+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 12 20:08:14 badkamer go-librespot[784]: time="2024-04-12T20:08:14+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 12 20:08:14 badkamer go-librespot[784]: time="2024-04-12T20:08:14+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 12 20:08:14 badkamer go-librespot[784]: time="2024-04-12T20:08:14+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" Apr 12 20:08:14 badkamer go-librespot[784]: time="2024-04-12T20:08:14+02:00" level=debug msg="received connection id: OTZlNWY4MmUtZDIzMi00MmEwLTk1NTQtNjM0YTAyMjhkMGYzK2RlYWxlcit0Y3A6Ly9nZXc0LWRlYWxlci1hLXpwbTYuZ2V3NC5zcG90aWZ5Lm5ldDo1NzAwKzIwRjRCRTFGQTMyRDc3NUJCRjIyQzM1RTAwOTU1QTZDMzY5MUYyQTAxNTNDOENDREI4Q0QxOUU1N0ZFQjIzQTg=" Apr 12 20:08:14 badkamer volumio[587]: /usr/bin/mkfifo: cannot create fifo '/tmp/fusiondspfifo': File exists Apr 12 20:08:14 badkamer volumio[587]: error: FusionDsp - ----failed to create fusiondspfifo :Error: Command failed: /bin/touch /tmp/fusiondsp_stream_params.log && /bin/chmod 666 /tmp/fusiondsp_stream_params.log && /bin/touch /tmp/camilladsp.log && /bin/chmod 666 /tmp/camilladsp.log && /usr/bin/mkfifo -m 646 /tmp/fusiondspfifo Apr 12 20:08:14 badkamer volumio[587]: /usr/bin/mkfifo: cannot create fifo '/tmp/fusiondspfifo': File exists Apr 12 20:08:14 badkamer volumio[587]: info: camilladsp spawned new process with pid 845, instance 1, run: true Apr 12 20:08:14 badkamer volumio[587]: info: camilladsp service started and running in background, instance 1 Apr 12 20:08:14 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 20:08:15 badkamer mpd[822]: Apr 12 20:08 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 12 20:08:15 badkamer systemd[1]: Started Music Player Daemon. Apr 12 20:08:15 badkamer sudo[753]: pam_unix(sudo:session): session closed for user root Apr 12 20:08:15 badkamer sudo[767]: pam_unix(sudo:session): session closed for user root Apr 12 20:08:15 badkamer sudo[817]: pam_unix(sudo:session): session closed for user root Apr 12 20:08:15 badkamer volumio[587]: info: FusionDsp - AAAAAAAAAAAAAA-> 22050 44100 48000 88200 96000 176400 192000 <-AAAAAAAAAAAAA Apr 12 20:08:15 badkamer go-librespot[784]: time="2024-04-12T20:08:15+02:00" level=debug msg="put connect state because NEW_DEVICE" Apr 12 20:08:15 badkamer volumio[587]: info: FusionDsp loaded Apr 12 20:08:15 badkamer volumio[587]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 12 20:08:15 badkamer sudo[857]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Apr 12 20:08:15 badkamer sudo[857]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 12 20:08:15 badkamer volumio[587]: info: FusionDsp - Reporting Fusion DSP Enabled Apr 12 20:08:15 badkamer volumio[587]: info: Adding Signal Path Element [object Object] Apr 12 20:08:15 badkamer volumio[587]: info: Adding fusiondspeq DSP Signal Path Element Apr 12 20:08:15 badkamer volumio[587]: info: FusionDsp - ---- installed callbackRead Apr 12 20:08:15 badkamer sudo[857]: pam_unix(sudo:session): session closed for user root Apr 12 20:08:15 badkamer volumio[587]: info: Completed starting Core Plugins Apr 12 20:08:15 badkamer volumio[587]: info: ------------------------------------------- Apr 12 20:08:15 badkamer volumio[587]: info: ----- MyVolumio plugins startup ---- Apr 12 20:08:15 badkamer volumio[587]: info: ------------------------------------------- Apr 12 20:08:15 badkamer volumio[587]: info: [MyVolumio PluginManager] Fetching plans data.... Apr 12 20:08:15 badkamer volumio[587]: info: FusionDsp - If filter freq >samplerate/2 then disable it Apr 12 20:08:15 badkamer volumio[587]: info: MPD running with PID822 Apr 12 20:08:15 badkamer volumio[587]: ,establishing connection Apr 12 20:08:15 badkamer volumio[587]: error: MPD error: The expression evaluated to a falsy value: Apr 12 20:08:15 badkamer volumio[587]: assert.ok(self.idling) Apr 12 20:08:15 badkamer volumio[587]: error: The expression evaluated to a falsy value: Apr 12 20:08:15 badkamer volumio[587]: assert.ok(self.idling) Apr 12 20:08:15 badkamer volumio[587]: error: MPD error: The expression evaluated to a falsy value: Apr 12 20:08:15 badkamer volumio[587]: assert.ok(self.idling) Apr 12 20:08:15 badkamer volumio[587]: error: The expression evaluated to a falsy value: Apr 12 20:08:15 badkamer volumio[587]: assert.ok(self.idling) Apr 12 20:08:15 badkamer volumio[587]: error: MPD error: The expression evaluated to a falsy value: Apr 12 20:08:15 badkamer volumio[587]: assert.ok(self.idling) Apr 12 20:08:15 badkamer volumio[587]: error: The expression evaluated to a falsy value: Apr 12 20:08:15 badkamer volumio[587]: assert.ok(self.idling) Apr 12 20:08:15 badkamer volumio[587]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 12 20:08:15 badkamer volumio[587]: info: FusionDsp - {"Reload":{"result":"Ok"}} Apr 12 20:08:15 badkamer volumio[587]: error: updateQueue error: null Apr 12 20:08:16 badkamer volumio[587]: info: go-librespot daemon successfully initialized Apr 12 20:08:18 badkamer go-librespot[784]: time="2024-04-12T20:08:18+02:00" level=debug msg="handling transfer player command from e41e6e21657a3e547616abf732378a36c228c3e2" Apr 12 20:08:18 badkamer go-librespot[784]: time="2024-04-12T20:08:18+02:00" level=trace msg="fetched new page 0 with 33 items (list: 33)" Apr 12 20:08:18 badkamer go-librespot[784]: time="2024-04-12T20:08:18+02:00" level=debug msg="shuffled context with seed 15469399185353964795 (len: 33, keep: 23)" Apr 12 20:08:18 badkamer go-librespot[784]: time="2024-04-12T20:08:18+02:00" level=debug msg="loading track spotify:track:6tGCxVJPo7iIydUVHOjVbM (paused: false, position: 25727ms)" Apr 12 20:08:18 badkamer go-librespot[784]: time="2024-04-12T20:08:18+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Apr 12 20:08:18 badkamer go-librespot[784]: time="2024-04-12T20:08:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 12 20:08:18 badkamer go-librespot[784]: time="2024-04-12T20:08:18+02:00" level=trace msg="emitting websocket event: will_play" Apr 12 20:08:18 badkamer go-librespot[784]: time="2024-04-12T20:08:18+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:6tGCxVJPo7iIydUVHOjVbM" Apr 12 20:08:18 badkamer go-librespot[784]: time="2024-04-12T20:08:18+02:00" level=debug msg="requested aes key for file cbca793c1205cdd6c14a103807f764821c1b872e, gid: 6tGCxVJPo7iIydUVHOjVbM" Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=debug msg="fetched first chunk of 18, total size is 9046756 bytes" Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=debug msg="fetched chunk 1/17, size: 524288" Apr 12 20:08:19 badkamer volumio[587]: info: Initializing connection to go-librespot Websocket Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=debug msg="new websocket client" Apr 12 20:08:19 badkamer volumio[587]: info: Connection to go-librespot Websocket established Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=debug msg="fetched chunk 3/17, size: 524288" Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=debug msg="fetched chunk 2/17, size: 524288" Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=debug msg="fetched chunk 4/17, size: 524288" Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=trace msg="seek to 25727ms (diff: 117ms, samples: 1134560, bytes: 1040903)" Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=info msg="loaded track \"Falling Apart\" (uri: spotify:track:6tGCxVJPo7iIydUVHOjVbM, paused: false, position: 25727ms, duration: 206616ms)" Apr 12 20:08:19 badkamer volumio[587]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Apr 12 20:08:19 badkamer volumio[587]: info: FusionDsp - ---- read samplerate from file: 44100 Apr 12 20:08:19 badkamer volumio[587]: info: camilladsp stopping service pid 845... Apr 12 20:08:19 badkamer kernel: bcm2835_audio bcm2835_audio: failed to close VCHI service connection (status=1) Apr 12 20:08:19 badkamer volumio[587]: info: camilladsp service terminated, instance 1 Apr 12 20:08:19 badkamer volumio[587]: info: FusionDsp - If filter freq >samplerate/2 then disable it Apr 12 20:08:19 badkamer volumio[587]: info: camilladsp service started and running in background, instance 1 Apr 12 20:08:19 badkamer volumio[587]: info: camilladsp spawned new process with pid 865, instance 1, run: true Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=debug msg="fetched chunk 5/17, size: 524288" Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=trace msg="emitting websocket event: metadata" Apr 12 20:08:19 badkamer volumio[587]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6tGCxVJPo7iIydUVHOjVbM","name":"Falling Apart","artist_names":["Massane"],"album_name":"Visage 1 (No Return)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02e39a9e121bc8c93587c329cb","position":25727,"duration":206616,"release_date":"year:2020 month:4 day:2","track_number":3,"disc_number":1}} Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=trace msg="emitting websocket event: active" Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=debug msg="sending successful reply for delaer request" Apr 12 20:08:19 badkamer go-librespot[784]: time="2024-04-12T20:08:19+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 12 20:08:19 badkamer volumio[587]: SPOTIFY: received: {"type":"active","data":null} Apr 12 20:08:19 badkamer volumio[587]: info: Aligning Spotify Volume to Volumio Volume Apr 12 20:08:19 badkamer volumio[587]: info: CoreCommandRouter::volumioGetState Apr 12 20:08:19 badkamer volumio[587]: info: CorePlayQueue::getTrack 0 Apr 12 20:08:19 badkamer volumio[587]: info: Setting Spotify Volume from Volumio: 44 Apr 12 20:08:20 badkamer go-librespot[784]: time="2024-04-12T20:08:20+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 12 20:08:20 badkamer go-librespot[784]: time="2024-04-12T20:08:20+02:00" level=trace msg="emitting websocket event: playing" Apr 12 20:08:20 badkamer volumio[587]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6tGCxVJPo7iIydUVHOjVbM","play_origin":"com.spotify.service.yourlibrarymusic.ui"}} Apr 12 20:08:20 badkamer volumio[587]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 12 20:08:20 badkamer volumio[587]: TypeError: Cannot read property 'service' of undefined Apr 12 20:08:20 badkamer volumio[587]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Apr 12 20:08:20 badkamer volumio[587]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) Apr 12 20:08:20 badkamer volumio[587]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Apr 12 20:08:20 badkamer volumio[587]: at WebSocket.emit (events.js:315:20) Apr 12 20:08:20 badkamer volumio[587]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Apr 12 20:08:20 badkamer volumio[587]: at Receiver.emit (events.js:315:20) Apr 12 20:08:20 badkamer volumio[587]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Apr 12 20:08:20 badkamer volumio[587]: at internal/process/task_queues.js:149:7 Apr 12 20:08:20 badkamer volumio[587]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Apr 12 20:08:20 badkamer volumio[587]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) Apr 12 20:08:20 badkamer volumio[587]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 12 20:08:20 badkamer sudo[881]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-12 20:07 Apr 12 20:08:20 badkamer sudo[881]: 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="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET" VOLUMIO_VERSION="3.631" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"