dovecot fts hangs on search

André Rodier andre at rodier.me
Fri May 4 01:13:41 EEST 2018 

On 02/05/18 22:17, André Rodier wrote:
> 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.

Hello - again,

I can only find a few explanations for the lack of answers to my questions..

If nobody knows how the dovecot fts code works anymore, it's OK, just 
just tell, so I stop searching what I am doing wrong...

If Dovecot team is planing to push another fts engine, it's OK as well, 
but I need to know...

I am loosing a lot of time on this, and I start to be upset.

To summarise:

- I have a custom script that extract text from attachments, for 
instance doc or pdf files.
- I successfully tested my script on the command line, and it returns 
the right text every time, in a few ms. I use a one page doc or pdf, 
with just a paragraph.
- When using the dovecot search function with the same documents 
attached to an email, I have a timeout, and sometimes an error message.

My dovecot plugin configuration:

>   fts = solr
>   fts_solr = url=http://localhost:8080/solr/
>   fts_decoder = decode2text
>   fts_index_timeout = 10

The script is a non modified version of decode2text provided by the 
Dovecot installation.

Please, just point me in some direction.

André Rodier.

More information about the dovecot mailing list