[Winston] Metadata passed through child logger isn't showing in Application Insights customDimensions

[sawyerh]

Environment:

• winston - Version 3.2.1
• applicationinsights - Version 1.3.1
• Node 10.15.3

Our application is using Winston's "child loggers" feature to set metadata defaults on each trace. Below is an example:

// Setup Application Insights
const appInsights = require("applicationinsights");
appInsights
        .setup(process.env.APPINSIGHTS_INSTRUMENTATIONKEY)
        .setAutoDependencyCorrelation(false)
        .start();

...

// Setup Winston
const winston = require("winston");
const logger = winston.createLogger({
      format: winston.format.json()
})

logger.add(new winston.transports.Console())

...

// Create a child logger so subsequent logs include the DB record IDs
const childLogger = logger.child({
    caseIndexingInfoId: caseIndexingInfo.id,
    fileUploadId: fileUpload.id
})

...

// Call the child logger and pass additional metadata
childLogger.info("Processing upload", { storagePath, contentType })

Expected result

Given the above, I would expect to see a trace recorded in Application insights with the following as the customDimensions shape:

{
  "caseIndexingInfoId": "123",
  "fileUploadId": "456",
  "storagePath": "bar.jpeg",
  "contentType": "image/jpeg",
}

Actual result

• The expected data is getting logged to my console
• However, the trace in Application Insights is not showing the metadata defined on the child logger.

What I see in my console:

{
  "caseIndexingInfoId": "123",
  "fileUploadId": "456",
  "storagePath": "bar.jpeg",
  "contentType": "image/jpeg",
  "level": "info",
  "message": "Processing upload"
}

But this is what I see in Application Insights (notice that caseIndexingInfoId and fileUploadId are missing from customDimensions:

[markwolff]

This is happening because winston's logger.child implementation is not doing all of the SPLAT stuff that the default logger does for metadata. This seems like an inconsistency on winston's part, but since it is not a bug, I doubt it will be fixed. I will rework how I grab the metadata in the next update. For now you can replace our winston logger patch with this Transport and disable winston patching via the environment variable.

// App Insights setup
const appInsights = require('applicationinsights');
appInsights.setup('')
.setInternalLogging(true,true)
.start();
appInsights.defaultClient.config.maxBatchSize = 1;

// Require in Winston 3.x
var winston = require('winston');
var {createLogger, transports, loggers} = winston;

// App Insights custom Transport
class AppInsightsTransport extends winston.Transport {
  constructor(winston, client, opts) {
    super(opts);
    this.winston = winston;
    this.client = client;
  }

  mapLevelToKind(winston, level) {
    let levelKind;
    if (winston.config.npm.levels[level] != null) {
      levelKind = "npm";
    } else if (winston.config.syslog.levels[level] != null) {
      levelKind = "syslog";
    } else {
      levelKind = "unknown";
    }
    return levelKind;
  };

  log(info, callback) {
    const {message, level} = info;
    const levelKind = this.mapLevelToKind(this.winston, level);
    const meta = {};

    const { level, message, ...splat } = info;
    for (const key in splat) {
        meta[key] = splat[key];
    }

    this.client.trackTrace({message: `${level}: ${message}`, properties: meta});
    callback();
  }
}

// Create the loggers
const myLogger = createLogger({
  level: 'info'
});
loggers.add('MY', myLogger);
loggers.options.transports = [new AppInsightsTransport(winston, appInsights.defaultClient)];

const logger = loggers.get('MY');
logger.info('hello world');

[sawyerh]

This is happening because winston's logger.child implementation is not doing all of the SPLAT stuff that the default logger does for metadata. This seems like an inconsistency on winston's part, but since it is not a bug, I doubt it will be fixed.

@markwolff If you have the info handy, can you share more details about this, or a reference to where this is in their codebase? I'm open to creating a pull request on the Winston side if it's feasible. I just might need a little more details about what you're describing here.

[markwolff]

@sawyerh For a typical logging situation, there is more complexity in how it handles the metadata field, as per:
https://github.com/winstonjs/winston/blob/8423c03c59c31f61f57519b4097420a464c90f83/lib/winston/logger.js#L227-L257

Compare this to the child logging process, where it simply copies the object over, but misses out on all of the splat stuff. I'm not sure if this was intentionally left out though.
https://github.com/winstonjs/winston/blob/8423c03c59c31f61f57519b4097420a464c90f83/lib/winston/logger.js#L45-L55

[markwolff]

Updating this thread to mention that I fixed this on our end here. It will land in 1.4.0 in a week or so. This PR on winston's end might also fix it: winstonjs/winston#1598

[maverick1872]

Updating this thread to mention that I fixed this on our end here. It will land in 1.4.0 in a week or so. This PR on winston's end might also fix it: winstonjs/winston#1598

@markwolff, glad to see I'm not the only one who ran into this issue. I'm hoping to get my PR on Winston cleaned up and ready for re-approval this weekend if life allows. That being said I'm not super familiar with the SPLAT functionality and if you want to help verify that's working on the child/root once I get my PR up it would be greatly appreciated!

[markwolff]

Closing this as the fix is already released. You can just reinstall this SDK to pick up the latest version of diagnostic-channel-publishers

[sawyerh]

@markwolff Unfortunately, diagnostic-channel-publishers is locked to 0.3.0 in the latest release of applicationinsights, so reinstalling the SDK doesn't bump it to 0.3.2, and adding diagnostic-channel-publishers@0.3.2 as project dependency doesn't seem to do the trick either: 5a3c406#diff-b9cfc7f2cdf78a7f4b91a753d10865a2

[sawyerh]

@markwolff Sorry to pester you – any idea when 1.4.0 is landing? The issue mentioned in my previous comment is preventing me from inheriting the bug fix applied in diagnostic-channel-publishers

[markwolff]

Hey sorry for the delays. I'm aiming for Monday.