Re: Issue with a bug with imap-login

https://wiki.dovecot.org/Debugging/Rawlog

Can you try with this?

Aki

On 31 March 2018 at 00:52 Grant Keller grant.keller@sonic.com wrote:

Hello,

Currently working on migrating our existing directors from 2.1.13 to 2.2.10. In 2.2.10 when issuing the logout command on an unauthenticated connection, the connection is closed before the server sends the BYE line to the client. The new version works as expected with a non-secure connection. I will include the strace output from the imap-login process that shows the connection closing before the message can be sent.

# 2.2.10: /etc/dovecot/dovecot.conf # OS: Linux 3.10.0-693.21.1.el7.x86_64 x86_64 CentOS Linux release 7.4.1708 (Core) auth_master_user_separator = * auth_username_format = %Ln auth_verbose = yes default_client_limit = 20000 director_mail_servers = removed director_servers = c.director.imapd.sonic.net d.director.imapd.sonic.net disable_plaintext_auth = no doveadm_port = 1842 login_trusted_networks = removed mbox_write_locks = fcntl passdb { args = /etc/dovecot/master-users driver = passwd-file master = yes pass = yes } passdb { args = proxy=y nopassword=y driver = static } service anvil { client_limit = 40103 } service auth { client_limit = 41704 } service director { fifo_listener login/proxy-notify { mode = 0666 } inet_listener { port = 9321 } unix_listener login/director { mode = 0666 } } service imap-login { executable = imap-login director process_limit = 20000 process_min_avail = 1 } service imap { process_limit = 20480 } service pop3-login { executable = pop3-login director process_limit = 20000 process_min_avail = 32 } ssl_ca =

STRACE:

263563 epoll_wait(14, [{EPOLLIN, {u32=2772983280, u64=94500643429872}}], 8, -1) = 1 263563 accept(9TCP:[0.0.0.0:993], {sa_family=AF_INET, sin_port=htons(39552), sin_addr=inet_addr("64.142.18.25")}, [16]) = 18TCP:[64.142.111.79:993-64.142.18.25:39552]> 263563 fcntl(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, F_GETFL) = 0x2 (flags O_RDWR) 263563 fcntl(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, F_SETFL, O_RDWR|O_NONBLOCK) = 0 263563 write(5pipe:[1445541], "\213\5\4\0\223\16\0\0\0\0\0\0", 12) = 12 263563 write(2pipe:[1445512], "\1\010263563 ip=64.142.18.25\n", 25) = 25 263563 getsockname(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, {sa_family=AF_INET, sin_port=htons(993), sin_addr=inet_addr("64.142.111.79")}, [16]) = 0 263563 socket(AF_LOCAL, SOCK_STREAM, 0) = 19UNIX:[1458853] 263563 fcntl(19UNIX:[1458853], F_GETFL) = 0x2 (flags O_RDWR) 263563 fcntl(19UNIX:[1458853], F_SETFL, O_RDWR|O_NONBLOCK) = 0 263563 connect(19UNIX:[1458853], {sa_family=AF_LOCAL, sun_path="ssl-params"}, 110) = 0 263563 fcntl(19UNIX:[1458853], F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK) 263563 fcntl(19UNIX:[1458853], F_SETFL, O_RDWR) = 0 263563 read(19UNIX:[1458853], "\0\2\0\0", 4) = 4 263563 read(19UNIX:[1458853], "H\0\0\0", 4) = 4 263563 read(19UNIX:[1458853], "0F\2A\0\246@\4\253O,\222\10\300\237\334\240>\331\270\24K\261w\300\16\0076\230\2039\1"..., 72) = 72 263563 read(19UNIX:[1458853], "\0\4\0\0", 4) = 4 263563 read(19UNIX:[1458853], "\212\0\0\0", 4) = 4 263563 read(19UNIX:[1458853], "0\201\207\2\201\201\0\213:7H\"\251}6d\371}\212\312\276\177p!\10\26\1[\241\265\254\216"..., 138) = 138 263563 read(19UNIX:[1458853], "\0\0\0\0", 4) = 4 263563 read(19UNIX:[1458853], "", 1) = 0 263563 close(19UNIX:[1458853]) = 0 263563 socketpair(AF_LOCAL, SOCK_STREAM, 0, [19UNIX:[1401333-1401334]>, 20UNIX:[1401334-1401333]>]) = 0 263563 fcntl(19UNIX:[1401333-1401334]>, F_GETFL) = 0x2 (flags O_RDWR) 263563 fcntl(19UNIX:[1401333-1401334]>, F_SETFL, O_RDWR|O_NONBLOCK) = 0 263563 fcntl(20UNIX:[1401334-1401333]>, F_GETFL) = 0x2 (flags O_RDWR) 263563 fcntl(20UNIX:[1401334-1401333]>, F_SETFL, O_RDWR|O_NONBLOCK) = 0 263563 fcntl(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK) 263563 fcntl(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, F_SETFL, O_RDWR|O_NONBLOCK) = 0 263563 fstat(20UNIX:[1401334-1401333]>, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 263563 lseek(20UNIX:[1401334-1401333]>, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) 263563 getsockname(20UNIX:[1401334-1401333]>, {sa_family=AF_LOCAL, NULL}, [2]) = 0 263563 epoll_ctl(14, EPOLL_CTL_ADD, 20UNIX:[1401334-1401333]>, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=2773038880, u64=94500643485472}}) = 0 263563 write(20UNIX:[1401334-1401333]>, "* OK [CAPABILITY IMAP4rev1 LITER"..., 103) = 103 263563 brk(NULL) = 0x55f2a549d000 263563 brk(0x55f2a54c2000) = 0x55f2a54c2000 263563 read(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, "\26\3\1\0\253\1\0\0\247\3\3", 11) = 11 263563 read(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, "\205\224\354\263zY\200p\240T\21\377\276\224\251(\343\255x\277\273.\223\304\"TCP:[64.142.111.79:993-64.142.18.25:39552]>, "\26\3\3\0=\2\0\0009\3\0033\336\314\231\205\305\330\206M\361qQ\240\272\225\317^\331Ysc"..., 4096) = 4096 263563 write(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, "http://ocsp.usertrust.com0\r\6\t*\206H"..., 680) = 680 263563 read(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, 0x55f2a5498db3, 5) = -1 EAGAIN (Resource temporarily unavailable) 263563 epoll_ctl(14, EPOLL_CTL_ADD, 18TCP:[64.142.111.79:993-64.142.18.25:39552]>, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=2773128976, u64=94500643575568}}) = 0 263563 epoll_ctl(14, EPOLL_CTL_DEL, 7TCP:[0.0.0.0:143], 0x7ffcd4f4f270) = 0 263563 epoll_ctl(14, EPOLL_CTL_DEL, 8TCPv6:[:::143], 0x7ffcd4f4f270) = 0 263563 epoll_ctl(14, EPOLL_CTL_DEL, 9TCP:[0.0.0.0:993], 0x7ffcd4f4f270) = 0 263563 epoll_ctl(14, EPOLL_CTL_DEL, 10TCPv6:[:::993], 0x7ffcd4f4f270) = 0 263563 close(7TCP:[0.0.0.0:143]) = 0 263563 close(8TCPv6:[:::143]) = 0 263563 close(9TCP:[0.0.0.0:993]) = 0 263563 close(10TCPv6:[:::993]) = 0 263563 epoll_wait(14, [{EPOLLIN, {u32=2773128976, u64=94500643575568}}], 10, 179981) = 1 263563 read(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, "\26\3\3\0f", 5) = 5 263563 read(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, "\20\0\0ba\4:tZW\323_&\31\205\274\254\242\246\203\342\324O\350\36\206uX\36@/\r"..., 102) = 102 263563 read(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, "\24\3\3\0\1", 5) = 5 263563 read(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, "\1", 1) = 1 263563 read(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, "\26\3\3\0(", 5) = 5 263563 read(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, "\224\204\216\367\254\217z\253$S\325\242F\t\256<'vz\3\355\37\fmz\204\261li\307\23\225"..., 40) = 40 263563 write(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, "\26\3\3\0\252\4\0\0\246\0\0\1,\0\240q/\300C\32\250\251\253I>\177\205A\3\331&\\"..., 226) = 226 263563 epoll_ctl(14, EPOLL_CTL_ADD, 19UNIX:[1401333-1401334]>, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=2773039024, u64=94500643485616}}) = 0 263563 read(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, 0x55f2a5498db3, 5) = -1 EAGAIN (Resource temporarily unavailable) 263563 epoll_wait(14, [{EPOLLIN, {u32=2773039024, u64=94500643485616}}], 10, 179974) = 1 263563 read(19UNIX:[1401333-1401334]>, "* OK [CAPABILITY IMAP4rev1 LITER"..., 1024) = 103 263563 setsockopt(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, SOL_TCP, TCP_CORK, [1], 4) = 0 263563 write(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, "\27\3\3\0\177[\202'O\267-\354\\\301@\225\301\363YeQ\213\341\204!x\347\314\305\327\16\366"..., 132) = 132 263563 read(19UNIX:[1401333-1401334]>, 0x55f2a5492a54, 1024) = -1 EAGAIN (Resource temporarily unavailable) 263563 setsockopt(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, SOL_TCP, TCP_CORK, [0], 4) = 0 263563 epoll_wait(14, [{EPOLLIN, {u32=2773128976, u64=94500643575568}}], 10, 179973) = 1 263563 read(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, "\27\3\3\0!", 5) = 5 263563 read(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, "\224\204\216\367\254\217z\254\366W\2765\27\22l\277\262\v\217f\323\254i\272\214\364\264#q\254n\323"..., 33) = 33 263563 sendto(19UNIX:[1401333-1401334]>, "? logout\n", 9, 0, NULL, 0) = 9 263563 read(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, 0x55f2a5498db3, 5) = -1 EAGAIN (Resource temporarily unavailable) 263563 epoll_wait(14, [{EPOLLIN, {u32=2773038880, u64=94500643485472}}], 10, 177320) = 1 263563 read(20UNIX:[1401334-1401333]>, "? logout\n", 863) = 9 263563 write(2pipe:[1445512], "\1\010263563 prefix=imap-login: \n", 29) = 29 263563 write(2pipe:[1445512], "\1\002263563 Aborted login (no auth "..., 131) = 131 263563 epoll_ctl(14, EPOLL_CTL_DEL, 18TCP:[64.142.111.79:993-64.142.18.25:39552]>, 0x7ffcd4f4f2d0) = 0 263563 epoll_ctl(14, EPOLL_CTL_DEL, 19UNIX:[1401333-1401334]>, 0x7ffcd4f4f2d0) = 0 263563 write(18TCP:[64.142.111.79:993-64.142.18.25:39552]>, "\25\3\3\0\32[\202'O\267-\354]\221\344\235?\351'\270g\262\2-\31\216V\236\364\314\253", 31) = 31 263563 close(18TCP:[64.142.111.79:993-64.142.18.25:39552]>) = 0 263563 close(19UNIX:[1401333-1401334]>) = 0 263563 setsockopt(20UNIX:[1401334-1401333]>, SOL_TCP, TCP_CORK, [1], 4) = -1 EOPNOTSUPP (Operation not supported) 263563 write(20UNIX:[1401334-1401333]>, "* BYE Logging out\r\n? OK Logout c"..., 43) = -1 EPIPE (Broken pipe) 263563 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=263563, si_uid=994} --- 263563 epoll_ctl(14, EPOLL_CTL_DEL, 20UNIX:[1401334-1401333]>, 0x7ffcd4f4f2e0) = 0 263563 close(20UNIX:[1401334-1401333]>) = 0 263563 epoll_ctl(14, EPOLL_CTL_DEL, 17UNIX:[1347141-1423948]>, 0x7ffcd4f4f280) = 0 263563 close(17UNIX:[1347141-1423948]>) = 0 263563 epoll_ctl(14, EPOLL_CTL_DEL, 13UNIX:[1347139-1250858]>, 0x7ffcd4f4f400) = 0 263563 close(13UNIX:[1347139-1250858]>) = 0 263563 close(11UNIX:[1347138-1449033]>) = 0 263563 epoll_ctl(14, EPOLL_CTL_DEL, 6pipe:[1445521], 0x7ffcd4f4f420) = 0 263563 epoll_ctl(14, EPOLL_CTL_DEL, 15pipe:[1347140], 0x7ffcd4f4f3f0) = 0 263563 close(15pipe:[1347140]) = 0 263563 close(16pipe:[1347140]) = 0 263563 close(14) = 0 263563 exit_group(0) = ? 263563 +++ exited with 0 +++

Grant Keller System Operations grant.keller@sonic.com