Dovecot core debug

10 Oct 2019


      Hi all,
I have a Dovecot core that I am trying to track down, in an attempt to
replicate so I can log a bug report, and am hoping others might be able to
help me as I’m reaching my limit.
My working theory is that two user sessions are active at the same time,
one of the sessions is “mid-search” (or perhaps in idle state) on a virtual
folder where the number of results is zero (due to a null results array),
when another session either performs an append or perhaps a new message
arrives in the virtual view and qualifies for the search.
It seems that the current list of UID’s in the search results is zero
(null), and new messages are being appended to the search results, which
results in a divide by zero.
But I have not been able to create a scenario to replicate this on my test
box, but is occurring regularly (every hour or so) on my mail server.  I
have been able to replicate on my test box using a single account by
performing many random operations over and over again, with multiple
sessions, but took over 24 hours and I can’t isolate the action that caused
it.
Dovecot version is 2.2.36 (1f10bfa63) as shipped with Centos 7 (latest
update).  If I can reproduce, I can then test the latest 2.3 and see if
this is still a problem in that version.
Here is the full back trace:
#0  0x00007f8d40636e58 in array_count_i (array=0x557be80cc168) at
array.h:155
No locals.
#1  array_get_i (count_r=<synthetic pointer>, array=0x557be80cc168) at
array.h:209
No locals.
#2  seq_range_lookup (array=0x557be80cc168, seq=2222, idx_r=0x7ffead4141d4)
at seq-range-array.c:14
    data = &lt;optimized out>

    idx = &lt;optimized out>

    left_idx = &lt;optimized out>

    right_idx = &lt;optimized out>

    count = &lt;optimized out>
#3  0x00007f8d406379ae in seq_range_exists (array=array@entry=0x557be80cc168,
seq=seq@entry=2222) at seq-range-array.c:391
    idx = 32766
#4  0x00007f8d408fd3d9 in mailbox_search_result_add
(result=result@entry=0x557be80cc150,
uid=2222) at mailbox-search-result.c:121
    __FUNCTION__ = "mailbox_search_result_add"
#5  0x00007f8d40962f30 in index_search_result_update_appends
(result=result@entry=0x557be80cc150, old_messages_count=<optimized out>)
at index-search-result.c:168

    t = 0x557be7fb1820

    search_ctx = 0x557be7fef860

    mail = 0x557be8100198

    search_arg = {next = 0x557be7fab460, type = SEARCH_SEQSET, value =
{subargs = 0x0, seqset = {arr = {buffer = 0x557be7f69208,
            element_size = 8}, v = 0x557be7f69208, v_modifiable =
0x557be7f69208}, str = 0x0, time = 0, size = 0, flags = 0,
        search_flags = (unknown: 0), date_type = 0, thread_type =
MAIL_THREAD_NONE, modseq = 0x0, search_result = 0x0,
        mime_part = 0x0}, initialized = {search_args = 0x0, keywords =
0x0, mailbox_glob = 0x0}, context = 0x0, hdr_field_name = 0x0,
      match_not = 0, match_always = 0, nonmatch_always = 0, fuzzy = 0,
no_fts = 0, result = -1}
    message_count = 2008

    ret = &lt;optimized out>

    __FUNCTION__ = "index_search_result_update_appends"
#6  0x00007f8d4096dc37 in search_result_update (result=0x557be80cc150,
ctx=0x557be7ff8950) at index-sync-search.c:78
No locals.
#7  index_sync_search_results_update (ctx=ctx@entry=0x557be7ff8950) at
index-sync-search.c:88
    results = 0x557be7f9d480

    i = &lt;optimized out>

    count = &lt;optimized out>
#8  0x00007f8d4096e4b4 in index_mailbox_sync_deinit (_ctx=0x557be7ff8950,
status_r=0x557be7ff0108) at index-sync.c:353
    ctx = 0x557be7ff8950

    sync_rec = {seq1 = 0, seq2 = 0, type = MAILBOX_SYNC_TYPE_EXPUNGE}

    delayed_expunges = false

    ret = &lt;optimized out>
#9  0x00007f8d40950400 in mailbox_list_index_sync_deinit
(ctx=0x557be7ff8950, status_r=0x557be7ff0108) at mailbox-list-index.c:976
---Type <return> to continue, or q <return> to quit---
    ibox = 0x557be7fd0bf0

    box = 0x557be7f9d078
#10 0x00007f8d408ed568 in mailbox_sync_deinit (_ctx=<optimized out>,
status_r=<optimized out>) at mail-storage.c:1953
    ctx = &lt;optimized out>

    box = &lt;optimized out>

    errormsg = &lt;optimized out>

    error = MAIL_ERROR_NONE

    ret = &lt;optimized out>
#11 0x0000557be6613431 in imap_sync_finish (ctx=ctx@entry=0x557be7ff0090,
aborting=aborting@entry=false) at imap-sync.c:279
    client = 0x557be7f8a6d8

    ret = 0
#12 0x0000557be6613fed in imap_sync_more (ctx=0x557be7ff0090) at
imap-sync.c:594
    str = &lt;optimized out>

    ret = 1

    __FUNCTION__ = "imap_sync_more"
#13 0x0000557be6614676 in cmd_sync_continue (sync_cmd=0x557be7f8be88) at
imap-sync.c:629
    cmd = 0x557be7f75e40

    prev = &lt;optimized out>

    client = 0x557be7f8a6d8

    ctx = 0x557be7ff0090

    ret = &lt;optimized out>

    __FUNCTION__ = "cmd_sync_continue"
#14 0x0000557be6614b34 in cmd_sync_client (sync_cmd=0x557be7f8be88) at
imap-sync.c:720
    ctx = &lt;optimized out>

    flags = &lt;optimized out>

    client = 0x557be7f8a6d8

    imap_flags = &lt;optimized out>

    no_newmail = &lt;optimized out>
#15 cmd_sync_delayed_real (client=0x557be7f8a6d8) at imap-sync.c:833
    cmd = &lt;optimized out>

    first_expunge = &lt;optimized out>

    first_nonexpunge = &lt;optimized out>
#16 cmd_sync_delayed (client=client@entry=0x557be7f8a6d8) at imap-sync.c:841
    _data_stack_cur_id = 3
#17 0x0000557be6607a18 in client_handle_input
(client=client@entry=0x557be7f8a6d8)
at imap-client.c:1233
    remove_io = &lt;optimized out>

    handled_commands = &lt;optimized out>

    __FUNCTION__ = "client_handle_input"
#18 0x0000557be6607eb5 in client_input (client=0x557be7f8a6d8) at
imap-client.c:1264
---Type <return> to continue, or q <return> to quit---
    cmd = 0xcfee4

    output = 0x557be7f8bd90

    bytes = 2052

    __FUNCTION__ = "client_input"
#19 0x00007f8d40624be2 in io_loop_call_io (io=0x557be7f84cb0) at
ioloop.c:600
    ioloop = 0x557be7f719c0

    t_id = 2

    __FUNCTION__ = "io_loop_call_io"
#20 0x00007f8d406262cf in io_loop_handler_run_internal
(ioloop=ioloop@entry=0x557be7f719c0)
at ioloop-epoll.c:223
    ctx = 0x557be7f734e0

    events = &lt;optimized out>

    list = 0x557be7f74f40

    io = &lt;optimized out>

    tv = {tv_sec = 1795, tv_usec = 114881}

    events_count = &lt;optimized out>

    msecs = &lt;optimized out>

    ret = 1

    i = 0

    call = &lt;optimized out>

    __FUNCTION__ = "io_loop_handler_run_internal"
#21 0x00007f8d40624c7c in io_loop_handler_run
(ioloop=ioloop@entry=0x557be7f719c0)
at ioloop.c:649
No locals.
#22 0x00007f8d40624e38 in io_loop_run (ioloop=0x557be7f719c0) at
ioloop.c:624
    __FUNCTION__ = "io_loop_run"
#23 0x00007f8d405a9c03 in master_service_run (service=0x557be7f71860,
callback=callback@entry=0x557be6614e30 <client_connected>)
at master-service.c:724
No locals.
#24 0x0000557be65fa262 in main (argc=1, argv=0x557be7f715f0) at main.c:484
    set_roots = {0x557be6825700 &lt;imap_setting_parser_info>,
0x7f8d40df95a0, 0x0}
    login_set = {auth_socket_path = 0x557be7f69048 "\001",
postlogin_socket_path = 0x0, postlogin_timeout_secs = 60,
      callback = 0x557be6615600 &lt;login_client_connected>,
failure_callback = 0x557be6614f40 <login_client_failed>,
      request_auth_token = 1}

    service_flags = &lt;optimized out>

    storage_service_flags = &lt;optimized out>

    username = 0x0

    auth_socket_path = &lt;optimized out>

    c = &lt;optimized out>
And the output of array in frame #0:
(gdb) f 0
#0  0x00007f8d40636e58 in array_count_i (array=0x557be80cc168) at
array.h:155
155 return array->buffer->used / array->element_size;
(gdb) p *array
$2 = {buffer = 0x0, element_size = 0}
Here is the virtual folder config in use:
# cat /etc/dovecot/virtual/combined/dovecot-virtual
!INBOX
INBOX/Sent
INBOX/Drafts
all
Any help would be greatly appreciated in diagnosing the cause here.
Thanks,
Dave

MediumDave

tags

participants (1)