-- Logs begin at Thu 2019-02-14 12:11:58 EET, end at Wed 2025-01-15 09:35:36 EET. -- Jan 15 09:35:26 primo systemd[1]: Starting Daily apt download activities... Jan 15 09:35:26 primo systemd[1]: Starting Daily man-db regeneration... Jan 15 09:35:26 primo volumio[3270]: ------------------------------------ BT MESSAGE: BT STATUS: running Jan 15 09:35:26 primo volumio[3270]: ------------------------------------ BT MESSAGE: BT STATUS: running Jan 15 09:35:26 primo ntpd[4663]: receive: Unexpected origin timestamp 0xead8beb1.bed71889 does not match aorg 0000000000.00000000 from server@108.61.56.35 xmt 0xeb31e3be.9cf1e8c1 Jan 15 09:35:26 primo ntpd[4663]: receive: Unexpected origin timestamp 0xead8beb1.becec55b does not match aorg 0000000000.00000000 from server@192.210.243.178 xmt 0xeb31e3be.9ddda897 Jan 15 09:35:26 primo go-librespot[4692]: time="2025-01-15T09:35:26+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2024-11-08T18:45:37+02:00 is before 2025-01-06T00:00:00Z" Jan 15 09:35:26 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 15 09:35:26 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 15 09:35:26 primo volumio[3270]: info: Discovery: A device disappeared from network Jan 15 09:35:26 primo volumio[3270]: info: Discovery: Device primo disappeared from network Jan 15 09:35:26 primo volumio[3270]: info: Discovery: A device disappeared from network Jan 15 09:35:26 primo systemd[1]: man-db.service: Succeeded. Jan 15 09:35:26 primo systemd[1]: Started Daily man-db regeneration. Jan 15 09:35:27 primo dhcpcd[3313]: eth0: offered 192.168.0.30 from 192.168.0.1 Jan 15 09:35:27 primo dhcpcd[3313]: eth0: probing address 192.168.0.30/24 Jan 15 09:35:27 primo systemd[1]: apt-daily.service: Succeeded. Jan 15 09:35:27 primo systemd[1]: Started Daily apt download activities. Jan 15 09:35:27 primo systemd[1]: Starting Daily apt upgrade and clean activities... Jan 15 09:35:27 primo volumio[3270]: ------------------------------------ BT MESSAGE: BT STATUS: running Jan 15 09:35:28 primo systemd[1]: apt-daily-upgrade.service: Succeeded. Jan 15 09:35:28 primo systemd[1]: Started Daily apt upgrade and clean activities. Jan 15 09:35:29 primo volumio[3270]: info: MRS: Found cast device: 75QNED91T6A.BPIFLJP-3e6081e6620b8951dd885c3daa7d7e98 Jan 15 09:35:29 primo volumio[3270]: info: Adding audio output: Jan 15 09:35:29 primo volumio[3270]: info: MRS: Found cast device: WiiM-AMP-3bcba04551695be6c2f809e23024a679 Jan 15 09:35:29 primo volumio[3270]: info: Adding audio output: Jan 15 09:35:29 primo volumio[3270]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Jan 15 09:35:29 primo volumio[3270]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 15 09:35:29 primo volumio[3270]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Jan 15 09:35:29 primo volumio[3270]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Jan 15 09:35:29 primo volumio[3270]: info: MRS: Found cast device: 75QNED91T6A.BPIFLJP-3e6081e6620b8951dd885c3daa7d7e98 Jan 15 09:35:29 primo volumio[3270]: info: MRS: Found cast device: WiiM-AMP-3bcba04551695be6c2f809e23024a679 Jan 15 09:35:29 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 15 09:35:29 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Jan 15 09:35:29 primo systemd[1]: Stopped go-librespot Daemon. Jan 15 09:35:29 primo systemd[1]: Started go-librespot Daemon. Jan 15 09:35:29 primo go-librespot[4812]: Librespot-go daemon starting... Jan 15 09:35:29 primo volumio[3270]: info: Discovery: adding 616b7e5d-0e34-4236-bc06-622956d06eab Jan 15 09:35:29 primo volumio[3270]: info: Discovery: Found device Primo Jan 15 09:35:29 primo volumio[3270]: info: CoreCommandRouter::volumioGetState Jan 15 09:35:29 primo volumio[3270]: info: CorePlayQueue::getTrack 0 Jan 15 09:35:29 primo go-librespot[4812]: time="2025-01-15T09:35:29+02:00" level=info msg="generated new device id: a4da29ba3671d1e1eeb5a4b245ab23a92c3fa6f5" Jan 15 09:35:29 primo go-librespot[4812]: time="2025-01-15T09:35:29+02:00" level=debug msg="stored credentials found for 8lifijmywkmtyo5nspkfeeenc" Jan 15 09:35:30 primo volumio[3270]: info: MRS: Found cast device: 75QNED91T6A.BPIFLJP-3e6081e6620b8951dd885c3daa7d7e98 Jan 15 09:35:30 primo volumio[3270]: info: MRS: Found cast device: WiiM-AMP-3bcba04551695be6c2f809e23024a679 Jan 15 09:35:30 primo volumio[3270]: info: Discovery: this is already registered, 616b7e5d-0e34-4236-bc06-622956d06eab Jan 15 09:35:30 primo volumio[3270]: info: Discovery: Found device Primo Jan 15 09:35:30 primo volumio[3270]: info: CoreCommandRouter::volumioGetState Jan 15 09:35:30 primo volumio[3270]: info: CorePlayQueue::getTrack 0 Jan 15 09:35:30 primo volumio[3270]: info: Discovery: this is already registered, 616b7e5d-0e34-4236-bc06-622956d06eab Jan 15 09:35:30 primo volumio[3270]: info: Discovery: Found device Primo Jan 15 09:35:30 primo volumio[3270]: info: CoreCommandRouter::volumioGetState Jan 15 09:35:30 primo volumio[3270]: info: CorePlayQueue::getTrack 0 Jan 15 09:35:30 primo go-librespot[4812]: time="2025-01-15T09:35:30+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 15 09:35:30 primo go-librespot[4812]: time="2025-01-15T09:35:30+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 15 09:35:30 primo go-librespot[4812]: time="2025-01-15T09:35:30+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 15 09:35:30 primo go-librespot[4812]: time="2025-01-15T09:35:30+02:00" level=debug msg="zeroconf server listening on port 36809" Jan 15 09:35:30 primo volumio[3270]: info: MRS: Found cast device: 75QNED91T6A.BPIFLJP-3e6081e6620b8951dd885c3daa7d7e98 Jan 15 09:35:30 primo volumio[3270]: info: MRS: Found cast device: WiiM-AMP-3bcba04551695be6c2f809e23024a679 Jan 15 09:35:30 primo volumio[3270]: info: CoreCommandRouter::volumioGetState Jan 15 09:35:30 primo volumio[3270]: info: CorePlayQueue::getTrack 0 Jan 15 09:35:30 primo volumio[3270]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 15 09:35:30 primo volumio[3270]: SPOTIFY: SPOTIFY VOLUME undefined Jan 15 09:35:30 primo volumio[3270]: SPOTIFY: VOLUMIO VOLUME 100 Jan 15 09:35:30 primo volumio[3270]: info: Aligning Spotify Volume to Volumio Volume Jan 15 09:35:30 primo volumio[3270]: info: CoreCommandRouter::volumioGetState Jan 15 09:35:30 primo volumio[3270]: info: CorePlayQueue::getTrack 0 Jan 15 09:35:30 primo volumio[3270]: info: Setting Spotify Volume from Volumio: 100 Jan 15 09:35:30 primo go-librespot[4812]: time="2025-01-15T09:35:30+02:00" level=debug msg="obtained new client token: AABNNVR74lDEkkaWVrJv1qDY11pbW13gAfZjIz7AECh6W1lM8VEghkwM/g7qLgf8DfrDOluKNVWbze0AveM33HO3k+/SRDu4jFI9dncOwjZES+tU4CXQaxn/mqwwxb8l7qZcVY/w2/qumSrfdpOzx4euDEAfBjjWAMZRTv0LrpI4cOveni9V7EmlPx2AE691175JeXpTixsch2f9ulfxT1Y2AX+RiueAugb39se+mcZ+TYYTSWkrrJDdmMf3mw==" Jan 15 09:35:30 primo go-librespot[4812]: time="2025-01-15T09:35:30+02:00" level=info msg="connected to ap-gew1.spotify.com:4070" Jan 15 09:35:30 primo volumio-time-update[2818]: volumio-time-update-util: Date not found in response Jan 15 09:35:30 primo volumio-time-update[2818]: volumio-time-update-util: Retrying in 5 seconds... Jan 15 09:35:30 primo go-librespot[4812]: time="2025-01-15T09:35:30+02:00" level=debug msg="completed keyexchange" Jan 15 09:35:31 primo go-librespot[4812]: time="2025-01-15T09:35:31+02:00" level=debug msg="completed challenge" Jan 15 09:35:31 primo go-librespot[4812]: time="2025-01-15T09:35:31+02:00" level=debug msg="authenticated as 8lifijmywkmtyo5nspkfeeenc" Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 15 09:35:31 primo volumio[3270]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 15 09:35:31 primo go-librespot[4812]: time="2025-01-15T09:35:31+02:00" level=debug msg="authenticated as 8lifijmywkmtyo5nspkfeeenc" Jan 15 09:35:31 primo go-librespot[4812]: time="2025-01-15T09:35:31+02:00" level=debug msg="dealer connection opened" Jan 15 09:35:31 primo go-librespot[4812]: time="2025-01-15T09:35:31+02:00" level=debug msg="initializing zeroconf session, username: 8lifijmywkmtyo5nspkfeeenc" Jan 15 09:35:31 primo go-librespot[4812]: time="2025-01-15T09:35:31+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 15 09:35:31 primo go-librespot[4812]: time="2025-01-15T09:35:31+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 15 09:35:31 primo go-librespot[4812]: time="2025-01-15T09:35:31+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 15 09:35:31 primo go-librespot[4812]: time="2025-01-15T09:35:31+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 15 09:35:31 primo go-librespot[4812]: time="2025-01-15T09:35:31+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 15 09:35:31 primo go-librespot[4812]: time="2025-01-15T09:35:31+02:00" level=debug msg="autoplay enabled: false" Jan 15 09:35:31 primo go-librespot[4812]: time="2025-01-15T09:35:31+02:00" level=debug msg="received connection id: ZWU1NmZhNDktZmM0OS00MmUxLTg2OWUtYzNjYTJlZDU3NzUwK2RlYWxlcit0Y3A6Ly8wYWNhNDBiYi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArNkMyMkIxRDlDQkVEOEJDRjI1OEFGMkFFMkY0MUVCRTIzNjRFQjY3RkUzMkM3NkMyMkYyMzdEQUQ4M0U0RTQyQw==" Jan 15 09:35:32 primo go-librespot[4812]: time="2025-01-15T09:35:32+02:00" level=debug msg="put connect state because NEW_DEVICE" Jan 15 09:35:32 primo dhcpcd[3313]: eth0: leased 192.168.0.30 for 7200 seconds Jan 15 09:35:32 primo dhcpcd[3313]: eth0: adding route to 192.168.0.0/24 Jan 15 09:35:32 primo avahi-daemon[2813]: Registering new address record for 192.168.0.30 on eth0.IPv4. Jan 15 09:35:32 primo dhcpcd[3313]: eth0: adding default route via 192.168.0.1 Jan 15 09:35:32 primo systemd[1]: Stopping Network Time Service... Jan 15 09:35:32 primo ntpd[4663]: ntpd exiting on signal 15 (Terminated) Jan 15 09:35:32 primo ntpd[4663]: 193.238.174.38 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 162.159.200.123 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 173.208.172.164 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 185.117.82.71 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 155.248.196.28 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 209.141.37.122 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 77.236.182.128 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 134.215.155.177 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 23.186.168.1 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 142.202.190.19 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 108.61.73.244 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 108.61.56.35 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 135.148.100.14 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 192.210.243.178 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 45.83.234.123 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 140.82.42.212 local addr 192.168.0.28 -> Jan 15 09:35:32 primo ntpd[4663]: 74.6.168.72 local addr 192.168.0.28 -> Jan 15 09:35:32 primo systemd[1]: ntp.service: Succeeded. Jan 15 09:35:32 primo systemd[1]: Stopped Network Time Service. Jan 15 09:35:32 primo systemd[1]: Starting Network Time Service... Jan 15 09:35:32 primo ntpd[4855]: ntpd 4.2.8p12@1.3728-o (1): Starting Jan 15 09:35:32 primo ntpd[4855]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Jan 15 09:35:32 primo systemd[1]: Started Network Time Service. Jan 15 09:35:32 primo ntpd[4861]: proto: precision = 1.291 usec (-19) Jan 15 09:35:32 primo ntpd[4861]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Jan 15 09:35:32 primo avahi-daemon[2813]: Withdrawing address record for 169.254.192.98 on eth0. Jan 15 09:35:32 primo avahi-daemon[2813]: Leaving mDNS multicast group on interface eth0.IPv4 with address 169.254.192.98. Jan 15 09:35:32 primo ntpd[4861]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Jan 15 09:35:32 primo ntpd[4861]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 750 days ago Jan 15 09:35:32 primo ntpd[4861]: Listen and drop on 0 v6wildcard [::]:123 Jan 15 09:35:32 primo ntpd[4861]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Jan 15 09:35:32 primo dhcpcd[3313]: eth0: deleting route to 169.254.0.0/16 Jan 15 09:35:32 primo avahi-daemon[2813]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.0.30. Jan 15 09:35:32 primo ntpd[4861]: Listen normally on 2 lo 127.0.0.1:123 Jan 15 09:35:32 primo ntpd[4861]: Listen normally on 3 eth0 192.168.0.30:123 Jan 15 09:35:32 primo ntpd[4861]: Listen normally on 4 wlan0 192.168.0.28:123 Jan 15 09:35:32 primo ntpd[4861]: Listening on routing socket on fd #21 for interface updates Jan 15 09:35:32 primo ntpd[4861]: kernel reports TIME_ERROR: 0x4041: Clock Unsynchronized Jan 15 09:35:32 primo ntpd[4861]: kernel reports TIME_ERROR: 0x4041: Clock Unsynchronized Jan 15 09:35:33 primo volumio[3270]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 15 09:35:33 primo volumio[3270]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 15 09:35:33 primo volumio[3270]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 15 09:35:33 primo volumio[3270]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 15 09:35:33 primo volumio[3270]: info: Starting MyVolumio Remote Streaming Endpoints Jan 15 09:35:33 primo volumio[3270]: info: MyVolumio login type: Token Jan 15 09:35:33 primo volumio[3270]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 15 09:35:33 primo volumio[3270]: error: [MyVolumio PluginManager] Could not read package.json file: Error: /myvolumio/plugins/music_service/streaming_services//package.json: ENOENT: no such file or directory, open '/myvolumio/plugins/music_service/streaming_services//package.json' Jan 15 09:35:33 primo volumio[3270]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Jan 15 09:35:33 primo volumio[3270]: info: Sending Spotify command with payload to local API: /player/volume Jan 15 09:35:33 primo volumio[3270]: info: Initializing connection to go-librespot Websocket Jan 15 09:35:33 primo volumio[3270]: ------------------------------------ BT MESSAGE: BT STATUS: running Jan 15 09:35:33 primo volumio[3270]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jan 15 09:35:33 primo volumio[3270]: ------------------------------------ BT MESSAGE: BT STATUS: running Jan 15 09:35:33 primo go-librespot[4812]: time="2025-01-15T09:35:33+02:00" level=debug msg="new websocket client" Jan 15 09:35:33 primo volumio[3270]: info: Connection to go-librespot Websocket established Jan 15 09:35:33 primo volumio[3270]: error: MyVolumio Custom Token format not valid, refreshing it Jan 15 09:35:33 primo ntpd[4861]: Soliciting pool server 192.210.243.178 Jan 15 09:35:34 primo volumio[3270]: info: MyVolumio login type: Token Jan 15 09:35:34 primo ntpd[4861]: Soliciting pool server 148.113.194.34 Jan 15 09:35:34 primo ntpd[4861]: Soliciting pool server 173.208.172.164 Jan 15 09:35:35 primo volumio[3270]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jan 15 09:35:35 primo ntpd[4861]: Soliciting pool server 155.248.196.28 Jan 15 09:35:35 primo ntpd[4861]: Soliciting pool server 140.82.42.212 Jan 15 09:35:35 primo volumio-time-update[2818]: volumio-time-update-util: Fetching time from Volumio... Jan 15 09:35:35 primo ntpd[4861]: Soliciting pool server 208.76.2.12 Jan 15 09:35:35 primo volumio[3270]: info: MyVolumio token set successfully Jan 15 09:35:35 primo volumio[3270]: info: MYVOLUMIO: Adding device Jan 15 09:35:35 primo volumio[3270]: info: MYVOLUMIO: Evaluating Server Jan 15 09:35:36 primo volumio-time-update[2818]: volumio-time-update-util: Setting system time to: 2025-01-15 09:35:35 Jan 15 09:35:36 primo sudo[4906]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2025-01-15 09:35:35 Jan 15 09:35:36 primo sudo[4906]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 15 09:35:36 primo dbus-daemon[2835]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.52' (uid=0 pid=4909 comm="timedatectl set-time 2025-01-15 09:35:35 " label="kernel") Jan 15 09:35:36 primo systemd[1]: Starting Time & Date Service... Jan 15 09:35:36 primo dbus-daemon[2835]: [system] Successfully activated service 'org.freedesktop.timedate1' Jan 15 09:35:36 primo systemd[1]: Started Time & Date Service. Jan 15 09:35:35 primo systemd-timedated[4912]: Changed local time to Wed Jan 15 09:35:35 2025 Jan 15 09:35:35 primo sudo[4906]: pam_unix(sudo:session): session closed for user root Jan 15 09:35:35 primo volumio-time-update[2818]: volumio-time-update-util: System time updated successfully. Jan 15 09:35:35 primo systemd[1]: Started Volumio Time Update Utility. Jan 15 09:35:35 primo systemd[1]: Reached target Multi-User System. Jan 15 09:35:35 primo systemd[1]: Reached target Graphical Interface. Jan 15 09:35:35 primo systemd[1]: Starting Update UTMP about System Runlevel Changes... Jan 15 09:35:35 primo systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jan 15 09:35:35 primo systemd[1]: Started Update UTMP about System Runlevel Changes. Jan 15 09:35:35 primo systemd[1]: Startup finished in 12.805s (kernel) + 4min 1.305s (userspace) = 4min 14.110s. Jan 15 09:35:35 primo volumio[3270]: info: Getting Spotify volume Jan 15 09:35:35 primo volumio[3270]: info: MyVolumio Plan changed: premium Jan 15 09:35:35 primo volumio[3270]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Jan 15 09:35:35 primo volumio[3270]: info: Removing browser output: myVolumio user plan is not superstar Jan 15 09:35:35 primo volumio[3270]: info: Removing audio output: Jan 15 09:35:35 primo volumio[3270]: info: MYVOLUMIO: Adding device Jan 15 09:35:35 primo volumio[3270]: info: MYVOLUMIO: Evaluating Server Jan 15 09:35:35 primo volumio[3270]: ------------------------------------ BT MESSAGE: BT STATUS: running Jan 15 09:35:35 primo volumio[3270]: ------------------------------------ BT MESSAGE: BT STATUS: running Jan 15 09:35:35 primo volumio[3270]: error: Failed to ping endpoint eu8.myvolumio.org : unknown error Jan 15 09:35:35 primo volumio[3270]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 15 09:35:35 primo volumio[3270]: Error: Unable to resolve or reject the same promise twice Jan 15 09:35:35 primo volumio[3270]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Jan 15 09:35:35 primo volumio[3270]: at Socket. (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:32367) Jan 15 09:35:35 primo volumio[3270]: at Socket.emit (events.js:400:28) Jan 15 09:35:35 primo volumio[3270]: at addChunk (internal/streams/readable.js:293:12) Jan 15 09:35:35 primo volumio[3270]: at readableAddChunk (internal/streams/readable.js:267:9) Jan 15 09:35:35 primo volumio[3270]: at Socket.Readable.push (internal/streams/readable.js:206:10) Jan 15 09:35:35 primo volumio[3270]: at Pipe.onStreamRead (internal/stream_base_commons.js:188:23) Jan 15 09:35:35 primo volumio[3270]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 15 09:35:35 primo ntpd[4861]: Soliciting pool server 212.227.240.160 Jan 15 09:35:35 primo ntpd[4861]: Soliciting pool server 108.61.56.35 Jan 15 09:35:35 primo ntpd[4861]: Soliciting pool server 99.28.14.242 Jan 15 09:35:35 primo ntpd[4861]: Soliciting pool server 135.148.100.14 Jan 15 09:35:35 primo sudo[4943]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-01-15 09:34 Jan 15 09:35:35 primo sudo[4943]: 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="armv7" VOLUMIO_VARIANT="primo2rev2" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 05:41:47 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Primo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo" VOLUMIO_HASH="d050b972c82ad0b26840d04dc6ef55b1"