search

nextcloud / server

☁️ Nextcloud server, a safe home for all your data
https://nextcloud.com
GNU Affero General Public License v3.0
27.44k stars 4.08k forks source link

[Bug]: User username still has unscanned files after running background scan, background scan might be stopped prematurely #43557

Open ostasevych opened 9 months ago

ostasevych commented 9 months ago

⚠️ This issue respects the following points: ⚠️

Bug description

Hi! I am constantly getting warning message for one of users (out of 25): User username still has unscanned files after running background scan, background scan might be stopped prematurely And this happens once per an hour.

Steps to reproduce

  1. Just observ in logs the warning message User username still has unscanned files after running background scan, background scan might be stopped prematurely

Expected behavior

No warning message or more explanation added.

Installation method

Community Web installer on a VPS or web space

Nextcloud Server version

27

Operating system

Debian/Ubuntu

PHP engine version

PHP 8.2

Web server

Apache (supported)

Database engine version

MariaDB

Is this bug present after an update or on a fresh install?

None

Are you using the Nextcloud Server Encryption module?

None

What user-backends are you using?

Configuration report

No response

List of activated Apps

No response

Nextcloud Signing status

No response

Nextcloud Logs

No response

Additional info

No response

matti-owl commented 8 months ago

28.0.2 same

JohanBoshoffWebAware commented 8 months ago

I also have this problem, only with one user. Is there any way to fix it while waiting for a fix?

dohlin commented 8 months ago

Would be so great if this could be resolved. Been a bug for the last few releases, yesterday I literally gave up and nuked my old install and re-installed using the new AIO method. Today I'm back to getting the same error for the same user. The only thing I use NC for is tasks, and accessing files remotely via my NAS mounted as an SMB/CIFS external storage. Don't understand why this is happening, even on a brand new fresh install.

JohanBoshoffWebAware commented 8 months ago

You will need to revert to using Nextcloud 26 or early versions of 27, before 27.1.5 and using the Desktop Client of the 3.11 range if you want to use a fresh install.

It is frustrating that the bug has been logged so long ago, two new releases and still no fix. If only the Temporary Files Lock app had a command to remove all file locks that do not get removed or add it to the cron job if there are stuck files then it would be moving forward at least.

Obviously, testing is not done properly before releasing new versions and the bugs persist, but Nextcloud is already busy with version 29 Beta. Why push version upgrades when old bugs remain on older versions?

Just stick to one version to get is stable, get all the bugs fixed, and then move on to new features and version upgrades.

dohlin commented 8 months ago

You will need to revert to using Nextcloud 26 or early versions of 27, before 27.1.5 and using the Desktop Client of the 3.11 range if you want to use a fresh install.

It is frustrating that the bug has been logged so long ago, two new releases and still no fix. If only the Temporary Files Lock app had a command to remove all file locks that do not get removed or add it to the cron job if there are stuck files then it would be moving forward at least.

Obviously, testing is not done properly before releasing new versions and the bugs persist, but Nextcloud is already busy with version 29 Beta. Why push version upgrades when old bugs remain on older versions?

Just stick to one version to get is stable, get all the bugs fixed, and then move on to new features and version upgrades.

100% agree. I'm am glad I'm not the only one seeing this bug, but I have to agree that it's really unfortunate bugs like this persist so long when new releases are being shoved down the pipe.

CDSWambo commented 8 months ago

so it's a known bug?

metronidazole commented 7 months ago

I'm getting this error with my read only external storage mount

CDSWambo commented 7 months ago

@metronidazole wait, you mean with an external hdd connected to your server? I have one that's through sata connected to my zimaboard so it shouldn't be a problem. The ro fs is set in your fstab?

metronidazole commented 7 months ago

@metronidazole wait, you mean with an external hdd connected to your server? I have one that's through sata connected to my zimaboard so it shouldn't be a problem. The ro fs is set in your fstab?

No with a external storage (nextcloud feature) configured. The file system is not read only, it's just configured as read only in nextcloud settings.

joshtrichards commented 7 months ago

This isn't a bug (at least this message alone isn't) per se. It's just a warning that the background scanner didn't finish on the last user. The question is, in each of your cases, why it's not completing?

Please do the following:

metronidazole commented 7 months ago

This isn't a bug (at least this message alone isn't) per se. It's just a warning that the background scanner didn't finish on the last user. The question is, in each of your cases, why it's not completing?

Please do the following:

* Check your Nextcloud log for the time period immediately before this warning is logged (it may have errors/exceptions/etc related to the scan - at least if you have a default `loglevel` of `2` or lower)

* Try doing [a scan of unscanned files from the command line](https://docs.nextcloud.com/server/latest/admin_manual/configuration_server/occ_command.html#scan) (basically what this background job does) with verbose mode on and seeing what happens (`occ files:scan --unscanned -vvv [user]`)

My log level is 2, there is no other log messages other than the described one being spammed every 10-15.

The second command doesn't work as the user doesn't exist anymore "Unknown user 1 4a286a0f-142b-3242-98e0-9cfdc9f443bd.

If I run it for all users (--all), then it does list some files (for an existing user) but with no errors

+---------+-------+-----+---------+---------+--------+--------------+ | Folders | Files | New | Updated | Removed | Errors | Elapsed time | +---------+-------+-----+---------+---------+--------+--------------+ | 56 | 406 | 0 | 0 | 0 | 0 | 00:00:04 | +---------+-------+-----+---------+---------+--------+--------------+

The log messages seem to have stopped however, so it looks like the issue for me at least is resolved.

Sieboldianus commented 6 months ago

I could solve this error that appeared after the update from 27 to 28 by running the files:scan --all command:

docker compose exec --user www-data app php occ files:scan --all
> Starting scan for user 1 out of 9 (...)
> Starting scan for user 2 out of 9 (...)
> Starting scan for user 3 out of 9 (...)
> Starting scan for user 4 out of 9 (...)
> Starting scan for user 5 out of 9 (...)
> Starting scan for user 6 out of 9 (...)
> Starting scan for user 7 out of 9 (...)
> Starting scan for user 8 out of 9 (...)
> Starting scan for user 9 out of 9 (...)
> +---------+---------+-----+---------+---------+--------+--------------+
> | Folders | Files   | New | Updated | Removed | Errors | Elapsed time |
> +---------+---------+-----+---------+---------+--------+--------------+
> | 288736  | 3345350 | 0   | 6967441 | 3       | 26     | 01:28:20     |
> +---------+---------+-----+---------+---------+--------+--------------+

No more "unscanned files" errors in admin logs since then.

joesch2 commented 4 months ago

I use Version 28.0.6

Result of occ-filescan: Screenshot 2024-06-23 094022

The following message continually appears in the log (after each execution of the cronjob task): User (...) still has unscanned files after running background scan, background scan might be stopped prematurely

Version File-App: 28.0.6.1

Best regards, Jörg

vasyugan commented 4 months ago

This isn't a bug (at least this message alone isn't) per se. It's just a warning that the background scanner didn't finish on the last user. The question is, in each of your cases, why it's not completing? Please do the following:

* Check your Nextcloud log for the time period immediately before this warning is logged (it may have errors/exceptions/etc related to the scan - at least if you have a default `loglevel` of `2` or lower)

* Try doing [a scan of unscanned files from the command line](https://docs.nextcloud.com/server/latest/admin_manual/configuration_server/occ_command.html#scan) (basically what this background job does) with verbose mode on and seeing what happens (`occ files:scan --unscanned -vvv [user]`)

In my case it reports zero unscanned files. So it is surprising that I see this error in the logs.

+---------+-------+-----+---------+---------+--------+--------------+
| Folders | Files | New | Updated | Removed | Errors | Elapsed time |
+---------+-------+-----+---------+---------+--------+--------------+
| 515     | 2614  | 0   | 0       | 0       | 0      | 00:00:08     |
+---------+-------+-----+---------+---------+--------+--------------+

{"reqId":"nccHIUToFqP0JT9UrAAa","level":2,"time":"2024-06-24T07:30:01+00:00","remoteAddr":"","user":"--","app":"files","method":"","url":"--","message":"User ***** still has unscanned files after running background scan, background scan might be stopped prematurely","userAgent":"--","version":"29.0.2.2","data":{"app":"files"},"id":"66792268ded20"}

vasyugan commented 4 months ago

I also have this problem, only with one user. Is there any way to fix it while waiting for a fix?

I'm afraid, that's only how it seems What I did in my desperation is that I deleted the user in question. That didn't make the error message go away. Instead, it reappeared with the next user name.

vasyugan commented 4 months ago

You will need to revert to using Nextcloud 26 or early versions of 27, before 27.1.5 and using the Desktop Client of the 3.11 range if you want to use a fresh install.

It is frustrating that the bug has been logged so long ago, two new releases and still no fix. If only the Temporary Files Lock app had a command to remove all file locks that do not get removed or add it to the cron job if there are stuck files then it would be moving forward at least.

[...]

How is this bug related to temporary files lock? I truncated the files lock table, but this didn't change a thing.

JohanBoshoffWebAware commented 4 months ago

All I can say is that the latest versions of Nextcloud are full of bugs, even the Desktop Client and it frustrates users and we are loosing clients because of dilly programming, or unwillingness from nextcloud to address or fix the issues at hand.

vasyugan commented 4 months ago

All I can say is that the latest versions of Nextcloud are full of bugs, even the Desktop Client and it frustrates users and we are loosing clients because of dilly programming, or unwillingness from nextcloud to address or fix the issues at hand.

I have to say, I agree with you there, and so does Heise.de. Still it would be a great relief to have at least some rough idea what might be causing this. The last suspect I had was that there must be some invalid filename such as .htaccess somewhere in the file cache table. But if so, shouldn't files:scan throw an error then? I'm just stupified that none of those manual actions I can take yields any error.

vasyugan commented 4 months ago

Maybe this helps. (just tried it, after backing up the DB using mysqldump). I'll see and watch.

Yes, it seems to help (have waited for the next cron execution, and the warning no longer appears.

So this is the quick fix. However as said above, back up your database first!

DELETE FROM oc_filecache WHERE fileid IN(SELECT DISTINCT f.fileid FROM oc_filecache AS f INNER JOIN oc_mounts AS m ON m.storage_id = f.storage WHERE size < 0 AND parent > -1);

And of course, this workaround does not justify Nextcloud not fixing this bug.

Forza-tng commented 3 months ago

@vasyugan Thanks for the 'fix'. It temporarily solved the 'user x has unscanned...' issue. There were over 250k rows.... unfortunately, the issue came back again today, but only with a few hundred rows.

I think most of the files are related to OCA\GroupFolders\Mount\MountProvider. I do have a group folder Backup with two users having access.

The database entries looks like this:

| 26825118 | 2 | appdata_oc56k9291p0f/preview/f/f/5/a/3/a | a64adeb42ae3cd3ca9c9e10078b31480 | 26825117 | a | 2 | 1 |  -1 | 1722361193 |  1722361193 | 0 | 0 | 66a9256988e11 | 31 |  | 590 | 2 | 24933 | anders  | /redacted-username/files/Backup/ |  NULL | OCA\GroupFolders\Mount\MountProvider |

I'm thinking that background scan somehow doesn't work properly with the GroupFolders app?

Before deleting the entries from the database, running occ files:scan --all --unscanned does nothing, it only shows 0 files. However after deleting the entries, it takes a considerable amount of time to finish.

I am on Nextcloud 29.0.4.1, PHP 8.2.20. Actual error message:

{"reqId":"O65kc9OIh2GQJxiWfqNa","level":2,"time":"2024-07-30T19:08:10+00:00","remoteAddr":"","user":"--","app":"files","method":"","url":"--","message":"User redacted-user still has unscanned files after running background scan, background scan might be stopped prematurely","userAgent":"--","version":"29.0.4.1","data":{"app":"files"},"id":"66a93d7dc4a9c"}

occ app:list

Enabled:
  - activity: 2.21.1
  - admin_audit: 1.19.0
  - appointments: 2.1.8
  - audioplayer: 3.4.1
  - bookmarks: 14.2.2
  - bruteforcesettings: 2.9.0
  - calendar: 4.7.13
  - camerarawpreviews: 0.8.5
  - cfg_share_links: 5.1.0
  - checksum: 1.2.4
  - circles: 29.0.0-dev
  - cloud_federation_api: 1.12.0
  - cloud_py_api: 0.1.9
  - comments: 1.19.0
  - contacts: 6.0.0
  - contactsinteraction: 1.10.0
  - dav: 1.30.1
  - epubviewer: 1.6.3
  - event_update_notification: 2.4.0
  - federatedfilesharing: 1.19.0
  - files: 2.1.0
  - files_downloadlimit: 2.0.0
  - files_external: 1.21.0
  - files_lock: 29.0.1
  - files_pdfviewer: 2.10.0
  - files_reminders: 1.2.0
  - files_sharing: 1.21.0
  - files_trashbin: 1.19.0
  - files_versions: 1.22.0
  - firstrunwizard: 2.18.0
  - groupfolders: 17.0.1
  - imageconverter: 2.0.2
  - impersonate: 1.16.0
  - integration_openstreetmap: 1.0.12
  - keeweb: 0.6.19
  - logreader: 2.14.0
  - lookup_server_connector: 1.17.0
  - mail: 3.7.5
  - maps: 1.4.0
  - memories: 7.3.1
  - notes: 4.10.1
  - notifications: 2.17.0
  - notify_push: 0.7.0
  - oauth2: 1.17.0
  - password_policy: 1.19.0
  - phonetrack: 0.8.1
  - photos: 2.5.0
  - previewgenerator: 5.6.0
  - privacy: 1.13.0
  - provisioning_api: 1.19.0
  - recognize: 7.1.0
  - related_resources: 1.4.0
  - root_cache_cleaner: 0.1.7
  - serverinfo: 1.19.0
  - settings: 1.12.0
  - sharebymail: 1.19.0
  - side_menu: 3.13.1
  - snappymail: 2.36.4
  - socialsharing_email: 3.1.0
  - systemtags: 1.19.0
  - tasks: 0.16.0
  - text: 3.10.1
  - theming: 2.4.0
  - twofactor_backupcodes: 1.18.0
  - unroundedcorners: 1.1.3
  - updatenotification: 1.19.1
  - user_status: 1.9.0
  - users_picker: 1.0.0
  - viewer: 2.3.0
  - weather_status: 1.9.0
  - workflowengine: 2.11.0
Disabled:
  - assistant: 1.1.0 (installed 1.1.0)
  - customproperties: 2.0.4 (installed 2.0.4)
  - dashboard: 7.9.0 (installed 7.6.0)
  - deck: 1.13.1 (installed 1.13.1)
  - encryption: 2.17.0 (installed 2.0.0)
  - extract: 1.3.6 (installed 1.3.6)
  - federation: 1.19.0 (installed 1.3.0)
  - files_antivirus: 5.5.7 (installed 5.5.7)
  - integration_giphy: 1.0.11 (installed 1.0.11)
  - login_notes: 1.5.0 (installed 1.5.0)
  - metadata: 0.20.0 (installed 0.20.0)
  - news: 24.0.0 (installed 24.0.0)
  - nextcloud_announcements: 1.18.0 (installed 1.15.0)
  - recommendations: 2.1.0 (installed 0.8.0)
  - spreed: 19.0.7 (installed 19.0.7)
  - support: 1.12.0 (installed 1.0.1)
  - survey_client: 1.17.0 (installed 1.5.0)
  - suspicious_login: 7.0.0 (installed 5.0.0)
  - twofactor_totp: 11.0.0-dev
  - user_ldap: 1.20.0

occ config:list system

{
    "system": {
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "redacted-domain"
        ],
        "trusted_proxies": "***REMOVED SENSITIVE VALUE***",
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "tempdirectory": "\/mnt\/storageTemp\/nextcloud",
        "updatedirectory": "\/mnt\/storageTemp\/nextcloud",
        "overwrite.cli.url": "https:\/\/redacted-domain\/",
        "htaccess.RewriteBase": "\/",
        "maintenance_window_start": "2",
        "log_rotate_size": 419430400,
        "log_type": "file",
        "log_type_audit": "file",
        "logfile_audit": "\/var\/log\/nextcloud\/audit.log",
        "syslog_tag": "Nextcloud",
        "logfile": "\/var\/log\/nextcloud\/nextcloud.log",
        "loglevel": 2,
        "redis_log_file": "",
        "log_query": false,
        "query_log_file": "\/var\/log\/nextcloud\/nextcloud\/query.log",
        "debug": false,
        "maintenance": false,
        "dbtype": "mysql",
        "version": "29.0.4.1",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbport": "3306",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "dbpersistent": "",
        "db.persistent": "",
        "dbdriveroptions": {
            "12": true
        },
        "dbtype_options": {
            "12": true
        },
        "installed": true,
        "mail_smtpmode": "smtp",
        "mail_smtpauthtype": "LOGIN",
        "mail_smtpsecure": "ssl",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpauth": 1,
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "465",
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "memcache.local": "\\OC\\Memcache\\APCu",
        "memcache.distributed": "\\OC\\Memcache\\Redis",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "***REMOVED SENSITIVE VALUE***",
            "port": 6379,
            "timeout": 0,
            "dbindex": 2
        },
        "session_relaxed_expiry": true,
        "session_lifetime": 86400,
        "remember_login_cookie_lifetime": 1296000,
        "session_keepalive": true,
        "auth.bruteforce.protection.enabled": false,
        "ratelimit.protection.enabled": false,
        "activity_expire_days": 180,
        "filesystem_check_changes": 1,
        "trashbin_retention_obligation": "auto, 60",
        "versions_retention_obligation": "auto, 60",
        "mysql.utf8mb4": true,
        "default_locale": "en_GB",
        "updater.release.channel": "stable",
        "enable_previews": true,
        "preview_format": "webp",
        "preview_concurrency_all": 12,
        "preview_concurrency_new": 12,
        "preview_max_x": 1920,
        "preview_max_y": 1200,
        "preview_max_filesize_image": 50,
        "preview_ffmpeg_path": "\/usr\/bin\/ffmpeg",
        "preview_imaginary_url": "***REMOVED SENSITIVE VALUE***",
        "default_phone_region": "SE",
        "enabledPreviewProviders": [
            "OC\\Preview\\Imaginary",
            "OC\\Preview\\HEIC",
            "OC\\Preview\\Movie",
            "OC\\Preview\\Photoshop",
            "OC\\Preview\\SVG",
            "OC\\Preview\\TIFF",
            "OC\\Preview\\PNG",
            "OC\\Preview\\JPEG",
            "OC\\Preview\\GIF",
            "OC\\Preview\\BMP",
            "OC\\Preview\\XBitmap",
            "OC\\Preview\\MP3",
            "OC\\Preview\\TXT",
            "OC\\Preview\\MarkDown",
            "OC\\Preview\\Krita",
            "OC\\Preview\\WebP",
            "OC\\Preview\\Image",
            "OC\\Preview\\AVIF",
            "OC\\Preview\\HEIF",
            "OC\\Preview\\Illustrator"
        ],
        "theme": "",
        "mail_sendmailmode": "smtp",
        "memories.exiftool": "\/usr\/bin\/exiftool",
        "memories.exiftool_no_local": true,
        "memories.vod.ffmpeg": "\/usr\/bin\/ffmpeg",
        "memories.vod.ffprobe": "\/usr\/bin\/ffprobe",
        "memories.vod.path": "\/var\/www\/domains\/redacted-domain\/htdocs\/nextcloud\/apps\/memories\/bin-ext\/go-vod-amd64",
        "allow_local_remote_servers": true,
        "preview_max_memory": 512,
        "memories.vod.vaapi": true,
        "app_install_overwrite": [
            "users_picker",
            "imageconverter"
        ],
        "memories.gis_type": 1,
        "memories.db.triggers.fcu": true,
        "memories.vod.disable": false
    }
}
Forza-tng commented 3 months ago

This isn't a bug (at least this message alone isn't) per se. It's just a warning that the background scanner didn't finish on the last user. The question is, in each of your cases, why it's not completing?

Please do the following:

  • Check your Nextcloud log for the time period immediately before this warning is logged (it may have errors/exceptions/etc related to the scan - at least if you have a default loglevel of 2 or lower)
  • Try doing a scan of unscanned files from the command line (basically what this background job does) with verbose mode on and seeing what happens (occ files:scan --unscanned -vvv [user])

Unfortunately running --unscanned gives nothing new with debug logging enabled:

This is the standard warning entry that keeps repeating over and over (guessing from cron runs):

{"reqId":"8MhX67MPXCgWet7HaHec","level":2,"time":"2024-08-02T14:48:00+00:00","remoteAddr":"","user":"--","app":"files","method":"","url":"--","message":"User REDACTED still has unscanned files after running background scan, background scan might be stopped prematurely","userAgent":"--","version":"29.0.4.1","data":{"app":"files"}}

Enabled debug log using occ log:manage --level=debug

Then started a occ files:scan --unscanned REDACTED

Starting scan for user 1 out of 1 (REDACTED)
+---------+-------+-----+---------+---------+--------+--------------+
| Folders | Files | New | Updated | Removed | Errors | Elapsed time |
+---------+-------+-----+---------+---------+--------+--------------+
| 0       | 0     | 0   | 0       | 0       | 0      | 00:00:00     |
+---------+-------+-----+---------+---------+--------+--------------+

log file does not have any extended details that shows the problemn

{"reqId":"EKbcDtoSSxqOf9WOyyUG","level":1,"time":"2024-08-02T14:51:15+00:00","remoteAddr":"","user":"--","app":"files","method":"","url":"--","message":"Completed scan of 0 files in 0 folder. Found 0 new, 0 updated and 0 removed items","userAgent":"--","version":"29.0.4.1","data":{"app":"files"}}

I also enabled debug and sql logging in config.php. This is the output from a manual occ files:scan --unscanned REDACTED

{
    "reqId":"qag26xbqQtUuLmGokmge",
    "level":0,
    "time":"2024-08-02T15:05:18+00:00",
    "remoteAddr":"",
    "user":"--",
    "app":"core",
    "method":"",
    "url":"--",
    "message":"DB QueryBuilder: 'SELECT `filecache`.`fileid`, `storage`, `path`, `path_hash`, `filecache`.`parent`, `filecache`.`name`, `mimetype`, `mimepart`, `size`, `mtime`, `storage_mtime`, `encrypted`, `etag`, `filecache`.`permissions`, `checksum`, `unencrypted_size`, `metadata_etag`, `creation_time`, `upload_time`, `meta`.`json` AS `meta_json`, `meta`.`sync_token` AS `meta_sync_token` FROM `*PREFIX*filecache` `filecache` LEFT JOIN `*PREFIX*filecache_extended` `fe` ON `filecache`.`fileid` = `fe`.`fileid` LEFT JOIN `*PREFIX*files_metadata` `meta` ON `filecache`.`fileid` = `meta`.`file_id` WHERE (`storage` = :dcValue1) AND (`path_hash` = :dcValue2)' with parameters: dcValue1 => '2', dcValue2 => '3f6e4da389de9761ccdfe0b54c30dae9'",
    "userAgent":"--",
    "version":"29.0.4.1",
    "data": {
        "app":"core"
    }}
{
    "reqId":"qag26xbqQtUuLmGokmge",
    "level":0,
    "time":"2024-08-02T15:05:18+00:00",
    "remoteAddr":"",
    "user":"--",
    "app":"core",
    "method":"",
    "url":"--",
    "message":"DB QueryBuilder: 'SELECT `size`, `unencrypted_size` FROM `*PREFIX*filecache` WHERE `parent` = :dcValue1' with parameters: dcValue1 => '27786456'",
    "userAgent":"--",
    "version":"29.0.4.1",
    "data": {
        "app":"core"
    }}
{
    "reqId":"qag26xbqQtUuLmGokmge",
    "level":0,
    "time":"2024-08-02T15:05:18+00:00",
    "remoteAddr":"",
    "user":"--",
    "app":"core",
    "method":"",
    "url":"--",
    "message":"DB QueryBuilder: 'SELECT `filecache`.`fileid`, `storage`, `path`, `path_hash`, `filecache`.`parent`, `filecache`.`name`, `mimetype`, `mimepart`, `size`, `mtime`, `storage_mtime`, `encrypted`, `etag`, `filecache`.`permissions`, `checksum`, `unencrypted_size`, `metadata_etag`, `creation_time`, `upload_time`, `meta`.`json` AS `meta_json`, `meta`.`sync_token` AS `meta_sync_token` FROM `*PREFIX*filecache` `filecache` LEFT JOIN `*PREFIX*filecache_extended` `fe` ON `filecache`.`fileid` = `fe`.`fileid` LEFT JOIN `*PREFIX*files_metadata` `meta` ON{"reqId":"qag26xbqQtUuLmGokmge","level":0,"time":"2024-08-02T15:05:18+00:00","remoteAddr":"","user":"--","app":"core","method":"","url":"--","message":"DB QueryBuilder: 'SELECT `filecache`.`fileid`, `storage`, `path`, `path_hash`, `filecache`.`parent`, `filecache`.`name`, `mimetype`, `mimepart`, `size`, `mtime`, `storage_mtime`, `encrypted`, `etaCT `fileid` FROM `*PREFIX*filecache` WHERE (`storage` = :dcValue1) AND (`size` < :dcValue2) ORDER BY `fileid` DESC LIMIT 1' with parameters: dcValue1 => '21',
    dcValue2 => '0'","userAgent":"--","version":"29.0.4.1","data":{"app":"core"}}
    {
        "reqId":"qag26xbqQtUuLmGokmge",
        "level":0,
        "time":"2024-08-02T15:05:18+00:00",
        "remoteAddr":"",
        "user":"--",
        "app":"core",
        "method":"",
        "url":"--",
        "message":"DB QueryBuilder: 'SELECT `fileid` FROM `*PREFIX*filecache` WHERE (`storage` = :dcValue1) AND (`path_hash` = :dcValue2)' with parameters: dcValue1 => '20', dcValue2 => 'd41d8cd98f00b204e9800998ecf8427e'",
        "userAgent":"--",
        "version":"29.0.4.1",
        "data": {
            "app":"core"
        }}
    {
        "reqId":"qag26xbqQtUuLmGokmge",
        "level":0,
        "time":"2024-08-02T15:05:18+00:00",
        "remoteAddr":"",
        "user":"--",
        "app":"core",
        "method":"",
        "url":"--",
        "message":"DB QueryBuilder: 'SELECT `fileid` FROM `*PREFIX*filecache` WHERE (`storage` = :dcValue1) AND (`size` < :dcValue2) ORDER BY `fileid` DESC LIMIT 1' with parameters: dcValue1 => '20', dcValue2 => '0'",
        "userAgent":"--",
        "version":"29.0.4.1",
        "data": {
            "app":"core"
        }}
    {
        "reqId":"qag26xbqQtUuLmGokmge",
        "level":0,
        "time":"2024-08-02T15:05:18+00:00",
        "remoteAddr":"",
        "user":"--",
        "app":"core",
        "method":"",
        "url":"--",
        "message":"DB QueryBuilder: 'SELECT `fileid` FROM `*PREFIX*filecache` WHERE (`storage` = :dcValue1) AND (`path_hash` = :dcValue2)' with parameters: dcValue1 => '2', dcValue2 => 'd41d8cd98f00b204e9800998ecf84g`, `filecache`.`permissions`, `checksum`, `unencrypted_size`, `metadata_etag`, `creation_time`, `upload_time`, `meta`.`json` AS `meta_json`, `meta`.`sync_token` AS `meta_sync_token` FROM `*PREFIX*filecache` `filecache` LEFT JOIN `*PREFIX*filecache_extended` `fe` ON `filecache`.`fileid` = `fe`.`fileid` LEFT JOIN `*PREFIX*files_metadata` `meta` ON `filecache`.`fileid` = `meta`.`file_id` WHERE `filecache`.`parent` = :dcValue1 ORDER BY `name` ASC' with parameters: dcValue1 => '27786456'",
        "userAgent":"--",
        "version":"29.0.4.1",
        "data": {
            "app":"core"
        }}
    {
        "reqId":"qag26xbqQtUuLmGokmge",
        "level":0,
        "time":"2024-08-02T15:05:18+00:00",
        "remoteAddr":"",
        "user":"--",
        "app":"core",
        "method":"",
        "url":"--",
        "message":"DB QueryBuilder: 'SELECT `filecache`.`fileid`, `storage`, `path`, `path_hash`, `filecache`.`parent`, `filecache`.`name`, `mimetype`, `mimepart`, `size`, `mtime`, `storage_mtime`, `encrypted`, `etag`, `filecache`.`permissions`, `checksum`, `unencrypted_size`, `metadata_etag`, `creation_time`, `upload_time`, `meta`.`json` AS `meta_json`, `meta`.`sync_token` AS `meta_sync_token` FROM `*PREFIX*filecache` `filecache` LEFT JOIN `*PREFIX*filecache_extended` `fe` ON `filecache`.`fileid` = `fe`.`fileid` LEFT JOIN `*PREFIX*files_metadata` `meta` ON `filecache`.`fileid` = `meta`.`file_id` WHERE (`storage` = :dcValue1) AND (`path_hash` = :dcValue2)' with parameters: dcValue1 => '2', dcValue2 => '3f6e4da389de9761ccdfe0b54c30dae9'",
        "userAgent":"--",
        "version":"29.0.4.1",
        "data": {
            "app":"core"
        }}
    {
        "reqId":"qag26xbqQtUuLmGokmge",
        "level":0,
        "time":"2024-08-02T15:05:18+00:00",
        "remoteAddr":"",
        "user":"--",
        "app":"core",
        "method":"",
        "url":"--",
        "message":"DB QueryBuilder: 'SELECT `size`, `unencrypted_size` FROM `*PREFIX*filecache` WHERE `parent` = :dcValue1' with parameters: dcValue1 => '27786456'",
        "userAgent":"--",
        "version":"29.0.4.1",
        "data": {
            "app":"core"
        }}
    {
        "reqId":"qag26xbqQtUuLmGokmge",
        "level":0,
        "time":"2024-08-02T15:05:18+00:00",
        "remoteAddr":"",
        "user":"--",
        "app":"core",
        "method":"",
        "url":"--",
        "message":"DB QueryBuilder: 'SELECT `filecache`.`fileid`, `storage`, `path`, `path_hash`, `filecache`.`parent`, `filecache`.`name`, `mimetype`, `mimepart`, `size`, `mtime`, `storage_mtime`, `encrypted`, `etag`, `filecache`.`permissions`, `checksum`, `unencrypted_size`, `metadata_etag`, `creation_time`, `upload_time`, `meta`.`json` AS `meta_json`, `meta`.`sync_token` AS `meta_sync_token` FROM `*PREFIX*filecache` `filecache` LEFT JOIN `*PREFIX*filecache_extended` `fe` ON `filecache`.`fileid` = `fe`.`fileid` LEFT JOIN `*PREFIX*files_metadata` `meta` ON `filecache`.`fileid` = `meta`.`file_id` WHERE (`storage` = :dcValue1) AND (`path_hash` = :dcValue2)' with parameters: dcValue1 => '2', dcValue2 => '318506f492798b558a7efd53295c042f'",
        "userAgent":"--",
        "version":"29.0.4.1",
        "data": {
            "app":"core"
        }}
    {
        "reqId":"qag26xbqQtUuLmGokmge",
        "level":0,
        "time":"2024-08-02T15:05:18+00:00",
        "remoteAddr":"",
        "user":"--",
        "app":"core",
        "method":"",
        "url":"--",
        "message":"DB QueryBuilder: 'SELECT `fileid` FROM `*PREFIX*filecache` WHERE (`storage` = :dcValue1) AND (`size` < :dcValue2) ORDER BY `fileid` DESC LIMIT 1' with parameters: dcValue1 => '2', dcValue2 => '0'",
        "userAgent":"--",
        "version":"29.0.4.1",
        "data": {
            "app":"core"
        }}
    {
        "reqId":"qag26xbqQtUuLmGokmge",
        "level":0,
        "time":"2024-08-02T15:05:18+00:00",
        "remoteAddr":"",
        "user":"--",
        "app":"core",
        "method":"",
        "url":"--",
        "message":"DB QueryBuilder: 'SELECT `path` FROM `*PREFIX*filecache` WHERE (`storage` = :dcValue1) AND (`fileid` = :dcValue2)' with parameters: dcValue1 => '2', dcValue2 => '27786457'",
        "userAgent":"--",
        "version":"29.0.4.1",
        "data": {
            "app":"core"
        }}
    {
        "reqId":"qag26xbqQtUuLmGokmge",
        "level":1,
        "time":"2024-08-02T15:05:18+00:00",
        "remoteAddr":"",
        "user":"--",
        "app":"files",
        "method":"",
        "url":"--",
        "message":"Completed scan of 0 files in 0 folder. Found 0 new, 0 updated and 0 removed items",
        "userAgent":"--",
        "version":"29.0.4.1",
        "data": {
            "app":"files"
        }}
Forza-tng commented 3 months ago

This isn't a bug (at least this message alone isn't) per se. It's just a warning that the background scanner didn't finish on the last user. The question is, in each of your cases, why it's not completing?

Looking at the code, I think the warning is a false positive:

protected function run($argument) {
        if ($this->config->getSystemValueBool('files_no_background_scan', false)) {
            return;
        }

        $usersScanned = 0;
        $lastUser = '';
        $user = $this->getUserToScan();
        while ($user && $usersScanned < self::USERS_PER_SESSION && $lastUser !== $user) {
            $this->runScanner($user);
            $lastUser = $user;
            $user = $this->getUserToScan();
            $usersScanned += 1;
        }

        if ($lastUser === $user) {
            $this->logger->warning("User $user still has unscanned files after running background scan, background scan might be stopped prematurely");
        }
    }

If $user = $this->getUserToScan() returns no users, that is there are no users with unscanned files, the check $lastUser === $user would evaluate as true and the warning message is logged.

Or am I missing something else here?

Update: I added some debug messages in the function. It scans one user inside the while loop, then exits. It must be because $user = $this->getUserToScan(); inside the loop still returns the same user or fails to update the variable.

{"reqId":"jKkEaMN08LrD3C2Nwr0x","level":2,"time":"2024-08-02T16:13:20+00:00","remoteAddr":"","user":"--","app":"files","method":"","url":"--","message":"BG scan 1 user: userX","userAgent":"--","version":"29.0.4.1","data":{"app":"files"}}
{"reqId":"jKkEaMN08LrD3C2Nwr0x","level":2,"time":"2024-08-02T16:13:20+00:00","remoteAddr":"","user":"--","app":"files","method":"","url":"--","message":"BG scan 2 user: userX","userAgent":"--","version":"29.0.4.1","data":{"app":"files"}}
{"reqId":"jKkEaMN08LrD3C2Nwr0x","level":2,"time":"2024-08-02T16:13:20+00:00","remoteAddr":"","user":"--","app":"files","method":"","url":"--","message":"BG scan 3 user: userX","userAgent":"--","version":"29.0.4.1","data":{"app":"files"}}
{"reqId":"jKkEaMN08LrD3C2Nwr0x","level":2,"time":"2024-08-02T16:13:20+00:00","remoteAddr":"","user":"--","app":"files","method":"","url":"--","message":"BG scan 4 usersScanned: 1","userAgent":"--","version":"29.0.4.1","data":{"app":"files"}}
{"reqId":"jKkEaMN08LrD3C2Nwr0x","level":2,"time":"2024-08-02T16:13:20+00:00","remoteAddr":"","user":"--","app":"files","method":"","url":"--","message":"BG scan 5 user: userX lastUser: userX","userAgent":"--","version":"29.0.4.1","data":{"app":"files"}}
{"reqId":"jKkEaMN08LrD3C2Nwr0x","level":2,"time":"2024-08-02T16:13:20+00:00","remoteAddr":"","user":"--","app":"files","method":"","url":"--","message":"User userX still has unscanned files after running background scan, background scan might be stopped prematurely","userAgent":"--","version":"29.0.4.1","data":{"app":"files"}}
protected function run($argument) {
    if ($this->config->getSystemValueBool('files_no_background_scan', false)) {
        return;
    }
    $usersScanned = 0;
    $lastUser = '';
    $user = $this->getUserToScan();
    $this->logger->warning("BG scan 1 user: $user");
    while ($user && $usersScanned < self::USERS_PER_SESSION && $lastUser !== $user) {
        $this->logger->warning("BG scan 2 user: $user");
        $this->runScanner($user);
        $lastUser = $user;
        $user = $this->getUserToScan();
        $this->logger->warning("BG scan 3 user: $user");
        $usersScanned += 1;
        $this->logger->warning("BG scan 4 usersScanned: $usersScanned");
    }
    $this->logger->warning("BG scan 5 user: $user lastUser: $lastUser");
    if ($lastUser === $user) {
        $this->logger->warning("User $user still has unscanned files after running background scan, background scan might be stopped prematurely");
    }
}