주요글: 도커 시작하기
반응형

스프링 리액터 로깅과 체크포인트


로깅

리액터의 동작을 보다 자세히 보고 싶다면 다음과 같이 log() 메서드를 사용한다. 아래 코드를 보자.


Flux.just(1, 2, 4, 5, 6)

        .log()

        .map(x -> x * 2)

        .subscribe(x -> logger.info("next: {}", x));


로깅 프레임워크로 SLF4j를 사용할 경우 실행한 결과는 다음과 같다.

08:38:29.990 [main] DEBUG reactor.util.Loggers$LoggerFactory - Using Slf4j logging framework
08:38:30.010 [main] INFO reactor.Flux.Array.1 - | onSubscribe([Synchronous Fuseable] FluxArray.ArraySubscription)
08:38:30.013 [main] INFO reactor.Flux.Array.1 - | request(unbounded)
08:38:30.014 [main] INFO reactor.Flux.Array.1 - | onNext(1)
08:38:30.014 [main] INFO logging.LoggingTest - next: 2
08:38:30.014 [main] INFO reactor.Flux.Array.1 - | onNext(2)
08:38:30.014 [main] INFO logging.LoggingTest - next: 4
08:38:30.014 [main] INFO reactor.Flux.Array.1 - | onNext(4)
08:38:30.014 [main] INFO logging.LoggingTest - next: 8
08:38:30.014 [main] INFO reactor.Flux.Array.1 - | onNext(5)
08:38:30.014 [main] INFO logging.LoggingTest - next: 10
08:38:30.014 [main] INFO reactor.Flux.Array.1 - | onNext(6)
08:38:30.014 [main] INFO logging.LoggingTest - next: 12
08:38:30.015 [main] INFO reactor.Flux.Array.1 - | onComplete()

"reactor.Flux.Array.1"이라는 로거가 출력한 로그 메시지는 Flux.just()가 생성한 시퀀스의 동작을 로그로 남긴 것이다. 로그를 보면 시퀀스가 request() 신호를 받은 시점, next 신호(onNext(2) 등)나 complete 신호(onComplete())를 발생한 시점을 확인할 수 있다.


로그 레벨은 INFO인데 로그 레벨을 변경하고 싶다면 다음과 같이 log() 메서드를 사용하면 된다.


Flux.just(1, 2, 4, 5, 6)

        .log(null, Level.FINE) // java.util.logging.Level 타입

        .subscribe(x -> logger.info("next: {}", x));


두 번째 인자로 자바 로깅의 Level.FINE을 주었다. SLF4j를 사용할 경우 리액터는 자바의 FINE 레벨을 SLF4j의 DEBUG 레벨로 기록한다. 따라서 위 코드를 실행하면 다음과 같이 DEBUG 레벨로 로그를 남기는 것을 확인할 수 있다.


08:50:30.098 [main] DEBUG reactor.Flux.Array.1 - | onSubscribe([Synchronous Fuseable] FluxArray.ArraySubscription)

08:50:30.101 [main] DEBUG reactor.Flux.Array.1 - | request(unbounded)

08:50:30.102 [main] DEBUG reactor.Flux.Array.1 - | onNext(1)

08:50:30.102 [main] INFO logging.LoggingTest - next: 1

08:50:30.102 [main] DEBUG reactor.Flux.Array.1 - | onNext(2)

08:50:30.102 [main] INFO logging.LoggingTest - next: 2


다음과 같이 특정 로거를 이용하도록 지정할 수도 있다. 


Flux.just(1, 2, 4, 5, 6)

        .log("MYLOG") // 또는 log("MYLOG", Level.INFO)

        .subscribe(x -> logger.info("next: {}", x));


위 코드를 실행하면 다음과 같이 지정한 로거를 이용해서 로그를 남긴다.


08:51:55.180 [main] INFO MYLOG - | onSubscribe([Synchronous Fuseable] FluxArray.ArraySubscription)

08:51:55.184 [main] INFO MYLOG - | request(unbounded)

08:51:55.184 [main] INFO MYLOG - | onNext(1)

08:51:55.184 [main] INFO logging.LoggingTest - next: 1

08:51:55.184 [main] INFO MYLOG - | onNext(2)

08:51:55.184 [main] INFO logging.LoggingTest - next: 2

08:51:55.184 [main] INFO MYLOG - | onNext(4)


체크포인트

시퀀스가 신호를 발생하는 과정에서 익셉션이 발생하면 어떻게 될까? 시퀀스가 여러 단게를 거쳐 변환한다면 어떤 시점에 익셉션이 발생했는지 단번에 찾기 힘들 수도 있다. 이럴 때 도움이 되는 것이 체크포인트이다. 다음은 체크포인트 사용 예이다.


Flux.just(1, 2, 4, -1, 5, 6)

        .map(x -> x + 1)

        .checkpoint("MAP1")

        .map(x -> 10 / x) // 원본 데이터가 -1인 경우 x는 0이 되어 익셉션이 발생

        .checkpoint("MAP2")

        .subscribe(

                x -> System.out.println("next: " + x),

                err -> err.printStackTrace());


이 코드는 데이터에 1을 더하고 다시 10을 데이터로 나누는 변환을 수행한다. 원본 데이터에 -1이 있으므로 중간에 0으로 나누게 되어 익셉션이 발생하게 된다. checkpoint()를 사용하면 어떤 단계에서 익셉션이 발생했는지 쉽게 확인할 수 있다. 아래 코드는 익셉션이 발생했을 때 출력한 익셉션 트레이스 메시지인데 이 메시지를 보면 checkpoint()로 지정한 description이 익셉션 트레이스 마지막에 출력되는 것을 알 수 있다. 이를 통해 어느 과정에서 익셉션이 발생했는지 쉽게 찾을 수 있다.

java.lang.ArithmeticException: / by zero
    at logging.CheckpointTest.lambda$checkpoint$1(CheckpointTest.java:15)
    at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:107)
    ...생략
    Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Assembly site of producer [reactor.core.publisher.FluxMapFuseable] is identified by light checkpoint [MAP2]."description" : "MAP2"



관련글


+ Recent posts