diff --git a/src/WebJobs.Extensions.DurableTask/WebJobs.Extensions.DurableTask.csproj b/src/WebJobs.Extensions.DurableTask/WebJobs.Extensions.DurableTask.csproj index 15e306be7..7a9dcda39 100644 --- a/src/WebJobs.Extensions.DurableTask/WebJobs.Extensions.DurableTask.csproj +++ b/src/WebJobs.Extensions.DurableTask/WebJobs.Extensions.DurableTask.csproj @@ -6,7 +6,8 @@ Microsoft.Azure.WebJobs.Extensions.DurableTask 3 0 - 2 + 3 + private $(MajorVersion).$(MinorVersion).$(PatchVersion) $(MajorVersion).$(MinorVersion).$(PatchVersion) $(MajorVersion).0.0.0 diff --git a/src/Worker.Extensions.DurableTask/EtwEventSource.cs b/src/Worker.Extensions.DurableTask/EtwEventSource.cs new file mode 100644 index 000000000..44a455127 --- /dev/null +++ b/src/Worker.Extensions.DurableTask/EtwEventSource.cs @@ -0,0 +1,349 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See LICENSE in the project root for license information. +#nullable enable +using System.Diagnostics.Tracing; + +namespace Microsoft.Azure.Functions.Worker.Extensions.DurableTask +{ + /// + /// ETW Event Provider for the WebJobs.Extensions.DurableTask extension. + /// + [EventSource(Name = "WebJobs-Extensions-DurableTask")] + internal sealed class EtwEventSource : EventSource + { + public static readonly EtwEventSource Instance = new EtwEventSource(); + + // Private .ctor - callers should use the shared static instance. + private EtwEventSource() + { } + +#pragma warning disable SA1313 // Parameter names should begin with lower-case letter + + [Event(201, Level = EventLevel.Informational, Version = 2)] + public void FunctionScheduled( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string Reason, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(201, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); + } + + [Event(202, Level = EventLevel.Informational, Version = 5)] + public void FunctionStarting( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + int TaskEventId, + string InstanceId, + string? Input, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(202, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, Input ?? "(null)", FunctionType, ExtensionVersion, IsReplay); + } + + [Event(203, Level = EventLevel.Informational, Version = 4)] + public void FunctionAwaited( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(203, TaskHub, AppName, SlotName, FunctionName, InstanceId, FunctionType, ExtensionVersion, IsReplay); + } + + [Event(204, Level = EventLevel.Informational, Version = 2)] + public void FunctionListening( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string Reason, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(204, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); + } + + [Event(205, Level = EventLevel.Informational, Version = 2)] + public void ExternalEventRaised( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string EventName, + string? Input, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(205, TaskHub, AppName, SlotName, FunctionName, InstanceId, EventName, Input ?? "(null)", FunctionType, ExtensionVersion, IsReplay); + } + + [Event(206, Level = EventLevel.Informational, Version = 5)] + public void FunctionCompleted( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + int TaskEventId, + string InstanceId, + string? Output, + bool ContinuedAsNew, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(206, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, Output ?? "(null)", ContinuedAsNew, FunctionType, ExtensionVersion, IsReplay); + } + + [Event(207, Level = EventLevel.Warning, Version = 2)] + public void FunctionTerminated( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string Reason, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(207, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); + } + + [Event(208, Level = EventLevel.Error, Version = 4)] + public void FunctionFailed( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + int TaskEventId, + string InstanceId, + string Reason, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(208, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); + } + + [Event(209, Level = EventLevel.Informational, Version = 2)] + public void TimerExpired( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string Reason, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(209, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); + } + + + [Event(213, Level = EventLevel.Informational)] + public void ExtensionInformationalEvent( + string TaskHub, + string AppName, + string SlotName, + string? FunctionName, + string? InstanceId, + string Details, + string ExtensionVersion) + { + this.WriteEvent(213, TaskHub, AppName, SlotName, FunctionName ?? string.Empty, InstanceId ?? string.Empty, Details, ExtensionVersion); + } + + [Event(214, Level = EventLevel.Warning)] + public void ExtensionWarningEvent( + string TaskHub, + string AppName, + string SlotName, + string? FunctionName, + string? InstanceId, + string Details, + string ExtensionVersion) + { + this.WriteEvent(214, TaskHub, AppName, SlotName, FunctionName ?? string.Empty, InstanceId ?? string.Empty, Details, ExtensionVersion); + } + + [Event(215, Level = EventLevel.Informational, Version = 2)] + public void ExternalEventSaved( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string EventName, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(215, TaskHub, AppName, SlotName, FunctionName, InstanceId, EventName, FunctionType, ExtensionVersion, IsReplay); + } + + [Event(216, Level = EventLevel.Informational)] + public void FunctionRewound( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string? Reason, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(216, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason ?? string.Empty, FunctionType, ExtensionVersion, IsReplay); + } + + [Event(217, Level = EventLevel.Informational)] + public void EntityOperationQueued( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string OperationId, + string OperationName, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(217, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, OperationName, FunctionType, ExtensionVersion, IsReplay); + } + + [Event(218, Level = EventLevel.Informational)] + public void EntityResponseReceived( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string OperationId, + string? Result, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(218, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, Result ?? "(null)", FunctionType, ExtensionVersion, IsReplay); + } + + [Event(219, Level = EventLevel.Informational, Version = 2)] + public void EntityLockAcquired( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string RequestingInstanceId, + string? RequestingExecutionId, + string RequestId, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(219, TaskHub, AppName, SlotName, FunctionName, InstanceId, RequestingInstanceId, RequestingExecutionId ?? "", RequestId, FunctionType, ExtensionVersion, IsReplay); + } + + [Event(220, Level = EventLevel.Informational)] + public void EntityLockReleased( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string RequestingInstance, + string RequestId, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(220, TaskHub, AppName, SlotName, FunctionName, InstanceId, RequestingInstance, RequestId, FunctionType, ExtensionVersion, IsReplay); + } + + [Event(221, Level = EventLevel.Informational)] + public void OperationCompleted( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string OperationId, + string OperationName, + string? Input, + string? Output, + double Duration, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(221, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, OperationName, Input ?? "(null)", Output ?? "(null)", Duration, FunctionType, ExtensionVersion, IsReplay); + } + + [Event(222, Level = EventLevel.Error)] + public void OperationFailed( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string OperationId, + string OperationName, + string? Input, + string Exception, + double Duration, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(222, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, OperationName, Input ?? "(null)", Exception, Duration, FunctionType, ExtensionVersion, IsReplay); + } + + [Event(223, Level = EventLevel.Informational)] + public void ExtensionConfiguration( + string TaskHub, + string AppName, + string SlotName, + string Details, + string ExtensionVersion) + { + this.WriteEvent(223, TaskHub, AppName, SlotName, Details, ExtensionVersion); + } + + [Event(224, Level = EventLevel.Warning)] + public void FunctionAborted( + string TaskHub, + string AppName, + string SlotName, + string FunctionName, + string InstanceId, + string Reason, + string FunctionType, + string ExtensionVersion, + bool IsReplay) + { + this.WriteEvent(224, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); + } + +#pragma warning restore SA1313 // Parameter names should begin with lower-case letter + } +} diff --git a/src/Worker.Extensions.DurableTask/FunctionsDurableClientProvider.cs b/src/Worker.Extensions.DurableTask/FunctionsDurableClientProvider.cs index 2169306a7..c4fde4419 100644 --- a/src/Worker.Extensions.DurableTask/FunctionsDurableClientProvider.cs +++ b/src/Worker.Extensions.DurableTask/FunctionsDurableClientProvider.cs @@ -108,6 +108,17 @@ public DurableTaskClient GetClient(Uri endpoint, string? taskHub, string? connec if (this.clients!.TryGetValue(key, out ClientHolder? holder)) { this.logger.LogTrace("DurableTaskClient resolved from cache"); + + EtwEventSource.Instance.ExtensionInformationalEvent( + taskHub, + AppName: string.Empty, + SlotName: string.Empty, + FunctionName: string.Empty, + InstanceId: string.Empty, + $"Connecion Name: '{connectionName}', Endpoint: '{endpoint}', DurableTaskClient resolved from cache with read", + "1.2.3-grpclog" + ); + return holder.Client; } } @@ -123,6 +134,16 @@ public DurableTaskClient GetClient(Uri endpoint, string? taskHub, string? connec if (this.clients!.TryGetValue(key, out ClientHolder? holder)) { this.logger.LogTrace("DurableTaskClient resolved from cache"); + + EtwEventSource.Instance.ExtensionInformationalEvent( + taskHub, + AppName: string.Empty, + SlotName: string.Empty, + FunctionName: string.Empty, + InstanceId: string.Empty, + $"Connecion Name: '{connectionName}', Endpoint: '{endpoint}, DurableTaskClient resolved from cache with write", + "1.2.3-grpclog" + ); return holder.Client; } @@ -131,6 +152,17 @@ public DurableTaskClient GetClient(Uri endpoint, string? taskHub, string? connec endpoint, taskHub, connectionName); + + EtwEventSource.Instance.ExtensionInformationalEvent( + taskHub, + AppName: string.Empty, + SlotName: string.Empty, + FunctionName: string.Empty, + InstanceId: string.Empty, + $"DurableTaskClient cache miss, creating new grpc channel : Connecion Name: '{connectionName}', Endpoint: '{endpoint}. Curernt Grpc channel count: '{this.clients.Count}'", + "1.2.3-grpclog" + ); + GrpcChannel channel = CreateChannel(key); GrpcDurableTaskClientOptions options = new() { @@ -145,6 +177,19 @@ public DurableTaskClient GetClient(Uri endpoint, string? taskHub, string? connec this.clients[key] = holder; return client; } + catch (Exception ex) + { + EtwEventSource.Instance.ExtensionInformationalEvent( + taskHub, + AppName: string.Empty, + SlotName: string.Empty, + FunctionName: string.Empty, + InstanceId: string.Empty, + $"Error occurred while constructing grpc channel. ConnectionName: '{connectionName}', Endpoint: '{endpoint}'. Exception Type: {ex.GetType()}, Exception Message: '{ex.Message}' ", + "1.2.3-grpclog" + ); + throw; + } finally { this.sync.ExitWriteLock(); diff --git a/src/Worker.Extensions.DurableTask/Worker.Extensions.DurableTask.csproj b/src/Worker.Extensions.DurableTask/Worker.Extensions.DurableTask.csproj index 135f4b352..c92f45b34 100644 --- a/src/Worker.Extensions.DurableTask/Worker.Extensions.DurableTask.csproj +++ b/src/Worker.Extensions.DurableTask/Worker.Extensions.DurableTask.csproj @@ -29,8 +29,8 @@ ..\..\sign.snk - 1.2.2 - + 1.2.3 + grpclog $(VersionPrefix).0 $(VersionPrefix).$(FileVersionRevision)