[Kafka] 클라이언트와 서버간 time zone 문제 (Negative message latency=-32376435 ms)

개요

• 카프카에서 다음과 같은 로그내용이 작업간격마다 발생하는 문제가 발생했습니다.

• 카프카에는 로그 cleaner가 동작해 해당 로그내용들이 일정주기마다 제거되고 있었지만, 도커 내부 컨테이너에서 해당 로그들이 따로 저장돼 문제가 발생했습니다.
• 로그가 초마다 수백개씩 쌓여 하루에 GB단위의 로그가 축적되고 있었고, 발견했을 때는 디스크 용량을 거의 잠식한 상태였습니다 (TB단위).
• 도커 log configuration을 수정해 쌓이는 로그 크기를 조절할 수도 있지만, 근본적으로 위 문제가 발생하는 원인을 파악하고 해결하는 것을 우선합니다.

원인

This is a log message indicating a warning about a negative message latency of -32389513 milliseconds. The message latency is being measured by the Confluent Monitoring Metrics interceptor (io.confluent.monitoring.clients.interceptor.MonitoringMetrics). A negative message latency value indicates that the message was processed before it was even sent, which is not possible. This may be an indication of a clock synchronization issue or some other problem with the system clock. The log message was generated on April 24, 2023 at 05:28:05 UTC.

• 위 에러 로그는 broker와 clent간 timezone이 다를 때 발생하는 문제입니다.
  • broker는 UTC 타임존 (+00:00)이고, 클라이언트는 KST 타임존 (+09:00)일 때 문제가 발생할 수 있습니다.
    1. 클라이언트의 작업메시지는 KST로 기록되며, broker의 타임존(+00:00)보다 9시간 빠릅니다.
    2. 작업메시지가 broker에게 전달될 때, broker는 현재 작업이 완료된 시점이 클라이언트가 보내준 시간보다 과거라 판단하고 negative message latency Warn메시지를 출력합니다.

 

 

• Confluent에서 Topics의 시간 차이를 통해 에러 로그가 왜 발생했는지 유추할 수 있습니다.
  • 2023-04-26 09:02(KST) 기준 데이터 처리 시간이 미래로 나와있습니다.
  • timestamp를 데이터에 있는 시간 변수 chetime으로 지정한 krx_price topic은 해당 시간을 timestamp로 설정합니다.
  • krx_price 를 재스트리밍하는 krx_filtered topic 과 다음 토픽인 krx_minute은 timestamp 문제가 발생합니다.
• 즉, 데이터를 재스트리밍 하는 과정에서 Timestamp가 꼬인것으로 추정됩니다.

 

해결 방법

• timezone이 꼬인 krx_filtered Stream topic에 timestamp를 지정해주면 됩니다.
  • 이 때 지정될 time변수는 차이나는 시간만큼 빼줘야 합니다.
  • 위 경우는 9시간 빨라짐으로 9시간을 뺐습니다.
    •