armeria: adds access logger integration (#115)

I think this setup isn't necessarily intuitive, so needs consideration if something to do by default or not. ``` zipkin | 2024-02-20 01:23:48:341 [armeria-boss-http-*:9411] INFO Server - Serving HTTP at /0.0.0.0:9411 - http://127.0.0.1:9411/ backend | 01:23:52.939 [main] [] [/] INFO brave.example.HttpTracingFactory - Using zipkin URI: http://zipkin:9411//api/v2/spans backend | 01:23:53.367 [armeria-boss-http-*:9000] [] [/] INFO com.linecorp.armeria.server.Server - Serving HTTP at /0.0.0.0:9000 - http://127.0.0.1:9000/ frontend | 01:23:54.573 [main] [] [/] INFO brave.example.HttpTracingFactory - Using zipkin URI: http://zipkin:9411//api/v2/spans frontend | 01:23:55.042 [armeria-boss-http-*:8081] [] [/] INFO com.linecorp.armeria.server.Server - Serving HTTP at /0.0.0.0:8081 - http://127.0.0.1:8081/ frontend | [84add10fbf6ccd88/84add10fbf6ccd88] 172.29.0.1 - - 20/Feb/2024:01:23:59 +0000 "GET /#Frontend$$Lambda/0x0000000100334120 h1c" 200 28 backend | [84add10fbf6ccd88/0c65e000e3889b86] 172.29.0.4 - - 20/Feb/2024:01:23:59 +0000 "GET /api#Backend$$Lambda/0x0000000100330968 h2c" 200 28 ``` Signed-off-by: Adrian Cole <[email protected]>
openzipkin · Feb 20, 2024 · 9fe8f0d · 9fe8f0d
1 parent 14a408d
commit 9fe8f0d
Show file tree

Hide file tree

Showing 4 changed files with 44 additions and 1 deletion.
diff --git a/armeria/src/main/java/brave/example/Backend.java b/armeria/src/main/java/brave/example/Backend.java
@@ -5,6 +5,7 @@
 import com.linecorp.armeria.server.Server;
 import com.linecorp.armeria.server.brave.BraveService;
 import com.linecorp.armeria.server.healthcheck.HealthCheckService;
+import com.linecorp.armeria.server.logging.AccessLogWriter;
 import com.linecorp.armeria.server.logging.LoggingService;
 import java.util.Date;
 
@@ -13,8 +14,12 @@ public final class Backend {
   public static void main(String[] args) {
     final HttpTracing httpTracing = HttpTracingFactory.create("backend");
 
+    final AccessLogWriter accessLogWriter =
+        HttpTracingFactory.accessLogWriter(httpTracing, AccessLogWriter.common());
+
     final Server server = Server.builder()
         .http(9000)
+        .accessLogWriter(accessLogWriter, true)
         .service("/health", HealthCheckService.builder().build())
         .service("/api", (ctx, req) -> {
           String response = new Date().toString();

diff --git a/armeria/src/main/java/brave/example/Frontend.java b/armeria/src/main/java/brave/example/Frontend.java
@@ -6,6 +6,7 @@
 import com.linecorp.armeria.server.Server;
 import com.linecorp.armeria.server.brave.BraveService;
 import com.linecorp.armeria.server.healthcheck.HealthCheckService;
+import com.linecorp.armeria.server.logging.AccessLogWriter;
 import com.linecorp.armeria.server.logging.LoggingService;
 
 public final class Frontend {
@@ -18,9 +19,13 @@ public static void main(String[] args) {
             .decorator(BraveClient.newDecorator(httpTracing.clientOf("backend")))
             .build();
 
+    final AccessLogWriter accessLogWriter =
+        HttpTracingFactory.accessLogWriter(httpTracing, AccessLogWriter.common());
+
     final Server server =
         Server.builder()
             .http(8081)
+            .accessLogWriter(accessLogWriter, true)
             .service("/health", HealthCheckService.builder().build())
             .service("/", (ctx, req) -> backendClient.get(""))
             .decorator(BraveService.newDecorator(httpTracing))

diff --git a/armeria/src/main/java/brave/example/HttpTracingFactory.java b/armeria/src/main/java/brave/example/HttpTracingFactory.java
@@ -9,14 +9,19 @@
 import brave.http.HttpTracing;
 import brave.propagation.B3Propagation;
 import brave.propagation.CurrentTraceContext;
+import brave.propagation.CurrentTraceContext.Scope;
 import brave.propagation.CurrentTraceContext.ScopeDecorator;
 import brave.propagation.Propagation;
+import brave.propagation.TraceContext;
 import com.linecorp.armeria.client.WebClient;
 import com.linecorp.armeria.client.eureka.EurekaEndpointGroup;
 import com.linecorp.armeria.client.eureka.EurekaEndpointGroupBuilder;
 import com.linecorp.armeria.common.SessionProtocol;
 import com.linecorp.armeria.common.auth.BasicToken;
 import com.linecorp.armeria.common.brave.RequestContextCurrentTraceContext;
+import com.linecorp.armeria.internal.common.brave.TraceContextUtil;
+import com.linecorp.armeria.server.logging.AccessLogWriter;
+import com.linecorp.armeria.server.logging.LoggingService;
 import java.io.IOException;
 import java.net.URI;
 import java.net.URISyntaxException;
@@ -52,6 +57,23 @@ static ScopeDecorator correlationScopeDecorator() {
         .add(CorrelationScopeConfig.SingleCorrelationField.create(USER_NAME)).build();
   }
 
+  /**
+   * Unlike {@link LoggingService#newDecorator}, the trace context isn't yet integrated for
+   * {@link AccessLogWriter}. Put it into scope manually until this is done in Armeria.
+   */
+  static AccessLogWriter accessLogWriter(HttpTracing httpTracing, AccessLogWriter delegate) {
+    CurrentTraceContext current = httpTracing.tracing().currentTraceContext();
+    // Adrian isn't sure if this is really the best way, but you have to make the thread
+    // "context aware" to avoid log warnings.
+    return log -> log.context().makeContextAware(() -> {
+      TraceContext ctx = TraceContextUtil.traceContext(log.context());
+      try (Scope scope = current.maybeScope(ctx)) {
+        delegate.log(log);
+      }
+    }
+    ).run();
+  }
+
   /** Propagates trace context between threads. */
   static CurrentTraceContext currentTraceContext(ScopeDecorator correlationScopeDecorator) {
     return RequestContextCurrentTraceContext.builder()

diff --git a/armeria/src/main/resources/logback.xml b/armeria/src/main/resources/logback.xml
@@ -8,7 +8,18 @@
     </encoder>
   </appender>
 
-  <logger name="com.linecorp.armeria" level="info"/>
+  <appender name="ACCESS" class="ch.qos.logback.core.ConsoleAppender">
+    <encoder>
+      <pattern>[%X{traceId}/%X{spanId}] %msg%n</pattern>
+    </encoder>
+  </appender>
+
+  <logger name="com.linecorp.armeria.logging.access" level="info" additivity="false">
+    <appender-ref ref="ACCESS"/>
+  </logger>
+
+  <logger name="com.linecorp.armeria" level="warn"/>
+  <logger name="com.linecorp.armeria.server.Server" level="info"/>
 
   <root level="info">
     <appender-ref ref="STDOUT" />