Bug 26854 - stage-marc-import.pl does not properly fork
Summary: stage-marc-import.pl does not properly fork
Status: Pushed to oldoldstable
Alias: None
Product: Koha
Classification: Unclassified
Component: MARC Bibliographic record staging/import (show other bugs)
Version: master
Hardware: All All
: P5 - low major (vote)
Assignee: David Cook
QA Contact: Martin Renvoize
URL:
Keywords:
: 25810 (view as bug list)
Depends on:
Blocks:
 
Reported: 2020-10-29 02:52 UTC by David Cook
Modified: 2020-12-10 16:34 UTC (History)
6 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Text to go in the release notes:
Version(s) released in:
20.11.00, 20.05.07, 19.11.13


Attachments
Bug 26854: Close STDERR when forking stage-marc-import.pl (2.32 KB, patch)
2020-10-29 04:29 UTC, David Cook
Details | Diff | Splinter Review
Bug 26854: Close STDERR when forking stage-marc-import.pl (2.37 KB, patch)
2020-11-05 04:45 UTC, David Nind
Details | Diff | Splinter Review
Bug 26854: Close STDERR when forking stage-marc-import.pl (2.43 KB, patch)
2020-11-16 10:08 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 26854: Remove log of STDERR (1.08 KB, patch)
2020-11-19 14:50 UTC, Jonathan Druart
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description David Cook 2020-10-29 02:52:47 UTC
When stage-marc-import.pl forks, the child process closes STDOUT, but it does not close STDERR, which is also connected to the Apache httpd parent process.

This means that the parent stage-marc-import.pl process becomes a zombie process, as Apache httpd (apache2 2.4.25 Debian 9 && apache2 2.4.29 Ubuntu 18.04 && apache2 2.4.33 openSUSE Leap 15.1) does not reap it, as you can see below:

kohadev+ 32716 32712 74 02:17 ?        00:00:26 [stage-marc-impo] <defunct>
kohadev+ 32725     1 28 02:18 ?        00:00:02 /usr/bin/perl /kohadevbox/koha/tools/stage-marc-import.pl

The above happens when running CGI-only Koha or Plack-enabled Koha which does not proxy stage-marc-import.pl.

Across 3 different Koha instances, I am experiencing different outcomes in the web browser, although ultimately the forked child process does stage the records (unless bug 26853 occurs).

--

That said, I have noticed something interesting. On openSUSE with CGI, I'm seeing a 200 in the browser, although the AJAX request does not complete, so the polling of background-job-progress.pl does not happen. On Ubuntu 18.04 with Plack, Apache returns a 502 to the browser. On Debian 9 with Plack (koha-testing-docker), no status is returned but it doesn't timeout. 

Possibly differences include different Apache httpd behaviour and different Apache configuration. If we fix this issue, I think that we'll find that behaviour across the different instances becomes more consistent.
Comment 1 David Cook 2020-10-29 02:54:28 UTC
*** Bug 25810 has been marked as a duplicate of this bug. ***
Comment 2 David Cook 2020-10-29 02:57:04 UTC
Of course, if we close STDERR in the child, we lose the logs. I'll look to see if I can do something clever there...
Comment 3 David Cook 2020-10-29 03:01:13 UTC
Note the following from https://perldoc.perl.org/functions/fork:

"Note that if your forked child inherits system file descriptors like STDIN and STDOUT that are actually connected by a pipe or socket, even if you exit, then the remote server (such as, say, a CGI script or a backgrounded job launched from a remote shell) won't think you're done. You should reopen those to /dev/null if it's any issue."

While they only list STDIN and STDOUT, when it comes to CGI all of STDIN, STDOUT, and STDERR of the CGI script are connected to the web server.
Comment 4 David Cook 2020-10-29 03:03:34 UTC
Note that in the case of openSUSE apache2 2.4.33 with CGI, eventually the zombie process is reaped, and that's when the AJAX request finally completes and the background-job-progress.pl polling starts. 

I have no idea why the Ubuntu 18.04 apache2 2.4.29 times out while the others do not.
Comment 5 David Cook 2020-10-29 04:29:28 UTC
Created attachment 112655 [details] [review]
Bug 26854: Close STDERR when forking stage-marc-import.pl

We need to close STDERR when forking stage-marc-import.pl,
or else the CGI session with Apache httpd does not properly
finish. This leads to unexpected behaviour across different httpd
versions, operating systems, etc.

This patch closes the STDERR file handle when forking a child
process to do MARC imports, and it re-opens STDERR to a log file
in the logdir directory to catch any import errors.

Test plan:
1. Apply the patch
2. Go to http://localhost:8081/cgi-bin/koha/tools/stage-marc-import.pl
3. Upload a MARC file with a large number of records (e.g. 30,000 records)
4. Open F12 dev tools
5. Click on "Network" tab
6. Clear all existing network logs
7. Click "Stage for import"
8. After ~30 seconds, the request to stage-marc-import.pl should return a 200 code
9. Immediately, calls to background-job-progress.pl should start, and the "Job progress"
bar should update at a maximum rate of every .5 seconds
(or more realistically 1-2 seconds)
Comment 6 David Cook 2020-10-29 05:37:16 UTC
Note: You can actually test this with as little as 436 records actually. I exported the koha-testing-docker database and re-imported it, and it demonstrated the change well.
Comment 7 David Nind 2020-11-05 04:45:04 UTC
Created attachment 113029 [details] [review]
Bug 26854: Close STDERR when forking stage-marc-import.pl

We need to close STDERR when forking stage-marc-import.pl,
or else the CGI session with Apache httpd does not properly
finish. This leads to unexpected behaviour across different httpd
versions, operating systems, etc.

This patch closes the STDERR file handle when forking a child
process to do MARC imports, and it re-opens STDERR to a log file
in the logdir directory to catch any import errors.

Test plan:
1. Apply the patch
2. Go to http://localhost:8081/cgi-bin/koha/tools/stage-marc-import.pl
3. Upload a MARC file with a large number of records (e.g. 30,000 records)
4. Open F12 dev tools
5. Click on "Network" tab
6. Clear all existing network logs
7. Click "Stage for import"
8. After ~30 seconds, the request to stage-marc-import.pl should return a 200 code
9. Immediately, calls to background-job-progress.pl should start, and the "Job progress"
bar should update at a maximum rate of every .5 seconds
(or more realistically 1-2 seconds)

Signed-off-by: David Nind <david@davidnind.com>
Comment 8 David Nind 2020-11-05 04:46:13 UTC
I've tested as per the test plan, hopefully someone else understands the technical details for this one!
Comment 9 David Cook 2020-11-05 23:04:44 UTC
I should flag here for QA that I do something a bit cheeky in this patch.

I add a new log file called "background-jobs.log" to log any errors generated by the child stage-marc-import.pl process. 

I'm happy to discuss what log file gets used, of course. And rather be upfront about it rather than requiring someone to dig that out of the patch.
Comment 10 Martin Renvoize 2020-11-16 10:08:35 UTC
Created attachment 113656 [details] [review]
Bug 26854: Close STDERR when forking stage-marc-import.pl

We need to close STDERR when forking stage-marc-import.pl,
or else the CGI session with Apache httpd does not properly
finish. This leads to unexpected behaviour across different httpd
versions, operating systems, etc.

This patch closes the STDERR file handle when forking a child
process to do MARC imports, and it re-opens STDERR to a log file
in the logdir directory to catch any import errors.

Test plan:
1. Apply the patch
2. Go to http://localhost:8081/cgi-bin/koha/tools/stage-marc-import.pl
3. Upload a MARC file with a large number of records (e.g. 30,000 records)
4. Open F12 dev tools
5. Click on "Network" tab
6. Clear all existing network logs
7. Click "Stage for import"
8. After ~30 seconds, the request to stage-marc-import.pl should return a 200 code
9. Immediately, calls to background-job-progress.pl should start, and the "Job progress"
bar should update at a maximum rate of every .5 seconds
(or more realistically 1-2 seconds)

Signed-off-by: David Nind <david@davidnind.com>
Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 11 Martin Renvoize 2020-11-16 10:10:29 UTC
This patch achieves the desired effect and the code is clear.  I'm happy with the log file as is myself, but defer the final decision to the RM.. I may be overlooking something there.

Passing QA
Comment 12 Jonathan Druart 2020-11-16 12:57:58 UTC
Shouldn't we use the log dir defined in the log4perl config file?
Comment 13 David Cook 2020-11-16 23:20:39 UTC
(In reply to Jonathan Druart from comment #12)
> Shouldn't we use the log dir defined in the log4perl config file?

I am not sure that I understand your question.

logdir in etc/koha-conf.xml is set by __LOG_DIR__ and the log dir in etc/log4perl.conf is also set by __LOG_DIR__, so it's the same log directory.

The log4perl config file is also not able to be parsed by anything except Log4Perl, and using Log4Perl isn't really an option here without rewriting tools/stage-marc-import.pl to use Log4Perl instead of using the warn built-in.
Comment 14 David Cook 2020-11-16 23:21:53 UTC
The log should also be automatically rotated by "debian/koha-common.logrotate", so it's new presence shouldn't cause any difficulties.
Comment 15 Jonathan Druart 2020-11-17 09:57:57 UTC
(In reply to David Cook from comment #13)
> (In reply to Jonathan Druart from comment #12)
> > Shouldn't we use the log dir defined in the log4perl config file?
> 
> I am not sure that I understand your question.
> 
> logdir in etc/koha-conf.xml is set by __LOG_DIR__ and the log dir in
> etc/log4perl.conf is also set by __LOG_DIR__, so it's the same log directory.

At the instance creation, yes. But you can modify it.

> The log4perl config file is also not able to be parsed by anything except
> Log4Perl, and using Log4Perl isn't really an option here without rewriting
> tools/stage-marc-import.pl to use Log4Perl instead of using the warn
> built-in.

It seems that the 'logdir' from the Koha config file is only used by installer/install.pl and misc/cronjobs/edi_cron.pl
And so I guess we should remove it in favour or the Log4Perl one. With that in mind I don't think it's a good idea to add another occurrence.

I think we should push this without the log, it's what we are doing for all other background jobs anyway.
Comment 16 David Cook 2020-11-17 22:57:09 UTC
(In reply to Jonathan Druart from comment #15)
> (In reply to David Cook from comment #13)
> > (In reply to Jonathan Druart from comment #12)
> > > Shouldn't we use the log dir defined in the log4perl config file?
> > 
> > I am not sure that I understand your question.
> > 
> > logdir in etc/koha-conf.xml is set by __LOG_DIR__ and the log dir in
> > etc/log4perl.conf is also set by __LOG_DIR__, so it's the same log directory.
> 
> At the instance creation, yes. But you can modify it.
 
True. I suppose that's true for the Apache config too.

koha-create appears to be hard-coded...

> > The log4perl config file is also not able to be parsed by anything except
> > Log4Perl, and using Log4Perl isn't really an option here without rewriting
> > tools/stage-marc-import.pl to use Log4Perl instead of using the warn
> > built-in.
> 
> It seems that the 'logdir' from the Koha config file is only used by
> installer/install.pl and misc/cronjobs/edi_cron.pl

That is interesting. 

> And so I guess we should remove it in favour or the Log4Perl one. With that
> in mind I don't think it's a good idea to add another occurrence.

But how could we use the Log4Perl one without Log4Perl?

> I think we should push this without the log, it's what we are doing for all
> other background jobs anyway.

Which other background jobs do you mean? 

If we don't use the log, then any output from the backgrounded stage-marc-import.pl will be completely lost. 

That said, I don't love adding a new log file. I'm just not sure about any other viable alternatives.

In any case, whatever we do here will be a temporary solution anyway. Once 20.11 is released and RabbitMQ has been around for a little while, I am thinking about rewriting the stage-marc-import.pl backend to use RabbitMQ. (After I finish bug 26791 of course...)
Comment 17 David Cook 2020-11-17 23:03:59 UTC
Actually... Bug 16357 was pushed on 2020-09-28... and we are overriding __WARN__ there to use Log4Perl, so maybe we don't need that log file after all (when using Plack)...
Comment 18 David Cook 2020-11-17 23:14:43 UTC
(In reply to David Cook from comment #17)
> Actually... Bug 16357 was pushed on 2020-09-28... and we are overriding
> __WARN__ there to use Log4Perl, so maybe we don't need that log file after
> all (when using Plack)...

Alas, the LogWarn middleware doesn't work here.

It'll be due to some combination of the forking and STDERR being closed. Might not be worth pursuing that one too deeply.

I suppose those a fairly simple fix would be to create a SIGWARN handler to use Log4Perl in the forked stage-marc-import.pl. That would be a fairly light touch and it would save a new log file and using that logdir config property...
Comment 19 Jonathan Druart 2020-11-18 08:23:16 UTC
(In reply to David Cook from comment #16)
> (In reply to Jonathan Druart from comment #15)
> > I think we should push this without the log, it's what we are doing for all
> > other background jobs anyway.
> 
> Which other background jobs do you mean? 

All other background jobs (using C4::BackgroundJob)

offline_circ/process_koc.pl:            close STDERR;
tools/batchMod.pl:        close STDERR;
tools/manage-marc-import.pl:        close STDERR;


> If we don't use the log, then any output from the backgrounded
> stage-marc-import.pl will be completely lost. 

What's done for other background jobs.

> That said, I don't love adding a new log file. I'm just not sure about any
> other viable alternatives.

Can we deal with that on a separate bug report? :)

Either we have it pushed for 20.11 without the new log file, or we wait for 21.05. I let you decide what's best for you.
Comment 20 David Cook 2020-11-19 03:07:28 UTC
(In reply to Jonathan Druart from comment #19)
> Either we have it pushed for 20.11 without the new log file, or we wait for
> 21.05. I let you decide what's best for you.

I reckon let's push for 20.11 without the new log file.

Do you want a new patch or are you going to modify it yourself?
Comment 21 Jonathan Druart 2020-11-19 14:50:30 UTC
Created attachment 113819 [details] [review]
Bug 26854: Remove log of STDERR

See discussion on comments 12-20
Comment 22 Jonathan Druart 2020-11-19 14:52:09 UTC
David, to be discussed on a separated bug report but, did you make the log work?

It kind of worked for me, but I got the log in /var/log/koha/kohadev/sip.log (?!)
Comment 23 David Cook 2020-11-20 03:25:27 UTC
(In reply to Jonathan Druart from comment #22)
> David, to be discussed on a separated bug report but, did you make the log
> work?
> 

Well, I didn't try to make it work. Rather, I wondered if Bug 16357 would cause the output to be logged to plack-intranet-error.log, but it was only logged to background-jobs.log. 

> It kind of worked for me, but I got the log in /var/log/koha/kohadev/sip.log
> (?!)

Can you tell me more about that? Did you alter the config at all to do that?
Comment 24 Jonathan Druart 2020-11-20 07:18:54 UTC
Pushed to master for 20.11, thanks to everybody involved!
Comment 25 Jonathan Druart 2020-11-20 07:42:18 UTC
(In reply to David Cook from comment #23)
> (In reply to Jonathan Druart from comment #22)
> > It kind of worked for me, but I got the log in /var/log/koha/kohadev/sip.log
> > (?!)
> 
> Can you tell me more about that? Did you alter the config at all to do that?

I run into it when I wrote bug 26557. And Victor saw it too when he tested it.
Comment 26 Jonathan Druart 2020-11-20 07:43:42 UTC
(In reply to Jonathan Druart from comment #25)
> (In reply to David Cook from comment #23)
> > (In reply to Jonathan Druart from comment #22)
> > > It kind of worked for me, but I got the log in /var/log/koha/kohadev/sip.log
> > > (?!)
> > 
> > Can you tell me more about that? Did you alter the config at all to do that?
> 
> I run into it when I wrote bug 26557. And Victor saw it too when he tested
> it.

So, I was writting bug 26557 on top of your patch. But I bet Victor didn't.
Comment 27 David Cook 2020-11-23 03:45:20 UTC
(In reply to Jonathan Druart from comment #25)
>
> I run into it when I wrote bug 26557. And Victor saw it too when he tested
> it.

Interesting. I'd like to hear more about it. I haven't been able to reproduce it...
Comment 28 Jonathan Druart 2020-11-24 08:46:34 UTC
(In reply to David Cook from comment #27)
> (In reply to Jonathan Druart from comment #25)
> >
> > I run into it when I wrote bug 26557. And Victor saw it too when he tested
> > it.
> 
> Interesting. I'd like to hear more about it. I haven't been able to
> reproduce it...

Pretty easy to recreate:
- Fresh KTD
- revert patch from bug 26557 (279ce72e4ced3ca191a8ee4e109c28df169dfc20)
- restart_all
- tail -f /var/log/koha/kohadev/*
- Repeat test plan from bug 26557
Comment 29 Andrew Fuerste-Henry 2020-12-09 21:28:33 UTC
Backported to 20.05.x for 20.05.07
Comment 30 Victor Grousset/tuxayo 2020-12-10 16:34:48 UTC
Backported to 19.11.x branch for 19.11.13