문제 상황
•
Slack 채널에서 한 유저분이 ‘cabi서비스만’ 회원가입/로그인이 되지 않는다 제보
BE에러인건 알겠는데.. 뭔 에러세요? 통역점..
•
서버 로그 확인 → invalid_grant에러’만’ 찍혀있다;; 뭣?
→ 주로 api key 설정이나 지정한 redirect-uri가 일치하지 않거나, 로그인 성공 후 oauth 서버로부터 발급받은 코드가 지정된 횟수 이상 사용되었을 때 발생
•
서버로 들어가서 더 많은 로그를 읽어봤지만 다른 에러 메세지는 딱히 보이지 않음..
•
기존 유저들은 모두 로그인에 문제가 없음
원인
•
추정되는 원인
◦
확신이 안섬; 42 api 키나 redirect-uri 문제라면 다른 유저들도 로그인 실패가 떠야함
◦
코드 사용 횟수 문제로 추측
•
실제 원인
◦
42에서 받은 정보 파싱도중 발생한 NullPointerException
▪
최초 시도 시에는 정보 받아오는 것 성공, 하지만 42 profile 파싱 도중 NPE 발생 → 에러 메세지 반환
▪
최초 실패 후, 유저는 모든 브라우저를 닫거나 시크릿창에서 로그인을 재시도한게 아니기 때문에 이전 상태 그대로 로그인 재시도
▪
최초 시도 시에 발급받은 동일한 code를 갖고 42 api에게 access token 발급 재요청 → 님아 이 코드는 이미 쓴건데요 invalid_grant 어쩌고 에러 발생
최종 해결
•
문제 파악 방법
◦
로그인 실패한 유저분 초청석..
◦
빠르게 처리해야함 + 고민해봐도 모르겠어서 로컬 세팅을 실제 서버와 동일하게 갖추고, 진짜 벼락맞아서 42api prod 키가 이분만 벤하나 싶어서 local에서 42api key 부분만 임시로 교체한 후 유저분께 로그인을 부탁드림
◦
NPE(???) 발생, 로그 우다다다
◦
이후 로그인부터는 창 새로 여는거 아니면 동일한 코드로 토큰달라고 떼쓰는거니 당연히 invalid_grant 어쩌고 에러
•
해결방법
◦
JsonNode 파싱 방식 변경, NPE 발생 시 예외 처리
문제의 코드..
private static final int CURSUS_INDEX = 1;
private LocalDateTime determineBlackHoledAt(JsonNode rootNode) {
JsonNode blackHoledAtNode =
rootNode.get("cursus_users").get(CURSUS_INDEX).get("blackholed_at");
if (blackHoledAtNode.isNull() || blackHoledAtNode.isEmpty()) {
return null;
}
return DateUtil.convertStringToDate(blackHoledAtNode.asText());
}
Java
복사
◦
일단. 유저분이 무척이나 특이한 케이스였다. 계정을 새로 발급받게 되어 일반 카뎃과는 달리 cursus_users의 0번 인덱스까지만 값이 존재했다.
▪
42 profile은 과정에 따라 cursus_users 인덱스가 늘어난다.
0 → 피신, 1 → 카뎃~멤버, 이후 더 추가적인 활동을 하면 늘어남
◦
기존 코드는 get(1)을 시도 → null 반환, 이 값에서 get(”blackholed_at”) 시도 -> NPE
바꿔주자..
private static final int CADET_INDEX = 1;
private static final int PISCINE_INDEX = 0;
private LocalDateTime determineBlackHoledAt(JsonNode rootNode) {
JsonNode cursusNode = rootNode.get("cursus_users");
int index = cursusNode.size() > CADET_INDEX ? CADET_INDEX : PISCINE_INDEX;
JsonNode blackHoledAtNode = cursusNode.get(index).get("blackholed_at");
if (blackHoledAtNode.isNull() || blackHoledAtNode.asText().isEmpty()) {
return null;
}
return DateUtil.convertStringToDate(blackHoledAtNode.asText());
}
Java
복사
◦
cursus_user의 size에 따라 인덱스를 지정하고 블랙홀 시점을 가져오는 방식으로 변경.
◦
추가적으로 기존 코드에서 cursus_user에 블랙홀 필드는 있지만 value가 비어있거나, null일 경우를 제대로 구분하지 못하는 케이스도 발견해 값을 text형식으로 값을 변경하고, 비어있는지 판별. 허무하도다.. -완-
추가 조치 - 왜 원인 파악이 늦어졌을까?
•
수정은 빨랐죠? 하지만 도대체 왜 invalid_grant 에러냐고!
public FtProfile getProfileByCode(String code)
throws IOException, ExecutionException, InterruptedException {
OAuth2AccessToken accessToken = ftOAuth20Service.getAccessToken(code);
OAuthRequest oAuthRequest = new OAuthRequest(Verb.GET, ftApiProperties.getUserInfoUri());
ftOAuth20Service.signRequest(accessToken, oAuthRequest);
try {
Response response = ftOAuth20Service.execute(oAuthRequest);
// convert를 수행하며 JsonNode 파싱 시작, 해당 필드가 없을 경우 NPE 위험
return convertJsonStringToProfile(objectMapper.readTree(response.getBody()));
} catch (Exception e) {
if (e instanceof IOException) {
log.error("42 API 서버에서 프로필 정보를 가져오는데 실패했습니다."
+ "code: {}, message: {}", code, e.getMessage());
}
if (e instanceof ExecutionException || e instanceof InterruptedException) {
log.error("42 API 서버에서 프로필 정보를 비동기적으로 가져오는데 실패했습니다."
+ "code: {}, message: {}", code, e.getMessage());
}
// 인터널서버에러로 일단 던지고 있었다에요
throw ExceptionStatus.INTERNAL_SERVER_ERROR.asServiceException();
}
}
Java
복사
•
일단 로컬에서 돌려보니 NPE인건 알겠음. 근데 서버로그에는 왜 invalid_granted로만 뒤덮여 있냐?
원인을 진짜 모르겠어서 서버 로그 한줄씩 보다가 혹시 하고 INTERNAL_SERVER_ERROR 내부 메세지를 로그중에서 검색해보니 한 줄 있었다..
그렇다.. INTERNAL_SERVER_ERROR로 단 한줄의 에러로그를 최초 1회 로그인 시도 시 한 번 던지고, 수많은 invalid_grant 에러로 뒤덮여 저 한줄을 못읽어 너 뭔데.. 어디서 오는데 하면서 근본적인 원인 파악이 많이 늦어졌다
private LocalDateTime determineBlackHoledAt(JsonNode rootNode) {
JsonNode cursusNode = getRequiredNode(rootNode, "cursus_users");
int index = cursusNode.size() > CADET_INDEX ? CADET_INDEX : PISCINE_INDEX;
JsonNode blackHoledAtNode =
getRequiredNode(cursusNode.get(index), "blackholed_at");
if (blackHoledAtNode.isNull() || blackHoledAtNode.asText().isEmpty()) {
return null;
}
return DateUtil.convertStringToDate(blackHoledAtNode.asText());
}
private JsonNode getRequiredNode(JsonNode rootNode, String fieldName) {
JsonNode node = rootNode.path(fieldName);
if (node.isMissingNode()) {
log.error("JsonNode 파싱 중, {} 에 해당하는 필드가 존재하지 않습니다.", fieldName);
throw ExceptionStatus.JSON_PROCESSING_EXCEPTION.asServiceException();
}
return node;
}
Java
복사
다음과 같이 찾으려는 필드가 없을 경우 어떤 필드인지에 대해 제대로 로그를 찍고, FE에게 에러 반환도 좀 더 구체적으로 해주자.
•
모바일 환경으로에서 한글이 저렇게 깨져보이는 오류도 당황시키는데 한 몫.. ㅎ
ExceptionController를 수정해 contentType에서 인코딩 방식을 지정해주면 String이 자동으로 UTF-8을 적용해 반환한다
return ResponseEntity
.status(status)
.contentType(MediaType.APPLICATION_JSON_UTF8) <- 얘 추가
.headers(headers)
.body(responseBody);
Java
복사
해결 자체는 난이도가 낮아 대처를 빠르게 했는데, NullPointerException을 어떤 강도가 와서 invalid_grant 에러로 바꾸시나요가 너무 궁금했다.
기존에 ExceptionContoller나 메세지 부분들을 잘 파악해뒀더라면 재로그인 시 발생한 코드 에러에 매몰되지 않고 원인을 빨리 파악했을 것 같은데.. 아쉽지만 이번에 제대로 봤으니 에러를 더 잘 읽고, 잘 던지고, 로그도 잘 쓰는 수밖에~
핫픽스 외의 코드들은 추가적인 테스트를 거친 후 반영하도록 하자!