Re: Dovecot mail-crypt webmail can't read encrypted messages

It's a testing install my main goal is to make it work. I will play around with password encryption before going live.

I have enabled all possible debugging yet I can's see the value you mentioned in the log file. Could you please point me?

Aug 29 01:46:04 mx dovecot: master: Dovecot v2.3.13 (89f716dc2) starting up for pop3, imap, sieve, lmtp (core dumps disabled) Aug 29 01:46:30 mx dovecot: auth: Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth Aug 29 01:46:30 mx dovecot: auth: Debug: Module loaded: /usr/lib/dovecot/modules/auth/lib20_auth_var_expand_crypt.so Aug 29 01:46:30 mx dovecot: auth: Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so Aug 29 01:46:30 mx dovecot: auth: Debug: Read auth token secret from /run/dovecot/auth-token-secret.dat Aug 29 01:46:30 mx dovecot: auth: Debug: passwd-file /etc/dovecot/dovecot-master-users: Read 1 users in 0 secs Aug 29 01:46:30 mx dovecot: auth: Debug: auth client connected (pid=648541) Aug 29 01:46:30 mx dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=Y+4ayVrnJ9VV/kpz#011lip=217.199.121.254#011rip=xx.xx.xx.xx#011lport=993#011rport=54567#011resp=AHBvc3RtYXN0ZXJAbWFpbGNpdGFkZWwueHl6ADJoZWt1cWUy (previous base64 data may contain sensitive data) Aug 29 01:46:30 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,xx.xx.xx.xx,): Performing passdb lookup Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: Module loaded: /usr/lib/dovecot/modules/auth/lib20_auth_var_expand_crypt.so Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: passwd-file /etc/dovecot/dovecot-master-users: Read 1 users in 0 secs Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): Server accepted connection (fd=15) Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): Sending version handshake Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<1>: Handling PASSV request Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<1>: sql(myuser@mydomain.xyz,xx.xx.xx.xx,): Performing passdb lookup Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<1>: sql(myuser@mydomain.xyz,xx.xx.xx.xx,): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:46:30 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,xx.xx.xx.xx,): Finished passdb lookup Aug 29 01:46:30 mx dovecot: auth: Debug: auth(myuser@mydomain.xyz,xx.xx.xx.xx,): Auth request finished Aug 29 01:46:30 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser@mydomain.xyz Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<1>: sql(myuser@mydomain.xyz,xx.xx.xx.xx,): Finished passdb lookup Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<1>: Finished Aug 29 01:46:30 mx dovecot: auth: Debug: master in: REQUEST#0111167065089#011648541#0111#0119960b0ca9068c3c686e5310a3c9fb9e7#011session_pid=648544#011request_auth_token Aug 29 01:46:30 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,xx.xx.xx.xx,): Performing userdb lookup Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<2>: Handling USER request Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<2>: sql(myuser@mydomain.xyz,xx.xx.xx.xx,): Performing userdb lookup Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<2>: sql(myuser@mydomain.xyz,xx.xx.xx.xx,): SELECT LOWER('myuser@mydomain.xyz') AS master_user, LOWER(CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir)) AS home, CONCAT(mailbox.mailboxformat, ':~/', mailbox.mailboxfolder) AS mail, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<2>: sql(myuser@mydomain.xyz,xx.xx.xx.xx,): Finished userdb lookup Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<2>: Finished Aug 29 01:46:30 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,xx.xx.xx.xx,): Finished userdb lookup Aug 29 01:46:30 mx dovecot: auth: Debug: master userdb out: USER#0111167065089#011myuser@mydomain.xyz#011master_user=myuser@mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/p/o/s/postmaster/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=7933ad17f03af83724ece6df2635483b7dadf3b4 Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Added userdb setting: plugin/master_user=myuser@mydomain.xyz Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/mydomain.xyz/p/o/s/postmaster/ Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser@mydomain.xyz Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser@mydomain.xyz Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser@mydomain.xyz Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser@mydomain.xyz Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: quota-dict: user=myuser@mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: maildir++: root=/var/vmail/vmail1/mydomain.xyz/p/o/s/postmaster//Maildir, index=, indexpvt=, control=, inbox=/var/vmail/vmail1/mydomain.xyz/p/o/s/postmaster//Maildir, alt= Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: acl: owner = 1 Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%Ld/%Ln Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, alt= Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: acl: owner = 0 Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/p/o/s/postmaster//Maildir/dovecot-acl not found Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/p/o/s/postmaster//Maildir/.Sent/dovecot-acl not found Aug 29 01:46:30 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:58 mx dovecot: auth: Debug: auth client connected (pid=648548) Aug 29 01:46:58 mx dovecot: auth: Debug: auth client connected (pid=648549) Aug 29 01:46:58 mx dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=e27BylrnOq5/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=44602#011local_name=127.0.0.1#011resp=AHRlc3RAbWFpbGNpdGFkZWwueHl6ADRIUFgxa3Q5IQ== (previous base64 data may contain sensitive data) Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<3>: Handling PASSV request Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<3>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<3>: sql(myuser@mydomain.xyz,127.0.0.1,): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<3>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<3>: Finished Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: auth(myuser@mydomain.xyz,127.0.0.1,): Auth request finished Aug 29 01:46:58 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: auth: Debug: master in: REQUEST#011656408577#011648548#0111#011a0ccbf759f343f0dddc21d76e549f523#011session_pid=648550#011request_auth_token Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<4>: Handling USER request Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<4>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<4>: sql(myuser@mydomain.xyz,127.0.0.1,): SELECT LOWER('myuser@mydomain.xyz') AS master_user, LOWER(CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir)) AS home, CONCAT(mailbox.mailboxformat, ':~/', mailbox.mailboxfolder) AS mail, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<4>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<4>: Finished Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: master userdb out: USER#011656408577#011myuser@mydomain.xyz#011master_user=myuser@mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=337bc511c6d68fee766b06b089f9ebf60b79a31b Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:46:58 mx dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=B9jBylrnPq5/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=44606#011local_name=127.0.0.1#011resp=AHRlc3RAbWFpbGNpdGFkZWwueHl6ADRIUFgxa3Q5IQ== (previous base64 data may contain sensitive data) Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<5>: Handling PASSV request Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<5>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<5>: sql(myuser@mydomain.xyz,127.0.0.1,): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<5>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<5>: Finished Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: auth(myuser@mydomain.xyz,127.0.0.1,): Auth request finished Aug 29 01:46:58 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Added userdb setting: plugin/master_user=myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:46:58 mx dovecot: auth: Debug: master in: REQUEST#011245760001#011648549#0111#011515fb953bec25b1461c9e7ac64b2029b#011session_pid=648551#011request_auth_token Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<6>: Handling USER request Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<6>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<6>: sql(myuser@mydomain.xyz,127.0.0.1,): SELECT LOWER('myuser@mydomain.xyz') AS master_user, LOWER(CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir)) AS home, CONCAT(mailbox.mailboxformat, ':~/', mailbox.mailboxfolder) AS mail, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<6>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<6>: Finished Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: master userdb out: USER#011245760001#011myuser@mydomain.xyz#011master_user=myuser@mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=91ae717b4f4cdfa5583bb297479b1a0cfd764a78 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/ Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: quota-dict: user=myuser@mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: maildir++: root=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, index=, indexpvt=, control=, inbox=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, alt= Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: acl: owner = 1 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%Ld/%Ln Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, alt= Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: acl: owner = 0 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Added userdb setting: plugin/master_user=myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/ Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: quota-dict: user=myuser@mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: maildir++: root=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, index=, indexpvt=, control=, inbox=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, alt= Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: acl: owner = 1 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%Ld/%Ln Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, alt= Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: acl: owner = 0 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/dovecot-acl not found Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/.Sent/dovecot-acl not found Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/.Drafts/dovecot-acl not found Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/.Trash/dovecot-acl not found Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/.Junk/dovecot-acl not found Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Namespace Shared/: Using permissions from : mode=0700 gid=default Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/dovecot-acl not found Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Mailbox INBOX: UID 1: Opened mail because: prefetch Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648551>: Debug: Mailbox INBOX: UID 1: Opened mail because: bodystructure (Mail has other cached fields, reset_id=1661671904) Aug 29 01:46:58 mx dovecot: auth: Debug: auth client connected (pid=648554) Aug 29 01:46:58 mx dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=cZnGylrnQq5/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=44610#011local_name=127.0.0.1#011resp=AHRlc3RAbWFpbGNpdGFkZWwueHl6ADRIUFgxa3Q5IQ== (previous base64 data may contain sensitive data) Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<7>: Handling PASSV request Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<7>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<7>: sql(myuser@mydomain.xyz,127.0.0.1,): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<7>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<7>: Finished Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: auth(myuser@mydomain.xyz,127.0.0.1,): Auth request finished Aug 29 01:46:58 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: auth: Debug: master in: REQUEST#0112451439617#011648554#0111#01185950d6991c145f770031243a0ee85df#011session_pid=648555#011request_auth_token Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<8>: Handling USER request Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<8>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<8>: sql(myuser@mydomain.xyz,127.0.0.1,): SELECT LOWER('myuser@mydomain.xyz') AS master_user, LOWER(CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir)) AS home, CONCAT(mailbox.mailboxformat, ':~/', mailbox.mailboxfolder) AS mail, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<8>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<8>: Finished Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: master userdb out: USER#0112451439617#011myuser@mydomain.xyz#011master_user=myuser@mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=b219e107b4a03047bae29da5dfc9ff9d59040288 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Added userdb setting: plugin/master_user=myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/ Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: quota-dict: user=myuser@mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: maildir++: root=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, index=, indexpvt=, control=, inbox=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, alt= Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: acl: owner = 1 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%Ld/%Ln Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, alt= Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: acl: owner = 0 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/dovecot-acl not found Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Mailbox INBOX: UID 1: Opened mail because: prefetch Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648555>: Debug: Mailbox INBOX: UID 1: Opened mail because: bodystructure (Mail has other cached fields, reset_id=1661671904) Aug 29 01:46:58 mx dovecot: auth: Debug: auth client connected (pid=648556) Aug 29 01:46:58 mx dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=O8LHylrnRK5/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=44612#011local_name=127.0.0.1#011resp=AHRlc3RAbWFpbGNpdGFkZWwueHl6ADRIUFgxa3Q5IQ== (previous base64 data may contain sensitive data) Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<9>: Handling PASSV request Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<9>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<9>: sql(myuser@mydomain.xyz,127.0.0.1,): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<9>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<9>: Finished Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: auth(myuser@mydomain.xyz,127.0.0.1,): Auth request finished Aug 29 01:46:58 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: auth: Debug: master in: REQUEST#0111870004225#011648556#0111#011300d0a24af7cfc60ba31680ea2b48678#011session_pid=648557#011request_auth_token Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<10>: Handling USER request Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<10>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<10>: sql(myuser@mydomain.xyz,127.0.0.1,): SELECT LOWER('myuser@mydomain.xyz') AS master_user, LOWER(CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir)) AS home, CONCAT(mailbox.mailboxformat, ':~/', mailbox.mailboxfolder) AS mail, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<10>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:46:58 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<10>: Finished Aug 29 01:46:58 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: master userdb out: USER#0111870004225#011myuser@mydomain.xyz#011master_user=myuser@mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=09e37aff8ca8d316bb3b98c62a4135a8a695c4cb Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Added userdb setting: plugin/master_user=myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/ Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: quota-dict: user=myuser@mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: maildir++: root=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, index=, indexpvt=, control=, inbox=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, alt= Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: acl: owner = 1 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%Ld/%Ln Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, alt= Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: acl: owner = 0 Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:58 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/dovecot-acl not found Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Mailbox INBOX: UID 2: Opened mail because: prefetch Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648557>: Debug: Mailbox INBOX: UID 2: Opened mail because: bodystructure (Mail has other cached fields, reset_id=1661671904) Aug 29 01:46:59 mx dovecot: auth: Debug: auth client connected (pid=648558) Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Mailbox INBOX: UID 1: Opened mail because: prefetch Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648550>: Debug: Mailbox INBOX: UID 1: Opened mail because: bodystructure (Mail has other cached fields, reset_id=1661671904) Aug 29 01:46:59 mx dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=HVbWylrnTq5/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=44622#011local_name=127.0.0.1#011resp=AHRlc3RAbWFpbGNpdGFkZWwueHl6ADRIUFgxa3Q5IQ== (previous base64 data may contain sensitive data) Aug 29 01:46:59 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<11>: Handling PASSV request Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<11>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<11>: sql(myuser@mydomain.xyz,127.0.0.1,): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<11>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<11>: Finished Aug 29 01:46:59 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:46:59 mx dovecot: auth: Debug: auth(myuser@mydomain.xyz,127.0.0.1,): Auth request finished Aug 29 01:46:59 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: auth: Debug: master in: REQUEST#01175890689#011648558#0111#011b7f4aa7b3fbeca8198bd8b165d74bd56#011session_pid=648560#011request_auth_token Aug 29 01:46:59 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<12>: Handling USER request Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<12>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<12>: sql(myuser@mydomain.xyz,127.0.0.1,): SELECT LOWER('myuser@mydomain.xyz') AS master_user, LOWER(CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir)) AS home, CONCAT(mailbox.mailboxformat, ':~/', mailbox.mailboxfolder) AS mail, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<12>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<12>: Finished Aug 29 01:46:59 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:46:59 mx dovecot: auth: Debug: master userdb out: USER#01175890689#011myuser@mydomain.xyz#011master_user=myuser@mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=f401b61b175bd41827a85265327b8136f7605b1c Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:46:59 mx dovecot: auth: Debug: auth client connected (pid=648559) Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Added userdb setting: plugin/master_user=myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/ Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: quota-dict: user=myuser@mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: maildir++: root=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, index=, indexpvt=, control=, inbox=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, alt= Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: acl: owner = 1 Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%Ld/%Ln Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, alt= Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: acl: owner = 0 Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/dovecot-acl not found Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Mailbox INBOX: UID 2: Opened mail because: prefetch Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648560>: Debug: Mailbox INBOX: UID 2: Opened mail because: bodystructure (Mail has other cached fields, reset_id=1661671904) Aug 29 01:46:59 mx dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=zXvXylrnUK5/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=44624#011local_name=127.0.0.1#011resp=AHRlc3RAbWFpbGNpdGFkZWwueHl6ADRIUFgxa3Q5IQ== (previous base64 data may contain sensitive data) Aug 29 01:46:59 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<13>: Handling PASSV request Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<13>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<13>: sql(myuser@mydomain.xyz,127.0.0.1,): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<13>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<13>: Finished Aug 29 01:46:59 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:46:59 mx dovecot: auth: Debug: auth(myuser@mydomain.xyz,127.0.0.1,): Auth request finished Aug 29 01:46:59 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: auth: Debug: master in: REQUEST#0111075052545#011648559#0111#011df42e59d960b83fe8c29c0b4f9cac058#011session_pid=648561#011request_auth_token Aug 29 01:46:59 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<14>: Handling USER request Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<14>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<14>: sql(myuser@mydomain.xyz,127.0.0.1,): SELECT LOWER('myuser@mydomain.xyz') AS master_user, LOWER(CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir)) AS home, CONCAT(mailbox.mailboxformat, ':~/', mailbox.mailboxfolder) AS mail, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<14>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:46:59 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<14>: Finished Aug 29 01:46:59 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:46:59 mx dovecot: auth: Debug: master userdb out: USER#0111075052545#011myuser@mydomain.xyz#011master_user=myuser@mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=5d013003077f0353817d0da72fbb421968a97534 Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Added userdb setting: plugin/master_user=myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/ Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: quota-dict: user=myuser@mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: maildir++: root=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, index=, indexpvt=, control=, inbox=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, alt= Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: acl: owner = 1 Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%Ld/%Ln Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, alt= Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: acl: owner = 0 Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/dovecot-acl not found Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Mailbox INBOX: UID 1: Opened mail because: prefetch Aug 29 01:46:59 mx dovecot: imap(myuser@mydomain.xyz)<648561>: Debug: Mailbox INBOX: UID 1: Opened mail because: bodystructure (Mail has other cached fields, reset_id=1661671904) Aug 29 01:47:03 mx dovecot: auth: Debug: auth client connected (pid=648580) Aug 29 01:47:03 mx dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=2aYSy1rnXK5/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=44636#011local_name=127.0.0.1#011resp=AHRlc3RAbWFpbGNpdGFkZWwueHl6ADRIUFgxa3Q5IQ== (previous base64 data may contain sensitive data) Aug 29 01:47:03 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,<2aYSy1rnXK5/AAAB>): Performing passdb lookup Aug 29 01:47:03 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<15>: Handling PASSV request Aug 29 01:47:03 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<15>: sql(myuser@mydomain.xyz,127.0.0.1,<2aYSy1rnXK5/AAAB>): Performing passdb lookup Aug 29 01:47:03 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<15>: sql(myuser@mydomain.xyz,127.0.0.1,<2aYSy1rnXK5/AAAB>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:47:03 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<15>: sql(myuser@mydomain.xyz,127.0.0.1,<2aYSy1rnXK5/AAAB>): Finished passdb lookup Aug 29 01:47:03 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<15>: Finished Aug 29 01:47:03 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,<2aYSy1rnXK5/AAAB>): Finished passdb lookup Aug 29 01:47:03 mx dovecot: auth: Debug: auth(myuser@mydomain.xyz,127.0.0.1,<2aYSy1rnXK5/AAAB>): Auth request finished Aug 29 01:47:03 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser@mydomain.xyz Aug 29 01:47:03 mx dovecot: auth: Debug: master in: REQUEST#011699531265#011648580#0111#011318e185cba03d08de530a2cb862dca4d#011session_pid=648581#011request_auth_token Aug 29 01:47:03 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,<2aYSy1rnXK5/AAAB>): Performing userdb lookup Aug 29 01:47:03 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<16>: Handling USER request Aug 29 01:47:03 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<16>: sql(myuser@mydomain.xyz,127.0.0.1,<2aYSy1rnXK5/AAAB>): Performing userdb lookup Aug 29 01:47:03 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<16>: sql(myuser@mydomain.xyz,127.0.0.1,<2aYSy1rnXK5/AAAB>): SELECT LOWER('myuser@mydomain.xyz') AS master_user, LOWER(CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir)) AS home, CONCAT(mailbox.mailboxformat, ':~/', mailbox.mailboxfolder) AS mail, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:47:03 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<16>: sql(myuser@mydomain.xyz,127.0.0.1,<2aYSy1rnXK5/AAAB>): Finished userdb lookup Aug 29 01:47:03 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<16>: Finished Aug 29 01:47:03 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,<2aYSy1rnXK5/AAAB>): Finished userdb lookup Aug 29 01:47:03 mx dovecot: auth: Debug: master userdb out: USER#011699531265#011myuser@mydomain.xyz#011master_user=myuser@mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=d7d60cb4f5bc934a89b394a5966a70a08a01237c Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Added userdb setting: plugin/master_user=myuser@mydomain.xyz Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/ Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser@mydomain.xyz Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser@mydomain.xyz Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser@mydomain.xyz Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser@mydomain.xyz Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: quota-dict: user=myuser@mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: maildir++: root=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, index=, indexpvt=, control=, inbox=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, alt= Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl: owner = 1 Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%Ld/%Ln Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, alt= Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl: owner = 0 Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/dovecot-acl not found Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/.Sent/dovecot-acl not found Aug 29 01:47:03 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Changing field flags decision temp -> yes (uid=1) Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: UID 1: Opened mail because: prefetch Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Changing field hdr.Bcc decision temp -> yes (uid=1) Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Changing field hdr.Cc decision temp -> yes (uid=1) Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Changing field hdr.Date decision temp -> yes (uid=1) Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Changing field hdr.From decision temp -> yes (uid=1) Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Changing field hdr.In-Reply-To decision temp -> yes (uid=1) Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Changing field hdr.Message-ID decision temp -> yes (uid=1) Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Changing field hdr.Reply-To decision temp -> yes (uid=1) Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Changing field hdr.Sender decision temp -> yes (uid=1) Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Changing field hdr.Subject decision temp -> yes (uid=1) Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Changing field hdr.To decision temp -> yes (uid=1) Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Changing field imap.bodystructure decision temp -> yes (uid=1) Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: UID 1: Opened mail because: header stream Aug 29 01:47:04 mx dovecot: auth: Debug: auth client connected (pid=648582) Aug 29 01:47:04 mx dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=u68ly1rnZK5/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=44644#011local_name=127.0.0.1#011resp=AHRlc3RAbWFpbGNpdGFkZWwueHl6ADRIUFgxa3Q5IQ== (previous base64 data may contain sensitive data) Aug 29 01:47:04 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:47:04 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<17>: Handling PASSV request Aug 29 01:47:04 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<17>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:47:04 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<17>: sql(myuser@mydomain.xyz,127.0.0.1,): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:47:04 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<17>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:47:04 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<17>: Finished Aug 29 01:47:04 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:47:04 mx dovecot: auth: Debug: auth(myuser@mydomain.xyz,127.0.0.1,): Auth request finished Aug 29 01:47:04 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser@mydomain.xyz Aug 29 01:47:04 mx dovecot: auth: Debug: master in: REQUEST#0112228225#011648582#0111#0118c40a8a1ef7dfc6e09cc3b139ab6d3b8#011session_pid=648583#011request_auth_token Aug 29 01:47:04 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:47:04 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<18>: Handling USER request Aug 29 01:47:04 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<18>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:47:04 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<18>: sql(myuser@mydomain.xyz,127.0.0.1,): SELECT LOWER('myuser@mydomain.xyz') AS master_user, LOWER(CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir)) AS home, CONCAT(mailbox.mailboxformat, ':~/', mailbox.mailboxfolder) AS mail, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:47:04 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<18>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:47:04 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<18>: Finished Aug 29 01:47:04 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:47:04 mx dovecot: auth: Debug: master userdb out: USER#0112228225#011myuser@mydomain.xyz#011master_user=myuser@mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=9f18e23092d8e4afb09b8a9ecbe152a6e60d37e5 Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Added userdb setting: plugin/master_user=myuser@mydomain.xyz Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/ Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser@mydomain.xyz Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser@mydomain.xyz Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser@mydomain.xyz Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser@mydomain.xyz Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: quota-dict: user=myuser@mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: maildir++: root=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, index=, indexpvt=, control=, inbox=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, alt= Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: acl: owner = 1 Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%Ld/%Ln Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, alt= Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: acl: owner = 0 Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/.Sent/dovecot-acl not found Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Mailbox Sent: UID 1: Opened mail because: prefetch Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: Mailbox Sent: UID 1: Opened mail because: header stream Aug 29 01:47:04 mx dovecot: imap(myuser@mydomain.xyz)<648583>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/dovecot-acl not found Aug 29 01:47:06 mx dovecot: auth: Debug: auth client connected (pid=648584) Aug 29 01:47:06 mx dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=LstCy1rnaK5/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=44648#011local_name=127.0.0.1#011resp=AHRlc3RAbWFpbGNpdGFkZWwueHl6ADRIUFgxa3Q5IQ== (previous base64 data may contain sensitive data) Aug 29 01:47:06 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<19>: Handling PASSV request Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<19>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<19>: sql(myuser@mydomain.xyz,127.0.0.1,): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<19>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<19>: Finished Aug 29 01:47:06 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:47:06 mx dovecot: auth: Debug: auth(myuser@mydomain.xyz,127.0.0.1,): Auth request finished Aug 29 01:47:06 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: auth: Debug: master in: REQUEST#0112930638849#011648584#0111#011c176cb34e2c20bad60d3203bd9a89c04#011session_pid=648585#011request_auth_token Aug 29 01:47:06 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<20>: Handling USER request Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<20>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<20>: sql(myuser@mydomain.xyz,127.0.0.1,): SELECT LOWER('myuser@mydomain.xyz') AS master_user, LOWER(CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir)) AS home, CONCAT(mailbox.mailboxformat, ':~/', mailbox.mailboxfolder) AS mail, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<20>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<20>: Finished Aug 29 01:47:06 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:47:06 mx dovecot: auth: Debug: master userdb out: USER#0112930638849#011myuser@mydomain.xyz#011master_user=myuser@mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=379d8162ba1592cdc3d2e770c52944169dbaf704 Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Added userdb setting: plugin/master_user=myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/ Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: quota-dict: user=myuser@mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: maildir++: root=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, index=, indexpvt=, control=, inbox=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, alt= Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: acl: owner = 1 Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%Ld/%Ln Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, alt= Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: acl: owner = 0 Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/.Sent/dovecot-acl not found Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Mailbox Sent: UID 2: Opened mail because: prefetch Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: Mailbox Sent: UID 2: Opened mail because: header stream Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648585>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/dovecot-acl not found Aug 29 01:47:06 mx dovecot: auth: Debug: auth client connected (pid=648586) Aug 29 01:47:06 mx dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=JJBEy1rnaq5/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=44650#011local_name=127.0.0.1#011resp=AHRlc3RAbWFpbGNpdGFkZWwueHl6ADRIUFgxa3Q5IQ== (previous base64 data may contain sensitive data) Aug 29 01:47:06 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<21>: Handling PASSV request Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<21>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<21>: sql(myuser@mydomain.xyz,127.0.0.1,): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<21>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<21>: Finished Aug 29 01:47:06 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:47:06 mx dovecot: auth: Debug: auth(myuser@mydomain.xyz,127.0.0.1,): Auth request finished Aug 29 01:47:06 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: auth: Debug: master in: REQUEST#0113705274369#011648586#0111#011ba734ab8cc663beb8f528fc91025f378#011session_pid=648587#011request_auth_token Aug 29 01:47:06 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<22>: Handling USER request Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<22>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<22>: sql(myuser@mydomain.xyz,127.0.0.1,): SELECT LOWER('myuser@mydomain.xyz') AS master_user, LOWER(CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir)) AS home, CONCAT(mailbox.mailboxformat, ':~/', mailbox.mailboxfolder) AS mail, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<22>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:47:06 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<22>: Finished Aug 29 01:47:06 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:47:06 mx dovecot: auth: Debug: master userdb out: USER#0113705274369#011myuser@mydomain.xyz#011master_user=myuser@mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=b0640ae9bdb037f719cb4d4e97bdf4df17dd3367 Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Added userdb setting: plugin/master_user=myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/ Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: quota-dict: user=myuser@mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: maildir++: root=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, index=, indexpvt=, control=, inbox=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, alt= Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: acl: owner = 1 Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%Ld/%Ln Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, alt= Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: acl: owner = 0 Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/.Sent/dovecot-acl not found Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Mailbox Sent: UID 2: Opened mail because: prefetch Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: Mailbox Sent: UID 2: Opened mail because: header stream Aug 29 01:47:06 mx dovecot: imap(myuser@mydomain.xyz)<648587>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/dovecot-acl not found Aug 29 01:47:08 mx dovecot: auth: Debug: auth client connected (pid=648588) Aug 29 01:47:08 mx dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=/u5by1rncK5/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=44656#011local_name=127.0.0.1#011resp=AHRlc3RAbWFpbGNpdGFkZWwueHl6ADRIUFgxa3Q5IQ== (previous base64 data may contain sensitive data) Aug 29 01:47:08 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:47:08 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<23>: Handling PASSV request Aug 29 01:47:08 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<23>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:47:08 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<23>: sql(myuser@mydomain.xyz,127.0.0.1,): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:47:08 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<23>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:47:08 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<23>: Finished Aug 29 01:47:08 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:47:08 mx dovecot: auth: Debug: auth(myuser@mydomain.xyz,127.0.0.1,): Auth request finished Aug 29 01:47:08 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser@mydomain.xyz Aug 29 01:47:08 mx dovecot: auth: Debug: master in: REQUEST#0112063597569#011648588#0111#011bac873a3503f02464a54ef68a928e482#011session_pid=648589#011request_auth_token Aug 29 01:47:08 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:47:08 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<24>: Handling USER request Aug 29 01:47:08 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<24>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:47:08 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<24>: sql(myuser@mydomain.xyz,127.0.0.1,): SELECT LOWER('myuser@mydomain.xyz') AS master_user, LOWER(CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir)) AS home, CONCAT(mailbox.mailboxformat, ':~/', mailbox.mailboxfolder) AS mail, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:47:08 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<24>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:47:08 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): auth-worker<24>: Finished Aug 29 01:47:08 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:47:08 mx dovecot: auth: Debug: master userdb out: USER#0112063597569#011myuser@mydomain.xyz#011master_user=myuser@mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=a73a0f4869a242b4759f230f7bb6422ccb8869f8 Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Added userdb setting: plugin/master_user=myuser@mydomain.xyz Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/ Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser@mydomain.xyz Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser@mydomain.xyz Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser@mydomain.xyz Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser@mydomain.xyz Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: quota-dict: user=myuser@mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: maildir++: root=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, index=, indexpvt=, control=, inbox=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, alt= Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: acl: owner = 1 Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%Ld/%Ln Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, alt= Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: acl: owner = 0 Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/.Sent/dovecot-acl not found Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:47:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/dovecot-acl not found Aug 29 01:48:08 mx dovecot: auth-worker(648543): Debug: conn unix:auth-worker (pid=648542,uid=110): Disconnected: Connection closed (fd=-1) Aug 29 01:51:59 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:52:08 mx dovecot: imap(myuser@mydomain.xyz)<648589>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:55:50 mx dovecot: auth: Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth Aug 29 01:55:50 mx dovecot: auth: Debug: Module loaded: /usr/lib/dovecot/modules/auth/lib20_auth_var_expand_crypt.so Aug 29 01:55:50 mx dovecot: auth: Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so Aug 29 01:55:50 mx dovecot: auth: Debug: Read auth token secret from /run/dovecot/auth-token-secret.dat Aug 29 01:55:50 mx dovecot: auth: Debug: passwd-file /etc/dovecot/dovecot-master-users: Read 1 users in 0 secs Aug 29 01:55:50 mx dovecot: auth: Debug: auth client connected (pid=648812) Aug 29 01:55:50 mx dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=uIx96lrnELB/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=45072#011local_name=127.0.0.1#011resp=AHRlc3RAbWFpbGNpdGFkZWwueHl6ADRIUFgxa3Q5IQ== (previous base64 data may contain sensitive data) Aug 29 01:55:50 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: Module loaded: /usr/lib/dovecot/modules/auth/lib20_auth_var_expand_crypt.so Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: passwd-file /etc/dovecot/dovecot-master-users: Read 1 users in 0 secs Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: conn unix:auth-worker (pid=648813,uid=110): Server accepted connection (fd=15) Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: conn unix:auth-worker (pid=648813,uid=110): Sending version handshake Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<1>: Handling PASSV request Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<1>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<1>: sql(myuser@mydomain.xyz,127.0.0.1,): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:55:50 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:55:50 mx dovecot: auth: Debug: auth(myuser@mydomain.xyz,127.0.0.1,): Auth request finished Aug 29 01:55:50 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser@mydomain.xyz Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<1>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<1>: Finished Aug 29 01:55:50 mx dovecot: auth: Debug: master in: REQUEST#0113702521857#011648812#0111#011e1ec3685eb1e4fd3a62ffd69272c4aec#011session_pid=648815#011request_auth_token Aug 29 01:55:50 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<2>: Handling USER request Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<2>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<2>: sql(myuser@mydomain.xyz,127.0.0.1,): SELECT LOWER('myuser@mydomain.xyz') AS master_user, LOWER(CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir)) AS home, CONCAT(mailbox.mailboxformat, ':~/', mailbox.mailboxfolder) AS mail, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<2>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:55:50 mx dovecot: auth-worker(648814): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<2>: Finished Aug 29 01:55:50 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:55:50 mx dovecot: auth: Debug: master userdb out: USER#0113702521857#011myuser@mydomain.xyz#011master_user=myuser@mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=eb5eddfaab5110960c7915faf8e3e609bb64c17e Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Added userdb setting: plugin/master_user=myuser@mydomain.xyz Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/ Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser@mydomain.xyz Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser@mydomain.xyz Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser@mydomain.xyz Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser@mydomain.xyz Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: quota-dict: user=myuser@mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: maildir++: root=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, index=, indexpvt=, control=, inbox=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, alt= Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: acl: initializing backend with data: vfile Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: acl: owner = 1 Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: acl vfile: Global ACLs disabled Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%Ld/%Ln Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, alt= Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: acl: initializing backend with data: vfile Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: acl: owner = 0 Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: acl vfile: Global ACLs disabled Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:55:50 mx dovecot: imap(myuser@mydomain.xyz)<648815>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/dovecot-acl not found Aug 29 01:56:50 mx dovecot: auth-worker(648814): Debug: conn unix:auth-worker (pid=648813,uid=110): Disconnected: Connection closed (fd=-1) Aug 29 01:56:59 mx dovecot: auth: Debug: auth client connected (pid=648868) Aug 29 01:56:59 mx dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=bWmc7lrnVrB/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=45142#011local_name=127.0.0.1#011resp=AHRlc3RAbWFpbGNpdGFkZWwueHl6ADRIUFgxa3Q5IQ== (previous base64 data may contain sensitive data) Aug 29 01:56:59 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: Module loaded: /usr/lib/dovecot/modules/auth/lib20_auth_var_expand_crypt.so Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: passwd-file /etc/dovecot/dovecot-master-users: Read 1 users in 0 secs Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: conn unix:auth-worker (pid=648813,uid=110): Server accepted connection (fd=15) Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: conn unix:auth-worker (pid=648813,uid=110): Sending version handshake Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<1>: Handling PASSV request Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<1>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing passdb lookup Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<1>: sql(myuser@mydomain.xyz,127.0.0.1,): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:56:59 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:56:59 mx dovecot: auth: Debug: auth(myuser@mydomain.xyz,127.0.0.1,): Auth request finished Aug 29 01:56:59 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser@mydomain.xyz Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<1>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished passdb lookup Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<1>: Finished Aug 29 01:56:59 mx dovecot: auth: Debug: master in: REQUEST#0111804468225#011648868#0111#011c7cbc590470915728ffb8068dc2f5fb0#011session_pid=648870#011request_auth_token Aug 29 01:56:59 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<2>: Handling USER request Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<2>: sql(myuser@mydomain.xyz,127.0.0.1,): Performing userdb lookup Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<2>: sql(myuser@mydomain.xyz,127.0.0.1,): SELECT LOWER('myuser@mydomain.xyz') AS master_user, LOWER(CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir)) AS home, CONCAT(mailbox.mailboxformat, ':~/', mailbox.mailboxfolder) AS mail, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='myuser@mydomain.xyz' AND mailbox.enableimaptls=1 AND mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<2>: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:56:59 mx dovecot: auth-worker(648869): Debug: conn unix:auth-worker (pid=648813,uid=110): auth-worker<2>: Finished Aug 29 01:56:59 mx dovecot: auth: Debug: sql(myuser@mydomain.xyz,127.0.0.1,): Finished userdb lookup Aug 29 01:56:59 mx dovecot: auth: Debug: master userdb out: USER#0111804468225#011myuser@mydomain.xyz#011master_user=myuser@mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=1050b7d18f93722b4e25a03bebefe31a3d93c4d0 Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Added userdb setting: plugin/master_user=myuser@mydomain.xyz Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15/ Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser@mydomain.xyz Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser@mydomain.xyz Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser@mydomain.xyz Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser@mydomain.xyz Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: quota-dict: user=myuser@mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: maildir++: root=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, index=, indexpvt=, control=, inbox=/var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir, alt= Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: acl: initializing backend with data: vfile Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: acl: owner = 1 Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: acl vfile: Global ACLs disabled Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%Ld/%Ln Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, alt= Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: acl: initializing backend with data: vfile Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: acl: acl username = myuser@mydomain.xyz Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: acl: owner = 0 Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: acl vfile: Global ACLs disabled Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:56:59 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: acl vfile: file /var/vmail/vmail1/mydomain.xyz/t/e/s/test-2022.08.28.03.26.15//Maildir/dovecot-acl not found Aug 29 01:57:09 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:57:59 mx dovecot: auth-worker(648869): Debug: conn unix:auth-worker (pid=648813,uid=110): Disconnected: Connection closed (fd=-1) Aug 29 02:02:01 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 02:02:10 mx dovecot: imap(myuser@mydomain.xyz)<648870>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 02:02:50 mx dovecot: imap(myuser@mydomain.xyz)<648544>: Debug: Mailbox INBOX: Mailbox opened because: SELECT

On 2022-08-29 07:56, Aki Tuomi wrote:

...

On 28/08/2022 09:20 EEST Serveria Support support@serveria.com wrote:

I'm trying to setup Dovecot with mail-crypt plugin with per-user encryption.

I have configured mail-crypt plugin as per official guide here: https://doc.dovecot.org/configuration_manual/mail_crypt_plugin/

After that I created a user and an encrypted key by running this command: doveadm -o \plugin/mail_crypt_private_password=12345 mailbox cryptokey generate -u mail@example.org -URf (replacing dummy data ofc)

I can log in to webmail (and Dovecot) just fine, emails are getting sent and delivered. I have also checked the storage and the messages seem to be stored encrypted.

However, I can't read the emails in webmail (just headers can be seen) and in Dovecot logs I can see the following error:

failed: Private key not available: Cannot decrypt key ### Cannot decrypt key ### <8632: Password not available (FETCH RFC822.HEADER)

There seems to be an issue with mySQL query. The query I'm using (Select username as "user", password,"%w" as userdb_mail_crypt_private_password from mailbox;) seems to work just fine, when run from mysql prompt it outputs the usernames and passwords, but the error is still there (Cannot decrypt key ### Password not available).

Any ideas? What am I missing

Hi!

First of all, it's super-unsafe to use user's password like that as private password, at least run it through SHA256. This prevents dovecot from doing expansions on it by accident.

Secondly, enable mail_debug=yes and auth_debug=yes, run it again, and make sure the correct value gets added as 'plugin/mail_crypt_private_password' when using with webmail.

Aki