microsoft / ApplicationInsights-node.js

Microsoft Application Insights SDK for Node.js
MIT License
325 stars 140 forks source link

Unable to integrate with Winston logger #1320

Open JPStrydom opened 6 months ago

JPStrydom commented 6 months ago

Issue

We're unable to get applicationinsights to communicate with our AppInsights instance via winston.

Versions

Tool Version
Node 20.12.0
NPM 10.5.2
applicationinsights 3.0.1
winston 3.13.0

Steps to reporduce

I've attached a minimum reproduceable example here: applicationinsights-winston-issue.zip

In the example, we currently have the following package.json file:

{
  "name": "applicationinsights",
  "version": "1.0.0",
  "main": "index.js",
  "scripts": {
    "test": "node index.js"
  },
  "keywords": [],
  "author": "",
  "license": "ISC",
  "description": "",
  "dependencies": {
    "applicationinsights": "^3.0.1",
    "winston": "^3.13.0"
  }
}

And the following index.js file:

let appInsights = require('applicationinsights');

appInsights.setup('<MY INSTRUMENTATION KEY>')
  .setAutoCollectRequests(true)
  .setAutoCollectPerformance(true, true)
  .setAutoCollectExceptions(true)
  .setAutoCollectDependencies(true)
  .setAutoCollectConsole(true, true)
  .setAutoCollectPreAggregatedMetrics(true)
  .setSendLiveMetrics(false)
  .setInternalLogging(false, true)
  .enableWebInstrumentation(false)
  .start()

const { createLogger, transports } = require('winston');

const logger = createLogger({
  transports: [new transports.Console()]
})

logger.info('Info Test');
logger.warn('Warn Test');
logger.error('Error Test');
  1. Install dependencies with npm i
  2. Run the file with npm t
  3. See the errors and logs in the terminal:

    npm t
    
    > applicationinsights@1.0.0 test
    > node index.js
    
    @azure/opentelemetry-instrumentation-azure-sdk [
      'Module @azure/core-tracing has been loaded before @azure/opentelemetry-instrumentation-azure-sdk so it might not work, 
    please initialize it before requiring @azure/core-tracing'
    ]
    Invalid metric name: "\ASP.NET Applications(??APP_W3SVC_PROC??)\Request Execution Time". The metric name should be a ASCII string with a length no greater than 255 characters. []
    Invalid metric name: "\ASP.NET Applications(??APP_W3SVC_PROC??)\Requests/Sec". The metric name should be a ASCII string with a length no greater than 255 characters. []
    Invalid metric name: "\Process(??APP_WIN32_PROC??)\Private Bytes". The metric name should be a ASCII string with a length no greater than 255 characters. []
    Invalid metric name: "\Memory\Available Bytes". The metric name should be a ASCII string with a length no greater than 255 characters. []
    Invalid metric name: "\Processor(_Total)\% Processor Time". The metric name should be a ASCII string with a length no greater than 255 characters. []
    Invalid metric name: "\Process(??APP_WIN32_PROC??)\% Processor Time". The metric name should be a ASCII string with a length no greater than 255 characters. []
    Accessing resource attributes before async attributes settled []
    Extended metrics are no longer supported. Please reference the Azure Monitor OpenTelemetry Migration Doc for more information. If this functionality is required, please revert to Application Insights 2.X SDK. []
    {"level":"info","message":"Info Test"}
    Accessing resource attributes before async attributes settled []
    {"level":"warn","message":"Warn Test"}
    Accessing resource attributes before async attributes settled []
    {"level":"error","message":"Error Test"}
    Accessing resource attributes before async attributes settled []
    Accessing resource attributes before async attributes settled []
    Accessing resource attributes before async attributes settled []
  4. See that no logs are sent to Azure AppInsights image

What else we've tried

We've also tried manually sending the logs to AppInsights with:

const { TelemetryClient } = require('applicationinsights');
const { Writable } = require('stream');

const appInsights = new TelemetryClient('<MY INSTRUMENTATION KEY>');

const stream = new Writable({
  write: message => {
    appInsights.trackTrace({ message: message.toString() });
  }
});

const { createLogger, transports } = require('winston');

const logger = createLogger({
  transports: [new transports.Console(), new transports.Stream({ stream })]
})

logger.info('Info Test');
logger.warn('Warn Test');
logger.error('Error Test');

When running like this, then we get the following logs: image

This appears to work, but then we get an additional info log (bottom of the above example image) and a few of the Accessing resource attributes before async attributes settled [] error logs (top and 2nd from the bottom of the above example image) as well.

This solution also requires us to install the stream package, which is not ideal.

How to fix?

We are receiving logs from our other applications, so AppInsights appears to be working, but we're unable to communicate via Winston from on NodeJS app.

How can we go about integrating with Winston?

JacksonWeber commented 6 months ago

@JPStrydom I was able to fix your example by modifying your index.js to be the following:

let appInsights = require('applicationinsights');

appInsights.setup("your-instrumentation-key")
  .setAutoCollectRequests(true)
  .setAutoCollectPerformance(true, true)
  .setAutoCollectExceptions(true)
  .setAutoCollectDependencies(true)
  .setAutoCollectConsole(true, true)
  .setAutoCollectPreAggregatedMetrics(true)
  .setSendLiveMetrics(false)
  .setInternalLogging(false, true)
  .enableWebInstrumentation(false)
  .start()

const { createLogger, transports } = require('winston');

const logger = createLogger({
  transports: [new transports.Console()]
})

async function test () {
  logger.info('Info Test');
  logger.warn('Warn Test');
  logger.error('Error Test');
  await appInsights.defaultClient.flush();
}

test();

The modification just ensures that the application waits to exit until the Application Insights SDK has gotten a chance to export the Winston logs. Please let me know if this example makes sense or if you have any other questions. Thanks!

JPStrydom commented 6 months ago

Hi @JacksonWeber !

Thanks for taking the time to reach out.

I tried your example and I managed to get a few logs, but still received many of the error logs: image

Was your thinking that the client needs to be flushed after every log? I'm just scared that this makes our logging asynchronous, which we've not currently catered for.

JacksonWeber commented 6 months ago

@JPStrydom It's great you were able to see the Winston logs! Those other logs you're seeing are warnings and they come from a few sources. The "accessing resource attributes" warning is from OpenTelemetry and reports this warning because we have a VM resource detector that makes an API call to a VM metadata service. Given that you're not running in that environment, the call times out, but using the SDK before that timeout generates this warning for now. It won't impact functionality for you.

The warning regarding extended metrics is because you're attempting to set a configuration option that used to modify the behavior of collection of extended metrics. However, like the warning mentions, we don't support extended metrics in versions greater than or equal to 3.0.0.

JPStrydom commented 6 months ago

Hi @JacksonWeber

Thanks again!

Given the setup config we have:

  .setAutoCollectRequests(true)
  .setAutoCollectPerformance(true, true)
  .setAutoCollectExceptions(true)
  .setAutoCollectDependencies(true)
  .setAutoCollectConsole(true, true)
  .setAutoCollectPreAggregatedMetrics(true)
  .setSendLiveMetrics(false)
  .setInternalLogging(false, true)
  .enableWebInstrumentation(false)

Is there anything we need to change to get rid of the errors/warnings you mentioned?

I'd also just like some clarification on when exactly we need to call the appInsights.defaultClient.flush() function:

JacksonWeber commented 6 months ago

@JPStrydom For removing the extended metrics warning, simply change .setAutoCollectPerformance(true, true) to .setAutoCollectPerformance(true). You'll still auto collect performance counters, but the second parameter is for setting auto collection of extended metrics (which isn't supported).

As for the resource attributes warning, this isn't currently ignorable because we turn on resource detection by default for popular Azure Resources.

Regarding on when to use flush(). It entirely depends on your application. If Node.js process flow ends quickly after a call to log telemetry, then it may make sense to await a flush() however, in most cases, such as a long running Node.js server application there typically isn't any need to asynchronously await a flush.

JacksonWeber commented 5 months ago

@JPStrydom Please let me know if this has been able to resolve your issue, thanks!

JPStrydom commented 5 months ago

@JPStrydom Please let me know if this has been able to resolve your issue, thanks!

We've temporarily paused development on the AppInsights integration, but as soon as we resume, I'll test and let you know. Thanks!