Sources Update / Rescan fails after a few hundred tracks

Bigguy2018 · November 10, 2023, 11:24am

Just built another system with RPi5 + DAC with latest Volumio 3.569.

Library on USB 3 attached 2,5" 1TB HDD.
Update / Rescan fails after a few hundred tracks and then shows an empty library.

Same system running RasPiOS Bookworm works fine, sees entire drive, plays all tracks etc.

Any suggestions how to get Volumio to scan entire HDD ?

Version of Volumio: 3.569
Hostname: volumio-rpi5
Kernel: 6.1.58-v8+
Governor: conservative
Uptime: 0 days, 0 Hrs, 15 Minutes, 56 Seconds

Audio info
Hw audio configured: HiFiBerry DAC2 HD
Mixer type: Hardware
Number of channels: 2
Supported sample rate: 44100 48000 88200 96000 176400 192000

Board info
Manufacturer: Raspberry Pi Foundation
Model: Raspberry Pi 5 Model B Rev 1.0
Version: c04170
Firmware Version: 2023/10/18 18:30:17 Copyright (c) - (embedded)

CPU info
Brand: undefined
Speed: 2.4Ghz
Number of cores: 4
Physical cores: 4
Average load: 7%
Temperature: 46°C

Memory info
Memory: 4089012 Ko
Free: 1208100 Ko
Used: 2880912 Ko

Storage info
INTERNAL storage - Size: 56409Mo
Used: 19Mo
Available for storage: 53476Mo (95%)

Filesystem Size Used Avail Use% Mounted on
/dev/mmcblk0p2 2.5G 535M 1.8G 24% /imgpart
/dev/loop0 470M 470M 0 100% /static
overlay 56G 19M 53G 1% / *** LOTS OF ROOM
devtmpfs 2.0G 0 2.0G 0% /dev
tmpfs 2.0G 0 2.0G 0% /dev/shm
tmpfs 2.0G 5.3M 2.0G 1% /run
tmpfs 5.0M 4.0K 5.0M 1% /run/lock
tmpfs 2.0G 0 2.0G 0% /sys/fs/cgroup
tmpfs 2.0G 36K 2.0G 1% /tmp
tmpfs 2.0G 0 2.0G 0% /var/spool/cups
tmpfs 20M 396K 20M 2% /var/log
tmpfs 2.0G 0 2.0G 0% /var/spool/cups/tmp
/dev/mmcblk0p1 92M 65M 27M 72% /boot
tmpfs 400M 0 400M 0% /run/user/1000
/dev/sda1 932G 756G 176G 82% /media/1TB

Bigguy2018 · November 10, 2023, 11:36am

OK, further investigations suggests the USB interface is crashing ?

Using a USB diagnostic tester inline shows normal HHD activity (max 520mA) and then drive stops and shows 180mA.

USB ports are good for 1.6A total with Official 27W PSU ?

This is a Volumio issue as the exact same hardware works AOK in RaspiOS

gkkpch · November 10, 2023, 12:34pm

In these cases it is better to submit a logfile than just observations, that will show information devs can work with.

Bigguy2018 · November 11, 2023, 4:25pm

Starting Live Log...
info: [MyVolumio PluginManager] Streaming Services plugin successfully started
 volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
error: Cannot start Volumio Streaming Daemon
error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
STREAMING PROXY: Starting server on port 3245
Node JS runtime: 14
error: MyVolumio Custom Token format not valid, refreshing it
info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=3.569&uuid=8d8eff4c7e45b8f2b76fa198a3c70c7f" http://updates.volumio.org/downloader-v1/track-device
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed

  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0curl: (6) Could not resolve host: updates.volumio.org
 retrying in 5 seconds, trial 0
info: Volumio Calling Home
info: Volumio called home
info: MyVolumio login type: Token
info: MYVOLUMIO SUCCESSFULLY LOGGED IN
.....................................................++++
info: MyVolumio token set successfully
info: MYVOLUMIO: Adding device
info: MYVOLUMIO: Evaluating Server
info: MyVolumio status changed
info: Streaming services startup
info: Starting Streaming Daemon
info: Removing browser output: myVolumio user plan is not superstar
info: Removing audio output:
info: Stoppping Tunnel 1
 volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
error: Cannot start Volumio Streaming Daemon
error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
 volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
info: Remote SSH Stopped
info: Setting Geolocation for MyVolumio to eu2
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
info: Updating MyVolumio device info
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
...................................++++
e is 65537 (0x010001)
writing RSA key
error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
info: MYVOLUMIO: Adding device
info: MYVOLUMIO: Evaluating Server
info: Setting Geolocation for MyVolumio to eu5
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
 volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
 volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root

error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
 volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root
 volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
pam_unix(sudo:session): session opened for user root by (uid=0)
pam_unix(sudo:session): session closed for user root

info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
info: CoreCommandRouter::volumioGetVisibleSources
info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback
info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
info: Received Get System Info
info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
info: Discovery: Getting this device information
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: Listing playlists
info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache
info: Updating MyVolumio device info
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
info: Received Get System Info
info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
info: Discovery: Getting this device information
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
info: Received Get System Info
info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
info: Discovery: Getting this device information
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
systemd-fsckd.service: Succeeded.
info: CoreCommandRouter::getUIConfigOnPlugin
info: CoreCommandRouter::getUIConfigOnPlugin
info: Retrieving Cloud Streaming UI
info: Getting Tidal Cloud Configuration
info: CoreCommandRouter::getUIConfigOnPlugin
info: Getting Qobuz Cloud Configuration
info: Asking plugin for UI Config
info: CoreCommandRouter::getUIConfigOnPlugin
info: Getting Spotify Cloud Configuration
info: Asking plugin for UI Config
info: CoreCommandRouter::getUIConfigOnPlugin
info: Saving Spotify Acccount
info: Got Tidal Cloud Configuration
info: Got it
info: Got it
error: Could not retrieve Spotify Config from plugin Spotify: no section found
info: CoreCommandRouter::getUIConfigOnPlugin
error: Error retrieving Highresaudio conf: TypeError: Cannot read property 'onSave' of undefined
info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus
info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam
info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam
info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam
info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
info: CoreCommandRouter::volumioGetBrowseSources
info: CoreCommandRouter::volumioGetBrowseSources
info: CoreCommandRouter::volumioGetBrowseSources
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: CoreCommandRouter::executeOnPlugin: networkfs , listShares
systemd-hostnamed.service: Succeeded.
info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings

info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::executeOnPlugin: mpd , updateDb


info:
---------------------------- MPD announces state update: update
info: sendMpdCommand update took 2 milliseconds
info: ControllerMpd::getState

info: sendMpdCommand status took 2 milliseconds
info: sendMpdCommand status took 1 milliseconds

info: Command Router : Notfying DB Updatetrue

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CorePlayQueue::getTrack 0


info: CoreStateMachine::syncState   stateService stop
info: CoreStateMachine::syncState   currentStatus stop
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: No code
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: ------------------------------ 51ms
info: CoreCommandRouter::Close All Modals sent
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam
info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam
info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject
info: CoreCommandRouter::volumioGetBrowseSources
info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
error: MyVolumio Plugin failed to authenticate in a timely fashion
info: Completed starting MyVolumio Plugin
info: BOOT COMPLETED
e[34m [Metrics] e[39m CommandRouter: e[31m 32s 3.63ms e[39m
info: CoreCommandRouter::volumiosetStartupVolume
info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
info: CoreCommandRouter::Close All Modals sent
info: CoreCommandRouter::Close All Modals sent
info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
No test mode
No alpha test mode
info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false}
info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache
info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable
info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined
info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates
info: Received Get System Version
info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
Soliciting pool server 178.62.250.107
Soliciting pool server 85.199.214.101
Soliciting pool server 188.114.116.1
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
Soliciting pool server 131.111.8.61
Soliciting pool server 51.89.151.183
Soliciting pool server 88.80.189.24
Soliciting pool server 95.215.175.2
Soliciting pool server 81.128.218.110
Soliciting pool server 195.171.43.10
Soliciting pool server 217.114.59.3
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
Soliciting pool server 162.159.200.123
Soliciting pool server 176.58.109.199
Soliciting pool server 139.143.5.31
Soliciting pool server 82.30.218.44
Soliciting pool server 2001:418:3ff::53
receive: Unexpected origin timestamp 0xe8f8dd2f.08aab3f8 does not match aorg 0000000000.00000000 from server@81.128.218.110 xmt 0xe8fa28a0.f5b76615
receive: Unexpected origin timestamp 0xe8f8dd2f.08aca013 does not match aorg 0000000000.00000000 from server@131.111.8.61 xmt 0xe8fa28a0.f5e519cc
Starting Daily apt download activities...
apt-daily.service: Succeeded.
Started Daily apt download activities.
Starting Daily apt upgrade and clean activities...
apt-daily-upgrade.service: Succeeded.
Started Daily apt upgrade and clean activities.
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: Discovery: A device disappeared from network
info: Discovery: Device rpi5 disappeared from network
info: Discovery: A device disappeared from network
info: Discovery: A device disappeared from network
info: Discovery: adding e553ff97-5166-40ae-aa68-4d1a217617b4
info: Discovery: Found device RPi5
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: Discovery: this is already registered,  e553ff97-5166-40ae-aa68-4d1a217617b4
info: Discovery: Found device RPi5
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: Discovery: adding 3e216f12-ed23-4f0f-87ac-92578888bd1e
info: Discovery: Found device Volumio OSA DAC
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
mpd.service: Main process exited, code=killed, status=7/BUS
mpd.service: Failed with result 'signal'.
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri
info: CURURI: artists://
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0

gkkpch · November 11, 2023, 7:10pm

sorry, not a live link, please read the guide above

Bigguy2018 · November 14, 2023, 1:58pm

http://logs.volumio.org/volumio/vgKxfRJ.html

Bigguy2018 · November 14, 2023, 2:04pm

After failed Rescan

http://logs.volumio.org/volumio/PiCSNb1.html

scanboostar · November 15, 2023, 6:31pm

I have a similar problem on a fresh install on 128GB Sandisk micro SD card on a 4GB Raspberry PI5
http://logs.volumio.org/volumio/mOFlswW.html

info: CoreCommandRouter::executeOnPlugin: mpd , rescanDb


info:
---------------------------- MPD announces state update: update
info: sendMpdCommand rescan took 2 milliseconds
info: ControllerMpd::getState

info: sendMpdCommand status took 7 milliseconds
info: sendMpdCommand status took 6 milliseconds

info: Command Router : Notfying DB Updatetrue

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CorePlayQueue::getTrack 0


info: CoreStateMachine::syncState   stateService stop
info: CoreStateMachine::syncState   currentStatus stop
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: No code
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: ------------------------------ 61ms
info: CoreCommandRouter::Close All Modals sent
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
mpd.service: Main process exited, code=killed, status=7/BUS
mpd.service: Failed with result 'signal'.
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}

scanboostar · November 17, 2023, 11:31am

I did a firmware upgrade of the Raspberry PI5 with Raspberry PI Desktop (Debian Bookwurm) and then tried a fresh Volumio image. The result was the same.

Darmur · November 17, 2023, 12:20pm

what power supply are you using with the RPi5?

if you don’t use the official one with 5V/5A, the current from the USB ports will be limited to 0.6A, too low for powering properly a USB HDD

Bigguy2018 · November 17, 2023, 1:01pm

I’m using the ‘official’ USB C supply.

Further investigation shows: when Rescan fails I can still access the USB drive via Samba from my Win PC, so disk is still mounted and functional.
Disc disappears in Volumio only.

scanboostar · November 17, 2023, 2:07pm

Me too I use the Official 27W USB-C EU Power Supply For Easpberry Pi [5].
By the way, It delivers 5.1v, 5.0A DC; 9.0V, 3.0A DC; 12.0V 2.25A DC; 15.0V, 1.8A DC
I Only Have HDMI connected, the Power Supply and a LAN Cable (CAT6a) connected to a 1Gbps switch.

scanboostar · November 17, 2023, 2:09pm

My CIFS mount does not disappear, it is constantly there. I can see that while logging on to the Pi using SSH and checking /mnt/NAS/DS.

MPD bails out:

Nov 14 19:31:41 volumio5 systemd[1]: mpd.service: Main process exited, code=killed, status=7/BUS
Nov 14 19:31:41 volumio5 systemd[1]: mpd.service: Failed with result ‘signal’.

Darmur · November 17, 2023, 2:46pm

I’ve discussed about this issue internally.

Unfortunately, it looks like MPD hangs during the database update if there are corrupted files.

In the coming releases we can finally try to update MPD to a newer version, hopefully it will be more robust in handling corrupted files.

scanboostar · November 17, 2023, 5:53pm

With Volumio 3.546 on a Raspberry PI3 using the same Network Drive and account I don’t have any issues with MPD.

Darmur · November 17, 2023, 6:23pm

OK, thanks for reporting that, we must investigate further

scanboostar · November 18, 2023, 9:49am

I installed the same “Volumio-3.569-2023-10-20-pi” image in a 32MB micro SD card for a Raspberry PI3.
The music library updated correctly and mpd did not crash.

However I noticed in the MPD log on the PI3 some ‘errors’ around the point that the PI5 MPD Crashes:
Nov 18 09:58 : mad: mp3 file header indicates too many frames: 100934231
Nov 18 09:58 : ffmpeg/mp3: Estimating duration from bitrate, this may be inaccurate
Nov 18 09:58 : update: added NAS/DS/Xtra - SoulShow/jingles.zip/jingles/01 FERRY MAAT, TE GEK.MP3

I removed these file and tried again after a factory reset. The update is still failing at the same spot every time I try.

scanboostar · November 21, 2023, 6:07pm

http://logs.volumio.org/volumio/E48cNns.html

keko123 · January 15, 2024, 11:45pm

Hello,

same issue here.

i use Pi 5 + 27w oficial PSU + Volumio 3.569

I have used two hard drives. External NVME WD and external HDD 2.5

I have also reinstalled Volumio many times. Any ideas?

Starting Live Log...
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::executeOnPlugin: system , getHwuuid
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: CoreCommandRouter::executeOnPlugin: mpd , rescanDb


info:
---------------------------- MPD announces state update: update
info: sendMpdCommand rescan took 4 milliseconds
info: ControllerMpd::getState

info: sendMpdCommand status took 2 milliseconds
info: sendMpdCommand status took 1 milliseconds

info: Command Router : Notfying DB Updatetrue

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CorePlayQueue::getTrack 0


info: CoreStateMachine::syncState   stateService stop
info: CoreStateMachine::syncState   currentStatus stop
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: No code
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: ------------------------------ 61ms
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: CoreCommandRouter::Close All Modals sent
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
mpd.service: Main process exited, code=killed, status=7/BUS
mpd.service: Failed with result 'signal'.
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
error: MPD error: Error: This socket has been ended by the other party
error: This socket has been ended by the other party {"code":"EPIPE"}

madx1701 · January 21, 2024, 2:07pm

I have noticed the same or similar behaviour.
I noticed that when scanning large amount of mp3 files, at some point the folder /var/log inside of volumio runs full.
This folder is a ramdisk and 20 MB in siize.
In my case at some point /var/log runs 100% full, as there is a log entry added for each scanned file into /var/log/mpd.log.

When /var/log is 100% it seems that the volumio is no longer able to operate correctly.

My current workaround is to run a custom script which monitors /var/log and in case of 80% or more the script truncates the mpd.log (echo >/var/log/mpd.log) to zero to free up the space.

I am not sure if this really fixes my issue, and i dont know if your issue is different.

Maybe you can check if /var/log is also 100% full in your case. if it is not, your issue must be a different one.