1 Reply Latest reply: May 26, 2011 9:39 AM by justincranford RSS

Missing AuditEvent from LogAuditProvider

justincranford Newbie

I 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:{}

  • 1. Re: Missing AuditEvent from LogAuditProvider
    justincranford Newbie

    I am getting LogAuditProvider messages for the web layer now. It turns out I was missing an entry in my deploy/properties-service.xml.

     

    ***************************************************

    <?xml version="1.0" encoding="UTF-8"?>
    <server>
      <mbean code="org.jboss.varia.property.SystemPropertiesService"
      name="jboss:type=Service,name=SystemProperties">
       <attribute name="Properties">JAVA_OPTS=%JAVA_OPTS% " -Dorg.jboss.security.web.audit=headers,cookies,parameter"</attribute>
      </mbean>
    </server>

    ***************************************************

     

    However, I still see a gap in web auditing. My client sends 3 requests to the server, but JBoss/PicketBox only logs the last two of them. The initial 302 redirect from HTTP to HTTPS is not recorded, even though the request it to a protected URI. That means a malicious client could flood the server with HTTP messages, getting back 302 redirect responses, but JBoss/PicketBox will not record any of them in the LogAuditProvider log.

     

     

    Here are my REST client and JBoss 6.0 server logs to illustrate the logging I get. All web auditing is enabled in properties-service.xml.

     

    -- Client-side requests/responses (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)

     

    -- Server-side messages for request/response 1 (Response was 302 redirect, but no LogAuditProvider messages???)

     

    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

     

    -- Server-side messages for request/response 2 (Response was 401 with authentication challenge, LogAuditProvider messages now present)

     

    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]
    TRACE [org.jboss.security.audit.providers.LogAuditProvider] [Success]Source=org.jboss.security.plugins.javaee.WebAuthorizationHelper;Exception:=;userDataPermissionCheck=true;securityConstraints=SecurityConstraint[Resteasy];Resource:=[org.jboss.security.authorization.resources.WebResource:contextMap={userDataPermissionCheck=true, securityConstraints=[Lorg.apache.catalina.deploy.SecurityConstraint;@1c2fc59, policyRegistration=org.jboss.security.plugins.JBossPolicyRegistration@830cbb},canonicalRequestURI=null,request=[/RestWeb1],CodeSource=null];policyRegistration=org.jboss.security.plugins.JBossPolicyRegistration@830cbb;
    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

     

    -- Server-side messages for request/response 3 (Response was 404 - URL not found, LogAuditProvider messages now present)

     

    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]
    TRACE [org.jboss.security.audit.providers.LogAuditProvider] [Success]Source=org.jboss.security.plugins.javaee.WebAuthorizationHelper;Exception:=;userDataPermissionCheck=true;securityConstraints=SecurityConstraint[Resteasy];Resource:=[org.jboss.security.authorization.resources.WebResource:contextMap={userDataPermissionCheck=true, securityConstraints=[Lorg.apache.catalina.deploy.SecurityConstraint;@1bc21b2, policyRegistration=org.jboss.security.plugins.JBossPolicyRegistration@830cbb},canonicalRequestURI=null,request=[/RestWeb1],CodeSource=null];policyRegistration=org.jboss.security.plugins.JBossPolicyRegistration@830cbb;
    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.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
    TRACE [org.jboss.security.audit.providers.LogAuditProvider] [Success]Source=org.jboss.web.tomcat.security.JBossWebRealm;CallerPrincipal=SystemAdministrator;principal=GenericPrincipal[SystemAdministrator(SystemAdministrator,)];request=[/RestWeb1:cookies=null:headers=cache-control=no-cache,host=localhost:8443,connection=Keep-Alive,user-agent=Apache-HttpClient/4.0.x (Java 6u24),authorization=][parameters=][attributes=javax.servlet.request.ssl_session=4dde512024314df813b51b3a53db26ce21b45b8f747e5dfd15443cf69adb08c4,javax.servlet.request.key_size=128,javax.servlet.request.cipher_suite=SSL_RSA_WITH_RC4_128_MD5,];
    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.audit.providers.LogAuditProvider] [Success]Source=org.jboss.security.plugins.javaee.WebAuthorizationHelper;roleRefPermissionCheck=true;principal.roles=SystemAdministrator;Exception:=;roleName=SystemAdministrator;Resource:=[org.jboss.security.authorization.resources.WebResource:contextMap={roleRefPermissionCheck=true, principal.roles=[SystemAdministrator], roleName=SystemAdministrator, policyRegistration=org.jboss.security.plugins.JBossPolicyRegistration@830cbb},canonicalRequestURI=null,request= ,CodeSource=null];policyRegistration=org.jboss.security.plugins.JBossPolicyRegistration@830cbb;
    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.audit.providers.LogAuditProvider] [Success]Source=org.jboss.security.plugins.javaee.WebAuthorizationHelper;resourcePermissionCheck=true;Exception:=;securityConstraints=SecurityConstraint[Resteasy];Resource:=[org.jboss.security.authorization.resources.WebResource:contextMap={resourcePermissionCheck=true, securityConstraints=[Lorg.apache.catalina.deploy.SecurityConstraint;@1bc21b2, policyRegistration=org.jboss.security.plugins.JBossPolicyRegistration@830cbb},canonicalRequestURI=/CustomerName/ApplicationName/UserName,request=[/RestWeb1],CodeSource=null];policyRegistration=org.jboss.security.plugins.JBossPolicyRegistration@830cbb;
    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.ResourceProtectionRestApplication
    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) [:6.0.0.Final]
    at org.jboss.resteasy.core.registry.RootSegment.matchChildren(RootSegment.java:339) [:6.0.0.Final]
    at org.jboss.resteasy.core.registry.RootSegment.matchRoot(RootSegment.java:374) [:6.0.0.Final]
    at org.jboss.resteasy.core.registry.RootSegment.matchRoot(RootSegment.java:367) [:6.0.0.Final]
    at org.jboss.resteasy.core.ResourceMethodRegistry.getResourceInvoker(ResourceMethodRegistry.java:251) [:6.0.0.Final]
    at org.jboss.resteasy.core.SynchronousDispatcher.getInvoker(SynchronousDispatcher.java:157) [:6.0.0.Final]
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:118) [:6.0.0.Final]
    at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:207) [:6.0.0.Final]
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55) [:6.0.0.Final]
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50) [: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