Shantanu Sen
Reputation: 221
Calculate Date difference in LOGSTASH based on conditional text
I have a condition here: I have a series of logs where it starts from startTransaction and ends at endtransaction. Now between there two events there are other logs.
My requirement is to capture the log time for the above mentioned events and calculate the difference.
As i read logstash do not support loop, there will be multiple blocks of start and end events, where I need to calculate the time difference.
Please help with some approach.
Conditions
- Note the time for starttransaction event log
- Note the time for endtransaction event log
- Find the time difference and store in variable.
- Add all the value of Analyze time appearing in between starttransaction and endtransaction.
- Subtract the value from #3
Log
2017-05-18 12:52:22,314 [RPC-0-startTransaction-sid:15488] (image.agent.Controller) DEBUG clientID:CSharp:version=10.4:2e329de7-2947-49dd-b97c-e9cad9015488: Controller: Start transaction 'BNG_iphone7_01_Applauch', status: true
2017-05-18 12:52:22,689 [RPC-0-click-sid:15488] (image.agent.Controller) DEBUG Will use NATIVE
2017-05-18 12:52:22,689 [RPC-0-click-sid:15488] (image.agent.Controller) INFO clientID:CSharp:version=10.4:2e329de7-2947-49dd-b97c-e9cad9015488: waitForElementInt: z=NATIVE, e=xpath=//*[@text=concat('McDonald', "'", 's')], i=0, t=10000, NATIVE
2017-05-18 12:52:22,798 [RPC-0-click-sid:15488] (experitest.device.aq) DEBUG ios_app:iPhone 7.enable-non-instrumented-mode=true
2017-05-18 12:52:22,798 [RPC-0-click-sid:15488] (experitest.device.aq) DEBUG ios_app:iPhone 7.enable-non-instrumented-mode=true
2017-05-18 12:52:23,032 [RPC-0-click-sid:15488] (experitest.device.aq) DEBUG ios_app:iPhone 7.enable-non-instrumented-mode=true
2017-05-18 12:52:23,250 [RPC-0-click-sid:15488] (device.ios.c) INFO send command: {"command":"dump"}
2017-05-18 12:52:23,250 [RPC-0-click-sid:15488] (device.ios.c) DEBUG Sending command :9
2017-05-18 12:52:24,186 [RPC-0-click-sid:15488] (image.agent.Controller) DEBUG Native analyze time: 1388
2017-05-18 12:52:24,186 [RPC-0-click-sid:15488] (image.agent.Controller) DEBUG Element identified: pos: java.awt.Point[x=38,y=580], width 150, height: 170
2017-05-18 12:52:24,186 [RPC-0-click-sid:15488] (image.agent.Controller) DEBUG (1388) end wait
2017-05-18 12:52:24,249 [RPC-0-click-sid:15488] (agent.appiphone.e) DEBUG Click on x: 113, y: 665, xr: 1.0, xy: 1.0
2017-05-18 12:52:27,765 [RPC-0-waitForElement-sid:15488] (image.agent.Controller) DEBUG Native analyze time: 2481
2017-05-18 12:52:27,765 [RPC-0-waitForElement-sid:15488] (image.agent.Controller) DEBUG Element identified: pos: java.awt.Point[x=10,y=52], width 94, height: 60
2017-05-18 12:52:27,765 [RPC-0-waitForElement-sid:15488] (image.agent.Controller) DEBUG (2481) end wait
2017-05-18 12:52:27,765 [RPC-0-waitForElement-sid:15488] (image.agent.Controller) DEBUG clientID:CSharp:version=10.4:2e329de7-2947-49dd-b97c-e9cad9015488: Controller: Wait for 'xpath=//*[@text='Menu']' in zone NATIVE, timeout: 10000, status: true
2017-05-18 12:52:27,968 [pool-4-thread-1] (image.agent.Controller) DEBUG Done writing file: C:\Users\Administrator\AppData\Roaming\seetest\rundata\clientID_CSharp_version=10.4_2e329de7-2947-49dd-b97c-e9cad9015488\7.PNG##
2017-05-18 12:52:32,024 [RPC-0-click-sid:15488] (image.agent.Controller) DEBUG Native analyze time: 2434
2017-05-18 12:52:32,024 [RPC-0-click-sid:15488] (image.agent.Controller) DEBUG Element identified: pos: java.awt.Point[x=10,y=52], width 94, height: 60
2017-05-18 12:52:32,024 [RPC-0-click-sid:15488] (image.agent.Controller) DEBUG (2434) end wait
2017-05-18 12:52:32,086 [RPC-0-click-sid:15488] (agent.appiphone.e) DEBUG Click on x: 57, y: 82, xr: 1.0, xy: 1.0
2017-05-18 12:52:32,086 [RPC-0-click-sid:15488] (device.ios.c) DEBUG iOS XCAutomation click (28, 41)
2017-05-18 12:52:32,086 [RPC-0-click-sid:15488] (device.ios.c) INFO send command: {"command":"tap","point1":{"x":28,"y":41}}
2017-05-18 12:52:32,086 [RPC-0-click-sid:15488] (device.ios.c) DEBUG Sending command :13
2017-05-18 12:52:32,305 [RPC-0-click-sid:15488] (device.ios.c) INFO result:
2017-05-18 12:52:35,987 [RPC-0-isElementFound-sid:15488] (experitest.device.aC) DEBUG dump time: 2496
2017-05-18 12:52:36,003 [RPC-0-isElementFound-sid:15488] (image.agent.Controller) DEBUG Native analyze time: 2746
2017-05-18 12:52:36,003 [RPC-0-isElementFound-sid:15488] (image.agent.Controller) DEBUG Element identified: pos: java.awt.Point[x=0,y=748], width 650, height: 132
2017-05-18 12:52:36,003 [RPC-0-isElementFound-sid:15488] (image.agent.Controller) DEBUG (2746) end wait
2017-05-18 12:52:36,003 [RPC-0-isElementFound-sid:15488] (image.agent.Controller) DEBUG clientID:CSharp:version=10.4:2e329de7-2947-49dd-b97c-e9cad9015488: Controller: Check if 'xpath=//*[@text='Our Menu']' is found in zone 'NATIVE' index 0, status: true
2017-05-18 12:52:36,128 [pool-4-thread-1] (image.agent.Controller) DEBUG Done writing file: C:\Users\Administrator\AppData\Roaming\seetest\rundata\clientID_CSharp_version=10.4_2e329de7-2947-49dd-b97c-e9cad9015488\11.PNG##
2017-05-18 12:52:36,424 [RPC-0-endTransaction-sid:15488] (image.agent.Controller) DEBUG clientID:CSharp:version=10.4:2e329de7-2947-49dd-b97c-e9cad9015488: Controller: End transaction 'BNG_iphone7_02_ClickMenu', status: true
I created the below Logstash Config. I am able to achieve #1 - #3
input {
file {
path => ["D:/SeeTestLog/SeeTest-2017-05-18-12-51-22.log"]
start_position => "beginning"
type => "st_ios"
}
}
filter {
if ("analyze" in [message]) {
grok {
match => { message => [ "%{TIMESTAMP_ISO8601:timestamp}\,%{INT:bytes}%{SPACE}\[(?<eventmessage>%{WORD:text1}\-%{WORD:text2}\-%{WORD:Event}\-%{NOTSPACE:deviceid}\])%{SPACE}\(%{NOTSPACE:controller}\)%{SPACE}%{WORD:logger}%{SPACE}(?<analyzetext>%{WORD:text1}%{SPACE}%{WORD:text2}%{SPACE}%{NOTSPACE:text3})%{SPACE}%{INT:analyzetime} (?<task_id>.*)"
]}
add_tag => [ "st_ios" ]
}
}
else
{
grok {
match => { message => ["%{TIMESTAMP_ISO8601:timestamp}\,%{INT:bytes}%{SPACE}\[(?<eventmessage>%{WORD:text1}\-%{WORD:text2}\-%{WORD:Event}\-%{NOTSPACE:deviceid}\])%{SPACE}\(%{NOTSPACE:controller}\)%{SPACE}%{WORD:logger}%{SPACE}%{GREEDYDATA:logmessage} (?<task_id>.*)"
]}
add_tag => [ "st_ios" ]
}
}
mutate {
convert => { "bytes" => "integer"}
convert => { "analyzetime" => "integer"}
}
date {
match => [ "timestamp", "dd-MMM-yyyy HH:mm:ss", "YYYY-MM-dd HH:mm:ss" ]
target => "timestamp"
locale => "en"
}
if ("startTransaction" in [message]) {
mutate { add_tag => ["eventstart"] }
}
else if ("endTransaction" in [message]) {
mutate { add_tag => ["eventend"] }
}
elapsed {
start_tag => "eventstart"
end_tag => "eventend"
unique_id_field => "task_id"
timeout => 600
new_event_on_match => false
add_tag => ["in2"]
}
}
output {
stdout {codec => rubydebug}
elasticsearch { hosts => ["localhost:9200"] index => "logstash-st-ios-1"}
}
Upvotes: 1
Views: 1639
Answers (1)
Shantanu Sen
Reputation: 221
I was able to achieve all the requirement. Wanted to share the out come.
#1 - #4 is achieved through logstash. Below is the conf file
input {
file {
path => ["temp.log"]
start_position => "beginning"
}
}
filter {
if ("analyze" in [message]) {
grok {
match => { message => ["%{TIMESTAMP_ISO8601:timestamp}\,%{INT:bytes}%{SPACE}\[(?<eventmessage>%{WORD:text1}\-%{WORD:text2}\-%{WORD:Event}\-%{NOTSPACE:deviceid}\])%{SPACE}\(%{NOTSPACE:controller}\)%{SPACE}%{WORD:logger}%{SPACE}(?<analyzetext>%{WORD:text1}%{SPACE}%{WORD:text2}%{SPACE}%{NOTSPACE:text3})%{SPACE}%{INT:analyzetime}"]}
}
}
else
{
grok {
match => { message => ["%{TIMESTAMP_ISO8601:timestamp}\,%{INT:bytes}%{SPACE}\[(?<eventmessage>%{WORD:text1}\-%{WORD:text2}\-%{WORD:Event}\-%{NOTSPACE:deviceid}\])%{SPACE}\(%{NOTSPACE:controller}\)%{SPACE}%{WORD:logger}%{SPACE}%{NOTSPACE:ClientID}\:%{SPACE}%{WORD:controllertext}\:%{SPACE}%{WORD:Val1}%{SPACE}%{WORD:Val2}%{SPACE}\'%{NOTSPACE:usertransaction}\'\,%{SPACE}%{WORD:statustext}\:%{SPACE}%{WORD:statusvalue}"]}
}
}
mutate {
convert => { "bytes" => "integer"}
convert => { "analyzetime" => "integer"}
}
date {
match => [ "timestamp", "dd-MMM-yyyy HH:mm:ss", "YYYY-MM-dd HH:mm:ss" ]
target => "timestamp"
locale => "en"
}
if ("startTransaction" in [message]) {
mutate { add_tag => ["eventstart"] }
}
else if ("endTransaction" in [message]) {
mutate { add_tag => ["eventend"] }
}
elapsed {
start_tag => "eventstart"
end_tag => "eventend"
unique_id_field => "deviceid"
timeout => 120
new_event_on_match => false
}
if ("startTransaction" in [message]) {
aggregate {
task_id => "%{deviceid}"
code => "map['sum_analyze_time'] = 0"
map_action => "create"
}
}
if ("analyze" in [message]) {
aggregate {
task_id => "%{deviceid}"
code => "map['sum_analyze_time'] += event.get('analyzetime')"
map_action => "update"
}
}
if ("endTransaction" in [message]) {
aggregate {
task_id => "%{deviceid}"
code => "event.set('sum_analyze_time', map['sum_analyze_time'])"
map_action => "update"
end_of_task => true
timeout => 120
}
}
}
output {
stdout {codec => rubydebug}
elasticsearch { hosts => ["localhost:9200"] index => "logstash-st-ios-1"}
}
--#5 is achieved through scripted field in Kibana.
Upvotes: 1
Related Questions
- How to calculate time stamp difference in Elasticsearch +Kibana and show it in new column in results
- Logstash Date filter not working properly
- Calculate difference or delta between different events in logstash
- Grok conditional parsing for ELK Stack
- logstash convert to date and use only the date part in kibana
- Logstash Date Parsing different
- Kibana time delta between two fields
- How to compare date in Logstash
- Logstash date filter in a special case
- Logstash Date Filter