<html><head><meta http-equiv="Content-Type" content="text/html; charset=utf-8"></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; line-break: after-white-space;" class="">Dear John,<div class=""><br class=""></div><div class="">Thank you very much for this reply! You saved me really a lot of hours of work! </div><div class=""><br class=""></div><div class="">I have managed to index those mailboxes finally after applying your patch. I don’t know why this patch never got any attention and didn’t find its way to the upstream...</div><div class=""><br class=""></div><div class="">But it became clear that in current configuration dovecot sends as message body tons of useless binary information that not just hard to index but also affects search performance badly. Moreover due to this on some mailboxes up to 1% of all messages are now ignored completely (it’s of course better than stuck index and overloaded IO of the whole system - thanks again!)</div><div class=""><br class=""></div><div class="">I have to wait for non-business hours to run some more tests, but it seems it happens really often when dovecot sends binary attachments of any kind for indexing. Once done I’ll try to submit more detailed separate bug report.</div><div class=""><br class=""></div><div class="">At the moment I am thinking about developing a small proxy that I gonna put between dovecot and solr and strip unnecessary body parts on that stage… </div><div class=""><div><br class=""><blockquote type="cite" class=""><div class="">On 16. Jan 2021, at 19:16, John Fawcett <<a href="mailto:john@voipsupport.it" class="">john@voipsupport.it</a>> wrote:</div><br class="Apple-interchange-newline"><div class="">
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8" class="">
<div class="">
<div class="moz-cite-prefix">On 15/01/2021 11:39, Alexey Panov
wrote:<br class="">
</div>
<blockquote type="cite" cite="mid:8C07E075-2F0B-4B70-8565-471B2C19F6CB@icloud.com" class="">
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8" class="">
I guess I was indeed correct. As message body is the part of mail
index dovecot indeed sends all those binary messages as a part of
message body:
<div class=""><br class="">
</div>
<div class="">
<blockquote type="cite" class="">
<div class="">doveadm fetch -u <a href="mailto:test.user@interpont.com" class="" moz-do-not-send="true">test.user@interpont.com</a> "body"
mailbox KS2 uid 2 | wc --bytes</div>
<div class="">21549696</div>
</blockquote>
<div class=""><br class="">
</div>
<div class="">This affects FTS indexing dramatically I guess… </div>
<div class=""><br class="">
<blockquote type="cite" class="">
<div class="">On 15. Jan 2021, at 17:10, Alexey Panov <<a href="mailto:programmierus@icloud.com" class="" moz-do-not-send="true">programmierus@icloud.com</a>>
wrote:</div>
<br class="Apple-interchange-newline">
<div class="">
<meta http-equiv="Content-Type" content="text/html;
charset=UTF-8" class="">
<div style="word-wrap: break-word; -webkit-nbsp-mode:
space; line-break: after-white-space;" class="">I could
find messages causing problems as solr log indeed shows
the IMAP UID.
<div class=""><br class="">
</div>
<div class="">Reducing batch_size to a single message I
could identify one of those messages causing the
problem. </div>
<div class=""><br class="">
</div>
<div class="">Now I can confirm the following behaviour:
there are some SINGLE messages where 60 seconds is NOT
ENOUGH to index. The message I am looking at now is
20MB big (compressed 17MB) and has a lot of inline
pasted screenshots. I guess that dovecot might send
those pasted images as a part of the message body to
solr?</div>
<div class=""><br class="">
</div>
<div class="">Here are some logs for better
understanding:</div>
<div class=""><br class="">
</div>
<div class="">Folder contents (single message):</div>
<div class=""><br class="">
</div>
<div class="">
<blockquote type="cite" class="">
<div class="">doveadm search -u u@d mailbox KS2</div>
<div class="">e836ff1d20640160340b0000532cee39 2</div>
</blockquote>
</div>
<div class=""><br class="">
</div>
<div class="">Force indexing:</div>
<div class=""><br class="">
</div>
<div class="">
<blockquote type="cite" class="">
<div class="">doveadm index -u u@d KS2</div>
<div class="">doveadm(u@d): Error: fts_solr:
Indexing failed: Request timed out (Request queued
61.105 secs ago, 1 send attempts in 61.089 secs,
60.071 in http ioloop, 0.000 in other ioloops,
connected 61.089 secs ago)</div>
<div class="">doveadm(u@d): Error: Mailbox KS2:
Transaction commit failed: FTS transaction commit
failed: backend deinit</div>
</blockquote>
</div>
<div class=""><br class="">
</div>
<div class="">Corresponding solr logs:</div>
<div class=""><br class="">
</div>
<div class="">
<blockquote type="cite" class="">solr-mailcow_1
| 2021-01-15 10:02:34.901 INFO (qtp524223214-2127)
[ x:dovecot-fts]
o.a.s.u.p.LogUpdateProcessorFactory [dovecot-fts]
webapp=/solr path=/update
params={}{add=[2/e836ff1d20640160340b0000532cee39/u@d
(1688946475272241152)]} 0 80683<br class="">
</blockquote>
<div class=""><br class="">
</div>
<div class="">I would greatly appreciate any help. My
users using pasted images heavily (designers
exchanging mockups etc) and if this truly is a
problem then I am screwed :) </div>
<div class=""><br class="">
</div>
<div class=""><br class="">
<blockquote type="cite" class="">
<div class="">On 14. Jan 2021, at 23:46, Alexey
Panov <<a href="mailto:programmierus@icloud.com" class="" moz-do-not-send="true">programmierus@icloud.com</a>>
wrote:</div>
<br class="Apple-interchange-newline">
<div class="">
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8" class="">
<div style="word-wrap: break-word;
-webkit-nbsp-mode: space; line-break:
after-white-space;" class="">Hello,
<div class=""><br class="">
</div>
<div class="">I am running recent
dovecot 2.3.13 (89f716dc2) within dockerized
mailcow setup. </div>
<div class=""><br class="">
</div>
<div class="">During just another update
routine I decided to reindex all mailboxes
and some of them fail (timeout) on exactly
SAME messages in SAME mailboxes:</div>
<div class=""><br class="">
</div>
<div class="">
<blockquote type="cite" class="">doveadm(u@d):
Error: fts_solr: Indexing failed: Request
timed out (Request queued 73.213 secs ago,
1 send attempts in 73.098 secs, 60.597 in
http ioloop, 0.000 in other ioloops,
connected 127.875 secs ago)<br class="">
doveadm(u@d): Error: Mailbox Sent: Mail
search failed: Internal error occurred.
Refer to server log for more information.
[2021-01-14 11:23:46]<br class="">
doveadm(u@d): Error: Mailbox Sent:
Transaction commit failed: FTS transaction
commit failed: backend deinit<br class="">
</blockquote>
<br class="">
This error is persistent and affects only
some, but always same folders of same
mailboxes (i mean solr can't finish indexing
them at all). </div>
<div class=""><br class="">
</div>
<div class="">I/O is in perfect condition and
has no corruptions. I also tried to do fts
rescan which made no change. RAM is fine, I
haven't seen OOM conditions.<br class="">
<br class="">
</div>
<div class="">During my research I found <a href="https://www.mail-archive.com/dovecot@dovecot.org/msg76944.html" class="" moz-do-not-send="true">this
discussion</a> which lead me idea of
reducing the batch_size to as low as 10 (for
testing purposes). Observing SOLR logs
during reindexing on the mailbox/folder
causing the error I noticed the following
strange behaviour. </div>
<div class=""><br class="">
</div>
<div class="">Firstly, it goes very fast but
then always kinda freezes on these messages:</div>
<div class=""><br class="">
</div>
<div class="">
<blockquote type="cite" class="">
<div class="">solr-mailcow_1 | <b class="">2021-01-14 16:05:09.615</b>
INFO (qtp524223214-1151) [
x:dovecot-fts]
o.a.s.u.p.LogUpdateProcessorFactory
[dovecot-fts] webapp=/solr path=/update
params={}{add=[6883/78a0ec27b091da5e4054000013681708/u@d
(1688878773188952064),
6884/78a0ec27b091da5e4054000013681708/u@d
(1688878773203632128),
6885/78a0ec27b091da5e4054000013681708/u@d
(1688878773218312192),
6886/78a0ec27b091da5e4054000013681708/u@d
(1688878773227749376),
6887/78a0ec27b091da5e4054000013681708/u@d
(1688878773237186560),
6888/78a0ec27b091da5e4054000013681708/u@d
(1688878773244526592),
6889/78a0ec27b091da5e4054000013681708/u@d
(1688878773250818048),
6890/78a0ec27b091da5e4054000013681708/u@d
(1688878773259206656),
6891/78a0ec27b091da5e4054000013681708/u@d
(1688878773272838144),
6892/78a0ec27b091da5e4054000013681708/u@d
(1688878773288566784)]} 0 101</div>
<div class="">solr-mailcow_1 | <b class="">2021-01-14 16:06:42.540</b>
INFO (qtp524223214-1143) [
x:dovecot-fts]
o.a.s.u.p.LogUpdateProcessorFactory
[dovecot-fts] webapp=/solr path=/update
params={}{add=[6893/78a0ec27b091da5e4054000013681708/u@d
(1688878773329461248),
6894/78a0ec27b091da5e4054000013681708/u@d
(1688878773332606976),
6895/78a0ec27b091da5e4054000013681708/u@d
(1688878774361260032),
6896/78a0ec27b091da5e4054000013681708/u@d
(1688878850290745344),
6897/78a0ec27b091da5e4054000013681708/u@d
(1688878851347709952),
6898/78a0ec27b091da5e4054000013681708/u@d
(1688878852404674560),
6899/78a0ec27b091da5e4054000013681708/u@d
(1688878853586419712),
6900/78a0ec27b091da5e4054000013681708/u@d
(1688878870704422912),
6901/78a0ec27b091da5e4054000013681708/u@d
(1688878870709665792),
6902/78a0ec27b091da5e4054000013681708/u@d
(1688878870727491584)]} 0 92891</div>
</blockquote>
</div>
<div class=""><br class="">
</div>
<div class="">It takes almost one and a half
minute to get those ten messages (6893-6902)
indexed. It freezes exactly on that position
every time I restart indexing. Actually only
reducing the batch_size to 10 made it
through. It was timing out with the default
batch_size exactly here each time. </div>
<div class=""><br class="">
</div>
<div class="">Than it goes further again
blazing fast until it reaches here:</div>
<div class=""><br class="">
</div>
<div class="">
<blockquote type="cite" class="">
<div class="">solr-mailcow_1 | <b class="">2021-01-14 16:07:26.148</b>
INFO (qtp524223214-1151) [
x:dovecot-fts]
o.a.s.u.p.LogUpdateProcessorFactory
[dovecot-fts] webapp=/solr path=/update
params={}{add=[7443/78a0ec27b091da5e4054000013681708/u@d
(1688878884286627840),
7444/78a0ec27b091da5e4054000013681708/u@d
(1688878884293967872),
7445/78a0ec27b091da5e4054000013681708/u@d
(1688878884304453632),
7446/78a0ec27b091da5e4054000013681708/u@d
(1688878884502634496),
7447/78a0ec27b091da5e4054000013681708/u@d
(1688878900331937792),
7448/78a0ec27b091da5e4054000013681708/u@d
(1688878900508098560),
7449/78a0ec27b091da5e4054000013681708/u@d
(1688878916409753600),
7450/78a0ec27b091da5e4054000013681708/u@d
(1688878916424433664),
7451/78a0ec27b091da5e4054000013681708/u@d
(1688878916438065152),
7452/78a0ec27b091da5e4054000013681708/u@d
(1688878916448550912)]} 0 30682</div>
<div class="">solr-mailcow_1 |<b class=""> 2021-01-14 16:09:40.277</b>
INFO (qtp524223214-1325) [
x:dovecot-fts]
o.a.s.u.p.LogUpdateProcessorFactory
[dovecot-fts] webapp=/solr path=/update
params={}{add=[7463/78a0ec27b091da5e4054000013681708/u@d
(1688879057103486976)]} 0 1</div>
<div class="">solr-mailcow_1 | <b class="">2021-01-14 16:10:00.628</b>
INFO (qtp524223214-1009) [
x:dovecot-fts]
o.a.s.u.p.LogUpdateProcessorFactory
[dovecot-fts] webapp=/solr path=/update
params={}{add=[7453/78a0ec27b091da5e4054000013681708/u@d
(1688878916486299648),
7454/78a0ec27b091da5e4054000013681708/u@d
(1688878916489445376),
7455/78a0ec27b091da5e4054000013681708/u@d
(1688878916496785408),
7456/78a0ec27b091da5e4054000013681708/u@d
(1688878917584158720),
7457/78a0ec27b091da5e4054000013681708/u@d
(1688878994974310400),
7458/78a0ec27b091da5e4054000013681708/u@d
(1688879073177108480),
7459/78a0ec27b091da5e4054000013681708/u@d
(1688879074234073088),
7460/78a0ec27b091da5e4054000013681708/u@d
(1688879075288940544),
7461/78a0ec27b091da5e4054000013681708/u@d
(1688879076339613696),
7462/78a0ec27b091da5e4054000013681708/u@d
(1688879077392384000)]} 0 154455</div>
</blockquote>
<br class="">
</div>
<div class="">This results in the following
error on the console where I start
reindexing: </div>
<div class=""><br class="">
</div>
<div class="">
<blockquote type="cite" class="">
<div class="">$ docker-compose exec
dovecot-mailcow doveadm index -u u@d
'Sent'</div>
<div class="">doveadm(u@d): Error:
fts_solr: Indexing failed: Request timed
out (Request queued 134.122 secs ago, 1
send attempts in 134.098 secs, 131.923
in http ioloop, 0.000 in other ioloops,
connected 376.408 secs ago)</div>
<div class="">doveadm(u@d): Error: Mailbox
Sent: Mail search failed: Internal error
occurred. Refer to server log for more
information. [<b class="">2021-01-14
17:09:40</b>]</div>
<div class="">doveadm(u@d): Error: Mailbox
Sent: Transaction commit failed: FTS
transaction commit failed: backend
deinit</div>
</blockquote>
</div>
<div class=""><br class="">
</div>
<div class="">The last message about indexed
block of ten messages (<b class="">2021-01-14
16:10:00.628 7453-7462)</b> arrives
already after reindexing error on the other
console occurs and doveadm exits.
Interestingly, exactly at the time mentioned
in the error message (<b class="">2021-01-14
17:09:40</b>, i.e. <b class="">16:06:40</b>
- I don’t know why timezone differs) a
message about indexing of a single message <b class="">7463</b> arrives (which is
actually NEXT message to the block that gets
indexed 20 seconds later). </div>
<div class=""><br class="">
</div>
<div class="">The whole mailbox consists of
8530 messages and doveadm/solr can’t finish
indexing it at all starting over and over.</div>
<div class=""><br class="">
</div>
<div class="">Can you please help me
understanding the reason of this behaviour?</div>
<div class=""><br class="">
</div>
<div class="">P.S. Is there any possibility to
determine what message in vmail maildir
corresponds to solr log, e.g. to
7463/78a0ec27b091da5e4054000013681708/u@d
(1688879057103486976) ? </div>
<div class=""><br class="">
</div>
<div class="">Thanks, Programmierus</div>
</div>
</div>
</blockquote>
</div>
<br class="">
</div>
</div>
</div>
</blockquote>
</div>
<br class="">
</div>
</blockquote><p class="">I previously posted a patch (7 Dec 2020) you might find useful in
this circumstance which includes an additional setting, for
example:</p>
<pre class="moz-quote-pre" wrap="">plugin {
...
fts_max_size = 2M
...
}
fts_max_size - do not parse message bodies if the message size exceeds
this value. A value of 0 indicates no limit. When the message body is not
parsed, attachments are also not parsed.
John
</pre>
</div>
</div></blockquote></div><br class=""></div></body></html>