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.

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

Add a configurable socket timeout #62

Closed
fupgang opened this issue Jun 10, 2021 · 5 comments
Closed

Add a configurable socket timeout #62

fupgang opened this issue Jun 10, 2021 · 5 comments
Milestone

Comments

@fupgang
Copy link
Contributor

fupgang commented Jun 10, 2021

We are using logback-gelf for a while and are pretty happy with it. The following rare error happened only once. It caused our application to freeze while all threads were blocked trying to send a log message.

We are using a GelfTcpTlsAppender.
When establishing the connection, the socket is read for the tls handshake. For some reason the tls handshake did never finish successfully. Since no socket timeout is configured, the appender keeps waiting forever:

"AsyncAppender-Worker-GELF_ASYNC" #29 daemon prio=5 os_prio=0 cpu=4681.06ms elapsed=47670.01s tid=0x00007febb8ea2000 nid=0x1f7a1 runnable  [0x00007febbb1fa000]
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(java.base@11.0.8/Native Method)
	at java.net.SocketInputStream.socketRead(java.base@11.0.8/SocketInputStream.java:115)
	at java.net.SocketInputStream.read(java.base@11.0.8/SocketInputStream.java:168)
	at java.net.SocketInputStream.read(java.base@11.0.8/SocketInputStream.java:140)
	at sun.security.ssl.SSLSocketInputRecord.read(java.base@11.0.8/SSLSocketInputRecord.java:467)
	at sun.security.ssl.SSLSocketInputRecord.readHeader(java.base@11.0.8/SSLSocketInputRecord.java:461)
	at sun.security.ssl.SSLSocketInputRecord.decode(java.base@11.0.8/SSLSocketInputRecord.java:160)
	at sun.security.ssl.SSLTransport.decode(java.base@11.0.8/SSLTransport.java:110)
	at sun.security.ssl.SSLSocketImpl.decode(java.base@11.0.8/SSLSocketImpl.java:1403)
	at sun.security.ssl.SSLSocketImpl.readHandshakeRecord(java.base@11.0.8/SSLSocketImpl.java:1309)
	at sun.security.ssl.SSLSocketImpl.startHandshake(java.base@11.0.8/SSLSocketImpl.java:440)
	at sun.security.ssl.SSLSocketImpl.ensureNegotiated(java.base@11.0.8/SSLSocketImpl.java:814)
	at sun.security.ssl.SSLSocketImpl$AppOutputStream.write(java.base@11.0.8/SSLSocketImpl.java:1184)
	at java.io.OutputStream.write(java.base@11.0.8/OutputStream.java:122)
	at de.siegmar.logbackgelf.TcpConnection.write(TcpConnection.java:55)
	at de.siegmar.logbackgelf.GelfTcpAppender$2.accept(GelfTcpAppender.java:176)
	at de.siegmar.logbackgelf.GelfTcpAppender$2.accept(GelfTcpAppender.java:173)
	at de.siegmar.logbackgelf.pool.SimpleObjectPool.execute(SimpleObjectPool.java:63)
	at de.siegmar.logbackgelf.GelfTcpAppender.sendMessage(GelfTcpAppender.java:173)

Of course the network error is out of logback-gelf's scopes and fortunately it seems to be a rare edge case.
We would appreciate it, if the GelfTcpTlsAppender's socket timeout can be configured, like it is already possible for the connection timeout.

Thank you!

@osiegmar
Copy link
Owner

In addition to a configurable socket timeout (thanks for the PR!) you can also configure logbacks AsyncAppender not to block.

@fupgang
Copy link
Contributor Author

fupgang commented Jun 11, 2021

We are ok with logback's AsyncAppender discarding TRACE, DEBUG and INFO messages when busy.
But we don't want to loose our ERRORs, therefore we still use blocking mode. We increased the default queue size instead.

@osiegmar osiegmar added this to the 4.0.0 milestone Jun 11, 2021
@osiegmar
Copy link
Owner

After reading https://stackoverflow.com/a/1338946 I'm wondering if the PR really helps regarding this issue as the socket timeout only seem to handle blocks for read operations not write operations.

@osiegmar osiegmar reopened this Jun 11, 2021
@fupgang
Copy link
Contributor Author

fupgang commented Jun 11, 2021

The above stacktrace shows the blocking read operation that happens during the tls handshake.
As I understand it, it helps.

This is relevant for GelfTcpTlsAppender only, as I wrote in #63:

Perhaps the socket timeout should be implemented in GelfTcpTlsAppender instead. I'm not sure, if it makes sense for a non-tls appender, since reading the socket appears when performing the tls handshake.

@osiegmar
Copy link
Owner

You're right. The PR circumvents this exact problem (from your stack trace). I think it is okay to implement the socket timeout in the TcpAppender class – it a) doesn't hurt and b) allows for an internal change to extend its use case to write operations. And the latter is exactly what I'm thinking about (but failed to express earlier). Maybe I should switch over to NIO in order to have a socket timeout for writer operations as well...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants