-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sun 2025-04-13 14:30:08 CEST. -- Apr 13 14:29:00 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:00 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:00 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:00 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:01 volumio kernel: hwmon hwmon1: Voltage normalised Apr 13 14:29:01 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:01 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:01 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:01 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:02 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:02 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:02 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:02 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:03 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:03 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:03 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:03 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:04 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:04 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:04 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:04 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:04 volumio go-librespot[1519]: time="2025-04-13T14:29:04+02:00" level=trace msg="sent dealer ping" Apr 13 14:29:04 volumio go-librespot[1519]: time="2025-04-13T14:29:04+02:00" level=trace msg="received dealer pong" Apr 13 14:29:05 volumio kernel: hwmon hwmon1: Undervoltage detected! Apr 13 14:29:05 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:05 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:05 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:05 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:06 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:06 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:06 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:06 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:07 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:07 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:07 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:07 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:08 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:08 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:08 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:08 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:09 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:09 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:09 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:09 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:10 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:10 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:10 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:10 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:11 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:12 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:12 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:12 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:13 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:13 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:13 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:13 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:14 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:14 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:14 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:14 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:15 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:15 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:15 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:15 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:15 volumio kernel: hwmon hwmon1: Voltage normalised Apr 13 14:29:16 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:16 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:16 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:16 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:17 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:17 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:17 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:17 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:17 volumio go-librespot[1519]: time="2025-04-13T14:29:17+02:00" level=debug msg="prefetching next track" uri="spotify:track:0lghczk0UjySvFOdrDyFFb" Apr 13 14:29:17 volumio go-librespot[1519]: time="2025-04-13T14:29:17+02:00" level=debug msg="selected format OGG_VORBIS_160 (77983f6e337dfd4873b6f1e47f2876de98c94cee)" uri="spotify:track:0lghczk0UjySvFOdrDyFFb" Apr 13 14:29:17 volumio go-librespot[1519]: time="2025-04-13T14:29:17+02:00" level=debug msg="requested aes key for file 77983f6e337dfd4873b6f1e47f2876de98c94cee, gid: 0lghczk0UjySvFOdrDyFFb" Apr 13 14:29:17 volumio kernel: hwmon hwmon1: Undervoltage detected! Apr 13 14:29:18 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:18 volumio go-librespot[1519]: time="2025-04-13T14:29:18+02:00" level=debug msg="fetched first chunk of 10, total size is 4871664 bytes" uri="spotify:track:0lghczk0UjySvFOdrDyFFb" Apr 13 14:29:18 volumio go-librespot[1519]: time="2025-04-13T14:29:18+02:00" level=info msg="prefetched track \"Chrysanthemum\" (duration: 234000ms)" uri="spotify:track:0lghczk0UjySvFOdrDyFFb" Apr 13 14:29:18 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:18 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:18 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:18 volumio go-librespot[1519]: time="2025-04-13T14:29:18+02:00" level=debug msg="fetched chunk 2/9, size: 524288" uri="spotify:track:0lghczk0UjySvFOdrDyFFb" Apr 13 14:29:18 volumio go-librespot[1519]: time="2025-04-13T14:29:18+02:00" level=debug msg="fetched chunk 3/9, size: 524288" uri="spotify:track:0lghczk0UjySvFOdrDyFFb" Apr 13 14:29:18 volumio go-librespot[1519]: time="2025-04-13T14:29:18+02:00" level=debug msg="fetched chunk 1/9, size: 524288" uri="spotify:track:0lghczk0UjySvFOdrDyFFb" Apr 13 14:29:19 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:19 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:19 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:19 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:20 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:20 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:20 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:20 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:21 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:21 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:21 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:21 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:22 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:22 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:22 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:22 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:23 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:23 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:23 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:23 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:24 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:24 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:24 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:24 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:25 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:25 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:25 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:25 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:26 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:26 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:26 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:26 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:27 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:27 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:27 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:27 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:28 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:28 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:28 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:28 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:29 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:29 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:29 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:29 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:30 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:30 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:30 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:30 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:31 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:31 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:31 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:31 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:32 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:32 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:32 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:32 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:33 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:33 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:33 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:33 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:34 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:34 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:34 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:34 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:34 volumio kernel: hwmon hwmon1: Voltage normalised Apr 13 14:29:34 volumio go-librespot[1519]: time="2025-04-13T14:29:34+02:00" level=trace msg="sent dealer ping" Apr 13 14:29:34 volumio go-librespot[1519]: time="2025-04-13T14:29:34+02:00" level=trace msg="received dealer pong" Apr 13 14:29:35 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:35 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:35 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:35 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:36 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:36 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:36 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:36 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:36 volumio kernel: hwmon hwmon1: Undervoltage detected! Apr 13 14:29:37 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:37 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:37 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:37 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:38 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:38 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:38 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:38 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:39 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:39 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:39 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:39 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:40 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:40 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:40 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:40 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:41 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:41 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:41 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:41 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:42 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:42 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:42 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:42 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:43 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:43 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:43 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:43 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:44 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:44 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:44 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:44 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:45 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:45 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:45 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:45 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:46 volumio go-librespot[1519]: time="2025-04-13T14:29:46+02:00" level=trace msg="emitting websocket event: not_playing" Apr 13 14:29:46 volumio go-librespot[1519]: time="2025-04-13T14:29:46+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0lghczk0UjySvFOdrDyFFb" Apr 13 14:29:46 volumio volumio[955]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:0qiYC1O0ffUsybjXttZrxw","play_origin":"playlist"}} Apr 13 14:29:46 volumio volumio[955]: error: Failed to decode event: not_playing Apr 13 14:29:46 volumio go-librespot[1519]: time="2025-04-13T14:29:46+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 13 14:29:46 volumio go-librespot[1519]: time="2025-04-13T14:29:46+02:00" level=trace msg="emitting websocket event: will_play" Apr 13 14:29:46 volumio go-librespot[1519]: time="2025-04-13T14:29:46+02:00" level=info msg="loaded track \"Chrysanthemum\" (paused: false, position: 0ms, duration: 234000ms, prefetched: true)" uri="spotify:track:0lghczk0UjySvFOdrDyFFb" Apr 13 14:29:46 volumio volumio[955]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0lghczk0UjySvFOdrDyFFb","play_origin":"playlist"}} Apr 13 14:29:46 volumio go-librespot[1519]: time="2025-04-13T14:29:46+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 13 14:29:46 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:46 volumio go-librespot[1519]: time="2025-04-13T14:29:46+02:00" level=trace msg="scheduling prefetch in 204s" Apr 13 14:29:46 volumio go-librespot[1519]: time="2025-04-13T14:29:46+02:00" level=trace msg="emitting websocket event: metadata" Apr 13 14:29:46 volumio volumio[955]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0lghczk0UjySvFOdrDyFFb","name":"Chrysanthemum","artist_names":["Emilio Bonito"],"album_name":"The River I Step In","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02010d626481a5b1d14da4fe94","position":0,"duration":234000,"release_date":"year:2019 month:10 day:25","track_number":1,"disc_number":1}} Apr 13 14:29:46 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:46 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:46 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:46 volumio go-librespot[1519]: time="2025-04-13T14:29:46+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 13 14:29:46 volumio go-librespot[1519]: time="2025-04-13T14:29:46+02:00" level=trace msg="emitting websocket event: playing" Apr 13 14:29:46 volumio volumio[955]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0lghczk0UjySvFOdrDyFFb","play_origin":"playlist"}} Apr 13 14:29:46 volumio volumio[955]: SPOTIFY: PUSH STATE SPOTIFY Apr 13 14:29:46 volumio volumio[955]: SPOTIFY: {"status":"play","service":"spop","title":"Chrysanthemum","artist":"Emilio Bonito","album":"The River I Step In","albumart":"https://i.scdn.co/image/ab67616d00001e02010d626481a5b1d14da4fe94","uri":"spotify:track:0lghczk0UjySvFOdrDyFFb","trackType":"spotify","seek":0,"duration":234,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 13 14:29:46 volumio volumio[955]: info: CoreCommandRouter::servicePushState Apr 13 14:29:46 volumio volumio[955]: info: CoreStateMachine::pushState Apr 13 14:29:46 volumio volumio[955]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 13 14:29:46 volumio volumio[955]: info: CoreCommandRouter::volumioPushState Apr 13 14:29:46 volumio volumio[955]: info: [LastFM] Current track has sufficient metadata: title (Chrysanthemum) and artist (Emilio Bonito) passed on explicitly Apr 13 14:29:46 volumio volumio[955]: error: [LastFM] plugin is not authenticated, please retry, or track info could not be determined (very rare) Apr 13 14:29:47 volumio volumio[955]: SPOTIFY: PUSH STATE SPOTIFY Apr 13 14:29:47 volumio volumio[955]: SPOTIFY: {"status":"play","service":"spop","title":"Chrysanthemum","artist":"Emilio Bonito","album":"The River I Step In","albumart":"https://i.scdn.co/image/ab67616d00001e02010d626481a5b1d14da4fe94","uri":"spotify:track:0lghczk0UjySvFOdrDyFFb","trackType":"spotify","seek":1000,"duration":234,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 13 14:29:47 volumio volumio[955]: info: CoreCommandRouter::servicePushState Apr 13 14:29:47 volumio volumio[955]: info: CoreStateMachine::pushState Apr 13 14:29:47 volumio volumio[955]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 13 14:29:47 volumio volumio[955]: info: CoreCommandRouter::volumioPushState Apr 13 14:29:47 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:47 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:47 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:47 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:48 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:48 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:48 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:48 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:49 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:49 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:49 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:49 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:50 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:50 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:50 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:50 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:50 volumio kernel: hwmon hwmon1: Voltage normalised Apr 13 14:29:51 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:51 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:51 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:51 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:52 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:52 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:52 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:52 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:53 volumio kernel: hwmon hwmon1: Undervoltage detected! Apr 13 14:29:53 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:53 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:53 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:53 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:54 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:54 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:54 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:54 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:55 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:55 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:55 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:55 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:56 volumio volumio[955]: info: CoreCommandRouter::volumioPause Apr 13 14:29:56 volumio volumio[955]: info: CoreStateMachine::pause Apr 13 14:29:56 volumio volumio[955]: info: CoreStateMachine::stPlaybackTimer Apr 13 14:29:56 volumio volumio[955]: info: CoreStateMachine::servicePause Apr 13 14:29:56 volumio volumio[955]: info: CoreCommandRouter::servicePause Apr 13 14:29:56 volumio volumio[955]: info: Spotify Received pause Apr 13 14:29:56 volumio volumio[955]: SPOTIFY: SPOTIFY PAUSE Apr 13 14:29:56 volumio volumio[955]: SPOTIFY: {"status":"play","title":"Chrysanthemum","artist":"Emilio Bonito","album":"The River I Step In","albumart":"https://i.scdn.co/image/ab67616d00001e02010d626481a5b1d14da4fe94","uri":"spotify:track:0lghczk0UjySvFOdrDyFFb","trackType":"spotify","codec":"ogg","seek":1000,"duration":234,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":100,"dbVolume":null,"mute":false,"disableVolumeControl":true,"stream":false,"volatile":true,"service":"spop"} Apr 13 14:29:56 volumio volumio[955]: info: Sending Spotify command to local API: /player/pause Apr 13 14:29:56 volumio go-librespot[1519]: time="2025-04-13T14:29:56+02:00" level=debug msg="pause track at 9773ms" Apr 13 14:29:56 volumio go-librespot[1519]: time="2025-04-13T14:29:56+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 13 14:29:56 volumio volumio[955]: info: CoreCommandRouter::volumioGetState Apr 13 14:29:56 volumio volumio[955]: info: CoreCommandRouter::volumioGetQueue Apr 13 14:29:56 volumio volumio[955]: info: CoreStateMachine::getQueue Apr 13 14:29:56 volumio volumio[955]: info: CorePlayQueue::getQueue Apr 13 14:29:56 volumio go-librespot[1519]: time="2025-04-13T14:29:56+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 13 14:29:56 volumio go-librespot[1519]: time="2025-04-13T14:29:56+02:00" level=trace msg="emitting websocket event: paused" Apr 13 14:29:56 volumio volumio[955]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0lghczk0UjySvFOdrDyFFb","play_origin":"playlist"}} Apr 13 14:29:56 volumio volumio[955]: SPOTIFY: PUSH STATE SPOTIFY Apr 13 14:29:56 volumio volumio[955]: SPOTIFY: {"status":"pause","service":"spop","title":"Chrysanthemum","artist":"Emilio Bonito","album":"The River I Step In","albumart":"https://i.scdn.co/image/ab67616d00001e02010d626481a5b1d14da4fe94","uri":"spotify:track:0lghczk0UjySvFOdrDyFFb","trackType":"spotify","seek":10000,"duration":234,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 13 14:29:56 volumio volumio[955]: info: CoreCommandRouter::servicePushState Apr 13 14:29:56 volumio volumio[955]: info: CoreStateMachine::pushState Apr 13 14:29:56 volumio volumio[955]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 13 14:29:56 volumio volumio[955]: info: CoreCommandRouter::volumioPushState Apr 13 14:29:56 volumio volumio[955]: info: touch_display: Setting screensaver timeout to 120 seconds. Apr 13 14:30:04 volumio go-librespot[1519]: time="2025-04-13T14:30:04+02:00" level=trace msg="received accesspoint ping" Apr 13 14:30:04 volumio go-librespot[1519]: time="2025-04-13T14:30:04+02:00" level=trace msg="received accesspoint pong ack" Apr 13 14:30:04 volumio go-librespot[1519]: time="2025-04-13T14:30:04+02:00" level=trace msg="sent dealer ping" Apr 13 14:30:04 volumio go-librespot[1519]: time="2025-04-13T14:30:04+02:00" level=trace msg="received dealer pong" Apr 13 14:30:05 volumio volumio[955]: info: ___________ PLUGINS: Run Shutdown Tasks ___________ Apr 13 14:30:05 volumio volumio[955]: info: PLUGIN onShutdown : networkfs Apr 13 14:30:05 volumio volumio[955]: info: PLUGIN onShutdown : audiophonicsonoff Apr 13 14:30:05 volumio volumio[955]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 13 14:30:05 volumio volumio[955]: TypeError: Cannot read property 'writeSync' of undefined Apr 13 14:30:05 volumio volumio[955]: at ControllerAudiophonicsOnOff.onVolumioShutdown (/data/plugins/system_hardware/audiophonicsonoff/index.js:48:25) Apr 13 14:30:05 volumio volumio[955]: at PluginManager.onVolumioShutdownPlugin (/volumio/app/pluginmanager.js:638:30) Apr 13 14:30:05 volumio volumio[955]: at HashMap. (/volumio/app/pluginmanager.js:621:31) Apr 13 14:30:05 volumio volumio[955]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Apr 13 14:30:05 volumio volumio[955]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Apr 13 14:30:05 volumio volumio[955]: at PluginManager.onVolumioShutdown (/volumio/app/pluginmanager.js:619:20) Apr 13 14:30:05 volumio volumio[955]: at CoreCommandRouter.shutdown (/volumio/app/index.js:1328:22) Apr 13 14:30:05 volumio volumio[955]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:859:33) Apr 13 14:30:05 volumio volumio[955]: at Socket.emit (events.js:315:20) Apr 13 14:30:05 volumio volumio[955]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Apr 13 14:30:05 volumio volumio[955]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Apr 13 14:30:05 volumio volumio[955]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 13 14:30:08 volumio sudo[16823]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-13 14:29 Apr 13 14:30:08 volumio sudo[16823]: 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="e32c2c71ae78852844c70357816bdd871c155ab8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 31 Mar 2025 06:54:47 PM CEST" VOLUMIO_VERSION="3.799" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="436f3f84f6d0b4ffc344f0bc132a32e8"