Bug 13606

Summary: Batch modification for records is limited to ~500
Product: Koha Reporter: Jonathan Druart <jonathan.druart>
Component: ToolsAssignee: Jonathan Druart <jonathan.druart>
Status: CLOSED FIXED QA Contact: Testopia <testopia>
Severity: major    
Priority: P5 - low CC: chris, claire.hernandez, dcook, f.demians, josef.moravec, mtompset, tomascohen
Version: Main   
Hardware: All   
OS: All   
See Also: http://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=10601
Change sponsored?: --- Patch complexity: ---
Documentation contact: Documentation submission:
Text to go in the release notes:
Version(s) released in:
Circulation function:
Bug Depends on: 11395    
Bug Blocks:    
Attachments: Bug 13606: Remove previous job data from the session
Bug 13606: Upgrade sessions.a_session to MEDIUMTEXT
[SIGNED-OFF] Bug 13606: Remove previous job data from the session
Bug 13606: Upgrade sessions.a_session to MEDIUMTEXT
Bug 13606: Upgrade sessions.a_session to MEDIUMTEXT
Bug 13606: Remove previous job data from the session
Bug 13606: Upgrade sessions.a_session to MEDIUMTEXT
Bug 13606: Upgrade sessions.a_session to MEDIUMTEXT
Bug 13606: Remove previous job data from the session
Proposal to clear the job session data at the end of the process
Bug 13606 Clear job data in session when the job is completed
Bug 13606 New test for added method to C4::BackgroundJob
Bug 13606: Add tests and fix existing ones
Bug 13606: Add tests and fix existing ones
Bug 13606: Upgrade sessions.a_session to MEDIUMTEXT
Bug 13606 Clear job data in session when the job is completed
Bug 13606: Add tests and fix existing ones
[PASSED QA] Bug 13606: Upgrade sessions.a_session to MEDIUMTEXT
[PASSED QA] Bug 13606: Upgrade sessions.a_session to MEDIUMTEXT
[PASSED QA] Bug 13606 Clear job data in session when the job is completed
[PASSED QA] Bug 13606: Add tests and fix existing ones
Bug 13606: (RM followup) DBIx updates

Description Jonathan Druart 2015-01-21 14:34:01 UTC
Bug 11395 uses the session to store the report sent to the interface (update on biblio XX OK, etc.).

If the session is stored in mysql, the max size of the sessions.a_session will be reached easily (TEXT field).

I found a first problem:
The C4::BackgroundJob module append to the session each job information.
Example for 2 jobs launched during the same session:

 --- 
_SESSION_ATIME: '1421843399'
_SESSION_CTIME: '1421843222'
_SESSION_ID: a5ffa813fc694706245cfe51dedc7697
_SESSION_REMOTE_ADDR: 192.168.113.2
branch: NO_LIBRARY_SET
branchname: NO_LIBRARY_SET
cardnumber: koha
emailaddress: koha@exampe.org
firstname: koha
flags: 1
id: koha
ip: 1.2.3.4
job_94357aff68a60dee98819f627c8a7f57: !!perl/hash:C4::BackgroundJob 
  extra_values: 
    messages: 
      - 
        biblionumber: 1
        code: biblio_modified
        type: success
      - 
        biblionumber: 2
        code: biblio_modified
        type: success
      - 
        biblionumber: 3
        code: biblio_modified
        type: success
      - 
        biblionumber: 4
        code: biblio_modified
        type: success
      - 
        biblionumber: 5
        code: biblio_modified
        type: success
    report: 
      total_records: 5
      total_success: 5
    view: report
  invoker: /cgi-bin/koha/tools/batch_record_modification.pl
  jobID: 94357aff68a60dee98819f627c8a7f57
  name: FIXME
  progress: 5
  results: ~
  sessionID: a5ffa813fc694706245cfe51dedc7697
  size: 5
  status: completed
job_98a251e034eec15b87027ea9c5c0a8cd: !!perl/hash:C4::BackgroundJob 
  extra_values: 
    messages: 
      - 
        biblionumber: 6
        code: biblio_modified
        type: success
      - 
        biblionumber: 7
        code: biblio_modified
        type: success
      - 
        biblionumber: 8
        code: biblio_modified
        type: success
      - 
        biblionumber: 9
        code: biblio_modified
        type: success
      - 
        biblionumber: 10
        code: biblio_modified
        type: success
    report: 
      total_records: 5
      total_success: 5
    view: report
  invoker: /cgi-bin/koha/tools/batch_record_modification.pl
  jobID: 98a251e034eec15b87027ea9c5c0a8cd
  name: FIXME
  progress: 5
  results: ~
  sessionID: a5ffa813fc694706245cfe51dedc7697
  size: 5
  status: completed

It's useless to keep old job information.

To reproduce:
1/ Create a file with 500 biblionumbers:
mysql -e "select biblionumber from biblio limit 500;" | tail -n 500 > /tmp/biblionumbers.txt
2/ Define a marc modification template
3/ Load the /tmp/biblionumbers.txt in the batch biblio modification tool
4/ Repeat 3
You will get:
  Syck parser (line 1534, column 6): syntax error at /usr/lib/i386-linux-gnu/perl5/5.20/YAML/Syck.pm line 75.

The sessions.a_session field has reach its maximum size and the yaml stored in it is not complete and not well formed.

To fix that I would like to
1/ Remove previous job information on creating a new one
2/ Increase the size of sessions.a_session from TEXT (64kb) to MEDIUMTEXT (32mb)
Comment 1 Jonathan Druart 2015-01-21 15:02:14 UTC Comment hidden (obsolete)
Comment 2 Jonathan Druart 2015-01-21 15:02:18 UTC Comment hidden (obsolete)
Comment 3 Frédéric Demians 2015-04-09 06:52:16 UTC
The second patch doesn't apply:

fatal: sha1 information is lacking or useless (installer/data/mysql/updatedatabase.pl).
Le dépôt n'a pas les blobs nécessaires pour un retour à une fusion à 3 points.
Impossible de retourner à une fusion à 3 points.
Comment 4 Frédéric Demians 2015-04-09 06:53:55 UTC Comment hidden (obsolete)
Comment 5 Jonathan Druart 2015-04-09 07:55:56 UTC Comment hidden (obsolete)
Comment 6 Jonathan Druart 2015-04-09 07:56:50 UTC
I am raising the priority of this one, it should absolutely be present in 3.20.
Comment 7 Jonathan Druart 2015-04-09 08:04:00 UTC
Actually I am wondering what happens if 2 jobs are launched simultaneously :-/
Comment 8 Frédéric Demians 2015-04-09 14:16:07 UTC Comment hidden (obsolete)
Comment 9 Frédéric Demians 2015-04-09 14:19:04 UTC
(In reply to Jonathan Druart from comment #7)
> Actually I am wondering what happens if 2 jobs are launched simultaneously
> :-/

Good question! Above ~1000 records, the processing time is long, and the UI feedback is not that good. So users could be tempted to refresh the page. It may be advisable to limit processing to let say 1000 records.
Comment 10 Jonathan Druart 2015-04-09 14:36:24 UTC
(In reply to Frédéric Demians from comment #9)
> (In reply to Jonathan Druart from comment #7)
> > Actually I am wondering what happens if 2 jobs are launched simultaneously
> > :-/
> 
> Good question! Above ~1000 records, the processing time is long, and the UI
> feedback is not that good. So users could be tempted to refresh the page. It
> may be advisable to limit processing to let say 1000 records.

I would be tempt to only keep the DB changes, not the first patch.
I did not try, but if several jobs are launched (any jobs using the BackgroundJob module), the last one will erase data from previous ones.
Comment 11 Jonathan Druart 2015-04-09 14:37:53 UTC
The first patch should be improved to only delete data from finished jobs.
Comment 12 Jonathan Druart 2015-04-09 16:05:29 UTC Comment hidden (obsolete)
Comment 13 Jonathan Druart 2015-04-09 16:09:10 UTC
(In reply to Jonathan Druart from comment #11)
> The first patch should be improved to only delete data from finished jobs.

Frederic, I rewrote my first patch. The job entries in the session are now deleted when a new job is created.
It looks better like that and we should not get issue with simultaneous jobs.

Could you confirm the progress bar is broken, even on the items modification tool?
I tried with an old version of the code, and same issue.
Not sure if it comes from me or if it's an issue...
Comment 14 Mark Tompsett 2015-04-09 16:59:13 UTC
Why is there no "Started: 2015-04-09 12:58:00" type value in the job session information? You could easily also delete anything that is more than 24 hours old, if there was a way to determine it.
Comment 15 Mark Tompsett 2015-04-09 19:08:43 UTC
Also, perhaps a 'LastTouched: 2015-04-09 15:07:00' type entry would be useful too. If it isn't touched in 30 minutes, is it even running?
Comment 16 Mark Tompsett 2015-04-09 23:22:22 UTC
I successfully (and that's not a good thing) ran two batch modify concurrently, and one progress bar hung, but the other finished. I suspect the process was killed by OS, because the javascript kept pulling the 99% just fine.

However, on a positive note, this does make a significant improvement. In the same kind of test ran multiple times, I actually had the error (mentioned in comment #1) triggered behind the scenes and the progress bar seemed to get stuck before the patch. I did not encounter the same problem after.

Though, the patch for the paragraph 1 problem would likely solve, as a side-effect the hidden hang in the paragraph 2 problem.

If we store the process ID of the child in the job session, then the progress javascript call can check for the existence of that process if the status is not completed. If the process does not exist, then it can change the status to failed OR perhaps attempt to restart with a smaller data set in order to continue.

This, of course, is discussion for the creation of another bug report.
Comment 17 Mark Tompsett 2015-04-09 23:45:13 UTC Comment hidden (obsolete)
Comment 18 Mark Tompsett 2015-04-09 23:45:38 UTC Comment hidden (obsolete)
Comment 19 Mark Tompsett 2015-04-09 23:45:44 UTC Comment hidden (obsolete)
Comment 20 Frédéric Demians 2015-04-10 06:43:06 UTC
Jonathan, reading your code, I understand better now how it interact with
C4::Background module. Your last patch clear the batch modification job data
when a new job is created. Wouldn't it be simpler to clear it just after the
job is completed in batch_record_modification.pl? I will do a proposal patch
for that, hoping I don't miss something important.

And, yes, I confirm that progress bar is also broken in batch item
modification. It may works that way since a while.
Comment 21 Frédéric Demians 2015-04-10 06:50:49 UTC Comment hidden (obsolete)
Comment 22 Jonathan Druart 2015-04-10 07:18:50 UTC Comment hidden (obsolete)
Comment 23 Jonathan Druart 2015-04-10 07:26:37 UTC
(In reply to Frédéric Demians from comment #20)
> Jonathan, reading your code, I understand better now how it interact with
> C4::Background module. Your last patch clear the batch modification job data
> when a new job is created. Wouldn't it be simpler to clear it just after the
> job is completed in batch_record_modification.pl? I will do a proposal patch
> for that, hoping I don't miss something important.

It works nicely.
I have tried to add this line in the finish method, but did not work.
The only concern could be in case we need debugging. If something wrong happens it is good to know what kind of batch has been launched. Apart from that my patch was not much better than yours...

> And, yes, I confirm that progress bar is also broken in batch item
> modification. It may works that way since a while.

That's really weird, I'm sure it worked when I have submitted my patch set on bug 11395.
Comment 24 Jonathan Druart 2015-04-10 07:28:47 UTC
(In reply to Frédéric Demians from comment #21)
> Created attachment 37636 [details] [review] [review]
> Proposal to clear the job session data at the end of the process

Note that I have c/p my test plan to your commit message.
Comment 25 Jonathan Druart 2015-04-10 08:10:47 UTC
(In reply to Jonathan Druart from comment #23)
> > And, yes, I confirm that progress bar is also broken in batch item
> > modification. It may works that way since a while.
> 
> That's really weird, I'm sure it worked when I have submitted my patch set
> on bug 11395.

It does not work on my dev install, but works perfectly on sandboxes (tested with batch records modification, and import).
I would suspect the perl version (5.20.1 vs 5.14.2).
Comment 26 Frédéric Demians 2015-04-10 10:03:40 UTC
(In reply to Jonathan Druart from comment #23)

> I have tried to add this line in the finish method, but did not work.

As I understand background process, the finish() method is called when the job is achieved. Then the job result is stored in the session. And from there, the result can be retrieved by a web page (like batch modification page). So the job data clearing must separated from marking a job as finished.
Comment 27 Mark Tompsett 2015-04-10 11:55:35 UTC
If you add a function to a C4 library, you need to add corresponding tests in a .t file too.
Comment 28 Frédéric Demians 2015-04-10 13:18:30 UTC
(In reply to M. Tompsett from comment #27)
> If you add a function to a C4 library, you need to add corresponding tests
> in a .t file too.

Is there somewhere a form to fill out in three copies?
Comment 29 Frédéric Demians 2015-04-10 13:21:29 UTC Comment hidden (obsolete)
Comment 30 Mark Tompsett 2015-04-10 14:55:03 UTC
(In reply to Frédéric Demians from comment #28)
> Is there somewhere a form to fill out in three copies?

No, just trying to keep the quality high.

I see that you encountered the same kind of problem I did when trying to make the test. Here's the problem that still exists.

$ mysql -u root -p
> use koha_library;
> delete from sessions;
^Z
$ prove -v t/db_dependent/BackgroundJob.t
$ fg
> select a_session from sessions where a_session like '%complete%';
...

There are still LOTS of anonymous sessions created for each stage tested in the file. That doesn't seem correct to me. Because if I run it from within Koha, there are not. And from within Koha clear() works, but in the test context it does not.

The fail is for a test that doesn't successfully test clear(). Perhaps clear() needs to actually clear based on jobID?

I apologize for being a testing pain.
Comment 31 Jonathan Druart 2015-04-10 15:13:18 UTC
I have a patch for tests, will be ready soon.
Comment 32 Jonathan Druart 2015-04-10 15:20:50 UTC Comment hidden (obsolete)
Comment 33 Jonathan Druart 2015-04-10 15:29:27 UTC Comment hidden (obsolete)
Comment 34 Frédéric Demians 2015-04-10 15:36:27 UTC
Jonathan: +1 for testing correctly
Mark: +1 for keeping the quality high, or elevating it even
Comment 35 Mark Tompsett 2015-04-10 16:22:09 UTC Comment hidden (obsolete)
Comment 36 Mark Tompsett 2015-04-10 16:22:22 UTC Comment hidden (obsolete)
Comment 37 Mark Tompsett 2015-04-10 16:22:37 UTC Comment hidden (obsolete)
Comment 38 Mark Tompsett 2015-04-10 16:24:12 UTC
This is so ready for QA now. :) Thanks everyone.
Comment 39 Kyle M Hall (khall) 2015-04-17 13:27:17 UTC Comment hidden (obsolete)
Comment 40 Kyle M Hall (khall) 2015-04-17 13:27:34 UTC
Created attachment 38059 [details] [review]
[PASSED QA] Bug 13606: Upgrade sessions.a_session to MEDIUMTEXT

The previous patch fixed partially the problem.
If you try to update more that 1000 records, you will get the same
error.

This patch change the type of sessions.a_session from TEXT (64kb) MEDIUMTEXT (32mb).

Test plan:
1/ Try to modify a huge amount of records (1000 should be enough)
2/ Confirm it worked!

Signed-off-by: Frederic Demians <f.demians@tamil.fr>

I confirm that with more than 1000 records the session object is truncated, and
then can't be anymore be desirialized, blocking completely Koha. Fixed with
this patch.

Signed-off-by: Mark Tompsett <mtompset@hotmail.com>

This only pushes off the problem expontentially (64KB vs. 16MB), but this is a
good start.

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 41 Kyle M Hall (khall) 2015-04-17 13:27:41 UTC
Created attachment 38060 [details] [review]
[PASSED QA] Bug 13606 Clear job data in session when the job is completed

Bug 11395 uses the session to store the report sent to the interface
(update on biblio XX OK, etc.).

If the session is stored in mysql, the max size of the
sessions.a_session will be reached easily (TEXT field).

To reproduce:
0/ Set SessionStorage to 'mysql'
1/ Create a file with 500 biblionumbers:
  mysql -e "select biblionumber from biblio limit 500;" | tail -n 500 > /tmp/biblionumbers.txt
2/ Define a marc modification template (something like "delete field 99$9" is nice)
3/ Load the /tmp/biblionumbers.txt in the batch biblio modification tool
4/ Repeat 3
You will get:
  Syck parser (line 1534, column 6): syntax error at
  /usr/lib/i386-linux-gnu/perl5/5.20/YAML/Syck.pm line 75.
None Koha page is reachable.

It comes from get_template_and_user > checkauth > get_session >
l.1595 $session = new CGI::Session("driver:MySQL;serializer:yaml;id:md5", $sessionID, {Handle=>$dbh});

5/ Get your sessionID contained in your CGISESSID cookie
Have a look at the value a_session in the sessions table:
mysql> select a_session from sessions where id="YOUR_SESSIONID";

You should see that the yaml is not correctly ended.
The size of the DB field has been reached and the yaml is truncated.

Test plan:
0/ Delete your CGISESSID cookie
1/ Try to reproduce the previous issue
2/ After the second batch, have a look at the sessions table and confirm
that only one job_$JOB_ID exist in the yaml

Signed-off-by: Jonathan Druart <jonathan.druart@biblibre.com>

NOTE: Nicely clears batch job session information.
      (2) is incorrect. This cleans up after a full run.

Signed-off-by: Mark Tompsett <mtompset@hotmail.com>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 42 Kyle M Hall (khall) 2015-04-17 13:27:44 UTC
Created attachment 38061 [details] [review]
[PASSED QA] Bug 13606: Add tests and fix existing ones

Some tests were wrong and not executed in a transaction.
Lot of sessions were created in DB because the session was never
flushed.

TEST PLAN
---------
$ mysql ...
> delete from sessions;
^Z
$ prove -v t/db_dependent/BackgroundJob.t
...
$ fg
> select id from sessions;
-- There will be lots of ids (10, if I recall)
^Z
$ git bz apply 13606
...
$ prove -v t/db_dependent/BackgroundJob.t
...
$ fg
> select * from sessions;
-- there should only be the one orphaned job.
   You can tell it is correct by the "making new job".
> quit

Run the koha-qa test tools.

Signed-off-by: Mark Tompsett <mtompset@hotmail.com>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 43 Tomás Cohen Arazi (tcohen) 2015-04-23 16:23:16 UTC
Created attachment 38431 [details] [review]
Bug 13606: (RM followup) DBIx updates

Signed-off-by: Tomas Cohen Arazi <tomascohen@gmail.com>
Comment 44 Tomás Cohen Arazi (tcohen) 2015-04-23 16:28:43 UTC
Patches pushed to master.

Thanks Jonathan and Frederic!
Comment 45 Chris Cormack 2015-05-17 03:44:12 UTC
Doesn't apply and I think is not needed on 3.18.x
Comment 46 Jonathan Druart 2015-05-18 09:44:57 UTC
(In reply to Chris Cormack from comment #45)
> Doesn't apply and I think is not needed on 3.18.x

No it's not, bug 11395 will be in 3.20