TelemetryClient keeps handles open

[alexg-axis]

When running some code in a test using the TelemetryClient, Jest detects open handles.

Here's a basic replication which causes the issue.

describe('telemetry', () => {
  // Requires the APPINSIGHTS_INSTRUMENTATIONKEY environment variable to be set
  test('replicate', async () => {
    const telemetryClient = new TelemetryClient()

    telemetryClient.trackMetric({ name: 'some_metric', value: 2 })

    // Wait for all logs to flush
    await new Promise((resolve) => {
      telemetryClient.flush({ callback: resolve })
    })
  })
})

If run using the --detectOpenHandles flag, the following error will be thrown.

Jest has detected the following 3 open handles potentially keeping Jest from exiting:

●  TCPWRAP

      42 |   // Requires the APPINSIGHTS_INSTRUMENTATIONKEY environment variable to be set
      43 |   test('replicate', async () => {
    > 44 |     const telemetryClient = new TelemetryClient()
         |                             ^
      45 |
      46 |     telemetryClient.trackMetric({ name: 'some_metric', value: 2 })
      47 |

      at Function.Object.<anonymous>.Util.makeRequest (../../node_modules/applicationinsights/Library/Util.ts:371:25)
      at Function.Object.<anonymous>.AzureVirtualMachine.getAzureComputeMetadata (../../node_modules/applicationinsights/Library/AzureVirtualMachine.ts:34:26)
      at ../../node_modules/applicationinsights/AutoCollection/Statsbeat.ts:332:44
      at Statsbeat.Object.<anonymous>.Statsbeat._getResourceProvider (../../node_modules/applicationinsights/AutoCollection/Statsbeat.ts:313:16)
      at Statsbeat.<anonymous> (../../node_modules/applicationinsights/AutoCollection/Statsbeat.ts:183:24)
      at step (../../node_modules/applicationinsights/out/AutoCollection/Statsbeat.js:33:23)
      at Object.next (../../node_modules/applicationinsights/out/AutoCollection/Statsbeat.js:14:53)
      at ../../node_modules/applicationinsights/out/AutoCollection/Statsbeat.js:8:71
      at Object.<anonymous>.__awaiter (../../node_modules/applicationinsights/out/AutoCollection/Statsbeat.js:4:12)
      at Statsbeat.Object.<anonymous>.Statsbeat.trackLongIntervalStatsbeats (../../node_modules/applicationinsights/out/AutoCollection/Statsbeat.js:190:16)
      at Statsbeat.Object.<anonymous>.Statsbeat.enable (../../node_modules/applicationinsights/AutoCollection/Statsbeat.ts:75:22)
      at NodeClient.TelemetryClient (../../node_modules/applicationinsights/Library/TelemetryClient.ts:50:29)
      at new NodeClient (../../node_modules/applicationinsights/out/Library/NodeClient.js:28:42)
      at Object.<anonymous> (tests/logging.test.ts:44:29)


  ●  TLSWRAP

      42 |   // Requires the APPINSIGHTS_INSTRUMENTATIONKEY environment variable to be set
      43 |   test('replicate', async () => {
    > 44 |     const telemetryClient = new TelemetryClient()
         |                             ^
      45 |
      46 |     telemetryClient.trackMetric({ name: 'some_metric', value: 2 })
      47 |

      at Function.Object.<anonymous>.CorrelationIdManager.queryCorrelationId (../../node_modules/applicationinsights/Library/CorrelationIdManager.ts:99:9)
      at Config.set (../../node_modules/applicationinsights/Library/Config.ts:115:30)
      at new Config (../../node_modules/applicationinsights/Library/Config.ts:103:34)
      at NodeClient.TelemetryClient (../../node_modules/applicationinsights/Library/TelemetryClient.ts:43:22)
      at new NodeClient (../../node_modules/applicationinsights/out/Library/NodeClient.js:28:42)
      at Object.<anonymous> (tests/logging.test.ts:44:29)


  ●  TLSWRAP

      42 |   // Requires the APPINSIGHTS_INSTRUMENTATIONKEY environment variable to be set
      43 |   test('replicate', async () => {
    > 44 |     const telemetryClient = new TelemetryClient()
         |                             ^
      45 |
      46 |     telemetryClient.trackMetric({ name: 'some_metric', value: 2 })
      47 |

      at Function.Object.<anonymous>.CorrelationIdManager.queryCorrelationId (../../node_modules/applicationinsights/Library/CorrelationIdManager.ts:99:9)
      at Config.set (../../node_modules/applicationinsights/Library/Config.ts:115:30)
      at new Config (../../node_modules/applicationinsights/Library/Config.ts:103:34)
      at new Statsbeat (../../node_modules/applicationinsights/AutoCollection/Statsbeat.ts:55:33)
      at NodeClient.TelemetryClient (../../node_modules/applicationinsights/Library/TelemetryClient.ts:49:31)
      at new NodeClient (../../node_modules/applicationinsights/out/Library/NodeClient.js:28:42)
      at Object.<anonymous> (tests/logging.test.ts:44:29)

I assumed this had to do with the use of a https.Agent internally and tried to specify one without any keep alive, but that didn't help.

const telemetryClient = new TelemetryClient()
telemetryClient.config.httpsAgent = new https.Agent({ keepAlive: false })

I also tried to call the dispose function from the package, but as suspected that didn't help. I assume it's only applicable when using the default client and appInsights.setup().

Is there any way to cleanly dispose of a TelemetryClient?

[jonthysell]

Have you tried disabling statsbeat? That's what was holding on to things in our jest tests.

https://github.com/microsoft/react-native-windows/pull/9801

Try disabling it via the environment variable:

set APPLICATION_INSIGHTS_NO_STATSBEAT=true

Related bug? https://github.com/microsoft/ApplicationInsights-node.js/issues/943

[alexg-axis]

At first, that didn't seem to work for me. Digging a bit deeper, it seems as if this might have been the culprit:

https://github.com/microsoft/ApplicationInsights-node.js/blob/c060888eb97d6a8d55366ebbfc49243f4f2794c4/Library/Config.ts#L118

And in turn, this part of the CorrelationIdManager:

https://github.com/microsoft/ApplicationInsights-node.js/blob/c060888eb97d6a8d55366ebbfc49243f4f2794c4/Library/CorrelationIdManager.ts#L49

My hunch was that this was done when first initializing the client and that it took some time, at the very least longer than my test took to complete.

I added a sleep at the end of the test for 5s to give the call some time (1s wasn't enough) and sure enough, the open handled went from being from the CorrelationIdManager to the Statsbeat class. Using your workaround for disabling it, no handles were left open.

I think the issue here is, in part, the one you already linked. But also, why there's no mechanism to either gracefully wait for the client to be up and running, or wait for the client to have fully flushed. My assumption is that flushing should require an id from the correlation manager and one could therefore argue that calling flush should wait for CorrelationIdManager.queryCorrelationId to complete.

[alexg-axis]

I tried to log the telemetryClient.config.correlationId right after having created it and then at the end of the test - and sure enough, it's empty ("cid-v1:") at first, but set in the end ("cid-v1:").

[jonthysell]

We had a workaround here to kill the CorrelationIdManager: https://github.com/microsoft/react-native-windows/commit/b6f8fd9bcab4e7d53467e35d2bc6892aec004bd2#diff-aee83d950f58adead81e3eb030b6e4af2d177e679cd9a2abd216e009ba2c3e0bL44

I took it out because the bug was supposed to be fixed, but now I'm seeing that my tests are flaky again.

[hectorhdzg]

Apparently, the open handles are basically HTTP requests that we send immediately when the TelemetryClient is instantiated, keepAlive=true in CorrelationIdManager was causing issues because the HTTP connection remain open for some time, even minutes, looks like in this case the test is faster than the actual HTTP call to be finished @alexg-axis if you wait one or two seconds is the handle gone?

[alexg-axis]

Yes, that seems as exactly what's going on here. Waiting for some seconds does let the CorrelationIdManager complete, thus closing the handle.

[hectorhdzg]

We could add a shutdown functionality in the TelemeryClient that actually wait for these requests, allowing you to wait for it on your tests, let me know if this will work for everyone, @alexg-axis, @jonthysell

[alexg-axis]

That sounds like a great solution for my use case at least.

[jonthysell]

Yes, an explicit shutdown function we could wait on would be great.

[rcbevans]

I was able to mitigate this by wrapping appInsights initialization in an env check, and then exporting the defaultClient from the module as TelemetryClient | undefined.

Setting all the options for automatic dependency collection etc to false didn't prevent the handle being opened.

I was hoping appInsights.dispose() would have cleaned up sufficiently.

[jordanchang]

Here is my code to disable AppInsights when running inside of Jest

if (!process.env.JEST_WORKER_ID) {
  console.log('Starting App Insights...')
  appInsights.setup().setAutoCollectConsole(true, true).start()
} else {
  console.log('Disabling App Insights since we are running in Jest...')
}

export const telemetryClient: TelemetryClient | null = appInsights.defaultClient

[DZwell]

☝️ This unblocked me.

[YasharHeydari]

Hi everyone, I'm not using the AppInsights or Telemetry directly, but I have a dev-dependency through office-add-in-usage-data which is part of different packages. Now in my Jest tests I'm getting the very same open handles due to CorrelationManager keeping handles open! Is there anyway I can get rid of this package entirely in Jest without initializing AppInsight or Telemetry objects?