trackException in express middleware doesn't get correlation context when using autoCorrelation

[alitheg]

I've got an express app set up like this:

const Promise = require('bluebird');
global.Promise = Promise;
Promise.longStackTraces();
require('./application-insights.js');
const express = require('express');
const app = express();

app.use(require('./middleware/logging.js'));

app.use('/version', require('./routes/version.js'));

app.use('/auth', require('./routes/auth.js'));
app.use('/user', require('./routes/user.js'));

app.use(require('./middleware/not-found.js'));
app.use(require('./middleware/error-handler.js'));

const port = config.get('port');
app.listen(port, () => log.info('server started', {port}));

./application-insights.js sets up the library like this:

const config = require('config');
const appInsights = require('applicationinsights');
const log = require('./logging.js')('application-insights');

let appInsightsConfig = config.get('applicationInsights');
if (config.has('applicationInsights.key')) {
    let key = appInsightsConfig.key;
    appInsights
        .setup(key)
        .setAutoCollectRequests(true)
        .setAutoCollectPerformance(true)
        .setAutoCollectExceptions(true)
        .setAutoCollectConsole(true)
        .setAutoDependencyCorrelation(true)
        .start();
} else {
    log.info('Application Insights error reporting is disabled');
}

module.exports = appInsights;

And the error handler middleware does this:

const log = require('../logging.js')('server');
const {UnauthorizedError} = require('express-jwt');
const applicationinsights = require('../application-insights.js');

module.exports = (err, req, res, next) => {
    res._error = true;
    if (res.headersSent) {
        log.error({err, req, res});
        applicationinsights.defaultClient.trackException({exception: err});
        return next(err);
    }
    if (err instanceof UnauthorizedError) {
        log.debug('unauthorized', {err});
        return res.status(401).json({message: 'Unauthorized'});
    } else {
        res.status(500).json({message: 'Internal Server Error'});
    }

    log.error({err, req, res});
    if (applicationinsights.defaultClient) {
        applicationinsights.defaultClient.trackException({exception: err});
    }
};

However, while I see requests and exceptions coming through in the Azure portal, they're not correlated together. I've tried debugging through the tracking calls, and it seems that in the trackException call, the call to getTag in the message envelope:

private static getTags(context: Context, tagOverrides?: { [key: string]: string; }) {
        var correlationContext = CorrelationContextManager.getCurrentContext();

returns a null correlationContext. I'm sure I'm doing something wrong, but I can't figure out what!

[markwolff]

Which version of the SDK are you using? I'm unable to repro this locally with this sample app.

const Promise = require('bluebird');
global.Promise = Promise;
Promise.longStackTraces();

const appInsights = require('applicationinsights');
appInsights.setup('ikey')
  .setSendLiveMetrics(true)
  .start();

const express = require('express');
const app = express();

app.get('/', (req, res) => {
  console.log(appInsights.getCorrelationContext());
  throw new Error();
});

app.use((err, req, res, next) => {
  console.log(appInsights.getCorrelationContext());
  res.sendStatus(500);
});

app.listen(3000);

There may be an issue with async stuff however, in which case you would need to bind the current context to any new async operations (appInsights.wrapWithCorrelationContext(yourCallback)). You can log out the context in your async operations and see if its propagating as expected.

[alitheg]

It's v1.5.0. I'll take a look at the sample and try adding some getCorrelationContext calls into my code to see where it gets lost. Thanks!

[shatodj]

I have the same problem... It's lost immediately :(

index.js

const appInsights = require('applicationinsights');

appInsights.setup(process.env.APPINSIGHTS_INSTRUMENTATIONKEY)
  .setAutoDependencyCorrelation(true, true)
  .setAutoCollectRequests(true)
  .setAutoCollectPerformance(true)
  .setAutoCollectExceptions(true)
  .setAutoCollectDependencies(true)
  .setAutoCollectConsole(true, true)
  .setUseDiskRetryCaching(true)
  .setSendLiveMetrics(true)
  .start();

console.log('CONTEXT', appInsights.getCorrelationContext()); // null :(

    "apollo-datasource-rest": "^0.5.0",
    "apollo-server-azure-functions": "^2.6.8",
    "apollo-server-core": "latest",
    "applicationinsights": "^1.7.2",
    "azure-functions-core-tools": "^2.7.1585"

Using Azure function. So all dependencies and exceptions in AppInsights are with no operation_id.

[alitheg]

It's v1.5.0. I'll take a look at the sample and try adding some getCorrelationContext calls into my code to see where it gets lost. Thanks!

It seems to be an issue with the promise chain calling out to the database. I've been able to get a context for most of my errors by wrapping all of the calls to next, from my database middleware and from the route catch handlers (ie. .catch(appInsights.wrapWithCorrelationContext(next));)

[Mike-Fink-Jr]

I have the same problem... It's lost immediately :(

index.js

const appInsights = require('applicationinsights');

appInsights.setup(process.env.APPINSIGHTS_INSTRUMENTATIONKEY)
  .setAutoDependencyCorrelation(true, true)
  .setAutoCollectRequests(true)
  .setAutoCollectPerformance(true)
  .setAutoCollectExceptions(true)
  .setAutoCollectDependencies(true)
  .setAutoCollectConsole(true, true)
  .setUseDiskRetryCaching(true)
  .setSendLiveMetrics(true)
  .start();

console.log('CONTEXT', appInsights.getCorrelationContext()); // null :(

    "apollo-datasource-rest": "^0.5.0",
    "apollo-server-azure-functions": "^2.6.8",
    "apollo-server-core": "latest",
    "applicationinsights": "^1.7.2",
    "azure-functions-core-tools": "^2.7.1585"

Using Azure function. So all dependencies and exceptions in AppInsights are with no operation_id.

running into the same issue, I need to create a correlating context outside of express (in a MQ) and all examples just assume a context is already created and getCorrelationContext() just returns null @shatodj did u figure this out

[shatodj]

Hey @Mike-Fink-Jr . YES. We used appInsights.wrapWithCorrelationContext function that will provide the correlation context for us. So we created our own wrapper function like this:

const appInsights = require("applicationinsights");

const withCorrelationContext = (invocationContext, req) => (handler) => {
    // Start an AI Correlation Context using the provided Function context
    const correlationContext = appInsights.startOperation(invocationContext, req);

    // Wrap the Function runtime with correlationContext
    return appInsights.wrapWithCorrelationContext(() => handler(invocationContext, req), correlationContext)();
}

const runHandler = (context, request) => {
    // our azure function intergation
}

module.exports = {
  run: (context, req) => withCorrelationContext(context, req)(runHandler),
};

I hope that helps.

[chriskuech]

getCorrelationContext is returning null for us as well. What is very frustrating is that this is not expected according to the types. We cannot use the proposed mitigations because we aren't using Azure Functions.