feat: 요청마다 고유한 아이디(traceId)를 만들어 로그에 남겨, 추적을 용이하게 한다. #744

tributetothemoon · 2021-11-11T19:15:32Z

상황 설명

Before

무수히 쌓인 로그들... 난잡하게 섞여있어서, 요청 단위별로 분간을 할 수 없지 않나요?

After

transaction 칼럼(현재는 traceId)에 주목해보세요. 이제 어떤 요청에 의해 로그가 남았는지 서로 분간이 가지 않나요?
4740a0cceaa4, f58cb3a7a4c9, 6e85cd7e49bd 이렇게 3개의 요청이 있었네요!

4740a0cceaa4 요청을 추적하기 위해 필터링을 걸어볼까요?

구현 기능

요청이 발생하면, 요청마다 트랜잭션 아이디를 부여합니다. 해당 요청에 의해 남는 로그는 모두 같은 트랜잭션 아이디로 남기게 됩니다.
이 트랜잭션 아이디는 데이터베이스의 트랜잭션과는 무관합니다! 어떠한 요청(transaction)에 의한 것인지를 구분하는 WAS만의 고유한 값입니다.
UUID의 마지막 12바이트만을 이용하고 있습니다. 길면 식별성이 좋지 않기도하고, 로그는 주기적으로 지우기 때문에 겹칠 확률이 대단히 낮다고 보았습니다.
요청마다 쓰레드가 부여된다는 점을 고려하여 ThreadLocal을 사용하였습니다. 쓰레드 로컬이란?

11월 13일 추가 사항

SLF4J는 이와 같은 고민을 미리 해놔서, 쓰레드 로컬 빈을 사용하지 않아도 되도록 MDC라는 걸 지원해주네요 ^_... 수정하니까 코드가 훨씬 간결해져서 바로 수정해보았습니다...
샐리의 의견대로 트랜잭션이 데이터베이스와 헷갈릴 수 있으니, traceId로 간소화해보았어요!!
traceId 부여하고, 풀어주는 것도 Interceptor를 이용하면 간단히 해결되는 문제였습니다. 기술에 골몰되지 않도록 주의하겠습니다. 😢

Close #743

및 불필요 캐스팅문 삭제

부모 클래스의 메소드도 로깅 기준에 포함토록 합니다.

실수로 바꾸어놓았었습니다.

sakjung

좋습니다. 많은 걸 배워가네요~

sakjung · 2021-11-12T12:45:06Z

backend/src/main/java/com/woowacourse/zzimkkong/config/logaspect/LogAspect.java


 import static net.logstash.logback.argument.StructuredArguments.value;

 @Slf4j
 @Component
 @Aspect
+@Order(2)


요게 뭐에요? ㅎ..ㅎ

AOP를 적용하는 순서입니다~ 시간 측정 프록시를 먼저 적용하고, 트랜잭션 아이디를 release해주는 메소드에 또 한 번 적용하는 것입니다.
이 경우엔 컨트롤러 들만 타겟으로 걸려서 프록시가 만들어지겠군요!

근데 이부분은 삭제되었습니다. Transaction Id를 릴리즈해주는 부분 때문에 넣었던 건데, 더 간단한 방법(MDC, Interceptor활용)이 있었습니다.

sakjung · 2021-11-12T12:47:49Z

backend/src/main/java/com/woowacourse/zzimkkong/config/logaspect/LogAspect.java

    }
+
+    @Pointcut("execution(public * com.woowacourse.zzimkkong..*(..))")


위에 createLogProxy 에서의 pointcut 표현식이랑 같은것 같네요! 하나의 상수로 관리할 수 있을것 같습니다

오 왜 놓쳤을까요. PointCut 표현식이 적용된 메소드 참조가 안 되길래 그냥 상수로 빼버렸습니다!!

sakjung · 2021-11-12T12:49:50Z

backend/src/main/java/com/woowacourse/zzimkkong/config/logaspect/TransactionReleaser.java

+public class TransactionReleaser {
+    private final TransactionThreadLocal transactionThreadLocal;
+
+    public TransactionReleaser(TransactionThreadLocal transactionThreadLocal) {


전체적으로 파라미터 final 체크 해주세요!

Suggested change

public TransactionReleaser(TransactionThreadLocal transactionThreadLocal) {

public TransactionReleaser(final TransactionThreadLocal transactionThreadLocal) {

으아 죄송합니다! 감사합니다!

sakjung · 2021-11-12T13:24:01Z

추가 질문
UUIDThreadLocal 얘가 지금 쓰레드 로컬 구현체인것으로 보여요. 이 친구가 빈으로 등록 되면 싱글톤일텐데, 여러 쓰레드에서 돌려 쓰여도 괜찮은 건가요?? 그래서 만약 빈으로 등록할거면 프로토타입 빈으로 등록해야한다고 생각했거든요.
요청을 처리하는 쓰레드 마다 쓰레드 로컬을 만들어줘야한다 라고 이해했는데, 어떻게 흐름이 돌아가는건지 궁금합니다! 제가 쓰레드 로컬에 대해서 첨봐서... 잘못 이해했다면 알려주세요!

dusdn1702

오호라 좋네요~
이러다 로깅 관련 로직이 api 로직보다 길어질 것 같은데 원래 그런건가요???? 그냥 궁금해서....ㅎㅎ...
로깅관련 로직이 길어질수록 시간도 더 들 것 같은데 그거에 대한 문제는 없나요?????? 트레이드오프인건가..
요청마다 아이디 주는 건 좋습니다! 근데 지금은 요청 하나마다 트랜잭션 하나이긴 하지만 앞으로 트랜잭션이 쪼개질 수 있다는 생각이 들어서 목적이 '요청마다'인지 '트랜잭션마다'인지 생각해보면 좋을 것 같아요! 만일 요청마다라면 트랜잭션 아이디라는 이름을 수정하면 좋을 것 같아요!

tributetothemoon · 2021-11-12T15:23:16Z

여러 쓰레드에서 돌려 쓰여도 괜찮은 건가요??

넹 완전히 괜찮습니다.
간단히 말하자면, ThreadLocal이란 해쉬맵인데요, 다만 get()을 해올 때 자기 쓰레드에 할당된 영역만을 가져옵니다.
결국 다수의 쓰레드가 하나의 ThreadLocal을 돌려써도, 각자의 쓰레드 이름이 다를 테니 다른 위치의 자원에 접근하게 되는 것이죠.

tributetothemoon · 2021-11-12T16:48:57Z

요청마다 아이디 주는 건 좋습니다! 근데 지금은 요청 하나마다 트랜잭션 하나이긴 하지만 앞으로 트랜잭션이 쪼개질 수 있다는 생각이 들어서 목적이 '요청마다'인지 '트랜잭션마다'인지 생각해보면 좋을 것 같아요! 만일 요청마다라면 트랜잭션 아이디라는 이름을 수정하면 좋을 것 같아요!

아주 좋은 생각이에요!! WAS에서도 트랜잭션이라는 개념이 성립하기 때문에 이렇게 해보았지만, 굳이 관례에 얽매이지 않고 우리에게 맞추어 적용하는 것이 주체적인 것 같아요. traceId로 변경해보았습니다!

이러다 로깅 관련 로직이 api 로직보다 길어질 것 같은데 원래 그런건가요????

트랜잭션 아이디를 풀어주는 것(TransactionIdReleaser) 때문에 프록시를 만들지 않도록 변경해보았습니다.
굉장히 간단한 방법이 있더라구요 ^_^... 이런 문제(요청을 구분하기)는 로깅 프레임워크에서 이미 해결한 문제였습니다. SLF4J의 MDC를 이용하는 방식으로 변경했습니다😢. 기술에 골몰되지 않도록 항상 주의하는 개발자가 되겠습니다😢😢😢.

로깅관련 로직이 길어질수록 시간도 더 들 것 같은데 그거에 대한 문제는 없나요??????

MDC(내부적으로 쓰레드 로컬 사용)에 의해 traceId를 만들어오는 부분은 해쉬맵을 사용하는 것과 같은 수준이라 문제가 되지 않을 것 같습니다! 항상 로깅에 의한 오버헤드에는 주의하고 있습니다!

dusdn1702

넘 좋습니다~~~~! 수고 많으셨슴니다~~~~~👍

sakjung

ㅇㅍㄹㅂ

sakjung · 2021-11-15T13:36:41Z

✅ ZZIMKKONG SONARQUBE ✅

All passes! - Read the report here!

tributetothemoon added 13 commits November 11, 2021 00:40

refactor: LogAspectConfigurer -> PostProcessor 로 기능 대체

fab4c86

refactor: LogAspect, 로그 프록시를 ProxyFactory를 사용해 만듦

b6169f5

refactor: LogRegistry -> FindInstanceAndCreateLogProxy 이름 변경

d40ffa7

refactor: 로그 프록시 생성시 CGLIB 사용

7a78d1d

및 불필요 캐스팅문 삭제

refactor: 로그 프록시 public 메소드에만 적용 되도록 변경

533a22b

refactor: LogMethodExecutionTime @target 으로 변경

1f82326

부모 클래스의 메소드도 로깅 기준에 포함토록 합니다.

refactor: LogProxyPostProcessor 생성자 protected로 변경

c93bef1

refactor: LogProxyPostProcessor를 LogAspect 내부 private 클래스로 은닉

9aee561

refactor: LogAspect 내부 클래스 외부로 추출, static 메소드 삭제

7c5ec6d

feat: 요청마다 로그에 트랜잭션 아이디를 남기도록 수정

8b4a8da

refactor: 웜업이 끝나고 트랜잭션 쓰레드 로컬 초기화

f0812a0

test: UUIDThreadLocalTest 테스트 코드 작성

95f4d14

refactor: zzimkkongExceptionHandler 로그 레벨 INFO로 재조정

fc17d96

실수로 바꾸어놓았었습니다.

tributetothemoon added 🌟 feature New feature or request 🕋 backend labels Nov 11, 2021

tributetothemoon requested review from dusdn1702, xrabcde and sakjung November 11, 2021 19:15

tributetothemoon self-assigned this Nov 11, 2021

sakjung previously approved these changes Nov 12, 2021

View reviewed changes

dusdn1702 previously approved these changes Nov 12, 2021

View reviewed changes

refactor: 생성자 파라미터에 final 속성 부여

d11f722

tributetothemoon dismissed stale reviews from dusdn1702 and sakjung via d11f722 November 12, 2021 15:14

tributetothemoon added 2 commits November 13, 2021 01:28

refactor: ThreadLocal 관련 빈을 MDC를 이용하여 대체

f9f380c

refactor: ControllerAdvice 내의 traceId 상수화

1cadfb1

tributetothemoon changed the title ~~feat: 요청마다 고유한 아이디(트랜잭션)을 만들어 로그에 남겨, 추적을 용이하게 한다.~~ feat: 요청마다 고유한 아이디(traceId)를 만들어 로그에 남겨, 추적을 용이하게 한다. Nov 12, 2021

dusdn1702 previously approved these changes Nov 13, 2021

View reviewed changes

xrabcde previously approved these changes Nov 13, 2021

View reviewed changes

sakjung previously approved these changes Nov 15, 2021

View reviewed changes

Merge branch 'dev' into feat/743-thread-local

089a9df

tributetothemoon dismissed stale reviews from sakjung, xrabcde, and dusdn1702 via 089a9df November 15, 2021 13:32

dusdn1702 approved these changes Nov 15, 2021

View reviewed changes

xrabcde approved these changes Nov 17, 2021

View reviewed changes

tributetothemoon merged commit cd119ac into dev Nov 18, 2021

tributetothemoon deleted the feat/743-thread-local branch November 18, 2021 06:50

This was referenced Apr 27, 2022

[ALL] v1.4.5 배포 #805

Closed

release: v1.4.5 #804

Merged

yujin113 mentioned this pull request Jan 30, 2023

Feat/로깅 세팅 #8 Wingle-SMWU/Wingle-Backend#14

Merged

6 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: 요청마다 고유한 아이디(traceId)를 만들어 로그에 남겨, 추적을 용이하게 한다. #744

feat: 요청마다 고유한 아이디(traceId)를 만들어 로그에 남겨, 추적을 용이하게 한다. #744

tributetothemoon commented Nov 11, 2021 •

edited

Loading

sakjung left a comment

sakjung Nov 12, 2021

tributetothemoon Nov 12, 2021

tributetothemoon Nov 12, 2021

sakjung Nov 12, 2021

tributetothemoon Nov 12, 2021

sakjung Nov 12, 2021

tributetothemoon Nov 12, 2021

sakjung commented Nov 12, 2021

dusdn1702 left a comment

tributetothemoon commented Nov 12, 2021 •

edited

Loading

tributetothemoon commented Nov 12, 2021 •

edited

Loading

dusdn1702 left a comment

sakjung left a comment

sakjung commented Nov 15, 2021

		}

		@Pointcut("execution(public * com.woowacourse.zzimkkong..*(..))")

	public TransactionReleaser(TransactionThreadLocal transactionThreadLocal) {
	public TransactionReleaser(final TransactionThreadLocal transactionThreadLocal) {

feat: 요청마다 고유한 아이디(traceId)를 만들어 로그에 남겨, 추적을 용이하게 한다. #744

feat: 요청마다 고유한 아이디(traceId)를 만들어 로그에 남겨, 추적을 용이하게 한다. #744

Conversation

tributetothemoon commented Nov 11, 2021 • edited Loading

상황 설명

Before

After

구현 기능

11월 13일 추가 사항

sakjung left a comment

Choose a reason for hiding this comment

sakjung Nov 12, 2021

Choose a reason for hiding this comment

tributetothemoon Nov 12, 2021

Choose a reason for hiding this comment

tributetothemoon Nov 12, 2021

Choose a reason for hiding this comment

sakjung Nov 12, 2021

Choose a reason for hiding this comment

tributetothemoon Nov 12, 2021

Choose a reason for hiding this comment

sakjung Nov 12, 2021

Choose a reason for hiding this comment

tributetothemoon Nov 12, 2021

Choose a reason for hiding this comment

sakjung commented Nov 12, 2021

dusdn1702 left a comment

Choose a reason for hiding this comment

tributetothemoon commented Nov 12, 2021 • edited Loading

tributetothemoon commented Nov 12, 2021 • edited Loading

dusdn1702 left a comment

Choose a reason for hiding this comment

sakjung left a comment

Choose a reason for hiding this comment

sakjung commented Nov 15, 2021

tributetothemoon commented Nov 11, 2021 •

edited

Loading

tributetothemoon commented Nov 12, 2021 •

edited

Loading

tributetothemoon commented Nov 12, 2021 •

edited

Loading