๐ป Programming/Java
[5๋ถ์ฝ๋ฉ] Filter๋ฅผ ์ด์ฉํ ์์ฒญ,์๋ต ๋ก๊น (How to log request, response info inlcuding payload using filter) - (1/2)
๊ฐ๋ฐ์๋ก์ ์ด์์ด์๋ฅผ ํด๊ฒฐํ๊ธฐ ์ํด์๋ ๋ก๊ทธ๋ฉ์์ง๊ฐ ๋๋ฒ๊น ์ ์ํด์ ๊ผญ ํ์ํ๋ค๋๊ฑด ๋๊ตฌ๋ ์๊ณ ๊ณ์ค๊ฒ๋๋ค.
ํ์ง๋ง ๋ก๊น ์ ์ ํ๊ธฐ ์ํด์๋ ๋ง์ ๊ณ ๋ฏผ์ด ํ์ํฉ๋๋ค.
๋ก๊ทธ๋ ๋ฒจ์ ์ด๋ป๊ฒ ํ ์ง ๋ก๊ทธ์ ๋ด์ฉ์ ์ด๋ค ์ ๋ณด๋ค๋ก ์ฑ์๋ฃ์์ง ๋ฑ๋ฑ ๋ง์ด์ฃ .
๋ก๊ทธ๋ ๋ง์ด ๋จ๊ธด๋ค๊ณ ์ข์๊ฒ ์๋์ฃ .
์ด๋ค ๋ถ๋ค์ ์๋ฌด๋ฐ ์๋ฏธ๋ ์๋ ์ ๋ณด๋ฅผ ๋ก๊น ํ๊ธฐ๋ ํฉ๋๋ค.
๋น์ฉ์ ์ธ ์ธก๋ฉด์ด ๋ฌธ์ ๋์ง ์๋๋ค๋ฉด ๋๋์ ๋ก๊ทธ๋ฅผ ๋ง์๊ป ๋จ๊ฒจ๋ ๋๊ฒ ์ง๋ง ํ์ค์ ๊ทธ๋ ์ง ์์ฃ .
๋ฐ๋ผ์ ์ค์๋์ ๋ฐ๋ผ์ ์ ๋น~~ํ ์ต์ํ์ ๋ด์ฉ๋ง ๋ก๊น ํ๋๊ฒ ์ข์ต๋๋ค.
๋ก๊ทธ ์ค์์ ๊ฐ์ฅ ์ค์ํ ๋ก๊ทธ๋ ์์ฒญ๊ณผ ์๋ต์ ๋ํ ๊ฒ์ ๋๋ค.
API ์์ฒญ์ ์ด๋ค ์ ๋ณด๋ฅผ ์ ๋ฌ๋ฐ์๋์ง์ ๋ํ request log๊ณผ
๊ทธ ๋ฐ์ดํฐ๋ฅผ ๊ธฐ์ค์ผ๋ก ๋น์ฆ๋์ค ๋ก์ง์ ํ์ด ๋ค์ ์ด๋ค ์๋ต์ ๋ด์ฃผ์๋์ง
response log ๋ง ์์ด๋ ๋๋ฒ๊น ์ ์ถฉ๋ถํ ๊ฐ๋ฅํ์ฃ .
๋ฌผ๋ก ์์ฒญ๊ณผ ์๋ต ์ค๊ฐ์ ๋ก์ง์ด ๋ณต์กํ๋ค๋ฉด ์ค๊ฐ์ค๊ฐ ์ถ๊ฐ์ ์ธ ๋ก๊ทธ๋ฅผ ์ฌ์ด์ฃผ๋๊ฒ ๋ง์ ๋์์ด ๋ ์ ์์ต๋๋ค.
๊ทธ๋์ ์ด๋ฒ ํฌ์คํ ์์๋ ์์ฒญ๊ณผ ์๋ต์ ์ด๋ป๊ฒ ๋ก๊น ํ๋์ง์ ๋ํด ๊ณต์ ๋๋ฆฌ๊ณ ์ ํฉ๋๋ค.
1. ํ๋ก์ ํธ ์์ฑ
๊ธฐ๋ณธ์ ์ธ ๊ฐ๋ฐํ๊ฒฝ์ ์๋์ ๊ฐ์ต๋๋ค.
- IntelliJ IDEA 2021.3.3 (Ultimate Edition)
- SpringBoot 2.7.3
- Java 18 (OpenJDK)
์, ์ฐ์ ๊นกํต ํ๋ก์ ํธ๋ฅผ ๋ง๋ค๊ฒ ์ต๋๋ค.
์, ๊นกํต ํ๋ก์ ํธ๊ฐ ์์ฑ๋์์ต๋๋ค.
2. ๋ผ์ด๋ธ๋ฌ๋ฆฌ ์ถ๊ฐ
์ด์ ๊ฐ๋ฐํธ์๋ฅผ ์ํด lombok๊ณผ ๋ก๊น ์ ์ํ logback ๋ผ์ด๋ธ๋ฌ๋ฆฌ๋ฅผ ์ถ๊ฐํ๊ณ , API ๊ฐ๋ฐ์ ์ํด spring-boot-starter-web ๋ผ์ด๋ธ๋ฌ๋ฆฌ๋ฅผ ์ถ๊ฐํ๊ฒ ์ต๋๋ค.
implementation 'org.springframework.boot:spring-boot-starter-web'
implementation 'org.projectlombok:lombok:1.18.24'
annotationProcessor 'org.projectlombok:lombok:1.18.24'
implementation 'ch.qos.logback:logback-classic:1.2.11'
3. API ์์ฑ
๊ทธ๋ฆฌ๊ณ ์๋์ ๊ฐ์ด ํ ์คํธ์ฉ ์ปจํธ๋กค๋ฌ๋ฅผ ํ๋ ์์ฑํด์ค๋๋ค.
package com.keichee.demo.controller;
import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.*;
@Slf4j
@RestController
@RequestMapping("/test")
public class TestController {
@GetMapping("/log")
public int requestResponseLog(@RequestParam int code) {
log.info("requestResponseLog method called with code {}", code);
return code;
}
}
์ฌ๊ธฐ๊น์งํ๊ณ ์ฑ์ ๊ธฐ๋ํ ๋ค API๋ฅผ ํธ์ถํ์ฌ ๋ก๊ทธ๊ฐ ์ ๋จ๋์ง ํ์ธํด๋ณผ๊ฒ์.
2022-09-15 17:04:50.580 INFO 92637 --- [ main] com.keichee.demo.DemoLoggingApplication : No active profile set, falling back to 1 default profile: "default"
2022-09-15 17:04:51.034 INFO 92637 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2022-09-15 17:04:51.038 INFO 92637 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2022-09-15 17:04:51.038 INFO 92637 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.65]
2022-09-15 17:04:51.105 INFO 92637 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2022-09-15 17:04:51.107 INFO 92637 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 495 ms
2022-09-15 17:04:51.306 INFO 92637 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
2022-09-15 17:04:51.312 INFO 92637 --- [ main] com.keichee.demo.DemoLoggingApplication : Started DemoLoggingApplication in 0.879 seconds (JVM running for 1.294)
2022-09-15 17:05:56.173 INFO 92637 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2022-09-15 17:05:56.173 INFO 92637 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2022-09-15 17:05:56.174 INFO 92637 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 1 ms
2022-09-15 17:05:56.186 INFO 92637 --- [nio-8080-exec-1] c.k.demo.controller.TestController : requestResponseLog method called with code 2
์ ์ผ ๋ง์ง๋ง์ค์ ๋ณด๋ฉด TestController์์ ์ถ๋ ฅํ ๋ก๊ทธ๊ฐ ๋ณด์ด๋ค์.
๋น์ฆ๋์ค ๋ก์ง์ ๋ก๊ทธ๋ ์ ์ถ๋ ฅ๋๊ณ ์์ผ๋ ์ด์ ๊ธฐ๋ณธ์ ์ธ ์ค๋น๊ฐ ๋๋ฌ์ต๋๋ค.
4. Filter ๊ตฌํ
์์ฒญ๊ณผ ์๋ต์ ๋ํ ๋ก๊ทธ์ถ๋ ฅ์ ์ํด์ ์ฐ๋ฆฌ๋ Filter๋ฅผ ์ด์ฉํ ๊ฒ๋๋ค.
spring-web์์๋ ์๋์ ๊ฐ์ด ์ฌ๋ฌ ์ข ๋ฅ์ filter๋ฅผ ์ ๊ณตํ๊ณ ์์ต๋๋ค.
AbstractRequestLoggingFilter
CharacterEncodingFilter
CommonsRequestLoggingFilter
CompositeFilter
CorsFilter
DelegatingFilterProxy
FormContentFilter
ForwardedHeaderFilter
GenericFilterBean
HiddenHttpMethodFilter
HttpPutFormContentFilter
OncePerRequestFilter
RelativeRedirectFilter
RelativeRedirectResponseWrapper
RequestContextFilter
ServletContextRequestLoggingFilter
ServletRequestPathFilter
ShallowEtagHeaderFilter
์ฌ๊ธฐ์ request logging๊ณผ ๊ด๋ จ๋ filter๋ AbstractRequestLoggingFilter, CommonsRequestLoggingFilter, ๊ทธ๋ฆฌ๊ณ ServletContextRequestLoggingFilter ๊ฐ ์์ต๋๋ค.
์ฐ๋ฆฌ๋ AbstractRequestLoggingFilter๋ฅผ ์์ํด์ ์ฐ๋ฆฌ๋ง์ ํํฐ๋ฅผ ๋ง๋ค์ด ๋ณผ๊ฑฐ์์.
com.keichee.demo ํจํค์ง ์๋์ filter ํจํค์ง๋ฅผ ๋ง๋ค๊ณ ์ด ์์ RequestLoggingFilter ๋ผ๋ ํด๋์ค๋ฅผ ์๋์ ๊ฐ์ด ๋ง๋ค์ด์ฃผ์ธ์
package com.keichee.demo.filter;
import lombok.extern.slf4j.Slf4j;
import org.springframework.web.filter.AbstractRequestLoggingFilter;
import org.springframework.web.util.ContentCachingRequestWrapper;
import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
@Slf4j
public class RequestLoggingFilter extends AbstractRequestLoggingFilter {
@Override
protected void beforeRequest(HttpServletRequest request, String message) {
logger.info(message);
}
@Override
protected void afterRequest(HttpServletRequest request, String message) {
logger.info(message);
}
}
์ด์ ์ด ํํฐ๋ฅผ ๋น์ผ๋ก ๋ฑ๋กํด์ค์ผ ํฉ๋๋ค.
com.keichee.demo ํจํค์ง ์๋์ config ํจํค์ง๋ฅผ ๋ง๋ค๊ณ ์ด ์์ RequestLoggingConfig ํด๋์ค๋ฅผ ๋ง๋ค๊ฒ ์ต๋๋ค.
package com.keichee.demo.config;
import com.keichee.demo.filter.RequestLoggingFilter;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
@Configuration
public class RequestLoggingConfig {
public static int MAX_PAYLOAD_LENGTH = 1000;
@Bean
public RequestLoggingFilter loggingFilter() {
RequestLoggingFilter filter = new RequestLoggingFilter();
filter.setIncludeClientInfo(true);
filter.setIncludeHeaders(false);
filter.setIncludePayload(true);
filter.setIncludeQueryString(true);
filter.setMaxPayloadLength(MAX_PAYLOAD_LENGTH);
return filter;
}
}
ํค๋์ ๋ณด ๋ก๊น ์ด ํ์ํ ๊ฒฝ์ฐ setIncludeHeaders(true)๋ก ์ค์ ํด์ฃผ์๋ฉด ๋ฉ๋๋ค.
payload์ max length๋ ๋ก๊น ๋๊ณผ ๋ก๊ทธ๋ฅผ ์ ์ฅํ๋ ์์คํ ์ ์ฉ๋ ๋ฑ์ ๋ฐ๋ผ ์ ๋นํ ์ค์ ํด์ฃผ์๋ฉด๋ฉ๋๋ค.
์ด์ ๋ง์ง๋ง ํ์คํ ์ด ๋จ์์ต๋๋ค.
logback-spring.xml ํ์ผ์ resources ๋๋ ํ ๋ฆฌ์ ์ถ๊ฐํด์ค๋๋ค.
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
<include resource="org/springframework/boot/logging/logback/console-appender.xml"/>
<springProfile name="local">
<logger name="com.keichee.demo" level="debug" additivity="false">
<appender-ref ref="CONSOLE"/>
</logger>
<root level="error">
<appender-ref ref="CONSOLE"/>
</root>
</springProfile>
</configuration>
์ง๊ธ๊น์ง ์์ฑํ ํ์ผ๋ค์ ํฌํจํ์ฌ ์ต์ข ์ ์ผ๋ก ํจํค์ง ํธ๋ฆฌ๋ฅผ ๋ณด๋ฉด ์๋์ ๊ฐ์ต๋๋ค.
์ด์ active profile ๊ฐ์ local ์ ์ฃผ๊ณ ์ฑ์ ์ฌ๊ธฐ๋ํ๋ค ํํฐ๊ฐ ์ ์์ ์ผ๋ก ์ ์ฉ๋์๋์ง ํ์ธํด๋ณด๊ฒ ์ต๋๋ค.
2022-09-16 07:28:54.399 DEBUG 31518 --- [ main] com.keichee.demo.DemoLoggingApplication : Running with Spring Boot v2.7.3, Spring v5.3.22
2022-09-16 07:28:54.399 INFO 31518 --- [ main] com.keichee.demo.DemoLoggingApplication : The following 1 profile is active: "local"
2022-09-16 07:28:54.751 DEBUG 31518 --- [ main] c.k.demo.filter.RequestLoggingFilter : Filter 'loggingFilter' configured for use
2022-09-16 07:28:54.866 INFO 31518 --- [ main] com.keichee.demo.DemoLoggingApplication : Started DemoLoggingApplication in 0.607 seconds (JVM running for 0.819)
์ถ๋ ฅ๋๋ ๋ก๊ทธ ์ค์ Filter 'loggingFilter' configured for use ๊ฐ ์ถ๋ ฅ๋๊ฑธ๋ก ๋ณด์ ์ ์์ ์ผ๋ก ์ ์ฉ์ด ๋ ๊ฒ์ผ๋ก ํ์ธ๋ฉ๋๋ค.
์ด์ ๊ธฐ์กด์ ๋ง๋ค์ด ๋์๋ API๋ฅผ ๋ค์ ํธ์ถํด๋ณด๊ฒ ์ต๋๋ค.
2022-09-16 07:29:18.541 INFO 31518 --- [nio-8080-exec-2] c.k.demo.filter.RequestLoggingFilter : Before request [GET /test/log?code=2, client=0:0:0:0:0:0:0:1]
2022-09-16 07:29:18.550 INFO 31518 --- [nio-8080-exec-2] c.k.demo.controller.TestController : requestResponseLog method called with code 2
2022-09-16 07:29:18.560 INFO 31518 --- [nio-8080-exec-2] c.k.demo.filter.RequestLoggingFilter : After request [GET /test/log?code=2, client=0:0:0:0:0:0:0:1]
์์ฒญ์ ๋ํ ์ ๋ณด uri์ query parameter ๊ทธ๋ฆฌ๊ณ client์ X-Forwarded-For ๊ฐ์ด ์ถ๋ ฅ๋ ๊ฒ์ ๋ณผ ์ ์๊ณ , ๋น์ฆ๋์ค ๋ก์ง ์คํ์ด ๋๋ ๋ค ์์์๊ฐ์ด ์ผ๋ง์ธ์ง http status ๊ฐ์ด ๋ญ์ง ์ถ๋ ฅ๋๋ ๊ฒ์ ํ์ธํ ์ ์์ต๋๋ค.
์ง๊ธ๊น์ง ์์ฒญ์ ๋ํ uri, query parameter์ API๋ฅผ ์์ฒญํ ํด๋ผ์ด์ธํธ์ IP ๋ฅผ ์ถ๋ ฅํ๊ณ ,
์๋ต์ ์ฃผ๊ธฐ๊น์ง์ ์์์๊ฐ๊ณผ ์๋ต ์ํ๊ฐ์ ๋ก๊น ํ๋๋ก ์ค์ ์ ํด๋ณด์์ต๋๋ค. ์ฌ๊ธฐ๊น์ง ์ ๋ฐ๋ผ ์ค์ จ๋์? ๐
์ด์ request body ๋ฅผ ์ ๋ ฅ๋ฐ์ payload๊ฐ ์ ์ถ๋ ฅ๋๋์ง ๋ณด๊ฒ ์ต๋๋ค.
TestController ์ request body๋ฅผ ๋ฐ๋ API๋ฅผ ํ๋ ์ถ๊ฐํ๊ฒ ์ต๋๋ค.
@PostMapping("/request-body-log")
public long requestBodyLog(@RequestBody Employee employee) {
return employee.getId();
}
Employee ์ ๋ณด๋ฅผ ๋ฐ์์ id๋ฅผ ๊ทธ๋๋ก ๋ฆฌํดํด์ฃผ๋ ๊ฐ๋จํ API์ ๋๋ค. (์ด์ฐจํผ request body ๋ก๊น ์ ์ํ๊ฑฐ๋ ์ฌํํ๊ฒ
๊ทธ๋ฆฌ๊ณ domain ํจํค์ง ํ์์ Employee ํด๋์ค๋ฅผ ์๋์ ๊ฐ์ด ์์ฑํด์ฃผ๊ฒ ์ต๋๋ค.
@Getter
@Setter
@FieldDefaults(level = AccessLevel.PRIVATE)
public class Employee {
long id;
String name;
int age;
}
์ด์ ์ฑ์ ๊ธฐ๋ํด์ postman์ผ๋ก ํ ์คํธ๋ฅผ ํด๋ณด๊ฒ ์ต๋๋ค.
๋ก๊ทธ๋ ์๋์ ๊ฐ์ด ์ถ๋ ฅ๋์์ต๋๋ค.
2022-09-16 07:32:49.190 INFO 31518 --- [nio-8080-exec-5] c.k.demo.filter.RequestLoggingFilter : Before request [POST /test/request-body-log, client=0:0:0:0:0:0:0:1]
2022-09-16 07:32:49.226 INFO 31518 --- [nio-8080-exec-5] c.k.demo.filter.RequestLoggingFilter : After request [POST /test/request-body-log, client=0:0:0:0:0:0:0:1, payload={
"id":1000,
"name":"์ผ์ด์น",
"age":20
}]
๊ทธ๋ฐ๋ฐ ๋ก๊ทธ๋ฅผ ๋ณด๋ uri ์ ๋ณด์ client ์ ๋ณด๊ฐ ์ค๋ณต๋์ ์ถ๋ ฅ์ด ๋๊ณ ์๊ณ , request body๋ก ๋๊ฒจ์ค ๋ฐ์ดํฐ๊ฐ ๋น์ฆ๋์ค ๋ก์ง์ด ๋ชจ๋ ์คํ๋๊ณ ๋ ๋ค์ ์ถ๋ ฅ๋๋ After request ... ๋ถ๋ถ์ ์ถ๋ ฅ์ด ๋๊ณ ์์ต๋๋ค. ๋ญ๊ฐ ์ถ๋ ฅ๋๋ ๋ด์ฉ์ด ๋ง์์ ๋ค์ง ์๋ค์.
๋ค์ ํฌ์คํ ์์๋ ๋ก๊ทธ๋ฉ์์ง๋ฅผ ๋ฐ๊ฟ๋ณด๋๋ก ํ๊ฒ ์ต๋๋ค.
์ฝ์ด์ฃผ์ ์ ๊ฐ์ฌํฉ๋๋ค~ ๐
๋์์ด ๋์ จ๋ค๋ฉด ์ข์์ ๊พน ๋๋ฌ์ฃผ๊ณ ๊ฐ์ธ์~
[ ๋ค์ ํฌ์คํ ๋ฐ๋ก ์ฝ๊ธฐ ]