From 2eca3121c9a56cbd3f67756cf323cb6185e697f2 Mon Sep 17 00:00:00 2001 From: George Date: Sat, 25 Jul 2026 15:58:35 +0200 Subject: [PATCH 01/12] Separate outbox completion failures --- TinyEvents-Coding-Guide.md | 568 ++++++++++++++++++ TinyEvents-Worker-Error-Policy-Plan.md | 247 ++++++++ .../Processing/TinyOutboxProcessor.cs | 38 +- .../Processing/TinyOutboxProcessorTests.cs | 59 ++ 4 files changed, 902 insertions(+), 10 deletions(-) create mode 100644 TinyEvents-Coding-Guide.md create mode 100644 TinyEvents-Worker-Error-Policy-Plan.md diff --git a/TinyEvents-Coding-Guide.md b/TinyEvents-Coding-Guide.md new file mode 100644 index 0000000..bf1121e --- /dev/null +++ b/TinyEvents-Coding-Guide.md @@ -0,0 +1,568 @@ +# TinyEvents Coding Guide + +You are working on **TinyEvents**, a production-grade .NET transactional outbox library being prepared for its first stable `1.0.0` release. + +Treat this repository as the foundation of a small, high-quality software company. The objective is not merely to make the implementation correct. The code must be simple to understand, predictable to operate, difficult to misuse, and pleasant for experienced engineers to maintain. + +## Product standard + +TinyEvents should feel: + +- Small. +- Explicit. +- Predictable. +- Boring in the best possible way. +- Easy to learn from the public API. +- Easy to debug in production. +- Honest about its guarantees and limitations. +- Consistent across providers and integration styles. + +Do not optimise for showing technical cleverness. Optimise for clarity and long-term supportability. + +## Core engineering principles + +### Prefer obvious code + +Choose the implementation that a competent engineer can understand immediately. + +Do not introduce: + +- Clever abstractions. +- Dense expressions. +- Hidden control flow. +- Unnecessary indirection. +- Generic frameworks created for one use case. +- Reflection when explicit registration or generated code is available. +- "Reusable" helpers that make the calling code harder to understand. +- Patterns added only because they are fashionable. + +A small amount of duplication is acceptable when it keeps behaviour local and obvious. + +Do not remove meaningful duplication until the shared concept is genuinely stable and clearly named. + +### Use intention-revealing names + +Names must explain the business or runtime meaning. + +Prefer: + +- `claimedMessages` +- `leaseExpiresAtUtc` +- `processingAttempt` +- `consumerType` +- `retryDelay` +- `affectedRows` + +Avoid vague names such as: + +- `data` +- `item` +- `result` +- `manager` +- `helper` +- `handler` +- `processor` when the specific responsibility can be named +- `DoWork` +- `Execute` +- `Process` without enough context + +Boolean names should read naturally in a condition: + +```csharp +if (leaseHasExpired) +if (messageCanBeRetried) +if (consumerWasResolved) +``` + +Avoid inverted or confusing boolean names. + +### Make conditions readable + +Complex conditions must be decomposed into named concepts. + +Avoid: + +```csharp +if (message.Attempts < options.MaxAttempts && + (message.LeaseUntilUtc == null || message.LeaseUntilUtc < now) && + !string.IsNullOrWhiteSpace(message.Type)) +``` + +Prefer named variables or small focused methods: + +```csharp +var leaseHasExpired = message.LeaseUntilUtc is null || + message.LeaseUntilUtc < now; + +var messageCanBeRetried = message.Attempts < options.MaxAttempts; + +if (leaseHasExpired && messageCanBeRetried) +{ + ... +} +``` + +Do not extract trivial conditions merely to increase the number of methods. Extract them when the resulting name adds meaning. + +Use early returns to avoid deep nesting. + +### Keep methods focused + +A method should perform one understandable operation. + +Split methods when they independently: + +- Load data. +- Decide policy. +- Mutate state. +- Call user code. +- Persist a result. +- Translate an exception. +- Log an outcome. + +Do not split methods into tiny fragments that force the reader to jump between files to understand a basic flow. + +The complete happy path should remain easy to follow. + +### Be explicit about failure + +Never silently ignore a failure unless that behaviour is an intentional and documented contract. + +For important persistence operations: + +- Check affected row counts where ownership or concurrency matters. +- Distinguish cancellation from failure. +- Preserve useful exception context. +- Do not catch `Exception` merely to log and continue without a clear policy. +- Do not convert programming errors into retries. +- Do not hide provider failures behind generic success results. +- Do not let a failed lease update look like successful ownership. + +Failure behaviour must be visible through code, logs, exceptions, or durable state. + +### Be precise about cancellation + +Cancellation is not an operational failure. + +Follow these rules: + +- Pass cancellation tokens through all asynchronous calls that support them. +- Do not wrap `OperationCanceledException` as a processing error when cancellation was requested. +- Do not record cancellation as a failed message attempt unless the documented product behaviour explicitly requires it. +- Hosted workers must stop promptly and predictably. +- Cancellation checks should be placed at meaningful boundaries, not scattered arbitrarily. + +### Be honest about delivery semantics + +TinyEvents provides **at-least-once processing**, not exactly-once processing. + +Do not add wording or implementation that implies exactly-once delivery. + +Assume: + +- A consumer may run more than once. +- A process may stop after the consumer succeeds but before completion is persisted. +- Leases may expire. +- Another worker may retry an event. +- Consumers must be idempotent where duplicate effects matter. + +Documentation, naming, tests, and logs must reflect these realities. + +### Keep configuration predictable + +Configuration must not depend on service-registration order unless the behaviour is explicitly designed, documented, and tested. + +Rules: + +- A registration method must not silently replace unrelated configuration. +- Multiple configuration calls must have understandable composition semantics. +- Defaults must exist in one obvious place. +- Invalid options should fail early with useful messages. +- Configuration validation should preferably happen during application startup. +- Worker options and core processing options must not have ambiguous ownership. +- Avoid maintaining the same setting in two option classes unless there is an unavoidable boundary. + +A user must not need to understand internal dependency-injection implementation details to configure TinyEvents safely. + +### Protect the public API + +Every public type becomes a long-term support commitment. + +Before adding or retaining a public type, ask: + +1. Does an application developer need to reference it? +2. Is it part of a deliberate extension point? +3. Can it be internal without blocking legitimate use? +4. Is its name suitable for years of public support? +5. Does it expose implementation details that may need to change? + +Do not casually rename existing public APIs during hardening. + +When a public API change is proposed: + +- Explain why it is necessary before implementing it. +- Identify the migration impact. +- Prefer additive changes where reasonable. +- Do not create compatibility aliases unless the value outweighs the permanent API cost. + +### Keep provider behaviour symmetrical + +SQL Server and PostgreSQL implementations, and EF Core and ADO.NET integrations, must expose equivalent observable behaviour wherever the product contract is the same. + +Review parity for: + +- Claiming. +- Lease ownership. +- Retry eligibility. +- Attempt counting. +- Completion. +- Failure recording. +- Affected-row validation. +- Date and time handling. +- Cancellation. +- Table-name validation. +- Transaction behaviour. +- Serialization. +- Empty batches. +- Unknown event types. + +Provider-specific SQL may differ. Product semantics should not drift accidentally. + +### Use UTC consistently + +All persisted and compared timestamps must have explicit UTC semantics. + +Prefer names ending in `Utc` for relevant values. + +Do not mix: + +- Local time. +- Unspecified `DateTime`. +- Database server local time. +- Application UTC time. + +Use one clear clock abstraction if the repository already has one. Do not introduce a clock abstraction merely for fashion; introduce it only where deterministic tests or consistent semantics require it. + +### Logging should help operations + +Logs must answer: + +- Which event? +- Which event type? +- Which worker? +- Which attempt? +- What outcome? +- What will happen next? + +Do not log event payloads by default because they may contain sensitive application data. + +Avoid noisy logs inside tight polling loops. + +Use appropriate levels: + +- `Debug` or `Trace` for routine polling details. +- `Information` for meaningful lifecycle events. +- `Warning` for recoverable abnormal conditions. +- `Error` for failures that need operational attention. + +Do not log the same exception repeatedly at multiple layers without additional value. + +### Write contract-focused tests + +Tests should describe externally meaningful behaviour. + +Prefer test names such as: + +```csharp +AddTinyEventsWorker_preserves_core_retry_configuration +ClaimAsync_returns_only_messages_owned_by_the_current_worker +ProcessAsync_does_not_record_cancellation_as_a_failure +CompleteAsync_fails_when_the_worker_no_longer_owns_the_lease +``` + +Avoid tests tightly coupled to private method structure. + +Every bug fix must include a test that fails before the fix and passes after it. + +For provider behaviour, prefer shared contract tests when they remain readable. Do not create a complicated test framework merely to eliminate duplicated test cases. + +Tests should cover: + +- Happy paths. +- Boundary values. +- Invalid configuration. +- Cancellation. +- Ownership loss. +- Concurrent claims. +- Temporary persistence failures. +- Permanent consumer failures. +- Retry exhaustion. +- Unknown event types. +- Empty batches. +- Multiple consumers where supported. +- Registration-order permutations. +- Provider parity. + +### Comments explain why + +Do not comment obvious code. + +Bad: + +```csharp +// Increment attempt count +attemptCount++; +``` + +Useful: + +```csharp +// The attempt is persisted before invoking user code so a process crash +// cannot cause unlimited retries without advancing the counter. +``` + +Comments should explain constraints, guarantees, database behaviour, or non-obvious trade-offs. + +Delete stale comments instead of preserving misleading history. + +### Avoid speculative features + +This is a hardening pass, not a feature-expansion project. + +Do not add: + +- New storage providers. +- New transport abstractions. +- Dashboards. +- Metrics frameworks. +- Dead-letter management APIs. +- Complex retry strategies. +- Distributed tracing frameworks. +- New serialization formats. +- Broad extensibility points. + +A new feature is allowed only when it is required to make the existing advertised behaviour safe, coherent, or supportable for v1.0. + +### Respect repository style + +Before changing code: + +- Inspect neighbouring production code. +- Inspect relevant tests. +- Inspect documentation describing the behaviour. +- Follow established formatting and language-version conventions. +- Reuse existing abstractions when they are clear and appropriate. + +Do not run broad automatic formatting across unrelated files. + +Do not modify generated files, `bin`, `obj`, package artifacts, or unrelated repository content. + +## Working in small reviewable slices + +Work on exactly **one slice at a time**. + +A slice should normally: + +- Address one behaviour or one closely related defect. +- Modify a small number of production files. +- Add or update focused tests. +- Avoid unrelated renaming or cleanup. +- Be understandable as a single commit. +- Be reviewable in approximately 10-20 minutes. + +Do not begin the next slice until the current slice has been presented and explicitly approved. + +Do not combine: + +- Configuration changes with worker-loop restructuring. +- Public API changes with provider SQL changes. +- Naming cleanup with behavioural fixes. +- Documentation rewrites with unrelated implementation changes. +- Multiple provider fixes unless they implement the same contract and are best reviewed together. + +If you discover another issue while implementing a slice, record it under **Follow-up findings**. Do not fix it opportunistically unless it directly blocks the current slice. + +## Required workflow for every slice + +### 1. Inspect + +Before editing, inspect: + +- Relevant implementation files. +- Relevant tests. +- Relevant public APIs. +- Relevant documentation. +- Equivalent code in other providers where parity matters. + +### 2. State the slice + +Before changing code, provide: + +- **Problem** +- **Why it matters for v1.0** +- **Proposed behaviour** +- **Files expected to change** +- **Tests to add or update** +- **Explicit non-goals** + +Do not edit until this scope is clear. + +### 3. Implement minimally + +Make the smallest coherent change that establishes the intended contract. + +Do not redesign adjacent code unless necessary. + +Do not add abstraction layers pre-emptively. + +### 4. Validate + +Run the narrowest relevant tests first. + +Then run broader tests only when appropriate. + +At minimum, report: + +- Build command. +- Test command. +- Test result. +- Any tests not run. +- Any environment limitations. +- Any warnings introduced. + +Never claim a command succeeded unless it was actually executed successfully. + +### 5. Present the result + +After the slice, stop and report: + +#### Summary + +A brief explanation of the behaviour changed. + +#### Files changed + +List each changed file and why. + +#### Contract established + +State the precise behaviour now guaranteed. + +#### Tests + +List tests added or modified and the commands executed. + +#### Review notes + +Call out any decision that deserves human attention. + +#### Follow-up findings + +List newly discovered issues without implementing them. + +#### Suggested next slice + +Recommend only one next slice. + +Then wait for approval. + +## Change discipline + +Do not: + +- Commit. +- Push. +- Open a pull request. +- Change package versions. +- Publish packages. +- Modify release tags. +- Rewrite large documentation sections. +- Delete compatibility APIs. +- Apply repository-wide formatting. + +Unless explicitly requested. + +Do not use `git reset --hard`, destructive checkout commands, or commands that discard local work. + +Before editing, inspect `git status`. + +After editing, show the relevant diff. + +Preserve existing user changes. + +## Definition of done for a slice + +A slice is complete only when: + +- The scope remained focused. +- Production behaviour is clear. +- Tests establish the contract. +- Relevant tests pass. +- No unrelated files changed. +- Public API impact is identified. +- Provider parity was considered. +- Documentation impact was considered. +- The resulting code is simpler or safer than before. +- The result has been presented for review. +- Work has stopped pending approval. + +## Definition of done for TinyEvents 1.0 + +The repository is ready for `1.0.0` only when: + +- Configuration behaviour is deterministic. +- Options are validated early. +- Worker lifecycle and cancellation are robust. +- Temporary infrastructure failures have an explicit policy. +- Claim ownership is verified. +- Lease loss cannot be mistaken for successful completion. +- Retry and attempt semantics are documented and tested. +- Unknown event types have explicit behaviour. +- At-least-once guarantees are documented clearly. +- Provider implementations behave consistently. +- Transaction requirements are clear. +- Public APIs have been deliberately reviewed. +- Packages contain only intended assets. +- Package metadata and versioning are centralised. +- Source Link and symbols are correct. +- Package-consumer smoke tests pass. +- Integration tests pass against supported databases. +- Documentation examples compile or are otherwise validated. +- The repository is clean of tracked build artifacts. +- The release process can be reproduced from a clean checkout. + +## Release-readiness rule + +Completing the planned slices does not automatically make TinyEvents ready for `1.0.0`. + +After all hardening slices, perform a dedicated release-candidate audit from a clean checkout. + +During the first pass of that audit: + +- Do not edit any files. +- Build the complete solution. +- Run all unit tests. +- Run all supported database integration tests. +- Pack every published NuGet package. +- Inspect package contents and metadata. +- Run package-consumer smoke tests against the locally produced packages. +- Review the public API surface. +- Review documentation against actual behaviour. +- Review tracked repository files for build artifacts, secrets or accidental content. +- Review the release workflow and version source. +- List every remaining issue as either: + - Release blocker. + - Important follow-up after 1.0. + - Acceptable known limitation. + +TinyEvents may be declared ready for `1.0.0` only when: + +- There are no unresolved release blockers. +- All required commands have actually passed. +- Any skipped validation is explicitly identified and manually accepted. +- The final package contents have been inspected. +- The documented guarantees match the implementation. +- The repository is clean. +- A human reviewer explicitly approves the release candidate. + +Never claim that TinyEvents is ready to ship based only on static code inspection. diff --git a/TinyEvents-Worker-Error-Policy-Plan.md b/TinyEvents-Worker-Error-Policy-Plan.md new file mode 100644 index 0000000..1e1ee08 --- /dev/null +++ b/TinyEvents-Worker-Error-Policy-Plan.md @@ -0,0 +1,247 @@ +# TinyEvents Worker Error Policy + +This document defines the worker error-policy feature and its implementation +slices. The engineering and review rules live in +`TinyEvents-Coding-Guide.md`. + +## Goal + +Keep the worker available when an individual message or polling iteration +fails, while preserving correct outbox state and making degraded operation +visible. + +The policy is based on where a failure occurs. It does not attempt to guess +whether arbitrary exception types are transient or fatal. + +## Failure Boundaries + +### Message Failure + +A message failure occurs while preparing or invoking one claimed message: + +- resolving its dispatcher +- deserializing its payload +- resolving or invoking its consumers +- retrieving a secret or calling an external service from a consumer +- executing consumer business logic + +Message failures are recorded through `MarkFailedAsync` while the worker still +owns the lease. They follow the existing attempt, retry, and exhaustion rules. +The worker continues with the next claimed message. + +Requested cancellation and lease loss are not message failures. + +### Completion Failure + +A completion failure occurs after every consumer has succeeded but the store +cannot mark the message as processed. + +The processor must not call `MarkFailedAsync` after a completion failure. The +consumer may already have produced side effects, and the processed update may +have succeeded even if its response was lost. + +A non-lease completion failure escapes the processor as an iteration failure. +Lease loss remains an expected at-least-once race: it is logged and processing +continues. + +### Iteration Failure + +An iteration failure prevents the worker from claiming or updating outbox +state: + +- database or network failure during claim +- completion-store failure +- failure while persisting a genuine message failure +- dependency-injection scope or processor resolution failure + +The hosted worker logs the failure, waits, and tries another iteration. It +does not infer fatality from provider-specific or user-defined exception +types. + +Repeated failures must be observable without producing an unbounded stream of +identical high-severity logs. The first later successful iteration reports +recovery and resets the consecutive-failure count. + +### Startup Failure + +Only an explicit startup operation may fail the host before polling starts. +Current examples are invalid options or missing required registrations when +they are explicitly validated at startup. + +Schema migration behavior is not part of this feature because built-in +migrations do not exist yet. The migration feature will define its startup +contract when implemented. + +### Cancellation + +Cancellation requested through the worker token: + +- stops the worker cleanly +- starts no additional message work +- does not call `MarkFailedAsync` +- does not increment message attempts +- is not logged as an error + +An unrelated `OperationCanceledException` thrown while the supplied token is +not canceled remains a message or iteration failure according to where it was +thrown. + +### Lease Loss + +Lease loss: + +- does not increment attempts +- does not kill the worker +- does not cause another state transition +- emits a warning +- allows processing to continue + +## Design Constraints + +- Prefer structural failure boundaries over exception-type classification. +- Do not introduce provider-specific transient-error classifiers. +- Do not introduce schema or migration exceptions before those features exist. +- Do not add an arbitrary limit that kills the worker after repeated failures. +- Use the existing polling interval as the initial retry delay. +- Keep SQL Server, PostgreSQL, EF Core, and ADO.NET behavior symmetrical. +- Add no public API unless a later slice proves it is necessary. + +## Implementation Slices + +Each slice should change only a few files and be reviewable in five to ten +minutes. Stop for review after every slice. + +### W1 — Separate Message And Completion Failures + +Status: completed; awaiting review. + +Files: + +- `src/TinyEvents/Processing/TinyOutboxProcessor.cs` +- `tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs` + +Contract: + +- Consumer, dispatcher, and deserialization failures call `MarkFailedAsync`. +- A successful consumer run proceeds to `MarkProcessedAsync`. +- A non-lease `MarkProcessedAsync` failure escapes the processor. +- `MarkFailedAsync` is never called because completion persistence failed. +- Existing cancellation and lease-loss behavior remains unchanged. + +Non-goals: + +- No worker-loop changes. +- No new exception types. +- No logging catalogue. +- No provider changes. + +### W2 — Protect Failure-Persistence Boundaries + +Files: + +- `src/TinyEvents/Processing/TinyOutboxProcessor.cs` +- `tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs` + +Contract: + +- A genuine message failure is recorded once. +- A non-lease failure from `MarkFailedAsync` escapes as an iteration failure. +- Requested cancellation during failure persistence escapes unchanged. +- Lease loss during failure persistence remains a warning and does not retry + the state transition. + +### W3 — Complete Cancellation Contract Tests + +Files: + +- `tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs` +- `tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs` + +Contract tests: + +- Cancellation during claim escapes. +- Cancellation after claim starts no message work. +- Cancellation during consumer execution is not recorded as failure. +- Cancellation during failure persistence escapes. +- Worker shutdown during an iteration stops promptly. +- Requested cancellation is not logged as an iteration failure. + +Production changes are out of scope unless a test proves a defect. + +### W4 — Inventory Worker Logging + +Read-only. + +Inspect current worker, processor, and lease-loss logs. Propose the smallest +stable event catalogue for: + +- iteration failure +- prominent repeated failure +- recovery +- message failure +- lease loss + +Do not implement logging in this slice. + +### W5 — Add Consecutive Failure State + +Files: + +- `src/TinyEvents.Worker/TinyEventsBackgroundService.cs` +- `tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs` + +Contract: + +- Each failed iteration increments a consecutive-failure count. +- A successful iteration resets the count. +- Cancellation is not counted. +- The worker remains alive after iteration failures. + +This slice establishes state only. Final structured logging belongs to W6. + +### W6 — Report Degradation And Recovery + +Files: + +- one small internal logging catalogue file +- `src/TinyEvents.Worker/TinyEventsBackgroundService.cs` +- `tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs` + +Initial policy: + +- Failures one through four log Warning. +- Failure five logs Error. +- Later failures log only at meaningful deterministic thresholds. +- The first successful iteration after failures logs Information with the + previous failure count. +- Recovery resets the count. + +Exact later thresholds must be approved during W4. + +### W7 — Document The Runtime Contract + +Files: + +- `docs/workers.md` + +Document: + +- message failures +- completion failures +- iteration retries +- cancellation +- lease loss +- polling delay after failure +- degraded-operation and recovery logs +- host-level health monitoring expectations + +## Deferred Decisions + +These require concrete later features or operational evidence: + +- migration initialization failures +- schema compatibility failures +- provider-specific transient detection +- exponential backoff +- health-check APIs +- metrics and telemetry diff --git a/src/TinyEvents/Processing/TinyOutboxProcessor.cs b/src/TinyEvents/Processing/TinyOutboxProcessor.cs index cbbfded..130aaa7 100644 --- a/src/TinyEvents/Processing/TinyOutboxProcessor.cs +++ b/src/TinyEvents/Processing/TinyOutboxProcessor.cs @@ -111,6 +111,19 @@ private async ValueTask ProcessMessageAsync( try { await InvokeConsumersAsync(message, cancellationToken); + } + catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) + { + throw; + } + catch (Exception exception) + { + await RecordProcessingFailureAsync(message, workerId, exception, cancellationToken); + return; + } + + try + { await MarkProcessedAsync(message, workerId, cancellationToken); } catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) @@ -121,17 +134,22 @@ private async ValueTask ProcessMessageAsync( { LogLeaseLost(message, workerId, exception, "marked as processed"); } - catch (Exception exception) + } + + private async ValueTask RecordProcessingFailureAsync( + TinyOutboxMessage message, + string workerId, + Exception exception, + CancellationToken cancellationToken) + { + try { - try - { - var failure = await MarkFailedAsync(message, workerId, exception, cancellationToken); - LogProcessingFailure(message, workerId, exception, failure); - } - catch (TinyOutboxLeaseLostException leaseLostException) - { - LogLeaseLost(message, workerId, leaseLostException, "recording a processing failure"); - } + var failure = await MarkFailedAsync(message, workerId, exception, cancellationToken); + LogProcessingFailure(message, workerId, exception, failure); + } + catch (TinyOutboxLeaseLostException leaseLostException) + { + LogLeaseLost(message, workerId, leaseLostException, "recording a processing failure"); } } diff --git a/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs b/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs index 1221867..58854f5 100644 --- a/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs +++ b/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs @@ -208,6 +208,22 @@ public async Task Process_pending_async_marks_processed_with_current_worker_id() Assert.Equal("worker-42", Assert.Single(store.ProcessedWorkerIds)); } + [Fact] + public async Task Process_pending_async_does_not_mark_failed_when_mark_processed_fails() + { + RecordingConsumer.Consumed.Clear(); + var message = NewProcessingMessage(new UserCreated(Guid.NewGuid(), "user@example.com")); + var store = new FailingMarkProcessedStore(message); + var processor = BuildProcessor(store); + + var exception = await Assert.ThrowsAsync( + async () => await processor.ProcessPendingAsync()); + + Assert.Equal("database failed while marking processed", exception.Message); + Assert.Single(RecordingConsumer.Consumed); + Assert.Equal(0, store.MarkFailedCount); + } + [Fact] public async Task Process_pending_async_marks_failed_with_current_worker_id() { @@ -644,6 +660,49 @@ public ValueTask MarkFailedAsync( } } + private sealed class FailingMarkProcessedStore : ITinyOutboxStore + { + private readonly IReadOnlyList claimedMessages; + + public FailingMarkProcessedStore(params TinyOutboxMessage[] claimedMessages) + { + this.claimedMessages = claimedMessages; + } + + public int MarkFailedCount { get; private set; } + + public ValueTask> ClaimPendingAsync( + int maxCount, + string workerId, + DateTimeOffset now, + TimeSpan claimTimeout, + CancellationToken cancellationToken) + { + return ValueTask.FromResult(claimedMessages); + } + + public ValueTask MarkProcessedAsync( + Guid messageId, + string workerId, + DateTimeOffset processedAtUtc, + CancellationToken cancellationToken) + { + throw new InvalidOperationException("database failed while marking processed"); + } + + public ValueTask MarkFailedAsync( + Guid messageId, + string workerId, + string error, + int attemptCount, + DateTimeOffset? nextAttemptAtUtc, + CancellationToken cancellationToken) + { + MarkFailedCount++; + return ValueTask.CompletedTask; + } + } + private sealed class LeaseLostOnFirstProcessedStore : ITinyOutboxStore { private readonly IReadOnlyList claimedMessages; From b260384f8cb3fdbab6cbf34154dd6e17a6dbb6c2 Mon Sep 17 00:00:00 2001 From: George Date: Sat, 25 Jul 2026 16:01:44 +0200 Subject: [PATCH 02/12] Cover outbox failure persistence errors --- TinyEvents-Worker-Error-Policy-Plan.md | 2 + .../Processing/TinyOutboxProcessorTests.cs | 59 +++++++++++++++++++ 2 files changed, 61 insertions(+) diff --git a/TinyEvents-Worker-Error-Policy-Plan.md b/TinyEvents-Worker-Error-Policy-Plan.md index 1e1ee08..16b5eb9 100644 --- a/TinyEvents-Worker-Error-Policy-Plan.md +++ b/TinyEvents-Worker-Error-Policy-Plan.md @@ -137,6 +137,8 @@ Non-goals: ### W2 — Protect Failure-Persistence Boundaries +Status: completed; awaiting review. + Files: - `src/TinyEvents/Processing/TinyOutboxProcessor.cs` diff --git a/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs b/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs index 58854f5..1064a04 100644 --- a/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs +++ b/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs @@ -241,6 +241,22 @@ public async Task Process_pending_async_marks_failed_with_current_worker_id() ThrowingConsumer.Throw = false; } + [Fact] + public async Task Process_pending_async_propagates_failure_persistence_errors() + { + ThrowingConsumer.Throw = true; + var message = NewProcessingMessage(new UserCreated(Guid.NewGuid(), "user@example.com")); + var store = new FailingMarkFailedStore(message); + var processor = BuildProcessor(store, includeThrowingConsumer: true); + + var exception = await Assert.ThrowsAsync( + async () => await processor.ProcessPendingAsync()); + + Assert.Equal("database failed while marking failed", exception.Message); + Assert.Equal(1, store.MarkFailedCount); + ThrowingConsumer.Throw = false; + } + [Fact] public async Task Process_pending_async_retries_expired_claim_after_worker_crash_simulation() { @@ -703,6 +719,49 @@ public ValueTask MarkFailedAsync( } } + private sealed class FailingMarkFailedStore : ITinyOutboxStore + { + private readonly IReadOnlyList claimedMessages; + + public FailingMarkFailedStore(params TinyOutboxMessage[] claimedMessages) + { + this.claimedMessages = claimedMessages; + } + + public int MarkFailedCount { get; private set; } + + public ValueTask> ClaimPendingAsync( + int maxCount, + string workerId, + DateTimeOffset now, + TimeSpan claimTimeout, + CancellationToken cancellationToken) + { + return ValueTask.FromResult(claimedMessages); + } + + public ValueTask MarkProcessedAsync( + Guid messageId, + string workerId, + DateTimeOffset processedAtUtc, + CancellationToken cancellationToken) + { + throw new InvalidOperationException("A failed consumer must not be marked as processed."); + } + + public ValueTask MarkFailedAsync( + Guid messageId, + string workerId, + string error, + int attemptCount, + DateTimeOffset? nextAttemptAtUtc, + CancellationToken cancellationToken) + { + MarkFailedCount++; + throw new InvalidOperationException("database failed while marking failed"); + } + } + private sealed class LeaseLostOnFirstProcessedStore : ITinyOutboxStore { private readonly IReadOnlyList claimedMessages; From 3bda99ecf29ff54ec0cc73b906d26bbde446c569 Mon Sep 17 00:00:00 2001 From: George Date: Sat, 25 Jul 2026 16:03:44 +0200 Subject: [PATCH 03/12] Cover processor cancellation boundaries --- .../Processing/TinyOutboxProcessorTests.cs | 123 ++++++++++++++++++ 1 file changed, 123 insertions(+) diff --git a/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs b/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs index 1064a04..e2ec430 100644 --- a/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs +++ b/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs @@ -350,6 +350,35 @@ await Assert.ThrowsAsync( Assert.Equal(0, store.MarkFailedCount); } + [Fact] + public async Task Process_pending_async_propagates_cancellation_during_claim() + { + using var cancellation = new CancellationTokenSource(); + var store = new CancelDuringClaimStore(cancellation); + var processor = BuildProcessor(store); + + await Assert.ThrowsAsync( + async () => await processor.ProcessPendingAsync(cancellation.Token)); + + Assert.Equal(0, store.MarkFailedCount); + } + + [Fact] + public async Task Process_pending_async_propagates_cancellation_during_failure_persistence() + { + ThrowingConsumer.Throw = true; + using var cancellation = new CancellationTokenSource(); + var message = NewProcessingMessage(new UserCreated(Guid.NewGuid(), "user@example.com")); + var store = new CancelDuringMarkFailedStore(cancellation, message); + var processor = BuildProcessor(store, includeThrowingConsumer: true); + + await Assert.ThrowsAsync( + async () => await processor.ProcessPendingAsync(cancellation.Token)); + + Assert.Equal(1, store.MarkFailedCount); + ThrowingConsumer.Throw = false; + } + [Fact] public async Task Process_pending_async_continues_when_mark_processed_loses_lease() { @@ -676,6 +705,100 @@ public ValueTask MarkFailedAsync( } } + private sealed class CancelDuringClaimStore : ITinyOutboxStore + { + private readonly CancellationTokenSource cancellation; + + public CancelDuringClaimStore(CancellationTokenSource cancellation) + { + this.cancellation = cancellation; + } + + public int MarkFailedCount { get; private set; } + + public ValueTask> ClaimPendingAsync( + int maxCount, + string workerId, + DateTimeOffset now, + TimeSpan claimTimeout, + CancellationToken cancellationToken) + { + this.cancellation.Cancel(); + cancellationToken.ThrowIfCancellationRequested(); + throw new InvalidOperationException("Cancellation should have been observed."); + } + + public ValueTask MarkProcessedAsync( + Guid messageId, + string workerId, + DateTimeOffset processedAtUtc, + CancellationToken cancellationToken) + { + throw new InvalidOperationException("Canceled claiming should not process messages."); + } + + public ValueTask MarkFailedAsync( + Guid messageId, + string workerId, + string error, + int attemptCount, + DateTimeOffset? nextAttemptAtUtc, + CancellationToken cancellationToken) + { + MarkFailedCount++; + return ValueTask.CompletedTask; + } + } + + private sealed class CancelDuringMarkFailedStore : ITinyOutboxStore + { + private readonly CancellationTokenSource cancellation; + private readonly IReadOnlyList claimedMessages; + + public CancelDuringMarkFailedStore( + CancellationTokenSource cancellation, + params TinyOutboxMessage[] claimedMessages) + { + this.cancellation = cancellation; + this.claimedMessages = claimedMessages; + } + + public int MarkFailedCount { get; private set; } + + public ValueTask> ClaimPendingAsync( + int maxCount, + string workerId, + DateTimeOffset now, + TimeSpan claimTimeout, + CancellationToken cancellationToken) + { + return ValueTask.FromResult(claimedMessages); + } + + public ValueTask MarkProcessedAsync( + Guid messageId, + string workerId, + DateTimeOffset processedAtUtc, + CancellationToken cancellationToken) + { + throw new InvalidOperationException("A failed consumer must not be marked as processed."); + } + + public ValueTask MarkFailedAsync( + Guid messageId, + string workerId, + string error, + int attemptCount, + DateTimeOffset? nextAttemptAtUtc, + CancellationToken cancellationToken) + { + MarkFailedCount++; + cancellation.Cancel(); + cancellationToken.ThrowIfCancellationRequested(); + throw new InvalidOperationException("Cancellation should have been observed."); + } + } + private sealed class FailingMarkProcessedStore : ITinyOutboxStore { private readonly IReadOnlyList claimedMessages; From 7c0767872fad014a1b04c907873c1323a1783737 Mon Sep 17 00:00:00 2001 From: George Date: Sat, 25 Jul 2026 16:05:05 +0200 Subject: [PATCH 04/12] Cover hosted worker cancellation --- .../TinyEventsWorkerTests.cs | 77 +++++++++++++++++++ 1 file changed, 77 insertions(+) diff --git a/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs b/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs index 7419a17..3ec5527 100644 --- a/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs +++ b/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs @@ -1,5 +1,6 @@ using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; using TinyEvents.Worker; using Xunit; @@ -250,6 +251,28 @@ public async Task Background_service_continues_after_processing_iteration_fails( Assert.True(FailingThenRecordingProcessor.CallCount >= 2); } + [Fact] + public async Task Background_service_stops_active_iteration_without_logging_cancellation_as_error() + { + var processor = new CancellationAwareProcessor(); + var logger = new RecordingLogger(); + var services = new ServiceCollection(); + services.AddSingleton(processor); + services.AddSingleton(new TinyEventsWorkerOptions()); + services.AddSingleton>(logger); + services.AddSingleton(); + using var provider = services.BuildServiceProvider(); + var worker = provider.GetRequiredService(); + using var timeout = new CancellationTokenSource(TimeSpan.FromSeconds(5)); + + await worker.StartAsync(CancellationToken.None); + await processor.Started.Task.WaitAsync(timeout.Token); + await worker.StopAsync(timeout.Token); + + Assert.True(processor.CancellationObserved); + Assert.DoesNotContain(logger.Entries, entry => entry.LogLevel == LogLevel.Error); + } + private sealed class RecordingProcessor : ITinyOutboxProcessor { public static int CallCount { get; set; } @@ -304,4 +327,58 @@ private static TaskCompletionSource NewTaskCompletionSource() return new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); } } + + private sealed class CancellationAwareProcessor : ITinyOutboxProcessor + { + public TaskCompletionSource Started { get; } = new TaskCompletionSource( + TaskCreationOptions.RunContinuationsAsynchronously); + + public bool CancellationObserved { get; private set; } + + public async ValueTask ProcessPendingAsync(CancellationToken cancellationToken = default) + { + Started.TrySetResult(); + + try + { + await Task.Delay(Timeout.InfiniteTimeSpan, cancellationToken); + } + catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) + { + CancellationObserved = true; + throw; + } + } + } + + private sealed class RecordingLogger : ILogger + { + public List Entries { get; } = new List(); + + public IDisposable? BeginScope(TState state) + where TState : notnull + { + return null; + } + + public bool IsEnabled(LogLevel logLevel) + { + return true; + } + + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + { + Entries.Add(new LogEntry(logLevel, formatter(state, exception), exception)); + } + } + + private sealed record LogEntry( + LogLevel LogLevel, + string Message, + Exception? Exception); } From e772b123ffb83b97915778b3eeff28f081e7379e Mon Sep 17 00:00:00 2001 From: George Date: Sat, 25 Jul 2026 16:10:26 +0200 Subject: [PATCH 05/12] Identify worker iteration failures --- src/TinyEvents.Worker/TinyEventsBackgroundService.cs | 5 ++++- src/TinyEvents.Worker/TinyEventsWorkerLogEvents.cs | 10 ++++++++++ tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs | 10 +++++++++- 3 files changed, 23 insertions(+), 2 deletions(-) create mode 100644 src/TinyEvents.Worker/TinyEventsWorkerLogEvents.cs diff --git a/src/TinyEvents.Worker/TinyEventsBackgroundService.cs b/src/TinyEvents.Worker/TinyEventsBackgroundService.cs index b1a7d53..ed6f72f 100644 --- a/src/TinyEvents.Worker/TinyEventsBackgroundService.cs +++ b/src/TinyEvents.Worker/TinyEventsBackgroundService.cs @@ -65,7 +65,10 @@ protected override async Task ExecuteAsync(CancellationToken stoppingToken) } catch (Exception exception) { - logger.LogError(exception, "TinyEvents worker processing iteration failed."); + logger.LogWarning( + TinyEventsWorkerLogEvents.WorkerIterationFailed, + exception, + "TinyEvents worker processing iteration failed."); } try diff --git a/src/TinyEvents.Worker/TinyEventsWorkerLogEvents.cs b/src/TinyEvents.Worker/TinyEventsWorkerLogEvents.cs new file mode 100644 index 0000000..a882e93 --- /dev/null +++ b/src/TinyEvents.Worker/TinyEventsWorkerLogEvents.cs @@ -0,0 +1,10 @@ +using Microsoft.Extensions.Logging; + +namespace TinyEvents.Worker; + +internal static class TinyEventsWorkerLogEvents +{ + public static readonly EventId WorkerIterationFailed = new( + 1100, + nameof(WorkerIterationFailed)); +} diff --git a/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs b/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs index 3ec5527..6cf62ca 100644 --- a/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs +++ b/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs @@ -233,12 +233,14 @@ public async Task Background_service_creates_scope_per_processing_iteration() public async Task Background_service_continues_after_processing_iteration_fails() { FailingThenRecordingProcessor.Reset(); + var logger = new RecordingLogger(); var services = new ServiceCollection(); services.AddSingleton(); services.AddSingleton(new TinyEventsWorkerOptions { PollingInterval = TimeSpan.FromMilliseconds(1) }); + services.AddSingleton>(logger); services.AddSingleton(); using var provider = services.BuildServiceProvider(); var worker = provider.GetRequiredService(); @@ -249,6 +251,11 @@ public async Task Background_service_continues_after_processing_iteration_fails( await worker.StopAsync(CancellationToken.None).WaitAsync(cancellation.Token); Assert.True(FailingThenRecordingProcessor.CallCount >= 2); + var entry = Assert.Single(logger.Entries); + Assert.Equal(LogLevel.Warning, entry.LogLevel); + Assert.Equal(1100, entry.EventId.Id); + Assert.Equal("WorkerIterationFailed", entry.EventId.Name); + Assert.IsType(entry.Exception); } [Fact] @@ -373,11 +380,12 @@ public void Log( Exception? exception, Func formatter) { - Entries.Add(new LogEntry(logLevel, formatter(state, exception), exception)); + Entries.Add(new LogEntry(eventId, logLevel, formatter(state, exception), exception)); } } private sealed record LogEntry( + EventId EventId, LogLevel LogLevel, string Message, Exception? Exception); From 3b6a096b59414b54d62be28c831255877988bb93 Mon Sep 17 00:00:00 2001 From: George Date: Sat, 25 Jul 2026 16:15:58 +0200 Subject: [PATCH 06/12] Report worker recovery --- .../TinyEventsBackgroundService.cs | 16 +++++++++--- .../TinyEventsWorkerFailureTracker.cs | 25 +++++++++++++++++++ src/TinyEvents.Worker/TinyEventsWorkerLog.cs | 25 +++++++++++++++++++ .../TinyEventsWorkerLogEvents.cs | 10 -------- .../TinyEventsWorkerTests.cs | 23 +++++++++++++---- 5 files changed, 80 insertions(+), 19 deletions(-) create mode 100644 src/TinyEvents.Worker/TinyEventsWorkerFailureTracker.cs create mode 100644 src/TinyEvents.Worker/TinyEventsWorkerLog.cs delete mode 100644 src/TinyEvents.Worker/TinyEventsWorkerLogEvents.cs diff --git a/src/TinyEvents.Worker/TinyEventsBackgroundService.cs b/src/TinyEvents.Worker/TinyEventsBackgroundService.cs index ed6f72f..970c3f2 100644 --- a/src/TinyEvents.Worker/TinyEventsBackgroundService.cs +++ b/src/TinyEvents.Worker/TinyEventsBackgroundService.cs @@ -53,11 +53,18 @@ public async ValueTask ProcessOnceAsync(CancellationToken cancellationToken = de protected override async Task ExecuteAsync(CancellationToken stoppingToken) { + var failures = new TinyEventsWorkerFailureTracker(); + while (!stoppingToken.IsCancellationRequested) { try { await ProcessOnceAsync(stoppingToken); + + if (failures.TryReset(out var previousFailureCount)) + { + TinyEventsWorkerLog.Recovered(logger, previousFailureCount); + } } catch (OperationCanceledException) when (stoppingToken.IsCancellationRequested) { @@ -65,10 +72,11 @@ protected override async Task ExecuteAsync(CancellationToken stoppingToken) } catch (Exception exception) { - logger.LogWarning( - TinyEventsWorkerLogEvents.WorkerIterationFailed, - exception, - "TinyEvents worker processing iteration failed."); + var consecutiveFailureCount = failures.RecordFailure(); + TinyEventsWorkerLog.IterationFailed( + logger, + consecutiveFailureCount, + exception); } try diff --git a/src/TinyEvents.Worker/TinyEventsWorkerFailureTracker.cs b/src/TinyEvents.Worker/TinyEventsWorkerFailureTracker.cs new file mode 100644 index 0000000..9f6620a --- /dev/null +++ b/src/TinyEvents.Worker/TinyEventsWorkerFailureTracker.cs @@ -0,0 +1,25 @@ +namespace TinyEvents.Worker; + +internal sealed class TinyEventsWorkerFailureTracker +{ + private int consecutiveFailureCount; + + public int RecordFailure() + { + consecutiveFailureCount++; + return consecutiveFailureCount; + } + + public bool TryReset(out int previousFailureCount) + { + previousFailureCount = consecutiveFailureCount; + + if (consecutiveFailureCount == 0) + { + return false; + } + + consecutiveFailureCount = 0; + return true; + } +} diff --git a/src/TinyEvents.Worker/TinyEventsWorkerLog.cs b/src/TinyEvents.Worker/TinyEventsWorkerLog.cs new file mode 100644 index 0000000..f24e5c6 --- /dev/null +++ b/src/TinyEvents.Worker/TinyEventsWorkerLog.cs @@ -0,0 +1,25 @@ +using Microsoft.Extensions.Logging; + +namespace TinyEvents.Worker; + +internal static partial class TinyEventsWorkerLog +{ + [LoggerMessage( + EventId = 1100, + EventName = "WorkerIterationFailed", + Level = LogLevel.Warning, + Message = "TinyEvents worker processing iteration failed. Consecutive failures: {ConsecutiveFailures}.")] + public static partial void IterationFailed( + ILogger logger, + int consecutiveFailures, + Exception exception); + + [LoggerMessage( + EventId = 1101, + EventName = "WorkerRecovered", + Level = LogLevel.Information, + Message = "TinyEvents worker recovered after {ConsecutiveFailures} consecutive failed iterations.")] + public static partial void Recovered( + ILogger logger, + int consecutiveFailures); +} diff --git a/src/TinyEvents.Worker/TinyEventsWorkerLogEvents.cs b/src/TinyEvents.Worker/TinyEventsWorkerLogEvents.cs deleted file mode 100644 index a882e93..0000000 --- a/src/TinyEvents.Worker/TinyEventsWorkerLogEvents.cs +++ /dev/null @@ -1,10 +0,0 @@ -using Microsoft.Extensions.Logging; - -namespace TinyEvents.Worker; - -internal static class TinyEventsWorkerLogEvents -{ - public static readonly EventId WorkerIterationFailed = new( - 1100, - nameof(WorkerIterationFailed)); -} diff --git a/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs b/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs index 6cf62ca..1ba4a54 100644 --- a/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs +++ b/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs @@ -251,11 +251,24 @@ public async Task Background_service_continues_after_processing_iteration_fails( await worker.StopAsync(CancellationToken.None).WaitAsync(cancellation.Token); Assert.True(FailingThenRecordingProcessor.CallCount >= 2); - var entry = Assert.Single(logger.Entries); - Assert.Equal(LogLevel.Warning, entry.LogLevel); - Assert.Equal(1100, entry.EventId.Id); - Assert.Equal("WorkerIterationFailed", entry.EventId.Name); - Assert.IsType(entry.Exception); + Assert.Collection( + logger.Entries, + failure => + { + Assert.Equal(LogLevel.Warning, failure.LogLevel); + Assert.Equal(1100, failure.EventId.Id); + Assert.Equal("WorkerIterationFailed", failure.EventId.Name); + Assert.Contains("Consecutive failures: 1", failure.Message, StringComparison.Ordinal); + Assert.IsType(failure.Exception); + }, + recovery => + { + Assert.Equal(LogLevel.Information, recovery.LogLevel); + Assert.Equal(1101, recovery.EventId.Id); + Assert.Equal("WorkerRecovered", recovery.EventId.Name); + Assert.Contains("after 1 consecutive failed iterations", recovery.Message, StringComparison.Ordinal); + Assert.Null(recovery.Exception); + }); } [Fact] From 6bc48feb6f7635b51330cc749860eaedcf5e3a91 Mon Sep 17 00:00:00 2001 From: George Date: Sat, 25 Jul 2026 16:19:08 +0200 Subject: [PATCH 07/12] Throttle repeated worker failures --- .../TinyEventsBackgroundService.cs | 4 +- .../TinyEventsWorkerFailureTracker.cs | 32 +++++++++- src/TinyEvents.Worker/TinyEventsWorkerLog.cs | 26 ++++++++ .../TinyEventsWorkerTests.cs | 63 +++++++++++++++++-- 4 files changed, 117 insertions(+), 8 deletions(-) diff --git a/src/TinyEvents.Worker/TinyEventsBackgroundService.cs b/src/TinyEvents.Worker/TinyEventsBackgroundService.cs index 970c3f2..a0a9206 100644 --- a/src/TinyEvents.Worker/TinyEventsBackgroundService.cs +++ b/src/TinyEvents.Worker/TinyEventsBackgroundService.cs @@ -72,10 +72,10 @@ protected override async Task ExecuteAsync(CancellationToken stoppingToken) } catch (Exception exception) { - var consecutiveFailureCount = failures.RecordFailure(); + var failure = failures.RecordFailure(); TinyEventsWorkerLog.IterationFailed( logger, - consecutiveFailureCount, + failure, exception); } diff --git a/src/TinyEvents.Worker/TinyEventsWorkerFailureTracker.cs b/src/TinyEvents.Worker/TinyEventsWorkerFailureTracker.cs index 9f6620a..fcc0c45 100644 --- a/src/TinyEvents.Worker/TinyEventsWorkerFailureTracker.cs +++ b/src/TinyEvents.Worker/TinyEventsWorkerFailureTracker.cs @@ -4,10 +4,12 @@ internal sealed class TinyEventsWorkerFailureTracker { private int consecutiveFailureCount; - public int RecordFailure() + public TinyEventsWorkerFailure RecordFailure() { consecutiveFailureCount++; - return consecutiveFailureCount; + + var reportKind = GetReportKind(consecutiveFailureCount); + return new TinyEventsWorkerFailure(consecutiveFailureCount, reportKind); } public bool TryReset(out int previousFailureCount) @@ -22,4 +24,30 @@ public bool TryReset(out int previousFailureCount) consecutiveFailureCount = 0; return true; } + + private static TinyEventsWorkerFailureReportKind GetReportKind(int failureCount) + { + if (failureCount <= 4) + { + return TinyEventsWorkerFailureReportKind.Warning; + } + + if (failureCount is 5 or 10 or 20 or 50 || failureCount % 100 == 0) + { + return TinyEventsWorkerFailureReportKind.Prominent; + } + + return TinyEventsWorkerFailureReportKind.None; + } +} + +internal readonly record struct TinyEventsWorkerFailure( + int Count, + TinyEventsWorkerFailureReportKind ReportKind); + +internal enum TinyEventsWorkerFailureReportKind +{ + None, + Warning, + Prominent } diff --git a/src/TinyEvents.Worker/TinyEventsWorkerLog.cs b/src/TinyEvents.Worker/TinyEventsWorkerLog.cs index f24e5c6..d60fdc1 100644 --- a/src/TinyEvents.Worker/TinyEventsWorkerLog.cs +++ b/src/TinyEvents.Worker/TinyEventsWorkerLog.cs @@ -4,6 +4,22 @@ namespace TinyEvents.Worker; internal static partial class TinyEventsWorkerLog { + public static void IterationFailed( + ILogger logger, + TinyEventsWorkerFailure failure, + Exception exception) + { + switch (failure.ReportKind) + { + case TinyEventsWorkerFailureReportKind.Warning: + IterationFailed(logger, failure.Count, exception); + break; + case TinyEventsWorkerFailureReportKind.Prominent: + RepeatedFailures(logger, failure.Count, exception); + break; + } + } + [LoggerMessage( EventId = 1100, EventName = "WorkerIterationFailed", @@ -14,6 +30,16 @@ public static partial void IterationFailed( int consecutiveFailures, Exception exception); + [LoggerMessage( + EventId = 1104, + EventName = "RepeatedWorkerFailures", + Level = LogLevel.Error, + Message = "TinyEvents worker has failed {ConsecutiveFailures} consecutive processing iterations and will continue retrying.")] + private static partial void RepeatedFailures( + ILogger logger, + int consecutiveFailures, + Exception exception); + [LoggerMessage( EventId = 1101, EventName = "WorkerRecovered", diff --git a/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs b/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs index 1ba4a54..7a0745f 100644 --- a/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs +++ b/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs @@ -1,3 +1,4 @@ +using System.Collections.Concurrent; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Logging; @@ -293,6 +294,57 @@ public async Task Background_service_stops_active_iteration_without_logging_canc Assert.DoesNotContain(logger.Entries, entry => entry.LogLevel == LogLevel.Error); } + [Fact] + public async Task Background_service_throttles_repeated_failures_and_reports_recovery() + { + FailingThenRecordingProcessor.Reset(failuresBeforeSuccess: 10); + var logger = new RecordingLogger(); + var services = new ServiceCollection(); + services.AddSingleton(); + services.AddSingleton(new TinyEventsWorkerOptions + { + PollingInterval = TimeSpan.FromMilliseconds(1) + }); + services.AddSingleton>(logger); + services.AddSingleton(); + using var provider = services.BuildServiceProvider(); + var worker = provider.GetRequiredService(); + using var timeout = new CancellationTokenSource(TimeSpan.FromSeconds(5)); + + await worker.StartAsync(CancellationToken.None); + await WaitForLogAsync(logger, eventId: 1101, timeout.Token); + await worker.StopAsync(timeout.Token); + + Assert.Equal(4, logger.Entries.Count(entry => entry.EventId.Id == 1100)); + Assert.Equal(2, logger.Entries.Count(entry => entry.EventId.Id == 1104)); + Assert.Single(logger.Entries, entry => entry.EventId.Id == 1101); + Assert.All( + logger.Entries.Where(entry => entry.EventId.Id == 1100), + entry => Assert.Equal(LogLevel.Warning, entry.LogLevel)); + Assert.All( + logger.Entries.Where(entry => entry.EventId.Id == 1104), + entry => Assert.Equal(LogLevel.Error, entry.LogLevel)); + Assert.Contains( + logger.Entries, + entry => entry.EventId.Id == 1104 + && entry.Message.Contains("failed 5 consecutive", StringComparison.Ordinal)); + Assert.Contains( + logger.Entries, + entry => entry.EventId.Id == 1104 + && entry.Message.Contains("failed 10 consecutive", StringComparison.Ordinal)); + } + + private static async Task WaitForLogAsync( + RecordingLogger logger, + int eventId, + CancellationToken cancellationToken) + { + while (!logger.Entries.Any(entry => entry.EventId.Id == eventId)) + { + await Task.Delay(TimeSpan.FromMilliseconds(1), cancellationToken); + } + } + private sealed class RecordingProcessor : ITinyOutboxProcessor { public static int CallCount { get; set; } @@ -319,13 +371,16 @@ public ValueTask ProcessPendingAsync(CancellationToken cancellationToken = defau private sealed class FailingThenRecordingProcessor : ITinyOutboxProcessor { + private static int failuresBeforeSuccess = 1; + public static int CallCount { get; private set; } public static TaskCompletionSource SecondCall { get; private set; } = NewTaskCompletionSource(); - public static void Reset() + public static void Reset(int failuresBeforeSuccess = 1) { CallCount = 0; + FailingThenRecordingProcessor.failuresBeforeSuccess = failuresBeforeSuccess; SecondCall = NewTaskCompletionSource(); } @@ -333,7 +388,7 @@ public ValueTask ProcessPendingAsync(CancellationToken cancellationToken = defau { CallCount++; - if (CallCount == 1) + if (CallCount <= failuresBeforeSuccess) { throw new InvalidOperationException("database failed"); } @@ -373,7 +428,7 @@ public async ValueTask ProcessPendingAsync(CancellationToken cancellationToken = private sealed class RecordingLogger : ILogger { - public List Entries { get; } = new List(); + public ConcurrentQueue Entries { get; } = new ConcurrentQueue(); public IDisposable? BeginScope(TState state) where TState : notnull @@ -393,7 +448,7 @@ public void Log( Exception? exception, Func formatter) { - Entries.Add(new LogEntry(eventId, logLevel, formatter(state, exception), exception)); + Entries.Enqueue(new LogEntry(eventId, logLevel, formatter(state, exception), exception)); } } From 578708eb508afe53d17614f078b47dded4eca772 Mon Sep 17 00:00:00 2001 From: George Date: Sat, 25 Jul 2026 16:21:44 +0200 Subject: [PATCH 08/12] Identify retryable event failures --- .../Processing/TinyOutboxProcessor.cs | 13 ++++++++++++ .../Processing/TinyOutboxProcessorLog.cs | 20 +++++++++++++++++++ .../Processing/TinyOutboxProcessorTests.cs | 5 ++++- 3 files changed, 37 insertions(+), 1 deletion(-) create mode 100644 src/TinyEvents/Processing/TinyOutboxProcessorLog.cs diff --git a/src/TinyEvents/Processing/TinyOutboxProcessor.cs b/src/TinyEvents/Processing/TinyOutboxProcessor.cs index 130aaa7..c09c73f 100644 --- a/src/TinyEvents/Processing/TinyOutboxProcessor.cs +++ b/src/TinyEvents/Processing/TinyOutboxProcessor.cs @@ -250,6 +250,19 @@ private void LogProcessingFailure( Exception exception, RecordedFailure failure) { + if (failure.NextAttemptAtUtc is not null) + { + TinyOutboxProcessorLog.ProcessingFailed( + logger, + message.Id, + message.EventType, + workerId, + failure.AttemptCount, + failure.NextAttemptAtUtc.Value, + exception); + return; + } + logger.LogWarning( exception, "TinyEvents outbox message {MessageId} for event type {EventType} failed processing on worker {WorkerId} at attempt {AttemptCount}. Next attempt at {NextAttemptAtUtc}.", diff --git a/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs b/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs new file mode 100644 index 0000000..894a907 --- /dev/null +++ b/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs @@ -0,0 +1,20 @@ +using Microsoft.Extensions.Logging; + +namespace TinyEvents; + +internal static partial class TinyOutboxProcessorLog +{ + [LoggerMessage( + EventId = 1202, + EventName = "EventProcessingFailed", + Level = LogLevel.Warning, + Message = "TinyEvents outbox message {MessageId} for event type {EventType} failed processing on worker {WorkerId} at attempt {Attempt}. Next attempt at {NextAttemptAtUtc}.")] + public static partial void ProcessingFailed( + ILogger logger, + Guid messageId, + string eventType, + string workerId, + int attempt, + DateTimeOffset nextAttemptAtUtc, + Exception exception); +} diff --git a/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs b/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs index e2ec430..00a7e32 100644 --- a/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs +++ b/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs @@ -190,6 +190,8 @@ public async Task Process_pending_async_logs_recorded_processing_failure() await processor.ProcessPendingAsync(); var entry = Assert.Single(logger.Entries); + Assert.Equal(1202, entry.EventId.Id); + Assert.Equal("EventProcessingFailed", entry.EventId.Name); Assert.Equal(LogLevel.Warning, entry.LogLevel); Assert.Contains("failed processing", entry.Message, StringComparison.Ordinal); Assert.IsType(entry.Exception); @@ -1003,11 +1005,12 @@ public void Log( Exception? exception, Func formatter) { - Entries.Add(new LogEntry(logLevel, formatter(state, exception), exception)); + Entries.Add(new LogEntry(eventId, logLevel, formatter(state, exception), exception)); } } private sealed record LogEntry( + EventId EventId, LogLevel LogLevel, string Message, Exception? Exception); From 665cab3fcf5c4c7040b62be30430f5d63ea7151d Mon Sep 17 00:00:00 2001 From: George Date: Sat, 25 Jul 2026 16:23:13 +0200 Subject: [PATCH 09/12] Identify exhausted event retries --- src/TinyEvents/Processing/TinyOutboxProcessor.cs | 8 ++++---- .../Processing/TinyOutboxProcessorLog.cs | 14 ++++++++++++++ .../Processing/TinyOutboxProcessorTests.cs | 12 +++++++++++- 3 files changed, 29 insertions(+), 5 deletions(-) diff --git a/src/TinyEvents/Processing/TinyOutboxProcessor.cs b/src/TinyEvents/Processing/TinyOutboxProcessor.cs index c09c73f..6bfef47 100644 --- a/src/TinyEvents/Processing/TinyOutboxProcessor.cs +++ b/src/TinyEvents/Processing/TinyOutboxProcessor.cs @@ -263,14 +263,14 @@ private void LogProcessingFailure( return; } - logger.LogWarning( - exception, - "TinyEvents outbox message {MessageId} for event type {EventType} failed processing on worker {WorkerId} at attempt {AttemptCount}. Next attempt at {NextAttemptAtUtc}.", + TinyOutboxProcessorLog.RetriesExhausted( + logger, message.Id, message.EventType, workerId, failure.AttemptCount, - failure.NextAttemptAtUtc); + options.MaxAttempts, + exception); } private void LogLeaseLost( diff --git a/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs b/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs index 894a907..f512b98 100644 --- a/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs +++ b/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs @@ -17,4 +17,18 @@ public static partial void ProcessingFailed( int attempt, DateTimeOffset nextAttemptAtUtc, Exception exception); + + [LoggerMessage( + EventId = 1204, + EventName = "EventRetriesExhausted", + Level = LogLevel.Error, + Message = "TinyEvents outbox message {MessageId} for event type {EventType} exhausted processing retries on worker {WorkerId} at attempt {Attempt} of {MaximumAttempts}.")] + public static partial void RetriesExhausted( + ILogger logger, + Guid messageId, + string eventType, + string workerId, + int attempt, + int maximumAttempts, + Exception exception); } diff --git a/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs b/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs index 00a7e32..e6c4804 100644 --- a/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs +++ b/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs @@ -288,11 +288,15 @@ await store.AddAsync( public async Task Process_pending_async_marks_failed_without_retry_after_max_attempts() { ThrowingConsumer.Throw = true; + var logger = new RecordingLogger(); var store = new InMemoryTinyOutboxStore(); await store.AddAsync( NewPendingMessage(new UserCreated(Guid.NewGuid(), "user@example.com"), attemptCount: 4), CancellationToken.None); - var processor = BuildProcessor(store, includeThrowingConsumer: true); + var processor = BuildProcessor( + store, + includeThrowingConsumer: true, + logger: logger); await processor.ProcessPendingAsync(); @@ -300,6 +304,12 @@ await store.AddAsync( Assert.Equal(TinyOutboxMessageStatus.Failed, message.Status); Assert.Equal(5, message.AttemptCount); Assert.Null(message.NextAttemptAtUtc); + var entry = Assert.Single(logger.Entries); + Assert.Equal(1204, entry.EventId.Id); + Assert.Equal("EventRetriesExhausted", entry.EventId.Name); + Assert.Equal(LogLevel.Error, entry.LogLevel); + Assert.Contains("at attempt 5 of 5", entry.Message, StringComparison.Ordinal); + Assert.IsType(entry.Exception); ThrowingConsumer.Throw = false; } From 62d40db50a1a62875e377177805af6e6f2edcfb3 Mon Sep 17 00:00:00 2001 From: George Date: Sat, 25 Jul 2026 16:24:24 +0200 Subject: [PATCH 10/12] Identify outbox lease loss --- src/TinyEvents/Processing/TinyOutboxProcessor.cs | 8 ++++---- src/TinyEvents/Processing/TinyOutboxProcessorLog.cs | 13 +++++++++++++ .../Processing/TinyOutboxProcessorTests.cs | 8 ++++++-- 3 files changed, 23 insertions(+), 6 deletions(-) diff --git a/src/TinyEvents/Processing/TinyOutboxProcessor.cs b/src/TinyEvents/Processing/TinyOutboxProcessor.cs index 6bfef47..2fc64ce 100644 --- a/src/TinyEvents/Processing/TinyOutboxProcessor.cs +++ b/src/TinyEvents/Processing/TinyOutboxProcessor.cs @@ -279,13 +279,13 @@ private void LogLeaseLost( TinyOutboxLeaseLostException exception, string operation) { - logger.LogWarning( - exception, - "TinyEvents outbox message {MessageId} for event type {EventType} lost its processing lease while {Operation} on worker {WorkerId}.", + TinyOutboxProcessorLog.LeaseLost( + logger, message.Id, message.EventType, operation, - workerId); + workerId, + exception); } private readonly record struct RecordedFailure( diff --git a/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs b/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs index f512b98..a3804bd 100644 --- a/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs +++ b/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs @@ -31,4 +31,17 @@ public static partial void RetriesExhausted( int attempt, int maximumAttempts, Exception exception); + + [LoggerMessage( + EventId = 1300, + EventName = "LeaseLost", + Level = LogLevel.Warning, + Message = "TinyEvents outbox message {MessageId} for event type {EventType} lost its processing lease while {Operation} on worker {WorkerId}.")] + public static partial void LeaseLost( + ILogger logger, + Guid messageId, + string eventType, + string operation, + string workerId, + Exception exception); } diff --git a/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs b/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs index e6c4804..8a20a34 100644 --- a/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs +++ b/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs @@ -407,7 +407,9 @@ public async Task Process_pending_async_continues_when_mark_processed_loses_leas Assert.Equal(secondMessage.Id, Assert.Single(store.ProcessedMessageIds)); Assert.Equal(0, store.MarkFailedCount); Assert.Contains(logger.Entries, entry => - entry.LogLevel == LogLevel.Warning + entry.EventId.Id == 1300 + && entry.EventId.Name == "LeaseLost" + && entry.LogLevel == LogLevel.Warning && entry.Message.Contains("lost its processing lease", StringComparison.Ordinal) && entry.Exception is TinyOutboxLeaseLostException); } @@ -425,7 +427,9 @@ public async Task Process_pending_async_continues_when_mark_failed_loses_lease() Assert.Equal(1, store.MarkFailedCount); Assert.Contains(logger.Entries, entry => - entry.LogLevel == LogLevel.Warning + entry.EventId.Id == 1300 + && entry.EventId.Name == "LeaseLost" + && entry.LogLevel == LogLevel.Warning && entry.Message.Contains("lost its processing lease", StringComparison.Ordinal) && entry.Exception is TinyOutboxLeaseLostException); ThrowingConsumer.Throw = false; From aba901309969bfbcfefe9b988b6b98152794cec6 Mon Sep 17 00:00:00 2001 From: George Date: Sat, 25 Jul 2026 16:27:36 +0200 Subject: [PATCH 11/12] Verify processor logging safety --- .../Processing/TinyOutboxProcessor.cs | 67 ++++++------------- .../Processing/TinyOutboxProcessorLog.cs | 54 ++++++++++++++- .../Processing/TinyOutboxProcessorTests.cs | 35 +++++++++- 3 files changed, 104 insertions(+), 52 deletions(-) diff --git a/src/TinyEvents/Processing/TinyOutboxProcessor.cs b/src/TinyEvents/Processing/TinyOutboxProcessor.cs index 2fc64ce..e9050e7 100644 --- a/src/TinyEvents/Processing/TinyOutboxProcessor.cs +++ b/src/TinyEvents/Processing/TinyOutboxProcessor.cs @@ -132,7 +132,12 @@ private async ValueTask ProcessMessageAsync( } catch (TinyOutboxLeaseLostException exception) { - LogLeaseLost(message, workerId, exception, "marked as processed"); + TinyOutboxProcessorLog.LeaseLost( + logger, + message, + workerId, + "marked as processed", + exception); } } @@ -145,11 +150,23 @@ private async ValueTask RecordProcessingFailureAsync( try { var failure = await MarkFailedAsync(message, workerId, exception, cancellationToken); - LogProcessingFailure(message, workerId, exception, failure); + TinyOutboxProcessorLog.ProcessingFailure( + logger, + message, + workerId, + failure.AttemptCount, + options.MaxAttempts, + failure.NextAttemptAtUtc, + exception); } catch (TinyOutboxLeaseLostException leaseLostException) { - LogLeaseLost(message, workerId, leaseLostException, "recording a processing failure"); + TinyOutboxProcessorLog.LeaseLost( + logger, + message, + workerId, + "recording a processing failure", + leaseLostException); } } @@ -244,50 +261,6 @@ private static void AddDispatcher( dispatchers.Add(dispatcher.EventTypeName, dispatcher); } - private void LogProcessingFailure( - TinyOutboxMessage message, - string workerId, - Exception exception, - RecordedFailure failure) - { - if (failure.NextAttemptAtUtc is not null) - { - TinyOutboxProcessorLog.ProcessingFailed( - logger, - message.Id, - message.EventType, - workerId, - failure.AttemptCount, - failure.NextAttemptAtUtc.Value, - exception); - return; - } - - TinyOutboxProcessorLog.RetriesExhausted( - logger, - message.Id, - message.EventType, - workerId, - failure.AttemptCount, - options.MaxAttempts, - exception); - } - - private void LogLeaseLost( - TinyOutboxMessage message, - string workerId, - TinyOutboxLeaseLostException exception, - string operation) - { - TinyOutboxProcessorLog.LeaseLost( - logger, - message.Id, - message.EventType, - operation, - workerId, - exception); - } - private readonly record struct RecordedFailure( int AttemptCount, DateTimeOffset? NextAttemptAtUtc); diff --git a/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs b/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs index a3804bd..9a591e5 100644 --- a/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs +++ b/src/TinyEvents/Processing/TinyOutboxProcessorLog.cs @@ -4,12 +4,60 @@ namespace TinyEvents; internal static partial class TinyOutboxProcessorLog { + public static void ProcessingFailure( + ILogger logger, + TinyOutboxMessage message, + string workerId, + int attemptCount, + int maximumAttempts, + DateTimeOffset? nextAttemptAtUtc, + Exception exception) + { + if (nextAttemptAtUtc is null) + { + RetriesExhausted( + logger, + message.Id, + message.EventType, + workerId, + attemptCount, + maximumAttempts, + exception); + return; + } + + ProcessingFailed( + logger, + message.Id, + message.EventType, + workerId, + attemptCount, + nextAttemptAtUtc.Value, + exception); + } + + public static void LeaseLost( + ILogger logger, + TinyOutboxMessage message, + string workerId, + string operation, + Exception exception) + { + LeaseLost( + logger, + message.Id, + message.EventType, + operation, + workerId, + exception); + } + [LoggerMessage( EventId = 1202, EventName = "EventProcessingFailed", Level = LogLevel.Warning, Message = "TinyEvents outbox message {MessageId} for event type {EventType} failed processing on worker {WorkerId} at attempt {Attempt}. Next attempt at {NextAttemptAtUtc}.")] - public static partial void ProcessingFailed( + private static partial void ProcessingFailed( ILogger logger, Guid messageId, string eventType, @@ -23,7 +71,7 @@ public static partial void ProcessingFailed( EventName = "EventRetriesExhausted", Level = LogLevel.Error, Message = "TinyEvents outbox message {MessageId} for event type {EventType} exhausted processing retries on worker {WorkerId} at attempt {Attempt} of {MaximumAttempts}.")] - public static partial void RetriesExhausted( + private static partial void RetriesExhausted( ILogger logger, Guid messageId, string eventType, @@ -37,7 +85,7 @@ public static partial void RetriesExhausted( EventName = "LeaseLost", Level = LogLevel.Warning, Message = "TinyEvents outbox message {MessageId} for event type {EventType} lost its processing lease while {Operation} on worker {WorkerId}.")] - public static partial void LeaseLost( + private static partial void LeaseLost( ILogger logger, Guid messageId, string eventType, diff --git a/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs b/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs index 8a20a34..e0d6d38 100644 --- a/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs +++ b/tests/TinyEvents.Tests/Processing/TinyOutboxProcessorTests.cs @@ -194,6 +194,18 @@ public async Task Process_pending_async_logs_recorded_processing_failure() Assert.Equal("EventProcessingFailed", entry.EventId.Name); Assert.Equal(LogLevel.Warning, entry.LogLevel); Assert.Contains("failed processing", entry.Message, StringComparison.Ordinal); + Assert.DoesNotContain("user@example.com", entry.Message, StringComparison.Ordinal); + Assert.Equal("worker-1", entry.Properties["WorkerId"]); + Assert.Equal(1, entry.Properties["Attempt"]); + Assert.Equal(typeof(UserCreated).FullName, entry.Properties["EventType"]); + Assert.IsType(entry.Properties["MessageId"]); + Assert.IsType(entry.Properties["NextAttemptAtUtc"]); + Assert.DoesNotContain( + entry.Properties.Values, + value => string.Equals( + value?.ToString(), + "user@example.com", + StringComparison.Ordinal)); Assert.IsType(entry.Exception); ThrowingConsumer.Throw = false; } @@ -1019,7 +1031,25 @@ public void Log( Exception? exception, Func formatter) { - Entries.Add(new LogEntry(eventId, logLevel, formatter(state, exception), exception)); + Entries.Add(new LogEntry( + eventId, + logLevel, + formatter(state, exception), + exception, + GetProperties(state))); + } + + private static IReadOnlyDictionary GetProperties(TState state) + { + if (state is not IEnumerable> properties) + { + return new Dictionary(StringComparer.Ordinal); + } + + return properties.ToDictionary( + property => property.Key, + property => property.Value, + StringComparer.Ordinal); } } @@ -1027,5 +1057,6 @@ private sealed record LogEntry( EventId EventId, LogLevel LogLevel, string Message, - Exception? Exception); + Exception? Exception, + IReadOnlyDictionary Properties); } From 51cfc9f9ab92d02417257e788d2e60d56495854f Mon Sep 17 00:00:00 2001 From: George Date: Sat, 25 Jul 2026 16:57:16 +0200 Subject: [PATCH 12/12] Document worker logging contract --- docs/workers.md | 42 +++++++++++++++++++ .../TinyEventsWorkerTests.cs | 33 +++++++++++---- 2 files changed, 68 insertions(+), 7 deletions(-) diff --git a/docs/workers.md b/docs/workers.md index 7eec204..612d443 100644 --- a/docs/workers.md +++ b/docs/workers.md @@ -88,6 +88,48 @@ On shutdown, TinyEvents does not scan and release claims. If processing does not A hosted worker can remain running while processing iterations repeatedly fail, for example during a database outage. Treat worker logs and host-level health checks as part of production operations. +## Runtime Logging + +TinyEvents uses `Microsoft.Extensions.Logging`. The application owns log +providers, storage, formatting, alerting, and retention. + +Runtime events have stable identifiers: + +| Event ID | Name | Level | Meaning | +|---:|---|---|---| +| 1100 | `WorkerIterationFailed` | Warning | An iteration failed and the worker will retry. | +| 1101 | `WorkerRecovered` | Information | An iteration succeeded after one or more consecutive failures. | +| 1104 | `RepeatedWorkerFailures` | Error | A repeated-failure threshold was reached and operator attention is required. | +| 1202 | `EventProcessingFailed` | Warning | A message failed and another attempt is scheduled. | +| 1204 | `EventRetriesExhausted` | Error | A message reached `MaxAttempts` and no retry remains. | +| 1300 | `LeaseLost` | Warning | The worker no longer owns the message lease. | + +Worker iteration failures are reported without stopping the worker: + +- failures 1 through 4 emit `WorkerIterationFailed` +- failures 5, 10, 20, and 50 emit `RepeatedWorkerFailures` +- later multiples of 100 emit `RepeatedWorkerFailures` +- failures between those thresholds are not logged +- the first later success emits one `WorkerRecovered` event and resets the + consecutive-failure count + +Requested cancellation is not counted as a failure and does not emit a +failure event. + +Runtime logs use structured properties where applicable: + +- `MessageId` +- `EventType` +- `WorkerId` +- `Attempt` +- `MaximumAttempts` +- `NextAttemptAtUtc` +- `ConsecutiveFailures` +- `Operation` + +TinyEvents does not log event payloads, serialized event bodies, connection +strings, credentials, secrets, tokens, or arbitrary event property values. + ## Marking Processed Or Failed Providers mark messages only when: diff --git a/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs b/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs index 7a0745f..cad558a 100644 --- a/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs +++ b/tests/TinyEvents.Worker.Tests/TinyEventsWorkerTests.cs @@ -259,7 +259,7 @@ public async Task Background_service_continues_after_processing_iteration_fails( Assert.Equal(LogLevel.Warning, failure.LogLevel); Assert.Equal(1100, failure.EventId.Id); Assert.Equal("WorkerIterationFailed", failure.EventId.Name); - Assert.Contains("Consecutive failures: 1", failure.Message, StringComparison.Ordinal); + Assert.Equal(1, failure.Properties["ConsecutiveFailures"]); Assert.IsType(failure.Exception); }, recovery => @@ -267,7 +267,7 @@ public async Task Background_service_continues_after_processing_iteration_fails( Assert.Equal(LogLevel.Information, recovery.LogLevel); Assert.Equal(1101, recovery.EventId.Id); Assert.Equal("WorkerRecovered", recovery.EventId.Name); - Assert.Contains("after 1 consecutive failed iterations", recovery.Message, StringComparison.Ordinal); + Assert.Equal(1, recovery.Properties["ConsecutiveFailures"]); Assert.Null(recovery.Exception); }); } @@ -291,7 +291,7 @@ public async Task Background_service_stops_active_iteration_without_logging_canc await worker.StopAsync(timeout.Token); Assert.True(processor.CancellationObserved); - Assert.DoesNotContain(logger.Entries, entry => entry.LogLevel == LogLevel.Error); + Assert.Empty(logger.Entries); } [Fact] @@ -327,11 +327,11 @@ public async Task Background_service_throttles_repeated_failures_and_reports_rec Assert.Contains( logger.Entries, entry => entry.EventId.Id == 1104 - && entry.Message.Contains("failed 5 consecutive", StringComparison.Ordinal)); + && Equals(entry.Properties["ConsecutiveFailures"], 5)); Assert.Contains( logger.Entries, entry => entry.EventId.Id == 1104 - && entry.Message.Contains("failed 10 consecutive", StringComparison.Ordinal)); + && Equals(entry.Properties["ConsecutiveFailures"], 10)); } private static async Task WaitForLogAsync( @@ -448,7 +448,25 @@ public void Log( Exception? exception, Func formatter) { - Entries.Enqueue(new LogEntry(eventId, logLevel, formatter(state, exception), exception)); + Entries.Enqueue(new LogEntry( + eventId, + logLevel, + formatter(state, exception), + exception, + GetProperties(state))); + } + + private static IReadOnlyDictionary GetProperties(TState state) + { + if (state is not IEnumerable> properties) + { + return new Dictionary(StringComparer.Ordinal); + } + + return properties.ToDictionary( + property => property.Key, + property => property.Value, + StringComparer.Ordinal); } } @@ -456,5 +474,6 @@ private sealed record LogEntry( EventId EventId, LogLevel LogLevel, string Message, - Exception? Exception); + Exception? Exception, + IReadOnlyDictionary Properties); }