Rt record locking after RT upgrade to 4.4.4

Good afternoon all,

We have a major issue with our RT install that has been running great for years. We upgraded from 4.2 to 4.4.4. and we are now receiving errors when one of our scripts runs on status change

The Script is very simple and passes the ID and one custom field to a URL, which then uses the rest API to update the ticket with information from an external server, this has worked well for a long time, Since the upgrade however the script takes about 2 minutes to run (Normally 3 seconds) and we are getting an error about the record being locked in the logs. The values from the script are entered into RT but then are deleted the same second. We checked one previous person who had the same issue but were unable to resolve it. we even went as far as to disable every script except this one so that we could make sure nothing else was modifying the record. The error is below. Any help would me massively appreciated

[error]: Doing Part Lookup 180191 ((eval 1421):7)

[5082] [Tue Nov 5 13:30:23 2019] [warning]: Use of uninitialized value in concatenation (.) or string at (eval 1421) line 8. ((eval 1421):8)
[5080] [Tue Nov 5 13:30:26 2019] [info]: Successful login for automator from 37.9.63.178 (/opt/rt4/sbin/…/lib/RT/Interface/Web.pm:832)
[5078] [Tue Nov 5 13:31:18 2019] [warning]: DBD::mysql::st execute failed: Lock wait timeout exceeded; try restarting transaction at /usr/share/perl5/DBIx/SearchBuilder/Handle.pm line 586. (/usr/share/perl5/DBIx/SearchBuilder/Handle.pm:586)
[5078] [Tue Nov 5 13:31:18 2019] [warning]: RT::Handle=HASH(0x5629e65f8e78) couldn’t execute the query ‘SELECT * FROM Tickets WHERE id = ? FOR UPDATE’ at /usr/share/perl5/DBIx/SearchBuilder/Handle.pm line 599.
DBIx::SearchBuilder::Handle::SimpleQuery(RT::Handle=HASH(0x5629e65f8e78), “SELECT * FROM Tickets WHERE id = ? FOR UPDATE”, 180191) called at /usr/share/perl5/DBIx/SearchBuilder/Record.pm line 1234
DBIx::SearchBuilder::Record::_LoadFromSQL(RT::Ticket=HASH(0x5629e95f3cd0), “SELECT * FROM Tickets WHERE id = ? FOR UPDATE”, 180191) called at /opt/rt4/sbin/…/lib/RT/Record.pm line 1614
RT::Record::LockForUpdate(RT::Ticket=HASH(0x5629e95f3cd0)) called at /opt/rt4/sbin/…/lib/RT/Record.pm line 1649
RT::Record::_NewTransaction(RT::Ticket=HASH(0x5629e95f3cd0), “Type”, “CustomField”, “Field”, 33, “OldReference”, undef, “NewReference”, …) called at /opt/rt4/sbin/…/lib/RT/Record.pm line 2035
RT::Record::_AddCustomFieldValue(RT::Ticket=HASH(0x5629e95f3cd0), “Field”, RT::CustomField=HASH(0x5629e97153b8), “Value”, “661-07293|SVCIPHONE 7 DISPLAYBLCK/JBLKDH|112.5 \x{a}”) called at /opt/rt4/sbin/…/lib/RT/Record.pm line 1925
RT::Record::AddCustomFieldValue(RT::Ticket=HASH(0x5629e95f3cd0), “Field”, RT::CustomField=HASH(0x5629e97153b8), “Value”, “661-07293|SVCIPHONE 7 DISPLAYBLCK/JBLKDH|112.5 \x{a}”) called at /opt/rt4/local/html/REST/1.0/Forms/ticket/default line 408
HTML::Mason::Commands::ANON(“id”, 180191, “args”, “edit”, “format”, undef, “changes”, HASH(0x5629e985da40)) called at /usr/share/perl5/HTML/Mason/Component.pm line 135
HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x5629e7215ef0), “id”, 180191, “args”, “edit”, “format”, undef, “changes”, …) 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, “id”, 180191, “args”, “edit”, “format”, undef, …) called at /opt/rt4/share/html/REST/1.0/dhandler line 299
HTML::Mason::Commands::ANON(“user”, “root”, " KGB: 661-07293| | \x{a}\x{a}CF-Condition Grade: A Grade AMS\x{a}", “”, “content”, “CF-GSX Repair ID: G381887002\x{a}CF-Spare Parts: 661-07293|SVCIPH”…, “pass”, “Wolf4u4u”) called at /usr/share/perl5/HTML/Mason/Component.pm line 135
HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x5629e6bf27f8), “user”, “root”, " KGB: 661-07293| | \x{a}\x{a}CF-Condition Grade: A Grade AMS\x{a}", “”, “content”, “CF-GSX Repair ID: G381887002\x{a}CF-Spare Parts: 661-07293|SVCIPH”…, “pass”, …) 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, “user”, “root”, " KGB: 661-07293| | \x{a}\x{a}CF-Condition Grade: A Grade AMS\x{a}", “”, “content”, …) called at /usr/share/perl5/HTML/Mason/Request.pm line 955
HTML::Mason::Request::call_next(RT::Interface::Web::Request=HASH(0x5629e8c97748)) called at /opt/rt4/share/html/REST/1.0/autohandler line 54
HTML::Mason::Commands::ANON(“user”, “root”, " KGB: 661-07293| | \x{a}\x{a}CF-Condition Grade: A Grade AMS\x{a}", “”, “content”, “CF-GSX Repair ID: G381887002\x{a}CF-Spare Parts: 661-07293|SVCIPH”…, “pass”, “Wolf4u4u”) called at /usr/share/perl5/HTML/Mason/Component.pm line 135
HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x5629e6c041c8), “user”, “root”, " KGB: 661-07293| | \x{a}\x{a}CF-Condition Grade: A Grade AMS\x{a}", “”, “content”, “CF-GSX Repair ID: G381887002\x{a}CF-Spare Parts: 661-07293|SVCIPH”…, “pass”, …) 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, “user”, “root”, " KGB: 661-07293| | \x{a}\x{a}CF-Condition Grade: A Grade AMS\x{a}", “”, “content”, …) called at /opt/rt4/sbin/…/lib/RT/Interface/Web.pm line 697
RT::Interface::Web::ShowRequestedPage(HASH(0x5629e92060e8)) called at /opt/rt4/sbin/…/lib/RT/Interface/Web.pm line 376
RT::Interface::Web::HandleRequest(HASH(0x5629e92060e8)) called at /opt/rt4/share/html/autohandler line 53
HTML::Mason::Commands::ANON(“content”, “CF-GSX Repair ID: G381887002\x{a}CF-Spare Parts: 661-07293|SVCIPH”…, “pass”, “Wolf4u4u”, “user”, “root”, " KGB: 661-07293| | \x{a}\x{a}CF-Condition Grade: A Grade AMS\x{a}", “”) called at /usr/share/perl5/HTML/Mason/Component.pm line 135
HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x5629e6659148), “content”, “CF-GSX Repair ID: G381887002\x{a}CF-Spare Parts: 661-07293|SVCIPH”…, “pass”, “Wolf4u4u”, “user”, “root”, " KGB: 661-07293| | \x{a}\x{a}CF-Condition Grade: A Grade AMS\x{a}", …) 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, “content”, “CF-GSX Repair ID: G381887002\x{a}CF-Spare Parts: 661-07293|SVCIPH”…, “pass”, “Wolf4u4u”, “user”, …) 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(0x5629e8c97748)) 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(0x5629e8c97748)) called at /usr/share/perl5/HTML/Mason/Interp.pm line 342
HTML::Mason::Interp::exec(undef, undef, “content”, “CF-GSX Repair ID: G381887002\x{a}CF-Spare Parts: 661-07293|SVCIPH”…, “pass”, “Wolf4u4u”, “user”, “root”, …) 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(0x5629e63a99c8), HASH(0x5629e8cfc320), HASH(0x5629e822e3c0)) called at /usr/share/perl5/HTML/Mason/PSGIHandler/Streamy.pm line 52
HTML::Mason::PSGIHandler::Streamy::ANON(CODE(0x5629e985aad0)) called at /usr/local/share/perl/5.26.1/Plack/Util.pm line 339
Plack::Util::ANON(CODE(0x5629e9546ac0)) called at /usr/local/share/perl/5.26.1/Plack/Handler/FCGI.pm line 149
Plack::Handler::FCGI::run(Plack::Handler::FCGI=HASH(0x5629e650f210), CODE(0x5629e6563510)) called at /usr/local/share/perl/5.26.1/Plack/Loader.pm line 84
Plack::Loader::run(Plack::Loader=HASH(0x5629e650edf0), Plack::Handler::FCGI=HASH(0x5629e650f210)) called at /usr/local/share/perl/5.26.1/Plack/Runner.pm line 277
Plack::runner::run(RT::PlackRunner=HASH(0x5629ded6e618)) called at /opt/rt4/sbin/…/lib/RT/PlackRunner.pm line 150
eval {…} called at /opt/rt4/sbin/…/lib/RT/PlackRunner.pm line 150

Assuming this is an RT::Scrip, did you try making the scrip a batch scrip?

Yep unfortunately after switching it to a batch script it has the same issue.

Just to add that if we trigger this web script manually, it works within the normal times we are expecting so this is definitely within RT.

I would add some debugging within the scrip and script find out which step it is hanging on next

A thought, does the RT user running the script outside of RT still have rights to run the script?

I think the main question is if you are trying to update the same ticket the scrip is running on. If so, that could explain why it’s locked.

It’s also strange to call out through the rest interface for a change. Why not just use the Perl API?

The ticket record that the RT::Scrip is updating will be locked until the RT::Scrip finishes, if the RT::Scrip is waiting for the external script to finish then the timeout makes sense.

I would suggest having the external script return the values that you want added to the ticket and then having the RT::Scrip use those values to update the ticket, this avoids using the REST API.

So the user executing the script definitely has permission to-do so, The ticket is updated normally on comment which also executes a status change, and then the script is performed (as is part of the batch transaction),

We are not using the Perl API because the API we are connecting to is huge and has no Perl library, however we already have a hosted script that is connected to this api and has made REST calls to RT for years now.

Any further help or advise would be great. I will upload an image of our current script, it really is basic and the only thing we have changed is the RT version

I believe the DB transactions were tightened up between 4.2 and 4.4, so that might be why it worked before and not now.

Can you move the REST API code out of the external script and into the RT::Scrip and just get some returned JSON value from the LWP::UserAgent?