From be9148c45a6ebc7cb1560d80500506b2de903d98 Mon Sep 17 00:00:00 2001 From: Steve Gordon Date: Wed, 7 Feb 2024 14:34:16 +0100 Subject: [PATCH 1/6] Add diagnostics, file logging and ILogger integration --- Directory.Build.props | 1 + .../Program.cs | 5 +- .../appsettings.Development.json | 3 +- src/Elastic.OpenTelemetry/Agent.cs | 206 +++++++++++------- src/Elastic.OpenTelemetry/AgentBuilder.cs | 100 +++++---- .../ElasticOtelDistroService.cs | 38 ++++ .../ServiceCollectionExtensions.cs | 21 ++ .../Diagnostics/DiagnosticErrorLevels.cs | 13 ++ .../Diagnostics/DiagnosticEvent.cs | 27 +++ .../ElasticDiagnosticLoggingObserver.cs | 119 ++++++++++ .../ElasticOpenTelemetryDiagnosticSource.cs | 91 ++++++++ .../Diagnostics/IDiagnosticEvent.cs | 14 ++ .../Diagnostics/LogFileWriter.cs | 188 ++++++++++++++++ .../LoggingDiagnosticSourceListener.cs | 26 +++ .../Diagnostics/LoggingEventListener.cs | 127 +++++++++++ .../Diagnostics/StringBuilderCache.cs | 61 ++++++ .../Elastic.OpenTelemetry.csproj | 4 + .../EnvironmentVariables.cs | 11 + .../TraceBuilderProviderExtensions.cs | 45 +++- src/Elastic.OpenTelemetry/IAgent.cs | 10 +- .../Processors/ElasticProcessor.cs | 33 +++ .../Processors/IElasticProcessor.cs | 9 + .../Processors/TransactionIdProcessor.cs | 30 ++- tests/Directory.Build.props | 3 + .../ProcessorTests.cs | 31 +++ 25 files changed, 1074 insertions(+), 142 deletions(-) create mode 100644 src/Elastic.OpenTelemetry/DependencyInjection/ElasticOtelDistroService.cs create mode 100644 src/Elastic.OpenTelemetry/Diagnostics/DiagnosticErrorLevels.cs create mode 100644 src/Elastic.OpenTelemetry/Diagnostics/DiagnosticEvent.cs create mode 100644 src/Elastic.OpenTelemetry/Diagnostics/ElasticDiagnosticLoggingObserver.cs create mode 100644 src/Elastic.OpenTelemetry/Diagnostics/ElasticOpenTelemetryDiagnosticSource.cs create mode 100644 src/Elastic.OpenTelemetry/Diagnostics/IDiagnosticEvent.cs create mode 100644 src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs create mode 100644 src/Elastic.OpenTelemetry/Diagnostics/LoggingDiagnosticSourceListener.cs create mode 100644 src/Elastic.OpenTelemetry/Diagnostics/LoggingEventListener.cs create mode 100644 src/Elastic.OpenTelemetry/Diagnostics/StringBuilderCache.cs create mode 100644 src/Elastic.OpenTelemetry/EnvironmentVariables.cs create mode 100644 src/Elastic.OpenTelemetry/Processors/ElasticProcessor.cs create mode 100644 src/Elastic.OpenTelemetry/Processors/IElasticProcessor.cs create mode 100644 tests/Elastic.OpenTelemetry.Tests/ProcessorTests.cs diff --git a/Directory.Build.props b/Directory.Build.props index e219530..c2b84ab 100644 --- a/Directory.Build.props +++ b/Directory.Build.props @@ -18,6 +18,7 @@ true $([MSBuild]::GetDirectoryNameOfFileAbove($(MSBuildThisFileDirectory), build.bat)) $(MSBuildThisFileDirectory).artifacts + 002400000480000094000000060200000024000052534131000400000100010015b0fa59d868c7f3ea2ae67567b19e102465745f01b430a38a42b92fd41a0f5869bec1f2b33b589d78662af432fe6b789ef72d4738f7b1a86264d7aeb5185ed8995b2bb104e7c5c58845f1a618be829e410fa34a6bd7d714ece191ed68a66333a83ae7456ee32e9aeb54bc1d7410ae8c344367257e9001abb5e96ce1f1d97696 diff --git a/examples/Example.Elastic.OpenTelemetry.Worker/Program.cs b/examples/Example.Elastic.OpenTelemetry.Worker/Program.cs index 75a64d4..a9afd6a 100644 --- a/examples/Example.Elastic.OpenTelemetry.Worker/Program.cs +++ b/examples/Example.Elastic.OpenTelemetry.Worker/Program.cs @@ -4,9 +4,10 @@ using Example.Elastic.OpenTelemetry.Worker; var builder = Host.CreateApplicationBuilder(args); -builder.Services.AddHostedService(); -builder.Services.AddElasticOpenTelemetry("CustomActivitySource"); +builder.EnableElasticOpenTelemetry("CustomActivitySource"); + +builder.Services.AddHostedService(); var host = builder.Build(); host.Run(); diff --git a/examples/Example.Elastic.OpenTelemetry.Worker/appsettings.Development.json b/examples/Example.Elastic.OpenTelemetry.Worker/appsettings.Development.json index b2dcdb6..5816332 100644 --- a/examples/Example.Elastic.OpenTelemetry.Worker/appsettings.Development.json +++ b/examples/Example.Elastic.OpenTelemetry.Worker/appsettings.Development.json @@ -2,7 +2,8 @@ "Logging": { "LogLevel": { "Default": "Information", - "Microsoft.Hosting.Lifetime": "Information" + "Microsoft.Hosting.Lifetime": "Information", + "Elastic": "Trace" } } } diff --git a/src/Elastic.OpenTelemetry/Agent.cs b/src/Elastic.OpenTelemetry/Agent.cs index 2c73a33..c25f424 100644 --- a/src/Elastic.OpenTelemetry/Agent.cs +++ b/src/Elastic.OpenTelemetry/Agent.cs @@ -1,97 +1,145 @@ // Licensed to Elasticsearch B.V under one or more agreements. // Elasticsearch B.V licenses this file to you under the Apache 2.0 License. // See the LICENSE file in the project root for more information -using OpenTelemetry; using System.Reflection; +using Microsoft.Extensions.Logging; + +using static Elastic.OpenTelemetry.Diagnostics.ElasticOpenTelemetryDiagnosticSource; namespace Elastic.OpenTelemetry; /// /// Supports building and accessing an which collects and ships observability signals. /// -public static class Agent +public static partial class Agent { - private static readonly object Lock = new(); - private static IAgent? _current; - - static Agent() - { - var assemblyInformationalVersion = typeof(Agent).Assembly.GetCustomAttribute()?.InformationalVersion; - InformationalVersion = ParseAssemblyInformationalVersion(assemblyInformationalVersion); - } - - /// - /// Returns the singleton instance. - /// - /// - /// If an instance is not already initialized, this will create and return a - /// default configured with recommended Elastic defaults. - /// - public static IAgent Current - { - get - { - if (_current is not null) return _current; - - lock (Lock) - { - // disable to satisfy double check lock pattern analyzer - // ReSharper disable once InvertIf - if (_current is null) - { - var agent = new AgentBuilder().Build(); - _current = agent; - } - return _current; - } - } - } - - internal static string InformationalVersion { get; } - - /// - /// Builds an . - /// - /// An instance. - /// - /// An exception will be thrown if - /// is called more than once during the lifetime of an application. - /// - public static IAgent Build(Action? configuration = null) - { - if (_current != null) - throw new Exception($"{nameof(Agent)}.{nameof(Build)} called twice or after {nameof(Agent)}.{nameof(Current)} was accessed."); - - lock (Lock) - { - if (_current != null) - throw new Exception($"{nameof(Agent)}.{nameof(Build)} called twice or after {nameof(Agent)}.{nameof(Current)} was accessed."); - - var agentBuilder = new AgentBuilder(); - configuration?.Invoke(agentBuilder); - var agent = agentBuilder.Build(); - _current = agent; - return _current; - } - } - - internal static string ParseAssemblyInformationalVersion(string? informationalVersion) - { - if (string.IsNullOrWhiteSpace(informationalVersion)) - { - informationalVersion = "1.0.0"; - } - - /* + private static readonly object Lock = new(); + private static IAgent? CurrentAgent; + + static Agent() + { + var assemblyInformationalVersion = typeof(Agent).Assembly.GetCustomAttribute()?.InformationalVersion; + InformationalVersion = ParseAssemblyInformationalVersion(assemblyInformationalVersion); + } + + /// + /// Returns the singleton instance. + /// + /// + /// If an instance is not already initialized, this will create and return a + /// default configured with recommended Elastic defaults. + /// + public static IAgent Current + { + get + { + if (CurrentAgent is not null) + return CurrentAgent; + + lock (Lock) + { + // disable to satisfy double check lock pattern analyzer + // ReSharper disable once InvertIf + if (CurrentAgent is null) + { + var agent = new AgentBuilder().Build(); + CurrentAgent = agent; + } + return CurrentAgent; + } + } + } + + internal static string InformationalVersion { get; } + + /// + /// Builds an . + /// + /// An instance. + /// + /// An exception will be thrown if + /// is called more than once during the lifetime of an application. + /// + public static IAgent Build(Action? configuration = null) + { + CheckCurrent(); + + lock (Lock) + { + CheckCurrent(); + var agentBuilder = new AgentBuilder(); + configuration?.Invoke(agentBuilder); + var agent = agentBuilder.Build(); + CurrentAgent = agent; + return CurrentAgent; + } + + static void CheckCurrent() + { + if (CurrentAgent is not null) + { + Log(AgentBuildCalledMultipleTimesEvent); + throw new Exception(); + } + } + } + + internal const string BuildErrorMessage = $"{nameof(Agent)}.{nameof(Build)} called twice or after " + + $"{nameof(Agent)}.{nameof(Current)} was accessed."; + + internal const string SetAgentErrorMessage = $"{nameof(Agent)}.{nameof(SetAgent)} called twice" + + $"or after {nameof(Agent)}.{nameof(Build)} or after {nameof(Agent)}.{nameof(Current)} was accessed."; + + [LoggerMessage(EventId = 1, Level = LogLevel.Error, Message = SetAgentErrorMessage)] + internal static partial void SetAgentError(this ILogger logger); + + /// + /// TODO + /// + /// + /// + /// + /// + internal static IAgent SetAgent(IAgent agent, ILogger logger) + { + CheckCurrent(logger); + + lock (Lock) + { + CheckCurrent(logger); + logger.LogInformation($"Setting {nameof(CurrentAgent)}."); + CurrentAgent = agent; + return CurrentAgent; + } + + static void CheckCurrent(ILogger logger) + { + if (CurrentAgent is not null) + { + Log(AgentSetAgentCalledMultipleTimesEvent); + logger.SetAgentError(); + throw new Exception(SetAgentErrorMessage); + } + } + } + + internal static string ParseAssemblyInformationalVersion(string? informationalVersion) + { + if (string.IsNullOrWhiteSpace(informationalVersion)) + { + informationalVersion = "1.0.0"; + } + + /* * InformationalVersion will be in the following format: * {majorVersion}.{minorVersion}.{patchVersion}.{pre-release label}.{pre-release version}.{gitHeight}+{Git SHA of current commit} * Ex: 1.5.0-alpha.1.40+807f703e1b4d9874a92bd86d9f2d4ebe5b5d52e4 * The following parts are optional: pre-release label, pre-release version, git height, Git SHA of current commit */ - var indexOfPlusSign = informationalVersion!.IndexOf('+'); - return indexOfPlusSign > 0 - ? informationalVersion[..indexOfPlusSign] - : informationalVersion; - } + var indexOfPlusSign = informationalVersion!.IndexOf('+'); + return indexOfPlusSign > 0 + ? informationalVersion[..indexOfPlusSign] + : informationalVersion; + } } diff --git a/src/Elastic.OpenTelemetry/AgentBuilder.cs b/src/Elastic.OpenTelemetry/AgentBuilder.cs index 479addd..c2f1a33 100644 --- a/src/Elastic.OpenTelemetry/AgentBuilder.cs +++ b/src/Elastic.OpenTelemetry/AgentBuilder.cs @@ -2,25 +2,21 @@ // Elasticsearch B.V licenses this file to you under the Apache 2.0 License. // See the LICENSE file in the project root for more information using System.Diagnostics; +using Elastic.OpenTelemetry.Diagnostics; using Elastic.OpenTelemetry.Extensions; +using Elastic.OpenTelemetry.Processors; using Elastic.OpenTelemetry.Resources; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; using OpenTelemetry; using OpenTelemetry.Exporter; using OpenTelemetry.Metrics; using OpenTelemetry.Resources; using OpenTelemetry.Trace; -namespace Elastic.OpenTelemetry; +using static Elastic.OpenTelemetry.Diagnostics.ElasticOpenTelemetryDiagnosticSource; -/// -/// -/// -public class DebugExporter : BaseExporter -{ - /// - public override ExportResult Export(in Batch batch) => ExportResult.Success; -} +namespace Elastic.OpenTelemetry; /// /// Supports building instances which include Elastic defaults, but can also be customised. @@ -42,7 +38,7 @@ public class AgentBuilder .AddRuntimeInstrumentation() .AddHttpClientInstrumentation(); - private readonly string[]? _activitySourceNames; + private readonly string[] _activitySourceNames = []; private Action _tracerProviderBuilderAction = tpb => { }; private Action? _resourceBuilderAction; private Action? _otlpExporterConfiguration; @@ -51,13 +47,26 @@ public class AgentBuilder /// /// TODO /// - public AgentBuilder() { } + public AgentBuilder() + { + if (LogFileWriter.FileLoggingEnabled) + { + // Enables logging of OpenTelemetry-SDK event source events + _ = new LoggingEventListener(LogFileWriter.Instance); + + // Enables logging of Elastic OpenTelemetry diagnostic source events + var listener = new LoggingDiagnosticSourceListener(LogFileWriter.Instance); + DiagnosticListener.AllListeners.Subscribe(listener); + } + + Log(AgentBuilderInitializedEvent, new DiagnosticEvent(new StackTrace(true))); + } // NOTE - Applies to all signals /// /// TODO /// - public AgentBuilder(params string[] activitySourceNames) => _activitySourceNames = activitySourceNames; + public AgentBuilder(params string[] activitySourceNames) : this() => _activitySourceNames = activitySourceNames; // NOTE: The builder methods below are extremely experimental and will go through a final API design and // refinement before alpha 1 @@ -181,7 +190,14 @@ public IAgent Build() var tracerProviderBuilder = Sdk.CreateTracerProviderBuilder(); TracerProviderBuilderAction.Invoke(tracerProviderBuilder); var tracerProvider = tracerProviderBuilder.Build(); - return tracerProvider is not null ? new Agent(tracerProvider) : new Agent(); + + Log(AgentBuilderBuiltTracerProviderEvent); + + var agent = tracerProvider is not null ? new Agent(tracerProvider) : new Agent(); + + Log(AgentBuilderBuiltAgentEvent); + + return agent; } /// @@ -191,24 +207,38 @@ public IAgent Build() /// The supplied . public IServiceCollection Register(IServiceCollection serviceCollection) { + // TODO - Docs, we should explain that prior to .NET 8, this needs to be added first if other hosted services emit signals. + // On .NET 8 we handle this with IHostedLifecycleService + _ = serviceCollection + .AddHostedService() + .AddSingleton() + .AddSingleton() .AddOpenTelemetry() .WithTracing(TracerProviderBuilderAction); + Log(AgentBuilderRegisteredDistroServicesEvent); + return serviceCollection; } private Action TracerProviderBuilderAction => tracerProviderBuilder => { - if (_activitySourceNames is not null) - tracerProviderBuilder.AddSource(_activitySourceNames); + foreach (var source in _activitySourceNames) + tracerProviderBuilder.LogAndAddSource(source); tracerProviderBuilder .AddHttpClientInstrumentation() .AddGrpcClientInstrumentation() - .AddEntityFrameworkCoreInstrumentation() - .AddElasticProcessors(); + .AddEntityFrameworkCoreInstrumentation(); // TODO - Should we add this by default? + + // TODO - Update these to capture the builder type also + //Log.AddedInstrumentation("HttpClient"); + //Log.AddedInstrumentation("GrpcClient"); + //Log.AddedInstrumentation("EntityFrameworkCore"); + + tracerProviderBuilder.AddElasticProcessors(); if (_resourceBuilderAction is not null) { @@ -221,15 +251,10 @@ public IServiceCollection Register(IServiceCollection serviceCollection) tracerProviderBuilder.ConfigureResource(DefaultResourceBuilderConfiguration); } + // TODO - Can/should we use reflection to determine and log what is configured by the user action? _tracerProviderBuilderAction?.Invoke(tracerProviderBuilder); - // Add the OTLP exporter configured to ship data to an Elastic backend. - // TODO - What about cases where users want to register processors/exporters after any exporters we add by default (OTLP)? tracerProviderBuilder.AddElasticOtlpExporter(_otlpExporterConfiguration, _otlpExporterName); - -#if DEBUG - tracerProviderBuilder.AddProcessor(new SimpleActivityExportProcessor(new DebugExporter())); -#endif }; /// @@ -242,10 +267,13 @@ public void ConfigureOtlpExporter(Action configure, string? _otlpExporterName = name; } - private sealed class Agent(TracerProvider? tracerProvider, MeterProvider? meterProvider) : IAgent + private sealed class ServiceProviderAgent(IServiceProvider serviceProvider) : Agent, IServiceProviderAgent { - private bool _disposedValue; + public IServiceProvider ServiceProvider => serviceProvider; + } + private class Agent(TracerProvider? tracerProvider, MeterProvider? meterProvider) : IAgent + { private readonly TracerProvider? _tracerProvider = tracerProvider; private readonly MeterProvider? _meterProvider = meterProvider; @@ -257,24 +285,18 @@ internal Agent(TracerProvider tracerProvider) : this(tracerProvider, null) { } - private void Dispose(bool disposing) + public void Dispose() { - if (!_disposedValue) - { - if (disposing) - { - _tracerProvider?.Dispose(); - _meterProvider?.Dispose(); - } - - _disposedValue = true; - } + _tracerProvider?.Dispose(); + _meterProvider?.Dispose(); + LogFileWriter.Instance.Dispose(); } - public void Dispose() + public async ValueTask DisposeAsync() { - Dispose(disposing: true); - GC.SuppressFinalize(this); + _tracerProvider?.Dispose(); + _meterProvider?.Dispose(); + await LogFileWriter.Instance.DisposeAsync().ConfigureAwait(false); } } } diff --git a/src/Elastic.OpenTelemetry/DependencyInjection/ElasticOtelDistroService.cs b/src/Elastic.OpenTelemetry/DependencyInjection/ElasticOtelDistroService.cs new file mode 100644 index 0000000..34adb87 --- /dev/null +++ b/src/Elastic.OpenTelemetry/DependencyInjection/ElasticOtelDistroService.cs @@ -0,0 +1,38 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +using Elastic.OpenTelemetry.Processors; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; + +namespace Elastic.OpenTelemetry +{ + internal sealed class ElasticOtelDistroService(IServiceProvider serviceProvider) : IHostedService, IHostedLifecycleService + { + private readonly IServiceProvider _serviceProvider = serviceProvider; + + public Task StartingAsync(CancellationToken cancellationToken) + { + var agent = _serviceProvider.GetRequiredService(); + var loggerFactory = _serviceProvider.GetService(); + var logger = loggerFactory?.CreateLogger($"{nameof(Elastic)}.{nameof(OpenTelemetry)}") ?? NullLogger.Instance; + + logger.LogInformation("Initialising processors."); + foreach (var processor in _serviceProvider.GetServices()) + processor?.Initialize(_serviceProvider); + + logger.LogInformation("Initialising Agent.Current."); + Agent.SetAgent(agent, logger); + + return Task.CompletedTask; + } + + public Task StartAsync(CancellationToken cancellationToken) => Task.CompletedTask; + public Task StartedAsync(CancellationToken cancellationToken) => Task.CompletedTask; + public Task StoppingAsync(CancellationToken cancellationToken) => Task.CompletedTask; + public Task StopAsync(CancellationToken cancellationToken) => Task.CompletedTask; + public Task StoppedAsync(CancellationToken cancellationToken) => Task.CompletedTask; + } +} diff --git a/src/Elastic.OpenTelemetry/DependencyInjection/ServiceCollectionExtensions.cs b/src/Elastic.OpenTelemetry/DependencyInjection/ServiceCollectionExtensions.cs index 6329005..28153ee 100644 --- a/src/Elastic.OpenTelemetry/DependencyInjection/ServiceCollectionExtensions.cs +++ b/src/Elastic.OpenTelemetry/DependencyInjection/ServiceCollectionExtensions.cs @@ -2,6 +2,7 @@ // Elasticsearch B.V licenses this file to you under the Apache 2.0 License. // See the LICENSE file in the project root for more information using Elastic.OpenTelemetry; +using Microsoft.Extensions.Hosting; using OpenTelemetry.Trace; namespace Microsoft.Extensions.DependencyInjection; @@ -11,6 +12,26 @@ namespace Microsoft.Extensions.DependencyInjection; /// public static class ServiceCollectionExtensions { + /// + /// TODO + /// + /// + /// + public static IHostApplicationBuilder EnableElasticOpenTelemetry(this IHostApplicationBuilder builder) => + EnableElasticOpenTelemetry(builder, []); + + /// + /// TODO + /// + /// + /// + /// + public static IHostApplicationBuilder EnableElasticOpenTelemetry(this IHostApplicationBuilder builder, params string[] activitySourceNames) + { + builder.Services.AddElasticOpenTelemetry(activitySourceNames); + return builder; + } + /// /// Adds the Elastic OpenTelemetry distribution to an application via the . /// diff --git a/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticErrorLevels.cs b/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticErrorLevels.cs new file mode 100644 index 0000000..15675dd --- /dev/null +++ b/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticErrorLevels.cs @@ -0,0 +1,13 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +namespace Elastic.OpenTelemetry.Diagnostics; + +internal static class DiagnosticErrorLevels +{ + public const string Critical = "Critical"; + public const string Error = "Error"; + public const string Warning = "Warn"; + public const string Info = "Info"; + public const string Trace = "Trace"; +} diff --git a/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticEvent.cs b/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticEvent.cs new file mode 100644 index 0000000..9bd66fe --- /dev/null +++ b/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticEvent.cs @@ -0,0 +1,27 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +using System.Diagnostics; + +namespace Elastic.OpenTelemetry.Diagnostics; + +internal readonly struct DiagnosticEvent(Activity? activity = null) : IDiagnosticEvent +{ + public int ManagedThreadId { get; } = Environment.CurrentManagedThreadId; + + public DateTime DateTime { get; } = DateTime.UtcNow; + + public Activity? Activity { get; } = activity ?? Activity.Current; +} + +internal readonly struct DiagnosticEvent(T data, Activity? activity = null) : IDiagnosticEvent +{ + public T Data { get; init; } = data; + + public int ManagedThreadId { get; } = Environment.CurrentManagedThreadId; + + public DateTime DateTime { get; } = DateTime.UtcNow; + + public Activity? Activity { get; } = activity ?? Activity.Current; +} + diff --git a/src/Elastic.OpenTelemetry/Diagnostics/ElasticDiagnosticLoggingObserver.cs b/src/Elastic.OpenTelemetry/Diagnostics/ElasticDiagnosticLoggingObserver.cs new file mode 100644 index 0000000..eda61ce --- /dev/null +++ b/src/Elastic.OpenTelemetry/Diagnostics/ElasticDiagnosticLoggingObserver.cs @@ -0,0 +1,119 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +using System.Diagnostics; +using Elastic.OpenTelemetry.Extensions; + +namespace Elastic.OpenTelemetry.Diagnostics; + +internal sealed class ElasticDiagnosticLoggingObserver(LogFileWriter logFileWriter) : IObserver> +{ + private readonly LogFileWriter _logFileWriter = logFileWriter; + + public void OnNext(KeyValuePair data) + { + if (data.Value is not IDiagnosticEvent) + return; + + switch (data.Key) + { + case ElasticOpenTelemetryDiagnosticSource.AgentBuilderInitializedEvent: + AgentBuilderInitialized(data); + break; + + case ElasticOpenTelemetryDiagnosticSource.AgentBuilderBuiltTracerProviderEvent: + AgentBuilderBuiltTracerProvider(data); + break; + + case ElasticOpenTelemetryDiagnosticSource.AgentBuilderBuiltAgentEvent: + AgentBuilderBuiltAgent(data); + break; + + case ElasticOpenTelemetryDiagnosticSource.AgentBuildCalledMultipleTimesEvent: + AgentBuilderBuildCalledMultipleTimes(data); + break; + + case ElasticOpenTelemetryDiagnosticSource.AgentSetAgentCalledMultipleTimesEvent: + AgentBuilderSetAgentCalledMultipleTimes(data); + break; + + case ElasticOpenTelemetryDiagnosticSource.AgentBuilderRegisteredDistroServicesEvent: + AgentBuilderRegisteredDistroServices(data); + break; + + case ElasticOpenTelemetryDiagnosticSource.TransactionIdAddedEvent: + TransactionIdAdded(data); + break; + + case ElasticOpenTelemetryDiagnosticSource.ProcessorAddedEvent: + ProcessorAdded(data); + break; + + case ElasticOpenTelemetryDiagnosticSource.SourceAddedEvent: + SourceAdded(data); + break; + + default: + break; + } + + void AgentBuilderInitialized(KeyValuePair data) + { + if (data.Value is DiagnosticEvent diagnostic) + _logFileWriter.LogAgentBuilderInitialized(in diagnostic); + } + + void AgentBuilderBuiltTracerProvider(KeyValuePair data) + { + if (data.Value is DiagnosticEvent diagnostic) + _logFileWriter.LogAgentBuilderBuiltTracerProvider(in diagnostic); + } + + void AgentBuilderBuiltAgent(KeyValuePair data) + { + if (data.Value is DiagnosticEvent diagnostic) + _logFileWriter.LogAgentBuilderBuiltAgent(in diagnostic); + } + + void AgentBuilderRegisteredDistroServices(KeyValuePair data) + { + if (data.Value is DiagnosticEvent diagnostic) + _logFileWriter.LogAgentBuilderRegisteredServices(in diagnostic); + } + + void AgentBuilderBuildCalledMultipleTimes(KeyValuePair data) + { + if (data.Value is DiagnosticEvent diagnostic) + _logFileWriter.LogAgentBuilderBuildCalledMultipleTimes(in diagnostic); + } + + void AgentBuilderSetAgentCalledMultipleTimes(KeyValuePair data) + { + if (data.Value is DiagnosticEvent diagnostic) + _logFileWriter.LogAgentBuilderSetAgentCalledMultipleTimes(in diagnostic); + } + + void TransactionIdAdded(KeyValuePair data) + { + if (data.Value is DiagnosticEvent diagnostic) + _logFileWriter.LogAddedTransactionIdTag(in diagnostic); + } + + void ProcessorAdded(KeyValuePair data) + { + if (data.Value is DiagnosticEvent diagnostic) + _logFileWriter.LogProcessorAdded(in diagnostic); + } + + void SourceAdded(KeyValuePair data) + { + if (data.Value is DiagnosticEvent diagnostic) + _logFileWriter.LogSourceAdded(in diagnostic); + } + } + + public void OnCompleted() { } + + public void OnError(Exception error) { } +} + diff --git a/src/Elastic.OpenTelemetry/Diagnostics/ElasticOpenTelemetryDiagnosticSource.cs b/src/Elastic.OpenTelemetry/Diagnostics/ElasticOpenTelemetryDiagnosticSource.cs new file mode 100644 index 0000000..f7e09f9 --- /dev/null +++ b/src/Elastic.OpenTelemetry/Diagnostics/ElasticOpenTelemetryDiagnosticSource.cs @@ -0,0 +1,91 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +using System.Diagnostics; +using Elastic.OpenTelemetry.Extensions; +using Elastic.OpenTelemetry.Processors; + +namespace Elastic.OpenTelemetry.Diagnostics; + +internal static class ElasticOpenTelemetryDiagnosticSource +{ + public const string DiagnosticSourceName = "Elastic.OpenTelemetry"; + + internal static readonly DiagnosticSource DiagnosticSource = new DiagnosticListener(DiagnosticSourceName); + + public static void Log(string name) + { + if (DiagnosticSource.IsEnabled(name)) + DiagnosticSource.Write(name, new DiagnosticEvent()); + } + + public static void Log(string name, IDiagnosticEvent data) + { + if (DiagnosticSource.IsEnabled(name)) + DiagnosticSource.Write(name, data); + } + + // Events + + public const string AgentBuilderInitializedEvent = "AgentBuilderInitialized"; + + public const string AgentBuilderBuiltTracerProviderEvent = "AgentBuilderBuiltTracerProvider"; + + public const string AgentBuilderRegisteredDistroServicesEvent = "RegisteredDistroServices"; + + public const string AgentBuilderBuiltAgentEvent = "AgentBuilderBuiltAgent"; + + public const string TransactionIdAddedEvent = "TransactionIdAdded"; + + public const string ProcessorAddedEvent = "ProcessorAdded"; + + public const string SourceAddedEvent = "SourceAdded"; + + public const string AgentBuildCalledMultipleTimesEvent = "AgentBuildCalledMultipleTimes"; + + public const string AgentSetAgentCalledMultipleTimesEvent = "AgentSetAgentCalledMultipleTimes"; + + // Log messages + + public const string TransactionIdProcessorTagAddedLog = + $"{nameof(TransactionIdProcessor)} added 'transaction.id' tag to Activity."; + + public static void LogAgentBuilderInitialized(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) + { + var message = diagnostic.Data is not null + ? $"AgentBuilder initialized{Environment.NewLine}{diagnostic.Data}." + : "AgentBuilder initialized."; + + logFileWriter.WriteInfoLogLine(diagnostic, message); + } + + public static void LogAgentBuilderBuiltTracerProvider(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) => + logFileWriter.WriteInfoLogLine(diagnostic, "AgentBuilder built TracerProvider."); + + public static void LogAgentBuilderBuiltAgent(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) => + logFileWriter.WriteInfoLogLine(diagnostic, "AgentBuilder built Agent."); + + public static void LogAgentBuilderRegisteredServices(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) => + logFileWriter.WriteInfoLogLine(diagnostic, "AgentBuilder registered agent services into IServiceCollection."); + + public static void LogAgentBuilderBuildCalledMultipleTimes(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) => + logFileWriter.WriteErrorLogLine(diagnostic, Agent.BuildErrorMessage); + + public static void LogAgentBuilderSetAgentCalledMultipleTimes(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) => + logFileWriter.WriteErrorLogLine(diagnostic, Agent.SetAgentErrorMessage); + + public static void LogAddedTransactionIdTag(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) => + logFileWriter.WriteTraceLogLine(diagnostic, TransactionIdProcessorTagAddedLog); + + public static void LogProcessorAdded(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) + { + var message = $"Added '{diagnostic.Data.ProcessorType}' processor to '{diagnostic.Data.BuilderType.Name}'."; + logFileWriter.WriteInfoLogLine(diagnostic, message); + } + + public static void LogSourceAdded(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) + { + var message = $"Added '{diagnostic.Data.ActivitySourceName}' ActivitySource to '{diagnostic.Data.BuilderType.Name}'."; + logFileWriter.WriteInfoLogLine(diagnostic, message); + } +} diff --git a/src/Elastic.OpenTelemetry/Diagnostics/IDiagnosticEvent.cs b/src/Elastic.OpenTelemetry/Diagnostics/IDiagnosticEvent.cs new file mode 100644 index 0000000..d1b2ed2 --- /dev/null +++ b/src/Elastic.OpenTelemetry/Diagnostics/IDiagnosticEvent.cs @@ -0,0 +1,14 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +using System.Diagnostics; + +namespace Elastic.OpenTelemetry.Diagnostics; + +internal interface IDiagnosticEvent +{ + int ManagedThreadId { get; } + DateTime DateTime { get; } + Activity? Activity { get; } +} + diff --git a/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs b/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs new file mode 100644 index 0000000..b1ce24d --- /dev/null +++ b/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs @@ -0,0 +1,188 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +using System.Diagnostics; +using System.Runtime.InteropServices; +using System.Text; +using System.Threading.Channels; + +namespace Elastic.OpenTelemetry.Diagnostics; + +internal sealed class LogFileWriter : IDisposable, IAsyncDisposable +{ + public static readonly bool FileLoggingEnabled = IsFileLoggingEnabled(); + + private readonly StreamWriter _streamWriter; + private readonly Channel _channel = Channel.CreateBounded(new BoundedChannelOptions(1024) + { + SingleReader = true, + SingleWriter = false, + AllowSynchronousContinuations = true, + FullMode = BoundedChannelFullMode.Wait + }); + + private LogFileWriter() + { + var process = Process.GetCurrentProcess(); + + var configuredPath = Environment.GetEnvironmentVariable(EnvironmentVariables.ElasticOtelLogDirectoryEnvironmentVariable); + + // Defaults to local application data (C:\Users\{username}\AppData\Local\Elastic on Windows; $HOME/.local/share/elastic on Linux) + var path = string.IsNullOrEmpty(configuredPath) + ? Path.Combine(Environment.GetFolderPath(Environment.SpecialFolder.LocalApplicationData), GetElasticFolder) + : configuredPath; + + // When ordered by filename, we get see logs from the same process grouped, then ordered by oldest to newest, then the PID for that instance + LogFilePath = Path.Combine(path, $"{process.ProcessName}_{DateTimeOffset.UtcNow.ToUnixTimeMilliseconds()}_{process.Id}.agent.log"); + + if (!Directory.Exists(path)) + Directory.CreateDirectory(path); + + _streamWriter = new StreamWriter(LogFilePath, Encoding.UTF8, new FileStreamOptions + { + Access = FileAccess.Write, + Mode = FileMode.OpenOrCreate, + }); + + WritingTask = Task.Run(async () => + { + while (await _channel.Reader.WaitToReadAsync().ConfigureAwait(false)) + { + while (_channel.Reader.TryRead(out var logLine)) + { + await _streamWriter.WriteLineAsync(logLine).ConfigureAwait(false); + } + } + }); + + string[] preAmble = [ + $"Elastic OpenTelemetry Distribution: {Agent.InformationalVersion}", + $"Process ID: {process.Id}", + $"Process started: {process.StartTime.ToUniversalTime():yyyy-MM-dd HH:mm:ss.fff}", + ]; + + var builder = StringBuilderCache.Acquire(); + + foreach (var item in preAmble) + { + WriteLogPrefix(DiagnosticErrorLevels.Info, builder); + builder.Append(item); + _streamWriter.WriteLine(builder.ToString()); + builder.Clear(); + } + + _streamWriter.Flush(); + _streamWriter.AutoFlush = true; // Ensure we don't lose logs by not flushing to the file. + + StringBuilderCache.Release(builder); + } + + private static void WriteLogPrefix(string logLevel, StringBuilder builder) => + WriteLogPrefix(Environment.CurrentManagedThreadId, DateTime.UtcNow, logLevel, builder); + + private static void WriteLogPrefix(int managedThreadId, DateTime dateTime, string level, StringBuilder builder) + { + builder.Append('[') + .Append(dateTime.ToString("yyyy-MM-dd HH:mm:ss.fff")) + .Append("][") + .Append(managedThreadId == -1 ? "-" : managedThreadId) + .Append("][") + .Append(level) + .Append(']'); + + var length = builder.Length; + var padding = 40 - length; + + for (var i = 0; i < padding; i++) + { + builder.Append(' '); + } + } + + public static LogFileWriter Instance { get; } = new(); + + public string LogFilePath { get; } + + public Task WritingTask { get; } + + public void WriteErrorLogLine(IDiagnosticEvent diagnosticEvent, string message) => + WriteLogLine(diagnosticEvent, DiagnosticErrorLevels.Error, message); + + public void WriteInfoLogLine(IDiagnosticEvent diagnosticEvent, string message) => + WriteLogLine(diagnosticEvent, DiagnosticErrorLevels.Info, message); + + public void WriteTraceLogLine(IDiagnosticEvent diagnosticEvent, string message) => + WriteLogLine(diagnosticEvent, DiagnosticErrorLevels.Trace, message); + + public void WriteLogLine(IDiagnosticEvent diagnosticEvent, string logLevel, string message) => + WriteLogLine(diagnosticEvent.Activity, diagnosticEvent.ManagedThreadId, diagnosticEvent.DateTime, logLevel, message); + + public void WriteLogLine(Activity? activity, int managedThreadId, DateTime dateTime, string logLevel, string logLine) + { + var builder = StringBuilderCache.Acquire(); + WriteLogPrefix(managedThreadId, dateTime, logLevel, builder); + builder.Append(logLine); + + if (activity is not null) + { + // Accessing activity.Id here will cause the Id to be initialized + // before the sampler runs in case where the activity is created using legacy way + // i.e. new Activity("Operation name"). This will result in Id not reflecting the + // correct sampling flags + // https://github.com/dotnet/runtime/issues/61857 + + var activityId = string.Concat("00-", activity.TraceId.ToHexString(), "-", activity.SpanId.ToHexString()); + builder.Append($" <{activityId}>"); + } + + var spin = new SpinWait(); + while (true) + { + if (_channel.Writer.TryWrite(StringBuilderCache.GetStringAndRelease(builder))) + break; + spin.SpinOnce(); + } + } + + private static bool IsFileLoggingEnabled() + { + var enableFileLogging = true; + + var isEnabledValue = Environment.GetEnvironmentVariable(EnvironmentVariables.ElasticOtelFileLogging); + + if (!string.IsNullOrEmpty(isEnabledValue)) + { + if (int.TryParse(isEnabledValue, out var intValue)) + enableFileLogging = intValue == 1; + else if (bool.TryParse(isEnabledValue, out var boolValue)) + enableFileLogging = boolValue; + } + + return enableFileLogging; + } + + private static string GetElasticFolder => + RuntimeInformation.IsOSPlatform(OSPlatform.Windows) ? "Elastic" : "elastic"; + + public void Dispose() + { + // We don't wait for the channel to be drained which is probably the correct choice. + // Dispose should be a quick operation with no chance of exceptions. + // We should document methods to wait for the WritingTask, before disposal, if that matters to the + // consumer. + + _channel.Writer.TryComplete(); + _streamWriter.Dispose(); + } + + public async ValueTask DisposeAsync() + { + // We don't wait for the channel to be drained which is probably the correct choice. + // Dispose should be a quick operation with no chance of exceptions. + // We should document methods to await the WritingTask, before disposal, if that matters to the + // consumer. + + _channel.Writer.TryComplete(); + await _streamWriter.DisposeAsync().ConfigureAwait(false); + } +} diff --git a/src/Elastic.OpenTelemetry/Diagnostics/LoggingDiagnosticSourceListener.cs b/src/Elastic.OpenTelemetry/Diagnostics/LoggingDiagnosticSourceListener.cs new file mode 100644 index 0000000..12bce82 --- /dev/null +++ b/src/Elastic.OpenTelemetry/Diagnostics/LoggingDiagnosticSourceListener.cs @@ -0,0 +1,26 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +using System.Diagnostics; + +namespace Elastic.OpenTelemetry.Diagnostics; + +internal sealed class LoggingDiagnosticSourceListener(LogFileWriter logFileWriter) : IObserver +{ + private readonly object _lock = new(); + private readonly LogFileWriter _logFileWriter = logFileWriter; + + public void OnNext(DiagnosticListener listener) + { + if (listener.Name == ElasticOpenTelemetryDiagnosticSource.DiagnosticSourceName) + { + lock (_lock) + listener.Subscribe(new ElasticDiagnosticLoggingObserver(_logFileWriter)); + } + } + + public void OnCompleted() { } + + public void OnError(Exception error) { } +} + diff --git a/src/Elastic.OpenTelemetry/Diagnostics/LoggingEventListener.cs b/src/Elastic.OpenTelemetry/Diagnostics/LoggingEventListener.cs new file mode 100644 index 0000000..40f0550 --- /dev/null +++ b/src/Elastic.OpenTelemetry/Diagnostics/LoggingEventListener.cs @@ -0,0 +1,127 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +using System.Diagnostics.Tracing; +using System.Text; + +namespace Elastic.OpenTelemetry.Diagnostics; + +internal sealed class LoggingEventListener : EventListener, IAsyncDisposable +{ + public const string OpenTelemetrySdkEventSourceNamePrefix = "OpenTelemetry-"; + + private readonly LogFileWriter _logFileWriter; + private readonly EventLevel _eventLevel = EventLevel.Informational; + + public LoggingEventListener(LogFileWriter logFileWriter) + { + _logFileWriter = logFileWriter; + + var eventLevel = Environment.GetEnvironmentVariable(EnvironmentVariables.ElasticOtelLogLevelEnvironmentVariable); + + if (!string.IsNullOrEmpty(eventLevel)) + { + _eventLevel = eventLevel.ToLowerInvariant() switch + { + "trace" => EventLevel.Verbose, + "info" => EventLevel.Informational, + "warning" => EventLevel.Warning, + "error" => EventLevel.Error, + "critical" => EventLevel.Critical, + _ => EventLevel.Informational // fallback to info level + }; + } + } + + public override void Dispose() + { + _logFileWriter.Dispose(); + base.Dispose(); + } + + public ValueTask DisposeAsync() => _logFileWriter.DisposeAsync(); + + protected override void OnEventSourceCreated(EventSource eventSource) + { + if (eventSource.Name.StartsWith(OpenTelemetrySdkEventSourceNamePrefix, StringComparison.Ordinal)) + EnableEvents(eventSource, _eventLevel, EventKeywords.All); + + base.OnEventSourceCreated(eventSource); + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + if (!eventData.EventSource.Name.StartsWith(OpenTelemetrySdkEventSourceNamePrefix, StringComparison.Ordinal)) + { + // Workaround for https://github.com/dotnet/runtime/issues/31927 + // EventCounters are published to all EventListeners, regardless of + // which EventSource providers a listener is enabled for. + return; + } + + // This should generally be reasonably efficient but we can consider switching + // to a rented array and Span if required. + var builder = StringBuilderCache.Acquire(); + + CreateLogMessage(eventData, builder); + + try + { + // TODO - We can only get the OS thread ID from the args - Do we send that instead?? + // As per this issue - https://github.com/dotnet/runtime/issues/13125 - OnEventWritten may be on a different thread + // so we can't use the Environment.CurrentManagedThreadId value here. + _logFileWriter.WriteLogLine(null, -1, eventData.TimeStamp, GetLevel(eventData), StringBuilderCache.GetStringAndRelease(builder)); + } + catch (Exception) + { + // TODO - We might want to block writing further events if we reach here as it's + // likely a file access issue + } + + static string GetLevel(EventWrittenEventArgs eventData) => + eventData.Level switch + { + EventLevel.Critical => DiagnosticErrorLevels.Critical, + EventLevel.Error => DiagnosticErrorLevels.Error, + EventLevel.Warning => DiagnosticErrorLevels.Warning, + EventLevel.Informational => DiagnosticErrorLevels.Info, + EventLevel.Verbose => DiagnosticErrorLevels.Trace, + EventLevel.LogAlways => "N/A", + _ => throw new Exception("Unhandled event data level") + }; + + static void CreateLogMessage(EventWrittenEventArgs eventData, StringBuilder builder) + { + // Handle events from the OpenTelemetry SDK + if (eventData.EventSource.Name.StartsWith(OpenTelemetrySdkEventSourceNamePrefix) && eventData.Message is not null) + { + LogMessageAndPayload(eventData, builder); + } + + static void LogMessageAndPayload(EventWrittenEventArgs eventData, StringBuilder builder) + { + builder.Append($"OTEL-SDK: [{eventData.OSThreadId}] "); + builder.Append(eventData.Message); + + if (eventData.Payload is not null) + { + for (var i = 0; i < eventData.Payload.Count; i++) + { + builder.Append(" - "); + + var payload = eventData.Payload[i]; + + if (payload is not null) + { + builder.Append(payload.ToString() ?? "null"); + } + else + { + builder.Append("null"); + } + } + } + } + } + } +} diff --git a/src/Elastic.OpenTelemetry/Diagnostics/StringBuilderCache.cs b/src/Elastic.OpenTelemetry/Diagnostics/StringBuilderCache.cs new file mode 100644 index 0000000..644d7f9 --- /dev/null +++ b/src/Elastic.OpenTelemetry/Diagnostics/StringBuilderCache.cs @@ -0,0 +1,61 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +using System.Text; + +namespace Elastic.OpenTelemetry.Diagnostics; + +// SOURCE: https://github.com/dotnet/runtime/blob/main/src/libraries/Common/src/System/Text/StringBuilderCache.cs +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +internal static class StringBuilderCache +{ + // The value 360 was chosen in discussion with performance experts as a compromise between using + // as little memory per thread as possible and still covering a large part of short-lived + // StringBuilder creations on the startup path of VS designers. + internal const int MaxBuilderSize = 360; + private const int DefaultCapacity = 64; // At least as large as the prefix + + [ThreadStatic] + private static StringBuilder? CachedInstance; + + /// Get a StringBuilder for the specified capacity. + /// If a StringBuilder of an appropriate size is cached, it will be returned and the cache emptied. + public static StringBuilder Acquire(int capacity = DefaultCapacity) + { + if (capacity <= MaxBuilderSize) + { + var sb = CachedInstance; + if (sb != null) + { + // Avoid StringBuilder block fragmentation by getting a new StringBuilder + // when the requested size is larger than the current capacity + if (capacity <= sb.Capacity) + { + CachedInstance = null; + sb.Clear(); + return sb; + } + } + } + + return new StringBuilder(capacity); + } + + /// Place the specified builder in the cache if it is not too big. + public static void Release(StringBuilder sb) + { + if (sb.Capacity <= MaxBuilderSize) + { + CachedInstance = sb; + } + } + + /// ToString() the StringBuilder, Release it to the cache, and return the resulting string. + public static string GetStringAndRelease(StringBuilder sb) + { + var result = sb.ToString(); + Release(sb); + return result; + } +} diff --git a/src/Elastic.OpenTelemetry/Elastic.OpenTelemetry.csproj b/src/Elastic.OpenTelemetry/Elastic.OpenTelemetry.csproj index fdb9eeb..26d01bd 100644 --- a/src/Elastic.OpenTelemetry/Elastic.OpenTelemetry.csproj +++ b/src/Elastic.OpenTelemetry/Elastic.OpenTelemetry.csproj @@ -18,5 +18,9 @@ + + + + diff --git a/src/Elastic.OpenTelemetry/EnvironmentVariables.cs b/src/Elastic.OpenTelemetry/EnvironmentVariables.cs new file mode 100644 index 0000000..f5fc33c --- /dev/null +++ b/src/Elastic.OpenTelemetry/EnvironmentVariables.cs @@ -0,0 +1,11 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +namespace Elastic.OpenTelemetry; + +internal static class EnvironmentVariables +{ + public const string ElasticOtelFileLogging = "ELASTIC_OTEL_ENABLE_FILE_LOGGING"; + public const string ElasticOtelLogDirectoryEnvironmentVariable = "ELASTIC_OTEL_LOG_DIRECTORY"; + public const string ElasticOtelLogLevelEnvironmentVariable = "ELASTIC_OTEL_LOG_LEVEL"; +} diff --git a/src/Elastic.OpenTelemetry/Extensions/TraceBuilderProviderExtensions.cs b/src/Elastic.OpenTelemetry/Extensions/TraceBuilderProviderExtensions.cs index 55c8440..828ff75 100644 --- a/src/Elastic.OpenTelemetry/Extensions/TraceBuilderProviderExtensions.cs +++ b/src/Elastic.OpenTelemetry/Extensions/TraceBuilderProviderExtensions.cs @@ -5,22 +5,48 @@ using OpenTelemetry.Exporter; using OpenTelemetry.Trace; using OpenTelemetry; +using System.Diagnostics; +using Elastic.OpenTelemetry.Diagnostics; + +using static Elastic.OpenTelemetry.Diagnostics.ElasticOpenTelemetryDiagnosticSource; namespace Elastic.OpenTelemetry.Extensions; +internal readonly record struct AddProcessorEvent(Type ProcessorType, Type BuilderType); + +internal readonly record struct AddSourceEvent(string ActivitySourceName, Type BuilderType); + /// Provides Elastic APM extensions to public static class TraceBuilderProviderExtensions { - //TODO binder source generator on Build() to make it automatic? + //TODO binder source generator on Build() to make it automatic? /// Include Elastic APM Trace Processors to ensure data is enriched and extended. - public static TracerProviderBuilder AddElasticProcessors(this TracerProviderBuilder builder) => - builder - .AddProcessor(new TransactionIdProcessor()); - - /// - /// Adds the OTLP exporter to the tracer, configured to send data to an Elastic APM backend. - /// - public static TracerProviderBuilder AddElasticOtlpExporter(this TracerProviderBuilder builder) => AddElasticOtlpExporter(builder, null, null); + public static TracerProviderBuilder AddElasticProcessors(this TracerProviderBuilder builder) => + builder.LogAndAddProcessor(new TransactionIdProcessor()); + + internal static TracerProviderBuilder LogAndAddProcessor(this TracerProviderBuilder builder, BaseProcessor processor) + { + Log(ProcessorAddedEvent, new DiagnosticEvent() + { + Data = new(processor.GetType(), builder.GetType()) + }); + return builder.AddProcessor(processor); + } + + internal static TracerProviderBuilder LogAndAddSource(this TracerProviderBuilder builder, string sourceName) + { + Log(SourceAddedEvent, new DiagnosticEvent() + { + Data = new(sourceName, builder.GetType()) + }); + return builder.AddSource(sourceName); + } + + /// + /// Adds the OTLP exporter to the tracer, configured to send data to an Elastic APM backend. + /// + public static TracerProviderBuilder AddElasticOtlpExporter(this TracerProviderBuilder builder) => + AddElasticOtlpExporter(builder, null, null); /// /// Adds the OTLP exporter to the tracer, configured to send data to an Elastic APM backend. @@ -35,6 +61,7 @@ public static TracerProviderBuilder AddElasticProcessors(this TracerProviderBuil public static TracerProviderBuilder AddElasticOtlpExporter(this TracerProviderBuilder builder, Action? configure, string? name) { // TODO - We need a clean way to test this behaviour + // TODO - Logging const string tracesPath = "/v1/traces"; diff --git a/src/Elastic.OpenTelemetry/IAgent.cs b/src/Elastic.OpenTelemetry/IAgent.cs index 65d6668..75111cc 100644 --- a/src/Elastic.OpenTelemetry/IAgent.cs +++ b/src/Elastic.OpenTelemetry/IAgent.cs @@ -6,6 +6,14 @@ namespace Elastic.OpenTelemetry; /// /// An Elastic OpenTelemetry Distribution agent. /// -public interface IAgent : IDisposable +public interface IAgent : IDisposable, IAsyncDisposable { } + +internal interface IServiceProviderAgent : IAgent +{ + /// + /// + /// + IServiceProvider ServiceProvider { get; } +} diff --git a/src/Elastic.OpenTelemetry/Processors/ElasticProcessor.cs b/src/Elastic.OpenTelemetry/Processors/ElasticProcessor.cs new file mode 100644 index 0000000..ee69d63 --- /dev/null +++ b/src/Elastic.OpenTelemetry/Processors/ElasticProcessor.cs @@ -0,0 +1,33 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +using System.Diagnostics; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using OpenTelemetry; + +namespace Elastic.OpenTelemetry.Processors; + +/// +/// +/// +public abstract class ElasticProcessor : BaseProcessor, IElasticProcessor +{ + /// + /// + /// + protected static ILogger Logger { get; private set; } = NullLogger.Instance; + + void IElasticProcessor.Initialize(IServiceProvider serviceProvider) + { + var resolvedLogger = serviceProvider.GetService>(); + + if (resolvedLogger is ILogger logger) + { + Logger = logger; + } + + Logger.LogInformation("Initialised {ProcessorType}.", typeof(T)); + } +} diff --git a/src/Elastic.OpenTelemetry/Processors/IElasticProcessor.cs b/src/Elastic.OpenTelemetry/Processors/IElasticProcessor.cs new file mode 100644 index 0000000..314d646 --- /dev/null +++ b/src/Elastic.OpenTelemetry/Processors/IElasticProcessor.cs @@ -0,0 +1,9 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +namespace Elastic.OpenTelemetry.Processors; + +internal interface IElasticProcessor +{ + void Initialize(IServiceProvider serviceProvider); +} diff --git a/src/Elastic.OpenTelemetry/Processors/TransactionIdProcessor.cs b/src/Elastic.OpenTelemetry/Processors/TransactionIdProcessor.cs index 5735069..f29f9c7 100644 --- a/src/Elastic.OpenTelemetry/Processors/TransactionIdProcessor.cs +++ b/src/Elastic.OpenTelemetry/Processors/TransactionIdProcessor.cs @@ -1,30 +1,38 @@ // Licensed to Elasticsearch B.V under one or more agreements. // Elasticsearch B.V licenses this file to you under the Apache 2.0 License. // See the LICENSE file in the project root for more information -using OpenTelemetry; using System.Diagnostics; +using Elastic.OpenTelemetry.Diagnostics; +using Microsoft.Extensions.Logging; + +using static Elastic.OpenTelemetry.Diagnostics.ElasticOpenTelemetryDiagnosticSource; namespace Elastic.OpenTelemetry.Processors; /// /// /// -public class TransactionIdProcessor : BaseProcessor +public class TransactionIdProcessor : ElasticProcessor { /// /// /// - public const string TransactionIdTagName = "transaction.id"; + public const string TransactionIdTagName = "transaction.id"; - private readonly AsyncLocal _currentTransactionId = new(); + private readonly AsyncLocal _currentTransactionId = new(); /// - public override void OnStart(Activity activity) - { - if (activity.Parent == null) - _currentTransactionId.Value = activity.SpanId; + public override void OnStart(Activity activity) + { + if (activity.Parent == null) + _currentTransactionId.Value = activity.SpanId; + + if (_currentTransactionId.Value.HasValue) + { + activity.SetTag(TransactionIdTagName, _currentTransactionId.Value.Value.ToString()); - if (_currentTransactionId.Value.HasValue) - activity.SetTag(TransactionIdTagName, _currentTransactionId.Value.Value.ToString()); - } + Log(TransactionIdAddedEvent, new DiagnosticEvent(activity)); + Logger.LogTrace(TransactionIdProcessorTagAddedLog); + } + } } diff --git a/tests/Directory.Build.props b/tests/Directory.Build.props index 9bf0584..79246d4 100644 --- a/tests/Directory.Build.props +++ b/tests/Directory.Build.props @@ -2,6 +2,9 @@ + true + $(SolutionRoot)\build\keys\keypair.snk + True diff --git a/tests/Elastic.OpenTelemetry.Tests/ProcessorTests.cs b/tests/Elastic.OpenTelemetry.Tests/ProcessorTests.cs new file mode 100644 index 0000000..b926b05 --- /dev/null +++ b/tests/Elastic.OpenTelemetry.Tests/ProcessorTests.cs @@ -0,0 +1,31 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +using Microsoft.Extensions.DependencyInjection; + +namespace Elastic.OpenTelemetry.Tests; + +public class ProcessorTests +{ + [Fact] + public void AllElasticProcessors_Should_BeAddedToDependencyInjectionContainer() + { + var sc = new ServiceCollection(); + sc.AddElasticOpenTelemetry(); + var sp = sc.BuildServiceProvider(); + + var processors = AppDomain.CurrentDomain.GetAssemblies() + .SelectMany(s => s.GetTypes()) + .Where(t => typeof(IElasticProcessor).IsAssignableFrom(t) && t.IsClass && !t.IsAbstract) + .ToArray(); + + var registeredProcessors = sp.GetRequiredService>().ToArray(); + + processors.Length.Should().Be(registeredProcessors.Length); + + foreach (var processor in processors) + { + _ = registeredProcessors.Single(rp => rp.GetType() == processor); + } + } +} From f7b88a36da17bfd0487d3f16527385b67110f34f Mon Sep 17 00:00:00 2001 From: Steve Gordon Date: Wed, 7 Feb 2024 15:15:36 +0100 Subject: [PATCH 2/6] Honour configured logging level --- .../Diagnostics/DiagnosticErrorLevels.cs | 25 +++++++- .../Diagnostics/LogFileWriter.cs | 58 ++++++++++++++++--- .../Diagnostics/LogLevel.cs | 14 +++++ .../Diagnostics/LoggingEventListener.cs | 39 ++++++------- 4 files changed, 105 insertions(+), 31 deletions(-) create mode 100644 src/Elastic.OpenTelemetry/Diagnostics/LogLevel.cs diff --git a/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticErrorLevels.cs b/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticErrorLevels.cs index 15675dd..977c32b 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticErrorLevels.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticErrorLevels.cs @@ -7,7 +7,30 @@ internal static class DiagnosticErrorLevels { public const string Critical = "Critical"; public const string Error = "Error"; - public const string Warning = "Warn"; + public const string Warning = "Warning"; public const string Info = "Info"; public const string Trace = "Trace"; + + public static LogLevel ToLogLevel(string logLevelString) => + logLevelString switch + { + Critical => LogLevel.Critical, + Error => LogLevel.Error, + Warning => LogLevel.Warning, + Info => LogLevel.Info, + Trace => LogLevel.Trace, + _ => LogLevel.Unknown, + }; + + public static string AsString(this LogLevel logLevel) => + logLevel switch + { + LogLevel.Critical => Critical, + LogLevel.Error => Error, + LogLevel.Warning => Warning, + LogLevel.Info => Info, + LogLevel.Trace => Trace, + LogLevel.Unknown => string.Empty, + _ => string.Empty + }; } diff --git a/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs b/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs index b1ce24d..cd64a8c 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs @@ -65,7 +65,8 @@ private LogFileWriter() foreach (var item in preAmble) { - WriteLogPrefix(DiagnosticErrorLevels.Info, builder); + // These preamble entries are ALWAYS logged, regardless of the configured log level + WriteLogPrefix(LogLevel.Info, builder); builder.Append(item); _streamWriter.WriteLine(builder.ToString()); builder.Clear(); @@ -77,17 +78,46 @@ private LogFileWriter() StringBuilderCache.Release(builder); } - private static void WriteLogPrefix(string logLevel, StringBuilder builder) => + private static readonly LogLevel ConfiguredLogLevel = GetConfiguredLogLevel(); + + public static LogLevel GetConfiguredLogLevel() + { + var logLevel = LogLevel.Info; + + var logLevelEnvironmentVariable = Environment.GetEnvironmentVariable(EnvironmentVariables.ElasticOtelLogLevelEnvironmentVariable); + + if (!string.IsNullOrEmpty(logLevelEnvironmentVariable)) + { + if (logLevelEnvironmentVariable.Equals(DiagnosticErrorLevels.Trace, StringComparison.OrdinalIgnoreCase)) + logLevel = LogLevel.Trace; + + else if (logLevelEnvironmentVariable.Equals(DiagnosticErrorLevels.Info, StringComparison.OrdinalIgnoreCase)) + logLevel = LogLevel.Info; + + else if (logLevelEnvironmentVariable.Equals(DiagnosticErrorLevels.Warning, StringComparison.OrdinalIgnoreCase)) + logLevel = LogLevel.Warning; + + else if (logLevelEnvironmentVariable.Equals(DiagnosticErrorLevels.Error, StringComparison.OrdinalIgnoreCase)) + logLevel = LogLevel.Error; + + else if (logLevelEnvironmentVariable.Equals(DiagnosticErrorLevels.Critical, StringComparison.OrdinalIgnoreCase)) + logLevel = LogLevel.Critical; + } + + return logLevel; + } + + private static void WriteLogPrefix(LogLevel logLevel, StringBuilder builder) => WriteLogPrefix(Environment.CurrentManagedThreadId, DateTime.UtcNow, logLevel, builder); - private static void WriteLogPrefix(int managedThreadId, DateTime dateTime, string level, StringBuilder builder) + private static void WriteLogPrefix(int managedThreadId, DateTime dateTime, LogLevel level, StringBuilder builder) { builder.Append('[') .Append(dateTime.ToString("yyyy-MM-dd HH:mm:ss.fff")) .Append("][") .Append(managedThreadId == -1 ? "-" : managedThreadId) .Append("][") - .Append(level) + .Append(level.AsString()) .Append(']'); var length = builder.Length; @@ -105,20 +135,30 @@ private static void WriteLogPrefix(int managedThreadId, DateTime dateTime, strin public Task WritingTask { get; } + public void WriteCriticalLogLine(IDiagnosticEvent diagnosticEvent, string message) => + WriteLogLine(diagnosticEvent, LogLevel.Critical, message); + public void WriteErrorLogLine(IDiagnosticEvent diagnosticEvent, string message) => - WriteLogLine(diagnosticEvent, DiagnosticErrorLevels.Error, message); + WriteLogLine(diagnosticEvent, LogLevel.Error, message); + + public void WriteWarningLogLine(IDiagnosticEvent diagnosticEvent, string message) => + WriteLogLine(diagnosticEvent, LogLevel.Warning, message); public void WriteInfoLogLine(IDiagnosticEvent diagnosticEvent, string message) => - WriteLogLine(diagnosticEvent, DiagnosticErrorLevels.Info, message); + WriteLogLine(diagnosticEvent, LogLevel.Info, message); public void WriteTraceLogLine(IDiagnosticEvent diagnosticEvent, string message) => - WriteLogLine(diagnosticEvent, DiagnosticErrorLevels.Trace, message); + WriteLogLine(diagnosticEvent, LogLevel.Trace, message); - public void WriteLogLine(IDiagnosticEvent diagnosticEvent, string logLevel, string message) => + public void WriteLogLine(IDiagnosticEvent diagnosticEvent, LogLevel logLevel, string message) => WriteLogLine(diagnosticEvent.Activity, diagnosticEvent.ManagedThreadId, diagnosticEvent.DateTime, logLevel, message); - public void WriteLogLine(Activity? activity, int managedThreadId, DateTime dateTime, string logLevel, string logLine) + public void WriteLogLine(Activity? activity, int managedThreadId, DateTime dateTime, LogLevel logLevel, string logLine) { + // We skip logging for any log level higher (numerically) than the configured log level + if (logLevel > ConfiguredLogLevel) + return; + var builder = StringBuilderCache.Acquire(); WriteLogPrefix(managedThreadId, dateTime, logLevel, builder); builder.Append(logLine); diff --git a/src/Elastic.OpenTelemetry/Diagnostics/LogLevel.cs b/src/Elastic.OpenTelemetry/Diagnostics/LogLevel.cs new file mode 100644 index 0000000..75fe2d3 --- /dev/null +++ b/src/Elastic.OpenTelemetry/Diagnostics/LogLevel.cs @@ -0,0 +1,14 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +namespace Elastic.OpenTelemetry.Diagnostics; + +internal enum LogLevel +{ + Unknown = 0, + Critical = 1, + Error = 2, + Warning = 3, + Info = 4, + Trace = 5 +} diff --git a/src/Elastic.OpenTelemetry/Diagnostics/LoggingEventListener.cs b/src/Elastic.OpenTelemetry/Diagnostics/LoggingEventListener.cs index 40f0550..1d7c4cb 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/LoggingEventListener.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/LoggingEventListener.cs @@ -17,20 +17,17 @@ public LoggingEventListener(LogFileWriter logFileWriter) { _logFileWriter = logFileWriter; - var eventLevel = Environment.GetEnvironmentVariable(EnvironmentVariables.ElasticOtelLogLevelEnvironmentVariable); + var eventLevel = LogFileWriter.GetConfiguredLogLevel(); - if (!string.IsNullOrEmpty(eventLevel)) + _eventLevel = eventLevel switch { - _eventLevel = eventLevel.ToLowerInvariant() switch - { - "trace" => EventLevel.Verbose, - "info" => EventLevel.Informational, - "warning" => EventLevel.Warning, - "error" => EventLevel.Error, - "critical" => EventLevel.Critical, - _ => EventLevel.Informational // fallback to info level - }; - } + LogLevel.Trace => EventLevel.Verbose, + LogLevel.Info => EventLevel.Informational, + LogLevel.Warning => EventLevel.Warning, + LogLevel.Error => EventLevel.Error, + LogLevel.Critical => EventLevel.Critical, + _ => EventLevel.Informational // fallback to info level + }; } public override void Dispose() @@ -70,7 +67,7 @@ protected override void OnEventWritten(EventWrittenEventArgs eventData) // TODO - We can only get the OS thread ID from the args - Do we send that instead?? // As per this issue - https://github.com/dotnet/runtime/issues/13125 - OnEventWritten may be on a different thread // so we can't use the Environment.CurrentManagedThreadId value here. - _logFileWriter.WriteLogLine(null, -1, eventData.TimeStamp, GetLevel(eventData), StringBuilderCache.GetStringAndRelease(builder)); + _logFileWriter.WriteLogLine(null, -1, eventData.TimeStamp, GetLogLevel(eventData), StringBuilderCache.GetStringAndRelease(builder)); } catch (Exception) { @@ -78,16 +75,16 @@ protected override void OnEventWritten(EventWrittenEventArgs eventData) // likely a file access issue } - static string GetLevel(EventWrittenEventArgs eventData) => + static LogLevel GetLogLevel(EventWrittenEventArgs eventData) => eventData.Level switch { - EventLevel.Critical => DiagnosticErrorLevels.Critical, - EventLevel.Error => DiagnosticErrorLevels.Error, - EventLevel.Warning => DiagnosticErrorLevels.Warning, - EventLevel.Informational => DiagnosticErrorLevels.Info, - EventLevel.Verbose => DiagnosticErrorLevels.Trace, - EventLevel.LogAlways => "N/A", - _ => throw new Exception("Unhandled event data level") + EventLevel.Critical => LogLevel.Critical, + EventLevel.Error => LogLevel.Error, + EventLevel.Warning => LogLevel.Warning, + EventLevel.Informational => LogLevel.Info, + EventLevel.Verbose => LogLevel.Trace, + EventLevel.LogAlways => LogLevel.Unknown, + _ => LogLevel.Unknown }; static void CreateLogMessage(EventWrittenEventArgs eventData, StringBuilder builder) From dfb0aaeb5f71445928f6d2b0d0410b654c9749c6 Mon Sep 17 00:00:00 2001 From: Steve Gordon Date: Wed, 7 Feb 2024 15:46:17 +0100 Subject: [PATCH 3/6] More initial logging --- .../Diagnostics/LogFileWriter.cs | 79 +++++++++++++++---- 1 file changed, 64 insertions(+), 15 deletions(-) diff --git a/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs b/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs index cd64a8c..8d3fb0a 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs @@ -5,6 +5,7 @@ using System.Runtime.InteropServices; using System.Text; using System.Threading.Channels; +using System.Xml.Serialization; namespace Elastic.OpenTelemetry.Diagnostics; @@ -55,27 +56,75 @@ private LogFileWriter() } }); - string[] preAmble = [ - $"Elastic OpenTelemetry Distribution: {Agent.InformationalVersion}", - $"Process ID: {process.Id}", - $"Process started: {process.StartTime.ToUniversalTime():yyyy-MM-dd HH:mm:ss.fff}", - ]; - var builder = StringBuilderCache.Acquire(); - foreach (var item in preAmble) + // Preamble and configuration entries are ALWAYS logged, regardless of the configured log level + LogPreamble(process, builder, _streamWriter); + LogConfiguration(builder, _streamWriter); + + StringBuilderCache.Release(builder); + + _streamWriter.AutoFlush = true; // Ensure we don't lose logs by not flushing to the file. + + static void LogPreamble(Process process, StringBuilder stringBuilder, StreamWriter streamWriter) { - // These preamble entries are ALWAYS logged, regardless of the configured log level - WriteLogPrefix(LogLevel.Info, builder); - builder.Append(item); - _streamWriter.WriteLine(builder.ToString()); - builder.Clear(); + string[] preAmble = [ + $"Elastic OpenTelemetry Distribution: {Agent.InformationalVersion}", + $"Process ID: {process.Id}", + $"Process name: {process.ProcessName}", + $"Process path: {Environment.ProcessPath}", + $"Process started: {process.StartTime.ToUniversalTime():yyyy-MM-dd HH:mm:ss.fff}", + $"Machine name: {Environment.MachineName}", + $"Process username: {Environment.UserName}", + $"User domain name: {Environment.UserDomainName}", + $"Command line: {Environment.CommandLine}", + $"Command current directory: {Environment.CurrentDirectory}", + $"Processor count: {Environment.ProcessorCount}", + $"OS version: {Environment.OSVersion}", + $"CLR version: {Environment.Version}", + ]; + + foreach (var item in preAmble) + { + WriteLogPrefix(LogLevel.Info, stringBuilder); + stringBuilder.Append(item); + streamWriter.WriteLine(stringBuilder.ToString()); + stringBuilder.Clear(); + } + + streamWriter.Flush(); } - _streamWriter.Flush(); - _streamWriter.AutoFlush = true; // Ensure we don't lose logs by not flushing to the file. + static void LogConfiguration(StringBuilder stringBuilder, StreamWriter streamWriter) + { + string[] environmentVariables = [ + EnvironmentVariables.ElasticOtelFileLogging, + EnvironmentVariables.ElasticOtelLogDirectoryEnvironmentVariable, + EnvironmentVariables.ElasticOtelLogLevelEnvironmentVariable + ]; - StringBuilderCache.Release(builder); + foreach (var variable in environmentVariables) + { + var envVarValue = Environment.GetEnvironmentVariable(variable); + + WriteLogPrefix(LogLevel.Info, stringBuilder); + + if (!string.IsNullOrEmpty(envVarValue)) + { + stringBuilder.Append($"Environment variable '{variable}' = '{envVarValue}'."); + streamWriter.WriteLine(stringBuilder.ToString()); + } + else + { + stringBuilder.Append($"Environment variable '{variable}' is not configured."); + streamWriter.WriteLine(stringBuilder.ToString()); + } + + stringBuilder.Clear(); + } + + streamWriter.Flush(); + } } private static readonly LogLevel ConfiguredLogLevel = GetConfiguredLogLevel(); From ba0211fe8681a4a4319bd3ca2db7cf7424e5eef5 Mon Sep 17 00:00:00 2001 From: Steve Gordon Date: Wed, 7 Feb 2024 15:54:07 +0100 Subject: [PATCH 4/6] Cleanup whitespace --- src/Elastic.OpenTelemetry/Agent.cs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/Elastic.OpenTelemetry/Agent.cs b/src/Elastic.OpenTelemetry/Agent.cs index c25f424..9e22d7f 100644 --- a/src/Elastic.OpenTelemetry/Agent.cs +++ b/src/Elastic.OpenTelemetry/Agent.cs @@ -131,11 +131,11 @@ internal static string ParseAssemblyInformationalVersion(string? informationalVe } /* - * InformationalVersion will be in the following format: - * {majorVersion}.{minorVersion}.{patchVersion}.{pre-release label}.{pre-release version}.{gitHeight}+{Git SHA of current commit} - * Ex: 1.5.0-alpha.1.40+807f703e1b4d9874a92bd86d9f2d4ebe5b5d52e4 - * The following parts are optional: pre-release label, pre-release version, git height, Git SHA of current commit - */ + * InformationalVersion will be in the following format: + * {majorVersion}.{minorVersion}.{patchVersion}.{pre-release label}.{pre-release version}.{gitHeight}+{Git SHA of current commit} + * Ex: 1.5.0-alpha.1.40+807f703e1b4d9874a92bd86d9f2d4ebe5b5d52e4 + * The following parts are optional: pre-release label, pre-release version, git height, Git SHA of current commit + */ var indexOfPlusSign = informationalVersion!.IndexOf('+'); return indexOfPlusSign > 0 From a6501a78160be75829defde4932c449b9032115f Mon Sep 17 00:00:00 2001 From: Steve Gordon Date: Wed, 7 Feb 2024 15:58:47 +0100 Subject: [PATCH 5/6] Fix encoding --- src/Elastic.OpenTelemetry/Diagnostics/IDiagnosticEvent.cs | 2 +- src/Elastic.OpenTelemetry/Diagnostics/LogLevel.cs | 2 +- .../Diagnostics/LoggingDiagnosticSourceListener.cs | 2 +- src/Elastic.OpenTelemetry/Processors/IElasticProcessor.cs | 2 +- 4 files changed, 4 insertions(+), 4 deletions(-) diff --git a/src/Elastic.OpenTelemetry/Diagnostics/IDiagnosticEvent.cs b/src/Elastic.OpenTelemetry/Diagnostics/IDiagnosticEvent.cs index d1b2ed2..358c578 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/IDiagnosticEvent.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/IDiagnosticEvent.cs @@ -1,4 +1,4 @@ -// Licensed to Elasticsearch B.V under one or more agreements. +// Licensed to Elasticsearch B.V under one or more agreements. // Elasticsearch B.V licenses this file to you under the Apache 2.0 License. // See the LICENSE file in the project root for more information using System.Diagnostics; diff --git a/src/Elastic.OpenTelemetry/Diagnostics/LogLevel.cs b/src/Elastic.OpenTelemetry/Diagnostics/LogLevel.cs index 75fe2d3..1e64591 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/LogLevel.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/LogLevel.cs @@ -1,4 +1,4 @@ -// Licensed to Elasticsearch B.V under one or more agreements. +// Licensed to Elasticsearch B.V under one or more agreements. // Elasticsearch B.V licenses this file to you under the Apache 2.0 License. // See the LICENSE file in the project root for more information namespace Elastic.OpenTelemetry.Diagnostics; diff --git a/src/Elastic.OpenTelemetry/Diagnostics/LoggingDiagnosticSourceListener.cs b/src/Elastic.OpenTelemetry/Diagnostics/LoggingDiagnosticSourceListener.cs index 12bce82..0c4f7bc 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/LoggingDiagnosticSourceListener.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/LoggingDiagnosticSourceListener.cs @@ -1,4 +1,4 @@ -// Licensed to Elasticsearch B.V under one or more agreements. +// Licensed to Elasticsearch B.V under one or more agreements. // Elasticsearch B.V licenses this file to you under the Apache 2.0 License. // See the LICENSE file in the project root for more information using System.Diagnostics; diff --git a/src/Elastic.OpenTelemetry/Processors/IElasticProcessor.cs b/src/Elastic.OpenTelemetry/Processors/IElasticProcessor.cs index 314d646..7c91ae1 100644 --- a/src/Elastic.OpenTelemetry/Processors/IElasticProcessor.cs +++ b/src/Elastic.OpenTelemetry/Processors/IElasticProcessor.cs @@ -1,4 +1,4 @@ -// Licensed to Elasticsearch B.V under one or more agreements. +// Licensed to Elasticsearch B.V under one or more agreements. // Elasticsearch B.V licenses this file to you under the Apache 2.0 License. // See the LICENSE file in the project root for more information namespace Elastic.OpenTelemetry.Processors; From d411f9da5d4fdd42d7fde5282856dec60f57026c Mon Sep 17 00:00:00 2001 From: Steve Gordon Date: Mon, 12 Feb 2024 14:19:55 +0000 Subject: [PATCH 6/6] Refine DI integration and log messages --- src/Elastic.OpenTelemetry/AgentBuilder.cs | 15 ++--- .../ElasticOtelDistroService.cs | 6 +- .../DependencyInjection/LoggerResolver.cs | 26 +++++++++ .../Diagnostics/DiagnosticErrorLevels.cs | 2 +- .../Diagnostics/DiagnosticEvent.cs | 18 +++--- .../ElasticDiagnosticLoggingObserver.cs | 22 +++---- .../ElasticOpenTelemetryDiagnosticSource.cs | 55 ++++++++++++------ .../Diagnostics/IDiagnosticEvent.cs | 14 ----- .../Diagnostics/LogFileWriter.cs | 58 +++++++++++++++---- .../Diagnostics/LoggerMessages.cs | 26 +++++++++ .../Diagnostics/LoggingEventListener.cs | 46 ++++++++++----- .../TraceBuilderProviderExtensions.cs | 10 +--- src/Elastic.OpenTelemetry/IAgent.cs | 8 --- .../Processors/ElasticProcessor.cs | 33 ----------- .../Processors/IElasticProcessor.cs | 9 --- .../Processors/TransactionIdProcessor.cs | 14 ++--- .../ProcessorTests.cs | 31 ---------- 17 files changed, 205 insertions(+), 188 deletions(-) create mode 100644 src/Elastic.OpenTelemetry/DependencyInjection/LoggerResolver.cs delete mode 100644 src/Elastic.OpenTelemetry/Diagnostics/IDiagnosticEvent.cs create mode 100644 src/Elastic.OpenTelemetry/Diagnostics/LoggerMessages.cs delete mode 100644 src/Elastic.OpenTelemetry/Processors/ElasticProcessor.cs delete mode 100644 src/Elastic.OpenTelemetry/Processors/IElasticProcessor.cs delete mode 100644 tests/Elastic.OpenTelemetry.Tests/ProcessorTests.cs diff --git a/src/Elastic.OpenTelemetry/AgentBuilder.cs b/src/Elastic.OpenTelemetry/AgentBuilder.cs index c2f1a33..9c52517 100644 --- a/src/Elastic.OpenTelemetry/AgentBuilder.cs +++ b/src/Elastic.OpenTelemetry/AgentBuilder.cs @@ -2,9 +2,9 @@ // Elasticsearch B.V licenses this file to you under the Apache 2.0 License. // See the LICENSE file in the project root for more information using System.Diagnostics; +using Elastic.OpenTelemetry.DependencyInjection; using Elastic.OpenTelemetry.Diagnostics; using Elastic.OpenTelemetry.Extensions; -using Elastic.OpenTelemetry.Processors; using Elastic.OpenTelemetry.Resources; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; @@ -59,7 +59,7 @@ public AgentBuilder() DiagnosticListener.AllListeners.Subscribe(listener); } - Log(AgentBuilderInitializedEvent, new DiagnosticEvent(new StackTrace(true))); + Log(AgentBuilderInitializedEvent, () => new DiagnosticEvent(new StackTrace(true))); } // NOTE - Applies to all signals @@ -212,8 +212,8 @@ public IServiceCollection Register(IServiceCollection serviceCollection) _ = serviceCollection .AddHostedService() - .AddSingleton() - .AddSingleton() + .AddSingleton() + .AddSingleton() .AddOpenTelemetry() .WithTracing(TracerProviderBuilderAction); @@ -267,17 +267,12 @@ public void ConfigureOtlpExporter(Action configure, string? _otlpExporterName = name; } - private sealed class ServiceProviderAgent(IServiceProvider serviceProvider) : Agent, IServiceProviderAgent - { - public IServiceProvider ServiceProvider => serviceProvider; - } - private class Agent(TracerProvider? tracerProvider, MeterProvider? meterProvider) : IAgent { private readonly TracerProvider? _tracerProvider = tracerProvider; private readonly MeterProvider? _meterProvider = meterProvider; - internal Agent() : this(null, null) + public Agent() : this(null, null) { } diff --git a/src/Elastic.OpenTelemetry/DependencyInjection/ElasticOtelDistroService.cs b/src/Elastic.OpenTelemetry/DependencyInjection/ElasticOtelDistroService.cs index 34adb87..27e7aeb 100644 --- a/src/Elastic.OpenTelemetry/DependencyInjection/ElasticOtelDistroService.cs +++ b/src/Elastic.OpenTelemetry/DependencyInjection/ElasticOtelDistroService.cs @@ -1,7 +1,7 @@ // Licensed to Elasticsearch B.V under one or more agreements. // Elasticsearch B.V licenses this file to you under the Apache 2.0 License. // See the LICENSE file in the project root for more information -using Elastic.OpenTelemetry.Processors; +using Elastic.OpenTelemetry.DependencyInjection; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Logging; @@ -19,9 +19,7 @@ public Task StartingAsync(CancellationToken cancellationToken) var loggerFactory = _serviceProvider.GetService(); var logger = loggerFactory?.CreateLogger($"{nameof(Elastic)}.{nameof(OpenTelemetry)}") ?? NullLogger.Instance; - logger.LogInformation("Initialising processors."); - foreach (var processor in _serviceProvider.GetServices()) - processor?.Initialize(_serviceProvider); + _serviceProvider.GetService(); logger.LogInformation("Initialising Agent.Current."); Agent.SetAgent(agent, logger); diff --git a/src/Elastic.OpenTelemetry/DependencyInjection/LoggerResolver.cs b/src/Elastic.OpenTelemetry/DependencyInjection/LoggerResolver.cs new file mode 100644 index 0000000..04b7c70 --- /dev/null +++ b/src/Elastic.OpenTelemetry/DependencyInjection/LoggerResolver.cs @@ -0,0 +1,26 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; + +namespace Elastic.OpenTelemetry.DependencyInjection; + +internal sealed class LoggerResolver +{ + private static ILoggerFactory LoggerFactory = NullLoggerFactory.Instance; + + public LoggerResolver(ILoggerFactory loggerFactory) + { + if (LoggerFactory == NullLoggerFactory.Instance) + LoggerFactory = loggerFactory; + } + + internal static ILogger GetLogger() => LoggerFactory.CreateLogger(); + + internal static ILogger GetLogger(ref ILogger? logger) + { + logger = LoggerFactory.CreateLogger(); + return logger; + } +} diff --git a/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticErrorLevels.cs b/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticErrorLevels.cs index 977c32b..daf96e7 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticErrorLevels.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticErrorLevels.cs @@ -7,7 +7,7 @@ internal static class DiagnosticErrorLevels { public const string Critical = "Critical"; public const string Error = "Error"; - public const string Warning = "Warning"; + public const string Warning = "Warn"; public const string Info = "Info"; public const string Trace = "Trace"; diff --git a/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticEvent.cs b/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticEvent.cs index 9bd66fe..0452284 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticEvent.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/DiagnosticEvent.cs @@ -2,26 +2,28 @@ // Elasticsearch B.V licenses this file to you under the Apache 2.0 License. // See the LICENSE file in the project root for more information using System.Diagnostics; +using Elastic.OpenTelemetry.DependencyInjection; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Elastic.OpenTelemetry.Diagnostics; -internal readonly struct DiagnosticEvent(Activity? activity = null) : IDiagnosticEvent +internal class DiagnosticEvent(Activity? activity = null, ILogger? logger = null) { public int ManagedThreadId { get; } = Environment.CurrentManagedThreadId; public DateTime DateTime { get; } = DateTime.UtcNow; public Activity? Activity { get; } = activity ?? Activity.Current; + + public ILogger Logger { get; } = logger ?? NullLogger.Instance; + + public static DiagnosticEvent Create(ref ILogger? logger, Activity? activity = null) => + new(activity, logger ?? LoggerResolver.GetLogger(ref logger)); } -internal readonly struct DiagnosticEvent(T data, Activity? activity = null) : IDiagnosticEvent +internal class DiagnosticEvent(T data, Activity? activity = null, ILogger? logger = null) : DiagnosticEvent(activity, logger) { public T Data { get; init; } = data; - - public int ManagedThreadId { get; } = Environment.CurrentManagedThreadId; - - public DateTime DateTime { get; } = DateTime.UtcNow; - - public Activity? Activity { get; } = activity ?? Activity.Current; } diff --git a/src/Elastic.OpenTelemetry/Diagnostics/ElasticDiagnosticLoggingObserver.cs b/src/Elastic.OpenTelemetry/Diagnostics/ElasticDiagnosticLoggingObserver.cs index eda61ce..e80ae91 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/ElasticDiagnosticLoggingObserver.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/ElasticDiagnosticLoggingObserver.cs @@ -12,7 +12,7 @@ internal sealed class ElasticDiagnosticLoggingObserver(LogFileWriter logFileWrit public void OnNext(KeyValuePair data) { - if (data.Value is not IDiagnosticEvent) + if (data.Value is not DiagnosticEvent) return; switch (data.Key) @@ -54,61 +54,63 @@ public void OnNext(KeyValuePair data) break; default: + if (data.Value is DiagnosticEvent diagnostic) + _logFileWriter.LogUnhandledEvent(data.Key, diagnostic); break; } void AgentBuilderInitialized(KeyValuePair data) { if (data.Value is DiagnosticEvent diagnostic) - _logFileWriter.LogAgentBuilderInitialized(in diagnostic); + _logFileWriter.LogAgentBuilderInitialized(diagnostic); } void AgentBuilderBuiltTracerProvider(KeyValuePair data) { if (data.Value is DiagnosticEvent diagnostic) - _logFileWriter.LogAgentBuilderBuiltTracerProvider(in diagnostic); + _logFileWriter.LogAgentBuilderBuiltTracerProvider(diagnostic); } void AgentBuilderBuiltAgent(KeyValuePair data) { if (data.Value is DiagnosticEvent diagnostic) - _logFileWriter.LogAgentBuilderBuiltAgent(in diagnostic); + _logFileWriter.LogAgentBuilderBuiltAgent(diagnostic); } void AgentBuilderRegisteredDistroServices(KeyValuePair data) { if (data.Value is DiagnosticEvent diagnostic) - _logFileWriter.LogAgentBuilderRegisteredServices(in diagnostic); + _logFileWriter.LogAgentBuilderRegisteredServices(diagnostic); } void AgentBuilderBuildCalledMultipleTimes(KeyValuePair data) { if (data.Value is DiagnosticEvent diagnostic) - _logFileWriter.LogAgentBuilderBuildCalledMultipleTimes(in diagnostic); + _logFileWriter.LogAgentBuilderBuildCalledMultipleTimes(diagnostic); } void AgentBuilderSetAgentCalledMultipleTimes(KeyValuePair data) { if (data.Value is DiagnosticEvent diagnostic) - _logFileWriter.LogAgentBuilderSetAgentCalledMultipleTimes(in diagnostic); + _logFileWriter.LogAgentBuilderSetAgentCalledMultipleTimes(diagnostic); } void TransactionIdAdded(KeyValuePair data) { if (data.Value is DiagnosticEvent diagnostic) - _logFileWriter.LogAddedTransactionIdTag(in diagnostic); + _logFileWriter.LogAddedTransactionIdTag(diagnostic); } void ProcessorAdded(KeyValuePair data) { if (data.Value is DiagnosticEvent diagnostic) - _logFileWriter.LogProcessorAdded(in diagnostic); + _logFileWriter.LogProcessorAdded(diagnostic); } void SourceAdded(KeyValuePair data) { if (data.Value is DiagnosticEvent diagnostic) - _logFileWriter.LogSourceAdded(in diagnostic); + _logFileWriter.LogSourceAdded(diagnostic); } } diff --git a/src/Elastic.OpenTelemetry/Diagnostics/ElasticOpenTelemetryDiagnosticSource.cs b/src/Elastic.OpenTelemetry/Diagnostics/ElasticOpenTelemetryDiagnosticSource.cs index f7e09f9..b609b13 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/ElasticOpenTelemetryDiagnosticSource.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/ElasticOpenTelemetryDiagnosticSource.cs @@ -2,8 +2,9 @@ // Elasticsearch B.V licenses this file to you under the Apache 2.0 License. // See the LICENSE file in the project root for more information using System.Diagnostics; +using Elastic.OpenTelemetry.DependencyInjection; using Elastic.OpenTelemetry.Extensions; -using Elastic.OpenTelemetry.Processors; +using Microsoft.Extensions.Logging.Abstractions; namespace Elastic.OpenTelemetry.Diagnostics; @@ -19,10 +20,13 @@ public static void Log(string name) DiagnosticSource.Write(name, new DiagnosticEvent()); } - public static void Log(string name, IDiagnosticEvent data) + public static void Log(string name, Func createDiagnosticEvent) { - if (DiagnosticSource.IsEnabled(name)) - DiagnosticSource.Write(name, data); + // We take a func here so that we only create an instance of the DiagnosticEvent when + // there is a listener for the event. + + if (DiagnosticSource.IsEnabled(name) && createDiagnosticEvent is not null) + DiagnosticSource.Write(name, createDiagnosticEvent.Invoke()); } // Events @@ -45,12 +49,7 @@ public static void Log(string name, IDiagnosticEvent data) public const string AgentSetAgentCalledMultipleTimesEvent = "AgentSetAgentCalledMultipleTimes"; - // Log messages - - public const string TransactionIdProcessorTagAddedLog = - $"{nameof(TransactionIdProcessor)} added 'transaction.id' tag to Activity."; - - public static void LogAgentBuilderInitialized(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) + public static void LogAgentBuilderInitialized(this LogFileWriter logFileWriter, DiagnosticEvent diagnostic) { var message = diagnostic.Data is not null ? $"AgentBuilder initialized{Environment.NewLine}{diagnostic.Data}." @@ -59,33 +58,51 @@ public static void LogAgentBuilderInitialized(this LogFileWriter logFileWriter, logFileWriter.WriteInfoLogLine(diagnostic, message); } - public static void LogAgentBuilderBuiltTracerProvider(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) => + public static void LogAgentBuilderBuiltTracerProvider(this LogFileWriter logFileWriter, DiagnosticEvent diagnostic) => logFileWriter.WriteInfoLogLine(diagnostic, "AgentBuilder built TracerProvider."); - public static void LogAgentBuilderBuiltAgent(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) => + public static void LogAgentBuilderBuiltAgent(this LogFileWriter logFileWriter, DiagnosticEvent diagnostic) => logFileWriter.WriteInfoLogLine(diagnostic, "AgentBuilder built Agent."); - public static void LogAgentBuilderRegisteredServices(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) => + public static void LogAgentBuilderRegisteredServices(this LogFileWriter logFileWriter, DiagnosticEvent diagnostic) => logFileWriter.WriteInfoLogLine(diagnostic, "AgentBuilder registered agent services into IServiceCollection."); - public static void LogAgentBuilderBuildCalledMultipleTimes(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) => + public static void LogAgentBuilderBuildCalledMultipleTimes(this LogFileWriter logFileWriter, DiagnosticEvent diagnostic) => logFileWriter.WriteErrorLogLine(diagnostic, Agent.BuildErrorMessage); - public static void LogAgentBuilderSetAgentCalledMultipleTimes(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) => + public static void LogAgentBuilderSetAgentCalledMultipleTimes(this LogFileWriter logFileWriter, DiagnosticEvent diagnostic) => logFileWriter.WriteErrorLogLine(diagnostic, Agent.SetAgentErrorMessage); - public static void LogAddedTransactionIdTag(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) => - logFileWriter.WriteTraceLogLine(diagnostic, TransactionIdProcessorTagAddedLog); + public static void LogAddedTransactionIdTag(this LogFileWriter logFileWriter, DiagnosticEvent diagnostic) + { + diagnostic.Logger.TransactionIdProcessorTagAdded(); + logFileWriter.WriteTraceLogLine(diagnostic, LoggerMessages.TransactionIdProcessorTagAddedLog); + } - public static void LogProcessorAdded(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) + public static void LogProcessorAdded(this LogFileWriter logFileWriter, DiagnosticEvent diagnostic) { var message = $"Added '{diagnostic.Data.ProcessorType}' processor to '{diagnostic.Data.BuilderType.Name}'."; logFileWriter.WriteInfoLogLine(diagnostic, message); } - public static void LogSourceAdded(this LogFileWriter logFileWriter, in DiagnosticEvent diagnostic) + public static void LogSourceAdded(this LogFileWriter logFileWriter, DiagnosticEvent diagnostic) { var message = $"Added '{diagnostic.Data.ActivitySourceName}' ActivitySource to '{diagnostic.Data.BuilderType.Name}'."; logFileWriter.WriteInfoLogLine(diagnostic, message); } + + public static void LogUnhandledEvent(this LogFileWriter logFileWriter, string eventKey, DiagnosticEvent diagnostic) + { + // Prefer the logger from the source of the event, when present, otherwise + // fallback to using a logger typed to the ElasticDiagnosticLoggingObserver instead. + + var logger = diagnostic.Logger; + + if (logger == NullLogger.Instance) + logger = LoggerResolver.GetLogger(); + + logger.UnhandledDiagnosticEvent(eventKey); + + logFileWriter.WriteWarningLogLine(diagnostic, $"Received an unhandled diagnostic event '{eventKey}'."); + } } diff --git a/src/Elastic.OpenTelemetry/Diagnostics/IDiagnosticEvent.cs b/src/Elastic.OpenTelemetry/Diagnostics/IDiagnosticEvent.cs deleted file mode 100644 index 358c578..0000000 --- a/src/Elastic.OpenTelemetry/Diagnostics/IDiagnosticEvent.cs +++ /dev/null @@ -1,14 +0,0 @@ -// Licensed to Elasticsearch B.V under one or more agreements. -// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. -// See the LICENSE file in the project root for more information -using System.Diagnostics; - -namespace Elastic.OpenTelemetry.Diagnostics; - -internal interface IDiagnosticEvent -{ - int ManagedThreadId { get; } - DateTime DateTime { get; } - Activity? Activity { get; } -} - diff --git a/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs b/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs index 8d3fb0a..4e4cc66 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs @@ -159,18 +159,49 @@ public static LogLevel GetConfiguredLogLevel() private static void WriteLogPrefix(LogLevel logLevel, StringBuilder builder) => WriteLogPrefix(Environment.CurrentManagedThreadId, DateTime.UtcNow, logLevel, builder); - private static void WriteLogPrefix(int managedThreadId, DateTime dateTime, LogLevel level, StringBuilder builder) + private const string EmptySpanId = "------"; + + private static void WriteLogPrefix(int managedThreadId, DateTime dateTime, LogLevel level, StringBuilder builder, string spanId = "") { + const int maxLength = 5; + + if (string.IsNullOrEmpty(spanId)) + spanId = EmptySpanId; + + var threadId = new string('-', maxLength); + + if (managedThreadId > 0) + { + var digits = (int)Math.Floor(Math.Log10(managedThreadId) + 1); + + if (digits < 5) + { + Span buffer = stackalloc char[maxLength]; + for (var i = 0; i < maxLength - digits; i++) + { + buffer[i] = '0'; + } + managedThreadId.TryFormat(buffer[(maxLength - digits)..], out _); + threadId = buffer.ToString(); + } + else + { + threadId = managedThreadId.ToString(); + } + } + builder.Append('[') .Append(dateTime.ToString("yyyy-MM-dd HH:mm:ss.fff")) .Append("][") - .Append(managedThreadId == -1 ? "-" : managedThreadId) + .Append(threadId) + .Append("][") + .Append(spanId[..6]) .Append("][") .Append(level.AsString()) .Append(']'); var length = builder.Length; - var padding = 40 - length; + var padding = 52 - length; for (var i = 0; i < padding; i++) { @@ -184,32 +215,35 @@ private static void WriteLogPrefix(int managedThreadId, DateTime dateTime, LogLe public Task WritingTask { get; } - public void WriteCriticalLogLine(IDiagnosticEvent diagnosticEvent, string message) => + public void WriteCriticalLogLine(DiagnosticEvent diagnosticEvent, string message) => WriteLogLine(diagnosticEvent, LogLevel.Critical, message); - public void WriteErrorLogLine(IDiagnosticEvent diagnosticEvent, string message) => + public void WriteErrorLogLine(DiagnosticEvent diagnosticEvent, string message) => WriteLogLine(diagnosticEvent, LogLevel.Error, message); - public void WriteWarningLogLine(IDiagnosticEvent diagnosticEvent, string message) => + public void WriteWarningLogLine(DiagnosticEvent diagnosticEvent, string message) => WriteLogLine(diagnosticEvent, LogLevel.Warning, message); - public void WriteInfoLogLine(IDiagnosticEvent diagnosticEvent, string message) => + public void WriteInfoLogLine(DiagnosticEvent diagnosticEvent, string message) => WriteLogLine(diagnosticEvent, LogLevel.Info, message); - public void WriteTraceLogLine(IDiagnosticEvent diagnosticEvent, string message) => + public void WriteTraceLogLine(DiagnosticEvent diagnosticEvent, string message) => WriteLogLine(diagnosticEvent, LogLevel.Trace, message); - public void WriteLogLine(IDiagnosticEvent diagnosticEvent, LogLevel logLevel, string message) => + public void WriteLogLine(DiagnosticEvent diagnosticEvent, LogLevel logLevel, string message) => WriteLogLine(diagnosticEvent.Activity, diagnosticEvent.ManagedThreadId, diagnosticEvent.DateTime, logLevel, message); - public void WriteLogLine(Activity? activity, int managedThreadId, DateTime dateTime, LogLevel logLevel, string logLine) + public void WriteLogLine(Activity? activity, int managedThreadId, DateTime dateTime, LogLevel logLevel, string logLine) => + WriteLogLine(activity, managedThreadId, dateTime, logLevel, logLine, null); + + public void WriteLogLine(Activity? activity, int managedThreadId, DateTime dateTime, LogLevel logLevel, string logLine, string? spanId) { // We skip logging for any log level higher (numerically) than the configured log level if (logLevel > ConfiguredLogLevel) return; var builder = StringBuilderCache.Acquire(); - WriteLogPrefix(managedThreadId, dateTime, logLevel, builder); + WriteLogPrefix(managedThreadId, dateTime, logLevel, builder, spanId ?? activity?.SpanId.ToHexString() ?? string.Empty); builder.Append(logLine); if (activity is not null) @@ -220,7 +254,7 @@ public void WriteLogLine(Activity? activity, int managedThreadId, DateTime dateT // correct sampling flags // https://github.com/dotnet/runtime/issues/61857 - var activityId = string.Concat("00-", activity.TraceId.ToHexString(), "-", activity.SpanId.ToHexString()); + var activityId = $"00-{activity.TraceId.ToHexString()}-{activity.SpanId.ToHexString()}-{(activity.ActivityTraceFlags.HasFlag(ActivityTraceFlags.Recorded) ? "01" : "00")}"; builder.Append($" <{activityId}>"); } diff --git a/src/Elastic.OpenTelemetry/Diagnostics/LoggerMessages.cs b/src/Elastic.OpenTelemetry/Diagnostics/LoggerMessages.cs new file mode 100644 index 0000000..6d03c06 --- /dev/null +++ b/src/Elastic.OpenTelemetry/Diagnostics/LoggerMessages.cs @@ -0,0 +1,26 @@ +// Licensed to Elasticsearch B.V under one or more agreements. +// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information +using Elastic.OpenTelemetry.Processors; +using Microsoft.Extensions.Logging; + +namespace Elastic.OpenTelemetry.Diagnostics +{ + internal static partial class LoggerMessages + { + public const string TransactionIdProcessorTagAddedLog = + $"{nameof(TransactionIdProcessor)} added 'transaction.id' tag to Activity."; + + [LoggerMessage( + EventId = 1, + Level = Microsoft.Extensions.Logging.LogLevel.Trace, + Message = TransactionIdProcessorTagAddedLog)] + internal static partial void TransactionIdProcessorTagAdded(this ILogger logger); + + [LoggerMessage( + EventId = 100, + Level = Microsoft.Extensions.Logging.LogLevel.Warning, + Message = "Received an unhandled diagnostic event '{EventName}'.")] + internal static partial void UnhandledDiagnosticEvent(this ILogger logger, string eventName); + } +} diff --git a/src/Elastic.OpenTelemetry/Diagnostics/LoggingEventListener.cs b/src/Elastic.OpenTelemetry/Diagnostics/LoggingEventListener.cs index 1d7c4cb..4cd0ca5 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/LoggingEventListener.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/LoggingEventListener.cs @@ -3,18 +3,22 @@ // See the LICENSE file in the project root for more information using System.Diagnostics.Tracing; using System.Text; +using System.Text.RegularExpressions; namespace Elastic.OpenTelemetry.Diagnostics; -internal sealed class LoggingEventListener : EventListener, IAsyncDisposable +internal sealed partial class LoggingEventListener : EventListener, IAsyncDisposable { public const string OpenTelemetrySdkEventSourceNamePrefix = "OpenTelemetry-"; private readonly LogFileWriter _logFileWriter; private readonly EventLevel _eventLevel = EventLevel.Informational; + [GeneratedRegex("^\\d{2}-[a-f0-9]{32}-[a-f0-9]{16}-\\d{2}$")] + private static partial Regex TraceParentRegex(); + public LoggingEventListener(LogFileWriter logFileWriter) - { + { _logFileWriter = logFileWriter; var eventLevel = LogFileWriter.GetConfiguredLogLevel(); @@ -60,14 +64,14 @@ protected override void OnEventWritten(EventWrittenEventArgs eventData) // to a rented array and Span if required. var builder = StringBuilderCache.Acquire(); - CreateLogMessage(eventData, builder); + var spanId = CreateLogMessage(eventData, builder); try { // TODO - We can only get the OS thread ID from the args - Do we send that instead?? // As per this issue - https://github.com/dotnet/runtime/issues/13125 - OnEventWritten may be on a different thread // so we can't use the Environment.CurrentManagedThreadId value here. - _logFileWriter.WriteLogLine(null, -1, eventData.TimeStamp, GetLogLevel(eventData), StringBuilderCache.GetStringAndRelease(builder)); + _logFileWriter.WriteLogLine(null, -1, eventData.TimeStamp, GetLogLevel(eventData), StringBuilderCache.GetStringAndRelease(builder), spanId); } catch (Exception) { @@ -87,24 +91,36 @@ static LogLevel GetLogLevel(EventWrittenEventArgs eventData) => _ => LogLevel.Unknown }; - static void CreateLogMessage(EventWrittenEventArgs eventData, StringBuilder builder) + static string? CreateLogMessage(EventWrittenEventArgs eventData, StringBuilder builder) { - // Handle events from the OpenTelemetry SDK - if (eventData.EventSource.Name.StartsWith(OpenTelemetrySdkEventSourceNamePrefix) && eventData.Message is not null) - { - LogMessageAndPayload(eventData, builder); - } + string? spanId = null; - static void LogMessageAndPayload(EventWrittenEventArgs eventData, StringBuilder builder) + if (eventData.EventSource.Name.StartsWith(OpenTelemetrySdkEventSourceNamePrefix) && eventData.Message is not null) { builder.Append($"OTEL-SDK: [{eventData.OSThreadId}] "); - builder.Append(eventData.Message); - if (eventData.Payload is not null) + if (eventData.Payload is null) + { + builder.Append(eventData.Message); + return spanId; + } + + try + { + var matchedActivityId = eventData.Payload.SingleOrDefault(p => p is string ps && TraceParentRegex().IsMatch(ps)); + + if (matchedActivityId is string payloadString) + spanId = payloadString[36..^3]; + + var message = string.Format(eventData.Message, [.. eventData.Payload]); + builder.Append(message); + return spanId; + } + catch { for (var i = 0; i < eventData.Payload.Count; i++) { - builder.Append(" - "); + builder.Append(" | "); var payload = eventData.Payload[i]; @@ -119,6 +135,8 @@ static void LogMessageAndPayload(EventWrittenEventArgs eventData, StringBuilder } } } + + return spanId; } } } diff --git a/src/Elastic.OpenTelemetry/Extensions/TraceBuilderProviderExtensions.cs b/src/Elastic.OpenTelemetry/Extensions/TraceBuilderProviderExtensions.cs index 828ff75..0a208ee 100644 --- a/src/Elastic.OpenTelemetry/Extensions/TraceBuilderProviderExtensions.cs +++ b/src/Elastic.OpenTelemetry/Extensions/TraceBuilderProviderExtensions.cs @@ -26,19 +26,13 @@ public static TracerProviderBuilder AddElasticProcessors(this TracerProviderBuil internal static TracerProviderBuilder LogAndAddProcessor(this TracerProviderBuilder builder, BaseProcessor processor) { - Log(ProcessorAddedEvent, new DiagnosticEvent() - { - Data = new(processor.GetType(), builder.GetType()) - }); + Log(ProcessorAddedEvent, () => new DiagnosticEvent(new(processor.GetType(), builder.GetType()))); return builder.AddProcessor(processor); } internal static TracerProviderBuilder LogAndAddSource(this TracerProviderBuilder builder, string sourceName) { - Log(SourceAddedEvent, new DiagnosticEvent() - { - Data = new(sourceName, builder.GetType()) - }); + Log(SourceAddedEvent, () => new DiagnosticEvent(new(sourceName, builder.GetType()))); return builder.AddSource(sourceName); } diff --git a/src/Elastic.OpenTelemetry/IAgent.cs b/src/Elastic.OpenTelemetry/IAgent.cs index 75111cc..e1a109f 100644 --- a/src/Elastic.OpenTelemetry/IAgent.cs +++ b/src/Elastic.OpenTelemetry/IAgent.cs @@ -9,11 +9,3 @@ namespace Elastic.OpenTelemetry; public interface IAgent : IDisposable, IAsyncDisposable { } - -internal interface IServiceProviderAgent : IAgent -{ - /// - /// - /// - IServiceProvider ServiceProvider { get; } -} diff --git a/src/Elastic.OpenTelemetry/Processors/ElasticProcessor.cs b/src/Elastic.OpenTelemetry/Processors/ElasticProcessor.cs deleted file mode 100644 index ee69d63..0000000 --- a/src/Elastic.OpenTelemetry/Processors/ElasticProcessor.cs +++ /dev/null @@ -1,33 +0,0 @@ -// Licensed to Elasticsearch B.V under one or more agreements. -// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. -// See the LICENSE file in the project root for more information -using System.Diagnostics; -using Microsoft.Extensions.DependencyInjection; -using Microsoft.Extensions.Logging; -using Microsoft.Extensions.Logging.Abstractions; -using OpenTelemetry; - -namespace Elastic.OpenTelemetry.Processors; - -/// -/// -/// -public abstract class ElasticProcessor : BaseProcessor, IElasticProcessor -{ - /// - /// - /// - protected static ILogger Logger { get; private set; } = NullLogger.Instance; - - void IElasticProcessor.Initialize(IServiceProvider serviceProvider) - { - var resolvedLogger = serviceProvider.GetService>(); - - if (resolvedLogger is ILogger logger) - { - Logger = logger; - } - - Logger.LogInformation("Initialised {ProcessorType}.", typeof(T)); - } -} diff --git a/src/Elastic.OpenTelemetry/Processors/IElasticProcessor.cs b/src/Elastic.OpenTelemetry/Processors/IElasticProcessor.cs deleted file mode 100644 index 7c91ae1..0000000 --- a/src/Elastic.OpenTelemetry/Processors/IElasticProcessor.cs +++ /dev/null @@ -1,9 +0,0 @@ -// Licensed to Elasticsearch B.V under one or more agreements. -// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. -// See the LICENSE file in the project root for more information -namespace Elastic.OpenTelemetry.Processors; - -internal interface IElasticProcessor -{ - void Initialize(IServiceProvider serviceProvider); -} diff --git a/src/Elastic.OpenTelemetry/Processors/TransactionIdProcessor.cs b/src/Elastic.OpenTelemetry/Processors/TransactionIdProcessor.cs index f29f9c7..d64253d 100644 --- a/src/Elastic.OpenTelemetry/Processors/TransactionIdProcessor.cs +++ b/src/Elastic.OpenTelemetry/Processors/TransactionIdProcessor.cs @@ -4,6 +4,7 @@ using System.Diagnostics; using Elastic.OpenTelemetry.Diagnostics; using Microsoft.Extensions.Logging; +using OpenTelemetry; using static Elastic.OpenTelemetry.Diagnostics.ElasticOpenTelemetryDiagnosticSource; @@ -12,16 +13,17 @@ namespace Elastic.OpenTelemetry.Processors; /// /// /// -public class TransactionIdProcessor : ElasticProcessor +public class TransactionIdProcessor : BaseProcessor { + private ILogger? _logger = null; + private readonly AsyncLocal _currentTransactionId = new(); + /// /// /// public const string TransactionIdTagName = "transaction.id"; - private readonly AsyncLocal _currentTransactionId = new(); - - /// + /// public override void OnStart(Activity activity) { if (activity.Parent == null) @@ -30,9 +32,7 @@ public override void OnStart(Activity activity) if (_currentTransactionId.Value.HasValue) { activity.SetTag(TransactionIdTagName, _currentTransactionId.Value.Value.ToString()); - - Log(TransactionIdAddedEvent, new DiagnosticEvent(activity)); - Logger.LogTrace(TransactionIdProcessorTagAddedLog); + Log(TransactionIdAddedEvent, () => DiagnosticEvent.Create(ref _logger, activity)); } } } diff --git a/tests/Elastic.OpenTelemetry.Tests/ProcessorTests.cs b/tests/Elastic.OpenTelemetry.Tests/ProcessorTests.cs deleted file mode 100644 index b926b05..0000000 --- a/tests/Elastic.OpenTelemetry.Tests/ProcessorTests.cs +++ /dev/null @@ -1,31 +0,0 @@ -// Licensed to Elasticsearch B.V under one or more agreements. -// Elasticsearch B.V licenses this file to you under the Apache 2.0 License. -// See the LICENSE file in the project root for more information -using Microsoft.Extensions.DependencyInjection; - -namespace Elastic.OpenTelemetry.Tests; - -public class ProcessorTests -{ - [Fact] - public void AllElasticProcessors_Should_BeAddedToDependencyInjectionContainer() - { - var sc = new ServiceCollection(); - sc.AddElasticOpenTelemetry(); - var sp = sc.BuildServiceProvider(); - - var processors = AppDomain.CurrentDomain.GetAssemblies() - .SelectMany(s => s.GetTypes()) - .Where(t => typeof(IElasticProcessor).IsAssignableFrom(t) && t.IsClass && !t.IsAbstract) - .ToArray(); - - var registeredProcessors = sp.GetRequiredService>().ToArray(); - - processors.Length.Should().Be(registeredProcessors.Length); - - foreach (var processor in processors) - { - _ = registeredProcessors.Single(rp => rp.GetType() == processor); - } - } -}