-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sat 2026-10-03 08:25:53 CEST. -- Oct 03 08:25:18 volumio systemd-timedated[1614]: Changed local time to Sat Oct 3 08:25:18 2026 Oct 03 08:25:18 volumio sudo[1605]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:18 volumio volumio-time-update[609]: volumio-time-update-util: System time updated successfully. Oct 03 08:25:18 volumio volumio-cpu-tweak[1618]: Setting RT Priority for mpd Oct 03 08:25:18 volumio systemd[1]: Started Volumio Time Update Utility. Oct 03 08:25:18 volumio systemd[1]: Starting Daily apt download activities... Oct 03 08:25:18 volumio netdata[677]: Postponing alarm checks for 60 seconds, because it seems that the system was just resumed from suspension. Oct 03 08:25:18 volumio netdata[677]: heartbeat clock: woke up 16312854275582 microseconds later than expected (can be due to system load or the CLOCK_REALTIME set to the future). Oct 03 08:25:18 volumio netdata[677]: STREAM PARENTS 'volumio': failed to extract fields from JSON stream info response from '192.168.1.64:19999': status reported (404) is not OK (200) - JSON data: { "version":1, "status":404, "host_id":"05804fe7-2ed3-49fb-95fb-8915cab835da", "nodes":1, "receivers":0, "nonce":2838474183 } Oct 03 08:25:18 volumio netdata[677]: STREAM CONNECT 'volumio' [to 192.168.1.64:19999]: remote server denied access, probably we don't have the right API key? - will retry in 60 secs, at 2026-10-03T08:26:05+02:00 Oct 03 08:25:18 volumio systemd-journal.plugin[1348]: heartbeat clock: woke up 16312854275617 microseconds later than expected (can be due to system load or the CLOCK_REALTIME set to the future). Oct 03 08:25:18 volumio netdata[677]: RRDCONTEXT: host 'volumio' pruned 244 queued context updates (force_drop_all=false, bounded=true) Oct 03 08:25:18 volumio network-viewer.plugin[1350]: heartbeat clock: woke up 16312854275617 microseconds later than expected (can be due to system load or the CLOCK_REALTIME set to the future). Oct 03 08:25:18 volumio volumio-remote-updater[594]: [2026-10-03 08:25:18] [info] asio async_connect error: system:111 (Connection refused) Oct 03 08:25:18 volumio volumio-remote-updater[594]: [2026-10-03 08:25:18] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Oct 03 08:25:18 volumio volumio-remote-updater[594]: [2026-10-03 08:25:18] [error] handle_connect error: Underlying Transport Error Oct 03 08:25:18 volumio netdata[677]: ACLK: connecting to app.netdata.cloud:443 (no proxy) Oct 03 08:25:18 volumio volumio-cpu-tweak[1618]: pid 35's current scheduling policy: SCHED_OTHER Oct 03 08:25:18 volumio volumio-cpu-tweak[1618]: pid 35's current scheduling priority: 0 Oct 03 08:25:18 volumio volumio-cpu-tweak[1618]: Setting MPD Affinity Oct 03 08:25:19 volumio nfacct.plugin[1345]: heartbeat clock: woke up 16312854275623 microseconds later than expected (can be due to system load or the CLOCK_REALTIME set to the future). Oct 03 08:25:19 volumio debugfs.plugin[1342]: heartbeat clock: woke up 16312854275617 microseconds later than expected (can be due to system load or the CLOCK_REALTIME set to the future). Oct 03 08:25:19 volumio apps.plugin[1344]: heartbeat clock: woke up 16312854275619 microseconds later than expected (can be due to system load or the CLOCK_REALTIME set to the future). Oct 03 08:25:19 volumio nmbd[698]: [2026/10/03 08:25:19.814997, 0] ../lib/util/become_daemon.c:138(daemon_ready) Oct 03 08:25:19 volumio nmbd[698]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Oct 03 08:25:19 volumio systemd[1]: Started Samba NMB Daemon. Oct 03 08:25:19 volumio systemd[1]: Starting Samba Winbind Daemon... Oct 03 08:25:20 volumio volumio-cpu-tweak[1618]: pid 3's current affinity mask: f Oct 03 08:25:20 volumio volumio-cpu-tweak[1618]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Oct 03 08:25:20 volumio volumio-cpu-tweak[1618]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Oct 03 08:25:20 volumio systemd[1]: volumio_cpu_tweak.service: Succeeded. Oct 03 08:25:22 volumio netflow-plugin[1347]: starting plugin runtime: netflow-plugin Oct 03 08:25:22 volumio netflow-plugin[1347]: chart registry started Oct 03 08:25:22 volumio netflow-plugin[1347]: declaring function: flows:netflow Oct 03 08:25:22 volumio netflow-plugin[1347]: scanning directory: /opt/netdata/var/cache/netdata/flows/raw Oct 03 08:25:22 volumio netflow-plugin[1347]: starting message processing loop Oct 03 08:25:22 volumio netflow-plugin[1347]: found 0 journal files in /opt/netdata/var/cache/netdata/flows/raw Oct 03 08:25:22 volumio netflow-plugin[1347]: now watching directory: /opt/netdata/var/cache/netdata/flows/raw (total directories: 1) Oct 03 08:25:22 volumio netflow-plugin[1347]: UDP receive buffer for 0.0.0.0:2055: 360448 bytes (requested 67108864; capped by net.core.rmem_max) Oct 03 08:25:22 volumio netflow-plugin[1347]: UDP receive buffer for 0.0.0.0:6343: 360448 bytes (requested 67108864; capped by net.core.rmem_max) Oct 03 08:25:22 volumio netdata[677]: ACLK: HTTPS "GET" request to "app.netdata.cloud" finished with HTTP code: 200 Oct 03 08:25:22 volumio netdata[677]: ACLK: connecting to api.netdata.cloud:443 (no proxy) Oct 03 08:25:23 volumio netdata[677]: ACLK: HTTPS "GET" request to "api.netdata.cloud" finished with HTTP code: 200 Oct 03 08:25:23 volumio netdata[677]: ACLK: connecting to api.netdata.cloud:443 (no proxy) Oct 03 08:25:23 volumio systemd[1]: systemd-fsckd.service: Succeeded. Oct 03 08:25:23 volumio netdata[677]: ACLK: HTTPS "POST" request to "api.netdata.cloud" finished with HTTP code: 201 Oct 03 08:25:23 volumio netdata[677]: ACLK: connecting to mqtt.netdata.cloud:443 (no proxy) Oct 03 08:25:23 volumio winbindd[1636]: [2026/10/03 08:25:23.736072, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Oct 03 08:25:23 volumio winbindd[1636]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Oct 03 08:25:23 volumio winbindd[1636]: [2026/10/03 08:25:23.869022, 0] ../lib/util/become_daemon.c:138(daemon_ready) Oct 03 08:25:23 volumio systemd[1]: Started Samba Winbind Daemon. Oct 03 08:25:23 volumio winbindd[1636]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Oct 03 08:25:23 volumio systemd[1]: Starting Samba SMB Daemon... Oct 03 08:25:23 volumio netdata[677]: ACLK: Websocket Connection Accepted By Server Oct 03 08:25:24 volumio netdata[677]: ACLK: MQTT server limits message size to 7340032 Oct 03 08:25:24 volumio netdata[677]: ACLK: MQTT server receive maximum is 32 Oct 03 08:25:24 volumio netdata[677]: ACLK: MQTT Connection Accepted By Server Oct 03 08:25:24 volumio netdata[677]: ACLK: connection successfully established Oct 03 08:25:24 volumio netdata[677]: Netdata Cloud, ACLK connection status: connected Oct 03 08:25:24 volumio netdata[677]: NODES INFO: 0 nodes loading contexts, 0 receiving replication, 0 sending replication, 1 pending context post processing (host 'volumio') Oct 03 08:25:24 volumio sh[477]: timed out Oct 03 08:25:24 volumio dhcpcd[521]: timed out Oct 03 08:25:24 volumio sh[477]: dhcpcd exited Oct 03 08:25:24 volumio dhcpcd[521]: dhcpcd exited Oct 03 08:25:24 volumio sh[477]: ifup: failed to bring up eth0 Oct 03 08:25:24 volumio systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Oct 03 08:25:24 volumio systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Oct 03 08:25:24 volumio netdata[677]: python.d WARNING: plugin[main] : [pandas] error on loading source : ModuleNotFoundError("No module named 'pandas'"), skipping it Oct 03 08:25:25 volumio netdata[677]: python.d INFO: plugin[main] : no jobs to serve Oct 03 08:25:25 volumio netdata[677]: python.d INFO: plugin[main] : exiting from main... Oct 03 08:25:25 volumio netdata[677]: PLUGINSD: plugin called DISABLE. Disabling it. Oct 03 08:25:25 volumio netdata[677]: PLUGINSD: 'host:volumio', '/opt/netdata/usr/libexec/netdata/plugins.d/python.d.plugin' (pid 1331) disconnected after 0 successful data collections. Oct 03 08:25:25 volumio netdata[677]: PLUGINSD: 'host:volumio', '/opt/netdata/usr/libexec/netdata/plugins.d/python.d.plugin' (pid 1331) does not generate useful output but it reports success (exits with 0). Will not start it again - it is now disabled.. Oct 03 08:25:26 volumio systemd[1]: Started Samba SMB Daemon. Oct 03 08:25:26 volumio smbd[1665]: [2026/10/03 08:25:26.023617, 0] ../lib/util/become_daemon.c:138(daemon_ready) Oct 03 08:25:26 volumio systemd[1]: Reached target Multi-User System. Oct 03 08:25:26 volumio smbd[1665]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Oct 03 08:25:26 volumio systemd[1]: Reached target Graphical Interface. Oct 03 08:25:26 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Oct 03 08:25:26 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Oct 03 08:25:26 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Oct 03 08:25:27 volumio netdata[677]: RRDCONTEXT: received version hash 195730384 for host 'volumio', does not match our version hash 0. Sending snapshot of all contexts. Oct 03 08:25:28 volumio volumio-remote-updater[594]: [2026-10-03 08:25:28] [connect] Successful connection Oct 03 08:25:30 volumio volumio[1617]: info: ------------------------------------------- Oct 03 08:25:30 volumio volumio[1617]: info: ----- Volumio3 ---- Oct 03 08:25:30 volumio volumio[1617]: info: ------------------------------------------- Oct 03 08:25:30 volumio volumio[1617]: info: ----- System startup ---- Oct 03 08:25:30 volumio volumio[1617]: info: ------------------------------------------- Oct 03 08:25:30 volumio systemd[1]: apt-daily.service: Succeeded. Oct 03 08:25:30 volumio systemd[1]: Started Daily apt download activities. Oct 03 08:25:30 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Oct 03 08:25:31 volumio volumio[1617]: info: MYVOLUMIO Environment detected Oct 03 08:25:32 volumio volumio[1617]: info: Plugin folders cleanup Oct 03 08:25:32 volumio volumio[1617]: info: Scanning into folder /volumio/app/plugins/ Oct 03 08:25:32 volumio volumio[1617]: info: Scanning category audio_interface Oct 03 08:25:32 volumio volumio[1617]: info: Scanning category miscellanea Oct 03 08:25:32 volumio volumio[1617]: info: Scanning category music_service Oct 03 08:25:32 volumio volumio[1617]: info: Scanning category plugins.json Oct 03 08:25:32 volumio volumio[1617]: info: Scanning category system_controller Oct 03 08:25:32 volumio volumio[1617]: info: Scanning category user_interface Oct 03 08:25:32 volumio volumio[1617]: info: Scanning into folder /data/plugins/ Oct 03 08:25:32 volumio volumio[1617]: info: Scanning category music_service Oct 03 08:25:32 volumio volumio[1617]: info: Plugin folders cleanup completed Oct 03 08:25:32 volumio volumio[1617]: info: ------------------------------------------- Oct 03 08:25:32 volumio volumio[1617]: info: ----- Core plugins startup ---- Oct 03 08:25:32 volumio volumio[1617]: info: ------------------------------------------- Oct 03 08:25:32 volumio volumio[1617]: info: Loading plugins from folder /volumio/app/plugins/ Oct 03 08:25:32 volumio volumio[1617]: info: Adding plugin upnp to MyMusic Plugins Oct 03 08:25:32 volumio volumio[1617]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 03 08:25:32 volumio volumio[1617]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 03 08:25:32 volumio volumio[1617]: info: Loading plugins from folder /data/plugins/ Oct 03 08:25:32 volumio volumio[1617]: info: Loading plugin "system"... Oct 03 08:25:32 volumio volumio[1617]: info: Loading plugin "appearance"... Oct 03 08:25:32 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Oct 03 08:25:32 volumio systemd[1]: Started Daily apt upgrade and clean activities. Oct 03 08:25:32 volumio systemd[1]: Startup finished in 13.868s (kernel) + 43.191s (userspace) = 57.060s. Oct 03 08:25:33 volumio netdata[677]: level=info msg="plugin: name=go.d, version=v2.11.0 go_version=go1.26.5 user_config_dir=/opt/netdata/etc/netdata stock_config_dir=/opt/netdata/usr/lib/netdata/conf.d plugins_dir=/opt/netdata/usr/libexec/netdata/plugins.d netdata_bin_dir=/opt/netdata/usr/sbin cache_dir=/opt/netdata/var/cache/netdata var_lib_dir=/opt/netdata/var/lib/netdata log_dir=/opt/netdata/var/log/netdata" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="env HTTP_PROXY '', HTTPS_PROXY ''" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="directories → config: [/opt/netdata/etc/netdata /opt/netdata/usr/lib/netdata/conf.d] | collectors: [/opt/netdata/etc/netdata/go.d /opt/netdata/usr/lib/netdata/conf.d/go.d] | sd: [/opt/netdata/etc/netdata/go.d/sd /opt/netdata/usr/lib/netdata/conf.d/go.d/sd] | varlib: /opt/netdata/var/lib/netdata" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="instance is started" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="loading config file" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="found '/opt/netdata/usr/lib/netdata/conf.d/go.d.conf" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="config successfully loaded" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="using config: enabled 'true', default_run 'true', max_procs '0'" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="loading modules" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="'k8s_state' module disabled by default, should be explicitly enabled in the config" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="'testrandom' module disabled by default, should be explicitly enabled in the config" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="enabled/registered modules: 133/135" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="building discovery config" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="couldn't find 'sql' module config, will use default config" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="dummy/read/watch paths: 1/132/0" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="found '/opt/netdata/usr/lib/netdata/conf.d/vnodes' (0 vhosts)" plugin=go.d component=agent Oct 03 08:25:33 volumio netdata[677]: level=info msg="runtime metrics job started" plugin=go.d component=agent component="runtime metrics service" component="runtime metrics job" Oct 03 08:25:33 volumio netdata[677]: level=info msg="job manager generation started" plugin=go.d component="job manager" event_sequence=1 run_generation=1 Oct 03 08:25:33 volumio netdata[677]: level=info msg="instance is started" plugin=go.d component=discovery discoverer=file Oct 03 08:25:33 volumio netdata[677]: level=info msg="instance is started" plugin=go.d component=discovery discoverer=dummy Oct 03 08:25:33 volumio netdata[677]: level=info msg="instance is started" plugin=go.d component="service discovery" Oct 03 08:25:33 volumio netdata[677]: level=info msg="registered dyncfg template for discoverer type 'net_listeners'" plugin=go.d component="service discovery" Oct 03 08:25:33 volumio netdata[677]: level=info msg="registered dyncfg template for discoverer type 'k8s'" plugin=go.d component="service discovery" Oct 03 08:25:33 volumio netdata[677]: level=info msg="registered dyncfg template for discoverer type 'http'" plugin=go.d component="service discovery" Oct 03 08:25:33 volumio netdata[677]: level=info msg="registered dyncfg template for discoverer type 'snmp'" plugin=go.d component="service discovery" Oct 03 08:25:33 volumio netdata[677]: level=info msg="registered dyncfg template for discoverer type 'docker'" plugin=go.d component="service discovery" Oct 03 08:25:33 volumio netdata[677]: level=info msg="instance is stopped" plugin=go.d component=discovery discoverer=dummy Oct 03 08:25:33 volumio netdata[677]: level=info msg="instance is started" plugin=go.d component=discovery discoverer=file Oct 03 08:25:33 volumio netdata[677]: level=info msg="job configuration command completed" plugin=go.d component="job manager" event_sequence=2 run_generation=1 resource=sql command=enable state=removed result_status=200 Oct 03 08:25:33 volumio netdata[677]: level=info msg="pipeline '/opt/netdata/usr/lib/netdata/conf.d/go.d/sd/docker.conf' started" plugin=go.d component="service discovery" Oct 03 08:25:33 volumio netdata[677]: level=info msg="instance is started" plugin=go.d component="service discovery" pipeline=docker Oct 03 08:25:33 volumio netdata[677]: level=info msg="service discovery configuration command completed" plugin=go.d component="job manager" event_sequence=3 run_generation=1 resource=sd:docker command=enable result_status=200 Oct 03 08:25:33 volumio netdata[677]: level=info msg="pipeline 'http' is disabled in config" plugin=go.d component="service discovery" Oct 03 08:25:33 volumio netdata[677]: level=info msg="instance is started" plugin=go.d component="service discovery" discoverer=docker Oct 03 08:25:33 volumio netdata[677]: level=error msg="failed to connect to the docker API at unix:///var/run/docker.sock; check if the path is correct and if the daemon is running: dial unix /var/run/docker.sock: connect: no such file or directory" plugin=go.d component="service discovery" discoverer=docker Oct 03 08:25:33 volumio netdata[677]: level=info msg="instance is stopped" plugin=go.d component="service discovery" discoverer=docker Oct 03 08:25:33 volumio netdata[677]: level=info msg="discoverer 'sd:docker' exited before ctx done" plugin=go.d component="service discovery" pipeline=docker Oct 03 08:25:33 volumio netdata[677]: level=info msg="all discoverers exited before ctx done" plugin=go.d component="service discovery" pipeline=docker Oct 03 08:25:33 volumio netdata[677]: level=info msg="instance is stopped" plugin=go.d component="service discovery" pipeline=docker Oct 03 08:25:33 volumio netdata[677]: level=info msg="pipeline '/opt/netdata/usr/lib/netdata/conf.d/go.d/sd/net_listeners.conf' started" plugin=go.d component="service discovery" Oct 03 08:25:33 volumio netdata[677]: level=info msg="service discovery configuration command completed" plugin=go.d component="job manager" event_sequence=4 run_generation=1 resource=sd:net_listeners command=enable result_status=200 Oct 03 08:25:33 volumio netdata[677]: level=info msg="instance is started" plugin=go.d component="service discovery" pipeline=net_listeners Oct 03 08:25:33 volumio netdata[677]: level=info msg="pipeline 'snmp' is disabled in config" plugin=go.d component="service discovery" Oct 03 08:25:33 volumio netdata[677]: level=info msg="instance is started" plugin=go.d component="service discovery" discoverer=net_listeners Oct 03 08:25:33 volumio netdata[677]: level=info msg="instance is stopped" plugin=go.d component=discovery discoverer=file Oct 03 08:25:34 volumio netdata[677]: level=info msg="chartengine program loaded revision=1 charts=1 metrics=1" plugin=go.d component=agent component="runtime metrics service" component="runtime metrics job" runtime_component=jobmgr.runtime Oct 03 08:25:34 volumio netdata[677]: level=info msg="runtime metrics job stopped" plugin=go.d component=agent component="runtime metrics service" component="runtime metrics job" Oct 03 08:25:34 volumio netdata[677]: panic: unaligned 64-bit atomic operation Oct 03 08:25:34 volumio netdata[677]: PARSER: read failed: POLLHUP. Oct 03 08:25:34 volumio spawn-plugins[843]: SPAWN SERVER: child with pid 1349 (request 13) exited with exit code 2: /bin/sh -c "exec /opt/netdata/usr/libexec/netdata/plugins.d/go.d.plugin 5 " Oct 03 08:25:34 volumio netdata[677]: PLUGINSD: buffered reader not OK (-4) Oct 03 08:25:34 volumio netdata[677]: PLUGINSD: 'host:volumio', '/opt/netdata/usr/libexec/netdata/plugins.d/go.d.plugin' (pid 1349) disconnected after 151 successful data collections. Oct 03 08:25:34 volumio netdata[677]: PLUGINSD: 'host:volumio', '/opt/netdata/usr/libexec/netdata/plugins.d/go.d.plugin' (pid 1349) exited with error code 2, but has given useful output in the past (151 times). Waiting a bit before starting it again. Oct 03 08:25:34 volumio netdata[677]: NODES INFO: 0 nodes loading contexts, 0 receiving replication, 0 sending replication, 1 pending context post processing (host 'volumio') Oct 03 08:25:34 volumio volumio[1617]: info: Loading plugin "network"... Oct 03 08:25:34 volumio volumio[1617]: info: Refreshing Cached IP Addresses Oct 03 08:25:34 volumio volumio[1617]: info: Loading plugin "services"... Oct 03 08:25:34 volumio volumio[1617]: info: Loading plugin "volumio5onboarding"... Oct 03 08:25:34 volumio sudo[1786]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 03 08:25:34 volumio sudo[1786]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:34 volumio sudo[1784]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 03 08:25:34 volumio sudo[1786]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:34 volumio volumio[1617]: info: Loading plugin "alsa_controller"... Oct 03 08:25:34 volumio sudo[1790]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 03 08:25:34 volumio sudo[1784]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:34 volumio sudo[1790]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:34 volumio sudo[1784]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:35 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 03 08:25:35 volumio volumio[1617]: info: Loading plugin "wizard"... Oct 03 08:25:35 volumio volumio[1617]: info: Loading plugin "networkfs"... Oct 03 08:25:35 volumio volumio[1617]: info: Starting Udev Watcher for removable devices Oct 03 08:25:35 volumio volumio[1617]: info: Ignoring mount for partition: boot Oct 03 08:25:35 volumio volumio[1617]: info: Ignoring mount for partition: volumio Oct 03 08:25:35 volumio volumio[1617]: info: Ignoring mount for partition: volumio_data Oct 03 08:25:35 volumio volumio[1617]: info: Mounting Device music Oct 03 08:25:35 volumio sudo[1814]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/music -o noatime Oct 03 08:25:35 volumio sudo[1814]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:35 volumio sudo[1814]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:35 volumio kernel: EXT4-fs (sda1): recovery complete Oct 03 08:25:35 volumio kernel: EXT4-fs (sda1): mounted filesystem 857ff047-3c5c-489f-9ea7-ff87f0f2ca99 r/w with ordered data mode. Quota mode: none. Oct 03 08:25:35 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 03 08:25:35 volumio volumio[1617]: info: Loading plugin "volumio_command_line_client"... Oct 03 08:25:35 volumio volumio[1617]: info: Loading plugin "upnp"... Oct 03 08:25:35 volumio volumio[1617]: info: [1791008735553] Starting Upmpd Daemon Oct 03 08:25:35 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 03 08:25:35 volumio volumio[1617]: info: Loading plugin "my_music"... Oct 03 08:25:35 volumio volumio[1617]: info: Loading plugin "mpd"... Oct 03 08:25:36 volumio volumio[1617]: info: Loading plugin "upnp_browser"... Oct 03 08:25:36 volumio volumio[1617]: info: Starting UPNP Browser Oct 03 08:25:36 volumio volumio[1617]: info: Loading plugin "alarm-clock"... Oct 03 08:25:37 volumio volumio[1617]: info: Loading plugin "airplay_emulation"... Oct 03 08:25:37 volumio volumio[1617]: info: Starting Shairport Sync Oct 03 08:25:37 volumio volumio[1617]: info: Loading plugin "last_100"... Oct 03 08:25:37 volumio volumio[1617]: info: Loading plugin "webradio"... Oct 03 08:25:38 volumio sudo[1790]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:38 volumio volumio[1617]: info: Loading plugin "i2s_dacs"... Oct 03 08:25:38 volumio volumio[1617]: info: I2S DAC not set, start Auto-detection Oct 03 08:25:38 volumio volumio[1617]: info: Loading plugin "volumiodiscovery"... Oct 03 08:25:39 volumio volumio[1617]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 03 08:25:39 volumio volumio[1617]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 03 08:25:39 volumio volumio[1617]: *** WARNING *** For more information see Oct 03 08:25:39 volumio node[1617]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 03 08:25:39 volumio volumio[1617]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 03 08:25:39 volumio volumio[1617]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 03 08:25:39 volumio volumio[1617]: *** WARNING *** For more information see Oct 03 08:25:39 volumio node[1617]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 03 08:25:39 volumio node[1617]: *** WARNING *** For more information see Oct 03 08:25:39 volumio node[1617]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 03 08:25:39 volumio node[1617]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 03 08:25:39 volumio node[1617]: *** WARNING *** For more information see Oct 03 08:25:39 volumio volumio[1617]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 03 08:25:39 volumio volumio[1617]: info: Discovery: Started advertising with name: Volumio Oct 03 08:25:39 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 03 08:25:39 volumio volumio[1617]: info: Loading plugin "spop"... Oct 03 08:25:42 volumio volumio[1617]: info: Loading plugin "outputs"... Oct 03 08:25:42 volumio volumio[1617]: info: Loading plugin "albumart"... Oct 03 08:25:42 volumio volumio[1617]: info: Plugin example_plugin is not enabled Oct 03 08:25:42 volumio volumio[1617]: info: Loading plugin "inputs"... Oct 03 08:25:42 volumio volumio[1617]: info: Loading plugin "updater_comm"... Oct 03 08:25:42 volumio volumio[1617]: info: Plugin mpdemulation is not enabled Oct 03 08:25:42 volumio volumio[1617]: info: Loading plugin "rest_api"... Oct 03 08:25:42 volumio volumio[1617]: info: Loading plugin "websocket"... Oct 03 08:25:42 volumio volumio[1617]: info: Starting Socket.io Server version 2.3.0 Oct 03 08:25:42 volumio volumio[1617]: info: Loading i18n strings for locale en Oct 03 08:25:42 volumio volumio[1617]: Updating browse sources language Oct 03 08:25:42 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 03 08:25:42 volumio volumio[1617]: Forking 3 albumart workers Oct 03 08:25:42 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 03 08:25:42 volumio volumio[1617]: info: CoreCommandRouter::initPlayerControls Oct 03 08:25:42 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:42 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:42 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:42 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:42 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:42 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:42 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:42 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:42 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 03 08:25:42 volumio volumio[1617]: Express server listening on port 3000 Oct 03 08:25:42 volumio volumio[1617]: [Metrics] WebUI: 15s 14.45ms Oct 03 08:25:42 volumio volumio[1617]: info: CoreStateMachine::resetVolumioState Oct 03 08:25:42 volumio volumio[1617]: info: CoreStateMachine::getcurrentVolume Oct 03 08:25:42 volumio volumio[1617]: info: CoreCommandRouter::volumioRetrievevolume Oct 03 08:25:42 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 03 08:25:42 volumio volumio[1617]: info: Volumio Network Manager: Network status updated: 2 Oct 03 08:25:43 volumio volumio[1617]: info: CoreStateMachine::pushState Oct 03 08:25:43 volumio volumio[1617]: info: CorePlayQueue::getTrack 0 Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::volumioPushState Oct 03 08:25:43 volumio volumio[1617]: info: CoreStateMachine::updateTrackBlock Oct 03 08:25:43 volumio volumio[1617]: info: CorePlayQueue::getTrackBlock Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::volumioRetrievevolume Oct 03 08:25:43 volumio volumio[1617]: info: Reloading queue from file Oct 03 08:25:43 volumio volumio[1617]: info: CoreStateMachine::setRepeat null single undefined Oct 03 08:25:43 volumio volumio[1617]: info: CoreStateMachine::pushState Oct 03 08:25:43 volumio volumio[1617]: info: CorePlayQueue::getTrack 0 Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::volumioPushState Oct 03 08:25:43 volumio volumio[1617]: info: CoreStateMachine::setRandom null Oct 03 08:25:43 volumio volumio[1617]: info: CoreStateMachine::pushState Oct 03 08:25:43 volumio volumio[1617]: info: CorePlayQueue::getTrack 0 Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::volumioPushState Oct 03 08:25:43 volumio volumio[1617]: info: Setting Device type: Raspberry PI Oct 03 08:25:43 volumio volumio[1617]: info: CoreStateMachine::pushState Oct 03 08:25:43 volumio volumio[1617]: info: CorePlayQueue::getTrack 0 Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::volumioPushState Oct 03 08:25:43 volumio volumio[1617]: info: Completed loading Core Plugins Oct 03 08:25:43 volumio volumio[1617]: info: Preparing to generate the ALSA configuration file Oct 03 08:25:43 volumio volumio[1617]: info: Discovery: adding 385ddf86-4e32-45c5-93a3-933287034ba2 Oct 03 08:25:43 volumio volumio[1617]: info: Discovery: Found device Volumio Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::volumioGetState Oct 03 08:25:43 volumio volumio[1617]: info: CorePlayQueue::getTrack 0 Oct 03 08:25:43 volumio volumio[1617]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Oct 03 08:25:43 volumio volumio[1617]: info: Reading ALSA contributions from plugins. Oct 03 08:25:43 volumio volumio[1617]: info: Asound.conf file unchanged, so no further update is needed Oct 03 08:25:43 volumio volumio[1617]: info: Output device has changed, restarting MPD Oct 03 08:25:43 volumio volumio[1617]: info: Output device has changed, restarting Shairport Sync Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 03 08:25:43 volumio sudo[1874]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 03 08:25:43 volumio sudo[1872]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 03 08:25:43 volumio sudo[1872]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:43 volumio sudo[1874]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:43 volumio sudo[1872]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:43 volumio volumio[1617]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 03 08:25:43 volumio volumio[1617]: info: ___________ START PLUGINS ___________ Oct 03 08:25:43 volumio volumio[1617]: info: ControllerMpd::onStart: Initializing MPD Oct 03 08:25:43 volumio volumio[1617]: info: Creating MPD Configuration file Oct 03 08:25:43 volumio systemd[1]: Listening on mpd.socket. Oct 03 08:25:43 volumio systemd[1]: Starting Music Player Daemon... Oct 03 08:25:43 volumio sudo[1882]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Oct 03 08:25:43 volumio sudo[1882]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:43 volumio systemd[1]: Started Volumio5 Onboarding Server. Oct 03 08:25:43 volumio sudo[1882]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 03 08:25:43 volumio sudo[1886]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 03 08:25:43 volumio volumio[1617]: info: [1791008743562] CoreMusicLibrary::Adding element Media Servers Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 03 08:25:43 volumio sudo[1886]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:43 volumio sudo[1886]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:43 volumio volumio[1617]: info: UPNP Browser: Client initialized successfully Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 03 08:25:43 volumio volumio[1617]: Starting albumart workers Oct 03 08:25:43 volumio volumio[1617]: Starting albumart workers Oct 03 08:25:43 volumio sudo[1883]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 03 08:25:43 volumio sudo[1889]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 03 08:25:43 volumio sudo[1883]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:43 volumio sudo[1883]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Oct 03 08:25:43 volumio volumio[1617]: Starting albumart workers Oct 03 08:25:43 volumio sudo[1889]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:43 volumio sudo[1883]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:43 volumio volumio[1617]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 03 08:25:43 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Oct 03 08:25:43 volumio systemd[1]: mpd.service: Succeeded. Oct 03 08:25:43 volumio systemd[1]: Stopped Music Player Daemon. Oct 03 08:25:43 volumio systemd[1]: Starting Music Player Daemon... Oct 03 08:25:43 volumio volumio-remote-updater[594]: [2026-10-03 08:25:43] [connect] Successful connection Oct 03 08:25:43 volumio volumio[1617]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 03 08:25:43 volumio volumio[1617]: info: [1791008743833] CoreMusicLibrary::Adding element Last_100 Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 03 08:25:43 volumio volumio[1617]: info: [1791008743852] CoreMusicLibrary::Adding element Webradio Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 03 08:25:43 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 03 08:25:43 volumio volumio[1617]: info: Initializing BBC Radios Oct 03 08:25:43 volumio sudo[1897]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 03 08:25:43 volumio sudo[1897]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:43 volumio sudo[1897]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Oct 03 08:25:43 volumio sudo[1897]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:44 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 03 08:25:44 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 03 08:25:44 volumio volumio[1617]: info: Creating Spotify config file Oct 03 08:25:44 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:44 volumio volumio[1617]: info: Volumio Calling Home Oct 03 08:25:44 volumio volumio[1617]: info: MPD Permissions set Oct 03 08:25:44 volumio volumio[1617]: info: MPD Permissions set Oct 03 08:25:44 volumio volumio-remote-updater[594]: [2026-10-03 08:25:44] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1791008743 101 Oct 03 08:25:44 volumio volumio[1617]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 Oct 03 08:25:44 volumio volumio[1617]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Oct 03 08:25:44 volumio volumio[1617]: info: Spotify config file written Oct 03 08:25:44 volumio sudo[1945]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 03 08:25:44 volumio sudo[1945]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:44 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:44 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:44 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:44 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:44 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:44 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:44 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:44 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:44 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 03 08:25:44 volumio systemd[1]: Started go-librespot Daemon. Oct 03 08:25:44 volumio go-librespot[1951]: go-librespot daemon starting... Oct 03 08:25:44 volumio sudo[1945]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:45 volumio volumio[1617]: info: No need to fix Spotify hosts Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::volumioGetState Oct 03 08:25:45 volumio volumio[1617]: info: CorePlayQueue::getTrack 0 Oct 03 08:25:45 volumio apps.plugin[1344]: apps.plugin CGROUPS_LOOKUP request failed (error 6); cgroup enrichment will retry Oct 03 08:25:45 volumio volumio[1617]: info: Starting Shairport Sync Oct 03 08:25:45 volumio volumio[1617]: info: Starting Shairport Sync Oct 03 08:25:45 volumio volumio[1617]: info: Starting Shairport Sync Oct 03 08:25:45 volumio sudo[1984]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 03 08:25:45 volumio sudo[1984]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:45 volumio sudo[1982]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 03 08:25:45 volumio sudo[1982]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:45 volumio sudo[1980]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 03 08:25:45 volumio sudo[1980]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:45 volumio volumio[1617]: info: Volumio called home Oct 03 08:25:45 volumio volumio5-onboarding[1887]: time=2026-10-03T08:25:45.666+02:00 level=INFO msg="running volumio5-device-gateway" version=687ad144+CHANGES buildDate=2026-02-10T16:50:24Z Oct 03 08:25:45 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 03 08:25:45 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 03 08:25:45 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 03 08:25:45 volumio volumio[1617]: info: An error occurred while refreshing Spotify Token Error: Bad Request Oct 03 08:25:45 volumio sudo[1993]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 03 08:25:45 volumio sudo[1993]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:45 volumio sudo[1995]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 03 08:25:45 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 03 08:25:45 volumio sudo[1984]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:45 volumio sudo[1993]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:45 volumio sudo[1980]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:45 volumio sudo[1982]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:45 volumio sudo[1995]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:45 volumio sudo[1995]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:45 volumio volumio[1617]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 3 Oct 03 08:25:45 volumio volumio[1617]: info: Shairport-Sync Started Oct 03 08:25:45 volumio volumio[1617]: Error adding Membership: Error: addMembership EINVAL Oct 03 08:25:45 volumio volumio[1617]: info: Shairport-Sync Started Oct 03 08:25:45 volumio volumio[1617]: info: Shairport-Sync Started Oct 03 08:25:45 volumio volumio[1617]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 3 Oct 03 08:25:45 volumio volumio[1617]: info: Received Get System Info Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 03 08:25:45 volumio volumio[1617]: info: Discovery: Getting this device information Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::volumioGetState Oct 03 08:25:45 volumio volumio[1617]: info: CorePlayQueue::getTrack 0 Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 03 08:25:45 volumio volumio5-onboarding[1887]: time=2026-10-03T08:25:45.858+02:00 level=INFO msg="system info for 5ee3cb5032f6c054c0aae3863eecf687" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=3.912 Oct 03 08:25:45 volumio volumio[1617]: info: Received Get System Info Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 03 08:25:45 volumio volumio[1617]: info: Discovery: Getting this device information Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::volumioGetState Oct 03 08:25:45 volumio volumio[1617]: info: CorePlayQueue::getTrack 0 Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 03 08:25:45 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 03 08:25:45 volumio volumio5-onboarding[1887]: time=2026-10-03T08:25:45.900+02:00 level=INFO msg="enabling local network discovery" Oct 03 08:25:45 volumio sudo[2003]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 03 08:25:45 volumio sudo[2003]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:45 volumio volumio5-onboarding[1887]: time=2026-10-03T08:25:45.934+02:00 level=INFO msg="enabling BLE discovery" Oct 03 08:25:45 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Oct 03 08:25:45 volumio sudo[2003]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:46 volumio volumio[1617]: info: Upmpdcli Daemon Started Oct 03 08:25:46 volumio volumio5-onboarding[1887]: time=2026-10-03T08:25:46.125+02:00 level=INFO msg="bootstrapping state" hasInternet=true Oct 03 08:25:46 volumio volumio[1617]: info: Received Get System Info Oct 03 08:25:46 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 03 08:25:46 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 03 08:25:46 volumio volumio[1617]: info: Discovery: Getting this device information Oct 03 08:25:46 volumio volumio[1617]: info: CoreCommandRouter::volumioGetState Oct 03 08:25:46 volumio volumio[1617]: info: CorePlayQueue::getTrack 0 Oct 03 08:25:46 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 03 08:25:46 volumio volumio-remote-updater[594]: No test mode Oct 03 08:25:46 volumio volumio-remote-updater[594]: No alpha test mode Oct 03 08:25:46 volumio netdata[677]: NODES INFO: 0 nodes loading contexts, 0 receiving replication, 0 sending replication, 1 pending context post processing (host 'volumio') Oct 03 08:25:46 volumio volumio[1617]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 03 08:25:46 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 03 08:25:46 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 03 08:25:46 volumio volumio5-onboarding[1887]: time=2026-10-03T08:25:46.599+02:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=tidal error="could not open plugin config file for \"tidal\": open /data/configuration/music_service/tidal/config.json: no such file or directory" Oct 03 08:25:46 volumio volumio5-onboarding[1887]: time=2026-10-03T08:25:46.600+02:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=qobuz error="could not open plugin config file for \"qobuz\": open /data/configuration/music_service/qobuz/config.json: no such file or directory" Oct 03 08:25:46 volumio volumio5-onboarding[1887]: time=2026-10-03T08:25:46.600+02:00 level=WARN msg="could not read username/password data for music provider" component=volumio provider=hi_res_audio error="could not open plugin config file for \"hi_res_audio\": open /data/configuration/music_service/hi_res_audio/config.json: no such file or directory" Oct 03 08:25:46 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 03 08:25:46 volumio volumio[1617]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 03 08:25:46 volumio go-librespot[1951]: time="2026-10-03T08:25:46+02:00" level=info msg="running go-librespot 0.4.0" Oct 03 08:25:46 volumio go-librespot[1951]: time="2026-10-03T08:25:46+02:00" level=debug msg="app state loaded" Oct 03 08:25:46 volumio go-librespot[1951]: time="2026-10-03T08:25:46+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 03 08:25:47 volumio volumio5-onboarding[1887]: time=2026-10-03T08:25:47.606+02:00 level=INFO msg="service successfully established" component=discovery/localnet Oct 03 08:25:48 volumio systemd[1]: systemd-timedated.service: Succeeded. Oct 03 08:25:48 volumio go-librespot[1951]: time="2026-10-03T08:25:48+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 03 08:25:48 volumio go-librespot[1951]: time="2026-10-03T08:25:48+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 03 08:25:48 volumio go-librespot[1951]: time="2026-10-03T08:25:48+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 03 08:25:48 volumio go-librespot[1951]: time="2026-10-03T08:25:48+02:00" level=info msg="zeroconf server listening on port 43065" Oct 03 08:25:48 volumio volumio[1617]: info: go-librespot daemon successfully initialized Oct 03 08:25:50 volumio go-librespot[1951]: time="2026-10-03T08:25:50+02:00" level=debug msg="obtained new client token: AAF70mjus5IROFc83N1wjm0nPyWZuOM3GScBoqEGKO6buLlB5QCrAjAp4UvbxAUrdkq6cmtFbVl8ZdF0lIgllbBAr6qYiX8fmrhcr60dcmYruWTCYMqwwNcV+IgpolMJHPMIi/Gp8/qPnaVuGbCqiSiZ/AxKIFEceupHv9Pog74oA0LTVCBAVp7EYFrvIEKRbQ1oVOdHFB6I75Lu608iPpm0kLrgZHC+nimPPPypO+TVmyQ80IEr" Oct 03 08:25:50 volumio go-librespot[1951]: time="2026-10-03T08:25:50+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="completed keyexchange" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="completed challenge" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=info msg="authenticated AP" username="31************************d4" Oct 03 08:25:51 volumio mpd[1908]: Oct 03 08:25 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=info msg="authenticated Login5" username="31************************d4" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=info msg="accepted zeroconf from moto g86 power 5G" username="31************************d4" Oct 03 08:25:51 volumio systemd[1]: Started Music Player Daemon. Oct 03 08:25:51 volumio volumio[1617]: Upnp client error: Error: This socket has been ended by the other party Oct 03 08:25:51 volumio sudo[1874]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:51 volumio sudo[1889]: pam_unix(sudo:session): session closed for user root Oct 03 08:25:51 volumio volumio[1617]: info: Initializing connection to go-librespot Websocket Oct 03 08:25:51 volumio volumio[1617]: info: Completed starting Core Plugins Oct 03 08:25:51 volumio volumio[1617]: info: ------------------------------------------- Oct 03 08:25:51 volumio volumio[1617]: info: ----- MyVolumio plugins startup ---- Oct 03 08:25:51 volumio volumio[1617]: info: ------------------------------------------- Oct 03 08:25:51 volumio volumio[1617]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 03 08:25:51 volumio volumio[1617]: error: MPD error: The expression evaluated to a falsy value: Oct 03 08:25:51 volumio volumio[1617]: assert.ok(self.idling) Oct 03 08:25:51 volumio volumio[1617]: error: The expression evaluated to a falsy value: Oct 03 08:25:51 volumio volumio[1617]: assert.ok(self.idling) Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="new websocket client" Oct 03 08:25:51 volumio volumio[1617]: info: MPD running with PID1908 Oct 03 08:25:51 volumio volumio[1617]: ,establishing connection Oct 03 08:25:51 volumio volumio[1617]: info: Connection to go-librespot Websocket established Oct 03 08:25:51 volumio volumio[1617]: error: MPD error: The expression evaluated to a falsy value: Oct 03 08:25:51 volumio volumio[1617]: assert.ok(self.idling) Oct 03 08:25:51 volumio volumio[1617]: error: The expression evaluated to a falsy value: Oct 03 08:25:51 volumio volumio[1617]: assert.ok(self.idling) Oct 03 08:25:51 volumio volumio[1617]: error: updateQueue error: null Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="dealer connection opened" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=trace msg="starting accesspoint recv loop" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=trace msg="starting dealer recv loop" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=trace msg="received accesspoint ping" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="received connection id: ZDVhYWViMjEtOWYw...OUY4N0JCQTkyMA==" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=trace msg="received accesspoint pong ack" Oct 03 08:25:51 volumio volumio[2007]: Generating RSA private key, 4096 bit long modulus (2 primes) Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="handling transfer player command from 8f8175a6bead76f4c3699dd4846d69adefca0041" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="resolved context of track" uri="spotify:album:0SI87BtvTbGXl6OqYzB9hg" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:album:0SI87BtvTbGXl6OqYzB9hg" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="loading track (paused: true, position: 73136ms)" uri="spotify:track:5cEzN1mB6kBm7dMTpOdrMk" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=trace msg="emitting websocket event: will_play" Oct 03 08:25:51 volumio volumio[1617]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:0SI87BtvTbGXl6OqYzB9hg","uri":"spotify:track:5cEzN1mB6kBm7dMTpOdrMk","play_origin":"voice-assistant-google"}} Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 435" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="selected format OGG_VORBIS_320 (5d17a62608d66522a1b2eddfe467416d53b7a4f9)" uri="spotify:track:5cEzN1mB6kBm7dMTpOdrMk" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=debug msg="requested aes key for file 5d17a62608d66522a1b2eddfe467416d53b7a4f9, gid: 5cEzN1mB6kBm7dMTpOdrMk" Oct 03 08:25:51 volumio go-librespot[1951]: time="2026-10-03T08:25:51+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5cEzN1mB6kBm7dMTpOdrMk" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 159" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1572" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 435" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1299" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="fetched first chunk of 15, total size is 7552712 bytes" uri="spotify:track:5cEzN1mB6kBm7dMTpOdrMk" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:5cEzN1mB6kBm7dMTpOdrMk" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="fetched chunk 7/14, size: 524288" uri="spotify:track:5cEzN1mB6kBm7dMTpOdrMk" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="fetched chunk 6/14, size: 524288" uri="spotify:track:5cEzN1mB6kBm7dMTpOdrMk" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=trace msg="seek to 73136ms (diff: 91ms, samples: 3225297, bytes: 3378724)" uri="spotify:track:5cEzN1mB6kBm7dMTpOdrMk" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="created new output device" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=info msg="loaded track \"Ankakh Hayastan\" (paused: true, position: 73136ms, duration: 165506ms, prefetched: false)" uri="spotify:track:5cEzN1mB6kBm7dMTpOdrMk" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:5cEzN1mB6kBm7dMTpOdrMk" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=trace msg="emitting websocket event: metadata" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=trace msg="emitting websocket event: active" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="sending successful reply for dealer request" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 03 08:25:52 volumio volumio[1617]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5cEzN1mB6kBm7dMTpOdrMk","name":"Ankakh Hayastan","artist_names":["Armine Simonyan"],"album_name":"Hot Hot Armenian Dance","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0237e49ce4c44b37acffb19d83","position":73136,"duration":165506,"release_date":"year:2023 month:4 day:13","track_number":1,"disc_number":1}} Oct 03 08:25:52 volumio volumio[1617]: SPOTIFY: received: {"type":"active","data":null} Oct 03 08:25:52 volumio volumio[1617]: info: Aligning Spotify Volume to Volumio Volume Oct 03 08:25:52 volumio volumio[1617]: info: CoreCommandRouter::volumioGetState Oct 03 08:25:52 volumio volumio[1617]: info: CorePlayQueue::getTrack 0 Oct 03 08:25:52 volumio volumio[1617]: info: Setting Spotify Volume from Volumio: 51 Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:5cEzN1mB6kBm7dMTpOdrMk" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="fetched chunk 8/14, size: 524288" uri="spotify:track:5cEzN1mB6kBm7dMTpOdrMk" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="fetched chunk 9/14, size: 524288" uri="spotify:track:5cEzN1mB6kBm7dMTpOdrMk" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=trace msg="emitting websocket event: paused" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="handling play player command from 8f8175a6bead76f4c3699dd4846d69adefca0041" Oct 03 08:25:52 volumio volumio[1617]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:album:0SI87BtvTbGXl6OqYzB9hg","uri":"spotify:track:5cEzN1mB6kBm7dMTpOdrMk","play_origin":"voice-assistant-google"}} Oct 03 08:25:52 volumio volumio[1617]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 03 08:25:52 volumio volumio[1617]: TypeError: Cannot read property 'service' of undefined Oct 03 08:25:52 volumio volumio[1617]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Oct 03 08:25:52 volumio volumio[1617]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:280:18) Oct 03 08:25:52 volumio volumio[1617]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Oct 03 08:25:52 volumio volumio[1617]: at WebSocket.emit (events.js:315:20) Oct 03 08:25:52 volumio volumio[1617]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Oct 03 08:25:52 volumio volumio[1617]: at Receiver.emit (events.js:315:20) Oct 03 08:25:52 volumio volumio[1617]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Oct 03 08:25:52 volumio volumio[1617]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Oct 03 08:25:52 volumio volumio[1617]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Oct 03 08:25:52 volumio volumio[1617]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Oct 03 08:25:52 volumio volumio[1617]: at writeOrBuffer (internal/streams/writable.js:358:12) Oct 03 08:25:52 volumio volumio[1617]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Oct 03 08:25:52 volumio volumio[1617]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Oct 03 08:25:52 volumio volumio[1617]: at Socket.emit (events.js:315:20) Oct 03 08:25:52 volumio volumio[1617]: at addChunk (internal/streams/readable.js:309:12) Oct 03 08:25:52 volumio volumio[1617]: at readableAddChunk (internal/streams/readable.js:284:9) Oct 03 08:25:52 volumio volumio[1617]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EVHGWrwldPRtj" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EVHGWrwldPRtj" Oct 03 08:25:52 volumio go-librespot[1951]: time="2026-10-03T08:25:52+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5GGTgkmfEzkhAfmG0hxXk9" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=trace msg="emitting websocket event: will_play" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=warning msg="original track has no formats, alternatives have a total of 4" uri="spotify:track:5GGTgkmfEzkhAfmG0hxXk9" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="selected format OGG_VORBIS_320 (2252a0665a9d42685202bfb2a40c3f34919d879c)" uri="spotify:track:5GGTgkmfEzkhAfmG0hxXk9" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="requested aes key for file 2252a0665a9d42685202bfb2a40c3f34919d879c, gid: 5GGTgkmfEzkhAfmG0hxXk9" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5GGTgkmfEzkhAfmG0hxXk9" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="fetched first chunk of 37, total size is 19070048 bytes" uri="spotify:track:5GGTgkmfEzkhAfmG0hxXk9" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=info msg="loaded track \"Champagne Supernova\" (paused: false, position: 0ms, duration: 449506ms, prefetched: false)" uri="spotify:track:5GGTgkmfEzkhAfmG0hxXk9" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="fetched chunk 1/36, size: 524288" uri="spotify:track:5GGTgkmfEzkhAfmG0hxXk9" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="fetched chunk 3/36, size: 524288" uri="spotify:track:5GGTgkmfEzkhAfmG0hxXk9" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=trace msg="scheduling prefetch in 420s" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=trace msg="emitting websocket event: metadata" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="sending successful reply for dealer request" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=trace msg="emitting websocket event: playing" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="fetched chunk 2/36, size: 524288" uri="spotify:track:5GGTgkmfEzkhAfmG0hxXk9" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="handling play player command from 8f8175a6bead76f4c3699dd4846d69adefca0041" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EVHGWrwldPRtj" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EVHGWrwldPRtj" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5GGTgkmfEzkhAfmG0hxXk9" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=trace msg="emitting websocket event: will_play" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=warning msg="original track has no formats, alternatives have a total of 4" uri="spotify:track:5GGTgkmfEzkhAfmG0hxXk9" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="selected format OGG_VORBIS_320 (2252a0665a9d42685202bfb2a40c3f34919d879c)" uri="spotify:track:5GGTgkmfEzkhAfmG0hxXk9" Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=debug msg="requested aes key for file 2252a0665a9d42685202bfb2a40c3f34919d879c, gid: 5GGTgkmfEzkhAfmG0hxXk9" Oct 03 08:25:53 volumio sudo[2047]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-10-03 08:24 Oct 03 08:25:53 volumio sudo[2047]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 03 08:25:53 volumio go-librespot[1951]: time="2026-10-03T08:25:53+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5GGTgkmfEzkhAfmG0hxXk9" 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="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="464fc672d77d3df6ee72b331d36cdf1fa936e1ec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 27 Feb 2026 10:59:40 AM CET" VOLUMIO_VERSION="3.912" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="37c6ab864cb114e1344d540995c69f86"