Guide to Real-time Object Logging in Kotlin + Spring Boot using Graylog

Taehyeong LeeTaehyeong Lee
14 min read

Overview

  • Graylog is an open-source centralized log management platform that enables the collection and management of logs from dispersed microservices centrally. It supports the unique Key-Value based GELF log format and, from version v4.0.0, supports Elasticsearch7.10 or higher as a log store. This article aims to explain how to transmit execution logs, such as all HTTP requests, in real-time to GELF UDP from a Spring Boot-based project.

The Need for Structured Logs

  • With the advent of AI, application logs have transformed from information for human eyes to data for machine analysis. Traditional line-based text logs are insufficient for machine analysis. Well-designed structured logs can be analyzed by machines to be processed into meaningful data. The structured GELF log format was born for this purpose. [Related Link]

GELF UDP Transmission

  • The original GELF log comprises all Key-Value pairs loaded by MDC.put() in the application, collected into a JSON string. This string is compressed by the appender before transmission using GZIP, and in the case of UDP, if the compressed total size exceeds 8,192 bytes, it is transmitted in parts. A problem arises if the message input is being load-balanced at the running Graylog server; even the fragmented packets can be load-balanced, leading to message loss. Therefore, it is advisable to design the compressed log message size to not exceed 8,192 bytes. Most logs generated by the application can be accommodated within this size.

Objectives

  • Transfer all HTTP request logs.

  • Transfer all @Controller execution logs.

  • Transfer all @Service execution logs.

  • Transfer all @Repository execution logs.

  • The transferred logs can be filtered and aggregated by object field units in near real-time at the remote Graylog.

build.gradle.kts

  • Add the following content to the build.gradle.kts at the project root.
dependencies {
    implementation("org.springframework.boot:spring-boot-starter-aop:3.3.3")
    implementation("io.github.microutils:kotlin-logging-jvm:3.0.5")
    implementation("de.siegmar:logback-gelf:6.0.2")
    implementation("com.github.ksuid:ksuid:1.1.2")
    implementation("commons-io:commons-io:2.16.1")
    implementation("org.apache.commons:commons-lang3:3.17.0")
    implementation("commons-validator:commons-validator:1.9.0")
    implementation("com.maxmind.geoip2:geoip2:4.2.0")
}

Enabling GELF UDP Logging

  • Write the /src/main/resources/logback-spring.xml file at the project root as follows.
<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE configuration>

<configuration scan="true">

    <springProperty scope="context" name="graylogHost" source="graylog.host" defaultValue="127.0.0.1"/>
    <springProperty scope="context" name="graylogPort" source="graylog.port" defaultValue="12201"/>

    <appender name="TEXT_CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <charset>UTF-8</charset>
            <Pattern>%d %-4relative [%thread] %-5level %logger{35} - %msg%n</Pattern>
        </encoder>
    </appender>

    <appender name="GELF_UDP" class="de.siegmar.logbackgelf.GelfUdpAppender">
        <graylogHost>${graylogHost}</graylogHost>
        <graylogPort>${graylogPort}</graylogPort>
        <maxChunkSize>8192</maxChunkSize>
        <useCompression>true</useCompression>
        <messageIdSupplier class="de.siegmar.logbackgelf.MessageIdSupplier"/>
        <encoder class="de.siegmar.logbackgelf.GelfEncoder">
            <includeRawMessage>false</includeRawMessage>
            <includeMarker>true</includeMarker>
            <includeMdcData>true</includeMdcData>
            <numbersAsString>false</numbersAsString>
            <staticField>appender=GELF_UDP</staticField>
        </encoder>
    </appender>

    <logger name="GELF_UDP" level="DEBUG" additivity="false">
        <appender-ref ref="GELF_UDP"/>
    </logger>

    <root>
        <level value="INFO"/>
        <appender-ref ref="TEXT_CONSOLE"/>
    </root>

</configuration>

  • Through the GRAYLOG_HOST, GRAYLOG_PORT environment variables, you can inject the input information of the remote Graylog server responsible for log storage.

  • Logs named GELF_UDP are all sent through the GELF_UDP appender.

  • By specifying additivity="false" (default is true) in the logger, the log is transmitted only through the GELF_UDP appender and does not propagate to upper appenders. This prevents unnecessary duplication or output of logs.

Application Startup

  • For logging via UDP within the Amazon ecosystem, as of 2022-11-01, AWS NLB does not support UDP + IPv6 packet transmission. To prevent log loss, it's necessary to enforce the transmission of UDP packets via IPv4 only at the application level by adding the -Djava.net.preferIPv4Stack=true option as follows.
$ java ${JAVA_OPTS} -XX:+AlwaysPreTouch -Djava.security.egd=file:/dev/./urandom -Djava.net.preferIPv4Stack=true -jar /app.jar

Creating a Logging Utility

  • This example involves writing a common utility for logging.
import org.aspectj.lang.ProceedingJoinPoint
import org.aspectj.lang.reflect.MethodSignature
import org.apache.commons.lang3.exception.ExceptionUtils
import org.slf4j.MDC
import java.net.URLDecoder
import java.nio.charset.StandardCharsets
import java.time.Instant
import java.util.concurrent.atomic.AtomicInteger

object LoggingUtil {

    private const val MAX_FIELD_VALUE_LENGTH = 30000

    @JvmStatic
    fun getCurrentFullProfile(): String {

        val fullProfile: String? =
            System.getProperty("spring.profiles.active") ?: System.getenv("SPRING_PROFILES_ACTIVE")
        return if (fullProfile.isNullOrBlank()) {
            "local"
        } else {
            fullProfile
        }
    }

    @JvmStatic
    fun getCurrentMainProfile(): String {

        val profile: String = getCurrentFullProfile()

        return profile.split(",").firstOrNull() ?: "local"
    }

    @JvmStatic
    fun isLocal(): Boolean {

        return when (getCurrentMainProfile()) {
            "local" -> true
            else -> false
        }
    }

    @JvmStatic
    fun generateUUID(): String {

        return KsuidGenerator.generate()
    }

    @JvmStatic
    fun String?.convertUrlEncodedToUrlDecoded(): String {

        this ?: return ""
        return URLDecoder.decode(this, StandardCharsets.UTF_8)
    }

    @JvmStatic
    fun getClassNameMethodNamePair(joinPoint: ProceedingJoinPoint): Pair<String, String> {

        val className = joinPoint.signature.declaringTypeName.split(".").last()
        val methodName = (joinPoint.signature as MethodSignature).method.name

        return Pair(className, methodName)
    }

    @JvmStatic
    fun mdcPut(key: String?, value: Int?) {

        key ?: return
        value ?: return

        MDC.remove(key)
        MDC.put(key, value.toString())
    }

    @JvmStatic
    fun mdcPut(key: String?, value: Long?) {

        key ?: return
        value ?: return

        MDC.remove(key)
        MDC.put(key, value.toString())
    }

    @JvmStatic
    fun mdcPut(key: String?, value: Boolean?) {

        key ?: return
        value ?: return

        MDC.remove(key)
        MDC.put(key, value.toString())
    }

    @JvmStatic
    fun mdcPut(key: String?, value: String?) {

        key ?: return
        value ?: return

        MDC.remove(key)
        MDC.put(key, value)
    }

    @JvmStatic
    fun mdcPut(key: String?, value: Instant?) {

        key ?: return
        value ?: return

        MDC.remove(key)
        MDC.put(key, value.toString())
    }

    @JvmStatic
    fun mdcPutTrimmed(key: String?, value: String?) {

        key ?: return
        value ?: return

        if (value.length <= MAX_FIELD_VALUE_LENGTH) {
            mdcPut(key, value)
            return
        }

        mdcPut(key, value.substring(0, MAX_FIELD_VALUE_LENGTH - 1))
    }

    @JvmStatic
    fun mdcPutRawMessage(rawMessage: String?) {

        rawMessage ?: return

        mdcPutCumulative("raw_message", rawMessage, "\n")
    }

    @JvmStatic
    fun mdcPutCumulative(fieldName: String, fieldValue: String, separator: String = "\n") {

        val existsFieldValue = MDC.get(fieldName)
        if (existsFieldValue.isNullOrEmpty()) {
            MDC.put(fieldName, fieldValue)
            return
        }
        when (existsFieldValue.toByteArray().size > LoggingUtil.MAX_FIELD_VALUE_LENGTH) {
            true -> {
                val currentIndexNo = fieldName.substringAfterLast('_')
                val newIndexNo = AtomicInteger(1)
                val hasIndexNo = currentIndexNo.matches("[0-9]+".toRegex())
                val currentFieldNameWithoutIndexNo = when (hasIndexNo) {
                    true -> {
                        newIndexNo.addAndGet(Integer.valueOf(currentIndexNo))
                        fieldName.substringBeforeLast('_')
                    }

                    else -> fieldName
                }
                val newFieldName = "${currentFieldNameWithoutIndexNo}_$newIndexNo"
                MDC.put(newFieldName, fieldValue)
            }

            else -> MDC.put(fieldName, existsFieldValue + separator + fieldValue)
        }
    }

    @JvmStatic
    fun mdcPutRequestBody(requestBody: String?) {

        requestBody ?: return

        mdcPut("request_body", requestBody)
    }

    @JvmStatic
    fun mdcPutException(ex: Throwable?, prefix: String? = null) {

        ex ?: return

        val prefixString: String = if (prefix.isNullOrBlank()) {
            ""
        } else {
            "${prefix}_"
        }

        mdcPut("${prefixString}error_exception", ex.javaClass.name)
        mdcPutTrimmed("${prefixString}error_message", ex.message)

        ExceptionUtils.getRootCause(ex)?.let {
            mdcPut("${prefixString}error_root_exception", it.javaClass.name)
            mdcPutTrimmed("${prefixString}error_root_message", ExceptionUtils.getMessage(it))
        }
        mdcPutTrimmed("${prefixString}error_trace", ExceptionUtils.getStackTrace(ex))
    }

    @JvmStatic
    fun mdcClearException() {

        MDC.remove("error_exception")
        MDC.remove("error_message")
        MDC.remove("error_root_exception")
        MDC.remove("error_root_message")
        MDC.remove("error_trace")
    }

    @JvmStatic
    fun mergeMdcContextMap(mdcContextMap: Map<String, String>?) {

        if (mdcContextMap.isNullOrEmpty()) return

        MDC.setContextMap(MDC.getCopyOfContextMap() + mdcContextMap)
    }

    @JvmStatic
    fun clearAndPutMdcContextMap(mdcContextMap: Map<String, String>?) {

        if (mdcContextMap.isNullOrEmpty()) return

        MDC.clear()
        MDC.setContextMap(mdcContextMap)
    }
}

Storing Request ID in ThreadLocal

  • The Request ID plays a crucial role in identifying individual HTTP request logs. The following code allows acquiring the Request ID value for the current request as RequestContext.REQUEST_ID.
class RequestContext {

    companion object {

        private val requestId = ThreadLocal<String?>()

        var REQUEST_ID: String?
            get() = requestId.get()
            set(requestId) {
                Companion.requestId.set(requestId)
            }

        fun remove() {
            requestId.remove()
        }
    }
}

Capturing HTTP Request Body

  • Through the settings below, it's possible to capture the body of every HTTP request. (If the request body is not captured at this stage, it will be impossible to obtain the request body during the loading of HTTP request logs as described below.)
import jakarta.servlet.*
import jakarta.servlet.http.HttpServletRequest
import jakarta.servlet.http.HttpServletRequestWrapper
import org.apache.commons.io.IOUtils
import org.springframework.stereotype.Component
import java.io.*

@Component
class MultiReadableRequestBodyFilter : Filter {

    @Throws(IOException::class, ServletException::class)
    override fun doFilter(servletRequest: ServletRequest, servletResponse: ServletResponse, filterChain: FilterChain) {

        if (servletRequest.contentType == null) {
            filterChain.doFilter(servletRequest, servletResponse)
            return
        }

        if (servletRequest.contentType.startsWith("multipart/form-data")) {
            filterChain.doFilter(servletRequest, servletResponse)
        } else {
            val wrappedRequest = MultiReadableRequestBodyHttpServletRequest(servletRequest as HttpServletRequest)
            filterChain.doFilter(wrappedRequest, servletResponse)
        }
    }
}

class MultiReadableRequestBodyHttpServletRequest(request: HttpServletRequest?) : HttpServletRequestWrapper(request) {

    private var cachedBytes: ByteArrayOutputStream? = null

    @Throws(IOException::class)
    override fun getInputStream(): ServletInputStream {

        if (cachedBytes == null) cacheInputStream()

        return CachedServletInputStream(cachedBytes!!.toByteArray())
    }

    @Throws(IOException::class)
    override fun getReader(): BufferedReader {

        return BufferedReader(InputStreamReader(inputStream))
    }

    @Throws(IOException::class)
    private fun cacheInputStream() {

        cachedBytes = ByteArrayOutputStream()
        IOUtils.copy(super.getInputStream(), cachedBytes)
    }

    class CachedServletInputStream(contents: ByteArray?) : ServletInputStream() {

        private val buffer: ByteArrayInputStream = ByteArrayInputStream(contents)

        override fun read(): Int {

            return buffer.read()
        }

        override fun isFinished(): Boolean {

            return buffer.available() == 0
        }

        override fun isReady(): Boolean {

            return true
        }

        override fun setReadListener(listener: ReadListener) {

            throw RuntimeException("Not implemented")
        }
    }
}

HTTP Request Logging

  • The following configuration enables the loading of all HTTP request logs. (For details on obtaining Geolocation information from a specific IP address, refer to this article.)
import jakarta.servlet.http.HttpServletRequest
import jakarta.servlet.http.HttpServletResponse
import mu.KLogging
import mu.NamedKLogging
import org.apache.commons.io.IOUtils
import org.slf4j.MDC
import org.springframework.stereotype.Component
import org.springframework.web.servlet.HandlerInterceptor
import org.springframework.web.servlet.ModelAndView
import java.net.InetAddress
import java.nio.charset.StandardCharsets
import java.util.concurrent.TimeUnit

private val consoleLogger = KLogging().logger

@Component
class LoggingRequestInterceptor(
    // [Optional] Geolocation logging
    private val geoLocationService: GeoLocationService
) : HandlerInterceptor {

    companion object : NamedKLogging("GELF_UDP")

    override fun preHandle(request: HttpServletRequest, response: HttpServletResponse, handler: Any): Boolean {

        if (request.method == "OPTIONS") {
            return true
        }

        if (request.contextPath + request.servletPath in arrayOf("/health-check", "/swagger-ui/index.html", "/error") {
            return true
        }

        MDC.clear()
        mdcPut("execution_start_time", System.nanoTime().toString())

        var requestId: String? = request.getHeader("X-Request-Id")
        if (requestId.isNullOrEmpty()) {
            requestId = LoggingUtil.generateUUID()
        }
        RequestContext.REQUEST_ID = requestId
        mdcPut("request_id", requestId)
        mdcPut("transaction_id", requestId)
        mdcPut("application", "{your-app-name}")
        mdcPut("main_profile", CommonUtil.getCurrentMainProfile())
        mdcPut("full_profile", CommonUtil.getCurrentFullProfile())
        mdcPut("node_ip_address", InetAddress.getLocalHost().hostAddress)
        mdcPut("log_type", "REQUEST")
        mdcPut("request_referer", request.getHeader("Referer"))
        mdcPut("request_user_agent", request.getHeader("User-Agent"))
        mdcPut("request_platform", request.getHeader("sec-ch-ua-platform")?.replace("\"", "")?.trim())
        val requestIpAddress = request.getHeader("X-Forwarded-For")?.split(",")?.first() ?: request.remoteAddr
        mdcPut("request_ip_address", requestIpAddress)

        // [Optional] Geolocation logging
        geoLocationService.getGeoLocation(requestIpAddress)?.logging("request")

        mdcPut("request_method", request.method)
        val requestPath = request.contextPath + request.servletPath
        mdcPut("request_path", requestPath)

        request.queryString?.let { mdcPut("request_query_string", it.convertUrlEncodedToUrlDecoded()) }
        request.contentType?.let { contentType ->
            if (!(contentType.startsWith("multipart/form-data") || contentType.startsWith("application/x-www-form-urlencoded"))) {
                val requestBody = IOUtils.toString(request.inputStream, StandardCharsets.UTF_8)
                if (!requestBody.contains("password")) {
                    mdcPutRequestBody(requestBody)
                }
            }
        }

        return true
    }

    override fun postHandle(
        request: HttpServletRequest, response: HttpServletResponse, handler: Any, modelAndView: ModelAndView?
    ) {
        if (request.method == "OPTIONS") {
            return
        }

        if (request.contextPath + request.servletPath in arrayOf("/health-check", "/swagger-ui/index.html", "/error") {
            return
        }

        MDC.getCopyOfContextMap() ?: return
        MDC.get("execution_start_time")?.let {
            LoggingUtil.putMdcField(
                "execution_time",
                TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - it.toLong()).toString()
            )
            MDC.remove("execution_start_time")
        }
        LoggingUtil.putMdcField("response_status_code", response.status.toString())


        when (response.status) {

            in (200..300) -> {
                if (MDC.get("result")?.toString() == "false") {
                    mdcPut("log_level", "INFO")
                    val errorMessage = "API_REQUEST_FAILED"
                    mdcPut("message", errorMessage)
                    logger.error(errorMessage)
                } else {
                    mdcPut("log_level", "INFO")
                    val message = "API_REQUEST_FINISHED"
                    MDC.remove("error_code")
                    MDC.remove("error_message")
                    mdcPut("message", message)
                    logger.info(message)
                }
            }

            in (400..499) -> {
                mdcPut("log_level", "WARN")
                val message = "API_REQUEST_REJECTED"
                mdcPut("message", message)
                MDC.remove("class")
                MDC.remove("class_method")
                MDC.remove("method")
                MDC.remove("method_args")
                if (response.status == 404 && MDC.get("error_code") == null) {
                    mdcPut("error_code", "API_NOT_FOUND")
                    mdcPut("error_message", "Requested API is not found.")
                }
                logger.warn(message)
                consoleLogger.warn(MDC.getCopyOfContextMap().toString())
            }

            in (500..599) -> {
                mdcPut("log_level", "ERROR")
                val message = "API_REQUEST_FAILED"
                mdcPut("message", message)
                logger.error(message)
                consoleLogger.error(MDC.getCopyOfContextMap().toString())
            }
        }

        RequestContext.remove()
        MDC.clear()
    }
}

Adding Request ID to HTTP Response Header

  • Through the configuration below, it is possible to pass the Request ID obtained or generated during the log loading process back to the requesting client. (The client can use this value to identify and query logs for a specific request.)
import org.springframework.core.MethodParameter
import org.springframework.http.MediaType
import org.springframework.http.converter.HttpMessageConverter
import org.springframework.http.server.ServerHttpRequest
import org.springframework.http.server.ServerHttpResponse
import org.springframework.lang.Nullable
import org.springframework.stereotype.Component
import org.springframework.web.bind.annotation.ControllerAdvice
import org.springframework.web.servlet.mvc.method.annotation.ResponseBodyAdvice

@ControllerAdvice
@Component
class LoggingResponseBodyAdvice : ResponseBodyAdvice<Any?> {

    override fun supports(returnType: MethodParameter, converterType: Class<out HttpMessageConverter<*>>): Boolean {

        return true
    }

    override fun beforeBodyWrite(
        @Nullable body: Any?,
        returnType: MethodParameter,
        selectedContentType: MediaType,
        selectedConverterType: Class<out HttpMessageConverter<*>>,
        request: ServerHttpRequest,
        response: ServerHttpResponse
    ): Any? {

        response.headers.add("X-Request-Id", RequestContext.REQUEST_ID)

        return body
    }
}

Enabling Logging Interceptor

  • The settings below allow for the addition of a log loading interceptor and specifying paths to exclude.
import org.springframework.context.annotation.Configuration
import org.springframework.web.servlet.config.annotation.InterceptorRegistry
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer

@Configuration
class InterceptorConfig(
    private val loggingRequestInterceptor: LoggingRequestInterceptor
) : WebMvcConfigurer {

    override fun addInterceptors(registry: InterceptorRegistry) {

        registry
            .addInterceptor(loggingRequestInterceptor)
            .addPathPatterns("/**")
            .excludePathPatterns(
                "/health-check",
                "/management/health",
                "/swagger-ui/**"
            )
    }
}

Exception Logging

  • The following configuration enables the logging of all exception handling results.
import jakarta.servlet.http.HttpServletRequest
import mu.KLogging
import org.apache.commons.lang3.exception.ExceptionUtils
import org.slf4j.MDC
import org.springframework.core.Ordered
import org.springframework.core.annotation.Order
import org.springframework.http.HttpStatus
import org.springframework.http.ResponseEntity
import org.springframework.web.bind.annotation.ControllerAdvice
import org.springframework.web.bind.annotation.ExceptionHandler
import org.springframework.web.bind.annotation.ResponseBody

private val consoleLogger = KLogging().logger

@ControllerAdvice
@Order(Ordered.HIGHEST_PRECEDENCE)
class FooControllerAdvice {

    @ExceptionHandler(FooException::class)
    @ResponseBody
    fun handleFooException(

        request: HttpServletRequest,
        ex: FooException

    ): ResponseEntity<*> {

        mdcPut("message", "API_REQUEST_REJECTED")
        mdcPut("error_code", ex.errorCode.name)
        mdcPut("error_message", ex.errorMessage)

        return ResponseEntity(
            FooErrorResponse(
                ex.errorCode.name,
                ex.errorMessage,
                ex.errorDetail
            ),
            ex.httpStatus
        )
    }

    @ExceptionHandler(Exception::class)
    @ResponseBody
    fun handleException(

        request: HttpServletRequest,
        ex: Exception

    ): ResponseEntity<*> {

        mdcPut("message", "API_REQUEST_FAILED")
        mdcPut("error_code", FooErrorCode.INTERNAL_SERVER_ERROR.name)
        mdcPut("error_exception", ex.javaClass.name)
        mdcPut("error_message", ex.message)
        ExceptionUtils.getRootCause(ex)?.let {
            mdcPut("error_root_exception", ExceptionUtils.getRootCause(ex).javaClass.name)
            mdcPut("error_root_message", ExceptionUtils.getRootCauseMessage(ex))
        }
        mdcPut("error_trace", ExceptionUtils.getStackTrace(ex))

        if (LoggingUtil.isLocal()) {
            consoleLogger.warn(MDC.getCopyOfContextMap().toString())
        }

        return ResponseEntity(
            FooErrorResponse
                (
                FooErrorCode.INTERNAL_SERVER_ERROR.name,
                FooErrorCode.INTERNAL_SERVER_ERROR.message
            ),
            HttpStatus.INTERNAL_SERVER_ERROR
        )
    }
}

@Controller Logging

  • The settings below allow for the logging of arguments and execution time of methods executed in all @Controller beans.
import mu.NamedKLogging
import org.aspectj.lang.ProceedingJoinPoint
import org.aspectj.lang.annotation.Around
import org.aspectj.lang.annotation.Aspect
import org.slf4j.MDC
import org.springframework.core.annotation.Order
import org.springframework.stereotype.Component
import java.util.concurrent.TimeUnit

@Component
@Aspect
@Order(65535)
class LoggingControllerAspect {

    companion object : NamedKLogging("GELF_UDP")

    @Around("@annotation(org.springframework.web.bind.annotation.RequestMapping)" + " || @annotation(org.springframework.web.bind.annotation.PostMapping)" + " || @annotation(org.springframework.web.bind.annotation.GetMapping)" + " || @annotation(org.springframework.web.bind.annotation.PutMapping)" + " || @annotation(org.springframework.web.bind.annotation.PatchMapping)" + " || @annotation(org.springframework.web.bind.annotation.DeleteMapping)")
    fun aroundControllerExecution(joinPoint: ProceedingJoinPoint): Any? {

        val classNameMethodNamePair = CommonUtil.getClassNameMethodNamePair(joinPoint)
        LoggingUtil.mdcPut("class", classNameMethodNamePair.first)
        LoggingUtil.mdcPut("method", classNameMethodNamePair.second)
        val classMethod = "${classNameMethodNamePair.first}#${classNameMethodNamePair.second}"
        LoggingUtil.mdcPut("class_method", classMethod)
        LoggingUtil.mdcPut("controller_class_method", classMethod)
        joinPoint.args?.let { args ->
            val argsString = ToStringBuilder.reflectionToString(args, ToStringStyle.JSON_STYLE)
            LoggingUtil.mdcPutTrimmed(
                "method_args",
                argsString
            )
        }

        return try {

            joinPoint.proceed()
        } catch (ex: Exception) {

            doRequestErrorLogging(ex)
            throw ex
        }
    }

    private fun doRequestErrorLogging(ex: Exception) {

        mdcPutException(ex)

        MDC.get("execution_start_time")?.let {
            LoggingUtil.putMdcField(
                "execution_time",
                TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - MDC.get("execution_start_time").toLong()).toString()
            )
            MDC.remove("execution_start_time")
        }

        RequestContext.remove()
        MDC.clear()
    }
}

@Service Logging

  • The following configuration allows for the logging of arguments and execution time for methods executed in all @Service beans.
import mu.NamedKLogging
import org.apache.commons.lang3.builder.ToStringBuilder
import org.apache.commons.lang3.builder.ToStringStyle
import org.aspectj.lang.ProceedingJoinPoint
import org.aspectj.lang.annotation.Around
import org.aspectj.lang.annotation.Aspect
import org.aspectj.lang.annotation.Pointcut
import org.slf4j.MDC
import org.springframework.stereotype.Component
import java.time.Instant
import java.util.concurrent.TimeUnit

@Component
@Aspect
class LoggingServiceAspect {

    companion object : NamedKLogging("GELF_UDP")

    @Pointcut("within(@org.springframework.stereotype.Service *)")
    fun serviceClassMethods() {
    }

    @Around("serviceClassMethods()")
    fun aroundServiceExecution(joinPoint: ProceedingJoinPoint): Any? {

        val classNameMethodNamePair = getClassNameMethodNamePair(joinPoint)
        val originalMdcMap = MDC.getCopyOfContextMap()
        mdcClearException()
        mdcPut("log_level", "DEBUG")
        mdcPut("log_type", "SERVICE")
        mdcPut("class", classNameMethodNamePair.first)
        mdcPut("method", classNameMethodNamePair.second)
        val classMethod = "${classNameMethodNamePair.first}#${classNameMethodNamePair.second}"
        mdcPut("class_method", classMethod)
        mdcPut("service_class_method", classMethod)
        joinPoint.args?.let { args ->
            val argsString = ToStringBuilder.reflectionToString(args, ToStringStyle.JSON_STYLE)
            if (!argsString.contains("password")) {
                putMdcFieldTrimmed(
                    "method_args",
                    argsString
                )
            }
        }

        var message = "SERVICE_EXECUTION_FINISHED"
        val executionStartTime = System.nanoTime()
        val result = try {
            joinPoint.proceed()

        } catch (ex: Exception) {
            message = "SERVICE_EXECUTION_FAILED"
            mdcPutException(ex)
            mdcPut(
                "execution_time",
                TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - executionStartTime).toString()
            )
            mdcPut("message", message)
            if (ex is YourAppException) {
                logger.debug(message)
            } else {
                mdcPut("log_level", "ERROR")
                logger.error(message)
            }
            mergeMdcContextMap(originalMdcMap)

            throw ex
        }

        mdcPut(
            "execution_time",
            TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - executionStartTime).toString()
        )
        mdcPut("message", message)

        if (classMethod == "ModelSpecificationFactory#create") {
            return result
        }

        logger.debug(message)
        LoggingUtil.mergeMdcFields(originalMdcMap)

        return result
    }
}

@Repository Query Logging

  • The settings below enable the logging of arguments and execution time for all queries executed through Spring Data JPA or Querydsl. (Logging at the code level offers incomparable advantages in readability and traceability over database-level logging.)
import mu.NamedKLogging
import org.apache.commons.lang3.builder.ToStringBuilder
import org.apache.commons.lang3.builder.ToStringStyle
import org.aspectj.lang.ProceedingJoinPoint
import org.aspectj.lang.annotation.Around
import org.aspectj.lang.annotation.Aspect
import org.aspectj.lang.annotation.Pointcut
import org.slf4j.MDC
import org.springframework.stereotype.Component
import java.util.concurrent.TimeUnit

@Component
@Aspect
class LoggingRepositoryAspect {

    companion object : NamedKLogging("GELF_UDP")

    @Pointcut("within(@org.springframework.stereotype.Repository *)")
    fun repositoryClassMethods() {
    }

    @Around("repositoryClassMethods() || within(org.springframework.data.jpa.repository.JpaRepository+) || within(org.springframework.data.querydsl.QuerydslPredicateExecutor+)")
    fun aroundQueryExecution(joinPoint: ProceedingJoinPoint): Any? {

        val classNameMethodNamePair = getClassNameMethodNamePair(joinPoint)
        val originalMdcMap = MDC.getCopyOfContextMap()
        mdcClearException()
        mdcPut("log_level", "DEBUG")
        mdcPut("log_type", "QUERY")
        mdcPut("class", classNameMethodNamePair.first)
        mdcPut("method", classNameMethodNamePair.second)
        val classMethod = "${classNameMethodNamePair.first}#${classNameMethodNamePair.second}"
        mdcPut("class_method", classMethod)
        mdcPut("repository_class_method", classMethod)
        val args = joinPoint.args
        when (classMethod) {
            "CrudRepository#save" -> {
                args?.let {
                    if (it.isNotEmpty()) {
                        val entity = args[0]
                        val entityName = entity::class.simpleName
                        entityName?.let {
                            mdcPut("class", classNameMethodNamePair.first.replace("Crud", entityName))
                            mdcPut("class_method", classMethod.replace("Crud", entityName))
                        }
                    }
                }
            }
            else -> {}
        }

        args?.let {
            LoggingUtil.mdcPutTrimmed(
                "method_args",
                ToStringBuilder.reflectionToString(it, ToStringStyle.JSON_STYLE)
            )
        }

        var message = "QUERY_EXECUTION_FINISHED"
        val executionStartTime = System.nanoTime()
        val result = try {
            joinPoint.proceed()
        } catch (ex: Exception) {
            message = "QUERY_EXECUTION_FAILED"
            mdcPutException(ex)
            mdcPut(
                "execution_time",
                TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - executionStartTime).toString()
            )
            mdcPut("message", message)
            mdcPut("log_level", "ERROR")
            logger.error(message)
            if (isLocal()) {
                consoleLogger.debug(MDC.getCopyOfContextMap().toString())
            }
            clearAndPutMdcContextMap(originalMdcMap)

            throw ex
        }

        mdcPut(
            "execution_time",
            TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - executionStartTime).toString()
        )
        mdcPut("message", message)

        logger.debug(message)
        clearAndPutMdcContextMap(originalMdcMap)

        return result
    }
}

@Scheduled Logging

  • Batch schedulers annotated with @Scheduled at the method level can also log as follows:
import mu.NamedKLogging
import org.aspectj.lang.ProceedingJoinPoint
import org.aspectj.lang.annotation.Around
import org.aspectj.lang.annotation.Aspect
import org.slf4j.MDC
import org.springframework.scheduling.annotation.Scheduled
import org.springframework.stereotype.Component
import java.net.InetAddress
import java.util.concurrent.TimeUnit

@Component
@Aspect
class LoggingScheduleAspect {

    companion object : NamedKLogging("GELF_UDP")

    @Around("@annotation(scheduled)")
    fun aroundScheduled(joinPoint: ProceedingJoinPoint, scheduled: Scheduled): Any? {

        MDC.clear()
        mdcPut("application", "{your-app-name}")
        mdcPut("main_profile", CommonUtil.getCurrentMainProfile())
        mdcPut("full_profile", CommonUtil.getCurrentFullProfile())
        mdcPut("node_ip_address", InetAddress.getLocalHost().hostAddress)
        mdcPut("log_type", "SCHEDULE")
        val transactionId = generateUUID()
        mdcPut("schedule_id", transactionId)
        mdcPut("transaction_id", transactionId)

        if (scheduled.cron.isNotEmpty()) {
            mdcPut("cron_expression", scheduled.cron)
        }

        val classNameMethodNamePair = CommonUtil.getClassNameMethodNamePair(joinPoint)
        val classMethod = "${classNameMethodNamePair.first}#${classNameMethodNamePair.second}"
        mdcPut("class", classNameMethodNamePair.first)
        mdcPut("method", classNameMethodNamePair.second)
        mdcPut("class_method", classMethod)
        mdcPut("schedule_class_method", classMethod)
        mdcPut("log_level", "INFO")
        var message = "API_SCHEDULE_STARTED"
        mdcPut("message", message)

        if (classMethod != "LoggingHeartbeatComponent#heartbeat") {
            logger.info(message)
        }

        val processStartTime = System.nanoTime()
        val result = try {
            joinPoint.proceed()
        } catch (ex: Exception) {
            mdcPut("execution_time", TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - processStartTime).toString())
            mdcPutException(ex)
            mdcPut("log_level", "ERROR")
            logger.error("API_SCHEDULE_FAILED")

            return null
        }

        mdcPut("execution_time", TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - processStartTime).toString())
        message = "API_SCHEDULE_FINISHED"
        mdcPut("message", message)

        if (classMethod != "LoggingHeartbeatComponent#heartbeat") {
            logger.info(message)
        }

        return result
    }
}

Asynchronous Thread Logging

  • Through the following configuration, methods executed asynchronously with @Async(TaskExecutionAutoConfiguration.APPLICATION_TASK_EXECUTOR_BEAN_NAME) can also be logged. For more detailed information, refer to this article.
import kotlinx.coroutines.CoroutineDispatcher
import kotlinx.coroutines.Dispatchers
import kotlinx.coroutines.asCoroutineDispatcher
import org.slf4j.MDC
import org.springframework.boot.autoconfigure.task.TaskExecutionAutoConfiguration
import org.springframework.context.annotation.Bean
import org.springframework.context.annotation.Configuration
import org.springframework.core.task.AsyncTaskExecutor
import org.springframework.core.task.TaskDecorator
import org.springframework.core.task.support.TaskExecutorAdapter
import org.springframework.scheduling.annotation.EnableAsync
import java.util.concurrent.Executors

@Configuration
@EnableAsync
class AsyncConfig {

    @Bean(TaskExecutionAutoConfiguration.APPLICATION_TASK_EXECUTOR_BEAN_NAME)
    fun asyncTaskExecutor(): AsyncTaskExecutor {

        val taskExecutor = TaskExecutorAdapter(Executors.newVirtualThreadPerTaskExecutor())
        taskExecutor.setTaskDecorator(LoggingTaskDecorator())

        return taskExecutor
    }
}

class LoggingTaskDecorator : TaskDecorator {

    override fun decorate(task: Runnable): Runnable {

        val callerThreadContext = MDC.getCopyOfContextMap()

        return Runnable {
            callerThreadContext?.let {
                MDC.setContextMap(it)
            }
            task.run()
        }
    }
}

val Dispatchers.LOOM: CoroutineDispatcher
    get() = Executors.newVirtualThreadPerTaskExecutor().asCoroutineDispatcher()

Application Status Logging

  • Logging the CPU usage, RAM usage, and other metrics of running instances every minute as shown below can greatly aid in performance monitoring.
import mu.NamedKLogging
import org.slf4j.MDC
import org.springframework.scheduling.annotation.Scheduled
import org.springframework.stereotype.Component
import java.lang.management.ManagementFactory
import java.net.InetAddress
import java.util.concurrent.TimeUnit

@Component
class LoggingHeartbeatComponent {

    companion object : NamedKLogging("GELF_UDP")

    @Scheduled(fixedRate = 60000)
    fun heartbeat() {

        MDC.clear()
        LoggingUtil.putMdcField("execution_start_time", System.nanoTime().toString())

        val runtime = Runtime.getRuntime()
        val memoryBean = ManagementFactory.getMemoryMXBean()
        val threadBean = ManagementFactory.getThreadMXBean()
        val cpuLoad = ManagementFactory.getOperatingSystemMXBean().systemLoadAverage
        val cpuCoreMax = ManagementFactory.getOperatingSystemMXBean().availableProcessors
        val cpuUsagePercentage = if (cpuLoad >= 0) (cpuLoad / cpuCoreMax * 100) else 0.0
        val maxMemory = runtime.maxMemory()
        val memoryHeapUsage = memoryBean.heapMemoryUsage.used
        val memoryNonHeapUsage = memoryBean.nonHeapMemoryUsage.used
        val threadUsageCount = threadBean.threadCount

        mdcPut("application", "{your-app-name}")
        mdcPut("main_profile", getCurrentMainProfile())
        mdcPut("full_profile", getCurrentFullProfile())
        mdcPut("node_ip_address", InetAddress.getLocalHost().hostAddress)
        mdcPut("log_type", "HEARTBEAT")
        mdcPut("cpu_core_max_count", cpuCoreMax.toString())
        mdcPut("cpu_load", cpuLoad.toString())
        mdcPut("cpu_usage_percentage", cpuUsagePercentage.toString())
        mdcPut("thread_usage_count", threadUsageCount.toString())
        mdcPut("memory_max_mb", convertBytesToMegabytes(maxMemory).toString())
        mdcPut("memory_heap_usage_mb", convertBytesToMegabytes(memoryHeapUsage).toString())
        mdcPut("memory_non_heap_usage_mb", convertBytesToMegabytes(memoryNonHeapUsage).toString())
        mdcPut("log_level", "DEBUG")
        val message = "API_HEARTBEAT_FINISHED"
        mdcPut("message", message)
        MDC.get("execution_start_time")?.let {
            mdcPut(
                "execution_time",
                TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - it.toLong()).toString()
            )
            MDC.remove("execution_start_time")
        }
        logger.debug(message)
        MDC.clear()
    }

    private fun convertValueToPercent(value: Double): Double {

        if (value <= 0.0) {
            return 0.0
        }
        if (value >= 100.0) {
            return 100.0
        }

        return value
    }

    private fun convertBytesToMegabytes(bytes: Long): Long = bytes / 1024 / 1024
}

Application Deployment Logging

  • By logging at the point when an application is newly deployed and ready to receive HTTP requests, and at the point when it terminates, you can get an overview of the deployment status of 'n' instances.
import mu.NamedKLogging
import org.slf4j.MDC
import org.springframework.boot.ApplicationArguments
import org.springframework.boot.ApplicationRunner
import org.springframework.boot.autoconfigure.SpringBootApplication
import org.springframework.boot.runApplication
import org.springframework.context.event.ContextClosedEvent
import org.springframework.context.event.EventListener
import java.net.InetAddress

@SpringBootApplication
class FooApplication : ApplicationRunner {

    companion object : NamedKLogging("GELF_UDP")

    override fun run(args: ApplicationArguments?) {

        MDC.clear()
        mdcPutApplication()
        val message = "API_APPLICATION_STARTED"
        mdcPut("message", message)
        logger.info(message)
        MDC.clear()
    }

    @EventListener
    fun onApplicationContextClosedEvent(event: ContextClosedEvent) {

        MDC.clear()
        mdcPutApplication()
        val message = "API_APPLICATION_TERMINATED"
        mdcPut("message", message)
        logger.info(message)
        MDC.clear()
    }

    private fun mdcPutApplication() {

        mdcPut("application", "{your-app-name}")
        mdcPut("main_profile", getCurrentMainProfile())
        mdcPut("full_profile", getCurrentFullProfile())
        mdcPut("node_ip_address", InetAddress.getLocalHost().hostAddress)
        mdcPut("log_type", "DEPLOYMENT")
        mdcPut("log_level", "DEBUG")
    }
}

fun main(args: Array<String>) {

    runApplication<FooApplication>(*args)
}
2
Subscribe to my newsletter

Read articles from Taehyeong Lee directly inside your inbox. Subscribe to the newsletter, and don't miss out.

KotlinSpringbootgraylog

Written by

Taehyeong Lee
Taehyeong Lee