[Reactive Programming] Debugging

 

 

 

개요

 

동기식 또는 명령형 프로그래밍 방식은 Exception이 발생했을 때, StackTrace를 확인하거나 의심되는 코드에 Breakpoint를 걸어서 문제의 원인을 단계적으로 찾아갈 수 있어 상대적으로 디버깅이 쉽다.

 

하지만 Reactor 같은 선언형 프로그래밍 방식은 작업의 대부분이 비동기적으로 실행되기 때문에 디버깅이 쉽지 않다. 그래서 Reactor는 디버깅의 어려움을 최소화하기 위해 몇 가지 방법을 제공한다.

 

 

 

---

Debug Mode를 사용한 디버깅

 

Reactor에서는 Hooks.onOperatorDebug() 메서드를 사용하여 디버그 모드를 활성화할 수 있다. 우선, 디버그 모드가 아닐 때 에러 메시지가 어떻게 출력되는지 확인해보자.

 

@Slf4j
public class Example12_1 {
	public static Map<String, String> fruits = new HashMap<>();

	static {
		fruits.put("banana", "바나나");
		fruits.put("apple", "사과");
		fruits.put("pear", "배");
		fruits.put("grape", "포도");
	}

	public static void main(String[] args) throws InterruptedException {
		// Hooks.onOperatorDebug();

		Flux
			.fromArray(new String[] {"BANANAS", "APPLES", "PEARS", "MELONS"})
			.subscribeOn(Schedulers.boundedElastic())
			.publishOn(Schedulers.parallel())
			.map(String::toLowerCase)
			.map(fruit -> fruit.substring(0, fruit.length() - 1))
			.map(fruits::get) // Map operator가 연속되면 IDE에서 Overhead에 대한 경고를 한다. 지양해야 하는 패턴.
			.map(translated -> "맛있는 " + translated)
			.subscribe(
				log::info,
				error -> log.error("# onError: ", error));

		Thread.sleep(100L);
	}
}

위 코드에서는 원본 데이터에 MELONS가 존재하지만 fruits에는 존재하지 않아, 세 번째 maps chain에서 get을 할 때 NullPointException 예외가 발생한다. 실제 발생하는 에러 메시지는 다음과 같다.

 

 

디버그 모드가 아닐 때 예외 메시지

 

예상대로 NullPointException이 발생했고 이것이 mapper에서 유발되었음을 확인할 수 있다. 하지만 4개나 되는 map Operator 중 어느 부분에서 발생했는지 추적이 어렵고, 그 이외에 디버깅에 유의미한 정보가 거의 없다. 

 

이번에는 Hooks.onOperatorDebug()의 주석을 해제한 뒤 에러 메시지를 확인해보도록 하자.

 

 

디버그 모드일 때 예외 메시지

 

디버그 모드를 활성화했더니 원래 메시지와 Stack Trace 사이에 새로운 내용이 추가되었다. Opeartor 체인에서 에러가 발생한 지점을 정확히 짚고 있고, 전파 상태 또한 표시해 준다.

 

한계

디버그 모드를 활성화하면 다음과 같은 동작을 거치기 때문에 많은 Overhead가 발생한다.

 

1. 애플리케이션 내에 있는 모든 Operator의 Stack Trace를 캡쳐한다.
2. 에러가 발생하면 캡쳐한 정보를 기반으로 에러가 발생한 Assembly의 Stack Trace를 원본 Stack Trace 중간에 끼워 넣는다.

 

따라서 에러 원인을 추적하기 위해 처음부터 디버그 모드를 활성화하는 것은 권장되지 않는다.

 

• Assembly: Operator에서 반환하는 새로운 Mono 또는 Flux가 선언된 지점
• Traceback: 디버그 모드를 활성화하면 Operator의 Assembly 정보를 캡쳐하는데, 이 중에서 에러가 발생한 Operator의 Stack Trace를 캡쳐한 Assembly 정보

---

checkpoint() Operator를 사용한 디버깅

 

디버그 모드를 활성화할 경우 애플리케이션 내에 있는 모든 Operator에서 Stack Trace를 캡쳐하게 되어 Overhead가 많이 발생한다. 반면 checkpoint() Operator를 사용할 경우, 특정 Operator 체인 내의 Stack Trace만 캡쳐하기 때문에 남발하지만 않는다면 이같은 낭비를 방지할 수 있다.

 

checkpoint()는 해당 체크포인트를 설정한 부분까지 정상 동작했는지 확인하는 용도로, 만약 예외가 전파된 경우 해당 체크포인트 지점의 traceback을 전달해준다.  이 checkpointI()를 이용하는 방법에는 크게 세 가지가 있다.

 

 

Traceback을 출력하는 방법

@Slf4j
public class Example12_2 {
	public static Map<String, Integer> numbers = new HashMap<>();

	public static void main(String[] args) throws InterruptedException {
		numbers.put("one", 1);
		numbers.put("two", 2);
		numbers.put("three", 3);

		Flux
			.just("one", "two", "four")
			.publishOn(Schedulers.boundedElastic())
			.checkpoint()
			.map(numbers::get)
			.checkpoint()
			.zipWith(Flux.just(1, 2, 3), (x, y) -> x * y)
			.checkpoint()
			.subscribe(
				data -> log.info("# onNext: {}", data),
				error -> log.error("# onError:", error)
			);

		Thread.sleep(100L);
	}
}

실행 결과

 

(책의 예제대로 ArithmeticException을 발생시키면 책에서 설명하는 것과 달리 checkpoint()유무와 상관없이 정확한 예외 지점의 traceback을 제공하여 다른 예제로 대체한다.)

 

checkpoint()를 사용하면 upstream에서 예외가 발생한 경우 위 사진처럼 예외가 전파된 checkpoint()의 traceback을 제공한다. 예외 발생 지점의 traceback을 제공하는 것은 아님에 주의해야 한다.

 

만약 checkpoint() 지점에 전파된 예외가 없다면 해당 checkpoint는 무시되고 지나간다.

 

 

Traceback 대신 Description 출력하는 방법

checkpoint() 안에 파라미터로 String 타입의 description을 전달하면 traceback 대신 description을 출력한다.

 

@Slf4j
public class Example12_3 {
	public static Map<String, Integer> numbers = new HashMap<>();

	public static void main(String[] args) throws InterruptedException {
		numbers.put("one", 1);
		numbers.put("two", 2);
		numbers.put("three", 3);

		Flux
			.just("one", "two", "four")
			.publishOn(Schedulers.boundedElastic())
			.map(numbers::get)
			.checkpoint("map checkpoint")
			.zipWith(Flux.just(1, 2, 3), (x, y) -> x * y)
			.checkpoint("zipWith checkpoint")
			.subscribe(
				data -> log.info("# onNext: {}", data),
				error -> log.error("# onError:", error)
			);

		Thread.sleep(100L);
	}
}

traceback 대신 description이 출력됨

 

 

Traceback과 Description을 모두 출력하는 방법

checkpoint(description, forceStackTrace) 메서드에서 boolean 타입인 forceStackTrace의 값을 true로 전달하면 Traceback과 description을 모두 출력할 수 있다.

 

@Slf4j
public class Example12_5 {
	public static Map<String, Integer> numbers = new HashMap<>();

	public static void main(String[] args) throws InterruptedException {
		numbers.put("one", 1);
		numbers.put("two", 2);
		numbers.put("three", 3);

		Flux
			.just("one", "two", "four")
			.checkpoint("emitted")
			.publishOn(Schedulers.boundedElastic())
			.map(numbers::get)
			.checkpoint("map checkpoint", true)
			.zipWith(Flux.just(1, 2, 3), (x, y) -> x * y)
			.checkpoint("zipWith checkpoint", true)
			.subscribe(
				data -> log.info("# onNext: {}", data),
				error -> log.error("# onError:", error)
			);

		Thread.sleep(100L);
	}
}

Traceback과 Description이 모두 출력된 모습

 

 

---

log() Operator를 사용한 디버깅

 

log() Operator는 Reactor Sequence의 동작을 로그로 출력하기 때문에, 이 로그를 통해 디버깅이 가능하다.

 

@Slf4j
public class Example12_7 {
	public static Map<String, String> fruits = new HashMap<>();

	static {
		fruits.put("banana", "바나나");
		fruits.put("apple", "사과");
		fruits.put("pear", "배");
		fruits.put("grape", "포도");
	}

	public static void main(String[] args) throws InterruptedException {
		Flux
			.fromArray(new String[] {"BANANAS", "APPLES", "PEARS", "MELONS"})
			.map(String::toLowerCase)
			.map(fruit -> fruit.substring(0, fruit.length() - 1))
			.log()
			.map(fruits::get)
			.subscribe(
				log::info,
				error -> log.error("# onError: ", error));

		Thread.sleep(100L);
	}
}

Reactor Sequence의 동작이 출력된 모습

 

onSubscribe(), request(), onNext() 같은 Signal들이 출력된 것을 확인할 수 있다. 이는 두 번째 map operator에서 발생한 Singal들이다. 

 

해당 signal들을 추적하다 보면 마지막에 cancel이라는 signal을 확인할 수 있는데, 이는 두 번째 map이 downstream으로 melon이라는 문자열을 Emit했지만, 그 이후의 operator에서 어떤 예외가 발생했음을 의미한다.

 

로그 분석을 보다 쉽게 하기 위해서 로그에 카테고리를 부여할 수 있으며, 위처럼 Log level을 모두 INFO로 하는 것이 아닌, log()에서 출력된 부분은 DEBUG 등의 다른 Level로 출력할 수 있다. 사용법은 다음과 같다.

 

public static void main(String[] args) throws InterruptedException {
    Flux
        .fromArray(new String[] {"BANANAS", "APPLES", "PEARS", "MELONS"})
        .map(String::toLowerCase)
        .map(fruit -> fruit.substring(0, fruit.length() - 1))
        .log("substring", Level.FINE)
        .map(fruits::get)
        .log("get", Level.FINE)
        .subscribe(
            log::info,
            error -> log.error("# onError: ", error));

    Thread.sleep(100L);
}

 

log() operator에서 출력되는 부분은 Debug Level로, log에서 지정한 카테고리별로 출력되는 것을 확인할 수 있다.

 

 

---

정리

 

방법	장점	단점
디버그 모드 활성화	- 개발 중 디테일한 오류 메시지 확인 가능 - 모든 이벤트의 흐름을 추적할 수 있음	- 성능 저하 발생 가능 - 복잡한 어플리케이션에서 과도한 정보로 인해 디버깅이 어려울 수 있음
checkpoint() 사용	- 특정 위치에서 프로그램 상태를 점검 가능 - 코드 실행의 특정 지점에서 문제를 쉽게 파악 가능	- 명시적인 코드 삽입이 필요하므로 코드 가독성 저하 가능 - 예외 처리 및 성능에 미치는 영향 고려 필요
log() 사용	- 중요한 정보 또는 이벤트 흐름을 기록하여 문제 원인 추적 가능 - 실행 과정 중 실시간으로 상태 확인 가능	- 로그 양이 많을 경우 로그를 관리하는 데 시간 소요 - 로그 설정이 복잡하거나, 너무 많은 로그로 인해 디버깅이 어려울 수 있음