Empty square brackets [] [] [] in Spring Boot Logs

Viewed 51

I have Spring Boot App in Gradle with Liquibase changesets.

This code is multi module app with about four modules in hexagonal architecture.

enter image description here

and the resources folder structure looks like this for doctors-data-deploy module:

enter image description here

when I run this app, I get lot of empty [] [] [] square brackets in the logs as shown below:

enter image description here

Can anyone please let me know why such behaviour or where the issue lies in my spring boot app configuration ?

Below is my application yml file

server:
  tomcat:
    connectionTimeout: 300000
management:
  endpoint:
    mappings:
      enabled: true
spring:
  liquibase:
    change-log: classpath:/db/changelog/db.changelog-master.xml
  datasource:
    driver-class-name: oracle.jdbc.driver.OracleDriver
    hikari:
      minimum-idle: 5
      maximumPoolSize: 20
      idleTimeout: 30000
      maxLifetime: 2000000
      connectionTimeout: 30000
      poolName: data-pool
  jpa:
    hibernate:
      use-new-id-generator-mappings: false
      ddl-auto: none
    database-platform: org.hibernate.dialect.Oracle12cDialect
  quartz:
    job-store-type: jdbc
    jdbc:
      initialize-schema: never
    properties:
      org:
        quartz:
          scheduler:
            instanceId: AUTO
          jobStore:
            class: org.quartz.impl.jdbcjobstore.JobStoreTX
            driverDelegateClass: org.quartz.impl.jdbcjobstore.oracle.OracleDelegate
            useProperties: false
            misfireThreshold: 60000
            clusterCheckinInterval: 5000
            isClustered: true
          threadPool:
            class: org.quartz.simpl.SimpleThreadPool
            threadCount: 10
            threadPriority: 5
            threadsInheritContextClassLoaderOfInitializingThread: true

Below is my logback-spring.xml file

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE configuration>
<configuration>

    <springProperty scope="context" name="app_name" source="spring.application.name"/>
    <springProperty scope="context" name="environment" source="param_env" defaultValue="default_env"/>
    <springProperty scope="context" name="tenant" source="param_tenant" defaultValue="default_tenant"/>

    <property name="GENERIC_PATTERN"
              value="[%date{ISO8601}] [%p] [%t] [%X{traceId:-}] [%X{orderId:-}] [%X{batchJobId:-}] [%X{username:-}] [%X{functional-context}] [%c{2}] %4L | %m%n"/>
    <property name="CONSOLE_LOG_PATTERN" value="$GENERIC_PATTERN"/>
    <property name="CHARSET" value="UTF-8"/>

    <property name="LOG_DIR"
              value="logs/${envname:-${environment}}/${param_dtlogname:-${app_name}}"/>

    <logger name="org.springframework" level="INFO"/>
    <logger name="org.springframework.web" level="INFO"/>
    <logger name="org.dt" level="INFO"/>
    <logger name="com.dt" level="INFO"/>

    <logger name="org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor"
            level="INFO"/>

    <logger name="org.springframework.security" level="INFO"/>
    <logger name="org.hibernate" level="INFO"/>

    <!-- Auto configuration report-->
    <logger name="org.springframework.boot.autoconfigure" level="DEBUG"/>
    <logger name="org.springframework.boot.autoconfigure.logging.ConditionEvaluationReportLoggingListener"
            level="TRACE"/>

    <springProfile name="local,component-test,component-test-security,scheduler-test">

        <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                <charset>${CHARSET}</charset>
                <pattern>${GENERIC_PATTERN}</pattern>
            </encoder>
        </appender>

        <logger name="zuul.web.request.logger" level="DEBUG" additivity="false">
            <appender-ref ref="CONSOLE"/>
        </logger>

        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
        </root>

    </springProfile>


        <appender name="FILE_APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender">

            <file>${LOG_DIR}/${param_dtlogname}-${HOSTNAME}.log</file>

            <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
                <!-- daily rollover -->
                <fileNamePattern>
                    ${LOG_DIR}/${param_dtlogname}-${HOSTNAME}.%d{yyyy-MM-dd}.%i.log
                </fileNamePattern>
                <maxFileSize>1GB</maxFileSize>
                <totalSizeCap>10GB</totalSizeCap>
                <!-- keep 30 days worth of history -->
                <maxHistory>30</maxHistory>
            </rollingPolicy>

            <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
                <providers>
                    <mdc/>
                    <pattern>
                        <omitEmptyFields>true</omitEmptyFields>
                        <pattern>
                            {
                            "app_name": "${app_name}",
                            "HOSTNAME":"${HOSTNAME}",
                            "environment":"${environment}"
                            }
                        </pattern>
                    </pattern>
                    <logLevel/>
                    <timestamp/>
                    <threadName/>
                    <logstashMarkers/>
                    <tags/>
                    <arguments/>
                    <version/>
                    <stackTrace/>
                    <loggerName/>
                    <threadName/>
                    <message/>
                </providers>
            </encoder>
        </appender>

        <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                <charset>${CHARSET}</charset>
                <pattern>${GENERIC_PATTERN}</pattern>
            </encoder>
        </appender>

        <appender name="CONSOLE_JSON" class="ch.qos.logback.core.ConsoleAppender">
            <encoder class="net.logstash.logback.encoder.LogstashEncoder">
                <fieldNames>
                    <timestamp>timestamp</timestamp>
                    <message>logdata</message>
                    <version>[ignore]</version>
                    <levelValue>[ignore]</levelValue>
                </fieldNames>
                <timeZone>UTC</timeZone>
            </encoder>
        </appender>

        <appender name="API_FILE_APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender">

            <file>${LOG_DIR}/api-${param_dtlogname}-${HOSTNAME}.log</file>
            <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
                <!-- daily rollover -->
                <fileNamePattern>
                    ${LOG_DIR}/api-${param_dtlogname}-${HOSTNAME}.%d{yyyy-MM-dd}.%i.log
                </fileNamePattern>
                <maxFileSize>1GB</maxFileSize>
                <totalSizeCap>10GB</totalSizeCap>
                <!-- keep 30 days worth of history -->
                <maxHistory>30</maxHistory>
            </rollingPolicy>

            <encoder class="net.logstash.logback.encoder.LogstashEncoder">
                <fieldNames>
                    <timestamp>[ignore]</timestamp>
                    <message>logdata</message>
                    <version>[ignore]</version>
                    <levelValue>[ignore]</levelValue>
                </fieldNames>
                <timeZone>UTC</timeZone>
            </encoder>
        </appender>

        <appender name="APPLICATION_FILE_APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender">

            <file>${LOG_DIR}/startup-${param_dtlogname}-${HOSTNAME}.log</file>
            <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
                <!-- daily rollover -->
                <fileNamePattern>
                    ${LOG_DIR}/startup-${param_dtlogname}-${HOSTNAME}.%d{yyyy-MM-dd}.%i.log
                </fileNamePattern>
                <maxFileSize>1GB</maxFileSize>
                <totalSizeCap>10GB</totalSizeCap>
                <!-- keep 30 days worth of history -->
                <maxHistory>30</maxHistory>
            </rollingPolicy>

            <encoder class="net.logstash.logback.encoder.LogstashEncoder">
                <fieldNames>
                    <timestamp>timestamp</timestamp>
                    <message>logdata</message>
                    <version>[ignore]</version>
                    <levelValue>[ignore]</levelValue>
                </fieldNames>
                <timeZone>UTC</timeZone>
            </encoder>
        </appender>

        <logger name="api.logger" level="INFO" additivity="false">
            <appender-ref ref="API_FILE_APPENDER"/>
        </logger>

        <logger name="application.startup.logger" level="INFO" additivity="false">
            <appender-ref ref="APPLICATION_FILE_APPENDER"/>
        </logger>

        <appender name="SENTRY" class="io.sentry.logback.SentryAppender">
            <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
                <level>ERROR</level>
            </filter>
            <encoder>
                <pattern>${GENERIC_PATTERN}</pattern>
            </encoder>
        </appender>

        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
            <appender-ref ref="FILE_APPENDER"/>
            <appender-ref ref="SENTRY"/>
        </root>
    </springProfile>
</configuration>

Can someone please help on this ?

1 Answers

where the issue lies in my spring boot app configuration ?

In logback.xml on the line

<property name="GENERIC_PATTERN"
      value="[%date{ISO8601}] [%p] [%t] [%X{traceId:-}] [%X{orderId:-}] [%X{batchJobId:-}] [%X{username:-}] [%X{functional-context}] [%c{2}] %4L | %m%n"/>

the following configurations produce those empty brackets.

[%X{traceId:-}] [%X{orderId:-}] [%X{batchJobId:-}] [%X{username:-}] [%X{functional-context}]

From an older thread

X{key:-defaultVal}

Outputs the MDC (mapped diagnostic context) associated with the thread that generated the logging event.

Your default value is empty for example in %X{traceId:-}. Also Spring when doing it's own logs does not even know about the key traceId in the logs which are written during startup. So you receive the printed log [].

You can either

  • put some default value X{traceId:-Unknown to Spring}

  • or exclude this pattern from the logback for classes that are logged by Spring it self.

You normally put the key to be printed in the logs in your own classes with

MDC.put("traceId", "your text");
Related