BUG: Authentication client sent unknown handshake command
Hi,
Some time ago my dovecot started to become BUGgy: Evertime I restart the system, dovecot is started but I cannot login. I see the following information in the logs:
Jul 4 04:04:36 mail dovecot: auth: passwd-file(user,127.11.91.218,<nfkQjFT9vwCADFra>): no passwd file: /etc/dovecot/imap.passwd Jul 4 04:04:36 mail dovecot: auth: Error: BUG: Authentication client sent unknown handshake command: REQUEST?1183186945?20438?1?a8c7241e7b0778f9f0125da760cd16fa Jul 4 04:04:36 mail dovecot: imap: Error: Authentication server didn't send valid SPID as expected: MECH#011PLAIN#011plaintext Jul 4 04:04:36 mail dovecot: imap: Error: Disconnected from auth server, aborting (client-pid=20438 client-id=1) Jul 4 04:04:36 mail dovecot: imap-login: Internal login failure (pid=20438 id=1) (internal failure, 1 succesful auths): user=<user>, method=PLAIN, rip=127.11.91.218, lip=73.82.101.172, mpid=20439, TLS, session=<nfkQjFT9vwCADFra>
It does not help to restart the client. But when I then restart the server service dovecot restart it works again.
But this is very dangerous because the server might reboot and I might not immideately have the chance to restart dovecot manually.
What's going on here?
mail:/# uname -a Linux mail 2.6.32-openvz-042stab090.2-amd64 #1 SMP Sat Jun 21 00:22:42 MSK 2014 i686 GNU/Linux mail:/# dovecot --version 2.1.7
Thanks, Luke
May I gently "push" this? The string "BUG: Authentication client sent unknown handshake command" comes from dovecot (presumably it's in the source code) so I think it shouldn't be too mysterious what's happening here.
Thank you, Luke
On 2014-07-03 19:10, Lukas Haase wrote:
Hi,
Some time ago my dovecot started to become BUGgy: Evertime I restart the system, dovecot is started but I cannot login. I see the following information in the logs:
Jul 4 04:04:36 mail dovecot: auth: passwd-file(user,127.11.91.218,<nfkQjFT9vwCADFra>): no passwd file: /etc/dovecot/imap.passwd Jul 4 04:04:36 mail dovecot: auth: Error: BUG: Authentication client sent unknown handshake command: REQUEST?1183186945?20438?1?a8c7241e7b0778f9f0125da760cd16fa Jul 4 04:04:36 mail dovecot: imap: Error: Authentication server didn't send valid SPID as expected: MECH#011PLAIN#011plaintext Jul 4 04:04:36 mail dovecot: imap: Error: Disconnected from auth server, aborting (client-pid=20438 client-id=1) Jul 4 04:04:36 mail dovecot: imap-login: Internal login failure (pid=20438 id=1) (internal failure, 1 succesful auths): user=<user>, method=PLAIN, rip=127.11.91.218, lip=73.82.101.172, mpid=20439, TLS, session=<nfkQjFT9vwCADFra>
It does not help to restart the client. But when I then restart the server service dovecot restart it works again.
But this is very dangerous because the server might reboot and I might not immideately have the chance to restart dovecot manually.
What's going on here?
mail:/# uname -a Linux mail 2.6.32-openvz-042stab090.2-amd64 #1 SMP Sat Jun 21 00:22:42 MSK 2014 i686 GNU/Linux mail:/# dovecot --version 2.1.7
Thanks, Luke
You have misconfigured Dovecot's auth sockets. Providing doveconf -n output would help figuring out the problem. Or just delete all the auth-related socket settings from config files and it should work.
On 9.7.2014, at 0.03, Lukas Haase <lukashaase@gmx.at> wrote:
May I gently "push" this? The string "BUG: Authentication client sent unknown handshake command" comes from dovecot (presumably it's in the source code) so I think it shouldn't be too mysterious what's happening here.
Thank you, Luke
On 2014-07-03 19:10, Lukas Haase wrote:
Hi,
Some time ago my dovecot started to become BUGgy: Evertime I restart the system, dovecot is started but I cannot login. I see the following information in the logs:
Jul 4 04:04:36 mail dovecot: auth: passwd-file(user,127.11.91.218,<nfkQjFT9vwCADFra>): no passwd file: /etc/dovecot/imap.passwd Jul 4 04:04:36 mail dovecot: auth: Error: BUG: Authentication client sent unknown handshake command: REQUEST?1183186945?20438?1?a8c7241e7b0778f9f0125da760cd16fa Jul 4 04:04:36 mail dovecot: imap: Error: Authentication server didn't send valid SPID as expected: MECH#011PLAIN#011plaintext Jul 4 04:04:36 mail dovecot: imap: Error: Disconnected from auth server, aborting (client-pid=20438 client-id=1) Jul 4 04:04:36 mail dovecot: imap-login: Internal login failure (pid=20438 id=1) (internal failure, 1 succesful auths): user=<user>, method=PLAIN, rip=127.11.91.218, lip=73.82.101.172, mpid=20439, TLS, session=<nfkQjFT9vwCADFra>
It does not help to restart the client. But when I then restart the server service dovecot restart it works again.
But this is very dangerous because the server might reboot and I might not immideately have the chance to restart dovecot manually.
What's going on here?
mail:/# uname -a Linux mail 2.6.32-openvz-042stab090.2-amd64 #1 SMP Sat Jun 21 00:22:42 MSK 2014 i686 GNU/Linux mail:/# dovecot --version 2.1.7
Thanks, Luke
Hi Timo,
Thank you very much. I really appreciate your response!
I have indeed a non-default socket config because I also let exim4 authenticate against it. So I I am not really able to remove the config.
What makes me wonder is that the problem just appeared recently. I think I have the config running for 2 years now or so.
I provide "doveconf -n" in any case, maybe you can spot an issue?
Thanks, Luke
2.1.7: /etc/dovecot/dovecot.conf
OS: Linux 2.6.32-openvz-042stab090.2-amd64 i686 Debian 7.5
auth_mechanisms = plain login auth_verbose = yes log_timestamp = "%Y-%m-%d %H:%M:%S " mail_location = maildir:~/Maildir mail_privileged_group = mail managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave imapflags namespace { hidden = yes inbox = no list = no location = maildir:~/Maildir-root prefix = separator = . subscriptions = yes type = private } namespace { inbox = yes location = maildir:~/Maildir prefix = INBOX. separator = . subscriptions = yes type = private } namespace { hidden = no inbox = no list = yes location = maildir:/var/mail/public:INDEX=~/Maildir/public prefix = Public. separator = . subscriptions = no type = public } namespace { hidden = no inbox = no list = yes location = maildir:/var/mail/shared:INDEX=~/Maildir/shared:LAYOUT=fs prefix = Shared. separator = . subscriptions = no type = public } passdb { args = /etc/dovecot/%Ls.passwd driver = passwd-file } passdb { args = /etc/dovecot/dovecot-ldap.conf driver = ldap } passdb { args = failure_show_msg=yes dovecotp driver = pam } plugin { acl = vfile sieve = ~/.dovecot.sieve sieve_dir = ~/sieve sieve_extensions = +imapflags sieve_global_path = /etc/dovecot/default.sieve } protocols = sieve imap service auth { unix_listener auth-client { mode = 0666 } user = root } service imap-login { inet_listener imap { port = 0 } } service imap { executable = /usr/local/sbin/dovecot-imap-fix } ssl_ca = </etc/ssl/sub.class1.server.ca.crt ssl_cert = </etc/ssl/mail.crt ssl_key = </etc/ssl/mail.key userdb { driver = prefetch } userdb { args = /etc/dovecot/dovecot-ldap.conf driver = ldap } protocol imap { imap_client_workarounds = tb-extra-mailbox-sep mail_max_userip_connections = 15 mail_plugins = acl } protocol pop3 { pop3_uidl_format = %08Xu%08Xv } protocol lda { hostname = mail.intra.local mail_plugins = sieve postmaster_address = postmaster@intra.local }
On 2014-07-10 8:23, Timo Sirainen wrote:
You have misconfigured Dovecot's auth sockets. Providing doveconf -n output would help figuring out the problem. Or just delete all the auth-related socket settings from config files and it should work.
On 9.7.2014, at 0.03, Lukas Haase <lukashaase@gmx.at> wrote:
May I gently "push" this? The string "BUG: Authentication client sent unknown handshake command" comes from dovecot (presumably it's in the source code) so I think it shouldn't be too mysterious what's happening here.
Thank you, Luke
On 2014-07-03 19:10, Lukas Haase wrote:
Hi,
Some time ago my dovecot started to become BUGgy: Evertime I restart the system, dovecot is started but I cannot login. I see the following information in the logs:
Jul 4 04:04:36 mail dovecot: auth: passwd-file(user,127.11.91.218,<nfkQjFT9vwCADFra>): no passwd file: /etc/dovecot/imap.passwd Jul 4 04:04:36 mail dovecot: auth: Error: BUG: Authentication client sent unknown handshake command: REQUEST?1183186945?20438?1?a8c7241e7b0778f9f0125da760cd16fa Jul 4 04:04:36 mail dovecot: imap: Error: Authentication server didn't send valid SPID as expected: MECH#011PLAIN#011plaintext Jul 4 04:04:36 mail dovecot: imap: Error: Disconnected from auth server, aborting (client-pid=20438 client-id=1) Jul 4 04:04:36 mail dovecot: imap-login: Internal login failure (pid=20438 id=1) (internal failure, 1 succesful auths): user=<user>, method=PLAIN, rip=127.11.91.218, lip=73.82.101.172, mpid=20439, TLS, session=<nfkQjFT9vwCADFra>
It does not help to restart the client. But when I then restart the server service dovecot restart it works again.
But this is very dangerous because the server might reboot and I might not immideately have the chance to restart dovecot manually.
What's going on here?
mail:/# uname -a Linux mail 2.6.32-openvz-042stab090.2-amd64 #1 SMP Sat Jun 21 00:22:42 MSK 2014 i686 GNU/Linux mail:/# dovecot --version 2.1.7
Thanks, Luke
Hi,
Just a very gentle reminder :) I don't see anything I am doing "wrong" in my config ...
Thanks Luke
On 2014-07-11 17:45, Lukas Haase wrote:
Hi Timo,
Thank you very much. I really appreciate your response!
I have indeed a non-default socket config because I also let exim4 authenticate against it. So I I am not really able to remove the config.
What makes me wonder is that the problem just appeared recently. I think I have the config running for 2 years now or so.
I provide "doveconf -n" in any case, maybe you can spot an issue?
Thanks, Luke
2.1.7: /etc/dovecot/dovecot.conf
OS: Linux 2.6.32-openvz-042stab090.2-amd64 i686 Debian 7.5
auth_mechanisms = plain login auth_verbose = yes log_timestamp = "%Y-%m-%d %H:%M:%S " mail_location = maildir:~/Maildir mail_privileged_group = mail managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave imapflags namespace { hidden = yes inbox = no list = no location = maildir:~/Maildir-root prefix = separator = . subscriptions = yes type = private } namespace { inbox = yes location = maildir:~/Maildir prefix = INBOX. separator = . subscriptions = yes type = private } namespace { hidden = no inbox = no list = yes location = maildir:/var/mail/public:INDEX=~/Maildir/public prefix = Public. separator = . subscriptions = no type = public } namespace { hidden = no inbox = no list = yes location = maildir:/var/mail/shared:INDEX=~/Maildir/shared:LAYOUT=fs prefix = Shared. separator = . subscriptions = no type = public } passdb { args = /etc/dovecot/%Ls.passwd driver = passwd-file } passdb { args = /etc/dovecot/dovecot-ldap.conf driver = ldap } passdb { args = failure_show_msg=yes dovecotp driver = pam } plugin { acl = vfile sieve = ~/.dovecot.sieve sieve_dir = ~/sieve sieve_extensions = +imapflags sieve_global_path = /etc/dovecot/default.sieve } protocols = sieve imap service auth { unix_listener auth-client { mode = 0666 } user = root } service imap-login { inet_listener imap { port = 0 } } service imap { executable = /usr/local/sbin/dovecot-imap-fix } ssl_ca = </etc/ssl/sub.class1.server.ca.crt ssl_cert = </etc/ssl/mail.crt ssl_key = </etc/ssl/mail.key userdb { driver = prefetch } userdb { args = /etc/dovecot/dovecot-ldap.conf driver = ldap } protocol imap { imap_client_workarounds = tb-extra-mailbox-sep mail_max_userip_connections = 15 mail_plugins = acl } protocol pop3 { pop3_uidl_format = %08Xu%08Xv } protocol lda { hostname = mail.intra.local mail_plugins = sieve postmaster_address = postmaster@intra.local }
On 2014-07-10 8:23, Timo Sirainen wrote:
You have misconfigured Dovecot's auth sockets. Providing doveconf -n output would help figuring out the problem. Or just delete all the auth-related socket settings from config files and it should work.
On 9.7.2014, at 0.03, Lukas Haase <lukashaase@gmx.at> wrote:
May I gently "push" this? The string "BUG: Authentication client sent unknown handshake command" comes from dovecot (presumably it's in the source code) so I think it shouldn't be too mysterious what's happening here.
Thank you, Luke
On 2014-07-03 19:10, Lukas Haase wrote:
Hi,
Some time ago my dovecot started to become BUGgy: Evertime I restart the system, dovecot is started but I cannot login. I see the following information in the logs:
Jul 4 04:04:36 mail dovecot: auth: passwd-file(user,127.11.91.218,<nfkQjFT9vwCADFra>): no passwd file: /etc/dovecot/imap.passwd Jul 4 04:04:36 mail dovecot: auth: Error: BUG: Authentication client sent unknown handshake command: REQUEST?1183186945?20438?1?a8c7241e7b0778f9f0125da760cd16fa Jul 4 04:04:36 mail dovecot: imap: Error: Authentication server didn't send valid SPID as expected: MECH#011PLAIN#011plaintext Jul 4 04:04:36 mail dovecot: imap: Error: Disconnected from auth server, aborting (client-pid=20438 client-id=1) Jul 4 04:04:36 mail dovecot: imap-login: Internal login failure (pid=20438 id=1) (internal failure, 1 succesful auths): user=<user>, method=PLAIN, rip=127.11.91.218, lip=73.82.101.172, mpid=20439, TLS, session=<nfkQjFT9vwCADFra>
It does not help to restart the client. But when I then restart the server service dovecot restart it works again.
But this is very dangerous because the server might reboot and I might not immideately have the chance to restart dovecot manually.
What's going on here?
mail:/# uname -a Linux mail 2.6.32-openvz-042stab090.2-amd64 #1 SMP Sat Jun 21 00:22:42 MSK 2014 i686 GNU/Linux mail:/# dovecot --version 2.1.7
Thanks, Luke
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
On Mon, 21 Jul 2014, Lukas Haase wrote:
I provide "doveconf -n" in any case, maybe you can spot an issue?
I don't think, it's your config. Setup a new server from scratch, without touching anything else on the new system [no init.d scripts either], but copy Dovecot to it. And try that system.
Some time ago my dovecot started to become BUGgy: Evertime I restart the system, dovecot is started but I cannot login. I see the following information in the logs:
Jul 4 04:04:36 mail dovecot: auth: passwd-file(user,127.11.91.218,<nfkQjFT9vwCADFra>): no passwd file: /etc/dovecot/imap.passwd Jul 4 04:04:36 mail dovecot: auth: Error: BUG: Authentication client sent unknown handshake command: REQUEST?1183186945?20438?1?a8c7241e7b0778f9f0125da760cd16fa Jul 4 04:04:36 mail dovecot: imap: Error: Authentication server didn't send valid SPID as expected: MECH#011PLAIN#011plaintext Jul 4 04:04:36 mail dovecot: imap: Error: Disconnected from auth server, aborting (client-pid=20438 client-id=1) Jul 4 04:04:36 mail dovecot: imap-login: Internal login failure (pid=20438 id=1) (internal failure, 1 succesful auths): user=<user>, method=PLAIN, rip=127.11.91.218, lip=73.82.101.172, mpid=20439, TLS, session=<nfkQjFT9vwCADFra>
It does not help to restart the client. But when I then restart the server service dovecot restart it works again.
You say, _each_ time you restart the system, this happens, but _never_ if you start Dovecot manually?
I would first look into:
- Dovecot v2.1 is pretty old. ;-)
a) Do you have more than one Dovecot version installed.
b) When and how often which Dovecot installation is started.
- -> e.g. is Dovecot started two times? I had some problem, when I started Postgres two times in init.d, it worked most of the time, but sometimes not.
c) Is Dovecot started too early?
- -> Maybe one dependency (LDAP, PAM, ...) blocks Dovecot, when someone is logging in too early and Dovecot gets desync'ed.
d) Your init.d script throws an error, which you don't see on startup and which does not happen, if you call the script manually.
- -> yes that can happen.
Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.11 (GNU/Linux)
iQEVAwUBU84MYHz1H7kL/d9rAQJEswf/a9OHp7JB9Pghj4Zr+Bws1Hxy1Q/+TaXF RCL5ttvKLzcTQ5WCgso35AFtu7knERdcSn+BOaknVDHT2IFwZqdmGi0EpxG5F40n MIIv97SWCu8jj8/wNxHlVhPbEnFvJTK4f4+mFivhSSYZ9ZVJMy/4rDh9ZunsJ7UG Ri3SSvWAOOAlZLgYafmUX9UMhAfQJihqCRkMGLAc2eAvOuE7iludSJpIT8QWW/nI ea9+K9NJ+iK6cxHKN23LZ/7bIDhSu6JbG5xjgp0+YdYECsGSGHgDz2noQkgR66Bo 4z+qn/DdITYdx7+mc6kLbnA3dcTEM1Le41eu72lMwo9wioq9I5vu0g== =WyKT -----END PGP SIGNATURE-----
participants (3)
-
Lukas Haase
-
Steffen Kaiser
-
Timo Sirainen