dovecot - Apr 2019 - Solr connection timeout hardwired to 60s

On 4/4/19 6:47 PM, dovecot-request at dovecot.org wrote:
> For a typical Solr index, 60 seconds is an eternity.  Most people aim
> for query times of 100 milliseconds or less, and they often achieve
> that goal.
I'm pretty sure I get these while indexing, not querying.

Apr 04 16:44:50 host dovecot[114690]: indexer-worker(me at example.com):
Error: fts_solr: Indexing failed: Request timed out (Request queued
66.015 secs ago, 1 attempts in 66.005 secs, 63.146 in http ioloop, 0.000
in other ioloops, connected 94.903 secs ago)

/Peter

On 4/4/19 6:57 PM, Peter Mogensen wrote:
> 
> 
> On 4/4/19 6:47 PM, dovecot-request at dovecot.org wrote:
>> For a typical Solr index, 60 seconds is an eternity.  Most people aim
>> for query times of 100 milliseconds or less, and they often achieve
>> that goal.
> 
> I'm pretty sure I get these while indexing, not querying.
> 
> Apr 04 16:44:50 host dovecot[114690]: indexer-worker(me at example.com):
> Error: fts_solr: Indexing failed: Request timed out (Request queued
> 66.015 secs ago, 1 attempts in 66.005 secs, 63.146 in http ioloop, 0.000
> in other ioloops, connected 94.903 secs ago)
Doing a TCP dump on indexing operations which consistently fail, I see
that there's a lot of softCommits which never get an HTTP answer:

=============================================POST /solr/dovebody/update HTTP/1.1
Host: localhost:8983
Date: Wed, 10 Apr 2019 14:22:29 GMT
Expect: 100-continue
Content-Length: 47
Connection: Keep-Alive
Content-Type: text/xml

HTTP/1.1 100 Continue

<commit softCommit="true" waitSearcher="true"/>
===============================================

... in contrast to the first softCommit on the connection:

===============================================POST /solr/dovebody/update
HTTP/1.1
Host: localhost:8983
Date: Wed, 10 Apr 2019 14:20:53 GMT
Expect: 100-continue
Content-Length: 47
Connection: Keep-Alive
Content-Type: text/xml

HTTP/1.1 100 Continue

<commit softCommit="true"
waitSearcher="true"/>HTTP/1.1 200 OK
Content-Type: application/xml; charset=UTF-8
Content-Length: 156

<?xml version="1.0" encoding="UTF-8"?>
<response>

<lst name="responseHeader">
  <int name="status">0</int>
  <int name="QTime">37</int>
</lst>
</response>
=================================================
The missing softCommit responses seem to start right after the last
added document:
=================================================</field></doc></add>
0

HTTP/1.1 200 OK
Content-Type: application/xml; charset=UTF-8
Content-Length: 156

<?xml version="1.0" encoding="UTF-8"?>
<response>

<lst name="responseHeader">
  <int name="status">0</int>
  <int name="QTime">12</int>
</lst>
</response>
POST /solr/dovebody/update HTTP/1.1
Host: localhost:8983
Date: Wed, 10 Apr 2019 14:22:29 GMT
Expect: 100-continue
Content-Length: 47
Connection: Keep-Alive
Content-Type: text/xml

HTTP/1.1 100 Continue

<commit softCommit="true" waitSearcher="true"/>
==================================================
... and then the rest of the TCP dump doesn't get responses to
softCommit POSTs

/Peter

Looking further at tcpdumps of the Dovecot->Solr traffic and Solr
metrics it doesn't seem like there's anything suspicious apart from the
TCP windows running full and Dovecot backing of ... until it times out
and close the connection.
>From my understanding of how Dovecot operates towards Solr it will flush
~1000 documents towards Solr in /update request until it has traversed
the mailbox (let's say 20.000 mails), doing softCommits after each.

But is it really reasonable for Dovecot to expect that no request will
take more than 60s to process by Solr?
It doesn't seem like my Solr can handle that, although it does process
documents and it does reasonably fast clear pending documents after
Dovecot closes the connection.

On the surface it looks like Dovecot is too impatient.

/Peter

On 4/10/19 6:25 PM, Peter Mogensen wrote:
> 
> 
> On 4/4/19 6:57 PM, Peter Mogensen wrote:
>>
>>
>> On 4/4/19 6:47 PM, dovecot-request at dovecot.org wrote:
>>> For a typical Solr index, 60 seconds is an eternity.  Most people
aim
>>> for query times of 100 milliseconds or less, and they often achieve
>>> that goal.
>>
>> I'm pretty sure I get these while indexing, not querying.
>>
>> Apr 04 16:44:50 host dovecot[114690]: indexer-worker(me at
example.com):
>> Error: fts_solr: Indexing failed: Request timed out (Request queued
>> 66.015 secs ago, 1 attempts in 66.005 secs, 63.146 in http ioloop,
0.000
>> in other ioloops, connected 94.903 secs ago)
> 
> Doing a TCP dump on indexing operations which consistently fail, I see
> that there's a lot of softCommits which never get an HTTP answer:
> 
> =============================================> POST
/solr/dovebody/update HTTP/1.1
> Host: localhost:8983
> Date: Wed, 10 Apr 2019 14:22:29 GMT
> Expect: 100-continue
> Content-Length: 47
> Connection: Keep-Alive
> Content-Type: text/xml
> 
> HTTP/1.1 100 Continue
> 
> <commit softCommit="true" waitSearcher="true"/>
> ===============================================
....