Attachments causing FCGI to become unresponsive

codemarauder · April 23, 2025, 1:16pm

I am running RT-5.0.7 on Debian 12 with Postgresql-15. Perl 5.32.0 is installed with prelbrew.

When I try to attach a file to a ticket on the GUI, FCGI process hangs and nginx returns 504 Gateway Time-out.

To debug, I have reduced $DatabaseQueryTimeout to 30 seconds.

Now, when I go to RT Home page, it opens fine. All other tickets would open fine, but when I try to open the same ticket to which I was attaching the file, it again times out.

Just before timing out, database shows the current query (to open the ticket) is blocked by the previous query (trying to attach the file):

postgres=# SELECT
    activity.pid,
    activity.usename,
    activity.query,
    blocking.pid AS blocking_id,
    blocking.query AS blocking_query
FROM pg_stat_activity AS activity
JOIN pg_stat_activity AS blocking ON blocking.pid = ANY(pg_blocking_pids(activity.pid));

  pid   | blocker_id | blocker_user |          blocker_start           |                                                  blocker_query                                                   |           trans_start            |                  trans_query                   
--------+------------+--------------+----------------------------------+------------------------------------------------------------------------------------------------------------------+----------------------------------+------------------------------------------------
 414512 |     411755 | rt_user      | 2025-04-23 14:40:10.379305+05:30 | SELECT main.* FROM Attributes main  WHERE (main.ObjectId = $1) AND (main.ObjectType = $2)  ORDER BY main.id ASC  | 2025-04-23 14:59:27.599437+05:30 | SELECT * FROM Tickets WHERE id = $1 FOR UPDATE
(1 row)

On terminating the blocker PID, ticket loads fine.

Now, when using rt-mailgate with fetchmail, when there is an attachment, ticket is not created but requestor and watchers received the e-mails with incrementing ticket numbers as fetchmail keeps re-trying to deliver the mail to the MDA.

The main problem is I am not able to attach a file (irrespective of the size - few kB to 5MB) to tickets at random. And not able to point out the reason for it.

I will be able to provide more debug information as required.

Below is the trace from the FCGI process:

2025-04-23_09:12:08.95581 [410787] [Wed Apr 23 09:12:08 2025] [warning]: DBD::Pg::st execute failed: ERROR:  canceling statement due to statement timeout           
2025-04-23_09:12:08.95589 CONTEXT:  while locking tuple (0,71) in relation "tickets" at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/DBIx/SearchBuilder/Handle.pm line 634. (/opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/DBIx/Sea
rchBuilder/Handle.pm:634)                                                                                                                                                                                                                   
2025-04-23_09:12:08.96263 [410787] [Wed Apr 23 09:12:08 2025] [warning]: RT::Handle=HASH(0x558b3fbe9028) couldn't execute the query 'SELECT * FROM Tickets WHERE id = ? FOR UPDATE' at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/DBI
x/SearchBuilder/Handle.pm line 647.                                                                                                                                                                                                         
2025-04-23_09:12:08.96272       DBIx::SearchBuilder::Handle::SimpleQuery(RT::Handle=HASH(0x558b3fbe9028), "SELECT * FROM Tickets WHERE id = ? FOR UPDATE", 12817) called at /opt/rt5/sbin/../lib/RT/Handle.pm line 3312
2025-04-23_09:12:08.96276       RT::Handle::SimpleQuery(RT::Handle=HASH(0x558b3fbe9028), "SELECT * FROM Tickets WHERE id = ? FOR UPDATE", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/DBIx/SearchBuilder/Record.pm li
ne 1237                                                                                                                                                                                                                                     
2025-04-23_09:12:08.96280       DBIx::SearchBuilder::Record::_LoadFromSQL(RT::Ticket=HASH(0x558b40693d70), "SELECT * FROM Tickets WHERE id = ? FOR UPDATE", 12817) called at /opt/rt5/sbin/../lib/RT/Record.pm line 1618    
2025-04-23_09:12:08.96286       RT::Record::LockForUpdate(RT::Ticket=HASH(0x558b40693d70)) called at /opt/rt5/sbin/../lib/RT/Ticket.pm line 1803        
2025-04-23_09:12:08.96290       RT::Ticket::Atomic(RT::Ticket=HASH(0x558b40693d70), CODE(0x558b3f4c61b8)) called at /opt/rt5/share/html/Ticket/Display.html line 208
2025-04-23_09:12:08.96294       HTML::Mason::Commands::__ANON__("id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Component.pm line 135
2025-04-23_09:12:08.96297       HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x558b3fd68870), "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1302
2025-04-23_09:12:08.96301       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1292                                                                                      
2025-04-23_09:12:08.96304       HTML::Mason::Request::comp(undef, undef, undef, "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 955                                     
2025-04-23_09:12:08.96311       HTML::Mason::Request::call_next(RT::Interface::Web::Request=HASH(0x558b3f2fdb88)) called at /opt/rt5/share/html/Ticket/autohandler line 66             
2025-04-23_09:12:08.96315       HTML::Mason::Commands::__ANON__("id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Component.pm line 135              
2025-04-23_09:12:08.96317       HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x558b3fd48328), "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1302
2025-04-23_09:12:08.96321       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1292                                                                    
2025-04-23_09:12:08.96325       HTML::Mason::Request::comp(undef, undef, undef, "id", 12817) called at /opt/rt5/sbin/../lib/RT/Interface/Web.pm line 760                                                  
2025-04-23_09:12:08.96328       RT::Interface::Web::ShowRequestedPage(HASH(0x558b40689cd0)) called at /opt/rt5/sbin/../lib/RT/Interface/Web.pm line 437                                                     
2025-04-23_09:12:08.96331       RT::Interface::Web::HandleRequest(HASH(0x558b40689cd0)) called at /opt/rt5/share/html/autohandler line 53                                                                   
2025-04-23_09:12:08.96333       HTML::Mason::Commands::__ANON__("id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Component.pm line 135         
2025-04-23_09:12:08.96336       HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x558b3fd48a30), "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1300                
2025-04-23_09:12:08.96339       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1292                                                                                                      
2025-04-23_09:12:08.96342       HTML::Mason::Request::comp(undef, undef, undef, "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 481                                                     
2025-04-23_09:12:08.96346       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 481                                               
2025-04-23_09:12:08.96349       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 433                                 
2025-04-23_09:12:08.96352       HTML::Mason::Request::exec(RT::Interface::Web::Request=HASH(0x558b3f2fdb88)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/PSGIHandler.pm line 96    
2025-04-23_09:12:08.96355       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/PSGIHandler.pm line 96                                                                              
2025-04-23_09:12:08.96360       HTML::Mason::Request::PSGI::exec(RT::Interface::Web::Request=HASH(0x558b3f2fdb88)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Interp.pm line 342          
2025-04-23_09:12:08.96363       HTML::Mason::Interp::exec(undef, undef, "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/PSGIHandler.pm line 59
2025-04-23_09:12:08.96366       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/PSGIHandler.pm line 59                                                                                                    
2025-04-23_09:12:08.96369       HTML::Mason::PSGIHandler::invoke_mason(HTML::Mason::PSGIHandler::Streamy=HASH(0x558b3f2fe368), HASH(0x558b3fd0f488), HASH(0x558b3fd0f7d0)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/
Mason/PSGIHandler/Streamy.pm line 52                                                                                                                                                                                                        
2025-04-23_09:12:08.96374       HTML::Mason::PSGIHandler::Streamy::__ANON__(CODE(0x558b36e58be8)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Util.pm line 339
2025-04-23_09:12:08.96378       Plack::Util::__ANON__(CODE(0x558b3fd8c7e8)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Util.pm line 339
2025-04-23_09:12:08.96381       Plack::Util::__ANON__(CODE(0x558b40666850)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Handler/FCGI.pm line 149
2025-04-23_09:12:08.96384       Plack::Handler::FCGI::run(Plack::Handler::FCGI=HASH(0x558b3fca0af0), CODE(0x558b3f39ddf0)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Loader.pm line 84
2025-04-23_09:12:08.96386       Plack::Loader::run(Plack::Loader=HASH(0x558b3f32e7f0), Plack::Handler::FCGI=HASH(0x558b3fca0af0)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Runner.pm line 279
2025-04-23_09:12:08.96389       Plack::Runner::run(RT::PlackRunner=HASH(0x558b351d9ce0)) called at /opt/rt5/sbin/../lib/RT/PlackRunner.pm line 150
2025-04-23_09:12:08.96395       eval {...} called at /opt/rt5/sbin/../lib/RT/PlackRunner.pm line 150
2025-04-23_09:12:08.96398       RT::PlackRunner::run(RT::PlackRunner=HASH(0x558b351d9ce0)) called at /opt/rt5/sbin/rt-server.fcgi line 165 (/opt/perl5/perls/perl-5.32.0/lib/5.32.0/Carp.pm:294)
2025-04-23_09:12:08.96653 [410787] [Wed Apr 23 09:12:08 2025] [warning]: DBD::Pg::st execute failed: ERROR:  current transaction is aborted, commands ignored until end of transaction block at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5
.32.0/DBIx/SearchBuilder/Handle.pm line 634. (/opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/DBIx/SearchBuilder/Handle.pm:634)
2025-04-23_09:12:08.97036 [410787] [Wed Apr 23 09:12:08 2025] [warning]: RT::Handle=HASH(0x558b3fbe9028) couldn't execute the query 'SELECT  * FROM Tickets WHERE id = ?' at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/DBIx/SearchBu
ilder/Handle.pm line 647.
2025-04-23_09:12:08.97041       DBIx::SearchBuilder::Handle::SimpleQuery(RT::Handle=HASH(0x558b3fbe9028), "SELECT  * FROM Tickets WHERE id = ?", 12817) called at /opt/rt5/sbin/../lib/RT/Handle.pm line 3312
2025-04-23_09:12:08.97042       RT::Handle::SimpleQuery(RT::Handle=HASH(0x558b3fbe9028), "SELECT  * FROM Tickets WHERE id = ?", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/DBIx/SearchBuilder/Record.pm line 1237
2025-04-23_09:12:08.97043       DBIx::SearchBuilder::Record::_LoadFromSQL(RT::Ticket=HASH(0x558b40693d70), "SELECT  * FROM Tickets WHERE id = ?", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/DBIx/SearchBuilder/Reco
rd.pm line 1156
2025-04-23_09:12:08.97043       DBIx::SearchBuilder::Record::LoadByCols(RT::Ticket=HASH(0x558b40693d70), "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/DBIx/SearchBuilder/Record/Cachable.pm line 117
2025-04-23_09:12:08.97045       DBIx::SearchBuilder::Record::Cachable::LoadByCols(RT::Ticket=HASH(0x558b40693d70), "id", 12817) called at /opt/rt5/sbin/../lib/RT/Record.pm line 405
2025-04-23_09:12:08.97046       RT::Record::LoadByCols(RT::Ticket=HASH(0x558b40693d70), "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/DBIx/SearchBuilder/Record.pm line 1171
2025-04-23_09:12:08.97046       DBIx::SearchBuilder::Record::LoadById(RT::Ticket=HASH(0x558b40693d70), 12817) called at /opt/rt5/sbin/../lib/RT/Ticket.pm line 192
2025-04-23_09:12:08.97047       RT::Ticket::Load(RT::Ticket=HASH(0x558b40693d70), 12817) called at /opt/rt5/sbin/../lib/RT/Ticket.pm line 1804
2025-04-23_09:12:08.97048       RT::Ticket::Atomic(RT::Ticket=HASH(0x558b40693d70), CODE(0x558b3f4c61b8)) called at /opt/rt5/share/html/Ticket/Display.html line 208
2025-04-23_09:12:08.97048       HTML::Mason::Commands::__ANON__("id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Component.pm line 135
2025-04-23_09:12:08.97049       HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x558b3fd68870), "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1302
2025-04-23_09:12:08.97050       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1292
2025-04-23_09:12:08.97051       HTML::Mason::Request::comp(undef, undef, undef, "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 955
2025-04-23_09:12:08.97052       HTML::Mason::Request::call_next(RT::Interface::Web::Request=HASH(0x558b3f2fdb88)) called at /opt/rt5/share/html/Ticket/autohandler line 66
2025-04-23_09:12:08.97052       HTML::Mason::Commands::__ANON__("id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Component.pm line 135
2025-04-23_09:12:08.97053       HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x558b3fd48328), "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1302
2025-04-23_09:12:08.97053       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1292
2025-04-23_09:12:08.97061       HTML::Mason::Request::comp(undef, undef, undef, "id", 12817) called at /opt/rt5/sbin/../lib/RT/Interface/Web.pm line 760
2025-04-23_09:12:08.97062       RT::Interface::Web::ShowRequestedPage(HASH(0x558b40689cd0)) called at /opt/rt5/sbin/../lib/RT/Interface/Web.pm line 437
2025-04-23_09:12:08.97066       RT::Interface::Web::HandleRequest(HASH(0x558b40689cd0)) called at /opt/rt5/share/html/autohandler line 53
2025-04-23_09:12:08.97068       HTML::Mason::Commands::__ANON__("id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Component.pm line 135
2025-04-23_09:12:08.97069       HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x558b3fd48a30), "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1300
2025-04-23_09:12:08.97070       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1292
2025-04-23_09:12:08.97071       HTML::Mason::Request::comp(undef, undef, undef, "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 481
2025-04-23_09:12:08.97073       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 481
2025-04-23_09:12:08.97074       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 433
2025-04-23_09:12:08.97075       HTML::Mason::Request::exec(RT::Interface::Web::Request=HASH(0x558b3f2fdb88)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/PSGIHandler.pm line 96
2025-04-23_09:12:08.97079       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/PSGIHandler.pm line 96
2025-04-23_09:12:08.97080       HTML::Mason::Request::PSGI::exec(RT::Interface::Web::Request=HASH(0x558b3f2fdb88)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Interp.pm line 342
2025-04-23_09:12:08.97080       HTML::Mason::Interp::exec(undef, undef, "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/PSGIHandler.pm line 59
2025-04-23_09:12:08.97081       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/PSGIHandler.pm line 59
2025-04-23_09:12:08.97082       HTML::Mason::PSGIHandler::invoke_mason(HTML::Mason::PSGIHandler::Streamy=HASH(0x558b3f2fe368), HASH(0x558b3fd0f488), HASH(0x558b3fd0f7d0)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/
Mason/PSGIHandler/Streamy.pm line 52
2025-04-23_09:12:08.97084       HTML::Mason::PSGIHandler::Streamy::__ANON__(CODE(0x558b36e58be8)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Util.pm line 339
2025-04-23_09:12:08.97086       Plack::Util::__ANON__(CODE(0x558b3fd8c7e8)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Util.pm line 339
2025-04-23_09:12:08.97087       Plack::Util::__ANON__(CODE(0x558b40666850)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Handler/FCGI.pm line 149
2025-04-23_09:12:08.97088       Plack::Handler::FCGI::run(Plack::Handler::FCGI=HASH(0x558b3fca0af0), CODE(0x558b3f39ddf0)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Loader.pm line 84
2025-04-23_09:12:08.97088       Plack::Loader::run(Plack::Loader=HASH(0x558b3f32e7f0), Plack::Handler::FCGI=HASH(0x558b3fca0af0)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Runner.pm line 279
2025-04-23_09:12:08.97089       Plack::Runner::run(RT::PlackRunner=HASH(0x558b351d9ce0)) called at /opt/rt5/sbin/../lib/RT/PlackRunner.pm line 150
2025-04-23_09:12:08.97090       eval {...} called at /opt/rt5/sbin/../lib/RT/PlackRunner.pm line 150
2025-04-23_09:12:08.97090       RT::PlackRunner::run(RT::PlackRunner=HASH(0x558b351d9ce0)) called at /opt/rt5/sbin/rt-server.fcgi line 165 (/opt/perl5/perls/perl-5.32.0/lib/5.32.0/Carp.pm:294)
2025-04-23_09:12:08.97721 [410787] [Wed Apr 23 09:12:08 2025] [warning]: DBD::Pg::st execute failed: ERROR:  current transaction is aborted, commands ignored until end of transaction block at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5
.32.0/DBIx/SearchBuilder/Handle.pm line 634. (/opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/DBIx/SearchBuilder/Handle.pm:634)
2025-04-23_09:12:08.98063 [410787] [Wed Apr 23 09:12:08 2025] [warning]: RT::Handle=HASH(0x558b3fbe9028) couldn't execute the query 'SELECT main.* FROM CustomFields main JOIN ObjectCustomFields ObjectCustomFields_1  ON ( ObjectCustomFie
lds_1.CustomField = main.id )  WHERE (ObjectCustomFields_1.ObjectId = ? OR ObjectCustomFields_1.ObjectId = ?) AND (main.Disabled = ?) AND (main.LookupType = ?)   GROUP BY main.id   ORDER BY MIN(ObjectCustomFields_1.SortOrder) ASC ' at /
opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/DBIx/SearchBuilder/Handle.pm line 647.
2025-04-23_09:12:08.98071       DBIx::SearchBuilder::Handle::SimpleQuery(RT::Handle=HASH(0x558b3fbe9028), "SELECT main.* FROM CustomFields main JOIN ObjectCustomFields "..., 3, 0, 0, "RT::Queue-RT::Ticket") called at /opt/rt5/sbin/../li
b/RT/Handle.pm line 3312
2025-04-23_09:12:08.98075       RT::Handle::SimpleQuery(RT::Handle=HASH(0x558b3fbe9028), "SELECT main.* FROM CustomFields main JOIN ObjectCustomFields "..., 3, 0, 0, "RT::Queue-RT::Ticket") called at /opt/perl5/perls/perl-5.32.0/lib/sit
e_perl/5.32.0/DBIx/SearchBuilder.pm line 249
2025-04-23_09:12:08.98078       DBIx::SearchBuilder::_DoSearch(RT::CustomFields=HASH(0x558b40af2088)) called at /opt/rt5/sbin/../lib/RT/SearchBuilder.pm line 1098
2025-04-23_09:12:08.98082       RT::SearchBuilder::_DoSearch(RT::CustomFields=HASH(0x558b40af2088)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/DBIx/SearchBuilder.pm line 630
2025-04-23_09:12:08.98085       DBIx::SearchBuilder::Next(RT::CustomFields=HASH(0x558b40af2088)) called at /opt/rt5/share/html/Elements/ValidateCustomFields line 54
2025-04-23_09:12:08.98088       HTML::Mason::Commands::__ANON__("Object", RT::Ticket=HASH(0x558b40693d70), "CustomFields", RT::CustomFields=HASH(0x558b40af2088), "ARGSRef", HASH(0x558b3f2012c0)) called at /opt/perl5/perls/perl-5.32.0/li
b/site_perl/5.32.0/HTML/Mason/Component.pm line 135
2025-04-23_09:12:08.98091       HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x558b3fe70240), "Object", RT::Ticket=HASH(0x558b40693d70), "CustomFields", RT::CustomFields=HASH(0x558b40af2088), "ARGSRef", HASH(0x558b
3f2012c0)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1298
2025-04-23_09:12:08.98094       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1292
2025-04-23_09:12:08.98098       HTML::Mason::Request::comp(undef, undef, "Object", RT::Ticket=HASH(0x558b40693d70), "CustomFields", RT::CustomFields=HASH(0x558b40af2088), "ARGSRef", HASH(0x558b3f2012c0)) called at /opt/rt5/share/html/Ti
cket/Display.html line 164
2025-04-23_09:12:08.98101       HTML::Mason::Commands::__ANON__() called at /opt/rt5/sbin/../lib/RT/Ticket.pm line 1838
2025-04-23_09:12:08.98104       eval {...} called at /opt/rt5/sbin/../lib/RT/Ticket.pm line 1832
2025-04-23_09:12:08.98110       RT::Ticket::Atomic(RT::Ticket=HASH(0x558b40693d70), CODE(0x558b3f4c61b8)) called at /opt/rt5/share/html/Ticket/Display.html line 208
2025-04-23_09:12:08.98114       HTML::Mason::Commands::__ANON__("id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Component.pm line 135
2025-04-23_09:12:08.98117       HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x558b3fd68870), "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1302
2025-04-23_09:12:08.98120       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1292
2025-04-23_09:12:08.98123       HTML::Mason::Request::comp(undef, undef, undef, "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 955
2025-04-23_09:12:08.98127       HTML::Mason::Request::call_next(RT::Interface::Web::Request=HASH(0x558b3f2fdb88)) called at /opt/rt5/share/html/Ticket/autohandler line 66
2025-04-23_09:12:08.98130       HTML::Mason::Commands::__ANON__("id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Component.pm line 135
2025-04-23_09:12:08.98134       HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x558b3fd48328), "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1302
2025-04-23_09:12:08.98138       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1292
2025-04-23_09:12:08.98140       HTML::Mason::Request::comp(undef, undef, undef, "id", 12817) called at /opt/rt5/sbin/../lib/RT/Interface/Web.pm line 760
2025-04-23_09:12:08.98143       RT::Interface::Web::ShowRequestedPage(HASH(0x558b40689cd0)) called at /opt/rt5/sbin/../lib/RT/Interface/Web.pm line 437
2025-04-23_09:12:08.98146       RT::Interface::Web::HandleRequest(HASH(0x558b40689cd0)) called at /opt/rt5/share/html/autohandler line 53
2025-04-23_09:12:08.98150       HTML::Mason::Commands::__ANON__("id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Component.pm line 135
2025-04-23_09:12:08.98153       HTML::Mason::Component::run(HTML::Mason::Component::FileBased=HASH(0x558b3fd48a30), "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1300
2025-04-23_09:12:08.98159       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 1292
2025-04-23_09:12:08.98163       HTML::Mason::Request::comp(undef, undef, undef, "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 481
2025-04-23_09:12:08.98166       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 481
2025-04-23_09:12:08.98169       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Request.pm line 433
2025-04-23_09:12:08.98172       HTML::Mason::Request::exec(RT::Interface::Web::Request=HASH(0x558b3f2fdb88)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/PSGIHandler.pm line 96
2025-04-23_09:12:08.98175       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/PSGIHandler.pm line 96
2025-04-23_09:12:08.98178       HTML::Mason::Request::PSGI::exec(RT::Interface::Web::Request=HASH(0x558b3f2fdb88)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/Interp.pm line 342
2025-04-23_09:12:08.98182       HTML::Mason::Interp::exec(undef, undef, "id", 12817) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/PSGIHandler.pm line 59
2025-04-23_09:12:08.98185       eval {...} called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/Mason/PSGIHandler.pm line 59
2025-04-23_09:12:08.98188       HTML::Mason::PSGIHandler::invoke_mason(HTML::Mason::PSGIHandler::Streamy=HASH(0x558b3f2fe368), HASH(0x558b3fd0f488), HASH(0x558b3fd0f7d0)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/HTML/
Mason/PSGIHandler/Streamy.pm line 52
2025-04-23_09:12:08.98191       HTML::Mason::PSGIHandler::Streamy::__ANON__(CODE(0x558b36e58be8)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Util.pm line 339
2025-04-23_09:12:08.98194       Plack::Util::__ANON__(CODE(0x558b3fd8c7e8)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Util.pm line 339
2025-04-23_09:12:08.98199       Plack::Util::__ANON__(CODE(0x558b40666850)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Handler/FCGI.pm line 149
2025-04-23_09:12:08.98201       Plack::Handler::FCGI::run(Plack::Handler::FCGI=HASH(0x558b3fca0af0), CODE(0x558b3f39ddf0)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Loader.pm line 84
2025-04-23_09:12:08.98204       Plack::Loader::run(Plack::Loader=HASH(0x558b3f32e7f0), Plack::Handler::FCGI=HASH(0x558b3fca0af0)) called at /opt/perl5/perls/perl-5.32.0/lib/site_perl/5.32.0/Plack/Runner.pm line 279
2025-04-23_09:12:08.98207       Plack::Runner::run(RT::PlackRunner=HASH(0x558b351d9ce0)) called at /opt/rt5/sbin/../lib/RT/PlackRunner.pm line 150
2025-04-23_09:12:08.98210       eval {...} called at /opt/rt5/sbin/../lib/RT/PlackRunner.pm line 150
2025-04-23_09:12:08.98213       RT::PlackRunner::run(RT::PlackRunner=HASH(0x558b351d9ce0)) called at /opt/rt5/sbin/rt-server.fcgi line 165 (/opt/perl5/perls/perl-5.32.0/lib/5.32.0/Carp.pm:294)
2025-04-23_09:12:16.85729 [410786] [Wed Apr 23 09:12:16 2025] [debug]: Rendering attachment #207 of 'text/plain' type (/opt/rt5/share/html/Elements/ShowTransactionAttachments:238)

Andrew_Ruthven · April 24, 2025, 11:07am

Hey,

Have you checked to make sure you have all the required indexes? You should these on the attributes table:

Indexes:
    "attributes_pkey" PRIMARY KEY, btree (id)
    "attributes1" btree (name)
    "attributes2" btree (objecttype, objectid)

codemarauder · April 24, 2025, 11:28am

Yes, the indexes are present.

rt5=# \d attributes;
                                          Table "public.attributes"
    Column     |            Type             | Collation | Nullable |                Default                 
---------------+-----------------------------+-----------+----------+----------------------------------------
 id            | integer                     |           | not null | nextval('attributes_id_seq'::regclass)
 name          | character varying(255)      |           | not null | 
 description   | character varying(255)      |           |          | 
 content       | text                        |           |          | 
 contenttype   | character varying(16)       |           |          | 
 objecttype    | character varying(64)       |           |          | 
 objectid      | integer                     |           |          | 
 creator       | integer                     |           | not null | 0
 created       | timestamp without time zone |           |          | 
 lastupdatedby | integer                     |           | not null | 0
 lastupdated   | timestamp without time zone |           |          | 
Indexes:
    "attributes_pkey" PRIMARY KEY, btree (id)
    "attributes1" btree (name)
    "attributes2" btree (objecttype, objectid)

Andrew_Ruthven · April 24, 2025, 1:01pm

Do you get a fast response if you run the SQL manually?

codemarauder · April 24, 2025, 1:40pm

Nope. It remains stuck.

I have selected only 4 columns, but result is the same with SELECT *

rt5=# SELECT id, effectiveid, queue, subject FROM Tickets WHERE id = 12817 FOR UPDATE;
^CCancel request sent
ERROR:  canceling statement due to user request
CONTEXT:  while locking tuple (0,71) in relation "tickets"
Time: 21318.922 ms (00:21.319)

$ psql
psql (15.12 (Debian 15.12-0+deb12u2))
Type "help" for help.

postgres=# SELECT
    activity.pid,
    activity.usename,
    activity.query,
    blocking.pid AS blocking_id,
    blocking.query AS blocking_query
FROM pg_stat_activity AS activity
JOIN pg_stat_activity AS blocking ON blocking.pid = ANY(pg_blocking_pids(activity.pid));
  pid   | usename  |                       query                        | blocking_id |                                                  blocking_query                                                  
--------+----------+----------------------------------------------------+-------------+------------------------------------------------------------------------------------------------------------------
 985945 | postgres | SELECT * FROM Tickets WHERE id = 12817 FOR UPDATE; |      414512 | SELECT main.* FROM Attributes main  WHERE (main.ObjectId = $1) AND (main.ObjectType = $2)  ORDER BY main.id ASC 
(1 row)

Below is after cancelling the query:

postgres=# SELECT
    activity.pid,
    activity.usename,
    activity.query,
    blocking.pid AS blocking_id,
    blocking.query AS blocking_query
FROM pg_stat_activity AS activity
JOIN pg_stat_activity AS blocking ON blocking.pid = ANY(pg_blocking_pids(activity.pid));
 pid | usename | query | blocking_id | blocking_query 
-----+---------+-------+-------------+----------------
(0 rows)

Searching for any other ticket works fine.

rt5=# SELECT id, effectiveid, queue, subject FROM Tickets WHERE id = 12819 FOR UPDATE;
  id   | effectiveid | queue |          subject           
-------+-------------+-------+----------------------------
 12819 |       12819 |     3 |   REDACTED
(1 row)

Time: 3.838 ms

Query starts working when I do TRUNCATE TABLE sessions;.

rt5=# truncate table sessions;
TRUNCATE TABLE
Time: 11.302 ms
rt5=# SELECT id, effectiveid, queue, subject FROM Tickets WHERE id = 12817 FOR UPDATE;
  id   | effectiveid | queue |          subject          
-------+-------------+-------+---------------------------
 12817 |       12817 |     3 | Why it's happening again?
(1 row)

Time: 2.964 ms

codemarauder · April 24, 2025, 3:14pm

Switched to Apache::Session::File.

Attached a few very small icons (around 7-8 images - total 1.4MB). Submitted and got 504 gateway timeout error.

Now, I am unable to open RT home page, not even a new session in a private window.

Below is the directory listing for session_data:

root@mail:/opt/rt5/var/session_data# ls -ltrh
total 1.4M
-rw-r--r-- 1 www-data www-data    0 Apr 24 19:57 Apache-Session-c62488b4bb8dea3225dba109f04a9765.lock
-rw-r--r-- 1 www-data www-data    0 Apr 24 19:57 Apache-Session-13482468dfa40b4b81a07ef83fe840c5.lock
-rw-r--r-- 1 www-data www-data    0 Apr 24 19:57 Apache-Session-469048ce54578c2dae32bffed1085382.lock
-rw-r--r-- 1 www-data www-data 1.4M Apr 24 19:58 b9205bd5172c05cbc99f45c25163f4af
-rw-r--r-- 1 www-data www-data    0 Apr 24 20:02 Apache-Session-b9205bd5172c05cbc99f45c25163f4af.lock

No query block seen in the DB:

postgres=# SELECT
    activity.pid,
    activity.usename,
    activity.query,
    blocking.pid AS blocking_id,
    blocking.query AS blocking_query
FROM pg_stat_activity AS activity
JOIN pg_stat_activity AS blocking ON blocking.pid = ANY(pg_blocking_pids(activity.pid));
 pid | usename | query | blocking_id | blocking_query 
-----+---------+-------+-------------+----------------
(0 rows)

Time: 2.701 ms

No e-mails sent.

Debug logs for FCGI:

2025-04-24_14:27:59.72841 [1007822] [Thu Apr 24 14:27:59 2025] [debug]: Rendering attachment #207 of 'text/plain' type (/opt/rt5/share/html/Elements/ShowTransactionAttachments:238)
2025-04-24_14:28:06.78978 [1007824] [Thu Apr 24 14:28:06 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/html - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:06.80191 [1007824] [Thu Apr 24 14:28:06 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/html - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:06.85149 [1007824] [Thu Apr 24 14:28:06 2025] [debug]: About to prepare scrips for transaction #697 (/opt/rt5/sbin/../lib/RT/Transaction.pm:189)
2025-04-24_14:28:06.86317 [1007824] [Thu Apr 24 14:28:06 2025] [debug]: Found 9 scrips for TransactionCreate stage with applicable type(s) Correspond for txn #697 on ticket #12817 (/opt/rt5/sbin/../lib/RT/Scrips.pm:482)
2025-04-24_14:28:06.99590 [1007824] [Thu Apr 24 14:28:06 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/plain - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:06.99658 [1007824] [Thu Apr 24 14:28:06 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/html - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:06.99783 [1007824] [Thu Apr 24 14:28:06 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:06.99868 [1007824] [Thu Apr 24 14:28:06 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:07.07969 [1007824] [Thu Apr 24 14:28:07 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/plain - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:07.08044 [1007824] [Thu Apr 24 14:28:07 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/html - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:07.08177 [1007824] [Thu Apr 24 14:28:07 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:07.08270 [1007824] [Thu Apr 24 14:28:07 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:07.19084 [1007824] [Thu Apr 24 14:28:07 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/plain - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:07.19144 [1007824] [Thu Apr 24 14:28:07 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/html - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:07.19288 [1007824] [Thu Apr 24 14:28:07 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:07.19667 [1007824] [Thu Apr 24 14:28:07 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:07.23547 [1007824] [Thu Apr 24 14:28:07 2025] [debug]: Skipping Scrip #11 because it isn't applicable (/opt/rt5/sbin/../lib/RT/Scrips.pm:337)
2025-04-24_14:28:07.24802 [1007824] [Thu Apr 24 14:28:07 2025] [debug]: Skipping Scrip #17 because it isn't applicable (/opt/rt5/sbin/../lib/RT/Scrips.pm:337)
2025-04-24_14:28:07.25525 [1007824] [Thu Apr 24 14:28:07 2025] [debug]: Skipping Scrip #18 because it isn't applicable (/opt/rt5/sbin/../lib/RT/Scrips.pm:337)
2025-04-24_14:28:07.30004 [1007824] [Thu Apr 24 14:28:07 2025] [debug]: Found 0 scrips for TransactionBatch stage with applicable type(s) Correspond for txn #697 on ticket #12817 (/opt/rt5/sbin/../lib/RT/Scrips.pm:482)
2025-04-24_14:28:29.85646 [1007825] [Thu Apr 24 14:28:29 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:29.85689 [1007825] [Thu Apr 24 14:28:29 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.02098 [1007822] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.02144 [1007822] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.36275 [1007823] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.36322 [1007823] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.47823 [1007824] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.47850 [1007824] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.55641 [1007825] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.55683 [1007825] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.65479 [1007822] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.65505 [1007822] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.73456 [1007823] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.73493 [1007823] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.80670 [1007824] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.80703 [1007824] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.87309 [1007825] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.87367 [1007825] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.94857 [1007822] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:30.94878 [1007822] [Thu Apr 24 14:28:30 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:31.04147 [1007823] [Thu Apr 24 14:28:31 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:31.04202 [1007823] [Thu Apr 24 14:28:31 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.00624 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/html - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:47.01393 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/html - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:47.01490 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.01536 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.01784 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.01833 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.02063 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.02110 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.02336 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.02380 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.02613 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.02660 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.02880 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.02926 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.03143 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.03184 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.03407 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.03454 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.03664 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.03708 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.03913 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.03955 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.04161 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.04204 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.04423 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.04483 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.05823 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Max size is 5242880 (/opt/rt5/sbin/../lib/RT/Record.pm:752)
2025-04-24_14:28:47.06253 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Max size is 5242880 (/opt/rt5/sbin/../lib/RT/Record.pm:752)
2025-04-24_14:28:47.06599 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Max size is 5242880 (/opt/rt5/sbin/../lib/RT/Record.pm:752)
2025-04-24_14:28:47.07301 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Max size is 5242880 (/opt/rt5/sbin/../lib/RT/Record.pm:752)
2025-04-24_14:28:47.07864 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Max size is 5242880 (/opt/rt5/sbin/../lib/RT/Record.pm:752)
2025-04-24_14:28:47.08257 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Max size is 5242880 (/opt/rt5/sbin/../lib/RT/Record.pm:752)
2025-04-24_14:28:47.09021 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Max size is 5242880 (/opt/rt5/sbin/../lib/RT/Record.pm:752)
2025-04-24_14:28:47.09802 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Max size is 5242880 (/opt/rt5/sbin/../lib/RT/Record.pm:752)
2025-04-24_14:28:47.11126 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Max size is 5242880 (/opt/rt5/sbin/../lib/RT/Record.pm:752)
2025-04-24_14:28:47.11965 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Max size is 5242880 (/opt/rt5/sbin/../lib/RT/Record.pm:752)
2025-04-24_14:28:47.13702 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Max size is 5242880 (/opt/rt5/sbin/../lib/RT/Record.pm:752)
2025-04-24_14:28:47.15140 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: About to prepare scrips for transaction #698 (/opt/rt5/sbin/../lib/RT/Transaction.pm:189)
2025-04-24_14:28:47.15653 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Found 9 scrips for TransactionCreate stage with applicable type(s) Correspond for txn #698 on ticket #12817 (/opt/rt5/sbin/../lib/RT/Scrips.pm:482)
2025-04-24_14:28:47.25808 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/plain - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:47.25856 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/html - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:47.25949 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.26010 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.36625 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/plain - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:47.36672 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/html - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:47.36757 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.36812 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.48605 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/plain - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:47.48644 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Converting 'utf-8' to 'utf-8' for text/html - Subjectless message (/opt/rt5/sbin/../lib/RT/I18N.pm:294)
2025-04-24_14:28:47.48724 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.48778 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Encode::Guess guessed encoding: ascii (/opt/rt5/sbin/../lib/RT/I18N.pm:583)
2025-04-24_14:28:47.53620 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Skipping Scrip #11 because it isn't applicable (/opt/rt5/sbin/../lib/RT/Scrips.pm:337)
2025-04-24_14:28:47.54084 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Skipping Scrip #17 because it isn't applicable (/opt/rt5/sbin/../lib/RT/Scrips.pm:337)
2025-04-24_14:28:47.54752 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Skipping Scrip #18 because it isn't applicable (/opt/rt5/sbin/../lib/RT/Scrips.pm:337)
2025-04-24_14:28:47.55571 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: About to commit scrips for transaction #698 (/opt/rt5/sbin/../lib/RT/Transaction.pm:212)
2025-04-24_14:28:47.55576 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Committing scrip #3 on txn #698 of ticket #12817 (/opt/rt5/sbin/../lib/RT/Scrips.pm:293)
2025-04-24_14:28:47.55594 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Calling SetRecipientDigests for transaction RT::Transaction=HASH(0x557588042810), id 698 (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:693)
2025-04-24_14:28:47.55600 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Working on mailfield To; recipients are  (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:709)
2025-04-24_14:28:47.55630 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: References: <RT-Ticket-12817@REDACTED>
2025-04-24_14:28:47.55631  <27ac9aec-ac38-42d1-87f7-3bb16eeb49d5.ref@REDACTED>
2025-04-24_14:28:47.55631  <27ac9aec-ac38-42d1-87f7-3bb16eeb49d5@REDACTED>
2025-04-24_14:28:47.55631 Subject: [REDACTED #12817] Why it's happening again?
2025-04-24_14:28:47.55631 X-Managed-BY: RT 5.0.7 (http://www.bestpractical.com/rt/)
2025-04-24_14:28:47.55632 Message-ID: <rt-5.0.7-1007824-1745504927-1648.12817-3-0@REDACTED>
2025-04-24_14:28:47.55632 X-RT-Loop-Prevention: support.REDACTED
2025-04-24_14:28:47.55632 X-RT-Originator: REDACTED@REDACTED
2025-04-24_14:28:47.55632 From: "REDACTED via REDACTED" <REDACTED@REDACTED>
2025-04-24_14:28:47.55632 X-RT-Ticket: support.REDACTED #12817
2025-04-24_14:28:47.55632 Reply-To: REDACTED@REDACTED
2025-04-24_14:28:47.55633 BCC: REDACTED@REDACTED, REDACTED@REDACTED, REDACTED@REDACTED, REDACTED@REDACTED
2025-04-24_14:28:47.55633 In-Reply-To: <27ac9aec-ac38-42d1-87f7-3bb16eeb49d5@REDACTED>
2025-04-24_14:28:47.55633 Content-Type: multipart/mixed; boundary="----------=_1745504927-1007824-9" (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:716)
2025-04-24_14:28:47.55641 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Removing deferred recipients from To: line (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:739)
2025-04-24_14:28:47.55648 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Setting deferred recipients for attribute creation (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:748)
2025-04-24_14:28:47.55652 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Working on mailfield Cc; recipients are  (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:709)
2025-04-24_14:28:47.55673 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: References: <RT-Ticket-12817@REDACTED>
2025-04-24_14:28:47.55673  <27ac9aec-ac38-42d1-87f7-3bb16eeb49d5.ref@REDACTED>
2025-04-24_14:28:47.55673  <27ac9aec-ac38-42d1-87f7-3bb16eeb49d5@REDACTED>
2025-04-24_14:28:47.55673 Subject: [REDACTED #12817] Why it's happening again?
2025-04-24_14:28:47.55674 X-Managed-BY: RT 5.0.7 (http://www.bestpractical.com/rt/)
2025-04-24_14:28:47.55674 Message-ID: <rt-5.0.7-1007824-1745504927-1648.12817-3-0@REDACTED>
2025-04-24_14:28:47.55674 X-RT-Loop-Prevention: support.REDACTED
2025-04-24_14:28:47.55674 X-RT-Originator: REDACTED@REDACTED
2025-04-24_14:28:47.55674 From: "REDACTED via REDACTED" <REDACTED@REDACTED>
2025-04-24_14:28:47.55674 X-RT-Ticket: support.REDACTED #12817
2025-04-24_14:28:47.55675 Reply-To: REDACTED@REDACTED
2025-04-24_14:28:47.55675 BCC: REDACTED@REDACTED, REDACTED@REDACTED, REDACTED@REDACTED, REDACTED@REDACTED
2025-04-24_14:28:47.55675 In-Reply-To: <27ac9aec-ac38-42d1-87f7-3bb16eeb49d5@REDACTED>
2025-04-24_14:28:47.55675 Content-Type: multipart/mixed; boundary="----------=_1745504927-1007824-9" (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:716)
2025-04-24_14:28:47.55677 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Removing deferred recipients from Cc: line (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:739)
2025-04-24_14:28:47.55681 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Setting deferred recipients for attribute creation (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:748)
2025-04-24_14:28:47.55685 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Working on mailfield Bcc; recipients are REDACTED@REDACTED,REDACTED@REDACTED,REDACTED@REDACTED,REDACTED@REDACTED (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:709)
2025-04-24_14:28:47.55707 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: References: <RT-Ticket-12817@REDACTED>
2025-04-24_14:28:47.55707  <27ac9aec-ac38-42d1-87f7-3bb16eeb49d5.ref@REDACTED>
2025-04-24_14:28:47.55708  <27ac9aec-ac38-42d1-87f7-3bb16eeb49d5@REDACTED>
2025-04-24_14:28:47.55708 Subject: [REDACTED #12817] Why it's happening again?
2025-04-24_14:28:47.55708 X-Managed-BY: RT 5.0.7 (http://www.bestpractical.com/rt/)
2025-04-24_14:28:47.55708 Message-ID: <rt-5.0.7-1007824-1745504927-1648.12817-3-0@REDACTED>
2025-04-24_14:28:47.55709 X-RT-Loop-Prevention: support.REDACTED
2025-04-24_14:28:47.55709 X-RT-Originator: REDACTED@REDACTED
2025-04-24_14:28:47.55709 From: "REDACTED via REDACTED" <REDACTED@REDACTED>
2025-04-24_14:28:47.55709 X-RT-Ticket: REDACTED #12817
2025-04-24_14:28:47.55710 Reply-To: REDACTED@REDACTED
2025-04-24_14:28:47.55710 BCC: REDACTED
2025-04-24_14:28:47.55710 In-Reply-To: <27ac9aec-ac38-42d1-87f7-3bb16eeb49d5@REDACTED>
2025-04-24_14:28:47.55710 Content-Type: multipart/mixed; boundary="----------=_1745504927-1007824-9" (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:716)
2025-04-24_14:28:47.55920 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Got user mail preference 'Individual messages' for user REDACTED@REDACTED (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:730)
2025-04-24_14:28:47.56115 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Got user mail preference 'Individual messages' for user REDACTED@REDACTED (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:730)
2025-04-24_14:28:47.56315 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Got user mail preference 'Individual messages' for user REDACTED@REDACTED (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:730)
2025-04-24_14:28:47.56502 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Got user mail preference 'Individual messages' for user REDACTED@REDACTED (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:730)
2025-04-24_14:28:47.56528 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Removing deferred recipients from Bcc: line (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:739)
2025-04-24_14:28:47.56543 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: Setting deferred recipients for attribute creation (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:748)
2025-04-24_14:28:47.56548 [1007824] [Thu Apr 24 14:28:47 2025] [debug]: No recipients found for deferred delivery on transaction #698 (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:761)
2025-04-24_14:28:47.56572 [1007824] [Thu Apr 24 14:28:47 2025] [info]: <rt-5.0.7-1007824-1745504927-1648.12817-3-0@REDACTED> #12817/698 - Scrip 3 On Correspond Notify Owner and AdminCcs (/opt/rt5/sbin/../lib/RT/Action/SendEmail.pm:293)

Tried to stop the FCGI server:

2025-04-24_14:41:58.29013 FastCGI: manager (pid 1007663): received signal TERM
2025-04-24_14:41:58.29058 FastCGI: manager (pid 1007663): sending TERM to PIDs, 1007822 1007825 1007824 1007823
2025-04-24_14:42:58.29372 FastCGI: manager (pid 1007663): wait timeout
2025-04-24_14:42:58.33319 msmtp: cannot write to TLS connection: Error in the push function.
2025-04-24_14:42:58.33332 msmtp: could not send mail (account REDACTED from /etc/msmtprc)

But processes took a long time (around a minute or more to exit):

root@mail:~# ps ax | grep perl
1007663 ?        S      0:02 perl-fcgi-pm
1007822 ?        S      0:00 perl-fcgi
1007823 ?        S      0:00 perl-fcgi
1007824 ?        S      0:00 perl-fcgi
1007825 ?        S      0:00 perl-fcgi

And then I am able to open the homepage again.

Below is the state of session_data directory after restarting FCGI server:

root@mail:/opt/rt5/var/session_data# ls -ltrh
total 1.4M
-rw-r--r-- 1 www-data www-data    0 Apr 24 19:57 Apache-Session-c62488b4bb8dea3225dba109f04a9765.lock
-rw-r--r-- 1 www-data www-data    0 Apr 24 19:57 Apache-Session-13482468dfa40b4b81a07ef83fe840c5.lock
-rw-r--r-- 1 www-data www-data    0 Apr 24 19:57 Apache-Session-469048ce54578c2dae32bffed1085382.lock
-rw-r--r-- 1 www-data www-data    0 Apr 24 20:15 Apache-Session-33b91f0abe2c9240a2cfc8e2dcb1cfc3.lock
-rw-r--r-- 1 www-data www-data    0 Apr 24 20:15 Apache-Session-3bb34be6c0a268e91ab2c1be370c64b1.lock
-rw-r--r-- 1 www-data www-data    0 Apr 24 20:15 Apache-Session-ae47512ae0ab0fa821522963b887c998.lock
-rw-r--r-- 1 www-data www-data  214 Apr 24 20:15 ae47512ae0ab0fa821522963b887c998
-rw-r--r-- 1 www-data www-data    0 Apr 24 20:16 Apache-Session-b9205bd5172c05cbc99f45c25163f4af.lock
-rw-r--r-- 1 www-data www-data 1.4M Apr 24 20:16 b9205bd5172c05cbc99f45c25163f4af

My existing session b9205bd5172c05cbc99f45c25163f4af has a lock file, so do another session ae47512ae0ab0fa821522963b887c998 where I opened the home page in incognito mode. I do not know why there are other session locks with no session file.

Although RT_Config.pm had Set($WebSessionClass, "Apache::Session::File");, it was saving sessions in Postgresql.

After adding Set($WebSessionClass, "Apache::Session::File"); to RT_SiteConfig.pm, sessions were stored on the filesystem.

With sessions being stored in Postgresql, I was able to browse the RT GUI and access other tickets except the ticket in question, but when sessions on the filesystem, whole RT became unresponsive and FCGI needed to be restarted.

Next step, I have run rt-clean-sessions and tried to attach same files - 504 Gateway Timeout. Session file size increased to double - 2.8MB from 1.4MB. This time I issued killall -9 perl-fcgi when processes were not exiting after TERM signal being sent .

2025-04-24_14:57:20.62043 FastCGI: manager (pid 1014640): received signal TERM                                                                                                                                                              
2025-04-24_14:57:20.62076 FastCGI: manager (pid 1014640): sending TERM to PIDs, 1014649 1014651 1014652 1014650                                                                                                                             
2025-04-24_14:57:20.95344 FastCGI: manager (pid 1014640): server (pid 1014650) exited with status 0                                                                                                                                         
2025-04-24_14:57:20.95816 FastCGI: manager (pid 1014640): server (pid 1014649) exited with status 0                                                                                                                                         
2025-04-24_14:58:06.12638 FastCGI: manager (pid 1014640): server (pid 1014652) exited with status 9                                                                                                                                         
2025-04-24_14:58:06.12976 FastCGI: manager (pid 1014640): server (pid 1014651) exited with status 9                                                                                                                                         
2025-04-24_14:58:06.13001 FastCGI: manager (pid 1014640): dying: safe exit from signal TERM

But there was no log line for msmtp as in the previous attempt which didn’t fire emails.

This fired emails with partial attachment files (79.1KB) , but database didn’t update and there is no record of this transaction in RT.

Does this mean, msmtp is holding the process hostage?

codemarauder · April 24, 2025, 3:57pm

Thanks for your patience @Andrew_Ruthven .

It was msmtp. I switched to using exim4 which uses the same smarthost, and the problem is resolved.

I installed a fresh RT with fresh DB - moved from MySQL to Postgres, changed Perl versions, changed VMs, moved from Debian 12 to Debian 11 and what not; losing trail of 10 years old worth of tickets.

And it had to be msmtp !!!

Andrew_Ruthven · April 24, 2025, 11:58pm

Hey,

Very glad to see you managed to solve the issue. Bizarre that it was msmtp causing the issues. I haven’t come across that MTA before.

Are you able to restore your previous database, or have you already added more tickets?

codemarauder · April 25, 2025, 4:25am

msmtp doesn’t queue the mails and tries to pass it to the SMTP server on the fly. It is very easy to configure as compared to a full SMTP server. In my case, I was using a smarthost and this set-up was working for past 10 years.

Problems started to surface and became worse when I upgraded from Debian 10 to 11 and then to 12. I created a monitor script running every minute that kept checking HTTP return code and restart FCGI processes if it is not 200.

This problem became more pronounced when we ditched G-Suite in the favour of a self-hosted mail server that uses postfix.

As RT is critical to our operations, a good number of tickets are already created in this new instance. Moreover, I had switched to storing attachments to the disk, restoring the database doesn’t seem viable. I will plan to run the old instance for internal reference separately.

If you have any suggestions, I am willing to consider them.

Andrew_Ruthven · April 25, 2025, 12:14pm

No sorry, no real suggestions. The only thing I can think of would to be import the tickets from the old instance after incrementing the numbers, but then the ticket IDs will be different. So … probably just keep the old one hanging around.

Jeff_Voskamp · April 25, 2025, 1:06pm

If you use rt-serializer and rt-importer it will renumber tickets but also add a CF of Original_ID (or some such) to help map back and forth.