[Dovecot] Auth Worker failures

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