Feign: More details (URL, method, body preview) in FeignClient(Server)Exception message

[jerzykrlk]

Can we make the FeignException message look like:

409 Conflict during [POST] to [http://localhost:8080/endpoint], response: [{"error":{"code":409,"message":"You already own this bucket. Please select another name."}}]

instead of just:

status 409 reading FeignClient#getResponse()

Reason:
Applications using Feign, communicate with multiple external systems.

As a developer, when I try to diagnose an issue in production, from the default exception message I cannot find out about:

• HTTP endpoint,
• HTTP method,
• the error response, which usually contains something interesting.

I think that the new format would improve developer experience. I would like to see the complete information from the moment when the issue occurred: which external system returned an error, what endpoint and response body was. Just like that.

This would automatically appear in the logs, so I do not need to 1st - search through the stacktraces to see which request that was, 2nd - try to reproduce the issue to see the actual response body. Especially hard with non-deterministic errors.

There are other ways to do it, but I think the exception message is most natural. Other ways I know, involve extra error handling code all around the application. And the new format would be almost no changes to users' existing code base.

Actual (sample of current Feign logs):

feign.FeignException$Conflict: status 409 reading FeignClient#getResponse()

    at feign.FeignException.clientErrorStatus(FeignException.java:118)
    at feign.FeignException.errorStatus(FeignException.java:91)
    at feign.FeignException.errorStatus(FeignException.java:86)

Expected (what the log entry could look like):

409 Conflict during [POST] to [http://localhost:8080/endpoint], response: [{"error":{"code":409,"message":"You already own this bucket. Please select another name."}}]

feign.FeignException$Conflict: 409 Conflict during [POST] to [http://localhost:8080/endpoint], response: [{"error":{"code":409,"message":"You already own this bucket. Please select another name."}}]

    at feign.FeignException.clientErrorStatus(FeignException.java:118)
    at feign.FeignException.errorStatus(FeignException.java:91)
    at feign.FeignException.errorStatus(FeignException.java:86)

I have implemented this multiple times already, in multiple projects. I think Feign would be a better place to do that.

Note - back in Feign 10.0.1, the message contained the complete body of the response (any size, even 1MB worked), which might cause problems. But I think the response can be abbreviated to just first 100 - 500 characters of the body.

This is basically the same idea as here: https://github.com/spring-projects/spring-framework/pull/1956 . I can provide a pull request for this, if you like the general concept.

[kdavisk6]

@jerzykrlk

I agree that the structure of FeignException could be improved. I like where you are headed. We can also update the Logger interface to include a logException method, to provide users the ability to customize the log structure as well.

To accomplish this, I think we'll need to make a few small updates:

1. Update the FeignException API to explicitly accept a status code, reason message in addition to the request and response data.
2. Update the FeignException.getMessage() API to return a well defined default message.
3. Create a logException method on the Logger that logs FeignExceptions by default and can be extended to customize the log message for those that need specific structured logs.

Thoughts?

[finnetrolle]

O think it is a good idea to create log formatter to give clients a chance to decide how to write message to logs. Also Logger now has some unexpected behaviour #985 and I'd like to develop new version.

[jerzykrlk]

@kdavisk6 @finnetrolle
I am not familiar with the Logger API, but after a quick look, it seems to be a slightly different direction. I would just prefer to work on FeignException's message.

From my understanding, ErrorDecoder would be the right place to build a verbose exception message.

One note: As a developer using Feign, I'd be happy to be able to do these, independently:

1. further customise the exception message.

This one is less likely, but it might happen. For example, when I use a DNS-load-balanced service, I want to log both the service hostname and the actual IP I connected to.

1. further customise the response body preview in the message.

It is nice to have something by default - like what I wrote above. However, I usually have to customise that further, anyway. For example:

• format the JSON with multi-line support,
• format XML,
• strip HTML tags from a HTML response,
• get 1st 1k characters, for a longer response.

We cannot incorporate all above in Feign, so I would love some interface for this, as I usually need some of these.

I cannot now think of a simple way to do that. I would probably extend ErrorDecoder.Default, and add my changes there, but that is probably a poor choice.

Any thoughts?

[kdavisk6]

@jerzykrlk

The ErrorDecoder is the right component for users to add their own exception management, and it is possible to achieve everything in your proposal by implementing your own ErrorDecoder. However FeignException does not provide enough context to support your needs. My suggestion is to start by adding that context to FeignException and then consider how this information may be used as part of a log, possibly as a separate issue, as that has larger implications.

Logging and exception handling go hand-in-hand when running any software at scale. These areas are very sensitive and highly specific. Given Feign's place as a middleware, we must do our best to remain neutral and provide ways for users to manage logging and exception handling, delegating that responsibility and not be too restrictive or too opinionated.

The request here is quite simple, a better error message. However, given that this information will be consumed primarily via log files, we need to be very careful how to approach the structure of the message and we must provide a way to override our format. I'm suggesting that we approach this ask as follows:

1. Update the FeignException API to expose Request and Response context information explicitly. Adding methods like the following:

   • getRequestEndpoint()
   • getRequestMethod()
   • getRequestHeaders()
   • getRequestParameters()
   • getResponseStatusCode()
   • getResponseReasonCode()
   • getResponseAsString()

2. Update FeignException#getMessage() to format the information in a very simple, unstructured way, specifically to avoid imposing any structure on users.

3. Refactor the Logger API to allow customization of these log messages when using Feign's built in logging capability. It is here that users will be able to add any specific structure they need, like format it as JSON, limit the response, etc...

[finnetrolle]

Looks like we should add Response to FeignException first (or may be only to derived http-code-specific classes) and develop points then. I can take this task

[jerzykrlk]

Hi @kdavisk6 @finnetrolle ,

Sorry, I was not familiar with the Logger approach. My naive attempt would rather be to build the message outside of the FeignException and pass it over as another parameter to exception constructor. That would be the extension point for customisation.

Could you point me to the right code? And, maybe could I see an example, how this would work eg. with SLF4J or some other logging API? So that I understand this better?

Thanks.

[finnetrolle]

@jerzykrlk
You can find basics about working with exceptions here - https://github.com/OpenFeign/feign#error-handling

Also, now you can get a response from FeignException you caught.

If you need to work with logs - read this first https://github.com/OpenFeign/feign#slf4j https://github.com/OpenFeign/feign#logging

When you want to log in your own way you can just extend Logger class. In default you must implement just log() method. But you also can override other methods of Logger and create your own way to write logs. But in fact you can face problem of splitted response and request logging... See example below

public class MyLogger extends Logger {

    private final static java.util.logging.Logger LOGGER = java.util.logging.Logger.getLogger(MyLogger.class.getName());

    @Override
    protected void logRequest(String configKey, Level logLevel, Request request) {
        LOGGER.info(request.toString());
    }

    @Override
    protected void logRetry(String configKey, Level logLevel) {
        LOGGER.info("RETRYING!");
    }

    @Override
    protected Response logAndRebufferResponse(String configKey, Level logLevel, Response response, long elapsedTime) throws IOException {
        LOGGER.info(response.toString());
        return response;
    }

    @Override
    protected IOException logIOException(String configKey, Level logLevel, IOException ioe, long elapsedTime) {
        LOGGER.log(java.util.logging.Level.SEVERE, "Bad news", ioe);
        return ioe;
    }

    @Override
    protected void log(String configKey, String format, Object... args) {
        LOGGER.fine(String.format(methodTag(configKey) + format, args));
    }
}

[jerzykrlk]

@finnetrolle

Thank you for explaining. I have read the docs. I am not worried about request/response split here - adding some request details to an exception would fix that.

And, I feel that in production, the overhead of adding request details to the exception would not be a big overhead - compared to building the stacktrace or executing the actual request. This might need to be measured, though.

One more question. Do I understand it right that logIOException() would log all HTTP exceptions that happened? This seems independent to the actual exception handling flow.

If yes, then I can see one thing here that could be a challenge.

Right now, I get a FeignException as a part of a stacktrace, in its context. Sometimes wrapped in other exceptions, passed as cause. Like below:

Exception in thread "main" java.lang.IllegalStateException: Failed to get book [1255] data
        at com.example.myproject.Author.getBookIds(Author.java:38)
        at com.example.myproject.Bootstrap.main(Bootstrap.java:14)
Caused by: feign.FeignException.BadGateway 502 Bad Gateway during [GET] to [http://api.example.com/books/1255], response: [{"error":{"code":502,"message":"Remote host failed to respond in 30 seconds."}}]
        at com.example.myproject.BookClient.getBook(Book.java:22)
        at com.example.myproject.Author.getBookIds(Author.java:36)
        ... 1 more

And, I have control of which exceptions get logged. Some exceptions are expected, like this:

try {
    googleClient.getData(...);
} catch (FeignException.NotFound e) {
    wait and try again after 30s;
}

or this:

try {
    googleClient.getData(...);
} catch (FeignException.Unauthorized e) {
    get the new authentication token
}

Usually, I don't log all of them, as they're not errors. And only unexpected exceptions make it to the logger. Just as a result of the above business logic, with no extra effort.

Do you think the above would be possible with Logger?

[finnetrolle]

@jerzykrlk
I took a look at code and we can find only two calls of logIOException
feign/SynchronousMethodHandler.java:113
feign/SynchronousMethodHandler.java:155
This lines are not related to FeignException.

If I got your question correct, I think you should use your own logger. Feign log some inner procedures. On the feignException level you gain request to get needed info and write it to log via SLF4J or else.

Add private static logger LoggerFactory.getLogger() to your class and inside catch block do something like LOGGER.info("Caught 404 at " + e.request().method())

[jerzykrlk]

Hi @finnetrolle

I'm sorry for the delay. I wrote some code clarify things. Can you look at https://github.com/OpenFeign/feign/pull/1095 ?

It is just an example. It just naively decodes the response body without any checks. But illustrates my idea.

All information is just visible in the exception's getMessage(). So it's clearly visible, what went wrong, in the log files.

And also, the information propagates nicely, when wrapped with other business-like exceptions.

I'm aware that the approach with LOGGER.info is an option, too. But I am worried that I would need to code this LOGGER.info(...) all across the code. As an 'everyday developer', I would want to avoid writing the same LOGGER.info() in multiple places.