Messages from logstash taking long time to appear in search

Elastic Stack Elasticsearch
1

Hi all,

I'm fairly new to ELK and I suspect this is an easy question for someone who knows ES well.

I am building a CI acceptance test pipeline in Serverspec to validate my Puppet ELK builds. The most important test of all for me is to prove that a message sent from logger to the /var/log/messages file finds its way through the shipper->redis->indexer pipeline and can be found via the ES search API within a reasonable time.

Unfortunately the messages are sometimes taking up to 15 minutes to appear.

My Serverspec code is:

describe 'end to end test' do
  it 'a message sent by logger is found in ES search' do

    shell 'logger -f /var/log/messages glueball'
    sleep 120
    shell "curl -XPOST 'localhost:9200/logstash-*/_refresh'" # see below for others I tried here 
    shell "curl 'localhost:9200/logstash-*/_search?pretty' -d '{\"query\":{\"match\":{\"message\":\"glueball\"}}}'" do |r|
      expect(r.stdout).to match /glueball/
    end
  end
end

I have tried various commands (most out of desperation) to force ES to be updated immediately but nothing seems to cause the message to instantly appear:

 8  curl -XPOST 'localhost:9200/logstash-*/_refresh'
 9  curl -XPOST 'localhost:9200/logstash-*/_flush'
10  curl -XPOST 'localhost:9200/logstash-*/_flush?wait_if_ongoing'
11  curl -XPOST 'localhost:9200/logstash-*/_flush?force'

Strangely, one thing that does seem to work is to send a second message via logger. The first message usually appears within a few seconds after that, as if it somehow dislodges the most recent message that is "stuck"!

Any help most appreciated.

2

It seems I'm wrong. It's actually the logstash indexer that seems to be holding the messages.

3

How I debugged this:

I was sending a message using:

# logger -f /var/log/messages glueball

There was no delay until the message reaches the Indexer. I could view the Redis queue with redis-cli monitor. In the redis queue I would see the queue updated with LPUSH and then the message immediately removed again with the a BLPOP.

Note I had the following Redis output for Logstash-shipper:

output {
  redis {
    data_type => "list"
    key => "logstash"
  }
}

And Redis input for Logstash-indexer:

input {
  redis {
    data_type => "list"
    key       => "logstash"
    codec     => "json"
  }
}

At the same time a message like the following appears in the indexer's debug output (I added the newlines for readability):

{
  :timestamp=>"2016-01-26T12:41:48.593000+1000",
  :message=>"Jan 26 02:41:46 centos-66-x64 vagrant: glueball",
  :pattern=>"(^\\s+at .+)|(^\\s+... \\d+ more)|(^\\s*Caused by:.+)",
  :match=>false,
  :negate=>false,
  :level=>:debug,
  :file=>"logstash/filters/multiline.rb",
  :line=>"154"
}

Then 100K more of related metadata followed that I can't post here.

Without getting to the bottom of exactly what in the filters was causing the delay, I found that by simply deleting all of them and restarting Indexer the messages moved straight to ES.

4

Do you have any multiline codec or filter in your configuration?

5

Yes, I did have multiline codecs and I suspect they related somehow to the delays. Didn't get to the bottom of exactly how or why.