dovecot - Jul 2016 - 2.3.0~alpha0-1~auto+197: Crash when openening a message via IMAP

>From the log:
Jul 11 13:12:42 mproxy dovecot: imap-login: Login: user=<hildeb>,
method=PLAIN, rip=141.42.206.36, lip=141.42.206.11, mpid=27254, TLS,
session=<TGwoO1o3id+NKs4k>
Jul 11 13:12:44 mproxy dovecot: imap(hildeb)<TGwoO1o3id+NKs4k>: Panic:
file imap-client.c: line 854 (client_check_command_hangs): assertion failed:
((io_loop_find_fd_conditions(current_ioloop, client->fd_out) & IO_WRITE)
!= 0)
Jul 11 13:12:44 mproxy dovecot: imap(hildeb)<TGwoO1o3id+NKs4k>: Error: Raw
backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x8e09e)
[0x7efd1d3a309e] -> /usr/lib/dovecot/libdovecot.so.0(+0x8e18c)
[0x7efd1d3a318c] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0)
[0x7efd1d34169e] -> dovecot/imap [hildeb 141.42.206.36 UID FETCH - 8192 bytes
waiting corked](+0x1ad42)
[0x55649b35cd42] -> dovecot/imap [hildeb 141.42.206.36 UID FETCH - 8192 bytes
waiting corked](client_output+0x118)
[0x55649b35ce68] -> /usr/lib/dovecot/libdovecot.so.0(+0xaf370) 
[0x7efd1d3c4370] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x4c)
[0x7efd1d3b715c] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x101)
[0x7efd1d3b85b1] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x25)
[0x7efd1d3b71e5] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x30)
[0x7efd1d3b7380] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13)
[0x7efd1d347c13] -> dovecot/imap [hildeb 141.42.206.36 UID FETCH - 8192 bytes
waiting corked](main+0x322) [0x55649b34faf2] ->
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)
[0x7efd1cf6c830] -> dovecot/imap [hildeb 141.42.206.36 UID FETCH - 8192 bytes
waiting corked](+0xdc6f) [0x55649b34fc6f]
Jul 11 13:12:44 mproxy dovecot: imap(hildeb)<TGwoO1o3id+NKs4k>: Fatal:
master: service(imap): child 27254 killed with signal 6 (core dumped)

# 2.3.0.alpha0 (3aae884) [XI:2:2.3.0~alpha0-1~auto+197]:
/etc/dovecot/dovecot.conf

-- 
Ralf Hildebrandt
  Gesch?ftsbereich IT | Abteilung Netzwerk
  Charit? - Universit?tsmedizin Berlin
  Campus Benjamin Franklin
  Hindenburgdamm 30 | D-12203 Berlin
  Tel. +49 30 450 570 155 | Fax: +49 30 450 570 962
  ralf.hildebrandt at charite.de | http://www.charite.de

On 11.07.2016 14:15, Ralf Hildebrandt wrote:
> From the log:
>
> Jul 11 13:12:42 mproxy dovecot: imap-login: Login: user=<hildeb>,
method=PLAIN, rip=141.42.206.36, lip=141.42.206.11, mpid=27254, TLS,
session=<TGwoO1o3id+NKs4k>
> Jul 11 13:12:44 mproxy dovecot: imap(hildeb)<TGwoO1o3id+NKs4k>:
Panic: file imap-client.c: line 854 (client_check_command_hangs): assertion
failed: ((io_loop_find_fd_conditions(current_ioloop, client->fd_out) &
IO_WRITE) != 0)
> Jul 11 13:12:44 mproxy dovecot: imap(hildeb)<TGwoO1o3id+NKs4k>:
Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x8e09e)
> [0x7efd1d3a309e] -> /usr/lib/dovecot/libdovecot.so.0(+0x8e18c)
> [0x7efd1d3a318c] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0)
> [0x7efd1d34169e] -> dovecot/imap [hildeb 141.42.206.36 UID FETCH - 8192
bytes waiting corked](+0x1ad42)
> [0x55649b35cd42] -> dovecot/imap [hildeb 141.42.206.36 UID FETCH - 8192
bytes waiting corked](client_output+0x118)
> [0x55649b35ce68] -> /usr/lib/dovecot/libdovecot.so.0(+0xaf370) 
> [0x7efd1d3c4370] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x4c)
> [0x7efd1d3b715c] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x101)
> [0x7efd1d3b85b1] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x25)
> [0x7efd1d3b71e5] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x30)
> [0x7efd1d3b7380] ->
/usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13)
> [0x7efd1d347c13] -> dovecot/imap [hildeb 141.42.206.36 UID FETCH - 8192
bytes waiting corked](main+0x322) [0x55649b34faf2] ->
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)
> [0x7efd1cf6c830] -> dovecot/imap [hildeb 141.42.206.36 UID FETCH - 8192
bytes waiting corked](+0xdc6f) [0x55649b34fc6f]
> Jul 11 13:12:44 mproxy dovecot: imap(hildeb)<TGwoO1o3id+NKs4k>:
Fatal: master: service(imap): child 27254 killed with signal 6 (core dumped)
>
> # 2.3.0.alpha0 (3aae884) [XI:2:2.3.0~alpha0-1~auto+197]:
/etc/dovecot/dovecot.conf
>
Did you forget to include doveconf -n?

Aki

On 11 Jul 2016, at 14:15, Ralf Hildebrandt <Ralf.Hildebrandt at
charite.de> wrote:
> 
> From the log:
> 
> Jul 11 13:12:42 mproxy dovecot: imap-login: Login: user=<hildeb>,
method=PLAIN, rip=141.42.206.36, lip=141.42.206.11, mpid=27254, TLS,
session=<TGwoO1o3id+NKs4k>
> Jul 11 13:12:44 mproxy dovecot: imap(hildeb)<TGwoO1o3id+NKs4k>:
Panic: file imap-client.c: line 854 (client_check_command_hangs): assertion
failed: ((io_loop_find_fd_conditions(current_ioloop, client->fd_out) &
IO_WRITE) != 0)
Could you gdb the core and print some outputs:

fr 5 (or whichever frame number has client_check_command_hangs)
p *client
p *client->command_queue
p *client->command_queue->next
p *client->command_queue->next->next
(etc, until it fails)
p *current_ioloop
p *current_ioloop->io_files
p *current_ioloop->io_files->next
p *current_ioloop->io_files->next->next
(etc, until it fails)

* Aki Tuomi <aki.tuomi at dovecot.fi>:
> Did you forget to include doveconf -n?
# 2.3.0.alpha0 (e84ffeb) [XI:2:2.3.0~alpha0-1~auto+200]:
/etc/dovecot/dovecot.conf
# Pigeonhole version 0.5.0.alpha0 (66b7c14)
# OS: Linux 4.4.0-24-generic x86_64 Ubuntu 16.04 LTS 
auth_mechanisms = plain login
default_vsz_limit = 1 G
imapc_host = email.charite.de
imapc_port = 993
imapc_ssl = imaps
imapc_ssl_verify = no
listen = *,::
mail_gid = imapproxy
mail_home = /home/imapproxy/%u
mail_location = imapc:~/imapc
mail_plugins = mail_log notify
mail_uid = imapproxy
passdb {
  args = host=email.charite.de port=993 ssl=imaps
  default_fields = userdb_imapc_user=%u userdb_imapc_password=%w
  userdb_imapc_host=email.charite.de userdb_imapc_ssl=imaps
  userdb_imapc_port=993
  driver = imap
}
plugin {
  sieve = file:~/sieve;active=~/.dovecot.sieve
}
protocols = imap
service auth {
   inet_listener {
      address = 127.0.0.1
      port = 12345
   }
}
ssl = required
ssl_ca = </etc/ssl/certs/ca-certificates.crt
ssl_cert = </etc/dovecot/dovecot.pem
ssl_cipher_list =
DHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA:ALL:!LOW:!SSLv2:!EXP:!aNULL
ssl_key = </etc/dovecot/private/dovecot.pem
userdb {
  driver = prefetch
}
verbose_proctitle = yes
  
-- 
Ralf Hildebrandt
  Gesch?ftsbereich IT | Abteilung Netzwerk
  Charit? - Universit?tsmedizin Berlin
  Campus Benjamin Franklin
  Hindenburgdamm 30 | D-12203 Berlin
  Tel. +49 30 450 570 155 | Fax: +49 30 450 570 962
  ralf.hildebrandt at charite.de | http://www.charite.de

* Timo Sirainen <tss at iki.fi>:
> On 11 Jul 2016, at 14:15, Ralf Hildebrandt <Ralf.Hildebrandt at
charite.de> wrote:
> > 
> > From the log:
> > 
> > Jul 11 13:12:42 mproxy dovecot: imap-login: Login:
user=<hildeb>, method=PLAIN, rip=141.42.206.36, lip=141.42.206.11,
mpid=27254, TLS, session=<TGwoO1o3id+NKs4k>
> > Jul 11 13:12:44 mproxy dovecot: imap(hildeb)<TGwoO1o3id+NKs4k>:
Panic: file imap-client.c: line 854 (client_check_command_hangs): assertion
failed: ((io_loop_find_fd_conditions(current_ioloop, client->fd_out) &
IO_WRITE) != 0)
> 
> Could you gdb the core and print some outputs:
> 
> fr 5 (or whichever frame number has client_check_command_hangs)
> p *client
> p *client->command_queue
> p *client->command_queue->next
> p *client->command_queue->next->next
> (etc, until it fails)
> p *current_ioloop
> p *current_ioloop->io_files
> p *current_ioloop->io_files->next
> p *current_ioloop->io_files->next->next
> (etc, until it fails)
Here it goes:

Core was generated by 'dovecot/imap'.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007f6fa260d418 in __GI_raise (sig=sig at entry=6) at
../sysdeps/unix/sysv/linux/raise.c:54
54	../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0  0x00007f6fa260d418 in __GI_raise (sig=sig at entry=6) at
../sysdeps/unix/sysv/linux/raise.c:54
#1  0x00007f6fa260f01a in __GI_abort () at abort.c:89
#2  0x00007f6fa2a2f226 in default_fatal_finish (type=<optimized out>,
status=status at entry=0) at failures.c:201
#3  0x00007f6fa2a2f31c in i_internal_fatal_handler (ctx=0x7ffc8041e430,
format=<optimized out>, args=<optimized out>) at failures.c:670
#4  0x00007f6fa29cd6ce in i_panic (format=format at entry=0x558b2197ce00
"file %s: line %d (%s): assertion failed: (%s)") at failures.c:275
#5  0x0000558b2196bd42 in client_check_command_hangs (client=0x558b21bf7030) at
imap-client.c:854
#6  client_continue_pending_input (client=0x558b21bf7030) at imap-client.c:919
#7  0x0000558b2196be68 in client_output (client=0x558b21bf7030) at
imap-client.c:1233
#8  0x00007f6fa2a50500 in stream_send_io (fstream=0x558b21be5bb0) at
ostream-file.c:478
#9  0x00007f6fa2a432ec in io_loop_call_io (io=0x558b21bfdf00) at ioloop.c:564
#10 0x00007f6fa2a44741 in io_loop_handler_run_internal (ioloop=ioloop at
entry=0x558b21ba3740) at ioloop-epoll.c:221
#11 0x00007f6fa2a43375 in io_loop_handler_run (ioloop=ioloop at
entry=0x558b21ba3740) at ioloop.c:612
#12 0x00007f6fa2a43510 in io_loop_run (ioloop=0x558b21ba3740) at ioloop.c:588
#13 0x00007f6fa29d3c43 in master_service_run (service=0x558b21ba35e0,
callback=<optimized out>) at master-service.c:650
#14 0x0000558b2195eaf2 in main (argc=1, argv=0x558b21ba3390) at main.c:460

(gdb) fr 5
#5  0x0000558b2196bd42 in client_check_command_hangs (client=0x558b21bf7030) at
imap-client.c:854
854	imap-client.c: No such file or directory.

(gdb) p *client
$1 = {prev = 0x0, next = 0x0, v = {state_export = 0x558b219763a0
<imap_state_export_base>, state_import = 0x558b219768f0
<imap_state_import_base>, destroy = 0x558b2196c290
<client_default_destroy>}, 
  session_id = 0x558b21bf71d8 "qsZiv2w3uLWNKs4k", userdb_fields
0x558b21bf7400, fd_in = 7, fd_out = 7, io = 0x558b21be5cf0, input
0x558b21be5a60, output = 0x558b21be5c40, to_idle = 0x558b21be5d50,
  to_idle_output = 0x558b21bfe020, to_delayed_input = 0x0, pool 0x558b21bf7010,
service_user = 0x558b21baa020, set = 0x558b21baa7f0,
lda_set = 0x558b21baa930, capability_string = 0x558b21bf7258, 
  user = 0x558b21bb8360, mailbox = 0x558b21bfa060, keywords = {names
0x558b21bfb0f8, announce_count = 1}, sync_counter = 1, messages_count
= 1443, recent_count = 0, uidvalidity = 58, 
  enabled_features = (unknown: 0), last_input = 1468315092,
last_output = 1468315092, bad_counter = 0, free_parser = 0x0,
command_pool = 0x558b21bf7820, command_queue = 0x558b21bf7840, 
  command_queue_size = 1, sync_last_full_modseq = 12854,
highest_fetch_modseq = 0, fetch_hdr_count = 0, fetch_body_count = 1,
fetch_hdr_bytes = 0, fetch_body_bytes = 369600, deleted_count = 0, 
  expunged_count = 0, trashed_count = 0, search_saved_uidset = {arr {buffer =
0x0, element_size = 0}, v = 0x0, v_modifiable = 0x0},
search_updates = {arr = {buffer = 0x0, element_size = 0}, v = 0x0, 
    v_modifiable = 0x0}, notify_ctx = 0x0, notify_uidnext = 157276,
input_lock = 0x0, output_cmd_lock = 0x558b21bf7840,
mailbox_change_lock = 0x0, urlauth_ctx = 0x0, module_contexts = {arr = {
      buffer = 0x558b21bf71f0, element_size = 8}, v = 0x558b21bf71f0,
v_modifiable = 0x558b21bf71f0}, sync_seen_deletes = false,
disconnected = false, destroyed = false, handling_input = false, 
  syncing = false, id_logged = false, mailbox_examined = false,
anvil_sent = true, tls_compression = false, input_skip_line = false,
modseqs_sent_since_sync = false, notify_immediate_expunges = false, 
  notify_count_changes = true, notify_flag_changes = true,
imap_metadata_enabled = false, nonpermanent_modseqs = false,
state_import_bad_idle_done = false, state_import_idle_continue = false}

(gdb) p *client->command_queue
$2 = {prev = 0x0, next = 0x0, client = 0x558b21bf7030, pool 0x558b21bf7820, tag
= 0x558b21bf7970 "a0020", name = 0x558b21bf7978
"UID FETCH", args = 0x558b21bf7988 "157242 BODY.PEEK[]", 
  cmd_flags = COMMAND_FLAG_BREAKS_SEQS, tagline_reply = 0x0, func 0x558b219616a0
<cmd_fetch_continue>, context = 0x558b21bf79a0,
module_contexts = {arr = {buffer = 0x558b21bf7908, element_size = 8}, 
    v = 0x558b21bf7908, v_modifiable = 0x558b21bf7908}, parser 0x558b21ba7810,
state = CLIENT_COMMAND_STATE_WAIT_OUTPUT, start_time {tv_sec = 1468315092,
tv_usec = 52854}, last_run_timeval = {
    tv_sec = 1468315092, tv_usec = 52854}, start_ioloop_wait_usecs 1094365,
running_usecs = 50959, bytes_in = 18, bytes_out = 369642,
sync = 0x0, uid = true, cancel = false, param_error = false, 
  search_save_result = false, search_save_result_used = false,
temp_executed = true, tagline_sent = false, executing = false}

(gdb) p *client->command_queue->next
Cannot access memory at address 0x0

(gdb) p *current_ioloop
$4 = {prev = 0x0, cur_ctx = 0x558b21bb8150, io_files = 0x558b21bfdea0,
next_io_file = 0x0, timeouts = 0x558b21ba37c0, timeouts_new = {arr {buffer =
0x558b21ba3930, element_size = 8},
    v = 0x558b21ba3930, v_modifiable = 0x558b21ba3930},
handler_context = 0x558b21ba5250, notify_handler_context = 0x0,
max_fd_count = 0,
  time_moved_callback = 0x7f6fa2cfdea0
<mail_storage_service_time_moved>, next_max_time = 1468315393,
ioloop_wait_usecs = 1097229, io_pending_count = 0, running = true,
iolooping = true}

(gdb) p *current_ioloop->io_files
$5 = {io = {condition = IO_READ, source_linenum = 1558, pending false, callback
= 0x7f6fa2d4bb50 <imapc_connection_input>, context 0x558b21be1570, ioloop
= 0x558b21ba3740, ctx = 0x558b21bb8150},
  prev = 0x0, next = 0x558b21be5cf0, refcount = 1, fd = 16, istream 0x0}

(gdb) p *current_ioloop->io_files->next
$6 = {io = {condition = IO_READ, source_linenum = 115, pending false, callback =
0x558b2196beb0 <client_input>, context 0x558b21bf7030, ioloop =
0x558b21ba3740, ctx = 0x558b21bb8150},
  prev = 0x558b21bfdea0, next = 0x558b21ba6ba0, refcount = 1, fd = 7,
istream = 0x558b21be5a60}

(gdb) p *current_ioloop->io_files->next->next
$7 = {io = {condition = IO_ERROR, source_linenum = 520, pending false, callback
= 0x7f6fa29d42f0 <master_status_error>, context 0x558b21ba35e0, ioloop =
0x558b21ba3740, ctx = 0x0},
  prev = 0x558b21be5cf0, next = 0x558b21ba6020, refcount = 1, fd = 6,
istream = 0x0}

(gdb) p *current_ioloop->io_files->next->next->next
$8 = {io = {condition = IO_READ, source_linenum = 244, pending false, callback =
0x7f6fa2a46540 <signal_read>, context = 0x0, ioloop
= 0x558b21ba3740, ctx = 0x0}, prev = 0x558b21ba6ba0, next = 0x0,
  refcount = 1, fd = 10, istream = 0x0}

(gdb) p *current_ioloop->io_files->next->next->next->next
Cannot access memory at address 0x0


-- 
Ralf Hildebrandt
  Gesch?ftsbereich IT | Abteilung Netzwerk
  Charit? - Universit?tsmedizin Berlin
  Campus Benjamin Franklin
  Hindenburgdamm 30 | D-12203 Berlin
  Tel. +49 30 450 570 155 | Fax: +49 30 450 570 962
  ralf.hildebrandt at charite.de | http://www.charite.de