Skip to content

Commit ac26f77

Browse files
authored
Mention network handler logging in docs (#100118) (#100126)
Mentions the `InboundHandler` (and `OutboundHandler`) as potential sources of useful log messages when tracking down a network threading bug.
1 parent 4ac2db5 commit ac26f77

File tree

4 files changed

+28
-20
lines changed

4 files changed

+28
-20
lines changed

docs/reference/modules/network/threading.asciidoc

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -107,3 +107,12 @@ However, this API itself sends network messages so may not work correctly if
107107
the `transport_worker` threads are too busy. It is more reliable to use
108108
`jstack` to obtain stack dumps or use Java Flight Recorder to obtain a
109109
profiling trace. These tools are independent of any work the JVM is performing.
110+
111+
It may also be possible to identify some reasons for delays from the server
112+
logs, particularly looking at warnings from
113+
`org.elasticsearch.transport.InboundHandler` and
114+
`org.elasticsearch.transport.OutboundHandler`. Warnings about long processing
115+
times from the `InboundHandler` are particularly indicative of incorrect
116+
threading behaviour, whereas the transmission time reported by the
117+
`OutboundHandler` includes time spent waiting for network congestion and the
118+
`transport_worker` thread is free to do other work during this time.

docs/reference/troubleshooting/network-timeouts.asciidoc

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -47,5 +47,7 @@ since it doesn't require any JVM threads.
4747
The threads involved in discovery and cluster membership are mainly
4848
`transport_worker` and `cluster_coordination` threads, for which there should
4949
never be a long wait. There may also be evidence of long waits for threads in
50-
the {es} logs. See <<modules-network-threading-model>> for more information.
50+
the {es} logs, particularly looking at warning logs from
51+
`org.elasticsearch.transport.InboundHandler`. See
52+
<<modules-network-threading-model>> for more information.
5153
end::troubleshooting-network-timeouts-threads[]

server/src/test/java/org/elasticsearch/transport/InboundHandlerTests.java

Lines changed: 9 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -236,7 +236,7 @@ public void testClosesChannelOnErrorInHandshake() throws Exception {
236236
mockAppender.addExpectation(
237237
new MockLogAppender.SeenEventExpectation(
238238
"expected message",
239-
InboundHandler.class.getCanonicalName(),
239+
EXPECTED_LOGGER_NAME,
240240
Level.WARN,
241241
"error processing handshake version"
242242
)
@@ -273,6 +273,12 @@ public void testClosesChannelOnErrorInHandshake() throws Exception {
273273
}
274274
}
275275

276+
/**
277+
* This logger is mentioned in the docs by name, so we cannot rename it without adjusting the docs. Thus we fix the expected logger
278+
* name in this string constant rather than using {@code InboundHandler.class.getCanonicalName()}.
279+
*/
280+
private static final String EXPECTED_LOGGER_NAME = "org.elasticsearch.transport.InboundHandler";
281+
276282
public void testLogsSlowInboundProcessing() throws Exception {
277283
final MockLogAppender mockAppender = new MockLogAppender();
278284
mockAppender.start();
@@ -284,12 +290,7 @@ public void testLogsSlowInboundProcessing() throws Exception {
284290
final TransportVersion remoteVersion = TransportVersion.current();
285291

286292
mockAppender.addExpectation(
287-
new MockLogAppender.SeenEventExpectation(
288-
"expected slow request",
289-
InboundHandler.class.getCanonicalName(),
290-
Level.WARN,
291-
"handling request "
292-
)
293+
new MockLogAppender.SeenEventExpectation("expected slow request", EXPECTED_LOGGER_NAME, Level.WARN, "handling request ")
293294
);
294295

295296
final long requestId = randomNonNegativeLong();
@@ -316,12 +317,7 @@ public void testLogsSlowInboundProcessing() throws Exception {
316317
mockAppender.assertAllExpectationsMatched();
317318

318319
mockAppender.addExpectation(
319-
new MockLogAppender.SeenEventExpectation(
320-
"expected slow response",
321-
InboundHandler.class.getCanonicalName(),
322-
Level.WARN,
323-
"handling response "
324-
)
320+
new MockLogAppender.SeenEventExpectation("expected slow response", EXPECTED_LOGGER_NAME, Level.WARN, "handling response ")
325321
);
326322

327323
final long responseId = randomNonNegativeLong();

server/src/test/java/org/elasticsearch/transport/OutboundHandlerTests.java

Lines changed: 7 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -317,16 +317,17 @@ public void onResponseSent(long requestId, String action, Exception error) {
317317
assertEquals("header_value", header.getHeaders().v1().get("header"));
318318
}
319319

320+
/**
321+
* This logger is mentioned in the docs by name, so we cannot rename it without adjusting the docs. Thus we fix the expected logger
322+
* name in this string constant rather than using {@code OutboundHandler.class.getCanonicalName()}.
323+
*/
324+
private static final String EXPECTED_LOGGER_NAME = "org.elasticsearch.transport.OutboundHandler";
325+
320326
public void testSlowLogOutboundMessage() throws Exception {
321327
final MockLogAppender mockAppender = new MockLogAppender();
322328
mockAppender.start();
323329
mockAppender.addExpectation(
324-
new MockLogAppender.SeenEventExpectation(
325-
"expected message",
326-
OutboundHandler.class.getCanonicalName(),
327-
Level.WARN,
328-
"sending transport message "
329-
)
330+
new MockLogAppender.SeenEventExpectation("expected message", EXPECTED_LOGGER_NAME, Level.WARN, "sending transport message ")
330331
);
331332
final Logger outboundHandlerLogger = LogManager.getLogger(OutboundHandler.class);
332333
Loggers.addAppender(outboundHandlerLogger, mockAppender);

0 commit comments

Comments
 (0)