Bug 26312

Summary: Add some error handling during Elasticsearch indexing
Product: Koha Reporter: Nick Clemens <nick>
Component: Searching - ElasticsearchAssignee: Nick Clemens <nick>
Status: CLOSED FIXED QA Contact: Joonas Kylmälä <joonas.kylmala>
Severity: major    
Priority: P5 - low CC: andrewfh, bjorn.nylen, ere.maijala, fridolin.somers, ian.bays, jon.turner, jonathan.druart, joonas.kylmala, kyle, martin.renvoize, nugged, tomascohen, victor
Version: master   
Hardware: All   
OS: All   
Change sponsored?: --- Patch complexity: ---
Documentation contact: Documentation submission:
Text to go in the release notes:
Version(s) released in:
21.05.00,20.11.05
Attachments: Bug 26312: Catch ES Client errors, log, and continue indexing when error encountered
Bug 26312: Catch ES Client errors, log, and continue indexing when error encountered
109626: Bug 26312: Catch ES Client errors, log, and continue indexing when error encountered
Bug 26312: (follow-up) Reset buffers even if commit fails
Bug 26312: Catch ES Client errors, log, and continue indexing when error encountered
Bug 26312: (follow-up) Reset buffers even if commit fails
Bug 26312: (follow-up) Fix whitespace and missing semicolon
Bug 26312: (follow-up) Fix passing of exception messages
Bug 26312: Catch ES Client errors, log, and continue indexing when error encountered
Bug 26312: (follow-up) Reset buffers even if commit fails
Bug 26312: (follow-up) Fix whitespace and missing semicolon
Bug 26312: (follow-up) Fix passing of exception messages
Bug 26312: Catch ES Client errors, log, and continue indexing when error encountered
Bug 26312: (follow-up) Fix passing of exception messages

Description Nick Clemens 2020-08-27 16:07:07 UTC
Currently Elasticsearch dies if we get an error rather than a response from the ES Client.

Generally we can see something like
[6056] Committing 5000 records...
[Timeout] ** [http://XXX.XXX.XXX.XXX:9200]-[599] Could not write to socket: 'Connection timed out', called from sub Search::Elasticsearch::Role::Client::Direct::__ANON__ at /usr/share/koha/lib/Koha/SearchEngine/Elasticsearch/Indexer.pm line 123. With vars: {'

Rather than killing the whole indexing process, we should catch the error, fail the commit, and keep indexing records.
Comment 1 Nick Clemens 2020-08-27 16:09:57 UTC
Created attachment 109241 [details] [review]
Bug 26312: Catch ES Client errors, log, and continue indexing when error encountered

This catches a timeout response from the ES server, logs this, and continues the indexing

To test:
1 - perl misc/search_tools/rebuild_elasticsearch.pl
2 - Make the ES server timeout (I don't have good instruction yet)
3 - Watch the job crash
4 - Apply patches
5 - perl misc/search_tools/rebuild_elasticsearch.pl
6 - Make the server timeout
7 - Note the job reports failed commit, and continues
Comment 2 Fridolin Somers 2020-09-03 09:06:45 UTC
Very nice.

Why add "use Try::Tiny" in misc/search_tools/rebuild_elasticsearch.pl ?
Comment 3 Nick Clemens 2020-09-03 13:37:36 UTC
(In reply to Fridolin SOMERS from comment #2)
> Very nice.
> 
> Why add "use Try::Tiny" in misc/search_tools/rebuild_elasticsearch.pl ?

Otherwise the try/catch doesn't work with the values returned from Indexer.pm
Comment 4 Nick Clemens 2020-09-03 13:47:46 UTC
Created attachment 109626 [details] [review]
Bug 26312: Catch ES Client errors, log, and continue indexing when error encountered

This catches a timeout response from the ES server, logs this, and continues the indexing

To test:
1 - perl misc/search_tools/rebuild_elasticsearch.pl
2 - Make the ES server timeout (I don't have good instruction yet)
3 - Watch the job crash
4 - Apply patches
5 - perl misc/search_tools/rebuild_elasticsearch.pl
6 - Make the server timeout
7 - Note the job reports failed commit, and continues
Comment 5 Björn Nylén 2020-11-11 15:32:47 UTC
Created attachment 113501 [details] [review]
109626: Bug 26312: Catch ES Client errors, log, and continue indexing when error encountered

This didn't apply cleanly, fixed the conflict in Koha/SearchEngine/Elasticsearch/Indexer.pm . We will try to test later as we're having timeout issues as well.
Comment 6 Björn Nylén 2020-12-07 10:52:58 UTC
Will this actually keep indexing after an error. The commit buffer and counter isn't reset in the catch block so would only keep filling the buffer and never commit the again. Didn't actually test but looks like it would act like that.
Comment 7 Nick Clemens 2020-12-07 11:33:33 UTC
Created attachment 114229 [details] [review]
Bug 26312: (follow-up) Reset buffers even if commit fails
Comment 8 Nick Clemens 2020-12-07 11:34:09 UTC
(In reply to Björn Nylén from comment #6)
> Will this actually keep indexing after an error. The commit buffer and
> counter isn't reset in the catch block so would only keep filling the buffer
> and never commit the again. Didn't actually test but looks like it would act
> like that.

Thanks! You are right, I moved the resets out of the try/catch
Comment 9 Martin Renvoize 2021-03-03 10:16:03 UTC
Did you have a chance to test this Björn?
Comment 10 Martin Renvoize 2021-03-03 15:39:59 UTC
Created attachment 117618 [details] [review]
Bug 26312: Catch ES Client errors, log, and continue indexing when error encountered

This catches a timeout response from the ES server, logs this, and continues the indexing

To test:
1 - perl misc/search_tools/rebuild_elasticsearch.pl
2 - Make the ES server timeout (I don't have good instruction yet)
3 - Watch the job crash
4 - Apply patches
5 - perl misc/search_tools/rebuild_elasticsearch.pl
6 - Make the server timeout
7 - Note the job reports failed commit, and continues

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 11 Martin Renvoize 2021-03-03 15:40:02 UTC
Created attachment 117619 [details] [review]
Bug 26312: (follow-up) Reset buffers even if commit fails

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 12 Martin Renvoize 2021-03-04 07:25:25 UTC
This works well in my testing, signing off
Comment 13 Björn Nylén 2021-03-05 10:54:47 UTC
(In reply to Martin Renvoize from comment #9)
> Did you have a chance to test this Björn?

Sorry, didn't figure out a good way to force a timeout in my testingenv. Worked around the timeouts in other ways so it got forgotten.
Comment 14 Martin Renvoize 2021-03-05 11:02:09 UTC
No worries, I managed to replicate it here for testing (give a broken marc record).

Not sure who I'm going to find to QA it though.. there's not many people with the right expertise in this field :(
Comment 15 Joonas Kylmälä 2021-03-30 10:10:53 UTC
This seems like a great improvement. Looking into this right now. In the future we could also add retry mechanism when encountering a timeout in indexing.
Comment 16 Martin Renvoize 2021-03-30 10:35:21 UTC
(In reply to Joonas Kylmälä from comment #15)
> This seems like a great improvement. Looking into this right now. In the
> future we could also add retry mechanism when encountering a timeout in
> indexing.

I'd love to see retry and things in the future.. This is a great first step though, thanks for taking a look
Comment 17 Joonas Kylmälä 2021-03-30 11:54:03 UTC
The proposed feature doesn't work, I get error:

> try() encountered an unexpected argument (5000) - perhaps a missing semi-colon > before or at /kohadevbox/koha/misc/search_tools/rebuild_elasticsearch.pl line > 317.
> Something went wrong rebuilding indexes for kohadev

Please also add spaces and tabs similarly as they are in the other parts of the modified files.
Comment 18 Nick Clemens 2021-03-30 14:25:59 UTC
Created attachment 119014 [details] [review]
Bug 26312: (follow-up) Fix whitespace and missing semicolon
Comment 19 Joonas Kylmälä 2021-03-31 07:58:18 UTC
Now it gives the following warnings:

> Use of uninitialized value in string eq at /kohadevbox/koha/misc/search_tools/rebuild_elasticsearch.pl line 352.

and 

> [8012] Use of uninitialized value $msg in concatenation (.) or string at /kohadevbox/koha/misc/search_tools/rebuild_elasticsearch.pl line 379.

Hmmm, because of the last error/warning I think the intended error message for timeout doesn't come up?
Comment 20 Nick Clemens 2021-03-31 12:10:08 UTC
(In reply to Joonas Kylmälä from comment #19)
> Now it gives the following warnings:
> 
> > Use of uninitialized value in string eq at /kohadevbox/koha/misc/search_tools/rebuild_elasticsearch.pl line 352.
> 
> and 
> 
> > [8012] Use of uninitialized value $msg in concatenation (.) or string at /kohadevbox/koha/misc/search_tools/rebuild_elasticsearch.pl line 379.
> 
> Hmmm, because of the last error/warning I think the intended error message
> for timeout doesn't come up?

Hi Joonas, can you detail how you are triggering the error/simulating a timeout?
Comment 21 Joonas Kylmälä 2021-04-01 07:13:01 UTC
Hi,

you can download and import for example https://ia600208.us.archive.org/22/items/marc_western_washington_univ/wwu_bibs.mrc_revrev.mrc to kohadevbox and after few thousand of those are in start indexing with:

> koha-elasticsearch -v -p 5 --commit 1000 --rebuild kohadev

and also 

> docker exec -it koha_es_1 bash
> vi config/jvm.options

and modify the JVM heap size to 50Mb:

> -Xms50m
> -Xmx50m

and then 

> docker restart koha_es_1
Comment 22 Nick Clemens 2021-04-01 13:51:39 UTC
Created attachment 119079 [details] [review]
Bug 26312: (follow-up) Fix passing of exception messages

'error' has special meaning in exceptions so naming the fields:
type, details

Rather than only dealing with a single exception type, we generically
get the ES exception info and pass it up.

I could not recreate timeout still, however, I simply restarted the
ES docker during commit stage to cause NoNodes exceptions
Comment 23 Victor Grousset/tuxayo 2021-04-12 19:08:08 UTC
Tested the thing with
koha-elasticsearch -v -p 5 --commit 1000 --rebuild kohadev
and running
docker restart koha_es_1
when the process was at step "Processing slice 5 of 5"

It still died even though the output was different:
[995] Processing slice 5 of 5
[995] Indexing biblios
[796] Committing final records...
[992] Committing final records...
[Bad response received when submitting request to Elasticsearch][Bad response received when submitting request to Elasticsearch][995] Committing final records...
[994] Committing final records...
Something went wrong rebuilding indexes for kohadev
root@kohadevbox:koha(testing-SO-QA)$ [Bad response received when submitting request to Elasticsearch][Bad response received when submitting request to Elasticsearch][993] Committing final records...
[Bad response received when submitting request to Elasticsearch]

note that shell prompt appeared when processing was still happening in the background and additional error message where outputted after.

Did I miss something?
Comment 24 Victor Grousset/tuxayo 2021-04-12 20:25:45 UTC
Wait, the issue was that ES needed time to restart
So if I use a batch size of 1
koha-elasticsearch -v -p 1 --commit 1 --rebuild kohadev
or
misc/search_tools/rebuild_elasticsearch.pl -v -d -c 1

ES has the time to restart and then commits start to succeed again.
So it seems to work.
Continuing testing :)
Comment 25 Victor Grousset/tuxayo 2021-04-14 18:45:20 UTC
(In reply to Joonas Kylmälä from comment #21)
> you can download and import for example
> https://ia600208.us.archive.org/22/items/marc_western_washington_univ/
> wwu_bibs.mrc_revrev.mrc to kohadevbox and after few thousand of those are in
> start indexing with:
> 
> > koha-elasticsearch -v -p 5 --commit 1000 --rebuild kohadev

Upload worked but I couldn't complete the staging so couldn't try to import. The process took all my free ram and swap (6.5 GiB) and I killed it before it would cause a system freeze or other processes to be killed. Should one just have more that 6.5 G free ram+swap to be able to complete the staging or did I went in the wrong direction?
Comment 26 Victor Grousset/tuxayo 2021-04-14 18:55:13 UTC
(In reply to Joonas Kylmälä from comment #21)
> and also 
> 
> > docker exec -it koha_es_1 bash
> > vi config/jvm.options
> 
> and modify the JVM heap size to 50Mb:
> 
> > -Xms50m
> > -Xmx50m
> 
> and then 
> 
> > docker restart koha_es_1

So I did without the patches
docker exec -it koha_es_1 bash
vi config/jvm.options
try with various values
-Xms50m
-Xmx50m

-Xms10m
-Xmx10m

-Xms10k
-Xmx10k
docker restart koha_es_1
and then
koha-elasticsearch -v -p 5 --commit 1000 --rebuild kohadev

Each time the reindex went without issue. Are there additional steps?
Comment 27 Joonas Kylmälä 2021-04-15 07:03:52 UTC
(In reply to Victor Grousset/tuxayo from comment #26)
> Each time the reindex went without issue. Are there additional steps?

No other steps (except don't have too fast computer I guess) And it required the biblios to be imported to work. The importing works on command line, I used bulkmarcimport.pl if I don't remember wrong.
Comment 28 Joonas Kylmälä 2021-04-15 11:30:31 UTC
Created attachment 119612 [details] [review]
Bug 26312: Catch ES Client errors, log, and continue indexing when error encountered

This catches a timeout response from the ES server, logs this, and continues the indexing

To test:
1 - perl misc/search_tools/rebuild_elasticsearch.pl
2 - Make the ES server timeout (I don't have good instruction yet)
3 - Watch the job crash
4 - Apply patches
5 - perl misc/search_tools/rebuild_elasticsearch.pl
6 - Make the server timeout
7 - Note the job reports failed commit, and continues

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi>
Comment 29 Joonas Kylmälä 2021-04-15 11:30:35 UTC
Created attachment 119613 [details] [review]
Bug 26312: (follow-up) Reset buffers even if commit fails

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi>
Comment 30 Joonas Kylmälä 2021-04-15 11:30:39 UTC
Created attachment 119614 [details] [review]
Bug 26312: (follow-up) Fix whitespace and missing semicolon

Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi>
Comment 31 Joonas Kylmälä 2021-04-15 11:30:44 UTC
Created attachment 119615 [details] [review]
Bug 26312: (follow-up) Fix passing of exception messages

'error' has special meaning in exceptions so naming the fields:
type, details

Rather than only dealing with a single exception type, we generically
get the ES exception info and pass it up.

I could not recreate timeout still, however, I simply restarted the
ES docker during commit stage to cause NoNodes exceptions

Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi>
Comment 32 Joonas Kylmälä 2021-04-15 11:31:29 UTC
The error is handled now nicely:

> [30266] Elasticsearch exception thrown: Timeout

and this QA tool error seems to be false positive:

>   FAIL	  pod coverage
> 		POD is missing for 'description'

Passing QA.
Comment 33 Jonathan Druart 2021-04-16 09:49:38 UTC
Created attachment 119699 [details] [review]
Bug 26312: Catch ES Client errors, log, and continue indexing when error encountered

This catches a timeout response from the ES server, logs this, and continues the indexing

To test:
1 - perl misc/search_tools/rebuild_elasticsearch.pl
2 - Make the ES server timeout (I don't have good instruction yet)
3 - Watch the job crash
4 - Apply patches
5 - perl misc/search_tools/rebuild_elasticsearch.pl
6 - Make the server timeout
7 - Note the job reports failed commit, and continues

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi>

Bug 26312: (follow-up) Reset buffers even if commit fails

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi>

Bug 26312: (follow-up) Fix whitespace and missing semicolon

Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi>
Comment 34 Jonathan Druart 2021-04-16 09:49:43 UTC
Created attachment 119700 [details] [review]
Bug 26312: (follow-up) Fix passing of exception messages

'error' has special meaning in exceptions so naming the fields:
type, details

Rather than only dealing with a single exception type, we generically
get the ES exception info and pass it up.

I could not recreate timeout still, however, I simply restarted the
ES docker during commit stage to cause NoNodes exceptions

Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi>
Comment 35 Jonathan Druart 2021-04-16 09:50:28 UTC
Patches squashed (indentation fix)
Comment 36 Jonathan Druart 2021-04-16 10:29:27 UTC
Pushed to master for 21.05, thanks to everybody involved!
Comment 37 Fridolin Somers 2021-04-19 13:15:44 UTC
Pushed to 20.11.x for 20.11.05
Comment 38 Andrew Fuerste-Henry 2021-04-25 15:26:15 UTC
Pushed to 20.05.x for 20.05.11
Comment 39 Victor Grousset/tuxayo 2021-04-25 20:30:20 UTC
Hi, trying to backport to 19.11.x.
I had a conflict but I'm not very sure about it's resolution.

Here it is.
== The conflict ==

3 parts of the conflict view:

<<<<<<< HEAD
THIS IS 19.11 before the patch
|||||||
THIS IS 20.05 before the patch
=======
THIS IS 20.05 after the patch
>>>>>>>

↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓

<<<<<<< HEAD
        $response = $elasticsearch->bulk(
            index => $conf->{index_name},
            type => 'data', # is just hard coded in Indexer.pm?
            body => \@body
        );
||||||| parent of a60a3b26d7 (Bug 26312: Catch ES Client errors, log, and continue indexing when error encountered)
        my $elasticsearch = $self->get_elasticsearch();
        $response = $elasticsearch->bulk(
            index => $self->index_name,
            type => 'data', # is just hard coded in Indexer.pm?
            body => \@body
        );
        if ($response->{errors}) {
            carp "One or more ElasticSearch errors occurred when indexing documents";
        }
=======
        try{
            my $elasticsearch = $self->get_elasticsearch();
            $response = $elasticsearch->bulk(
                index => $self->index_name,
                type => 'data', # is just hard coded in Indexer.pm?
                body => \@body
            );
            if ($response->{errors}) {
                carp "One or more ElasticSearch errors occurred when indexing documents";
            }
        } catch {
            if( ref $_ eq 'Search::Elasticsearch::Error::Timeout' ){
            Koha::Exceptions::Elasticsearch::BadResponse->throw(
                error => "Record commit failed.",
                details => "Timeout",
            );
            }
        };
>>>>>>> a60a3b26d7 (Bug 26312: Catch ES Client errors, log, and continue indexing when error encountered)


== The resolution ==
        try{
            $response = $elasticsearch->bulk(
                index => $conf->{index_name},
                type => 'data', # is just hard coded in Indexer.pm?
                body => \@body
            );
        } catch {
            if ( ref $_ eq 'Search::Elasticsearch::Error::Timeout' ) {
                Koha::Exceptions::Elasticsearch::BadResponse->throw(
                    error => "Record commit failed.",
                    details => "Timeout",
                );
            }
        };
But I'm not sure not to have caused a side effect when filtering the changes to keep between 19.11 and 20.05

There are also two other minor conflicts. Not worried about these.

== Test ==
misc/search_tools/rebuild_elasticsearch.pl -v -d -c 1
# PLUS
docker restart koha_es_1
# during the process
# It did show the expected difference with and without the patch

But still worried about an eventual side effect.

If someone would like to have this in 19.11.x some review is need.
Comment 40 Victor Grousset/tuxayo 2021-04-25 21:38:43 UTC
Test branch with the patches in case that helps.

https://gitlab.com/tuxayo/Koha/-/commits/19.11.x-test-26312