Bug 26128 - Proxy Error while importing a large number of patrons (e.g. 6000 patrons) with Plack
Summary: Proxy Error while importing a large number of patrons (e.g. 6000 patrons) wit...
Status: REOPENED
Alias: None
Product: Koha
Classification: Unclassified
Component: Staff interface (show other bugs)
Version: Main
Hardware: All All
: P5 - low normal with 10 votes (vote)
Assignee: Ulrich Kleiber
QA Contact: Testopia
URL:
Keywords:
: 26254 (view as bug list)
Depends on:
Blocks:
 
Reported: 2020-08-03 12:24 UTC by Ulrich Kleiber
Modified: 2020-12-14 00:44 UTC (History)
6 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:


Attachments
Bug 26128: Proxy Error while importing patrons (976 bytes, patch)
2020-08-03 12:47 UTC, Ulrich Kleiber
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Ulrich Kleiber 2020-08-03 12:24:46 UTC

    
Comment 1 Ulrich Kleiber 2020-08-03 12:47:25 UTC
Created attachment 107702 [details] [review]
Bug 26128: Proxy Error while importing patrons

Current status: NEW
Comment 2 Ulrich Kleiber 2020-08-03 13:09:22 UTC
The script import_borrowers.pl doesn't seem to be 'plack-save'.

Test plan with plack enabled (tested with Koha 18.11):

1) Import a large number of patrons e.g. 6000 patrons
2) You get a proxy error
3) Apply patch.
4) Repeat step 1
5) The proxy error does not occur anymore
Comment 3 Katrin Fischer 2020-08-20 07:38:30 UTC
*** Bug 26254 has been marked as a duplicate of this bug. ***
Comment 4 David Cook 2020-08-20 23:25:34 UTC
After quickly reviewing the code, I don't see anything that is particularly Plack unfriendly. The non-proxying of certain CGI scripts was due to them forking (like Bug 15032). 

But this code doesn't seem to have that problem. It just seems like it's probably long-running code. 

What proxy error is received and how long does it take to receive it? Is it 300+ seconds or less? 

If ProxyTimeout is not defined in Apache, it should use Timeout, which I think should default to 300 in Debian and Ubuntu.
Comment 5 Ulrich Kleiber 2020-08-21 06:39:21 UTC
I don't now the real reason for this bug, but without Plack there is no ProxyError and no Timeout. With 6000 patrons, the script runs for approximately 8 minutes.
Comment 6 David Cook 2020-08-23 23:43:05 UTC
(In reply to Ulrich Kleiber from comment #5)
> I don't now the real reason for this bug, but without Plack there is no
> ProxyError and no Timeout. With 6000 patrons, the script runs for
> approximately 8 minutes.

That's interesting. I would expect Apache httpd to timeout after 5 minutes. How do you have Koha installed? Can you verify your Apache configuration?
Comment 7 Ulrich Kleiber 2020-09-03 08:24:23 UTC
We use Debian packages and the Apache configuration is correct. We are happy with our solution.
Comment 8 David Cook 2020-09-03 23:13:50 UTC
(In reply to Ulrich Kleiber from comment #7)
> We use Debian packages and the Apache configuration is correct. We are happy
> with our solution.

Hi Ulrich, that doesn't really answer my question, but I'm glad that your solution is working for you. 

I am interested in finding a more long-term solution, so maybe you can help me by providing some more information. 

If you can provide more information about the number of columns per row in the CSV, that could be useful. 

Also, what options are used for /cgi-bin/koha/tools/import_borrowers.pl? If possible, it would be great if you could take a screenshot and upload it here.

I can look at trying to reproduce this issue, and then working out exactly why it's not working in Plack.

While I believe that your solution works, it really is more of a workaround, rather than a fix. And I'm really interested in fixing this.
Comment 9 David Cook 2020-09-03 23:20:21 UTC
Actually, while I stand by my words, I think it would be practical to proceed with your patch.

Based on Bug 15218, it looks like this file upload issues has been a problem in Koha for 5 years now, so I don't that I'm going to fix it over night.

Switching back to Needs Sign Off.
Comment 10 David Cook 2020-09-04 00:14:53 UTC
I'm going to try to reproduce in Plack using koha-testing-docker first without the patch:

Test plan:
1) Upload file with 2000 patrons (majority of columns filled)
2) "Cardnumber" used for matching
3) "Overwrite the existing one with this" for matching
4) "Replace all patron attributes" for attributes

Got the following message in my UI:

Import results :
0 imported records
0 overwritten
0 not imported because already in borrowers table and overwrite disabled
2415 not imported because they are not in the expected format
2415 records parsed

1) Replacing "branchcode" with CPL
2) Replacing "categorycode" with "PT"
3) Deleting dateenrolled (date format), dateexpiry (date format), borrowernotes (the script apparently can't handle double quotes), opacnotes (double quotes), contact note (double quotes), updated_on (date format)

I got the proxy error after importing 678 rows.

After reviewing the code and watching the database, this code is just really really slow. The code is 326 lines long and really inefficient. 

Using a bit of debugging code, I can see that the file is uploaded almost immediately the Koha server (I can see it at /tmp/H9VmB7xkED).

Trying again and I'm up to 1877 rows imported/updated before getting the error. 

I'm thinking this isn't a Plack vs CGI issue but rather a proxy issue...

Ohhhhh... this is a 502 and not a 504. I kept thinking it was a 504 Gateway Timeout, but it's actually a 502 Proxy Error:

Proxy Error
The proxy server received an invalid response from an upstream server.
The proxy server could not handle the request

Reason: Error reading from remote server

I notice I am still getting some database errors. I wonder what kind of response it is generating...
Comment 11 David Cook 2020-09-04 00:23:18 UTC
Wow yeah it just took like 10 seconds to do 1 patron. 

On my 3rd try I did not get the 502 with the same dateset:

Import results :
22 imported records
2114 overwritten
0 not imported because already in borrowers table and overwrite disabled
205 not imported because they are not in the expected format
2341 records parsed
Comment 12 David Cook 2020-09-04 00:40:05 UTC
No errors on my 4th try with the same dataset.

Import results :
0 imported records
2134 overwritten
0 not imported because already in borrowers table and overwrite disabled
207 not imported because they are not in the expected format
2341 records parsed
Back to Tools

It looks like it took from 00:23:09 to 00:27:14

So just over 4 minutes and 5 seconds. Very close to a timeout. 

It looks like about 5-10 records *updated* per second. The average is 9.55 records *processed* per second. 

If you have a max of 300 seconds, then the max records processed in that time would be 2,865 records. 

But I suspect that the average goes way down when importing rather than overwriting records. 

Which is why I'll delete those borrowers, retry, and evaluate the import rate...
Comment 13 David Cook 2020-09-04 00:42:14 UTC
Just at a glance, I'm getting between 2-4 records imported per second.
Comment 14 David Cook 2020-09-04 00:46:08 UTC
I'm going to calculate the rate, and then try with CGI...

In theory, Apache should timeout too as it would exceed 300 seconds before receiving a response from the CGI script.

Unless the non-Plack CGI script actually performs faster.
Comment 15 David Cook 2020-09-04 00:48:52 UTC
Whoa... I've received the 502 error from Apache... but the database is still being updated.

When I run "ps" on koha-testing-docker, I can see that Starman is still running /kohadevbox/koha/tools/import_borrowers.pl!

The import started at 00:40:33 and it looks like Apache would've timed out (why we're getting a 502 and not a 504 I have no idea) around 00:45:33 but we're at 00:48:15 now and it's still going.

The rate is super super slow though. In 8 minutes, it's only imported 477 rows out of 2136.
Comment 16 David Cook 2020-09-04 00:51:04 UTC
koha-plack --disable kohadev
service apache2 restart

Starting with CGI...

Started at 00:50:02

The import performance is still absolutely terrible. 1-3 rows imported per second.

Really curious what will happen at 00:55:02...
Comment 17 David Cook 2020-09-04 00:55:39 UTC
(In reply to David Cook from comment #16)
> koha-plack --disable kohadev
> service apache2 restart
> 
> Starting with CGI...
> 
> Started at 00:50:02
> 
> The import performance is still absolutely terrible. 1-3 rows imported per
> second.
> 
> Really curious what will happen at 00:55:02...

It's 00:55:19 and Apache hasn't timed out... that's bizarre.
Comment 18 David Cook 2020-09-04 01:02:40 UTC
(In reply to David Cook from comment #17)
> It's 00:55:19 and Apache hasn't timed out... that's bizarre.

Ok even more bizarre...

I just got a 504 Gateway Timeout from Apache around 01:00:02. So it ran from 00:50:02 to 01:00:02. 

10 minutes or 600 seconds...

Only 592 rows were imported, and the process is well and truly dead.
Comment 19 David Cook 2020-09-04 01:10:44 UTC
Googling around about this and it seems to be a known issue with Apache.

https://serverfault.com/questions/575252/apache-version-2-doubles-the-timeout-directive-on-requests

https://lists.debian.org/debian-apache/2015/03/msg00004.html

Looking at the Koha error logs...

[Fri Sep 04 00:55:02.986540 2020] [cgi:warn] [pid 2210] [client 172.20.0.1:42150] AH01220: Timeout waiting for output from CGI script /kohadevbox/koha/tools/import_borrowers.pl, referer: http://localhost:8081/cgi-bin/koha/tools/impor
    t_borrowers.pl
 11 [Fri Sep 04 00:55:02.986584 2020] [cgi:error] [pid 2210] [client 172.20.0.1:42150] Script timed out before returning headers: import_borrowers.pl, referer: http://localhost:8081/cgi-bin/koha/tools/import_borrowers.pl
 12 [Fri Sep 04 01:00:03.085525 2020] [cgi:warn] [pid 2210] [client 172.20.0.1:42150] AH01220: Timeout waiting for output from CGI script /kohadevbox/koha/tools/import_borrowers.pl, referer: http://localhost:8081/cgi-bin/koha/tools/impor
    t_borrowers.pl
Comment 20 David Cook 2020-09-04 01:11:30 UTC
Oh and insight into that 502 instead of the 504...

[Fri Sep 04 00:45:33.501382 2020] [proxy_http:error] [pid 1995] (70007)The timeout specified has expired: [client 172.20.0.1:42126] AH01102: error reading status line from remote server httpd-UDS:0, referer: http://localhost:8081/cgi
    -bin/koha/tools/import_borrowers.pl
[Fri Sep 04 00:45:33.501517 2020] [proxy:error] [pid 1995] [client 172.20.0.1:42126] AH00898: Error reading from remote server returned by /cgi-bin/koha/tools/import_borrowers.pl, referer: http://localhost:8081/cgi-bin/koha/tools/imp
    ort_borrowers.pl
Comment 21 David Cook 2020-09-04 02:20:26 UTC
I'm reading through the httpd source code for 2.4.25 (the Apache httpd used in koha-testing-docker) from https://github.com/apache/httpd, and it's not clear why Apache didn't return the 504 until after 10 minutes (600 seconds).

Looking at "modules/generators/mod_cgi.c", I can see the "cgi_handler"...

It calls "run_cgi_child", and it sets a timeout "apr_file_pipe_timeout_set(*script_out, r->server->timeout);"

The "cgi_handler" calls "apr_bucket_read" which should map to "cgi_bucket_read". That runs "rv = apr_pollset_poll(data->pollset, timeout, &num, &results);" in a loop, which runs the following:

if (APR_STATUS_IS_TIMEUP(rv)) {
    if (timeout) {
        ap_log_rerror(APLOG_MARK, APLOG_WARNING, 0, data->r, APLOGNO(01220)
                      "Timeout waiting for output from CGI script %s",
                      data->r->filename);
        return rv;
    }
    else {
        return APR_EAGAIN;
    }
}

Based on the Koha Apache logs, we did get this after the first 5 minutes (300 seconds). 

But then we got the message "Script timed out before returning headers"...

So if we keep going down the "cgi_handler", we get to "ap_scan_script_header_err_brigade_ex", which ultimately maps to "ap_scan_script_header_err_core_ex" in "server/util_script.c". We can see the following code there:

ap_log_rerror(SCRIPT_LOG_MARK, APLOG_ERR|APLOG_TOCLIENT, 0, r,
              "Script timed out before returning headers: %s",
              apr_filepath_name_get(r->filename));
return HTTP_GATEWAY_TIME_OUT;

Now that should've been when we got our 504 from Apache httpd... but it's not. As per the Koha Apache logs, there was a "Timeout waiting for output from CGI script" timeout followed by "Script timed out before returning headers", but the CGI script kept running after that and unless I got my timing wrong (which is possible) then Apache kept running too... since we got a 2nd "Timeout waiting for output from CGI script" timeout.

It's almost like it tried to gracefully stop/close the CGI script... but then after getting another timeout it just killed it. 

It does look like after "ap_scan_script_header_err_brigade_ex" returns then "log_script" is run... and that runs "discard_script_output" and that does another "apr_bucket_read" although I think that's for a different bucket...
Comment 22 David Cook 2020-09-04 02:27:00 UTC
Started at 02:15:27... still running at 02:21:00...

My browser is still waiting for Apache...

But the Apache logs do say the following:

[Fri Sep 04 02:20:27.854260 2020] [cgi:warn] [pid 2296] [client 172.20.0.1:42178] AH01220: Timeout waiting for output from CGI script /kohadevbox/koha/tools/import_borrowers.pl, referer: http://localhost:8081/cgi-bin/koha/tools/import_bo
rrowers.pl
[Fri Sep 04 02:20:27.854290 2020] [cgi:error] [pid 2296] [client 172.20.0.1:42178] Script timed out before returning headers: import_borrowers.pl, referer: http://localhost:8081/cgi-bin/koha/tools/import_borrowers.pl

But the database is updating, browser loading, and process still running:

kohadev+  2297  2296 15 02:15 ?        00:01:02 /usr/bin/perl /kohadevbox/koha/tools/import_borrowers.pl

Now I get the 504, CGI process killed, and DB not updating

[Fri Sep 04 02:25:27.917648 2020] [cgi:warn] [pid 2296] [client 172.20.0.1:42178] AH01220: Timeout waiting for output from CGI script /kohadevbox/koha/tools/import_borrowers.pl, referer: http://localhost:8081/cgi-bin/koha/tools/import_bo
rrowers.pl
Comment 23 David Cook 2020-09-04 02:30:35 UTC
I don't think I'm going to solve the Apache issue today, but I think I've demonstrated that the problem isn't really CGI vs Plack, but rather that Apache does not process TimeOut as expected for CGI scripts (mod_cgi), whereas it *does* process TimeOut correctly when proxying HTTP (mod_proxy_http).

Rather than using CGI, my recommendation is for Koha to change either the TimeOut or ProxyTimeOut directives to 600 seconds when using Plack.

Of course, ultimately, this is still not a scalable solution. It just increases the threshold for failure.

The real solution would be to upload the file via the Web UI and then process the patron import asynchronously (which will be doable after Bug 22417 is pushed).
Comment 24 David Cook 2020-09-04 03:09:12 UTC
Doing more testing... just got a 504 Gateway Timeout around 2:58/02:59... but using 

Using the Apache ScriptLog directive, I actually see... very strange things.

I'm see 2 POSTs at 02:49:05... then a 504 that looks like it was at 02:54:05... 

It shows a 200 OK successful HTTP response dated at 02:58:39...
Comment 25 David Cook 2020-09-04 03:12:55 UTC
Doing another attempt and I see the POST being done at 03:11:13

%% [Fri Sep 04 03:11:13 2020] POST /cgi-bin/koha/tools/import_borrowers.pl HTTP/1.1
%% 200 /kohadevbox/koha/tools/import_borrowers.pl
%error
[Fri Sep  4 03:11:13 2020] import_borrowers.pl: /tmp/wJC1_zFN37 at /kohadevbox/koha/tools/import_borrowers.pl line 121.
%% [Fri Sep 04 03:11:13 2020] POST /cgi-bin/koha/tools/import_borrowers.pl HTTP/1.1
%% 200 /kohadevbox/koha/tools/import_borrowers.pl
%error
[Fri Sep  4 03:11:13 2020] import_borrowers.pl: CGI::param called in list context from /kohadevbox/koha/tools/import_borrowers.pl line 125, this can lead to vulnerabilities. See the warning in "Fetching the value or values of a single na
med parameter" at /usr/share/perl5/CGI.pm line 412.

The logging really leaves a lot to be desired.

It looks like it's assuming a 200 code and it's not listing POSTs but just that the current request was that POST...
Comment 26 David Cook 2020-09-04 03:19:55 UTC
So started at 03:11:13...

In the ScriptLog, I see the following at 03:16:13:

%% [Fri Sep 04 03:16:13 2020] POST /cgi-bin/koha/tools/import_borrowers.pl HTTP/1.1
%% 504 /kohadevbox/koha/tools/import_borrowers.pl
%request
Host: localhost:8081
Connection: keep-alive
Content-Length: 782178
Cache-Control: max-age=0
Upgrade-Insecure-Requests: 1
Origin: http://localhost:8081
Content-Type: multipart/form-data; boundary=----WebKitFormBoundarypJ1wnOBOdpsnQP5P
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
Sec-Fetch-Site: same-origin
Sec-Fetch-Mode: navigate
Sec-Fetch-User: ?1
Sec-Fetch-Dest: document
Referer: http://localhost:8081/cgi-bin/koha/tools/import_borrowers.pl
Accept-Encoding: gzip, deflate, br
Accept-Language: en-GB,en-US;q=0.9,en;q=0.8
Cookie: marcdocs_51=show; marctags_51=show; catalogue_editor_51=advanced; CGISESSID=47097b810251d8412739d71656d51c0a

------WebKitFormBoundarypJ1wnOBOdpsnQP5P
Content-Disposition: form-data; name="uploadborrowers"; filename="patron_test.csv"
Content-Type: application/vnd.ms-excel

cardnumber,surname,firstname,title,othernames,initials,streetnumber,streettype,address,address2,city,state,zipcode,country,email,phone,mobile,fax,emailpro,phonepro,B_streetnumber,B_streettype,B_address,B_address2,B_city,B_state,B_zipcode
,B_country,B_email,B_phone,dateofbirth,branchcode,categorycode,dateenrolled,dateexpiry,date_renewed,gonenoaddress,lost,debarred,debarredcomment,contactname,contactfirstname,contacttitle,borrowernotes,relationship,sex,password,flags,useri
d,opacnote,contactnote,sort1,sort2,altcontactfirstname,altcontactsurname,altcontactaddress1,altcontactaddress2,altcontactaddress3,altcontactstate,altcontactzipcode,altcontactcountry,altcontactphone,smsalertnumber,sms_provider_id,privacy,
privacy_guarantor_fines,privacy_guarantor_checkouts,checkprevcheckout,updated_on,lastseen,lang,login_attempts,overdrive_auth_token,anon
%response

The browser is still waiting, Apache still waiting, Koha still importing...

I expect to see more content in the ScriptLog at 03:21:13 and to get a 504 response in the browser...
Comment 27 David Cook 2020-09-04 03:26:06 UTC
504 received in the browser at 03:21:13...

Database stopped updating...

Koha not running the import...

The ScriptLog file hasn't been updated though...

Anyway, I'm just going to open a bug on Apache's Bugzilla about this.
Comment 28 David Cook 2020-09-04 03:26:49 UTC
(In reply to David Cook from comment #23)
> I don't think I'm going to solve the Apache issue today, but I think I've
> demonstrated that the problem isn't really CGI vs Plack, but rather that
> Apache does not process TimeOut as expected for CGI scripts (mod_cgi),
> whereas it *does* process TimeOut correctly when proxying HTTP
> (mod_proxy_http).
> 
> Rather than using CGI, my recommendation is for Koha to change either the
> TimeOut or ProxyTimeOut directives to 600 seconds when using Plack.
> 
> Of course, ultimately, this is still not a scalable solution. It just
> increases the threshold for failure.
> 
> The real solution would be to upload the file via the Web UI and then
> process the patron import asynchronously (which will be doable after Bug
> 22417 is pushed).

Just pushing this down to the bottom so that people don't have to read through all my troubleshooting comments >_>.
Comment 29 David Cook 2020-09-04 03:46:13 UTC
(Raised issue with Apache: https://bz.apache.org/bugzilla/show_bug.cgi?id=64709)
Comment 30 Ulrich Kleiber 2020-09-04 05:50:49 UTC
Hi David, wow you have been really busy today.
Comment 31 David Cook 2020-09-04 06:28:52 UTC
(In reply to Ulrich Kleiber from comment #30)
> Hi David, wow you have been really busy today.

Tough to know sometimes whether my passion and persistence is a bug or a feature ;). 

Apologies for the verbosity, but hopefully the ultimate outcome is useful. You'll probably get slightly better performance overall by sticking with Plack and increasing the ProxyTimeout value. 

I might open a bug report in the near future to add ProxyTimeout to the Apache Plack configuration. I just want to leave it a few days to see if the Apache httpd community come back with any answers first.
Comment 32 David Cook 2020-09-07 01:49:45 UTC
(In reply to David Cook from comment #29)
> (Raised issue with Apache:
> https://bz.apache.org/bugzilla/show_bug.cgi?id=64709)

A developer from Red Hat has written a fix, and I've tested the fix, so thanks Ulrich for raising this bug report, which led to me uncovering this issue with mod_cgi!

I'm changing this to RESOLVED WONTFIX, and I'll raise a separate report about adding ProxyTimeout 600 to the Plack configuration so that the buggy CGI timeout is emulated.
Comment 33 Liz Rea 2020-10-13 16:14:27 UTC
Hi,

This is great that they're going to fix the bug in mod_cgi, but koha still takes a really long time to process these and it would be great if we could look at the scripts to not make them run so long. I have libraries easily doing jobs that will exceed 500 seconds, routinely. I don't think it's fair to ask them to split up their work because we can't get our act together and make this work better (or do it differently so that we can handle big, and I mean BIG, batch jobs). This is bad user experience.

It would still time out if the job exceeded the 600 seconds, and I think that means this isn't solved.
Comment 34 David Cook 2020-10-13 22:08:31 UTC
(In reply to Liz Rea from comment #33)
> This is great that they're going to fix the bug in mod_cgi, but koha still
> takes a really long time to process these and it would be great if we could
> look at the scripts to not make them run so long. I have libraries easily
> doing jobs that will exceed 500 seconds, routinely. I don't think it's fair
> to ask them to split up their work because we can't get our act together and
> make this work better (or do it differently so that we can handle big, and I
> mean BIG, batch jobs). This is bad user experience.

Bug 22417 has been pushed to master, so feel free to create a background task to handle large patron imports. In order to handle big batch jobs, we really need to be able to handle it asynchronously. 

> It would still time out if the job exceeded the 600 seconds, and I think
> that means this isn't solved.

Sure, although I'd argue that you should open a new bug report for that, as this one is about Plack specifically timing out, and Bug 26400 would address that.
Comment 35 AspenCat Team 2020-12-11 20:31:57 UTC
Fixing this bug would be helpful to our consortium.  I don't know what the limit is on the number of patrons we can import.  The process now is make the edits, save the file, run the import tool and wait (a very long time) to see if it will successfully load. If it doesn't load, open a ticket and send the file, update our own help ticket and then when loaded, check to see if changes were correct.  If not, start over.
Comment 36 David Cook 2020-12-14 00:44:04 UTC
It's unlikely that I'm going to work on this any time soon, since this doesn't impact any of my clients and I have other priorities. 

At this point, I'd suggest a temporary workaround of requesting a high ProxyTimeout, or asking one's vendor to create a more robust patron import. If someone sponsored the development, I could work on it, although I'd need to take some time to analyze the code to estimate the effort/cost involved.