Il 31/05/21 21:00, Aki Tuomi ha scritto:

      
On 31/05/2021 21:58 Alessio Cecchi <alessio@skye.it> wrote:

 
Il 31/05/21 18:17, Aki Tuomi ha scritto:

On 31/05/2021 19:09 Alessio Cecchi <alessio@skye.it> wrote:


Hi,
I have setup on a (little busy) Dovecot server FTS with Solr and Virtual folder to enable "search in all folders" for users.
  
  All works fine until for some users the indexer-worker process crash.
After this crash Dovecot stop to query Solr for new search in BODY, returning SERVERBUG, for all users on the server and only with a dovecot restart users can search in BODY again.
Before the dovecot restart I can see that on Solr server no query from dovecot arriving anymore (for SEARCH BODY because SEARCH in FROM/TO/SUBJECT still works fine)
  
Hi!

It's a known bug and will be fixed in next release. It happens with tika and solr being used together.

Aki
Good to know, I'm not using tika but decode2text, is the same?

Hm. Not necessarely. It could be something related to some other http connection though. The fix done should help in any case.

Aki

Hi,

I'm not sure if can help but I have collect the core dump also for this crash. I notice that happens only when indexing Virtual mailbox folder, example:

- doveadm index -u user4@email.com '*' works fine

- doveadm index -u user4@email.com 'Virtual/All' crash

If I run first the index on '*' and after on 'Virtual/All' works fine for both. But when users from webmail search in all folders via Virtual/All always crash and after no more indexer-worker run until I reload dovecot or kill "indexer" process.

Here the core dump:

Jun 03 05:05:34 Panic: indexer-worker(user4@email.com) session=<x0EZ2dPDiuW5Ydlx:pQBBH/tGuGDjBwAAxbYlJw>: file http-client-request.c: line 1240 (http_client_request_send_more): assertion failed: (req->payload_input != NULL)
Jun 03 05:05:34 Error: indexer-worker(user4@email.com) session=<x0EZ2dPDiuW5Ydlx:pQBBH/tGuGDjBwAAxbYlJw>: Raw backtrace: /usr/lib64/dovecot/libdovecot.so.0(backtrace_append+0x42) [0x7f5d132cbac2] -> /usr/lib64/dovecot/libdovecot.so.0(backtrace_get+0x1e) [0x7f5d132cbbce] -> /usr/lib64/dovecot/libdovecot.so.0(+0xf3cde) [0x7f5d132d8cde] -> /usr/lib64/dovecot/libdovecot.so.0(+0xf3d81) [0x7f5d132d8d81] -> /usr/lib64/dovecot/libdovecot.so.0(i_fatal+0) [0x7f5d1322a25a] -> /usr/lib64/dovecot/libdovecot.so.0(http_client_request_send_more+0x3dd) [0x7f5d132729ad] -> /usr/lib64/dovecot/libdovecot.so.0(http_client_connection_output+0xf1) [0x7f5d13277101] -> /usr/lib64/dovecot/libdovecot.so.0(+0x11d2b0) [0x7f5d133022b0] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_call_io+0x65) [0x7f5d132f0f45] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x12b) [0x7f5d132f28fb] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run+0x59) [0x7f5d132f1049] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7f5d132f1288] -> /usr/lib64/dovecot/libdovecot.so.0(http_client_wait+0xcd) [0x7f5d1328020d] -> /usr/lib64/dovecot/lib21_fts_solr_plugin.so(solr_connection_select+0xe4) [0x7f5d11440174] -> /usr/lib64/dovecot/lib21_fts_solr_plugin.so(+0x45d4) [0x7f5d1143c5d4] -> /usr/lib64/dovecot/lib20_fts_plugin.so(fts_backend_get_last_uid+0x6e) [0x7f5d125af3fe] -> /usr/lib64/dovecot/lib20_fts_plugin.so(+0xf952) [0x7f5d125b5952] -> /usr/lib64/dovecot/lib20_fts_plugin.so(+0x10ef6) [0x7f5d125b6ef6] -> /usr/lib64/dovecot/lib20_virtual_plugin.so(+0x966a) [0x7f5d1239b66a] -> /usr/lib64/dovecot/lib20_fts_plugin.so(+0x10ba6) [0x7f5d125b6ba6] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_precache+0x2e) [0x7f5d135dbb0e] -> dovecot/indexer-worker [user4@email.com Virtual/All](+0x2924) [0x561e504cb924] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_call_io+0x65) [0x7f5d132f0f45] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x12b) [0x7f5d132f28fb] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run+0x59) [0x7f5d132f1049] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7f5d132f1288] -> /usr/lib64/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7f5d1325bbb3] -> dovecot/indexer-worker [user4@email.com Virtual/All](main+0xd7) [0x561e504cb1f7] -> /lib64/libc.so.6(__libc_start_main+0xf5) [0x7f5d12e39555] -> dovecot/indexer-worker [user4@email.com Virtual/All](+0x22ba) [0x561e504cb2ba]
Jun 03 05:05:34 Fatal: indexer-worker(user4@email.com) session=<x0EZ2dPDiuW5Ydlx:pQBBH/tGuGDjBwAAxbYlJw>: master: service(indexer-worker): child 2019 killed with signal 6 (core dumped)


[root@popimap ~]# gdb /usr/libexec/dovecot/indexer-worker /var/core/core.indexer-worker.2019
GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-120.el7
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/libexec/dovecot/indexer-worker...Reading symbols from /usr/lib/debug/usr/libexec/dovecot/indexer-worker.debug...done.
done.
[New LWP 2019]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `dovecot/indexer-worker'.
Program terminated with signal 6, Aborted.
#0  0x00007f5d12e4d387 in raise () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install bzip2-libs-1.0.6-13.el7.x86_64 expat-2.1.0-12.el7.x86_64 glibc-2.17-324.el7_9.x86_64 libgcc-4.8.5-44.el7.x86_64 libzstd-1.4.9-1.el7.x86_64 xz-libs-5.2.2-1.el7.x86_64 zlib-1.2.7-19.el7_9.x86_64
(gdb) bt full
#0  0x00007f5d12e4d387 in raise () from /lib64/libc.so.6
No symbol table info available.
#1  0x00007f5d12e4ea78 in abort () from /lib64/libc.so.6
No symbol table info available.
#2  0x00007f5d132d8c97 in default_fatal_finish (status=0, type=<optimized out>) at failures.c:459
        backtrace = 0x561e523ecab8 "/usr/lib64/dovecot/libdovecot.so.0(backtrace_append+0x42) [0x7f5d132cbac2] -> /usr/lib64/dovecot/libdovecot.so.0(backtrace_get+0x1e) [0x7f5d132cbbce] -> /usr/lib64/dovecot/libdovecot.so.0(+0xf3cde) [0"...
        recursed = 0
#3  fatal_handler_real (ctx=<optimized out>, format=<optimized out>, args=<optimized out>) at failures.c:471
        status = 0
#4  0x00007f5d132d8d81 in i_internal_fatal_handler (ctx=<optimized out>, format=<optimized out>, args=<optimized out>)
    at failures.c:866
No locals.
#5  0x00007f5d1322a25a in i_panic (format=format@entry=0x7f5d1331a730 "file %s: line %d (%s): assertion failed: (%s)")
    at failures.c:523
        ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0, timestamp_usecs = 0, log_prefix = 0x0,
          log_prefix_type_pos = 0}
        args = {{gp_offset = 40, fp_offset = 48, overflow_arg_area = 0x7ffdccb024d0, reg_save_area = 0x7ffdccb02410}}
#6  0x00007f5d132729ad in http_client_request_send_more (req=req@entry=0x561e524c2a68, pipelined=pipelined@entry=false)
    at http-client-request.c:1240
        conn = 0x561e524aa5f0
        cctx = 0x561e52427fa8
        output = 0x561e524abf60
        res = <optimized out>
        error = <optimized out>
        offset = <optimized out>
        __func__ = "http_client_request_send_more"
#7  0x00007f5d13277101 in http_client_connection_continue_request (conn=0x561e524aa5f0) at http-client-connection.c:1342
        tmp_conn = 0x561e524aa5f0
        count = 1
        ret = <optimized out>
        reqs = <optimized out>
        req = 0x561e524c2a68
        pipelined = false
#8  http_client_connection_output (conn=0x561e524aa5f0) at http-client-connection.c:1374
        output = <optimized out>
        ret = <optimized out>
#9  0x00007f5d133022b0 in stream_send_io (fstream=0x561e524ab320) at ostream-file.c:520
        ostream = 0x561e524ab3c0
        iostream = 0x561e524ab320
        use_cork = true
        ret = <optimized out>
---Type <return> to continue, or q <return> to quit---
#10 0x00007f5d132f0f45 in io_loop_call_io (io=0x561e524a4fb0) at ioloop.c:714
        ioloop = 0x561e524c2840
        t_id = 6
        __func__ = "io_loop_call_io"
#11 0x00007f5d132f28fb in io_loop_handler_run_internal (ioloop=ioloop@entry=0x561e524c2840) at ioloop-epoll.c:222
        ctx = 0x561e524a4f80
        events = <optimized out>
        list = 0x561e524ae350
        io = <optimized out>
        tv = {tv_sec = 0, tv_usec = 0}
        events_count = <optimized out>
        msecs = <optimized out>
        ret = 1
        i = 0
        call = <optimized out>
        __func__ = "io_loop_handler_run_internal"
#12 0x00007f5d132f1049 in io_loop_handler_run (ioloop=ioloop@entry=0x561e524c2840) at ioloop.c:766
        __func__ = "io_loop_handler_run"
#13 0x00007f5d132f1288 in io_loop_run (ioloop=0x561e524c2840) at ioloop.c:739
        __func__ = "io_loop_run"
#14 0x00007f5d1328020d in http_client_wait (client=0x561e52425f98) at http-client.c:339
        prev_ioloop = 0x561e523f0ff0
        client_ioloop = 0x561e524c2840
        prev_client_ioloop = 0x561e523f0ff0
        __func__ = "http_client_wait"
#15 0x00007f5d11440174 in solr_connection_select (conn=0x561e52425ed0, query=<optimized out>, pool=<optimized out>,
    box_results_r=0x7ffdccb02780) at solr-connection.c:206
        lctx = {result_pool = 0x561e5249dba0, payload = 0x0, io = 0x0, request_status = 0, parser = 0x0, results = 0x0}
        http_req = 0x561e5249dfd8
        url = <optimized out>
#16 0x00007f5d1143c5d4 in fts_backend_solr_get_last_uid (_backend=0x561e52425e10, box=0x561e52452538, last_uid_r=0x7ffdccb02824)
    at fts-backend-solr.c:237
        hdr = {last_indexed_uid = 0, settings_checksum = 0, unused = 0}
#17 0x00007f5d125af3fe in fts_backend_get_last_uid (backend=<optimized out>, box=box@entry=0x561e52452538,
    last_uid_r=last_uid_r@entry=0x7ffdccb02824) at fts-api.c:106
        hdr = {last_indexed_uid = 3434097176, settings_checksum = 32765, unused = 325539906}
#18 0x00007f5d125b5952 in fts_mailbox_get_last_cached_seq (box=box@entry=0x561e52452538, seq_r=seq_r@entry=0x7ffdccb02874)
    at fts-storage.c:85
        flist = <optimized out>
        seq1 = 22046
        seq2 = 1380210400
        last_uid = 22046
---Type <return> to continue, or q <return> to quit---
#19 0x00007f5d125b6ef6 in fts_mail_precache_init (_mail=<optimized out>, _mail=<optimized out>) at fts-storage.c:486
        ft = 0x561e52499650
        flist = 0x561e5241e928
        last_seq = 22046
#20 fts_mail_index (_mail=0x561e524ad188) at fts-storage.c:507
        ft = 0x561e52499650
        flist = 0x561e5241e928
        pmail = 0x561e524ad188
#21 fts_mail_precache (_mail=0x561e524ad188) at fts-storage.c:571
        _data_stack_cur_id = 5
        mail = 0x561e524ad188
        fmail = <optimized out>
        ft = 0x561e52499650
        __func__ = "fts_mail_precache"
#22 0x00007f5d1239b66a in virtual_mail_precache (mail=<optimized out>) at virtual-mail.c:265
        vmail = <optimized out>
        backend_mail = 0x561e524ad188
        p = <optimized out>
#23 0x00007f5d125b6ba6 in fts_mail_precache (_mail=0x561e5248e0e8) at fts-storage.c:564
        mail = 0x561e5248e0e8
        fmail = 0x561e5248e650
        ft = 0x561e52458670
        __func__ = "fts_mail_precache"
#24 0x00007f5d135dbb0e in mail_precache (mail=0x561e5248e0e8) at mail.c:453
        _data_stack_cur_id = 4
        p = 0x561e5248e0e8
#25 0x0000561e504cb924 in index_mailbox_precache (conn=<optimized out>, box=0x561e52435a18) at master-connection.c:104
        counter = 1
        max = 172
        percentage_sent = 0
        storage = <optimized out>
        status = {messages = 172, recent = 0, unseen = 0, uidvalidity = 1622689531, uidnext = 173, first_unseen_seq = 0,
          first_recent_uid = 173, last_cached_seq = 0, highest_modseq = 0, highest_pvt_modseq = 0, keywords = 0x0,
          permanent_flags = 0, flags = 0, permanent_keywords = false, allow_new_keywords = false, nonpermanent_modseqs = false,
          no_modseq_tracking = false, have_guids = true, have_save_guids = true, have_only_guid128 = false}
        uids = <optimized out>
        username = 0x561e524158c8 "user4@email.com"
        first_uid = 1
        percentage_str = "0\000\000"
        percentage = <optimized out>
        error = 1379909712
        trans = 0x561e524641a0
---Type <return> to continue, or q <return> to quit---
        ctx = 0x561e52434ee0
        last_uid = 2
        ret = 0
        box_vname = 0x561e52435db0 "Virtual/All"
        errstr = <optimized out>
        search_args = 0x0
        mail = 0x561e5248e0e8
        metadata = {guid = '\000' <repeats 15 times>, virtual_size = 0, physical_size = 0, first_save_date = 0,
          cache_fields = 0x0,
          precache_fields = (MAIL_FETCH_STREAM_HEADER | MAIL_FETCH_STREAM_BODY | MAIL_FETCH_RECEIVED_DATE | MAIL_FETCH_SAVE_DATE | MAIL_FETCH_PHYSICAL_SIZE | MAIL_FETCH_VIRTUAL_SIZE | MAIL_FETCH_UIDL_BACKEND | MAIL_FETCH_GUID | MAIL_FETCH_POP3_ORDER),
          backend_ns_prefix = 0x0, backend_ns_type = (unknown: 0)}
        seq = <optimized out>
#26 index_mailbox (user=<optimized out>, user=<optimized out>, what=<optimized out>, max_recent_msgs=<optimized out>,
    mailbox=<optimized out>, conn=0x561e523fc070) at master-connection.c:207
        box = 0x561e52435a18
        status = {messages = 0, recent = 0, unseen = 733118976, uidvalidity = 3265295405, uidnext = 3434097280,
          first_unseen_seq = 32765, first_recent_uid = 1, last_cached_seq = 0, highest_modseq = 94688228871760,
          highest_pvt_modseq = 140037729927678, keywords = 0x7ffdccb02a80, permanent_flags = 1379864144, flags = 22046,
          permanent_keywords = false, allow_new_keywords = false, nonpermanent_modseqs = false, no_modseq_tracking = false,
          have_guids = true, have_save_guids = false, have_only_guid128 = true}
        errstr = <optimized out>
        ret = 0
        ns = <optimized out>
        path = 0x561e523eb6d0 "/home/vmail/nas10/domains/R/email.com/user4/Maildir/virtual/All"
        error = 172
        sync_flags = <optimized out>
#27 master_connection_input_line (line=<optimized out>, conn=0x561e523fc070) at master-connection.c:249
        str = <optimized out>
        max_recent_msgs = 0
        ret = <optimized out>
        args = <optimized out>
        input = {parent_event = 0x0, module = 0x561e504cbfff "mail", service = 0x561e504cbff0 "indexer-worker",
          username = 0x561e523e8038 "user4@email.com", session_id = 0x0,
          session_id_prefix = 0x561e523e805b "x0EZ2dPDiuW5Ydlx", session_create_time = 0, local_ip = {family = 0, u = {ip6 = {
                __in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0,
                    0}}}, ip4 = {s_addr = 0}}}, remote_ip = {family = 0, u = {ip6 = {__in6_u = {
                  __u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}},
              ip4 = {s_addr = 0}}}, local_port = 0, remote_port = 0, userdb_fields = 0x0, forward_fields = 0x0,
          flags_override_add = (unknown: 0), flags_override_remove = (unknown: 0), no_userdb_lookup = false, debug = false,
          conn_secured = false, conn_ssl_secured = false}
        service_user = 0x561e523ffe30
---Type <return> to continue, or q <return> to quit---
        user = 0x561e524157a8
        error = 0x0
#28 master_connection_input (conn=0x561e523fc070) at master-connection.c:289
        _data_stack_cur_id = 3
        line = <optimized out>
#29 0x00007f5d132f0f45 in io_loop_call_io (io=0x561e523fc0b0) at ioloop.c:714
        ioloop = 0x561e523f0ff0
        t_id = 2
        __func__ = "io_loop_call_io"
#30 0x00007f5d132f28fb in io_loop_handler_run_internal (ioloop=ioloop@entry=0x561e523f0ff0) at ioloop-epoll.c:222
        ctx = 0x561e523f1c30
        events = <optimized out>
        list = 0x561e523fc110
        io = <optimized out>
        tv = {tv_sec = 2147483, tv_usec = 0}
        events_count = <optimized out>
        msecs = <optimized out>
        ret = 1
        i = 0
        call = <optimized out>
        __func__ = "io_loop_handler_run_internal"
#31 0x00007f5d132f1049 in io_loop_handler_run (ioloop=ioloop@entry=0x561e523f0ff0) at ioloop.c:766
        __func__ = "io_loop_handler_run"
#32 0x00007f5d132f1288 in io_loop_run (ioloop=0x561e523f0ff0) at ioloop.c:739
        __func__ = "io_loop_run"
#33 0x00007f5d1325bbb3 in master_service_run (service=0x561e523f0e50, callback=callback@entry=0x561e504cb3b0 <client_connected>)
    at master-service.c:853
No locals.
#34 0x0000561e504cb1f7 in main (argc=1, argv=0x561e523f0b90) at indexer-worker.c:76
        storage_service_flags = (MAIL_STORAGE_SERVICE_FLAG_USERDB_LOOKUP | MAIL_STORAGE_SERVICE_FLAG_TEMP_PRIV_DROP | MAIL_STORAGE_SERVICE_FLAG_NO_IDLE_TIMEOUT)
        c = <optimized out>
(gdb) exit

I hope can help to fix it.

Thanks

-- 
Alessio Cecchi
Postmaster @ http://www.qboxmail.it
https://www.linkedin.com/in/alessice