dovecot - Oct 2020 - v2.3.11.3 solr plugin search via MUA fails to match accented ascii characters; cmd line exec of `doveadm fts lookup` PANICs (assertion failed)

On 10/19/20 1:18 AM, John Fawcett wrote:
> I would recommend you to redo the tests after correcting the
> configuration. To be doubly sure you can include accented and unique non
> accented text in the same email and search for both. If the non accented
> text is found you know you've searching against the updated index and
> the fact that accented text is not found is not simply because the index
> updates are not visible.
temp changing,

	fts_solr = url=https://solr.example.com:8984/solr/dovecot/ use_libfts
soft_commit=yes batch_size=250
-	fts_enforced = body
+	fts_enforced = yes
-	fts_filters = normalizer-icu snowball stopwords
+	fts_filters = lowercase snowball stopwords

now,

	doveadm fts rescan -u testuser at example.com
	doveadm index      -u testuser at example.com -q '*'

, no errors.

on receipt of a test email with

	subject: aausdfrhy?tdwgyatrdf aausdfrhyetdwgyatrdf
	body:    aausdfrhy?tdwgyatrdf aausdfrhyetdwgyatrdf

i see a solr auto-scan,

	2020-10-19 14:41:50.628 INFO 
(searcherExecutor-15-thread-1-processing-x:dovecot) [   x:dovecot]
o.a.s.c.SolrCore [dovecot]  Registered new searcher autowarm time: 1 ms
	2020-10-19 14:41:50.634 INFO  (qtp1533985074-18) [   x:dovecot]
o.a.s.u.p.LogUpdateProcessorFactory [dovecot]  webapp=/solr path=/update
params={}{commit=} 0 155
	2020-10-19 14:41:51.571 INFO  (qtp1533985074-24) [   x:dovecot]
o.a.s.u.p.LogUpdateProcessorFactory [dovecot]  webapp=/solr path=/update
params={}{add=[135785/c92f64f79f0d1ed01e6d5b314f04886c/testuser at example.com
(1680991596381732864)]} 0 9

	==> /var/log/solr/solr_gc.log <=
[2020-10-19T07:41:51.612-0700][146823.946s] GC(343) Pause Young (Normal) (G1
Evacuation Pause)
	[2020-10-19T07:41:51.613-0700][146823.947s] GC(343) Using 2 workers of 2 for
evacuation
	[2020-10-19T07:41:51.635-0700][146823.969s] GC(343)   Pre Evacuate Collection
Set: 0.3ms
	[2020-10-19T07:41:51.636-0700][146823.970s] GC(343)   Merge Heap Roots: 0.2ms
	[2020-10-19T07:41:51.636-0700][146823.970s] GC(343)   Evacuate Collection Set:
18.9ms
	[2020-10-19T07:41:51.637-0700][146823.971s] GC(343)   Post Evacuate Collection
Set: 2.0ms
	[2020-10-19T07:41:51.637-0700][146823.971s] GC(343)   Other: 1.5ms
	[2020-10-19T07:41:51.637-0700][146823.971s] GC(343) Eden regions:
238->0(244)
	[2020-10-19T07:41:51.638-0700][146823.972s] GC(343) Survivor regions:
4->2(31)
	[2020-10-19T07:41:51.638-0700][146823.972s] GC(343) Old regions: 189->189
	[2020-10-19T07:41:51.638-0700][146823.973s] GC(343) Archive regions: 2->2
	[2020-10-19T07:41:51.639-0700][146823.973s] GC(343) Humongous regions: 10->9
	[2020-10-19T07:41:51.639-0700][146823.973s] GC(343) Metaspace:
61564K(78028K)->61564K(78028K) NonClass: 55348K(65024K)->55348K(65024K)
Class: 6216K(13004K)->6216K(13004K)
	[2020-10-19T07:41:51.640-0700][146823.974s] GC(343) Pause Young (Normal) (G1
Evacuation Pause) 441M->200M(512M) 27.372ms
	[2020-10-19T07:41:51.640-0700][146823.974s] GC(343) User=0.01s Sys=0.01s
Real=0.03s

	==> /var/log/solr/solr.log <=	2020-10-19 14:41:51.702 INFO 
(searcherExecutor-15-thread-1-processing-x:dovecot) [   x:dovecot]
o.a.s.c.SolrCore [dovecot]  Registered new searcher autowarm time: 0 ms
	2020-10-19 14:41:51.705 INFO  (qtp1533985074-18) [   x:dovecot]
o.a.s.u.p.LogUpdateProcessorFactory [dovecot]  webapp=/solr path=/update
params={}{commit=} 0 127


search in TBird

	subject: aausdfrhyetdwgyatrdf  => FOUND
	body:    aausdfrhy?tdwgyatrdf  => FOUND

	subject: aausdfrhyetdwgyatrdf  => FOUND
	body:    aausdfrhy?tdwgyatrdf  => (emtpy)

on header search, I'm _not_ seeing any additional activity in solr.log

so, either i'm looking in the wrong place, haven't turned on appropriate
logging, or i'm still not searching via solr ...

separately,

	doveadm fts lookup ...

still panics; Aki's bug will hopefully deal with that

On 19/10/2020 17:00, PGNet Dev wrote:
> On 10/19/20 1:18 AM, John Fawcett wrote:
>> I would recommend you to redo the tests after correcting the
>> configuration. To be doubly sure you can include accented and unique
non
>> accented text in the same email and search for both. If the non
accented
>> text is found you know you've searching against the updated index
and
>> the fact that accented text is not found is not simply because the
index
>> updates are not visible.
>
> temp changing,
>
> ????fts_solr = url=https://solr.example.com:8984/solr/dovecot/
> use_libfts soft_commit=yes batch_size=250
> -??? fts_enforced = body
> +??? fts_enforced = yes
> -??? fts_filters = normalizer-icu snowball stopwords
> +??? fts_filters = lowercase snowball stopwords
>
> now,
>
> ????doveadm fts rescan -u testuser at example.com
> ????doveadm index????? -u testuser at example.com -q '*'
>
> , no errors.
>
> on receipt of a test email with
>
> ????subject: aausdfrhy?tdwgyatrdf aausdfrhyetdwgyatrdf
> ????body:??? aausdfrhy?tdwgyatrdf aausdfrhyetdwgyatrdf
>
> i see a solr auto-scan,
>
> ????2020-10-19 14:41:50.628 INFO?
> (searcherExecutor-15-thread-1-processing-x:dovecot) [?? x:dovecot]
> o.a.s.c.SolrCore [dovecot]? Registered new searcher autowarm time: 1 ms
> ????2020-10-19 14:41:50.634 INFO? (qtp1533985074-18) [?? x:dovecot]
> o.a.s.u.p.LogUpdateProcessorFactory [dovecot]? webapp=/solr
> path=/update params={}{commit=} 0 155
> ????2020-10-19 14:41:51.571 INFO? (qtp1533985074-24) [?? x:dovecot]
> o.a.s.u.p.LogUpdateProcessorFactory [dovecot]? webapp=/solr
> path=/update
> params={}{add=[135785/c92f64f79f0d1ed01e6d5b314f04886c/testuser at
example.com
> (1680991596381732864)]} 0 9
>
> ????==> /var/log/solr/solr_gc.log <=>
????[2020-10-19T07:41:51.612-0700][146823.946s] GC(343) Pause Young
> (Normal) (G1 Evacuation Pause)
> ????[2020-10-19T07:41:51.613-0700][146823.947s] GC(343) Using 2
> workers of 2 for evacuation
> ????[2020-10-19T07:41:51.635-0700][146823.969s] GC(343)?? Pre Evacuate
> Collection Set: 0.3ms
> ????[2020-10-19T07:41:51.636-0700][146823.970s] GC(343)?? Merge Heap
> Roots: 0.2ms
> ????[2020-10-19T07:41:51.636-0700][146823.970s] GC(343)?? Evacuate
> Collection Set: 18.9ms
> ????[2020-10-19T07:41:51.637-0700][146823.971s] GC(343)?? Post
> Evacuate Collection Set: 2.0ms
> ????[2020-10-19T07:41:51.637-0700][146823.971s] GC(343)?? Other: 1.5ms
> ????[2020-10-19T07:41:51.637-0700][146823.971s] GC(343) Eden regions:
> 238->0(244)
> ????[2020-10-19T07:41:51.638-0700][146823.972s] GC(343) Survivor
> regions: 4->2(31)
> ????[2020-10-19T07:41:51.638-0700][146823.972s] GC(343) Old regions:
> 189->189
> ????[2020-10-19T07:41:51.638-0700][146823.973s] GC(343) Archive
> regions: 2->2
> ????[2020-10-19T07:41:51.639-0700][146823.973s] GC(343) Humongous
> regions: 10->9
> ????[2020-10-19T07:41:51.639-0700][146823.973s] GC(343) Metaspace:
> 61564K(78028K)->61564K(78028K) NonClass:
> 55348K(65024K)->55348K(65024K) Class: 6216K(13004K)->6216K(13004K)
> ????[2020-10-19T07:41:51.640-0700][146823.974s] GC(343) Pause Young
> (Normal) (G1 Evacuation Pause) 441M->200M(512M) 27.372ms
> ????[2020-10-19T07:41:51.640-0700][146823.974s] GC(343) User=0.01s
> Sys=0.01s Real=0.03s
>
> ????==> /var/log/solr/solr.log <=> ????2020-10-19 14:41:51.702
INFO?
> (searcherExecutor-15-thread-1-processing-x:dovecot) [?? x:dovecot]
> o.a.s.c.SolrCore [dovecot]? Registered new searcher autowarm time: 0 ms
> ????2020-10-19 14:41:51.705 INFO? (qtp1533985074-18) [?? x:dovecot]
> o.a.s.u.p.LogUpdateProcessorFactory [dovecot]? webapp=/solr
> path=/update params={}{commit=} 0 127
>
>
> search in TBird
>
> ????subject: aausdfrhyetdwgyatrdf? => FOUND
> ????body:??? aausdfrhy?tdwgyatrdf? => FOUND
>
> ????subject: aausdfrhyetdwgyatrdf? => FOUND
> ????body:??? aausdfrhy?tdwgyatrdf? => (emtpy)
>
> on header search, I'm _not_ seeing any additional activity in solr.log
>
> so, either i'm looking in the wrong place, haven't turned on
> appropriate logging, or i'm still not searching via solr ...
>
> separately,
>
> ????doveadm fts lookup ...
>
> still panics; Aki's bug will hopefully deal with that
Depending how solr has been setup you could see the logging in the web
server access log. My access log is where I configured it in
/var/log/httpd/servername.access_log, yours may be different.

For searches I see things like this (one for each folder searched)

2a01:488:67:1000:523:f8eb:0:1 - john [19/Oct/2020:17:16:39 +0200] "GET
/solr/dovecot/select?wt=xml&fl=uid,score&rows=3176&sort=uid+asc&q=%7b!lucene+q.op%3dAND%7dbody:aausdfrhy%c3%a9tdwgyatrdf&fq=%2Bbox:b1626f0fe8d9145e54100000c54a863a+%2Buser:john
at voipsupport.it
HTTP/1.1" 200 910 "-" "-"

For index updates I see things like this:

2a01:488:67:1000:523:f8eb:0:1 - john [19/Oct/2020:17:10:01 +0200] "POST
/solr/dovecot/update HTTP/1.1" 200 156 "-" "-"

BTW I've noticed that Thunderbird does not always send the search to the
server even with the "search on server" flag set, which is why I look
at
the access_log in solr if I want to be really sure it's going to solr.

John

On 10/19/20 8:24 AM, John Fawcett wrote:
> Depending how solr has been setup you could see the logging in the web
> server access log. My access log is where I configured it in
> /var/log/httpd/servername.access_log, yours may be different.
here, not running a standalone webserver/proxy in front of solr.

webui's provided by the built-in.

my solr config atm, includes

	/etc/default/solr.in.sh
		...
		SOLR_LOG_LEVEL=INFO
		SOLR_LOGS_DIR="/var/log/solr"
		...

so, iiuc, the

	tail /var/log/solr/*

should be sufficient.
> BTW I've noticed that Thunderbird does not always send the search to
the
> server even with the "search on server" flag set, which is why I
look at
> the access_log in solr if I want to be really sure it's going to solr.
hmmmm ....

watching

	tcpdump -i lo port 8984

shows the usual/expected loads of traffic on inbound mail's scans.

but, @ TBird search -- with "search on server" -- not a peep.

no traffic. at all.

seems there's more than one problem here.

Am 19.10.20 um 17:00 schrieb PGNet Dev:
> 
> 
> search in TBird
> 
>  ????subject: aausdfrhyetdwgyatrdf? => FOUND
>  ????body:??? aausdfrhy?tdwgyatrdf? => FOUND
> 
>  ????subject: aausdfrhyetdwgyatrdf? => FOUND
>  ????body:??? aausdfrhy?tdwgyatrdf? => (emtpy)
> 
> on header search, I'm _not_ seeing any additional activity in solr.log
If I remember correctly, that is an issue with TB - it only does body 
serches serverside, regardless of what you request, there should be an 
entry in their bugzilla, I'm too lazy right now.

-- 
peter

On 10/19/20 9:15 AM, Peter wrote:
> If I remember correctly, that is an issue with TB - it only does body
serches serverside, regardless of what you request, there should be an entry in
their bugzilla, I'm too lazy right now.
this is a very old bug

	https://groups.google.com/forum/#!topic/tb-enterprise/TuUXyQLBB1o

with leads to a comment from Timo

	https://www.mail-archive.com/dovecot at dovecot.org/msg43366.html

		"So, Solr in Dovecot works perfectly.
		> But the same search in thunderbird return "No matches found" :(
		Thunderbird problem, nothing you can do about it from Dovecot's
side."


at the very least, there are/were _known_ issues with TBird's
search-on-server bits.

now, whether that issue is still relevant here, I dunno yet; haven't
finished digging through the ~ decade of Mozilla bug reports, finger pointing,
and lack-of-resource complaints.  grumble.