fts_solr: Error: fts_solr: received invalid uid '0'
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.
If you need any further information please ask - thanks! :-)
dovecont -n: 2.3.4.1 (f79e8e7e4): /etc/dovecot/dovecot.conf # Pigeonhole version 0.5.4 () # OS: Linux 4.9.0-11-amd64 x86_64 Debian 9.11 ext4 # Hostname: localhost auth_master_user_separator = * auth_username_format = %Ln default_client_limit = 5000 default_process_limit = 1000 default_vsz_limit = 256M dict { sqlquota = mysql:/etc/dovecot/dovecot-dict-sql.conf.ext } disable_plaintext_auth = no first_valid_uid = 480 imap_capability = +XDOVECOT lmtp_save_to_detail_mailbox = yes mail_attribute_dict = file:/var/spool/dovecot/user/%n/Maildir/dovecot-attributes mail_gid = vmail mail_location = maildir:/var/spool/dovecot/user/%d/%n/Maildir:LAYOUT=fs mail_plugins = " listescape mail_log notify quota acl fts fts_solr virtual" mail_privileged_group = vmail mail_uid = vmail managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date index ihave duplicate mime foreverypart extracttext namespace { hidden = yes inbox = yes list = no location = prefix = separator = / subscriptions = yes } namespace { list = yes location = maildir:%%h/Maildir:INDEXPVT=~/shared/%%u:LAYOUT=fs prefix = shared/%%n/ separator = / subscriptions = no type = shared } namespace Public { list = children location = maildir:/var/spool/dovecot/public:INDEXPVT=~/public:LAYOUT=fs prefix = Public/ separator = / subscriptions = no type = public } namespace Virtual { hidden = no list = yes location = virtual:/etc/dovecot/virtual:INDEX=/var/spool/dovecot/user/%u/virtual prefix = Virtual/ separator = / subscriptions = no } namespace inbox { inbox = no location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = INBOX/ separator = / subscriptions = no type = private } passdb { args = /etc/dovecot/masteruser.%s driver = passwd-file master = yes } passdb { args = /etc/dovecot/dovecot-ldap.conf.ext driver = ldap } passdb { args = scheme=CRYPT username_format=%u /etc/dovecot/users driver = passwd-file } plugin { acl = vfile acl_anyone = allow acl_shared_dict = file:/var/spool/dovecot/public/shared-mailboxes.db fts = solr fts_autoindex = yes fts_solr = url=<a href="http://172.17.10.12:8983/solr/dovecot/" rel="noreferrer noopener" target="_blank">172.17.10.12:8983/solr/dovecot/</a> quota = dict:User quota::no-unset:proxy::sqlquota quota_rule = *:storage=10G sieve = file:~/sieve;active=~/.dovecot.sieve sieve_before = /var/spool/dovecot/globalsieve/duplicate.sieve sieve_duplicate_default_period = 1h sieve_duplicate_max_period = 1d } protocols = " imap lmtp sieve pop3" service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0660 user = postfix } } service decode2text { executable = script /usr/lib/dovecot/<a href="http://decode2text.sh" rel="noreferrer noopener" target="_blank">decode2text.sh</a> unix_listener decode2text { mode = 0666 } user = dovecot } service dict { unix_listener dict { group = vmail user = vmail } } service lmtp { unix_listener /var/spool/postfix/private/dovecot-lmtp { group = postfix mode = 0600 user = postfix } } service managesieve-login { inet_listener sieve { port = 4190 } } ssl = no userdb { args = /etc/dovecot/mysql-userdb.conf.ext driver = sql } protocol lmtp { mail_plugins = " listescape mail_log notify quota acl fts fts_solr virtual acl quota sieve notify" quota_full_tempfail = yes } protocol imap { imap_capability = +XDOVECOT mail_max_userip_connections = 100 mail_plugins = " listescape mail_log notify quota acl fts fts_solr virtual imap_acl imap_quota" } remote <a href="http://172.17.10.10" rel="noreferrer noopener" target="_blank">172.17.10.10</a> { protocol imap { imap_metadata = yes } }
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.
-- Daniel
Hi,
Am 16.09.2019 um 09:39 schrieb Daniel Miller dmiller@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
On 9/19/2019 6:28 AM, Fabian via dovecot wrote:
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: Creating 1 new connections to handle requests (already 0 usable, connecting t$
Your post has truncated the lines (right margin). Re-post with the full lines.
-- Daniel
participants (2)
-
Daniel Miller
-
Fabian