From dac63d5e136b299394c4f7c7147fb06b2762a13c Mon Sep 17 00:00:00 2001 From: Reuben Bond Date: Sat, 8 Aug 2026 14:27:32 -0700 Subject: [PATCH 1/4] fix(transactions): improve recovery liveness and diagnostics Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: 926dfb31-52fb-4a8a-8af8-6a9fe3d0e152 --- .../Orleans.Transactions.TestKit.Base.csproj | 4 + .../TransactionRecoveryEventObserver.cs | 532 ++++++++ .../TransactionRecoveryFailureObservation.cs | 204 ++++ .../TransactionRecoveryTestsRunner.cs | 617 +++++++++- .../TransactionDiagnosticEvents.cs | 1070 ++++++++++++++++- .../DistributedTM/TransactionAgent.cs | 108 +- .../DistributedTM/TransactionRecord.cs | 32 + .../State/ReaderWriterLock.cs | 59 +- .../State/StorageBatch.cs | 6 + .../State/TransactionManager.cs | 15 +- .../State/TransactionQueue.cs | 593 ++++++++- .../State/TransactionalResource.cs | 6 +- .../State/TransactionalState.cs | 15 +- .../TOC/TocTransactionQueue.cs | 6 +- .../TOC/TransactionCommitter.cs | 16 +- .../Orleans.Transactions.TestKit.Base.cs | 6 + .../TransactionRecoveryTests.cs | 21 + .../TransactionRecoveryTests.cs | 21 + .../BankTransferDiagnosticFaults.cs | 8 +- .../TransactionDiagnosticEventsTests.cs | 782 ++++++++++++ ...nsactionRecoveryFailureObservationTests.cs | 143 +++ .../TransactionRecoveryLatencyTests.cs | 749 ++++++++++++ 22 files changed, 4882 insertions(+), 131 deletions(-) create mode 100644 src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryEventObserver.cs create mode 100644 src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryFailureObservation.cs create mode 100644 test/Transactions/Orleans.Transactions.Tests/TransactionDiagnosticEventsTests.cs create mode 100644 test/Transactions/Orleans.Transactions.Tests/TransactionRecoveryFailureObservationTests.cs create mode 100644 test/Transactions/Orleans.Transactions.Tests/TransactionRecoveryLatencyTests.cs diff --git a/src/Orleans.Transactions.TestKit.Base/Orleans.Transactions.TestKit.Base.csproj b/src/Orleans.Transactions.TestKit.Base/Orleans.Transactions.TestKit.Base.csproj index 5c9d08e04a2..5a50b1da83f 100644 --- a/src/Orleans.Transactions.TestKit.Base/Orleans.Transactions.TestKit.Base.csproj +++ b/src/Orleans.Transactions.TestKit.Base/Orleans.Transactions.TestKit.Base.csproj @@ -26,4 +26,8 @@ + + + + diff --git a/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryEventObserver.cs b/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryEventObserver.cs new file mode 100644 index 00000000000..f84bd650557 --- /dev/null +++ b/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryEventObserver.cs @@ -0,0 +1,532 @@ +using System; +using System.Collections.Generic; +using System.Collections.Immutable; +using System.Diagnostics; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using Orleans.Runtime; +using Orleans.Transactions.Diagnostics; + +namespace Orleans.Transactions.TestKit; + +internal sealed class TransactionRecoveryEventObserver : IObserver, IDisposable +{ + private readonly object lockObj = new(); + private readonly Func candidateFilter; + private readonly IDisposable subscription; + private readonly long startedAt = Stopwatch.GetTimestamp(); + private readonly List timeline = []; + private readonly List waiters = []; + private HashSet? relevantGrains; + private PhaseGate? phaseGate; + private long nextSequence; + private bool disposed; + + public TransactionRecoveryEventObserver(IEnumerable candidateGrains) + : this(CreateCandidateFilter(candidateGrains)) + { + } + + internal TransactionRecoveryEventObserver(Func candidateFilter) + { + this.candidateFilter = candidateFilter; + this.subscription = TransactionDiagnosticEvents.AllEvents.Subscribe(this); + } + + public long LatestRelevantSequence + { + get + { + lock (this.lockObj) + { + for (var i = this.timeline.Count - 1; i >= 0; i--) + { + if (this.IsCurrentlyRelevant(this.timeline[i])) + { + return this.timeline[i].Sequence; + } + } + + return 0; + } + } + } + + public void SetRelevantGrains(IEnumerable grainIds) + { + List<(Waiter Waiter, RecoveryTransition Transition)> completed = []; + lock (this.lockObj) + { + this.ThrowIfDisposed(); + this.relevantGrains = grainIds.ToHashSet(); + for (var i = this.waiters.Count - 1; i >= 0; i--) + { + var waiter = this.waiters[i]; + var transition = this.FindTransitionAfter(waiter.AfterSequence); + if (transition is not null) + { + this.waiters.RemoveAt(i); + completed.Add((waiter, transition)); + } + } + } + + foreach (var item in completed) + { + item.Waiter.Completion.TrySetResult(item.Transition); + } + } + + internal PhaseGate GateNextTransition(Func predicate) + { + lock (this.lockObj) + { + this.ThrowIfDisposed(); + if (this.phaseGate is not null) + { + throw new InvalidOperationException("A transaction recovery phase gate is already armed."); + } + + return this.phaseGate = new(predicate, this.ReleaseGate); + } + } + + public async Task WaitForNextTransitionAsync( + long afterSequence, + long deadline, + CancellationToken cancellationToken = default) + { + Waiter waiter; + lock (this.lockObj) + { + this.ThrowIfDisposed(); + var existing = this.FindTransitionAfter(afterSequence); + if (existing is not null) + { + return existing; + } + + waiter = new(afterSequence); + this.waiters.Add(waiter); + } + + try + { + var now = Stopwatch.GetTimestamp(); + if (now >= deadline) + { + throw new TimeoutException(); + } + + return await waiter.Completion.Task.WaitAsync(Stopwatch.GetElapsedTime(now, deadline), cancellationToken); + } + catch (TimeoutException) + { + this.RemoveWaiter(waiter); + throw new TimeoutException( + $"No relevant transaction recovery transition was observed before the watchdog deadline." + + Environment.NewLine + + this.FormatTimeline()); + } + catch (OperationCanceledException) + { + this.RemoveWaiter(waiter); + throw; + } + } + + public IReadOnlyList GetTimeline() + { + lock (this.lockObj) + { + return this.timeline.Where(this.IsCurrentlyRelevant).ToArray(); + } + } + + public string FormatTimeline() + { + var entries = this.GetTimeline(); + if (entries.Count == 0) + { + return "Transaction recovery timeline: "; + } + + return "Transaction recovery timeline:" + + Environment.NewLine + + string.Join(Environment.NewLine, entries.Select(FormatTransition)); + } + + public static string FormatTransition(RecoveryTransition transition) + => $" sequence={transition.Sequence}, observedAt={transition.ObservedAtUtc:O}, elapsed={transition.Elapsed}, " + + $"kind={transition.Kind}, transactions={FormatTransactionIds(transition.TransactionIds)}, " + + $"role={transition.ProtocolRole}, phase={transition.Phase}, " + + $"resource={transition.ResourceName}, grain={transition.GrainId?.ToString() ?? ""}, " + + $"silo={transition.SiloAddress?.ToString() ?? ""}, " + + $"activation={(transition.ActivationId.IsDefault ? "" : transition.ActivationId.ToString())}, " + + $"status={transition.Status ?? ""}"; + + public void Dispose() + { + List waiters; + PhaseGate? phaseGate; + lock (this.lockObj) + { + if (this.disposed) + { + return; + } + + this.disposed = true; + waiters = [.. this.waiters]; + this.waiters.Clear(); + phaseGate = this.phaseGate; + this.phaseGate = null; + } + + this.subscription.Dispose(); + phaseGate?.Release(); + foreach (var waiter in waiters) + { + waiter.Completion.TrySetException(new ObjectDisposedException(nameof(TransactionRecoveryEventObserver))); + } + } + + void IObserver.OnCompleted() + { + } + + void IObserver.OnError(Exception error) + { + } + + void IObserver.OnNext( + TransactionDiagnosticEvents.TransactionDiagnosticEvent value) + { + if (!this.candidateFilter(value.Resource) + || !TryCreateTransition(value, Stopwatch.GetElapsedTime(this.startedAt), out var transition)) + { + return; + } + + List completed = []; + PhaseGate? reachedGate = null; + var isRelevant = false; + lock (this.lockObj) + { + if (this.disposed) + { + return; + } + + transition = transition with { Sequence = ++this.nextSequence }; + this.timeline.Add(transition); + if (this.phaseGate is { } phaseGate + && phaseGate.Predicate(transition) + && phaseGate.TryReach(transition)) + { + this.phaseGate = null; + reachedGate = phaseGate; + } + + isRelevant = this.IsCurrentlyRelevant(transition); + if (isRelevant) + { + for (var i = this.waiters.Count - 1; i >= 0; i--) + { + if (transition.Sequence > this.waiters[i].AfterSequence) + { + completed.Add(this.waiters[i]); + this.waiters.RemoveAt(i); + } + } + } + } + + if (isRelevant) + { + foreach (var waiter in completed) + { + waiter.Completion.TrySetResult(transition); + } + } + + reachedGate?.Block(); + } + + private static Func CreateCandidateFilter(IEnumerable candidateGrains) + { + var candidates = candidateGrains.ToHashSet(); + return resource => resource.Reference is not null && candidates.Contains(resource.Reference.GrainId); + } + + private static bool TryCreateTransition( + TransactionDiagnosticEvents.TransactionDiagnosticEvent evt, + TimeSpan elapsed, + out RecoveryTransition transition) + { + var kind = evt switch + { + TransactionDiagnosticEvents.StorageWriteCompleted => RecoveryTransitionKind.StorageWriteCompleted, + TransactionDiagnosticEvents.TransactionManagerWaitingForPrepared => RecoveryTransitionKind.TransactionManagerWaitingForPrepared, + TransactionDiagnosticEvents.RemotePreparePersisted => RecoveryTransitionKind.RemotePreparePersisted, + TransactionDiagnosticEvents.RemotePreparedSent => RecoveryTransitionKind.RemotePreparedSent, + TransactionDiagnosticEvents.PrepareTimedOut => RecoveryTransitionKind.PrepareTimedOut, + TransactionDiagnosticEvents.RemoteRecoveryPingSent => RecoveryTransitionKind.RemoteRecoveryPingSent, + TransactionDiagnosticEvents.TransactionManagerAbortDecisionCompleted => RecoveryTransitionKind.TransactionManagerAbortDecisionCompleted, + TransactionDiagnosticEvents.TransactionCancelCompleted => RecoveryTransitionKind.TransactionCancelCompleted, + TransactionDiagnosticEvents.TransactionConfirmCompleted => RecoveryTransitionKind.TransactionConfirmCompleted, + TransactionDiagnosticEvents.CancelSendStarted => RecoveryTransitionKind.CancelSendStarted, + TransactionDiagnosticEvents.CancelSendCompleted => RecoveryTransitionKind.CancelSendCompleted, + TransactionDiagnosticEvents.CancelSendFailed => RecoveryTransitionKind.CancelSendFailed, + TransactionDiagnosticEvents.CancelFanOutStarted => RecoveryTransitionKind.CancelFanOutStarted, + TransactionDiagnosticEvents.CancelFanOutCompleted => RecoveryTransitionKind.CancelFanOutCompleted, + TransactionDiagnosticEvents.CancelFanOutFailed => RecoveryTransitionKind.CancelFanOutFailed, + TransactionDiagnosticEvents.ReadyWaitStarted => RecoveryTransitionKind.ReadyWaitStarted, + TransactionDiagnosticEvents.ReadyWaitCompleted => RecoveryTransitionKind.ReadyWaitCompleted, + TransactionDiagnosticEvents.ReadyWaitFailed => RecoveryTransitionKind.ReadyWaitFailed, + TransactionDiagnosticEvents.DeactivationRequested => RecoveryTransitionKind.DeactivationRequested, + TransactionDiagnosticEvents.StorageConflictDetected => RecoveryTransitionKind.StorageConflict, + TransactionDiagnosticEvents.AbortAndRestoreCompleted => RecoveryTransitionKind.AbortAndRestoreCompleted, + TransactionDiagnosticEvents.QueueRestoreCompleted => RecoveryTransitionKind.QueueRestoreCompleted, + TransactionDiagnosticEvents.QueueRestoreFailed => RecoveryTransitionKind.QueueRestoreFailed, + TransactionDiagnosticEvents.LockExpired => RecoveryTransitionKind.LockExpired, + TransactionDiagnosticEvents.LockBroken => RecoveryTransitionKind.LockBroken, + _ => (RecoveryTransitionKind?)null, + }; + + if (kind is null) + { + transition = null!; + return false; + } + + var transactionIds = evt switch + { + TransactionDiagnosticEvents.TransactionEvent transactionEvent => ImmutableArray.Create(transactionEvent.TransactionId), + TransactionDiagnosticEvents.StorageWriteCompleted completedWrite => completedWrite.TransactionIds, + TransactionDiagnosticEvents.LockBroken lockBroken => ImmutableArray.Create(lockBroken.TransactionId), + TransactionDiagnosticEvents.StorageConflictDetected conflict => conflict.TransactionIds, + TransactionDiagnosticEvents.AbortAndRestoreCompleted restored => restored.TransactionIds, + TransactionDiagnosticEvents.QueueRestoreCompleted restored => restored.TransactionIds, + TransactionDiagnosticEvents.QueueRestoreFailed failed => failed.TransactionIds, + TransactionDiagnosticEvents.ReadyWaitEvent ready when ready.TransactionId is { } transactionId => + ImmutableArray.Create(transactionId), + TransactionDiagnosticEvents.DeactivationRequested deactivation => deactivation.TransactionIds, + _ => ImmutableArray.Empty, + }; + var status = evt switch + { + TransactionDiagnosticEvents.StorageWriteCompleted stored => + $"batchSize={stored.BatchSize}, commitCount={stored.CommitCount}, eTag={stored.ETag ?? ""}", + TransactionDiagnosticEvents.TransactionManagerWaitingForPrepared waiting => + $"remaining={waiting.WaitCount}, deadline={waiting.Deadline:O}", + TransactionDiagnosticEvents.PrepareTimedOut timedOut => $"remaining={timedOut.RemainingCount}", + TransactionDiagnosticEvents.TransactionManagerAbortDecisionCompleted aborted => aborted.Status.ToString(), + TransactionDiagnosticEvents.TransactionCancelCompleted canceled => + $"{canceled.Status}, queueEntryFound={canceled.QueueEntryFound}, succeeded={canceled.Succeeded}", + TransactionDiagnosticEvents.TransactionConfirmCompleted confirmed => + $"{confirmed.Status}, queueEntryFound={confirmed.QueueEntryFound}, succeeded={confirmed.Succeeded}", + TransactionDiagnosticEvents.CancelSendStarted cancel => + $"{cancel.Status}, target={cancel.Target.Name}, isSelf={cancel.IsSelf}, reason={cancel.Reason}", + TransactionDiagnosticEvents.CancelSendCompleted cancel => + $"{cancel.Status}, target={cancel.Target.Name}, isSelf={cancel.IsSelf}, reason={cancel.Reason}", + TransactionDiagnosticEvents.CancelSendFailed cancel => + $"{cancel.Status}, target={cancel.Target.Name}, isSelf={cancel.IsSelf}, reason={cancel.Reason}, " + + $"exception={cancel.ExceptionType}", + TransactionDiagnosticEvents.CancelFanOutStarted fanOut => + $"{fanOut.Status}, targets={fanOut.TargetCount}, selfTargets={fanOut.SelfTargetCount}", + TransactionDiagnosticEvents.CancelFanOutCompleted fanOut => + $"{fanOut.Status}, targets={fanOut.TargetCount}, selfTargets={fanOut.SelfTargetCount}, " + + $"duration={fanOut.Duration}", + TransactionDiagnosticEvents.CancelFanOutFailed fanOut => + $"{fanOut.Status}, targets={fanOut.TargetCount}, selfTargets={fanOut.SelfTargetCount}, " + + $"duration={fanOut.Duration}, exception={fanOut.ExceptionType}", + TransactionDiagnosticEvents.ReadyWaitStarted => "started", + TransactionDiagnosticEvents.ReadyWaitCompleted ready => + $"recoveredAfterFailure={ready.RecoveredAfterFailure}", + TransactionDiagnosticEvents.ReadyWaitFailed ready => $"exception={ready.ExceptionType}", + TransactionDiagnosticEvents.DeactivationRequested deactivation => + $"{deactivation.Status}, failureCount={deactivation.FailureCount}", + TransactionDiagnosticEvents.StorageConflictDetected conflict => + $"operation={conflict.Operation}, storageOutcomeInDoubt={conflict.StorageOutcomeInDoubt}, " + + $"queued={conflict.QueuedTransactionCount}, exception={conflict.ExceptionType}", + TransactionDiagnosticEvents.AbortAndRestoreCompleted restored => + $"{restored.Status}, storageOutcomeInDoubt={restored.StorageOutcomeInDoubt}", + TransactionDiagnosticEvents.QueueRestoreCompleted restored => + $"pending={restored.RecoveredPendingCount}, commits={restored.RecoveredCommitCount}", + TransactionDiagnosticEvents.QueueRestoreFailed failed => + $"storageConflict={failed.StorageConflict}, exception={failed.ExceptionType}", + TransactionDiagnosticEvents.LockExpired expired => + $"{expired.Kind}, deadline={expired.Deadline:O}, observedAt={expired.ObservedAt:O}", + TransactionDiagnosticEvents.LockBroken broken => broken.Reason.ToString(), + _ => null, + }; + + transition = new( + Sequence: 0, + ObservedAtUtc: DateTime.UtcNow, + elapsed, + kind.Value, + transactionIds, + evt.ProtocolRole, + evt.Phase, + evt.Resource.Name, + evt.Resource.Reference is null ? null : evt.Resource.Reference.GrainId, + evt.SiloAddress, + evt.ActivationId, + status, + evt is TransactionDiagnosticEvents.StorageWriteCompleted storageWrite ? storageWrite.CommitCount : null); + return true; + } + + private static string FormatTransactionIds(ImmutableArray transactionIds) + => transactionIds.IsDefaultOrEmpty ? "" : $"[{string.Join(",", transactionIds)}]"; + + private bool IsCurrentlyRelevant(RecoveryTransition transition) + => this.relevantGrains is null + || transition.GrainId is { } grainId && this.relevantGrains.Contains(grainId); + + private RecoveryTransition? FindTransitionAfter(long sequence) + => this.timeline.FirstOrDefault(transition => transition.Sequence > sequence && this.IsCurrentlyRelevant(transition)); + + private void RemoveWaiter(Waiter waiter) + { + lock (this.lockObj) + { + this.waiters.Remove(waiter); + } + } + + private void ReleaseGate(PhaseGate gate) + { + lock (this.lockObj) + { + if (ReferenceEquals(this.phaseGate, gate)) + { + this.phaseGate = null; + } + } + } + + private void ThrowIfDisposed() + { + ObjectDisposedException.ThrowIf(this.disposed, this); + } + + private sealed class Waiter(long afterSequence) + { + public long AfterSequence { get; } = afterSequence; + public TaskCompletionSource Completion { get; } = + new(TaskCreationOptions.RunContinuationsAsynchronously); + } + + internal enum RecoveryTransitionKind + { + StorageWriteCompleted, + TransactionManagerWaitingForPrepared, + RemotePreparePersisted, + RemotePreparedSent, + PrepareTimedOut, + RemoteRecoveryPingSent, + TransactionManagerAbortDecisionCompleted, + TransactionCancelCompleted, + TransactionConfirmCompleted, + CancelSendStarted, + CancelSendCompleted, + CancelSendFailed, + CancelFanOutStarted, + CancelFanOutCompleted, + CancelFanOutFailed, + ReadyWaitStarted, + ReadyWaitCompleted, + ReadyWaitFailed, + DeactivationRequested, + StorageConflict, + AbortAndRestoreCompleted, + QueueRestoreCompleted, + QueueRestoreFailed, + LockExpired, + LockBroken, + } + + internal sealed record RecoveryTransition( + long Sequence, + DateTime ObservedAtUtc, + TimeSpan Elapsed, + RecoveryTransitionKind Kind, + ImmutableArray TransactionIds, + TransactionDiagnosticEvents.TransactionProtocolRole ProtocolRole, + TransactionDiagnosticEvents.TransactionPhase Phase, + string ResourceName, + GrainId? GrainId, + SiloAddress? SiloAddress, + ActivationId ActivationId, + string? Status, + int? CommitCount) + { + public Guid? TransactionId => this.TransactionIds.Length == 1 ? this.TransactionIds[0] : null; + } + + internal sealed class PhaseGate( + Func predicate, + Action onDisposed) : IDisposable + { + private readonly TaskCompletionSource release = + new(TaskCreationOptions.RunContinuationsAsynchronously); + private readonly TaskCompletionSource reached = + new(TaskCreationOptions.RunContinuationsAsynchronously); + private int state; + + internal Func Predicate { get; } = predicate; + + internal bool TryReach(RecoveryTransition transition) + { + if (Interlocked.CompareExchange(ref this.state, 1, 0) != 0) + { + return false; + } + + this.reached.TrySetResult(transition); + return true; + } + + internal void Block() => this.release.Task.GetAwaiter().GetResult(); + + internal void Release() => this.release.TrySetResult(); + + internal async Task WaitAsync(long deadline) + { + if (this.reached.Task.IsCompleted) + { + return await this.reached.Task; + } + + var now = Stopwatch.GetTimestamp(); + if (now >= deadline) + { + throw new TimeoutException("The transaction recovery phase gate was not reached before the deadline."); + } + + try + { + return await this.reached.Task.WaitAsync(Stopwatch.GetElapsedTime(now, deadline)); + } + catch (TimeoutException) + { + throw new TimeoutException("The transaction recovery phase gate was not reached before the deadline."); + } + } + + public void Dispose() + { + if (Interlocked.Exchange(ref this.state, 2) == 2) + { + return; + } + + this.release.TrySetResult(); + onDisposed(this); + } + } +} diff --git a/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryFailureObservation.cs b/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryFailureObservation.cs new file mode 100644 index 00000000000..513044caba0 --- /dev/null +++ b/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryFailureObservation.cs @@ -0,0 +1,204 @@ +using System; +using System.Diagnostics; +using System.Threading; +using System.Threading.Tasks; + +namespace Orleans.Transactions.TestKit; + +internal static class TransactionRecoveryFailureObservation +{ + internal enum OutcomeKind + { + FailureObserved, + StoppedWithoutFailure, + AttemptTimedOut, + } + + internal sealed record Outcome( + OutcomeKind Kind, + TFailure? Failure, + TProducerResult ProducerResult, + bool ProducerSettled, + TimeSpan Elapsed, + TimeSpan DrainElapsed) + where TFailure : class; + + public static async Task ObserveAsync(Task task, Action onFailure) + { + try + { + await task.ConfigureAwait(false); + } + catch (Exception exception) + { + onFailure(exception, Stopwatch.GetTimestamp()); + } + } + + public static bool IsPremature(long observedAt, long shutdownRequestedAt) => observedAt < shutdownRequestedAt; + + internal static async Task> DetectAsync( + Task producer, + Task firstFailure, + CancellationTokenSource stopProducing, + TimeSpan responseWindow, + TimeSpan schedulingMargin) + where TFailure : class + { + ArgumentOutOfRangeException.ThrowIfLessThan(responseWindow, TimeSpan.Zero); + ArgumentOutOfRangeException.ThrowIfLessThan(schedulingMargin, TimeSpan.Zero); + + var startedAt = Stopwatch.GetTimestamp(); + var responseDeadline = GetDeadline(startedAt, responseWindow); + var drainDeadline = GetDeadline(responseDeadline, schedulingMargin); + + await WaitUntilAsync(firstFailure, producer, responseDeadline); + if (firstFailure.IsCompleted) + { + return await CompleteFailureAsync( + producer, + firstFailure, + stopProducing, + startedAt, + drainDeadline); + } + + if (producer.IsCompleted) + { + var producerResult = await producer.ConfigureAwait(false); + if (firstFailure.IsCompleted) + { + return await CompleteFailureAsync( + producer, + firstFailure, + stopProducing, + startedAt, + drainDeadline); + } + + return new( + OutcomeKind.StoppedWithoutFailure, + Failure: null, + producerResult, + ProducerSettled: true, + Stopwatch.GetElapsedTime(startedAt), + DrainElapsed: TimeSpan.Zero); + } + + stopProducing.Cancel(); + var drainStartedAt = Stopwatch.GetTimestamp(); + await WaitUntilAsync(firstFailure, producer, drainDeadline); + + if (firstFailure.IsCompleted) + { + return await CompleteFailureAsync( + producer, + firstFailure, + stopProducing, + startedAt, + drainDeadline, + drainStartedAt); + } + + if (producer.IsCompleted) + { + var producerResult = await producer.ConfigureAwait(false); + if (firstFailure.IsCompleted) + { + return await CompleteFailureAsync( + producer, + firstFailure, + stopProducing, + startedAt, + drainDeadline, + drainStartedAt); + } + + return new( + OutcomeKind.StoppedWithoutFailure, + Failure: null, + producerResult, + ProducerSettled: true, + Stopwatch.GetElapsedTime(startedAt), + Stopwatch.GetElapsedTime(drainStartedAt)); + } + + producer.Ignore(); + return new( + OutcomeKind.AttemptTimedOut, + Failure: null, + ProducerResult: default!, + ProducerSettled: false, + Stopwatch.GetElapsedTime(startedAt), + Stopwatch.GetElapsedTime(drainStartedAt)); + } + + private static async Task> CompleteFailureAsync( + Task producer, + Task firstFailure, + CancellationTokenSource stopProducing, + long startedAt, + long drainDeadline, + long? drainStartedAt = null) + where TFailure : class + { + stopProducing.Cancel(); + var failure = await firstFailure.ConfigureAwait(false); + var drainStarted = drainStartedAt ?? Stopwatch.GetTimestamp(); + if (!producer.IsCompleted) + { + await WaitUntilAsync(producer, drainDeadline); + } + + if (producer.IsCompleted) + { + return new( + OutcomeKind.FailureObserved, + failure, + await producer.ConfigureAwait(false), + ProducerSettled: true, + Stopwatch.GetElapsedTime(startedAt), + Stopwatch.GetElapsedTime(drainStarted)); + } + + producer.Ignore(); + return new( + OutcomeKind.FailureObserved, + failure, + ProducerResult: default!, + ProducerSettled: false, + Stopwatch.GetElapsedTime(startedAt), + Stopwatch.GetElapsedTime(drainStarted)); + } + + private static async Task WaitUntilAsync(Task first, long deadline) + { + if (first.IsCompleted) + { + return; + } + + var now = Stopwatch.GetTimestamp(); + if (now < deadline) + { + await Task.WhenAny(first, Task.Delay(Stopwatch.GetElapsedTime(now, deadline))).ConfigureAwait(false); + } + } + + private static async Task WaitUntilAsync(Task first, Task second, long deadline) + { + if (first.IsCompleted || second.IsCompleted) + { + return; + } + + var now = Stopwatch.GetTimestamp(); + if (now < deadline) + { + await Task.WhenAny(first, second, Task.Delay(Stopwatch.GetElapsedTime(now, deadline))).ConfigureAwait(false); + } + } + + private static long GetDeadline(long startedAt, TimeSpan duration) + => checked(startedAt + (long)(duration.TotalSeconds * Stopwatch.Frequency)); +} diff --git a/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryTestsRunner.cs b/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryTestsRunner.cs index 2868a72aadd..64b2decb72c 100644 --- a/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryTestsRunner.cs +++ b/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryTestsRunner.cs @@ -1,24 +1,30 @@ using System; using System.Collections.Generic; +using System.Diagnostics; using System.Linq; +using System.Threading; using System.Threading.Tasks; using AwesomeAssertions; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; +using Orleans.Configuration; +using Orleans.Runtime; using Orleans.TestingHost; -using Orleans.TestingHost.Utils; using Orleans.Transactions.TestKit.Correctnesss; namespace Orleans.Transactions.TestKit { public partial class TransactionRecoveryTestsRunner : TransactionTestRunnerBase { - private static readonly TimeSpan RecoveryTimeout = TimeSpan.FromSeconds(60); - // reduce to or remove once we fix timeouts abort - private static readonly TimeSpan RetryDelay = TimeSpan.FromSeconds(1); + private static readonly TimeSpan FailureDetectionSchedulingMargin = TimeSpan.FromSeconds(15); private readonly TestCluster testCluster; private readonly ILogger logger; + private readonly TimeSpan clientResponseTimeout; + private readonly TimeSpan failureDetectionTimeout; + private readonly TimeSpan recoveryTimeout; protected void Log(string message) { @@ -35,6 +41,7 @@ public ExpectedGrainActivity(Guid grainId, ITransactionalBitArrayGrain grain) } public Guid GrainId { get; } public ITransactionalBitArrayGrain Grain { get; } + public GrainId RuntimeGrainId => this.Grain.GetGrainId(); public BitArrayState Expected { get; } = new BitArrayState(); public BitArrayState Unambiguous { get; } = new BitArrayState(); public List Actual { get; set; } = null!; @@ -52,11 +59,30 @@ public async Task GetActual() } } + private sealed record TransactionFailure(int Index, Guid[] GrainIds, Exception Exception, long ObservedAt); + + private sealed record InFlightBatch(int Index, int PendingCount); + + private sealed record RecoveryResult( + bool Succeeded, + bool LastProbeSucceeded, + int Attempts, + int RemainingGroupCount, + int LastTransactionIndex, + TimeSpan Elapsed); + public TransactionRecoveryTestsRunner(TestCluster testCluster, Action testOutput) : base(testCluster.GrainFactory!, testOutput) // Transaction test clusters initialize a client. { this.testCluster = testCluster; this.logger = this.testCluster.ServiceProvider.GetService>()!; + this.clientResponseTimeout = this.testCluster.ServiceProvider + .GetRequiredService>() + .Value + .ResponseTimeout; + this.failureDetectionTimeout = this.clientResponseTimeout + FailureDetectionSchedulingMargin; + this.recoveryTimeout = + this.failureDetectionTimeout + TransactionalStateOptions.DefaultRemoteTransactionPingFrequency; } public virtual Task TransactionWillRecoverAfterRandomSiloGracefulShutdown(string transactionTestGrainClassName, int concurrent) @@ -69,11 +95,195 @@ public virtual Task TransactionWillRecoverAfterRandomSiloUnGracefulShutdown(stri return TransactionWillRecoverAfterRandomSiloFailure(transactionTestGrainClassName, concurrent, false); } + /// + /// Verifies recovery when the transaction manager activation is terminated while waiting for remote prepares. + /// + public Task TransactionWillRecoverAfterManagerWait(string transactionTestGrainClassName) + => TransactionWillRecoverAfterTargetedPhase( + transactionTestGrainClassName, + TransactionRecoveryEventObserver.RecoveryTransitionKind.TransactionManagerWaitingForPrepared, + requireParticipantConfirmation: false); + + /// + /// Verifies recovery when a remote participant activation is terminated after persisting its prepare. + /// + public Task TransactionWillRecoverAfterRemotePreparePersisted(string transactionTestGrainClassName) + => TransactionWillRecoverAfterTargetedPhase( + transactionTestGrainClassName, + TransactionRecoveryEventObserver.RecoveryTransitionKind.RemotePreparePersisted, + requireParticipantConfirmation: false); + + /// + /// Verifies recovery when the transaction manager activation is terminated after its commit is durable. + /// + public Task TransactionWillRecoverAfterLocalCommitStored(string transactionTestGrainClassName) + => TransactionWillRecoverAfterTargetedPhase( + transactionTestGrainClassName, + TransactionRecoveryEventObserver.RecoveryTransitionKind.StorageWriteCompleted, + requireParticipantConfirmation: true); + + private async Task TransactionWillRecoverAfterTargetedPhase( + string transactionTestGrainClassName, + TransactionRecoveryEventObserver.RecoveryTransitionKind phase, + bool requireParticipantConfirmation) + { + var index = 0; + int getIndex() => Interlocked.Increment(ref index) - 1; + var txGrains = Enumerable.Range(0, 2) + .Select(_ => Guid.NewGuid()) + .Select(grainId => new ExpectedGrainActivity( + grainId, + TestGrain(transactionTestGrainClassName, grainId))) + .ToList(); + var transactionGroups = new[] { txGrains }; + + await WakeupGrains(txGrains.Select(grain => grain.Grain).ToList()); + (await AllTxSucceed(transactionGroups, getIndex())).Should().BeTrue(); + await ValidateResults(txGrains, transactionGroups); + + using var recoveryEvents = new TransactionRecoveryEventObserver( + txGrains.Select(grain => grain.RuntimeGrainId)); + using var phaseGate = recoveryEvents.GateNextTransition(transition => + transition.Kind == phase + && (!requireParticipantConfirmation + || transition.CommitCount > 0 && !transition.TransactionIds.IsDefaultOrEmpty)); + var phaseDeadline = Stopwatch.GetTimestamp() + + (long)(this.failureDetectionTimeout.TotalSeconds * Stopwatch.Frequency); + var attemptIndex = getIndex(); + var attempt = RunAllTxReportFailed(transactionGroups, attemptIndex); + TransactionRecoveryEventObserver.RecoveryTransition transition; + try + { + transition = await phaseGate.WaitAsync(phaseDeadline); + } + catch + { + attempt.Ignore(); + throw; + } + + if (transition.SiloAddress is null || transition.ActivationId.IsDefault) + { + attempt.Ignore(); + throw new InvalidOperationException( + $"The {phase} transition did not identify its owning silo and activation." + + Environment.NewLine + + recoveryEvents.FormatTimeline()); + } + + this.Log( + $"Recovery phase=targeted-gate reached, timestamp={DateTime.UtcNow:O}. " + + TransactionRecoveryEventObserver.FormatTransition(transition).Trim()); + recoveryEvents.SetRelevantGrains(txGrains.Select(grain => grain.RuntimeGrainId)); + + TransactionRecoveryEventObserver.PhaseGate? cleanupGate = null; + Task? cleanupObservation = null; + if (requireParticipantConfirmation) + { + cleanupGate = recoveryEvents.GateNextTransition(candidate => + candidate.Sequence > transition.Sequence + && candidate.Kind == TransactionRecoveryEventObserver.RecoveryTransitionKind.TransactionConfirmCompleted + && candidate.TransactionId is { } transactionId + && transition.TransactionIds.Contains(transactionId) + && candidate.GrainId != transition.GrainId); + cleanupObservation = ObserveAndReleaseGateAsync(cleanupGate, GetDeadline(this.recoveryTimeout)); + } + + try + { + var siloToTerminate = this.testCluster.Silos.Single( + silo => silo.SiloAddress.Equals(transition.SiloAddress)); + var applicationLifetime = this.testCluster + .GetSiloServiceProvider(siloToTerminate.SiloAddress) + .GetRequiredService(); + var stopping = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + using var stoppingRegistration = applicationLifetime.ApplicationStopping.Register( + () => stopping.TrySetResult()); + var shutdown = this.testCluster.KillSiloAsync(siloToTerminate); + try + { + await stopping.Task.WaitAsync(this.failureDetectionTimeout); + phaseGate.Release(); + await shutdown.WaitAsync(this.recoveryTimeout); + } + catch (TimeoutException) + { + phaseGate.Release(); + shutdown.Ignore(); + throw; + } + + List[]? failedGroups; + try + { + failedGroups = await attempt.WaitAsync(this.failureDetectionTimeout); + } + catch (TimeoutException) + { + attempt.Ignore(); + throw new TimeoutException( + $"The transaction gated at {phase} did not settle within {this.failureDetectionTimeout}."); + } + + failedGroups.Should().NotBeNullOrEmpty( + $"terminating the activation blocked at {phase} must interrupt the gated transaction"); + var liveness = this.testCluster.WaitForLivenessToStabilizeAsync(didKill: true); + try + { + await liveness.WaitAsync(this.recoveryTimeout); + } + catch (TimeoutException) + { + liveness.Ignore(); + throw; + } + var recovery = await RecoverTransactions( + failedGroups!, + getIndex, + this.recoveryTimeout, + this.failureDetectionTimeout, + recoveryEvents); + recovery.Succeeded.Should().BeTrue( + $"the transaction path gated at {phase} should recover within {this.recoveryTimeout}"); + + if (cleanupObservation is not null) + { + var cleanup = await cleanupObservation; + cleanup.ActivationId.IsDefault.Should().BeFalse(); + cleanup.SiloAddress.Should().NotBeNull(); + } + + await ValidateResults(txGrains, transactionGroups); + } + finally + { + phaseGate.Release(); + cleanupObservation?.Ignore(); + cleanupGate?.Dispose(); + } + } + + private static async Task ObserveAndReleaseGateAsync( + TransactionRecoveryEventObserver.PhaseGate gate, + long deadline) + { + try + { + return await gate.WaitAsync(deadline); + } + finally + { + gate.Release(); + } + } + + private static long GetDeadline(TimeSpan timeout) + => Stopwatch.GetTimestamp() + (long)(timeout.TotalSeconds * Stopwatch.Frequency); + protected virtual async Task TransactionWillRecoverAfterRandomSiloFailure(string transactionTestGrainClassName, int concurrent, bool gracefulShutdown) { - var endOnCommand = new[] { false }; - var index = new[] { 0 }; - int getIndex() => index[0]++; + var index = 0; + int getIndex() => Interlocked.Increment(ref index) - 1; List txGrains = Enumerable.Range(0, concurrent * 2) .Select(i => Guid.NewGuid()) .Select(grainId => new ExpectedGrainActivity(grainId, TestGrain(transactionTestGrainClassName, grainId))) @@ -85,33 +295,170 @@ protected virtual async Task TransactionWillRecoverAfterRandomSiloFailure(string .GroupBy(v => v.index / 2) .Select(g => g.Select(i => i.value).ToList()) .ToArray(); + using var recoveryEvents = new TransactionRecoveryEventObserver(txGrains.Select(grain => grain.RuntimeGrainId)); var txSucceedBeforeInterruption = await AllTxSucceed(transactionGroups, getIndex()); txSucceedBeforeInterruption.Should().BeTrue(); await ValidateResults(txGrains, transactionGroups); // have transactions in flight when silo goes down - Task succeeding = RunWhileSucceeding(transactionGroups, getIndex, endOnCommand); - await Task.Delay(TimeSpan.FromSeconds(2)); + using var stopProducing = new CancellationTokenSource(); + var firstFailure = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var firstInFlightBatch = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + Task[]?> producer = RunWhileSucceeding( + transactionGroups, + getIndex, + stopProducing, + firstFailure, + firstInFlightBatch); + var inFlightBatch = await firstInFlightBatch.Task.WaitAsync(this.failureDetectionTimeout); + if (firstFailure.Task.IsCompleted) + { + stopProducing.Cancel(); + producer.Ignore(); + var prematureFailure = await firstFailure.Task; + throw new InvalidOperationException( + $"A transaction failed before the silo was terminated. Index: {prematureFailure.Index}. " + + $"Groups: {string.Join(":", prematureFailure.GrainIds)}. Exception: {prematureFailure.Exception.GetType().Name}."); + } + + var pendingAtShutdownRequest = inFlightBatch.PendingCount; + pendingAtShutdownRequest.Should().BeGreaterThan( + 0, + "the silo failure must overlap an incomplete mutating transaction batch"); var siloToTerminate = this.testCluster.Silos[Random.Shared.Next(this.testCluster.Silos.Count)]; - this.Log($"Warmup transaction succeeded. {(gracefulShutdown ? "Stopping" : "Killing")} silo {siloToTerminate.SiloAddress} ({siloToTerminate.Name}) and continuing"); + var shutdownMode = gracefulShutdown ? "graceful-stop" : "in-process-kill-shutdown"; + this.Log( + $"Recovery phase=silo-shutdown requested, timestamp={DateTime.UtcNow:O}. Silo={siloToTerminate.SiloAddress} " + + $"({siloToTerminate.Name}), mode={shutdownMode}. " + + $"inFlightIndex={inFlightBatch.Index}, pendingMutations={pendingAtShutdownRequest}. " + + "The in-process kill mode requests host shutdown through cancellation; it does not terminate a process."); + var shutdownStartedAt = Stopwatch.GetTimestamp(); if (gracefulShutdown) await this.testCluster.StopSiloAsync(siloToTerminate); else await this.testCluster.KillSiloAsync(siloToTerminate); + var shutdownElapsed = Stopwatch.GetElapsedTime(shutdownStartedAt); + this.Log( + $"Recovery phase=silo-shutdown completed, timestamp={DateTime.UtcNow:O}. Silo={siloToTerminate.SiloAddress}, " + + $"mode={shutdownMode}, elapsed={shutdownElapsed}."); this.Log("Waiting for transactions to stop completing successfully"); - var complete = await Task.WhenAny(succeeding, Task.Delay(TimeSpan.FromSeconds(30))); - endOnCommand[0] = true; - bool endedOnCommand = await succeeding; - if (endedOnCommand) this.Log($"No transactions failed due to silo death. Test may not be valid"); - - this.Log($"Waiting for system to recover. Performed {index[0]} transactions on each group."); - List[]?[] transactionGroupsRef = new[] { transactionGroups }; - await TestingUtils.WaitUntilAsync(lastTry => CheckTxResult(transactionGroupsRef, getIndex, lastTry), RecoveryTimeout, RetryDelay); - this.Log($"Recovery completed. Performed {index[0]} transactions on each group. Validating results."); + var failureDetectionStartedAt = Stopwatch.GetTimestamp(); + this.Log( + $"Recovery phase=failure-watchdog started. ClientResponseTimeout=" + + $"{this.clientResponseTimeout}, " + + $"schedulingMargin={FailureDetectionSchedulingMargin}, watchdog={this.failureDetectionTimeout}."); + var failureDetection = await TransactionRecoveryFailureObservation.DetectAsync( + producer, + firstFailure.Task, + stopProducing, + this.clientResponseTimeout, + FailureDetectionSchedulingMargin); + this.Log( + $"Recovery phase=failure-watchdog completed, timestamp={DateTime.UtcNow:O}. " + + $"Outcome={failureDetection.Kind}, elapsed={failureDetection.Elapsed}, " + + $"drainElapsed={failureDetection.DrainElapsed}, producerSettled={failureDetection.ProducerSettled}."); + + if (failureDetection.Kind == TransactionRecoveryFailureObservation.OutcomeKind.AttemptTimedOut) + { + throw new TimeoutException( + $"The in-flight transaction attempt did not settle within the {this.failureDetectionTimeout} " + + $"failure-detection deadline after silo death. Shutdown elapsed={shutdownElapsed}, " + + $"failure detection elapsed={failureDetection.Elapsed}, drain elapsed={failureDetection.DrainElapsed}. " + + $"Performed {Volatile.Read(ref index)} transactions on each group."); + } + + if (failureDetection.Kind == TransactionRecoveryFailureObservation.OutcomeKind.StoppedWithoutFailure) + { + throw new InvalidOperationException( + $"Transaction production stopped without observing a failure after silo death. " + + $"Shutdown elapsed={shutdownElapsed}, failure detection elapsed={failureDetection.Elapsed}. " + + $"Performed {Volatile.Read(ref index)} transactions on each group."); + } + + var interruption = failureDetection.Failure!; + if (!failureDetection.ProducerSettled) + { + throw new TimeoutException( + $"A transaction failure was observed at index {interruption.Index}, but the in-flight batch did not " + + $"settle within the {this.failureDetectionTimeout} absolute deadline. No recovery probe was started " + + $"while that state-mutating attempt remained active. Drain elapsed={failureDetection.DrainElapsed}."); + } + + var failedGroups = failureDetection.ProducerResult; + if (TransactionRecoveryFailureObservation.IsPremature(interruption.ObservedAt, shutdownStartedAt)) + { + throw new InvalidOperationException( + $"A transaction failed before silo shutdown began. Index: {interruption.Index}. " + + $"Groups: {string.Join(":", interruption.GrainIds)}. Exception: {interruption.Exception.GetType().Name}."); + } + + if (interruption.ObservedAt >= failureDetectionStartedAt + && Stopwatch.GetElapsedTime(failureDetectionStartedAt, interruption.ObservedAt) > this.failureDetectionTimeout) + { + throw new TimeoutException( + $"No transaction failure was observed within the {this.failureDetectionTimeout} watchdog after silo death. " + + $"The first later failure was at index {interruption.Index} after " + + $"{Stopwatch.GetElapsedTime(failureDetectionStartedAt, interruption.ObservedAt)}."); + } + + var firstFailureAfterShutdownRequest = Stopwatch.GetElapsedTime(shutdownStartedAt, interruption.ObservedAt); + var firstFailureRelativeToShutdownCompletion = Stopwatch.GetElapsedTime(failureDetectionStartedAt, interruption.ObservedAt); + this.Log( + $"Recovery phase=transaction-terminal-failure observed, timestamp={DateTime.UtcNow:O}. " + + $"Index={interruption.Index}, " + + $"grains={string.Join(":", interruption.GrainIds)}, " + + $"afterShutdownRequest={firstFailureAfterShutdownRequest}, " + + $"relativeToShutdownCompletion={firstFailureRelativeToShutdownCompletion}, " + + $"producerDrain={failureDetection.DrainElapsed}, " + + $"exception={interruption.Exception.GetType().Name}: {interruption.Exception.Message}."); + + failedGroups.Should().NotBeNullOrEmpty( + "the drained producer must identify the transaction groups affected by the observed failure"); + recoveryEvents.SetRelevantGrains(failedGroups!.SelectMany(group => group).Select(grain => grain.RuntimeGrainId)); + + var convergenceStartedAt = Stopwatch.GetTimestamp(); + this.Log( + $"Recovery phase=membership-directory-convergence started, timestamp={DateTime.UtcNow:O}, " + + $"failedGroups={FormatGroups(failedGroups)}."); + await this.testCluster.WaitForLivenessToStabilizeAsync(didKill: !gracefulShutdown); + var convergenceElapsed = Stopwatch.GetElapsedTime(convergenceStartedAt); + this.Log( + $"Recovery phase=membership-directory-convergence completed, timestamp={DateTime.UtcNow:O}, " + + $"elapsed={convergenceElapsed}, failedGroups={FormatGroups(failedGroups)}."); + + this.Log($"Waiting for system to recover. Performed {Volatile.Read(ref index)} transactions on each group."); + this.Log( + $"Recovery phase=transaction-path-watchdog started. " + + $"watchdog={this.recoveryTimeout}, failureDetection={this.failureDetectionTimeout}, " + + $"remotePingFrequency={TransactionalStateOptions.DefaultRemoteTransactionPingFrequency}."); + var recovery = await RecoverTransactions( + failedGroups, + getIndex, + this.recoveryTimeout, + this.failureDetectionTimeout, + recoveryEvents); + this.Log( + $"Recovery phase=transaction-path-probe completed, timestamp={DateTime.UtcNow:O}. Succeeded={recovery.Succeeded}, " + + $"lastProbeSucceeded={recovery.LastProbeSucceeded}, " + + $"attempts={recovery.Attempts}, remainingGroups={recovery.RemainingGroupCount}, " + + $"lastIndex={recovery.LastTransactionIndex}, elapsed={recovery.Elapsed}. " + + $"Performed {Volatile.Read(ref index)} transactions on each group."); + recovery.Succeeded.Should().BeTrue( + $"transactions should recover within {this.recoveryTimeout}; " + + $"the last probe succeeded={recovery.LastProbeSucceeded}, " + + $"remaining groups={recovery.RemainingGroupCount}, elapsed={recovery.Elapsed}"); + + this.Log( + $"Recovery phase=final-validation started, timestamp={DateTime.UtcNow:O}. " + + $"Performed {Volatile.Read(ref index)} transactions on each group."); + var validationStartedAt = Stopwatch.GetTimestamp(); await ValidateResults(txGrains, transactionGroups); + this.Log( + $"Recovery phase=final-validation completed, timestamp={DateTime.UtcNow:O}, " + + $"elapsed={Stopwatch.GetElapsedTime(validationStartedAt)}. Transaction results validated."); } private static Task WakeupGrains(List grains) @@ -124,51 +471,223 @@ private static Task WakeupGrains(List grains) return Task.WhenAll(tasks); } - private async Task RunWhileSucceeding(List[] transactionGroups, Func getIndex, bool[] end) + private async Task[]?> RunWhileSucceeding( + List[] transactionGroups, + Func getIndex, + CancellationTokenSource stopProducing, + TaskCompletionSource firstFailure, + TaskCompletionSource firstInFlightBatch) { - // Loop until failure, or getTime changes - while (await AllTxSucceed(transactionGroups, getIndex()) && !end[0]) + while (!stopProducing.IsCancellationRequested) { + var transactionIndex = getIndex(); + var failed = await RunAllTxReportFailed( + transactionGroups, + transactionIndex, + failure => + { + if (firstFailure.TrySetResult(failure)) + { + stopProducing.Cancel(); + } + }, + tasks => + { + var pendingCount = tasks.Count(task => !task.IsCompleted); + if (pendingCount > 0) + { + firstInFlightBatch.TrySetResult(new(transactionIndex, pendingCount)); + } + }); + + if (failed is not null) + { + return failed; + } } - return end[0]; + + return null; } - private async Task CheckTxResult(List[]?[] transactionGroupsRef, Func getIndex, bool assertIsTrue) + private async Task RecoverTransactions( + List[] transactionGroups, + Func getIndex, + TimeSpan timeout, + TimeSpan cleanupTimeout, + TransactionRecoveryEventObserver recoveryEvents) { - // only retry failed transactions - transactionGroupsRef[0] = await RunAllTxReportFailed(transactionGroupsRef[0]!, getIndex()); - bool succeed = transactionGroupsRef[0] == null; - this.Log($"All transactions succeed after interruption : {succeed}"); - if (assertIsTrue) - { - //consider it recovered if all tx succeed - this.Log($"Final check : {succeed}"); - succeed.Should().BeTrue(); - return succeed; - } - else + var startedAt = Stopwatch.GetTimestamp(); + var deadline = startedAt + (long)(timeout.TotalSeconds * Stopwatch.Frequency); + var remainingGroups = transactionGroups; + var attempts = 0; + var lastTransactionIndex = -1; + var waitForTransitionAfter = recoveryEvents.LatestRelevantSequence; + var timelineLogCursor = 0L; + var probeRequiresTransition = false; + + while (Stopwatch.GetTimestamp() < deadline) { - return succeed; + if (probeRequiresTransition) + { + var transition = await recoveryEvents.WaitForNextTransitionAsync(waitForTransitionAfter, deadline); + waitForTransitionAfter = transition.Sequence; + if (transition.Sequence > timelineLogCursor) + { + this.Log( + $"Recovery phase=transaction-event, timestamp={DateTime.UtcNow:O}. " + + TransactionRecoveryEventObserver.FormatTransition(transition).Trim()); + timelineLogCursor = transition.Sequence; + } + } + + if (Stopwatch.GetTimestamp() >= deadline) + { + break; + } + + lastTransactionIndex = getIndex(); + attempts++; + var attemptStartedAt = Stopwatch.GetTimestamp(); + var eventSequenceBeforeProbe = recoveryEvents.LatestRelevantSequence; + var groupsBeingProbed = remainingGroups; + this.Log( + $"Recovery phase=transaction-probe started, timestamp={DateTime.UtcNow:O}, " + + $"attempt={attempts}, index={lastTransactionIndex}, groups={FormatGroups(groupsBeingProbed)}."); + var probeTask = RunAllTxReportFailed(groupsBeingProbed, lastTransactionIndex); + List[]? failedGroups; + try + { + var now = Stopwatch.GetTimestamp(); + failedGroups = await probeTask.WaitAsync(Stopwatch.GetElapsedTime(now, deadline)); + } + catch (TimeoutException) + { + var cleanup = await Task.WhenAny(probeTask, Task.Delay(cleanupTimeout)); + var cleanupSettled = ReferenceEquals(cleanup, probeTask); + if (cleanupSettled) + { + await probeTask; + } + else + { + probeTask.Ignore(); + } + + throw new TimeoutException( + $"Transaction recovery probe {attempts} did not settle before the {timeout} watchdog. " + + $"Index={lastTransactionIndex}, groups={FormatGroups(groupsBeingProbed)}, " + + $"cleanupTimeout={cleanupTimeout}, cleanupSettled={cleanupSettled}." + + Environment.NewLine + + recoveryEvents.FormatTimeline()); + } + + var attemptElapsed = Stopwatch.GetElapsedTime(attemptStartedAt); + var elapsed = Stopwatch.GetElapsedTime(startedAt); + this.Log( + $"Recovery phase=transaction-probe completed, timestamp={DateTime.UtcNow:O}, " + + $"attempt={attempts}, index={lastTransactionIndex}, groups={FormatGroups(groupsBeingProbed)}, " + + $"succeeded={failedGroups is null}, attemptElapsed={attemptElapsed}, totalElapsed={elapsed}."); + LogNewTransitions(recoveryEvents, ref timelineLogCursor); + + if (failedGroups is null) + { + return new RecoveryResult( + elapsed < timeout, + true, + attempts, + 0, + lastTransactionIndex, + elapsed); + } + + remainingGroups = failedGroups; + recoveryEvents.SetRelevantGrains( + remainingGroups.SelectMany(group => group).Select(grain => grain.RuntimeGrainId)); + waitForTransitionAfter = eventSequenceBeforeProbe; + probeRequiresTransition = true; } + + LogNewTransitions(recoveryEvents, ref timelineLogCursor); + return new RecoveryResult( + false, + false, + attempts, + remainingGroups.Length, + lastTransactionIndex, + Stopwatch.GetElapsedTime(startedAt)); } // Runs all transactions and returns failed; - private async Task[]?> RunAllTxReportFailed(List[] transactionGroups, int index) + private async Task[]?> RunAllTxReportFailed( + List[] transactionGroups, + int index, + Action? onFailure = null, + Action>? onStarted = null) { - List tasks = transactionGroups - .Select(p => SetBit(p, index)) + var pending = transactionGroups + .Select(group => (Task: SetBit(group, index), Group: group)) .ToList(); - try + var failureObservers = onFailure is null + ? [] + : pending + .Select(item => TransactionRecoveryFailureObservation.ObserveAsync( + item.Task, + (exception, observedAt) => onFailure( + new TransactionFailure( + index, + item.Group.Select(activity => activity.GrainId).ToArray(), + exception, + observedAt)))) + .ToArray(); + onStarted?.Invoke(pending.Select(item => item.Task).ToArray()); + + var failedGroups = new List>(); + while (pending.Count > 0) + { + var completed = await Task.WhenAny(pending.Select(item => item.Task)); + var completedIndex = pending.FindIndex(item => ReferenceEquals(item.Task, completed)); + var transactionGroup = pending[completedIndex].Group; + pending.RemoveAt(completedIndex); + + try + { + await completed; + } + catch (Exception) + { + failedGroups.Add(transactionGroup); + } + } + await Task.WhenAll(failureObservers); + + if (failedGroups.Count == 0) { - await Task.WhenAll(tasks); return null; } - catch (Exception) + + var result = failedGroups.ToArray(); + this.Log( + $"Some transactions failed. Index: {index}. {result.Length} out of {transactionGroups.Length} failed. " + + $"Failed groups: {string.Join(", ", result.Select(transactionGroup => string.Join(":", transactionGroup.Select(a => a.GrainId))))}"); + return result; + } + + private static string FormatGroups(IEnumerable> groups) + => string.Join(",", groups.Select(group => $"[{string.Join(":", group.Select(grain => grain.GrainId))}]")); + + private void LogNewTransitions(TransactionRecoveryEventObserver observer, ref long cursor) + { + foreach (var transition in observer.GetTimeline()) { - // Collect the indices of the transaction groups which failed their transactions for diagnostics. - List[] failedGroups = tasks.Select((task, i) => new { task, i }).Where(t => t.task.IsFaulted).Select(t => transactionGroups[t.i]).ToArray(); - this.Log($"Some transactions failed. Index: {index}. {failedGroups.Length} out of {tasks.Count} failed. Failed groups: {string.Join(", ", failedGroups.Select(transactionGroup => string.Join(":", transactionGroup.Select(a => a.GrainId))))}"); - return failedGroups; + if (transition.Sequence <= cursor) + { + continue; + } + + this.Log( + $"Recovery phase=transaction-event, timestamp={DateTime.UtcNow:O}. " + + TransactionRecoveryEventObserver.FormatTransition(transition).Trim()); + cursor = transition.Sequence; } } @@ -191,7 +710,7 @@ private async Task SetBit(List grains, int index) } catch (OrleansTransactionAbortedException e) { - this.Log($"Some transactions failed. Index: {index}: Exception: {e.GetType().Name}"); + this.Log($"Some transactions failed. Index: {index}: Exception: {e.GetType().Name}: {e.Message}"); grains.ForEach(g => { g.Expected.Set(index, false); @@ -201,7 +720,7 @@ private async Task SetBit(List grains, int index) } catch (Exception e) { - this.Log($"Ambiguous transaction failure. Index: {index}: Exception: {e.GetType().Name}"); + this.Log($"Ambiguous transaction failure. Index: {index}: Exception: {e.GetType().Name}: {e.Message}"); grains.ForEach(g => { g.Expected.Set(index, false); diff --git a/src/Orleans.Transactions/Diagnostics/TransactionDiagnosticEvents.cs b/src/Orleans.Transactions/Diagnostics/TransactionDiagnosticEvents.cs index 30e92d73e72..c6f586ecb23 100644 --- a/src/Orleans.Transactions/Diagnostics/TransactionDiagnosticEvents.cs +++ b/src/Orleans.Transactions/Diagnostics/TransactionDiagnosticEvents.cs @@ -1,7 +1,9 @@ using System; using System.Collections.Generic; +using System.Collections.Immutable; using System.Diagnostics; using System.Runtime.CompilerServices; +using Orleans.Runtime; namespace Orleans.Transactions.Diagnostics; @@ -13,36 +15,1094 @@ internal static class TransactionDiagnosticEvents internal static IObservable AllEvents { get; } = new Observable(); + internal readonly struct TransactionDiagnosticIdentity(SiloAddress? siloAddress, ActivationId activationId) + { + public readonly SiloAddress? SiloAddress = siloAddress; + public readonly ActivationId ActivationId = activationId; + } + + internal enum TransactionProtocolRole + { + Unknown, + LocalTransactionManager, + RemoteParticipant, + } + + internal enum TransactionPhase + { + Unknown, + StorageWrite, + WaitingForRemotePrepares, + PreparedCallback, + PrepareTimeout, + RemotePreparePersisted, + RemotePreparedSent, + RecoveryPingScheduled, + RecoveryPingSent, + QueueRestore, + Lock, + StorageConflict, + AbortAndRestore, + Deactivation, + Cancel, + Confirm, + CancelFanOut, + AbortDecision, + ReadyWait, + } + internal abstract class TransactionDiagnosticEvent(ParticipantId resource) { public readonly ParticipantId Resource = resource; + public SiloAddress? SiloAddress { get; private set; } + public ActivationId ActivationId { get; private set; } + public TransactionProtocolRole ProtocolRole { get; private set; } + public TransactionPhase Phase { get; private set; } + + internal void SetContext( + TransactionDiagnosticIdentity identity, + TransactionProtocolRole protocolRole, + TransactionPhase phase) + { + SiloAddress = identity.SiloAddress; + ActivationId = identity.ActivationId; + ProtocolRole = protocolRole; + Phase = phase; + } } internal sealed class StorageWriteCompleted( ParticipantId resource, string? eTag, int batchSize, - int commitCount) : TransactionDiagnosticEvent(resource) + int commitCount, + ImmutableArray transactionIds) : TransactionDiagnosticEvent(resource) { public readonly string? ETag = eTag; public readonly int BatchSize = batchSize; public readonly int CommitCount = commitCount; + public readonly ImmutableArray TransactionIds = transactionIds; + } + + internal abstract class TransactionEvent( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp) : TransactionDiagnosticEvent(resource) + { + public readonly Guid TransactionId = transactionId; + public readonly DateTime TimeStamp = timeStamp; + } + + internal sealed class TransactionManagerWaitingForPrepared( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + int waitCount, + DateTime deadline) : TransactionEvent(resource, transactionId, timeStamp) + { + public readonly int WaitCount = waitCount; + public readonly DateTime Deadline = deadline; + } + + internal sealed class PreparedReceived( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId participant, + TransactionalStatus status, + int? remainingCount) : TransactionEvent(resource, transactionId, timeStamp) + { + public readonly ParticipantId Participant = participant; + public readonly TransactionalStatus Status = status; + public readonly int? RemainingCount = remainingCount; } - internal static void EmitStorageWriteCompleted(ParticipantId resource, string? eTag, int batchSize, int commitCount) + internal sealed class PrepareTimedOut( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + int remainingCount, + DateTime deadline) : TransactionEvent(resource, transactionId, timeStamp) + { + public readonly int RemainingCount = remainingCount; + public readonly DateTime Deadline = deadline; + } + + internal sealed class RemotePreparePersisted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId transactionManager) : TransactionEvent(resource, transactionId, timeStamp) + { + public readonly ParticipantId TransactionManager = transactionManager; + } + + internal sealed class RemotePreparedSent( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId transactionManager, + DateTime sentAt) : TransactionEvent(resource, transactionId, timeStamp) + { + public readonly ParticipantId TransactionManager = transactionManager; + public readonly DateTime SentAt = sentAt; + } + + internal sealed class RemoteRecoveryPingScheduled( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId transactionManager, + DateTime scheduledAt) : TransactionEvent(resource, transactionId, timeStamp) + { + public readonly ParticipantId TransactionManager = transactionManager; + public readonly DateTime ScheduledAt = scheduledAt; + } + + internal sealed class RemoteRecoveryPingSent( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId transactionManager, + DateTime sentAt) : TransactionEvent(resource, transactionId, timeStamp) + { + public readonly ParticipantId TransactionManager = transactionManager; + public readonly DateTime SentAt = sentAt; + } + + internal sealed class TransactionCancelCompleted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status, + bool queueEntryFound, + bool succeeded) : TransactionEvent(resource, transactionId, timeStamp) + { + public readonly TransactionalStatus Status = status; + public readonly bool QueueEntryFound = queueEntryFound; + public readonly bool Succeeded = succeeded; + } + + internal sealed class TransactionConfirmCompleted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status, + bool queueEntryFound, + bool succeeded) : TransactionEvent(resource, transactionId, timeStamp) + { + public readonly TransactionalStatus Status = status; + public readonly bool QueueEntryFound = queueEntryFound; + public readonly bool Succeeded = succeeded; + } + + internal sealed class TransactionManagerAbortDecisionCompleted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status) : TransactionEvent(resource, transactionId, timeStamp) + { + public readonly TransactionalStatus Status = status; + } + + internal sealed class QueueRestoreStarted( + ParticipantId resource, + ImmutableArray transactionIds) : TransactionDiagnosticEvent(resource) + { + public readonly ImmutableArray TransactionIds = transactionIds; + } + + internal sealed class QueueRestoreCompleted( + ParticipantId resource, + long committedSequence, + int recoveredPendingCount, + int recoveredCommitCount, + ImmutableArray transactionIds) : TransactionDiagnosticEvent(resource) + { + public readonly long CommittedSequence = committedSequence; + public readonly int RecoveredPendingCount = recoveredPendingCount; + public readonly int RecoveredCommitCount = recoveredCommitCount; + public readonly ImmutableArray TransactionIds = transactionIds; + } + + internal sealed class QueueRestoreFailed( + ParticipantId resource, + string exceptionType, + string exceptionMessage, + bool storageConflict, + ImmutableArray transactionIds) : TransactionDiagnosticEvent(resource) + { + public readonly string ExceptionType = exceptionType; + public readonly string ExceptionMessage = exceptionMessage; + public readonly bool StorageConflict = storageConflict; + public readonly ImmutableArray TransactionIds = transactionIds; + } + + internal sealed class LockExpired( + ParticipantId resource, + Guid transactionId, + DateTime deadline, + DateTime observedAt, + LockExpirationKind kind) : TransactionDiagnosticEvent(resource) + { + public readonly Guid TransactionId = transactionId; + public readonly DateTime Deadline = deadline; + public readonly DateTime ObservedAt = observedAt; + public readonly LockExpirationKind Kind = kind; + } + + internal enum LockExpirationKind + { + HeldLock, + QueuedWaiter, + } + + internal enum LockBreakReason + { + Conflict, + ValidationFailure, + Expired, + TransactionAbort, + StorageRecovery, + } + + internal sealed class LockBroken( + ParticipantId resource, + Guid transactionId, + LockBreakReason reason) : TransactionDiagnosticEvent(resource) + { + public readonly Guid TransactionId = transactionId; + public readonly LockBreakReason Reason = reason; + } + + internal enum StorageOperation + { + Load, + Store, + } + + internal sealed class StorageConflictDetected( + ParticipantId resource, + StorageOperation operation, + bool storageOutcomeInDoubt, + int queuedTransactionCount, + string exceptionType, + string exceptionMessage, + ImmutableArray transactionIds) : TransactionDiagnosticEvent(resource) + { + public readonly StorageOperation Operation = operation; + public readonly bool StorageOutcomeInDoubt = storageOutcomeInDoubt; + public readonly int QueuedTransactionCount = queuedTransactionCount; + public readonly string ExceptionType = exceptionType; + public readonly string ExceptionMessage = exceptionMessage; + public readonly ImmutableArray TransactionIds = transactionIds; + } + + internal sealed class AbortAndRestoreStarted( + ParticipantId resource, + TransactionalStatus status, + bool storageOutcomeInDoubt, + int queuedTransactionCount, + ImmutableArray transactionIds) : TransactionDiagnosticEvent(resource) + { + public readonly TransactionalStatus Status = status; + public readonly bool StorageOutcomeInDoubt = storageOutcomeInDoubt; + public readonly int QueuedTransactionCount = queuedTransactionCount; + public readonly ImmutableArray TransactionIds = transactionIds; + } + + internal sealed class AbortAndRestoreCompleted( + ParticipantId resource, + TransactionalStatus status, + bool storageOutcomeInDoubt, + ImmutableArray transactionIds) : TransactionDiagnosticEvent(resource) + { + public readonly TransactionalStatus Status = status; + public readonly bool StorageOutcomeInDoubt = storageOutcomeInDoubt; + public readonly ImmutableArray TransactionIds = transactionIds; + } + + internal sealed class DeactivationRequested( + ParticipantId resource, + TransactionalStatus status, + int failureCount, + ImmutableArray transactionIds) : TransactionDiagnosticEvent(resource) + { + public readonly TransactionalStatus Status = status; + public readonly int FailureCount = failureCount; + public readonly ImmutableArray TransactionIds = transactionIds; + } + + internal enum CancelReason + { + TransactionAbort, + RecoveryPing, + } + + internal abstract class CancelSendEvent( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId target, + bool isSelf, + TransactionalStatus status, + CancelReason reason) : TransactionEvent(resource, transactionId, timeStamp) + { + public readonly ParticipantId Target = target; + public readonly bool IsSelf = isSelf; + public readonly TransactionalStatus Status = status; + public readonly CancelReason Reason = reason; + } + + internal sealed class CancelSendStarted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId target, + bool isSelf, + TransactionalStatus status, + CancelReason reason) : CancelSendEvent(resource, transactionId, timeStamp, target, isSelf, status, reason); + + internal sealed class CancelSendCompleted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId target, + bool isSelf, + TransactionalStatus status, + CancelReason reason) : CancelSendEvent(resource, transactionId, timeStamp, target, isSelf, status, reason); + + internal sealed class CancelSendFailed( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId target, + bool isSelf, + TransactionalStatus status, + CancelReason reason, + string exceptionType, + string exceptionMessage) : CancelSendEvent(resource, transactionId, timeStamp, target, isSelf, status, reason) + { + public readonly string ExceptionType = exceptionType; + public readonly string ExceptionMessage = exceptionMessage; + } + + internal abstract class CancelFanOutEvent( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status, + int targetCount, + int selfTargetCount) : TransactionEvent(resource, transactionId, timeStamp) + { + public readonly TransactionalStatus Status = status; + public readonly int TargetCount = targetCount; + public readonly int SelfTargetCount = selfTargetCount; + } + + internal sealed class CancelFanOutStarted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status, + int targetCount, + int selfTargetCount) : CancelFanOutEvent(resource, transactionId, timeStamp, status, targetCount, selfTargetCount); + + internal sealed class CancelFanOutCompleted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status, + int targetCount, + int selfTargetCount, + TimeSpan duration) : CancelFanOutEvent(resource, transactionId, timeStamp, status, targetCount, selfTargetCount) + { + public readonly TimeSpan Duration = duration; + } + + internal sealed class CancelFanOutFailed( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status, + int targetCount, + int selfTargetCount, + TimeSpan duration, + string exceptionType, + string exceptionMessage) : CancelFanOutEvent(resource, transactionId, timeStamp, status, targetCount, selfTargetCount) + { + public readonly TimeSpan Duration = duration; + public readonly string ExceptionType = exceptionType; + public readonly string ExceptionMessage = exceptionMessage; + } + + internal abstract class ReadyWaitEvent( + ParticipantId resource, + Guid? transactionId) : TransactionDiagnosticEvent(resource) + { + public readonly Guid? TransactionId = transactionId; + } + + internal sealed class ReadyWaitStarted( + ParticipantId resource, + Guid? transactionId) : ReadyWaitEvent(resource, transactionId); + + internal sealed class ReadyWaitCompleted( + ParticipantId resource, + Guid? transactionId, + bool recoveredAfterFailure) : ReadyWaitEvent(resource, transactionId) + { + public readonly bool RecoveredAfterFailure = recoveredAfterFailure; + } + + internal sealed class ReadyWaitFailed( + ParticipantId resource, + Guid? transactionId, + string exceptionType, + string exceptionMessage) : ReadyWaitEvent(resource, transactionId) + { + public readonly string ExceptionType = exceptionType; + public readonly string ExceptionMessage = exceptionMessage; + } + + internal static void EmitStorageWriteCompleted( + ParticipantId resource, + string? eTag, + int batchSize, + int commitCount, + ImmutableArray transactionIds, + TransactionDiagnosticIdentity identity = default) { if (!Listener.IsEnabled(nameof(StorageWriteCompleted))) { return; } - Emit(resource, eTag, batchSize, commitCount); + Emit(resource, eTag, batchSize, commitCount, transactionIds, identity); [MethodImpl(MethodImplOptions.NoInlining)] - static void Emit(ParticipantId resource, string? eTag, int batchSize, int commitCount) + static void Emit( + ParticipantId resource, + string? eTag, + int batchSize, + int commitCount, + ImmutableArray transactionIds, + TransactionDiagnosticIdentity identity) { // Observer exceptions intentionally propagate so tests can inject post-write faults. - Listener.Write(nameof(StorageWriteCompleted), new StorageWriteCompleted(resource, eTag, batchSize, commitCount)); + var evt = new StorageWriteCompleted(resource, eTag, batchSize, commitCount, transactionIds); + evt.SetContext(identity, TransactionProtocolRole.Unknown, TransactionPhase.StorageWrite); + Listener.Write(nameof(StorageWriteCompleted), evt); + } + } + + internal static void EmitTransactionManagerWaitingForPrepared( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + int waitCount, + DateTime deadline, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(TransactionManagerWaitingForPrepared))) + { + Write( + nameof(TransactionManagerWaitingForPrepared), + new TransactionManagerWaitingForPrepared(resource, transactionId, timeStamp, waitCount, deadline), + identity, + TransactionProtocolRole.LocalTransactionManager, + TransactionPhase.WaitingForRemotePrepares); + } + } + + internal static void EmitPreparedReceived( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId participant, + TransactionalStatus status, + int? remainingCount, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(PreparedReceived))) + { + Write( + nameof(PreparedReceived), + new PreparedReceived(resource, transactionId, timeStamp, participant, status, remainingCount), + identity, + TransactionProtocolRole.LocalTransactionManager, + TransactionPhase.PreparedCallback); + } + } + + internal static void EmitPrepareTimedOut( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + int remainingCount, + DateTime deadline, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(PrepareTimedOut))) + { + Write( + nameof(PrepareTimedOut), + new PrepareTimedOut(resource, transactionId, timeStamp, remainingCount, deadline), + identity, + TransactionProtocolRole.LocalTransactionManager, + TransactionPhase.PrepareTimeout); + } + } + + internal static void EmitRemotePreparePersisted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId transactionManager, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(RemotePreparePersisted))) + { + Write( + nameof(RemotePreparePersisted), + new RemotePreparePersisted(resource, transactionId, timeStamp, transactionManager), + identity, + TransactionProtocolRole.RemoteParticipant, + TransactionPhase.RemotePreparePersisted); + } + } + + internal static void EmitRemotePreparedSent( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId transactionManager, + DateTime sentAt, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(RemotePreparedSent))) + { + Write( + nameof(RemotePreparedSent), + new RemotePreparedSent(resource, transactionId, timeStamp, transactionManager, sentAt), + identity, + TransactionProtocolRole.RemoteParticipant, + TransactionPhase.RemotePreparedSent); + } + } + + internal static void EmitRemoteRecoveryPingScheduled( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId transactionManager, + DateTime scheduledAt, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(RemoteRecoveryPingScheduled))) + { + Write( + nameof(RemoteRecoveryPingScheduled), + new RemoteRecoveryPingScheduled(resource, transactionId, timeStamp, transactionManager, scheduledAt), + identity, + TransactionProtocolRole.RemoteParticipant, + TransactionPhase.RecoveryPingScheduled); + } + } + + internal static void EmitRemoteRecoveryPingSent( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId transactionManager, + DateTime sentAt, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(RemoteRecoveryPingSent))) + { + Write( + nameof(RemoteRecoveryPingSent), + new RemoteRecoveryPingSent(resource, transactionId, timeStamp, transactionManager, sentAt), + identity, + TransactionProtocolRole.RemoteParticipant, + TransactionPhase.RecoveryPingSent); + } + } + + internal static void EmitTransactionCancelCompleted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status, + bool queueEntryFound, + bool succeeded, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(TransactionCancelCompleted))) + { + Write( + nameof(TransactionCancelCompleted), + new TransactionCancelCompleted(resource, transactionId, timeStamp, status, queueEntryFound, succeeded), + identity, + TransactionProtocolRole.RemoteParticipant, + TransactionPhase.Cancel); + } + } + + internal static void EmitTransactionConfirmCompleted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status, + bool queueEntryFound, + bool succeeded, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(TransactionConfirmCompleted))) + { + Write( + nameof(TransactionConfirmCompleted), + new TransactionConfirmCompleted(resource, transactionId, timeStamp, status, queueEntryFound, succeeded), + identity, + TransactionProtocolRole.RemoteParticipant, + TransactionPhase.Confirm); + } + } + + internal static void EmitTransactionManagerAbortDecisionCompleted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(TransactionManagerAbortDecisionCompleted))) + { + Write( + nameof(TransactionManagerAbortDecisionCompleted), + new TransactionManagerAbortDecisionCompleted(resource, transactionId, timeStamp, status), + identity, + TransactionProtocolRole.LocalTransactionManager, + TransactionPhase.AbortDecision); + } + } + + internal static void EmitQueueRestoreStarted( + ParticipantId resource, + ImmutableArray transactionIds, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(QueueRestoreStarted))) + { + Write( + nameof(QueueRestoreStarted), + new QueueRestoreStarted(resource, transactionIds), + identity, + TransactionProtocolRole.Unknown, + TransactionPhase.QueueRestore); + } + } + + internal static void EmitQueueRestoreCompleted( + ParticipantId resource, + long committedSequence, + int recoveredPendingCount, + int recoveredCommitCount, + ImmutableArray transactionIds, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(QueueRestoreCompleted))) + { + Write( + nameof(QueueRestoreCompleted), + new QueueRestoreCompleted( + resource, + committedSequence, + recoveredPendingCount, + recoveredCommitCount, + transactionIds), + identity, + TransactionProtocolRole.Unknown, + TransactionPhase.QueueRestore); + } + } + + internal static void EmitQueueRestoreFailed( + ParticipantId resource, + Exception exception, + bool storageConflict, + ImmutableArray transactionIds, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(QueueRestoreFailed))) + { + Write( + nameof(QueueRestoreFailed), + new QueueRestoreFailed( + resource, + exception.GetType().FullName ?? exception.GetType().Name, + exception.Message, + storageConflict, + transactionIds), + identity, + TransactionProtocolRole.Unknown, + TransactionPhase.QueueRestore); + } + } + + internal static void EmitLockExpired( + ParticipantId resource, + Guid transactionId, + DateTime deadline, + DateTime observedAt, + LockExpirationKind kind, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(LockExpired))) + { + Write( + nameof(LockExpired), + new LockExpired(resource, transactionId, deadline, observedAt, kind), + identity, + TransactionProtocolRole.Unknown, + TransactionPhase.Lock); + } + } + + internal static void EmitLockBroken( + ParticipantId resource, + Guid transactionId, + LockBreakReason reason, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(LockBroken))) + { + Write( + nameof(LockBroken), + new LockBroken(resource, transactionId, reason), + identity, + TransactionProtocolRole.Unknown, + TransactionPhase.Lock); + } + } + + internal static void EmitStorageConflictDetected( + ParticipantId resource, + StorageOperation operation, + bool storageOutcomeInDoubt, + int queuedTransactionCount, + Exception exception, + ImmutableArray transactionIds, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(StorageConflictDetected))) + { + Write( + nameof(StorageConflictDetected), + new StorageConflictDetected( + resource, + operation, + storageOutcomeInDoubt, + queuedTransactionCount, + exception.GetType().FullName ?? exception.GetType().Name, + exception.Message, + transactionIds), + identity, + TransactionProtocolRole.Unknown, + TransactionPhase.StorageConflict); + } + } + + internal static void EmitAbortAndRestoreStarted( + ParticipantId resource, + TransactionalStatus status, + bool storageOutcomeInDoubt, + int queuedTransactionCount, + ImmutableArray transactionIds, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(AbortAndRestoreStarted))) + { + Write( + nameof(AbortAndRestoreStarted), + new AbortAndRestoreStarted(resource, status, storageOutcomeInDoubt, queuedTransactionCount, transactionIds), + identity, + TransactionProtocolRole.Unknown, + TransactionPhase.AbortAndRestore); + } + } + + internal static void EmitAbortAndRestoreCompleted( + ParticipantId resource, + TransactionalStatus status, + bool storageOutcomeInDoubt, + ImmutableArray transactionIds, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(AbortAndRestoreCompleted))) + { + Write( + nameof(AbortAndRestoreCompleted), + new AbortAndRestoreCompleted(resource, status, storageOutcomeInDoubt, transactionIds), + identity, + TransactionProtocolRole.Unknown, + TransactionPhase.AbortAndRestore); + } + } + + internal static void EmitDeactivationRequested( + ParticipantId resource, + TransactionalStatus status, + int failureCount, + ImmutableArray transactionIds, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(DeactivationRequested))) + { + Write( + nameof(DeactivationRequested), + new DeactivationRequested(resource, status, failureCount, transactionIds), + identity, + TransactionProtocolRole.Unknown, + TransactionPhase.Deactivation); + } + } + + internal static void EmitCancelSendStarted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId target, + bool isSelf, + TransactionalStatus status, + CancelReason reason, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(CancelSendStarted))) + { + Write( + nameof(CancelSendStarted), + new CancelSendStarted(resource, transactionId, timeStamp, target, isSelf, status, reason), + identity, + TransactionProtocolRole.LocalTransactionManager, + TransactionPhase.Cancel); + } + } + + internal static void EmitCancelSendCompleted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId target, + bool isSelf, + TransactionalStatus status, + CancelReason reason, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(CancelSendCompleted))) + { + Write( + nameof(CancelSendCompleted), + new CancelSendCompleted(resource, transactionId, timeStamp, target, isSelf, status, reason), + identity, + TransactionProtocolRole.LocalTransactionManager, + TransactionPhase.Cancel); + } + } + + internal static void EmitCancelSendFailed( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + ParticipantId target, + bool isSelf, + TransactionalStatus status, + CancelReason reason, + Exception exception, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(CancelSendFailed))) + { + Write( + nameof(CancelSendFailed), + new CancelSendFailed( + resource, + transactionId, + timeStamp, + target, + isSelf, + status, + reason, + exception.GetType().FullName ?? exception.GetType().Name, + exception.Message), + identity, + TransactionProtocolRole.LocalTransactionManager, + TransactionPhase.Cancel); + } + } + + internal static void EmitCancelFanOutStarted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status, + int targetCount, + int selfTargetCount, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(CancelFanOutStarted))) + { + Write( + nameof(CancelFanOutStarted), + new CancelFanOutStarted(resource, transactionId, timeStamp, status, targetCount, selfTargetCount), + identity, + TransactionProtocolRole.LocalTransactionManager, + TransactionPhase.CancelFanOut); + } + } + + internal static void EmitCancelFanOutCompleted( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status, + int targetCount, + int selfTargetCount, + TimeSpan duration, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(CancelFanOutCompleted))) + { + Write( + nameof(CancelFanOutCompleted), + new CancelFanOutCompleted( + resource, + transactionId, + timeStamp, + status, + targetCount, + selfTargetCount, + duration), + identity, + TransactionProtocolRole.LocalTransactionManager, + TransactionPhase.CancelFanOut); + } + } + + internal static void EmitCancelFanOutFailed( + ParticipantId resource, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status, + int targetCount, + int selfTargetCount, + TimeSpan duration, + Exception exception, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(CancelFanOutFailed))) + { + Write( + nameof(CancelFanOutFailed), + new CancelFanOutFailed( + resource, + transactionId, + timeStamp, + status, + targetCount, + selfTargetCount, + duration, + exception.GetType().FullName ?? exception.GetType().Name, + exception.Message), + identity, + TransactionProtocolRole.LocalTransactionManager, + TransactionPhase.CancelFanOut); + } + } + + internal static void EmitReadyWaitStarted( + ParticipantId resource, + Guid? transactionId, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(ReadyWaitStarted))) + { + Write( + nameof(ReadyWaitStarted), + new ReadyWaitStarted(resource, transactionId), + identity, + TransactionProtocolRole.Unknown, + TransactionPhase.ReadyWait); + } + } + + internal static void EmitReadyWaitCompleted( + ParticipantId resource, + Guid? transactionId, + bool recoveredAfterFailure, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(ReadyWaitCompleted))) + { + Write( + nameof(ReadyWaitCompleted), + new ReadyWaitCompleted(resource, transactionId, recoveredAfterFailure), + identity, + TransactionProtocolRole.Unknown, + TransactionPhase.ReadyWait); + } + } + + internal static void EmitReadyWaitFailed( + ParticipantId resource, + Guid? transactionId, + Exception exception, + TransactionDiagnosticIdentity identity = default) + { + if (IsEnabled(nameof(ReadyWaitFailed))) + { + Write( + nameof(ReadyWaitFailed), + new ReadyWaitFailed( + resource, + transactionId, + exception.GetType().FullName ?? exception.GetType().Name, + exception.Message), + identity, + TransactionProtocolRole.Unknown, + TransactionPhase.ReadyWait); + } + } + + internal static bool IsEnabled(string eventName) + { + try + { + return Listener.IsEnabled(eventName); + } + catch + { + // Recovery diagnostics are observational and must not affect transaction processing. + return false; + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + private static void Write( + string eventName, + TransactionDiagnosticEvent evt, + TransactionDiagnosticIdentity identity, + TransactionProtocolRole protocolRole, + TransactionPhase phase) + { + try + { + evt.SetContext(identity, protocolRole, phase); + Listener.Write(eventName, evt); + } + catch (Exception) + { + // Recovery diagnostics are observational. StorageWriteCompleted remains the sole fault-injection event. } } diff --git a/src/Orleans.Transactions/DistributedTM/TransactionAgent.cs b/src/Orleans.Transactions/DistributedTM/TransactionAgent.cs index 398467c1145..0295e1a5460 100644 --- a/src/Orleans.Transactions/DistributedTM/TransactionAgent.cs +++ b/src/Orleans.Transactions/DistributedTM/TransactionAgent.cs @@ -15,13 +15,25 @@ internal partial class TransactionAgent : ITransactionAgent private readonly CausalClock clock; private readonly ITransactionAgentStatistics statistics; private readonly ITransactionOverloadDetector overloadDetector; + private readonly ITransactionAgentProtocol protocol; public TransactionAgent(IClock clock, ILogger logger, ITransactionAgentStatistics statistics, ITransactionOverloadDetector overloadDetector) + : this(clock, logger, statistics, overloadDetector, TransactionAgentProtocol.Instance) + { + } + + internal TransactionAgent( + IClock clock, + ILogger logger, + ITransactionAgentStatistics statistics, + ITransactionOverloadDetector overloadDetector, + ITransactionAgentProtocol protocol) { this.clock = new CausalClock(clock); this.logger = logger; this.statistics = statistics; this.overloadDetector = overloadDetector; + this.protocol = protocol; } public Task StartTransaction(bool readOnly, TimeSpan timeout) @@ -140,6 +152,7 @@ await Task.WhenAll(resources.Select(r => r.Key.Reference.AsReference r.Key.Reference.AsReference() - .Prepare(p.Key.Name, transactionInfo.TransactionId, p.Value, transactionInfo.TimeStamp, manager.Key) - .Ignore(); + protocol.Prepare( + p.Key, + transactionInfo.TransactionId, + p.Value, + transactionInfo.TimeStamp, + manager.Key); } // wait for the TM to commit the transaction - status = await manager.Key.Reference.AsReference() - .PrepareAndCommit(manager.Key.Name, transactionInfo.TransactionId, manager.Value, transactionInfo.TimeStamp, writeResources, resources.Count); + status = await protocol.PrepareAndCommit( + manager.Key, + transactionInfo.TransactionId, + manager.Value, + transactionInfo.TimeStamp, + writeResources, + resources.Count); + cancelNotificationOwner = CancelNotificationOwner.TransactionManager; exception = null; } catch (TimeoutException ex) @@ -178,13 +200,12 @@ await Task.WhenAll(resources.Select(r => r.Key.Reference.AsReference !p.Equals(manager.Key)) - .Select(p => p.Reference.AsReference() - .Cancel(p.Name, transactionInfo.TransactionId, transactionInfo.TimeStamp, status))); + .Select(p => protocol.Cancel(p, transactionInfo.TransactionId, transactionInfo.TimeStamp, status))); } } catch (Exception ex) @@ -198,6 +219,12 @@ await Task.WhenAll(writeResources return (status, exception); } + private enum CancelNotificationOwner + { + TransactionAgent, + TransactionManager, + } + public async Task Abort(TransactionInfo transactionInfo) { this.statistics.TrackTransactionFailed(); @@ -369,4 +396,67 @@ private readonly struct ParticipantsLogRecord(List participants) )] private partial void LogTraceAbortTransaction(TransactionInfo transactionInfo, ParticipantsLogRecord participants); } + + internal interface ITransactionAgentProtocol + { + void Prepare( + ParticipantId participant, + Guid transactionId, + AccessCounter accessCount, + DateTime timeStamp, + ParticipantId transactionManager); + + Task PrepareAndCommit( + ParticipantId transactionManager, + Guid transactionId, + AccessCounter accessCount, + DateTime timeStamp, + List writeResources, + int totalParticipants); + + Task Cancel( + ParticipantId participant, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status); + } + + internal sealed class TransactionAgentProtocol : ITransactionAgentProtocol + { + public static TransactionAgentProtocol Instance { get; } = new(); + + public void Prepare( + ParticipantId participant, + Guid transactionId, + AccessCounter accessCount, + DateTime timeStamp, + ParticipantId transactionManager) + => participant.Reference.AsReference() + .Prepare(participant.Name, transactionId, accessCount, timeStamp, transactionManager) + .Ignore(); + + public Task PrepareAndCommit( + ParticipantId transactionManager, + Guid transactionId, + AccessCounter accessCount, + DateTime timeStamp, + List writeResources, + int totalParticipants) + => transactionManager.Reference.AsReference() + .PrepareAndCommit( + transactionManager.Name, + transactionId, + accessCount, + timeStamp, + writeResources, + totalParticipants); + + public Task Cancel( + ParticipantId participant, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status) + => participant.Reference.AsReference() + .Cancel(participant.Name, transactionId, timeStamp, status); + } } diff --git a/src/Orleans.Transactions/DistributedTM/TransactionRecord.cs b/src/Orleans.Transactions/DistributedTM/TransactionRecord.cs index 3ba6b342be4..0c6768005b7 100644 --- a/src/Orleans.Transactions/DistributedTM/TransactionRecord.cs +++ b/src/Orleans.Transactions/DistributedTM/TransactionRecord.cs @@ -74,9 +74,41 @@ public void AddWrite() // used for remote commit public DateTime? LastSent; + public bool IsRestoredRemoteCommit; + public int RecoveryPingCount; public bool PrepareIsPersisted; public TaskCompletionSource? ConfirmationResponsePromise; + internal DateTime GetNextRemotePingAt(TimeSpan pingFrequency) + { + if (IsRestoredRemoteCommit && RecoveryPingCount == 0) + { + return DateTime.MinValue; + } + + return LastSent!.Value + GetRemotePingDelay(pingFrequency); + } + + internal void RecordRemotePingSent(DateTime sentAt) + { + LastSent = sentAt; + if (RecoveryPingCount < int.MaxValue) + { + RecoveryPingCount++; + } + } + + private TimeSpan GetRemotePingDelay(TimeSpan pingFrequency) + { + if (RecoveryPingCount == 0) + { + return pingFrequency; + } + + var exponent = Math.Min(RecoveryPingCount - 1, 30); + var retryDelayTicks = TimeSpan.TicksPerSecond << exponent; + return TimeSpan.FromTicks(Math.Min(retryDelayTicks, pingFrequency.Ticks)); + } /// /// Indicates whether a transaction record is ready to commit diff --git a/src/Orleans.Transactions/State/ReaderWriterLock.cs b/src/Orleans.Transactions/State/ReaderWriterLock.cs index eed6439d698..37efb8f6ccd 100644 --- a/src/Orleans.Transactions/State/ReaderWriterLock.cs +++ b/src/Orleans.Transactions/State/ReaderWriterLock.cs @@ -7,6 +7,7 @@ using Microsoft.Extensions.Options; using Orleans.Configuration; using Orleans.Transactions.Abstractions; +using Orleans.Transactions.Diagnostics; namespace Orleans.Transactions.State { @@ -65,7 +66,7 @@ public async Task EnterLock(Guid transactionId, DateTime prior bool rollbacksOccurred = false; List cleanup = new List(); - await this.queue.Ready(); + await this.queue.Ready(transactionId); // search active transactions if (Find(transactionId, isRead && !exclusiveLock, out var group, out var record)) @@ -92,7 +93,7 @@ public async Task EnterLock(Guid transactionId, DateTime prior { foreach (var r in conflicts) { - cleanup.Add(Rollback(r, true)); + cleanup.Add(Rollback(r, true, TransactionDiagnosticEvents.LockBreakReason.Conflict)); rollbacksOccurred = true; } } @@ -196,7 +197,7 @@ void completion() else if (record.NumberReads != accessCount.Reads || record.NumberWrites != accessCount.Writes) { - await Rollback(transactionId, true); + await Rollback(transactionId, true, TransactionDiagnosticEvents.LockBreakReason.ValidationFailure); return (TransactionalStatus.LockValidationFailed, record); } else @@ -215,20 +216,31 @@ public bool TryGetRecord(Guid transactionId, [NotNullWhen(true)] out Transaction return this.currentGroup!.TryGetValue(transactionId, out record); } - public Task AbortExecutingTransactions(Exception? exception) + public Task AbortExecutingTransactions( + Exception? exception, + TransactionDiagnosticEvents.LockBreakReason reason = TransactionDiagnosticEvents.LockBreakReason.TransactionAbort) { if (currentGroup != null) { - Task[] pending = currentGroup.Select(g => BreakLock(g.Key, g.Value, exception)).ToArray(); + Task[] pending = currentGroup.Select(g => BreakLock(g.Key, g.Value, exception, reason)).ToArray(); currentGroup.Reset(); return Task.WhenAll(pending); } return Task.CompletedTask; } - private Task BreakLock(Guid transactionId, TransactionRecord entry, Exception? exception) + private Task BreakLock( + Guid transactionId, + TransactionRecord entry, + Exception? exception, + TransactionDiagnosticEvents.LockBreakReason reason) { LogTraceBreakLock(transactionId); + TransactionDiagnosticEvents.EmitLockBroken( + queue.Resource, + transactionId, + reason, + queue.DiagnosticIdentity); return this.queue.NotifyOfAbort(entry, TransactionalStatus.BrokenLock, exception); } @@ -254,7 +266,7 @@ public void AbortQueuedTransactions() public void Rollback(Guid guid) => currentGroup?.Remove(guid); - public Task Rollback(Guid guid, bool notify) + public Task Rollback(Guid guid, bool notify, TransactionDiagnosticEvents.LockBreakReason reason) { // no-op if the transaction never happened or already rolled back if (currentGroup == null || !currentGroup.Remove(guid, out var record)) @@ -263,7 +275,17 @@ public Task Rollback(Guid guid, bool notify) } // notify remote listeners - return notify ? queue.NotifyOfAbort(record, TransactionalStatus.BrokenLock, exception: null) : Task.CompletedTask; + if (!notify) + { + return Task.CompletedTask; + } + + TransactionDiagnosticEvents.EmitLockBroken( + queue.Resource, + guid, + reason, + queue.DiagnosticIdentity); + return queue.NotifyOfAbort(record, TransactionalStatus.BrokenLock, exception: null); } private async Task LockWork() @@ -304,7 +326,19 @@ private async Task LockWork() // the lock group has timed out. TimeSpan late = now - currentGroup.Deadline.Value; LogTraceBreakLockTimeout(new(currentGroup.Keys), Math.Floor(late.TotalMilliseconds)); - await AbortExecutingTransactions(exception: null); + foreach (var transactionId in currentGroup.Keys) + { + TransactionDiagnosticEvents.EmitLockExpired( + queue.Resource, + transactionId, + currentGroup.Deadline.Value, + now, + TransactionDiagnosticEvents.LockExpirationKind.HeldLock, + queue.DiagnosticIdentity); + } + await AbortExecutingTransactions( + exception: null, + reason: TransactionDiagnosticEvents.LockBreakReason.Expired); lockWorker.Notify(); } else @@ -337,6 +371,13 @@ private async Task LockWork() { if (now > kvp.Value.Deadline) { + TransactionDiagnosticEvents.EmitLockExpired( + queue.Resource, + kvp.Key, + kvp.Value.Deadline, + now, + TransactionDiagnosticEvents.LockExpirationKind.QueuedWaiter, + queue.DiagnosticIdentity); currentGroup.Remove(kvp.Key); LogTraceExpireLockWaiter(kvp.Key); } diff --git a/src/Orleans.Transactions/State/StorageBatch.cs b/src/Orleans.Transactions/State/StorageBatch.cs index 699cbf5fc97..cd468a5d996 100644 --- a/src/Orleans.Transactions/State/StorageBatch.cs +++ b/src/Orleans.Transactions/State/StorageBatch.cs @@ -1,5 +1,6 @@ using System; using System.Collections.Generic; +using System.Collections.Immutable; using System.Linq; using System.Threading; using System.Threading.Tasks; @@ -39,6 +40,7 @@ internal class StorageBatch : ITransactionalStateStorageEvents // prepare records private readonly SortedDictionary> prepares; + private readonly List committedTransactionIds; // follow-up actions, to be executed when this batch completes private readonly List> followUpActions; @@ -62,6 +64,8 @@ internal class StorageBatch : ITransactionalStateStorageEvents public int CommitCount => commit; + public ImmutableArray CommittedTransactionIds => [.. committedTransactionIds]; + public override string ToString() { return $"batchsize={total} [{read}r {prepare}p {commit}c {confirm}cf {collect}cl {cancel}cc]"; @@ -77,6 +81,7 @@ public StorageBatch(TransactionalStateMetaData metaData, string? etag, long conf this.followUpActions = new List>(); this.storeConditions = new List>>(); this.prepares = new SortedDictionary>(); + this.committedTransactionIds = new List(); } public StorageBatch(StorageBatch previous) @@ -185,6 +190,7 @@ public void Commit(Guid transactionId, DateTime timestamp, List W { commit++; total++; + committedTransactionIds.Add(transactionId); MetaData.CommitRecords.Add(transactionId, new CommitRecord() { diff --git a/src/Orleans.Transactions/State/TransactionManager.cs b/src/Orleans.Transactions/State/TransactionManager.cs index 2bf2c1f9e05..02a08829975 100644 --- a/src/Orleans.Transactions/State/TransactionManager.cs +++ b/src/Orleans.Transactions/State/TransactionManager.cs @@ -2,6 +2,7 @@ using System.Collections.Generic; using System.Threading.Tasks; using Orleans.Transactions.Abstractions; +using Orleans.Transactions.Diagnostics; namespace Orleans.Transactions.State { @@ -35,6 +36,16 @@ public async Task PrepareAndCommit(Guid transactionId, Acce else { this.queue.Clock.Merge(record.Timestamp); + if (record.WaitCount > 0) + { + TransactionDiagnosticEvents.EmitTransactionManagerWaitingForPrepared( + this.queue.Resource, + transactionId, + timeStamp, + record.WaitCount, + record.WaitingSince + this.queue.PrepareTimeout, + this.queue.DiagnosticIdentity); + } } this.queue.RWLock.Notify(); @@ -43,12 +54,12 @@ public async Task PrepareAndCommit(Guid transactionId, Acce public Task Prepared(Guid transactionId, DateTime timeStamp, ParticipantId resource, TransactionalStatus status) { - return this.queue.NotifyOfPrepared(transactionId, timeStamp, status); + return this.queue.NotifyOfPrepared(transactionId, timeStamp, resource, status); } public async Task Ping(Guid transactionId, DateTime timeStamp, ParticipantId resource) { - await this.queue.Ready(); + await this.queue.Ready(transactionId); await this.queue.NotifyOfPing(transactionId, timeStamp, resource); } } diff --git a/src/Orleans.Transactions/State/TransactionQueue.cs b/src/Orleans.Transactions/State/TransactionQueue.cs index 75bb342b1e0..ce0107c8639 100644 --- a/src/Orleans.Transactions/State/TransactionQueue.cs +++ b/src/Orleans.Transactions/State/TransactionQueue.cs @@ -1,5 +1,7 @@ using System; using System.Collections.Generic; +using System.Collections.Immutable; +using System.Diagnostics; using System.Linq; using System.Threading.Tasks; using Microsoft.Extensions.Logging; @@ -24,6 +26,7 @@ internal partial class TransactionQueue protected readonly ILogger logger; private readonly IActivationLifetime activationLifetime; private readonly ConfirmationWorker confirmationWorker; + private readonly TransactionDiagnosticEvents.TransactionDiagnosticIdentity diagnosticIdentity; private CommitQueue commitQueue; private Task readyTask; @@ -47,6 +50,9 @@ public PreparedMessages(TransactionalStatus status) private long stableSequenceNumber; public ReadWriteLock RWLock { get; } public CausalClock Clock { get; } + internal ParticipantId Resource => resource; + internal TimeSpan PrepareTimeout => options.PrepareTimeout; + internal TransactionDiagnosticEvents.TransactionDiagnosticIdentity DiagnosticIdentity => diagnosticIdentity; public TransactionQueue( IOptions options, @@ -56,7 +62,8 @@ public TransactionQueue( IClock clock, ILogger logger, ITimerManager timerManager, - IActivationLifetime activationLifetime) + IActivationLifetime activationLifetime, + TransactionDiagnosticEvents.TransactionDiagnosticIdentity diagnosticIdentity) { this.options = options.Value; this.resource = resource; @@ -65,6 +72,7 @@ public TransactionQueue( this.Clock = new CausalClock(clock); this.logger = logger; this.activationLifetime = activationLifetime; + this.diagnosticIdentity = diagnosticIdentity; this.storageWorker = new BatchWorkerFromDelegate(StorageWork, this.activationLifetime.OnDeactivating); this.RWLock = new ReadWriteLock(options, this, this.storageWorker, logger, activationLifetime); this.confirmationWorker = new ConfirmationWorker(options, this.resource, this.storageWorker, () => this.storageBatch, this.logger, timerManager, activationLifetime); @@ -139,6 +147,12 @@ public async Task EnqueueCommit(TransactionRecord record) LogTracePersisted(record); record.PrepareIsPersisted = true; + TransactionDiagnosticEvents.EmitRemotePreparePersisted( + resource, + record.TransactionId, + record.Timestamp, + record.TransactionManager, + identity: diagnosticIdentity); if (behindRemoteEntryBySameTM) { @@ -148,6 +162,13 @@ public async Task EnqueueCommit(TransactionRecord record) .Prepared(record.TransactionManager.Name, record.TransactionId, record.Timestamp, this.resource, TransactionalStatus.Ok) .Ignore(); record.LastSent = DateTime.UtcNow; + TransactionDiagnosticEvents.EmitRemotePreparedSent( + resource, + record.TransactionId, + record.Timestamp, + record.TransactionManager, + record.LastSent.Value, + identity: diagnosticIdentity); } }); break; @@ -167,7 +188,7 @@ public async Task EnqueueCommit(TransactionRecord record) } } - public async Task NotifyOfPrepared(Guid transactionId, DateTime timeStamp, TransactionalStatus status) + public async Task NotifyOfPrepared(Guid transactionId, DateTime timeStamp, ParticipantId participant, TransactionalStatus status) { var pos = commitQueue.Find(transactionId, timeStamp); LogTraceNotifyOfPrepared(transactionId, new(timeStamp), status); @@ -185,11 +206,27 @@ public async Task NotifyOfPrepared(Guid transactionId, DateTime timeStamp, Trans if (status == TransactionalStatus.Ok) { localEntry.WaitCount--; + TransactionDiagnosticEvents.EmitPreparedReceived( + resource, + transactionId, + timeStamp, + participant, + status, + localEntry.WaitCount, + identity: diagnosticIdentity); storageWorker.Notify(); } else { + TransactionDiagnosticEvents.EmitPreparedReceived( + resource, + transactionId, + timeStamp, + participant, + status, + localEntry.WaitCount, + identity: diagnosticIdentity); await AbortCommits(status, pos); this.RWLock.Notify(); @@ -211,6 +248,15 @@ public async Task NotifyOfPrepared(Guid transactionId, DateTime timeStamp, Trans info.Status = status; } + TransactionDiagnosticEvents.EmitPreparedReceived( + resource, + transactionId, + timeStamp, + participant, + status, + remainingCount: null, + identity: diagnosticIdentity); + // TODO fix memory leak if corresponding commit messages never arrive } } @@ -267,27 +313,147 @@ public async Task NotifyOfAbort(TransactionRecord entry, TransactionalSt case CommitRole.LocalCommit: { LogTraceAborting(status, entry); - try + var deactivationToken = this.activationLifetime.OnDeactivating; + var fanOutDiagnosticsEnabled = AreCancelFanOutEventsEnabled(); + var targetCount = 0; + var selfTargetCount = 0; + var fanOutStartedAt = 0L; + if (fanOutDiagnosticsEnabled) { - // tell remote participants - await Task.WhenAll(entry.WriteParticipants - .Where(p => !p.Equals(resource)) - .Select(p => p.Reference.AsReference() - .Cancel(p.Name, entry.TransactionId, entry.Timestamp, status))); + (targetCount, selfTargetCount) = CountCancelTargets(entry.WriteParticipants); + if (targetCount > 0) + { + TransactionDiagnosticEvents.EmitCancelFanOutStarted( + resource, + entry.TransactionId, + entry.Timestamp, + status, + targetCount, + selfTargetCount, + diagnosticIdentity); + fanOutStartedAt = Stopwatch.GetTimestamp(); + } } - catch(Exception ex) + + var fanOutTasks = new List(); + foreach (var participant in entry.WriteParticipants) { - LogWarningFailedToNotifyAllTransactionParticipantsOfCancellation(entry.TransactionId, new(entry.Timestamp), status, ex); + if (participant.Equals(resource)) + { + continue; + } + + try + { + fanOutTasks.Add(SendCancel( + participant, + entry.TransactionId, + entry.Timestamp, + status, + TransactionDiagnosticEvents.CancelReason.TransactionAbort)); + } + catch (Exception ex) + { + fanOutTasks.Add(Task.FromException(ex)); + } } - // reply to transaction agent - if (exception is not null) + var fanOut = Task.WhenAll(fanOutTasks); + CompleteAbortDecision(entry, status, exception); + var cleanupBudgetExpired = false; + + try + { + var cleanupDeadline = Task.Delay(this.options.LockTimeout, deactivationToken); + var completed = await Task.WhenAny(fanOut, cleanupDeadline); + if (ShouldAbandonCancelFanOut(fanOut, completed)) + { + fanOut.Ignore(); + await cleanupDeadline; + cleanupBudgetExpired = true; + throw new TimeoutException( + $"Cancel fan-out did not complete within the {this.options.LockTimeout} cleanup budget."); + } + + await fanOut; + + if (fanOutDiagnosticsEnabled && targetCount > 0) + { + TransactionDiagnosticEvents.EmitCancelFanOutCompleted( + resource, + entry.TransactionId, + entry.Timestamp, + status, + targetCount, + selfTargetCount, + Stopwatch.GetElapsedTime(fanOutStartedAt), + diagnosticIdentity); + } + } + catch (OperationCanceledException ex) when (deactivationToken.IsCancellationRequested) { - entry.PromiseForTA.TrySetException(exception); + fanOut.Ignore(); + if (fanOutDiagnosticsEnabled && targetCount > 0) + { + TransactionDiagnosticEvents.EmitCancelFanOutFailed( + resource, + entry.TransactionId, + entry.Timestamp, + status, + targetCount, + selfTargetCount, + Stopwatch.GetElapsedTime(fanOutStartedAt), + ex, + diagnosticIdentity); + } + + LogWarningCancelFanOutAbandonedDuringDeactivation( + entry.TransactionId, + new(entry.Timestamp), + status, + ex); } - else + catch (TimeoutException ex) when (cleanupBudgetExpired) { - entry.PromiseForTA.TrySetResult(status); + fanOut.Ignore(); + if (fanOutDiagnosticsEnabled && targetCount > 0) + { + TransactionDiagnosticEvents.EmitCancelFanOutFailed( + resource, + entry.TransactionId, + entry.Timestamp, + status, + targetCount, + selfTargetCount, + Stopwatch.GetElapsedTime(fanOutStartedAt), + ex, + diagnosticIdentity); + } + + LogWarningCancelFanOutCleanupTimedOut( + entry.TransactionId, + new(entry.Timestamp), + status, + this.options.LockTimeout, + ex); + } + catch (Exception ex) + { + if (fanOutDiagnosticsEnabled && targetCount > 0) + { + TransactionDiagnosticEvents.EmitCancelFanOutFailed( + resource, + entry.TransactionId, + entry.Timestamp, + status, + targetCount, + selfTargetCount, + Stopwatch.GetElapsedTime(fanOutStartedAt), + ex, + diagnosticIdentity); + } + + LogWarningFailedToNotifyAllTransactionParticipantsOfCancellation(entry.TransactionId, new(entry.Timestamp), status, ex); } break; @@ -295,16 +461,7 @@ await Task.WhenAll(entry.WriteParticipants case CommitRole.ReadOnly: { LogTraceAborting(status, entry); - - // reply to transaction agent - if (exception is not null) - { - entry.PromiseForTA.TrySetException(exception); - } - else - { - entry.PromiseForTA.TrySetResult(status); - } + CompleteAbortDecision(entry, status, exception); break; } @@ -316,6 +473,26 @@ await Task.WhenAll(entry.WriteParticipants } } + private void CompleteAbortDecision( + TransactionRecord entry, + TransactionalStatus status, + Exception? exception) + { + var completed = exception is not null + ? entry.PromiseForTA.TrySetException(exception) + : entry.PromiseForTA.TrySetResult(status); + + if (completed) + { + TransactionDiagnosticEvents.EmitTransactionManagerAbortDecisionCompleted( + resource, + entry.TransactionId, + entry.Timestamp, + status, + diagnosticIdentity); + } + } + public async Task NotifyOfPing(Guid transactionId, DateTime timeStamp, ParticipantId resource) { if (this.commitQueue.Find(transactionId, timeStamp) != -1) @@ -334,8 +511,12 @@ public async Task NotifyOfPing(Guid transactionId, DateTime timeStamp, Participa LogTraceReceivedPingUnknown(transactionId); // we never heard of this transaction - so it must have aborted - await resource.Reference.AsReference() - .Cancel(resource.Name, transactionId, timeStamp, TransactionalStatus.PresumedAbort); + await SendCancel( + resource, + transactionId, + timeStamp, + TransactionalStatus.PresumedAbort, + TransactionDiagnosticEvents.CancelReason.RecoveryPing); } } } @@ -348,7 +529,17 @@ public async Task NotifyOfConfirm(Guid transactionId, DateTime timeStamp) var pos = commitQueue.Find(transactionId, timeStamp); if (pos == -1) + { + TransactionDiagnosticEvents.EmitTransactionConfirmCompleted( + resource, + transactionId, + timeStamp, + TransactionalStatus.Ok, + queueEntryFound: false, + succeeded: true, + identity: diagnosticIdentity); return; // must have already been confirmed + } var remoteEntry = commitQueue[pos]; @@ -366,7 +557,27 @@ public async Task NotifyOfConfirm(Guid transactionId, DateTime timeStamp) // now we wait for the batch to finish - await remoteEntry.ConfirmationResponsePromise.Task; + var confirmStatus = TransactionalStatus.Ok; + try + { + await remoteEntry.ConfirmationResponsePromise.Task; + } + catch + { + confirmStatus = TransactionalStatus.UnknownException; + throw; + } + finally + { + TransactionDiagnosticEvents.EmitTransactionConfirmCompleted( + resource, + transactionId, + timeStamp, + confirmStatus, + queueEntryFound: true, + succeeded: confirmStatus == TransactionalStatus.Ok, + identity: diagnosticIdentity); + } } public async Task NotifyOfCancel(Guid transactionId, DateTime timeStamp, TransactionalStatus status) @@ -376,15 +587,38 @@ public async Task NotifyOfCancel(Guid transactionId, DateTime timeStamp, Transac var pos = commitQueue.Find(transactionId, timeStamp); if (pos == -1) + { + TransactionDiagnosticEvents.EmitTransactionCancelCompleted( + resource, + transactionId, + timeStamp, + status, + queueEntryFound: false, + succeeded: true, + identity: diagnosticIdentity); return; + } - this.storageBatch.Cancel(commitQueue[pos].SequenceNumber); - - await AbortCommits(status, pos); - - storageWorker.Notify(); - - this.RWLock.Notify(); + var succeeded = false; + try + { + this.storageBatch.Cancel(commitQueue[pos].SequenceNumber); + await AbortCommits(status, pos); + storageWorker.Notify(); + this.RWLock.Notify(); + succeeded = true; + } + finally + { + TransactionDiagnosticEvents.EmitTransactionCancelCompleted( + resource, + transactionId, + timeStamp, + status, + queueEntryFound: true, + succeeded, + identity: diagnosticIdentity); + } } /// @@ -407,31 +641,75 @@ public async Task NotifyOfRestore() /// Ensures queue is ready to process requests. /// /// - public Task Ready() + public Task Ready(Guid? transactionId = null) { if (this.readyTask.IsCompletedSuccessfully) { return readyTask; } + TransactionDiagnosticEvents.EmitReadyWaitStarted(resource, transactionId, diagnosticIdentity); return ReadyAsync(); async Task ReadyAsync() { + var recoveredAfterFailure = false; try { await readyTask; } catch (Exception exception) { + recoveredAfterFailure = true; + TransactionDiagnosticEvents.EmitReadyWaitFailed(resource, transactionId, exception, diagnosticIdentity); LogWarningExceptionInTransactionQueue(exception); await AbortAndRestore(TransactionalStatus.UnknownException, exception, storageOutcomeInDoubt: false); } + + TransactionDiagnosticEvents.EmitReadyWaitCompleted( + resource, + transactionId, + recoveredAfterFailure, + diagnosticIdentity); } } - private async Task Restore() + private async Task Restore(ImmutableArray transactionIds = default) { - TransactionalStorageLoadResponse loadresponse = await storage.Load(); + if (transactionIds.IsDefault) + { + transactionIds = ImmutableArray.Empty; + } + + TransactionDiagnosticEvents.EmitQueueRestoreStarted(resource, transactionIds, diagnosticIdentity); + + TransactionalStorageLoadResponse loadresponse; + try + { + loadresponse = await storage.Load(); + } + catch (Exception exception) + { + var storageConflict = exception is InconsistentStateException; + if (storageConflict) + { + TransactionDiagnosticEvents.EmitStorageConflictDetected( + resource, + TransactionDiagnosticEvents.StorageOperation.Load, + storageOutcomeInDoubt: false, + queuedTransactionCount: transactionIds.Length, + exception: exception, + transactionIds: transactionIds, + identity: diagnosticIdentity); + } + + TransactionDiagnosticEvents.EmitQueueRestoreFailed( + resource, + exception, + storageConflict, + transactionIds, + diagnosticIdentity); + throw; + } this.storageBatch = new StorageBatch(loadresponse); @@ -444,27 +722,39 @@ private async Task Restore() this.Clock.Merge(storageBatch.MetaData.TimeStamp); // resume prepared transactions (not TM) + var recoveredPendingCount = 0; foreach (var pr in loadresponse.PendingStates.OrderBy(ps => ps.TimeStamp)) { if (pr.SequenceId > loadresponse.CommittedSequenceId && pr.TransactionManager.Reference != null) { LogDebugRecoverTwoPhaseCommit(pr.TransactionId); ParticipantId tm = pr.TransactionManager; + var transactionId = Guid.Parse(pr.TransactionId); commitQueue.Add(new TransactionRecord() { Role = CommitRole.RemoteCommit, - TransactionId = Guid.Parse(pr.TransactionId), + TransactionId = transactionId, Timestamp = pr.TimeStamp, State = pr.State, SequenceNumber = pr.SequenceId, TransactionManager = tm, PrepareIsPersisted = true, LastSent = default(DateTime), + IsRestoredRemoteCommit = true, ConfirmationResponsePromise = null, NumberWrites = 1 // was a writing transaction }); this.stableSequenceNumber = pr.SequenceId; + recoveredPendingCount++; + + TransactionDiagnosticEvents.EmitRemoteRecoveryPingScheduled( + resource, + transactionId, + pr.TimeStamp, + tm, + DateTime.UtcNow, + identity: diagnosticIdentity); } } @@ -475,6 +765,14 @@ private async Task Restore() this.confirmationWorker.Add(kvp.Key, kvp.Value.Timestamp, kvp.Value.WriteParticipants); } + TransactionDiagnosticEvents.EmitQueueRestoreCompleted( + resource, + loadresponse.CommittedSequenceId, + recoveredPendingCount, + storageBatch.MetaData.CommitRecords.Count, + transactionIds, + diagnosticIdentity); + // check for work this.storageWorker.Notify(); this.RWLock.Notify(); @@ -580,6 +878,18 @@ private async Task StorageWork() if (exception is InconsistentStateException) { status = TransactionalStatus.StorageConflict; + var transactionIds = TransactionDiagnosticEvents.IsEnabled( + nameof(TransactionDiagnosticEvents.StorageConflictDetected)) + ? CaptureTransactionIds() + : ImmutableArray.Empty; + TransactionDiagnosticEvents.EmitStorageConflictDetected( + resource, + TransactionDiagnosticEvents.StorageOperation.Store, + writeAttempted, + commitQueue.Count, + exception, + transactionIds, + diagnosticIdentity); LogWarningReloadFromStorageTriggeredByETagMismatch(exception); } else @@ -597,7 +907,9 @@ private async Task StorageWork() this.resource, this.storageBatch.ETag, batchBeingSentToStorage.BatchSize, - batchBeingSentToStorage.CommitCount); + batchBeingSentToStorage.CommitCount, + batchBeingSentToStorage.CommittedTransactionIds, + diagnosticIdentity); } if (committableEntries > 0) @@ -650,7 +962,23 @@ private async Task AbortAndRestore(TransactionalStatus status, Exception? except async Task AbortAndRestoreCore(TransactionalStatus status, Exception? exception, bool storageOutcomeInDoubt) { - List pending = [RWLock.AbortExecutingTransactions(exception)]; + var transactionIds = AreRecoveryCorrelationEventsEnabled() + ? CaptureTransactionIds() + : ImmutableArray.Empty; + TransactionDiagnosticEvents.EmitAbortAndRestoreStarted( + resource, + status, + storageOutcomeInDoubt, + commitQueue.Count, + transactionIds, + diagnosticIdentity); + + List pending = + [ + RWLock.AbortExecutingTransactions( + exception, + TransactionDiagnosticEvents.LockBreakReason.StorageRecovery) + ]; this.RWLock.AbortQueuedTransactions(); foreach (var entry in commitQueue.Elements) @@ -671,18 +999,135 @@ async Task AbortAndRestoreCore(TransactionalStatus status, Exception? exception, commitQueue.Clear(); await Task.WhenAll(pending); - if (++failCounter >= 10 || status == TransactionalStatus.StorageConflict) + var failureCount = ++failCounter; + if (failureCount >= 10 || status == TransactionalStatus.StorageConflict) { LogDebugStorageWorkerTriggeringGrainDeactivation(); + TransactionDiagnosticEvents.EmitDeactivationRequested( + resource, + status, + failureCount, + transactionIds, + diagnosticIdentity); this.deactivate(); } StorageBatch? discardedBatch = this.storageBatch; - await this.Restore(); + await this.Restore(transactionIds); if (discardedBatch is not null && !ReferenceEquals(discardedBatch, this.storageBatch)) { discardedBatch.Complete(success: false); } + TransactionDiagnosticEvents.EmitAbortAndRestoreCompleted( + resource, + status, + storageOutcomeInDoubt, + transactionIds, + diagnosticIdentity); + } + } + + private static bool AreRecoveryCorrelationEventsEnabled() + => TransactionDiagnosticEvents.IsEnabled(nameof(TransactionDiagnosticEvents.AbortAndRestoreStarted)) + || TransactionDiagnosticEvents.IsEnabled(nameof(TransactionDiagnosticEvents.AbortAndRestoreCompleted)) + || TransactionDiagnosticEvents.IsEnabled(nameof(TransactionDiagnosticEvents.QueueRestoreStarted)) + || TransactionDiagnosticEvents.IsEnabled(nameof(TransactionDiagnosticEvents.QueueRestoreCompleted)) + || TransactionDiagnosticEvents.IsEnabled(nameof(TransactionDiagnosticEvents.QueueRestoreFailed)) + || TransactionDiagnosticEvents.IsEnabled(nameof(TransactionDiagnosticEvents.StorageConflictDetected)) + || TransactionDiagnosticEvents.IsEnabled(nameof(TransactionDiagnosticEvents.DeactivationRequested)); + + private ImmutableArray CaptureTransactionIds() + { + if (commitQueue.Count == 0) + { + return ImmutableArray.Empty; } + + var result = ImmutableArray.CreateBuilder(commitQueue.Count); + for (var i = 0; i < commitQueue.Count; i++) + { + result.Add(commitQueue[i].TransactionId); + } + + return result.MoveToImmutable(); + } + + protected virtual async Task SendCancel( + ParticipantId target, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status, + TransactionDiagnosticEvents.CancelReason reason) + { + var isSelf = target.Reference.GrainId == resource.Reference.GrainId; + TransactionDiagnosticEvents.EmitCancelSendStarted( + resource, + transactionId, + timeStamp, + target, + isSelf, + status, + reason, + diagnosticIdentity); + + try + { + await target.Reference.AsReference() + .Cancel(target.Name, transactionId, timeStamp, status); + TransactionDiagnosticEvents.EmitCancelSendCompleted( + resource, + transactionId, + timeStamp, + target, + isSelf, + status, + reason, + diagnosticIdentity); + } + catch (Exception exception) + { + TransactionDiagnosticEvents.EmitCancelSendFailed( + resource, + transactionId, + timeStamp, + target, + isSelf, + status, + reason, + exception, + diagnosticIdentity); + throw; + } + } + + private static bool AreCancelFanOutEventsEnabled() + => TransactionDiagnosticEvents.IsEnabled(nameof(TransactionDiagnosticEvents.CancelFanOutStarted)) + || TransactionDiagnosticEvents.IsEnabled(nameof(TransactionDiagnosticEvents.CancelFanOutCompleted)) + || TransactionDiagnosticEvents.IsEnabled(nameof(TransactionDiagnosticEvents.CancelFanOutFailed)); + + internal static bool ShouldAbandonCancelFanOut(Task fanOut, Task completed) + => !ReferenceEquals(completed, fanOut) && !fanOut.IsCompleted; + + private (int TargetCount, int SelfTargetCount) CountCancelTargets(List participants) + { + var targetCount = 0; + var selfTargetCount = 0; + foreach (var participant in participants) + { + if (participant.Equals(resource)) + { + continue; + } + + targetCount++; + if (participant.Reference is not null + && resource.Reference is not null + && participant.Reference.GrainId == resource.Reference.GrainId) + { + selfTargetCount++; + } + } + + return (targetCount, selfTargetCount); } private void CompleteInDoubtEntryLocally(TransactionRecord entry, TransactionalStatus status, Exception? exception) @@ -727,6 +1172,13 @@ private async Task CheckProgressOfCommitQueue() // check for timeout periodically if (bottom.WaitingSince + this.options.PrepareTimeout <= now) { + TransactionDiagnosticEvents.EmitPrepareTimedOut( + resource, + bottom.TransactionId, + bottom.Timestamp, + bottom.WaitCount, + bottom.WaitingSince + this.options.PrepareTimeout, + diagnosticIdentity); await AbortCommits(TransactionalStatus.PrepareTimeout); this.RWLock.Notify(); } @@ -747,6 +1199,13 @@ private async Task CheckProgressOfCommitQueue() .Ignore(); bottom.LastSent = now; + TransactionDiagnosticEvents.EmitRemotePreparedSent( + resource, + bottom.TransactionId, + bottom.Timestamp, + bottom.TransactionManager, + now, + diagnosticIdentity); LogTraceSentPrepared(bottom); @@ -756,21 +1215,45 @@ private async Task CheckProgressOfCommitQueue() } else { - storageWorker.Notify(bottom.LastSent.Value + this.options.RemoteTransactionPingFrequency); + var scheduledAt = bottom.LastSent.Value + this.options.RemoteTransactionPingFrequency; + TransactionDiagnosticEvents.EmitRemoteRecoveryPingScheduled( + resource, + bottom.TransactionId, + bottom.Timestamp, + bottom.TransactionManager, + scheduledAt, + diagnosticIdentity); + storageWorker.Notify(scheduledAt); } } else if (!bottom.IsReadOnly && bottom.LastSent.HasValue) { // send ping messages periodically to reactivate crashed TMs - if (bottom.LastSent + this.options.RemoteTransactionPingFrequency <= now) + if (bottom.GetNextRemotePingAt(this.options.RemoteTransactionPingFrequency) <= now) { LogTraceSentPing(bottom); bottom.TransactionManager.Reference.AsReference() .Ping(bottom.TransactionManager.Name, bottom.TransactionId, bottom.Timestamp, resource).Ignore(); - bottom.LastSent = now; + bottom.RecordRemotePingSent(now); + TransactionDiagnosticEvents.EmitRemoteRecoveryPingSent( + resource, + bottom.TransactionId, + bottom.Timestamp, + bottom.TransactionManager, + now, + diagnosticIdentity); + + var scheduledAt = bottom.GetNextRemotePingAt(this.options.RemoteTransactionPingFrequency); + TransactionDiagnosticEvents.EmitRemoteRecoveryPingScheduled( + resource, + bottom.TransactionId, + bottom.Timestamp, + bottom.TransactionManager, + scheduledAt, + diagnosticIdentity); } - storageWorker.Notify(bottom.LastSent.Value + this.options.RemoteTransactionPingFrequency); + storageWorker.Notify(bottom.GetNextRemotePingAt(this.options.RemoteTransactionPingFrequency)); } break; @@ -903,7 +1386,9 @@ private async Task AbortCommits(TransactionalStatus status, int from = 0) } commitQueue.RemoveFromBack(commitQueue.Count - from); - pending.Add(this.RWLock.AbortExecutingTransactions(exception: null)); + pending.Add(this.RWLock.AbortExecutingTransactions( + exception: null, + reason: TransactionDiagnosticEvents.LockBreakReason.TransactionAbort)); await Task.WhenAll(pending); } @@ -973,6 +1458,18 @@ private readonly struct DateTimeLogRecord(DateTime ts) )] private partial void LogWarningFailedToNotifyAllTransactionParticipantsOfCancellation(Guid transactionId, DateTimeLogRecord timeStamp, TransactionalStatus status, Exception exception); + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Stopped awaiting transaction cancellation fan-out because the activation is deactivating. TransactionId: {TransactionId}, Timestamp: {Timestamp}, Status: {Status}" + )] + private partial void LogWarningCancelFanOutAbandonedDuringDeactivation(Guid transactionId, DateTimeLogRecord timeStamp, TransactionalStatus status, Exception exception); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Stopped awaiting transaction cancellation fan-out after the cleanup budget elapsed. TransactionId: {TransactionId}, Timestamp: {Timestamp}, Status: {Status}, CleanupTimeout: {CleanupTimeout}" + )] + private partial void LogWarningCancelFanOutCleanupTimedOut(Guid transactionId, DateTimeLogRecord timeStamp, TransactionalStatus status, TimeSpan cleanupTimeout, Exception exception); + [LoggerMessage( Level = LogLevel.Trace, Message = "Received ping for {TransactionId}, irrelevant (still processing)" diff --git a/src/Orleans.Transactions/State/TransactionalResource.cs b/src/Orleans.Transactions/State/TransactionalResource.cs index 7b587aa4001..f52c44f2f40 100644 --- a/src/Orleans.Transactions/State/TransactionalResource.cs +++ b/src/Orleans.Transactions/State/TransactionalResource.cs @@ -39,7 +39,7 @@ public async Task CommitReadOnly(Guid transactionId, Access public async Task Abort(Guid transactionId) { - await this.queue.Ready(); + await this.queue.Ready(transactionId); // release the lock this.queue.RWLock.Rollback(transactionId); @@ -48,13 +48,13 @@ public async Task Abort(Guid transactionId) public async Task Cancel(Guid transactionId, DateTime timeStamp, TransactionalStatus status) { - await this.queue.Ready(); + await this.queue.Ready(transactionId); await this.queue.NotifyOfCancel(transactionId, timeStamp, status); } public async Task Confirm(Guid transactionId, DateTime timeStamp) { - await this.queue.Ready(); + await this.queue.Ready(transactionId); await this.queue.NotifyOfConfirm(transactionId, timeStamp); } diff --git a/src/Orleans.Transactions/State/TransactionalState.cs b/src/Orleans.Transactions/State/TransactionalState.cs index a00ad1e0915..97abdf52552 100644 --- a/src/Orleans.Transactions/State/TransactionalState.cs +++ b/src/Orleans.Transactions/State/TransactionalState.cs @@ -7,6 +7,7 @@ using Microsoft.Extensions.Options; using Orleans.Runtime; using Orleans.Transactions.Abstractions; +using Orleans.Transactions.Diagnostics; using Orleans.Transactions.State; using Orleans.Configuration; using Orleans.Timers.Internal; @@ -201,7 +202,19 @@ internal async Task OnSetupState(Action>(); var clock = this.context.ActivationServices.GetRequiredService(); var timerManager = this.context.ActivationServices.GetRequiredService(); - this.queue = new TransactionQueue(options, this.participantId, deactivate, storage, clock, logger, timerManager, this.activationLifetime); + var diagnosticIdentity = new TransactionDiagnosticEvents.TransactionDiagnosticIdentity( + this.context.Address.SiloAddress, + this.context.ActivationId); + this.queue = new TransactionQueue( + options, + this.participantId, + deactivate, + storage, + clock, + logger, + timerManager, + this.activationLifetime, + diagnosticIdentity); setupResourceFactory(this.context, this.config.StateName, queue); diff --git a/src/Orleans.Transactions/TOC/TocTransactionQueue.cs b/src/Orleans.Transactions/TOC/TocTransactionQueue.cs index a03bf0181f5..58a205b813d 100644 --- a/src/Orleans.Transactions/TOC/TocTransactionQueue.cs +++ b/src/Orleans.Transactions/TOC/TocTransactionQueue.cs @@ -4,6 +4,7 @@ using Orleans.Configuration; using Orleans.Timers.Internal; using Orleans.Transactions.Abstractions; +using Orleans.Transactions.Diagnostics; using Orleans.Transactions.State; namespace Orleans.Transactions.TOC @@ -22,8 +23,9 @@ public TocTransactionQueue( IClock clock, ILogger logger, ITimerManager timerManager, - IActivationLifetime activationLifetime) - : base(options, resource, deactivate, storage, clock, logger, timerManager, activationLifetime) + IActivationLifetime activationLifetime, + TransactionDiagnosticEvents.TransactionDiagnosticIdentity diagnosticIdentity) + : base(options, resource, deactivate, storage, clock, logger, timerManager, activationLifetime, diagnosticIdentity) { this.service = service; } diff --git a/src/Orleans.Transactions/TOC/TransactionCommitter.cs b/src/Orleans.Transactions/TOC/TransactionCommitter.cs index 0317aa96a15..f62cf57ef7f 100644 --- a/src/Orleans.Transactions/TOC/TransactionCommitter.cs +++ b/src/Orleans.Transactions/TOC/TransactionCommitter.cs @@ -8,6 +8,7 @@ using Orleans.Runtime; using Orleans.Timers.Internal; using Orleans.Transactions.Abstractions; +using Orleans.Transactions.Diagnostics; using Orleans.Transactions.State; using Orleans.Transactions.TOC; @@ -129,7 +130,20 @@ private async Task OnSetupState(CancellationToken ct) var clock = this.context.ActivationServices.GetRequiredService(); TService service = this.context.ActivationServices.GetRequiredKeyedService(this.config.ServiceName); var timerManager = this.context.ActivationServices.GetRequiredService(); - this.queue = new TocTransactionQueue(service, options, this.participantId, deactivate, storage, clock, logger, timerManager, this.activationLifetime); + var diagnosticIdentity = new TransactionDiagnosticEvents.TransactionDiagnosticIdentity( + this.context.Address.SiloAddress, + this.context.ActivationId); + this.queue = new TocTransactionQueue( + service, + options, + this.participantId, + deactivate, + storage, + clock, + logger, + timerManager, + this.activationLifetime, + diagnosticIdentity); // Add transaction manager factory to the grain context this.context.RegisterResourceFactory(this.config.ServiceName, () => new TransactionManager(this.queue)); diff --git a/src/api/Orleans.Transactions.TestKit.Base/Orleans.Transactions.TestKit.Base.cs b/src/api/Orleans.Transactions.TestKit.Base/Orleans.Transactions.TestKit.Base.cs index a0e69116523..fbafd25bb49 100644 --- a/src/api/Orleans.Transactions.TestKit.Base/Orleans.Transactions.TestKit.Base.cs +++ b/src/api/Orleans.Transactions.TestKit.Base/Orleans.Transactions.TestKit.Base.cs @@ -806,9 +806,15 @@ protected void Log(string message) { } protected virtual System.Threading.Tasks.Task TransactionWillRecoverAfterRandomSiloFailure(string transactionTestGrainClassName, int concurrent, bool gracefulShutdown) { throw null; } + public System.Threading.Tasks.Task TransactionWillRecoverAfterLocalCommitStored(string transactionTestGrainClassName) { throw null; } + + public System.Threading.Tasks.Task TransactionWillRecoverAfterManagerWait(string transactionTestGrainClassName) { throw null; } + public virtual System.Threading.Tasks.Task TransactionWillRecoverAfterRandomSiloGracefulShutdown(string transactionTestGrainClassName, int concurrent) { throw null; } public virtual System.Threading.Tasks.Task TransactionWillRecoverAfterRandomSiloUnGracefulShutdown(string transactionTestGrainClassName, int concurrent) { throw null; } + + public System.Threading.Tasks.Task TransactionWillRecoverAfterRemotePreparePersisted(string transactionTestGrainClassName) { throw null; } } public static partial class TransactionTestConstants diff --git a/test/Transactions/Orleans.Transactions.Azure.Test/TransactionRecoveryTests.cs b/test/Transactions/Orleans.Transactions.Azure.Test/TransactionRecoveryTests.cs index 9bc7fac3d5b..e0dcf08ffc4 100644 --- a/test/Transactions/Orleans.Transactions.Azure.Test/TransactionRecoveryTests.cs +++ b/test/Transactions/Orleans.Transactions.Azure.Test/TransactionRecoveryTests.cs @@ -61,6 +61,27 @@ public Task TransactionWillRecoverAfterRandomSiloUnGracefulShutdown(string trans return this.testRunner.TransactionWillRecoverAfterRandomSiloUnGracefulShutdown(transactionTestGrainClassName, concurrent); } + [SkippableFact] + public Task TransactionWillRecoverAfterManagerWait() + { + return this.testRunner.TransactionWillRecoverAfterManagerWait( + TransactionTestConstants.SingleStateTransactionalGrain); + } + + [SkippableFact] + public Task TransactionWillRecoverAfterRemotePreparePersisted() + { + return this.testRunner.TransactionWillRecoverAfterRemotePreparePersisted( + TransactionTestConstants.SingleStateTransactionalGrain); + } + + [SkippableFact] + public Task TransactionWillRecoverAfterLocalCommitStored() + { + return this.testRunner.TransactionWillRecoverAfterLocalCommitStored( + TransactionTestConstants.SingleStateTransactionalGrain); + } + private class SiloBuilderConfiguratorUsingAzureClustering : ISiloConfigurator { public void Configure(ISiloBuilder hostBuilder) diff --git a/test/Transactions/Orleans.Transactions.DynamoDB.Test/TransactionRecoveryTests.cs b/test/Transactions/Orleans.Transactions.DynamoDB.Test/TransactionRecoveryTests.cs index b1e7ddef0dd..60302235a1c 100644 --- a/test/Transactions/Orleans.Transactions.DynamoDB.Test/TransactionRecoveryTests.cs +++ b/test/Transactions/Orleans.Transactions.DynamoDB.Test/TransactionRecoveryTests.cs @@ -64,6 +64,27 @@ public Task TransactionWillRecoverAfterRandomSiloUnGracefulShutdown(string trans return this.testRunner.TransactionWillRecoverAfterRandomSiloUnGracefulShutdown(transactionTestGrainClassName, concurrent); } + [SkippableFact] + public Task TransactionWillRecoverAfterManagerWait() + { + return this.testRunner.TransactionWillRecoverAfterManagerWait( + TransactionTestConstants.SingleStateTransactionalGrain); + } + + [SkippableFact] + public Task TransactionWillRecoverAfterRemotePreparePersisted() + { + return this.testRunner.TransactionWillRecoverAfterRemotePreparePersisted( + TransactionTestConstants.SingleStateTransactionalGrain); + } + + [SkippableFact] + public Task TransactionWillRecoverAfterLocalCommitStored() + { + return this.testRunner.TransactionWillRecoverAfterLocalCommitStored( + TransactionTestConstants.SingleStateTransactionalGrain); + } + private class SiloBuilderConfiguratorUsingDynamoDBClustering : ISiloConfigurator { public void Configure(ISiloBuilder hostBuilder) diff --git a/test/Transactions/Orleans.Transactions.Tests/BankTransferDiagnosticFaults.cs b/test/Transactions/Orleans.Transactions.Tests/BankTransferDiagnosticFaults.cs index 642611d184a..bdb92d96473 100644 --- a/test/Transactions/Orleans.Transactions.Tests/BankTransferDiagnosticFaults.cs +++ b/test/Transactions/Orleans.Transactions.Tests/BankTransferDiagnosticFaults.cs @@ -39,7 +39,10 @@ public void Dispose() private void OnStorageWriteCompleted(TransactionDiagnosticEvents.StorageWriteCompleted evt) { - if (evt.Resource.Name != this.stateName || evt.Resource.Reference.GrainId != this.targetGrainId || evt.CommitCount == 0) + if (evt.Resource.Name != this.stateName + || evt.Resource.Reference.GrainId != this.targetGrainId + || evt.CommitCount == 0 + || evt.TransactionIds.IsDefaultOrEmpty) { return; } @@ -48,7 +51,8 @@ private void OnStorageWriteCompleted(TransactionDiagnosticEvents.StorageWriteCom if (Interlocked.Exchange(ref this.shouldThrow, 0) == 1) { throw new InvalidOperationException( - $"Transaction queue exception thrown after storage write completed for {evt.Resource}, batch size {evt.BatchSize}, etag {evt.ETag}"); + $"Transaction queue exception thrown after storage write completed for {evt.Resource}, " + + $"transactions [{string.Join(",", evt.TransactionIds)}], batch size {evt.BatchSize}, etag {evt.ETag}"); } } diff --git a/test/Transactions/Orleans.Transactions.Tests/TransactionDiagnosticEventsTests.cs b/test/Transactions/Orleans.Transactions.Tests/TransactionDiagnosticEventsTests.cs new file mode 100644 index 00000000000..347f1d90f06 --- /dev/null +++ b/test/Transactions/Orleans.Transactions.Tests/TransactionDiagnosticEventsTests.cs @@ -0,0 +1,782 @@ +using System.Collections.Concurrent; +using System.Collections.Immutable; +using System.Diagnostics; +using System.Net; +using Orleans.Runtime; +using Orleans.Storage; +using Orleans.Transactions.Diagnostics; +using Orleans.Transactions.TestKit; +using TestExtensions; +using Xunit; + +namespace Orleans.Transactions.Tests; + +[TestCategory("BVT"), TestCategory("Transactions")] +public class TransactionDiagnosticEventsTests +{ + [Fact] + public void RecoveryEventsDeliverExpectedPayloads() + { + var resource = CreateParticipant("resource", ParticipantId.Role.Resource); + var participant = CreateParticipant("participant", ParticipantId.Role.Resource); + var manager = CreateParticipant("manager", ParticipantId.Role.Manager); + var transactionId = Guid.NewGuid(); + var timeStamp = new DateTime(2026, 8, 8, 12, 0, 0, DateTimeKind.Utc); + var deadline = timeStamp.AddSeconds(20); + var observedAt = deadline.AddMilliseconds(25); + var sentAt = timeStamp.AddSeconds(1); + var scheduledAt = sentAt.AddSeconds(60); + var fanOutDuration = TimeSpan.FromSeconds(30); + var transactionIds = ImmutableArray.Create(transactionId); + var conflictException = new InconsistentStateException( + "DynamoDB transactional state storage conflict.", + storedEtag: "1", + currentEtag: "2"); + var loadException = new InconsistentStateException( + "Could not load a consistent DynamoDB transactional state snapshot.", + storedEtag: "1", + currentEtag: "2"); + var timeoutException = new TimeoutException("Cancel timed out."); + var siloAddress = SiloAddress.New(IPAddress.Loopback, 11_111, 7); + var activationId = ActivationId.NewId(); + var identity = new TransactionDiagnosticEvents.TransactionDiagnosticIdentity(siloAddress, activationId); + var observer = new RecordingObserver(); + + using var subscription = TransactionDiagnosticEvents.AllEvents.Subscribe(observer); + + TransactionDiagnosticEvents.EmitTransactionManagerWaitingForPrepared(resource, transactionId, timeStamp, 2, deadline); + TransactionDiagnosticEvents.EmitPreparedReceived( + resource, + transactionId, + timeStamp, + participant, + TransactionalStatus.Ok, + remainingCount: 1); + TransactionDiagnosticEvents.EmitPrepareTimedOut(resource, transactionId, timeStamp, 1, deadline); + TransactionDiagnosticEvents.EmitRemotePreparePersisted(resource, transactionId, timeStamp, manager); + TransactionDiagnosticEvents.EmitRemotePreparedSent(resource, transactionId, timeStamp, manager, sentAt); + TransactionDiagnosticEvents.EmitRemoteRecoveryPingScheduled(resource, transactionId, timeStamp, manager, scheduledAt, identity); + TransactionDiagnosticEvents.EmitRemoteRecoveryPingSent(resource, transactionId, timeStamp, manager, sentAt, identity); + TransactionDiagnosticEvents.EmitTransactionManagerAbortDecisionCompleted( + resource, + transactionId, + timeStamp, + TransactionalStatus.PrepareTimeout, + identity); + TransactionDiagnosticEvents.EmitTransactionCancelCompleted( + resource, + transactionId, + timeStamp, + TransactionalStatus.PresumedAbort, + queueEntryFound: true, + succeeded: true, + identity); + TransactionDiagnosticEvents.EmitTransactionConfirmCompleted( + resource, + transactionId, + timeStamp, + TransactionalStatus.UnknownException, + queueEntryFound: false, + succeeded: false, + identity); + TransactionDiagnosticEvents.EmitQueueRestoreStarted(resource, transactionIds, identity); + TransactionDiagnosticEvents.EmitQueueRestoreCompleted(resource, 42, 2, 3, transactionIds); + TransactionDiagnosticEvents.EmitQueueRestoreFailed( + resource, + loadException, + storageConflict: true, + transactionIds); + TransactionDiagnosticEvents.EmitStorageConflictDetected( + resource, + TransactionDiagnosticEvents.StorageOperation.Load, + storageOutcomeInDoubt: false, + queuedTransactionCount: transactionIds.Length, + exception: loadException, + transactionIds: transactionIds); + TransactionDiagnosticEvents.EmitLockExpired( + resource, + transactionId, + deadline, + observedAt, + TransactionDiagnosticEvents.LockExpirationKind.HeldLock); + TransactionDiagnosticEvents.EmitLockBroken( + resource, + transactionId, + TransactionDiagnosticEvents.LockBreakReason.Expired); + TransactionDiagnosticEvents.EmitStorageConflictDetected( + resource, + TransactionDiagnosticEvents.StorageOperation.Store, + storageOutcomeInDoubt: true, + queuedTransactionCount: 4, + exception: conflictException, + transactionIds: transactionIds); + TransactionDiagnosticEvents.EmitAbortAndRestoreStarted( + resource, + TransactionalStatus.StorageConflict, + storageOutcomeInDoubt: true, + queuedTransactionCount: 4, + transactionIds: transactionIds); + TransactionDiagnosticEvents.EmitAbortAndRestoreCompleted( + resource, + TransactionalStatus.StorageConflict, + storageOutcomeInDoubt: true, + transactionIds: transactionIds); + TransactionDiagnosticEvents.EmitDeactivationRequested( + resource, + TransactionalStatus.StorageConflict, + failureCount: 1, + transactionIds); + TransactionDiagnosticEvents.EmitCancelSendStarted( + resource, + transactionId, + timeStamp, + participant, + isSelf: true, + TransactionalStatus.PresumedAbort, + TransactionDiagnosticEvents.CancelReason.RecoveryPing); + TransactionDiagnosticEvents.EmitCancelSendCompleted( + resource, + transactionId, + timeStamp, + participant, + isSelf: false, + TransactionalStatus.CascadingAbort, + TransactionDiagnosticEvents.CancelReason.TransactionAbort); + TransactionDiagnosticEvents.EmitCancelSendFailed( + resource, + transactionId, + timeStamp, + participant, + isSelf: true, + TransactionalStatus.PresumedAbort, + TransactionDiagnosticEvents.CancelReason.RecoveryPing, + timeoutException); + TransactionDiagnosticEvents.EmitCancelFanOutStarted( + resource, + transactionId, + timeStamp, + TransactionalStatus.BrokenLock, + targetCount: 2, + selfTargetCount: 1); + TransactionDiagnosticEvents.EmitCancelFanOutCompleted( + resource, + transactionId, + timeStamp, + TransactionalStatus.BrokenLock, + targetCount: 2, + selfTargetCount: 1, + duration: fanOutDuration); + TransactionDiagnosticEvents.EmitCancelFanOutFailed( + resource, + transactionId, + timeStamp, + TransactionalStatus.BrokenLock, + targetCount: 2, + selfTargetCount: 1, + duration: fanOutDuration, + exception: timeoutException); + TransactionDiagnosticEvents.EmitReadyWaitStarted(resource, transactionId); + TransactionDiagnosticEvents.EmitReadyWaitFailed(resource, transactionId, timeoutException); + TransactionDiagnosticEvents.EmitReadyWaitCompleted(resource, transactionId, recoveredAfterFailure: true); + TransactionDiagnosticEvents.EmitStorageWriteCompleted(resource, "etag", 1, 1, transactionIds, identity); + + var waiting = observer.Single(resource); + Assert.Equal(transactionId, waiting.TransactionId); + Assert.Equal(timeStamp, waiting.TimeStamp); + Assert.Equal(2, waiting.WaitCount); + Assert.Equal(deadline, waiting.Deadline); + Assert.Equal(TransactionDiagnosticEvents.TransactionProtocolRole.LocalTransactionManager, waiting.ProtocolRole); + Assert.Equal(TransactionDiagnosticEvents.TransactionPhase.WaitingForRemotePrepares, waiting.Phase); + + var prepared = observer.Single(resource); + Assert.Equal(participant, prepared.Participant); + Assert.Equal(TransactionalStatus.Ok, prepared.Status); + Assert.Equal(1, prepared.RemainingCount); + Assert.Equal(TransactionDiagnosticEvents.TransactionProtocolRole.LocalTransactionManager, prepared.ProtocolRole); + Assert.Equal(TransactionDiagnosticEvents.TransactionPhase.PreparedCallback, prepared.Phase); + + var timedOut = observer.Single(resource); + Assert.Equal(1, timedOut.RemainingCount); + Assert.Equal(deadline, timedOut.Deadline); + + var preparePersisted = observer.Single(resource); + Assert.Equal(manager, preparePersisted.TransactionManager); + Assert.Equal(TransactionDiagnosticEvents.TransactionProtocolRole.RemoteParticipant, preparePersisted.ProtocolRole); + Assert.Equal(TransactionDiagnosticEvents.TransactionPhase.RemotePreparePersisted, preparePersisted.Phase); + Assert.Equal(sentAt, observer.Single(resource).SentAt); + var pingScheduled = observer.Single(resource); + Assert.Equal(scheduledAt, pingScheduled.ScheduledAt); + Assert.Equal(activationId, pingScheduled.ActivationId); + var pingSent = observer.Single(resource); + Assert.Equal(sentAt, pingSent.SentAt); + Assert.Equal(activationId, pingSent.ActivationId); + var abortDecision = observer.Single(resource); + Assert.Equal(TransactionalStatus.PrepareTimeout, abortDecision.Status); + Assert.Equal(activationId, abortDecision.ActivationId); + Assert.Equal(TransactionDiagnosticEvents.TransactionProtocolRole.LocalTransactionManager, abortDecision.ProtocolRole); + Assert.Equal(TransactionDiagnosticEvents.TransactionPhase.AbortDecision, abortDecision.Phase); + var canceled = observer.Single(resource); + Assert.Equal(transactionId, canceled.TransactionId); + Assert.Equal(timeStamp, canceled.TimeStamp); + Assert.Equal(TransactionalStatus.PresumedAbort, canceled.Status); + Assert.True(canceled.QueueEntryFound); + Assert.True(canceled.Succeeded); + Assert.Equal(siloAddress, canceled.SiloAddress); + Assert.Equal(activationId, canceled.ActivationId); + Assert.Equal(TransactionDiagnosticEvents.TransactionProtocolRole.RemoteParticipant, canceled.ProtocolRole); + Assert.Equal(TransactionDiagnosticEvents.TransactionPhase.Cancel, canceled.Phase); + var confirmed = observer.Single(resource); + Assert.Equal(transactionId, confirmed.TransactionId); + Assert.Equal(timeStamp, confirmed.TimeStamp); + Assert.Equal(TransactionalStatus.UnknownException, confirmed.Status); + Assert.False(confirmed.QueueEntryFound); + Assert.False(confirmed.Succeeded); + Assert.Equal(siloAddress, confirmed.SiloAddress); + Assert.Equal(activationId, confirmed.ActivationId); + Assert.Equal(TransactionDiagnosticEvents.TransactionProtocolRole.RemoteParticipant, confirmed.ProtocolRole); + Assert.Equal(TransactionDiagnosticEvents.TransactionPhase.Confirm, confirmed.Phase); + + var restoreStartedEvent = observer.Single(resource); + Assert.Equal(transactionIds, restoreStartedEvent.TransactionIds); + Assert.Equal(siloAddress, restoreStartedEvent.SiloAddress); + Assert.Equal(activationId, restoreStartedEvent.ActivationId); + + var restored = observer.Single(resource); + Assert.Equal(42, restored.CommittedSequence); + Assert.Equal(2, restored.RecoveredPendingCount); + Assert.Equal(3, restored.RecoveredCommitCount); + Assert.Equal(transactionIds, restored.TransactionIds); + + var restoreFailed = observer.Single(resource); + Assert.True(restoreFailed.StorageConflict); + Assert.Equal(typeof(InconsistentStateException).FullName, restoreFailed.ExceptionType); + Assert.Equal(loadException.Message, restoreFailed.ExceptionMessage); + Assert.Equal(transactionIds, restoreFailed.TransactionIds); + + var expired = observer.Single(resource); + Assert.Equal(transactionId, expired.TransactionId); + Assert.Equal(deadline, expired.Deadline); + Assert.Equal(observedAt, expired.ObservedAt); + Assert.Equal(TransactionDiagnosticEvents.LockExpirationKind.HeldLock, expired.Kind); + + var broken = observer.Single(resource); + Assert.Equal(TransactionDiagnosticEvents.LockBreakReason.Expired, broken.Reason); + + var conflicts = observer.All(resource); + var storeConflict = Assert.Single( + conflicts, + conflict => conflict.Operation == TransactionDiagnosticEvents.StorageOperation.Store); + Assert.True(storeConflict.StorageOutcomeInDoubt); + Assert.Equal(4, storeConflict.QueuedTransactionCount); + Assert.Equal(conflictException.Message, storeConflict.ExceptionMessage); + Assert.Equal(transactionIds, storeConflict.TransactionIds); + + var loadConflict = Assert.Single( + conflicts, + conflict => conflict.Operation == TransactionDiagnosticEvents.StorageOperation.Load); + Assert.False(loadConflict.StorageOutcomeInDoubt); + Assert.Equal(transactionIds.Length, loadConflict.QueuedTransactionCount); + Assert.Equal(loadException.Message, loadConflict.ExceptionMessage); + Assert.Equal(transactionIds, loadConflict.TransactionIds); + + var restoreStarted = observer.Single(resource); + Assert.Equal(TransactionalStatus.StorageConflict, restoreStarted.Status); + Assert.True(restoreStarted.StorageOutcomeInDoubt); + Assert.Equal(4, restoreStarted.QueuedTransactionCount); + Assert.Equal(transactionIds, restoreStarted.TransactionIds); + + var restoreCompleted = observer.Single(resource); + Assert.Equal(TransactionalStatus.StorageConflict, restoreCompleted.Status); + Assert.True(restoreCompleted.StorageOutcomeInDoubt); + Assert.Equal(transactionIds, restoreCompleted.TransactionIds); + + var deactivation = observer.Single(resource); + Assert.Equal(TransactionalStatus.StorageConflict, deactivation.Status); + Assert.Equal(1, deactivation.FailureCount); + Assert.Equal(transactionIds, deactivation.TransactionIds); + + var cancelStarted = observer.Single(resource); + Assert.Equal(transactionId, cancelStarted.TransactionId); + Assert.Equal(participant, cancelStarted.Target); + Assert.True(cancelStarted.IsSelf); + Assert.Equal(TransactionDiagnosticEvents.CancelReason.RecoveryPing, cancelStarted.Reason); + Assert.Equal(TransactionDiagnosticEvents.TransactionProtocolRole.LocalTransactionManager, cancelStarted.ProtocolRole); + Assert.Equal(TransactionDiagnosticEvents.TransactionPhase.Cancel, cancelStarted.Phase); + + var cancelCompleted = observer.Single(resource); + Assert.False(cancelCompleted.IsSelf); + Assert.Equal(TransactionalStatus.CascadingAbort, cancelCompleted.Status); + Assert.Equal(TransactionDiagnosticEvents.CancelReason.TransactionAbort, cancelCompleted.Reason); + + var cancelFailed = observer.Single(resource); + Assert.True(cancelFailed.IsSelf); + Assert.Equal(typeof(TimeoutException).FullName, cancelFailed.ExceptionType); + Assert.Equal(timeoutException.Message, cancelFailed.ExceptionMessage); + + var fanOutStarted = observer.Single(resource); + Assert.Equal(2, fanOutStarted.TargetCount); + Assert.Equal(1, fanOutStarted.SelfTargetCount); + Assert.Equal(TransactionDiagnosticEvents.TransactionPhase.CancelFanOut, fanOutStarted.Phase); + + var fanOutCompleted = observer.Single(resource); + Assert.Equal(fanOutDuration, fanOutCompleted.Duration); + Assert.Equal( + TransactionDiagnosticEvents.TransactionProtocolRole.LocalTransactionManager, + fanOutCompleted.ProtocolRole); + + var fanOutFailed = observer.Single(resource); + Assert.Equal(fanOutDuration, fanOutFailed.Duration); + Assert.Equal(timeoutException.Message, fanOutFailed.ExceptionMessage); + + Assert.Equal( + transactionId, + observer.Single(resource).TransactionId); + var readyFailed = observer.Single(resource); + Assert.Equal(transactionId, readyFailed.TransactionId); + Assert.Equal(timeoutException.Message, readyFailed.ExceptionMessage); + var readyCompleted = observer.Single(resource); + Assert.Equal(transactionId, readyCompleted.TransactionId); + Assert.True(readyCompleted.RecoveredAfterFailure); + + var storageWrite = observer.Single(resource); + Assert.Equal(siloAddress, storageWrite.SiloAddress); + Assert.Equal(activationId, storageWrite.ActivationId); + Assert.Equal(TransactionDiagnosticEvents.TransactionProtocolRole.Unknown, storageWrite.ProtocolRole); + Assert.Equal(TransactionDiagnosticEvents.TransactionPhase.StorageWrite, storageWrite.Phase); + Assert.Equal(transactionIds, storageWrite.TransactionIds); + } + + [Fact] + public void OnlyStorageWriteCompletedPropagatesObserverExceptions() + { + var resource = CreateParticipant("fault-target", ParticipantId.Role.Resource); + using var subscription = TransactionDiagnosticEvents.AllEvents.Subscribe(new ThrowingObserver()); + + TransactionDiagnosticEvents.EmitQueueRestoreStarted(resource, ImmutableArray.Empty); + TransactionDiagnosticEvents.EmitTransactionCancelCompleted( + resource, + Guid.NewGuid(), + DateTime.UtcNow, + TransactionalStatus.PresumedAbort, + queueEntryFound: false, + succeeded: true); + + Assert.Throws( + () => TransactionDiagnosticEvents.EmitStorageWriteCompleted( + resource, + "etag", + 1, + 1, + ImmutableArray.Empty)); + } + + [Fact] + public void RecoveryEventFilterExceptionsDoNotPropagate() + { + var resource = CreateParticipant("filter-fault-target", ParticipantId.Role.Resource); + var listener = Assert.IsType( + typeof(TransactionDiagnosticEvents) + .GetField("Listener", System.Reflection.BindingFlags.NonPublic | System.Reflection.BindingFlags.Static)! + .GetValue(null)); + using var subscription = listener.Subscribe( + new RawDiagnosticObserver(), + static (_, _, _) => throw new InvalidOperationException("Filter fault")); + + TransactionDiagnosticEvents.EmitQueueRestoreStarted(resource, ImmutableArray.Empty); + Assert.Throws( + () => TransactionDiagnosticEvents.EmitStorageWriteCompleted( + resource, + "etag", + 1, + 1, + ImmutableArray.Empty)); + } + + [Fact] + public async Task RecoveryObserverStorageWriteTransitionContainsCommittedTransactionIds() + { + var resource = CreateParticipant("resource", ParticipantId.Role.Resource); + var committedTransactionIds = ImmutableArray.Create(Guid.NewGuid(), Guid.NewGuid()); + using var observer = new TransactionRecoveryEventObserver(candidate => candidate.Name == resource.Name); + + TransactionDiagnosticEvents.EmitStorageWriteCompleted( + resource, + "etag", + batchSize: 3, + commitCount: committedTransactionIds.Length, + committedTransactionIds); + + var transition = await observer.WaitForNextTransitionAsync( + afterSequence: 0, + GetDeadline(TimeSpan.FromSeconds(1))); + + Assert.Equal(TransactionRecoveryEventObserver.RecoveryTransitionKind.StorageWriteCompleted, transition.Kind); + Assert.Equal(committedTransactionIds, transition.TransactionIds); + Assert.Equal(committedTransactionIds.Length, transition.CommitCount); + } + + [Fact] + public void StorageWriteCompletedFaultScopeOnlyInjectsForMatchingCommittedTransactions() + { + var target = CreateGrainReference("fault-target"); + var otherTarget = CreateGrainReference("other-target"); + var matchingResource = CreateParticipant("balance", target, ParticipantId.Role.Resource); + var wrongState = CreateParticipant("other-state", target, ParticipantId.Role.Resource); + var wrongTarget = CreateParticipant("balance", otherTarget, ParticipantId.Role.Resource); + var transactionId = Guid.NewGuid(); + var transactionIds = ImmutableArray.Create(transactionId); + using var fault = BankTransferDiagnosticFaults.ThrowOnStorageWriteCompleted(target); + + TransactionDiagnosticEvents.EmitStorageWriteCompleted( + matchingResource, + "etag", + batchSize: 1, + commitCount: 0, + transactionIds); + TransactionDiagnosticEvents.EmitStorageWriteCompleted( + matchingResource, + "etag", + batchSize: 1, + commitCount: 1, + ImmutableArray.Empty); + TransactionDiagnosticEvents.EmitStorageWriteCompleted( + wrongState, + "etag", + batchSize: 1, + commitCount: 1, + transactionIds); + TransactionDiagnosticEvents.EmitStorageWriteCompleted( + wrongTarget, + "etag", + batchSize: 1, + commitCount: 1, + transactionIds); + + Assert.Equal(0, fault.ObservedCount); + Assert.False(fault.FaultInjected); + + var exception = Assert.Throws( + () => TransactionDiagnosticEvents.EmitStorageWriteCompleted( + matchingResource, + "etag", + batchSize: 1, + commitCount: 1, + transactionIds)); + + Assert.Contains(transactionId.ToString(), exception.Message); + Assert.Equal(1, fault.ObservedCount); + Assert.True(fault.FaultInjected); + } + + [Fact] + public async Task RecoveryObserverFiltersEventsAndReturnsAlreadyObservedTransition() + { + var relevant = CreateParticipant("relevant", ParticipantId.Role.Resource); + var unrelated = CreateParticipant("unrelated", ParticipantId.Role.Resource); + var manager = CreateParticipant("manager", ParticipantId.Role.Manager); + var transactionId = Guid.NewGuid(); + using var observer = new TransactionRecoveryEventObserver(resource => resource.Name == relevant.Name); + + TransactionDiagnosticEvents.EmitRemotePreparePersisted( + unrelated, + Guid.NewGuid(), + DateTime.UtcNow, + manager); + TransactionDiagnosticEvents.EmitRemotePreparePersisted( + relevant, + transactionId, + DateTime.UtcNow, + manager); + + var transition = await observer.WaitForNextTransitionAsync(0, GetDeadline(TimeSpan.FromSeconds(1))); + + Assert.Equal(TransactionRecoveryEventObserver.RecoveryTransitionKind.RemotePreparePersisted, transition.Kind); + Assert.Equal(transactionId, transition.TransactionId); + Assert.Equal(relevant.Name, transition.ResourceName); + Assert.Single(observer.GetTimeline()); + } + + [Fact] + public async Task RecoveryObserverDoesNotMissEventBetweenStateCheckAndWait() + { + var resource = CreateParticipant("resource", ParticipantId.Role.Resource); + var manager = CreateParticipant("manager", ParticipantId.Role.Manager); + using var observer = new TransactionRecoveryEventObserver(candidate => candidate.Name == resource.Name); + var afterSequence = observer.LatestRelevantSequence; + + TransactionDiagnosticEvents.EmitRemotePreparedSent( + resource, + Guid.NewGuid(), + DateTime.UtcNow, + manager, + DateTime.UtcNow); + + var transition = await observer.WaitForNextTransitionAsync( + afterSequence, + GetDeadline(TimeSpan.FromSeconds(1))); + + Assert.Equal(TransactionRecoveryEventObserver.RecoveryTransitionKind.RemotePreparedSent, transition.Kind); + } + + [Fact] + public async Task RecoveryObserverPhaseGateBlocksAtTransitionUntilReleased() + { + var resource = CreateParticipant("manager", ParticipantId.Role.Manager); + var transactionId = Guid.NewGuid(); + var timeStamp = DateTime.UtcNow; + var siloAddress = SiloAddress.New(IPAddress.Loopback, 22_223, 10); + var activationId = ActivationId.NewId(); + var identity = new TransactionDiagnosticEvents.TransactionDiagnosticIdentity(siloAddress, activationId); + using var observer = new TransactionRecoveryEventObserver(candidate => candidate.Name == resource.Name); + using var gate = observer.GateNextTransition(transition => + transition.Kind == TransactionRecoveryEventObserver.RecoveryTransitionKind.TransactionManagerWaitingForPrepared); + + var emission = Task.Run(() => TransactionDiagnosticEvents.EmitTransactionManagerWaitingForPrepared( + resource, + transactionId, + timeStamp, + waitCount: 2, + deadline: timeStamp.AddSeconds(10), + identity)); + var transition = await gate.WaitAsync(GetDeadline(TimeSpan.FromSeconds(1))); + + Assert.False(emission.IsCompleted); + Assert.Equal(transactionId, transition.TransactionId); + Assert.Equal(TransactionDiagnosticEvents.TransactionPhase.WaitingForRemotePrepares, transition.Phase); + Assert.Equal(siloAddress, transition.SiloAddress); + Assert.Equal(activationId, transition.ActivationId); + + gate.Release(); + await emission; + } + + [Fact] + public async Task RecoveryObserverCleanupGateIgnoresUnrelatedConfirmation() + { + var resource = CreateParticipant("resource", ParticipantId.Role.Resource); + var committedTransactionId = Guid.NewGuid(); + var unrelatedTransactionId = Guid.NewGuid(); + var timeStamp = DateTime.UtcNow; + using var observer = new TransactionRecoveryEventObserver(candidate => candidate.Name == resource.Name); + using var gate = observer.GateNextTransition(transition => + transition.Kind == TransactionRecoveryEventObserver.RecoveryTransitionKind.TransactionConfirmCompleted + && transition.TransactionId == committedTransactionId); + var wait = gate.WaitAsync(GetDeadline(TimeSpan.FromSeconds(1))); + + TransactionDiagnosticEvents.EmitTransactionConfirmCompleted( + resource, + unrelatedTransactionId, + timeStamp, + TransactionalStatus.Ok, + queueEntryFound: true, + succeeded: true); + + Assert.False(wait.IsCompleted); + + var matchingEmission = Task.Run(() => TransactionDiagnosticEvents.EmitTransactionConfirmCompleted( + resource, + committedTransactionId, + timeStamp, + TransactionalStatus.Ok, + queueEntryFound: true, + succeeded: true)); + var transition = await wait; + + Assert.Equal(committedTransactionId, transition.TransactionId); + Assert.False(matchingEmission.IsCompleted); + + gate.Release(); + await matchingEmission; + } + + [Fact] + public async Task RecoveryObserverHonorsCancellationAndDeadline() + { + using var observer = new TransactionRecoveryEventObserver(_ => true); + using var canceled = new CancellationTokenSource(); + canceled.Cancel(); + + await Assert.ThrowsAnyAsync( + () => observer.WaitForNextTransitionAsync( + observer.LatestRelevantSequence, + GetDeadline(TimeSpan.FromSeconds(1)), + canceled.Token)); + + var timeout = await Assert.ThrowsAsync( + () => observer.WaitForNextTransitionAsync( + observer.LatestRelevantSequence, + GetDeadline(TimeSpan.FromMilliseconds(20)))); + Assert.Contains("Transaction recovery timeline: ", timeout.Message); + } + + [Fact] + public void RecoveryObserverTimelineIsMonotonicAndDiagnostic() + { + var resource = CreateParticipant("resource", ParticipantId.Role.Resource); + var transactionId = Guid.NewGuid(); + var cohortTransactionId = Guid.NewGuid(); + var transactionIds = ImmutableArray.Create(transactionId, cohortTransactionId); + var conflict = new InconsistentStateException("Load conflict", storedEtag: "1", currentEtag: "2"); + var siloAddress = SiloAddress.New(IPAddress.Loopback, 22_222, 9); + var activationId = ActivationId.NewId(); + var identity = new TransactionDiagnosticEvents.TransactionDiagnosticIdentity(siloAddress, activationId); + using var observer = new TransactionRecoveryEventObserver(candidate => candidate.Name == resource.Name); + + TransactionDiagnosticEvents.EmitPrepareTimedOut( + resource, + transactionId, + DateTime.UtcNow, + remainingCount: 2, + DateTime.UtcNow, + identity); + TransactionDiagnosticEvents.EmitTransactionManagerAbortDecisionCompleted( + resource, + transactionId, + DateTime.UtcNow, + TransactionalStatus.PrepareTimeout, + identity); + TransactionDiagnosticEvents.EmitStorageConflictDetected( + resource, + TransactionDiagnosticEvents.StorageOperation.Load, + storageOutcomeInDoubt: false, + queuedTransactionCount: transactionIds.Length, + conflict, + transactionIds, + identity); + TransactionDiagnosticEvents.EmitQueueRestoreFailed( + resource, + conflict, + storageConflict: true, + transactionIds, + identity); + TransactionDiagnosticEvents.EmitTransactionCancelCompleted( + resource, + transactionId, + DateTime.UtcNow, + TransactionalStatus.PresumedAbort, + queueEntryFound: true, + succeeded: true, + identity); + TransactionDiagnosticEvents.EmitTransactionConfirmCompleted( + resource, + transactionId, + DateTime.UtcNow, + TransactionalStatus.Ok, + queueEntryFound: false, + succeeded: true, + identity); + TransactionDiagnosticEvents.EmitLockBroken( + resource, + transactionId, + TransactionDiagnosticEvents.LockBreakReason.Expired, + identity); + + var timeline = observer.GetTimeline(); + Assert.Collection( + timeline, + first => Assert.Equal(1, first.Sequence), + second => Assert.Equal(2, second.Sequence), + third => Assert.Equal(3, third.Sequence), + fourth => Assert.Equal(4, fourth.Sequence), + fifth => Assert.Equal(5, fifth.Sequence), + sixth => Assert.Equal(6, sixth.Sequence), + seventh => Assert.Equal(7, seventh.Sequence)); + var diagnostics = observer.FormatTimeline(); + Assert.Contains(transactionId.ToString(), diagnostics); + Assert.Contains(cohortTransactionId.ToString(), diagnostics); + Assert.Contains("resource=resource", diagnostics); + Assert.Contains("status=remaining=2", diagnostics); + Assert.Contains("kind=TransactionManagerAbortDecisionCompleted", diagnostics); + Assert.Contains("status=PrepareTimeout", diagnostics); + Assert.Contains("operation=Load", diagnostics); + Assert.Contains("kind=QueueRestoreFailed", diagnostics); + Assert.Contains("kind=TransactionCancelCompleted", diagnostics); + Assert.Contains("PresumedAbort, queueEntryFound=True, succeeded=True", diagnostics); + Assert.Contains("role=RemoteParticipant, phase=Cancel", diagnostics); + Assert.Contains("kind=TransactionConfirmCompleted", diagnostics); + Assert.Contains("Ok, queueEntryFound=False, succeeded=True", diagnostics); + Assert.Contains("role=RemoteParticipant, phase=Confirm", diagnostics); + Assert.Contains("status=Expired", diagnostics); + Assert.Contains($"silo={siloAddress}", diagnostics); + Assert.Contains($"activation={activationId}", diagnostics); + } + + private static ParticipantId CreateParticipant(string name, ParticipantId.Role role) + => CreateParticipant(name, reference: null!, role); + + private static ParticipantId CreateParticipant( + string name, + GrainReference reference, + ParticipantId.Role role) => new(name, reference, role); + + private static GrainReference CreateGrainReference(string key) + => new TestGrainReference(GrainId.Create("transaction-diagnostics-test", key)); + + private static long GetDeadline(TimeSpan timeout) + => Stopwatch.GetTimestamp() + (long)(timeout.TotalSeconds * Stopwatch.Frequency); + + private sealed class RecordingObserver : IObserver + { + private readonly ConcurrentQueue events = new(); + + public void OnCompleted() + { + } + + public void OnError(Exception error) + { + } + + public void OnNext(TransactionDiagnosticEvents.TransactionDiagnosticEvent value) => events.Enqueue(value); + + public T Single(ParticipantId resource) + where T : TransactionDiagnosticEvents.TransactionDiagnosticEvent + => Assert.Single(events.OfType(), evt => evt.Resource.Name == resource.Name); + + public IEnumerable All(ParticipantId resource) + where T : TransactionDiagnosticEvents.TransactionDiagnosticEvent + => events.OfType().Where(evt => evt.Resource.Name == resource.Name); + } + + private sealed class ThrowingObserver : IObserver + { + public void OnCompleted() + { + } + + public void OnError(Exception error) + { + } + + public void OnNext(TransactionDiagnosticEvents.TransactionDiagnosticEvent value) + => throw new InvalidOperationException("Observer fault"); + } + + private sealed class RawDiagnosticObserver : IObserver> + { + public void OnCompleted() + { + } + + public void OnError(Exception error) + { + } + + public void OnNext(KeyValuePair value) + { + } + } + + private sealed class TestGrainReference(GrainId grainId) + : GrainReference( + new GrainReferenceShared( + grainId.Type, + default, + interfaceVersion: 0, + runtime: null!, + invokeMethodOptions: default, + codecProvider: null!, + copyContextPool: null!, + serviceProvider: null!), + grainId.Key); +} diff --git a/test/Transactions/Orleans.Transactions.Tests/TransactionRecoveryFailureObservationTests.cs b/test/Transactions/Orleans.Transactions.Tests/TransactionRecoveryFailureObservationTests.cs new file mode 100644 index 00000000000..7f0e9c64e83 --- /dev/null +++ b/test/Transactions/Orleans.Transactions.Tests/TransactionRecoveryFailureObservationTests.cs @@ -0,0 +1,143 @@ +using System.Diagnostics; +using Orleans.Transactions.TestKit; +using TestExtensions; +using Xunit; + +namespace Orleans.Transactions.Tests; + +[TestCategory("BVT"), TestCategory("Transactions")] +public class TransactionRecoveryFailureObservationTests +{ + [Fact] + public async Task DetectAsync_NonCancellableProducerTimesOutAndStopsProducing() + { + var producer = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var failure = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + using var stopProducing = new CancellationTokenSource(); + var responseWindow = TimeSpan.FromMilliseconds(25); + var schedulingMargin = TimeSpan.FromMilliseconds(25); + + var outcome = await TransactionRecoveryFailureObservation.DetectAsync( + producer.Task, + failure.Task, + stopProducing, + responseWindow, + schedulingMargin); + + Assert.Equal(TransactionRecoveryFailureObservation.OutcomeKind.AttemptTimedOut, outcome.Kind); + Assert.Null(outcome.Failure); + Assert.Equal(0, outcome.ProducerResult); + Assert.False(outcome.ProducerSettled); + Assert.True(stopProducing.IsCancellationRequested); + Assert.False(producer.Task.IsCompleted); + Assert.True(outcome.Elapsed >= responseWindow + schedulingMargin); + Assert.InRange( + outcome.Elapsed, + responseWindow + schedulingMargin, + responseWindow + schedulingMargin + TimeSpan.FromSeconds(5)); + Assert.InRange(outcome.DrainElapsed, TimeSpan.Zero, schedulingMargin + TimeSpan.FromSeconds(5)); + } + + [Fact] + public async Task DetectAsync_FailureAtWatchdogBoundaryWinsOverSettledProducer() + { + var producer = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var failure = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var expectedFailure = new InvalidOperationException("Failure at the watchdog boundary"); + using var stopProducing = new CancellationTokenSource(); + using var registration = stopProducing.Token.Register( + () => + { + producer.TrySetResult(73); + failure.TrySetResult(expectedFailure); + }); + + var outcome = await TransactionRecoveryFailureObservation.DetectAsync( + producer.Task, + failure.Task, + stopProducing, + responseWindow: TimeSpan.Zero, + schedulingMargin: TimeSpan.FromSeconds(1)); + + Assert.Equal(TransactionRecoveryFailureObservation.OutcomeKind.FailureObserved, outcome.Kind); + Assert.Same(expectedFailure, outcome.Failure); + Assert.Equal(73, outcome.ProducerResult); + Assert.True(outcome.ProducerSettled); + Assert.True(stopProducing.IsCancellationRequested); + Assert.True(producer.Task.IsCompletedSuccessfully); + } + + [Fact] + public async Task DetectAsync_CancellationBetweenAttemptsStartsNoNextAttempt() + { + var firstAttemptStarted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var finishFirstAttempt = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var betweenAttempts = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var cancellationObserved = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var failure = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + using var stopProducing = new CancellationTokenSource(); + using var registration = stopProducing.Token.Register(() => cancellationObserved.TrySetResult()); + var attemptCount = 0; + var activeAttempts = 0; + var maximumActiveAttempts = 0; + + async Task ProduceAsync() + { + while (!stopProducing.IsCancellationRequested) + { + var active = Interlocked.Increment(ref activeAttempts); + maximumActiveAttempts = Math.Max(maximumActiveAttempts, active); + Interlocked.Increment(ref attemptCount); + firstAttemptStarted.TrySetResult(); + await finishFirstAttempt.Task; + Interlocked.Decrement(ref activeAttempts); + + betweenAttempts.TrySetResult(); + await cancellationObserved.Task; + } + + return attemptCount; + } + + var producer = ProduceAsync(); + await firstAttemptStarted.Task; + finishFirstAttempt.TrySetResult(); + await betweenAttempts.Task; + + var outcome = await TransactionRecoveryFailureObservation.DetectAsync( + producer, + failure.Task, + stopProducing, + responseWindow: TimeSpan.Zero, + schedulingMargin: TimeSpan.FromSeconds(1)); + + Assert.Equal(TransactionRecoveryFailureObservation.OutcomeKind.StoppedWithoutFailure, outcome.Kind); + Assert.Null(outcome.Failure); + Assert.Equal(1, outcome.ProducerResult); + Assert.True(outcome.ProducerSettled); + Assert.True(producer.IsCompletedSuccessfully); + Assert.Equal(1, attemptCount); + Assert.Equal(1, maximumActiveAttempts); + Assert.Equal(0, activeAttempts); + } + + [Fact] + public async Task FaultAfterInFlightSignalAndBeforeShutdownIsPremature() + { + var mutation = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var inFlight = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var observedFailure = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var observation = TransactionRecoveryFailureObservation.ObserveAsync( + mutation.Task, + (_, observedAt) => observedFailure.TrySetResult(observedAt)); + + inFlight.TrySetResult(); + await inFlight.Task; + mutation.TrySetException(new InvalidOperationException("Pre-shutdown transaction fault")); + var observedAt = await observedFailure.Task; + var shutdownRequestedAt = Stopwatch.GetTimestamp(); + await observation; + + Assert.True(TransactionRecoveryFailureObservation.IsPremature(observedAt, shutdownRequestedAt)); + } +} diff --git a/test/Transactions/Orleans.Transactions.Tests/TransactionRecoveryLatencyTests.cs b/test/Transactions/Orleans.Transactions.Tests/TransactionRecoveryLatencyTests.cs new file mode 100644 index 00000000000..f5399f32688 --- /dev/null +++ b/test/Transactions/Orleans.Transactions.Tests/TransactionRecoveryLatencyTests.cs @@ -0,0 +1,749 @@ +using System.Collections.Concurrent; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Options; +using Orleans.Configuration; +using Orleans.Runtime; +using Orleans.Timers.Internal; +using Orleans.Transactions.Abstractions; +using Orleans.Transactions.Diagnostics; +using Orleans.Transactions.State; +using TestExtensions; +using Xunit; + +namespace Orleans.Transactions.Tests; + +[TestCategory("BVT"), TestCategory("Transactions")] +public class TransactionRecoveryLatencyTests +{ + [Fact] + public void RestoredRemoteCommitUsesBoundedExponentialPingRetry() + { + var frequency = TimeSpan.FromSeconds(60); + var sentAt = new DateTime(2026, 8, 8, 12, 0, 0, DateTimeKind.Utc); + var record = new TransactionRecord + { + Role = CommitRole.RemoteCommit, + LastSent = DateTime.MinValue, + IsRestoredRemoteCommit = true, + }; + + Assert.Equal(DateTime.MinValue, record.GetNextRemotePingAt(frequency)); + + foreach (var expectedDelay in new[] { 1, 2, 4, 8, 16, 32, 60, 60 }) + { + record.RecordRemotePingSent(sentAt); + Assert.Equal(sentAt.AddSeconds(expectedDelay), record.GetNextRemotePingAt(frequency)); + sentAt = record.GetNextRemotePingAt(frequency); + } + } + + [Fact] + public void FreshRemoteCommitRetainsFirstPingGraceThenUsesBoundedExponentialRetry() + { + var frequency = TransactionalStateOptions.DefaultRemoteTransactionPingFrequency; + var sentAt = new DateTime(2026, 8, 8, 12, 0, 0, DateTimeKind.Utc); + var record = new TransactionRecord + { + Role = CommitRole.RemoteCommit, + LastSent = sentAt, + }; + + Assert.Equal(sentAt.AddSeconds(60), record.GetNextRemotePingAt(frequency)); + + sentAt = sentAt.Add(frequency); + foreach (var expectedDelay in new[] { 1, 2, 4, 8, 16, 32, 60, 60 }) + { + record.RecordRemotePingSent(sentAt); + Assert.Equal(sentAt.AddSeconds(expectedDelay), record.GetNextRemotePingAt(frequency)); + sentAt = record.GetNextRemotePingAt(frequency); + } + } + + [Fact] + public void StorageBatchTracksCommittedTransactionIds() + { + var firstTransactionId = Guid.NewGuid(); + var secondTransactionId = Guid.NewGuid(); + var batch = new StorageBatch( + new TransactionalStateMetaData(), + etag: null, + confirmUpTo: 0, + cancelAbove: 0); + + batch.Commit(firstTransactionId, DateTime.UtcNow, []); + batch.Commit(secondTransactionId, DateTime.UtcNow, []); + + Assert.Equal(2, batch.CommitCount); + Assert.Equal( + new[] { firstTransactionId, secondTransactionId }, + batch.CommittedTransactionIds.ToArray()); + } + + [Fact] + public void CompletedFanOutWinsAfterCleanupDeadlineWasSelected() + { + var fanOut = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var cleanupDeadline = Task.CompletedTask; + + Assert.True(TransactionQueue.ShouldAbandonCancelFanOut(fanOut.Task, cleanupDeadline)); + + fanOut.SetResult(); + + Assert.False(TransactionQueue.ShouldAbandonCancelFanOut(fanOut.Task, cleanupDeadline)); + } + + [Fact] + public async Task AlreadyCompletedFanOutWinsWhenCleanupDeadlineIsAlsoComplete() + { + var fanOut = Task.CompletedTask; + var cleanupDeadline = Task.CompletedTask; + + var completed = await Task.WhenAny(fanOut, cleanupDeadline); + + Assert.Same(fanOut, completed); + Assert.False(TransactionQueue.ShouldAbandonCancelFanOut(fanOut, completed)); + } + + [Fact] + public async Task LocalAbortCompletesManagerDecisionAfterDispatchAndBeforeCleanupSettles() + { + var manager = CreateParticipant( + "manager", + ParticipantId.Role.Manager | ParticipantId.Role.Resource); + var remoteOne = CreateParticipant("remote-one", ParticipantId.Role.Resource); + var remoteTwo = CreateParticipant("remote-two", ParticipantId.Role.Resource); + var remoteOneDispatchGate = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var remoteOneGate = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var remoteTwoGate = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var activationId = ActivationId.NewId(); + var identity = new TransactionDiagnosticEvents.TransactionDiagnosticIdentity(null, activationId); + var queue = new GatedCancelTransactionQueue( + manager, + new TestActivationLifetime(), + new Dictionary + { + [remoteOne.Name] = remoteOneGate.Task, + [remoteTwo.Name] = remoteTwoGate.Task, + }, + new Dictionary + { + [remoteOne.Name] = remoteOneDispatchGate.Task, + }, + identity); + var protocol = new ManagerAbortProtocol(queue); + var agent = CreateTransactionAgent(protocol); + var transactionId = Guid.NewGuid(); + var timeStamp = new DateTime(2026, 8, 8, 12, 0, 0, DateTimeKind.Utc); + var transaction = new TransactionInfo(transactionId, timeStamp, timeStamp); + transaction.RecordWrite(manager, timeStamp); + transaction.RecordWrite(remoteOne, timeStamp); + transaction.RecordWrite(remoteTwo, timeStamp); + var observer = new RecordingObserver(transactionId); + using var subscription = TransactionDiagnosticEvents.AllEvents.Subscribe(observer); + + var resolution = Task.Run(async () => await agent.Resolve(transaction)); + Assert.True(SpinWait.SpinUntil( + () => protocol.ManagerPromise is not null && queue.CancelSendCount == 1, + TimeSpan.FromSeconds(1))); + + var promise = Assert.IsType>(protocol.ManagerPromise); + Assert.False(promise.Task.IsCompleted); + Assert.False(resolution.IsCompleted); + Assert.Equal(remoteOne.Name, Assert.Single(queue.CancelInvocations).Target.Name); + + remoteOneDispatchGate.TrySetResult(); + Assert.True(SpinWait.SpinUntil( + () => queue.CancelSendCount == 2 + && protocol.ManagerFanOutTask is not null + && promise.Task.IsCompleted + && resolution.IsCompleted, + TimeSpan.FromSeconds(1))); + + var managerFanOut = Assert.IsAssignableFrom(protocol.ManagerFanOutTask); + Assert.False(managerFanOut.IsCompleted); + Assert.Equal(TransactionalStatus.PrepareTimeout, await promise.Task); + var (status, exception) = await resolution; + Assert.Equal(TransactionalStatus.PrepareTimeout, status); + Assert.Null(exception); + Assert.Equal(0, protocol.TransactionAgentCancelCount); + Assert.Collection( + observer.Events.Take(4), + evt => Assert.IsType(evt), + evt => Assert.IsType(evt), + evt => Assert.IsType(evt), + evt => + { + var decision = Assert.IsType(evt); + Assert.Equal(TransactionalStatus.PrepareTimeout, decision.Status); + }); + + remoteTwoGate.TrySetResult(); + remoteOneGate.TrySetResult(); + await Task.WhenAll(queue.CancelInvocations.Select(send => send.SendTask)); + await managerFanOut; + Assert.True(managerFanOut.IsCompletedSuccessfully); + Assert.Equal( + new[] { remoteOne.Name, remoteTwo.Name }, + queue.CancelInvocations.Select(send => send.Target.Name).Order()); + Assert.All( + queue.CancelInvocations, + send => + { + Assert.Equal(TransactionalStatus.PrepareTimeout, send.Status); + Assert.Equal(TransactionDiagnosticEvents.CancelReason.TransactionAbort, send.Reason); + }); + Assert.IsType(observer.Events[^1]); + Assert.All(observer.Events, evt => Assert.Equal(activationId, evt.ActivationId)); + } + + [Fact] + public async Task LocalAbortWithCanceledActivationDispatchesOnceAndCompletesOriginalDecision() + { + var reference = CreateGrainReference("already-deactivating"); + var manager = CreateParticipant("manager", reference, ParticipantId.Role.Manager); + var remote = CreateParticipant("remote", ParticipantId.Role.Resource); + var selfResource = CreateParticipant("self-resource", reference, ParticipantId.Role.Resource); + var remoteGate = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var selfGate = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var lifetime = new TestActivationLifetime(); + lifetime.Cancel(); + var queue = new GatedCancelTransactionQueue( + manager, + lifetime, + new Dictionary + { + [remote.Name] = remoteGate.Task, + [selfResource.Name] = selfGate.Task, + }); + var protocol = new ManagerAbortProtocol(queue); + var agent = CreateTransactionAgent(protocol); + var timeStamp = new DateTime(2026, 8, 8, 12, 0, 0, DateTimeKind.Utc); + var transaction = new TransactionInfo(Guid.NewGuid(), timeStamp, timeStamp); + transaction.RecordWrite(manager, timeStamp); + transaction.RecordWrite(remote, timeStamp); + transaction.RecordWrite(selfResource, timeStamp); + + var resolution = agent.Resolve(transaction); + Assert.True(SpinWait.SpinUntil( + () => queue.CancelSendCount == 2 + && protocol.ManagerPromise is not null + && protocol.ManagerPromise.Task.IsCompleted, + TimeSpan.FromSeconds(1))); + var (status, exception) = await resolution.WaitAsync(TimeSpan.FromSeconds(1)); + + Assert.Equal(TransactionalStatus.PrepareTimeout, status); + Assert.Null(exception); + Assert.Equal(TransactionalStatus.PrepareTimeout, await protocol.ManagerPromise!.Task); + Assert.True(protocol.ManagerFanOutTask!.IsCompletedSuccessfully); + Assert.Equal(2, queue.CancelSendCount); + Assert.Equal(1, queue.CancelInvocations.Count(send => send.Target.Equals(remote))); + Assert.Equal(1, queue.CancelInvocations.Count(send => send.Target.Equals(selfResource))); + Assert.Contains(queue.CancelInvocations, send => send.Target.Equals(selfResource) && send.IsSelf); + Assert.All( + queue.CancelInvocations, + send => + { + Assert.False(send.SendTask.IsCompleted); + Assert.Equal(TransactionalStatus.PrepareTimeout, send.Status); + Assert.Equal(TransactionDiagnosticEvents.CancelReason.TransactionAbort, send.Reason); + }); + Assert.Equal(1, protocol.ManagerFanOutCount); + Assert.Equal(0, protocol.TransactionAgentCancelCount); + + var remoteSend = queue.CancelInvocations.Single(send => send.Target.Equals(remote)); + var selfSend = queue.CancelInvocations.Single(send => send.Target.Equals(selfResource)); + remoteGate.TrySetResult(); + await remoteSend.SendTask.WaitAsync(TimeSpan.FromSeconds(1)); + Assert.False(selfSend.SendTask.IsCompleted); + + selfGate.TrySetResult(); + await selfSend.SendTask.WaitAsync(TimeSpan.FromSeconds(1)); + } + + [Fact] + public async Task LocalAbortDeactivationBoundsNeverCompletingCancelAndDiagnosesCancellation() + { + var manager = CreateParticipant("manager", ParticipantId.Role.Manager); + var remote = CreateParticipant("remote", ParticipantId.Role.Resource); + var remoteGate = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var lifetime = new TestActivationLifetime(); + var queue = new GatedCancelTransactionQueue( + manager, + lifetime, + new Dictionary { [remote.Name] = remoteGate.Task }); + var record = CreateLocalCommitRecord(manager, remote); + var observer = new RecordingObserver(record.TransactionId); + using var subscription = TransactionDiagnosticEvents.AllEvents.Subscribe(observer); + + var notification = queue.NotifyOfAbort(record, TransactionalStatus.PrepareTimeout, exception: null); + var send = Assert.Single(queue.CancelInvocations); + + Assert.False(send.SendTask.IsCompleted); + Assert.Equal(TransactionalStatus.PrepareTimeout, await record.PromiseForTA.Task); + Assert.False(notification.IsCompleted); + + lifetime.Cancel(); + await notification; + + Assert.False(send.SendTask.IsCompleted); + Assert.Equal(TransactionalStatus.PrepareTimeout, send.Status); + Assert.IsType( + observer.Events.Single(evt => evt is TransactionDiagnosticEvents.TransactionManagerAbortDecisionCompleted)); + var failed = Assert.Single(observer.Events.OfType()); + Assert.Equal(TransactionalStatus.PrepareTimeout, failed.Status); + Assert.Equal(1, failed.TargetCount); + Assert.Equal(0, failed.SelfTargetCount); + Assert.EndsWith("CanceledException", failed.ExceptionType); + Assert.Single(observer.Events.OfType()); + Assert.Empty(observer.Events.OfType()); + Assert.Empty(observer.Events.OfType()); + Assert.IsType(observer.Events[^1]); + + remoteGate.TrySetResult(); + await send.SendTask; + } + + [Fact] + public async Task LocalAbortCleanupTimeoutCompletesBeforeOuterDeadlineWithoutDuplicateFanOut() + { + var manager = CreateParticipant( + "manager", + ParticipantId.Role.Manager | ParticipantId.Role.Resource); + var remote = CreateParticipant("remote", ParticipantId.Role.Resource); + var cancelGate = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var cleanupTimeout = TimeSpan.FromMilliseconds(250); + var queue = new GatedCancelTransactionQueue( + manager, + new TestActivationLifetime(), + new Dictionary { [remote.Name] = cancelGate.Task }, + options: new TransactionalStateOptions { LockTimeout = cleanupTimeout }); + var protocol = new ManagerAbortProtocol(queue); + var agent = CreateTransactionAgent(protocol); + var timeStamp = new DateTime(2026, 8, 8, 12, 0, 0, DateTimeKind.Utc); + var transaction = new TransactionInfo(Guid.NewGuid(), timeStamp, timeStamp); + transaction.RecordWrite(manager, timeStamp); + transaction.RecordWrite(remote, timeStamp); + var observer = new RecordingObserver(transaction.TransactionId); + using var subscription = TransactionDiagnosticEvents.AllEvents.Subscribe(observer); + var outerDeadline = TimeSpan.FromSeconds(2); + + var resolution = agent.Resolve(transaction); + + Assert.True(SpinWait.SpinUntil( + () => protocol.ManagerPromise is not null + && protocol.ManagerFanOutTask is not null + && queue.CancelSendCount == 1 + && protocol.ManagerPromise.Task.IsCompleted + && resolution.IsCompleted, + TimeSpan.FromSeconds(1))); + + Assert.False(protocol.ManagerFanOutTask!.IsCompleted); + var (status, exception) = await resolution.WaitAsync(outerDeadline); + + Assert.Equal(TransactionalStatus.PrepareTimeout, status); + Assert.Null(exception); + Assert.Equal(1, queue.CancelSendCount); + Assert.Equal(1, protocol.ManagerFanOutCount); + Assert.Equal(0, protocol.TransactionAgentCancelCount); + Assert.Equal(TransactionalStatus.PrepareTimeout, await protocol.ManagerPromise!.Task); + var send = Assert.Single(queue.CancelInvocations); + Assert.False(send.SendTask.IsCompleted); + Assert.Equal(TransactionalStatus.PrepareTimeout, send.Status); + Assert.Equal(TransactionDiagnosticEvents.CancelReason.TransactionAbort, send.Reason); + + await protocol.ManagerFanOutTask.WaitAsync(outerDeadline); + + Assert.True(protocol.ManagerFanOutTask.IsCompletedSuccessfully); + var failed = Assert.Single(observer.Events.OfType()); + Assert.Equal(typeof(TimeoutException).FullName, failed.ExceptionType); + Assert.Equal(TransactionalStatus.PrepareTimeout, failed.Status); + Assert.Equal(1, failed.TargetCount); + Assert.Equal(0, failed.SelfTargetCount); + Assert.Single(observer.Events.OfType()); + Assert.Empty(observer.Events.OfType()); + Assert.Empty(observer.Events.OfType()); + Assert.IsType( + observer.Events.Single(evt => evt is TransactionDiagnosticEvents.TransactionManagerAbortDecisionCompleted)); + Assert.IsType(observer.Events[^1]); + + cancelGate.TrySetResult(); + await send.SendTask.WaitAsync(outerDeadline); + } + + [Fact] + public async Task SelfDirectedCancelDuringDeactivationIsInitiatedOnceAndDiagnosedAsSelf() + { + var reference = CreateGrainReference("shared-transactional-state"); + var manager = CreateParticipant("manager", reference, ParticipantId.Role.Manager); + var selfResource = CreateParticipant("resource-alias", reference, ParticipantId.Role.Resource); + var selfGate = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var lifetime = new TestActivationLifetime(); + var queue = new GatedCancelTransactionQueue( + manager, + lifetime, + new Dictionary { [selfResource.Name] = selfGate.Task }); + var record = CreateLocalCommitRecord(manager, selfResource); + var observer = new RecordingObserver(record.TransactionId); + using var subscription = TransactionDiagnosticEvents.AllEvents.Subscribe(observer); + + var notification = queue.NotifyOfAbort(record, TransactionalStatus.PrepareTimeout, exception: null); + var send = Assert.Single(queue.CancelInvocations); + + Assert.Equal("resource-alias", send.Target.Name); + Assert.True(send.IsSelf); + Assert.False(send.SendTask.IsCompleted); + Assert.Equal(TransactionalStatus.PrepareTimeout, await record.PromiseForTA.Task); + Assert.False(notification.IsCompleted); + + lifetime.Cancel(); + await notification; + + Assert.Equal(1, queue.CancelSendCount); + Assert.False(send.SendTask.IsCompleted); + var sendStarted = Assert.Single(observer.Events.OfType()); + Assert.True(sendStarted.IsSelf); + Assert.Equal(selfResource, sendStarted.Target); + Assert.Equal(TransactionalStatus.PrepareTimeout, sendStarted.Status); + Assert.Equal(TransactionDiagnosticEvents.CancelReason.TransactionAbort, sendStarted.Reason); + var failed = Assert.Single(observer.Events.OfType()); + Assert.Equal(TransactionalStatus.PrepareTimeout, failed.Status); + Assert.Equal(1, failed.TargetCount); + Assert.Equal(1, failed.SelfTargetCount); + Assert.Empty(observer.Events.OfType()); + Assert.Empty(observer.Events.OfType()); + Assert.IsType( + observer.Events.Single(evt => evt is TransactionDiagnosticEvents.TransactionManagerAbortDecisionCompleted)); + Assert.IsType(observer.Events[^1]); + + selfGate.TrySetResult(); + await send.SendTask; + } + + [Fact] + public async Task ManagerOwnedAbortProducesOneFanOutAndNoTransactionAgentDuplicateCancel() + { + var manager = CreateParticipant( + "manager", + ParticipantId.Role.Manager | ParticipantId.Role.Resource); + var remote = CreateParticipant("remote", ParticipantId.Role.Resource); + var cancelGate = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var queue = new GatedCancelTransactionQueue( + manager, + new TestActivationLifetime(), + new Dictionary { [remote.Name] = cancelGate.Task }); + var protocol = new ManagerAbortProtocol(queue); + var agent = CreateTransactionAgent(protocol); + var timeStamp = new DateTime(2026, 8, 8, 12, 0, 0, DateTimeKind.Utc); + var transaction = new TransactionInfo(Guid.NewGuid(), timeStamp, timeStamp); + transaction.RecordWrite(manager, timeStamp); + transaction.RecordWrite(remote, timeStamp); + + var resolution = agent.Resolve(transaction); + Assert.True(SpinWait.SpinUntil( + () => protocol.ManagerPromise is not null + && protocol.ManagerFanOutTask is not null + && queue.CancelSendCount == 1 + && protocol.ManagerPromise.Task.IsCompleted + && resolution.IsCompleted, + TimeSpan.FromSeconds(1))); + + var promise = Assert.IsType>(protocol.ManagerPromise); + var managerFanOut = Assert.IsAssignableFrom(protocol.ManagerFanOutTask); + Assert.False(managerFanOut.IsCompleted); + Assert.Equal(1, protocol.ManagerFanOutCount); + Assert.Equal(1, queue.CancelSendCount); + Assert.Equal(0, protocol.TransactionAgentCancelCount); + + var (status, exception) = await resolution; + + Assert.Equal(TransactionalStatus.PrepareTimeout, status); + Assert.Null(exception); + Assert.Equal(TransactionalStatus.PrepareTimeout, await promise.Task); + Assert.Equal(1, protocol.ManagerFanOutCount); + Assert.Equal(1, queue.CancelSendCount); + Assert.Equal(0, protocol.TransactionAgentCancelCount); + + cancelGate.TrySetResult(); + await managerFanOut; + + Assert.True(managerFanOut.IsCompletedSuccessfully); + } + + [Fact] + public async Task RepeatedRecoveryPingsRemainIdempotent() + { + var manager = CreateParticipant("manager", ParticipantId.Role.Manager); + var remote = CreateParticipant("remote", ParticipantId.Role.Resource); + var queue = new GatedCancelTransactionQueue(manager, new TestActivationLifetime()); + var transactionId = Guid.NewGuid(); + var timeStamp = new DateTime(2026, 8, 8, 12, 0, 0, DateTimeKind.Utc); + var observer = new RecordingObserver(transactionId); + using var subscription = TransactionDiagnosticEvents.AllEvents.Subscribe(observer); + + await queue.NotifyOfPing(transactionId, timeStamp, remote); + await queue.NotifyOfPing(transactionId, timeStamp, remote); + + Assert.Equal(2, observer.Events.OfType().Count()); + Assert.Equal(2, observer.Events.OfType().Count()); + Assert.All( + observer.Events.OfType(), + evt => + { + Assert.Equal(TransactionalStatus.PresumedAbort, evt.Status); + Assert.Equal(TransactionDiagnosticEvents.CancelReason.RecoveryPing, evt.Reason); + }); + } + + private static ParticipantId CreateParticipant(string name, ParticipantId.Role role) + => CreateParticipant(name, reference: null!, role); + + private static ParticipantId CreateParticipant( + string name, + GrainReference reference, + ParticipantId.Role role) => new(name, reference, role); + + private static GrainReference CreateGrainReference(string key) + => new TestGrainReference(GrainId.Create("transaction-recovery-test", key)); + + private static TransactionAgent CreateTransactionAgent(ITransactionAgentProtocol protocol) + => new( + new TestClock(), + NullLogger.Instance, + new TransactionAgentStatistics(), + new NeverOverloaded(), + protocol); + + private static TransactionRecord CreateLocalCommitRecord( + ParticipantId manager, + params ParticipantId[] participants) + => new() + { + Role = CommitRole.LocalCommit, + TransactionId = Guid.NewGuid(), + Timestamp = new DateTime(2026, 8, 8, 12, 0, 0, DateTimeKind.Utc), + PromiseForTA = new(TaskCreationOptions.RunContinuationsAsynchronously), + WriteParticipants = [manager, .. participants], + }; + + private sealed class TestState + { + } + + private sealed class GatedCancelTransactionQueue : TransactionQueue + { + private readonly IReadOnlyDictionary cancelGates; + private readonly IReadOnlyDictionary dispatchGates; + private readonly ConcurrentQueue cancelInvocations = new(); + + public int CancelSendCount => cancelInvocations.Count; + public IReadOnlyList CancelInvocations => cancelInvocations.ToArray(); + + public GatedCancelTransactionQueue( + ParticipantId resource, + IActivationLifetime activationLifetime, + IReadOnlyDictionary? cancelGates = null, + IReadOnlyDictionary? dispatchGates = null, + TransactionDiagnosticEvents.TransactionDiagnosticIdentity identity = default, + TransactionalStateOptions? options = null) + : base( + Options.Create(options ?? new TransactionalStateOptions()), + resource, + static () => { }, + null!, + new TestClock(), + NullLogger.Instance, + null!, + activationLifetime, + identity) + { + this.cancelGates = cancelGates ?? new Dictionary(); + this.dispatchGates = dispatchGates ?? new Dictionary(); + } + + protected override Task SendCancel( + ParticipantId target, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status, + TransactionDiagnosticEvents.CancelReason reason) + { + var isSelf = target.Reference is not null + && Resource.Reference is not null + && target.Reference.GrainId == Resource.Reference.GrainId; + var gate = cancelGates.TryGetValue(target.Name, out var configuredGate) + ? configuredGate + : Task.CompletedTask; + var invocation = new CancelInvocation(target, status, reason, isSelf); + cancelInvocations.Enqueue(invocation); + if (dispatchGates.TryGetValue(target.Name, out var dispatchGate)) + { + dispatchGate.GetAwaiter().GetResult(); + } + + invocation.SendTask = SendCancelCore( + invocation, + transactionId, + timeStamp, + gate); + return invocation.SendTask; + } + + private async Task SendCancelCore( + CancelInvocation invocation, + Guid transactionId, + DateTime timeStamp, + Task gate) + { + TransactionDiagnosticEvents.EmitCancelSendStarted( + Resource, + transactionId, + timeStamp, + invocation.Target, + invocation.IsSelf, + invocation.Status, + invocation.Reason, + DiagnosticIdentity); + await gate; + TransactionDiagnosticEvents.EmitCancelSendCompleted( + Resource, + transactionId, + timeStamp, + invocation.Target, + invocation.IsSelf, + invocation.Status, + invocation.Reason, + DiagnosticIdentity); + } + } + + private sealed class CancelInvocation( + ParticipantId target, + TransactionalStatus status, + TransactionDiagnosticEvents.CancelReason reason, + bool isSelf) + { + public ParticipantId Target { get; } = target; + public TransactionalStatus Status { get; } = status; + public TransactionDiagnosticEvents.CancelReason Reason { get; } = reason; + public bool IsSelf { get; } = isSelf; + public Task SendTask { get; set; } = null!; + } + + private sealed class ManagerAbortProtocol(GatedCancelTransactionQueue queue) : ITransactionAgentProtocol + { + public Task? ManagerFanOutTask { get; private set; } + public TaskCompletionSource? ManagerPromise { get; private set; } + public int ManagerFanOutCount { get; private set; } + public int TransactionAgentCancelCount { get; private set; } + + public void Prepare( + ParticipantId participant, + Guid transactionId, + AccessCounter accessCount, + DateTime timeStamp, + ParticipantId transactionManager) + { + } + + public Task PrepareAndCommit( + ParticipantId transactionManager, + Guid transactionId, + AccessCounter accessCount, + DateTime timeStamp, + List writeResources, + int totalParticipants) + { + var promise = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + ManagerPromise = promise; + var record = new TransactionRecord + { + Role = CommitRole.LocalCommit, + TransactionId = transactionId, + Timestamp = timeStamp, + PromiseForTA = promise, + WriteParticipants = writeResources, + }; + + ManagerFanOutCount++; + ManagerFanOutTask = queue.NotifyOfAbort(record, TransactionalStatus.PrepareTimeout, exception: null); + return promise.Task; + } + + public Task Cancel( + ParticipantId participant, + Guid transactionId, + DateTime timeStamp, + TransactionalStatus status) + { + TransactionAgentCancelCount++; + return Task.CompletedTask; + } + } + + private sealed class NeverOverloaded : ITransactionOverloadDetector + { + public bool IsOverloaded() => false; + } + + private sealed class TestClock : IClock + { + public DateTime UtcNow() => new(2026, 8, 8, 12, 0, 0, DateTimeKind.Utc); + } + + private sealed class TestActivationLifetime : IActivationLifetime + { + private readonly CancellationTokenSource cancellation = new(); + + public CancellationToken OnDeactivating => cancellation.Token; + + public IDisposable BlockDeactivation() => NullDisposable.Instance; + + public void Cancel() => cancellation.Cancel(); + } + + private sealed class TestGrainReference(GrainId grainId) + : GrainReference( + new GrainReferenceShared( + grainId.Type, + default, + interfaceVersion: 0, + runtime: null!, + invokeMethodOptions: default, + codecProvider: null!, + copyContextPool: null!, + serviceProvider: null!), + grainId.Key); + + private sealed class NullDisposable : IDisposable + { + public static NullDisposable Instance { get; } = new(); + + public void Dispose() + { + } + } + + private sealed class RecordingObserver(Guid transactionId) : IObserver + { + private readonly ConcurrentQueue events = new(); + + public IReadOnlyList Events => events.ToArray(); + + public void OnCompleted() + { + } + + public void OnError(Exception error) + { + } + + public void OnNext(TransactionDiagnosticEvents.TransactionDiagnosticEvent value) + { + if (value is TransactionDiagnosticEvents.TransactionEvent transactionEvent + && transactionEvent.TransactionId == transactionId) + { + events.Enqueue(value); + } + } + } +} From 76c7216427b323cdb0bdaa158aa1f2608cd0f664 Mon Sep 17 00:00:00 2001 From: Reuben Bond Date: Sun, 9 Aug 2026 16:28:14 -0700 Subject: [PATCH 2/4] fix(transactions): preserve lock expiration transaction id Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../TransactionRecoveryEventObserver.cs | 1 + .../TransactionDiagnosticEventsTests.cs | 23 +++++++++++++++++++ 2 files changed, 24 insertions(+) diff --git a/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryEventObserver.cs b/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryEventObserver.cs index f84bd650557..90f1b82e310 100644 --- a/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryEventObserver.cs +++ b/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryEventObserver.cs @@ -305,6 +305,7 @@ private static bool TryCreateTransition( { TransactionDiagnosticEvents.TransactionEvent transactionEvent => ImmutableArray.Create(transactionEvent.TransactionId), TransactionDiagnosticEvents.StorageWriteCompleted completedWrite => completedWrite.TransactionIds, + TransactionDiagnosticEvents.LockExpired lockExpired => ImmutableArray.Create(lockExpired.TransactionId), TransactionDiagnosticEvents.LockBroken lockBroken => ImmutableArray.Create(lockBroken.TransactionId), TransactionDiagnosticEvents.StorageConflictDetected conflict => conflict.TransactionIds, TransactionDiagnosticEvents.AbortAndRestoreCompleted restored => restored.TransactionIds, diff --git a/test/Transactions/Orleans.Transactions.Tests/TransactionDiagnosticEventsTests.cs b/test/Transactions/Orleans.Transactions.Tests/TransactionDiagnosticEventsTests.cs index 347f1d90f06..fa4f6918b0f 100644 --- a/test/Transactions/Orleans.Transactions.Tests/TransactionDiagnosticEventsTests.cs +++ b/test/Transactions/Orleans.Transactions.Tests/TransactionDiagnosticEventsTests.cs @@ -415,6 +415,29 @@ public async Task RecoveryObserverStorageWriteTransitionContainsCommittedTransac Assert.Equal(committedTransactionIds.Length, transition.CommitCount); } + [Fact] + public async Task RecoveryObserverLockExpiredTransitionContainsTransactionId() + { + var resource = CreateParticipant("resource", ParticipantId.Role.Resource); + var transactionId = Guid.NewGuid(); + var deadline = DateTime.UtcNow; + using var observer = new TransactionRecoveryEventObserver(candidate => candidate.Name == resource.Name); + + TransactionDiagnosticEvents.EmitLockExpired( + resource, + transactionId, + deadline, + deadline.AddMilliseconds(1), + TransactionDiagnosticEvents.LockExpirationKind.HeldLock); + + var transition = await observer.WaitForNextTransitionAsync( + afterSequence: 0, + GetDeadline(TimeSpan.FromSeconds(1))); + + Assert.Equal(TransactionRecoveryEventObserver.RecoveryTransitionKind.LockExpired, transition.Kind); + Assert.Equal(transactionId, transition.TransactionId); + } + [Fact] public void StorageWriteCompletedFaultScopeOnlyInjectsForMatchingCommittedTransactions() { From 9784c635e91cedc74e785092aa469bf99fbcf438 Mon Sep 17 00:00:00 2001 From: Reuben Bond Date: Sun, 9 Aug 2026 17:05:29 -0700 Subject: [PATCH 3/4] fix(transactions): stabilize recovery tests Honor absolute watchdog deadlines even when a timer wakes early, and allow targeted recovery attempts to complete transparently after the owning silo is terminated. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../TransactionRecoveryFailureObservation.cs | 24 +++++++++---------- .../TransactionRecoveryTestsRunner.cs | 5 ++-- 2 files changed, 14 insertions(+), 15 deletions(-) diff --git a/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryFailureObservation.cs b/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryFailureObservation.cs index 513044caba0..e47c5d2292a 100644 --- a/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryFailureObservation.cs +++ b/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryFailureObservation.cs @@ -173,28 +173,28 @@ await producer.ConfigureAwait(false), private static async Task WaitUntilAsync(Task first, long deadline) { - if (first.IsCompleted) + while (!first.IsCompleted) { - return; - } + var now = Stopwatch.GetTimestamp(); + if (now >= deadline) + { + return; + } - var now = Stopwatch.GetTimestamp(); - if (now < deadline) - { await Task.WhenAny(first, Task.Delay(Stopwatch.GetElapsedTime(now, deadline))).ConfigureAwait(false); } } private static async Task WaitUntilAsync(Task first, Task second, long deadline) { - if (first.IsCompleted || second.IsCompleted) + while (!first.IsCompleted && !second.IsCompleted) { - return; - } + var now = Stopwatch.GetTimestamp(); + if (now >= deadline) + { + return; + } - var now = Stopwatch.GetTimestamp(); - if (now < deadline) - { await Task.WhenAny(first, second, Task.Delay(Stopwatch.GetElapsedTime(now, deadline))).ConfigureAwait(false); } } diff --git a/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryTestsRunner.cs b/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryTestsRunner.cs index 64b2decb72c..0f9a6fce5bc 100644 --- a/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryTestsRunner.cs +++ b/src/Orleans.Transactions.TestKit.Base/TestRunners/TransactionRecoveryTestsRunner.cs @@ -225,8 +225,7 @@ private async Task TransactionWillRecoverAfterTargetedPhase( $"The transaction gated at {phase} did not settle within {this.failureDetectionTimeout}."); } - failedGroups.Should().NotBeNullOrEmpty( - $"terminating the activation blocked at {phase} must interrupt the gated transaction"); + var groupsToProbe = failedGroups ?? transactionGroups; var liveness = this.testCluster.WaitForLivenessToStabilizeAsync(didKill: true); try { @@ -238,7 +237,7 @@ private async Task TransactionWillRecoverAfterTargetedPhase( throw; } var recovery = await RecoverTransactions( - failedGroups!, + groupsToProbe, getIndex, this.recoveryTimeout, this.failureDetectionTimeout, From 693e7a472eab4b6570f4efb05d41cb6bfc9ad3bd Mon Sep 17 00:00:00 2001 From: Reuben Bond Date: Sun, 9 Aug 2026 17:44:22 -0700 Subject: [PATCH 4/4] fix(transactions): update storage queue test setup Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: a9491034-9b04-4ca3-b96b-949371ffea34 --- .../TransactionQueueStorageWorkTests.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/Transactions/Orleans.Transactions.Tests/TransactionQueueStorageWorkTests.cs b/test/Transactions/Orleans.Transactions.Tests/TransactionQueueStorageWorkTests.cs index 3486d6137c4..129efd88115 100644 --- a/test/Transactions/Orleans.Transactions.Tests/TransactionQueueStorageWorkTests.cs +++ b/test/Transactions/Orleans.Transactions.Tests/TransactionQueueStorageWorkTests.cs @@ -429,7 +429,7 @@ public TestTransactionQueue( Microsoft.Extensions.Logging.ILogger logger, ITimerManager timerManager, IActivationLifetime activationLifetime) - : base(options, resource, deactivate, storage, clock, logger, timerManager, activationLifetime) + : base(options, resource, deactivate, storage, clock, logger, timerManager, activationLifetime, diagnosticIdentity: default) { }