Dovecot 2.3.0 imap-login using 100% CPU

[Aki Tuomi]

Thank you for this, we'll look into it.

Aki


On 11.01.2018 01:29, Jason Kiniry wrote:
> 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