Volumio stops playing every few hours

pmoorhead · December 19, 2016, 10:53pm

I’m running Volumio on several Pi 2s connected to FM transmitters - they’re meant to play continuously, and they did when I ran that other Pi-based music software (ru****io). But after several hours playing stops. Nothing obviously wrong - if I press play it starts up again.
and yes I do have random and loop enabled.
I’ve tried short playlists as well as very very long ones - same result.
i can’t be the only person trying to play music continuously but I don’t see any other reports for this problem.

I also can’t find an option anywhere to automatically refresh the database. I’m ok with using a cron entry but it means installing cron.

Is anyone else seeing this issue?

volumio · December 20, 2016, 9:59am

The db automatically updates whenever you add new files to USB .

To understand what goes wrong (and why playback stops) we need to see a bit of logs:

do this

sudo journalctl -f /home/volumio/log.log

then attach the file /home/volumio/log.log here

pmoorhead · December 21, 2016, 8:35pm

thanks for responding.

I tried that command. Got:

Couldn’t stat file: No such file or directory
Failed to add filters: No such file or directory

volumio · December 21, 2016, 9:43pm

Sorry my mistake, it should have been

sudo journalctl -f > /home/volumio/log.log

pmoorhead · December 22, 2016, 5:22pm

thanks, that worked.
log file attached.
or rather, it’s not - I don’t seem to be able to upload any files - it objects to whichever extension I use (or none at all).
it’s too big to paste into the post unless you only need the last few lines, which are here:

--------------------------- 8< --------------------------
Dec 22 17:10:08 garage volumio[771]: info: [1482426608537] ControllerMpd::pushState
Dec 22 17:10:08 garage volumio[771]: info: CoreCommandRouter::servicePushState
Dec 22 17:10:08 garage volumio[771]: info: [1482426608555] CoreStateMachine::syncState
Dec 22 17:10:08 garage volumio[771]: info: [1482426608558] CorePlayQueue::getTrack 4111
Dec 22 17:10:08 garage volumio[771]: info: STATE SERVICE {“status”:“play”,“position”:0,“seek”:638,“duration”:274,“samplerate”:“44.1 KHz”,“bitdepth”:“24 bit”,“channels”:2,“random”:false,“updatedb”:false,“repeat”:false,“isStreaming”:false,“title”:“Push”,“artist”:“Neil Davidge”,“album”:null,“uri”:“NAS/NAS1/Favourites/Neil Davidge/Unknown Album/01-- Push.mp3”,“trackType”:“mp3”}
Dec 22 17:10:08 garage volumio[771]: info: CURRENT POSITION 4111
Dec 22 17:10:08 garage volumio[771]: info: [1482426608579] CoreStateMachine::syncState stateService play
Dec 22 17:10:08 garage volumio[771]: info: [1482426608596] CoreStateMachine::syncState currentStatus play
Dec 22 17:10:08 garage volumio[771]: info: [1482426608600] Received an update from plaugin. extracting info from payload
Dec 22 17:10:08 garage volumio[771]: info: [1482426608611] CoreStateMachine::pushState
Dec 22 17:10:08 garage volumio[771]: info: [1482426608623] CoreStateMachine::getState
Dec 22 17:10:08 garage volumio[771]: info: [1482426608626] CorePlayQueue::getTrack 4111
Dec 22 17:10:08 garage volumio[771]: info: CoreCommandRouter::volumioPushState
Dec 22 17:10:08 garage volumio[771]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 22 17:10:08 garage volumio[771]: info: [1482426608648] interfaceApi::pushState
Dec 22 17:10:08 garage volumio[771]: info: [1482426608666] InterfaceWebUI::pushState
Dec 22 17:10:08 garage volumio[771]: info: [1482426608771] ------------------------------ 1665ms
Dec 22 17:10:08 garage volumio[771]: info: [1482426608787] ------------------------------ 1542ms
Dec 22 17:10:08 garage volumio[771]: info: [1482426608804] ------------------------------ 1532ms
Dec 22 17:10:08 garage volumio[771]: info: [1482426608894] CoreStateMachine::startPlaybackTimer
Dec 22 17:10:08 garage volumio[771]: info: [1482426608902] CorePlayQueue::getTrack 2272
Dec 22 17:10:08 garage volumio[771]: info: Pushing Favourites {“service”:“mpd”,“uri”:“mnt/NAS/NAS1/Favourites/ZZ Top/Unknown Album/01-- Cheap Sunglasses.mp3”,“favourite”:false}
Dec 22 17:10:09 garage volumio[771]: info: Pushing Favourites {“service”:“mpd”,“uri”:“mnt/NAS/NAS1/Favourites/ZZ Top/Unknown Album/01-- Cheap Sunglasses.mp3”,“favourite”:false}
Dec 22 17:10:09 garage volumio[771]: info: Pushing Favourites {“service”:“mpd”,“uri”:“mnt/NAS/NAS1/Favourites/ZZ Top/Unknown Album/01-- Cheap Sunglasses.mp3”,“favourite”:false}
Dec 22 17:10:36 garage nmbd[721]: [2016/12/22 17:10:36.731229, 0] …/source3/nmbd/nmbd_namequery.c:109(query_name_response)
Dec 22 17:10:36 garage nmbd[721]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.0.125 for name WORKGROUP<1d>.
Dec 22 17:10:36 garage nmbd[721]: This response was from IP 192.168.0.57, reporting an IP address of 192.168.0.57.
Dec 22 17:10:36 garage nmbd[721]: [2016/12/22 17:10:36.738857, 0] …/source3/nmbd/nmbd_namequery.c:109(query_name_response)
Dec 22 17:10:36 garage nmbd[721]: query_name_response: Multiple (3) responses received for a query on subnet 192.168.0.125 for name WORKGROUP<1d>.
Dec 22 17:10:36 garage nmbd[721]: This response was from IP 192.168.0.55, reporting an IP address of 192.168.0.55.

pmoorhead · December 24, 2016, 6:03pm

tail of a further log at time volumio stopped playing

Dec 24 17:52:04 radio volumio[768]: info: [1482601924957] interfaceApi::pushState
Dec 24 17:52:04 radio volumio[768]: info: [1482601924970] InterfaceWebUI::pushState
Dec 24 17:52:05 radio volumio[768]: info: [1482601925074] ------------------------------ 718ms
Dec 24 17:52:05 radio volumio[768]: info: Pushing Favourites {“service”:“mpd”,“uri”:“mnt/NAS/NAS1/Favourites/All The Young/Unknown Album/01-01- Welcome Home.mp3”,“favourite”:fal$
Dec 24 17:52:05 radio volumio[768]: info: Pushing Favourites {“service”:“mpd”,“uri”:“mnt/NAS/NAS1/Favourites/All The Young/Unknown Album/01-01- Welcome Home.mp3”,“favourite”:fal$
Dec 24 17:52:08 radio volumio[768]: info: [1482601928753] CoreStateMachine::startPlaybackTimer
Dec 24 17:52:08 radio volumio[768]: info: [1482601928763] CorePlayQueue::getTrack 1763
Dec 24 17:53:34 radio volumio[768]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
Dec 24 17:53:34 radio volumio[768]: info: CoreCommandRouter::volumioGetState
Dec 24 17:53:34 radio volumio[768]: info: [1482602014402] CoreStateMachine::getState
Dec 24 17:53:34 radio volumio[768]: info: [1482602014411] CorePlayQueue::getTrack 1763
Dec 24 17:53:34 radio volumio[768]: info:
Dec 24 17:53:34 radio volumio[768]: [1482602014416] ---------------------------- Client requests Volumio state
Dec 24 17:53:34 radio volumio[768]: info: [1482602014441] Listing playlists
Dec 24 17:53:34 radio volumio[768]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Dec 24 17:53:34 radio volumio[768]: Plugin multiroom or method getMultiroom not found
Dec 24 17:53:34 radio volumio[768]: info:
Dec 24 17:53:34 radio volumio[768]: [1482602014557] ---------------------------- Client requests Menu Items
Dec 24 17:53:34 radio volumio[768]: info: [1482602014575] InterfaceWebUI::pushState
Dec 24 17:53:34 radio volumio[768]: info: [1482602014704] ------------------------------ 312ms
Dec 24 17:53:35 radio volumio[768]: info: [1482602015062] ------------------------------ 505ms
Dec 24 17:53:35 radio volumio[768]: info: /data/albumart/folder//mnt/NAS/NAS1/Favourites/All The Young/Unknown Album/extralarge.jpeg
Dec 24 17:53:35 radio volumio[768]: info: Sending file /data/albumart/folder//mnt/NAS/NAS1/Favourites/All The Young/Unknown Album/extralarge.jpeg
Dec 24 17:53:35 radio volumio[768]: info: Serving request took 89 milliseconds
Dec 24 17:53:35 radio volumio[768]: info: /data/albumart/folder//mnt/NAS/NAS1/Favourites/KLF/Unknown Album/extralarge.jpeg
Dec 24 17:53:35 radio volumio[768]: info: Sending file /data/albumart/folder//mnt/NAS/NAS1/Favourites/KLF/Unknown Album/extralarge.jpeg
Dec 24 17:53:35 radio volumio[768]: info: Serving request took 24 milliseconds
Dec 24 17:55:29 radio nmbd[720]: [2016/12/24 17:55:29.420726, 0] …/source3/nmbd/nmbd_namequery.c:109(query_name_response)
Dec 24 17:55:29 radio nmbd[720]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.0.120 for name WORKGROUP<1d>.
Dec 24 17:55:29 radio nmbd[720]: This response was from IP 192.168.0.55, reporting an IP address of 192.168.0.55.
Dec 24 17:55:29 radio nmbd[720]: [2016/12/24 17:55:29.426782, 0] …/source3/nmbd/nmbd_namequery.c:109(query_name_response)
Dec 24 17:55:29 radio nmbd[720]: query_name_response: Multiple (3) responses received for a query on subnet 192.168.0.120 for name WORKGROUP<1d>.
Dec 24 17:55:29 radio nmbd[720]: This response was from IP 192.168.0.42, reporting an IP address of 192.168.0.42.

pmoorhead · January 6, 2017, 4:52pm

I’ve eliminated a few things:

occurs with both Pi 2 and Pi 3
occurs whether source music is on NAS or local drive
occurs whether playlist is very very large, or just one album on shuffle/repeat

Have had to revert to Runeaudio for the time being. Will await the next release and try again.

pmoorhead · April 29, 2017, 9:46am

update 2.129 has same problem. sigh.

chsims1 · April 29, 2017, 10:55am

The key here is seeing the logs at the point the problem occurs.

Would you mind flashing the latest version (2.141) just to rule out anything altered since v2.129?

There is now a method of sending posts from the Volumio interface. Please do a reboot of your RPi before waiting for the problem to occur, and then include your username in the problem description, and note that it is not necessary for you to post the log here.