https://wiki.dovecot.org/Debugging/Rawlog
Can you try with this?
Aki
> On 31 March 2018 at 00:52 Grant Keller <grant.kel...@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 = </etc/dovecot/ssl/gd_bundle.crt
> ssl_cert = </etc/dovecot/ssl/imap.sonic.net.crt
> ssl_cipher_list =
> ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-DSS-AES128-GCM-SHA256:kEDH+AESGCM:ECDHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA:ECDHE-ECDSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES128-SHA:DHE-DSS-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-DSS-AES256-SHA:DHE-RSA-AES256-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA256:AES256-SHA256:AES128-SHA:AES256-SHA:AES:CAMELLIA:DES-CBC3-SHA:!aNULL:!eNULL:!EXPORT:!DES:!RC4:!MD5:!PSK:!aECDH:!EDH-DSS-DES-CBC3-SHA:!EDH-RSA-DES-CBC3-SHA:!KRB5-DES-CBC3-SHA
> ssl_key = </etc/dovecot/ssl/imap.sonic.net.key
> ssl_parameters_regenerate = 1 days
> ssl_protocols = !SSLv2 !SSLv3
> syslog_facility = local0
> protocol imap {
> imap_max_line_length = 128 k
> ssl_ca = </etc/dovecot/ssl/gd_bundle.crt
> ssl_cert = </etc/dovecot/ssl/imap.sonic.net.crt
> ssl_key = </etc/dovecot/ssl/imap.sonic.net.key
> }
> protocol pop3 {
> ssl_ca = </etc/dovecot/ssl/pop.sonic.net.ca-bundle
> ssl_cert = </etc/dovecot/ssl/pop.sonic.net.crt
> ssl_key = </etc/dovecot/ssl/pop.sonic.net.key
> }
>
> STRACE:
>
> 263563 epoll_wait(14<anon_inode:[eventpoll]>, [{EPOLLIN, {u32=2772983280,
> u64=94500643429872}}], 8, -1) = 1
> 263563 accept(9<TCP:[0.0.0.0:993]>, {sa_family=AF_INET,
> sin_port=htons(39552), sin_addr=inet_addr("64.142.18.25")}, [16]) =
> 18<TCP:[64.142.111.79:993->64.142.18.25:39552]>
> 263563 fcntl(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, F_GETFL) = 0x2
> (flags O_RDWR)
> 263563 fcntl(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, F_SETFL,
> O_RDWR|O_NONBLOCK) = 0
> 263563 write(5<pipe:[1445541]>, "\213\5\4\0\223\16\0\0\0\0\0\0", 12) = 12
> 263563 write(2<pipe:[1445512]>, "\1\010263563 ip=64.142.18.25\n", 25) = 25
> 263563 getsockname(18<TCP:[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) = 19<UNIX:[1458853]>
> 263563 fcntl(19<UNIX:[1458853]>, F_GETFL) = 0x2 (flags O_RDWR)
> 263563 fcntl(19<UNIX:[1458853]>, F_SETFL, O_RDWR|O_NONBLOCK) = 0
> 263563 connect(19<UNIX:[1458853]>, {sa_family=AF_LOCAL,
> sun_path="ssl-params"}, 110) = 0
> 263563 fcntl(19<UNIX:[1458853]>, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
> 263563 fcntl(19<UNIX:[1458853]>, F_SETFL, O_RDWR) = 0
> 263563 read(19<UNIX:[1458853]>, "\0\2\0\0", 4) = 4
> 263563 read(19<UNIX:[1458853]>, "H\0\0\0", 4) = 4
> 263563 read(19<UNIX:[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(19<UNIX:[1458853]>, "\0\4\0\0", 4) = 4
> 263563 read(19<UNIX:[1458853]>, "\212\0\0\0", 4) = 4
> 263563 read(19<UNIX:[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(19<UNIX:[1458853]>, "\0\0\0\0", 4) = 4
> 263563 read(19<UNIX:[1458853]>, "", 1) = 0
> 263563 close(19<UNIX:[1458853]>) = 0
> 263563 socketpair(AF_LOCAL, SOCK_STREAM, 0, [19<UNIX:[1401333->1401334]>,
> 20<UNIX:[1401334->1401333]>]) = 0
> 263563 fcntl(19<UNIX:[1401333->1401334]>, F_GETFL) = 0x2 (flags O_RDWR)
> 263563 fcntl(19<UNIX:[1401333->1401334]>, F_SETFL, O_RDWR|O_NONBLOCK) = 0
> 263563 fcntl(20<UNIX:[1401334->1401333]>, F_GETFL) = 0x2 (flags O_RDWR)
> 263563 fcntl(20<UNIX:[1401334->1401333]>, F_SETFL, O_RDWR|O_NONBLOCK) = 0
> 263563 fcntl(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, F_GETFL) =
> 0x802 (flags O_RDWR|O_NONBLOCK)
> 263563 fcntl(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, F_SETFL,
> O_RDWR|O_NONBLOCK) = 0
> 263563 fstat(20<UNIX:[1401334->1401333]>, {st_mode=S_IFSOCK|0777, st_size=0,
> ...}) = 0
> 263563 lseek(20<UNIX:[1401334->1401333]>, 0, SEEK_CUR) = -1 ESPIPE (Illegal
> seek)
> 263563 getsockname(20<UNIX:[1401334->1401333]>, {sa_family=AF_LOCAL, NULL},
> [2]) = 0
> 263563 epoll_ctl(14<anon_inode:[eventpoll]>, EPOLL_CTL_ADD,
> 20<UNIX:[1401334->1401333]>, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP,
> {u32=2773038880, u64=94500643485472}}) = 0
> 263563 write(20<UNIX:[1401334->1401333]>, "* OK [CAPABILITY IMAP4rev1
> LITER"..., 103) = 103
> 263563 brk(NULL) = 0x55f2a549d000
> 263563 brk(0x55f2a54c2000) = 0x55f2a54c2000
> 263563 read(18<TCP:[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(18<TCP:[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\"<R\222\16\3538s"...,
> 165) = 165
> 263563 write(18<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(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>,
> "http://ocsp.usertrust.com0\r\6\t*\206H";..., 680) = 680
> 263563 read(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, 0x55f2a5498db3,
> 5) = -1 EAGAIN (Resource temporarily unavailable)
> 263563 epoll_ctl(14<anon_inode:[eventpoll]>, EPOLL_CTL_ADD,
> 18<TCP:[64.142.111.79:993->64.142.18.25:39552]>,
> {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=2773128976, u64=94500643575568}}) = > 0
> 263563 epoll_ctl(14<anon_inode:[eventpoll]>, EPOLL_CTL_DEL,
> 7<TCP:[0.0.0.0:143]>, 0x7ffcd4f4f270) = 0
> 263563 epoll_ctl(14<anon_inode:[eventpoll]>, EPOLL_CTL_DEL,
> 8<TCPv6:[:::143]>, 0x7ffcd4f4f270) = 0
> 263563 epoll_ctl(14<anon_inode:[eventpoll]>, EPOLL_CTL_DEL,
> 9<TCP:[0.0.0.0:993]>, 0x7ffcd4f4f270) = 0
> 263563 epoll_ctl(14<anon_inode:[eventpoll]>, EPOLL_CTL_DEL,
> 10<TCPv6:[:::993]>, 0x7ffcd4f4f270) = 0
> 263563 close(7<TCP:[0.0.0.0:143]>) = 0
> 263563 close(8<TCPv6:[:::143]>) = 0
> 263563 close(9<TCP:[0.0.0.0:993]>) = 0
> 263563 close(10<TCPv6:[:::993]>) = 0
> 263563 epoll_wait(14<anon_inode:[eventpoll]>, [{EPOLLIN, {u32=2773128976,
> u64=94500643575568}}], 10, 179981) = 1
> 263563 read(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, "\26\3\3\0f", 5)
> = 5
> 263563 read(18<TCP:[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(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, "\24\3\3\0\1",
> 5) = 5
> 263563 read(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, "\1", 1) = 1
> 263563 read(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, "\26\3\3\0(", 5)
> = 5
> 263563 read(18<TCP:[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(18<TCP:[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<anon_inode:[eventpoll]>, EPOLL_CTL_ADD,
> 19<UNIX:[1401333->1401334]>, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP,
> {u32=2773039024, u64=94500643485616}}) = 0
> 263563 read(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, 0x55f2a5498db3,
> 5) = -1 EAGAIN (Resource temporarily unavailable)
> 263563 epoll_wait(14<anon_inode:[eventpoll]>, [{EPOLLIN, {u32=2773039024,
> u64=94500643485616}}], 10, 179974) = 1
> 263563 read(19<UNIX:[1401333->1401334]>, "* OK [CAPABILITY IMAP4rev1
> LITER"..., 1024) = 103
> 263563 setsockopt(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, SOL_TCP,
> TCP_CORK, [1], 4) = 0
> 263563 write(18<TCP:[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(19<UNIX:[1401333->1401334]>, 0x55f2a5492a54, 1024) = -1 EAGAIN
> (Resource temporarily unavailable)
> 263563 setsockopt(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, SOL_TCP,
> TCP_CORK, [0], 4) = 0
> 263563 epoll_wait(14<anon_inode:[eventpoll]>, [{EPOLLIN, {u32=2773128976,
> u64=94500643575568}}], 10, 179973) = 1
> 263563 read(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, "\27\3\3\0!", 5)
> = 5
> 263563 read(18<TCP:[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(19<UNIX:[1401333->1401334]>, "? logout\n", 9, 0, NULL, 0) = 9
> 263563 read(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, 0x55f2a5498db3,
> 5) = -1 EAGAIN (Resource temporarily unavailable)
> 263563 epoll_wait(14<anon_inode:[eventpoll]>, [{EPOLLIN, {u32=2773038880,
> u64=94500643485472}}], 10, 177320) = 1
> 263563 read(20<UNIX:[1401334->1401333]>, "? logout\n", 863) = 9
> 263563 write(2<pipe:[1445512]>, "\1\010263563 prefix=imap-login: \n", 29) = 29
> 263563 write(2<pipe:[1445512]>, "\1\002263563 Aborted login (no auth "...,
> 131) = 131
> 263563 epoll_ctl(14<anon_inode:[eventpoll]>, EPOLL_CTL_DEL,
> 18<TCP:[64.142.111.79:993->64.142.18.25:39552]>, 0x7ffcd4f4f2d0) = 0
> 263563 epoll_ctl(14<anon_inode:[eventpoll]>, EPOLL_CTL_DEL,
> 19<UNIX:[1401333->1401334]>, 0x7ffcd4f4f2d0) = 0
> 263563 write(18<TCP:[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(18<TCP:[64.142.111.79:993->64.142.18.25:39552]>) = 0
> 263563 close(19<UNIX:[1401333->1401334]>) = 0
> 263563 setsockopt(20<UNIX:[1401334->1401333]>, SOL_TCP, TCP_CORK, [1], 4) =
> -1 EOPNOTSUPP (Operation not supported)
> 263563 write(20<UNIX:[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<anon_inode:[eventpoll]>, EPOLL_CTL_DEL,
> 20<UNIX:[1401334->1401333]>, 0x7ffcd4f4f2e0) = 0
> 263563 close(20<UNIX:[1401334->1401333]>) = 0
> 263563 epoll_ctl(14<anon_inode:[eventpoll]>, EPOLL_CTL_DEL,
> 17<UNIX:[1347141->1423948]>, 0x7ffcd4f4f280) = 0
> 263563 close(17<UNIX:[1347141->1423948]>) = 0
> 263563 epoll_ctl(14<anon_inode:[eventpoll]>, EPOLL_CTL_DEL,
> 13<UNIX:[1347139->1250858]>, 0x7ffcd4f4f400) = 0
> 263563 close(13<UNIX:[1347139->1250858]>) = 0
> 263563 close(11<UNIX:[1347138->1449033]>) = 0
> 263563 epoll_ctl(14<anon_inode:[eventpoll]>, EPOLL_CTL_DEL,
> 6<pipe:[1445521]>, 0x7ffcd4f4f420) = 0
> 263563 epoll_ctl(14<anon_inode:[eventpoll]>, EPOLL_CTL_DEL,
> 15<pipe:[1347140]>, 0x7ffcd4f4f3f0) = 0
> 263563 close(15<pipe:[1347140]>) = 0
> 263563 close(16<pipe:[1347140]>) = 0
> 263563 close(14<anon_inode:[eventpoll]>) = 0
> 263563 exit_group(0) = ?
> 263563 +++ exited with 0 +++
>
>
> Grant Keller
> System Operations
> grant.kel...@sonic.com
