Logstash Connection Reset by Peer

Hello, I'm trying to debug a warning message I'm getting in my Logstash logs for my Winlogbeat filter. I've tried adding the setting client_inactivity_timeout => 0 to my Logstash input filter like I read in similar issues with no luck. I've also tried setting ttl: 0s within the client's winlogbeat.yml, and that didn't work either.

Here's the error message:

[2020-02-03T00:04:39,594][INFO ][org.logstash.beats.BeatsHandler][winlogbeat] [local: 0.0.0.0:5044, remote: 192.168.15.17:63807] Handling exception: Connection reset by peer
[2020-02-03T00:04:39,596][WARN ][io.netty.channel.DefaultChannelPipeline][winlogbeat] An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
        at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
        at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
        at io.netty.buffer.PooledUnsafeDirectByteBuf.setBytes(PooledUnsafeDirectByteBuf.java:288) ~[netty-all-4.1.34.Final.jar:4.1.34.Final]
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1125) ~[netty-all-4.1.34.Final.jar:4.1.34.Final]
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[netty-all-4.1.34.Final.jar:4.1.34.Final]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) ~[netty-all-4.1.34.Final.jar:4.1.34.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:677) ~[netty-all-4.1.34.Final.jar:4.1.34.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:612) ~[netty-all-4.1.34.Final.jar:4.1.34.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:529) ~[netty-all-4.1.34.Final.jar:4.1.34.Final]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:491) [netty-all-4.1.34.Final.jar:4.1.34.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905) [netty-all-4.1.34.Final.jar:4.1.34.Final]
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-all-4.1.34.Final.jar:4.1.34.Final]
        at java.lang.Thread.run(Thread.java:834) [?:?]

And this is my Logstash filter:

input {
  # Listen on port 5044 for events using the beats codec and keep the connection to host open for 10 minutes to prevent premature timeouts.
  beats {
    port => 5044
    client_inactivity_timeout => 0
  }
}

filter {
  # Tag event with GeoIP based on the location of their IP address.
  geoip {
    source => "[event_data][source.ip]"
  }
  if ("192.168.1*" in [source.ip]) {
    mutate {
      add_tag => ["Internal IP"]
      remove_tag => ["_geoip_lookup_failure"]
    }
  }
}

output {
  # Output data to Elasticsearch.
  elasticsearch {
    hosts => ["localhost:9200"]
    manage_template => false
    index => "%{[@metadata][beat]}-%{+YYYY.MM.dd}"
  }
}

First time posting on the forum, so I apologize if any of my syntax is off.

Thanks!

EDIT: I should also note that it doesn't appear that I'm missing any logs, I just get this warning very frequently and would like to know the cause and how to prevent it.

What does the beat log when this happens?

So the weird thing is that the log doesn't appear to be coming from any of our hosts. Also, I've gone through all of the hosts I have Winlogbeat setup on (deployed via GPO) and there were no other logs than the "successfully published x events"

The IP address within the Logstash log is that of our firewall, but I figure that's only due to it translating the IP across VLANs, as it's set to allow all traffic from our internal VLANs.

1 Like

Seems like the Winlogbeat logs restart themselves after a period of time, as if the service is restarting, I'm going to run a tail on them for a while and see if that tells me anything.

Okay, so it looks like the log stops on three separate machines after five minutes. Strangely they have the exact same configs as a handful of other machines that don't have this issue.

2020-02-04T10:25:35.293-0500	INFO	instance/beat.go:610	Home path: [C:\Program Files\Winlogbeat] Config path: [C:\Program Files\Winlogbeat] Data path: [C:\ProgramData\Winlogbeat] Logs path: [C:\ProgramData\Winlogbeat\Logs]
2020-02-04T10:25:35.327-0500	INFO	instance/beat.go:618	Beat ID: 2a6ecdf3-2813-4081-afb3-afb2d92fabed
2020-02-04T10:25:35.392-0500	INFO	[beat]	instance/beat.go:941	Beat info	{"system_info": {"beat": {"path": {"config": "C:\\Program Files\\Winlogbeat", "data": "C:\\ProgramData\\Winlogbeat", "home": "C:\\Program Files\\Winlogbeat", "logs": "C:\\ProgramData\\Winlogbeat\\Logs"}, "type": "winlogbeat", "uuid": "2a6ecdf3-2813-4081-afb3-afb2d92fabed"}}}
2020-02-04T10:25:35.394-0500	INFO	[beat]	instance/beat.go:950	Build info	{"system_info": {"build": {"commit": "60dd883ca29e1fdd5b8b075bd5f3698948b1d44d", "libbeat": "7.5.1", "time": "2019-12-16T22:05:28.000Z", "version": "7.5.1"}}}
2020-02-04T10:25:35.395-0500	INFO	[beat]	instance/beat.go:953	Go runtime info	{"system_info": {"go": {"os":"windows","arch":"amd64","max_procs":2,"version":"go1.12.12"}}}
2020-02-04T10:25:35.415-0500	INFO	[beat]	instance/beat.go:957	Host info	{"system_info": {"host": {"architecture":"x86_64","boot_time":"2020-01-30T11:12:42.44-05:00","name":"PD-DC1","ip":["fe80::d4a4:abee:a75f:ba72/64","192.168.120.6/24","::1/128","127.0.0.1/8"],"kernel_version":"10.0.17763.973 (WinBuild.160101.0800)","mac":["00:15:5d:0f:30:00"],"os":{"family":"windows","platform":"windows","name":"Windows Server 2019 Datacenter","version":"10.0","major":10,"minor":0,"patch":0,"build":"17763.973"},"timezone":"EST","timezone_offset_sec":-18000,"id":"38a8c0d0-dc22-4ec0-9fe7-a27cac9a73e5"}}}
2020-02-04T10:25:35.428-0500	INFO	[beat]	instance/beat.go:986	Process info	{"system_info": {"process": {"cwd": "C:\\Windows\\system32", "exe": "C:\\Program Files\\Winlogbeat\\winlogbeat.exe", "name": "winlogbeat.exe", "pid": 4452, "ppid": 648, "start_time": "2020-02-04T10:25:34.977-0500"}}}
2020-02-04T10:25:35.428-0500	INFO	instance/beat.go:297	Setup Beat: winlogbeat; Version: 7.5.1
2020-02-04T10:25:35.430-0500	INFO	[publisher]	pipeline/module.go:97	Beat name: PD-DC1
2020-02-04T10:25:35.431-0500	INFO	beater/winlogbeat.go:69	State will be read from and persisted to C:\ProgramData\Winlogbeat\.winlogbeat.yml
2020-02-04T10:25:35.616-0500	WARN	[cfgwarn]	registered_domain/registered_domain.go:60	BETA: The registered_domain processor is beta.
2020-02-04T10:25:35.617-0500	INFO	instance/beat.go:429	winlogbeat start running.
2020-02-04T10:25:35.617-0500	INFO	[monitoring]	log/log.go:118	Starting metrics logging every 30s
2020-02-04T10:25:35.646-0500	WARN	beater/eventlogger.go:113	EventLog[Microsoft-Windows-Sysmon/Operational] Open() error. No events will be read from this source. The specified channel could not be found.
2020-02-04T10:25:45.658-0500	INFO	pipeline/output.go:95	Connecting to backoff(async(tcp://192.168.15.37:5044))
2020-02-04T10:25:45.663-0500	INFO	pipeline/output.go:105	Connection to backoff(async(tcp://192.168.15.37:5044)) established
2020-02-04T10:25:45.677-0500	INFO	beater/eventlogger.go:81	EventLog[System] successfully published 3 events
2020-02-04T10:25:45.677-0500	INFO	beater/eventlogger.go:81	EventLog[Security] successfully published 9 events
2020-02-04T10:25:56.732-0500	INFO	beater/eventlogger.go:81	EventLog[Security] successfully published 1 events
2020-02-04T10:26:05.629-0500	INFO	[monitoring]	log/log.go:145	Non-zero metrics in the last 30s	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":250,"time":{"ms":250}},"total":{"ticks":484,"time":{"ms":484},"value":484},"user":{"ticks":234,"time":{"ms":234}}},"handles":{"open":232},"info":{"ephemeral_id":"e370c385-315b-40a4-901d-7cffca27b342","uptime":{"ms":30529}},"memstats":{"gc_next":9991520,"memory_alloc":7364968,"memory_total":16319048,"rss":33767424},"runtime":{"goroutines":31}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":13,"batches":2,"total":13},"read":{"bytes":12},"type":"logstash","write":{"bytes":6879}},"pipeline":{"clients":3,"events":{"active":0,"published":13,"retry":12,"total":13},"queue":{"acked":13}}},"msg_file_cache":{"SecurityHits":10,"SecurityMisses":1,"SecuritySize":1,"SystemHits":2,"SystemMisses":1,"SystemSize":1},"published_events":{"Security":10,"System":3,"total":13},"system":{"cpu":{"cores":2}}}}}
...
2020-02-04T10:30:13.113-0500	INFO	beater/eventlogger.go:81	EventLog[Security] successfully published 36 events
2020-02-04T10:30:19.217-0500	INFO	beater/winlogbeat.go:169	Stopping Winlogbeat
2020-02-04T10:30:19.453-0500	INFO	beater/eventlogger.go:118	EventLog[Security] Stop processing.
2020-02-04T10:30:19.721-0500	INFO	beater/eventlogger.go:118	EventLog[Application] Stop processing.
2020-02-04T10:30:19.721-0500	INFO	beater/eventlogger.go:118	EventLog[System] Stop processing.
2020-02-04T10:30:19.724-0500	INFO	[monitoring]	log/log.go:153	Total non-zero metrics	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":843,"time":{"ms":843}},"total":{"ticks":1811,"time":{"ms":1811},"value":1811},"user":{"ticks":968,"time":{"ms":968}}},"handles":{"open":225},"info":{"ephemeral_id":"e370c385-315b-40a4-901d-7cffca27b342","uptime":{"ms":284620}},"memstats":{"gc_next":10264832,"memory_alloc":5296384,"memory_total":63793648,"rss":38068224},"runtime":{"goroutines":17}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":130,"batches":18,"total":130},"read":{"bytes":108},"type":"logstash","write":{"bytes":73994}},"pipeline":{"clients":0,"events":{"active":0,"published":130,"retry":12,"total":130},"queue":{"acked":130}}},"msg_file_cache":{"SecurityHits":128,"SecurityMisses":1,"SecuritySize":1,"SystemHits":2,"SystemMisses":1},"published_events":{"Security":127,"System":3,"total":130},"system":{"cpu":{"cores":2}}}}}
2020-02-04T10:30:19.724-0500	INFO	[monitoring]	log/log.go:154	Uptime: 4m44.6222013s
2020-02-04T10:30:19.724-0500	INFO	[monitoring]	log/log.go:131	Stopping metrics logging.
2020-02-04T10:30:19.724-0500	INFO	instance/beat.go:435	winlogbeat stopped.

*The "..." just signifies more of the same.

After the service stops, the log is wiped and started again.

[2020-02-17T15:27:20,062][INFO ][org.logstash.beats.BeatsHandler][main] [local: 0.0.0.0:5044, remote: undefined] Handling exception: Connection reset by peer
[2020-02-17T15:27:20,074][WARN ][io.netty.channel.DefaultChannelPipeline][main] An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
java.io.IOException: Connection reset by peer
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
	at io.netty.buffer.PooledUnsafeDirectByteBuf.setBytes(PooledUnsafeDirectByteBuf.java:288) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1128) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:644) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:579) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:496) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:458) [netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897) [netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-all-4.1.30.Final.jar:4.1.30.Final]
	at java.lang.Thread.run(Thread.java:834) [?:?]

this is my LS logs, does anyone know what may be causing this problem?

1 Like

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