-- Logs begin at Thu 2024-08-22 14:10:26 CEST, end at Thu 2024-08-22 18:37:14 CEST. -- Aug 22 18:36:04 volumio ifplugd(eth0)[819]: Executing '/etc/ifplugd/ifplugd.action eth0 down'. Aug 22 18:36:04 volumio ifplugd(eth0)[819]: client: sending signal ALRM to pid 907 Aug 22 18:36:04 volumio dhcpcd[25187]: sending signal ALRM to pid 907 Aug 22 18:36:04 volumio dhcpcd[907]: received SIGALRM, releasing Aug 22 18:36:04 volumio dhcpcd[907]: eth0: removing interface Aug 22 18:36:04 volumio ifplugd(eth0)[819]: client: waiting for pid 907 to exit Aug 22 18:36:04 volumio dhcpcd[25187]: waiting for pid 907 to exit Aug 22 18:36:04 volumio dhcpcd[907]: dhcpcd exited Aug 22 18:36:04 volumio kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup Aug 22 18:36:04 volumio ifplugd(eth0)[819]: Program executed successfully. Aug 22 18:36:04 volumio kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup Aug 22 18:36:04 volumio kernel: smsc95xx 1-1.1:1.0 eth0: Link is Down Aug 22 18:36:20 volumio nmbd[775]: [2024/08/22 18:36:20.950890, 0] ../source3/nmbd/nmbd.c:361(reload_interfaces) Aug 22 18:36:20 volumio nmbd[775]: reload_interfaces: No subnets to listen to. Waiting.. Aug 22 18:36:23 volumio volumio[886]: info: Aug 22 18:36:23 volumio volumio[886]: ---------------------------- MPD announces state update: player Aug 22 18:36:23 volumio volumio[886]: info: ControllerMpd::getState Aug 22 18:36:23 volumio volumio[886]: verbose: ControllerMpd::sendMpdCommand status Aug 22 18:36:23 volumio volumio[886]: info: Aug 22 18:36:23 volumio volumio[886]: ---------------------------- MPD announces state update: player Aug 22 18:36:23 volumio volumio[886]: info: ControllerMpd::getState Aug 22 18:36:23 volumio volumio[886]: verbose: ControllerMpd::sendMpdCommand status Aug 22 18:36:23 volumio volumio[886]: info: Aug 22 18:36:23 volumio volumio[886]: ---------------------------- MPD announces state update: player Aug 22 18:36:23 volumio volumio[886]: info: ControllerMpd::getState Aug 22 18:36:23 volumio volumio[886]: verbose: ControllerMpd::sendMpdCommand status Aug 22 18:36:23 volumio volumio[886]: info: sendMpdCommand status took 4 milliseconds Aug 22 18:36:23 volumio volumio[886]: info: sendMpdCommand status took 3 milliseconds Aug 22 18:36:23 volumio volumio[886]: info: sendMpdCommand status took 1 milliseconds Aug 22 18:36:23 volumio volumio[886]: verbose: ControllerMpd::parseState Aug 22 18:36:23 volumio volumio[886]: verbose: ControllerMpd::parseState Aug 22 18:36:23 volumio volumio[886]: verbose: ControllerMpd::parseState Aug 22 18:36:23 volumio volumio[886]: info: ControllerMpd::pushState Aug 22 18:36:23 volumio volumio[886]: info: CoreCommandRouter::servicePushState Aug 22 18:36:23 volumio volumio[886]: info: CoreStateMachine::pushState Aug 22 18:36:23 volumio volumio[886]: info: CorePlayQueue::getTrack 0 Aug 22 18:36:23 volumio volumio[886]: info: ControllerMpd::pushState Aug 22 18:36:23 volumio volumio[886]: info: CoreCommandRouter::servicePushState Aug 22 18:36:23 volumio volumio[886]: info: CoreStateMachine::pushState Aug 22 18:36:23 volumio volumio[886]: info: CorePlayQueue::getTrack 0 Aug 22 18:36:23 volumio volumio[886]: info: ControllerMpd::pushState Aug 22 18:36:23 volumio volumio[886]: info: CoreCommandRouter::servicePushState Aug 22 18:36:23 volumio volumio[886]: info: CoreStateMachine::pushState Aug 22 18:36:23 volumio volumio[886]: info: CorePlayQueue::getTrack 0 Aug 22 18:36:23 volumio volumio[886]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Aug 22 18:36:23 volumio volumio[886]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Aug 22 18:36:23 volumio volumio[886]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Aug 22 18:36:23 volumio volumio[886]: info: ------------------------------ 18ms Aug 22 18:36:23 volumio volumio[886]: info: ------------------------------ 16ms Aug 22 18:36:23 volumio volumio[886]: info: ------------------------------ 15ms Aug 22 18:36:35 volumio go-librespot[1102]: time="2024-08-22T18:36:35+02:00" level=error msg="did not receive last pong from dealer, 60s passed" Aug 22 18:36:40 volumio go-librespot[1102]: time="2024-08-22T18:36:40+02:00" level=error msg="failed receiving dealer message" error="failed to get reader: WebSocket closed: sent close frame: status = StatusServiceRestart and reason = \"\"" Aug 22 18:36:40 volumio go-librespot[1102]: time="2024-08-22T18:36:40+02:00" level=debug msg="renewing login5 access token" Aug 22 18:36:41 volumio go-librespot[1102]: time="2024-08-22T18:36:41+02:00" level=debug msg="renewing login5 access token" Aug 22 18:36:41 volumio go-librespot[1102]: time="2024-08-22T18:36:41+02:00" level=debug msg="renewing login5 access token" Aug 22 18:36:42 volumio go-librespot[1102]: time="2024-08-22T18:36:42+02:00" level=debug msg="renewing login5 access token" Aug 22 18:36:44 volumio go-librespot[1102]: time="2024-08-22T18:36:44+02:00" level=debug msg="renewing login5 access token" Aug 22 18:36:47 volumio go-librespot[1102]: time="2024-08-22T18:36:47+02:00" level=debug msg="renewing login5 access token" Aug 22 18:36:52 volumio go-librespot[1102]: time="2024-08-22T18:36:52+02:00" level=debug msg="renewing login5 access token" Aug 22 18:36:56 volumio kernel: smsc95xx 1-1.1:1.0 eth0: Link is Up - 100Mbps/Full - flow control off Aug 22 18:36:56 volumio go-librespot[1102]: time="2024-08-22T18:36:56+02:00" level=debug msg="renewing login5 access token" Aug 22 18:36:56 volumio ifplugd(eth0)[819]: Link beat detected. Aug 22 18:36:56 volumio ifplugd(eth0)[819]: Executing '/etc/ifplugd/ifplugd.action eth0 up'. Aug 22 18:36:56 volumio dhcpcd[25307]: DUID 00:01:00:01:2d:69:1c:ce:b8:27:eb:c6:6c:ae Aug 22 18:36:56 volumio ifplugd(eth0)[819]: client: DUID 00:01:00:01:2d:69:1c:ce:b8:27:eb:c6:6c:ae Aug 22 18:36:56 volumio ifplugd(eth0)[819]: client: eth0: IAID eb:c6:6c:ae Aug 22 18:36:56 volumio dhcpcd[25307]: eth0: IAID eb:c6:6c:ae Aug 22 18:36:56 volumio ifplugd(eth0)[819]: client: eth0: adding address fe80::ba27:ebff:fec6:6cae Aug 22 18:36:56 volumio dhcpcd[25307]: eth0: adding address fe80::ba27:ebff:fec6:6cae Aug 22 18:36:56 volumio ifplugd(eth0)[819]: client: ipv6_addaddr1: Permission denied Aug 22 18:36:56 volumio dhcpcd[25307]: ipv6_addaddr1: Permission denied Aug 22 18:36:56 volumio ifplugd(eth0)[819]: client: eth0: soliciting an IPv6 router Aug 22 18:36:56 volumio dhcpcd[25307]: eth0: soliciting an IPv6 router Aug 22 18:36:57 volumio ifplugd(eth0)[819]: client: eth0: soliciting a DHCP lease Aug 22 18:36:57 volumio dhcpcd[25307]: eth0: soliciting a DHCP lease Aug 22 18:36:57 volumio ifplugd(eth0)[819]: client: eth0: offered 10.223.223.20 from 10.223.223.254 Aug 22 18:36:57 volumio dhcpcd[25307]: eth0: offered 10.223.223.20 from 10.223.223.254 Aug 22 18:36:57 volumio ifplugd(eth0)[819]: client: eth0: probing address 10.223.223.20/24 Aug 22 18:36:57 volumio dhcpcd[25307]: eth0: probing address 10.223.223.20/24 Aug 22 18:37:00 volumio ntpd[25156]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Aug 22 18:37:01 volumio go-librespot[1102]: time="2024-08-22T18:37:01+02:00" level=debug msg="renewing login5 access token" Aug 22 18:37:01 volumio ntpd[25156]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Aug 22 18:37:02 volumio ntpd[25156]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Aug 22 18:37:02 volumio ntpd[25156]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Aug 22 18:37:03 volumio ifplugd(eth0)[819]: client: eth0: leased 10.223.223.20 for 604800 seconds Aug 22 18:37:03 volumio dhcpcd[25307]: eth0: leased 10.223.223.20 for 604800 seconds Aug 22 18:37:03 volumio avahi-daemon[702]: Joining mDNS multicast group on interface eth0.IPv4 with address 10.223.223.20. Aug 22 18:37:03 volumio avahi-daemon[702]: New relevant interface eth0.IPv4 for mDNS. Aug 22 18:37:03 volumio avahi-daemon[702]: Registering new address record for 10.223.223.20 on eth0.IPv4. Aug 22 18:37:03 volumio ifplugd(eth0)[819]: client: eth0: adding route to 10.223.223.0/24 Aug 22 18:37:03 volumio dhcpcd[25307]: eth0: adding route to 10.223.223.0/24 Aug 22 18:37:03 volumio ifplugd(eth0)[819]: client: eth0: adding default route via 10.223.223.254 Aug 22 18:37:03 volumio dhcpcd[25307]: eth0: adding default route via 10.223.223.254 Aug 22 18:37:03 volumio ntpd[25156]: ntpd exiting on signal 15 (Terminated) Aug 22 18:37:03 volumio systemd[1]: Stopping Network Time Service... Aug 22 18:37:03 volumio systemd[1]: ntp.service: Succeeded. Aug 22 18:37:03 volumio systemd[1]: Stopped Network Time Service. Aug 22 18:37:03 volumio systemd[1]: Starting Network Time Service... Aug 22 18:37:03 volumio ntpd[25342]: ntpd 4.2.8p12@1.3728-o (1): Starting Aug 22 18:37:03 volumio ntpd[25342]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -c /run/ntp.conf.dhcp -u 103:103 Aug 22 18:37:03 volumio systemd[1]: Started Network Time Service. Aug 22 18:37:03 volumio ntpd[25350]: proto: precision = 0.677 usec (-20) Aug 22 18:37:03 volumio ntpd[25350]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Aug 22 18:37:03 volumio ntpd[25350]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2024-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Aug 22 18:37:03 volumio ntpd[25350]: Listen and drop on 0 v6wildcard [::]:123 Aug 22 18:37:03 volumio ntpd[25350]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Aug 22 18:37:03 volumio dhcpcd[25307]: forked to background, child pid 25351 Aug 22 18:37:03 volumio ntpd[25350]: Listen normally on 2 lo 127.0.0.1:123 Aug 22 18:37:03 volumio ntpd[25350]: Listen normally on 3 eth0 10.223.223.20:123 Aug 22 18:37:03 volumio ntpd[25350]: Listening on routing socket on fd #20 for interface updates Aug 22 18:37:03 volumio ifplugd(eth0)[819]: client: forked to background, child pid 25351 Aug 22 18:37:03 volumio ntpd[25350]: kernel reports TIME_ERROR: 0x2041: Clock Unsynchronized Aug 22 18:37:03 volumio ntpd[25350]: kernel reports TIME_ERROR: 0x2041: Clock Unsynchronized Aug 22 18:37:03 volumio ifplugd(eth0)[819]: Program executed successfully. Aug 22 18:37:05 volumio go-librespot[1102]: time="2024-08-22T18:37:05+02:00" level=error msg="did not receive last pong from dealer, 90s passed" Aug 22 18:37:05 volumio volumio[886]: info: CoreCommandRouter::volumioGetState Aug 22 18:37:05 volumio volumio[886]: info: CorePlayQueue::getTrack 0 Aug 22 18:37:05 volumio volumio[886]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Aug 22 18:37:05 volumio volumio[886]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Aug 22 18:37:05 volumio volumio[886]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) Aug 22 18:37:05 volumio volumio[886]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Aug 22 18:37:05 volumio volumio[886]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Aug 22 18:37:05 volumio volumio[886]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Aug 22 18:37:05 volumio volumio[886]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Aug 22 18:37:05 volumio volumio[886]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Aug 22 18:37:05 volumio volumio[886]: at /volumio/node_modules/express/lib/router/index.js:281:22 Aug 22 18:37:05 volumio volumio[886]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Aug 22 18:37:05 volumio volumio[886]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Aug 22 18:37:05 volumio volumio[886]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Aug 22 18:37:05 volumio volumio[886]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Aug 22 18:37:05 volumio volumio[886]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Aug 22 18:37:05 volumio volumio[886]: at /volumio/node_modules/express/lib/router/index.js:284:7 Aug 22 18:37:05 volumio volumio[886]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Aug 22 18:37:05 volumio volumio[886]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Aug 22 18:37:05 volumio volumio[886]: info: Listing playlists Aug 22 18:37:05 volumio volumio[886]: info: Listing playlists Aug 22 18:37:09 volumio go-librespot[1102]: time="2024-08-22T18:37:09+02:00" level=debug msg="renewing login5 access token" Aug 22 18:37:09 volumio ntpd[25350]: Soliciting pool server 178.215.228.24 Aug 22 18:37:09 volumio ntpd[25350]: Soliciting pool server 91.212.242.20 Aug 22 18:37:09 volumio ntpd[25350]: Soliciting pool server 80.50.102.126 Aug 22 18:37:09 volumio go-librespot[1102]: time="2024-08-22T18:37:09+02:00" level=debug msg="authenticated as kostpiotr" Aug 22 18:37:10 volumio go-librespot[1102]: time="2024-08-22T18:37:10+02:00" level=debug msg="re-established dealer connection" Aug 22 18:37:10 volumio go-librespot[1102]: time="2024-08-22T18:37:10+02:00" level=debug msg="received connection id: MmVkY2M3OWYtZTdkZC00ZTU2LTljYmMtMzQ0NzRjZTU2ODI1K2RlYWxlcit0Y3A6Ly8wYWNiZDg1MS5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArOTQyODVBMDZGNDY0NkMxMEY0QjVDRjE4MDdBM0FEMjQ1NDJDRjExMEE2MkE3N0U5NjZBNDFCOEI4RThFRDNFOQ==" Aug 22 18:37:10 volumio go-librespot[1102]: time="2024-08-22T18:37:10+02:00" level=debug msg="put connect state because NEW_DEVICE" Aug 22 18:37:10 volumio ntpd[25350]: Soliciting pool server 185.157.13.96 Aug 22 18:37:10 volumio ntpd[25350]: Soliciting pool server 212.160.106.226 Aug 22 18:37:10 volumio ntpd[25350]: Soliciting pool server 212.127.95.218 Aug 22 18:37:11 volumio ntpd[25350]: Soliciting pool server 195.46.37.22 Aug 22 18:37:11 volumio ntpd[25350]: Soliciting pool server 156.17.20.254 Aug 22 18:37:11 volumio ntpd[25350]: Soliciting pool server 156.17.20.254 Aug 22 18:37:12 volumio ntpd[25350]: Soliciting pool server 2a05:f480:2400:18af:5400:4ff:fe0c:1486 Aug 22 18:37:12 volumio ntpd[25350]: Soliciting pool server 212.127.78.21 Aug 22 18:37:13 volumio volumio[886]: info: Discovery: adding cbcc718b-5366-4c65-9d18-3c59b73da343 Aug 22 18:37:13 volumio volumio[886]: info: Discovery: Found device Volumio Aug 22 18:37:13 volumio volumio[886]: info: CoreCommandRouter::volumioGetState Aug 22 18:37:13 volumio volumio[886]: info: CorePlayQueue::getTrack 0 Aug 22 18:37:13 volumio volumio[886]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 22 18:37:13 volumio volumio[886]: TypeError: Cannot read property 'name' of undefined Aug 22 18:37:13 volumio volumio[886]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Aug 22 18:37:13 volumio volumio[886]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) Aug 22 18:37:13 volumio volumio[886]: at ControllerVolumioDiscovery.connectToRemoteVolumio (/volumio/app/plugins/system_controller/volumiodiscovery/index.js:272:40) Aug 22 18:37:13 volumio volumio[886]: at Browser. (/volumio/app/plugins/system_controller/volumiodiscovery/index.js:192:12) Aug 22 18:37:13 volumio volumio[886]: at Browser.emit (events.js:315:20) Aug 22 18:37:13 volumio volumio[886]: at on_resolver_done (/volumio/node_modules/mdns/lib/browser.js:31:14) Aug 22 18:37:13 volumio volumio[886]: at next (/volumio/node_modules/mdns/lib/browser.js:106:7) Aug 22 18:37:13 volumio volumio[886]: at Array.makeAddressesUnique (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:177:5) Aug 22 18:37:13 volumio volumio[886]: at next (/volumio/node_modules/mdns/lib/browser.js:109:21) Aug 22 18:37:13 volumio volumio[886]: at /volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:160:11 Aug 22 18:37:13 volumio volumio[886]: at getaddrinfo_complete (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:108:7) Aug 22 18:37:13 volumio volumio[886]: at GetAddrInfoReqWrap.oncomplete (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:120:9) Aug 22 18:37:13 volumio volumio[886]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 22 18:37:14 volumio ntpd[25350]: Soliciting pool server 46.174.178.150 Aug 22 18:37:14 volumio sudo[25398]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-22 18:36 Aug 22 18:37:14 volumio sudo[25398]: 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="4b122b2365bb8c09786cd63b50d1ea6db780eb4e" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="49f98390f2d84c6549f33dc85b694fbd99e4c720" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 04 Jun 2024 08:41:12 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="8e78a6e3f56f1bcbbd1760812129a8e9"