Messages from logstash taking long time to appear in search

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/

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.

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

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):

  :message=>"Jan 26 02:41:46 centos-66-x64 vagrant: glueball",
  :pattern=>"(^\\s+at .+)|(^\\s+... \\d+ more)|(^\\s*Caused by:.+)",

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.

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

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.