안 온 것과 일이 없었던 것은 다르다

한 줄 요약

로그가 비어 있을 때 "안 왔다" 와 "일이 없었다" 를 가르는 것은 시각이 아니라 발신 쪽이 붙인 번호다. 번호가 없으면 유실은 영원히 증명되지 않고, 번호가 있어도 재시작 앞에서는 거짓말을 한다.

왜 이게 필요했나

수집기에 쌓인 로그를 보고 "이 5분 동안 요청이 없었다" 고 말하는 순간, 우리는 증명할 수 없는 것을 말한 것이다. 요청이 없었을 수도 있고, 요청은 있었는데 그 줄이 오다가 사라졌을 수도 있다. 이 둘은 결론이 정반대인데 파일만 봐서는 구별되지 않는다.

[RFC 5424](https://www.rfc-editor.org/rfc/rfc5424.html)는 8.5절에서 이것을 아주 분명히 적어 두었다. syslog 프로토콜에는 전달을 보장하는 장치가 없고 하부 전송(UDP 같은)도 불안정해서 일부 메시지는 그냥 사라질 수 있다. 그리고 같은 절이 더 불편한 이야기를 덧붙인다 — 신뢰 전달이 늘 바람직한 것도 아니다. 수신자가 더 받을 수 없을 때 발신자가 막혀야 하는데, 유닉스에서 syslogd 는 높은 우선순위의 시스템 프로세스라 그것이 막히면 시스템 전체가 멈춘다. 그래서 현실적인 구현은 막히는 대신 의도적으로 버리되 버렸다는 사실을 알린다. 아무 표시 없이 사라지는 것보다 그 편이 낫다는 것이다.

크기도 이유가 된다. 같은 문서의 6.1절은 전송 수신자가 최소 480 옥텟만 지원하면 되고 2048 옥텟을 넘는 메시지는 잘라도 되고 버려도 된다고 적는다. 그래서 8.3절은 중요한 정보를 메시지 앞쪽에 두라고 권한다. 뒤는 잘려 나갈 수 있기 때문이다.

어떻게 동작하나

유실을 세는 유일한 방법은 발신 쪽의 단조 증가 번호다. 보낸 쪽이 seq 를 붙이고 어디까지 보냈는지 주기적으로 알려 주면, 받은 번호의 집합과 보낸 범위를 빼는 것만으로 무엇이 빠졌는지 나온다. 구간으로 묶어 보면 더 유용하다 — 흩어진 한 건씩의 손실과 50건이 한 덩어리로 빠진 것은 원인이 다르다.

그런데 번호는 재시작에서 되돌아간다. 프로세스가 다시 뜨면 seq 는 다시 1부터다. 그래서 번호만으로 같은 줄을 판정하면 두 가지가 한꺼번에 무너진다. 재시작 전후의 같은 번호가 중복으로 보이고, 재시작 뒤에 빠진 번호는 재시작 전의 기록에 가려 유실이 아닌 것으로 보인다. 해법은 하나다 — 번호에 부팅 식별자를 함께 묶는다. systemd 저널이 _BOOT_ID 를 남기는 이유이기도 하다.

같은 줄이 두 번 오는 것은 정상이다. 응답을 못 받은 발신자가 다시 보내면 수신자는 같은 줄을 두 번 받는다(at-least-once). 이때 필요한 것은 "무엇을 같은 줄로 볼 것인가" 의 정의다. (호스트, 부팅 식별자, 번호) 가 있으면 그것이 답이고, 없으면 내용의 지문을 써야 하는데 그러면 진짜로 똑같은 두 사건까지 하나로 접힌다.

받은 순서는 일어난 순서가 아니다. 수집 경로가 막히면 줄은 몇 분 뒤에 도착한다. [OpenTelemetry 로그 데이터 모델](https://opentelemetry.io/docs/specs/otel/logs/data-model/)이 시각 필드를 둘로 나눠 두는 이유가 이것이다. Timestamp 는 사건이 일어난 시각을 원본 시계로 잰 것이고, ObservedTimestamp 는 수집계가 그 사건을 관측한 시각이다. 규격은 시각을 하나만 담을 수 있는 형식으로 옮길 때 "Timestamp 가 있으면 그것을, 없으면 ObservedTimestamp 를" 쓰라고 권한다. 둘의 차이가 곧 도착 지연이고, 그 분포를 보면 수집 경로의 건강 상태가 보인다.

현장에서 만나는 모습

마감 시각이 숫자를 바꾼다. "어제 오류가 몇 건이었나" 를 자정 직후에 세면, 아직 도착하지 않은 줄은 빠진다. 며칠 뒤 같은 질의를 돌리면 숫자가 늘어난다. 버그가 아니라 늦은 도착이다. 그래서 집계에는 마감 여유(late window) 가 필요하고, 그 여유는 지연 분포의 p95 나 p99 를 보고 정한다.

보관을 늘려도 안 오는 줄이 있다. [journald.conf(5)](https://www.man7.org/linux/man-pages/man5/journald.conf.5.html)의 RateLimitIntervalSec= 와 RateLimitBurst= 는 한 서비스가 정해진 구간 안에 정해진 수보다 많이 찍으면 그 구간의 나머지를 버린다. 기본값은 30초에 10000건이고 서비스별로 적용되며, 버린 개수를 알리는 메시지가 남는다. 장애로 로그가 폭주하는 바로 그 순간에 가장 많이 버려진다.

유실률은 구간마다 다르다. 전체 6퍼센트라는 숫자는 대개 쓸모가 없다. 어떤 5분에 50건이 통째로 빠졌는지가 중요하고, 그 구간이 사고 구간과 겹치는지가 결론을 바꾼다.

다음 실습에서 할 것

수집기가 받은 파일과 보낸 쪽의 카운터를 함께 만들고, 둘을 견주어 유실을 센다. 빠진 번호를 구간으로 묶고, at-least-once 가 만든 중복을 접고, 도착 지연의 분포를 구한다. 그다음 마감 시각에 집계했다면 몇 건을 놓쳤을지 계산하고, 마지막으로 재시작으로 번호가 되돌아간 호스트에서 부팅 식별자를 무시하면 유실과 중복이 어떻게 뒤바뀌는지를 숫자로 보인다.