Duplicate mails on pop3 expunge with dsync replication on 2.2.35 (2.2.33.2 works)

Jan Münnich jan at dotplex.com
Wed Sep 19 00:20:39 EEST 2018


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 args=
2018-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=, alt=
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 = 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=, alt=
2018-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 args=
2018-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=, alt=
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 = 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=, alt=
2018-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 args=
2018-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=, alt=
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 = 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=, alt=
2018-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 args=
2018-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=, alt=
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 = 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=, alt=
2018-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 args=
2018-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=, alt=
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 = 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=, alt=
2018-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 args=
2018-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=, alt=
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 = 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=, alt=
2018-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 args=
2018-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=, alt=
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 = 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=, alt=
2018-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 args=
2018-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=, alt=
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 = 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=, alt=
2018-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 args=
2018-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=, alt=
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 = 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=, alt=
2018-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 args=
2018-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=, alt=
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 = 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=, alt=
2018-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


More information about the dovecot mailing list