Bug 26854

*** Bug 25810 has been marked as a duplicate of this bug. ***

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...

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.

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.

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)

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.

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>

I've tested as per the test plan, hopefully someone else understands the technical details for this one!

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.

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>

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

Shouldn't we use the log dir defined in the log4perl config file?

(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.

The log should also be automatically rotated by "debian/koha-common.logrotate", so it's new presence shouldn't cause any difficulties.

(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.

(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...)

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)...

(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...

(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.

(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?

Created attachment 113819 [details] [review]
Bug 26854: Remove log of STDERR

See discussion on comments 12-20

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 (?!)

(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?

Pushed to master for 20.11, thanks to everybody involved!

(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.

(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.

(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...

(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

Backported to 20.05.x for 20.05.07

Backported to 19.11.x branch for 19.11.13