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 = <optimized out>

        idx = <optimized out>

        left_idx = <optimized out>

        right_idx = <optimized out>

        count = <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 = <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 = <optimized out>

        count = <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 = <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 = <optimized out>

        box = <optimized out>

        errormsg = <optimized out>

        error = MAIL_ERROR_NONE

        ret = <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 = <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 = <optimized out>

        client = 0x557be7f8a6d8

        ctx = 0x557be7ff0090

        ret = <optimized out>

        __FUNCTION__ = "cmd_sync_continue"

#14 0x0000557be6614b34 in cmd_sync_client (sync_cmd=0x557be7f8be88) at imap-sync.c:720

        ctx = <optimized out>

        flags = <optimized out>

        client = 0x557be7f8a6d8

        imap_flags = <optimized out>

        no_newmail = <optimized out>

#15 cmd_sync_delayed_real (client=0x557be7f8a6d8) at imap-sync.c:833

        cmd = <optimized out>

        first_expunge = <optimized out>

        first_nonexpunge = <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 = <optimized out>

        handled_commands = <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 = <optimized out>

        list = 0x557be7f74f40

        io = <optimized out>

        tv = {tv_sec = 1795, tv_usec = 114881}

        events_count = <optimized out>

        msecs = <optimized out>

        ret = 1

        i = 0

        call = <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 <imap_setting_parser_info>, 0x7f8d40df95a0, 0x0}

        login_set = {auth_socket_path = 0x557be7f69048 "\001", postlogin_socket_path = 0x0, postlogin_timeout_secs = 60, 

          callback = 0x557be6615600 <login_client_connected>, failure_callback = 0x557be6614f40 <login_client_failed>, 

          request_auth_token = 1}

        service_flags = <optimized out>

        storage_service_flags = <optimized out>

        username = 0x0

        auth_socket_path = <optimized out>

        c = <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