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
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"}
}
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.