dovecot - Jan 2018 - Dovecot 2.3.0 imap-login using 100% CPU

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

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

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

Is it possible for you to provide output of

p *client
p *client->next
p *client->next->next

until it hits NULL?

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

On 10 Jan 2018, at 17.28, 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
So it's not doing any syscalls. What about ltrace -tt -e '*' -p
<pid>?

Also what's your doveconf -n? Mainly wondering about service imap-login { ..
} settings. Probably service_count=1 (default)? This somehow hangs here when
there's a client with pending input, but auth process wasn't yet
connected to. It's not very obvious though how it could have gotten stuck in
there.