2020년 2월 28일 금요일

Logstash codec 플러그인 multiline

Logstash 필터 elapsed 플러그인을 이용하면 완료된 트랜잭션의 실행 시간을 구할 수 있다. 이때 정확한 시간을 계산하기 위해서는 발생 순서대로 로그를 처리하는 것이 필수.

그런데 멀티 코어 환경에서는 그게 잘 안 된다. 트랜잭션 시작 시점을 기준으로 종료 시점을 기다려야 하는데 종료 시점이 먼저 처리될 수도 있기 때문. 그렇다고 싱글 코어를 쓰자니 로그양이 너무 많고(..) 이럴 땐 어떻게 해야 할까?
[08:00:37.410] SendJob(jobID:75343414529)
[08:00:39.235] SendReport(jobID:75343414529)

다음은 예제 로그를 처리하는 파이프라인 설정.
input {
 file {
  path => "D:/test.log"
  start_position => "beginning"
  sincedb_path => "nul"
 }
}

output {
 stdout {}
}

실행 결과는 다음과 같다.
{
      "@version" => "1",
    "@timestamp" => 2020-02-27T12:51:55.940Z,
          "host" => "MHKANG",
          "path" => "D:/test.log",
       "message" => "[08:00:37.410] SendJob(jobID:75343414529)\r"
}
{
      "@version" => "1",
    "@timestamp" => 2020-02-27T12:51:55.968Z,
          "host" => "MHKANG",
          "path" => "D:/test.log",
       "message" => "[08:00:39.235] SendReport(jobID:75343414529)\r"
}

멀티 라인 구조가 문제

SendJob으로 시작, SendReport로 끝나는 멀티 라인 구조를 싱글 라인으로 바꿔보자. codec 플러그인 중 multiline은 서로 다른 시점에 발생한 여러 개의 로그를 특정 조건으로 합쳐준다.

다음은 message 필드에 'SendReport' 패턴이 존재하면 독립된 필드에 기록하지 않고 직전(previous)에 발생한 message 필드에 추가하는 설정이며, 결과적으로 동일 트랜잭션의 시작과 끝을 알리는 로그를 하나로 합쳐준다.
input {
 file {
  path => "D:/test.log"
  start_position => "beginning"
  sincedb_path => "nul"
  codec => multiline {
   pattern => "SendReport"
   what => "previous"
  }
 }
}

output {
 stdout {}
}

다음은 실행 결과.
{
      "@version" => "1",
    "@timestamp" => 2020-02-27T12:55:23.224Z,
          "tags" => [
        [0] "multiline"
    ],
          "path" => "D:/test.log",
       "message" => "[08:00:37.410] SendJob(jobID:75343414529)\r\n[08:00:39.235] SendReport(jobID:75343414529)\r",
          "host" => "MHKANG"
}

계산이 가능한 테이블 구조로

이제 종료 시간에서 시작 시간을 빼면 된다. 다음은 dissect 플러그인을 이용해서 해당 계산이 가능한 구조를 만들어주는 설정.
filter {
 dissect {
  mapping => { "message" => "[%{start_time}]%{}[%{end_time}]%{}" }
 }
}

실행 결과는 다음과 같다. 의도했던 대로 트랜잭션의 시작(start_time)과 종료(end_time) 시간을 별도 필드로 분리했다. 이제 계산만 하면 됨.
{
      "@version" => "1",
    "@timestamp" => 2020-02-27T13:04:16.713Z,
          "tags" => [
        [0] "multiline"
    ],
          "path" => "D:/test.log",
       "message" => "[08:00:37.410] SendJob(jobID:75343414529)\r\n[08:00:39.235] SendReport(jobID:75343414529)\r",
    "start_time" => "08:00:37.410",
          "host" => "MHKANG",
      "end_time" => "08:00:39.235"
}

문제는 추출된 필드의 데이터 유형이 '문자열'이란 사실. 문자는 산술 연산을 할 수 없다. 데이터 유형을 숫자로 바꿔주면 될까? 계산 대상은 무려 '시간'이다. 시간, 분, 초 등 시간 단위를 반영한 계산이 필요하다는 얘기.

대충 생각해도 ①각 시간 단위를 쪼갠 후 ②숫자 유형으로 바꾼 다음 ③다시 각 단위를 초 단위로 바꾸고 ④그걸 더한 필드끼리 계산 어쩌구 저쩌구(..)

그런데 이 어려운 걸

ruby 플러그인이 해냄. 다음은 Time.parse() 함수를 이용해서 문자 유형으로 저장된 시간 필드를 시간 유형으로 변환 후, 시간차를 계산하는 설정.
filter {
 dissect {
  mapping => { "message" => "[%{start_time}]%{}[%{end_time}]%{}" }
 }
 ruby {
  code => "event.set('delay_time', Time.parse(event.get('end_time')) - Time.parse(event.get('start_time')) )"
 }
}

실행 결과는 다음과 같다.
{
      "@version" => "1",
    "@timestamp" => 2020-02-27T13:19:16.779Z,
          "tags" => [
        [0] "multiline"
    ],
          "path" => "D:/test.log",
       "message" => "[08:00:37.410] SendJob(jobID:75343414529)\r\n[08:00:39.235] SendReport(jobID:75343414529)\r",
    "start_time" => "08:00:37.410",
    "delay_time" => 1.825,
          "host" => "MHKANG",
      "end_time" => "08:00:39.235"
}

로그양을 늘려가며 테스트해봤는데 멀티 코어 환경에서 누수 없이 잘 처리한다. multiline 작업이 코어 단위로 이루어지는 건가?

특이한 점은 마지막 처리 결과를 안 보여준다. 로그스태시를 종료(or 재시작)해야 보여줌. 마지막 처리 후 SendReport가 또 발생하는지 확인하는 모양. 됐고 ruby 만세

관련 글

댓글 없음:

댓글 쓰기

크리에이티브 커먼즈 라이선스