💡 Intro
앱을 호기롭게 업데이트 했다. 그런데 2가지 치명적인 문제가 발견되었다.
먼저, 기존에 앱을 가지고 있던 사용자가 플레이스토어에서 업데이트를 요청하는 경우 다음과 같은 화면이 발생하며 업데이트가 되지 않는 문제가 있었다.. 처음 보는 문제이고, 내가 직접 겪은 것이 아니라 사용자가 나에게 이러한 문제가 있다고 알려주어서 상당히 곤란했다. 그래도 이러한 문제가 뜨고, 다시 한 번 업데이트 요청을 했을 때는 문제없이 동작한다고 한다.
두 번째 문제는 앱이 지속적으로 비정상종료 되는 것! 정상적으로 앱을 실행하기 위해서는 기존에 존재하던 앱의 캐시와 데이터를 모두 삭제해야만 했다. 그러면 정상적으로 실행이 되었지만 과연 개발자가 아닌 일반 사용자가 앱의 캐시와 데이터를 지우는 작업을 할까? 절대 절대 절대 아니라고 생각한다. 그러니 필수로 해결해야 한다.
해결하려면 원인을 알아야 하는데 짧은 안드로이드 개발 지식으로는 원인을 도저히 예상할 수 없었다. 그리고 더 큰 문제는 그 상황을 재현해볼 수 없다는 것. 내가 앱을 실행하면서 생긴 문제가 아니라 외부의 사용자가 사용하다가 생긴 문제였기 때문에 나는 어떤 상황에서 발생한 것인지를 전혀 알 수 없었다.
하지만 친절한 사용자께서 나에게 문제 발생 상황을 정리하여 공유해주었다. (자세한 상황 설명까지 첨부해셔서 감사합니다 🙇♂️)
1. 로그인한다.
2. 앱 내 로그아웃을 한다.
3. 다시 앱을 켠다.
4. 스플래시 화면에서 비정상 종료된다.이제 문제가 언제 발생하는지는 알아냈다. 하지만 스플래시에서도 적은 작업을 하는 것이 아니라 어디서 문제가 발생하는지 바로 캐치할 수 없었다. 어디서 문제가 발생하는지 어떻게 찾을 수 있을까 계속 고민했는데 아주 좋은 방법이 떠올랐다.
👏 Firebase Crashlytics
Firebase Crashlytics를 추가해두었었다. 하지만 활용은 커녕 들어가보지도 않았다. 앱의 비정상 종료를 로깅하는 친구라고만 알고 있고 어디에 활용할 수 있을지 감이 오지 않았는데 바로 지금 필요한 때였다. Firebase Crashlytics를 연결해두길 잘헀구나 하는 생각이 들었고, 전혀 고려하지 않고 활용하지 못하고 있던 친구를 드디어 이번에 활용할 수 있게 되었다.
들어가보니 역시나 앱의 비정상 종료를 모두 로깅하고 있었고 로깅은 모습은 아래 사진과 같다.
안드로이드 스튜디오에서 찍히는 로그와 똑같이 생겨서 정말 신기했다.
이것 이외에도 엄청난 비정상 종료 로그가 찍혀있었는데 대부분 앱을 개발하면서 발생한 비정상 종료였다. 릴리즈 모드로 등록해놓은 것이 아니라 개발하면서 발생한 비정상 종료도 모두 로깅이 된다. 이건 고치는 편이 낫겠다고 생각했다.
Crashlytics를 바탕으로 어디서 문제가 발생하는지 찾아낼 수 있었다.
로그인 로직에 문제가 있었는데, 이 기능을 붙일 때 나는 다른 기능을 집중하고 있어서 코드를 100% 이해하고 있지 못했다. (로그인 로직이 좀 까다롭기도 하고..) 그래서 구체적인 로직을 머릿속에 그리기는 어려웠지만 몇 가지의 원인을 추측해볼 수 있었다.
예상 원인
1️⃣ 액세스 토큰 & 리프레시 토큰을 보내주는 과정에서 문제가 있을 수 있다❓
이전 버전에서는 자동 로그인 기능이 없었다. 그래서 리프레시 토큰은 있었지만 실제로 사용되지 않았었다. 하지만 이번 업데이트를 기점으로 자동 로그인을 붙이면서 액세스 토큰과 리프레시 토큰을 모두 사용하도록 변경되었고, 이 때문에 문제가 생길 수도 있겠다 생각했다. 예를 들면 sharedPreferences에 원하는 값이 저장되어 있지 않을 수도 있고, 서버에서 원하는 값을 올바르게 보내지 못하고 있을 수도 있고.
2️⃣ 액세스 토큰이 만료되었을 때 서버로 보내는 요청이 잘못되었다❓
액세스 토큰이 만료된 경우 우리가 가지고 있는 리프레시 토큰을 바디에 담아 서버에 액세스 토큰을 갱신해줘! 라는 요청을 보낸다. 이 요청에 대한 반환 값은 갱신된 액세스 토큰이다. 하지만 리프레시 토큰이 바디에 정상적으로 담기지 않는가? 혹은 만료된 액세스 토큰을 헤더에 담아줘서 그런 것인가? 하는 예상을 해보았다.
3️⃣ 액세스 토큰과 리프레시 토큰을 삭제하는 것이 아닌 “” 값으로 초기화를 시켜주는 것이 문제다❓
문제점을 인식하고 코드를 살펴본 결과 로그아웃 하는 경우 sharedPreferences에 있는 액세스 토큰과 리프레시 토큰을 모두 “”로 변경해주고 있었다. 로그아웃 후에 서버로 다시 요청을 보내게 되면 액세스 토큰 & 리프레시 토큰이 없는 것이 아니라 “”이라는 값으로 존재하기 때문에 잘못된 토큰을 헤더에 담아주고 있고, 이 때문에 서버에서 통과가 되지 않는 것이 아닐까? 하는 생각이 들었다.
여러가지 생각을 했지만 결론부터 말하면 위 문제가 아니다.
문제점
사실 우리 앱에 실사용자는 존재하지 않는다. 그래서 냉정하게 생각해보면 로직의 수정이 시급하지 않다고 생각할 수도 있다.
하지만 만약 사용자가 있는 앱을 배포했을 때 이런 일이 생긴다면? 절대 안된다. 그래서 한시라도 빨리 문제를 해결하고 플레이스토어에 다시 배포하고 싶었다.
좀 이기적일 수 있지만.. 10월 6일 금요일 밤 11시. 연락이 가능한 백엔드를 찾았다. 로그인을 담당한 백엔드 팀원 2명이 달려와주었다. 굉장해 엄청나!!!
백엔드 팀원들과 함께 이야기하고 정리한 로그인이 되는 로직은 다음과 같다.
1. 안드로이드 sdk에서 로그인 요청
2. 사용자가 카카오에 카카오 계정으로 로그인
3. 카카오에서 안드로이드에게 카카오 액세스 토큰을 받아옴
4. 안드로이드에서 카카오 토큰을 가지고 서버에 로그인 요청을 함
5. 서버에서 카카오 액세스 토큰으로 카카오에게 유저 정보를 요청해서 받음
6. 서버에서 서버의 액세스 토큰과 리프레시 토큰을 말아서 안드로이드로 준다.
다음으로 백엔드 팀원들이 현재 서버에 에러 로그가 어떻게 찍히고 있는지 확인해줬다. 여기서 발생한 에러는 서버쪽에서 처리한 뒤에 클라이언트로 내려오는 에러이고, 어떤 경우에 해당 에러가 발생하는지를 괄호 안에 적었다.
1. 토큰 정보가 옳지 않습니다.(서버에 accessToken이 없는 경우)
2. 토큰 정보가 옳지 않습니다.(서버에 accessToken이 없는 경우)
3. 헤더 정보가 존재하지 않습니다.(authorization이 없을 때 발생하는 에러)즉 결론은, 리프레시 요청이 클라이언트에서 서버로 전송되지 않는다 는 것이다.
이유를 찾았으니 이제 해결을 위한 노력을 해보자.
해결과정
어떻게 해결할 수 있을까? 디버깅밖에 모르겠다.
위에서 언급한 문제가 생기는 시나리오 대로 앱을 실행하며 서버로 요청이 어떻게 가고 어떤 응답이 돌아오는지 하나씩 디버깅을 통해 확인했다.
1️⃣ 첫 실행시
1. statistics/my 로 GET 요청을 보낸다. (여기서 인터셉터 로직 발동)
2. 인터셉터에서 sharedPreferences로부터 AccessToken을 가져온다. 하지만 첫 실행이기 때문에 Null이다.
3. Null이기 때문에 chain.proceed()가 실행되고 아무런 추가 작업 없이 요청이 발송된다.
4. 서버에서는 http상태코드는 401, {”code”:101, “message”:”헤더 정보가 존재하지 않습니다.”} 반환해준다.
5. SplashViewModel이 가지고 있는 isTokenValid 라이브데이터가 false로 변경한다.
6. SplashViewModel의 isTokenValid을 구독하고 있는 SplashActivity에서 현재 액티비티를 종료시키고 로그인 뷰로 이동
7. 사용자가 카카오 계정으로 로그인을 한다.
8. /auth 로 POST 요청을 보낸다. → 액세스 토큰과 리프레시 토큰을 발급받고 sharedPreferences에 저장한다.
9. 로그인에 성공한다.이전에도 앱을 처음 실행할 때는 아무런 문제가 발생하지 않았기 때문에 로직이 이상하다거나 잘못된 값을 보낸다거나 하는 문제는 찾지 못했다.
2️⃣ 로그아웃 시
1. sharedPreferences로부터 액세스 토큰을 가져온다.
2. /auth로 DELETE 요청을 보낸다. 이 때 요청의 헤더에 액세스 토큰을 담아준다.
3. 요청에 성공한 경우 http 상태코드는 204가 떨어진다.
4. DefaultAuthDataSource에서 sharedPreferences에 저장되어 있는 액세스 토큰과 리프레시 토큰을 ""로 수정하는 메서드가 실행된다.로그아웃 역시도 문제가 발생하지 않았기 때문에 문제는 찾지 못했다.
3️⃣ 로그아웃 이후 앱 재실행
1. statistics/my 로 GET 요청을 보낸다. (여기서 인터셉터 로직 발동)
2. 인터셉터에서 sharedPreferences로부터 AccessToken을 가져온다.
로그아웃을 했기 때문에 sharedPreferences 에는 AccessToken 키 값에 대해 “”이 저장되어 있고 getAccessToken() 메서드의 실행결과는 “Bearer “ 가 된다.
3. 같은 요청에 대해 헤더 Authorization에 “Bearer “ 만 담아서 보낸다.
4. 서버에서는 http상태코드는 401이 떨어진다.
5. http 상태코드가 401이기 때문에 새로운 액세스 토큰을 발급받기 위해 리프레시 토큰을 사용하여 액세스 토큰을 리프레시 하는 요청을보낸다. 이 때 인자로 들어가는 서버로 전송되는 액세스 토큰은 “Bearer “ 이다.
6. 리프레시 토큰을 가지고 리퀘스트 바디를 만든다. 이 때 리퀘스트 바디는 아래와 같다.
7. 앞에서 얻은 액세스토큰과 리퀘스트 바디를 갖고 리퀘스트를 만든다.
8. 액세스 토큰의 리프레시를 요청하는 리퀘스트를 보낸다. 리퀘스트 요청은 아래와 같다.
여기서 문제가 발생했는데, 잘못된 URL 주소를 던져줘서 생기는 문제였다. 누가봐도 잘못된 URL이라고 보일 것이다.
그리고 여기서 No address associated with hostname 에러가 발생한다.
URL 주소를 /auth/refresh 로 변경해주어 해결했다.
9. 액세스 토큰의 리프레시를 요청하는 리퀘스트를 보낸다. 서버에서는 http상태코드는 401, {"code":101, "message":토큰 정보가 옳지 않습니다."} 를 반환해준다.
10. 토큰 정보가 옳지 않습니다. 즉 요청에 실패 → 로그인 뷰로 이동한다.
11. 카카오톡 로그인을 클릭한다.
12. /auth 로 POST 요청을 보낸다. 헤더에는 잘못된 액세스 토큰이 들어가도 상관없다. 서버에서 확인하지 않기 때문에. 바디에 token과 토큰의 type이 잘 들어가 있다면 요청에 성공한다.
이 문제를 해결하면서 액세스 토큰의 리프레시 요청도 잘 되는지 확인해보고 싶었다. 근데 현 시각 4시 50분. 액세스 토큰의 만료 기한은 30분이다. 일단 30분은 절대 기다릴 수 없다ㅋㅋ.. 이 로직은 어떻게 테스트를 할 수 있을까.. 한참을 고민하다 자고 일어나면 액세스 토큰은 만료되어 있고, 리프레시 토큰은 만료되지 않았을테니 문제가 없겠지!? 했다.
시간이 지나고 액세스 토큰이 만료되고, 리프레시 토큰은 만료되지 않은 상태에서 서버에 액세스 토큰 리프레시 요청을 해봤다. 하지만 이 것도 잘 진행되지 않았다.. 쓰읍…. 후,,, 다시 한 번 디버깅 해보자고..
액세스 토큰이 만료된 경우
1. sharedPreferences에 저장되어 있는 액세스 토큰을 가져온다. 이 액세스 토큰은 만료된 액세스 토큰이다.
2. statistics/my 로 GET 요청을 보낸다. (여기서 인터셉터 로직 발동)
3. 만료된 액세스 토큰을 사용했기 때문에 서버로부터 http 상태코드 401이 떨어진다.
4. sharedPreferences에 저장되어 있는 리프레시 토큰을 가져와 리퀘스트 바디를 만든다.
5. 리프레시 리퀘스트를 만들어 서버에 요청한다.
6. 서버에서 http 상태코드 401이 떨어진다.
7. 응답을 우리가 만든 FailureDto로 변환하면 토큰이 만료되었습니다. 라는 메시지를 서버로부터 반환받는다.
문제 발생
어제 잘 고쳐놔서 서버로 액세스 토큰을 리프레시 하는 POST요청은 서버로 잘 도착한다.
하지만 통계를 가져오는 GET요청이든 액세스 토큰을 리프레시 하는 POST요청이든 http 상태코드가 401이 떨어진다.
무엇이 문제일까? 다시 한 번 백엔드와 함께 이야기를 나누어봤고, 안드로이드에서 자동로그인을 함께 디버깅하면서 두 가지의 원인을 발견했다.
1️⃣ refreshToken 값 문제
우리 서버가 refreshToken을 받을 때 “Bearer: “ 가 붙지 않아야 한다. 그런데 클라이언트에서는 “Bearer: “를 붙여서 보내줬기 때문에 서버에서 올바른 리프레시 토큰이 아니라고 판단해서 에러를 내보낸 것이다.
[before]
[after]
그래서 이렇게 "Bearer: " 를 붙이지 않도록 수정해줬다.
2️⃣ Reponse 재오픈
위와 같은 에러가 발생했다. 처음보는 에러였는데, 이 에러 메시지는 이전 호출을 완료하지 않고 연쇄적으로 호출하려고 할 때 발생하는 에러라고 한다.
[before]
[after]
response.close() 혹은 response.closeQuietly() 를 이용하여 이전 요청을 완료할 수 있다. 그리고 여기를 참고하면 close() 메서드에서 예외가 발생할 수 있으므로 closeQuietly()를 사용하는 것이 더 좋다고 한다.
그리고 실제 코드를 보면 closeQuietly()는 try catch를 통해 에러처리를 해놓은 것을 볼 수 있다.
closeQuietly() 는 Closeable의 확장함수로 구현이 되어있는데 Response를 보면 Closeable을 구현하고 있기 때문에 closeQuietly() 메서드를 호출할 수 있는 것이다.
✚ 추가
디버깅을 하다가 신기한 것을 발견했다. 어쩔 때는 response.toString()의 결과를 확인할 수 있고, 어쩔 때는 IllegalStateException이 발생했다. 처음에는 언제 이런 상황이 생기는지 몰랐지만, 여러번의 디버깅 끝에 어떤 상황에 다음과 같은 상황이 생기는지 알아냈다.
대단한 이유는 아니고, response를 이미 한 번 읽었기 때문에 closed되고, 다시 읽을 수 없는 것이다. 이를 해결하기 위해 Square의 깃허브로 들어가보면 다음과 같은 이슈를 확인할 수 있다.
여기서는 해결책으로 굉장히 간단한 방법을 제시한다.
response의 body는 한 번만 호출되어야 한다.
근데 왜 한 번만 호출되어야 하는 것일까?
response는 거대할 수 있기 때문에 OkHttp는 이것을 메모리에 저장하지 않는다. 필요할 때 네트워크의 스트림으로부터 읽어올 뿐이다.
string() 을 이용하여 response body를 읽어올 때 OkHttp는 문자열을 참조하는 것이 아니라 response body를 다운받는 것이기 때문에 새로운 요청 없이 두 번 호출할 수 없다고 한다.
느낀점
이번에 문제를 해결하면서 적지 않은 것들을 느꼈다.
첫째로 Firebase Crashlytics가 상당히 유용하다.
실제 사용자가 앱을 사용하다 비정상 종료가 되었는지 나는 알 수 없다. 하지만 주기적으로 Crashlytics를 통해 확인한다면 비정상 종료되는 이유를 추측하여 해결한 뒤 다시 앱을 배포할 수 있겠다고 생각했다. 상당히 유용한 친구였다.
둘째로 협업 과정에서 커뮤니케이션이 충분하지 않았다.
다른 팀원이 작성한 로그인 로직에 대해 깊이 알고 있지 못했다. 인터셉터에 대한 개념과 지식을 쌓고 로직을 이해하는데 시간이 필요해서 문제를 해결하는데 더 오랜 시간이 필요했다. 만약 내가 신경을 조금 더 쓰고 시간을 더 투자했었더라면 어땟을까 생각했다.
또, local.properties로 관리하는 값이 달랐다. 안드로이드 팀원 고작 3명이다. 공동으로 관리해야 하는 값들을 서로 다르게 저장하고 있었으니 소통이 부족했다라고밖에 생각할 수 없다. 정말 많이 반성했다.
셋째로 아쉬웠다. 그렇지만 흥미로웠다.
더 딥한 문제 해결이었으면 좋았겠다는 아쉬움이 들었다. 하지만 꼭 깊은 문제를 해결해야만 대단한 것은 아니니까. 적지 않은 시간을 투자하여 문제를 찾았고, 해결했으니 다행이라는 생각이 들었다. 동시에 새로운 개념들에 대해 더 깊이 알아갈 수 있는 시간이었기 때문에 흥미로웠다.
액세스 토큰이 만료되었을 때 테스트를 해보고 싶었는데.. 액세스 토큰이 만료될 때까지 앱을 실행하지 않고 멍 때리며 기다리는 것은 정말 비효율적인 방법이다. 이러한 로그인 관련 로직은 테스트를 어떻게 할 수 있는 것일까? 조금 더 고민해봐야겠다.
참고
