Merge pull request #33213 from overleaf/em-git-bridge-structured-logging

git-bridge: structured JSON logging for GCP Cloud Logging
GitOrigin-RevId: 7ff06202cab6fe0e35c4a4f757d0b9ad04e5431a

services/git-bridge/pom.xml

@@ -27,6 +27,7 @@
         <google.http.client.version>1.23.0</google.http.client.version>
         <commons.lang3.version>3.20.0</commons.lang3.version>
         <logback.classic.version>1.5.24</logback.classic.version>
+        <logstash.logback.encoder.version>8.0</logstash.logback.encoder.version>
         <mockserver.version>5.15.0</mockserver.version>
         <mockito.version>5.20.0</mockito.version>
         <aws.java.sdk.version>2.41.7</aws.java.sdk.version>
@@ -200,6 +201,12 @@
             <artifactId>logback-classic</artifactId>
             <version>${logback.classic.version}</version>
         </dependency>
+        <!-- https://mvnrepository.com/artifact/net.logstash.logback/logstash-logback-encoder -->
+        <dependency>
+            <groupId>net.logstash.logback</groupId>
+            <artifactId>logstash-logback-encoder</artifactId>
+            <version>${logstash.logback.encoder.version}</version>
+        </dependency>
         <!-- https://mvnrepository.com/artifact/org.mock-server/mockserver-netty -->
         <dependency>
             <groupId>org.mock-server</groupId>

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/Main.java

@@ -1,5 +1,7 @@
 package uk.ac.ic.wlgitbridge;
 
+import java.net.InetAddress;
+import java.net.UnknownHostException;
 import java.util.Arrays;
 import uk.ac.ic.wlgitbridge.application.GitBridgeApp;
 import uk.ac.ic.wlgitbridge.util.Log;
@@ -27,6 +29,19 @@ import uk.ac.ic.wlgitbridge.util.Log;
 public class Main {
 
   public static void main(String[] args) {
+    if ("gke".equals(System.getenv("LOGGING_FORMAT"))) {
+      System.setProperty("logback.configurationFile", "logback-gke.xml");
+    }
+    String hostname = System.getenv("HOSTNAME");
+    if (hostname == null || hostname.isEmpty()) {
+      try {
+        hostname = InetAddress.getLocalHost().getHostName();
+      } catch (UnknownHostException e) {
+        hostname = "unknown";
+      }
+    }
+    System.setProperty("HOSTNAME", hostname);
+    System.setProperty("PID", String.valueOf(ProcessHandle.current().pid()));
     Log.info("Git Bridge started with args: " + Arrays.toString(args));
     try {
       new GitBridgeApp(args).run();

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/BunyanLevelJsonProvider.java

@@ -0,0 +1,24 @@
+package uk.ac.ic.wlgitbridge.server;
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import com.fasterxml.jackson.core.JsonGenerator;
+import java.io.IOException;
+import net.logstash.logback.composite.AbstractFieldJsonProvider;
+
+/** Writes log level as a bunyan-compatible numeric value. */
+public class BunyanLevelJsonProvider extends AbstractFieldJsonProvider<ILoggingEvent> {
+
+  @Override
+  public void writeTo(JsonGenerator generator, ILoggingEvent event) throws IOException {
+    generator.writeNumberField("level", toBunyanLevel(event.getLevel()));
+  }
+
+  private static int toBunyanLevel(Level level) {
+    if (level.isGreaterOrEqual(Level.ERROR)) return 50;
+    if (level.isGreaterOrEqual(Level.WARN)) return 40;
+    if (level.isGreaterOrEqual(Level.INFO)) return 30;
+    if (level.isGreaterOrEqual(Level.DEBUG)) return 20;
+    return 10;
+  }
+}

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/GceMetadataLogLevelChecker.java

@@ -0,0 +1,100 @@
+package uk.ac.ic.wlgitbridge.server;
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
+import java.io.IOException;
+import java.net.URI;
+import java.net.http.HttpClient;
+import java.net.http.HttpRequest;
+import java.net.http.HttpResponse;
+import java.nio.file.Files;
+import java.nio.file.Path;
+import java.time.Duration;
+import java.util.concurrent.Executors;
+import java.util.concurrent.ScheduledExecutorService;
+import java.util.concurrent.TimeUnit;
+import org.slf4j.LoggerFactory;
+
+public class GceMetadataLogLevelChecker {
+
+  private static final Path TRACING_END_TIME_FILE = Path.of("/logging/tracingEndTime");
+  private static final String METADATA_BASE =
+      "http://metadata.google.internal/computeMetadata/v1/project/attributes/";
+
+  private final Logger appLogger;
+  private final Level defaultLevel;
+  private final URI metadataUri;
+  private final HttpClient httpClient;
+  private final ScheduledExecutorService scheduler;
+
+  public GceMetadataLogLevelChecker(String serviceName, Level defaultLevel) {
+    this.appLogger = (Logger) LoggerFactory.getLogger("uk.ac.ic.wlgitbridge");
+    this.defaultLevel = defaultLevel;
+    this.metadataUri = URI.create(METADATA_BASE + serviceName + "-setLogLevelEndTime");
+    this.httpClient = HttpClient.newBuilder().connectTimeout(Duration.ofSeconds(5)).build();
+    this.scheduler =
+        Executors.newSingleThreadScheduledExecutor(
+            r -> {
+              Thread t = new Thread(r, "log-level-checker");
+              t.setDaemon(true);
+              return t;
+            });
+  }
+
+  public void start() {
+    checkLogLevel();
+    scheduler.scheduleAtFixedRate(this::checkLogLevel, 60, 60, TimeUnit.SECONDS);
+  }
+
+  public void stop() {
+    scheduler.shutdown();
+  }
+
+  private void checkLogLevel() {
+    try {
+      long endTime = fetchTracingEndTime();
+      if (endTime > System.currentTimeMillis()) {
+        setLevel(Level.TRACE);
+      } else {
+        setLevel(defaultLevel);
+      }
+    } catch (Exception e) {
+      appLogger.warn("Failed to fetch log level: {}", e.getMessage());
+      setLevel(defaultLevel);
+    }
+  }
+
+  private void setLevel(Level newLevel) {
+    Level currentLevel = appLogger.getLevel();
+    if (currentLevel == newLevel) return;
+    appLogger.setLevel(newLevel);
+    appLogger.info("Log level changed from {} to {}", currentLevel, newLevel);
+  }
+
+  private long fetchTracingEndTime() throws Exception {
+    try {
+      return Long.parseLong(Files.readString(TRACING_END_TIME_FILE).trim());
+    } catch (IOException ignored) {
+      // File not present; fall back to GCE project metadata
+    }
+    return fetchTracingEndTimeFromMetadata();
+  }
+
+  private long fetchTracingEndTimeFromMetadata() throws Exception {
+    HttpRequest request =
+        HttpRequest.newBuilder()
+            .uri(metadataUri)
+            .header("Metadata-Flavor", "Google")
+            .timeout(Duration.ofSeconds(5))
+            .GET()
+            .build();
+    HttpResponse<String> response = httpClient.send(request, HttpResponse.BodyHandlers.ofString());
+    if (response.statusCode() == 404) {
+      return 0;
+    }
+    if (response.statusCode() != 200) {
+      throw new Exception("Unexpected HTTP status: " + response.statusCode());
+    }
+    return Long.parseLong(response.body().trim());
+  }
+}

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/GcpLabelsJsonProvider.java

@@ -0,0 +1,22 @@
+package uk.ac.ic.wlgitbridge.server;
+
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import com.fasterxml.jackson.core.JsonGenerator;
+import java.io.IOException;
+import net.logstash.logback.composite.AbstractFieldJsonProvider;
+import net.logstash.logback.composite.JsonWritingUtils;
+
+/** Writes projectId from MDC into logging.googleapis.com/labels so GCP Cloud Logging indexes it. */
+public class GcpLabelsJsonProvider extends AbstractFieldJsonProvider<ILoggingEvent> {
+
+  @Override
+  public void writeTo(JsonGenerator generator, ILoggingEvent event) throws IOException {
+    String projectId = event.getMDCPropertyMap().get("projectId");
+    if (projectId == null || projectId.isEmpty()) {
+      return;
+    }
+    generator.writeObjectFieldStart("logging.googleapis.com/labels");
+    JsonWritingUtils.writeStringField(generator, "projectId", projectId);
+    generator.writeEndObject();
+  }
+}

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/GitBridgeServer.java

@@ -1,5 +1,6 @@
 package uk.ac.ic.wlgitbridge.server;
 
+import ch.qos.logback.classic.Level;
 import jakarta.servlet.DispatcherType;
 import jakarta.servlet.Filter;
 import jakarta.servlet.ServletException;
@@ -45,6 +46,8 @@ public class GitBridgeServer {
 
   private final Server jettyServer;
 
+  private final GceMetadataLogLevelChecker logLevelChecker;
+
   private final int port;
   private String rootGitDirectoryPath;
   private String apiBaseURL;
@@ -72,6 +75,11 @@ public class GitBridgeServer {
     Util.setServiceName(config.getServiceName());
     Util.setPostbackURL(config.getPostbackURL());
     Util.setPort(config.getPort());
+    String configuredLogLevel = System.getenv().getOrDefault("LOG_LEVEL", "INFO");
+    String normalizedLogLevel =
+        "WARNING".equalsIgnoreCase(configuredLogLevel) ? "WARN" : configuredLogLevel;
+    Level defaultLogLevel = Level.toLevel(normalizedLogLevel, Level.INFO);
+    logLevelChecker = new GceMetadataLogLevelChecker(config.getServiceName(), defaultLogLevel);
   }
 
   /*
@@ -82,6 +90,7 @@ public class GitBridgeServer {
       bridge.checkDB();
       jettyServer.start();
       bridge.startBackgroundJobs();
+      logLevelChecker.start();
       Log.info(Util.getServiceName() + "-Git Bridge server started");
       Log.info("Listening on port: " + port);
       Log.info("Bridged to: " + apiBaseURL);
@@ -95,6 +104,7 @@ public class GitBridgeServer {
   }
 
   public void stop() {
+    logLevelChecker.stop();
     try {
       jettyServer.stop();
     } catch (Exception e) {
@@ -152,6 +162,8 @@ public class GitBridgeServer {
       throws ServletException {
     final ServletContextHandler servletContextHandler = new ServletContextHandler();
     servletContextHandler.setSessionHandler(new SessionHandler());
+    servletContextHandler.addFilter(
+        new FilterHolder(new MdcLoggingFilter()), "/*", EnumSet.of(DispatcherType.REQUEST));
     if (config.getOauth2Server() != null) {
       Filter filter =
           new Oauth2Filter(snapshotApi, config.getOauth2Server(), config.isUserPasswordEnabled());

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/MdcLoggingFilter.java

@@ -0,0 +1,33 @@
+package uk.ac.ic.wlgitbridge.server;
+
+import jakarta.servlet.*;
+import jakarta.servlet.http.HttpServletRequest;
+import java.io.IOException;
+import org.slf4j.MDC;
+import uk.ac.ic.wlgitbridge.util.Util;
+
+public class MdcLoggingFilter implements Filter {
+
+  @Override
+  public void init(FilterConfig filterConfig) {}
+
+  @Override
+  public void doFilter(
+      ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain)
+      throws IOException, ServletException {
+    HttpServletRequest request = (HttpServletRequest) servletRequest;
+    String[] parts = request.getRequestURI().split("/");
+    if (parts.length > 1) {
+      MDC.put("projectId", Util.removeAllSuffixes(parts[1], ".git"));
+    }
+    MDC.put("ip", Util.getClientIp(request));
+    try {
+      filterChain.doFilter(servletRequest, servletResponse);
+    } finally {
+      MDC.clear();
+    }
+  }
+
+  @Override
+  public void destroy() {}
+}

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/Oauth2Filter.java

@@ -287,11 +287,7 @@ public class Oauth2Filter implements Filter {
    * Gets the remote IP from the request.
    */
   private String getClientIp(HttpServletRequest request) {
-    String clientIp = request.getHeader("X-Forwarded-For");
-    if (clientIp == null) {
-      clientIp = request.getRemoteAddr();
-    }
-    return clientIp;
+    return Util.getClientIp(request);
   }
 
   /*

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/util/Util.java

@@ -2,6 +2,7 @@ package uk.ac.ic.wlgitbridge.util;
 
 import com.google.gson.JsonElement;
 import com.google.gson.JsonObject;
+import jakarta.servlet.http.HttpServletRequest;
 import java.io.*;
 import java.text.DateFormat;
 import java.text.SimpleDateFormat;
@@ -158,6 +159,17 @@ public class Util {
     return fromStream(stream, 0);
   }
 
+  public static String getClientIp(HttpServletRequest request) {
+    String clientIp = request.getHeader("X-Forwarded-For");
+    if (clientIp != null) {
+      clientIp = clientIp.split(",", 2)[0].trim();
+    }
+    if (clientIp == null || clientIp.isEmpty()) {
+      clientIp = request.getRemoteAddr();
+    }
+    return clientIp;
+  }
+
   public static String getCodeFromResponse(JsonObject json) {
     String code = "error";
     JsonElement codeElement = json.get("code");

services/git-bridge/src/main/resources/logback-gke.xml

@@ -0,0 +1,60 @@
+<configuration>
+
+    <variable name="LOG_LEVEL" value="${LOG_LEVEL:-INFO}" />
+
+    <!-- Log everything (subject to logger and root levels set below) to stdout. -->
+    <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
+        <target>System.out</target>
+        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
+            <timestampPattern>yyyy-MM-dd'T'HH:mm:ss.SSSXXX</timestampPattern>
+            <fieldNames>
+                <timestamp>time</timestamp>
+                <version>[ignore]</version>
+                <message>message</message>
+                <logger>logger</logger>
+                <thread>thread</thread>
+                <level>[ignore]</level>
+                <levelValue>[ignore]</levelValue>
+                <stackTrace>stack_trace</stackTrace>
+            </fieldNames>
+            <provider class="net.logstash.logback.composite.loggingevent.LoggingEventPatternJsonProvider">
+                <pattern>{"severity":"%replace(%replace(%level){'WARN','WARNING'}){'TRACE','DEBUG'}"}</pattern>
+            </provider>
+            <provider class="uk.ac.ic.wlgitbridge.server.GcpLabelsJsonProvider" />
+        </encoder>
+    </appender>
+
+    <!-- Log warnings and errors to stderr. We send them to a log aggregation service for monitoring. -->
+    <appender name="stderr" class="ch.qos.logback.core.ConsoleAppender">
+        <target>System.err</target>
+        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
+            <level>WARN</level>
+        </filter>
+        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
+            <timestampPattern>yyyy-MM-dd'T'HH:mm:ss.SSSXXX</timestampPattern>
+            <fieldNames>
+                <timestamp>time</timestamp>
+                <version>[ignore]</version>
+                <message>message</message>
+                <logger>logger</logger>
+                <thread>thread</thread>
+                <level>[ignore]</level>
+                <levelValue>[ignore]</levelValue>
+                <stackTrace>stack_trace</stackTrace>
+            </fieldNames>
+            <provider class="net.logstash.logback.composite.loggingevent.LoggingEventPatternJsonProvider">
+                <pattern>{"severity":"%replace(%replace(%level){'WARN','WARNING'}){'TRACE','DEBUG'}"}</pattern>
+            </provider>
+            <provider class="uk.ac.ic.wlgitbridge.server.GcpLabelsJsonProvider" />
+        </encoder>
+    </appender>
+
+    <!-- Set log levels for the application (or parts of the application). -->
+    <logger name="uk.ac.ic.wlgitbridge" level="${LOG_LEVEL}" />
+
+    <!-- The root log level determines how much our dependencies put in the logs. -->
+    <root level="WARN">
+        <appender-ref ref="stdout" />
+        <appender-ref ref="stderr" />
+    </root>
+</configuration>

services/git-bridge/src/main/resources/logback.xml

@@ -5,11 +5,22 @@
     <!-- Log everything (subject to logger and root levels set below) to stdout. -->
     <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
         <target>System.out</target>
-        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
-            <level>${LOG_LEVEL}</level>
-        </filter>
-        <encoder>
-            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread] %logger{0}: %msg%n</pattern>
+        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
+            <timestampPattern>yyyy-MM-dd'T'HH:mm:ss.SSSXXX</timestampPattern>
+            <fieldNames>
+                <timestamp>time</timestamp>
+                <version>[ignore]</version>
+                <message>msg</message>
+                <logger>[ignore]</logger>
+                <thread>[ignore]</thread>
+                <level>[ignore]</level>
+                <levelValue>[ignore]</levelValue>
+                <stackTrace>stack_trace</stackTrace>
+            </fieldNames>
+            <provider class="net.logstash.logback.composite.loggingevent.LoggingEventPatternJsonProvider">
+                <pattern>{"v":0,"name":"git-bridge","hostname":"${HOSTNAME:-unknown}","pid":${PID:-0}}</pattern>
+            </provider>
+            <provider class="uk.ac.ic.wlgitbridge.server.BunyanLevelJsonProvider" />
         </encoder>
     </appender>
 
@@ -19,8 +30,22 @@
         <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
             <level>WARN</level>
         </filter>
-        <encoder>
-            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread] %logger{0}: %msg%n</pattern>
+        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
+            <timestampPattern>yyyy-MM-dd'T'HH:mm:ss.SSSXXX</timestampPattern>
+            <fieldNames>
+                <timestamp>time</timestamp>
+                <version>[ignore]</version>
+                <message>msg</message>
+                <logger>[ignore]</logger>
+                <thread>[ignore]</thread>
+                <level>[ignore]</level>
+                <levelValue>[ignore]</levelValue>
+                <stackTrace>stack_trace</stackTrace>
+            </fieldNames>
+            <provider class="net.logstash.logback.composite.loggingevent.LoggingEventPatternJsonProvider">
+                <pattern>{"v":0,"name":"git-bridge","hostname":"${HOSTNAME:-unknown}","pid":${PID:-0}}</pattern>
+            </provider>
+            <provider class="uk.ac.ic.wlgitbridge.server.BunyanLevelJsonProvider" />
         </encoder>
     </appender>
 
@@ -32,4 +57,4 @@
         <appender-ref ref="stdout" />
         <appender-ref ref="stderr" />
     </root>
-</configuration>
+</configuration>