How to customize logging with the server log interceptor?

Hello :smiley:

I’m having trouble understanding how to implement Logging & debugging — tapir 1.x documentation

In fact, if I manage to get this working for me, I’d like to shot a PR to provide some examples in the repo.

Say I have a very simple GET /hello?name=[string] endpoint, the same you get from https://adopt-tapir.softwaremill.com/.

If I omit the mandatory name parameter, as expected, I get a 400 error

❯ curl localhost:8080/hello

Invalid value for: query parameter name (missing)

And, I get some debug-level logs

23:49:09.067 [default-pekko.actor.default-dispatcher-4] DEBUG s.t.s.p.PekkoHttpServerInterpreter$ - Request: GET /hello, handled by: GET /hello, took: 49ms; decode failure: Missing, on input: ?name; response: 400

However, I don’t want this to be on a debug level. Instead, I want to println it.

Note: I want to println in this simple example to avoid any slf4j complications, though I suspect the issue lies there anyways

My main looks like

package com.example

import org.apache.pekko.actor.ActorSystem
import org.apache.pekko.http.scaladsl.Http
import sttp.tapir.server.pekkohttp.{PekkoHttpServerInterpreter, PekkoHttpServerOptions}

import scala.concurrent.ExecutionContext.Implicits.global
import scala.concurrent.Future
import scala.io.StdIn

@main def run(): Unit =
  implicit val actorSystem: ActorSystem = ActorSystem()

  val serverOptions: PekkoHttpServerOptions =
    PekkoHttpServerOptions
      .customiseInterceptors
      .metricsInterceptor(Endpoints.prometheusMetrics.metricsInterceptor())
      .options

  val route = PekkoHttpServerInterpreter(serverOptions).toRoute(Endpoints.all)

  val port = sys.env.get("http.port").map(_.toInt).getOrElse(8080)

  val bindingFuture = Http()
    .newServerAt("localhost", port)
    .bindFlow(route)
    .map { binding =>
      println(s"Go to http://localhost:${binding.localAddress.getPort}/docs to open SwaggerUI. Press ENTER key to exit.")
      binding
    }

  StdIn.readLine()

  bindingFuture.flatMap(_.unbind()).onComplete(_ => actorSystem.terminate())

, so I add a log interceptor

  val serverOptions: PekkoHttpServerOptions =
    PekkoHttpServerOptions
      .customiseInterceptors
      .metricsInterceptor(Endpoints.prometheusMetrics.metricsInterceptor())
      .serverLog(
        PekkoHttpServerOptions.defaultSlf4jServerLog
          .doLogAllDecodeFailures { (message, maybeThrowable) =>
            Future.successful {
              println("Tapirs are amazing animals!")
              println(message)
            }
          }
          .logAllDecodeFailures(true) // just to be sure
      )
      .options

However, this setting seems to be completely ignored.

Note that this is a toy example, in a real word scenario it’s of course a bit more complex. In my case, I want to “promote” the log level from debug to warn.

Actually, I’ve never managed to make this work despite using tapir for 2 years. My workaround is adding logging to a custom rejection handler, which works. However, that is sub-optimal because

  • Separation of concerns: the logging interceptor should… deal with logging
  • Ideally, I’d have access to the whole context, but when customizing the default rejection handler, you don’t have that

To be more precise, you only have access to message and statusCode in the response method when using DefaultDecodeFailureHandler. You can hack it at the cost of truly ugly code by logging when defining the failureMessage

          failureMessage = (context: DecodeFailureContext) => {
            logger.warn(
              s"""Failed to decode request
                 |  Request:  ${context.request.showShort}
                 |  Error:   ${FailureMessages.failureMessage(context)}
                 |""".stripMargin
            )

            FailureMessages.failureMessage(context)
          }

Anyhow, back at the topic at hand: what am I doing wrong?

All I want is to simply enable logging when a request decoding fails. Ideally, I’d like to be able to pass a function (context: DecodeFailureContext) => F[Unit] so I can do whatever, but I’m fine with the default “decorators” and just customizing the error message

def doLogAllDecodeFailures(f: (String, Option[Throwable]) => F[Unit]): DefaultServerLog[F]

Thanks!

The doLogAllDecodeFailures is handler used when decoding inputs caused the server to try another endpoint, so it’s a different kind of error than the one you want to handle. This is further enabled by the logDecodeAllFailures Boolean, which you probably don’t need.

Your case will be handled by doLogWhenHandled, because ServerLog calls it for 3 cases where a result is returned by the backend:

  1. Endpoint handled the request which resulted in a decoding error (your case, for example HTTP 400 response)
  2. Endpoint handled the request without errors
  3. Endpoint handled the request and failed with a security failure

Unfortunately it’s not enough to override decodeWhenHandled, because this method will receive just an already formatted String with error, or information about successful handling.

What you can do is override decodeFailureHandled in DefaultServerLog:

  val mySlf4jServerLog: DefaultServerLog[Future] = {

    def debugLog(msg: String, exOpt: Option[Throwable]): Future[Unit] = Future.successful {
      exOpt match {
        case None     => println(s"DEBUG: $msg")
        case Some(ex) => println(s"DEBUG: $msg; exception: $ex")
      }
    }

    def errorLog(msg: String, ex: Throwable): Future[Unit] = Future.successful(println(s"ERROR: $msg"))

    new DefaultServerLog[Future](
      doLogWhenReceived = debugLog(_, None),
      doLogWhenHandled = debugLog,
      doLogAllDecodeFailures = debugLog,
      doLogExceptions = errorLog,
      noLog = Future.successful(())
    ) {

      override def decodeFailureHandled(ctx: DecodeFailureContext, response: ServerResponse[_], token: TOKEN): Future[Unit] =
        Future.successful {
          println( // TODO use a proper logger instead
            s"ERROR: Endpoint: ${showEndpoint(ctx.endpoint)}; decode failure: ${ctx.failure}, on input: ${ctx.failingInput.show}; response: ${showResponse(response)}"
          )
        }
    }
  }

 val serverOptions =
    PekkoHttpServerOptions.customiseInterceptors.serverLog(mySlf4jServerLog).options

Please not that in the example above I’m just printing the entire ctx.failure, which may be unsafe. It’s recommended to treat subclasses of DecodeResult.Failure individually. For example failed JSON deserialization may result in an Error(original: String, error: Throwable), where original contains the full input JSON, which one often doesn’t want to put in logs.

Thanks for reporting this! I guess we may want to simplify the API for “I want to log decode failures as warnings/errors” scenario and similar cases, or at least improve the docs.

Do I understand correctly that the problem is with customising the logging of decode failures, that have been handled and produce a response?

If so, I think indeed this should be fixed over here.

There are four cases here:

  1. logWhenHandled = false, logAllDecodeFailures = false - do nothing (current behavior)
  2. logWhenHandled = true, logAllDecodeFailures = false - log a single message using doLogWhenHandled (current behavior)
  3. logWhenHandled = false, logAllDecodeFailures = true - this is not how it works currently, but I think the proper thing to do would be to log the message using doLogAllDecodeFailures
  4. logWhenHandled = true, logAllDecodeFailures = true - also not how it works currently, but I’m not sure, if we should log a single message, or two messages? Logging two messages seems wrong, but then if we log a single one, should we use doLogWhenHandled or doLogAllDecodeFailures?

Say I have a very simple GET /hello?name=[string] endpoint, the same you get from https://adopt-tapir.softwaremill.com/.
If I omit the mandatory name parameter, as expected, I get a 400 error

@adamw I think this counts as “handled and produce a response”?
I think that case 4. intuitively matches doLogAllDecodeFailures , and a single message is enough. The msg string will be

s"Request: ${showRequest(ctx.request)}, handled by: ${showEndpoint(
            ctx.endpoint
          )}${took(token)}; decode failure: ${ctx.failure}, on input: ${ctx.failingInput.show}; response: ${showResponse(response)}"

which says “handled”.

@kciesielski right, so then we’d call doLogAllDecodeFailures if possible, and if that’s turned off, optionally doLogWhenHandled. Now we must only turn this into code :slight_smile:

One more remark: the message passed to doLogAllDecodeFailures contains ${ctx.failure} which may be unsafe, as I mentioned earlier. I suspect users may want to customize this message, what’s the way to go in such case - something akin to my proposition of overriding decodeFailureHandled?
Or maybe we should add a showFailure(ctx.failure) similar to current showRequest and showEndpoint to print all subtypes of DecodeResult.Failure properly. We even have nice printing of DecodeResult.Failure in FailureMessages, which is used to build response body. Maybe we can refactor this a bit to make it reusable for the log message.

Why is it unsafe? I guess showing exceptions in logs is fine, as long as we don’t return the exception’s message or such to the user.

It’s not only the exception. In

Error(original: String, error: Throwable)

the original field contains the entire input body.

Ah true … well on one hand this is handy for debugging (you can get a reproducible example easily), on the other you might log too much. A “proper” solution is to wrap any sensitive data in a dedicated type which masks when converted to a string. So indeed showFailure as an additional option is a good idea, but as a default value I’d just convert this to string (maybe capping the length of the original that is printed out?)

I created an issue for ServerLog improvements: Enhancing ServerLog handling of decode failures · Issue #3488 · softwaremill/tapir · GitHub