저작권 안내: 저작권자표시 Yes 상업적이용 No 컨텐츠변경 No

스프링5 입문

JSP 2.3

JPA 입문

DDD Start

인프런 객체 지향 입문 강의

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


로깅

리액터의 동작을 보다 자세히 보고 싶다면 다음과 같이 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"



관련글


Posted by 최범균 madvirus

댓글을 달아 주세요