로그가 간헐적으로 중복 노출되는 이슈

작업했었던 프로젝트를 배포하고 모니터링을 하는데, 로그가 간헐적으로 중복 노출되는 이슈가 있었다.

 

사실 처음에는 다른 로그들은 한 번씩만 남고 있는 상태였기 때문에 로그가 중복 노출될 거라는 생각은 전혀 하지 못했다. 따라서, 당연히 휴먼에러로 인해 애플리케이션 레벨에서 의도치 않게 작업이 여러 번 수행되고 있을 거라는 생각을 가장 먼저 했다.

 

하지만, 아무리 생각해봐도 애플리케이션 레벨의 이슈는 아닌 것 같았다. 왜냐하면, 간헐적으로 중복 노출됐던 로그 중 하나가 아래 코드 부분이었는데 DB로부터 데이터를 읽어와서 publish 메소드를 호출하는데, 여기서 간헐적으로 해당 메소드가 여러 번 호출되는 건 로직상 불가능하다고 생각했기 때문이다.

또한, 이 시점에 중복 노출됐던 로그 정보를 자세히 확인해 봤는데 중복 노출됐던 로그 모두 로그가 남은 시간(ts, tsNs 시간) 정보까지 완벽히 일치했다. (아래 이미지 참조) 백번 양보해서 설령 애플리케이션 레벨에서 메소드가 여러 번 호출됐다고 하더라도 로그가 남은 시간까지 완벽히 일치하는 건 불가능하다고 생각했다.

이때부터 로그가 간헐적으로 중복 노출되는 게 아닐까란 의심을 하게 됐고 이 부분을 담당 팀에게 먼저 문의 요청드리고 확인하기 시작했다.

 

내가 확인한 사항

• 중복 노출된 로그가 실제로 서버 로그 파일에 2개가 남아서 노출되는 건 아닌지 확인
  • 374 밀리초 시간까지 일치하는 로그는 1개뿐이었음
  • 참고로, 143 밀리초 시간을 가진 로그도 1개 뿐이었지만 그라파나에서 중복 노출되고 있었음 
  • 이를 통해 애플리케이션 이슈는 아니라는 것 확인 

 

이를 통해 해당 이슈의 원인이 둘 중 하나라고 생각했다.

• 1. 로그를 조회하는 LogQL 쿼리가 내 예상과 다르게 동작하는 부분이 있다. (정답)
• 2. 로그 수집기에서 간헐적으로 동일 로그를 두 번 수집하고 있다. (but. 다른 팀에서는 문의가 없는 상황, 가능성 희박)

 

여기까지 이슈 트래킹을 하고 있을 때쯤 타팀 시니어 개발자 한 분께서 이슈 원인을 찾아주셨다.

이슈 원인은 LogQL 쿼리에 있는 정규식 때문이고 이로 인해 해당하는 로그들을 그룹핑하는 과정에서 동일 로그가 중복 노출될 수 있었던 것이었다.

 

해결

| message=~"(?s).*.*"   ->   | message=~"((?s).*.*)"

 

용어 정리

LogQL은 loki에서 쿼리를 조회하기 위한 query language로 log stream selector와 적절한 filter expression(단순 텍스트 또는 정규 표현식)을 사용하여 쿼리를 작성할 수 있다.