Logstash 5.3 Persistent Queue issue

devsibwarra · April 4, 2017, 11:39pm

Versions

OS: Ubuntu 14.04.5 LTS
Filebeat 5.3.0 from https://artifacts.elastic.co/packages/5.x/apt/
Logstash 1:5.3.0-1 from https://artifacts.elastic.co/packages/5.x/apt/
Oracle Java(TM) SE Runtime Environment (build 1.8.0_121-b13)

Logstash Config

# grep -v '^#' /etc/logstash/logstash.yml
path:
  config: "/etc/logstash/conf.d"
queue:
  type: persisted
  max_bytes: 2gb

Issue
On initial persistent queue Logstash startup, the logs are queued and passed to the output target as expected. When attempting to restart logstash (sudo service logstash restart), it fails to load the queue files with the errors below

Logs

[2017-04-04T18:04:48,285][DEBUG][org.logstash.ackedqueue.Queue] opening tail page: 1, in: /usr/share/logstash/data/queue/main, with checkpoint: pageNum=1, firstUnackedPageNum=0, firstUnackedSeqNum=415520, minSeqNum=415520, elementCount=418519, isFullyAcked=no
[2017-04-04T18:04:48,357][ERROR][logstash.pipeline        ] Logstash failed to create queue {"exception"=>"Element seqNum 415583 is expected to be 415581", "backtrace"=>["org/logstash/ackedqueue/ext/JrubyAckedQueueExtLibrary.java:136:in `open'", "/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:40:in `with_queue'", "/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:29:in `create_file_based'", "/usr/share/logstash/logstash-core/lib/logstash/queue_factory.rb:30:in `create'", "/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:142:in `initialize'", "/usr/share/logstash/logstash-core/lib/logstash/agent.rb:277:in `create_pipeline'", "/usr/share/logstash/logstash-core/lib/logstash/agent.rb:95:in `register_pipeline'", "/usr/share/logstash/logstash-core/lib/logstash/runner.rb:264:in `execute'", "/usr/share/logstash/vendor/bundle/jruby/1.9/gems/clamp-0.6.5/lib/clamp/command.rb:67:in `run'", "/usr/share/logstash/logstash-core/lib/logstash/runner.rb:183:in `run'", "/usr/share/logstash/vendor/bundle/jruby/1.9/gems/clamp-0.6.5/lib/clamp/command.rb:132:in `run'", "/usr/share/logstash/lib/bootstrap/environment.rb:71:in `(root)'"]}
[2017-04-04T18:04:48,365][ERROR][logstash.agent           ] Cannot load an invalid configuration {:reason=>"Element seqNum 415583 is expected to be 415581", :backtrace=>["org/logstash/ackedqueue/ext/JrubyAckedQueueExtLibrary.java:136:in `open'", "/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:40:in `with_queue'", "/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:29:in `create_file_based'", "/usr/share/logstash/logstash-core/lib/logstash/queue_factory.rb:30:in `create'", "/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:142:in `initialize'", "/usr/share/logstash/logstash-core/lib/logstash/agent.rb:277:in `create_pipeline'", "/usr/share/logstash/logstash-core/lib/logstash/agent.rb:95:in `register_pipeline'", "/usr/share/logstash/logstash-core/lib/logstash/runner.rb:264:in `execute'", "/usr/share/logstash/vendor/bundle/jruby/1.9/gems/clamp-0.6.5/lib/clamp/command.rb:67:in `run'", "/usr/share/logstash/logstash-core/lib/logstash/runner.rb:183:in `run'", "/usr/share/logstash/vendor/bundle/jruby/1.9/gems/clamp-0.6.5/lib/clamp/command.rb:132:in `run'", "/usr/share/logstash/lib/bootstrap/environment.rb:71:in `(root)'"]}

AuroraBorealis · April 5, 2017, 8:03am

I am having the same problem (same OS and Logstash versions).

[2017-04-04T15:45:46,176][ERROR][logstash.pipeline        ] Logstash failed to create queue {"exception"=>"Element seqNum 330813 is expected to be 330812", "backtrace"=>["org/logstash/ackedqueue/ext/JrubyAckedQueueExtLibrary.java:136:in `open'", "/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:40:in `with_queue'", "/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:29:in `create_file_based'", "/usr/share/logstash/logstash-core/lib/logstash/queue_factory.rb:30:in `create'", "/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:142:in `initialize'", "/usr/share/logstash/logstash-core/lib/logstash/agent.rb:277:in `create_pipeline'", "/usr/share/logstash/logstash-core/lib/logstash/agent.rb:95:in `register_pipeline'", "/usr/share/logstash/logstash-core/lib/logstash/runner.rb:264:in `execute'", "/usr/share/logstash/vendor/bundle/jruby/1.9/gems/clamp-0.6.5/lib/clamp/command.rb:67:in `run'", "/usr/share/logstash/logstash-core/lib/logstash/runner.rb:183:in `run'", "/usr/share/logstash/vendor/bundle/jruby/1.9/gems/clamp-0.6.5/lib/clamp/command.rb:132:in `run'", "/usr/share/logstash/lib/bootstrap/environment.rb:71:in `(root)'"]}
[2017-04-04T15:45:46,181][ERROR][logstash.agent           ] Cannot load an invalid configuration {:reason=>"Element seqNum 330813 is expected to be 330812"}

Timo_Friedl · April 5, 2017, 9:35am

I have the exact same issue:

[2017-04-05T09:20:00,149][ERROR][logstash.pipeline        ] Logstash failed to create queue {"exception"=>"Element seqNum 1 is expected to be 8", "backtrace"=>["org/logstash/ackedqueue/ext/JrubyAckedQueueExtLibrary.java:136:in `open'", "/opt/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:40:in `with_queue'", "/opt/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:29:in `create_file_based'", "/opt/logstash/logstash-core/lib/logstash/queue_factory.rb:30:in `create'", "/opt/logstash/logstash-core/lib/logstash/pipeline.rb:142:in `initialize'", "/opt/logstash/logstash-core/lib/logstash/agent.rb:277:in `create_pipeline'", "/opt/logstash/logstash-core/lib/logstash/agent.rb:95:in `register_pipeline'", "/opt/logstash/logstash-core/lib/logstash/runner.rb:264:in `execute'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/clamp-0.6.5/lib/clamp/command.rb:67:in `run'", "/opt/logstash/logstash-core/lib/logstash/runner.rb:183:in `run'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/clamp-0.6.5/lib/clamp/command.rb:132:in `run'", "/opt/logstash/lib/bootstrap/environment.rb:71:in `(root)'"]}
[2017-04-05T09:20:00,155][ERROR][logstash.agent           ] Cannot load an invalid configuration {:reason=>"Element seqNum 1 is expected to be 8"}

I followed the migration guide from 5.2.0 to 5.3.0 and I also tried with a fresh/empty queue folder. Restart of logstash produces the above error.

guyboertje · April 5, 2017, 11:30am

@devsibwarra, @AuroraBorealis, @Timo_Friedl
Can you post the inputs section of your config here please.

AuroraBorealis · April 5, 2017, 11:41am

My input section (in /etc/logstash/conf.d/logstash-xxx.conf.yml) looks as follows:

input {
    beats {
        id => "beats-input"
        port => 5044
    }

    redis {
        id => "redis-abcd999-filebeat"
        host => "abcd999"
        data_type => "list"
        key => "filebeat"
    }

    redis {
        id => "redis-abcd999-packetbeat"
        host => "abcd999"
        data_type => "list"
        key => "packetbeat"
    }
}

The main Logstash config file contains:

# grep -v '^#' /etc/logstash/logstash.yml

path.data: /MB/Mon/logstash-data
path.config: /etc/logstash/conf.d
queue.type: persistent
path.queue: /MB/Mon/logstash-data/queue
path.logs: /var/log/logstash

guyboertje · April 5, 2017, 11:53am

I think this is a bug.
We thought the write side of the PQ was thread safe but its not.
A different bug with the same cause.

I am working on a fix as we speak.

@AuroraBorealis in your case the work around, if still want to use the PQ, is to split the config across two LS instances.
LS 1: beats input with PQ
LS 2: redis inputs without the PQ (redis is already a queue, you gain nothing here - you're draining a stable redis into a experimental feature PQ)

AuroraBorealis · April 5, 2017, 1:35pm

Thank you for working on this and for your help!

For the moment, I changed the queue type back to "memory". When I configured it before, I did not think about that PQ are useless when Redis input is used.

devsibwarra · April 5, 2017, 2:22pm

@guyboertje

My input section in /etc/logstash/conf.d/logstash.conf is pretty simple

input {
	beats {
		port => "5044"
	}
}

Thanks for the bug links. Will follow those and try PQ again once a fix is available.

guyboertje · April 5, 2017, 2:26pm

@devsibwarra
Thanks for your config, I think the beats input uses a thread per connection. How many far side beats are talking to the beats input?

devsibwarra · April 5, 2017, 2:28pm

Right now I've got 7 filebeats pointing at this Logstash instance

guyboertje · April 5, 2017, 2:58pm

@devsibwarra that will do it. Best not to use the PQ until the fix is pushed. Monitor the logstash release release notes - look for fix on multithreaded write to PQ. I can't say if its 5.3.1 or 5.3.2 or 5.4.0

devsibwarra · April 5, 2017, 3:16pm

@guyboertje sounds good. Thanks for your assistance with this!

system · May 3, 2017, 3:16pm

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