mirrors/nomulus
1
0
Fork 0
mirror of https://github.com/google/nomulus synced 2025-12-23 06:15:42 +00:00
Code Issues Releases Wiki Activity

Log session cookies in metadata (#2703)

Browse Source 
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 <hello>)
should have the same GCLB value, and every request after a successful
<login> 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).
This commit is contained in:
Lai Jiang
2025-03-04 15:18:15 -05:00
committed by GitHub
parent fa54c26ee2
commit a3f510d0db
3 changed files with 68 additions and 8 deletions
Download Patch File Download Diff File Expand all files Collapse all files

17
core/src/main/java/google/registry/module/RegistryServlet.java
View File

@@ -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<RequestComponent> requestHandler = component.requestHandler();
private static final Lazy<MetricReporter> metricReporter = component.metricReporter();
// The names of the session cookies to log.
private static final ImmutableSet<String> 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<String> 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();
}
}

27
util/src/main/java/google/registry/util/GcpJsonFormatter.java
View File

@@ -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.
*
* <p>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<HttpRequest> request = new ThreadLocal<>();
private static final ThreadLocal<Map<String, String>> 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.
*
* <p>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.

32
util/src/test/java/google/registry/util/GcpJsonFormatterTest.java
View File

@@ -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)