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

    Missing AuditEvent from LogAuditProvider

    justincranford

      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

          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