Contents of subscribed calendars almost completely disappear after invoking cron.php

AxelStieglbauer commented 4 years ago

Steps to reproduce

Subscribe a new calendar.
Run cron.php

Expected behaviour

Calendar stay in database (mysql) and stay visible in the NextCloud web GUI. After subscrabing the same calendar file, all the calendar entires are stored in the DB again and shown in the web GUI.

Actual behaviour

Almost all calendar entries of the subscribed calendars are deleted in the DB and therefore not shown on the NextCloud web GUI. In one subscribed calendar only one entry stays in the database, in the other subscribed calendar all entries are deleted.

Server configuration detail

Operating system: Linux 5.4.51-v7l+ #1326 SMP Fri Jul 17 10:51:18 BST 2020 armv7l

Webserver: Apache (fpm-fcgi)

Database: mysql 10.3.22

PHP version:

7.3.19-1~deb10u1 Modules loaded: Core, date, libxml, openssl, pcre, zlib, filter, hash, Reflection, SPL, session, sodium, standard, cgi-fcgi, mysqlnd, PDO, xml, bz2, calendar, ctype, curl, dom, mbstring, fileinfo, ftp, gd, gettext, gmp, iconv, igbinary, imagick, intl, json, ldap, exif, mysqli, pdo_mysql, Phar, posix, readline, redis, shmop, SimpleXML, smbclient, sockets, sysvmsg, sysvsem, sysvshm, tokenizer, wddx, xmlreader, xmlwriter, xsl, zip, libsmbclient, Zend OPcache

Nextcloud version: 18.0.7 - 18.0.7.1

Updated from an older Nextcloud/ownCloud or fresh install: Updated from an oleder version. 17 I think - or even 16.

Where did you install Nextcloud from: https://ownyourbits.com/nextcloudpi/

Signing status

Array ( )

List of activated apps

``` Enabled: - accessibility: 1.4.0 - activity: 2.11.0 - bookmarks: 3.2.5 - calendar: 2.0.3 - checksum: 0.4.4 - circles: 0.18.9 - cloud_federation_api: 1.1.0 - comments: 1.8.0 - contacts: 3.3.0 - dav: 1.14.0 - deck: 1.0.5 - drawio: 0.9.6 - epubreader: 1.4.2 - extract: 1.2.4 - federatedfilesharing: 1.8.0 - federation: 1.8.0 - files: 1.13.1 - files_external: 1.9.0 - files_linkeditor: 1.1.1 - files_lock: 0.8.3 - files_pdfviewer: 1.7.0 - files_rightclick: 0.15.2 - files_sharing: 1.10.1 - files_trashbin: 1.8.0 - files_versions: 1.11.0 - files_videoplayer: 1.7.0 - firstrunwizard: 2.7.0 - groupfolders: 6.0.6 - issuetemplate: 0.6.0 - logreader: 2.3.0 - lookup_server_connector: 1.6.0 - mail: 1.4.1 - metadata: 0.12.0 - news: 14.1.11 - nextcloud_announcements: 1.7.0 - nextcloudpi: 0.0.1 - notes: 3.6.0 - notifications: 2.6.0 - oauth2: 1.6.0 - ocdownloader: 1.7.8 - password_policy: 1.8.0 - photos: 1.0.0 - previewgenerator: 2.3.0 - privacy: 1.2.0 - provisioning_api: 1.8.0 - quota_warning: 1.7.0 - ransomware_detection: 0.7.1 - ransomware_protection: 1.6.1 - recommendations: 0.6.0 - serverinfo: 1.8.0 - settings: 1.0.0 - sharebymail: 1.8.0 - socialsharing_email: 2.0.0 - spreed: 8.0.10 - support: 1.1.1 - survey_client: 1.6.0 - systemtags: 1.8.0 - tasks: 0.13.2 - text: 2.0.0 - theming: 1.9.0 - twofactor_backupcodes: 1.7.0 - updatenotification: 1.8.0 - viewer: 1.2.0 - workflow_pdf_converter: 1.3.2 - workflowengine: 2.0.0 Disabled: - admin_audit - breezedark - encryption - previewgenerator.orig - user_ldap ```

Configuration (config/config.php)

``` { "passwordsalt": "***REMOVED SENSITIVE VALUE***", "secret": "***REMOVED SENSITIVE VALUE***", "trusted_domains": { "0": "localhost", "5": "nextcloudpi.local", "7": "nextcloudpi", "8": "nextcloudpi.lan", "11": "88.66.249.125", "1": "192.168.1.230", "4": "stieg-muc.spdns.de" }, "datadirectory": "***REMOVED SENSITIVE VALUE***", "dbtype": "mysql", "version": "18.0.7.1", "overwrite.cli.url": "https:\/\/stieg-muc.spdns.de\/", "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***", "memcache.local": "\\OC\\Memcache\\Redis", "memcache.locking": "\\OC\\Memcache\\Redis", "redis": { "host": "***REMOVED SENSITIVE VALUE***", "port": 0, "timeout": 0, "password": "***REMOVED SENSITIVE VALUE***" }, "tempdirectory": "\/media\/USBdrive\/ncdata\/tmp", "mail_smtpmode": "smtp", "mail_smtpauthtype": "LOGIN", "mail_from_address": "***REMOVED SENSITIVE VALUE***", "mail_domain": "***REMOVED SENSITIVE VALUE***", "preview_max_x": "2048", "preview_max_y": "2048", "jpeg_quality": "60", "overwriteprotocol": "https", "maintenance": false, "logfile": "\/media\/USBdrive\/ncdata\/nextcloud.log", "loglevel": "2", "log_type": "file", "theme": "", "mail_sendmailmode": "smtp", "mail_smtpsecure": "tls", "mail_smtphost": "***REMOVED SENSITIVE VALUE***", "mail_smtpport": "587", "mail_smtpauth": 1, "mail_smtpname": "***REMOVED SENSITIVE VALUE***", "mail_smtppassword": "***REMOVED SENSITIVE VALUE***", "updater.secret": "***REMOVED SENSITIVE VALUE***" } ```

Are you using external storage, if yes which one: smb

Are you using encryption: false

Are you using an external user-backend, if yes which one:

Client configuration

Browser: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Ubuntu Chromium/83.0.4103.61 Chrome/83.0.4103.61 Safari/537.36

Operating system: Ubuntu 18.04, 20.04

Logs

Web server error log

``` ```

Nextcloud log

``` {"reqId":"BTLQJe8qHnqDElJhdUTD","level":3,"time":"2020-07-21T23:18:24+00:00","remoteAddr":"","user":"--","app":"core","method":"","url":"--","message":{"Exception":"InvalidArgumentException","Message":"malformed xml string. parsing error : Calling the \"Symfony\\Component\\EventDispatcher\\EventDispatcherInterface::dispatch()\" method with the event name as the first argument is deprecated since Symfony 4.3, pass it as the second argument and provide the event object as the first argument instead. (16384)","Code":0,"Trace":[{"function":"FeedIo\\Reader\\{closure}","class":"FeedIo\\Reader\\Document","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/3rdparty/symfony/event-dispatcher/EventDispatcher.php","line":58,"function":"trigger_error","args":["*** sensitive parameter replaced ***","*** sensitive parameter replaced ***"]},{"file":"/var/www/nextcloud/lib/private/EventDispatcher/SymfonyAdapter.php","line":70,"function":"dispatch","class":"Symfony\\Component\\EventDispatcher\\EventDispatcher","type":"->","args":["\\OCA\\DAV\\CalDAV\\CalDavBackend::createCachedCalendarObject",{"__class__":"Symfony\\Component\\EventDispatcher\\GenericEvent"}]},{"file":"/var/www/nextcloud/apps/dav/lib/CalDAV/CalDavBackend.php","line":1109,"function":"dispatch","class":"OC\\EventDispatcher\\SymfonyAdapter","type":"->","args":["\\OCA\\DAV\\CalDAV\\CalDavBackend::createCachedCalendarObject",{"__class__":"Symfony\\Component\\EventDispatcher\\GenericEvent"}]},{"file":"/var/www/nextcloud/apps/dav/lib/CalDAV/WebcalCaching/RefreshWebcalService.php","line":141,"function":"createCalendarObject","class":"OCA\\DAV\\CalDAV\\CalDavBackend","type":"->","args":["21","3f32aa05-e77e-4a06-b3c5-b4a2889a315a.ics","BEGIN:VCALENDAR\r\nVERSION:2.0\r\nPRODID:-//Sabre//Sabre VObject 4.1.6//EN\r\nCALSCALE:GREGORIAN\r\nBEGIN:VEVENT\r\nDTSTAMP:20200721T231824Z\r\nDTSTART:20200717T070000Z\r\nDTEND:20200717T074500Z\r\nUID:128372-5812-\r\nDESCRIPTION:1SE432 St\r\nSUMMARY:SK\r\nLOCATION:2.2.26\r\nEND:VEVENT\r\nEND:VCALENDAR\r\n",1]},{"file":"/var/www/nextcloud/apps/dav/lib/BackgroundJob/RefreshWebcalJob.php","line":113,"function":"refreshSubscription","class":"OCA\\DAV\\CalDAV\\WebcalCaching\\RefreshWebcalService","type":"->","args":["principals/users/axel","3f32aa05-e77e-4a06-b3c5-b4a2889a315a.ics"]},{"file":"/var/www/nextcloud/lib/private/BackgroundJob/Job.php","line":61,"function":"run","class":"OCA\\DAV\\BackgroundJob\\RefreshWebcalJob","type":"->","args":[{"principaluri":"principals/users/axel","uri":"heptawebuntiscom-1"}]},{"file":"/var/www/nextcloud/apps/dav/lib/BackgroundJob/RefreshWebcalJob.php","line":106,"function":"execute","class":"OC\\BackgroundJob\\Job","type":"->","args":[{"__class__":"OC\\BackgroundJob\\JobList"},{"__class__":"OC\\Log"}]},{"file":"/var/www/nextcloud/cron.php","line":125,"function":"execute","class":"OCA\\DAV\\BackgroundJob\\RefreshWebcalJob","type":"->","args":[{"__class__":"OC\\BackgroundJob\\JobList"},{"__class__":"OC\\Log"}]}],"File":"/var/www/nextcloud/apps/news/vendor/debril/feed-io/src/FeedIo/Reader/Document.php","Line":106,"CustomMessage":"Error while running background job (class: OCA\\DAV\\BackgroundJob\\RefreshWebcalJob, arguments: Array\n(\n [principaluri] => principals/users/axel\n [uri] => heptawebuntiscom-1\n)\n)"},"userAgent":"--","version":"18.0.7.1","id":"5f177b7f0474c"} ```

Browser log

georgehrke commented 4 years ago

Can you manually open the subscribed ics file and confirm there are more events in there than in Nextcloud?

Is that really the entire Nextcloud.log? If that's the case, please increase the log-level to more verbose output and run cron.php again.

AxelStieglbauer commented 4 years ago

Can you manually open the subscribed ics file and confirm there are more events in there than in Nextcloud?

There are more events in the ICS files than in NextCloud.

I have 2 subscribed calendars WebUntis and Facebook. Both show almost the same behaviour. The Facebook calendar is completely empty after a run of cron.php, in the WebUntis calendar only the first entry remains. When I delete the calendars on NextCloud and resubscribe them, all events are there again.

Is that really the entire Nextcloud.log? If that's the case, please increase the log-level to more verbose output and run cron.php again.

That was the only log entry that seemed relevant to me. The other entries were from "News" and said that the subscribed feed wasn't well-formed and therefore could not be parse or the domain to fetch the feed from was unavailable.

There is a strange thing: After my NextCloud instance showing the described behaviour for month, the behaviour vanished while writing this comment. It seems all events in the subscribed calendars survive a run of cron.php now. I have neither updated NextCloud nor the Calendar app since filing the bug.

ndx1905-github commented 2 years ago

Looks like I have a similar issue, but with slightly different symptoms.

When I subscribe to an external read only calendar (in my case icloud based), no events ever show on the web GUI. However, clients that connect to my nextcloud server do show those external subscribed calendars and all events show.

It looks like it's only the web GUI that does not update, but nextcloud calendar clients do.

Any clue how to solve this ?

tcitworld commented 2 years ago

@ndx1905-github This is because subscriptions are cached on the server for the Nextcloud Calendar app, not for other clients. The caching process might encounter parsing errors that may be tolerated in other clients.

Increase loglevel and check your nextcloud.log file for related errors when you add the subscription.

ndx1905-github commented 2 years ago

Thanks for the quick reply Here is the debug. I see some "deprecated" and some "subscription could not be parsed" as you said, but can't make much sense of it.

{"reqId":"dOHug8YUc0QlSCghvABN","level":0,"time":"2022-03-21T19:18:32+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"maps","method":"MKCOL","url":"/remote.php/dav/calendars/nicolas/p58-caldavicloudcom","message":"/appinfo/app.php is deprecated, use \OCP\AppFramework\Bootstrap\IBootstrap on the application class instead.","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15","version":"23.0.2.1"} {"reqId":"dOHug8YUc0QlSCghvABN","level":1,"time":"2022-03-21T19:18:32+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"no app in context","method":"MKCOL","url":"/remote.php/dav/calendars/nicolas/p58-caldavicloudcom","message":"Deprecated event type for \OCA\DAV\CalDAV\CalDavBackend::createSubscription: Symfony\Component\EventDispatcher\GenericEvent is used","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15","version":"23.0.2.1"} {"reqId":"00zWfxATk5uTZRZF8GNZ","level":0,"time":"2022-03-21T19:18:33+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"maps","method":"PROPFIND","url":"/remote.php/dav/files/nicolas/Documents","message":"/appinfo/app.php is deprecated, use \OCP\AppFramework\Bootstrap\IBootstrap on the application class instead.","userAgent":"Mozilla/5.0 (Macintosh) mirall/3.4.2git (build 9042) (Nextcloud, osx-21.4.0 ClientArchitecture: x86_64 OsArchitecture: x86_64)","version":"23.0.2.1"} {"reqId":"dOHug8YUc0QlSCghvABN","level":0,"time":"2022-03-21T19:18:34+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"dav","method":"MKCOL","url":"/remote.php/dav/calendars/nicolas/p58-caldavicloudcom","message":"Subscription 26 could not be parsed","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15","version":"23.0.2.1"} {"reqId":"olmn4jmTHZfjAYblFTTY","level":0,"time":"2022-03-21T19:18:34+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"maps","method":"PROPFIND","url":"/remote.php/dav/calendars/nicolas/p58-caldavicloudcom/","message":"/appinfo/app.php is deprecated, use \OCP\AppFramework\Bootstrap\IBootstrap on the application class instead.","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15","version":"23.0.2.1"} {"reqId":"BYXY7fWi1o9inNzwmZf7","level":0,"time":"2022-03-21T19:18:34+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"maps","method":"REPORT","url":"/remote.php/dav/calendars/nicolas/p58-caldavicloudcom/","message":"/appinfo/app.php is deprecated, use \OCP\AppFramework\Bootstrap\IBootstrap on the application class instead.","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15","version":"23.0.2.1"} {"reqId":"cbSzoe5Db1KpqtvKLQl5","level":0,"time":"2022-03-21T19:18:35+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"maps","method":"REPORT","url":"/remote.php/dav/calendars/nicolas/p58-caldavicloudcom/","message":"/appinfo/app.php is deprecated, use \OCP\AppFramework\Bootstrap\IBootstrap on the application class instead.","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15","version":"23.0.2.1"} {"reqId":"l5IG5W8CXzVP5q5HQHEl","level":0,"time":"2022-03-21T19:18:46+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"apporder","method":"GET","url":"/ocs/v2.php/apps/notifications/api/v2/notifications","message":"/appinfo/app.php is deprecated, use \OCP\AppFramework\Bootstrap\IBootstrap on the application class instead.","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15","version":"23.0.2.1"} {"reqId":"l5IG5W8CXzVP5q5HQHEl","level":0,"time":"2022-03-21T19:18:46+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"files_linkeditor","method":"GET","url":"/ocs/v2.php/apps/notifications/api/v2/notifications","message":"/appinfo/app.php is deprecated, use \OCP\AppFramework\Bootstrap\IBootstrap on the application class instead.","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15","version":"23.0.2.1"} {"reqId":"l5IG5W8CXzVP5q5HQHEl","level":0,"time":"2022-03-21T19:18:46+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"keeweb","method":"GET","url":"/ocs/v2.php/apps/notifications/api/v2/notifications","message":"/appinfo/app.php is deprecated, use \OCP\AppFramework\Bootstrap\IBootstrap on the application class instead.","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15","version":"23.0.2.1"} {"reqId":"l5IG5W8CXzVP5q5HQHEl","level":0,"time":"2022-03-21T19:18:46+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"maps","method":"GET","url":"/ocs/v2.php/apps/notifications/api/v2/notifications","message":"/appinfo/app.php is deprecated, use \OCP\AppFramework\Bootstrap\IBootstrap on the application class instead.","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15","version":"23.0.2.1"} {"reqId":"l5IG5W8CXzVP5q5HQHEl","level":0,"time":"2022-03-21T19:18:46+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"rainloop","method":"GET","url":"/ocs/v2.php/apps/notifications/api/v2/notifications","message":"/appinfo/app.php is deprecated, use \OCP\AppFramework\Bootstrap\IBootstrap on the application class instead.","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15","version":"23.0.2.1"} {"reqId":"l5IG5W8CXzVP5q5HQHEl","level":0,"time":"2022-03-21T19:18:46+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"side_menu","method":"GET","url":"/ocs/v2.php/apps/notifications/api/v2/notifications","message":"/appinfo/app.php is deprecated, use \OCP\AppFramework\Bootstrap\IBootstrap on the application class instead.","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15","version":"23.0.2.1"}

tcitworld commented 2 years ago

{"reqId":"dOHug8YUc0QlSCghvABN","level":0,"time":"2022-03-21T19:18:34+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"dav","method":"MKCOL","url":"/remote.php/dav/calendars/nicolas/p58-caldavicloudcom","message":"Subscription 26 could not be parsed","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15","version":"23.0.2.1"}

Yup, that's the culprit indeed. Can you try to validate your source at https://icalendar.org/validator.html ?

The next release might have more logging details with https://github.com/nextcloud/server/pull/31622, but in the meantime if you're feeling adventurous you can try to patch file apps/dav/lib/CalDAV/WebcalCaching/RefreshWebcalService.php like this:

-$this->logger->debug("Subscription $subscriptionId could not be parsed");
+$this->logger->warning("Subscription $subscriptionId could not be parsed", ['exception' => $ex]);

ndx1905-github commented 2 years ago

Mmm so indeed icalendar tells me there are two errors Problem! Found 2 errors Errors Lines not delimited by CRLF sequence [near line # 1]() Reference: RFC 5545 3.1. Content Lines Missing required PRODID property [near line # 1]() Reference: RFC 5545 3.6. Calendar Components

It's annoying that icloud can't be parsed because of that.

I'm going to try the adventurous route !

ndx1905-github commented 2 years ago

So .. I did change the RefreshWebcalService.php as indicated. However nothing changed 😕 Should I restart something?

tcitworld commented 2 years ago

Remove the subscription and recreate it.

ndx1905-github commented 2 years ago

Mmm I had done that and it didnt work

So I went back to the RefreshWebcalService.php file to check it and noticed I had changed only one line with your correction, when there were 3 lines

I've changed them all, I've removed the subscription and I've recreated it.

Same symptoms: nothing on the Web UI, but updating on all other clients

tcitworld commented 2 years ago

The change is only there to have more details in the logs.

ndx1905-github commented 2 years ago

ah ok.. silly me

I've done the modification but the log doesn't seem to be more detailed {"reqId":"DRFt8E0fQohtmVf66cDN","level":0,"time":"2022-03-22T21:57:38+00:00","remoteAddr":"192.168.1.1","user":"nicolas","app":"dav","method":"MKCOL","url":"/remote.php/dav/calendars/nicolas/p58-caldavicloudcom-2","message":"Subscription 31 could not be parsed","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15","version":"23.0.3.2"}

no-response[bot] commented 2 years ago

This issue has been automatically closed because there has been no response to our request for more information from the original author. With only the information that is currently in the issue, we don't have enough information to take action. Please reach out if you have or find the answers we need so that we can investigate further.

nextcloud / calendar