dovecot - Feb 2014 - Logging authentication failures when Dovecot's auth service used to authenticate postfix smtpd

Hello,

tl;dr: Is there a way to get dovecot's auth to log failed smtp
authentications without having to switch on "auth_verbose"?
postfix version 2.11.0 and dovecot version 2.2.12

I'm currently migrating my postfix+courier to postfix+dovecot and so
far it's working as expected. Except for logging smtp login failures.

Despite Postfix logging successful authentications (see sample below),
it doesn't log failed smtp logins.
Feb 25 22:28:53 mailer2 postfix/submission[20274]: C981B20198:
client=A-B-C-D.*****.net[A.B.C.D]:63107, sasl_method=PLAIN,
sasl_username=joe at example.net

And since my postfix setup authenticates virtual users through
Dovecot's auth, I thought maybe dovecot could report smtp login
failures the same way it reports imap and pop3 login failures.
Below is a sample extracted from "info_log_path" after several imap
and pop3 login failures. (Obviously the IP 255.... is made up and
irrelevant for this mater).

# begin extract "/var/log/dovecot-info.log"
2014-02-27 21:14:26 auth: Info:
passwd-file(joe at example.net,255.255.255.255,<Y0lbzmnzfwAuQV80>):
Password mismatch
2014-02-27 21:16:46 auth: Info:
passwd-file(foobar,255.255.255.255,<Y0lbzmnzfwAuQV80>): unknown user
2014-02-27 21:52:00 auth: Info:
passwd-file(foo at example.net,255.255.255.255,<0Su6VGrzGwAuQV80>):
unknown user
2014-02-27 21:53:35 auth: Info:
plain(?,255.255.255.255,<0Su6VGrzGwAuQV80>): Empty username
2014-02-27 21:53:55 auth: Info:
plain(?,255.255.255.255,<0Su6VGrzGwAuQV80>): Username character
disallowed by auth_username_chars: 0x5c (username: \0)
2014-02-27 22:08:05 auth: Info: plain(?,255.255.255.255): invalid input
2014-02-27 22:09:36 auth: Info:
passwd-file(joe at example.net,255.255.255.255): Password mismatch
2014-02-27 22:09:53 auth: Info: login(?,255.255.255.255): Empty username
# end extract

I've tried adding "-L -o info_log_path=/var/log/dovecot-info.log"
to
the both auth and auth-worker services but that yield nothing.

----------------------%<--------------------------------

auth_mechanisms = plain login
auth_verbose = yes
base_dir = /var/run/dovecot/
info_log_path = /var/log/dovecot-info.log
log_path = /var/log/dovecot.log
log_timestamp = "%Y-%m-%d %H:%M:%S "

passdb {
  args = scheme=CRYPT username_format=%u /etc/dovecot/virtual_users
  driver = passwd-file
}

userdb {
  args = username_format=%u /etc/dovecot/virtual_users
  default_fields = uid=vmail gid=vmail
  driver = passwd-file
  override_fields = home=/home/vmail/%d/%u
  result_failure = return-fail
  result_internalfail = return-fail
}

service auth-worker {
  executable = auth -w -L -o info_log_path=/var/log/dovecot-info.log
}

service auth {
  executable = auth -L -o info_log_path=/var/log/dovecot-info.log
  unix_listener /var/spool/postfix/private/dovecot-auth {
    group = postfix
    user = postfix
    mode = 0660
  }
}

service lmtp {
  executable = lmtp -L -o info_log_path=/var/log/dovecot-info.log
  unix_listener /var/spool/postfix/private/dovecot-lmtp {
    group = postfix
    user = postfix
    mode = 0660
  }
}

---------------------->%--------------------------------


The relevant postfix config is ...

smtpd_sasl_type = dovecot
smtpd_sasl_path = private/dovecot-auth
virtual_transport = lmtp:unix:private/dovecot-lmtp

Please ignore my previous email. I guess the lack of sleep has taken
the best of me.

What I was trying to achieve is, to have a log entry for every
authentication attempted regardless of its success or failure. And
from that log I should extract the client's IP.

My setup authenticates imap and pop3 users through a "passwd-file"
authentication database. And postfix is setup to authenticate
submissions through the dovecot socket "auth". So far so good.

Currently ("auth_verbose = yes" and "auth_debug = no") when
a client
connects to either imap, pop3 or submission/smtpd and fails to
authenticate, Dovecot *immediately* logs the failure as below.

auth: Info: passwd-file(...) ...
auth: Info: plain(...) ...
auth: Info: login(...) ...

And when a client connects to either imap and pop3 successfully,
Docecot *immediately* logs that too.

The reason I enforce _immediately_ is because successful
submission/smtpd authentications are not logged until after postfix
receives the command "RCPT TO". And as such, the following sequence of
commands will not be logged by Dovecot, and will only be logged as
connect+disconnect by Postfix.

connect to Postfix/Submission/587
Send EHLO...
Send STARTTLS
Send AUTH...
Wait success
Send QUIT
Goto connect

And below is what postfix's log will show after the commands above are
executed by the remote client.

... postfix/smtpd[1234]: connect from host.domain.tld[0.0.0.0]
... postfix/smtpd[1234]: disconnect from host.domain.tld[0.0.0.0]
... postfix/smtpd[5678]: connect from host.domain.tld[0.0.0.0]
... postfix/smtpd[5678]: disconnect from host.domain.tld[0.0.0.0]

So there's no trace in Postfix's log neither in Dovecot's log of the
successful authentication because the client quit the connection after
AUTH and before RCPT TO.

And finally, in order to have every AUTH logged (imap, pop3 and smtpd)
I could set auth_verbose=yes and auth_debug=yes and use syslog to
discard the excess debug messages keeping only the line that reads
    auth: Debug: client in: AUTH ... rip=<...> ...
or instead I could keep auth_verbose=yes and auth_debug=no and patch
src/auth/auth-client-connection.c (see attachment).
-------------- next part --------------
A non-text attachment was scrubbed...
Name: auth-client-connection.patch
Type: text/x-patch
Size: 714 bytes
Desc: not available
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20140228/cf4c7d36/attachment.bin>