I recently brought up some machines in a new colo and needed to ship their logs to a local logstash and then on to a centralized elasticsearch server at another site.<\/p>\n
The first batch of machines seemed to come up OK. \u00a0When I brought the second set up a few weeks later, I started seeing errors in logstash:<\/p>\n
Lumberjack input: the pipeline is blocked, temporary refusing new connection.\r\n\r\nLumberjack input: The circuit breaker has detected a slowdown or stall in the pipeline, the input is closing the current connection and rejecting new connection until the pipeline recover.\r\n<\/pre>\nThe “refusing new connection” part was easily confirmed in the logstash-forwarder logs:<\/p>\n
Connecting to [10.1.2.3]:5544 (10.1.2.3)\r\nConnected to 10.1.2.3\r\nRead error looking for ack: EOF<\/pre>\nThese errors seem to be common understood to mean that your ELK infrastructure is congested. \u00a0Perhaps logstash is dead\/slow (no); perhaps elasticsearch was dead\/slow (no).<\/p>\n
Elasticsearch looked healthy, and there were no signs of similar problem in other colos. \u00a0We’d see this behavior for most of an hour, and then a small batch of logs would make it through, which just added to the mystery.<\/p>\n
Upon further investigation, we found that even the first batch of machines was suffering from this problem. \u00a0That they were able to process a backlog of files and keep up to date is surprising.<\/p>\n
Turning up debugging in logstash yielded one additional message, but it was basically\u00a0a repeat of information already seen.<\/p>\n
The next step was to see what was going on when logstash talked to elasticsearch. \u00a0I grabbed a few minute’s info with tcpdump:<\/p>\n
tcpdump -ni eth0 -w tcpdump.out tcp port 9200<\/pre>\nThis showed three\u00a0interesting datapoints:<\/p>\n
\n
- all interactions between logstash and elasticsearch resulted in “200” responses (OK)<\/li>\n
- the small successful batches were being sent exactly 40 seconds apart<\/li>\n
- elasticsearch was responding quickly to the indexing requests that made it through.<\/li>\n<\/ol>\n
A google search for issues around “40 seconds” turned up nothing.<\/p>\n
To confirm the 40-second problem, I ran another tcpdump but restarted logstash at the same time. \u00a0This showed it to work for a while (~2 minutes), and then slow down to 40-second intervals.<\/p>\n
There didn’t seem to be much more to learn from tcpdump. \u00a0That led to java debugging steps, starting with a thread dump:<\/p>\n
kill -3 <pid><\/pre>\nThis added a thread dump to logstash’s logfile. \u00a0Looking through it, I found about 1\/3 of the threads were “BLOCKED”:<\/p>\n
\njava.lang.Thread.State: BLOCKED (on object monitor)
\nat java.net.InetAddress.getLocalHost(InetAddress.java:1486)
\n- waiting to lock <0x0000000538a5dfe0> (a java.lang.Object)
\nat org.jruby.ext.socket.SocketUtils.gethostname(SocketUtils.java:77)
\nat org.jruby.ext.socket.RubySocket.gethostname(RubySocket.java:257)
\nat org.jruby.ext.socket.RubySocket$INVOKER$s$0$0$gethostname.call(RubySocket$INVOKER$s$0$0$gethostname.gen)
\nat org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:134) at rubyjit.LogStash::Filters::Metrics$$flush_486027b1b0fe337b5753334309092d65d96630e51028566121.__file__(\/opt\/logstash\/vendor\/bundle\/jruby\/1.9\/gems\/logstash-filter-metrics-1.0.0\/lib\/logstash\/filters\/metrics.rb:186)
\nat rubyjit.LogStash::Filters::Metrics$$flush_486027b1b0fe337b5753334309092d65d96630e51028566121.__file__(\/opt\/logstash\/vendor\/bundle\/jruby\/1.9\/gems\/logstash-filter-metrics-1.0.0\/lib\/logstash\/filters\/metrics.rb)<\/code><\/p>\nThe great thing here is the stacktrace, which showed that the block was coming from the metrics{} filter<\/a>, on this line:<\/p>\n
event[\"<\/span>message\"<\/span><\/span>] =<\/span> Socket<\/span>.gethostname<\/pre>\nThis led to the discovery that these logstash instances – in only this colo – didn’t have access to a DNS server. \u00a0This is seemingly required so that the metric event can be tagged with the hostname from which it originates.<\/p>\n
Adding a line to \/etc\/hosts fixed the problem:<\/p>\n
127.0.0.1 myhost.mydomain.com<\/pre>\nHopefully nobody else will hit this exact problem, but perhaps the debugging techniques described above will be helpful.<\/p>\n","protected":false},"excerpt":{"rendered":"
I recently brought up some machines in a new colo and needed to ship their logs to a local logstash and then on to a centralized elasticsearch server at another site. The first batch of machines seemed to come up … Continue reading