RT doesn't like one particular user

RT Users
1

A bit of background:

I’m in the process of migrating RT from version 3.6.3 on Solaris with a MySQL 4 backend to 4.4.3 on Linux with a MySQL 5.7.22 backend. At the same time, I’m also migrating to using Active Directory/Kerberos for authentication.

Despite the fairly complex migration path, this has actually gone pretty smoothly. I’ve got everything working just fine, and (because most of our RT login usernames already matched AD equivalents), it’s pretty seamless for the end user.

There is one user, however, who hasn’t been so lucky. He can log in and use RT just fine, but if he spends more than a few seconds clicking around and searching for tickets, eventually he tries searching, RT times out and the web browser reports a 500 error.

I don’t know if it’s relevant, but prior to the migration, his Active Directory username did not match his RT username. I have manually changed his RT username to match.

In my Apache logs, I have:

[Wed Jan 23 14:31:35.163113 2019] [fcgid:warn] [pid 28647] [client 10.138.32.29:49303] mod_fcgid: read data timeout in 40 seconds
[Wed Jan 23 14:31:35.163222 2019] [core:error] [pid 28647] [client 10.138.32.29:49303] End of script output before headers: rt-server.fcgi
[Wed Jan 23 14:31:38.115214 2019] [fcgid:warn] [pid 28649] [client 10.138.32.29:49307] mod_fcgid: read data timeout in 40 seconds
[Wed Jan 23 14:31:38.115289 2019] [core:error] [pid 28649] [client 10.138.32.29:49307] End of script output before headers: rt-server.fcgi

I also have debug logging turned on in RT. At the same of time, that shows:

[33154] [Wed Jan 23 14:28:24 2019] [debug]: Using internal Perl HTML -> text conversion (/opt/rt/rt4/sbin/../lib/RT/Interface/Email.pm:1479)
[33246] [Wed Jan 23 14:30:02 2019] [debug]: Using internal Perl HTML -> text conversion (/opt/rt/rt4/sbin/../lib/RT/Interface/Email.pm:1479)
[33154] [Wed Jan 23 14:30:37 2019] [debug]: Attempting to use external auth service: ActiveDirectory (/opt/rt/rt4/sbin/../lib/RT/Authen/ExternalAuth.pm:288)
[33154] [Wed Jan 23 14:30:37 2019] [debug]: SSO Failed and no user to test with. Nexting (/opt/rt/rt4/sbin/../lib/RT/Authen/ExternalAuth.pm:316)
[33154] [Wed Jan 23 14:30:37 2019] [debug]: Autohandler called ExternalAuth. Response: (0, No User) (/opt/rt/rt4/share/html/Elements/DoAuth:58)
[33154] [Wed Jan 23 14:30:39 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 125 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:40 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 164 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:40 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 82 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:40 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 75 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:40 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 32 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:40 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 48 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:40 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 146 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:40 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 19 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:42 2019] [debug]: Unable to load Which Test or Document Ref? for RT::Queue-RT::Ticket 4 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:51 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 75 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:52 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 125 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:52 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 164 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:52 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 82 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:52 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 32 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:52 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 48 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:52 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 146 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:52 2019] [debug]: Unable to load Which Test? for RT::Queue-RT::Ticket 19 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33154] [Wed Jan 23 14:30:54 2019] [debug]: Unable to load Which Test or Document Ref? for RT::Queue-RT::Ticket 4 (/opt/rt/rt4/share/html/Elements/ColumnMap:117)
[33309] [Wed Jan 23 14:30:59 2019] [debug]: Using internal Perl HTML -> text conversion (/opt/rt/rt4/sbin/../lib/RT/Interface/Email.pm:1479)
2

I have tracked this down to two SQL queries that take a very long time to execute.

The first takes about 50 seconds and is:

SELECT COUNT(DISTINCT main.id) FROM Tickets main LEFT JOIN Groups Groups_1  ON ( Groups_1.Domain = 'RT::Ticket-Role' ) AND ( Groups_1.Instance = main.id ) LEFT JOIN CachedGroupMembers CachedGroupMembers_2  ON ( CachedGroupMembers_2.Disabled = '0' ) AND ( CachedGroupMembers_2.MemberId = '6877' ) AND ( CachedGroupMembers_2.GroupId = Groups_1.id )  WHERE ( ( main.Queue IN ('19', '23', '48', '68', '75', '82', '86', '90', '99', '125', '146', '147', '157', '164') OR  ( main.Owner = '6877' AND main.Queue IN ('4', '6') )  OR  ( CachedGroupMembers_2.MemberId IS NOT NULL AND Groups_1.Name = 'Requestor' AND main.Queue IN ('4', '6') )  OR  ( CachedGroupMembers_2.MemberId IS NOT NULL AND Groups_1.Name = 'Cc' AND main.Queue IN ('6') )  OR  ( CachedGroupMembers_2.MemberId IS NOT NULL AND Groups_1.Name = 'AdminCc' AND main.Queue IN ('155') )  ) ) AND (main.IsMerged IS NULL) AND (main.Status != 'deleted') AND (main.Type = 'ticket') AND (main.id < '1500' AND main.id > '1000') ;

The second takes around 33 seconds and is:

SELECT DISTINCT main.* FROM Tickets main LEFT JOIN Groups Groups_1  ON ( Groups_1.Domain = 'RT::Ticket-Role' ) AND ( Groups_1.Instance = main.id ) LEFT JOIN CachedGroupMembers CachedGroupMembers_2  ON ( CachedGroupMembers_2.Disabled = '0' ) AND ( CachedGroupMembers_2.MemberId = '6877' ) AND ( CachedGroupMembers_2.GroupId = Groups_1.id )  WHERE ( ( main.Queue IN ('19', '23', '48', '68', '75', '82', '86', '90', '99', '125', '146', '147', '157', '164') OR  ( main.Owner = '6877' AND main.Queue IN ('4', '6') )  OR  ( CachedGroupMembers_2.MemberId IS NOT NULL AND Groups_1.Name = 'Requestor' AND main.Queue IN ('4', '6') )  OR  ( CachedGroupMembers_2.MemberId IS NOT NULL AND Groups_1.Name = 'Cc' AND main.Queue IN ('6') )  OR  ( CachedGroupMembers_2.MemberId IS NOT NULL AND Groups_1.Name = 'AdminCc' AND main.Queue IN ('155') )  ) ) AND (main.IsMerged IS NULL) AND (main.Status != 'deleted') AND (main.Type = 'ticket') AND (main.id < '1500' AND main.id > '1000')  ORDER BY main.id ASC  LIMIT 50;

Running EXPLAIN against the backend database generates a warning in MySQL:

Cannot use ref access on index 'groups3' due to type or collation conversion on field 'Instance'

MySQL [rt4]> describe Groups;
+---------------+--------------+------+-----+---------+----------------+
| Field         | Type         | Null | Key | Default | Extra          |
+---------------+--------------+------+-----+---------+----------------+
| id            | int(11)      | NO   | PRI | NULL    | auto_increment |
| Name          | varchar(200) | YES  |     | NULL    |                |
| Description   | varchar(255) | YES  |     | NULL    |                |
| Domain        | varchar(64)  | YES  | MUL | NULL    |                |
| Instance      | varchar(64)  | YES  | MUL | NULL    |                |
| Creator       | int(11)      | NO   |     | 0       |                |
| Created       | datetime     | YES  |     | NULL    |                |
| LastUpdatedBy | int(11)      | NO   |     | 0       |                |
| LastUpdated   | datetime     | YES  |     | NULL    |                |
+---------------+--------------+------+-----+---------+----------------+
9 rows in set (0.00 sec)

MySQL [rt4]> describe Tickets;
+-----------------+--------------+------+-----+--------------+----------------+
| Field           | Type         | Null | Key | Default      | Extra          |
+-----------------+--------------+------+-----+--------------+----------------+
| id              | int(11)      | NO   | PRI | NULL         | auto_increment |
| EffectiveId     | int(11)      | NO   | MUL | 0            |                |
| Queue           | int(11)      | NO   | MUL | 0            |                |
| Type            | varchar(16)  | YES  |     | NULL         |                |
| Owner           | int(11)      | NO   | MUL | 0            |                |
| Subject         | varchar(200) | YES  |     | [no subject] |                |
| InitialPriority | int(11)      | NO   |     | 0            |                |
| FinalPriority   | int(11)      | NO   |     | 0            |                |
| Priority        | int(11)      | NO   |     | 0            |                |
| TimeEstimated   | int(11)      | NO   |     | 0            |                |
| TimeWorked      | int(11)      | NO   |     | 0            |                |
| Status          | varchar(64)  | YES  |     | NULL         |                |
| TimeLeft        | int(11)      | NO   |     | 0            |                |
| Told            | datetime     | YES  |     | NULL         |                |
| Starts          | datetime     | YES  |     | NULL         |                |
| Started         | datetime     | YES  |     | NULL         |                |
| Due             | datetime     | YES  |     | NULL         |                |
| Resolved        | datetime     | YES  |     | NULL         |                |
| LastUpdatedBy   | int(11)      | NO   |     | 0            |                |
| LastUpdated     | datetime     | YES  |     | NULL         |                |
| Creator         | int(11)      | NO   |     | 0            |                |
| Created         | datetime     | YES  |     | NULL         |                |
| IsMerged        | smallint(6)  | YES  |     | NULL         |                |
| SLA             | varchar(64)  | YES  |     | NULL         |                |
+-----------------+--------------+------+-----+--------------+----------------+
24 rows in set (0.00 sec)

It would seem MySQL is obliged to convert Ticket.id or Groups.Instance for every ticket in the database in order to execute this query. That might explain the performance issues!

Are there any issues with changing Groups.Instance into a int(11)?

3

It looks like for a fresh new RT, Instance is an integer:

So updating it seems sensible.

1 Like
4

Sorry, I should have updated this.

Not only is it an integer, but it was also an integer in the old version it was upgraded from.

And yet my old database also shows a VARCHAR(64); I have no idea how this came to be.

As suggested, have changed this to an INT. Performance is now fine.

5

I’ve just fixed the same issue (Groups table’s Instance column was a varchar(64)) in our RT 5.0.2. There were a few records with Instance=’’ so I needed to set those to 0 before MySQL would change the type.

This had been causing progressively worse performance in many situations, but most noticeably when sorting tickets by owner.

Our RT has a long history, with tickets dating back to 1999. I guess that a schema update must’ve failed or been missed at some stage.