How does new&changed scanner detect what files to scan?

[frank1969]

I even don't understand in German :-D. I didn't understand _what_
explained the behaviour.

Ah, OK! I just wanted to express, till then we concentrated on trying to see why scanner does "wrong changes" or doesn't remove artists and in which order scans happen.
But if server doesn't detect the files as changed (eg for "windows reasons") and they aren't even handled by scanner, the problem maybe is "outside scanner" and in server structure or in windows...?

I'll check the scanned files too and report (will take a little for I now saved db and log after EVERY scan and I did a lot of scans ;-))

[mherger]

> Ah, OK! I just wanted to express, till then we concentrated on trying to
> see why scanner does "wrong changes" or doesn't remove artists and in
> which order scans happen.
> But if server doesn't detect the files as changed (eg for "windows
> reasons") and they aren't even handled by scanner, the problem maybe is
> "outside scanner" and in server structure or in windows...?

Ok, that makes sense. Thanks for clarifying.

[frank1969]

So, I finally collected all the data - I watched the "0 scan" (the last scan before the change), 1st scan (after the change) and 2nd scan (after the change)

"0 scan":
(Last scan BEFORE changes =
= BEFORE "1st scan" (after changes))

tracks.timestamp
1624895572 - Montag, 28. Juni 2021 17:52:52 GMT+02:00 DST (ctime?)

tracks.filesize
5898100

tracks.added_time
1643710345 - Dienstag, 1. Februar 2022 11:12:25 GMT+01:00

tracks.updates_time
1643710345 - Dienstag, 1. Februar 2022 11:12:25 GMT+01:00

scanned_files.timestamp
1624895572 - Montag, 28. Juni 2021 17:52:52 GMT+02:00 DST (ctime = mtime at that point)

scanned_files.filesize
5898100


AFTER 1st scan (after changes):

tracks.timestamp
1624895572 - Montag, 28. Juni 2021 17:52:52 GMT+02:00 DST (ctime?)

tracks.filesize
5898100

tracks.added_time
1643710345 - Dienstag, 1. Februar 2022 11:12:25 GMT+01:00

tracks.updates_time
1643710345 - Dienstag, 1. Februar 2022 11:12:25 GMT+01:00

scanned_files.timestamp
1644444840 - Mittwoch, 9. Februar 2022 23:14:00 GMT+01:00 (mtime)

scanned_files.filesize
5890048

After this (1st) scan, the track and album had been (on contributor_track.contributor and contributor_track.album) still be linked to the OLD contributor ("Nalin & Kane")



AFTER 2nd scan (after changes):

tracks.timestamp
1644444840 - Mittwoch, 9. Februar 2022 23:14:00 GMT+01:00 (mtime)

tracks.filesize
5890048

tracks.added_time
1643710345 - Dienstag, 1. Februar 2022 11:12:25 GMT+01:00

tracks.updates_time
1644484141 - Donnerstag, 10. Februar 2022 10:09:01 GMT+01:00

scanned_files.timestamp
1644444840 - Mittwoch, 9. Februar 2022 23:14:00 GMT+01:00 (mtime)

scanned_files.filesize
5890048

After this (2nd) scan, the track and album finally had been (on contributor_track.contributor and contributor_track.album) changed and now linked to the NEW contributor ("Nalin + Kane")


As far as I can see, with 1st scan, scanned_files.timestamp and scanned_files.filesize have been changed, so they were different now from tracks.timestamp and tracks.filesize.
But this lead to no changes on any "contributor-files".

Only on 2nd scan the comparison scanned_files.timestamp != tracks.timestamp (or scanned_files.filesize != tracks.filesize) lead to changes within the contributor-fields in library.db ...

So it looks to me as it "always needs 2 scans" - one to change the scanned_files.timestamp / scanned_file.filesize and a 2nd one to make those changes take effect on other fields in the db?

[mherger]

The full query to get the changed tracks is:

SELECT DISTINCT (scanned_files.url) 
  FROM scanned_files
       JOIN
       tracks ON (scanned_files.url = tracks.url AND 
                  (scanned_files.timestamp != tracks.timestamp OR 
                   scanned_files.filesize != tracks.filesize) AND 
                  tracks.content_type != 'dir') 
 WHERE scanned_files.url LIKE 'file:///path/to/your/music%';

Where the last condition would be the URLified music folder. You can probably even leave it out. Next time you have a first scan after changes, which missed some items, could you please run the above to see what you get?

And one more thing: would there be more than 50 _changed_ tracks overall when this happens? (Of which some would be picked up, and some not?)

I think you've identified a long standing bug...

[mherger]

Ok, time for another batch of updates :-).

I believe there was a bug in the scanner introduced more than a decade
ago... the processing of changed files happens in batches of 50 tracks.
After closer inspection I figured out that only ever _one_ such batch
would have been processed. Which means that as soon as you had more than
50 changed tracks, you'd get partial results. I was able to easily
reproduce the issue by lowering the batch size to 1 track.

So please give the latest build another try. Thank you very much for
your testing and reporting! I believe we've identified quite a few
issues in the past two weeks :-).

[frank1969]

OK, MANY MANY thanks, I've just installed, made sure I changed more than 50 files and started a "new&changed" (which takes a little longer due to the changes, I guess - till now it was about 45 min. for a new & changed, now it is after 45 min. halfways through the database so I guess it will be "times 3" - but that's worth it, if You found and fixed the bug.

And it's a little "fun" or thrill to find it - what makes me crazy is (or was) that I didn't find what caused the behavior. I did the same things to my files and "sometimes it worked" (= the scanner found the files and corrected the db-entries) and "sometimes it didn't" (= the scanner didn't change entries in the db) - and I didn't came to the idea it depends on the number of changes I do (as Your remember, if I especially tested a new beta, I just did 1-3 files so I could see the effect easily - and mostly it worked. But in "normal work" (when I change a lot of entries) the bug appeared again. So the "> 50" thing sound reasonable...

[mherger]

> OK, MANY MANY thanks, I've just installed, made sure I changed more than
> 50 files and started a "new&changed" (which takes a little longer due to
> the changes, I guess - till now it was about 45 min. for a new &
> changed, now it is after 45 min. halfways through the database so I
> guess it will be "times 3" - but that's worth it, if You found and fixed
> the bug.

It should certainly not take that much longer. The only step which might
take longer is the "Rescanning changed audio files (x)" - which
shouldn't be where the scanner is spending a lot of time. In the log
snippet you posted a few days ago (70 tracks), finding all tracks took
almost 10 minutes, whereas the actual update only took a few seconds. So
even if that latter took 3x as long as before, it would only be seconds.

> And it's a little "fun" or thrill to find it - what makes me crazy is
> (or was) that I didn't find what caused the behavior. I did the same
> things to my files and "sometimes it worked" (= the scanner found the
> files and corrected the db-entries) and "sometimes it didn't" (= the

Yep, I hate that kind of behaviour (and like the challenge, as you do :-)).

[frank1969]

Ok, one quick feedback cause scanner "hangs".

Logfile says:
[22-02-12 11:26:38.0681] Slim::Utils::Scanner::Local::updateTracks (531) Rescanning changed audio files (298)

298 tracks sounds reasonable.
Then it starts scanning the changed files (I looked into scanner.log and recognized those are the files I changed today, files I changed yesterday or eben the day(s) before and it does some more updates on files, I changed a few days before and today again (for example:
On the following tracked I changed the year from "0" to "1967" some days ago - today I changed the artists name (from "The Temptations" to "Temptations") now it sees the files as new and updates the year-change from some days ago.
[22-02-12 11:26:41.7569] Slim::Utils::Scanner::Local::changed (967) Handling changed audio track file:///M:/_Various/M/Motown%20Unreleased%201967/21%20%20-%20The%20Temptations%20-%20Since%20I%20Don%27t%20Have%20You.mp3
[22-02-12 11:26:41.7844] Slim::Utils::Scanner::Local::__ANON__ (1077) Rescanning changed year 0 -> 1967

That all looks good.

But now for more than 20 minutes - nothing happens.

Web-interface says
"Help Rescanning Media Library... Geänderte Dateien werden durchsucht (1487 of 298)" (and the number increases, now it is (a few seconds later) "(1515 of 298)")

Last log-entry ist:
[22-02-12 11:27:15.0623] Slim::Utils::Scanner::Local::changed (967) Handling changed audio track file:///M:/S/Sonny%20+%20Cher/1965%20-%20Baby%20Don%27t%20Go/12%20-%20Caesar%20+%20Cleo%3B%20Sonny%20+%20Cher%20-%20Let%20The%20Good%20Times%20Roll.mp3
[22-02-12 11:27:15.0675] Slim::Schema::Contributor::rescan (244) Removing unused contributor: 127316

which is 20 minutes ago now.

I exported log file to excel and scanner already did "Handling changed audio track" on all 298 tracks (ok, to be honest, excel says 294 but this might be an error in exporting or "counting" - as far as I can see, this "Sonny + Cher" track is the last (in alphabetical order) I changed".

Server.log is unchanged since 11:11 - scanner.log since 11:27 ... - scanner seemingly doesn't know what to do after handling changed tracks and "goes on counting" ...

I will now abort and set db back to "yesterday evening" and start to scan anew...

[frank1969]

It should certainly not take that much longer.

Yes!
It became quicker till the end and now I started the "2nd try" and it's "as quick as it always was".
Guess there were some windows update in the background this morning, didn't check task manager, sry!
I will report if it "runs through" this time...

[frank1969]

*** Tested with r1644665330 ***

Ok, 2nd try, same result:
"Rescanning Media Library... Geänderte Dateien werden durchsucht (511 of 298)"

"Information" tab on options says:

Discovering files/directories: M: (1260039 of 1260039) Complete 00:22:32
Removing deleted files: M: (714 of 714) Complete 00:06:37
Scanning changed files: M: (527) Running 00:05:13
M:\_Various\M\Motown Collection\1998 - Motown Collection - Motown Hits Of Gold - CD 3\04 - The Supremes; The Temptations - I'm Gonna Make You Love Me.mp3

Note:
The File mentioned there (M:\_Various\M\...) is actually NOT the last file scanned according to scanner.log

scanner.log says:


[22-02-12 12:51:35.2076] Slim::Utils::Scanner::Local::deleted (636) Handling deleted audio file [...]
[22-02-12 12:51:35.2107] Slim::Schema::Album::rescan (273) Removing unused album: 26137
[22-02-12 12:51:41.9899] Slim::Utils::SQLiteHelper::updateProgress (442) Notify to server: [
"progress:1644666304||importer||M:|directory_delet ed||714||714||1644666701.98934",
]
[22-02-12 12:51:41.9929] Slim::Utils::SQLiteHelper::updateProgress (466) Notify to server OK
[22-02-12 12:51:41.9935] Slim::Utils::Scanner::Local::updateTracks (531) Rescanning changed audio files (298)
[22-02-12 12:51:42.0129] Slim::Utils::SQLiteHelper::updateProgress (442) Notify to server: [
"progress:1644666701.99379||importer||M:|directory _changed||1||298||",
]
[22-02-12 12:51:42.0160] Slim::Utils::SQLiteHelper::updateProgress (466) Notify to server OK
[22-02-12 12:51:42.0165] Slim::Utils::Scanner::Local::changed (967) Handling changed audio track file:///M:/[...]

[...]
* Here are about 295 changed tracks handled *

[22-02-12 12:52:17.9092] Slim::Utils::Scanner::Local::changed (967) Handling changed audio track file:///M:/S/Sonny%20+%20Cher/1965%20-%20Baby%20Don%27t%20Go/07%20-%20Caesar%20+%20Cleo%3B%20Sonny%20+%20Cher%20-%20Do%20You%20Want%20to%20Dance.mp3
[22-02-12 12:52:18.2522] Slim::Utils::Scanner::Local::changed (967) Handling changed audio track file:///M:/S/Sonny%20+%20Cher/1965%20-%20Baby%20Don%27t%20Go/12%20-%20Caesar%20+%20Cleo%3B%20Sonny%20+%20Cher%20-%20Let%20The%20Good%20Times%20Roll.mp3
[22-02-12 12:52:18.2574] Slim::Schema::Contributor::rescan (244) Removing unused contributor: 127316

[22-02-12 12:52:23.4628] Slim::Utils::SQLiteHelper::updateProgress (442) Notify to server: [
"progress:1644666701.99379||importer||M:|directory _changed||318||298||",
]
[22-02-12 12:52:23.4658] Slim::Utils::SQLiteHelper::updateProgress (466) Notify to server OK
[22-02-12 12:52:28.6004] Slim::Utils::SQLiteHelper::updateProgress (442) Notify to server: [
"progress:1644666701.99379||importer||M:|directory _changed||322||298||",
]
[22-02-12 12:52:28.6032] Slim::Utils::SQLiteHelper::updateProgress (466) Notify to server OK
[22-02-12 12:52:33.7420] Slim::Utils::SQLiteHelper::updateProgress (442) Notify to server: [
"progress:1644666701.99379||importer||M:|directory _changed||326||298||",
]
[22-02-12 12:52:33.7451] Slim::Utils::SQLiteHelper::updateProgress (466) Notify to server OK
[22-02-12 12:52:38.9079] Slim::Utils::SQLiteHelper::updateProgress (442) Notify to server: [
"progress:1644666701.99379||importer||M:|directory _changed||330||298||",
]

[...]

]
[22-02-12 12:59:08.6201] Slim::Utils::SQLiteHelper::updateProgress (466) Notify to server OK
[22-02-12 12:59:14.0922] Slim::Utils::SQLiteHelper::updateProgress (442) Notify to server: [
"progress:1644666701.99379||importer||M:|directory _changed||639||298||",
]
[22-02-12 12:59:14.0950] Slim::Utils::SQLiteHelper::updateProgress (466) Notify to server OK
[22-02-12 12:59:19.3689] Slim::Utils::SQLiteHelper::updateProgress (442) Notify to server: [
"progress:1644666701.99379||importer||M:|directory _changed||643||298||",
]
[22-02-12 12:59:19.3718] Slim::Utils::SQLiteHelper::updateProgress (466) Notify to server OK

* [...] and so on *

server.log says:

[22-02-12 12:51:32.5101] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666304.99661||importer||M:|directory_ deleted||712||714||
[22-02-12 12:51:41.9925] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666304||importer||M:|directory_delete d||714||714||1644666701.98934
[22-02-12 12:51:42.0154] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666701.99379||importer||M:|directory_ changed||1||298||
[22-02-12 12:51:47.1941] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666701.99379||importer||M:|directory_ changed||12||298||
[22-02-12 12:51:52.5882] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666701.99379||importer||M:|directory_ changed||30||298||
[22-02-12 12:51:57.5921] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666701.99379||importer||M:|directory_ changed||80||298||
[22-02-12 12:52:02.6086] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666701.99379||importer||M:|directory_ changed||157||298||
[22-02-12 12:52:07.6585] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666701.99379||importer||M:|directory_ changed||247||298||
[22-02-12 12:52:12.6596] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666701.99379||importer||M:|directory_ changed||293||298||
[22-02-12 12:52:17.8212] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666701.99379||importer||M:|directory_ changed||304||298||
[22-02-12 12:52:23.4643] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666701.99379||importer||M:|directory_ changed||318||298||
[22-02-12 12:52:28.6027] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666701.99379||importer||M:|directory_ changed||322||298||
[...]
[22-02-12 13:04:24.7709] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666701.99379||importer||M:|directory_ changed||879||298||
[22-02-12 13:04:29.9774] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666701.99379||importer||M:|directory_ changed||883||298||
[22-02-12 13:04:35.2212] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644666701.99379||importer||M:|directory_ changed||887||298||

... and so on for once again 15 minutes now...