Java crash when mutating to many fields?
Jinkxed opened this issue · 21 comments
- Version: Logstash 5.0.1 logstash-filter-mutate (3.1.3)
- Operating System: Amazon Linux
- Config File (if you have sensitive info, please remove it): Shown Below
- Sample Data:
- Steps to Reproduce:
Issue: Logstash stops processing any new events when I add to many mutate renames to the config file.
Error Message:
[2016-11-15T20:27:37,243][ERROR][logstash.pipeline ] dBlock19.yield(CompiledBlock19.java:135)", "org.jruby.runtime.Block.yield(Block.java:142)", "org.jruby.RubyHash$13.visit(RubyHash.java:1355)", "org.jruby.RubyHash.visitLimited(RubyHash.java:648)", "org.jruby.RubyHash.visitAll(RubyHash.java:634)", "org.jruby.RubyHash.iteratorVisitAll(RubyHash.java:1306)", "org.jruby.RubyHash.each_pairCommon(RubyHash.java:1351)", "org.jruby.RubyHash.each19(RubyHash.java:1342)", "org.jruby.RubyHash$INVOKER$i$0$0$each19.call(RubyHash$INVOKER$i$0$0$each19.gen)", "org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:143)", "org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:154)", "rubyjit.LogStash::Filters::Mutate$$rename_86877101c922e43dc1452c3c68bb09668ac4f2e91442407170.__file__(/usr/share/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-mutate-3.1.3/lib/logstash/filters/mutate.rb:222)", "rubyjit.LogStash::Filters::Mutate$$rename_86877101c922e43dc1452c3c68bb09668ac4f2e91442407170.__file__(/usr/share/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-mutate-3.1.3/lib/logstash/filters/mutate.rb)", "org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:181)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)", "rubyjit.LogStash::Filters::Mutate$$filter_7ece4ecf2c9d8324f6c4933fda087138f0104c701442407170.__file__(/usr/share/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-mutate-3.1.3/lib/logstash/filters/mutate.rb:203)", "rubyjit.LogStash::Filters::Mutate$$filter_7ece4ecf2c9d8324f6c4933fda087138f0104c701442407170.__file__(/usr/share/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-mutate-3.1.3/lib/logstash/filters/mutate.rb)", "org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:201)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:336)", "org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:179)", "org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:188)", "rubyjit.LogStash::Filters::Base$$multi_filter_1ee1ab11f89a1dea5c87673dc32bcc4de88a737f1442407170.block_0$RUBY$__file__(/usr/share/logstash/logstash-core/lib/logstash/filters/base.rb:156)", "rubyjit$LogStash::Filters::Base$$multi_filter_1ee1ab11f89a1dea5c87673dc32bcc4de88a737f1442407170$block_0$RUBY$__file__.call(rubyjit$LogStash::Filters::Base$$multi_filter_1ee1ab11f89a1dea5c87673dc32bcc4de88a737f1442407170$block_0$RUBY$__file__)", "org.jruby.runtime.CompiledBlock19.yield(CompiledBlock19.java:135)", "org.jruby.runtime.Block.yield(Block.java:142)", "org.jruby.RubyArray.eachCommon(RubyArray.java:1606)", "org.jruby.RubyArray.each(RubyArray.java:1613)", "org.jruby.RubyArray$INVOKER$i$0$0$each.call(RubyArray$INVOKER$i$0$0$each.gen)", "org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:143)", "org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:154)", "rubyjit.LogStash::Filters::Base$$multi_filter_1ee1ab11f89a1dea5c87673dc32bcc4de88a737f1442407170.__file__(/usr/share/logstash/logstash-core/lib/logstash/filters/base.rb:153)", "rubyjit.LogStash::Filters::Base$$multi_filter_1ee1ab11f89a1dea5c87673dc32bcc4de88a737f1442407170.__file__(/usr/share/logstash/logstash-core/lib/logstash/filters/base.rb)", "org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:181)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:170)", "rubyjit.LogStash::FilterDelegator$$multi_filter_87d312cb29252318f5ba9dfc74f2695ff3ca582a1442407170.__file__(/usr/share/logstash/logstash-core/lib/logstash/filter_delegator.rb:41)", "rubyjit.LogStash::FilterDelegator$$multi_filter_87d312cb29252318f5ba9dfc74f2695ff3ca582a1442407170.__file__(/usr/share/logstash/logstash-core/lib/logstash/filter_delegator.rb)", "org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:181)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)", "org.jruby.ast.CallOneArgNode.interpret(CallOneArgNode.java:57)", "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.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.internal.runtime.methods.ProcMethod.call(ProcMethod.java:64)", "org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:210)", "org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:206)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)", "org.jruby.ast.FCallOneArgNode.interpret(FCallOneArgNode.java:36)", "org.jruby.ast.CallNoArgBlockNode.interpret(CallNoArgBlockNode.java:60)", "org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)", "org.jruby.ast.IfNode.interpret(IfNode.java:116)", "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:210)", "org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:206)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)", "rubyjit.LogStash::Util::WrappedSynchronousQueue::ReadBatch$$each_cc57d8888498073a1852ab1bae0383dbea1b388e1442407170.block_0$RUBY$__file__(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb:186)", "rubyjit$LogStash::Util::WrappedSynchronousQueue::ReadBatch$$each_cc57d8888498073a1852ab1bae0383dbea1b388e1442407170$block_0$RUBY$__file__.call(rubyjit$LogStash::Util::WrappedSynchronousQueue::ReadBatch$$each_cc57d8888498073a1852ab1bae0383dbea1b388e1442407170$block_0$RUBY$__file__)", "org.jruby.runtime.CompiledBlock19.yield(CompiledBlock19.java:135)", "org.jruby.runtime.Block.yield(Block.java:142)", "org.jruby.RubyHash$13.visit(RubyHash.java:1355)", "org.jruby.RubyHash.visitLimited(RubyHash.java:648)", "org.jruby.RubyHash.visitAll(RubyHash.java:634)", "org.jruby.RubyHash.iteratorVisitAll(RubyHash.java:1306)", "org.jruby.RubyHash.each_pairCommon(RubyHash.java:1351)", "org.jruby.RubyHash.each19(RubyHash.java:1342)", "org.jruby.RubyHash$INVOKER$i$0$0$each19.call(RubyHash$INVOKER$i$0$0$each19.gen)", "org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:143)", "org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:154)", "rubyjit.LogStash::Util::WrappedSynchronousQueue::ReadBatch$$each_cc57d8888498073a1852ab1bae0383dbea1b388e1442407170.__file__(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb:185)", "rubyjit.LogStash::Util::WrappedSynchronousQueue::ReadBatch$$each_cc57d8888498073a1852ab1bae0383dbea1b388e1442407170.__file__(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb)", "org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:161)", "org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:143)", "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.ast.RescueNode.executeBody(RescueNode.java:221)", "org.jruby.ast.RescueNode.interpret(RescueNode.java:116)", "org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)", "org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:182)", "org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:203)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)", "org.jruby.ast.FCallOneArgNode.interpret(FCallOneArgNode.java:36)", "org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)", "org.jruby.ast.BlockNode.interpret(BlockNode.java:71)", "org.jruby.ast.WhileNode.interpret(WhileNode.java:131)", "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:225)", "org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:219)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:202)", "org.jruby.ast.FCallTwoArgNode.interpret(FCallTwoArgNode.java:38)", "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: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:99)", "java.lang.Thread.run(Thread.java:745)"]}
Note: I've tried this both adding a rename => for each line and as a giant single hash, issue still happens on both.
Example Config:
mutate {
rename => {
"content_channel" => "channel_id"
"[api_request][endpoint]" => "endpoint"
"[api_request][method]" => "method"
"[api_request][options][body][action]" => "action"
"[api_request][options][body][advocate_id]" => "advocate_id"
"[api_request][options][body][archived_at]" => "archived_at"
"[api_request][options][body][authenticity_token]" => "authenticity_token"
"[api_request][options][body][channel]" => "channel_id"
"[api_request][options][body][controller]" => "controller"
"[api_request][options][body][count]" => "count"
"[api_request][options][body][criterion_or]" => "criterion_or"
"[api_request][options][body][days]" => "days"
"[api_request][options][body][description]" => "description"
"[api_request][options][body][from]" => "from"
"[api_request][options][body][gallery_id]" => "gallery_id"
"[api_request][options][body][group_titles]" => "group_titles"
"[api_request][options][body][hours]" => "hours"
"[api_request][options][body][html]" => "html"
"[api_request][options][body][id]" => "external_content_source_id"
"[api_request][options][body][minutes]" => "minutes"
"[api_request][options][body][name]" => "name"
"[api_request][options][body][program_id]" => "program_id"
"[api_request][options][body][subject]" => "subject"
"[api_request][options][body][template]" => "template"
"[api_request][options][body][text]" => "text"
"[api_request][options][body][time_zone]" => "time_zone"
"[api_request][options][body][type]" => "trigger_type"
"[api_request][options][body][url]" => "url"
"[api_request][options][body][content][author]" => "author"
"[api_request][options][body][content][body]" => "body"
"[api_request][options][body][content][published_at]" => "published_at"
"[api_request][options][body][content][summary]" => "summary"
"[api_request][options][body][content][template_id]" => "template_id"
"[api_request][options][body][content][title]" => "title"
"[api_request][options][body][content][program_id]" => "program_id"
"[api_request][options][body][data][attributes][body]" => "body"
"[api_request][options][body][data][attributes][content_channels]" => "content_channels"
"[content_channels][0][id]" => "channel_id"
"[content_channels][0][hidden]" => "hidden"
"[api_request][options][body][data][attributes][content_template_id]" => "template_id"
"[api_request][options][body][data][attributes][display_settings][display_internal_content]" => "display_internal_content"
"[api_request][options][body][data][attributes][images]" => "images"
"[images][0][url]" => "image_url"
"[api_request][options][body][data][attributes][is_shareable]" => "is_shareable"
"[api_request][options][body][data][attributes][prepopulated_share_message]" => "prepopulated_share_message"
"[api_request][options][body][data][attributes][program_id]" => "program_id"
"[api_request][options][body][data][attributes][published_at]" => "published_at"
"[api_request][options][body][data][attributes][summary]" => "summary"
"[api_request][options][body][data][attributes][thumbnail]" => "thumbnail"
"[api_request][options][body][data][attributes][featured_at]" => "featured_at"
"[api_request][options][body][data][attributes][title]" => "title"
"[api_request][options][body][data][attributes][url]" => "url"
"[api_request][options][body]" => "body"
"[api_request][options][headers][SourceApp]" => "sourceapp"
"[api_request][options][headers][X-Request-ID]" => "x-request-id"
"[api_request][options][query][content_channel_ids]" => "channel_id"
"[api_request][options][query][controller]" => "controller"
"[api_request][options][query][feed_item_ids]" => "feed_item_ids"
"[api_request][options][query][fields]" => "content_fields"
"[api_request][options][query][page]" => "page_number"
"[api_request][options][query][page_size]" => "page_size"
"[api_request][options][query][per_page]" => "per_page"
"[api_request][options][query][program_id]" => "program_id"
"[api_request][options][query][publication_state]" => "publication_state"
"[api_request][options][query][search]" => "search"
"[api_request][options][query][status]" => "status"
"[api_request][options][query][total_entries]" => "total_entries"
"[api_request][options][query][total_pages]" => "total_pages"
"[api_request][options][query][query_type]" => "query_type"
"[params][advocate_id]" => "advocate_id"
"[params][authenticity_token]" => "authenticity_token"
"[params][author]" => "author"
"[params][author_username]" => "author_username"
"[params][author_thumbnail]" => "author_thumbnail"
"[params][body]" => "body"
"[params][blocked]" => "blocked"
"[params][brand_slug]" => "brand_slug"
"[params][content_channel]" => "channel_id"
"[params][content_channels]" => "content_channels"
"[params][created_at]" => "created_at"
"[params][current_channel_id]" => "current_channel_id"
"[params][current_channel_ids]" => "current_channel_id"
"[params][display_settings][display_internal_content]" => "display_internal_content"
"[params][display_settings_json]" => "display_settings_json"
"[params][expired_at]" => "expired_at"
"[params][featured_at]" => "featured_at"
"[params][feed_item_id]" => "feed_item_id"
"[params][hashtags]" => "hashtags"
"[params][id]" => "id"
"[params][image_file_name]" => "image_file_name"
"[params][image_size]" => "image_size"
"[params][images]" => "images"
"[params][is_shareable]" => "is_shareable"
"[params][joined_date]" => "joined_date"
"[params][links]" => "links"
"[params][links][content_channels]" => "content_channels"
"[params][links][created_at]" => "created_at"
"[params][links][updated_at]" => "updated_at"
"[params][featured]" => "featured"
"[params][fields]" => "content_fields"
"[params][metadata][parent_id]" => "parent_id"
"[params][metadata][program_id]" => "program_id"
"[params][metadata][publication_state]" => "publication_state"
"[params][metadata][type]" => "metadata_type"
"[params][older_than_id]" => "older_than_id"
"[params][page]" => "page"
"[params][page][number]" => "page_number"
"[params][page][size]" => "page_size"
"[params][page_size]" => "page_size"
"[params][parent_id]" => "parent_id"
"[params][per_page]" => "per_page"
"[params][post_id]" => "post_id"
"[params][posted_at]" => "posted_at"
"[params][prepopulated_share_message]" => "prepopulated_share_message"
"[params][preview_images]" => "preview_images"
"[params][program]" => "program"
"[params][program_id]" => "program_id"
"[params][program_memberships]" => "program_memberships"
"[params][program_memberships][unviewed_highlights_counter]" => "unviewed_highlights_counter"
"[params][program_membership_id]" => "program_membership_id"
"[params][program_slug]" => "program_slug"
"[params][publication_state]" => "publication_state"
"[params][published_at]" => "published_at"
"[params][push_notification_message]" => "push_notification_message"
"[params][source_attribution]" => "source_attribution"
"[params][source_avatar_url]" => "source_avatar_url"
"[params][source_name]" => "source_name"
"[params][status]" => "status"
"[params][summary]" => "summary"
"[params][thumbnail]" => "thumbnail"
"[params][title]" => "title"
"[params][total_entries]" => "total_entries"
"[params][total_pages]" => "total_pages"
"[params][type]" => "content_type"
"[params][trackable_links]" => "trackable_links"
"[params][url]" => "url"
"[params][utm_campaign]" => "utm_campaign"
"[params][utm_medium]" => "utm_medium"
"[params][utm_source]" => "utm_source"
"[params][unviewed_highlights_counter]" => "unviewed_highlights_counter"
"[params][videos]" => "videos"
"[params][welcome_video_watched]" => "welcome_video_watched"
"[params][X-HTTP-Accept]" => "x-http-accept"
"[params][X-Requested-With]" => "x-requested-with"
"[params][_method]" => "method"
"[trackable_links][url]" => "trackable_links_urls"
"[trackable_links][program_id]" => "trackable_links_program_ids"
"[trackable_links][optional_query_string]" => "trackable_links_optional_query_string"
"[params][content][advocate_id]" => "advocate_id"
"[params][content][author]" => "author"
"[params][content][author_username]" => "author_username"
"[params][content][body]" => "body"
"[params][content][content_channel_ids]" => "content_channel_ids"
"[params][content][content_channels]" => "content_channels"
"[params][content][content_template_id]" => "content_template_id"
"[params][content][content_url_preview]" => "content_url_preview"
"[params][content][created_at]" => "created_at"
"[params][content][display_settings][display_internal_content]" => "display_internal_content"
"[params][content][expired_at]" => "expired_at"
"[params][content][featured_at]" => "featured_at"
"[params][content][feed_item_id]" => "feed_item_id"
"[params][content][hashtags]" => "hashtags"
"[params][content][id]" => "external_content_source_id"
"[params][content][images]" => "images"
"[params][content][is_shareable]" => "is_shareable"
"[params][content][links]" => "links"
"[params][content][links][created_at]" => "created_at"
"[params][content][links][updated_at]" => "updated_at"
"[params][content][metadata][parent_id]" => "parent_id"
"[params][content][metadata][program_id]" => "program_id"
"[params][content][metadata][publication_state]" => "publication_state"
"[params][content][metadata][type]" => "metadata_type"
"[params][content][parent_id]" => "parent_id"
"[params][content][post_id]" => "post_id"
"[params][content][posted_at]" => "posted_at"
"[params][content][prepopulated_share_message]" => "prepopulated_share_message"
"[params][content][program_id]" => "program_id"
"[params][content][publication_state]" => "publication_state"
"[params][content][published_at]" => "published_at"
"[params][content][push_notification_message]" => "push_notification_message"
"[params][content][source_attribution]" => "bsource_attributionlah"
"[params][content][source_avatar_url]" => "source_avatar_url"
"[params][content][source_name]" => "source_name"
"[params][content][status]" => "status"
"[params][content][summary]" => "summary"
"[params][content][title]" => "title"
"[params][content][type]" => "external_content_source_type"
"[params][content][updated_at]" => "updated_at"
"[params][content][url]" => "url"
"[params][content][videos]" => "videos"
"[params][data][attributes][published_at]" => "published_at"
"[arguments][channel_id]" => "channel_id"
"[arguments][content_channel_id]" => "content_channel_id"
"[arguments][feed_item_id]" => "feed_item_id"
"[arguments][program_id]" => "program_id"
"[arguments][program_membership_id]" => "program_membership_id"
"[arguments][shareable_type]" => "shareable_type"
"[arguments][social_channel_id]" => "social_channel_id"
"[arguments][status_text]" => "status_text"
}
}
}```
Is there no other surrounding log messages or exceptions? Your log contains just a (partial?) stack trace. It's hard to tell what's going on here.
By way of example:
[2016-11-15T20:27:37,243][ERROR][logstash.pipeline ] dBlock19.yield(CompiledBlock19.j
This is the start of your log message. Somehow it is a truncated log message. I don't know what truncated it, or why, but it is incomplete. I suspect something either split it across lines in the log? I don't know.
I agree that the stack trace comes from the mutate filter, but beyond that I am not sure what is going on. If you can find the missing pieces of that log message, this would be helpful.
Attaching full logs from the time I started the agent.
mutate_crash.tar.gz
I'll help anyway I can, this one is eating my lunch for sure since switching over to 5.0. Really appreciate you looking at it jordan.
This comment is part of investigation of the truncated log message and not a diagnosis of your mutate filter problem.
% tar -zxf mutate_crash.tar.gz -O mutate_crash.log | grep CallSite | head -1 | sed -e 's/^.* \] //' | tr -d '\n'| wc -c
10000
Well that's an oddly-specific value for the length of the log message. Googling for this, I find that log4j appears to have a maximum message size of 10000 bytes.
Until we fix this log message length problem, I'm not sure exactly how to go about digging into this further.
The visible part of the stack trace includes reference to this: https://github.com/logstash-plugins/logstash-filter-mutate/blob/v3.1.3/lib/logstash/filters/mutate.rb#L222 --- so somewhere in this loop is where the exception comes from.
If you are feeling enterprising, you can find this file in your deployment and try to debug it yourself. From the stack trace, mutate.rb is here: /usr/share/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-mutate-3.1.3/lib/logstash/filters/mutate.rb
I did find that this problem doesn't happen in logstash 2.4.1 using logstash-filter-mutate (2.0.6).
I'll look at the differences appreciate the fast response!
@sc-chad The log truncation is caused by log4j, though I don't know why it does this. This truncation is hiding the reason the mutate filter is failing.
Gotcha.
@sc-chad from what I can tell, I don't think the problem is related to the config or mutate filter code, but more probably related to the content of the event. Would it be possible for you to share some log/data sample(s) which triggers this problem so we can try to reproduce locally?
@colinsurprenant Well I'm not completely sure which event is causing the issue. We process thousands of them a minute. Is there something I can do to capture it?
@sc-chad well, ideally, sharing the minimal config with some data that reproduces the problem would be great. Alternatively you could share your complete config and a data file that you know contains logs which triggers the problem would also be good.
@sc-chad Can you attach your config/log4j2.properties file?
Pretty sure it's the default.
status = error
name = LogstashPropertiesConfig
appender.rolling.type = RollingFile
appender.rolling.name = plain_rolling
appender.rolling.fileName = ${sys:ls.logs}/logstash-${sys:ls.log.format}.log
appender.rolling.filePattern = ${sys:ls.logs}/logstash-${sys:ls.log.format}-%d{yyyy-MM-dd}.log
appender.rolling.policies.type = Policies
appender.rolling.policies.time.type = TimeBasedTriggeringPolicy
appender.rolling.policies.time.interval = 1
appender.rolling.policies.time.modulate = true
appender.rolling.layout.type = PatternLayout
appender.rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %.10000m%n
appender.json_rolling.type = RollingFile
appender.json_rolling.name = json_rolling
appender.json_rolling.fileName = ${sys:ls.logs}/logstash-${sys:ls.log.format}.log
appender.json_rolling.filePattern = ${sys:ls.logs}/logstash-${sys:ls.log.format}-%d{yyyy-MM-dd}.log
appender.json_rolling.policies.type = Policies
appender.json_rolling.policies.time.type = TimeBasedTriggeringPolicy
appender.json_rolling.policies.time.interval = 1
appender.json_rolling.policies.time.modulate = true
appender.json_rolling.layout.type = JSONLayout
appender.json_rolling.layout.compact = true
appender.json_rolling.layout.eventEol = true
rootLogger.level = ${sys:ls.log.level}
rootLogger.appenderRef.rolling.ref = ${sys:ls.log.format}_rolling
I got lucky, I found the specific event that I think was causing the issue.
Steps to reproduce:
Extract tar.
Run ./populate
Copy contents of event.log to test.log.
Should see error in stdout, but if not I saved the full error in error_logs/logstash-5.0.1.error
ooooh my how did I miss that, haha.
appender.rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] %.10000m%n
THis is the default we ship, and it's causing this truncation (from the front!). Can you replace %.10000m with %m (remove the dot and 10000) and run Logstash again? When it fails again, it should include the full log message.
Let me know if you aren't able to reproduce it with those files. I've made that change @jordansissel just wanting on the event to come through again.
Don't have the event that caused this, but here's the full error after making that change.
[2016-11-15T23:00:23,563][ERROR][logstash.pipeline ] Exception in pipelineworker, the pipeline stopped processing new events, please check your filter configuration and restart Logstash. {"exception"=>java.lang.NumberFormatException: For input string: "attributes", "backtrace"=>["java.lang.NumberFormatException.forInputString(NumberFormatException.java:65)", "java.lang.Integer.parseInt(Integer.java:580)", "java.lang.Integer.parseInt(Integer.java:615)", "org.logstash.Accessors.fetch(Accessors.java:130)", "org.logstash.Accessors.findTarget(Accessors.java:69)", "org.logstash.Accessors.includes(Accessors.java:50)", "org.logstash.Event.includes(Event.java:164)", "org.logstash.ext.JrubyEventExtLibrary$RubyEvent.ruby_includes(JrubyEventExtLibrary.java:156)", "org.logstash.ext.JrubyEventExtLibrary$RubyEvent$INVOKER$i$1$0$ruby_includes.call(JrubyEventExtLibrary$RubyEvent$INVOKER$i$1$0$ruby_includes.gen)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)", "rubyjit.LogStash::Filters::Mutate$$rename_86877101c922e43dc1452c3c68bb09668ac4f2e91442407170.block_0$RUBY$__file__(/usr/share/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-mutate-3.1.3/lib/logstash/filters/mutate.rb:225)", "rubyjit$LogStash::Filters::Mutate$$rename_86877101c922e43dc1452c3c68bb09668ac4f2e91442407170$block_0$RUBY$__file__.call(rubyjit$LogStash::Filters::Mutate$$rename_86877101c922e43dc1452c3c68bb09668ac4f2e91442407170$block_0$RUBY$__file__)", "org.jruby.runtime.CompiledBlock19.yield(CompiledBlock19.java:135)", "org.jruby.runtime.Block.yield(Block.java:142)", "org.jruby.RubyHash$13.visit(RubyHash.java:1355)", "org.jruby.RubyHash.visitLimited(RubyHash.java:648)", "org.jruby.RubyHash.visitAll(RubyHash.java:634)", "org.jruby.RubyHash.iteratorVisitAll(RubyHash.java:1306)", "org.jruby.RubyHash.each_pairCommon(RubyHash.java:1351)", "org.jruby.RubyHash.each19(RubyHash.java:1342)", "org.jruby.RubyHash$INVOKER$i$0$0$each19.call(RubyHash$INVOKER$i$0$0$each19.gen)", "org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:143)", "org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:154)", "rubyjit.LogStash::Filters::Mutate$$rename_86877101c922e43dc1452c3c68bb09668ac4f2e91442407170.__file__(/usr/share/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-mutate-3.1.3/lib/logstash/filters/mutate.rb:222)", "rubyjit.LogStash::Filters::Mutate$$rename_86877101c922e43dc1452c3c68bb09668ac4f2e91442407170.__file__(/usr/share/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-mutate-3.1.3/lib/logstash/filters/mutate.rb)", "org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:181)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)", "rubyjit.LogStash::Filters::Mutate$$filter_7ece4ecf2c9d8324f6c4933fda087138f0104c701442407170.__file__(/usr/share/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-mutate-3.1.3/lib/logstash/filters/mutate.rb:203)", "rubyjit.LogStash::Filters::Mutate$$filter_7ece4ecf2c9d8324f6c4933fda087138f0104c701442407170.__file__(/usr/share/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-mutate-3.1.3/lib/logstash/filters/mutate.rb)", "org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:201)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:336)", "org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:179)", "org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:188)", "rubyjit.LogStash::Filters::Base$$multi_filter_1ee1ab11f89a1dea5c87673dc32bcc4de88a737f1442407170.block_0$RUBY$__file__(/usr/share/logstash/logstash-core/lib/logstash/filters/base.rb:156)", "rubyjit$LogStash::Filters::Base$$multi_filter_1ee1ab11f89a1dea5c87673dc32bcc4de88a737f1442407170$block_0$RUBY$__file__.call(rubyjit$LogStash::Filters::Base$$multi_filter_1ee1ab11f89a1dea5c87673dc32bcc4de88a737f1442407170$block_0$RUBY$__file__)", "org.jruby.runtime.CompiledBlock19.yield(CompiledBlock19.java:135)", "org.jruby.runtime.Block.yield(Block.java:142)", "org.jruby.RubyArray.eachCommon(RubyArray.java:1606)", "org.jruby.RubyArray.each(RubyArray.java:1613)", "org.jruby.RubyArray$INVOKER$i$0$0$each.call(RubyArray$INVOKER$i$0$0$each.gen)", "org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:143)", "org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:154)", "rubyjit.LogStash::Filters::Base$$multi_filter_1ee1ab11f89a1dea5c87673dc32bcc4de88a737f1442407170.__file__(/usr/share/logstash/logstash-core/lib/logstash/filters/base.rb:153)", "rubyjit.LogStash::Filters::Base$$multi_filter_1ee1ab11f89a1dea5c87673dc32bcc4de88a737f1442407170.__file__(/usr/share/logstash/logstash-core/lib/logstash/filters/base.rb)", "org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:181)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:170)", "rubyjit.LogStash::FilterDelegator$$multi_filter_87d312cb29252318f5ba9dfc74f2695ff3ca582a1442407170.__file__(/usr/share/logstash/logstash-core/lib/logstash/filter_delegator.rb:41)", "rubyjit.LogStash::FilterDelegator$$multi_filter_87d312cb29252318f5ba9dfc74f2695ff3ca582a1442407170.__file__(/usr/share/logstash/logstash-core/lib/logstash/filter_delegator.rb)", "org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:181)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)", "org.jruby.ast.CallOneArgNode.interpret(CallOneArgNode.java:57)", "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.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.internal.runtime.methods.ProcMethod.call(ProcMethod.java:64)", "org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:210)", "org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:206)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)", "rubyjit.LogStash::Pipeline$$filter_batch_dcf719a486d1119c9be57d0fcabb58d262fd21981442407170.block_0$RUBY$__file__(/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:260)", "rubyjit$LogStash::Pipeline$$filter_batch_dcf719a486d1119c9be57d0fcabb58d262fd21981442407170$block_0$RUBY$__file__.call(rubyjit$LogStash::Pipeline$$filter_batch_dcf719a486d1119c9be57d0fcabb58d262fd21981442407170$block_0$RUBY$__file__)", "org.jruby.runtime.CompiledBlock19.yield(CompiledBlock19.java:159)", "org.jruby.runtime.CompiledBlock19.call(CompiledBlock19.java:87)", "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:210)", "org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:206)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)", "rubyjit.LogStash::Util::WrappedSynchronousQueue::ReadBatch$$each_cc57d8888498073a1852ab1bae0383dbea1b388e1442407170.block_0$RUBY$__file__(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb:186)", "rubyjit$LogStash::Util::WrappedSynchronousQueue::ReadBatch$$each_cc57d8888498073a1852ab1bae0383dbea1b388e1442407170$block_0$RUBY$__file__.call(rubyjit$LogStash::Util::WrappedSynchronousQueue::ReadBatch$$each_cc57d8888498073a1852ab1bae0383dbea1b388e1442407170$block_0$RUBY$__file__)", "org.jruby.runtime.CompiledBlock19.yield(CompiledBlock19.java:135)", "org.jruby.runtime.Block.yield(Block.java:142)", "org.jruby.RubyHash$13.visit(RubyHash.java:1355)", "org.jruby.RubyHash.visitLimited(RubyHash.java:648)", "org.jruby.RubyHash.visitAll(RubyHash.java:634)", "org.jruby.RubyHash.iteratorVisitAll(RubyHash.java:1306)", "org.jruby.RubyHash.each_pairCommon(RubyHash.java:1351)", "org.jruby.RubyHash.each19(RubyHash.java:1342)", "org.jruby.RubyHash$INVOKER$i$0$0$each19.call(RubyHash$INVOKER$i$0$0$each19.gen)", "org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:143)", "org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:154)", "rubyjit.LogStash::Util::WrappedSynchronousQueue::ReadBatch$$each_cc57d8888498073a1852ab1bae0383dbea1b388e1442407170.__file__(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb:185)", "rubyjit.LogStash::Util::WrappedSynchronousQueue::ReadBatch$$each_cc57d8888498073a1852ab1bae0383dbea1b388e1442407170.__file__(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb)", "org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:161)", "org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:143)", "org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:154)", "rubyjit.LogStash::Pipeline$$filter_batch_dcf719a486d1119c9be57d0fcabb58d262fd21981442407170.chained_0_rescue_1$RUBY$SYNTHETIC__file__(/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:258)", "rubyjit.LogStash::Pipeline$$filter_batch_dcf719a486d1119c9be57d0fcabb58d262fd21981442407170.__file__(/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb)", "rubyjit.LogStash::Pipeline$$filter_batch_dcf719a486d1119c9be57d0fcabb58d262fd21981442407170.__file__(/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb)", "org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:181)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)", "org.jruby.ast.FCallOneArgNode.interpret(FCallOneArgNode.java:36)", "org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)", "org.jruby.ast.BlockNode.interpret(BlockNode.java:71)", "org.jruby.ast.WhileNode.interpret(WhileNode.java:131)", "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:225)", "org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:219)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:202)", "org.jruby.ast.FCallTwoArgNode.interpret(FCallTwoArgNode.java:38)", "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: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:99)", "java.lang.Thread.run(Thread.java:745)"]}
Exception in pipelineworker, the pipeline stopped processing new events, please check your filter configuration and restart Logstash. {"exception"=>java.lang.NumberFormatException: For input string: "attributes",
One of your fieldreferences that has a part named 'attributes' actually is a list, so the fieldref tries to do an list index (number) and fails to parse it.
In these scenarios, for example, the field [params][data] or [api_request][options][body] is a list, not an object (hash, dictionary, whatever term we want to use here.)
Here's an example of me reproducing this:
⓿ localhost(~/build/logstash-5.0.0)
% bin/logstash -e 'input { generator { message => stdin codec => json count => 1 } } filter { mutate { rename => { "[api_request][options][body][data][attributes][thumbnail]" => "thu
mbnail" } } }'
# Me telling the generator input to use this as the event input:
{ "api_request": { "options": { "body": { "data": [ "this", "is", "a", "list" ] } } } }
[2016-11-14T01:44:17,215][ERROR][logstash.pipeline ] Exception in pipelineworker, the pipeline stopped processing new events, please check your filter configuration and restar
t Logstash. {"exception"=>java.lang.NumberFormatException: For input string: "attributes", "backtrace"=>["java.lang.NumberFormatException.forInputString(NumberFormatException.java:65
)", "java.lang.Integer.parseInt(Integer.java:580)", "java.lang.Integer.parseInt(Integer.java:615)", "...
The bug
Fundamentally, the bug is this: You have asked Logstash to rename a field that doesn't exist. In trying to find the field, Logstash travels your event's data, api_request to options to body to data, then finally finds, for example, that 'data' is an array, and throws an exception due to a failure in attempting to do that array lookup
From your configuration, any of these renames could cause your problem:
"[api_request][options][body][data][attributes][body]" => "body"
"[api_request][options][body][data][attributes][content_channels]" => "content_channels"
"[content_channels][0][id]" => "channel_id"
"[content_channels][0][hidden]" => "hidden"
"[api_request][options][body][data][attributes][content_template_id]" => "template_id"
"[api_request][options][body][data][attributes][display_settings][display_internal_content]" => "display_internal_content"
"[api_request][options][body][data][attributes][images]" => "images"
"[images][0][url]" => "image_url"
"[api_request][options][body][data][attributes][is_shareable]" => "is_shareable"
"[api_request][options][body][data][attributes][prepopulated_share_message]" => "prepopulated_share_message"
"[api_request][options][body][data][attributes][program_id]" => "program_id"
"[api_request][options][body][data][attributes][published_at]" => "published_at"
"[api_request][options][body][data][attributes][summary]" => "summary"
"[api_request][options][body][data][attributes][thumbnail]" => "thumbnail"
"[api_request][options][body][data][attributes][featured_at]" => "featured_at"
"[api_request][options][body][data][attributes][title]" => "title"
"[api_request][options][body][data][attributes][url]" => "url"
....
"[params][data][attributes][published_at]" => "published_at"
This is a bug in Logstash core. I'll file an issue.
Filed this: elastic/logstash#6260
@jordansissel You rock sir thank you very much!
And if you guys haven't been told enough, people like me seriously appreciate all the work you put into things like this. It makes our job so much more interesting when we can stand on the shoulders of giants.
@sc-chad Together we can build some pretty awesome things. <3