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.
Forgot to mention that this does not always happen when processing staged records, only every second or third time I try.
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.
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?
I believe this happens when a record in the batch has invalid MARC data.