On 18 October 2011 10:37, Timo Sirainen tss@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@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@example.net' AND active = '1'; Oct 20 06:25:14 mail dovecot: auth-worker(default): sql(simon@example.net,127.0.0.1): Password mismatch Oct 20 06:25:14 mail dovecot: auth-worker(default): md5_verify(simon@example.net): Not a valid MD5-CRYPT or PLAIN-MD5 password Oct 20 06:25:14 mail dovecot: auth-worker(default): smd5_verify(simon@example.net): SMD5 password too short Oct 20 06:25:14 mail dovecot: auth-worker(default): ssha_verify(simon@example.net): SSHA password too short Oct 20 06:25:14 mail dovecot: auth-worker(default): ssha256_verify(simon@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@example.net,127.0.0.1): CRYPT() != 'RaNDomsTRinG' Oct 20 06:25:16 mail dovecot: auth(default): client out: FAIL#0112#011user=simon@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@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@example.net' AND active = '1'; Oct 20 06:25:26 mail dovecot: auth-worker(default): sql(simon@example.net,127.0.0.1): Password mismatch Oct 20 06:25:26 mail dovecot: auth-worker(default): md5_verify(simon@example.net): Not a valid MD5-CRYPT or PLAIN-MD5 password Oct 20 06:25:26 mail dovecot: auth-worker(default): smd5_verify(simon@example.net): SMD5 password too short Oct 20 06:25:26 mail dovecot: auth-worker(default): ssha_verify(simon@example.net): SSHA password too short Oct 20 06:25:26 mail dovecot: auth-worker(default): ssha256_verify(simon@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@example.net,127.0.0.1): CRYPT() != 'RaNDomsTRinG' Oct 20 06:25:28 mail dovecot: auth(default): client out: FAIL#0113#011user=simon@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@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@example.net' AND active = '1'; Oct 20 06:25:43 mail dovecot: auth-worker(default): sql(simon@example.net,127.0.0.1): Password mismatch Oct 20 06:25:43 mail dovecot: auth-worker(default): md5_verify(simon@example.net): Not a valid MD5-CRYPT or PLAIN-MD5 password Oct 20 06:25:43 mail dovecot: auth-worker(default): smd5_verify(simon@example.net): SMD5 password too short Oct 20 06:25:43 mail dovecot: auth-worker(default): ssha_verify(simon@example.net): SSHA password too short Oct 20 06:25:43 mail dovecot: auth-worker(default): ssha256_verify(simon@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@example.net,127.0.0.1): CRYPT() != 'RaNDomsTRinG' Oct 20 06:25:45 mail dovecot: auth(default): client out: FAIL#0114#011user=simon@example.net Oct 20 06:26:05 mail dovecot: imap-login: Disconnected (auth failed, 4 attempts): user=simon@example.net, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured Oct 20 06:26:15 mail dovecot: IMAP(simon@example.net): Disconnected: Logged out bytes=8/334 Oct 20 06:26:15 mail dovecot: IMAP(simon@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@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@example.net' AND active = '1'; Oct 20 06:26:16 mail dovecot: auth(default): client out: OK#0111#011user=simon@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@example.net,127.0.0.1): success Oct 20 06:26:16 mail dovecot: auth(default): master out: USER#0111712#011simon@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@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@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@example.net' AND active = '1'; Oct 20 06:26:16 mail dovecot: auth(default): client out: OK#0111#011user=simon@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@example.net,127.0.0.1): success Oct 20 06:26:16 mail dovecot: auth(default): master out: USER#0111713#011simon@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@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@lydiard.net (Horde user simon@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