Spring-cloud-sleuth: Trace information is missing when Exception is thrown from RabbitListener methods

[goober]

Describe the bug
When an exception is thrown from a method annotated with @RabbitListener all trace information is lost when it reaches the ConditionalRejectingErrorHandler

Sample
I have created a minimal application that reproduces the issue with a little more context that can be found here:
https://github.com/goober/spring-sleuth-rabbit-bug

[goober]

Could it be the same cause as #1659 ?

[jonatan-ivanov]

@goober Thank you for the sample project, I was able to repro the issue locally (I deleted your consumer class, since you have another listener already and updated a few things: spring-boot 2.3.7.RELEASE and spring-coud Hoxton.SR9).

It seems the issue you are seeing is caused by the followings:

• Brave is closing the span in TracingRabbitListenerAdvice right after it catches the exception thrown by the listener
• This will cause closing the CorrelationUpdateScope that updates the context and sets its fields to null
• The context here is an MDCScopeDecorator$MDCContext instance that removes the MDC entries
• After the MDC is empty, ConditionalRejectingErrorHandler logs out the exception, that's why you don't see tracing info in the logs (and I guess the context update will make sure that we lose the rest of the tracing context)

The whole thing is orchestrated by AbstractMessageListenerContainer.
It seems TracingRabbitListenerAdvice wraps only the invocation of the listener not the invocation and the error handling. I think it should wrap both.

@marcingrzejszczak @adriancole What do you think?

[codefromthecrypt]

if there's a way for the error handler to be wrapped in currentTraceContext.maybeScope(contextOfListenerSpan), it should. This might be related to an old issue so you can follow-up here. https://github.com/openzipkin/brave/issues/815

Feel free to raise a pull request in brave, including an integration test so that it stays fixed. I won't personally have time for a while as doing job interviews, but if you raise a PR I will try to help review it.

[jonatan-ivanov]

@adriancole Thanks, I'm going to look into this deeper later and get back to this thread but right now I feel that the change to wrap both the invocation and the error handling logic should happen in the AbstractMessageListenerContainer in spring-amqp, it should be "just" changing the scope/target of the AOP Proxy and not the advice itself.

[jonatan-ivanov]

Fyi: I have a fix for this: https://github.com/spring-projects/spring-amqp/pull/1287
I asked for feedback, let's see if this can be merged. :)

[garyrussell]

The @RabbitListener has error handlers at two levels - the container error handler is invoked outside the scope of the advice chain.

If you use a RabbitListenerErrorHandler instead...

    /**
     * Set an
     * {@link org.springframework.amqp.rabbit.listener.api.RabbitListenerErrorHandler} to
     * invoke if the listener method throws an exception. A simple String representing the
     * bean name. If a Spel expression (#{...}) is provided, the expression must
     * evaluate to a bean name or a
     * {@link org.springframework.amqp.rabbit.listener.api.RabbitListenerErrorHandler}
     * instance.
     * @return the error handler.
     * @since 2.0
     */
    String errorHandler() default "";

It is invoked within the scope of the advice.

It provides access to the original spring-amqp Message as well as the spring-messaging Message<?> that was converted from it.

@FunctionalInterface
public interface RabbitListenerErrorHandler {

    /**
     * Handle the error. If an exception is not thrown, the return value is returned to
     * the sender using normal {@code replyTo/@SendTo} semantics.
     * @param amqpMessage the raw message received.
     * @param message the converted spring-messaging message.
     * @param exception the exception the listener threw, wrapped in a
     * {@link ListenerExecutionFailedException}.
     * @return the return value to be sent to the sender.
     * @throws Exception an exception which may be the original or different.
     */
    Object handleError(Message amqpMessage, org.springframework.messaging.Message<?> message,
            ListenerExecutionFailedException exception) throws Exception; // NOSONAR

}

If you re-throw the exception after processing the error, it will be handled by the container error handler, as before.

[garyrussell]

Changing the sample app to...

@SpringBootApplication
@EnableScheduling
public class SleuthRabbitDemoApplication {

    Logger log = LoggerFactory.getLogger(SleuthRabbitDemoApplication.class);

    @Autowired
    private RabbitTemplate rabbitTemplate;

    public static void main(String[] args) {
        SpringApplication.run(SleuthRabbitDemoApplication.class, args);
    }

    @RabbitListener(queues = {RabbitConfiguration.queueName}, errorHandler = "leh")
    public void handler() {
        log.info("Received message");
        throw new AmqpRejectAndDontRequeueException("The message should be rejected");
    }

    @Scheduled(fixedRate = 10000)
    public void publish() {
        log.info("Publish message");
        rabbitTemplate.convertAndSend( RabbitConfiguration.topicExchangeName, "", "test");
    }
}

@Component("leh")
class LEH implements RabbitListenerErrorHandler {

    Logger log = LoggerFactory.getLogger(LEH.class);

    @Override
    public Object handleError(Message amqpMessage, org.springframework.messaging.Message<?> message, ListenerExecutionFailedException exception) throws Exception {
        log.info("failed");
        throw exception;
    }

}

We get

2020-12-21 14:12:09.466  INFO [,3db982c58f87634c,3db982c58f87634c,true] 33014 --- [   scheduling-1] c.g.g.s.SleuthRabbitDemoApplication      : Publish message
2020-12-21 14:12:09.483  INFO [,3db982c58f87634c,7cc9c0e5b9b62a69,true] 33014 --- [ntContainer#0-1] c.g.g.s.SleuthRabbitDemoApplication      : Received message
2020-12-21 14:12:09.483  INFO [,3db982c58f87634c,7cc9c0e5b9b62a69,true] 33014 --- [ntContainer#0-1] com.github.goober.sleuthrabbitdemo.LEH   : failed
2020-12-21 14:12:09.486  WARN [,,,] 33014 --- [ntContainer#0-1] s.a.r.l.ConditionalRejectingErrorHandler : Execution of Rabbit message listener failed.

[jonatan-ivanov]

Closing in favor of https://github.com/spring-projects/spring-amqp/issues/1306