基于条件文本的LOGSTASH数据差计算

Question

这里有一个条件:我有一系列日志，从startTransaction开始，到终端事务结束。在这两个事件之间还有其他日志。

我的要求是捕获上述事件的日志时间并计算差异。

当我阅读logstash不支持循环时，会出现多个开始和结束事件块，在其中我需要计算时间差。

请帮忙找点办法。

条件

1. 请注意启动事务事件日志的时间。
2. 请注意结束事务事件日志的时间。
3. 找出时差并存储在变量中。
4. 添加在启动事务和结束事务之间出现的所有分析时间的值。
5. 从#3中减去值

日志

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

我创建了下面的Logstash。我能实现#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"}
}

Answer 1

我能够达到所有的要求。想要分享出来的东西。

#1 - #4是通过对数存储来实现的。下面是conf文件

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是通过基巴纳的脚本字段实现的。