From d48af6dc1bccc01e5ee28e55dadd5c06885b1ca7 Mon Sep 17 00:00:00 2001 From: Eric Mc Sween <5454374+emcsween@users.noreply.github.com> Date: Tue, 12 May 2026 11:30:29 -0400 Subject: [PATCH] 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 | 7 ++ .../main/java/uk/ac/ic/wlgitbridge/Main.java | 15 +++ .../server/BunyanLevelJsonProvider.java | 24 +++++ .../server/GceMetadataLogLevelChecker.java | 100 ++++++++++++++++++ .../server/GcpLabelsJsonProvider.java | 22 ++++ .../wlgitbridge/server/GitBridgeServer.java | 12 +++ .../wlgitbridge/server/MdcLoggingFilter.java | 33 ++++++ .../ic/wlgitbridge/server/Oauth2Filter.java | 6 +- .../java/uk/ac/ic/wlgitbridge/util/Util.java | 12 +++ .../src/main/resources/logback-gke.xml | 60 +++++++++++ .../git-bridge/src/main/resources/logback.xml | 41 +++++-- 11 files changed, 319 insertions(+), 13 deletions(-) create mode 100644 services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/BunyanLevelJsonProvider.java create mode 100644 services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/GceMetadataLogLevelChecker.java create mode 100644 services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/GcpLabelsJsonProvider.java create mode 100644 services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/MdcLoggingFilter.java create mode 100644 services/git-bridge/src/main/resources/logback-gke.xml diff --git a/services/git-bridge/pom.xml b/services/git-bridge/pom.xml index bd0cefec09..b93529bc8f 100644 --- a/services/git-bridge/pom.xml +++ b/services/git-bridge/pom.xml @@ -27,6 +27,7 @@ 1.23.0 3.20.0 1.5.24 + 8.0 5.15.0 5.20.0 2.41.7 @@ -200,6 +201,12 @@ logback-classic ${logback.classic.version} + + + net.logstash.logback + logstash-logback-encoder + ${logstash.logback.encoder.version} + org.mock-server diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/Main.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/Main.java index 5e365b893b..437f052978 100644 --- a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/Main.java +++ b/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(); diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/BunyanLevelJsonProvider.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/BunyanLevelJsonProvider.java new file mode 100644 index 0000000000..f00de0c268 --- /dev/null +++ b/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 { + + @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; + } +} diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/GceMetadataLogLevelChecker.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/GceMetadataLogLevelChecker.java new file mode 100644 index 0000000000..5294829503 --- /dev/null +++ b/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 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()); + } +} diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/GcpLabelsJsonProvider.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/GcpLabelsJsonProvider.java new file mode 100644 index 0000000000..e41c8fbb8e --- /dev/null +++ b/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 { + + @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(); + } +} diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/GitBridgeServer.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/GitBridgeServer.java index 53c6c62345..15cc3b7e7e 100644 --- a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/GitBridgeServer.java +++ b/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()); diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/MdcLoggingFilter.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/MdcLoggingFilter.java new file mode 100644 index 0000000000..e53db7a51f --- /dev/null +++ b/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() {} +} diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/Oauth2Filter.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/Oauth2Filter.java index c884813e75..f47325284a 100644 --- a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/server/Oauth2Filter.java +++ b/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); } /* diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/util/Util.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/util/Util.java index 57eeb11899..b09af4dbed 100644 --- a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/util/Util.java +++ b/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"); diff --git a/services/git-bridge/src/main/resources/logback-gke.xml b/services/git-bridge/src/main/resources/logback-gke.xml new file mode 100644 index 0000000000..f78457ea53 --- /dev/null +++ b/services/git-bridge/src/main/resources/logback-gke.xml @@ -0,0 +1,60 @@ + + + + + + + System.out + + yyyy-MM-dd'T'HH:mm:ss.SSSXXX + + time + [ignore] + message + logger + thread + [ignore] + [ignore] + stack_trace + + + {"severity":"%replace(%replace(%level){'WARN','WARNING'}){'TRACE','DEBUG'}"} + + + + + + + + System.err + + WARN + + + yyyy-MM-dd'T'HH:mm:ss.SSSXXX + + time + [ignore] + message + logger + thread + [ignore] + [ignore] + stack_trace + + + {"severity":"%replace(%replace(%level){'WARN','WARNING'}){'TRACE','DEBUG'}"} + + + + + + + + + + + + + + \ No newline at end of file diff --git a/services/git-bridge/src/main/resources/logback.xml b/services/git-bridge/src/main/resources/logback.xml index 343ae578a7..cbb32f7c65 100644 --- a/services/git-bridge/src/main/resources/logback.xml +++ b/services/git-bridge/src/main/resources/logback.xml @@ -5,11 +5,22 @@ System.out - - ${LOG_LEVEL} - - - %d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread] %logger{0}: %msg%n + + yyyy-MM-dd'T'HH:mm:ss.SSSXXX + + time + [ignore] + msg + [ignore] + [ignore] + [ignore] + [ignore] + stack_trace + + + {"v":0,"name":"git-bridge","hostname":"${HOSTNAME:-unknown}","pid":${PID:-0}} + + @@ -19,8 +30,22 @@ WARN - - %d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread] %logger{0}: %msg%n + + yyyy-MM-dd'T'HH:mm:ss.SSSXXX + + time + [ignore] + msg + [ignore] + [ignore] + [ignore] + [ignore] + stack_trace + + + {"v":0,"name":"git-bridge","hostname":"${HOSTNAME:-unknown}","pid":${PID:-0}} + + @@ -32,4 +57,4 @@ - + \ No newline at end of file