"Failed to publish events", "use of closed network connection"

Andrew_Shu · February 11, 2018, 11:06pm

I'm trying to get a basic ELK setup, but I've been having difficulties verifying that Filebeat publishes to Logstash. Filebeat reports that it can't publish events because "use of closed network connection".

I suspect it's a network issue between client and server, but I'd like to gather ideas for what to do next. After some Googling, it looks like the phrase "use of a closed network connection" is a message that golang uses.

Packet captures suggest that the server is responding to the client. I have a sneaking suspicion that the issue is actually Logstash and not Filebeat, because the error messages suggests that the server isn't responding properly. But I'm posting it here because the immediate issue is visible in Filebeat.

Filebeat error

 #<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
# Client using filebeat: Filebeat failed to publish
# Host: 10.10.10.81
# Command: cat /etc/filebeat/filebeat.yml
2018-02-11T14:10:15.372-0800    ERROR   logstash/async.go:235   Failed to publish events caused by: read tcp 10.10.10.81:52152->10.10.10.93:5044: i/o timeout
2018-02-11T14:10:15.372-0800    ERROR   logstash/async.go:235   Failed to publish events caused by: write tcp 10.10.10.81:52152->10.10.10.93:5044: use of closed network connection
2018-02-11T14:10:16.373-0800    ERROR   pipeline/output.go:92   Failed to publish events: write tcp 10.10.10.81:52152->10.10.10.93:5044: use of closed network connection

Client info

#<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
# Client info
# Host: 10.10.10.81
# Command: miscellaneous info
$ filebeat version
filebeat version 6.2.1 (amd64), libbeat 6.2.1
$ cat /etc/centos-release
CentOS Linux release 7.4.1708 (Core)

Client has an active TCP connection to server

#<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
# Client using filebeat: client (http-29) has a connection to logstash server (logs-1)
# Host: 10.10.10.81
# Command: lsof -i -P # I filtered for only the relevant row
COMMAND    PID       USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
filebeat  2331       root    5u  IPv4 393900      0t0  TCP http-29.node.dc1.app.local:52062->logs-1.node.dc1.app.local:5044 (ESTABLISHED)

Filebeat conf in the client

#<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
# Client using filebeat: filebeat configuration
# Host: 10.10.10.81
# Command: cat /etc/filebeat/filebeat.yml
filebeat.prospectors:
- type: log
  enabled: true
  paths:
    - /var/log/messages

output.logstash:
  hosts: ["logstash.service.app.local:5044"]

Server packet capture

#>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
# Logstash server: packet capture shows that the server is receiving and responding to 
# Host: 10.10.10.93
# Command: tcpdump -i eth0 -nn host 10.10.10.81 and port 5044
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
14:38:46.178866 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [S], seq 1666666507, win 29200, options [mss 1460,sackOK,TS val 51722092 ecr 0,nop,wscale 6], length 0
14:38:46.178980 IP 10.10.10.93.5044 > 10.10.10.81.52618: Flags [S.], seq 1518647658, ack 1666666508, win 28960, options [mss 1460,sackOK,TS val 3216965 ecr 51722092,nop,wscale 7], length 0
14:38:46.179312 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], ack 1, win 457, options [nop,nop,TS val 51722093 ecr 3216965], length 0
14:38:46.257717 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], seq 1:1449, ack 1, win 457, options [nop,nop,TS val 51722171 ecr 3216965], length 1448
14:38:46.257720 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], seq 1449:2897, ack 1, win 457, options [nop,nop,TS val 51722171 ecr 3216965], length 1448
14:38:46.257721 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], seq 2897:4345, ack 1, win 457, options [nop,nop,TS val 51722171 ecr 3216965], length 1448
14:38:46.257723 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], seq 4345:5793, ack 1, win 457, options [nop,nop,TS val 51722171 ecr 3216965], length 1448
14:38:46.257725 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], seq 5793:7241, ack 1, win 457, options [nop,nop,TS val 51722171 ecr 3216965], length 1448
14:38:46.257729 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], seq 7241:8689, ack 1, win 457, options [nop,nop,TS val 51722171 ecr 3216965], length 1448
14:38:46.257731 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], seq 8689:10137, ack 1, win 457, options [nop,nop,TS val 51722171 ecr 3216965], length 1448
14:38:46.257733 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], seq 10137:11585, ack 1, win 457, options [nop,nop,TS val 51722171 ecr 3216965], length 1448
14:38:46.257735 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], seq 11585:13033, ack 1, win 457, options [nop,nop,TS val 51722171 ecr 3216965], length 1448
14:38:46.257737 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], seq 13033:14481, ack 1, win 457, options [nop,nop,TS val 51722171 ecr 3216965], length 1448
14:38:46.267452 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], seq 14481:15929, ack 1, win 457, options [nop,nop,TS val 51722181 ecr 3216965], length 1448
14:38:46.471405 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], seq 1:1449, ack 1, win 457, options [nop,nop,TS val 51722385 ecr 3216965], length 1448
14:38:46.880479 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], seq 1:1449, ack 1, win 457, options [nop,nop,TS val 51722794 ecr 3216965], length 1448
14:38:47.500773 IP 10.10.10.93.5044 > 10.10.10.81.52618: Flags [S.], seq 1518647658, ack 1666666508, win 28960, options [mss 1460,sackOK,TS val 3218287 ecr 51722794,nop,wscale 7], length 0
14:38:47.501165 IP 10.10.10.81.52618 > 10.10.10.93.5044: Flags [.], ack 1, win 457, options [nop,nop,TS val 51723414 ecr 3216965], length 0

Server logstash configuration

#>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
# Logstash server: logstash configuration
# Host: 10.10.10.93
# Command: cat /etc/logstash/logstash.yml
path.data: /var/lib/logstash
path.logs: /var/log/logstash

Server profile to listen to filebeat

#>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
# Logstash server: listen to filebeat
# Host: 10.10.10.93
# Command: cat /etc/logstash/conf.d/default_port_5044.conf
input {
  beats {
    host => "logstash.service.app.local"
    port => 5044
  }
}

output {
  elasticsearch {
    hosts => ["http://elasticsearch.service.app.local:9200"]
    index => "%{[@metadata][beat]}-%{[@metadata][version]}-%{+YYYY.MM.dd}"
  }
}

tudor · February 12, 2018, 10:59am

What versions of Filebeat and Logstash do you have?

Also, is there a firewall or anything of that sorts between Filebeat and Logstash?

tudor · February 12, 2018, 11:02am

Also can you run:

filebeat test output

and give us the result?

Andrew_Shu · February 12, 2018, 5:55pm

@tudor thanks for responding. Here's the info you were interested in:

Versions

logstash 6.2.1
filebeat version 6.2.1 (amd64), libbeat 6.2.1

Output of filebeat test output

$ filebeat test output
logstash: logstash.service.app.local:5044...
  connection...
    parse host... OK
    dns lookup... OK
    addresses: 10.10.10.93
    dial up... OK
  TLS... WARN secure connection disabled
  talk to server... OK

Firewall?

Yes there is. However, I do not believe the firewall is an issue because I tried a few things to verify the packets were hitting logstash.

I tried disabling it (didn't help)
I took a packet capture (see above - verified that the server was receiving and responding), and
I stopped Logstash and manually listened on the port and saw output coming in.

tudor · February 12, 2018, 8:48pm

Do the errors show up immediately or after a while? I'm thinking that the firewall breaks the connection after some period of inactivity. The read tcp i/o timeout errors really look like something gets wrong at the connectivity level, that's why I'm insisting.

Andrew_Shu · February 13, 2018, 7:32am

Re: immediately vs. after a while. The errors shows up immediately. I run systemctl restart filebeat, and I immediately get the error.

Re: connectivity. I definitely agree that firewalls are always a potential issue. However, evidence suggests that the packets are getting through to the logstash service.

I disabled firewalls on both client/server, restarted filebeat, and the issue persisted.
I disabled logstash and ran nc -l 5044 and verified a lot of data was getting sent through (shouldn't it be encrypted? It was coming in garbled)

Re: the error message "use of closed network connection" - googling for references to the error, I came upon this link: https://github.com/garyburd/redigo/issues/189 .

Is it possible that there's an issue in how the data is encoded/decoded between the filebeat client and logstash server?

tudor · February 13, 2018, 12:55pm

Can you enable debug logging in Logstash and give us the logs on that side as well, please? It might be worth giving it a try with the Elasticsearch output in Logstash disabled, and use the stdout output instead. The theory here is that Logstash might be blocked and can accept the connection but doesn't answer with any ACKs or keep alives, which causes the connection to be closed.

pierhugues · February 13, 2018, 4:47pm

Can you also attach the output of the following command bin/logstash-plugin list --verbose beats, Plugins have their own release cycle so I want to make sure we look at the right place.

Andrew_Shu · February 14, 2018, 6:24pm

@pierhugues plugin version:

Command: /usr/share/logstash/bin/logstash-plugin list --verbose beats

logstash-input-beats (5.0.6)

@tudor - I noticed these errors in Logstash - are they expected?

[2018-02-13T23:18:48,905][INFO ][org.logstash.beats.BeatsHandler] [local: 0.0.0.0:5044, remote: undefined] Handling exception: event executor terminated
[2018-02-13T23:18:48,905][DEBUG][org.logstash.beats.BeatsHandler] [local: 0.0.0.0:5044, remote: undefined] Handling exception: event executor terminated
java.util.concurrent.RejectedExecutionException: event executor terminated
  at io.netty.util.concurrent.SingleThreadEventExecutor.reject(SingleThreadEventExecutor.java:821) ~[netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.util.concurrent.SingleThreadEventExecutor.offerTask(SingleThreadEventExecutor.java:327) ~[netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.util.concurrent.SingleThreadEventExecutor.addTask(SingleThreadEventExecutor.java:320) ~[netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.util.concurrent.SingleThreadEventExecutor.execute(SingleThreadEventExecutor.java:746) ~[netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:317) [netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.channel.AbstractChannelHandlerContext.fireUserEventTriggered(AbstractChannelHandlerContext.java:307) [netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.channel.ChannelInboundHandlerAdapter.userEventTriggered(ChannelInboundHandlerAdapter.java:108) ~[netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:329) [netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.channel.AbstractChannelHandlerContext.access$500(AbstractChannelHandlerContext.java:38) [netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.channel.AbstractChannelHandlerContext$6.run(AbstractChannelHandlerContext.java:320) [netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) [netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasksFrom(SingleThreadEventExecutor.java:379) [netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:354) [netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.util.concurrent.SingleThreadEventExecutor.confirmShutdown(SingleThreadEventExecutor.java:678) [netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:70) [netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858) [netty-all-4.1.18.Final.jar:4.1.18.Final]
  at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-all-4.1.18.Final.jar:4.1.18.Final]
  at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]

If this doesn't ring a bell - I'll do a little troubleshooting. I want to recreate the machines to get a fresh install/configs.

pierhugues · February 16, 2018, 7:42pm

I've seen a report of similar errors on the beats input repository, but I haven't been able to reproduce it.

Would you mind updating the logstash-input-beats plugin with the following command: bin/logstash-plugin update logstash-input-beats.

Some fixes have been applied concerning the shutdown and creation of the event loop.

Andrew_Shu · February 19, 2018, 4:57am

@pierhugues Will do. I may not get around to to it for a few days.

Andrew_Shu · March 18, 2018, 7:17pm

@pierhugues Quick update - I won't be pursuing this anymore. I was a little pressed for time, so I ended up shipping directly from Filebeat to Elasticsearch.

BenKl · March 22, 2018, 8:50am

I had the same issue. I remembered, that I did a telnet test on port 5044 to check teh connection because one server is connected over a VPN. So after restarting Logstash everything worked fine.

system · April 19, 2018, 8:50am

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.