From 8ec2071400e98182a4d7cd35229e6dbe6e1d7dd9 Mon Sep 17 00:00:00 2001 From: agrawalabhi Date: Mon, 14 Sep 2026 08:02:33 +0000 Subject: [PATCH 1/2] examples: add a Log4j 2 logging context example Add example-log4j2, showing how a server interceptor can put per-call values into the Log4j 2 ThreadContext so that they are appended to every log statement the service makes. This is the non-io.grpc.Context scoped case, since logging frameworks read from thread-local storage. The server uses LogManager plus a log4j2.xml whose pattern includes %X, rather than constructing an internal SimpleLogger by hand, so the contextual values are actually visible in the output. Supersedes #5835, which was reviewed but went stale. Relative to that change: the directory is example-log4j2 rather than examples-log4j2 so that the loop over examples/example-* in buildscripts/kokoro/unix.sh picks it up; the BUILD.bazel copied from the ALTS example and the vendored gradlew files are dropped; the README explains what the example illustrates and names the scripts the build actually produces; and the gRPC, protoc and Log4j 2 versions are current. --- examples/README.md | 2 + examples/example-log4j2/README.md | 61 +++++++++ examples/example-log4j2/build.gradle | 71 ++++++++++ examples/example-log4j2/settings.gradle | 17 +++ .../examples/logcontext/CustomLogClient.java | 125 ++++++++++++++++++ .../examples/logcontext/CustomLogServer.java | 108 +++++++++++++++ .../logcontext/HeaderServerInterceptor.java | 108 +++++++++++++++ .../main/proto/helloworld/helloworld.proto | 37 ++++++ .../src/main/resources/log4j2.xml | 34 +++++ 9 files changed, 563 insertions(+) create mode 100644 examples/example-log4j2/README.md create mode 100644 examples/example-log4j2/build.gradle create mode 100644 examples/example-log4j2/settings.gradle create mode 100644 examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/CustomLogClient.java create mode 100644 examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/CustomLogServer.java create mode 100644 examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/HeaderServerInterceptor.java create mode 100644 examples/example-log4j2/src/main/proto/helloworld/helloworld.proto create mode 100644 examples/example-log4j2/src/main/resources/log4j2.xml diff --git a/examples/README.md b/examples/README.md index 91fde2c045c..f67f1f90ec3 100644 --- a/examples/README.md +++ b/examples/README.md @@ -125,6 +125,8 @@ $ bazel-bin/hello-world-client - [OAuth2-based Authentication](example-oauth) +- [Log4j 2 logging context](example-log4j2) + - [Pre-serialized messages](src/main/java/io/grpc/examples/preserialized) ## Unit test examples diff --git a/examples/example-log4j2/README.md b/examples/example-log4j2/README.md new file mode 100644 index 00000000000..add5d4e2636 --- /dev/null +++ b/examples/example-log4j2/README.md @@ -0,0 +1,61 @@ +gRPC Log4j 2 Example +============================================== + +This example illustrates how to set the Log4j 2 `ThreadContext` from a server interceptor so that +it is picked up by the logger in your server. + +The server interceptor puts a `requestId` (a randomly generated UUID) and the `clientName` taken +from a request header into the `ThreadContext`. The `%X` conversion pattern in +[log4j2.xml](src/main/resources/log4j2.xml) then appends both values to every log statement made +while the call is being handled, so the service method itself does not have to pass them around. + +These values are deliberately *not* stored in an `io.grpc.Context`: logging frameworks read from +thread-local storage, so the interceptor sets and clears the `ThreadContext` around each callback +using `CloseableThreadContext`. + +### Build the example + +The examples require `grpc-java` to already be built. You are strongly encouraged to check out a +git release tag, since there will already be a build of gRPC available. Otherwise you must follow +[COMPILING](../../COMPILING.md). + +From the `grpc-java/examples/example-log4j2` directory: +``` +$ ../gradlew installDist +``` + +This creates the scripts `build/install/example-log4j2/bin/custom-log-server` and +`build/install/example-log4j2/bin/custom-log-client`. + +### Run the example + +1. To start the server on its default port of 50051, run: +``` +$ ./build/install/example-log4j2/bin/custom-log-server +``` + +2. In a different terminal window, run the client: +``` +$ ./build/install/example-log4j2/bin/custom-log-client +``` + +The server logs a line for each request that includes the contextual values appended by `%X`: + +``` +2026/09/14 15:22:12:686 PDT INFO CustomLogServer - Got a request {requestId=3e6c256d-6e87-411e-8bf3-fbf81e7ce0e6, clientName=my.domain.name} +``` + +Log statements made outside of an RPC, such as the server's startup message, are unaffected: + +``` +2026/09/14 15:22:04:132 PDT INFO CustomLogServer - Server started, listening on 50051 +``` + +### Caveat + +The interceptor establishes the `ThreadContext` only for the `ServerCall.Listener` callbacks. It is +not set while interceptors further down the chain run their `interceptCall()` method, so a +downstream interceptor that logs from `interceptCall()` will not see these values. + +For more information, refer to gRPC Java's [README](../../README.md) and +[tutorial](https://grpc.io/docs/languages/java/basics). diff --git a/examples/example-log4j2/build.gradle b/examples/example-log4j2/build.gradle new file mode 100644 index 00000000000..51ff6352172 --- /dev/null +++ b/examples/example-log4j2/build.gradle @@ -0,0 +1,71 @@ +plugins { + id 'application' // Provide convenience executables for trying out the examples. + id 'com.google.protobuf' version '0.9.5' + // Generate IntelliJ IDEA's .idea & .iml project files + id 'idea' + id 'java' +} + +repositories { + mavenCentral() + mavenLocal() +} + +java { + sourceCompatibility = JavaVersion.VERSION_1_8 + targetCompatibility = JavaVersion.VERSION_1_8 +} + +// IMPORTANT: You probably want the non-SNAPSHOT version of gRPC. Make sure you +// are looking at a tagged version of the example and not "master"! + +// Feel free to delete the comment at the next line. It is just for safely +// updating the version in our release process. +def grpcVersion = '1.85.0-SNAPSHOT' // CURRENT_GRPC_VERSION +def protocVersion = '3.25.8' +def log4jVersion = '2.26.0' + +dependencies { + implementation "io.grpc:grpc-protobuf:${grpcVersion}" + implementation "io.grpc:grpc-stub:${grpcVersion}" + implementation "org.apache.logging.log4j:log4j-api:${log4jVersion}" + runtimeOnly "io.grpc:grpc-netty-shaded:${grpcVersion}" + // The Log4j 2 implementation is only needed at runtime; the example compiles against the API. + runtimeOnly "org.apache.logging.log4j:log4j-core:${log4jVersion}" +} + +protobuf { + protoc { artifact = "com.google.protobuf:protoc:${protocVersion}" } + plugins { + grpc { artifact = "io.grpc:protoc-gen-grpc-java:${grpcVersion}" } + } + generateProtoTasks { + all()*.plugins { grpc {} } + } +} + +startScripts.enabled = false + +task customLogServer(type: CreateStartScripts) { + mainClass = 'io.grpc.examples.logcontext.CustomLogServer' + applicationName = 'custom-log-server' + outputDir = new File(project.buildDir, 'tmp/scripts/' + name) + classpath = startScripts.classpath +} + +task customLogClient(type: CreateStartScripts) { + mainClass = 'io.grpc.examples.logcontext.CustomLogClient' + applicationName = 'custom-log-client' + outputDir = new File(project.buildDir, 'tmp/scripts/' + name) + classpath = startScripts.classpath +} + +application { + applicationDistribution.into('bin') { + from(customLogServer) + from(customLogClient) + filePermissions { + unix(0755) + } + } +} diff --git a/examples/example-log4j2/settings.gradle b/examples/example-log4j2/settings.gradle new file mode 100644 index 00000000000..d553cc5f674 --- /dev/null +++ b/examples/example-log4j2/settings.gradle @@ -0,0 +1,17 @@ +pluginManagement { + // https://issuetracker.google.com/issues/342522142#comment8 + // use D8/R8 8.0.44 or 8.1.44 with AGP 7.4 if needed. + buildscript { + repositories { + mavenCentral() + maven { + url = uri("https://storage.googleapis.com/r8-releases/raw") + } + } + dependencies { + classpath("com.android.tools:r8:8.1.44") + } + } +} + +rootProject.name = 'example-log4j2' diff --git a/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/CustomLogClient.java b/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/CustomLogClient.java new file mode 100644 index 00000000000..02edfedb30f --- /dev/null +++ b/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/CustomLogClient.java @@ -0,0 +1,125 @@ +/* + * Copyright 2026 The gRPC Authors + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package io.grpc.examples.logcontext; + +import io.grpc.CallOptions; +import io.grpc.Channel; +import io.grpc.ClientCall; +import io.grpc.ClientInterceptor; +import io.grpc.ForwardingClientCall.SimpleForwardingClientCall; +import io.grpc.Grpc; +import io.grpc.InsecureChannelCredentials; +import io.grpc.ManagedChannel; +import io.grpc.Metadata; +import io.grpc.MethodDescriptor; +import io.grpc.StatusRuntimeException; +import io.grpc.examples.helloworld.GreeterGrpc; +import io.grpc.examples.helloworld.HelloReply; +import io.grpc.examples.helloworld.HelloRequest; +import java.net.InetAddress; +import java.net.UnknownHostException; +import java.util.concurrent.TimeUnit; +import java.util.logging.Level; +import java.util.logging.Logger; + +/** + * A client like {@link io.grpc.examples.helloworld.HelloWorldClient} that sends the header + * {@link CustomLogServer} logs. + * + *

The client itself does not use Log4j 2; it only supplies the {@code clientName} header that + * {@link HeaderServerInterceptor} copies into the server's logging context. + */ +public class CustomLogClient { + + private static final Logger logger = Logger.getLogger(CustomLogClient.class.getName()); + + private final GreeterGrpc.GreeterBlockingStub blockingStub; + + /** Construct a client for accessing the server using the existing channel. */ + public CustomLogClient(Channel channel) { + // 'channel' here is a Channel, not a ManagedChannel, so it is not this code's responsibility to + // shut it down. + blockingStub = GreeterGrpc.newBlockingStub(channel).withInterceptors(new ClientInterceptor() { + @Override + public ClientCall interceptCall( + MethodDescriptor method, CallOptions callOptions, Channel next) { + return new SimpleForwardingClientCall(next.newCall(method, callOptions)) { + @Override + public void start(Listener responseListener, Metadata headers) { + headers.put(HeaderServerInterceptor.CLIENT_NAME_KEY, localHostName()); + super.start(responseListener, headers); + } + }; + } + }); + } + + private static String localHostName() { + try { + return InetAddress.getLocalHost().getHostName(); + } catch (UnknownHostException e) { + logger.log(Level.WARNING, "Unable to determine the local host name", e); + return "unknown"; + } + } + + /** Say hello to the server. */ + public void greet(String name) { + logger.info("Will try to greet " + name + " ..."); + HelloRequest request = HelloRequest.newBuilder().setName(name).build(); + HelloReply response; + try { + response = blockingStub.sayHello(request); + } catch (StatusRuntimeException e) { + logger.log(Level.WARNING, "RPC failed: {0}", e.getStatus()); + return; + } + logger.info("Greeting: " + response.getMessage()); + } + + /** + * Greet the server. If provided, the first element of {@code args} is the name to use in the + * greeting. The second argument is the target server. + */ + public static void main(String[] args) throws Exception { + String user = "world"; + // Access a service running on the local machine on port 50051 + String target = "localhost:50051"; + if (args.length > 0) { + if ("--help".equals(args[0])) { + System.err.println("Usage: [name [target]]"); + System.err.println(""); + System.err.println(" name The name you wish to be greeted by. Defaults to " + user); + System.err.println(" target The server to connect to. Defaults to " + target); + System.exit(1); + } + user = args[0]; + } + if (args.length > 1) { + target = args[1]; + } + + ManagedChannel channel = Grpc.newChannelBuilder(target, InsecureChannelCredentials.create()) + .build(); + try { + CustomLogClient client = new CustomLogClient(channel); + client.greet(user); + } finally { + channel.shutdownNow().awaitTermination(5, TimeUnit.SECONDS); + } + } +} diff --git a/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/CustomLogServer.java b/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/CustomLogServer.java new file mode 100644 index 00000000000..69130e5089e --- /dev/null +++ b/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/CustomLogServer.java @@ -0,0 +1,108 @@ +/* + * Copyright 2026 The gRPC Authors + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package io.grpc.examples.logcontext; + +import io.grpc.Grpc; +import io.grpc.InsecureServerCredentials; +import io.grpc.Server; +import io.grpc.ServerInterceptors; +import io.grpc.examples.helloworld.GreeterGrpc; +import io.grpc.examples.helloworld.HelloReply; +import io.grpc.examples.helloworld.HelloRequest; +import io.grpc.stub.StreamObserver; +import java.io.IOException; +import java.util.concurrent.TimeUnit; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; + +/** + * A server like {@link io.grpc.examples.helloworld.HelloWorldServer} that logs through Log4j 2. + * + *

It installs {@link HeaderServerInterceptor}, which puts a request id and the client name into + * the Log4j 2 {@code ThreadContext}. The {@code %X} conversion pattern in {@code log4j2.xml} then + * appends those values to every log statement the service makes, without the service having to pass + * them around itself. + */ +public class CustomLogServer { + + private static final Logger logger = LogManager.getLogger(CustomLogServer.class); + + /* The port on which the server should run */ + private static final int PORT = 50051; + + private Server server; + + private void start() throws IOException { + server = Grpc.newServerBuilderForPort(PORT, InsecureServerCredentials.create()) + .addService(ServerInterceptors.intercept(new GreeterImpl(), new HeaderServerInterceptor())) + .build() + .start(); + logger.info("Server started, listening on {}", PORT); + Runtime.getRuntime().addShutdownHook(new Thread() { + @Override + public void run() { + // Use stderr here since the logger may have been reset by its JVM shutdown hook. + System.err.println("*** shutting down gRPC server since JVM is shutting down"); + try { + CustomLogServer.this.stop(); + } catch (InterruptedException e) { + e.printStackTrace(System.err); + } + System.err.println("*** server shut down"); + } + }); + } + + private void stop() throws InterruptedException { + if (server != null) { + server.shutdown().awaitTermination(30, TimeUnit.SECONDS); + } + } + + /** + * Await termination on the main thread since the grpc library uses daemon threads. + */ + private void blockUntilShutdown() throws InterruptedException { + if (server != null) { + server.awaitTermination(); + } + } + + /** + * Main launches the server from the command line. + */ + public static void main(String[] args) throws IOException, InterruptedException { + final CustomLogServer server = new CustomLogServer(); + server.start(); + server.blockUntilShutdown(); + } + + private static class GreeterImpl extends GreeterGrpc.GreeterImplBase { + + @Override + public void sayHello(HelloRequest req, StreamObserver responseObserver) { + // The ThreadContext set by HeaderServerInterceptor is still in place here, so this outputs + // something like: + // 2026/09/14 15:22:12:686 PDT INFO CustomLogServer - Got a request + // {requestId=3e6c256d-6e87-411e-8bf3-fbf81e7ce0e6, clientName=my.domain.name} + logger.info("Got a request"); + HelloReply reply = HelloReply.newBuilder().setMessage("Hello " + req.getName()).build(); + responseObserver.onNext(reply); + responseObserver.onCompleted(); + } + } +} diff --git a/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/HeaderServerInterceptor.java b/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/HeaderServerInterceptor.java new file mode 100644 index 00000000000..ba9f3757840 --- /dev/null +++ b/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/HeaderServerInterceptor.java @@ -0,0 +1,108 @@ +/* + * Copyright 2026 The gRPC Authors + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package io.grpc.examples.logcontext; + +import io.grpc.ForwardingServerCallListener.SimpleForwardingServerCallListener; +import io.grpc.Metadata; +import io.grpc.ServerCall; +import io.grpc.ServerCallHandler; +import io.grpc.ServerInterceptor; +import java.util.UUID; +import org.apache.logging.log4j.CloseableThreadContext; +import org.apache.logging.log4j.CloseableThreadContext.Instance; + +/** + * A server interceptor that puts per-call values into the Log4j 2 {@code ThreadContext} so that + * every log statement made while handling the call is automatically annotated with them. + * + *

The values are scoped to the thread rather than to an {@link io.grpc.Context}, because that is + * what logging frameworks read from. Each callback re-populates the {@code ThreadContext} and + * clears it again on the way out, since gRPC does not guarantee that every callback for a call runs + * on the same thread. + * + *

Note that the context is only established for the callbacks below. It is not set while + * interceptors further down the chain run their {@code interceptCall()}, so a downstream + * interceptor logging from {@code interceptCall()} will not see these values. + */ +public class HeaderServerInterceptor implements ServerInterceptor { + + private static final String REQUEST_ID_NAME = "requestId"; + + static final Metadata.Key CLIENT_NAME_KEY = + Metadata.Key.of("clientName", Metadata.ASCII_STRING_MARSHALLER); + + @Override + public ServerCall.Listener interceptCall( + ServerCall call, + final Metadata requestHeaders, + ServerCallHandler next) { + + final String requestId = UUID.randomUUID().toString(); + final String headerValue = requestHeaders.get(CLIENT_NAME_KEY); + final String clientName = headerValue != null ? headerValue : "unknown"; + + return new SimpleForwardingServerCallListener(next.startCall(call, requestHeaders)) { + + /** + * Populates the Log4j 2 {@code ThreadContext} for the duration of the try-with-resources + * block that calls this method. + */ + private Instance logContext() { + return CloseableThreadContext.put(REQUEST_ID_NAME, requestId) + .put(CLIENT_NAME_KEY.originalName(), clientName); + } + + @Override + public void onCancel() { + try (Instance ignored = logContext()) { + super.onCancel(); + } + } + + @Override + public void onComplete() { + try (Instance ignored = logContext()) { + super.onComplete(); + } + } + + @Override + public void onMessage(ReqT message) { + try (Instance ignored = logContext()) { + super.onMessage(message); + } + } + + @Override + public void onReady() { + try (Instance ignored = logContext()) { + super.onReady(); + } + } + + @Override + public void onHalfClose() { + // For unary calls this is the callback that invokes the service method, so this is the one + // that matters most. The others are here so that the pattern is correct if this code is + // copied into a streaming service. + try (Instance ignored = logContext()) { + super.onHalfClose(); + } + } + }; + } +} diff --git a/examples/example-log4j2/src/main/proto/helloworld/helloworld.proto b/examples/example-log4j2/src/main/proto/helloworld/helloworld.proto new file mode 100644 index 00000000000..442539973a0 --- /dev/null +++ b/examples/example-log4j2/src/main/proto/helloworld/helloworld.proto @@ -0,0 +1,37 @@ +// Copyright 2026 The gRPC Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +syntax = "proto3"; + +option java_multiple_files = true; +option java_package = "io.grpc.examples.helloworld"; +option java_outer_classname = "HelloWorldProto"; +option objc_class_prefix = "HLW"; + +package helloworld; + +// The greeting service definition. +service Greeter { + // Sends a greeting + rpc SayHello (HelloRequest) returns (HelloReply) {} +} + +// The request message containing the user's name. +message HelloRequest { + string name = 1; +} + +// The response message containing the greetings +message HelloReply { + string message = 1; +} diff --git a/examples/example-log4j2/src/main/resources/log4j2.xml b/examples/example-log4j2/src/main/resources/log4j2.xml new file mode 100644 index 00000000000..d69c02b5224 --- /dev/null +++ b/examples/example-log4j2/src/main/resources/log4j2.xml @@ -0,0 +1,34 @@ + + + + + + + + + + + + + + + From 9268f1ac6a8d84c317a7a94c38db408f2369acec Mon Sep 17 00:00:00 2001 From: agrawalabhi Date: Mon, 14 Sep 2026 09:11:40 +0000 Subject: [PATCH 2/2] examples: address review feedback on the Log4j 2 example Establish the ThreadContext around next.startCall() as well as in the listener callbacks, so that interceptors further down the chain see the values while their own interceptCall() runs. This was raised on #5835 and left unresolved there. Also resolve the client's host name once instead of on every RPC, bump Log4j 2 to 2.26.1, and correct the log4j2.xml comment, which described a bare %X rather than the explicit keys the pattern actually uses. --- examples/example-log4j2/README.md | 14 +++++-- examples/example-log4j2/build.gradle | 2 +- .../examples/logcontext/CustomLogClient.java | 6 ++- .../logcontext/HeaderServerInterceptor.java | 38 ++++++++++--------- .../src/main/resources/log4j2.xml | 7 ++-- 5 files changed, 41 insertions(+), 26 deletions(-) diff --git a/examples/example-log4j2/README.md b/examples/example-log4j2/README.md index add5d4e2636..d8f97492f78 100644 --- a/examples/example-log4j2/README.md +++ b/examples/example-log4j2/README.md @@ -51,11 +51,17 @@ Log statements made outside of an RPC, such as the server's startup message, are 2026/09/14 15:22:04:132 PDT INFO CustomLogServer - Server started, listening on 50051 ``` -### Caveat +### Why each callback sets the context -The interceptor establishes the `ThreadContext` only for the `ServerCall.Listener` callbacks. It is -not set while interceptors further down the chain run their `interceptCall()` method, so a -downstream interceptor that logs from `interceptCall()` will not see these values. +gRPC does not guarantee that every callback for a call runs on the same thread, and an application +that supplies its own call executor may have each callback handled by a different worker. Logging +frameworks read from thread-local storage, so the values have to be established on whichever thread +is actually running the code that logs. That is why each `ServerCall.Listener` callback re-populates +the `ThreadContext` and clears it again on the way out, instead of the interceptor setting it once +and leaving it. + +The context is also established around `next.startCall()`, so that interceptors further down the +chain see these values while their own `interceptCall()` runs. For more information, refer to gRPC Java's [README](../../README.md) and [tutorial](https://grpc.io/docs/languages/java/basics). diff --git a/examples/example-log4j2/build.gradle b/examples/example-log4j2/build.gradle index 51ff6352172..314f5b1bc0a 100644 --- a/examples/example-log4j2/build.gradle +++ b/examples/example-log4j2/build.gradle @@ -23,7 +23,7 @@ java { // updating the version in our release process. def grpcVersion = '1.85.0-SNAPSHOT' // CURRENT_GRPC_VERSION def protocVersion = '3.25.8' -def log4jVersion = '2.26.0' +def log4jVersion = '2.26.1' dependencies { implementation "io.grpc:grpc-protobuf:${grpcVersion}" diff --git a/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/CustomLogClient.java b/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/CustomLogClient.java index 02edfedb30f..2985f7bcea4 100644 --- a/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/CustomLogClient.java +++ b/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/CustomLogClient.java @@ -47,6 +47,10 @@ public class CustomLogClient { private static final Logger logger = Logger.getLogger(CustomLogClient.class.getName()); + // Resolved once rather than per RPC: InetAddress.getLocalHost() may block on a DNS lookup, and + // start() runs on the calling thread. + private static final String LOCAL_HOST_NAME = localHostName(); + private final GreeterGrpc.GreeterBlockingStub blockingStub; /** Construct a client for accessing the server using the existing channel. */ @@ -60,7 +64,7 @@ public ClientCall interceptCall( return new SimpleForwardingClientCall(next.newCall(method, callOptions)) { @Override public void start(Listener responseListener, Metadata headers) { - headers.put(HeaderServerInterceptor.CLIENT_NAME_KEY, localHostName()); + headers.put(HeaderServerInterceptor.CLIENT_NAME_KEY, LOCAL_HOST_NAME); super.start(responseListener, headers); } }; diff --git a/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/HeaderServerInterceptor.java b/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/HeaderServerInterceptor.java index ba9f3757840..20464ec5d46 100644 --- a/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/HeaderServerInterceptor.java +++ b/examples/example-log4j2/src/main/java/io/grpc/examples/logcontext/HeaderServerInterceptor.java @@ -34,9 +34,8 @@ * clears it again on the way out, since gRPC does not guarantee that every callback for a call runs * on the same thread. * - *

Note that the context is only established for the callbacks below. It is not set while - * interceptors further down the chain run their {@code interceptCall()}, so a downstream - * interceptor logging from {@code interceptCall()} will not see these values. + *

The context is also established around {@code next.startCall()}, so that interceptors further + * down the chain, and the handler's own call setup, see these values too. */ public class HeaderServerInterceptor implements ServerInterceptor { @@ -45,6 +44,15 @@ public class HeaderServerInterceptor implements ServerInterceptor { static final Metadata.Key CLIENT_NAME_KEY = Metadata.Key.of("clientName", Metadata.ASCII_STRING_MARSHALLER); + /** + * Populates the Log4j 2 {@code ThreadContext} for the duration of the try-with-resources block + * that calls this method, restoring whatever was there before on the way out. + */ + private static Instance logContext(String requestId, String clientName) { + return CloseableThreadContext.put(REQUEST_ID_NAME, requestId) + .put(CLIENT_NAME_KEY.originalName(), clientName); + } + @Override public ServerCall.Listener interceptCall( ServerCall call, @@ -55,41 +63,37 @@ public ServerCall.Listener interceptCall( final String headerValue = requestHeaders.get(CLIENT_NAME_KEY); final String clientName = headerValue != null ? headerValue : "unknown"; - return new SimpleForwardingServerCallListener(next.startCall(call, requestHeaders)) { + final ServerCall.Listener delegate; + try (Instance ignored = logContext(requestId, clientName)) { + delegate = next.startCall(call, requestHeaders); + } - /** - * Populates the Log4j 2 {@code ThreadContext} for the duration of the try-with-resources - * block that calls this method. - */ - private Instance logContext() { - return CloseableThreadContext.put(REQUEST_ID_NAME, requestId) - .put(CLIENT_NAME_KEY.originalName(), clientName); - } + return new SimpleForwardingServerCallListener(delegate) { @Override public void onCancel() { - try (Instance ignored = logContext()) { + try (Instance ignored = logContext(requestId, clientName)) { super.onCancel(); } } @Override public void onComplete() { - try (Instance ignored = logContext()) { + try (Instance ignored = logContext(requestId, clientName)) { super.onComplete(); } } @Override public void onMessage(ReqT message) { - try (Instance ignored = logContext()) { + try (Instance ignored = logContext(requestId, clientName)) { super.onMessage(message); } } @Override public void onReady() { - try (Instance ignored = logContext()) { + try (Instance ignored = logContext(requestId, clientName)) { super.onReady(); } } @@ -99,7 +103,7 @@ public void onHalfClose() { // For unary calls this is the callback that invokes the service method, so this is the one // that matters most. The others are here so that the pattern is correct if this code is // copied into a streaming service. - try (Instance ignored = logContext()) { + try (Instance ignored = logContext(requestId, clientName)) { super.onHalfClose(); } } diff --git a/examples/example-log4j2/src/main/resources/log4j2.xml b/examples/example-log4j2/src/main/resources/log4j2.xml index d69c02b5224..4aabcd48d6c 100644 --- a/examples/example-log4j2/src/main/resources/log4j2.xml +++ b/examples/example-log4j2/src/main/resources/log4j2.xml @@ -18,9 +18,10 @@