Assert failure in 2.2.20: imap-fetch.c:554 (ctx->client->output_cmd_lock || ctx->client->output_cmd_lock == cmd)

[Peter Eriksson]

Just got another core-dump from Dovecot's imap process on our mail server.

Dovecot 2.2.20
Solaris 10 / x86
Maildir


Output from syslog:

Dec 14 10:58:12 mail dovecot: [ID 583609 mail.crit] imap(oling): Panic: file imap-fetch.c: line 554: assertion failed: (ctx->client->output_cmd_lock == NULL || ctx->client->output_cmd_lock == cmd)
Dec 14 10:58:15 mail dovecot: [ID 583609 mail.crit] imap(oling): Fatal: master: service(imap): child 2167 killed with signal 6 (core dumped)


Checked the users' Maildir for files modified around this time and found:

-rw-------   1 oling    root       15743 Dec 14 10:54 .Deleted Messages/cur/1450099463.M318113P13582.mail,S=15743,W=16026:2,RSbcd

Don't know if it's related though.



Data from the core-dump / debugger:

# /pkg/studio/default/bin/dbx /ifm/pkg/dovecot/default/libexec/dovecot/imap imap.2167.306
...
program terminated by signal ABRT (Abort)
0xfffffd7ffeb81eca: __lwp_kill+0x000a:  jae      __lwp_kill+0x18        [ 0xfffffd7ffeb81ed8, .+0xe ]
Current function is default_fatal_finish
  201                   abort();
  
(dbx) where                                                                  
  [1] __lwp_kill(0x1, 0x6, 0xfffffe88d2948e40, 0xfffffd7ffeb827be, 0x4552555443, 0x0), at 0xfffffd7ffeb81eca 
  [2] _thr_kill(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7ffeb7a7d3 
  [3] raise(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7ffeb26fe9 
  [4] abort(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7ffeb05f60 
=>[5] default_fatal_finish(type = LOG_TYPE_PANIC, status = 0), line 201 in "failures.c"
  [6] i_internal_fatal_handler(ctx = 0xfffffd7fffdff858, format = 0x492df0 "file %s: line %d: assertion failed: (%s)", args = 0xfffffd7fffdff840), line 670 in "failures.c"
  [7] i_panic(format = 0x492df0 "file %s: line %d: assertion failed: (%s)", ... = 0x467f4f, ...), line 275 in "failures.c"
  [8] imap_fetch_more(ctx = 0x736b00, cmd = 0x7369a8), line 554 in "imap-fetch.c"
  [9] cmd_fetch(cmd = 0x7369a8), line 297 in "cmd-fetch.c"
  [10] command_exec(cmd = 0x7369a8), line 172 in "imap-commands.c"
  [11] client_command_input(cmd = 0x7369a8), line 948 in "imap-client.c"
  [12] client_command_input(cmd = 0x7369a8), line 1008 in "imap-client.c"
  [13] client_handle_next_command(client = 0x4d16c0, remove_io_r = 0xfffffd7fffdffa7d), line 1022 in "imap-client.c"
  [14] client_handle_input(client = 0x4d16c0), line 1058 in "imap-client.c"
  [15] client_input(client = 0x4d16c0), line 1105 in "imap-client.c"
  [16] io_loop_call_io(io = 0x5bab00), line 559 in "ioloop.c"
  [17] io_loop_handler_run_internal(ioloop = 0x4b2580), line 211 in "ioloop-poll.c"
  [18] io_loop_handler_run(ioloop = 0x4b2580), line 607 in "ioloop.c"
  [19] io_loop_run(ioloop = 0x4b2580), line 583 in "ioloop.c"
  [20] master_service_run(service = 0x4b2450, callback = 0x482690 = &`imap`main.c`client_connected(struct master_service_connection *conn)), line 640 in "master-service.c"
  [21] main(argc = 1, argv = 0xfffffd7fffdffcb8), line 442 in "main.c"

(dbx) print cmd                            
cmd = 0x7369a8

(dbx) print ctx->client->output_cmd_lock   
ctx->client->output_cmd_lock = 0x72e0f8

(dbx) print *cmd
*cmd = {
    prev                    = (nil)
    next                    = 0x72e0f8
    client                  = 0x4d16c0
    pool                    = 0x4d1eb0
    tag                     = 0x736ac0 "150.11"
    name                    = 0x736ac8 "UID FETCH"
    args                    = 0x736ad8 "12663:12665 (BODY.PEEK[] BODYSTRUCTURE)"
    cmd_flags               = COMMAND_FLAG_BREAKS_SEQS
    func                    = 0x437220 = &cmd_fetch(struct client_command_context *cmd)
    context                 = (nil)
    module_contexts         = {
        arr          = {
            buffer       = 0x736a58
            element_size = 8U
        }
        v            = 0x736a58
        v_modifiable = 0x736a58
    }
    parser                  = 0x4d3d40
    state                   = CLIENT_COMMAND_STATE_WAIT_INPUT
    start_time              = {
        tv_sec  = 1450087092
        tv_usec = 924042
    }
    start_ioloop_wait_usecs = 119688401U
    running_usecs           = 0
    bytes_in                = 0
    bytes_out               = 0
    sync                    = (nil)
    uid                     = 1U
    cancel                  = 0
    param_error             = 0
    search_save_result      = 0
    search_save_result_used = 0
    temp_executed           = 0
    tagline_sent            = 0
}


(dbx) print *(ctx->client->output_cmd_lock)
*ctx->client->output_cmd_lock = {
    prev                    = 0x7369a8
    next                    = 0x72d8c8
    client                  = 0x4d16c0
    pool                    = 0x4d1eb0
    tag                     = 0x72e208 "149.11"
    name                    = 0x72e210 "UID FETCH"
    args                    = 0x72e220 "12666 (BODY.PEEK[] BODYSTRUCTURE)"
    cmd_flags               = COMMAND_FLAG_BREAKS_SEQS
    func                    = 0x4371b0 = &`imap`cmd-fetch.c`cmd_fetch_continue(struct client_command_context *cmd)
    context                 = 0x72e248
    module_contexts         = {
        arr          = {
            buffer       = 0x72e1a8
            element_size = 8U
        }
        v            = 0x72e1a8
        v_modifiable = 0x72e1a8
    }
    parser                  = 0x5bb410
    state                   = CLIENT_COMMAND_STATE_WAIT_OUTPUT
    start_time              = {
        tv_sec  = 1450087092
        tv_usec = 923420
    }
    start_ioloop_wait_usecs = 119688382U
    running_usecs           = 538U
    bytes_in                = 33U
    bytes_out               = 32994U
    sync                    = (nil)
    uid                     = 1U
    cancel                  = 0
    param_error             = 0
    search_save_result      = 0
    search_save_result_used = 0
    temp_executed           = 1U
    tagline_sent            = 0
}


-- 
[Ll.U] Peter Eriksson KITVS-IFM & ITI-NET IT.LiU.SE +46-70 518 2786