Logstash: pipelineworker exception upon field set

[colinsurprenant]

This reproduces in master and 5.6, did not specifically test 6.0.

The following case crashed logstash with a pipelineworker exception:

echo '{"source":"foo", "log":"bar"}' | bin/logstash -e 'input{stdin{codec => json_lines}} filter {mutate {rename => {"source" => "[log][file]"}}} output{stdout{codec => rubydebug}}'

which result in the following exception:

Exception in pipelineworker, the pipeline stopped processing new events, please check your filter configuration and restart Logstash. {:pipeline_id=>"main", "exception"=>"org.jruby.RubyString cannot be cast to org.logstash.ConvertedList", "backtrace"=>["org.logstash.Accessors.setChild(org/logstash/Accessors.java:107)", "org.logstash.Accessors.set(org/logstash/Accessors.java:16)", "org.logstash.Event.setField(org/logstash/Event.java:162)", "org.logstash.ext.JrubyEventExtLibrary$RubyEvent.set(org/logstash/ext/JrubyEventExtLibrary.java:95)", "org.logstash.ext.JrubyEventExtLibrary$RubyEvent$INVOKER$i$2$0$ruby_set_field.call(org/logstash/ext/JrubyEventExtLibrary$RubyEvent$INVOKER$i$2$0$ruby_set_field.gen)", "Users.colin.dev.src.elasticsearch.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_mutate_minus_3_dot_2_dot_0.lib.logstash.filters.mutate.block in rename(/Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-mutate-3.2.0/lib/logstash/filters/mutate.rb:243)", "org.jruby.RubyHash$12.visit(org/jruby/RubyHash.java:1362)", "org.jruby.RubyHash$12.visit(org/jruby/RubyHash.java:1359)", "org.jruby.RubyHash.visitLimited(org/jruby/RubyHash.java:662)", "org.jruby.RubyHash.visitAll(org/jruby/RubyHash.java:647)", "org.jruby.RubyHash.iteratorVisitAll(org/jruby/RubyHash.java:1319)", "org.jruby.RubyHash.each_pairCommon(org/jruby/RubyHash.java:1354)", "org.jruby.RubyHash.each(org/jruby/RubyHash.java:1343)", "org.jruby.RubyHash$INVOKER$i$0$0$each.call(org/jruby/RubyHash$INVOKER$i$0$0$each.gen)", "Users.colin.dev.src.elasticsearch.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_mutate_minus_3_dot_2_dot_0.lib.logstash.filters.mutate.rename(/Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-mutate-3.2.0/lib/logstash/filters/mutate.rb:239)", "Users.colin.dev.src.elasticsearch.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_mutate_minus_3_dot_2_dot_0.lib.logstash.filters.mutate.RUBY$method$rename$0$__VARARGS__(Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/$2_dot_3_dot_0/gems/logstash_minus_filter_minus_mutate_minus_3_dot_2_dot_0/lib/logstash/filters//Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-mutate-3.2.0/lib/logstash/filters/mutate.rb)", "Users.colin.dev.src.elasticsearch.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_mutate_minus_3_dot_2_dot_0.lib.logstash.filters.mutate.filter(/Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-mutate-3.2.0/lib/logstash/filters/mutate.rb:219)", "Users.colin.dev.src.elasticsearch.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_mutate_minus_3_dot_2_dot_0.lib.logstash.filters.mutate.RUBY$method$filter$0$__VARARGS__(Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/$2_dot_3_dot_0/gems/logstash_minus_filter_minus_mutate_minus_3_dot_2_dot_0/lib/logstash/filters//Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-mutate-3.2.0/lib/logstash/filters/mutate.rb)", "Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.filters.base.do_filter(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/filters/base.rb:145)", "Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.filters.base.RUBY$method$do_filter$0$__VARARGS__(Users/colin/dev/src/elasticsearch/logstash/logstash_minus_core/lib/logstash/filters//Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/filters/base.rb)", "Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.filters.base.block in multi_filter(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/filters/base.rb:164)", "org.jruby.RubyArray.each(org/jruby/RubyArray.java:1734)", "Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.filters.base.multi_filter(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/filters/base.rb:161)", "Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.java_filter_delegator.multi_filter(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/java_filter_delegator.rb:53)", "Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.java_filter_delegator.RUBY$method$multi_filter$0$__VARARGS__(Users/colin/dev/src/elasticsearch/logstash/logstash_minus_core/lib/logstash//Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/java_filter_delegator.rb)", "CompiledDataset3.compute(CompiledDataset3)", "CompiledDataset4.compute(CompiledDataset4)", "java.lang.reflect.Method.invoke(java/lang/reflect/Method.java:498)", "org.jruby.javasupport.JavaMethod.invokeDirectWithExceptionHandling(org/jruby/javasupport/JavaMethod.java:483)", "org.jruby.javasupport.JavaMethod.invokeDirect(org/jruby/javasupport/JavaMethod.java:338)", "Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.java_pipeline.execute_batch(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/java_pipeline.rb:649)", "Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.java_pipeline.worker_loop(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/java_pipeline.rb:411)", "Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.java_pipeline.block in start_workers(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/java_pipeline.rb:375)", "org.jruby.RubyProc.call(org/jruby/RubyProc.java:289)", "org.jruby.RubyProc.call(org/jruby/RubyProc.java:246)", "java.lang.Thread.run(java/lang/Thread.java:748)"], :thread=>"#<Thread:0x7b456197 run>"}
Exception in thread "Ruby-0-Thread-15@[main]>worker7: :1" java.lang.ClassCastException: org.jruby.RubyString cannot be cast to org.logstash.ConvertedList
    at org.logstash.Accessors.setChild(org/logstash/Accessors.java:107)
    at org.logstash.Accessors.set(org/logstash/Accessors.java:16)
    at org.logstash.Event.setField(org/logstash/Event.java:162)
    at org.logstash.ext.JrubyEventExtLibrary$RubyEvent.set(org/logstash/ext/JrubyEventExtLibrary.java:95)
    at org.logstash.ext.JrubyEventExtLibrary$RubyEvent$INVOKER$i$2$0$ruby_set_field.call(org/logstash/ext/JrubyEventExtLibrary$RubyEvent$INVOKER$i$2$0$ruby_set_field.gen)
    at Users.colin.dev.src.elasticsearch.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_mutate_minus_3_dot_2_dot_0.lib.logstash.filters.mutate.block in rename(/Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-mutate-3.2.0/lib/logstash/filters/mutate.rb:243)
    at org.jruby.RubyHash$12.visit(org/jruby/RubyHash.java:1362)
    at org.jruby.RubyHash$12.visit(org/jruby/RubyHash.java:1359)
    at org.jruby.RubyHash.visitLimited(org/jruby/RubyHash.java:662)
    at org.jruby.RubyHash.visitAll(org/jruby/RubyHash.java:647)
    at org.jruby.RubyHash.iteratorVisitAll(org/jruby/RubyHash.java:1319)
    at org.jruby.RubyHash.each_pairCommon(org/jruby/RubyHash.java:1354)
    at org.jruby.RubyHash.each(org/jruby/RubyHash.java:1343)
    at org.jruby.RubyHash$INVOKER$i$0$0$each.call(org/jruby/RubyHash$INVOKER$i$0$0$each.gen)
    at Users.colin.dev.src.elasticsearch.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_mutate_minus_3_dot_2_dot_0.lib.logstash.filters.mutate.rename(/Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-mutate-3.2.0/lib/logstash/filters/mutate.rb:239)
    at Users.colin.dev.src.elasticsearch.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_mutate_minus_3_dot_2_dot_0.lib.logstash.filters.mutate.RUBY$method$rename$0$__VARARGS__(Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/$2_dot_3_dot_0/gems/logstash_minus_filter_minus_mutate_minus_3_dot_2_dot_0/lib/logstash/filters//Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-mutate-3.2.0/lib/logstash/filters/mutate.rb)
    at Users.colin.dev.src.elasticsearch.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_mutate_minus_3_dot_2_dot_0.lib.logstash.filters.mutate.filter(/Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-mutate-3.2.0/lib/logstash/filters/mutate.rb:219)
    at Users.colin.dev.src.elasticsearch.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_mutate_minus_3_dot_2_dot_0.lib.logstash.filters.mutate.RUBY$method$filter$0$__VARARGS__(Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/$2_dot_3_dot_0/gems/logstash_minus_filter_minus_mutate_minus_3_dot_2_dot_0/lib/logstash/filters//Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-mutate-3.2.0/lib/logstash/filters/mutate.rb)
    at Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.filters.base.do_filter(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/filters/base.rb:145)
    at Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.filters.base.RUBY$method$do_filter$0$__VARARGS__(Users/colin/dev/src/elasticsearch/logstash/logstash_minus_core/lib/logstash/filters//Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/filters/base.rb)
    at Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.filters.base.block in multi_filter(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/filters/base.rb:164)
    at org.jruby.RubyArray.each(org/jruby/RubyArray.java:1734)
    at Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.filters.base.multi_filter(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/filters/base.rb:161)
    at Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.java_filter_delegator.multi_filter(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/java_filter_delegator.rb:53)
    at Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.java_filter_delegator.RUBY$method$multi_filter$0$__VARARGS__(Users/colin/dev/src/elasticsearch/logstash/logstash_minus_core/lib/logstash//Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/java_filter_delegator.rb)
    at CompiledDataset3.compute(CompiledDataset3)
    at CompiledDataset4.compute(CompiledDataset4)
    at java.lang.reflect.Method.invoke(java/lang/reflect/Method.java:498)
    at org.jruby.javasupport.JavaMethod.invokeDirectWithExceptionHandling(org/jruby/javasupport/JavaMethod.java:483)
    at org.jruby.javasupport.JavaMethod.invokeDirect(org/jruby/javasupport/JavaMethod.java:338)
    at Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.java_pipeline.execute_batch(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/java_pipeline.rb:649)
    at Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.java_pipeline.worker_loop(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/java_pipeline.rb:411)
    at Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.java_pipeline.block in start_workers(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/java_pipeline.rb:375)
    at org.jruby.RubyProc.call(org/jruby/RubyProc.java:289)
    at org.jruby.RubyProc.call(org/jruby/RubyProc.java:246)
    at java.lang.Thread.run(java/lang/Thread.java:748)

[original-brownbear]

@colinsurprenant I remember asking @jordansissel about the behaviour in this case and was told that this is the expected behaviour. (I guess we could have a nicer Exception, but in general this it's simply logically impossible to do anything else (except for overwriting the existing String), you can't set a subfield on a String)
@jordansissel can you confirm?

[colinsurprenant]

@original-brownbear yeah, I agree, this is more about better handling for the exception which crashes the worker. At the very least we should try to output a better error log and see if we should avoid crashing the worker.