Re: 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@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Loading modules from directory: /usr/lib/dovecot/modules 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_fts_plugin.so 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_replication_plugin.so 2018-09-18 23:03:17 lmtp(user@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@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Module loaded: /usr/lib/dovecot/modules/lib90_sieve_plugin.so 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: auth USER input: user@example.org home=/var/vmail/user/user@example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user@example.org/ 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: Quota root: name=User quota backend=count args= 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: Quota rule: root=User quota mailbox=Trash bytes=+1073741824 messages=0 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user@example.org 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user@example.org 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user@example.org 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user@example.org 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:17 lmtp(6916, user@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@example.org): Debug: fs: root=/var/vmail/user/user@example.org//mdbox, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: acl: acl username = user@example.org 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: acl: owner = 1 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 lmtp(6916, user@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@example.org): Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: acl: acl username = user@example.org 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: acl: owner = 0 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 lmtp(6916, user@example.org): Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: Pigeonhole version 0.5.2 (5d6d7c92) initializing 2018-09-18 23:03:17 lmtp(user@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@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: file storage: Using active Sieve script path: /var/vmail/user/user@example.org/.dovecot.sieve 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: file storage: Using script storage path: /var/vmail/user/user@example.org//sieve 2018-09-18 23:03:17 lmtp(user@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@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: file storage: Using Sieve script path: /var/vmail/user/user@example.org/.dovecot.sieve 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: file script: Opened script Default' from /var/vmail/user/user@example.org/.dovecot.sieve' 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: Using the following location for user's Sieve script: /var/vmail/user/user@example.org/.dovecot.sieve 2018-09-18 23:03:17 lmtp(user@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@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: Opening script 1 of 1 from /var/vmail/user/user@example.org/.dovecot.sieve' 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: Loading script /var/vmail/user/user@example.org/.dovecot.sieve 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: Script binary /var/vmail/user/user@example.org/.dovecot.svbin successfully loaded 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: binary save: not saving binary /var/vmail/user/user@example.org/.dovecot.svbin, because it is already stored 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: sieve: Executing script from `/var/vmail/user/user@example.org/.dovecot.svbin' 2018-09-18 23:03:17 lmtp(user@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@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: INBOX: Mailbox opened because: lib-lda delivery 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Namespace : Using permissions from /var/vmail/user/user@example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/dovecot-acl not found 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Trash: Mailbox opened because: quota count 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Sent/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: INBOX: Mailbox opened because: quota count 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Drafts/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Archive/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: Mailbox <lmtp DATA local>: Opened mail UID=1 because: copying 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: replication: Replication requested by 'act_store_execute', priority=2 2018-09-18 23:03:17 lmtp(user@example.org)<6916><I/GKABVooVsEGwAAo4bJGw>: Debug: INBOX: Mailbox opened because: quota count 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><>: Debug: auth USER input: user@example.org home=/var/vmail/user/user@example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user@example.org/ 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Quota root: name=User quota backend=count args= 2018-09-18 23:03:17 indexer-worker(user@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@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@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user@example.org 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user@example.org 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user@example.org 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user@example.org 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:17 indexer-worker(user@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@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: fs: root=/var/vmail/user/user@example.org//mdbox, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl: acl username = user@example.org 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl: owner = 1 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 indexer-worker(user@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@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl: acl username = user@example.org 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl: owner = 0 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 indexer-worker(user@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@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: INBOX: Mailbox opened because: indexing 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Namespace : Using permissions from /var/vmail/user/user@example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:17 indexer-worker(user@example.org)<8732><I/GKABVooVsEGwAAo4bJGw:kBrCARVooVscIgAAo4bJGw>: Debug: Mailbox INBOX: Opened mail UID=175261 because: fts indexing 2018-09-18 23:03:17 doveadm(user@example.org)<9390><>: Debug: auth USER input: user@example.org home=/var/vmail/user/user@example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 doveadm(user@example.org)<9390><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 doveadm(user@example.org): Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user@example.org/ 2018-09-18 23:03:17 doveadm(user@example.org): Debug: Quota root: name=User quota backend=count args= 2018-09-18 23:03:17 doveadm(user@example.org): Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 2018-09-18 23:03:17 doveadm(user@example.org): Debug: Quota rule: root=User quota mailbox=Trash bytes=+1073741824 messages=0 2018-09-18 23:03:17 doveadm(user@example.org): Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user@example.org 2018-09-18 23:03:17 doveadm(user@example.org): Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user@example.org 2018-09-18 23:03:17 doveadm(user@example.org): Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user@example.org 2018-09-18 23:03:17 doveadm(user@example.org): Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user@example.org 2018-09-18 23:03:17 doveadm(user@example.org): Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:17 doveadm(user@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@example.org): Debug: fs: root=/var/vmail/user/user@example.org//mdbox, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:17 doveadm(user@example.org): Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 doveadm(user@example.org): Debug: acl: acl username = user@example.org 2018-09-18 23:03:17 doveadm(user@example.org): Debug: acl: owner = 1 2018-09-18 23:03:17 doveadm(user@example.org): Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 doveadm(user@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@example.org): Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:17 doveadm(user@example.org): Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:17 doveadm(user@example.org): Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 doveadm(user@example.org): Debug: acl: acl username = user@example.org 2018-09-18 23:03:17 doveadm(user@example.org): Debug: acl: owner = 0 2018-09-18 23:03:17 doveadm(user@example.org): Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 doveadm(user@example.org): Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2018-09-18 23:03:17 doveadm(user@example.org): Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/dovecot-acl not found 2018-09-18 23:03:17 doveadm(user@example.org): Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 doveadm(user@example.org): Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Sent/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 doveadm(user@example.org): Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 doveadm(user@example.org): Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Drafts/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 doveadm(user@example.org): Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Archive/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 doveadm(user@example.org): Debug: Namespace : Using permissions from /var/vmail/user/user@example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:17 dsync-local(user@example.org)<4fVlAhVooVuuJAAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 dsync-local(user@example.org)<4fVlAhVooVuuJAAAo4bJGw>: Debug: Mailbox INBOX: Opened mail UID=175261 because: mail stream 2018-09-18 23:03:17 dsync-local(user@example.org)<4fVlAhVooVuuJAAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><>: Debug: auth USER input: user@example.org home=/var/vmail/user/user@example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user@example.org/ 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Quota root: name=User quota backend=count args= 2018-09-18 23:03:19 indexer-worker(user@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@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@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:19 indexer-worker(user@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@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: fs: root=/var/vmail/user/user@example.org//mdbox, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl: acl username = user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl: owner = 1 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user@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@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl: acl username = user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl: owner = 0 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user@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@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: INBOX: Mailbox opened because: indexing 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Namespace : Using permissions from /var/vmail/user/user@example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:+H6vHxdooVscIgAAo4bJGw>: Debug: Mailbox INBOX: Opened mail UID=175262 because: fts indexing 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><>: Debug: auth USER input: user@example.org home=/var/vmail/user/user@example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user@example.org/ 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Quota root: name=User quota backend=count args= 2018-09-18 23:03:19 indexer-worker(user@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@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@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:19 indexer-worker(user@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@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: fs: root=/var/vmail/user/user@example.org//mdbox, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl: acl username = user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl: owner = 1 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user@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@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl: acl username = user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl: owner = 0 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user@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@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Trash: Mailbox opened because: indexing 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 indexer-worker(user@example.org)<8732><BX7YHhdooVu3JAAAo4bJGw:mCoNIRdooVscIgAAo4bJGw>: Debug: Namespace : Using permissions from /var/vmail/user/user@example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:19 indexer-worker(user@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@example.org)<3875><>: Debug: auth USER input: user@example.org home=/var/vmail/user/user@example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user@example.org/ 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Quota root: name=User quota backend=count args= 2018-09-18 23:03:17 indexer-worker(user@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@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@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user@example.org 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user@example.org 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user@example.org 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user@example.org 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:17 indexer-worker(user@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@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: fs: root=/var/vmail/user/user@example.org//mdbox, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl: acl username = user@example.org 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl: owner = 1 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 indexer-worker(user@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@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl: acl username = user@example.org 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl: owner = 0 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 indexer-worker(user@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@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: INBOX: Mailbox opened because: indexing 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Namespace : Using permissions from /var/vmail/user/user@example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:17 indexer-worker(user@example.org)<3875><298GDRVooVtaFwAAs2wLYQ:APjWDRVooVsjDwAAs2wLYQ>: Debug: Mailbox INBOX: Opened mail UID=175261 because: fts indexing 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Loading modules from directory: /usr/lib/dovecot/modules 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_fts_plugin.so 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_listescape_plugin.so 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_replication_plugin.so 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Module loaded: /usr/lib/dovecot/modules/lib21_fts_solr_plugin.so 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user@example.org/ 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota root: name=User quota backend=count args= 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota rule: root=User quota mailbox=Trash bytes=+1073741824 messages=0 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user@example.org 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user@example.org 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user@example.org 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user@example.org 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:17 imap(user@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@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: fs: root=/var/vmail/user/user@example.org//mdbox, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl: acl username = user@example.org 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl: owner = 1 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 imap(user@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@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl: acl username = user@example.org 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl: owner = 0 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:17 imap(user@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@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: imap-master: Unhibernated to send mailbox changes 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: INBOX: Mailbox opened because: unhibernate 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:17 imap(user@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@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Namespace : Using permissions from /var/vmail/user/user@example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:17 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Mailbox INBOX: Opened mail UID=175261 because: full mail 2018-09-18 23:03:18 imap(user@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@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Trash: Mailbox opened because: UID MOVE 2018-09-18 23:03:19 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/dovecot-acl not found 2018-09-18 23:03:19 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Sent/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: INBOX: Mailbox opened because: quota count 2018-09-18 23:03:19 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Drafts/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Archive/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: replication: Replication requested by 'UID MOVE 175261 Trash', priority=1 2018-09-18 23:03:19 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Trash: Mailbox opened because: quota count 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><>: Debug: auth USER input: user@example.org home=/var/vmail/user/user@example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user@example.org/ 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Quota root: name=User quota backend=count args= 2018-09-18 23:03:19 indexer-worker(user@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@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@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:19 indexer-worker(user@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@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: fs: root=/var/vmail/user/user@example.org//mdbox, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl: acl username = user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl: owner = 1 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user@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@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl: acl username = user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl: owner = 0 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user@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@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Trash: Mailbox opened because: indexing 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Namespace : Using permissions from /var/vmail/user/user@example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:19 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: INBOX: Mailbox opened because: quota count 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA:oK1KEhdooVsjDwAAs2wLYQ>: Debug: Mailbox Trash: Opened mail UID=201632 because: fts indexing 2018-09-18 23:03:19 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Trash: Mailbox opened because: quota count 2018-09-18 23:03:19 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: INBOX: Mailbox opened because: quota count 2018-09-18 23:03:19 doveadm(user@example.org)<5986><>: Debug: auth USER input: user@example.org home=/var/vmail/user/user@example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 doveadm(user@example.org)<5986><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 doveadm(user@example.org): Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user@example.org/ 2018-09-18 23:03:19 doveadm(user@example.org): Debug: Quota root: name=User quota backend=count args= 2018-09-18 23:03:19 doveadm(user@example.org): Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 2018-09-18 23:03:19 doveadm(user@example.org): Debug: Quota rule: root=User quota mailbox=Trash bytes=+1073741824 messages=0 2018-09-18 23:03:19 doveadm(user@example.org): Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user@example.org 2018-09-18 23:03:19 doveadm(user@example.org): Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user@example.org 2018-09-18 23:03:19 doveadm(user@example.org): Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user@example.org 2018-09-18 23:03:19 doveadm(user@example.org): Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user@example.org 2018-09-18 23:03:19 doveadm(user@example.org): Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:19 doveadm(user@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@example.org): Debug: fs: root=/var/vmail/user/user@example.org//mdbox, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:19 doveadm(user@example.org): Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 doveadm(user@example.org): Debug: acl: acl username = user@example.org 2018-09-18 23:03:19 doveadm(user@example.org): Debug: acl: owner = 1 2018-09-18 23:03:19 doveadm(user@example.org): Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 doveadm(user@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@example.org): Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:19 doveadm(user@example.org): Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:19 doveadm(user@example.org): Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 doveadm(user@example.org): Debug: acl: acl username = user@example.org 2018-09-18 23:03:19 doveadm(user@example.org): Debug: acl: owner = 0 2018-09-18 23:03:19 doveadm(user@example.org): Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 doveadm(user@example.org): Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2018-09-18 23:03:19 doveadm(user@example.org): Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/dovecot-acl not found 2018-09-18 23:03:19 doveadm(user@example.org): Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 doveadm(user@example.org): Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Sent/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 doveadm(user@example.org): Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 doveadm(user@example.org): Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Drafts/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 doveadm(user@example.org): Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Archive/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 doveadm(user@example.org): Debug: Namespace : Using permissions from /var/vmail/user/user@example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:19 dsync-local(user@example.org)<1zn9FBdooVtiFwAAs2wLYQ>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><>: Debug: auth USER input: user@example.org home=/var/vmail/user/user@example.org/ uid=2000 gid=2000 quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10737418240 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/user/user@example.org/ 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Quota root: name=User quota backend=count args= 2018-09-18 23:03:19 indexer-worker(user@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@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@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=10630044057 (99%) messages=0 reverse=no command=quota-warning 100 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=10200547328 (95%) messages=0 reverse=no command=quota-warning 95 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=9663676416 (90%) messages=0 reverse=no command=quota-warning 90 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Quota warning: bytes=8589934592 (80%) messages=0 reverse=no command=quota-warning 80 user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) 2018-09-18 23:03:19 indexer-worker(user@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@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: fs: root=/var/vmail/user/user@example.org//mdbox, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl: acl username = user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl: owner = 1 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user@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@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: shared: root=/var/run/dovecot, index=, indexpvt=, control=, inbox=, alt= 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: fts: Indexes disabled for namespace 'shared/%u/' 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl: initializing backend with data: vfile 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl: acl username = user@example.org 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl: owner = 0 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl vfile: Global ACLs disabled 2018-09-18 23:03:19 indexer-worker(user@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@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: INBOX: Mailbox opened because: indexing 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/INBOX/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Namespace : Using permissions from /var/vmail/user/user@example.org//mdbox: mode=0700 gid=default 2018-09-18 23:03:19 indexer-worker(user@example.org)<3875><1zn9FBdooVtiFwAAs2wLYQ:+PCcHxdooVsjDwAAs2wLYQ>: Debug: Mailbox INBOX: Opened mail UID=175262 because: fts indexing 2018-09-18 23:03:19 dsync-local(user@example.org)<1zn9FBdooVtiFwAAs2wLYQ>: Debug: acl vfile: file /var/vmail/user/user@example.org//mdbox/mailboxes/Trash/dbox-Mails/dovecot-acl not found 2018-09-18 23:03:19 dsync-local(user@example.org)<1zn9FBdooVtiFwAAs2wLYQ>: Debug: Mailbox Trash: Opened mail UID=201632 because: mail stream 2018-09-18 23:03:20 imap(user@example.org)<5946><wrpbISt2XuUqDF8AAAAAIAAAAAAAABAA>: Debug: Mailbox INBOX: Opened mail UID=175262 because: full mail