transport error, will try again: EOF

[driskell]

transport error, will try again: EOF

[driskell]

Can you share your courier and logstash configs? Best to close #43 and out the entry here it is likely related.

[tedder]

Here is the top of my courier config; the rest is picking up more files, I don't think it's relevant, but lemme know. The logcourier_transport is set to TCP.

Logcourier client

{
  "general": {
    "persist directory": "/opt/logcourier",
    "log stdout": false,
    "log syslog": true,
    "log level": "warning"
  },
  "network": {
    "servers": [ "{{logcourier_forwarder_host}}:{{logcourier_forwarder_port}}" ],
    "transport": "{{logcourier_transport}}"
  },
  "files": [
    {
      "paths": [
        "/var/log/syslog"
      ],

Logcourier server

Again, transport is TCP.

input {
  courier {
    # The port to listen on
    port => {{logcourier_input_port}}
    transport => {{logcourier_transport}}
  }
}

[driskell]

Do you get any other messages in the logstash logs apart from failed to flush?

When courier gets EOF it normally means logstash plugin closed the connection - but it normally states the reason in logstash logs. Can you check?

[driskell]

Hi @tedder did you manage to get any further into this?

[tedder]

hey- you sent this as I was leaving on vacation. I'm back, I'll get it to you within the next few days.

[aaliang]

hey @driskell, this may be an unrelated issue to @tedder's error but it appears that max_packet_size is no longer being defaulted on logstash's side. Seems to work correctly if you set a max_packet_size in the logstash conf

I have commit 7cd0c63

log-courier gives me transport error EOF's
without specifying a max_packet_size I consistently get an error on transport:

'[LogCourierServer] ["org/jruby/RubyFixnum.java:931:in >'", "/home/ec2-user/logstash-1.4.2/vendor/bundle/jruby/1.9/gems/log-courier-0.13/lib/log-courier/server_tcp.rb:176:inrun'", "org/jruby/RubyKernel.java:1521:in loop'", "/home/ec2-user/logstash-1.4.2/vendor/bundle/jruby/1.9/gems/log-courier-0.13/lib/log-courier/server_tcp.rb:167:inrun'", "/home/ec2-user/logstash-1.4.2/vendor/bundle/jruby/1.9/gems/log-courier-0.13/lib/log-courier/server_tcp.rb:136:in `run'"]: comparison of Fixnum with nil failed (ArgumentError) {:level=>:warn}'

[driskell]

Hi @aaliang - I've addressed that in the latest commit. Sorry about that.

[tedder]

@driskell, I dug through my servers ("clients" and elasticsearch/logstash receivers) and don't have errors that indicate anything with these EOFs. The last major errors were the ones seen in #43 with the flush, and none of those are recent.

I'm going to increase verbosity of logstash (literally --verbose) and see what happens.

[tedder]

Here's the EOF:

Sep 16 01:49:24 ip-xxxx log-courier[10937]: Transport error, will try again: EOF

Here's the same event form the server side

{:timestamp=>"2014-09-16T01:49:24.343000+0000", :message=>"[LogCourierServer] Connection from 0.0.0.15:55310 closed", :level=>:info}

Here's the context of that specific message. I've included one extra line on each side as context.

{:timestamp=>"2014-09-16T01:48:11.590000+0000", :message=>"[LogCourierServer] New connection from 0.0.0.15:55308", :level=>:info}
{:timestamp=>"2014-09-16T01:48:12.569000+0000", :message=>"[LogCourierServer] Connection from 0.0.0.126:38846 closed", :level=>:info}
{:timestamp=>"2014-09-16T01:48:24.361000+0000", :message=>"[LogCourierServer] New connection from 0.0.0.15:55310", :level=>:info}
{:timestamp=>"2014-09-16T01:49:11.343000+0000", :message=>"[LogCourierServer] Connection from 0.0.0.15:55308 closed", :level=>:info}
{:timestamp=>"2014-09-16T01:49:18.369000+0000", :message=>"[LogCourierServer] New connection from 0.0.0.126:38890", :level=>:info}
{:timestamp=>"2014-09-16T01:49:24.343000+0000", :message=>"[LogCourierServer] Connection from 0.0.0.15:55310 closed", :level=>:info}
{:timestamp=>"2014-09-16T01:49:25.361000+0000", :message=>"[LogCourierServer] New connection from 0.0.0.15:55333", :level=>:info}

One thing I notice is that the connection is open EXACTLY for 60 seconds. That smells like a timeout. (in fact, it's the Amazon TCP ELB idle timeout). If you compare that to an event that was apparently successful, port 55308, its time is not exactly a minute.

Hmm. Does courier leave a connection open and expect to be able to talk to it without doing a keepalive?

(I've scrubbed the IP address)

[driskell]

Hi @tedder

Ah, you didn't mention ELB.

Yes it will open a connection and expect it to remain open. Unencumbered, a TCP connection would remain open indefinitely.

Firewalls and NAT generally limit it to as low as an hour. Thus courier has a keep alive internally that triggered every 30 minutes.

A one minute timeout is very low. You should increase if you can. IIRC you can increase it now for ELB.

Jason

[tedder]

Sorry for not mentioning it. I was trying to figure out the key issues, that should have been more obvious. As of this summer it's settable, so I'll increase it to an hour.

I see the timeouts are here.. too bad I can't configure them to ping every 30 seconds.

• log-courier/lib/log-courier/client.rb

  Line 133 in c802090

  @keepalive_timeout = 1800

• log-courier/src/lc-lib/admin/server.go

  Line 100 in b51c7bf

  // TODO: Make idle timeout configurable

And for posterity, here's how to set it in AWS ELB:

• http://docs.aws.amazon.com/ElasticLoadBalancing/latest/DeveloperGuide/config-idle-timeout.html

[driskell]

It's actually here for Log Courier:

log-courier/src/lc-lib/publisher/publisher.go

Line 36 in c802090

keepalive_timeout time.Duration = 900 * time.Second

The first one you found is the keep alive for the courier output Logstash plugin:

log-courier/lib/log-courier/client.rb

Line 133 in c802090

@keepalive_timeout = 1800

The other one you found is for the admin connection:

log-courier/src/lc-lib/admin/server.go

Line 100 in b51c7bf

// TODO: Make idle timeout configurable

I'll be making the Log Courier one configurable at some point in the future, and probably the admin connection one too. With regards to the Logstash output plugin, not any time soon - that's behind in development in many areas already as I don't know of anyone using it (it's more of a forwarder legacy plugin I kept just in case). Once I see people using the output plugin I'll start catching it up to Log Courier standards. I'll also be documenting it as such shortly as those documentation pages are my next piece.

[tedder]

Thanks for fixing my file searches. I just looked for "1800". No worries about making it configurable, I can normalize my stack to have a long timeout.

Feel free to close this (or I will).

[tedder]

I reconfigured the timeout (including plumbing it through Ansible), zero transport errors since then. yay!

For posterity/SEO, here's the aws-cli command to reconfigure it:

AWS_ACCESS_KEY_ID="xx" AWS_SECRET_ACCESS_KEY="yy" aws elb modify-load-balancer-attributes --load-balancer-name LBNAME --load-balancer-attributes "{\"ConnectionSettings\":{\"IdleTimeout\":3600}}"