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

[mherger]

How does new&changed scanner detect whatfiles to scan?

> In German "Das erklärt, warum es einmal geht und einmal nicht (obwohl
> nichts am Code oder an den Dateien verändert wurde)"

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

> I looked in "tracks" (library.db) there it was unchanged with added_time
> = 1643710345 and updated_time = 1643710345 (which is Tue Feb 01 2022
> 11:12:25 GMT+0100 - the day of my initial scan )

Did you check the scanned_files.timestamp, too? The comparison to figure
out whether a file would need to be re-evaluated or not is:

scanned_files.timestamp != tracks.timestamp
OR
scanned_files.filesize != tracks.filesize

[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]

How does new&changed scanner detect whatfiles to scan?

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

How does new&changed scanner detect whatfiles to scan?

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]

How does new&changed scanner detect whatfiles to scan?

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

[mherger]

How does new&changed scanner detect whatfiles to scan?

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

Argh... that's likely due to my attempt at not running a last,
unnecessary request over the tracks table. I've now committed an
alternative approach, which might actually be slightly faster. But I
preferred the first approach for its simplicity. So... more testing to
do. A new build is on its way.

[frank1969]

Argh... that's likely due to my attempt at not running a last,
unnecessary request over the tracks table. I've now committed an
alternative approach, which might actually be slightly faster. But I
preferred the first approach for its simplicity. So... more testing to
do. A new build is on its way.

Thanks!
Scan ran through r1644672553

Will do some tests later and try r1644678709 so it looks it's about other issues...

[frank1969]

r1644703639 looks good again.
The changes I checked worked fine!

One thing only:
At the end of the scan (or I even guess AFTER the end of the scan) server STOPPED.
Can't imagine a memory issue, my machine hast 16 GB (I know, LMS is 32 bit, so it can't use all of it) and the use of scanner/server is usually about 300-500 MB... (and no other app was running only "usual" background action)

If I restarted it showed:

Database Optimize (2 of 2) Complete 00:00:42
The server has finished scanning your media library.
Total Time: 00:56:18 (Sunday, 13. February 2022 / 11.01.15)

so it looks, the server DIDN'T crash but stopped afterwards?

I give You the last entries from server.log - maybe You can see any reason?

[22-02-13 10:05:15.9106] Slim::Utils::SQLiteHelper::_notifyFromScanner (581) Notify from scanner: progress:1644743057.79672||importer||M:|discoverin g_directory||206||0||
[22-02-13 10:49:32.7410] Slim::Plugin::UPnP::Events::error (326) Subscribe/unsubscribe error: 412 Precondition Failed
[22-02-13 10:49:32.8843] Slim::Plugin::UPnP::Events::error (326) Subscribe/unsubscribe error: 412 Precondition Failed

*** At This Point [22-02-13 11:01:15] server obviously had finished scan***

[22-02-13 11:01:16.9242] Slim::Schema::wipeCaches (2130) Wiped all in-memory caches.
[22-02-13 11:01:16.9247] Slim::Schema::wipeCaches (2130) Wiped all in-memory caches.
[22-02-13 11:01:16.9254] Slim::Utils::Misc::msg (1343) Warning: [11:01:16.9253] DBIx::Class::ResultSet::update_or_create(): Query returned more than one row. SQL that returns multiple rows is DEPRECATED for ->find and ->single at /<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Schema.pm line 1905
[22-02-13 11:01:17.0761] Slim::Schema::Storage::throw_exception (121) Error: DBI Exception: DBD::SQLite::db selectcol_arrayref failed: out of memory [for Statement "
SELECT term, d FROM (
SELECT term, SUM(documents) d
FROM fulltext_terms
WHERE NOT col IN ('*', 1, 0) AND LENGTH(term) > 1
GROUP BY term
ORDER BY d DESC
)
WHERE d > 500
"]
[22-02-13 11:01:17.0763] Slim::Schema::Storage::throw_exception (121) Backtrace:

frame 0: Slim::Utils::Log::logBacktrace (/<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Schema/Storage.pm line 121)
frame 1: Slim::Schema::Storage::throw_exception (/<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>DBIx/Class/Storage/DBI.pm line 1006)
frame 2: DBIx::Class::Storage:BI::__ANON__ (C:/PROGRA~2/SQUEEZ~1/server/Slim/Plugin/FullTextSearch/Plugin.pm line 587)
frame 3: Slim::Plugin::FullTextSearch::Plugin::_initPopular Terms (C:/PROGRA~2/SQUEEZ~1/server/Slim/Plugin/FullTextSearch/Plugin.pm line 148)
frame 4: Slim::Plugin::FullTextSearch::Plugin::__ANON__ (/<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Control/Request.pm line 2058)
frame 5: (eval) (/<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Control/Request.pm line 2058)
frame 6: Slim::Control::Request::notify (/<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Control/Request.pm line 859)
frame 7: Slim::Control::Request::checkNotifications (slimserver.pl line 715)
frame 8: main::idle (slimserver.pl line 684)
frame 9: main::main (slimserver.pl line 131)
frame 10: PerlSvc::Interactive (/<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>PerlSvc. pm line 99)
frame 11: PerlSvc::_interactive (slimserver.pl line 0)
frame 12: (eval) (slimserver.pl line 0)

[22-02-13 11:01:17.0765] Slim::Control::Request::notify (2060) Error: Failed notify: Carp::Clan::__ANON__(): DBI Exception: DBD::SQLite::db selectcol_arrayref failed: out of memory [for Statement "
SELECT term, d FROM (
SELECT term, SUM(documents) d
FROM fulltext_terms
WHERE NOT col IN ('*', 1, 0) AND LENGTH(term) > 1
GROUP BY term
ORDER BY d DESC
)
WHERE d > 500
"] at /<C:\PROGRA~2\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Schema/Storage.pm line 125
[22-02-13 11:01:17.0771] Slim::Music::Import::nextScanTask (801) remaining scans in queue)

[mherger]

How does new&amp;changed scanner detect whatfiles to scan?

> [22-02-13 11:01:17.0761] Slim::Schema::Storage::throw_exception (121)
> Error: DBI Exception: DBD::SQLite::db selectcol_arrayref failed: out of
> memory [for Statement "
> SELECT term, d FROM (
> SELECT term, SUM(documents) d
> FROM fulltext_terms
> WHERE NOT col IN ('*', 1, 0) AND LENGTH(term) > 1
> GROUP BY term
> ORDER BY d DESC
> )
> WHERE d > 500
> "]

Argh... how much free disk space would you have, in particular on the
drive where your TEMP folder lives?

Could you please run the inner SELECT in the above statement in SQLite
directly, to get the total number of rows for that query?