Dovecot 2.3.0 imap-login using 100% CPU

[Jason Kiniry]

We were able to obtain a better backtrace:

0x00007f4b303b5af5 in clients_notify_auth_connected () at client-common-auth.c:839
839                     if (!client_does_custom_io(client) && client->input_blocked) {
(gdb) run

Thank you!

Regards,

Jason Kiniry

> On Jan 10, 2018, at 4:28 PM, Jason Kiniry <jason at cpanel.net> wrote:
> 
> When in the process of testing out the 2.3.0 version of Dovecot, we noticed that on a busy server, imap-login can sometimes take 100% CPU and remain there indefinitely. We grabbed a gdb trace while it was happening:
> 
> dovenull 36053 31.2  0.0  60460 17316 ?        R    04:38  11:55 dovecot/imap-login
> root at server [~]# strace -p 36053
> Process 36053 attached
> ^CProcess 36053 detached
> root at server [~]# gdb 
> atGNU gdb (GDB) Red Hat Enterprise Linux (7.2-92.el6)
> Copyright (C) 2010 Free Software Foundation, Inc.
> License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
> This is free software: you are free to change and redistribute it.
> There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
> and "show warranty" for details.
> This GDB was configured as "x86_64-redhat-linux-gnu".
> For bug reporting instructions, please see:
> <http://www.gnu.org/software/gdb/bugs/>.
> (gdb) attach 36053
> Attaching to process 36053
> Reading symbols from /usr/libexec/dovecot/imap-login...done.
> Reading symbols from /usr/lib64/dovecot/libdovecot-login.so.0...done.
> Loaded symbols for /usr/lib64/dovecot/libdovecot-login.so.0
> Reading symbols from /usr/lib64/dovecot/libdovecot.so.0...done.
> Loaded symbols for /usr/lib64/dovecot/libdovecot.so.0
> Reading symbols from /lib64/libc.so.6...(no debugging symbols found)...done.
> Loaded symbols for /lib64/libc.so.6
> Reading symbols from /usr/lib64/libssl.so.10...(no debugging symbols found)...done.
> Loaded symbols for /usr/lib64/libssl.so.10
> Reading symbols from /usr/lib64/libcrypto.so.10...(no debugging symbols found)...done.
> Loaded symbols for /usr/lib64/libcrypto.so.10
> Reading symbols from /lib64/librt.so.1...(no debugging symbols found)...done.
> Loaded symbols for /lib64/librt.so.1
> Reading symbols from /lib64/libdl.so.2...(no debugging symbols found)...done.
> Loaded symbols for /lib64/libdl.so.2
> Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
> Loaded symbols for /lib64/ld-linux-x86-64.so.2
> Reading symbols from /lib64/libgssapi_krb5.so.2...(no debugging symbols found)...done.
> Loaded symbols for /lib64/libgssapi_krb5.so.2
> Reading symbols from /lib64/libkrb5.so.3...(no debugging symbols found)...done.
> Loaded symbols for /lib64/libkrb5.so.3
> Reading symbols from /lib64/libcom_err.so.2...(no debugging symbols found)...done.
> Loaded symbols for /lib64/libcom_err.so.2
> Reading symbols from /lib64/libk5crypto.so.3...(no debugging symbols found)...done.
> Loaded symbols for /lib64/libk5crypto.so.3
> Reading symbols from /lib64/libz.so.1...(no debugging symbols found)...done.
> Loaded symbols for /lib64/libz.so.1
> Reading symbols from /lib64/libpthread.so.0...(no debugging symbols found)...done.
> [Thread debugging using libthread_db enabled]
> Loaded symbols for /lib64/libpthread.so.0
> Reading symbols from /lib64/libkrb5support.so.0...(no debugging symbols found)...done.
> Loaded symbols for /lib64/libkrb5support.so.0
> Reading symbols from /lib64/libkeyutils.so.1...(no debugging symbols found)...done.
> Loaded symbols for /lib64/libkeyutils.so.1
> Reading symbols from /lib64/libresolv.so.2...(no debugging symbols found)...done.
> Loaded symbols for /lib64/libresolv.so.2
> Reading symbols from /lib64/libselinux.so.1...(no debugging symbols found)...done.
> Loaded symbols for /lib64/libselinux.so.1
> Reading symbols from /usr/lib64/dovecot/libssl_iostream_openssl.so...done.
> Loaded symbols for /usr/lib64/dovecot/libssl_iostream_openssl.so
> 0x00007f758fb8dd18 in client_notify_auth_ready at plt () from /usr/lib64/dovecot/libdovecot-login.so.0
> Missing separate debuginfos, use: debuginfo-install dovecot-2.3.0-4.cp1162.x86_64
> (gdb) back
> #0  0x00007f758fb8dd18 in client_notify_auth_ready at plt () from /usr/lib64/dovecot/libdovecot-login.so.0
> #1  0x00007f758fb90af0 in clients_notify_auth_connected () at client-common-auth.c:837
> #2  0x00007f758f8cfc04 in auth_server_input_done (conn=0x7f7591911838) at auth-server-connection.c:127
> #3  auth_server_connection_input_line (conn=0x7f7591911838) at auth-server-connection.c:229
> #4  auth_server_connection_input (conn=0x7f7591911838) at auth-server-connection.c:281
> #5  0x00007f758f8f5e35 in io_loop_call_io (io=0x7f759277e2a0) at ioloop.c:614
> #6  0x00007f758f8f7d3f in io_loop_handler_run_internal (ioloop=<value optimized out>) at ioloop-epoll.c:222
> #7  0x00007f758f8f5f25 in io_loop_handler_run (ioloop=0x7f75918e4d00) at ioloop.c:666
> #8  0x00007f758f8f6148 in io_loop_run (ioloop=0x7f75918e4d00) at ioloop.c:639
> #9  0x00007f758f875ab3 in master_service_run (service=0x7f75918e4b90, callback=<value optimized out>) at master-service.c:767
> #10 0x00007f758fb96156 in login_binary_run (binary=<value optimized out>, argc=1, argv=0x7f75918e4890) at main.c:549
> #11 0x00007f758f4a2d1d in __libc_start_main () from /lib64/libc.so.6
> #12 0x00007f758ffc4469 in _start ()
> (gdb) run
> The program being debugged has been started already.
> Start it from the beginning? (y or n) n
> Program not restarted.
> (gdb) continue
> Continuing.
> ^C
> Program received signal SIGINT, Interrupt.
> client_notify_auth_ready (client=0x7f7592775140) at client-common.c:1031
> 1031	client-common.c: No such file or directory.
> 	in client-common.c
> (gdb) back
> #0  client_notify_auth_ready (client=0x7f7592775140) at client-common.c:1031
> #1  0x00007f758fb90af0 in clients_notify_auth_connected () at client-common-auth.c:837
> #2  0x00007f758f8cfc04 in auth_server_input_done (conn=0x7f7591911838) at auth-server-connection.c:127
> #3  auth_server_connection_input_line (conn=0x7f7591911838) at auth-server-connection.c:229
> #4  auth_server_connection_input (conn=0x7f7591911838) at auth-server-connection.c:281
> #5  0x00007f758f8f5e35 in io_loop_call_io (io=0x7f759277e2a0) at ioloop.c:614
> #6  0x00007f758f8f7d3f in io_loop_handler_run_internal (ioloop=<value optimized out>) at ioloop-epoll.c:222
> #7  0x00007f758f8f5f25 in io_loop_handler_run (ioloop=0x7f75918e4d00) at ioloop.c:666
> #8  0x00007f758f8f6148 in io_loop_run (ioloop=0x7f75918e4d00) at ioloop.c:639
> #9  0x00007f758f875ab3 in master_service_run (service=0x7f75918e4b90, callback=<value optimized out>) at master-service.c:767
> #10 0x00007f758fb96156 in login_binary_run (binary=<value optimized out>, argc=1, argv=0x7f75918e4890) at main.c:549
> #11 0x00007f758f4a2d1d in __libc_start_main () from /lib64/libc.so.6
> #12 0x00007f758ffc4469 in _start ()
> (gdb) 
> 
> Anyone have any thoughts?
> 
> Regards,
> 
> Jason Kiniry