[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관련 글
댓글 없음:
댓글 쓰기