Logstash pipeline error date

Jozziej · January 18, 2019, 1:29pm

I'm trying to parse an error log, but my date filter keeps failing

example log entry:

Wed Nov 28 02:16:24.654 [MCSS:7497:0x7F17018E7700]: Warning: invalid cid (-1) in Msg::receive for unknown ip, with msg id (0x2b0300)

The date I want to put in @Timestamp
and if that works i want the text in the this field [MCSS:7497:0x7F17018E7700]: to be filtered as useless

Below is my configuration

input {
file {
path => "C:/cygwin64/home/Logstashfiles/IAC/iqs.log"
type => "iqs.log"
start_position => "beginning"
}
}
filter {
grok {
match => { "message" => "%{TIMESTAMP:timestamp} %{GREEDYDATA:useless} %{GREEDYDATA:message}" }
}
date {
match => [ "timestamp" , "EEE MMM dd HH:mm:ss.SSS" ] }
}
output {
stdout {}
}

Below is the error from the Logstash logs

[2019-01-18T14:27:56,740][INFO ][logstash.pipeline ] Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>4, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50}
[2019-01-18T14:27:57,019][ERROR][logstash.pipeline ] Error registering plugin {:pipeline_id=>"main", :plugin=>"#<LogStash::FilterDelegator:0x1db0ddad @metric_events_out=org.jruby.proxy.org.logstash.instrument.metrics.counter.LongCounter$Proxy2 - name: out value:0, @metric_events_in=org.jruby.proxy.org.logstash.instrument.metrics.counter.LongCounter$Proxy2 - name: in value:0, @metric_events_time=org.jruby.proxy.org.logstash.instrument.metrics.counter.LongCounter$Proxy2 - name: duration_in_millis value:0, @id="c04f67adb828c4c42d8d6592d98b10597fb883c99f12c642fc64df949a440c61", @klass=LogStash::Filters::Grok, @metric_events=#LogStash::Instrument::NamespacedMetric:0xbecbfda, @filter=<LogStash::Filters::Grok match=>{"message"=>"%{TIMESTAMP:timestamp} %{GREEDYDATA:useless} %{GREEDYDATA:message}"}, id=>"c04f67adb828c4c42d8d6592d98b10597fb883c99f12c642fc64df949a440c61", enable_metric=>true, periodic_flush=>false, patterns_files_glob=>"*", break_on_match=>true, named_captures_only=>true, keep_empty_captures=>false, tag_on_failure=>["_grokparsefailure"], timeout_millis=>30000, tag_on_timeout=>"_groktimeout">>", :error=>"pattern %{TIMESTAMP:timestamp} not defined", :thread=>"#<Thread:0x2f64e4d1 run>"}
[2019-01-18T14:27:57,029][ERROR][logstash.pipeline ] Pipeline aborted due to error {:pipeline_id=>"main", :exception=>#<Grok::PatternError: pattern %{TIMESTAMP:timestamp} not defined>, :backtrace=>["C:/ELK/logstash-6.5.4/vendor/bundle/jruby/2.3.0/gems/jls-grok-0.11.5/lib/grok-pure.rb:123:in block in compile'", "org/jruby/RubyKernel.java:1292:inloop'", "C:/ELK/logstash-6.5.4/vendor/bundle/jruby/2.3.0/gems/jls-grok-0.11.5/lib/grok-pure.rb:93:in compile'", "C:/ELK/logstash-6.5.4/vendor/bundle/jruby/2.3.0/gems/logstash-filter-grok-4.0.4/lib/logstash/filters/grok.rb:281:inblock in register'", "org/jruby/RubyArray.java:1734:in each'", "C:/ELK/logstash-6.5.4/vendor/bundle/jruby/2.3.0/gems/logstash-filter-grok-4.0.4/lib/logstash/filters/grok.rb:275:inblock in register'", "org/jruby/RubyHash.java:1343:in each'", "C:/ELK/logstash-6.5.4/vendor/bundle/jruby/2.3.0/gems/logstash-filter-grok-4.0.4/lib/logstash/filters/grok.rb:270:inregister'", "C:/ELK/logstash-6.5.4/logstash-core/lib/logstash/pipeline.rb:242:in register_plugin'", "C:/ELK/logstash-6.5.4/logstash-core/lib/logstash/pipeline.rb:253:inblock in register_plugins'", "org/jruby/RubyArray.java:1734:in each'", "C:/ELK/logstash-6.5.4/logstash-core/lib/logstash/pipeline.rb:253:inregister_plugins'", "C:/ELK/logstash-6.5.4/logstash-core/lib/logstash/pipeline.rb:595:in maybe_setup_out_plugins'", "C:/ELK/logstash-6.5.4/logstash-core/lib/logstash/pipeline.rb:263:instart_workers'", "C:/ELK/logstash-6.5.4/logstash-core/lib/logstash/pipeline.rb:200:in run'", "C:/ELK/logstash-6.5.4/logstash-core/lib/logstash/pipeline.rb:160:inblock in start'"], :thread=>"#<Thread:0x2f64e4d1 run>"}
[2019-01-18T14:27:57,058][ERROR][logstash.agent ] Failed to execute action {:id=>:main, :action_type=>LogStash::ConvergeResult::FailedAction, :message=>"Could not execute action: PipelineAction::Create, action_result: false", :backtrace=>nil}
[2019-01-18T14:27:57,519][INFO ][logstash.agent ] Successfully started Logstash API endpoint {:port=>9600}

Badger · January 18, 2019, 3:11pm

There is no pattern called TIMESTAMP unless you define it.

Personally I would use dissect instead of grok

dissect { mapping => { "message" => "%{ts} %{+ts} %{+ts} %{+ts} [%{}]: %{msg}" } }

guyboertje · January 18, 2019, 3:18pm

It is not the date filter that is failing, it is the grok filter.

[2019-01-18T14:27:57,029][ERROR][logstash.pipeline ] Pipeline aborted due to error {:pipeline_id=>"main", :exception=>#<Grok::PatternError: pattern %{TIMESTAMP:timestamp} not defined>

Your date does not match any predefined formats

This one comes close:
DATESTAMP_OTHER %{DAY} %{MONTH} %{MONTHDAY} %{TIME} %{TZ} %{YEAR}
but it will not work out of the box.

You will have to define you own pattern.

The grok filter has a setting pattern_definitions. NOTE in the example below I also changed the first GREEDYDATA to NOTSPACE as you are wanting to skip all until the next space char. It is not advisable to use more that one GREEDYDATA.

grok {
  pattern_definitions => { "DATESTAMP_IQS" => "%{DAY} %{MONTH} %{MONTHDAY} %{TIME}" }
  match => { "message" => "%{DATESTAMP_IQS:timestamp} %{NOTSPACE:useless} %{GREEDYDATA:message}" }

Jozziej · January 18, 2019, 3:43pm

Hi guyboertje thanks for your reply

The parsing still doesn't work correctly

this is the logstash-plain.log

[2019-01-18T16:34:37,288][WARN ][logstash.config.source.multilocal] Ignoring the 'pipelines.yml' file because modules or command line options are specified
[2019-01-18T16:34:37,312][INFO ][logstash.runner ] Starting Logstash {"logstash.version"=>"6.5.4"}
[2019-01-18T16:34:45,169][INFO ][logstash.pipeline ] Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>4, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50}
[2019-01-18T16:34:46,060][INFO ][logstash.inputs.file ] No sincedb_path set, generating one based on the "path" setting {:sincedb_path=>"C:/ELK/logstash-6.5.4/data/plugins/inputs/file/.sincedb_40647c5112ef4dde3c411f57a7d3d556", :path=>["C:/cygwin64/home/Logstashfiles/IAC/iqs.log"]}
[2019-01-18T16:34:46,119][INFO ][logstash.pipeline ] Pipeline started successfully {:pipeline_id=>"main", :thread=>"#<Thread:0x23a06ca6 run>"}
[2019-01-18T16:34:46,223][INFO ][logstash.agent ] Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>}
[2019-01-18T16:34:46,257][INFO ][filewatch.observingtail ] START, creating Discoverer, Watch with file and sincedb collections
[2019-01-18T16:34:46,806][INFO ][logstash.agent ] Successfully started Logstash API endpoint {:port=>9600}

See the image as result

Badger · January 18, 2019, 4:12pm

There are two spaces after the date.

match => { "message" => "%{DATESTAMP_IQS:timestamp}  %{NOTSPACE:useless} %{GREEDYDATA:message}" }

This is why it is helpful to use </> (in the toolbar above the edit panel) to blockquote things like logs, data, and configurations.

guyboertje · January 18, 2019, 4:14pm

Try the dissect option that @badger suggested.

Alternatively you can work systematically from left to right by extending the custom pattern.

grok {
  # pattern_definitions => { "DATESTAMP_IQS" => "%{DAY} %{MONTH} %{MONTHDAY} %{TIME}" }
  pattern_definitions => { "DATESTAMP_IQS" => "%{DAY}" }
  match => { "message" => "%{DATESTAMP_IQS:timestamp} %{GREEDYDATA:msg}" }
}

grok {
  # pattern_definitions => { "DATESTAMP_IQS" => "%{DAY} %{MONTH} %{MONTHDAY} %{TIME}" }
  pattern_definitions => { "DATESTAMP_IQS" => "%{DAY} %{MONTH}" }
  match => { "message" => "%{DATESTAMP_IQS:timestamp} %{GREEDYDATA:msg}" }
}

and so on.

Jozziej · January 18, 2019, 4:15pm

Hi Badger,

I used dissect now

dissect { mapping => { "message" => "%{timestamp} %{+timestamp} %{+timestamp} %{+timestamp} [%{}]: %{message}" } }

this works correctly for this error log as far as I can see

guyboertje · January 18, 2019, 4:15pm

The sample line posted in the original post has only one space

Jozziej · January 18, 2019, 4:18pm

Thanks you all!
It appears the Dissect works good enough:)

guyboertje · January 18, 2019, 4:22pm

Either way, whether you use grok or dissect, I encourage you to use the generator input.
You can add multiple variant lines in the lines array and retest changes really easily until your grok/dissect, date and other filters all work for each variant.

e.g.

input {
  generator {
    lines => [
      'Wed Nov 28 02:16:24.654  [MCSS:7497:0x7F17018E7700]: Warning: invalid cid (-1) in Msg::receive for unknown ip, with msg id (0x2b0300)',
      'Wed Nov 28 02:16:24.654 [MCSS:7497:0x7F17018E7700]: Warning: invalid cid (-1) in Msg::receive for unknown ip, with msg id (0x2b0300)'
    ]
    count => 1
  }
}

filter {
  grok {
    pattern_definitions => { "DATESTAMP_IQS" => "%{DAY} %{MONTH} %{MONTHDAY} %{TIME}" }
    match => {
      "message" => [
        '%{DATESTAMP_IQS:timestamp} +%{NOTSPACE:discard} %{GREEDYDATA:msg}'
      ]
    }
    break_on_match => true
  }
}

output {
  stdout {
    codec => rubydebug
  }
}

Gives:

{
           "msg" => "Warning: invalid cid (-1) in Msg::receive for unknown ip, with msg id (0x2b0300)",
       "discard" => "[MCSS:7497:0x7F17018E7700]:",
      "sequence" => 0,
       "message" => "Wed Nov 28 02:16:24.654 [MCSS:7497:0x7F17018E7700]: Warning: invalid cid (-1) in Msg::receive for unknown ip, with msg id (0x2b0300)",
      "@version" => "1",
          "host" => "Elastics-MacBook-Pro.local",
    "@timestamp" => 2019-01-18T16:21:53.645Z,
     "timestamp" => "Wed Nov 28 02:16:24.654"
}
{
           "msg" => "Warning: invalid cid (-1) in Msg::receive for unknown ip, with msg id (0x2b0300)",
       "discard" => "[MCSS:7497:0x7F17018E7700]:",
      "sequence" => 0,
       "message" => "Wed Nov 28 02:16:24.654  [MCSS:7497:0x7F17018E7700]: Warning: invalid cid (-1) in Msg::receive for unknown ip, with msg id (0x2b0300)",
      "@version" => "1",
          "host" => "Elastics-MacBook-Pro.local",
    "@timestamp" => 2019-01-18T16:21:53.629Z,
     "timestamp" => "Wed Nov 28 02:16:24.654"
}

Jozziej · January 18, 2019, 4:42pm

Ah great the generator input helps speed up parsing my logs alot!

Do you recommend to put all my log files in the config as one pipeline?
will be around 15 logfiles which do not all have the same format.

Also some logfiles i tail with .log* because they store the older logs with .log.1 .log.2 .log.3 and so on

system · February 15, 2019, 4:42pm

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