-- Logs begin at Thu 2019-02-14 10:11:58 GMT, end at Sun 2025-12-07 00:59:08 GMT. -- Dec 07 00:59:00 sony-avr systemd-timedated[1163]: Changed local time to Sun Dec 7 00:59:00 2025 Dec 07 00:59:00 sony-avr sudo[1145]: pam_unix(sudo:session): session closed for user root Dec 07 00:59:00 sony-avr volumio-time-update[622]: volumio-time-update-util: System time updated successfully. Dec 07 00:59:00 sony-avr volumio[878]: info: Discovery: Browse raised the following error Error: dns service error: unknown Dec 07 00:59:00 sony-avr systemd[1]: Started Volumio Time Update Utility. Dec 07 00:59:00 sony-avr volumio[878]: info: Discovery: A device disappeared from network Dec 07 00:59:00 sony-avr volumio[878]: info: Discovery: Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=info msg="running go-librespot 0.4.0" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="app state loaded" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=info msg="api server listening on 127.0.0.1:9879" Dec 07 00:59:00 sony-avr volumio[878]: info: Discovery: adding cab198b3-ca75-428e-97fb-ea405aa7d6ce Dec 07 00:59:00 sony-avr volumio[878]: info: Discovery: Found device sony-avr Dec 07 00:59:00 sony-avr volumio[878]: info: CoreCommandRouter::volumioGetState Dec 07 00:59:00 sony-avr volumio[878]: info: CorePlayQueue::getTrack 0 Dec 07 00:59:00 sony-avr systemd[1]: Starting Daily apt download activities... Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=info msg="zeroconf server listening on port 43611" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="obtained new client token: AABGqWnmMczQzcshuWeKUy/QXk2GyUHr/W7p66WaDpgTQk6MUZpsvhdFvJjvEbeUFq/9pAjr/2MDaF63JWFVTaUasWbamRSHUSPPT0/UYLelyYaeIQ1hDij9MSRrtVVS/iooGIZSTvrXDfpws1SbKb7viIw7OWHtYL3d+YZKrFB42OvbTNT6vNY8AzkpYq7m+oP6/etv8uNeF5moMQ/ALjp8fVQtbeeiGwq+aSfPt274o6dBPsHWjI1d" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="completed keyexchange" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="completed challenge" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=info msg="authenticated AP" username="pg*********************tg" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=info msg="authenticated Login5" username="pg*********************tg" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="initializing zeroconf session" username="pg*********************tg" Dec 07 00:59:00 sony-avr nmbd[773]: [2025/12/07 00:59:00.750186, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 07 00:59:00 sony-avr nmbd[773]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Dec 07 00:59:00 sony-avr systemd[1]: Started Samba NMB Daemon. Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="dealer connection opened" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=trace msg="starting accesspoint recv loop" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=trace msg="starting dealer recv loop" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=trace msg="received accesspoint ping" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="received connection id: MGJiM2Y4MjItZjlj...QUFBMEE3RUE4NA==" Dec 07 00:59:00 sony-avr systemd[1]: Starting Samba Winbind Daemon... Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=trace msg="received accesspoint pong ack" Dec 07 00:59:00 sony-avr ntpd[800]: Listen normally on 3 eth0 192.168.8.172:123 Dec 07 00:59:00 sony-avr ntpd[800]: new interface(s) found: waking up resolver Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="put connect state because NEW_DEVICE" Dec 07 00:59:00 sony-avr go-librespot[1118]: time="2025-12-07T00:59:00Z" level=debug msg="update volume requested to 45219/65535" Dec 07 00:59:01 sony-avr go-librespot[1118]: time="2025-12-07T00:59:01Z" level=debug msg="put connect state because VOLUME_CHANGED" Dec 07 00:59:01 sony-avr go-librespot[1118]: time="2025-12-07T00:59:01Z" level=trace msg="emitting websocket event: volume" Dec 07 00:59:01 sony-avr systemd[1]: avr-status.service: Service RestartSec=1s expired, scheduling restart. Dec 07 00:59:01 sony-avr systemd[1]: avr-status.service: Scheduled restart job, restart counter is at 6. Dec 07 00:59:01 sony-avr systemd[1]: Stopped avr-status. Dec 07 00:59:01 sony-avr systemd[1]: Started avr-status. Dec 07 00:59:01 sony-avr winbindd[1193]: [2025/12/07 00:59:01.254566, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Dec 07 00:59:01 sony-avr winbindd[1193]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Dec 07 00:59:01 sony-avr winbindd[1193]: [2025/12/07 00:59:01.386694, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 07 00:59:01 sony-avr systemd[1]: Started Samba Winbind Daemon. Dec 07 00:59:01 sony-avr winbindd[1193]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Dec 07 00:59:01 sony-avr systemd[1]: Starting Samba SMB Daemon... Dec 07 00:59:01 sony-avr python3[1195]: /home/volumio/scripts/scripts/avr-status/start.py:85: DeprecationWarning: Callback API version 1 is deprecated, update to latest version Dec 07 00:59:01 sony-avr python3[1195]: client = mqtt.Client(mqtt.CallbackAPIVersion.VERSION1) Dec 07 00:59:01 sony-avr python3[1195]: Monitoring CEC power status every 2 seconds... Dec 07 00:59:01 sony-avr python3[1195]: Connected to MQTT Broker: 192.168.8.164 Dec 07 00:59:01 sony-avr python3[1195]: Warning: 'pwr-state' not found in command output. Dec 07 00:59:01 sony-avr python3[1195]: Could not determine initial power state. Exiting script. Dec 07 00:59:01 sony-avr mpd[1030]: Dec 07 00:59 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 07 00:59:01 sony-avr systemd[1]: Started Music Player Daemon. Dec 07 00:59:01 sony-avr sudo[1019]: pam_unix(sudo:session): session closed for user root Dec 07 00:59:01 sony-avr sudo[1008]: pam_unix(sudo:session): session closed for user root Dec 07 00:59:01 sony-avr systemd[1]: avr-status.service: Main process exited, code=exited, status=1/FAILURE Dec 07 00:59:01 sony-avr systemd[1]: avr-status.service: Failed with result 'exit-code'. Dec 07 00:59:01 sony-avr volumio[878]: info: Completed starting Core Plugins Dec 07 00:59:01 sony-avr volumio[878]: info: ------------------------------------------- Dec 07 00:59:01 sony-avr volumio[878]: info: ----- MyVolumio plugins startup ---- Dec 07 00:59:01 sony-avr volumio[878]: info: ------------------------------------------- Dec 07 00:59:01 sony-avr volumio[878]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 07 00:59:01 sony-avr volumio[878]: error: MPD error: The expression evaluated to a falsy value: Dec 07 00:59:01 sony-avr volumio[878]: assert.ok(self.idling) Dec 07 00:59:01 sony-avr volumio[878]: error: The expression evaluated to a falsy value: Dec 07 00:59:01 sony-avr volumio[878]: assert.ok(self.idling) Dec 07 00:59:01 sony-avr volumio[878]: error: updateQueue error: null Dec 07 00:59:01 sony-avr volumio[878]: info: MPD running with PID1030 Dec 07 00:59:01 sony-avr volumio[878]: ,establishing connection Dec 07 00:59:01 sony-avr volumio[878]: error: updateQueue error: null Dec 07 00:59:01 sony-avr smbd[1199]: [2025/12/07 00:59:01.962673, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 07 00:59:01 sony-avr systemd[1]: Started Samba SMB Daemon. Dec 07 00:59:01 sony-avr smbd[1199]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Dec 07 00:59:01 sony-avr systemd[1]: Reached target Multi-User System. Dec 07 00:59:01 sony-avr systemd[1]: Reached target Graphical Interface. Dec 07 00:59:02 sony-avr volumio[878]: info: CoreCommandRouter::volumioGetState Dec 07 00:59:02 sony-avr volumio[878]: info: CorePlayQueue::getTrack 0 Dec 07 00:59:02 sony-avr systemd[1]: Starting Update UTMP about System Runlevel Changes... Dec 07 00:59:02 sony-avr systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Dec 07 00:59:02 sony-avr systemd[1]: Started Update UTMP about System Runlevel Changes. Dec 07 00:59:02 sony-avr systemd[1]: apt-daily.service: Succeeded. Dec 07 00:59:02 sony-avr systemd[1]: Started Daily apt download activities. Dec 07 00:59:02 sony-avr systemd[1]: Starting Daily apt upgrade and clean activities... Dec 07 00:59:02 sony-avr volumio[878]: info: go-librespot daemon successfully initialized Dec 07 00:59:02 sony-avr systemd[1]: avr-status.service: Service RestartSec=1s expired, scheduling restart. Dec 07 00:59:02 sony-avr systemd[1]: avr-status.service: Scheduled restart job, restart counter is at 7. Dec 07 00:59:02 sony-avr systemd[1]: Stopped avr-status. Dec 07 00:59:02 sony-avr systemd[1]: Started avr-status. Dec 07 00:59:03 sony-avr python3[1267]: /home/volumio/scripts/scripts/avr-status/start.py:85: DeprecationWarning: Callback API version 1 is deprecated, update to latest version Dec 07 00:59:03 sony-avr python3[1267]: client = mqtt.Client(mqtt.CallbackAPIVersion.VERSION1) Dec 07 00:59:03 sony-avr python3[1267]: Monitoring CEC power status every 2 seconds... Dec 07 00:59:03 sony-avr python3[1267]: Connected to MQTT Broker: 192.168.8.164 Dec 07 00:59:03 sony-avr python3[1267]: Warning: 'pwr-state' not found in command output. Dec 07 00:59:03 sony-avr python3[1267]: Could not determine initial power state. Exiting script. Dec 07 00:59:03 sony-avr systemd[1]: avr-status.service: Main process exited, code=exited, status=1/FAILURE Dec 07 00:59:03 sony-avr systemd[1]: avr-status.service: Failed with result 'exit-code'. Dec 07 00:59:03 sony-avr systemd[1]: apt-daily-upgrade.service: Succeeded. Dec 07 00:59:03 sony-avr systemd[1]: Started Daily apt upgrade and clean activities. Dec 07 00:59:03 sony-avr systemd[1]: Startup finished in 11.795s (kernel) + 18.057s (userspace) = 29.853s. Dec 07 00:59:04 sony-avr volumio[878]: info: CoreCommandRouter::volumioGetState Dec 07 00:59:04 sony-avr volumio[878]: info: CorePlayQueue::getTrack 0 Dec 07 00:59:04 sony-avr systemd[1]: avr-status.service: Service RestartSec=1s expired, scheduling restart. Dec 07 00:59:04 sony-avr systemd[1]: avr-status.service: Scheduled restart job, restart counter is at 8. Dec 07 00:59:04 sony-avr systemd[1]: Stopped avr-status. Dec 07 00:59:04 sony-avr systemd[1]: Started avr-status. Dec 07 00:59:04 sony-avr sudo[1306]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 07 00:59:04 sony-avr sudo[1306]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 07 00:59:04 sony-avr sudo[1308]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 07 00:59:04 sony-avr sudo[1308]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 07 00:59:04 sony-avr systemd[1]: Started MPD Monitor Service. Dec 07 00:59:04 sony-avr sudo[1306]: pam_unix(sudo:session): session closed for user root Dec 07 00:59:04 sony-avr python3[1304]: /home/volumio/scripts/scripts/avr-status/start.py:85: DeprecationWarning: Callback API version 1 is deprecated, update to latest version Dec 07 00:59:04 sony-avr python3[1304]: client = mqtt.Client(mqtt.CallbackAPIVersion.VERSION1) Dec 07 00:59:04 sony-avr python3[1304]: Monitoring CEC power status every 2 seconds... Dec 07 00:59:04 sony-avr python3[1304]: Connected to MQTT Broker: 192.168.8.164 Dec 07 00:59:04 sony-avr python3[1304]: Warning: 'pwr-state' not found in command output. Dec 07 00:59:04 sony-avr python3[1304]: Could not determine initial power state. Exiting script. Dec 07 00:59:04 sony-avr volumio[878]: info: Successfully started MPD Monitor Dec 07 00:59:04 sony-avr mpd_monitor.sh[1311]: MPD Monitor Service: Starting MPD Monitor Service Dec 07 00:59:04 sony-avr systemd[1]: Stopping MPD Monitor Service... Dec 07 00:59:04 sony-avr systemd[1]: mpd_monitor.service: Main process exited, code=killed, status=15/TERM Dec 07 00:59:04 sony-avr systemd[1]: mpd_monitor.service: Succeeded. Dec 07 00:59:04 sony-avr systemd[1]: Stopped MPD Monitor Service. Dec 07 00:59:04 sony-avr systemd[1]: Started MPD Monitor Service. Dec 07 00:59:04 sony-avr mpd_monitor.sh[1317]: MPD Monitor Service: Starting MPD Monitor Service Dec 07 00:59:04 sony-avr sudo[1308]: pam_unix(sudo:session): session closed for user root Dec 07 00:59:04 sony-avr volumio[878]: info: Successfully started MPD Monitor Dec 07 00:59:04 sony-avr systemd[1]: avr-status.service: Main process exited, code=exited, status=1/FAILURE Dec 07 00:59:04 sony-avr systemd[1]: avr-status.service: Failed with result 'exit-code'. Dec 07 00:59:05 sony-avr volumio[878]: info: Volumio Network Manager: Network status updated: 1 Dec 07 00:59:05 sony-avr volumio[878]: info: Initializing connection to go-librespot Websocket Dec 07 00:59:05 sony-avr go-librespot[1118]: time="2025-12-07T00:59:05Z" level=debug msg="new websocket client" Dec 07 00:59:05 sony-avr volumio[878]: info: Connection to go-librespot Websocket established Dec 07 00:59:05 sony-avr sudo[1336]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 07 00:59:05 sony-avr sudo[1336]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 07 00:59:05 sony-avr sudo[1336]: pam_unix(sudo:session): session closed for user root Dec 07 00:59:05 sony-avr sudo[1338]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 07 00:59:05 sony-avr sudo[1338]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 07 00:59:05 sony-avr sudo[1338]: pam_unix(sudo:session): session closed for user root Dec 07 00:59:05 sony-avr sudo[1342]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 07 00:59:05 sony-avr sudo[1342]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 07 00:59:05 sony-avr systemd[1]: Started UPnP Renderer front-end to MPD. Dec 07 00:59:05 sony-avr sudo[1342]: pam_unix(sudo:session): session closed for user root Dec 07 00:59:05 sony-avr volumio[878]: info: Upmpdcli Daemon Started Dec 07 00:59:05 sony-avr volumio[1344]: Generating RSA private key, 4096 bit long modulus (2 primes) Dec 07 00:59:06 sony-avr volumio[878]: info: CoreCommandRouter::volumioGetState Dec 07 00:59:06 sony-avr volumio[878]: info: CorePlayQueue::getTrack 0 Dec 07 00:59:06 sony-avr systemd[1]: avr-status.service: Service RestartSec=1s expired, scheduling restart. Dec 07 00:59:06 sony-avr systemd[1]: avr-status.service: Scheduled restart job, restart counter is at 9. Dec 07 00:59:06 sony-avr systemd[1]: Stopped avr-status. Dec 07 00:59:06 sony-avr systemd[1]: Started avr-status. Dec 07 00:59:06 sony-avr python3[1363]: /home/volumio/scripts/scripts/avr-status/start.py:85: DeprecationWarning: Callback API version 1 is deprecated, update to latest version Dec 07 00:59:06 sony-avr python3[1363]: client = mqtt.Client(mqtt.CallbackAPIVersion.VERSION1) Dec 07 00:59:06 sony-avr python3[1363]: Monitoring CEC power status every 2 seconds... Dec 07 00:59:06 sony-avr python3[1363]: Connected to MQTT Broker: 192.168.8.164 Dec 07 00:59:06 sony-avr python3[1363]: Warning: 'pwr-state' not found in command output. Dec 07 00:59:06 sony-avr python3[1363]: Could not determine initial power state. Exiting script. Dec 07 00:59:06 sony-avr systemd[1]: avr-status.service: Main process exited, code=exited, status=1/FAILURE Dec 07 00:59:06 sony-avr systemd[1]: avr-status.service: Failed with result 'exit-code'. Dec 07 00:59:06 sony-avr volumio[878]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 07 00:59:06 sony-avr go-librespot[1118]: time="2025-12-07T00:59:06Z" level=debug msg="dealer connection closed" Dec 07 00:59:06 sony-avr go-librespot[1118]: time="2025-12-07T00:59:06Z" level=debug msg="dealer recv loop stopped" Dec 07 00:59:06 sony-avr go-librespot[1118]: time="2025-12-07T00:59:06Z" level=debug msg="obtained new client token: AACAviQQCMj2rcd63XjFsMQdWxY+tXFGq9yYMNvWnTDUas2wJq4xmMA9plyV6/3tHmMg6/i4FRB4MDEB+RkguBjHyVubAMBCxsgprgHaneOBVVdw+CqW6fEyKKsTa59iLD6oyps++s+0kbftjjlHx1YZBylvn4U/yuDqTLuUWT3j4OYAv1VslyoOfXcH3ENmWToA1HXdqA+HVzY4B8eg1Qho9vuBiEi0n4AHnlHhjdqEgukGFUk7c32s068=" Dec 07 00:59:06 sony-avr go-librespot[1118]: time="2025-12-07T00:59:06Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="completed keyexchange" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="completed challenge" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=info msg="authenticated AP" username="ni********75" Dec 07 00:59:07 sony-avr volumio[1344]: ............++++ Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=info msg="authenticated Login5" username="ni********75" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=info msg="accepted zeroconf from iPhone" username="ni********75" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="dealer connection opened" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=trace msg="starting accesspoint recv loop" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=trace msg="starting dealer recv loop" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=trace msg="received accesspoint ping" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="received connection id: M2U3ZjYzZDQtM2Ez...OTZBNkRCNjREMQ==" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=trace msg="received accesspoint pong ack" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="put connect state because NEW_DEVICE" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="update volume requested to 45219/65535" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="handling transfer player command from 24f5b0320d9e128c309b51d39c226795985f2211" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="resolved context of track" uri="spotify:search" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:search" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="loading track (paused: false, position: 143454ms)" uri="spotify:track:234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=trace msg="emitting websocket event: will_play" Dec 07 00:59:07 sony-avr volumio[878]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:search","uri":"spotify:track:234SaqlzLfKAsE6gsmvMnR","play_origin":"search"}} Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="selected format OGG_VORBIS_320 (c353bdedea8eb13fca23551cfa57c042dd738f19)" uri="spotify:track:234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="requested aes key for file c353bdedea8eb13fca23551cfa57c042dd738f19, gid: 234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2608" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 391" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2596" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=trace msg="found 2 cdn urls" uri="spotify:track:234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="fetched first chunk of 33, total size is 17132776 bytes" uri="spotify:track:234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="fetched chunk 13/32, size: 524288" uri="spotify:track:234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=trace msg="seek to 143454ms (diff: 184ms, samples: 6326321, bytes: 7300104)" uri="spotify:track:234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="created new output device" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="fetched chunk 1/32, size: 524288" uri="spotify:track:234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="fetched chunk 2/32, size: 524288" uri="spotify:track:234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="fetched chunk 3/32, size: 524288" uri="spotify:track:234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=info msg="loaded track \"Victory Lap Five\" (paused: false, position: 143454ms, duration: 344571ms, prefetched: false)" uri="spotify:track:234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="fetched chunk 14/32, size: 524288" uri="spotify:track:234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="fetched chunk 15/32, size: 524288" uri="spotify:track:234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="fetched chunk 16/32, size: 524288" uri="spotify:track:234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=trace msg="scheduling prefetch in 171s" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=trace msg="emitting websocket event: metadata" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=trace msg="emitting websocket event: active" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="sending successful reply for dealer request" Dec 07 00:59:07 sony-avr volumio[878]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:234SaqlzLfKAsE6gsmvMnR","name":"Victory Lap Five","artist_names":["Fred again..","Skepta","PlaqueBoyMax","Denzel Curry","Hanumankind","That Mexican OT","D Double E","LYNY"],"album_name":"Victory Lap","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0203a07a0ca0a03dab6525e915","position":143454,"duration":344571,"release_date":"year:2025 month:7 day:9","track_number":2,"disc_number":1}} Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 07 00:59:07 sony-avr volumio[878]: SPOTIFY: received: {"type":"active","data":null} Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 07 00:59:07 sony-avr volumio[878]: info: Aligning Spotify Volume to Volumio Volume Dec 07 00:59:07 sony-avr volumio[878]: info: CoreCommandRouter::volumioGetState Dec 07 00:59:07 sony-avr volumio[878]: info: CorePlayQueue::getTrack 0 Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=trace msg="emitting websocket event: playing" Dec 07 00:59:07 sony-avr volumio[878]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:search","uri":"spotify:track:234SaqlzLfKAsE6gsmvMnR","resume":false,"play_origin":"search"}} Dec 07 00:59:07 sony-avr volumio[878]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 07 00:59:07 sony-avr volumio[878]: TypeError: Cannot read property 'service' of undefined Dec 07 00:59:07 sony-avr volumio[878]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Dec 07 00:59:07 sony-avr volumio[878]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Dec 07 00:59:07 sony-avr volumio[878]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Dec 07 00:59:07 sony-avr volumio[878]: at WebSocket.emit (events.js:315:20) Dec 07 00:59:07 sony-avr volumio[878]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Dec 07 00:59:07 sony-avr volumio[878]: at Receiver.emit (events.js:315:20) Dec 07 00:59:07 sony-avr volumio[878]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Dec 07 00:59:07 sony-avr volumio[878]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Dec 07 00:59:07 sony-avr volumio[878]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Dec 07 00:59:07 sony-avr volumio[878]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Dec 07 00:59:07 sony-avr volumio[878]: at writeOrBuffer (internal/streams/writable.js:358:12) Dec 07 00:59:07 sony-avr volumio[878]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Dec 07 00:59:07 sony-avr volumio[878]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Dec 07 00:59:07 sony-avr volumio[878]: at Socket.emit (events.js:315:20) Dec 07 00:59:07 sony-avr volumio[878]: at addChunk (internal/streams/readable.js:309:12) Dec 07 00:59:07 sony-avr volumio[878]: at readableAddChunk (internal/streams/readable.js:284:9) Dec 07 00:59:07 sony-avr volumio[878]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 07 00:59:07 sony-avr systemd[1]: avr-status.service: Service RestartSec=1s expired, scheduling restart. Dec 07 00:59:07 sony-avr systemd[1]: avr-status.service: Scheduled restart job, restart counter is at 10. Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=debug msg="put connect state because VOLUME_CHANGED" Dec 07 00:59:07 sony-avr go-librespot[1118]: time="2025-12-07T00:59:07Z" level=trace msg="emitting websocket event: volume" Dec 07 00:59:07 sony-avr systemd[1]: Stopped avr-status. Dec 07 00:59:07 sony-avr systemd[1]: Started avr-status. Dec 07 00:59:08 sony-avr go-librespot[1118]: time="2025-12-07T00:59:08Z" level=debug msg="fetched chunk 17/32, size: 524288" uri="spotify:track:234SaqlzLfKAsE6gsmvMnR" Dec 07 00:59:08 sony-avr python3[1369]: /home/volumio/scripts/scripts/avr-status/start.py:85: DeprecationWarning: Callback API version 1 is deprecated, update to latest version Dec 07 00:59:08 sony-avr python3[1369]: client = mqtt.Client(mqtt.CallbackAPIVersion.VERSION1) Dec 07 00:59:08 sony-avr python3[1369]: Monitoring CEC power status every 2 seconds... Dec 07 00:59:08 sony-avr python3[1369]: Connected to MQTT Broker: 192.168.8.164 Dec 07 00:59:08 sony-avr python3[1369]: Warning: 'pwr-state' not found in command output. Dec 07 00:59:08 sony-avr python3[1369]: Could not determine initial power state. Exiting script. Dec 07 00:59:08 sony-avr systemd[1]: avr-status.service: Main process exited, code=exited, status=1/FAILURE Dec 07 00:59:08 sony-avr systemd[1]: avr-status.service: Failed with result 'exit-code'. Dec 07 00:59:08 sony-avr sudo[1386]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-07 00:58 Dec 07 00:59:08 sony-avr sudo[1386]: 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="cc50ad4a2058d01de272214eb33827883bd2b7d8" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="502750e5d54ecf269d25125b622bfabc030fb553" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 12 Nov 2025 06:58:02 PM CET" VOLUMIO_VERSION="3.874" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="4ae6504ed6f22e44c01a6e93b16badbd"