Hi,
> Am 16.09.2019 um 09:39 schrieb Daniel Miller <dmiller at amfes.com>:
>
> On 9/13/2019 1:21 AM, Fabian via dovecot wrote:
>> Hi,
>> we are trying to add full text search functionality with Solr to our
Doveoct setup. Our Versions:
>> OS: Debian 9
>> Tried versions:
>> - Dovecot 2.2.7 with Solr 3.6
>> - Dovecot 2.3.4 with Solr 8.2
>> (2.2.7 from offical Debian repository, 2.3.4 from backports)
>> Search is working mostly of the time perfrectly smooth. But sometimes
following message appears in mail.err:
>> dovecot:
imap(username)<16189><UxYWLVuSYMasEQoK>: Error:
fts_solr: received invalid uid '0'
>> If this error occurs our webmail frontend delivers most of the time a
timeout. Sometimes the search only takes really long.
>> Are there any ideas why this error occurs? We are not able to
reproduce the error in such a way that it would always be reproducible. However,
we can reproduce the behavior in some form over and over again - but we do not
know exactly what is decisive.
>
> Are you limiting Solr's memory usage? How much available memory is on
your server?
>
> To shortcut the conversation - if you don't have at least 16G of *free*
RAM it's time to upgrade. My own server has 32G installed - I used to have
16G. My own Solr problems basically disappeared after adding RAM. And I only
serve a few users - my own mailstore is the largest as I keep most of my mails.
If you're serving 20+ users you'd probably benefit from doubling to at
least 64G.
>
Thanks for your response! No we are not limiting Soli?s memory usage. After your
tip, we've also upgraded the memory to 32GB. But the behavior remains the
same. I have also already considered that Dovecot may index the UID incorrectly.
But if I search the index directly, I don't find any entries with UID = 0,
so I have no idea where this "fts_solr: received invalid uid
'0"" message might come from.
In our test environment we actually indexed only one user. The user's
mailbox contains about 100.000 mails. This means that there is not really much
data in the index.
Are there any other hints or tips regarding this ?invalid uid ?0?"-message?
Logfile:
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: peer
172.17.10.12:8983: Linked queue http://172.17.10.12:8983 (1 queues linked)
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: queue
http://172.17.10.12:8983: Started new connection to 172.17.10.12:8983
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]:
request [Req1: GET
http://172.17.10.12/solr/dovecot/select?wt=xml&fl=box,uid,score&rows=100000&sort=b$
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]:
Waiting for 1 requests to finish
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: peer
172.17.10.12:8983: Creating 1 new connections to handle requests (already 0
usable, connecting t$
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: peer
172.17.10.12:8983: Making new connection 1 of 1 (0 connections exist, 0 pending)
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: conn
172.17.10.12:8983 [0]: (172.17.10.12:8983): Connecting
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: conn
172.17.10.12:8983 [0]: (172.17.10.12:8983): Waiting for connect (fd=26) to
finish for max 0 msecs
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: conn
172.17.10.12:8983 [0]: HTTP connection created (1 parallel connections exist)
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: conn
172.17.10.12:8983 [0]: (172.17.10.12:8983): Client connected (fd=26)
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: conn
172.17.10.12:8983 [0]: Connected
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: conn
172.17.10.12:8983 [0]: Ready for requests
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: peer
172.17.10.12:8983: Successfully connected (1 connections exist, 0 pending)
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client: peer
172.17.10.12:8983: Successfully connected (1 connections exist, 0 pending)
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: peer
172.17.10.12:8983: Using 1 idle connections to handle 1 requests (1 total
connections ready)
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: queue
http://172.17.10.12:8983: Connection to peer 172.17.10.12:8983 claimed request
[Req1: GET http:$
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: conn
172.17.10.12:8983 [0]: Claimed request [Req1: GET
http://172.17.10.12:8983/solr/dovecot/select?w$
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]:
request [Req1: GET
http://172.17.10.12/solr/dovecot/select?wt=xml&fl=box,uid,score&rows=100000&sort=b$
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: peer
172.17.10.12:8983: No more requests to service for this peer (1 connections
exist, 0 pending)
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: conn
172.17.10.12:8983 [0]: Got 200 response for request [Req1: GET
http://172.17.10.12:8983/solr/dov$
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: conn
172.17.10.12:8983 [0]: Response payload stream destroyed (554 ms after initial
response)
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]:
request [Req1: GET
http://172.17.10.12/solr/dovecot/select?wt=xml&fl=box,uid,score&rows=100000&sort=b$
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: queue
http://172.17.10.12:8983: Dropping request [Req1: GET
http://172.17.10.12:8983/solr/dovecot/sel$
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]:
request [Req1: GET
http://172.17.10.12/solr/dovecot/select?wt=xml&fl=box,uid,score&rows=100000&sort=b$
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: All
requests finished
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: queue
http://172.17.10.12:8983: Using existing connection to 172.17.10.12:8983 (1
requests pending)
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]:
request [Req2: GET
http://172.17.10.12/solr/dovecot/select?wt=xml&fl=box,uid,score&rows=100000&sort=b$
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]:
Waiting for 1 requests to finish
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: peer
172.17.10.12:8983: Using 1 idle connections to handle 1 requests (1 total
connections ready)
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: queue
http://172.17.10.12:8983: Connection to peer 172.17.10.12:8983 claimed request
[Req2: GET http:$
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: conn
172.17.10.12:8983 [0]: Claimed request [Req2: GET
http://172.17.10.12:8983/solr/dovecot/select?w$
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]:
request [Req2: GET
http://172.17.10.12/solr/dovecot/select?wt=xml&fl=box,uid,score&rows=100000&sort=b$
Sep 16 08:35:27 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: peer
172.17.10.12:8983: No more requests to service for this peer (1 connections
exist, 0 pending)
Sep 16 08:35:28 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: conn
172.17.10.12:8983 [0]: Got 200 response for request [Req2: GET
http://172.17.10.12:8983/solr/dov$
Sep 16 08:35:28 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Error: fts_solr: received
invalid uid '0'
Sep 16 08:35:28 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: conn
172.17.10.12:8983 [0]: Response payload stream destroyed (937 ms after initial
response)
Sep 16 08:35:28 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]:
request [Req2: GET
http://172.17.10.12/solr/dovecot/select?wt=xml&fl=box,uid,score&rows=100000&sort=b$
Sep 16 08:35:28 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: queue
http://172.17.10.12:8983: Dropping request [Req2: GET
http://172.17.10.12:8983/solr/dovecot/sel$
Sep 16 08:35:28 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]:
request [Req2: GET
http://172.17.10.12/solr/dovecot/select?wt=xml&fl=box,uid,score&rows=100000&sort=b$
Sep 16 08:35:28 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: http-client[1]: All
requests finished
Sep 16 08:35:29 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: Mailbox INBOX: UID
238: Opened mail because: virtual mailbox Virtual/All: Opened mail UID=370:
search
Sep 16 08:35:29 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: Mailbox INBOX: UID
289: Opened mail because: virtual mailbox Virtual/All: Opened mail UID=390:
search
Sep 16 08:35:29 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: Mailbox INBOX: UID
290: Opened mail because: virtual mailbox Virtual/All: Opened mail UID=391:
search
Sep 16 08:35:29 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: Mailbox INBOX: UID
338: Opened mail because: virtual mailbox Virtual/All: Opened mail UID=419:
search
Sep 16 08:35:29 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: Mailbox INBOX: UID
340: Opened mail because: virtual mailbox Virtual/All: Opened mail UID=420:
search
Sep 16 08:35:29 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: Mailbox INBOX: UID
565: Opened mail because: virtual mailbox Virtual/All: Opened mail UID=723:
search
Sep 16 08:35:29 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: Mailbox INBOX: UID
586: Opened mail because: virtual mailbox Virtual/All: Opened mail UID=763:
search
Sep 16 08:35:29 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: Mailbox INBOX: UID
696: Opened mail because: virtual mailbox Virtual/All: Opened mail UID=999:
search
Sep 16 08:35:29 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: Mailbox INBOX: UID
727: Opened mail because: virtual mailbox Virtual/All: Opened mail UID=1070:
search
Sep 16 08:35:29 mailservertest dovecot:
imap(user01)<30204><+IjNzqWS2s2sEQoK>: Debug: Mailbox INBOX: UID
738: Opened mail because: virtual mailbox Virtual/All: Opened mail UID=1089:
search
Kind regards,
Fabian