Hystrix: how to pass MDC context from calling thread to timer thread in case of hystrix time out fallback

[JagmohanSharma]

With reference to https://github.com/Netflix/Hystrix/issues/1564 and https://github.com/Netflix/Hystrix/pull/1570 issue, as
it will now invoke wrapCallable only when:
putting the Hystrix-wrapped work onto a Hystrix thread (command is thread-isolated)
executing the fallback on a HystrixTimer thread
executing a HystrixCollapser-produced command on a HystrixTimer thread

As this fallback execution is being done on HystrixTimer thread. We are passing MDC context (which contains Logging correlation id ) between calling(parent) and callee(child) threads but as in this case child thread will be HystrixTimer which is not getting parent MDC so does not has Logging correaltion id. We are not getting any correlation id in our log statements inside fallback methods in case of hystrix time out.

  public K call() throws Exception {
try {
    if (parentMDC != null && !parentMDC.isEmpty()) {
        MDC.setContextMap(parentMDC);
    }
    return actual.call();
} finally {
    MDC.clear();
}

}

In recent changes done in hystrix library currently we are capturing HystrixRequestContext upfront so that we can use it in the timeout thread later

           final HystrixRequestContext hystrixRequestContext = HystrixRequestContext.getContextForCurrentThread();

But initialising the HystrixContextRunnable in child thread "TimerListener" context so it does not have any calling thread information:

 final HystrixContextRunnable timeoutRunnable = new HystrixContextRunnable(originalCommand.concurrencyStrategy, hystrixRequestContext, new Runnable() {

                        @Override
                        public void run() {
                            child.onError(new HystrixTimeoutException());
                        }
                    });

@mattrjacobs @spencergibb please let me know how to achieve this with respect to recent changes done in hystrix?

[JagmohanSharma]

Can anybody help in this issue ?

[jjathman]

I'm also interested in this, we are having the same problem. Any ideas?

[JagmohanSharma]

This can be achieved by overriding HystrixCommandExecutionHook implementation. and pass the MDC context in appropriate methods. more details here -
https://github.com/Netflix/Hystrix/wiki/Plugins#commandexecutionhook

[jjathman]

Do you have an example of how this can be done? I'm not seeing how this class will work.

[JagmohanSharma]

@jjathman Yes you can do something like this:

  public class MDCPropagatingHystrixCommandExecutionHook extends HystrixCommandExecutionHook {

private HystrixRequestVariableDefault<Map<String, String>> mdcContextVariable = new HystrixRequestVariableDefault<>();

public <T> void onStart(HystrixInvokable<T> commandInstance) {
    extractMDCContext();
}

 private void extractMDCContext() {
    HystrixRequestContext.initializeContext();
    Map<String, String> originalMDCContext = MDC.getCopyOfContextMap();
    if (originalMDCContext != null && !originalMDCContext.isEmpty()) {
        mdcContextVariable.set(originalMDCContext);
    }
}
  }

Sorry for delay in replying. Let me know if this resolve your issue.

[the-wang]

@JagmohanSharma after HystrixRequestContext.initializeContext() was called then shutdown() must also be called or a memory leak will occur. How do you deal with it?

[JagmohanSharma]

@the-wang Its complete implementation will be

 public class MDCPropagatingHystrixCommandExecutionHook extends 
  HystrixCommandExecutionHook {

private HystrixRequestVariableDefault<Map<String, String>> mdcContextVariable = new HystrixRequestVariableDefault<>();

public <T> void onStart(HystrixInvokable<T> commandInstance) {
    extractMDCContext();
}

public <T> void onThreadStart(HystrixInvokable<T> commandInstance) {
    setupMDCContext();
}

public <T> void onFallbackStart(HystrixInvokable<T> commandInstance) {
    setupMDCContext();
}

public <T> Exception onFallbackError(HystrixInvokable<T> commandInstance, Exception e) {
    cleanup();
    return e;
}

public <T> void onFallbackSuccess(HystrixInvokable<T> commandInstance) {
    cleanup();
}

public <T> Exception onExecutionError(HystrixInvokable<T> commandInstance, Exception e) {
    cleanup();
    return e;
}

public <T> void onExecutionSuccess(HystrixInvokable<T> commandInstance) {
    cleanup();
}

private void extractMDCContext() {
    HystrixRequestContext.initializeContext();
    Map<String, String> originalMDCContext = MDC.getCopyOfContextMap();
    if (originalMDCContext != null && !originalMDCContext.isEmpty()) {
        mdcContextVariable.set(originalMDCContext);
    }
}

private void setupMDCContext() {
    if (HystrixRequestContext.getContextForCurrentThread() == null) {
        extractMDCContext();
    }
    if (mdcContextVariable.get() != null) {
        MDC.setContextMap(mdcContextVariable.get());
    }
}

private void cleanup() {
    HystrixRequestContext.getContextForCurrentThread().shutdown();
}

 }

[JagmohanSharma]

We have also implemented HystrixConcurrencyStrategy to clear MDC.

public class CircuitBreakerConcurrencyStrategy extends HystrixConcurrencyStrategy {

private static final Logger LOGGER = LoggerFactory.getLogger(CircuitBreakerConcurrencyStrategy.class);

public CircuitBreakerConcurrencyStrategy(boolean threadWarmupEnabled) {
    super();
}

@Override
public <T> Callable<T> wrapCallable(final Callable<T> callable) {
    return new Callable<T>() {
        @Override
        public T call() throws Exception {
            try {
                return callable.call();
            } finally {
                //MDC context is being set in MDCPropagatingHystrixCommandExecutionHook.
                MDC.clear();
            }
        }
    };
}

 }

[oliver-steinbrecher]

Thanks @JagmohanSharma for providing an approach here. Is there a reason for having both MDCPropagatingHystrixCommandExecutionHook and HystrixConcurrencyStrategy activated ?

[devinwhalen]

Is there an answer to oliver-steinbrecher question? Why do the MDC.clear() in HystrixConcurrencyStrategy instead of the HystrixCommandExecutionHook?

[victormferrara]

@oliver-steinbrecher @devinwhalen I had a very similar issue and in my tests I found the following situation when only using HystrixCommandExecutionHook:

1. hystrix-commandGroup-X thread sets the context in onThreadStart.
2. Command times out.
3. HystrixTimer-X thread sets the context in onFallbackStart.
4. When fallback finishes, onFallbackSuccess runs on HystrixTimer-X thead and clears the context.
5. Nothing else is done with hystrix-commandGroup-X thread, so the context is not cleared.

On the other hand, HystrixConcurrencyStrategy is executed both in the hystrix-commandGroup-X and HystrixTimer-X threads.

With all this premises, the best way I've found to solve this is to only override in HystrixCommandExecutionHook onStart, onThreadStart and onFallbackStart methods, and do the clean-up in HystrixConcurrencyStrategy.

I hope this helps and thanks for the discussion!

[oliver-steinbrecher]

Great - thanks for the feedback. I'm wondering why there is no official support for handling this. It feels like being a standard pattern "coping context from parent to child thread"

[shnax0210]

I resolved the issue by creation of abstract command and placing there logic to inherit MDC in next way:

public abstract class AbstractHystrixCommand<R> extends HystrixCommand<R> {
    private final Map<String, String> mdcFromCreatorThread;

    public AbstractHystrixCommand(final Setter setter) {
        super(setter);
        this.mdcFromCreatorThread = MDC.getCopyOfContextMap();
    }

    /**
     * Please override {@link AbstractHystrixCommand#runInContext()} instead of this method.
     */
    @Override
    protected final R run() throws Exception { //NOSONAR
        getMdcFromCreatorThread().ifPresent(MDC::setContextMap);
        try {
            return runInContext();
        }
        finally {
            MDC.clear();
        }
    }

    protected abstract R runInContext() throws Exception; //NOSONAR

    private Optional<Map<String, String>> getMdcFromCreatorThread() {
        return Optional.ofNullable(mdcFromCreatorThread);
    }
}

And inherited all our hyxtrix command from it. Since each command is created from a thread where we already have MDC we can save it to a variable in the command constructor and use in run method that is triggered from another thread where we need to get this MDC.

[yp-palF]

Encountered same problem, for those who are still confused refer to this blog
Suggestions are welcome

[utkarshmeesho]

This can be achieved by overriding HystrixCommandExecutionHook implementation. and pass the MDC context in appropriate methods. more details here -
https://github.com/Netflix/Hystrix/wiki/Plugins#commandexecutionhook

@JagmohanSharma
HI JagmohanSharma, This orks for fallback but when i had registered the HystrixEventNotifier, then this event notifier doesn't get the mdc context.
So when TIMEOUT happens, then the HystrixEventNotifier is executed in which there is no mdc/thread local context but after that it falls on fallback which is having all MDC context and surprisingly both happens in the same Timer thread. My use case is to get the MDC context at HystrixEventNotifier. Any idea anyone ?