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

fix #4254: adding debug logging for exec stream messages #4288

Merged
merged 1 commit into from
Aug 9, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@
* Fix #4247: NO_PROXY with invalid entries throws exception

#### Improvements
* Fix #4254: adding debug logging for exec stream messages
* Fix #4041: adding Quantity.getNumericalAmount with an explanation about bytes and cores.
* Fix #4241: added more context to informer logs with the endpoint path
* Fix #4250: allowing for deserialization of polymorphic unwrapped fields
Expand Down
10 changes: 8 additions & 2 deletions doc/FAQ.md
Original file line number Diff line number Diff line change
Expand Up @@ -30,7 +30,7 @@ If you wish to use another HttpClient implementation typically you will exclude

### What threading concerns are there?

There has been a lot of changes under the covers with thread utilization in the fabric8 client over the 5.x and 6.x releases. So the exact details of what threads are created / used where will depend on the particular release version.
There has been a lot of changes under the covers with thread utilization in the Fabric8 client over the 5.x and 6.x releases. So the exact details of what threads are created / used where will depend on the particular release version.

At the core the thread utilization will depend upon the http client implementation. Per client OkHttp maintains a pool of threads for task execution. It will dedicate 2 threads out of that pool per WebSocket connection. If you have a lot of WebSocket usage (Informer or Watches) with OkHttp, you can expect to see a large number of threads in use - which can potentially exhaust the OkHttp defaults.

Expand All @@ -40,6 +40,12 @@ With the JDK http client it will only maintain a selector thread and a small wor

For non-ResourceEventHandlers call backs long-running operation can be a problem. When using the OkHttp client and default settings holding a IO thread inhibits websocket processing that can timeout the ping and may prevent additional requests since the okhttp client defaults to only 5 concurrent requests per host. When using the JDK http client the long running task will inhibit the use of that IO thread for ALL http processing. Note that calling other KubernetesClient operations, especially those with waits, can be long-running. We are working towards providing non-blocking mode for many of these operations, but until that is available consider using a separate task queue for such work.

On top of the http client threads the fabric8 client maintains a task thread pool for scheduled tasks and for potentially long-running tasks that are called from WebSocket operations, such as handling input and output streams and ResourceEventHandler call backs. This thread pool defaults to an unlimited number of cached threads, which will be shutdown when the client is closed - that is a sensible default with either http client as the amount of concurrently running async tasks will typically be low. If you would rather take full control over the threading use KubernetesClientBuilder.withExecutor or KubernetesClientBuilder.withExecutorSupplier - however note that constraining this thread pool too much will result in a build up of event processing queues.
On top of the http client threads the Fabric8 client maintains a task thread pool for scheduled tasks and for potentially long-running tasks that are called from WebSocket operations, such as handling input and output streams and ResourceEventHandler call backs. This thread pool defaults to an unlimited number of cached threads, which will be shutdown when the client is closed - that is a sensible default with either http client as the amount of concurrently running async tasks will typically be low. If you would rather take full control over the threading use KubernetesClientBuilder.withExecutor or KubernetesClientBuilder.withExecutorSupplier - however note that constraining this thread pool too much will result in a build up of event processing queues.

Finally the fabric8 client will use 1 thread per PortForward and an additional thread per socket connection - this may be improved upon in the future.

### What additional logging is available?

Like many java application the Fabric8 Client utilizes [slf4j](https://www.slf4j.org/). You may configure support for whatever underlying logging framework suits your needs. The logging contexts for the Fabric8 Client follow the standard convention of the package structure - everything from within the client will be rooted at the io.fabric8 context. Third-party dependencies, including the chosen HTTP client implementation, will have different root contexts.

If you are using pod exec, which can occur indirectly via pod operations like copying files, and not seeing the expected behavior - please enable debug logging for the io.fabric8.kubernetes.client.dsl.internal context. That will provide the stdErr and stdOut as debug logs to further diagnose what is occurring.
Original file line number Diff line number Diff line change
Expand Up @@ -100,17 +100,29 @@ public interface MessageHandler {
private final class ListenerStream {
private MessageHandler handler;
private ExecWatchInputStream inputStream;
private String name;

public ListenerStream(String name) {
this.name = name;
}

private void handle(ByteBuffer byteString, WebSocket webSocket) throws IOException {
if (handler != null) {
handler.handle(byteString);
} else {
if (LOGGER.isDebugEnabled()) {
String message = ExecWebSocketListener.toString(byteString);
if (message.length() > 200) {
message = message.substring(0, 197) + "...";
}
LOGGER.debug("exec message received on channel {}: {}", name, message);
}
webSocket.request();
}
}
}

private static final Logger LOGGER = LoggerFactory.getLogger(ExecWebSocketListener.class);
static final Logger LOGGER = LoggerFactory.getLogger(ExecWebSocketListener.class);
Copy link
Member

Choose a reason for hiding this comment

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

Could we keep this private and retrieve the logger in PodOperationContext using the same approach?

Copy link
Member

Choose a reason for hiding this comment

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

Also, are we sure that this is the class/package/point where we want to add the flag to decide if these messages should be logged? Can we document how to enable this logging? Would it make sense to check for debug enabled at the base package?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Could we keep this private and retrieve the logger in PodOperationContext using the same approach?

You mean enable this off of two separate loggers? I didn't like that approach, even if they share a common base.

Also, are we sure that this is the class/package/point where we want to add the flag to decide if these messages should be logged?

Yes, they should be logged in the ExecWebSocketListener, and we have to make an earlier decision to include the query flags.

Can we document how to enable this logging?

Yes, we just have to agree on what it should be first.

Would it make sense to check for debug enabled at the base package?

You could, it's just a bit more code to create / access a couple of additional loggers - call me lazy, but I'd rather reuse something that exists if possible.

Copy link
Member

Choose a reason for hiding this comment

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

You mean enable this off of two separate loggers? I didn't like that approach, even if they share a common base.

I meant doing this from PodOperationContext:

boolean debug = // ExecWebSocketListener.LOGGER.isDebugEnabled();
  LoggerFactory.getLogger(ExecWebSocketListener.class);

It's still coupled, but at least we don't access the other class variable that should be used for internal purposes only.

However, I'm going over both #4288 (comment) and #4288 (comment) and as I see it's just that the structure is flawed.

The PodOperationContext is not only used for Exec operations, but for other operations too.

It's usage should be clear from the context :)

For me it's not clear that a public addQueryParameters method is used only to add exec-related parameters. Maybe this method just doesn't belong here.

I guess that at this point it doesn't matter anyway.

private static final String HEIGHT = "Height";
private static final String WIDTH = "Width";

Expand Down Expand Up @@ -152,14 +164,14 @@ public ExecWebSocketListener(PodOperationContext context, Executor executor) {
}

this.terminateOnError = context.isTerminateOnError();
this.out = createStream(context.getOutput());
this.error = createStream(context.getError());
this.errorChannel = createStream(context.getErrorChannel());
this.out = createStream("stdOut", context.getOutput());
this.error = createStream("stdErr", context.getError());
this.errorChannel = createStream("errorChannel", context.getErrorChannel());
this.serialExecutor = new SerialExecutor(executor);
}

private ListenerStream createStream(StreamContext streamContext) {
ListenerStream stream = new ListenerStream();
private ListenerStream createStream(String name, StreamContext streamContext) {
ListenerStream stream = new ListenerStream(name);
if (streamContext == null) {
return stream;
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -164,10 +164,11 @@ public void addQueryParameters(URLBuilder httpUrlBuilder) {
if (in != null || redirectingIn) {
httpUrlBuilder.addQueryParameter("stdin", "true");
}
if (output != null) {
boolean debug = ExecWebSocketListener.LOGGER.isDebugEnabled();
Copy link
Member

Choose a reason for hiding this comment

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

This reveals an odd coupling between ExecWebSocketListener and this class.

The name of the method suggests a wider usage of these parameters, however, they are only ultimately consumed at the public ExecWatch exec(String... command) method. Maybe we should rename the addQueryParameters method.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

This reveals an odd coupling between ExecWebSocketListener and this class.

It's partly an issue with the existing code structure. The entry class is PodOperationsImpl, but it's in a different package from the rest of the logic - presumably because there could eventually be a v2. That's how most of dsl.internal is used.

Maybe we should rename the addQueryParameters method.

It's usage should be clear from the context :) You could also make the case that the classes in dsl.internal should move into core.v1 and have methods be made package private.

if (output != null || debug) {
httpUrlBuilder.addQueryParameter("stdout", "true");
}
if (error != null || terminateOnError) {
if (error != null || terminateOnError || debug) {
httpUrlBuilder.addQueryParameter("stderr", "true");
}
}
Expand Down
5 changes: 5 additions & 0 deletions kubernetes-itests/pom.xml
Original file line number Diff line number Diff line change
Expand Up @@ -58,6 +58,11 @@
<groupId>org.awaitility</groupId>
<artifactId>awaitility</artifactId>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-simple</artifactId>
<scope>test</scope>
</dependency>
</dependencies>

<profiles>
Expand Down