logstash log-courier plugin output not working properly

[dsolsona]

Hi Jason,

I'm back on trying to migrate my lumberjack logstash output configuration to log-courier.

I'm running logstash 1.4 on the logstash server where I have the log-courier output configured, and logsatsh 1.5 on the server where I have log-courier input.

I'm frequently seeing these errors in the logs

{:timestamp=>"2015-07-06T04:55:50.311000+0000", :hint=>"Unknown error, connection aborted", :peer=>"aa.bb.cc.dd:54255", :level=>:warn, :message=>"Unexpected end-of-input: expected close marker for OBJECT (from [Source: [B@3acde403; line: 1, column: 0])\n at [Source: [B@3acde403; line: 1, column: 2177]", :exception=>JrJackson::ParseError, :backtrace=>["com/jrjackson/JrJacksonRaw.java:75:in `parse_raw'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/jrjackson-0.2.9/lib/jrjackson/jrjackson.rb:23:in `load'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.1/lib/multi_json/adapters/jr_jackson.rb:11:in `load'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.7/lib/log-courier/server.rb:176:in `process_jdat'", "org/jruby/RubyKernel.java:1511:in `loop'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.7/lib/log-courier/server.rb:147:in `process_jdat'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.7/lib/log-courier/server.rb:76:in `run'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.7/lib/log-courier/server_tcp.rb:256:in `run'", "org/jruby/RubyKernel.java:1511:in `loop'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.7/lib/log-courier/server_tcp.rb:232:in `run'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.7/lib/log-courier/server_tcp.rb:203:in `run_thread'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.7/lib/log-courier/server_tcp.rb:167:in `run'"]}


{:timestamp=>"2015-07-06T04:55:56.359000+0000", :hint=>"Unknown error, connection aborted", :peer=>"aa.bb.cc.dd:54256", :level=>:warn, :message=>"Unexpected end-of-input: expected close marker for OBJECT (from [Source: [B@2dc269a9; line: 1, column: 0])\n at [Source: [B@2dc269a9; line: 1, column: 2177]", :exception=>JrJackson::ParseError, :backtrace=>["com/jrjackson/JrJacksonRaw.java:75:in `parse_raw'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/jrjackson-0.2.9/lib/jrjackson/jrjackson.rb:23:in `load'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.1/lib/multi_json/adapters/jr_jackson.rb:11:in `load'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.7/lib/log-courier/server.rb:176:in `process_jdat'", "org/jruby/RubyKernel.java:1511:in `loop'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.7/lib/log-courier/server.rb:147:in `process_jdat'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.7/lib/log-courier/server.rb:76:in `run'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.7/lib/log-courier/server_tcp.rb:256:in `run'", "org/jruby/RubyKernel.java:1511:in `loop'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.7/lib/log-courier/server_tcp.rb:232:in `run'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.7/lib/log-courier/server_tcp.rb:203:in `run_thread'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.7/lib/log-courier/server_tcp.rb:167:in `run'"]}

I can see that some log events are making it's way through both logstash servers.

[driskell]

I've not seen that error before. Do you notice any specific pattern or is it completely random?

[driskell]

I can see one bug here - which is the handling of the JrJackson::ParseError. But not sure why the event itself would not be valid JSON. I'll have a look further if I can but if you can get any more information that'll be great. Specific minor versions of Logstash would be useful to me also.

[driskell]

The fix I added gracefully handles broken JSON - unless other issues become apparent it will just mean the raw JSON that failed to parse gets send through Logstash instead. Might make it easier to locate any cause if you can find that raw event in Elasticsearch.

[driskell]

Hi - I had this reported again and investigated again, and found the problem. If the event contained multibyte sequences (characters with accents) in the output plugin, the protocol stream would corrupt as it was using character length instead of byte length in a few places. I'll push out 1.9 plugins shortly with fix.