cubox-i4-pro crashes while scanning library

daniel · May 1, 2017, 12:45pm

I have problem scanning my library with cubox-i4-pro using latest image form oph.mdrjr.net/gkkpch/ (Volumio-debian-mpd-2017-03-31-cuboxi.img)

The log shows that it first scanned around 180 albums all HiRes 24/96 and than crashed with

Apr 17 08:44:25 volumio mpd[716]: update: added NAS/Music96/Donald Fagen/Kamakiriad/01 - Trans-Island Skyway.flac
Apr 17 08:44:25 volumio systemd[1]: mpd.service: main process exited, code=killed, status=11/SEGV
Apr 17 08:44:25 volumio systemd[1]: Unit mpd.service entered failed state.
Apr 17 08:44:26 volumio systemd[1]: mpd.service holdoff time over, scheduling restart.
Apr 17 08:44:26 volumio systemd[1]: Stopping Music Player Daemon...
Apr 17 08:44:26 volumio systemd[1]: Starting Music Player Daemon...
Apr 17 08:44:26 volumio systemd[1]: Started Music Player Daemon.
Apr 17 08:44:26 volumio mpd[4118]: [146B blob data]

than the system tries to restart the process several times:

Apr 17 08:44:26 volumio systemd[1]: mpd.service: main process exited, code=exited, status=127/n/a
Apr 17 08:44:26 volumio systemd[1]: Unit mpd.service entered failed state.
Apr 17 08:44:26 volumio systemd[1]: mpd.service holdoff time over, scheduling restart.
Apr 17 08:44:26 volumio systemd[1]: Stopping Music Player Daemon...
Apr 17 08:44:26 volumio systemd[1]: Starting Music Player Daemon...
Apr 17 08:44:26 volumio systemd[1]: Started Music Player Daemon.
Apr 17 08:44:26 volumio mpd[4120]: [146B blob data]

Than it shuts down and tries to do a system restart but failed several times.

Apr 17 08:44:27 volumio systemd[1]: mpd.service start request repeated too quickly, refusing to start.
    Apr 17 08:44:27 volumio systemd[1]: Failed to start Music Player Daemon.
    Apr 17 08:44:27 volumio systemd[1]: Unit mpd.service entered failed state.
    Apr 17 08:44:28 volumio systemd-journal[4129]: Runtime journal is using 12.0M (max allowed 30.0M, trying to leave 284.2M free of 1.8G available → current limit 30.0M).
    Apr 17 08:44:28 volumio systemd[1]: systemd-journald.service has no holdoff time, scheduling restart.
    Apr 17 08:44:28 volumio systemd[1]: Stopping Journal Service...
    Apr 17 08:44:28 volumio systemd[1]: Starting Journal Service...
    Apr 17 08:44:28 volumio systemd[1]: Started Journal Service.
    Apr 17 08:44:28 volumio systemd-journal[4129]: Journal started
    Apr 17 08:44:28 volumio systemd[1]: systemd-journald.service: main process exited, code=killed, status=11/SEGV
    Apr 17 08:44:28 volumio systemd[1]: Unit systemd-journald.service entered failed state.
    Apr 17 08:44:28 volumio systemd[1]: Starting Trigger Flushing of Journal to Persistent Storage...
    Apr 17 08:44:28 volumio systemd[1]: udisks-glue.service: main process exited, code=killed, status=4/ILL
    Apr 17 08:44:28 volumio systemd[1]: Unit udisks-glue.service entered failed state.
    Apr 17 08:44:28 volumio systemd[1]: udisks.service: main process exited, code=killed, status=4/ILL
    Apr 17 08:44:28 volumio systemd[1]: Unit udisks.service entered failed state.
    Apr 17 08:44:28 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
    Apr 17 08:44:28 volumio systemd[1]: Unit volumio.service entered failed state.

finally it losts connection

Apr 17 08:44:43 volumio volumio[4224]: info: Cannot initialize  MPD Connection: MPD is not running
Apr 17 08:44:43 volumio sudo[4287]: PAM unable to dlopen(pam_systemd.so): /lib/security/pam_systemd.so: cannot open shared object file: No such file or directory
Apr 17 08:44:43 volumio sudo[4287]: PAM adding faulty module: pam_systemd.so
Apr 17 08:44:43 volumio sudo[4287]: pam_unix(sudo:auth): conversation failed
Apr 17 08:44:43 volumio sudo[4287]: pam_unix(sudo:auth): auth could not identify password for [volumio]
Apr 17 08:44:43 volumio volumio[4224]: info: Cannot read I2C interface or I2C interface not presentError: Command failed: /usr/bin/sudo /usr/sbin/i2cdetect -y 1

scanning only a single folders worked but not the entire library. Do I run into some limitations?

Daniel

gkkpch · May 3, 2017, 8:24pm

Hi Daniel,
Yes, this is a known issue from a number of platforms, where a lot of time has been spend on lately to get it solved.
Luckily we have the solution now, it will be part of the next release.

As you’re asking, could you check something for me (unrelated though) on the Cubox platform and do

sudo cat /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor

daniel · May 13, 2017, 9:28am

Sorry, I just noticed your post … even though I have enabled the option ‘Notify me when a reply is posted’.

sudo cat /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor

Anyway, the result is

ondemand

Second I noticed an update for several boards and the changelog for 2.163 says

“Fixed Database creation on big libraries”

Does this address the issue? Unfortunately not yet a new release for Cubox.

gkkpch · May 13, 2017, 9:39am

Thanks.
I will generate a new image and post the link here in an hour or so.

gkkpch · May 13, 2017, 10:01am

here you go: http://updates.volumio.org/cuboxi/volumio/2.170/volumio-2.170-2017-05-13-cuboxi.img.zip

daniel · May 13, 2017, 11:17am

unfortunately this build did not work for me. Could not even boot

gkkpch · May 13, 2017, 12:11pm

Strange, no errors while building, going to download now myself and test it.

gkkpch · May 13, 2017, 1:01pm

yes, confirming it does not boot properly, this needs to be checked and might take some time…
Sorry about that.

volumio · May 13, 2017, 1:03pm

Might be related to the initram changes I’ve made?

gkkpch · May 13, 2017, 1:27pm

it fails in initrd, so very well possible. Let’s check it out.

gkkpch · May 15, 2017, 5:48pm

Hi Daniel,

Problem solved: download version 2.173 here

daniel · May 15, 2017, 8:11pm

Thanks gkkpch.

It boots fine. Library scanning seems to be much faster - at least it feels much faster.
But it still crashes volumio at around 190 albums .

sudo journalctl -f
-- Logs begin at Mon 2017-05-15 17:35:23 UTC. --
May 15 19:56:00 volumio systemd[1226]: Starting Basic System.
May 15 19:56:00 volumio systemd[1226]: Reached target Basic System.
May 15 19:56:00 volumio systemd[1226]: Starting Default.
May 15 19:56:00 volumio systemd[1226]: Reached target Default.
May 15 19:56:00 volumio systemd[1226]: Startup finished in 53ms.
May 15 19:56:00 volumio systemd[1]: Started User Manager for UID 1000.
May 15 19:56:01 volumio sshd[1224]: lastlog_openseek: Couldn't stat /var/log/lastlog: No such file or directory
May 15 19:56:01 volumio sshd[1224]: lastlog_openseek: Couldn't stat /var/log/lastlog: No such file or directory
May 15 19:56:39 volumio sudo[1236]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/journalctl -f
May 15 19:56:39 volumio sudo[1236]: pam_unix(sudo:session): session opened for user root by volumio(uid=0)
May 15 19:56:42 volumio dhcpd[1077]: DHCPDISCOVER from b8:5a:f7:82:7b:09 (volumio) via wlan0
May 15 19:56:43 volumio dhcpd[1077]: DHCPOFFER on 192.168.211.2 to b8:5a:f7:82:7b:09 (volumio) via wlan0
May 15 19:56:51 volumio volumio[1067]: info: CoreCommandRouter::getUIConfigOnPlugin
May 15 19:56:51 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam
May 15 19:56:51 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam
May 15 19:56:52 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:56:52 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares
May 15 19:56:56 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:00 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:01 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , rescanDb
May 15 19:57:01 volumio volumio[1067]: info: [1494878221220] ControllerMpd::sendMpdCommand rescan
May 15 19:57:01 volumio volumio[1067]: info: [1494878221222] sending command...
May 15 19:57:01 volumio volumio[1067]: info: [1494878221226] ControllerMpd::sendMpdCommand status
May 15 19:57:01 volumio volumio[1067]: info: Mpd Status Update: update
May 15 19:57:01 volumio volumio[1067]: info:
May 15 19:57:01 volumio volumio[1067]: [1494878221233] ---------------------------- MPD announces state update
May 15 19:57:01 volumio volumio[1067]: info: [1494878221237] parsing response...
May 15 19:57:01 volumio volumio[1067]: info: [1494878221240] sending command...
May 15 19:57:01 volumio volumio[1067]: info: [1494878221242] ControllerMpd::getState
May 15 19:57:01 volumio volumio[1067]: info: [1494878221244] ControllerMpd::sendMpdCommand status
May 15 19:57:01 volumio volumio[1067]: info: [1494878221245] sending command...
May 15 19:57:01 volumio volumio[1067]: info: [1494878221248] parsing response...
May 15 19:57:01 volumio volumio[1067]: info: [1494878221249] parsing response...
May 15 19:57:01 volumio volumio[1067]: info: [1494878221253] ControllerMpd::parseState
May 15 19:57:01 volumio volumio[1067]: info: Command Router : Notfying DB Updatetrue
May 15 19:57:01 volumio volumio[1067]: info: [1494878221345] ControllerMpd::parseState
May 15 19:57:01 volumio volumio[1067]: info: [1494878221346] ControllerMpd::pushState
May 15 19:57:01 volumio volumio[1067]: info: CoreCommandRouter::servicePushState
May 15 19:57:01 volumio volumio[1067]: info: [1494878221355] CoreStateMachine::syncState
May 15 19:57:01 volumio volumio[1067]: info: [1494878221356] CorePlayQueue::getTrack 0
May 15 19:57:01 volumio volumio[1067]: info: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null}
May 15 19:57:01 volumio volumio[1067]: info: CURRENT POSITION 0
May 15 19:57:01 volumio volumio[1067]: info: [1494878221359] CoreStateMachine::syncState   stateService stop
May 15 19:57:01 volumio volumio[1067]: info: [1494878221360] CoreStateMachine::syncState   currentStatus stop
May 15 19:57:01 volumio volumio[1067]: info: [1494878221360] CoreStateMachine::pushState
May 15 19:57:01 volumio volumio[1067]: info: [1494878221362] CoreStateMachine::getState
May 15 19:57:01 volumio volumio[1067]: info: [1494878221363] CorePlayQueue::getTrack 0
May 15 19:57:01 volumio volumio[1067]: info: CoreCommandRouter::volumioPushState
May 15 19:57:01 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 15 19:57:01 volumio volumio[1067]: info: [1494878221368] interfaceApi::pushState
May 15 19:57:01 volumio volumio[1067]: info: [1494878221369] InterfaceWebUI::pushState
May 15 19:57:01 volumio volumio[1067]: info: [1494878221391] No code
May 15 19:57:01 volumio volumio[1067]: info: [1494878221392] CoreStateMachine::pushState
May 15 19:57:01 volumio volumio[1067]: info: [1494878221393] CoreStateMachine::getState
May 15 19:57:01 volumio volumio[1067]: info: [1494878221394] CorePlayQueue::getTrack 0
May 15 19:57:01 volumio volumio[1067]: info: CoreCommandRouter::volumioPushState
May 15 19:57:01 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 15 19:57:01 volumio volumio[1067]: info: [1494878221396] interfaceApi::pushState
May 15 19:57:01 volumio volumio[1067]: info: [1494878221397] InterfaceWebUI::pushState
May 15 19:57:01 volumio volumio[1067]: info: [1494878221423] ------------------------------ 196ms
May 15 19:57:01 volumio volumio[1067]: info: Pushing Favourites {"service":"mpd","uri":"","favourite":false}
May 15 19:57:01 volumio volumio[1067]: info: Pushing Favourites {"service":"mpd","uri":"","favourite":false}
May 15 19:57:04 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:08 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:12 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:16 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:20 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:24 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:28 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:32 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:36 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:40 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:44 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:47 volumio dhcpd[1077]: DHCPDISCOVER from b8:5a:f7:82:7b:09 (volumio) via wlan0
May 15 19:57:48 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:48 volumio dhcpd[1077]: DHCPOFFER on 192.168.211.2 to b8:5a:f7:82:7b:09 (volumio) via wlan0
May 15 19:57:52 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:57:58 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:00 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:05 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:09 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:13 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:16 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:21 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:24 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:28 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:32 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:36 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:40 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:44 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:48 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:52 volumio dhcpd[1077]: DHCPDISCOVER from b8:5a:f7:82:7b:09 (volumio) via wlan0
May 15 19:58:52 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:58:53 volumio dhcpd[1077]: DHCPOFFER on 192.168.211.2 to b8:5a:f7:82:7b:09 (volumio) via wlan0
May 15 19:58:56 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:00 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:04 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:08 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:12 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:16 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:20 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:24 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:28 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:32 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:36 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:40 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:44 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:48 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:52 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:55 volumio dhcpd[1077]: DHCPDISCOVER from b8:5a:f7:82:7b:09 (volumio) via wlan0
May 15 19:59:56 volumio volumio[1067]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
May 15 19:59:56 volumio dhcpd[1077]: DHCPOFFER on 192.168.211.2 to b8:5a:f7:82:7b:09 (volumio) via wlan0
packet_write_poll: Connection to 192.168.1.125 port 22: Host is down

gkkpch · May 15, 2017, 9:54pm

you mean, the whole device crashed, not just the scanning!
This is not the issue we solved, something else must be happening but we need to be on the uart interface to see that.
Do you know how to connect the pc to the cubox with a usb cable and open a terminal with the putty terminal program?

daniel · May 16, 2017, 7:35pm

I am on OSX with Darwin and comfortable with the terminal. But my knowledge with nix commands is limited. Thus if you give some hints, I am happy to try it

bdouble · May 19, 2017, 3:27am

I can reproduce the hard crash, happens shortly after starting the initial library scan. Running 2.173 on my cubox-i4 pro. I can’t ssh into it after this happens, but it does respond to ping.

bdouble · May 20, 2017, 7:41pm

Was able to get the uart interface running, the Solid Run site has instructions for Cubox here - worked fine on my mac laptop with the driver and other details:
https://wiki.solid-run.com/doku.php?id=products:imx6:microsom:usbuart

This output is with the latest build, in this thread, on a cubox-i4 pro. I’d already mounted my NFS share, which the system had in the config from a previous boot. These logs are from a power-cycle boot, first thing I did when the system came online is to run a re-scan of the library which led to the usual crash.

Here’s my output from the uart - line 471 is where the crash started:
https://pastebin.com/bafrMAq3

And here’s the output of journalctl -f, ssh’ed into the box as soon as it came up and ran that command immediately:
https://pastebin.com/nrV4DhYR

gkkpch · May 20, 2017, 9:20pm

Thanks guys,
I’ll have a look at the details when I’m back home tomorrow.

gkkpch · May 22, 2017, 6:59pm

ok, this seems a different issue, it seems the 3rd (data) partition on the SD is corrupted.
Are you sure you ejected the sd (or synced when using dd) after you flashed?

bdouble · May 23, 2017, 12:02am

I used Etcher on mac to write the image to the SD card - this unmounts the card automatically when the flash is complete. I’ve tried a couple of cards, always a crash on scanning library.

Have a brand new SD card that just came in, will try with that tonight. If the crash happens again I’ll send fresh uart and journalctl logs.

bdouble · May 23, 2017, 1:30am

Trying a brand new Samsung Evo SD card, using Etcher on mac.

Same result - crash on library scan, after a little while.

uart output: pastebin.com/K46tVqk1

journalctl -f: pastebin.com/VDg8NZn0