[Bug]: S3 excessive egress traffic caused by background GenerateMetadataJob

[motoride]

⚠️ This issue respects the following points: ⚠️

• This is a bug, not a question or a configuration/webserver/proxy issue.
• This issue is not already reported on Github OR Nextcloud Community Forum (I've searched it).
• Nextcloud Server is up to date. See Maintenance and Release Schedule for supported versions.
• I agree to follow Nextcloud's Code of Conduct.

Bug description

NC tries to reindex metadata on my entire external storage mount, causing high data transfer costs.

Steps to reproduce

1. Attach external S3 compatible storage
2. Wait for cron to trigger GenerateMetadataJob
3. Observe every single file on external storage being called through the API on a daily basis

Expected behavior

Files should be indexed once, and if possible shouldn’t be downloaded from the external storage which causes high data transfer costs.

Installation method

Other Community project

Nextcloud Server version

28

Operating system

Other

PHP engine version

PHP 8.2

Web server

Nginx

Database engine version

MySQL

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

Upgraded to a MAJOR version (ex. 22 to 23)

Are you using the Nextcloud Server Encryption module?

Encryption is Disabled

What user-backends are you using?

• Default user-backend (database)
• LDAP/ Active Directory
• SSO - SAML
• Other

Configuration report

{
    "system": {
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "***REMOVED SENSITIVE VALUE***"
        ],
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "dbtype": "mysql",
        "version": "28.0.0.11",
        "overwrite.cli.url": "***REMOVED SENSITIVE VALUE***",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbport": "",
        "dbtableprefix": "nc_",
        "mysql.utf8mb4": true,
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "installed": true,
        "memcache.local": "\\OC\\Memcache\\Redis",
        "memcache.distributed": "\\OC\\Memcache\\Redis",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "***REMOVED SENSITIVE VALUE***",
            "port": 0,
            "dbindex": 0
        },
        "mail_smtpmode": "smtp",
        "mail_sendmailmode": "smtp",
        "htaccess.RewriteBase": "\/",
        "preview_max_memory": 2048,
        "enable_previews": true,
        "enabledPreviewProviders": [
            "OC\\Preview\\PNG",
            "OC\\Preview\\JPEG",
            "OC\\Preview\\GIF",
            "OC\\Preview\\BMP",
            "OC\\Preview\\XBitmap",
            "OC\\Preview\\PDF",
            "OC\\Preview\\MP3",
            "OC\\Preview\\TXT",
            "OC\\Preview\\MarkDown",
            "OC\\Preview\\HEIC",
            "OC\\Preview\\MKV",
            "OC\\Preview\\MP4",
            "OC\\Preview\\AVI",
            "OC\\Preview\\Movie"
        ],
        "preview_max_x": "2048",
        "preview_max_y": "2048",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpauth": 1,
        "mail_smtpauthtype": "PLAIN",
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "587",
        "mail_smtpsecure": "tls",
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "maintenance": false,
        "default_phone_region": "***REMOVED SENSITIVE VALUE***",
        "theme": "",
        "logtimezone": "***REMOVED SENSITIVE VALUE***",
        "loglevel": 2,
        "jpeg_quality": "80",
        "session_relaxed_expiry": false
    }
}

List of activated Apps

- activity: 2.20.0
  - admin_audit: 1.18.0
  - analytics: 4.12.0
  - bruteforcesettings: 2.8.0
  - calendar: 4.6.1
  - circles: 28.0.0-dev
  - cloud_federation_api: 1.11.0
  - collectives: 2.9.2
  - comments: 1.18.0
  - contacts: 5.5.0
  - contactsinteraction: 1.9.0
  - dashboard: 7.8.0
  - dav: 1.29.1
  - external: 5.3.1
  - federatedfilesharing: 1.18.0
  - federation: 1.18.0
  - files: 2.0.0
  - files_automatedtagging: 1.18.0
  - files_external: 1.20.0
  - files_pdfviewer: 2.9.0
  - files_reminders: 1.1.0
  - files_sharing: 1.20.0
  - files_trashbin: 1.18.0
  - files_versions: 1.21.0
  - files_versions_s3: 0.2.1
  - firstrunwizard: 2.17.0
  - group_everyone: 0.1.14
  - logreader: 2.13.0
  - lookup_server_connector: 1.16.0
  - mail: 3.5.0
  - nextcloud_announcements: 1.17.0
  - notes: 4.9.1
  - notifications: 2.16.0
  - oauth2: 1.16.3
  - password_policy: 1.18.0
  - passwords: 2023.12.31
  - photos: 2.4.0
  - privacy: 1.12.0
  - provisioning_api: 1.18.0
  - recommendations: 2.0.0
  - related_resources: 1.3.0
  - serverinfo: 1.18.0
  - settings: 1.10.0
  - sharebymail: 1.18.0
  - spreed: 18.0.1
  - support: 1.11.0
  - survey_client: 1.16.0
  - systemtags: 1.18.0
  - tasks: 0.15.0
  - text: 3.9.1
  - theming: 2.3.0
  - twofactor_backupcodes: 1.17.0
  - twofactor_totp: 10.0.0-beta.2
  - updatenotification: 1.18.0
  - user_status: 1.8.1
  - viewer: 2.2.0
  - weather_status: 1.8.0
  - workflowengine: 2.10.0

Nextcloud Signing status

Integrity checker has been disabled. Integrity cannot be verified.

Nextcloud Logs

No response

Additional info

See https://help.nextcloud.com/t/s3-external-storage-excessive-network-traffic/177455/4

I have installed through Installatron

[bjo81]

I've been stumbling about the same issue as mentioned in the forum thread, running NC 28.0.1 with juicefs on Backblaze B2 . Every day around the same time, a massive increase of egress traffic was visible.
Looking into nextcloud.log showed:

{"reqId":"LF9xJW9in00pBvwc4Tw9","level":0,"time":"2023-12-26T18:12:41+00:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Run OC\\Core\\BackgroundJobs\\GenerateMetadataJob job with ID 119439","userAgent":"--","version":"28.0.1.1","data":{"app":"cron"}}

At the same time, the first file is accessed by this request according to audit.log:

{"reqId":"LF9xJW9in00pBvwc4Tw9","level":1,"time":"2023-12-26T18:12:41+00:00","remoteAddr":"","user":"--","app":"admin_audit","method":"","url":"--","message":
"File accessed: \"/23008967420230721898193.png\"","userAgent":"--","version":"28.0.1.1","data":{"app":"admin_audit"}}

Hours later, files are still accessed:

{"reqId":"LF9xJW9in00pBvwc4Tw9","level":1,"time":"2023-12-26T21:28:25+00:00","remoteAddr":"","user":"--","app":"admin_audit","method":"","url":"--","message":"File accessed: \"/Fotos/2016/09/IMG_20160928_193056.jpg\"","userAgent":"--","version":"28.0.1.1","data":{"app":"admin_audit"}}

To prevent further costs I killed the process then. wc -l shows that 22461 files has been accessed with this request ID in audit.log.

If I understand the code of https://github.com/nextcloud/server/blob/master/core/BackgroundJobs/GenerateMetadataJob.php correctly, all files are scanned (and when using S3 storage also downloaded) every day. But e.g. occ files:scan --all should have indexed all files already, and why is a scan every day necessary when according to https://docs.nextcloud.com/server/stable/developer_manual/digging_deeper/files-metadata.html metadata is updated when a file is created updated or modified? Then it should be only neccessary after an upgrade from NC27 to NC28 when no metadata for the existing files exist.

[paulchen]

On my instance of Nextcloud (running NC 28.0.1), I also stumbled upon a problem with the GenerateMetadataJob which sounds similar to what is reported above.

Every 24 hours the GenerateMetadataJob is started which reads all files. I'm not using external storage, but the total size of the files is about 290 GiB. As a consequence the load on my server dramatically goes up for several hours, every day.

I can't imagine this works as intended.

EDIT: Setting enable_file_metadata to false as suggested at https://help.nextcloud.com/t/s3-external-storage-excessive-network-traffic/177455/8 seems to disable GenerateMetadataJob.

[ArtificialOwl]

Few things about this issue:

• The scan of folder/files is done like this:

  • every night a process will get a list of your users and, user per user, scan their files once to generate metadata,
  • this process will not switch to the next user if it has already run for an hour,
  • the process will restart itself next night and only stop once all your users get the files scanned.

• enable_file_metadata is deprecated and setting it to true or false will not change anything.

[bjo81]

When somebody stores "only" 200GB, why does the job generate 100GB traffic every day?

[ArtificialOwl]

When somebody stores "only" 200GB, why does the job generate 100GB traffic every day?

Is it shared/available to multiple users ?

[bjo81]

200GB was summerized, 100GB is used by one user, 90GB by another. According to your explanation, the scans should be done after some time?
I will set again $this->setInterval(24 * 3600); instead of $this->setInterval(30 *24 * 3600);and check again if it finishes after some days.

[ArtificialOwl]

Right now, if multiple users have access to the same file, file will be retrieved each time.

This #42627 will avoid refresh metadata on already existing metadata.

[bjo81]

Shared files between the users are around 10GB I think, that wouldn't explain it.

[mehlkopf]

Few things about this issue:

• The scan of folder/files is done like this:

  • every night a process will get a list of your users and, user per user, scan their files once to generate metadata,
  • this process will not switch to the next user if it has already run for an hour,
  • the process will restart itself next night and only stop once all your users get the files scanned.

• enable_file_metadata is deprecated and setting it to true or false will not change anything.

I am quite certain that on my server, it does not only scan the files once. In my case, all files (almost all in a folder shared by 6 users, 60 GB) are scanned each time the cronjob runs, and it does not stop after 3600 seconds, but runs for ~ 1.5 hours.