Custom Logger로 통신 문제 해결

어느날 평소에 잘 사용 하던 고객사로 부터 새벽에 앱 접속이 안된다는 연락을 받았다 문제 진단을 위해 앱에서는 OKHttpClient의 connectTimeout, readTimeout, writeTimeout 값 확인 및 API 테스트를 했지만 timeout은 각각 120초로 잘 설정 되어 있었고 테스트에도 문제는 없었다 서버쪽에서도 문제 해결을 위해 timeout 로그를 확인 했지만 관련 로그는 남아 있는게 없었다고 했다

혹시나 하는 마음에 몇몇 API에 Firebase Crashlytics 로그를 남겨 놓은 부분을 확인 했고 로그인 뿐만 아니라 스캔이나 그 외 다른 API 에서 timeout 에러가 나는게 확인 됐다

java.net.SocketTimeoutException: timeout

하지만 이 로그들만으로 문제를 확실히 파악 하기가 불가능 했던게 먼저 Firebase Crashlytics 로그를 모든 API에 연결 해놓지 않았어서 어떤 API 들에서 나는지 특정하기가 어려웠고, 문제가 발생한 유저의 정보나 어느 정도 시간이 지났을 때 발생 하는지 등 자세한 정보가 없었다 방법을 찾던 중 Android Studio에 device를 연결하여 개발할 때 API를 호출 하면 okhttp.OkHttpClient 에서 자세한 로그를 찍어주던게 생각 났다 timeout이 발생할 때 OkHttpClient 로그를 남길 수 있다면 어떤 API에서 문제가 생기는지 정확한 파악이 가능할거 같았고 okhttp.OkHttpClient 로그에 대한 정보를 찾아봤다

okhttp.OKHttpClient 로그는 OkHttpClient.Builder()에 추가한 HttpLoggingInterceptor 에서

  private class DefaultLogger : Logger {
    override fun log(message: String) {
      Platform.get().log(message)
    }
  }

이 메소드를 통해 로그를 남기는거였고 나는 저 로그를 남기기 위해 HttpLoggingInterceptor.Logger 를 상속한 HttpLogger Class를 만들었다 HttpLogger는 위에 DefaultLogger 처럼 log 메소드를 override 하고 있었고 message를 Log로 찍어보니 내가 원하는 로그가 Logcat에 찍혔다 로그가 잘 찍히는걸 확인 하고 로그를 저장 하려고 보니 몇 가지 문제가 있었다

먼저 Logger의 로그는 요청과 결과 값이 하나의 String으로 들어오지 않고 한 줄씩 들어 오는 것이였다

--> POST /greeting http/1.1
Host: example.com
Content-Type: plain/text
Content-Length: 3

Hi?
--> END POST

<-- 200 OK (22ms)
Content-Type: plain/text
Content-Length: 6

Hello!
<-- END HTTP

이런 형식의 데이터가 한 줄씩 들어 오기 때문에 로그를 API 요청별로 저장할 수 없었고 해결 방법을 고민하다 StringBuffer에 로그를 넣어서 저장할 수 있도록 방향성을 잡았다 이제 어떻게 하면 통신 오류 상황에서의 로그만을 필터링 해서 저장할 수 있을까가 문제였는데 HttpLogginInterceptor 의 Example 코드와 테스트를 통해 규칙을 찾을 수 있었다

API가 정상 호출 됐을 때, 통신 오류가 나는 경우를 테스트 했을 때 시작은 항상 --> POST 또는 --> GET으로 시작 되는걸 발견 했다 그리고 종료는 <-- END HTTP 또는 <-- HTTP FAILED 로 종료 된다

val isStartLog : Boolean = message.startsWith("--> POST") || message.startsWith("--> GET")
val isEndLog : Boolean = message.startsWith("<-- END HTTP") || message.startsWith("<-- HTTP FAILED")

시작과 종료를 구분할 수 있는 규칙을 사용 하여 시작과 종료를 구분할 수 있는 Boolean 값을 만들었고 isStartLog 일 때 StringBuffer에 유저 정보를 append 하고 isEndlog 일 때 StringBuffer를 초기화 하도록 코드를 작성 했고 isEndlog에서 message에 FAILED이 포함 되어 있는 경우 Firebase Crashlytics의 recordException()을 사용 하여 로그를 남겼다

코드를 완성한 후 또 하나의 문제가 발생 됐는데 API가 직렬로 호출 되지 않고 병렬로 동시에 호출 되는 경우에 log message가 섞이는 문제가 생겼다 여기서 더 큰 문제는 isEndlog 일 때 StringBuffer를 비우는데 log message가 섞이면서 통신 에러가 나는 경우에도 정상적으로 로그가 남지 않는 경우가 생겼다

이 문제를 해결 하기 위해 var apiCallCount : Int = 0 변수를 생성 하여 isStartLog 일 때 apiCallCount++, isEndLog 일 때 apiCallCount-- 하여 apiCallCount == 0 경우에만 StringBuffer를 비우도록 처리 했다

이렇게 처리하면 API가 병렬로 호출 되더라도 모든 API를 다 호출한 후 저장이 되게 된다

커스텀 HttpLogger를 다 만든 후 배포를 하여 확인 해보니 02시 이후부터 로그인과 스캔 API에서 timeout 문제가 발생 되는걸 확인 했고 두 API의 공통점을 찾아 보니 회사 공용 DB에 로그를 저장 하는 로직이 있었다 그리고 그 공용 DB에 02시에 스케줄러를 통해 작업을 하는 부분이 있었는데 스케줄러 작업 때문에 공용 DB가 문제가 생기면서 앱에도 문제가 생긴거였다

다행히 문제를 찾아내서 DB를 분리 하는 방법으로 문제 해결을 했다