[Bug]: Used memory grew by more than 50 MB when executing job OCA\DAV\BackgroundJob\RefreshWebcalJob

[Markoise]

⚠️ 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

This entry appears in the log every hour when a Google calendar is called up.

[cron] Warnung: Used memory grew by more than 50 MB when executing job OCA\DAV\BackgroundJob\RefreshWebcalJob (id: 74290, arguments: {"principaluri":"principals/users/markus","uri":"calendargooglecom-1"}): 119.6 MB (before: 58.6 MB)
von ? von -- um 19.07.2024, 12:31:43

Steps to reproduce

Subscribe to Google Calendar

Expected behavior

No entry in the log

Installation method

Community Manual installation with Archive

Nextcloud Server version

29

Operating system

Debian/Ubuntu

PHP engine version

PHP 8.2

Web server

Nginx

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?

Encryption is Disabled

What user-backends are you using?

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

Configuration report

{
    "system": {
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "nextcloud",
            "xxx.xxx.xx",
            "192.168.178.50",
            "nextcloud.local"
        ],
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "dbtype": "mysql",
        "version": "29.0.4.1",
        "overwrite.cli.url": "https:\/\/xxx.xxx.xx",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbport": "",
        "dbtableprefix": "oc_",
        "mysql.utf8mb4": true,
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "installed": true,
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "overwritehost": "xxx.xxx.xx",
        "activity_expire_days": 14,
        "allow_local_remote_servers": true,
        "auth.bruteforce.protection.enabled": true,
        "blacklisted_files": [
            ".htaccess",
            "Thumbs.db",
            "thumbs.db"
        ],
        "cron_log": true,
        "default_phone_region": "DE",
        "default_language": "de",
        "default_locale": "de",
        "default_timezone": "Europe\/Berlin",
        "enable_previews": true,
        "enabledPreviewProviders": [
            "OC\\Preview\\PNG",
            "OC\\Preview\\JPEG",
            "OC\\Preview\\GIF",
            "OC\\Preview\\BMP",
            "OC\\Preview\\XBitmap",
            "OC\\Preview\\Movie",
            "OC\\Preview\\PDF",
            "OC\\Preview\\MP3",
            "OC\\Preview\\TXT",
            "OC\\Preview\\MarkDown"
        ],
        "filesystem_check_changes": 0,
        "filelocking.enabled": "true",
        "htaccess.RewriteBase": "\/",
        "integrity.check.disabled": false,
        "knowledgebaseenabled": false,
        "log_rotate_size": "104857600",
        "logfile": "\/var\/log\/nextcloud\/nextcloud.log",
        "loglevel": 2,
        "logtimezone": "Europe\/Berlin",
        "memcache.local": "\\OC\\Memcache\\APCu",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "overwriteprotocol": "https",
        "preview_max_x": 1024,
        "preview_max_y": 768,
        "preview_max_scale_factor": 1,
        "profile.enabled": false,
        "redis": {
            "host": "***REMOVED SENSITIVE VALUE***",
            "port": 0,
            "password": "***REMOVED SENSITIVE VALUE***",
            "timeout": 0.5,
            "dbindex": 1
        },
        "quota_include_external_storage": false,
        "share_folder": "\/Freigaben",
        "skeletondirectory": "",
        "trashbin_retention_obligation": "auto, 90",
        "mail_smtpmode": "smtp",
        "mail_smtpsecure": "ssl",
        "mail_sendmailmode": "smtp",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "465",
        "mail_smtpauth": 1,
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "memories.exiftool": "\/var\/www\/nextcloud\/apps\/memories\/bin-ext\/exiftool-aarch64-glibc",
        "memories.vod.path": "\/var\/www\/nextcloud\/apps\/memories\/bin-ext\/go-vod-aarch64",
        "memories.vod.ffmpeg": "\/usr\/bin\/ffmpeg",
        "memories.vod.ffprobe": "\/usr\/bin\/ffprobe",
        "maintenance": false,
        "app_install_overwrite": [
            "news",
            "files_rightclick",
            "tasks",
            "groupfolders"
        ],
        "theme": "",
        "debug": false,
        "memories.gis_type": 1,
        "updater.release.channel": "stable",
        "versions_retention_obligation": "auto, 365",
        "simpleSignUpLink.shown": false,
        "upgrade.disable-web": true,
        "log.condition": {
            "apps": [
                "admin_audit"
            ]
        },
        "has_rebuilt_cache": true,
        "memories.db.triggers.fcu": true,
        "maintenance_window_start": 1
    }
}

List of activated Apps

Enabled:
  - activity: 2.21.1
  - admin_audit: 1.19.0
  - announcementcenter: 6.8.1
  - bookmarks: 14.2.2
  - bruteforcesettings: 2.9.0
  - calendar: 4.7.12
  - circles: 29.0.0-dev
  - cloud_federation_api: 1.12.0
  - collectives: 2.12.0
  - comments: 1.19.0
  - contacts: 6.0.0
  - contactsinteraction: 1.10.0
  - cookbook: 0.11.1
  - dashboard: 7.9.0
  - dav: 1.30.1
  - deck: 1.13.1
  - drawio: 3.0.2
  - federatedfilesharing: 1.19.0
  - federation: 1.19.0
  - files: 2.1.0
  - files_automatedtagging: 1.19.0
  - files_downloadlimit: 2.0.0
  - 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
  - flow_notifications: 1.9.0
  - forms: 4.2.4
  - geoblocker: 0.5.14
  - gpoddersync: 3.9.0
  - gpxpod: 5.0.18
  - groupfolders: 17.0.1
  - integration_tmdb: 1.0.4
  - logreader: 2.14.0
  - lookup_server_connector: 1.17.0
  - mail: 3.7.5
  - maps: 1.4.0
  - memories: 7.3.1
  - news: 25.0.0-alpha8
  - nextcloud_announcements: 1.18.0
  - notes: 4.10.0
  - notifications: 2.17.0
  - oauth2: 1.17.0
  - password_policy: 1.19.0
  - passwords: 2024.7.20
  - photos: 2.5.0
  - previewgenerator: 5.5.0
  - privacy: 1.13.0
  - provisioning_api: 1.19.0
  - recognize: 7.0.3
  - recommendations: 2.1.0
  - related_resources: 1.4.0
  - repod: 2.3.3
  - richdocuments: 8.4.3
  - richdocumentscode_arm64: 24.4.502
  - serverinfo: 1.19.0
  - settings: 1.12.0
  - sharebymail: 1.19.0
  - spreed: 19.0.7
  - survey_client: 1.17.0
  - suspicious_login: 7.0.0
  - systemtags: 1.19.0
  - tables: 0.7.4
  - tasks: 0.16.0
  - text: 3.10.1
  - theming: 2.4.0
  - twofactor_backupcodes: 1.18.0
  - twofactor_nextcloud_notification: 3.9.0
  - twofactor_totp: 11.0.0-dev
  - updatenotification: 1.19.1
  - user_status: 1.9.0
  - viewer: 2.3.0
  - weather_status: 1.9.0
  - workflowengine: 2.11.0
Disabled:
  - encryption: 2.17.0
  - files_external: 1.21.0 (installed 1.21.0)
  - firstrunwizard: 2.18.0 (installed 2.17.0)
  - support: 1.12.0 (installed 1.11.0)
  - user_ldap: 1.20.0

Nextcloud Signing status

No errors have been found.

Nextcloud Logs

No response

Additional info

No response

[ChristophWurst]

@miaulalala please triage. This could be fixed by your incremental sync PR.

[miaulalala]

@miaulalala please triage. This could be fixed by your incremental sync PR.

Yep pretty sure that is fixed when using an incremental sync. But I'm wondering why the calendar is synced every hour. @Markoise did you manually set a sync period for every hour?

[Markoise]

Yep pretty sure that is fixed when using an incremental sync. But I'm wondering why the calendar is synced every hour. @Markoise did you manually set a sync period for every hour?

Yes, I did.

[miaulalala]

Yep pretty sure that is fixed when using an incremental sync. But I'm wondering why the calendar is synced every hour. @Markoise did you manually set a sync period for every hour?

Yes, I did.

Ok, that's fine - this will be fixed in Nextcloud 30, the job will be up to 99% faster. Are you ok to close?

[Markoise]

Sure. Thanks a lot. 🙂

[Markoise]

I also get these messages in Nextcloud 30

Used memory grew by more than 50 MB when executing job OCA\DAV\BackgroundJob\RefreshWebcalJob (id: 74290, arguments: {“principaluri”: “principals/users/markus”, “uri”: “calendargooglecom-1”}): 113.7 MB (before: 51.3 MB)

[mayonezo]

Nextcloud 30 and I get a bunch of these:
{"reqId":"swEDeTs7A3dPZHgjVdW3","level":2,"time":"2024-09-23T14:12:34+02:00","remoteAddr":"","user":"--","app":"cron","method":"","url":"--","message":"Used memory grew by more than 50 MB when executing job OCA\\DAV\\BackgroundJob\\RefreshWebcalJob (id: 1275988, arguments: {\"principaluri\":\"principals\\/users\\/%user%\",\"uri\":\"calendargooglecom\"}): 83.6 MB (before: 10 MB)","userAgent":"--","version":"30.0.0.14","data":{"app":"cron"}}

[mayonezo]

@miaulalala Could you please reopen the issue?

[miaulalala]

Sure thing

Is your calendar a holiday subscription calendar or is it a regular calendar that changes a lot?

[Markoise]

In this case, it's my wife's Google calendar. But it doesn't change very much. Sometimes an appointment is moved, sometimes a new one is created. But that happens maybe once a day. The message in the log for this calendar appears every hour.

Subscribed school vacation, football and public holiday calendars do not cause a log entry.

[miaulalala]

Hm, it's interesting for sure. So, the sync interval provided by the subscription calendar is taken into account now, so the hourly message isn't really surprising if this is the provided sync interval; but I'm still suprised that the delta sync is not helping for your calendar subscription. Can you do an export of this calendar before and after the sync and use a diffing tool to check what exactly is different with those calendars? Please let me know what you find.

[Markoise]

Okay. I have compared two files.
No changes have been made in Google Calendar. Nevertheless, the ICS files that I created with the Nextcloud app (calendar backup) are different.

In both ICS files there are DTSTAMP= entries per appointment.
Here is a different value for all appointments. This seems to be the date and time of the export.

Nothing else is different. The files are 966 kb in size and contain appointments from 2013 onwards.

[miaulalala]

Okay. I have compared two files. No changes have been made in Google Calendar. Nevertheless, the ICS files that I created with the Nextcloud app (calendar backup) are different.

In both ICS files there are DTSTAMP= entries per appointment. Here is a different value for all appointments. This seems to be the date and time of the export.

Nothing else is different. The files are 966 kb in size and contain appointments from 2013 onwards.

Yeah I think the export generates a new DTSTAMP. We ignore the DTSTAMP when doing a sync anyway, so that shouldn't lead to a write. Lemme think some more, maybe I can find a debug strategy that will tell us more. Are you opposed to patching your instance with some debug logging?

[Markoise]

Yeah I think the export generates a new DTSTAMP. We ignore the DTSTAMP when doing a sync anyway, so that shouldn't lead to a write. Lemme think some more, maybe I can find a debug strategy that will tell us more. Are you opposed to patching your instance with some debug logging?

If you tell me how to do it and if it has any other effects, I can do it.