# Elapsed plugin
**URL:** https://discuss.elastic.co/t/elapsed-plugin/23885
**Category:** Logstash
**Created:** [June 18, 2015, 12:29am UTC](https://discuss.elastic.co/t/elapsed-plugin/23885 "2015-06-18T00:29:13Z")
**Posts on this page:** 4
**Page:** 1
### Author:  [@Andre\_Hole](https://discuss.elastic.co/u/Andre_Hole)
#### Post date: [June 18, 2015, 12:29am UTC](https://discuss.elastic.co/t/elapsed-plugin/23885/1 "2015-06-18T00:29:13Z")
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
---
### Author:  [@warkolm](https://discuss.elastic.co/u/warkolm)
#### Post date: [June 18, 2015, 2:36am UTC](https://discuss.elastic.co/t/elapsed-plugin/23885/2 "2015-06-18T02:36:21Z")
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/](http://grokdebug.herokuapp.com/) to build a valid pattern first, then go from there.
---
### Author:  [@Andre\_Hole](https://discuss.elastic.co/u/Andre_Hole)
#### Post date: [June 18, 2015, 11:21am UTC](https://discuss.elastic.co/t/elapsed-plugin/23885/3 "2015-06-18T11:21:03Z")
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
---
### Author:  [@system](https://discuss.elastic.co/u/system)
#### Post date: [July 6, 2017, 5:37am UTC](https://discuss.elastic.co/t/elapsed-plugin/23885/4 "2017-07-06T05:37:06Z")