Console.time() generates two telemetry traces

[nulltoken]

Lib version:

• applicationinsights: 2.0.0

Given the following code

import { setup, defaultClient } from 'applicationinsights';
import { Contracts } from "applicationinsights";
import {
  Data,
  MessageData,
} from "applicationinsights/out/Declarations/Contracts";

const telemetryConsoleLogger = (envelope: Contracts.Envelope, _contextObjects?: {
  [name: string]: unknown;
}): boolean => {
  if (envelope.data.baseType !== "MessageData") {
    return true;
  }

  const data = envelope.data as Data<MessageData>;
  console.log("Logged: " + data.baseData.message);
  return true;
};

const sleep = (ms: number): Promise<void> => {
  return new Promise(resolve => setTimeout(resolve, ms));
}

void (async function () {
  setup("_your_ikey_")
    .setAutoCollectConsole(true, true)
    .start();

  defaultClient.addTelemetryProcessor(telemetryConsoleLogger);

  console.log("Hello")
  console.time("Test")
  await sleep(150)
  console.timeEnd("Test")
  console.log("Goodbye")
})();

The following is dumped in the console.

ApplicationInsights:An invalid instrumentation key was provided. There may be resulting telemetry loss [ '_your_ikey_' ]
Logged: Hello
Hello
Logged: Test: 153.578ms   # <-- Here.
Logged: Test: 155.478ms
Test: 155.478ms
Logged: Goodbye
Goodbye

I'm not sure why Logged: Test: 153.578ms goes through the telemetry processor, but that looks like an unexpected behavior.

This has been discovered while going through Azure ApplicationInsights logs and generates quite a bit of pollution...

[hectorhdzg]

This by design node-diagnostic-channel will send telemetry for time and timeEnd methods in the console https://github.com/microsoft/node-diagnostic-channel/blob/master/src/diagnostic-channel-publishers/src/console.pub.ts#L41

[nulltoken]

@hectorhdzg Thanks for the feedback.

However, I'm not sure to understand why a call to time() generates a trace entry. The spec (https://console.spec.whatwg.org/#timing) only defines calls to Printer for timeLog and timeEnd.

Any chance you could please explain the rationale to make time generate a trace entry when the same method doesn't send anything to the standard console output?

[hectorhdzg]

That functionally had been there for a while, I don't know the rationale used several years ago unfortunately as I was not part of that discussion, the problem now is that is someone is relying on this and we remove it they will be missing telemetry and would be a breaking change for them.