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
at master-service.c:724No 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
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