Bug 31968

Summary: Problems with MARC staging/import
Product: Koha Reporter: Magnus Enger <magnus>
Component: MARC Bibliographic record staging/importAssignee: Bugs List <koha-bugs>
Status: NEW --- QA Contact: Testopia <testopia>
Severity: normal    
Priority: P5 - low CC: wizzyrea
Version: 22.05   
Hardware: All   
OS: All   
GIT URL: Change sponsored?: ---
Patch complexity: --- Documentation contact:
Documentation submission: Text to go in the release notes:
Version(s) released in:
Circulation function:

Description Magnus Enger 2022-10-25 09:18:25 UTC
I'm having various problems with importing staged MARC records on 22.05.05. 

One example: I have staged a file and click on "Import this batch to the catalogue". The progress bar jumps to 31% but then it stops and goes no further. In the background there are lots of calls to /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id>, but the last one gives a 500 error. This is when the progress bar stops. The job is actually finished after a while, but the interface never updates. 

I think these are the relevant errors in the logs: 

==> /var/log/koha/koha/intranet-access.log <==
...
a.b.c.d - - [25/Oct/2022:10:46:39 +0200] "GET /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id> HTTP/1.1" 200 57
a.b.c.d - - [25/Oct/2022:10:46:40 +0200] "GET /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id> HTTP/1.1" 200 57
a.b.c.d - - [25/Oct/2022:10:46:40 +0200] "GET /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id> HTTP/1.1" 200 57

==> /var/log/koha/koha/intranet-error.log <==
[2022/10/25 10:47:50] [WARN] binmode() on closed filehandle _GEN_70 at /usr/share/koha/lib/C4/Templates.pm line 126.
 CGI::Compile::ROOT::usr_share_koha_intranet_cgi_2dbin_tools_manage_2dmarc_2dimport_2epl::__ANON__ /usr/share/koha/intranet/cgi-bin/tools/manage-marc-import.pl (331) 
[2022/10/25 10:47:50] [WARN] print() on closed filehandle _GEN_70 at /usr/share/koha/lib/C4/Output.pm line 285.
 CGI::Compile::ROOT::usr_share_koha_intranet_cgi_2dbin_tools_manage_2dmarc_2dimport_2epl::__ANON__ /usr/share/koha/intranet/cgi-bin/tools/manage-marc-import.pl (331) 

==> /var/log/koha/koha/plack-intranet-error.log <==
[2022/10/25 10:47:50] [WARN] seek() on closed filehandle _GEN_70 at /usr/share/perl5/CGI/Emulate/PSGI.pm line 34.

==> /var/log/koha/koha/intranet-access.log <==
a.b.c.d - - [25/Oct/2022:10:46:41 +0200] "GET /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id> HTTP/1.1" 500 118732

The only related bug I can find is Bug 15032, which mentions "binmode() on closed filehandle" way back in 2015.
Comment 1 Magnus Enger 2022-10-25 10:56:16 UTC
Forgot to mention that this does not always happen when processing staged records, only every second or third time I try.
Comment 2 Magnus Enger 2022-10-25 12:24:35 UTC
Now the same thing happened after I clicked "Stage for import". The progress goes up to some percentage, and then stops, because background-job-progress.pl returns a 500 error:

==> /var/log/koha/koha/intranet-access.log <==
...
a.b.c.d - - [25/Oct/2022:14:02:17 +0200] "GET /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id> HTTP/1.1" 200 67
a.b.c.d - - [25/Oct/2022:14:02:18 +0200] "GET /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id> HTTP/1.1" 200 68
a.b.c.d - - [25/Oct/2022:14:02:18 +0200] "GET /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id> HTTP/1.1" 200 68
a.b.c.d - - [25/Oct/2022:14:02:19 +0200] "GET /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id> HTTP/1.1" 200 68

==> /var/log/koha/koha/intranet-error.log <==
[2022/10/25 14:02:19] [WARN] binmode() on closed filehandle _GEN_60 at /usr/share/koha/lib/C4/Templates.pm line 126.
 CGI::Compile::ROOT::usr_share_koha_intranet_cgi_2dbin_tools_manage_2dmarc_2dimport_2epl::__ANON__ /usr/share/koha/intranet/cgi-bin/tools/manage-marc-import.pl (331) 
[2022/10/25 14:02:19] [WARN] print() on closed filehandle _GEN_60 at /usr/share/koha/lib/C4/Output.pm line 285.
 CGI::Compile::ROOT::usr_share_koha_intranet_cgi_2dbin_tools_manage_2dmarc_2dimport_2epl::__ANON__ /usr/share/koha/intranet/cgi-bin/tools/manage-marc-import.pl (331) 

==> /var/log/koha/koha/plack-intranet-error.log <==
[2022/10/25 14:02:19] [WARN] seek() on closed filehandle _GEN_60 at /usr/share/perl5/CGI/Emulate/PSGI.pm line 34.

==> /var/log/koha/koha/intranet-access.log <==
a.b.c.d - - [25/Oct/2022:14:02:19 +0200] "GET /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id> HTTP/1.1" 200 68
a.b.c.d - - [25/Oct/2022:14:02:20 +0200] "GET /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id> HTTP/1.1" 200 80
a.b.c.d - - [25/Oct/2022:14:02:20 +0200] "GET /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id> HTTP/1.1" 200 68
a.b.c.d - - [25/Oct/2022:14:02:21 +0200] "GET /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id> HTTP/1.1" 200 68
a.b.c.d - - [25/Oct/2022:14:02:21 +0200] "GET /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id> HTTP/1.1" 200 68

==> /var/log/koha/koha/plack-intranet-error.log <==
[2022/10/25 14:02:22] [WARN] commit ineffective with AutoCommit enabled at /usr/share/perl5/DBIx/Class/Storage/DBI.pm line 1621.
[2022/10/25 14:02:22] [WARN] seek() on closed filehandle _GEN_134 at /usr/share/perl5/CGI/Emulate/PSGI.pm line 34.

==> /var/log/koha/koha/intranet-access.log <==
a.b.c.d - - [25/Oct/2022:14:02:22 +0200] "GET /cgi-bin/koha/tools/background-job-progress.pl?jobID=<id> HTTP/1.1" 500 118732


The file was actually staged, so the problem seems to be background-job-progress.pl returning a 500 error.
Comment 3 Katrin Fischer 2022-11-14 23:47:00 UTC
Hm, the dependency made no sense, this was reported for 22.05, but bug 27421 is only in 22.11... but the mention of the background_job?
Comment 4 Liz Rea 2023-10-18 14:45:27 UTC
I believe this happens when a record in the batch has invalid MARC data.