Oct 11 22:31:27 volumio ntpd[1002]: CLOCK: time stepped by 0.178968 Oct 11 22:31:27 volumio ntpd[1002]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Oct 11 22:31:45 volumio kernel: usb 1-1.4: new high-speed USB device number 5 using xhci_hcd Oct 11 22:31:46 volumio kernel: usb 1-1.4: device descriptor read/64, error -71 Oct 11 22:31:46 volumio kernel: usb 1-1.4: config 1 has an invalid interface number: 6 but max is 3 Oct 11 22:31:46 volumio kernel: usb 1-1.4: config 1 has no interface number 3 Oct 11 22:31:46 volumio kernel: usb 1-1.4: New USB device found, idVendor=262a, idProduct=9227, bcdDevice= 0.01 Oct 11 22:31:46 volumio kernel: usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Oct 11 22:31:46 volumio kernel: usb 1-1.4: Product: USB-Phone Oct 11 22:31:46 volumio kernel: usb 1-1.4: Manufacturer: Quloos Oct 11 22:31:46 volumio kernel: hid-generic 0003:262A:9227.0001: No inputs registered, leaving Oct 11 22:31:46 volumio kernel: hid-generic 0003:262A:9227.0001: hidraw0: USB HID v1.00 Device [Quloos USB-Phone] on usb-0000:01:00.0-1.4/input0 Oct 11 22:31:46 volumio (udev-worker)[2962]: controlC4: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 4' failed with exit code 99. Oct 11 22:31:47 volumio kernel: usb 1-1.4: USB disconnect, device number 5 Oct 11 22:31:47 volumio kernel: usb 1-1.4: new high-speed USB device number 6 using xhci_hcd Oct 11 22:31:47 volumio kernel: usb 1-1.4: Device not responding to setup address. Oct 11 22:31:48 volumio kernel: usb 1-1.4: Device not responding to setup address. Oct 11 22:31:48 volumio kernel: usb 1-1.4: device not accepting address 6, error -71 Oct 11 22:31:48 volumio kernel: usb 1-1.4: new high-speed USB device number 7 using xhci_hcd Oct 11 22:31:48 volumio kernel: usb 1-1.4: config 1 has an invalid interface number: 6 but max is 3 Oct 11 22:31:48 volumio kernel: usb 1-1.4: config 1 has no interface number 3 Oct 11 22:31:48 volumio kernel: usb 1-1.4: New USB device found, idVendor=262a, idProduct=9227, bcdDevice= 0.01 Oct 11 22:31:48 volumio kernel: usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Oct 11 22:31:48 volumio kernel: usb 1-1.4: Product: USB-Phone Oct 11 22:31:48 volumio kernel: usb 1-1.4: Manufacturer: Quloos Oct 11 22:31:48 volumio kernel: hid-generic 0003:262A:9227.0002: No inputs registered, leaving Oct 11 22:31:48 volumio kernel: hid-generic 0003:262A:9227.0002: hidraw0: USB HID v1.00 Device [Quloos USB-Phone] on usb-0000:01:00.0-1.4/input0 Oct 11 22:31:48 volumio (udev-worker)[2961]: controlC4: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 4' failed with exit code 99. Oct 11 22:31:50 volumio kernel: usb 1-1.4: USB disconnect, device number 7 Oct 11 22:31:50 volumio kernel: usb 1-1.4: new high-speed USB device number 8 using xhci_hcd Oct 11 22:31:50 volumio kernel: usb 1-1.4: config 1 has an invalid interface number: 6 but max is 3 Oct 11 22:31:50 volumio kernel: usb 1-1.4: config 1 has no interface number 3 Oct 11 22:31:50 volumio kernel: usb 1-1.4: New USB device found, idVendor=262a, idProduct=9227, bcdDevice= 0.01 Oct 11 22:31:50 volumio kernel: usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Oct 11 22:31:50 volumio kernel: usb 1-1.4: Product: USB-Phone Oct 11 22:31:50 volumio kernel: usb 1-1.4: Manufacturer: Quloos Oct 11 22:31:50 volumio kernel: hid-generic 0003:262A:9227.0003: No inputs registered, leaving Oct 11 22:31:50 volumio kernel: hid-generic 0003:262A:9227.0003: hidraw0: USB HID v1.00 Device [Quloos USB-Phone] on usb-0000:01:00.0-1.4/input0 Oct 11 22:31:50 volumio (udev-worker)[2961]: controlC4: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 4' failed with exit code 99. Oct 11 22:31:51 volumio sudo[2986]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 11 22:31:51 volumio sudo[2986]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 11 22:31:51 volumio sudo[2986]: pam_unix(sudo:session): session closed for user root Oct 11 22:31:51 volumio sudo[2988]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 11 22:31:51 volumio sudo[2988]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 11 22:31:51 volumio sudo[2988]: pam_unix(sudo:session): session closed for user root Oct 11 22:31:51 volumio volumio[1246]: verbose: New Socket.io Connection to 192.168.10.5 from 192.168.10.2 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/154.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::volumioGetVisibleSources Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::volumioGetState Oct 11 22:31:51 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 11 22:31:51 volumio volumio[1246]: info: Received Get System Info Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 11 22:31:51 volumio volumio[1246]: info: Discovery: Getting this device information Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::volumioGetState Oct 11 22:31:51 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::volumioGetState Oct 11 22:31:51 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:31:51 volumio volumio[1246]: info: Listing playlists Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 11 22:31:51 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 11 22:31:52 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 11 22:31:53 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 11 22:31:53 volumio volumio[1246]: info: Received Get System Info Oct 11 22:31:53 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 11 22:31:53 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 11 22:31:53 volumio volumio[1246]: info: Discovery: Getting this device information Oct 11 22:31:53 volumio volumio[1246]: info: CoreCommandRouter::volumioGetState Oct 11 22:31:53 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:31:53 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 11 22:31:54 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 11 22:31:54 volumio volumio[1246]: info: Received Get System Info Oct 11 22:31:54 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 11 22:31:54 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 11 22:31:54 volumio volumio[1246]: info: Discovery: Getting this device information Oct 11 22:31:54 volumio volumio[1246]: info: CoreCommandRouter::volumioGetState Oct 11 22:31:54 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:31:54 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 11 22:31:58 volumio kernel: usb 1-1.3: USB disconnect, device number 4 Oct 11 22:31:58 volumio volumio[1246]: info: Oct 11 22:31:58 volumio volumio[1246]: ---------------------------- USB Audio Device Detached Oct 11 22:31:58 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach Oct 11 22:31:58 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 11 22:32:01 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 11 22:32:04 volumio volumio[1246]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions Oct 11 22:32:04 volumio volumio[1246]: info: Preparing to save Alsa Options, stopping services first Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::volumioGetState Oct 11 22:32:04 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::volumioPause Oct 11 22:32:04 volumio volumio[1246]: info: CoreStateMachine::pause Oct 11 22:32:04 volumio volumio[1246]: info: Saving Audio Output to: {"output_device":{"value":"4","label":"USB-Phone"},"i2s":false,"i2sid":{"value":"adafruit-max98357","label":"Adafruit MAX98357"}} Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 11 22:32:04 volumio volumio[1246]: info: Setting mixer PCM for card USB-Phone Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::volumioUpdateVolumeSettings Oct 11 22:32:04 volumio volumio[1246]: info: Updating Volume Controller Parameters: Device: 4 Name: USB-Phone Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Oct 11 22:32:04 volumio volumio[1246]: info: Disabling external Volume Control Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 11 22:32:04 volumio volumio[1246]: info: Preparing to generate the ALSA configuration file Oct 11 22:32:04 volumio volumio[1246]: info: VolumeController:: Volume=25 Mute =false Oct 11 22:32:04 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:04 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 11 22:32:04 volumio volumio[1246]: info: Asound.conf file written Oct 11 22:32:04 volumio sudo[3060]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Oct 11 22:32:04 volumio sudo[3060]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 11 22:32:04 volumio sudo[3060]: pam_unix(sudo:session): session closed for user root Oct 11 22:32:04 volumio volumio[1246]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Oct 11 22:32:04 volumio volumio[1246]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Oct 11 22:32:04 volumio volumio[1246]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Oct 11 22:32:04 volumio volumio[1246]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:3 use case configuration -2 Oct 11 22:32:04 volumio volumio[1246]: No state is present for card USBPhone Oct 11 22:32:04 volumio volumio[1246]: Found hardware: "USB-Audio" "USB Mixer" "USB262a:9227" "" "" Oct 11 22:32:04 volumio volumio[1246]: Hardware is initialized using a generic method Oct 11 22:32:04 volumio volumio[1246]: No state is present for card USBPhone Oct 11 22:32:04 volumio volumio[1246]: info: Output device has changed, restarting MPD Oct 11 22:32:04 volumio volumio[1246]: info: Output device has changed, restarting Shairport Sync Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 11 22:32:04 volumio sudo[3066]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 11 22:32:04 volumio sudo[3068]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 11 22:32:04 volumio sudo[3066]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 11 22:32:04 volumio sudo[3068]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 11 22:32:04 volumio sudo[3066]: pam_unix(sudo:session): session closed for user root Oct 11 22:32:04 volumio volumio[1246]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 11 22:32:04 volumio volumio[1246]: info: Output device has changed, restarting MPD Oct 11 22:32:04 volumio volumio[1246]: info: Output device has changed, restarting Shairport Sync Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 11 22:32:04 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 11 22:32:04 volumio sudo[3077]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 11 22:32:04 volumio sudo[3077]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 11 22:32:04 volumio sudo[3078]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 11 22:32:04 volumio sudo[3078]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 11 22:32:04 volumio sudo[3077]: pam_unix(sudo:session): session closed for user root Oct 11 22:32:04 volumio volumio[1246]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 11 22:32:04 volumio volumio[1246]: info: MPD Permissions set Oct 11 22:32:04 volumio volumio[1246]: info: MPD Permissions set Oct 11 22:32:04 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 11 22:32:04 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 11 22:32:04 volumio systemd[1]: mpd.service: Consumed 1.381s CPU time. Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 11 22:32:04 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 11 22:32:04 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 11 22:32:04 volumio volumio[1246]: info: Starting Shairport Sync Oct 11 22:32:04 volumio volumio[1246]: info: Starting Shairport Sync Oct 11 22:32:04 volumio sudo[3097]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 11 22:32:04 volumio sudo[3097]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 11 22:32:04 volumio sudo[3099]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 11 22:32:04 volumio sudo[3099]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 11 22:32:04 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 11 22:32:04 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 11 22:32:04 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 11 22:32:04 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 11 22:32:04 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 11 22:32:04 volumio systemd[1]: shairport-sync.service: Consumed 2.938s CPU time. Oct 11 22:32:04 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 11 22:32:04 volumio sudo[3099]: pam_unix(sudo:session): session closed for user root Oct 11 22:32:04 volumio sudo[3097]: pam_unix(sudo:session): session closed for user root Oct 11 22:32:04 volumio volumio[1246]: info: Shairport-Sync Started Oct 11 22:32:04 volumio volumio[1246]: info: Shairport-Sync Started Oct 11 22:32:04 volumio sudo[3102]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 11 22:32:04 volumio sudo[3102]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 11 22:32:04 volumio sudo[3102]: pam_unix(sudo:session): session closed for user root Oct 11 22:32:06 volumio mpd[3119]: 2026-10-11T22:32:06 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 11 22:32:06 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 11 22:32:06 volumio sudo[3078]: pam_unix(sudo:session): session closed for user root Oct 11 22:32:06 volumio sudo[3068]: pam_unix(sudo:session): session closed for user root Oct 11 22:32:06 volumio volumio[1246]: error: MPD error: The expression evaluated to a falsy value: Oct 11 22:32:06 volumio volumio[1246]: assert.ok(self.idling) Oct 11 22:32:06 volumio volumio[1246]: error: The expression evaluated to a falsy value: Oct 11 22:32:06 volumio volumio[1246]: assert.ok(self.idling) Oct 11 22:32:06 volumio volumio[1246]: error: updateQueue error: null Oct 11 22:32:08 volumio volumio[1246]: info: CoreCommandRouter::volumioRetrieveVolumeLevels Oct 11 22:32:08 volumio volumio[1246]: info: CoreStateMachine::getcurrentVolume Oct 11 22:32:08 volumio volumio[1246]: info: CoreCommandRouter::volumioRetrievevolume Oct 11 22:32:08 volumio volumio[1246]: info: VolumeController:: Volume=25 Mute =false Oct 11 22:32:08 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:08 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:08 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:08 volumio volumio[1246]: info: CoreStateMachine::updateTrackBlock Oct 11 22:32:08 volumio volumio[1246]: info: CorePlayQueue::getTrackBlock Oct 11 22:32:08 volumio volumio[1246]: info: CoreCommandRouter::volumioRetrievevolume Oct 11 22:32:08 volumio volumio[1246]: info: VolumeController:: Volume=25 Mute =false Oct 11 22:32:08 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:08 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:08 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:08 volumio kernel: usb 1-1.4: USB disconnect, device number 8 Oct 11 22:32:08 volumio kernel: usb 1-1.4: new high-speed USB device number 9 using xhci_hcd Oct 11 22:32:08 volumio kernel: usb 1-1.4: config 1 has an invalid interface number: 6 but max is 3 Oct 11 22:32:08 volumio kernel: usb 1-1.4: config 1 has no interface number 3 Oct 11 22:32:08 volumio kernel: usb 1-1.4: New USB device found, idVendor=262a, idProduct=9227, bcdDevice= 0.01 Oct 11 22:32:08 volumio kernel: usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Oct 11 22:32:08 volumio kernel: usb 1-1.4: Product: USB-Phone Oct 11 22:32:08 volumio kernel: usb 1-1.4: Manufacturer: Quloos Oct 11 22:32:08 volumio kernel: hid-generic 0003:262A:9227.0004: No inputs registered, leaving Oct 11 22:32:08 volumio kernel: hid-generic 0003:262A:9227.0004: hidraw0: USB HID v1.00 Device [Quloos USB-Phone] on usb-0000:01:00.0-1.4/input0 Oct 11 22:32:08 volumio (udev-worker)[3140]: controlC5: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 5' failed with exit code 99. Oct 11 22:32:08 volumio volumio[1246]: info: Oct 11 22:32:08 volumio volumio[1246]: ---------------------------- USB Audio Device Attached Oct 11 22:32:08 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach Oct 11 22:32:10 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 11 22:32:10 volumio volumio[1246]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 11 22:32:10 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 11 22:32:10 volumio volumio[1246]: info: Received Get System Version Oct 11 22:32:10 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 11 22:32:10 volumio volumio[1246]: info: Received Get System Info Oct 11 22:32:10 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 11 22:32:10 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 11 22:32:10 volumio volumio[1246]: info: Discovery: Getting this device information Oct 11 22:32:10 volumio volumio[1246]: info: CoreCommandRouter::volumioGetState Oct 11 22:32:10 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:10 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 11 22:32:10 volumio kernel: usb 1-1.4: USB disconnect, device number 9 Oct 11 22:32:10 volumio volumio[1246]: info: Oct 11 22:32:10 volumio volumio[1246]: ---------------------------- USB Audio Device Detached Oct 11 22:32:10 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach Oct 11 22:32:10 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 11 22:32:10 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: raat , onStop Oct 11 22:32:10 volumio kernel: usb 1-1.4: new high-speed USB device number 10 using xhci_hcd Oct 11 22:32:10 volumio kernel: usb 1-1.4: config 1 has an invalid interface number: 6 but max is 3 Oct 11 22:32:10 volumio kernel: usb 1-1.4: config 1 has no interface number 3 Oct 11 22:32:10 volumio kernel: usb 1-1.4: New USB device found, idVendor=262a, idProduct=9227, bcdDevice= 0.01 Oct 11 22:32:10 volumio kernel: usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Oct 11 22:32:10 volumio kernel: usb 1-1.4: Product: USB-Phone Oct 11 22:32:10 volumio kernel: usb 1-1.4: Manufacturer: Quloos Oct 11 22:32:10 volumio kernel: hid-generic 0003:262A:9227.0005: No inputs registered, leaving Oct 11 22:32:10 volumio kernel: hid-generic 0003:262A:9227.0005: hidraw0: USB HID v1.00 Device [Quloos USB-Phone] on usb-0000:01:00.0-1.4/input0 Oct 11 22:32:10 volumio (udev-worker)[3142]: controlC5: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 5' failed with exit code 99. Oct 11 22:32:10 volumio volumio[1246]: info: Oct 11 22:32:10 volumio volumio[1246]: ---------------------------- USB Audio Device Attached Oct 11 22:32:10 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach Oct 11 22:32:18 volumio volumio[1246]: info: CoreCommandRouter::volumioGetState Oct 11 22:32:18 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:19 volumio volumio[1246]: info: CoreCommandRouter::volumioPlay Oct 11 22:32:19 volumio volumio[1246]: info: CoreStateMachine::play index undefined Oct 11 22:32:19 volumio volumio[1246]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 11 22:32:19 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:19 volumio volumio[1246]: info: CoreStateMachine::startPlaybackTimer Oct 11 22:32:19 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:19 volumio volumio[1246]: verbose: ControllerMpd::clearAddPlayTracks http://127.0.0.1:8088/wav/track/1?disc=1791730273222 Oct 11 22:32:19 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand stop Oct 11 22:32:19 volumio volumio[1246]: info: sendMpdCommand stop took 1 milliseconds Oct 11 22:32:19 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand clear Oct 11 22:32:19 volumio volumio[1246]: info: Oct 11 22:32:19 volumio volumio[1246]: ---------------------------- MPD announces system playlist update Oct 11 22:32:19 volumio volumio[1246]: info: Ignoring MPD Status Update Oct 11 22:32:19 volumio volumio[1246]: info: sendMpdCommand clear took 2 milliseconds Oct 11 22:32:19 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:8088/wav/track/1?disc=1791730273222" Oct 11 22:32:19 volumio volumio[1246]: info: Oct 11 22:32:19 volumio volumio[1246]: ---------------------------- MPD announces system playlist update Oct 11 22:32:19 volumio volumio[1246]: info: Ignoring MPD Status Update Oct 11 22:32:19 volumio volumio[1246]: error: updateQueue error: null Oct 11 22:32:19 volumio volumio[1246]: info: Oct 11 22:32:19 volumio volumio[1246]: ---------------------------- MPD announces system playlist update Oct 11 22:32:19 volumio volumio[1246]: info: Ignoring MPD Status Update Oct 11 22:32:19 volumio volumio[1246]: info: ------------------------------ 6ms Oct 11 22:32:19 volumio volumio[1246]: info: sendMpdCommand add "http://127.0.0.1:8088/wav/track/1?disc=1791730273222" took 4 milliseconds Oct 11 22:32:19 volumio volumio[1246]: info: ------------------------------ 4ms Oct 11 22:32:19 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand play Oct 11 22:32:19 volumio volumio[1246]: info: Oct 11 22:32:19 volumio volumio[1246]: ---------------------------- MPD announces system playlist update Oct 11 22:32:19 volumio volumio[1246]: info: Ignoring MPD Status Update Oct 11 22:32:19 volumio volumio[1246]: info: ------------------------------ 5ms Oct 11 22:32:19 volumio volumio[1246]: info: sendMpdCommand play took 3 milliseconds Oct 11 22:32:19 volumio volumio[1246]: info: ------------------------------ 4ms Oct 11 22:32:22 volumio volumio[1246]: info: Oct 11 22:32:22 volumio volumio[1246]: ---------------------------- MPD announces state update: player Oct 11 22:32:22 volumio volumio[1246]: info: ControllerMpd::getState Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand status Oct 11 22:32:22 volumio volumio[1246]: info: Oct 11 22:32:22 volumio volumio[1246]: ---------------------------- MPD announces state update: player Oct 11 22:32:22 volumio volumio[1246]: info: ControllerMpd::getState Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand status Oct 11 22:32:22 volumio volumio[1246]: info: Oct 11 22:32:22 volumio volumio[1246]: ---------------------------- MPD announces state update: player Oct 11 22:32:22 volumio volumio[1246]: info: sendMpdCommand status took 24 milliseconds Oct 11 22:32:22 volumio volumio[1246]: info: ControllerMpd::getState Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand status Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::parseState Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 11 22:32:22 volumio volumio[1246]: info: Oct 11 22:32:22 volumio volumio[1246]: ---------------------------- MPD announces state update: player Oct 11 22:32:22 volumio volumio[1246]: info: ControllerMpd::getState Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand status Oct 11 22:32:22 volumio volumio[1246]: info: sendMpdCommand status took 27 milliseconds Oct 11 22:32:22 volumio volumio[1246]: info: sendMpdCommand status took 4 milliseconds Oct 11 22:32:22 volumio volumio[1246]: info: sendMpdCommand playlistinfo took 3 milliseconds Oct 11 22:32:22 volumio volumio[1246]: info: sendMpdCommand status took 1 milliseconds Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::parseState Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::parseState Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::parseTrackInfo Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::parseState Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 11 22:32:22 volumio volumio[1246]: info: ControllerMpd::pushState Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::servicePushState Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:22 volumio volumio[1246]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":189,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"1?disc=1791730273222","artist":null,"album":null,"uri":"http://127.0.0.1:8088/wav/track/1?disc=1791730273222","trackType":""} Oct 11 22:32:22 volumio volumio[1246]: verbose: CURRENT POSITION 0 Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::syncState stateService play Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::syncState currentStatus stop Oct 11 22:32:22 volumio volumio[1246]: info: ------------------------------ 37ms Oct 11 22:32:22 volumio volumio[1246]: info: sendMpdCommand playlistinfo took 7 milliseconds Oct 11 22:32:22 volumio volumio[1246]: info: sendMpdCommand playlistinfo took 7 milliseconds Oct 11 22:32:22 volumio volumio[1246]: info: sendMpdCommand playlistinfo took 8 milliseconds Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::parseTrackInfo Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::parseTrackInfo Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::parseTrackInfo Oct 11 22:32:22 volumio volumio[1246]: info: ControllerMpd::pushState Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::servicePushState Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:22 volumio volumio[1246]: verbose: STATE SERVICE {"status":"play","position":0,"seek":46,"duration":189,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"1?disc=1791730273222","artist":null,"album":null,"uri":"http://127.0.0.1:8088/wav/track/1?disc=1791730273222","trackType":""} Oct 11 22:32:22 volumio volumio[1246]: verbose: CURRENT POSITION 0 Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::syncState stateService play Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::syncState currentStatus play Oct 11 22:32:22 volumio volumio[1246]: info: Received an update from plugin. extracting info from payload Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:22 volumio volumio[1246]: info: ControllerMpd::pushState Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::servicePushState Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:22 volumio volumio[1246]: verbose: STATE SERVICE {"status":"play","position":0,"seek":848,"duration":189,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"1?disc=1791730273222","artist":null,"album":null,"uri":"http://127.0.0.1:8088/wav/track/1?disc=1791730273222","trackType":""} Oct 11 22:32:22 volumio volumio[1246]: verbose: CURRENT POSITION 0 Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::syncState stateService play Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::syncState currentStatus play Oct 11 22:32:22 volumio volumio[1246]: info: Received an update from plugin. extracting info from payload Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:22 volumio volumio[1246]: info: ControllerMpd::pushState Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::servicePushState Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:22 volumio volumio[1246]: verbose: STATE SERVICE {"status":"play","position":0,"seek":848,"duration":189,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"1?disc=1791730273222","artist":null,"album":null,"uri":"http://127.0.0.1:8088/wav/track/1?disc=1791730273222","trackType":""} Oct 11 22:32:22 volumio volumio[1246]: verbose: CURRENT POSITION 0 Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::syncState stateService play Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::syncState currentStatus play Oct 11 22:32:22 volumio volumio[1246]: info: Received an update from plugin. extracting info from payload Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:22 volumio volumio[1246]: info: ------------------------------ 93ms Oct 11 22:32:22 volumio volumio[1246]: info: ------------------------------ 70ms Oct 11 22:32:22 volumio volumio[1246]: info: ------------------------------ 67ms Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::volumioGetQueue Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::getQueue Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getQueue Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::volumioGetQueue Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::getQueue Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getQueue Oct 11 22:32:22 volumio kernel: usb 1-1.4: USB disconnect, device number 10 Oct 11 22:32:22 volumio kernel: usb 1-1.4: cannot submit urb (err = -19) Oct 11 22:32:22 volumio volumio[1246]: info: Oct 11 22:32:22 volumio volumio[1246]: ---------------------------- MPD announces state update: player Oct 11 22:32:22 volumio volumio[1246]: info: ControllerMpd::getState Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand status Oct 11 22:32:22 volumio volumio[1246]: info: Oct 11 22:32:22 volumio volumio[1246]: ---------------------------- MPD announces state update: player Oct 11 22:32:22 volumio volumio[1246]: info: ControllerMpd::getState Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand status Oct 11 22:32:22 volumio volumio[1246]: error: MPD returned error for command status: Failed to open audio output Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand clearerror Oct 11 22:32:22 volumio volumio[1246]: info: sendMpdCommand status took 9 milliseconds Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::parseState Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 11 22:32:22 volumio volumio[1246]: error: MPD returned error for command status: Failed to open audio output Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand clearerror Oct 11 22:32:22 volumio volumio[1246]: info: sendMpdCommand status took 15 milliseconds Oct 11 22:32:22 volumio volumio[1246]: info: sendMpdCommand clearerror took 7 milliseconds Oct 11 22:32:22 volumio volumio[1246]: info: sendMpdCommand playlistinfo took 7 milliseconds Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::parseState Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::parseTrackInfo Oct 11 22:32:22 volumio volumio[1246]: info: ControllerMpd::pushState Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::servicePushState Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:22 volumio volumio[1246]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2567,"duration":189,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"1?disc=1791730273222","artist":null,"album":null,"uri":"http://127.0.0.1:8088/wav/track/1?disc=1791730273222","trackType":""} Oct 11 22:32:22 volumio volumio[1246]: verbose: CURRENT POSITION 0 Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::syncState stateService pause Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::syncState currentStatus play Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:22 volumio volumio[1246]: info: ------------------------------ 30ms Oct 11 22:32:22 volumio volumio[1246]: info: sendMpdCommand clearerror took 19 milliseconds Oct 11 22:32:22 volumio volumio[1246]: info: sendMpdCommand playlistinfo took 17 milliseconds Oct 11 22:32:22 volumio volumio[1246]: verbose: ControllerMpd::parseTrackInfo Oct 11 22:32:22 volumio volumio[1246]: info: ControllerMpd::pushState Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::servicePushState Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:22 volumio volumio[1246]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2567,"duration":189,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"1?disc=1791730273222","artist":null,"album":null,"uri":"http://127.0.0.1:8088/wav/track/1?disc=1791730273222","trackType":""} Oct 11 22:32:22 volumio volumio[1246]: verbose: CURRENT POSITION 0 Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::syncState stateService pause Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::syncState currentStatus play Oct 11 22:32:22 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:22 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:22 volumio volumio[1246]: info: ------------------------------ 47ms Oct 11 22:32:22 volumio volumio[1246]: info: Oct 11 22:32:22 volumio volumio[1246]: ---------------------------- USB Audio Device Detached Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 11 22:32:22 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: raat , onStop Oct 11 22:32:23 volumio kernel: usb 1-1.4: new high-speed USB device number 11 using xhci_hcd Oct 11 22:32:23 volumio kernel: usb 1-1.4: config 1 has an invalid interface number: 6 but max is 3 Oct 11 22:32:23 volumio kernel: usb 1-1.4: config 1 has no interface number 3 Oct 11 22:32:23 volumio kernel: usb 1-1.4: New USB device found, idVendor=262a, idProduct=9227, bcdDevice= 0.01 Oct 11 22:32:23 volumio kernel: usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Oct 11 22:32:23 volumio kernel: usb 1-1.4: Product: USB-Phone Oct 11 22:32:23 volumio kernel: usb 1-1.4: Manufacturer: Quloos Oct 11 22:32:23 volumio kernel: hid-generic 0003:262A:9227.0006: No inputs registered, leaving Oct 11 22:32:23 volumio kernel: hid-generic 0003:262A:9227.0006: hidraw0: USB HID v1.00 Device [Quloos USB-Phone] on usb-0000:01:00.0-1.4/input0 Oct 11 22:32:23 volumio (udev-worker)[3190]: controlC5: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 5' failed with exit code 99. Oct 11 22:32:23 volumio volumio[1246]: info: Oct 11 22:32:23 volumio volumio[1246]: ---------------------------- USB Audio Device Attached Oct 11 22:32:23 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach Oct 11 22:32:23 volumio kernel: usb 1-1.4: USB disconnect, device number 11 Oct 11 22:32:23 volumio volumio[1246]: info: Oct 11 22:32:23 volumio volumio[1246]: ---------------------------- USB Audio Device Detached Oct 11 22:32:23 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach Oct 11 22:32:23 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 11 22:32:23 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: raat , onStop Oct 11 22:32:23 volumio kernel: usb 1-1.4: new high-speed USB device number 12 using xhci_hcd Oct 11 22:32:23 volumio kernel: usb 1-1.4: config 1 has an invalid interface number: 6 but max is 3 Oct 11 22:32:23 volumio kernel: usb 1-1.4: config 1 has no interface number 3 Oct 11 22:32:23 volumio kernel: usb 1-1.4: New USB device found, idVendor=262a, idProduct=9227, bcdDevice= 0.01 Oct 11 22:32:23 volumio kernel: usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Oct 11 22:32:23 volumio kernel: usb 1-1.4: Product: USB-Phone Oct 11 22:32:23 volumio kernel: usb 1-1.4: Manufacturer: Quloos Oct 11 22:32:23 volumio kernel: hid-generic 0003:262A:9227.0007: No inputs registered, leaving Oct 11 22:32:23 volumio kernel: hid-generic 0003:262A:9227.0007: hidraw0: USB HID v1.00 Device [Quloos USB-Phone] on usb-0000:01:00.0-1.4/input0 Oct 11 22:32:23 volumio (udev-worker)[3190]: controlC5: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 5' failed with exit code 99. Oct 11 22:32:23 volumio volumio[1246]: info: Oct 11 22:32:23 volumio volumio[1246]: ---------------------------- USB Audio Device Attached Oct 11 22:32:23 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach Oct 11 22:32:23 volumio kernel: usb 1-1.4: USB disconnect, device number 12 Oct 11 22:32:23 volumio volumio[1246]: info: Oct 11 22:32:23 volumio volumio[1246]: ---------------------------- USB Audio Device Detached Oct 11 22:32:23 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach Oct 11 22:32:23 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 11 22:32:23 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: raat , onStop Oct 11 22:32:24 volumio kernel: usb 1-1.4: new high-speed USB device number 13 using xhci_hcd Oct 11 22:32:24 volumio kernel: usb 1-1.4: config 1 has an invalid interface number: 6 but max is 3 Oct 11 22:32:24 volumio kernel: usb 1-1.4: config 1 has no interface number 3 Oct 11 22:32:24 volumio kernel: usb 1-1.4: New USB device found, idVendor=262a, idProduct=9227, bcdDevice= 0.01 Oct 11 22:32:24 volumio kernel: usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Oct 11 22:32:24 volumio kernel: usb 1-1.4: Product: USB-Phone Oct 11 22:32:24 volumio kernel: usb 1-1.4: Manufacturer: Quloos Oct 11 22:32:24 volumio kernel: hid-generic 0003:262A:9227.0008: No inputs registered, leaving Oct 11 22:32:24 volumio kernel: hid-generic 0003:262A:9227.0008: hidraw0: USB HID v1.00 Device [Quloos USB-Phone] on usb-0000:01:00.0-1.4/input0 Oct 11 22:32:24 volumio (udev-worker)[3193]: controlC5: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 5' failed with exit code 99. Oct 11 22:32:24 volumio volumio[1246]: info: Oct 11 22:32:24 volumio volumio[1246]: ---------------------------- USB Audio Device Attached Oct 11 22:32:24 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach Oct 11 22:32:29 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Oct 11 22:32:29 volumio volumio[1246]: info: CURURI: albums:// Oct 11 22:32:29 volumio volumio[1246]: info: listAlbums - loading Albums from cache Oct 11 22:32:29 volumio volumio[1246]: info: Preload queue cleared Oct 11 22:32:30 volumio kernel: usb 1-1.4: USB disconnect, device number 13 Oct 11 22:32:30 volumio volumio[1246]: info: Oct 11 22:32:30 volumio volumio[1246]: ---------------------------- USB Audio Device Detached Oct 11 22:32:30 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach Oct 11 22:32:30 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 11 22:32:30 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: raat , onStop Oct 11 22:32:30 volumio kernel: usb 1-1.4: new high-speed USB device number 14 using xhci_hcd Oct 11 22:32:30 volumio kernel: usb 1-1.4: config 1 has an invalid interface number: 6 but max is 3 Oct 11 22:32:30 volumio kernel: usb 1-1.4: config 1 has no interface number 3 Oct 11 22:32:30 volumio kernel: usb 1-1.4: New USB device found, idVendor=262a, idProduct=9227, bcdDevice= 0.01 Oct 11 22:32:30 volumio kernel: usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Oct 11 22:32:30 volumio kernel: usb 1-1.4: Product: USB-Phone Oct 11 22:32:30 volumio kernel: usb 1-1.4: Manufacturer: Quloos Oct 11 22:32:30 volumio kernel: hid-generic 0003:262A:9227.0009: No inputs registered, leaving Oct 11 22:32:30 volumio kernel: hid-generic 0003:262A:9227.0009: hidraw0: USB HID v1.00 Device [Quloos USB-Phone] on usb-0000:01:00.0-1.4/input0 Oct 11 22:32:30 volumio (udev-worker)[3237]: controlC5: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 5' failed with exit code 99. Oct 11 22:32:30 volumio volumio[1246]: info: Oct 11 22:32:30 volumio volumio[1246]: ---------------------------- USB Audio Device Attached Oct 11 22:32:30 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach Oct 11 22:32:32 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: cdplayer , handleBrowseUri Oct 11 22:32:32 volumio volumio[1246]: info: [CDPlayer]: Attempt #1 to list CD tracks Oct 11 22:32:35 volumio volumio[1246]: info: [CDPlayer]: No CD metadata found, retrying in background Oct 11 22:32:35 volumio volumio[1246]: info: Preload queue cleared Oct 11 22:32:35 volumio volumio[1246]: info: Preloading song: cdplayer/1?disc=1791731895998 Oct 11 22:32:35 volumio volumio[1246]: info: Preloading song: cdplayer/2?disc=1791731895998 Oct 11 22:32:35 volumio volumio[1246]: info: Preloading song: cdplayer/3?disc=1791731895998 Oct 11 22:32:35 volumio volumio[1246]: info: Preloading song: cdplayer/4?disc=1791731895998 Oct 11 22:32:35 volumio volumio[1246]: info: Preloading song: cdplayer/5?disc=1791731895998 Oct 11 22:32:35 volumio volumio[1246]: info: Preloading song: cdplayer/6?disc=1791731895998 Oct 11 22:32:35 volumio volumio[1246]: info: Preloading song: cdplayer/7?disc=1791731895998 Oct 11 22:32:35 volumio volumio[1246]: info: Preloading song: cdplayer/8?disc=1791731895998 Oct 11 22:32:35 volumio volumio[1246]: info: Preloading song: cdplayer/9?disc=1791731895998 Oct 11 22:32:35 volumio volumio[1246]: info: Preloading song: cdplayer/10?disc=1791731895998 Oct 11 22:32:35 volumio volumio[1246]: info: Preloading song: cdplayer/11?disc=1791731895998 Oct 11 22:32:35 volumio volumio[1246]: info: Preload queue cleared Oct 11 22:32:36 volumio volumio[1246]: info: [CDPlayer]: [tray-watcher] handling change on /dev/sr0 Oct 11 22:32:36 volumio volumio[1246]: info: [CDPlayer]: [tray-watcher] decision for /dev/sr0: action=change media=1 ready= ejectReq=1 mediaPresent=true pendingEject=true noDisc=false Oct 11 22:32:36 volumio volumio[1246]: info: [CDPlayer]: CD metadata fetch attempt #1 error Oct 11 22:32:36 volumio kernel: usb 1-1.4: USB disconnect, device number 14 Oct 11 22:32:36 volumio volumio[1246]: info: Oct 11 22:32:36 volumio volumio[1246]: ---------------------------- USB Audio Device Detached Oct 11 22:32:36 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach Oct 11 22:32:36 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 11 22:32:36 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: raat , onStop Oct 11 22:32:36 volumio kernel: usb 1-1.4: new high-speed USB device number 15 using xhci_hcd Oct 11 22:32:37 volumio kernel: usb 1-1.4: config 1 has an invalid interface number: 6 but max is 3 Oct 11 22:32:37 volumio kernel: usb 1-1.4: config 1 has no interface number 3 Oct 11 22:32:37 volumio kernel: usb 1-1.4: New USB device found, idVendor=262a, idProduct=9227, bcdDevice= 0.01 Oct 11 22:32:37 volumio kernel: usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Oct 11 22:32:37 volumio kernel: usb 1-1.4: Product: USB-Phone Oct 11 22:32:37 volumio kernel: usb 1-1.4: Manufacturer: Quloos Oct 11 22:32:37 volumio kernel: hid-generic 0003:262A:9227.000A: No inputs registered, leaving Oct 11 22:32:37 volumio kernel: hid-generic 0003:262A:9227.000A: hidraw0: USB HID v1.00 Device [Quloos USB-Phone] on usb-0000:01:00.0-1.4/input0 Oct 11 22:32:37 volumio (udev-worker)[3262]: controlC5: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 5' failed with exit code 99. Oct 11 22:32:37 volumio volumio[1246]: info: Oct 11 22:32:37 volumio volumio[1246]: ---------------------------- USB Audio Device Attached Oct 11 22:32:37 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach Oct 11 22:32:37 volumio volumio[1246]: info: [CDPlayer]: CD metadata fetch attempt #2... Oct 11 22:32:39 volumio volumio[1246]: info: [CDPlayer]: [tray-watcher] handling change on /dev/sr0 Oct 11 22:32:39 volumio volumio[1246]: info: [CDPlayer]: CD metadata fetch attempt #2 error Oct 11 22:32:39 volumio volumio[1246]: info: [CDPlayer]: [tray-watcher] decision for /dev/sr0: action=change media= ready= ejectReq=0 mediaPresent=null pendingEject=true noDisc=true Oct 11 22:32:39 volumio volumio[1246]: info: [CDPlayer]: Eject detected ... Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioGetState Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:39 volumio volumio[1246]: info: [CDPlayer]: Stopping CD playback due to eject event Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioStop Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::stop Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::stPlaybackTimer Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::updateTrackBlock Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::getTrackBlock Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::serviceStop Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::serviceStop Oct 11 22:32:39 volumio volumio[1246]: info: ControllerMpd::stop Oct 11 22:32:39 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand stop Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioGetQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::getQueue Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::getQueue Oct 11 22:32:39 volumio volumio[1246]: info: [CDPlayer]: Removing CDPlayer from Browse Sources Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesCDPlayer Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 11 22:32:39 volumio volumio[1246]: info: [CDPlayer]: Adding CDPlayer to Browse Sources Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 11 22:32:39 volumio volumio[1246]: info: [1791732759544] CoreMusicLibrary::Adding element CDPlayer Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 11 22:32:39 volumio volumio[1246]: Cannot find translation for source CDPlayer Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioRemoveQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::removeQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::removeQueueItem undefined Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::saveQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioRemoveQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::removeQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::removeQueueItem undefined Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::saveQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioRemoveQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::removeQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::removeQueueItem undefined Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::saveQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioRemoveQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::removeQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::removeQueueItem undefined Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::saveQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioRemoveQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::removeQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::removeQueueItem undefined Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::saveQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioRemoveQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::removeQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::removeQueueItem undefined Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::saveQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioRemoveQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::removeQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::removeQueueItem undefined Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::saveQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioRemoveQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::removeQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::removeQueueItem undefined Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::saveQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioRemoveQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::removeQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::removeQueueItem undefined Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::saveQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioRemoveQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::removeQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::removeQueueItem undefined Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::saveQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioRemoveQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::removeQueueItem Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::removeQueueItem undefined Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::saveQueue Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushQueue Oct 11 22:32:39 volumio volumio[1246]: info: Oct 11 22:32:39 volumio volumio[1246]: ---------------------------- MPD announces state update: player Oct 11 22:32:39 volumio volumio[1246]: info: sendMpdCommand stop took 139 milliseconds Oct 11 22:32:39 volumio volumio[1246]: info: ControllerMpd::getState Oct 11 22:32:39 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand status Oct 11 22:32:39 volumio volumio[1246]: info: Oct 11 22:32:39 volumio volumio[1246]: ---------------------------- MPD announces state update: player Oct 11 22:32:39 volumio volumio[1246]: info: ControllerMpd::getState Oct 11 22:32:39 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand status Oct 11 22:32:39 volumio volumio[1246]: info: [CDPlayer]: [tray-watcher] handling change on /dev/sr0 Oct 11 22:32:39 volumio volumio[1246]: info: sendMpdCommand status took 19 milliseconds Oct 11 22:32:39 volumio volumio[1246]: info: sendMpdCommand status took 18 milliseconds Oct 11 22:32:39 volumio volumio[1246]: verbose: ControllerMpd::parseState Oct 11 22:32:39 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 11 22:32:39 volumio volumio[1246]: verbose: ControllerMpd::parseState Oct 11 22:32:39 volumio volumio[1246]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 11 22:32:39 volumio volumio[1246]: info: sendMpdCommand playlistinfo took 1 milliseconds Oct 11 22:32:39 volumio volumio[1246]: info: sendMpdCommand playlistinfo took 1 milliseconds Oct 11 22:32:39 volumio volumio[1246]: verbose: ControllerMpd::parseTrackInfo Oct 11 22:32:39 volumio volumio[1246]: verbose: ControllerMpd::parseTrackInfo Oct 11 22:32:39 volumio volumio[1246]: info: ControllerMpd::pushState Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::servicePushState Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:39 volumio volumio[1246]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"1?disc=1791730273222","artist":null,"album":null,"uri":"http://127.0.0.1:8088/wav/track/1?disc=1791730273222","trackType":""} Oct 11 22:32:39 volumio volumio[1246]: verbose: CURRENT POSITION 0 Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::syncState stateService stop Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::syncState currentStatus stop Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:39 volumio volumio[1246]: info: No code Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:39 volumio volumio[1246]: info: ControllerMpd::pushState Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::servicePushState Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:39 volumio volumio[1246]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"1?disc=1791730273222","artist":null,"album":null,"uri":"http://127.0.0.1:8088/wav/track/1?disc=1791730273222","trackType":""} Oct 11 22:32:39 volumio volumio[1246]: verbose: CURRENT POSITION 0 Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::syncState stateService stop Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::syncState currentStatus stop Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:39 volumio volumio[1246]: info: No code Oct 11 22:32:39 volumio volumio[1246]: info: CoreStateMachine::pushState Oct 11 22:32:39 volumio volumio[1246]: info: CorePlayQueue::getTrack 0 Oct 11 22:32:39 volumio volumio[1246]: info: CoreCommandRouter::volumioPushState Oct 11 22:32:39 volumio volumio[1246]: info: ------------------------------ 62ms Oct 11 22:32:39 volumio volumio[1246]: info: ------------------------------ 61ms Oct 11 22:32:39 volumio volumio[1246]: info: [CDPlayer]: [tray-watcher] decision for /dev/sr0: action=change media= ready=0 ejectReq=1 mediaPresent=null pendingEject=true noDisc=true Oct 11 22:32:39 volumio volumio[1246]: info: [CDPlayer]: [tray-watcher] handling change on /dev/sr0 Oct 11 22:32:39 volumio volumio[1246]: info: [CDPlayer]: [tray-watcher] decision for /dev/sr0: action=change media= ready=0 ejectReq=0 mediaPresent=null pendingEject=false noDisc=false Oct 11 22:32:42 volumio volumio[1246]: info: [CDPlayer]: CD metadata fetch attempt #3... Oct 11 22:32:42 volumio volumio[1246]: info: [CDPlayer]: [tray-watcher] handling change on /dev/sr0 Oct 11 22:32:42 volumio volumio[1246]: info: [CDPlayer]: [tray-watcher] decision for /dev/sr0: action=change media= ready=0 ejectReq=0 mediaPresent=null pendingEject=false noDisc=false Oct 11 22:32:46 volumio volumio[1246]: info: Preload queue cleared Oct 11 22:32:46 volumio volumio[1246]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 11 22:32:46 volumio volumio[1246]: info: CoreStateMachine::ClearQueue Oct 11 22:32:46 volumio volumio[1246]: info: CoreStateMachine::stop Oct 11 22:32:46 volumio volumio[1246]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 11 22:32:46 volumio volumio[1246]: info: CorePlayQueue::clearPlayQueue Oct 11 22:32:46 volumio volumio[1246]: info: CorePlayQueue::saveQueue Oct 11 22:32:46 volumio volumio[1246]: info: CoreCommandRouter::volumioPushQueue Oct 11 22:32:46 volumio volumio[1246]: info: CoreStateMachine::addQueueItems Oct 11 22:32:46 volumio volumio[1246]: info: CorePlayQueue::addQueueItems Oct 11 22:32:46 volumio volumio[1246]: info: Preload queue cleared Oct 11 22:32:46 volumio volumio[1246]: info: Adding Item to queue: cdplayer/1?disc=1791731895998 Oct 11 22:32:46 volumio volumio[1246]: info: Exploding uri cdplayer/1?disc=1791731895998 in service cdplayer Oct 11 22:32:46 volumio volumio[1246]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 11 22:32:46 volumio volumio[1246]: TypeError: Cannot read properties of null (reading '0') Oct 11 22:32:46 volumio volumio[1246]: at cdplayer.explodeUri (/data/plugins/music_service/cdplayer/index.js:355:21) Oct 11 22:32:46 volumio volumio[1246]: at CoreCommandRouter.explodeUriFromService (/volumio/app/index.js:1384:16) Oct 11 22:32:46 volumio volumio[1246]: at CorePlayQueue.explodeUriFromCache (/volumio/app/playqueue.js:123:24) Oct 11 22:32:46 volumio volumio[1246]: at CorePlayQueue.explodeUri (/volumio/app/playqueue.js:181:19) Oct 11 22:32:46 volumio volumio[1246]: at CorePlayQueue.addQueueItems (/volumio/app/playqueue.js:223:30) Oct 11 22:32:46 volumio volumio[1246]: at CoreStateMachine.addQueueItems (/volumio/app/statemachine.js:251:25) Oct 11 22:32:46 volumio volumio[1246]: at CoreCommandRouter.replaceAndPlay (/volumio/app/index.js:511:25) Oct 11 22:32:46 volumio volumio[1246]: at CoreCommandRouter.playItemsList (/volumio/app/index.js:484:17) Oct 11 22:32:46 volumio volumio[1246]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:142:33) Oct 11 22:32:46 volumio volumio[1246]: at Socket.emit (node:events:514:28) Oct 11 22:32:46 volumio volumio[1246]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Oct 11 22:32:46 volumio volumio[1246]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Oct 11 22:32:46 volumio volumio[1246]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 11 22:32:47 volumio sudo[3313]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-11 22:31' Oct 11 22:32:47 volumio sudo[3313]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"