[Dovecot] Dovecot 1.2.13 intermittent authentication failures

[Timo Sirainen]

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.