[rt-users] RT 4.4.1 and transaction isolation level on Postgres

Václav Ovsík vaclav.ovsik at i.cz
Mon Jan 2 11:12:29 EST 2017


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 at 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 at example.com> sent  To: root at 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 at 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 at 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 at 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 at 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 at 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 at 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 at example.com> not sending to root at 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 at example.com> not sending to root at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at example.com> not sending to root at 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 at 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 at 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 at 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 at 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 at example.com> not sending to root at 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



More information about the rt-users mailing list