Sources Update / Rescan fails after a few hundred tracks

Help and Support
21

During a source scan the mpd.log file grows to 700186 then no more - mpd then crashes (?) and mpd.log returns to size 186.

volumio@volumio:/var/log$ ls -al /var/log
total 708
drwxr-xr-x 4 volumio adm 200 Jan 28 13:18 .
drwxr-xr-x 1 root root 4096 Oct 20 14:34 …
-rw-r–r-- 1 volumio volumio 0 Jan 27 21:12 albumart.log
-rw------- 1 root root 5480 Jan 27 21:12 boot.log
-rw-rw---- 1 root utmp 0 Jan 27 21:12 btmp
-rw-rw-r-- 1 root utmp 292292 Jan 28 12:59 lastlog
-rw-r–r-- 1 root root 700186 Jan 28 13:17 mpd.log
drwx------ 2 root root 40 Jan 27 21:12 private
drwxr-xr-x 3 root root 180 Jan 27 21:12 samba
-rw-rw-r-- 1 root utmp 2688 Jan 28 12:59 wtmp

22

@Bigguy2018 can you provide a log?

23 
Starting Live Log...
info: Listing playlists
info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard
info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
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
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: 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: mpd , updateDb


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


info:
---------------------------- MPD announces state update: update
info: ControllerMpd::getState


info:
---------------------------- MPD announces state update: update
info: ControllerMpd::getState

info: sendMpdCommand status took 6 milliseconds
info: sendMpdCommand status took 4 milliseconds
info: sendMpdCommand status took 4 milliseconds
info: sendMpdCommand status took 3 milliseconds
info: sendMpdCommand status took 3 milliseconds
info: sendMpdCommand status took 2 milliseconds

info: Command Router : Notfying DB Updatetrue


info: Command Router : Notfying DB Updatetrue
info: CoreCommandRouter::Close All Modals sent


info: Command Router : Notfying DB Updatetrue
info: CoreCommandRouter::Close All Modals sent

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: 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::volumioPushState
info: No code
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
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::volumioPushState
info: No code
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: ------------------------------ 81ms
info: ------------------------------ 79ms
info: ------------------------------ 78ms
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
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::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::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::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::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"}

Modified to keep it readable. (Wheaten)

24

8d8eff4c7e45b8f2b76fa198a3c70c7f

25

Please follow the instructions here:

And paste the link here. Thanks

26

@madx1701 thanks for the pointer. this is a direction we are investigating. Are you able to test your assumption?

27

Hello @volumio

while my workaround prevented that /var/log runs full, it did not fix the issue.
The script empties the /var/log/mpd.log whenever it is at risk to get too big.
I now did a full rescan of the library, and it never finishes.
What i notice:

  1. When i try to browse the music library, the “rescan is going on” animation persistently is there in the upper corner.
  2. The “My Music” satistics in “Sources” have no lines after the scan gets stuck.
  3. the last visible line in “mpd.log” shows : “client: error on client 4: Output buffer is full”

After a reboot only the library is usable. But i did not yet have time to check if the library DB then contains all files or not. So maybe the scan is incomplete (as it got stuck before).

Maybe on weekend i can check if i find some way to re-direct the /var/log to some local location or to increase the ram disk size to 1 or 2 GB. Then i can re-produce the issue without space limits on the log and could do some full rebuilds of the DB, checking if it always gets stuck after the same amount of files.

For reference, my workaround solution is:

  1. Script “/root/script/volumio.clean-logs-loop.bash”
    The script adds itself to /etc/rc.local if not found there already, so that it launches with each boot, and installs the screen utitlity if it is not installed. The loop to monitor and clean up /var/log/ is fired into a screen session, where it then runs in an infinite loop and then empties the largest file which it finds if it is above 70%.
#!/bin/bash

PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin

SCRIPT_DIR="$( cd -- "$( dirname -- "${BASH_SOURCE[0]}" )" &> /dev/null && pwd )"
SCRIPT_NAME="$(basename $0)"

ls -1 /usr/bin/screen 2>/dev/null >/dev/null || (
  apt-get -y update >/dev/null 2>/dev/null
  apt-get -y install screen >/dev/null 2>/dev/null
)

grep -q "^${SCRIPT_DIR}/${SCRIPT_NAME} " /etc/rc.local || sed -i "/^exit 0$/i ${SCRIPT_DIR}/${SCRIPT_NAME} 2>\/dev\/null 2>\/dev\/null" /etc/rc.local

/usr/bin/screen -list | grep -q "${SCRIPT_NAME}" || (
  /usr/bin/screen -S ${SCRIPT_NAME} -dm /bin/bash -c 'while sleep 15 ; do df /var/log --output=pcent | tail -1 | tr -d " " | grep -Eq "^100%$|^9.%$|^8.%$|7.%" && ( > $(ls -1rS $(find /var/log -type f 2>/dev/null | grep -Ev "\.xz$|\.gz$") | tail -1) ) ; done'
)
exit 0
28

Thanks @madx1701 . Actually we had a provision in place to clear the /var/log folder in case it got too big, but for some reason that was never ported to V3. This did not represent an issue until we migrated to this mpd versio, which seems to be more verbose than previous ones in logs.

Now we reinstated the log rotation service, see here:

However I think this mpd crash is due to something else. But we can’t replicate with our libraries, so your help in understanding why it happens is very important and appreciated :wink:

29

I will try to figure out. It is also in my own interest, as the issue is quite annoying, and for x86 there is nearly no alternative to volumio, except maybe daphile, which is however less comfortable to handle…

I blew up the /var/log ramdisk now to 1GB (system has 4GB , so it should be fine).

Q1: Is there any way to increase the log verbosity of the scan? Some debug log level which can be enabled? 1GB should be able to store any kind of log data… so maybe with higher log level i can grep for something meaningful.
Q2: Is there any specific process visible during the scan, which should disappear after the scan is complete? I could check if the process is still there when the scan gets stuck…

Current results:
If i remove from the current log the file name related lines, i get the events below in the log, but it seems mpd is able to handle them, so they should not cause the issue…

# grep -iEv "update: updating|update: added|update: removing" mpd.log | grep -v "^Feb 01" | sort -u
Consider increasing the value for the 'analyzeduration' and 'probesize' options
Note: Hit end of (available) data during resync.
Note: Illegal Audio-MPEG-Header 0x00000000 at offset 2044.
Note: Illegal Audio-MPEG-Header 0x00000000 at offset 2248.
Note: Trying to resync...
[src/libmpg123/parse.c:1185] error: Giving up searching valid MPEG header after 65536 bytes of junk.

# grep -iEv "update: updating|update: added|update: removing" mpd.log |grep "^Feb 01" | cut -c 16- | sort -u
audiofile: unrecognized audio file format
client: error on client 4: Output buffer is full
exception: No such directory
ffmpeg/mov,mp4,m4a,3gp,3g2,mj2: stream 0, timescale not set
ffmpeg/mp3: Could not find codec parameters for stream 0 (Audio: mp3 (mp3float), 0 channels, fltp): unspecified frame size
ffmpeg/mp3: Failed to read frame size: Could not seek to 1560.
ffmpeg/mp3: Failed to read frame size: Could not seek to 8239.
ffmpeg/mp3: Format mp3 detected only with low score of 1, misdetection possible!
ffmpeg/mp3: Format mp3 detected only with low score of 24, misdetection possible!
mixer: Failed to read mixer for 'alsa': no such mixer control: PCM
mpg123: mpg123_getformat() failed: Message: I am done with this track.
zeroconf: No global port, disabling zeroconf
30

Hi @madx1701 there are a coupe of things that you can do:

  1. Enable more verbose logging, however from my experience when MPD crashes (like in this case) the log won’t tell much… You can enable verbose logging by creating a file named /data/alsadebug
touch /data/alsadebug

Then reboot the system

  1. And this is probably the best way. Is to install the debug version of MPD. We have one already compiled for arm here

MPD 0.23.5 DEBUG

If you need it for x64, unfortunately you have to compile it, follow the instructions here:

https://mpd.readthedocs.io/en/stable/user.html#crash

Thanks for any effort you’re able to put in and for the hints that you might give us…

31

For now i will go with the aladebug only, as the mpd update fails due to dependency issues on my rpi which i updated to the latest volumio version over web interface… 3.611

Does the normal volumio integrated update not update the mpd as well?

-bash-5.0# dpkg -i mpd-dbgsym_0.23.5-1_armhf.deb
(Reading database … 36297 files and directories currently installed.)
Preparing to unpack mpd-dbgsym_0.23.5-1_armhf.deb …
Unpacking mpd-dbgsym (0.23.5-1) over (0.23.5-1) …
dpkg: dependency problems prevent configuration of mpd-dbgsym:
mpd-dbgsym depends on mpd (= 0.23.5-1); however:
Version of mpd on system is 0.21.18.

dpkg: error processing package mpd-dbgsym (–install):
dependency problems - leaving unconfigured
Errors were encountered while processing:
mpd-dbgsym

32

@madx1701 happy to join forces here.
I found this thread, as I’m experiencing an issue with the rescan as well.
According to, to journalctl, by the external 7/BUS signal

Feb 04 17:46:10 volumiio systemd[1]: mpd.service: Main process exited, code=killed, status=7/BUS
Feb 04 17:46:10 volumiio systemd[1]: mpd.service: Failed with result 'signal'.

Now, compiling the package shared above got me the same error as you’ve got (version conflict).
However, I found this article explaining how to compile a package by yourself:

So far, I have followed the steps to get mpd to the latest release available, 0.23.15
Using the argument --buildtype=debugoptimized when building.

Yet, running (from here)
gdb --args mpd --stderr --no-daemon --verbose
run
… reproduce bug …
bt

game me nothing. I’ll try to compile it again, following the arguments --buildtype=debug -Db_ndebug=false

Maybe with my steps will help you to get to the result sooner

33

that’s weird, mpd 0.23.5-1 should be already in place on v3.611

what is the response to the following command?

mpd --version

35

Just to give you a faster response, for me initially indeed 0.23.5-1.
However, the debug package somehow starts saying that 0.21.18 is installed

Even now I’ve got

volumio@volumiio:~$ mpd --version
Music Player Daemon 0.23.15 (0.23.15)
Copyright 2003-2007 Warren Dukes <warren.dukes@gmail.com>
Copyright 2008-2021 Max Kellermann <max.kellermann@gmail.com>
This is free software; see the source for copying conditions.  There is NO
warranty; not even MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

Bug installed the debug package provided throws the same error.

I presume it’s due to 0.21.18 being the latest available on apt:

apt list -a mpd
Listing... Done
mpd/now 0.21.18 armhf [installed,local]
mpd/oldoldstable 0.21.5-3 armhf

upd
While I was on the way to debug my issue, I apparently fix it.

So as soon as I not only compiled and installed the newest version 0.23.15 but also updated MPD.service and systemctl to the new location (it uses usr/local/bin instead of usr/bin as the included one), it just worked.
It scanned through the whole media storage connected via USB for the first time ever.
And didn’t throw a single error to test the debug.

My assumption (and I’m not an expert by any mean) is the following:

  1. Volumio may ship with v 0.23.5-1
  2. The latest available via apt is 0.21.X
  3. When “pro” users update packages somehow, a downgrade occurs
    The old version has got some issues with scanning catalogs of certain types.

But it’s subjective.

36

Build from this instructions does not have Volumio specific parameters, discards upstream pipe rework and fails socket init, brings dependency on non-ported newer libraries and dependencies. I trust you took appropriate steps.
Every reset or upgrade will discard custom packages and will revert to the Volumio shipped.
The mpd-0.23.15 is being evaluated for production use across all Volumio ports, no ETA as yet.

37

The most honest answer will be no. And I appreciate that you are raising it.
As the original goal was to debug MPD’s scan function and see why it fails, I had to take the risk of it being incompatible with the Volumio.

Yet, it does to work for the time being for me. Not just in terms of scanning but in terms of playback too.
Maybe it’s due to the fact I use Volumio’s mpd.config file, maybe it’s a blind luck.

I do indeed acknowledge that it will most certainly not support further Volumio updates.

However, I’m not sure at the moment that I’d instead build an older debug package to continue the investigation. Maybe unless I’m asked to.

38

Can you verify this by doing a factory reset and see if you still have this error?
Thanks a lot

39

After having internal discussion please download testing packages for:

mpc - https://github.com/foonerd/volumio3-mpc/tree/main/packages/static
liburing1/mpd - https://github.com/foonerd/volumio3-mpd/tree/main/packages/static

The liburing1 is prerequisite for newer mpd versions.

40

Just a quick update from running in alsadbug mode:

If i remove all " update " lines about the filenames which were scanned, the last lines in the log look like this in my case.

As it seems the scan has completed and at the end the DB is written as last step. However, the volumio web interface reports still the rotating scan animation in the upper left corner, and i cannot browse the library at all. Also the library statistics are not showing in the sources menu.

If i run “killall node” and let volumio reload, the statistics are showing up.

Next i will try to add the custom mpd packages.

-bash-5.0# tail -2000 mpd.log | grep -v " : update: " | tail -40
Feb 04 22:50 : mad: LAME peak found: 0
Feb 04 22:50 : mad: encoder delay is 576, encoder padding is 864
Feb 04 22:50 : mad: detected LAME version 3.99 ("LAME3.99r")
Feb 04 22:50 : mad: LAME peak found: 0
Feb 04 22:50 : mad: encoder delay is 576, encoder padding is 576
Feb 04 22:50 : simple_db: removing empty directories from DB
Feb 04 22:50 : simple_db: sorting DB
Feb 04 22:50 : simple_db: writing DB
Feb 04 22:50 : client: [2] process command "count "group" "artist""
Feb 04 22:50 : client: [2] command returned 0
Feb 04 22:50 : client: [2] process command "idle"
Feb 04 22:50 : client: [2] command returned 1
Feb 04 22:50 : client: [2] process command "search album """
Feb 04 22:50 : client: [2] command returned 0
Feb 04 22:50 : client: [2] process command "idle"
Feb 04 22:50 : client: [2] command returned 1
Feb 04 22:50 : client: [2] process command "status"
Feb 04 22:50 : client: [2] command returned 0
Feb 04 22:50 : client: [2] process command "idle"
Feb 04 22:50 : client: [2] command returned 1
Feb 04 22:50 : client: [2] process command "status"
Feb 04 22:50 : client: [2] command returned 0
Feb 04 22:50 : client: [2] process command "idle"
Feb 04 22:50 : client: [2] command returned 1
Feb 04 22:50 : client: [2] process command "status"
Feb 04 22:50 : client: [2] command returned 0
Feb 04 22:50 : client: [2] process command "idle"
Feb 04 22:50 : client: [2] command returned 1
Feb 04 22:50 : client: [2] process command "count "group" "artist""
Feb 04 22:50 : client: [2] command returned 0
Feb 04 22:50 : client: [2] process command "idle"
Feb 04 22:50 : client: [2] command returned 1
Feb 04 22:50 : client: [2] process command "search album """
Feb 04 22:50 : client: error on client 2: Output buffer is full
Feb 04 22:50 : client: [2] command returned 0
Feb 04 22:50 : client: [2] closed
Feb 04 22:50 : client: [1] process command "idle"
Feb 04 22:50 : client: [1] command returned 1
Feb 04 22:50 : client: [0] process command "idle"
Feb 04 22:50 : client: [0] command returned 1
41

Update: Package installation does not succeed on my rpi4.

wget https://github.com/foonerd/volumio3-mpc/blob/main/packages/static/mpc_0.34-2_armhf.deb
wget https://github.com/foonerd/volumio3-mpd/blob/main/packages/static/liburing1_0.7-3~bpo10%2B1_armhf.deb
wget https://github.com/foonerd/volumio3-mpd/blob/main/packages/static/mpd_0.23.14-3_armhf.deb
wget https://github.com/foonerd/volumio3-mpd/blob/main/packages/static/mpd_0.23.15-1_armhf.deb


-bash-5.0# dpkg -i liburing1_0.7-3~bpo10\+1_armhf.deb mpc_0.34-2_armhf.deb mpd_0.23.15-1_armhf.deb
dpkg-deb: error: 'liburing1_0.7-3~bpo10+1_armhf.deb' is not a Debian format archive
dpkg: error processing archive liburing1_0.7-3~bpo10+1_armhf.deb (--install):
 dpkg-deb --control subprocess returned error exit status 2
dpkg-deb: error: 'mpc_0.34-2_armhf.deb' is not a Debian format archive
dpkg: error processing archive mpc_0.34-2_armhf.deb (--install):
 dpkg-deb --control subprocess returned error exit status 2
dpkg-deb: error: 'mpd_0.23.15-1_armhf.deb' is not a Debian format archive
dpkg: error processing archive mpd_0.23.15-1_armhf.deb (--install):
 dpkg-deb --control subprocess returned error exit status 2
Errors were encountered while processing:
 liburing1_0.7-3~bpo10+1_armhf.deb
 mpc_0.34-2_armhf.deb
 mpd_0.23.15-1_armhf.deb