Logstash Ruby filter to subtract difference between two timestamps in single event

Elastic Stack Logstash
1

Hi,

I'm trying to demonstrate the feasability of switching from a Splunk solution to an ELK (Elasticsearch, Logstash and Kibana) stack (with Redis) solution for log analysis and triggering alerts.

I have a requirement (due to a legacy application on a system with performace issues which is not the ELK stack server) to add a field at the time of indexing to events that shows the difference between two timestamps from the the same event (so I can't use the logstash elapsed filter plugin as that compares events). Google has only returned code not valid or requiring look up tables when I'm sure this can be done in just Ruby but there appears to issues due to my novice abilities in Ruby and perhaps becuase Logstash uses JRuby.

The two timestamps show the difference in time between when an event is received by logstash and when a network host says the event occured (which can be different due the network latency or the network host having NTP [network time protocol] issues) which is exactly what needs to be recorded. Here are the sample fields:

"@timestamp": "2015-10-20T13:52:47.000Z" # this is when the host says the event occurred
"received_at": "2015-10-20T02:02:51.191Z" # this is when Logstash forwarder received the event

I would like to do something like the below (pseudocode) that will actually work:

filter {
  if [received_at] and [@timestamp] {
  # calculate the time difference in seconds between two different timestamps and add return to event as a new field
    ruby {
      init => "require 'time'"
      code => "event['time_difference']= (Time.parse(event['received_at']).to_i) - (Time.parse(event['@timestamp']).to_i)"
      add_tag => [ "calculated_time_difference" ]
    }
  }
}

Has anybody done this sucessfully who can share their filter or can anybody advise what Logstash JRuby functions can be used?

Thanks :smile:

1 Like
2

Hi, we do something similar but we are calculating the difference between the log's timestamp vs. the current system time. We do this to detect when logstash is having issues keeping up with the log file updates. You should be able to modify this to meet your requirements:

# Calculate lag in seconds from event's timestamp to current system time
ruby {
    init => "require 'time'"
    code => "event['[metrics][server_lag]'] = Time.now() - event['@timestamp']; event['[metrics][server_time]'] = Time.now()"
}
3

Thank you Craig,

Doesn't solve it but atleast lets me know I am on the correct track with my pseudocode.

I have a feeling I'm going to have to learn some Ruby and the differences between Ruby and JRuby very quickly (which is a bit scary for someone who has spent the last few years as a glorified cable monkey) :scream:

4

I think you could just do something like:

ruby {
    init => "require 'time'"
    code => "event['time_difference'] = event['received_at'] - event['@timestamp'];"
}
5

That was my very first attempt. The maths it produced was all wrong for some reason. I've actually got some working code now (but messy with string converversions though server resources on a tiny virtual machine seem to be coping fine with 5000 events a minute):

filter {
  if [received_at] and [@timestamp] {
    ruby {
      init => "require 'time'"
      code => "
        received_by_indexer = Time.iso8601(event['received_at'].to_s).to_i;
        time_in_event = Time.iso8601(event['@timestamp'].to_s).to_i;
        event['time_difference_in_seconds'] = received_by_indexer - time_in_event;
        event['epoch_received_at_in_seconds'] = received_by_indexer;
        event['epoch_timestamp_in_seconds'] = time_in_event;
        "
      add_tag => [ "calculated_time_difference" ]
    }
  }
}

I guess this will need optimising but I hope this thread helps anyone else out there googling for a solution. Any obvious gotchas with the above?

Once again Craig, thank you very much for your time, I was expecting it to be years before anyone replied with anything at all :smiley:

3 Likes