[Tip] RxSwift 콜스택만 잔뜩있는 크래시 로그로 디버깅하기

이미 다 아시는 내용일 수도 있지만...
Rx를 많이 쓰다보면 아래와 같은 크래시 로그를 마주하는 것이 낯설지 않죠..

 

그런데 QA나 CS로 들어오는 크래시 로그는 위의 경우 처럼 정작 애플리케이션 코드(위에서는 UseCase라고 되어 있는 부분)의 콜스택은 symbolification되어 있지 않은 경우가 많습니다.

이 경우에 RxSwift 콜스택을 이용하면 의외로 쉽게 문제가 된 지점을 찾아낼 수 있습니다.

위의 콜스택에서 protocol witness for ObserverType.on(_:) in conformance XXXSink<A> 라고 되어있는 콜스택은 Rx의 XXX 오퍼레이터를 사용한 부분이라고 볼 수 있고 따라서 이 경우는 다음과 같은 순서로 Rx 오퍼레이터가 사용된 곳이라고 볼 수 있습니다.

.filter(...)
.withLatestFrom(...)
.compactMap(...)
.timeout(...)
.take(_ count: ...)
.do(onNext: ...)

이렇게 많은 오퍼레이터가 정확히 같은 순서로 사용된 곳은 극히 드물테니 아마 한 두 군데 밖에 없을 것 같습니다.
문제는 이걸 코드에서 어떻게 찾을 것인가...?
여기서 잠깐 고민스러웠지만 다행히 엑스코드는 라인 브레이크를 포함한 정규식으로 검색하는 방법을 지원하더군요.
먼저 다음 정규식으로 검색했습니다.

\.filter(.*\n.*|.*)\.withLatestFrom

filter와 withLatestFrom이 한줄에서 사용되었을 수도 있고 두 줄에 걸쳐서 사용되었을 수도 있기 때문에 (.*\n.*|.*) 를 사용했습니다.
두 군데의 검색 결과가 나왔습니다. 공교롭게도 둘 다 DataStore 라는 모듈의 코드였네요.

 

둘다 withLatestFrom 까지만 사용되고 그 다음 compactMap 이 사용되고 있지는 않네요. 하지만 둘다 withLatestFrom의 결과를 그대로 반환하고 있기 때문에 observable(.*\n.*|.*)\.compactMap 으로 검색할 수도 있겠지만 observable이 다른 함수나 프로퍼티에 래핑된 경우도 있고 빈도수도 흔할 것으로 예상되어 그것보다는 timeout오퍼레이터를 사용한 곳이 드물 것 같아서 다음과 같이 검색했습니다.

\.timeout(.*\n.*|.*)\.take

한 군데가 나왔습니다.

여기서 store.conversationObservable은 위 검색결과 중 두번째 함수를 래핑한 함수이기 때문에 콜스택에 나온 순서대로 모든 오퍼레이터가 맞아떨어집니다.

추가적으로 이 경우는 9번 콜스택에서 do 오퍼레이터의 onNext 클로져에서 UseCase의 뭔가를 호출했다가 발생했다는 걸 알 수 있고 콜스택 캡쳐이미지에는 나와 있지 않지만 크래시의 원인이 되는 오류 메시지는 dispatch_sync called on queue already owned by current thread 인 점 등을 고려해보면 이 크래시는 serial queue 에서 동작하는 DataStore에서 값이 변경되었다는 이벤트가 발생했고 그 스트림을 처리하는 도중에 다시 DataStore에 값을 업데이트 하려고 한 것이 원인이었습니다.

결과적으로 크래시의 원인을 파악하기 위해서는 다른 정보와의 결합이 거의 필수이긴 하겠지만 위의 방법을 알고 있다면 해결의 실마리가 되는 경우를 종종 만날 수 있을 것으로 보입니다.