[Dovecot] Dovecot 1.2.13 intermittent authentication failures
Hey folks,
I recently upgraded my mail server from an older OpenBSD -CURRENT snapshot to the latest (Aug 1). As part of this upgrade, I updated all of my packages to their latest versions.
Since this upgrade, dovecot has begun failing to authenticate intermittently. I use it primarily for web mail (Squirrelmail 1.4.20) and leave myself logged in during the day. This problem manifests itself by kicking me back to the "Username or password incorrect" screen occasionally (several times an hour) when the page refreshes.
I am not using sieve, and while I have the PostgreSQL version of the OpenBSD package installed, I do not currently use it for authentication. I am authenticating against the OpenBSD system.
The only error I get in the mail log is:
Aug 3 11:00:09 fusion dovecot: imap-login: Aborted login (auth failed, 1 attempts): user=<benny>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured
There are no errors in the Apache error log... Squirrelmail's version wasn't upgraded, so I don't think this is a Squirrelmail problem as far as I can tell.
My config is pretty simple:
# 1.2.13: /etc/dovecot.conf Warning: fd limit 128 is lower than what Dovecot can use under full load (more than 640). Either grow the limit or change login_max_processes_count and max_mail_processes settings # OS: OpenBSD 4.8 i386 base_dir: /var/dovecot/ listen: *, [::1] ssl_cert_file: /etc/ssl/webmail.crt ssl_key_file: /etc/ssl/private/webmail.key login_dir: /var/dovecot/login login_executable: /usr/local/libexec/dovecot/imap-login login_user: _dovecot mail_location: maildir:~/Maildir mbox_write_locks: fcntl imap_client_workarounds: delay-newmail netscape-eoh tb-extra-mailbox-sep namespace: type: private prefix: INBOX. inbox: yes list: yes subscriptions: yes lda: postmaster_address: postmaster@example.com auth default: mechanisms: plain login passdb: driver: bsdauth userdb: driver: passwd socket: type: listen client: path: /var/spool/postfix/private/auth mode: 432 user: _postfix group: _postfix
Everything seems to be working just fine (ie, I don't get any other IMAP errors or see any problems), it's just that it will spontaneously fail to authenticate. When this happens, it may take more than one try to get logged back in.
I checked with the OpenBSD port's maintainer, and he hadn't heard of any similar issues (and he uses it himself). Can anyone please help?
Thank you so much!
Benny
-- "Something's going on in this house - last night, I saw a face!" "Did it have a nose?" "Yes!" "That sounds like a face all right." -- Scary Movie 4
On Tue, 2010-08-03 at 11:10 -0500, C. Bensend wrote:
The only error I get in the mail log is:
Aug 3 11:00:09 fusion dovecot: imap-login: Aborted login (auth failed, 1 attempts): user=<benny>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured
Get it to log more with auth_verbose=yes, and perhaps even auth_debug_passwords=yes.
The only error I get in the mail log is:
Aug 3 11:00:09 fusion dovecot: imap-login: Aborted login (auth failed, 1 attempts): user=<benny>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured
Get it to log more with auth_verbose=yes, and perhaps even auth_debug_passwords=yes.
And sure enough, there it is:
Aug 3 12:15:23 fusion dovecot: auth(default): client in: AUTH 1
PLAIN service=imap secured lip=127.0.0.1 rip=127.0.0.1 lport=143
rport=19068 resp=<hidden>
Aug 3 12:15:23 fusion dovecot: auth(default): bsdauth(benny,127.0.0.1):
lookup
Aug 3 12:15:23 fusion dovecot: auth(default): bsdauth(benny,127.0.0.1):
password mismatch
The "password mismatch" would suggest that Squirrelmail may be having a problem, which I have asked about on their list. However, just to cover my bases, is there something else that could have happened that would be causing dovecot to get *random* password mismatch errors?
Thank you so much!
Benny
-- "Something's going on in this house - last night, I saw a face!" "Did it have a nose?" "Yes!" "That sounds like a face all right." -- Scary Movie 4
On Tue, 2010-08-03 at 12:43 -0500, C. Bensend wrote:
And sure enough, there it is:
Aug 3 12:15:23 fusion dovecot: auth(default): client in: AUTH 1
PLAIN service=imap secured lip=127.0.0.1 rip=127.0.0.1 lport=143 rport=19068 resp=<hidden> Aug 3 12:15:23 fusion dovecot: auth(default): bsdauth(benny,127.0.0.1): lookup Aug 3 12:15:23 fusion dovecot: auth(default): bsdauth(benny,127.0.0.1): password mismatch
Did you check with auth_debug_passwords=yes what the password is? v1.2 doesn't seem to log it clearly, but by base64 decoding resp= value you could see it.
The "password mismatch" would suggest that Squirrelmail may be having a problem, which I have asked about on their list. However, just to cover my bases, is there something else that could have happened that would be causing dovecot to get *random* password mismatch errors?
I vaguely remember seeing something like this before too .. but I don't remember what the end result was. Maybe you could find something from Dovecot mailing list archives.
And sure enough, there it is:
Aug 3 12:15:23 fusion dovecot: auth(default): client in: AUTH 1 PLAIN service=imap secured lip=127.0.0.1 rip=127.0.0.1 lport=143 rport=19068 resp=<hidden> Aug 3 12:15:23 fusion dovecot: auth(default): bsdauth(benny,127.0.0.1): lookup Aug 3 12:15:23 fusion dovecot: auth(default): bsdauth(benny,127.0.0.1): password mismatch
Did you check with auth_debug_passwords=yes what the password is? v1.2 doesn't seem to log it clearly, but by base64 decoding resp= value you could see it.
I did, yes. However, it didn't output plain text, so I didn't go hunting as to what format I was seeing. The "password mismatch" seemed to point to Squirrelmail, so I moved on towards that angle. I'll decode it and see what's actually happening to the password, that might help track down the issue.
The "password mismatch" would suggest that Squirrelmail may be having a problem, which I have asked about on their list. However, just to cover my bases, is there something else that could have happened that would be causing dovecot to get *random* password mismatch errors?
I vaguely remember seeing something like this before too .. but I don't remember what the end result was. Maybe you could find something from Dovecot mailing list archives.
I did do some searching in the archives before asking, but I'll certainly go back and do some more exhaustive searching.
Thank you for all your help, Timo, it's greatly appreciated!
Benny
-- "Something's going on in this house - last night, I saw a face!" "Did it have a nose?" "Yes!" "That sounds like a face all right." -- Scary Movie 4
Did you check with auth_debug_passwords=yes what the password is? v1.2 doesn't seem to log it clearly, but by base64 decoding resp= value you could see it.
Hi Timo,
Well, I cranked the debug back up all the way and captured the password. After whipping up a quick perl script to decode it, it gives me my username and password, end-to-end, no delimiter. Both the username and password are correct, and are the correct case. If that is the correct format for the Base 64-encoded string, it seems to be the right content.
So. Uh. Why is dovecot giving back a "password mismatch" ? I don't believe it's the system's authentication mechanism doing anything weird, I have yet to fail a single SSH authentication (and yes, I do use both password and key-based auth).
I vaguely remember seeing something like this before too .. but I don't remember what the end result was. Maybe you could find something from Dovecot mailing list archives.
I'm calling it a night, my head is throbbing. I will hit the archives again first thing in the morning... If anyone can help, I certainly would appreciate it!
Benny
-- "Something's going on in this house - last night, I saw a face!" "Did it have a nose?" "Yes!" "That sounds like a face all right." -- Scary Movie 4
On Tue, 2010-08-03 at 21:18 -0500, C. Bensend wrote:
Well, I cranked the debug back up all the way and captured the password. After whipping up a quick perl script to decode it, it gives me my username and password, end-to-end, no delimiter. Both the username and password are correct, and are the correct case. If that is the correct format for the Base 64-encoded string, it seems to be the right content.
So it's either
NUL username NUL password
or
username NUL username NUL password
?
So. Uh. Why is dovecot giving back a "password mismatch" ? I don't believe it's the system's authentication mechanism doing anything weird, I have yet to fail a single SSH authentication (and yes, I do use both password and key-based auth).
Wonder if it has to do with a single process doing multiple lookups. That's the main difference compared to SSH and pretty much everything else.
So it's either
NUL username NUL password
or
username NUL username NUL password
It's username then password.
Wonder if it has to do with a single process doing multiple lookups. That's the main difference compared to SSH and pretty much everything else.
I upgraded the server again today to the latest and greatest snapshot of both OpenBSD and the packages, with no change in behavior.
This is crippling me... This morning, I wasn't able to authenticate at *all* to my email, via either Squirrelmail or via IMAPS (my Droid smartphone). After rebooting the system, it worked again while randomly failing.
Should I try the straight dovecot package instead of the postgresql flavor? I'm not *using* PostgreSQL to authenticate, but it could cause an issue I guess...
One more thing - I ktraced the dovecot processes, and caught the failure:
24165 dovecot-auth CALL lstat(0xcfbbff58,0xcfbbfd00) 24165 dovecot-auth NAMI "/usr/libexec/auth/login_passwd" 24165 dovecot-auth RET lstat 0 24165 dovecot-auth CALL socketpair(0x1,0x1,0,0xcfbbfeec) 24165 dovecot-auth RET socketpair 0 24165 dovecot-auth CALL fork() 24165 dovecot-auth RET fork 22689/0x58a1 24165 dovecot-auth CALL close(0xe) 24165 dovecot-auth RET close 0 24165 dovecot-auth CALL write(0xd,0x8357d0fc,0x1) 24165 dovecot-auth GIO fd 13 wrote 1 bytes "\0" 24165 dovecot-auth RET write 1 24165 dovecot-auth CALL write(0xd,0x860dc66c,0x9) 24165 dovecot-auth GIO fd 13 wrote 9 bytes "OBSCURED\0" 24165 dovecot-auth RET write 9 24165 dovecot-auth CALL read(0xd,0x8550e034,0x2000) 24165 dovecot-auth PSIG SIGCHLD caught handler=0x1c02a8f0 mask=0x0 24165 dovecot-auth RET read -1 errno 4 Interrupted system call 24165 dovecot-auth CALL write(0x8,0xcfbbfa77,0x1) 24165 dovecot-auth GIO fd 8 wrote 1 bytes "\0"
Does that help at all?
Thank you so much!
Benny
-- "Something's going on in this house - last night, I saw a face!" "Did it have a nose?" "Yes!" "That sounds like a face all right." -- Scary Movie 4
On Wed, 2010-08-04 at 11:07 -0500, C. Bensend wrote:
So it's either
NUL username NUL password
or
username NUL username NUL password
It's username then password.
What about the NUL characters in the middle? Those are important.
Should I try the straight dovecot package instead of the postgresql flavor? I'm not *using* PostgreSQL to authenticate, but it could cause an issue I guess...
I doubt that makes a difference.
One more thing - I ktraced the dovecot processes, and caught the failure:
24165 dovecot-auth RET write 9 24165 dovecot-auth CALL read(0xd,0x8550e034,0x2000) 24165 dovecot-auth PSIG SIGCHLD caught handler=0x1c02a8f0 mask=0x0 24165 dovecot-auth RET read -1 errno 4 Interrupted system call 24165 dovecot-auth CALL write(0x8,0xcfbbfa77,0x1) 24165 dovecot-auth GIO fd 8 wrote 1 bytes "\0"
Does that help at all?
That code is OpenBSD's auth_userokay() call in libc. I don't know if its behavior is correct or not.
username NUL username NUL password
It's username then password.
What about the NUL characters in the middle? Those are important.
Ummmm... I wrote a quick perl script to decrypt the string and print it out... I'll have to look at how to tell if there are NUL chars in there.
24165 dovecot-auth RET write 9 24165 dovecot-auth CALL read(0xd,0x8550e034,0x2000) 24165 dovecot-auth PSIG SIGCHLD caught handler=0x1c02a8f0 mask=0x0 24165 dovecot-auth RET read -1 errno 4 Interrupted system call 24165 dovecot-auth CALL write(0x8,0xcfbbfa77,0x1) 24165 dovecot-auth GIO fd 8 wrote 1 bytes "\0"
That code is OpenBSD's auth_userokay() call in libc. I don't know if its behavior is correct or not.
Ugh, crap, I meant to include more of the output, I'm sorry. Immediately following the above:
24165 dovecot-auth RET write 1
24165 dovecot-auth CALL sigreturn(0xcfbbfa9c)
24165 dovecot-auth RET sigreturn JUSTRETURN
24165 dovecot-auth CALL close(0xb)
24165 dovecot-auth RET close 0
24165 dovecot-auth CALL wait4(0x5d89,0xcfbbfef4,0,0)
24165 dovecot-auth RET wait4 23945/0x5d89
24165 dovecot-auth CALL write(0x2,0x80d53468,0x2e)
24165 dovecot-auth GIO fd 2 wrote 46 bytes
"\^AIbsdauth(benny,127.0.0.1): password mismatch
"
24165 dovecot-auth RET write 46/0x2e
24165 dovecot-auth CALL gettimeofday(0x860dc648,0)
24165 dovecot-auth RET gettimeofday 0
24165 dovecot-auth CALL gettimeofday(0xcfbc0674,0)
24165 dovecot-auth RET gettimeofday 0
24165 dovecot-auth CALL kevent(0x6,0,0,0x8bc58600,0x8,0xcfbc066c)
24165 dovecot-auth RET kevent 1
24165 dovecot-auth CALL gettimeofday(0x3c016f5c,0x3c016f64)
24165 dovecot-auth RET gettimeofday 0
24165 dovecot-auth CALL sigprocmask(0x1,0xffffffff)
24165 dovecot-auth RET sigprocmask 0
24165 dovecot-auth CALL read(0x7,0xcfbc05e8,0x40)
24165 dovecot-auth GIO fd 7 read 1 bytes
"\0"
24165 dovecot-auth RET read 1
24165 dovecot-auth CALL sigprocmask(0x3,0)
24165 dovecot-auth RET sigprocmask -65793/0xfffefeff
24165 dovecot-auth CALL wait4(0xffffffff,0xcfbbf5b8,0x1,0)
24165 dovecot-auth RET wait4 -1 errno 10 No child processes
24165 dovecot-auth CALL gettimeofday(0xcfbc0674,0)
24165 dovecot-auth RET gettimeofday 0
24165 dovecot-auth CALL kevent(0x6,0,0,0x8bc58600,0x8,0xcfbc066c)
23502 dovecot RET kevent 1
23502 dovecot CALL gettimeofday(0x3c00bd04,0x3c00bd0c)
23502 dovecot RET gettimeofday 0
23502 dovecot CALL read(0x11,0x86d50901,0x2ff)
23502 dovecot GIO fd 17 read 46 bytes
"\^AIbsdauth(benny,127.0.0.1): password mismatch
"
23502 dovecot RET read 46/0x2e
23502 dovecot CALL gettimeofday(0xcfbbfdc8,0)
23502 dovecot RET gettimeofday 0
23502 dovecot CALL sendto(0x5,0xcfbbfe78,0x57,0,0,0)
23502 dovecot GIO fd 5 wrote 87 bytes
"<22>Aug 4 07:18:01 dovecot: auth(default):
bsdauth(benny,127.0.0.1):
password mismatch"
23502 dovecot RET sendto 87/0x57
23502 dovecot CALL gettimeofday(0xcfbc0c34,0)
23502 dovecot RET gettimeofday 0
23502 dovecot CALL kevent(0xc,0,0,0x86cbd600,0xd,0xcfbc0c2c)
24165 dovecot-auth RET kevent 0
24165 dovecot-auth CALL gettimeofday(0x3c016f5c,0x3c016f64)
24165 dovecot-auth RET gettimeofday 0
24165 dovecot-auth CALL gettimeofday(0xcfbc0674,0)
24165 dovecot-auth RET gettimeofday 0
24165 dovecot-auth CALL kevent(0x6,0,0,0x8bc58600,0x8,0xcfbc066c)
23502 dovecot RET kevent 0
23502 dovecot CALL gettimeofday(0x3c00bd04,0x3c00bd0c)
23502 dovecot RET gettimeofday 0
23502 dovecot CALL socketpair(0x1,0x1,0,0xcfbc0b8c)
23502 dovecot RET socketpair 0
23502 dovecot CALL fcntl(0x12,0x1,0)
23502 dovecot RET fcntl 0
23502 dovecot CALL fcntl(0x12,0x2,0x1)
23502 dovecot RET fcntl 0
23502 dovecot CALL fcntl(0x17,0x1,0)
I have more if it would be helpful... I'm not skilled enough in debugging compiled programs to effectively interpret what I see above.
Gut instinct - do you think this might be a problem with OpenBSD's lib, or Dovecot, or .. ? I think my configuration is OK, I have tried with both the previous version (that was running under the older Dovecot) as well as migrating my settings to the new Dovecot's version of the configuration.
I *really* appreciate all your help.
Benny
-- "Something's going on in this house - last night, I saw a face!" "Did it have a nose?" "Yes!" "That sounds like a face all right." -- Scary Movie 4
On Wed, 2010-08-04 at 11:49 -0500, C. Bensend wrote:
username NUL username NUL password
It's username then password.
What about the NUL characters in the middle? Those are important.
Ummmm... I wrote a quick perl script to decrypt the string and print it out... I'll have to look at how to tell if there are NUL chars in there.
less would show them as ^@ in reverse, or hexdump would work too.
That code is OpenBSD's auth_userokay() call in libc. I don't know if its behavior is correct or not.
Ugh, crap, I meant to include more of the output, I'm sorry. Immediately following the above: ..
Still the important code that appears to fail is in OpenBSD. I don't know what it does or how it does it..
24165 dovecot-auth RET write 1 24165 dovecot-auth CALL sigreturn(0xcfbbfa9c) 24165 dovecot-auth RET sigreturn JUSTRETURN 24165 dovecot-auth CALL close(0xb) 24165 dovecot-auth RET close 0 24165 dovecot-auth CALL wait4(0x5d89,0xcfbbfef4,0,0) 24165 dovecot-auth RET wait4 23945/0x5d89
dovecot-auth code doesn't call wait*(), so up to here it's executing in libc.
24165 dovecot-auth CALL write(0x2,0x80d53468,0x2e) 24165 dovecot-auth GIO fd 2 wrote 46 bytes "\^AIbsdauth(benny,127.0.0.1): password mismatch "
Then the first thing dovecot-auth itself does it just log this error message.
24165 dovecot-auth RET write 46/0x2e 24165 dovecot-auth CALL gettimeofday(0x860dc648,0) 24165 dovecot-auth RET gettimeofday 0 24165 dovecot-auth CALL gettimeofday(0xcfbc0674,0) 24165 dovecot-auth RET gettimeofday 0 24165 dovecot-auth CALL kevent(0x6,0,0,0x8bc58600,0x8,0xcfbc066c) 24165 dovecot-auth RET kevent 1 24165 dovecot-auth CALL gettimeofday(0x3c016f5c,0x3c016f64) 24165 dovecot-auth RET gettimeofday 0 24165 dovecot-auth CALL sigprocmask(0x1,0xffffffff) 24165 dovecot-auth RET sigprocmask 0 24165 dovecot-auth CALL read(0x7,0xcfbc05e8,0x40) 24165 dovecot-auth GIO fd 7 read 1 bytes "\0" 24165 dovecot-auth RET read 1 24165 dovecot-auth CALL sigprocmask(0x3,0) 24165 dovecot-auth RET sigprocmask -65793/0xfffefeff 24165 dovecot-auth CALL wait4(0xffffffff,0xcfbbf5b8,0x1,0) 24165 dovecot-auth RET wait4 -1 errno 10 No child processes 24165 dovecot-auth CALL gettimeofday(0xcfbc0674,0) 24165 dovecot-auth RET gettimeofday 0 24165 dovecot-auth CALL kevent(0x6,0,0,0x8bc58600,0x8,0xcfbc066c) 23502 dovecot RET kevent 1 23502 dovecot CALL gettimeofday(0x3c00bd04,0x3c00bd0c) 23502 dovecot RET gettimeofday 0 23502 dovecot CALL read(0x11,0x86d50901,0x2ff) 23502 dovecot GIO fd 17 read 46 bytes "\^AIbsdauth(benny,127.0.0.1): password mismatch "
Above it's no longer fork()ing, but it still tries to wait for some child process. That's a possible bug I guess.
Gut instinct - do you think this might be a problem with OpenBSD's lib, or Dovecot, or .. ? I think my configuration is OK, I have tried with both the previous version (that was running under the older Dovecot) as well as migrating my settings to the new Dovecot's version of the configuration.
My guess is that OpenBSD's auth code somehow doesn't like running inside dovecot-auth. But the specifics can be tricky to figure out.
participants (2)
-
C. Bensend
-
Timo Sirainen