[Dovecot] BUG: Authentication client sent unknown handshake command
Hi
After upgrading the kernel, everything is fine, except dovecot authentication. I get this trange thing (data after REQUEST? changed just in case it contains anything sensitive):
Nov 29 16:56:01 volanges dovecot: auth: Error: BUG: Authentication client sent unknown handshake command: REQUEST?6970356762?616?6?235264ef69dbd1665538af54d12fdaea?session_pid=453?req... Nov 29 16:56:01 volanges dovecot: imap: Error: Authentication server didn't send valid SPID as expected: MECH PLAIN plaintext Nov 29 16:56:01 volanges dovecot: imap: Error: Disconnected from auth server, aborting (client-pid=161 client-id=1) Nov 29 16:56:01 volanges dovecot: imap-login: Internal login failure (pid=161 id=1) (internal failure, 1 successful auths): user=<jdoe>, method=PLAIN, rip=192.0.2.251, lip=192.0.2.10, mpid=453, TLS, TLSv1 with cipher AES128-SHA (128/128 bits)
Reverting to the previous kernel fixed the problem, but I have not been able to spot what the problem was. Any idea?
-- Emmanuel Dreyfus manu@netbsd.org
Emmanuel Dreyfus <manu@netbsd.org> wrote:
Nov 29 16:56:01 volanges dovecot: auth: Error: BUG: Authentication client sent unknown handshake command: REQUEST?6970356762?616?6?235264ef69dbd1665538af54...
I have real trouble to debug that one. I had a look at wiki2.dovecot.org/Design/AuthProtocol, and if I understand correctly, the auth server receives data from the master where it awaits data from the auth client.
That suggests some confusion with file descriptors somewhere. Where are the pipe() invocation to create these two pipe sets?
-- Emmanuel Dreyfus http://hcpnet.free.fr/pubz manu@netbsd.org
On 29.11.2013, at 18.54, Emmanuel Dreyfus <manu@netbsd.org> wrote:
After upgrading the kernel, everything is fine, except dovecot authentication. I get this trange thing (data after REQUEST? changed just in case it contains anything sensitive):
Nov 29 16:56:01 volanges dovecot: auth: Error: BUG: Authentication client sent unknown handshake command: REQUEST?6970356762?616?6?235264ef69dbd1665538af54d12fdaea?session_pid=453?req...
I think net_getunixname() no longer works correctly. src/auth/main.c uses it to figure out what each socket is.
Timo Sirainen <tss@iki.fi> wrote:
I think net_getunixname() no longer works correctly. src/auth/main.c uses it to figure out what each socket is.
Indeed, when the auth process calls net_getunixname(), getsockname() fills the name buffer with garbage. That happens with fd 7 for instance, and inspecting the process with fstat(1) I see no fd 7. I am not yet sure if it is closed before or after getsockname()
# ps -axp 6025 6025 ? I 0:00.02 dovecot/auth -w # fstat -p 6025 USER CMD PID FD MOUNT INUM MODE SZ|DV R/W root auth 6025 wd / 636320 drwxr-xr-x 1024 r root auth 6025 0 / 68173 crw-rw-rw- null w root auth 6025 1 / 68173 crw-rw-rw- null w root auth 6025 2* pipe 0xc732d254 -> 0xc710c010 w root auth 6025 3* pipe 0xc725e310 -> 0xc70b330c w root auth 6025 4 / 545650 -rw-r--r-- 121 r root auth 6025 5* pipe 0xc725ecd0 -> 0xc710c0d0 wn root auth 6025 6* pipe 0xc7be385c -> 0xc79b885c w root auth 6025 5* misc 0xc67dff18 root auth 6025 9* pipe 0xc7057f04 <- 0xc618f000 rn root auth 6025 10* pipe 0xc618f000 -> 0xc7057f04 wn root auth 6025 4* kqueue pending 0 root auth 6025 4* kqueue pending 0 root auth 6025 13 / 545650 -rw-r--r-- 121 r root auth 6025 14* internet stream tcp 192.0.2.16:636 <-> 192.0.2.26:62473 root auth 6025 15* unix stream <-> /var/run/dovecot/auth-worker root auth 6025 130 / 545650 -rw-r--r-- 121 r
The other auth process has it as a Unix socket like we expect:
# ps -axp 17204 PID TTY STAT TIME COMMAND 17204 ? I 0:00.02 dovecot/auth # fstat -p 17204 USER CMD PID FD MOUNT INUM MODE SZ|DV R/W root auth 17204 wd / 636320 drwxr-xr-x 1024 r root auth 17204 0 / 68173 crw-rw-rw- null w root auth 17204 1 / 68173 crw-rw-rw- null w root auth 17204 2* pipe 0xc725e250 -> 0xc618ee40 w root auth 17204 3* pipe 0xc725e310 -> 0xc70b330c w root auth 17204 4 / 545650 -rw-r--r-- 121 r root auth 17204 5* pipe 0xc7058184 -> 0xc710c9d0 wn root auth 17204 6* pipe 0xc7be385c -> 0xc79b885c w root auth 17204 7* unix stream <-> /var/run/dovecot/login/login root auth 17204 8* unix stream <-> /var/run/dovecot/token-login/tokenlogin root auth 17204 9* unix stream <-> /var/run/dovecot/auth-login root auth 17204 10* unix stream <-> /var/run/dovecot/auth-client root auth 17204 11* unix stream <-> /var/run/dovecot/auth-userdb root auth 17204 12* unix stream <-> /var/run/dovecot/auth-master root auth 17204 5* misc 0xc67dff60 root auth 17204 14* unix stream <-> c71b6e14 root auth 17204 4* kqueue pending 0 root auth 17204 16* pipe 0xc70b36cc <- 0xc7058244 rn root auth 17204 17* pipe 0xc7058244 -> 0xc70b36cc wn root auth 17204 4* kqueue pending 0 root auth 17204 19 / 545650 -rw-r--r-- 121 r root auth 17204 20* internet stream tcp 192.0.2.15:636 <-> 192.0.2.26:62459 root auth 17204 22* unix stream <-> c60cb974 root auth 17204 130 / 545650 -rw-r--r-- 121 r
-- Emmanuel Dreyfus http://hcpnet.free.fr/pubz manu@netbsd.org
Emmanuel Dreyfus <manu@netbsd.org> wrote:
Indeed, when the auth process calls net_getunixname(), getsockname() fills the name buffer with garbage.
I checked with a test program: on a non open, or closed socket, getsockname() returns -1. However on a socket that was not bound, it returns 0 and fills the buffer with garbage. I suspect this is a kernel bug, but how do we reach that situation?
-- Emmanuel Dreyfus http://hcpnet.free.fr/pubz manu@netbsd.org
Emmanuel Dreyfus <manu@netbsd.org> wrote:
I checked with a test program: on a non open, or closed socket, getsockname() returns -1. However on a socket that was not bound, it returns 0 and fills the buffer with garbage.
Wrong diagnostic. I am now tracking synchronisation problems between auth and imap-login.
-- Emmanuel Dreyfus http://hcpnet.free.fr/pubz manu@netbsd.org
participants (3)
-
Emmanuel Dreyfus
-
manu＠netbsd.org
-
Timo Sirainen