Tickets :: Comment on [#13034] CalDav Sync with Kolab Backend

* Your Email Address
* Spam protection	Enter the letters below: .__.. ..__ .__ .__ [__]\|__\|[ __[__)[__) \| \|\| \|[_./\| [__)
Comment	> 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: m.gabriel@das-netzwerkteam.de, 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: > m.gabriel@das-netzwerkteam.de, 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: m.gabriel@das-netzwerkteam.de, 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: > m.gabriel@das-netzwerkteam.de, 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"] > ``` >
Attachment
Watch this ticket

Saved Queries