grpc/otel context mess up with non-context executor

[junhuangli]

We are hosting a grpc service in a generic way except:

There are cases where we're running in the context of a user request, and add some work to a queue. A background thread will process the queue generically, grouping multiple queue entries into an aggregate operation. An example would be communicating something to another service via grpc, but it's more efficient to have a single grpc request with a repeated field for many items, rather than a bunch of individual grpc requests.
In this case, the background processing has its own context, and the individual request contexts are restored when their individual futures are completed.

When using the java agent with grpc instrumentation, we are getting the following error.
"Context ancestry chain length is abnormally long. This suggests an error in application code. Length exceeded: 1000"

I understand this is sort of a expected behavior since there is a bridge between grpc context and otel context. So when different otel contexts create the bridge to the same(default/root) grpc context, it will be messed up.

My question is what is the best practice to handle this kind of "non-context executor"? It makes a lot of sense from application efficiency/perf perspective. But it makes instrumentation hard.

[laurit]

Without being able to reproduce this it is hard to say where the problem is or whether it can be fixed. I guess we could consider adding a flag that disables propagating otel context through the grpc context.

[junhuangli]

Thanks for replying @laurit . Couple of follow up questions

1. What will happen if there is this flag and a I turn off the "otel context through the grpc context"? Will it create a new trace for each async all or it will not instrument each async call?
2. If I use "OTEL_JAVAAGENT_EXCLUDE_CLASSES" to exclude this non-context executor, will it stop instrument this async call? I feel this might be good for us now if it works

A bit more details about this non-context executor.

1. The grpc context was dropped intentionally when entering this executor
2. A default/root grpc context is used in all threads of this non-context ececutor.

I assume several otel context creates a bridge to the same/default grpc context when multiple "non-context executor" threads are running. And we are seeing the same "Trade Id" leaks to different threads. So it is causing multiple issues, the question is how can we avoid all of them?

[laurit]

What will happen if there is this flag and a I turn off the "otel context through the grpc context"? Will it create a new trace for each async all or it will not instrument each async call?

Probably context will stop propagating into grpc callbacks. You could examine the failing tests in https://github.com/open-telemetry/opentelemetry-java-instrumentation/tree/main/instrumentation/grpc-1.6/javaagent after modifying https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/instrumentation/grpc-1.6/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/grpc/v1_6/GrpcContextInstrumentation.java to determine what is affected.

If I use "OTEL_JAVAAGENT_EXCLUDE_CLASSES" to exclude this non-context executor, will it stop instrument this async call? I feel this might be good for us now if it works

I don't know what you mean by non-context executor. Without a minimal sample app that reproduces the issue can't really tell whether excluding classes would work or not.

[junhuangli]

Sorry for the confusion. Here is a bit of code that shows the pattern. Each call to someOperation() would have request specific context in place, but the background processing would pick up the context from the first request and propagate it to all of the subsequent requests. Hope this helps :)

class BatchTogetherOperations {
private static class Task {
CompletableFuture future = new CompletableFuture<>();
}

private ScheduledExecutorService executor;
private boolean active = false;
private List<Task> tasks = new ArrayList<>();

public synchronized CompletableFuture<Void> someOperation() {
    Task task = new Task();
    tasks.add(task);

    if (!active) {
        executor.schedule(this::backgroundTask, 100, TimeUnit.MILLISECONDS);
        active = true;
    }
}

private synchronized List<CompletableFuture<Void>> getNextBatch() {
    List<CompletableFuture<Void>> tmp = tasks;
    tasks = new ArrayList<>();
    if (tmp.isEmpty()) active = false; // no need to continue background processing
    return tmp;
}

private void backgroundTask() {
    List<Task> batch = getNextBatch();
    if (batch.isEmpty()) return; // stop handling batches of tasks

    // do some common processing for the back of tasks

    for (var task : batch) task.future.complete();

    executor.schedule(this::backgroundTask, 100, TimeUnit.MILLISECONDS);
}

}

[laurit]

does it work better when you use

try (Scope ignored = Context.root().makeCurrent()) {
  executor.schedule(this::backgroundTask, 100, TimeUnit.MILLISECONDS);
}

in someOperation?

[junhuangli]

Could you explain a bit of this approach? The purpose is to avoid java agent propagating otel context into the executor thread?

[laurit]

Could you explain a bit of this approach? The purpose is to avoid java agent propagating otel context into the executor thread?

yes. By default context is propagated into ScheduledExecutorService.execute. If I understand your code correctly the result is that first time when someOperation is called the context is propagated to backgroundTask task method. Since the backgroundTask method also calls executor.schedule the same context is propagated there too. Without a minimal sample app that reproduces the issue it is hard to tell whether this will help or not.

[junhuangli]

Thanks @laurit , I will give it a try. On the other hand, could you briefly explain what is the purpose of this? So even if we don't explicitly propagate grpc context, this code will propagate the grpc context into the executor thread using the otel bridge automatically, right? Or do I misunderstand what it does?

[laurit]

Thanks @laurit , I will give it a try. On the other hand, could you briefly explain what is the purpose of this?

See https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/instrumentation/grpc-1.6/library/src/main/java/io/opentelemetry/instrumentation/grpc/v1_6/internal/ContextStorageBridge.java

So even if we don't explicitly propagate grpc context, this code will propagate the grpc context into the executor thread using the otel bridge automatically, right? Or do I misunderstand what it does?

yes