log weekly june 2024

2024년 6월 26일 수요일

Today I Learned

날짜

2024년 6월 26일 수요일

내용

JWT 토큰

기존 알파플러스 서비스에서는 클라이언트가 보내는 요청을 따로 검증하지 않는다. 접근 자체가 일반적으로 쇼피파이에 로그인 한 후에 이루어 지는 이유도 있을 것이고, 애초에 로그인이 되면 로컬 세션에 jwt로 생성한 토큰이 저장되기 때문이다. 이 토큰이 없으면 프론트 쪽에서 어드민 페이지에서 내보낸다. 사실 직접 URL을 입력해서 접속할 수 있기 때문에 첫번째 이유는 무력화 될 수 있겠으나, 우리만 그렇고 대부분의 유저들은 쇼피파이 어드민을 통해 접근할 것이다.

이번에 새로 제작하는 서비스는 access token 과 refresh token 개념을 가져왔다. 예전 취직전에 이커머스 사이트 만들 때 한번 만들어 보긴 했는데..

  1. 로그인으로 사이트 접근 권한을 제어하고
  2. 토큰으로 권한이 있는 올바른 유저가 요청했는지를 확인한다.

우선 유저가 로그인 하는 시점에 액세스토큰과 리프레쉬 토큰을 만든다. 액세스 토큰은 비교적 짧은(30분 ~ 1시간) 만료시간을 가진 토큰이고 리프레쉬 토큰은 긴(30일 ~ 1년) 만료 기간을 가진다. 두 토큰을 로그인한 유저에게 반환하고, 리프레쉬 토큰믄 DB에 저장한다.

유저는 모든 요청에 액세스 토큰을 보내야 하고, 서버는 요청때 마다 이 토큰이 제대로 된 토큰인지 검증한다. 토큰이 없거나, 토큰의 만료시간이 지나거나, 토큰이 제대로 된게 아니라면 요청은 401로 반환한다. 이 중 액세스 토큰의 만료시간이 지났다는 응답을 받게 되면, 클라이언트는 리프레쉬 토큰을 포함한 액세스 토큰 재발급 요청을 보내야 한다. 서버는 리프레쉬 토큰을 검증하고(제대로 된 토큰인지, 데이터베이스에 들어있는지) 액세스 토큰을 재발급 해준다. 만약 리프레쉬 토큰의 만료기간이 지났다면? 로그인 한지 1년이 됐다는 소리니 로그아웃 시켜준다.

굳이 두 토큰을 이용하는 이유는, 혹시나 액세스 토큰이 털려도 피해를 최소화 하기 위함이다. 토큰의 payload에 어떤값들을 더 추가할지는 좀 더 고민해볼 예정.

네트워크 오류

최근 5일간 계속 0 Unknown Error가 발생해왔다. 진짜 골떄리는건 프론트에서만 에러가 뜨고 서버에서는 그 요청이 200으로 처리된다는 사실이다. 클라이언트에선 요청이 왔고, 서버에선 요청을 제대로 받아 올바른 데이터를 반환했으나 프론트는 그 응답을 0 Unknown error로 받고 있다는 뜻이다.

우선 상황을 정리했다.

발생시점

  1. 2024년 6월 20일 오전 8시(최초)
  2. 2024년 6월 21일 오전 11시
  3. 2024년 6월 22일 오후 11시
  4. 2024년 6월 24일 오전 8시
  5. 2024년 6월 25일 오전 8시

최근 실서버 변경 내역

최초로 발생한 시점을 기준으로 가장 마지막에 반영된 실서버 변경 내역은 두 가지였다.

  1. 샵 액세스 코드로 값을 찾지 못했을 떄, 모든 필드가 None인 가짜 객체가 반환되어 404 에러가 뜨지 않고 500이 떴었다. 이 부분에 대한 수정
  2. 리스트 디자이너 위젯에서 할인 전 가격 설정을 끄지 않고 0으로 설정하는 영국 신사분을 위해, 에러가 발생하지 않도록 예외처리

오류 내용

20일

  1. 위치 https://a-review.co/write/detail/fb28fe2f/1/5/1
    1. 메시지 Http failure response for https://shop.a-review.co/orders/line-items: 0 Unknown Error
    2. 횟수: 5회
  2. 위치 https://a-review.co/write/detail/ce1461d1/1/5/1
    1. 메시지 Http failure response for https://shop.a-review.co/options/types: 0 Unknown Error
    2. 횟수: 5회

    ### 관련 데이터

    hashcode shop_id product_platform_id customer_id order_id
    fb28fe2f 1402 6702824751179 306258 590803
    ce1461d1 1402 6701850886219 306258 590803

22일

오류내용

  1. 위치 https://a-review.co/write/login/AA5aaa53?&email=ramendraverma@ntpc.co.in&phone=None
    1. 메시지 : Unhandled promise rejection: Object Not Found Matching Id:9, MethodName: update, ParamCount:4
    2. 횟수 : 41회
  2. 위치 https://a-review.co/write/detail/8d99d776/1/3/1
    1. 메시지 Http failure response for https://shop.a-review.co/orders/line-item/8d99d776
  3. 위치 https://a-review.co/write/detail/a94013fb/1/3/1
    1. 메시지 Http failure response for https://shop.a-review.co/orders/line-item/a94013fb
  4. 위치 https://a-review.co/write/detail/a94013fb/1/5/1
    1. 메시지 Http failure response for https://shop.a-review.co/orders/line-item/a94013fb
  5. 8d99d776(위와 같음)
  6. ae3404d0

관련 데이터

hashcode shop_id product_platform_id customer_id order_id
8d99d776 1822 7881126805658 310138 594900
a94013fb 1822 7505918984346 310138 594900
ae3404d0 1822 7490868838554 310138 594900

24일

오류내용

  1. 645b4f2f 2회
  2. c4151bad 1회
  3. 14ab3e1f 6회
  4. https://a-review.co/write/login/AAb304fb?email=rchou@kent.edu&phone=None
    1. Http failure response for https://review.a-review.co/review-benefit/ 0 Unknow Error
  5. 4e90fe02 1회

관련 데이터

hashcode shop_id product_platform_id customer_id order_id
645b4f2f 1167 6167443996848 310673 597145
c4151bad 1167 6167447634096 310673 597145
14ab3e1f 1167 6167447634096 310673 597149
4e90fe02 1167 6167443996848 310673 597149

25일

오류 내용

  1. 7e21c975 6회 + 3회
  2. 6314229f 9회

관련 데이터

hashcode shop_id product_platform_id customer_id order_id
7e21c975 1402 6702824751179 306258 598601
6314229f 1402 6701850886219 306258 598601

이때 데이터를 종합해서 다음과 같은 추론을 내렸다.

  1. 그날 오류는 스토어 중 딱 1곳에서만 발생한다.
    1. 발생하는 스토어는 무작위로 보인다.
  2. 하루에 한번, 특정 주문의 리뷰 작성이 고장난다.
  3. 22일을 제외하면 고객이 주문한 모든 라인아이템에서 발생한다.
    1. 라인아이템이라 하면 주문 내역에 작성된 상품이다.
    2. 예를 들어 A 상품 5개, B 상품 3개, C 상품 1개를 주문하면 라인아이템 데이터는 3개(A,B,C)가 생성된다.
    3. 어떤 라인아이템에서 오류가 발생했다면, 그 오더 내에 있는 모든 라인아이템에서 에러가 발생한다는 의미
    4. 22일에 594900번 주문의 라인아이템은 5개였으나 오류는 3곳에서만 발생했다.

우선 직접 같은 페이지로 들어가 문제를 재현할 수 있는지 확인했다. write/detail은 고객에게 리뷰를 작성해달라고 전송하는 이메일 내에서 접근할 수 있는 리뷰작성 페이지다. 직접 테스트 해봤을 땐 아무런 문제가 없었고, 오류가 뜬 저 URL로 가봐도 잘 작동했다. 나도 같은 에러를 볼 순 없었다.

페이지에서 발생하는 문제가 아니라면, 데이터 상으로 잘못된 점이 있을 거라고 판단했다. 모든 오류는 1개의 주문 내에 있는 라인아이템에서 발생하므로 주문 데이터를 위주로 뒤져봤으나.. 전혀 다른점을 찾지 못했다.

사실 서버 쪽 코드나 데이터가 잘못되었으면 진작 다른 오류들처럼 그 내역이 떴을 것이다. 최소한 500 에러는 나타났어야 했고, 서버쪽에서도 알람이 왔어야 했는데 그러지 않았다. 0 Unknown error에 대해 찾아보니 네트워크 문제로 나타나는 메시지라는 이야기가 많았고 100중 95는 CORS 에러 떄문이라고 한다. 그런데 하루 중 비슷한 시간대에, 1개의 주문에서만 CORS 에러가 발생한다는 건 도저히 납득이 안됐다.

이것저것 뒤져보던 중 다음을 발견했다.

transaction latency.png

24일 발생한 에러의 레이턴시 분포도이다. 클라이언트에서 요청이 출발해서 서버에 도달할 때 까지 걸리는 시간 + 서버가 보낸 응답이 클라이언트에게 돌아오는데 걸리는 시간을 합친 시간이다. 거의 다 1초(1000ms)가 넘어갔으며 2초가 넘어간 요청들도 많이 보인다. 뭔가, 네트워크에 문제가 있었다는 생각이 들었다. 반면 이떄 서버의 처리율은 정상적이였다. 두 가지 가설을 세웠다.

  1. 저 시간대에 프론트의 요청이 많았다.

    매일은 아니지만 오전 8시에 에러가 몰려있다. 저 시간대에 요청이 너무 많아서 발생한 문제일 수 있다고 생각했다. 우리의 주 고객층은 미국인데, 한국시간으로 오전 8시면 미국은 오후 4시쯤이다. 아예 사용이 없을 시간대는 아니지만 가장 많을 시기도 아닌 듯해서 사용자가 많은건 원인이 아닐거라고 생각했다.

    매일 오전 7시 부터 크론 작업으로 데이터를 종합하여 스프레드시트에 데이터를 추가하는데 이게 원인일 수 있다고 생각했다. 서비스의 사용 실태를 확인하는 작업이라 확인하는 데이터가 많다. “그렇다면 서버의 처리 속도가 느려져야 하지 않나?” 라는 생각이 들었는데, 우리 서비스는 MSA라 여러 데이터를 종합하기 위해 서버간 통신도 분명 영향이 있을거라는 생각이 들었다.

    따라서 시간대가 중요하지 않은 크론 작업을 분산시켰다.

  2. 서버의 네트워크 처리능력이 떨어진다.

    문제가 된 시점에 네트워크 사용량이 늘어났고, 서버가 문제를 일으킬만한 역치가 마침 그 수준이라면 그럴 수도 있겠다고 생각했다. 특히 elastic apm 상으로, 프론트 서버의 평균 레이턴시가 2000~ 6000ms 에 머물러있는 걸 보면.. 심지어 오류가 안나고 있을 때 조차! 서버는 미국에 있고, 그렇다면 한국에 있는 우리가 더 체감해야 하는데 실서버에 접속해보면 그러지 않는 걸 보면 문제가 있는 건가 싶기도 하고… 비용 문제도 있으니 우선 후순위로 두었다.

현재까지 내린 결론은

  1. 어떤 이유가 되었든 네트워크 요청이 상당히 몰렸다.
  2. 네트워크 상 지연 큐의 수용량을 넘어선 요청이 몰렸다.
  3. 데이터 손실이 발생했다.
  4. 이로 인해 서버에서 제대로 된 응답을 보냈으나 클라이언트는 데이터 손실로 받지 못한다.

인데 맞을까..?

우선 오늘 아침은 같은 오류가 안떴으나, 계속 유의해야겠다.

회고

영국 신사분이 자꾸 에러뜨는데도 열심히 써주신다. 잉글랜드 화이팅 근데 왜 자꾸 할인 전 가격을 0원으로 설정하시는건데요..

CATALOG
    weekly