Bug 26457 - DB DeadLock when renewing checkout items
Summary: DB DeadLock when renewing checkout items
Status: CLOSED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Circulation (show other bugs)
Version: master
Hardware: All All
: P5 - low major (vote)
Assignee: Nick Clemens
QA Contact: Marcel de Rooy
URL:
Keywords:
: 29650 (view as bug list)
Depends on: 20086
Blocks:
  Show dependency treegraph
 
Reported: 2020-09-14 15:17 UTC by Didier Gautheron
Modified: 2022-12-12 21:24 UTC (History)
12 users (show)

See Also:
Change sponsored?: ---
Patch complexity: Small patch
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:
21.05.00,20.11.04,20.05.10,19.11.16


Attachments
Bug 26457: Throw exception if update of issues table fails (2.79 KB, patch)
2020-12-04 12:07 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 26457: Throw exception if update of issues table fails (3.43 KB, patch)
2020-12-04 12:08 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 26457: Throw exception if update of issues table fails (3.43 KB, patch)
2020-12-04 12:09 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 26457: Throw exception if update of issues table fails (3.43 KB, patch)
2020-12-04 12:20 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 26457: Throw exception if update of issues table fails (3.26 KB, patch)
2020-12-04 12:30 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 26457: Throw exception if update of issues table fails (3.33 KB, patch)
2020-12-23 13:08 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 26457: Unit test (1.97 KB, patch)
2020-12-24 12:23 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 26457: Throw exception if update of issues table fails (3.37 KB, patch)
2021-02-24 00:24 UTC, David Nind
Details | Diff | Splinter Review
Bug 26457: Unit test (2.02 KB, patch)
2021-02-24 00:24 UTC, David Nind
Details | Diff | Splinter Review
Bug 26457: Throw exception if update of issues table fails (3.46 KB, patch)
2021-02-26 10:54 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 26457: Unit test (2.11 KB, patch)
2021-02-26 10:54 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 26457: (QA follow-up) Switch to PK index in UPDATE on issues (1.82 KB, patch)
2021-02-26 10:54 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 26457: [20.05.x] Throw exception if update of issues table fails (5.61 KB, patch)
2021-03-05 20:19 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 26457: [19.11.x] Throw exception if update of issues table fails (5.79 KB, patch)
2021-03-23 10:56 UTC, Jonathan Druart
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Didier Gautheron 2020-09-14 15:17:16 UTC
Hi,

Since it's in a transaction ( https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=20086 ) we are seeing deadlock when renewing checkout and items aren't renewed randomly.



plack error
DBD::mysql::st execute failed: Deadlock found when trying to get lock; try restarting transaction [for Statement "UPDATE issues SET date_due = ?, renewals = ?, lastreneweddate = ?
                                WHERE borrowernumber=?
                                AND itemnumber=?" with P


SHOW ENGINE INNODB STATUS;

-----------------------
LATEST DETECTED DEADLOCK
------------------------
2020-09-14 11:09:55 0x7f69b85c0700
*** (1) TRANSACTION:
TRANSACTION 19363996, ACTIVE 1 sec fetching rows
mysql tables in use 4, locked 4
LOCK WAIT 7 lock struct(s), heap size 1128, 8 row lock(s)
MySQL thread id 22449, OS thread handle 140092040718080, query id 38767706 localhost kohaadmin Updating
UPDATE issues SET date_due = '2020-09-18 23:59', renewals = '1', lastreneweddate = '2020-09-14T11:09:54'
                                WHERE borrowernumber='93697'
                                AND itemnumber='999735'
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 476 page no 87 n bits 248 index PRIMARY of table `koha`.`issues` trx id 19363996 lock_mode X locks rec but not gap waiting
Record lock, heap no 109 PHYSICAL RECORD: n_fields 18; compact format; info bits 0
 0: len 4; hex 802713f6; asc  '  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80016e01; asc   n ;;
 4: len 4; hex 8008e784; asc     ;;
 5: len 5; hex 99a7397ec0; asc   9~ ;;
 6: len 6; hex 43454e545245; asc CENTRE;;
 7: SQL NULL;
 8: SQL NULL;
 9: len 1; hex 80; asc  ;;
 10: len 1; hex 80; asc  ;;
 11: SQL NULL;
 12: len 4; hex 5f326b5e; asc _2k^;;
 13: len 5; hex 99a6e20000; asc      ;;
 14: len 4; hex 80000000; asc     ;;
 15: SQL NULL;
 16: SQL NULL;
 17: SQL NULL;

*** (2) TRANSACTION:
TRANSACTION 19363999, ACTIVE 1 sec starting index read
mysql tables in use 4, locked 4
4 lock struct(s), heap size 1128, 3 row lock(s)
MySQL thread id 22450, OS thread handle 140092041332480, query id 38767702 localhost kohaadmin Updating
UPDATE issues SET date_due = '2020-09-18 23:59', renewals = '1', lastreneweddate = '2020-09-14T11:09:54'
                                WHERE borrowernumber='93697'
                                AND itemnumber='583556'
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 476 page no 87 n bits 248 index PRIMARY of table `koha`.`issues` trx id 19363999 lock_mode X locks rec but not gap
Record lock, heap no 109 PHYSICAL RECORD: n_fields 18; compact format; info bits 0
 0: len 4; hex 802713f6; asc  '  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80016e01; asc   n ;;
 4: len 4; hex 8008e784; asc     ;;
 5: len 5; hex 99a7397ec0; asc   9~ ;;
 6: len 6; hex 43454e545245; asc CENTRE;;
 7: SQL NULL;
 8: SQL NULL;
 9: len 1; hex 80; asc  ;;
 10: len 1; hex 80; asc  ;;
 11: SQL NULL;
 12: len 4; hex 5f326b5e; asc _2k^;;
 13: len 5; hex 99a6e20000; asc      ;;
 14: len 4; hex 80000000; asc     ;;
 15: SQL NULL;
 16: SQL NULL;
 17: SQL NULL;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 476 page no 425 n bits 1168 index issuesborridx of table `koha`.`issues` trx id 19363999 lock_mode X waiting
Record lock, heap no 52 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 80016e01; asc   n ;;
 1: len 4; hex 8026df40; asc  & @;;

*** WE ROLL BACK TRANSACTION (2)
Comment 1 David Cook 2020-09-15 00:33:17 UTC
I'm more familiar with PostgreSQL deadlocks than MySQL deadlocks, but it looks to me like 2 separate Koha processes are trying to add renewals for different items for the same borrower, and perhaps the lock contention is over the issuesborridx index.

Looking at Bug 20086, I see that those are unnecessarily large transactions. It's better to keep transactions as small as possible, especially to avoid scenarios like this.

Looking at koha-tmpl/intranet-tmpl/prog/js/checkouts.js, I see that the renewals are POSTed to "/cgi-bin/koha/svc/renew" asynchronously, so that's how there would be multiple AddRenewal transactions running for the same borrower at the same time...

Looking at https://dev.mysql.com/doc/refman/8.0/en/innodb-locking.html#innodb-record-locks, I think my theory is correct about the issue being contention over the issuesborridx.

Now, I haven't noticed this / haven't gotten any reports of this, but I don't think we really use fines, so this report is interesting. 

I'm guessing that your renewals must be processed *very* slowly, and that your 2nd transaction is rolled back, because your 1st transaction is taking too long to release a lock on issuesborridx. 

I'd say the solution is to redo the transaction handling for C4::Circulation::AddRenewal.

Didier, do you been able to reproduce this issue in koha-testing-docker? That would help in fixing the problem.
Comment 2 David Cook 2020-09-15 01:18:40 UTC
I suppose one option would be to do 1 AJAX request with all the information, rather than 1 AJAX request for *each* issue.

That would probably cause a performance degradation overall though.

I suppose one obvious fix would be changing from

UPDATE issues SET date_due = ?, renewals = ?, lastreneweddate = ? WHERE borrowernumber=? AND itemnumber=?"

to:

UPDATE issues SET date_due = ?, renewals = ?, lastreneweddate = ? WHERE issue_id=?"
Comment 3 Didier Gautheron 2020-09-15 10:19:51 UTC
(In reply to David Cook from comment #1)
> I'm more familiar with PostgreSQL deadlocks than MySQL deadlocks, but it
> looks to me like 2 separate Koha processes are trying to add renewals for
> different items for the same borrower, and perhaps the lock contention is
> over the issuesborridx index.
> 
> Looking at Bug 20086, I see that those are unnecessarily large transactions.
> It's better to keep transactions as small as possible, especially to avoid
> scenarios like this.
> 
> Looking at koha-tmpl/intranet-tmpl/prog/js/checkouts.js, I see that the
> renewals are POSTed to "/cgi-bin/koha/svc/renew" asynchronously, so that's
> how there would be multiple AddRenewal transactionsissuesborridx running for the same
> borrower at the same time...
It's also our analysis, there's redundant indexes on issues which may on may not compound the problem.
 PRIMARY KEY (`issue_id`),
  UNIQUE KEY `itemnumber` (`itemnumber`),
  KEY `issuesborridx` (`borrowernumber`),
  KEY `itemnumber_idx` (`itemnumber`),
  KEY `branchcode_idx` (`branchcode`),
  KEY `bordate` (`borrowernumber`,`timestamp`),

itemnumber_idx  and issuesborridx are redundant.
> 
> Looking at
> https://dev.mysql.com/doc/refman/8.0/en/innodb-locking.html#innodb-record-
> locks, I think my theory is correct about the issue being contention over
> the issuesborridx.
> 
> Now, I haven't noticed this / haven't gotten any reports of this, but I
> don't think we really use fines, so this report is interesting. 
> 
> I'm guessing that your renewals must be processed *very* slowly, and that
> your 2nd transaction is rolled back, because your 1st transaction is taking
> too long to release a lock on issuesborridx. 
> 
> I'd say the solution is to redo the transaction handling for
> C4::Circulation::AddRenewal.
I'm not sure block to redo is idempotent... 
> 
> Didier, do you been able to reproduce this issue in koha-testing-docker?
> That would help in fixing the problem.
I'll try, maybe adding a fat sleep(5) in transaction block.
Comment 4 David Cook 2020-09-16 04:11:35 UTC
(In reply to didier from comment #3)
> It's also our analysis, there's redundant indexes on issues which may on may
> not compound the problem.
>  PRIMARY KEY (`issue_id`),
>   UNIQUE KEY `itemnumber` (`itemnumber`),
>   KEY `issuesborridx` (`borrowernumber`),
>   KEY `itemnumber_idx` (`itemnumber`),
>   KEY `branchcode_idx` (`branchcode`),
>   KEY `bordate` (`borrowernumber`,`timestamp`),
> 
> itemnumber_idx  and issuesborridx are redundant.

I doubt that the indexes compound the problem, but I suppose more investigation would be needed.

I see that itemnumber_idx is redundant, but how is issuesborridx redundant? It's not the same as bordate. 

> I'll try, maybe adding a fat sleep(5) in transaction block.

Certainly worth experimenting.
Comment 5 Didier Gautheron 2020-09-16 07:13:36 UTC
(In reply to David Cook from comment #4)
> 
> I see that itemnumber_idx is redundant, but how is issuesborridx redundant?
> It's not the same as bordate. 
bordate is a composed index with borrowernumber first and mysql is able to use it for search on borrowernumber only.

 explain select * from issues where borrowernumber = 3;
+------+-------------+--------+------+-----------------------+---------------+---------+-------+------+-------+
| id   | select_type | table  | type | possible_keys         | key           | key_len | ref   | rows | Extra |
+------+-------------+--------+------+-----------------------+---------------+---------+-------+------+-------+
|    1 | SIMPLE      | issues | ref  | issuesborridx,bordate | issuesborridx | 5       | const | 1    |       |
+------+-------------+--------+------+-----------------------+---------------+---------+-------+------+-------+

drop index issuesborridx on issues;
explain select * from issues where borrowernumber = 3;
+------+-------------+--------+------+---------------+---------+---------+-------+------+-------+
| id   | select_type | table  | type | possible_keys | key     | key_len | ref   | rows | Extra |
+------+-------------+--------+------+---------------+---------+---------+-------+------+-------+
|    1 | SIMPLE      | issues | ref  | bordate       | bordate | 5       | const | 1    |       |
+------+-------------+--------+------+---------------+---------+---------+-------+------+-------+

> 
> > I'll try, maybe adding a fat sleep(5) in transaction block.
> 
> Certainly worth experimenting.
I did it but was unable to reproduce the deadlock even with a sleep(5) and 8 concurrent plack workers.
Comment 6 David Cook 2020-09-16 07:27:35 UTC
(In reply to didier from comment #5)
> (In reply to David Cook from comment #4)
> > 
> > I see that itemnumber_idx is redundant, but how is issuesborridx redundant?
> > It's not the same as bordate. 
> bordate is a composed index with borrowernumber first and mysql is able to
> use it for search on borrowernumber only.

That's interesting! I've had mixed experiences (with PostgreSQL) with composite indexes being used when searching for only part of the index. I hadn't thought about column order, but maybe that explains some of my experiences. Food for thought!

> > > I'll try, maybe adding a fat sleep(5) in transaction block.
> > 
> > Certainly worth experimenting.
> I did it but was unable to reproduce the deadlock even with a sleep(5) and 8
> concurrent plack workers.

How many renewals did you try to do? I figure if you have maybe 32+ renewals and the browser does about 8 requests in parallel, maybe you'd be able to reproduce it with that.
Comment 7 Didier Gautheron 2020-09-16 12:17:11 UTC
(In reply to David Cook from comment #6)

> How many renewals did you try to do? I figure if you have maybe 32+ renewals
> and the browser does about 8 requests in parallel, maybe you'd be able to
> reproduce it with that.

8 or 9 so there was 8 requests in parallel.
Comment 8 David Cook 2020-09-16 23:24:39 UTC
(In reply to didier from comment #7)
> 8 or 9 so there was 8 requests in parallel.

Hmm and did they have all fine generation? I keep thinking that has to be part of it, as I haven't noticed any deadlock issues, but we don't use fines typically.
Comment 9 Didier Gautheron 2020-09-17 09:14:44 UTC
(In reply to David Cook from comment #8)
> (In reply to didier from comment #7)
> > 8 or 9 so there was 8 requests in parallel.
> 
> Hmm and did they have all fine generation? I keep thinking that has to be
> part of it, as I haven't noticed any deadlock issues, but we don't use fines
> typically.

As far I can tell they don't fine overdue.
Comment 10 Jonathan Druart 2020-10-01 07:31:40 UTC
If you want to fix that you should follow what is done in C4::Circulation::SendCirculationAlert
Comment 11 Jonathan Druart 2020-10-12 15:01:47 UTC
(In reply to Jonathan Druart from comment #10)
> If you want to fix that you should follow what is done in
> C4::Circulation::SendCirculationAlert

Reading the other comments, maybe this is not needed.
Comment 12 Jonathan Druart 2020-10-12 15:05:21 UTC
I've tried hard to recreate the problem but failed (ktd).

40 plack workers, limit 50 renewals
I created a bunch of checkouts for a given patron:

use Koha::Items;
use C4::Circulation;
use t::lib::Mocks;
my $items = Koha::Items->search();
my $patron = Koha::Patrons->find(51);
t::lib::Mocks::mock_userenv({ patron => $patron }); 
while ( my $item = $items->next ) { 
    C4::Circulation::AddIssue($patron->unblessed, $item->barcode);
}


Then opened 5 tabs /cgi-bin/koha/circ/circulation.pl?borrowernumber=51
And click "Renewal all" as soon as I could.

Everything got renewed correctly.
Comment 13 Didier Gautheron 2020-10-12 15:32:10 UTC
Hi,
Thanks for looking at it.

We have a second library with the same issue, but they have only issuesborridx.

we are using nginx and mariadb
mysql --version
mysql  Ver 15.1 Distrib 10.4.13-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2
Comment 14 Nick Clemens 2020-12-03 19:24:09 UTC
Investigating this, as near as I can tell it only occurs during 'Renew all' when too many processes hit the server at once. I cannot recreate locally, but can verify on larger active koha instances

The renewals silently fail and the user is never notified leading to problems later.

We have other issues from the multiple concurrent renewals, see bug 26208

I attached a patch there to perform the actions serially which I believe will mitigate this issue
Comment 15 David Cook 2020-12-04 02:11:55 UTC
It would be good to have more data from real life examples.
Comment 16 Nick Clemens 2020-12-04 11:24:30 UTC
(In reply to David Cook from comment #15)
> It would be good to have more data from real life examples.

From the access logs, there are three requests with the same timestamp:
somesite.bywatersolutions.com:80 IP.IP.IP.IP - - [30/Nov/2020:16:02:14 -0700] "POST /cgi-bin/koha/svc/renew HTTP/1.1" 200 349 "https://staff.somesite.bywatersolutions.com/cgi-bin/koha/circ/circulation.pl?borrowernumber=250710" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.198 Safari/537.36"
somesite.bywatersolutions.com:80 IP.IP.IP.IP - - [30/Nov/2020:16:02:14 -0700] "POST /cgi-bin/koha/svc/renew HTTP/1.1" 200 350 "https://staff.somesite.bywatersolutions.com/cgi-bin/koha/circ/circulation.pl?borrowernumber=250710" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.198 Safari/537.36"
somesite.bywatersolutions.com:80 IP.IP.IP.IP - - [30/Nov/2020:16:02:14 -0700] "POST /cgi-bin/koha/svc/renew HTTP/1.1" 200 349 "https://staff.somesite.bywatersolutions.com/cgi-bin/koha/circ/circulation.pl?borrowernumber=250710" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.198 Safari/537.36"

In the plack log:
DBD::mysql::st execute failed: Deadlock found when trying to get lock; try restarting transaction [for Statement "UPDATE issues SET date_due = ?, renewals = ?, lastreneweddate = ?
                                WHERE borrowernumber=?
                                AND itemnumber=?" with ParamValues: 0='2020-12-30 23:59', 1=1, 2=DateTime=HASH(0x5561e7d4fb08), 3="borrowernumber", 4="itemnumber"] at /usr/share/koha/lib/C4/Circulation.pm line 2964.

In the action_logs:
*************************** 15. row ***************************
action_id: 10050103
timestamp: 2020-11-30 16:02:14
     user: staff_borrowernumber
   module: CIRCULATION
   action: RENEWAL
   object: borrowernumber
     info: itemnumber
interface: intranet

Statistics:
*************************** 19. row ***************************
      datetime: 2020-11-30 16:02:14
        branch: BRANCH
         value: 0.0000
          type: renew
         other: 
    itemnumber: itemnumber
      itemtype: BOOK
      location: ADULT
borrowernumber: borrowernumber
         ccode: FICTION

Issues table:
*************************** 1. row ***************************
       Table: issues
Create Table: CREATE TABLE `issues` (
  `issue_id` int(11) NOT NULL AUTO_INCREMENT,
  `borrowernumber` int(11) NOT NULL,
  `itemnumber` int(11) NOT NULL,
  `date_due` datetime DEFAULT NULL,
  `branchcode` varchar(10) COLLATE utf8mb4_unicode_ci DEFAULT NULL,
  `returndate` datetime DEFAULT NULL,
  `lastreneweddate` datetime DEFAULT NULL,
  `renewals` tinyint(4) NOT NULL DEFAULT '0',
  `auto_renew` tinyint(1) DEFAULT '0',
  `auto_renew_error` varchar(32) COLLATE utf8mb4_unicode_ci DEFAULT NULL,
  `timestamp` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `issuedate` datetime DEFAULT NULL,
  `onsite_checkout` int(1) NOT NULL DEFAULT '0',
  `note` longtext COLLATE utf8mb4_unicode_ci,
  `notedate` datetime DEFAULT NULL,
  `noteseen` int(1) DEFAULT NULL,
  PRIMARY KEY (`issue_id`),
  KEY `issuesborridx` (`borrowernumber`),
  KEY `bordate` (`borrowernumber`,`timestamp`),
  KEY `itemnumber_idx` (`itemnumber`),
  KEY `branchcode_idx` (`branchcode`),
  CONSTRAINT `issues_ibfk_1` FOREIGN KEY (`borrowernumber`) REFERENCES `borrowers` (`borrowernumber`) ON UPDATE CASCADE,
  CONSTRAINT `issues_ibfk_2` FOREIGN KEY (`itemnumber`) REFERENCES `items` (`itemnumber`) ON UPDATE CASCADE
) ENGINE=InnoDB AUTO_INCREMENT=increment DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci

Server version: 10.1.47-MariaDB-0+deb9u1 Debian 9.13
Koha 19.1108000
Comment 17 Nick Clemens 2020-12-04 12:07:09 UTC Comment hidden (obsolete)
Comment 18 Nick Clemens 2020-12-04 12:08:17 UTC Comment hidden (obsolete)
Comment 19 Nick Clemens 2020-12-04 12:09:44 UTC Comment hidden (obsolete)
Comment 20 Nick Clemens 2020-12-04 12:20:59 UTC Comment hidden (obsolete)
Comment 21 Nick Clemens 2020-12-04 12:30:50 UTC
Created attachment 114190 [details] [review]
Bug 26457: Throw exception if update of issues table fails

While this won't prevent the deadlock, it should catch the case where
a deadlock causes the DB update to fail and provide feedback to the user
and rollback the transaction

I don't know how to trigger the deadlock, I can only confirm that we see it, and
that this should catch it.

To test:
1 - Apply patches
2 - Confirm that 'Renew all' feature continues to work as expected
Comment 22 Jonathan Druart 2020-12-04 15:04:44 UTC
Could you provide a test?
Comment 23 David Cook 2020-12-06 23:05:22 UTC
Thanks for the info, Nick. And yeah I think throwing an exception is a good immediate improvement.

Looking at Bug 20086, I think that we're trying to do way too much in 1 database transaction. I've seen this on other systems with a lot of concurrent activity, and debugging these deadlocks is a struggle. 

The AddRenewal function is a bit of a mess in general...
Comment 24 Victor Grousset/tuxayo 2020-12-21 20:17:13 UTC
After applying the patch , while restarting the services, I have a compilation issue.


root@kohadevbox:koha((6982680ae9...))$ restart_all 
Restarting Apache httpd web server: apache2.
Restarting Koha ILS: koha-commonStopping Plack daemon for kohadev:.
Stopping Z39.50/SRU daemon for kohadev:.
Stopping Koha worker daemon for kohadev:.
Stopping Koha indexing daemon for kohadev:.
Starting Plack daemon for kohadev:.
Starting Z39.50/SRU daemon for kohadev:syntax error at /kohadevbox/koha/C4/Circulation.pm line 3091, near "->errstr;"
Type of arg 1 to List::MoreUtils::any must be block or sub {} (not reference constructor) at /kohadevbox/koha/C4/Circulation.pm line 4397, near "} )"
Type of arg 1 to List::MoreUtils::any must be block or sub {} (not reference constructor) at /kohadevbox/koha/C4/Circulation.pm line 4400, near "}) "



> 2 - Confirm that 'Renew all' feature continues to work as expected

Is testing the "Renew all" button in a patron's checkout list enough?
Comment 25 Nick Clemens 2020-12-23 13:08:58 UTC
Created attachment 114669 [details] [review]
Bug 26457: Throw exception if update of issues table fails

While this won't prevent the deadlock, it should catch the case where
a deadlock causes the DB update to fail and provide feedback to the user
and rollback the transaction

I don't know how to trigger the deadlock, I can only confirm that we see it, and
that this should catch it.

To test:
1 - Apply patches
2 - Checkout several items to a patron
3 - Confirm that 'Renew all' feature continues to work as expected and all items are renewed
Comment 26 Nick Clemens 2020-12-23 13:10:00 UTC
(In reply to Jonathan Druart from comment #22)
> Could you provide a test?

I have tried, but it seems it requires a lot of mocking and I have not been successful, help would be appreciated :-)
Comment 27 David Cook 2020-12-23 22:22:17 UTC
(In reply to Nick Clemens from comment #26)
> (In reply to Jonathan Druart from comment #22)
> > Could you provide a test?
> 
> I have tried, but it seems it requires a lot of mocking and I have not been
> successful, help would be appreciated :-)

Couldn't you add a unit test for AddRenewal that just puts in junk data to trigger the exception?
Comment 28 Nick Clemens 2020-12-24 12:23:25 UTC
Created attachment 114697 [details] [review]
Bug 26457: Unit test
Comment 29 Nick Clemens 2020-12-24 12:24:28 UTC
(In reply to David Cook from comment #27)
> (In reply to Nick Clemens from comment #26)
> > (In reply to Jonathan Druart from comment #22)
> > > Could you provide a test?
> > 
> > I have tried, but it seems it requires a lot of mocking and I have not been
> > successful, help would be appreciated :-)
> 
> Couldn't you add a unit test for AddRenewal that just puts in junk data to
> trigger the exception?

Indeed I can! Turns out we pass 'lastreneweddate' right through, so adding junk data in the call lets us trigger the exception
Comment 30 David Nind 2021-02-24 00:24:07 UTC
Created attachment 117227 [details] [review]
Bug 26457: Throw exception if update of issues table fails

While this won't prevent the deadlock, it should catch the case where
a deadlock causes the DB update to fail and provide feedback to the user
and rollback the transaction

I don't know how to trigger the deadlock, I can only confirm that we see it, and
that this should catch it.

To test:
1 - Apply patches
2 - Checkout several items to a patron
3 - Confirm that 'Renew all' feature continues to work as expected and all items are renewed

Signed-off-by: David Nind <david@davidnind.com>
Comment 31 David Nind 2021-02-24 00:24:11 UTC
Created attachment 117228 [details] [review]
Bug 26457: Unit test

Signed-off-by: David Nind <david@davidnind.com>
Comment 32 David Nind 2021-02-24 00:26:11 UTC
Tested by:
- Following test plan (checking out 11 items to a patron, renewing all items 5 times)
- Running prove t/db_dependent/Circulation.t (all tests pass)
Comment 33 Marcel de Rooy 2021-02-26 10:22:14 UTC
QAing
Comment 34 Marcel de Rooy 2021-02-26 10:54:09 UTC
Created attachment 117371 [details] [review]
Bug 26457: Throw exception if update of issues table fails

While this won't prevent the deadlock, it should catch the case where
a deadlock causes the DB update to fail and provide feedback to the user
and rollback the transaction

I don't know how to trigger the deadlock, I can only confirm that we see it, and
that this should catch it.

To test:
1 - Apply patches
2 - Checkout several items to a patron
3 - Confirm that 'Renew all' feature continues to work as expected and all items are renewed

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 35 Marcel de Rooy 2021-02-26 10:54:12 UTC
Created attachment 117372 [details] [review]
Bug 26457: Unit test

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 36 Marcel de Rooy 2021-02-26 10:54:15 UTC
Created attachment 117373 [details] [review]
Bug 26457: (QA follow-up) Switch to PK index in UPDATE on issues

The deadlock reports tell us that multiple transactions are
waiting for a X lock on a record but using a secondary index
on borrowernumber and itemnumber. Since we have the issue_id
at hand already, we should use that and benefit from the clustered
index (on PK) instead of using a secondary index.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 37 Marcel de Rooy 2021-02-26 11:02:09 UTC
Just for completeness, from sql man:

To avoid deadlocks when performing multiple concurrent write operations on a single InnoDB table, acquire necessary locks at the start of the transaction by issuing a SELECT ... FOR UPDATE statement for each group of rows expected to be modified, even if the data change statements come later in the transaction.
Comment 38 Jonathan Druart 2021-03-01 10:28:56 UTC
Pushed to master for 21.05, thanks to everybody involved!
Comment 39 Fridolin Somers 2021-03-02 07:13:06 UTC
Pushed to 20.11.x for 20.11.04
Comment 40 Andrew Fuerste-Henry 2021-03-05 19:49:02 UTC
Doesn't apply cleanly to 20.05. Thought I'd cleared merge errors, but ended up with an error when trying to restart services: 
Global symbol "$unseen_renewals" requires explicit package name (did you forget to declare "my $unseen_renewals"?) at /kohadevbox/koha/C4/Circulation.pm line 2977.
Type of arg 1 to List::MoreUtils::any must be block or sub {} (not reference constructor) at /kohadevbox/koha/C4/Circulation.pm line 4213, near "} )"
Type of arg 1 to List::MoreUtils::any must be block or sub {} (not reference constructor) at /kohadevbox/koha/C4/Circulation.pm line 4216, near "}) "


Please rebase for backport.
Comment 41 Nick Clemens 2021-03-05 20:19:38 UTC
Created attachment 117876 [details] [review]
Bug 26457: [20.05.x] Throw exception if update of issues table fails

While this won't prevent the deadlock, it should catch the case where
a deadlock causes the DB update to fail and provide feedback to the user
and rollback the transaction

I don't know how to trigger the deadlock, I can only confirm that we see it, and
that this should catch it.

To test:
1 - Apply patches
2 - Checkout several items to a patron
3 - Confirm that 'Renew all' feature continues to work as expected and all items are renewed

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Bug 26457: Unit test

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Bug 26457: (QA follow-up) Switch to PK index in UPDATE on issues

The deadlock reports tell us that multiple transactions are
waiting for a X lock on a record but using a secondary index
on borrowernumber and itemnumber. Since we have the issue_id
at hand already, we should use that and benefit from the clustered
index (on PK) instead of using a secondary index.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 42 Andrew Fuerste-Henry 2021-03-05 20:43:58 UTC
Pushed to 20.05.x for 20.05.10
Comment 43 Victor Grousset/tuxayo 2021-03-22 15:59:11 UTC
Issue when trying to backport to 19.11.x, failing test.

kohadev-koha@be9bfe372adf:/kohadevbox/koha$ prove t/db_dependent/Circulation.t
t/db_dependent/Circulation.t .. 40/47 DBD::mysql::st execute failed: Incorrect datetime value: 'HASH(0x562f3aaf8048)' for column 'lastreneweddate' at row 1 [for Statement "UPDATE issues SET date_due = ?, renewals = ?, lastreneweddate = ? WHERE issue_id = ?" with ParamValues: 0='2021-04-12 23:59', 1=1, 2=HASH(0x562f3aaf8048), 3=264] at /kohadevbox/koha/C4/Circulation.pm line 2969.
    # No tests run!
t/db_dependent/Circulation.t .. 42/47 
#   Failed test 'No tests run for subtest "AddRenewal and AddIssuingCharge tests"'
#   at t/db_dependent/Circulation.t line 3201.
Update of issue# 264 failed with error: Incorrect datetime value: 'HASH(0x562f3aaf8048)' for column 'lastreneweddate' at row 1# Looks like your test exited with 255 just after 42.

The conflicts weren't tricky to solve and I don't see how the patch affects lastreneweddate.
So help needed for backporting to 19.11.x
Comment 44 Jonathan Druart 2021-03-23 10:56:07 UTC
Created attachment 118647 [details] [review]
Bug 26457: [19.11.x] Throw exception if update of issues table fails

While this won't prevent the deadlock, it should catch the case where
a deadlock causes the DB update to fail and provide feedback to the user
and rollback the transaction

I don't know how to trigger the deadlock, I can only confirm that we see it, and
that this should catch it.

To test:
1 - Apply patches
2 - Checkout several items to a patron
3 - Confirm that 'Renew all' feature continues to work as expected and all items are renewed

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Bug 26457: Unit test

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Bug 26457: (QA follow-up) Switch to PK index in UPDATE on issues

The deadlock reports tell us that multiple transactions are
waiting for a X lock on a record but using a secondary index
on borrowernumber and itemnumber. Since we have the issue_id
at hand already, we should use that and benefit from the clustered
index (on PK) instead of using a secondary index.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 45 Jonathan Druart 2021-03-23 10:56:30 UTC
I had a try with the conflict on 19.11, can you test this patch?
Comment 46 Victor Grousset/tuxayo 2021-03-23 13:20:31 UTC
Thanks a lot Jonathan, it works! :D
Comment 47 Victor Grousset/tuxayo 2021-03-23 13:21:51 UTC
Backported: Pushed to 19.11.x branch for 19.11.16
Comment 48 Jonathan Druart 2021-12-08 11:14:04 UTC
*** Bug 29650 has been marked as a duplicate of this bug. ***