microsoft / ApplicationInsights-node.js

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

[Beta] Error that @azure/core-tracing is loaded before @azure/opentelemetry-instrumentation-azure-sdk #1107

Open marcus13371337 opened 1 year ago

marcus13371337 commented 1 year ago

Hello,

I'm using the latest beta-version of this package, however, on startup, I'm getting the following error:

ApplicationInsights:@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'
]

I don't have those packages as a dependency, and I don't import/require them anywhere, so I guess the error originates from this package. Is this a bug?

MikaelEdebro commented 1 year ago

I got the same warning when trying out the beta package.

dariusmb commented 1 year ago

Hello. I get the same error.

Are there any updates on this?

hectorhdzg commented 1 year ago

This is not an error just a warning, Azure SDK auto instrumentation should be functional even if the warning is triggered, please ignore for now, this warning would be gone once we add a LogExporter and remove internal @azure package dependencies in this project

ericis commented 10 months ago

This is not an error just a warning, Azure SDK auto instrumentation should be functional even if the warning is triggered, please ignore for now, this warning would be gone once we add a LogExporter and remove internal @Azure package dependencies in this project

@hectorhdzg this actually appears in my program's output. We are generating a Node CLI that uses command telemetry through the SDK. So, this so-called "warning" is not simply output to logs on a server, but actually written out to the console whenever any command is executed.

How can we avoid this?

hectorhdzg commented 10 months ago

@ericis this is an internal log, so you should be able to control it changing the log level, you can also change the log destination to be file and console would not be written.

https://github.com/microsoft/ApplicationInsights-node.js/tree/beta?tab=readme-ov-file#self-diagnostics

ericis commented 10 months ago

Thank you @hectorhdzg . It seems it is not possible to override the logging in the usual way.

I was surprised that the "@azure/monitor-opentelemetry" package has it's own InternalAzureLogger and doesn't seem to make use of the existing "@azure/logger" instance.

As a result, there are THREE logging overrides to be successful while using the "@azure/opentelemetry-instrumentation-azure-sdk" library.

Override "@opentelemetry/api" logging

import api, {
  DiagLogger,
  DiagLoggerOptions,
} from '@opentelemetry/api'

const openTelemetryLogger: DiagLogger = {
  debug: (message: string, ...args: unknown[]) => {
    // no-op example
  },
  error: (message: string, ...args: unknown[]) => {
    // no-op example
  },
  info: (message: string, ...args: unknown[]) => {
    // no-op example
  },
  verbose: (message: string, ...args: unknown[]) => {
    // no-op example
  },
  warn: (message: string, ...args: unknown[]) => {
    // no-op example
  },
}

const openTelemetryLoggerOptions: DiagLoggerOptions = {
  suppressOverrideMessage: true,
}

api.diag.setLogger(openTelemetryLogger, openTelemetryLoggerOptions)

Override "@azure/logger" logging

import { AzureLogger } from '@azure/logger'

AzureLogger.log = (...args: any[]) => {
  // no-op example
}

Override "@azure/opentelemetry-instrumentation-azure-sdk" logging

This is not currently possible. Instead, all warnings have to be ignored in order to ignore this one message or logging has to be redirected to an output file in order to suppress it from the console.

This is inconsistent with the OpenTelemetry logging and Azure SDK logging solutions and does not provide the developer with enough control.

process.env.APPLICATIONINSIGHTS_INSTRUMENTATION_LOGGING_LEVEL = "INFO";
process.env.APPLICATIONINSIGHTS_LOG_DESTINATION = "file";
process.env.APPLICATIONINSIGHTS_LOGDIR = "C:/applicationinsights/logs";
ericis commented 10 months ago

Given the current limitations of the "@azure/opentelemetry-instrumentation-azure-sdk" logging, I was able to workaround this issue with a fairly significant flaw that logging details will be treated very differently for this specific library than anything else in the application. This also limits our future ability to redirect these log entries and mandates that the developers are all aware that there is a separate "appinsights" log file for the application.

// map to AppInsights-specific log levels
const getAppInsightsLogLevel = (logLevel: LogLevel) => {
  // NONE, ERROR, WARN, INFO, DEBUG, VERBOSE and ALL
  // https://github.com/microsoft/ApplicationInsights-node.js/tree/beta?tab=readme-ov-file#self-diagnostics
  switch (logLevel) {
    case LogLevel.debug:
      return 'DEBUG'
    case LogLevel.error:
      return 'ERROR'
    case LogLevel.info:
      return 'INFO'
    case LogLevel.warn:
      return 'WARN'
    default:
      return 'NONE'
  }
}

// BUG: AppInsights and Azure OpenTelemetry do not offer the ability to
//      override logging. As a result, the only option to prevent log
//      details from "spilling" into the console is to send it to a file.
//      Of course, this also results in important information like Errors
//      being sent to a separate log file with no ability to control how
//      they are reported.
const appInsightsLogFilePath = path.join(
  options.config.dataDir,
  'my-cli.appinsights.log'
)

process.env.APPLICATIONINSIGHTS_INSTRUMENTATION_LOGGING_LEVEL =
  getAppInsightsLogLevel(activeLogLevel)
process.env.APPLICATIONINSIGHTS_LOG_DESTINATION = 'file'
process.env.APPLICATIONINSIGHTS_LOGDIR = appInsightsLogFilePath
hectorhdzg commented 10 months ago

@ericis I'm a little bit confused about what is your specific need, we do in fact have multiple loggers involved, as we use both OpenTelemetry and Azure SDK packages in our SDK, I can see level works as expected when using application insights config, we do not support filtering out specific logs so there is no way to filter out the current warning without changing the level to error. Can you describe your scenario?, are you using other Azure SDKs and expecting to be able to override Azure SDK logger?, we are working on improving internal logging here, I can see we have some flaws but understanding your issue better could help us to include it as well.

ericis commented 10 months ago

@ericis I'm a little bit confused about what is your specific need, we do in fact have multiple loggers involved, as we use both OpenTelemetry and Azure SDK packages in our SDK, I can see level works as expected when using application insights config, we do not support filtering out specific logs so there is no way to filter out the current warning without changing the level to error. Can you describe your scenario?, are you using other Azure SDKs and expecting to be able to override Azure SDK logger?, we are working on improving internal logging here, I can see we have some flaws but understanding your issue better could help us to include it as well.

Thanks @hectorhdzg . Sorry for the confusion.

If I were to take a step back, while I can't speak for all developers, I might hypothesize that developer joy when using OpenTelemetry + Azure would be to assume that overriding the DiagLogger provided by OpenTelemetry would be sufficient to provide logging for the entire application and that Microsoft would internally wire-up logging like AzureLogger and Application Insights internal logging to behave accordingly. In other words, if a developer were to implement OpenTelemetry to send ALL logging to a single ReST web service endpoint, then all Microsoft Azure implementation code would assume to do the same thing.

However, I have some empathy toward the fact that AzureLogger is super generic (too generic) for overriding all Azure-related logging activities (except AppInsights in this case, which has its own internal logging solution and does not seem to even know about AzureLogger... which is odd to me by itself). I also have empathy toward the fact that AppInsights logging has to work independently of OpenTelemetry as well. For both of these, my personal suggestion would be to align the extensibility of these logging solutions to allow for developer control and overrides as well as to work toward a unified development interface for logging in much the same way that OpenTelemetry itself is still working toward a global standard. As a bonus, it would be great if Microsoft simply put it's weight behind the standard without any customization other than backwards-compatible "shims" for existing libraries.

hectorhdzg commented 10 months ago

Thanks @ericis for extra details, I created following PR related to that https://github.com/Azure/azure-sdk-for-js/pull/28183

JPStrydom commented 1 month ago

I'm seeing similar logs that I suspect might be related to this issue.

We're using winston, winston-transport and applicationinsights. These are imported in the following order:

import { createLogger, format, transports } from 'winston';
import WinstonTransport from 'winston-transport';
import appInsights from 'applicationinsights';

And they are called in the following order:

export const logger = createLogger({
  level: 'info',
  format: format.combine(format.splat(), format.simple()),
  transports: [new transports.Console()],
  silent: process.argv.includes('--silent')
});

Then

const severityMap = { error: 'Error', warn: 'Warning', info: 'Information' };

export class AzureAppInsightsTransport extends WinstonTransport {
  constructor(app) {
    super();
    this.appInsightsClient = this.getAppInsightsClient(app);
  }

  getAppInsightsClient(app) {
    const { instrumentationKey } = app.get('azureAppInsights');

    appInsights
      .setup(instrumentationKey)
      .setAutoCollectRequests(true)
      .setAutoCollectPerformance(false)
      .setAutoCollectExceptions(true)
      .setAutoCollectDependencies(false)
      .setAutoCollectConsole(true)
      .setAutoCollectPreAggregatedMetrics(false)
      .setSendLiveMetrics(false)
      .setInternalLogging(false, false)
      .enableWebInstrumentation(false)
      .start();

    return appInsights.defaultClient;
  }

  log({ message, level, ...properties }, callback) {
    const severity = severityMap[level] ?? severityMap.info;

    this.appInsightsClient.trackTrace({ message, severity, properties });

    callback();
  }
}

Then

logger.level = app.get('logLevel');
logger.add(new AzureAppInsightsTransport(app));

Whenever my application starts up, I get the following logs:

@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'
]
@opentelemetry/instrumentation-winston [
  'Module winston has been loaded before @opentelemetry/instrumentation-winston so it might not work, please initialize it before requiring winston'
]
@opentelemetry/instrumentation-winston [
  'Module winston has been loaded before @opentelemetry/instrumentation-winston so it might not work, please initialize it before requiring winston'
]
The 'logRecordProcessor' option is deprecated. Please use 'logRecordProcessors' instead. []

These are a bit annoying, as they pollute not only our console, but also our App Insights.

Is there a way we can avoid these logs, or do we need to wait for a fix?