log level에 해당되는 글 1건

스프링 핵심 원리 - 고급편 2

Spring 정리 2022. 10. 29. 18:49

인프런 강의 61일차.

 - 스프링 핵심 원리 - 고급편 (김영한 강사님)

 - 반드시 한번은 정복해야할 쉽지 않은 내용들

 - 크게 3가지 고급 개념을 학습

  1. 스프링 핵심 디자인 패턴

     > 템플릿 메소드 패턴

     > 전략 패턴

     > 템플릿 콜백 패턴

     > 프록시 패턴

     > 데코레이터 패턴

  2. 동시성 문제와 쓰레드 로컬

     > 웹 애플리케이션

     > 멀티쓰레드

     > 동시성 문제

  3. 스프링 AOP

     > 개념, 용어정리

     > 프록시 - JDK 동적 프록시, CGLIB

     > 동작 원리

     > 실전 예제

     > 실무 주의 사항

 - 기타

     > 스프링 컨테이너의 확장 포인트 - 빈 후처리기

     > 스프링 애플리케이션을 개발하는 다양한 실무 팁

 - 타입 컨버터, 파일 업로드, 활용, 쿠키, 세션, 필터, 인터셉터, 예외 처리, 타임리프, 메시지, 국제화, 검증 등등

 

 

 1.4. 로그 추적기 V1 - 적용

  - 애플리케이션에 우리가 개발한 로그 추적기를 적용해보자.

  - v0 -> v1 복사 후 v1 적용

 

package hello.advanced.app.v1;

import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.helloTrace.HelloTraceV1;
import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
@RequiredArgsConstructor
public class OrderControllerV1 {

    private final OrderServiceV1 orderService;
    private final HelloTraceV1 trace;


    @GetMapping("/v1/request")
    public String request(String itemId) {
        TraceStatus status = null;
        try {
            status = trace.begin("OrderController.request()");
            orderService.OrderItem(itemId);
            trace.end(status);
            return "ok";
        }catch (Exception e){
            trace.exception(status, e);
            throw e;    //예외를 꼭 다시 던져줘야 한다. (trace.exception에서 예외처리를 해두었기 때문)
        }
    }
}

  - hello/advanced/app/v1/OrderControllerV1.java

  - HelloTraceV1 trace : HelloTraceV1 을 주입 받는다.

  - 참고로 HelloTraceV1 은 @Component 애노테이션을 가지고 있기 때문에 컴포넌트 스캔의 대상이 된다.

  - trace.begin("OrderController.request()") : 로그를 시작할 때 메시지 이름으로 컨트롤러 이름 + 메서드 이름을 주었다.

    > 이렇게 하면 어떤 컨트롤러와 메서드가 호출되었는지 로그로 편리하게 확인할 수 있다. 물론 수작업이다

  - 단순하게 trace.begin() , trace.end() 코드 두 줄만 적용하면 될 줄 알았지만, 실상은 그렇지 않다. trace.exception() 으로 예외까지 처리해야 하므로 지저분한 try , catch 코드가 추가된다.

  - begin() 의 결과 값으로 받은 TraceStatus status 값을 end() , exception() 에 넘겨야 한다. 결국 try , catch 블록 모두에 이 값을 넘겨야한다. 따라서 try 상위에 TraceStatus status 코드를 선언해야 한다. 만약 try 안에서 TraceStatus status 를 선언하면 try 블록안에서만 해당 변수가 유효하기 때문에 catch 블록에 넘길 수 없다. 따라서 컴파일 오류가 발생한다.

  - throw e : 예외를 꼭 다시 던져주어야 한다. 그렇지 않으면 여기서 예외를 먹어버리고, 이후에 정상 흐름으로 동작한다. 로그는 애플리케이션에 흐름에 영향을 주면 안된다. 로그 때문에 예외가 사라지면 안된다.

 

package hello.advanced.app.v1;

import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.helloTrace.HelloTraceV1;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;

@Service
@RequiredArgsConstructor
public class OrderServiceV1 {

    private final OrderRepositoryV1 orderRepository;
    private final HelloTraceV1 trace;


    public void OrderItem(String itemId){

        TraceStatus status = null;
        try {
            status = trace.begin("OrderService.OrderItem()");
            orderRepository.save(itemId);
            trace.end(status);
        }catch (Exception e){
            trace.exception(status, e);
            throw e;    //예외를 꼭 다시 던져줘야 한다. (trace.exception에서 예외처리를 해두었기 때문)
        }
    }
}

  - hello/advanced/app/v1/OrderServiceV1.java

 

package hello.advanced.app.v1;

import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.helloTrace.HelloTraceV1;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;


@Repository
@RequiredArgsConstructor
public class OrderRepositoryV1 {
    private final HelloTraceV1 trace;

    public void save(String itemId) {

        TraceStatus status = null;
        try {
            status = trace.begin("OrderRepository.save()");
            //저장 로직
            if (itemId.equals("ex")) {  //상품 ID 가 ex 면 예외 처리
                throw new IllegalStateException("예외 발생!");
            }
            sleep(1000);    //상품을 저장하는데 1초가 걸린다고 가정
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }


    }

    private void sleep(int miilis) {
        try {
            Thread.sleep(miilis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

  - hello/advanced/app/v1/OrderRepositoryV1.java

 

//정상 실행 로그
[11111111] OrderController.request()
[22222222] OrderService.orderItem()
[33333333] OrderRepository.save()
[33333333] OrderRepository.save() time=1000ms
[22222222] OrderService.orderItem() time=1001ms
[11111111] OrderController.request() time=1001ms

  - 아직 level 관련 기능과 transaction id 를 맞추는 부분은 개발하지 않았다.

 

[0c7f8444] OrderController.request()
[b6506b2b] OrderService.OrderItem()
[2161fa31] OrderRepository.save()
[2161fa31] OrderRepository.save() time=0ms ex=java.lang.IllegalStateException: 예외 발생!
[b6506b2b] OrderService.OrderItem() time=0ms ex=java.lang.IllegalStateException: 예외 발생!
[0c7f8444] OrderController.request() time=4ms ex=java.lang.IllegalStateException: 예외 발생!

  - HelloTraceV1 덕분에 직접 로그를 하나하나 남기는 것 보다는 편하게 여러가지 로그를 남길 수 있었다. 하지만 로그를 남기기 위한 코드가 생각보다 너무 복잡하다. 남은 요구사항을 보자

 

 * 남은 요구사항

  - 모든 PUBLIC 메서드의 호출과 응답 정보를 로그로 출력

  - 애플리케이션의 흐름을 변경하면 안됨

    > 로그를 남긴다고 해서 비즈니스 로직의 동작에 영향을 주면 안됨

  - 메서드 호출에 걸린 시간

  - 정상 흐름과 예외 흐름 구분

    > 예외 발생시 예외 정보가 남아야 함

  - 메서드 호출의 깊이 표현

  - HTTP 요청을 구분

    > HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야 함

    > 트랜잭션 ID (DB 트랜잭션X), 여기서는 하나의 HTTP 요청이 시작해서 끝날 때 까지를 하나의 트랜잭션이라 함

 

 * 남은 기능은 직전 로그의 깊이와 트랜잭션 ID가 무엇인지 알아야 할 수 있는 일이다. 예를 들어서 OrderController.request() 에서 로그를 남길 때 어떤 깊이와 어떤 트랜잭션 ID를 사용했는지를 그 다음에 로그를 남기는 OrderService.orderItem() 에서 로그를 남길 때 알아야한다. 결국 현재 로그의 상태 정보인 트랜잭션ID 와 level 이 다음으로 전달되어야 한다. 정리하면 로그에 대한 문맥( Context ) 정보가 필요하다.

 

 1.5. 로그 추적기 V2 - 파라미터로 동기화 개발

  - 트랜잭션ID와 메서드 호출의 깊이를 표현하는 하는 가장 단순한 방법은 사용한 트랜잭션ID 와 level 를 파라미터화 한다.

 

package hello.advanced.trace.helloTrace;

import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;

@Slf4j
@Component
public class HelloTraceV2 {
	...
    //V2에서 추가
    public TraceStatus beginSync(TraceId beforeTraceId, String message) {
	//  TraceId traceId = new TraceId();
        TraceId nextId = beforeTraceId.createNextId();
        Long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}", nextId.getId(), addSpace(START_PREFIX, nextId.getLevel()), message);
        return new TraceStatus(nextId, startTimeMs, message);
    }
	...
}

  - hello/advanced/trace/helloTrace/HelloTraceV2.java

  - 기존 HelloTraceV1에서 beginSync 메소드만 추가되었다,

 

 * beginSync(..)  : 기존 TraceId 에서 createNextId() 를 통해 다음 ID를 구한다.

  - createNextId() 의 TraceId 생성 로직 : 트랜잭션ID는 기존과 같이 유지하고, 깊이를 표현하는 Level만 하나 증가한다.

 

package hello.advanced.trace.helloTrace;

import hello.advanced.trace.TraceStatus;
import org.junit.jupiter.api.Test;

class HelloTraceV2Test {

    @Test
    void begin_end_level2() {
        HelloTraceV2 trace = new HelloTraceV2();
        TraceStatus status1 = trace.begin("hello1");
        TraceStatus status2 = trace.beginSync(status1.getTraceId(), "hello2");
        //status end는 호출한 순서 역순으로 진행.
        trace.end(status2);
        trace.end(status1);
    }

    @Test
    void begin_exception_level2() {
        HelloTraceV2 trace = new HelloTraceV2();
        TraceStatus status1 = trace.begin("hello1");
        TraceStatus status2 = trace.beginSync(status1.getTraceId(), "hello2");
        //status end는 호출한 순서 역순으로 진행.
        trace.exception(status2, new IllegalStateException());
        trace.exception(status1, new IllegalStateException());
    }
}

  - hello/advanced/trace/helloTrace/HelloTraceV2Test.java

  - HelloTrace2를 적용한 Test

 

// begin_end_level2() - 실행 로그
[299b9e59] hello1
[299b9e59] |-->hello2
[299b9e59] |<--hello2 time=8ms
[299b9e59] hello1 time=22ms

// begin_exception_level2() - 실행 로그
[5beb874d] hello1
[5beb874d] |-->hello2
[5beb874d] |<X-hello2 time=1ms ex=java.lang.IllegalStateException
[5beb874d] hello1 time=2ms ex=java.lang.IllegalStateException

  - 같은 트랜잭션ID 를 유지하고 level 을 통해 메서드 호출의 깊이를 표현하는 것을 확인할 수 있다.

 

 1.6. 로그 추적기 V2 - 적용

  - v1 -> v2 복사 후 v2 적용

  - 메서드 호출의 깊이를 표현하고, HTTP 요청도 구분해보자. 이렇게 하려면 처음 로그를 남기는 OrderController.request() 에서 로그를 남길 때 어떤 깊이와 어떤 트랜잭션 ID를 사용했는지 다음 차례인 OrderService.orderItem() 에서 로그를 남기는 시점에 알아야한다.

  - 결국 현재 로그의 상태 정보인 트랜잭션ID 와 level 이 다음으로 전달되어야 한다.

  - 이 정보는 TraceStatus.traceId 에 담겨있다. 따라서 traceId 를 컨트롤러에서 서비스를 호출할 때 넘겨주면 된다

 

package hello.advanced.app.v2;

import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.helloTrace.HelloTraceV1;
import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
@RequiredArgsConstructor
public class OrderControllerV2 {

    private final OrderServiceV2 orderService;
    private final HelloTraceV1 trace;

    @GetMapping("/v2/request")
    public String request(String itemId) {
        TraceStatus status = null;
        try {
            status = trace.begin("OrderController.request()");
            orderService.OrderItem(status.getTraceId(), itemId);
            trace.end(status);
            return "ok";
        }catch (Exception e){
            trace.exception(status, e);
            throw e;    //예외를 꼭 다시 던져줘야 한다. (trace.exception에서 예외처리를 해두었기 때문)
        }
    }
}

  - hello/advanced/app/v2/OrderControllerV2.java

  - TraceStatus status = trace.begin() 에서 반환 받은 TraceStatus 에는 트랜잭션ID 와 level 정보가 있는 TraceId 가 있다.

  - orderService.orderItem() 을 호출할 때 TraceId 를 파라미터로 전달한다.

  - TraceId 를 파라미터로 전달하기 위해 OrderServiceV2.orderItem() 의 파라미터에 TraceId 를 추가해야 한다.

 

package hello.advanced.app.v2;

import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.helloTrace.HelloTraceV1;
import hello.advanced.trace.helloTrace.HelloTraceV2;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;

@Service
@RequiredArgsConstructor
public class OrderServiceV2 {

    private final OrderRepositoryV2 orderRepository;
    private final HelloTraceV2 trace;


    public void OrderItem(TraceId traceId, String itemId){

        TraceStatus status = null;
        try {
            status = trace.beginSync(traceId, "OrderService.OrderItem()");
            orderRepository.save(status.getTraceId(), itemId);
            trace.end(status);
        }catch (Exception e){
            trace.exception(status, e);
            throw e;    //예외를 꼭 다시 던져줘야 한다. (trace.exception에서 예외처리를 해두었기 때문)
        }
    }
}

  - hello/advanced/app/v2/OrderServiceV2.java

  - orderItem() 은 파라미터로 전달 받은 traceId 를 사용해서 trace.beginSync() 를 실행한다.

  - beginSync() 는 내부에서 다음 traceId 를 생성하면서 트랜잭션ID는 유지하고 level 은 하나 증가시킨다.

  - beginSync() 가 반환한 새로운 TraceStatus 를 orderRepository.save() 를 호출하면서 파라미터로 전달한다.

  - TraceId 를 파라미터로 전달하기 위해 orderRepository.save() 의 파라미터에 TraceId 를 추가해야 한다.

 

package hello.advanced.app.v2;

import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.helloTrace.HelloTraceV1;
import hello.advanced.trace.helloTrace.HelloTraceV2;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;


@Repository
@RequiredArgsConstructor
public class OrderRepositoryV2 {
    private final HelloTraceV2 trace;

    public void save(TraceId traceId, String itemId) {

        TraceStatus status = null;
        try {
            status = trace.beginSync(traceId, "OrderRepository.save()");
            //저장 로직
            if (itemId.equals("ex")) {  //상품 ID 가 ex 면 예외 처리
                throw new IllegalStateException("예외 발생!");
            }
            sleep(1000);    //상품을 저장하는데 1초가 걸린다고 가정
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }


    }

    private void sleep(int miilis) {
        try {
            Thread.sleep(miilis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

 

  - hello/advanced/app/v2/OrderRepositoryV2.java

  - save() 는 파라미터로 전달 받은 traceId 를 사용해서 trace.beginSync() 를 실행한다.

  - beginSync() 는 내부에서 다음 traceId 를 생성하면서 트랜잭션ID는 유지하고 level 은 하나 증가시킨다.

  - beginSync() 는 이렇게 갱신된 traceId 로 새로운 TraceStatus 를 반환한다.

  - trace.end(status) 를 호출하면서 반환된 TraceStatus 를 전달한다

 

// 정상 실행 로그
[ef297b0a] OrderController.request()
[ef297b0a] |-->OrderService.OrderItem()
[ef297b0a] | |-->OrderRepository.save()
[ef297b0a] | |<--OrderRepository.save() time=1004ms
[ef297b0a] |<--OrderService.OrderItem() time=1005ms
[ef297b0a] OrderController.request() time=1008ms

// 예외 실행 로그
[0bd1dc2d] OrderController.request()
[0bd1dc2d] |-->OrderService.OrderItem()
[0bd1dc2d] | |-->OrderRepository.save()
[0bd1dc2d] | |<X-OrderRepository.save() time=1ms ex=java.lang.IllegalStateException: 예외 발생!
[0bd1dc2d] |<X-OrderService.OrderItem() time=2ms ex=java.lang.IllegalStateException: 예외 발생!
[0bd1dc2d] OrderController.request() time=2ms ex=java.lang.IllegalStateException: 예외 발생!

  - 실행 로그를 보면 같은 HTTP 요청에 대해서 트랜잭션ID 가 유지되고, level 도 잘 표현되는 것을 확인할 수 있다.

  - 모든 요구사항을 만족했다.

 

 * 사용할 때 문제

  - HTTP 요청을 구분하고 깊이를 표현하기 위해서 TraceId 동기화가 필요하다

  - TraceId 의 동기화를 위해서 관련 메서드의 모든 파라미터를 수정해야 한다.

    > 만약 인터페이스가 있다면 인터페이스까지 모두 고쳐야 하는 상황이다.

  - 로그를 처음 시작할 때는 begin() 을 호출하고, 처음이 아닐때는 beginSync() 를 호출해야 한다

    > 만약에 컨트롤러를 통해서 서비스를 호출하는 것이 아니라, 다른 곳에서 서비스를 처음으로 호출하는 상황이라면 파리미터로 넘길 TraceId 가 없다

'Spring 정리' 카테고리의 다른 글

스프링 핵심 원리 - 고급편 4  (0) 2023.01.16
스프링 핵심 원리 - 고급편 3  (0) 2022.10.29
스프링 핵심 원리 - 고급편 1  (1) 2022.09.20
스프링 MVC 2편 - 백엔드 웹 개발 활용 기술 21  (0) 2022.07.25
스프링 MVC 2편 - 백엔드 웹 개발 활용 기술 20  (0) 2022.07.22
,
1

티스토리툴바