dovecot fts hangs on search
André Rodier
andre at rodier.me
Tue May 1 23:29:54 EEST 2018
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
More information about the dovecot
mailing list