From a3f510d0db340e81f11975b10dad36551c06e243 Mon Sep 17 00:00:00 2001 From: Lai Jiang Date: Tue, 4 Mar 2025 15:18:15 -0500 Subject: [PATCH] Log session cookies in metadata (#2703) There are two session cookies, JSESSIONID, which is set by Jetty, and GCLB, which is set by the Gateway. In one session, every request other than the first one (the ) should have the same GCLB value, and every request after a successful should have the same JSESSIONID. With these two metadata, we should be able to trace all requests that *should* belong to the same session and debug issues with session mismatch (if any). --- .../registry/module/RegistryServlet.java | 17 ++++++++++ .../registry/util/GcpJsonFormatter.java | 27 ++++++++++++++++ .../registry/util/GcpJsonFormatterTest.java | 32 ++++++++++++++----- 3 files changed, 68 insertions(+), 8 deletions(-) diff --git a/core/src/main/java/google/registry/module/RegistryServlet.java b/core/src/main/java/google/registry/module/RegistryServlet.java index 9ffe1c3fb..8a9e45803 100644 --- a/core/src/main/java/google/registry/module/RegistryServlet.java +++ b/core/src/main/java/google/registry/module/RegistryServlet.java @@ -16,10 +16,14 @@ package google.registry.module; import static google.registry.util.GcpJsonFormatter.setCurrentRequest; import static google.registry.util.GcpJsonFormatter.setCurrentTraceId; +import static google.registry.util.GcpJsonFormatter.setLabel; import static google.registry.util.GcpJsonFormatter.unsetCurrentRequest; +import static google.registry.util.GcpJsonFormatter.unsetLabels; import static google.registry.util.RandomStringGenerator.insecureRandomStringGenerator; import static google.registry.util.StringGenerator.Alphabets.HEX_DIGITS_ONLY; +import com.google.common.base.Splitter; +import com.google.common.collect.ImmutableSet; import com.google.monitoring.metrics.MetricReporter; import dagger.Lazy; import google.registry.request.RequestHandler; @@ -30,6 +34,7 @@ import jakarta.servlet.http.HttpServletRequest; import jakarta.servlet.http.HttpServletResponse; import java.io.IOException; import java.util.Arrays; +import java.util.Optional; import java.util.logging.ConsoleHandler; import java.util.logging.Handler; import java.util.logging.Level; @@ -48,6 +53,9 @@ public class RegistryServlet extends ServletBase { private static final RequestHandler requestHandler = component.requestHandler(); private static final Lazy metricReporter = component.metricReporter(); + // The names of the session cookies to log. + private static final ImmutableSet COOKIES_TO_LOG = ImmutableSet.of("JSESSIONID", "GCLB"); + private final String projectId; static { @@ -74,11 +82,20 @@ public class RegistryServlet extends ServletBase { String userAgent = String.valueOf(req.getHeader("User-Agent")); String protocol = req.getProtocol(); setCurrentRequest(requestMethod, requestUrl, userAgent, protocol); + Optional maybeCookie = Optional.ofNullable(req.getHeader("Cookie")); + if (maybeCookie.isPresent() && !maybeCookie.get().isEmpty()) { + // GCLB sets the value with a leading and trailing double quote. + String cookie = maybeCookie.get().replace("\"", ""); + Splitter.on(';').trimResults().withKeyValueSeparator('=').split(cookie).entrySet().stream() + .filter(e -> COOKIES_TO_LOG.contains(e.getKey())) + .forEach(e -> setLabel(e.getKey(), e.getValue())); + } try { super.service(req, rsp); } finally { setCurrentTraceId(null); unsetCurrentRequest(); + unsetLabels(); } } diff --git a/util/src/main/java/google/registry/util/GcpJsonFormatter.java b/util/src/main/java/google/registry/util/GcpJsonFormatter.java index 8c6a80b64..c305dcfe2 100644 --- a/util/src/main/java/google/registry/util/GcpJsonFormatter.java +++ b/util/src/main/java/google/registry/util/GcpJsonFormatter.java @@ -20,6 +20,7 @@ import com.google.common.flogger.backend.system.SimpleLogRecord; import com.google.gson.Gson; import java.io.PrintWriter; import java.io.StringWriter; +import java.util.HashMap; import java.util.LinkedHashMap; import java.util.Map; import java.util.Optional; @@ -58,6 +59,13 @@ public class GcpJsonFormatter extends Formatter { /** JSON field that stores the parameters of the current request, if any. */ private static final String HTTP_REQUEST = "httRequest"; + /** + * JSON field that stores the arbitrary labels. + * + *

In practice, we store session cookies so we can identify requests from the same session. + */ + private static final String LABELS = "logging.googleapis.com/labels"; + /** JSON field that contains the content, this will show up as the main entry in a log. */ private static final String MESSAGE = "message"; @@ -83,6 +91,9 @@ public class GcpJsonFormatter extends Formatter { private static final ThreadLocal request = new ThreadLocal<>(); + private static final ThreadLocal> labels = + ThreadLocal.withInitial(HashMap::new); + /** * Set the Trace ID associated with any logging done by the current thread. * @@ -107,6 +118,19 @@ public class GcpJsonFormatter extends Formatter { request.set(new HttpRequest(requestMethod, requestUrl, userAgent, protocol)); } + /** + * Set an arbitrary key-value pair as a label for the current request. + * + *

Existing labels will be overwritten. + */ + public static void setLabel(String key, String value) { + labels.get().put(key, value); + } + + public static void unsetLabels() { + labels.get().clear(); + } + public static void unsetCurrentRequest() { request.remove(); } @@ -180,6 +204,9 @@ public class GcpJsonFormatter extends Formatter { if (request.get() != null) { json.put(HTTP_REQUEST, request.get()); } + if (!labels.get().isEmpty()) { + json.put(LABELS, labels.get()); + } // This trailing newline is required for the proxy because otherwise multiple logs might be // sent to Stackdriver together (due to the async nature of the proxy), and not parsed // correctly. diff --git a/util/src/test/java/google/registry/util/GcpJsonFormatterTest.java b/util/src/test/java/google/registry/util/GcpJsonFormatterTest.java index acf3c1bc8..5c8ad890d 100644 --- a/util/src/test/java/google/registry/util/GcpJsonFormatterTest.java +++ b/util/src/test/java/google/registry/util/GcpJsonFormatterTest.java @@ -72,6 +72,7 @@ class GcpJsonFormatterTest { jdkLogger.removeHandler(handler); GcpJsonFormatter.setCurrentTraceId(null); GcpJsonFormatter.unsetCurrentRequest(); + GcpJsonFormatter.unsetLabels(); } @Test @@ -79,7 +80,7 @@ class GcpJsonFormatterTest { logger.atInfo().log("Something I have to say"); handler.close(); String output = ostream.toString(StandardCharsets.US_ASCII); - assertThat(output).isEqualTo(makeJson("INFO", 79, "testSuccess", "Something I have to say")); + assertThat(output).isEqualTo(makeJson("INFO", 80, "testSuccess", "Something I have to say")); } @Test @@ -88,7 +89,7 @@ class GcpJsonFormatterTest { logger.atInfo().log("Something I have to say"); handler.close(); String output = ostream.toString(StandardCharsets.US_ASCII); - String expected = makeJson("INFO", 88, "testSuccess_traceId", "Something I have to say"); + String expected = makeJson("INFO", 89, "testSuccess_traceId", "Something I have to say"); // Remove the last two characters (}, \n) from the template and add the trace ID. expected = expected.substring(0, expected.length() - 2) @@ -103,7 +104,7 @@ class GcpJsonFormatterTest { handler.close(); String output = ostream.toString(StandardCharsets.US_ASCII); String expected = - makeJson("INFO", 102, "testSuccess_currentRequest", "Something I have to say"); + makeJson("INFO", 103, "testSuccess_currentRequest", "Something I have to say"); // Remove the last two characters (}, \n) from the template and add the request. expected = expected.substring(0, expected.length() - 2) @@ -112,13 +113,28 @@ class GcpJsonFormatterTest { assertThat(output).isEqualTo(expected); } + @Test + void testSuccess_labels() { + GcpJsonFormatter.setLabel("label1", "value1"); + GcpJsonFormatter.setLabel("label2", "value2"); + logger.atInfo().log("Something I have to say"); + handler.close(); + String output = ostream.toString(StandardCharsets.US_ASCII); + String expected = makeJson("INFO", 120, "testSuccess_labels", "Something I have to say"); + // Remove the last two characters (}, \n) from the template and add the labels. + expected = + expected.substring(0, expected.length() - 2) + + ",\"logging.googleapis.com/labels\":{\"label1\":\"value1\",\"label2\":\"value2\"}}\n"; + assertThat(output).isEqualTo(expected); + } + @Test void testSuccess_logLevel() { logger.atSevere().log("Something went terribly wrong"); handler.close(); String output = ostream.toString(StandardCharsets.US_ASCII); assertThat(output) - .isEqualTo(makeJson("ERROR", 117, "testSuccess_logLevel", "Something went terribly wrong")); + .isEqualTo(makeJson("ERROR", 133, "testSuccess_logLevel", "Something went terribly wrong")); } @Test @@ -127,7 +143,7 @@ class GcpJsonFormatterTest { handler.close(); String output = ostream.toString(StandardCharsets.US_ASCII); String prefix = - makeJson("ERROR", 126, "testSuccess_withCause", "Something went terribly wrong"); + makeJson("ERROR", 142, "testSuccess_withCause", "Something went terribly wrong"); // Remove the last two characters (}, \n) from the template as the actual output contains // the full stack trace. prefix = prefix.substring(0, prefix.length() - 2); @@ -141,7 +157,7 @@ class GcpJsonFormatterTest { handler.close(); String output = ostream.toString(StandardCharsets.US_ASCII); String prefix = - makeJson("ERROR", 140, "testSuccess_withStackTrace", "Something is worth checking"); + makeJson("ERROR", 156, "testSuccess_withStackTrace", "Something is worth checking"); // Remove the last three characters (}, \n) from the template as the actual output contains // the full stack trace. prefix = prefix.substring(0, prefix.length() - 2); @@ -167,7 +183,7 @@ class GcpJsonFormatterTest { TimeLimiter.create().callWithTimeout(this::logSomething, 1, TimeUnit.SECONDS); handler.close(); String output = ostream.toString(StandardCharsets.US_ASCII); - assertThat(output).isEqualTo(makeJson("INFO", 188, "logSomething", "Something I have to say")); + assertThat(output).isEqualTo(makeJson("INFO", 204, "logSomething", "Something I have to say")); } @Test @@ -176,7 +192,7 @@ class GcpJsonFormatterTest { TimeLimiter.create().callWithTimeout(this::logSomething, 1, TimeUnit.SECONDS); handler.close(); String output = ostream.toString(StandardCharsets.US_ASCII); - String expected = makeJson("INFO", 188, "logSomething", "Something I have to say"); + String expected = makeJson("INFO", 204, "logSomething", "Something I have to say"); // Remove the last two characters (}, \n) from the template and add the trace ID. expected = expected.substring(0, expected.length() - 2)