Bug: Dovecot index loosing sync with FTS despite "fts_autoindex = yes"

[kadafax at gmail.com]

Le 17/04/2018 à 14:18, kfx a écrit :
> dovecot 2.2.34
> solr 7.2
>
> I only see new messages after typing on the server "doveadm fts rescan
> -u username" though I've followed the wiki and added "fts_autoindex =
> yes" in 90-plugin.conf . Subsequent search for the same pattern always
> gives the same result, ignoring new emails with that particular pattern.
> Solr is working correctly and the correct search results comes
> immediately (whatever the searched word) after a "doveadm fts rescan"
>
> # doveconf | grep fts
> mail_plugins = " quota stats fts fts_solr"
>   fts = solr
>   fts_autoindex = yes
>   fts_solr = url=http://localhost:8983/solr/dovecot/
> [POP]  mail_plugins = " quota stats fts fts_solr sieve virtual"
> [IMAP]  mail_plugins = " quota stats fts fts_solr imap_quota virtual
> imap_stats"
>
>
>
>

Here are some debug logs from a search (responding with incorrect - or
old - results, as new emails have arrived, containing the same
"MySearchPattern" pattern).
This leads me to a problem on the dovecot side. Only a "doveadm fts
rescan -u username" can solve this situation, so should I add a cronjob
for it ? It defeats the purpose of solr as the first search after is
really slow (but correct).

Here are the logs, please tell me if I should provide more info, and
thanks for any help:

Apr 17 21:44:56 imap(MyUsername): Debug: http-client: host localhost:
Host created
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: host localhost:
DNS lookup successful; got 2 IPs
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: peer [::1]:8983:
Peer created
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: queue
http://localhost:8983: Setting up connection to [::1]:8983 (1 requests
pending)
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: peer [::1]:8983:
Linked queue http://localhost:8983 (1 queues linked)
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: queue
http://localhost:8983: Started new connection to [::1]:8983
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: request [Req1: GET
http://localhost:8983/solr/dovecot/select?fl=uid,score&rows=25495&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:MySearchPattern+OR+body:MySearchPattern)&fq=%2Bbox:e09cce0283e8695ab760000002deed92+%2Buser:MyUsername]:
Submitted
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: Waiting for 1
requests to finish
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: peer [::1]:8983:
Creating 1 new connections to handle requests (already 0 usable,
connecting to 0, closing 0)
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: peer [::1]:8983:
Making new connection 1 of 1
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: conn [::1]:8983
[0]: HTTP connection created (1 parallel connections exist)
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: conn [::1]:8983
[0]: Connected
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: conn [::1]:8983
[0]: Ready for requests
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: peer [::1]:8983:
Successfully connected (connections=1)
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: peer [::1]:8983:
Using 1 idle connections to handle 1 requests (1 total connections ready)
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: queue
http://localhost:8983: Connection to peer [::1]:8983 claimed request
[Req1: GET
http://localhost:8983/solr/dovecot/select?fl=uid,score&rows=25495&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:MySearchPattern+OR+body:MySearchPattern)&fq=%2Bbox:e09cce0283e8695ab760000002deed92+%2Buser:MyUsername]
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: conn [::1]:8983
[0]: Claimed request [Req1: GET
http://localhost:8983/solr/dovecot/select?fl=uid,score&rows=25495&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:MySearchPattern+OR+body:MySearchPattern)&fq=%2Bbox:e09cce0283e8695ab760000002deed92+%2Buser:MyUsername]
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: request [Req1: GET
http://localhost:8983/solr/dovecot/select?fl=uid,score&rows=25495&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:MySearchPattern+OR+body:MySearchPattern)&fq=%2Bbox:e09cce0283e8695ab760000002deed92+%2Buser:MyUsername]:
Sent header
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: peer [::1]:8983:
No more requests to service for this peer (1 connections exist)
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: conn [::1]:8983
[0]: Got 200 response for request [Req1: GET
http://localhost:8983/solr/dovecot/select?fl=uid,score&rows=25495&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:MySearchPattern+OR+body:MySearchPattern)&fq=%2Bbox:e09cce0283e8695ab760000002deed92+%2Buser:MyUsername]
(took 109 ms + 23 ms in queue)
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: conn [::1]:8983
[0]: Response payload stream destroyed (0 ms after initial response)
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: request [Req1: GET
http://localhost:8983/solr/dovecot/select?fl=uid,score&rows=25495&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:MySearchPattern+OR+body:MySearchPattern)&fq=%2Bbox:e09cce0283e8695ab760000002deed92+%2Buser:MyUsername]:
Finished
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: queue
http://localhost:8983: Dropping request [Req1: GET
http://localhost:8983/solr/dovecot/select?fl=uid,score&rows=25495&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:MySearchPattern+OR+body:MySearchPattern)&fq=%2Bbox:e09cce0283e8695ab760000002deed92+%2Buser:MyUsername]
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: host localhost:
Host is idle (timeout = 1799867 msecs)
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: request [Req1: GET
http://localhost:8983/solr/dovecot/select?fl=uid,score&rows=25495&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7d(hdr:MySearchPattern+OR+body:MySearchPattern)&fq=%2Bbox:e09cce0283e8695ab760000002deed92+%2Buser:MyUsername]:
Free (requests left=1)
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: All requests finished
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: peer [::1]:8983:
No requests to service for this peer (1 connections exist)
Apr 17 21:44:56 imap(MyUsername): Debug: http-client: conn [::1]:8983
[0]: No more requests queued; going idle (timeout = 5000 msecs)