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