1. 기술 스택 정보
- Server Framwork : Spring boot 2.2.1.RELEASE
- Client Library : Jersey (spring-boot-starter-jersey:2.2.1.RELEASE)
- Logging Library
- log4jdbc-log4j2:1.16
- logback:1.2.9 (slf4j)
2. RequestFilter 작성
Jersey 라이브러리의 ContainerRequestFilter, ContainerResponseFilter Interface를 구현하여 작성한다.
public class ApiFilter implements ContainerRequestFilter, ContainerResponseFilter {
@Context
private HttpServletRequest servletRequest;
@Context
private Providers providers;
@Override
public void filter(ContainerRequestContext requestContext) {
try {
// 인입된 각 요청 마다 MDC 작성을 통해 traceId, spanId 로깅.
MDC.put("traceId", TracingUtils.generateTraceId());
MDC.put("spanId", TracingUtils.generateSpanId());
}
catch (Exception e) {
logger.error(e.getMessage(), e);
}
}
@Override
public void filter(ContainerRequestContext requestContext, ContainerResponseContext responseContext) {
try {
MDC.clear();
}
catch (Exception e) {
logger.error(e.getMessage(), e);
}
}
}Filter를 작성했으면 Jersey ResourceConfig class를 상속해 만든 Configuration class에서 register 해야 필터가 정상 동작한다.
@Configuration
@Component
@ApplicationPath("/api")
public class JerseyConfig extends ResourceConfig {
register(ApiFilter.class);
register(new LoggingFeature(Logger.getLogger("KIOSK"), Level.INFO, LoggingFeature.Verbosity.PAYLOAD_TEXT, 262140));
// exception handler, controller 등 등록 가능.
}위 config class 에서 볼 수 있듯 LoggingFeature 로 이미 logging 관련 기능이 동작하고 있다. (Legacy Source). 처음 filter class를 작성할 땐 두 개 모두 사용하여도 정상 동작할 것이라고 판단하였으나 실제 로그를 보았을 때 예상되는 동작과 다른 이슈가 생겼다. LoggingFeature를 통해 로깅된 내용에 최초 인입 관련 request logging과 최후의 response 관련 내용에서 traceId와 spanId 가 로깅되지 않는 것.
2023-07-20 17:24:48.836 [KIOSK,,] [https-jsse-nio-27100-exec-8] INFO (132) - 667561 * Server has received a request on thread https-jsse-nio-27100-exec-8
667561 > POST https://****
667561 > accept: application/json
667561 > content-encoding: utf-8
667561 > content-length: 477
667561 > content-type: application/json; charset=utf-8
667561 > host: ki***
667561 > user-agent: Mozilla/3.0 (compatible; Indy Library)
2023-07-20 17:24:49.475 [KIOSK,,] [https-jsse-nio-27100-exec-8] INFO KIOSK.log(132) - 667561 * Server responded with a response on thread https-jsse-nio-27100-exec-8
667561 < 200
667561 < Content-Type: application/json사유는 아래와 같다.
// LoggingFeature.java (jersey-common-2.29.1.jar)
@Override
public boolean configure(FeatureContext context) {
boolean enabled = false;
if (context.getConfiguration().getRuntimeType() == RuntimeType.CLIENT) {
ClientLoggingFilter clientLoggingFilter = (ClientLoggingFilter) createLoggingFilter(context, RuntimeType.CLIENT);
context.register(clientLoggingFilter);
enabled = true;
}
if (context.getConfiguration().getRuntimeType() == RuntimeType.SERVER) {
ServerLoggingFilter serverClientFilter = (ServerLoggingFilter) createLoggingFilter(context, RuntimeType.SERVER);
context.register(serverClientFilter);
enabled = true;
}
return enabled;
}LoggingFeature class 내부에서 LoggingFilter를 등록하는 과정이며. Server로 동작할 경우 ServerLoggingFilter가 등록되는 것을 확인할 수 있다. ServerLoggingFilter의 일부 소스는 아래와 같은데,
@ConstrainedTo(RuntimeType.SERVER)
@PreMatching
@Priority(Integer.MIN_VALUE)
@SuppressWarnings("ClassWithMultipleLoggers")
final class ServerLoggingFilter extends LoggingInterceptor implements ContainerRequestFilter, ContainerResponseFilter {
// ... 생략
}@Priority(Integer.MIN_VALUE) 부분에서 볼 수 있듯 filter 순서에서 최우선적으로 실행되도록 구현되어 있다.
Server filter logs requests and responses to specified logger, at required level, with entity or not.
...
The priority is set to the maximul value, which means that filter is called as the first filter when request arrives and similarly as the last filter when the response is dispatched.
...위의 class 주석에서 볼 수 있듯, request가 들어오면 최우선적으로, response가 나갈 땐 최후에 실행된다.
Client Reuqest -> ServerLoggingFilter -> UserCustomFilter -> ... logic
... logic -> UserCustomFilter -> ServerLoggingFilter -> response떄문에 UserCustomFilter의 request filter에서 MDC를 세팅하면 최초 인입 로그엔 MDC 관련 값들을 볼 수 없이 중간부터 확인 가능했던 것이고, response filter 에서 serverLoggingFilter에 도달하기 전에 MDC를 해제하였으니 response 상세 정보에 MDC 값을 볼 수 없었다.
때문에 등록된 LoggingFeature를 삭제하고 Custom Logging Filter 를 아래와 같이 작성했다.
@Slf4j
@Provider
public class KioskIfFilter implements ContainerRequestFilter, ContainerResponseFilter {
@Context
private HttpServletRequest servletRequest;
@Context
private Providers providers;
private static final ThreadLocal<Long> startTime = new ThreadLocal<Long>();
private final String REQUEST_LOG_PREFIX = "> ";
private final String RESPONSE_LOG_PREFIX = "< ";
private final String SEPARATOR = " : ";
@Override
public void filter(ContainerRequestContext requestContext) {
try {
MDC.put("traceId", TracingUtils.generateTraceId());
MDC.put("spanId", TracingUtils.generateSpanId());
logger.info(">>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>");
logger.info(String.format(">>>[from %s CALL %s] |%s|%s", servletRequest.getRemoteAddr(), servletRequest.getMethod(),
servletRequest.getRequestURI(), servletRequest.getContentType()));
printHeaders(requestContext.getHeaders(), REQUEST_LOG_PREFIX);
logRequestPayload(requestContext);
startTime.set(System.currentTimeMillis());
}
catch (Exception e) {
logger.error(e.getMessage(), e);
}
}
@Override
public void filter(ContainerRequestContext requestContext, ContainerResponseContext responseContext) {
try {
Long elapse = System.currentTimeMillis() - startTime.get().longValue();
logger.info("<<<[END] " + servletRequest.getMethod() + " | Elapsed time milli-sec : " + elapse);
logger.info("<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<");
printHeaders(responseContext.getHeaders(), RESPONSE_LOG_PREFIX);
logResponsePayload(responseContext);
MDC.clear();
}
catch (Exception e) {
logger.error(String.format("<<<[from %s CALL %s] |%s|%s", servletRequest.getRemoteAddr(), servletRequest.getMethod(),
servletRequest.getRequestURI(), servletRequest.getContentType()));
}
}
private void logResponsePayload(ContainerResponseContext responseContext) throws IOException {
String message = "";
if (responseContext.hasEntity()) {
ByteArrayOutputStream baos = new ByteArrayOutputStream();
Class<?> entityClass = responseContext.getEntityClass();
Type entityType = responseContext.getEntityType();
Annotation[] entityAnnotations = responseContext.getEntityAnnotations();
MediaType mediaType = responseContext.getMediaType();
@SuppressWarnings("unchecked")
MessageBodyWriter<Object> bodyWriter = (MessageBodyWriter<Object>) providers.getMessageBodyReader(entityClass,
entityType,
entityAnnotations,
mediaType);
bodyWriter.writeTo(responseContext.getEntity(),
entityClass,
entityType,
entityAnnotations,
mediaType,
responseContext.getHeaders(),
baos);
message = message.concat(baos.toString());
}
logger.info(message);
}
private void printHeaders(MultivaluedMap headers, String prefix) {
StringBuilder sb = new StringBuilder();
sb.append("Http Headers : ");
for (Object key : headers.keySet()) {
sb.append(prefix);
sb.append(key);
sb.append(SEPARATOR);
sb.append(headers.get(key));
sb.append(", ");
}
logger.info(sb.toString());
}
private void logRequestPayload(ContainerRequestContext requestContext) {
StringBuilder sb = new StringBuilder();
try {
requestContext.setEntityStream(logInboundEntity(sb, requestContext.getEntityStream()));
} catch (IOException e) {
logger.error("error encountered by log inbound entity");
}
logger.info(sb.toString());
}
InputStream logInboundEntity(final StringBuilder b, InputStream stream) throws IOException {
if (!stream.markSupported()) {
stream = new BufferedInputStream(stream);
}
stream.mark(262140 + 1);
final byte[] entity = new byte[262140 + 1];
final int entitySize = stream.read(entity);
b.append(new String(entity, 0, Math.min(entitySize, 262140)).replaceAll("\r\n|\r|\n", ""));
if (entitySize > 262140) {
b.append("...more...");
}
b.append('\n');
stream.reset();
return stream;
}printHeaders를 통해 header 로깅, 각 request, response payload 로깅 메소드를 작성해 인바운드 및 아웃바운드에 대한 상세한 로깅에도 MDC로 세팅한 값들이 잘 보일 수 있도록 세팅했다.
2023-07-12 17:35:40.294 [KIOSK,2307126cde2cb87d,001519cd25084945] [http-nio-27100-exec-1] INFO c.o.k.a.v1.controller.KioskIfFilter.filter(48) - >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-07-12 17:35:40.295 [KIOSK,2307126cde2cb87d,001519cd25084945] [http-nio-27100-exec-1] INFO c.o.k.a.v1.controller.KioskIfFilter.filter(49) - >>>[from 127.0.0.1 CALL POST] |/api/v1/login|application/json
2023-07-12 17:35:40.296 [KIOSK,2307126cde2cb87d,001519cd25084945] [http-nio-27100-exec-1] INFO c.o.k.a.v1.controller.KioskIfFilter.printHeaders(121) - Http Headers : > content-type : [application/json], > user-agent : [PostmanRuntime/7.25.0], > accept : [*/*], > postman-token : [a3c799f3-2895-4ed0-ba5e-029cb9714ead], > host : [localhost:27100], > accept-encoding : [gzip, deflate, br], > connection : [keep-alive], > content-length : [262],
2023-07-12 17:35:40.296 [KIOSK,2307126cde2cb87d,001519cd25084945] [http-nio-27100-exec-1] INFO c.o.k.a.v1.controller.KioskIfFilter.logRequestPayload(131) - { "header": { "msgSendYmd": "20230522", "msgSendHms": "152700"}}
2023-07-12 17:35:40.778 [KIOSK,2307126cde2cb87d,001519cd25084945] [http-nio-27100-exec-1] INFO jdbc.sqltiming.sqlTimingOccurred(373) - LOG Message...
{executed in 14 msec}
2023-07-12 17:35:40.789 [KIOSK,2307126cde2cb87d,001519cd25084945] [http-nio-27100-exec-1] INFO c.o.k.a.v1.controller.KioskIfFilter.filter(69) - <<<[END] POST | Elapsed time milli-sec : 493
2023-07-12 17:35:40.789 [KIOSK,2307126cde2cb87d,001519cd25084945] [http-nio-27100-exec-1] INFO c.o.k.a.v1.controller.KioskIfFilter.filter(70) - <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-07-12 17:35:40.789 [KIOSK,2307126cde2cb87d,001519cd25084945] [http-nio-27100-exec-1] INFO c.o.k.a.v1.controller.KioskIfFilter.printHeaders(121) - Http Headers : < Content-Type : [application/json],
2023-07-12 17:35:40.833 [KIOSK,2307126cde2cb87d,001519cd25084945] [http-nio-27100-exec-1] INFO c.o.k.a.v1.controller.KioskIfFilter.logResponsePayload(106) - {"header":{"respCd":"00000","respMsg":"정상처리[00000]"}
3. AsyncExecutor
해당 프로세스 내부의 특정 로직엔 병렬로 처리되는 내역이 있다. (신규 thread를 생성해 asynchronous 요청). 기본적으로 OpenTracing 의 룰은 신규 thread엔 신규 spanId를 채번해야 한다.
단, 레거시 코드에선 taskExecutor를 Bean으로 등록해 사용하고 있는데, 수정이 불가능한 spring 자체 Executor를 사용하고 있으므로 wrapper 클래스를 작성해야한다.
또한 참고할 점은 MDC 는 ThreadLocal을 기반으로 동작되기 때문에 신규 Thread가 생성될 때는 기존 traceId 등을 다시 세팅해주어야하는 이슈가 있다.
import java.util.concurrent.Executor;
import org.springframework.aop.interceptor.AsyncUncaughtExceptionHandler;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.scheduling.annotation.AsyncConfigurer;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;
@Configuration
public class AsyncThreadConfig implements AsyncConfigurer {
@Override
public AsyncUncaughtExceptionHandler getAsyncUncaughtExceptionHandler() {
return new AsyncExceptionHandler();
}
@Bean("asyncExecutor")
public Executor asyncExecutor() {
// This will create new thread each time a task comes till 10.
// Then It will keep tasks in queue.
// If queue is full it will create 11th thread and will go till 25
ThreadPoolTaskExecutor taskExecutor = new ThreadPoolTaskExecutor();
taskExecutor.setCorePoolSize(10);
taskExecutor.setMaxPoolSize(25);
taskExecutor.setQueueCapacity(200);
taskExecutor.setThreadNamePrefix("asyncExecutor-");
taskExecutor.initialize();
return taskExecutor;
}
}
기본적으로 AsyncTaskExecutor를 상속받아 중요 동작 직전에 wrapping 된 메서드를 실행하도록 만든다. MDC에서 기존 값들을 가져와 traceId는 동일하게 매핑해주고, spanId는 새로 채번한다.
import org.slf4j.MDC;
import org.springframework.core.task.AsyncTaskExecutor;
import java.util.Map;
import java.util.concurrent.Callable;
import java.util.concurrent.Future;
public class AsyncThreadMdcTaskExecutor implements AsyncTaskExecutor {
private final AsyncTaskExecutor executor;
public AsyncThreadMdcTaskExecutor (AsyncTaskExecutor executor) {
this.executor = executor;
}
@Override
public void execute(Runnable task, long startTimeout) {
executor.execute(wrapRunnable(task), startTimeout);
}
@Override
public void execute(Runnable task) {
executor.execute(wrapRunnable(task));
}
@Override
public <T> Future<T> submit(Callable<T> task) {
return executor.submit(wrapCallable(task));
}
@Override
public Future<?> submit(Runnable task) {
return executor.submit(wrapRunnable(task));
}
private <T> Callable<T> wrapCallable(final Callable<T> task) {
final Map<String, String> contextMap = MDC.getCopyOfContextMap();
return () -> {
try {
MDC.put("traceId", contextMap.get("traceId"));
MDC.put("spanId", TracingUtils.generateSpanId());
return task.call();
} finally {
MDC.clear();
}
};
}
private Runnable wrapRunnable(final Runnable task) {
final Map<String, String> contextMap = MDC.getCopyOfContextMap();
return () -> {
try {
MDC.put("traceId", contextMap.get("traceId"));
MDC.put("spanId", TracingUtils.generateSpanId());
task.run();
} finally {
MDC.clear();
}
};
}
}신규 thread 생성될 때 신규 span id 정상 채번되는 내용 확인 가능하다.
2023-07-21 10:07:45.582 [KIOSK,2307219fcb561f86,0008c02489739b4c] [http-nio-27100-exec-3] log contents
2023-07-21 10:07:45.583 [KIOSK,2307219fcb561f86,009afd4ef1bbaa4f] [asyncExecutor-2] log contents4. Append to Request Header
trace id 와 span id 에 대한 세팅이 마무리 되었으므로 타 서비스로 연동될 때 해당 정보들을 넘겨줘야 한다. MDC는 Local Thread를 통해 실행되기 때문에 Client 로 요청 보내는 부분에서 간단히 Http header 에 세팅해주면 된다.
header.putSingle("X-B3-TraceId", MDC.get("traceId"));
header.putSingle("X-B3-SpanId", TracingUtils.generateSpanId());
header.putSingle("X-B3-ParentSpanId", MDC.get("spanId"));2023-07-21 10:07:45.603 [KIOSK_IF,2307219fcb561f86,00b9d75c8ab3d54d] [asyncExecutor-1] INFO c.o.k.s.r.proto.RexpayxApiClient.log(132) - 1 * Sending client request on thread asyncExecutor-1
1 > PUT http://...
1 > Content-Type: application/json
1 > X-B3-ParentSpanId: 00b9d75c8ab3d54d
1 > X-B3-SpanId: 002b3824edf95642
1 > X-B3-TraceId: 2307219fcb561f86
... 생략
json...'로직과의 사투 > Operational Issues' 카테고리의 다른 글
| 로깅 룰 구축기 (1) (0) | 2023.09.26 |
|---|---|
| 네이티브 메모리 누수 추적기 (0) | 2023.07.25 |