Problem with combining xmlfilter and ruby code to compute a time difference

[Franco (Frank Feller)]

Hi all,

I have an xml log which looks like this:

  <xml-request id='199263291' request='0x0x7f153c000e20' rsp='0' HTTP-rsp='0' session='28' bytesSent='1063' status='ended' created='2019-08-20T04:23:08.984+02:00' ended='2019-08-20T04:23:08.985+02:00'>
   <method>POST</method>
   <uri>/Zuschreibung/</uri>
   <remote_addr>10.49.9.50</remote_addr>
</xml-request>

I use an xmlfilter like this

  xml {
    source => "message"
    target => "xmldata"
    store_xml => false
    force_array => false
    xpath => [ "/xml-request/uri/text()", "uri" ]
    xpath => [ "/xml-request/@created", "req_created" ]
    xpath => [ "/xml-request/@ended", "req_ended" ]
  }

Since I'm interested in the time difference (between req_ended minus req_created) I add a ruby code part with DateTime parsing.
Due to some strange error messages with something like "RubyNil" I checked the req_ended and req_created field for nil before computing

  ruby {
      code => "

           @@duration = 0.0
           @@ended = event.get('[req_ended]')
           @@created = event.get('[req_created]')
           if (!@@ended.nil? and !@@created.nil?)
           then
               @@duration= (((DateTime.strptime(@@ended, '%Y-%m-%dT%H:%M:%S.%L%z')) - (DateTime.strptime(@@created, '%Y-%m-%dT%H:%M:%S.%L%z'))) * 86400).to_f
           end
           event.set('req_duration_sec',@@duration)
        "
  }

When testing my logstash config with reading the xml logs from a prepared file, the time computing seems ok.
When the xml is delivered from a filebeat, I got a lot of strange time values like

req_duration_sec 25,352.693

from such a line (which should have 0.001 sec as duration)

<xml-request id='199435077' request='0x0x7f0fe80008c0' rsp='0' HTTP-rsp='0' session='16' bytesSent='475' status='ended' created='2019-08-20T11:32:57.333+02:00' ended='2019-08-20T11:32:57.334+02:00'>

Or even neagtive ones

req_duration_sec -36,157.805

from
<xml-request id='199434849' request='0x0x7f1534000a30' rsp='0' HTTP-rsp='0' session='26' bytesSent='6384' status='ended' created='2019-08-20T11:32:56.132+02:00' ended='2019-08-20T11:32:56.132+02:00'>

Can anyone see what I'm doing wrong?

Best regards
Franco

[Badger]

There is no reason to use class or even instance variables here. You can use local variables. In fact, that might be the problem. If a message is missing one of req_created or req_ended it will use the value from the previous message. Personally I would use a date filter to parse the timestamps.

    date { match => [ "req_created", "ISO8601" ] target => "req_created" }
    date { match => [ "req_ended", "ISO8601" ] target => "req_ended" }
    ruby {
        code => '
            duration = 0.0
            ended = event.get("req_ended")
            created = event.get("req_created")
            if created and ended then
                duration = ended.to_f - created.to_f
            end
            event.set("req_duration_sec", duration)
        '
    }

[Franco (Frank Feller)]

@Badger

date { match => [ "req_created", "ISO8601" ] target => "req_created" } date { match => [ "req_ended", "ISO8601" ] target => "req_ended" }

Tnx Badger,
your advice helped me perfectly. No more negative or huge positives.

So lucky.