Kodi Community Forum

Full Version: odd startup scanning issue
You're currently viewing a stripped down version of our content. View the full version with proper formatting.
Pages: 1 2
Dave,

is there any light you could shed on the following

started up kodi 18 beta 4 (which is set to a scan on startup)

and going by the speed it the media scan was going at it appeared as though it was doing a rescan of all my albums

but on further investigation log is full of the following entries

12:14:08.617 T:19284  NOTICE: CWebServer[8080]: Started
12:14:08.620 T:21860  NOTICE: ES: Starting UDP Event server on port 9777
12:14:08.620 T:21860  NOTICE: UDP: Listening on port 9777 (ipv6 : true)
12:14:10.957 T:20552   ERROR: SQL: [MyMusic72.db] Abort due to constraint violation
                                            Query: INSERT INTO album_source (idAlbum, idSource) values(47, 2)
12:14:10.957 T:20552   ERROR: CDatabase::ExecuteQuery - failed to execute query 'INSERT INTO album_source (idAlbum, idSource) values(47, 2)'
12:14:11.937 T:20552   ERROR: SQL: [MyMusic72.db] Abort due to constraint violation
                                            Query: INSERT INTO album_source (idAlbum, idSource) values(48, 2)
12:14:11.937 T:20552   ERROR: CDatabase::ExecuteQuery - failed to execute query 'INSERT INTO album_source (idAlbum, idSource) values(48, 2)'
12:14:13.875 T:20552   ERROR: SQL: [MyMusic72.db] Abort due to constraint violation
                                            Query: INSERT INTO album_source (idAlbum, idSource) values(49, 2)
12:14:13.875 T:20552   ERROR: CDatabase::ExecuteQuery - failed to execute query 'INSERT INTO album_source (idAlbum, idSource) values(49, 2)'
12:14:15.341 T:20552   ERROR: SQL: [MyMusic72.db] Abort due to constraint violation
                                            Query: INSERT INTO album_source (idAlbum, idSource) values(50, 2)
12:14:15.342 T:20552   ERROR: CDatabase::ExecuteQuery - failed to execute query 'INSERT INTO album_source (idAlbum, idSource) values(50, 2)'
12:14:16.296 T:20552   ERROR: SQL: [MyMusic72.db] Abort due to constraint violation
                                            Query: INSERT INTO album_source (idAlbum, idSource) values(51, 2)
12:14:16.296 T:20552   ERROR: CDatabase::ExecuteQuery - failed to execute query 'INSERT INTO album_source (idAlbum, idSource) values(51, 2)'
12:14:17.958 T:20552   ERROR: SQL: [MyMusic72.db] Abort due to constraint violation

and one entry for each album I wondered why the first 46 albums appeared to have been ok, but realised they are a different source and they appeared at the end 

12:58:50.764 T:20552   ERROR: SQL: [MyMusic72.db] Abort due to constraint violation
                                            Query: INSERT INTO album_source (idAlbum, idSource) values(1, 1)
12:58:50.764 T:20552   ERROR: CDatabase::ExecuteQuery - failed to execute query 'INSERT INTO album_source (idAlbum, idSource) values(1, 1)'
12:58:52.349 T:20552   ERROR: SQL: [MyMusic72.db] Abort due to constraint violation
                                            Query: INSERT INTO album_source (idAlbum, idSource) values(2, 1)
12:58:52.349 T:20552   ERROR: CDatabase::ExecuteQuery - failed to execute query 'INSERT INTO album_source (idAlbum, idSource) values(2, 1)'
12:58:53.583 T:20552   ERROR: SQL: [MyMusic72.db] Abort due to constraint violation
                                            Query: INSERT INTO album_source (idAlbum, idSource) values(3, 1)
12:58:53.584 T:20552   ERROR: CDatabase::ExecuteQuery - failed to execute query 'INSERT INTO album_source (idAlbum, idSource) values(3, 1)'
12:58:54.698 T:20552   ERROR: SQL: [MyMusic72.db] Abort due to constraint violation
                                            Query: INSERT INTO album_source (idAlbum, idSource) values(4, 1)
12:58:54.699 T:20552   ERROR: CDatabase::ExecuteQuery - failed to execute query 'INSERT INTO album_source (idAlbum, idSource) values(4, 1)'

etc etc

the album sources are held on a linux box sharing them out as samba shares, which are then mounted locally using a mapped drive

Kodi started up normally yesterday, and I closed it and restarted again, after this and it started normally

I have the whole log saved although there is nothing else of any note in it really but can supply if required

Can't see what the constraint violation could be nothing else would touch the kodi database,

I could browse the samba shares and play tracks during the issue,

pc had plenty of spare ram and cpu

so at a bit of a loss as to what underlying issue could be

from problem run 12:59:56.412 T:20552  NOTICE: My Music: Scanning for music info using worker thread, operation took 45:47

from good run straight after 13:05:33.625 T:18964  NOTICE: My Music: Scanning for music info using worker thread, operation took 00:45

any thoughts

Tim
Thanks Tim, I'll take a look. The "constraint violation" is because the scan is trying to add album source data that already exists, so I need to have a think about how that situation could arise. I take it that those albums were alreday in the librray, and music files unchanged so should not have been rescanned? Makes me wonder if this is also an unexpected rescan example too?

The final db state will be fine, but obviously want to solve the issue. I'll probably be back with  more questions
Dave,

yes no changes from previous day, so I was surprised when start up scan took so long, which made me look at log

every album would already exist in DB

only thing I did after checking log was run a clean to remove a couple of albums which I noticed I had at some point earlier spotted that their folder name was spelt incorrectly to remove their entries

I then restarted kodi and it scanned at its normal speed ie very fast as there would be nothing to do
Tim, I have some idea of the issue but can't reproduce at will yet. Could you post a link to the full log file please.
I use a Win10 Pro PC for KODI.  My music files are stored on a Win7 Pro PC, accessed via SMB network shares.  I am still on v17.6

Twice a year, without fail, when the clocks change due to Daylight Savings time in the UK, a full scan is always started for me the next time I do a KODI manual Update Library scan.

I've always assumed this is caused by some confused timestamp somewhere.  It feels like it is doing a much deeper scan and tag check than a usual scan.  (I know it is a deeper scan than I can trigger with "Update Library")

I would suggest that this is why your scan took longer than usual on the 28th - the first day you probably started KODI since the clock changes.

Hopefully this adds to a hint as to how to track this one down.
will do, 

Sorry been away for a few days
Dave 

have sent you a PM with link to log and database
@tkgafs

Expect a short delay in Dave responding. He is away for a few days.
@Karellen is right, and I probably won't be able to get back into this until Monday

@BatterPudding I think you are right, clock change on some systems does trigger a rescan of every item (because the hash comparison finds  differences). What systems is an interesting one, because for example neither my RPi for Windows set up (connected to NAS drive) do it. I suspect using Samba is sigificant, but yet to prove it.

@tkgafs got your data, but the debug log link doesn't work. Try again with that?
link re sent in pm
Yep, got it this time Tim (with added - that didn't stay in link)
OK, I have fixed the constraint violation errors https://github.com/xbmc/xbmc/pull/14906 which will be in v18 RC1 release.  Thanks @tkgafs  for reporting this. The db is left in an OK state, but the errors were slowing the scan, I had overlooked removing some records before recreating them on album update. Sorry for taking so long to fix but I have had family stuff to deal with.

As for the clock-change related library total rescan (if beahves as if every file has changed and recreates every library entry), I really don't know how to stop that. It is only on Samba drives as far as I can tell, and something to do with how the hash is created. So if anyone has ideas why file timestamp and name produces a different hash combo after clock-change on Samba drives and how we can avoid it then  I am happy to hear them.
I think it's to do with the fact that NTFS uses UTC for timestamps but adjusts for daylight saving. So if you look at the timestamp after the clocks have changed it will be an hour different.  The FAT filesystem doesn't use UTC but instead just uses the local time on your PC/NAS/whatever so the issue doesn't occur with FAT formatted disks.  There was a bug in the implementation of the exFAT (also using UTC) driver for linux which didn't respect the timezone and/or timeoffset which caused the timestamps of files on exFAT drives to display incorrectly under Linux.
Since NTFS timetamps are in UTC, they can't be affected, but I guess when the timestamps are queried (via CFile::stat ?) they are being converted to windows system time so Kodi sees that as a change.

scott s.
.
(2018-11-19, 20:39)DaveBlake Wrote: [ -> ] Sorry for taking so long to fix but I have had family stuff to deal with.

As for the clock-change related library total rescan (if beahves as if every file has changed and recreates every library entry), I really don't know how to stop that. It is only on Samba drives as far as I can tell, and something to do with how the hash is created. So if anyone has ideas why file timestamp and name produces a different hash combo after clock-change on Samba drives and how we can avoid it then  I am happy to hear them.
No need to be sorry it wouldn't happen again for another 6 months anyway Smile
Pages: 1 2