ThreadContext.getRequestTelemetryContext().getRequestTelemetry().setDuration() is not supported by the Application Insights for Java 3.x agent

[rangarnow]

Expected behavior

ThreadContext.getRequestTelemetryContext().getRequestTelemetry().setDuration() method is invoked without errors resulting changed duration of request.

This is needed, because we are receiving message which is then processed asynchronously. Then we have subscribe on Mono result, so in fact I would like to see real time of processing (including subscribe invocation), that's why the need to modify duration of the request programatically.

There is an example code showing my problem and workaround I try to have with ThreadContext.getRequestTelemetryContext().getRequestTelemetry().setDuration():

public void processMessage() {
   long startTime = System.currentTimeMillis();
   RequestTelemetryContext telemetryContext = ThreadContext.getRequestTelemetryContext();
   RequestTelemetry requestTelemetry = telemetryContext.getHttpRequestTelemetry();

   someAsyncTask().subscribe(data -> {
      long endTime = System.currentTimeMillis();
      requestTelemetry.setDuration(new Duration(endTime - startTime)); // Warning is thrown, has no effect

      // This works, but I would like to have parent request with real time, not a dependency
      RemoteDependencyTelemetry telemetry = new RemoteDependencyTelemetry();
      telemetry.setId(requestTelemetry.getId());
      telemetry.setName("Processing time 2");
      telemetry.setDuration(new Duration(endTime - startTime));
   });     
}

Effect:

If you have any other idea how to make ServiceBus.process (other than via setting Duration) to take the same time as "Processing time 2" it would be welcome.

I tried also with open telemetry API (given #1442 (comment)), but still no luck:

Span currentSpan = Span.current();
SpanContext spanContext =
                SpanContext.createFromRemoteParent(
                        currentSpan.getSpanContext().getTraceId(), currentSpan.getSpanContext().getSpanId(), TraceFlags.getDefault(), TraceState.getDefault());
try (Scope scope = Context.root().with(Span.wrap(spanContext)).makeCurrent()) {
   Span.current().end();
}

Actual behavior

An error occur when trying to execute this method. This also occur for other methods, like setResponseCode() etc.:
ThreadContext.getRequestTelemetryContext().getRequestTelemetry().setDuration() is not supported by the Application Insights for Java 3.x agent (this message will only be logged once)

To Reproduce

• use Java program with latest application insights jar 3.4.7,
• import these dependencies to pom.xml:

        <dependency>
            <groupId>com.microsoft.azure</groupId>
            <artifactId>applicationinsights-core</artifactId>
            <version>3.4.7</version>
        </dependency>
        <dependency>
            <groupId>com.microsoft.azure</groupId>
            <artifactId>applicationinsights-web</artifactId>
            <version>3.4.7</version>
        </dependency>

Sample Application

System information

Logs

Screenshots

[trask]

hi @rangarnow!

can you post a small repro of your issue (including the service bus sdk)? I'd like to look at it to see how best to solve this issue.

even if you could call "setDuration", the request would have already been ended/exported, and so it would have no real effect.

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 7 days. It will be closed if no further activity occurs within 7 days of this comment.

[rangarnow]

hi @trask, thank you for your response. I was on holidays so that's why no feedback from my side :) I will prepare today an example code to highlight my problem.

[rangarnow]

Service bus implementation details:

I am using Service Bus Processor as below:

ServiceBusProcessorClient processorClient = new ServiceBusClientBuilder()
                .connectionString(...)
                .processor()
                .queueName(...)
                .processMessage(this::processMessage)
                .processError(this::processError)
                .receiveMode(ServiceBusReceiveMode.PEEK_LOCK)
                .maxConcurrentCalls(...)
                .disableAutoComplete()
                .maxAutoLockRenewDuration(...)
                .buildProcessorClient();

        processorClient.start();

Process message function (returns void):

this.executeAsyncTask(message)
                .publishOn(Schedulers.boundedElastic()) // because context.compelete is synchronous
                .subscribe(data -> {
                        context.complete();
                });

Time elapsed doesn't take into account context.complete() invocation, but instead it ends without waiting for async result to arrive resulting with different time than real context.complete() execution.

I've also checked pure Service bus async client and it's working almost fine.

The time calculated in Application Insights is almost correct, but it doesn't take into account last async invocations, can it be because of threads switching in reactor from bounded elastic to http reactor threads? I have an impression that when it switched from boundedElastic-1 to other threads, then context is not catched and in fact time calculated doesn't take this into account. Given nature of async programming, we shouldn't care about switching threads and I would like to minimalize forcing context switching to particular thread.

However I would like to use processor client, since it gives out of the box async wrapper utilities already where we can limit max concurrent calls etc.

Process message function returns Mono<T> in that case (pure async client)

        ServiceBusReceiverAsyncClient receiver = new ServiceBusClientBuilder()
                .connectionString(...)
                .receiver()
                .queueName(...)
                .disableAutoComplete()
                .maxAutoLockRenewDuration(...)
                .buildAsyncClient();

        Disposable subscription = receiver.receiveMessages()
                .flatMap(message -> this.processMessage(message)
                        .flatMap(data -> receiver.complete(message))
                )
                .subscribe(
                        (arg) -> System.out.println("Message processed.")
                );

        try {
            countdownLatch.await(100000, TimeUnit.DAYS);
        } catch (InterruptedException e) {
            e.printStackTrace();
        } finally {
            // Disposing of the subscription will cancel the receive() operation.
            subscription.dispose();

            // Close the receiver.
            receiver.close();
        }

Is there any way to make processor behave just like pure async client for Application Insights tracking?

To summarize:

• in processor it doesn't wait at all for final result to arrive. I tried to put subscribe logic to flatMap, but still (due to thread context switching?) it ends calculating time prematurely,
• in pure async client time is calculated well till the time I use blocking invocations. As long as I start invoking reactor flux with flat maps, it loses context and also time calculated doesn't take into account further async processing.

[rangarnow]

I think you are right that at the point I would like to call setDuration, request has been already ended so it has no real effect. I just don't know how to let it wait for async result and if that's even possible.

[trask]

@rangarnow can you post the full (runnable) example to a github repository? thx!