How to enable trace logging for Mule Policies

To enable trace logging level on policies applied to a Mule Application the following procedure should be performed:

For Mule Applications deployed to CloudHub:

On the logging section of your application add the following logging level and package:

Mule 4:

TRACE org.mule.runtime.core.internal.policy

To enable Debug Logger levels in custom policies, please use:

DEBUG org.mule.runtime.core.internal.processor.LoggerMessageProcessor

[Note: Currently, the option of enabling TRACE level logging is not available for Cloudhub 2.0 and RTF in the Anypoint platform Runtime Manager UI.]

Mule 3: 

DEBUG com.mulesoft.module.policies

[Note: This package does not print the input and output of the policies.]

For Mule Applications deployed on-premises:

Add the following snippet to your Mule 4 Application's log4j2.xml file under the <Loggers> tab:

<AsyncLogger name="org.mule.runtime.core.internal.policy" level="TRACE" />

<AsyncLogger name="com.mulesoft.extension.policies" level="DEBUG"/>

Snippet for your Mule 3 Application's logger log4j2.xml file under the <Loggers> tab:

<AsyncLogger name="com.mulesoft.module.policies" level="DEBUG"/>

Sample Mule 4 Log for a request that was validated successfully using Client ID - Enforcement policy:
 

TRACE 2019-06-26 13:49:40,358 [http.listener.08 SelectorRunner] [event: 09e59b60-9832-11e9-9c30-f0189891604d] org.mule.runtime.core.internal.policy.CompositeSourcePolicy: Event Id: 63ea0a60-9832-11e9-9c30-f0189891604d.
Starting Policy analytics-policy-15711910-proxy
org.mule.extension.http.api.HttpRequestAttributes
{
   Request path=/proxy/greet
   Method=GET
   Listener path=/proxy/*
   Local Address=/127.0.0.1:8081
   Query String=****
   Relative Path=/proxy/greet
   Masked Request Path=/greet
   Remote Address=/127.0.0.1:51863
   Request Uri=/proxy/greet
   Scheme=http
   Version=HTTP/1.1
   Headers=[
      host=localhost:8081
      client_id=a906ef0ad6f6470fa956a5cef3d4324a
      client_secret=****
   ]
   Query Parameters=[
      client_id=a906ef0ad6f6470fa956a5cef3d4324a
      client_secret=****
   ]
   URI Parameters=[]
}
TRACE 2019-06-26 13:49:40,359 [http.listener.08 SelectorRunner] [event: 63ea0a60-9832-11e9-9c30-f0189891604d] org.mule.runtime.core.internal.policy.PolicyNextActionMessageProcessor: 
Event Id: 63ea0a60-9832-11e9-9c30-f0189891604d
Before execute-next.
Policy: analytics-policy-15711910-proxy
org.mule.extension.http.api.HttpRequestAttributes
{
   Request path=/proxy/greet
   Method=GET
   Listener path=/proxy/*
   Local Address=/127.0.0.1:8081
   Query String=****
   Relative Path=/proxy/greet
   Masked Request Path=/greet
   Remote Address=/127.0.0.1:51863
   Request Uri=/proxy/greet
   Scheme=http
   Version=HTTP/1.1
   Headers=[
      host=localhost:8081
      client_id=a906ef0ad6f6470fa956a5cef3d4324a
      client_secret=****
   ]
   Query Parameters=[
      client_id=a906ef0ad6f6470fa956a5cef3d4324a
      client_secret=****
   ]
   URI Parameters=[]
}
TRACE 2019-06-26 13:49:40,359 [http.listener.08 SelectorRunner] [event: 63ea0a60-9832-11e9-9c30-f0189891604d] org.mule.runtime.core.internal.policy.CompositeSourcePolicy: Event Id: 63ea0a60-9832-11e9-9c30-f0189891604d_935185858_1980926608_51433528.
Starting Policy client-id-enforcement-564286-proxy
org.mule.extension.http.api.HttpRequestAttributes
{
   Request path=/proxy/greet
   Method=GET
   Listener path=/proxy/*
   Local Address=/127.0.0.1:8081
   Query String=****
   Relative Path=/proxy/greet
   Masked Request Path=/greet
   Remote Address=/127.0.0.1:51863
   Request Uri=/proxy/greet
   Scheme=http
   Version=HTTP/1.1
   Headers=[
      host=localhost:8081
      client_id=a906ef0ad6f6470fa956a5cef3d4324a
      client_secret=****
   ]
   Query Parameters=[
      client_id=a906ef0ad6f6470fa956a5cef3d4324a
      client_secret=****
   ]
   URI Parameters=[]
}
TRACE 2019-06-26 13:49:40,360 [http.listener.08 SelectorRunner] [event: 63ea0a60-9832-11e9-9c30-f0189891604d] org.mule.runtime.core.internal.policy.PolicyNextActionMessageProcessor: 
Event Id: 63ea0a60-9832-11e9-9c30-f0189891604d
Before execute-next.
Policy: client-id-enforcement-564286-proxy
org.mule.extension.http.api.HttpRequestAttributes
{
   Request path=/proxy/greet
   Method=GET
   Listener path=/proxy/*
   Local Address=/127.0.0.1:8081
   Query String=****
   Relative Path=/proxy/greet
   Masked Request Path=/greet
   Remote Address=/127.0.0.1:51863
   Request Uri=/proxy/greet
   Scheme=http
   Version=HTTP/1.1
   Headers=[
      host=localhost:8081
      client_id=a906ef0ad6f6470fa956a5cef3d4324a
      client_secret=****
   ]
   Query Parameters=[
      client_id=a906ef0ad6f6470fa956a5cef3d4324a
      client_secret=****
   ]
   URI Parameters=[]
}
TRACE 2019-06-26 13:49:41,127 [[MuleRuntime].cpuLight.01: [sample_sofi2-v1-v1_15711910].proxy.CPU_LITE @48a9e30b] [event: 63ea0a60-9832-11e9-9c30-f0189891604d] org.mule.runtime.core.internal.policy.PolicyNextActionMessageProcessor: 
Event Id: 63ea0a60-9832-11e9-9c30-f0189891604d
After execute-next.
Policy: client-id-enforcement-564286-proxy
org.mule.extension.http.api.HttpResponseAttributes
{
   Status Code=200
   Reason Phrase=OK
   Headers=[
      date=Wed, 26 Jun 2019 16:49:41 GMT
      x-ratelimit-limit=480
      content-type=application/json
      x-ratelimit-reset=18539
      x-ratelimit-remaining=479
      strict-transport-security=max-age=31536000; includeSubDomains
   ]
}
TRACE 2019-06-26 13:49:41,127 [[MuleRuntime].cpuLight.01: [sample_sofi2-v1-v1_15711910].proxy.CPU_LITE @48a9e30b] [event: 63ea0a60-9832-11e9-9c30-f0189891604d] org.mule.runtime.core.internal.policy.CompositeSourcePolicy: Event Id: 63ea0a60-9832-11e9-9c30-f0189891604d_935185858_1980926608_51433528.
At the end of the Policy client-id-enforcement-564286-proxy
org.mule.extension.http.api.HttpResponseAttributes
{
   Status Code=200
   Reason Phrase=OK
   Headers=[
      date=Wed, 26 Jun 2019 16:49:41 GMT
      x-ratelimit-limit=480
      content-type=application/json
      x-ratelimit-reset=18539
      x-ratelimit-remaining=479
      strict-transport-security=max-age=31536000; includeSubDomains
   ]
}
TRACE 2019-06-26 13:49:41,127 [[MuleRuntime].cpuLight.01: [sample_sofi2-v1-v1_15711910].proxy.CPU_LITE @48a9e30b] [event: 63ea0a60-9832-11e9-9c30-f0189891604d] org.mule.runtime.core.internal.policy.PolicyNextActionMessageProcessor: 
Event Id: 63ea0a60-9832-11e9-9c30-f0189891604d
After execute-next.
Policy: analytics-policy-15711910-proxy
org.mule.extension.http.api.HttpResponseAttributes
{
   Status Code=200
   Reason Phrase=OK
   Headers=[
      date=Wed, 26 Jun 2019 16:49:41 GMT
      x-ratelimit-limit=480
      content-type=application/json
      x-ratelimit-reset=18539
      x-ratelimit-remaining=479
      strict-transport-security=max-age=31536000; includeSubDomains
   ]
}
TRACE 2019-06-26 13:49:41,127 [[MuleRuntime].cpuLight.01: [sample_sofi2-v1-v1_15711910].proxy.CPU_LITE @48a9e30b] [event: 63ea0a60-9832-11e9-9c30-f0189891604d] org.mule.runtime.core.internal.policy.CompositeSourcePolicy: Event Id: 63ea0a60-9832-11e9-9c30-f0189891604d.
At the end of the Policy analytics-policy-15711910-proxy
org.mule.extension.http.api.HttpResponseAttributes
{
   Status Code=200
   Reason Phrase=OK
   Headers=[
      date=Wed, 26 Jun 2019 16:49:41 GMT
      x-ratelimit-limit=480
      content-type=application/json
      x-ratelimit-reset=18539
      x-ratelimit-remaining=479
      strict-transport-security=max-age=31536000; includeSubDomains
   ]
}
TRACE 2019-06-26 13:49:41,127 [[MuleRuntime].cpuLight.01: [sample_sofi2-v1-v1_15711910].proxy.CPU_LITE @48a9e30b] [event: 63ea0a60-9832-11e9-9c30-f0189891604d] org.mule.runtime.core.internal.policy.CompositeSourcePolicy: Event id: 63ea0a60-9832-11e9-9c30-f0189891604d
Finished processing. 
org.mule.extension.http.api.HttpResponseAttributes
{
   Status Code=200
   Reason Phrase=OK
   Headers=[
      date=Wed, 26 Jun 2019 16:49:41 GMT
      x-ratelimit-limit=480
      content-type=application/json
      x-ratelimit-reset=18539
      x-ratelimit-remaining=479
      strict-transport-security=max-age=31536000; includeSubDomains
   ]
}