-- Logs begin at Thu 2019-02-14 19:12:00 JST, end at Sat 2024-10-05 10:21:20 JST. -- Oct 05 10:21:03 volumio ntpd[531]: receive: Unexpected origin timestamp 0xe9f85a8b.d76083b8 does not match aorg 0000000000.00000000 from server@129.250.35.251 xmt 0xeaab12ff.78d03360 Oct 05 10:21:03 volumio ntpd[531]: receive: Unexpected origin timestamp 0xe9f85a8b.d72eb35a does not match aorg 0000000000.00000000 from server@202.181.103.212 xmt 0xeaab12ff.78c7292a Oct 05 10:21:03 volumio systemd[1]: Starting Daily apt download activities... Oct 05 10:21:03 volumio ntpd[531]: receive: Unexpected origin timestamp 0xe9f85a8b.d75375f9 does not match aorg 0000000000.00000000 from server@162.159.200.123 xmt 0xeaab12ff.78fe8948 Oct 05 10:21:03 volumio ntpd[531]: receive: Unexpected origin timestamp 0xe9f85a8b.d75aa999 does not match aorg 0000000000.00000000 from server@172.105.204.105 xmt 0xeaab12ff.78ebd2da Oct 05 10:21:03 volumio ntpd[531]: receive: Unexpected origin timestamp 0xe9f85a8b.d74352c2 does not match aorg 0000000000.00000000 from server@122.215.240.52 xmt 0xeaab12ff.77fbfd6d Oct 05 10:21:03 volumio ntpd[531]: receive: Unexpected origin timestamp 0xe9f85a8b.d74c8f6a does not match aorg 0000000000.00000000 from server@163.44.97.196 xmt 0xeaab12ff.79128fd6 Oct 05 10:21:03 volumio volumio[820]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 05 10:21:03 volumio volumio[820]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 05 10:21:03 volumio volumio[820]: info: [1728091263654] CoreMusicLibrary::Adding element Last_100 Oct 05 10:21:03 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 10:21:03 volumio volumio[820]: Cannot find translation for sourceMedia Servers Oct 05 10:21:03 volumio volumio[820]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 05 10:21:03 volumio volumio[820]: info: [1728091263703] CoreMusicLibrary::Adding element Webradio Oct 05 10:21:03 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 10:21:03 volumio volumio[820]: Cannot find translation for sourceMedia Servers Oct 05 10:21:03 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 05 10:21:03 volumio volumio[820]: info: Creating Spotify config file Oct 05 10:21:03 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 10:21:03 volumio volumio[820]: info: [youtube2-auth] Starting auth flow... Oct 05 10:21:04 volumio volumio[820]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 05 10:21:04 volumio volumio[820]: info: [1728091264051] CoreMusicLibrary::Adding element YouTube2 Oct 05 10:21:04 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 10:21:04 volumio volumio[820]: Cannot find translation for sourceMedia Servers Oct 05 10:21:04 volumio volumio[820]: Cannot find translation for sourceYouTube2 Oct 05 10:21:04 volumio volumio[820]: info: Volumio Calling Home Oct 05 10:21:04 volumio volumio[820]: Starting albumart workers Oct 05 10:21:04 volumio volumio[820]: Starting albumart workers Oct 05 10:21:04 volumio volumio[820]: Starting albumart workers Oct 05 10:21:04 volumio volumio[820]: info: Completed starting Core Plugins Oct 05 10:21:04 volumio volumio[820]: info: ------------------------------------------- Oct 05 10:21:04 volumio volumio[820]: info: ----- MyVolumio plugins startup ---- Oct 05 10:21:04 volumio volumio[820]: info: ------------------------------------------- Oct 05 10:21:04 volumio volumio[820]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 05 10:21:04 volumio volumio[820]: info: MPD Permissions set Oct 05 10:21:04 volumio volumio[820]: info: Upmpdcli Daemon Started Oct 05 10:21:05 volumio volumio[820]: info: Discovery: A device disappeared from network Oct 05 10:21:05 volumio volumio[820]: info: Discovery: Device volumio disappeared from network Oct 05 10:21:05 volumio volumio[820]: info: Volumio called home Oct 05 10:21:05 volumio volumio[820]: info: Spotify config file written Oct 05 10:21:05 volumio sudo[992]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 05 10:21:05 volumio sudo[992]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 10:21:05 volumio systemd[1]: Stopping go-librespot Daemon... Oct 05 10:21:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 05 10:21:05 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 05 10:21:05 volumio systemd[1]: Stopped go-librespot Daemon. Oct 05 10:21:05 volumio systemd[1]: Started go-librespot Daemon. Oct 05 10:21:05 volumio sudo[992]: pam_unix(sudo:session): session closed for user root Oct 05 10:21:05 volumio go-librespot[1001]: Librespot-go daemon starting... Oct 05 10:21:05 volumio go-librespot[1001]: time="2024-10-05T10:21:05+09:00" level=info msg="generated new device id: 71cf8a030a6c55660baf7344125214cf8629f378" Oct 05 10:21:05 volumio volumio[820]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 1 Oct 05 10:21:05 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 10:21:05 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 10:21:05 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 10:21:05 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 10:21:05 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 10:21:05 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 10:21:05 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 10:21:05 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 10:21:06 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 05 10:21:06 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 10:21:06 volumio volumio[820]: error: [youtube2-auth] Failed to obtain 'grant access page' info: "invalid_client - The OAuth client was not found." Oct 05 10:21:06 volumio volumio[820]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 10:21:06 volumio systemd[1]: apt-daily.service: Succeeded. Oct 05 10:21:06 volumio systemd[1]: Started Daily apt download activities. Oct 05 10:21:06 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Oct 05 10:21:06 volumio mpd[958]: exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 05 10:21:06 volumio mpd[958]: output: No 'audio_output' defined in config file Oct 05 10:21:06 volumio mpd[958]: output: Attempt to detect audio output device Oct 05 10:21:06 volumio mpd[958]: output: Attempting to detect a alsa audio device Oct 05 10:21:06 volumio mpd[958]: output: Successfully detected a alsa audio device Oct 05 10:21:06 volumio mpd[958]: exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Oct 05 10:21:06 volumio mpd[958]: exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Oct 05 10:21:06 volumio mpd[958]: zeroconf: No global port, disabling zeroconf Oct 05 10:21:06 volumio systemd[1]: Started Music Player Daemon. Oct 05 10:21:06 volumio sudo[940]: pam_unix(sudo:session): session closed for user root Oct 05 10:21:06 volumio go-librespot[1001]: time="2024-10-05T10:21:06+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 05 10:21:06 volumio go-librespot[1001]: time="2024-10-05T10:21:06+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 05 10:21:06 volumio go-librespot[1001]: time="2024-10-05T10:21:06+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 05 10:21:06 volumio go-librespot[1001]: time="2024-10-05T10:21:06+09:00" level=debug msg="zeroconf server listening on port 41867" Oct 05 10:21:07 volumio mpd[958]: client: [0] opened from local Oct 05 10:21:07 volumio sudo[1060]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.10.108/Yoshio /mnt/NAS/Yoshio Oct 05 10:21:07 volumio volumio[820]: info: Starting Shairport Sync Oct 05 10:21:07 volumio sudo[1060]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 10:21:07 volumio volumio[820]: info: Starting Shairport Sync Oct 05 10:21:07 volumio kernel: CIFS: Attempting to mount //192.168.10.108/Yoshio Oct 05 10:21:07 volumio volumio[820]: info: Starting Shairport Sync Oct 05 10:21:07 volumio sudo[1079]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 05 10:21:07 volumio sudo[1079]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 10:21:07 volumio sudo[1083]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 05 10:21:07 volumio sudo[1083]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 10:21:07 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 05 10:21:07 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 05 10:21:07 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 05 10:21:07 volumio volumio[820]: info: Discovery: adding d1dfa324-4afd-4978-9955-82e371951dcd Oct 05 10:21:07 volumio volumio[820]: info: Discovery: Found device Volumio Oct 05 10:21:07 volumio volumio[820]: info: CoreCommandRouter::volumioGetState Oct 05 10:21:07 volumio volumio[820]: info: CorePlayQueue::getTrack 0 Oct 05 10:21:07 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 05 10:21:07 volumio sudo[1079]: pam_unix(sudo:session): session closed for user root Oct 05 10:21:07 volumio sudo[1092]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 05 10:21:07 volumio sudo[1092]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 10:21:07 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 05 10:21:07 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Oct 05 10:21:07 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 05 10:21:07 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 05 10:21:07 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 05 10:21:07 volumio volumio[820]: error: updateQueue error: null Oct 05 10:21:07 volumio sudo[1083]: pam_unix(sudo:session): session closed for user root Oct 05 10:21:07 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 05 10:21:07 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Oct 05 10:21:07 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 05 10:21:07 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 05 10:21:07 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 05 10:21:07 volumio sudo[1092]: pam_unix(sudo:session): session closed for user root Oct 05 10:21:07 volumio volumio[820]: info: Shairport-Sync Started Oct 05 10:21:07 volumio volumio[820]: Error adding Membership: Error: addMembership EINVAL Oct 05 10:21:07 volumio volumio[820]: info: Shairport-Sync Started Oct 05 10:21:07 volumio volumio[820]: info: Shairport-Sync Started Oct 05 10:21:07 volumio volumio[820]: info: CoreCommandRouter::volumioGetState Oct 05 10:21:07 volumio volumio[820]: info: CorePlayQueue::getTrack 0 Oct 05 10:21:08 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Oct 05 10:21:08 volumio systemd[1]: Started Daily apt upgrade and clean activities. Oct 05 10:21:08 volumio mpd[958]: client: [1] opened from 127.0.0.1:32930 Oct 05 10:21:08 volumio mpd[958]: client: [2] opened from 127.0.0.1:32934 Oct 05 10:21:08 volumio mpd[958]: exception: Failed to read mixer for 'default detected output': no such mixer control: PCM Oct 05 10:21:08 volumio volumio[757]: Generating RSA private key, 4096 bit long modulus (2 primes) Oct 05 10:21:09 volumio volumio[820]: info: go-librespot daemon successfully initialized Oct 05 10:21:11 volumio volumio-remote-updater[346]: [2024-10-05 10:21:11] [connect] Successful connection Oct 05 10:21:11 volumio volumio-remote-updater[346]: [2024-10-05 10:21:11] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1728091271 101 Oct 05 10:21:11 volumio volumio[820]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 2 Oct 05 10:21:12 volumio volumio[820]: info: Initializing connection to go-librespot Websocket Oct 05 10:21:13 volumio go-librespot[1001]: time="2024-10-05T10:21:13+09:00" level=debug msg="new websocket client" Oct 05 10:21:13 volumio volumio[820]: info: Connection to go-librespot Websocket established Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 05 10:21:13 volumio volumio[820]: info: Adding plugin bluetooth to MyMusic Plugins Oct 05 10:21:13 volumio volumio[820]: info: Adding plugin multiroom to MyMusic Plugins Oct 05 10:21:13 volumio volumio[820]: info: Adding plugin metavolumio to MyMusic Plugins Oct 05 10:21:13 volumio volumio[820]: info: Adding plugin cd_controller to MyMusic Plugins Oct 05 10:21:13 volumio volumio[820]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 05 10:21:13 volumio volumio[820]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 05 10:21:13 volumio volumio[820]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 05 10:21:13 volumio sudo[1060]: pam_unix(sudo:session): session closed for user root Oct 05 10:21:13 volumio kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Oct 05 10:21:13 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -113 Oct 05 10:21:15 volumio volumio[820]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 05 10:21:15 volumio volumio[820]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 05 10:21:15 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 05 10:21:15 volumio volumio[820]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 05 10:21:15 volumio volumio[820]: info: Starting MyVolumio Remote Streaming Endpoints Oct 05 10:21:15 volumio volumio[820]: info: MyVolumio login type: Token Oct 05 10:21:15 volumio volumio[820]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 05 10:21:15 volumio volumio[820]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 05 10:21:16 volumio go-librespot[1001]: time="2024-10-05T10:21:16+09:00" level=debug msg="obtained new client token: AACKOJ5CyuZb+2QrFO0u0NQqDWQtM2owgemoa9K7GKjj4bJ2MGWrhoIjawLQ4JSxuf+AMa08GAG5HGNR0iljBgXFR33NmAfGYVMPpioCdViSGybl4XddOKwxBbFi5APkYDqlp5oi0OoTFvCZJQSQwhAYx+U6vDMRShrGsDM0grnCey+6GsQ7UGkCg6cUF9y/ZknJgAFY3MVwB1p2P9Vd8e+560vb82kITdcM6+O9QjMrG7w0k0ps+HrmvJUt1A==" Oct 05 10:21:16 volumio go-librespot[1001]: time="2024-10-05T10:21:16+09:00" level=debug msg="completed keyexchange" Oct 05 10:21:16 volumio go-librespot[1001]: time="2024-10-05T10:21:16+09:00" level=debug msg="completed challenge" Oct 05 10:21:16 volumio go-librespot[1001]: time="2024-10-05T10:21:16+09:00" level=debug msg="authenticated as pxc01330" Oct 05 10:21:16 volumio go-librespot[1001]: time="2024-10-05T10:21:16+09:00" level=debug msg="authenticated as pxc01330" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="dealer connection opened" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=info msg="accepted zeroconf user pxc01330 from iPhone" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="received connection id: YTFkZGVmZmUtNWIwZC00MzA2LWJiZDctOWU1YzBhYzg3ZTVjK2RlYWxlcit0Y3A6Ly8wYWM5NDk1Zi5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArMThGMzJDODA1OThBRjc5Nzg2MzJFNjI2RUMyODA3RDUxQjg1Njc0MkRFRkRGRDRFODU2NURERTcxMDA2OTFGNw==" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="put connect state because NEW_DEVICE" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="handling transfer player command from 3ed6bfee058675945b030dc012b6e2b639250cd3" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=trace msg="fetched new page 0 with 18 items (list: 18)" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="loading track spotify:track:7jqoWo7hC5hTugEo3gYi1M (paused: false, position: 231370ms)" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=trace msg="emitting websocket event: will_play" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:7jqoWo7hC5hTugEo3gYi1M" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="requested aes key for file bacf7195cef92b8f6fc51e5d29b9836b55f7aadf, gid: 7jqoWo7hC5hTugEo3gYi1M" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1367" Oct 05 10:21:17 volumio go-librespot[1001]: time="2024-10-05T10:21:17+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1145" Oct 05 10:21:18 volumio go-librespot[1001]: time="2024-10-05T10:21:18+09:00" level=debug msg="fetched first chunk of 32, total size is 16777204 bytes" Oct 05 10:21:18 volumio go-librespot[1001]: time="2024-10-05T10:21:18+09:00" level=debug msg="fetched chunk 1/31, size: 524288" Oct 05 10:21:18 volumio volumio[820]: info: Starting Streaming Service Transparent Proxy Oct 05 10:21:18 volumio volumio[820]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 05 10:21:18 volumio volumio[820]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 05 10:21:18 volumio volumio[820]: info: Streaming services startup Oct 05 10:21:18 volumio volumio[820]: info: Starting Streaming Daemon Oct 05 10:21:18 volumio go-librespot[1001]: time="2024-10-05T10:21:18+09:00" level=debug msg="fetched chunk 21/31, size: 524288" Oct 05 10:21:18 volumio sudo[1143]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 05 10:21:18 volumio go-librespot[1001]: time="2024-10-05T10:21:18+09:00" level=debug msg="fetched chunk 3/31, size: 524288" Oct 05 10:21:18 volumio sudo[1143]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 10:21:18 volumio go-librespot[1001]: time="2024-10-05T10:21:18+09:00" level=debug msg="fetched chunk 2/31, size: 524288" Oct 05 10:21:18 volumio go-librespot[1001]: time="2024-10-05T10:21:18+09:00" level=trace msg="seek to 231370ms (diff: 464ms, samples: 10203417, bytes: 11234499)" Oct 05 10:21:18 volumio sudo[1143]: pam_unix(sudo:session): session closed for user root Oct 05 10:21:18 volumio volumio[820]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 05 10:21:18 volumio go-librespot[1001]: time="2024-10-05T10:21:18+09:00" level=debug msg="fetched chunk 23/31, size: 524288" Oct 05 10:21:18 volumio go-librespot[1001]: time="2024-10-05T10:21:18+09:00" level=debug msg="fetched chunk 22/31, size: 524288" Oct 05 10:21:18 volumio go-librespot[1001]: time="2024-10-05T10:21:18+09:00" level=debug msg="fetched chunk 24/31, size: 524288" Oct 05 10:21:18 volumio go-librespot[1001]: time="2024-10-05T10:21:18+09:00" level=info msg="loaded track \"RIOT IN LAGOS - Live\" (uri: spotify:track:7jqoWo7hC5hTugEo3gYi1M, paused: false, position: 231370ms, duration: 344964ms)" Oct 05 10:21:19 volumio volumio[757]: ........................................++++ Oct 05 10:21:19 volumio go-librespot[1001]: time="2024-10-05T10:21:19+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 10:21:19 volumio go-librespot[1001]: time="2024-10-05T10:21:19+09:00" level=trace msg="emitting websocket event: metadata" Oct 05 10:21:19 volumio go-librespot[1001]: time="2024-10-05T10:21:19+09:00" level=trace msg="emitting websocket event: active" Oct 05 10:21:19 volumio go-librespot[1001]: time="2024-10-05T10:21:19+09:00" level=debug msg="sending successful reply for delaer request" Oct 05 10:21:19 volumio volumio[820]: info: Getting Spotify volume Oct 05 10:21:19 volumio go-librespot[1001]: time="2024-10-05T10:21:19+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 05 10:21:19 volumio go-librespot[1001]: time="2024-10-05T10:21:19+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 05 10:21:19 volumio go-librespot[1001]: time="2024-10-05T10:21:19+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 05 10:21:19 volumio volumio[820]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7jqoWo7hC5hTugEo3gYi1M","play_origin":"album"}} Oct 05 10:21:19 volumio volumio[820]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7jqoWo7hC5hTugEo3gYi1M","name":"RIOT IN LAGOS - Live","artist_names":["YELLOW MAGIC ORCHESTRA"],"album_name":"LONDONYMO -YELLOW MAGIC ORCHESTRA LIVE IN LONDON 15/6 08-","album_cover_url":"https://i.scdn.co/image/ab67616d00001e022f70babb700c0c4c88489020","position":231370,"duration":344964,"release_date":"year:2008 month:12 day:10","track_number":6,"disc_number":1}} Oct 05 10:21:19 volumio volumio[820]: SPOTIFY: received: {"type":"active","data":null} Oct 05 10:21:19 volumio volumio[820]: info: Aligning Spotify Volume to Volumio Volume Oct 05 10:21:19 volumio volumio[820]: info: CoreCommandRouter::volumioGetState Oct 05 10:21:19 volumio volumio[820]: info: CorePlayQueue::getTrack 0 Oct 05 10:21:19 volumio volumio[820]: error: Cannot start Volumio Streaming Daemon Oct 05 10:21:19 volumio volumio[820]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 05 10:21:19 volumio volumio[820]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 05 10:21:19 volumio volumio[820]: info: Cannot mount NAS Yoshio at system boot, trial number 2 ,retrying in 5 seconds Oct 05 10:21:19 volumio volumio[820]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 3 Oct 05 10:21:19 volumio go-librespot[1001]: time="2024-10-05T10:21:19+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 10:21:19 volumio go-librespot[1001]: time="2024-10-05T10:21:19+09:00" level=trace msg="emitting websocket event: playing" Oct 05 10:21:19 volumio volumio[820]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:7jqoWo7hC5hTugEo3gYi1M","play_origin":"album"}} Oct 05 10:21:19 volumio volumio[820]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 05 10:21:19 volumio volumio[820]: TypeError: Cannot read property 'service' of undefined Oct 05 10:21:19 volumio volumio[820]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Oct 05 10:21:19 volumio volumio[820]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) Oct 05 10:21:19 volumio volumio[820]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Oct 05 10:21:19 volumio volumio[820]: at WebSocket.emit (events.js:315:20) Oct 05 10:21:19 volumio volumio[820]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Oct 05 10:21:19 volumio volumio[820]: at Receiver.emit (events.js:315:20) Oct 05 10:21:19 volumio volumio[820]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Oct 05 10:21:19 volumio volumio[820]: at internal/process/task_queues.js:149:7 Oct 05 10:21:19 volumio volumio[820]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Oct 05 10:21:19 volumio volumio[820]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) Oct 05 10:21:19 volumio volumio[820]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Oct 05 10:21:19 volumio volumio[820]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 05 10:21:20 volumio sudo[1159]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-05 10:20 Oct 05 10:21:20 volumio sudo[1159]: 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="c87c6e2b1ae33dc5801986cbcbe970898b92e7b4" VOLUMIO_FE_VERSION="c433755e569617abac52264d17ad61be303ef463" VOLUMIO_FE3_VERSION="2419ddd8e895c5bdc456962163c9dc7c0f187aa7" VOLUMIO_BE_VERSION="b949d6001d7e656b4668f31c119d2247cdf45158" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 30 Mar 2023 05:45:03 PM CEST" VOLUMIO_VERSION="3.449" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="6428d8e2c06e98483f5c5d77e8f01989"