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

**URL:** https://discuss.elastic.co/t/problem-with-combining-xmlfilter-and-ruby-code-to-compute-a-time-difference/195924
**Category:** Logstash
**Created:** [August 20, 2019, 12:16pm UTC](https://discuss.elastic.co/t/problem-with-combining-xmlfilter-and-ruby-code-to-compute-a-time-difference/195924 "2019-08-20T12:16:17Z")
**Posts on this page:** 4
**Page:** 1

<div class="post-metadata">

### Author: ![Franco](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/franco/32/52614_2.png) [@Franco](https://discuss.elastic.co/u/Franco)
#### Post date: [August 20, 2019, 12:16pm UTC](https://discuss.elastic.co/t/problem-with-combining-xmlfilter-and-ruby-code-to-compute-a-time-difference/195924/1 "2019-08-20T12:16:17Z")

</div>

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

---

<div class="post-metadata">

### Author: ![Badger](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/badger/32/25190_2.png) [@Badger](https://discuss.elastic.co/u/Badger)
#### Post date: [August 20, 2019, 12:55pm UTC](https://discuss.elastic.co/t/problem-with-combining-xmlfilter-and-ruby-code-to-compute-a-time-difference/195924/2 "2019-08-20T12:55:31Z")

</div>

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)
        '
    }
```

---

<div class="post-metadata">

### Author: ![Franco](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/franco/32/52614_2.png) [@Franco](https://discuss.elastic.co/u/Franco)
#### Post date: [August 20, 2019, 1:24pm UTC](https://discuss.elastic.co/t/problem-with-combining-xmlfilter-and-ruby-code-to-compute-a-time-difference/195924/3 "2019-08-20T13:24:44Z")

</div>

> [@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. 😂

---

<div class="post-metadata">

### Author: ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)
#### Post date: [September 17, 2019, 1:24pm UTC](https://discuss.elastic.co/t/problem-with-combining-xmlfilter-and-ruby-code-to-compute-a-time-difference/195924/4 "2019-09-17T13:24:55Z")

</div>

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