Bug 27707 - Renewing doesn't work when renewal notices are enabled
Summary: Renewing doesn't work when renewal notices are enabled
Status: CLOSED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Circulation (show other bugs)
Version: Main
Hardware: All All
: P5 - low critical (vote)
Assignee: Jonathan Druart
QA Contact: Joonas Kylmälä
URL:
Keywords: rel_20_11_candidate
Depends on: 15854 26639
Blocks:
  Show dependency treegraph
 
Reported: 2021-02-15 11:23 UTC by Joonas Kylmälä
Modified: 2021-12-13 21:11 UTC (History)
7 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:
21.05.00,20.11.03,20.05.09,19.11.15


Attachments
Bug 27707: (bug 26639 follow-up) Fix renewals when RenewalSendNotice is set (1.94 KB, patch)
2021-02-16 08:22 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 27707: (bug 26639 follow-up) Fix renewals when RenewalSendNotice is set (1.99 KB, patch)
2021-02-16 09:30 UTC, Andrii Nugged
Details | Diff | Splinter Review
Bug 27707: (bug 26639 follow-up) Fix renewals when RenewalSendNotice is set (2.14 KB, patch)
2021-02-16 09:46 UTC, Joonas Kylmälä
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Joonas Kylmälä 2021-02-15 11:23:19 UTC
Renewing loans doesn't work for patrons who have enabled renewal notices to be sent to them. To reproduce:

1) Enable RenewalSendNotice 
2) Add some email address to patron and select the email box from the message preference "Item checkout and renewal" in order to receive renewal emails.
3) Checkout 4 items to the patron (maybe 1 is enough not quite sure)
4) Try to renew the loans in intranet and notice the progress icon circles forever and in the plack-error.log you have following error:

> DBIx::Class::Storage::DBI::mysql::_exec_svp_release(): DBI Exception: DBD::mysql::db do failed: SAVEPOINT savepoint_0 does not exist [for Statement "RELEASE SAVEPOINT savepoint_0"] at /usr/share/koha/lib/C4/Circulation.pm line 3590

This bug seems to have started happening after bug 26639 was merged, i.e. AUTO SAVEPOINT was enabled. I have found a workaround and possibly it is also a reasonable solution:

In C4/Circulation.pm function SendCirculationAlert there is this comment:

> # LOCK TABLES is not transaction-safe and implicitly commits any active 
> transaction before attempting to lock the tables.

So basically if that comment is true (I have not verified) then it means that the transaction that has been put around the "LOCK TABLE message_queue READ" stuff is doing nothing. And here based on the error message we got in plack-error.log the problem is that we are trying to commit a non-existent transaction because as per the comment in the code calling LOCK TABLE already commited the transaction so there is no transaction left for us to commit manually in the end. To summarise we need to remove the two lines I think:

        $schema->storage->txn_begin;
        $schema->storage->txn_commit;

Also why I think the above solution is reasonable is because otherwise we need to rethought the design here totally on how the digest messages are sent and maybe add a new is_digest db column and do the logic in the message sending script instead of "merging db rows". For more background on why the table locking was introduced see bug 15854.

PS. I think this bug might affect check-in and checkouts, not totally sure.
Comment 1 Jonathan Druart 2021-02-15 13:53:25 UTC
I did some testing and I confirm that the txn is not needed here.

use Koha::Database;
my $schema = Koha::Database->new->schema;
$schema->txn_do(sub {
    $schema->txn_do( sub {
        my $dbh = $schema->storage->dbh;
        say "getting locks";
        $dbh->do(q|LOCK TABLE message_queue READ|);
        $dbh->do(q|LOCK TABLE message_queue WRITE|);
        say "locked!";
        sleep 10;
        say "unlocking";
        $dbh->do(q|UNLOCK TABLES|);
        say "unlocked!";
    });
});

Start several parallel processes.

Remove the nested txn_do, try again.
Comment 2 Jonathan Druart 2021-02-16 08:22:36 UTC
Created attachment 116906 [details] [review]
Bug 27707: (bug 26639 follow-up) Fix renewals when RenewalSendNotice is set

Since bug 26639 we have auto savepoint enabled and the LOCK TABLE query
in C4::Circulation::SendCirculationAlert is not correctly handled.
From the MySQL doc that is copied few lines before, "LOCK TABLE will
commit any transactions", but here we don't have a savepoint and the
release for a non-existent savepoint will throw a DBI exception.

This patch removes the unecessary transaction and prevent the following
error when a renewal is done:
> DBIx::Class::Storage::DBI::mysql::_exec_svp_release(): DBI Exception: DBD::mysql::db do failed: SAVEPOINT savepoint_0 does not exist [for Statement "RELEASE SAVEPOINT savepoint_0"] at /usr/share/koha/lib/C4/Circulation.pm line 3590

Test plan:
1. Enable RenewalSendNotice
2. Add some email address to patron and select the email box from the message preference "Item checkout and renewal" in order to receive renewal emails.
3. Check 1 item out to a patron
4. Renew it
Comment 3 Andrii Nugged 2021-02-16 09:30:54 UTC
Created attachment 116909 [details] [review]
Bug 27707: (bug 26639 follow-up) Fix renewals when RenewalSendNotice is set

Since bug 26639 we have auto savepoint enabled and the LOCK TABLE query
in C4::Circulation::SendCirculationAlert is not correctly handled.
From the MySQL doc that is copied few lines before, "LOCK TABLE will
commit any transactions", but here we don't have a savepoint and the
release for a non-existent savepoint will throw a DBI exception.

This patch removes the unecessary transaction and prevent the following
error when a renewal is done:
> DBIx::Class::Storage::DBI::mysql::_exec_svp_release(): DBI Exception: DBD::mysql::db do failed: SAVEPOINT savepoint_0 does not exist [for Statement "RELEASE SAVEPOINT savepoint_0"] at /usr/share/koha/lib/C4/Circulation.pm line 3590

Test plan:
1. Enable RenewalSendNotice
2. Add some email address to patron and select the email box from the message preference "Item checkout and renewal" in order to receive renewal emails.
3. Check 1 item out to a patron
4. Renew it

Signed-off-by: Andrew Nugged <nugged@gmail.com>
Comment 4 Joonas Kylmälä 2021-02-16 09:40:23 UTC
I found the MySQL documentation where the LOCK Tables behaviour with transactions is explained: https://dev.mysql.com/doc/refman/8.0/en/lock-tables.html
Comment 5 Joonas Kylmälä 2021-02-16 09:46:47 UTC
Created attachment 116910 [details] [review]
Bug 27707: (bug 26639 follow-up) Fix renewals when RenewalSendNotice is set

Since bug 26639 we have auto savepoint enabled and the LOCK TABLE query
in C4::Circulation::SendCirculationAlert is not correctly handled.
From the MySQL doc that is copied few lines before, "LOCK TABLE will
commit any transactions", but here we don't have a savepoint and the
release for a non-existent savepoint will throw a DBI exception.

This patch removes the unecessary transaction and prevent the following
error when a renewal is done:
> DBIx::Class::Storage::DBI::mysql::_exec_svp_release(): DBI Exception: DBD::mysql::db do failed: SAVEPOINT savepoint_0 does not exist [for Statement "RELEASE SAVEPOINT savepoint_0"] at /usr/share/koha/lib/C4/Circulation.pm line 3590

Test plan:
1. Enable RenewalSendNotice
2. Add some email address to patron and select the email box from the message preference "Item checkout and renewal" in order to receive renewal emails.
3. Check 1 item out to a patron
4. Renew it

Signed-off-by: Andrew Nugged <nugged@gmail.com>
Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi>
Comment 6 Jonathan Druart 2021-02-16 13:50:24 UTC
@RMaints: you all need this one.
Comment 7 Jonathan Druart 2021-02-16 13:55:19 UTC
Pushed to master for 21.05, thanks to everybody involved!
Comment 8 Fridolin Somers 2021-02-19 14:33:25 UTC
Pushed to 20.11.x for 20.11.03
Comment 9 Andrew Fuerste-Henry 2021-02-22 20:45:25 UTC
Testing this for backport on 20.05, I am able to renew without a problem with RenewalSendNotice on and the patch not applied. I get a warning in the plack-intranet-error.log:
[2021/02/22 20:41:57] [WARN] DBD::mysql::db do failed: SAVEPOINT savepoint_0 does not exist [for Statement "RELEASE SAVEPOINT savepoint_0"] at /usr/share/perl5/DBIx/Class/Storage/DBI/mysql.pm line 152.

That warning persists after I've applied the patch. Again, I get a successful renewal and renewal notice regardless of whether or not this patch is present.

I'm inclined to skip backport, since I can't recreate the issue.
Comment 10 Andrew Fuerste-Henry 2021-02-23 17:11:39 UTC
Pushed to 20.05.x for 20.05.09

As mentioned, I was unable to reproduce this error on my Koha Testing Docker running MariaDB 10.1.48. However, the patch applied fine and didn't break anything. I'm backporting on the assumption that this may impact 20.05 users with a different database version.
Comment 11 Victor Grousset/tuxayo 2021-02-23 17:28:33 UTC
Backported: Pushed to 19.11.x branch for 19.11.15
Comment 12 Joonas Kylmälä 2021-04-26 09:54:49 UTC
Still problems with renewals, now the error is just:

Waiting for table metadata lock | LOCK TABLE message_queue READ
Comment 13 Joonas Kylmälä 2021-04-27 04:58:08 UTC
(In reply to Joonas Kylmälä from comment #12)
> Still problems with renewals, now the error is just:
> 
> Waiting for table metadata lock | LOCK TABLE message_queue READ

The locked table seems to have been caused by Bug 28230 so continuing discussion relating to this there.