SumoLogic/logstash-output-sumologic

invalid datetime format

Closed this issue · 10 comments

My current plugin is based off of your byi-queue-pool branch with debugging removed.
https://github.com/sstarcher/logstash-output-sumologic/tree/byi-queue-pool

Let me know I can get you the body, but once this error happened logstash stopped processing logs until I killed the server.

[2018-03-14T10:24:43,321][ERROR][logstash.outputs.sumologic] HTTP response 429 {:body=>"BODY", :headers=>{"X-Sumo-Host"=>"logstash-6444846f7-8jndq", "X-Sumo-Client"=>"logstash-output-sumologic", "Content-Encoding"=>"deflate", "Content-Type"=>"text/plain"}}
java.lang.IllegalArgumentException: Illegal pattern component: F
	at org.joda.time.format.DateTimeFormat.parsePatternTo(DateTimeFormat.java:566)
	at org.joda.time.format.DateTimeFormat.createFormatterForPattern(DateTimeFormat.java:687)
	at org.joda.time.format.DateTimeFormat.forPattern(DateTimeFormat.java:177)
	at org.logstash.StringInterpolation.evaluate(StringInterpolation.java:48)
	at org.logstash.Event.sprintf(Event.java:261)
	at org.logstash.ext.JrubyEventExtLibrary$RubyEvent.ruby_sprintf(JrubyEventExtLibrary.java:166)
	at usr.share.logstash.vendor.local_gems.e077d162.logstash_minus_output_minus_sumologic_minus_1_dot_1_dot_3.lib.logstash.outputs.sumologic.RUBY$method$expand$0(/usr/share/logstash/vendor/local_gems/e077d162/logstash-output-sumologic-1.1.3/lib/logstash/outputs/sumologic.rb:352)
	at usr.share.logstash.vendor.local_gems.e077d162.logstash_minus_output_minus_sumologic_minus_1_dot_1_dot_3.lib.logstash.outputs.sumologic.RUBY$method$event2log$0(/usr/share/logstash/vendor/local_gems/e077d162/logstash-output-sumologic-1.1.3/lib/logstash/outputs/sumologic.rb:296)
	at usr.share.logstash.vendor.local_gems.e077d162.logstash_minus_output_minus_sumologic_minus_1_dot_1_dot_3.lib.logstash.outputs.sumologic.RUBY$method$event2content$0(/usr/share/logstash/vendor/local_gems/e077d162/logstash-output-sumologic-1.1.3/lib/logstash/outputs/sumologic.rb:289)
	at usr.share.logstash.vendor.local_gems.e077d162.logstash_minus_output_minus_sumologic_minus_1_dot_1_dot_3.lib.logstash.outputs.sumologic.RUBY$method$receive$0(/usr/share/logstash/vendor/local_gems/e077d162/logstash-output-sumologic-1.1.3/lib/logstash/outputs/sumologic.rb:136)
	at usr.share.logstash.vendor.local_gems.e077d162.logstash_minus_output_minus_sumologic_minus_1_dot_1_dot_3.lib.logstash.outputs.sumologic.RUBY$block$multi_receive$1(/usr/share/logstash/vendor/local_gems/e077d162/logstash-output-sumologic-1.1.3/lib/logstash/outputs/sumologic.rb:125)
	at org.jruby.runtime.CompiledIRBlockBody.yieldDirect(CompiledIRBlockBody.java:156)
	at org.jruby.runtime.BlockBody.yield(BlockBody.java:114)
	at org.jruby.runtime.Block.yield(Block.java:165)
	at org.jruby.RubyArray.each(RubyArray.java:1734)
	at usr.share.logstash.vendor.local_gems.e077d162.logstash_minus_output_minus_sumologic_minus_1_dot_1_dot_3.lib.logstash.outputs.sumologic.RUBY$method$multi_receive$0(/usr/share/logstash/vendor/local_gems/e077d162/logstash-output-sumologic-1.1.3/lib/logstash/outputs/sumologic.rb:125)
	at usr.share.logstash.logstash_minus_core.lib.logstash.output_delegator_strategies.legacy.RUBY$method$multi_receive$0(/usr/share/logstash/logstash-core/lib/logstash/output_delegator_strategies/legacy.rb:22)
	at usr.share.logstash.logstash_minus_core.lib.logstash.output_delegator.RUBY$method$multi_receive$0(/usr/share/logstash/logstash-core/lib/logstash/output_delegator.rb:49)
	at usr.share.logstash.logstash_minus_core.lib.logstash.pipeline.RUBY$block$output_batch$3(/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:479)
	at org.jruby.runtime.CompiledIRBlockBody.yieldDirect(CompiledIRBlockBody.java:156)
	at org.jruby.runtime.BlockBody.yield(BlockBody.java:114)
	at org.jruby.runtime.Block.yield(Block.java:165)
	at org.jruby.RubyHash$12.visit(RubyHash.java:1362)
	at org.jruby.RubyHash$12.visit(RubyHash.java:1359)
	at org.jruby.RubyHash.visitLimited(RubyHash.java:662)
	at org.jruby.RubyHash.visitAll(RubyHash.java:647)
	at org.jruby.RubyHash.iteratorVisitAll(RubyHash.java:1319)
	at org.jruby.RubyHash.each_pairCommon(RubyHash.java:1354)
	at org.jruby.RubyHash.each(RubyHash.java:1343)
	at usr.share.logstash.logstash_minus_core.lib.logstash.pipeline.RUBY$method$output_batch$0(/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:478)
	at usr.share.logstash.logstash_minus_core.lib.logstash.pipeline.RUBY$method$worker_loop$0(/usr/share/logstash/logstash-core/lib/logstash/pipeline.rb:430)
	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:385)
	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)

I think there are 2 different problems.

For HTTP 429, it's because the data volume exceeded the quota of your organization. If the volume is expected, you should contact SumoLogic support team through Zendesk to adjust the quota temporary or permanently:
screenshot 2018-03-14 10 10 35

For the DateTimeFormat exception, looks like the input event has an incompatible timestamp. (we expect there is @timestamp field in event object which is a valid timestamp.) May because of a customized format configuration. Could you please provide the :format you currently using and a sample event from your input?

@bin3377 without any configuration changes on our end it was functioning for 24 hours prior to it hanging due to the error. After terminating it, it started functioning again. I understand if somehow it got an invalid event, but when it gets an invalid event it should not stop functioning until someone restarts it.

ya, the 429 does not really concern me it's understandable

The format for the sumologic output is format=>"%{@json}"

I agree adding some exception handling is a valid point.
But as the logstash SDK the @timestamp should be a valid ISO8601 timestamp, which I think should be a bug in your input or filter plugin

The setup is very basic filebeat(6.2.2) -> redis -> logstash(6.2.2) -> sumologic(byi-queue-pool).
Somehow an invalid value got in the system and logstash-output-sumologic chocked the system at least from what I can tell.

We didn't handle the timestamp individually in our code but only call event.sprintf(template) from logstash and now it throw an exception (which is not there earlier following what you said). So the root cause must be input/logstash engine somehow pass an invalid object to the output plugin.

sounds like the root of the issue, but my request is not for you to fix the invalid data coming in, but to catch the exception and log the failure instead of returning an exception to the pipe.

yep. I said I agree there could be some exception handling but it really an edge case for an invalid timestamp here since it's not following the logstash SDK

Certainly I only really raised the issue due to it halting all log ingestion.