thr3ads.net - dovecot - Dovecot mail-crypt webmail can't read encrypted messages [Sep 2022]

If this information is useful, please help other people find it:
Share via:

Serveria Support

2022-Sep-14 13:41 UTC

Dovecot mail-crypt webmail can't read encrypted messages

Hi,

This log shows no errors. Running doveadm fetch command gives me this:

doveadm(user at mydomain.xyz): Error: fetch(text) failed for box=INBOX 
uid=15: read() failed: 
read(/var/vmail/vmail1/mydomain.xyz/a/b/d/xxxxxxxx-2022.09.09.05.52.29//Maildir/cur/1663034263.M491074P1457418.mx,S=2217,W=2266:2,S)
failed: Private key not available: Cannot decrypt key 
fd98762c573b8c54805884838695bd5b7eaeb9e0b0d326434c2f63a95a905a89: Cannot 
decrypt key 
10fed5d3e938ce19a20046b84f29e50a271f6404f0760037996b4cf2d1ecfeb7: 
Password not available

On 2022-09-13 14:43, hi at zakaria.website wrote:> On 2022-09-02 20:40, Serveria Support wrote:
>> I tried it but it doesn't seem to make any difference at all.
>> 
>> Can someone please assist me with reading logs? Does this log below 
>> mean Dovecot is trying to use master_user again or simply reading 
>> master_user password file?
>> 
>> Sep  2 15:35:33 mx dovecot: auth: Debug: Read auth token secret from 
>> /run/dovecot/auth-token-secret.dat
>> Sep  2 15:35:33 mx dovecot: auth: Debug: passwd-file 
>> /etc/dovecot/dovecot-master-users: Read 1 users in 0 secs
>> Sep  2 15:35:33 mx dovecot: auth: Debug: auth client connected 
>> (pid=900284)
>> Sep  2 15:35:33 mx dovecot: auth: Debug: client in: 
>>
AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=Vfxm1bbnRo9/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=36678#011local_name=127.0.0.1#011resp=AHRlc3RvQG1haWxjaXRhZGVsLnh5egA0SFBYMWt0OSE=
>> (previous base64 data may contain sensitive data)
>> 
>> Everything ok here?
>> 
>> Sep  2 15:25:34 mx dovecot: auth: Debug: auth client connected 
>> (pid=899859)
>> Sep  2 15:25:34 mx dovecot: auth: Debug: client in: 
>>
AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=97OusbbnXI1/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=36188#011local_name=127.0.0.1#011resp=AHRlc3RvQG1haWxjaXRhZGVsLnh5egA0SFBYMWt0OSE=
>> (previous base64 data may contain sensitive data)
>> Sep  2 15:25:34 mx dovecot: auth: Debug: 
>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
Performing
>> passdb lookup
>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>> unix:auth-worker (pid=899853,uid=110): auth-worker<3>: Handling
PASSV
>> request
>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>> unix:auth-worker (pid=899853,uid=110): auth-worker<3>: 
>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
Performing
>> passdb lookup
>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>> unix:auth-worker (pid=899853,uid=110): auth-worker<3>: 
>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>): query:
SELECT
>> mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE 
>> mailbox.username='user1 at mydomain.xyz' AND
mailbox.`enableimaptls`=1
>> AND mailbox.active=1 AND mailbox.domain=domain.domain AND 
>> domain.backupmx=0 AND domain.active=1
>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>> unix:auth-worker (pid=899853,uid=110): auth-worker<3>: 
>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>): Finished
passdb
>> lookup
>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>> unix:auth-worker (pid=899853,uid=110): auth-worker<3>: Finished
>> Sep  2 15:25:34 mx dovecot: auth: Debug: 
>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>): Finished
passdb
>> lookup
>> Sep  2 15:25:34 mx dovecot: auth: Debug: 
>> auth(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>): Auth
request
>> finished
>> Sep  2 15:25:34 mx dovecot: auth: Debug: client passdb out: 
>> OK#0111#011user=user1 at mydomain.xyz
>> Sep  2 15:25:34 mx dovecot: auth: Debug: master in: 
>>
REQUEST#0111998585857#011899859#0111#01131314e9e09e38b194a05b78bfe279780#011session_pid=899860#011request_auth_token
>> Sep  2 15:25:34 mx dovecot: auth: Debug: 
>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
Performing
>> userdb lookup
>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>> unix:auth-worker (pid=899853,uid=110): auth-worker<4>: Handling
USER
>> request
>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>> unix:auth-worker (pid=899853,uid=110): auth-worker<4>: 
>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
Performing
>> userdb lookup
>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>> unix:auth-worker (pid=899853,uid=110): auth-worker<4>: 
>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>): SELECT 
>> 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='user1 at mydomain.xyz' AND
mailbox.`enableimaptls`=1
>> AND mailbox.active=1 AND mailbox.domain=domain.domain AND 
>> domain.backupmx=0 AND domain.active=1
>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>> unix:auth-worker (pid=899853,uid=110): auth-worker<4>: 
>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>): Finished
userdb
>> lookup
>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>> unix:auth-worker (pid=899853,uid=110): auth-worker<4>: Finished
>> Sep  2 15:25:34 mx dovecot: auth: Debug: 
>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>): Finished
userdb
>> lookup
>> Sep  2 15:25:34 mx dovecot: auth: Debug: master userdb out: 
>> USER#0111998585857#011user1 at
mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/xxxxx-2022.08.30.06.07.08/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=fac9c351492fd6073176272c79ff65b1b3e87f37
>> 
>> Sep  2 15:25:34 mx dovecot: 
>> imap(user1 at mydomain.xyz)<899860><97OusbbnXI1/AAAB>:
Debug: Added
>> userdb setting: mail=maildir:~/Maildir
>> Sep  2 15:25:34 mx dovecot: 
>> imap(user1 at mydomain.xyz)<899860><97OusbbnXI1/AAAB>:
Debug: Added
>> userdb setting: plugin/quota_rule=*:bytes=1073741824
>> Sep  2 15:25:34 mx dovecot: 
>> imap(user1 at mydomain.xyz)<899860><97OusbbnXI1/AAAB>:
Debug: Effective
>> uid=2000, gid=2000, 
>> home=/var/vmail/vmail1/mydomain.xyz/t/e/s/xxxxx-2022.08.30.06.07.08/
>> 
>> Any ideas?
>> 
>> On 2022-09-02 20:08, dovecot at ptld.com wrote:
>>>> password_query = SELECT \
>>>>   username as user, password, \
>>>>   '%w' AS userdb_mail_crypt_private_password \
>>>>   FROM mailbox WHERE username="%u";
>>> 
>>> Try if using ' instead of " makes a difference.
>>> FROM mailbox WHERE username='%u';
> 
> The logs doesn't show any errors?

hi at zakaria.website

2022-Sep-14 14:23 UTC

head link

Dovecot mail-crypt webmail can't read encrypted messages

On 2022-09-14 14:41, Serveria Support wrote:> Hi,
> 
> This log shows no errors. Running doveadm fetch command gives me this:
> 
> doveadm(user at mydomain.xyz): Error: fetch(text) failed for box=INBOX 
> uid=15: read() failed: 
>
read(/var/vmail/vmail1/mydomain.xyz/a/b/d/xxxxxxxx-2022.09.09.05.52.29//Maildir/cur/1663034263.M491074P1457418.mx,S=2217,W=2266:2,S)
> failed: Private key not available: Cannot decrypt key 
> fd98762c573b8c54805884838695bd5b7eaeb9e0b0d326434c2f63a95a905a89: 
> Cannot decrypt key 
> 10fed5d3e938ce19a20046b84f29e50a271f6404f0760037996b4cf2d1ecfeb7: 
> Password not available
> 
> On 2022-09-13 14:43, hi at zakaria.website wrote:
>> On 2022-09-02 20:40, Serveria Support wrote:
>>> I tried it but it doesn't seem to make any difference at all.
>>> 
>>> Can someone please assist me with reading logs? Does this log below
>>> mean Dovecot is trying to use master_user again or simply reading 
>>> master_user password file?
>>> 
>>> Sep  2 15:35:33 mx dovecot: auth: Debug: Read auth token secret
from
>>> /run/dovecot/auth-token-secret.dat
>>> Sep  2 15:35:33 mx dovecot: auth: Debug: passwd-file 
>>> /etc/dovecot/dovecot-master-users: Read 1 users in 0 secs
>>> Sep  2 15:35:33 mx dovecot: auth: Debug: auth client connected 
>>> (pid=900284)
>>> Sep  2 15:35:33 mx dovecot: auth: Debug: client in: 
>>>
AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=Vfxm1bbnRo9/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=36678#011local_name=127.0.0.1#011resp=AHRlc3RvQG1haWxjaXRhZGVsLnh5egA0SFBYMWt0OSE=
>>> (previous base64 data may contain sensitive data)
>>> 
>>> Everything ok here?
>>> 
>>> Sep  2 15:25:34 mx dovecot: auth: Debug: auth client connected 
>>> (pid=899859)
>>> Sep  2 15:25:34 mx dovecot: auth: Debug: client in: 
>>>
AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=97OusbbnXI1/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=36188#011local_name=127.0.0.1#011resp=AHRlc3RvQG1haWxjaXRhZGVsLnh5egA0SFBYMWt0OSE=
>>> (previous base64 data may contain sensitive data)
>>> Sep  2 15:25:34 mx dovecot: auth: Debug: 
>>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
Performing
>>> passdb lookup
>>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>>> unix:auth-worker (pid=899853,uid=110): auth-worker<3>:
Handling PASSV
>>> request
>>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>>> unix:auth-worker (pid=899853,uid=110): auth-worker<3>: 
>>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
Performing
>>> passdb lookup
>>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>>> unix:auth-worker (pid=899853,uid=110): auth-worker<3>: 
>>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
query: SELECT
>>> mailbox.password, mailbox.allow_nets FROM mailbox,domain WHERE 
>>> mailbox.username='user1 at mydomain.xyz' AND
mailbox.`enableimaptls`=1
>>> AND mailbox.active=1 AND mailbox.domain=domain.domain AND 
>>> domain.backupmx=0 AND domain.active=1
>>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>>> unix:auth-worker (pid=899853,uid=110): auth-worker<3>: 
>>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
Finished passdb
>>> lookup
>>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>>> unix:auth-worker (pid=899853,uid=110): auth-worker<3>:
Finished
>>> Sep  2 15:25:34 mx dovecot: auth: Debug: 
>>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
Finished passdb
>>> lookup
>>> Sep  2 15:25:34 mx dovecot: auth: Debug: 
>>> auth(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
Auth request
>>> finished
>>> Sep  2 15:25:34 mx dovecot: auth: Debug: client passdb out: 
>>> OK#0111#011user=user1 at mydomain.xyz
>>> Sep  2 15:25:34 mx dovecot: auth: Debug: master in: 
>>>
REQUEST#0111998585857#011899859#0111#01131314e9e09e38b194a05b78bfe279780#011session_pid=899860#011request_auth_token
>>> Sep  2 15:25:34 mx dovecot: auth: Debug: 
>>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
Performing
>>> userdb lookup
>>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>>> unix:auth-worker (pid=899853,uid=110): auth-worker<4>:
Handling USER
>>> request
>>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>>> unix:auth-worker (pid=899853,uid=110): auth-worker<4>: 
>>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
Performing
>>> userdb lookup
>>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>>> unix:auth-worker (pid=899853,uid=110): auth-worker<4>: 
>>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
SELECT
>>> 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='user1 at mydomain.xyz' AND
mailbox.`enableimaptls`=1
>>> AND mailbox.active=1 AND mailbox.domain=domain.domain AND 
>>> domain.backupmx=0 AND domain.active=1
>>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>>> unix:auth-worker (pid=899853,uid=110): auth-worker<4>: 
>>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
Finished userdb
>>> lookup
>>> Sep  2 15:25:34 mx dovecot: auth-worker(899854): Debug: conn 
>>> unix:auth-worker (pid=899853,uid=110): auth-worker<4>:
Finished
>>> Sep  2 15:25:34 mx dovecot: auth: Debug: 
>>> sql(user1 at mydomain.xyz,127.0.0.1,<97OusbbnXI1/AAAB>):
Finished userdb
>>> lookup
>>> Sep  2 15:25:34 mx dovecot: auth: Debug: master userdb out: 
>>> USER#0111998585857#011user1 at
mydomain.xyz#011home=/var/vmail/vmail1/mydomain.xyz/t/e/s/xxxxx-2022.08.30.06.07.08/#011mail=maildir:~/Maildir#011quota_rule=*:bytes=1073741824#011auth_mech=PLAIN#011auth_token=fac9c351492fd6073176272c79ff65b1b3e87f37
>>> 
>>> Sep  2 15:25:34 mx dovecot: 
>>> imap(user1 at mydomain.xyz)<899860><97OusbbnXI1/AAAB>:
Debug: Added
>>> userdb setting: mail=maildir:~/Maildir
>>> Sep  2 15:25:34 mx dovecot: 
>>> imap(user1 at mydomain.xyz)<899860><97OusbbnXI1/AAAB>:
Debug: Added
>>> userdb setting: plugin/quota_rule=*:bytes=1073741824
>>> Sep  2 15:25:34 mx dovecot: 
>>> imap(user1 at mydomain.xyz)<899860><97OusbbnXI1/AAAB>:
Debug: Effective
>>> uid=2000, gid=2000, 
>>>
home=/var/vmail/vmail1/mydomain.xyz/t/e/s/xxxxx-2022.08.30.06.07.08/
>>> 
>>> Any ideas?
>>> 
>>> On 2022-09-02 20:08, dovecot at ptld.com wrote:
>>>>> password_query = SELECT \
>>>>>   username as user, password, \
>>>>>   '%w' AS userdb_mail_crypt_private_password \
>>>>>   FROM mailbox WHERE username="%u";
>>>> 
>>>> Try if using ' instead of " makes a difference.
>>>> FROM mailbox WHERE username='%u';
>> 
>> The logs doesn't show any errors?
Private key not available? Isn't clear enough?

Did you set the global private key in dovecot config?

The error is saying the private key that meant to be used to decrypt 
emails is not found, thus it must be the path you set in mail crypt 
plugin definition is incorrect or private key file have either wrong 
ownership or permissions.

Notice it has to be in .pem format as well.

dovecot - Sep 2022 - Dovecot mail-crypt webmail can't read encrypted messages

Dovecot mail-crypt webmail can't read encrypted messages

Dovecot mail-crypt webmail can't read encrypted messages