Dovecot - unknown user / sending mails not possible

Discussion in 'ISPConfig 3 Priority Support' started by muelli75, Nov 21, 2020.

  1. muelli75

    muelli75 Member HowtoForge Supporter

    Hi!

    We did a new setup of Debian 10 and ispconfig 3.2, postfix is reciving mails, dovecot get this mails in the boxes.
    But we are not able to send mails. I think its on the encryption, here ist the log of syslog (dovecot log-level extended)

    First, heres the logfile of opening the inbox
    Code:
    Nov 21 19:30:01 tesoro dovecot: auth-worker(14147): Debug: sql(): SELECT email as user FROM mail_user WHERE server_id = '1'
    Nov 21 19:30:01 tesoro dovecot: auth: Debug: master in: USER#0111#[email protected]#011service=doveadm
    Nov 21 19:30:01 tesoro dovecot: auth: Debug: prefetch([email protected]): passdb didn't return userdb entries, trying the next userdb
    Nov 21 19:30:01 tesoro dovecot: auth-worker(14147): Debug: sql([email protected]): SELECT email as user, maildir as home, CONCAT( maildir_format, ':', maildir, '/', IF(maildir_format='maildir','Maildir',maildir_format)) as mail, uid, gid, CONCAT('*:storage=', quota, 'B') AS quota_rule, CONCAT(maildir, '/.sieve') as sieve FROM mail_user WHERE (login = '[email protected]' OR email = '[email protected]') AND `disabledoveadm` = 'n' AND server_id = '1'
    Nov 21 19:30:01 tesoro dovecot: auth: Debug: userdb out: USER#0111#[email protected]#011home=/var/vmail/abc.at/office#011mail=maildir:/var/vmail/abc.at/office/Maildir#011uid=5000#011gid=5000#011quota_rule=*:storage=157286400B#011sieve=/var/vmail/abc.at/office/.sieve
    Nov 21 19:30:01 tesoro dovecot: auth: Debug: auth client connected (pid=14193)
    Nov 21 19:30:01 tesoro dovecot: pop3-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=127.0.0.1, lip=127.0.0.1, secured, session=<DI8wJqK0yol/AAAB>
    Nov 21 19:30:01 tesoro dovecot: auth: Debug: auth client connected (pid=14195)
    Nov 21 19:30:01 tesoro dovecot: imap-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=127.0.0.1, lip=127.0.0.1, secured, session=<npEwJqK00o9/AAAB>
    Nov 21 19:30:01 tesoro postfix/smtpd[14194]: connect from localhost.localdomain[127.0.0.1]
    Nov 21 19:30:01 tesoro dovecot: auth: Debug: auth client connected (pid=0)
    Nov 21 19:30:01 tesoro postfix/smtpd[14194]: lost connection after CONNECT from localhost.localdomain[127.0.0.1]
    Nov 21 19:30:01 tesoro postfix/smtpd[14194]: disconnect from localhost.localdomain[127.0.0.1] commands=0/0
    Nov 21 19:31:22 tesoro dovecot: imap([email protected])<13839><VRNHC6K0veFQS/Yj>: Connection closed (IDLE running for 0.001 + waiting input for 0.001 secs, 2 B in + 10 B out, state=wait-input) in=917 out=2436 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0

    Now the log of sending mail
    Code:
    Nov 21 19:35:31 tesoro dovecot: auth: Debug: auth client connected (pid=14366)
    Nov 21 19:35:31 tesoro dovecot: imap-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=167.248.133.39, lip=46.4.28.xxx, TLS: Connection closed, session=<XLvbOaK0Dr6n+IUn>
    Nov 21 19:36:39 tesoro postfix/submission/smtpd[14386]: connect from wlan-246-35.stone.at[80.75.246.xxx]
    Nov 21 19:36:39 tesoro dovecot: auth: Debug: auth client connected (pid=0)
    Nov 21 19:36:39 tesoro dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=smtp#011nologin#011lip=46.4.28.16#011rip=80.75.246.35#011secured#011resp=AG9mZmljZUBhc3BoYWx0YnJpbmUuYXQAbnZRdUpzTURNQDhyMw== (previous base64 data may contain sensitive data)
    Nov 21 19:36:39 tesoro dovecot: auth-worker(14388): Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
    Nov 21 19:36:39 tesoro dovecot: auth-worker(14388): Debug: Module loaded: /usr/lib/dovecot/modules/auth/lib20_auth_var_expand_crypt.so
    Nov 21 19:36:39 tesoro dovecot: auth-worker(14388): Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so
    Nov 21 19:36:39 tesoro dovecot: auth-worker(14388): Debug: sql([email protected],80.75.246.xxx): query: SELECT email as user, password, maildir as userdb_home, CONCAT( maildir_format, ':', maildir, '/', IF(maildir_format='maildir','Maildir',maildir_format)) as userdb_mail, uid as userdb_uid, gid as userdb_gid, CONCAT('*:storage=', quota, 'B') AS userdb_quota_rule, CONCAT(maildir, '/.sieve') as userdb_sieve FROM mail_user WHERE (login = '[email protected]' OR email = '[email protected]') AND `disablesmtp` = 'n' AND server_id = '1'
    Nov 21 19:36:39 tesoro dovecot: auth-worker(14388): sql([email protected],80.75.246.xxx): unknown user (given password: REMOVED-BY-MOD)
    Nov 21 19:36:41 tesoro postfix/submission/smtpd[14386]: warning: wlan-246-35.stone-rich.at[80.75.246.xxx]: SASL PLAIN authentication failed:
    Nov 21 19:36:41 tesoro dovecot: auth: Debug: client passdb out: FAIL#0111#[email protected]
    Nov 21 19:36:41 tesoro dovecot: auth: Debug: client in: AUTH#0112#011LOGIN#011service=smtp#011nologin#011lip=46.4.28.xxx#011rip=80.75.246.xxx#011secured
    Nov 21 19:36:45 tesoro dovecot: auth: Debug: client passdb out: CONT#0112#011VXNlcm5hbWU6
    Nov 21 19:36:45 tesoro dovecot: auth: Debug: client in: CONT#0112#011b2ZmaWNlQGFzcGhhbHRicmluZS5hdA== (previous base64 data may contain sensitive data)
    Nov 21 19:36:45 tesoro dovecot: auth: Debug: client passdb out: CONT#0112#011UGFzc3dvcmQ6
    Nov 21 19:36:45 tesoro dovecot: auth: Debug: client in: CONT#0112#011bnZRdUpzTURNQDhyMw== (previous base64 data may contain sensitive data)
    Nov 21 19:36:45 tesoro dovecot: auth-worker(14388): Debug: sql([email protected],80.75.246.xxx): query: SELECT email as user, password, maildir as userdb_home, CONCAT( maildir_format, ':', maildir, '/', IF(maildir_format='maildir','Maildir',maildir_format)) as userdb_mail, uid as userdb_uid, gid as userdb_gid, CONCAT('*:storage=', quota, 'B') AS userdb_quota_rule, CONCAT(maildir, '/.sieve') as userdb_sieve FROM mail_user WHERE (login = '[email protected]' OR email = '[email protected]') AND `disablesmtp` = 'n' AND server_id = '1'
    Nov 21 19:36:45 tesoro dovecot: auth-worker(14388): sql([email protected],80.75.246.xxx): unknown user (given password: REMOVED-BY-MOD)
    Nov 21 19:36:47 tesoro postfix/submission/smtpd[14386]: warning: wlan-246-35.stone.at[80.75.246.xxx]: SASL LOGIN authentication failed: UGFzc3dvcmQ6
    Nov 21 19:36:47 tesoro dovecot: auth: Debug: client passdb out: FAIL#0112#[email protected]
    Nov 21 19:36:49 tesoro postfix/submission/smtpd[14386]: disconnect from wlan-246-35.rich.at[80.75.246.xxx] ehlo=2 starttls=1 auth=0/2 quit=1 commands=4/6
    
    I tried several settings in thunderbird, but none worked. Also sending through webmail (roundcube) is not possible, "Autentication error" is the message.

    Any hints for me? Thanks in advance!

    Martin
     
    Last edited: Nov 21, 2020
  2. Th0m

    Th0m ISPConfig Developer Staff Member ISPConfig Developer

    Hi Martin,

    To set up Roundcube correctly, you have to change the default config file. If the mail and webmail server are on the same host, just use localhost as server and port 25 for submission. You can set this up in /etc/roundcube/config.inc.php. The setting for smtp port should be
    Code:
    $config['smtp_port'] = 25;
    Does the user exist and is sending enabled for that user? Did you change your postfix master.cf accordingly to the Perfect Server guide?
     
  3. muelli75

    muelli75 Member HowtoForge Supporter

  4. Th0m

    Th0m ISPConfig Developer Staff Member ISPConfig Developer

    Can you share the settings used in Thunderbird?
     
  5. muelli75

    muelli75 Member HowtoForge Supporter

    Here the settings of TB: Bildschirmfoto 2020-11-21 um 20.35.02.png
     
  6. Th0m

    Th0m ISPConfig Developer Staff Member ISPConfig Developer

    Did you open port 587 in your firewall?
     
  7. muelli75

    muelli75 Member HowtoForge Supporter

    At this time there is no FW active, first I want to setup the services, than I enable the FW.
    If there is no work to do I activate the FW until I do new setups.
     
  8. Th0m

    Th0m ISPConfig Developer Staff Member ISPConfig Developer

    When sending a email from Thunderbird, do you get a error? If so, can you share that? And can you share your full mail logs?
     
  9. muelli75

    muelli75 Member HowtoForge Supporter

    The TB-Error is not very helpful

    Code:
    Senden der Nachricht ist fehlgeschlagen.
    
    Senden der Nachricht fehlgeschlagen.
    Auf Grund des unerwarteten Fehlers 80004005 fehlgeschlagen. Keine Beschreibung verfügbar.
    Die Nachricht konnte aus unbekannten Gründen nicht über den SMTP-Server milk.maindomain.at gesendet werden. Bitte kontrollieren Sie die SMTP-Server-Einstellungen und versuchen Sie es nochmals.
    Second Post follow, because of characterlimitation.
     
  10. muelli75

    muelli75 Member HowtoForge Supporter

    Here the part of mail.log

    Code:
     21:11:00 milk postfix/submission/smtpd[20100]: connect from wlan-246.XXX.stone.at[80.75.246.XXX]
     21:11:00 milk dovecot: auth: Debug: auth client connected (pid=0)
     21:11:00 milk dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=smtp#011nologin#011lip=46.4.28.16#011rip=80.75.246.XXX#011secured#011resp=AG9mZmljZUBhc3BoYWx0YnJpbmUuYXQAbnZRdUpzTURNQDhyMw== (previous base64 data may contain sensitive data)
     21:11:00 milk dovecot: auth-worker(20018): Debug: sql([email protected],80.75.246.XXX): query: SELECT email as user, password, maildir as userdb_home, CONCAT( maildir_format, ':', maildir, '/', IF(maildir_format='maildir','Maildir',maildir_format)) as userdb_mail, uid as userdb_uid, gid as userdb_gid, CONCAT('*:storage=', quota, 'B') AS userdb_quota_rule, CONCAT(maildir, '/.sieve') as userdb_sieve FROM mail_user WHERE (login = '[email protected]' OR email = '[email protected]') AND `disablesmtp` = 'n' AND server_id = '1'
     21:11:00 milk dovecot: auth-worker(20018): sql([email protected],80.75.246.XXX): unknown user (given password: [email protected])
     21:11:01 milk dovecot: auth: Debug: auth client connected (pid=20120)
     21:11:01 milk dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured#011session=/ZVaj6O0tJF/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=37300#011resp=AG9mZmljZUBhc3BoYWx0YmlybmUuYXQAbnZRdUpzTURNQDhyMw== (previous base64 data may contain sensitive data)
     21:11:01 milk dovecot: auth-worker(20018): Debug: sql([email protected],127.0.0.1,</ZVaj6O0tJF/AAAB>): query: SELECT email as user, password, maildir as userdb_home, CONCAT( maildir_format, ':', maildir, '/', IF(maildir_format='maildir','Maildir',maildir_format)) as userdb_mail, uid as userdb_uid, gid as userdb_gid, CONCAT('*:storage=', quota, 'B') AS userdb_quota_rule, CONCAT(maildir, '/.sieve') as userdb_sieve FROM mail_user WHERE (login = '[email protected]' OR email = '[email protected]') AND `disableimap` = 'n' AND server_id = '1'
     21:11:01 milk dovecot: auth: Debug: client passdb out: OK#0111#[email protected]#011
     21:11:01 milk dovecot: auth: Debug: master in: REQUEST#0113653894145#01120120#0111#01136a4026061f0a21edb004cf42ddd68d2#011session_pid=20121#011request_auth_token
     21:11:01 milk dovecot: auth: Debug: prefetch([email protected],127.0.0.1,</ZVaj6O0tJF/AAAB>): success
     21:11:01 milk dovecot: auth: Debug: master userdb out: USER#0113653894145#[email protected]#011home=/var/vmail/abc.at/office#011mail=maildir:/var/vmail/abc.at/office/Maildir#011uid=5000#011gid=5000#011quota_rule=*:storage=157286400B#011sieve=/var/vmail/abc.at/office/.sieve#011auth_token=9a20243d94fd9254dd0f4303a35d71b1eff5db17
     21:11:01 milk dovecot: imap-login: Login: user=<[email protected]>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=20121, secured, session=</ZVaj6O0tJF/AAAB>
     21:11:01 milk dovecot: imap([email protected])<20121></ZVaj6O0tJF/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules
    --snip--  quota-Moule loaded
     21:11:01 milk dovecot: imap([email protected])<20121></ZVaj6O0tJF/AAAB>: Debug: Added userdb setting: mail=maildir:/var/vmail/abc.at/office/Maildir
     21:11:01 milk dovecot: imap([email protected])<20121></ZVaj6O0tJF/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:storage=157286400B
     21:11:01 milk dovecot: imap([email protected])<20121></ZVaj6O0tJF/AAAB>: Debug: Added userdb setting: plugin/sieve=/var/vmail/abc.at/office/.sieve
     21:11:01 milk dovecot: imap([email protected])<20121></ZVaj6O0tJF/AAAB>: Debug: Effective uid=5000, gid=5000, home=/var/vmail/abc.at/office
    --snip--  quota-things
     21:11:01 milk dovecot: imap([email protected])<20121></ZVaj6O0tJF/AAAB>: Debug: Namespace inbox: type=private, prefix=, sep=., inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/var/vmail/abc.at/office/Maildir
     21:11:01 milk dovecot: imap([email protected])<20121></ZVaj6O0tJF/AAAB>: Debug: maildir++: root=/var/vmail/abc.at/office/Maildir, index=, indexpvt=, control=, inbox=/var/vmail/abc.at/office/Maildir, alt=
     21:11:01 milk dovecot: imap([email protected])<20121></ZVaj6O0tJF/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping
     21:11:01 milk dovecot: imap([email protected])<20121></ZVaj6O0tJF/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: STATUS
     21:11:01 milk dovecot: imap([email protected])<20121></ZVaj6O0tJF/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT
     21:11:01 milk dovecot: imap([email protected])<20121></ZVaj6O0tJF/AAAB>: Logged out in=90 out=1009 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
     21:11:02 milk postfix/submission/smtpd[20100]: warning: wlan-246.XXX.stone.at[80.75.246.XXX]: SASL PLAIN authentication failed:
     21:11:02 milk dovecot: auth: Debug: client passdb out: FAIL#0111#[email protected]
     21:11:02 milk dovecot: auth: Debug: client in: AUTH#0112#011LOGIN#011service=smtp#011nologin#011lip=46.4.28.16#011rip=80.75.246.XXX#011secured
     21:11:06 milk dovecot: auth: Debug: client passdb out: CONT#0112#011VXNlcm5hbWU6
     21:11:06 milk dovecot: auth: Debug: client in: CONT#0112#011b2ZmaWNlQGFzcGhhbHRicmluZS5hdA== (previous base64 data may contain sensitive data)
     21:11:06 milk dovecot: auth: Debug: client passdb out: CONT#0112#011UGFzc3dvcmQ6
     21:11:06 milk dovecot: auth: Debug: client in: CONT#0112#011bnZRdUpzTURNQDhyMw== (previous base64 data may contain sensitive data)
     21:11:06 milk dovecot: auth-worker(20018): Debug: sql([email protected],80.75.246.XXX): query: SELECT email as user, password, maildir as userdb_home, CONCAT( maildir_format, ':', maildir, '/', IF(maildir_format='maildir','Maildir',maildir_format)) as userdb_mail, uid as userdb_uid, gid as userdb_gid, CONCAT('*:storage=', quota, 'B') AS userdb_quota_rule, CONCAT(maildir, '/.sieve') as userdb_sieve FROM mail_user WHERE (login = '[email protected]' OR email = '[email protected]') AND `disablesmtp` = 'n' AND server_id = '1'
     21:11:06 milk dovecot: auth-worker(20018): sql([email protected],80.75.246.XXX): unknown user (given password: [email protected])
     21:11:08 milk postfix/submission/smtpd[20100]: warning: wlan-246.XXX.stone.at[80.75.246.XXX]: SASL LOGIN authentication failed: UGFzc3dvcmQ6
     21:11:08 milk dovecot: auth: Debug: client passdb out: FAIL#0112#[email protected]
     21:11:10 milk postfix/submission/smtpd[20100]: disconnect from wlan-246.XXX.stone.at[80.75.246.XXX] ehlo=2 starttls=1 auth=0/2 quit=1 commands=4/6
     21:12:01 milk dovecot: auth: Debug: auth client connected (pid=20138)
     21:12:01 milk dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured#011session=Eb3vkqO0tpF/AAAB#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=37302#011resp=AG9mZmljZUBhc3BoYWx0YmlybmUuYXQAbnZRdUpzTURNQDhyMw== (previous base64 data may contain sensitive data)
     21:12:01 milk dovecot: auth-worker(20018): Debug: sql([email protected],127.0.0.1,<Eb3vkqO0tpF/AAAB>): query: SELECT email as user, password, maildir as userdb_home, CONCAT( maildir_format, ':', maildir, '/', IF(maildir_format='maildir','Maildir',maildir_format)) as userdb_mail, uid as userdb_uid, gid as userdb_gid, CONCAT('*:storage=', quota, 'B') AS userdb_quota_rule, CONCAT(maildir, '/.sieve') as userdb_sieve FROM mail_user WHERE (login = '[email protected]' OR email = '[email protected]') AND `disableimap` = 'n' AND server_id = '1'
     21:12:01 milk dovecot: auth: Debug: client passdb out: OK#0111#[email protected]#011
     21:12:01 milk dovecot: auth: Debug: master in: REQUEST#0112759983105#01120138#0111#01140b195156a632eb372861dc53a225efe#011session_pid=20139#011request_auth_token
     21:12:01 milk dovecot: auth: Debug: prefetch([email protected],127.0.0.1,<Eb3vkqO0tpF/AAAB>): success
     21:12:01 milk dovecot: auth: Debug: master userdb out: USER#0112759983105#[email protected]#011home=/var/vmail/abc.at/office#011mail=maildir:/var/vmail/abc.at/office/Maildir#011uid=5000#011gid=5000#011quota_rule=*:storage=157286400B#011sieve=/var/vmail/abc.at/office/.sieve#011auth_token=83624bd46548d892086e5ef47f8cdd09fffb2509
     21:12:01 milk dovecot: imap-login: Login: user=<[email protected]>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=20139, secured, session=<Eb3vkqO0tpF/AAAB>
     21:12:01 milk dovecot: imap([email protected])<20139><Eb3vkqO0tpF/AAAB>: Debug: Loading modules from directory: /usr/lib/dovecot/modules
    --snip--  quota-Moule loaded
     21:12:01 milk dovecot: imap([email protected])<20139><Eb3vkqO0tpF/AAAB>: Debug: Added userdb setting: mail=maildir:/var/vmail/abc.at/office/Maildir
     21:12:01 milk dovecot: imap([email protected])<20139><Eb3vkqO0tpF/AAAB>: Debug: Added userdb setting: plugin/quota_rule=*:storage=157286400B
     21:12:01 milk dovecot: imap([email protected])<20139><Eb3vkqO0tpF/AAAB>: Debug: Added userdb setting: plugin/sieve=/var/vmail/abc.at/office/.sieve
     21:12:01 milk dovecot: imap([email protected])<20139><Eb3vkqO0tpF/AAAB>: Debug: Effective uid=5000, gid=5000, home=/var/vmail/abc.at/office
    --snip--  quota-things
     21:12:01 milk dovecot: imap([email protected])<20139><Eb3vkqO0tpF/AAAB>: Debug: Namespace inbox: type=private, prefix=, sep=., inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/var/vmail/abc.at/office/Maildir
     21:12:01 milk dovecot: imap([email protected])<20139><Eb3vkqO0tpF/AAAB>: Debug: maildir++: root=/var/vmail/abc.at/office/Maildir, index=, indexpvt=, control=, inbox=/var/vmail/abc.at/office/Maildir, alt=
     21:12:01 milk dovecot: imap([email protected])<20139><Eb3vkqO0tpF/AAAB>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping
     21:12:01 milk dovecot: imap([email protected])<20139><Eb3vkqO0tpF/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: STATUS
     21:12:01 milk dovecot: imap([email protected])<20139><Eb3vkqO0tpF/AAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT
     21:12:01 milk dovecot: imap([email protected])<20139><Eb3vkqO0tpF/AAAB>: Logged out in=90 out=1009 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
    
     
  11. Th0m

    Th0m ISPConfig Developer Staff Member ISPConfig Developer

    Dovecot is not related, only Postfix. Are there more lines regarding Postfix?
     
  12. muelli75

    muelli75 Member HowtoForge Supporter

    OMG - it was a typo in the loginname! Shame on me!

    Thanks for your hint on roundcube - that was really a big help. So this thread was not completely unnecessary.

    Sorry for the rest. o_O
     
  13. Th0m

    Th0m ISPConfig Developer Staff Member ISPConfig Developer

    No problem ;) Glad to hear it's fixed
     

Share This Page