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

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'>

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?)
               @@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

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

<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

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
            event.set("req_duration_sec", duration)

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

So lucky. :joy:

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.