Contents

Few tips to improve logging

This post is inspired in this post

Introduce

Here is a default Logback’s console pattern of Spring Boot.

1
${CONSOLE_LOG_PATTERN:-%clr(%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}

And its output:

1
2
3
2020-12-08 22:12:49.269  INFO 17092 --- [    Test worker] c.h.logging.controller.DemoController    : This is a INFO log
2020-12-08 22:12:49.270  WARN 17092 --- [    Test worker] c.h.logging.controller.DemoController    : This is a WARN log
2020-12-08 22:12:49.270 ERROR 17092 --- [    Test worker] c.h.logging.controller.DemoController    : This is a ERROR log

It’s so cool but we add some modifications by extending ch.qos.logback.classic.PatternLayout to make it greater.

1
2
3
4
public class GreatPatternLayout extends PatternLayout {
  static {
  }
}

Finally layout, pattern and output:

1
%d{yyyy-MM-dd HH:mm:ss.SSS, UTC} %level ${PID:- } [%user %session] [%t] %-40.40logger{39}@%method:%line - %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}
1
2
3
4
5
2020-12-11 15:02:04.398 D 17597 [admin BE8F11][nio-8080-exec-1] c.h.logging.controller.DemoController   @currentUserName:27 - This is a DEBUG log
2020-12-11 15:02:04.417 I 17597 [admin BE8F11][nio-8080-exec-1] c.h.logging.controller.DemoController   @currentUserName:28 - This is a INFO log
2020-12-11 15:02:04.418 W 17597 [admin BE8F11][nio-8080-exec-1] c.h.logging.controller.DemoController   @currentUserName:29 - This is a WARN log
2020-12-11 15:02:04.419 E 17597 [admin BE8F11][nio-8080-exec-1] c.h.logging.controller.DemoController   @currentUserName:30 - This is a ERROR log
2020-12-11 15:02:04.430 E 17597 [admin BE8F11][nio-8080-exec-1] c.hukacode.logging.aop.ExecutionLogging @logException:42 - ->class com.hukacode.logging.controller.DemoController.currentUserName(input=abc, request=SecurityContextHolderAwareRequestWrapper[ org.springframework.security.web.header.HeaderWriterFilter$HeaderWriterRequest@4739d1f8])

Who was doing this?

  • We can answer this question by getting Username/ID from SecurityContext. We do it by extend ch.qos.logback.classic.pattern.ClassicConverter.
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
public class UserConverter extends ClassicConverter {
  @Override
  public String convert(ILoggingEvent iLoggingEvent) {
    var authentication = SecurityContextHolder.getContext().getAuthentication();
    if (authentication == null) {
      return "";
    } else {
      return authentication.getName();
    }
  }
}
  • We also can add Session into log
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
public class SessionConverter extends ClassicConverter {
  @Override
  public String convert(ILoggingEvent event) {
    var attrs = RequestContextHolder.getRequestAttributes();

    if (attrs != null) {
      return attrs.getSessionId().substring(0, Math.min(6, attrs.getSessionId().length()));
    }

    return "";
  }
}

Then put new Converters into GreatPatternLayout class

1
2
3
4
5
6
public class GreatPatternLayout extends PatternLayout {
  static {
    PatternLayout.defaultConverterMap.put("user", UserConverter.class.getName());
    PatternLayout.defaultConverterMap.put("session", SessionConverter.class.getName());
  }
}

Where did it happen?

Print method and line number

1
@%method:%line

When did it occur?

  1. Use UTC
1
d{yyyy-MM-dd HH:mm:ss.SSS, UTC}
  1. Or add Timezone
1
d{yyyy-MM-dd HH:mm:ss.SSSZZZ}

What is going on?

  • We can use 1 letter instead of using (ERROR, WARN, INFO, DEBUG, TRACE)
1
2
3
4
5
6
public class ShortLevelConverter extends ClassicConverter {
  @Override
  public String convert(ILoggingEvent iLoggingEvent) {
    return iLoggingEvent.getLevel().toString().substring(0, 1);
  }
}
1
2
3
4
5
6
7
public class GreatPatternLayout extends PatternLayout {
  static {
    PatternLayout.defaultConverterMap.put("user", UserConverter.class.getName());
    PatternLayout.defaultConverterMap.put("session", SessionConverter.class.getName());
    PatternLayout.defaultConverterMap.put("level", ShortLevelConverter.class.getName());
  }
}
  • Create log files for each level INFO and WARN/ERROR
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
<appender name="LOG_INFO" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <file>${LOG_FILE_INFO}</file>
  <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
    <fileNamePattern>${LOG_FILE_INFO}.%d{yyyy-MM-dd}.log.zip</fileNamePattern>
    <!-- Days to keep -->
    <maxHistory>7</maxHistory>
    <!-- total size of all archive files, if total size > N, it will delete old archived file -->
    <totalSizeCap>2GB</totalSizeCap>
  </rollingPolicy>
  <filter class="ch.qos.logback.classic.filter.LevelFilter">
    <level>INFO</level>
    <onMatch>ACCEPT</onMatch>
    <onMismatch>DENY</onMismatch>
  </filter>
  <encoder name="enc" class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
    <layout class="com.hukacode.logging.logback.GreatPatternLayout">
      <pattern>
        ${FILE_LOG_PATTERN}
      </pattern>
    </layout>
    <charset>utf8</charset>
  </encoder>
</appender>
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
<appender name="LOG_ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <file>${LOG_FILE_ERROR}</file>
  <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
    <fileNamePattern>${LOG_FILE_ERROR}.%d{yyyy-MM-dd}.log.zip</fileNamePattern>
    <!-- Days to keep -->
    <maxHistory>7</maxHistory>
    <!-- total size of all archive files, if total size > N, it will delete old archived file -->
    <totalSizeCap>2GB</totalSizeCap>
  </rollingPolicy>
  <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
    <level>ERROR</level>
  </filter>
  <encoder name="enc" class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
    <layout class="com.hukacode.logging.logback.GreatPatternLayout">
      <pattern>
        ${FILE_LOG_PATTERN}
      </pattern>
    </layout>
    <charset>utf8</charset>
  </encoder>
</appender>

Why did it happen?

// TODO

How did it happen?

When an exception occurs, we want to print all of the input parameters. We can achieve it by using Spring AOP

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
@Aspect
public class ExecutionLogging {
  @Pointcut("execution(* com.hukacode.logging.controller.*.*(..))")
  public void controllerMethods() {}

  @AfterThrowing(value = "controllerMethods()", throwing = "exception")
  public void logException(JoinPoint joinPoint, Exception exception) throws Throwable {
    // ommitted
  }
}

Source code

Demo here

1
2
gradle bootRun
curl http://localhost:8080/api/me?input=abc

References

https://github.com/onready/demo-spring-security-logging-pattern

🔗 Backlinks