2020년 2월 11일 화요일

Logstash 필터 elapsed

특정 작업의 생성부터 소멸까지, 하나의 트랜잭션을 jobID라는 식별자로 구분하는 로그가 있다. 하나의 작업에 소요된 시간을 구해보자. 작업이 완료된 시간에서 시작된 시간을 빼면 된다.
[08:00:37.410] SendJob(jobID:75343414529)
[08:00:39.235] SendReport(jobID:75343414529)

근데 어떻게 하지? 가장 간단한 방법은 서로 다른 시점에 발생한 두 로그 간의 시간차를 계산해주는 로그스태시 필터 elapsed를 사용하는 것.

다음은 파이프라인 설정. 작업을 시작할 때는 send_begin, 작업이 끝날 때는 send_end 태그를 추가했으며, elapsed 플러그인은 해당 태그를 이용해서 계산이 필요한 시간대의 시작과 끝을 결정한다.
input {
 file {
  path => "D:/test.log"
  start_position => "beginning"
  sincedb_path => "nul"
 }
}

filter {
 dissect {
  mapping => { "message" => "[%{timestamp}] %{info}jobID:%{jobid})" }
  remove_field => [ "path", "host", "@version", "message" ]
 }

 date { 
  match => [ "timestamp", "HH:mm:ss.SSS" ]
  remove_field => "timestamp" 
 }

 if "SendJob" in [info] {
  mutate { add_tag => "send_begin" }
 } else {
   mutate { add_tag => "send_end" }
 } 

 elapsed {
  unique_id_field => "jobid"
  start_tag => "send_begin"
  end_tag => "send_end"
 }
}

output {
 stdout {}
}

다음은 실행 결과. 작업이 끝났음을 알리는 send_end 태그가 달린 로그에 두 로그 간 시간차가 기록된 elapsed_time 필드가 추가된다.
PS D:\ELK\logstash-7.5.2\bin> .\logstash -f d:\test.conf
Thread.exclusive is deprecated, use Thread::Mutex
Sending Logstash logs to D:/ELK/logstash-7.5.2/logs which is now configured via log4j2.properties
[2020-02-11T21:56:05,761][WARN ][logstash.config.source.multilocal] Ignoring the 'pipelines.yml' file because modules or command line options are specified
[2020-02-11T21:56:05,906][INFO ][logstash.runner          ] Starting Logstash {"logstash.version"=>"7.5.2"}
[2020-02-11T21:56:08,942][INFO ][org.reflections.Reflections] Reflections took 33 ms to scan 1 urls, producing 20 keys and 40 values
[2020-02-11T21:56:11,792][INFO ][logstash.filters.elapsed ][main] Elapsed, timeout: 1800 seconds
[2020-02-11T21:56:11,945][WARN ][org.logstash.instrument.metrics.gauge.LazyDelegatingGauge][main] A gauge metric of an unknown type (org.jruby.RubyArray) has been create for key: cluster_uuids. This may result in invalid serialization.  It is recommended to log an issue to the responsible developer/development team.
[2020-02-11T21:56:11,955][INFO ][logstash.javapipeline    ][main] Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>1, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50, "pipeline.max_inflight"=>125, "pipeline.sources"=>["d:/test.conf"], :thread=>"#"}
[2020-02-11T21:56:12,604][INFO ][logstash.javapipeline    ][main] Pipeline started {"pipeline.id"=>"main"}
[2020-02-11T21:56:12,691][INFO ][logstash.agent           ] Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>[]}
[2020-02-11T21:56:12,695][INFO ][filewatch.observingtail  ][main] START, creating Discoverer, Watch with file and sincedb collections
[2020-02-11T21:56:13,196][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9601}
D:/ELK/logstash-7.5.2/vendor/bundle/jruby/2.5.0/gems/awesome_print-1.7.0/lib/awesome_print/formatters/base_formatter.rb:31: warning: constant ::Fixnum is deprecated
{
          "tags" => [
        [0] "send_begin"
    ],
         "jobid" => "75343414529",
    "@timestamp" => 2019-12-31T23:00:37.410Z,
          "info" => "SendJob("
}
{
               "elapsed_time" => 1.825,
                       "tags" => [
        [0] "send_end",
        [1] "elapsed",
        [2] "elapsed_match"
    ],
    "elapsed_timestamp_start" => 2019-12-31T23:00:37.410Z,
                      "jobid" => "75343414529",
                 "@timestamp" => 2019-12-31T23:00:39.235Z,
                       "info" => "SendReport("
}

그런데 요거 쓸만하겠다란 생각을 할 때쯤 시간차를 계산하지 못하는 상황 발생.
{
          "tags" => [
        [0] "send_begin"
    ],
         "jobid" => "75343414529",
    "@timestamp" => 2019-12-31T23:00:37.410Z,
          "info" => "SendJob("
}
{
          "tags" => [
        [0] "send_end",
        [1] "elapsed_end_without_start"
    ],
         "jobid" => "75343414529",
    "@timestamp" => 2019-12-31T23:00:39.235Z,
          "info" => "SendReport("
}

대략 대여섯 번에 한 번 꼴로 시간차를 계산하지 못한다. 왜 그럴까? 혹시나 싶어 '-w' 옵션으로 CPU 코어를 1개로 제한했더니 시간차를 구하지 못하는 상황이 사라짐.
PS D:\ELK\logstash-7.5.2\bin> .\logstash -f d:\test.conf -w 1

로그스태시는 모든 코어를 사용하는데, 코어별로 로그를 처리하는 과정에서 순서가 뒤섞일 수 있다. 그래서 멀티 코어 환경에서는 로그 간 관계를 이용한 처리 시 거의 반드시 오류가 발생한다(..)

로그양이 많지 않아서 싱글 코어로도 충분히 처리 가능하다면 해피엔딩. 그렇지 않다면 기능을 따로 개발하는 게 나을 듯. 참고로 해당 플러그인은 기본 포함되어 있지 않기 때문에 별도 설치가 필요하다.
PS D:\ELK\logstash-7.5.2\bin> .\logstash-plugin install logstash-filter-elapsed
Validating logstash-filter-elapsed
Installing logstash-filter-elapsed
Installation successful

관련 글

댓글 없음:

댓글 쓰기

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