-- 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"