Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
RastaX opened this issue Oct 17, 2016 · 24 comments
Closed

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

RastaX opened this issue Oct 17, 2016 · 24 comments

Comments

@RastaX
Copy link

RastaX commented Oct 17, 2016

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!

@RastaX
Copy link
Author

RastaX commented Oct 17, 2016

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
....

@RastaX
Copy link
Author

RastaX commented Oct 17, 2016

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

@RastaX
Copy link
Author

RastaX commented Oct 21, 2016

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

@RastaX
Copy link
Author

RastaX commented Dec 1, 2016

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.

@RastaX
Copy link
Author

RastaX commented Dec 1, 2016

Here's a screenshot from MyMusic:

unbenannt

@RastaX
Copy link
Author

RastaX commented Dec 1, 2016

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:~$

@xipmix
Copy link
Contributor

xipmix commented Dec 3, 2016

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?

@RastaX
Copy link
Author

RastaX commented Dec 3, 2016

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?

@RastaX
Copy link
Author

RastaX commented Dec 3, 2016

Maybe #890 could be related?
No Raspberry again!

@RastaX
Copy link
Author

RastaX commented Dec 3, 2016

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...

@chsims1
Copy link

chsims1 commented Jan 26, 2017

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

@volumio
Copy link
Owner

volumio commented Jan 26, 2017

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

@fabiangr
Copy link

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.

@RastaX
Copy link
Author

RastaX commented Mar 14, 2017

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: -------------------------------------------

@xipmix
Copy link
Contributor

xipmix commented Mar 14, 2017

This helps quite a bit, thanks for the posting.

@RastaX
Copy link
Author

RastaX commented Mar 15, 2017

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

@RastaX
Copy link
Author

RastaX commented Mar 18, 2017

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

@RastaX
Copy link
Author

RastaX commented Mar 18, 2017

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

@xipmix
Copy link
Contributor

xipmix commented Mar 18, 2017

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.

  1. LC_ALL=POSIX ls '/mnt/NAS/elements2/Artist2 - Album2/' - what file is coming next?
  2. 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/

@RastaX
Copy link
Author

RastaX commented Mar 19, 2017

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...

@fabiangr
Copy link

@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.

@jans23
Copy link

jans23 commented May 11, 2017

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?

@chsims1
Copy link

chsims1 commented May 12, 2017

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

@jans23
Copy link

jans23 commented May 12, 2017

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

@volumio volumio closed this as completed Jun 2, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants