0003396: Contact not synced when moved from one folder to another on client - SOGo

ID	Project	Category	View Status	Date Submitted	Last Update

0003396	SOGo Connector	with external server	public	2015-11-26 12:29	2016-05-06 13:02

Reporter	j.otisk	Assigned To	ludovic
Priority	urgent	Severity	major	Reproducibility	always
Status	resolved	Resolution	fixed
Platform	Zimbra 8.0.X	OS	Debian Linux	OS Version	Wheezy 7
Product Version	31.0.1

Summary	0003396: Contact not synced when moved from one folder to another on client
Description	When create of delete contact on client sync in ok. When contact is moved to another synced folder then sync is broken and this contact is never synced again. Tried on different versions of client and sogo connectors, all behaves the same.
Steps To Reproduce	1.Create contact in synced folder. 2.Move contact from one synced folder to another. 3.Moved contact is not synced to server.
Additional Information	Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4
Tags	No tags attached.

j.otisk 2015-11-26 12:29 reporter	sogo log 31.0.1.txt (1,364 bytes) ###create contact 31.0.1 * new sync: 3 3/sync with https://mail.btv.cz/dav/j.otisk@btv.cz/Contacts/... GOT STATUS: 207 card set for upload: C61CBCDB-5EC0-0001-BA4B-FB90147F150F.vcf new card 'aaaa' will be uploaded ctag matches or drop operation NOTICE: uploading modified vcard with etag: -1 NOTICE: uploading modified vcard without etag NOTICE: uploading new vcard with empty key GOT STATUS: 409 GOT STATUS: 201 new card uploaded with key: C6DAAD3D-5CB0-0001-4E8A-12D0F3C04F70.vcf uploaded card has etag: "295323-295323" GOT STATUS: 207 3/sync with https://mail.btv.cz/dav/j.otisk@btv.cz/Contacts/ has ended. ### move contact 31.0.1 * new sync: 1 1/sync with https://mail.btv.cz/dav/j.otisk@btv.cz/Contacts/test/... cardKeys: 1 to delete we delete: C6DAAD3D-5CB0-0001-4E8A-12D0F3C04F70.vcf with deleteLocally=undefined webdav_delete on 'https://mail.btv.cz/dav/j.otisk@btv.cz/Contacts/C6DAAD3D-5CB0- 0001-4E8A-12D0F3C04F70.vcf' done drop delete GOT STATUS: 207 card set for upload: C6DAAD3D-5CB0-0001-4E8A-12D0F3C04F70.vcf ctag matches or drop operation NOTICE: uploading modified vcard with etag: -1 NOTICE: uploading modified vcard without etag GOT STATUS: 204 GOT STATUS: 409 GOT STATUS: 207 1/sync with https://mail.btv.cz/dav/j.otisk@btv.cz/Contacts/test/ has ended. sogo log 31.0.1.txt (1,364 bytes)

j.otisk 2015-11-26 12:40 reporter	server zimbra_sogo 24 move.txt (99,705 bytes) 2015-11-26 11:36:30,601 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - DAV REQUEST: PROPFIND https://mail.domain/service/dav/home/user@domain/Contacts/test/ HTTP/1.1 2015-11-26 11:36:30,602 INFO [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] FileUploadServlet - saveUpload(): received Upload: { accountId=41f7126a-dddf-4e67-870e-e5d5869c4bd3, time=Thu Nov 26 11:36:30 CET 2015, size=175, uploadId=5b5f1a35-ecce-430f-9ad1-0af64a151c6a:3ac2d429-ea3b-4b36-a430-3876ae6e9efe, name=null, path=null } 2015-11-26 11:36:30,602 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - Request: requested content-type: application/xml; charset=utf8, actual content-type: application/xml 2015-11-26 11:36:30,602 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemById 2015-11-26 11:36:30,602 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,602 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,602 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getFolderByPathLongestMatch 2015-11-26 11:36:30,602 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,602 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,603 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - DAV REQUEST: DELETE https://mail.domain/service/dav/home/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf HTTP/1.1 2015-11-26 11:36:30,604 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - getResource at user@domain /Contacts/test/ 2015-11-26 11:36:30,604 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemByPath 2015-11-26 11:36:30,604 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,604 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,604 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getConfig 2015-11-26 11:36:30,604 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,604 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,604 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - RESPONSE: <D:href>/dav/user@domain/Contacts/test/</D:href> 2015-11-26 11:36:30,605 INFO [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - DavServlet operation PROPFIND to /home/user@domain/Contacts/test/ (depth: zero) finished in 4ms 2015-11-26 11:36:30,608 INFO [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] FileUploadServlet - saveUpload(): received Upload: { accountId=41f7126a-dddf-4e67-870e-e5d5869c4bd3, time=Thu Nov 26 11:36:30 CET 2015, size=0, uploadId=5b5f1a35-ecce-430f-9ad1-0af64a151c6a:f550a264-f801-44f7-a5bd-a01c17c5fe9d, name=C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf, path=null } 2015-11-26 11:36:30,608 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - Request: requested content-type: null, actual content-type: text/directory 2015-11-26 11:36:30,608 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemById 2015-11-26 11:36:30,608 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,608 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,608 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getFolderByPathLongestMatch 2015-11-26 11:36:30,608 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,608 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,608 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - getResource at user@domain /Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf 2015-11-26 11:36:30,608 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemByPath 2015-11-26 11:36:30,609 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - fetching new DB connection 2015-11-26 11:36:30,609 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - SELECT mi.id, mi.type, mi.parent_id, mi.folder_id, mi.index_id, mi.imap_id, mi.date, mi.size, mi.locator, mi.blob_digest, mi.unread, mi.flags, mi.tag_names, mi.subject, mi.name, mi.metadata, mi.mod_metadata, mi.change_date, mi.mod_content, mi.uuid FROM mboxgroup13.mail_item AS mi WHERE mailbox_id = 13 AND folder_id = 7 AND type IN (8,18,14) AND name = 'C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf' - 0ms, conn=32393692 2015-11-26 11:36:30,609 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,609 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - rollback, conn=32393692 2015-11-26 11:36:30,610 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - rollback, conn=32393692 2015-11-26 11:36:30,610 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,610 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemById 2015-11-26 11:36:30,610 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,610 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,610 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getFolderByPath 2015-11-26 11:36:30,610 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,610 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,610 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - query #vcardUID:"C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70" OR #vcardURL:"C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70" 2015-11-26 11:36:30,611 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - ZQ: Q(l.field:vcarduid:c6daa8aa,vcarduid:84e0,vcarduid:0001,vcarduid:83fc,vcarduid:72dcf9e7ca70) \|\| Q(l.field:vcardurl:c6daa8aa,vcardurl:84e0,vcardurl:0001,vcardurl:83fc,vcardurl:72dcf9e7ca70),types=[contact],sort=nameAsc 2015-11-26 11:36:30,611 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - Tokenizing id=126753 2015-11-26 11:36:30,611 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: IndexItemList-Fetch 2015-11-26 11:36:30,611 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] cache - Cache hit for contact 126753 in mailbox 13 2015-11-26 11:36:30,611 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,611 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,611 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - Batch progress 1/1 2015-11-26 11:36:30,611 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: IndexItemList-Commit 2015-11-26 11:36:30,611 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,614 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: 2015-11-26 11:36:30,614 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - Indexing id=126753 2015-11-26 11:36:30,616 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - Commit IndexWriter 2015-11-26 11:36:30,616 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: commit: start 2015-11-26 11:36:30,616 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: commit: enter lock 2015-11-26 11:36:30,616 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: commit: now prepare 2015-11-26 11:36:30,616 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: prepareCommit: flush 2015-11-26 11:36:30,616 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: now trigger flush reason=explicit flush 2015-11-26 11:36:30,616 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: start flush: applyAllDeletes=true 2015-11-26 11:36:30,616 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: index before flush _2az(3.5):C113863/4891 _34y(3.5):C26271/2718 _3l1(3.5):C16071/1998 _3t5(3.5):c1019 _3tq(3.5):c1010/1 _3u1(3.5):c367 _3u2(3.5):c47/16 _3u3(3.5):c1 _3u4(3.5):c1 _3u5(3.5):c75 2015-11-26 11:36:30,616 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: DW: flush postings as segment _3u6 numDocs=1 2015-11-26 11:36:30,617 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: DW: new segment has no vectors 2015-11-26 11:36:30,617 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: DW: flushedFiles=[_3u6.fdt, _3u6.nrm, _3u6.tis, _3u6.frq, _3u6.fdx, _3u6.prx, _3u6.tii, _3u6.fnm] 2015-11-26 11:36:30,617 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: DW: flush: create compound file "_3u6.cfs" 2015-11-26 11:36:30,618 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: DW: flush: segment=_3u6(3.5):c1 2015-11-26 11:36:30,618 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: DW: ramUsed=0.097 MB newFlushedSize=0.001 MB (0.001 MB w/o doc stores) docs/MB=997.694 new/old=1.037% 2015-11-26 11:36:30,618 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: DW: flush time 2 msec 2015-11-26 11:36:30,618 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: apply all deletes during flush 2015-11-26 11:36:30,618 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: clearFlushPending 2015-11-26 11:36:30,619 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: findMerges: 11 segments 2015-11-26 11:36:30,619 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: seg=_2az(3.5):C113863/4891 level=5.037315 size=159.953 MB 2015-11-26 11:36:30,619 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: seg=_34y(3.5):C26271/2718 level=4.372046 size=42.490 MB 2015-11-26 11:36:30,619 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: seg=_3l1(3.5):C16071/1998 level=4.1483865 size=24.863 MB 2015-11-26 11:36:30,619 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: seg=_3t5(3.5):c1019 level=3.0081742 size=1.430 MB 2015-11-26 11:36:30,619 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: seg=_3tq(3.5):c1010/1 level=3.0038912 size=1.676 MB 2015-11-26 11:36:30,619 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: seg=_3u1(3.5):c367 level=2.564666 size=0.786 MB 2015-11-26 11:36:30,619 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: seg=_3u2(3.5):c47/16 level=1.4913616 size=0.125 MB 2015-11-26 11:36:30,619 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: seg=_3u3(3.5):c1 level=0.0 size=0.001 MB 2015-11-26 11:36:30,620 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: seg=_3u4(3.5):c1 level=0.0 size=0.001 MB 2015-11-26 11:36:30,620 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: seg=_3u5(3.5):c75 level=1.8750613 size=0.055 MB 2015-11-26 11:36:30,620 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: seg=_3u6(3.5):c1 level=0.0 size=0.001 MB 2015-11-26 11:36:30,620 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: level 4.287315 to 5.037315: 2 segments 2015-11-26 11:36:30,620 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: level 3.3983865 to 4.1483865: 1 segments 2015-11-26 11:36:30,620 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: level 3.0 to 3.0081742: 2 segments 2015-11-26 11:36:30,620 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: LMP: level -1.0 to 2.564666: 6 segments 2015-11-26 11:36:30,620 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: startCommit(): start 2015-11-26 11:36:30,620 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: startCommit index=_2az(3.5):C113863/4891 _34y(3.5):C26271/2718 _3l1(3.5):C16071/1998 _3t5(3.5):c1019 _3tq(3.5):c1010/1 _3u1(3.5):c367 _3u2(3.5):c47/16 _3u3(3.5):c1 _3u4(3.5):c1 _3u5(3.5):c75 _3u6(3.5):c1 changeCount=2 2015-11-26 11:36:30,622 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - DAV REQUEST: PROPFIND https://mail.domain/service/dav/home/user@domain/Contacts/test/ HTTP/1.1 2015-11-26 11:36:30,623 INFO [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] FileUploadServlet - saveUpload(): received Upload: { accountId=41f7126a-dddf-4e67-870e-e5d5869c4bd3, time=Thu Nov 26 11:36:30 CET 2015, size=110, uploadId=5b5f1a35-ecce-430f-9ad1-0af64a151c6a:5b57e372-388b-4541-980f-2acf0b7517c9, name=null, path=null } 2015-11-26 11:36:30,623 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - Request: requested content-type: application/xml; charset=utf8, actual content-type: application/xml 2015-11-26 11:36:30,743 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: done all syncs 2015-11-26 11:36:30,743 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: commit: pendingCommit != null 2015-11-26 11:36:30,784 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: commit: wrote segments file "segments_5vq" 2015-11-26 11:36:30,785 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - IW: commit: done 2015-11-26 11:36:30,785 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: findMerges: 11 segments 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: seg=_2az(3.5):C113863/4891 level=5.037315 size=159.953 MB 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: seg=_34y(3.5):C26271/2718 level=4.372046 size=42.490 MB 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: seg=_3l1(3.5):C16071/1998 level=4.1483865 size=24.863 MB 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: seg=_3t5(3.5):c1019 level=3.0081742 size=1.430 MB 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: seg=_3tq(3.5):c1010/1 level=3.0038912 size=1.676 MB 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: seg=_3u1(3.5):c367 level=2.564666 size=0.786 MB 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: seg=_3u2(3.5):c47/16 level=1.4913616 size=0.125 MB 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: seg=_3u3(3.5):c1 level=0.0 size=0.001 MB 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: seg=_3u4(3.5):c1 level=0.0 size=0.001 MB 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: seg=_3u5(3.5):c75 level=1.8750613 size=0.055 MB 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: seg=_3u6(3.5):c1 level=0.0 size=0.001 MB 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: level 4.287315 to 5.037315: 2 segments 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: level 3.3983865 to 4.1483865: 1 segments 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: level 3.0 to 3.0081742: 2 segments 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: LMP: level -1.0 to 2.564666: 6 segments 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - Close IndexWriter 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: now flush at close waitForMerges=false 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: now trigger flush reason=explicit flush 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: start flush: applyAllDeletes=true 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: index before flush _2az(3.5):C113863/4891 _34y(3.5):C26271/2718 _3l1(3.5):C16071/1998 _3t5(3.5):c1019 _3tq(3.5):c1010/1 _3u1(3.5):c367 _3u2(3.5):c47/16 _3u3(3.5):c1 _3u4(3.5):c1 _3u5(3.5):c75 _3u6(3.5):c1 2015-11-26 11:36:30,786 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: DW: flush: no docs; skipping 2015-11-26 11:36:30,789 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - Close IndexSearcher 2015-11-26 11:36:30,790 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: apply all deletes during flush 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: clearFlushPending 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: all running merges have aborted 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: now call final commit() 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: commit: start 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: commit: enter lock 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: commit: now prepare 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: prepareCommit: flush 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: now trigger flush reason=explicit flush 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: start flush: applyAllDeletes=true 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: index before flush _2az(3.5):C113863/4891 _34y(3.5):C26271/2718 _3l1(3.5):C16071/1998 _3t5(3.5):c1019 _3tq(3.5):c1010/1 _3u1(3.5):c367 _3u2(3.5):c47/16 _3u3(3.5):c1 _3u4(3.5):c1 _3u5(3.5):c75 _3u6(3.5):c1 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: DW: flush: no docs; skipping 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: apply all deletes during flush 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: clearFlushPending 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: startCommit(): start 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: skip startCommit(): no changes pending 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: commit: pendingCommit == null; skip 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: commit: done 2015-11-26 11:36:30,791 DEBUG [Index-8] [name=user@domain;mid=13;] index - IW: at close: _2az(3.5):C113863/4891 _34y(3.5):C26271/2718 _3l1(3.5):C16071/1998 _3t5(3.5):c1019 _3tq(3.5):c1010/1 _3u1(3.5):c367 _3u2(3.5):c47/16 _3u3(3.5):c1 _3u4(3.5):c1 _3u5(3.5):c75 _3u6(3.5):c1 2015-11-26 11:36:30,792 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - fetching new DB connection 2015-11-26 11:36:30,793 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - UPDATE mboxgroup13.mail_item SET index_id = id WHERE mailbox_id = 13 AND id = 126753 - 1ms, conn=32393692 2015-11-26 11:36:30,793 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - commit, conn=32393692 2015-11-26 11:36:30,793 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - rollback, conn=32393692 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemById 2015-11-26 11:36:30,794 INFO [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] index - Batch complete processed=1,failed=0,elapsed=183 (5.46 items/sec) 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - query: #vcardUID:"C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70" OR #vcardURL:"C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70" 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getFolderByPathLongestMatch 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - OP=UNION{LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70") OR LUCENE(l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70")} 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - AFTEREXP=UNION{LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70") OR LUCENE(l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70")} 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - OPTIMIZED=LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70") 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - LOCAL_IN=UNION{LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70")} 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemById 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemById 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - LOCAL_AFTER_TRASH/SPAM/DUMPSTER=UNION{<LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70") AND DB[-ID:/Trash -ID:/Junk ]>} 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getVisibleFolders 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - LOCAL_AFTER_PERM_CHECKS=UNION{<LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70") AND DB[-ID:/Trash -ID:/Junk ]>} 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - BEFORE_FINAL_OPT=UNION{UNION{<LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70") AND DB[-ID:/Trash -ID:/Junk ]>} OR UNION{}} 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - COMPILED=<LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70") AND DB[-ID:/Trash -ID:/Junk ]> 2015-11-26 11:36:30,794 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - OPERATION: <LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70") AND DB[-ID:/Trash -ID:/Junk ]> 2015-11-26 11:36:30,795 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - CacheHitLuceneSearcher IndexSearcher(ReadOnlyDirectoryReader(segments_5vq _2az(3.5):C113863/4891 _34y(3.5):C26271/2718 _3l1(3.5):C16071/1998 _3t5(3.5):c1019 _3tq(3.5):c1010/1 _3u1(3.5):c367 _3u2(3.5):c47/16 _3u3(3.5):c1 _3u4(3.5):c1 _3u5(3.5):c75 _3u6(3.5):c1)) 2015-11-26 11:36:30,796 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemByPath 2015-11-26 11:36:30,796 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,796 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,796 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getConfig 2015-11-26 11:36:30,796 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,796 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,796 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemList 2015-11-26 11:36:30,796 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,796 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,796 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemList 2015-11-26 11:36:30,797 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - fetching new DB connection 2015-11-26 11:36:30,798 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - SELECT mi.id, mi.type, mi.parent_id, mi.folder_id, mi.index_id, mi.imap_id, mi.date, mi.size, mi.locator, mi.blob_digest, mi.unread, mi.flags, mi.tag_names, mi.subject, mi.name, mi.metadata, mi.mod_metadata, mi.change_date, mi.mod_content, mi.uuid FROM mboxgroup13.mail_item AS mi WHERE mailbox_id = 13 AND folder_id = 126731 AND type IN (8,18,14) - 1ms, conn=32393692 2015-11-26 11:36:30,798 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,798 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - commit, conn=32393692 2015-11-26 11:36:30,798 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - rollback, conn=32393692 2015-11-26 11:36:30,799 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,799 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemList 2015-11-26 11:36:30,799 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - fetching new DB connection 2015-11-26 11:36:30,799 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - LuceneSearch query=l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70",n=3000,total=1,elapsed=4 2015-11-26 11:36:30,800 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - LuceneFetchDocs n=1,elapsed=0 2015-11-26 11:36:30,800 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - SELECT mi.id, mi.type, mi.parent_id, mi.folder_id, mi.index_id, mi.imap_id, mi.date, mi.size, mi.locator, mi.blob_digest, mi.unread, mi.flags, mi.tag_names, mi.subject, mi.name, mi.metadata, mi.mod_metadata, mi.change_date, mi.mod_content, mi.uuid FROM mboxgroup13.mail_item AS mi WHERE mailbox_id = 13 AND folder_id = 126731 AND type = 14 - 1ms, conn=32393692 2015-11-26 11:36:30,800 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,800 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - commit, conn=32393692 2015-11-26 11:36:30,800 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - rollback, conn=32393692 2015-11-26 11:36:30,801 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,801 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemList 2015-11-26 11:36:30,801 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - fetching new DB connection 2015-11-26 11:36:30,803 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - SELECT mi.id, mi.type, mi.parent_id, mi.folder_id, mi.index_id, mi.imap_id, mi.date, mi.size, mi.locator, mi.blob_digest, mi.unread, mi.flags, mi.tag_names, mi.subject, mi.name, mi.metadata, mi.mod_metadata, mi.change_date, mi.mod_content, mi.uuid FROM mboxgroup13.mail_item AS mi WHERE mailbox_id = 13 AND folder_id = 126731 AND type = 6 - 1ms, conn=32393692 2015-11-26 11:36:30,803 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,803 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - commit, conn=32393692 2015-11-26 11:36:30,803 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - rollback, conn=32393692 2015-11-26 11:36:30,803 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,804 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: search 2015-11-26 11:36:30,804 DEBUG [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - RESPONSE: <D:href>/dav/user@domain/Contacts/test/</D:href> 2015-11-26 11:36:30,804 INFO [qtp679447471-114252:https://192.168.1.11:443/dav/user@domain/Contacts/test/] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - DavServlet operation PROPFIND to /home/user@domain/Contacts/test/ (depth: one) finished in 181ms 2015-11-26 11:36:30,804 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - fetching new DB connection 2015-11-26 11:36:30,805 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - SELECT mi.id, mi.type, mi.parent_id, mi.folder_id, mi.index_id, mi.imap_id, mi.date, mi.size, mi.locator, mi.blob_digest, mi.unread, mi.flags, mi.tag_names, mi.subject, mi.name, mi.metadata, mi.mod_metadata, mi.change_date, mi.mod_content, mi.uuid, CONCAT(mi.sender, LPAD(CAST(mi.id AS CHAR), 10, '0')) AS sortcol FROM mboxgroup13.mail_item AS mi FORCE INDEX (i_index_id) WHERE mi.mailbox_id = 13 AND (mi.type = 6 AND (mi.folder_id <> 3 AND mi.folder_id <> 4) AND mi.index_id = 126753) ORDER BY sortcol - 1ms, conn=32393692 2015-11-26 11:36:30,805 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] cache - Cache hit for contact 126753 in mailbox 13 2015-11-26 11:36:30,805 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,805 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - commit, conn=32393692 2015-11-26 11:36:30,805 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - rollback, conn=32393692 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - DBSearch elapsed=6 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - LuceneFetchDocs n=1,elapsed=0 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getConfig 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemById 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] cache - Cache hit for contact 126753 in mailbox 13 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: move 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] cache - Cache hit for contact 126753 in mailbox 13 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - increasing stack depth to 2 (getItemById) 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - decreasing stack depth to 1 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - increasing stack depth to 2 (getFolderByPath) 2015-11-26 11:36:30,806 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - decreasing stack depth to 1 2015-11-26 11:36:30,807 INFO [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailop - moving Contact <undefined> (id=126753) to Folder Trash (id=3) 2015-11-26 11:36:30,807 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - fetching new DB connection 2015-11-26 11:36:30,808 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - UPDATE mboxgroup13.mail_item SET folder_id = 3, index_id = 126753, mod_metadata = 295152, change_date = 1448534190 , imap_id = CASE WHEN imap_id IS NULL THEN NULL ELSE 0 END WHERE mailbox_id = 13 AND id = 126753 - 1ms, conn=32393692 2015-11-26 11:36:30,808 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation MoveItem 2015-11-26 11:36:30,809 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - UPDATE mboxgroup13.mail_item SET size = 397, unread = 5, metadata = 'd1:ai1e3:das5:false3:i4di23e3:i4ri125446e5:mdveri2e4:mseqi295152e2:szi16386366e4:unxti126754e1:vi10ee', mod_metadata = 70167, change_date = 1399366240, mod_content = 1 WHERE mailbox_id = 13 AND id = 3 - 1ms, conn=32393692 2015-11-26 11:36:30,809 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - "Trash": updating folder counts (c397/d23/u5/du0/s16386366) 2015-11-26 11:36:30,809 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - UPDATE mboxgroup13.mail_item SET size = 1532, unread = 0, metadata = 'd1:ai1e3:das5:false4:mseqi295152e4:unxti126754e1:vi10e2:vti6ee', mod_metadata = 1, change_date = 1396283781, mod_content = 1 WHERE mailbox_id = 13 AND id = 7 - 0ms, conn=32393692 2015-11-26 11:36:30,810 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - "Contacts": updating folder counts (c1532/d0/u0/du0/s0) 2015-11-26 11:36:30,820 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - DAV REQUEST: PUT https://mail.domain/service/dav/home/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf HTTP/1.1 2015-11-26 11:36:30,821 INFO [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] FileUploadServlet - saveUpload(): received Upload: { accountId=41f7126a-dddf-4e67-870e-e5d5869c4bd3, time=Thu Nov 26 11:36:30 CET 2015, size=171, uploadId=5b5f1a35-ecce-430f-9ad1-0af64a151c6a:5f0d63ad-e4af-46f5-acd0-a59d82205d15, name=null, path=null } 2015-11-26 11:36:30,821 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - Request: requested content-type: text/vcard; charset=utf-8, actual content-type: text/vcard 2015-11-26 11:36:30,821 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - REQUEST 2015-11-26 11:36:30,861 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] redolog - txn 1447403047.28614 [MoveItem] ver=1.42, tstamp=1448534190806, change=295152, mailbox=13, id=[126753], type=unknown, dest=3 2015-11-26 11:36:30,861 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - commit, conn=32393692 2015-11-26 11:36:30,861 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] redolog - txn 1447403047.28614 [CommitTxn] ver=1.42, tstamp=1448534190861, mailbox=13, txnType=MoveItem 2015-11-26 11:36:30,866 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - rollback, conn=32393692 2015-11-26 11:36:30,867 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,867 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] acl - PermissionCache get: NO_MATCHING_ACL (target=user@domain, grantee=scepkova@domain, right=loginAs, canDelegateNeeded=false) 2015-11-26 11:36:30,867 DEBUG [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] acl - check ACL: no matching ACL(target=user@domain, grantee=scepkova@domain, right=loginAs, canDelegateNeeded=false) 2015-11-26 11:36:30,868 INFO [qtp679447471-114254:https://192.168.1.11:443/dav/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [name=user@domain;aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - DavServlet operation DELETE to /home/user@domain/Contacts/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf (depth: zero) finished in 265ms 2015-11-26 11:36:30,868 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemById 2015-11-26 11:36:30,868 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,868 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,868 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getFolderByPathLongestMatch 2015-11-26 11:36:30,868 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,868 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,868 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - getResource at user@domain /Contacts/test 2015-11-26 11:36:30,868 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemByPath 2015-11-26 11:36:30,868 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,868 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,868 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getConfig 2015-11-26 11:36:30,868 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,868 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,868 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - getResource at user@domain /Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf 2015-11-26 11:36:30,869 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemByPath 2015-11-26 11:36:30,869 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - fetching new DB connection 2015-11-26 11:36:30,870 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - SELECT mi.id, mi.type, mi.parent_id, mi.folder_id, mi.index_id, mi.imap_id, mi.date, mi.size, mi.locator, mi.blob_digest, mi.unread, mi.flags, mi.tag_names, mi.subject, mi.name, mi.metadata, mi.mod_metadata, mi.change_date, mi.mod_content, mi.uuid FROM mboxgroup13.mail_item AS mi WHERE mailbox_id = 13 AND folder_id = 126731 AND type IN (8,18,14) AND name = 'C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf' - 1ms, conn=32393692 2015-11-26 11:36:30,870 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,870 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - rollback, conn=32393692 2015-11-26 11:36:30,870 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - rollback, conn=32393692 2015-11-26 11:36:30,871 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,871 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemById 2015-11-26 11:36:30,871 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,871 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,871 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getFolderByPath 2015-11-26 11:36:30,871 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,871 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,871 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - query #vcardUID:"C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70" OR #vcardURL:"C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70" 2015-11-26 11:36:30,871 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - ZQ: Q(l.field:vcarduid:c6daa8aa,vcarduid:84e0,vcarduid:0001,vcarduid:83fc,vcarduid:72dcf9e7ca70) \|\| Q(l.field:vcardurl:c6daa8aa,vcardurl:84e0,vcardurl:0001,vcardurl:83fc,vcardurl:72dcf9e7ca70),types=[contact],sort=nameAsc 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - query: #vcardUID:"C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70" OR #vcardURL:"C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70" 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - OP=UNION{LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70") OR LUCENE(l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70")} 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - AFTEREXP=UNION{LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70") OR LUCENE(l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70")} 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - OPTIMIZED=LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70") 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - LOCAL_IN=UNION{LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70")} 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemById 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getItemById 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - LOCAL_AFTER_TRASH/SPAM/DUMPSTER=UNION{<LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70") AND DB[-ID:/Trash -ID:/Junk ]>} 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: getVisibleFolders 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - LOCAL_AFTER_PERM_CHECKS=UNION{<LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70") AND DB[-ID:/Trash -ID:/Junk ]>} 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - BEFORE_FINAL_OPT=UNION{UNION{<LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70") AND DB[-ID:/Trash -ID:/Junk ]>} OR UNION{}} 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - COMPILED=<LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70") AND DB[-ID:/Trash -ID:/Junk ]> 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - OPERATION: <LUCENE(l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70") AND DB[-ID:/Trash -ID:/Junk ]> 2015-11-26 11:36:30,874 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - CacheHitLuceneSearcher IndexSearcher(ReadOnlyDirectoryReader(segments_5vq _2az(3.5):C113863/4891 _34y(3.5):C26271/2718 _3l1(3.5):C16071/1998 _3t5(3.5):c1019 _3tq(3.5):c1010/1 _3u1(3.5):c367 _3u2(3.5):c47/16 _3u3(3.5):c1 _3u4(3.5):c1 _3u5(3.5):c75 _3u6(3.5):c1)) 2015-11-26 11:36:30,882 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - LuceneSearch query=l.field:"vcarduid:c6daa8aa vcarduid:84e0 vcarduid:0001 vcarduid:83fc vcarduid:72dcf9e7ca70" l.field:"vcardurl:c6daa8aa vcardurl:84e0 vcardurl:0001 vcardurl:83fc vcardurl:72dcf9e7ca70",n=3000,total=1,elapsed=7 2015-11-26 11:36:30,882 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - LuceneFetchDocs n=1,elapsed=0 2015-11-26 11:36:30,883 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - beginning operation: search 2015-11-26 11:36:30,883 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - fetching new DB connection 2015-11-26 11:36:30,884 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - SELECT mi.id, mi.type, mi.parent_id, mi.folder_id, mi.index_id, mi.imap_id, mi.date, mi.size, mi.locator, mi.blob_digest, mi.unread, mi.flags, mi.tag_names, mi.subject, mi.name, mi.metadata, mi.mod_metadata, mi.change_date, mi.mod_content, mi.uuid, CONCAT(mi.sender, LPAD(CAST(mi.id AS CHAR), 10, '0')) AS sortcol FROM mboxgroup13.mail_item AS mi FORCE INDEX (i_index_id) WHERE mi.mailbox_id = 13 AND (mi.type = 6 AND (mi.folder_id <> 3 AND mi.folder_id <> 4) AND mi.index_id = 126753) ORDER BY sortcol - 0ms, conn=32393692 2015-11-26 11:36:30,884 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - ending operation 2015-11-26 11:36:30,884 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - commit, conn=32393692 2015-11-26 11:36:30,884 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] sqltrace - rollback, conn=32393692 2015-11-26 11:36:30,885 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] mailbox - clearing change 2015-11-26 11:36:30,885 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - DBSearch elapsed=2 2015-11-26 11:36:30,885 DEBUG [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] search - LuceneFetchDocs n=1,elapsed=0 2015-11-26 11:36:30,885 INFO [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - sending http error 409 because: item does not exists 2015-11-26 11:36:30,886 INFO [qtp679447471-114255:https://192.168.1.11:443/dav/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf] [aname=user@domain;ip=192.168.1.130;ua=Mozilla/5.0 (Windows NT 5.1;; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4;] dav - DavServlet operation PUT to /home/user@domain/Contacts/test/C6DAA8AA-84E0-0001-83FC-72DCF9E7CA70.vcf (depth: zero) finished in 66ms 2015-11-26 11:37:18,655 INFO [qtp679447471-114258:https://192.168.1.11:443/service/soap/NoOpRequest] [name=user@domain;aname=scepkova@domain;mid=13;ip=192.168.1.130;ua=ZimbraWebClient - FF42 (Win)/8.0.6_GA_5922;] misc - delegated access: doc=NoOp, delegating account=admin@domain, authenticated account=scepkova@domain, target account=scepkova@domain 2015-11-26 11:37:18,655 INFO [qtp679447471-114258:https://192.168.1.11:443/service/soap/NoOpRequest] [name=user@domain;aname=scepkova@domain;mid=13;ip=192.168.1.130;ua=ZimbraWebClient - FF42 (Win)/8.0.6_GA_5922;] soap - NoOpRequest elapsed=0 2015-11-26 11:37:18,655 DEBUG [qtp679447471-114258:https://192.168.1.11:443/service/soap/NoOpRequest] [name=user@domain;aname=scepkova@domain;mid=13;ip=192.168.1.130;ua=ZimbraWebClient - FF42 (Win)/8.0.6_GA_5922;] session - refresh required: forceRefresh=2,lastSequence=8,currentSequence=9 server zimbra_sogo 24 move.txt (99,705 bytes)

j.otisk 2015-11-26 14:20 reporter	save with sync 31.0.1.txt (4,893 bytes) PROPFIND /dav/user@domain/Contacts/test/ HTTP/1.1 Host: mail.btv.cz User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4 Accept: text/xml Accept-Language: cs,en-US;q=0.7,en;q=0.3 Accept-Encoding: gzip, deflate Accept-Charset: utf-8,;q=0.1 Depth: 0 Content-Type: application/xml; charset=utf8 Content-Length: 175 Authorization: Basic ################## Connection: keep-alive Pragma: no-cache Cache-Control: no-cache <?xml version="1.0"?> <D:propfind xmlns:D="DAV:" xmlns:x0="http://calendarserver.org/ns/"><D:prop><D:resourcetype/><D:supported-report-set/><x0:getctag/></D:prop></D:propfind>HTTP/1.1 207 Multi-Status Date: Thu, 26 Nov 2015 14:14:35 GMT DAV: 1, 2, 3, access-control, calendar-access, calendar-schedule DAV: version-control, addressbook, extended-mkcol, calendar-proxy DAV: calendarserver-principal-property-search Content-Type: text/xml;charset=UTF-8 Transfer-Encoding: chunked 6B7 <?xml version="1.0" encoding="UTF-8"?> <D:multistatus xmlns:D="DAV:"> <D:response> <D:href>/dav/user@domain/Contacts/test/</D:href> <D:propstat> <D:status>HTTP/1.1 200 OK</D:status> <D:prop> <D:supported-report-set> <D:supported-report> <D:report> <C:addressbook-multiget xmlns:C="urn:ietf:params:xml:ns:carddav"/> </D:report> </D:supported-report> <D:supported-report> <D:report> <C:addressbook-query xmlns:C="urn:ietf:params:xml:ns:carddav"/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:acl-principal-prop-set/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:principal-match/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:principal-property-search/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:principal-search-property-set/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:expand-property/> </D:report> </D:supported-report> </D:supported-report-set> <CS:getctag xmlns:CS="http://calendarserver.org/ns/">295044-295532</CS:getctag> <D:resourcetype> <D:collection/> <C:addressbook xmlns:C="urn:ietf:params:xml:ns:carddav"/> </D:resourcetype> </D:prop> </D:propstat> </D:response> </D:multistatus> 0 PUT /dav/user@domain/Contacts/test/C6DAB52A-2C70-0001-2B9B-1D808B616C40.vcf HTTP/1.1 Host: mail.btv.cz User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4 Accept: text/xml Accept-Language: cs,en-US;q=0.7,en;q=0.3 Accept-Encoding: gzip, deflate Accept-Charset: utf-8,;q=0.1 Content-Type: text/vcard; charset=utf-8 If-None-Match: * Content-Length: 169 Authorization: Basic ################## Connection: keep-alive Pragma: no-cache Cache-Control: no-cache BEGIN:VCARD VERSION:3.0 PRODID:-//Inverse inc.//SOGo Connector 1.0//EN UID:C6DAB52A-2CB0-0001-6395-CDBFA3061C00 N:;test FN:test X-MOZILLA-HTML:FALSE END:VCARD HTTP/1.1 201 Created Date: Thu, 26 Nov 2015 14:14:35 GMT ETag: "295533-295533" X-Zimbra-ETag: "295533-295533" Content-Length: 0 PROPFIND /dav/user@domain/Contacts/test/ HTTP/1.1 Host: mail.btv.cz User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4 Accept: text/xml Accept-Language: cs,en-US;q=0.7,en;q=0.3 Accept-Encoding: gzip, deflate Accept-Charset: utf-8,*;q=0.1 Depth: 0 Content-Type: application/xml; charset=utf8 Content-Length: 133 Authorization: Basic ################## Connection: keep-alive Pragma: no-cache Cache-Control: no-cache <?xml version="1.0"?> <D:propfind xmlns:D="DAV:" xmlns:x0="http://calendarserver.org/ns/"><D:prop><x0:getctag/></D:prop></D:propfind>HTTP/1.1 207 Multi-Status Date: Thu, 26 Nov 2015 14:14:36 GMT DAV: 1, 2, 3, access-control, calendar-access, calendar-schedule DAV: version-control, addressbook, extended-mkcol, calendar-proxy DAV: calendarserver-principal-property-search Content-Type: text/xml;charset=UTF-8 Transfer-Encoding: chunked 174 <?xml version="1.0" encoding="UTF-8"?> <D:multistatus xmlns:D="DAV:"> <D:response> <D:href>/dav/user@domain/Contacts/test/</D:href> <D:propstat> <D:status>HTTP/1.1 200 OK</D:status> <D:prop> <CS:getctag xmlns:CS="http://calendarserver.org/ns/">295044-295533</CS:getctag> </D:prop> </D:propstat> </D:response> </D:multistatus> 0 save with sync 31.0.1.txt (4,893 bytes)

j.otisk 2015-11-26 14:20 reporter	save without sync 31.0.1.txt (4,808 bytes) PROPFIND /dav/user@domain/Contacts/test/ HTTP/1.1 Host: mail.btv.cz User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4 Accept: text/xml Accept-Language: cs,en-US;q=0.7,en;q=0.3 Accept-Encoding: gzip, deflate Accept-Charset: utf-8,;q=0.1 Depth: 0 Content-Type: application/xml; charset=utf8 Content-Length: 175 Authorization: Basic ############# Connection: keep-alive Pragma: no-cache Cache-Control: no-cache <?xml version="1.0"?> <D:propfind xmlns:D="DAV:" xmlns:x0="http://calendarserver.org/ns/"><D:prop><D:resourcetype/><D:supported-report-set/><x0:getctag/></D:prop></D:propfind>HTTP/1.1 207 Multi-Status Date: Thu, 26 Nov 2015 14:04:17 GMT DAV: 1, 2, 3, access-control, calendar-access, calendar-schedule DAV: version-control, addressbook, extended-mkcol, calendar-proxy DAV: calendarserver-principal-property-search Content-Type: text/xml;charset=UTF-8 Transfer-Encoding: chunked 6B7 <?xml version="1.0" encoding="UTF-8"?> <D:multistatus xmlns:D="DAV:"> <D:response> <D:href>/dav/user@domain/Contacts/test/</D:href> <D:propstat> <D:status>HTTP/1.1 200 OK</D:status> <D:prop> <D:supported-report-set> <D:supported-report> <D:report> <C:addressbook-multiget xmlns:C="urn:ietf:params:xml:ns:carddav"/> </D:report> </D:supported-report> <D:supported-report> <D:report> <C:addressbook-query xmlns:C="urn:ietf:params:xml:ns:carddav"/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:acl-principal-prop-set/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:principal-match/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:principal-property-search/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:principal-search-property-set/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:expand-property/> </D:report> </D:supported-report> </D:supported-report-set> <CS:getctag xmlns:CS="http://calendarserver.org/ns/">295044-295504</CS:getctag> <D:resourcetype> <D:collection/> <C:addressbook xmlns:C="urn:ietf:params:xml:ns:carddav"/> </D:resourcetype> </D:prop> </D:propstat> </D:response> </D:multistatus> 0 PUT /dav/user@domain/Contacts/test/C6DAB493-14E0-0001-5232-D700163B2060.vcf HTTP/1.1 Host: mail.btv.cz User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4 Accept: text/xml Accept-Language: cs,en-US;q=0.7,en;q=0.3 Accept-Encoding: gzip, deflate Accept-Charset: utf-8,;q=0.1 Content-Type: text/vcard; charset=utf-8 Content-Length: 171 Authorization: Basic ############# Connection: keep-alive Pragma: no-cache Cache-Control: no-cache BEGIN:VCARD VERSION:3.0 PRODID:-//Inverse inc.//SOGo Connector 1.0//EN UID:C6DAB493-14E0-0001-5232-D700163B2060.vcf N:;ddd FN:ddd X-MOZILLA-HTML:FALSE END:VCARD HTTP/1.1 409 Conflict Date: Thu, 26 Nov 2015 14:04:17 GMT Content-Length: 0 PROPFIND /dav/user@domain/Contacts/test/ HTTP/1.1 Host: mail.btv.cz User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4 Accept: text/xml Accept-Language: cs,en-US;q=0.7,en;q=0.3 Accept-Encoding: gzip, deflate Accept-Charset: utf-8,*;q=0.1 Depth: 0 Content-Type: application/xml; charset=utf8 Content-Length: 133 Authorization: Basic ############# Connection: keep-alive Pragma: no-cache Cache-Control: no-cache <?xml version="1.0"?> <D:propfind xmlns:D="DAV:" xmlns:x0="http://calendarserver.org/ns/"><D:prop><x0:getctag/></D:prop></D:propfind>HTTP/1.1 207 Multi-Status Date: Thu, 26 Nov 2015 14:04:17 GMT DAV: 1, 2, 3, access-control, calendar-access, calendar-schedule DAV: version-control, addressbook, extended-mkcol, calendar-proxy DAV: calendarserver-principal-property-search Content-Type: text/xml;charset=UTF-8 Transfer-Encoding: chunked 174 <?xml version="1.0" encoding="UTF-8"?> <D:multistatus xmlns:D="DAV:"> <D:response> <D:href>/dav/user@domain/Contacts/test/</D:href> <D:propstat> <D:status>HTTP/1.1 200 OK</D:status> <D:prop> <CS:getctag xmlns:CS="http://calendarserver.org/ns/">295044-295504</CS:getctag> </D:prop> </D:propstat> </D:response> </D:multistatus> 0 save without sync 31.0.1.txt (4,808 bytes)

j.otisk 2015-11-26 14:20 reporter	move without sync 31.0.1.txt (5,441 bytes) DELETE /dav/user@domain/Contacts/test/C6DAB52A-2C70-0001-2B9B-1D808B616C40.vcf HTTP/1.1 Host: mail.btv.cz User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4 Accept: text/xml Accept-Language: cs,en-US;q=0.7,en;q=0.3 Accept-Encoding: gzip, deflate Accept-Charset: utf-8,;q=0.1 Authorization: Basic ######################## Connection: keep-alive Pragma: no-cache Cache-Control: no-cache HTTP/1.1 204 No Content Date: Thu, 26 Nov 2015 14:15:33 GMT PROPFIND /dav/user@domain/Contacts/test/ HTTP/1.1 Host: mail.btv.cz User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4 Accept: text/xml Accept-Language: cs,en-US;q=0.7,en;q=0.3 Accept-Encoding: gzip, deflate Accept-Charset: utf-8,;q=0.1 Depth: 0 Content-Type: application/xml; charset=utf8 Content-Length: 175 Authorization: Basic ######################## Connection: keep-alive Pragma: no-cache Cache-Control: no-cache <?xml version="1.0"?> <D:propfind xmlns:D="DAV:" xmlns:x0="http://calendarserver.org/ns/"><D:prop><D:resourcetype/><D:supported-report-set/><x0:getctag/></D:prop></D:propfind>HTTP/1.1 207 Multi-Status Date: Thu, 26 Nov 2015 14:15:49 GMT DAV: 1, 2, 3, access-control, calendar-access, calendar-schedule DAV: version-control, addressbook, extended-mkcol, calendar-proxy DAV: calendarserver-principal-property-search Content-Type: text/xml;charset=UTF-8 Transfer-Encoding: chunked 6B7 <?xml version="1.0" encoding="UTF-8"?> <D:multistatus xmlns:D="DAV:"> <D:response> <D:href>/dav/user@domain/Contacts/test/</D:href> <D:propstat> <D:status>HTTP/1.1 200 OK</D:status> <D:prop> <D:supported-report-set> <D:supported-report> <D:report> <C:addressbook-multiget xmlns:C="urn:ietf:params:xml:ns:carddav"/> </D:report> </D:supported-report> <D:supported-report> <D:report> <C:addressbook-query xmlns:C="urn:ietf:params:xml:ns:carddav"/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:acl-principal-prop-set/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:principal-match/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:principal-property-search/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:principal-search-property-set/> </D:report> </D:supported-report> <D:supported-report> <D:report> <D:expand-property/> </D:report> </D:supported-report> </D:supported-report-set> <CS:getctag xmlns:CS="http://calendarserver.org/ns/">295044-295536</CS:getctag> <D:resourcetype> <D:collection/> <C:addressbook xmlns:C="urn:ietf:params:xml:ns:carddav"/> </D:resourcetype> </D:prop> </D:propstat> </D:response> </D:multistatus> 0 PROPFIND /dav/user@domain/Contacts/test/ HTTP/1.1 Host: mail.btv.cz User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4 Accept: text/xml Accept-Language: cs,en-US;q=0.7,en;q=0.3 Accept-Encoding: gzip, deflate Accept-Charset: utf-8,;q=0.1 Depth: 1 Content-Type: application/xml; charset=utf8 Content-Length: 110 Authorization: Basic ######################## Connection: keep-alive Pragma: no-cache Cache-Control: no-cache <?xml version="1.0"?> <D:propfind xmlns:D="DAV:"><D:prop><D:getcontenttype/><D:getetag/></D:prop></D:propfind>HTTP/1.1 207 Multi-Status Date: Thu, 26 Nov 2015 14:15:49 GMT DAV: 1, 2, 3, access-control, calendar-access, calendar-schedule DAV: version-control, addressbook, extended-mkcol, calendar-proxy DAV: calendarserver-principal-property-search Content-Type: text/xml;charset=UTF-8 Transfer-Encoding: chunked 1DB <?xml version="1.0" encoding="UTF-8"?> <D:multistatus xmlns:D="DAV:"> <D:response> <D:href>/dav/user@domain/Contacts/test/</D:href> <D:propstat> <D:status>HTTP/1.1 200 OK</D:status> <D:prop> <D:getetag>"295044-295044"</D:getetag> </D:prop> </D:propstat> <D:propstat> <D:status>HTTP/1.1 404 Not Found</D:status> <D:prop> <D:getcontenttype/> </D:prop> </D:propstat> </D:response> </D:multistatus> 0 PUT /dav/user@domain/Contacts/test/C6DAB52A-2C70-0001-2B9B-1D808B616C40.vcf HTTP/1.1 Host: mail.btv.cz User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:38.0) Gecko/20100101 Thunderbird/38.4.0 Lightning/4.0.4 Accept: text/xml Accept-Language: cs,en-US;q=0.7,en;q=0.3 Accept-Encoding: gzip, deflate Accept-Charset: utf-8,;q=0.1 Content-Type: text/vcard; charset=utf-8 Content-Length: 173 Authorization: Basic ######################## Connection: keep-alive Pragma: no-cache Cache-Control: no-cache BEGIN:VCARD VERSION:3.0 PRODID:-//Inverse inc.//SOGo Connector 1.0//EN UID:C6DAB52A-2C70-0001-2B9B-1D808B616C40.vcf N:;test FN:test X-MOZILLA-HTML:FALSE END:VCARD HTTP/1.1 409 Conflict Date: Thu, 26 Nov 2015 14:15:49 GMT Content-Length: 0 move without sync 31.0.1.txt (5,441 bytes)

j.otisk 2015-11-26 14:21 reporter ~0009155	After few tries sogo stopped to sync even new created contacts, problem resolved by reinstall of addon to thundrebird. HTTP conversation with server logged and attached.

j.otisk 2015-11-26 14:24 reporter ~0009156	From logs it looks like when HTTP PUT request missing If-None-Match: *, then sync fails.

j.otisk 2015-11-26 14:46 reporter	sogoWebDAV.js (17,057 bytes)

j.otisk 2015-11-26 14:48 reporter ~0009158	Problem fixed by modify of sogoWebDAV.js to add If-None-Match: * to other PUT requests too. Unfortunately I have no idea it this can have some drawbacks, so please review this ugly modification. modified file attached.

ludovic 2015-11-26 14:49 administrator ~0009159	Can you please submit a pull request on github? The project is here: https://github.com/inverse-inc/sogo-connector.tb31 Thanks,

j.otisk 2015-11-26 16:57 reporter ~0009160	Pull request sent.

ludovic 2016-05-06 13:02 administrator ~0010053	PR merged: https://github.com/inverse-inc/sogo-connector.tb31/commit/b838cf020b7a7cda951ac3c127934adc76fbca5d The v31.0.3 extension will contain the fix.

Date Modified	Username	Field	Change
2015-11-26 12:29	j.otisk	New Issue
2015-11-26 12:29	j.otisk	File Added: sogo log 31.0.1.txt
2015-11-26 12:40	j.otisk	File Added: server zimbra_sogo 24 move.txt
2015-11-26 14:20	j.otisk	File Added: save with sync 31.0.1.txt
2015-11-26 14:20	j.otisk	File Added: save without sync 31.0.1.txt
2015-11-26 14:20	j.otisk	File Added: move without sync 31.0.1.txt
2015-11-26 14:21	j.otisk	Note Added: 0009155
2015-11-26 14:24	j.otisk	Note Added: 0009156
2015-11-26 14:46	j.otisk	File Added: sogoWebDAV.js
2015-11-26 14:48	j.otisk	Note Added: 0009158
2015-11-26 14:49	ludovic	Note Added: 0009159
2015-11-26 16:57	j.otisk	Note Added: 0009160
2016-05-06 13:02	ludovic	Note Added: 0010053
2016-05-06 13:02	ludovic	Status	new => resolved
2016-05-06 13:02	ludovic	Resolution	open => fixed
2016-05-06 13:02	ludovic	Assigned To	=> ludovic

View Issue Details

Activities

Issue History