Dovecot authentication issue - unknown user

B

breefsd

Hello,

I used this "How to" to set up a mail server with Postfix and Dovecot: http://forums.freebsd.org/showthread.php?t=10728 (using a PostgreSQL database to store users).

I'm able to send mails but when trying to send mail to myself (using SMTP via OpenSSL on localhost:25) I face a Dovecot error:
Code: 
Aug 28 13:17:39 <mail.info> mailJail dovecot: auth(default): new auth connection: pid=23743
Aug 28 13:18:30 <mail.info> mailJail dovecot: auth(default): new auth connection: pid=23753
Aug 28 13:18:30 <mail.info> mailJail dovecot: deliver(test@domain.com): Loading modules from directory: /usr/local/lib/dovecot/lda
Aug 28 13:18:30 <mail.info> mailJail dovecot: deliver(test@domain.com): Module loaded: /usr/local/lib/dovecot/lda/lib10_quota_plugin.so
[B]Aug 28 13:18:30 <mail.info> mailJail dovecot: auth(default): master in: USER	1	test@domain.com	service=deliver
Aug 28 13:18:30 <mail.info> mailJail dovecot: auth(default): prefetch(test@domain.com): passdb didn't return userdb entries, trying the next userdb
Aug 28 13:18:30 <mail.info> mailJail dovecot: auth-worker(default): passwd(test@domain.com): lookup
Aug 28 13:18:30 <mail.info> mailJail dovecot: auth-worker(default): passwd(test@domain.com): unknown user[/B]
Aug 28 13:18:30 <mail.info> mailJail dovecot: auth(default): master out: NOTFOUND	1
Aug 28 13:18:30 <mail.info> mailJail postfix/pipe[23756]: DC9FD408: to=<test@domain.com>, relay=dovecot, delay=0.07, delays=0.03/0.03/0/0.02, dsn=5.1.1, status=bounced (user unknown)

In dovecot.conf:
Code: 
protocols = imaps
disable_plaintext_auth = no

ssl = yes
ssl_cert_file = /etc/ssl/dovecot/cert.pem
ssl_key_file = /etc/ssl/dovecot/key.pem

mail_privileged_group = mail
dotlock_use_excl = yes
mail_location = maildir:/mail/%d/%n
verbose_proctitle = yes

# mailnull user id is 26
first_valid_uid = 26
last_valid_uid = 26
mail_uid = mailnull

# mail goup id is 6
first_valid_gid = 6
last_valid_gid = 6
mail_gid = mail

maildir_copy_with_hardlinks = yes

protocol imap {
  imap_client_workarounds = delay-newmail netscape-eoh tb-extra-mailbox-sep
  mail_plugins = quota imap_quota
}

protocol managesieve {}

protocol lda {
  postmaster_address = postmaster@domain.com
  sendmail_path = /usr/sbin/sendmail
  mail_plugins = quota
}

auth_username_format = %Lu

auth default {
  mechanisms = plain
  passdb sql {
    args = /usr/local/etc/dovecot-sql.conf
  }
  userdb prefetch {}

  user = root

  socket listen {
    master {
      path = /var/run/dovecot/auth-master
      mode = 0600
      user = mailnull
      group = mail
    }
    client {
      path = /var/run/dovecot/auth-client
      mode = 0660
      user = postfix
      group = mail
    }
  }
}

dict {}

plugin {
  quota = maildir:User quota
  quota_rule = *:storage=1GB
}

In dovecot-sql.conf:
Code: 
driver = pgsql
connect = host=localhost dbname=mail user=dovecot password=xxxxxxxxxxxx
default_pass_scheme = PLAIN-MD5
password_query = \
  SELECT username, domain, password, '*:bytes=' || quota || 'M' AS userdb_quota_rule \
  FROM mailbox WHERE username = '%n' AND domain = '%d' AND active = true

I queried
Code: 
SELECT username, domain, password, '*:bytes=' || quota || 'M' AS userdb_quota_rule \
  FROM mailbox WHERE username = 'test' AND domain = 'domain.com' AND active = true
in the mail database, which returns the expected row, but I suspect Dovecot uses [email='test@domain.com]'test@domain.com[/email]' as '%n'. I'm not sure about that and I don't know how to change it.

Some help would be really appreciated,
Thanks.
 
Just an edit, I don't know if Dovecot ever executes the SQL query. I don't see any difference with this in dovecot-sql.conf:
Code: 
password_query = foo

I still get the log:
Code: 
passdb didn't return userdb entries, trying the next userdb

Any idea?
 
This is a long shot but have you tried adding something like this in dovecot-sql.conf?
Code: 
user_query = SELECT home, uid, gid FROM users WHERE userid = '%n' AND domain = '%d'
 
I tried but no chance, not surprising since "user query" is not supposed to be used with my Dovecot configuration. The real problem is that I cannot set an upper log level in Dovecot. So I think I must guess why
Code: 
passdb didn't return userdb entries
 
I looked at some PostgreSQL logging. It seems Dovecot doesn't send the SQL query. What I've done is trying to send an email to "test@domain.com" from a fake sender "fake@foo.com" using OpenSSL:
Code: 
[...]
MAIL FROM: fake@foo.com
RCPT TO: test@domain.com
[...]

Some logs if it can help:
Code: 
Aug 29 10:37:56 <mail.info> mailJail postfix/smtpd[81492]: connect from mailJail.domain.com[jailIP.jailIP.jailIP.jailIP]
Aug 29 10:37:56 <mail.info> mailJail dovecot: auth(default): new auth connection: pid=81492
Aug 29 10:38:06 <local0.info> mailJail postgres[81495]: [292-1] postfix mail LOG:  statement: set client_encoding to 'LATIN1'
Aug 29 10:38:06 <local0.info> mailJail postgres[81495]: [293-1] postfix mail LOG:  statement: SELECT dest_username || '@' || dest_domain FROM mailbox_aliases WHERE address = 'foo.com' AND active = true
Aug 29 10:38:06 <local0.info> mailJail postgres[81496]: [292-1] postfix mail LOG:  statement: set client_encoding to 'LATIN1'
Aug 29 10:38:06 <local0.info> mailJail postgres[81496]: [293-1] postfix mail LOG:  statement: SELECT domain FROM mailbox WHERE domain = 'foo.com' AND active = true
Aug 29 10:38:14 <local0.info> mailJail postgres[81495]: [294-1] postfix mail LOG:  statement: SELECT dest_username || '@' || dest_domain FROM mailbox_aliases WHERE address = 'domain.com' AND active = true
Aug 29 10:38:14 <local0.info> mailJail postgres[81496]: [294-1] postfix mail LOG:  statement: SELECT domain FROM mailbox WHERE domain = 'domain.com' AND active = true
Aug 29 10:38:14 <local0.info> mailJail postgres[81498]: [292-1] postfix mail LOG:  statement: set client_encoding to 'LATIN1'
Aug 29 10:38:14 <local0.info> mailJail postgres[81498]: [293-1] postfix mail LOG:  statement: SELECT dest_username || '@' || dest_domain FROM mailbox_aliases WHERE address = 'test@domain.com' AND active = true
Aug 29 10:38:14 <local0.info> mailJail postgres[81498]: [294-1] postfix mail LOG:  statement: SELECT dest_username || '@' || dest_domain FROM mailbox_aliases WHERE address = 'test' AND active = true
Aug 29 10:38:14 <local0.info> mailJail postgres[81498]: [295-1] postfix mail LOG:  statement: SELECT dest_username || '@' || dest_domain FROM mailbox_aliases WHERE address = '@domain.com' AND active = true
Aug 29 10:38:14 <local0.info> mailJail postgres[81499]: [292-1] postfix mail LOG:  statement: set client_encoding to 'LATIN1'
Aug 29 10:38:14 <local0.info> mailJail postgres[81499]: [293-1] postfix mail LOG:  statement: SELECT domain || '/' || username FROM mailbox WHERE username = 'test' AND domain = 'domain.com' AND active = true
Aug 29 10:38:14 <mail.info> mailJail postfix/smtpd[81492]: 8C5926C8: client=mailJail.domain.com[jailIP.jailIP.jailIP.jailIP]
Aug 29 10:38:14 <local0.info> mailJail postgres[81501]: [292-1] postfix mail LOG:  statement: set client_encoding to 'LATIN1'
Aug 29 10:38:14 <local0.info> mailJail postgres[81501]: [293-1] postfix mail LOG:  statement: SELECT dest_username || '@' || dest_domain FROM mailbox_aliases WHERE address = 'test@domain.com' AND active = true
Aug 29 10:38:14 <local0.info> mailJail postgres[81501]: [294-1] postfix mail LOG:  statement: SELECT dest_username || '@' || dest_domain FROM mailbox_aliases WHERE address = 'test' AND active = true
Aug 29 10:38:14 <local0.info> mailJail postgres[81501]: [295-1] postfix mail LOG:  statement: SELECT dest_username || '@' || dest_domain FROM mailbox_aliases WHERE address = '@domain.com' AND active = true
Aug 29 10:38:20 <mail.info> mailJail postfix/cleanup[81500]: 8C5926C8: message-id=<20130829083814.8C5926C8@domain.com>
Aug 29 10:38:20 <mail.info> mailJail postfix/qmgr[81485]: 8C5926C8: from=<fake@foo.com>, size=386, nrcpt=1 (queue active)
Aug 29 10:38:20 <mail.info> mailJail amavis[55478]: loaded policy bank "AM.INET"
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: process_request: fileno sock=10, STDIN=0, STDOUT=1
.
Aug 29 10:38:20 <mail.info> mailJail amavis[55478]: (55478-13) LMTP::10024 /var/amavis/tmp/amavis-20130827T134358-55478-08UE3_CP: <fake@foo.com> -> <test@domain.com> SIZE=386 Received: from domain.com ([jailIP.jailIP.jailIP.jailIP]) by mailJail (mailspc.domain.com [jailIP.jailIP.jailIP.jailIP]) (amavisd-new, port 10024) with LMTP for <test@domain.com>; Thu, 29 Aug 2013 10:38:20 +0200 (CEST)
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) smtp connection cache, dt: 1713.0, state: 0
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) body hash: 157bf78d509a4c07e562f9f830fb5d9f
Aug 29 10:38:20 <mail.info> mailJail amavis[55478]: (55478-13) Checking: 6aX4jHRyjq4U AM.INET <fake@foo.com> -> <test@domain.com>
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) 2822.From: <fake@foo.com>
Aug 29 10:38:20 <mail.info> mailJail amavis[55478]: (55478-13) p001 1 Content-Type: text/plain, size: 4 B, name: 
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) inspect_dsn: not a bounce
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) Checking for banned types and filenames
[B][...][/B]
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) smtp cmd> EHLO mailJail
Aug 29 10:38:20 <mail.info> mailJail dovecot: auth(default): new auth connection: pid=81504
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) smtp resp to EHLO: 250 domain.com\nPIPELINING\nSIZE 10240000\nVRFY\nETRN\nSTARTTLS\nAUTH PLAIN\nAUTH=PLAIN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) AUTH not needed, user='', MTA offers 'PLAIN'
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) smtp cmd> MAIL FROM:<fake@foo.com> BODY=7BIT
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) smtp cmd> RCPT TO:<test@domain.com> ORCPT=rfc822;test@domain.com
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) smtp cmd> DATA
Aug 29 10:38:20 <local0.info> mailJail postgres[81495]: [295-1] postfix mail LOG:  statement: SELECT dest_username || '@' || dest_domain FROM mailbox_aliases WHERE address = 'foo.com' AND active = true
Aug 29 10:38:20 <local0.info> mailJail postgres[81496]: [295-1] postfix mail LOG:  statement: SELECT domain FROM mailbox WHERE domain = 'foo.com' AND active = true
Aug 29 10:38:20 <local0.info> mailJail postgres[81495]: [296-1] postfix mail LOG:  statement: SELECT dest_username || '@' || dest_domain FROM mailbox_aliases WHERE address = 'domain.com' AND active = true
Aug 29 10:38:20 <local0.info> mailJail postgres[81496]: 
[B][...][/B]
Aug 29 10:38:20 <mail.info> mailJail postfix/smtpd[81504]: 9DE196D3: client=mailJail.domain.com[jailIP.jailIP.jailIP.jailIP]
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) smtp resp to MAIL (pip): 250 2.1.0 Ok
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) smtp resp to RCPT (pip) (<test@domain.com>): 250 2.1.5 Ok
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) smtp cmd> QUIT
Aug 29 10:38:20 <local0.info> mailJail postgres[81501]: [296-1] postfix mail LOG:  statement: SELECT dest_username || '@' || dest_domain FROM mailbox_aliases WHERE address = 'test@domain.com' AND active = true
Aug 29 10:38:20 <local0.info> mailJail postgres[81501]: [297-1] postfix mail LOG:  statement: SELECT dest_username || '@' || dest_domain FROM mailbox_aliases WHERE address = 'test' AND active = true
Aug 29 10:38:20 <local0.info> mailJail postgres[81501]: [298-1] postfix mail LOG:  statement: SELECT dest_username || '@' || dest_domain FROM mailbox_aliases WHERE address = '@domain.com' AND active = true
Aug 29 10:38:20 <mail.info> mailJail postfix/cleanup[81500]: 9DE196D3: message-id=<20130829083814.8C5926C8@domain.com>
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) smtp resp to data-dot (<test@domain.com>): 250 2.0.0 Ok: queued as 9DE196D3, dt: 5.2 ms
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) Amavis::Out::SMTP::Session close, disconnecting
Aug 29 10:38:20 <mail.info> mailJail postfix/smtpd[81504]: disconnect from mailJail.domain.com[jailIP.jailIP.jailIP.jailIP]
Aug 29 10:38:20 <mail.info> mailJail postfix/qmgr[81485]: 9DE196D3: from=<fake@foo.com>, size=801, nrcpt=1 (queue active)
Aug 29 10:38:20 <mail.info> mailJail amavis[55478]: (55478-13) FWD from <fake@foo.com> -> <test@domain.com>,BODY=7BIT 250 2.0.0 from MTA(smtp:[jailIP.jailIP.jailIP.jailIP]:10025): 250 2.0.0 Ok: queued as 9DE196D3
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
Aug 29 10:38:20 <local0.info> mailJail postgres[81495]: [297-1] postfix mail LOG:  statement: SELECT dest_username || '@' || dest_domain FROM mailbox_aliases WHERE address = 'domain.com' AND active = true
Aug 29 10:38:20 <mail.notice> mailJail amavis[55478]: (55478-13) Passed CLEAN {RelayedInbound}, AM.INET [jailIP.jailIP.jailIP.jailIP] <fake@foo.com> -> <test@domain.com>, Message-ID: <20130829083814.8C5926C8@domain.com>, mail_id: 6aX4jHRyjq4U, Hits: 1.974, size: 386, queued_as: 9DE196D3, 395 ms
Aug 29 10:38:20 <local0.info> mailJail postgres[81496]: [297-1] postfix mail LOG:  statement: SELECT domain FROM mailbox WHERE domain = 'domain.com' AND active = true
Aug 29 10:38:20 <mail.info> mailJail amavis[55478]: (55478-13) TIMING-SA total 199 ms - parse: 1.31 (0.7%), extract_message_metadata: 49 (24.4%), poll_dns_idle: 41 (20.4%), get_uri_detail_list: 0.27 (0.1%), tests_pri_-1000: 8 (3.9%), tests_pri_-950: 2 (1.1%), tests_pri_-900: 1.60 (0.8%), tests_pri_-400: 1.21 (0.6%), tests_pri_0: 117 (58.8%), check_dkim_adsp: 39 (19.4%), check_razor2: 48 (24.0%), check_pyzor: 0.33 (0.2%), tests_pri_500: 3 (1.7%), get_report: 1.11 (0.6%)
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) LMTP response for <test@domain.com>: "250 2.0.0 from MTA(smtp:[jailIP.jailIP.jailIP.jailIP]:10025): 250 2.0.0 Ok: queued as 9DE196D3"
Aug 29 10:38:20 <mail.info> mailJail postfix/lmtp[81502]: 8C5926C8: to=<test@domain.com>, relay=jailIP.jailIP.jailIP.jailIP[jailIP.jailIP.jailIP.jailIP]:10024, delay=14, delays=14/0.01/0.01/0.4, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[jailIP.jailIP.jailIP.jailIP]:10025): 250 2.0.0 Ok: queued as 9DE196D3)
Aug 29 10:38:20 <mail.info> mailJail amavis[55478]: (55478-13) size: 386, TIMING [total 403 ms] - SMTP greeting: 3 (1%)1, SMTP LHLO: 1 (0%)1, [B][...][/B] rundown: 1 (0%)100
Aug 29 10:38:20 <mail.debug> mailJail amavis[55478]: (55478-13) load: 0 %, total idle 161655.106 s, busy 7.206 s
Aug 29 10:38:20 <mail.info> mailJail postfix/qmgr[81485]: 8C5926C8: removed
Aug 29 10:38:20 <mail.info> mailJail dovecot: deliver(test@domain.com): Loading modules from directory: /usr/local/lib/dovecot/lda
Aug 29 10:38:20 <mail.info> mailJail dovecot: deliver(test@domain.com): Module loaded: /usr/local/lib/dovecot/lda/lib10_quota_plugin.so
[B]Aug 29 10:38:20 <mail.info> mailJail dovecot: auth(default): master in: USER	1	test@domain.com	service=deliver
Aug 29 10:38:20 <mail.info> mailJail dovecot: auth(default): prefetch(test@domain.com): passdb didn't return userdb entries, trying the next userdb
Aug 29 10:38:20 <mail.info> mailJail dovecot: auth-worker(default): passwd(test@domain.com): lookup
Aug 29 10:38:20 <mail.info> mailJail dovecot: auth-worker(default): passwd(test@domain.com): unknown user
Aug 29 10:38:20 <mail.info> mailJail dovecot: auth(default): master out: NOTFOUND	1
Aug 29 10:38:20 <mail.info> mailJail postfix/pipe[81507]: 9DE196D3: to=<test@domain.com>, relay=dovecot, delay=0.07, delays=0.03/0.03/0/0.01, dsn=5.1.1, status=bounced (user unknown)[/B]
[...]
 
Thank you so much, it seems to work correctly, but I suppose it's a Dovecot error related to Dovecot LDA. I really don't understand where the issue is exactly and the problem is not really solved because the "userdb prefetch" is made useless with the LDA.

So this is just a workaround. I added this in dovecot.conf after the "userdb prefetch" statement:
Code: 
userdb sql {
    args = /usr/local/etc/dovecot-sql.conf
}

I added this in dovecot-sql.conf:
Code: 
user_query = \
SELECT 26 AS uid, 6 AS gid \ 
FROM mailbox WHERE username = '%n' AND domain = '%d' AND active = true
(See the "how to" link in my first post.)

Regards
 
You must log in or register to reply here.
Back
Top