v2.002, odroid: Scanning of local music library crashes

Latest version of Volumio on OdroidC2 with HifiShield:

Scanning of newly added music-library always stops when reaching approx. 60 artists, 90 albums, 900 tracks and 75:00:00. All counts (Artists, Albums, Tracks and Time) are reset to 0. The arrows near "Browse" (bottom left) keep turning. After clicking Update or Rescan (What's the difference btw?) scanning starts again but only until reaching 75h, then crashes again. The drive is mounted (mounted-status: green, size: 1.42TB) on a wired 1gb/s network smb-share (samba on raspbian). No difference between entering IP or the name for NAS. No difference between fixed IP or DHCP. No difference between system on SD-card or emmc. The same hardware (network, nas, odroid, emmc, ...) was previously working well for months on the latest odroidc2-beta-version (thanks to gkkpch!)

Have there maybe been changes to supported file types so that scanning crashes? My lib has different types, some flac, mostly mp3s. How can I find out, where it stops/crashes? Any other ideas?

Thanks!

I've found "sudo journalctl -f" :)

....updating like next line.... Oct 17 18:11:23 volumio mpd[1312]: update: added NAS/elements2/Artist - Album/Song_xxx.mp3 Oct 17 18:11:23 volumio kernel: Unhandled fault: alignment fault (0x92000021) at 0x00000000eec40c57 Oct 17 18:11:23 volumio systemd[1]: mpd.service: main process exited, code=killed, status=7/BUS Oct 17 18:11:23 volumio systemd[1]: Unit mpd.service entered failed state. Oct 17 18:11:24 volumio systemd[1]: mpd.service holdoff time over, scheduling restart. Oct 17 18:11:24 volumio systemd[1]: Stopping Music Player Daemon... Oct 17 18:11:24 volumio systemd[1]: Starting Music Player Daemon... Oct 17 18:11:24 volumio systemd[1]: Started Music Player Daemon. Oct 17 18:11:24 volumio mpd[1537]: zeroconf: No global port, disabling zeroconf Oct 17 18:11:25 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:11:25 volumio volumio[904]: MPD error: Error: This socket has been ended by the other party Oct 17 18:11:25 volumio volumio[904]: MPD error: Error: This socket has been ended by the other party Oct 17 18:11:25 volumio volumio[904]: MPD error: Error: This socket has been ended by the other party Oct 17 18:11:29 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:11:29 volumio volumio[904]: MPD error: Error: This socket has been ended by the other party Oct 17 18:11:29 volumio volumio[904]: MPD error: Error: This socket has been ended by the other party Oct 17 18:11:29 volumio volumio[904]: MPD error: Error: This socket has been ended by the other party Oct 17 18:11:30 volumio mpd[1537]: client: [0] opened from ::ffff:127.0.0.1:53092 Oct 17 18:11:30 volumio mpd[1537]: client: [1] opened from ::ffff:127.0.0.1:53093 Oct 17 18:11:30 volumio mpd[1537]: alsa_mixer: Failed to read mixer for 'alsa': failed to attach to SoftMaster: No such file or directory Oct 17 18:11:30 volumio mpd[1537]: client: [2] opened from ::ffff:127.0.0.1:53094 Oct 17 18:11:30 volumio mpd[1537]: client: [3] opened from ::ffff:127.0.0.1:53095 Oct 17 18:11:30 volumio volumio[904]: info: Oct 17 18:11:33 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:11:34 volumio mpd[1537]: client: [4] opened from ::ffff:127.0.0.1:53096 Oct 17 18:11:34 volumio mpd[1537]: client: [5] opened from ::ffff:127.0.0.1:53097 Oct 17 18:11:34 volumio mpd[1537]: client: [6] opened from ::ffff:127.0.0.1:53098 Oct 17 18:11:34 volumio volumio[904]: info: Oct 17 18:11:37 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:11:41 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:11:45 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:11:49 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:11:53 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:11:57 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:01 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:05 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:09 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:13 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:17 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:21 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:25 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:29 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:33 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:37 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:41 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:45 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:49 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:53 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:12:57 volumio volumio[904]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats ....

I've removed the folder from the comment above, no change:

..... Oct 17 18:49:12 volumio mpd[604]: update: added NAS/elements2/Artist2 - Album2/Song2_xxx.mp3 Oct 17 18:49:12 volumio kernel: Unhandled fault: alignment fault (0x92000021) at 0x00000000ee74568f Oct 17 18:49:12 volumio systemd[1]: mpd.service: main process exited, code=killed, status=7/BUS Oct 17 18:49:12 volumio systemd[1]: Unit mpd.service entered failed state. Oct 17 18:49:13 volumio systemd[1]: mpd.service holdoff time over, scheduling restart. Oct 17 18:49:13 volumio systemd[1]: Stopping Music Player Daemon... Oct 17 18:49:13 volumio systemd[1]: Starting Music Player Daemon... Oct 17 18:49:13 volumio systemd[1]: Started Music Player Daemon. Oct 17 18:49:13 volumio mpd[1195]: zeroconf: No global port, disabling zeroconf Oct 17 18:49:15 volumio volumio[894]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:49:15 volumio volumio[894]: MPD error: Error: This socket has been ended by the other party Oct 17 18:49:15 volumio volumio[894]: MPD error: Error: This socket has been ended by the other party Oct 17 18:49:15 volumio volumio[894]: MPD error: Error: This socket has been ended by the other party Oct 17 18:49:17 volumio mpd[1195]: client: [0] opened from ::ffff:127.0.0.1:34438 Oct 17 18:49:17 volumio mpd[1195]: alsa_mixer: Failed to read mixer for 'alsa': failed to attach to SoftMaster: No such file or directory Oct 17 18:49:19 volumio volumio[894]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:49:19 volumio volumio[894]: MPD error: Error: This socket has been ended by the other party Oct 17 18:49:19 volumio volumio[894]: MPD error: Error: This socket has been ended by the other party Oct 17 18:49:19 volumio volumio[894]: MPD error: Error: This socket has been ended by the other party Oct 17 18:49:20 volumio mpd[1195]: client: [1] opened from ::ffff:127.0.0.1:34439 Oct 17 18:49:20 volumio mpd[1195]: client: [2] opened from ::ffff:127.0.0.1:34440 Oct 17 18:49:20 volumio mpd[1195]: client: [3] opened from ::ffff:127.0.0.1:34441 Oct 17 18:49:20 volumio volumio[894]: info: Oct 17 18:49:23 volumio volumio[894]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:49:24 volumio mpd[1195]: client: [4] opened from ::ffff:127.0.0.1:34442 Oct 17 18:49:24 volumio mpd[1195]: client: [5] opened from ::ffff:127.0.0.1:34443 Oct 17 18:49:24 volumio mpd[1195]: client: [6] opened from ::ffff:127.0.0.1:34444 Oct 17 18:49:24 volumio volumio[894]: info: Oct 17 18:49:27 volumio volumio[894]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:49:31 volumio volumio[894]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:49:35 volumio volumio[894]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:49:39 volumio volumio[894]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:49:43 volumio volumio[894]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:49:47 volumio volumio[894]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:49:51 volumio volumio[894]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:49:55 volumio volumio[894]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:49:59 volumio volumio[894]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 17 18:50:03 volumio volumio[894]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats

I'm back on VolumioRC2Fix-2016-07-31-odroidc2 now, which scanned through the directory without problems again...

I'm just trying Volumio 2.030 - same result:

Dec 01 20:00:36 volumio volumio[1568]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Dec 01 20:00:38 volumio volumio[1568]: info: CoreCommandRouter::executeOnPlugin: mpd , rescanDb Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438626] ControllerMpd::sendMpdCommand rescan Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438629] sending command... Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438634] ControllerMpd::sendMpdCommand status Dec 01 20:00:38 volumio volumio[1568]: info: Mpd Status Update: update Dec 01 20:00:38 volumio volumio[1568]: info: Dec 01 20:00:38 volumio volumio[1568]: [1480622438638] ---------------------------- MPD announces state update Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438641] parsing response... Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438644] sending command... Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438671] ControllerMpd::getState Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438671] ControllerMpd::sendMpdCommand status Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438673] sending command... Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438675] parsing response... Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438676] parsing response... Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438679] ControllerMpd::parseState Dec 01 20:00:38 volumio volumio[1568]: info: Command Router : Notfying DB Updatetrue Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438701] ControllerMpd::parseState Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438703] ControllerMpd::pushState Dec 01 20:00:38 volumio volumio[1568]: info: CoreCommandRouter::servicePushState Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438710] CoreStateMachine::syncState Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438712] CorePlayQueue::getTrack 0 Dec 01 20:00:38 volumio volumio[1568]: 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} Dec 01 20:00:38 volumio volumio[1568]: info: CURRENT POSITION 0 Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438715] CoreStateMachine::syncState stateService stop Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438716] CoreStateMachine::syncState currentStatus stop Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438722] CoreStateMachine::pushState Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438723] CoreStateMachine::getState Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438724] CorePlayQueue::getTrack 0 Dec 01 20:00:38 volumio volumio[1568]: info: CoreCommandRouter::volumioPushState Dec 01 20:00:38 volumio volumio[1568]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438727] InterfaceWebUI::pushState Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438753] No code Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438753] CoreStateMachine::pushState Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438754] CoreStateMachine::getState Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438754] CorePlayQueue::getTrack 0 Dec 01 20:00:38 volumio volumio[1568]: info: CoreCommandRouter::volumioPushState Dec 01 20:00:38 volumio volumio[1568]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438756] InterfaceWebUI::pushState Dec 01 20:00:38 volumio volumio[1568]: info: [1480622438777] ------------------------------ 140ms Dec 01 20:00:38 volumio volumio[1568]: info: Pushing Favourites {"service":"mpd","uri":"","favourite":false} Dec 01 20:00:38 volumio volumio[1568]: info: Pushing Favourites {"service":"mpd","uri":"","favourite":false} Dec 01 20:00:39 volumio mpd[1551]: update: added NAS/elements2/Artist1 - Album1/Song1_xxx.mp3 Dec 01 20:00:39 volumio mpd[1551]: update: added NAS/elements2/Artist1 - Album1/Song2_xxx.mp3 Dec 01 20:00:39 volumio mpd[1551]: update: added NAS/elements2/Artist1 - Album1/Song3_xxx.mp3 Dec 01 20:00:39 volumio mpd[1551]: update: added NAS/elements2/Artist1 - Album1/Song4_xxx.mp3 ... ... ... Dec 01 20:02:37 volumio mpd[1551]: update: added NAS/elements2/Artist100 - Album2/Song21_xxx.mp3 Dec 01 20:02:37 volumio mpd[1551]: update: added NAS/elements2/Artist100 - Album2/Song22_xxx.mp3 Dec 01 20:02:37 volumio mpd[1551]: update: added NAS/elements2/Artist100 - Album2/Song23_xxx.mp3 Dec 01 20:02:37 volumio kernel: Unhandled fault: alignment fault (0x92000021) at 0x00000000eec3ee67 Dec 01 20:02:37 volumio systemd[1]: mpd.service: main process exited, code=killed, status=7/BUS Dec 01 20:02:37 volumio systemd[1]: Unit mpd.service entered failed state. Dec 01 20:02:37 volumio systemd[1]: mpd.service holdoff time over, scheduling restart. Dec 01 20:02:37 volumio systemd[1]: Stopping Music Player Daemon... Dec 01 20:02:37 volumio systemd[1]: Starting Music Player Daemon... Dec 01 20:02:37 volumio systemd[1]: Started Music Player Daemon. Dec 01 20:02:37 volumio mpd[1676]: zeroconf: No global port, disabling zeroconf Dec 01 20:02:40 volumio volumio[1568]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 01 20:02:40 volumio volumio[1568]: MPD error: Error: This socket has been ended by the other party Dec 01 20:02:40 volumio volumio[1568]: MPD error: Error: This socket has been ended by the other party Dec 01 20:02:40 volumio volumio[1568]: MPD error: Error: This socket has been ended by the other party Dec 01 20:02:44 volumio volumio[1568]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 01 20:02:44 volumio volumio[1568]: MPD error: Error: This socket has been ended by the other party Dec 01 20:02:44 volumio volumio[1568]: MPD error: Error: This socket has been ended by the other party Dec 01 20:02:44 volumio volumio[1568]: MPD error: Error: This socket has been ended by the other party Dec 01 20:02:48 volumio volumio[1568]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 01 20:02:48 volumio volumio[1568]: assert.js:85 Dec 01 20:02:48 volumio volumio[1568]: throw new assert.AssertionError({ Dec 01 20:02:48 volumio volumio[1568]: ^ Dec 01 20:02:48 volumio volumio[1568]: AssertionError: false == true Dec 01 20:02:48 volumio volumio[1568]: at MpdClient.sendCommand (/volumio/node_modules/mpd/index.js:86:10) Dec 01 20:02:48 volumio volumio[1568]: at ControllerMpd.getMyCollectionStats (/volumio/app/plugins/music_service/mpd/index.js:2256:20) Dec 01 20:02:48 volumio volumio[1568]: at CoreCommandRouter.executeOnPlugin (/volumio/app/index.js:818:29) Dec 01 20:02:48 volumio volumio[1568]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1112:43) Dec 01 20:02:48 volumio volumio[1568]: at emitTwo (events.js:106:13) Dec 01 20:02:48 volumio volumio[1568]: at Socket.emit (events.js:191:7) Dec 01 20:02:48 volumio volumio[1568]: at Socket.onevent (/volumio/node_modules/socket.io/lib/socket.js:348:8) Dec 01 20:02:48 volumio volumio[1568]: at Socket.onpacket (/volumio/node_modules/socket.io/lib/socket.js:308:12) Dec 01 20:02:48 volumio volumio[1568]: at /volumio/node_modules/socket.io/lib/client.js:195:16 Dec 01 20:02:48 volumio volumio[1568]: at _combinedTickCallback (internal/process/next_tick.js:67:7) Dec 01 20:02:48 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE Dec 01 20:02:48 volumio systemd[1]: Unit volumio.service entered failed state. Dec 01 20:02:48 volumio systemd[1]: Starting dynamicswap.service... Dec 01 20:02:48 volumio systemd[1]: Started dynamicswap.service. Dec 01 20:02:48 volumio systemd[1]: volumio.service holdoff time over, scheduling restart. Dec 01 20:02:48 volumio systemd[1]: Starting dynamicswap.service... Dec 01 20:02:48 volumio systemd[1]: Started dynamicswap.service. Dec 01 20:02:48 volumio systemd[1]: Stopping Volumio Backend Module... Dec 01 20:02:48 volumio systemd[1]: Starting Volumio Backend Module... Dec 01 20:02:48 volumio systemd[1]: Started Volumio Backend Module. Dec 01 20:02:50 volumio volumio[1693]: info: ------------------------------------------- Dec 01 20:02:50 volumio volumio[1693]: info: ----- Volumio2 ---- Dec 01 20:02:50 volumio volumio[1693]: info: ------------------------------------------- Dec 01 20:02:50 volumio volumio[1693]: info: ----- System startup ---- Dec 01 20:02:50 volumio volumio[1693]: info: ------------------------------------------- Dec 01 20:02:50 volumio volumio[1693]: info: Plugin folders cleanup Dec 01 20:02:50 volumio volumio[1693]: info: Scanning into folder /volumio/app/plugins/ Dec 01 20:02:50 volumio volumio[1693]: info: Scanning category audio_interface Dec 01 20:02:50 volumio volumio[1693]: info: Scanning category miscellanea Dec 01 20:02:50 volumio volumio[1693]: info: Scanning category music_service Dec 01 20:02:50 volumio volumio[1693]: info: Scanning category plugins.json Dec 01 20:02:50 volumio volumio[1693]: info: Scanning category system_controller Dec 01 20:02:50 volumio volumio[1693]: info: Scanning category user_interface Dec 01 20:02:50 volumio volumio[1693]: info: Scanning into folder /data/plugins/ Dec 01 20:02:50 volumio volumio[1693]: info: Plugin folders cleanup completed Dec 01 20:02:50 volumio volumio[1693]: info: Loading plugins from folder /volumio/app/plugins/ Dec 01 20:02:50 volumio volumio[1693]: info: Loading plugins from folder /data/plugins/ Dec 01 20:02:50 volumio volumio[1693]: info: Loading plugin "system"... Dec 01 20:02:51 volumio volumio[1693]: info: Loading plugin "appearance"... Dec 01 20:02:51 volumio volumio[1693]: info: Loading plugin "network"... Dec 01 20:02:51 volumio volumio[1693]: info: Loading plugin "services"... Dec 01 20:02:51 volumio volumio[1693]: info: Loading plugin "alsa_controller"... Dec 01 20:02:51 volumio volumio[1693]: info: Loading plugin "volumio_command_line_client"... Dec 01 20:02:51 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 20:02:51 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 20:02:51 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 20:02:51 volumio volumio[1693]: info: Loading plugin "upnp"... Dec 01 20:02:51 volumio volumio[1693]: info: [1480622571385] Starting Upmpd Daemon Dec 01 20:02:51 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 01 20:02:51 volumio volumio[1693]: info: Loading plugin "mpd"... Dec 01 20:02:51 volumio volumio[1693]: info: Loading plugin "networkfs"... Dec 01 20:02:51 volumio volumio[1693]: Something is already mounted on /mnt/NAS/elements2 Dec 01 20:02:51 volumio volumio[1693]: info: Cannot mount NAS elements2 at system boot, trial number 1 ,retrying in 5 seconds Dec 01 20:02:51 volumio volumio[1693]: info: Loading plugin "alarm-clock"... Dec 01 20:02:51 volumio volumio[1693]: info: Loading plugin "airplay_emulation"... Dec 01 20:02:51 volumio volumio[1693]: info: [1480622571599] Starting Shairport Sync Dec 01 20:02:51 volumio volumio[1693]: info: Loading plugin "last_100"... Dec 01 20:02:51 volumio volumio[1693]: info: Loading plugin "webradio"... Dec 01 20:02:51 volumio mpd[1676]: client: [0] opened from ::ffff:127.0.0.1:52157 Dec 01 20:02:51 volumio mpd[1676]: client: [1] opened from ::ffff:127.0.0.1:52158 Dec 01 20:02:51 volumio mpd[1676]: client: [2] opened from ::ffff:127.0.0.1:52159 Dec 01 20:02:51 volumio mpd[1676]: client: [1] closed Dec 01 20:02:51 volumio mpd[1676]: client: [3] opened from ::ffff:127.0.0.1:52160 Dec 01 20:02:51 volumio mpd[1676]: client: [2] closed Dec 01 20:02:51 volumio mpd[1676]: client: [3] closed Dec 01 20:02:51 volumio mpd[1676]: alsa_mixer: Failed to read mixer for 'alsa': no such mixer control: PCM Dec 01 20:02:52 volumio volumio[1693]: info: Loading plugin "i2s_dacs"... Dec 01 20:02:52 volumio volumio[1693]: info: I2S DAC not set, start Auto-detection Dec 01 20:02:52 volumio volumio[1693]: info: Loading plugin "my_volumio"... Dec 01 20:02:52 volumio volumio[1693]: info: Loading plugin "volumiodiscovery"... Dec 01 20:02:52 volumio volumio[1693]: WARNING The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 01 20:02:52 volumio node[1693]: WARNING The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 01 20:02:52 volumio node[1693]: WARNING Please fix your application to use the native API of Avahi! Dec 01 20:02:52 volumio node[1693]: WARNING For more information see http://0pointer.de/avahi-compat?s=libdns_sd&e=node Dec 01 20:02:52 volumio node[1693]: WARNING The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 01 20:02:52 volumio node[1693]: WARNING Please fix your application to use the native API of Avahi! Dec 01 20:02:52 volumio node[1693]: WARNING For more information see http://0pointer.de/avahi-compat?s=libdns_sd&e=node&f=DNSServiceRegister Dec 01 20:02:52 volumio volumio[1693]: WARNING Please fix your application to use the native API of Avahi! Dec 01 20:02:52 volumio volumio[1693]: WARNING For more information see http://0pointer.de/avahi-compat?s=libdns_sd&e=node Dec 01 20:02:52 volumio volumio[1693]: WARNING The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 01 20:02:52 volumio volumio[1693]: WARNING Please fix your application to use the native API of Avahi! Dec 01 20:02:52 volumio volumio[1693]: WARNING For more information see http://0pointer.de/avahi-compat?s=libdns_sd&e=node&f=DNSServiceRegister Dec 01 20:02:52 volumio volumio[1693]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 01 20:02:52 volumio volumio[1693]: Discovery: StartAdv! undefined Dec 01 20:02:52 volumio volumio[1693]: Discovery: Started advertising... Volumio - undefined Dec 01 20:02:52 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 01 20:02:52 volumio volumio[1693]: info: Loading plugin "albumart"... Dec 01 20:02:52 volumio volumio[1693]: info: Plugin example_plugin is not enabled Dec 01 20:02:52 volumio volumio[1693]: info: Loading plugin "updater_comm"... Dec 01 20:02:52 volumio volumio[1693]: info: Plugin mpdemulation is not enabled Dec 01 20:02:52 volumio volumio[1693]: info: Loading plugin "websocket"... Dec 01 20:02:52 volumio volumio[1693]: info: START PLUGINS Dec 01 20:02:52 volumio volumio[1693]: PLUGIN START: appearance Dec 01 20:02:52 volumio volumio[1693]: PLUGIN START: last_100 Dec 01 20:02:52 volumio volumio[1693]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 01 20:02:52 volumio volumio[1693]: info: [1480622572581] CoreMusicLibrary::Adding element Last_100 Dec 01 20:02:52 volumio volumio[1693]: PLUGIN START: webradio Dec 01 20:02:52 volumio volumio[1693]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 01 20:02:52 volumio volumio[1693]: info: [1480622572591] CoreMusicLibrary::Adding element Webradio Dec 01 20:02:52 volumio volumio[1693]: PLUGIN START: my_volumio Dec 01 20:02:52 volumio volumio[1693]: info: Loading i18n strings for locale en Dec 01 20:02:52 volumio volumio[1693]: Updating browse sources language Dec 01 20:02:52 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 20:02:52 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getAlsaCards Dec 01 20:02:52 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 20:02:52 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 20:02:52 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 20:02:52 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 20:02:52 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 20:02:52 volumio volumio[1693]: info: BOOT COMPLETED Dec 01 20:02:52 volumio volumio[1693]: Express server listening on port 3000 Dec 01 20:02:52 volumio volumio[1693]: Volumio Calling Home Dec 01 20:02:52 volumio kernel: [aml-i2s-dai]i2s dma ffffff800048e000,phy addr 1611005952,mode 0,ch 2 Dec 01 20:02:52 volumio kernel: ----aml_hw_iec958_init,runtime->rate=44100,sample_rate=5-- Dec 01 20:02:52 volumio kernel: aml_set_spdif_clk rate Dec 01 20:02:52 volumio kernel: divider=22,frac=13030400,SDMval=2364 Dec 01 20:02:52 volumio kernel: set normal 512 fs /4 fs Dec 01 20:02:52 volumio kernel: iec958 mode PCM16 Dec 01 20:02:52 volumio kernel: IEC958 16bit Dec 01 20:02:52 volumio volumio[1693]: info: [1480622572731] CoreStateMachine::resetVolumioState Dec 01 20:02:52 volumio volumio[1693]: info: [1480622572734] CoreStateMachine::getcurrentVolume Dec 01 20:02:52 volumio volumio[1693]: info: CoreCommandRouter::volumioRetrievevolume Dec 01 20:02:52 volumio kernel: hdmitx: audio: aout notify rate 44100 Dec 01 20:02:52 volumio kernel: hdmitx: audio: aout notify size 16 Dec 01 20:02:52 volumio kernel: 958 with i2s Dec 01 20:02:52 volumio kernel: aiu i2s playback enable Dec 01 20:02:52 volumio kernel: audio_hw_958_enable 1 Dec 01 20:02:52 volumio volumio[1693]: info: [1480622572759] CoreStateMachine::updateTrackBlock Dec 01 20:02:52 volumio volumio[1693]: info: [1480622572760] CorePlayQueue::getTrackBlock Dec 01 20:02:52 volumio volumio[1693]: info: Cannot read play queue form file Dec 01 20:02:52 volumio volumio[1693]: info: MPD running with PID1676 ,establishing connection Dec 01 20:02:52 volumio sudo[1754]: pam_unix(sudo:auth): conversation failed Dec 01 20:02:52 volumio sudo[1754]: pam_unix(sudo:auth): auth could not identify password for [volumio] Dec 01 20:02:52 volumio volumio[1693]: info: Setting Device type: Odroid-C2 Dec 01 20:02:52 volumio mpd[1676]: client: [4] opened from ::ffff:127.0.0.1:52162 Dec 01 20:02:53 volumio volumio[1693]: info: Cannot read I2C interface or I2C interface not presentError: Command failed: /usr/bin/sudo /usr/sbin/i2cdetect -y 1 Dec 01 20:02:53 volumio volumio[1693]: We trust you have received the usual lecture from the local System Dec 01 20:02:53 volumio volumio[1693]: Administrator. It usually boils down to these three things: Dec 01 20:02:53 volumio volumio[1693]: #1) Respect the privacy of others. Dec 01 20:02:53 volumio volumio[1693]: #2) Think before you type. Dec 01 20:02:53 volumio volumio[1693]: #3) With great power comes great responsibility. Dec 01 20:02:53 volumio volumio[1693]: sudo: no tty present and no askpass program specified Dec 01 20:02:53 volumio volumio[1693]: null Dec 01 20:02:53 volumio volumio[1693]: info: [1480622573191] VolumeController:: Volume=undefined Mute =undefined Dec 01 20:02:53 volumio volumio[1693]: info: [1480622573196] CoreStateMachine::pushState Dec 01 20:02:53 volumio volumio[1693]: info: [1480622573199] CoreStateMachine::getState Dec 01 20:02:53 volumio volumio[1693]: info: [1480622573201] CorePlayQueue::getTrack 0 Dec 01 20:02:53 volumio volumio[1693]: info: CoreCommandRouter::volumioPushState Dec 01 20:02:53 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 01 20:02:53 volumio volumio[1693]: info: [1480622573210] InterfaceWebUI::pushState Dec 01 20:02:53 volumio volumio[1693]: info: Pushing Favourites {"service":"mpd","uri":"","favourite":false} Dec 01 20:02:53 volumio volumio[1693]: info: Dec 01 20:02:53 volumio sudo[1758]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart airplay Dec 01 20:02:53 volumio sudo[1758]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 20:02:53 volumio systemd[1]: Stopping ShairportSync AirTunes receiver... Dec 01 20:02:53 volumio shairport-sync[1640]: exit... Dec 01 20:02:53 volumio systemd[1]: Starting ShairportSync AirTunes receiver... Dec 01 20:02:53 volumio systemd[1]: Started ShairportSync AirTunes receiver. Dec 01 20:02:53 volumio shairport-sync[1763]: startup Dec 01 20:02:53 volumio sudo[1761]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 01 20:02:53 volumio sudo[1758]: pam_unix(sudo:session): session closed for user root Dec 01 20:02:53 volumio sudo[1761]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 20:02:53 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Dec 01 20:02:53 volumio sudo[1761]: pam_unix(sudo:session): session closed for user root Dec 01 20:02:53 volumio volumio[1693]: info: [1480622573422] Shairport-Sync Started Dec 01 20:02:53 volumio volumio[1693]: Discovery: adding a32ab84b-9e50-4b91-9c22-3b23e073f03a Dec 01 20:02:53 volumio volumio[1693]: info: mDNS: Found device Volumio Dec 01 20:02:53 volumio volumio[1693]: info: Upmpdcli Daemon Started Dec 01 20:02:53 volumio volumio[1693]: info: Volumio called home Dec 01 20:02:53 volumio volumio[1693]: success! Dec 01 20:02:55 volumio volumio[1693]: info: CoreCommandRouter::volumioGetState Dec 01 20:02:55 volumio volumio[1693]: info: [1480622575732] CoreStateMachine::getState Dec 01 20:02:55 volumio volumio[1693]: info: [1480622575733] CorePlayQueue::getTrack 0 Dec 01 20:02:55 volumio volumio[1693]: info: Dec 01 20:02:55 volumio volumio[1693]: [1480622575735] ---------------------------- Client requests Volumio state Dec 01 20:02:55 volumio volumio[1693]: info: [1480622575739] InterfaceWebUI::pushState Dec 01 20:02:55 volumio volumio[1693]: info: [1480622575760] ------------------------------ 29ms Dec 01 20:02:56 volumio volumio[1693]: Something is already mounted on /mnt/NAS/elements2 Dec 01 20:02:56 volumio volumio[1693]: info: Cannot mount NAS elements2 at system boot, trial number 2 ,retrying in 5 seconds Dec 01 20:02:57 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 01 20:02:57 volumio volumio[1693]: info: CoreCommandRouter::volumioGetState Dec 01 20:02:57 volumio volumio[1693]: info: [1480622577606] CoreStateMachine::getState Dec 01 20:02:57 volumio volumio[1693]: info: [1480622577607] CorePlayQueue::getTrack 0 Dec 01 20:02:57 volumio volumio[1693]: info: Dec 01 20:02:57 volumio volumio[1693]: [1480622577607] ---------------------------- Client requests Volumio state Dec 01 20:02:57 volumio volumio[1693]: info: [1480622577609] Listing playlists Dec 01 20:02:57 volumio volumio[1693]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 01 20:02:57 volumio volumio[1693]: Plugin multiroom or method getMultiroom not found Dec 01 20:02:57 volumio volumio[1693]: info: Dec 01 20:02:57 volumio volumio[1693]: [1480622577627] ---------------------------- Client requests Menu Items Dec 01 20:02:57 volumio volumio[1693]: info: [1480622577628] InterfaceWebUI::pushState Dec 01 20:02:57 volumio volumio[1693]: info: [1480622577647] ------------------------------ 42ms Dec 01 20:02:57 volumio volumio[1693]: info: [1480622577672] ------------------------------ 45ms Dec 01 20:02:57 volumio kernel: aiu i2s playback disable Dec 01 20:02:57 volumio kernel: audio_hw_958_enable 0 Dec 01 20:03:01 volumio volumio[1693]: Something is already mounted on /mnt/NAS/elements2 Dec 01 20:03:01 volumio volumio[1693]: info: Cannot mount NAS elements2 at system boot, trial number 3 ,retrying in 5 seconds Dec 01 20:03:06 volumio volumio[1693]: Something is already mounted on /mnt/NAS/elements2 Dec 01 20:03:06 volumio volumio[1693]: info: Cannot mount NAS elements2 at system boot, trial number 4 ,retrying in 5 seconds Dec 01 20:03:11 volumio volumio[1693]: Something is already mounted on /mnt/NAS/elements2 Dec 01 20:03:11 volumio volumio[1693]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Dec 01 20:04:11 volumio systemd[1]: Starting Cleanup of Temporary Directories... Dec 01 20:04:11 volumio systemd[1]: Started Cleanup of Temporary Directories.

Here's a screenshot from MyMusic:

unbenannt

as per request for another problem:

volumio@volumio:~$ id
uid=1000(volumio) gid=1000(volumio) groups=1000(volumio),4(adm),20(dialout),24(cdrom),25(floppy),29(audio),30(dip),44(video),46(plugdev),102(netdev)
volumio@volumio:~$ sudo -l
Matching Defaults entries for volumio on localhost:
    env_reset, mail_badpass, secure_path=/usr/local/sbin\:/usr/local/bin\:/usr/sbin\:/usr/bin\:/sbin\:/bin

User volumio may run the following commands on localhost:
    (ALL) ALL
    (ALL) NOPASSWD: /sbin/poweroff, /sbin/shutdown, /sbin/reboot, /sbin/halt, /bin/systemctl, /usr/bin/apt-get, /usr/sbin/update-rc.d, /usr/bin/gpio, /bin/mount, /bin/umount/, /sbin/iwconfig, /sbin/iwlist,
        /sbin/ifconfig, /usr/bin/killall, /bin/ip, /usr/sbin/service, /etc/init.d/netplug, /bin/journalctl, /bin/chmod, /sbin/ethtool, /usr/sbin/alsactl, /bin/tar, /usr/bin/dtoverlay, /sbin/dhclient,
        /usr/sbin/i2cdetect, /sbin/dhcpcd, /usr/bin/alsactl, /bin/mv, /sbin/iw, /bin/hostname
volumio@volumio:~$

kernel: Unhandled fault: alignment fault (0x92000021) at 0x00000000eec3ee67
mpd.service: main process exited, code=killed, status=7/BUS

Looks like a problem with the mpd installed for your platform. No idea how to fix that. I don't think it is anything to do with sudo this time. I wonder if memory is a limitation though. You could test that by watching the memory usage during the scan, until it crashes.

volumio$ while true; do (date; free -l) | tee -a mem.log; sleep 2; done

What you are looking for is the output at the time journalctl shows mpd exiting - is free memory low?

I just tested again:

Memory usage before scanning:

volumio@volumio:~$ while true; do (date; free -l) | tee -a mem.log; sleep 2; done Sat Dec 3 17:55:37 UTC 2016 total used free shared buffers cached Mem: 1758728 605404 1153324 5860 72064 250560 Low: 1758728 605404 1153324 High: 0 0 0 -/+ buffers/cache: 282780 1475948

Scanning is crashing again:

Dec 03 17:58:02 volumio mpd[700]: update: added NAS/elements2/.......mp3 Dec 03 17:58:02 volumio kernel: Unhandled fault: alignment fault (0x92000021) at 0x00000000ee73ee67 Dec 03 17:58:02 volumio systemd[1]: mpd.service: main process exited, code=killed, status=7/BUS Dec 03 17:58:02 volumio systemd[1]: Unit mpd.service entered failed state. Dec 03 17:58:03 volumio systemd[1]: mpd.service holdoff time over, scheduling restart.

Memory usage during crash:

Sat Dec 3 17:58:00 UTC 2016 total used free shared buffers cached Mem: 1758728 716884 1041844 5864 72512 357572 Low: 1758728 716884 1041844 High: 0 0 0 -/+ buffers/cache: 286800 1471928 Swap: 0 0 0 Sat Dec 3 17:58:02 UTC 2016 total used free shared buffers cached Mem: 1758728 718372 1040356 5864 72516 358968 Low: 1758728 718372 1040356 High: 0 0 0 -/+ buffers/cache: 286888 1471840 Swap: 0 0 0 Sat Dec 3 17:58:04 UTC 2016 total used free shared buffers cached Mem: 1758728 641200 1117528 5864 72516 283348 Low: 1758728 641200 1117528 High: 0 0 0 -/+ buffers/cache: 285336 1473392 Swap: 0 0 0 Sat Dec 3 17:58:06 UTC 2016 total used free shared buffers cached Mem: 1758728 610076 1148652 5864 72516 251600 Low: 1758728 610076 1148652 High: 0 0 0 -/+ buffers/cache: 285960 1472768 Swap: 0 0 0 Sat Dec 3 17:58:08 UTC 2016 total used free shared buffers cached Mem: 1758728 611052 1147676 5864 72520 251596 Low: 1758728 611052 1147676 High: 0 0 0 -/+ buffers/cache: 286936 1471792 Swap: 0 0 0

Doesn't seem to be related to memory to me? Any other hints?

Maybe #890 could be related? No Raspberry again!

Other findings after scanning a few times:

Scanning crashes always with exactly the same file, multiple times
If the folder containing the file is removed, scanning crashes with another file in the next folder, multiple times again
It doesn't always crash with the same file-count: sometimes the 4th file, sometimes the 9th...

... i got curious and tried this:

I reduced the library to 1 folder (= 1 album), 13 tracks, that were scanned ok
adding to complete count of 4 folders, 50 tracks, scanning is ok
8 albums, 89 tracks ok
11 albums, 133 tracks ok
22 albums, 267 tracks ok
24 albums, 281 tracks ok
adding up to 35 folders is crashing at 27 albums, 300 tracks (last displayed), but no complete restart of interface, count on MyMusic states 24 albums, 281 tracks.
adding up to 134 folders is crashing at 78 albums, 830 tracks (last displayed), but no complete restart of interface, count on MyMusic states 24 albums, 281 tracks.
adding up to 240 folders is crashing at 139 albums, 1590 tracks (last displayed), but no complete restart of interface, count on MyMusic states 24 albums, 281 tracks.
adding up to 322 folders is crashing at 176 albums, 1974 tracks (last displayed), but no complete restart of interface, count on MyMusic states 24 albums, 281 tracks.

Scanning stopped with the same file as with 240 folders, so i remove this folder and try again:

321 folders now, crashing at 176 albums, 1985 tracks (last displayed), but no complete restart of interface, count on MyMusic states 24 albums, 281 tracks.

Removing the last folder again:

320 folders now, crashing at 175 albums, 1965 tracks (last displayed), but no complete restart of interface, count on MyMusic states 24 albums, 281 tracks.

I have to stop the fun now ;)

One last scan with the complete library:

664 folders, crashing at 110 albums and 1233 tracks , now WITH complete reset of the UI

Here's the systemctl-output from the crashes WITH and WITHOUT UI-reset:

scanning failed without UI-reset.txt scanning failed with UI.txt

I hope, somebody can get some info or hints out of this, to find the problem! I'm glad to help in testing, if needed...

Is anyone currently looking into this? Problem still present in gkkpch's Volumiodev042 image.

Yes, I've spotted the bug yesterday. It relates to ffmpeg, so we need to compile a new version

This affects me, too. I am running 2.041 on a RPi 3 connected to my NAS via cifs. Took the same steps as above to reproduce. The issue is also occurring when connecting via nfs.

Sorry guys, the problem is still persistent on OdroidC2 v2.118:

Mar 14 19:28:42 volumio mpd[1520]: update: NAS/elements2/Artist2 - Album2/Song2_xxx.mp3 Mar 14 19:28:42 volumio mpd[1520]: update: NAS/elements2/Artist2 - Album2/Song2_xxx.mp3 Mar 14 19:28:42 volumio kernel: Unhandled fault: alignment fault (0x92000021) at 0x00000000ef43e7ff Mar 14 19:28:42 volumio systemd[1]: mpd.service: main process exited, code=killed, status=7/BUS Mar 14 19:28:42 volumio systemd[1]: Unit mpd.service entered failed state. Mar 14 19:28:42 volumio systemd[1]: mpd.service holdoff time over, scheduling restart. Mar 14 19:28:42 volumio systemd[1]: Stopping Music Player Daemon... Mar 14 19:28:42 volumio systemd[1]: Starting Music Player Daemon... Mar 14 19:28:42 volumio systemd[1]: Started Music Player Daemon. Mar 14 19:28:43 volumio mpd[1676]: zeroconf: No global port, disabling zeroconf Mar 14 19:28:43 volumio volumio[1553]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Mar 14 19:28:43 volumio volumio[1553]: error: MPD error: Error: This socket has been ended by the other party Mar 14 19:28:43 volumio volumio[1553]: error: MPD error: Error: This socket has been ended by the other party Mar 14 19:28:43 volumio volumio[1553]: error: MPD error: Error: This socket has been ended by the other party Mar 14 19:28:47 volumio volumio[1553]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Mar 14 19:28:47 volumio volumio[1553]: error: MPD error: Error: This socket has been ended by the other party Mar 14 19:28:47 volumio volumio[1553]: error: MPD error: Error: This socket has been ended by the other party Mar 14 19:28:47 volumio volumio[1553]: error: MPD error: Error: This socket has been ended by the other party Mar 14 19:28:51 volumio volumio[1553]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Mar 14 19:28:51 volumio volumio[1553]: assert.js:85 Mar 14 19:28:51 volumio volumio[1553]: throw new assert.AssertionError({ Mar 14 19:28:51 volumio volumio[1553]: ^ Mar 14 19:28:51 volumio volumio[1553]: AssertionError: false == true Mar 14 19:28:51 volumio volumio[1553]: at MpdClient.sendCommand (/volumio/node_modules/mpd/index.js:86:10) Mar 14 19:28:51 volumio volumio[1553]: at ControllerMpd.getMyCollectionStats (/volumio/app/plugins/music_service/mpd/index.js:2317:20) Mar 14 19:28:51 volumio volumio[1553]: at CoreCommandRouter.executeOnPlugin (/volumio/app/index.js:954:29) Mar 14 19:28:51 volumio volumio[1553]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1132:43) Mar 14 19:28:51 volumio volumio[1553]: at emitTwo (events.js:106:13) Mar 14 19:28:51 volumio volumio[1553]: at Socket.emit (events.js:191:7) Mar 14 19:28:51 volumio volumio[1553]: at Socket.onevent (/volumio/node_modules/socket.io/lib/socket.js:348:8) Mar 14 19:28:51 volumio volumio[1553]: at Socket.onpacket (/volumio/node_modules/socket.io/lib/socket.js:308:12) Mar 14 19:28:51 volumio volumio[1553]: at /volumio/node_modules/socket.io/lib/client.js:195:16 Mar 14 19:28:51 volumio volumio[1553]: at _combinedTickCallback (internal/process/next_tick.js:67:7) Mar 14 19:28:51 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE Mar 14 19:28:51 volumio systemd[1]: Unit volumio.service entered failed state. Mar 14 19:28:51 volumio systemd[1]: Starting dynamicswap.service... Mar 14 19:28:51 volumio systemd[1]: Started dynamicswap.service. Mar 14 19:28:51 volumio systemd[1]: volumio.service holdoff time over, scheduling restart. Mar 14 19:28:51 volumio systemd[1]: Starting dynamicswap.service... Mar 14 19:28:51 volumio systemd[1]: Started dynamicswap.service. Mar 14 19:28:51 volumio systemd[1]: Stopping Volumio Backend Module... Mar 14 19:28:51 volumio systemd[1]: Starting Volumio Backend Module... Mar 14 19:28:51 volumio systemd[1]: Started Volumio Backend Module. Mar 14 19:28:53 volumio volumio[1700]: info: ------------------------------------------- Mar 14 19:28:53 volumio volumio[1700]: info: ----- Volumio2 ---- Mar 14 19:28:53 volumio volumio[1700]: info: ------------------------------------------- Mar 14 19:28:53 volumio volumio[1700]: info: ----- System startup ---- Mar 14 19:28:53 volumio volumio[1700]: info: -------------------------------------------

This helps quite a bit, thanks for the posting.

As before: I'm glad to help in testing, if needed...

I tried deleting all embeded artwork with no success according to this thread: https://volumio.org/forum/volumio2-beta-indexing-music-library-fail-t3943.html

would it be possible to find out, which specific file crashed the update process?

Mar 14 19:28:42 volumio mpd[1520]: update: NAS/elements2/Artist2 - Album2/Song11_xxx.mp3 Mar 14 19:28:42 volumio mpd[1520]: update: NAS/elements2/Artist2 - Album2/Song12_xxx.mp3 Mar 14 19:28:42 volumio kernel: Unhandled fault: alignment fault (0x92000021) at 0x00000000ef43e7ff

now it seems, that the log is written after successfull update (Artist2 - Album2/Song12_xxx.mp3). i don't know, which is the next file that is being scanned...

would it be possible to add an update-start-log? where would i need to change something for a log like this:

Mar 14 19:28:42 volumio mpd[1520]: update start: NAS/elements2/Artist2 - Album2/Song11_xxx.mp3 Mar 14 19:28:42 volumio mpd[1520]: update success: NAS/elements2/Artist2 - Album2/Song11_xxx.mp3 Mar 14 19:28:42 volumio mpd[1520]: update start: NAS/elements2/Artist2 - Album2/Song12_xxx.mp3 Mar 14 19:28:42 volumio mpd[1520]: update success: NAS/elements2/Artist2 - Album2/Song12_xxx.mp3

I may be wrong about this but I think that would require a code change to mpd. Which is possible, as mpd is built specifically for volumio. Maybe upstream would even take the patch...

The log entries you see (mpd[1520]) are coming from the 'mpd' program, running as process number 1520. I think that all volumio does is ask mpd to do a 'scan' or an 'update scan' and leaves mpd to get on with it.

However it is reasonable to assume the directory is traversed in the normal sort order for the locale being used (POSIX I think), so next file will be NAS/elements2/Artist2 - Album2/Song13_xxx.mp3, no? Here are a couple of things to try to confirm this.

LC_ALL=POSIX ls '/mnt/NAS/elements2/Artist2 - Album2/' - what file is coming next?
LC_ALL=POSIX ls -lu '/mnt/NAS/elements2/Artist2 - Album2/' - right after a crash. The first file listed should be the one that was the most recently accessed, ie the one that caused the crash. If there is a tie you might be able to use 'stat' to get sub-second access timestamp:
```
$ cd  '/mnt/NAS/elements2/Artist2 - Album2/'
$ stat -c '%X %n' * | sort -rn |head  # top 10 suspects
$ stat suspect1.mp3
$ stat suspect2.mp3
...etc
```
Of course this is a bit trickier if Song12 is the last on that album, but you may be able to figure out the next-accessed directory with ls -uld /mnt/NAS/elements2/

After dividing the library and scanning, dividing again and scanning again, and again ... I finally found the problem for the crashes: mpd-update didn't like some (not all) of the mpc-files I had in the library...

@RastaX Thanks for your updates. I tried removing all mpc files from my music library blindly but unfortunately the problem still persists. After a bit more digging around, I added the following to my /etc/mpd.conf: decoder { plugin "ffmpeg" enabled "no" } That seems to have solved the issue. So the problem is actually with ffmpeg as @volumio pointed out earlier. Now I'm just wondering if /etc/mpd.conf is handled by volumio in any way so it might get overwritten at some point.

I experience the same issue but adding decoder { plugin "ffmpeg" enabled "no" } doesn't has any effect. What else could I try to solve the issue?

Library scanning problem (alignment fault (0x92000021)) resolved in v2.166, released 11/05/17

Right, 2.166 solved the problem. Thank you. Perhaps you want to close this issue.

volumio / Volumio2

v2.002, odroid: Scanning of local music library crashes #777