# How to customize logging with the server log interceptor?

**URL:** <https://softwaremill.community/t/how-to-customize-logging-with-the-server-log-interceptor/361>\
**Category:** tapir\
**Created:** [January 16, 2024, 11:14pm UTC](https://softwaremill.community/t/how-to-customize-logging-with-the-server-log-interceptor/361 "2024-01-16T23:14:10Z")\
**Posts on this page:** 10\
**Page:** 1

<div class="post-metadata">

**Author:** ![andreazube-eu](https://dub1.discourse-cdn.com/flex005/user_avatar/softwaremill.community/andreazube-eu/32/233_2.png) [@andreazube-eu](https://softwaremill.community/u/andreazube-eu)\
**Post date:** [January 16, 2024, 11:14pm UTC](https://softwaremill.community/t/how-to-customize-logging-with-the-server-log-interceptor/361/1 "2024-01-16T23:14:10Z")

</div>

Hello 😃

I’m having trouble understanding how to implement [Logging & debugging — tapir 1.x documentation](https://tapir.softwaremill.com/en/latest/server/debugging.html)

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/](https://adopt-tapir.softwaremill.com/).

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

```auto
❯ curl localhost:8080/hello

Invalid value for: query parameter name (missing)

```

_And_, I get some debug-level logs

```auto
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

```auto
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

```auto
  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`

```auto
          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!

---

<div class="post-metadata">

**Author:** ![kciesielski](https://dub1.discourse-cdn.com/flex005/user_avatar/softwaremill.community/kciesielski/32/133_2.png) [@kciesielski](https://softwaremill.community/u/kciesielski)\
**Post date:** [January 18, 2024, 12:51pm UTC](https://softwaremill.community/t/how-to-customize-logging-with-the-server-log-interceptor/361/2 "2024-01-18T12:51:42Z")

</div>

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`:

```auto
  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.

---

<div class="post-metadata">

**Author:** ![adamw](https://dub1.discourse-cdn.com/flex005/user_avatar/softwaremill.community/adamw/32/28_2.png) [@adamw](https://softwaremill.community/u/adamw)\
**Post date:** [January 24, 2024, 1:37pm UTC](https://softwaremill.community/t/how-to-customize-logging-with-the-server-log-interceptor/361/3 "2024-01-24T13:37:52Z")

</div>

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](https://github.com/softwaremill/tapir/blob/69d9ac79044c69a950bda8d7b0a767ae4fdbef36/server/core/src/main/scala/sttp/tapir/server/interceptor/log/ServerLog.scala#L104).

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`?

---

<div class="post-metadata">

**Author:** ![kciesielski](https://dub1.discourse-cdn.com/flex005/user_avatar/softwaremill.community/kciesielski/32/133_2.png) [@kciesielski](https://softwaremill.community/u/kciesielski)\
**Post date:** [January 24, 2024, 3:59pm UTC](https://softwaremill.community/t/how-to-customize-logging-with-the-server-log-interceptor/361/4 "2024-01-24T15:59:40Z")

</div>

> Say I have a very simple `GET /hello?name=[string]` endpoint, the same you get from [https://adopt-tapir.softwaremill.com/](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

```auto
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”.

---

<div class="post-metadata">

**Author:** ![adamw](https://dub1.discourse-cdn.com/flex005/user_avatar/softwaremill.community/adamw/32/28_2.png) [@adamw](https://softwaremill.community/u/adamw)\
**Post date:** [January 24, 2024, 4:12pm UTC](https://softwaremill.community/t/how-to-customize-logging-with-the-server-log-interceptor/361/5 "2024-01-24T16:12:37Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![kciesielski](https://dub1.discourse-cdn.com/flex005/user_avatar/softwaremill.community/kciesielski/32/133_2.png) [@kciesielski](https://softwaremill.community/u/kciesielski)\
**Post date:** [January 24, 2024, 8:32pm UTC](https://softwaremill.community/t/how-to-customize-logging-with-the-server-log-interceptor/361/6 "2024-01-24T20:32:50Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![adamw](https://dub1.discourse-cdn.com/flex005/user_avatar/softwaremill.community/adamw/32/28_2.png) [@adamw](https://softwaremill.community/u/adamw)\
**Post date:** [January 24, 2024, 8:45pm UTC](https://softwaremill.community/t/how-to-customize-logging-with-the-server-log-interceptor/361/7 "2024-01-24T20:45:27Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![kciesielski](https://dub1.discourse-cdn.com/flex005/user_avatar/softwaremill.community/kciesielski/32/133_2.png) [@kciesielski](https://softwaremill.community/u/kciesielski)\
**Post date:** [January 24, 2024, 10:09pm UTC](https://softwaremill.community/t/how-to-customize-logging-with-the-server-log-interceptor/361/8 "2024-01-24T22:09:43Z")

</div>

It’s not only the exception. In

```auto
Error(original: String, error: Throwable)

```

the `original` field contains the entire input body.

---

<div class="post-metadata">

**Author:** ![adamw](https://dub1.discourse-cdn.com/flex005/user_avatar/softwaremill.community/adamw/32/28_2.png) [@adamw](https://softwaremill.community/u/adamw)\
**Post date:** [January 25, 2024, 7:49am UTC](https://softwaremill.community/t/how-to-customize-logging-with-the-server-log-interceptor/361/9 "2024-01-25T07:49:27Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![kciesielski](https://dub1.discourse-cdn.com/flex005/user_avatar/softwaremill.community/kciesielski/32/133_2.png) [@kciesielski](https://softwaremill.community/u/kciesielski)\
**Post date:** [January 27, 2024, 11:50am UTC](https://softwaremill.community/t/how-to-customize-logging-with-the-server-log-interceptor/361/10 "2024-01-27T11:50:59Z")

</div>

I created an issue for ServerLog improvements: [Enhancing ServerLog handling of decode failures · Issue #3488 · softwaremill/tapir · GitHub](https://github.com/softwaremill/tapir/issues/3488)