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.

Sign up for GitHub

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

Jump to bottom

Fix: reduce error logging on connection resets #424

Merged
merged 4 commits into from
Jun 17, 2021
Merged

Fix: reduce error logging on connection resets #424

merged 4 commits into from
Jun 17, 2021

Conversation

kares
Copy link
Contributor

@kares kares commented Jun 16, 2021 •
edited
Loading

Currently Beats input logs verbosely on a remote end closing the connection:

[2021-06-16T13:26:38,587][INFO ][org.logstash.beats.BeatsHandler][main][e15b199972a311b83bf379d2da4ce5b544931c9f4c00e94c4cd1dd4c5582a6a0] [local: 0.0.0.0:5044, remote: undefined] Handling exception: java.io.IOException: Connection reset by peer (caused by: java.io.IOException: Connection reset by peer)
[2021-06-16T13:26:38,601][WARN ][io.netty.channel.DefaultChannelPipeline][main][e15b199972a311b83bf379d2da4ce5b544931c9f4c00e94c4cd1dd4c5582a6a0] 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.PooledByteBuf.setBytes(PooledByteBuf.java:253) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1133) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) [netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-all-4.1.49.Final.jar:4.1.49.Final]
	at java.lang.Thread.run(Thread.java:834) [?:?]

we are reducing those 2 log entries into:

[2021-06-16T13:31:05,604][INFO ][org.logstash.beats.BeatsHandler][main][e15b199972a311b83bf379d2da4ce5b544931c9f4c00e94c4cd1dd4c5582a6a0] [local: 0.0.0.0:5044, remote: undefined] closing (Connection reset by peer)

full trace is still visible when debug level logging enabled:

[2021-06-16T13:32:52,413][INFO ][org.logstash.beats.BeatsHandler][main][e15b199972a311b83bf379d2da4ce5b544931c9f4c00e94c4cd1dd4c5582a6a0] [local: 0.0.0.0:5044, remote: 127.0.0.1:55886] closing
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.PooledByteBuf.setBytes(PooledByteBuf.java:253) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1133) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) ~[netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-all-4.1.49.Final.jar:4.1.49.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-all-4.1.49.Final.jar:4.1.49.Final]
	at java.lang.Thread.run(Thread.java:834) [?:?]

resolves #407
resolves #348

@kares kares requested a review from robbavey June 16, 2021 11:36
robbavey
robbavey approved these changes Jun 16, 2021
View reviewed changes
Copy link
Contributor

@robbavey robbavey left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Couple of nits/suggestions, other than that LGTM

src/main/java/org/logstash/beats/BeatsHandler.java Outdated
logger.info(format("Handling exception: " + cause + " (caused by: " + realCause + ")"));
final Throwable realCause = extractCause(cause, 0);
if (logger.isDebugEnabled()){
logger.debug(format("Handling exception: " + cause + " (caused by: " + realCause + ")"), cause);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do you think we should also change this to info if debug is enabled on the logger to be consistent with the above log message? I know this was what we had before, but it seems a little unusual to change the log level of a logging statement just because the amount of detail in the message has changed

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

makes sense, thanks

src/main/java/org/logstash/beats/BeatsHandler.java Outdated
ctx.flush();
ctx.close();
}
}

private boolean silentException(final Throwable ex) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit: Maybe silenceException or isNoisyException?

@kares kares merged commit 4d00d57 into logstash-plugins:master Jun 17, 2021
@kares kares mentioned this pull request Jul 27, 2021
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@robbavey robbavey robbavey approved these changes

Assignees
No one assigned
Labels
status:approved
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

handle healt-checks on port without error (warn) logging Better handle exceptions in ConnectionHandler
3 participants
@kares @robbavey @roaksoax