Wed Jun 23 12:33:08 UTC 2021 Description="'I wanted to start a spotify connect session to the volumio device from my desktop, the volumio device doesnt even start playing the spotify song and the desktop app of spotify falls back to local playback'" # cat /proc/version --------------- Linux version 4.19.118-v7+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1311 SMP Mon Apr 27 14:21:24 BST 2020 # cat /etc/os-release --------------- PRETTY_NAME="Raspbian GNU/Linux 8 (jessie)" NAME="Raspbian GNU/Linux" VERSION_ID="8" VERSION="8 (jessie)" 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="14acf028cf46278bd3fd3dd02523424a9bc825bf" VOLUMIO_FE_VERSION="74f64fbba9dc8053dc27ed7125863d6ad6533965" VOLUMIO_BE_VERSION="0a6008ded215bf284d5d4cd9c4df3333cb320899" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Apr 24 17:39:58 CEST 2021" VOLUMIO_VERSION="2.882" VOLUMIO_HARDWARE="pi" VOLUMIO_HASH="1a98a01eef5aa5927a5874c2d3c1b0dc" # ifconfig --------------- eth0 Link encap:Ethernet HWaddr b8:27:eb:e8:3c:05 inet addr:10.0.0.144 Bcast:10.0.0.255 Mask:255.255.255.0 UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1 RX packets:33071 errors:0 dropped:3074 overruns:0 frame:0 TX packets:21125 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:22640576 (21.5 MiB) TX bytes:4770631 (4.5 MiB) lo Link encap:Local Loopback inet addr:127.0.0.1 Mask:255.0.0.0 UP LOOPBACK RUNNING MTU:65536 Metric:1 RX packets:28140 errors:0 dropped:0 overruns:0 frame:0 TX packets:28140 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:2794108 (2.6 MiB) TX bytes:2794108 (2.6 MiB) # sudo iwconfig --------------- eth0 no wireless extensions. lo no wireless extensions. # aplay -l --------------- **** List of PLAYBACK Hardware Devices **** card 0: ALSA [bcm2835 ALSA], device 0: bcm2835 ALSA [bcm2835 ALSA] Subdevices: 4/4 Subdevice #0: subdevice #0 Subdevice #1: subdevice #1 Subdevice #2: subdevice #2 Subdevice #3: subdevice #3 card 0: ALSA [bcm2835 ALSA], device 1: bcm2835 IEC958/HDMI [bcm2835 IEC958/HDMI] Subdevices: 1/1 Subdevice #0: subdevice #0 card 0: ALSA [bcm2835 ALSA], device 2: bcm2835 IEC958/HDMI1 [bcm2835 IEC958/HDMI1] Subdevices: 1/1 Subdevice #0: subdevice #0 card 1: Headphones [bcm2835 Headphones], device 0: bcm2835 Headphones [bcm2835 Headphones] Subdevices: 3/3 Subdevice #0: subdevice #0 Subdevice #1: subdevice #1 Subdevice #2: subdevice #2 card 5: USB [AudioBox USB], device 0: USB Audio [USB Audio] Subdevices: 1/1 Subdevice #0: subdevice #0 # ps -ef --------------- UID PID PPID C STIME TTY TIME CMD root 1 0 0 11:42 ? 00:00:08 /sbin/init root 2 0 0 11:42 ? 00:00:00 [kthreadd] root 3 2 0 11:42 ? 00:00:00 [rcu_gp] root 4 2 0 11:42 ? 00:00:00 [rcu_par_gp] root 8 2 0 11:42 ? 00:00:00 [mm_percpu_wq] root 9 2 0 11:42 ? 00:00:00 [ksoftirqd/0] root 10 2 0 11:42 ? 00:00:01 [rcu_sched] root 11 2 0 11:42 ? 00:00:00 [rcu_bh] root 12 2 0 11:42 ? 00:00:00 [migration/0] root 13 2 0 11:42 ? 00:00:00 [cpuhp/0] root 14 2 0 11:42 ? 00:00:00 [cpuhp/1] root 15 2 0 11:42 ? 00:00:00 [migration/1] root 16 2 0 11:42 ? 00:00:00 [ksoftirqd/1] root 19 2 0 11:42 ? 00:00:00 [cpuhp/2] root 20 2 0 11:42 ? 00:00:00 [migration/2] root 21 2 0 11:42 ? 00:00:00 [ksoftirqd/2] root 24 2 0 11:42 ? 00:00:00 [cpuhp/3] root 25 2 0 11:42 ? 00:00:00 [migration/3] root 26 2 0 11:42 ? 00:00:00 [ksoftirqd/3] root 29 2 0 11:42 ? 00:00:00 [kdevtmpfs] root 30 2 0 11:42 ? 00:00:00 [netns] root 31 2 0 11:42 ? 00:00:00 [kworker/1:1-mm_] root 34 2 0 11:42 ? 00:00:00 [kworker/3:1-cgr] root 35 2 0 11:42 ? 00:00:00 [khungtaskd] root 36 2 0 11:42 ? 00:00:00 [oom_reaper] root 37 2 0 11:42 ? 00:00:00 [writeback] root 38 2 0 11:42 ? 00:00:00 [kcompactd0] root 39 2 0 11:42 ? 00:00:00 [crypto] root 40 2 0 11:42 ? 00:00:00 [kblockd] root 41 2 0 11:42 ? 00:00:00 [watchdogd] root 42 2 0 11:42 ? 00:00:00 [rpciod] root 43 2 0 11:42 ? 00:00:00 [kworker/u9:0] root 44 2 0 11:42 ? 00:00:00 [xprtiod] root 45 2 0 11:42 ? 00:00:00 [kworker/u8:1-ev] root 47 2 0 11:42 ? 00:00:00 [kswapd0] root 48 2 0 11:42 ? 00:00:00 [nfsiod] root 70 2 0 11:42 ? 00:00:00 [kthrotld] root 71 2 0 11:42 ? 00:00:00 [iscsi_eh] root 72 2 0 11:42 ? 00:00:00 [dwc_otg] root 73 2 0 11:42 ? 00:00:00 [DWC Notificatio] root 74 2 0 11:42 ? 00:00:01 [vchiq-slot/0] root 75 2 0 11:42 ? 00:00:00 [vchiq-recy/0] root 76 2 0 11:42 ? 00:00:00 [vchiq-sync/0] root 77 2 0 11:42 ? 00:00:00 [vchiq-keep/0] root 78 2 0 11:42 ? 00:00:00 [SMIO] root 87 2 0 11:42 ? 00:00:00 [mmc_complete] root 88 2 0 11:42 ? 00:00:00 [kworker/2:1H-kb] root 89 2 0 11:42 ? 00:00:00 [kworker/0:1H-kb] root 110 2 0 11:42 ? 00:00:00 [kworker/1:1H-kb] root 111 2 0 11:42 ? 00:00:00 [kworker/1:2H-kb] root 115 2 0 11:42 ? 00:00:00 [kworker/3:1H-kb] root 116 2 0 11:42 ? 00:00:00 [jbd2/mmcblk0p2-] root 117 2 0 11:42 ? 00:00:00 [ext4-rsv-conver] root 124 2 0 11:42 ? 00:00:01 [loop0] root 143 2 0 11:42 ? 00:00:00 [kworker/3:2H-kb] root 144 2 0 11:42 ? 00:00:00 [jbd2/mmcblk0p3-] root 145 2 0 11:42 ? 00:00:00 [ext4-rsv-conver] root 152 2 0 11:42 ? 00:00:00 [kworker/0:2H-kb] root 153 2 0 11:42 ? 00:00:00 [ipv6_addrconf] root 180 1 0 11:42 ? 00:00:04 /lib/systemd/systemd-journald root 192 2 0 11:42 ? 00:00:00 [kworker/1:3-cgr] root 195 2 0 11:42 ? 00:00:00 [kworker/3:2-mm_] root 204 1 0 11:42 ? 00:00:00 /lib/systemd/systemd-udevd root 248 2 0 11:42 ? 00:00:00 [SMIO] root 282 2 0 11:42 ? 00:00:00 [mmal-vchiq] root 284 2 0 11:42 ? 00:00:00 [mmal-vchiq] root 286 2 0 11:42 ? 00:00:00 [mmal-vchiq] root 311 2 0 11:42 ? 00:00:00 [kworker/2:2H-kb] root 348 2 0 11:42 ? 00:00:00 [kworker/u8:3-ev] root 361 2 0 11:42 ? 00:00:00 [cfg80211] root 503 1 0 11:42 ? 00:00:00 dhcpcd eth0 root 563 1 0 11:42 ? 00:00:00 /sbin/rpcbind -w statd 573 1 0 11:42 ? 00:00:00 /sbin/rpc.statd root 590 1 0 11:42 ? 00:00:00 /usr/sbin/rpc.idmapd root 592 1 0 11:42 ? 00:00:02 /usr/sbin/haveged --Foreground --verbose=1 --write=1024 volumio 594 1 0 11:42 ? 00:00:00 /usr/bin/udisks-glue --foreground volumio 596 1 0 11:42 ? 00:00:00 /usr/local/bin/volumio-remote-updater root 597 1 0 11:42 ? 00:00:00 /bin/bash /bin/volumiologrotate root 603 1 0 11:42 ? 00:00:00 /lib/systemd/systemd-logind avahi 636 1 0 11:42 ? 00:00:01 avahi-daemon: running [schuur.local] message+ 651 1 0 11:42 ? 00:00:00 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation nobody 675 1 0 11:42 ? 00:00:00 /usr/sbin/thd --daemon --triggers /etc/triggerhappy/triggers.d/ --socket /var/run/thd.socket --pidfile /var/run/thd.pid --user nobody /dev/input/event* root 698 1 0 11:42 ? 00:00:01 /usr/sbin/ifplugd -i eth0 -q -f -u0 -d10 -w -I avahi 711 636 0 11:42 ? 00:00:00 avahi-daemon: chroot helper ntp 736 1 0 11:42 ? 00:00:00 /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 100:104 root 740 1 0 11:42 ? 00:00:00 /usr/lib/udisks/udisks-daemon --no-debug root 759 740 0 11:42 ? 00:00:00 udisks-daemon: not polling any devices root 761 1 0 11:42 tty1 00:00:00 /sbin/agetty --noclear tty1 linux root 762 1 0 11:42 ? 00:00:00 /sbin/agetty --keep-baud 115200 38400 9600 ttyAMA0 vt102 root 764 1 0 11:42 ? 00:00:00 /usr/lib/policykit-1/polkitd --no-debug volumio 786 1 2 11:43 ? 00:01:07 /usr/local/bin/node /volumio/index.js root 813 1 0 11:43 ? 00:00:00 /usr/sbin/nmbd -D root 814 813 0 11:43 ? 00:00:00 /usr/sbin/nmbd -D root 815 1 0 11:43 ? 00:00:00 /usr/sbin/winbindd root 823 815 0 11:43 ? 00:00:00 /usr/sbin/winbindd root 828 1 0 11:43 ? 00:00:00 /usr/sbin/smbd -D root 834 815 0 11:43 ? 00:00:00 /usr/sbin/winbindd root 835 815 0 11:43 ? 00:00:00 /usr/sbin/winbindd root 836 828 0 11:43 ? 00:00:00 /usr/sbin/smbd -D volumio 880 786 0 11:43 ? 00:00:00 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart volumio 886 880 0 11:43 ? 00:00:04 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart volumio 887 880 0 11:43 ? 00:00:03 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart volumio 892 880 0 11:43 ? 00:00:03 /bin/node /volumio/app/plugins/miscellanea/albumart/serverStartup.js 3001 /data/albumart volumio 1003 1 0 11:43 ? 00:00:11 /usr/bin/upmpdcli -c /tmp/upmpdcli.conf shairpo+ 1018 1 0 11:43 ? 00:00:16 /usr/local/bin/shairport-sync --configfile=/tmp/shairport-sync.conf volumio 1042 1 0 11:43 ? 00:00:00 /bin/streaming-daemon volumio 1387 786 0 11:45 ? 00:00:00 /bin/journalctl --output cat -f mpd 2192 1 1 11:49 ? 00:00:29 /usr/bin/mpd --no-daemon root 5820 2 0 12:15 ? 00:00:00 [kworker/2:2-mm_] root 6479 2 0 12:20 ? 00:00:00 [kworker/0:0-cgr] root 6559 2 0 12:20 ? 00:00:00 [kworker/2:0-mm_] root 7303 2 0 12:26 ? 00:00:00 [kworker/2:1-eve] root 7525 2 0 12:27 ? 00:00:00 [kworker/0:1-cgr] root 7900 2 0 12:30 ? 00:00:00 [kworker/2:3-mm_] root 8236 2 0 12:32 ? 00:00:00 [kworker/0:2-eve] volumio 8241 1 0 12:32 ? 00:00:00 /bin/bash /data/plugins/music_service/volspotconnect2/startconnect.sh volumio 8242 8241 1 12:32 ? 00:00:00 ./vollibrespot -c volspotify.toml root 8263 597 0 12:33 ? 00:00:00 sleep 60 volumio 8276 786 1 12:33 ? 00:00:00 /bin/sh -c /usr/local/bin/node /volumio/logsubmit.js 'I wanted to start a spotify connect session to the volumio device from my desktop, the volumio device doesnt even start playing the spotify song and the desktop app of spotify falls back to local playback' volumio 8277 8276 63 12:33 ? 00:00:00 /usr/local/bin/node /volumio/logsubmit.js I wanted to start a spotify connect session to the volumio device from my desktop, the volumio device doesnt even start playing the spotify song and the desktop app of spotify falls back to local playback volumio 8304 8277 0 12:33 ? 00:00:00 /bin/sh -c ps -ef >>/tmp/logondemand 2>&1 volumio 8305 8304 0 12:33 ? 00:00:00 ps -ef # df -h --------------- Filesystem Size Used Avail Use% Mounted on /dev/mmcblk0p2 2.2G 826M 1.3G 40% /imgpart /dev/loop0 355M 355M 0 100% /static overlay 27G 31M 26G 1% / devtmpfs 471M 0 471M 0% /dev tmpfs 485M 0 485M 0% /dev/shm tmpfs 485M 4.7M 481M 1% /run tmpfs 5.0M 4.0K 5.0M 1% /run/lock tmpfs 485M 0 485M 0% /sys/fs/cgroup tmpfs 485M 48K 485M 1% /tmp tmpfs 485M 0 485M 0% /var/spool/cups tmpfs 20M 16K 20M 1% /var/log tmpfs 485M 0 485M 0% /var/spool/cups/tmp /dev/mmcblk0p1 61M 57M 3.4M 95% /boot # mount --------------- /dev/mmcblk0p2 on /imgpart type ext4 (rw,relatime,stripe=1024) /dev/loop0 on /static type squashfs (ro,relatime) overlay on / type overlay (rw,relatime,lowerdir=/mnt/static,upperdir=/mnt/ext/dyn,workdir=/mnt/ext/work) sysfs on /sys type sysfs (rw,nosuid,nodev,noexec,relatime) proc on /proc type proc (rw,relatime) devtmpfs on /dev type devtmpfs (rw,nosuid,size=482104k,nr_inodes=120526,mode=755) tmpfs on /dev/shm type tmpfs (rw,nosuid,nodev,noexec) devpts on /dev/pts type devpts (rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000) tmpfs on /run type tmpfs (rw,nosuid,nodev,mode=755) tmpfs on /run/lock type tmpfs (rw,nosuid,nodev,noexec,relatime,size=5120k) tmpfs on /sys/fs/cgroup type tmpfs (ro,nosuid,nodev,noexec,mode=755) cgroup on /sys/fs/cgroup/systemd type cgroup (rw,nosuid,nodev,noexec,relatime,xattr,release_agent=/lib/systemd/systemd-cgroups-agent,name=systemd) cgroup on /sys/fs/cgroup/cpuset type cgroup (rw,nosuid,nodev,noexec,relatime,cpuset) cgroup on /sys/fs/cgroup/cpu,cpuacct type cgroup (rw,nosuid,nodev,noexec,relatime,cpu,cpuacct) cgroup on /sys/fs/cgroup/blkio type cgroup (rw,nosuid,nodev,noexec,relatime,blkio) cgroup on /sys/fs/cgroup/memory type cgroup (rw,nosuid,nodev,noexec,relatime,memory) cgroup on /sys/fs/cgroup/devices type cgroup (rw,nosuid,nodev,noexec,relatime,devices) cgroup on /sys/fs/cgroup/freezer type cgroup (rw,nosuid,nodev,noexec,relatime,freezer) cgroup on /sys/fs/cgroup/net_cls type cgroup (rw,nosuid,nodev,noexec,relatime,net_cls) cgroup on /sys/fs/cgroup/pids type cgroup (rw,nosuid,nodev,noexec,relatime,pids) systemd-1 on /proc/sys/fs/binfmt_misc type autofs (rw,relatime,fd=22,pgrp=1,timeout=300,minproto=5,maxproto=5,direct) debugfs on /sys/kernel/debug type debugfs (rw,relatime) mqueue on /dev/mqueue type mqueue (rw,relatime) tmpfs on /tmp type tmpfs (rw,noatime,mode=755) tmpfs on /var/spool/cups type tmpfs (rw,noatime,mode=755) tmpfs on /var/log type tmpfs (rw,nodev,relatime,size=20480k,mode=777,uid=1000,gid=4) fusectl on /sys/fs/fuse/connections type fusectl (rw,relatime) tmpfs on /var/spool/cups/tmp type tmpfs (rw,noatime,mode=755) configfs on /sys/kernel/config type configfs (rw,relatime) /dev/mmcblk0p1 on /boot type vfat (rw,nosuid,nodev,noexec,relatime,fmask=0111,dmask=0000,allow_utime=0022,codepage=437,iocharset=ascii,shortname=mixed,utf8,errors=remount-ro) rpc_pipefs on /run/rpc_pipefs type rpc_pipefs (rw,relatime) # netstat -natp --------------- (Not all processes could be identified, non-owned process info will not be shown, you would have to be root to see it all.) Active Internet connections (servers and established) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 0.0.0.0:39579 0.0.0.0:* LISTEN 8242/vollibrespot tcp 0 0 0.0.0.0:445 0.0.0.0:* LISTEN - tcp 0 0 10.0.0.144:49152 0.0.0.0:* LISTEN 1003/upmpdcli tcp 0 0 0.0.0.0:42439 0.0.0.0:* LISTEN - tcp 0 0 0.0.0.0:5000 0.0.0.0:* LISTEN - tcp 0 0 0.0.0.0:139 0.0.0.0:* LISTEN - tcp 0 0 0.0.0.0:111 0.0.0.0:* LISTEN - tcp 0 0 127.0.0.1:34962 127.0.0.1:3000 ESTABLISHED 786/node tcp 0 0 127.0.0.1:34976 127.0.0.1:3000 ESTABLISHED 596/volumio-remote- tcp 0 0 127.0.0.1:38126 127.0.0.1:6600 ESTABLISHED 786/node tcp 0 0 127.0.0.1:35596 127.0.0.1:6599 ESTABLISHED 1003/upmpdcli tcp 0 0 127.0.0.1:34950 127.0.0.1:3000 ESTABLISHED 786/node tcp 0 0 10.0.0.144:54262 5.39.56.60:80 TIME_WAIT - tcp 0 0 10.0.0.144:56682 34.98.74.57:80 TIME_WAIT - tcp6 0 0 :::3000 :::* LISTEN 786/node tcp6 0 0 :::3001 :::* LISTEN 880/node tcp6 0 0 :::3005 :::* LISTEN 786/node tcp6 0 0 :::445 :::* LISTEN - tcp6 0 0 :::49152 :::* LISTEN 1003/upmpdcli tcp6 0 0 :::7777 :::* LISTEN 1042/streaming-daem tcp6 0 0 :::6599 :::* LISTEN 786/node tcp6 0 0 :::5000 :::* LISTEN - tcp6 0 0 :::6600 :::* LISTEN - tcp6 0 0 :::52041 :::* LISTEN - tcp6 0 0 :::139 :::* LISTEN - tcp6 0 0 :::111 :::* LISTEN - tcp6 0 0 10.0.0.144:3000 10.0.0.235:51199 FIN_WAIT2 - tcp6 0 0 10.0.0.144:3000 10.0.0.235:55912 FIN_WAIT2 - tcp6 0 0 127.0.0.1:3000 127.0.0.1:34962 ESTABLISHED 786/node tcp6 0 0 127.0.0.1:6599 127.0.0.1:35596 ESTABLISHED 786/node tcp6 0 0 10.0.0.144:3000 10.0.0.235:50109 ESTABLISHED 786/node tcp6 0 0 10.0.0.144:3000 10.0.0.235:62303 FIN_WAIT2 - tcp6 0 0 127.0.0.1:3000 127.0.0.1:34950 ESTABLISHED 786/node tcp6 0 0 127.0.0.1:6600 127.0.0.1:38126 ESTABLISHED - tcp6 0 0 127.0.0.1:3000 127.0.0.1:34976 ESTABLISHED 786/node # cat /var/log/mpd.log --------------- Jun 23 11:42 : zeroconf: No global port, disabling zeroconf Jun 23 11:43 : client: [0] opened from local Jun 23 11:43 : exception: No such directory Jun 23 11:43 : client: [1] opened from 127.0.0.1:37832 Jun 23 11:48 : exception: No such playlist Jun 23 11:49 : player: played "http://stream.radionl.fm/radionl" Jun 23 11:49 : zeroconf: No global port, disabling zeroconf Jun 23 11:49 : client: [0] opened from local Jun 23 11:49 : client: [1] opened from 127.0.0.1:38126 Jun 23 12:22 : exception: No such playlist Jun 23 12:32 : player: played "http://stream.radionl.fm/radionl" # cat /data/configuration/plugins.json --------------- { "music_service": { "airplay_emulation": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "inputs": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "mpd": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "webradio": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "example_plugin": { "enabled": { "type": "boolean", "value": false }, "status": { "type": "string", "value": "STOPPED" } }, "last_100": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "upnp_browser": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "streaming_services": { "status": { "type": "string", "value": "STARTED" } }, "volspotconnect2": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } } }, "audio_interface": { "outputs": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "upnp": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "alsa_controller": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } } }, "miscellanea": { "alarm-clock": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "albumart": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "appearance": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "wizard": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "my_music": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } } }, "user_interface": { "websocket": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "mpdemulation": { "enabled": { "type": "boolean", "value": false }, "status": { "type": "string", "value": "STARTED" } }, "rest_api": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } } }, "system_controller": { "updater_comm": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "network": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "networkfs": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "services": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "system": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "i2s_dacs": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "volumiodiscovery": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "volumio_command_line_client": { "enabled": { "type": "boolean", "value": true }, "status": { "type": "string", "value": "STARTED" } }, "my_volumio": { "status": { "type": "string", "value": "STARTED" } } } } # cat /etc/mpd.conf --------------- # Volumio MPD Configuration File # Files and directories ####################################################### music_directory "/var/lib/mpd/music" playlist_directory "/var/lib/mpd/playlists" db_file "/var/lib/mpd/tag_cache" log_file "/var/log/mpd.log" #pid_file "/var/run/mpd/pid" #state_file "/var/lib/mpd/state" #sticker_file "/var/lib/mpd/sticker.sql" ############################################################################### # General music daemon options ################################################ user "mpd" group "audio" bind_to_address "any" #port "6600" #log_level "default" gapless_mp3_playback "no" #save_absolute_paths_in_playlists "no" #metadata_to_use "artist,album,title,track,name,genre,date,composer,performer,disc" auto_update "yes" #auto_update_depth "3" ############################################################################### # Symbolic link behavior ###################################################### follow_outside_symlinks "yes" follow_inside_symlinks "yes" ############################################################################### # Input ####################################################################### # input { plugin "curl" # proxy "proxy.isp.com:8080" # proxy_user "user" # proxy_password "password" } ############################################################################### # Decoder ################################################################ ############################################################################### # Audio Output ################################################################ resampler { plugin "soxr" quality "high" threads "1" } audio_output { type "alsa" name "alsa" device "hw:1,0" dop "no" } audio_output { type "fifo" enabled "no" name "multiroom" path "/tmp/snapfifo" format "44100:16:2" } #replaygain "album" #replaygain_preamp "0" volume_normalization "no" ############################################################################### # MPD Internal Buffering ###################################################### audio_buffer_size "12288" buffer_before_play "10%" ############################################################################### # Resource Limitations ######################################################## #connection_timeout "60" max_connections "20" max_playlist_length "81920" max_command_list_size "81920" max_output_buffer_size "81920" ############################################################################### # Character Encoding ########################################################## filesystem_charset "UTF-8" id3v1_encoding "UTF-8" ############################################################################### # volumio endpointstest --------------- TESTING REMOTE ENDPOINTS https://google.com, 1357 ms: OK https://www.googleapis.com, 1004 ms: OK https://securetoken.googleapis.com, 1140 ms: OK https://myvolumio.firebaseio.com, 1270 ms: OK https://functions.volumio.cloud, 1373 ms: OK https://oauth-performer.dfs.volumio.org, 968 ms: OK https://browsing-performer.dfs.volumio.org, 958 ms: OK http://cddb.volumio.org, 1384 ms: OK https://functions.volumio.cloud, 1351 ms: OK http://pushupdates.volumio.org, 498 ms: OK http://plugins.volumio.org, 1583 ms: OK https://database.volumio.cloud, 1252 ms: OK https://radio-directory.firebaseapp.com, 932 ms: OK ---------- REMOTE ENDPOINTS TEST OK, all Endpoints are reachable ---------- # sudo journalctl -p 7 --------------- -- Logs begin at Wed 2021-06-23 11:42:24 UTC, end at Wed 2021-06-23 12:33:12 UTC. -- Jun 23 11:42:24 schuur systemd-journal[180]: Runtime journal is using 4.0M (max allowed 30.0M, trying to leave 72.7M free of 480.6M available → current limit 30.0M). Jun 23 11:42:24 schuur kernel: Booting Linux on physical CPU 0xf00 Jun 23 11:42:24 schuur kernel: Linux version 4.19.118-v7+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1311 SMP Mon Apr 27 14:21:24 BST 2020 Jun 23 11:42:24 schuur kernel: CPU: ARMv7 Processor [410fc075] revision 5 (ARMv7), cr=10c5387d Jun 23 11:42:24 schuur kernel: CPU: div instructions available: patching division code Jun 23 11:42:24 schuur kernel: CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache Jun 23 11:42:24 schuur kernel: OF: fdt: Machine model: Raspberry Pi 2 Model B Rev 1.1 Jun 23 11:42:24 schuur kernel: Memory policy: Data cache writealloc Jun 23 11:42:24 schuur kernel: cma: Reserved 8 MiB at 0x3d800000 Jun 23 11:42:24 schuur kernel: On node 0 totalpages: 253952 Jun 23 11:42:24 schuur kernel: Normal zone: 2232 pages used for memmap Jun 23 11:42:24 schuur kernel: Normal zone: 0 pages reserved Jun 23 11:42:24 schuur kernel: Normal zone: 253952 pages, LIFO batch:63 Jun 23 11:42:24 schuur kernel: random: get_random_bytes called from start_kernel+0xac/0x4b4 with crng_init=0 Jun 23 11:42:24 schuur kernel: percpu: Embedded 16 pages/cpu s36864 r8192 d20480 u65536 Jun 23 11:42:24 schuur kernel: pcpu-alloc: s36864 r8192 d20480 u65536 alloc=16*4096 Jun 23 11:42:24 schuur kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 Jun 23 11:42:24 schuur kernel: Built 1 zonelists, mobility grouping on. Total pages: 251720 Jun 23 11:42:24 schuur kernel: Kernel command line: coherent_pool=1M bcm2708_fb.fbwidth=640 bcm2708_fb.fbheight=480 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 splash quiet plymouth.ignore-serial-consoles dwc_otg.fiq_enable=1 dwc_otg.fiq_fsm_enable=1 dwc_otg.fiq_fsm_mask=0xF dwc_otg.nak_holdoff=1 console=ttyAMA0,115200 kgdboc=ttyAMA0,115200 console=tty1 imgpart=/dev/mmcblk0p2 imgfile=/volumio_current.sqsh elevator=noop rootwait bootdelay=5 logo.nologo vt.global_cursor_default=0 loglevel=0 snd-bcm2835.enable_compat_alsa=1 snd_bcm2835.enable_headphones=1 Jun 23 11:42:24 schuur kernel: Dentry cache hash table entries: 131072 (order: 7, 524288 bytes) Jun 23 11:42:24 schuur kernel: Inode-cache hash table entries: 65536 (order: 6, 262144 bytes) Jun 23 11:42:24 schuur kernel: Memory: 964212K/1015808K available (8192K kernel code, 656K rwdata, 2232K rodata, 1024K init, 831K bss, 43404K reserved, 8192K cma-reserved) Jun 23 11:42:24 schuur kernel: Virtual kernel memory layout: vector : 0xffff0000 - 0xffff1000 ( 4 kB) fixmap : 0xffc00000 - 0xfff00000 (3072 kB) vmalloc : 0xbe800000 - 0xff800000 (1040 MB) lowmem : 0x80000000 - 0xbe000000 ( 992 MB) modules : 0x7f000000 - 0x80000000 ( 16 MB) .text : 0x(ptrval) - 0x(ptrval) (9184 kB) .init : 0x(ptrval) - 0x(ptrval) (1024 kB) .data : 0x(ptrval) - 0x(ptrval) ( 657 kB) .bss : 0x(ptrval) - 0x(ptrval) ( 832 kB) Jun 23 11:42:24 schuur kernel: SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 Jun 23 11:42:24 schuur kernel: ftrace: allocating 27093 entries in 80 pages Jun 23 11:42:24 schuur kernel: rcu: Hierarchical RCU implementation. Jun 23 11:42:24 schuur kernel: NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16 Jun 23 11:42:24 schuur kernel: arch_timer: cp15 timer(s) running at 19.20MHz (phys). Jun 23 11:42:24 schuur kernel: clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns Jun 23 11:42:24 schuur kernel: sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns Jun 23 11:42:24 schuur kernel: Switching to timer-based delay loop, resolution 52ns Jun 23 11:42:24 schuur kernel: Console: colour dummy device 80x30 Jun 23 11:42:24 schuur kernel: console [tty1] enabled Jun 23 11:42:24 schuur kernel: Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000) Jun 23 11:42:24 schuur kernel: pid_max: default: 32768 minimum: 301 Jun 23 11:42:24 schuur kernel: Mount-cache hash table entries: 2048 (order: 1, 8192 bytes) Jun 23 11:42:24 schuur kernel: Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes) Jun 23 11:42:24 schuur kernel: CPU: Testing write buffer coherency: ok Jun 23 11:42:24 schuur kernel: CPU0: update cpu_capacity 1024 Jun 23 11:42:24 schuur kernel: CPU0: thread -1, cpu 0, socket 15, mpidr 80000f00 Jun 23 11:42:24 schuur kernel: Setting up static identity map for 0x100000 - 0x10003c Jun 23 11:42:24 schuur kernel: rcu: Hierarchical SRCU implementation. Jun 23 11:42:24 schuur kernel: smp: Bringing up secondary CPUs ... Jun 23 11:42:24 schuur kernel: CPU1: update cpu_capacity 1024 Jun 23 11:42:24 schuur kernel: CPU1: thread -1, cpu 1, socket 15, mpidr 80000f01 Jun 23 11:42:24 schuur kernel: CPU2: update cpu_capacity 1024 Jun 23 11:42:24 schuur kernel: CPU2: thread -1, cpu 2, socket 15, mpidr 80000f02 Jun 23 11:42:24 schuur kernel: CPU3: update cpu_capacity 1024 Jun 23 11:42:24 schuur kernel: CPU3: thread -1, cpu 3, socket 15, mpidr 80000f03 Jun 23 11:42:24 schuur kernel: smp: Brought up 1 node, 4 CPUs Jun 23 11:42:24 schuur kernel: SMP: Total of 4 processors activated (153.60 BogoMIPS). Jun 23 11:42:24 schuur kernel: CPU: All CPU(s) started in HYP mode. Jun 23 11:42:24 schuur kernel: CPU: Virtualization extensions available. Jun 23 11:42:24 schuur kernel: devtmpfs: initialized Jun 23 11:42:24 schuur kernel: VFP support v0.3: implementor 41 architecture 2 part 30 variant 7 rev 5 Jun 23 11:42:24 schuur kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns Jun 23 11:42:24 schuur kernel: futex hash table entries: 1024 (order: 4, 65536 bytes) Jun 23 11:42:24 schuur kernel: pinctrl core: initialized pinctrl subsystem Jun 23 11:42:24 schuur kernel: NET: Registered protocol family 16 Jun 23 11:42:24 schuur kernel: DMA: preallocated 1024 KiB pool for atomic coherent allocations Jun 23 11:42:24 schuur kernel: hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers. Jun 23 11:42:24 schuur kernel: hw-breakpoint: maximum watchpoint size is 8 bytes. Jun 23 11:42:24 schuur kernel: Serial: AMBA PL011 UART driver Jun 23 11:42:24 schuur kernel: bcm2835-mbox 3f00b880.mailbox: mailbox enabled Jun 23 11:42:24 schuur kernel: raspberrypi-firmware soc:firmware: Attached to firmware from 2020-04-27 14:35, variant start Jun 23 11:42:24 schuur kernel: raspberrypi-firmware soc:firmware: Firmware hash is 3a8f1793b758d6fb7f375edaa260e069ecd34c88 Jun 23 11:42:24 schuur kernel: bcm2835-dma 3f007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1 Jun 23 11:42:24 schuur kernel: SCSI subsystem initialized Jun 23 11:42:24 schuur kernel: usbcore: registered new interface driver usbfs Jun 23 11:42:24 schuur kernel: usbcore: registered new interface driver hub Jun 23 11:42:24 schuur kernel: usbcore: registered new device driver usb Jun 23 11:42:24 schuur kernel: clocksource: Switched to clocksource arch_sys_counter Jun 23 11:42:24 schuur kernel: VFS: Disk quotas dquot_6.6.0 Jun 23 11:42:24 schuur kernel: VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes) Jun 23 11:42:24 schuur kernel: FS-Cache: Loaded Jun 23 11:42:24 schuur kernel: CacheFiles: Loaded Jun 23 11:42:24 schuur kernel: NET: Registered protocol family 2 Jun 23 11:42:24 schuur kernel: tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes) Jun 23 11:42:24 schuur kernel: TCP established hash table entries: 8192 (order: 3, 32768 bytes) Jun 23 11:42:24 schuur kernel: TCP bind hash table entries: 8192 (order: 4, 65536 bytes) Jun 23 11:42:24 schuur kernel: TCP: Hash tables configured (established 8192 bind 8192) Jun 23 11:42:24 schuur kernel: UDP hash table entries: 512 (order: 2, 16384 bytes) Jun 23 11:42:24 schuur kernel: UDP-Lite hash table entries: 512 (order: 2, 16384 bytes) Jun 23 11:42:24 schuur kernel: NET: Registered protocol family 1 Jun 23 11:42:24 schuur kernel: RPC: Registered named UNIX socket transport module. Jun 23 11:42:24 schuur kernel: RPC: Registered udp transport module. Jun 23 11:42:24 schuur kernel: RPC: Registered tcp transport module. Jun 23 11:42:24 schuur kernel: RPC: Registered tcp NFSv4.1 backchannel transport module. Jun 23 11:42:24 schuur kernel: Trying to unpack rootfs image as initramfs... Jun 23 11:42:24 schuur kernel: Freeing initrd memory: 19516K Jun 23 11:42:24 schuur kernel: hw perfevents: enabled with armv7_cortex_a7 PMU driver, 5 counters available Jun 23 11:42:24 schuur kernel: Initialise system trusted keyrings Jun 23 11:42:24 schuur kernel: workingset: timestamp_bits=14 max_order=18 bucket_order=4 Jun 23 11:42:24 schuur kernel: FS-Cache: Netfs 'nfs' registered for caching Jun 23 11:42:24 schuur kernel: NFS: Registering the id_resolver key type Jun 23 11:42:24 schuur kernel: Key type id_resolver registered Jun 23 11:42:24 schuur kernel: Key type id_legacy registered Jun 23 11:42:24 schuur kernel: nfs4filelayout_init: NFSv4 File Layout Driver Registering... Jun 23 11:42:24 schuur kernel: Key type asymmetric registered Jun 23 11:42:24 schuur kernel: Asymmetric key parser 'x509' registered Jun 23 11:42:24 schuur kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250) Jun 23 11:42:24 schuur kernel: io scheduler noop registered (default) Jun 23 11:42:24 schuur kernel: io scheduler deadline registered Jun 23 11:42:24 schuur kernel: io scheduler cfq registered Jun 23 11:42:24 schuur kernel: io scheduler mq-deadline registered Jun 23 11:42:24 schuur kernel: io scheduler kyber registered Jun 23 11:42:24 schuur kernel: bcm2708_fb soc:fb: FB found 1 display(s) Jun 23 11:42:24 schuur kernel: Console: switching to colour frame buffer device 80x30 Jun 23 11:42:24 schuur kernel: bcm2708_fb soc:fb: Registered framebuffer for display 0, size 640x480 Jun 23 11:42:24 schuur kernel: bcm2835-rng 3f104000.rng: hwrng registered Jun 23 11:42:24 schuur kernel: vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB) Jun 23 11:42:24 schuur kernel: vc-sm: Videocore shared memory driver Jun 23 11:42:24 schuur kernel: gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000 Jun 23 11:42:24 schuur kernel: brd: module loaded Jun 23 11:42:24 schuur kernel: loop: module loaded Jun 23 11:42:24 schuur kernel: Loading iSCSI transport class v2.0-870. Jun 23 11:42:24 schuur kernel: libphy: Fixed MDIO Bus: probed Jun 23 11:42:24 schuur kernel: usbcore: registered new interface driver lan78xx Jun 23 11:42:24 schuur kernel: usbcore: registered new interface driver smsc95xx Jun 23 11:42:24 schuur kernel: dwc_otg: version 3.00a 10-AUG-2012 (platform bus) Jun 23 11:42:24 schuur kernel: dwc_otg 3f980000.usb: base=(ptrval) Jun 23 11:42:24 schuur kernel: Core Release: 2.80a Jun 23 11:42:24 schuur kernel: Setting default values for core params Jun 23 11:42:24 schuur kernel: Finished setting default values for core params Jun 23 11:42:24 schuur kernel: Using Buffer DMA mode Jun 23 11:42:24 schuur kernel: Periodic Transfer Interrupt Enhancement - disabled Jun 23 11:42:24 schuur kernel: Multiprocessor Interrupt Enhancement - disabled Jun 23 11:42:24 schuur kernel: OTG VER PARAM: 0, OTG VER FLAG: 0 Jun 23 11:42:24 schuur kernel: Dedicated Tx FIFOs mode Jun 23 11:42:24 schuur kernel: WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = bd914000 dma = 0xfd914000 len=9024 Jun 23 11:42:24 schuur kernel: FIQ FSM acceleration enabled for : Non-periodic Split Transactions Periodic Split Transactions High-Speed Isochronous Endpoints Interrupt/Control Split Transaction hack enabled Jun 23 11:42:24 schuur kernel: dwc_otg: Microframe scheduler enabled Jun 23 11:42:24 schuur kernel: WARN::hcd_init_fiq:457: FIQ on core 1 Jun 23 11:42:24 schuur kernel: WARN::hcd_init_fiq:458: FIQ ASM at 8068fda0 length 36 Jun 23 11:42:24 schuur kernel: WARN::hcd_init_fiq:497: MPHI regs_base at be810000 Jun 23 11:42:24 schuur kernel: dwc_otg 3f980000.usb: DWC OTG Controller Jun 23 11:42:24 schuur kernel: dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1 Jun 23 11:42:24 schuur kernel: dwc_otg 3f980000.usb: irq 56, io mem 0x00000000 Jun 23 11:42:24 schuur kernel: Init: Port Power? op_state=1 Jun 23 11:42:24 schuur kernel: Init: Power Port (0) Jun 23 11:42:24 schuur kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19 Jun 23 11:42:24 schuur kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 Jun 23 11:42:24 schuur kernel: usb usb1: Product: DWC OTG Controller Jun 23 11:42:24 schuur kernel: usb usb1: Manufacturer: Linux 4.19.118-v7+ dwc_otg_hcd Jun 23 11:42:24 schuur kernel: usb usb1: SerialNumber: 3f980000.usb Jun 23 11:42:24 schuur kernel: hub 1-0:1.0: USB hub found Jun 23 11:42:24 schuur kernel: hub 1-0:1.0: 1 port detected Jun 23 11:42:24 schuur kernel: dwc_otg: FIQ enabled Jun 23 11:42:24 schuur kernel: dwc_otg: NAK holdoff enabled Jun 23 11:42:24 schuur kernel: dwc_otg: FIQ split-transaction FSM enabled Jun 23 11:42:24 schuur kernel: Module dwc_common_port init Jun 23 11:42:24 schuur kernel: usbcore: registered new interface driver usb-storage Jun 23 11:42:24 schuur kernel: mousedev: PS/2 mouse device common for all mice Jun 23 11:42:24 schuur kernel: bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer Jun 23 11:42:24 schuur kernel: bcm2835-cpufreq: min=600000 max=900000 Jun 23 11:42:24 schuur kernel: sdhci: Secure Digital Host Controller Interface driver Jun 23 11:42:24 schuur kernel: sdhci: Copyright(c) Pierre Ossman Jun 23 11:42:24 schuur kernel: sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe Jun 23 11:42:24 schuur kernel: sdhci-pltfm: SDHCI platform and OF driver helper Jun 23 11:42:24 schuur kernel: ledtrig-cpu: registered to indicate activity on CPUs Jun 23 11:42:24 schuur kernel: hidraw: raw HID events driver (C) Jiri Kosina Jun 23 11:42:24 schuur kernel: usbcore: registered new interface driver usbhid Jun 23 11:42:24 schuur kernel: usbhid: USB HID core driver Jun 23 11:42:24 schuur kernel: vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0 Jun 23 11:42:24 schuur kernel: [vc_sm_connected_init]: start Jun 23 11:42:24 schuur kernel: [vc_sm_connected_init]: end - returning 0 Jun 23 11:42:24 schuur kernel: Initializing XFRM netlink socket Jun 23 11:42:24 schuur kernel: NET: Registered protocol family 17 Jun 23 11:42:24 schuur kernel: Key type dns_resolver registered Jun 23 11:42:24 schuur kernel: Registering SWP/SWPB emulation handler Jun 23 11:42:24 schuur kernel: registered taskstats version 1 Jun 23 11:42:24 schuur kernel: Loading compiled-in X.509 certificates Jun 23 11:42:24 schuur kernel: uart-pl011 3f201000.serial: cts_event_workaround enabled Jun 23 11:42:24 schuur kernel: 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2 Jun 23 11:42:24 schuur kernel: console [ttyAMA0] enabled Jun 23 11:42:24 schuur kernel: sdhost: log_buf @ (ptrval) (fd913000) Jun 23 11:42:24 schuur kernel: mmc0: sdhost-bcm2835 loaded - DMA enabled (>1) Jun 23 11:42:24 schuur kernel: of_cfs_init Jun 23 11:42:24 schuur kernel: of_cfs_init: OK Jun 23 11:42:24 schuur kernel: Freeing unused kernel memory: 1024K Jun 23 11:42:24 schuur kernel: Run /init as init process Jun 23 11:42:24 schuur kernel: mmc0: host does not support reading read-only switch, assuming write-enable Jun 23 11:42:24 schuur kernel: mmc0: new high speed SDHC card at address aaaa Jun 23 11:42:24 schuur kernel: mmcblk0: mmc0:aaaa SB32G 29.7 GiB Jun 23 11:42:24 schuur kernel: mmcblk0: p1 p2 p3 Jun 23 11:42:24 schuur kernel: Indeed it is in host mode hprt0 = 00021501 Jun 23 11:42:24 schuur kernel: random: fast init done Jun 23 11:42:24 schuur initramfs: Booting Volumio for BCM2835 Jun 23 11:42:24 schuur initramfs: This script mounts rootfs RO with an overlay RW layer. Jun 23 11:42:24 schuur kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher Jun 23 11:42:24 schuur kernel: fuse init (API version 7.27) Jun 23 11:42:24 schuur initramfs: IMGPART=/dev/mmcblk0p2 Jun 23 11:42:24 schuur initramfs: IMGFILE=/volumio_current.sqsh Jun 23 11:42:24 schuur initramfs: Boot delay (except first time) will be 5 seconds Jun 23 11:42:24 schuur kernel: usb 1-1: new high-speed USB device number 2 using dwc_otg Jun 23 11:42:24 schuur kernel: Indeed it is in host mode hprt0 = 00001101 Jun 23 11:42:24 schuur initramfs: /dev/mmcblk0p2: Jun 23 11:42:24 schuur kernel: EXT4-fs (mmcblk0p2): recovery complete Jun 23 11:42:24 schuur kernel: EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null) Jun 23 11:42:24 schuur initramfs: Doing a 5 second delay here to give kernel load a headstart Jun 23 11:42:24 schuur kernel: usb 1-1: New USB device found, idVendor=0424, idProduct=9514, bcdDevice= 2.00 Jun 23 11:42:24 schuur kernel: usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 Jun 23 11:42:24 schuur kernel: hub 1-1:1.0: USB hub found Jun 23 11:42:24 schuur kernel: hub 1-1:1.0: 5 ports detected Jun 23 11:42:24 schuur kernel: usb 1-1.1: new high-speed USB device number 3 using dwc_otg Jun 23 11:42:24 schuur kernel: usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00 Jun 23 11:42:24 schuur kernel: usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 Jun 23 11:42:24 schuur kernel: smsc95xx v1.0.6 Jun 23 11:42:24 schuur kernel: smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:e8:3c:05 Jun 23 11:42:24 schuur kernel: usb 1-1.3: new full-speed USB device number 4 using dwc_otg Jun 23 11:42:24 schuur kernel: usb 1-1.3: New USB device found, idVendor=194f, idProduct=0301, bcdDevice= 1.10 Jun 23 11:42:24 schuur kernel: usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Jun 23 11:42:24 schuur kernel: usb 1-1.3: Product: AudioBox USB Jun 23 11:42:24 schuur kernel: usb 1-1.3: Manufacturer: PreSonus Audio Jun 23 11:42:24 schuur initramfs: Checking for USB updates Jun 23 11:42:24 schuur initramfs: No USB device detected (when incorrect, try adding 'bootdelay=5' to your boot cmdline) Jun 23 11:42:24 schuur kernel: EXT4-fs (mmcblk0p3): recovery complete Jun 23 11:42:24 schuur kernel: EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null) Jun 23 11:42:24 schuur initramfs: With Option: Jun 23 11:42:24 schuur initramfs: VOLUMIO_VERSION="2.882" Jun 23 11:42:24 schuur initramfs: Finish initramfs, continue booting Volumio Jun 23 11:42:24 schuur kernel: random: systemd: uninitialized urandom read (16 bytes read) Jun 23 11:42:24 schuur systemd[1]: systemd 215 running in system mode. (+PAM +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ -SECCOMP -APPARMOR) Jun 23 11:42:24 schuur systemd[1]: Detected architecture 'arm'. Jun 23 11:42:24 schuur kernel: NET: Registered protocol family 10 Jun 23 11:42:24 schuur kernel: Segment Routing with IPv6 Jun 23 11:42:24 schuur systemd[1]: Inserted module 'ipv6' Jun 23 11:42:24 schuur systemd[1]: Set hostname to . Jun 23 11:42:24 schuur kernel: uart-pl011 3f201000.serial: no DMA platform data Jun 23 11:42:24 schuur kernel: random: systemd-sysv-ge: uninitialized urandom read (16 bytes read) Jun 23 11:42:24 schuur kernel: random: systemd: uninitialized urandom read (16 bytes read) Jun 23 11:42:24 schuur systemd[1]: [/lib/systemd/system/mpd.service:18] Unknown lvalue 'ProtectKernelTunables' in section 'Service' Jun 23 11:42:24 schuur systemd[1]: [/lib/systemd/system/mpd.service:19] Unknown lvalue 'ProtectControlGroups' in section 'Service' Jun 23 11:42:24 schuur systemd[1]: [/lib/systemd/system/mpd.service:20] Unknown lvalue 'ProtectKernelModules' in section 'Service' Jun 23 11:42:24 schuur systemd[1]: [/lib/systemd/system/mpd.service:23] Unknown lvalue 'RestrictNamespaces' in section 'Service' Jun 23 11:42:24 schuur systemd[1]: Cannot add dependency job for unit display-manager.service, ignoring: Unit display-manager.service failed to load: No such file or directory. Jun 23 11:42:24 schuur systemd[1]: Starting Forward Password Requests to Wall Directory Watch. Jun 23 11:42:24 schuur kernel: i2c /dev entries driver Jun 23 11:42:24 schuur systemd-journal[180]: Journal started Jun 23 11:42:24 schuur systemd[1]: Starting Slices. Jun 23 11:42:24 schuur systemd[1]: Reached target Slices. Jun 23 11:42:24 schuur systemd[1]: Starting Remount Root and Kernel File Systems... Jun 23 11:42:24 schuur systemd[1]: Started Create list of required static device nodes for the current kernel. Jun 23 11:42:24 schuur systemd[1]: Starting Create Static Device Nodes in /dev... Jun 23 11:42:24 schuur systemd[1]: Started Restore / save the current clock. Jun 23 11:42:24 schuur systemd[1]: Time has been changed Jun 23 11:42:24 schuur systemd[1]: Mounted Debug File System. Jun 23 11:42:24 schuur systemd[1]: Mounted POSIX Message Queue File System. Jun 23 11:42:24 schuur systemd[1]: Started Remount Root and Kernel File Systems. Jun 23 11:42:24 schuur systemd[1]: Started Create Static Device Nodes in /dev. Jun 23 11:42:24 schuur systemd-modules-load[178]: Inserted module 'i2c_dev' Jun 23 11:42:24 schuur systemd[1]: Starting udev Kernel Device Manager... Jun 23 11:42:24 schuur systemd[1]: Started Various fixups to make systemd work better on Debian. Jun 23 11:42:24 schuur systemd[1]: Starting Load/Save Random Seed... Jun 23 11:42:24 schuur systemd[1]: Starting Local File Systems (Pre). Jun 23 11:42:24 schuur systemd[1]: Reached target Local File Systems (Pre). Jun 23 11:42:24 schuur systemd[1]: Mounting /tmp... Jun 23 11:42:24 schuur systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway. Jun 23 11:42:24 schuur systemd[1]: Mounting /var/spool/cups... Jun 23 11:42:24 schuur fake-hwclock[170]: Wed Jun 23 11:42:24 UTC 2021 Jun 23 11:42:24 schuur systemd[1]: Mounting /var/log... Jun 23 11:42:24 schuur systemd[1]: var-log.mount: Directory /var/log to mount over is not empty, mounting anyway. Jun 23 11:42:24 schuur systemd-udevd[204]: starting version 215 Jun 23 11:42:24 schuur systemd[1]: Mounted /tmp. Jun 23 11:42:24 schuur systemd[1]: Mounted /var/spool/cups. Jun 23 11:42:24 schuur systemd[1]: Started udev Kernel Device Manager. Jun 23 11:42:24 schuur systemd[1]: Started Load Kernel Modules. Jun 23 11:42:24 schuur systemd[1]: Started Load/Save Random Seed. Jun 23 11:42:24 schuur systemd[1]: Mounted /var/log. Jun 23 11:42:24 schuur systemd[1]: Mounting FUSE Control File System... Jun 23 11:42:24 schuur systemd[1]: Mounting Configuration File System... Jun 23 11:42:24 schuur systemd[1]: Starting Apply Kernel Variables... Jun 23 11:42:24 schuur systemd[1]: Starting Show Plymouth Boot Screen... Jun 23 11:42:24 schuur systemd[1]: Starting Copy rules generated while the root was ro... Jun 23 11:42:24 schuur systemd[1]: Mounting /var/spool/cups/tmp... Jun 23 11:42:24 schuur systemd[1]: Mounted FUSE Control File System. Jun 23 11:42:24 schuur systemd[1]: Mounted Configuration File System. Jun 23 11:42:24 schuur systemd[1]: Mounted /var/spool/cups/tmp. Jun 23 11:42:24 schuur systemd[1]: Started Copy rules generated while the root was ro. Jun 23 11:42:24 schuur systemd[1]: Started Apply Kernel Variables. Jun 23 11:42:24 schuur systemd[1]: Started Show Plymouth Boot Screen. Jun 23 11:42:24 schuur systemd[1]: Starting Forward Password Requests to Plymouth Directory Watch. Jun 23 11:42:24 schuur systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. Jun 23 11:42:24 schuur systemd[1]: Started Dispatch Password Requests to Console Directory Watch. Jun 23 11:42:24 schuur systemd[1]: Starting Paths. Jun 23 11:42:24 schuur systemd[1]: Reached target Paths. Jun 23 11:42:24 schuur kernel: vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned. Jun 23 11:42:24 schuur kernel: bcm2835_vc_sm_cma_probe: Videocore shared memory driver Jun 23 11:42:24 schuur kernel: [vc_sm_connected_init]: start Jun 23 11:42:24 schuur kernel: media: Linux media interface: v0.10 Jun 23 11:42:24 schuur kernel: [vc_sm_connected_init]: installed successfully Jun 23 11:42:25 schuur kernel: videodev: Linux video capture interface: v2.00 Jun 23 11:42:25 schuur kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Jun 23 11:42:25 schuur systemd[1]: Found device /dev/ttyAMA0. Jun 23 11:42:25 schuur kernel: bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. Jun 23 11:42:25 schuur kernel: bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. Jun 23 11:42:25 schuur kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video10 Jun 23 11:42:25 schuur kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 decode Jun 23 11:42:25 schuur kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video11 Jun 23 11:42:25 schuur kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode Jun 23 11:42:25 schuur kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video12 Jun 23 11:42:25 schuur kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 isp Jun 23 11:42:25 schuur kernel: snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned. Jun 23 11:42:25 schuur kernel: snd_bcm2835: unknown parameter 'index' ignored Jun 23 11:42:25 schuur kernel: bcm2835_audio soc:audio: card created with 5 channels Jun 23 11:42:25 schuur kernel: bcm2835_audio soc:audio: card created with 3 channels Jun 23 11:42:25 schuur systemd[1]: Starting Sound Card. Jun 23 11:42:25 schuur systemd[1]: Reached target Sound Card. Jun 23 11:42:25 schuur kernel: snd_usb_audio: unknown parameter 'nrpacks' ignored Jun 23 11:42:25 schuur kernel: snd_usb_audio: unknown parameter 'nrpacks' ignored Jun 23 11:42:25 schuur systemd[1]: Found device /dev/mmcblk0p1. Jun 23 11:42:25 schuur systemd[1]: Starting File System Check on /dev/mmcblk0p1... Jun 23 11:42:25 schuur kernel: usb 1-1.3: 2:1: cannot get freq at ep 0x1 Jun 23 11:42:25 schuur kernel: usb 1-1.3: 3:1: cannot get freq at ep 0x82 Jun 23 11:42:25 schuur kernel: usbcore: registered new interface driver snd-usb-audio Jun 23 11:42:25 schuur systemd[1]: Starting system-ifup.slice. Jun 23 11:42:25 schuur systemd[1]: Created slice system-ifup.slice. Jun 23 11:42:26 schuur systemd-fsck[314]: fsck.fat 3.0.27 (2014-11-12) Jun 23 11:42:26 schuur systemd-fsck[314]: /dev/mmcblk0p1: 239 files, 116219/123044 clusters Jun 23 11:42:26 schuur systemd[1]: Started File System Check on /dev/mmcblk0p1. Jun 23 11:42:26 schuur systemd[1]: Mounting /boot... Jun 23 11:42:26 schuur systemd[1]: Mounted /boot. Jun 23 11:42:26 schuur systemd[1]: Starting Local File Systems. Jun 23 11:42:26 schuur systemd[1]: Reached target Local File Systems. Jun 23 11:42:26 schuur systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... Jun 23 11:42:26 schuur systemd[1]: Starting Remote File Systems. Jun 23 11:42:26 schuur systemd[1]: Reached target Remote File Systems. Jun 23 11:42:26 schuur systemd[1]: Starting Trigger Flushing of Journal to Persistent Storage... Jun 23 11:42:26 schuur systemd[1]: Starting Create Volatile Files and Directories... Jun 23 11:42:26 schuur systemd[1]: Starting LSB: Raise network interfaces.... Jun 23 11:42:26 schuur systemd[1]: Started Tell Plymouth To Write Out Runtime Data. Jun 23 11:42:26 schuur systemd[1]: Started Create Volatile Files and Directories. Jun 23 11:42:26 schuur systemd[1]: Started Trigger Flushing of Journal to Persistent Storage. Jun 23 11:42:26 schuur systemd[1]: Starting Update UTMP about System Boot/Shutdown... Jun 23 11:42:26 schuur systemd[1]: Started Update UTMP about System Boot/Shutdown. Jun 23 11:42:27 schuur kernel: Under-voltage detected! (0x00050000) Jun 23 11:42:27 schuur kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database Jun 23 11:42:27 schuur kernel: cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' Jun 23 11:42:27 schuur kernel: platform regulatory.0: Direct firmware load for regulatory.db failed with error -2 Jun 23 11:42:27 schuur kernel: cfg80211: failed to load regulatory.db Jun 23 11:42:27 schuur networking[332]: Configuring network interfaces...command failed: No such device (-19) Jun 23 11:42:27 schuur networking[332]: command failed: No such device (-19) Jun 23 11:42:28 schuur systemd[1]: Received SIGRTMIN+20 from PID 242 (plymouthd). Jun 23 11:42:28 schuur kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup Jun 23 11:42:28 schuur networking[332]: command failed: No such device (-19) Jun 23 11:42:28 schuur networking[332]: dhcpcd[440]: version 6.0.5 starting Jun 23 11:42:28 schuur dhcpcd[440]: version 6.0.5 starting Jun 23 11:42:29 schuur networking[332]: dhcpcd[440]: eth0: soliciting a DHCP lease Jun 23 11:42:29 schuur dhcpcd[440]: eth0: soliciting a DHCP lease Jun 23 11:42:29 schuur kernel: Voltage normalised (0x00000000) Jun 23 11:42:29 schuur dhcpcd[440]: eth0: carrier lost Jun 23 11:42:29 schuur networking[332]: dhcpcd[440]: eth0: carrier lost Jun 23 11:42:30 schuur dhcpcd[440]: eth0: carrier acquired Jun 23 11:42:30 schuur networking[332]: dhcpcd[440]: eth0: carrier acquired Jun 23 11:42:30 schuur kernel: smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC1E1 Jun 23 11:42:30 schuur dhcpcd[440]: eth0: soliciting a DHCP lease Jun 23 11:42:30 schuur networking[332]: dhcpcd[440]: eth0: soliciting a DHCP lease Jun 23 11:42:31 schuur dhcpcd[440]: eth0: offered 10.0.0.144 from 10.0.0.254 Jun 23 11:42:31 schuur networking[332]: dhcpcd[440]: eth0: offered 10.0.0.144 from 10.0.0.254 Jun 23 11:42:31 schuur dhcpcd[440]: eth0: leased 10.0.0.144 for 86400 seconds Jun 23 11:42:31 schuur dhcpcd[440]: eth0: adding host route to 10.0.0.144 via 127.0.0.1 Jun 23 11:42:31 schuur dhcpcd[440]: eth0: adding route to 10.0.0.0/24 Jun 23 11:42:31 schuur dhcpcd[440]: eth0: adding default route via 10.0.0.254 Jun 23 11:42:31 schuur networking[332]: dhcpcd[440]: eth0: leased 10.0.0.144 for 86400 seconds Jun 23 11:42:31 schuur networking[332]: dhcpcd[440]: eth0: adding host route to 10.0.0.144 via 127.0.0.1 Jun 23 11:42:31 schuur networking[332]: dhcpcd[440]: eth0: adding route to 10.0.0.0/24 Jun 23 11:42:31 schuur networking[332]: dhcpcd[440]: eth0: adding default route via 10.0.0.254 Jun 23 11:42:31 schuur dhcpcd[440]: forked to background, child pid 503 Jun 23 11:42:31 schuur networking[332]: dhcpcd[440]: forked to background, child pid 503 Jun 23 11:42:32 schuur networking[332]: done. Jun 23 11:42:32 schuur systemd[1]: Started LSB: Raise network interfaces.. Jun 23 11:42:32 schuur systemd[1]: Starting ifup for eth0... Jun 23 11:42:32 schuur systemd[1]: Started ifup for eth0. Jun 23 11:42:32 schuur systemd[1]: Starting Network. Jun 23 11:42:32 schuur systemd[1]: Reached target Network. Jun 23 11:42:32 schuur systemd[1]: Starting Network is Online. Jun 23 11:42:32 schuur systemd[1]: Reached target Network is Online. Jun 23 11:42:32 schuur systemd[1]: Starting LSB: RPC portmapper replacement... Jun 23 11:42:32 schuur ifup[550]: /sbin/ifup: interface eth0 already configured Jun 23 11:42:32 schuur rpcbind[551]: Starting rpcbind daemon.... Jun 23 11:42:32 schuur systemd[1]: Started LSB: RPC portmapper replacement. Jun 23 11:42:32 schuur systemd[1]: Starting RPC Port Mapper. Jun 23 11:42:32 schuur systemd[1]: Reached target RPC Port Mapper. Jun 23 11:42:32 schuur systemd[1]: Starting LSB: NFS support files common to client and server... Jun 23 11:42:32 schuur rpc.statd[573]: Version 1.2.8 starting Jun 23 11:42:32 schuur sm-notify[574]: Version 1.2.8 starting Jun 23 11:42:32 schuur kernel: Installing knfsd (copyright (C) 1996 okir@monad.swb.de). Jun 23 11:42:33 schuur nfs-common[567]: Starting NFS common utilities: statd idmapd. Jun 23 11:42:33 schuur systemd[1]: Started LSB: NFS support files common to client and server. Jun 23 11:42:33 schuur systemd[1]: Starting System Initialization. Jun 23 11:42:33 schuur systemd[1]: Reached target System Initialization. Jun 23 11:42:33 schuur systemd[1]: Starting Avahi mDNS/DNS-SD Stack Activation Socket. Jun 23 11:42:33 schuur systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket. Jun 23 11:42:33 schuur systemd[1]: Starting mpd.socket. Jun 23 11:42:33 schuur systemd[1]: Listening on mpd.socket. Jun 23 11:42:33 schuur systemd[1]: Starting D-Bus System Message Bus Socket. Jun 23 11:42:33 schuur systemd[1]: Listening on D-Bus System Message Bus Socket. Jun 23 11:42:33 schuur systemd[1]: Starting Sockets. Jun 23 11:42:33 schuur systemd[1]: Reached target Sockets. Jun 23 11:42:33 schuur systemd[1]: Starting Daily Cleanup of Temporary Directories. Jun 23 11:42:33 schuur systemd[1]: Started Daily Cleanup of Temporary Directories. Jun 23 11:42:33 schuur systemd[1]: Starting Timers. Jun 23 11:42:33 schuur systemd[1]: Reached target Timers. Jun 23 11:42:33 schuur systemd[1]: Started Manage Sound Card State (restore and store). Jun 23 11:42:33 schuur systemd[1]: Starting Restore Sound Card State... Jun 23 11:42:33 schuur systemd[1]: Starting Basic System. Jun 23 11:42:33 schuur systemd[1]: Reached target Basic System. Jun 23 11:42:33 schuur systemd[1]: Starting Entropy daemon using the HAVEGE algorithm... Jun 23 11:42:33 schuur systemd[1]: Started Entropy daemon using the HAVEGE algorithm. Jun 23 11:42:33 schuur systemd[1]: Started Configure Bluetooth Modems connected by UART. Jun 23 11:42:33 schuur systemd[1]: Starting Volumio Iptables Module... Jun 23 11:42:33 schuur systemd[1]: Started Volumio Iptables Module. Jun 23 11:42:33 schuur systemd[1]: Starting mount disks automatically with standby... Jun 23 11:42:33 schuur systemd[1]: Started mount disks automatically with standby. Jun 23 11:42:33 schuur systemd[1]: Starting UPnP Renderer front-end to MPD... Jun 23 11:42:33 schuur systemd[1]: Started UPnP Renderer front-end to MPD. Jun 23 11:42:33 schuur systemd[1]: Starting volumio-remote-updater.service... Jun 23 11:42:33 schuur systemd[1]: Started volumio-remote-updater.service. Jun 23 11:42:33 schuur systemd[1]: Starting Volumio Log Rotation Service... Jun 23 11:42:33 schuur systemd[1]: Started Volumio Log Rotation Service. Jun 23 11:42:33 schuur systemd[1]: Starting Volumio SSH enabler... Jun 23 11:42:33 schuur systemd[1]: Started Volumio SSH enabler. Jun 23 11:42:33 schuur systemd[1]: Starting Wireless Services... Jun 23 11:42:33 schuur systemd[1]: Starting OpenBSD Secure Shell server... Jun 23 11:42:33 schuur systemd[1]: Starting /etc/rc.local Compatibility... Jun 23 11:42:33 schuur systemd[1]: Started getty on tty2-tty6 if dbus and logind are not available. Jun 23 11:42:33 schuur systemd[1]: Starting Login Service... Jun 23 11:42:33 schuur systemd[1]: Starting LSB: start Winbind daemon... Jun 23 11:42:33 schuur systemd[1]: Starting LSB: triggerhappy hotkey daemon... Jun 23 11:42:33 schuur systemd[1]: Starting LSB: start Samba daemons for the AD DC... Jun 23 11:42:33 schuur systemd[1]: Starting LSB: Start NTP daemon... Jun 23 11:42:33 schuur systemd[1]: Starting LSB: start Samba NetBIOS nameserver (nmbd)... Jun 23 11:42:33 schuur systemd[1]: Starting LSB: Load kernel modules needed to enable cpufreq scaling... Jun 23 11:42:33 schuur systemd[1]: Starting LSB: Brings up/down network automatically... Jun 23 11:42:33 schuur systemd[1]: Starting LSB: Advanced IEEE 802.11 management daemon... Jun 23 11:42:33 schuur systemd[1]: Starting LSB: IPv4 DHCP client with IPv4LL support... Jun 23 11:42:33 schuur systemd[1]: Starting Avahi mDNS/DNS-SD Stack... Jun 23 11:42:33 schuur systemd[1]: Starting Music Player Daemon... Jun 23 11:42:33 schuur systemd[1]: Starting D-Bus System Message Bus... Jun 23 11:42:33 schuur systemd[1]: Started D-Bus System Message Bus. Jun 23 11:42:33 schuur dhcpcd[634]: Not running dhcpcd because there is aleady an interface specific instance ... failed! Jun 23 11:42:33 schuur triggerhappy[609]: Unable to parse trigger line: Jun 23 11:42:33 schuur triggerhappy[609]: Unable to parse trigger line: Jun 23 11:42:33 schuur triggerhappy[609]: Unable to parse trigger line: Jun 23 11:42:33 schuur triggerhappy[609]: Unable to parse trigger line: Jun 23 11:42:33 schuur triggerhappy[609]: Unable to parse trigger line: Jun 23 11:42:33 schuur triggerhappy[609]: Unable to parse trigger line: Jun 23 11:42:33 schuur triggerhappy[609]: Unable to parse trigger line: Jun 23 11:42:33 schuur triggerhappy[609]: Error opening '/dev/input/event*': No such file or directory Jun 23 11:42:33 schuur dhcpcd[634]: /var/run/dhcpcd-eth0.pid ... failed! Jun 23 11:42:33 schuur ifplugd(eth0)[698]: ifplugd 0.28 initializing. Jun 23 11:42:33 schuur ifplugd(eth0)[698]: Using interface eth0/B8:27:EB:E8:3C:05 with driver (version: 22-Aug-2005) Jun 23 11:42:33 schuur ifplugd(eth0)[698]: Using detection mode: SIOCETHTOOL Jun 23 11:42:33 schuur ifplugd(eth0)[698]: Initialization complete, link beat detected. Jun 23 11:42:34 schuur ifplugd(eth0)[698]: Executing '/etc/ifplugd/ifplugd.action eth0 up'. Jun 23 11:42:34 schuur loadcpufreq[617]: Loading cpufreq kernel modules...done (none). Jun 23 11:42:34 schuur avahi-daemon[636]: Found user 'avahi' (UID 104) and group 'avahi' (GID 106). Jun 23 11:42:34 schuur avahi-daemon[636]: Successfully dropped root privileges. Jun 23 11:42:34 schuur avahi-daemon[636]: avahi-daemon 0.6.31 starting up. Jun 23 11:42:34 schuur ifplugd(eth0)[698]: client: /sbin/ifup: interface eth0 already configured Jun 23 11:42:34 schuur ifplugd(eth0)[698]: Program executed successfully. Jun 23 11:42:34 schuur ifplugd[624]: Network Interface Plugging Daemon...start eth0...done. Jun 23 11:42:34 schuur sudo[606]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 set power_save off Jun 23 11:42:34 schuur sudo[606]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:42:34 schuur avahi-daemon[636]: Successfully called chroot(). Jun 23 11:42:34 schuur avahi-daemon[636]: Successfully dropped remaining capabilities. Jun 23 11:42:34 schuur avahi-daemon[636]: Loading service file /services/volumio.service. Jun 23 11:42:34 schuur avahi-daemon[636]: Joining mDNS multicast group on interface eth0.IPv4 with address 10.0.0.144. Jun 23 11:42:34 schuur avahi-daemon[636]: New relevant interface eth0.IPv4 for mDNS. Jun 23 11:42:34 schuur avahi-daemon[636]: Network interface enumeration completed. Jun 23 11:42:34 schuur avahi-daemon[636]: Registering new address record for 10.0.0.144 on eth0.IPv4. Jun 23 11:42:34 schuur avahi-daemon[636]: Registering HINFO record with values 'ARMV7L'/'LINUX'. Jun 23 11:42:34 schuur systemd[1]: Started Avahi mDNS/DNS-SD Stack. Jun 23 11:42:34 schuur systemd[1]: Starting Permit User Sessions... Jun 23 11:42:34 schuur systemd[1]: Started Restore Sound Card State. Jun 23 11:42:34 schuur systemd[1]: Started OpenBSD Secure Shell server. Jun 23 11:42:34 schuur systemd[1]: Started /etc/rc.local Compatibility. Jun 23 11:42:34 schuur systemd[1]: Started LSB: triggerhappy hotkey daemon. Jun 23 11:42:34 schuur wifistart.sh[599]: command failed: No such device (-19) Jun 23 11:42:34 schuur sudo[606]: pam_unix(sudo:session): session closed for user root Jun 23 11:42:34 schuur systemd[1]: Started LSB: Load kernel modules needed to enable cpufreq scaling. Jun 23 11:42:34 schuur systemd[1]: Started LSB: Brings up/down network automatically. Jun 23 11:42:34 schuur systemd[1]: Started LSB: Advanced IEEE 802.11 management daemon. Jun 23 11:42:34 schuur systemd[1]: dhcpcd.service: control process exited, code=exited status=6 Jun 23 11:42:34 schuur systemd[1]: Failed to start LSB: IPv4 DHCP client with IPv4LL support. Jun 23 11:42:34 schuur systemd[1]: Unit dhcpcd.service entered failed state. Jun 23 11:42:34 schuur systemd[1]: Started Permit User Sessions. Jun 23 11:42:34 schuur dbus[651]: [system] Activating via systemd: service name='org.freedesktop.UDisks' unit='udisks.service' Jun 23 11:42:34 schuur volumio-remote-updater[596]: Error: No active session Jun 23 11:42:34 schuur volumio-remote-updater[596]: [2021-06-23 11:42:34] [info] asio async_connect error: system:111 (Connection refused) Jun 23 11:42:34 schuur ntpd[681]: ntpd 4.2.6p5@1.2349-o Mon Jul 25 22:35:28 UTC 2016 (1) Jun 23 11:42:34 schuur ntp[611]: Starting NTP server: ntpd. Jun 23 11:42:34 schuur ntpd[736]: proto: precision = 1.407 usec Jun 23 11:42:34 schuur ntpd[736]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123 Jun 23 11:42:34 schuur systemd[1]: Started LSB: Start NTP daemon. Jun 23 11:42:34 schuur volumio-remote-updater[596]: [2021-06-23 11:42:34] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Jun 23 11:42:34 schuur volumio-remote-updater[596]: [2021-06-23 11:42:34] [error] handle_connect error: Underlying Transport Error Jun 23 11:42:34 schuur ntpd[736]: Listen and drop on 1 v6wildcard :: UDP 123 Jun 23 11:42:34 schuur ntpd[736]: Listen normally on 2 lo 127.0.0.1 UDP 123 Jun 23 11:42:34 schuur ntpd[736]: Listen normally on 3 eth0 10.0.0.144 UDP 123 Jun 23 11:42:34 schuur ntpd[736]: peers refreshed Jun 23 11:42:34 schuur ntpd[736]: Listening on routing socket on fd #20 for interface updates Jun 23 11:42:34 schuur sshd[728]: Server listening on 0.0.0.0 port 22. Jun 23 11:42:34 schuur sshd[728]: Server listening on :: port 22. Jun 23 11:42:35 schuur systemd-logind[603]: New seat seat0. Jun 23 11:42:35 schuur systemd[1]: Started Login Service. Jun 23 11:42:35 schuur systemd[1]: Starting Disk Manager (legacy version)... Jun 23 11:42:35 schuur systemd[1]: Starting LSB: set CPUFreq kernel parameters... Jun 23 11:42:35 schuur systemd[1]: Starting Hold until boot process finishes up... Jun 23 11:42:35 schuur systemd[1]: Starting Terminate Plymouth Boot Screen... Jun 23 11:42:35 schuur systemd[1]: Received SIGRTMIN+21 from PID 242 (plymouthd). Jun 23 11:42:35 schuur systemd[1]: Started Terminate Plymouth Boot Screen. Jun 23 11:42:35 schuur systemd[1]: Started Hold until boot process finishes up. Jun 23 11:42:35 schuur cpufrequtils[741]: CPUFreq Utilities: Setting performance CPUFreq governor...CPU0...CPU1...CPU2...CPU3...done. Jun 23 11:42:35 schuur systemd[1]: Started LSB: set CPUFreq kernel parameters. Jun 23 11:42:35 schuur volumio[595]: Could not open config: /tmp/upmpdcli.conf Jun 23 11:42:35 schuur dbus[651]: [system] Successfully activated service 'org.freedesktop.UDisks' Jun 23 11:42:35 schuur systemd[1]: Started Disk Manager (legacy version). Jun 23 11:42:35 schuur systemd[1]: upmpdcli.service: main process exited, code=exited, status=1/FAILURE Jun 23 11:42:35 schuur systemd[1]: Unit upmpdcli.service entered failed state. Jun 23 11:42:35 schuur systemd[1]: Starting Getty on tty1... Jun 23 11:42:35 schuur systemd[1]: Started Getty on tty1. Jun 23 11:42:35 schuur systemd[1]: Starting Serial Getty on ttyAMA0... Jun 23 11:42:35 schuur kernel: Under-voltage detected! (0x00050005) Jun 23 11:42:35 schuur systemd[1]: Started Serial Getty on ttyAMA0. Jun 23 11:42:35 schuur systemd[1]: Starting Login Prompts. Jun 23 11:42:35 schuur systemd[1]: Reached target Login Prompts. Jun 23 11:42:35 schuur avahi-daemon[636]: Server startup complete. Host name is schuur.local. Local service cookie is 3294725968. Jun 23 11:42:35 schuur dbus[651]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkitd.service' Jun 23 11:42:35 schuur systemd[1]: Starting Authenticate and Authorize Users to Run Privileged Tasks... Jun 23 11:42:35 schuur polkitd[764]: started daemon version 0.105 using authority implementation `local' version `0.105' Jun 23 11:42:35 schuur dbus[651]: [system] Successfully activated service 'org.freedesktop.PolicyKit1' Jun 23 11:42:35 schuur systemd[1]: Started Authenticate and Authorize Users to Run Privileged Tasks. Jun 23 11:42:36 schuur udisks-glue[594]: Device file /dev/mmcblk0 inserted Jun 23 11:42:36 schuur udisks-glue[594]: Device file /dev/mmcblk0p3 inserted Jun 23 11:42:36 schuur haveged[592]: haveged: ver: 1.9.1; arch: generic; vend: ; build: (gcc 4.8.2 CTV); collect: 128K Jun 23 11:42:36 schuur haveged[592]: haveged: cpu: (VC); data: 16K (D); inst: 16K (D); idx: 8/40; sz: 15248/74244 Jun 23 11:42:36 schuur haveged[592]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B): last entropy estimate 7.99946 Jun 23 11:42:36 schuur haveged[592]: haveged: fills: 0, generated: 0 Jun 23 11:42:36 schuur kernel: random: crng init done Jun 23 11:42:36 schuur kernel: random: 7 urandom warning(s) missed due to ratelimiting Jun 23 11:42:36 schuur avahi-daemon[636]: Service "Schuur" (/services/volumio.service) successfully established. Jun 23 11:42:39 schuur volumio-remote-updater[596]: [2021-06-23 11:42:39] [info] asio async_connect error: system:111 (Connection refused) Jun 23 11:42:39 schuur volumio-remote-updater[596]: [2021-06-23 11:42:39] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Jun 23 11:42:39 schuur volumio-remote-updater[596]: [2021-06-23 11:42:39] [error] handle_connect error: Underlying Transport Error Jun 23 11:42:40 schuur wireless.js[737]: WIRELESS: No wireless interface, exiting Jun 23 11:42:40 schuur systemd[1]: wireless.service: control process exited, code=exited status=1 Jun 23 11:42:40 schuur systemd[1]: Failed to start Wireless Services. Jun 23 11:42:40 schuur systemd[1]: Unit wireless.service entered failed state. Jun 23 11:42:41 schuur systemd[1]: Starting Volumio Backend Module... Jun 23 11:42:41 schuur systemd[1]: Started Volumio Backend Module. Jun 23 11:42:41 schuur systemd[1]: Starting Volumio Streaming Daemon... Jun 23 11:42:41 schuur systemd[1]: Started Volumio Streaming Daemon. Jun 23 11:42:41 schuur systemd[1]: Started Music Player Daemon. Jun 23 11:42:41 schuur volumio-streaming-daemon[787]: ############################ Jun 23 11:42:41 schuur volumio-streaming-daemon[787]: # Volumio Streaming Daemon # Jun 23 11:42:41 schuur volumio-streaming-daemon[787]: # Running on port 7777 # Jun 23 11:42:41 schuur volumio-streaming-daemon[787]: ############################ Jun 23 11:42:41 schuur volumio-streaming-daemon[787]: Environment: production Jun 23 11:43:05 schuur systemd[1]: Time has been changed Jun 23 11:43:05 schuur systemd[1]: Started LSB: start Samba daemons for the AD DC. Jun 23 11:43:06 schuur winbind[605]: Starting the Winbind daemon: winbindmkdir failed on directory /var/log/samba/cores: No such file or directory Jun 23 11:43:06 schuur winbind[605]: Failed to create /var/log/samba/cores for user 0 with mode 0700 Jun 23 11:43:06 schuur winbind[605]: Unable to setup corepath for winbindd: No such file or directory Jun 23 11:43:06 schuur winbind[605]: mkdir failed on directory /var/log/samba/cores: No such file or directory Jun 23 11:43:06 schuur winbind[605]: Failed to create /var/log/samba/cores for user 0 with mode 0700 Jun 23 11:43:06 schuur winbind[605]: Unable to setup corepath for winbindd: No such file or directory Jun 23 11:43:06 schuur winbind[605]: [2021/06/23 11:43:06, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:06 schuur winbind[605]: Unable to open new log file '/var/log/samba/log.winbindd': No such file or directory Jun 23 11:43:06 schuur winbind[605]: [2021/06/23 11:43:06, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:06 schuur winbind[605]: Unable to open new log file '/var/log/samba/log.winbindd': No such file or directory Jun 23 11:43:06 schuur winbind[605]: [2021/06/23 11:43:06, 0] ../source3/winbindd/winbindd.c:1549(main) Jun 23 11:43:06 schuur winbind[605]: winbindd version 4.2.14-Debian started. Jun 23 11:43:06 schuur winbind[605]: Copyright Andrew Tridgell and the Samba Team 1992-2014 Jun 23 11:43:06 schuur winbind[605]: [2021/06/23 11:43:06, 0] ../lib/util/util.c:220(directory_create_or_exist) Jun 23 11:43:06 schuur winbind[605]: mkdir failed on directory /var/log/samba/cores: No such file or directory Jun 23 11:43:06 schuur winbind[605]: [2021/06/23 11:43:06, 0] ../source3/lib/dumpcore.c:59(get_default_corepath) Jun 23 11:43:06 schuur winbind[605]: Failed to create /var/log/samba/cores for user 0 with mode 0700 Jun 23 11:43:06 schuur winbind[605]: [2021/06/23 11:43:06, 0] ../source3/lib/dumpcore.c:250(dump_core_setup) Jun 23 11:43:06 schuur winbind[605]: Unable to setup corepath for winbindd: No such file or directory Jun 23 11:43:06 schuur winbindd[809]: [2021/06/23 11:43:06.138130, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:06 schuur winbindd[809]: Unable to open new log file '/var/log/samba/log.winbindd': No such file or directory Jun 23 11:43:06 schuur winbindd[809]: [2021/06/23 11:43:06.140465, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:06 schuur winbindd[809]: Unable to open new log file '/var/log/samba/log.winbindd': No such file or directory Jun 23 11:43:06 schuur winbind[605]: [2021/06/23 11:43:06.138130, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:06 schuur winbind[605]: Unable to open new log file '/var/log/samba/log.winbindd': No such file or directory Jun 23 11:43:06 schuur winbind[605]: [2021/06/23 11:43:06.140465, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:06 schuur winbind[605]: Unable to open new log file '/var/log/samba/log.winbindd': No such file or directory Jun 23 11:43:06 schuur nmbd[812]: [2021/06/23 11:43:06.153628, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:06 schuur nmbd[812]: Unable to open new log file '/var/log/samba/log.nmbd': No such file or directory Jun 23 11:43:06 schuur nmbd[812]: [2021/06/23 11:43:06.157406, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:06 schuur nmbd[812]: Unable to open new log file '/var/log/samba/log.nmbd': No such file or directory Jun 23 11:43:06 schuur nmbd[813]: [2021/06/23 11:43:06.165046, 0] ../source3/nmbd/asyncdns.c:157(start_async_dns) Jun 23 11:43:06 schuur nmbd[813]: started asyncdns process 814 Jun 23 11:43:06 schuur systemd[1]: Started LSB: start Winbind daemon. Jun 23 11:43:06 schuur systemd[1]: Started LSB: start Samba NetBIOS nameserver (nmbd). Jun 23 11:43:06 schuur systemd[1]: Starting LSB: start Samba SMB/CIFS daemon (smbd)... Jun 23 11:43:06 schuur winbindd[815]: [2021/06/23 11:43:06.181606, 0] ../source3/winbindd/winbindd_cache.c:3235(initialize_winbindd_cache) Jun 23 11:43:06 schuur winbindd[815]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Jun 23 11:43:06 schuur nmbd[616]: Starting NetBIOS name server: nmbdmkdir failed on directory /var/log/samba/cores: No such file or directory Jun 23 11:43:06 schuur nmbd[616]: Failed to create /var/log/samba/cores for user 0 with mode 0700 Jun 23 11:43:06 schuur nmbd[616]: Unable to setup corepath for nmbd: No such file or directory Jun 23 11:43:06 schuur nmbd[616]: [2021/06/23 11:43:06, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:06 schuur nmbd[616]: Unable to open new log file '/var/log/samba/log.nmbd': No such file or directory Jun 23 11:43:06 schuur nmbd[616]: [2021/06/23 11:43:06, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:06 schuur nmbd[616]: Unable to open new log file '/var/log/samba/log.nmbd': No such file or directory Jun 23 11:43:06 schuur nmbd[616]: [2021/06/23 11:43:06, 0] ../source3/nmbd/nmbd.c:908(main) Jun 23 11:43:06 schuur nmbd[616]: nmbd version 4.2.14-Debian started. Jun 23 11:43:06 schuur nmbd[616]: Copyright Andrew Tridgell and the Samba Team 1992-2014 Jun 23 11:43:06 schuur nmbd[616]: [2021/06/23 11:43:06.153628, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:06 schuur nmbd[616]: Unable to open new log file '/var/log/samba/log.nmbd': No such file or directory Jun 23 11:43:06 schuur nmbd[616]: [2021/06/23 11:43:06.157406, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:06 schuur nmbd[616]: Unable to open new log file '/var/log/samba/log.nmbd': No such file or directory Jun 23 11:43:06 schuur nmbd[813]: [2021/06/23 11:43:06.202513, 0] ../lib/util/become_daemon.c:124(daemon_ready) Jun 23 11:43:06 schuur nmbd[813]: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Jun 23 11:43:06 schuur winbind[605]: . Jun 23 11:43:06 schuur nmbd[616]: . Jun 23 11:43:06 schuur winbindd[815]: [2021/06/23 11:43:06.253124, 0] ../lib/util/become_daemon.c:124(daemon_ready) Jun 23 11:43:06 schuur winbindd[815]: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Jun 23 11:43:06 schuur winbindd[823]: [2021/06/23 11:43:06.263847, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:06 schuur winbindd[823]: Unable to open new log file '/var/log/samba/log.wb-SCHUUR': No such file or directory Jun 23 11:43:08 schuur smbd[816]: Starting SMB/CIFS daemon: smbd[2021/06/23 11:43:08, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:08 schuur smbd[816]: Unable to open new log file '/var/log/samba/log.smbd': No such file or directory Jun 23 11:43:08 schuur smbd[816]: [2021/06/23 11:43:08, 0] ../lib/util/util.c:220(directory_create_or_exist) Jun 23 11:43:08 schuur smbd[816]: mkdir failed on directory /var/log/samba/cores: No such file or directory Jun 23 11:43:08 schuur smbd[816]: [2021/06/23 11:43:08, 0] ../source3/lib/dumpcore.c:59(get_default_corepath) Jun 23 11:43:08 schuur smbd[816]: Failed to create /var/log/samba/cores for user 0 with mode 0700 Jun 23 11:43:08 schuur smbd[816]: [2021/06/23 11:43:08, 0] ../source3/lib/dumpcore.c:250(dump_core_setup) Jun 23 11:43:08 schuur smbd[816]: Unable to setup corepath for smbd: No such file or directory Jun 23 11:43:08 schuur smbd[816]: [2021/06/23 11:43:08, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:08 schuur smbd[816]: Unable to open new log file '/var/log/samba/log.smbd': No such file or directory Jun 23 11:43:08 schuur smbd[816]: [2021/06/23 11:43:08, 0] ../source3/smbd/server.c:1241(main) Jun 23 11:43:08 schuur smbd[816]: smbd version 4.2.14-Debian started. Jun 23 11:43:08 schuur smbd[816]: Copyright Andrew Tridgell and the Samba Team 1992-2014 Jun 23 11:43:08 schuur smbd[827]: [2021/06/23 11:43:08.401354, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:08 schuur smbd[827]: Unable to open new log file '/var/log/samba/log.smbd': No such file or directory Jun 23 11:43:08 schuur smbd[827]: [2021/06/23 11:43:08.404853, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:08 schuur smbd[827]: Unable to open new log file '/var/log/samba/log.smbd': No such file or directory Jun 23 11:43:08 schuur smbd[827]: [2021/06/23 11:43:08.405651, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:08 schuur smbd[827]: Unable to open new log file '/var/log/samba/log.smbd': No such file or directory Jun 23 11:43:08 schuur smbd[816]: [2021/06/23 11:43:08.401354, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:08 schuur smbd[816]: Unable to open new log file '/var/log/samba/log.smbd': No such file or directory Jun 23 11:43:08 schuur smbd[816]: [2021/06/23 11:43:08.404853, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:08 schuur smbd[816]: Unable to open new log file '/var/log/samba/log.smbd': No such file or directory Jun 23 11:43:08 schuur smbd[816]: [2021/06/23 11:43:08.405651, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:08 schuur smbd[816]: Unable to open new log file '/var/log/samba/log.smbd': No such file or directory Jun 23 11:43:08 schuur smbd[816]: . Jun 23 11:43:08 schuur systemd[1]: Started LSB: start Samba SMB/CIFS daemon (smbd). Jun 23 11:43:08 schuur systemd[1]: Starting Multi-User System. Jun 23 11:43:08 schuur systemd[1]: Reached target Multi-User System. Jun 23 11:43:08 schuur systemd[1]: Starting Graphical Interface. Jun 23 11:43:08 schuur systemd[1]: Reached target Graphical Interface. Jun 23 11:43:08 schuur systemd[1]: Starting Update UTMP about System Runlevel Changes... Jun 23 11:43:08 schuur systemd[1]: Started Update UTMP about System Runlevel Changes. Jun 23 11:43:08 schuur systemd[1]: Startup finished in 10.135s (kernel) + 22.102s (userspace) = 32.237s. Jun 23 11:43:08 schuur winbindd[834]: [2021/06/23 11:43:08.532287, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:08 schuur winbindd[834]: Unable to open new log file '/var/log/samba/log.winbindd-idmap': No such file or directory Jun 23 11:43:08 schuur winbindd[835]: [2021/06/23 11:43:08.649599, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:08 schuur winbindd[835]: Unable to open new log file '/var/log/samba/log.wb-BUILTIN': No such file or directory Jun 23 11:43:08 schuur smbd[828]: [2021/06/23 11:43:08.749189, 0] ../lib/util/become_daemon.c:124(daemon_ready) Jun 23 11:43:08 schuur smbd[828]: STATUS=daemon 'smbd' finished starting up and ready to serve connections Jun 23 11:43:08 schuur smbd[836]: [2021/06/23 11:43:08.759970, 0] ../lib/util/debug.c:603(reopen_logs_internal) Jun 23 11:43:08 schuur smbd[836]: Unable to open new log file '/var/log/samba/log.smbd': No such file or directory Jun 23 11:43:10 schuur volumio-remote-updater[596]: [2021-06-23 11:43:10] [connect] Successful connection Jun 23 11:43:10 schuur volumio[786]: info: ------------------------------------------- Jun 23 11:43:10 schuur volumio[786]: info: ----- Volumio2 ---- Jun 23 11:43:10 schuur volumio[786]: info: ------------------------------------------- Jun 23 11:43:10 schuur volumio[786]: info: ----- System startup ---- Jun 23 11:43:10 schuur volumio[786]: info: ------------------------------------------- Jun 23 11:43:11 schuur kernel: Voltage normalised (0x00000000) Jun 23 11:43:12 schuur volumio[786]: info: MYVOLUMIO Environment detected Jun 23 11:43:13 schuur volumio[786]: info: Plugin folders cleanup Jun 23 11:43:13 schuur volumio[786]: info: Scanning into folder /volumio/app/plugins/ Jun 23 11:43:13 schuur volumio[786]: info: Scanning category audio_interface Jun 23 11:43:13 schuur volumio[786]: info: Scanning category miscellanea Jun 23 11:43:13 schuur volumio[786]: info: Scanning category music_service Jun 23 11:43:13 schuur volumio[786]: info: Scanning category plugins.json Jun 23 11:43:13 schuur volumio[786]: info: Scanning category system_controller Jun 23 11:43:13 schuur volumio[786]: info: Scanning category user_interface Jun 23 11:43:13 schuur volumio[786]: info: Scanning into folder /data/plugins/ Jun 23 11:43:13 schuur volumio[786]: info: Scanning category music_service Jun 23 11:43:13 schuur volumio[786]: info: Plugin folders cleanup completed Jun 23 11:43:13 schuur volumio[786]: info: ------------------------------------------- Jun 23 11:43:13 schuur volumio[786]: info: ----- Core plugins startup ---- Jun 23 11:43:13 schuur volumio[786]: info: ------------------------------------------- Jun 23 11:43:13 schuur volumio[786]: info: Loading plugins from folder /volumio/app/plugins/ Jun 23 11:43:13 schuur volumio[786]: info: Adding plugin upnp to MyMusic Plugins Jun 23 11:43:13 schuur volumio[786]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 23 11:43:13 schuur volumio[786]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 23 11:43:13 schuur volumio[786]: info: Loading plugins from folder /data/plugins/ Jun 23 11:43:13 schuur volumio[786]: info: Loading plugin "system"... Jun 23 11:43:13 schuur volumio[786]: info: Loading plugin "appearance"... Jun 23 11:43:15 schuur kernel: Under-voltage detected! (0x00050005) Jun 23 11:43:18 schuur volumio[786]: info: Loading plugin "network"... Jun 23 11:43:19 schuur volumio[786]: info: Refreshing Cached IP Addresses Jun 23 11:43:19 schuur volumio[786]: info: Loading plugin "services"... Jun 23 11:43:19 schuur sudo[849]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 23 11:43:19 schuur volumio[786]: info: Loading plugin "alsa_controller"... Jun 23 11:43:19 schuur sudo[849]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:43:19 schuur sudo[851]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 23 11:43:19 schuur sudo[851]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:43:19 schuur sudo[849]: pam_unix(sudo:session): session closed for user root Jun 23 11:43:19 schuur sudo[851]: pam_unix(sudo:session): session closed for user root Jun 23 11:43:19 schuur volumio[786]: info: Loading plugin "wizard"... Jun 23 11:43:19 schuur volumio[786]: info: Loading plugin "volumio_command_line_client"... Jun 23 11:43:19 schuur volumio[786]: info: Loading plugin "upnp"... Jun 23 11:43:19 schuur volumio[786]: info: [1624448599603] Starting Upmpd Daemon Jun 23 11:43:19 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 23 11:43:19 schuur volumio[786]: info: Loading plugin "my_music"... Jun 23 11:43:19 schuur volumio[786]: info: Loading plugin "mpd"... Jun 23 11:43:21 schuur volumio[786]: info: Loading plugin "upnp_browser"... Jun 23 11:43:22 schuur volumio[786]: info: Loading plugin "networkfs"... Jun 23 11:43:22 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 23 11:43:22 schuur volumio[786]: info: Loading plugin "alarm-clock"... Jun 23 11:43:23 schuur volumio[786]: info: Loading plugin "airplay_emulation"... Jun 23 11:43:23 schuur volumio[786]: info: Starting Shairport Sync Jun 23 11:43:23 schuur volumio[786]: info: Loading plugin "last_100"... Jun 23 11:43:23 schuur volumio[786]: info: Loading plugin "webradio"... Jun 23 11:43:23 schuur volumio[786]: info: Loading plugin "i2s_dacs"... Jun 23 11:43:23 schuur volumio[786]: info: I2S DAC not set, start Auto-detection Jun 23 11:43:23 schuur volumio[786]: info: Loading plugin "volumiodiscovery"... Jun 23 11:43:23 schuur volumio[786]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 23 11:43:23 schuur node[786]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 23 11:43:23 schuur node[786]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 23 11:43:23 schuur node[786]: *** WARNING *** For more information see Jun 23 11:43:23 schuur node[786]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 23 11:43:23 schuur node[786]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 23 11:43:23 schuur node[786]: *** WARNING *** For more information see Jun 23 11:43:23 schuur volumio[786]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 23 11:43:23 schuur volumio[786]: *** WARNING *** For more information see Jun 23 11:43:23 schuur volumio[786]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 23 11:43:23 schuur volumio[786]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 23 11:43:23 schuur volumio[786]: *** WARNING *** For more information see Jun 23 11:43:23 schuur volumio[786]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 23 11:43:23 schuur volumio[786]: Discovery: StartAdv! undefined Jun 23 11:43:23 schuur volumio[786]: Discovery: Started advertising... Schuur - undefined Jun 23 11:43:23 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 23 11:43:23 schuur volumio[786]: info: Loading plugin "outputs"... Jun 23 11:43:23 schuur volumio[786]: info: Loading plugin "albumart"... Jun 23 11:43:23 schuur volumio[786]: info: Plugin example_plugin is not enabled Jun 23 11:43:23 schuur volumio[786]: info: Loading plugin "inputs"... Jun 23 11:43:23 schuur volumio[786]: info: Loading plugin "updater_comm"... Jun 23 11:43:24 schuur volumio[786]: info: Plugin mpdemulation is not enabled Jun 23 11:43:24 schuur volumio[786]: info: Loading plugin "rest_api"... Jun 23 11:43:24 schuur volumio[786]: info: Loading plugin "websocket"... Jun 23 11:43:24 schuur volumio[786]: info: Loading plugin "volspotconnect2"... Jun 23 11:43:24 schuur volumio[786]: Forking 3 albumart workers Jun 23 11:43:25 schuur volumio-remote-updater[596]: [2021-06-23 11:43:25] [connect] Successful connection Jun 23 11:43:26 schuur volumio[786]: Starting albumart workers Jun 23 11:43:26 schuur volumio[786]: Starting albumart workers Jun 23 11:43:27 schuur volumio[786]: Starting albumart workers Jun 23 11:43:27 schuur volumio[786]: info: ___________ START PLUGINS ___________ Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 23 11:43:27 schuur volumio[786]: info: [1624448607097] CoreMusicLibrary::Adding element Media Servers Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 23 11:43:27 schuur volumio[786]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 23 11:43:27 schuur volumio[786]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 23 11:43:27 schuur volumio[786]: info: [1624448607545] CoreMusicLibrary::Adding element Last_100 Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 23 11:43:27 schuur volumio[786]: info: [1624448607558] CoreMusicLibrary::Adding element Webradio Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 23 11:43:27 schuur volumio[786]: [SpotifyConnect] Creating VLS config file Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:43:27 schuur volumio[786]: [SpotifyConnect] Starting metadata listener Jun 23 11:43:27 schuur volumio[786]: info: ------------------------------------------- Jun 23 11:43:27 schuur volumio[786]: info: ----- MyVolumio plugins startup ---- Jun 23 11:43:27 schuur volumio[786]: info: ------------------------------------------- Jun 23 11:43:27 schuur volumio[786]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 23 11:43:27 schuur sudo[911]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volspotconnect2.service Jun 23 11:43:27 schuur volumio[786]: info: Loading i18n strings for locale nl Jun 23 11:43:27 schuur volumio[786]: Updating browse sources language Jun 23 11:43:27 schuur volumio[786]: Cannot find translation for sourceMedia Servers Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 23 11:43:27 schuur sudo[911]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::initPlayerControls Jun 23 11:43:27 schuur systemd[1]: Starting Volspotconnect2 Daemon... Jun 23 11:43:27 schuur systemd[1]: Started Volspotconnect2 Daemon. Jun 23 11:43:27 schuur sudo[911]: pam_unix(sudo:session): session closed for user root Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:43:27 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getAlsaCards Jun 23 11:43:28 schuur volumio[916]: vollibrespot v0.2.2 cd96399 2020-10-07 (librespot 08d8bcc 2020-10-07) -- Built On 2020-10-07 Jun 23 11:43:28 schuur volumio[916]: Reading Config from "volspotify.toml" Jun 23 11:43:28 schuur volumio[916]: [Vollibrespot] : Using Alsa backend with device: plughw:1 Jun 23 11:43:28 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:43:28 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:43:28 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:43:28 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:43:28 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:43:28 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 23 11:43:28 schuur volumio[786]: info: BOOT COMPLETED Jun 23 11:43:28 schuur volumio[786]: [Metrics] CommandRouter: 17s 391.64ms Jun 23 11:43:28 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 23 11:43:28 schuur volumio[916]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" } Jun 23 11:43:33 schuur volumio[786]: Playing WAVE '/volumio/app/startup.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo Jun 23 11:43:33 schuur volumio[786]: info: CoreCommandRouter::Close All Modals sent Jun 23 11:43:33 schuur volumio[786]: info: CoreCommandRouter::Close All Modals sent Jun 23 11:43:33 schuur volumio[786]: Express server listening on port 3000 Jun 23 11:43:33 schuur volumio[786]: [Metrics] WebUI: 24s 231.35ms Jun 23 11:43:33 schuur volumio[786]: Volumio Calling Home Jun 23 11:43:33 schuur volumio[786]: info: CoreStateMachine::resetVolumioState Jun 23 11:43:33 schuur volumio[786]: info: CoreStateMachine::getcurrentVolume Jun 23 11:43:33 schuur volumio[786]: info: CoreCommandRouter::volumioRetrievevolume Jun 23 11:43:34 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 23 11:43:34 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:43:34 schuur sudo[957]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 23 11:43:34 schuur kernel: Voltage normalised (0x00000000) Jun 23 11:43:34 schuur sudo[957]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:43:34 schuur sudo[959]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 23 11:43:34 schuur sudo[957]: pam_unix(sudo:session): session closed for user root Jun 23 11:43:34 schuur sudo[959]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:43:34 schuur sudo[959]: pam_unix(sudo:session): session closed for user root Jun 23 11:43:34 schuur volumio[786]: info: Cannot read play queue from file Jun 23 11:43:34 schuur volumio[786]: info: Volumio called home Jun 23 11:43:34 schuur volumio[786]: info: Setting Device type: Raspberry PI Jun 23 11:43:34 schuur volumio[786]: [SpotifyConnect] Vollibrespot Daemon service started! Jun 23 11:43:34 schuur volumio[786]: [Metrics] SpotifyConnect: 7s 325.95ms Jun 23 11:43:34 schuur volumio[786]: info: MPD running with PID643 Jun 23 11:43:34 schuur volumio[786]: ,establishing connection Jun 23 11:43:35 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Jun 23 11:43:35 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jun 23 11:43:35 schuur sudo[978]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cdetect -y 1 Jun 23 11:43:35 schuur sudo[978]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:43:35 schuur sudo[978]: pam_unix(sudo:session): session closed for user root Jun 23 11:43:35 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Jun 23 11:43:35 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 23 11:43:35 schuur volumio[786]: info: VolumeController:: Volume=26 Mute =false Jun 23 11:43:35 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:43:35 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:43:35 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:43:35 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:43:35 schuur volumio[786]: info: CoreStateMachine::updateTrackBlock Jun 23 11:43:35 schuur volumio[786]: info: CorePlayQueue::getTrackBlock Jun 23 11:43:35 schuur volumio[786]: info: CoreCommandRouter::volumioRetrievevolume Jun 23 11:43:36 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:43:36 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:43:36 schuur volumio[786]: error: updateQueue error: null Jun 23 11:43:36 schuur volumio[786]: error: Failed LSINFO: Error: [50@0] {} No such directory Jun 23 11:43:36 schuur volumio[786]: info: CoreStateMachine::setRepeat null single undefined Jun 23 11:43:36 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:43:36 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:43:36 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:43:36 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:43:36 schuur volumio[786]: info: CoreStateMachine::setRandom null Jun 23 11:43:36 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:43:36 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:43:36 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:43:36 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:43:36 schuur volumio[786]: Discovery: Changing my name to schuur CINGHIALE is undefined Jun 23 11:43:36 schuur volumio[786]: info: CoreCommandRouter::volumioGetQueue Jun 23 11:43:36 schuur volumio[786]: info: CoreStateMachine::getQueue Jun 23 11:43:36 schuur volumio[786]: info: CorePlayQueue::getQueue Jun 23 11:43:36 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getHwuuid Jun 23 11:43:36 schuur volumio[786]: info: VolumeController:: Volume=26 Mute =false Jun 23 11:43:36 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:43:36 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:43:36 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:43:36 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:43:36 schuur volumio[786]: info: Starting Shairport Sync Jun 23 11:43:37 schuur volumio[786]: info: Starting Shairport Sync Jun 23 11:43:37 schuur sudo[992]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 23 11:43:37 schuur sudo[992]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:43:37 schuur sudo[994]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 23 11:43:37 schuur systemd[1]: Starting UPnP Renderer front-end to MPD... Jun 23 11:43:37 schuur systemd[1]: Started UPnP Renderer front-end to MPD. Jun 23 11:43:37 schuur sudo[994]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:43:37 schuur sudo[999]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 23 11:43:37 schuur sudo[992]: pam_unix(sudo:session): session closed for user root Jun 23 11:43:37 schuur sudo[999]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:43:37 schuur systemd[1]: Starting Shairport Sync - AirPlay Audio Receiver... Jun 23 11:43:37 schuur systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 23 11:43:37 schuur sudo[994]: pam_unix(sudo:session): session closed for user root Jun 23 11:43:37 schuur systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 23 11:43:37 schuur systemd[1]: Starting Shairport Sync - AirPlay Audio Receiver... Jun 23 11:43:37 schuur sudo[999]: pam_unix(sudo:session): session closed for user root Jun 23 11:43:37 schuur systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 23 11:43:37 schuur volumio[786]: Discovery: adding c354d6a7-9ce0-4f43-8e7a-2557b4f2d81e Jun 23 11:43:37 schuur volumio[786]: info: mDNS: Found device Schuur Jun 23 11:43:37 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:43:37 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:43:37 schuur volumio[786]: info: Upmpdcli Daemon Started Jun 23 11:43:37 schuur volumio[786]: info: Shairport-Sync Started Jun 23 11:43:37 schuur volumio[786]: Error adding Membership: Error: addMembership EINVAL Jun 23 11:43:37 schuur volumio[786]: info: Shairport-Sync Started Jun 23 11:43:37 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:43:37 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jun 23 11:43:37 schuur volumio[786]: info: Adding plugin bluetooth to MyMusic Plugins Jun 23 11:43:37 schuur volumio[786]: info: Adding plugin cd_controller to MyMusic Plugins Jun 23 11:43:37 schuur volumio[786]: info: Adding plugin smart_inputs to MyMusic Plugins Jun 23 11:43:37 schuur volumio[786]: info: Adding plugin tidalconnect to MyMusic Plugins Jun 23 11:43:37 schuur volumio[786]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jun 23 11:43:39 schuur volumio[786]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jun 23 11:43:40 schuur volumio-remote-updater[596]: [2021-06-23 11:43:40] [connect] Successful connection Jun 23 11:43:40 schuur volumio[786]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jun 23 11:43:40 schuur volumio[786]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jun 23 11:43:40 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 23 11:43:40 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 23 11:43:40 schuur volumio[786]: info: Starting MyVolumio Remote Streaming Endpoints Jun 23 11:43:40 schuur volumio[786]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jun 23 11:43:40 schuur volumio[786]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jun 23 11:43:40 schuur volumio[786]: info: Streaming services startup Jun 23 11:43:40 schuur volumio[786]: info: Starting Streaming Daemon Jun 23 11:43:40 schuur sudo[1032]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 23 11:43:40 schuur sudo[1032]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:43:40 schuur volumio[786]: info: MyVolumio not started Jun 23 11:43:40 schuur volumio[786]: info: Initializing device activation check Jun 23 11:43:40 schuur volumio[786]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jun 23 11:43:40 schuur systemd[1]: Stopping Volumio Streaming Daemon... Jun 23 11:43:40 schuur systemd[1]: Starting Volumio Streaming Daemon... Jun 23 11:43:40 schuur systemd[1]: Started Volumio Streaming Daemon. Jun 23 11:43:40 schuur sudo[1032]: pam_unix(sudo:session): session closed for user root Jun 23 11:43:40 schuur volumio-streaming-daemon[1042]: ############################ Jun 23 11:43:40 schuur volumio-streaming-daemon[1042]: # Volumio Streaming Daemon # Jun 23 11:43:40 schuur volumio-streaming-daemon[1042]: # Running on port 7777 # Jun 23 11:43:40 schuur volumio-streaming-daemon[1042]: ############################ Jun 23 11:43:40 schuur volumio-streaming-daemon[1042]: Environment: production Jun 23 11:43:41 schuur volumio[786]: info: mDNS: A device disapperared from network Jun 23 11:43:41 schuur volumio[786]: info: mDNS: Device schuur disapperared from network Jun 23 11:43:41 schuur volumio-remote-updater[596]: [2021-06-23 11:43:41] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.5.1" /socket.io/?EIO=4&transport=websocket&t=1624448620 101 Jun 23 11:43:42 schuur sudo[1066]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 23 11:43:42 schuur sudo[1066]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:43:42 schuur sudo[1068]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 23 11:43:42 schuur sudo[1066]: pam_unix(sudo:session): session closed for user root Jun 23 11:43:42 schuur sudo[1068]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:43:42 schuur sudo[1068]: pam_unix(sudo:session): session closed for user root Jun 23 11:43:42 schuur sudo[1086]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 23 11:43:42 schuur sudo[1086]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:43:42 schuur sudo[1088]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 23 11:43:42 schuur sudo[1086]: pam_unix(sudo:session): session closed for user root Jun 23 11:43:42 schuur sudo[1088]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:43:42 schuur sudo[1088]: pam_unix(sudo:session): session closed for user root Jun 23 11:43:42 schuur volumio[786]: Discovery: adding c354d6a7-9ce0-4f43-8e7a-2557b4f2d81e Jun 23 11:43:42 schuur volumio[786]: info: mDNS: Found device schuur Jun 23 11:43:42 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:43:42 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:43:43 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:43:43 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:43:43 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 23 11:43:43 schuur volumio[786]: info: CoreCommandRouter::volumioGetVisibleSources Jun 23 11:43:43 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 23 11:43:43 schuur volumio[786]: info: Listing playlists Jun 23 11:43:43 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 23 11:43:43 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 23 11:43:43 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 23 11:43:43 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 23 11:43:43 schuur volumio-streaming-daemon[1042]: Environment: production Jun 23 11:43:43 schuur volumio[786]: info: Fetching Streaming Services browse cache Jun 23 11:43:45 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 23 11:43:48 schuur volumio[916]: [Vollibrespot] : Connecting to AP "gew1-accesspoint-a-d460.ap.spotify.com:443" Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : Authenticated as "21hptgkjwzcroc6eo5gh3whki" ! Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : Setting up new mixer: card:hw:1 mixer:Headphone index:0 Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : Alsa Mixer info min: -10239 (MilliBel(-9999999)[dB]) -- max: 400 (MilliBel(400)[dB]) HW: true Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : Using alsa sink Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : Metadata pipe established Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : Country: "NL" Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : Event: Volume { volume_to_mixer: 0 } Jun 23 11:43:49 schuur volumio[786]: [SpotifyConnect] 0 Jun 23 11:43:49 schuur volumio[786]: [SpotifyConnect] Volume: Spotify:0 Volumio: 0 Jun 23 11:43:49 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:43:49 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : Fetching autoplay context uri Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : Event: SessionActive { became_active_at: 1624448629491 } Jun 23 11:43:49 schuur volumio[786]: [SpotifyConnect] A connect session has begun Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : SessionActive! Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 326796467406114409174184022292929984107, audio_type: Track } } Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 326796467406114409174184022292929984107, audio_type: Track } } Jun 23 11:43:49 schuur volumio[786]: [SpotifyConnect] Device palyback is active! Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:43:49 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:43:49 schuur volumio[786]: [SpotifyConnect] Currently active: mpd Jun 23 11:43:49 schuur volumio[786]: [SpotifyConnect] Stopping currently active service Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::volumioStop Jun 23 11:43:49 schuur volumio[786]: info: CoreStateMachine::stop Jun 23 11:43:49 schuur volumio[786]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 23 11:43:49 schuur volumio[786]: UNSET VOLATILE Jun 23 11:43:49 schuur volumio[786]: [SpotifyConnect] Vollibrespot Active Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:43:49 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:43:49 schuur volumio[786]: [SpotifyConnect] Currently active: mpd Jun 23 11:43:49 schuur volumio[786]: [SpotifyConnect] Setting Volatile state to Volspotconnect2 Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : error 403 for uri hm://keymaster/token/authenticated?client_id=4ced2e7c73484127be5d36015752eb43&scope=streaming,user-read-playback-state,user-modify-playback-state,user-read-currently-playing,user-read-private Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : Error: MercuryError Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : Autoplay uri resolved to <"spotify:station:playlist:37i9dQZF1E35NtXBZ3bCCn"> Jun 23 11:43:49 schuur volumio[916]: [Vollibrespot] : Resolving uri "spotify:station:playlist:37i9dQZF1E35NtXBZ3bCCn" Jun 23 11:43:49 schuur volumio[916]: thread 'main' panicked at 'cannot poll Map twice', /build/cache/registry/src/github.com-1ecc6299db9ec823/futures-0.1.29/src/future/map.rs:35:29 Jun 23 11:43:49 schuur volumio[916]: stack backtrace: Jun 23 11:43:49 schuur volumio[786]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:43:49 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:43:49 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:43:49 schuur volumio[786]: verbose: STATE SERVICE {"status":"stop","service":"volspotconnect2","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2} Jun 23 11:43:49 schuur volumio[786]: verbose: CURRENT POSITION 0 Jun 23 11:43:49 schuur volumio[786]: info: CoreStateMachine::syncState stateService stop Jun 23 11:43:49 schuur volumio[786]: info: CoreStateMachine::syncState currentStatus stop Jun 23 11:43:49 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:43:49 schuur volumio[786]: info: No code Jun 23 11:43:49 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:43:49 schuur volumio[786]: [SpotifyConnect] Currently active: undefined Jun 23 11:43:49 schuur volumio[786]: [SpotifyConnect] Pushing new state :: true Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:43:49 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:43:49 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:43:49 schuur volumio[786]: verbose: STATE SERVICE {"status":"stop","service":"volspotconnect2","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2} Jun 23 11:43:49 schuur volumio[786]: verbose: CURRENT POSITION 0 Jun 23 11:43:49 schuur volumio[786]: info: CoreStateMachine::syncState stateService stop Jun 23 11:43:49 schuur volumio[786]: info: CoreStateMachine::syncState currentStatus stop Jun 23 11:43:49 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:43:49 schuur volumio[786]: info: No code Jun 23 11:43:49 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:43:49 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:43:50 schuur volumio[916]: 0: 0x9cb33c - backtrace::backtrace::libunwind::trace::hae21a072c81e5842 Jun 23 11:43:50 schuur volumio[916]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86 Jun 23 11:43:50 schuur volumio[916]: 1: 0x9cb33c - backtrace::backtrace::trace_unsynchronized::h0f9b260087e46e47 Jun 23 11:43:50 schuur volumio[916]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66 Jun 23 11:43:50 schuur volumio[916]: 2: 0x9cb33c - std::sys_common::backtrace::_print_fmt::hbf1a59173a7860c3 Jun 23 11:43:50 schuur volumio[916]: at src/libstd/sys_common/backtrace.rs:78 Jun 23 11:43:50 schuur volumio[916]: 3: 0x9cb33c - ::fmt::he1a5d6f378e506c4 Jun 23 11:43:50 schuur volumio[916]: at src/libstd/sys_common/backtrace.rs:59 Jun 23 11:43:50 schuur volumio[916]: 4: 0x9ebd5c - core::fmt::write::hb37ae5a5e0b70623 Jun 23 11:43:50 schuur volumio[916]: at src/libcore/fmt/mod.rs:1076 Jun 23 11:43:50 schuur volumio[916]: 5: 0x9c4c64 - std::io::Write::write_fmt::ha24bb3f5a858327b Jun 23 11:43:50 schuur volumio[916]: at src/libstd/io/mod.rs:1537 Jun 23 11:43:50 schuur volumio[916]: 6: 0x9cd974 - std::sys_common::backtrace::_print::h47b03aa1342833e3 Jun 23 11:43:50 schuur volumio[916]: at src/libstd/sys_common/backtrace.rs:62 Jun 23 11:43:50 schuur volumio[916]: 7: 0x9cd974 - std::sys_common::backtrace::print::h2217cbc390250439 Jun 23 11:43:50 schuur volumio[916]: at src/libstd/sys_common/backtrace.rs:49 Jun 23 11:43:50 schuur volumio[916]: 8: 0x9cd974 - std::panicking::default_hook::{{closure}}::h179f5229ea1c8e30 Jun 23 11:43:50 schuur volumio[916]: at src/libstd/panicking.rs:198 Jun 23 11:43:50 schuur volumio[916]: 9: 0x9cd640 - std::panicking::default_hook::h46ab82039cbc65eb Jun 23 11:43:50 schuur volumio[916]: at src/libstd/panicking.rs:217 Jun 23 11:43:50 schuur volumio[916]: 10: 0x9ce054 - std::panicking::rust_panic_with_hook::h7326c48419bc7c33 Jun 23 11:43:50 schuur volumio[916]: at src/libstd/panicking.rs:526 Jun 23 11:43:50 schuur volumio[916]: 11: 0x9cdc54 - rust_begin_unwind Jun 23 11:43:50 schuur volumio[916]: at src/libstd/panicking.rs:437 Jun 23 11:43:50 schuur volumio[916]: 12: 0x9e9594 - core::panicking::panic_fmt::ha292e19d5ae716ed Jun 23 11:43:50 schuur volumio[916]: at src/libcore/panicking.rs:85 Jun 23 11:43:50 schuur volumio[916]: 13: 0x9e9370 - core::option::expect_failed::he9e39f8f5ba60ecb Jun 23 11:43:50 schuur volumio[916]: at src/libcore/option.rs:1261 Jun 23 11:43:50 schuur volumio[916]: 14: 0x6bfbf8 - as futures::future::Future>::poll::h3d56b212ca27d9e4 Jun 23 11:43:50 schuur volumio[916]: 15: 0x5753a4 - ::poll::ha2e91a6b75c719f3 Jun 23 11:43:50 schuur volumio[916]: 16: 0x4ebca4 - ::poll::hc5e7d2d1b7dbef13 Jun 23 11:43:50 schuur volumio[916]: 17: 0x4b3844 - futures::task_impl::std::set::h8f081cf0436110c9 Jun 23 11:43:50 schuur volumio[916]: 18: 0x4c741c - std::thread::local::LocalKey::with::h711a13323aafc45a Jun 23 11:43:50 schuur volumio[916]: 19: 0x4a3a50 - tokio_current_thread::Entered

::block_on::h339073902a399eb7 Jun 23 11:43:50 schuur volumio[916]: 20: 0x4c7e00 - std::thread::local::LocalKey::with::hff64c13ccfec5327 Jun 23 11:43:50 schuur volumio[916]: 21: 0x4d420c - tokio_reactor::with_default::h7ef12e65cb103d2f Jun 23 11:43:50 schuur volumio[916]: 22: 0x4a79f8 - tokio::runtime::current_thread::runtime::Runtime::block_on::h043f136d6b8cf48f Jun 23 11:43:50 schuur volumio[916]: 23: 0x4ed2c8 - vollibrespot::main::h02a0d49d4cc5eaa6 Jun 23 11:43:50 schuur volumio[916]: 24: 0x4d4f18 - std::rt::lang_start::{{closure}}::h279cd2b7929fdba7 Jun 23 11:43:50 schuur volumio[916]: 25: 0x9ce404 - std::rt::lang_start_internal::{{closure}}::he93bfc404849b78a Jun 23 11:43:50 schuur volumio[916]: at src/libstd/rt.rs:52 Jun 23 11:43:50 schuur volumio[916]: 26: 0x9ce404 - std::panicking::try::do_call::h6e9e98f4078affb0 Jun 23 11:43:50 schuur volumio[916]: at src/libstd/panicking.rs:348 Jun 23 11:43:50 schuur volumio[916]: 27: 0x9ce404 - std::panicking::try::h2e68d4f7f799a6df Jun 23 11:43:50 schuur volumio[916]: at src/libstd/panicking.rs:325 Jun 23 11:43:50 schuur volumio[916]: 28: 0x9ce404 - std::panic::catch_unwind::h8880a4c07cc66391 Jun 23 11:43:50 schuur volumio[916]: at src/libstd/panic.rs:394 Jun 23 11:43:50 schuur volumio[916]: 29: 0x9ce404 - std::rt::lang_start_internal::hf4ae2140248bf16b Jun 23 11:43:50 schuur volumio[916]: at src/libstd/rt.rs:51 Jun 23 11:43:50 schuur volumio[916]: 30: 0x4edd84 - main Jun 23 11:43:50 schuur systemd[1]: volspotconnect2.service: main process exited, code=exited, status=101/n/a Jun 23 11:43:50 schuur systemd[1]: Unit volspotconnect2.service entered failed state. Jun 23 11:43:50 schuur volumio[786]: [SpotifyConnect] Device palyback is inactive Jun 23 11:43:50 schuur volumio[786]: [SpotifyConnect] Device Session is_active: true Jun 23 11:43:50 schuur volumio[786]: [SpotifyConnect] Sink released Jun 23 11:43:50 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:43:50 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:43:50 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:43:50 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:43:50 schuur volumio[916]: 31: 0x76cbc678 - __libc_start_main Jun 23 11:43:50 schuur volumio[916]: [Vollibrespot] : EventSender disconnected Jun 23 11:43:52 schuur systemd[1]: volspotconnect2.service holdoff time over, scheduling restart. Jun 23 11:43:52 schuur systemd[1]: Stopping Volspotconnect2 Daemon... Jun 23 11:43:52 schuur systemd[1]: Starting Volspotconnect2 Daemon... Jun 23 11:43:52 schuur systemd[1]: Started Volspotconnect2 Daemon. Jun 23 11:43:52 schuur volumio[1137]: vollibrespot v0.2.2 cd96399 2020-10-07 (librespot 08d8bcc 2020-10-07) -- Built On 2020-10-07 Jun 23 11:43:52 schuur volumio[1137]: Reading Config from "volspotify.toml" Jun 23 11:43:52 schuur volumio[1137]: [Vollibrespot] : Using Alsa backend with device: plughw:1 Jun 23 11:43:52 schuur volumio[1137]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" } Jun 23 11:43:57 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 23 11:43:57 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 23 11:44:34 schuur volumio[786]: info: Retrieving Cloud Streaming UI Jun 23 11:44:34 schuur volumio[786]: info: Getting Tidal Cloud Configuration Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 23 11:44:34 schuur volumio[786]: info: Getting Qobuz Cloud Configuration Jun 23 11:44:34 schuur volumio[786]: info: Asking plugin for UI Config Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 23 11:44:34 schuur volumio[786]: info: Getting Spotify Cloud Configuration Jun 23 11:44:34 schuur volumio[786]: info: Asking plugin for UI Config Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 23 11:44:34 schuur volumio[786]: info: Saving Spotify Acccount Jun 23 11:44:34 schuur volumio[786]: info: Got Tidal Cloud Configuration Jun 23 11:44:34 schuur volumio[786]: info: Got it Jun 23 11:44:34 schuur volumio[786]: info: Got it Jun 23 11:44:34 schuur volumio[786]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 23 11:44:34 schuur volumio[786]: error: Error retrieving Highresaudio conf: TypeError: Cannot read property 'onSave' of undefined Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::volumioGetBrowseSources Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 23 11:44:34 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Jun 23 11:44:38 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 23 11:44:42 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 23 11:44:47 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 23 11:44:51 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 23 11:44:52 schuur volumio[786]: info: CALLMETHOD: miscellanea my_music updateMusicLibraryBrowseSourcesVisibility [object Object] Jun 23 11:44:52 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: my_music , updateMusicLibraryBrowseSourcesVisibility Jun 23 11:44:52 schuur volumio[786]: info: CoreCommandRouter::volumioUpdateToBrowseSources Jun 23 11:44:52 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 23 11:44:54 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jun 23 11:44:54 schuur volumio[786]: info: CoreCommandRouter::volumioGetQueue Jun 23 11:44:54 schuur volumio[786]: info: CoreStateMachine::getQueue Jun 23 11:44:54 schuur volumio[786]: info: CorePlayQueue::getQueue Jun 23 11:45:02 schuur volumio[1137]: [Vollibrespot] : Connecting to AP "gew1-accesspoint-a-ft2t.ap.spotify.com:443" Jun 23 11:45:02 schuur volumio[1137]: [Vollibrespot] : Authenticated as "21hptgkjwzcroc6eo5gh3whki" ! Jun 23 11:45:02 schuur volumio[1137]: [Vollibrespot] : Setting up new mixer: card:hw:1 mixer:Headphone index:0 Jun 23 11:45:02 schuur volumio[1137]: [Vollibrespot] : Alsa Mixer info min: -10239 (MilliBel(-9999999)[dB]) -- max: 400 (MilliBel(400)[dB]) HW: true Jun 23 11:45:02 schuur volumio[1137]: [Vollibrespot] : Using alsa sink Jun 23 11:45:02 schuur volumio[1137]: [Vollibrespot] : Metadata pipe established Jun 23 11:45:02 schuur volumio[1137]: [Vollibrespot] : Country: "NL" Jun 23 11:45:02 schuur volumio[1137]: [Vollibrespot] : Event: Volume { volume_to_mixer: 0 } Jun 23 11:45:02 schuur volumio[786]: [SpotifyConnect] 0 Jun 23 11:45:02 schuur volumio[786]: [SpotifyConnect] Volume: Spotify:0 Volumio: 0 Jun 23 11:45:02 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:02 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:02 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:03 schuur volumio[1137]: [Vollibrespot] : Fetching autoplay context uri Jun 23 11:45:03 schuur volumio[1137]: [Vollibrespot] : Event: SessionActive { became_active_at: 1624448703124 } Jun 23 11:45:03 schuur volumio[1137]: [Vollibrespot] : SessionActive! Jun 23 11:45:03 schuur volumio[786]: [SpotifyConnect] A connect session has begun Jun 23 11:45:03 schuur volumio[1137]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 227505564021348702370395239071615962111, audio_type: Track } } Jun 23 11:45:03 schuur volumio[1137]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 227505564021348702370395239071615962111, audio_type: Track } } Jun 23 11:45:03 schuur volumio[786]: [SpotifyConnect] Device palyback is active! Jun 23 11:45:03 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:45:03 schuur volumio[786]: [SpotifyConnect] Currently active: volspotconnect2 Jun 23 11:45:03 schuur volumio[786]: [SpotifyConnect] Not requsting volumioStop on our own service Jun 23 11:45:03 schuur volumio[786]: [SpotifyConnect] Vollibrespot Active Jun 23 11:45:03 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:45:03 schuur volumio[786]: [SpotifyConnect] Currently active: volspotconnect2 Jun 23 11:45:03 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:45:03 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:03 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:03 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:03 schuur volumio[1137]: [Vollibrespot] : Autoplay uri resolved to <"spotify:station:album:4BHfl4OpAhzyFs275AOiv2"> Jun 23 11:45:03 schuur volumio[1137]: [Vollibrespot] : Resolving uri "spotify:station:album:4BHfl4OpAhzyFs275AOiv2" Jun 23 11:45:03 schuur volumio[1137]: [Vollibrespot] : error 403 for uri hm://keymaster/token/authenticated?client_id=4ced2e7c73484127be5d36015752eb43&scope=streaming,user-read-playback-state,user-modify-playback-state,user-read-currently-playing,user-read-private Jun 23 11:45:03 schuur volumio[1137]: [Vollibrespot] : Error: MercuryError Jun 23 11:45:03 schuur volumio[1137]: thread 'main' panicked at 'cannot poll Map twice', /build/cache/registry/src/github.com-1ecc6299db9ec823/futures-0.1.29/src/future/map.rs:35:29 Jun 23 11:45:03 schuur volumio[1137]: stack backtrace: Jun 23 11:45:03 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:45:03 schuur volumio[786]: [SpotifyConnect] Currently active: volspotconnect2 Jun 23 11:45:03 schuur volumio[786]: [SpotifyConnect] Pushing new state :: true Jun 23 11:45:03 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:45:03 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:03 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:03 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:03 schuur volumio[1137]: 0: 0xa2333c - backtrace::backtrace::libunwind::trace::hae21a072c81e5842 Jun 23 11:45:03 schuur volumio[1137]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86 Jun 23 11:45:03 schuur volumio[1137]: 1: 0xa2333c - backtrace::backtrace::trace_unsynchronized::h0f9b260087e46e47 Jun 23 11:45:03 schuur volumio[1137]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66 Jun 23 11:45:03 schuur volumio[1137]: 2: 0xa2333c - std::sys_common::backtrace::_print_fmt::hbf1a59173a7860c3 Jun 23 11:45:03 schuur volumio[1137]: at src/libstd/sys_common/backtrace.rs:78 Jun 23 11:45:03 schuur volumio[1137]: 3: 0xa2333c - ::fmt::he1a5d6f378e506c4 Jun 23 11:45:03 schuur volumio[1137]: at src/libstd/sys_common/backtrace.rs:59 Jun 23 11:45:03 schuur volumio[1137]: 4: 0xa43d5c - core::fmt::write::hb37ae5a5e0b70623 Jun 23 11:45:03 schuur volumio[1137]: at src/libcore/fmt/mod.rs:1076 Jun 23 11:45:03 schuur volumio[1137]: 5: 0xa1cc64 - std::io::Write::write_fmt::ha24bb3f5a858327b Jun 23 11:45:03 schuur volumio[1137]: at src/libstd/io/mod.rs:1537 Jun 23 11:45:03 schuur volumio[1137]: 6: 0xa25974 - std::sys_common::backtrace::_print::h47b03aa1342833e3 Jun 23 11:45:03 schuur volumio[1137]: at src/libstd/sys_common/backtrace.rs:62 Jun 23 11:45:03 schuur volumio[1137]: 7: 0xa25974 - std::sys_common::backtrace::print::h2217cbc390250439 Jun 23 11:45:03 schuur volumio[1137]: at src/libstd/sys_common/backtrace.rs:49 Jun 23 11:45:03 schuur volumio[1137]: 8: 0xa25974 - std::panicking::default_hook::{{closure}}::h179f5229ea1c8e30 Jun 23 11:45:03 schuur volumio[1137]: at src/libstd/panicking.rs:198 Jun 23 11:45:03 schuur volumio[1137]: 9: 0xa25640 - std::panicking::default_hook::h46ab82039cbc65eb Jun 23 11:45:03 schuur volumio[1137]: at src/libstd/panicking.rs:217 Jun 23 11:45:03 schuur volumio[1137]: 10: 0xa26054 - std::panicking::rust_panic_with_hook::h7326c48419bc7c33 Jun 23 11:45:03 schuur volumio[1137]: at src/libstd/panicking.rs:526 Jun 23 11:45:03 schuur volumio[1137]: 11: 0xa25c54 - rust_begin_unwind Jun 23 11:45:03 schuur volumio[1137]: at src/libstd/panicking.rs:437 Jun 23 11:45:03 schuur volumio[1137]: 12: 0xa41594 - core::panicking::panic_fmt::ha292e19d5ae716ed Jun 23 11:45:03 schuur volumio[1137]: at src/libcore/panicking.rs:85 Jun 23 11:45:03 schuur volumio[1137]: 13: 0xa41370 - core::option::expect_failed::he9e39f8f5ba60ecb Jun 23 11:45:03 schuur volumio[1137]: at src/libcore/option.rs:1261 Jun 23 11:45:03 schuur systemd[1]: volspotconnect2.service: main process exited, code=exited, status=101/n/a Jun 23 11:45:03 schuur systemd[1]: Unit volspotconnect2.service entered failed state. Jun 23 11:45:03 schuur volumio[786]: [SpotifyConnect] Device palyback is inactive Jun 23 11:45:03 schuur volumio[786]: [SpotifyConnect] Device Session is_active: true Jun 23 11:45:03 schuur volumio[786]: [SpotifyConnect] Sink released Jun 23 11:45:03 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:45:03 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:03 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:03 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:03 schuur volumio[1137]: 14: 0x717bf8 - as futures::future::Future>::poll::h3d56b212ca27d9e4 Jun 23 11:45:03 schuur volumio[1137]: 15: 0x5cd3a4 - ::poll::ha2e91a6b75c719f3 Jun 23 11:45:03 schuur volumio[1137]: 16: 0x543ca4 - ::poll::hc5e7d2d1b7dbef13 Jun 23 11:45:03 schuur volumio[1137]: 17: 0x50b844 - futures::task_impl::std::set::h8f081cf0436110c9 Jun 23 11:45:03 schuur volumio[1137]: 18: 0x51f41c - std::thread::local::LocalKey::with::h711a13323aafc45a Jun 23 11:45:03 schuur volumio[1137]: 19: 0x4fba50 - tokio_current_thread::Entered

::block_on::h339073902a399eb7 Jun 23 11:45:03 schuur volumio[1137]: 20: 0x51fe00 - std::thread::local::LocalKey::with::hff64c13ccfec5327 Jun 23 11:45:03 schuur volumio[1137]: 21: 0x52c20c - tokio_reactor::with_default::h7ef12e65cb103d2f Jun 23 11:45:03 schuur volumio[1137]: 22: 0x4ff9f8 - tokio::runtime::current_thread::runtime::Runtime::block_on::h043f136d6b8cf48f Jun 23 11:45:03 schuur volumio[1137]: 23: 0x5452c8 - vollibrespot::main::h02a0d49d4cc5eaa6 Jun 23 11:45:03 schuur volumio[1137]: 24: 0x52cf18 - std::rt::lang_start::{{closure}}::h279cd2b7929fdba7 Jun 23 11:45:03 schuur volumio[1137]: 25: 0xa26404 - std::rt::lang_start_internal::{{closure}}::he93bfc404849b78a Jun 23 11:45:03 schuur volumio[1137]: at src/libstd/rt.rs:52 Jun 23 11:45:03 schuur volumio[1137]: 26: 0xa26404 - std::panicking::try::do_call::h6e9e98f4078affb0 Jun 23 11:45:03 schuur volumio[1137]: at src/libstd/panicking.rs:348 Jun 23 11:45:03 schuur volumio[1137]: 27: 0xa26404 - std::panicking::try::h2e68d4f7f799a6df Jun 23 11:45:03 schuur volumio[1137]: at src/libstd/panicking.rs:325 Jun 23 11:45:03 schuur volumio[1137]: 28: 0xa26404 - std::panic::catch_unwind::h8880a4c07cc66391 Jun 23 11:45:03 schuur volumio[1137]: at src/libstd/panic.rs:394 Jun 23 11:45:03 schuur volumio[1137]: 29: 0xa26404 - std::rt::lang_start_internal::hf4ae2140248bf16b Jun 23 11:45:03 schuur volumio[1137]: at src/libstd/rt.rs:51 Jun 23 11:45:03 schuur volumio[1137]: 30: 0x545d84 - main Jun 23 11:45:03 schuur volumio[1137]: 31: 0x76c58678 - __libc_start_main Jun 23 11:45:03 schuur volumio[1137]: [Vollibrespot] : EventSender disconnected Jun 23 11:45:05 schuur systemd[1]: volspotconnect2.service holdoff time over, scheduling restart. Jun 23 11:45:05 schuur systemd[1]: Stopping Volspotconnect2 Daemon... Jun 23 11:45:05 schuur systemd[1]: Starting Volspotconnect2 Daemon... Jun 23 11:45:05 schuur systemd[1]: Started Volspotconnect2 Daemon. Jun 23 11:45:05 schuur volumio[1328]: vollibrespot v0.2.2 cd96399 2020-10-07 (librespot 08d8bcc 2020-10-07) -- Built On 2020-10-07 Jun 23 11:45:05 schuur volumio[1328]: Reading Config from "volspotify.toml" Jun 23 11:45:05 schuur volumio[1328]: [Vollibrespot] : Using Alsa backend with device: plughw:1 Jun 23 11:45:05 schuur volumio[1328]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" } Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Connecting to AP "gew1-accesspoint-a-x4zb.ap.spotify.com:443" Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Authenticated as "21hptgkjwzcroc6eo5gh3whki" ! Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Setting up new mixer: card:hw:1 mixer:Headphone index:0 Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Alsa Mixer info min: -10239 (MilliBel(-9999999)[dB]) -- max: 400 (MilliBel(400)[dB]) HW: true Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Using alsa sink Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Metadata pipe established Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Country: "NL" Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Event: Volume { volume_to_mixer: 0 } Jun 23 11:45:08 schuur volumio[786]: [SpotifyConnect] 0 Jun 23 11:45:08 schuur volumio[786]: [SpotifyConnect] Volume: Spotify:0 Volumio: 0 Jun 23 11:45:08 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:08 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:08 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Fetching autoplay context uri Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Event: SessionActive { became_active_at: 1624448708766 } Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : SessionActive! Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 227505564021348702370395239071615962111, audio_type: Track } } Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 227505564021348702370395239071615962111, audio_type: Track } } Jun 23 11:45:08 schuur volumio[786]: [SpotifyConnect] A connect session has begun Jun 23 11:45:08 schuur volumio[786]: [SpotifyConnect] Device palyback is active! Jun 23 11:45:08 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:45:08 schuur volumio[786]: [SpotifyConnect] Currently active: volspotconnect2 Jun 23 11:45:08 schuur volumio[786]: [SpotifyConnect] Not requsting volumioStop on our own service Jun 23 11:45:08 schuur volumio[786]: [SpotifyConnect] Vollibrespot Active Jun 23 11:45:08 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:45:08 schuur volumio[786]: [SpotifyConnect] Currently active: volspotconnect2 Jun 23 11:45:08 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:45:08 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:08 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:08 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:08 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:45:08 schuur volumio[786]: [SpotifyConnect] Currently active: volspotconnect2 Jun 23 11:45:08 schuur volumio[786]: [SpotifyConnect] Pushing new state :: true Jun 23 11:45:08 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:45:08 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:08 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:08 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Autoplay uri resolved to <"spotify:station:album:4BHfl4OpAhzyFs275AOiv2"> Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Resolving uri "spotify:station:album:4BHfl4OpAhzyFs275AOiv2" Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : error 403 for uri hm://keymaster/token/authenticated?client_id=4ced2e7c73484127be5d36015752eb43&scope=streaming,user-read-playback-state,user-modify-playback-state,user-read-currently-playing,user-read-private Jun 23 11:45:08 schuur volumio[1328]: [Vollibrespot] : Error: MercuryError Jun 23 11:45:08 schuur volumio[1328]: thread 'main' panicked at 'cannot poll Map twice', /build/cache/registry/src/github.com-1ecc6299db9ec823/futures-0.1.29/src/future/map.rs:35:29 Jun 23 11:45:08 schuur volumio[1328]: stack backtrace: Jun 23 11:45:09 schuur volumio[1328]: 0: 0x9ea33c - backtrace::backtrace::libunwind::trace::hae21a072c81e5842 Jun 23 11:45:09 schuur volumio[1328]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86 Jun 23 11:45:09 schuur volumio[1328]: 1: 0x9ea33c - backtrace::backtrace::trace_unsynchronized::h0f9b260087e46e47 Jun 23 11:45:09 schuur volumio[1328]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66 Jun 23 11:45:09 schuur volumio[1328]: 2: 0x9ea33c - std::sys_common::backtrace::_print_fmt::hbf1a59173a7860c3 Jun 23 11:45:09 schuur volumio[1328]: at src/libstd/sys_common/backtrace.rs:78 Jun 23 11:45:09 schuur volumio[1328]: 3: 0x9ea33c - ::fmt::he1a5d6f378e506c4 Jun 23 11:45:09 schuur volumio[1328]: at src/libstd/sys_common/backtrace.rs:59 Jun 23 11:45:09 schuur volumio[1328]: 4: 0xa0ad5c - core::fmt::write::hb37ae5a5e0b70623 Jun 23 11:45:09 schuur volumio[1328]: at src/libcore/fmt/mod.rs:1076 Jun 23 11:45:09 schuur volumio[1328]: 5: 0x9e3c64 - std::io::Write::write_fmt::ha24bb3f5a858327b Jun 23 11:45:09 schuur volumio[1328]: at src/libstd/io/mod.rs:1537 Jun 23 11:45:09 schuur volumio[1328]: 6: 0x9ec974 - std::sys_common::backtrace::_print::h47b03aa1342833e3 Jun 23 11:45:09 schuur volumio[1328]: at src/libstd/sys_common/backtrace.rs:62 Jun 23 11:45:09 schuur volumio[1328]: 7: 0x9ec974 - std::sys_common::backtrace::print::h2217cbc390250439 Jun 23 11:45:09 schuur volumio[1328]: at src/libstd/sys_common/backtrace.rs:49 Jun 23 11:45:09 schuur volumio[1328]: 8: 0x9ec974 - std::panicking::default_hook::{{closure}}::h179f5229ea1c8e30 Jun 23 11:45:09 schuur volumio[1328]: at src/libstd/panicking.rs:198 Jun 23 11:45:09 schuur volumio[1328]: 9: 0x9ec640 - std::panicking::default_hook::h46ab82039cbc65eb Jun 23 11:45:09 schuur volumio[1328]: at src/libstd/panicking.rs:217 Jun 23 11:45:09 schuur volumio[1328]: 10: 0x9ed054 - std::panicking::rust_panic_with_hook::h7326c48419bc7c33 Jun 23 11:45:09 schuur volumio[1328]: at src/libstd/panicking.rs:526 Jun 23 11:45:09 schuur volumio[1328]: 11: 0x9ecc54 - rust_begin_unwind Jun 23 11:45:09 schuur volumio[1328]: at src/libstd/panicking.rs:437 Jun 23 11:45:09 schuur volumio[1328]: 12: 0xa08594 - core::panicking::panic_fmt::ha292e19d5ae716ed Jun 23 11:45:09 schuur volumio[1328]: at src/libcore/panicking.rs:85 Jun 23 11:45:09 schuur volumio[1328]: 13: 0xa08370 - core::option::expect_failed::he9e39f8f5ba60ecb Jun 23 11:45:09 schuur volumio[1328]: at src/libcore/option.rs:1261 Jun 23 11:45:09 schuur volumio[1328]: 14: 0x6debf8 - as futures::future::Future>::poll::h3d56b212ca27d9e4 Jun 23 11:45:09 schuur systemd[1]: volspotconnect2.service: main process exited, code=exited, status=101/n/a Jun 23 11:45:09 schuur systemd[1]: Unit volspotconnect2.service entered failed state. Jun 23 11:45:09 schuur volumio[1328]: 15: 0x5943a4 - ::poll::ha2e91a6b75c719f3 Jun 23 11:45:09 schuur volumio[1328]: 16: 0x50aca4 - ::poll::hc5e7d2d1b7dbef13 Jun 23 11:45:09 schuur volumio[1328]: 17: 0x4d2844 - futures::task_impl::std::set::h8f081cf0436110c9 Jun 23 11:45:09 schuur volumio[1328]: 18: 0x4e641c - std::thread::local::LocalKey::with::h711a13323aafc45a Jun 23 11:45:09 schuur volumio[1328]: 19: 0x4c2a50 - tokio_current_thread::Entered

::block_on::h339073902a399eb7 Jun 23 11:45:09 schuur volumio[1328]: 20: 0x4e6e00 - std::thread::local::LocalKey::with::hff64c13ccfec5327 Jun 23 11:45:09 schuur volumio[1328]: 21: 0x4f320c - tokio_reactor::with_default::h7ef12e65cb103d2f Jun 23 11:45:09 schuur volumio[1328]: 22: 0x4c69f8 - tokio::runtime::current_thread::runtime::Runtime::block_on::h043f136d6b8cf48f Jun 23 11:45:09 schuur volumio[1328]: 23: 0x50c2c8 - vollibrespot::main::h02a0d49d4cc5eaa6 Jun 23 11:45:09 schuur volumio[1328]: 24: 0x4f3f18 - std::rt::lang_start::{{closure}}::h279cd2b7929fdba7 Jun 23 11:45:09 schuur volumio[1328]: 25: 0x9ed404 - std::rt::lang_start_internal::{{closure}}::he93bfc404849b78a Jun 23 11:45:09 schuur volumio[1328]: at src/libstd/rt.rs:52 Jun 23 11:45:09 schuur volumio[1328]: 26: 0x9ed404 - std::panicking::try::do_call::h6e9e98f4078affb0 Jun 23 11:45:09 schuur volumio[1328]: at src/libstd/panicking.rs:348 Jun 23 11:45:09 schuur volumio[1328]: 27: 0x9ed404 - std::panicking::try::h2e68d4f7f799a6df Jun 23 11:45:09 schuur volumio[1328]: at src/libstd/panicking.rs:325 Jun 23 11:45:09 schuur volumio[1328]: 28: 0x9ed404 - std::panic::catch_unwind::h8880a4c07cc66391 Jun 23 11:45:09 schuur volumio[1328]: at src/libstd/panic.rs:394 Jun 23 11:45:09 schuur volumio[1328]: 29: 0x9ed404 - std::rt::lang_start_internal::hf4ae2140248bf16b Jun 23 11:45:09 schuur volumio[1328]: at src/libstd/rt.rs:51 Jun 23 11:45:09 schuur volumio[1328]: 30: 0x50cd84 - main Jun 23 11:45:09 schuur volumio[1328]: 31: 0x76c58678 - __libc_start_main Jun 23 11:45:09 schuur volumio[1328]: [Vollibrespot] : EventSender disconnected Jun 23 11:45:09 schuur volumio[786]: [SpotifyConnect] Device palyback is inactive Jun 23 11:45:09 schuur volumio[786]: [SpotifyConnect] Device Session is_active: true Jun 23 11:45:09 schuur volumio[786]: [SpotifyConnect] Sink released Jun 23 11:45:09 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:45:09 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:09 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:09 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:11 schuur systemd[1]: volspotconnect2.service holdoff time over, scheduling restart. Jun 23 11:45:11 schuur systemd[1]: Stopping Volspotconnect2 Daemon... Jun 23 11:45:11 schuur systemd[1]: Starting Volspotconnect2 Daemon... Jun 23 11:45:11 schuur systemd[1]: Started Volspotconnect2 Daemon. Jun 23 11:45:11 schuur volumio[1349]: vollibrespot v0.2.2 cd96399 2020-10-07 (librespot 08d8bcc 2020-10-07) -- Built On 2020-10-07 Jun 23 11:45:11 schuur volumio[1349]: Reading Config from "volspotify.toml" Jun 23 11:45:11 schuur volumio[1349]: [Vollibrespot] : Using Alsa backend with device: plughw:1 Jun 23 11:45:11 schuur volumio[1349]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" } Jun 23 11:45:15 schuur volumio[1349]: [Vollibrespot] : Connecting to AP "gew1-accesspoint-a-k0sx.ap.spotify.com:443" Jun 23 11:45:15 schuur volumio[1349]: [Vollibrespot] : Authenticated as "21hptgkjwzcroc6eo5gh3whki" ! Jun 23 11:45:15 schuur volumio[1349]: [Vollibrespot] : Setting up new mixer: card:hw:1 mixer:Headphone index:0 Jun 23 11:45:15 schuur volumio[1349]: [Vollibrespot] : Alsa Mixer info min: -10239 (MilliBel(-9999999)[dB]) -- max: 400 (MilliBel(400)[dB]) HW: true Jun 23 11:45:15 schuur volumio[1349]: [Vollibrespot] : Using alsa sink Jun 23 11:45:16 schuur volumio[1349]: [Vollibrespot] : Metadata pipe established Jun 23 11:45:16 schuur volumio[1349]: [Vollibrespot] : Country: "NL" Jun 23 11:45:16 schuur volumio[1349]: [Vollibrespot] : Event: Volume { volume_to_mixer: 0 } Jun 23 11:45:16 schuur volumio[786]: [SpotifyConnect] 0 Jun 23 11:45:16 schuur volumio[786]: [SpotifyConnect] Volume: Spotify:0 Volumio: 0 Jun 23 11:45:16 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:16 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:16 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:16 schuur volumio[1349]: [Vollibrespot] : Event: SessionActive { became_active_at: 1624448716232 } Jun 23 11:45:16 schuur volumio[1349]: [Vollibrespot] : SessionActive! Jun 23 11:45:16 schuur volumio[786]: [SpotifyConnect] A connect session has begun Jun 23 11:45:16 schuur volumio[1349]: [Vollibrespot] : Fetching autoplay context uri Jun 23 11:45:16 schuur volumio[1349]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 227505564021348702370395239071615962111, audio_type: Track } } Jun 23 11:45:16 schuur volumio[1349]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 227505564021348702370395239071615962111, audio_type: Track } } Jun 23 11:45:16 schuur volumio[786]: [SpotifyConnect] Device palyback is active! Jun 23 11:45:16 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:45:16 schuur volumio[786]: [SpotifyConnect] Currently active: volspotconnect2 Jun 23 11:45:16 schuur volumio[786]: [SpotifyConnect] Not requsting volumioStop on our own service Jun 23 11:45:16 schuur volumio[786]: [SpotifyConnect] Vollibrespot Active Jun 23 11:45:16 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:45:16 schuur volumio[786]: [SpotifyConnect] Currently active: volspotconnect2 Jun 23 11:45:16 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:45:16 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:16 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:16 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:16 schuur volumio[1349]: [Vollibrespot] : error 403 for uri hm://keymaster/token/authenticated?client_id=4ced2e7c73484127be5d36015752eb43&scope=streaming,user-read-playback-state,user-modify-playback-state,user-read-currently-playing,user-read-private Jun 23 11:45:16 schuur volumio[1349]: [Vollibrespot] : Error: MercuryError Jun 23 11:45:16 schuur volumio[1349]: [Vollibrespot] : Autoplay uri resolved to <"spotify:station:album:4BHfl4OpAhzyFs275AOiv2"> Jun 23 11:45:16 schuur volumio[1349]: [Vollibrespot] : Resolving uri "spotify:station:album:4BHfl4OpAhzyFs275AOiv2" Jun 23 11:45:16 schuur volumio[1349]: thread 'main' panicked at 'cannot poll Map twice', /build/cache/registry/src/github.com-1ecc6299db9ec823/futures-0.1.29/src/future/map.rs:35:29 Jun 23 11:45:16 schuur volumio[1349]: stack backtrace: Jun 23 11:45:16 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:45:16 schuur volumio[786]: [SpotifyConnect] Currently active: volspotconnect2 Jun 23 11:45:16 schuur volumio[786]: [SpotifyConnect] Pushing new state :: true Jun 23 11:45:16 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:45:16 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:16 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:16 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:16 schuur volumio[1349]: 0: 0xa3133c - backtrace::backtrace::libunwind::trace::hae21a072c81e5842 Jun 23 11:45:16 schuur volumio[1349]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86 Jun 23 11:45:16 schuur volumio[1349]: 1: 0xa3133c - backtrace::backtrace::trace_unsynchronized::h0f9b260087e46e47 Jun 23 11:45:16 schuur volumio[1349]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66 Jun 23 11:45:16 schuur volumio[1349]: 2: 0xa3133c - std::sys_common::backtrace::_print_fmt::hbf1a59173a7860c3 Jun 23 11:45:16 schuur volumio[1349]: at src/libstd/sys_common/backtrace.rs:78 Jun 23 11:45:16 schuur volumio[1349]: 3: 0xa3133c - ::fmt::he1a5d6f378e506c4 Jun 23 11:45:16 schuur volumio[1349]: at src/libstd/sys_common/backtrace.rs:59 Jun 23 11:45:16 schuur volumio[1349]: 4: 0xa51d5c - core::fmt::write::hb37ae5a5e0b70623 Jun 23 11:45:16 schuur volumio[1349]: at src/libcore/fmt/mod.rs:1076 Jun 23 11:45:16 schuur volumio[1349]: 5: 0xa2ac64 - std::io::Write::write_fmt::ha24bb3f5a858327b Jun 23 11:45:16 schuur volumio[1349]: at src/libstd/io/mod.rs:1537 Jun 23 11:45:16 schuur volumio[1349]: 6: 0xa33974 - std::sys_common::backtrace::_print::h47b03aa1342833e3 Jun 23 11:45:16 schuur volumio[1349]: at src/libstd/sys_common/backtrace.rs:62 Jun 23 11:45:16 schuur volumio[1349]: 7: 0xa33974 - std::sys_common::backtrace::print::h2217cbc390250439 Jun 23 11:45:16 schuur volumio[1349]: at src/libstd/sys_common/backtrace.rs:49 Jun 23 11:45:16 schuur volumio[1349]: 8: 0xa33974 - std::panicking::default_hook::{{closure}}::h179f5229ea1c8e30 Jun 23 11:45:16 schuur volumio[1349]: at src/libstd/panicking.rs:198 Jun 23 11:45:16 schuur volumio[1349]: 9: 0xa33640 - std::panicking::default_hook::h46ab82039cbc65eb Jun 23 11:45:16 schuur volumio[1349]: at src/libstd/panicking.rs:217 Jun 23 11:45:16 schuur volumio[1349]: 10: 0xa34054 - std::panicking::rust_panic_with_hook::h7326c48419bc7c33 Jun 23 11:45:16 schuur volumio[1349]: at src/libstd/panicking.rs:526 Jun 23 11:45:16 schuur volumio[1349]: 11: 0xa33c54 - rust_begin_unwind Jun 23 11:45:16 schuur volumio[1349]: at src/libstd/panicking.rs:437 Jun 23 11:45:16 schuur volumio[1349]: 12: 0xa4f594 - core::panicking::panic_fmt::ha292e19d5ae716ed Jun 23 11:45:16 schuur volumio[1349]: at src/libcore/panicking.rs:85 Jun 23 11:45:16 schuur volumio[1349]: 13: 0xa4f370 - core::option::expect_failed::he9e39f8f5ba60ecb Jun 23 11:45:16 schuur volumio[1349]: at src/libcore/option.rs:1261 Jun 23 11:45:16 schuur volumio[1349]: 14: 0x725bf8 - as futures::future::Future>::poll::h3d56b212ca27d9e4 Jun 23 11:45:16 schuur systemd[1]: volspotconnect2.service: main process exited, code=exited, status=101/n/a Jun 23 11:45:16 schuur systemd[1]: Unit volspotconnect2.service entered failed state. Jun 23 11:45:16 schuur volumio[786]: [SpotifyConnect] Device palyback is inactive Jun 23 11:45:16 schuur volumio[786]: [SpotifyConnect] Device Session is_active: true Jun 23 11:45:16 schuur volumio[786]: [SpotifyConnect] Sink released Jun 23 11:45:16 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:45:16 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:16 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:16 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:16 schuur volumio[1349]: 15: 0x5db3a4 - ::poll::ha2e91a6b75c719f3 Jun 23 11:45:16 schuur volumio[1349]: 16: 0x551ca4 - ::poll::hc5e7d2d1b7dbef13 Jun 23 11:45:16 schuur volumio[1349]: 17: 0x519844 - futures::task_impl::std::set::h8f081cf0436110c9 Jun 23 11:45:16 schuur volumio[1349]: 18: 0x52d41c - std::thread::local::LocalKey::with::h711a13323aafc45a Jun 23 11:45:16 schuur volumio[1349]: 19: 0x509a50 - tokio_current_thread::Entered

::block_on::h339073902a399eb7 Jun 23 11:45:16 schuur volumio[1349]: 20: 0x52de00 - std::thread::local::LocalKey::with::hff64c13ccfec5327 Jun 23 11:45:16 schuur volumio[1349]: 21: 0x53a20c - tokio_reactor::with_default::h7ef12e65cb103d2f Jun 23 11:45:16 schuur volumio[1349]: 22: 0x50d9f8 - tokio::runtime::current_thread::runtime::Runtime::block_on::h043f136d6b8cf48f Jun 23 11:45:16 schuur volumio[1349]: 23: 0x5532c8 - vollibrespot::main::h02a0d49d4cc5eaa6 Jun 23 11:45:16 schuur volumio[1349]: 24: 0x53af18 - std::rt::lang_start::{{closure}}::h279cd2b7929fdba7 Jun 23 11:45:16 schuur volumio[1349]: 25: 0xa34404 - std::rt::lang_start_internal::{{closure}}::he93bfc404849b78a Jun 23 11:45:16 schuur volumio[1349]: at src/libstd/rt.rs:52 Jun 23 11:45:16 schuur volumio[1349]: 26: 0xa34404 - std::panicking::try::do_call::h6e9e98f4078affb0 Jun 23 11:45:16 schuur volumio[1349]: at src/libstd/panicking.rs:348 Jun 23 11:45:16 schuur volumio[1349]: 27: 0xa34404 - std::panicking::try::h2e68d4f7f799a6df Jun 23 11:45:16 schuur volumio[1349]: at src/libstd/panicking.rs:325 Jun 23 11:45:16 schuur volumio[1349]: 28: 0xa34404 - std::panic::catch_unwind::h8880a4c07cc66391 Jun 23 11:45:16 schuur volumio[1349]: at src/libstd/panic.rs:394 Jun 23 11:45:16 schuur volumio[1349]: 29: 0xa34404 - std::rt::lang_start_internal::hf4ae2140248bf16b Jun 23 11:45:16 schuur volumio[1349]: at src/libstd/rt.rs:51 Jun 23 11:45:16 schuur volumio[1349]: 30: 0x553d84 - main Jun 23 11:45:16 schuur volumio[1349]: 31: 0x76cca678 - __libc_start_main Jun 23 11:45:16 schuur volumio[1349]: [Vollibrespot] : EventSender disconnected Jun 23 11:45:18 schuur systemd[1]: volspotconnect2.service holdoff time over, scheduling restart. Jun 23 11:45:18 schuur systemd[1]: Stopping Volspotconnect2 Daemon... Jun 23 11:45:18 schuur systemd[1]: Starting Volspotconnect2 Daemon... Jun 23 11:45:18 schuur systemd[1]: Started Volspotconnect2 Daemon. Jun 23 11:45:18 schuur volumio[1375]: vollibrespot v0.2.2 cd96399 2020-10-07 (librespot 08d8bcc 2020-10-07) -- Built On 2020-10-07 Jun 23 11:45:18 schuur volumio[1375]: Reading Config from "volspotify.toml" Jun 23 11:45:18 schuur volumio[1375]: [Vollibrespot] : Using Alsa backend with device: plughw:1 Jun 23 11:45:19 schuur volumio[1375]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" } Jun 23 11:45:22 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:45:22 schuur volumio[786]: info: CoreCommandRouter::volumioGetQueue Jun 23 11:45:22 schuur volumio[786]: info: CoreStateMachine::getQueue Jun 23 11:45:22 schuur volumio[786]: info: CorePlayQueue::getQueue Jun 23 11:45:22 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getHwuuid Jun 23 11:45:24 schuur volumio[786]: info: CALLMETHOD: system_controller system enableLiveLog true Jun 23 11:45:24 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog Jun 23 11:45:24 schuur volumio[786]: info: Launching a new LiveLog session Jun 23 11:45:28 schuur volumio[1375]: [Vollibrespot] : Connecting to AP "gew1-accesspoint-a-676c.ap.spotify.com:443" Jun 23 11:45:28 schuur volumio[1375]: [Vollibrespot] : Authenticated as "21hptgkjwzcroc6eo5gh3whki" ! Jun 23 11:45:28 schuur volumio[1375]: [Vollibrespot] : Setting up new mixer: card:hw:1 mixer:Headphone index:0 Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : Alsa Mixer info min: -10239 (MilliBel(-9999999)[dB]) -- max: 400 (MilliBel(400)[dB]) HW: true Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : Metadata pipe established Jun 23 11:45:29 schuur volumio[786]: [SpotifyConnect] 0 Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : Event: Volume { volume_to_mixer: 0 } Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : Country: "NL" Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : Using alsa sink Jun 23 11:45:29 schuur volumio[786]: [SpotifyConnect] Volume: Spotify:0 Volumio: 0 Jun 23 11:45:29 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:29 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:29 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : Fetching autoplay context uri Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : Event: SessionActive { became_active_at: 1624448728224 } Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : SessionActive! Jun 23 11:45:29 schuur volumio[786]: [SpotifyConnect] A connect session has begun Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 227505564021348702370395239071615962111, audio_type: Track } } Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 227505564021348702370395239071615962111, audio_type: Track } } Jun 23 11:45:29 schuur volumio[786]: [SpotifyConnect] Device palyback is active! Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : error 403 for uri hm://keymaster/token/authenticated?client_id=4ced2e7c73484127be5d36015752eb43&scope=streaming,user-read-playback-state,user-modify-playback-state,user-read-currently-playing,user-read-private Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : Error: MercuryError Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : Autoplay uri resolved to <"spotify:station:album:4BHfl4OpAhzyFs275AOiv2"> Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : Resolving uri "spotify:station:album:4BHfl4OpAhzyFs275AOiv2" Jun 23 11:45:29 schuur volumio[1375]: thread 'main' panicked at 'cannot poll Map twice', /build/cache/registry/src/github.com-1ecc6299db9ec823/futures-0.1.29/src/future/map.rs:35:29 Jun 23 11:45:29 schuur volumio[1375]: stack backtrace: Jun 23 11:45:29 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:45:29 schuur volumio[786]: [SpotifyConnect] Currently active: volspotconnect2 Jun 23 11:45:29 schuur volumio[786]: [SpotifyConnect] Not requsting volumioStop on our own service Jun 23 11:45:29 schuur volumio[786]: [SpotifyConnect] Vollibrespot Active Jun 23 11:45:29 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:45:29 schuur volumio[786]: [SpotifyConnect] Currently active: volspotconnect2 Jun 23 11:45:29 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:45:29 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:29 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:29 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:29 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:45:29 schuur volumio[786]: [SpotifyConnect] Currently active: volspotconnect2 Jun 23 11:45:29 schuur volumio[786]: [SpotifyConnect] Pushing new state :: true Jun 23 11:45:29 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:45:29 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:29 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:29 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:29 schuur volumio[1375]: 0: 0xa7b33c - backtrace::backtrace::libunwind::trace::hae21a072c81e5842 Jun 23 11:45:29 schuur volumio[1375]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86 Jun 23 11:45:29 schuur volumio[1375]: 1: 0xa7b33c - backtrace::backtrace::trace_unsynchronized::h0f9b260087e46e47 Jun 23 11:45:29 schuur volumio[1375]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66 Jun 23 11:45:29 schuur volumio[1375]: 2: 0xa7b33c - std::sys_common::backtrace::_print_fmt::hbf1a59173a7860c3 Jun 23 11:45:29 schuur volumio[1375]: at src/libstd/sys_common/backtrace.rs:78 Jun 23 11:45:29 schuur volumio[1375]: 3: 0xa7b33c - ::fmt::he1a5d6f378e506c4 Jun 23 11:45:29 schuur volumio[1375]: at src/libstd/sys_common/backtrace.rs:59 Jun 23 11:45:29 schuur volumio[1375]: 4: 0xa9bd5c - core::fmt::write::hb37ae5a5e0b70623 Jun 23 11:45:29 schuur volumio[1375]: at src/libcore/fmt/mod.rs:1076 Jun 23 11:45:29 schuur volumio[1375]: 5: 0xa74c64 - std::io::Write::write_fmt::ha24bb3f5a858327b Jun 23 11:45:29 schuur volumio[1375]: at src/libstd/io/mod.rs:1537 Jun 23 11:45:29 schuur volumio[1375]: 6: 0xa7d974 - std::sys_common::backtrace::_print::h47b03aa1342833e3 Jun 23 11:45:29 schuur volumio[1375]: at src/libstd/sys_common/backtrace.rs:62 Jun 23 11:45:29 schuur volumio[1375]: 7: 0xa7d974 - std::sys_common::backtrace::print::h2217cbc390250439 Jun 23 11:45:29 schuur volumio[1375]: at src/libstd/sys_common/backtrace.rs:49 Jun 23 11:45:29 schuur volumio[1375]: 8: 0xa7d974 - std::panicking::default_hook::{{closure}}::h179f5229ea1c8e30 Jun 23 11:45:29 schuur volumio[1375]: at src/libstd/panicking.rs:198 Jun 23 11:45:29 schuur volumio[1375]: 9: 0xa7d640 - std::panicking::default_hook::h46ab82039cbc65eb Jun 23 11:45:29 schuur volumio[1375]: at src/libstd/panicking.rs:217 Jun 23 11:45:29 schuur volumio[1375]: 10: 0xa7e054 - std::panicking::rust_panic_with_hook::h7326c48419bc7c33 Jun 23 11:45:29 schuur volumio[1375]: at src/libstd/panicking.rs:526 Jun 23 11:45:29 schuur volumio[1375]: 11: 0xa7dc54 - rust_begin_unwind Jun 23 11:45:29 schuur volumio[1375]: at src/libstd/panicking.rs:437 Jun 23 11:45:29 schuur volumio[1375]: 12: 0xa99594 - core::panicking::panic_fmt::ha292e19d5ae716ed Jun 23 11:45:29 schuur volumio[1375]: at src/libcore/panicking.rs:85 Jun 23 11:45:29 schuur volumio[1375]: 13: 0xa99370 - core::option::expect_failed::he9e39f8f5ba60ecb Jun 23 11:45:29 schuur volumio[1375]: at src/libcore/option.rs:1261 Jun 23 11:45:29 schuur volumio[1375]: 14: 0x76fbf8 - as futures::future::Future>::poll::h3d56b212ca27d9e4 Jun 23 11:45:29 schuur volumio[1375]: 15: 0x6253a4 - ::poll::ha2e91a6b75c719f3 Jun 23 11:45:29 schuur volumio[1375]: 16: 0x59bca4 - ::poll::hc5e7d2d1b7dbef13 Jun 23 11:45:29 schuur volumio[1375]: 17: 0x563844 - futures::task_impl::std::set::h8f081cf0436110c9 Jun 23 11:45:29 schuur volumio[1375]: 18: 0x57741c - std::thread::local::LocalKey::with::h711a13323aafc45a Jun 23 11:45:29 schuur systemd[1]: volspotconnect2.service: main process exited, code=exited, status=101/n/a Jun 23 11:45:29 schuur systemd[1]: Unit volspotconnect2.service entered failed state. Jun 23 11:45:29 schuur volumio[786]: [SpotifyConnect] Device palyback is inactive Jun 23 11:45:29 schuur volumio[786]: [SpotifyConnect] Device Session is_active: true Jun 23 11:45:29 schuur volumio[786]: [SpotifyConnect] Sink released Jun 23 11:45:29 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:45:29 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:45:29 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:45:29 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:45:29 schuur volumio[1375]: 19: 0x553a50 - tokio_current_thread::Entered

::block_on::h339073902a399eb7 Jun 23 11:45:29 schuur volumio[1375]: 20: 0x577e00 - std::thread::local::LocalKey::with::hff64c13ccfec5327 Jun 23 11:45:29 schuur volumio[1375]: 21: 0x58420c - tokio_reactor::with_default::h7ef12e65cb103d2f Jun 23 11:45:29 schuur volumio[1375]: 22: 0x5579f8 - tokio::runtime::current_thread::runtime::Runtime::block_on::h043f136d6b8cf48f Jun 23 11:45:29 schuur volumio[1375]: 23: 0x59d2c8 - vollibrespot::main::h02a0d49d4cc5eaa6 Jun 23 11:45:29 schuur volumio[1375]: 24: 0x584f18 - std::rt::lang_start::{{closure}}::h279cd2b7929fdba7 Jun 23 11:45:29 schuur volumio[1375]: 25: 0xa7e404 - std::rt::lang_start_internal::{{closure}}::he93bfc404849b78a Jun 23 11:45:29 schuur volumio[1375]: at src/libstd/rt.rs:52 Jun 23 11:45:29 schuur volumio[1375]: 26: 0xa7e404 - std::panicking::try::do_call::h6e9e98f4078affb0 Jun 23 11:45:29 schuur volumio[1375]: at src/libstd/panicking.rs:348 Jun 23 11:45:29 schuur volumio[1375]: 27: 0xa7e404 - std::panicking::try::h2e68d4f7f799a6df Jun 23 11:45:29 schuur volumio[1375]: at src/libstd/panicking.rs:325 Jun 23 11:45:29 schuur volumio[1375]: 28: 0xa7e404 - std::panic::catch_unwind::h8880a4c07cc66391 Jun 23 11:45:29 schuur volumio[1375]: at src/libstd/panic.rs:394 Jun 23 11:45:29 schuur volumio[1375]: 29: 0xa7e404 - std::rt::lang_start_internal::hf4ae2140248bf16b Jun 23 11:45:29 schuur volumio[1375]: at src/libstd/rt.rs:51 Jun 23 11:45:29 schuur volumio[1375]: 30: 0x59dd84 - main Jun 23 11:45:29 schuur volumio[1375]: 31: 0x76d00678 - __libc_start_main Jun 23 11:45:29 schuur volumio[1375]: [Vollibrespot] : EventSender disconnected Jun 23 11:45:31 schuur systemd[1]: volspotconnect2.service holdoff time over, scheduling restart. Jun 23 11:45:31 schuur systemd[1]: Stopping Volspotconnect2 Daemon... Jun 23 11:45:31 schuur systemd[1]: Starting Volspotconnect2 Daemon... Jun 23 11:45:31 schuur systemd[1]: Started Volspotconnect2 Daemon. Jun 23 11:45:31 schuur volumio[1410]: vollibrespot v0.2.2 cd96399 2020-10-07 (librespot 08d8bcc 2020-10-07) -- Built On 2020-10-07 Jun 23 11:45:31 schuur volumio[1410]: Reading Config from "volspotify.toml" Jun 23 11:45:31 schuur volumio[1410]: [Vollibrespot] : Using Alsa backend with device: plughw:1 Jun 23 11:45:32 schuur volumio[1410]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" } Jun 23 11:46:40 schuur volumio[786]: info: CALLMETHOD: system_controller system sendBugReport [object Object] Jun 23 11:46:40 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , sendBugReport Jun 23 11:46:41 schuur sudo[1587]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig Jun 23 11:46:41 schuur sudo[1587]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:46:41 schuur sudo[1587]: pam_unix(sudo:session): session closed for user root Jun 23 11:46:41 schuur volumio[786]: info: CALLMETHOD: system_controller system enableSSH false Jun 23 11:46:41 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , enableSSH Jun 23 11:46:41 schuur sudo[1609]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop ssh.service Jun 23 11:46:41 schuur sudo[1609]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:46:41 schuur systemd[1]: Stopping OpenBSD Secure Shell server... Jun 23 11:46:41 schuur sshd[728]: Received signal 15; terminating. Jun 23 11:46:41 schuur systemd[1]: Stopped OpenBSD Secure Shell server. Jun 23 11:46:41 schuur sudo[1609]: pam_unix(sudo:session): session closed for user root Jun 23 11:46:41 schuur sudo[1630]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable ssh.service Jun 23 11:46:41 schuur sudo[1630]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:46:42 schuur systemd[1]: Reloading. Jun 23 11:46:43 schuur systemd[1]: [/lib/systemd/system/mpd.service:18] Unknown lvalue 'ProtectKernelTunables' in section 'Service' Jun 23 11:46:43 schuur systemd[1]: [/lib/systemd/system/mpd.service:19] Unknown lvalue 'ProtectControlGroups' in section 'Service' Jun 23 11:46:43 schuur systemd[1]: [/lib/systemd/system/mpd.service:20] Unknown lvalue 'ProtectKernelModules' in section 'Service' Jun 23 11:46:43 schuur systemd[1]: [/lib/systemd/system/mpd.service:23] Unknown lvalue 'RestrictNamespaces' in section 'Service' Jun 23 11:46:44 schuur systemd[1]: Reloading. Jun 23 11:46:44 schuur systemd[1]: [/lib/systemd/system/mpd.service:18] Unknown lvalue 'ProtectKernelTunables' in section 'Service' Jun 23 11:46:44 schuur systemd[1]: [/lib/systemd/system/mpd.service:19] Unknown lvalue 'ProtectControlGroups' in section 'Service' Jun 23 11:46:44 schuur systemd[1]: [/lib/systemd/system/mpd.service:20] Unknown lvalue 'ProtectKernelModules' in section 'Service' Jun 23 11:46:44 schuur systemd[1]: [/lib/systemd/system/mpd.service:23] Unknown lvalue 'RestrictNamespaces' in section 'Service' Jun 23 11:46:44 schuur systemd[1]: Reloading. Jun 23 11:46:44 schuur systemd[1]: [/lib/systemd/system/mpd.service:18] Unknown lvalue 'ProtectKernelTunables' in section 'Service' Jun 23 11:46:44 schuur systemd[1]: [/lib/systemd/system/mpd.service:19] Unknown lvalue 'ProtectControlGroups' in section 'Service' Jun 23 11:46:44 schuur systemd[1]: [/lib/systemd/system/mpd.service:20] Unknown lvalue 'ProtectKernelModules' in section 'Service' Jun 23 11:46:44 schuur systemd[1]: [/lib/systemd/system/mpd.service:23] Unknown lvalue 'RestrictNamespaces' in section 'Service' Jun 23 11:46:44 schuur sudo[1630]: pam_unix(sudo:session): session closed for user root Jun 23 11:46:45 schuur volumio[786]: info: disable SSH service success Jun 23 11:46:46 schuur sudo[1693]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl -p 7 Jun 23 11:46:46 schuur sudo[1693]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:46:47 schuur sudo[1693]: pam_unix(sudo:session): session closed for user root Jun 23 11:46:47 schuur volumio[786]: info: Log sent successfully, reply: {"status":"OK","link":"http://logs.volumio.org/volumio/w3hFiqm.html"} Jun 23 11:47:36 schuur sudo[1840]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 23 11:47:36 schuur sudo[1840]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:47:36 schuur sudo[1842]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 23 11:47:36 schuur sudo[1840]: pam_unix(sudo:session): session closed for user root Jun 23 11:47:36 schuur sudo[1842]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:47:36 schuur sudo[1842]: pam_unix(sudo:session): session closed for user root Jun 23 11:47:36 schuur sudo[1862]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 23 11:47:36 schuur sudo[1862]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:47:36 schuur sudo[1864]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 23 11:47:36 schuur sudo[1862]: pam_unix(sudo:session): session closed for user root Jun 23 11:47:36 schuur sudo[1864]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:47:36 schuur sudo[1864]: pam_unix(sudo:session): session closed for user root Jun 23 11:47:37 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:47:37 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 23 11:47:37 schuur volumio[786]: info: CoreCommandRouter::volumioGetVisibleSources Jun 23 11:47:37 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 23 11:47:37 schuur volumio[786]: info: Listing playlists Jun 23 11:47:37 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 23 11:47:37 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 23 11:47:37 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 23 11:47:37 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 23 11:47:39 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 23 11:47:41 schuur volumio[786]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 23 11:47:41 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , getBackgrounds Jun 23 11:47:42 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , setBackgrounds Jun 23 11:47:42 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , getBackgrounds Jun 23 11:47:42 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 23 11:47:45 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , setBackgrounds Jun 23 11:47:45 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , getBackgrounds Jun 23 11:47:45 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 23 11:47:49 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jun 23 11:47:49 schuur volumio[786]: info: CoreCommandRouter::volumioGetQueue Jun 23 11:47:49 schuur volumio[786]: info: CoreStateMachine::getQueue Jun 23 11:47:49 schuur volumio[786]: info: CorePlayQueue::getQueue Jun 23 11:47:53 schuur volumio[786]: Searching plugin music_service/webradio Jun 23 11:47:53 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: webradio , search Jun 23 11:47:55 schuur volumio[786]: info: All search sources collected, pushing search results Jun 23 11:48:01 schuur volumio[786]: info: Saving local item radio-favourites Jun 23 11:48:01 schuur volumio[786]: info: Pushing Favourites {"uri":"http://opml.radiotime.com/Tune.ashx?id=s54815","favourite":false} Jun 23 11:48:02 schuur volumio[786]: info: CoreCommandRouter::volumioReplaceandPlayItems Jun 23 11:48:02 schuur volumio[786]: info: CoreStateMachine::ClearQueue Jun 23 11:48:02 schuur volumio[786]: info: CoreStateMachine::stop Jun 23 11:48:02 schuur volumio[786]: info: CoreStateMachine::serviceStop Jun 23 11:48:02 schuur volumio[786]: info: CoreCommandRouter::serviceStop Jun 23 11:48:02 schuur volumio[786]: [SpotifyConnect] Received stop Jun 23 11:48:02 schuur volumio[786]: info: CorePlayQueue::clearPlayQueue Jun 23 11:48:02 schuur volumio[786]: info: CorePlayQueue::saveQueue Jun 23 11:48:02 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:48:02 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:48:02 schuur volumio[786]: info: CoreCommandRouter::volumioPushQueue Jun 23 11:48:02 schuur volumio[786]: info: CoreStateMachine::addQueueItems Jun 23 11:48:02 schuur volumio[786]: info: CorePlayQueue::addQueueItems Jun 23 11:48:02 schuur volumio[786]: info: Adding Item to queue: http://opml.radiotime.com/Tune.ashx?id=s54815 Jun 23 11:48:02 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri Jun 23 11:48:03 schuur volumio[786]: info: CorePlayQueue::saveQueue Jun 23 11:48:03 schuur volumio[786]: info: CoreCommandRouter::volumioPushQueue Jun 23 11:48:03 schuur volumio[786]: info: CoreStateMachine::updateTrackBlock Jun 23 11:48:03 schuur volumio[786]: info: CorePlayQueue::getTrackBlock Jun 23 11:48:03 schuur volumio[786]: info: CoreCommandRouter::volumioPlay Jun 23 11:48:03 schuur volumio[786]: UNSET VOLATILE Jun 23 11:48:03 schuur volumio[786]: [SpotifyConnect] unSetVolatile called Jun 23 11:48:03 schuur volumio[786]: [SpotifyConnect] Relinquishing Volumio State to another service Jun 23 11:48:03 schuur volumio[786]: [SpotifyConnect] Received stop Jun 23 11:48:03 schuur volumio[786]: info: CoreStateMachine::play index 0 Jun 23 11:48:03 schuur volumio[786]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 23 11:48:03 schuur volumio[786]: info: CoreStateMachine::stop Jun 23 11:48:03 schuur volumio[786]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 23 11:48:03 schuur volumio[786]: UNSET VOLATILE Jun 23 11:48:03 schuur volumio[786]: info: CoreStateMachine::updateTrackBlock Jun 23 11:48:03 schuur volumio[786]: info: CorePlayQueue::getTrackBlock Jun 23 11:48:03 schuur volumio[786]: info: CoreStateMachine::stPlaybackTimer Jun 23 11:48:03 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:48:03 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:48:03 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:48:03 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:48:03 schuur volumio[786]: info: CoreStateMachine::serviceStop Jun 23 11:48:03 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:48:03 schuur volumio[786]: info: CoreCommandRouter::serviceStop Jun 23 11:48:03 schuur volumio[786]: info: [1624448883155] ControllerWebradio::stop Jun 23 11:48:03 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand stop Jun 23 11:48:03 schuur volumio[786]: info: sendMpdCommand stop took 23 milliseconds Jun 23 11:48:03 schuur volumio[786]: info: CoreStateMachine::play index undefined Jun 23 11:48:03 schuur volumio[786]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 23 11:48:03 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:48:03 schuur volumio[786]: info: CoreStateMachine::startPlaybackTimer Jun 23 11:48:03 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:48:03 schuur volumio[786]: info: [1624448883189] ControllerWebradio::clearAddPlayTrack Jun 23 11:48:03 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand stop Jun 23 11:48:03 schuur volumio[786]: info: sendMpdCommand stop took 10 milliseconds Jun 23 11:48:03 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand clear Jun 23 11:48:03 schuur volumio[786]: info: Jun 23 11:48:03 schuur volumio[786]: ---------------------------- MPD announces system playlist update Jun 23 11:48:03 schuur volumio[786]: info: Ignoring MPD Status Update Jun 23 11:48:03 schuur volumio[786]: info: sendMpdCommand clear took 17 milliseconds Jun 23 11:48:03 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand load "http://stream.radionl.fm/radionl" Jun 23 11:48:03 schuur volumio[786]: error: updateQueue error: null Jun 23 11:48:03 schuur volumio[786]: info: ------------------------------ 16ms Jun 23 11:48:04 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand add "http://stream.radionl.fm/radionl" Jun 23 11:48:04 schuur volumio[786]: info: Jun 23 11:48:04 schuur volumio[786]: ---------------------------- MPD announces system playlist update Jun 23 11:48:04 schuur volumio[786]: info: Ignoring MPD Status Update Jun 23 11:48:04 schuur volumio[786]: info: sendMpdCommand add "http://stream.radionl.fm/radionl" took 9 milliseconds Jun 23 11:48:04 schuur volumio[786]: info: CoreStateMachine::setConsumeUpdateService mpd Jun 23 11:48:04 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand play Jun 23 11:48:04 schuur volumio[786]: info: ------------------------------ 18ms Jun 23 11:48:04 schuur volumio[786]: info: sendMpdCommand play took 13 milliseconds Jun 23 11:48:04 schuur volumio[786]: info: Jun 23 11:48:04 schuur volumio[786]: ---------------------------- MPD announces state update: player Jun 23 11:48:04 schuur volumio[786]: info: ControllerMpd::getState Jun 23 11:48:04 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand status Jun 23 11:48:04 schuur volumio[786]: info: Jun 23 11:48:04 schuur volumio[786]: ---------------------------- MPD announces system playlist update Jun 23 11:48:04 schuur volumio[786]: info: Ignoring MPD Status Update Jun 23 11:48:04 schuur volumio[786]: info: Jun 23 11:48:04 schuur volumio[786]: ---------------------------- MPD announces state update: player Jun 23 11:48:04 schuur volumio[786]: info: ControllerMpd::getState Jun 23 11:48:04 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand status Jun 23 11:48:04 schuur volumio[786]: info: sendMpdCommand status took 9 milliseconds Jun 23 11:48:04 schuur volumio[786]: verbose: ControllerMpd::parseState Jun 23 11:48:04 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 23 11:48:04 schuur volumio[786]: info: ------------------------------ 25ms Jun 23 11:48:04 schuur volumio[786]: info: sendMpdCommand status took 22 milliseconds Jun 23 11:48:04 schuur volumio[786]: info: sendMpdCommand playlistinfo took 11 milliseconds Jun 23 11:48:04 schuur volumio[786]: verbose: ControllerMpd::parseState Jun 23 11:48:04 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 23 11:48:04 schuur volumio[786]: verbose: ControllerMpd::parseTrackInfo Jun 23 11:48:04 schuur volumio[786]: info: ControllerMpd::pushState Jun 23 11:48:04 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:48:04 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:48:04 schuur volumio[786]: verbose: STATE SERVICE {"status":"play","position":0,"seek":487,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"radionl","artist":"RADIONL","album":null,"uri":"http://stream.radionl.fm/radionl","trackType":"fm/radionl"} Jun 23 11:48:04 schuur volumio[786]: verbose: CURRENT POSITION 0 Jun 23 11:48:04 schuur volumio[786]: info: CoreStateMachine::syncState stateService play Jun 23 11:48:04 schuur volumio[786]: info: CoreStateMachine::syncState currentStatus stop Jun 23 11:48:04 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:48:04 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:48:04 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:48:04 schuur volumio[786]: info: ------------------------------ 70ms Jun 23 11:48:05 schuur volumio[786]: info: sendMpdCommand playlistinfo took 65 milliseconds Jun 23 11:48:05 schuur volumio[786]: verbose: ControllerMpd::parseTrackInfo Jun 23 11:48:05 schuur volumio[786]: info: ControllerMpd::pushState Jun 23 11:48:05 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:48:05 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:48:05 schuur volumio[786]: verbose: STATE SERVICE {"status":"play","position":0,"seek":487,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"radionl","artist":"RADIONL","album":null,"uri":"http://stream.radionl.fm/radionl","trackType":"fm/radionl"} Jun 23 11:48:05 schuur volumio[786]: verbose: CURRENT POSITION 0 Jun 23 11:48:05 schuur volumio[786]: info: CoreStateMachine::syncState stateService play Jun 23 11:48:05 schuur volumio[786]: info: CoreStateMachine::syncState currentStatus play Jun 23 11:48:05 schuur volumio[786]: info: Received an update from plugin. extracting info from payload Jun 23 11:48:05 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:48:05 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:48:05 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:48:05 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:48:05 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:48:05 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:48:05 schuur volumio[786]: info: ------------------------------ 131ms Jun 23 11:48:06 schuur kernel: rpi_firmware_get_throttled: 7 callbacks suppressed Jun 23 11:48:06 schuur kernel: Under-voltage detected! (0x00050005) Jun 23 11:48:08 schuur volumio[786]: info: VolumeController::SetAlsaVolume25 Jun 23 11:48:08 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:48:08 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:48:08 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:48:10 schuur kernel: rpi_firmware_get_throttled: 7 callbacks suppressed Jun 23 11:48:10 schuur kernel: Voltage normalised (0x00000000) Jun 23 11:48:12 schuur kernel: Under-voltage detected! (0x00050005) Jun 23 11:48:15 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jun 23 11:48:16 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jun 23 11:48:23 schuur kernel: Voltage normalised (0x00000000) Jun 23 11:48:27 schuur volumio[786]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 23 11:48:27 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jun 23 11:48:28 schuur volumio[786]: info: Received Get System Version Jun 23 11:48:28 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 23 11:48:29 schuur kernel: Under-voltage detected! (0x00050005) Jun 23 11:48:31 schuur volumio[786]: info: CALLMETHOD: system_controller system savePrivacySettings [object Object] Jun 23 11:48:31 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , savePrivacySettings Jun 23 11:48:31 schuur volumio[786]: info: CoreCommandRouter::Reload Ui Jun 23 11:48:31 schuur sudo[2021]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 23 11:48:31 schuur sudo[2021]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:48:31 schuur sudo[2023]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 23 11:48:31 schuur sudo[2021]: pam_unix(sudo:session): session closed for user root Jun 23 11:48:31 schuur sudo[2023]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:48:31 schuur sudo[2023]: pam_unix(sudo:session): session closed for user root Jun 23 11:48:32 schuur volumio[786]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 23 11:48:32 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jun 23 11:48:32 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 23 11:48:32 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:48:32 schuur volumio[786]: info: CoreCommandRouter::volumioGetVisibleSources Jun 23 11:48:32 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 23 11:48:32 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 23 11:48:32 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 23 11:48:32 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 23 11:48:32 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 23 11:48:32 schuur volumio[786]: info: Received Get System Version Jun 23 11:48:32 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 23 11:48:34 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 23 11:48:36 schuur volumio[786]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 23 11:48:36 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jun 23 11:48:36 schuur volumio[786]: info: Received Get System Version Jun 23 11:48:36 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 23 11:48:37 schuur kernel: Voltage normalised (0x00000000) Jun 23 11:48:37 schuur volumio[786]: info: Jun 23 11:48:37 schuur volumio[786]: ---------------------------- MPD announces system playlist update Jun 23 11:48:37 schuur volumio[786]: info: Ignoring MPD Status Update Jun 23 11:48:37 schuur volumio[786]: info: Jun 23 11:48:37 schuur volumio[786]: ---------------------------- MPD announces state update: player Jun 23 11:48:37 schuur volumio[786]: info: ControllerMpd::getState Jun 23 11:48:37 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand status Jun 23 11:48:37 schuur volumio[786]: info: ------------------------------ 9ms Jun 23 11:48:37 schuur volumio[786]: info: sendMpdCommand status took 6 milliseconds Jun 23 11:48:37 schuur volumio[786]: verbose: ControllerMpd::parseState Jun 23 11:48:37 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 23 11:48:37 schuur volumio[786]: info: sendMpdCommand playlistinfo took 10 milliseconds Jun 23 11:48:37 schuur volumio[786]: verbose: ControllerMpd::parseTrackInfo Jun 23 11:48:37 schuur volumio[786]: info: ControllerMpd::pushState Jun 23 11:48:37 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 11:48:37 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 11:48:37 schuur volumio[786]: verbose: STATE SERVICE {"status":"play","position":0,"seek":33491,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"JOHN DE BEVER - LAAT ZE BEVEN","artist":"RADIONL","album":null,"uri":"http://stream.radionl.fm/radionl","trackType":"fm/radionl"} Jun 23 11:48:37 schuur volumio[786]: verbose: CURRENT POSITION 0 Jun 23 11:48:37 schuur volumio[786]: info: CoreStateMachine::syncState stateService play Jun 23 11:48:37 schuur volumio[786]: info: CoreStateMachine::syncState currentStatus play Jun 23 11:48:37 schuur volumio[786]: info: Received an update from plugin. extracting info from payload Jun 23 11:48:37 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:48:37 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:48:37 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:48:37 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 11:48:37 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 11:48:37 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 11:48:37 schuur volumio[786]: info: ------------------------------ 55ms Jun 23 11:48:41 schuur volumio-remote-updater[596]: No test mode Jun 23 11:48:41 schuur volumio[786]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Jun 23 11:48:43 schuur volumio[786]: info: CoreCommandRouter::Close All Modals sent Jun 23 11:48:53 schuur volumio[786]: info: CALLMETHOD: system_controller system savePrivacySettings [object Object] Jun 23 11:48:53 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , savePrivacySettings Jun 23 11:48:53 schuur volumio[786]: info: CoreCommandRouter::Reload Ui Jun 23 11:48:53 schuur sudo[2097]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 23 11:48:53 schuur sudo[2097]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:48:53 schuur sudo[2099]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 23 11:48:53 schuur sudo[2097]: pam_unix(sudo:session): session closed for user root Jun 23 11:48:53 schuur sudo[2099]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:48:53 schuur sudo[2099]: pam_unix(sudo:session): session closed for user root Jun 23 11:48:53 schuur volumio[786]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 23 11:48:53 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jun 23 11:48:53 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 23 11:48:53 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 11:48:53 schuur volumio[786]: info: CoreCommandRouter::volumioGetVisibleSources Jun 23 11:48:53 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 23 11:48:53 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 23 11:48:53 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 23 11:48:53 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 23 11:48:53 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 23 11:48:53 schuur volumio[786]: info: Received Get System Version Jun 23 11:48:53 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 23 11:48:55 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 23 11:48:56 schuur volumio[786]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 23 11:48:57 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Jun 23 11:48:57 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 23 11:48:57 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jun 23 11:48:57 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 23 11:48:57 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 23 11:48:57 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 23 11:48:57 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 23 11:48:57 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 23 11:48:57 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 23 11:48:57 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 23 11:48:57 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Jun 23 11:48:57 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Jun 23 11:49:05 schuur volumio[786]: info: CALLMETHOD: music_service mpd savePlaybackOptions [object Object] Jun 23 11:49:05 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: mpd , savePlaybackOptions Jun 23 11:49:06 schuur sudo[2173]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 23 11:49:06 schuur sudo[2173]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:49:06 schuur sudo[2173]: pam_unix(sudo:session): session closed for user root Jun 23 11:49:06 schuur sudo[2176]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 23 11:49:06 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:49:06 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:49:06 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:49:06 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:49:06 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:49:06 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:49:06 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:49:06 schuur sudo[2176]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 11:49:06 schuur systemd[1]: Stopping Music Player Daemon... Jun 23 11:49:06 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 23 11:49:06 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 23 11:49:06 schuur volumio[786]: info: MPD Permissions set Jun 23 11:49:06 schuur systemd[1]: Starting Music Player Daemon... Jun 23 11:49:06 schuur volumio[786]: error: Upnp client error: Error: This socket has been ended by the other party Jun 23 11:49:07 schuur systemd[1]: Started Music Player Daemon. Jun 23 11:49:07 schuur sudo[2176]: pam_unix(sudo:session): session closed for user root Jun 23 11:49:07 schuur volumio[786]: error: updateQueue error: null Jun 23 11:57:37 schuur systemd[1]: Starting Cleanup of Temporary Directories... Jun 23 11:57:37 schuur systemd[1]: Started Cleanup of Temporary Directories. Jun 23 12:22:10 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jun 23 12:22:10 schuur volumio[786]: info: CoreCommandRouter::volumioGetQueue Jun 23 12:22:10 schuur volumio[786]: info: CoreStateMachine::getQueue Jun 23 12:22:10 schuur volumio[786]: info: CorePlayQueue::getQueue Jun 23 12:22:10 schuur volumio[786]: info: Listing playlists Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Connecting to AP "gew1-accesspoint-a-hb0n.ap.spotify.com:443" Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Authenticated as "21hptgkjwzcroc6eo5gh3whki" ! Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Setting up new mixer: card:hw:1 mixer:Headphone index:0 Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Alsa Mixer info min: -10239 (MilliBel(-9999999)[dB]) -- max: 400 (MilliBel(400)[dB]) HW: true Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Using alsa sink Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Country: "NL" Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Metadata pipe established Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Event: Volume { volume_to_mixer: 0 } Jun 23 12:22:24 schuur volumio[786]: [SpotifyConnect] 0 Jun 23 12:22:24 schuur volumio[786]: [SpotifyConnect] Volume: Spotify:0 Volumio: 0 Jun 23 12:22:24 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Fetching autoplay context uri Jun 23 12:22:24 schuur volumio[786]: [SpotifyConnect] A connect session has begun Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Event: SessionActive { became_active_at: 1624450944721 } Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : SessionActive! Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 227505564021348702370395239071615962111, audio_type: Track } } Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 227505564021348702370395239071615962111, audio_type: Track } } Jun 23 12:22:24 schuur volumio[786]: [SpotifyConnect] Device palyback is active! Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 12:22:24 schuur volumio[786]: [SpotifyConnect] Currently active: webradio Jun 23 12:22:24 schuur volumio[786]: [SpotifyConnect] Stopping currently active service Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::volumioStop Jun 23 12:22:24 schuur volumio[786]: info: CoreStateMachine::stop Jun 23 12:22:24 schuur volumio[786]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 23 12:22:24 schuur volumio[786]: UNSET VOLATILE Jun 23 12:22:24 schuur volumio[786]: info: CoreStateMachine::stPlaybackTimer Jun 23 12:22:24 schuur volumio[786]: info: CoreStateMachine::updateTrackBlock Jun 23 12:22:24 schuur volumio[786]: info: CorePlayQueue::getTrackBlock Jun 23 12:22:24 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:22:24 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:22:24 schuur volumio[786]: info: CoreStateMachine::serviceStop Jun 23 12:22:24 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::serviceStop Jun 23 12:22:24 schuur volumio[786]: info: [1624450944751] ControllerWebradio::stop Jun 23 12:22:24 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand stop Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : error 403 for uri hm://keymaster/token/authenticated?client_id=4ced2e7c73484127be5d36015752eb43&scope=streaming,user-read-playback-state,user-modify-playback-state,user-read-currently-playing,user-read-private Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Error: MercuryError Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Autoplay uri resolved to <"spotify:station:album:4BHfl4OpAhzyFs275AOiv2"> Jun 23 12:22:24 schuur volumio[1410]: [Vollibrespot] : Resolving uri "spotify:station:album:4BHfl4OpAhzyFs275AOiv2" Jun 23 12:22:24 schuur volumio[1410]: thread 'main' panicked at 'cannot poll Map twice', /build/cache/registry/src/github.com-1ecc6299db9ec823/futures-0.1.29/src/future/map.rs:35:29 Jun 23 12:22:24 schuur volumio[1410]: stack backtrace: Jun 23 12:22:24 schuur volumio[786]: info: sendMpdCommand stop took 30 milliseconds Jun 23 12:22:24 schuur volumio[786]: [SpotifyConnect] Vollibrespot Active Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 12:22:24 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:22:24 schuur volumio[786]: [SpotifyConnect] Currently active: webradio Jun 23 12:22:24 schuur volumio[786]: [SpotifyConnect] Setting Volatile state to Volspotconnect2 Jun 23 12:22:24 schuur volumio[786]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 12:22:24 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 12:22:24 schuur volumio[786]: [SpotifyConnect] Currently active: volspotconnect2 Jun 23 12:22:24 schuur volumio[786]: [SpotifyConnect] Pushing new state :: true Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 12:22:24 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:22:24 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:22:25 schuur volumio[1410]: 0: 0x9b833c - backtrace::backtrace::libunwind::trace::hae21a072c81e5842 Jun 23 12:22:25 schuur volumio[1410]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86 Jun 23 12:22:25 schuur volumio[1410]: 1: 0x9b833c - backtrace::backtrace::trace_unsynchronized::h0f9b260087e46e47 Jun 23 12:22:25 schuur volumio[1410]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66 Jun 23 12:22:25 schuur volumio[1410]: 2: 0x9b833c - std::sys_common::backtrace::_print_fmt::hbf1a59173a7860c3 Jun 23 12:22:25 schuur volumio[1410]: at src/libstd/sys_common/backtrace.rs:78 Jun 23 12:22:25 schuur volumio[1410]: 3: 0x9b833c - ::fmt::he1a5d6f378e506c4 Jun 23 12:22:25 schuur volumio[1410]: at src/libstd/sys_common/backtrace.rs:59 Jun 23 12:22:25 schuur volumio[1410]: 4: 0x9d8d5c - core::fmt::write::hb37ae5a5e0b70623 Jun 23 12:22:25 schuur volumio[1410]: at src/libcore/fmt/mod.rs:1076 Jun 23 12:22:25 schuur volumio[1410]: 5: 0x9b1c64 - std::io::Write::write_fmt::ha24bb3f5a858327b Jun 23 12:22:25 schuur volumio[1410]: at src/libstd/io/mod.rs:1537 Jun 23 12:22:25 schuur volumio[1410]: 6: 0x9ba974 - std::sys_common::backtrace::_print::h47b03aa1342833e3 Jun 23 12:22:25 schuur volumio[1410]: at src/libstd/sys_common/backtrace.rs:62 Jun 23 12:22:25 schuur volumio[1410]: 7: 0x9ba974 - std::sys_common::backtrace::print::h2217cbc390250439 Jun 23 12:22:25 schuur volumio[1410]: at src/libstd/sys_common/backtrace.rs:49 Jun 23 12:22:25 schuur volumio[1410]: 8: 0x9ba974 - std::panicking::default_hook::{{closure}}::h179f5229ea1c8e30 Jun 23 12:22:25 schuur volumio[1410]: at src/libstd/panicking.rs:198 Jun 23 12:22:25 schuur volumio[1410]: 9: 0x9ba640 - std::panicking::default_hook::h46ab82039cbc65eb Jun 23 12:22:25 schuur volumio[1410]: at src/libstd/panicking.rs:217 Jun 23 12:22:25 schuur volumio[1410]: 10: 0x9bb054 - std::panicking::rust_panic_with_hook::h7326c48419bc7c33 Jun 23 12:22:25 schuur volumio[1410]: at src/libstd/panicking.rs:526 Jun 23 12:22:25 schuur volumio[1410]: 11: 0x9bac54 - rust_begin_unwind Jun 23 12:22:25 schuur volumio[1410]: at src/libstd/panicking.rs:437 Jun 23 12:22:25 schuur volumio[1410]: 12: 0x9d6594 - core::panicking::panic_fmt::ha292e19d5ae716ed Jun 23 12:22:25 schuur volumio[1410]: at src/libcore/panicking.rs:85 Jun 23 12:22:25 schuur volumio[1410]: 13: 0x9d6370 - core::option::expect_failed::he9e39f8f5ba60ecb Jun 23 12:22:25 schuur volumio[1410]: at src/libcore/option.rs:1261 Jun 23 12:22:25 schuur systemd[1]: volspotconnect2.service: main process exited, code=exited, status=101/n/a Jun 23 12:22:25 schuur systemd[1]: Unit volspotconnect2.service entered failed state. Jun 23 12:22:25 schuur volumio[786]: [SpotifyConnect] Device palyback is inactive Jun 23 12:22:25 schuur volumio[786]: [SpotifyConnect] Device Session is_active: true Jun 23 12:22:25 schuur volumio[786]: [SpotifyConnect] Sink released Jun 23 12:22:25 schuur volumio[786]: [SpotifyConnect] Not pushing Pause { active: true, isStopping: true} Jun 23 12:22:25 schuur volumio[786]: [SpotifyConnect] ResolvedStop in 2062s 342.42ms Jun 23 12:22:25 schuur volumio[786]: [SpotifyConnect] ResolvedStop in 2062s 40.71ms Jun 23 12:22:25 schuur volumio[1410]: 14: 0x6acbf8 - as futures::future::Future>::poll::h3d56b212ca27d9e4 Jun 23 12:22:25 schuur volumio[1410]: 15: 0x5623a4 - ::poll::ha2e91a6b75c719f3 Jun 23 12:22:25 schuur volumio[1410]: 16: 0x4d8ca4 - ::poll::hc5e7d2d1b7dbef13 Jun 23 12:22:25 schuur volumio[1410]: 17: 0x4a0844 - futures::task_impl::std::set::h8f081cf0436110c9 Jun 23 12:22:25 schuur volumio[1410]: 18: 0x4b441c - std::thread::local::LocalKey::with::h711a13323aafc45a Jun 23 12:22:25 schuur volumio[1410]: 19: 0x490a50 - tokio_current_thread::Entered

::block_on::h339073902a399eb7 Jun 23 12:22:25 schuur volumio[1410]: 20: 0x4b4e00 - std::thread::local::LocalKey::with::hff64c13ccfec5327 Jun 23 12:22:25 schuur volumio[1410]: 21: 0x4c120c - tokio_reactor::with_default::h7ef12e65cb103d2f Jun 23 12:22:25 schuur volumio[1410]: 22: 0x4949f8 - tokio::runtime::current_thread::runtime::Runtime::block_on::h043f136d6b8cf48f Jun 23 12:22:25 schuur volumio[1410]: 23: 0x4da2c8 - vollibrespot::main::h02a0d49d4cc5eaa6 Jun 23 12:22:25 schuur volumio[1410]: 24: 0x4c1f18 - std::rt::lang_start::{{closure}}::h279cd2b7929fdba7 Jun 23 12:22:25 schuur volumio[1410]: 25: 0x9bb404 - std::rt::lang_start_internal::{{closure}}::he93bfc404849b78a Jun 23 12:22:25 schuur volumio[1410]: at src/libstd/rt.rs:52 Jun 23 12:22:25 schuur volumio[1410]: 26: 0x9bb404 - std::panicking::try::do_call::h6e9e98f4078affb0 Jun 23 12:22:25 schuur volumio[1410]: at src/libstd/panicking.rs:348 Jun 23 12:22:25 schuur volumio[1410]: 27: 0x9bb404 - std::panicking::try::h2e68d4f7f799a6df Jun 23 12:22:25 schuur volumio[1410]: at src/libstd/panicking.rs:325 Jun 23 12:22:25 schuur volumio[1410]: 28: 0x9bb404 - std::panic::catch_unwind::h8880a4c07cc66391 Jun 23 12:22:25 schuur volumio[1410]: at src/libstd/panic.rs:394 Jun 23 12:22:25 schuur volumio[1410]: 29: 0x9bb404 - std::rt::lang_start_internal::hf4ae2140248bf16b Jun 23 12:22:25 schuur volumio[1410]: at src/libstd/rt.rs:51 Jun 23 12:22:25 schuur volumio[1410]: 30: 0x4dad84 - main Jun 23 12:22:25 schuur volumio[1410]: 31: 0x76c4e678 - __libc_start_main Jun 23 12:22:25 schuur volumio[1410]: [Vollibrespot] : EventSender disconnected Jun 23 12:22:25 schuur kernel: rpi_firmware_get_throttled: 3 callbacks suppressed Jun 23 12:22:25 schuur kernel: Under-voltage detected! (0x00050005) Jun 23 12:22:27 schuur systemd[1]: volspotconnect2.service holdoff time over, scheduling restart. Jun 23 12:22:27 schuur systemd[1]: Stopping Volspotconnect2 Daemon... Jun 23 12:22:27 schuur systemd[1]: Starting Volspotconnect2 Daemon... Jun 23 12:22:27 schuur systemd[1]: Started Volspotconnect2 Daemon. Jun 23 12:22:27 schuur volumio[6781]: vollibrespot v0.2.2 cd96399 2020-10-07 (librespot 08d8bcc 2020-10-07) -- Built On 2020-10-07 Jun 23 12:22:27 schuur volumio[6781]: Reading Config from "volspotify.toml" Jun 23 12:22:27 schuur volumio[6781]: [Vollibrespot] : Using Alsa backend with device: plughw:1 Jun 23 12:22:27 schuur volumio[6781]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" } Jun 23 12:22:29 schuur volumio[786]: info: CoreCommandRouter::volumioVolatilePlay Jun 23 12:22:29 schuur volumio[786]: info: CoreStateMachine::volatilePlay Jun 23 12:22:29 schuur volumio[786]: [SpotifyConnect] Received play: Jun 23 12:22:29 schuur volumio[786]: [SpotifyConnect] Playing on: undefined Jun 23 12:22:29 schuur volumio[786]: [SpotifyConnect] Unauthorized Jun 23 12:22:32 schuur kernel: rpi_firmware_get_throttled: 3 callbacks suppressed Jun 23 12:22:32 schuur kernel: Voltage normalised (0x00000000) Jun 23 12:22:37 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jun 23 12:22:38 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jun 23 12:22:39 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jun 23 12:22:39 schuur volumio[786]: info: CoreCommandRouter::volumioReplaceandPlayItems Jun 23 12:22:39 schuur volumio[786]: info: CoreStateMachine::ClearQueue Jun 23 12:22:39 schuur volumio[786]: info: CoreStateMachine::stop Jun 23 12:22:39 schuur volumio[786]: info: CoreStateMachine::serviceStop Jun 23 12:22:39 schuur volumio[786]: info: CoreCommandRouter::serviceStop Jun 23 12:22:39 schuur volumio[786]: [SpotifyConnect] Received stop Jun 23 12:22:39 schuur volumio[786]: info: CorePlayQueue::clearPlayQueue Jun 23 12:22:39 schuur volumio[786]: info: CorePlayQueue::saveQueue Jun 23 12:22:39 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:22:39 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:22:39 schuur volumio[786]: info: CoreCommandRouter::volumioPushQueue Jun 23 12:22:39 schuur volumio[786]: info: CoreStateMachine::addQueueItems Jun 23 12:22:39 schuur volumio[786]: info: CorePlayQueue::addQueueItems Jun 23 12:22:39 schuur volumio[786]: info: Adding Item to queue: http://opml.radiotime.com/Tune.ashx?id=s54815 Jun 23 12:22:39 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri Jun 23 12:22:40 schuur volumio[786]: info: CorePlayQueue::saveQueue Jun 23 12:22:40 schuur volumio[786]: info: CoreCommandRouter::volumioPushQueue Jun 23 12:22:40 schuur volumio[786]: info: CoreStateMachine::updateTrackBlock Jun 23 12:22:40 schuur volumio[786]: info: CorePlayQueue::getTrackBlock Jun 23 12:22:40 schuur volumio[786]: info: CoreCommandRouter::volumioPlay Jun 23 12:22:40 schuur volumio[786]: UNSET VOLATILE Jun 23 12:22:40 schuur volumio[786]: [SpotifyConnect] unSetVolatile called Jun 23 12:22:40 schuur volumio[786]: [SpotifyConnect] Relinquishing Volumio State to another service Jun 23 12:22:40 schuur volumio[786]: [SpotifyConnect] Received stop Jun 23 12:22:40 schuur volumio[786]: info: CoreStateMachine::play index 0 Jun 23 12:22:40 schuur volumio[786]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 23 12:22:40 schuur volumio[786]: info: CoreStateMachine::stop Jun 23 12:22:40 schuur volumio[786]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 23 12:22:40 schuur volumio[786]: UNSET VOLATILE Jun 23 12:22:40 schuur volumio[786]: info: CoreStateMachine::updateTrackBlock Jun 23 12:22:40 schuur volumio[786]: info: CorePlayQueue::getTrackBlock Jun 23 12:22:40 schuur volumio[786]: info: CoreStateMachine::stPlaybackTimer Jun 23 12:22:40 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:22:40 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:22:40 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:22:40 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:22:40 schuur volumio[786]: info: CoreStateMachine::serviceStop Jun 23 12:22:40 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:22:40 schuur volumio[786]: info: CoreCommandRouter::serviceStop Jun 23 12:22:40 schuur volumio[786]: info: [1624450960360] ControllerWebradio::stop Jun 23 12:22:40 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand stop Jun 23 12:22:40 schuur volumio[786]: info: sendMpdCommand stop took 22 milliseconds Jun 23 12:22:40 schuur volumio[786]: info: CoreStateMachine::play index undefined Jun 23 12:22:40 schuur volumio[786]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 23 12:22:40 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:22:40 schuur volumio[786]: info: CoreStateMachine::startPlaybackTimer Jun 23 12:22:40 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:22:40 schuur volumio[786]: info: [1624450960389] ControllerWebradio::clearAddPlayTrack Jun 23 12:22:40 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand stop Jun 23 12:22:40 schuur volumio[786]: info: sendMpdCommand stop took 15 milliseconds Jun 23 12:22:40 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand clear Jun 23 12:22:40 schuur volumio[786]: info: Jun 23 12:22:40 schuur volumio[786]: ---------------------------- MPD announces system playlist update Jun 23 12:22:40 schuur volumio[786]: info: Ignoring MPD Status Update Jun 23 12:22:40 schuur volumio[786]: info: sendMpdCommand clear took 9 milliseconds Jun 23 12:22:40 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand load "http://stream.radionl.fm/radionl" Jun 23 12:22:40 schuur volumio[786]: error: updateQueue error: null Jun 23 12:22:40 schuur volumio[786]: info: ------------------------------ 18ms Jun 23 12:22:41 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand add "http://stream.radionl.fm/radionl" Jun 23 12:22:41 schuur volumio[786]: info: Jun 23 12:22:41 schuur volumio[786]: ---------------------------- MPD announces system playlist update Jun 23 12:22:41 schuur volumio[786]: info: Ignoring MPD Status Update Jun 23 12:22:41 schuur volumio[786]: info: sendMpdCommand add "http://stream.radionl.fm/radionl" took 8 milliseconds Jun 23 12:22:41 schuur volumio[786]: info: CoreStateMachine::setConsumeUpdateService mpd Jun 23 12:22:41 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand play Jun 23 12:22:41 schuur volumio[786]: info: ------------------------------ 40ms Jun 23 12:22:41 schuur volumio[786]: info: sendMpdCommand play took 48 milliseconds Jun 23 12:22:42 schuur volumio[786]: info: Jun 23 12:22:42 schuur volumio[786]: ---------------------------- MPD announces state update: player Jun 23 12:22:42 schuur volumio[786]: info: ControllerMpd::getState Jun 23 12:22:42 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand status Jun 23 12:22:42 schuur volumio[786]: info: Jun 23 12:22:42 schuur volumio[786]: ---------------------------- MPD announces system playlist update Jun 23 12:22:42 schuur volumio[786]: info: Ignoring MPD Status Update Jun 23 12:22:42 schuur volumio[786]: info: Jun 23 12:22:42 schuur volumio[786]: ---------------------------- MPD announces system playlist update Jun 23 12:22:42 schuur volumio[786]: info: Ignoring MPD Status Update Jun 23 12:22:42 schuur volumio[786]: info: Jun 23 12:22:42 schuur volumio[786]: ---------------------------- MPD announces state update: player Jun 23 12:22:42 schuur kernel: Under-voltage detected! (0x00050005) Jun 23 12:22:42 schuur volumio[786]: info: sendMpdCommand status took 28 milliseconds Jun 23 12:22:42 schuur volumio[786]: info: ControllerMpd::getState Jun 23 12:22:42 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand status Jun 23 12:22:42 schuur volumio[786]: verbose: ControllerMpd::parseState Jun 23 12:22:42 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 23 12:22:42 schuur volumio[786]: info: ------------------------------ 25ms Jun 23 12:22:42 schuur volumio[786]: info: ------------------------------ 25ms Jun 23 12:22:42 schuur volumio[786]: info: sendMpdCommand status took 18 milliseconds Jun 23 12:22:42 schuur volumio[786]: info: sendMpdCommand playlistinfo took 16 milliseconds Jun 23 12:22:42 schuur volumio[786]: verbose: ControllerMpd::parseState Jun 23 12:22:42 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 23 12:22:42 schuur volumio[786]: verbose: ControllerMpd::parseTrackInfo Jun 23 12:22:42 schuur volumio[786]: info: ControllerMpd::pushState Jun 23 12:22:42 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 12:22:42 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:22:42 schuur volumio[786]: verbose: STATE SERVICE {"status":"play","position":0,"seek":464,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"radionl","artist":"RADIONL","album":null,"uri":"http://stream.radionl.fm/radionl","trackType":"fm/radionl"} Jun 23 12:22:42 schuur volumio[786]: verbose: CURRENT POSITION 0 Jun 23 12:22:42 schuur volumio[786]: info: CoreStateMachine::syncState stateService play Jun 23 12:22:42 schuur volumio[786]: info: CoreStateMachine::syncState currentStatus stop Jun 23 12:22:42 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:22:42 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:22:42 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:22:42 schuur volumio[786]: info: ------------------------------ 86ms Jun 23 12:22:42 schuur volumio[786]: info: sendMpdCommand playlistinfo took 40 milliseconds Jun 23 12:22:42 schuur volumio[786]: verbose: ControllerMpd::parseTrackInfo Jun 23 12:22:42 schuur volumio[786]: info: ControllerMpd::pushState Jun 23 12:22:42 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 12:22:42 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:22:42 schuur volumio[786]: verbose: STATE SERVICE {"status":"play","position":0,"seek":487,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"radionl","artist":"RADIONL","album":null,"uri":"http://stream.radionl.fm/radionl","trackType":"fm/radionl"} Jun 23 12:22:42 schuur volumio[786]: verbose: CURRENT POSITION 0 Jun 23 12:22:42 schuur volumio[786]: info: CoreStateMachine::syncState stateService play Jun 23 12:22:42 schuur volumio[786]: info: CoreStateMachine::syncState currentStatus play Jun 23 12:22:42 schuur volumio[786]: info: Received an update from plugin. extracting info from payload Jun 23 12:22:42 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:22:42 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:22:42 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:22:42 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:22:42 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:22:42 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:22:42 schuur volumio[786]: info: ------------------------------ 100ms Jun 23 12:22:46 schuur kernel: Voltage normalised (0x00000000) Jun 23 12:23:01 schuur kernel: Under-voltage detected! (0x00050005) Jun 23 12:23:01 schuur volumio[786]: info: Jun 23 12:23:01 schuur volumio[786]: ---------------------------- MPD announces system playlist update Jun 23 12:23:01 schuur volumio[786]: info: Ignoring MPD Status Update Jun 23 12:23:01 schuur volumio[786]: info: Jun 23 12:23:01 schuur volumio[786]: ---------------------------- MPD announces state update: player Jun 23 12:23:01 schuur volumio[786]: info: ControllerMpd::getState Jun 23 12:23:01 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand status Jun 23 12:23:01 schuur volumio[786]: info: ------------------------------ 9ms Jun 23 12:23:01 schuur volumio[786]: info: sendMpdCommand status took 16 milliseconds Jun 23 12:23:01 schuur volumio[786]: verbose: ControllerMpd::parseState Jun 23 12:23:01 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 23 12:23:01 schuur volumio[786]: info: sendMpdCommand playlistinfo took 16 milliseconds Jun 23 12:23:01 schuur volumio[786]: verbose: ControllerMpd::parseTrackInfo Jun 23 12:23:01 schuur volumio[786]: info: ControllerMpd::pushState Jun 23 12:23:01 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 12:23:01 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:23:01 schuur volumio[786]: verbose: STATE SERVICE {"status":"play","position":0,"seek":19989,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"RADIONL - ALTIJD AAN!","artist":"RADIONL","album":null,"uri":"http://stream.radionl.fm/radionl","trackType":"fm/radionl"} Jun 23 12:23:01 schuur volumio[786]: verbose: CURRENT POSITION 0 Jun 23 12:23:01 schuur volumio[786]: info: CoreStateMachine::syncState stateService play Jun 23 12:23:01 schuur volumio[786]: info: CoreStateMachine::syncState currentStatus play Jun 23 12:23:01 schuur volumio[786]: info: Received an update from plugin. extracting info from payload Jun 23 12:23:01 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:23:01 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:23:01 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:23:01 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:23:01 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:23:01 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:23:02 schuur volumio[786]: info: ------------------------------ 77ms Jun 23 12:23:11 schuur kernel: Voltage normalised (0x00000000) Jun 23 12:24:59 schuur volumio[786]: info: Jun 23 12:24:59 schuur volumio[786]: ---------------------------- MPD announces system playlist update Jun 23 12:24:59 schuur volumio[786]: info: Ignoring MPD Status Update Jun 23 12:24:59 schuur volumio[786]: info: Jun 23 12:24:59 schuur volumio[786]: ---------------------------- MPD announces state update: player Jun 23 12:24:59 schuur volumio[786]: info: ControllerMpd::getState Jun 23 12:24:59 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand status Jun 23 12:24:59 schuur volumio[786]: info: ------------------------------ 9ms Jun 23 12:24:59 schuur volumio[786]: info: sendMpdCommand status took 9 milliseconds Jun 23 12:24:59 schuur volumio[786]: verbose: ControllerMpd::parseState Jun 23 12:24:59 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 23 12:24:59 schuur volumio[786]: info: sendMpdCommand playlistinfo took 10 milliseconds Jun 23 12:24:59 schuur volumio[786]: verbose: ControllerMpd::parseTrackInfo Jun 23 12:24:59 schuur volumio[786]: info: ControllerMpd::pushState Jun 23 12:24:59 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 12:24:59 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:24:59 schuur volumio[786]: verbose: STATE SERVICE {"status":"play","position":0,"seek":137607,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"PETER BEENSE & MELANIE - HET VOELT GOED","artist":"RADIONL","album":null,"uri":"http://stream.radionl.fm/radionl","trackType":"fm/radionl"} Jun 23 12:24:59 schuur volumio[786]: verbose: CURRENT POSITION 0 Jun 23 12:24:59 schuur volumio[786]: info: CoreStateMachine::syncState stateService play Jun 23 12:24:59 schuur volumio[786]: info: CoreStateMachine::syncState currentStatus play Jun 23 12:24:59 schuur volumio[786]: info: Received an update from plugin. extracting info from payload Jun 23 12:24:59 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:24:59 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:24:59 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:24:59 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:24:59 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:24:59 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:24:59 schuur volumio[786]: info: ------------------------------ 50ms Jun 23 12:27:58 schuur kernel: rpi_firmware_get_throttled: 4 callbacks suppressed Jun 23 12:27:58 schuur kernel: Under-voltage detected! (0x00050005) Jun 23 12:28:02 schuur kernel: rpi_firmware_get_throttled: 4 callbacks suppressed Jun 23 12:28:02 schuur kernel: Voltage normalised (0x00000000) Jun 23 12:28:21 schuur kernel: Under-voltage detected! (0x00050005) Jun 23 12:28:27 schuur kernel: Voltage normalised (0x00000000) Jun 23 12:28:46 schuur kernel: Under-voltage detected! (0x00050005) Jun 23 12:28:50 schuur kernel: Voltage normalised (0x00000000) Jun 23 12:28:59 schuur volumio[786]: info: Jun 23 12:28:59 schuur volumio[786]: ---------------------------- MPD announces system playlist update Jun 23 12:28:59 schuur volumio[786]: info: Ignoring MPD Status Update Jun 23 12:28:59 schuur volumio[786]: info: Jun 23 12:28:59 schuur volumio[786]: ---------------------------- MPD announces state update: player Jun 23 12:28:59 schuur volumio[786]: info: ControllerMpd::getState Jun 23 12:28:59 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand status Jun 23 12:28:59 schuur volumio[786]: info: ------------------------------ 6ms Jun 23 12:28:59 schuur volumio[786]: info: sendMpdCommand status took 3 milliseconds Jun 23 12:28:59 schuur volumio[786]: verbose: ControllerMpd::parseState Jun 23 12:28:59 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 23 12:28:59 schuur volumio[786]: info: sendMpdCommand playlistinfo took 7 milliseconds Jun 23 12:28:59 schuur volumio[786]: verbose: ControllerMpd::parseTrackInfo Jun 23 12:28:59 schuur volumio[786]: info: ControllerMpd::pushState Jun 23 12:28:59 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 12:28:59 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:28:59 schuur volumio[786]: verbose: STATE SERVICE {"status":"play","position":0,"seek":377199,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"RADIONL - ALTIJD AAN!","artist":"RADIONL","album":null,"uri":"http://stream.radionl.fm/radionl","trackType":"fm/radionl"} Jun 23 12:28:59 schuur volumio[786]: verbose: CURRENT POSITION 0 Jun 23 12:28:59 schuur volumio[786]: info: CoreStateMachine::syncState stateService play Jun 23 12:28:59 schuur volumio[786]: info: CoreStateMachine::syncState currentStatus play Jun 23 12:28:59 schuur volumio[786]: info: Received an update from plugin. extracting info from payload Jun 23 12:28:59 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:28:59 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:28:59 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:28:59 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:28:59 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:28:59 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:28:59 schuur volumio[786]: info: ------------------------------ 45ms Jun 23 12:31:46 schuur volumio[786]: info: Jun 23 12:31:46 schuur volumio[786]: ---------------------------- MPD announces system playlist update Jun 23 12:31:46 schuur volumio[786]: info: Ignoring MPD Status Update Jun 23 12:31:46 schuur volumio[786]: info: Jun 23 12:31:46 schuur volumio[786]: ---------------------------- MPD announces state update: player Jun 23 12:31:46 schuur volumio[786]: info: ControllerMpd::getState Jun 23 12:31:46 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand status Jun 23 12:31:46 schuur volumio[786]: info: ------------------------------ 6ms Jun 23 12:31:46 schuur volumio[786]: info: sendMpdCommand status took 9 milliseconds Jun 23 12:31:46 schuur volumio[786]: verbose: ControllerMpd::parseState Jun 23 12:31:46 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 23 12:31:46 schuur volumio[786]: info: sendMpdCommand playlistinfo took 10 milliseconds Jun 23 12:31:46 schuur volumio[786]: verbose: ControllerMpd::parseTrackInfo Jun 23 12:31:46 schuur volumio[786]: info: ControllerMpd::pushState Jun 23 12:31:46 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 12:31:46 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:31:46 schuur volumio[786]: verbose: STATE SERVICE {"status":"play","position":0,"seek":544934,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"RADIONL - ALTIJD AAN!","artist":"RADIONL","album":null,"uri":"http://stream.radionl.fm/radionl","trackType":"fm/radionl"} Jun 23 12:31:46 schuur volumio[786]: verbose: CURRENT POSITION 0 Jun 23 12:31:46 schuur volumio[786]: info: CoreStateMachine::syncState stateService play Jun 23 12:31:46 schuur volumio[786]: info: CoreStateMachine::syncState currentStatus play Jun 23 12:31:46 schuur volumio[786]: info: Received an update from plugin. extracting info from payload Jun 23 12:31:46 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:31:46 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:31:46 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:31:46 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:31:46 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:31:46 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:31:46 schuur volumio[786]: info: ------------------------------ 52ms Jun 23 12:32:07 schuur volumio[786]: info: Jun 23 12:32:07 schuur volumio[786]: ---------------------------- MPD announces system playlist update Jun 23 12:32:07 schuur volumio[786]: info: Ignoring MPD Status Update Jun 23 12:32:07 schuur volumio[786]: info: Jun 23 12:32:07 schuur volumio[786]: ---------------------------- MPD announces state update: player Jun 23 12:32:07 schuur volumio[786]: info: ControllerMpd::getState Jun 23 12:32:07 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand status Jun 23 12:32:07 schuur volumio[786]: info: ------------------------------ 6ms Jun 23 12:32:07 schuur volumio[786]: info: sendMpdCommand status took 9 milliseconds Jun 23 12:32:07 schuur volumio[786]: verbose: ControllerMpd::parseState Jun 23 12:32:07 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 23 12:32:07 schuur volumio[786]: info: sendMpdCommand playlistinfo took 10 milliseconds Jun 23 12:32:07 schuur volumio[786]: verbose: ControllerMpd::parseTrackInfo Jun 23 12:32:07 schuur volumio[786]: info: ControllerMpd::pushState Jun 23 12:32:07 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 12:32:07 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:32:07 schuur volumio[786]: verbose: STATE SERVICE {"status":"play","position":0,"seek":565942,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"RADIONL - ALTIJD AAN!","artist":"RADIONL","album":null,"uri":"http://stream.radionl.fm/radionl","trackType":"fm/radionl"} Jun 23 12:32:07 schuur volumio[786]: verbose: CURRENT POSITION 0 Jun 23 12:32:07 schuur volumio[786]: info: CoreStateMachine::syncState stateService play Jun 23 12:32:07 schuur volumio[786]: info: CoreStateMachine::syncState currentStatus play Jun 23 12:32:07 schuur volumio[786]: info: Received an update from plugin. extracting info from payload Jun 23 12:32:07 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:32:07 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:32:07 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:32:07 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:32:07 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:32:07 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:32:07 schuur volumio[786]: info: ------------------------------ 51ms Jun 23 12:32:50 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 12:32:50 schuur volumio[786]: info: CoreCommandRouter::volumioGetQueue Jun 23 12:32:50 schuur volumio[786]: info: CoreStateMachine::getQueue Jun 23 12:32:50 schuur volumio[786]: info: CorePlayQueue::getQueue Jun 23 12:32:50 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , getHwuuid Jun 23 12:32:55 schuur volumio[6781]: [Vollibrespot] : Connecting to AP "gew1-accesspoint-a-shch.ap.spotify.com:443" Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : Authenticated as "21hptgkjwzcroc6eo5gh3whki" ! Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : Setting up new mixer: card:hw:1 mixer:Headphone index:0 Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : Alsa Mixer info min: -10239 (MilliBel(-9999999)[dB]) -- max: 400 (MilliBel(400)[dB]) HW: true Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : Metadata pipe established Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : Country: "NL" Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : Using alsa sink Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : Event: Volume { volume_to_mixer: 0 } Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] 0 Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] Volume: Spotify:0 Volumio: 0 Jun 23 12:32:56 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : Fetching autoplay context uri Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : Event: SessionActive { became_active_at: 1624451576348 } Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : SessionActive! Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 227505564021348702370395239071615962111, audio_type: Track } } Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 227505564021348702370395239071615962111, audio_type: Track } } Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] A connect session has begun Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] Device palyback is active! Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] Currently active: webradio Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] Stopping currently active service Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::volumioStop Jun 23 12:32:56 schuur volumio[786]: info: CoreStateMachine::stop Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : error 403 for uri hm://keymaster/token/authenticated?client_id=4ced2e7c73484127be5d36015752eb43&scope=streaming,user-read-playback-state,user-modify-playback-state,user-read-currently-playing,user-read-private Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : Error: MercuryError Jun 23 12:32:56 schuur volumio[6781]: thread 'main' panicked at 'cannot poll Map twice', /build/cache/registry/src/github.com-1ecc6299db9ec823/futures-0.1.29/src/future/map.rs:35:29 Jun 23 12:32:56 schuur volumio[6781]: stack backtrace: Jun 23 12:32:56 schuur volumio[786]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 23 12:32:56 schuur volumio[786]: UNSET VOLATILE Jun 23 12:32:56 schuur volumio[786]: info: CoreStateMachine::stPlaybackTimer Jun 23 12:32:56 schuur volumio[786]: info: CoreStateMachine::updateTrackBlock Jun 23 12:32:56 schuur volumio[786]: info: CorePlayQueue::getTrackBlock Jun 23 12:32:56 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:32:56 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:32:56 schuur volumio[786]: info: CoreStateMachine::serviceStop Jun 23 12:32:56 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::serviceStop Jun 23 12:32:56 schuur volumio[786]: info: [1624451576387] ControllerWebradio::stop Jun 23 12:32:56 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand stop Jun 23 12:32:56 schuur volumio[786]: info: sendMpdCommand stop took 119 milliseconds Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] Vollibrespot Active Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 12:32:56 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] Currently active: webradio Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] Setting Volatile state to Volspotconnect2 Jun 23 12:32:56 schuur volumio[786]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 12:32:56 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::volumioGetState Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] Currently active: volspotconnect2 Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] Pushing new state :: true Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 12:32:56 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:32:56 schuur volumio[786]: info: Jun 23 12:32:56 schuur volumio[786]: ---------------------------- MPD announces state update: player Jun 23 12:32:56 schuur volumio[786]: info: ControllerMpd::getState Jun 23 12:32:56 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand status Jun 23 12:32:56 schuur volumio[786]: info: sendMpdCommand status took 31 milliseconds Jun 23 12:32:56 schuur volumio[786]: verbose: ControllerMpd::parseState Jun 23 12:32:56 schuur volumio[786]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 23 12:32:56 schuur volumio[786]: info: sendMpdCommand playlistinfo took 10 milliseconds Jun 23 12:32:56 schuur volumio[786]: verbose: ControllerMpd::parseTrackInfo Jun 23 12:32:56 schuur volumio[786]: info: ControllerMpd::pushState Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::servicePushState Jun 23 12:32:56 schuur volumio[786]: info: CoreStateMachine::pushState Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::volumioPushState Jun 23 12:32:56 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 23 12:32:56 schuur volumio[786]: info: CorePlayQueue::getTrack 0 Jun 23 12:32:56 schuur volumio[786]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Jun 23 12:32:56 schuur volumio[786]: info: ------------------------------ 74ms Jun 23 12:32:56 schuur volumio[6781]: 0: 0xa7b33c - backtrace::backtrace::libunwind::trace::hae21a072c81e5842 Jun 23 12:32:56 schuur volumio[6781]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86 Jun 23 12:32:56 schuur volumio[6781]: 1: 0xa7b33c - backtrace::backtrace::trace_unsynchronized::h0f9b260087e46e47 Jun 23 12:32:56 schuur volumio[6781]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66 Jun 23 12:32:56 schuur volumio[6781]: 2: 0xa7b33c - std::sys_common::backtrace::_print_fmt::hbf1a59173a7860c3 Jun 23 12:32:56 schuur volumio[6781]: at src/libstd/sys_common/backtrace.rs:78 Jun 23 12:32:56 schuur volumio[6781]: 3: 0xa7b33c - ::fmt::he1a5d6f378e506c4 Jun 23 12:32:56 schuur volumio[6781]: at src/libstd/sys_common/backtrace.rs:59 Jun 23 12:32:56 schuur volumio[6781]: 4: 0xa9bd5c - core::fmt::write::hb37ae5a5e0b70623 Jun 23 12:32:56 schuur volumio[6781]: at src/libcore/fmt/mod.rs:1076 Jun 23 12:32:56 schuur volumio[6781]: 5: 0xa74c64 - std::io::Write::write_fmt::ha24bb3f5a858327b Jun 23 12:32:56 schuur volumio[6781]: at src/libstd/io/mod.rs:1537 Jun 23 12:32:56 schuur volumio[6781]: 6: 0xa7d974 - std::sys_common::backtrace::_print::h47b03aa1342833e3 Jun 23 12:32:56 schuur volumio[6781]: at src/libstd/sys_common/backtrace.rs:62 Jun 23 12:32:56 schuur volumio[6781]: 7: 0xa7d974 - std::sys_common::backtrace::print::h2217cbc390250439 Jun 23 12:32:56 schuur volumio[6781]: at src/libstd/sys_common/backtrace.rs:49 Jun 23 12:32:56 schuur volumio[6781]: 8: 0xa7d974 - std::panicking::default_hook::{{closure}}::h179f5229ea1c8e30 Jun 23 12:32:56 schuur volumio[6781]: at src/libstd/panicking.rs:198 Jun 23 12:32:56 schuur volumio[6781]: 9: 0xa7d640 - std::panicking::default_hook::h46ab82039cbc65eb Jun 23 12:32:56 schuur volumio[6781]: at src/libstd/panicking.rs:217 Jun 23 12:32:56 schuur volumio[6781]: 10: 0xa7e054 - std::panicking::rust_panic_with_hook::h7326c48419bc7c33 Jun 23 12:32:56 schuur volumio[6781]: at src/libstd/panicking.rs:526 Jun 23 12:32:56 schuur volumio[6781]: 11: 0xa7dc54 - rust_begin_unwind Jun 23 12:32:56 schuur volumio[6781]: at src/libstd/panicking.rs:437 Jun 23 12:32:56 schuur volumio[6781]: 12: 0xa99594 - core::panicking::panic_fmt::ha292e19d5ae716ed Jun 23 12:32:56 schuur volumio[6781]: at src/libcore/panicking.rs:85 Jun 23 12:32:56 schuur volumio[6781]: 13: 0xa99370 - core::option::expect_failed::he9e39f8f5ba60ecb Jun 23 12:32:56 schuur volumio[6781]: at src/libcore/option.rs:1261 Jun 23 12:32:56 schuur volumio[6781]: 14: 0x76fbf8 - as futures::future::Future>::poll::h3d56b212ca27d9e4 Jun 23 12:32:56 schuur volumio[6781]: 15: 0x6253a4 - ::poll::ha2e91a6b75c719f3 Jun 23 12:32:56 schuur volumio[6781]: 16: 0x59bca4 - ::poll::hc5e7d2d1b7dbef13 Jun 23 12:32:56 schuur volumio[6781]: 17: 0x563844 - futures::task_impl::std::set::h8f081cf0436110c9 Jun 23 12:32:56 schuur systemd[1]: volspotconnect2.service: main process exited, code=exited, status=101/n/a Jun 23 12:32:56 schuur systemd[1]: Unit volspotconnect2.service entered failed state. Jun 23 12:32:56 schuur volumio[6781]: 18: 0x57741c - std::thread::local::LocalKey::with::h711a13323aafc45a Jun 23 12:32:56 schuur volumio[6781]: 19: 0x553a50 - tokio_current_thread::Entered

::block_on::h339073902a399eb7 Jun 23 12:32:56 schuur volumio[6781]: 20: 0x577e00 - std::thread::local::LocalKey::with::hff64c13ccfec5327 Jun 23 12:32:56 schuur volumio[6781]: 21: 0x58420c - tokio_reactor::with_default::h7ef12e65cb103d2f Jun 23 12:32:56 schuur volumio[6781]: 22: 0x5579f8 - tokio::runtime::current_thread::runtime::Runtime::block_on::h043f136d6b8cf48f Jun 23 12:32:56 schuur volumio[6781]: 23: 0x59d2c8 - vollibrespot::main::h02a0d49d4cc5eaa6 Jun 23 12:32:56 schuur volumio[6781]: 24: 0x584f18 - std::rt::lang_start::{{closure}}::h279cd2b7929fdba7 Jun 23 12:32:56 schuur volumio[6781]: 25: 0xa7e404 - std::rt::lang_start_internal::{{closure}}::he93bfc404849b78a Jun 23 12:32:56 schuur volumio[6781]: at src/libstd/rt.rs:52 Jun 23 12:32:56 schuur volumio[6781]: 26: 0xa7e404 - std::panicking::try::do_call::h6e9e98f4078affb0 Jun 23 12:32:56 schuur volumio[6781]: at src/libstd/panicking.rs:348 Jun 23 12:32:56 schuur volumio[6781]: 27: 0xa7e404 - std::panicking::try::h2e68d4f7f799a6df Jun 23 12:32:56 schuur volumio[6781]: at src/libstd/panicking.rs:325 Jun 23 12:32:56 schuur volumio[6781]: 28: 0xa7e404 - std::panic::catch_unwind::h8880a4c07cc66391 Jun 23 12:32:56 schuur volumio[6781]: at src/libstd/panic.rs:394 Jun 23 12:32:56 schuur volumio[6781]: 29: 0xa7e404 - std::rt::lang_start_internal::hf4ae2140248bf16b Jun 23 12:32:56 schuur volumio[6781]: at src/libstd/rt.rs:51 Jun 23 12:32:56 schuur volumio[6781]: 30: 0x59dd84 - main Jun 23 12:32:56 schuur volumio[6781]: 31: 0x76c5e678 - __libc_start_main Jun 23 12:32:56 schuur volumio[6781]: [Vollibrespot] : EventSender disconnected Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] Device palyback is inactive Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] Device Session is_active: true Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] Sink released Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] Not pushing Pause { active: true, isStopping: true} Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] ResolvedStop in 616s 855.08ms Jun 23 12:32:56 schuur volumio[786]: [SpotifyConnect] ResolvedStop in 616s 471.27ms Jun 23 12:32:58 schuur systemd[1]: volspotconnect2.service holdoff time over, scheduling restart. Jun 23 12:32:58 schuur systemd[1]: Stopping Volspotconnect2 Daemon... Jun 23 12:32:58 schuur systemd[1]: Starting Volspotconnect2 Daemon... Jun 23 12:32:58 schuur systemd[1]: Started Volspotconnect2 Daemon. Jun 23 12:32:58 schuur volumio[8241]: vollibrespot v0.2.2 cd96399 2020-10-07 (librespot 08d8bcc 2020-10-07) -- Built On 2020-10-07 Jun 23 12:32:58 schuur volumio[8241]: Reading Config from "volspotify.toml" Jun 23 12:32:58 schuur volumio[8241]: [Vollibrespot] : Using Alsa backend with device: plughw:1 Jun 23 12:32:59 schuur volumio[8241]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" } Jun 23 12:33:07 schuur volumio[786]: info: CALLMETHOD: system_controller system sendBugReport [object Object] Jun 23 12:33:07 schuur volumio[786]: info: CoreCommandRouter::executeOnPlugin: system , sendBugReport Jun 23 12:33:08 schuur sudo[8294]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig Jun 23 12:33:08 schuur sudo[8294]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 23 12:33:08 schuur sudo[8294]: pam_unix(sudo:session): session closed for user root Jun 23 12:33:10 schuur kernel: rpi_firmware_get_throttled: 5 callbacks suppressed Jun 23 12:33:10 schuur kernel: Under-voltage detected! (0x00050005) Jun 23 12:33:12 schuur sudo[8341]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl -p 7 Jun 23 12:33:12 schuur sudo[8341]: pam_unix(sudo:session): session opened for user root by (uid=0)