[Tickets #13034] Re: CalDav Sync with Kolab Backend

noreply at bugs.horde.org noreply at bugs.horde.org
Sat May 11 23:49:28 UTC 2019 

DO NOT REPLY TO THIS MESSAGE. THIS EMAIL ADDRESS IS NOT MONITORED.

Ticket URL: https://bugs.horde.org/ticket/13034
------------------------------------------------------------------------------
  Ticket             | 13034
  Updated By         | mike.gabriel at das-netzwerkteam.de
  Summary            | CalDav Sync with Kolab Backend
  Queue              | Synchronization
  Version            | Git master
  Type               | Bug
  State              | No Feedback
  Priority           | 2. Medium
  Milestone          |
  Patch              |
  Owners             |
------------------------------------------------------------------------------


mike.gabriel at das-netzwerkteam.de (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: m.gabriel at 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 at 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 at 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 at 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"]
```

More information about the bugs mailing list