Calculate Date difference in LOGSTASH based on conditional text

Question

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

this answer should help: https://stackoverflow.com/questions/37353365/calculating-time-between-events/37359000#37359000 (hint: use `elapsed`) — Val, May 23 '17 at 06:53
Achieved the time difference between two logs using elapsed. updated the grok in main post. Next working on Add all the value of Analyze time appearing in between starttransaction and endtransaction. Subtract the value from #3 — Shantanu Sen, May 24 '17 at 08:11

score 1 · Accepted Answer · answered May 26 '17 at 03:19

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.

Calculate Date difference in LOGSTASH based on conditional text

1 Answers1