-- Logs begin at Thu 2019-02-14 10:11:58 UTC, end at Sun 2025-05-11 03:49:06 UTC. -- May 11 03:48:02 volumio go-librespot[1166]: time="2025-05-11T03:48:02Z" level=trace msg="sent dealer ping" May 11 03:48:02 volumio go-librespot[1166]: time="2025-05-11T03:48:02Z" level=trace msg="received dealer pong" May 11 03:48:03 volumio volumio[965]: info: Selecting previously unselected package adwaita-icon-theme. May 11 03:48:03 volumio volumio[965]: info: Preparing to unpack .../02-adwaita-icon-theme_3.30.1-1_all.deb ... May 11 03:48:03 volumio volumio[965]: info: Unpacking adwaita-icon-theme (3.30.1-1) ... May 11 03:48:05 volumio go-librespot[1166]: time="2025-05-11T03:48:05Z" level=debug msg="fetched chunk 15/16, size: 524288" uri="spotify:track:6aCBjSb87RizdH8lVBIRW7" May 11 03:48:07 volumio volumio[965]: info: CoreCommandRouter::volumioGetState May 11 03:48:17 volumio volumio[965]: info: CoreCommandRouter::volumioGetState May 11 03:48:17 volumio volumio[965]: info: Listing playlists May 11 03:48:17 volumio volumio[965]: info: Listing playlists May 11 03:48:18 volumio go-librespot[1166]: time="2025-05-11T03:48:18Z" level=debug msg="fetched chunk 16/16, size: 180546" uri="spotify:track:6aCBjSb87RizdH8lVBIRW7" May 11 03:48:27 volumio volumio[965]: info: CoreCommandRouter::volumioGetState May 11 03:48:32 volumio go-librespot[1166]: time="2025-05-11T03:48:32Z" level=trace msg="sent dealer ping" May 11 03:48:32 volumio go-librespot[1166]: time="2025-05-11T03:48:32Z" level=trace msg="received dealer pong" May 11 03:48:37 volumio volumio[965]: info: CoreCommandRouter::volumioGetState May 11 03:48:37 volumio volumio[965]: info: Listing playlists May 11 03:48:37 volumio volumio[965]: info: Selecting previously unselected package libatspi2.0-0:armhf. May 11 03:48:37 volumio volumio[965]: info: Preparing to unpack .../03-libatspi2.0-0_2.30.0-7_armhf.deb ... May 11 03:48:37 volumio volumio[965]: info: Unpacking libatspi2.0-0:armhf (2.30.0-7) ... May 11 03:48:38 volumio volumio[965]: info: Selecting previously unselected package at-spi2-core. May 11 03:48:38 volumio volumio[965]: info: Preparing to unpack .../04-at-spi2-core_2.30.0-7_armhf.deb ... May 11 03:48:38 volumio volumio[965]: info: Unpacking at-spi2-core (2.30.0-7) ... May 11 03:48:38 volumio volumio[965]: info: Selecting previously unselected package libgif7:armhf. May 11 03:48:38 volumio volumio[965]: info: Preparing to unpack .../05-libgif7_5.1.4-3+deb10u1_armhf.deb ... May 11 03:48:38 volumio volumio[965]: info: Unpacking libgif7:armhf (5.1.4-3+deb10u1) ... May 11 03:48:38 volumio volumio[965]: info: Selecting previously unselected package libimlib2:armhf. May 11 03:48:38 volumio volumio[965]: info: Preparing to unpack .../06-libimlib2_1.5.1-1_armhf.deb ... May 11 03:48:38 volumio volumio[965]: info: Unpacking libimlib2:armhf (1.5.1-1) ... May 11 03:48:38 volumio volumio[965]: info: Selecting previously unselected package giblib1:armhf. May 11 03:48:38 volumio volumio[965]: info: Preparing to unpack .../07-giblib1_1.2.4-12_armhf.deb ... May 11 03:48:38 volumio volumio[965]: info: Unpacking giblib1:armhf (1.2.4-12) ... May 11 03:48:39 volumio volumio[965]: info: Selecting previously unselected package gnome-icon-theme. May 11 03:48:39 volumio volumio[965]: info: Preparing to unpack .../08-gnome-icon-theme_3.12.0-3_all.deb ... May 11 03:48:39 volumio volumio[965]: info: Unpacking gnome-icon-theme (3.12.0-3) ... May 11 03:48:47 volumio volumio[965]: info: CoreCommandRouter::volumioGetState May 11 03:48:57 volumio volumio[965]: info: CoreCommandRouter::volumioGetState May 11 03:48:57 volumio volumio[965]: info: Listing playlists May 11 03:48:57 volumio volumio[965]: info: Listing playlists May 11 03:49:00 volumio volumio[965]: verbose: New Socket.io Connection to 192.168.1.170 from 192.168.1.201 UA: Mozilla/5.0 (Linux; Android 15; Pixel 7 Pro Build/BP1A.250405.007.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/135.0.7049.111 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 May 11 03:49:00 volumio volumio[965]: verbose: New Socket.io Connection to 192.168.1.170 from 192.168.1.201 UA: Mozilla/5.0 (Linux; Android 15; Pixel 7 Pro Build/BP1A.250405.007.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/135.0.7049.111 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 May 11 03:49:00 volumio volumio[965]: verbose: New Socket.io Connection to 192.168.1.170 from 192.168.1.201 UA: Mozilla/5.0 (Linux; Android 15; Pixel 7 Pro Build/BP1A.250405.007.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/135.0.7049.111 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 May 11 03:49:01 volumio go-librespot[1166]: time="2025-05-11T03:49:01Z" level=trace msg="received accesspoint ping" May 11 03:49:01 volumio go-librespot[1166]: time="2025-05-11T03:49:01Z" level=trace msg="received accesspoint pong ack" May 11 03:49:02 volumio go-librespot[1166]: time="2025-05-11T03:49:02Z" level=trace msg="sent dealer ping" May 11 03:49:02 volumio go-librespot[1166]: time="2025-05-11T03:49:02Z" level=trace msg="received dealer pong" May 11 03:49:02 volumio volumio[965]: verbose: New Socket.io Connection to 192.168.1.170 from 192.168.1.201 UA: Mozilla/5.0 (Linux; Android 15; Pixel 7 Pro Build/BP1A.250405.007.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/135.0.7049.111 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 May 11 03:49:02 volumio volumio[965]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 11 03:49:02 volumio volumio[965]: info: CoreCommandRouter::volumioGetVisibleSources May 11 03:49:02 volumio volumio[965]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 03:49:02 volumio volumio[965]: info: CoreCommandRouter::volumioGetState May 11 03:49:02 volumio volumio[965]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 11 03:49:02 volumio volumio[965]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 11 03:49:02 volumio volumio[965]: info: Received Get System Info May 11 03:49:02 volumio volumio[965]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 11 03:49:02 volumio volumio[965]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 11 03:49:02 volumio volumio[965]: info: Discovery: Getting this device information May 11 03:49:02 volumio volumio[965]: info: CoreCommandRouter::volumioGetState May 11 03:49:02 volumio volumio[965]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 11 03:49:02 volumio volumio[965]: info: CoreCommandRouter::volumioGetState May 11 03:49:02 volumio volumio[965]: info: Listing playlists May 11 03:49:02 volumio volumio[965]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 11 03:49:02 volumio volumio[965]: info: Selecting previously unselected package libatk1.0-data. May 11 03:49:02 volumio volumio[965]: info: Preparing to unpack .../09-libatk1.0-data_2.30.0-2_all.deb ... May 11 03:49:02 volumio volumio[965]: info: Unpacking libatk1.0-data (2.30.0-2) ... May 11 03:49:02 volumio volumio[965]: info: Selecting previously unselected package libatk1.0-0:armhf. May 11 03:49:02 volumio volumio[965]: info: Preparing to unpack .../10-libatk1.0-0_2.30.0-2_armhf.deb ... May 11 03:49:02 volumio volumio[965]: info: Unpacking libatk1.0-0:armhf (2.30.0-2) ... May 11 03:49:03 volumio volumio[965]: info: Selecting previously unselected package libatk-bridge2.0-0:armhf. May 11 03:49:03 volumio volumio[965]: info: Preparing to unpack .../11-libatk-bridge2.0-0_2.30.0-5_armhf.deb ... May 11 03:49:03 volumio volumio[965]: info: Unpacking libatk-bridge2.0-0:armhf (2.30.0-5) ... May 11 03:49:03 volumio volumio[965]: info: Selecting previously unselected package libcairo-gobject2:armhf. May 11 03:49:03 volumio volumio[965]: info: Preparing to unpack .../12-libcairo-gobject2_1.16.0-4+rpt1+deb10u1_armhf.deb ... May 11 03:49:03 volumio volumio[965]: info: Unpacking libcairo-gobject2:armhf (1.16.0-4+rpt1+deb10u1) ... May 11 03:49:03 volumio volumio[965]: info: Selecting previously unselected package liblcms2-2:armhf. May 11 03:49:03 volumio volumio[965]: info: Preparing to unpack .../13-liblcms2-2_2.9-3_armhf.deb ... May 11 03:49:03 volumio volumio[965]: info: Unpacking liblcms2-2:armhf (2.9-3) ... May 11 03:49:04 volumio volumio[965]: info: Selecting previously unselected package libcolord2:armhf. May 11 03:49:04 volumio volumio[965]: info: Preparing to unpack .../14-libcolord2_1.4.3-4_armhf.deb ... May 11 03:49:04 volumio volumio[965]: info: Unpacking libcolord2:armhf (1.4.3-4) ... May 11 03:49:04 volumio go-librespot[1166]: time="2025-05-11T03:49:04Z" level=trace msg="emitting websocket event: not_playing" May 11 03:49:04 volumio go-librespot[1166]: time="2025-05-11T03:49:04Z" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:1uhces29ApKuQWFdpiUsvH" May 11 03:49:04 volumio volumio[965]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:6aCBjSb87RizdH8lVBIRW7","play_origin":"playlist"}} May 11 03:49:04 volumio volumio[965]: error: Failed to decode event: not_playing May 11 03:49:05 volumio go-librespot[1166]: time="2025-05-11T03:49:05Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 03:49:05 volumio go-librespot[1166]: time="2025-05-11T03:49:05Z" level=trace msg="emitting websocket event: will_play" May 11 03:49:05 volumio volumio[965]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1uhces29ApKuQWFdpiUsvH","play_origin":"playlist"}} May 11 03:49:05 volumio go-librespot[1166]: time="2025-05-11T03:49:05Z" level=debug msg="selected format OGG_VORBIS_320 (f51a31342f8061899be70a3b0051cb9b0b6f9e13)" uri="spotify:track:1uhces29ApKuQWFdpiUsvH" May 11 03:49:05 volumio go-librespot[1166]: time="2025-05-11T03:49:05Z" level=debug msg="requested aes key for file f51a31342f8061899be70a3b0051cb9b0b6f9e13, gid: 1uhces29ApKuQWFdpiUsvH" May 11 03:49:05 volumio go-librespot[1166]: time="2025-05-11T03:49:05Z" level=debug msg="fetched first chunk of 2, total size is 752052 bytes" uri="spotify:track:1uhces29ApKuQWFdpiUsvH" May 11 03:49:05 volumio go-librespot[1166]: time="2025-05-11T03:49:05Z" level=info msg="loaded track \"From Zero (Intro)\" (paused: true, position: 0ms, duration: 22174ms, prefetched: false)" uri="spotify:track:1uhces29ApKuQWFdpiUsvH" May 11 03:49:05 volumio go-librespot[1166]: time="2025-05-11T03:49:05Z" level=debug msg="fetched chunk 1/1, size: 227764" uri="spotify:track:1uhces29ApKuQWFdpiUsvH" May 11 03:49:05 volumio go-librespot[1166]: time="2025-05-11T03:49:05Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 03:49:05 volumio go-librespot[1166]: time="2025-05-11T03:49:05Z" level=trace msg="emitting websocket event: metadata" May 11 03:49:05 volumio go-librespot[1166]: time="2025-05-11T03:49:05Z" level=trace msg="emitting websocket event: stopped" May 11 03:49:05 volumio volumio[965]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1uhces29ApKuQWFdpiUsvH","name":"From Zero (Intro)","artist_names":["Linkin Park"],"album_name":"From Zero","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b11a5489e8cb11dd22b930a0","position":0,"duration":22174,"release_date":"year:2024 month:11 day:15","track_number":1,"disc_number":1}} May 11 03:49:05 volumio volumio[965]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"playlist"}} May 11 03:49:05 volumio volumio[965]: SPOTIFY: PUSH STATE SPOTIFY May 11 03:49:05 volumio volumio[965]: SPOTIFY: {"status":"stop","service":"spop","title":"From Zero (Intro)","artist":"Linkin Park","album":"From Zero","albumart":"https://i.scdn.co/image/ab67616d00001e02b11a5489e8cb11dd22b930a0","uri":"spotify:track:1uhces29ApKuQWFdpiUsvH","trackType":"spotify","seek":0,"duration":22,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 11 03:49:05 volumio volumio[965]: info: CoreCommandRouter::servicePushState May 11 03:49:05 volumio volumio[965]: info: CoreStateMachine::pushState May 11 03:49:05 volumio volumio[965]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 03:49:05 volumio volumio[965]: info: CoreCommandRouter::volumioPushState May 11 03:49:05 volumio volumio[965]: info: CorePlayQueue::getTrack 0 May 11 03:49:05 volumio volumio[965]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"From Zero (Intro)","artist":"Linkin Park","album":"From Zero","albumart":"https://i.scdn.co/image/ab67616d00001e02b11a5489e8cb11dd22b930a0","uri":"spotify:track:1uhces29ApKuQWFdpiUsvH","trackType":"spotify","seek":0,"duration":22,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 11 03:49:05 volumio volumio[965]: verbose: CURRENT POSITION 0 May 11 03:49:05 volumio volumio[965]: info: CoreStateMachine::syncState stateService stop May 11 03:49:05 volumio volumio[965]: info: CoreStateMachine::syncState currentStatus play May 11 03:49:05 volumio volumio[965]: info: CoreStateMachine::play index undefined May 11 03:49:05 volumio volumio[965]: info: CoreStateMachine::setConsumeUpdateService undefined May 11 03:49:05 volumio volumio[965]: info: CoreStateMachine::pushState May 11 03:49:05 volumio volumio[965]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 03:49:05 volumio volumio[965]: info: CoreCommandRouter::volumioPushState May 11 03:49:05 volumio volumio[965]: info: CorePlayQueue::getTrack 0 May 11 03:49:05 volumio volumio[965]: info: [ASDebug] CurState: stop PrevState: play May 11 03:49:05 volumio volumio[965]: info: [ASDebug] InitTimeout - Amp off in: 720 ms May 11 03:49:05 volumio volumio[965]: info: [ASDebug] CurState: stop PrevState: play May 11 03:49:05 volumio volumio[965]: info: [ASDebug] InitTimeout - Amp off in: 720 ms May 11 03:49:05 volumio volumio[965]: info: Selecting previously unselected package libgtk2.0-common. May 11 03:49:05 volumio go-librespot[1166]: time="2025-05-11T03:49:05Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 03:49:05 volumio go-librespot[1166]: time="2025-05-11T03:49:05Z" level=trace msg="emitting websocket event: paused" May 11 03:49:05 volumio volumio[965]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:1uhces29ApKuQWFdpiUsvH","play_origin":"playlist"}} May 11 03:49:05 volumio volumio[965]: SPOTIFY: PUSH STATE SPOTIFY May 11 03:49:05 volumio volumio[965]: SPOTIFY: {"status":"pause","service":"spop","title":"From Zero (Intro)","artist":"Linkin Park","album":"From Zero","albumart":"https://i.scdn.co/image/ab67616d00001e02b11a5489e8cb11dd22b930a0","uri":"spotify:track:1uhces29ApKuQWFdpiUsvH","trackType":"spotify","seek":0,"duration":22,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 11 03:49:05 volumio volumio[965]: info: CoreCommandRouter::servicePushState May 11 03:49:05 volumio volumio[965]: info: CoreStateMachine::pushState May 11 03:49:05 volumio volumio[965]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 03:49:05 volumio volumio[965]: info: CoreCommandRouter::volumioPushState May 11 03:49:05 volumio volumio[965]: info: [ASDebug] CurState: pause PrevState: play May 11 03:49:05 volumio volumio[965]: info: [ASDebug] InitTimeout - Amp off in: 720 ms May 11 03:49:05 volumio volumio[965]: info: Preparing to unpack .../15-libgtk2.0-common_2.24.32-3+rpt1_all.deb ... May 11 03:49:05 volumio volumio[965]: info: Unpacking libgtk2.0-common (2.24.32-3+rpt1) ... May 11 03:49:06 volumio volumio[965]: info: [ASDebug] Togle GPIO: OFF May 11 03:49:06 volumio volumio[965]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 11 03:49:06 volumio volumio[965]: Error: EBADF: bad file descriptor, write May 11 03:49:06 volumio volumio[965]: at Object.writeSync (fs.js:711:3) May 11 03:49:06 volumio volumio[965]: at Gpio.writeSync (/data/plugins/system_controller/ampswitch/node_modules/onoff/onoff.js:243:8) May 11 03:49:06 volumio volumio[965]: at AmpSwitchController.off (/data/plugins/system_controller/ampswitch/index.js:221:23) May 11 03:49:06 volumio volumio[965]: at Timeout._onTimeout (/data/plugins/system_controller/ampswitch/index.js:195:88) May 11 03:49:06 volumio volumio[965]: at listOnTimeout (internal/timers.js:554:17) May 11 03:49:06 volumio volumio[965]: at processTimers (internal/timers.js:497:7) { May 11 03:49:06 volumio volumio[965]: errno: -9, May 11 03:49:06 volumio volumio[965]: syscall: 'write', May 11 03:49:06 volumio volumio[965]: code: 'EBADF' May 11 03:49:06 volumio volumio[965]: } May 11 03:49:06 volumio volumio[965]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 11 03:49:06 volumio sudo[11645]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-11 03:48 May 11 03:49:06 volumio sudo[11645]: 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="9ab87de061b3649c303da550e73c92d340b0f989" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 30 Apr 2025 11:47:57 AM CEST" VOLUMIO_VERSION="3.807" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fddd10196af80fdc784c726185a6abe4"