-
로그가 간헐적으로 중복 노출되는 이슈실무에서 알게된 내용 2022. 6. 29. 08:56
작업했었던 프로젝트를 배포하고 모니터링을 하는데, 로그가 간헐적으로 중복 노출되는 이슈가 있었다.
사실 처음에는 다른 로그들은 한 번씩만 남고 있는 상태였기 때문에 로그가 중복 노출될 거라는 생각은 전혀 하지 못했다. 따라서, 당연히 휴먼에러로 인해 애플리케이션 레벨에서 의도치 않게 작업이 여러 번 수행되고 있을 거라는 생각을 가장 먼저 했다.
하지만, 아무리 생각해봐도 애플리케이션 레벨의 이슈는 아닌 것 같았다. 왜냐하면, 간헐적으로 중복 노출됐던 로그 중 하나가 아래 코드 부분이었는데 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(단순 텍스트 또는 정규 표현식)을 사용하여 쿼리를 작성할 수 있다.
'실무에서 알게된 내용' 카테고리의 다른 글
좌충우돌 Coroutine 적용기 (0) 2022.07.01 모듈간 의존성 개선 및 정리 작업 (0) 2022.06.30 ClientAbortException은 언제 발생하는가? (0) 2022.06.23 운영 배포 전에 챙겼던 Kafka Producer Client 포인트들 (0) 2022.06.22 컬럼 값을 Collection으로 받을 때 Querydsl 이슈 (0) 2022.06.21 - 중복 노출된 로그가 실제로 서버 로그 파일에 2개가 남아서 노출되는 건 아닌지 확인