dovecot fts hangs on search
André Rodier
andre at rodier.me
Thu May 3 00:17:13 EEST 2018
On 02/05/18 11:45, André Rodier wrote:
> On 2018-05-01 21:29, André Rodier wrote:
>> On 2018-05-01 07:22, André Rodier wrote:
>>> Hello,
>>>
>>> I am trying to use Doevecot fts, with solr the script provided.
>>>
>>> To rebuild the index, I use the command:
>>> doveadm -D index -u mirina 'inbox'
>>>
>>> To rescan, I use: doveadm -D fts rescan -u mirina
>>>
>>> But when I do a search, with doveadm, the program hangs:
>>>
>>> doveadm -D search -u mirina text Madagascar
>>>
>>>> Debug: Loading modules from directory: /usr/lib/dovecot/modules
>>>> Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so
>>>> Debug: Module loaded: /usr/lib/dovecot/modules/lib20_fts_plugin.so
>>>> Debug: Module loaded: /usr/lib/dovecot/modules/lib21_fts_solr_plugin.so
>>>> Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm
>>>> Debug: Skipping module doveadm_acl_plugin, because dlopen() failed:
>>>> /usr/lib/dovecot/modules/doveadm/lib10_doveadm_acl_plugin.so:
>>>> undefined symbol: acl_lookup_dict_iterate_visible_next (this is
>>>> usually intentional, so just ignore this message)
>>>> Debug: Skipping module doveadm_expire_plugin, because dlopen()
>>>> failed:
>>>> /usr/lib/dovecot/modules/doveadm/lib10_doveadm_expire_plugin.so:
>>>> undefined symbol: expire_set_deinit (this is usually intentional, so
>>>> just ignore this message)
>>>> Debug: Module loaded:
>>>> /usr/lib/dovecot/modules/doveadm/lib10_doveadm_quota_plugin.so
>>>> Debug: Module loaded:
>>>> /usr/lib/dovecot/modules/doveadm/lib10_doveadm_sieve_plugin.so
>>>> Debug: Skipping module doveadm_fts_lucene_plugin, because dlopen()
>>>> failed:
>>>> /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_lucene_plugin.so:
>>>> undefined symbol: lucene_index_iter_deinit (this is usually
>>>> intentional, so just ignore this m$
>>>> ssage)
>>>> Debug: Module loaded:
>>>> /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_plugin.so
>>>> Debug: Skipping module doveadm_mail_crypt_plugin, because dlopen()
>>>> failed:
>>>> /usr/lib/dovecot/modules/doveadm/libdoveadm_mail_crypt_plugin.so:
>>>> undefined symbol: mail_crypt_box_get_pvt_digests (this is usually
>>>> intentional, so just ignore thi$ message)
>>>> doveadm(mirina): Debug: auth USER input: mirina
>>>> home=/home/users/mirina uid=1002 gid=1001 mail=mirina at homebox.space
>>>> doveadm(mirina): Debug: Added userdb setting:
>>>> mail=mirina at homebox.space doveadm(mirina): Debug: Effective
>>>> uid=1002, gid=1001, home=/home/users/mirina
>>>> doveadm(mirina): Debug: Quota root: name=User quota backend=maildir
>>>> args=
>>>> doveadm(mirina): Debug: Quota rule: root=User quota mailbox=*
>>>> bytes=2147483648 messages=0
>>>> doveadm(mirina): Debug: Quota grace: root=User quota bytes=214748364
>>>> (10%)
>>>> doveadm(mirina): Debug: Namespace inbox: type=private, prefix=,
>>>> sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes
>>>> location=maildir:~/mails/maildir:INDEX=~/mails/indexes/
>>>> doveadm(mirina): Debug: maildir++:
>>>> root=/home/users/mirina/mails/maildir,
>>>> index=/home/users/mirina/mails/indexes, indexpvt=, control=,
>>>> inbox=/home/users/mirina/mails/maildir, alt=
>>>> doveadm(mirina): Debug: quota: quota_over_flag check: STORAGE ret=1
>>>> value=134 limit=2097152
>>>> doveadm(mirina): Debug: quota: quota_over_flag check: MESSAGE ret=0
>>>> value=3 limit=0
>>>> doveadm(mirina): Debug: quota: quota_over_flag=0((null)) vs
>>>> currently overquota=0
>>>> doveadm(mirina): Debug: Namespace : Using permissions from
>>>> /home/users/mirina/mails/maildir: mode=0700 gid=default
>>>> doveadm(mirina): Debug: http-client: host localhost: Host created
>>>> doveadm(mirina): Debug: http-client: host localhost: DNS lookup
>>>> successful; got 2 IPs
>>>> doveadm(mirina): Debug: http-client: peer [::1]:8080: Peer created
>>>> doveadm(mirina): Debug: http-client: queue http://localhost:8080:
>>>> Setting up connection to [::1]:8080 (1 requests pending)
>>>> doveadm(mirina): Debug: http-client: peer [::1]:8080: Linked queue
>>>> http://localhost:8080 (1 queues linked)
>>>> doveadm(mirina): Debug: http-client: queue http://localhost:8080:
>>>> Started new connection to [::1]:8080
>>>> doveadm(mirina): Debug: http-client: request [Req1: GET
>>>> http://localhost:8080/solr/select?fl=uid,score&rows=1&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:Madagascar+OR+body:Madagascar)&fq=%2Bbox:838a1701af1ae65a3e12000032c62018+%2Buser:mi$
>>>>
>>>> ina]: Submitted
>>>> doveadm(mirina): Debug: http-client: Waiting for 1 requests to finish
>>>> doveadm(mirina): Debug: http-client: peer [::1]:8080: Creating 1 new
>>>> connections to handle requests (already 0 usable, connecting to 0,
>>>> closing 0)
>>>> doveadm(mirina): Debug: http-client: peer [::1]:8080: Making new
>>>> connection 1 of 1
>>>> doveadm(mirina): Debug: http-client: conn [::1]:8080 [0]: HTTP
>>>> connection created (1 parallel connections exist)
>>>> doveadm(mirina): Debug: http-client: conn [::1]:8080 [0]: Connected
>>>> doveadm(mirina): Debug: http-client: conn [::1]:8080 [0]: Ready for
>>>> requests
>>>> doveadm(mirina): Debug: http-client: peer [::1]:8080: Successfully
>>>> connected (connections=1)
>>>> doveadm(mirina): Debug: http-client: peer [::1]:8080: Using 1 idle
>>>> connections to handle 1 requests (1 total connections ready)
>>>> doveadm(mirina): Debug: http-client: queue http://localhost:8080:
>>>> Connection to peer [::1]:8080 claimed request [Req1: GET
>>>> http://localhost:8080/solr/select?fl=uid,score&rows=1&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:Madagascar+OR+bod$
>>>>
>>>> :Madagascar)&fq=%2Bbox:838a1701af1ae65a3e12000032c62018+%2Buser:mirina]
>>>> doveadm(mirina): Debug: http-client: conn [::1]:8080 [0]: Claimed
>>>> request [Req1: GET
>>>> http://localhost:8080/solr/select?fl=uid,score&rows=1&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:Madagascar+OR+body:Madagascar)&fq=%2Bbox:838a1701af1ae6$
>>>>
>>>> a3e12000032c62018+%2Buser:mirina]
>>>> [...]
>>>> doveadm(mirina): Debug: http-client: request [Req5: GET
>>>> http://localhost:8080/solr/select?fl=uid,score&rows=1&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:Madagascar+OR+body:Madagascar)&fq=%2Bbox:6dd14d3aae1ae65a3e12000032c62018+%2Buser:mirina]:
>>>> Sent header
>>>> doveadm(mirina): Debug: http-client: peer [::1]:8080: No more
>>>> requests to service for this peer (1 connections exist)
>>>> doveadm(mirina): Debug: http-client: conn [::1]:8080 [0]: Got 200
>>>> response for request [Req5: GET
>>>> http://localhost:8080/solr/select?fl=uid,score&rows=1&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:Madagascar+OR+body:Madagascar)&fq=%2Bbox:6dd14d3aae1ae65a3e12000032c62018+%2Buser:mirina]
>>>> (took 2 ms + 0 ms in queue)
>>>> doveadm(mirina): Debug: http-client: conn [::1]:8080 [0]: Response
>>>> payload stream destroyed (0 ms after initial response)
>>>> doveadm(mirina): Debug: http-client: request [Req5: GET
>>>> http://localhost:8080/solr/select?fl=uid,score&rows=1&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:Madagascar+OR+body:Madagascar)&fq=%2Bbox:6dd14d3aae1ae65a3e12000032c62018+%2Buser:mirina]:
>>>> Finished
>>>> doveadm(mirina): Debug: http-client: queue http://localhost:8080:
>>>> Dropping request [Req5: GET
>>>> http://localhost:8080/solr/select?fl=uid,score&rows=1&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:Madagascar+OR+body:Madagascar)&fq=%2Bbox:6dd14d3aae1ae65a3e12000032c62018+%2Buser:mirina]
>>>>
>>>> doveadm(mirina): Debug: http-client: host localhost: Host is idle
>>>> (timeout = 1799974 msecs)
>>>> doveadm(mirina): Debug: http-client: request [Req5: GET
>>>> http://localhost:8080/solr/select?fl=uid,score&rows=1&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:Madagascar+OR+body:Madagascar)&fq=%2Bbox:6dd14d3aae1ae65a3e12000032c62018+%2Buser:mirina]:
>>>> Free (requests left=1)
>>>> doveadm(mirina): Debug: http-client: All requests finished
>>>
>>> When I do the search with an imap client, I have this error after a
>>> long timeout:
>>>
>>>> May 01 07:08:58 homebox dovecot[5683]: imap(mirina): Panic: file
>>>> imap-client.c: line 854 (client_check_command_hangs): assertion
>>>> failed: (client->io != NULL || (client->output_cmd_lock != NULL &&
>>>> client->output_cmd_lock != client->input_lock))
>>>> May 01 07:08:58 homebox dovecot[5683]: imap(mirina): Error: Raw
>>>> backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x95e92)
>>>> [0x7f216b6f6e92] -> /usr/lib/dovecot/libdovecot.so.0(+0x95f8d)
>>>> [0x7f216b6f6f8d] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0)
>>>> [0x7f216b68ca91] ->
>>>> dovecot/imap(client_continue_pending_input+0x1fc) [0x55f44a7eb15c]
>>>> -> dovecot/imap(client_input+0x120) [0x55f44a7eb460] ->
>>>> /usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x52)
>>>> [0x7f216b70b9f2] ->
>>>> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x109)
>>>> [0x7f216b70d029] ->
>>>> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x3c)
>>>> [0x7f216b70ba8c] ->
>>>> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7f216b70bc38]
>>>> -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13)
>>>> [0x7f216b692fd3] -> dovecot/imap(main+0x328) [0x55f44a7dde68] ->
>>>> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1)
>>>> [0x7f216b2e22e1] -> dovecot/imap(_start+0x2a) [0x55f44a7ddfea]
>>>> May 01 07:08:58 homebox dovecot[5683]: imap(mirina): Fatal: master:
>>>> service(imap): child 6149 killed with signal 6 (core dumps disabled)
>>>> May 01 07:08:58 homebox in.imapproxyd[20305]: Raw_Proxy(): IMAP
>>>> server unexpectedly closed the connection on sd 11
>>>
>>> My 10-master.conf:
>>>
>>> service decode2text {
>>> executable = script /usr/local/bin/decode2text.sh
>>> user = dovecot
>>> unix_listener decode2text {
>>> mode = 0666
>>> }
>>> }
>>>
>>> And my 90-plugins.cof:
>>> # Add dovecot fts config
>>> fts = solr
>>> fts_autoindex = no
>>> fts_solr = url=http://localhost:8080/solr/ debug
>>> fts_decoder = decode2text
>>>
>>> Am I doing anything wrong?
>>>
>>> Thanks for your help.
>>>
>>> André
>>
>> hello again,
>>
>> The issue is not solved, but I have been able to see an error message:
>> indexer-worker(andre): Error: parser script didn't send any data
>>
>> This is weird, because 1) this error is intermittent, 2) I explicitly
>> modified the script to echo a specific word in al the cases.
>>
>> Any idea, someone?
>>
>> Thanks
>
> Hello again,
>
> I am still having this issue.
>
> The inbox I am testing has only three emails, with three attachments.
> The same document in doc, pdf and odt...
>
> Thanks for your help and advice, if you have any.
>
> Kind regards,
> André
Hello again, I really hope to find some Dovecot support on this list.
On Debian stretch, I have tried versions from stable (2.2.27-3+deb9u2)
and from the backports (2.2.34-2~bpo9+1)
None of the version works. The operation doveadm search, or by imap is
frozen...Even if I use the exact script provided by Dovecot decode2txt.sh.
Any idea from the Dovecot core team would be nice.
Thanks.
André Rodier.
More information about the dovecot
mailing list