Bug 20342

Created attachment 72481 [details] [review]
Bug 20342: Fix table locking issue, progress bar not updating, and allow use of plack for Stage MARC Import

Have you ever seen this error?
DBD::mysql::st execute failed: Deadlock found when trying to get lock; try restarting transaction [for Statement "INSERT INTO import_record_matches (import_record_id, candidate_match_id, score),

Have you ever noticed your progress bar during stage for import jumps from 0% to 100% with no updates in between?

Would you like stage-marc-import.pl to work under plack?

If you answered yes to any of the following questions, this bug is for you!

During uploads of large records using matching rules, we were getting 'Failed to submit form' popups on the marc record importer.

First, I noticed that the parent process of stage-marc-import.pl wasn't returning the job id via ajax until the child process had completed. This works fine for smaller files as they process fast. For large files ( and in particular when using matching rules ) the process takes *much* longer.

It appears that $.ajax will resubmit the form if it doesn't get a response back in a given time ( I would estimate that to be about 30 seconds or so ). This causes a *second* instance of stage-marc-import.pl to be run. So now we have two processes both running transactions on the same table for the same batch id. I believe this is what is causing the Deadlock.

So, the crux of the matter is that for whatever reason, the parent process will not output until the child process has gone away. Hours of research entailed. The final answer is that the child process must be detached from the parent process. I tried doing this via setsid() but it did not help. Finally, I found that using Net::Server::Daemonize did!

After I had my solution, I decided to see if stage-marc-import.pl and background-job-progress.pl could now be run under plack, and it appears that they can!

Test Plan:
1) Apply this patch
2) Update /etc/koha/apache-shared-intranet-plack.conf manually, comment
   out the lines for stage-marc-import.pl and  background-job-progress.pl
3) Restart apache, plack and memcached
4) Stage a large record in stage-marc-import.pl, use a matching rule
5) Note it works!

Created attachment 72483 [details] [review]
Bug 20342: Use File::Temp to get temp dir

Kyle,
I does not work for me: I have exported all my bibliographic records then import the .mrc and I get a random 500 that block the progress bar.

(In reply to Jonathan Druart from comment #3)
> Kyle,
> I does not work for me: I have exported all my bibliographic records then
> import the .mrc and I get a random 500 that block the progress bar.

Hmmm. No idea why the fix worked for me and not for you. Maybe we can get another person or two to test? It definitely worked for me. Worst case scenario would be a full reengineering of this script to split it into two to remove the need to fork.

(In reply to Kyle M Hall from comment #4)
> (In reply to Jonathan Druart from comment #3)
> > Kyle,
> > I does not work for me: I have exported all my bibliographic records then
> > import the .mrc and I get a random 500 that block the progress bar.
> 
> Hmmm. No idea why the fix worked for me and not for you. Maybe we can get
> another person or two to test? It definitely worked for me. Worst case
> scenario would be a full reengineering of this script to split it into two
> to remove the need to fork.

Also, did you make the changes to the apache files to allow it to run under plack?

(In reply to Kyle M Hall from comment #5)
> (In reply to Kyle M Hall from comment #4)
> > (In reply to Jonathan Druart from comment #3)
> > > Kyle,
> > > I does not work for me: I have exported all my bibliographic records then
> > > import the .mrc and I get a random 500 that block the progress bar.
> > 
> > Hmmm. No idea why the fix worked for me and not for you. Maybe we can get
> > another person or two to test? It definitely worked for me. Worst case
> > scenario would be a full reengineering of this script to split it into two
> > to remove the need to fork.
> 
> Also, did you make the changes to the apache files to allow it to run under
> plack?

Yes of course.
I have just retried and I confirm it does not work for me :-/

This is the error I get at 97%

Can't seek stdout handle: Bad file descriptor at /usr/share/perl5/Plack/App/WrapCGI.pm line 87.
 at /usr/share/perl/5.20/Carp.pm line 166
	Carp::croak('Can\'t seek stdout handle: Bad file descriptor') called at /usr/share/perl5/CGI/Emulate/PSGI.pm line 32
	CGI::Emulate::PSGI::__ANON__('HASH(0xb88bd38)') called at /usr/share/perl5/Plack/App/WrapCGI.pm line 87
	Plack::App::WrapCGI::call('Plack::App::WrapCGI=HASH(0xa6c5ad8)', 'HASH(0xb88bd38)') called at /usr/share/perl5/Plack/Component.pm line 50
	Plack::Component::__ANON__('HASH(0xb88bd38)') called at /usr/share/perl5/Plack/App/CGIBin.pm line 50
	Plack::App::CGIBin::serve_path('Plack::App::CGIBin=HASH(0x2d227a8)', 'HASH(0xb88bd38)', '/home/vagrant/kohaclone/tools/stage-marc-import.pl') called at /usr/share/perl5/Plack/App/File.pm line 34
	Plack::App::File::call('Plack::App::CGIBin=HASH(0x2d227a8)', 'HASH(0xb88bd38)') called at /usr/share/perl5/Plack/Component.pm line 50
	Plack::Component::__ANON__('HASH(0xb88bd38)') called at /usr/share/perl5/Plack/App/URLMap.pm line 71
	Plack::App::URLMap::call('Plack::App::URLMap=HASH(0x99e9a38)', 'HASH(0xb88bd38)') called at /usr/share/perl5/Plack/Component.pm line 50
	Plack::Component::__ANON__('HASH(0xb88bd38)') called at /home/vagrant/kohaclone/Koha/Middleware/SetEnv.pm line 103
	Koha::Middleware::SetEnv::call('Koha::Middleware::SetEnv=HASH(0xa8b0160)', 'HASH(0x99da4c0)') called at /usr/share/perl5/Plack/Component.pm line 50
	Plack::Component::__ANON__('HASH(0x99da4c0)') called at /usr/share/perl5/Plack/Middleware/Static.pm line 18
	Plack::Middleware::Static::call('Plack::Middleware::Static=HASH(0xa835230)', 'HASH(0x99da4c0)') called at /usr/share/perl5/Plack/Component.pm line 50
	Plack::Component::__ANON__('HASH(0x99da4c0)') called at /usr/share/perl5/Plack/Middleware/ReverseProxy.pm line 68
	Plack::Middleware::ReverseProxy::call('Plack::Middleware::ReverseProxy=HASH(0xa87af20)', 'HASH(0x99da4c0)') called at /usr/share/perl5/Plack/Component.pm line 50
	Plack::Component::__ANON__('HASH(0x99da4c0)') called at /usr/share/perl5/Plack/Middleware/Lint.pm line 24
	Plack::Middleware::Lint::call('Plack::Middleware::Lint=HASH(0x2aa6338)', 'HASH(0x99da4c0)') called at /usr/share/perl5/Plack/Component.pm line 50
	Plack::Middleware::StackTrace::try {...}  at /usr/share/perl5/Try/Tiny.pm line 79
	eval {...} at /usr/share/perl5/Try/Tiny.pm line 72
	Plack::Middleware::StackTrace::call('Plack::Middleware::StackTrace=HASH(0x99da658)', 'HASH(0x99da4c0)') called at /usr/share/perl5/Plack/Component.pm line 50
	Plack::Component::__ANON__('HASH(0x99da4c0)') called at /usr/share/perl5/Plack/Middleware/AccessLog.pm line 24
	Plack::Middleware::AccessLog::call('Plack::Middleware::AccessLog=HASH(0x2d3a388)', 'HASH(0x99da4c0)') called at /usr/share/perl5/Plack/Component.pm line 50
	Plack::Component::__ANON__('HASH(0x99da4c0)') called at /usr/share/perl5/Plack/Util.pm line 142
	eval {...} at /usr/share/perl5/Plack/Util.pm line 142
	Plack::Util::run_app('CODE(0xa867218)', 'HASH(0x99da4c0)') called at /usr/share/perl5/Starman/Server.pm line 281
	Starman::Server::process_request('Starman::Server=HASH(0x26b3188)', 'Net::Server::Proto::UNIX=GLOB(0xa864250)') called at /usr/share/perl5/Net/Server.pm line 74
	Net::Server::run_client_connection('Starman::Server=HASH(0x26b3188)') called at /usr/share/perl5/Net/Server/PreFork.pm line 229
	eval {...} at /usr/share/perl5/Net/Server/PreFork.pm line 229
	Net::Server::PreFork::run_child('Starman::Server=HASH(0x26b3188)') called at /usr/share/perl5/Net/Server/PreFork.pm line 187
	Net::Server::PreFork::run_n_children('Starman::Server=HASH(0x26b3188)', 2) called at /usr/share/perl5/Net/Server/PreFork.pm line 111
	Net::Server::PreFork::loop('Starman::Server=HASH(0x26b3188)') called at /usr/share/perl5/Net/Server.pm line 60
	Net::Server::run('Starman::Server=HASH(0x26b3188)', 'port', 'ARRAY(0x2b4ce50)', 'host', '*', 'proto', 'tcp', 'serialize', 'none', 'min_servers', 2, 'min_spare_servers', 1, 'max_spare_servers', 1, 'max_servers', 2, 'max_requests', 50, 'user', 'kohadev-koha', 'group', 'kohadev-koha', 'listen', 1024, 'check_for_waiting', 1, 'no_client_stdout', 1, 'background', 1, 'setsid', 1, 'log_file', '/var/log/koha/kohadev/plack-error.log', 'pid_file', '/var/run/koha/kohadev/plack.pid') called at /usr/share/perl5/Starman/Server.pm line 89
	Starman::Server::run('Starman::Server=HASH(0x26b3188)', 'CODE(0x26b3020)', 'HASH(0x26b2d08)') called at /usr/share/perl5/Plack/Handler/Starman.pm line 18
	Plack::Handler::Starman::run('Plack::Handler::Starman=HASH(0x26b3038)', 'CODE(0x26b3020)') called at /usr/share/perl5/Plack/Loader/Delayed.pm line 20
	Plack::Loader::Delayed::run('Plack::Loader::Delayed=HASH(0x24560f0)', 'Plack::Handler::Starman=HASH(0x26b3038)') called at /usr/share/perl5/Plack/Runner.pm line 277
	Plack::Runner::run('Plack::Runner=HASH(0x243b638)') called at /usr/bin/starman line 38

I have worked a lot on this issue last year (see bug 15032 and the remote branch) but failed to fix it. The problem is in the process communication and we found that the problem comes from WrapCGI.

I do not remember exactly where it came from, but it was very tricky.

Francesco hoped bug 18315 could fix the problem.
I also remember the issue appears randomly in some of my tests. So it could work once but fail the another try.

I tried on Plack + Nginx, sorry it does not work.

Progess bar is always 0%.
I tried to look at processes, only one child is created and is immediately stopped. The end of the parent process returns error 500 "Internal Server Error" but I don't see a log in plack logs.

We are using actually Bug 17240 everywhere, our servers performance allows to use not-backgrounded jobs. We set a gateway timeout of 60 seconds, sometimes 300 for huge catalogs.

Los here, but hope you can figure it out. Setting to Failed for last 2 comments.

I just retested this patch and it *still* fixes the problem for me on kohadevbox.

Here is a video. In the first part I'm testing plain master without the patch, then with the patch under cgi. In the second video I'm testing it with plack enabled for the marc record stager. I had running commentary, but I forgot to enable voice recording ; )


https://monosnap.com/file/UBUO1lKVPlMONLSCgVwtJsrE4RkYtC

https://monosnap.com/file/3MvDxxlYjDhXjdetZ580AEVw2ypaGy

Why does this patch set work for me every time?

Could it be different versions of something? Different plack configuration?

I used a file with 5000 records.

Note that if it works with Apache but not with Nginx I'm ok with it ;)

(In reply to Kyle M Hall from comment #11)
> I just retested this patch and it *still* fixes the problem for me on
> kohadevbox.
> 
> Here is a video. In the first part I'm testing plain master without the
> patch, then with the patch under cgi. In the second video I'm testing it
> with plack enabled for the marc record stager. I had running commentary, but
> I forgot to enable voice recording ; )
> 
> 
> https://monosnap.com/file/UBUO1lKVPlMONLSCgVwtJsrE4RkYtC
> 
> https://monosnap.com/file/3MvDxxlYjDhXjdetZ580AEVw2ypaGy
> 
> Why does this patch set work for me every time?

A quick note about your second screencast: you did not remove /cgi-bin/koha/tools/background-job-progress.pl
I have retried and still does not work for me.

You should retest the scenario several times: I remember that last year I got it working in 10% of my tries, and Francesco got it working in 90% of his tries, with the same code!
There is a race in the last request that is causing the issue.
If you want to have a look at the problem you should test the branch I posted on bug 15032 (I isolated the problem in a simple script).

(In reply to Jonathan Druart from comment #14)
> You should retest the scenario several times: I remember that last year I
> got it working in 10% of my tries, and Francesco got it working in 90% of
> his tries, with the same code!

FWIW I recreate the problem much more easily in Firefox than in Chromium.

It'll be great to switch over to using RabbitMQ for managing this one. 

The web controller really should just be responsible for the file upload, the enqueuing of the import task, and then the polling for results.

By the way, Bug 26854 will fix the progress bar not updating issue. 

While I haven't tried it, I bet that it would also allow use of Plack for Stage MARC Import. 

Can't speak go the table locking as I've never seen that issue.

(In reply to David Cook from comment #17)
> By the way, Bug 26854 will fix the progress bar not updating issue. 
> 
> While I haven't tried it, I bet that it would also allow use of Plack for
> Stage MARC Import. 
> 

I was definitely wrong there. Bug 26854 fixes CGI but not Plack.

As Kyle has observed, the child process used to do the background import isn't exiting. It's staying on as a starman worker, and that's causing the problems.

I've looked at the posted patches and tried modifications of them (along with the patch for Bug 26854), and I've wound up with 2 scenarios.

1. The child process does not exit and it causes problems. You'll see a 500 in your access logs when the child process exits, and further imports will fail. Probably other unexpected bad things too.

2. The child process exits but it stays as a zombie process, since its parent Starman process is long lived

In the 2nd scenario, everything seems fine in the Koha UI, but eventually your process table will fill up, and your OS will crash.

Except... Starman workers are recycled every X requests due to the --max-requests option for starman. At that point, the zombie processes would be inherited by the init process 1, and then they'd be reaped.

But that's really not a reasonable path forward.

Btw, what I found worked was to have the child process basically commit suicide by doing a kill('QUIT',$$) command. That QUIT is Starman (or rather Net::Server::Prefork) specific, but it looks like it's just an alias for TERM anyway.

I just tried kill('TERM',$$) and that worked too.

The more I think about it... the more I can't see this ever working with a persistent process.

The only reason it works with CGI is because the parent process is not persistent / is short lived.

--

In theory, if $SIG{CHLD} were set to IGNORE rather than DEFAULT, then we possibly wouldn't get zombie processes, but that would need to be set at a higher level than stage-marc-import.pl I reckon, plus it's not a brilliant idea, as it would have wider consequences.

--

Looking at https://metacpan.org/pod/CGI::Compile#exit-and-exceptions, I see that exit() isn't a real exit as well... makes sense. 

If we use CORE::exit(0) instead of exit(0), it actually exits the background child process, although we still wind up with the zombie process like so:

kohadev+ 69925 69922 10 00:49 ?        00:00:03 starman worker -M FindBin --max-requests 50 --workers 2 --user=kohadev-koha --group kohadev-koha --pid /var/run/koha/kohadev/plack.pid --daemonize --access-log /var/log/koha/kohadev/plack.l
og --error-log /var/log/koha/kohadev/plack-error.log -E development --socket /var/run/koha/kohadev/plack.sock /etc/koha/sites/kohadev/plack.psgi
kohadev+ 69999 69925 17 00:50 ?        00:00:03 [starman worker ] <defunct>

(In reply to David Cook from comment #21)
> In theory, if $SIG{CHLD} were set to IGNORE rather than DEFAULT, then we
> possibly wouldn't get zombie processes, but that would need to be set at a
> higher level than stage-marc-import.pl I reckon, plus it's not a brilliant
> idea, as it would have wider consequences.
> 
> --
> 
> Looking at https://metacpan.org/pod/CGI::Compile#exit-and-exceptions, I see
> that exit() isn't a real exit as well... makes sense. 
> 
> If we use CORE::exit(0) instead of exit(0), it actually exits the background
> child process, although we still wind up with the zombie process like so:
 
So if I use CORE::exit(0) in stage-marc-import.pl and $SIG{CHLD} = 'IGNORE' in /etc/koha/sites/kohadev/plack.psgi, then I don't get a zombie process. 

But... I really don't think this is a great idea, although I'm not seeing any explicit web usage of wait/waitpid...

https://docstore.mik.ua/orelly/perl/cookbook/ch16_20.htm makes me think we should be more careful.

I think the best bet is to have this be a proper background task where stage-marc-import.pl is responsible only for the file upload, and then it enqueues a background task with RabbitMQ to let a background worker deal with the actual work.

> I think the best bet is to have this be a proper background task where
> stage-marc-import.pl is responsible only for the file upload, and then it
> enqueues a background task with RabbitMQ to let a background worker deal
> with the actual work.

Agreed. I think we should just close this one out.