Audit logger org.alfresco.repo.audit.inbound fails to log inbound auditable values

Summary

With just audit.enabled=true, and no audit application (ex. audit.alfresco-access) enabled, you can log the available inbound audit methods/values.

This allows you to determine what inbound audit values are 'available' (not actually recorded without a audit application defining it to record) to create an audit application against.

This is not working in v4.2.N, v5.0.N versions.

Replication Steps

• Install and startup Alfresco One v4.2.5 (or v5.0.3)
• Using jconsole check the configurations under: MBeans (tab) > Alfresco > Configuration > Audit > Attributes. By default you should only see:

audit.alfresco-access.enabled=false
audit.cmischangelog.enabled=false
audit.enable=true
audit.sync.enabled=true
audit.tagging.enabled=true

• set the following logger to debug in jconsole "org.alfresco.repo.audit.inbound"
• monitor catalina.out log
• do anything on share ui from logging in to any action at all, example login

  2016-05-09 12:56:42,855  DEBUG [repo.audit.inbound] [http-8080-7] 
  Inbound audit values:
  	/alfresco-api/pre/AuthenticationService/authenticateAsGuest/args=null
   2016-05-09 12:56:42,863  DEBUG [repo.audit.inbound] [http-8080-7] 
  Inbound audit values:
  	/alfresco-api/post/AuthenticationService/authenticateAsGuest/args=null
  	/alfresco-api/post/AuthenticationService/authenticateAsGuest/no-error=null
   2016-05-09 12:56:42,886  DEBUG [repo.audit.inbound] [http-8080-7] 
  Inbound audit values:
  	/alfresco-api/pre/RepoAdminService/getRestrictions/args=null
   2016-05-09 12:56:42,886  DEBUG [repo.audit.inbound] [http-8080-7] 
  Inbound audit values:
  	/alfresco-api/post/RepoAdminService/getRestrictions/args=null
  	/alfresco-api/post/RepoAdminService/getRestrictions/no-error=null
   2016-05-09 12:56:42,907  INFO  [web.site.EditionInterceptor] [http-8080-1] Successfully retrieved license information from Alfresco.
   2016-05-09 12:56:43,016  DEBUG [repo.audit.inbound] [http-8080-7] 
  Inbound audit values:
  	/alfresco-api/pre/FileFolderService/resolveNamePath/args/rootNodeRef=workspace://SpacesStore/8cd7bf99-2880-4264-94b1-19d2de2c9030
  	/alfresco-api/pre/FileFolderService/resolveNamePath/args/pathElements=[configurations, slingshot.site.configuration.xml]
   2016-05-09 12:56:43,021  DEBUG [repo.audit.inbound] [defaultThreadPool1] 
  Inbound audit values:
  	/alfresco-api/post/FileFolderService/resolveNamePath/error=Folder not found:  
     Started at: 
        org.alfresco.repo.model.filefolder.FileFolderServiceImpl.resolveNamePath(FileFolderServiceImpl.java:1462)
        org.alfresco.repo.model.filefolder.FileFolderServiceImpl.resolveNamePath(FileFolderServiceImpl.java:1441)
        sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        java.lang.reflect.Method.invoke(Method.java:606)
        org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
        org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        org.alfresco.repo.model.ml.MLContentInterceptor.invoke(MLContentInterceptor.java:125)
        org.springframework.aop.framework.Reflec
  	/alfresco-api/post/FileFolderService/resolveNamePath/args/rootNodeRef=workspace://SpacesStore/8cd7bf99-2880-4264-94b1-19d2de2c9030
  	/alfresco-api/post/FileFolderService/resolveNamePath/args/pathElements=[configurations, slingshot.site.configuration.xml]
   2016-05-09 12:56:43,025  DEBUG [repo.audit.inbound] [http-8080-7] 
  Inbound audit values:
  	/alfresco-api/pre/FileFolderService/resolveNamePath/args/rootNodeRef=workspace://SpacesStore/8cd7bf99-2880-4264-94b1-19d2de2c9030
  	/alfresco-api/pre/FileFolderService/resolveNamePath/args/pathElements=[pages, site-index.xml]
  
  . . .
  
   2016-05-09 12:57:09,705  DEBUG [repo.audit.inbound] [http-8080-8] 
  Inbound audit values:
  	/alfresco-api/post/NodeService/getProperties/no-error=null
  	/alfresco-api/post/NodeService/getProperties/args/nodeRef=workspace://SpacesStore/53223edb-476a-499c-b5cd-bbd326585268
  	/alfresco-api/post/NodeService/getProperties/result={{http://www.alfresco.org/model/content/1.0}name=53223edb-476a-499c-b5cd-bbd326585268, {http://www.alfresco.org/model/system/1.0}node-dbid=29, {http://www.alfresco.org/model/content/1.0}organizationId=, {http://www.alfresco.org/model/content/1.0}email=admin@alfresco.com, {http://www.alfresco.org/model/system/1.0}store-identifier=SpacesStore, {http://www.alfresco.org/model/system/1.0}locale=en_US, {http://www.alfresco.org/model/content/1.0}homeFolderProvider=bootstrapHomeFolderProvider, {http://www.alfresco.org/model/content/1.0}sizeCurrent=null, {http://www.alfresco.org/model/content/1.0}userName=admin, {http://www.alfresco.org/model/content/1.0}owner=admin, {http://www.alfresco.org/model/system/1.0}node-uuid=53223edb-476a-499c-b5cd-bbd326585268, {http://www.alfresco.org/model/content/1.0}lastName=, {http://www.alfresco.org/model/system/1.0}store-protocol=workspace, {http://www.alfresco.org/model/content/1.0}firstName=Administrator, {http://www.alfresco.org/model/content/1.0}homeFolder=workspace://SpacesStore/326e347d-9fa8-4445-b21f-e784e6af9619}
   2016-05-09 12:57:09,706  DEBUG [repo.audit.inbound] [http-8080-8] 
  Inbound audit values:
  	/alfresco-api/pre/PersonService/getPerson/args/userName=admin
   2016-05-09 12:57:09,706  DEBUG [repo.audit.inbound] [http-8080-8] 
  Inbound audit values:
  	/alfresco-api/post/PersonService/getPerson/no-error=null
  	/alfresco-api/post/PersonService/getPerson/result=workspace://SpacesStore/53223edb-476a-499c-b5cd-bbd326585268
  	/alfresco-api/post/PersonService/getPerson/args/userName=admin
   2016-05-09 12:57:09,706  DEBUG [repo.audit.inbound] [http-8080-8] 
  Inbound audit values:
  	/alfresco-api/pre/NodeService/hasAspect/args/nodeRef=workspace://SpacesStore/53223edb-476a-499c-b5cd-bbd326585268
  	/alfresco-api/pre/NodeService/hasAspect/args/aspectTypeQName={http://www.alfresco.org/model/content/1.0}preferences
   2016-05-09 12:57:09,707  DEBUG [repo.audit.inbound] [http-8080-8] 
  Inbound audit values:
  	/alfresco-api/post/NodeService/hasAspect/args/aspectTypeQName={http://www.alfresco.org/model/content/1.0}preferences
  	/alfresco-api/post/NodeService/hasAspect/no-error=null
  	/alfresco-api/post/NodeService/hasAspect/args/nodeRef=workspace://SpacesStore/53223edb-476a-499c-b5cd-bbd326585268
  	/alfresco-api/post/NodeService/hasAspect/result=false
   2016-05-09 12:57:09,707  DEBUG [repo.audit.inbound] [http-8080-8] 
  Inbound audit values:
  	/alfresco-api/pre/PersonService/getPerson/args/userName=admin
   2016-05-09 12:57:09,708  DEBUG [repo.audit.inbound] [http-8080-8] 
  Inbound audit values:
  	/alfresco-api/post/PersonService/getPerson/no-error=null
  	/alfresco-api/post/PersonService/getPerson/result=workspace://SpacesStore/53223edb-476a-499c-b5cd-bbd326585268
  	/alfresco-api/post/PersonService/getPerson/args/userName=admin
   2016-05-09 12:57:09,708  DEBUG [repo.audit.inbound] [http-8080-8] 
  Inbound audit values:
  	/alfresco-api/pre/NodeService/hasAspect/args/nodeRef=workspace://SpacesStore/53223edb-476a-499c-b5cd-bbd326585268
  	/alfresco-api/pre/NodeService/hasAspect/args/aspectTypeQName={http://www.alfresco.org/model/content/1.0}preferences
   2016-05-09 12:57:09,708  DEBUG [repo.audit.inbound] [http-8080-8] 
  Inbound audit values:
  	/alfresco-api/post/NodeService/hasAspect/args/aspectTypeQName={http://www.alfresco.org/model/content/1.0}preferences
  	/alfresco-api/post/NodeService/hasAspect/no-error=null
  	/alfresco-api/post/NodeService/hasAspect/args/nodeRef=workspace://SpacesStore/53223edb-476a-499c-b5cd-bbd326585268
  	/alfresco-api/post/NodeService/hasAspect/result=false
   2016-05-09 12:57:09,715  DEBUG [repo.audit.inbound] [http-8080-8] 
  Inbound audit values:
  	/alfresco-api/pre/SearchService/query/args=null
   2016-05-09 12:57:09,805  DEBUG [repo.audit.inbound] [http-8080-9] 
  Inbound audit values:
  	/alfresco-api/pre/AuthenticationService/validate/args=null
   2016-05-09 12:57:09,805  DEBUG [repo.audit.inbound] [http-8080-9] 
  Inbound audit values:
  	/alfresco-api/post/AuthenticationService/validate/args=null
  	/alfresco-api/post/AuthenticationService/validate/no-error=null
   2016-05-09 12:57:09,806  DEBUG [repo.audit.inbound] [http-8080-9] 
  Inbound audit values:
  	/alfresco-api/pre/AuthorityService/isGuestAuthority/args/authorityName=admin
   2016-05-09 12:57:09,807  DEBUG [repo.audit.inbound] [http-8080-9] 
  Inbound audit values:
  	/alfresco-api/post/AuthorityService/isGuestAuthority/no-error=null
  	/alfresco-api/post/AuthorityService/isGuestAuthority/args/authorityName=admin
  	/alfresco-api/post/AuthorityService/isGuestAuthority/result=false
   2016-05-09 12:57:09,814  DEBUG [repo.audit.inbound] [http-8080-9] 
  Inbound audit values:
  	/alfresco-api/pre/AuthorityService/isAdminAuthority/args/authorityName=admin
   2016-05-09 12:57:09,815  DEBUG [repo.audit.inbound] [http-8080-9] 
  Inbound audit values:
  	/alfresco-api/post/AuthorityService/isAdminAuthority/no-error=null
  	/alfresco-api/post/AuthorityService/isAdminAuthority/args/authorityName=admin
  	/alfresco-api/post/AuthorityService/isAdminAuthority/result=true
   2016-05-09 12:57:09,826  DEBUG [repo.audit.inbound] [http-8080-9] 
  Inbound audit values:
  	/alfresco-api/pre/AuthenticationService/validate/args=null
   2016-05-09 12:57:09,826  DEBUG [repo.audit.inbound] [http-8080-9] 
  Inbound audit values:
  	/alfresco-api/post/AuthenticationService/validate/args=null
  	/alfresco-api/post/AuthenticationService/validate/no-error=null
   2016-05-09 12:57:09,827  DEBUG [repo.audit.inbound] [http-8080-9] 
  Inbound audit values:
  	/alfresco-api/pre/AuthorityService/isGuestAuthority/args/authorityName=admin
   2016-05-09 12:57:09,828  DEBUG [repo.audit.inbound] [http-8080-9] 
  Inbound audit values:
  	/alfresco-api/post/AuthorityService/isGuestAuthority/no-error=null
  	/alfresco-api/post/AuthorityService/isGuestAuthority/args/authorityName=admin
  	/alfresco-api/post/AuthorityService/isGuestAuthority/result=false
   2016-05-09 12:57:09,832  DEBUG [repo.audit.inbound] [http-8080-9] 
  Inbound audit values:
  	/alfresco-api/pre/NodeService/getProperties/args/nodeRef=workspace://SpacesStore/53223edb-476a-499c-b5cd-bbd326585268
   2016-05-09 12:57:09,832  DEBUG [repo.audit.inbound] [http-8080-9] 
  Inbound audit values:
  	/alfresco-api/post/NodeService/getProperties/no-error=null
  	/alfresco-api/post/NodeService/getProperties/args/nodeRef=workspace://SpacesStore/53223edb-476a-499c-b5cd-bbd326585268
  	/alfresco-api/post/NodeService/getProperties/result={{http://www.alfresco.org/model/content/1.0}name=53223edb-476a-499c-b5cd-bbd326585268, {http://www.alfresco.org/model/system/1.0}node-dbid=29, {http://www.alfresco.org/model/content/1.0}organizationId=, {http://www.alfresco.org/model/content/1.0}email=admin@alfresco.com, {http://www.alfresco.org/model/system/1.0}store-identifier=SpacesStore, {http://www.alfresco.org/model/system/1.0}locale=en_US, {http://www.alfresco.org/model/content/1.0}homeFolderProvider=bootstrapHomeFolderProvider, {http://www.alfresco.org/model/content/1.0}sizeCurrent=null, {http://www.alfresco.org/model/content/1.0}userName=admin, {http://www.alfresco.org/model/content/1.0}owner=admin, {http://www.alfresco.org/model/system/1.0}node-uuid=53223edb-476a-499c-b5cd-bbd326585268, {http://www.alfresco.org/model/content/1.0}lastName=, {http://www.alfresco.org/model/system/1.0}store-protocol=workspace, {http://www.alfresco.org/model/content/1.0}firstName=Administrator, {http://www.alfresco.org/model/content/1.0}homeFolder=workspace://SpacesStore/326e347d-9fa8-4445-b21f-e784e6af9619}
   2016-05-09 12:57:10,043  DEBUG [repo.audit.inbound] [http-8080-8] 
  Inbound audit values:
  	/alfresco-api/post/SearchService/query/args=null
  	/alfresco-api/post/SearchService/query/no-error=null
  

Expected Behaviour

• when setting org.alfresco.repo.audit.inbound=debug, you should see all the auditable method calls generate in the logs, regardless of any audit applications being enabled.

Actual Behaviour

• when setting the org.alfresco.repo.audit.inbound=debug, you do not see any logging of auditable method calls generated in the logs, you must enable audit.alfresco-access.enabled=true (the ootb audit application) to get inbound logging generates

Additional Information

• Tested on v4.2.5, v5.0.3 Alfresco One in comparison to v4.1.5 Alfresco One, sometime since v4.1 SP this is no longer logging as needed.
• Without this logging you must enable an audit application ex. (aflresco-access) and you will only see the audited and recorded data for what is defined in that application

This logger was extremely helpful when defining a custom audit application to fit your needs and when debugging auditing issues.
Full example of what would normally log on a login action in the UI is attached.