CallLogging and overview of other plugins for monitoring

Monitoring utilities is essential in any web application to monitor and debug issues during development and in production. Developers should use it to better understand the behavior of their applications, identify performance bottlenecks, and fix bugs more efficiently. By logging incoming requests and responses, developers can better understand how their apps are being used and make data-driven decisions to improve overall performance and user experience.

One of the main elements of application monitoring is logging. It is the process of storing information about actions and events that occur within the application, system, or network. It is often used to track and analyze application behavior during development and to diagnose issues that may arise in production environments.

The Ktor CallLogging plugin is a handy tool for logging incoming HTTP requests and responses. This plugin can be used to log important details like request and response headers, the body, and the HTTP status code. This information can be useful in debugging and troubleshooting the application, as well as providing valuable insights into the application's usage.

Installation

To install the CallLogging plugin in a Ktor project, you need to add the following dependency to the build.gradle.kts file:

implementation("io.ktor:ktor-server-call-logging:$ktor_version")

Configuration

To configure the plugin, you can write an extension function for the Application class as follows:

fun Application.configureMonitoring() {
    install(CallLogging) {
        level = Level.INFO
        filter { call -> call.request.path().startsWith("/") }
    }
}

In the code above, we use the install method to install the CallLogging plugin and configure it to only record logs at the Level.INFO level. The logging level refers to the severity of the logs being written. In Ktor, there are several logging levels available, including the following:

• Level.TRACE is the lowest level, used for very detailed debugging information.
• Level.DEBUG is used for debugging information and lower-level events.
• Level.INFO is used for informative messages and high-level events.
• Level.WARN is used for warnings and potentially problematic events.
• Level.ERROR is used for errors and critical events.

It is not necessary to explicitly specify the logging level. Level.DEBUG will be used by default.

The filter function can be used to exclude requests that do not satisfy the predicate, in our case not starting with the "/" character.

Usage Example

Let's set up a simple routing:

fun Application.configureRouting() {
    routing {
        get("/") {
            call.respondText("Hello World!")
        }
    }
}

When a request is made to the "/" endpoint, the following logs will be written to the console:

2023-01-01 12:00:00.000 [eventLoopGroupProxy-4-1] INFO  ktor.application - 200 OK: GET - / in 82ms

The meaning of each part of the log entry is explained below:

1. 2023-01-01 12:00:00.000 is the timestamp when the log entry was generated.

2. [eventLoopGroupProxy-4-1] is the thread name where the log entry was generated.

3. INFO is the log level, which indicates the severity of the log. In this case, it's an INFO log, which means it's an informative message.

4. ktor.application is the name of the logger that generated the log entry.

5. 200 OK: GET - / in 82ms is the message of the log entry. It contains information about the HTTP request, including the HTTP status code (200 OK), the HTTP method (GET), the request URL (/), and the time it took to process the request (in 82ms).

Advanced configuration

You can choose to log only certain requests using the filter function. The filter function takes a lambda expression that returns a Boolean value, indicating whether the request should be logged or not. For example:

install(CallLogging) {
    level = Level.INFO
    filter { call -> call.request.path().startsWith("/debug/") }
}

We configure the plugin to log only the requests that start with the "/debug/" path. When a request is made to the "/" endpoint, there will be no logs generated.

By default, the Ktor call logging plugin generates log messages in a predefined format. However, you can customize the log message format using the format function. The format function takes a lambda expression that returns a String value, representing the log message format:

install(CallLogging) {
    level = Level.INFO
    filter { call -> call.request.path().startsWith("/") }
    format { call ->
        val path = call.request.path()
        val name = call.request.queryParameters["name"] ?: "Anonymous"
        "A user named $name made a request to the path: $path"
    }
}

1. When a request is made to "/?name=John", the following logs will be written to the log file:

   INFO  ktor.application - A user named John made a request to the path: /
   

2. When a request is made to "/" without a name query parameter, the following logs will be written to the log file:

   INFO  ktor.application - A user named Anonymous made a request to the path: /
   

In the example above, we log information about the user who makes the request. Thus, we can supplement the logs and get comprehensive information about the behavior of the application and users.

Mapped Diagnostic Context (MDC)

Mapped Diagnostic Context (MDC) is a thread-local storage of values that can be associated with specific requests, allowing storage and retrieval of data across different log messages. This feature is especially useful when working with a distributed system, where each request can have its context and be processed by different threads.

Ktor CallLogging plugin supports MDC out-of-the-box, allowing to customize log messages by adding context-specific data to the log file. This can be achieved by using an mdc block in the CallLogging configuration:

install(CallLogging) {
    level = Level.INFO
    mdc("requestId") { call -> call.request.header("Request-Id") }
    format { call ->
        val path = call.request.path()
        val requestId = MDC.get("requestId") ?: "Unknown"
        val name = call.request.queryParameters["name"] ?: "Anonymous"
        "[ID: $requestId] A user named $name made a request to the path: $path"
    }
}

In the above code, we have added an mdc block that sets a requestId to the value of the Request-Id header from the incoming request. Then, in the format block, we retrieve the requestId from the call's attributes and include it in the log message.

For example, if a request with Request-Id: 123 header is made to the / endpoint, the following log will be generated:

[ID: 123] A user named John made a request to the path: /

Monitoring plugins overview

Ktor provides several monitoring plugins to help developers keep track of the performance and usage of their applications. Here are some of the most popular plugins:

The CallId plugin provides a unique identifier for each request and response, allowing one to easily track and monitor the flow of requests through the application. This plugin also provides an API to retrieve the CallId from anywhere in the code, making it easier to troubleshoot issues and diagnose problems.

Micrometer Metrics is a monitoring plugin for Ktor that allows one to collect and report various metrics, such as request processing time, response sizes, and error counts. It integrates with popular monitoring systems, such as Prometheus, Datadog, and InfluxDB, making it easy to collect, visualize, and alert on the metrics.

Dropwizard Metrics is another monitoring plugin for Ktor that provides a comprehensive set of metrics and reporters. It allows to collection, expose, and report metrics, including request processing time, response sizes, and error counts. Dropwizard Metrics supports various reporters, including Graphite, Ganglia, and JMX, making it easy to integrate with existing monitoring systems.

Conclusion

In this topic we learned that the standard Ktor logs are often not enough to get all the necessary information about requests, such as user data or body and parameters. In addition, sometimes it is necessary to limit the scope of requests that should be logged. For these tasks, we can use the Call Logging plugin. With features such as request and response logging, filtering log requests, and customizing log messages, the Call Logging plugin provides detailed information about the behavior of your application.

Also, the use of Mapped Diagnostic Context allows further customize the logging and provides additional context information. In combination with other monitoring plugins, such as CallId, Micrometer Metrics, and Dropwizard Metrics, Ktor provides a comprehensive and flexible solution for monitoring and tracking the performance of your applications.