Spring Bean이아닌
회사 프로젝트를 진행하면서, 각 요청에 대한 흐름을 한줄의 로그로 뽑아내는 기능이 있었다. 한줄로 어떤 흐름을 탔는지 알수 있지만. 정확히 알려면 서비스로그를 한번더 봐야했다. “그렇다면. 아예 그 흐름을 서비스로그에 남기면 어떨까?” 라는 생각을 했다.
- 예를들어 아래와같은 회원가입의 상황이있을때 아래 처럼 남기는것이다.
11:58:48.376 INFO : [DUPCHECK] - Check for this login ID [ Kimchi-dev ].
11:58:48.380 INFO : [DUPCHECK] - There is no Users that, which used this Identification. [Kimchi-dev]
11:58:48:392 INFO : [DUPCHECK,REGISTER] - Registering this account to Service. [Kimchi-dev]
회원 가입할때 DUPCHECK라는 곳을 지나 REGISTGER 까지 거쳤 다는걸 알 수있다. 물론 서비스 로직이 복잡하면 로그가 길어지겠지만, 아직은 그럴일이 없으니 한번 해보기로 했다. 결국 해당요청에서 같은 로거를 사용하며 어딘가의 현재 서비스로직 단계를 기록 해야하는데, 쓰레드 로컬 밖에 떠오르는게 없었다.
package me.missionfamily.web.mission_family_be.common.logging.context;
import me.missionfamily.web.mission_family_be.common.util.Utils;
import org.springframework.util.Assert;
final class ThreadLocalTrackerContextHolderStrategy implements TrackerContextHolderStrategy {
private static final ThreadLocal<TrackerContext> contextHolder = new ThreadLocal<>();
@Override
public void clearContext() {
contextHolder.remove();
}
@Override
public TrackerContext getContext() {
TrackerContext context = contextHolder.get();
if(Utils.isNull(context)) {
context = createEmptyContext();
contextHolder.set(context);
}
return context;
}
@Override
public void setContext(TrackerContext context) {
Assert.notNull(context, "Only non-null TrackerContext instances are permitted");
contextHolder.set(context);
}
@Override
public TrackerContext createEmptyContext() {
return new TrackerContextImpl();
}
}위의 코드처럼 Thread Local을 생성하는 코드 이다. 첫번째는 특정 서비스 메서드를 진입할때 AOP를 걸어두고 현재 스탭을 넣어주는 방식으로 진행했다.
@Around("@annotation(ServiceDescriptions)")
public Object addServiceTracking(ProceedingJoinPoint joinPoint) throws Throwable {
MethodSignature signature = (MethodSignature) joinPoint.getSignature();
ServiceDescriptions checker = signature.getMethod().getAnnotation(ServiceDescriptions.class);
TrackerContextHolder.getContext()
.getTracker()
.addStep(checker.value());
return joinPoint.proceed();
}LogStep은 해당 서비스의 스텝을 담을 Enum 객체이다. 따라서 다음의 순서로 로깅을 진행해야 겠다는 생각을 했다.
- 서비스 단계를 기록할 ThreadLocal 변수를 가진 객체 초기화.
- 서비스 로직 진입시 AOP를 호출하여 위의 마지막 소스처럼 현재 스텝을 쓰레드로컬에 저장
- 해당 로그가 쓰여지는 시점인 logback의 doLayout 메서드가 호출될때 쓰레드로컬에 저장된 스텝을 꺼내어 로깅
2번에서 서비스 단계가 들어가는 것까지 성공했다. 하지만 3에서 현재 로거를 가져와서 쌓여있던 스탭을 꺼내는데, 갑자기 NPE가 떴다…
무슨일이지? 갑자기..?
Thread Local의 get() 메서드를 보면 다음 과같이 나와있다.
/**
* Returns the value in the current thread's copy of this
* thread-local variable. If the variable has no value for the
* current thread, it is first initialized to the value returned
* by an invocation of the {@link #initialValue} method.
*
* @return the current thread's value of this thread-local
*/
public T get() {
Thread t = Thread.currentThread();
ThreadLocalMap map = getMap(t);
if (map != null) {
ThreadLocalMap.Entry e = map.getEntry(this);
if (e != null) {
@SuppressWarnings("unchecked")
T result = (T)e.value;
return result;
}
}
return setInitialValue();
}
/**
* Variant of set() to establish initialValue. Used instead
* of set() in case user has overridden the set() method.
*
* @return the initial value
*/
private T setInitialValue() {
T value = initialValue();
Thread t = Thread.currentThread();
ThreadLocalMap map = getMap(t);
if (map != null)
map.set(this, value);
else
createMap(t, value);
return value;
}get() 할 때 현재 쓰레드에대한 쓰레드로컬 값이 없다면, initialValue 메소드 호출에 반환된 첫번째 값으로 초기화 한다는말… 엥? 현재 쓰레드에 대한 값이 왜 없지..? 내가 아까 넣어줬는데… 현재 쓰레드에 값이 없다면, 다른 쓰레드에서 생성된건가? 먼저 쓰레드가 다른지 부터 확인했다.
public static TrackerContext getContext() {
System.out.println("The id for Current Thread = " + Thread.currentThread().getId());
return strategy.getContext();
}결과
The id for Current Thread = 46
...
The id for Current Thread = 46쓰레드 아이디는 똑같이 46으로 나온다니..? 그럼 일단 같은 쓰레드에서 동작한다는건데… 그럼 마지막 추측은 get()하는 시점에 쓰레드로컬의 initialValue를 호출 한다하는데 initialValue()의 기본값이 null을 리턴하니 값만 set()으로 넣어봤다.
혹시나해서 디버거 찍어봤는데 역시나 2번에서 서비스 단계를 Thread Local에 넣어주기전에 get()하여 한번 체크를 한다. 체크 될때 ThreadLocalMap에서 해당 ThreadLocal이 key로 되어있는 EntrySet을 찾고 없으면 initailValue()를 호출한다.
일단. 값을 set() 해줬기 때문에 2단계까지 initialValue()를 호출 하지않았다.
public T get() {
Thread t = Thread.currentThread();
ThreadLocalMap map = getMap(t);
if (map != null) {
ThreadLocalMap.Entry e = map.getEntry(this);
if (e != null) { //Thread Local 맵에서 해당 키로 찾은 Entry가 비어있다면,
@SuppressWarnings("unchecked")
T result = (T)e.value;
return result;
}
}
return setInitialValue(); // 새로운 값으로 세팅
}계속 디버거를 찍어보면서 확인하였다. 여기서 이상한 점은 위의 각 단계에서 Thread Local은 “1, 2, 4” 에서만 공유되고 사용됐다. 이 세개의 공통점은 Spring Bean이었다. 말도 안된다..Spring Bean끼리만 Thread Local을 공유한다는 것처럼 보인다. 더 신기한건 3. 에서 getContext() 할 때 TrackerContextHolder의 static block이 실행 되었다..
다음의 표를 보면 ThreadLocal 변수를 가지고있는 객체에접근 했을때 디버거로 본 주소값이다.
| # | Class name | address | is Spring Bean |
| 1 | LoggerInterceptor | ThreadLocalTrackerContextHolderStrategy@11196 | true |
| 2 | LoggerAop | ThreadLocalTrackerContextHolderStrategy@11196 | true |
| 3 | StepLogLayout | ThreadLocalTrackerContextHolderStrategy@13587 | false |
| 4 | AccountService | ThreadLocalTrackerContextHolderStrategy@11196 | true |
위에서도 설명했지만 TrackerContextHolder 객체의 static block은 1. 번과 3. 번에서 두번 실행됐다.
심지어 접근한 객체의 주소값도 다르다. 3개의 시점에서는 11196으로 접근하고, 로그백 라이브러리에서는 13587이라는 객체를 새로 생성했다.
정말 놀라운건 이 객체를 Singleton으로 바꿨는데도 두번 생성 됐다. 마치 서로 다른곳에 있는것 처럼. 생성 됐다가 아니라 로드됐다가 맞는 표현 인거같다. 좀 소름 돋지만 좀 더 방법을 찾아봐야겠다.
이틀동안 출근 할때 퇴근할때 스프링컨테이너와 컨테이너 밖의 관계에서 클래스가 다르게 생성되는지 계속 찾아봤다.
java create both same instance at spring and java ,spring does create new instance twice, how to proccessed non-spring bean in the spring, spring execute static block twice, java create diffent instance as same classes that outside spring container 진짜 별에별 검색 다해봤는데 안나왔다…
진짜 포기하고 아무생각 없이 간단하게 다시 처음 으로 돌아갔다.
- 클래스는 메모리에 로드되기 전에 static block을 실행함. 결국
Method area내에서Static Area로 할당됨. Static Block이 이미 로드됐는데, 중간에 한번더 실행됐다? -> 같은 클래스로 다른 인스턴스 한번더 생성?2.의 내용이 정말 이해되지않아서 클래스로더 해쉬코드를찍어봤다.
static {
initialize();
int i = TrackerContextHolder.class.getClassLoader().hashCode();
System.out.println("class loder = #" + i);
}—> 콘솔
class loder = #1532034558 //실행시 로드된 객체 클래스로더의 해시코드
class loder = #414493378. //스프링 컨테이너 밖에서 호출 되는시점에 로드된 객체 클래스로더의 해시코드어?????????????? 미쳤다... 드디어 빛이 보이기 시작했다. 처음부터 너무 어렵게 생각했던것 같다.
같은 클래스의 다른 객체가 생성됐다면 클래스로더부터 확인 했어야 했다.
일단 확인된 문제는 동적으로 Class를 로드한 문제이다. 이번에는 다시 클래스로더의 이름을 찍어보니 아래처럼 출력됐다.
class loader -> loaderorg.springframework.boot.devtools.restart.classloader.RestartClassLoader
class loader -> loadersun.misc.Launcher$AppClassLoader
첫번째. 최초의 클래스가 로드되는 시점은 RestartClassLoader가 로드했고 Spring Container 밖의 일반 Java Bean인 logback library 메소드에서는AppClassLoader가 로드했다.
답이나왔다. spring-boot-devtools를 사용하면 기본적으로 최초 로드시 RestartClassLoader를 사용하므로 이후 AppClassLoader에 의해 해당 클래스를 호출시 동일한 클래스를 또 로드하기 때문에 다시 생성되는 문제였다.
애초에 쓰레드로컬과 관계있다고 생각을 하고 계속 쓰레드의 관점에서만 찾았는데, 답은 가까이 있었다.RestartClassloader를 사용하지 않는 옵션은 아직 찾지 못했고, 어차피 서비스중에는 데브툴 쓸일 없으니 의존성 주석처리 해놓으면 된다.
사실 Thread Local과 관련없는 문제였지만, 내가 겪었던문제를 다른사람들이 격을수도 있기때문에 엮었고 문제에대한 쉬운 접근방식을 다시한번 생각할수 있었기에 좋은 경험이라 생각들었다.