Login at Kodi Home

novoid · (This post was last modified: 2016-09-28, 19:10 by novoid.)

Hi!

Raspberry Pi 2 (SD has couple of GB free space)
LibreELEC (official) - Version: 7.0.2 (ARM; migrated from OpenElec)
Kodi: 16.1
mp3 files are located on a NFS share and not on Kodi directly

When I try to sync my Yatse Android remote app, I get sync errors. I analyzed this issue and found the culprit within Kodi:

Code:
18:24:14 393.306519 T:1725739936   ERROR: GetArtistsByWhere - out of memory getting listing (got 0)

18:24:14 393.307495 T:1725739936   ERROR: GetArtistsByWhere failed

I already removed MyMusic56.db and rebooted. This did not help :-(

I noticed that I don't have a music library although I see the update process running after each boot (as I configured).

When updating manually:

Code:
01:37 2636.425781 T:1609331616 WARNING: Process directory 'nfs://192.168.2.42/home/user/mp3/library/The Who/Meaty Beaty Big And Bouncy/' does not exist - skipping scan.

01:40 2639.768799 T:1771525024   ERROR: Failed to open(//The Who/Meaty Beaty Big And Bouncy/) opendir call failed with "NFS: Lookup of /The Who/Meaty Beaty Big And Bouncy failed with NFS3ERR_NOENT(-2)"

01:40 2639.769043 T:1771525024   ERROR: GetDirectory - Error getting nfs://192.168.2.42/home/user/mp3/library/The Who/Meaty Beaty Big And Bouncy/

01:43 2641.998291 T:1609331616  NOTICE: My Music: Scanning for music info using worker thread, operation took 00:5819:01:43 2642.085449 T:1963413504 WARNING: CreateLoader - unsupported protocol(sources) in sources://music.tbn

02:04 2663.692383 T:1963413504 WARNING: Previous line repeats 1 times.

02:04 2663.692627 T:1963413504   ERROR: SQL: [MyMusic56.db] The database disk image is malformed

                                            Query: select count(idSong) as NumSongs from songview

02:04 2663.692871 T:1963413504   ERROR: GetSongsCount() failed

02:05 2664.010010 T:1609331616   ERROR: GetRecentlyAddedAlbums failed

02:05 2664.144043 T:1609331616   ERROR: SQL: [MyMusic56.db] The database disk image is malformed

                                            Query: SELECT count(1) FROM songview LIMIT 1

02:05 2664.144287 T:1609331616   ERROR: GetSingleValue - failed on query 'SELECT count(1) FROM songview LIMIT 1'

02:05 2664.324463 T:1609331616   ERROR: SQL: [MyMusic56.db] The database disk image is malformed

                                            Query: SELECT count(distinct strAlbum) FROM songview LIMIT 1

02:05 2664.324707 T:1609331616   ERROR: GetSingleValue - failed on query 'SELECT count(distinct strAlbum) FROM songview LIMIT 1'

02:05 2664.558594 T:1609331616   ERROR: SQL: [MyMusic56.db] The database disk image is malformed

                                            Query: SELECT count(distinct strArtists) FROM songview LIMIT 1

02:05 2664.558838 T:1609331616   ERROR: GetSingleValue - failed on query 'SELECT count(distinct strArtists) FROM songview LIMIT 1'

03:21 2740.605225 T:1963413504  NOTICE: NFS is idle. Closing the remaining connections.

04:46 2824.827881 T:1963413504 WARNING: CreateLoader - unsupported protocol(sources) in sources://music.tbn

05:57 2896.789795 T:1609331616 WARNING: Process directory 'nfs://192.168.2.42/home/user/mp3/library/The Who/Meaty Beaty Big And Bouncy/' does not exist - skipping scan.

05:58 2897.347900 T:1771525024   ERROR: Failed to open(//The Who/Meaty Beaty Big And Bouncy/) opendir call failed with "NFS: Lookup of /The Who/Meaty Beaty Big And Bouncy failed with NFS3ERR_NOENT(-2)"

05:58 2897.348389 T:1771525024   ERROR: GetDirectory - Error getting nfs://192.168.2.42/home/user/mp3/library/The Who/Meaty Beaty Big And Bouncy/

06:00 2899.547363 T:1609331616  NOTICE: My Music: Scanning for music info using worker thread, operation took 00:58

06:00 2899.613281 T:1963413504 WARNING: CreateLoader - unsupported protocol(sources) in sources://music.tbn

Although I removed MyMusic56.db and rebooted, I get "The database disk image is malformed" again? Hm, something's fishy here.

Since I could not find anything via my search engine nor the search of this forum, I need your help to fix my Kodi.

**popcornmix** · 2016-09-28, 19:47

Enable debug logging. Delete Music56.db. reboot. Post the complete debug log to a paste site (e.g. pastebin.org) and post a link to it here.

Milhouse · 2016-09-28, 20:47

Are you running out of disk space?

Run in ssh:

Code:
df -h | pastebinit

and paste the resulting URL.

novoid · 2016-09-29, 09:41

(2016-09-28, 20:47)Milhouse Wrote: Are you running out of disk space?

Run in ssh:

Code:
df -h | pastebinit
and paste the resulting URL.

Good guess. However, as I wrote in my first line of content:

Quote:SD has couple of GB free space

Milhouse · 2016-09-29, 09:49

I guess we'll have to take your word for it.

Then something (another add-on, a separate process, or maybe filesystem corruption) is trashing your - presumably, as we've not yet seen a full debug log - SQLite databases.

It would be helpful if you provided evidence of your storage and a full debug log, as requested.

novoid · 2016-09-29, 11:52

(2016-09-28, 19:47)popcornmix Wrote: Enable debug logging. Delete Music56.db. reboot. Post the complete debug log to a paste site (e.g. pastebin.org) and post a link to it here.

To make sure, nothing is filling up my disk space:

Code:
PlayPi:~/.kodi/temp # df -h 

Filesystem                Size      Used Available Use% Mounted on

devtmpfs                363.4M         0    363.4M   0% /dev

/dev/mmcblk0p1          255.7M    127.6M    128.1M  50% /flash

/dev/mmcblk0p2            6.9G    484.3M      6.5G   7% /storage

/dev/loop0              117.9M    117.9M         0 100% /

tmpfs                   368.5M         0    368.5M   0% /dev/shm

tmpfs                   368.5M      5.8M    362.7M   2% /run

tmpfs                   368.5M         0    368.5M   0% /sys/fs/cgroup

tmpfs                   368.5M    236.0K    368.3M   0% /var

tmpfs                   368.5M         0    368.5M   0% /tmp

PlayPi:~/.kodi/temp #

kodi.log from the reboot with deleted MyMusic56.db: http://sprunge.us/fdMH

I deleted some redundant lines ([...]) and anonymized some music folders.

In my opinion, the crucial part is:

Code:
11:22:26  15.936304 T:1963278336   ERROR: SQL: [MyMusic56.db] The database disk image is malformed

                                            Query: CREATE INDEX idxSong ON song(strTitle)

11:22:26  15.940744 T:1963278336   ERROR: Exception updating database MyMusic56 from version 52 to 56

11:22:26  15.940950 T:1963278336   ERROR: Error updating database MyMusic56 from version 52 to 56

I noticed, that there is MyMusic52.db as well. To my astonishment, this file seems to be used as a substitute when MyMusic56.db is missing.

So I moved MyMusic* out of the way and rebooted again.

MyMusic56.db is re-generated but obviously much smaller.

Still no library in my Music folder. So I did a re-index:

Code:
46:34 330.484894 T:1857000352   DEBUG: PushCecKeypress - received key a9 duration 0 (rep:0 size:0)

46:34 330.485168 T:1857000352   DEBUG: PushCecKeypress - added key a9

46:34 330.506287 T:1962909696   DEBUG: OnKey: 169 (0xa9) pressed, action is Left

46:35 330.665649 T:1857000352   DEBUG: PushCecKeypress - received key a9 duration 181 (rep:0 size:0)

46:35 330.665924 T:1857000352   DEBUG: PushCecKeypress - ignored key a9

46:36 331.884766 T:1857000352   DEBUG: PushCecKeypress - received key a6 duration 0 (rep:0 size:0)

46:36 331.884979 T:1857000352   DEBUG: PushCecKeypress - added key a6

46:36 331.900391 T:1962909696   DEBUG: OnKey: 166 (0xa6) pressed, action is Up

46:36 332.065247 T:1857000352   DEBUG: PushCecKeypress - received key a6 duration 181 (rep:0 size:0)

46:36 332.065521 T:1857000352   DEBUG: PushCecKeypress - ignored key a6

46:37 332.936035 T:1857000352   DEBUG: PushCecKeypress - received key  b duration 0 (rep:0 size:0)

46:37 332.936310 T:1857000352   DEBUG: PushCecKeypress - added key  b

46:37 332.945190 T:1962909696   DEBUG: OnKey: 11 (0x0b) pressed, action is Select

46:37 332.960205 T:1737487264   DEBUG: Thread MusicInfoScanner start, auto delete: false

46:37 332.960510 T:1737487264   DEBUG: CAnnouncementManager - Announcement: OnScanStarted from xbmc

46:37 332.960785 T:1737487264   DEBUG: GOT ANNOUNCEMENT, type: 32, from xbmc, message OnScanStarted

46:37 332.980286 T:1962909696   DEBUG: ------ Window Init (DialogExtendedProgressBar.xml) ------

46:37 332.980957 T:1737487264   DEBUG: Process - Starting scan

46:37 332.981506 T:1756361632   DEBUG: Thread MusicFileCounter start, auto delete: false

46:37 332.981720 T:1756361632   DEBUG: Thread MusicFileCounter 1756361632 terminating

46:37 332.981873 T:1737487264  NOTICE: My Music: Scanning for music info using worker thread, operation took 00:00

46:37 332.983276 T:1737487264   DEBUG: Process - Finished scan

46:37 332.983673 T:1737487264   DEBUG: CAnnouncementManager - Announcement: OnScanFinished from xbmc

46:37 332.983948 T:1737487264   DEBUG: GOT ANNOUNCEMENT, type: 32, from xbmc, message OnScanFinished

46:37 332.997467 T:1737487264   DEBUG: Thread MusicInfoScanner 1737487264 terminating

46:37 333.002441 T:1962909696   DEBUG: CGUIMediaWindow::GetDirectory (sources://music/)

46:37 333.002625 T:1962909696   DEBUG:   ParentPath = [sources://music/]

46:37 333.005219 T:1737487264   DEBUG: Thread JobWorker start, auto delete: true

46:37 333.051453 T:1962909696 WARNING: CreateLoader - unsupported protocol(sources) in sources://music.tbn

46:37 333.058197 T:1962909696   DEBUG: RetrieveMusicInfo() took 0 msec

46:37 333.084381 T:1756361632   DEBUG: Thread BackgroundLoader start, auto delete: false

46:37 333.104034 T:1756361632   DEBUG: Thread BackgroundLoader 1756361632 terminating

46:37 333.109375 T:1962909696   DEBUG: ------ Window Deinit (DialogExtendedProgressBar.xml) ------

46:37 333.123169 T:1857000352   DEBUG: PushCecKeypress - received key  b duration 188 (rep:0 size:0)

46:37 333.123413 T:1857000352   DEBUG: PushCecKeypress - ignored key  b

47:07 363.041687 T:1737487264   DEBUG: Thread JobWorker 1737487264 terminating (autodelete)

47:12 368.199707 T:1962909696  NOTICE: NFS is idle. Closing the remaining connections.

The DB file is not gaining size and there is no NFS-share index progress-bar on the top right.

See the kodi.log of this last reboot at http://sprunge.us/aDgI

**popcornmix** · 2016-09-29, 14:42

(2016-09-29, 11:52)novoid Wrote: I noticed, that there is MyMusic52.db as well. To my astonishment, this file seems to be used as a substitute when MyMusic56.db is missing.

Yes, if kodi finds an older database it will attempt to convert it to the latest version.
Note, now you have deleted the database, you will need to add your music sources again (they live in the database).

novoid · 2016-09-29, 19:33

(2016-09-29, 14:42)popcornmix Wrote: Note, now you have deleted the database, you will need to add your music sources again (they live in the database).

The NFS-share was still visible but the library obviously not updated on reboot. I just had to invoke "re-scan
share" (or similar) for my share in the Music > Library > Files screen.

After the long re-indexing and another re-indexing of Yatse, Kodi as well as Yatse are doing fine again.

My issue is resolved.

As a lessons learned for Kodi, I'd say that an emergency re-build of MyMusic*.db should be added to the UI. Additionally, there maybe should be a consistency check of the databases (I did this in the shell as well) which results in an emergency rebuild in case of a DB error.

To me, even as an IT savvy guy, resolving the issue was tedious because of lack of knowledge to drill down the issue. There was no valuable error message in the UI although a main function stopped working.

Somebody with no IT background will probably fail to fix the issue and has to start with a brand new Kodi installation which certainly lead to frustration and loss of confidence in Kodi.

Maybe this issue leads to an improved process for those users as well.

Thanks for your help!