Missing AuditEvent from LogAuditProvider
justincranford May 24, 2011 11:22 AMI have LogAuditProvider enabled in jboss-logging.xml to do console logging. I get AuditEvent records for successful authentication of a URL that exists (HTTP.OK 200), but not for URLs that do not exist (HTTP 404). Resteasy exceptions are thrown inside the WEB container, after the request has been authenticated. Why no AuditEvent for that authenticated request with a HTTP 404 error, or even the unauthenticated HTTP 401 challenge? I would reasonably expect all individual HTTP requests to be logged by LogAuditProvider. This seems like an oversight in PicketBox auditing, or perhaps even a bug?
Here are my client and server logs. The client uses HttpClient 4.0.3 and does the HTTP 302 redirect manually. I also override DefaultRedirectHandler.isRedirectRequired() to log the automatic 401 redirect as part of the authentication challenge...
>>>>> Client Console Log <<<<<
-- Delete "/CustomerName/ApplicationName/UserName" (Note: A Resteasy resource does not exist for this URL pattern!!!)
Request 1: DELETE http://localhost:8080/RestWeb1/CustomerName/ApplicationName/UserName
Response 1: HTTP 302 (URL moved to https://localhost:8443/RestWeb1/CustomerName/ApplicationName/UserName)
Request 2: DELETE https://localhost:8443/RestWeb1/CustomerName/ApplicationName/UserName
Response 2: HTTP 401 (Request not authenticated, authentication redirect challenge requested using BASIC scheme)
Request 3: DELETE https://localhost:8443/RestWeb1/CustomerName/ApplicationName/UserName
Response 3: HTTP 404 (Request was authenticated, but could not find resource for relative /CustomerName/ApplicationName/UserName)
-- Delete "/CustomerName/ApplicationName" (Note: A Resteasy resource does exist for this URL pattern!!!)
Request 4: DELETE http://localhost:8080/RestWeb1/CustomerName/ApplicationName
Response 4: HTTP 302 (URL moved to https://localhost:8443/RestWeb1/CustomerName/ApplicationName)
Request 5: DELETE https://localhost:8443/RestWeb1/CustomerName/ApplicationName
Response 5: HTTP 401 (Request not authenticated, authentication redirect challenge requested using BASIC scheme)
Request 6: DELETE https://localhost:8443/RestWeb1/CustomerName/ApplicationName
Response 6: HTTP 200 (Request was authenticated and authorized, response was HTTP.OK)
>>>>> JBoss 6.0 Server Console log <<<<<
--Log messages for request/response 1
TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:{}
DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Security checking request DELETE /RestWeb1/CustomerName/ApplicationName/UserName
DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling hasUserDataPermission()
DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Failed hasUserDataPermission() test
TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:null
--Log messages for request/response 2
TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:{}
DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Security checking request DELETE /RestWeb1/CustomerName/ApplicationName/UserName
DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling hasUserDataPermission()
TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling authenticate()
DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Failed authenticate() test
TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:null
TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:{}
--Log messages for request/response 3 (Authenticated, but LogAuditProvider message is not present?)
DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Security checking request DELETE /RestWeb1/CustomerName/ApplicationName/UserName
DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling hasUserDataPermission()
TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling authenticate()
TRACE [org.jboss.security.auth.login.XMLLoginConfigImpl] Begin getAppConfigurationEntry(JustinCranfordSecurityDomain), size=12
TRACE [org.jboss.security.auth.login.XMLLoginConfigImpl] End getAppConfigurationEntry(JustinCranfordSecurityDomain), authInfo=AppConfigurationEntry[]:
[0]
LoginModule Class: org.jboss.security.auth.spi.DatabaseServerLoginModule
ControlFlag: LoginModuleControlFlag: sufficient
Options:
name=hashAlgorithm, value=MD5
name=principalsQuery, value=SELECT password FROM actor WHERE name=?
name=unauthenticatedIdentity, value=unauthenticated
name=hashEncoding, value=base64
name=dsJndiName, value=java:/MsSqlDS
name=rolesQuery, value=SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?
[1]
LoginModule Class: org.jboss.security.auth.spi.DatabaseCertLoginModule
ControlFlag: LoginModuleControlFlag: required
Options:
name=hashAlgorithm, value=MD5
name=principalsQuery, value=SELECT password FROM actor WHERE dname=?
name=unauthenticatedIdentity, value=unauthenticated
name=hashEncoding, value=base64
name=dsJndiName, value=java:/MsSqlDS
name=securityDomain, value=java:/jaas/JustinCranfordSecurityDomain
name=rolesQuery, value=SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.dname=?
[2]
LoginModule Class: org.jboss.security.ClientLoginModule
ControlFlag: LoginModuleControlFlag: required
Options:
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] initialize
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Security domain: JustinCranfordSecurityDomain
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Saw unauthenticatedIdentity=unauthenticated
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Password hashing activated: algorithm = MD5, encoding = base64, charset = {default}, callback = null, storeCallback = null
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] DatabaseServerLoginModule, dsJndiName=java:/MsSqlDS
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] principalsQuery=SELECT password FROM actor WHERE name=?
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] rolesQuery=SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] suspendResume=true
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] login
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] suspendAnyTransaction
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Excuting query: SELECT password FROM actor WHERE name=?, with username: SystemAdministrator
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Obtained user password
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] resumeAnyTransaction
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] User 'SystemAdministrator' authenticated, loginOk=true
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] commit, loginOk=true
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] getRoleSets using rolesQuery: SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?, username: SystemAdministrator
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] suspendAnyTransaction
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Excuting query: SELECT r.name,'Roles' FROM actor a,role r WHERE r.id=a.roleid AND a.name=?, with username: SystemAdministrator
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] Assign user to role SystemAdministrator
TRACE [org.jboss.security.auth.spi.DatabaseServerLoginModule] resumeAnyTransaction
TRACE [org.jboss.web.tomcat.security.JBossWebRealm] User: SystemAdministrator is authenticated
DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Authenticated 'SystemAdministrator' with type 'BASIC'
DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling accessControl()
TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Successfully passed all security constraints
TRACE [org.jboss.web.tomcat.security.RunAsListener] Resteasy, runAs: null
INFO [org.jboss.resteasy.spi.ResteasyDeployment] Deploying javax.ws.rs.core.Application: class com.mycom.rest.RestApplication1
INFO [org.jboss.resteasy.spi.ResteasyDeployment] Adding singleton resource com.mycom.rest.ApplicationResource from Application javax.ws.rs.core.Application
INFO [org.jboss.resteasy.spi.ResteasyDeployment] Adding singleton resource com.mycom.rest.CustomerResource from Application javax.ws.rs.core.Application
INFO [org.jboss.resteasy.spi.ResteasyDeployment] Adding singleton resource com.mycom.rest.UserResource from Application javax.ws.rs.core.Application
TRACE [org.jboss.web.tomcat.security.RunAsListener] Resteasy, runAs: null
TRACE [org.jboss.web.tomcat.security.RunAsListener] Resteasy, runAs: null
TRACE [org.jboss.web.tomcat.security.RunAsListener] Resteasy, runAs: null
DEBUG [org.jboss.resteasy.core.SynchronousDispatcher] PathInfo: /CustomerName/ApplicationName/UserName
DEBUG [org.jboss.resteasy.core.SynchronousDispatcher] Failed executing DELETE /CustomerName/ApplicationName/UserName: org.jboss.resteasy.spi.NotFoundException: Could not find resource for relative : /CustomerName/ApplicationName/UserName of full path: https://localhost:8443/RestWeb1/CustomerName/ApplicationName/UserName
at org.jboss.resteasy.core.registry.PathParamSegment.matchPattern(PathParamSegment.java:200) [:]
at org.jboss.resteasy.core.registry.RootSegment.matchChildren(RootSegment.java:339) [:]
at org.jboss.resteasy.core.registry.RootSegment.matchRoot(RootSegment.java:374) [:]
at org.jboss.resteasy.core.registry.RootSegment.matchRoot(RootSegment.java:367) [:]
at org.jboss.resteasy.core.ResourceMethodRegistry.getResourceInvoker(ResourceMethodRegistry.java:251) [:]
at org.jboss.resteasy.core.SynchronousDispatcher.getInvoker(SynchronousDispatcher.java:158) [:]
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119) [:]
at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:200) [:6.0.0.Final]
at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:48) [:6.0.0.Final]
at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:43) [:6.0.0.Final]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [:1.0.0.Final]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:324) [:6.0.0.Final]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:242) [:6.0.0.Final]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [:6.0.0.Final]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) [:6.0.0.Final]
at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:181) [:6.0.0.Final]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:593) [:6.0.0.Final]
at org.jboss.modcluster.catalina.CatalinaContext$RequestListenerValve.event(CatalinaContext.java:285) [:1.1.0.Final]
at org.jboss.modcluster.catalina.CatalinaContext$RequestListenerValve.invoke(CatalinaContext.java:261) [:1.1.0.Final]
at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:88) [:6.0.0.Final]
at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:100) [:6.0.0.Final]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) [:6.0.0.Final]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [:6.0.0.Final]
at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158) [:6.0.0.Final]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [:6.0.0.Final]
at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.invoke(ActiveRequestResponseCacheValve.java:53) [:6.0.0.Final]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:362) [:6.0.0.Final]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [:6.0.0.Final]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:654) [:6.0.0.Final]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:951) [:6.0.0.Final]
at java.lang.Thread.run(Thread.java:662) [:1.6.0_24]
TRACE [org.jboss.web.tomcat.security.RunAsListener] Resteasy, runAs: null
TRACE [org.jboss.web.tomcat.security.RunAsListener] Resteasy, runAs: null
TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:null
--Log messages for request/response 4
10:39:06,492 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:{}
10:39:06,492 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Security checking request DELETE /RestWeb1/CustomerName/ApplicationName
10:39:06,492 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling hasUserDataPermission()
10:39:06,492 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Failed hasUserDataPermission() test
10:39:06,492 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:null
--Log messages for request/response 5
10:39:06,492 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:{}
10:39:06,492 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Security checking request DELETE /RestWeb1/CustomerName/ApplicationName
10:39:06,492 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling hasUserDataPermission()
10:39:06,492 TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
10:39:06,492 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling authenticate()
10:39:06,492 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Failed authenticate() test
10:39:06,492 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:null
--Log messages for request/response 6 (Authenticated, and LogAuditProvider message is logged!)
10:39:06,492 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:{}
10:39:06,492 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Security checking request DELETE /RestWeb1/CustomerName/ApplicationName
10:39:06,492 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling hasUserDataPermission()
10:39:06,492 TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
10:39:06,492 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling authenticate()
10:39:06,492 TRACE [org.jboss.web.tomcat.security.JBossWebRealm] User: SystemAdministrator is authenticated
10:39:06,492 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Authenticated 'SystemAdministrator' with type 'BASIC'
10:39:06,492 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Calling accessControl()
10:39:06,492 TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
10:39:06,492 TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
10:39:06,492 DEBUG [org.apache.catalina.authenticator.AuthenticatorBase] Successfully passed all security constraints
10:39:06,492 TRACE [org.jboss.web.tomcat.security.RunAsListener] Resteasy, runAs: null
10:39:06,492 TRACE [org.jboss.web.tomcat.security.RunAsListener] Resteasy, runAs: null
10:39:06,492 DEBUG [org.jboss.resteasy.core.SynchronousDispatcher] PathInfo: /CustomerName/ApplicationName
10:39:06,664 TRACE [org.jboss.security.audit.providers.LogAuditProvider] [Success]Source=org.jboss.security.javaee.EJBAuthenticationHelper;principal=SystemAdministrator;method=deleteApplication;
10:39:06,664 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:{}
10:39:06,664 TRACE [org.jboss.security.plugins.authorization.JBossAuthorizationContext] Control flag for entry:org.jboss.security.authorization.config.AuthorizationModuleEntry{org.jboss.security.authorization.modules.DelegatingAuthorizationModule:{}REQUIRED}is:[REQUIRED]
10:39:06,664 TRACE [org.jboss.security.authorization.modules.ejb.EJBPolicyModuleDelegate] method=public void com.mycom.services.ResourceProtectionServiceBean.deleteApplication(java.lang.String,java.lang.String), interface=Remote, requiredRoles=Roles(SystemAdministrator,Provisioner,)
10:39:06,679 TRACE [org.jboss.security.audit.providers.LogAuditProvider] [Success]Source=org.jboss.security.plugins.javaee.EJBAuthorizationHelper;Exception:=;Resource:=[org.jboss.security.authorization.resources.EJBResource:contextMap={policyRegistration=org.jboss.security.plugins.JBossPolicyRegistration@185c517}:method=public void com.mycom.services.ResourceProtectionServiceBean.deleteApplication(java.lang.String,java.lang.String):ejbMethodInterface=Remote:ejbName=ResourceProtectionServiceBean:ejbPrincipal=SystemAdministrator:MethodRoles=Roles(SystemAdministrator,Provisioner,):securityRoleReferences=null:callerSubject=Subject:
Principal: SystemAdministrator
Principal: Roles(members:SystemAdministrator)
:callerRunAs=null:callerRunAs=null:ejbRestrictionEnforcement=false:ejbVersion=null];policyRegistration=org.jboss.security.plugins.JBossPolicyRegistration@185c517;
10:39:06,679 INFO [STDOUT] auditEvent.auditLevel=SuccessauditEvent.underlyingException=nullauditEvent.contextMap[Source]=org.jboss.security.javaee.EJBAuthenticationHelperauditEvent.contextMap[principal]=SystemAdministratorauditEvent.contextMap[method]=deleteApplicationauditEvent.auditLevel=SuccessauditEvent.underlyingException=nullauditEvent.contextMap[Source]=org.jboss.security.plugins.javaee.EJBAuthorizationHelperauditEvent.contextMap[Exception:]=auditEvent.contextMap[Resource:]=[org.jboss.security.authorization.resources.EJBResource:contextMap={policyRegistration=org.jboss.security.plugins.JBossPolicyRegistration@185c517}:method=public void com.mycom.services.ResourceProtectionServiceBean.deleteApplication(java.lang.String,java.lang.String):ejbMethodInterface=Remote:ejbName=ResourceProtectionServiceBean:ejbPrincipal=SystemAdministrator:MethodRoles=Roles(SystemAdministrator,Provisioner,):securityRoleReferences=null:callerSubject=Subject:
10:39:06,679 INFO [STDOUT] Principal: SystemAdministrator
10:39:06,679 INFO [STDOUT] Principal: Roles(members:SystemAdministrator)
10:39:06,820 TRACE [org.jboss.web.tomcat.security.RunAsListener] Resteasy, runAs: null
10:39:06,820 TRACE [org.jboss.web.tomcat.security.RunAsListener] Resteasy, runAs: null
10:39:06,820 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:null
10:39:06,820 TRACE [org.jboss.security.SecurityRolesAssociation] Setting threadlocal:{}