ASB + Application Insights - all dependencies for sent mesages show as failed

[razvangoga]

• Package Name: @azure/service-bus
• Package Version: 7.3.0
• Operating system: Windows 10 21H1 19043.1110
• nodejs
  • version: 14.17.3 (LTS)
• browser
  • name/version:
• typescript
  • version:
• Is the bug related to documentation in
  • README.md
  • source code documentation
  • SDK API docs on https://docs.microsoft.com

Describe the bug

When using the Azure Service Bus package in conjunction with the Application Insights one, dependency log entries are captured for each message sent.

When sending messages to an ASB topic, although the message sending succeeds, the Application Insights dependency entry logged by the

See repro repo here

To Reproduce

• create new nodejs project
• add the following npm packages :
  • @azure/service-bus (currently v7.3.0)
  • applicationinsights (currently v2.1.4)
• initialize application insights
• send one message to an ASB topic
• check auto-logged application insights dependency

See repro repo here

Expected behavior

Application Insights dependency should be logged as successful if the message push to ASB succeeds

Screenshots

Additional context

[chradek]

@razvangoga Thanks for opening the issue and providing a repro!

I'm having some issues on my end running the repro project. I can see messages getting sent to service bus, and I can see that performance-related metrics (e.g. processor usage) are being sent to application insights, but I'm not seeing the dependency info getting logged. I tried uncommenting out some of the code you had commented out but haven't had luck.

Can you verify the repro works as is to demonstrate this issue? Is there some config I might be missing?

[razvangoga]

@chradek i've uncommented all the configs - not sure why without them the the logs were not pushed. In any case, the processor added at line 21 dumps the log item to console, and in it it's visible that the dependency is marked as failed

i've updated the repo

[razvangoga]

one thing to keep in mind is that Application Insights does have sometimes lag in processing and displaying logged items (up to a few minutes 3, 5... )

[chradek]

Hey @razvangoga
I've been trying to get your repro to work locally, but I'm still not seeing the RemoteDependencyData you're getting after each send event. I do see metrics related to the performance of the app (for example, I can see the average amount of available memory on my machine), but even the custom telemetry processor isn't logging the RemoteDependencyData.

Are you running this locally and seeing the RemoteDependencyData showing up? I checked with an engineer on the application insights package, and it should be collecting this information if you're using Open Telemetry. Since service bus is an AMQP-based client and not an HTTP-based client, that's the only hook it has. I don't see Open Telemetry in your repro though, is there anything missing from it?

[razvangoga]

Hi @chradek

yes i'm running locally on win 10 + node lts

but the issue was spotted on an alpine node container running in Azure in AKS

---

i've rerun the repro on a different machine. Was able to repro the issue again. What i have done was to:

1. clone the repo (make sure you have the latest version where the lines 7-16 in index.js are uncommented
2. add your AppInsights instrumentation key in the .env file
3. add your ASB conn string and TopicName in the .env file (i've only tested with a Topic - not sure if using a Queue will have another behaviour)
4. run npm install to pull dependencies
5. run npm start to start the script
6. for each message sent the telemetryprocessor will dump to console the envelope that will be sent to the AppInsights instance. And these are always unsuccessful -> are you seeing these items dumped to console? They are produced even if you provide a bogus instrumentation key.
7. after a few minutes, you should see dependencies logged in AppInsights. Use the kusto query dependencies | order by timestamp asc in the Logs blade of your AppInsights instance
8. alternatively you can look in the LiveMetrics blade of your AppInsights instance
   

---

regarding OpenTelemetry - i haven't done anything explicitly (in the repro or the real service) except the config done on line 7 of the index.js.

.setDistributedTracingMode(appInsights.DistributedTracingModes.AI_AND_W3C)

This is inline with what was configured on the other services in our project which are written in .netcore 3.1 as described here

---

if this info is not enough for you to repro, let's connect some other way (teams / zoom / skype) and take a look at it - i'm on CET but i'm flexible regarding the time as the issue is a high prio for us

[chradek]

@razvangoga One more thing, can you share the output of running npm ls @azure/core-tracing in your package?

I tried your exact steps on another machine and still am not seeing the RemoteDependencyData logged to the console. This is what I see:

> asb-with-application-inisghts@1.0.0 start C:\workplace\repro-nodejs-asb-with-application-inisghts
> node -r dotenv/config index

sending message 1
ApplicationInsights:CorrelationIdManager [ { method: 'GET', disableAppInsightsAutoCollection: true } ]       
ApplicationInsights:CorrelationIdManager [ 'ef58889f-ea36-4a27-b348-c2c819492226' ]
message 1 sent
sending message 2
message 2 sent
sending message 3
message 3 sent
sending message 4
message 4 sent
sending message 5
message 5 sent
sending message 6
message 6 sent
sending message 7
message 7 sent
sending message 8
message 8 sent
sending message 9
message 9 sent
sending message 10
message 10 sent
sending message 11
message 11 sent
sending message 12
message 12 sent
Envelope {
  ver: 1,
  sampleRate: 100,
  tags: {
    'ai.application.ver': '1.0.0',
    'ai.device.id': '',
    'ai.cloud.roleInstance': 'MININT-7VLH5EN',
    'ai.device.osVersion': 'Windows_NT 10.0.19041',
    'ai.cloud.role': 'Web',
    'ai.device.osArchitecture': 'x64',
    'ai.device.osPlatform': 'win32',
    'ai.internal.sdkVersion': 'node:2.1.4'
  },
  data: Data {
    baseType: 'MetricData',
    baseData: MetricData { ver: 2, metrics: [Array], properties: {} }
  },
  iKey: '<REDACTED>',
  name: 'Microsoft.ApplicationInsights.<REDACTED>.Metric',
  time: '2021-07-20T16:22:31.325Z'
}
Envelope {
  ver: 1,
  sampleRate: 100,
  tags: {
    'ai.application.ver': '1.0.0',
    'ai.device.id': '',
    'ai.cloud.roleInstance': 'MININT-7VLH5EN',
    'ai.device.osVersion': 'Windows_NT 10.0.19041',
    'ai.cloud.role': 'Web',
    'ai.device.osArchitecture': 'x64',
    'ai.device.osPlatform': 'win32',
    'ai.internal.sdkVersion': 'node:2.1.4'
  },
  data: Data {
    baseType: 'MetricData',
    baseData: MetricData { ver: 2, metrics: [Array], properties: {} }
  },
  iKey: '<REDACTED>',
  name: 'Microsoft.ApplicationInsights.<REDACTED>.Metric',
  time: '2021-07-20T16:22:31.332Z'
}
Envelope {
  ver: 1,
  sampleRate: 100,
  tags: {
    'ai.application.ver': '1.0.0',
    'ai.device.id': '',
    'ai.cloud.roleInstance': 'MININT-7VLH5EN',
    'ai.device.osVersion': 'Windows_NT 10.0.19041',
    'ai.cloud.role': 'Web',
    'ai.device.osArchitecture': 'x64',
    'ai.device.osPlatform': 'win32',
    'ai.internal.sdkVersion': 'node:2.1.4'
  },
  data: Data {
    baseType: 'MetricData',
    baseData: MetricData { ver: 2, metrics: [Array], properties: {} }
  },
  iKey: '<REDACTED>',
  name: 'Microsoft.ApplicationInsights.<REDACTED>.Metric',
  time: '2021-07-20T16:22:31.339Z'
}
Envelope {
  ver: 1,
  sampleRate: 100,
  tags: {
    'ai.application.ver': '1.0.0',
    'ai.device.id': '',
    'ai.cloud.roleInstance': 'MININT-7VLH5EN',
    'ai.device.osVersion': 'Windows_NT 10.0.19041',
    'ai.cloud.role': 'Web',
    'ai.device.osArchitecture': 'x64',
    'ai.device.osPlatform': 'win32',
    'ai.internal.sdkVersion': 'node:2.1.4'
  },
  data: Data {
    baseType: 'MetricData',
    baseData: MetricData { ver: 2, metrics: [Array], properties: {} }
  },
  iKey: '<REDACTED>',
  name: 'Microsoft.ApplicationInsights.<REDACTED>.Metric',
  time: '2021-07-20T16:22:31.346Z'
}
Envelope {
  ver: 1,
  sampleRate: 100,
  tags: {
    'ai.application.ver': '1.0.0',
    'ai.device.id': '',
    'ai.cloud.roleInstance': 'MININT-7VLH5EN',
    'ai.device.osVersion': 'Windows_NT 10.0.19041',
    'ai.cloud.role': 'Web',
    'ai.device.osArchitecture': 'x64',
    'ai.device.osPlatform': 'win32',
    'ai.internal.sdkVersion': 'node:2.1.4'
  },
  data: Data {
    baseType: 'MetricData',
    baseData: MetricData { ver: 2, metrics: [Array], properties: {} }
  },
  iKey: '<REDACTED>',
  name: 'Microsoft.ApplicationInsights.<REDACTED>.Metric',
  time: '2021-07-20T16:22:31.352Z'
}
Envelope {
  ver: 1,
  sampleRate: 100,
  tags: {
    'ai.application.ver': '1.0.0',
    'ai.device.id': '',
    'ai.cloud.roleInstance': 'MININT-7VLH5EN',
    'ai.device.osVersion': 'Windows_NT 10.0.19041',
    'ai.cloud.role': 'Web',
    'ai.device.osArchitecture': 'x64',
    'ai.device.osPlatform': 'win32',
    'ai.internal.sdkVersion': 'node:2.1.4'
  },
  data: Data {
    baseType: 'MetricData',
    baseData: MetricData { ver: 2, metrics: [Array], properties: {} }
  },
  iKey: '<REDACTED>',
  name: 'Microsoft.ApplicationInsights.<REDACTED>.Metric',
  time: '2021-07-20T16:22:31.358Z'
}
sending message 13
message 13 sent

Do you mind opening a support ticket and mentioning my alias, chradek? That'll allow us to set up a teams meeting/call.

[razvangoga]

this is how it looks on my end

D:\_work\tests\node-playground\asb-with-application-inisghts [master ≡ +0 ~1 -0 !]> npm ls @azure/core-tracing
asb-with-application-inisghts@1.0.0 D:\_work\tests\node-playground\asb-with-application-inisghts
`-- @azure/service-bus@7.3.0
  +-- @azure/core-http@2.0.0
  | `-- @azure/core-tracing@1.0.0-preview.12  deduped
  `-- @azure/core-tracing@1.0.0-preview.12

D:\_work\tests\node-playground\asb-with-application-inisghts [master ≡ +0 ~1 -0 !]> npm start

> asb-with-application-inisghts@1.0.0 start D:\_work\tests\node-playground\asb-with-application-inisghts
> node -r dotenv/config index

ApplicationInsights:An invalid instrumentation key was provided. There may be resulting telemetry loss [ 'bogus' ]
sending message 1
ApplicationInsights:CorrelationIdManager [ { method: 'GET', disableAppInsightsAutoCollection: true } ]
Envelope {
  ver: 1,
  sampleRate: 100,
  tags: {
    'ai.application.ver': '1.0.0',
    'ai.device.id': '',
    'ai.cloud.roleInstance': 'rg-ghost',
    'ai.device.osVersion': 'Windows_NT 10.0.19043',
    'ai.cloud.role': 'Web',
    'ai.device.osArchitecture': 'x64',
    'ai.device.osPlatform': 'win32',
    'ai.internal.sdkVersion': 'node:2.1.4',
    'ai.operation.id': 'a43a64e0fff75a1aafd22be881be17a3',
    'ai.operation.name': 'Azure.ServiceBus.send',
    'ai.operation.parentId': 'a43a64e0fff75a1aafd22be881be17a3'
  },
  data: Data {
    baseType: 'RemoteDependencyData',
    baseData: RemoteDependencyData {
      ver: 2,
      success: false,
      properties: [Object],
      measurements: {},
      name: 'Azure.ServiceBus.send',
      data: 'asb-dependencies.servicebus.windows.net',
      target: 'asb-dependencies.servicebus.windows.net',
      duration: '00:00:00.034',
      type: 'Azure.ServiceBus.send',
      resultCode: '1',
      id: '|a43a64e0fff75a1aafd22be881be17a3.8290921556fb46af.'
    }
  },
  iKey: 'bogus',
  name: 'Microsoft.ApplicationInsights.bogus.RemoteDependency',
  time: '2021-07-20T16:32:45.326Z'
}
message 1 sent
sending message 2
Envelope {
  ver: 1,
  sampleRate: 100,
  tags: {
    'ai.application.ver': '1.0.0',
    'ai.device.id': '',
    'ai.cloud.roleInstance': 'rg-ghost',
    'ai.device.osVersion': 'Windows_NT 10.0.19043',
    'ai.cloud.role': 'Web',
    'ai.device.osArchitecture': 'x64',
    'ai.device.osPlatform': 'win32',
    'ai.internal.sdkVersion': 'node:2.1.4',
    'ai.operation.id': '29b4b05a429c3c813e54e0aa20452ab9',
    'ai.operation.name': 'Azure.ServiceBus.send',
    'ai.operation.parentId': '29b4b05a429c3c813e54e0aa20452ab9'
  },
  data: Data {
    baseType: 'RemoteDependencyData',
    baseData: RemoteDependencyData {
      ver: 2,
      success: false,
      properties: [Object],
      measurements: {},
      name: 'Azure.ServiceBus.send',
      data: 'asb-dependencies.servicebus.windows.net',
      target: 'asb-dependencies.servicebus.windows.net',
      duration: '00:00:00.038',
      type: 'Azure.ServiceBus.send',
      resultCode: '1',
      id: '|29b4b05a429c3c813e54e0aa20452ab9.2f2f764e2baa50c1.'
    }
  },
  iKey: 'bogus',
  name: 'Microsoft.ApplicationInsights.bogus.RemoteDependency',
  time: '2021-07-20T16:32:47.369Z'
}
message 2 sent

how / where do i open the support ticket?

[chradek]

There are some links for opening a support ticket here:
https://github.com/Azure/azure-sdk-for-js/blob/main/SUPPORT.md#azure-support-tickets

I am starting to suspect that the issue you're seeing is with the applicationinsights package. This is the code path that should be hit:
https://github.com/microsoft/ApplicationInsights-node.js/blob/5ce8855414ab552ad6b23eeddb27f1c20e6a2a2f/AutoCollection/diagnostic-channel/SpanParser.ts#L69-L81

success: span.status.code === 0

I think this line is what's causing the data to show up as failed. I believe this should be updated to check against SpanStatusCode.OK (which is the value 1). I'm talking to one of the engineers on app insights, @hectorhdzg, to verify this.