make the OOTB response logs before deserialization

[chaoky]

Currently response logs will not show up when there's a deserialization error, this doesn't seem to be intended, but if it is, maybe logging every request could be addded as a logging backend config?

Slf4jLoggingBackend(_, logResponseBody = true, alwaysLog = true)

version: 3.3.13

[adamw]

To make sure I understand correctly, what you'd like is that if the response has type such as ResponseAs[Either[ResponseException[String, io.circe.Error], B], Any], in case the result is a Left (e.g. a DeserialisationException), you'd like it logged as if an exception was thrown?

I'm not sure what should happen with alwaysLog, though?

[chaoky]

I would like to log the Response body whether or not a Circe error happens "always log" was a dumb suggestion

[adamw]

Don't worry, there are no dumb suggestions, there's usually a use-case behind :)

Currently the idea is that you can do .response(asJson.getRight) - which will represent any deserialisation errors as failed effects, and this will be logged (as an exception).

You can also do .response(asJson), and then you get an Either[..., ...], which you have to log manually. Question is, what do you do in your code when you get a Left - that is, a deserialisation/http error? Do you just discard it, perform logging, sth else?

[chaoky]

Sorry for posting such a bad issue,

If you throw while mapping a ResponseAs logs will not show up, this is specially anoying with Circe errors since they don't include the whole request like a HttpError would. Because logs don't contain any information that's obtained after processing the request, I think it would make sense for logging to happen before anything else

basicRequest
      .get("somewebsite")
      .response(asString.getRight.map(s =>
        throw SomeErr
        s
      ))
      .send

This is what I've been doing to keep the logs even when decoding fails

basicRequest
      .get("somewebsite")
      .response(asString.getRight)
      .send      
      .flatMap(r =>
        decode[SomeJsonBody](r.body) match {
          case Right(a) => r.copy(body = a) //IO(...)
          case Left(a) => throw a //IO.raiseError(a)
        })

[adamw]

Hm any exceptions thrown when mapping over a response are logged. For example:

import sttp.client3._
import sttp.client3.logging.slf4j.Slf4jLoggingBackend

object Test extends App {
  val backend = Slf4jLoggingBackend(HttpURLConnectionBackend(), logResponseBody = true)

  println(
    basicRequest
      .get(uri"http://example.com")
      .response(asString.getRight.map(s => throw new RuntimeException("test")))
      .send(backend)
  )
}

gives:

11:55:05.643 [main] DEBUG s.c.l.s.Slf4jLoggingBackend - Sending request: GET http://example.com, response as: mapped(mapped(either(as string, as string))), headers: Accept-Encoding: gzip, deflate
11:55:05.943 [main] ERROR s.c.l.s.Slf4jLoggingBackend - Exception when sending request: GET http://example.com, took: 0.290s
java.lang.RuntimeException: test

are you seeing some other behavior?

[chaoky]

Since the request has gone through and failed during parsing, this is what I would want to see in your example

DEBUG 11:55:05.643   sttp.client3.logging.slf4j.Slf4jLoggingBackend
  Sending request: GET http://example.com, response as: mapped(mapped(either(as string, as string))), headers: Accept-Encoding: gzip, deflate

DEBUG 11:55:05.743  sttp.client3.logging.slf4j.Slf4jLoggingBackend 
 Request: GET http://example.com, took: 1.003s, response: 200 , headers: access-control-allow-headers: x-after-offline, set-cookie: ***, date: Thu, 09 Sep 2021 18:00:44 GMT, access-control-allow-headers: Authorization, cache-control: no-store, no-cache, must-revalidate, set-cookie: ***, :status: 200, server: Apache, set-cookie: ***, content-length: 884, content-encoding: gzip, expires: Thu, 19 Nov 1981 08:52:00 GMT, access-control-allow-methods: GET, OPTIONS, POST, PUT, set-cookie: ***, content-type: application/json, vary: Accept-Encoding,User-Agent, set-cookie: ***, access-control-allow-headers: x-used-method, pragma: no-cache, body: { "foo":  "bar" }

ERROR 11:55:05.943   sttp.client3.logging.slf4j.Slf4jLoggingBackend 
 Exception when sending request: GET http://example.com, took: 0.290s

...

that's why my work around is to map over F[Request[A]] and throw there instead

[adamw]

@chaoky Hmm I understand and I see the problem. Unfortunately I think we can't fix it right now, without breaking binary compatibility. So this will have to wait until v4 in some (distant or not - no idea :) ) future.

The problem is that logging might be an effectful operation (logs return F[Unit]), and when creating the ResponseAs description, we don't allow for effectful mappings (that is, you can't give a function T => F[U], only a T => U, without changing the result's type).

So there are two solutions:

1. add effectful maps - quite heavy, and I'm not sure if useful outside of logging
2. modify DeserialisationException and HttpError to include the full original response

As a workaround, I think I would use the "pure" response-as specifications (e.g. asJson instead of asJson.getRight), which will do the logging as expected. After sending the request, I would fold the Either into a value or an exception.

Meanwhile, if you'd have other logging-related improvements, keep them coming :)