From f0c7eec1e3b3fffeadaa27033aff08727319fd69 Mon Sep 17 00:00:00 2001 From: andystaples <77818326+andystaples@users.noreply.github.com> Date: Fri, 12 Apr 2024 12:00:00 -0700 Subject: [PATCH] OpenTelemetry support in worker (#1049) * Detect if OpenTelemetry module is present and environment variable is set * Pre-instrument invocations with a span using Invocation ID + parent span ID * Forward all user logs to the module to be sent to OTel endpoint --- protobuf/src/proto/FunctionRpc.proto | 150 +++++++++++++--- src/DurableSDK/PowerShellServices.cs | 33 +--- src/Logging/LoggingEventHandler.cs | 20 +++ src/Logging/RpcLogger.cs | 3 + .../IPowerShellServicesForOpenTelemetry.cs | 16 ++ src/OpenTelemetry/OpenTelemetryController.cs | 104 +++++++++++ .../OpenTelemetryInvocationContext.cs | 27 +++ .../PowerShellServicesForOpenTelemetry.cs | 76 ++++++++ src/PowerShell/PowerShellManager.cs | 35 +++- src/PowerShell/PowerShellModuleDetector.cs | 56 ++++++ src/RequestProcessor.cs | 20 ++- src/Utility/Utils.cs | 3 +- src/resources/PowerShellWorkerStrings.resx | 9 + test/Unit/Logging/ConsoleLogger.cs | 1 + .../OpenTelemetryControllerTests.cs | 170 ++++++++++++++++++ .../Unit/PowerShell/PowerShellManagerTests.cs | 5 +- 16 files changed, 655 insertions(+), 73 deletions(-) create mode 100644 src/Logging/LoggingEventHandler.cs create mode 100644 src/OpenTelemetry/IPowerShellServicesForOpenTelemetry.cs create mode 100644 src/OpenTelemetry/OpenTelemetryController.cs create mode 100644 src/OpenTelemetry/OpenTelemetryInvocationContext.cs create mode 100644 src/OpenTelemetry/PowerShellServicesForOpenTelemetry.cs create mode 100644 src/PowerShell/PowerShellModuleDetector.cs create mode 100644 test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs diff --git a/protobuf/src/proto/FunctionRpc.proto b/protobuf/src/proto/FunctionRpc.proto index 1280982..110df5d 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 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 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/DurableSDK/PowerShellServices.cs b/src/DurableSDK/PowerShellServices.cs index 98e4878..6f9a0c0 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 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.Durable 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 new file mode 100644 index 0000000..3b81005 --- /dev/null +++ b/src/Logging/LoggingEventHandler.cs @@ -0,0 +1,20 @@ +using System; +using System.Collections.Generic; + +namespace Microsoft.Azure.Functions.PowerShellWorker.Utility +{ + internal class LoggingEventHandler + { + private Action _eventHandler = (a, b, c) => { }; + + public void Subscribe(Action handler) + { + _eventHandler = handler; + } + + public void LogToHandlers(string level, string message, Exception exception = null) + { + _eventHandler(level, message, exception); + } + } +} diff --git a/src/Logging/RpcLogger.cs b/src/Logging/RpcLogger.cs index 160b7f9..23b9c0c 100644 --- a/src/Logging/RpcLogger.cs +++ b/src/Logging/RpcLogger.cs @@ -18,6 +18,7 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.Utility private readonly MessagingStream _msgStream; private string _invocationId; private string _requestId; + public LoggingEventHandler outputLogHandler = new LoggingEventHandler(); internal RpcLogger(MessagingStream msgStream) { @@ -55,6 +56,8 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.Utility }; _msgStream.Write(logMessage); + + outputLogHandler.LogToHandlers(logLevel.ToString(), message, exception); } else { diff --git a/src/OpenTelemetry/IPowerShellServicesForOpenTelemetry.cs b/src/OpenTelemetry/IPowerShellServicesForOpenTelemetry.cs new file mode 100644 index 0000000..aeb6c17 --- /dev/null +++ b/src/OpenTelemetry/IPowerShellServicesForOpenTelemetry.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 IPowerShellServicesForOpenTelemetry + { + bool? IsModuleLoaded(); + void AddStartOpenTelemetryInvocationCommand(OpenTelemetryInvocationContext otelContext); + void StopOpenTelemetryInvocation(OpenTelemetryInvocationContext otelContext, bool invokeCommands); + void StartFunctionsLoggingListener(bool invokeCommands); + } +} diff --git a/src/OpenTelemetry/OpenTelemetryController.cs b/src/OpenTelemetry/OpenTelemetryController.cs new file mode 100644 index 0000000..5533d46 --- /dev/null +++ b/src/OpenTelemetry/OpenTelemetryController.cs @@ -0,0 +1,104 @@ +using System; +using Microsoft.Azure.Functions.PowerShellWorker.Utility; + +namespace Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetry +{ + using PowerShell = System.Management.Automation.PowerShell; + + internal class OpenTelemetryController + { + private IPowerShellServicesForOpenTelemetry _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 PowerShellServicesForOpenTelemetry(logger, pwsh)) + { } + + public OpenTelemetryController(IPowerShellServicesForOpenTelemetry 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, bool invokeCommands = true) + { + if (!IsOpenTelemetryCapable()) + { + return; + } + + _services.StopOpenTelemetryInvocation(otelContext, invokeCommands); + } + + internal void StartFunctionsLoggingListener(bool invokeCommands = true) + { + if (!IsOpenTelemetryCapable()) + { + return; + } + + _services.StartFunctionsLoggingListener(invokeCommands); + } + } +} diff --git a/src/OpenTelemetry/OpenTelemetryInvocationContext.cs b/src/OpenTelemetry/OpenTelemetryInvocationContext.cs new file mode 100644 index 0000000..54178ed --- /dev/null +++ b/src/OpenTelemetry/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.OpenTelemetry +{ + 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/OpenTelemetry/PowerShellServicesForOpenTelemetry.cs b/src/OpenTelemetry/PowerShellServicesForOpenTelemetry.cs new file mode 100644 index 0000000..6966822 --- /dev/null +++ b/src/OpenTelemetry/PowerShellServicesForOpenTelemetry.cs @@ -0,0 +1,76 @@ +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 PowerShellServicesForOpenTelemetry : IPowerShellServicesForOpenTelemetry + { + private const string StartOpenTelemetryInvocationCmdlet = "Start-OpenTelemetryInvocationInternal"; + private const string StopOpenTelemetryInvocationCmdlet = "Stop-OpenTelemetryInvocationInternal"; + private const string GetFunctionsLogHandlerCmdlet = "Get-FunctionsLogHandlerInternal"; + + private readonly ILogger _logger; + public readonly PowerShell _pwsh; + + public PowerShellServicesForOpenTelemetry(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, bool invokeCommands) + { + _pwsh.AddCommand(StopOpenTelemetryInvocationCmdlet) + .AddParameter("InvocationId", otelContext.InvocationId); + + if (invokeCommands) + { + _pwsh.InvokeAndClearCommands(); + } + } + + public void StartFunctionsLoggingListener(bool invokeCommands) + { + _pwsh.AddCommand(GetFunctionsLogHandlerCmdlet); + + if (!invokeCommands) + { + return; + } + + var eventHandlers = + _pwsh.InvokeAndClearCommands>(); + + if (eventHandlers.Any()) + { + if (_logger is RpcLogger rpcLogger) + { + rpcLogger.outputLogHandler.Subscribe(eventHandlers.First()); + } + } + } + } +} diff --git a/src/PowerShell/PowerShellManager.cs b/src/PowerShell/PowerShellManager.cs index 5a0a4db..5bd506b 100644 --- a/src/PowerShell/PowerShellManager.cs +++ b/src/PowerShell/PowerShellManager.cs @@ -15,7 +15,7 @@ using LogLevel = Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types.Level namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell { - using Microsoft.Azure.Functions.PowerShellWorker.DurableWorker; + using Microsoft.Azure.Functions.PowerShellWorker.OpenTelemetry; using System.Management.Automation; using System.Text; @@ -37,6 +37,8 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell private readonly ErrorRecordFormatter _errorRecordFormatter = new ErrorRecordFormatter(); + private OpenTelemetryController _openTelemetryController; + /// /// Gets the Runspace InstanceId. /// @@ -106,6 +108,9 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell // Run the profile.ps1 InvokeProfile(FunctionLoader.FunctionAppProfilePath); + _openTelemetryController = new OpenTelemetryController(Logger, _pwsh); + _openTelemetryController.StartFunctionsLoggingListener(); + _runspaceInited = true; } } @@ -202,7 +207,8 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell 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 +218,12 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell 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 +236,7 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell try { - if(functionInfo.DurableFunctionInfo.IsOrchestrationFunction) + if (functionInfo.DurableFunctionInfo.IsOrchestrationFunction) { return durableFunctionsUtils.InvokeOrchestrationFunction(); } @@ -255,6 +267,7 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell } finally { + _openTelemetryController.StopOpenTelemetryInvocation(otelContext); durableFunctionsUtils.AfterFunctionInvocation(); outputBindings.Clear(); ResetRunspace(); @@ -314,6 +327,17 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell 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 +346,6 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell } 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/PowerShell/PowerShellModuleDetector.cs b/src/PowerShell/PowerShellModuleDetector.cs new file mode 100644 index 0000000..dfa5caf --- /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 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 module 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 module 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 ad192aa..ee3378a 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.OpenTelemetry; internal class RequestProcessor { @@ -113,6 +114,11 @@ namespace Microsoft.Azure.Functions.PowerShellWorker 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 @@ namespace Microsoft.Azure.Functions.PowerShellWorker 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) @@ -384,6 +393,15 @@ namespace Microsoft.Azure.Functions.PowerShellWorker 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; } diff --git a/src/Utility/Utils.cs b/src/Utility/Utils.cs index e8d3a3d..1c3ce45 100644 --- a/src/Utility/Utils.cs +++ b/src/Utility/Utils.cs @@ -23,12 +23,13 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.Utility 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 0685d7b..53f0c80 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 @@ -379,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/Logging/ConsoleLogger.cs b/test/Unit/Logging/ConsoleLogger.cs index e41dfea..d49d772 100644 --- a/test/Unit/Logging/ConsoleLogger.cs +++ b/test/Unit/Logging/ConsoleLogger.cs @@ -7,6 +7,7 @@ using System; 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/OpenTelemetry/OpenTelemetryControllerTests.cs b/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs new file mode 100644 index 0000000..3a9b229 --- /dev/null +++ b/test/Unit/OpenTelemetry/OpenTelemetryControllerTests.cs @@ -0,0 +1,170 @@ +using Moq; +using System; +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 + { + // 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; + + public OpenTelemetryControllerTests() + { + _mockOtelServices = new Mock(MockBehavior.Strict); + } + + [Theory] + [InlineData("true", true)] + [InlineData("false", false)] + [InlineData("True", true)] + [InlineData("False", false)] + [InlineData(null, false)] + internal void OpenTelemetryEnvironmentVariableCheckWorks(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(); + } + } + + [Fact] + internal void AddStartOpenTelemetryInvocationCommand_AddsCommands() + { + try + { + PowerShell _pwsh = PowerShell.Create(); + var _realOTelServices = new PowerShellServicesForOpenTelemetry(_mockLogger.Object, _pwsh); + + OpenTelemetryController controller = CreateMockOpenTelemetryController(); + + OpenTelemetryInvocationContext context = new OpenTelemetryInvocationContext( + FakeInvocationID, + FakeTraceParent, + string.Empty + ); + + 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 PowerShellServicesForOpenTelemetry(_mockLogger.Object, _pwsh); + + OpenTelemetryController controller = CreateMockOpenTelemetryController(); + + OpenTelemetryInvocationContext context = new OpenTelemetryInvocationContext( + FakeInvocationID, + FakeTraceParent, + string.Empty + ); + + Environment.SetEnvironmentVariable("OTEL_FUNCTIONS_WORKER_ENABLED", "true"); + _mockOtelServices.Setup(_ => _.IsModuleLoaded()).Returns(true); + _mockOtelServices.Setup(_ => _.StopOpenTelemetryInvocation(context, false)) + .Callback(() => _realOTelServices.StopOpenTelemetryInvocation(context, false)); + + controller.StopOpenTelemetryInvocation(context, false); + + 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, false), 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 PowerShellServicesForOpenTelemetry(_mockLogger.Object, _pwsh); + + OpenTelemetryController controller = CreateMockOpenTelemetryController(); + + Environment.SetEnvironmentVariable("OTEL_FUNCTIONS_WORKER_ENABLED", "true"); + _mockOtelServices.Setup(_ => _.IsModuleLoaded()).Returns(true); + _mockOtelServices.Setup(_ => _.StartFunctionsLoggingListener(false)) + .Callback(() => _realOTelServices.StartFunctionsLoggingListener(false)); + + controller.StartFunctionsLoggingListener(false); + + 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(false), Times.Once); + } + finally + { + Environment.SetEnvironmentVariable("OTEL_FUNCTIONS_WORKER_ENABLED", null); + OpenTelemetryController.ResetOpenTelemetryModuleStatus(); + } + } + + private OpenTelemetryController CreateMockOpenTelemetryController() + { + return new OpenTelemetryController(_mockOtelServices.Object); + } + } +} diff --git a/test/Unit/PowerShell/PowerShellManagerTests.cs b/test/Unit/PowerShell/PowerShellManagerTests.cs index 3658861..5bceda4 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 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.Test { 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 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.Test 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