fts_solr: Error: fts_solr: received invalid uid '0'

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
11 messages Options
Reply | Threaded
Open this post in threaded view
|

fts_solr: Error: fts_solr: received invalid uid '0'

Dovecot mailing list
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
  }
}


Reply | Threaded
Open this post in threaded view
|

Re: fts_solr: Error: fts_solr: received invalid uid '0'

Dovecot mailing list
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)&lt;16189&gt;&lt;UxYWLVuSYMasEQoK&gt;: 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

Reply | Threaded
Open this post in threaded view
|

Re: fts_solr: Error: fts_solr: received invalid uid '0'

Dovecot mailing list
Hi,

> Am 16.09.2019 um 09:39 schrieb Daniel Miller <[hidden email]>:
>
> 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)&lt;16189&gt;&lt;UxYWLVuSYMasEQoK&gt;: 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 <a href="http://172.17.10.12:8983:">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 <a href="http://172.17.10.12:8983:">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 <a href="http://172.17.10.12:8983:">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 <a href="http://172.17.10.12:8983:">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 <a href="http://172.17.10.12:8983:">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 <a href="http://172.17.10.12:8983:">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

Reply | Threaded
Open this post in threaded view
|

Re: fts_solr: Error: fts_solr: received invalid uid '0'

Dovecot mailing list
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

Reply | Threaded
Open this post in threaded view
|

Re: fts_solr: Error: fts_solr: received invalid uid '0'

Dovecot mailing list
In reply to this post by Dovecot mailing list
Hi,

Am 23.09.2019 um 09:36 schrieb Filip Hanes <[hidden email]>:


št 19. 9. 2019 o 15:30 Fabian via dovecot <[hidden email]> napísal(a):
Are there any other hints or tips regarding this „invalid uid ‚0‘"-message?
from fts-solr source:
    case SOLR_XML_CONTENT_STATE_UID:
        if (uint32_parse(str, len, &ctx->uid) < 0 || ctx->uid == 0) {
            i_error("fts_solr: received invalid uid '%s'", t_strndup(str, len));
It means that plugin tries to parse '0' when in state of parsing uid in xml response from solr or there is a bug in xml response parser.
I would enable rawlog_dir in config and look there for unusual response or extra tags near usual uid in xml response. For example:
plugin {
  fts = solr
  fts_solr = url=... rawlog_dir=/var/log/fts-solr/
}


Thanks for this tip! The rawlog_dir option is not yet supported in our version 2.3.4. What we could provide now would be the XML-Response from Solr. The corresponding search query sometimes causes this error. But Solr's answer seems to always remain the same - in my opinion this already indicates a bug of Dovecot?

The XML response can be downloaded here: https://owncloud.eideo.de/index.php/s/8oyJaf5HBK6zdbr

Kind regards,
Fabian

Reply | Threaded
Open this post in threaded view
|

Re: fts_solr: Error: fts_solr: received invalid uid '0'

Dovecot mailing list


On 07/10/2019 15:13, Fabian Kuran via dovecot wrote:

> Hi,
>
>> Am 23.09.2019 um 09:36 schrieb Filip Hanes <[hidden email]
>> <mailto:[hidden email]>>:
>>
>>
>> št 19. 9. 2019 o 15:30 Fabian via dovecot <[hidden email]
>> <mailto:[hidden email]>> napísal(a):
>>
>>     Are there any other hints or tips regarding this „invalid uid
>>     ‚0‘"-message?
>>
>> from fts-solr source:
>>     case SOLR_XML_CONTENT_STATE_UID:
>>         if (uint32_parse(str, len, &ctx->uid) < 0 || ctx->uid == 0) {
>>             i_error("fts_solr: received invalid uid '%s'", t_strndup(str, len));
>> It means that plugin tries to parse '0' when in state of parsing uid
>> in xml response from solr or there is a bug in xml response parser.
>> I would enable rawlog_dir in config and look there for unusual
>> response or extra tags near usual uid in xml response. For example:
>> |plugin { fts = solr fts_solr = url=... rawlog_dir=/var/log/fts-solr/ }|
>>
>
> Thanks for this tip! The rawlog_dir option is not yet supported in our
> version 2.3.4. What we could provide now would be the XML-Response
> from Solr. The corresponding search query sometimes causes this error.
> But Solr's answer seems to always remain the same - in my opinion this
> already indicates a bug of Dovecot?
>
> The XML response can be downloaded here:
> https://owncloud.eideo.de/index.php/s/8oyJaf5HBK6zdbr

Based on the XML response above, I investigated this problem thoroughly
and determined that this is a pretty severe bug in the Solr XML response
parsing code. This occurs only when the response is rather large and the
boundary between two read chunks falls in the middle of a numeric value
(that happens to end in '0').

Tracking internally as DOP-1470.

I think this may also explain some of the weird reports about invalid
UIDs that we've seen in recent history on this mailing list.

Regards,

Stephan.


Reply | Threaded
Open this post in threaded view
|

Re: fts_solr: Error: fts_solr: received invalid uid '0'

Dovecot mailing list


On 08/10/2019 02:52, Stephan Bosch via dovecot wrote:

>
>
> On 07/10/2019 15:13, Fabian Kuran via dovecot wrote:
>> Hi,
>>
>>> Am 23.09.2019 um 09:36 schrieb Filip Hanes <[hidden email]
>>> <mailto:[hidden email]>>:
>>>
>>>
>>> št 19. 9. 2019 o 15:30 Fabian via dovecot <[hidden email]
>>> <mailto:[hidden email]>> napísal(a):
>>>
>>>     Are there any other hints or tips regarding this „invalid uid
>>>     ‚0‘"-message?
>>>
>>> from fts-solr source:
>>>     case SOLR_XML_CONTENT_STATE_UID:
>>>         if (uint32_parse(str, len, &ctx->uid) < 0 || ctx->uid == 0) {
>>>             i_error("fts_solr: received invalid uid '%s'", t_strndup(str, len));
>>>
>>> It means that plugin tries to parse '0' when in state of parsing uid
>>> in xml response from solr or there is a bug in xml response parser.
>>> I would enable rawlog_dir in config and look there for unusual
>>> response or extra tags near usual uid in xml response. For example:
>>> |plugin { fts = solr fts_solr = url=...
>>> rawlog_dir=/var/log/fts-solr/ }|
>>>
>>
>> Thanks for this tip! The rawlog_dir option is not yet supported in
>> our version 2.3.4. What we could provide now would be the
>> XML-Response from Solr. The corresponding search query sometimes
>> causes this error. But Solr's answer seems to always remain the same
>> - in my opinion this already indicates a bug of Dovecot?
>>
>> The XML response can be downloaded here:
>> https://owncloud.eideo.de/index.php/s/8oyJaf5HBK6zdbr
>
> Based on the XML response above, I investigated this problem
> thoroughly and determined that this is a pretty severe bug in the Solr
> XML response parsing code. This occurs only when the response is
> rather large and the boundary between two read chunks falls in the
> middle of a numeric value (that happens to end in '0').
>
> Tracking internally as DOP-1470.
>
> I think this may also explain some of the weird reports about invalid
> UIDs that we've seen in recent history on this mailing list.

Preliminary fix is here:
https://github.com/stephanbosch/dovecot-core/commits/fix-solr-xml-parser

It's big due to some code restructuring for making a proper unit test. I
am not sure when this will be in a release.

Regards,

Stephan.

Reply | Threaded
Open this post in threaded view
|

Re: fts_solr: Error: fts_solr: received invalid uid '0'

Dovecot mailing list
Is there a way to get this as a patchset against 2.3.8?


On Tue, Oct 8, 2019 at 12:03 PM Stephan Bosch via dovecot <[hidden email]> wrote:


On 08/10/2019 02:52, Stephan Bosch via dovecot wrote:
>
>
> On 07/10/2019 15:13, Fabian Kuran via dovecot wrote:
>> Hi,
>>
>>> Am 23.09.2019 um 09:36 schrieb Filip Hanes <[hidden email]
>>> <mailto:[hidden email]>>:
>>>
>>>
>>> št 19. 9. 2019 o 15:30 Fabian via dovecot <[hidden email]
>>> <mailto:[hidden email]>> napísal(a):
>>>
>>>     Are there any other hints or tips regarding this „invalid uid
>>>     ‚0‘"-message?
>>>
>>> from fts-solr source:
>>>     case SOLR_XML_CONTENT_STATE_UID:
>>>         if (uint32_parse(str, len, &ctx->uid) < 0 || ctx->uid == 0) {
>>>             i_error("fts_solr: received invalid uid '%s'", t_strndup(str, len));
>>>
>>> It means that plugin tries to parse '0' when in state of parsing uid
>>> in xml response from solr or there is a bug in xml response parser.
>>> I would enable rawlog_dir in config and look there for unusual
>>> response or extra tags near usual uid in xml response. For example:
>>> |plugin { fts = solr fts_solr = url=...
>>> rawlog_dir=/var/log/fts-solr/ }|
>>>
>>
>> Thanks for this tip! The rawlog_dir option is not yet supported in
>> our version 2.3.4. What we could provide now would be the
>> XML-Response from Solr. The corresponding search query sometimes
>> causes this error. But Solr's answer seems to always remain the same
>> - in my opinion this already indicates a bug of Dovecot?
>>
>> The XML response can be downloaded here:
>> https://owncloud.eideo.de/index.php/s/8oyJaf5HBK6zdbr
>
> Based on the XML response above, I investigated this problem
> thoroughly and determined that this is a pretty severe bug in the Solr
> XML response parsing code. This occurs only when the response is
> rather large and the boundary between two read chunks falls in the
> middle of a numeric value (that happens to end in '0').
>
> Tracking internally as DOP-1470.
>
> I think this may also explain some of the weird reports about invalid
> UIDs that we've seen in recent history on this mailing list.

Preliminary fix is here:
https://github.com/stephanbosch/dovecot-core/commits/fix-solr-xml-parser

It's big due to some code restructuring for making a proper unit test. I
am not sure when this will be in a release.

Regards,

Stephan.



--
Larry Rosenman                     http://www.lerctr.org/~ler
Phone: +1 214-642-9640 (c)     E-Mail: [hidden email]
US Mail: 5708 Sabbia Dr, Round Rock, TX 78665-2106
Reply | Threaded
Open this post in threaded view
|

Re: fts_solr: Error: fts_solr: received invalid uid '0'

Dovecot mailing list


On 10/10/2019 04:05, Larry Rosenman via dovecot wrote:
> Is there a way to get this as a patchset against 2.3.8?
>

https://github.com/stephanbosch/dovecot-core/tree/fix-solr-xml-parser-2.3.8

This hasn't seen any QA yet, so handle with care.

Regards,

Stephan.

>
> On Tue, Oct 8, 2019 at 12:03 PM Stephan Bosch via dovecot
> <[hidden email] <mailto:[hidden email]>> wrote:
>
>
>
>     On 08/10/2019 02:52, Stephan Bosch via dovecot wrote:
>     >
>     >
>     > On 07/10/2019 15:13, Fabian Kuran via dovecot wrote:
>     >> Hi,
>     >>
>     >>> Am 23.09.2019 um 09:36 schrieb Filip Hanes
>     <[hidden email] <mailto:[hidden email]>
>     >>> <mailto:[hidden email] <mailto:[hidden email]>>>:
>     >>>
>     >>>
>     >>> št 19. 9. 2019 o 15:30 Fabian via dovecot <[hidden email]
>     <mailto:[hidden email]>
>     >>> <mailto:[hidden email] <mailto:[hidden email]>>>
>     napísal(a):
>     >>>
>     >>>     Are there any other hints or tips regarding this „invalid uid
>     >>>     ‚0‘"-message?
>     >>>
>     >>> from fts-solr source:
>     >>>     case SOLR_XML_CONTENT_STATE_UID:
>     >>>
>             if (uint32_parse(str, len, &ctx->uid) < 0 || ctx->uid == 0) {
>     >>>
>                 i_error("fts_solr: received invalid uid '%s'", t_strndup(str, len));
>
>     >>>
>     >>> It means that plugin tries to parse '0' when in state of
>     parsing uid
>     >>> in xml response from solr or there is a bug in xml response
>     parser.
>     >>> I would enable rawlog_dir in config and look there for unusual
>     >>> response or extra tags near usual uid in xml response. For
>     example:
>     >>> |plugin { fts = solr fts_solr = url=...
>     >>> rawlog_dir=/var/log/fts-solr/ }|
>     >>>
>     >>
>     >> Thanks for this tip! The rawlog_dir option is not yet supported in
>     >> our version 2.3.4. What we could provide now would be the
>     >> XML-Response from Solr. The corresponding search query sometimes
>     >> causes this error. But Solr's answer seems to always remain the
>     same
>     >> - in my opinion this already indicates a bug of Dovecot?
>     >>
>     >> The XML response can be downloaded here:
>     >> https://owncloud.eideo.de/index.php/s/8oyJaf5HBK6zdbr
>     >
>     > Based on the XML response above, I investigated this problem
>     > thoroughly and determined that this is a pretty severe bug in
>     the Solr
>     > XML response parsing code. This occurs only when the response is
>     > rather large and the boundary between two read chunks falls in the
>     > middle of a numeric value (that happens to end in '0').
>     >
>     > Tracking internally as DOP-1470.
>     >
>     > I think this may also explain some of the weird reports about
>     invalid
>     > UIDs that we've seen in recent history on this mailing list.
>
>     Preliminary fix is here:
>     https://github.com/stephanbosch/dovecot-core/commits/fix-solr-xml-parser
>
>     It's big due to some code restructuring for making a proper unit
>     test. I
>     am not sure when this will be in a release.
>
>     Regards,
>
>     Stephan.
>
>
>
> --
> Larry Rosenman http://www.lerctr.org/~ler
> Phone: +1 214-642-9640 (c) E-Mail: [hidden email]
> <mailto:[hidden email]>
> US Mail: 5708 Sabbia Dr, Round Rock, TX 78665-2106

Reply | Threaded
Open this post in threaded view
|

Re: fts_solr: Error: fts_solr: received invalid uid '0'

Dovecot mailing list
Any news on this getting into a release?

On Sun, Oct 13, 2019 at 2:24 AM Stephan Bosch <[hidden email]> wrote:


On 10/10/2019 04:05, Larry Rosenman via dovecot wrote:
> Is there a way to get this as a patchset against 2.3.8?
>

https://github.com/stephanbosch/dovecot-core/tree/fix-solr-xml-parser-2.3.8

This hasn't seen any QA yet, so handle with care.

Regards,

Stephan.

>
> On Tue, Oct 8, 2019 at 12:03 PM Stephan Bosch via dovecot
> <[hidden email] <mailto:[hidden email]>> wrote:
>
>
>
>     On 08/10/2019 02:52, Stephan Bosch via dovecot wrote:
>     >
>     >
>     > On 07/10/2019 15:13, Fabian Kuran via dovecot wrote:
>     >> Hi,
>     >>
>     >>> Am 23.09.2019 um 09:36 schrieb Filip Hanes
>     <[hidden email] <mailto:[hidden email]>
>     >>> <mailto:[hidden email] <mailto:[hidden email]>>>:
>     >>>
>     >>>
>     >>> št 19. 9. 2019 o 15:30 Fabian via dovecot <[hidden email]
>     <mailto:[hidden email]>
>     >>> <mailto:[hidden email] <mailto:[hidden email]>>>
>     napísal(a):
>     >>>
>     >>>     Are there any other hints or tips regarding this „invalid uid
>     >>>     ‚0‘"-message?
>     >>>
>     >>> from fts-solr source:
>     >>>     case SOLR_XML_CONTENT_STATE_UID:
>     >>>
>             if (uint32_parse(str, len, &ctx->uid) < 0 || ctx->uid == 0) {
>     >>>
>                 i_error("fts_solr: received invalid uid '%s'", t_strndup(str, len));
>
>     >>>
>     >>> It means that plugin tries to parse '0' when in state of
>     parsing uid
>     >>> in xml response from solr or there is a bug in xml response
>     parser.
>     >>> I would enable rawlog_dir in config and look there for unusual
>     >>> response or extra tags near usual uid in xml response. For
>     example:
>     >>> |plugin { fts = solr fts_solr = url=...
>     >>> rawlog_dir=/var/log/fts-solr/ }|
>     >>>
>     >>
>     >> Thanks for this tip! The rawlog_dir option is not yet supported in
>     >> our version 2.3.4. What we could provide now would be the
>     >> XML-Response from Solr. The corresponding search query sometimes
>     >> causes this error. But Solr's answer seems to always remain the
>     same
>     >> - in my opinion this already indicates a bug of Dovecot?
>     >>
>     >> The XML response can be downloaded here:
>     >> https://owncloud.eideo.de/index.php/s/8oyJaf5HBK6zdbr
>     >
>     > Based on the XML response above, I investigated this problem
>     > thoroughly and determined that this is a pretty severe bug in
>     the Solr
>     > XML response parsing code. This occurs only when the response is
>     > rather large and the boundary between two read chunks falls in the
>     > middle of a numeric value (that happens to end in '0').
>     >
>     > Tracking internally as DOP-1470.
>     >
>     > I think this may also explain some of the weird reports about
>     invalid
>     > UIDs that we've seen in recent history on this mailing list.
>
>     Preliminary fix is here:
>     https://github.com/stephanbosch/dovecot-core/commits/fix-solr-xml-parser
>
>     It's big due to some code restructuring for making a proper unit
>     test. I
>     am not sure when this will be in a release.
>
>     Regards,
>
>     Stephan.
>
>
>
> --
> Larry Rosenman http://www.lerctr.org/~ler
> Phone: +1 214-642-9640 (c) E-Mail: [hidden email]
> <mailto:[hidden email]>
> US Mail: 5708 Sabbia Dr, Round Rock, TX 78665-2106



--
Larry Rosenman                     http://www.lerctr.org/~ler
Phone: +1 214-642-9640 (c)     E-Mail: [hidden email]
US Mail: 5708 Sabbia Dr, Round Rock, TX 78665-2106
Reply | Threaded
Open this post in threaded view
|

Re: fts_solr: Error: fts_solr: received invalid uid '0'

Dovecot mailing list
Lets hope 2.3.10 ...

Aki

> On 10/12/2019 20:57 Larry Rosenman via dovecot <[hidden email]> wrote:
>
>
> Any news on this getting into a release?
>
>
> On Sun, Oct 13, 2019 at 2:24 AM Stephan Bosch <[hidden email]> wrote:
> >
> >  
> >  On 10/10/2019 04:05, Larry Rosenman via dovecot wrote:
> >  > Is there a way to get this as a patchset against 2.3.8?
> >  >
> >  
> >  https://github.com/stephanbosch/dovecot-core/tree/fix-solr-xml-parser-2.3.8
> >  
> >  This hasn't seen any QA yet, so handle with care.
> >  
> >  Regards,
> >  
> >  Stephan.
> >  
> >  >
> >  > On Tue, Oct 8, 2019 at 12:03 PM Stephan Bosch via dovecot
> >  > <[hidden email] <mailto:[hidden email]>> wrote:
> >  >
> >  >
> >  >
> >  > On 08/10/2019 02:52, Stephan Bosch via dovecot wrote:
> >  > >
> >  > >
> >  > > On 07/10/2019 15:13, Fabian Kuran via dovecot wrote:
> >  > >> Hi,
> >  > >>
> >  > >>> Am 23.09.2019 um 09:36 schrieb Filip Hanes
> >  > <[hidden email] <mailto:[hidden email]>
> >  > >>> <mailto:[hidden email] <mailto:[hidden email]>>>:
> >  > >>>
> >  > >>>
> >  > >>> št 19. 9. 2019 o 15:30 Fabian via dovecot <[hidden email]
> >  > <mailto:[hidden email]>
> >  > >>> <mailto:[hidden email] <mailto:[hidden email]>>>
> >  > napísal(a):
> >  > >>>
> >  > >>> Are there any other hints or tips regarding this „invalid uid
> >  > >>> ‚0‘"-message?
> >  > >>>
> >  > >>> from fts-solr source:
> >  > >>> case SOLR_XML_CONTENT_STATE_UID:
> >  > >>>
> >  > if (uint32_parse(str, len, &ctx->uid) < 0 || ctx->uid == 0) {
> >  > >>>
> >  > i_error("fts_solr: received invalid uid '%s'", t_strndup(str, len));
> >  >
> >  > >>>
> >  > >>> It means that plugin tries to parse '0' when in state of
> >  > parsing uid
> >  > >>> in xml response from solr or there is a bug in xml response
> >  > parser.
> >  > >>> I would enable rawlog_dir in config and look there for unusual
> >  > >>> response or extra tags near usual uid in xml response. For
> >  > example:
> >  > >>> |plugin { fts = solr fts_solr = url=...
> >  > >>> rawlog_dir=/var/log/fts-solr/ }|
> >  > >>>
> >  > >>
> >  > >> Thanks for this tip! The rawlog_dir option is not yet supported in
> >  > >> our version 2.3.4. What we could provide now would be the
> >  > >> XML-Response from Solr. The corresponding search query sometimes
> >  > >> causes this error. But Solr's answer seems to always remain the
> >  > same
> >  > >> - in my opinion this already indicates a bug of Dovecot?
> >  > >>
> >  > >> The XML response can be downloaded here:
> >  > >> https://owncloud.eideo.de/index.php/s/8oyJaf5HBK6zdbr
> >  > >
> >  > > Based on the XML response above, I investigated this problem
> >  > > thoroughly and determined that this is a pretty severe bug in
> >  > the Solr
> >  > > XML response parsing code. This occurs only when the response is
> >  > > rather large and the boundary between two read chunks falls in the
> >  > > middle of a numeric value (that happens to end in '0').
> >  > >
> >  > > Tracking internally as DOP-1470.
> >  > >
> >  > > I think this may also explain some of the weird reports about
> >  > invalid
> >  > > UIDs that we've seen in recent history on this mailing list.
> >  >
> >  > Preliminary fix is here:
> >  > https://github.com/stephanbosch/dovecot-core/commits/fix-solr-xml-parser
> >  >
> >  > It's big due to some code restructuring for making a proper unit
> >  > test. I
> >  > am not sure when this will be in a release.
> >  >
> >  > Regards,
> >  >
> >  > Stephan.
> >  >
> >  >
> >  >
> >  > --
> >  > Larry Rosenman http://www.lerctr.org/~ler
> >  > Phone: +1 214-642-9640 (c) E-Mail: [hidden email]
> >  > <mailto:[hidden email]>
> >  > US Mail: 5708 Sabbia Dr, Round Rock, TX 78665-2106
> >  
> >
>
>
>
> --
>
> Larry Rosenman http://www.lerctr.org/~ler
> Phone: +1 214-642-9640 (c) E-Mail:[hidden email]
> US Mail: 5708 Sabbia Dr, Round Rock, TX 78665-2106