NAS Media Library disappearing when DRC plugin enabled

[ogroot]

I noticed that with recent versions of Volumio, my NAS Music Library disappears as soon as I reboot with DRC plugin enabled.

Tested versions: Volumio 2.703 + DRC 1.4.3.

1. DRC disabled + rebooting Volumio/PI --> NAS is shown in Music Library after reboot
2. DRC enabled + rebooting Volumio/PI --> NAS is NOT shown in Music Library after reboot
3. Reboot Volumio/PI with disabled DRC --> NAS is stays shown in Music Library after enabling/disabling DRC subsequentially

[balbuze]

I think it is because mpd fails to start. Need investigation. You are not using last version of Volumio

[ogroot]

Indeed. I am not using the last version. Because 2.712 + 2.713 have another MDP issue. They update/rescan stops half way. See: https://forum.volumio.org/database-update-stops-after-few-artists-t14069.html

[ogroot]

Error in /var/log/volumio.log : 2020-02-28T19:01:25.163Z - info: CoreCommandRouter::executeOnPlugin: system , getShowWizard 2020-02-28T19:01:26.548Z - info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus 2020-02-28T19:01:26.900Z - info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri 2020-02-28T19:01:26.901Z - info: CURURI: music-library 2020-02-28T19:01:26.902Z - info: message= [50@0] {} No database, stack=Error: [50@0] {} No database at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:63:14) at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:10) at emitOne (events.js:116:13) at Socket.emit (events.js:211:7) at addChunk (_stream_readable.js:263:12) at readableAddChunk (_stream_readable.js:246:13) at Socket.Readable.push (_stream_readable.js:208:10) at Pipe.onread (net.js:607:20)

[balbuze]

can you generate a log from volumio : https://volumio.github.io/docs/User_Manual/Sending_logs_for_troubleshooting.html

[ogroot]

Here you go: http://logs.volumio.org/volumio/0sV2hjJ.html

[balbuze]

can just confirm that with a previous version of the plugin, with the same version of volumio it was working? Does the sound play after reboot?

[ogroot]

Previous version of DRC plugin had the same problem.

I think it worked OK with older Volumio versions (2.587). But with all the latest Volumio versions this is broken.

[balbuze]

the problem is that I have 3 working device (RPI3, RPI4, Thinkerboard) working with last version of volumio and plugin with NAS. It's hard to fix...

[ogroot]

That is strange, because there are quite a few reports about update/rescan issues in the latest 2.712 + 2.713 See: https://forum.volumio.org/database-update-stops-after-few-artists-t14069.html

[ogroot]

I have this myself as well in these versions

[balbuze]

Can you send the content of /etc/mpd.conf when the plugin is enabled?

[ogroot]

mpd.zip

[ogroot]

I just tested Volumio 2.598 + the new DRC 1.4.3.

No Problem with missing NAS after reboot when plugin is enabled!! So the problem should occur with a later version of Volumio. I will try to test some versions tomorrow

[balbuze]

Do you use resampling in Volumio?

[ogroot]

No. I do not

[ogroot]

Ok. Did some further testing.....

Volumio= 2.598 DRC= 1.4.3 --> works OK Volumio= 2.668 DRC= 1.4.3 --> works OK Volumio= 2.692 DRC= 1.4.3 --> works OK Volumio= 2.698 DRC= 1.4.3 --> NOT WORKING

In the last scenario browser UI is stuck/not responding anymore) I see the following error in /var/logvolumio.log:

2020-02-29T10:06:12.313Z - info: Upmpdcli Daemon Started 2020-02-29T10:06:12.326Z - info: Shairport-Sync Started 2020-02-29T10:06:12.328Z - info: Shairport-Sync Started 2020-02-29T10:06:12.345Z - info: Cannot mount NAS archive at system boot, trial number 3 ,retrying in 5 seconds

[balbuze]

thank for your investigation! unfortunately I still don't see what happens!

[balbuze]

what returns "systemctl status mpd" ?

[ogroot]

I will come back to your question later, because I'm still trying to test with some different versions. I see very erratic behaviour with the latest releases (>2.692). Some only work (boot) on RP2 and others on both RP2 + RP4. I will report back later with some conclusions....

[ogroot]

Well it looks like it has something to do with the RPI4, because:

RPI2 + Volumio= 2.699 + DRC= 1.4.3 --> works OK RPI2 + Volumio= 2.703 + DRC= 1.4.3 --> works OK

RPI4 + Volumio= 2.699 + DRC= 1.4.3 --> NOT OK (losing NAS after restart). RPI4 + Volumio= 2.703 + DRC= 1.4.3 --> NOT OK (losing NAS after restart).

BTW: I have an RPI4 updated to the latest EEPROM firmware (reduce heat).

[balbuze]

nice investigation! my rpi4

[balbuze]

what is your firmware now?

[ogroot]

OS info Version of Volumio: 2.699 Hostname: volumio-living Kernel: 4.19.86-v7l+ Governor: performance Uptime: 0 days, 0 Hrs, 4 Minutes, 34 Seconds

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

Board info Manufacturer: Raspberry Pi Foundation Model: BCM2835 - Pi 4 Model B Version: b03111 - Rev. 1.1 Firmware Version: Nov 29 2019 18:44:32 - aabb1fb5c19d80db268aeccd67b9f4e0f3d48a2a

CPU info Brand: Processor rev 3 (v7l) Speed: 1.50Mhz Number of cores: 4 Physical cores: 4 Average load: 6% Temperature: 41°C

Memory info Memory: 2031168 Ko Free: 1425192 Ko Used: 605976 Ko

Storage info INTERNAL storage - Size: 262Mo Used: 192Mo Available: 50Mo (19%)

[balbuze]

so no hw difference. Does the problem occur even with jack as output?

[ogroot]

Yes. The problem occurs also with jack and HDMI outputs (I removed the Allo DigiOne to eliminate this as cause).

[balbuze]

can you try : https://forum.volumio.org/database-update-stops-after-few-artists-t14069-10.html#p72948

[ogroot]

Thanks for the hint, that was strange..... I just "saved" again the playback options page..... and now the NAS has returned !?!?!! :smiley: .

[ogroot]

I do not understand.....how comes it is now working.??? I only saved the "Playback Options" again..... Will test it again tomorrow. Just to make sure that this was it

[balbuze]

Good! Do you use a fresh SD card or a update?

[ogroot]

complete fresh

[ogroot]

Nope. After some further testing it is still not working 'robust' on a RPI4. As soon as I change some setting in the DRC plugin and save the setting, then on the next reboot the NAS is gone. If I then save "Playback Options", the NAS reappears (probably because MPD is restarted. But next reboot it is gone again.

[ogroot]

I also notice that on RPI2 also gives this problem "occasionally" (1 in 10 reboots). But the RPI4 gives this problem very often. So maybe some timing / race conditions in the startup of MPD and DRC plugin?

[balbuze]

Yes I think this is the case. In the past I spent a lot of time to determine some timer in the plugin for different operations. Some settings were okay with rpi3 but not with a pine64 or thinkerboard. But the result was something like usb Dac through brutefir through brutefir... Or more time through brutefir. If you feel, you can change value in index.js for timeout in section set loopback. I can't check now, but a value such as 22000ms is set.

[balbuze]

Section start at line 2761. Make changes, save and do a killall node to restart Volumio

[ogroot]

Ok. Will try. BTW: I noticed indeed this "DigiOne through brutefir through brutefir" this morning.

[ogroot]

Not sure if I was changing the correct value/line in index.js, but there was a value 13500 at line 2811. Changed it to several values and restarted with killall node. Results are:

8000 --> sometimes it works, sometimes not (no significant noticable difference) 13500 --> (default value) sometimes it works, sometimes not 25000 --> sometimes it works, sometimes not (no significant noticable difference)

So this does make not a noticeable difference. Also tested with other values for the 5500 at line 2788. Not no difference either.

Did I change the correct value?

[ogroot]

Above test was on: Bare RPI4 (Allo DigiOne removed. Output = jack) Clean Volumio 2.713 install with DRC 1.4.3.

I can imagine that it is difficult for you to reproduce, because here it is very unpredictable. Sometimes it work 5x in a row. And then suddenly it does not work 5x in a row.

[ogroot]

See attached zip file with output from journalctl -f after killall node and NAS is not shown.

Notice also: message= [50@0] {} No database, stack=Error: [50@0] {} No database Mar 01 12:49:07 volumio-living volumio[4545]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:63:14)

r4.out.zip

[balbuze]

hi! have any chance too try last volumio 2.714?

[balbuze]

if not better, can you try to add 'boot priority" in package.json like that : { "name": "brutefir", "version": "1.4.3", "description": "DRC -Digital Room Correction - for Volumio2", "main": "index.js", "scripts": { "test": "echo \"Error: no test specified\" && exit 1" }, "author": "Balbuze", "license": "GPL 3.0", "volumio_info": { "prettyName": "DRC for Volumio", "plugin_type": "audio_interface", "icon": "fa-sliders fa-rotate-90", "boot_priority": 10 }, "dependencies": { "child_process": "", "fs-extra": "^4.0.2", "kew": "", "socket.io": "", "socket.io-client": "", "v-conf": "", "wav-file-info": "0.0.8", "journalctl": "" } } and reboot.

[ogroot]

ok. I will try 2.714 and this boot priority tomorrow.

[ogroot]

Ok. I tested with boot priority. But makes no difference. With DRC disabled --> 100% Ok With DRC enabled --> +/- 50% OK / 50% NOT OK

[ogroot]

Is just rebooting after adding 'boot priority" in package.json enough? Or should I have done something extra?

[ogroot]

Restarting MPD makes the NAS share immediately visible again. (via Save: Playback Options - Audio Output)

Because of this I had a look at the process list and notice something!!!

After booting MPD is running as user "root" and the NAS is not visible. After restarting MPD it is running as user "mpd" and now the NAS is visible

Process list immediatelly after Booting: root 1083 0.0 0.0 7384 1448 ? S 15:52 0:00 /bin/journalctl -o json -f -u brutefir root 1117 0.3 1.5 153696 30728 ? Ssl 15:52 0:00 /usr/bin/mpd --no-daemon root 1149 0.0 0.0 1820 384 ? Ss 15:52 0:00 /bin/sh /usr/bin/brutefir /data/configuration/audio_interface/brutefir/volumio-brutefir-c root 1150 0.9 1.8 39496 37424 ? SL 15:52 0:00 /usr/lib/brutefir/brutefir.real /data/configuration/audio_interface/brutefir/volumio-brut root 1192 0.6 1.9 42380 40232 ? SL 15:52 0:00 /usr/lib/brutefir/brutefir.real /data/configuration/audio_interface/brutefir/volumio-brut root 1193 0.7 1.9 42380 40236 ? SL 15:52 0:00 /usr/lib/brutefir/brutefir.real /data/configuration/audio_interface/brutefir/volumio-brut root 1194 0.2 1.8 39496 37368 ? SL 15:52 0:00 /usr/lib/brutefir/brutefir.real /data/configuration/audio_interface/brutefir/volumio-brut root 1195 0.1 1.8 39496 37436 ? SL 15:52 0:00 /usr/lib/brutefir/brutefir.real /data/configuration/audio_interface/brutefir/volumio-brut volumio 1212 0.0 0.2 852156 5956 ? Ssl 15:53 0:00 /bin/streaming-daemon root 1296 0.3 0.2 9380 5204 ? Ss 15:53 0:00 sshd: volumio [priv] volumio 1301 0.1 0.1 5028 3356 ? Ss 15:53 0:00 /lib/systemd/systemd --user volumio 1304 0.0 0.0 25156 1408 ? S 15:53 0:00 (sd-pam)

Proces list after restarting MPD: root 1083 0.0 0.0 7384 1448 ? S 15:52 0:00 /bin/journalctl -o json -f -u brutefir root 1149 0.0 0.0 1820 384 ? Ss 15:52 0:00 /bin/sh /usr/bin/brutefir /data/configuration/audio_interface/brutefir/volumio-brutefir-c root 1150 0.4 1.8 39496 37424 ? SL 15:52 0:00 /usr/lib/brutefir/brutefir.real /data/configuration/audio_interface/brutefir/volumio-brut root 1192 1.1 1.9 42380 40232 ? RL 15:52 0:01 /usr/lib/brutefir/brutefir.real /data/configuration/audio_interface/brutefir/volumio-brut root 1193 1.1 1.9 42380 40236 ? RL 15:52 0:01 /usr/lib/brutefir/brutefir.real /data/configuration/audio_interface/brutefir/volumio-brut root 1194 0.0 1.8 39496 37368 ? SL 15:52 0:00 /usr/lib/brutefir/brutefir.real /data/configuration/audio_interface/brutefir/volumio-brut root 1195 0.1 1.8 39496 37436 ? SL 15:52 0:00 /usr/lib/brutefir/brutefir.real /data/configuration/audio_interface/brutefir/volumio-brut volumio 1212 0.0 0.2 852156 5956 ? Ssl 15:53 0:00 /bin/streaming-daemon root 1296 0.0 0.2 9380 5204 ? Ss 15:53 0:00 sshd: volumio [priv] volumio 1301 0.0 0.1 5028 3356 ? Ss 15:53 0:00 /lib/systemd/systemd --user volumio 1304 0.0 0.0 25156 1408 ? S 15:53 0:00 (sd-pam) mpd 1343 2.1 1.8 158828 37152 ? Ssl 15:55 0:00 /usr/bin/mpd --no-daemon

[ogroot]

@balbuze : could it be that DRC plugin is causing MPD to restart as "root"?

[balbuze]

hello! thank for your investigation. when the plugin start, it changes the output of volumio (not only mpd, but all output such spotify, airplay, upnp...) This cause a restart of all related services. I don't see why restart use mpd as user... but this could be a reason

[balbuze]

do you log into volumio using volumio as user ? (ssh volumio@ip ?)

[ogroot]

Yes I login into ssh as 'volumio'. But restarting of MPD I do via the GUI. (by pressing the save button of Playback Options - Audio Output. After I do this MPD runs as "mpd".

[ogroot]

1. Booting with DRC disabled --> mpd runs as 'mpd' --> NAS visible
2. Booting with DRC enabled --> mpd runs as 'root' --> NAS not visible

[ogroot]

Is it correct that DRC plugin and Brutefir run as 'root'?