feat: Adds logging for every request to ksqlDB #6615

AlanConfluent · 2020-11-14T01:33:23Z

Description

Adds logging to every request that comes in with standard fields so it's easier to monitor incoming traffic.

Testing done

Ran unit tests and manually tested.

Reviewer checklist

Ensure docs are updated if necessary. (eg. if a user visible feature is being added or changed).
Ensure relevant issues are linked (description should include text like "Fixes #")

purplefox · 2020-11-14T10:49:50Z

Hi Alan, vertx-web does have the concept of a "filter" - that's basically what a handler is. Handlers can do stuff to a request, and decided whether or not to forward to the next handler. They can also do stuff when the request is complete - by setting end handlers on the routing context, (i.e. ctx.addEndHandler(), ctx.addBodyEndHandler(), ctx.addHeadersEndHandler()).

So you can end up with something like this:


public class MyLoggingFilter implements Handler<RoutingContext> {

    public void handle(RoutingContext context) {

        log.info("Logging request " + context.request());

        context.addEndHandler(ar -> {
            if (ar.succeeded()) {
                log.info("request completed");
            } else {
                log.error("request failed", ar.cause());
            }
        });
    }
}

And then you just add your "filter" at the beginning of your handler chain

AlanConfluent · 2020-11-16T19:11:33Z

Hi @purplefox . Thanks for the feedback. I was going to reach out to you, but glad you found me first.

I hadn't noticed the addEndHandler API and had thought you had to insert a handler at the end of the chain to achieve similar effects. Unfortunately web searching didn't turn up this obvious answer. I made the change you suggested.

vcrfxia

Thanks @AlanConfluent -- bunch of comments inline but LGTM overall!

vcrfxia · 2020-11-16T23:56:18Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/api/server/LoggingHandler.java

+          try {
+            return Integer.parseInt(responseCode);
+          } catch (NumberFormatException e) {
+            throw new IllegalStateException("Configured bad response code " + responseCode);


Can we add a validator on the config to ensure that the config parses properly? Then we can throw a ConfigException rather than IllegalStateException.

Done. Added validator. It's somewhat irritating that you can't actually do the parsing as well as part of the validation stage because I effectively have to parse again.

vcrfxia · 2020-11-16T23:56:23Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/api/server/LoggingHandler.java

+
+  @Override
+  public void handle(final RoutingContext routingContext) {
+    // If we wanted to log at the beginning of a request, it would go here.


I don't think this comment adds anything -- I was also confused the first time I read it since I thought it was describing the line below.

Makes sense. Removed.

vcrfxia · 2020-11-16T23:56:24Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/api/server/LoggingHandler.java

+      if (routingContext.response().getStatusCode() > 300) {
+        errorMessage = routingContext.response().getStatusMessage();
+        if (Strings.isNullOrEmpty(errorMessage)) {
+          errorMessage = routingContext.getBodyAsString();


What's the purpose of this? Why would we have a situation where an erroneous response code was returned with no message, and why would we want to log the body in this case?

I was looking through the code and though it was possible to not set the status message. Either way, in conforming to the Apache log format, I'm just going to remove this.

vcrfxia · 2020-11-16T23:56:26Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/api/server/LoggingHandler.java

+          "Request complete - %s %s status: %d, user agent: %s, request body: %d bytes,"
+              + " error response: %s",
+          routingContext.request().remoteAddress().host(),
+          routingContext.request().uri(),


Let's also add the HTTP method. (We used to have Jetty HTTP request logging. This is the information we had at the time: https://www.eclipse.org/jetty/documentation/current/configuring-jetty-request-logs.html#constructing-request-log-entry)

Done. I kept a mostly apache like log message with the addition of request body bytes.

vcrfxia · 2020-11-16T23:56:30Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/api/server/LoggingHandler.java

+          routingContext.request().uri(),
+          routingContext.response().getStatusCode(),
+          routingContext.request().getHeader(HTTP_HEADER_USER_AGENT),
+          routingContext.request().bytesRead(),


Is this just the size of the request body, or does it include the size of the headers as well? It'd be nice to have both. At minimum we should understand which this is.

It's just the body. There's no API I've seen for the header size, though we do have access to the headers. I was going to try to estimate the size, by looking at java objects, since from all of my research they're always ASCII, but this seems a bit hacky. I can try that out if we really want that.

vcrfxia · 2020-11-16T23:57:04Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/rest/server/KsqlRestConfig.java

@@ -319,6 +319,11 @@
      "The key store certificate alias to be used for internal client requests. If not set, "
          + "the system will fall back on the Vert.x default choice";

+  public static final String KSQL_LOGGING_SKIP_RESPONSE_CODES_CONFIG =


Add docs for this new config?

vcrfxia · 2020-11-16T23:57:26Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/rest/server/KsqlRestConfig.java

+  public static final String KSQL_LOGGING_SKIP_RESPONSE_CODES_CONFIG =
+      KSQL_CONFIG_PREFIX + "logging.skip.response.codes";
+  private static final String KSQL_LOGGING_SKIP_RESPONSE_CODES_DOC =
+      "A list of response codes to skip logging";


nit:

Suggested change

"A list of response codes to skip logging";

"A list of HTTP response codes to skip during server request logging";

ksqldb-rest-app/src/test/java/io/confluent/ksql/api/server/LoggingHandlerTest.java

AlanConfluent

There was worry that pull queries could introduce too much logging if done at high qps, so I introduced a rate limiter to the logger.

AlanConfluent · 2020-11-17T22:09:10Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/api/server/LoggingHandler.java

+          try {
+            return Integer.parseInt(responseCode);
+          } catch (NumberFormatException e) {
+            throw new IllegalStateException("Configured bad response code " + responseCode);


Done. Added validator. It's somewhat irritating that you can't actually do the parsing as well as part of the validation stage because I effectively have to parse again.

AlanConfluent · 2020-11-17T22:09:25Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/api/server/LoggingHandler.java

+
+  @Override
+  public void handle(final RoutingContext routingContext) {
+    // If we wanted to log at the beginning of a request, it would go here.


Makes sense. Removed.

AlanConfluent · 2020-11-17T22:10:52Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/api/server/LoggingHandler.java

+      if (routingContext.response().getStatusCode() > 300) {
+        errorMessage = routingContext.response().getStatusMessage();
+        if (Strings.isNullOrEmpty(errorMessage)) {
+          errorMessage = routingContext.getBodyAsString();


I was looking through the code and though it was possible to not set the status message. Either way, in conforming to the Apache log format, I'm just going to remove this.

AlanConfluent · 2020-11-19T23:22:53Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/api/server/LoggingHandler.java

+          "Request complete - %s %s status: %d, user agent: %s, request body: %d bytes,"
+              + " error response: %s",
+          routingContext.request().remoteAddress().host(),
+          routingContext.request().uri(),


Done. I kept a mostly apache like log message with the addition of request body bytes.

AlanConfluent · 2020-11-19T23:28:37Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/api/server/LoggingHandler.java

+          routingContext.request().uri(),
+          routingContext.response().getStatusCode(),
+          routingContext.request().getHeader(HTTP_HEADER_USER_AGENT),
+          routingContext.request().bytesRead(),


It's just the body. There's no API I've seen for the header size, though we do have access to the headers. I was going to try to estimate the size, by looking at java objects, since from all of my research they're always ASCII, but this seems a bit hacky. I can try that out if we really want that.

AlanConfluent · 2020-11-19T23:30:12Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/rest/server/KsqlRestConfig.java

+  public static final String KSQL_LOGGING_SKIP_RESPONSE_CODES_CONFIG =
+      KSQL_CONFIG_PREFIX + "logging.skip.response.codes";
+  private static final String KSQL_LOGGING_SKIP_RESPONSE_CODES_DOC =
+      "A list of response codes to skip logging";


AlanConfluent · 2020-11-20T23:12:14Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/rest/server/KsqlRestConfig.java

@@ -319,6 +319,11 @@
      "The key store certificate alias to be used for internal client requests. If not set, "
          + "the system will fall back on the Vert.x default choice";

+  public static final String KSQL_LOGGING_SKIP_RESPONSE_CODES_CONFIG =


ksqldb-rest-app/src/test/java/io/confluent/ksql/api/server/LoggingHandlerTest.java

docs/operate-and-deploy/installation/server-config/config-reference.md

Co-authored-by: Jim Galasyn <jim.galasyn@confluent.io>

docs/operate-and-deploy/installation/server-config/config-reference.md

JimGalasyn

LGTM, with a couple of suggestions.

Co-authored-by: Jim Galasyn <jim.galasyn@confluent.io>

vcrfxia

Thanks @AlanConfluent . Awesome stuff!

docs/operate-and-deploy/installation/server-config/config-reference.md

vcrfxia · 2020-11-23T18:01:51Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/rest/server/KsqlRestConfig.java

-  private static final String KSQL_LOGGING_SKIP_RESPONSE_CODES_DOC =
-      "A list of response codes to skip logging";
+  public static final String KSQL_LOGGING_SKIPPED_RESPONSE_CODES_CONFIG =
+      KSQL_CONFIG_PREFIX + "logging.skipped.response.codes";


Can we make this ksql.logging.server.skipped.response.codes or similar to indicate that this is only for server request logging, in contrast to the ksql.logging.processing.* configs for the processing log? I considered suggesting ksql.logging.request.* rather than ksql.logging.server.*but I worry that a config such as ksql.logging.request.skipped.response.codes could be confusing. Maybe it's OK and that's actually better, unsure.

If we change the config name, we'll also have to update the docs. (Thanks for adding those!)

I chose ksql.logging.server.* since I agree it's confusing if you have both request and response in the same name.

I also updated the docs I added as well.

vcrfxia · 2020-11-23T18:01:53Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/rest/server/KsqlRestConfig.java

+      "A list of HTTP response codes to skip during server request logging";
+
+  public static final String KSQL_LOGGING_RATE_LIMITED_REQUEST_PATHS_CONFIG =
+      KSQL_CONFIG_PREFIX + "logging.rate.limited.request.paths";


Same comment as above regarding clarifying that this a server request logging config, in contrast to other types of logging.

vcrfxia · 2020-11-23T18:02:01Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/rest/server/KsqlRestConfig.java

@@ -914,4 +930,8 @@ private static String getLocalHostName() {
    }
  }

+  public Map<String, String> getStringAsMap(final String key) {


This looks unused?

This is called in LoggingHandler.getSkipRequestPaths() to get the map of rate limits. I also called KsqlConfig.parseStringAsMap in the validator, so it's being parsed twice. It would be nice to be able to parse and validate at once, but it doesn't seem like the config library supports this at the moment.

vcrfxia · 2020-11-23T18:02:08Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/api/server/LoggingHandler.java

+          routingContext.request().getHeader(HTTP_HEADER_USER_AGENT)).orElse("-");
+      final String timestamp = Utils.formatRFC1123DateTime(clock.millis());
+      final String message = String.format(
+          "%s - %s [%s] \"%s %s %s\" %d %d \"-\" \"%s\" %d",


Does it make sense to add a short docs topic on the meaning of this format, since there are adaptations from the standard Apache log format?

Since it's mixed with the other debug statements and the format may change if we get additional requested fields, it doesn't seem like should commit to a particular format for the moment. I'm happy to write up a short doc explaining the format if this ends up being what we stick with.

vcrfxia · 2020-11-23T18:02:14Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/api/server/Server.java

@@ -117,7 +117,7 @@ public synchronized void start() {
    final List<URI> allListenUris = new ArrayList<>(listenUris);
    internalListenUri.ifPresent(allListenUris::add);

-    final int instances = config.getInt(KsqlRestConfig.VERTICLE_INSTANCES);
+    final int   instances = config.getInt(KsqlRestConfig.VERTICLE_INSTANCES);


nit: spacing

Done. I think this was an accidental addition of whitespace!

vcrfxia · 2020-11-23T18:02:18Z

ksqldb-rest-app/src/main/java/io/confluent/ksql/api/server/LoggingHandler.java

    this.logger = logger;
+    this.clock = clock;
+    this.rateLimiterFactory = rateLimiterFactory;
  }

  private static Set<Integer> getSkipResponseCodes(final KsqlRestConfig config) {


nit: move private helper methods to end of file?

ksqldb-rest-app/src/main/java/io/confluent/ksql/api/server/LoggingHandler.java

Co-authored-by: Victoria Xia <victoria.f.xia281@gmail.com>

feat: Adds logging for every request that comes in

8caaa34

AlanConfluent requested a review from vcrfxia November 14, 2020 01:33

AlanConfluent requested a review from a team as a code owner November 14, 2020 01:33

Feedback

295a0a8

vcrfxia approved these changes Nov 16, 2020

View reviewed changes

AlanConfluent added 2 commits November 20, 2020 15:18

Feedback

ff2e715

lint

051a4dd

AlanConfluent requested a review from JimGalasyn as a code owner November 20, 2020 23:33

AlanConfluent commented Nov 20, 2020

View reviewed changes

JimGalasyn reviewed Nov 21, 2020

View reviewed changes

docs/operate-and-deploy/installation/server-config/config-reference.md Outdated Show resolved Hide resolved

JimGalasyn reviewed Nov 21, 2020

View reviewed changes

docs/operate-and-deploy/installation/server-config/config-reference.md Outdated Show resolved Hide resolved

JimGalasyn reviewed Nov 21, 2020

View reviewed changes

docs/operate-and-deploy/installation/server-config/config-reference.md Outdated Show resolved Hide resolved

Apply suggestions from code review

7d33fab

Co-authored-by: Jim Galasyn <jim.galasyn@confluent.io>

JimGalasyn reviewed Nov 21, 2020

View reviewed changes

docs/operate-and-deploy/installation/server-config/config-reference.md Outdated Show resolved Hide resolved

JimGalasyn approved these changes Nov 21, 2020

View reviewed changes

AlanConfluent and others added 2 commits November 20, 2020 16:49

Apply suggestions from code review

5d0425e

Co-authored-by: Jim Galasyn <jim.galasyn@confluent.io>

when, given, then

3e16849

vcrfxia approved these changes Nov 23, 2020

View reviewed changes

AlanConfluent and others added 2 commits November 24, 2020 14:15

Apply suggestions from code review

291558e

Co-authored-by: Victoria Xia <victoria.f.xia281@gmail.com>

Feedback

32f6b8e

AlanConfluent merged commit 57b0c91 into confluentinc:master Nov 30, 2020

	"A list of response codes to skip logging";
	"A list of HTTP response codes to skip during server request logging";

feat: Adds logging for every request to ksqlDB #6615

feat: Adds logging for every request to ksqlDB #6615

Conversation

AlanConfluent commented Nov 14, 2020 • edited Loading

Description

Testing done

Reviewer checklist

purplefox commented Nov 14, 2020 • edited Loading

AlanConfluent commented Nov 16, 2020

vcrfxia left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

AlanConfluent left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

JimGalasyn left a comment

Choose a reason for hiding this comment

vcrfxia left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

AlanConfluent commented Nov 14, 2020 •

edited

Loading

purplefox commented Nov 14, 2020 •

edited

Loading