From b0bfe6259a0d7dab115dc81f3335a9ea6989c2bd Mon Sep 17 00:00:00 2001 From: Timothy Mothra Lee Date: Tue, 24 Nov 2020 17:21:25 -0800 Subject: [PATCH 1/6] new test to verify correlation ids using Activity + iLogger --- .../TelemetryItemTests.cs | 76 +++++++++++++++++-- 1 file changed, 71 insertions(+), 5 deletions(-) diff --git a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs index c370e60acdce..6ead04e35851 100644 --- a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs +++ b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs @@ -5,7 +5,6 @@ using System.Collections.Generic; using System.Diagnostics; using System.Linq; -using System.Threading.Tasks; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; @@ -113,7 +112,6 @@ private TelemetryItem RunActivityTest(Action testScenario) // CLEANUP processor.ForceFlush(); - //Task.Delay(100).Wait(); //TODO: HOW TO REMOVE THIS WAIT? Assert.True(transmitter.TelemetryItems.Any(), "test project did not capture telemetry"); return transmitter.TelemetryItems.Single(); @@ -137,19 +135,87 @@ private TelemetryItem RunLoggerTest(Action> testScen .AddProcessor(processor)); }); - // ACT using var serviceProvider = serviceCollection.BuildServiceProvider(); var logger = serviceProvider.GetRequiredService>(); + + // ACT testScenario(logger); // CLEANUP processor.ForceFlush(); - //Task.Delay(100).Wait(); //TODO: HOW TO REMOVE THIS WAIT? Assert.True(transmitter.TelemetryItems.Any(), "test project did not capture telemetry"); return transmitter.TelemetryItems.Single(); } - // TODO: INCLUDE ADDITIONAL TESTS VALIDATING ILOGGER + ACTIVITY + /// + /// This test is to verify that the correlation Ids from Activity are set on Log Telemetry. + /// This test will generate two telemetry items and their Ids are expected to match. + /// This test does not inspect any other fields. + /// + [Fact] + public void VerifyLoggerWithActivity() + { + // SETUP + var ActivitySourceName = "MyCompany.MyProduct.MyLibrary"; + using var activitySource = new ActivitySource(ActivitySourceName); + + var transmitter = new MockTransmitter(); + + var processor1 = new BatchExportProcessor(new AzureMonitorTraceExporter( + options: new AzureMonitorExporterOptions + { + ConnectionString = EmptyConnectionString, + }, + transmitter: transmitter)); + + var processor2 = new BatchExportProcessor(new AzureMonitorLogExporter( + options: new AzureMonitorExporterOptions + { + ConnectionString = EmptyConnectionString, + }, + transmitter: transmitter)); + + Sdk.CreateTracerProviderBuilder() + .SetSampler(new AlwaysOnSampler()) + .AddSource(ActivitySourceName) + .AddProcessor(processor1) + .Build(); + + var serviceCollection = new ServiceCollection().AddLogging(builder => + { + builder.SetMinimumLevel(LogLevel.Trace) + .AddOpenTelemetry(options => options + .AddProcessor(processor2)); + }); + + using var serviceProvider = serviceCollection.BuildServiceProvider(); + var logger = serviceProvider.GetRequiredService>(); + + // ACT + using (var activity = activitySource.StartActivity(name: "test activity", kind: ActivityKind.Server)) + { + activity.SetTag("message", "hello activity!"); + + logger.LogWarning("hello ilogger"); + } + + // CLEANUP + processor1.ForceFlush(); + processor2.ForceFlush(); + + // VERIFY + Assert.True(transmitter.TelemetryItems.Any(), "test project did not capture telemetry"); + Assert.Equal(2, transmitter.TelemetryItems.Count); + + var logTelemetry = transmitter.TelemetryItems.Single(x => x.Name == "Message"); + var activityTelemetry = transmitter.TelemetryItems.Single(x => x.Name == "Request"); + + var activityId = ((RequestData)activityTelemetry.Data.BaseData).Id; + var operationId = activityTelemetry.Tags["ai.operation.id"]; + + Assert.Equal(activityId, logTelemetry.Tags["ai.operation.parentId"]); + Assert.Equal(operationId, logTelemetry.Tags["ai.operation.id"]); + } } } From 36b51d48641f242e1474229cbc9df7db504ea6e7 Mon Sep 17 00:00:00 2001 From: Timothy Mothra Lee Date: Tue, 24 Nov 2020 17:34:10 -0800 Subject: [PATCH 2/6] dispose tracerProvider --- .../TelemetryItemTests.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs index 6ead04e35851..db29fd88ecc2 100644 --- a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs +++ b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs @@ -101,7 +101,7 @@ private TelemetryItem RunActivityTest(Action testScenario) }, transmitter: transmitter)); - Sdk.CreateTracerProviderBuilder() + using var tracerProvider = Sdk.CreateTracerProviderBuilder() .SetSampler(new AlwaysOnSampler()) .AddSource(ActivitySourceName) .AddProcessor(processor) @@ -176,7 +176,7 @@ public void VerifyLoggerWithActivity() }, transmitter: transmitter)); - Sdk.CreateTracerProviderBuilder() + using var tracerProvider = Sdk.CreateTracerProviderBuilder() .SetSampler(new AlwaysOnSampler()) .AddSource(ActivitySourceName) .AddProcessor(processor1) From e491b6298ec7859c1a03b4d8c6ed37f23411e8df Mon Sep 17 00:00:00 2001 From: Timothy Mothra Lee Date: Tue, 24 Nov 2020 17:37:53 -0800 Subject: [PATCH 3/6] de-dupe exporter options --- .../TelemetryItemTests.cs | 15 +++++++-------- 1 file changed, 7 insertions(+), 8 deletions(-) diff --git a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs index db29fd88ecc2..2a460acd1686 100644 --- a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs +++ b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs @@ -162,18 +162,17 @@ public void VerifyLoggerWithActivity() var transmitter = new MockTransmitter(); + var azureMonitorExporterOptions = new AzureMonitorExporterOptions + { + ConnectionString = EmptyConnectionString, + }; + var processor1 = new BatchExportProcessor(new AzureMonitorTraceExporter( - options: new AzureMonitorExporterOptions - { - ConnectionString = EmptyConnectionString, - }, + options: azureMonitorExporterOptions, transmitter: transmitter)); var processor2 = new BatchExportProcessor(new AzureMonitorLogExporter( - options: new AzureMonitorExporterOptions - { - ConnectionString = EmptyConnectionString, - }, + options: azureMonitorExporterOptions, transmitter: transmitter)); using var tracerProvider = Sdk.CreateTracerProviderBuilder() From d09c0e001895305140ab7b42de3970d106ae8c63 Mon Sep 17 00:00:00 2001 From: Timothy Mothra Lee Date: Tue, 24 Nov 2020 17:39:18 -0800 Subject: [PATCH 4/6] cleanup --- .../TelemetryItemTests.cs | 34 +++++++++---------- 1 file changed, 17 insertions(+), 17 deletions(-) diff --git a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs index 2a460acd1686..ff0f3fe728c2 100644 --- a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs +++ b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs @@ -93,13 +93,13 @@ private TelemetryItem RunActivityTest(Action testScenario) var ActivitySourceName = "MyCompany.MyProduct.MyLibrary"; using var activitySource = new ActivitySource(ActivitySourceName); - var transmitter = new MockTransmitter(); + var mockTransmitter = new MockTransmitter(); var processor = new BatchExportProcessor(new AzureMonitorTraceExporter( options: new AzureMonitorExporterOptions { ConnectionString = EmptyConnectionString, }, - transmitter: transmitter)); + transmitter: mockTransmitter)); using var tracerProvider = Sdk.CreateTracerProviderBuilder() .SetSampler(new AlwaysOnSampler()) @@ -113,26 +113,26 @@ private TelemetryItem RunActivityTest(Action testScenario) // CLEANUP processor.ForceFlush(); - Assert.True(transmitter.TelemetryItems.Any(), "test project did not capture telemetry"); - return transmitter.TelemetryItems.Single(); + Assert.True(mockTransmitter.TelemetryItems.Any(), "test project did not capture telemetry"); + return mockTransmitter.TelemetryItems.Single(); } private TelemetryItem RunLoggerTest(Action> testScenario) { // SETUP - var transmitter = new MockTransmitter(); + var mockTransmitter = new MockTransmitter(); var processor = new BatchExportProcessor(new AzureMonitorLogExporter( options: new AzureMonitorExporterOptions { ConnectionString = EmptyConnectionString, }, - transmitter: transmitter)); + transmitter: mockTransmitter)); var serviceCollection = new ServiceCollection().AddLogging(builder => { builder.SetMinimumLevel(LogLevel.Trace) .AddOpenTelemetry(options => options - .AddProcessor(processor)); + .AddProcessor(processor)); }); using var serviceProvider = serviceCollection.BuildServiceProvider(); @@ -144,8 +144,8 @@ private TelemetryItem RunLoggerTest(Action> testScen // CLEANUP processor.ForceFlush(); - Assert.True(transmitter.TelemetryItems.Any(), "test project did not capture telemetry"); - return transmitter.TelemetryItems.Single(); + Assert.True(mockTransmitter.TelemetryItems.Any(), "test project did not capture telemetry"); + return mockTransmitter.TelemetryItems.Single(); } /// @@ -160,7 +160,7 @@ public void VerifyLoggerWithActivity() var ActivitySourceName = "MyCompany.MyProduct.MyLibrary"; using var activitySource = new ActivitySource(ActivitySourceName); - var transmitter = new MockTransmitter(); + var mockTransmitter = new MockTransmitter(); var azureMonitorExporterOptions = new AzureMonitorExporterOptions { @@ -169,11 +169,11 @@ public void VerifyLoggerWithActivity() var processor1 = new BatchExportProcessor(new AzureMonitorTraceExporter( options: azureMonitorExporterOptions, - transmitter: transmitter)); + transmitter: mockTransmitter)); var processor2 = new BatchExportProcessor(new AzureMonitorLogExporter( options: azureMonitorExporterOptions, - transmitter: transmitter)); + transmitter: mockTransmitter)); using var tracerProvider = Sdk.CreateTracerProviderBuilder() .SetSampler(new AlwaysOnSampler()) @@ -185,7 +185,7 @@ public void VerifyLoggerWithActivity() { builder.SetMinimumLevel(LogLevel.Trace) .AddOpenTelemetry(options => options - .AddProcessor(processor2)); + .AddProcessor(processor2)); }); using var serviceProvider = serviceCollection.BuildServiceProvider(); @@ -204,11 +204,11 @@ public void VerifyLoggerWithActivity() processor2.ForceFlush(); // VERIFY - Assert.True(transmitter.TelemetryItems.Any(), "test project did not capture telemetry"); - Assert.Equal(2, transmitter.TelemetryItems.Count); + Assert.True(mockTransmitter.TelemetryItems.Any(), "test project did not capture telemetry"); + Assert.Equal(2, mockTransmitter.TelemetryItems.Count); - var logTelemetry = transmitter.TelemetryItems.Single(x => x.Name == "Message"); - var activityTelemetry = transmitter.TelemetryItems.Single(x => x.Name == "Request"); + var logTelemetry = mockTransmitter.TelemetryItems.Single(x => x.Name == "Message"); + var activityTelemetry = mockTransmitter.TelemetryItems.Single(x => x.Name == "Request"); var activityId = ((RequestData)activityTelemetry.Data.BaseData).Id; var operationId = activityTelemetry.Tags["ai.operation.id"]; From cc9e56bf13f3a01a74e3807e92ebc9c10a0803a8 Mon Sep 17 00:00:00 2001 From: Timothy Mothra Lee Date: Wed, 25 Nov 2020 10:20:20 -0800 Subject: [PATCH 5/6] dedupe activitysourcename --- .../TelemetryItemTests.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs index ff0f3fe728c2..dc1dbac67fcd 100644 --- a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs +++ b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs @@ -90,7 +90,7 @@ public void VerifyILogger(LogLevel logLevel, string expectedSeverityLevel) private TelemetryItem RunActivityTest(Action testScenario) { // SETUP - var ActivitySourceName = "MyCompany.MyProduct.MyLibrary"; + var ActivitySourceName = $"{nameof(TelemetryItemTests)}.{nameof(RunActivityTest)}"; using var activitySource = new ActivitySource(ActivitySourceName); var mockTransmitter = new MockTransmitter(); @@ -157,7 +157,7 @@ private TelemetryItem RunLoggerTest(Action> testScen public void VerifyLoggerWithActivity() { // SETUP - var ActivitySourceName = "MyCompany.MyProduct.MyLibrary"; + var ActivitySourceName = $"{nameof(TelemetryItemTests)}.{nameof(VerifyLoggerWithActivity)}"; using var activitySource = new ActivitySource(ActivitySourceName); var mockTransmitter = new MockTransmitter(); From c1848bd1487feaf9ec4b4fcb72475113490b3f56 Mon Sep 17 00:00:00 2001 From: Timothy Mothra Lee Date: Wed, 25 Nov 2020 11:03:25 -0800 Subject: [PATCH 6/6] additional activity test --- .../TelemetryItemTests.cs | 4 ++++ .../TestFramework/ExpectedTelemetryItemValues.cs | 2 ++ .../TestFramework/VerifyTelemetryItem.cs | 3 ++- 3 files changed, 8 insertions(+), 1 deletion(-) diff --git a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs index dc1dbac67fcd..6f5b1bae6a61 100644 --- a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs +++ b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TelemetryItemTests.cs @@ -76,7 +76,9 @@ public void VerifyILogger(LogLevel logLevel, string expectedSeverityLevel) { var message = "Hello World!"; + var activity = new Activity("test activity").Start(); var telemetryItem = this.RunLoggerTest(x => x.Log(logLevel: logLevel, message: message)); + activity.Stop(); VerifyTelemetryItem.VerifyEvent( telemetryItem: telemetryItem, @@ -84,6 +86,8 @@ public void VerifyILogger(LogLevel logLevel, string expectedSeverityLevel) { Message = message, SeverityLevel = expectedSeverityLevel, + SpanId = activity.SpanId.ToHexString(), + TraceId = activity.TraceId.ToHexString(), }); } diff --git a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TestFramework/ExpectedTelemetryItemValues.cs b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TestFramework/ExpectedTelemetryItemValues.cs index 751df0394216..235c77874c6d 100644 --- a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TestFramework/ExpectedTelemetryItemValues.cs +++ b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TestFramework/ExpectedTelemetryItemValues.cs @@ -13,5 +13,7 @@ internal struct ExpectedTelemetryItemValues public string Message; public Dictionary CustomProperties; public SeverityLevel SeverityLevel; + public string SpanId; + public string TraceId; } } diff --git a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TestFramework/VerifyTelemetryItem.cs b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TestFramework/VerifyTelemetryItem.cs index 57fb6734fbbf..2e485ac75aac 100644 --- a/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TestFramework/VerifyTelemetryItem.cs +++ b/sdk/monitor/Microsoft.OpenTelemetry.Exporter.AzureMonitor/tests/Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests/TestFramework/VerifyTelemetryItem.cs @@ -12,7 +12,6 @@ namespace Microsoft.OpenTelemetry.Exporter.AzureMonitor.Integration.Tests.TestFr { internal static class VerifyTelemetryItem { - public static void Verify(TelemetryItem telemetryItem, ActivityKind activityKind, ExpectedTelemetryItemValues expectedVars) { switch (activityKind) @@ -59,6 +58,8 @@ public static void VerifyEvent(TelemetryItem telemetryItem, ExpectedTelemetryIte var data = (MessageData)telemetryItem.Data.BaseData; Assert.Equal(expectedVars.Message, data.Message); Assert.Equal(expectedVars.SeverityLevel, data.SeverityLevel); + Assert.Equal(expectedVars.SpanId, telemetryItem.Tags["ai.operation.parentId"]); + Assert.Equal(expectedVars.TraceId, telemetryItem.Tags["ai.operation.id"]); } } }