Skip to content

Dynamic Log Levels

Jump to bottom
Karsten Schnitter edited this page Jan 15, 2021 · 10 revisions

Dynamic Log Levels

Dynamic Log Levels enable application developers to change the log level during the runtime of the application without restart. In very general terms this means the enforcement of some policy containing:

  • the condition of the change (e.g. a time, user or tenant id)
  • the property of the change (e.g. new log level and package)

Modelling the condition can be very application specific. You might want to change the log level for a very specific user or tenant of the application, a single request or for a certain period of time. Depending on the reasons checking for the condition needs tight integration with the application data models. Therefore the dynamic log level support by this library focusses on the enforcement of the change.

Introduction to Dynamic Log Levels by HTTP Headers

cf-java-logging-support supports setting a specific log level for each HTTP request by inspecting a JWT inside a request header. This feature allows to understand misbehavior of a live-system in detail for a specific request, without flooding the system with an enormous number of DEBUG level log messages emitted during the processing of all other requests. This approach has the advantage that no unnecessary log messages need to be processed and stored. To avoid abuse of this feature, the dynamic log level has to be provided within an RSA-signed JWT token that also contains an expiry date.

Using HTTP headers sets the minimal scope for dynamically changed log levels to the handling of that particular request. This is a very fine-grained slice of the application. The used JWT communicates the log policy decision to cf-java-logging-support for enforcement. Application developers need to provide components to there solution, that can generate the required tokens or enhance tokens already in use by additional claims for dynamic log levels. It is possible to extend existing OAuth tokens to contain the required claims (c.f. Usage). Tokens can also be inserted by service proxies (e.g. CF Route Services), API gateways or service meshes.

One mayor benefit of the approach is, that the JWTs can be forwarded to outgoing requests. When upstream services also use cf-java-logging-support, this allows a very convenient dynamic log level instrumentation across multiple services. Note, that you need to use the same RSA key for verification in all services.

Internally, the dynamic log level support has two components:

  • a servlet filter to extract and verify the JWT claims
  • log backend specific filters to apply the dynamic configurations

The extracted configuration is communicated via the MDC between the two components. This allows the following extensions:

  • custom implementations of the JWT filtering
  • custom acquisition on log configuration writing to MDC

See Extending Dynamic Log Levels for details.

App-Configuration

Dynamic Log Levels easy to use and requires only little extra configuration of the application. It is available with version 2.1.1 of the cf-java-logging-support or higher. There are two parts, that need configuration:

  • the request instrumentation to access the JWT headers
  • the logging backend specific filter to apply the log level

In version 3.2.0 new backend filters were introduced to limit packages or classes, that should log at a different level.

Request Instrumentation Configuration

Dynamic Log Levels are controlled by an HTTP header containing a JWT. These headers are processed by the DynamicLogLevelFilter, which is included the RequestLoggingFilter. You need to configure one of those filtes as described in Instrumenting Servlets. The instrumentation is further controlled by two environment variables:

  • DYN_LOG_HEADER: a specific header name for the log level token can be defined here. If not specified, the default value (SAP-LOG-LEVEL) is used.

  • DYN_LOG_LEVEL_KEY: a public key which can be used to verify the JWT tokens that contain the dynamic log level.

There are several possibilities to extend those configuration options and provide custom features on top of the default request implementation. See section Extending Dynamic Log Levels for details.

Log Event Filter Configuration

The actual processing of dynamic log levels is done by filters provided for the two supported logging backendds log4j2 and logback. There configuration is specific to those libraries.

Logback Specific Configuration

Filtering log events for dynamic log levels is implemented with Turbofilters. In version 3.2.0 a new filter was added, that allows specification of the classes and packages to filter on. The old filter was kept for compatibility.

Filtering with Package Support

Filtering with package support will only emit log messages with a log level allowed by the JWT token, if the originating class is in one of the packages specified in the JWT token. All other messages will be subjected to the statically declared rules of the configuration file. In the logback.xml file, add the following turbo filter:

<turboFilter class="com.sap.hcp.cf.logback.filter.DynamicLevelPrefixLoggerTurboFilter" />
Filtering without Package Support (Legacy approach)

This is the old filter, that was introduced in version 2.1.1. It will filter all messages for the log level allowed by the JWT token. However, it will reject all messages not allowed by the token. In the logback.xml file, add the following turbo filter:

<turboFilter class="com.sap.hcp.cf.logback.filter.CustomLoggingTurboFilter" />

Log4j2 Specific Configuration

Filtering log events for dynamic log levels is implemented with Filters. In version 3.2.0 a new filter was added, that allows specification of the classes and packages to filter on. The old filter was kept for compatibility.

Filtering with Package Support

Filtering with package support will only emit log messages with a log level allowed by the JWT token, if the originating class is in one of the packages specified in the JWT token. All other messages will be subjected to the statically declared rules of the configuration file. In the log4j2 file, add the following filter:

<DynamicLevelPrefixLoggerFilter />
Filtering without Package Support (Legacy approach)

This is the old filter, that was introduced in version 2.1.1. It will filter all messages for the log level allowed by the JWT token. However, it will reject all messages not allowed by the token. In the log4j2.xml file, add the following filter:

<DynamicThresholdFilter key="dynamic_log_level"
    defaultThreshold="ERROR" onMatch="ACCEPT" onMismatch="DENY">
    <KeyValuePair key="TRACE" value="TRACE" />
    <KeyValuePair key="DEBUG" value="DEBUG" />
    <KeyValuePair key="INFO" value="INFO" />
    <KeyValuePair key="WARN" value="WARN" />
    <KeyValuePair key="ERROR" value="ERROR" />
</DynamicThresholdFilter>

Usage

To set log levels dynamically an HTTP header with an appropiate JWT content is required. This section explains how that JWT should be constructed.

What should a valid token look like

A valid JWT token should be signed with RSA256. Its payload should contain the email of the issuer, the desired log-level, a timestamp for the time at which the token has been generated and a timestamp that represents the expiry date. If you are using the new filters introduced in version 3.2.0, you must add a list of comma-separated packages, the filtering applies to.

Header

{
  "alg": "RS256",
  "typ": "JWT"
}

Payload

{
  "issuer": "<valid e-mail address>",
  "level": "TRACE",
  "packages": "com.sap.hcp.cf.logging.servlet.filter,com.sap.hcp.cf.logging.common",
  "iat": 1506016127,
  "exp": 1506188927
}

The Java class TokenCreator can be used to create valid tokens. It can be run as a Java application after you adapted some constants to your requirements.

Extending Dynamic Log Levels

The overall flow of a dynamic log level change is a follows:

  1. A JWT header of an incoming request is extracted by the DynamicLogLevelFilter.
  2. The JWT is handed over to the DynamicLogLevelProcessor for validation and parsing. Desired log level and packages are extracted.
  3. The log level and packages are written into the two MDC fields dynamic_log_level and dynamic_log_level_prefixes.
  4. When a log event is generated, the logging backend filters check for the MDC fields and apply the contained information as described in section Log Event Filter Configuration.

The first two steps can be customized by extending the classes of this library. Using the MDC fields defined in DynamicLogLevelHelper allows addition of completely custom implementations of either steps 1+2 or filtering in step 4.

Extending JWT Processing

Extraction and Processing of the dynamic log level JWT is controlled by two classes/interfaces:

If you want to customize the JWT processing, e.g. by additional validations, subclass the DynamicLogLevelProcessor and override processJWT(DecodedJWT jwt) according to your requirements.

If you want to provide the RSA key in a different way then by environment variable or change the name of the HTTP to be used, you need to provide your own implementation of DynamicLogLevelConfiguration.

Once you have done your own implementation of DynamicLogLevelProcessor or DynamicLogLevelConfiguration, you need to inject them into the DynamicLogLevelFilter. There are two ways of doing that:

  1. Use one of the constructors to supply a ConcurrentInitializer of your processor or configuration.There are two constructors one for only the configuration and one for both processor and configuration.
  2. Subclass the filter and override getConfiguration() or getProcessor() depending on your needs.

It is depending on your servlet configuration which of these two apporaches is viable. With static configuration, e.g. web.xml only the second approach is possible. If you use a custom processor or filter you need to manually configure all servlet filters and cannot use the default RequestLoggingFilter. See the default implementations on how to do that.

Example Using the Sample App

Our sample app can provide an example for the Dynamic Log Levels with the JWT token. The logging configuration of this app is already complete, but the manifest is missing the DYN_LOG_LEVEL_KEY entry. For testing purposes just execute the TokenCreator. You can customise its output by changing the variables as documented. If you leave everything as is you will get an output like this:

You successfully created a dynamic log level token with log level TRACE!

Your private key is:
MIIEvQIBADANBgkqhkiG9w0BAQEFAASCBKcwggSjAgEAAoIBAQCAtT0LL5QNZOy3dV0vB4KRqUec7o8UqOMgKa3O6gCz85qtKV98icN6gG0vgzIYvYwJI/MpHSbRke93YcaYiaYETl0XngxB/05BwW9NsGkdtnpKWJPC4gH8PULCMEJoAjsuueSo6xY7LBL/eZEZ0tI7Djf5hrE/IzXbn1DgXfIvHHeG4nfZN+DwBEjJGuGi9I2ojDYuKD7FieWUnBbODgbjTiWEbmfASGU0uvks9ZEp/QqFTlbL9ZP0GeYcoI4BUa/4dwBJLDo963OYOuCTuMQonTv5Tfty6lv/kjqW1JTUI/Ai3FmngrjeFlkH2BTueb0Kfp+ijXGZBaYCU2J533X/AgMBAAECggEAZOk0VivUgXfqnKA5EiFqPrghPKpRphoQEWx8KGmRaYWKdU+l3OfKSqacdI8BXSJnw9ba1BZWFCO+Q7R2V6w8bM3f8R9qbugzvBxkHt48XB5w3Q97smUut0x0pfneZtuw+R6oZ8QBpx0UPBddK4j+aWzpeAshtuXtWScc6vzdYA9oZhvt70Lu8cBDRx9OHoY8QQLM2lLxiMI4QCCs59ICRvrGRClNfFQZEeM/2G7ZaJfSrQmrDYl57XRQdji6UgzzdfzQiev2poZAPyzxuA8XzX7R/13q9vITYqISMpjyRtNQbRubtW+kvgdXMWSDJQ4+Y7fXPVAwBlDTCC1PJ5w40QKBgQDdZzg/Jgpeaz5DCv7Kaf4X1k6UctLz97IFR5+3cuipk2rxnsj99mnD31AH45JufgwsalN3FqZPs6qC/pJlAHvEVpiqUZ3nqNW745C0HxtzAh9gmnsS0r+wri6/TnXW978zm9fN+MAPkF6aaxDG0G6XDKFqy5LOO/YYlxEcaoqGBwKBgQCU0e+kpKU3SLywzeU4esA10uIYOP67d8bxEGcZ0S30DGDoPibm9UBtvPdOonXdQe27gn5HW1QfNuSbzp5IRxAx0Rad9L5VR8Bxi1s/DI6woZLW5oOpCJuxjpzMLNuSM/4RMA2shmmwPtNYRkd4KMStlQwtwRrn9z7To1OnpsdSSQKBgB3R+D5xJjZfZWxsP7MNoZ6eS8ksygL4Gq8hXX686F9mrqHKjDHAjbBHFKVrXl6pdYRJ8eH5V/8mKNIp7ZfS/9iK/Vb7VTRNhjQfS28nPXA5GfbN98OqRQ1L+JnlvHNuvP77f46LcXrnLAbKYuEUU8Def6M9thE2/EeFmVVleDDjAoGAKNZzLHsB22naXaoifJ0yoZJ8+KirPkZgEUavBCaitZWwAgsMIdSrGXIBa1KphU3SLuJgRLSLIQWvNhI83RijGQiHbFD86eoGpSHYqDSJ825jHRWki34RO2gnHuAwYK5jydOl7PH1jqeu10px0kddsUR1UxjqiT0PwIPRMPBTQgECgYEAibPoDNWCsDIqkH18LTJwyB1KpeO7ZD3HNEoeZFBdIFPUboxqka/qlmueXAGguQEvBOYmSZc4EzZSmlH7XUvMVlnOWHl3Y1USbEWO3gjGPkFDsdSL1dy2+0qgVi1FZPWGzb0sJImi1Dhofyhfaf9F8Kp44Ap9v4zZrlaFhltdqnU=
Your public key is:
MIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAgLU9Cy+UDWTst3VdLweCkalHnO6PFKjjICmtzuoAs/OarSlffInDeoBtL4MyGL2MCSPzKR0m0ZHvd2HGmImmBE5dF54MQf9OQcFvTbBpHbZ6SliTwuIB/D1CwjBCaAI7LrnkqOsWOywS/3mRGdLSOw43+YaxPyM1259Q4F3yLxx3huJ32Tfg8ARIyRrhovSNqIw2Lig+xYnllJwWzg4G404lhG5nwEhlNLr5LPWRKf0KhU5Wy/WT9BnmHKCOAVGv+HcASSw6PetzmDrgk7jEKJ07+U37cupb/5I6ltSU1CPwItxZp4K43hZZB9gU7nm9Cn6foo1xmQWmAlNied91/wIDAQAB
Your JWT token with log level TRACE is:
eyJ0eXAiOiJKV1QiLCJhbGciOiJSUzI1NiJ9.eyJsZXZlbCI6IlRSQUNFIiwiaXNzIjoiZmlyc3RuYW1lLmxhc3RuYW1lQHNhcC5jb20iLCJleHAiOjE1OTMyNTY2OTcsImlhdCI6MTU5MzA4Mzg5N30.Yw-UwhhR1uMMmi6j4ReaFohTiKiSV_H_TPFUFMnwDbV9AUyyrGNKnsnY5YF8Rem3Wh8HHQYFI5gf11yn1A0uve3wRsxyq0TWLJ7ptbPDpG6LWSGrUFfF3YiKXt91mkL9GtUMYGUuj0Kji7W4zPBBOePYapurKr00IGg8La6cT4R5HKxhNSobjFzxGGRH_qlzdwFHM_Jsp3XIDBPMGYqtTVyt0nqqLExJAsU0S6Oew8tptNIJcSSFjF1NS8VhlYs198s_dj-7ntcM3jy3EzvqtQv8TNDo7sA7bFJ_he9lktmDdjPQ2gt2gyJAx-sUswcS5qvFY6JpXd74Xl-PbsT9sA

Please copy and save token and keys for later usage. The JWT token can now be written
to an HTTP header in order to change the corresponding request's log level to TRACE
For token validation, the public key must be added to the environment of the application.
In order to generate a new token with specific keys, the variables privateKey and publicKey
can be instantiated with these keys

Take the public key and add it as DYN_LOG_LEVEL_KEY to the manifest.yml. The whole file should look like this:

---
applications:
#
# You may want/need to change these to avoid naming conflicts
#
- name: logging-sample-app
  instances: 1
  path: target/logging-sample-app-3.0.9.war
  env:
    RANDOM_SLEEP: true
# Set LOG_*: true to activate logging of respective field
    LOG_SENSITIVE_CONNECTION_DATA: false
    LOG_REMOTE_USER: false
    LOG_REFERER: false
    DYN_LOG_LEVEL_KEY: MIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAgLU9Cy+UDWTst3VdLweCkalHnO6PFKjjICmtzuoAs/OarSlffInDeoBtL4MyGL2MCSPzKR0m0ZHvd2HGmImmBE5dF54MQf9OQcFvTbBpHbZ6SliTwuIB/D1CwjBCaAI7LrnkqOsWOywS/3mRGdLSOw43+YaxPyM1259Q4F3yLxx3huJ32Tfg8ARIyRrhovSNqIw2Lig+xYnllJwWzg4G404lhG5nwEhlNLr5LPWRKf0KhU5Wy/WT9BnmHKCOAVGv+HcASSw6PetzmDrgk7jEKJ07+U37cupb/5I6ltSU1CPwItxZp4K43hZZB9gU7nm9Cn6foo1xmQWmAlNied91/wIDAQAB

You can now call the app while specifying the JWT token as HTTP header:

curl -k https://logging-sample-app.<your-cf-domain> -H "SAP-LOG-LEVEL: eyJ0eXAiOiJKV1QiLCJhbGciOiJSUzI1NiJ9.eyJsZXZlbCI6IlRSQUNFIiwiaXNzIjoiZmlyc3RuYW1lLmxhc3RuYW1lQHNhcC5jb20iLCJleHAiOjE1OTMyNTY2OTcsImlhdCI6MTU5MzA4Mzg5N30.Yw-UwhhR1uMMmi6j4ReaFohTiKiSV_H_TPFUFMnwDbV9AUyyrGNKnsnY5YF8Rem3Wh8HHQYFI5gf11yn1A0uve3wRsxyq0TWLJ7ptbPDpG6LWSGrUFfF3YiKXt91mkL9GtUMYGUuj0Kji7W4zPBBOePYapurKr00IGg8La6cT4R5HKxhNSobjFzxGGRH_qlzdwFHM_Jsp3XIDBPMGYqtTVyt0nqqLExJAsU0S6Oew8tptNIJcSSFjF1NS8VhlYs198s_dj-7ntcM3jy3EzvqtQv8TNDo7sA7bFJ_he9lktmDdjPQ2gt2gyJAx-sUswcS5qvFY6JpXd74Xl-PbsT9sA"

The app logs 5 messages in this configuration with the respective log levels:

This is a trace message with attached string TESTSTRING
This is a debug message with attached string TESTSTRING
This is a info message with attached string TESTSTRING
This is a warning message with attached string TESTSTRING
This is a error message with attached string TESTSTRING

If you leave out the JWT token, it will only log the last 3 messages.

Clone this wiki locally