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. |
This knowledge article may contain information that does not apply to version 21.05 or later which runs in a container environment. Please refer to Article Number 000385088 for more information about troubleshooting BMC products in containers. 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:
....<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 ------------------- Note : Entering no value or 0 disables authentication using an AREA service, and the BMC Remedy AR System server accesses the operating system for authentication purposes. Sample arerror snippet Mon Jun 22 11:16:11.673 2020 Actual Authentication Chaining Applied:DEFAULT_OS |