-- Logs begin at Sun 2025-02-16 00:48:58 +07, end at Sun 2025-02-16 16:50:13 +07. -- Feb 16 16:49:00 volpi volumio[1102]: Searching all installed plugins Feb 16 16:49:00 volpi volumio[1102]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 16 16:49:00 volpi volumio[1102]: info: CoreCommandRouter::executeOnPlugin: , search Feb 16 16:49:00 volpi volumio[1102]: info: CoreCommandRouter::executeOnPlugin: mpd , search Feb 16 16:49:00 volpi volumio[1102]: info: All search sources collected, pushing search results Feb 16 16:49:03 volpi ntpd[13991]: Soliciting pool server 203.113.174.44 Feb 16 16:49:04 volpi volumio[1102]: Searching all installed plugins Feb 16 16:49:04 volpi volumio[1102]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 16 16:49:04 volpi volumio[1102]: info: CoreCommandRouter::executeOnPlugin: , search Feb 16 16:49:04 volpi volumio[1102]: info: CoreCommandRouter::executeOnPlugin: mpd , search Feb 16 16:49:04 volpi volumio[1102]: info: All search sources collected, pushing search results Feb 16 16:49:21 volpi volumio[1102]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 16 16:49:21 volpi volumio[1102]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 16 16:49:25 volpi volumio[1102]: info: Enabling plugin spop Feb 16 16:49:25 volpi volumio[1102]: info: Loading plugin "spop"... Feb 16 16:49:27 volpi volumio[1102]: info: PLUGIN START: spop Feb 16 16:49:27 volpi volumio[1102]: info: Creating Spotify config file Feb 16 16:49:27 volpi volumio[1102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 16:49:27 volpi volumio[1102]: info: Done. Feb 16 16:49:27 volpi volumio[1102]: info: Spotify config file written Feb 16 16:49:27 volpi volumio[1102]: info: No need to fix Spotify hosts Feb 16 16:49:27 volpi sudo[18334]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 16 16:49:27 volpi sudo[18334]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 16:49:27 volpi systemd[1]: Started go-librespot Daemon. Feb 16 16:49:27 volpi go-librespot[18336]: go-librespot daemon starting... Feb 16 16:49:27 volpi sudo[18334]: pam_unix(sudo:session): session closed for user root Feb 16 16:49:27 volpi volumio[1102]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 16 16:49:27 volpi go-librespot[18336]: time="2025-02-16T16:49:27+07:00" level=info msg="running go-librespot 0.2.0" Feb 16 16:49:27 volpi go-librespot[18336]: time="2025-02-16T16:49:27+07:00" level=debug msg="app state loaded" Feb 16 16:49:27 volpi go-librespot[18336]: time="2025-02-16T16:49:27+07:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 16 16:49:28 volpi go-librespot[18336]: time="2025-02-16T16:49:28+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 16 16:49:28 volpi go-librespot[18336]: time="2025-02-16T16:49:28+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 16 16:49:28 volpi go-librespot[18336]: time="2025-02-16T16:49:28+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 16 16:49:28 volpi go-librespot[18336]: time="2025-02-16T16:49:28+07:00" level=info msg="zeroconf server listening on port 38839" Feb 16 16:49:28 volpi volumio[1102]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Feb 16 16:49:28 volpi volumio[1102]: SPOTIFY: BQBrt16pTHCLG1mnHkbQUz0qZS1q8yZuvWHxk84-_JAcF38XTYIseeLJOFuSkhtav8P3gROJz_jX-o6MLvsqJydADycSovRMJbKWImoNM42vpbnUbh0ehZ-t4hLIkh8oueVhz5RNmQWiU5GmBZbYQoo6WhDx9nAJIoFN7LV1O8S-b3eaIZ-tMTNB8t9aUo57uMNQ9M1HFGAaQbqUBjvsHKO6vwgS0EQm0gv1-Q_SnxnLtu7xieYzwZH7H6tiffWuq2wm939-3mxpEORmAXWZ48oKZgK-1DZRJ8wJrRFnZGs Feb 16 16:49:28 volpi volumio[1102]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Feb 16 16:49:28 volpi volumio[1102]: info: New Spotify access token = BQBrt16pTHCLG1mnHkbQUz0qZS1q8yZuvWHxk84-_JAcF38XTYIseeLJOFuSkhtav8P3gROJz_jX-o6MLvsqJydADycSovRMJbKWImoNM42vpbnUbh0ehZ-t4hLIkh8oueVhz5RNmQWiU5GmBZbYQoo6WhDx9nAJIoFN7LV1O8S-b3eaIZ-tMTNB8t9aUo57uMNQ9M1HFGAaQbqUBjvsHKO6vwgS0EQm0gv1-Q_SnxnLtu7xieYzwZH7H6tiffWuq2wm939-3mxpEORmAXWZ48oKZgK-1DZRJ8wJrRFnZGs Feb 16 16:49:28 volpi volumio[1102]: info: Spotify credentials grant success - running version from March 24, 2019 Feb 16 16:49:28 volpi go-librespot[18336]: time="2025-02-16T16:49:28+07:00" level=debug msg="obtained new client token: AABMloZsx9uN3MhcmZ6os8WtAS5aaVimaA+P7UUISDqGIsygfTADm2X7sYC0mbXVzIuQz1KYxRjQeNEziL7QkDd07N7jODdQ+fh+1/nAWd0OBY4xXK1C+FqK5O4FdU8zPtEqeskpaq97ZwCH6kpvLQpvDy0L8LRDAHd0smqhPXdHluZIxlAZ4EQLIhSDkonhUfU5UtMqN5hsM0zqvl3NBhsZYTuSFgAqI3mxhis/madvh6htMRau" Feb 16 16:49:28 volpi volumio[1102]: SPOTIFY: User informations: {"country":"VN","display_name":"Quang Thang","email":"rxfnd8jtdm@privaterelay.appleid.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31xcuwirp2h4xppvz5tksgw2s4tu"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31xcuwirp2h4xppvz5tksgw2s4tu","id":"31xcuwirp2h4xppvz5tksgw2s4tu","images":[],"product":"premium","type":"user","uri":"spotify:user:31xcuwirp2h4xppvz5tksgw2s4tu"} Feb 16 16:49:28 volpi volumio[1102]: info: Spotify Successfully logged in Feb 16 16:49:28 volpi volumio[1102]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 16 16:49:28 volpi volumio[1102]: info: [1739699368495] CoreMusicLibrary::Adding element Spotify Feb 16 16:49:28 volpi volumio[1102]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 16 16:49:28 volpi go-librespot[18336]: time="2025-02-16T16:49:28+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Feb 16 16:49:28 volpi volumio[1102]: Cannot find translation for source Spotify Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=debug msg="completed keyexchange" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=debug msg="completed challenge" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=info msg="authenticated AP as 31xcuwirp2h4xppvz5tksgw2s4tu" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=info msg="authenticated Login5 as 31xcuwirp2h4xppvz5tksgw2s4tu" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=debug msg="initializing zeroconf session, username: 31xcuwirp2h4xppvz5tksgw2s4tu" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=debug msg="dealer connection opened" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=trace msg="starting accesspoint recv loop" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=trace msg="starting dealer recv loop" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=trace msg="received accesspoint ping" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=debug msg="received connection id: MWVmZjA0ZmQtYzNlNi00NWMzLTg4ZmYtOGEyNWM2Yjk0YmNlK2RlYWxlcit0Y3A6Ly8wYWM5NDgwNC5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArMTFBNTUzRUE2NUQxMTMyNEY1NTdGNDZEMkU0MzU5NkU4MTA1OUIxMDFBNUJBNzM4OTVBNUE0OTAwREI0REE1MQ==" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=trace msg="received accesspoint pong ack" Feb 16 16:49:29 volpi go-librespot[18336]: time="2025-02-16T16:49:29+07:00" level=debug msg="put connect state because NEW_DEVICE" Feb 16 16:49:30 volpi ntpd[13991]: Soliciting pool server 2a0c:b847:ffff:79::e53c Feb 16 16:49:30 volpi volumio[1102]: info: go-librespot daemon successfully initialized Feb 16 16:49:31 volpi ntpd[13991]: Soliciting pool server 103.199.19.135 Feb 16 16:49:33 volpi volumio[1102]: info: Initializing connection to go-librespot Websocket Feb 16 16:49:33 volpi go-librespot[18336]: time="2025-02-16T16:49:33+07:00" level=debug msg="new websocket client" Feb 16 16:49:33 volpi volumio[1102]: info: Connection to go-librespot Websocket established Feb 16 16:49:36 volpi volumio[1102]: info: Getting Spotify volume Feb 16 16:49:36 volpi volumio[1102]: info: Spotify volume: 100 Feb 16 16:49:36 volpi volumio[1102]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Feb 16 16:49:36 volpi volumio[1102]: info: CoreCommandRouter::volumioGetState Feb 16 16:49:36 volpi volumio[1102]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Feb 16 16:49:36 volpi volumio[1102]: SPOTIFY: SPOTIFY VOLUME 100 Feb 16 16:49:36 volpi volumio[1102]: SPOTIFY: VOLUMIO VOLUME 86 Feb 16 16:49:36 volpi volumio[1102]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 16 16:49:36 volpi volumio[1102]: info: Setting Spotify Volume from Volumio: 86 Feb 16 16:49:38 volpi volumio[1102]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Feb 16 16:49:38 volpi volumio[1102]: info: Sending Spotify command with payload to local API: /player/volume Feb 16 16:49:38 volpi go-librespot[18336]: time="2025-02-16T16:49:38+07:00" level=debug msg="update volume to 56360/65535" Feb 16 16:49:38 volpi ntpd[13991]: Soliciting pool server 103.184.124.254 Feb 16 16:49:39 volpi go-librespot[18336]: time="2025-02-16T16:49:39+07:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 16 16:49:39 volpi go-librespot[18336]: time="2025-02-16T16:49:39+07:00" level=trace msg="emitting websocket event: volume" Feb 16 16:49:39 volpi volumio[1102]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Feb 16 16:49:39 volpi volumio[1102]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Feb 16 16:49:59 volpi go-librespot[18336]: time="2025-02-16T16:49:59+07:00" level=trace msg="sent dealer ping" Feb 16 16:49:59 volpi go-librespot[18336]: time="2025-02-16T16:49:59+07:00" level=trace msg="received dealer pong" Feb 16 16:50:10 volpi ntpd[13991]: Soliciting pool server 27.71.27.209 Feb 16 16:50:13 volpi volumio[1102]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 16 16:50:13 volpi volumio[1102]: Error: connect ETIMEDOUT 151.101.194.79:443 Feb 16 16:50:13 volpi volumio[1102]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) { Feb 16 16:50:13 volpi volumio[1102]: errno: -110, Feb 16 16:50:13 volpi volumio[1102]: code: 'ETIMEDOUT', Feb 16 16:50:13 volpi volumio[1102]: syscall: 'connect', Feb 16 16:50:13 volpi volumio[1102]: address: '151.101.194.79', Feb 16 16:50:13 volpi volumio[1102]: port: 443 Feb 16 16:50:13 volpi volumio[1102]: } Feb 16 16:50:13 volpi volumio[1102]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 16 16:50:13 volpi sudo[18485]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-16 16:49 Feb 16 16:50:13 volpi sudo[18485]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 07:25:16 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="66c567362bdbb3dc1644a18f7879afe7"