-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Tue 2024-04-16 16:41:11 CEST. -- Apr 16 16:40:08 volumio volumio[1879]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 84 Apr 16 16:40:08 volumio volumio[1879]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 85 Apr 16 16:40:08 volumio volumio[1879]: info: CoreCommandRouter::volumioGetState Apr 16 16:40:22 volumio go-librespot[2146]: time="2024-04-16T16:40:22+02:00" level=trace msg="emitting websocket event: not_playing" Apr 16 16:40:22 volumio go-librespot[2146]: time="2024-04-16T16:40:22+02:00" level=debug msg="loading track spotify:track:5UbAGvv5BB9U4LWgA5l5dd (paused: false, position: 0ms)" Apr 16 16:40:22 volumio volumio[1879]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:1AUwrey3n69snJNwvhzLB7","play_origin":"playlist"}} Apr 16 16:40:22 volumio volumio[1879]: error: Failed to decode event: not_playing Apr 16 16:40:22 volumio kernel: xhci_hcd 0000:01:00.0: ERROR Transfer event for disabled endpoint slot 2 ep 1 Apr 16 16:40:22 volumio kernel: xhci_hcd 0000:01:00.0: @000000042a118df0 00000000 00000000 0e000000 02028000 Apr 16 16:40:22 volumio go-librespot[2146]: time="2024-04-16T16:40:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 16 16:40:22 volumio go-librespot[2146]: time="2024-04-16T16:40:22+02:00" level=trace msg="emitting websocket event: will_play" Apr 16 16:40:22 volumio volumio[1879]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5UbAGvv5BB9U4LWgA5l5dd","play_origin":"playlist"}} Apr 16 16:40:22 volumio go-librespot[2146]: time="2024-04-16T16:40:22+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:5UbAGvv5BB9U4LWgA5l5dd" Apr 16 16:40:22 volumio go-librespot[2146]: time="2024-04-16T16:40:22+02:00" level=debug msg="requested aes key for file 27ed7c6c1b7810924619b30862ae14f6751834e9, gid: 5UbAGvv5BB9U4LWgA5l5dd" Apr 16 16:40:24 volumio go-librespot[2146]: time="2024-04-16T16:40:24+02:00" level=debug msg="fetched first chunk of 18, total size is 9397976 bytes" Apr 16 16:40:24 volumio go-librespot[2146]: time="2024-04-16T16:40:24+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" Apr 16 16:40:24 volumio go-librespot[2146]: time="2024-04-16T16:40:24+02:00" level=info msg="loaded track \"Manha de Carnival\" (uri: spotify:track:5UbAGvv5BB9U4LWgA5l5dd, paused: false, position: 0ms, duration: 239840ms)" Apr 16 16:40:24 volumio go-librespot[2146]: time="2024-04-16T16:40:24+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 16 16:40:24 volumio go-librespot[2146]: time="2024-04-16T16:40:24+02:00" level=trace msg="emitting websocket event: metadata" Apr 16 16:40:24 volumio volumio[1879]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5UbAGvv5BB9U4LWgA5l5dd","name":"Manha de Carnival","artist_names":["Carmen Cuesta"],"album_name":"Mi Bossa Nova","album_cover_url":"https://i.scdn.co/image/ab67616d00001e026e8309984745901fbfba9d82","position":0,"duration":239840,"release_date":"year:2010 month:4 day:28","track_number":9,"disc_number":1}} Apr 16 16:40:24 volumio volumio[1879]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 83 Apr 16 16:40:25 volumio volumio[1879]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 84 Apr 16 16:40:25 volumio volumio[1879]: info: CoreCommandRouter::volumioGetState Apr 16 16:40:25 volumio go-librespot[2146]: time="2024-04-16T16:40:25+02:00" level=debug msg="fetched chunk 2/17, size: 524288" Apr 16 16:40:26 volumio go-librespot[2146]: time="2024-04-16T16:40:26+02:00" level=debug msg="fetched chunk 3/17, size: 524288" Apr 16 16:40:26 volumio go-librespot[2146]: time="2024-04-16T16:40:26+02:00" level=debug msg="fetched chunk 1/17, size: 524288" Apr 16 16:40:26 volumio go-librespot[2146]: time="2024-04-16T16:40:26+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 16 16:40:26 volumio go-librespot[2146]: time="2024-04-16T16:40:26+02:00" level=trace msg="emitting websocket event: playing" Apr 16 16:40:26 volumio volumio[1879]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5UbAGvv5BB9U4LWgA5l5dd","play_origin":"playlist"}} Apr 16 16:40:26 volumio volumio[1879]: SPOTIFY: PUSH STATE SPOTIFY Apr 16 16:40:26 volumio volumio[1879]: SPOTIFY: {"status":"play","service":"spop","title":"Manha de Carnival","artist":"Carmen Cuesta","album":"Mi Bossa Nova","albumart":"https://i.scdn.co/image/ab67616d00001e026e8309984745901fbfba9d82","uri":"spotify:track:5UbAGvv5BB9U4LWgA5l5dd","trackType":"spotify","seek":3000,"duration":239,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 16 16:40:26 volumio volumio[1879]: info: CoreCommandRouter::servicePushState Apr 16 16:40:26 volumio volumio[1879]: info: CoreStateMachine::pushState Apr 16 16:40:26 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 16:40:26 volumio volumio[1879]: info: CoreCommandRouter::volumioPushState Apr 16 16:40:27 volumio volumio[1879]: info: [ASDebug] CurState: play PrevState: play Apr 16 16:40:27 volumio volumio[1879]: SPOTIFY: PUSH STATE SPOTIFY Apr 16 16:40:27 volumio volumio[1879]: SPOTIFY: {"status":"play","service":"spop","title":"Manha de Carnival","artist":"Carmen Cuesta","album":"Mi Bossa Nova","albumart":"https://i.scdn.co/image/ab67616d00001e026e8309984745901fbfba9d82","uri":"spotify:track:5UbAGvv5BB9U4LWgA5l5dd","trackType":"spotify","seek":3000,"duration":239,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 16 16:40:27 volumio volumio[1879]: info: CoreCommandRouter::servicePushState Apr 16 16:40:27 volumio volumio[1879]: info: CoreStateMachine::pushState Apr 16 16:40:27 volumio volumio[1879]: info: CoreCommandRouter::volumioPushState Apr 16 16:40:27 volumio volumio[1879]: info: [ASDebug] CurState: play PrevState: play Apr 16 16:40:36 volumio go-librespot[2146]: time="2024-04-16T16:40:36+02:00" level=debug msg="fetched chunk 4/17, size: 524288" Apr 16 16:40:42 volumio volumio[1879]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 85 Apr 16 16:40:42 volumio volumio[1879]: info: CoreCommandRouter::volumioGetState Apr 16 16:40:42 volumio volumio[1879]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 86 Apr 16 16:40:47 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 16 16:40:47 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 16 16:40:47 volumio volumio[1879]: info: Discovery: Getting this device information Apr 16 16:40:47 volumio volumio[1879]: info: CoreCommandRouter::volumioGetState Apr 16 16:40:47 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 16 16:40:47 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 16 16:40:47 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 16 16:40:47 volumio volumio[1879]: info: Discovery: Getting this device information Apr 16 16:40:47 volumio volumio[1879]: info: CoreCommandRouter::volumioGetState Apr 16 16:40:47 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 16 16:40:47 volumio volumio[1879]: verbose: New Socket.io Connection to 192.168.178.67 from 192.168.178.78 UA: okhttp/4.9.2 Total Clients: 86 Apr 16 16:40:47 volumio volumio[1879]: info: CoreCommandRouter::volumioGetState Apr 16 16:40:47 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 16 16:40:47 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 16 16:40:49 volumio go-librespot[2146]: time="2024-04-16T16:40:49+02:00" level=debug msg="fetched chunk 5/17, size: 524288" Apr 16 16:40:57 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 16 16:40:57 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 16 16:40:57 volumio volumio[1879]: info: Discovery: Getting this device information Apr 16 16:40:57 volumio volumio[1879]: info: CoreCommandRouter::volumioGetState Apr 16 16:40:57 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 16 16:40:57 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 16 16:40:57 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 16 16:40:57 volumio volumio[1879]: info: Discovery: Getting this device information Apr 16 16:40:57 volumio volumio[1879]: info: CoreCommandRouter::volumioGetState Apr 16 16:40:57 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 16 16:40:58 volumio volumio[1879]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 87 Apr 16 16:40:58 volumio volumio[1879]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 88 Apr 16 16:40:58 volumio volumio[1879]: info: CoreCommandRouter::volumioGetState Apr 16 16:41:00 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 16 16:41:00 volumio volumio[1879]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 16 16:41:01 volumio go-librespot[2146]: time="2024-04-16T16:41:01+02:00" level=debug msg="fetched chunk 6/17, size: 524288" Apr 16 16:41:08 volumio volumio[1879]: info: [ASDebug] Port: 24 Apr 16 16:41:08 volumio volumio[1879]: info: [ASDebug] Inverted: false Apr 16 16:41:08 volumio volumio[1879]: info: [ASDebug] Delay: 720 Apr 16 16:41:10 volumio volumio[1879]: info: Starting Uninstall of plugin system_controller - ampswitch Apr 16 16:41:10 volumio volumio[1879]: info: Uninstalling plugin ampswitch Apr 16 16:41:10 volumio volumio[1879]: info: [ASDebug] Port: 24 Apr 16 16:41:10 volumio volumio[1879]: info: [ASDebug] Inverted: false Apr 16 16:41:10 volumio volumio[1879]: info: [ASDebug] Delay: 720 Apr 16 16:41:10 volumio volumio[1879]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 16 16:41:10 volumio volumio[1879]: Error: EBADF: bad file descriptor, close Apr 16 16:41:10 volumio volumio[1879]: at Object.closeSync (fs.js:439:3) Apr 16 16:41:10 volumio volumio[1879]: at Object.closeSync (/volumio/node_modules/graceful-fs/graceful-fs.js:74:20) Apr 16 16:41:10 volumio volumio[1879]: at Gpio.unexport (/data/plugins/system_controller/ampswitch/node_modules/onoff/onoff.js:307:8) Apr 16 16:41:10 volumio volumio[1879]: at AmpSwitchController.freeGPIO (/data/plugins/system_controller/ampswitch/index.js:234:19) Apr 16 16:41:10 volumio volumio[1879]: at AmpSwitchController.onStop (/data/plugins/system_controller/ampswitch/index.js:84:10) Apr 16 16:41:10 volumio volumio[1879]: at PluginManager.stopPlugin (/volumio/app/pluginmanager.js:460:30) Apr 16 16:41:10 volumio volumio[1879]: at PluginManager.unInstallPlugin (/volumio/app/pluginmanager.js:1449:10) Apr 16 16:41:10 volumio volumio[1879]: at CoreCommandRouter.unInstallPlugin (/volumio/app/index.js:1459:22) Apr 16 16:41:10 volumio volumio[1879]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1218:45) Apr 16 16:41:10 volumio volumio[1879]: at Socket.emit (events.js:315:20) Apr 16 16:41:10 volumio volumio[1879]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Apr 16 16:41:10 volumio volumio[1879]: at processTicksAndRejections (internal/process/task_queues.js:75:11) { Apr 16 16:41:10 volumio volumio[1879]: errno: -9, Apr 16 16:41:10 volumio volumio[1879]: syscall: 'close', Apr 16 16:41:10 volumio volumio[1879]: code: 'EBADF' Apr 16 16:41:10 volumio volumio[1879]: } Apr 16 16:41:10 volumio volumio[1879]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 16 16:41:11 volumio sudo[3692]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-16 16:40 Apr 16 16:41:11 volumio sudo[3692]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET" VOLUMIO_VERSION="3.631" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"