redis cache

2024년 8월 27일 화요일

Today I Learned

날짜

2024년 8월 27일 화요일

내용

Redis 캐시 대소동

오늘 새벽, 똑같은 오류가 6만번이나 발생했다.. 기능에는 이상이 없었으나 너무 놀랄만한 수치라 후딱 확인해봤다. 상품과 관련된 리뷰나 평점 데이터를 쇼피파이 메타필드에 업로드 하는 함수에서 발생했다. 오류 메시지는 떴으나, 정확히 어떤 오류인지 이해가 잘안됐다. 오류 상황들을 살펴보니 공통적으로 비활성화 된 스토어의 상품들이었다.

몇가지 테스트 해보니 쇼피파이에서 비활성화된 스토어의 메타필드에는 접근 자체가 안되었고 거기서 발생한 오류였다. 이 함수는 진작에 매일매일 실행되는 애인데 왜 하필 오늘 아침에만 문제가 됐는가? 어제 내가 수정한 부분 떄문이었다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
# 기존 코드
# shopify GraphQL의 결과와 상관없이 종료된다. 설령 반환 값이 비정상적이더라도..
with shopify.Session.temp(
        shop.platform_shop_url, config.API_VERSION, shop.access_token
    ):
        result = json.loads(shopify.GraphQL().execute(query=query, variables=variables))
        return result
        
# 변경된 코드
# 실패시 3회 반복하는 코드를 추가
# 요청 중 예외 발생시 elastic apm으로 감지하도록 추가
max_retries = 3
for attempt in range(max_retries):
    try:
        with shopify.Session.temp(
            shop.platform_shop_url, config.API_VERSION, shop.access_token
        ):
            result = json.loads(shopify.GraphQL().execute(query=query, variables=variables))
            return result
    except Exception as e:
        if attempt < max_retries - 1:
            time.sleep(2 ** attempt)  # 지수 백오프
            continue
        else:
            apm.capture_exception(e)
            return

쇼피파이쪽에서 API에 변화가 있다고 공지가 뜬 것 + 그저께 쇼피파이 통신이 불안정해서 발생했던 몇 가지 오류들로 인해 추가한 코드였는데.. 그동안은 저 요청이 잘못되고 있었으나 그냥 조용히 넘어갔었고 이제야 발견된 것이다. 무려 60977번..

문제를 정리하면 다음과 같다.

  1. 알파플러스는 MSA로 설계하여 샵서버와 리뷰서버가 나뉘어져 있고 데이터베이스도 별개다.
  2. 리뷰서버에서 샵 정보가 필요할 때가 잦다.
  3. 매번 서버간 요청으로 처리하기 보단 Redis Cache 를 이용해 기본적으로 자주쓰이는 샵정보는 저장된다.
  4. 샵이 삭제되면 캐시도 삭제되고 샵 정보가 변경되면 변경된 내용대로 새로운 캐시가 추가된다.

4번으로 인해 야기된 두 가지 문제는

  1. 샵이 삭제되지 않고 “비활성화”되면 이는 반영되지 않는다. 따라서 데이터상으론 정상적인 샵이나, 실제 쇼피파이쪽에선 비활성화되어 있어 메타필드 등에 접근할 수 없다.
  2. 샵 정보가 변경되면 기존 캐시를 삭제하지 않은 채 새로운 데이터가 추가된다. 이로 인해 특정 샵은 두 개의 캐시를 가진다.

정도였다. 예를 들어, 도메인 주소를 바꾼 스토어 는 캐시가 2개가 발견됐고, 캐시를 가져오는 경우 이 케이스가 처리되지 않아 때로는 전혀 엉뚱한 예전 캐시를 가져와서 문제가 발생하기도 했다. 위 6만번의 오류 중 거의 대다수는 비활성화된 샵의 상품 정보를 업데이트하기 위해 메타필드에 접근하다가 발생한 문제였다. 비활성화된 샵에 접근하면 {'errors' : 'Not Available'} 이 뜬다. 일부 경우엔 진작에 삭제된 샵이 캐시에 남아있는 경우도 있었다.

따라서 모든 샵의 상태를 조회하여 비활성화일 경우, Redis 캐시에서 삭제하도록 로직을 추가했다. 모든 샵을 탐색하는 로직에서 비활성화된 스토어들은 포함되지 않도록 했다. 뿐만 아니라 모든 캐시를 다 조회해서 정상적인 데이터로 바꿔줬다.

캐시의 키 값은 문자열로 ‘shop:{shop_id}:{shop_access_code}:{shop_platform_url}:{shop_url}:{shop_platform_id}’ 의 꼴이다. 이 키의 값이 샵 데이터와 샵의 결제 상태 json이 된다. 예를 들어 shop_url(스토어의 도메인)이 바뀐 경우

기존 캐시의 키

shop:256:AA236df:js-test5.myshopify.com:js-test.myshopify.com:3563535

데이터 변경 후 생성 된 캐시의 키

shop:256:AA236df:js-test5.myshopify.com:www.js-test5.com:3563535

이렇게 키가 다른 두 캐시를 가진다. 검색을 “키를 모두 조회해서 그중 “shop:256” 으로 시작하는 애를 찾아” 라고 처리하면 저 위의 두개 모두 잡힌다. 그래서 지우도록 로직을 추가해준 것이다.

한가지 골머리 아팠던 부분은, 캐시의 키를 가져와서 비교하는 부분이었다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
# Redis에서 조회한 키
print(cache_key)
// b'shop:256:AA236df:js-test5.myshopify.com:www.js-test5.com:3563535'

# DB에서 가져온 정보로 만든 키
my_new_key = f"shop:{shop.id}:{shop.access_code}:{shop.shop_platform_url}:{shop_url}:{shop.shop_platform_id}"
my_new_key_with_b = f"b'{my_new_key}'"

print(my_new_key)
// shop:256:AA236df:js-test5.myshopify.com:www.js-test5.com:3563535

print(my_new_key_with_b)
// b'shop:256:AA236df:js-test5.myshopify.com:www.js-test5.com:3563535'

print(get_cache == my_new_key)
// False

print(get_cache == my_new_key_with_b)
// False

가져온 캐시 키를 출력해보니 저렇게 앞에 b가 붙길래, 나도 붙여서 비교했는데도 다르다고 나온다. 도대체 뭐가 다르다는건가 싶어 한글자씩 비교해봤더니

1
2
3
4
5
6
7
8
for i in range(min(len(cache_key), len(my_new_key_with_b))):
	if cache_key[i] != my_new_key[i]:
		print(f"diff {cache_key[i]} with {my_new_key_with_b[i]}")

// diff 115 with b
// diff 104 with '
// diff 111 with s
... 

이렇게 된다. 갑자기 웬 숫자여… 하고 헤메다 저 값이 각 글자의 아스키코드인걸 알게 됐다. Redis에서 가져온 키가 string이 아니라 bytes라 그런거였다.. 바꿔주니 깔쌈하게 해결됐다. 문장 앞에 b는 바이트란 의미였을 줄이야..

1
2
3
4
5
6
7
decoded_cache_key = cache_key.decode('utf-8')

print(cache_key == my_new_key)
// False

print(decoded_cache_key == my_new_key)
// True

회고

결국 하루종일 캐시만 건드렸다. 사실 이 부분은 건드린적이 없어서 잘 몰라 무서웠는데 이참에 제대로 공부해버렸다. 허허..