diff --git a/src/Orleans.Core.Abstractions/Logging/ErrorCodes.cs b/src/Orleans.Core.Abstractions/Logging/ErrorCodes.cs index 9d6d6eef697..17af2046ccc 100644 --- a/src/Orleans.Core.Abstractions/Logging/ErrorCodes.cs +++ b/src/Orleans.Core.Abstractions/Logging/ErrorCodes.cs @@ -441,6 +441,8 @@ public enum ErrorCode Catalog_DeactivateAllActivations = CatalogBase + 45, Catalog_ActivationCollector_BadState_3 = CatalogBase + 46, Catalog_UnregisterAsync = CatalogBase + 47, + Catalog_CancelledActivate = CatalogBase + 48, + Catalog_DisposedObjectAccess = CatalogBase + 49, MembershipBase = Runtime + 600, MembershipCantWriteLivenessDisabled = Runtime_Error_100225, // Backward compatability diff --git a/src/Orleans.Runtime/Catalog/ActivationData.cs b/src/Orleans.Runtime/Catalog/ActivationData.cs index c5b999bad5a..15dcfca56b7 100644 --- a/src/Orleans.Runtime/Catalog/ActivationData.cs +++ b/src/Orleans.Runtime/Catalog/ActivationData.cs @@ -805,7 +805,7 @@ public async ValueTask DisposeAsync() await DisposeAsync(_serviceScope); } - private static async ValueTask DisposeAsync(object obj) + private static async ValueTask DisposeAsync(object? obj) { try { @@ -1580,6 +1580,32 @@ private async Task ActivateAsync(Dictionary? requestContextData, { await grainBase.OnActivateAsync(cancellationToken).WaitAsync(cancellationToken); } + // this captures the case where user code in OnActivateAsync doesn't use the passed cancellation token + // and makes a call that tries to resolve the scoped IServiceProvider or other type that has been disposed because of cancellation. + catch (ObjectDisposedException ode) when (cancellationToken.IsCancellationRequested) + { + LogActivationDisposedObjectAccessed(_shared.Logger, ode.ObjectName, this); + CatalogInstruments.ActivationFailedToActivate.Add(1); + Deactivate(new(DeactivationReason.ReasonCode, ode, DeactivationReason.Description), CancellationToken.None); + // TODO: after the PR for activation data activity is in, re-enable this + // SetActivityError(_activationActivity, ode, ActivityErrorEvents.ActivationCancelled); + LogActivationCancelled(_shared.Logger, this, cancellationToken.IsCancellationRequested, DeactivationReason.ReasonCode.ToString(), ForwardingAddress); + // TODO: after the PR for activation data activity is in, re-enable this + // _activationActivity?.Stop(); + return; + } + // catch OperationCanceledException only if it wasn't for a timeout. + catch (OperationCanceledException oce) when (cancellationToken.IsCancellationRequested && DeactivationReason.ReasonCode != DeactivationReasonCode.ActivationUnresponsive) + { + CatalogInstruments.ActivationFailedToActivate.Add(1); + Deactivate(new(DeactivationReason.ReasonCode, oce, DeactivationReason.Description), CancellationToken.None); + // TODO: after the PR for activation data activity is in, re-enable this + // SetActivityError(_activationActivity, oce, ActivityErrorEvents.ActivationCancelled); + LogActivationCancelled(_shared.Logger, this, cancellationToken.IsCancellationRequested, DeactivationReason.ReasonCode.ToString(), ForwardingAddress); + // TODO: after the PR for activation data activity is in, re-enable this + // _activationActivity?.Stop(); + return; + } catch (Exception exception) { LogErrorInGrainMethod(_shared.Logger, exception, nameof(IGrainBase.OnActivateAsync), this); @@ -2361,11 +2387,24 @@ private readonly struct ActivationDataLogValue(ActivationData activation, bool i Message = "Error activating grain {Grain}")] private static partial void LogErrorActivatingGrain(ILogger logger, Exception exception, ActivationData grain); + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_DisposedObjectAccess, + Level = LogLevel.Warning, + Message = "Disposed object {ObjectName} accessed in OnActivateAsync for grain {Grain}. Ensure the cancellationToken is passed to all async methods or they have .WaitAsync(cancellationToken) called on them.")] + private static partial void LogActivationDisposedObjectAccessed(ILogger logger, string objectName, ActivationData grain); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_CancelledActivate, + Level = LogLevel.Information, + Message = "Activation was cancelled for {Grain}. CancellationRequested={CancellationRequested}, DeactivationReason={DeactivationReason}, ForwardingAddress={ForwardingAddress}" + )] + private static partial void LogActivationCancelled(ILogger logger, ActivationData grain, bool cancellationRequested, string? deactivationReason, SiloAddress? forwardingAddress); + [LoggerMessage( Level = LogLevel.Error, Message = "Activation of grain {Grain} failed")] private static partial void LogActivationFailed(ILogger logger, Exception exception, ActivationData grain); - + [LoggerMessage( Level = LogLevel.Trace, Message = "Completing deactivation of '{Activation}'")] diff --git a/test/Grains/TestGrainInterfaces/IActivationCancellationTestGrain.cs b/test/Grains/TestGrainInterfaces/IActivationCancellationTestGrain.cs new file mode 100644 index 00000000000..b3df7fa2621 --- /dev/null +++ b/test/Grains/TestGrainInterfaces/IActivationCancellationTestGrain.cs @@ -0,0 +1,62 @@ +#nullable enable + +namespace UnitTests.GrainInterfaces; + +/// +/// Interface for testing activation cancellation scenarios. +/// These grains are used to verify the proper handling of cancellation during grain activation. +/// +public interface IActivationCancellationTestGrain : IGrainWithGuidKey +{ + /// + /// A simple method to test that the grain is activated and working. + /// + Task GetActivationId(); + + /// + /// Checks if the activation was successful. + /// + Task IsActivated(); +} + +/// +/// Grain that throws OperationCanceledException during OnActivateAsync when the cancellation token is triggered. +/// This simulates code that properly observes the cancellation token. +/// +public interface IActivationCancellation_ThrowsOperationCancelledGrain : IActivationCancellationTestGrain; + +/// +/// Grain that throws ObjectDisposedException during OnActivateAsync when trying to access disposed services. +/// This simulates code that doesn't observe the cancellation token but tries to access services that have been disposed. +/// +public interface IActivationCancellation_ThrowsObjectDisposedGrain : IActivationCancellationTestGrain; + +/// +/// Grain that throws a generic exception during OnActivateAsync (not related to cancellation). +/// This is used to verify that non-cancellation exceptions are still handled properly. +/// +public interface IActivationCancellation_ThrowsGenericExceptionGrain : IActivationCancellationTestGrain; + +/// +/// Grain that activates successfully without any issues. +/// This is a baseline to verify normal activation continues to work. +/// +public interface IActivationCancellation_SuccessfulActivationGrain : IActivationCancellationTestGrain; + +/// +/// Grain that throws TaskCanceledException during OnActivateAsync. +/// TaskCanceledException inherits from OperationCanceledException and should be handled the same way. +/// +public interface IActivationCancellation_ThrowsTaskCancelledGrain : IActivationCancellationTestGrain; + +/// +/// Grain that throws ObjectDisposedException unconditionally (not due to cancellation). +/// This tests that ObjectDisposedException thrown for other reasons is NOT treated as cancellation. +/// +public interface IActivationCancellation_ThrowsObjectDisposedUnconditionallyGrain : IActivationCancellationTestGrain; + +/// +/// Grain that throws OperationCanceledException unconditionally (not due to cancellation). +/// This tests that OperationCanceledException thrown for other reasons is NOT treated as cancellation. +/// +public interface IActivationCancellation_ThrowsOperationCancelledUnconditionallyGrain : IActivationCancellationTestGrain; diff --git a/test/Grains/TestGrains/ActivationCancellationTestGrains.cs b/test/Grains/TestGrains/ActivationCancellationTestGrains.cs new file mode 100644 index 00000000000..7f9e42397bf --- /dev/null +++ b/test/Grains/TestGrains/ActivationCancellationTestGrains.cs @@ -0,0 +1,267 @@ +#nullable enable +using Microsoft.Extensions.Logging; +using Orleans.Runtime; +using UnitTests.GrainInterfaces; + +namespace UnitTests.Grains; + +/// +/// Base class for activation cancellation test grains. +/// +public abstract class ActivationCancellationTestGrainBase : Grain +{ + protected readonly ILogger Logger; + protected readonly string ActivationId = Guid.NewGuid().ToString(); + protected bool IsActivatedSuccessfully; + private readonly IGrainRuntime _grainRuntime; + + protected ActivationCancellationTestGrainBase(ILogger logger, IGrainRuntime grainRuntime) + { + Logger = logger; + _grainRuntime = grainRuntime; + } + + /// + /// Gets the TimeProvider from the grain runtime. + /// + protected TimeProvider TimeProvider => _grainRuntime.TimeProvider; + + public Task GetActivationId() => Task.FromResult(ActivationId); + + public Task IsActivated() => Task.FromResult(IsActivatedSuccessfully); +} + +/// +/// Grain that throws OperationCanceledException during OnActivateAsync when the cancellation token is triggered. +/// This simulates code that properly observes the cancellation token by passing it to async methods. +/// +public class ActivationCancellation_ThrowsOperationCancelledGrain + : ActivationCancellationTestGrainBase, IActivationCancellation_ThrowsOperationCancelledGrain +{ + public ActivationCancellation_ThrowsOperationCancelledGrain(ILogger logger, IGrainRuntime grainRuntime) + : base(logger, grainRuntime) + { + } + + public override async Task OnActivateAsync(CancellationToken cancellationToken) + { + Logger.LogDebug("OnActivateAsync starting for {GrainType}", GetType().Name); + + // Check if we should simulate a delay that would cause cancellation + if (RequestContext.Get("delay_activation_ms") is int delayMs && delayMs > 0) + { + Logger.LogDebug("Delaying activation by {DelayMs}ms", delayMs); + await Task.Delay(TimeSpan.FromMilliseconds(delayMs), cancellationToken); + } + + IsActivatedSuccessfully = true; + Logger.LogDebug("OnActivateAsync completed successfully for {GrainType}", GetType().Name); + await base.OnActivateAsync(cancellationToken); + } +} + +/// +/// Grain that throws ObjectDisposedException during OnActivateAsync. +/// This simulates code that doesn't observe the cancellation token but tries to access services +/// that have been disposed after cancellation. +/// +public class ActivationCancellation_ThrowsObjectDisposedGrain + : ActivationCancellationTestGrainBase, IActivationCancellation_ThrowsObjectDisposedGrain +{ + public ActivationCancellation_ThrowsObjectDisposedGrain( + ILogger logger, + IGrainRuntime grainRuntime) + : base(logger, grainRuntime) + { + } + + public override async Task OnActivateAsync(CancellationToken cancellationToken) + { + Logger.LogDebug("OnActivateAsync starting for {GrainType}", GetType().Name); + + if (RequestContext.Get("delay_activation_ms") is int delayMs && delayMs > 0) + { + Logger.LogDebug("Setting up cancellation callback to throw ObjectDisposedException after {DelayMs}ms max", delayMs); + + var tcs = new TaskCompletionSource(); + + // Register callback to throw ObjectDisposedException when cancellation is requested + await using var registration = cancellationToken.Register(() => + { + Logger.LogDebug("Cancellation was requested, throwing ObjectDisposedException"); + tcs.TrySetException(new ObjectDisposedException("IServiceProvider", "The service provider has been disposed because the activation was cancelled.")); + }); + + Thread.Sleep(TimeSpan.FromMilliseconds(delayMs)); + + await tcs.Task; + } + + IsActivatedSuccessfully = true; + Logger.LogDebug("OnActivateAsync completed successfully for {GrainType}", GetType().Name); + await base.OnActivateAsync(cancellationToken); + } +} + +/// +/// Grain that throws a generic exception during OnActivateAsync (not related to cancellation). +/// +public class ActivationCancellation_ThrowsGenericExceptionGrain + : ActivationCancellationTestGrainBase, IActivationCancellation_ThrowsGenericExceptionGrain +{ + public ActivationCancellation_ThrowsGenericExceptionGrain(ILogger logger, IGrainRuntime grainRuntime) + : base(logger, grainRuntime) + { + } + + public override Task OnActivateAsync(CancellationToken cancellationToken) + { + Logger.LogDebug("OnActivateAsync starting for {GrainType}", GetType().Name); + + // Check if we should throw an exception + if (RequestContext.Get("throw_exception") is bool shouldThrow && shouldThrow) + { + Logger.LogDebug("Throwing generic exception as requested"); + throw new InvalidOperationException("This is a test exception thrown during activation."); + } + + IsActivatedSuccessfully = true; + Logger.LogDebug("OnActivateAsync completed successfully for {GrainType}", GetType().Name); + return base.OnActivateAsync(cancellationToken); + } +} + +/// +/// Grain that activates successfully without any issues. +/// +public class ActivationCancellation_SuccessfulActivationGrain + : ActivationCancellationTestGrainBase, IActivationCancellation_SuccessfulActivationGrain +{ + public ActivationCancellation_SuccessfulActivationGrain(ILogger logger, IGrainRuntime grainRuntime) + : base(logger, grainRuntime) + { + } + + public override Task OnActivateAsync(CancellationToken cancellationToken) + { + Logger.LogDebug("OnActivateAsync starting for {GrainType}", GetType().Name); + IsActivatedSuccessfully = true; + Logger.LogDebug("OnActivateAsync completed successfully for {GrainType}", GetType().Name); + return base.OnActivateAsync(cancellationToken); + } +} + +/// +/// Grain that throws TaskCanceledException during OnActivateAsync. +/// TaskCanceledException inherits from OperationCanceledException and should be handled the same way. +/// +public class ActivationCancellation_ThrowsTaskCancelledGrain + : ActivationCancellationTestGrainBase, IActivationCancellation_ThrowsTaskCancelledGrain +{ + public ActivationCancellation_ThrowsTaskCancelledGrain(ILogger logger, IGrainRuntime grainRuntime) + : base(logger, grainRuntime) + { + } + + public override async Task OnActivateAsync(CancellationToken cancellationToken) + { + Logger.LogDebug("OnActivateAsync starting for {GrainType}", GetType().Name); + + if (RequestContext.Get("delay_activation_ms") is int delayMs && delayMs > 0) + { + Logger.LogDebug("Setting up cancellation callback to throw TaskCanceledException after {DelayMs}ms max", delayMs); + + var tcs = new TaskCompletionSource(); + + // Register callback to throw TaskCanceledException when cancellation is requested + /*await using var registration = cancellationToken.Register(() => + { + Logger.LogDebug("Cancellation was requested, throwing TaskCanceledException"); + tcs.TrySetException(new TaskCanceledException("Activation was cancelled", null, cancellationToken)); + });*/ + + // Start the delay task (without cancellation token) + var delayTask = Task.Delay(TimeSpan.FromMilliseconds(delayMs), TimeProvider, CancellationToken.None); + + // Wait for either the delay to complete or the cancellation to trigger the exception + var completedTask = await Task.WhenAny(delayTask, tcs.Task); + + // If the TCS task completed, it has an exception - await it to propagate + if (completedTask == tcs.Task) + { + await tcs.Task; + } + } + + IsActivatedSuccessfully = true; + Logger.LogDebug("OnActivateAsync completed successfully for {GrainType}", GetType().Name); + await base.OnActivateAsync(cancellationToken); + } +} + +/// +/// Grain that throws ObjectDisposedException unconditionally (not due to cancellation). +/// This tests that ObjectDisposedException thrown for other reasons is NOT treated as cancellation. +/// +public class ActivationCancellation_ThrowsObjectDisposedUnconditionallyGrain + : ActivationCancellationTestGrainBase, IActivationCancellation_ThrowsObjectDisposedUnconditionallyGrain +{ + public ActivationCancellation_ThrowsObjectDisposedUnconditionallyGrain( + ILogger logger, + IGrainRuntime grainRuntime) + : base(logger, grainRuntime) + { + } + + public override Task OnActivateAsync(CancellationToken cancellationToken) + { + Logger.LogDebug("OnActivateAsync starting for {GrainType}", GetType().Name); + + // Check if we should throw an exception (without cancellation being requested) + if (RequestContext.Get("throw_object_disposed") is bool shouldThrow && shouldThrow) + { + Logger.LogDebug("Throwing ObjectDisposedException unconditionally (cancellation NOT requested)"); + // This simulates a bug where ObjectDisposedException is thrown for reasons + // unrelated to cancellation - should NOT be treated as ActivationCancelledException + throw new ObjectDisposedException("SomeObject", "This object was disposed for reasons unrelated to cancellation."); + } + + IsActivatedSuccessfully = true; + Logger.LogDebug("OnActivateAsync completed successfully for {GrainType}", GetType().Name); + return base.OnActivateAsync(cancellationToken); + } +} + +/// +/// Grain that throws OperationCanceledException unconditionally (not due to cancellation token being cancelled). +/// This tests that OperationCanceledException thrown for other reasons is NOT treated as ActivationCancelledException. +/// +public class ActivationCancellation_ThrowsOperationCancelledUnconditionallyGrain + : ActivationCancellationTestGrainBase, IActivationCancellation_ThrowsOperationCancelledUnconditionallyGrain +{ + public ActivationCancellation_ThrowsOperationCancelledUnconditionallyGrain( + ILogger logger, + IGrainRuntime grainRuntime) + : base(logger, grainRuntime) + { + } + + public override Task OnActivateAsync(CancellationToken cancellationToken) + { + Logger.LogDebug("OnActivateAsync starting for {GrainType}", GetType().Name); + + // Check if we should throw an exception (without cancellation being requested) + if (RequestContext.Get("throw_operation_cancelled") is bool shouldThrow && shouldThrow) + { + Logger.LogDebug("Throwing OperationCanceledException unconditionally (cancellation NOT requested on the passed token)"); + // This simulates a scenario where OperationCanceledException is thrown for reasons + // unrelated to the activation's cancellation token being cancelled + // The code should check cancellationToken.IsCancellationRequested before converting to ActivationCancelledException + throw new OperationCanceledException("Operation was cancelled for reasons unrelated to activation cancellation."); + } + + IsActivatedSuccessfully = true; + Logger.LogDebug("OnActivateAsync completed successfully for {GrainType}", GetType().Name); + return base.OnActivateAsync(cancellationToken); + } +} diff --git a/test/TesterInternal/ActivationsLifeCycleTests/ActivationCancellationTests.cs b/test/TesterInternal/ActivationsLifeCycleTests/ActivationCancellationTests.cs new file mode 100644 index 00000000000..dc157f15d5b --- /dev/null +++ b/test/TesterInternal/ActivationsLifeCycleTests/ActivationCancellationTests.cs @@ -0,0 +1,396 @@ +#nullable enable +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; +using Orleans.Configuration; +using Orleans.TestingHost; +using TestExtensions; +using UnitTests.GrainInterfaces; +using Xunit; +using Xunit.Abstractions; + +namespace UnitTests.ActivationCancellationTests; + +/// +/// Tests for activation cancellation logging behavior in Orleans. +/// +/// These tests verify that: +/// 1. When activation is cancelled gracefully (OperationCanceledException or ObjectDisposedException +/// thrown while cancellation token is cancelled), the exception is wrapped in ActivationCancelledException +/// and logged at WARNING level (not ERROR level). +/// 2. When non-cancellation exceptions occur, they are still logged at ERROR level as expected. +/// +/// The key code being tested is in ActivationData.cs: +/// - catch (ObjectDisposedException) when (cancellationToken.IsCancellationRequested) → ActivationCancelledException → Warning log +/// - catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested && !timeout) → ActivationCancelledException → Warning log +/// - catch (Exception) → Error log +/// +/// Plan / Pseudocode (inserted as comment for traceability): +/// 1. Add two reusable assertion helpers: +/// - AssertLogEventExists(logs, eventId) -> asserts that any log in 'logs' has EventId == eventId. +/// - AssertLogEventNotExists(logs, eventId) -> asserts that no log in 'logs' has EventId == eventId. +/// 2. Keep existing behavior: ensure OperationCanceledException scenario finds info logs with the cancelled-activate EventId. +/// 3. Additionally assert that across error logs there is NOT an event with EventId == (int)ErrorCode.Catalog_ErrorCallingActivate. +/// 4. Helpers include clear diagnostic messages listing captured EventIds for easier debugging. +/// 5. Place helpers as private methods on the test class so they can be reused by other tests. +/// +/// The code below implements these helpers and uses them in the OperationCanceledException test. +/// +public class ActivationCancellationLoggingTests : OrleansTestingBase, IClassFixture +{ + private readonly Fixture _fixture; + private readonly ITestOutputHelper _output; + + public class Fixture : BaseTestClusterFixture + { + // Static so it can be accessed from the configurator + public static InMemoryLoggerProvider SharedLoggerProvider { get; } = new(); + + protected override void ConfigureTestCluster(TestClusterBuilder builder) + { + builder.Options.InitialSilosCount = 1; + builder.AddSiloBuilderConfigurator(); + } + + private class SiloHostConfigurator : ISiloConfigurator, IHostConfigurator + { + public void Configure(ISiloBuilder hostBuilder) + { + hostBuilder.Configure(options => + { + options.CollectionAge = TimeSpan.FromSeconds(10); + options.CollectionQuantum = TimeSpan.FromSeconds(1); + // Short activation timeout so we can test cancellation scenarios + options.ActivationTimeout = TimeSpan.FromSeconds(2); + options.DeactivationTimeout = TimeSpan.FromSeconds(2); + }); + + hostBuilder.Configure(options => + { + options.MaxRequestProcessingTime = TimeSpan.FromSeconds(5); + }); + } + + public void Configure(IHostBuilder hostBuilder) + { + hostBuilder.ConfigureServices(services => + { + services.AddSingleton(SharedLoggerProvider); + }); + } + } + } + + public ActivationCancellationLoggingTests(Fixture fixture, ITestOutputHelper output) + { + _fixture = fixture; + _output = output; + Fixture.SharedLoggerProvider.Clear(); + } + + private (IReadOnlyList ErrorLogs, IReadOnlyList WarningLogs, IReadOnlyList InfoLogs) GetActivationLogs() + { + var logs = Fixture.SharedLoggerProvider.GetLogs(); + + // Log all captured entries for debugging + _output.WriteLine($"Total logs captured: {logs.Count}"); + foreach (var log in logs.Where(l => l.Level >= LogLevel.Warning)) + { + _output.WriteLine($"[{log.Level}] [{log.Category}] {log.Message}"); + } + + // Look for activation-related logs + var activationLogs = logs.Where(l => + l.Category.Contains("Orleans.Grain") || + l.Category.Contains("ActivationData") || + l.Message.Contains("Activation", StringComparison.OrdinalIgnoreCase) || + l.Message.Contains("activating", StringComparison.OrdinalIgnoreCase)).ToList(); + + var errorLogs = activationLogs.Where(l => l.Level == LogLevel.Error).ToList(); + var warningLogs = activationLogs.Where(l => l.Level == LogLevel.Warning).ToList(); + var infoLogs = activationLogs.Where(l => l.Level == LogLevel.Information).ToList(); + + return (errorLogs, warningLogs, infoLogs); + } + + // Reusable helper: assert that at least one log in 'logs' has the specified event id. + private static void AssertLogEventExists(IEnumerable logs, int eventId) + { + var ids = logs.Select(l => l.EventId.Id).ToList(); + Assert.True(ids.Any(id => id == eventId), + $"Expected an information log with EventId {eventId} but it was not found. Captured EventIds: {string.Join(',', ids)}"); + } + + // Reusable helper: assert that no log in 'logs' has the specified event id. + private static void AssertLogEventNotExists(IEnumerable logs, int eventId) + { + var ids = logs.Select(l => l.EventId.Id).ToList(); + Assert.False(ids.Any(id => id == eventId), + $"Did not expect a log with EventId {eventId}, but it was found. Captured EventIds: {string.Join(',', ids)}"); + } + + #region Cancellation Scenarios - Should NOT log ERROR + + /// + /// When OperationCanceledException is thrown because the cancellation token was observed during activation, + /// it should be logged at WARNING level (not ERROR) because this is intentional cancellation behavior. + /// + [Fact, TestCategory("Functional"), TestCategory("ActivationCancellation")] + public async Task OperationCanceledException_WhenCancellationTokenObserved_LogsInfoNotError() + { + Fixture.SharedLoggerProvider.Clear(); + var grain = _fixture.GrainFactory.GetGrain(Guid.NewGuid()); + + // Set a delay longer than the activation timeout (2 seconds) to trigger cancellation + RequestContext.Set("delay_activation_ms", 5000); + + await Assert.ThrowsAnyAsync(async () => + { + await grain.IsActivated().WaitAsync(TimeSpan.FromSeconds(5)); + }); + + RequestContext.Clear(); + + await Task.Delay(100); + + var (errorLogs, warningLogs, infoLogs) = GetActivationLogs(); + + Assert.Empty(errorLogs); + Assert.Empty(warningLogs); + Assert.NotEmpty(infoLogs); + + // New assertion: ensure there is an info log with EventId == (int)ErrorCode.Catalog_CancelledActivate + AssertLogEventExists(infoLogs, (int)ErrorCode.Catalog_CancelledActivate); + + // Also ensure across error logs there is NOT an event with EventId == (int)ErrorCode.Catalog_ErrorCallingActivate + AssertLogEventNotExists(errorLogs, (int)ErrorCode.Catalog_ErrorCallingActivate); + } + + /// + /// When ObjectDisposedException is thrown because services are disposed after cancellation, + /// it should be logged at WARNING level (not ERROR) because this is expected behavior during cancellation. + /// + [Fact, TestCategory("Functional"), TestCategory("ActivationCancellation")] + public async Task ObjectDisposedException_WhenCancellationRequested_LogsWarningNotError() + { + Fixture.SharedLoggerProvider.Clear(); + var grain = _fixture.GrainFactory.GetGrain(Guid.NewGuid()); + + // Set a delay longer than the activation timeout to trigger cancellation + RequestContext.Set("delay_activation_ms", 5000); + + await Assert.ThrowsAnyAsync(async () => + { + await grain.IsActivated(); + }); + + RequestContext.Clear(); + + await Task.Delay(100); + + var (errorLogs, warningLogs, infoLogs) = GetActivationLogs(); + + Assert.Empty(errorLogs); + Assert.NotEmpty(warningLogs); + + + // New assertion: ensure there is an info log with EventId == (int)ErrorCode.Catalog_CancelledActivate + AssertLogEventExists(warningLogs, (int)ErrorCode.Catalog_DisposedObjectAccess); + + // Also ensure across error logs there is NOT an event with EventId == (int)ErrorCode.Catalog_ErrorCallingActivate + AssertLogEventNotExists(errorLogs, (int)ErrorCode.Catalog_ErrorCallingActivate); + } + + /// + /// When TaskCanceledException (which inherits from OperationCanceledException) is thrown during cancellation, + /// it should be logged at INFO level (not ERROR). + /// + [Fact, TestCategory("Functional"), TestCategory("ActivationCancellation")] + public async Task TaskCanceledException_WhenCancellationRequested_LogsInfoNotError() + { + Fixture.SharedLoggerProvider.Clear(); + var grain = _fixture.GrainFactory.GetGrain(Guid.NewGuid()); + + RequestContext.Set("delay_activation_ms", 5000); + + await Assert.ThrowsAnyAsync(async () => + { + await grain.IsActivated().WaitAsync(TimeSpan.FromSeconds(5)); + }); + + RequestContext.Clear(); + + await Task.Delay(100); + + var (errorLogs, warningLogs, infoLogs) = GetActivationLogs(); + + Assert.Empty(errorLogs); + Assert.Empty(warningLogs); + Assert.NotEmpty(infoLogs); + + // New assertion: ensure there is an info log with EventId == (int)ErrorCode.Catalog_CancelledActivate + AssertLogEventExists(infoLogs, (int)ErrorCode.Catalog_CancelledActivate); + + // Also ensure across error logs there is NOT an event with EventId == (int)ErrorCode.Catalog_ErrorCallingActivate + AssertLogEventNotExists(errorLogs, (int)ErrorCode.Catalog_ErrorCallingActivate); + } + + #endregion + + #region Non-Cancellation Scenarios - SHOULD log ERROR + + /// + /// When a generic exception (not related to cancellation) is thrown during activation, + /// it should be logged at ERROR level because this is an unexpected failure. + /// + [Fact, TestCategory("BVT"), TestCategory("ActivationCancellation")] + public async Task GenericException_DuringActivation_LogsError() + { + Fixture.SharedLoggerProvider.Clear(); + var grain = _fixture.GrainFactory.GetGrain(Guid.NewGuid()); + + RequestContext.Set("throw_exception", true); + + await Assert.ThrowsAsync(() => grain.IsActivated()); + + RequestContext.Clear(); + + await Task.Delay(100); + + var (errorLogs, _, infoLogs) = GetActivationLogs(); + + Assert.NotEmpty(errorLogs); + + // New assertion: ensure there is an info log with EventId == (int)ErrorCode.Catalog_CancelledActivate + AssertLogEventExists(errorLogs, (int)ErrorCode.Catalog_ErrorCallingActivate); + } + + /// + /// When ObjectDisposedException is thrown but the cancellation token was NOT cancelled, + /// it should be logged at ERROR level (the 'when' guard should NOT match). + /// + [Fact, TestCategory("BVT"), TestCategory("ActivationCancellation")] + public async Task ObjectDisposedException_WhenNotCancelled_LogsError() + { + Fixture.SharedLoggerProvider.Clear(); + var grain = _fixture.GrainFactory.GetGrain(Guid.NewGuid()); + + RequestContext.Set("throw_object_disposed", true); + + await Assert.ThrowsAsync(() => grain.IsActivated()); + + RequestContext.Clear(); + + await Task.Delay(100); + + var (errorLogs, _, infoLogs) = GetActivationLogs(); + + Assert.NotEmpty(errorLogs); + + // New assertion: ensure there is an info log with EventId == (int)ErrorCode.Catalog_CancelledActivate + AssertLogEventExists(errorLogs, (int)ErrorCode.Catalog_ErrorCallingActivate); + } + + /// + /// When OperationCanceledException is thrown but the cancellation token was NOT cancelled, + /// it should be logged at ERROR level (the 'when' guard should NOT match). + /// + [Fact, TestCategory("BVT"), TestCategory("ActivationCancellation")] + public async Task OperationCanceledException_WhenNotCancelled_LogsError() + { + Fixture.SharedLoggerProvider.Clear(); + var grain = _fixture.GrainFactory.GetGrain(Guid.NewGuid()); + + RequestContext.Set("throw_operation_cancelled", true); + + await Assert.ThrowsAsync(() => grain.IsActivated()); + + RequestContext.Clear(); + + await Task.Delay(100); + + var (errorLogs, _, infoLogs) = GetActivationLogs(); + + Assert.NotEmpty(errorLogs); + + // New assertion: ensure there is an info log with EventId == (int)ErrorCode.Catalog_CancelledActivate + AssertLogEventExists(errorLogs, (int)ErrorCode.Catalog_ErrorCallingActivate); + } + + #endregion + + #region Baseline Tests - Normal Operation + + /// + /// Baseline test: Successful activation should not log any errors or warnings. + /// + [Fact, TestCategory("BVT"), TestCategory("ActivationCancellation")] + public async Task SuccessfulActivation_NoErrorOrWarningLogs() + { + Fixture.SharedLoggerProvider.Clear(); + var grain = _fixture.GrainFactory.GetGrain(Guid.NewGuid()); + + var isActivated = await grain.IsActivated(); + + await Task.Delay(100); + + var (errorLogs, warningLogs, infoLogs) = GetActivationLogs(); + + Assert.True(isActivated); + Assert.Empty(errorLogs); + Assert.Empty(warningLogs); + + // New assertion: ensure there is an info log with EventId == (int)ErrorCode.Catalog_CancelledActivate + AssertLogEventNotExists(infoLogs, (int)ErrorCode.Catalog_CancelledActivate); + } + + #endregion +} + +public class InMemoryLoggerProvider : ILoggerProvider +{ + private readonly List _logs = new(); + private readonly object _lock = new(); + + public ILogger CreateLogger(string categoryName) => new InMemoryLogger(this, categoryName); + + public void Dispose() { } + + public void Clear() + { + lock (_lock) + { + _logs.Clear(); + } + } + + public IReadOnlyList GetLogs() + { + lock (_lock) + { + return _logs.ToList(); + } + } + + internal void AddLog(LogEntry entry) + { + lock (_lock) + { + _logs.Add(entry); + } + } + + private class InMemoryLogger(InMemoryLoggerProvider provider, string categoryName) : ILogger + { + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) + { + provider.AddLog(new LogEntry(categoryName, logLevel, eventId, formatter(state, exception), exception)); + } + } +} + +public record LogEntry(string Category, LogLevel Level, EventId EventId, string Message, Exception? Exception);