Logging should happen after micrometer instrumentation

[gviczai]

Request logging happens at line 96 of SynchronousMethodHandler and client.execute called a few lines after that.
However, micrometer observation starts in client.execute (in enriched client code), which means that extra trace headers added for example by Brave's PropagatingSenderTracingObservationHandler do not appear in the logs.

I think logging should happen only after the request is fully decorated by all possible observationhandlers, so the log should reflect the exact same data that was sent...

[velo]

I think logging should happen only after the request is fully decorated by all possible observationhandlers, so the log should reflect the exact same data that was sent...

that would be tricky, as this is a change happening inside the client, which feign-core doesn't control.
Any suggestions how we could implement that?

[gviczai]

Of course if one decorates the actual http client (for example using okhttp's interceptors) then it is nearly impossible to add Feign logging there, except if logging itself is implemented as an okhttp interceptor, but that would be a far too complex solution and arises more problems than it would solve...

But I think what we have here decorated by Feign using Capapbility instances are not low-level http clients but the Feign Client itself.
What I'm really concerned about is the MicrometerObservationCapability which opens the door for Various Observation handlers (like the one implemented by Tracing) to interfere with the Feign Client. So we have to focus on Capability implementations.

I think logging should be done in a Capability as well, 'cause as I see there can be multiple capabilities - they act in a way like Spring bean postprocessors - they get a bean, modify it and pass it to the next postprocessor. Although, TBH, I do not understand the deep details how this capability framework of Feign's works, but since the micrometer observation patter is implemented through one, I don't think it would be impossible to add another just for logging. If I'm right these capabilities can add enrichment code to Client that are applied in a nested way much like servlet filters... If so, and the last enrichment added by a capapbility is the inner most one, if it was the one doing the logging, that'd do the job. (If @Order could be used on Capapbility instances, that would be the most elegant way...)

What I'm thinking of RN:

@Order(Integer.MAX_VALUE)
public class LoggingCapability implements Capability {

 @Override
  public Client enrich(Client client) {
    return (request, options) -> {
        //do the request logging here 
        Response response = client.execute(request, options);
        //do the response logging here
       return response;
    };
  }
}

Note: Capability instances not having @Order class level annotation should get a default value, something like 100 or so... Thus LoggingCapapbility is guaranteed to applied as the last, and backward compatibility is kept, too.

[gviczai]

I've just realized (during debugging some code) that the situation is even worse: Since Feign logging happens BEFORE the micrometer observation is created, the spanId logged (as an MDC) is NOT what is created by the observation handler and sent to the endpoint operation called in the request. (The tracing observation handler creates a new span for each started observation, as it should.)
So the logging - in its current state - is misleading in two ways: first, it does not shows all the headers that are sent in the request and second, it logs the wrong span (the parent span), not what is actually sent to the remote server.

[gviczai]

The situation is even worse than the "even worse" I mentioned previously. I've fount two additional problems:

1. The RequestInterceptor instances (if any defined) also executed before the tracing span is created when the observation is started by MicrometerObservationCapability. (So one is not able to access correct values from interceptors either.)
2. I realized that the new span is set in a TracingContext in a separate micrometer FeignContext object, the TracingContext in the Spring aplication context is not changed.

So I think, this whole concept requires some re-thinking and re-writing. (In sync with the team responsible for Spring micrometer observation logic.)
Currently the only solution I found to log the correct headers sent through the wire and the correct spanId is to create a MeterObservationHandler which logs them. Fortunately enough the Observation.Context (feign.micrometer.FeignContext) available as the handler onStart() parameter contains both the correct TracingContext and updated headers as well.
(Yes, a MeterObservationHandler is required, because "normal" observation handlers are notified BEFORE "grouped" handlers like the PropagatingSenderTracingObservationHandler which creates the new span. See org.springframework.boot.actuate.autoconfigure.observation.ObservationHandlerGrouping.apply() for details.)

For those who also face the same requirement (logging correct values) here is my workaround:

package eu.skiltor.projects.demo.service.observation;

import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;

import brave.baggage.BaggageFields;
import feign.micrometer.FeignContext;
import io.micrometer.core.instrument.observation.MeterObservationHandler;
import io.micrometer.observation.Observation.Context;
import io.micrometer.tracing.handler.TracingObservationHandler.TracingContext;

@Component
public class FeignLoggingObservationHandler implements MeterObservationHandler<FeignContext> {
    private static final org.slf4j.Logger LOGGER = LoggerFactory.getLogger(FeignLoggingObservationHandler.class);
    
    @Override
    public void onStart(FeignContext feignMicrometerContext) {
        TracingContext tracingCtx = feignMicrometerContext.get(TracingContext.class);
        String previousSpanId = MDC.get(BaggageFields.SPAN_ID.name());
        MDC.put(BaggageFields.SPAN_ID.name(),tracingCtx.getSpan().context().spanId());
        LOGGER.debug("Sending request with headers: {}",feignMicrometerContext.getCarrier().headers());
        MDC.put(BaggageFields.SPAN_ID.name(),previousSpanId);
    }
    
    @Override
    public boolean supportsContext(Context context) {
        return context instanceof FeignContext;
    }

}

[kdavisk6]

I think that logging in Feign in general is working as expected. I do agree that the interplay between logging and trace/log correlation is not working as one would expect, but I would also say that Feign's general logging should not take tracing into account, here's why.

Feign logging is intended to provide simple visibility into the request preparation and response processing. It does not interact with request execution, which is where I think things are becoming confusing. Typically, we delegate this to the Client themselves, so @velo is correct in saying that, in general, we'd defer to the TracingClient to manage the logging of the trace information as it's only appropriate in that context.

With that said, I think your suggestion of an additional observation handler is appropriate, but it is only relevant when using Tracing, Micrometer with log/trace correlation and could be an enhancement to the MicrometerObservationCapability, but it does not belong in Feign's general use Logger feature. The separation of responsibilities should remain as follows:

• Feign Logger: responsible for logging Feign request preparation and response processing
• Feign Client: responsible for logging request execution, if desired

Recommendation: improve MicrometerObservationCapability's documentation when using Feign's general Logger and provide reference implementation/examples explaining the separation and how to use them together.

[marcingrzejszczak]

Can Feign maintainers tell us again why the capabilities are executed after the logging? Can we do sth about it? Have we done sth wrong while introducing Micrometer capabilities? How can we fix it?

[OlgaMaciaszek]

Hi @kdavisk6, @velo - this is a blocker for spring-cloud/spring-cloud-openfeign#812. Could this be addressed (please see @marcingrzejszczak's comment above)?

[velo]

There is quite a lot to read and a lot of context I don't have to understand this issue.

Can you boil it down to a single unit test that I can run here and see the problem?

[joloto]

For those who also face the same requirement (logging correct values) here is my workaround:

Thanks for this suggestion above @gviczai - it got me on the path to a workaround solution. We log and use the spanid of the feign request for log correlation across applications, and it's also good to have the capability to log the trace headers when debugging.

Just be careful which interface you implement and not to replace the default metrics and tracing handlers as this could break metrics or another aspect of tracing - I discovered there will only be a maximum of one MeterObservationHandler and one TracingObservationHandler invoked for a given observation context (see ObservationHandlerGrouping#apply that uses FirstMatchingCompositeObservationHandler).

I ended up extending the PropagatingSenderTracingObservationHandlerwhere the actual tracing field values are propagated to the client request headers (still need to invoke this before my custom logging logic!) with a higher precedence custom bean (i.e. @Order(MicrometerTracingAutoConfiguration.SENDER_TRACING_OBSERVATION_HANDLER_ORDER - 1) or lower) as outlined here:

@Component
@Order(MicrometerTracingAutoConfiguration.SENDER_TRACING_OBSERVATION_HANDLER_ORDER - 1)
public class MyCustomTracingObservationHandler extends PropagatingSenderTracingObservationHandler<FeignContext> {

     // constructor and other fields 

    @Override
    public void onStart(FeignContext feignContext) {
        super.onStart(feignContext);

        // do custom spanid / header logging logic here
    }

    @Override
    public boolean supportsContext(Observation.Context context) {
        return context instanceof FeignContext;
    }
}

[marcingrzejszczak]

So is there any issue here? I'm getting super confused