Падает Logstash

Elastic In Your Native Tongue Вопросы на русском языке
1

Проблема номер один

Собственно, периодически падает Logstash, при смерти в лог выдает:
[2017-09-25T07:28:01,929][FATAL][logstash.runner ] An unexpected error occurred! {:error=>java.lang.NullPointerException, :backtrace=>["org.logstash.ackedqueue.Queue.lambda$getPersistedByteSize$0(Queue.java:145)", "java.util.stream.ReferencePipeline$5$1.accept(ReferencePipeline.java:227)", "java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1374)", "java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)", "java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)", "java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)", "java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)", "java.util.stream.LongPipeline.reduce(LongPipeline.java:438)", "java.util.stream.LongPipeline.sum(LongPipeline.java:396)", Часть лога сокращена "org.logstash.ackedqueue.Queue.getPersistedByteSize(Queue.java:145)", "org.logstash.ackedqueue.ext.JrubyAckedQueueExtLibrary$RubyAckedQueue.ruby_persisted_size_in_bytes(JrubyAckedQueueExtLibrary.java:109)", "org.logstash.ackedqueue.ext.JrubyAckedQueueExtLibrary$RubyAckedQueue$INVOKER$i$0$0$ruby_persisted_size_in_bytes.call(JrubyAckedQueueExtLibrary$RubyAckedQueue$INVOKER$i$0$0$ruby_persisted_size_in_bytes.gen)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:306)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:136)", "org.jruby.ast.CallNoArgNode.interpret(CallNoArgNode.java:60)", "org.jruby.ast.CallTwoArgNode.interpret(CallTwoArgNode.java:59)", "org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)", "org.jruby.ast.BlockNode.interpret(BlockNode.java:71)", "org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)", "org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206)", "org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:157)", .... .... , "org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:145)", "org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:154)", "org.jruby.ast.CallNoArgBlockNode.interpret(CallNoArgBlockNode.java:64)", "org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)", "org.jruby.ast.BlockNode.interpret(BlockNode.java:71)", "org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)", "org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:139)", "org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:187)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:306)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:136)", "org.jruby.ast.VCallNode.interpret(VCallNode.java:88)", "org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)", "org.jruby.ast.BlockNode.interpret(BlockNode.java:71)", "org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)", "org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:139)", "org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:187)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:306)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:136)", "org.jruby.ast.CallNoArgNode.interpret(CallNoArgNode.java:60)", "org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)", "org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)", "org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206)", "org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:194)", "org.jruby.runtime.Interpreted19Block.call(Interpreted19Block.java:125)", "org.jruby.runtime.Block.call(Block.java:101)", "org.jruby.RubyProc.call(RubyProc.java:300)", "org.jruby.RubyProc.call19(RubyProc.java:281)", "org.jruby.RubyProc$INVOKER$i$0$0$call19.call(RubyProc$INVOKER$i$0$0$call19.gen)", "org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:202)", "org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:198)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:306)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:136)", "org.jruby.ast.CallSpecialArgNode.interpret(CallSpecialArgNode.java:65)", "org.jruby.ast.DAsgnNode.interpret(DAsgnNode.java:110)", "org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)", "org.jruby.ast.BlockNode.interpret(BlockNode.java:71)", "org.jruby.ast.RescueNode.executeBody(RescueNode.java:221)", "org.jruby.ast.RescueNode.interpret(RescueNode.java:116)", "org.jruby.ast.BeginNode.interpret(BeginNode.java:83)", "org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)", "org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)", "org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206)", "org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:194)", "org.jruby.runtime.Interpreted19Block.call(Interpreted19Block.java:125)", "org.jruby.runtime.Block.call(Block.java:101)", "org.jruby.RubyProc.call(RubyProc.java:300)", "org.jruby.RubyProc.call(RubyProc.java:230)", "org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:103)", "java.lang.Thread.run(Thread.java:748)"]}
в конфигурации используется persisted.queue, для повторного запуска сервиса приходится очищать очередь, что ведет к потере данных. Подскажите что можно сделать, дабы избавится от сего неприятного события?

Проблема номер два:

Периодически от файлбита на логстэш приходят большие строки (более 5000 символов) от дебага, и опять-таки периодически Логстэш подвисает на их обработке, в логе пусто, при этом апи логстэша отвечает, из-за чего образуется очередь. Лечится перезапуском сервиса.

2

Может, какой нибудь regex зависает, пытаясь эти большие строки распрасить?

A это какая версия logstash?

3

logstash 5.5.2

проводимые логстэшем операции:

# Get rid of color codes
    mutate {
    gsub => ["message", "\x1B\[([0-9]{1,2}(;[0-9]{1,2})?)?[m|K]", ""]
    }
    grok {
    match => { "message" => "^(?:(?:.*?\|)){3}(?<hyb_datetime_string>.*?)\|(?<log_message>.*)$" }
    }

if [message] =~ /(?:(?:.*?\|)){4}\s(>>)?(\tat\s.+|\t...\s\d+\smore|Caused\sby:\s.+)/ {
    mutate {
    gsub => ["log_message", "(?:(?:.*?\|)){4}", ""]
    add_tag => ["javastacktrace"]
    }
}
# cutting datetime from splitted xml message
if [message] =~ /(\&lt\;p\&gt\;.{10,}\&lt\;\/p\&gt\;)/ {
    mutate {
    gsub => ["log_message", "(?:(?:.*?\|)){4}", ""]
    add_tag => ["xmlmessage"]
    }
}
# DMS monitoring for PERF envs
if [type] == "cluster-hybris" and [message] =~ ".*Time\-DmsService.*" {
    grok {
    match => [ "log_message", "^.*MagicDmsGroupKey\-%{INT:dms_group_key:int}.*Time\-DmsService\s*\(%{GREEDYDATA:dms_uri}\)\s*\:%{INT:duration:int}.*$" ]
    }
}

# remove trailing spaces
    mutate {
    strip => "hyb_datetime_string"
    }
# matching of hybris datetime string
    date {
    match => [ "hyb_datetime_string" , "yyyy/MM/dd HH:mm:ss.SSS" ]
    timezone => "Etc/GMT"
    }

    mutate {
    remove_field => [ "file" ]
    remove_field => [ "offset" ]
    remove_field => [ "message" ]
    remove_field => [ "hyb_datetime_string" ]
    }
}
4

Попробуйте прогнать строку, которая вызывает проблему, на отдельно-стоящем logstash-е и попробуйте определить какое выражение застревает, заменяя их по очереди на что-нибудь тривиальное. Мне, на вскидку, не видя этой строки сказать сложно что именно заедает.

Что касается первой проблемы, вы не могли бы полный лог прислать, и содержимое директории с очередью (ls -la) сразу после крушения.

5

Переговорил с разработчиками logstash. Они считают, что крушение вызвано вот этим багом - https://github.com/elastic/logstash/pull/8317 Должны исправить в следующей версии.

6

Спасибо. Я правильно понимаю, что пока баг не пофикшен лучше переключить очередь на memory?
Сейчас сделаю отдельный инстанс с Логстэшем для проблемных логов, и постараюсь в ближайшее время дополнить материалы

7

Да, можно и так сделать, но при этом вы теряете персистентность. Кстати, такой вопрос, вы в первом посте написали:

Почему вам приходиться чистить очередь? Что происходит если вы ее не чистите? Если ошибки - то можно на этот лог тоже посмотреть?

8

С утра проблем не обнаружено.

По вышеописаной просьбе на одном из инстов восстанавливаю "плохую" очередь за 21.09

logstash]# mv queue queue_27.09
logstash]# mv queue_21.09 queue

logstash]# service logstash start
Redirecting to /bin/systemctl start  logstash.service
logstash]# tail -f /var/log/logstash/logstash-plain.log

и он обрабатывет несколько событий и виснет
в логе: logstash-plain.log

по апи отвечает:

/usr/bin/curl -s  -XGET ''$IP':9600/_node/stats/pipeline?pretty'  | grep -A8  \"queue\"
        "queue" : {
          "events" : 1091308,
          "type" : "persisted",
          "capacity" : {
            "queue_size_in_bytes" : 1104390167,
            "page_capacity_in_bytes" : 1073741824,
            "max_queue_size_in_bytes" : 53687091200,
            "max_unread_events" : 0
          },

API HTTP Request {:status=>200, :request_method=>"GET", :path_info=>"/_node/stats/jvm", :query_string=>"pretty", :http_version=>"HTTP/1.1", :http_accept=>"/"}

  • это обращения от zabbix-agent'a

содержимое очереди:

queue]# ls -l
total 1080432
-rw-r--r--. 1 logstash logstash         34 Sep 21 06:27 checkpoint.0
-rw-r--r--. 1 logstash logstash         34 Sep 21 06:41 checkpoint.1
-rw-r--r--. 1 logstash logstash         34 Sep 21 06:50 checkpoint.2
-rw-r--r--. 1 logstash logstash         34 Sep 27 05:57 checkpoint.3
-rw-r--r--. 1 logstash logstash         34 Sep 27 06:10 checkpoint.head
-rw-r--r--. 1 logstash logstash 1073741824 Sep 21 06:26 page.0
-rw-r--r--. 1 logstash logstash 1073741824 Sep 21 06:39 page.1
-rw-r--r--. 1 logstash logstash 1073741824 Sep 21 06:48 page.2
-rw-r--r--. 1 logstash logstash 1073741824 Sep 21 07:39 page.3
-rw-r--r--. 1 logstash logstash 1073741824 Sep 27 06:11 page.4
9

Что касается "падающего" с ошибкой:
Опять-таки восстанавливаю "плохую" очередь, запускаю:
получаю: error2.log
Содержимое очереди:

queue]# cd main/
main]# ls -l
total 4872316
-rw-r--r--. 1 logstash logstash         34 Sep 19 16:12 checkpoint.58
-rw-r--r--. 1 logstash logstash         34 Sep 18 10:13 checkpoint.59
-rw-r--r--. 1 logstash logstash         34 Sep 18 12:31 checkpoint.60
-rw-r--r--. 1 logstash logstash         34 Sep 18 14:56 checkpoint.61
-rw-r--r--. 1 logstash logstash         34 Sep 18 17:17 checkpoint.62
-rw-r--r--. 1 logstash logstash         34 Sep 19 08:44 checkpoint.63
-rw-r--r--. 1 logstash logstash         34 Sep 19 11:00 checkpoint.64
-rw-r--r--. 1 logstash logstash         34 Sep 19 13:18 checkpoint.65
-rw-r--r--. 1 logstash logstash         34 Sep 19 14:35 checkpoint.66
-rw-r--r--. 1 logstash logstash         34 Sep 18 11:41 checkpoint.67
-rw-r--r--. 1 logstash logstash         34 Sep 19 11:57 checkpoint.68
-rw-r--r--. 1 logstash logstash         34 Sep 19 16:10 checkpoint.69
-rw-r--r--. 1 logstash logstash         34 Sep 27 06:23 checkpoint.head
-rw-r--r--. 1 logstash logstash 1073741824 Sep 15 18:07 page.58
-rw-r--r--. 1 logstash logstash 1073741824 Sep 17 03:07 page.66
-rw-r--r--. 1 logstash logstash 1073741824 Sep 18 11:41 page.67
-rw-r--r--. 1 logstash logstash 1073741824 Sep 19 11:57 page.68
-rw-r--r--. 1 logstash logstash 1073741824 Sep 19 16:07 page.69
-rw-r--r--. 1 logstash logstash 1073741824 Sep 19 16:10 page.70
10

Ну с падающим случаем, вроде все понятно - это этот самый баг. А с подвисающим случаем, вы не могли бы запустить jstack и прислать thread dump для logstash-а, когда он висит?

11

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