Mailing List Archive: RT 4.4.1 and transaction isolation level on Postgres

Hi,
to reproduce the deadlock problem with RT 4.4.1 on Postgres I tried to install
RT 4.4.1 as clean new instalation:
1. On Debian 8.6 stable + Postgres 9.4
2. On Debian sid (unstable) + Postgres 9.6 (there was a need to
change one sql command, option NOCREATEUSER -> NOCREATEROLE)

To my surprise I created ticket in queue General (default) and the bug
appeared immediately when I tried to change owner of a ticket and record
comment together.

Can anybody confirm on different system?

Steps:
1. Create Postgres cluster (server instance):

pg_createcluster 9.6 main --locale cs_CZ.UTF-8

2. Change access to rt4 database, so I don't need to set password for rt_user
in /etc/postgresql/9.6/main/pg_hba.conf

diff --git a/postgresql/9.6/main/pg_hba.conf b/postgresql/9.6/main/pg_hba.conf
index b708a885..85857f64 100644
--- a/postgresql/9.6/main/pg_hba.conf
+++ b/postgresql/9.6/main/pg_hba.conf
@@ -86,6 +86,8 @@ local all postgres peer

# TYPE DATABASE USER ADDRESS METHOD

+local rt4 rt_user trust
+
# "local" is for Unix domain socket connections only
local all all peer
# IPv4 local connections:

3. Start Postgres & check

pg_ctlcluster 9.6 main start
pg_lsclusters

4. Install RT 4.4.1 from RT sources...

cd rt-4.4.1-sources
./configure --prefix=/opt/rt --with-db-type=Pg
sudo make install

Change db host, so the connection will go through unix domain socket

cd /opt/rt
cat <<'EOT' >etc/RT_SiteConfig.pm
Set($WebPort, 8888);
Set($DatabaseHost, undef);
Set($DatabaseRTHost, undef);
1;
EOT

Postgres user needs to read schame etc

chmod a+r etc/{acl,initialdata,schema}*

Postgres 9.6 no longer support NOCREATEUSER, but NOTCREATEROLE
(https://www.postgresql.org/docs/9.6/static/release-9-6.html)

sed -i -e 's/NOCREATEUSER/NOCREATEROLE/;' etc/acl.Pg

Initialize database (if something went wrong, remove not finished database
using 'sudo -u postgres dropdb rt4' and try better again)

sudo -u postgres /usr/bin/perl -I/opt/rt/local/lib -I/opt/rt/lib sbin/rt-setup-database --action init

5. Start RT built int HTTP server by hand:

sudo -u www-data /opt/rt/sbin/rt-server --port 8888

6. Go to browser and type location localhost:8888

- login as root / password
- click on "New ticket in" General, enter something into subject and message
and click "Create"
(Owner is nobody, requestor is root)
- Go Actions / Comment, type something into message and change owner
to root. Click "Update ticket"
- If owner was changed, try repeat previous step switching owner
between nobody & root, until error.

My session:

bobek:/opt/rt# sudo -u www-data /opt/rt/sbin/rt-server --port 8888
[21132] [Mon Jan 2 15:58:50 2017] [info]: Successful login for root from 127.0.0.1 (/opt/rt/sbin/../lib/RT/Interface/Web.pm:831)
[21133] [Mon Jan 2 16:00:21 2017] [info]: <rt-4.4.1-21133-1483372820-1051.1-7-0@example.com> #1/31 - Scrip 7 On Create Autoreply To Requestors (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:285)
[21133] [Mon Jan 2 16:00:21 2017] [info]: <rt-4.4.1-21133-1483372820-1051.1-7-0@example.com> sent To: root@localhost (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:316)
[21133] [Mon Jan 2 16:00:21 2017] [info]: <rt-4.4.1-21133-1483372821-1765.1-8-0@example.com> #1/31 - Scrip 8 On Create Notify Owner and AdminCcs (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:285)
[21133] [Mon Jan 2 16:00:21 2017] [info]: <rt-4.4.1-21133-1483372821-1765.1-8-0@example.com> No recipients found. Not sending. (/opt/rt/sbin/../lib/RT/Interface/Email.pm:806)
[21133] [Mon Jan 2 16:00:21 2017] [info]: <rt-4.4.1-21133-1483372821-1271.1-9-0@example.com> #1/31 - Scrip 9 On Create Notify Ccs (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:285)
[21133] [Mon Jan 2 16:00:21 2017] [info]: <rt-4.4.1-21133-1483372821-1271.1-9-0@example.com> No recipients found. Not sending. (/opt/rt/sbin/../lib/RT/Interface/Email.pm:806)
[21133] [Mon Jan 2 16:00:21 2017] [info]: <rt-4.4.1-21133-1483372821-1685.1-10-0@example.com> #1/31 - Scrip 10 On Create Notify Other Recipients (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:285)
[21133] [Mon Jan 2 16:00:21 2017] [info]: <rt-4.4.1-21133-1483372821-1685.1-10-0@example.com> No recipients found. Not sending. (/opt/rt/sbin/../lib/RT/Interface/Email.pm:806)
[21133] [Mon Jan 2 16:00:21 2017] [info]: Ticket 1 created in queue 'General' by root (/opt/rt/sbin/../lib/RT/Ticket.pm:567)
[21132] [Mon Jan 2 16:02:37 2017] [info]: <rt-4.4.1-21132-1483372957-1152.1-11-0@example.com> not sending to root@localhost, creator of the transaction, due to NotifyActor setting (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:901)
[21133] [Mon Jan 2 16:02:48 2017] [info]: <rt-4.4.1-21133-1483372968-1533.1-11-0@example.com> not sending to root@localhost, creator of the transaction, due to NotifyActor setting (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:901)
[21133] [Mon Jan 2 16:02:48 2017] [info]: <rt-4.4.1-21133-1483372968-1533.1-11-0@example.com> #1/39 - Scrip 11 On Owner Change Notify Owner (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:285)
[21133] [Mon Jan 2 16:02:48 2017] [info]: <rt-4.4.1-21133-1483372968-1533.1-11-0@example.com> No recipients found. Not sending. (/opt/rt/sbin/../lib/RT/Interface/Email.pm:806)
[21133] [Mon Jan 2 16:03:19 2017] [info]: <rt-4.4.1-21133-1483372999-1299.1-1-0@example.com> #1/45 - Scrip 1 On Comment Notify AdminCcs as Comment (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:285)
[21133] [Mon Jan 2 16:03:19 2017] [info]: <rt-4.4.1-21133-1483372999-1299.1-1-0@example.com> No recipients found. Not sending. (/opt/rt/sbin/../lib/RT/Interface/Email.pm:806)
[21133] [Mon Jan 2 16:03:19 2017] [info]: <rt-4.4.1-21133-1483372999-1044.1-2-0@example.com> #1/45 - Scrip 2 On Comment Notify Other Recipients as Comment (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:285)
[21133] [Mon Jan 2 16:03:19 2017] [info]: <rt-4.4.1-21133-1483372999-1044.1-2-0@example.com> No recipients found. Not sending. (/opt/rt/sbin/../lib/RT/Interface/Email.pm:806)
[21133] [Mon Jan 2 16:03:19 2017] [info]: <rt-4.4.1-21133-1483372999-1062.1-11-0@example.com> #1/46 - Scrip 11 On Owner Change Notify Owner (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:285)
[21133] [Mon Jan 2 16:03:19 2017] [info]: <rt-4.4.1-21133-1483372999-1062.1-11-0@example.com> No recipients found. Not sending. (/opt/rt/sbin/../lib/RT/Interface/Email.pm:806)
[21132] [Mon Jan 2 16:03:34 2017] [info]: <rt-4.4.1-21132-1483373014-750.1-11-0@example.com> not sending to root@localhost, creator of the transaction, due to NotifyActor setting (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:901)
[21140] [Mon Jan 2 16:03:37 2017] [info]: <rt-4.4.1-21140-1483373017-415.1-1-0@example.com> #1/53 - Scrip 1 On Comment Notify AdminCcs as Comment (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:285)
[21140] [Mon Jan 2 16:03:37 2017] [info]: <rt-4.4.1-21140-1483373017-415.1-1-0@example.com> No recipients found. Not sending. (/opt/rt/sbin/../lib/RT/Interface/Email.pm:806)
[21140] [Mon Jan 2 16:03:37 2017] [info]: <rt-4.4.1-21140-1483373017-851.1-2-0@example.com> #1/53 - Scrip 2 On Comment Notify Other Recipients as Comment (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:285)
[21140] [Mon Jan 2 16:03:37 2017] [info]: <rt-4.4.1-21140-1483373017-851.1-2-0@example.com> No recipients found. Not sending. (/opt/rt/sbin/../lib/RT/Interface/Email.pm:806)
[21140] [Mon Jan 2 16:03:38 2017] [warning]: DBD::Pg::st execute failed: ERROR: deadlock detected
DETAIL: Process 21479 waits for ShareLock on transaction 1134; blocked by process 21157.
Process 21157 waits for ShareLock on transaction 1135; blocked by process 21479.
HINT: See server log for query details.
CONTEXT: while updating tuple (0,21) in relation "tickets" at /usr/share/perl5/DBIx/SearchBuilder/Handle.pm line 586. (/usr/share/perl5/DBIx/SearchBuilder/Handle.pm:586)
[21140] [Mon Jan 2 16:03:38 2017] [warning]: RT::Handle=HASH(0x55fc4d97fd18) couldn't execute the query 'UPDATE Tickets SET Owner=? WHERE id=? ' at /usr/share/perl5/DBIx/SearchBuilder/Handle.pm line 599.
DBIx::SearchBuilder::Handle::SimpleQuery(RT::Handle=HASH(0x55fc4d97fd18), "UPDATE Tickets SET Owner=? WHERE id=? ", 14, 1) called at /usr/share/perl5/DBIx/SearchBuilder/Handle.pm line 453
DBIx::SearchBuilder::Handle::UpdateRecordValue(RT::Handle=HASH(0x55fc4d97fd18), "Column", "Owner", "Table", "Tickets", "PrimaryKeys", HASH(0x55fc4de23ab8), "Value", ...) called at /usr/share/perl5/DBIx/SearchBuilder/Record.pm line 871
DBIx::SearchBuilder::Record::__Set(RT::Ticket=HASH(0x55fc4dce9210), "Field", "Owner", "Value", 14, "IsSQL", undef) called at /usr/share/perl5/DBIx/SearchBuilder/Record/Cachable.pm line 140
DBIx::SearchBuilder::Record::Cachable::__Set(RT::Ticket=HASH(0x55fc4dce9210), "Field", "Owner", "Value", 14, "IsSQL", undef) called at /usr/share/perl5/DBIx/SearchBuilder/Record.pm line 744
DBIx::SearchBuilder::Record::_Set(RT::Ticket=HASH(0x55fc4dce9210), "Field", "Owner", "Value", 14, "IsSQL", undef) called at /opt/rt/sbin/../lib/RT/Record.pm line 462
RT::Record::_Set(RT::Ticket=HASH(0x55fc4dce9210), "Field", "Owner", "Value", 14) called at /opt/rt/sbin/../lib/RT/Ticket.pm line 2634
RT::Ticket::_Set(RT::Ticket=HASH(0x55fc4dce9210), "Field", "Owner", "Value", 14, "CheckACL", 0, "RecordTransaction", ...) called at /opt/rt/sbin/../lib/RT/Group.pm line 993
RT::Group::_AddMember(RT::Group=HASH(0x55fc4db25448), "PrincipalId", 14, "InsideTransaction", 1, "Object", RT::Ticket=HASH(0x55fc4dce9210)) called at /opt/rt/sbin/../lib/RT/Ticket.pm line 1968
RT::Ticket::SetOwner(RT::Ticket=HASH(0x55fc4dce9210), 14, "Set") called at /opt/rt/sbin/../lib/RT/Interface/Web.pm line 2975
HTML::Mason::Commands::ProcessTicketBasics("ARGSRef", HASH(0x55fc4dc9a470), "TicketObj", RT::Ticket=HASH(0x55fc4dce9210)) called at /opt/rt/share/html/Ticket/Display.html line 190
HTML::Mason::Commands::__ANON__("TicketObj", RT::Ticket=HASH(0x55fc4dce9210), "SubmitTicket", "Update Ticket", "TxnRecipients", "", "QuoteTransaction", "", ...) called at /usr/share/perl5/HTML/Mason/Component.pm line 135
HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x55fc4dc8e118), "TicketObj", RT::Ticket=HASH(0x55fc4dce9210), "SubmitTicket", "Update Ticket", "TxnRecipients", "", "QuoteTransaction", ...) called at /usr/share/perl5/HTML/Mason/Request.pm line 1302
eval {...} called at /usr/share/perl5/HTML/Mason/Request.pm line 1292
HTML::Mason::Request::comp(undef, undef, "TicketObj", RT::Ticket=HASH(0x55fc4dce9210), "SubmitTicket", "Update Ticket", "TxnRecipients", "", ...) called at /opt/rt/share/html/Ticket/Update.html line 347
HTML::Mason::Commands::__ANON__("UpdateTimeWorked", "", "Action", "Comment", "DefaultStatus", "new", "UpdateBcc", "", ...) called at /usr/share/perl5/HTML/Mason/Component.pm line 135
HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x55fc4dbdba78), "UpdateTimeWorked", "", "Action", "Comment", "DefaultStatus", "new", "UpdateBcc", ...) called at /usr/share/perl5/HTML/Mason/Request.pm line 1302
eval {...} called at /usr/share/perl5/HTML/Mason/Request.pm line 1292
HTML::Mason::Request::comp(undef, undef, undef, "UpdateTimeWorked", "", "Action", "Comment", "DefaultStatus", ...) called at /usr/share/perl5/HTML/Mason/Request.pm line 955
HTML::Mason::Request::call_next(RT::Interface::Web::Request=HASH(0x55fc4d5afea0)) called at /opt/rt/share/html/Ticket/autohandler line 66
HTML::Mason::Commands::__ANON__("UpdateTimeWorked", "", "Action", "Comment", "DefaultStatus", "new", "UpdateBcc", "", ...) called at /usr/share/perl5/HTML/Mason/Component.pm line 135
HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x55fc4dbf6580), "UpdateTimeWorked", "", "Action", "Comment", "DefaultStatus", "new", "UpdateBcc", ...) called at /usr/share/perl5/HTML/Mason/Request.pm line 1302
eval {...} called at /usr/share/perl5/HTML/Mason/Request.pm line 1292
HTML::Mason::Request::comp(undef, undef, undef, "UpdateTimeWorked", "", "Action", "Comment", "DefaultStatus", ...) called at /opt/rt/sbin/../lib/RT/Interface/Web.pm line 696
RT::Interface::Web::ShowRequestedPage(HASH(0x55fc4da121e8)) called at /opt/rt/sbin/../lib/RT/Interface/Web.pm line 375
RT::Interface::Web::HandleRequest(HASH(0x55fc4da121e8)) called at /opt/rt/share/html/autohandler line 53
HTML::Mason::Commands::__ANON__("QuoteTransaction", "", "TxnRecipients", "", "SubmitTicket", "Update Ticket", "UpdateTimeWorked-TimeUnits", "minutes", ...) called at /usr/share/perl5/HTML/Mason/Component.pm line 135
HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x55fc4d9d0930), "QuoteTransaction", "", "TxnRecipients", "", "SubmitTicket", "Update Ticket", "UpdateTimeWorked-TimeUnits", ...) called at /usr/share/perl5/HTML/Mason/Request.pm line 1300
eval {...} called at /usr/share/perl5/HTML/Mason/Request.pm line 1292
HTML::Mason::Request::comp(undef, undef, undef, "QuoteTransaction", "", "TxnRecipients", "", "SubmitTicket", ...) called at /usr/share/perl5/HTML/Mason/Request.pm line 481
eval {...} called at /usr/share/perl5/HTML/Mason/Request.pm line 481
eval {...} called at /usr/share/perl5/HTML/Mason/Request.pm line 433
HTML::Mason::Request::exec(RT::Interface::Web::Request=HASH(0x55fc4d5afea0)) called at /usr/share/perl5/HTML/Mason/PSGIHandler.pm line 96
eval {...} called at /usr/share/perl5/HTML/Mason/PSGIHandler.pm line 96
HTML::Mason::Request::PSGI::exec(RT::Interface::Web::Request=HASH(0x55fc4d5afea0)) called at /usr/share/perl5/HTML/Mason/Interp.pm line 342
HTML::Mason::Interp::exec(undef, undef, "QuoteTransaction", "", "TxnRecipients", "", "SubmitTicket", "Update Ticket", ...) called at /usr/share/perl5/HTML/Mason/PSGIHandler.pm line 59
eval {...} called at /usr/share/perl5/HTML/Mason/PSGIHandler.pm line 59
HTML::Mason::PSGIHandler::invoke_mason(HTML::Mason::PSGIHandler::Streamy=HASH(0x55fc4d5ae0a8), HASH(0x55fc4d9c9e38), HASH(0x55fc4d9b4de8)) called at /usr/share/perl5/HTML/Mason/PSGIHandler/Streamy.pm line 52
HTML::Mason::PSGIHandler::Streamy::__ANON__(CODE(0x55fc4d9b4ba8)) called at /usr/share/perl5/Plack/Util.pm line 339
Plack::Util::__ANON__(CODE(0x55fc4dcc5180)) called at /usr/share/perl5/Starlet/Server.pm line 377
Starlet::Server::handle_connection(Plack::Handler::Starlet=HASH(0x55fc4d79b858), HASH(0x55fc4da86f38), IO::Socket::INET=GLOB(0x55fc4d9c9b80), CODE(0x55fc4d353d00), "", "", "") called at /usr/share/perl5/Starlet/Server.pm line 190
Starlet::Server::accept_loop(Plack::Handler::Starlet=HASH(0x55fc4d79b858), CODE(0x55fc4d353d00), 100) called at /usr/share/perl5/Plack/Handler/Starlet.pm line 80
Plack::Handler::Starlet::run(Plack::Handler::Starlet=HASH(0x55fc4d79b858), CODE(0x55fc4d353d00)) called at /usr/share/perl5/Plack/Loader.pm line 84
Plack::Loader::run(Plack::Loader=HASH(0x55fc4d45ee08), Plack::Handler::Starlet=HASH(0x55fc4d79b858)) called at /usr/share/perl5/Plack/Runner.pm line 277
Plack::Runner::run(RT::PlackRunner=HASH(0x55fc46c5af10)) called at /opt/rt/sbin/../lib/RT/PlackRunner.pm line 141
eval {...} called at /opt/rt/sbin/../lib/RT/PlackRunner.pm line 141
RT::PlackRunner::run(RT::PlackRunner=HASH(0x55fc46c5af10)) called at /opt/rt/sbin/rt-server line 162 (/usr/share/perl/5.24/Carp.pm:170)
[21140] [Mon Jan 2 16:03:38 2017] [warning]: Rollback and commit are mixed while escaping nested transaction at /usr/share/perl5/DBIx/SearchBuilder/Handle.pm line 845. (/usr/share/perl5/DBIx/SearchBuilder/Handle.pm:845)
[21131] [Mon Jan 2 16:03:38 2017] [info]: <rt-4.4.1-21131-1483373018-15.1-11-0@example.com> not sending to root@localhost, creator of the transaction, due to NotifyActor setting (/opt/rt/sbin/../lib/RT/Action/SendEmail.pm:901)

PS: I reported this problem already on https://issues.bestpractical.com/:
#32381: RT 4.4 database deadlock during comment/correspondence + owner change together

--
Zito

On Tue, 3 Jan 2017 17:06:47 +0100
VÃ¡clav OvsÃk <vaclav.ovsik@i.cz> wrote:
> How about the Mysql don't have this problem - is this caused by
> the different default transaction isolation level or not?

MySQL suffers from the exact same problem -- but, as it happens,
both more silently and more catastrophically. See
https://github.com/bestpractical/rt/commit/e36364c5

> I can change isolation level in postgresql.conf to 'repeatable read'
> and things are different.

I advise against doing that. Upon inspection, RT is not prepared to
deal with the "could not serialize access due to concurrent update"
errors that arise from updates to rows in multiple transactions in
Postgres' repeatable-read isolation.

Repeatable-read is only possible in MySQL because it has a fascinating
definition of "repeatable":

----------------------------- Process 1 ------------------------
Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

+----+---------+
| id | Subject |
+----+---------+
| 1 | foo |
+----+---------+
1 row in set (0.00 sec)

----------------------------- Process 2 ------------------------

Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

Query OK, 1 row affected (0.00 sec)
Rows matched: 1 Changed: 1 Warnings: 0

Query OK, 0 rows affected (0.00 sec)

----------------------------- Process 1 ------------------------

+----+---------+
| id | Subject |
+----+---------+
| 1 | foo |
+----+---------+
1 row in set (0.00 sec)

+----+---------+
| id | Subject |
+----+---------+
| 1 | bar |
+----+---------+
1 row in set (0.00 sec)
----------------------------------------------------------------

Contrast this with PostgreSQL, whose definition of repeatable read
acknowledges that fully consistent updates are not possible in all
cases:

----------------------------- Process 1 ------------------------
rt4=# start transaction;
START TRANSACTION
rt4=# set transaction isolation level repeatable read;
SET
rt4=# select id, Subject from Tickets where id = 1;
id | subject
----+---------
1 | foo
(1 row)

----------------------------- Process 2 ------------------------
rt4=# start transaction;
START TRANSACTION
rt4=# set transaction isolation level repeatable read;
SET
rt4=# update Tickets set Subject = 'bar' where id = 1;
UPDATE 1
rt4=# commit;
COMMIT

----------------------------- Process 1 ------------------------
rt4=# select id, Subject from Tickets where id = 1;
id | subject
----+---------
1 | foo
(1 row)

rt4=# select id, Subject from Tickets where id = 1 FOR UPDATE;
ERROR: could not serialize access due to concurrent update

----------------------------------------------------------------

( Yes, MySQL requires SET TRANSACTION ISOLATION _outside_ the
transaction, and PostgreSQL requires it to be _inside_. See
https://dev.mysql.com/doc/refman/5.7/en/set-transaction.html
https://www.postgresql.org/docs/9.1/static/sql-set-transaction.html )

> Should I change the default isolation level on Postgres for RT to
> 'repeatable read'?

No. You should try the 4.4/previewscrips-race branch, which I've just
pushed:

https://github.com/bestpractical/rt/compare/4.4-trunk...4.4/previewscrips-race

The gory details are contained in the commits therein.
- Alex