Elapsed plugin

Elastic Stack Logstash
1

Hello,

I'm trying to use logstash 1.5.1 to parse an application log file with the following pattern:

2015-04-30 17:11:04.640 [INFO] 123 message started
2015-04-30 17:11:14.320 [DEBUG] 123 message in the middle
2015-04-30 17:11:14.850 [INFO] 124 message started
2015-04-30 17:11:15.240 [INFO] 123 message ended
2015-04-30 17:11:18.340 [DEBUG] 124 message in the middle
2015-04-30 17:11:19.620 [INFO] 124 message ended
2015-04-30 17:11:24.640 [INFO] 230 message started
2015-04-30 17:11:29.620 [INFO] 230 message ended
2015-04-30 17:11:39.220 [INFO] 450 message started
2015-04-30 17:11:51.420 [INFO] 455 message started
2015-04-30 17:11:53.420 [DEBUG] 455 message in the middle
2015-04-30 17:11:53.456 [DEBUG] 450 message in the middle
2015-04-30 17:11:54.431 [INFO] 455 message ended
2015-04-30 17:11:56.431 [INFO] 450 message ended

At the end I need to generate an output file with time difference between "message started" and "message ended" for each thread id.

I'm not a logstash expert and after some hard work I realize that I need your support. I created the following configuration file but it doesn't work:

input {
file {
path => "/home/vagrant/workdir/temp.log"
start_position => beginning
}
}

filter {
grok {
match => [ "message" , "''%{TIMESTAMP_ISO8601:logdate} %{LOGLEVEL:loglevel} [%{DATA:thread}] message started" ]
add_tag => [ "transactionstarted" ]
}
grok {
match => [ "message" , "''%{TIMESTAMP_ISO8601:logdate} %{LOGLEVEL:loglevel} [%{DATA:thread}] message ended" ]
add_tag => [ "transactionended" ]
}

elapsed
{
start_tag => "transactionstarted"
end_tag => "transactionended"
unique_id_field => "thread"
}

}

output {
file {
path => "/home/vagrant/workdir/output.log"
}
}

Wrong output generated:

{"message":"2015-04-30 17:11:04.640 [INFO] 123\tmessage started ","@version":"1","@timestamp":"2015-06-18T00:21:30.224Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:14.320 [DEBUG] 123\tmessage in the middle ","@version":"1","@timestamp":"2015-06-18T00:21:30.232Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:14.850 [INFO] 124\tmessage started ","@version":"1","@timestamp":"2015-06-18T00:21:30.237Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:15.240 [INFO] 123\tmessage ended ","@version":"1","@timestamp":"2015-06-18T00:21:30.243Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:18.340 [DEBUG] 124\tmessage in the middle","@version":"1","@timestamp":"2015-06-18T00:21:30.256Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:19.620 [INFO] 124\tmessage ended","@version":"1","@timestamp":"2015-06-18T00:21:30.271Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:24.640 [INFO] 230\tmessage started ","@version":"1","@timestamp":"2015-06-18T00:21:30.284Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:29.620 [INFO] 230\tmessage ended","@version":"1","@timestamp":"2015-06-18T00:21:30.291Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:39.220 [INFO] 450\tmessage started","@version":"1","@timestamp":"2015-06-18T00:21:30.303Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:51.420 [INFO] 455\tmessage started","@version":"1","@timestamp":"2015-06-18T00:21:30.312Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:53.420 [DEBUG] 455\tmessage in the middle","@version":"1","@timestamp":"2015-06-18T00:21:30.314Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:53.456 [DEBUG] 450\tmessage in the middle","@version":"1","@timestamp":"2015-06-18T00:21:30.335Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:54.431 [INFO] 455\tmessage ended","@version":"1","@timestamp":"2015-06-18T00:21:30.360Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:56.431 [INFO] 450\tmessage ended","@version":"1","@timestamp":"2015-06-18T00:21:30.388Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp.log","tags":["_grokparsefailure"]}

Can I ask for your expertise to get the expected output?

Thanks a lot

2

Elapsed is what you want, though your grok pattern doesn't seem right as it's the loglevel field that is actually in square brackets, not thread.

Try using http://grokdebug.herokuapp.com/ to build a valid pattern first, then go from there.

3

Thanks!

Filter is now working:

filter {
grok {
match => [ "message" , "%{TIMESTAMP_ISO8601:time_request}%{SPACE}[%{GREEDYDATA:level}]%{SPACE}%{WORD:threadid}%{SPACE}message started" ]
add_tag => [ "transactionstarted" ]
}
grok {
match => [ "message" , "%{TIMESTAMP_ISO8601:time_request}%{SPACE}[%{GREEDYDATA:level}]%{SPACE}%{WORD:threadid}%{SPACE}message ended" ]
add_tag => [ "transactionended" ]
}

elapsed
{
start_tag => "transactionstarted"
end_tag => "transactionended"
unique_id_field => "threadid"
}

}

However, I don't understand elapsed output. Elapsed time and elapsed.timestamp_start are not correct.

{"message":"2015-04-30 17:11:04.640 [INFO] 123\tmessage started ","@version":"1","@timestamp":"2015-06-18T11:22:55.665Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp1.log","time_request":"2015-04-30 17:11:04.640","level":"INFO","threadid":"123","tags":["transactionstarted","_grokparsefailure"]}
{"message":"2015-04-30 17:11:14.320 [DEBUG] 123\tmessage in the middle ","@version":"1","@timestamp":"2015-06-18T11:22:55.674Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp1.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:14.850 [INFO] 124\tmessage started ","@version":"1","@timestamp":"2015-06-18T11:22:55.682Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp1.log","time_request":"2015-04-30 17:11:14.850","level":"INFO","threadid":"124","tags":["transactionstarted","_grokparsefailure"]}
{"message":"2015-04-30 17:11:15.240 [INFO] 123\tmessage ended ","@version":"1","@timestamp":"2015-06-18T11:22:55.685Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp1.log","tags":["_grokparsefailure","transactionended","elapsed","elapsed.match"],"time_request":"2015-04-30 17:11:15.240","level":"INFO","threadid":"123"," > elapsed.time":0.02,"elapsed.timestamp_start":"2015-06-18T11:22:55.665Z"
}
{"message":"2015-04-30 17:11:18.340 [DEBUG] 124\tmessage in the middle","@version":"1","@timestamp":"2015-06-18T11:22:55.701Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp1.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:19.620 [INFO] 124\tmessage ended","@version":"1","@timestamp":"2015-06-18T11:22:55.711Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp1.log","tags":["_grokparsefailure","transactionended","elapsed","elapsed.match"],"time_request":"2015-04-30 17:11:19.620","level":"INFO","threadid":"124","elapsed.time":0.029,"elapsed.timestamp_start":"2015-06-18T11:22:55.682Z"}
{"message":"2015-04-30 17:11:24.640 [INFO] 230\tmessage started ","@version":"1","@timestamp":"2015-06-18T11:22:55.734Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp1.log","time_request":"2015-04-30 17:11:24.640","level":"INFO","threadid":"230","tags":["transactionstarted","_grokparsefailure"]}
{"message":"2015-04-30 17:11:29.620 [INFO] 230\tmessage ended","@version":"1","@timestamp":"2015-06-18T11:22:55.735Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp1.log","tags":["_grokparsefailure","transactionended","elapsed","elapsed.match"],"time_request":"2015-04-30 17:11:29.620","level":"INFO","threadid":"230","elapsed.time":0.001,"elapsed.timestamp_start":"2015-06-18T11:22:55.734Z"}
{"message":"2015-04-30 17:11:39.220 [INFO] 450\tmessage started","@version":"1","@timestamp":"2015-06-18T11:22:55.761Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp1.log","time_request":"2015-04-30 17:11:39.220","level":"INFO","threadid":"450","tags":["transactionstarted","_grokparsefailure"]}
{"message":"2015-04-30 17:11:51.420 [INFO] 455\tmessage started","@version":"1","@timestamp":"2015-06-18T11:22:55.764Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp1.log","time_request":"2015-04-30 17:11:51.420","level":"INFO","threadid":"455","tags":["transactionstarted","_grokparsefailure"]}
{"message":"2015-04-30 17:11:53.420 [DEBUG] 455\tmessage in the middle","@version":"1","@timestamp":"2015-06-18T11:22:55.771Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp1.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:53.456 [DEBUG] 450\tmessage in the middle","@version":"1","@timestamp":"2015-06-18T11:22:55.794Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp1.log","tags":["_grokparsefailure"]}
{"message":"2015-04-30 17:11:54.431 [INFO] 455\tmessage ended","@version":"1","@timestamp":"2015-06-18T11:22:55.808Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp1.log","tags":["_grokparsefailure","transactionended","elapsed","elapsed.match"],"time_request":"2015-04-30 17:11:54.431","level":"INFO","threadid":"455","elapsed.time":0.044,"elapsed.timestamp_start":"2015-06-18T11:22:55.764Z"}
{"message":"2015-04-30 17:11:56.431 [INFO] 450\tmessage ended","@version":"1","@timestamp":"2015-06-18T11:22:55.825Z","host":"0.0.0.0","path":"/home/vagrant/workdir/temp1.log","tags":["_grokparsefailure","transactionended","elapsed","elapsed.match"],"time_request":"2015-04-30 17:11:56.431","level":"INFO","threadid":"450","elapsed.time":0.064,"elapsed.timestamp_start":"2015-06-18T11:22:55.761Z"}

Any idea?

Thanks