Remedy - Server - How to enable Authentication Logging in AR System Server 9.x?

Version 7
    Share This:

    This document contains official content from the BMC Software Knowledge Base. It is automatically updated when the knowledge article is modified.


    PRODUCT:

    Remedy AR System Server


    COMPONENT:

    AR System


    APPLIES TO:

    BMC Remedy AR System Server 9.x and higher version.



    QUESTION:

    How to enable Authentication Logging in AR System Server 9.x?
    the aim to enable this type of logging is to determine when AR Server is performing a OS or AREA authentication and whether it is successful or not.


    ANSWER:

    There are a few types of logging that can be used when troubleshooting an authentication issue.
    In general, there are 3 types of authentication, 

    1.  ARS (or Internal) authentication.
    2.  AREA (AR External Authentication) via one or more AREA Plugins.
         a.  This can be achieved through the C plugin server, a Java plugin server, or a combination.
    3.  OS Authentication (Windows Authentication or Unix authentication, depending on the platform of AR Server).

    The aruser.log provides information about when a user logs in our out, whether they failed a login attempt.
    Here is an example that contains the following information:

       
    • Some integration or component successfully logged in as 'Remedy Application Service'
    •  
    • The 'administrator' user attempted to login from a Remedy User client and failed.  The '(authentication)' tag lets you know this was an external authentication.
    •  
    • The Mid-Tier itself performed a login
    •  
    • The 'Demo' user successfully logged in through the Mid-Tier
    •  
    • The '(impersonated)' tag lets you know that the Mid-Tier performed its own login as 'Demo' in order to perform some task while impersonating 'Demo' in order to use his permissions:
                      -------------------
                   ....<USER: Remedy Application Service> <Overlay-Group: 0> /* Wed Feb 17 2016 23:26:11.2350 */      LOGIN              Remedy Application Service   
                   ....<USER: administrator> <Overlay-Group: 1> /* Wed Feb 17 2016 23:26:14.9960 */     LOGIN FAILED       administrator   (authentication) ARGetServerInfo from Remedy User (protocol 18) at IP address <IP address>
                   ....<USER:
    Demo> <Overlay-Group: 1> /* Wed Feb 17 2016 23:27:03.2060 */     LOGIN              Demo   
                   ....<USER: MidTier Service> <Overlay-Group: 1> /* Wed Feb 17 2016 23:27:03.9230 */     LOGIN              MidTier Service   
                   ....<USER:
    Demo -- Impersonated by MidTier Service --> <Overlay-Group: 1> /* Wed Feb 17 2016 23:27:04.0640 */     LOGIN              Demo   (impersonated)
                   ....<USER: Demo -- Impersonated by MidTier Service --> <Overlay-Group: 1> /* Wed Feb 17 2016 23:27:04.7360 */     LOGOUT             Demo
                   -------------------


    The  arapi.log will show the API call that was issued when a user attempted a login: 
    For example, the Mid-Tier will issue the +VER call: 
                   -------------------
                   ....*/ +VER     ARVerifyUser -- user Demo from Mid-tier (protocol 23) at IP address <IP Address> using RPC // :q:0.19s
                   -------------------

    The   arsql.log will show a query on the '  user_cache' table when AR Server is checking if a user is a valid internal user or a user that requires external authentication: 
                   -------------------
                   SELECT userName,password,authUserName,shortAuthString,longAuthString,badPwd,badPwdTotal,notifyMech,licType,licTypeFText,licTypeReserv1,licTypeApp,email,shortGroup,longGroup,shortCompGroup,longCompGroup,timestamp
                   
    ,validateKey FROM user_cache WHERE userName = 'billybob'
                   -------------------

    Both the   arplugin.log (for C plugins) and the   arjavaplugin.log (for Java plugins) will log when an attempt has been make to login a user via AREA. 
    There is no currently supported C AREA Plugin so no example will be shown here.  But the tag to look for is '  +VL' .  This represents the   VerifyLoginCallback function that gets called when AREA is invoked. 

    For Java plugins, it is best to enable '  DEBUG' level logging via the Plugin Server Configuration option in the Administration Console. 
    Then search for the 'AREAVerifyLogin' tag. Here is an example of a login attempt: 
                   -------------------
                   ....<DEBUG> <AREAChainingHandler > <      AREAChainingHandler.java:116    > /* Wed Feb 17 2016 09:52:05.639 */  Calling AREAVerifyLogin() through plugin: ARSYS.AREA.ATRIUMSSO
                   ....<INFO > <ARPluginContext > <          ARPluginContext.java:170    > /* Wed Feb 17 2016 09:52:05.640 */  <ARSYS.AREA.ATRIUMSSO>areaVerifyLogin()
                   ....<ERROR> <ARPluginContext > <          ARPluginContext.java:176    > /* Wed Feb 17 2016 09:52:05.640 */  <ARSYS.AREA.ATRIUMSSO>Login Failed as Atrium SSO Server Location is null
                   ....<DEBUG> <AREAChainingHandler > <      AREAChainingHandler.java:116    > /* Wed Feb 17 2016 09:52:05.640 */  Calling AREAVerifyLogin() through plugin: ARSYS.AREA.AREALDAP
                   ....<INFO > <ARPluginContext > <          ARPluginContext.java:170    > /* Wed Feb 17 2016 09:52:05.640 */  <AREA.LDAP>areaVerifyLogin()
                   ....<WARN > <ARPluginContext > <          ARPluginContext.java:173    > /* Wed Feb 17 2016 09:52:05.640 */  <AREA.LDAP>Password cannot be empty for external authentication
                   ....<INFO > <ARPluginContext  > <          ARPluginContext.java:170    > /* Wed Feb 17 2016 09:52:05.640 */  <AREA.LDAP>Return Code:1

                   -------------------

    Notice that OS Authentication is not well represented in these logs. To get additional Authentication Logging, including logs that show OS authentication, perform the following steps: 

    1.  Edit the   logback_server.xml file in the   <ARSystem Install Dir>/conf directory 
    2.  Locate the block of settings (from  '<logger'  to </logger>') that contains the word   'AuthenticationChainProcessor'
    3.  In that block, locate the  'level='  setting and change it to  'DEBUG'
    4.  Add the following block of text directory after the   </logger> line from the previous block of settings: 
              <logger
                    name="com.bmc.arsys.server.accesscontrol.loginmodules.WindowsLoginModule"
                    level="debug" additivity="false">
                    <appender-ref ref="ServerLog" />
                    <appender-ref ref="DebugLog" />
            </logger>


    5.  Open the AR System   Administration Console >System >General >Server Information >Log Files,  click on the '  Reload Log Conf File' box and click apply. 

    Once we do this, we get additional information about authentication inside the   arerror.log
    NOTE: Do not forget to set the 2 'level=' settings to 'warn' once you have finished troubleshooting

    Here are a couple of snippets of the resulting logs. 
    The first snippet shows the 'administrator' user logging in using OS authentication and failing due to a bad password. 
    It also shows the '  Demo' user logging in with internal authentication and succeeding.  Note that in this example, Authentication Chaining is set to   ARS-AREA-OS
                   -------------------
                   Wed Feb 17 23:25:49.551 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Wed Feb 17 23:25:49.551 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Wed Feb 17 23:26:13.616 2016 Error while getting Windows Identity from Local OScom.sun.jna.platform.win32.Win32Exception: Logon failure: unknown user name or bad password.
                   Wed Feb 17 23:26:13.763 2016 Exception in windows login module com.sun.jna.platform.win32.Win32Exception: The interface is unknown.
                   Wed Feb 17 23:26:14.457 2016 Authentication failed: administrator
                   Wed Feb 17 23:26:14.457 2016 Authentication failed: administrator
                   Wed Feb 17 23:27:03.199 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Wed Feb 17 23:27:03.199 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Wed Feb 17 23:27:03.200 2016 Principals :
    Demo
                   Wed Feb 17 23:27:03.200 2016 Principals : Demo
                   Wed Feb 17 23:27:12.758 2016 in checkIfExtSyncIsNeeded for Demo UserType = EBO in session = 11288
                   Wed Feb 17 23:27:12.758 2016 in checkIfExtSyncIsNeeded for
    Demo UserType = EBO in session = 11288
                   -------------------

    This final log snippet shows the '  Administrator' user logging in successfully using   AREA LDAP.  Note that in this example, Authentication Chaining is set to   ARS-AREA
                   -------------------
                    Tue Feb 16 23:09:25.974 2016 Actual Authentication Chaining Applied:ARS_AREA
                   Tue Feb 16 23:09:26.755 2016 Principals :
    Administrator
                   Tue Feb 16 23:09:26.755 2016 Got response from Area-SSO.
                   Tue Feb 16 23:09:27.255 2016 in checkIfExtSyncIsNeeded for
    Administrator UserType = LDAP in session = 27636
                   Tue Feb 16 23:09:27.271 2016 The session instance for user Administrator needs to perform ext auth
                   Tue Feb 16 23:09:27.271 2016 Actual Authentication Chaining Applied:ARS_AREA
                   Tue Feb 16 23:09:28.021 2016 Principals :
    Administrator
                   Tue Feb 16 23:09:28.021 2016 Got response from Area-SSO.
                   Tue Feb 16 23:09:28.333 2016 in checkIfExtSyncIsNeeded for
    Administrator UserType = LDAP in session = 27636
                   Tue Feb 16 23:09:28.333 2016 The session instance for user Administrator needs to perform ext auth
                   Tue Feb 16 23:09:28.333 2016 Actual Authentication Chaining Applied:ARS_AREA
                   Tue Feb 16 23:09:29.067 2016 Principals :
    Administrator
                   Tue Feb 16 23:09:29.067 2016 Got response from Area-SSO.
                   Tue Feb 16 23:09:29.224 2016 in checkIfExtSyncIsNeeded for Demo UserType = EBO in session = 27611
                   Tue Feb 16 23:09:29.396 2016 in checkIfExtSyncIsNeeded for
    Administrator UserType = LDAP in session = 27636
                   -------------------
    NOTE:  Make sure you set the logback_server.xml back to its original values once you are done troubleshooting to avoid having a huge arerror.log


    Additional Information:
    There are other logging modules related to authentication that can be enabled. 

    Here is the complete list: 
    <logger
            name="com.bmc.arsys.server.accesscontrol.AuthenticationChainProcessor"
            level="debug" additivity="true">
            <appender-ref ref="ServerLog" />
            <appender-ref ref="DebugLog" />
    </logger>
    <logger
            name="com.bmc.arsys.server.accesscontrol.loginmodules.WindowsLoginModule"   
            level="debug" additivity="false">
            <appender-ref ref="ServerLog" />
            <appender-ref ref="DebugLog" />
    </logger>
    <logger
            name="com.bmc.arsys.server.accesscontrol.loginmodules.DefaultLoginModule"       
            level="debug" additivity="false">
            <appender-ref ref="ServerLog" />
            <appender-ref ref="DebugLog" />
    </logger>
    <logger
            name="com.bmc.arsys.server.accesscontrol.loginmodules.ExternalAuthLoginModule"  
            level="debug" additivity="false">
            <appender-ref ref="ServerLog" />
            <appender-ref ref="DebugLog" />
    </logger>
    <logger
            name="com.bmc.arsys.server.accesscontrol.loginmodules.LdapLoginModule"   
            level="debug" additivity="false">
            <appender-ref ref="ServerLog" />
            <appender-ref ref="DebugLog" />
    </logger>
    <logger
            name="com.bmc.arsys.server.accesscontrol.loginmodules.UnixLoginModule"   
            level="debug" additivity="false">
            <appender-ref ref="ServerLog" />
            <appender-ref ref="DebugLog" />
    </logger>



    Here is an example log (  with annotations) with all of the above settings enabled: 
                   -------------------
                   Thu Feb 18 17:44:44.463 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Thu Feb 18 17:44:44.463 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Thu Feb 18 17:44:47.055 2016 Principals : RemedyProd\Administrator
                   Thu Feb 18 17:44:47.055 2016 Principals : RemedyProd\Administrator
                   
    [The above line shows that AR Server detected that the local server name is RemedyProd and passed it to the login routine]

                   Thu Feb 18 17:44:47.056 2016 Got response from OS.
                   Thu Feb 18 17:44:47.056 2016 Got response from OS.
                   Thu Feb 18 17:44:50.907 2016 in checkIfExtSyncIsNeeded for administrator UserType = OS in session = 1394
                 
     [The above line shows that AR Server checks to see if the External Authentication Need To Sync Timeout has elapsed]

                   Thu Feb 18 17:44:50.907 2016 in checkIfExtSyncIsNeeded for administrator UserType = OS in session = 1394
                   Thu Feb 18 17:44:50.912 2016 in checkIfExtSyncIsNeeded for administrator UserType = OS in session = 1394
                   Thu Feb 18 17:44:50.912 2016 in checkIfExtSyncIsNeeded for administrator UserType = OS in session = 1394
                   Thu Feb 18 17:45:31.930 2016 in checkIfExtSyncIsNeeded for administrator UserType = OS in session = 1394
                   Thu Feb 18 17:46:14.132 2016 in checkIfExtSyncIsNeeded for administrator UserType = OS in session = 1394
                   Thu Feb 18 17:46:14.132 2016 in checkIfExtSyncIsNeeded for administrator UserType = OS in session = 1394
                   Thu Feb 18 17:46:28.929 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Thu Feb 18 17:46:28.929 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Thu Feb 18 17:46:35.813 2016 logging out administrator
                   Thu Feb 18 17:46:35.813 2016 logging out administrator
                   Thu Feb 18 17:46:35.820 2016 Authentication failed: administrator
                   Thu Feb 18 17:46:35.820 2016 Authentication failed: administrator
                   Thu Feb 18 17:47:22.749 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Thu Feb 18 17:47:22.749 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Thu Feb 18 17:47:22.750 2016 Principals : Demo
                   Thu Feb 18 17:47:22.750 2016 Principals : Demo
                   Thu Feb 18 17:47:22.821 2016 in checkIfExtSyncIsNeeded for Demo UserType = EBO in session = 1410
                   Thu Feb 18 17:47:22.821 2016 in checkIfExtSyncIsNeeded for Demo UserType = EBO in session = 1410
                   Thu Feb 18 17:47:22.824 2016 in checkIfExtSyncIsNeeded for Demo UserType = EBO in session = 1410
                   Thu Feb 18 17:47:22.824 2016 in checkIfExtSyncIsNeeded for Demo UserType = EBO in session = 1410
                   Thu Feb 18 17:48:52.364 2016 in checkIfExtSyncIsNeeded for Demo UserType = EBO in session = 1410
                   Thu Feb 18 17:49:24.504 2016 in checkIfExtSyncIsNeeded for Demo UserType = EBO in session = 1410
                   Thu Feb 18 17:49:24.504 2016 in checkIfExtSyncIsNeeded for Demo UserType = EBO in session = 1410
                   Thu Feb 18 17:49:42.013 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Thu Feb 18 17:49:42.013 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Thu Feb 18 17:49:42.701 2016 External auth success
                   Thu Feb 18 17:49:42.701 2016 Principals : administrator
                   Thu Feb 18 17:49:42.701 2016 Principals : administrator
                   Thu Feb 18 17:49:42.701 2016 Got response from Area-SSO.
                   Thu Feb 18 17:49:42.701 2016 Got response from Area-SSO.
                   Thu Feb 18 17:49:43.158 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Thu Feb 18 17:49:43.158 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Thu Feb 18 17:49:43.464 2016 External auth success
                   Thu Feb 18 17:49:43.464 2016 Principals : administrator
                   Thu Feb 18 17:49:43.464 2016 Principals : administrator
                   Thu Feb 18 17:49:43.465 2016 Got response from Area-SSO.
                   Thu Feb 18 17:49:43.465 2016 Got response from Area-SSO.
                   Thu Feb 18 17:49:43.468 2016 in checkIfExtSyncIsNeeded for administrator UserType = LDAP in session = 1457
                   Thu Feb 18 17:49:43.468 2016 in checkIfExtSyncIsNeeded for administrator UserType = LDAP in session = 1457
                   Thu Feb 18 17:49:43.470 2016 The session instance for user administrator needs to perform ext auth

                   [AREA Authentication is required]

                   Thu Feb 18 17:49:43.470 2016 The session instance for user administrator needs to perform ext auth
                   Thu Feb 18 17:49:43.470 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Thu Feb 18 17:49:43.470 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Thu Feb 18 17:49:43.487 2016 External auth success
                   Thu Feb 18 17:49:43.487 2016 Principals : administrator
                   Thu Feb 18 17:49:43.487 2016 Principals : administrator
                   Thu Feb 18 17:49:43.488 2016 Got response from Area-SSO.
                   Thu Feb 18 17:49:43.488 2016 Got response from Area-SSO.
                   Thu Feb 18 17:49:43.493 2016 in checkIfExtSyncIsNeeded for administrator UserType = LDAP in session = 1457
                   Thu Feb 18 17:49:43.493 2016 in checkIfExtSyncIsNeeded for administrator UserType = LDAP in session = 1457
                   Thu Feb 18 17:49:43.494 2016 The session instance for user administrator needs to perform ext auth
                   Thu Feb 18 17:49:43.494 2016 The session instance for user administrator needs to perform ext auth
                   Thu Feb 18 17:49:43.495 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Thu Feb 18 17:49:43.495 2016 Actual Authentication Chaining Applied:ARS_AREA_OS
                   Thu Feb 18 17:49:43.779 2016 External auth success
                   Thu Feb 18 17:49:43.779 2016 Principals : administrator
                   Thu Feb 18 17:49:43.779 2016 Principals : administrator
                   Thu Feb 18 17:49:43.779 2016 Got response from Area-SSO.
                   Thu Feb 18 17:49:43.779 2016 Got response from Area-SSO.
                   Thu Feb 18 17:49:43.814 2016 in checkIfExtSyncIsNeeded for administrator UserType = LDAP in session = 1457
                   Thu Feb 18 17:49:43.814 2016 in checkIfExtSyncIsNeeded for administrator UserType = LDAP in session = 1457
                   Thu Feb 18 17:49:43.818 2016 in checkIfExtSyncIsNeeded for administrator UserType = LDAP in session = 1457
                   Thu Feb 18 17:49:43.818 2016 in checkIfExtSyncIsNeeded for administrator UserType = LDAP in session = 1457
                   Thu Feb 18 17:49:43.863 2016 in checkIfExtSyncIsNeeded for administrator UserType = LDAP in session = 1457
                   Thu Feb 18 17:49:43.863 2016 in checkIfExtSyncIsNeeded for administrator UserType = LDAP in session = 1457
                   Thu Feb 18 18:00:24.511 2016 in checkIfExtSyncIsNeeded for administrator UserType = LDAP in session = 1440
                   Thu Feb 18 18:01:33.949 2016 in checkIfExtSyncIsNeeded for Demo UserType = EBO in session = 14317
                   

                   [EBO is an Internal User-logged in using ARS authentication]
                   Thu Feb 18 18:01:33.949 2016 in checkIfExtSyncIsNeeded for Demo UserType = EBO in session = 14317
                   Thu Feb 18 18:01:43.356 2016 in checkIfExtSyncIsNeeded for Demo UserType = EBO in session = 14317
                   
    Thu Feb 18 18:01:43.356 2016 in checkIfExtSyncIsNeeded for Demo UserType = EBO in session = 14317
                   -------------------



      

     


    Article Number:

    000102533


    Article Type:

    FAQ/Procedural



      Looking for additional information?    Search BMC Support  or  Browse Knowledge Articles