Share:|

Introduction

In this series we're looking at how to setup the Elastic Stack to collect, parse, and display data from our Remedy logs.  So far we've covered:

 

  • Part 1 - setting up Elasticsearch, Kibana and Filebeat to collect logs from one or more Remedy servers.
  • Part 2 - adding Logstash and modifying the setup to pass logs through it to Elasticsearch.
  • Part 3 - first steps in using Logstash to enrich the logs with additional data for filtering and visualizatiions in Kibana.

 

This post will look at adding other Remedy server logs to the data being collected, one way to handle non-standard logs lines, and more advanced use of Logstash filters.

 

More Logs Please

At the moment we're collecting the API and arerror log files from our Remedy server so let's add some more.  To do this we need to modify the Filebeat configuration file on our Remedy server.  The files that are being collected are defined by filebeat.prospectors entries like this one for the arapi.log:

 

- type: log

  enabled: true

  paths:

    - /opt/bmc/ARSystem/db/arapi.log

  fields:

    logtype: arserver

  fields_under_root: true

 

There are several different ways to add additional logs.  We could

  1. create a new prospector entry for each log.
  2. add a new file in the paths: section.
  3. use a wildcard for the filename.

 

However, for our tests, I'm going to change the filename we're reading from to logstash.log and then use the logging options on the Remedy server to control what gets logged.  The advantage of doing it this way is that we can easily change which logs are being sent to Elasticsearch simply by using the same log file name for all of them and turning them on or off.   We won't need to reconfigure and restart Filebeat each time we want to use different log types.

 

Remedy server logging directed to a single file and switchable by using the checkboxes.

 

How Many Lines Should a Log Line Log?

While we're here I'd also like to look at how we can handle log entries that span multiple lines.  At the moment we're only interested in the standard Remedy server logs which all have the less than symbol as the first character of the line and share the same format for the first few fields :

 

<API > <TID: 0000000336> <RPC ID: 0000021396> <Queue: Prv:390680> <Client-RPC: 390680 > <USER: Remedy Application Service...

<SQL > <TID: 0000000336> <RPC ID: 0000021396> <Queue: Prv:390680> <Client-RPC: 390680 > <USER: Remedy Application Service...

<FLTR> <TID: 0000000336> <RPC ID: 0000021396> <Queue: Prv:390680> <Client-RPC: 390680 > <USER: Remedy Application Service...


If you take a look at some sample logs you'll see that although the majority of lines follow this standard, there are some exceptions such as:

 

  • stack traces

<SQL > <TID: 0000000509> <RPC ID: 0000135141> <Queue: Fast      > <Client-RPC: 390620   > <USER: markw...

  com.bmc.arsys.domain.etc.ARException: ERROR (302): Entry does not exist in database

  at com.bmc.arsys.server.persistence.entry.impl.SQLHelperImpl.executePreparedStatement_aroundBody30(SQLHelperImpl.java:1121) [bundlefile:9.1.04-SNAPSHOT]

  at com.bmc.arsys.server.persistence.entry.impl.SQLHelperImpl$AjcClosure31.run(SQLHelperImpl.java:1) [bundlefile:9.1.04-SNAPSHOT]

 

  • some FLTR Set Fields and Notify action entries where text being processed can appear

<FLTR> <TID: 0000000334> <RPC ID: 0000135942> <Queue: Fast      > <Client-RPC: 390620   > <USER: markw...

z5VF_Message (304384301) = <html>

test text


In these cases the lines that don't start with < are continuations of the last line that does and, with our current configuration, will not be parsed by our Logstash grok filter.  They will be added to Elasticsearch as records without any of the new parsed data fields we're creating.  Both Logstash and Filebeat have methods to deal with these multi-line messages but the recommendation is to do this as early in the pipeline as possible.  For our logs, whenever we come across a line that does not start with <, we want to include it as part of the last line that does.  The Filebeat link above explains the details of how this is configured for each prospector definition.

 

The filebeat.yml updates we need to make to our API log file prospector for the file name change and multi-line processing are shown in bold below:

 

- type: log

  enabled: true

  paths:

    - /opt/bmc/ARSystem/db/logstash.log

  fields:

    logtype: arserver

  fields_under_root: true

  multiline.pattern: '^<'

  multiline.negate: true

  multiline.match: after

 

If you want to be very thorough you could make the pattern more selective as it is possible that the continuation lines may also start with <.  If you want to try this change multi-line pattern regex to lines starting with < and then having one of the recognised log type values:

 

    multiline.pattern: '^<(FLTR|SQL|API|ESCL|FTI|USER|THRD|ALRT|SGRP)'

 

Restart Filebeat and you should see that multi-line data, such as Java stack traces, is contained in a single record rather than the one record per line they would be otherwise:

 

Getting More Data From Log Lines

Now that we've changed Filebeat to pick up data from logstash.log go ahead and enable SQL or some of the other log types to that file and see what appears in Kibana:

 

Here we have API, SQL and FLTR logs.

 

Looking at the data above it would be nice to try and enhance our Logstash filter to capture some additional information such as the API type, schema or form names, and so on.  To do this we need to go back and tweak our Logstash grok filter.

 

At the moment we're handling all the fields up to the timestamp, storing the remainder of the line in log_details.

 

filter {

  grok {

    match => {"message" => "^<%{WORD:log_type}%{SPACE}> <TID: %{DATA:tid}> <RPC ID: %{DATA:rpc_id}> <Queue: %{DATA:rpc_queue}%{SPACE}\> <Client-RPC: %{DATA:client_rpc}%{SPACE}> <USER: %{DATA:user}%{SPACE}> <Overlay-Group: %{NUMBER:overlay_group:}%{SPACE}>%{SPACE}%{GREEDYDATA:log_details}$"}

  }

}

 

Next up is the timestamp so what can we do with that?  We could just skip it and rely on the @timestamp field that's already part of the Elasticsearch record. However, you'll notice that these are not the same as the Remedy timestamps as they're added when Filebeat processes the log lines and so lag by a small amount.  However, before we continue there's one other thing we need to consider.

 

It's Just a Matter of Time...

Here's where we hit our first gotcha with Remedy log lines.  Compare the log details below:

 

<API > <TID: 0000000336>...     /* Tue Jul 31 2018 11:21:39.8570 */ +GLEWF ARGetListEntryWithFields -- schema AR System....

<SQL > <TID: 0000000336>...     /* Fri Aug 03 2018 11:31:17.7820 */ SELECT t0.schemaId, t0.name, t0.overlayGroup, t0.schemaType...

<FLTR> <TID: 0000000336>...     /* Fri Aug 03 2018 11:30:58.0360 */ End of filter processing (phase 1) -- Operation - GET...

<FLTR> <TID: 0000000336>...     --> Passed -- perform actions

 

Oops - no timestamp on some FLTR lines!  These variations will start to crop up more frequently as we dig deeper into the details of the different log formats.  Of course it's unavoidable at some point as the different log types are recording fundamentally different information.  We can usually handle this by building filters for specific log types but, in this case, we're just going to ignore it for the moment.  If you're collecting FLTR logs you'll have to accept that some of them won't have a Remedy generated timestamp.  The net effect of this is that it won't be possible to display all the lines in the correct sequence in Kibana if sorting by this timestamp as all of the records without it will be out of sequence.  In most cases the system @timestamp should be a good enough alternative.  There's a similar problem for lines logged with identical timestamps.  There's no guarantee which order they will be displayed when sorted on matching values so, for example, you may notice the occasional SQL OK before a SELECT.

 

We need a grok pattern to match our Remedy ICU format timestamp of EEE MMM d yyyy HH:mm:ss:SSSS. Unfortunately there isn't a standard one available so we need to define a custom pattern as detailed in the docs.   Using the grok debugger we can build a pattern to create a field called remedy_timestamp:

 

As not all of our log lines have the timestamp present we can't just add our new pattern to the existing filter.  The grok only works if the line matches the pattern so lines without this data would not be parsed into our extra data fields.  We need a second grok in the filter {...} block of our logstash.conf:

 

filter {

  grok {

    match => {"message" => "^<%{WORD:log_type}%{SPACE}> <TID: %{DATA:tid}> <RPC ID: %{DATA:rpc_id}> <Queue: %{DATA:rpc_queue}%{SPACE}\> <Client-RPC: %{DATA:client_rpc}%{SPACE}> <USER: %{DATA:user}%{SPACE}> <Overlay-Group: %{NUMBER:overlay_group:}%{SPACE}>%{SPACE}%{GREEDYDATA:log_details}$"}

  }

 

  grok {

    match => {"log_details" => "^/\* (?<remedy_timestamp>%{DAY} %{MONTH} %{MONTHDAY} %{YEAR} %{TIME}) \*/%{SPACE}%{GREEDYDATA:log_details}"}

    overwrite => ["log_details"]

  }

}

 

This new filter searches the log_details field, looking for /* at the start of the line (note that we have to escape the asterisk as it's a recognised regex character), and the parses the timestamp before assigning the remainder of the line back to log_details.  The second line uses the grok overwrite option otherwise the field would be turned into an array containing both the old and the new strings.

 

We have the timestamp but it's not in the correct format because the time is specified to four decimal places and Elasticsearch uses three. It's time to introduce a couple of new filter plugins.

 

mutate the date

The mutate plugin has a range of features to modify data in fields and we can use one of these, gsub, to remove the last digit from the string:

 

  mutate { # remove the last digit so we're left with milliseconds

    gsub => ["remedy_timestamp", "\d{1}$", ""]

  }

 

This will turn "Tue Jul 31 2018 11:21:39.8570" into "Tue Jul 31 2018 11:21:39.857".  Now we use the date plugin to convert this to the Elasticsearch timestamp format:

 

  date {

    match => ["remedy_timestamp", "EEE MMM dd yyyy HH:mm:ss.SSS"]

    target => "remedy_timestamp"

  }

 

After adding both of these below our new grok, restart the Logstash container..

 

# docker-compose -f elk.yml restart logstash

Restarting logstash ... done

 

and take a look at the logs in Kibana to see the new field.  Remember that we need to refresh the index pattern so that it is recognised correctly:

 

before refresh

 

and after

 

 

Further API Log Parsing

We're now adding extra fields to our Elasticsearch index for all of the common log markers up to, and including, the timestamp.   For API type logs this is the type of information that's left in log_details after this parsing:

 

+GLEWF ARGetListEntryWithFields -- schema AR System Configuration Component from Approval Server (protocol 26) at IP address 10.133.181.82 using RPC // :q:0.0s

-GLEWF OK

 

We're going to build add some new grok patterns to get the following

  • API call name
  • schema or form being used
  • client type
  • client protocol
  • client IP address
  • client transport
  • API queue time

 

Remember that we may be handling more than just API log lines though. We don't want to try and parse SQL or FLTR lines with an API specific regex as it won't match and would just be a waste of CPU cycles.  We can use conditional clauses to help streamline the code in our filter {...} block.  The following filters are only run if the log_type is API and they get the type of call along with adding a tag to mark the line as the start or end of an API:

 

if [log_type] == "API" {

 

  grok { # Mark the start of an API

    match => ["log_details", "^\+%{WORD:api_call}"]

    add_tag => ["API_Start"]

  }

 

  grok { # Mark the end of an API

    match => ["log_details", "^\-%{WORD:api_call}"]

    add_tag => ["API_End"]

  }

 

}

 

With the start and end tags we can now go mining for all the other nuggets using the set of filters below.  They're broken down into multiple filters because the exact format of the line varies by the API call.  For example, a GSI call does not have a form or schema recorded and some internal calls are missing the :q: value, so we need separate filters otherwise the pattern wouldn't match and nothing would be gathered.

 

if "API_Start" in [tags] {

 

  grok { # Specific to +API entries we get the client details

    match => ["log_details", " from %{DATA:client_type} \(protocol %{DATA:protocol}\)"]

  }

 

  grok { # and schema/form

          match => ["log_details", " \-\- (schema|form) %{DATA:form} (from|entry|fieldId|changed|# of)"]

  }

 

  grok { # client IP

    match => ["log_details", " at IP address %{IP:client_ip}"]

  }

 

  grok { # the API transport

    match => ["log_details", " using %{WORD:api_transport} \/\/"]

  }

 

  grok { # the API queue time

    match => ["log_details", "\/\/ :q:%{NUMBER:api_qtime:float}s"]

  }

 

}

 

The queue time filter shows how to set the type of a field in Elasticsearch as the default is text and automatic detection of numbers doesn't always work reliably.

 

Our final filter handles the API end lines and captures errors if they're present.

 

if "API_End" in [tags] {

 

  grok { # catch failing API and the related error

    match => ["log_details", "^\-%{DATA}-- AR Error\(%{DATA:arerror_number}\)%{SPACE}%{GREEDYDATA:arerror_message}$"]

  }

 

}

 

Our updated logstash.conf file is now a bit big to display in full so it's attached at the end of this post.  Once we've restarted Logstash and refreshed the index pattern we can now see all the additional fields in Kibana:

 

Wrapping Up

That's it for this post.  I had planned on showing some visualizations using our new fields but i think this is long enough for now!   I hope these posts have given you a good idea of the type of data it's possible to extract from Remedy logs,  and provided enough detail to help you get started if you want to give it a go yourself.  There are many ways to extend what we've done so far, for example you could:

 

  • Write filters to parse other log types or look at other plugins to see what they could do.
  • Break down SQL logs by the type of command being run and the table being used?
  • The full text indexer logs record the number of records in the ft_pending table that could be used to watch for a backlog developing.
  • There are plugins that you can use to calculate elapsed time between events - how long are your CreateEntry API calls taking?

 

I'm sure there are many other use cases you could think of.

 

As always questions and feedback or all sorts is welcome.  Happy grok'ing!

 

Mark Walters

 

Using the Elastic Stack with Remedy Logs - Part 1

Using the Elastic Stack with Remedy Logs - Part 2

Using the Elastic Stack with Remedy Logs - Part 3