Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Possible Logstash 2.0 compatibility issue #247

Closed
juanqui opened this issue Oct 31, 2015 · 28 comments
Closed

Possible Logstash 2.0 compatibility issue #247

juanqui opened this issue Oct 31, 2015 · 28 comments

Comments

@juanqui
Copy link

juanqui commented Oct 31, 2015

I recently upgraded a small dev cluster to logstash 2.0 and elasticsearch 2.0. We've been using logstash-forwarder in our infrastructure, but I wanted to give log-courier a short (specifically because of client-side multiline codec support!). I see that very recently a patch was dropped to add compatibility for logstash 2.0 (v1.8.2). Nevertheless, I seem to be having some issue with my configuration.

I have two logstash inputs configured.

1 - logstash forwarder

input {
  lumberjack {
    port => 16789
    ssl_certificate => "/etc/logstash/ssl/logstash.crt"
    ssl_key => "/etc/logstash/ssl/logstash.key"
  }
}

2 - log courier

input {
  courier {
    port => 18789
    ssl_certificate => "/etc/logstash/ssl/logstash.crt"
    ssl_key => "/etc/logstash/ssl/logstash.key"
  }
}

My courier clients are configured the following way:

{
    "general": {
        "log stdout": true
    },
    "network": {
        "servers": [
            "cp3logstash01.blah.com:18789"
        ],
        "ssl ca": "/etc/logstash-ssl-ca.crt",
        "timeout": 15
    },
    "files": [
        {
            "fields": {
                "app": "blah",
                "env": "prod",
                "type": "python-verbose"
            },
            "paths": [
                "/etc/sv/blah-web/log/main/current"
            ]
        },
        {
            "fields": {
                "app": "blah",
                "env": "prod",
                "type": "python-celery"
            },
            "paths": [
                "/etc/sv/blah-worker/log/main/current"
            ]
        }
    ]
}

When I start one of the log-courier process I immediately start seeing the following errors in logstash:

{
  :timestamp=>"2015-10-31T19:36:00.580000+0000", 
  :message=>"Attempted to send a bulk request to Elasticsearch configured at '[\"http://cp3elasticlogs01.blah.com:9200/\", 
            \"http://cp3elasticlogs02.blah.com:9200/\", \"http://cp3elasticlogs03.blah.com:9200/\"]', but an error occurred and 
            it failed! Are you sure you can reach elasticsearch from this machine using the configuration provided?", 
  :client_config=>{
    :hosts=>["http://cp3elasticlogs01.blah.com:9200/", "http://cp3elasticlogs02.blah.com:9200/", 
    "http://cp3elasticlogs03.blah.com:9200/"], 
    :ssl=>nil, 
    :transport_options=>{
      :socket_timeout=>0, 
      :request_timeout=>0, 
      :proxy=>nil, :ssl=>{}}, 
    :transport_class=>Elasticsearch::Transport::Transport::HTTP::Manticore, 
    :logger=>nil, 
    :tracer=>nil, 
    :reload_connections=>false, 
    :retry_on_failure=>false, 
    :reload_on_failure=>false, 
    :randomize_hosts=>false
  }, 
  :error_message=>"Failed to load class 'org.jruby.RubyObject$Access4JacksonDeserializer45931591': 
                  com.fasterxml.jackson.module.afterburner.ser.BeanPropertyAccessor", 
  :error_class=>"JrJackson::ParseError", 
  :backtrace=>[
    "com/jrjackson/JrJacksonBase.java:83:in `generate'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/jrjackson-0.3.6/lib/jrjackson/jrjackson.rb:59:in `dump'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.2/lib/multi_json/adapters/jr_jackson.rb:20:in `dump'",
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.2/lib/multi_json/adapter.rb:25:in `dump'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.2/lib/multi_json.rb:136:in `dump'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/elasticsearch-api-1.0.14/lib/elasticsearch/api/utils.rb:102:in `__bulkify'", 
    "org/jruby/RubyArray.java:2414:in `map'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/elasticsearch-api-1.0.14/lib/elasticsearch/api/utils.rb:102:in `__bulkify'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/elasticsearch-api-1.0.14/lib/elasticsearch/api/actions/bulk.rb:82:in `bulk'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch/http_client.rb:56:in `bulk'",
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:353:in `submit'", 
    "org/jruby/ext/thread/Mutex.java:149:in `synchronize'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:350:in `submit'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:382:in `flush'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/buffer.rb:219:in `buffer_flush'", 
    "org/jruby/RubyHash.java:1342:in `each'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/buffer.rb:216:in `buffer_flush'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/buffer.rb:193:in `buffer_flush'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/buffer.rb:159:in `buffer_receive'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:343:in `receive'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/outputs/base.rb:80:in `handle'", "(eval):187:in `output_func'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/pipeline.rb:252:in `outputworker'", 
    "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/pipeline.rb:169:in `start_outputs'"], 
  :level=>:error
}

I'm not sure if this is being caused by the combination of logstash 2.0 and elasticsearch 2.0.

According to the release notes on logstash 2.0, the JrJackson library was upgraded.

JSON processing: We updated to a new version of JrJackson, which is the JSON serialization/deserialization library used in Logstash. In addition to fixes, this provides good performance boosts when dealing with JSON.

I'm going to keep on looking into it as I have time.

Found a possibly similar issue...
elastic/logstash#3289

Thanks for the awesome project @driskell

@driskell
Copy link
Owner

Ahhhh odd! Much like filebeat now does courier uses JSON in the transport so you can have array fields and tags etc.

At the input plugin courier uses JrJackson just like Logstash does in order to decode the network data.

Could it be related to filters? Is it feasible to replay log files until you find one that reproduces and try to isolate the offending log lines maybe?

Regarding the update to 2.0 compatibility there's actually no behavioural change except shutdown so I think unrelated to courier plugin, but we can keep an open mind though!

@driskell
Copy link
Owner

Sorry I was meant to say, because JrJackson is used to deserialise and then by ES output to serialise I would expect it to be fine (unless a JrJackson bug) - this my thoughts on filters that may change the event.

@juanqui
Copy link
Author

juanqui commented Oct 31, 2015

Thanks for the ideas @driskell ! I'll try a few simple thing like disabling all filters, then I'll narrow down from there.

@juanqui
Copy link
Author

juanqui commented Oct 31, 2015

No luck! I disabled all the filters. I left only logstash-forwarder and courier inputs and the elasticsearch output. Same errors.

@driskell
Copy link
Owner

Does it occur immediately? Or after a while? Have you disabled forwarder input to test that?

What if you run Logstash with debug flag, it'll tell you events as it processes them so maybe point towards the problem event.

@juanqui
Copy link
Author

juanqui commented Oct 31, 2015

It happens immediately. I'm going to test disabling the forwarder input and enable the debug flag.

@juanqui
Copy link
Author

juanqui commented Oct 31, 2015

I know these are not beautifully formatted and little hard to read :(

I enabled the debug flag, and disabled everything except for courier input, ES output, and then started a single log-courier agent.

After the first message, it failed with the same error.

{:timestamp=>"2015-10-31T22:35:17.946000+0000", :message=>"New connection", :peer=>"10.165.120.106:41483", :level=>:info, :file=>"log-courier/server_tcp.rb", :line=>"158", :method=>"run"}

{:timestamp=>"2015-10-31T22:35:18.288000+0000", :message=>"output received", :event=>{"message"=>"#EXT-X-KEY:METHOD=AES-128,URI=\"KBLAH_4.key\",IV=0x00000000000000000000000000000048", "@timestamp"=>"2015-10-31T22:35:18.285Z", "app"=>"blahgovod", "host"=>"cp3blahgovod01", "path"=>"/etc/sv/blahgovod-worker/log/main/current", "env"=>"prod", "type"=>"python-celery", "offset"=>0, "@version"=>"1"}, :level=>:debug, :file=>"(eval)", :line=>"21", :method=>"output_func"}

{:timestamp=>"2015-10-31T22:35:18.322000+0000", :message=>"Flushing output", :outgoing_count=>1, :time_since_last_flush=>27.422, :outgoing_events=>{nil=>[["index", {:_id=>nil, :_index=>"logstash-2015.10.31", :_type=>"python-celery", :_routing=>nil}, #<LogStash::Event:0x8001a94 @metadata={"retry_count"=>0}, @accessors=#<LogStash::Util::Accessors:0x6e3f482 @store={"message"=>"#EXT-X-KEY:METHOD=AES-128,URI=\"KBLAH_4.key\",IV=0x00000000000000000000000000000048", "@timestamp"=>"2015-10-31T22:35:18.285Z", "app"=>"blahgovod", "host"=>"cp3blahgovod01", "path"=>"/etc/sv/blahgovod-worker/log/main/current", "env"=>"prod", "type"=>"python-celery", "offset"=>0, "@version"=>"1"}, @lut={"type"=>[{"message"=>"#EXT-X-KEY:METHOD=AES-128,URI=\"KBLAH_4.key\",IV=0x00000000000000000000000000000048", "@timestamp"=>"2015-10-31T22:35:18.285Z", "app"=>"blahgovod", "host"=>"cp3blahgovod01", "path"=>"/etc/sv/blahgovod-worker/log/main/current", "env"=>"prod", "type"=>"python-celery", "offset"=>0, "@version"=>"1"}, "type"]}>, @data={"message"=>"#EXT-X-KEY:METHOD=AES-128,URI=\"KBLAH_4.key\",IV=0x00000000000000000000000000000048", "@timestamp"=>"2015-10-31T22:35:18.285Z", "app"=>"blahgovod", "host"=>"cp3blahgovod01", "path"=>"/etc/sv/blahgovod-worker/log/main/current", "env"=>"prod", "type"=>"python-celery", "offset"=>0, "@version"=>"1"}, @metadata_accessors=#<LogStash::Util::Accessors:0x38811c19 @store={"retry_count"=>0}, @lut={}>, @cancelled=false>]]}, :batch_timeout=>1, :force=>nil, :final=>nil, :level=>:debug, :file=>"stud/buffer.rb", :line=>"207", :method=>"buffer_flush"}

{:timestamp=>"2015-10-31T22:35:18.428000+0000", :message=>"Attempted to send a bulk request to Elasticsearch configured at '[\"http://cp3elasticlogs01.blah.com:9200/\", \"http://cp3elasticlogs02.blah.com:9200/\", \"http://cp3elasticlogs03.blah.com:9200/\"]', but an error occurred and it failed! Are you sure you can reach elasticsearch from this machine using the configuration provided?", :client_config=>{:hosts=>["http://cp3elasticlogs01.blah.com:9200/", "http://cp3elasticlogs02.blah.com:9200/", "http://cp3elasticlogs03.blah.com:9200/"], :ssl=>nil, :transport_options=>{:socket_timeout=>0, :request_timeout=>0, :proxy=>nil, :ssl=>{}}, :transport_class=>Elasticsearch::Transport::Transport::HTTP::Manticore, :level=>:debug, :logger=>nil, :tracer=>nil, :reload_connections=>false, :retry_on_failure=>false, :reload_on_failure=>false, :randomize_hosts=>false}, :error_message=>"Failed to load class 'org.jruby.RubyObject$Access4JacksonDeserializer45931591': com.fasterxml.jackson.module.afterburner.ser.BeanPropertyAccessor", :error_class=>"JrJackson::ParseError", :backtrace=>["com/jrjackson/JrJacksonBase.java:83:in `generate'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/jrjackson-0.3.6/lib/jrjackson/jrjackson.rb:59:in `dump'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.2/lib/multi_json/adapters/jr_jackson.rb:20:in `dump'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.2/lib/multi_json/adapter.rb:25:in `dump'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.2/lib/multi_json.rb:136:in `dump'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/elasticsearch-api-1.0.14/lib/elasticsearch/api/utils.rb:102:in `__bulkify'", "org/jruby/RubyArray.java:2414:in `map'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/elasticsearch-api-1.0.14/lib/elasticsearch/api/utils.rb:102:in `__bulkify'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/elasticsearch-api-1.0.14/lib/elasticsearch/api/actions/bulk.rb:82:in `bulk'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch/http_client.rb:56:in `bulk'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:353:in `submit'", "org/jruby/ext/thread/Mutex.java:149:in `synchronize'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:350:in `submit'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:382:in `flush'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/buffer.rb:219:in `buffer_flush'", "org/jruby/RubyHash.java:1342:in `each'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/buffer.rb:216:in `buffer_flush'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/buffer.rb:159:in `buffer_receive'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:343:in `receive'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/outputs/base.rb:80:in `handle'", "(eval):22:in `output_func'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/pipeline.rb:252:in `outputworker'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/pipeline.rb:169:in `start_outputs'"], :level=>:error, :file=>"logstash/outputs/elasticsearch.rb", :line=>"396", :method=>"flush"}}

{:timestamp=>"2015-10-31T22:35:18.433000+0000", :message=>"Failed actions for last bad bulk request!", :actions=>[["index", {:_id=>nil, :_index=>"logstash-2015.10.31", :_type=>"python-celery", :_routing=>nil}, #<LogStash::Event:0x8001a94 @metadata={"retry_count"=>0}, @accessors=#<LogStash::Util::Accessors:0x6e3f482 @store={"message"=>"#EXT-X-KEY:METHOD=AES-128,URI=\"KBLAH_4.key\",IV=0x00000000000000000000000000000048", "@timestamp"=>"2015-10-31T22:35:18.285Z", "app"=>"blahgovod", "host"=>"cp3blahgovod01", "path"=>"/etc/sv/blahgovod-worker/log/main/current", "env"=>"prod", "type"=>"python-celery", "offset"=>0, "@version"=>"1"}, @lut={"type"=>[{"message"=>"#EXT-X-KEY:METHOD=AES-128,URI=\"K22347360_4.key\",IV=0x00000000000000000000000000000048", "@timestamp"=>"2015-10-31T22:35:18.285Z", "app"=>"blahgovod", "host"=>"cp3blahgovod01", "path"=>"/etc/sv/blahgovod-worker/log/main/current", "env"=>"prod", "type"=>"python-celery", "offset"=>0, "@version"=>"1"}, "type"]}>, @data={"message"=>"#EXT-X-KEY:METHOD=AES-128,URI=\"KBLAH_4.key\",IV=0x00000000000000000000000000000048", "@timestamp"=>"2015-10-31T22:35:18.285Z", "app"=>"blahgovod", "host"=>"cp3blahgovod01", "path"=>"/etc/sv/blahgovod-worker/log/main/current", "env"=>"prod", "type"=>"python-celery", "offset"=>0, "@version"=>"1"}, @metadata_accessors=#<LogStash::Util::Accessors:0x38811c19 @store={"retry_count"=>0}, @lut={}>, @cancelled=false>]], :level=>:debug, :file=>"logstash/outputs/elasticsearch.rb", :line=>"405", :method=>"flush"}

@sysmonk
Copy link
Contributor

sysmonk commented Nov 2, 2015

Hi,

Unfortunately, i see the same issue. Log-courier 1.8.2 and Logstash 2.0 (with the latest 1.8.2 log-courier plugin) and ES 1.5. Let me know if i can help debug this issue.

@kabakaev
Copy link

kabakaev commented Nov 2, 2015

Looks like some library was updated in both logstash-1.5.5 and logstash-2.0, which is not compatible. I rolled back to logstash-1.5.4 and it works fine, even with elasticsearch-2.0.

@driskell
Copy link
Owner

driskell commented Nov 2, 2015

Hmmm. Could someone try the file input with a file that reproduces, to see if it is indeed the fault of courier? I'll look some more into it and try some more exoteric log files and field configurations.

@sysmonk
Copy link
Contributor

sysmonk commented Nov 3, 2015

Here is my test:

# tail -10 /var/log/auth.log > /tmp/auth.log

cat /tmp/auth.log

Nov  3 07:48:43 logstash1 sshd[25872]: Connection closed by 127.0.0.1 [preauth]
Nov  3 07:49:14 logstash1 sshd[25883]: Set /proc/self/oom_score_adj to 0
Nov  3 07:49:14 logstash1 sshd[25883]: Connection from 127.0.0.1 port 13536 on 127.0.0.1 port 22
Nov  3 07:49:14 logstash1 sshd[25883]: Connection closed by 127.0.0.1 [preauth]
Nov  3 07:49:43 logstash1 sudo:   nagios : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/....sh
Nov  3 07:49:43 logstash1 sudo: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov  3 07:49:43 logstash1 sudo: pam_unix(sudo:session): session closed for user root
Nov  3 07:49:44 logstash1 sshd[25942]: Set /proc/self/oom_score_adj to 0
Nov  3 07:49:44 logstash1 sshd[25942]: Connection from 127.0.0.1 port 13542 on 127.0.0.1 port 22
Nov  3 07:49:44 logstash1 sshd[25942]: Connection closed by 127.0.0.1 [preauth]

cat /home/logstash/test/10-input.conf

input {

    courier {
        port        => 9000
        transport   => "plainzmq"
    }

    courier {
        port => 9001
        ssl_certificate   => "/home/logstash/config/log-courier.crt"
        ssl_key           => "/home/logstash/config/log-courier.key"
    }
}


filter {

        if "authlog" == [type] {
                grok {
                        match => [
                                "message", "^%{SYSLOGBASE}"
                        ]
                        tag_on_failure => [ ]
                }

        }

}

output {

        if "authlog" == [type] {
                elasticsearch {
                        hosts        => [
                                "es1.example.com:9200",
                                "es2.example.com:9200",
                                "es3.example.com:9200",
                                "es4.example.com:9200",
                                "es5.example.com:9200"
                            ]
                        flush_size  => 2000
                        workers     => 1
                        index       => "authlog-%{+xxxx.ww}"
                }
        }

}

cat /tmp/log-courier.conf

{
        "general": {
                "spool timeout": 5,
                "spool size": 128,
                "log level" : "info",
                "log syslog" : true,
                "admin enabled": true,
                "admin listen address": "unix:/var/run/log-courier-admin.socket"
        },
        "network": {
                "servers": [ "logstash1.example.com:9001" ],
                "ssl ca": "/usr/local/share/logstash/logstash.crt",
                "timeout": 60,
                "reconnect": 20,
                "max pending payloads": 5
        },
        "includes": [
                "/etc/log-courier.d/*.conf"
        ]
}

cat /etc/log-courier.d/99-global.conf

[
        {
                "paths": [ "/var/log/auth.log" ],
                "fields": { "type": "authlog" }
        }
]
# /home/logstash/bin/logstash agent -f /home/logstash/test/10-input.conf -w 4 --log /tmp/test.log
# /usr/local/bin/log-courier -config /tmp/log-courier.conf 

And the result is:

tail -2 /tmp/test.log

{:timestamp=>"2015-11-03T07:47:49.137000+0000", :message=>"Attempted to send a bulk request to Elasticsearch configured at '[\"http://es1.example.com:9200/\", \"http://es2.example.com:9200/\", \"http://es3.example.com:9200/\", \"http://es4.example.com:9200/\", \"http://es5.example.com:9200/\"]', but an error occurred and it failed! Are you sure you can reach elasticsearch from this machine using the configuration provided?", :client_config=>{:hosts=>["http://es1.example.com:9200/", "http://es2.example.com:9200/", "http://es3.example.com:9200/", "http://es4.example.com:9200/", "http://es5.example.com:9200/"], :ssl=>nil, :transport_options=>{:socket_timeout=>0, :request_timeout=>0, :proxy=>nil, :ssl=>{}}, :transport_class=>Elasticsearch::Transport::Transport::HTTP::Manticore, :logger=>nil, :tracer=>nil, :reload_connections=>false, :retry_on_failure=>false, :reload_on_failure=>false, :randomize_hosts=>false}, :error_message=>"Failed to load class 'org.jruby.RubyObject$Access4JacksonDeserializer45931591': com.fasterxml.jackson.module.afterburner.ser.BeanPropertyAccessor", :error_class=>"JrJackson::ParseError", :backtrace=>["com/jrjackson/JrJacksonBase.java:83:in `generate'", "/home/logstash/vendor/bundle/jruby/1.9/gems/jrjackson-0.3.6/lib/jrjackson/jrjackson.rb:59:in `dump'", "/home/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.2/lib/multi_json/adapters/jr_jackson.rb:20:in `dump'", "/home/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.2/lib/multi_json/adapter.rb:25:in `dump'", "/home/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.2/lib/multi_json.rb:136:in `dump'", "/home/logstash/vendor/bundle/jruby/1.9/gems/elasticsearch-api-1.0.14/lib/elasticsearch/api/utils.rb:102:in `__bulkify'", "org/jruby/RubyArray.java:2414:in `map'", "/home/logstash/vendor/bundle/jruby/1.9/gems/elasticsearch-api-1.0.14/lib/elasticsearch/api/utils.rb:102:in `__bulkify'", "/home/logstash/vendor/bundle/jruby/1.9/gems/elasticsearch-api-1.0.14/lib/elasticsearch/api/actions/bulk.rb:82:in `bulk'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch/http_client.rb:56:in `bulk'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:353:in `submit'", "org/jruby/ext/thread/Mutex.java:149:in `synchronize'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:350:in `submit'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:382:in `flush'", "/home/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/buffer.rb:219:in `buffer_flush'", "org/jruby/RubyHash.java:1342:in `each'", "/home/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/buffer.rb:216:in `buffer_flush'", "/home/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/buffer.rb:159:in `buffer_receive'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:343:in `receive'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/outputs/base.rb:80:in `handle'", "(eval):52:in `output_func'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/pipeline.rb:252:in `outputworker'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/pipeline.rb:169:in `start_outputs'"], :level=>:error}
{:timestamp=>"2015-11-03T07:47:49.139000+0000", :message=>"Failed to flush outgoing items", :outgoing_count=>1, :exception=>"JrJackson::ParseError", :backtrace=>["com/jrjackson/JrJacksonBase.java:83:in `generate'", "/home/logstash/vendor/bundle/jruby/1.9/gems/jrjackson-0.3.6/lib/jrjackson/jrjackson.rb:59:in `dump'", "/home/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.2/lib/multi_json/adapters/jr_jackson.rb:20:in `dump'", "/home/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.2/lib/multi_json/adapter.rb:25:in `dump'", "/home/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.2/lib/multi_json.rb:136:in `dump'", "/home/logstash/vendor/bundle/jruby/1.9/gems/elasticsearch-api-1.0.14/lib/elasticsearch/api/utils.rb:102:in `__bulkify'", "org/jruby/RubyArray.java:2414:in `map'", "/home/logstash/vendor/bundle/jruby/1.9/gems/elasticsearch-api-1.0.14/lib/elasticsearch/api/utils.rb:102:in `__bulkify'", "/home/logstash/vendor/bundle/jruby/1.9/gems/elasticsearch-api-1.0.14/lib/elasticsearch/api/actions/bulk.rb:82:in `bulk'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch/http_client.rb:56:in `bulk'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:353:in `submit'", "org/jruby/ext/thread/Mutex.java:149:in `synchronize'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:350:in `submit'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:382:in `flush'", "/home/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/buffer.rb:219:in `buffer_flush'", "org/jruby/RubyHash.java:1342:in `each'", "/home/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/buffer.rb:216:in `buffer_flush'", "/home/logstash/vendor/bundle/jruby/1.9/gems/stud-0.0.22/lib/stud/buffer.rb:159:in `buffer_receive'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.1.2-java/lib/logstash/outputs/elasticsearch.rb:343:in `receive'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/outputs/base.rb:80:in `handle'", "(eval):52:in `output_func'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/pipeline.rb:252:in `outputworker'", "/home/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/pipeline.rb:169:in `start_outputs'"], :level=>:warn}

If i kill log-courier and change the input {} to be:

input {

    courier {
        port        => 9000
        transport   => "plainzmq"
    }

    courier {
        port => 9001
        ssl_certificate   => "/home/logstash/config/log-courier.crt"
        ssl_key           => "/home/logstash/config/log-courier.key"
    }

        file {
                path => "/tmp/auth.log"
                type => "authlog"
                sincedb_path => "/tmp/auth.log.sincedb"
                start_position => "beginning"
        }
}

And start logstash again with the same command, i don't get anything in /tmp/test.log

@driskell
Copy link
Owner

driskell commented Nov 3, 2015

Thanks! I just managed to reproduce it using output { stdout { codec => json } } and some real logs. Looking at it now.

@driskell
Copy link
Owner

driskell commented Nov 3, 2015

Tracking this a little in logstash-plugins/logstash-output-elasticsearch#294

Traced it to a JrJackson issue I believe. Gonna raise there and see where we get in next day or so. If not much progress I have a workaround, it just slows the JSON processing slightly (not sure how much). It's to do with how the Courier input lets JrJackson produce Java objects rather than Ruby objects, and it's always worked fine, but it seems the updated JrJackson in Logstash 2.0.0 is having issues when serialising again to send to Elasticsearch. Just means we have to disable this and use Ruby objects. JrJackson is native Java though so it's a slight overhead, hopefully negligible if we have to disable it.

@driskell
Copy link
Owner

driskell commented Nov 4, 2015

I'm looking at releasing an update to Courier plugin soon to workaround this issue, and will revisit once it's fixed in JrJackson and Logstash is updated with the fixed version (which could be some time, thus the workaround plan.)

@packplusplus
Copy link

👍

Also running into this. @driskell Which issue do we want pushed on thru ES support? logstash-plugins/logstash-output-elasticsearch/issues/294

@groeney
Copy link

groeney commented Nov 7, 2015

Awesome, glad I ran into this thread. Been battling with this for a bit over a week. In my case it was the courier input, to an output plugin trying to use the json or json_lines codec. https://discuss.elastic.co/t/json-codec-crashing-logstash/33680

Is there any workaround (like applying some filter to achieve same result as only using Ruby objects) that we could apply in the meantime?

thanks again for this project @driskell

@groeney
Copy link

groeney commented Nov 7, 2015

for now i just downgraded to logstash-1.5.4 (note: not logstash-1.5.5, still has same issue).

@driskell
Copy link
Owner

driskell commented Nov 8, 2015

I just pushed logstash-input-courier 1.8.3
Could you give it a go? It works around the JrJackson problem in 1.5.5 and 2.0.0

Thanks

@driskell
Copy link
Owner

driskell commented Nov 8, 2015

Unfortunately 1.8.3 regressed the compatibility too 👎
I've just pushed 1.8.4 - all should be working - please let me know if not.

@juanqui
Copy link
Author

juanqui commented Nov 8, 2015

Awesome stuff @driskell ! Thanks a ton! I'll check it out this week.

@sisoftrg
Copy link

sisoftrg commented Nov 9, 2015

After updating from 1.8.2 to 1.8.4 with logstash-2.0.0, logstash stop working at all:

RuntimeError: Logstash expects concurrent-ruby version 0.9.1 and version 0.9.2 is installed, please verify this patch: /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/patches/silence_concurrent_ruby_warning.rb
   (root) at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/patches/silence_concurrent_ruby_warning.rb:53
  require at org/jruby/RubyKernel.java:1040
   (root) at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/patches.rb:1
  require at org/jruby/RubyKernel.java:1040
   (root) at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/patches.rb:6
  require at org/jruby/RubyKernel.java:1040
   (root) at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.0.0-java/lib/logstash/environment.rb:1
  require at org/jruby/RubyKernel.java:1040
   (root) at /opt/logstash/lib/bootstrap/environment.rb:48

Uninstalling plugin doesn't help. But all start to work after completely uninstalling logstash, removing files from /opt/logstash/vendor/ and reinstalling lostash + log-courier. Seems that above described problem is solved.

Another problem - logstash can't stop now:

Killing logstash (pid 5100) with SIGTERM
Waiting logstash (pid 5100) to die...
Waiting logstash (pid 5100) to die...
Waiting logstash (pid 5100) to die...
Waiting logstash (pid 5100) to die...
Waiting logstash (pid 5100) to die...
logstash stop failed; still running.

From logstash log:

{:timestamp=>"2015-11-09T09:17:03.903000+0000", :message=>"SIGTERM received. Shutting down the pipeline.", :level=>:warn}
{:timestamp=>"2015-11-09T09:17:05.977000+0000", :message=>["INFLIGHT_EVENTS_REPORT", "2015-11-09T09:17:05+00:00", {"input_to_filter"=>0, "filter_to_output"=>0, "outputs"=>[]}], :level=>:warn}
{:timestamp=>"2015-11-09T09:17:08.905000+0000", :message=>["INFLIGHT_EVENTS_REPORT", "2015-11-09T09:17:08+00:00", {"input_to_filter"=>0, "filter_to_output"=>0, "outputs"=>[]}], :level=>:warn}

after 10mins log have many INFLIGHT_EVENTS_REPORT, logstash continues processing new logs. I can stop it only with sigkill.

@packplusplus
Copy link

EDITED
I know it's bad form to edit previously posted comments, but the initial report was wrongly indicating objects made it to the filter correctly. The always driskell updated the thread anyways, because he is awesome and makes this better.

Simple low volume syslog messages with grok are fine, but when it's a 10meg file of weblogs (including unicode chars), I'm seeing corrupted objects stored in ES. Like objects aren't getting to the filter as individual json objects, but clumps with \u0000\u0000\u0004� in between each object (that last unicode char changes). Causes JrJackson errors.

Messages are not grok'd correctly because they are malformed json. I originally thought the groks were happening but I was seeing @timestamps, paths, and other fields added by the input.

Client:

  • centos 5
  • java-1.7.0-openjdk-1.7.0.85-2.6.1.3.el5_11
  • logstash 2.0
  • logstash-output-courier (1.8.4)

Server:

  • centos 6
  • java-1.8.0-openjdk-headless-1.8.0.65-0.b17.el6_7.x86_64
  • logstash 2.0 and 1.5.4
  • logstash-input-courier (1.8.4)

Client shows no errors

Server, errors like

Unexpected end-of-input: expected close marker for OBJECT (from [Source: [B@38adad5; line: 1, column: 0])
 at [Source: [B@38adad5; line: 1, column: 3611] {:invalid_encodings=>0, :hint=>"JSON parse failure, falling back to plain-text", :level=>:warn, :exception=>JrJackson::ParseError, :backtrace=>["com/jrjackson/JrJacksonRuby.java:63:in `parse'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/jrjackson-0.3.6/lib/jrjackson/jrjackson.rb:49:in `load'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/multi_json-1.11.2/lib/multi_json/adapters/jr_jackson.rb:11:in `load'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server.rb:203:in `process_jdat'", "org/jruby/RubyKernel.java:1479:in `loop'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server.rb:168:in `process_jdat'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server.rb:91:in `run'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server_tcp.rb:274:in `process_messages'", "org/jruby/RubyKernel.java:1479:in `loop'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server_tcp.rb:250:in `process_messages'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server_tcp.rb:238:in `run'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server_tcp.rb:204:in `run_thread'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server_tcp.rb:167:in `run'"]}
Cabin::Channel#warn(message, data={}) requires at least 1 argument {:hint=>"Unknown error, connection aborted", :peer=>"EGRESSIP:58953", :level=>:warn, :exception=>ArgumentError, :backtrace=>["/opt/logstash/vendor/bundle/jruby/1.9/gems/cabin-0.7.1/lib/cabin/mixins/logger.rb:47:in `warn'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server.rb:182:in `process_jdat'", "org/jruby/RubyKernel.java:1479:in `loop'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server.rb:168:in `process_jdat'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server.rb:91:in `run'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server_tcp.rb:274:in `process_messages'", "org/jruby/RubyKernel.java:1479:in `loop'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server_tcp.rb:250:in `process_messages'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server_tcp.rb:238:in `run'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server_tcp.rb:204:in `run_thread'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/log-courier-1.8.3/lib/log-courier/server_tcp.rb:167:in `run'"]}

@driskell
Copy link
Owner

@packplusplus This was reported before in #200 but I didn't locate the problem initially. I've found the output plugin incorrectly using character length instead of byte length, so if the event going out had multibyte characters it would corrupt the protocol stream. Will push out 1.9 plugins soon.

@sisoftrg Apologies for that issue - I've been separating the plugin code from Log Courier into other repositories and it looks like one of the compatibility patches didn't make it through. Specifically, the one to update the shutdown code (which is triggered differently in Logstash 2.0.0) - this will also be fixed in 1.9 plugins which I'll get out shortly.

driskell added a commit to driskell/logstash-output-courier that referenced this issue Nov 10, 2015
Increase log-courier gem dependency for byte/length fix
Fixes driskell/log-courier#247
Fixes driskell/log-courier#200
1.9.0
@driskell
Copy link
Owner

@sisoftrg Regarding the concurrent-ruby gem problem. This is known issue in Logstash and it seems it can occur when updating plugins. It is being tracked at elastic/logstash#4141.

To fix without reinstalling Logstash:

  1. Add gem "concurrent-ruby", "0.9.1" to the bottom of Gemfile in the Logstash directory
  2. Attempt to update any plugin, e.g. bin/plugin update logstash-input-tcp. Even if the plugin doesn't update it triggers a rollback for the concurrent-ruby gem
  3. Future plugin updates will no longer break the concurrent-ruby version due to the Gemfile entry

@sisoftrg
Copy link

@driskell, Thanks.
Currently I have 2.0-based pipeline running full day at ~1500 loglines per second and all works well, no any i/o timeouts and duplicates, which happens early with log-forwarder.

@disaster37
Copy link

I have tried the solution on logstash 1.5.5, but I have still error:
LogStash::Json::GeneratorError: Failed to load class 'org.jruby.RubyObject$Access4JacksonDeserializer01a41575': com.fasterxml.jacon.module.afterburner.ser.BeanPropertyAccessor

@driskell
Copy link
Owner

@disaster37 Can you confirm you updated the plugin to 1.9.0? As well as followed the steps for concurrent-ruby if you encountered an issue with it after updating?

@disaster37
Copy link

I have added on my Gemfile:
gem "concurrent-ruby", "0.9.1"

And I have edit my Gemfile.jruby-1.9.lock to modify
logstash-input-courier (1.9.0)
log-courier (= 1.9.0)
logstash-core (~> 1.4)

After that I have run:
bin/plugin install logstash-input-tcp (I can't use update because of it not support proxy)
bin/plugin update logstash-input-courier

With that the problem persist.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

8 participants