From b7fd7eea9e23d12cd9872dbbc6129cd06eba0ebf Mon Sep 17 00:00:00 2001 From: Andy Staples Date: Wed, 3 Apr 2024 11:56:25 -0600 Subject: [PATCH 1/8] Initial code changes before proto update --- src/Logging/LoggingEventHandler.cs | 31 ++++ src/Logging/RpcLogger.cs | 3 + .../OpenTelemetryController.cs | 152 ++++++++++++++++++ .../OpenTelemetryInvocationContext.cs | 27 ++++ src/PowerShell/PowerShellManager.cs | 35 +++- src/RequestProcessor.cs | 14 +- src/Utility/Utils.cs | 3 +- src/resources/PowerShellWorkerStrings.resx | 3 + test/Unit/Logging/ConsoleLogger.cs | 1 + .../Unit/PowerShell/PowerShellManagerTests.cs | 5 +- 10 files changed, 263 insertions(+), 11 deletions(-) create mode 100644 src/Logging/LoggingEventHandler.cs create mode 100644 src/OpenTelemetrySDK/OpenTelemetryController.cs create mode 100644 src/OpenTelemetrySDK/OpenTelemetryInvocationContext.cs diff --git a/src/Logging/LoggingEventHandler.cs b/src/Logging/LoggingEventHandler.cs new file mode 100644 index 00000000..91a8895b --- /dev/null +++ b/src/Logging/LoggingEventHandler.cs @@ -0,0 +1,31 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Text; +using System.Threading.Tasks; + +namespace Microsoft.Azure.Functions.PowerShellWorker.Utility +{ + internal class LoggingEventHandler + { + private HashSet> _eventHandlers = new HashSet>(); + + public void Subscribe(Action handler) + { + _eventHandlers.Add(handler); + } + + public void Unsubscribe(Action handler) + { + _eventHandlers.Remove(handler); + } + + public void LogToHandlers(string level, string message, Exception exception = null) + { + foreach (var handler in _eventHandlers) + { + handler(level, message, exception); + } + } + } +} diff --git a/src/Logging/RpcLogger.cs b/src/Logging/RpcLogger.cs index 160b7f9e..23b9c0ca 100644 --- a/src/Logging/RpcLogger.cs +++ b/src/Logging/RpcLogger.cs @@ -18,6 +18,7 @@ internal class RpcLogger : ILogger private readonly MessagingStream _msgStream; private string _invocationId; private string _requestId; + public LoggingEventHandler outputLogHandler = new LoggingEventHandler(); internal RpcLogger(MessagingStream msgStream) { @@ -55,6 +56,8 @@ public void Log(bool isUserOnlyLog, LogLevel logLevel, string message, Exception }; _msgStream.Write(logMessage); + + outputLogHandler.LogToHandlers(logLevel.ToString(), message, exception); } else { diff --git a/src/OpenTelemetrySDK/OpenTelemetryController.cs b/src/OpenTelemetrySDK/OpenTelemetryController.cs new file mode 100644 index 00000000..0fa60038 --- /dev/null +++ b/src/OpenTelemetrySDK/OpenTelemetryController.cs @@ -0,0 +1,152 @@ +using System; +using System.Linq; +using System.Management.Automation; +using Microsoft.Azure.Functions.PowerShellWorker.PowerShell; +using Microsoft.Azure.Functions.PowerShellWorker.Utility; +using LogLevel = Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types.Level; + +namespace Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetrySDK +{ + using PowerShell = System.Management.Automation.PowerShell; + + internal class OpenTelemetryController + { + private readonly ILogger _logger; + private PowerShell _pwsh { get; set; } + + private const string StartOpenTelemetryInvocationCmdlet = "Start-OpenTelemetryInvocation"; + private const string StopOpenTelemetryInvocationCmdlet = "Stop-OpenTelemetryInvocation"; + private const string GetFunctionsLogHandlerCmdlet = "Get-FunctionsLogHandler"; + + private const string OTelEnvironmentVariableName = "OTEL_FUNCTIONS_WORKER_ENABLED"; + + private static bool? _isOpenTelemetryCapable; + private static bool? _isOpenTelemetryModuleLoaded; + private static bool? _isOpenTelmetryEnvironmentEnabled; + + public OpenTelemetryController(ILogger logger, PowerShell pwsh) + { + _logger = logger; + _pwsh = pwsh; + } + + public bool isOpenTelemetryCapable() + { + if (_isOpenTelemetryCapable.HasValue) + { + return _isOpenTelemetryCapable.Value; + } + + _isOpenTelemetryCapable = isOpenTelemetryEnvironmentEnabled() && isOpenTelemetryModuleLoaded(); + + return _isOpenTelemetryCapable.Value; + } + + public static bool isOpenTelemetryEnvironmentEnabled() + { + if (_isOpenTelmetryEnvironmentEnabled.HasValue) + { + return _isOpenTelmetryEnvironmentEnabled.Value; + } + + string isOpenTelemetryWorkerLogEnabled = Environment.GetEnvironmentVariable(OTelEnvironmentVariableName); + _isOpenTelmetryEnvironmentEnabled = !string.IsNullOrEmpty(isOpenTelemetryWorkerLogEnabled); + + return _isOpenTelmetryEnvironmentEnabled.Value; + } + + public bool isOpenTelemetryModuleLoaded() + { + if (_isOpenTelemetryModuleLoaded.HasValue) + { + return _isOpenTelemetryModuleLoaded.Value; + } + + // Search for the OpenTelemetry SDK in the current session + var matchingModules = _pwsh.AddCommand(Utils.GetModuleCmdletInfo) + .AddParameter("FullyQualifiedName", Utils.OpenTelemetrySdkName) + .InvokeAndClearCommands(); + + // If we get at least one result, we know the OpenTelemetry SDK was imported + var numCandidates = matchingModules.Count(); + var isModuleInCurrentSession = numCandidates > 0; + + if (isModuleInCurrentSession) + { + var candidatesInfo = matchingModules.Select(module => string.Format( + PowerShellWorkerStrings.FoundOpenTelemetrySdkInSession, module.Name, module.Version, module.Path)); + var otelSDKModuleInfo = string.Join('\n', candidatesInfo); + + if (numCandidates > 1) + { + // If there's more than 1 result, there may be runtime conflicts + // warn user of potential conflicts + _logger.Log(isUserOnlyLog: false, LogLevel.Warning, String.Format( + PowerShellWorkerStrings.MultipleExternalSDKsInSession, + numCandidates, Utils.OpenTelemetrySdkName, otelSDKModuleInfo)); + } + else + { + // a single SDK is in session. Report its metadata + _logger.Log(isUserOnlyLog: false, LogLevel.Trace, otelSDKModuleInfo); + } + } + + _isOpenTelemetryModuleLoaded = isModuleInCurrentSession; + + + return _isOpenTelemetryModuleLoaded.Value; + } + + public static void ResetOpenTelemetryModuleStatus() + { + _isOpenTelemetryCapable = null; + _isOpenTelemetryModuleLoaded = null; + _isOpenTelmetryEnvironmentEnabled = null; + } + + public void AddStartOpenTelemetryInvocationCommand(OpenTelemetryInvocationContext otelContext) + { + if (!isOpenTelemetryCapable() || !otelContext.isValid()) + { + return; + } + + _pwsh.AddCommand(StartOpenTelemetryInvocationCmdlet) + .AddParameter("InvocationId", otelContext.InvocationId) + .AddParameter("TraceParent", otelContext.TraceParent) + .AddParameter("TraceState", otelContext.TraceState); + } + + public void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext) + { + if (!isOpenTelemetryCapable()) + { + return; + } + + _pwsh.AddCommand(StopOpenTelemetryInvocationCmdlet) + .AddParameter("InvocationId", otelContext.InvocationId) + .InvokeAndClearCommands(); + } + + internal void StartFunctionsLoggingListener() + { + if (!isOpenTelemetryCapable()) + { + return; + } + + var eventHandlers = _pwsh.AddCommand(GetFunctionsLogHandlerCmdlet) + .InvokeAndClearCommands>(); + + foreach (var eventHandler in eventHandlers) + { + if (_logger is RpcLogger rpcLogger) + { + rpcLogger.outputLogHandler.Subscribe(eventHandler); + } + } + } + } +} diff --git a/src/OpenTelemetrySDK/OpenTelemetryInvocationContext.cs b/src/OpenTelemetrySDK/OpenTelemetryInvocationContext.cs new file mode 100644 index 00000000..d1714ac7 --- /dev/null +++ b/src/OpenTelemetrySDK/OpenTelemetryInvocationContext.cs @@ -0,0 +1,27 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Text; +using System.Threading.Tasks; + +namespace Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetrySDK +{ + internal class OpenTelemetryInvocationContext + { + public OpenTelemetryInvocationContext(string invocationId, string traceParent, string traceState) + { + InvocationId = invocationId; + TraceParent = traceParent; + TraceState = traceState; + } + + public bool isValid() + { + return InvocationId != null && TraceParent != null; + } + + public string InvocationId { get; set; } + public string TraceParent { get; set; } + public string TraceState { get; set; } + } +} diff --git a/src/PowerShell/PowerShellManager.cs b/src/PowerShell/PowerShellManager.cs index 5a0a4db7..5b0894d5 100644 --- a/src/PowerShell/PowerShellManager.cs +++ b/src/PowerShell/PowerShellManager.cs @@ -16,6 +16,8 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell { using Microsoft.Azure.Functions.PowerShellWorker.DurableWorker; + using Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetrySDK; + using System.Collections.ObjectModel; using System.Management.Automation; using System.Text; @@ -37,6 +39,8 @@ internal class PowerShellManager private readonly ErrorRecordFormatter _errorRecordFormatter = new ErrorRecordFormatter(); + private OpenTelemetryController _openTelemetryController; + /// /// Gets the Runspace InstanceId. /// @@ -106,6 +110,9 @@ internal void Initialize() // Run the profile.ps1 InvokeProfile(FunctionLoader.FunctionAppProfilePath); + _openTelemetryController = new OpenTelemetryController(Logger, _pwsh); + _openTelemetryController.StartFunctionsLoggingListener(); + _runspaceInited = true; } } @@ -202,7 +209,8 @@ public Hashtable InvokeFunction( TraceContext traceContext, RetryContext retryContext, IList inputData, - FunctionInvocationPerformanceStopwatch stopwatch) + FunctionInvocationPerformanceStopwatch stopwatch, + OpenTelemetryInvocationContext otelContext) { var outputBindings = FunctionMetadata.GetOutputBindingHashtable(_pwsh.Runspace.InstanceId); var durableFunctionsUtils = new DurableController(functionInfo.DurableFunctionInfo, _pwsh, Logger); @@ -212,6 +220,12 @@ public Hashtable InvokeFunction( durableFunctionsUtils.InitializeBindings(inputData, out bool hasExternalDFsdk); Logger.Log(isUserOnlyLog: false, LogLevel.Trace, String.Format(PowerShellWorkerStrings.UtilizingExternalDurableSDK, hasExternalDFsdk)); + ImportEntryPointModule(functionInfo); + + // This cmdlet must be run in the same .InvokeAndClearCommands() run as the function code itself + // If it is not, the Activity.Current context that we are trying to preserve is dropped + _openTelemetryController.AddStartOpenTelemetryInvocationCommand(otelContext); + AddEntryPointInvocationCommand(functionInfo); stopwatch.OnCheckpoint(FunctionInvocationPerformanceStopwatch.Checkpoint.FunctionCodeReady); @@ -224,7 +238,7 @@ public Hashtable InvokeFunction( try { - if(functionInfo.DurableFunctionInfo.IsOrchestrationFunction) + if (functionInfo.DurableFunctionInfo.IsOrchestrationFunction) { return durableFunctionsUtils.InvokeOrchestrationFunction(); } @@ -255,6 +269,7 @@ public Hashtable InvokeFunction( } finally { + _openTelemetryController.StopOpenTelemetryInvocation(otelContext); durableFunctionsUtils.AfterFunctionInvocation(); outputBindings.Clear(); ResetRunspace(); @@ -314,6 +329,17 @@ private Hashtable ExecuteUserCode(bool addPipelineOutput, IDictionary outputBind return result; } + private void ImportEntryPointModule(AzFunctionInfo functionInfo) + { + if (!string.IsNullOrEmpty(functionInfo.EntryPoint)) + { + // If an entry point is defined, we import the script module. + _pwsh.AddCommand(Utils.ImportModuleCmdletInfo) + .AddParameter("Name", functionInfo.ScriptPath) + .InvokeAndClearCommands(); + } + } + private void AddEntryPointInvocationCommand(AzFunctionInfo functionInfo) { if (string.IsNullOrEmpty(functionInfo.EntryPoint)) @@ -322,11 +348,6 @@ private void AddEntryPointInvocationCommand(AzFunctionInfo functionInfo) } else { - // If an entry point is defined, we import the script module. - _pwsh.AddCommand(Utils.ImportModuleCmdletInfo) - .AddParameter("Name", functionInfo.ScriptPath) - .InvokeAndClearCommands(); - _pwsh.AddCommand(functionInfo.EntryPoint); } } diff --git a/src/RequestProcessor.cs b/src/RequestProcessor.cs index ad192aa0..594cd581 100644 --- a/src/RequestProcessor.cs +++ b/src/RequestProcessor.cs @@ -21,6 +21,7 @@ namespace Microsoft.Azure.Functions.PowerShellWorker using System.Diagnostics; using LogLevel = Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types.Level; using System.Runtime.InteropServices; + using Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetrySDK; internal class RequestProcessor { @@ -113,6 +114,11 @@ internal StreamingMessage ProcessWorkerInitRequest(StreamingMessage request) response.WorkerInitResponse.Capabilities.Add("RpcHttpBodyOnly", "true"); response.WorkerInitResponse.Capabilities.Add("WorkerStatus", "true"); + if (OpenTelemetryController.isOpenTelemetryEnvironmentEnabled()) + { + response.WorkerInitResponse.Capabilities.Add("WorkerOpenTelemetryEnabled", "true"); + } + // If the environment variable is set, spin up the custom named pipe server. // This is typically used for debugging. It will throw a friendly exception if the // pipe name is not a valid pipename. @@ -354,7 +360,10 @@ private Hashtable InvokeFunction( var retryContext = GetRetryContext(functionInfo, invocationRequest); stopwatch.OnCheckpoint(FunctionInvocationPerformanceStopwatch.Checkpoint.MetadataAndTraceContextReady); - return psManager.InvokeFunction(functionInfo, triggerMetadata, traceContext, retryContext, invocationRequest.InputData, stopwatch); + OpenTelemetryInvocationContext otelContext = new OpenTelemetryInvocationContext(invocationRequest.InvocationId, + invocationRequest.TraceContext?.TraceParent, invocationRequest.TraceContext?.TraceState); + + return psManager.InvokeFunction(functionInfo, triggerMetadata, traceContext, retryContext, invocationRequest.InputData, stopwatch, otelContext); } internal StreamingMessage ProcessInvocationCancelRequest(StreamingMessage request) @@ -377,6 +386,9 @@ internal StreamingMessage ProcessFunctionEnvironmentReloadRequest(StreamingMessa environmentReloadRequest.EnvironmentVariables, environmentReloadRequest.FunctionAppDirectory); + // This will force the OpenTelemetryController to check the environment variables and module presence again + OpenTelemetryController.ResetOpenTelemetryModuleStatus(); + rpcLogger.Log(isUserOnlyLog: false, LogLevel.Trace, string.Format(PowerShellWorkerStrings.EnvironmentReloadCompleted, stopwatch.ElapsedMilliseconds)); StreamingMessage response = NewStreamingMessageTemplate( diff --git a/src/Utility/Utils.cs b/src/Utility/Utils.cs index e8d3a3d1..1c3ce45d 100644 --- a/src/Utility/Utils.cs +++ b/src/Utility/Utils.cs @@ -23,12 +23,13 @@ internal class Utils internal readonly static CmdletInfo RemoveJobCmdletInfo = new CmdletInfo("Remove-Job", typeof(RemoveJobCommand)); internal readonly static CmdletInfo OutStringCmdletInfo = new CmdletInfo("Out-String", typeof(OutStringCommand)); internal readonly static CmdletInfo WriteInformationCmdletInfo = new CmdletInfo("Write-Information", typeof(WriteInformationCommand)); - + internal const string InternalDurableSdkName = "Microsoft.Azure.Functions.PowerShellWorker"; internal const string ExternalDurableSdkName = "AzureFunctions.PowerShell.Durable.SDK"; internal const string IsOrchestrationFailureKey = "IsOrchestrationFailure"; internal const string TracePipelineObjectCmdlet = "Microsoft.Azure.Functions.PowerShellWorker\\Trace-PipelineObject"; internal const string ExternalDurableSdkEnvVariable = "ExternalDurablePowerShellSDK"; + internal const string OpenTelemetrySdkName = "AzureFunctions.PowerShell.OpenTelemetry.SDK"; internal readonly static object BoxedTrue = (object)true; internal readonly static object BoxedFalse = (object)false; diff --git a/src/resources/PowerShellWorkerStrings.resx b/src/resources/PowerShellWorkerStrings.resx index 0685d7b4..710687c0 100644 --- a/src/resources/PowerShellWorkerStrings.resx +++ b/src/resources/PowerShellWorkerStrings.resx @@ -355,6 +355,9 @@ Found external Durable Functions SDK in session: Name='{0}', Version='{1}', Path='{2}'. + + Found Open Telemetry SDK in session: Name='{0}', Version='{1}', Path='{2}'. + Unable to initialize orchestrator function due to presence of other bindings. Total number of bindings found is '{0}'. Orchestrator Functions should never use any input or output bindings other than the orchestration trigger itself. See: aka.ms/df-bindings diff --git a/test/Unit/Logging/ConsoleLogger.cs b/test/Unit/Logging/ConsoleLogger.cs index e41dfea1..d49d772f 100644 --- a/test/Unit/Logging/ConsoleLogger.cs +++ b/test/Unit/Logging/ConsoleLogger.cs @@ -7,6 +7,7 @@ using System.Collections; using System.Collections.Generic; using Microsoft.Azure.Functions.PowerShellWorker.Utility; +using Microsoft.Extensions.Logging.Abstractions; using LogLevel = Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types.Level; namespace Microsoft.Azure.Functions.PowerShellWorker.Test diff --git a/test/Unit/PowerShell/PowerShellManagerTests.cs b/test/Unit/PowerShell/PowerShellManagerTests.cs index 36588611..5bceda4a 100644 --- a/test/Unit/PowerShell/PowerShellManagerTests.cs +++ b/test/Unit/PowerShell/PowerShellManagerTests.cs @@ -19,6 +19,7 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.Test using System.Management.Automation; using Microsoft.Azure.Functions.PowerShellWorker.Durable; using Microsoft.Azure.Functions.PowerShellWorker.DurableWorker; + using Microsoft.Extensions.Logging.Abstractions; using Newtonsoft.Json; internal class TestUtils @@ -403,7 +404,7 @@ internal void SuppressPipelineTracesForDurableActivityFunctionOnly(DurableFuncti { FunctionMetadata.RegisterFunctionMetadata(testManager.InstanceId, functionInfo.OutputBindings); - var result = testManager.InvokeFunction(functionInfo, null, null, null, CreateOrchestratorInputData(), new FunctionInvocationPerformanceStopwatch()); + var result = testManager.InvokeFunction(functionInfo, null, null, null, CreateOrchestratorInputData(), new FunctionInvocationPerformanceStopwatch(), null); var relevantLogs = s_testLogger.FullLog.Where(message => message.StartsWith("Information: OUTPUT:")).ToList(); var expected = shouldSuppressPipelineTraces ? new string[0] : new[] { "Information: OUTPUT: Hello" }; @@ -439,7 +440,7 @@ private static Hashtable InvokeFunction( Hashtable triggerMetadata = null, RetryContext retryContext = null) { - return powerShellManager.InvokeFunction(functionInfo, triggerMetadata, null, retryContext, s_testInputData, new FunctionInvocationPerformanceStopwatch()); + return powerShellManager.InvokeFunction(functionInfo, triggerMetadata, null, retryContext, s_testInputData, new FunctionInvocationPerformanceStopwatch(), null); } private class ContextValidatingLogger : ILogger From 261d74e16f14f697780ad66f2031c8e40485862b Mon Sep 17 00:00:00 2001 From: Andy Staples Date: Wed, 3 Apr 2024 12:03:34 -0600 Subject: [PATCH 2/8] Update to latest protobuf (1.10.0-ptotofile) - Report opentelemetry capability at environemnt reload --- protobuf/src/proto/FunctionRpc.proto | 152 +++++++++++++++++++++------ src/Logging/LoggingEventHandler.cs | 3 - src/PowerShell/PowerShellManager.cs | 2 - src/RequestProcessor.cs | 12 ++- 4 files changed, 131 insertions(+), 38 deletions(-) diff --git a/protobuf/src/proto/FunctionRpc.proto b/protobuf/src/proto/FunctionRpc.proto index 12809828..110df5d2 100644 --- a/protobuf/src/proto/FunctionRpc.proto +++ b/protobuf/src/proto/FunctionRpc.proto @@ -32,7 +32,8 @@ message StreamingMessage { WorkerInitRequest worker_init_request = 17; // Worker responds after initializing with its capabilities & status WorkerInitResponse worker_init_response = 16; - + + // MESSAGE NOT USED // Worker periodically sends empty heartbeat message to host WorkerHeartbeat worker_heartbeat = 15; @@ -85,6 +86,13 @@ message StreamingMessage { // Host gets the list of function load responses FunctionLoadResponseCollection function_load_response_collection = 32; + + // Host sends required metadata to worker to warmup the worker + WorkerWarmupRequest worker_warmup_request = 33; + + // Worker responds after warming up with the warmup result + WorkerWarmupResponse worker_warmup_response = 34; + } } @@ -120,7 +128,7 @@ message WorkerInitRequest { // Worker responds with the result of initializing itself message WorkerInitResponse { - // NOT USED + // PROPERTY NOT USED // TODO: Remove from protobuf during next breaking change release string worker_version = 1; @@ -173,7 +181,7 @@ message StatusResult { repeated RpcLog logs = 3; } -// NOT USED +// MESSAGE NOT USED // TODO: Remove from protobuf during next breaking change release message WorkerHeartbeat {} @@ -187,7 +195,7 @@ message WorkerTerminate { message FileChangeEventRequest { // Types of File change operations (See link for more info: https://msdn.microsoft.com/en-us/library/t6xf43e0(v=vs.110).aspx) enum Type { - Unknown = 0; + Unknown = 0; Created = 1; Deleted = 2; Changed = 4; @@ -237,8 +245,26 @@ message FunctionEnvironmentReloadRequest { } message FunctionEnvironmentReloadResponse { + enum CapabilitiesUpdateStrategy { + // overwrites existing values and appends new ones + // ex. worker init: {A: foo, B: bar} + env reload: {A:foo, B: foo, C: foo} -> {A: foo, B: foo, C: foo} + merge = 0; + // existing capabilities are cleared and new capabilities are applied + // ex. worker init: {A: foo, B: bar} + env reload: {A:foo, C: foo} -> {A: foo, C: foo} + replace = 1; + } + // After specialization, worker sends capabilities & metadata. + // Worker metadata captured for telemetry purposes + WorkerMetadata worker_metadata = 1; + + // A map of worker supported features/capabilities + map capabilities = 2; + // Status of the response StatusResult result = 3; + + // If no strategy is defined, the host will default to merge + CapabilitiesUpdateStrategy capabilities_update_strategy = 4; } // Tell the out-of-proc worker to close any shared memory maps it allocated for given invocation @@ -322,10 +348,13 @@ message RpcFunctionMetadata { // A flag indicating if managed dependency is enabled or not bool managed_dependency_enabled = 14; + // The optional function execution retry strategy to use on invocation failures. + RpcRetryOptions retry_options = 15; + // Properties for function metadata // They're usually specific to a worker and largely passed along to the controller API for use // outside the host - map Properties = 16; + map properties = 16; } // Host tells worker it is ready to receive metadata @@ -369,14 +398,14 @@ message InvocationRequest { // Host sends ActivityId, traceStateString and Tags from host message RpcTraceContext { - // This corresponds to Activity.Current?.Id - string trace_parent = 1; + // This corresponds to Activity.Current?.Id + string trace_parent = 1; - // This corresponds to Activity.Current?.TraceStateString - string trace_state = 2; + // This corresponds to Activity.Current?.TraceStateString + string trace_state = 2; - // This corresponds to Activity.Current?.Tags - map attributes = 3; + // This corresponds to Activity.Current?.Tags + map attributes = 3; } // Host sends retry context for a function invocation @@ -396,8 +425,8 @@ message InvocationCancel { // Unique id for invocation string invocation_id = 2; - // Time period before force shutdown - google.protobuf.Duration grace_period = 1; // could also use absolute time + // PROPERTY NOT USED + google.protobuf.Duration grace_period = 1; } // Worker responds with status of Invocation @@ -415,6 +444,15 @@ message InvocationResponse { StatusResult result = 3; } +message WorkerWarmupRequest { + // Full path of worker.config.json location + string worker_directory = 1; +} + +message WorkerWarmupResponse { + StatusResult result = 1; +} + // Used to encapsulate data which could be a variety of types message TypedData { oneof data { @@ -429,6 +467,8 @@ message TypedData { CollectionString collection_string = 9; CollectionDouble collection_double = 10; CollectionSInt64 collection_sint64 = 11; + ModelBindingData model_binding_data = 12; + CollectionModelBindingData collection_model_binding_data = 13; } } @@ -496,20 +536,20 @@ message ParameterBinding { // Used to describe a given binding on load message BindingInfo { - // Indicates whether it is an input or output binding (or a fancy inout binding) - enum Direction { - in = 0; - out = 1; - inout = 2; - } - - // Indicates the type of the data for the binding - enum DataType { - undefined = 0; - string = 1; - binary = 2; - stream = 3; - } + // Indicates whether it is an input or output binding (or a fancy inout binding) + enum Direction { + in = 0; + out = 1; + inout = 2; + } + + // Indicates the type of the data for the binding + enum DataType { + undefined = 0; + string = 1; + binary = 2; + stream = 3; + } // Type of binding (e.g. HttpTrigger) string type = 2; @@ -518,6 +558,9 @@ message BindingInfo { Direction direction = 3; DataType data_type = 4; + + // Properties for binding metadata + map properties = 5; } // Used to send logs back to the Host @@ -582,13 +625,13 @@ message RpcException { // Textual message describing the exception string message = 2; - // Worker specifies whether exception is a user exception, - // for purpose of application insights logging. Defaults to false. + // Worker specifies whether exception is a user exception, + // for purpose of application insights logging. Defaults to false. bool is_user_exception = 4; // Type of exception. If it's a user exception, the type is passed along to app insights. // Otherwise, it's ignored for now. - string type = 5; + string type = 5; } // Http cookie type. Note that only name and value are used for Http requests @@ -647,3 +690,52 @@ message RpcHttp { map nullable_params = 21; map nullable_query = 22; } + +// Message representing Microsoft.Azure.WebJobs.ParameterBindingData +// Used for hydrating SDK-type bindings in out-of-proc workers +message ModelBindingData +{ + // The version of the binding data content + string version = 1; + + // The extension source of the binding data + string source = 2; + + // The content type of the binding data content + string content_type = 3; + + // The binding data content + bytes content = 4; +} + +// Used to encapsulate collection model_binding_data +message CollectionModelBindingData { + repeated ModelBindingData model_binding_data = 1; +} + +// Retry policy which the worker sends the host when the worker indexes +// a function. +message RpcRetryOptions +{ + // The retry strategy to use. Valid values are fixed delay or exponential backoff. + enum RetryStrategy + { + exponential_backoff = 0; + fixed_delay = 1; + } + + // The maximum number of retries allowed per function execution. + // -1 means to retry indefinitely. + int32 max_retry_count = 2; + + // The delay that's used between retries when you're using a fixed delay strategy. + google.protobuf.Duration delay_interval = 3; + + // The minimum retry delay when you're using an exponential backoff strategy + google.protobuf.Duration minimum_interval = 4; + + // The maximum retry delay when you're using an exponential backoff strategy + google.protobuf.Duration maximum_interval = 5; + + RetryStrategy retry_strategy = 6; +} diff --git a/src/Logging/LoggingEventHandler.cs b/src/Logging/LoggingEventHandler.cs index 91a8895b..b4bd1dac 100644 --- a/src/Logging/LoggingEventHandler.cs +++ b/src/Logging/LoggingEventHandler.cs @@ -1,8 +1,5 @@ using System; using System.Collections.Generic; -using System.Linq; -using System.Text; -using System.Threading.Tasks; namespace Microsoft.Azure.Functions.PowerShellWorker.Utility { diff --git a/src/PowerShell/PowerShellManager.cs b/src/PowerShell/PowerShellManager.cs index 5b0894d5..b7426356 100644 --- a/src/PowerShell/PowerShellManager.cs +++ b/src/PowerShell/PowerShellManager.cs @@ -15,9 +15,7 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell { - using Microsoft.Azure.Functions.PowerShellWorker.DurableWorker; using Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetrySDK; - using System.Collections.ObjectModel; using System.Management.Automation; using System.Text; diff --git a/src/RequestProcessor.cs b/src/RequestProcessor.cs index 594cd581..5c276ca1 100644 --- a/src/RequestProcessor.cs +++ b/src/RequestProcessor.cs @@ -386,9 +386,6 @@ internal StreamingMessage ProcessFunctionEnvironmentReloadRequest(StreamingMessa environmentReloadRequest.EnvironmentVariables, environmentReloadRequest.FunctionAppDirectory); - // This will force the OpenTelemetryController to check the environment variables and module presence again - OpenTelemetryController.ResetOpenTelemetryModuleStatus(); - rpcLogger.Log(isUserOnlyLog: false, LogLevel.Trace, string.Format(PowerShellWorkerStrings.EnvironmentReloadCompleted, stopwatch.ElapsedMilliseconds)); StreamingMessage response = NewStreamingMessageTemplate( @@ -396,6 +393,15 @@ internal StreamingMessage ProcessFunctionEnvironmentReloadRequest(StreamingMessa StreamingMessage.ContentOneofCase.FunctionEnvironmentReloadResponse, out StatusResult status); + // This will force the OpenTelemetryController to check the environment variables and module presence again + OpenTelemetryController.ResetOpenTelemetryModuleStatus(); + if (OpenTelemetryController.isOpenTelemetryEnvironmentEnabled()) + { + // Note: The ability to edit worker capabilities is new within the last few months. I am unsure if we need to + // report all prior capabilities that were sent at worker init. Going with minimal change for now. + response.FunctionEnvironmentReloadResponse.Capabilities.Add("WorkerOpenTelemetryEnabled", "true"); + } + return response; } From 48c83b43666d76d070e6ce14e6043fc200baf92b Mon Sep 17 00:00:00 2001 From: Andy Staples Date: Tue, 9 Apr 2024 18:15:11 -0600 Subject: [PATCH 3/8] Initial PR review changes - Outline of unit testing, more is needed --- src/DurableSDK/PowerShellServices.cs | 33 +--- src/Logging/LoggingEventHandler.cs | 14 +- src/OpenTelemetry/IOpenTelemetryServices.cs | 16 ++ src/OpenTelemetry/OpenTelemetryController.cs | 107 ++++++++++++ .../OpenTelemetryInvocationContext.cs | 2 +- src/OpenTelemetry/OpenTelemetryServices.cs | 65 ++++++++ .../OpenTelemetryController.cs | 152 ------------------ src/PowerShell/PowerShellManager.cs | 2 +- src/PowerShell/PowerShellModuleDetector.cs | 56 +++++++ src/RequestProcessor.cs | 6 +- src/resources/PowerShellWorkerStrings.resx | 6 + .../OpenTelemetryControllerTests.cs | 37 +++++ 12 files changed, 296 insertions(+), 200 deletions(-) create mode 100644 src/OpenTelemetry/IOpenTelemetryServices.cs create mode 100644 src/OpenTelemetry/OpenTelemetryController.cs rename src/{OpenTelemetrySDK => OpenTelemetry}/OpenTelemetryInvocationContext.cs (99%) create mode 100644 src/OpenTelemetry/OpenTelemetryServices.cs delete mode 100644 src/OpenTelemetrySDK/OpenTelemetryController.cs create mode 100644 src/PowerShell/PowerShellModuleDetector.cs create mode 100644 test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs diff --git a/src/DurableSDK/PowerShellServices.cs b/src/DurableSDK/PowerShellServices.cs index 98e48783..6f9a0c03 100644 --- a/src/DurableSDK/PowerShellServices.cs +++ b/src/DurableSDK/PowerShellServices.cs @@ -9,12 +9,10 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.Durable using System.Collections.ObjectModel; using System.Linq; using System.Management.Automation; - using System.Reflection.Metadata; using Microsoft.Azure.Functions.PowerShellWorker.PowerShell; using Microsoft.Azure.Functions.PowerShellWorker.Utility; using Microsoft.Azure.WebJobs.Script.Grpc.Messages; using Newtonsoft.Json; - using LogLevel = WebJobs.Script.Grpc.Messages.RpcLog.Types.Level; internal class PowerShellServices : IPowerShellServices { @@ -43,36 +41,7 @@ public PowerShellServices(PowerShell pwsh, ILogger logger) public bool isExternalDurableSdkLoaded() { - // Search for the external DF SDK in the current session - var matchingModules = _pwsh.AddCommand(Utils.GetModuleCmdletInfo) - .AddParameter("FullyQualifiedName", Utils.ExternalDurableSdkName) - .InvokeAndClearCommands(); - - // If we get at least one result, we know the external SDK was imported - var numCandidates = matchingModules.Count(); - var isModuleInCurrentSession = numCandidates > 0; - - if (isModuleInCurrentSession) - { - var candidatesInfo = matchingModules.Select(module => string.Format( - PowerShellWorkerStrings.FoundExternalDurableSdkInSession, module.Name, module.Version, module.Path)); - var externalSDKModuleInfo = string.Join('\n', candidatesInfo); - - if (numCandidates > 1) - { - // If there's more than 1 result, there may be runtime conflicts - // warn user of potential conflicts - _logger.Log(isUserOnlyLog: false, LogLevel.Warning, String.Format( - PowerShellWorkerStrings.MultipleExternalSDKsInSession, - numCandidates, Utils.ExternalDurableSdkName, externalSDKModuleInfo)); - } - else - { - // a single external SDK is in session. Report its metadata - _logger.Log(isUserOnlyLog: false, LogLevel.Trace, externalSDKModuleInfo); - } - } - return isModuleInCurrentSession; + return PowerShellModuleDetector.IsPowerShellModuleLoaded(_pwsh, _logger, Utils.ExternalDurableSdkName); } public void EnableExternalDurableSDK() diff --git a/src/Logging/LoggingEventHandler.cs b/src/Logging/LoggingEventHandler.cs index b4bd1dac..3b81005d 100644 --- a/src/Logging/LoggingEventHandler.cs +++ b/src/Logging/LoggingEventHandler.cs @@ -5,24 +5,16 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.Utility { internal class LoggingEventHandler { - private HashSet> _eventHandlers = new HashSet>(); + private Action _eventHandler = (a, b, c) => { }; public void Subscribe(Action handler) { - _eventHandlers.Add(handler); - } - - public void Unsubscribe(Action handler) - { - _eventHandlers.Remove(handler); + _eventHandler = handler; } public void LogToHandlers(string level, string message, Exception exception = null) { - foreach (var handler in _eventHandlers) - { - handler(level, message, exception); - } + _eventHandler(level, message, exception); } } } diff --git a/src/OpenTelemetry/IOpenTelemetryServices.cs b/src/OpenTelemetry/IOpenTelemetryServices.cs new file mode 100644 index 00000000..5e84b638 --- /dev/null +++ b/src/OpenTelemetry/IOpenTelemetryServices.cs @@ -0,0 +1,16 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Text; +using System.Threading.Tasks; + +namespace Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetry +{ + internal interface IOpenTelemetryServices + { + bool? IsModuleLoaded(); + void AddStartOpenTelemetryInvocationCommand(OpenTelemetryInvocationContext otelContext); + void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext); + void StartFunctionsLoggingListener(); + } +} diff --git a/src/OpenTelemetry/OpenTelemetryController.cs b/src/OpenTelemetry/OpenTelemetryController.cs new file mode 100644 index 00000000..367c90a8 --- /dev/null +++ b/src/OpenTelemetry/OpenTelemetryController.cs @@ -0,0 +1,107 @@ +using System; +using System.Linq; +using Microsoft.Azure.Functions.PowerShellWorker.PowerShell; +using Microsoft.Azure.Functions.PowerShellWorker.Utility; +using LogLevel = Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types.Level; + +namespace Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetry +{ + using PowerShell = System.Management.Automation.PowerShell; + + internal class OpenTelemetryController + { + private IOpenTelemetryServices _services; + + private const string OTelEnabledEnvironmentVariableName = "OTEL_FUNCTIONS_WORKER_ENABLED"; + + private static bool? _isOpenTelemetryCapable; + private static bool? _isOpenTelemetryModuleLoaded; + private static bool? _isOpenTelmetryEnvironmentEnabled; + + public OpenTelemetryController(ILogger logger, PowerShell pwsh) + : this(new OpenTelemetryServices(logger, pwsh)) + { } + + public OpenTelemetryController(IOpenTelemetryServices services) + { + _services = services; + } + + public bool IsOpenTelemetryCapable() + { + if (_isOpenTelemetryCapable.HasValue) + { + return _isOpenTelemetryCapable.Value; + } + + _isOpenTelemetryCapable = IsOpenTelemetryEnvironmentEnabled() && IsOpenTelemetryModuleLoaded(); + + return _isOpenTelemetryCapable.Value; + } + + public static bool IsOpenTelemetryEnvironmentEnabled() + { + if (_isOpenTelmetryEnvironmentEnabled.HasValue) + { + return _isOpenTelmetryEnvironmentEnabled.Value; + } + + string enabledEnvVarValue = Environment.GetEnvironmentVariable(OTelEnabledEnvironmentVariableName); + + if (!string.IsNullOrEmpty(enabledEnvVarValue) && bool.TryParse(enabledEnvVarValue, out bool isEnabled)) + { + _isOpenTelmetryEnvironmentEnabled = isEnabled; + } + else + { + _isOpenTelmetryEnvironmentEnabled = false; + } + + return _isOpenTelmetryEnvironmentEnabled.Value; + } + + public bool IsOpenTelemetryModuleLoaded() + { + var isLoaded = _services.IsModuleLoaded(); + _isOpenTelemetryModuleLoaded = isLoaded; + return _isOpenTelemetryModuleLoaded.Value; + } + + public static void ResetOpenTelemetryModuleStatus() + { + _isOpenTelemetryCapable = null; + _isOpenTelemetryModuleLoaded = null; + _isOpenTelmetryEnvironmentEnabled = null; + } + + public void AddStartOpenTelemetryInvocationCommand(OpenTelemetryInvocationContext otelContext) + { + if (!IsOpenTelemetryCapable()) + { + return; + } + + _services.AddStartOpenTelemetryInvocationCommand(otelContext); + } + + public void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext) + { + if (!IsOpenTelemetryCapable()) + { + return; + } + + _services.StopOpenTelemetryInvocation(otelContext); + } + + internal void StartFunctionsLoggingListener() + { + if (!IsOpenTelemetryCapable()) + { + return; + } + + _services.StartFunctionsLoggingListener(); + } + } +} diff --git a/src/OpenTelemetrySDK/OpenTelemetryInvocationContext.cs b/src/OpenTelemetry/OpenTelemetryInvocationContext.cs similarity index 99% rename from src/OpenTelemetrySDK/OpenTelemetryInvocationContext.cs rename to src/OpenTelemetry/OpenTelemetryInvocationContext.cs index d1714ac7..368463c9 100644 --- a/src/OpenTelemetrySDK/OpenTelemetryInvocationContext.cs +++ b/src/OpenTelemetry/OpenTelemetryInvocationContext.cs @@ -4,7 +4,7 @@ using System.Text; using System.Threading.Tasks; -namespace Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetrySDK +namespace Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetry { internal class OpenTelemetryInvocationContext { diff --git a/src/OpenTelemetry/OpenTelemetryServices.cs b/src/OpenTelemetry/OpenTelemetryServices.cs new file mode 100644 index 00000000..022177d9 --- /dev/null +++ b/src/OpenTelemetry/OpenTelemetryServices.cs @@ -0,0 +1,65 @@ +using Microsoft.Azure.Functions.PowerShellWorker.PowerShell; +using Microsoft.Azure.Functions.PowerShellWorker.Utility; +using System.Linq; +using System; + +namespace Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetry +{ + using PowerShell = System.Management.Automation.PowerShell; + using LogLevel = Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types.Level; + + internal class OpenTelemetryServices : IOpenTelemetryServices + { + private const string StartOpenTelemetryInvocationCmdlet = "Start-OpenTelemetryInvocationInternal"; + private const string StopOpenTelemetryInvocationCmdlet = "Stop-OpenTelemetryInvocationInternal"; + private const string GetFunctionsLogHandlerCmdlet = "Get-FunctionsLogHandlerInternal"; + + private readonly ILogger _logger; + private readonly PowerShell _pwsh; + + public OpenTelemetryServices(ILogger logger, PowerShell pwsh) + { + _logger = logger; + _pwsh = pwsh; + } + + public bool? IsModuleLoaded() + { + return PowerShellModuleDetector.IsPowerShellModuleLoaded(_pwsh, _logger, Utils.OpenTelemetrySdkName); + } + + public void AddStartOpenTelemetryInvocationCommand(OpenTelemetryInvocationContext otelContext) + { + if (!otelContext.isValid()) + { + _logger.Log(false, LogLevel.Warning, PowerShellWorkerStrings.InvalidOpenTelemetryContext); + } + + _pwsh.AddCommand(StartOpenTelemetryInvocationCmdlet) + .AddParameter("InvocationId", otelContext.InvocationId) + .AddParameter("TraceParent", otelContext.TraceParent) + .AddParameter("TraceState", otelContext.TraceState); + } + + public void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext) + { + _pwsh.AddCommand(StopOpenTelemetryInvocationCmdlet) + .AddParameter("InvocationId", otelContext.InvocationId) + .InvokeAndClearCommands(); + } + + public void StartFunctionsLoggingListener() + { + var eventHandlers = _pwsh.AddCommand(GetFunctionsLogHandlerCmdlet) + .InvokeAndClearCommands>(); + + if (eventHandlers.Any()) + { + if (_logger is RpcLogger rpcLogger) + { + rpcLogger.outputLogHandler.Subscribe(eventHandlers.First()); + } + } + } + } +} diff --git a/src/OpenTelemetrySDK/OpenTelemetryController.cs b/src/OpenTelemetrySDK/OpenTelemetryController.cs deleted file mode 100644 index 0fa60038..00000000 --- a/src/OpenTelemetrySDK/OpenTelemetryController.cs +++ /dev/null @@ -1,152 +0,0 @@ -using System; -using System.Linq; -using System.Management.Automation; -using Microsoft.Azure.Functions.PowerShellWorker.PowerShell; -using Microsoft.Azure.Functions.PowerShellWorker.Utility; -using LogLevel = Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types.Level; - -namespace Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetrySDK -{ - using PowerShell = System.Management.Automation.PowerShell; - - internal class OpenTelemetryController - { - private readonly ILogger _logger; - private PowerShell _pwsh { get; set; } - - private const string StartOpenTelemetryInvocationCmdlet = "Start-OpenTelemetryInvocation"; - private const string StopOpenTelemetryInvocationCmdlet = "Stop-OpenTelemetryInvocation"; - private const string GetFunctionsLogHandlerCmdlet = "Get-FunctionsLogHandler"; - - private const string OTelEnvironmentVariableName = "OTEL_FUNCTIONS_WORKER_ENABLED"; - - private static bool? _isOpenTelemetryCapable; - private static bool? _isOpenTelemetryModuleLoaded; - private static bool? _isOpenTelmetryEnvironmentEnabled; - - public OpenTelemetryController(ILogger logger, PowerShell pwsh) - { - _logger = logger; - _pwsh = pwsh; - } - - public bool isOpenTelemetryCapable() - { - if (_isOpenTelemetryCapable.HasValue) - { - return _isOpenTelemetryCapable.Value; - } - - _isOpenTelemetryCapable = isOpenTelemetryEnvironmentEnabled() && isOpenTelemetryModuleLoaded(); - - return _isOpenTelemetryCapable.Value; - } - - public static bool isOpenTelemetryEnvironmentEnabled() - { - if (_isOpenTelmetryEnvironmentEnabled.HasValue) - { - return _isOpenTelmetryEnvironmentEnabled.Value; - } - - string isOpenTelemetryWorkerLogEnabled = Environment.GetEnvironmentVariable(OTelEnvironmentVariableName); - _isOpenTelmetryEnvironmentEnabled = !string.IsNullOrEmpty(isOpenTelemetryWorkerLogEnabled); - - return _isOpenTelmetryEnvironmentEnabled.Value; - } - - public bool isOpenTelemetryModuleLoaded() - { - if (_isOpenTelemetryModuleLoaded.HasValue) - { - return _isOpenTelemetryModuleLoaded.Value; - } - - // Search for the OpenTelemetry SDK in the current session - var matchingModules = _pwsh.AddCommand(Utils.GetModuleCmdletInfo) - .AddParameter("FullyQualifiedName", Utils.OpenTelemetrySdkName) - .InvokeAndClearCommands(); - - // If we get at least one result, we know the OpenTelemetry SDK was imported - var numCandidates = matchingModules.Count(); - var isModuleInCurrentSession = numCandidates > 0; - - if (isModuleInCurrentSession) - { - var candidatesInfo = matchingModules.Select(module => string.Format( - PowerShellWorkerStrings.FoundOpenTelemetrySdkInSession, module.Name, module.Version, module.Path)); - var otelSDKModuleInfo = string.Join('\n', candidatesInfo); - - if (numCandidates > 1) - { - // If there's more than 1 result, there may be runtime conflicts - // warn user of potential conflicts - _logger.Log(isUserOnlyLog: false, LogLevel.Warning, String.Format( - PowerShellWorkerStrings.MultipleExternalSDKsInSession, - numCandidates, Utils.OpenTelemetrySdkName, otelSDKModuleInfo)); - } - else - { - // a single SDK is in session. Report its metadata - _logger.Log(isUserOnlyLog: false, LogLevel.Trace, otelSDKModuleInfo); - } - } - - _isOpenTelemetryModuleLoaded = isModuleInCurrentSession; - - - return _isOpenTelemetryModuleLoaded.Value; - } - - public static void ResetOpenTelemetryModuleStatus() - { - _isOpenTelemetryCapable = null; - _isOpenTelemetryModuleLoaded = null; - _isOpenTelmetryEnvironmentEnabled = null; - } - - public void AddStartOpenTelemetryInvocationCommand(OpenTelemetryInvocationContext otelContext) - { - if (!isOpenTelemetryCapable() || !otelContext.isValid()) - { - return; - } - - _pwsh.AddCommand(StartOpenTelemetryInvocationCmdlet) - .AddParameter("InvocationId", otelContext.InvocationId) - .AddParameter("TraceParent", otelContext.TraceParent) - .AddParameter("TraceState", otelContext.TraceState); - } - - public void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext) - { - if (!isOpenTelemetryCapable()) - { - return; - } - - _pwsh.AddCommand(StopOpenTelemetryInvocationCmdlet) - .AddParameter("InvocationId", otelContext.InvocationId) - .InvokeAndClearCommands(); - } - - internal void StartFunctionsLoggingListener() - { - if (!isOpenTelemetryCapable()) - { - return; - } - - var eventHandlers = _pwsh.AddCommand(GetFunctionsLogHandlerCmdlet) - .InvokeAndClearCommands>(); - - foreach (var eventHandler in eventHandlers) - { - if (_logger is RpcLogger rpcLogger) - { - rpcLogger.outputLogHandler.Subscribe(eventHandler); - } - } - } - } -} diff --git a/src/PowerShell/PowerShellManager.cs b/src/PowerShell/PowerShellManager.cs index b7426356..5bd506b5 100644 --- a/src/PowerShell/PowerShellManager.cs +++ b/src/PowerShell/PowerShellManager.cs @@ -15,7 +15,7 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell { - using Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetrySDK; + using Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetry; using System.Management.Automation; using System.Text; diff --git a/src/PowerShell/PowerShellModuleDetector.cs b/src/PowerShell/PowerShellModuleDetector.cs new file mode 100644 index 00000000..753f756f --- /dev/null +++ b/src/PowerShell/PowerShellModuleDetector.cs @@ -0,0 +1,56 @@ +using Microsoft.Azure.Functions.PowerShellWorker.Utility; +using System; +using System.Linq; +using System.Management.Automation; + +namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell +{ + using LogLevel = WebJobs.Script.Grpc.Messages.RpcLog.Types.Level; + + internal class PowerShellModuleDetector + { + public static bool IsPowerShellModuleLoaded(System.Management.Automation.PowerShell _pwsh, ILogger _logger, string moduleName) + { + // Search for the external DF SDK in the current session + var matchingModules = _pwsh.AddCommand(Utils.GetModuleCmdletInfo) + .AddParameter("FullyQualifiedName", moduleName) + .InvokeAndClearCommands(); + + // If we get at least one result, we know the external SDK was imported + var numCandidates = matchingModules.Count(); + var isModuleInCurrentSession = numCandidates > 0; + + if (isModuleInCurrentSession) + { + string successMessage = PowerShellWorkerStrings.FoundExternalModuleInSession; + + if (moduleName == Utils.ExternalDurableSdkName) + { + successMessage = PowerShellWorkerStrings.FoundExternalDurableSdkInSession; + } + else if (moduleName == Utils.OpenTelemetrySdkName) + { + successMessage = PowerShellWorkerStrings.FoundOpenTelemetrySdkInSession; + } + + var candidatesInfo = matchingModules.Select(module => string.Format(successMessage, module.Name, module.Version, module.Path)); + var externalSDKModuleInfo = string.Join('\n', candidatesInfo); + + if (numCandidates > 1) + { + // If there's more than 1 result, there may be runtime conflicts + // warn user of potential conflicts + _logger.Log(isUserOnlyLog: false, LogLevel.Warning, String.Format( + PowerShellWorkerStrings.MultipleExternalSDKsInSession, + numCandidates, moduleName, externalSDKModuleInfo)); + } + else + { + // a single external SDK is in session. Report its metadata + _logger.Log(isUserOnlyLog: false, LogLevel.Trace, externalSDKModuleInfo); + } + } + return isModuleInCurrentSession; + } + } +} diff --git a/src/RequestProcessor.cs b/src/RequestProcessor.cs index 5c276ca1..ee3378ad 100644 --- a/src/RequestProcessor.cs +++ b/src/RequestProcessor.cs @@ -21,7 +21,7 @@ namespace Microsoft.Azure.Functions.PowerShellWorker using System.Diagnostics; using LogLevel = Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types.Level; using System.Runtime.InteropServices; - using Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetrySDK; + using Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetry; internal class RequestProcessor { @@ -114,7 +114,7 @@ internal StreamingMessage ProcessWorkerInitRequest(StreamingMessage request) response.WorkerInitResponse.Capabilities.Add("RpcHttpBodyOnly", "true"); response.WorkerInitResponse.Capabilities.Add("WorkerStatus", "true"); - if (OpenTelemetryController.isOpenTelemetryEnvironmentEnabled()) + if (OpenTelemetryController.IsOpenTelemetryEnvironmentEnabled()) { response.WorkerInitResponse.Capabilities.Add("WorkerOpenTelemetryEnabled", "true"); } @@ -395,7 +395,7 @@ internal StreamingMessage ProcessFunctionEnvironmentReloadRequest(StreamingMessa // This will force the OpenTelemetryController to check the environment variables and module presence again OpenTelemetryController.ResetOpenTelemetryModuleStatus(); - if (OpenTelemetryController.isOpenTelemetryEnvironmentEnabled()) + if (OpenTelemetryController.IsOpenTelemetryEnvironmentEnabled()) { // Note: The ability to edit worker capabilities is new within the last few months. I am unsure if we need to // report all prior capabilities that were sent at worker init. Going with minimal change for now. diff --git a/src/resources/PowerShellWorkerStrings.resx b/src/resources/PowerShellWorkerStrings.resx index 710687c0..53f0c801 100644 --- a/src/resources/PowerShellWorkerStrings.resx +++ b/src/resources/PowerShellWorkerStrings.resx @@ -382,4 +382,10 @@ Managed Dependencies is not supported in Linux Consumption on Legion. Please remove all module references from requirements.psd1 and include the function app dependencies with the function app content. For more information, please see https://aka.ms/functions-powershell-include-modules. + + Found external module in session: Name='{0}', Version='{1}', Path='{2}'. + + + The app is configured to use OpenTelemetry but the TraceContext passed from host was null. + \ No newline at end of file diff --git a/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs b/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs new file mode 100644 index 00000000..a3a4d29b --- /dev/null +++ b/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs @@ -0,0 +1,37 @@ +using Moq; +using System; +using Xunit; + +using Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetry; + +namespace Microsoft.Azure.Functions.PowerShellWorker.Test.OpenTelemetry +{ + public class OpenTelemetryControllerTests + { + private readonly Mock _mockOtelServices = new Mock(MockBehavior.Strict); + + [Theory] + [InlineData("true", true)] + [InlineData("false", false)] + [InlineData(null, false)] + internal void OpenTelemetryEnvironmentVariableCheckWorking(string? environmentVariableValue, bool desiredResult) + { + try + { + Environment.SetEnvironmentVariable("OTEL_FUNCTIONS_WORKER_ENABLED", environmentVariableValue); + + Assert.Equal(desiredResult, OpenTelemetryController.IsOpenTelemetryEnvironmentEnabled()); + } + finally + { + Environment.SetEnvironmentVariable("OTEL_FUNCTIONS_WORKER_ENABLED", null); + OpenTelemetryController.ResetOpenTelemetryModuleStatus(); + } + } + + private OpenTelemetryController CreateOpenTelemetryController() + { + return new OpenTelemetryController(_mockOtelServices.Object); + } + } +} From 4589d8fdd2c40ce474afd72c0c8c0977f01c7995 Mon Sep 17 00:00:00 2001 From: Andy Staples Date: Wed, 10 Apr 2024 13:27:33 -0600 Subject: [PATCH 4/8] Expand testing --- src/OpenTelemetry/IOpenTelemetryServices.cs | 4 +- src/OpenTelemetry/OpenTelemetryController.cs | 8 +- src/OpenTelemetry/OpenTelemetryServices.cs | 25 +++- .../OpenTelemetryControllerTests.cs | 132 +++++++++++++++++- 4 files changed, 153 insertions(+), 16 deletions(-) diff --git a/src/OpenTelemetry/IOpenTelemetryServices.cs b/src/OpenTelemetry/IOpenTelemetryServices.cs index 5e84b638..93315928 100644 --- a/src/OpenTelemetry/IOpenTelemetryServices.cs +++ b/src/OpenTelemetry/IOpenTelemetryServices.cs @@ -10,7 +10,7 @@ internal interface IOpenTelemetryServices { bool? IsModuleLoaded(); void AddStartOpenTelemetryInvocationCommand(OpenTelemetryInvocationContext otelContext); - void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext); - void StartFunctionsLoggingListener(); + void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext, bool testing); + void StartFunctionsLoggingListener(bool testing); } } diff --git a/src/OpenTelemetry/OpenTelemetryController.cs b/src/OpenTelemetry/OpenTelemetryController.cs index 367c90a8..825a1d75 100644 --- a/src/OpenTelemetry/OpenTelemetryController.cs +++ b/src/OpenTelemetry/OpenTelemetryController.cs @@ -84,24 +84,24 @@ public void AddStartOpenTelemetryInvocationCommand(OpenTelemetryInvocationContex _services.AddStartOpenTelemetryInvocationCommand(otelContext); } - public void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext) + public void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext, bool testing = false) { if (!IsOpenTelemetryCapable()) { return; } - _services.StopOpenTelemetryInvocation(otelContext); + _services.StopOpenTelemetryInvocation(otelContext, testing); } - internal void StartFunctionsLoggingListener() + internal void StartFunctionsLoggingListener(bool testing = false) { if (!IsOpenTelemetryCapable()) { return; } - _services.StartFunctionsLoggingListener(); + _services.StartFunctionsLoggingListener(testing); } } } diff --git a/src/OpenTelemetry/OpenTelemetryServices.cs b/src/OpenTelemetry/OpenTelemetryServices.cs index 022177d9..4e67f9f6 100644 --- a/src/OpenTelemetry/OpenTelemetryServices.cs +++ b/src/OpenTelemetry/OpenTelemetryServices.cs @@ -15,7 +15,7 @@ internal class OpenTelemetryServices : IOpenTelemetryServices private const string GetFunctionsLogHandlerCmdlet = "Get-FunctionsLogHandlerInternal"; private readonly ILogger _logger; - private readonly PowerShell _pwsh; + public readonly PowerShell _pwsh; public OpenTelemetryServices(ILogger logger, PowerShell pwsh) { @@ -41,17 +41,28 @@ public void AddStartOpenTelemetryInvocationCommand(OpenTelemetryInvocationContex .AddParameter("TraceState", otelContext.TraceState); } - public void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext) + public void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext, bool _testing) { _pwsh.AddCommand(StopOpenTelemetryInvocationCmdlet) - .AddParameter("InvocationId", otelContext.InvocationId) - .InvokeAndClearCommands(); + .AddParameter("InvocationId", otelContext.InvocationId); + + if (!_testing) + { + _pwsh.InvokeAndClearCommands(); + } } - public void StartFunctionsLoggingListener() + public void StartFunctionsLoggingListener(bool testing) { - var eventHandlers = _pwsh.AddCommand(GetFunctionsLogHandlerCmdlet) - .InvokeAndClearCommands>(); + _pwsh.AddCommand(GetFunctionsLogHandlerCmdlet); + + if (testing) + { + return; + } + + var eventHandlers = + _pwsh.InvokeAndClearCommands>(); if (eventHandlers.Any()) { diff --git a/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs b/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs index a3a4d29b..dabf4a05 100644 --- a/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs +++ b/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs @@ -3,18 +3,28 @@ using Xunit; using Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetry; +using System.Linq; +using Microsoft.Azure.Functions.PowerShellWorker.Utility; namespace Microsoft.Azure.Functions.PowerShellWorker.Test.OpenTelemetry { + using PowerShell = System.Management.Automation.PowerShell; + public class OpenTelemetryControllerTests { - private readonly Mock _mockOtelServices = new Mock(MockBehavior.Strict); + private readonly Mock _mockLogger = new Mock(MockBehavior.Strict); + private readonly Mock _mockOtelServices; + + public OpenTelemetryControllerTests() + { + _mockOtelServices = new Mock(MockBehavior.Strict); + } [Theory] [InlineData("true", true)] [InlineData("false", false)] [InlineData(null, false)] - internal void OpenTelemetryEnvironmentVariableCheckWorking(string? environmentVariableValue, bool desiredResult) + internal void OpenTelemetryEnvironmentVariableCheckWorks(string? environmentVariableValue, bool desiredResult) { try { @@ -29,7 +39,123 @@ internal void OpenTelemetryEnvironmentVariableCheckWorking(string? environmentVa } } - private OpenTelemetryController CreateOpenTelemetryController() + [Fact] + internal void AddStartOpenTelemetryInvocationCommand_AddsCommands() + { + try + { + PowerShell _pwsh = PowerShell.Create(); + var _realOTelServices = new OpenTelemetryServices(_mockLogger.Object, _pwsh); + + OpenTelemetryController controller = CreateMockOpenTelemetryController(); + + OpenTelemetryInvocationContext context = new OpenTelemetryInvocationContext( + "93d73ba2-bac9-41f9-ad31-e7ab56a6d7e1", + "00-59081e54d24b74f20957499295f4e835-b492942fa64debb3-00", + "" + ); + + Environment.SetEnvironmentVariable("OTEL_FUNCTIONS_WORKER_ENABLED", "true"); + _mockOtelServices.Setup(_ => _.IsModuleLoaded()).Returns(true); + _mockOtelServices.Setup(_ => _.AddStartOpenTelemetryInvocationCommand(context)) + .Callback(() => _realOTelServices.AddStartOpenTelemetryInvocationCommand(context)); + + controller.AddStartOpenTelemetryInvocationCommand(context); + + Assert.Single(_pwsh.Commands.Commands); + Assert.Equal("Start-OpenTelemetryInvocationInternal", _pwsh.Commands.Commands.First().CommandText); + + var parameters = _pwsh.Commands.Commands.First().Parameters; + Assert.Equal(3, parameters.Count); + Assert.Equal("InvocationId", parameters.ElementAt(0).Name); + Assert.Equal(context.InvocationId, parameters.ElementAt(0).Value); + Assert.Equal("TraceParent", parameters.ElementAt(1).Name); + Assert.Equal(context.TraceParent, parameters.ElementAt(1).Value); + Assert.Equal("TraceState", parameters.ElementAt(2).Name); + Assert.Equal(context.TraceState, parameters.ElementAt(2).Value); + + _mockOtelServices.Verify(_ => _.AddStartOpenTelemetryInvocationCommand(context), Times.Once); + } + finally + { + Environment.SetEnvironmentVariable("OTEL_FUNCTIONS_WORKER_ENABLED", null); + OpenTelemetryController.ResetOpenTelemetryModuleStatus(); + } + } + + [Fact] + internal void StopOpenTelemetryInvocationCommand_AddsCommands() + { + try + { + PowerShell _pwsh = PowerShell.Create(); + var _realOTelServices = new OpenTelemetryServices(_mockLogger.Object, _pwsh); + + OpenTelemetryController controller = CreateMockOpenTelemetryController(); + + OpenTelemetryInvocationContext context = new OpenTelemetryInvocationContext( + "93d73ba2-bac9-41f9-ad31-e7ab56a6d7e1", + "00-59081e54d24b74f20957499295f4e835-b492942fa64debb3-00", + "" + ); + + Environment.SetEnvironmentVariable("OTEL_FUNCTIONS_WORKER_ENABLED", "true"); + _mockOtelServices.Setup(_ => _.IsModuleLoaded()).Returns(true); + _mockOtelServices.Setup(_ => _.StopOpenTelemetryInvocation(context, true)) + .Callback(() => _realOTelServices.StopOpenTelemetryInvocation(context, true)); + + controller.StopOpenTelemetryInvocation(context, true); + + Assert.Single(_pwsh.Commands.Commands); + Assert.Equal("Stop-OpenTelemetryInvocationInternal", _pwsh.Commands.Commands.First().CommandText); + + var parameters = _pwsh.Commands.Commands.First().Parameters; + Assert.Single(parameters); + Assert.Equal("InvocationId", parameters.ElementAt(0).Name); + Assert.Equal(context.InvocationId, parameters.ElementAt(0).Value); + + _mockOtelServices.Verify(_ => _.StopOpenTelemetryInvocation(context, true), Times.Once); + } + finally + { + Environment.SetEnvironmentVariable("OTEL_FUNCTIONS_WORKER_ENABLED", null); + OpenTelemetryController.ResetOpenTelemetryModuleStatus(); + } + } + + [Fact] + internal void StartFunctionsLoggingListener_CorrectCommands() + { + try + { + PowerShell _pwsh = PowerShell.Create(); + var _realOTelServices = new OpenTelemetryServices(_mockLogger.Object, _pwsh); + + OpenTelemetryController controller = CreateMockOpenTelemetryController(); + + Environment.SetEnvironmentVariable("OTEL_FUNCTIONS_WORKER_ENABLED", "true"); + _mockOtelServices.Setup(_ => _.IsModuleLoaded()).Returns(true); + _mockOtelServices.Setup(_ => _.StartFunctionsLoggingListener(true)) + .Callback(() => _realOTelServices.StartFunctionsLoggingListener(true)); + + controller.StartFunctionsLoggingListener(true); + + Assert.Single(_pwsh.Commands.Commands); + Assert.Equal("Get-FunctionsLogHandlerInternal", _pwsh.Commands.Commands.First().CommandText); + + var parameters = _pwsh.Commands.Commands.First().Parameters; + Assert.Empty(parameters); + + _mockOtelServices.Verify(_ => _.StartFunctionsLoggingListener(true), Times.Once); + } + finally + { + Environment.SetEnvironmentVariable("OTEL_FUNCTIONS_WORKER_ENABLED", null); + OpenTelemetryController.ResetOpenTelemetryModuleStatus(); + } + } + + private OpenTelemetryController CreateMockOpenTelemetryController() { return new OpenTelemetryController(_mockOtelServices.Object); } From ecdfbf510f8d79ef92c6e09652b58dbb1086a830 Mon Sep 17 00:00:00 2001 From: Andy Staples Date: Wed, 10 Apr 2024 13:58:44 -0600 Subject: [PATCH 5/8] Additional PR changes --- src/OpenTelemetry/OpenTelemetryController.cs | 3 --- src/OpenTelemetry/OpenTelemetryInvocationContext.cs | 2 +- src/OpenTelemetry/OpenTelemetryServices.cs | 2 +- src/PowerShell/PowerShellModuleDetector.cs | 6 +++--- 4 files changed, 5 insertions(+), 8 deletions(-) diff --git a/src/OpenTelemetry/OpenTelemetryController.cs b/src/OpenTelemetry/OpenTelemetryController.cs index 825a1d75..ad36b136 100644 --- a/src/OpenTelemetry/OpenTelemetryController.cs +++ b/src/OpenTelemetry/OpenTelemetryController.cs @@ -1,8 +1,5 @@ using System; -using System.Linq; -using Microsoft.Azure.Functions.PowerShellWorker.PowerShell; using Microsoft.Azure.Functions.PowerShellWorker.Utility; -using LogLevel = Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types.Level; namespace Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetry { diff --git a/src/OpenTelemetry/OpenTelemetryInvocationContext.cs b/src/OpenTelemetry/OpenTelemetryInvocationContext.cs index 368463c9..54178edb 100644 --- a/src/OpenTelemetry/OpenTelemetryInvocationContext.cs +++ b/src/OpenTelemetry/OpenTelemetryInvocationContext.cs @@ -15,7 +15,7 @@ public OpenTelemetryInvocationContext(string invocationId, string traceParent, s TraceState = traceState; } - public bool isValid() + public bool IsValid() { return InvocationId != null && TraceParent != null; } diff --git a/src/OpenTelemetry/OpenTelemetryServices.cs b/src/OpenTelemetry/OpenTelemetryServices.cs index 4e67f9f6..43ee2d3c 100644 --- a/src/OpenTelemetry/OpenTelemetryServices.cs +++ b/src/OpenTelemetry/OpenTelemetryServices.cs @@ -30,7 +30,7 @@ public OpenTelemetryServices(ILogger logger, PowerShell pwsh) public void AddStartOpenTelemetryInvocationCommand(OpenTelemetryInvocationContext otelContext) { - if (!otelContext.isValid()) + if (!otelContext.IsValid()) { _logger.Log(false, LogLevel.Warning, PowerShellWorkerStrings.InvalidOpenTelemetryContext); } diff --git a/src/PowerShell/PowerShellModuleDetector.cs b/src/PowerShell/PowerShellModuleDetector.cs index 753f756f..dbee8c1c 100644 --- a/src/PowerShell/PowerShellModuleDetector.cs +++ b/src/PowerShell/PowerShellModuleDetector.cs @@ -11,12 +11,12 @@ internal class PowerShellModuleDetector { public static bool IsPowerShellModuleLoaded(System.Management.Automation.PowerShell _pwsh, ILogger _logger, string moduleName) { - // Search for the external DF SDK in the current session + // Search for the module in the current session var matchingModules = _pwsh.AddCommand(Utils.GetModuleCmdletInfo) .AddParameter("FullyQualifiedName", moduleName) .InvokeAndClearCommands(); - // If we get at least one result, we know the external SDK was imported + // If we get at least one result, we know the module was imported var numCandidates = matchingModules.Count(); var isModuleInCurrentSession = numCandidates > 0; @@ -46,7 +46,7 @@ public static bool IsPowerShellModuleLoaded(System.Management.Automation.PowerSh } else { - // a single external SDK is in session. Report its metadata + // a single module is in session. Report its metadata _logger.Log(isUserOnlyLog: false, LogLevel.Trace, externalSDKModuleInfo); } } From 59effad78d0b392c28927c3f59126f4fadc20ec3 Mon Sep 17 00:00:00 2001 From: Andy Staples Date: Thu, 11 Apr 2024 15:09:12 -0600 Subject: [PATCH 6/8] Better naming in tests --- src/OpenTelemetry/IOpenTelemetryServices.cs | 4 +-- src/OpenTelemetry/OpenTelemetryController.cs | 8 ++--- src/OpenTelemetry/OpenTelemetryServices.cs | 8 ++--- .../OpenTelemetryControllerTests.cs | 35 +++++++++++-------- 4 files changed, 31 insertions(+), 24 deletions(-) diff --git a/src/OpenTelemetry/IOpenTelemetryServices.cs b/src/OpenTelemetry/IOpenTelemetryServices.cs index 93315928..caaa33b2 100644 --- a/src/OpenTelemetry/IOpenTelemetryServices.cs +++ b/src/OpenTelemetry/IOpenTelemetryServices.cs @@ -10,7 +10,7 @@ internal interface IOpenTelemetryServices { bool? IsModuleLoaded(); void AddStartOpenTelemetryInvocationCommand(OpenTelemetryInvocationContext otelContext); - void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext, bool testing); - void StartFunctionsLoggingListener(bool testing); + void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext, bool invokeCommands); + void StartFunctionsLoggingListener(bool invokeCommands); } } diff --git a/src/OpenTelemetry/OpenTelemetryController.cs b/src/OpenTelemetry/OpenTelemetryController.cs index ad36b136..3ac91866 100644 --- a/src/OpenTelemetry/OpenTelemetryController.cs +++ b/src/OpenTelemetry/OpenTelemetryController.cs @@ -81,24 +81,24 @@ public void AddStartOpenTelemetryInvocationCommand(OpenTelemetryInvocationContex _services.AddStartOpenTelemetryInvocationCommand(otelContext); } - public void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext, bool testing = false) + public void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext, bool invokeCommands = true) { if (!IsOpenTelemetryCapable()) { return; } - _services.StopOpenTelemetryInvocation(otelContext, testing); + _services.StopOpenTelemetryInvocation(otelContext, invokeCommands); } - internal void StartFunctionsLoggingListener(bool testing = false) + internal void StartFunctionsLoggingListener(bool invokeCommands = true) { if (!IsOpenTelemetryCapable()) { return; } - _services.StartFunctionsLoggingListener(testing); + _services.StartFunctionsLoggingListener(invokeCommands); } } } diff --git a/src/OpenTelemetry/OpenTelemetryServices.cs b/src/OpenTelemetry/OpenTelemetryServices.cs index 43ee2d3c..311e0201 100644 --- a/src/OpenTelemetry/OpenTelemetryServices.cs +++ b/src/OpenTelemetry/OpenTelemetryServices.cs @@ -41,22 +41,22 @@ public void AddStartOpenTelemetryInvocationCommand(OpenTelemetryInvocationContex .AddParameter("TraceState", otelContext.TraceState); } - public void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext, bool _testing) + public void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext, bool invokeCommands) { _pwsh.AddCommand(StopOpenTelemetryInvocationCmdlet) .AddParameter("InvocationId", otelContext.InvocationId); - if (!_testing) + if (invokeCommands) { _pwsh.InvokeAndClearCommands(); } } - public void StartFunctionsLoggingListener(bool testing) + public void StartFunctionsLoggingListener(bool invokeCommands) { _pwsh.AddCommand(GetFunctionsLogHandlerCmdlet); - if (testing) + if (!invokeCommands) { return; } diff --git a/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs b/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs index dabf4a05..eb75b563 100644 --- a/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs +++ b/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs @@ -12,6 +12,11 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.Test.OpenTelemetry public class OpenTelemetryControllerTests { + // These constant values will work because they are not actually passed to the module + // The module would fail with these inputs, it needs real invocation id and trace information + private const string FakeInvocationID = "Fake InvocationID"; + private const string FakeTraceParent = "Fake TraceParent"; + private readonly Mock _mockLogger = new Mock(MockBehavior.Strict); private readonly Mock _mockOtelServices; @@ -23,6 +28,8 @@ public OpenTelemetryControllerTests() [Theory] [InlineData("true", true)] [InlineData("false", false)] + [InlineData("True", true)] + [InlineData("False", false)] [InlineData(null, false)] internal void OpenTelemetryEnvironmentVariableCheckWorks(string? environmentVariableValue, bool desiredResult) { @@ -50,9 +57,9 @@ internal void AddStartOpenTelemetryInvocationCommand_AddsCommands() OpenTelemetryController controller = CreateMockOpenTelemetryController(); OpenTelemetryInvocationContext context = new OpenTelemetryInvocationContext( - "93d73ba2-bac9-41f9-ad31-e7ab56a6d7e1", - "00-59081e54d24b74f20957499295f4e835-b492942fa64debb3-00", - "" + FakeInvocationID, + FakeTraceParent, + string.Empty ); Environment.SetEnvironmentVariable("OTEL_FUNCTIONS_WORKER_ENABLED", "true"); @@ -94,17 +101,17 @@ internal void StopOpenTelemetryInvocationCommand_AddsCommands() OpenTelemetryController controller = CreateMockOpenTelemetryController(); OpenTelemetryInvocationContext context = new OpenTelemetryInvocationContext( - "93d73ba2-bac9-41f9-ad31-e7ab56a6d7e1", - "00-59081e54d24b74f20957499295f4e835-b492942fa64debb3-00", - "" + FakeInvocationID, + FakeTraceParent, + string.Empty ); Environment.SetEnvironmentVariable("OTEL_FUNCTIONS_WORKER_ENABLED", "true"); _mockOtelServices.Setup(_ => _.IsModuleLoaded()).Returns(true); - _mockOtelServices.Setup(_ => _.StopOpenTelemetryInvocation(context, true)) - .Callback(() => _realOTelServices.StopOpenTelemetryInvocation(context, true)); + _mockOtelServices.Setup(_ => _.StopOpenTelemetryInvocation(context, false)) + .Callback(() => _realOTelServices.StopOpenTelemetryInvocation(context, false)); - controller.StopOpenTelemetryInvocation(context, true); + controller.StopOpenTelemetryInvocation(context, false); Assert.Single(_pwsh.Commands.Commands); Assert.Equal("Stop-OpenTelemetryInvocationInternal", _pwsh.Commands.Commands.First().CommandText); @@ -114,7 +121,7 @@ internal void StopOpenTelemetryInvocationCommand_AddsCommands() Assert.Equal("InvocationId", parameters.ElementAt(0).Name); Assert.Equal(context.InvocationId, parameters.ElementAt(0).Value); - _mockOtelServices.Verify(_ => _.StopOpenTelemetryInvocation(context, true), Times.Once); + _mockOtelServices.Verify(_ => _.StopOpenTelemetryInvocation(context, false), Times.Once); } finally { @@ -135,10 +142,10 @@ internal void StartFunctionsLoggingListener_CorrectCommands() Environment.SetEnvironmentVariable("OTEL_FUNCTIONS_WORKER_ENABLED", "true"); _mockOtelServices.Setup(_ => _.IsModuleLoaded()).Returns(true); - _mockOtelServices.Setup(_ => _.StartFunctionsLoggingListener(true)) - .Callback(() => _realOTelServices.StartFunctionsLoggingListener(true)); + _mockOtelServices.Setup(_ => _.StartFunctionsLoggingListener(false)) + .Callback(() => _realOTelServices.StartFunctionsLoggingListener(false)); - controller.StartFunctionsLoggingListener(true); + controller.StartFunctionsLoggingListener(false); Assert.Single(_pwsh.Commands.Commands); Assert.Equal("Get-FunctionsLogHandlerInternal", _pwsh.Commands.Commands.First().CommandText); @@ -146,7 +153,7 @@ internal void StartFunctionsLoggingListener_CorrectCommands() var parameters = _pwsh.Commands.Commands.First().Parameters; Assert.Empty(parameters); - _mockOtelServices.Verify(_ => _.StartFunctionsLoggingListener(true), Times.Once); + _mockOtelServices.Verify(_ => _.StartFunctionsLoggingListener(false), Times.Once); } finally { From 04302ca6e283bd426ba20f28f19d87555768b1c2 Mon Sep 17 00:00:00 2001 From: Andy Staples Date: Thu, 11 Apr 2024 15:33:43 -0600 Subject: [PATCH 7/8] Explicit naming for services class --- ...vices.cs => IPowerShellServicesForOpenTelemetry.cs} | 2 +- src/OpenTelemetry/OpenTelemetryController.cs | 6 +++--- ...rvices.cs => PowerShellServicesForOpenTelemetry.cs} | 4 ++-- .../Unit/OpenTelemetry/OpenTelemetryControllerTests.cs | 10 +++++----- 4 files changed, 11 insertions(+), 11 deletions(-) rename src/OpenTelemetry/{IOpenTelemetryServices.cs => IPowerShellServicesForOpenTelemetry.cs} (89%) rename src/OpenTelemetry/{OpenTelemetryServices.cs => PowerShellServicesForOpenTelemetry.cs} (93%) diff --git a/src/OpenTelemetry/IOpenTelemetryServices.cs b/src/OpenTelemetry/IPowerShellServicesForOpenTelemetry.cs similarity index 89% rename from src/OpenTelemetry/IOpenTelemetryServices.cs rename to src/OpenTelemetry/IPowerShellServicesForOpenTelemetry.cs index caaa33b2..aeb6c171 100644 --- a/src/OpenTelemetry/IOpenTelemetryServices.cs +++ b/src/OpenTelemetry/IPowerShellServicesForOpenTelemetry.cs @@ -6,7 +6,7 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetry { - internal interface IOpenTelemetryServices + internal interface IPowerShellServicesForOpenTelemetry { bool? IsModuleLoaded(); void AddStartOpenTelemetryInvocationCommand(OpenTelemetryInvocationContext otelContext); diff --git a/src/OpenTelemetry/OpenTelemetryController.cs b/src/OpenTelemetry/OpenTelemetryController.cs index 3ac91866..5533d46f 100644 --- a/src/OpenTelemetry/OpenTelemetryController.cs +++ b/src/OpenTelemetry/OpenTelemetryController.cs @@ -7,7 +7,7 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetry internal class OpenTelemetryController { - private IOpenTelemetryServices _services; + private IPowerShellServicesForOpenTelemetry _services; private const string OTelEnabledEnvironmentVariableName = "OTEL_FUNCTIONS_WORKER_ENABLED"; @@ -16,10 +16,10 @@ internal class OpenTelemetryController private static bool? _isOpenTelmetryEnvironmentEnabled; public OpenTelemetryController(ILogger logger, PowerShell pwsh) - : this(new OpenTelemetryServices(logger, pwsh)) + : this(new PowerShellServicesForOpenTelemetry(logger, pwsh)) { } - public OpenTelemetryController(IOpenTelemetryServices services) + public OpenTelemetryController(IPowerShellServicesForOpenTelemetry services) { _services = services; } diff --git a/src/OpenTelemetry/OpenTelemetryServices.cs b/src/OpenTelemetry/PowerShellServicesForOpenTelemetry.cs similarity index 93% rename from src/OpenTelemetry/OpenTelemetryServices.cs rename to src/OpenTelemetry/PowerShellServicesForOpenTelemetry.cs index 311e0201..69668225 100644 --- a/src/OpenTelemetry/OpenTelemetryServices.cs +++ b/src/OpenTelemetry/PowerShellServicesForOpenTelemetry.cs @@ -8,7 +8,7 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetry using PowerShell = System.Management.Automation.PowerShell; using LogLevel = Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types.Level; - internal class OpenTelemetryServices : IOpenTelemetryServices + internal class PowerShellServicesForOpenTelemetry : IPowerShellServicesForOpenTelemetry { private const string StartOpenTelemetryInvocationCmdlet = "Start-OpenTelemetryInvocationInternal"; private const string StopOpenTelemetryInvocationCmdlet = "Stop-OpenTelemetryInvocationInternal"; @@ -17,7 +17,7 @@ internal class OpenTelemetryServices : IOpenTelemetryServices private readonly ILogger _logger; public readonly PowerShell _pwsh; - public OpenTelemetryServices(ILogger logger, PowerShell pwsh) + public PowerShellServicesForOpenTelemetry(ILogger logger, PowerShell pwsh) { _logger = logger; _pwsh = pwsh; diff --git a/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs b/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs index eb75b563..3a9b2297 100644 --- a/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs +++ b/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs @@ -18,11 +18,11 @@ public class OpenTelemetryControllerTests private const string FakeTraceParent = "Fake TraceParent"; private readonly Mock _mockLogger = new Mock(MockBehavior.Strict); - private readonly Mock _mockOtelServices; + private readonly Mock _mockOtelServices; public OpenTelemetryControllerTests() { - _mockOtelServices = new Mock(MockBehavior.Strict); + _mockOtelServices = new Mock(MockBehavior.Strict); } [Theory] @@ -52,7 +52,7 @@ internal void AddStartOpenTelemetryInvocationCommand_AddsCommands() try { PowerShell _pwsh = PowerShell.Create(); - var _realOTelServices = new OpenTelemetryServices(_mockLogger.Object, _pwsh); + var _realOTelServices = new PowerShellServicesForOpenTelemetry(_mockLogger.Object, _pwsh); OpenTelemetryController controller = CreateMockOpenTelemetryController(); @@ -96,7 +96,7 @@ internal void StopOpenTelemetryInvocationCommand_AddsCommands() try { PowerShell _pwsh = PowerShell.Create(); - var _realOTelServices = new OpenTelemetryServices(_mockLogger.Object, _pwsh); + var _realOTelServices = new PowerShellServicesForOpenTelemetry(_mockLogger.Object, _pwsh); OpenTelemetryController controller = CreateMockOpenTelemetryController(); @@ -136,7 +136,7 @@ internal void StartFunctionsLoggingListener_CorrectCommands() try { PowerShell _pwsh = PowerShell.Create(); - var _realOTelServices = new OpenTelemetryServices(_mockLogger.Object, _pwsh); + var _realOTelServices = new PowerShellServicesForOpenTelemetry(_mockLogger.Object, _pwsh); OpenTelemetryController controller = CreateMockOpenTelemetryController(); From 44a729604022181b5985324da39c4dd7897a5254 Mon Sep 17 00:00:00 2001 From: Andy Staples Date: Fri, 12 Apr 2024 12:57:57 -0600 Subject: [PATCH 8/8] Naming nit --- src/PowerShell/PowerShellModuleDetector.cs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/PowerShell/PowerShellModuleDetector.cs b/src/PowerShell/PowerShellModuleDetector.cs index dbee8c1c..dfa5caf7 100644 --- a/src/PowerShell/PowerShellModuleDetector.cs +++ b/src/PowerShell/PowerShellModuleDetector.cs @@ -9,10 +9,10 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell internal class PowerShellModuleDetector { - public static bool IsPowerShellModuleLoaded(System.Management.Automation.PowerShell _pwsh, ILogger _logger, string moduleName) + public static bool IsPowerShellModuleLoaded(System.Management.Automation.PowerShell pwsh, ILogger logger, string moduleName) { // Search for the module in the current session - var matchingModules = _pwsh.AddCommand(Utils.GetModuleCmdletInfo) + var matchingModules = pwsh.AddCommand(Utils.GetModuleCmdletInfo) .AddParameter("FullyQualifiedName", moduleName) .InvokeAndClearCommands(); @@ -40,14 +40,14 @@ public static bool IsPowerShellModuleLoaded(System.Management.Automation.PowerSh { // If there's more than 1 result, there may be runtime conflicts // warn user of potential conflicts - _logger.Log(isUserOnlyLog: false, LogLevel.Warning, String.Format( + logger.Log(isUserOnlyLog: false, LogLevel.Warning, String.Format( PowerShellWorkerStrings.MultipleExternalSDKsInSession, numCandidates, moduleName, externalSDKModuleInfo)); } else { // a single module is in session. Report its metadata - _logger.Log(isUserOnlyLog: false, LogLevel.Trace, externalSDKModuleInfo); + logger.Log(isUserOnlyLog: false, LogLevel.Trace, externalSDKModuleInfo); } } return isModuleInCurrentSession;