[Error #1] Server - update 가 랜덤하게 성공하는 경우

---

매우 짧은 순간에 여러 개의 update API 요청이 진행되는 경우 순서를 보장하지 못한다.
서버 외 클라이언트 로직도 살피고 로그 분석 시 API 호출 시간 간격도 살펴보자!

---

 

▶ 발생한 오류

플레이어에서 다른 목차로 이동 후 콘텐츠를 목록을 띄울 시, 사용자의 재생률이 update 되지 않는 경우가 발생한다. (=update 가 랜덤하게 성공한다)

대충 이런 상황

(※ 참고 1 : 재생률은 실제로 유저가 재생한 소요 시간으로 책정되는 것이 아닌, 유저가 마지막으로 재생한 위치가 콘텐츠 전체 길이에서 몇 퍼센트 지점인지를 나타낸다.)

(※ 참고 2 : 이번에 작업한 부분과 전혀 관계없는 부분이다. 이번에 작업한 부분은 재생 플레이어에서 콘텐츠 목록을 띄우는 기능으로, QA 에서 해당 목록에서 사용자의 재생률이 즉각 반영되는지 테스트를 진행 -> 해당 이슈를 인지하게 된 상황이다. = 기존부터 존재했던 이슈라는 뜻.)

 

▶ 발생한 이유

• AOS 및 iOS 개발자님께 재생 관련 로직을 물어봤다. (언제 어떻게 어떤 API 를 호출하여 재생 정보를 서버로 보내는지 물어봄.)
• 재생 플레이어가 시작(START), 일시정지(PAUSE), 종료(END) 될 때 or 재생 중 30초가 흐를 때마다 또는 사용자 동작으로 재생 위치가 변경되는 경우 POST ... progress api 를 호출하여 재생 정보를 보낸다.
• 재생 플레이어에서 목차 리스트를 띄우고 다른 목차로 이동하는 경우, 재생 중이던 목차가 종료되었다는 정보(END) 와 이동한 목차가 시작되었다는 정보(START) 를 0.2-0.3초 간격으로 거의 동시에 전송하고 있었다.
• POST ... progress api 의 경우 로직상 END 정보를 받을 때가 START 정보를 받을 때보다 시간이 더 소요된다. (정확한 시간은 아직 측정 안 해봤지만 END 정보를 받을 때 추가적인 로직이 더 붙음.)
• API 호출 자체는 END -> START 순으로 진행되지만 / 0.2초로 그 간격이 매우 짧아 / API 로직을 거치며 START -> END 순으로 DB Update 가 이뤄지는 경우가 발생한다. (체감 80% 정도의 빈도)
• 이로 인해 START 정보가 END 정보로 덮어 씌워지면서 재생률이 Update 되지 않는 것처럼 인지된다.
• 다만 END 로직은 콘텐츠가 무엇이냐에 따라 소요 시간이 달라질 수 있기 때문에 / 목차 이동 시 랜덤하게 Update 되는 것처럼 보여진다.

 

▶ 해결점에 도달한 방법

• 관련 QA 티켓을 받음. 로그 분석을 위해 해당 현상이 발생한 테스트 계정을 받음.
• DB 를 보니 재생률이 0.259...% 로 0% 로 표현되는 것이 맞음.
• 다시 QA 분과 대화 -> 이와 별개로 해당 현상이 빈번하게 재현됨을 발견.
• 일단 AOS/iOS 개발자에게 재생 관련 로직이 어떻게 되어 있는지 질문. (언제 어떻게 어떤 API 를 호출하여 재생 정보를 서버로 보내는지에 대해 질문)
• 직접 스테이징 서버에 배포된 어플을 통해 문제 상황 재현 => 패턴 발견 => 패턴 검증 => 재현 시나리오 작성.

패턴 발견 => 재현 시나리오 작성

• 재현 시나리오와 클라이언트 재생 관련 로직을 엮어 문제 원인 추론.
• 추론한 내용 (목차 이동 시 START 정보를 클라에서 안보내는 것 같다) 을 바탕으로 AOS/iOS 개발자 분들과 소통.
• 확인해보니 정보 제대로 보내고 있음 -> ELK 로그 확인해보니 제대로 호출되었음 -> 근데 왜 DB 에 Update 가 안될 때가 있지?????? (고통)
• ELK 로그를 최근 순으로 타고 올라가며 리딩 -> END 정보를 보내고 START 정보를 보냄을 발견 -> 아 설마
• 둘 간의 시간 간격을 확인 -> 0.2초 ^ㅁ^ㅠㅠㅠㅠㅠ

• 나름의 해결책 구상 후 AOS/iOS 개발자 분들과 소통 => 모두의 결론 : 우리가 해결할 수 있는 Level 을 넘어섰다.
• 클라 과장님께 질문 - END 를 안보내는 건 불가 - 간격을 늘릴 수는 있다 (해당 문제는 고질적인 문제. 구조적인 문제이다.) => 0.2초 간격에서 1초 간격으로 늘려주심.
• 재생률이 미반영되는 빈도가 줄어들었으나 반영까지 약 2초의 텀 발생. (완전한 해결 X)
• 추가로 백엔드 차장님께 질문 - 간격을 늘려도 완전한 해결은 안 될 것 - 예전부터 있었던 문제로 구조적인 문제 - 이건 지금 당장 해결할 수 있는 문제는 아니다.
• 이 문제는 일단 API 호출 간격을 조정하는 형태로 QA 넘기기로 결정 - QA 님께 해당 상황 공유 

 

▷▷▷ 만약 완전히 해결되려면 어떻게 해야 할까 (생각해보기) ▷▷▷

• 클라에서 ① END -> 그대로 종료 인지, ② END -> 다른 목차 START 인지 분기처리해서 API 호출을 조정할 수는 없을까? (일단 이거는 클라 쪽에서는 안된다고 하긴 함)
• 현재는 user - content 별로 묶어 재생정보를 Update 하는 방식인데, API 가 받은 액션 (START, END...) 정보도 DB 에 저장해서 DB Update 시 저장된 이전 액션 정보가 START 이면 END 정보 Update 스킵하도록 하면 괜찮을까? (완전한 해결책은 못 될 것 같다. 시작하고 종료하는 경우 문제될 수도 있으려나? 생각해보니 네트워크가 끊겨서 재생 정보가 전송 못 되는 경우도 고려해야 한다고 하셨음)
• 음... 재생 정보 받는 API 로직을 뜯어봐서 END 정보를 받을 때 왜 추가 로직이 붙어 소요 시간이 길어지는지 분석해봐야 해결책을 생각해볼 수 있을 것 같다.

 

▶ 원인 분석에 방해가 된 요소

• 이번에 작업한 부분은 재생 쪽과는 관련없는 부분으로, 이로 인해 재생 관련 API 로직은 아예 모르는 상태.
• 기존에 있었던 문제라면 QA 에서 인지하고 있지 않았을까? 티켓이 생성되었다는 건 이번에 새롭게 발생한 문제인건가? 하지만 나는 재생 쪽은 건들인 적인 없는데????? => 혼란
• 위와 같은 이유로 클라에서 재생 부분에서 어떤 API 를 언제 어떻게 호출해 재생 정보를 주는지 모르는 상태.
• 같이 작업하는 클라 분 중 한 분도 들어온지 얼마 안되서 재생 정보를 보낸다는 사실조차 인지하지 못하고 있던 상황. (클라 로직을 서버인 내가 클라 분께 알려주게 된 사건.txt)
• 추가로 QA 진행이 처음이라 스테이징 서버에서 테스트하는 것과 ELK 로그 보는 법에 있어 미숙한 상태.

 

=> 결과적으로 생각해봤을 때 이번에 새롭게 발생한 문제가 아닌 기존에 있었던 문제였음을 인지했다면 차장님께 질문해서 빠르게 원인 분석 했을지도...?? 하지만 새롭게 발생한 문제인지 여부를 알려면 어찌되었든 원인을 어느정도 파악해야 질문이 가능했을 거기 때문에... 신입으로서 자연스럽게 거치는 시행착오였다고 생각한다. ㅎㅎㅠ

▶ 결론

매우 짧은 순간에 여러 개의 update API 요청이 진행되는 경우 순서를 보장하지 못한다.
서버 외 클라이언트 로직도 살피고 로그 분석 시 API 호출 시간 간격도 살펴보자!