Serveria Support
2022-Aug-29 06:26 UTC
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 at mydomain.xyz,xx.xx.xx.xx,<Y+4ayVrnJ9VV/kpz>): 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 at mydomain.xyz,xx.xx.xx.xx,<Y+4ayVrnJ9VV/kpz>): 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 at mydomain.xyz,xx.xx.xx.xx,<Y+4ayVrnJ9VV/kpz>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser at 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 at mydomain.xyz,xx.xx.xx.xx,<Y+4ayVrnJ9VV/kpz>): Finished passdb lookup Aug 29 01:46:30 mx dovecot: auth: Debug: auth(myuser at mydomain.xyz,xx.xx.xx.xx,<Y+4ayVrnJ9VV/kpz>): Auth request finished Aug 29 01:46:30 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser at 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 at mydomain.xyz,xx.xx.xx.xx,<Y+4ayVrnJ9VV/kpz>): 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 at mydomain.xyz,xx.xx.xx.xx,<Y+4ayVrnJ9VV/kpz>): 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 at mydomain.xyz,xx.xx.xx.xx,<Y+4ayVrnJ9VV/kpz>): 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 at mydomain.xyz,xx.xx.xx.xx,<Y+4ayVrnJ9VV/kpz>): SELECT LOWER('myuser at 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 at 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 at mydomain.xyz,xx.xx.xx.xx,<Y+4ayVrnJ9VV/kpz>): 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 at mydomain.xyz,xx.xx.xx.xx,<Y+4ayVrnJ9VV/kpz>): Finished userdb lookup Aug 29 01:46:30 mx dovecot: auth: Debug: master userdb out: USER#0111167065089#011myuser at mydomain.xyz#011master_user=myuser at 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 at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Added userdb setting: plugin/master_user=myuser at mydomain.xyz Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: 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 at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser at mydomain.xyz Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser at mydomain.xyz Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser at mydomain.xyz Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser at mydomain.xyz Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: quota-dict: user=myuser at mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: 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 at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: 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, altAug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: acl: owner = 1 Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: 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 at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, altAug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: acl: owner 0 Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: 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 at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:46:30 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: 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 at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: 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 at mydomain.xyz,127.0.0.1,<e27BylrnOq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<e27BylrnOq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<e27BylrnOq5/AAAB>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser at 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 at mydomain.xyz,127.0.0.1,<e27BylrnOq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<e27BylrnOq5/AAAB>): Finished passdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: auth(myuser at mydomain.xyz,127.0.0.1,<e27BylrnOq5/AAAB>): Auth request finished Aug 29 01:46:58 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser at 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 at mydomain.xyz,127.0.0.1,<e27BylrnOq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<e27BylrnOq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<e27BylrnOq5/AAAB>): SELECT LOWER('myuser at 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 at 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 at mydomain.xyz,127.0.0.1,<e27BylrnOq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<e27BylrnOq5/AAAB>): Finished userdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: master userdb out: USER#011656408577#011myuser at mydomain.xyz#011master_user=myuser at 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 at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: 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 at mydomain.xyz,127.0.0.1,<B9jBylrnPq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<B9jBylrnPq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<B9jBylrnPq5/AAAB>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser at 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 at mydomain.xyz,127.0.0.1,<B9jBylrnPq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<B9jBylrnPq5/AAAB>): Finished passdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: auth(myuser at mydomain.xyz,127.0.0.1,<B9jBylrnPq5/AAAB>): Auth request finished Aug 29 01:46:58 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Added userdb setting: plugin/master_user=myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: 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 at mydomain.xyz,127.0.0.1,<B9jBylrnPq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<B9jBylrnPq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<B9jBylrnPq5/AAAB>): SELECT LOWER('myuser at 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 at 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 at mydomain.xyz,127.0.0.1,<B9jBylrnPq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<B9jBylrnPq5/AAAB>): Finished userdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: master userdb out: USER#011245760001#011myuser at mydomain.xyz#011master_user=myuser at 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 at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/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:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: quota-dict: user=myuser at mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: 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 at mydomain.xyz)<648550><e27BylrnOq5/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, altAug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: acl: owner = 1 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/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:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, altAug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: acl: owner 0 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Added userdb setting: plugin/master_user=myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/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:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: quota-dict: user=myuser at mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: 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 at mydomain.xyz)<648551><B9jBylrnPq5/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, altAug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: acl: owner = 1 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/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:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, altAug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: acl: owner 0 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/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:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/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:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: 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 at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: 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 at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: 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 at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Namespace Shared/: Using permissions from : mode=0700 gid=default Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/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:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: Debug: Mailbox INBOX: UID 1: Opened mail because: prefetch Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648551><B9jBylrnPq5/AAAB>: 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 at mydomain.xyz,127.0.0.1,<cZnGylrnQq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<cZnGylrnQq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<cZnGylrnQq5/AAAB>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser at 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 at mydomain.xyz,127.0.0.1,<cZnGylrnQq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<cZnGylrnQq5/AAAB>): Finished passdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: auth(myuser at mydomain.xyz,127.0.0.1,<cZnGylrnQq5/AAAB>): Auth request finished Aug 29 01:46:58 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser at 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 at mydomain.xyz,127.0.0.1,<cZnGylrnQq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<cZnGylrnQq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<cZnGylrnQq5/AAAB>): SELECT LOWER('myuser at 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 at 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 at mydomain.xyz,127.0.0.1,<cZnGylrnQq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<cZnGylrnQq5/AAAB>): Finished userdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: master userdb out: USER#0112451439617#011myuser at mydomain.xyz#011master_user=myuser at 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 at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Added userdb setting: plugin/master_user=myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/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:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: quota-dict: user=myuser at mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: 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 at mydomain.xyz)<648555><cZnGylrnQq5/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, altAug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: acl: owner = 1 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/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:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, altAug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: acl: owner 0 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/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:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: Debug: Mailbox INBOX: UID 1: Opened mail because: prefetch Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648555><cZnGylrnQq5/AAAB>: 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 at mydomain.xyz,127.0.0.1,<O8LHylrnRK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<O8LHylrnRK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<O8LHylrnRK5/AAAB>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser at 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 at mydomain.xyz,127.0.0.1,<O8LHylrnRK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<O8LHylrnRK5/AAAB>): Finished passdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: auth(myuser at mydomain.xyz,127.0.0.1,<O8LHylrnRK5/AAAB>): Auth request finished Aug 29 01:46:58 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser at 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 at mydomain.xyz,127.0.0.1,<O8LHylrnRK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<O8LHylrnRK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<O8LHylrnRK5/AAAB>): SELECT LOWER('myuser at 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 at 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 at mydomain.xyz,127.0.0.1,<O8LHylrnRK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<O8LHylrnRK5/AAAB>): Finished userdb lookup Aug 29 01:46:58 mx dovecot: auth: Debug: master userdb out: USER#0111870004225#011myuser at mydomain.xyz#011master_user=myuser at 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 at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Added userdb setting: plugin/master_user=myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/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:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: quota-dict: user=myuser at mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: 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 at mydomain.xyz)<648557><O8LHylrnRK5/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, altAug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: acl: owner = 1 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/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:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, altAug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: acl: owner 0 Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:58 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/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:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: Debug: Mailbox INBOX: UID 2: Opened mail because: prefetch Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648557><O8LHylrnRK5/AAAB>: 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 at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: Debug: Mailbox INBOX: UID 1: Opened mail because: prefetch Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648550><e27BylrnOq5/AAAB>: 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 at mydomain.xyz,127.0.0.1,<HVbWylrnTq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<HVbWylrnTq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<HVbWylrnTq5/AAAB>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser at 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 at mydomain.xyz,127.0.0.1,<HVbWylrnTq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<HVbWylrnTq5/AAAB>): Finished passdb lookup Aug 29 01:46:59 mx dovecot: auth: Debug: auth(myuser at mydomain.xyz,127.0.0.1,<HVbWylrnTq5/AAAB>): Auth request finished Aug 29 01:46:59 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser at 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 at mydomain.xyz,127.0.0.1,<HVbWylrnTq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<HVbWylrnTq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<HVbWylrnTq5/AAAB>): SELECT LOWER('myuser at 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 at 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 at mydomain.xyz,127.0.0.1,<HVbWylrnTq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<HVbWylrnTq5/AAAB>): Finished userdb lookup Aug 29 01:46:59 mx dovecot: auth: Debug: master userdb out: USER#01175890689#011myuser at mydomain.xyz#011master_user=myuser at 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 at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: 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 at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Added userdb setting: plugin/master_user=myuser at mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/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:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser at mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser at mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser at mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser at mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: quota-dict: user=myuser at mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: 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 at mydomain.xyz)<648560><HVbWylrnTq5/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, altAug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: acl: owner = 1 Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/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:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, altAug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: acl: owner 0 Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/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:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: Debug: Mailbox INBOX: UID 2: Opened mail because: prefetch Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648560><HVbWylrnTq5/AAAB>: 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 at mydomain.xyz,127.0.0.1,<zXvXylrnUK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<zXvXylrnUK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<zXvXylrnUK5/AAAB>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser at 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 at mydomain.xyz,127.0.0.1,<zXvXylrnUK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<zXvXylrnUK5/AAAB>): Finished passdb lookup Aug 29 01:46:59 mx dovecot: auth: Debug: auth(myuser at mydomain.xyz,127.0.0.1,<zXvXylrnUK5/AAAB>): Auth request finished Aug 29 01:46:59 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser at 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 at mydomain.xyz,127.0.0.1,<zXvXylrnUK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<zXvXylrnUK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<zXvXylrnUK5/AAAB>): SELECT LOWER('myuser at 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 at 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 at mydomain.xyz,127.0.0.1,<zXvXylrnUK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<zXvXylrnUK5/AAAB>): Finished userdb lookup Aug 29 01:46:59 mx dovecot: auth: Debug: master userdb out: USER#0111075052545#011myuser at mydomain.xyz#011master_user=myuser at 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 at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Added userdb setting: plugin/master_user=myuser at mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/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:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser at mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser at mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser at mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser at mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: quota-dict: user=myuser at mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: 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 at mydomain.xyz)<648561><zXvXylrnUK5/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, altAug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: acl: owner = 1 Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/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:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, altAug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: acl: owner 0 Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/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:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: Debug: Mailbox INBOX: UID 1: Opened mail because: prefetch Aug 29 01:46:59 mx dovecot: imap(myuser at mydomain.xyz)<648561><zXvXylrnUK5/AAAB>: 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 at 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 at 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 at mydomain.xyz,127.0.0.1,<2aYSy1rnXK5/AAAB>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser at 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 at 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 at mydomain.xyz,127.0.0.1,<2aYSy1rnXK5/AAAB>): Finished passdb lookup Aug 29 01:47:03 mx dovecot: auth: Debug: auth(myuser at 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 at 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 at 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 at 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 at mydomain.xyz,127.0.0.1,<2aYSy1rnXK5/AAAB>): SELECT LOWER('myuser at 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 at 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 at 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 at 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 at mydomain.xyz#011master_user=myuser at 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 at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:47:03 mx dovecot: imap(myuser at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Added userdb setting: plugin/master_user=myuser at mydomain.xyz Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:47:03 mx dovecot: imap(myuser at 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 at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser at mydomain.xyz Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser at mydomain.xyz Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser at mydomain.xyz Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser at mydomain.xyz Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: quota-dict: user=myuser at mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:47:03 mx dovecot: imap(myuser at 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 at 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, altAug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl: owner = 1 Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:03 mx dovecot: imap(myuser at 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 at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, altAug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl: owner 0 Aug 29 01:47:03 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:03 mx dovecot: imap(myuser at 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 at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:47:03 mx dovecot: imap(myuser at 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 at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:47:03 mx dovecot: imap(myuser at 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 at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:47:04 mx dovecot: imap(myuser at 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 at mydomain.xyz)<648581><2aYSy1rnXK5/AAAB>: Debug: Mailbox Sent: UID 1: Opened mail because: prefetch Aug 29 01:47:04 mx dovecot: imap(myuser at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at mydomain.xyz,127.0.0.1,<u68ly1rnZK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<u68ly1rnZK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<u68ly1rnZK5/AAAB>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser at 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 at mydomain.xyz,127.0.0.1,<u68ly1rnZK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<u68ly1rnZK5/AAAB>): Finished passdb lookup Aug 29 01:47:04 mx dovecot: auth: Debug: auth(myuser at mydomain.xyz,127.0.0.1,<u68ly1rnZK5/AAAB>): Auth request finished Aug 29 01:47:04 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser at 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 at mydomain.xyz,127.0.0.1,<u68ly1rnZK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<u68ly1rnZK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<u68ly1rnZK5/AAAB>): SELECT LOWER('myuser at 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 at 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 at mydomain.xyz,127.0.0.1,<u68ly1rnZK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<u68ly1rnZK5/AAAB>): Finished userdb lookup Aug 29 01:47:04 mx dovecot: auth: Debug: master userdb out: USER#0112228225#011myuser at mydomain.xyz#011master_user=myuser at 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 at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Added userdb setting: plugin/master_user=myuser at mydomain.xyz Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/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:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser at mydomain.xyz Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser at mydomain.xyz Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser at mydomain.xyz Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser at mydomain.xyz Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: quota-dict: user=myuser at mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: 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 at mydomain.xyz)<648583><u68ly1rnZK5/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, altAug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: acl: owner = 1 Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/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:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, altAug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: acl: owner 0 Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/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:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Mailbox Sent: UID 1: Opened mail because: prefetch Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/AAAB>: Debug: Mailbox Sent: UID 1: Opened mail because: header stream Aug 29 01:47:04 mx dovecot: imap(myuser at mydomain.xyz)<648583><u68ly1rnZK5/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: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 at mydomain.xyz,127.0.0.1,<LstCy1rnaK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<LstCy1rnaK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<LstCy1rnaK5/AAAB>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser at 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 at mydomain.xyz,127.0.0.1,<LstCy1rnaK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<LstCy1rnaK5/AAAB>): Finished passdb lookup Aug 29 01:47:06 mx dovecot: auth: Debug: auth(myuser at mydomain.xyz,127.0.0.1,<LstCy1rnaK5/AAAB>): Auth request finished Aug 29 01:47:06 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser at 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 at mydomain.xyz,127.0.0.1,<LstCy1rnaK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<LstCy1rnaK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<LstCy1rnaK5/AAAB>): SELECT LOWER('myuser at 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 at 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 at mydomain.xyz,127.0.0.1,<LstCy1rnaK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<LstCy1rnaK5/AAAB>): Finished userdb lookup Aug 29 01:47:06 mx dovecot: auth: Debug: master userdb out: USER#0112930638849#011myuser at mydomain.xyz#011master_user=myuser at 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 at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Added userdb setting: plugin/master_user=myuser at mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/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:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser at mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser at mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser at mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser at mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: quota-dict: user=myuser at mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: 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 at mydomain.xyz)<648585><LstCy1rnaK5/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, altAug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: acl: owner = 1 Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/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:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, altAug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: acl: owner 0 Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/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:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Mailbox Sent: UID 2: Opened mail because: prefetch Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/AAAB>: Debug: Mailbox Sent: UID 2: Opened mail because: header stream Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648585><LstCy1rnaK5/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: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 at mydomain.xyz,127.0.0.1,<JJBEy1rnaq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<JJBEy1rnaq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<JJBEy1rnaq5/AAAB>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser at 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 at mydomain.xyz,127.0.0.1,<JJBEy1rnaq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<JJBEy1rnaq5/AAAB>): Finished passdb lookup Aug 29 01:47:06 mx dovecot: auth: Debug: auth(myuser at mydomain.xyz,127.0.0.1,<JJBEy1rnaq5/AAAB>): Auth request finished Aug 29 01:47:06 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser at 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 at mydomain.xyz,127.0.0.1,<JJBEy1rnaq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<JJBEy1rnaq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<JJBEy1rnaq5/AAAB>): SELECT LOWER('myuser at 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 at 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 at mydomain.xyz,127.0.0.1,<JJBEy1rnaq5/AAAB>): 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 at mydomain.xyz,127.0.0.1,<JJBEy1rnaq5/AAAB>): Finished userdb lookup Aug 29 01:47:06 mx dovecot: auth: Debug: master userdb out: USER#0113705274369#011myuser at mydomain.xyz#011master_user=myuser at 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 at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Added userdb setting: plugin/master_user=myuser at mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/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:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser at mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser at mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser at mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser at mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: quota-dict: user=myuser at mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: 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 at mydomain.xyz)<648587><JJBEy1rnaq5/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, altAug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: acl: owner = 1 Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/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:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, altAug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: acl: owner 0 Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/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:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Mailbox Sent: UID 2: Opened mail because: prefetch Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/AAAB>: Debug: Mailbox Sent: UID 2: Opened mail because: header stream Aug 29 01:47:06 mx dovecot: imap(myuser at mydomain.xyz)<648587><JJBEy1rnaq5/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: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 at mydomain.xyz,127.0.0.1,</u5by1rncK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,</u5by1rncK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,</u5by1rncK5/AAAB>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser at 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 at mydomain.xyz,127.0.0.1,</u5by1rncK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,</u5by1rncK5/AAAB>): Finished passdb lookup Aug 29 01:47:08 mx dovecot: auth: Debug: auth(myuser at mydomain.xyz,127.0.0.1,</u5by1rncK5/AAAB>): Auth request finished Aug 29 01:47:08 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser at 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 at mydomain.xyz,127.0.0.1,</u5by1rncK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,</u5by1rncK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,</u5by1rncK5/AAAB>): SELECT LOWER('myuser at 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 at 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 at mydomain.xyz,127.0.0.1,</u5by1rncK5/AAAB>): 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 at mydomain.xyz,127.0.0.1,</u5by1rncK5/AAAB>): Finished userdb lookup Aug 29 01:47:08 mx dovecot: auth: Debug: master userdb out: USER#0112063597569#011myuser at mydomain.xyz#011master_user=myuser at 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 at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Added userdb setting: plugin/master_user=myuser at mydomain.xyz Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/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:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser at mydomain.xyz Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser at mydomain.xyz Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser at mydomain.xyz Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser at mydomain.xyz Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: quota-dict: user=myuser at mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: 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 at mydomain.xyz)<648589></u5by1rncK5/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, altAug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: acl: owner = 1 Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/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:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, altAug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: acl: owner 0 Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Mailbox Sent: Mailbox opened because: SELECT Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/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:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:47:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/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: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 at mydomain.xyz)<648589></u5by1rncK5/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:52:08 mx dovecot: imap(myuser at mydomain.xyz)<648589></u5by1rncK5/AAAB>: 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 at mydomain.xyz,127.0.0.1,<uIx96lrnELB/AAAB>): 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 at mydomain.xyz,127.0.0.1,<uIx96lrnELB/AAAB>): 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 at mydomain.xyz,127.0.0.1,<uIx96lrnELB/AAAB>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser at 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 at mydomain.xyz,127.0.0.1,<uIx96lrnELB/AAAB>): Finished passdb lookup Aug 29 01:55:50 mx dovecot: auth: Debug: auth(myuser at mydomain.xyz,127.0.0.1,<uIx96lrnELB/AAAB>): Auth request finished Aug 29 01:55:50 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser at 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 at mydomain.xyz,127.0.0.1,<uIx96lrnELB/AAAB>): 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 at mydomain.xyz,127.0.0.1,<uIx96lrnELB/AAAB>): 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 at mydomain.xyz,127.0.0.1,<uIx96lrnELB/AAAB>): 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 at mydomain.xyz,127.0.0.1,<uIx96lrnELB/AAAB>): SELECT LOWER('myuser at 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 at 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 at mydomain.xyz,127.0.0.1,<uIx96lrnELB/AAAB>): 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 at mydomain.xyz,127.0.0.1,<uIx96lrnELB/AAAB>): Finished userdb lookup Aug 29 01:55:50 mx dovecot: auth: Debug: master userdb out: USER#0113702521857#011myuser at mydomain.xyz#011master_user=myuser at 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 at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Added userdb setting: plugin/master_user=myuser at mydomain.xyz Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/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:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser at mydomain.xyz Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser at mydomain.xyz Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser at mydomain.xyz Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser at mydomain.xyz Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: quota-dict: user=myuser at mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: 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 at mydomain.xyz)<648815><uIx96lrnELB/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, altAug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: acl: owner = 1 Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/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:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, altAug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: acl: owner 0 Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:55:50 mx dovecot: imap(myuser at mydomain.xyz)<648815><uIx96lrnELB/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: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 at mydomain.xyz,127.0.0.1,<bWmc7lrnVrB/AAAB>): 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 at mydomain.xyz,127.0.0.1,<bWmc7lrnVrB/AAAB>): 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 at mydomain.xyz,127.0.0.1,<bWmc7lrnVrB/AAAB>): query: SELECT mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE mailbox.username='myuser at 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 at mydomain.xyz,127.0.0.1,<bWmc7lrnVrB/AAAB>): Finished passdb lookup Aug 29 01:56:59 mx dovecot: auth: Debug: auth(myuser at mydomain.xyz,127.0.0.1,<bWmc7lrnVrB/AAAB>): Auth request finished Aug 29 01:56:59 mx dovecot: auth: Debug: client passdb out: OK#0111#011user=myuser at 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 at mydomain.xyz,127.0.0.1,<bWmc7lrnVrB/AAAB>): 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 at mydomain.xyz,127.0.0.1,<bWmc7lrnVrB/AAAB>): 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 at mydomain.xyz,127.0.0.1,<bWmc7lrnVrB/AAAB>): 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 at mydomain.xyz,127.0.0.1,<bWmc7lrnVrB/AAAB>): SELECT LOWER('myuser at 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 at 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 at mydomain.xyz,127.0.0.1,<bWmc7lrnVrB/AAAB>): 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 at mydomain.xyz,127.0.0.1,<bWmc7lrnVrB/AAAB>): Finished userdb lookup Aug 29 01:56:59 mx dovecot: auth: Debug: master userdb out: USER#0111804468225#011myuser at mydomain.xyz#011master_user=myuser at 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 at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib02_imap_acl_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_last_login_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_mail_crypt_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_mailbox_alias_plugin.so Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Added userdb setting: mail=maildir:~/Maildir Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Added userdb setting: plugin/master_user=myuser at mydomain.xyz Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=1073741824 Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/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:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Quota root: name=user backend=dict args=:proxy::quotadict Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0 Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Quota warning: bytes=1073741824 (100%) messages=0 reverse=no command=quota-warning 100 myuser at mydomain.xyz Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 myuser at mydomain.xyz Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 myuser at mydomain.xyz Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 myuser at mydomain.xyz Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Quota grace: root=user bytes=107374182 (10%) Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: quota-dict: user=myuser at mydomain.xyz, uri=proxy::quotadict, noenforcing=0 Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: 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 at mydomain.xyz)<648870><bWmc7lrnVrB/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, altAug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: acl: owner = 1 Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/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:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: shared: root=/run/dovecot, index=, indexpvt=, control=, inbox=, altAug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: acl: initializing backend with data: vfile Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: acl: acl username = myuser at mydomain.xyz Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: acl: owner 0 Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: acl vfile: Global ACLs disabled Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 01:56:59 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/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:57:09 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: 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 at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 02:02:10 mx dovecot: imap(myuser at mydomain.xyz)<648870><bWmc7lrnVrB/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT Aug 29 02:02:50 mx dovecot: imap(myuser at mydomain.xyz)<648544><Y+4ayVrnJ9VV/kpz>: 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 at 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 at 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
> On 29/08/2022 09:26 EEST Serveria Support <support at serveria.com> wrote: > > > 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:30 mx dovecot: auth-worker(648543): Debug: conn > unix:auth-worker (pid=648542,uid=110): auth-worker<1>: > sql(myuser at mydomain.xyz,xx.xx.xx.xx,<Y+4ayVrnJ9VV/kpz>): query: SELECT > mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE > mailbox.username='myuser at mydomain.xyz' AND mailbox.`enableimaptls`=1 AND > mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 > AND domain.active=1it's not set here.> Aug 29 01:46:30 mx dovecot: auth-worker(648543): Debug: conn > unix:auth-worker (pid=648542,uid=110): auth-worker<2>: > sql(myuser at mydomain.xyz,xx.xx.xx.xx,<Y+4ayVrnJ9VV/kpz>): SELECT > LOWER('myuser at 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 at mydomain.xyz' AND mailbox.`enableimaptls`=1 AND > mailbox.active=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 > AND domain.active=1it's not set here either. So. You are doing master user login, and are wondering why user's password is not available? Master user logins are not really compatible with using user's password as encryption key. Aki> > On 2022-08-29 07:56, Aki Tuomi wrote: > >> On 28/08/2022 09:20 EEST Serveria Support <support at 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 at 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