-- Logs begin at Thu 2019-02-14 11:12:00 CET, end at Sat 2024-08-17 01:31:10 CEST. -- Aug 17 01:31:03 volumio ntpd[1003]: receive: Unexpected origin timestamp 0xea661b0c.36d08520 does not match aorg 0000000000.00000000 from server@195.186.1.100 xmt 0xea6a5fb7.e85108f4 Aug 17 01:31:03 volumio ntpd[1003]: receive: Unexpected origin timestamp 0xea661b0c.36d6ea87 does not match aorg 0000000000.00000000 from server@84.72.108.37 xmt 0xea6a5fb7.e69221b4 Aug 17 01:31:03 volumio volumio[1014]: info: ir_controller: Raspberry Pi revision code: c03111 Aug 17 01:31:03 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Aug 17 01:31:03 volumio sudo[1195]: pam_unix(sudo:session): session closed for user root Aug 17 01:31:03 volumio sudo[1197]: pam_unix(sudo:session): session closed for user root Aug 17 01:31:03 volumio volumio[1014]: info: Discovery: A device disappeared from network Aug 17 01:31:03 volumio volumio[1014]: info: Discovery: Device volumio disappeared from network Aug 17 01:31:03 volumio sudo[1200]: pam_unix(sudo:session): session closed for user root Aug 17 01:31:03 volumio systemd[1]: Starting Daily apt download activities... Aug 17 01:31:04 volumio volumio[1014]: info: Shairport-Sync Started Aug 17 01:31:04 volumio volumio[1014]: Error adding Membership: Error: addMembership EINVAL Aug 17 01:31:04 volumio volumio[1014]: info: Shairport-Sync Started Aug 17 01:31:04 volumio volumio[1014]: info: Discovery: adding eb861ebb-7adb-459c-b624-f0742436f87a Aug 17 01:31:04 volumio volumio[1014]: info: Discovery: Found device Volumio Aug 17 01:31:04 volumio volumio[1014]: info: CoreCommandRouter::volumioGetState Aug 17 01:31:04 volumio volumio[1014]: info: CorePlayQueue::getTrack 0 Aug 17 01:31:04 volumio go-librespot[1189]: time="2024-08-17T01:31:04+02:00" level=info msg="generated new device id: 05a9162c3017f858240a8abf472c8dcbd71e42de" Aug 17 01:31:04 volumio sudo[1220]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -r -1 Aug 17 01:31:04 volumio sudo[1220]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 17 01:31:04 volumio sudo[1220]: pam_unix(sudo:session): session closed for user root Aug 17 01:31:04 volumio sudo[1232]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay gpio-ir gpio_pin=25 gpio_pull=up Aug 17 01:31:04 volumio sudo[1232]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 17 01:31:04 volumio kernel: Registered IR keymap rc-rc6-mce Aug 17 01:31:04 volumio sudo[1232]: pam_unix(sudo:session): session closed for user root Aug 17 01:31:04 volumio volumio[1014]: info: ir_controller: Overlay gpio-ir gpio_pin=25 gpio_pull=up loaded. Aug 17 01:31:04 volumio kernel: IR RC6 protocol handler initialized Aug 17 01:31:04 volumio sudo[1252]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart lircd.service Aug 17 01:31:04 volumio sudo[1252]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 17 01:31:04 volumio kernel: rc rc0: gpio_ir_recv as /devices/platform/ir-receiver@19/rc/rc0 Aug 17 01:31:04 volumio kernel: rc rc0: lirc_dev: driver gpio_ir_recv registered at minor = 0, raw IR receiver, no transmitter Aug 17 01:31:04 volumio kernel: input: gpio_ir_recv as /devices/platform/ir-receiver@19/rc/rc0/input4 Aug 17 01:31:04 volumio go-librespot[1189]: time="2024-08-17T01:31:04+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 17 01:31:04 volumio go-librespot[1189]: time="2024-08-17T01:31:04+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 17 01:31:04 volumio go-librespot[1189]: time="2024-08-17T01:31:04+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 17 01:31:04 volumio go-librespot[1189]: time="2024-08-17T01:31:04+02:00" level=debug msg="zeroconf server listening on port 43567" Aug 17 01:31:04 volumio systemd[1]: Starting lircd(8) initialization helper tool... Aug 17 01:31:04 volumio systemd-udevd[1241]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. Aug 17 01:31:04 volumio systemd-logind[698]: Watching system buttons on /dev/input/event4 (gpio_ir_recv) Aug 17 01:31:04 volumio sudo[1268]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart lircd.service Aug 17 01:31:04 volumio sudo[1268]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 17 01:31:05 volumio lircd-setup[1260]: /usr/sbin/lircd-setup:37: DeprecationWarning: The SafeConfigParser class has been renamed to ConfigParser in Python 3.2. This alias will be removed in future versions. Use ConfigParser directly instead. Aug 17 01:31:05 volumio lircd-setup[1260]: parser = configparser.SafeConfigParser() Aug 17 01:31:05 volumio systemd[1]: lircd-setup.service: Succeeded. Aug 17 01:31:05 volumio systemd[1]: Started lircd(8) initialization helper tool. Aug 17 01:31:05 volumio systemd[1]: Starting Flexible IR remote input/output application support... Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Info: lircd: Opening log, level: Info Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Version: lircd 0.10.1 Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: System info: Linux volumio 6.1.69-v7l+ #1710 SMP Thu Dec 21 13:17:38 GMT 2023 armv7l GNU/Linux Aug 17 01:31:05 volumio systemd[1]: systemd-fsckd.service: Succeeded. Aug 17 01:31:05 volumio mpd[1168]: Aug 17 01:31 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 17 01:31:05 volumio systemd[1]: Started Music Player Daemon. Aug 17 01:31:05 volumio sudo[1149]: pam_unix(sudo:session): session closed for user root Aug 17 01:31:05 volumio sudo[1135]: pam_unix(sudo:session): session closed for user root Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Info: Initial device: /dev/lirc0 Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: 'lirc' written to protocols file /sys/class/rc/rc0/protocols Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Info: Initial device: /dev/lirc0 Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Info: [lirc] protocol is enabled Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: driver: default Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: output: /var/run/lirc/lircd Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: nodaemon: 1 Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: plugindir: /usr/lib/arm-linux-gnueabihf/lirc/plugins Aug 17 01:31:05 volumio lircd[1270]: lircd-0.10.1[1270]: Info: lircd: Opening log, level: Info Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: logfile: syslog Aug 17 01:31:05 volumio lircd[1270]: lircd-0.10.1[1270]: Notice: Using systemd fd Aug 17 01:31:05 volumio lircd[1270]: lircd-0.10.1[1270]: Warning: Running as root Aug 17 01:31:05 volumio lircd[1270]: lircd-0.10.1[1270]: Info: Using remote: mceusb. Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: immediate-init: 0 Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: permission: 666 Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: driver-options: Aug 17 01:31:05 volumio lircd[1270]: lircd-0.10.1[1270]: Notice: lircd(default) ready, using /var/run/lirc/lircd Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: pidfile: /var/run/lirc/lircd.pid Aug 17 01:31:05 volumio systemd[1]: Started Flexible IR remote input/output application support. Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: listen: 0 Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: connect: (null) Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: userelease: 0 Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: effective_user: (null) Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: release_suffix: _EVUP Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: allow_simulate: 0 Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: repeat_max: 600 Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: configfile: /etc/lirc/lircd.conf Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Options: dynamic_codes: (null) Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Current driver: default Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Driver API version: 3 Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Driver version: 0.10.0 Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Driver info: See file:///usr/share/doc/lirc/plugindocs/default.html Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Info: lircd: Opening log, level: Info Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: Using systemd fd Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Warning: Running as root Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Info: Using remote: mceusb. Aug 17 01:31:05 volumio lircd-0.10.1[1270]: Notice: lircd(default) ready, using /var/run/lirc/lircd Aug 17 01:31:05 volumio sudo[1252]: pam_unix(sudo:session): session closed for user root Aug 17 01:31:05 volumio sudo[1268]: pam_unix(sudo:session): session closed for user root Aug 17 01:31:05 volumio volumio[1014]: info: Completed starting Core Plugins Aug 17 01:31:05 volumio volumio[1014]: info: ------------------------------------------- Aug 17 01:31:05 volumio volumio[1014]: info: ----- MyVolumio plugins startup ---- Aug 17 01:31:05 volumio volumio[1014]: info: ------------------------------------------- Aug 17 01:31:05 volumio volumio[1014]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 17 01:31:05 volumio volumio[1014]: error: MPD error: The expression evaluated to a falsy value: Aug 17 01:31:05 volumio volumio[1014]: assert.ok(self.idling) Aug 17 01:31:05 volumio volumio[1014]: error: The expression evaluated to a falsy value: Aug 17 01:31:05 volumio volumio[1014]: assert.ok(self.idling) Aug 17 01:31:05 volumio volumio[1014]: info: ir_controller: systemctl restart lircd.service succeeded. Aug 17 01:31:05 volumio volumio[1014]: info: ir_controller: systemctl restart lircd.service succeeded. Aug 17 01:31:05 volumio sudo[1279]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart irexec.service Aug 17 01:31:05 volumio sudo[1279]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 17 01:31:05 volumio volumio[1014]: info: MPD running with PID1168 Aug 17 01:31:05 volumio volumio[1014]: ,establishing connection Aug 17 01:31:05 volumio volumio[1014]: error: updateQueue error: null Aug 17 01:31:05 volumio volumio[1014]: error: updateQueue error: null Aug 17 01:31:05 volumio sudo[1281]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart irexec.service Aug 17 01:31:05 volumio sudo[1281]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 17 01:31:05 volumio systemd[1]: Started Handle events from IR remotes decoded by lircd(8). Aug 17 01:31:06 volumio lircd[1270]: lircd-0.10.1[1270]: Notice: accepted new client on /var/run/lirc/lircd Aug 17 01:31:06 volumio lircd-0.10.1[1270]: Notice: accepted new client on /var/run/lirc/lircd Aug 17 01:31:06 volumio lircd[1270]: lircd-0.10.1[1270]: Info: [lirc] protocol is enabled Aug 17 01:31:06 volumio lircd-0.10.1[1270]: Info: [lirc] protocol is enabled Aug 17 01:31:06 volumio sudo[1279]: pam_unix(sudo:session): session closed for user root Aug 17 01:31:06 volumio lircd[1270]: lircd-0.10.1[1270]: Info: removed client Aug 17 01:31:06 volumio lircd-0.10.1[1270]: Info: removed client Aug 17 01:31:06 volumio volumio[1014]: info: ir_controller: systemctl restart irexec.service succeeded. Aug 17 01:31:06 volumio systemd[1]: Stopping Handle events from IR remotes decoded by lircd(8)... Aug 17 01:31:06 volumio systemd[1]: irexec.service: Main process exited, code=killed, status=15/TERM Aug 17 01:31:06 volumio systemd[1]: irexec.service: Succeeded. Aug 17 01:31:06 volumio systemd[1]: Stopped Handle events from IR remotes decoded by lircd(8). Aug 17 01:31:06 volumio systemd[1]: Started Handle events from IR remotes decoded by lircd(8). Aug 17 01:31:06 volumio lircd[1270]: lircd-0.10.1[1270]: Notice: accepted new client on /var/run/lirc/lircd Aug 17 01:31:06 volumio lircd-0.10.1[1270]: Notice: accepted new client on /var/run/lirc/lircd Aug 17 01:31:06 volumio lircd[1270]: lircd-0.10.1[1270]: Info: [lirc] protocol is enabled Aug 17 01:31:06 volumio lircd-0.10.1[1270]: Info: [lirc] protocol is enabled Aug 17 01:31:06 volumio sudo[1281]: pam_unix(sudo:session): session closed for user root Aug 17 01:31:06 volumio volumio[1014]: info: ir_controller: systemctl restart irexec.service succeeded. Aug 17 01:31:06 volumio sh[567]: timed out Aug 17 01:31:06 volumio dhcpcd[610]: timed out Aug 17 01:31:06 volumio sh[567]: dhcpcd exited Aug 17 01:31:06 volumio dhcpcd[610]: dhcpcd exited Aug 17 01:31:06 volumio sh[567]: ifup: failed to bring up eth0 Aug 17 01:31:06 volumio systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Aug 17 01:31:06 volumio systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Aug 17 01:31:06 volumio go-librespot[1189]: time="2024-08-17T01:31:06+02:00" level=debug msg="obtained new client token: AADCfi1ltGYCuzfJ+crMcbHubhnwjt+eeRsJF5fe6x1NkPCzDrcRvWdapxUXmxx1Ju0pp0eaQJ7rJ9ecxUKLda0rpfTzQduDnAZ0VsQZXMdZ217WhOC/WIfpMrWhzalOoEZaqhvXor1hiADG36qLE5ILHek19Q2HEPLkzJ7/LH5Y0e6AgbMWjvhN4PhCND71vhHOwj23q3AoAycgO2+XgO4KiqkFuSCItZf4pp/yUj2JL5B1XIprSchW" Aug 17 01:31:06 volumio go-librespot[1189]: time="2024-08-17T01:31:06+02:00" level=debug msg="completed keyexchange" Aug 17 01:31:06 volumio systemd[1]: apt-daily.service: Succeeded. Aug 17 01:31:06 volumio systemd[1]: Started Daily apt download activities. Aug 17 01:31:06 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Aug 17 01:31:06 volumio volumio[1014]: info: go-librespot daemon successfully initialized Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="completed challenge" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="authenticated as janic.blattner" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="authenticated as janic.blattner" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="dealer connection opened" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=info msg="accepted zeroconf user janic.blattner from iPhone" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="autoplay enabled: false" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="received connection id: YTc1ZTM3YmUtMzkyYi00YWNhLTg3Y2UtMTg0NGRjZTEzZTc0K2RlYWxlcit0Y3A6Ly8wYWNhNThmMS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMTc5MUQwRTRCODAzMDI5RTI4MTExQTUxQzVEMjUzOUJGNjI0OUQ5NjUzMDc0MEQyMEYzNDQ0QTdDMTQ1RTVFMA==" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="put connect state because NEW_DEVICE" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="handling transfer player command from c6efad92cb42d04d7db48f287a824daddd7ce2bd" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:0Hy2Xq8xduN00d93MZLkaA" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=trace msg="fetched new page 0 with 11 items (list: 11)" uri="spotify:playlist:0Hy2Xq8xduN00d93MZLkaA" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="shuffled context with seed 10123116751466776550 (len: 11, keep: 2)" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="loading track (paused: true, position: 137027ms)" uri="spotify:track:06cu1SVS8iYXZaO5PR3TkX" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=trace msg="emitting websocket event: will_play" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="selected format OGG_VORBIS_320 (a17d845c2337c15aa658c1804dcd5ddcba228853)" uri="spotify:track:06cu1SVS8iYXZaO5PR3TkX" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="requested aes key for file a17d845c2337c15aa658c1804dcd5ddcba228853, gid: 06cu1SVS8iYXZaO5PR3TkX" Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1376" Aug 17 01:31:07 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Aug 17 01:31:07 volumio systemd[1]: Started Daily apt upgrade and clean activities. Aug 17 01:31:07 volumio go-librespot[1189]: time="2024-08-17T01:31:07+02:00" level=debug msg="fetched first chunk of 38, total size is 19634704 bytes" uri="spotify:track:06cu1SVS8iYXZaO5PR3TkX" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1142" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="fetched chunk 1/37, size: 524288" uri="spotify:track:06cu1SVS8iYXZaO5PR3TkX" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="fetched chunk 2/37, size: 524288" uri="spotify:track:06cu1SVS8iYXZaO5PR3TkX" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="fetched chunk 13/37, size: 524288" uri="spotify:track:06cu1SVS8iYXZaO5PR3TkX" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="fetched chunk 11/37, size: 524288" uri="spotify:track:06cu1SVS8iYXZaO5PR3TkX" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="fetched chunk 12/37, size: 524288" uri="spotify:track:06cu1SVS8iYXZaO5PR3TkX" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="fetched chunk 3/37, size: 524288" uri="spotify:track:06cu1SVS8iYXZaO5PR3TkX" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="fetched chunk 10/37, size: 524288" uri="spotify:track:06cu1SVS8iYXZaO5PR3TkX" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=trace msg="seek to 137027ms (diff: 130ms, samples: 6042890, bytes: 5479024)" uri="spotify:track:06cu1SVS8iYXZaO5PR3TkX" Aug 17 01:31:08 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="created new output device" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=info msg="loaded track \"Good Morning Reality\" (paused: true, position: 137027ms, duration: 492960ms, prefetched: false)" uri="spotify:track:06cu1SVS8iYXZaO5PR3TkX" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=trace msg="emitting websocket event: metadata" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=trace msg="emitting websocket event: active" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="sending successful reply for dealer request" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Aug 17 01:31:08 volumio systemd[1]: systemd-hostnamed.service: Succeeded. Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 17 01:31:08 volumio go-librespot[1189]: time="2024-08-17T01:31:08+02:00" level=trace msg="emitting websocket event: paused" Aug 17 01:31:09 volumio sudo[1370]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 17 01:31:09 volumio sudo[1370]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 17 01:31:09 volumio sudo[1370]: pam_unix(sudo:session): session closed for user root Aug 17 01:31:09 volumio sudo[1373]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 17 01:31:09 volumio sudo[1373]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 17 01:31:09 volumio sudo[1373]: pam_unix(sudo:session): session closed for user root Aug 17 01:31:09 volumio sudo[1376]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 17 01:31:09 volumio sudo[1376]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 17 01:31:09 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Aug 17 01:31:09 volumio sudo[1376]: pam_unix(sudo:session): session closed for user root Aug 17 01:31:09 volumio volumio[1014]: info: Upmpdcli Daemon Started Aug 17 01:31:09 volumio volumio[1378]: Generating RSA private key, 4096 bit long modulus (2 primes) Aug 17 01:31:09 volumio volumio[1014]: info: Initializing connection to go-librespot Websocket Aug 17 01:31:09 volumio go-librespot[1189]: time="2024-08-17T01:31:09+02:00" level=debug msg="new websocket client" Aug 17 01:31:09 volumio volumio[1014]: info: Connection to go-librespot Websocket established Aug 17 01:31:10 volumio go-librespot[1189]: time="2024-08-17T01:31:10+02:00" level=debug msg="handling resume player command from c6efad92cb42d04d7db48f287a824daddd7ce2bd" Aug 17 01:31:10 volumio go-librespot[1189]: time="2024-08-17T01:31:10+02:00" level=trace msg="seek to 137027ms (diff: 130ms, samples: 6042890, bytes: 5479024)" uri="spotify:track:06cu1SVS8iYXZaO5PR3TkX" Aug 17 01:31:10 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Aug 17 01:31:10 volumio go-librespot[1189]: time="2024-08-17T01:31:10+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Aug 17 01:31:10 volumio go-librespot[1189]: time="2024-08-17T01:31:10+02:00" level=debug msg="resume track at 136897ms" Aug 17 01:31:10 volumio go-librespot[1189]: time="2024-08-17T01:31:10+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 17 01:31:10 volumio go-librespot[1189]: time="2024-08-17T01:31:10+02:00" level=trace msg="scheduling prefetch in 326s" Aug 17 01:31:10 volumio go-librespot[1189]: time="2024-08-17T01:31:10+02:00" level=debug msg="sending successful reply for dealer request" Aug 17 01:31:10 volumio go-librespot[1189]: time="2024-08-17T01:31:10+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 17 01:31:10 volumio go-librespot[1189]: time="2024-08-17T01:31:10+02:00" level=trace msg="emitting websocket event: playing" Aug 17 01:31:10 volumio volumio[1014]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:06cu1SVS8iYXZaO5PR3TkX","play_origin":"playlist/ondemand"}} Aug 17 01:31:10 volumio volumio[1014]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 17 01:31:10 volumio volumio[1014]: TypeError: Cannot read property 'service' of undefined Aug 17 01:31:10 volumio volumio[1014]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Aug 17 01:31:10 volumio volumio[1014]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) Aug 17 01:31:10 volumio volumio[1014]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Aug 17 01:31:10 volumio volumio[1014]: at WebSocket.emit (events.js:315:20) Aug 17 01:31:10 volumio volumio[1014]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Aug 17 01:31:10 volumio volumio[1014]: at Receiver.emit (events.js:315:20) Aug 17 01:31:10 volumio volumio[1014]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Aug 17 01:31:10 volumio volumio[1014]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Aug 17 01:31:10 volumio volumio[1014]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Aug 17 01:31:10 volumio volumio[1014]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Aug 17 01:31:10 volumio volumio[1014]: at writeOrBuffer (internal/streams/writable.js:358:12) Aug 17 01:31:10 volumio volumio[1014]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Aug 17 01:31:10 volumio volumio[1014]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Aug 17 01:31:10 volumio volumio[1014]: at Socket.emit (events.js:315:20) Aug 17 01:31:10 volumio volumio[1014]: at addChunk (internal/streams/readable.js:309:12) Aug 17 01:31:10 volumio volumio[1014]: at readableAddChunk (internal/streams/readable.js:284:9) Aug 17 01:31:10 volumio volumio[1014]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 17 01:31:10 volumio sudo[1403]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-17 01:30 Aug 17 01:31:10 volumio sudo[1403]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"