[SOLVED] Migrated to OTRS 5s, now agent login is too slow

[nedmaj]

Hi guys!

I've just migrated a test environment from OTRS 4.0.15 to 5.0.15. After solving all major issues, I've noticed the agent login is taking to long. Before it was 2 seconds, now it takes almost 10 seconds! Curiosly, the root user login is almost instantaneous. Also created a local agent user, and its login is very fast. Here it goes what I already did so far trying to identify the cause:

• Disabled all the user dashboards (I'm talking about my own agent user).
• Cleaned all the preferences.
• Disabled all the ACLs.
• Disabled OTRS Cloud Services.
• Tested the LDAP access from the command line. Looks ok.
• Already using FS module for session control.
• Caching using tmpfs.
• Apache logs show nothing.
• /var/log/messages show nothing.
• OTRS Performance logs doesn't give a clue.

And the agent login remains slow.

Here it goes my environment description:

• CentOS 6.5
• LDAP auth (Microsoft Active Directory)
• 4 x CPUs
• 16GB RAM (20% max memory utilization)
• 20% max cpu utilization
• Oracle 12.1
• Using a clone from production database. It has almost 60000 tickets
• Using OTRS::ITSM and some few other packages like DynamicField-ITSMConfigItem

Any help or clue would be very appreciated. I'm depending only on this to fully migrate.

Thanks in advance!

Samuel

[root]

Wow, awesome checklist. But let's go ahead. Do you use role/group sync? Did you used the same DC for the LDAP test form the command line which you use in the configuration?

[nedmaj]

Wow, awesome checklist. But let's go ahead. Do you use role/group sync? Did you used the same DC for the LDAP test form the command line which you use in the configuration?

Hi,

Thanks for the aswer!

Yes, I do use group sync. And yes, I used the same DC for the LDAP test.

[nedmaj]

Wow, awesome checklist. But let's go ahead. Do you use role/group sync? Did you used the same DC for the LDAP test form the command line which you use in the configuration?

Disabled all the group sync definitions, but one. The slowness remains. It takes actually 16 seconds. Before the migration, even with all the group sync definitions, the login was almost instantaneous.

[nedmaj]

Definitely, I don't think it's a LDAP issue.

During the login process the cpu raises a little. So I thing there's something going on in OTRS itself. Maybe something like 'look all the agent tickets' or so.

[root]

Definitely, I don't think it's a LDAP issue.

I agree, does not sound like this. Did you increased the log level to debug and enabled Debug for LDAP? Maybe the logfile will be chatty

[nedmaj]

Just did it and it shows nothing during the time lapse. Look:

Code: Select all

Feb 22 15:42:34 impala OTRS-CGI-6[23849]: [Notice][Kernel::System::Auth::Sync::LDAP::Sync] User: P_7029 not in GroupDN='cn=itsm-sotic-seuso,ou=Times,ou=ITSM,ou=Usuarios,dc=redecamara,dc=camara,dc=gov,dc=br', Filter='(member=CN=P_7029,OU=Funcionarios,OU=Usuarios,DC=redecamara,DC=camara,DC=gov,DC=br)'! (REMOTE_ADDR: 10.251.14.131).
Feb 22 15:42:51 impala OTRS-CGI-6[23849]: [Notice][Kernel::System::Web::InterfaceAgent::Run] Response::Agent: 1s taken (URL:Action=AgentDashboard&Subaction=:P_7029)

Almost 20 seconds passed from the last LDAP group sync to the action that returns the dashboard.

[root]

Well, to make sure that the dashboard is not involved try for the SysConfig setting Frontend::CommonParam###Action AgentTicketQueue instead of AgentDashboard.

[nedmaj]

Well, to make sure that the dashboard is not involved try for the SysConfig setting Frontend::CommonParam###Action AgentTicketQueue instead of AgentDashboard.

Just did it. The slowness remains.

Do you know which module is responsable for the login execution? I'm thinking about extract all the database queries executed and analyse the performance query by query.

[root]

Some of the statement are generated, but you could add tome debug output in Kernel/System/DB.pm around the 'sub Do'.

Anyway I've did more than one migration, even with Oracle, but this behavior is unknown to me :-/

[nedmaj]

Some of the statement are generated, but you could add tome debug output in Kernel/System/DB.pm around the 'sub Do'.

Anyway I've did more than one migration, even with Oracle, but this behavior is unknown to me :-/

Did it. But the sub Do only hands inserts, updates and deletes. I implemented a log in sub Prepare, but for some reason only some selects were logged. Looks like some queries don't pass through sub Prepare. I'll keep trying.

[root]

Any possibility to log on the database side?

[nedmaj]

Any possibility to log on the database side?

Sure. I'll request a trace. Meanwhile, I'm debugging InterfaceAgent.pm.

[nedmaj]

Something is wrong. Don't know why, but each login is executing the queries below several times:

Code: Select all

SELECT id, login,  title, first_name, last_name, pw, valid_id,  create_time, change_time FROM users WHERE  id = ?

Code: Select all

SELECT preferences_key, preferences_value            FROM user_preferences            WHERE user_id = ?

[nedmaj]

And this only happens with LDAP users. When I login with a local user (DB), the queries above are executed only one time.

[nedmaj]

There is a "for" loop calling "GetUserData" but the execution doesn't get into it.

[nedmaj]

I forced an exception in GetUserData to see the stack trace.

For some reason, OTRS is looping through all the agents. I still have to dig a little deeper.

Code: Select all

 Traceback (106370):
   Module: Kernel::System::User::GetUserData Line: 113
   Module: Kernel::System::User::UserList Line: 1133
   Module: Kernel::System::Group::PermissionUserRoleGet Line: 1891
   Module: Kernel::System::Group::PermissionUserGet Line: 1023
   Module: Kernel::System::Web::InterfaceAgent::Run Line: 334
   Module: ModPerl::ROOT::ModPerl::Registry::opt_otrs_bin_cgi_2dbin_index_2epl::handler Line: 40
   Module: (eval) (v1.99) Line: 204
   Module: ModPerl::RegistryCooker::run (v1.99) Line: 204
   Module: ModPerl::RegistryCooker::default_handler (v1.99) Line: 170
   Module: ModPerl::Registry::handler (v1.99) Line: 31

[nedmaj]

Oh my g... Just found a nasty piece of code. See below:

Kernel::System::Group::PermissionUserRoleGet Line: 1890-1895

Code: Select all

    # get valid user list
    my %UserList = $Kernel::OM->Get('Kernel::System::User')->UserList(
        Type => 'Short',
    );

    return if !$UserList{ $Param{UserID} };

Every time PermissionUserRoleGet is called to return an user roles set, OTRS loops through all the agents list in order to see if the user is valid or not. That is totally unnecessary since the code already got the user id. GetUserData once is enough to see if the user is valid or not.

That is definetely a bug!!!

[nedmaj]

Got it!

Commented the code above. Problem solved!

I'll post a bug to xxx.

[jojo]

please post the bug# here

[nedmaj]

please post the bug# here

https://bugs.otrs.org/show_bug.cgi?id=12643

[nedmaj]

Too bad. OTRS denied the bug.

[nedmaj]

Posted another bug, this time related to the user cache. Looks like every time a agent logins the user cache is beeing deleted.

https://bugs.otrs.org/show_bug.cgi?id=12648

[nedmaj]

Hi guys,

Found the problem. I was trying to sync an attribute that doesn't exists:

Suspicious log error:

Code: Select all

[Fri Mar  3 09:50:25 2017] -e: Use of uninitialized value $SyncUser{"UserPhone"} in string eq at /opt/otrs/Custom/Kernel/System/Auth/Sync/LDAP.pm line 336.

From Config.pm:

Code: Select all

    $Self->{'AuthSyncModule::LDAP::UserSyncMap'} = {
    # DB -> LDAP
        UserLogin     => 'sAMAccountName',
        UserFirstname => 'givenname',
        UserLastname  => 'sn',
        UserEmail     => 'mail',
        UserPhone     => 'telephonenumber', <=========== This is the cause of all evil!!!
        };

So the database attribute was always empty, triggering the UserUpdate that was triggering Cache::CleanUp.

Removed attribute UserPhone and problem solved!

By the way, OTRS has just acknowledge the bug above, so in the case of a user attribute change, the Cache will not be cleaned up anymore. Version 5.0.17 was just released.

Thanks everyone for the help!!!

[root]

Thanks for sharing the solution!