volumio boot issue ?

Volumio Development Bug reports
1

Hi

This would be my first topic on this forum.

I’ve been using volumio for about 8 months now and i really like it. It has now replaced my living room system.
The System is a RPi2 with Volumio 2.452 with an Audiophonics DAC AMP and ATX board.
This means I’m also running some plugins : Volumio simple Equilizer, Autostart, Audiophonics ON/OFF, Backup/Restore

In this configuration I’m able to start & shut down the system with a push button like a ‘normal’ PC would.
I usually have some webstream in the queue so that should start playing after a boot

That’ s where the problem starts :
after a cold boot (power was completely shut off), the Pi boots normally, the startup sound is played but then something goes wrong.
I can connect to the Volumio UI over the webinterface, ssh into it… all works fine. As far as the interface is showing it ‘should’ be playing tunes nicely and responds to normal start/stop/next commands as expected.
However no sound is played.
I noticed also in this ‘state’ that my music library doesn’t show the NAS drive I have setup.

the only way to recover from that is to reboot from the webUI, sometimes even a few times, after which everything works as it should

If I use the ATX board to power cycle the system, it sometimes comes up ok, but more often not.

I have attached the volumio logs of such a cold boot and hot boot as well as the dmesg outputs if that may be of assistance

the cold boot throws an error that the database could not be loaded

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.<anonymous> (/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)

after which the boot continues

I’d be more than willing to offer any assistance to run more tests to try and solve this issue.

If I need to post this elsewhere (github?) please inform me accordingly

thank you
Diego
bootdiff.tgz (16.1 KB)

2

Where are your music files located?

3

My main music storage with 8k+ files is on a Synology NAS NFS share.

Under Settings -> My Music it always shows as mounted on the Network Drives panel yet the counters under My Music are at zero after a cold boot.
And when I browse to the Music Library in the GUI nothing is shown. Not even the internal drive or the local USB stick I plugged in to see If it could be that the NAS is too slow at startup.

It seems this database error is crippling everything up since I can’t even get Volumio to play a webstream or even an item from a playlist off the USB stick that was running before the power cycle. (A lot of iterations have been tried)

To make it more awkward : the GUI shows - aside from the zero counters above - everything as normal. When ‘playing’ off an old playlist even album art is displayed, the playtime ticks away… yet no sound is heard !?

Is there a way to get more verbose logs to see if something more shows up ?

Diego

4

This seems to me to likely be your hardware setup. Is it possible to try a cold boot without your ATX board (not even sure what that is in this particular case, but presumably something to do with power supply). Also, you might get such an error presumably if your NAS is not “awake” when the RPi trys to access it after a cold boot (and a sufficiently long time for the NAS to sleep). Clutching at straws a bit here. but it’s rather a strange one.

5

Thanks for trying to figure it out, it has me baffled as well as I’m trying to reliably recreate the issue.

FYI the ATX board is https://www.audiophonics.fr/en/diy-kits-and-boards/audiophonics-pi-spc-v2-power-management-module-for-raspberry-pi-preassembled-p-11125.html

and by extension the output device is https://www.audiophonics.fr/en/dac-and-interfaces-for-raspberry-pi/audiophonics-i-sabre-amp-dac-es9023-class-d-amplifier-2x30w-tpa3118-p-11800.html BTW nifty little thing when coupled to vintage high efficiency speakers (95 db/W)…

I’ve tried as you suggested to recreate the issue with the ATX board removed and to simplify autoplay files from the local usb stick. Removing the ATX board doesn’t change things So far I have not been able to get in to the cold boot state with the database error, starting from a playing state.

So I looked at my NAS and tried to recreate the coldboot issue with the NAS hibernating or not (I set the hibernate time to 10 min, as low as it’ll go and wait - luckily I can play some tunes while waiting) but again no luck to recreate the failed database issue.

I would think my NAS setup is pretty plain, just a little home server to host the music files for various renderers, and set to hibernate when not in use to reduce wear on the internal drives.
I can imagine that - although volumio appears to be designed to be always up and running - every now and then somebody would unplug the power to a RPi for whatever reason and might not be able to get it back running
I’m not trying to be judgemental here, just trying to figure out why this problem keeps coming up.

Even when playing tracks from the stick, my NAS goes into hibernation as volumio isn’t actively accessing the system. When I start browsing the library, there is the normal (?) longer wait for the NAS to finish powering up (10-20 s at most) before I can contine to play files from the NAS, in all provided we didn’t have the database error at boot.

I understand it’s pretty hard to keep track of all possible configurations to be able to debug everything but as far as I’m concerned my system is at your disposal for further testing

could it be an issue with how the network drives are mounted (fstab -nobootwait) ? Didn’t check that… but it could be a problem with NFS drives that aren’t always up and running .

So for now it appears to be working but I’m not totally convinced this thing won’t come back

Diego

6

I haven’t ever seen that error message reported, and yes I’m sure that plenty of people switch the psu to their devices off (including myself).

Can you just confirm that you are doing a standard Volumio mount of the NAS drive via the UI, and not trying to manually mount via fstab?

7

Confirmed, no manual mounting of my network shares or any other for that matter…

Just managed to get it into the fault state again, I’ll try to detail it as good as I can.

With the autostart plugin on,
With a radiostream as first item in the play queue
After a cold boot the database gives an error though the NAS drive shows as mounted, nothing in the My 'Music db, see pic. NAS is hibernating.

Screenshot_2018-09-28-16-07-05.jpg

A hotboot from the web UI Is required to resolve the situation
It is impossible to have anything playing, not even locally from a stick (not even when present on the play queue before power cycle) nor from any other dlna controller

The UI seems to be playing the webstream yet aside from startup sound, no sound.

Screenshot_2018-09-28-16-18-58.jpg
Does this help ?
Diego

8

There have been a number of plugins causing problems recently; I think that I would try removing them all & then reintroducing them one by one. The problem here though is how reproducible getting the failed state is. Try the ‘autostart’ one first.

9

Well I’ve tried as you suggested, however I kind of need all of these plug-ins .

The autoplay is for SWMBO that just want to push a button and then the music starts, can’t get her to browse to a web UI and press some more things.

I have uninstalled the autoplay plugin and sure enough I could cold boot normally, even the NAS comes out of hibernation.

So I reinstalled it and for now it seems to be working normally… Probably an upgrade of volumio didn’t upgrade the plugins. Shouldn’t it just do that as well ?

I’ll see how it goes in the next few days.

Diego

10

No reason that you can’t have all your plugins :wink: The reason for removing them was to find which if any was causing the problem. You seem to be saying that the ‘autoplay’ was responsible, so progress …

Now, exactly which plugin is it, because I remember that the original was called ‘autoplay’, but that was superseded by ‘autostart’. If you are using the older one then try the new version. If you have the latest version, then contact the plugin author.

Just to clarify, plugins are often produced by the Community, and it is necessary for the plugin author to keep up to date with internal Volumio changes. Sometimes they need a nudge to do this, especially if they don’t see the problem in their own system.

Let us know how you get on :slight_smile:

11

Well, I’m not out of the woods yet…

I have tried to keep cold booting the system because today I had the same issue yet with sometimes different behaviour. It would appear that any plugin causes the spurious database thing.

Sometimes the counters are at zero , other times nothing is shown, a situation that appears to rectify itself after a while. It might be that a ssh login matters as well.

In the no counters situation, a different error is logged :

2018-09-30T16:18:30.387Z - error: MPD error: Error: read ECONNRESET 2018-09-30T16:19:33.951Z - error: Upnp client error: Error: connect ETIMEDOUT 127.0.0 .1:6600

which is repeated a few times especially so when I try to initiate a play state (USB stick track)

I still can’t find a way to invoke the fault state in a repeatable way, as it appears quite random .
Is there any other way to get some more insight what’s going on ?

So for now I’ve increased the wait time for the autoplay, but I fear tomorrow we 'll be back at square one.

Edit : same thing, mpd error and no counters

Any hints ?
Diego

12

Sorry to keep bugging everybody

Yet now I’ve found this in journalctl :

[code]-- Logs begin at Sun 2018-09-30 19:52:38 UTC, end at Mon 2018-10-01 06:11:50 UTC. –
Oct 01 06:09:55 volumioii sudo[1279]: pam_unix(sudo:session): session opened for user root by volumio(uid=0)
Oct 01 06:10:26 volumioii systemd[1]: mpd.service start operation timed out. Terminating.
Oct 01 06:10:32 volumioii volumio[931]: Upnp client error: Error: This socket has been ended by the other party
Oct 01 06:10:32 volumioii volumio[931]: error: MPD error: Error: read ECONNRESET
Oct 01 06:10:32 volumioii systemd[1]: Failed to start Music Player Daemon.
– Subject: Unit mpd.service has failed
– Defined-By: systemd
– Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel

– Unit mpd.service has failed.

– The result is failed.
Oct 01 06:10:32 volumioii systemd[1]: Unit mpd.service entered failed state.
Oct 01 06:10:32 volumioii systemd[1]: Starting Music Player Daemon…
– Subject: Unit mpd.service has begun with start-up
– Defined-By: systemd
– Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel

– Unit mpd.service has begun starting up.
Oct 01 06:10:43 volumioii sudo[1279]: pam_unix(sudo:session): session closed for user root
Oct 01 06:11:50 volumioii sudo[1301]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/journalctl -xn
Oct 01 06:11:50 volumioii sudo[1301]: pam_unix(sudo:session): session opened for user root by volumio(uid=0)
[/code]

Diego

13

Updated to new version,reinstalled all plugins from scratch, still the problem persists.

Error codes, which are repeated a few times

Oct 03 03:48:24 volumioii systemd[1]: mpd.service start operation timed out. Terminating. Oct 03 03:49:55 volumioii systemd[1]: mpd.service stop-final-sigterm timed out. Killing. Oct 03 03:49:55 volumioii systemd[1]: mpd.service: main process exited, code=killed, status=9/KILL Oct 03 03:49:55 volumioii systemd[1]: Failed to start Music Player Daemon. Oct 03 03:49:55 volumioii systemd[1]: Unit mpd.service entered failed state. Oct 03 03:49:55 volumioii sudo[1074]: pam_unix(sudo:session): session closed for user root Oct 03 03:49:55 volumioii systemd[1]: Starting Music Player Daemon... Oct 03 03:49:55 volumioii volumio[947]: info: Cannot restart MPD: Error: Command failed: /usr/bin/sudo /bin/systemctl restart mpd.service Oct 03 03:49:55 volumioii volumio[947]: Job for mpd.service failed. See 'systemctl status mpd.service' and 'journalctl -xn' for details. Oct 03 03:51:16 volumioii volumio[947]: info: CorePlayQueue::getTrack 0

14

this issue had been raised long time. Volumio is busy. Maybe releasing everything as myvolumio