[Dovecot] Auth Worker failures

Simon Brereton simon.brereton at buongiorno.com
Thu Oct 20 23:24:43 EEST 2011


On 18 October 2011 10:37, Timo Sirainen <tss at iki.fi> wrote:
> On Wed, 2011-10-12 at 10:24 -0400, Simon Brereton wrote:
>>
>>
>> Of all the accounts on the box, it's only mine that throws this up.
>> Since its LIP is localhost, it could really only be for webmail - but
>> I don't always leave the webmail open, so I'm curious to know how this
>> gets there and what it is.
>>
>> Any suggestions?  I find it difficult to believe I have an IMAP
>> process in a script somewhere (especially with my user account - the
>> postmaster account, I could believe, but not with my personal one)..
>>
> You could enable auth_debug_passwords=yes and see what password it
> tries.

The first day I did this, I forgot to restart dovecot.  Doh.  This
morning I had:



Oct 20 06:25:14 mail dovecot: auth(default): client in:
AUTH#0112#011PLAIN#011service=imap#011secured#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=50683#011resp=--alsoremoved--==
Oct 20 06:25:14 mail dovecot: auth-worker(default):
sql(simon at example.net,127.0.0.1): query: SELECT EmailAdd AS user,
Password AS password,  concat('/var/spool/mail/virtual/',MailDirLoc)
as userdb_home, 999 as userdb_uid, 115 as userdb_gid FROM MailAccounts
WHERE Username='simon at example.net' AND active = '1';
Oct 20 06:25:14 mail dovecot: auth-worker(default):
sql(simon at example.net,127.0.0.1): Password mismatch
Oct 20 06:25:14 mail dovecot: auth-worker(default):
md5_verify(simon at example.net): Not a valid MD5-CRYPT or PLAIN-MD5
password
Oct 20 06:25:14 mail dovecot: auth-worker(default):
smd5_verify(simon at example.net): SMD5 password too short
Oct 20 06:25:14 mail dovecot: auth-worker(default):
ssha_verify(simon at example.net): SSHA password too short
Oct 20 06:25:14 mail dovecot: auth-worker(default):
ssha256_verify(simon at example.net): SSHA256 password too short
Oct 20 06:25:14 mail dovecot: auth-worker(default): Invalid OTP data in passdb
Oct 20 06:25:14 mail dovecot: auth-worker(default): Invalid OTP data in passdb
Oct 20 06:25:14 mail dovecot: auth-worker(default):
sql(simon at example.net,127.0.0.1): CRYPT() != 'RaNDomsTRinG'
Oct 20 06:25:16 mail dovecot: auth(default): client out:
FAIL#0112#011user=simon at example.net
Oct 20 06:25:26 mail dovecot: auth(default): client in:
AUTH#0113#011PLAIN#011service=imap#011secured#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=50683#011resp=--truncated--
Oct 20 06:25:26 mail dovecot: auth-worker(default):
sql(simon at example.net,127.0.0.1): query: SELECT EmailAdd AS user,
Password AS password,  concat('/var/spool/mail/virtual/',MailDirLoc)
as userdb_home, 999 as userdb_uid, 115 as userdb_gid FROM MailAccounts
WHERE Username='simon at example.net' AND active = '1';
Oct 20 06:25:26 mail dovecot: auth-worker(default):
sql(simon at example.net,127.0.0.1): Password mismatch
Oct 20 06:25:26 mail dovecot: auth-worker(default):
md5_verify(simon at example.net): Not a valid MD5-CRYPT or PLAIN-MD5
password
Oct 20 06:25:26 mail dovecot: auth-worker(default):
smd5_verify(simon at example.net): SMD5 password too short
Oct 20 06:25:26 mail dovecot: auth-worker(default):
ssha_verify(simon at example.net): SSHA password too short
Oct 20 06:25:26 mail dovecot: auth-worker(default):
ssha256_verify(simon at example.net): SSHA256 password too short
Oct 20 06:25:26 mail dovecot: auth-worker(default): Invalid OTP data in passdb
Oct 20 06:25:26 mail dovecot: auth-worker(default): Invalid OTP data in passdb
Oct 20 06:25:26 mail dovecot: auth-worker(default):
sql(simon at example.net,127.0.0.1): CRYPT() != 'RaNDomsTRinG'
Oct 20 06:25:28 mail dovecot: auth(default): client out:
FAIL#0113#011user=simon at example.net
Oct 20 06:25:43 mail dovecot: auth(default): client in:
AUTH#0114#011PLAIN#011service=imap#011secured#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=50683#011resp=--alsoremoved--==
Oct 20 06:25:43 mail dovecot: auth-worker(default):
sql(simon at example.net,127.0.0.1): query: SELECT EmailAdd AS user,
Password AS password,  concat('/var/spool/mail/virtual/',MailDirLoc)
as userdb_home, 999 as userdb_uid, 115 as userdb_gid FROM MailAccounts
WHERE Username='simon at example.net' AND active = '1';
Oct 20 06:25:43 mail dovecot: auth-worker(default):
sql(simon at example.net,127.0.0.1): Password mismatch
Oct 20 06:25:43 mail dovecot: auth-worker(default):
md5_verify(simon at example.net): Not a valid MD5-CRYPT or PLAIN-MD5
password
Oct 20 06:25:43 mail dovecot: auth-worker(default):
smd5_verify(simon at example.net): SMD5 password too short
Oct 20 06:25:43 mail dovecot: auth-worker(default):
ssha_verify(simon at example.net): SSHA password too short
Oct 20 06:25:43 mail dovecot: auth-worker(default):
ssha256_verify(simon at example.net): SSHA256 password too short
Oct 20 06:25:43 mail dovecot: auth-worker(default): Invalid OTP data in passdb
Oct 20 06:25:43 mail dovecot: auth-worker(default): Invalid OTP data in passdb
Oct 20 06:25:43 mail dovecot: auth-worker(default):
sql(simon at example.net,127.0.0.1): CRYPT() != 'RaNDomsTRinG'
Oct 20 06:25:45 mail dovecot: auth(default): client out:
FAIL#0114#011user=simon at example.net
Oct 20 06:26:05 mail dovecot: imap-login: Disconnected (auth failed, 4
attempts): user=<simon at example.net>, method=PLAIN, rip=127.0.0.1,
lip=127.0.0.1, secured
Oct 20 06:26:15 mail dovecot: IMAP(simon at example.net): Disconnected:
Logged out bytes=8/334
Oct 20 06:26:15 mail dovecot: IMAP(simon at example.net): Disconnected:
Logged out bytes=21/393
Oct 20 06:26:16 mail dovecot: auth(default): client in:
AUTH#0111#011PLAIN#011service=imap#011secured#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=50696#011resp=--removed--==
Oct 20 06:26:16 mail dovecot: auth-worker(default):
sql(simon at example.net,127.0.0.1): query: SELECT EmailAdd AS user,
Password AS password,  concat('/var/spool/mail/virtual/',MailDirLoc)
as userdb_home, 999 as userdb_uid, 115 as userdb_gid FROM MailAccounts
WHERE Username='simon at example.net' AND active = '1';
Oct 20 06:26:16 mail dovecot: auth(default): client out:
OK#0111#011user=simon at example.net
Oct 20 06:26:16 mail dovecot: auth(default): master in:
REQUEST#0111712#01119179#0111
Oct 20 06:26:16 mail dovecot: auth(default):
prefetch(simon at example.net,127.0.0.1): success
Oct 20 06:26:16 mail dovecot: auth(default): master out:
USER#0111712#011simon at example.net#011home=/var/spool/mail/virtual/example.net/simon/#011uid=999#011gid=115
Oct 20 06:26:16 mail dovecot: imap-login: Login:
user=<simon at example.net>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1,
secured
Oct 20 06:26:16 mail dovecot: auth(default): client in:
AUTH#0111#011PLAIN#011service=imap#011secured#011lip=127.0.0.1#011rip=127.0.0.1#011lport=143#011rport=50697#011resp=--removed--==
Oct 20 06:26:16 mail dovecot: auth-worker(default):
sql(simon at example.net,127.0.0.1): query: SELECT EmailAdd AS user,
Password AS password,  concat('/var/spool/mail/virtual/',MailDirLoc)
as userdb_home, 999 as userdb_uid, 115 as userdb_gid FROM MailAccounts
WHERE Username='simon at example.net' AND active = '1';
Oct 20 06:26:16 mail dovecot: auth(default): client out:
OK#0111#011user=simon at example.net
Oct 20 06:26:16 mail dovecot: auth(default): master in:
REQUEST#0111713#01119228#0111
Oct 20 06:26:16 mail dovecot: auth(default):
prefetch(simon at example.net,127.0.0.1): success
Oct 20 06:26:16 mail dovecot: auth(default): master out:
USER#0111713#011simon at example.net#011home=/var/spool/mail/virtual/example.net/simon/#011uid=999#011gid=115
Oct 20 06:26:16 mail dovecot: imap-login: Login:
user=<simon at example.net>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1,
secured

Note, the RaNDomsTRinG is what I believe is my encrypted password.
the other strings (removed, alsoremoved and truncated) were all
variations on a string (which looks like an MD5 hash string to me).

I'm still sure this is the webmail trying to log in though..

>From the Horde log:

mail:~# grep "2011-10-20T06:" /var/log/horde/horde4.log
2011-10-20T06:25:16+00:00 ERR: HORDE4 [imp] IMAP server denied
authentication. [pid 19222 on line 340 of
"/usr/share/horde4/imp/lib/Imap.php"]
2011-10-20T06:25:16+00:00 INFO: HORDE4 [imp] FAILED LOGIN for
simon at lydiard.net (Horde user simon at lydiard.net) [] to {localhost:143
[imap]} [pid 19222 on line 176 of
"/usr/share/horde4/imp/lib/Auth.php"]

But that only shows one attempt.  Dovecot is complaining about 4.

I'm not overly concerned, but I'm concerned that this will impact as
we scale up on users.


Simon


More information about the dovecot mailing list