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