-- Logs begin at Thu 2019-02-14 10:12:03 UTC, end at Thu 2024-10-17 15:39:22 UTC. -- Oct 17 15:38:00 volumio sudo[1015]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 17 15:38:00 volumio sudo[1015]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 17 15:38:00 volumio volumio[788]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 15:38:00 volumio volumio[788]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 15:38:00 volumio volumio[788]: info: Starting Shairport Sync Oct 17 15:38:00 volumio systemd[1]: Started go-librespot Daemon. Oct 17 15:38:00 volumio go-librespot[1022]: Librespot-go daemon starting... Oct 17 15:38:00 volumio sudo[1015]: pam_unix(sudo:session): session closed for user root Oct 17 15:38:00 volumio volumio[788]: info: Starting Shairport Sync Oct 17 15:38:01 volumio volumio[788]: info: Starting Shairport Sync Oct 17 15:38:01 volumio sudo[1023]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 17 15:38:01 volumio sudo[1023]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 17 15:38:01 volumio go-librespot[1022]: time="2024-10-17T15:38:01Z" level=info msg="generated new device id: 856fd418687a15051e68d081fdcdcbf24efa62a2" Oct 17 15:38:01 volumio go-librespot[1022]: time="2024-10-17T15:38:01Z" level=debug msg="stored credentials found for jvp2903" Oct 17 15:38:01 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 17 15:38:02 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 17 15:38:02 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 17 15:38:02 volumio sudo[1029]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 17 15:38:02 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 17 15:38:02 volumio sudo[1029]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 17 15:38:02 volumio sudo[1023]: pam_unix(sudo:session): session closed for user root Oct 17 15:38:03 volumio sudo[1033]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 17 15:38:03 volumio volumio[788]: info: Shairport-Sync Started Oct 17 15:38:03 volumio sudo[1033]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 17 15:38:03 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 17 15:38:03 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Oct 17 15:38:03 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 17 15:38:03 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 17 15:38:03 volumio volumio[788]: Error adding Membership: Error: addMembership EINVAL Oct 17 15:38:03 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 17 15:38:03 volumio sudo[1029]: pam_unix(sudo:session): session closed for user root Oct 17 15:38:03 volumio volumio[788]: info: Shairport-Sync Started Oct 17 15:38:04 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 17 15:38:04 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Oct 17 15:38:04 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 17 15:38:04 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 17 15:38:04 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 17 15:38:04 volumio sudo[1033]: pam_unix(sudo:session): session closed for user root Oct 17 15:38:04 volumio volumio[788]: info: Shairport-Sync Started Oct 17 15:38:05 volumio volumio[788]: info: go-librespot daemon successfully initialized Oct 17 15:38:07 volumio go-librespot[1022]: time="2024-10-17T15:38:07Z" level=debug msg="obtained new client token: AADVRTFjLSvUN+DVUOKFPT5UZIuWs14fZckbyFl4cjY4CzGFjXr/jGmBC/12McfpcaY8kw4cafwQbS4y++0fd/dXgNdvXZdhk2JZshGLanCV1QcMvvbL3N+oSJLH2MJnHXZCqkVcYcxN8oM6cPoCIOX4elAwj6fevZn7T9ndybsZhpi14tvsCI6w/I9zkoM+wk6kqxKlXL0NwinFnWht+CKk2va+F9UmmVACkvrN0Il2ZqzILd8IE825Ujw=" Oct 17 15:38:07 volumio go-librespot[1022]: time="2024-10-17T15:38:07Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 17 15:38:08 volumio go-librespot[1022]: time="2024-10-17T15:38:08Z" level=debug msg="completed keyexchange" Oct 17 15:38:08 volumio go-librespot[1022]: time="2024-10-17T15:38:08Z" level=debug msg="completed challenge" Oct 17 15:38:08 volumio go-librespot[1022]: time="2024-10-17T15:38:08Z" level=debug msg="authenticated as jvp2903" Oct 17 15:38:08 volumio volumio[788]: info: Initializing connection to go-librespot Websocket Oct 17 15:38:09 volumio go-librespot[1022]: time="2024-10-17T15:38:09Z" level=debug msg="authenticated as jvp2903" Oct 17 15:38:09 volumio go-librespot[1022]: time="2024-10-17T15:38:09Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 17 15:38:09 volumio go-librespot[1022]: time="2024-10-17T15:38:09Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 17 15:38:09 volumio go-librespot[1022]: time="2024-10-17T15:38:09Z" level=debug msg="dealer connection opened" Oct 17 15:38:09 volumio go-librespot[1022]: time="2024-10-17T15:38:09Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 17 15:38:09 volumio go-librespot[1022]: time="2024-10-17T15:38:09Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 17 15:38:09 volumio go-librespot[1022]: time="2024-10-17T15:38:09Z" level=debug msg="received connection id: ZWRiZTdmNjItNTQxNy00YTdmLTlkZjYtYzQzNWYxZmZiYTdkK2RlYWxlcit0Y3A6Ly8wYWNhNDIwMS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArN0UxNzdDN0Q0MkU4RUM4MUZFQ0FBQzY2QTY5NjYwMDAzNEYxNDY2ODBFODAzQkY3QUY1MjM2RTA4ODU1RDVERA==" Oct 17 15:38:10 volumio go-librespot[1022]: time="2024-10-17T15:38:10Z" level=debug msg="put connect state because NEW_DEVICE" Oct 17 15:38:10 volumio go-librespot[1022]: time="2024-10-17T15:38:10Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 17 15:38:10 volumio go-librespot[1022]: time="2024-10-17T15:38:10Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 17 15:38:10 volumio go-librespot[1022]: time="2024-10-17T15:38:10Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Oct 17 15:38:10 volumio mpd[1010]: Oct 17 15:38 : exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 17 15:38:10 volumio mpd[1010]: Oct 17 15:38 : exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Oct 17 15:38:10 volumio mpd[1010]: Oct 17 15:38 : exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Oct 17 15:38:11 volumio systemd[1]: Started Music Player Daemon. Oct 17 15:38:11 volumio volumio[788]: Upnp client error: Error: This socket has been ended by the other party Oct 17 15:38:11 volumio sudo[995]: pam_unix(sudo:session): session closed for user root Oct 17 15:38:11 volumio volumio[788]: Upnp client error: Error: This socket has been ended by the other party Oct 17 15:38:11 volumio volumio[788]: Upnp client error: Error: This socket has been ended by the other party Oct 17 15:38:11 volumio volumio[788]: error: updateQueue error: null Oct 17 15:38:12 volumio volumio[996]: Generating RSA private key, 4096 bit long modulus (2 primes) Oct 17 15:38:26 volumio volumio[788]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 17 15:38:26 volumio volumio[788]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 15:38:26 volumio volumio[788]: error: Plugin music_service ytcr failed to complete 'onStart' in a timely fashion Oct 17 15:38:26 volumio volumio[788]: info: ------------------------------------------- Oct 17 15:38:26 volumio volumio[788]: info: ----- MyVolumio plugins startup ---- Oct 17 15:38:26 volumio volumio[788]: info: ------------------------------------------- Oct 17 15:38:26 volumio volumio[788]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 17 15:38:37 volumio volumio[996]: .................................................................++++ Oct 17 15:38:46 volumio volumio[788]: info: Discovery: adding 67ec844f-eff6-4f43-a68d-b823bf73da95 Oct 17 15:38:46 volumio volumio[788]: info: mDNS: Found device Volumio Oct 17 15:38:46 volumio volumio[788]: info: CoreCommandRouter::volumioGetState Oct 17 15:38:46 volumio volumio[788]: info: CorePlayQueue::getTrack 0 Oct 17 15:38:46 volumio volumio[788]: info: Discovery: this is already registered, 67ec844f-eff6-4f43-a68d-b823bf73da95 Oct 17 15:38:46 volumio volumio[788]: info: mDNS: Found device Volumio Oct 17 15:38:46 volumio volumio[788]: info: CoreCommandRouter::volumioGetState Oct 17 15:38:46 volumio volumio[788]: info: CorePlayQueue::getTrack 0 Oct 17 15:38:46 volumio go-librespot[1022]: time="2024-10-17T15:38:46Z" level=debug msg="new websocket client" Oct 17 15:38:47 volumio volumio[788]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 Oct 17 15:38:47 volumio volumio[788]: error: MyVolumio Plugin failed to start in a timely fashion Oct 17 15:38:47 volumio volumio[788]: info: BOOT COMPLETED Oct 17 15:38:47 volumio volumio[788]: [Metrics] CommandRouter: 168s 796.78ms Oct 17 15:38:47 volumio volumio[788]: info: CoreCommandRouter::volumiosetStartupVolume Oct 17 15:38:47 volumio volumio[788]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 15:38:47 volumio volumio[788]: info: VolumeController:: Setting startup Volume 55 Oct 17 15:38:47 volumio volumio[788]: info: VolumeController::SetAlsaVolume55 Oct 17 15:38:47 volumio volumio[788]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 15:38:47 volumio volumio[788]: info: CoreCommandRouter::Close All Modals sent Oct 17 15:38:47 volumio volumio[788]: info: CoreCommandRouter::Close All Modals sent Oct 17 15:38:47 volumio volumio[788]: info: CoreCommandRouter::volumioGetState Oct 17 15:38:47 volumio volumio[788]: info: CorePlayQueue::getTrack 0 Oct 17 15:38:47 volumio volumio[788]: info: CoreStateMachine::pushState Oct 17 15:38:47 volumio volumio[788]: info: CorePlayQueue::getTrack 0 Oct 17 15:38:47 volumio volumio[788]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 15:38:47 volumio volumio[788]: info: CoreCommandRouter::volumioPushState Oct 17 15:38:49 volumio volumio[788]: info: Connection to go-librespot Websocket established Oct 17 15:38:49 volumio volumio[788]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 3 Oct 17 15:38:49 volumio volumio[788]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 4 Oct 17 15:38:49 volumio volumio[788]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 17 15:38:49 volumio volumio[788]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 17 15:38:49 volumio volumio[788]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 17 15:38:50 volumio volumio[788]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 17 15:38:50 volumio volumio[788]: info: Adding plugin bluetooth to MyMusic Plugins Oct 17 15:38:50 volumio volumio[788]: info: Adding plugin multiroom to MyMusic Plugins Oct 17 15:38:50 volumio volumio[788]: info: Adding plugin cd_controller to MyMusic Plugins Oct 17 15:38:51 volumio volumio[788]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 17 15:38:51 volumio volumio[788]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 17 15:38:51 volumio volumio[788]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 17 15:38:52 volumio go-librespot[1022]: time="2024-10-17T15:38:52Z" level=debug msg="handling transfer player command from a73b0734c36a36f80bdf73eeea14656d04d1fb8a" Oct 17 15:38:52 volumio go-librespot[1022]: time="2024-10-17T15:38:52Z" level=trace msg="fetched new page 0 with 22 items (list: 22)" Oct 17 15:38:52 volumio go-librespot[1022]: time="2024-10-17T15:38:52Z" level=debug msg="shuffled context with seed 6926943042349327182 (len: 22, keep: 5)" Oct 17 15:38:52 volumio go-librespot[1022]: time="2024-10-17T15:38:52Z" level=debug msg="loading track spotify:track:6PLIfuZYh2IrRNqJIEH26S (paused: true, position: 112733ms)" Oct 17 15:38:52 volumio volumio[996]: ............................++++ Oct 17 15:38:52 volumio volumio[996]: e is 65537 (0x010001) Oct 17 15:38:52 volumio go-librespot[1022]: time="2024-10-17T15:38:52Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 15:38:52 volumio go-librespot[1022]: time="2024-10-17T15:38:52Z" level=trace msg="emitting websocket event: will_play" Oct 17 15:38:52 volumio go-librespot[1022]: time="2024-10-17T15:38:52Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 17 15:38:52 volumio go-librespot[1022]: time="2024-10-17T15:38:52Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1348" Oct 17 15:38:52 volumio go-librespot[1022]: time="2024-10-17T15:38:52Z" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:6PLIfuZYh2IrRNqJIEH26S" Oct 17 15:38:52 volumio go-librespot[1022]: time="2024-10-17T15:38:52Z" level=debug msg="requested aes key for file a8b0603ea64a51af69f0be2331038c95ba7134e9, gid: 6PLIfuZYh2IrRNqJIEH26S" Oct 17 15:38:52 volumio volumio[996]: writing RSA key Oct 17 15:38:52 volumio go-librespot[1022]: time="2024-10-17T15:38:52Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1128" Oct 17 15:38:54 volumio go-librespot[1022]: time="2024-10-17T15:38:54Z" level=debug msg="fetched first chunk of 13, total size is 6579348 bytes" Oct 17 15:38:56 volumio go-librespot[1022]: time="2024-10-17T15:38:56Z" level=debug msg="fetched chunk 3/12, size: 524288" Oct 17 15:38:59 volumio go-librespot[1022]: time="2024-10-17T15:38:59Z" level=debug msg="fetched chunk 1/12, size: 524288" Oct 17 15:38:59 volumio go-librespot[1022]: time="2024-10-17T15:38:59Z" level=debug msg="fetched chunk 10/12, size: 524288" Oct 17 15:38:59 volumio go-librespot[1022]: time="2024-10-17T15:38:59Z" level=debug msg="fetched chunk 9/12, size: 524288" Oct 17 15:38:59 volumio go-librespot[1022]: time="2024-10-17T15:38:59Z" level=debug msg="fetched chunk 2/12, size: 524288" Oct 17 15:38:59 volumio go-librespot[1022]: time="2024-10-17T15:38:59Z" level=debug msg="fetched chunk 11/12, size: 524288" Oct 17 15:38:59 volumio go-librespot[1022]: time="2024-10-17T15:38:59Z" level=debug msg="fetched chunk 8/12, size: 524288" Oct 17 15:38:59 volumio go-librespot[1022]: time="2024-10-17T15:38:59Z" level=trace msg="seek to 112733ms (diff: 143ms, samples: 4971525, bytes: 4712901)" Oct 17 15:39:00 volumio go-librespot[1022]: time="2024-10-17T15:39:00Z" level=info msg="loaded track \"Hablar De Nada\" (uri: spotify:track:6PLIfuZYh2IrRNqJIEH26S, paused: true, position: 112733ms, duration: 159306ms)" Oct 17 15:39:00 volumio go-librespot[1022]: time="2024-10-17T15:39:00Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 15:39:00 volumio go-librespot[1022]: time="2024-10-17T15:39:00Z" level=trace msg="emitting websocket event: metadata" Oct 17 15:39:00 volumio go-librespot[1022]: time="2024-10-17T15:39:00Z" level=trace msg="emitting websocket event: active" Oct 17 15:39:00 volumio go-librespot[1022]: time="2024-10-17T15:39:00Z" level=debug msg="sending successful reply for delaer request" Oct 17 15:39:00 volumio go-librespot[1022]: time="2024-10-17T15:39:00Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 17 15:39:00 volumio go-librespot[1022]: time="2024-10-17T15:39:00Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 17 15:39:00 volumio go-librespot[1022]: time="2024-10-17T15:39:00Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 17 15:39:00 volumio go-librespot[1022]: time="2024-10-17T15:39:00Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 15:39:00 volumio go-librespot[1022]: time="2024-10-17T15:39:00Z" level=trace msg="emitting websocket event: paused" Oct 17 15:39:00 volumio go-librespot[1022]: time="2024-10-17T15:39:00Z" level=debug msg="fetched chunk 12/12, size: 287892" Oct 17 15:39:03 volumio go-librespot[1022]: time="2024-10-17T15:39:03Z" level=debug msg="handling resume player command from a73b0734c36a36f80bdf73eeea14656d04d1fb8a" Oct 17 15:39:03 volumio go-librespot[1022]: time="2024-10-17T15:39:03Z" level=trace msg="seek to 112733ms (diff: 143ms, samples: 4971525, bytes: 4712901)" Oct 17 15:39:03 volumio go-librespot[1022]: time="2024-10-17T15:39:03Z" level=debug msg="resume track at 112243ms" Oct 17 15:39:03 volumio go-librespot[1022]: time="2024-10-17T15:39:03Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 15:39:03 volumio go-librespot[1022]: time="2024-10-17T15:39:03Z" level=debug msg="sending successful reply for delaer request" Oct 17 15:39:03 volumio go-librespot[1022]: time="2024-10-17T15:39:03Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 15:39:03 volumio go-librespot[1022]: time="2024-10-17T15:39:03Z" level=trace msg="emitting websocket event: playing" Oct 17 15:39:08 volumio volumio[788]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 17 15:39:08 volumio volumio[788]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 17 15:39:08 volumio volumio[788]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 15:39:08 volumio volumio[788]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 15:39:08 volumio volumio[788]: info: Starting MyVolumio Remote Streaming Endpoints Oct 17 15:39:09 volumio volumio[788]: info: MyVolumio login type: Token Oct 17 15:39:09 volumio volumio[788]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 17 15:39:09 volumio volumio[788]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 17 15:39:11 volumio volumio[788]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 17 15:39:11 volumio volumio[788]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 17 15:39:11 volumio volumio[788]: info: Streaming services startup Oct 17 15:39:11 volumio volumio[788]: info: Starting Streaming Daemon Oct 17 15:39:12 volumio sudo[1081]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 17 15:39:12 volumio sudo[1081]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 17 15:39:12 volumio systemd[1]: Stopping Volumio Streaming Daemon... Oct 17 15:39:12 volumio systemd[1]: volumio-streaming-daemon.service: Main process exited, code=killed, status=15/TERM Oct 17 15:39:12 volumio systemd[1]: volumio-streaming-daemon.service: Succeeded. Oct 17 15:39:12 volumio systemd[1]: Stopped Volumio Streaming Daemon. Oct 17 15:39:12 volumio systemd[1]: Started Volumio Streaming Daemon. Oct 17 15:39:13 volumio sudo[1081]: pam_unix(sudo:session): session closed for user root Oct 17 15:39:13 volumio volumio-streaming-daemon[1087]: ############################ Oct 17 15:39:13 volumio volumio-streaming-daemon[1087]: # Volumio Streaming Daemon # Oct 17 15:39:13 volumio volumio-streaming-daemon[1087]: # Running on port 7777 # Oct 17 15:39:13 volumio volumio-streaming-daemon[1087]: ############################ Oct 17 15:39:13 volumio volumio-streaming-daemon[1087]: Environment: production Oct 17 15:39:14 volumio volumio[788]: info: Getting Spotify volume Oct 17 15:39:14 volumio volumio[788]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 17 15:39:14 volumio volumio[788]: SPOTIFY: BQAFX2xyXgGCG29t7yrD7ReC2HWGkMBxzk11A50gOkZh1VFLBN_nnND0VBiG-hLVTkzu1aBZHxeiNQt47oK7D4EZjSzZ_1QWFjvef9m-7SeZ5JQymsBKKvhc-iOWhoLZICGYp960tUbrkULqBDVwkAnzvrN3CQcqDAVNBI_CxDs67UAWmKZS9QPH6Yct9GolXa61aw72rl2nLeb4vbmVwcS2cEZGID9V5xAkQQwwR3khBxgw1Lh4Y0o Oct 17 15:39:14 volumio volumio[788]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 17 15:39:14 volumio volumio[788]: info: New Spotify access token = BQAFX2xyXgGCG29t7yrD7ReC2HWGkMBxzk11A50gOkZh1VFLBN_nnND0VBiG-hLVTkzu1aBZHxeiNQt47oK7D4EZjSzZ_1QWFjvef9m-7SeZ5JQymsBKKvhc-iOWhoLZICGYp960tUbrkULqBDVwkAnzvrN3CQcqDAVNBI_CxDs67UAWmKZS9QPH6Yct9GolXa61aw72rl2nLeb4vbmVwcS2cEZGID9V5xAkQQwwR3khBxgw1Lh4Y0o Oct 17 15:39:14 volumio volumio[788]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 17 15:39:15 volumio volumio[788]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6PLIfuZYh2IrRNqJIEH26S","play_origin":"playlist"}} Oct 17 15:39:15 volumio volumio[788]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6PLIfuZYh2IrRNqJIEH26S","name":"Hablar De Nada","artist_names":["Viva Suecia"],"album_name":"El Amor De La Clase Que Sea","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b44457cf24aab471ac0d5709","position":112733,"duration":159306,"release_date":"year:2022 month:10 day:6","track_number":5,"disc_number":1}} Oct 17 15:39:15 volumio volumio[788]: SPOTIFY: received: {"type":"active","data":null} Oct 17 15:39:15 volumio volumio[788]: info: Aligning Spotify Volume to Volumio Volume Oct 17 15:39:15 volumio volumio[788]: info: CoreCommandRouter::volumioGetState Oct 17 15:39:15 volumio volumio[788]: info: CorePlayQueue::getTrack 0 Oct 17 15:39:15 volumio volumio[788]: info: Setting Spotify Volume from Volumio: 55 Oct 17 15:39:15 volumio volumio[788]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6PLIfuZYh2IrRNqJIEH26S","play_origin":"playlist"}} Oct 17 15:39:15 volumio volumio[788]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 17 15:39:15 volumio volumio[788]: TypeError: Cannot read property 'service' of undefined Oct 17 15:39:15 volumio volumio[788]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Oct 17 15:39:15 volumio volumio[788]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Oct 17 15:39:15 volumio volumio[788]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Oct 17 15:39:15 volumio volumio[788]: at WebSocket.emit (events.js:315:20) Oct 17 15:39:15 volumio volumio[788]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Oct 17 15:39:15 volumio volumio[788]: at Receiver.emit (events.js:315:20) Oct 17 15:39:15 volumio volumio[788]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Oct 17 15:39:15 volumio volumio[788]: at internal/process/task_queues.js:149:7 Oct 17 15:39:15 volumio volumio[788]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Oct 17 15:39:15 volumio volumio[788]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) Oct 17 15:39:15 volumio volumio[788]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Oct 17 15:39:15 volumio volumio[788]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 17 15:39:21 volumio go-librespot[1022]: time="2024-10-17T15:39:21Z" level=debug msg="handling pause player command from a73b0734c36a36f80bdf73eeea14656d04d1fb8a" Oct 17 15:39:21 volumio go-librespot[1022]: time="2024-10-17T15:39:21Z" level=debug msg="pause track at 127107ms" Oct 17 15:39:21 volumio go-librespot[1022]: time="2024-10-17T15:39:21Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 15:39:21 volumio go-librespot[1022]: time="2024-10-17T15:39:21Z" level=debug msg="sending successful reply for delaer request" Oct 17 15:39:21 volumio go-librespot[1022]: time="2024-10-17T15:39:21Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 15:39:21 volumio go-librespot[1022]: time="2024-10-17T15:39:21Z" level=trace msg="emitting websocket event: paused" Oct 17 15:39:22 volumio sudo[1100]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-17 15:38 Oct 17 15:39:22 volumio sudo[1100]: 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="682e0b17433cee9f9da31457f545345105e06e63" VOLUMIO_FE_VERSION="fba46add594d630e1b506bc42f1beddaad53fb64" VOLUMIO_FE3_VERSION="c23fef6dba8e02db978bd39bd8d26872e60ada6e" VOLUMIO_BE_VERSION="f7885966dee9f148ddf4f5050103a7d6734e1a10" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 20 Dec 2021 04:57:50 PM CET" VOLUMIO_VERSION="3.179" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="6d5d4c489f0b1e608d9cefb791a9102d"