[exim-dev] [Bug 1512] New: dovecot authenticator waits for s…

Page principale
Supprimer ce message
Répondre à ce message
Auteur: Andreas Metzler
Date:  
À: exim-dev
Sujet: [exim-dev] [Bug 1512] New: dovecot authenticator waits for server's DONE before sending DATA
------- You are receiving this mail because: -------
You are on the CC list for the bug.

http://bugs.exim.org/show_bug.cgi?id=1512
           Summary: dovecot authenticator waits for server's DONE before
                    sending DATA
           Product: Exim
           Version: 4.83
          Platform: Other
               URL: http://bugs.debian.org/756258
        OS/Version: Linux
            Status: NEW
          Severity: bug
          Priority: medium
         Component: SMTP Authentication
        AssignedTo: pdp@???
        ReportedBy: eximusers@???
                CC: exim-dev@???



Hello,

this is <http://bugs.debian.org/756258> as submitted by Mildred Ki'Lya:

<Quote>
When exim4 is configured with dovecot authenticator, it blocks at some
point, apparently expecting some information from dovecot. Dovecot on its
side is expecting additional information from exim. None of the two
parties move forward and exim do not respond to the SMTp client. After
some unspecified time, the MUA terminates the connection, because no
response is sent from the server.

Exim is configured with:

    begin authenticators


    dovecot_plain:
      driver = dovecot
      public_name = PLAIN
      server_socket = /var/run/dovecot/auth-userdb
      server_set_id = $auth1


    dovecot_login:
      driver = dovecot
      public_name = LOGIN
      server_socket = /var/run/dovecot/auth-userdb
      server_set_id = $auth1


Dovecot configuration is left as default. It is:

    service auth {
      unix_listener auth-userdb {}
    }


Both daemons in full debug mode (-d+all for exim and auth_verbose,
auth_verbose_passwords, auth_debug, auth_debug_passwords activated in
dovecot). The last debug log from exim is:

@4000000053d5e25003272ac4 05:40:22    61 SMTP<< EHLO toto
@4000000053d5e250032853a4 05:40:22    61 toto in helo_lookup_domains? no (end
of list)
@4000000053d5e25003292694 05:40:22    61 sender_fullhost = (toto) [172.17.42.1]
@4000000053d5e250032a0d0c 05:40:22    61 sender_rcvhost = [172.17.42.1]
(helo=toto)
@4000000053d5e250032ad82c 05:40:22    61 set_process_info:    61 handling
incoming connection from (toto) [172.17.42.1]
@4000000053d5e250032baf04 05:40:22    61 host in pipelining_advertise_hosts?
yes (matched "*")
@4000000053d5e250032c6a84 05:40:22    61 host in auth_advertise_hosts? yes
(matched "*")
@4000000053d5e250032d2dd4 05:40:22    61 host in tls_advertise_hosts? yes
(matched "*")
@4000000053d5e250032df8f4 05:40:22    61 SMTP>> 250-4a5b0a328ab7 Hello toto
[172.17.42.1]
@4000000053d5e250032df8f4 05:40:22    61 250-SIZE 52428800
@4000000053d5e250032dfcdc 05:40:22    61 250-8BITMIME
@4000000053d5e250032dfcdc 05:40:22    61 250-PIPELINING
@4000000053d5e250032dfcdc 05:40:22    61 250-AUTH PLAIN LOGIN
@4000000053d5e250032dfcdc 05:40:22    61 250-STARTTLS
@4000000053d5e250032e00c4 05:40:22    61 250 HELP
@4000000053d5e26322f6eb8c 05:40:41    61 SMTP<< AUTH PLAIN
AG1AbWFpbHRlc3QubWlsZHJlZC5mcgAxMjM=
@4000000053d5e26322f7d204 05:40:41    61 dovecot authentication
@4000000053d5e26322fe8cac 05:40:41    61 received: VERSION      1       1
@4000000053d5e26322ff6b54 05:40:41    61 received: SPID 48


(no debug log from dovecot at this point)

Running strace on exim leads to the following output for the AUTH PLAIN
command:

[pid 10113] read(10, "AUTH PLAIN AG1AbWFpbHRlc3QubWlsZ"..., 8192) = 48
[pid 10113] alarm(0)                    = 288
[pid 10113] rt_sigaction(SIGALRM, {0x7fb417616690, [], SA_RESTORER,
0x7fb414d17030}, NULL, 8) = 0
[pid 10113] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) =
0
[pid 10113] write(2, "05:40:41    61 SMTP<< AUTH PLAIN"..., 70) = 70
[pid 10113] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) =
0
[pid 10113] write(2, "05:40:41    61 dovecot authentic"..., 38) = 38
[pid 10113] socket(PF_LOCAL, SOCK_STREAM, 0) = 3
[pid 10113] connect(3, {sa_family=AF_LOCAL,
sun_path="/var/run/dovecot/auth-userdb"}, 110) = 0
[pid 10113] read(3, "VERSION\t1\t1\nSPID\t48\n", 256) = 20
[pid 10113] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) =
0
[pid 10113] write(2, "05:40:41    61 received: VERSION"..., 37) = 37
[pid 10113] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) =
0
[pid 10113] write(2, "05:40:41    61 received: SPID\t48"..., 33) = 33
[pid 10113] read(3, 
(blocked)


strace for dovecot auth process shows:

epoll_wait(13, {{EPOLLIN, {u32=967924496, u64=140021196741392}}}, 12, -1) = 1
accept(10, {sa_family=AF_LOCAL, NULL}, [2]) = 19
fcntl(19, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(19, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
write(5, "0\0\0\0\5\0\0\0\345\3\0\0", 12) = 12
fstat(19, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
lseek(19, 0, SEEK_CUR)                  = -1 ESPIPE (Illegal seek)
getsockname(19, {sa_family=AF_LOCAL,
sun_path="/var/run/dovecot/auth-userY\177"}, [31]) = 0
epoll_ctl(13, EPOLL_CTL_ADD, 19, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP,
{u32=967948080, u64=140021196764976}}) = 0
write(19, "VERSION\t1\t1\nSPID\t48\n", 20) = 20
getsockopt(19, SOL_SOCKET, SO_PEERCRED, {pid=61, uid=103, gid=104}, [12]) = 0
epoll_wait(13, 
(blocked)


We deduce the following AUTH protocol log:

        exim connects to dovecot auth
        dovecot VERSION 1       1
        dovecot SPID    48


According to <http://wiki2.dovecot.org/Design/AuthProtocol>, the protocol
log should start with the client (exim here) issuing the VERSION and CPID
commands. Dovecot should then reply with VERSION, SPID, CUID, COOKIE,
MECH and DONE.

Unfortunately, according to exim code (src/auths/dovecot.c around line
220), exim waits the DONE from dovecot to send VERSION and CPID. I
believe exim is wrong here.

exim version: 4.80 (debconf not used at all) dovecot version: 2.1.7


Note: I have another server running successfully in this configuration.
The auth protocol log (found using strace again) is:

        exim connects to dovecot auth
        dovecot VERSION 1       1
        dovecot MECH    PLAIN   plaintext
        dovecot SPID    10905
        dovecot CUID    1
        dovecot COOKIE  d3861d29441f06d962490eab8549fd46
        dovecot DONE
        exim    VERSION 1       0
        exim    CPID    10619
        exim    AUTH    1       PLAIN   service=smtp    secured
rip=82.247.184.53       lip=80.67.179.36        nologin resp=<base64 encoded
string>


Dovecot is version 2.1.17, but it worked with earler versions. Exim is
version 4.80

In any case, relying to the fact that the auth server will send its
handshake first is wrong as it doesn't seem to be always the case (and
the documentation says that the client is to start the handshake).
<Unquote>

In a later message Mildred confirmed that the problem was still present in
4.83.


--
Configure bugmail: http://bugs.exim.org/userprefs.cgi?tab=email