mirror of
https://github.com/google/nomulus
synced 2026-01-07 14:05:44 +00:00
Record http request parameters in log metadata (#2642)
This allows us to search for logs for a given path using a filter like this: jsonPayload.httpRequest.requestUrl="/_dr/blah" TESTED=tested on crash
This commit is contained in:
@@ -14,7 +14,9 @@
|
|||||||
|
|
||||||
package google.registry.module;
|
package google.registry.module;
|
||||||
|
|
||||||
|
import static google.registry.util.GcpJsonFormatter.setCurrentRequest;
|
||||||
import static google.registry.util.GcpJsonFormatter.setCurrentTraceId;
|
import static google.registry.util.GcpJsonFormatter.setCurrentTraceId;
|
||||||
|
import static google.registry.util.GcpJsonFormatter.unsetCurrentRequest;
|
||||||
import static google.registry.util.RandomStringGenerator.insecureRandomStringGenerator;
|
import static google.registry.util.RandomStringGenerator.insecureRandomStringGenerator;
|
||||||
import static google.registry.util.StringGenerator.Alphabets.HEX_DIGITS_ONLY;
|
import static google.registry.util.StringGenerator.Alphabets.HEX_DIGITS_ONLY;
|
||||||
|
|
||||||
@@ -67,10 +69,16 @@ public class RegistryServlet extends ServletBase {
|
|||||||
@Override
|
@Override
|
||||||
public void service(HttpServletRequest req, HttpServletResponse rsp) throws IOException {
|
public void service(HttpServletRequest req, HttpServletResponse rsp) throws IOException {
|
||||||
setCurrentTraceId(traceId());
|
setCurrentTraceId(traceId());
|
||||||
|
String requestMethod = req.getMethod();
|
||||||
|
String requestUrl = req.getRequestURI();
|
||||||
|
String userAgent = String.valueOf(req.getHeader("User-Agent"));
|
||||||
|
String protocol = req.getProtocol();
|
||||||
|
setCurrentRequest(requestMethod, requestUrl, userAgent, protocol);
|
||||||
try {
|
try {
|
||||||
super.service(req, rsp);
|
super.service(req, rsp);
|
||||||
} finally {
|
} finally {
|
||||||
setCurrentTraceId(null);
|
setCurrentTraceId(null);
|
||||||
|
unsetCurrentRequest();
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -43,7 +43,8 @@ import org.postgresql.util.PSQLException;
|
|||||||
final class RegistryCli implements CommandRunner {
|
final class RegistryCli implements CommandRunner {
|
||||||
|
|
||||||
private static final ImmutableSet<RegistryToolEnvironment> DEFAULT_GKE_ENVIRONMENTS =
|
private static final ImmutableSet<RegistryToolEnvironment> DEFAULT_GKE_ENVIRONMENTS =
|
||||||
ImmutableSet.of(RegistryToolEnvironment.ALPHA, RegistryToolEnvironment.QA);
|
ImmutableSet.of(
|
||||||
|
RegistryToolEnvironment.ALPHA, RegistryToolEnvironment.CRASH, RegistryToolEnvironment.QA);
|
||||||
|
|
||||||
// The environment parameter is parsed twice: once here, and once with {@link
|
// The environment parameter is parsed twice: once here, and once with {@link
|
||||||
// RegistryToolEnvironment#parseFromArgs} in the {@link RegistryTool#main} function.
|
// RegistryToolEnvironment#parseFromArgs} in the {@link RegistryTool#main} function.
|
||||||
|
|||||||
@@ -26,6 +26,7 @@ import java.util.Optional;
|
|||||||
import java.util.logging.Formatter;
|
import java.util.logging.Formatter;
|
||||||
import java.util.logging.Level;
|
import java.util.logging.Level;
|
||||||
import java.util.logging.LogRecord;
|
import java.util.logging.LogRecord;
|
||||||
|
import javax.annotation.Nullable;
|
||||||
|
|
||||||
/**
|
/**
|
||||||
* JUL formatter that formats log messages in a single-line JSON that Stackdriver logging can parse.
|
* JUL formatter that formats log messages in a single-line JSON that Stackdriver logging can parse.
|
||||||
@@ -54,6 +55,9 @@ public class GcpJsonFormatter extends Formatter {
|
|||||||
/** JSON field that stores the trace associated with the log entry, if any. */
|
/** JSON field that stores the trace associated with the log entry, if any. */
|
||||||
private static final String TRACE = "logging.googleapis.com/trace";
|
private static final String TRACE = "logging.googleapis.com/trace";
|
||||||
|
|
||||||
|
/** JSON field that stores the parameters of the current request, if any. */
|
||||||
|
private static final String HTTP_REQUEST = "httRequest";
|
||||||
|
|
||||||
/** JSON field that contains the content, this will show up as the main entry in a log. */
|
/** JSON field that contains the content, this will show up as the main entry in a log. */
|
||||||
private static final String MESSAGE = "message";
|
private static final String MESSAGE = "message";
|
||||||
|
|
||||||
@@ -77,12 +81,14 @@ public class GcpJsonFormatter extends Formatter {
|
|||||||
|
|
||||||
private static final ThreadLocal<String> traceId = new ThreadLocal<>();
|
private static final ThreadLocal<String> traceId = new ThreadLocal<>();
|
||||||
|
|
||||||
|
private static final ThreadLocal<HttpRequest> request = new ThreadLocal<>();
|
||||||
|
|
||||||
/**
|
/**
|
||||||
* Set the Trace ID associated with any logging done by the current thread.
|
* Set the Trace ID associated with any logging done by the current thread.
|
||||||
*
|
*
|
||||||
* @param id The traceID, in the form projects/[PROJECT_ID]/traces/[TRACE_ID]
|
* @param id The traceID, in the form projects/[PROJECT_ID]/traces/[TRACE_ID]
|
||||||
*/
|
*/
|
||||||
public static void setCurrentTraceId(String id) {
|
public static void setCurrentTraceId(@Nullable String id) {
|
||||||
if (id == null) {
|
if (id == null) {
|
||||||
traceId.remove();
|
traceId.remove();
|
||||||
} else {
|
} else {
|
||||||
@@ -90,6 +96,21 @@ public class GcpJsonFormatter extends Formatter {
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
/**
|
||||||
|
* Record the parameters of the current request.
|
||||||
|
*
|
||||||
|
* @see <a
|
||||||
|
* href="https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#httprequest">HttpRequest</a>
|
||||||
|
*/
|
||||||
|
public static void setCurrentRequest(
|
||||||
|
String requestMethod, String requestUrl, String userAgent, String protocol) {
|
||||||
|
request.set(new HttpRequest(requestMethod, requestUrl, userAgent, protocol));
|
||||||
|
}
|
||||||
|
|
||||||
|
public static void unsetCurrentRequest() {
|
||||||
|
request.remove();
|
||||||
|
}
|
||||||
|
|
||||||
/**
|
/**
|
||||||
* Get the Trace ID associated with any logging done by the current thread.
|
* Get the Trace ID associated with any logging done by the current thread.
|
||||||
*
|
*
|
||||||
@@ -156,6 +177,9 @@ public class GcpJsonFormatter extends Formatter {
|
|||||||
if (traceId.get() != null) {
|
if (traceId.get() != null) {
|
||||||
json.put(TRACE, traceId.get());
|
json.put(TRACE, traceId.get());
|
||||||
}
|
}
|
||||||
|
if (request.get() != null) {
|
||||||
|
json.put(HTTP_REQUEST, request.get());
|
||||||
|
}
|
||||||
// This trailing newline is required for the proxy because otherwise multiple logs might be
|
// 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
|
// sent to Stackdriver together (due to the async nature of the proxy), and not parsed
|
||||||
// correctly.
|
// correctly.
|
||||||
@@ -181,4 +205,7 @@ public class GcpJsonFormatter extends Formatter {
|
|||||||
default -> "DEFAULT";
|
default -> "DEFAULT";
|
||||||
};
|
};
|
||||||
}
|
}
|
||||||
|
|
||||||
|
private record HttpRequest(
|
||||||
|
String requestMethod, String requestUrl, String userAgent, String protocol) {}
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -71,6 +71,7 @@ class GcpJsonFormatterTest {
|
|||||||
void afterEach() {
|
void afterEach() {
|
||||||
jdkLogger.removeHandler(handler);
|
jdkLogger.removeHandler(handler);
|
||||||
GcpJsonFormatter.setCurrentTraceId(null);
|
GcpJsonFormatter.setCurrentTraceId(null);
|
||||||
|
GcpJsonFormatter.unsetCurrentRequest();
|
||||||
}
|
}
|
||||||
|
|
||||||
@Test
|
@Test
|
||||||
@@ -78,7 +79,7 @@ class GcpJsonFormatterTest {
|
|||||||
logger.atInfo().log("Something I have to say");
|
logger.atInfo().log("Something I have to say");
|
||||||
handler.close();
|
handler.close();
|
||||||
String output = ostream.toString(StandardCharsets.US_ASCII);
|
String output = ostream.toString(StandardCharsets.US_ASCII);
|
||||||
assertThat(output).isEqualTo(makeJson("INFO", 78, "testSuccess", "Something I have to say"));
|
assertThat(output).isEqualTo(makeJson("INFO", 79, "testSuccess", "Something I have to say"));
|
||||||
}
|
}
|
||||||
|
|
||||||
@Test
|
@Test
|
||||||
@@ -87,7 +88,7 @@ class GcpJsonFormatterTest {
|
|||||||
logger.atInfo().log("Something I have to say");
|
logger.atInfo().log("Something I have to say");
|
||||||
handler.close();
|
handler.close();
|
||||||
String output = ostream.toString(StandardCharsets.US_ASCII);
|
String output = ostream.toString(StandardCharsets.US_ASCII);
|
||||||
String expected = makeJson("INFO", 87, "testSuccess_traceId", "Something I have to say");
|
String expected = makeJson("INFO", 88, "testSuccess_traceId", "Something I have to say");
|
||||||
// Remove the last two characters (}, \n) from the template and add the trace ID.
|
// Remove the last two characters (}, \n) from the template and add the trace ID.
|
||||||
expected =
|
expected =
|
||||||
expected.substring(0, expected.length() - 2)
|
expected.substring(0, expected.length() - 2)
|
||||||
@@ -95,13 +96,29 @@ class GcpJsonFormatterTest {
|
|||||||
assertThat(output).isEqualTo(expected);
|
assertThat(output).isEqualTo(expected);
|
||||||
}
|
}
|
||||||
|
|
||||||
|
@Test
|
||||||
|
void testSuccess_currentRequest() {
|
||||||
|
GcpJsonFormatter.setCurrentRequest("GET", "/path", "My-Agent", "HTTP/1.1");
|
||||||
|
logger.atInfo().log("Something I have to say");
|
||||||
|
handler.close();
|
||||||
|
String output = ostream.toString(StandardCharsets.US_ASCII);
|
||||||
|
String expected =
|
||||||
|
makeJson("INFO", 102, "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)
|
||||||
|
+ ",\"httRequest\":{\"requestMethod\":\"GET\",\"requestUrl\":\"/path\""
|
||||||
|
+ ",\"userAgent\":\"My-Agent\",\"protocol\":\"HTTP/1.1\"}}\n";
|
||||||
|
assertThat(output).isEqualTo(expected);
|
||||||
|
}
|
||||||
|
|
||||||
@Test
|
@Test
|
||||||
void testSuccess_logLevel() {
|
void testSuccess_logLevel() {
|
||||||
logger.atSevere().log("Something went terribly wrong");
|
logger.atSevere().log("Something went terribly wrong");
|
||||||
handler.close();
|
handler.close();
|
||||||
String output = ostream.toString(StandardCharsets.US_ASCII);
|
String output = ostream.toString(StandardCharsets.US_ASCII);
|
||||||
assertThat(output)
|
assertThat(output)
|
||||||
.isEqualTo(makeJson("ERROR", 100, "testSuccess_logLevel", "Something went terribly wrong"));
|
.isEqualTo(makeJson("ERROR", 117, "testSuccess_logLevel", "Something went terribly wrong"));
|
||||||
}
|
}
|
||||||
|
|
||||||
@Test
|
@Test
|
||||||
@@ -110,7 +127,7 @@ class GcpJsonFormatterTest {
|
|||||||
handler.close();
|
handler.close();
|
||||||
String output = ostream.toString(StandardCharsets.US_ASCII);
|
String output = ostream.toString(StandardCharsets.US_ASCII);
|
||||||
String prefix =
|
String prefix =
|
||||||
makeJson("ERROR", 109, "testSuccess_withCause", "Something went terribly wrong");
|
makeJson("ERROR", 126, "testSuccess_withCause", "Something went terribly wrong");
|
||||||
// Remove the last two characters (}, \n) from the template as the actual output contains
|
// Remove the last two characters (}, \n) from the template as the actual output contains
|
||||||
// the full stack trace.
|
// the full stack trace.
|
||||||
prefix = prefix.substring(0, prefix.length() - 2);
|
prefix = prefix.substring(0, prefix.length() - 2);
|
||||||
@@ -124,7 +141,7 @@ class GcpJsonFormatterTest {
|
|||||||
handler.close();
|
handler.close();
|
||||||
String output = ostream.toString(StandardCharsets.US_ASCII);
|
String output = ostream.toString(StandardCharsets.US_ASCII);
|
||||||
String prefix =
|
String prefix =
|
||||||
makeJson("ERROR", 123, "testSuccess_withStackTrace", "Something is worth checking");
|
makeJson("ERROR", 140, "testSuccess_withStackTrace", "Something is worth checking");
|
||||||
// Remove the last three characters (}, \n) from the template as the actual output contains
|
// Remove the last three characters (}, \n) from the template as the actual output contains
|
||||||
// the full stack trace.
|
// the full stack trace.
|
||||||
prefix = prefix.substring(0, prefix.length() - 2);
|
prefix = prefix.substring(0, prefix.length() - 2);
|
||||||
@@ -150,7 +167,7 @@ class GcpJsonFormatterTest {
|
|||||||
TimeLimiter.create().callWithTimeout(this::logSomething, 1, TimeUnit.SECONDS);
|
TimeLimiter.create().callWithTimeout(this::logSomething, 1, TimeUnit.SECONDS);
|
||||||
handler.close();
|
handler.close();
|
||||||
String output = ostream.toString(StandardCharsets.US_ASCII);
|
String output = ostream.toString(StandardCharsets.US_ASCII);
|
||||||
assertThat(output).isEqualTo(makeJson("INFO", 171, "logSomething", "Something I have to say"));
|
assertThat(output).isEqualTo(makeJson("INFO", 188, "logSomething", "Something I have to say"));
|
||||||
}
|
}
|
||||||
|
|
||||||
@Test
|
@Test
|
||||||
@@ -159,7 +176,7 @@ class GcpJsonFormatterTest {
|
|||||||
TimeLimiter.create().callWithTimeout(this::logSomething, 1, TimeUnit.SECONDS);
|
TimeLimiter.create().callWithTimeout(this::logSomething, 1, TimeUnit.SECONDS);
|
||||||
handler.close();
|
handler.close();
|
||||||
String output = ostream.toString(StandardCharsets.US_ASCII);
|
String output = ostream.toString(StandardCharsets.US_ASCII);
|
||||||
String expected = makeJson("INFO", 171, "logSomething", "Something I have to say");
|
String expected = makeJson("INFO", 188, "logSomething", "Something I have to say");
|
||||||
// Remove the last two characters (}, \n) from the template and add the trace ID.
|
// Remove the last two characters (}, \n) from the template and add the trace ID.
|
||||||
expected =
|
expected =
|
||||||
expected.substring(0, expected.length() - 2)
|
expected.substring(0, expected.length() - 2)
|
||||||
|
|||||||
Reference in New Issue
Block a user