Logging with Logback

You already know that you can use the debugger to find and fix errors in Kotlin. In practice, it's not that easy. Errors can occur in unexpected places and are impossible to catch at the application development stage. Errors may occur only for some users under certain conditions. Logs were invented to detect these conditions. They allow developers to find weaknesses in the web server that were not detected during testing.

Today you will get acquainted with the logging system in Ktor.

What are logs?

Logs are simply text messages in a console or file that an application writes there at runtime. Essentially, logs allow the developer to see what's going on in the application in chronological order. If you see your server is not behaving as planned, you can use this event history to find a weak spot in the program without even stopping the server.

Such a story is not created automatically. You, as a developer, have to set up logging where you need it. Don't be afraid it's easy, you will now see yourself.

Logs in Ktor

Logging in Ktor is provided by the SLF4J library and the Logback logging framework. When you create a new project through the IDE or Project Generator Site, they are already connected to the project.

If you go into build.gradle.kts and look at the dependencies section, you will see the line:

implementation("ch.qos.logback:logback-classic:$logback_version")

This just adds a logging framework to your project.

Tip: If for some reason this line was not added there when you created the new project, add it yourself and rebuild Gradle.

Logs configuration

Logging is configured using the appropriate logback.xml configuration file. By default it should be located at src\main\resources folder and has the following content:

<configuration>
    <appender name="APPENDER" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>
    <root level="trace">
        <appender-ref ref="APPENDER"/>
    </root>
    <logger name="io.netty" level="INFO"/>
</configuration>

Tip: If for some reason it is not created, then create it and put the content specified above into it.

%d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n is the template according to which logs will be kept. We're not going to change it yet.

Output logs to a file

By default, logs are output to the console. In real applications, it is useful to output them to a file so that they do not disappear after closing the application. All you need to write logs to a file is to change the logback.xml as follows:

<configuration>
    <appender name="APPENDER" class="ch.qos.logback.core.FileAppender"> 
        <file>myFile.log</file>
        <append>true</append> 
        <encoder>
            <pattern>%d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>
    <root level="trace">
        <appender-ref ref="APPENDER"/>
    </root>
    <logger name="io.netty" level="INFO"/>
</configuration>

<file>myFile.log</file> is the name of the file where the logs will be written. It will be automatically created in the project folder. If we are talking about a ready-made application, it will be created in the folder with the .jar file of the server.

<append>true</append> means the logs will be written to the end of the file without erasing its previous contents.<append>false</append> means the file will be cleaned of old logs every time the application starts.

For now, let's leave the output to the console so that we can see the log output directly in the IDE console.

Output the message to logs

Now that you have made sure that the Gradle Logback dependency is connected and the configuration file is created, you can output some information to the logs.

We use the log.info function to display the message in the logs:

log.info(message)

Let's display some kind of message at the start of the server:

import com.example.plugins.configureRouting
import io.ktor.server.application.*
import io.ktor.server.engine.*
import io.ktor.server.netty.*

fun main() {
    embeddedServer(Netty, port = 8080, host = "0.0.0.0") {
        log.info("Server started!") // output string "Server started!" to the logs
        configureRouting()
    }.start(wait = true)
}

Now every time you start the server, you will see this message in the console:

Tip: Note that the message was displayed exactly according to the template, which is specified in the logback.xml.

<pattern>%d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>

The date and time are displayed instead of %d{YYYY-MM-dd HH:mm:ss.SSS}.

Service information is displayed instead of [%thread] %-5level %logger{36}.

Finally, our message that we passed as an argument to the log.info function is displayed instead of %msg%n.

To call log.info in the routing handler, you should use the call.application.environment.log property:

routing {
    get("/") {
        call.application.environment.log.info("Index page requested")
        call.respondText("Index page")
    }
}

Then a log entry will be made every time one of the users accesses that page:

It is up to the developer to decide where to place log.info and which events to log.

Different log levels

In fact, log.info is not the only function used for logging. There are also other functions such as: log.debug, log.warn, log.error. But how do they all differ from each other?

Let's call them one by one with the same message and see if the log entries generated by these functions are different.

log.info("My message")
log.debug("My message")
log.warn("My message")
log.error("My message")

We see that their logs differ only by labels: "INFO", "DEBUG", "WARN", "ERROR".

This is the so-called level of importance of the logs. Let's talk about them in a little more detail.

In practice, there may be a lot of logs and it may be almost impossible for a person to understand them. Therefore, all events that are logged have their own level of importance. So that a person who looks through the logs can sort them by their importance.

• DEBUG is used mainly for logging system information, which can help the developers to understand if everything works correctly in the program (for example, load statistics for the servers, HTTP request history).
• INFO is used to log general messages that do not affect the correctness of the application (for example, service start/stop).
• WARN is used for logging events that might affect the correctness of the application (such as switching from a primary to the backup server, missing secondary data, and so on).
• ERROR is used to alert you to a failed operation. Logs at this level are always important because the errors they report can affect your users (for example, can't connect to the database, missing file).

There are other levels of logs, but they are used less frequently. For now, remember that we need log levels so that we can easily find important events, such as errors and warnings, among all other events in the logs.

Therefore, if you log some regular event, for example, a user's visit to the site, then use log.debug. If an error occurs (an abnormal event) then use log.error.

routing {
    get("/") {
        try {
            call.application
                .environment
                .log.debug("Index page requested") //use log.debug for unimportant events
            call.respondText("Index page")
            call.respondText("Content")
        } catch (e: Exception) {
            call.application
                .environment
                .log.error(e.message) //use log.error for important events (errors)
        }
    }
}

Changing the color of logs

Now that you've learned the basics of logging in Ktor, you can dabble with colors!

Logback allows you to customize the color of the logs. This is done by changing the pattern in the logback.xml file:

<pattern>%d{YYYY-MM-dd HH:mm:ss.SSS} %highlight(%-5level) %green(%msg) %n</pattern>

We get this beautiful output in the console:

Instead of %green, we also can use %red, %cyan, %blue, and other colors. Try it yourself!

With %highlight the logs are highlighted according to their importance (look at the color of the labels "INFO", "DEBUG", "WARN", "ERROR"). This is also very convenient.

See more options in the official Logback documentation section.

Conclusion

In this topic, you've learned what logs are, what they are for, and how to write logs in Ktor. Now you know how to redirect logs to a file using the appropriate setting in the src\main\resources\logback.xml file.

You also know the main levels of logging importance and corresponding functions for each of them:

• INFO: log.info(message)
• DEBUG: log.debug(message)
• WARN: log.warn(message)
• ERROR: log.error(message)

All you need to do to write the log is to call one of these functions by passing the appropriate message.

It is up to you to decide what and how to log. Remember that intelligent logging will help you find errors in the program that the debugger did not detect. The usefulness of unreadable logs tends to zero. Try to make meaningful log messages and respect the levels of importance.