Logstash: QueueRuntimeException: deserialize invocation error

Created on 27 Apr 2018 · 6Comments · Source: elastic/logstash

Version: 6.2.4
Operating System:

We are using the official logstash Docker image: docker.elastic.co/logstash/logstash-oss:6.2.4

Installing via helm stable/logstash Chart. Here is the Dockerfile we are using

FROM docker.elastic.co/logstash/logstash-oss:6.2.4

RUN bin/logstash-plugin install logstash-output-loggly

Doesn't look like an issue with the loggly output plugin, but I wanted to use the exact config we were using.

Steps to Reproduce: helm install --values values.yaml stable/logstash

values.yaml:

replicaCount: 3

image:
  repository: REDACTED (see Dockerfile above)
  tag: REDACTED (see Dockerfile above)
  pullPolicy: IfNotPresent

exporter:
  logstash:
    enabled: true

podAnnotations:
  prometheus.io/scrape: "true"
  prometheus.io/path: "/metrics"
  prometheus.io/port: "9198"

outputs:
  main: |-
    output {
      loggly {
        proto => "https"
        host => "logs-01.loggly.com"
        key => REDACTED
      }
    }

Stack trace:

2018/04/27 14:54:02 Setting 'queue.max_bytes' from environment.
2018/04/27 14:54:02 Setting 'path.config' from environment.
2018/04/27 14:54:02 Setting 'queue.drain' from environment.
2018/04/27 14:54:02 Setting 'http.port' from environment.
2018/04/27 14:54:02 Setting 'http.host' from environment.
2018/04/27 14:54:02 Setting 'path.data' from environment.
2018/04/27 14:54:02 Setting 'queue.checkpoint.writes' from environment.
2018/04/27 14:54:02 Setting 'queue.type' from environment.
2018/04/27 14:54:02 Setting 'config.reload.automatic' from environment.
Sending Logstash's logs to /usr/share/logstash/logs which is now configured via log4j2.properties
[2018-04-27T14:54:26,963][INFO ][logstash.modules.scaffold] Initializing module {:module_name=>"netflow", :directory=>"/usr/share/logstash/modules/netflow/configuration"}
[2018-04-27T14:54:26,979][INFO ][logstash.modules.scaffold] Initializing module {:module_name=>"fb_apache", :directory=>"/usr/share/logstash/modules/fb_apache/configuration"}
[2018-04-27T14:54:27,671][WARN ][logstash.config.source.multilocal] Ignoring the 'pipelines.yml' file because modules or command line options are specified
[2018-04-27T14:54:28,253][INFO ][logstash.runner          ] Starting Logstash {"logstash.version"=>"6.2.4"}
[2018-04-27T14:54:28,848][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9600}
[2018-04-27T14:54:31,595][INFO ][logstash.pipeline        ] Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>2, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50}
Exception in thread "Ruby-0-Thread-8@[main]>worker0: :1" org.logstash.ackedqueue.QueueRuntimeException: deserialize invocation error
    at org.logstash.ackedqueue.Queue.deserialize(Queue.java:733)
    at org.logstash.ackedqueue.Batch.deserializeElements(Batch.java:62)
    at org.logstash.ackedqueue.Batch.<init>(Batch.java:23)
    at org.logstash.ackedqueue.Queue._readPageBatch(Queue.java:589)
    at org.logstash.ackedqueue.Queue.readBatch(Queue.java:523)
    at org.logstash.ackedqueue.ext.AbstractJRubyQueue.ruby_read_batch(AbstractJRubyQueue.java:115)
    at usr.share.logstash.logstash_minus_core.lib.logstash.util.wrapped_acked_queue.RUBY$method$read_batch$0(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:66)
    at usr.share.logstash.logstash_minus_core.lib.logstash.util.wrapped_acked_queue.RUBY$method$read_batch$0$__VARARGS__(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb)
    at org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:77)
    at org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:93)
    at org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)
    at usr.share.logstash.logstash_minus_core.lib.logstash.util.wrapped_acked_queue.RUBY$method$read_next$0(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:229)
    at usr.share.logstash.logstash_minus_core.lib.logstash.util.wrapped_acked_queue.RUBY$method$read_next$0$__VARARGS__(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb)
    at org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:77)
    at org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:93)
    at org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)
    at usr.share.logstash.logstash_minus_core.lib.logstash.util.wrapped_acked_queue.RUBY$method$read_batch$0(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:164)
    at usr.share.logstash.logstash_minus_core.lib.logstash.util.wrapped_acked_queue.RUBY$method$read_batch$0$__VARARGS__(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb)
    at org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:77)
    at org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:93)
    at org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)
    at usr.share.logstash.logstash_minus_core.lib.logstash.pipeline.RUBY$method$worker_loop$0(/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:420)
    at usr.share.logstash.logstash_minus_core.lib.logstash.pipeline.RUBY$method$worker_loop$0$__VARARGS__(/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb)
    at org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:77)
    at org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:93)
    at org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)
    at usr.share.logstash.logstash_minus_core.lib.logstash.pipeline.RUBY$block$start_workers$2(/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:386)
    at org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:145)
    at org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:71)
    at org.jruby.runtime.Block.call(Block.java:124)
    at org.jruby.RubyProc.call(RubyProc.java:289)
    at org.jruby.RubyProc.call(RubyProc.java:246)
    at org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:104)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.reflect.InvocationTargetException
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.logstash.ackedqueue.Queue.deserialize(Queue.java:731)
    ... 33 more
Caused by: com.fasterxml.jackson.databind.JsonMappingException: (was java.lang.NullPointerException) (through reference chain: java.util.HashMap["DATA"]->org.logstash.ConvertedMap["host"])
    at com.fasterxml.jackson.databind.JsonMappingException.wrapWithPath(JsonMappingException.java:391)
    at com.fasterxml.jackson.databind.JsonMappingException.wrapWithPath(JsonMappingException.java:351)
    at com.fasterxml.jackson.databind.deser.std.ContainerDeserializerBase.wrapAndThrow(ContainerDeserializerBase.java:181)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer._readAndBindStringKeyMap(MapDeserializer.java:539)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:364)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:29)
    at com.fasterxml.jackson.databind.jsontype.impl.AsArrayTypeDeserializer._deserialize(AsArrayTypeDeserializer.java:116)
    at com.fasterxml.jackson.databind.jsontype.impl.AsArrayTypeDeserializer.deserializeTypedFromAny(AsArrayTypeDeserializer.java:71)
    at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.deserializeWithType(UntypedObjectDeserializer.java:712)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer._readAndBindStringKeyMap(MapDeserializer.java:529)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:364)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:29)
    at com.fasterxml.jackson.databind.jsontype.impl.AsArrayTypeDeserializer._deserialize(AsArrayTypeDeserializer.java:116)
    at com.fasterxml.jackson.databind.jsontype.impl.AsArrayTypeDeserializer.deserializeTypedFromObject(AsArrayTypeDeserializer.java:61)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserializeWithType(MapDeserializer.java:400)
    at com.fasterxml.jackson.databind.deser.impl.TypeWrappedDeserializer.deserialize(TypeWrappedDeserializer.java:68)
    at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:4001)
    at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:3109)
    at org.logstash.Event.fromSerializableMap(Event.java:184)
    at org.logstash.Event.deserialize(Event.java:397)
    ... 38 more
Caused by: java.lang.NullPointerException
    at org.jruby.RubyEncoding$UTF8Coder.encode(RubyEncoding.java:281)
    at org.jruby.RubyEncoding.encodeUTF8(RubyEncoding.java:182)
    at org.jruby.RubyString.encodeBytelist(RubyString.java:5523)
    at org.jruby.RubyString.<init>(RubyString.java:359)
    at org.jruby.RubyString.<init>(RubyString.java:351)
    at org.jruby.RubyString.newString(RubyString.java:446)
    at org.logstash.ObjectMappers$RubyStringDeserializer.deserialize(ObjectMappers.java:122)
    at org.logstash.ObjectMappers$RubyStringDeserializer.deserialize(ObjectMappers.java:113)
    at com.fasterxml.jackson.databind.jsontype.impl.AsArrayTypeDeserializer._deserialize(AsArrayTypeDeserializer.java:116)
    at com.fasterxml.jackson.databind.jsontype.impl.AsArrayTypeDeserializer.deserializeTypedFromAny(AsArrayTypeDeserializer.java:71)
    at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.deserializeWithType(UntypedObjectDeserializer.java:712)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer._readAndBindStringKeyMap(MapDeserializer.java:529)
    ... 54 more
Exception in thread "Ruby-0-Thread-9@[main]>worker1: :1" org.logstash.ackedqueue.QueueRuntimeException: deserialize invocation error
    at org.logstash.ackedqueue.Queue.deserialize(Queue.java:733)
    at org.logstash.ackedqueue.Batch.deserializeElements(Batch.java:62)
    at org.logstash.ackedqueue.Batch.<init>(Batch.java:23)
    at org.logstash.ackedqueue.Queue._readPageBatch(Queue.java:589)
    at org.logstash.ackedqueue.Queue.readBatch(Queue.java:523)
    at org.logstash.ackedqueue.ext.AbstractJRubyQueue.ruby_read_batch(AbstractJRubyQueue.java:115)
    at org.logstash.ackedqueue.ext.AbstractJRubyQueue$INVOKER$i$2$0$ruby_read_batch.call(AbstractJRubyQueue$INVOKER$i$2$0$ruby_read_batch.gen)
    at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodN.call(JavaMethod.java:741)
    at org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)
    at usr.share.logstash.logstash_minus_core.lib.logstash.util.wrapped_acked_queue.RUBY$method$read_batch$0(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:66)
    at usr.share.logstash.logstash_minus_core.lib.logstash.util.wrapped_acked_queue.RUBY$method$read_batch$0$__VARARGS__(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb)
    at org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:77)
    at org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:93)
    at org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)
    at usr.share.logstash.logstash_minus_core.lib.logstash.util.wrapped_acked_queue.RUBY$method$read_next$0(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:229)
    at usr.share.logstash.logstash_minus_core.lib.logstash.util.wrapped_acked_queue.RUBY$method$read_next$0$__VARARGS__(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb)
    at org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:77)
    at org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:93)
    at org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)
    at usr.share.logstash.logstash_minus_core.lib.logstash.util.wrapped_acked_queue.RUBY$method$read_batch$0(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb:164)
    at usr.share.logstash.logstash_minus_core.lib.logstash.util.wrapped_acked_queue.RUBY$method$read_batch$0$__VARARGS__(/usr/share/logstash/logstash-core/lib/logstash/util/wrapped_acked_queue.rb)
    at org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:77)
    at org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:93)
    at org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)
    at usr.share.logstash.logstash_minus_core.lib.logstash.pipeline.RUBY$method$worker_loop$0(/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:420)
    at usr.share.logstash.logstash_minus_core.lib.logstash.pipeline.RUBY$method$worker_loop$0$__VARARGS__(/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb)
    at org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:77)
    at org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:93)
    at org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)
    at usr.share.logstash.logstash_minus_core.lib.logstash.pipeline.RUBY$block$start_workers$2(/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:386)
    at org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:145)
    at org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:71)
    at org.jruby.runtime.Block.call(Block.java:124)
    at org.jruby.RubyProc.call(RubyProc.java:289)
    at org.jruby.RubyProc.call(RubyProc.java:246)
    at org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:104)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.reflect.InvocationTargetException
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.logstash.ackedqueue.Queue.deserialize(Queue.java:731)
    ... 36 more
Caused by: com.fasterxml.jackson.databind.JsonMappingException: (was java.lang.NullPointerException) (through reference chain: java.util.HashMap["DATA"]->org.logstash.ConvertedMap["host"])
    at com.fasterxml.jackson.databind.JsonMappingException.wrapWithPath(JsonMappingException.java:391)
    at com.fasterxml.jackson.databind.JsonMappingException.wrapWithPath(JsonMappingException.java:351)
    at com.fasterxml.jackson.databind.deser.std.ContainerDeserializerBase.wrapAndThrow(ContainerDeserializerBase.java:181)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer._readAndBindStringKeyMap(MapDeserializer.java:539)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:364)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:29)
    at com.fasterxml.jackson.databind.jsontype.impl.AsArrayTypeDeserializer._deserialize(AsArrayTypeDeserializer.java:116)
    at com.fasterxml.jackson.databind.jsontype.impl.AsArrayTypeDeserializer.deserializeTypedFromAny(AsArrayTypeDeserializer.java:71)
    at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.deserializeWithType(UntypedObjectDeserializer.java:712)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer._readAndBindStringKeyMap(MapDeserializer.java:529)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:364)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:29)
    at com.fasterxml.jackson.databind.jsontype.impl.AsArrayTypeDeserializer._deserialize(AsArrayTypeDeserializer.java:116)
    at com.fasterxml.jackson.databind.jsontype.impl.AsArrayTypeDeserializer.deserializeTypedFromObject(AsArrayTypeDeserializer.java:61)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserializeWithType(MapDeserializer.java:400)
    at com.fasterxml.jackson.databind.deser.impl.TypeWrappedDeserializer.deserialize(TypeWrappedDeserializer.java:68)
    at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:4001)
    at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:3109)
    at org.logstash.Event.fromSerializableMap(Event.java:184)
    at org.logstash.Event.deserialize(Event.java:397)
    ... 41 more
Caused by: java.lang.NullPointerException
    at org.jruby.RubyEncoding$UTF8Coder.encode(RubyEncoding.java:281)
    at org.jruby.RubyEncoding.encodeUTF8(RubyEncoding.java:182)
    at org.jruby.RubyString.encodeBytelist(RubyString.java:5523)
    at org.jruby.RubyString.<init>(RubyString.java:359)
    at org.jruby.RubyString.<init>(RubyString.java:351)
    at org.jruby.RubyString.newString(RubyString.java:446)
    at org.logstash.ObjectMappers$RubyStringDeserializer.deserialize(ObjectMappers.java:122)
    at org.logstash.ObjectMappers$RubyStringDeserializer.deserialize(ObjectMappers.java:113)
    at com.fasterxml.jackson.databind.jsontype.impl.AsArrayTypeDeserializer._deserialize(AsArrayTypeDeserializer.java:116)
    at com.fasterxml.jackson.databind.jsontype.impl.AsArrayTypeDeserializer.deserializeTypedFromAny(AsArrayTypeDeserializer.java:71)
    at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.deserializeWithType(UntypedObjectDeserializer.java:712)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer._readAndBindStringKeyMap(MapDeserializer.java:529)
    ... 57 more

P2 bug persistent queues

Source

sdanbury

All 6 comments

Thanks for the report, we're going to mostly be tracking fixes here: https://github.com/elastic/logstash/issues/9494

andrewvc on 27 Apr 2018

@sdanbury are you running into this during normal operation, or did it happen as the result of an upgrade of LS versions with existing data in the PQ?

original-brownbear on 28 Apr 2018

@original-brownbear come to think of it, we only saw this shortly after bumping the docker container to use image version 6.2.4, after we noticed the helm chart was using 6.2.2. No real proof that it happens only in 6.2.4 though and not in 6.2.2.

sdanbury on 29 Apr 2018

I have seen this error in the field. Also did some testing, by inducing events in Logstash 6.1.3 queue, then upgrading to 6.2.4 (using a new Docker image pointing to the same data directory).

We get the exact same error message.

Draining the queue using 6.1.3 works :-)