Spring boot สร้าง ID ให้กับ Log แต่ละ Request

Programming

Spring boot สร้าง ID ให้กับ Log แต่ละ Request

เมื่อประมาณ 3 ปีที่แล้วได้ผมเขียนเรื่องเกี่ยวกับ Log ว่ามันควรจะ Log ยังไงต่างๆนาๆ ซึ่งผมก็พยายามทำตาม ตามกำลังที่ตัวเองพอจะทำได้ เพื่อที่เวลาเกิดปัญหาจะได้ตามหาปัญหาที่เกิดได้ง่ายๆ ซึ่งมันก็อยู่ในระดับที่โอเคพอหาได้ แต่ปัญหาเกี่ยวกับการอ่าน Log ก็ยังมีอยู่ไม่ได้หมดไป

1 Request ที่เข้ามามันทำงานหลายที่ใน Application

ปัญหานี้มันเริ่มมาจากการที่เราเขียน Code แยกเป็นส่วนๆ แล้วแบ่งกันไปทำงาน ดังนั้น เวลาทำงาน Code มันส่งไปทำงานหลายส่วน ดังนั้น 1 Request ที่มาจาก Client นั้นมันผ่านไปทำงานหลายส่วน คราวนี้เวลาเกิดปัญหาเนี่ย มันรู้แหละว่าเกิดปัญหาที่ไหน แต่ประเด็นที่มักเจอคือ มันไปผ่านอะไรมาบ้างก่อนหน้านี้ทำให้เกิดเรื่องขึ้น ซึ่งจริงๆ trace log นี่มันบอกว่าผ่านอะไรมาบ้าง แต่มันเป็น Line number of code เวลาดูต้องเปิด code ไล่ดูด้วย อีกทั้งแต่ละส่วนที่ผ่านมันอาจไม่ได้ใช้ Key ที่เราใช้หาเวลาเกิดปัญหาเช่น มันเกิดปัญหาเกี่ยวกับ Order ที่ OrderId เลขนี้ แต่การตัดสินใจต่างๆมันตัดสินใจว่า Order จะดำเนินการได้มันไปอยู่ที่หลายส่วนที่พิจารณา และในบางส่วนมันไม่ได้จำเป็นต้องใช้ OrderId ในกระบวนการการทำงานทำให้เวลาเรา Grep Log ด้วย OrderId Log ในส่วนที่ไม่มี OrderId นี้ก็ไม่ขึ้นมาแสดงให้ดูด้วย ทำให้เวลาไล่ดู Log ต้องใช้ความรู้ความเข้าใจเกี่ยวกับ Flow ของ Program มากขึ้นด้วยเช่น ต้อง Grep ด้วย OrderId จากนั้น Grep ต่อด้วยส่วนที่ใช้ที่เกี่ยวข้องต้องดูเวลาที่ใกล้เคียง ทำให้คนที่ดูแลระบบอาจต้องเป็น Dev ไปด้วย

ตัวอย่าง Log

อันนี้เป็นตัวอย่าง Log ที่ผมจำลองขึ้นมา การทำงานของมันก็ประมาณว่า TestController -> OrderService -> UserService

1
2
3
4
5
6
7
8
9
10
11
12
13
14
2020-06-20 20:58:05.855  INFO  --- blog.surapong.example.logproblem.api.controller.TestController : TEST_LOG orderId : 5678 BEGIN
2020-06-20 20:58:05.855  INFO  --- blog.surapong.example.logproblem.service.OrderService : Complete order orderId : 5678 BEGIN COMPLETE ORDER ORDER
2020-06-20 20:58:05.856  INFO  --- blog.surapong.example.logproblem.service.OrderService : Complete order orderId : 5678 Check user userId : a8caf905-4116-44cf-9fc7-572b96b11e96
2020-06-20 20:58:07.850  INFO  --- blog.surapong.example.logproblem.api.controller.TestController : TEST_LOG orderId : 1234 BEGIN
2020-06-20 20:58:07.850  INFO  --- blog.surapong.example.logproblem.service.OrderService : Complete order orderId : 1234 BEGIN COMPLETE ORDER ORDER
2020-06-20 20:58:07.850  INFO  --- blog.surapong.example.logproblem.service.OrderService : Complete order orderId : 1234 Check user userId : c75043d4-064a-4c41-8b5d-549ceee72914
2020-06-20 20:58:09.247  INFO  --- blog.surapong.example.logproblem.service.UserService : Check user  userId : c75043d4-064a-4c41-8b5d-549ceee72914 BEGIN 
2020-06-20 20:58:09.247  INFO  --- blog.surapong.example.logproblem.service.UserService : Check user  userId : c75043d4-064a-4c41-8b5d-549ceee72914 FINISH 
2020-06-20 20:58:09.247  INFO  --- blog.surapong.example.logproblem.service.OrderService : Complete order orderId : 1234 END COMPLETE ORDER
2020-06-20 20:58:09.247  INFO  --- blog.surapong.example.logproblem.api.controller.TestController : TEST_LOG orderId : 1234 END
2020-06-20 20:58:13.026  INFO  --- blog.surapong.example.logproblem.service.UserService : Check user  userId : a8caf905-4116-44cf-9fc7-572b96b11e96 BEGIN 
2020-06-20 20:58:13.026  INFO  --- blog.surapong.example.logproblem.service.UserService : Check user  userId : a8caf905-4116-44cf-9fc7-572b96b11e96 FINISH 
2020-06-20 20:58:13.026  INFO  --- blog.surapong.example.logproblem.service.OrderService : Complete order orderId : 5678 END COMPLETE ORDER
2020-06-20 20:58:13.026  INFO  --- blog.surapong.example.logproblem.api.controller.TestController : TEST_LOG orderId : 5678 END

พอมาอ่าน Log ก็จะเริ่มงงๆว่า เฮ้ย ตกลง orderId 5678 มันไปคู่กับ userId ไหนกันแน่หว่า เพราะเราไม่สามารถเชื่อลำดับได้เพราะ Request มันเข้ามาใกล้ๆกันตอนไปเรียกเช็ค user ตัว UserService ก็ไม่ได้รับตัวแปร orderId มา log ด้วย (ก็มันทำไว้กลางๆ ไม่ได้เจาะจงว่าให้ OrderService ใช้) จริงๆปัญหานี้แก้ได้โดย OrderService ควรจะ Log ด้วยว่า userId ที่จะส่งไปตรวจสอบคืออะไร จะได้รู้ ซึ่งจริงๆคนเขียน Code บางทีเขาก็ไม่รู้หรอกว่ามันจะเกิดปัญหาอะไรบ้าง ส่วนใหญ่เขาก็ Log ประมาณว่ามันกำลังทำอะไรอยู่ บางทีเขาไม่รู้ว่ามันจะเกิดปัญหากับ UserService เลยไม่ได้ Log userId ไว้คู่กับ orderId

ปัญหาแบบนี้มีคนคิดวิธีแก้ไว้แล้ว

ปัญหาของเราคือต้องการมีตัวอ้างอิงให้ Log ของแต่ละ Request จะได้ดู Log ง่ายๆ ซึ่งปัญหาแบบนี้มีหลายคนเจอแน่นอนและแน่นอนชาวโปรแกรมเมอร์ของโลกย่อมลุกขึ้นมาแก้ไขและบอกต่อ โดยผมเป็นคนเขียน java ด้วย spring boot จึงไป search หาวิธีการ config จึงเจอว่ามีคนทำแล้ว โดยเขาใช้ความสามารถของ SLFJ Log และการใช้ Filter ซึ่งเมื่อทำการ Config ตามทำให้เราได้ Log แบบนี้

1
2
3
4
5
6
7
8
9
10
11
12
13
14
2020-06-20 21:36:53.976  INFO 004E4E7AE9FE47E9BBAAAA5A078608F2 --- blog.surapong.example.logproblem.api.controller.TestController : TEST_LOG orderId : 1234 BEGIN
2020-06-20 21:36:53.976  INFO 004E4E7AE9FE47E9BBAAAA5A078608F2 --- blog.surapong.example.logproblem.service.OrderService : Complete order orderId : 1234BEGIN COMPLETE ORDER ORDER
2020-06-20 21:36:53.976  INFO 004E4E7AE9FE47E9BBAAAA5A078608F2 --- blog.surapong.example.logproblem.service.OrderService : Complete order orderId : 1234Check user userId : 27dc9962-20c8-4f1a-80fa-fe5235baa43f
2020-06-20 21:36:55.262  INFO 6E81515230B941ECAEE47438BE2C9370 --- blog.surapong.example.logproblem.api.controller.TestController : TEST_LOG orderId : 5678 BEGIN
2020-06-20 21:36:55.262  INFO 6E81515230B941ECAEE47438BE2C9370 --- blog.surapong.example.logproblem.service.OrderService : Complete order orderId : 5678 BEGIN COMPLETE ORDER ORDER
2020-06-20 21:36:55.262  INFO 6E81515230B941ECAEE47438BE2C9370 --- blog.surapong.example.logproblem.service.OrderService : Complete order orderId : 5678 Check user userId : 7d6ca7e1-4dfa-4aee-9f75-93eb451fbeab
2020-06-20 21:36:59.203  INFO 004E4E7AE9FE47E9BBAAAA5A078608F2 --- blog.surapong.example.logproblem.service.UserService : Check user  userId : 27dc9962-20c8-4f1a-80fa-fe5235baa43f BEGIN 
2020-06-20 21:36:59.203  INFO 004E4E7AE9FE47E9BBAAAA5A078608F2 --- blog.surapong.example.logproblem.service.UserService : Check user  userId : 27dc9962-20c8-4f1a-80fa-fe5235baa43f FINISH 
2020-06-20 21:36:59.203  INFO 004E4E7AE9FE47E9BBAAAA5A078608F2 --- blog.surapong.example.logproblem.service.OrderService : Complete order orderId : 1234 END COMPLETE ORDER
2020-06-20 21:36:59.203  INFO 004E4E7AE9FE47E9BBAAAA5A078608F2 --- blog.surapong.example.logproblem.api.controller.TestController : TEST_LOG orderId : 1234 END
2020-06-20 21:37:01.167  INFO 6E81515230B941ECAEE47438BE2C9370 --- blog.surapong.example.logproblem.service.UserService : Check user  userId : 7d6ca7e1-4dfa-4aee-9f75-93eb451fbeab BEGIN 
2020-06-20 21:37:01.167  INFO 6E81515230B941ECAEE47438BE2C9370 --- blog.surapong.example.logproblem.service.UserService : Check user  userId : 7d6ca7e1-4dfa-4aee-9f75-93eb451fbeab FINISH 
2020-06-20 21:37:01.167  INFO 6E81515230B941ECAEE47438BE2C9370 --- blog.surapong.example.logproblem.service.OrderService : Complete order orderId : 5678END COMPLETE ORDER
2020-06-20 21:37:01.167  INFO 6E81515230B941ECAEE47438BE2C9370 --- blog.surapong.example.logproblem.api.controller.TestController : TEST_LOG orderId : 5678 END

จะเห็นว่าหลัง INFO จะมีเลขยาวๆโผล่ขึ้นมา ซึ่งเลขนี้เป็นเลข ID ของแต่ละ Request นั่นเองคราวนี้เราสามารถ Grep log ด้วยเลข ID นี้ ทำให้ได้ Log ที่เกี่ยวข้องกับ Request นี้ทั้งหมด

เพิ่ม Lib ลงใน pom.xml

เพิ่มตัว Log4j2 ให้กับ Project และบอกให้ spring boot ไม่ใช้ log ของตัวเอง ให้ไปใช้ log ของ log4j2

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
<dependencies>

<!--> 
Another lib
<-->

<!-- Exclude Spring Boot's Default Logging -->
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter</artifactId>
			<exclusions>
				<exclusion>
					<groupId>org.springframework.boot</groupId>
					<artifactId>spring-boot-starter-logging</artifactId>
				</exclusion>
			</exclusions>
		</dependency>

		<!-- Add Log4j2 Dependency -->
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-log4j2</artifactId>
		</dependency>
</dependencies>

สร้าง Filter และ เพิ่ม Filter เข้าไป

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
// สร้าง Filter class

public class Slf4jMDCFilter extends OncePerRequestFilter {
    @Override
    protected void doFilterInternal(final HttpServletRequest request, final HttpServletResponse response, final FilterChain chain)
            throws java.io.IOException, ServletException {

        final String mdcTokenKey = "Slf4jMDCFilter.UUID";
        try {
            final String token = UUID.randomUUID().toString().toUpperCase().replace("-", "");
            MDC.put(mdcTokenKey, token);
            chain.doFilter(request, response);
        } finally {
            MDC.remove(mdcTokenKey);
        }
    }
}
1
2
3
4
5
6
7
8
9
10
11
12
13
@Configuration
public class FilterConfig {

    @Bean
    public FilterRegistrationBean servletRegistrationBean() {
        final FilterRegistrationBean registrationBean = new FilterRegistrationBean();
        final Slf4jMDCFilter log4jMDCFilterFilter = new Slf4jMDCFilter();
        registrationBean.setFilter(log4jMDCFilterFilter);
        registrationBean.setOrder(2);
        return registrationBean;
    }

}

Config ตัว log4j2.xml

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN" monitorInterval="30">
    <Properties>
        <Property name="LOG_PATTERN">
            %d{yyyy-MM-dd HH:mm:ss.SSS} %5p %X{Slf4jMDCFilter.UUID} --- %-50c : %m%n%ex
        </Property>
    </Properties>
    <Appenders>
        <Console name="ConsoleAppender" target="SYSTEM_OUT" follow="true">
            <PatternLayout pattern="${LOG_PATTERN}"/>
        </Console>
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="ConsoleAppender" />
        </Root>
    </Loggers>
</Configuration>

ลองสังเกตตรง Slf4jMDCFilter.UUID ในไฟล์ log4j2.xml นั้นจะตรงกับ final String mdcTokenKey = “Slf4jMDCFilter.UUID”; ใน class : Slf4jMDCFilter ซึ่งหากอ่าน Code มันคือการ Register UUID ที่สร้างขึ้นมาไปใส่ใน key ที่ชื่อ Slf4jMDCFilter.UUID ซึ่งเมื่อทำการ Log ตัว Log4j2 จะเอาค่าไปแทนตาม Pattern ที่กำหนดไว้นั่นเอง

สรุป

สำหรับตอนนี้เป็นวิธีการทำให้ Spring boot สร้าง ID ให้กับ Log แต่ละ Request ซึ่งจากวิธีการทำนั้นไม่ยากเลย คราวนี้ก็ช่วยให้เรา Grep log ได้ง่ายขึ้น ในส่วนของภาษาอื่นนั้น เดี๋ยวขอผมไปลองหาดูว่าทำยังไง ถ้าเจอแล้วทำไม่ยากเดี๋ยวผมมาเขียนเป็นตอนใหม่ครับ

แนะนำไอดอล

Toktak

Toktak

เพลงประกอบการเขียน Blog

เป็นเพลงที่ฟังครั้งแรกแล้วรู้สึกชอบมากๆ ทั้งๆดนตรี เสียงประสาน ความหมายของเพลง คือแบบ โอ้ยได้อารมณ์มาก แถมท่อน Rap นี่ใส่มาแบบจริงจังไม่ได้ใส่เล่นๆเอากระแส ส่วน MV นี่ยิ่งโคตรโดนไปใหญ่ เล่นทั้ง JOJO , Forest gump ดูแล้วฮาไปอีก

ref :

https://www.greeneyed.org/post/spring-boot-setting-a-unique-id-per-request/