Gerald Galster
2018-Aug-02 14:28 UTC
Duplicate mails on pop3 expunge with dsync replication on 2.2.35 (2.2.33.2 works)
Hi Tim,> Do you have any new insights on the problem with reappearing mail using dovecot replication + pop3? > > It's driving me mad. I'm running dovecot 2.2.34 (874deae) on OpenBSD and it looks like I have the same problem as you have.unfortunately there has been no response, I'm stuck with 2.2.33.2 for the time being. I can only suspect it has something to do with mailbox locking which was introduced in 2.2.34 (int dsync_mailbox_lock) or maybe with some cached values (drop_older_timestamp) as it just happens when the mail is deleted on the node that it has been synced to but not if it's deleted on the node where it has originally been received. Best regards, Gerald diff -Nru dovecot-2.2.33.2/src/doveadm/dsync/dsync-brain-mailbox.c dovecot-2.2.34/src/doveadm/dsync/dsync-brain-mailbox.c --- dovecot-2.2.33.2/src/doveadm/dsync/dsync-brain-mailbox.c 2017-10-05 19:10:44.000000000 +0200 +++ dovecot-2.2.34/src/doveadm/dsync/dsync-brain-mailbox.c 2018-02-28 15:45:34.000000000 +0100 @@ -522,25 +529,33 @@ } /* mailbox appears to have changed. do a full sync here and get the - state again */ + state again. Lock before syncing. */ + if (dsync_mailbox_lock(brain, box, &lock) < 0) { + brain->failed = TRUE; + mailbox_free(&box); + return -1; + } if (mailbox_sync(box, MAILBOX_SYNC_FLAG_FULL_READ) < 0) { i_error("Can't sync mailbox %s: %s", mailbox_get_vname(box), mailbox_get_last_internal_error(box, &brain->mail_error)); ... @@ -599,6 +615,7 @@ static void dsync_cache_fields_update(const struct dsync_mailbox *local_box, const struct dsync_mailbox *remote_box, + struct mailbox *box, struct mailbox_update *update) { ARRAY_TYPE(mailbox_cache_field) local_sorted, remote_sorted, changes; @@ -630,7 +647,8 @@ local_fields = array_get(&local_sorted, &local_count); remote_fields = array_get(&remote_sorted, &remote_count); t_array_init(&changes, local_count + remote_count); - drop_older_timestamp = ioloop_time - MAIL_CACHE_FIELD_DROP_SECS; + drop_older_timestamp = ioloop_time - + box->index->optimization_set.cache.unaccessed_field_drop_secs; diff -Nru dovecot-2.2.33.2/src/doveadm/dsync/dsync-mailbox.c dovecot-2.2.34/src/doveadm/dsync/dsync-mailbox.c --- dovecot-2.2.33.2/src/doveadm/dsync/dsync-mailbox.c 2017-06-23 13:18:28.000000000 +0200 +++ dovecot-2.2.34/src/doveadm/dsync/dsync-mailbox.c 2018-02-28 15:45:34.000000000 +0100 @@ -1,7 +1,9 @@ -/* Copyright (c) 2013-2017 Dovecot authors, see the included COPYING file */ +/* Copyright (c) 2013-2018 Dovecot authors, see the included COPYING file */ #include "lib.h" #include "istream.h" +#include "mail-storage-private.h" +#include "dsync-brain-private.h" #include "dsync-mailbox.h" void dsync_mailbox_attribute_dup(pool_t pool, @@ -20,3 +22,40 @@ dest_r->last_change = src->last_change; dest_r->modseq = src->modseq; } + +int dsync_mailbox_lock(struct dsync_brain *brain, struct mailbox *box, + struct file_lock **lock_r) +{ + const char *path, *error; + int ret; + + /* Make sure the mailbox is open - locking requires it */ + if (mailbox_open(box) < 0) { + i_error("Can't open mailbox %s: %s", mailbox_get_vname(box), + mailbox_get_last_internal_error(box, &brain->mail_error)); + return -1; + } + + ret = mailbox_get_path_to(box, MAILBOX_LIST_PATH_TYPE_INDEX, &path); + if (ret < 0) { + i_error("Can't get mailbox %s path: %s", mailbox_get_vname(box), + mailbox_get_last_internal_error(box, &brain->mail_error)); + return -1; + } + if (ret == 0) { + /* No index files - don't do any locking. In theory we still + could, but this lock is mainly meant to prevent replication + problems, and replication wouldn't work without indexes. */ + *lock_r = NULL; + return 0; + } + + if (mailbox_lock_file_create(box, DSYNC_MAILBOX_LOCK_FILENAME, + brain->mailbox_lock_timeout_secs, + lock_r, &error) <= 0) { + i_error("Failed to lock mailbox %s for dsyncing: %s", + box->vname, error); + return -1; + } + return 0; +}
Jan Münnich
2018-Sep-18 21:20 UTC
Duplicate mails on pop3 expunge with dsync replication on 2.2.35 (2.2.33.2 works)
Hi, Has anyone any idea how to solve or further debug this issue? It seems indeed that it was introduced in 2.2.34 and is still there in 2.3.2.1. I found a couple of posts for this on the mailing list and elsewhere, but no solution: When a message is retrieved and immediately expunged, it gets replicated back from the other dsync node. This usually happens with POP3 but with IMAP as well, when the MUA fetches the mail and the user opens and reads it immediately within seconds. It does not seem to happen when the message is retrieved and only expunged a while after, which is mostly the case with IMAP. The bug occurs and is reproducible when the message is delivered to node A and then fetched by the client from node B. If the message is delivered to and fetched from the same node, the message does not get duplicated. I'm attaching the debug logs from both nodes for a full example transaction. The message is delivered via lmtp to node A with UID 175261, fetched and deleted on node B and then appears again with the new UID 175262. Thanks, Jan Node A: 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Loading modules from directory: /usr/lib/dovecot/modules 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_fts_plugin.so 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_replication_plugin.so 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Module loaded: /usr/lib/dovecot/modules/lib21_fts_solr_plugin.so 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Module loaded: /usr/lib/dovecot/modules/lib90_sieve_plugin.so 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: auth USER input: user at example.org home=/var/vmail/user/user at example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user at example.org/ 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: Quota root: name=User quota backend=count args2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: Quota rule: root=User quota mailbox=Trash bytes=+1073741824 messages=0 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user at example.org 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user at example.org 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user at example.org 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user at example.org 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: Namespace inbox: type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mdbox:~/mdbox 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: fs: root=/var/vmail/user/user at example.org//mdbox, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: acl: acl username = user at example.org 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: acl: owner = 1 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: Namespace : type=shared, prefix=shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no location=mdbox:%h:INDEX=~/shared/%u 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: acl: acl username = user at example.org 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: acl: owner = 0 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 lmtp(6916, user at example.org): Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: Pigeonhole version 0.5.2 (5d6d7c92) initializing 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: include: sieve_global is not set; it is currently not possible to include `:global' scripts. 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: file storage: Using active Sieve script path: /var/vmail/user/user at example.org/.dovecot.sieve 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: file storage: Using script storage path: /var/vmail/user/user at example.org//sieve 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: file storage: Relative path to sieve storage in active link: sieve/ 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: file storage: Using Sieve script path: /var/vmail/user/user at example.org/.dovecot.sieve 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: file script: Opened script `Default' from `/var/vmail/user/user at example.org/.dovecot.sieve' 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: Using the following location for user's Sieve script: /var/vmail/user/user at example.org/.dovecot.sieve 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Mailbox <lmtp DATA local>: Opened mail UID=1 because: header Message-ID (Cache file is unusable) 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: Opening script 1 of 1 from `/var/vmail/user/user at example.org/.dovecot.sieve' 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: Loading script /var/vmail/user/user at example.org/.dovecot.sieve 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: Script binary /var/vmail/user/user at example.org/.dovecot.svbin successfully loaded 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: binary save: not saving binary /var/vmail/user/user at example.org/.dovecot.svbin, because it is already stored 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: Executing script from `/var/vmail/user/user at example.org/.dovecot.svbin' 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Mailbox <lmtp DATA local>: Opened mail UID=1 because: header Cc (Cache file is unusable) 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: INBOX: Mailbox opened because: lib-lda delivery 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Namespace : Using permissions from /var/vmail/user/user at example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/dovecot-acl not found 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Trash: Mailbox opened because: quota count 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Sent/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: INBOX: Mailbox opened because: quota count 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Drafts/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Archive/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Mailbox <lmtp DATA local>: Opened mail UID=1 because: copying 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: replication: Replication requested by 'act_store_execute', priority=2 2018-09-18 23:03:17 lmtp(user at example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: INBOX: Mailbox opened because: quota count 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><>: Debug: auth USER input: user at example.org home=/var/vmail/user/user at example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user at example.org/ 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Quota root: name=User quota backend=count args2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Quota rule: root=User quota mailbox=Trash bytes=+1073741824 messages=0 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user at example.org 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user at example.org 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user at example.org 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user at example.org 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Namespace inbox: type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mdbox:~/mdbox 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: fs: root=/var/vmail/user/user at example.org//mdbox, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl: acl username = user at example.org 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl: owner = 1 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Namespace : type=shared, prefix=shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no location=mdbox:%h:INDEX=~/shared/%u 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl: acl username = user at example.org 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl: owner = 0 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: INBOX: Mailbox opened because: indexing 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Namespace : Using permissions from /var/vmail/user/user at example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:17 indexer-worker(user at example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Mailbox INBOX: Opened mail UID=175261 because: fts indexing 2018-09-18 23:03:17 doveadm(user at example.org)<9390><>: Debug: auth USER input: user at example.org home=/var/vmail/user/user at example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 doveadm(user at example.org)<9390><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 doveadm(user at example.org): Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user at example.org/ 2018-09-18 23:03:17 doveadm(user at example.org): Debug: Quota root: name=User quota backend=count args2018-09-18 23:03:17 doveadm(user at example.org): Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 2018-09-18 23:03:17 doveadm(user at example.org): Debug: Quota rule: root=User quota mailbox=Trash bytes=+1073741824 messages=0 2018-09-18 23:03:17 doveadm(user at example.org): Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user at example.org 2018-09-18 23:03:17 doveadm(user at example.org): Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user at example.org 2018-09-18 23:03:17 doveadm(user at example.org): Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user at example.org 2018-09-18 23:03:17 doveadm(user at example.org): Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user at example.org 2018-09-18 23:03:17 doveadm(user at example.org): Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:17 doveadm(user at example.org): Debug: Namespace inbox: type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mdbox:~/mdbox 2018-09-18 23:03:17 doveadm(user at example.org): Debug: fs: root=/var/vmail/user/user at example.org//mdbox, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:17 doveadm(user at example.org): Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 doveadm(user at example.org): Debug: acl: acl username = user at example.org 2018-09-18 23:03:17 doveadm(user at example.org): Debug: acl: owner = 1 2018-09-18 23:03:17 doveadm(user at example.org): Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 doveadm(user at example.org): Debug: Namespace : type=shared, prefix=shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no location=mdbox:%h:INDEX=~/shared/%u 2018-09-18 23:03:17 doveadm(user at example.org): Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:17 doveadm(user at example.org): Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:17 doveadm(user at example.org): Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 doveadm(user at example.org): Debug: acl: acl username = user at example.org 2018-09-18 23:03:17 doveadm(user at example.org): Debug: acl: owner = 0 2018-09-18 23:03:17 doveadm(user at example.org): Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 doveadm(user at example.org): Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2018-09-18 23:03:17 doveadm(user at example.org): Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/dovecot-acl not found 2018-09-18 23:03:17 doveadm(user at example.org): Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 doveadm(user at example.org): Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Sent/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 doveadm(user at example.org): Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 doveadm(user at example.org): Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Drafts/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 doveadm(user at example.org): Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Archive/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 doveadm(user at example.org): Debug: Namespace : Using permissions from /var/vmail/user/user at example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:17 dsync-local(user at example.org)<4fVlAhVooVuuJAAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 dsync-local(user at example.org)<4fVlAhVooVuuJAAAo4bJGw>: Debug: Mailbox INBOX: Opened mail UID=175261 because: mail stream 2018-09-18 23:03:17 dsync-local(user at example.org)<4fVlAhVooVuuJAAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><>: Debug: auth USER input: user at example.org home=/var/vmail/user/user at example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user at example.org/ 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Quota root: name=User quota backend=count args2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Quota rule: root=User quota mailbox=Trash bytes=+1073741824 messages=0 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Namespace inbox: type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mdbox:~/mdbox 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: fs: root=/var/vmail/user/user at example.org//mdbox, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl: acl username = user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl: owner = 1 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Namespace : type=shared, prefix=shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no location=mdbox:%h:INDEX=~/shared/%u 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl: acl username = user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl: owner = 0 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: INBOX: Mailbox opened because: indexing 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Namespace : Using permissions from /var/vmail/user/user at example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Mailbox INBOX: Opened mail UID=175262 because: fts indexing 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><>: Debug: auth USER input: user at example.org home=/var/vmail/user/user at example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user at example.org/ 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Quota root: name=User quota backend=count args2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Quota rule: root=User quota mailbox=Trash bytes=+1073741824 messages=0 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Namespace inbox: type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mdbox:~/mdbox 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: fs: root=/var/vmail/user/user at example.org//mdbox, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl: acl username = user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl: owner = 1 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Namespace : type=shared, prefix=shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no location=mdbox:%h:INDEX=~/shared/%u 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl: acl username = user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl: owner = 0 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Trash: Mailbox opened because: indexing 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Namespace : Using permissions from /var/vmail/user/user at example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:19 indexer-worker(user at example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Mailbox Trash: Opened mail UID=201632 because: fts indexing Node B: 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><>: Debug: auth USER input: user at example.org home=/var/vmail/user/user at example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user at example.org/ 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Quota root: name=User quota backend=count args2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Quota rule: root=User quota mailbox=Trash bytes=+1073741824 messages=0 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user at example.org 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user at example.org 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user at example.org 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user at example.org 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Namespace inbox: type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mdbox:~/mdbox 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: fs: root=/var/vmail/user/user at example.org//mdbox, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl: acl username = user at example.org 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl: owner = 1 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Namespace : type=shared, prefix=shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no location=mdbox:%h:INDEX=~/shared/%u 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl: acl username = user at example.org 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl: owner = 0 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: INBOX: Mailbox opened because: indexing 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Namespace : Using permissions from /var/vmail/user/user at example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:17 indexer-worker(user at example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Mailbox INBOX: Opened mail UID=175261 because: fts indexing 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Loading modules from directory: /usr/lib/dovecot/modules 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_fts_plugin.so 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_listescape_plugin.so 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_replication_plugin.so 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib21_fts_solr_plugin.so 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user at example.org/ 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota root: name=User quota backend=count args2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota rule: root=User quota mailbox=Trash bytes=+1073741824 messages=0 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user at example.org 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user at example.org 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user at example.org 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user at example.org 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Namespace inbox: type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mdbox:~/mdbox 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: fs: root=/var/vmail/user/user at example.org//mdbox, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl: acl username = user at example.org 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl: owner = 1 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Namespace : type=shared, prefix=shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no location=mdbox:%h:INDEX=~/shared/%u 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl: acl username = user at example.org 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl: owner = 0 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: quota: quota_over_flag check: Flag lookup time is too old - skipping 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: imap-master: Unhibernated to send mailbox changes 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: INBOX: Mailbox opened because: unhibernate 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Unhibernation sync: 0 expunges, 1 new messages, 0 flag changes, 1 modseq changes 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Namespace : Using permissions from /var/vmail/user/user at example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:17 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Mailbox INBOX: Opened mail UID=175261 because: full mail 2018-09-18 23:03:18 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: replication: Replication requested by 'UID STORE 175261 +FLAGS.SILENT (\Seen)', priority=1 2018-09-18 23:03:19 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Trash: Mailbox opened because: UID MOVE 2018-09-18 23:03:19 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/dovecot-acl not found 2018-09-18 23:03:19 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Sent/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: INBOX: Mailbox opened because: quota count 2018-09-18 23:03:19 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Drafts/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Archive/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: replication: Replication requested by 'UID MOVE 175261 Trash', priority=1 2018-09-18 23:03:19 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Trash: Mailbox opened because: quota count 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><>: Debug: auth USER input: user at example.org home=/var/vmail/user/user at example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user at example.org/ 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Quota root: name=User quota backend=count args2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Quota rule: root=User quota mailbox=Trash bytes=+1073741824 messages=0 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Namespace inbox: type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mdbox:~/mdbox 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: fs: root=/var/vmail/user/user at example.org//mdbox, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl: acl username = user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl: owner = 1 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Namespace : type=shared, prefix=shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no location=mdbox:%h:INDEX=~/shared/%u 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl: acl username = user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl: owner = 0 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Trash: Mailbox opened because: indexing 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Namespace : Using permissions from /var/vmail/user/user at example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:19 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: INBOX: Mailbox opened because: quota count 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Mailbox Trash: Opened mail UID=201632 because: fts indexing 2018-09-18 23:03:19 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Trash: Mailbox opened because: quota count 2018-09-18 23:03:19 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: INBOX: Mailbox opened because: quota count 2018-09-18 23:03:19 doveadm(user at example.org)<5986><>: Debug: auth USER input: user at example.org home=/var/vmail/user/user at example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 doveadm(user at example.org)<5986><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 doveadm(user at example.org): Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user at example.org/ 2018-09-18 23:03:19 doveadm(user at example.org): Debug: Quota root: name=User quota backend=count args2018-09-18 23:03:19 doveadm(user at example.org): Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 2018-09-18 23:03:19 doveadm(user at example.org): Debug: Quota rule: root=User quota mailbox=Trash bytes=+1073741824 messages=0 2018-09-18 23:03:19 doveadm(user at example.org): Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user at example.org 2018-09-18 23:03:19 doveadm(user at example.org): Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user at example.org 2018-09-18 23:03:19 doveadm(user at example.org): Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user at example.org 2018-09-18 23:03:19 doveadm(user at example.org): Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user at example.org 2018-09-18 23:03:19 doveadm(user at example.org): Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:19 doveadm(user at example.org): Debug: Namespace inbox: type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mdbox:~/mdbox 2018-09-18 23:03:19 doveadm(user at example.org): Debug: fs: root=/var/vmail/user/user at example.org//mdbox, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:19 doveadm(user at example.org): Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 doveadm(user at example.org): Debug: acl: acl username = user at example.org 2018-09-18 23:03:19 doveadm(user at example.org): Debug: acl: owner = 1 2018-09-18 23:03:19 doveadm(user at example.org): Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 doveadm(user at example.org): Debug: Namespace : type=shared, prefix=shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no location=mdbox:%h:INDEX=~/shared/%u 2018-09-18 23:03:19 doveadm(user at example.org): Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:19 doveadm(user at example.org): Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:19 doveadm(user at example.org): Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 doveadm(user at example.org): Debug: acl: acl username = user at example.org 2018-09-18 23:03:19 doveadm(user at example.org): Debug: acl: owner = 0 2018-09-18 23:03:19 doveadm(user at example.org): Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 doveadm(user at example.org): Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2018-09-18 23:03:19 doveadm(user at example.org): Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/dovecot-acl not found 2018-09-18 23:03:19 doveadm(user at example.org): Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 doveadm(user at example.org): Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Sent/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 doveadm(user at example.org): Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 doveadm(user at example.org): Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Drafts/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 doveadm(user at example.org): Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Archive/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 doveadm(user at example.org): Debug: Namespace : Using permissions from /var/vmail/user/user at example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:19 dsync-local(user at example.org)<1zn9FBdooVtiFwAAs2wLYQ>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><>: Debug: auth USER input: user at example.org home=/var/vmail/user/user at example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user at example.org/ 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Quota root: name=User quota backend=count args2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Quota rule: root=User quota mailbox=Trash bytes=+1073741824 messages=0 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Namespace inbox: type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mdbox:~/mdbox 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: fs: root=/var/vmail/user/user at example.org//mdbox, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl: acl username = user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl: owner = 1 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Namespace : type=shared, prefix=shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no location=mdbox:%h:INDEX=~/shared/%u 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl: acl username = user at example.org 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl: owner = 0 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: INBOX: Mailbox opened because: indexing 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Namespace : Using permissions from /var/vmail/user/user at example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:19 indexer-worker(user at example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Mailbox INBOX: Opened mail UID=175262 because: fts indexing 2018-09-18 23:03:19 dsync-local(user at example.org)<1zn9FBdooVtiFwAAs2wLYQ>: Debug: acl vfile: file /var/vmail/user/user at example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 dsync-local(user at example.org)<1zn9FBdooVtiFwAAs2wLYQ>: Debug: Mailbox Trash: Opened mail UID=201632 because: mail stream 2018-09-18 23:03:20 imap(user at example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Mailbox INBOX: Opened mail UID=175262 because: full mail
Gerald Galster
2018-Sep-21 11:47 UTC
Duplicate mails on pop3 expunge with dsync replication on 2.2.35 (2.2.33.2 works)
Hi Jan, unfortunately no news on this topic after 6 months. I understand this bug might not be a top priority but perhaps someone from the dovecot team can clarify if they will investigate eventually or if we're on our own. Thanks, Gerald> Am 18.09.2018 um 23:20 schrieb Jan M?nnich <jan at dotplex.com>: > > Hi, > > Has anyone any idea how to solve or further debug this issue? It seems indeed that it was introduced in 2.2.34 and is still there in 2.3.2.1. I found a couple of posts for this on the mailing list and elsewhere, but no solution: > > When a message is retrieved and immediately expunged, it gets replicated back from the other dsync node. This usually happens with POP3 but with IMAP as well, when the MUA fetches the mail and the user opens and reads it immediately within seconds. It does not seem to happen when the message is retrieved and only expunged a while after, which is mostly the case with IMAP. > > The bug occurs and is reproducible when the message is delivered to node A and then fetched by the client from node B. If the message is delivered to and fetched from the same node, the message does not get duplicated. > > I'm attaching the debug logs from both nodes for a full example transaction. The message is delivered via lmtp to node A with UID 175261, fetched and deleted on node B and then appears again with the new UID 175262. > > Thanks, > Jan > > > [...]