Перемешиваются события между воркерами?

[11116 (Мишка Карташов)]

Здравствуйте!
Заметил такую странную вещь.
Логи ко мне прилетают, увы, в куче не очень совместимых форматов, например
1 вариант: param1|param2|field3:param3|field4:param4
2 вариант: param1|param2|4.3|param4|field5:param5|field6:param6
3 вариант: param1|param2|field7:param7|field8:param8
Сделал так :
//обрабатываю первые два поля, остаток складывается в поле fields
if [fields] =~ /^4|/{
//обрабатываются поля до param4, с разделителем |
}
//через kv обрабатываются остальные поля key:value

Так вот, на больших объемах (порядка 7-8 тысяч событий в секунду) периодически условие перестает работать - сообщения из первого или третьего варианта почему-то проваливаются в условие, в результате чего получается каша вида:
field1 = param1
field2 = param2
field3 = field3:param3
field4 = field4:param4
На что справедливо ругается elasticsearch - маппинг не сходится.

Ок, я взял кусок этой логики из конфига, скопировал ее в тестовый, вход с stdin, выход с stdout. Запустил, отправил эту строку - условие отработало правильно. Так же ошибка не появляется, если запускать логстэш с параметром -w 1
То есть, когда воркер один, условие срабатывает правильно.
Поля без имени с разделителем я разбираю своим простеньким плагином, если это важно:
https://pastebin.com/CXDHr7wZ

Аналогичные странности замечал, когда для своего плагина и kv задавал target и потом пытался смержить полученные поля - периодически они оказывались пустыми, хотя прогон через тест с stdin stdout проходил нормально.

• если запускаю с параметром debug, то выдается:

[FATAL] 2017-10-19 21:57:33.628 [LogStash::Runner] runner - An unexpected error occurred! {:error=>#<NoMethodError: undefined method to_hash' for []:Array>, :backtrace=>["(eval):18:infilter_func'", "/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:398:in filter_batch'", "/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:379:inworker_loop'", "/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:342:in `start_workers'"]}

Версия логстэша 5.6.3, OS Centos 7.4.1708

В какую сторону копать?
Спасибо!

[Igor_Motov]

Похоже на баг в logstash. В данный момент тут обссуждается. Где копать, пока не знаем.

[11116 (Мишка Карташов)]

Вот еще пример:

[2017-10-23T15:42:35,067][WARN ][logstash.outputs.elasticsearch] Could not index event to Elasticsearch. {:status=>400, :action=>["index", {:_id=>nil, :_index=>"logstash-2017.10.23-12", :_type=>"logstash", :_routing=>nil}, 2017-10-23T12:39:14.526Z 10.1.18.6 1508762354.523|31.173.240.159|4.3|A593FC83-7880-EB41-4130-0E78E07DF7CA||BCA26ABF-A641-13D8-F64A-77495DE79FD7|2|5||F|||101945472|||||M|8046||ADVXL:0|ADVPT:180|ADCLS:0], :response=>{"index"=>{"_index"=>"logstash-2017.10.23-12", "_type"=>"logstash", "_id"=>"AV9JQYKjLlYouzjYEQju", "status"=>400, "error"=>{"type"=>"mapper_parsing_exception", "reason"=>"failed to parse [N]", "caused_by"=>{"type"=>"number_format_exception", "reason"=>"For input string: "BRWSR:Mozilla/5.0 (SMART-TV; Linux; Tizen 2.3) AppleWebkit/538.1 (KHTML, like Gecko) SamsungBrowser/1.0 TV Safari/538.1""}}}}}

То есть, он в параметр N положил что-то вообще из другого сообщения, в этой строке UserAgent отсутствует:worried:

[Igor_Motov]

Поговорил со спецами по logstash. Похоже, что ошибка в debug и перемешивание событий между собой не связаны. Проблемы с перемешиванием скорее всего происходят от использования переменная экземпляра. Это ведь по сути ruby, и @var - это переменная экземпляра, который одновременно используется всеми воркерами. То есть все ваши воркеры пишут в одно и тоже время в одни и те же переменные. Самое простое решение - перейти на локальные переменные (отбросить @).

[11116 (Мишка Карташов)]

Да, похоже, дело было в этом. Спасибо большое!