Automatically tracked dependencies are tracked _twice_ from time to time

[nulltoken]

:wave:,

We're building a product which acts as a reverse proxy and relays incoming requests to remote backends. Everything is instrumented through ApplicationInsights SDK for Nodejs (https://github.com/microsoft/ApplicationInsights-node.js).

We've just discovered a weird behavior. While analyzing the telemetry stored in ApplicationInsights, for a very small percentage (0.07%) of the traffic, it looks like the calls to the backends are tracked twice.

When that happens, the vast majority of this duplicate tracks shows one successful dependency call, and one failed dependency call. However, one can also find entries with two successful dependency calls or two failed ones.

Those duplicate entries bear the same dependency.timestamp, dependency.id, ... but usually their duration differs by few milliseconds.

Although the numbers seem low, this is quite annoying from a monitoring standpoint (false positives, ...).

Unfortunately, we haven't been unable to create a small scale repro case.

How can we proceed further? Would it be possible to set up a screen sharing session so that we could demonstrate the finding?

In order to help move the ball further, below are three "proofs" of those behaviors, extracted from our ApplicationInsights instance. Some of the data has been redacted, it should help share what we actually encounter.

2.failed.dependencies.txt 2.successful.dependencies.txt 1.fail.and.1.successful.dependencies.txt

/cc @hectorhdzg

[nulltoken]

@hectorhdzg I know there's not a lot of meat in this issue. However, it keeps on happening. How could we try and tackle this?

[hectorhdzg]

@nulltoken sorry for late reply, are you manually or automatically tracking the dependencies?, if automatically from where the telemetry is coming from? HTTPs library? Azure SDK? the fact that duration is different means is not exactly a duplicate, can you share your setup of the SDK? this kind of issues are usually pretty hard to pin down but we can try.

[nulltoken]

@hectorhdzg Thanks for the response.

are you manually or automatically tracking the dependencies?

Automatically

if automatically from where the telemetry is coming from? HTTPs library? Azure SDK?

Mostly Got and Azure SDK as well (to read blobs from storage accounts)

Can you share your setup of the SDK?

Below the extended setup

  AppInsights.setup(config.get('appinsights_key'))
    .setAutoCollectConsole(true, true)
    .setDistributedTracingMode(AppInsights.DistributedTracingModes.AI_AND_W3C);

  const commitSha = config.get('commitSha');
  const instanceId = config.get('instanceId');

  AppInsights.defaultClient.commonProperties = {
    Environment: config.get('env'),
    InstanceId: instanceId,
    CommitSha: commitSha,
    BuildAt: config.get('buildAt'),
    DeployedAt: new Date().toISOString()
  };

  AppInsights.defaultClient.context.tags[AppInsights.defaultClient.context.keys.applicationVersion] = commitSha;
  AppInsights.defaultClient.context.tags[AppInsights.defaultClient.context.keys.cloudRoleInstance] = instanceId;

  AppInsights.defaultClient.addTelemetryProcessor(AuthTelemetryProcessor);
  AppInsights.defaultClient.addTelemetryProcessor(RoutingTelemetryProcessor);
  AppInsights.defaultClient.addTelemetryProcessor(RequestHeadersTelemetryProcessor);
  AppInsights.defaultClient.addTelemetryProcessor(DependencyHeadersTelemetryProcessor);

  AppInsights.start();

this kind of issues are usually pretty hard to pin down but we can try.

Awesome <3

[nulltoken]

@hectorhdzg What would be the next steps according to you?

[hectorhdzg]

@nulltoken in failed dependencies log you shared, both events are the same except the custom properties, one have "headers.out" and the other doesn't, I guess you are adding that in one of the telemetryProcessors you have in there, can you share more details about it? also which version of node.js runtime are you using?, I suspect the problem could be related to the events we listen in the HTTP request, so is it important to check which events are available in your environment.

[hectorhdzg]

@nulltoken is this still an issue for you?, can you share more details

[nulltoken]

@hectorhdzg Sorry for the delay. I've completely missed your message from March, 15th. I'll come back to you in the following days with some answers.

[nulltoken]

@hectorhdzg Below the requested information

also which version of node.js runtime are you using?

Node v16.17.0

in failed dependencies log you shared, both events are the same except the custom properties, one have "headers.out" and the other doesn't, I guess you are adding that in one of the telemetryProcessors you have in there, can you share more details about it?

dependencyHeaders.js:

'use strict';

const { cleanAuth } = require('./cleanAuth');
const { filterAIHeadersFrom } = require('./utils');

module.exports = function (envelope, context) {

  if (envelope.data.baseType !== 'RemoteDependencyData') {
    return true;
  }

  const clientRequest = context['http.ClientRequest'];

  if (!clientRequest) {
    return true;
  }

  const props = envelope.data.baseData.properties;

  const headers = filterAIHeadersFrom(clientRequest.getHeaders());

  props['headers.in'] = JSON.stringify(cleanAuth(headers));

  const nodeHttpResponse = context['http.ClientResponse'];

  if (!nodeHttpResponse) {
    return true;
  }

  props['headers.out'] = JSON.stringify(cleanAuth(nodeHttpResponse.headers));

  return true;
};

where

• filterAIHeadersFrom removes 'request-context', 'request-id', 'x-ms-request-id', 'x-ms-request-root-id' from headers
• cleanAuth obfuscates content of headers known to hold sensitive information

[nulltoken]

@hectorhdzg We've just discovered that we've got "reproducible" duplicates. Would you be interested in taking a peek, we'd be happy to setup a screen share.

[nulltoken]

@hectorhdzg Just confirmed that the change fixed our duplicate issue as well.

Tons of thanks !

:heart: