# Calculate time difference between two log lines in a file
**URL:** https://discuss.elastic.co/t/calculate-time-difference-between-two-log-lines-in-a-file/203606
**Category:** Logstash
**Created:** [October 15, 2019, 9:27am UTC](https://discuss.elastic.co/t/calculate-time-difference-between-two-log-lines-in-a-file/203606 "2019-10-15T09:27:41Z")
**Posts on this page:** 5
**Page:** 1
### Author:  [@basavyr](https://discuss.elastic.co/u/basavyr)
#### Post date: [October 15, 2019, 9:27am UTC](https://discuss.elastic.co/t/calculate-time-difference-between-two-log-lines-in-a-file/203606/1 "2019-10-15T09:27:41Z")
Hello there,
I have a log file (given by the SLURM workload manager) that looks something like this:
```auto
2019-07-15 13:26:40 Started - job id: V3gNDm1MD7unkvVVEmSjiJLoABFKDmABFKDmtdGKDmABFKDmN8Erlm, unix user: 45001:45000, name: "org.nordugrid.ARC-CE-result-ops", owner: "/DC=EU/DC=EGI/C=GR/O=Robots/O=Greek Research and Technology Network/CN=Robot:argo-egi@grnet.gr", lrms: SLURM, queue: parallel1
2019-07-15 13:31:10 Finished - job id: V3gNDm1MD7unkvVVEmSjiJLoABFKDmABFKDmtdGKDmABFKDmN8Erlm, unix user: 45001:45000, name: "org.nordugrid.ARC-CE-result-ops", owner: "/DC=EU/DC=EGI/C=GR/O=Robots/O=Greek Research and Technology Network/CN=Robot:argo-egi@grnet.gr", lrms: SLURM, queue: parallel1, lrmsid: 66918
```
Basically pairs of lines with "Started" - "Finished" status which correspond to a unique job\_id.
I want to parse the data into a JSON format and also I want to add a new field for each "Finished" line with the job duration (which is given by subtracting the time in Finished line and the time from Started line.
I've started to use logstash filtering last week, so I am quite new to this. From my research, I found that ruby plug-in could help me, but so far I didn't manage to get a non-zero value for the job duration calculus.
This is my code:
```auto
filter { #filtering process for SLURM log file
grok { #DEFINED PATTERN FOR TXT FILE
match => { "message" => ["%{TIMESTAMP_ISO8601:[JOB][job_Details][Date1]} %{WORD:[JOB][job_status]} [-] %{DATA}[:] %{DATA:[JOB][job_id]}[,] %{DATA:[JOB][job_Details][user_Type]}[:] %{DATA:[JOB][job_Details][user_ID]}[,] %{DATA}[:] \"%{DATA:[JOB][job_Details][user_Name]}\"[,] %{DATA}: \"%{DATA:[JOB][job_Details][owner]}\"[,] %{DATA}[:] %{DATA:[JOB][job_Details][Workload_Manager_Type]}[,] %{DATA}[:] %{DATA:[JOB][job_Details][queue_Type]}[,] %{DATA}[:] %{NUMBER:[JOB][job_Details][Workload_Manager_id]}","%{TIMESTAMP_ISO8601:[JOB][job_Details][Date2]} %{WORD:[JOB][job_status]} [-] %{DATA}[:] %{DATA:[JOB][job_id]}[,] %{DATA:[JOB][job_Details][user_Type]}[:] %{DATA:[JOB][job_Details][user_ID]}[,] %{DATA}[:] \"%{DATA:[JOB][job_Details][user_Name]}\"[,] %{DATA}: \"%{DATA:[JOB][job_Details][owner]}\"[,] %{DATA}[:] %{DATA:[JOB][job_Details][Workload_Manager_Type]}[,] %{DATA}[:] %{GREEDYDATA:[JOB][job_Details][queue_Type]}" ]
}
remove_field => ["message","host","@version","path"]
}
date {
match => ["[JOB][job_Details][Date1]", "yyyy-MM-dd HH:mm:ss"]
target => "[JOB][job_Details][Finish_Time]"
}
date {
match => ["[JOB][job_Details][Date2]", "yyyy-MM-dd HH:mm:ss"]
target => "[JOB][job_Details][Start_Time]"
}
ruby {
init => "require 'time'"
code => "duration=(Time.parse(event.get('[JOB][job_Details][Date1]'))-Time.parse(event.get('[JOB][job_Details][Date2]'))) rescue nil; event.set('[JOB][job_Details][PROCESS_DURATION]',duration);"
}
```
And my output:
```auto
{
"@timestamp": "2019-10-15T09:07:29.057Z",
"JOB": {
"job_id": "V3gNDm1MD7unkvVVEmSjiJLoABFKDmABFKDmtdGKDmABFKDmN8Erlm",
"job_Details": {
"user_ID": "45001:45000",
"owner": "/DC=EU/DC=EGI/C=GR/O=Robots/O=Greek Research and Technology Network/CN=Robot:argo-egi@grnet.gr",
"user_Type": "unix user",
"PROCESS_DURATION": null,
"queue_Type": "parallel1",
"Workload_Manager_Type": "SLURM",
"Start_Time": "2019-07-15T10:26:40.000Z",
"user_Name": "org.nordugrid.ARC-CE-result-ops"
},
"job_status": "Started"
}
} {
"@timestamp": "2019-10-15T09:07:29.057Z",
"JOB": {
"job_id": "V3gNDm1MD7unkvVVEmSjiJLoABFKDmABFKDmtdGKDmABFKDmN8Erlm",
"job_Details": {
"user_ID": "45001:45000",
"owner": "/DC=EU/DC=EGI/C=GR/O=Robots/O=Greek Research and Technology Network/CN=Robot:argo-egi@grnet.gr",
"Workload_Manager_id": "66918",
"user_Type": "unix user",
"PROCESS_DURATION": null,
"queue_Type": "parallel1",
"Workload_Manager_Type": "SLURM",
"Finish_Time": "2019-07-15T10:31:10.000Z",
"user_Name": "org.nordugrid.ARC-CE-result-ops"
},
"job_status": "Finished"
}
}
```
As you can see, I can add the "PROCESS\_DURATION field to the lines (although I would like to add it only to the "Finished" line) but the result is null.
What am I doing wrong here?
Thank you in advance:)
---
### Author:  [@Badger](https://discuss.elastic.co/u/Badger)
#### Post date: [October 15, 2019, 3:24pm UTC](https://discuss.elastic.co/t/calculate-time-difference-between-two-log-lines-in-a-file/203606/2 "2019-10-15T15:24:55Z")
I cannot see what you did wrong there, but I would do it in a different way, using aggregate.
```
dissect { mapping => { "message" => "%{[@metadata][timestamp]} %{+[@metadata][timestamp]} %{event} - %{[@metadata][restOfLine]}" } }
date { match => ["[@metadata][timestamp]", "YYYY-MM-dd HH:mm:ss" ] }
kv { source => "[@metadata][restOfLine]" target => "[@metadata][keys]" field_split => "," value_split => ":" remove_char_key => " " }
aggregate {
task_id => "%{[@metadata][keys][jobid]}"
code => '
keys = event.get("[@metadata][keys]")
if keys
keys.each { |k, v|
map[k] = v
}
end
e = event.get("event")
map["time#{e}"] = event.get("@timestamp")
event.cancel
'
push_map_as_event_on_timeout => true
timeout => 3
timeout_code => '
event.set("duration", event.get("timeFinished").to_f - event.get("timeStarted").to_f)
'
}
```
will produce
```
"@version" => "1",
"owner" => "/DC=EU/DC=EGI/C=GR/O=Robots/O=Greek Research and Technology Network/CN=Robot:argo-egi@grnet.gr",
"lrmsid" => "66918",
"queue" => "parallel1",
"timeStarted" => 2019-07-15T13:26:40.000Z,
"@timestamp" => 2019-10-15T15:22:13.905Z,
"name" => "org.nordugrid.ARC-CE-result-ops",
"timeFinished" => 2019-07-15T13:31:10.000Z,
"unixuser" => "45001:45000",
"lrms" => "SLURM",
"jobid" => "V3gNDm1MD7unkvVVEmSjiJLoABFKDmABFKDmtdGKDmABFKDmN8Erlm",
"duration" => 270.0
```
Obviously you can move the keys under [JOB][job\_Details] using string interpolation in the keys.each loop as I do in storing the timestamps.
---
### Author:  [@basavyr](https://discuss.elastic.co/u/basavyr)
#### Post date: [October 16, 2019, 7:00am UTC](https://discuss.elastic.co/t/calculate-time-difference-between-two-log-lines-in-a-file/203606/3 "2019-10-16T07:00:04Z")
Ok @Badger, first of all thank you very much for the solution! It works perfectly for my entire log. The great thing is that now with aggregate I have everything under the same job\_id (in my case I had two objects: one for "started" and one for "finished")
Regarding the keys, I changed the fields using mutate filter e.g.:
```auto
rename => { "name" => "[job_Details][user_Name]"}
```
I know this is the naive implementation, but I didn't know how to change it in the Aggregate filter 😃
I also have to say that your solution is quite elegant, the way you created all the fields from the "restOfLine" key. However, I do have a couple of questions regarding your method. Namely these two parts:
```auto
keys.each { |k, v|
map[k] = v
}
```
and
```auto
push_map_as_event_on_timeout => true
timeout => 3
timeout_code => '
```
Could you please elaborate more on what is this actually doing, and why did you go this way? Thank you very much \<3
---
### Author:  [@Badger](https://discuss.elastic.co/u/Badger)
#### Post date: [October 16, 2019, 1:33pm UTC](https://discuss.elastic.co/t/calculate-time-difference-between-two-log-lines-in-a-file/203606/4 "2019-10-16T13:33:06Z")
> [@basavyr](#):
>
> keys.each { |k, v| map[k] = v }
When using push\_map\_as\_event\_on\_timeout the only fields on the resulting event are whatever is added to the map, so I configured the kv filter to put all of the extra fields into a known place ([@metadata][keys]), then in the aggregate filter I copy (or overwrite) each of the keys into the map.
---
### Author:  [@system](https://discuss.elastic.co/u/system)
#### Post date: [November 13, 2019, 1:33pm UTC](https://discuss.elastic.co/t/calculate-time-difference-between-two-log-lines-in-a-file/203606/5 "2019-11-13T13:33:07Z")
This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.