nextcloud / calendar

📆 Calendar app for Nextcloud
https://apps.nextcloud.com/apps/calendar
GNU Affero General Public License v3.0
968 stars 236 forks source link

Subscribed calendar attempting refresh 100-200 times per day #4966

Open inthreedee opened 1 year ago

inthreedee commented 1 year ago

Steps to reproduce

Background: I somehow triggered a refresh frequency limit on a subscribed calendar. I don't know how or when this first happened or if Nextcloud contributed to causing it; I only just noticed the warnings in my logs. I suspect that a caldav client, Evolution, was attempting to refresh too frequently. I have since adjusted its refresh rate. Regardless, the current situation is that the remote server is currently responding with a 503 error Your calendar software is requesting this resource too often!

Issue Details: My Nextcloud is now attempting 100-200 refreshes of this calendar per day. It appears to try every 5 minutes for a while, then gives up for a while, then tries again every 5 minutes for another while.

According to the docs, the default value of calendarSubscriptionRefreshRate is 1x per week. I manually configured it to 1x per day on the off chance that the default setting had somehow changed to 5 minutes. No apparent change in behavior.

Repro:

  1. Subscribe to https://cantonbecker.com/astronomy-calendar/
  2. Trigger the remote server's refresh frequency limit (I don't know how this happened as explained above)
  3. Nextcloud continues to attempt refreshes every 5 minutes up to 100-200 times per day
  4. Configure calendarSubscriptionRefreshRate to P1D. Still happens.

Expected behavior

Nextcloud should not be flooding this poor server with refresh requests 100-200 times per day.

Actual behaviour

I don't know if the problem is that calendarSubscriptionRefreshRate is not being respected or if the 503 response from the remote server has triggered a different, more aggressive refresh policy until a successful connection is made. Either way, my logs show 164 attempts to refresh on Feb 5th, 204 on the 6th, and 122 so far for today the 7th.

Calendar app version

4.2.3

CalDAV-clients used

Evolution, currently refreshing 1x per day

Browser

Firefox 109

Client operating system

Arch Linux

Server operating system

Ubuntu Server 22.04.1 LTS

Web server

Apache

Database engine version

MySQL

PHP engine version

PHP 8.0

Nextcloud version

25.0.3 installed from Snap

Updated from an older installed version or fresh install

Updated from an older version

List of activated apps

Enabled:
  - activity: 2.17.0
  - bruteforcesettings: 2.5.0
  - calendar: 4.2.3
  - circles: 25.0.0
  - cloud_federation_api: 1.8.0
  - comments: 1.15.0
  - contacts: 5.1.0
  - contactsinteraction: 1.6.0
  - dashboard: 7.5.0
  - dav: 1.24.0
  - deck: 1.8.3
  - encryption: 2.13.0
  - federatedfilesharing: 1.15.0
  - federation: 1.15.0
  - files: 1.20.1
  - files_pdfviewer: 2.6.0
  - files_rightclick: 1.4.0
  - files_sharing: 1.17.0
  - files_trashbin: 1.15.0
  - files_versions: 1.18.0
  - firstrunwizard: 2.14.0
  - logreader: 2.10.0
  - lookup_server_connector: 1.13.0
  - mail: 2.2.2
  - maps: 0.2.4
  - memories: 4.10.3
  - music: 1.8.1
  - nextcloud_announcements: 1.14.0
  - notifications: 2.13.1
  - oauth2: 1.13.0
  - password_policy: 1.15.0
  - photos: 2.0.1
  - privacy: 1.9.0
  - provisioning_api: 1.15.0
  - recommendations: 1.4.0
  - related_resources: 1.0.3
  - serverinfo: 1.15.0
  - settings: 1.7.0
  - sharebymail: 1.15.0
  - spreed: 15.0.3
  - support: 1.8.0
  - systemtags: 1.15.0
  - tasks: 0.14.5
  - text: 3.6.0
  - theming: 2.0.1
  - timetracker: 0.0.77
  - twofactor_backupcodes: 1.14.0
  - twofactor_totp: 7.0.0
  - user_status: 1.5.0
  - viewer: 1.9.0
  - weather_status: 1.5.0
  - workflowengine: 2.7.0
Disabled:
  - admin_audit
  - backup: 1.2.0
  - event_update_notification: 2.0.0
  - files_external
  - files_texteditor: 2.15.0
  - notes: 4.6.0
  - richdocuments: 7.1.0
  - richdocumentscode_arm64: 22.5.802
  - social: 0.4.2
  - survey_client: 1.11.0
  - suspicious_login
  - user_ldap

Nextcloud configuration

{
    "system": {
        "apps_paths": [
            {
                "path": "\/snap\/nextcloud\/current\/htdocs\/apps",
                "url": "\/apps",
                "writable": false
            },
            {
                "path": "\/var\/snap\/nextcloud\/current\/nextcloud\/extra-apps",
                "url": "\/extra-apps",
                "writable": true
            }
        ],
        "supportedDatabases": [
            "mysql"
        ],
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "memcache.local": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "***REMOVED SENSITIVE VALUE***",
            "port": 0
        },
        "log_type": "file",
        "logfile": "\/var\/snap\/nextcloud\/current\/logs\/nextcloud.log",
        "logfilemode": 416,
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "***REMOVED SENSITIVE VALUE***",
            "***REMOVED SENSITIVE VALUE***",
            "***REMOVED SENSITIVE VALUE***"
        ],
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "dbtype": "mysql",
        "version": "25.0.3.2",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbport": "",
        "dbtableprefix": "oc_",
        "mysql.utf8mb4": true,
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "installed": true,
        "twofactor_enforced": "true",
        "twofactor_enforced_groups": [],
        "twofactor_enforced_excluded_groups": [],
        "mail_smtpmode": "smtp",
        "mail_smtpsecure": "tls",
        "mail_sendmailmode": "smtp",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "587",
        "mail_smtpauthtype": "LOGIN",
        "mail_smtpauth": 1,
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "maintenance": false,
        "loglevel": 0,
        "overwriteprotocol": "https",
        "app_install_overwrite": [
            "files_texteditor"
        ],
        "overwrite.cli.url": "***REMOVED SENSITIVE VALUE***",
        "default_phone_region": "US",
        "allow_local_remote_servers": true,
        "memories.exiftool": "\/var\/snap\/nextcloud\/33060\/nextcloud\/extra-apps\/memories\/exiftool-bin\/exiftool-aarch64-glibc"
    }
}

Web server error log

No response

Log file

{"reqId":"lhG7cXe6HcmCHkpY7o4F","level":2,"time":"2023-02-07T13:49:56+00:00","remoteAddr":"","user":"--","app":"dav","method":"","url":"--","message":"Subscription 1 could not be refreshed due to a network error","userAgent":"--","version":"25.0.3.2","exception":{"Exception":"GuzzleHttp\\Exception\\ServerException","Message":"Server error: `GET https://cantonbecker.com/astronomy-calendar-files/astrocal.ics` resulted in a `503 Service Temporarily Unavailable` response:\n<h1>503 Service Temporarily Unavailable</h1><p>Your calendar software is requesting this resource too often!\n\t\t\t<br />\n\t (truncated...)\n","Code":503,"Trace":[{"file":"/snap/nextcloud/33503/htdocs/3rdparty/guzzlehttp/guzzle/src/Middleware.php","line":69,"function":"create","class":"GuzzleHttp\\Exception\\RequestException","type":"::"},{"file":"/snap/nextcloud/33503/htdocs/3rdparty/guzzlehttp/promises/src/Promise.php","line":204,"function":"GuzzleHttp\\{closure}","class":"GuzzleHttp\\Middleware","type":"::","args":["*** sensitive parameters replaced ***"]},{"file":"/snap/nextcloud/33503/htdocs/3rdparty/guzzlehttp/promises/src/Promise.php","line":153,"function":"callHandler","class":"GuzzleHttp\\Promise\\Promise","type":"::"},{"file":"/snap/nextcloud/33503/htdocs/3rdparty/guzzlehttp/promises/src/TaskQueue.php","line":48,"function":"GuzzleHttp\\Promise\\{closure}","class":"GuzzleHttp\\Promise\\Promise","type":"::","args":["*** sensitive parameters replaced ***"]},{"file":"/snap/nextcloud/33503/htdocs/3rdparty/guzzlehttp/promises/src/Promise.php","line":248,"function":"run","class":"GuzzleHttp\\Promise\\TaskQueue","type":"->"},{"file":"/snap/nextcloud/33503/htdocs/3rdparty/guzzlehttp/promises/src/Promise.php","line":224,"function":"invokeWaitFn","class":"GuzzleHttp\\Promise\\Promise","type":"->"},{"file":"/snap/nextcloud/33503/htdocs/3rdparty/guzzlehttp/promises/src/Promise.php","line":269,"function":"waitIfPending","class":"GuzzleHttp\\Promise\\Promise","type":"->"},{"file":"/snap/nextcloud/33503/htdocs/3rdparty/guzzlehttp/promises/src/Promise.php","line":226,"function":"invokeWaitList","class":"GuzzleHttp\\Promise\\Promise","type":"->"},{"file":"/snap/nextcloud/33503/htdocs/3rdparty/guzzlehttp/promises/src/Promise.php","line":62,"function":"waitIfPending","class":"GuzzleHttp\\Promise\\Promise","type":"->"},{"file":"/snap/nextcloud/33503/htdocs/3rdparty/guzzlehttp/guzzle/src/Client.php","line":187,"function":"wait","class":"GuzzleHttp\\Promise\\Promise","type":"->"},{"file":"/snap/nextcloud/33503/htdocs/lib/private/Http/Client/Client.php","line":218,"function":"request","class":"GuzzleHttp\\Client","type":"->"},{"file":"/snap/nextcloud/33503/htdocs/apps/dav/lib/CalDAV/WebcalCaching/RefreshWebcalService.php","line":217,"function":"get","class":"OC\\Http\\Client\\Client","type":"->"},{"file":"/snap/nextcloud/33503/htdocs/apps/dav/lib/CalDAV/WebcalCaching/RefreshWebcalService.php","line":89,"function":"queryWebcalFeed","class":"OCA\\DAV\\CalDAV\\WebcalCaching\\RefreshWebcalService","type":"->"},{"file":"/snap/nextcloud/33503/htdocs/apps/dav/lib/BackgroundJob/RefreshWebcalJob.php","line":115,"function":"refreshSubscription","class":"OCA\\DAV\\CalDAV\\WebcalCaching\\RefreshWebcalService","type":"->"},{"file":"/snap/nextcloud/33503/htdocs/lib/public/BackgroundJob/Job.php","line":78,"function":"run","class":"OCA\\DAV\\BackgroundJob\\RefreshWebcalJob","type":"->"},{"file":"/snap/nextcloud/33503/htdocs/lib/public/BackgroundJob/Job.php","line":64,"function":"start","class":"OCP\\BackgroundJob\\Job","type":"->"},{"file":"/snap/nextcloud/33503/htdocs/apps/dav/lib/BackgroundJob/RefreshWebcalJob.php","line":108,"function":"execute","class":"OCP\\BackgroundJob\\Job","type":"->"},{"file":"/snap/nextcloud/33503/htdocs/cron.php","line":152,"function":"execute","class":"OCA\\DAV\\BackgroundJob\\RefreshWebcalJob","type":"->"}],"File":"/snap/nextcloud/33503/htdocs/3rdparty/guzzlehttp/guzzle/src/Exception/RequestException.php","Line":113,"message":"Subscription 1 could not be refreshed due to a network error","exception":[],"CustomMessage":"Subscription 1 could not be refreshed due to a network error"},"id":"63e25e48a9f8d"}

Browser log

No response

Additional info

No response

tcitworld commented 1 year ago

Hi,

calendarSubscriptionRefreshRate is the default refresh rate. If your client has modified the CalDAV property {http://apple.com/ns/ical/}refreshrate, then it's being used instead.

If you can't find what in your client triggered this, you can update the value inside the database:

SELECT * FROM oc_calendarsubscriptions WHERE principaluri = 'principals/users/%your_user_id%';
UPDATE oc_calendarsubscriptions SET refreshrate = 'P1D' WHERE id = '%the_calendar_subscription_id_you_found_above%';
tcitworld commented 1 year ago

There's currently no issue about having this option in the Calendar app UI, but we could have one (with some kind of minimal setting).

inthreedee commented 1 year ago

To clarify, this issue is not about what triggered the problem, but that my Nextcloud server (not my client) is currently attempting to refresh this calendar 100-200x per day regardless of what I set calendarSubscriptionRefreshRate to.

tcitworld commented 1 year ago

What I said is that there's a setting per calendar subscription that overrides what calendarSubscriptionRefreshRate is set to.

Also there's the new REFRESH-INTERVAL icalendar property that can be followed as well for a calendar.

inthreedee commented 1 year ago

Oh, sorry, I misunderstood. I know clients can refresh separately as often as they're configured for, but you're saying a client can change the server's per-calendar refresh rate setting?

When I connected my Nextcloud calendars to my iPhone, it automatically pulled in the subscription I had made on my Nextcloud web interface. So if I'm understanding you correctly now, that would mean my iPhone is likely responsible for making my Nextcloud server attempt a refresh every 5 minutes.

If that's the case, I went looking and don't see any way on my iPhone to change the refresh rate for this situation. The obvious setting would be its "Fetch" interval, but it's set to 15 minutes, not 5 minutes, so that doesn't explain what's going on.

Is there a way to limit this serverside using the occ tool, similar to modifying calendarSubscriptionRefreshRate?

tcitworld commented 1 year ago

I don't think the fetch interval manages the refresh rate as well. It's more about checking new changes for regular calendars.

Only the Apple macOS Calendar app has such a setting afaik (see "Refresh a subscribed calendar").

Last time I checked, Evolution didn't have support for detecting subscriptions over CalDAV, so it's unlikely it was the culprit.

In any case, if you can't access the database, I would simply advise removing the subscription from the Calendar Nextcloud app and try adding it again (maybe after a while to avoid being blocked again).

inthreedee commented 1 year ago

Last time I checked, Evolution didn't have support for detecting subscriptions over CalDAV, so it's unlikely it was the culprit.

Just an FYI, you're right, it does not appear to and I had to add it in as its own separate subscription with its own refresh rate.

I do have access to the database, but I'd prefer not to go mucking around in it if I can help it. Even if I did, wouldn't my device just change it again? I obviously don't know how that works.

There's currently no issue about having this option in the Calendar app UI, but we could have one (with some kind of minimal setting).

In any case, this seems like it might be a prudent thing to look into. I'm not sure it needs to be a UI element though? It's not really a user-facing problem that they'd need to address. Users wouldn't even know that it would need to be addressed since the only negative effect is log spam and possibly annoying the remote server.

If it were to be configurable, I'd say it'd be an admin who would notice the issue and want to configure it, therefore an occ command would be the appropriate place for it. I envision this as one config value that, when set, would enforce the specified limit globally across all subscribed calendars. Calendars may attempt to refresh less frequently than the limit, but not more frequently.

miaulalala commented 1 year ago

In any case, this seems like it might be a prudent thing to look into. I'm not sure it needs to be a UI element though? It's not really a user-facing problem that they'd need to address. Users wouldn't even know that it would need to be addressed since the only negative effect is log spam and possibly annoying the remote server.

An occ command could be the way to go here. @tcitworld what do you think?

tcitworld commented 1 year ago

Yes, that would be the minimal app setting I was referring to. Otherwise users could set the refresh rate for their calendars (accidentally or voluntarily) to something that would not be sustainable for the source server and for NC itself.

inthreedee commented 1 year ago

An update: I did as suggested and removed the subscribed calendar from my Nextcloud web interface for a day to allow the frequency limit to pass, then re-added it. It's been 2 days and, so far, I have not tripped the frequency limit again.

But, given that I don't know how or why the limit was exceeded in the first place, it seems like a good idea to have some occ setting with a reasonable default minimum value that would prevent a rogue client from doing this again in the future.

Is that something we want to have? Should I create a new feature request or can we rename this one and use it since it has all the background info?

ernolf commented 1 year ago

@tcitworld

If you can't find what in your client triggered this, you can update the value inside the database:

SELECT * FROM oc_calendarsubscriptions WHERE principaluri = 'principals/users/%your_user_id%';
UPDATE oc_calendarsubscriptions SET refreshrate = 'P1D' WHERE id = '%the_calendar_subscription_id_you_found_above%';

This is the way I handled this until now, as admin. But non admin users without direct database-access can not do that. An example: subscribed calendars with religious or legal holidays or moon phases can be upated once a month or even once a year while subscribed personal google callendars would have to be synchronized up to every 15 minutes or sometimes even more often depending on the individual case. It would be a great enhancement, if this setting could be managed in the edit dialog screen of the subscribed calendar.

Something like Refreshrate: default (refreshrate = null, the standard behaviour like it is now, dealt by the oc_appconfig. dav calendarSubscriptionRefreshRate) and a per calendar value.

A "Synchronize now" buton would be a great tool as wel. I do that now with this workaround:

Find out the background-job id with occ background-job:list -c "OCA\DAV\BackgroundJob\RefreshWebcalJob"

then I run it:

occ background-job:execute --force-execute -- <job-id>

This, like the other solutions that require direct database access, is only for server administrators with terminal access to the server.


EDIT: This script gives the means to set everything as described above:

Install it with:

sudo wget -qO /usr/local/bin/nc-subscribed-calendar https://global-social.net/script/nc-subscribed-calendar
sudo chmod +x /usr/local/bin/nc-subscribed-calendar

.. then simply run it:

nc-subscribed-calendar

.. it guides self explanatory through the steps.

ernolf