[Tickets #13034] Re: CalDav Sync with Kolab Backend
[email protected] Sat, 11 May 2019 23:49:28 +0000
| Newsgroups | gmane.comp.horde.bugs |
|---|---|
| Message-ID | <[email protected]> |
DO NOT REPLY TO THIS MESSAGE. THIS EMAIL ADDRESS IS NOT MONITORED. Ticket URL: https://bugs.horde.org/ticket/13034 ------------------------------------------------------------------------------ Ticket | 13034 Updated By | [email protected] Summary | CalDav Sync with Kolab Backend Queue | Synchronization Version | Git master Type | Bug State | No Feedback Priority | 2. Medium Milestone | Patch | Owners | ------------------------------------------------------------------------------ [email protected] (2019-05-11 23:49) wrote: Here is the only backtraces I see (after eliminating some others which were all red herings). This backtrace comes at the very beginning of a CalDaV session and only once: ``` 2019-05-12T00:48:57+02:00 EMERG: HORDE Invalid VObject, line 1 did not follow the icalendar/vcard format [pid 17266 on line 143 of "/usr/share/php/Sabre/VObject/Reader.php"] 2019-05-12T00:48:57+02:00 DEBUG: HORDE 1. Horde_Rpc_Webdav->getResponse() /usr/share/horde/rpc.php:160 2. Sabre\DAV\Server->exec() /usr/share/php/Horde/Rpc/Webdav.php:66 3. Sabre\DAV\Server->invokeMethod() /usr/share/php/Sabre/DAV/Server.php:214 4. call_user_func() /usr/share/php/Sabre/DAV/Server.php:474 5. Sabre\DAV\Server->httpReport() 6. Sabre\DAV\Server->broadcastEvent() /usr/share/php/Sabre/DAV/Server.php:1066 7. call_user_func_array() /usr/share/php/Sabre/DAV/Server.php:433 8. Sabre\CalDAV\Plugin->report() 9. Sabre\CalDAV\Plugin->calendarQueryReport() /usr/share/php/Sabre/CalDAV/Plugin.php:265 10. Sabre\CalDAV\Calendar->calendarQuery() /usr/share/php/Sabre/CalDAV/Plugin.php:591 11. Sabre\CalDAV\Backend\AbstractBackend->calendarQuery() /usr/share/php/Sabre/CalDAV/Calendar.php:372 12. Sabre\CalDAV\Backend\AbstractBackend->validateFilterForObject() /usr/share/php/Sabre/CalDAV/Backend/AbstractBackend.php:119 13. Sabre\VObject\Reader::read() /usr/share/php/Sabre/CalDAV/Backend/AbstractBackend.php:147 14. Sabre\VObject\Reader::readLine() /usr/share/php/Sabre/VObject/Reader.php:70 2019-05-12T00:48:57+02:00 DEBUG: HORDE [horde] Max memory usage: 58720256 bytes [pid 18996 on line 613 of "/usr/share/php/Horde/Registry.php"] 2019-05-12T00:48:59+02:00 EMERG: HORDE Allowed memory size of 536870912 bytes exhausted (tried to allocate 467668992 bytes) [pid 17266 on line 130 of "/usr/share/php/Horde/ErrorHandler.php"] 2019-05-12T00:48:59+02:00 DEBUG: HORDE 1. Horde_ErrorHandler::catchFatalError() 2019-05-12T00:48:59+02:00 WARN: HORDE PHP ERROR: Cannot modify header information - headers already sent [pid 17266 on line 0 of "Unknown"] 2019-05-12T00:48:59+02:00 DEBUG: HORDE 1. Horde_ErrorHandler::errorHandler() ``` Then I see similar log passages for each event that's being exchanged between client and server. Some look like this: ``` 2019-05-11T23:41:00+00:00 DEBUG: HORDE Load config file (conf.php; app: horde) [pid 25876 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-11T23:41:00+00:00 DEBUG: HORDE Load config file (nls.php; app: horde) [pid 25876 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-11T23:41:00+00:00 DEBUG: HORDE [horde] Horde_Rpc::__construct complete [pid 25876 on line 45 of "/usr/share/php/Horde/Rpc/Webdav.php"] 2019-05-11T23:41:00+00:00 DEBUG: HORDE Horde_Rpc::authorize() starting [pid 25876 on line 137 of "/usr/share/horde/rpc.php"] 2019-05-11T23:41:00+00:00 DEBUG: HORDE Load config file (prefs.php; app: horde) [pid 25876 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-11T23:41:00+00:00 DEBUG: HORDE Load config file (conf.php; app: horde) [pid 25876 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-11T23:41:00+00:00 DEBUG: HORDE Load config file (conf.php; app: ) [pid 25876 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-11T23:41:01+00:00 DEBUG: HORDE [kronolith] Load config file (conf.php; app: kronolith) [pid 25876 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-11T23:41:01+00:00 DEBUG: HORDE [kronolith] Load config file (prefs.php; app: kronolith) [pid 25876 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] Driver "Horde_Kolab_Storage_Driver_Imap": Retrieving namespaces. [pid 25876 on line 310 of "/usr/share/php/Horde/Kolab/Storage/Driver/Decorator/Base.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] Driver "Horde_Kolab_Storage_Driver_Imap": Retrieved namespaces [Horde_Kolab_Storage_Folder_Namespace_Imap: "INBOX" (personal, "/"), "user" (other, "/"), "" (shared, "/")]. [pid 25876 on line 310 of "/usr/share/php/Horde/Kolab/Storage/Driver/Decorator/Base.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] REQUEST OUT IMAP: 0 ms [getNamespace] [pid 25876 on line 276 of "/usr/share/php/Horde/Kolab/Storage/List/Tools.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] Driver "Horde_Kolab_Storage_Driver_Imap": Retrieving namespaces. [pid 25876 on line 310 of "/usr/share/php/Horde/Kolab/Storage/Driver/Decorator/Base.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] Driver "Horde_Kolab_Storage_Driver_Imap": Retrieved namespaces [Horde_Kolab_Storage_Folder_Namespace_Imap: "INBOX" (personal, "/"), "user" (other, "/"), "" (shared, "/")]. [pid 25876 on line 310 of "/usr/share/php/Horde/Kolab/Storage/Driver/Decorator/Base.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] REQUEST OUT IMAP: 0 ms [getNamespace] [pid 25876 on line 276 of "/usr/share/php/Horde/Kolab/Storage/List/Tools.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] Driver "Horde_Kolab_Storage_Driver_Imap": Retrieving namespaces. [pid 25876 on line 310 of "/usr/share/php/Horde/Kolab/Storage/Driver/Decorator/Base.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] Driver "Horde_Kolab_Storage_Driver_Imap": Retrieved namespaces [Horde_Kolab_Storage_Folder_Namespace_Imap: "INBOX" (personal, "/"), "user" (other, "/"), "" (shared, "/")]. [pid 25876 on line 310 of "/usr/share/php/Horde/Kolab/Storage/Driver/Decorator/Base.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] REQUEST OUT IMAP: 0 ms [getNamespace] [pid 25876 on line 276 of "/usr/share/php/Horde/Kolab/Storage/List/Tools.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] Load config file (prefs.php; app: horde) [pid 25876 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] [KOLAB_STORAGE] Fetching stamp WITH token. [pid 25876 on line 252 of "/usr/share/php/Horde/Kolab/Storage/Data/Cached.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] Synchronized data cache for INBOX/Kalender. [pid 25876 on line 63 of "/usr/share/php/Horde/Kolab/Storage/Synchronization/OncePerSession.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] INBOX/Kalender has 30 objects [too many to list]. [pid 25876 on line 114 of "/usr/share/horde/kronolith/lib/Driver/Kolab.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] [KOLAB_STORAGE] Fetching stamp WITH token. [pid 25876 on line 252 of "/usr/share/php/Horde/Kolab/Storage/Data/Cached.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] [KOLAB_STORAGE] Incremental folder sync: user: [email protected], folder: INBOX/Kalender, last_sync: 1557618061, current_sync: 1557618061, changes: Array ( [add] => Array ( [5319] => 59ad2597-807c-441b-89ef-01bb94fbc969 ) [del] => Array ( [5318] => 59ad2597-807c-441b-89ef-01bb94fbc969 ) ) [pid 25876 on line 351 of "/usr/share/php/Horde/Kolab/Storage/Data/Base.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] [KOLAB_STORAGE] Incremental Horde_History update for user: [email protected], folder: INBOX/Kalender, prefix: kronolith:YTozOntpOjA7czoyOToibS5nYWJyaWVsQGRhcy1uZXR6d2Vya3RlYW0uZGUiO2k6MTtzOjg6IkthbGVuZGVyIjtpOjI7czo1OiJJTkJPWCI7fQ: [pid 25876 on line 73 of "/usr/share/php/Horde/Kolab/Storage/Data/Query/History/Cache.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] [KOLAB_STORAGE] Modifying object in Horde_History: kronolith:YTozOntpOjA7czoyOToibS5nYWJyaWVsQGRhcy1uZXR6d2Vya3RlYW0uZGUiO2k6MTtzOjg6IkthbGVuZGVyIjtpOjI7czo1OiJJTkJPWCI7fQ:59ad2597-807c-441b-89ef-01bb94fbc969, uid: 5319, force: 0 [pid 25876 on line 127 of "/usr/share/php/Horde/Kolab/Storage/Data/Query/History/Base.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] [KOLAB_STORAGE] Object still existing: object: 59ad2597-807c-441b-89ef-01bb94fbc969, vanished IMAP uid: 5318. Skipping delete from Horde_History. [pid 25876 on line 73 of "/usr/share/php/Horde/Kolab/Storage/Data/Query/History/Cache.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] Modified data object 59ad2597-807c-441b-89ef-01bb94fbc969 in INBOX/Kalender. [pid 25876 on line 409 of "/usr/share/horde/kronolith/lib/Driver/Kolab.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE [kronolith] INBOX/Kalender has 30 objects [too many to list]. [pid 25876 on line 114 of "/usr/share/horde/kronolith/lib/Driver/Kolab.php"] 2019-05-12T01:41:01+02:00 ERR: HORDE [kronolith] SQL QUERY FAILED: Duplicate entry '59ad2597-807c-441b-89ef-01bb94fbc969' for key 'index_horde_dav_objects_on_id_internal' INSERT INTO horde_dav_objects (id_internal, id_external, id_collection) VALUES ('59ad2597-807c-441b-89ef-01bb94fbc969', '59ad2597-807c-441b-89ef-01bb94fbc969.ics', 'YTozOntpOjA7czoyOToibS5nYWJyaWVsQGRhcy1uZXR6d2Vya3RlYW0uZGUiO2k6MTtzO jg6IkthbGVuZGVyIjtpOjI7czo1OiJJTkJPWCI7fQ') [pid 25876 on line 318 of "/usr/share/php/Horde/Db/Adapter/Mysqli.php"] 2019-05-12T01:41:01+02:00 DEBUG: HORDE Max memory usage: 2097152 bytes [pid 25876 on line 613 of "/usr/share/php/Horde/Registry.php"] ``` ... and some look like this: ``` 2019-05-11T23:40:42+00:00 DEBUG: HORDE Load config file (conf.php; app: horde) [pid 17266 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-11T23:40:42+00:00 DEBUG: HORDE Load config file (nls.php; app: horde) [pid 17266 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-11T23:40:42+00:00 DEBUG: HORDE [horde] Horde_Rpc::__construct complete [pid 17266 on line 45 of "/usr/share/php/Horde/Rpc/Webdav.php"] 2019-05-11T23:40:42+00:00 DEBUG: HORDE Horde_Rpc::authorize() starting [pid 17266 on line 137 of "/usr/share/horde/rpc.php"] 2019-05-11T23:40:42+00:00 DEBUG: HORDE Load config file (prefs.php; app: horde) [pid 17266 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-11T23:40:42+00:00 DEBUG: HORDE Load config file (conf.php; app: horde) [pid 17266 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-11T23:40:42+00:00 DEBUG: HORDE Load config file (conf.php; app: ) [pid 17266 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-11T23:40:42+00:00 DEBUG: HORDE [kronolith] Load config file (conf.php; app: kronolith) [pid 17266 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-11T23:40:42+00:00 DEBUG: HORDE [kronolith] Load config file (prefs.php; app: kronolith) [pid 17266 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-12T01:40:42+02:00 DEBUG: HORDE [kronolith] Driver "Horde_Kolab_Storage_Driver_Imap": Retrieving namespaces. [pid 17266 on line 310 of "/usr/share/php/Horde/Kolab/Storage/Driver/Decorator/Base.php"] 2019-05-12T01:40:42+02:00 DEBUG: HORDE [kronolith] Driver "Horde_Kolab_Storage_Driver_Imap": Retrieved namespaces [Horde_Kolab_Storage_Folder_Namespace_Imap: "INBOX" (personal, "/"), "user" (other, "/"), "" (shared, "/")]. [pid 17266 on line 310 of "/usr/share/php/Horde/Kolab/Storage/Driver/Decorator/Base.php"] 2019-05-12T01:40:42+02:00 DEBUG: HORDE [kronolith] REQUEST OUT IMAP: 0 ms [getNamespace] [pid 17266 on line 276 of "/usr/share/php/Horde/Kolab/Storage/List/Tools.php"] 2019-05-12T01:40:42+02:00 DEBUG: HORDE [kronolith] Driver "Horde_Kolab_Storage_Driver_Imap": Retrieving namespaces. [pid 17266 on line 310 of "/usr/share/php/Horde/Kolab/Storage/Driver/Decorator/Base.php"] 2019-05-12T01:40:42+02:00 DEBUG: HORDE [kronolith] Driver "Horde_Kolab_Storage_Driver_Imap": Retrieved namespaces [Horde_Kolab_Storage_Folder_Namespace_Imap: "INBOX" (personal, "/"), "user" (other, "/"), "" (shared, "/")]. [pid 17266 on line 310 of "/usr/share/php/Horde/Kolab/Storage/Driver/Decorator/Base.php"] 2019-05-12T01:40:42+02:00 DEBUG: HORDE [kronolith] REQUEST OUT IMAP: 0 ms [getNamespace] [pid 17266 on line 276 of "/usr/share/php/Horde/Kolab/Storage/List/Tools.php"] 2019-05-12T01:40:42+02:00 DEBUG: HORDE [kronolith] Driver "Horde_Kolab_Storage_Driver_Imap": Retrieving namespaces. [pid 17266 on line 310 of "/usr/share/php/Horde/Kolab/Storage/Driver/Decorator/Base.php"] 2019-05-12T01:40:42+02:00 DEBUG: HORDE [kronolith] Driver "Horde_Kolab_Storage_Driver_Imap": Retrieved namespaces [Horde_Kolab_Storage_Folder_Namespace_Imap: "INBOX" (personal, "/"), "user" (other, "/"), "" (shared, "/")]. [pid 17266 on line 310 of "/usr/share/php/Horde/Kolab/Storage/Driver/Decorator/Base.php"] 2019-05-12T01:40:42+02:00 DEBUG: HORDE [kronolith] REQUEST OUT IMAP: 0 ms [getNamespace] [pid 17266 on line 276 of "/usr/share/php/Horde/Kolab/Storage/List/Tools.php"] 2019-05-12T01:40:42+02:00 DEBUG: HORDE [kronolith] Load config file (prefs.php; app: horde) [pid 17266 on line 109 of "/usr/share/php/Horde/Registry/Loadconfig.php"] 2019-05-12T01:40:42+02:00 DEBUG: HORDE [kronolith] [KOLAB_STORAGE] Fetching stamp WITH token. [pid 17266 on line 252 of "/usr/share/php/Horde/Kolab/Storage/Data/Cached.php"] 2019-05-12T01:40:42+02:00 DEBUG: HORDE [kronolith] Synchronized data cache for INBOX/Kalender. [pid 17266 on line 63 of "/usr/share/php/Horde/Kolab/Storage/Synchronization/OncePerSession.php"] 2019-05-12T01:40:42+02:00 DEBUG: HORDE [kronolith] INBOX/Kalender has 30 objects [too many to list]. [pid 17266 on line 114 of "/usr/share/horde/kronolith/lib/Driver/Kolab.php"] 2019-05-12T01:40:43+02:00 DEBUG: HORDE [kronolith] [KOLAB_STORAGE] Fetching stamp WITH token. [pid 17266 on line 252 of "/usr/share/php/Horde/Kolab/Storage/Data/Cached.php"] 2019-05-12T01:40:43+02:00 DEBUG: HORDE [kronolith] [KOLAB_STORAGE] Incremental folder sync: user: [email protected], folder: INBOX/Kalender, last_sync: 1557618042, current_sync: 1557618043, changes: Array ( [add] => Array ( [5312] => 2B0D064A-CE3C-4125-B8FF-93A0AD004305 ) [del] => Array ( [5246] => 2B0D064A-CE3C-4125-B8FF-93A0AD004305 ) ) [pid 17266 on line 351 of "/usr/share/php/Horde/Kolab/Storage/Data/Base.php"] 2019-05-12T01:40:43+02:00 DEBUG: HORDE [kronolith] [KOLAB_STORAGE] Incremental Horde_History update for user: [email protected], folder: INBOX/Kalender, prefix: kronolith:YTozOntpOjA7czoyOToibS5nYWJyaWVsQGRhcy1uZXR6d2Vya3RlYW0uZGUiO2k6MTtzOjg6IkthbGVuZGVyIjtpOjI7czo1OiJJTkJPWCI7fQ: [pid 17266 on line 73 of "/usr/share/php/Horde/Kolab/Storage/Data/Query/History/Cache.php"] 2019-05-12T01:40:43+02:00 DEBUG: HORDE [kronolith] [KOLAB_STORAGE] Modifying object in Horde_History: kronolith:YTozOntpOjA7czoyOToibS5nYWJyaWVsQGRhcy1uZXR6d2Vya3RlYW0uZGUiO2k6MTtzOjg6IkthbGVuZGVyIjtpOjI7czo1OiJJTkJPWCI7fQ:2B0D064A-CE3C-4125-B8FF-93A0AD004305, uid: 5312, force: 0 [pid 17266 on line 127 of "/usr/share/php/Horde/Kolab/Storage/Data/Query/History/Base.php"] 2019-05-12T01:40:43+02:00 DEBUG: HORDE [kronolith] [KOLAB_STORAGE] Object still existing: object: 2B0D064A-CE3C-4125-B8FF-93A0AD004305, vanished IMAP uid: 5246. Skipping delete from Horde_History. [pid 17266 on line 73 of "/usr/share/php/Horde/Kolab/Storage/Data/Query/History/Cache.php"] 2019-05-12T01:40:43+02:00 DEBUG: HORDE [kronolith] Modified data object 2B0D064A-CE3C-4125-B8FF-93A0AD004305 in INBOX/Kalender. [pid 17266 on line 409 of "/usr/share/horde/kronolith/lib/Driver/Kolab.php"] 2019-05-12T01:40:43+02:00 DEBUG: HORDE [kronolith] INBOX/Kalender has 30 objects [too many to list]. [pid 17266 on line 114 of "/usr/share/horde/kronolith/lib/Driver/Kolab.php"] 2019-05-12T01:40:43+02:00 DEBUG: HORDE Max memory usage: 2097152 bytes [pid 17266 on line 613 of "/usr/share/php/Horde/Registry.php"] ``` -- bugs mailing list Frequently Asked Questions: http://wiki.horde.org/FAQ To unsubscribe, mail: [email protected]