I am trying to print nanosecond precision of the time stamp in the logs for my spring boot app. I am using logback 1.5.6 in Spring Boot 3.3 with Java 17. I looked for different approaches and that concludes that we already have access to nanosecond precision from Java 9+ and log4j was upgraded with SimpleDateFormatter that supports nanosecond precision. We can implement the same using enconder in logback-spring.xml with format %d{HH:mm:ss.SSSSSSSSS} or %date{HH:mm:ss.SSSSSSSSS}
But with all things considered I got the nano second format in the Logs (dd:mm:ss.SSSSSSSSS) but the data was in millisecond unfortunately. (12:30:17:815000000).
So though it supports nanoseconds precision but data comes with millisecond precision. Seems this is a casting issue some where in logback library.
I also found that we can use a custom encoder or filter or MDC custom format variable to manually get the data and convert it to nanosecond but should not by default it should give nanoseconds as suggested by its docs & use cases ? Basically as the library already has the functionality then why can't I use it.
logback-spring.xml
<configuration status="TRACE">
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{HH:mm:ss.SSSSSSSSS} [%thread] [%logger] [%level] - %msg%n</pattern>
</encoder>
</appender>
<root level="INFO">
<appender-ref ref="CONSOLE" />
</root>
</configuration>
pom.xml
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>3.3.0</version>
<relativePath/> <!-- lookup parent from repository -->
</parent>
<groupId>com.demo.ems</groupId>
<artifactId>ems</artifactId>
<version>1.0-SNAPSHOT</version>
<packaging>pom</packaging>
<modules>
<module>employee-service</module>
<module>task-service</module>
<module>discovery-service</module>
<module>gateway-service</module>
<module>admin-server-service</module>
<module>config-service</module>
</modules>
<properties>
<maven.compiler.source>17</maven.compiler.source>
<maven.compiler.target>17</maven.compiler.target>
<project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
<spring-cloud.version>2023.0.0</spring-cloud.version>
<spring-boot-admin.version>3.2.1</spring-boot-admin.version>
</properties>
<dependencies>
<dependency>
<groupId>org.modelmapper</groupId>
<artifactId>modelmapper</artifactId>
<version>3.2.0</version>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-actuator</artifactId>
</dependency>
</dependencies>
<dependencyManagement>
<dependencies>
<dependency>
<groupId>org.springframework.cloud</groupId>
<artifactId>spring-cloud-dependencies</artifactId>
<version>${spring-cloud.version}</version>
<type>pom</type>
<scope>import</scope>
</dependency>
<dependency>
<groupId>de.codecentric</groupId>
<artifactId>spring-boot-admin-dependencies</artifactId>
<version>${spring-boot-admin.version}</version>
<type>pom</type>
<scope>import</scope>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-logging</artifactId>
</dependency>
</dependencies>
</dependencyManagement>
<build>
<plugins>
<plugin>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-maven-plugin</artifactId>
<configuration>
<excludes>
<exclude>
<groupId>org.projectlombok</groupId>
<artifactId>lombok</artifactId>
</exclude>
</excludes>
</configuration>
</plugin>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-compiler-plugin</artifactId>
<configuration>
<source>17</source>
<target>17</target>
</configuration>
</plugin>
</plugins>
</build>
</project>
Also I debugged while logging and found out that. In the log %d gives the this.timeStamp attribute present in the LoggingEvent.class of ch.qos.logback.classic.spi package which is actually formed using milisecond instead of nanosecond though it is available.
Also I debugged while logging and found out that. In the log %d gives the this.timeStamp attribute present in the LoggingEvent.class of ch.qos.logback.classic.spi package which is actually formed using milisecond instead of nanosecond though it is available.
For logback you have to write custom converter
This is a customer converter which returns the time elapsed since its creation in nanoseconds:
public class MySampleConverter extends ClassicConverter {
long start = System.nanoTime();
@Override
public String convert(ILoggingEvent event) {
long nowInNanos = System.nanoTime();
return Long.toString(nowInNanos-start);
}
}
and then point to it in configuration file
<configuration>
<conversionRule conversionWord="nanos"
converterClass="chapters.;layouts.MySampleConverter" />
<appender name="STDOUT" class="ch.qos.logback.;core.ConsoleAppender">
<encoder>
<pattern>%-6nanos [%thread] -%kvp -%msg%n</pattern>
</encoder>
</appender>
<root level="DEBUG">
<appender-ref ref="STDOUT" />
</root>
</configuration>
For details please see https://logback.qos.ch/manual/layouts.html