diff --git a/CHANGELOG.md b/CHANGELOG.md index 358834df3..3ebf09051 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -11,6 +11,17 @@ follow [Semantic Versioning](https://semver.org). Ongoing work is collected unde ### Fixed +- **Edits to an agent no longer fail for minutes after a busy save.** Under concurrent traffic — an + agent being updated while its traces were still arriving and the UI was open — the in-process entity + cache could refill with the *pre-save* version of a row and keep serving it for up to five minutes. + Every write attempted against that stale copy was rejected as a conflict, so ingestion retried and + saves failed for no visible reason. Cached entries are now dropped again once the save commits, so + the stale copy cannot outlive the write that replaced it. + +- **The proxy logs each upstream request once, not four times.** Every call your agents made through + the proxy emitted four identical sets of HTTP client log lines, quadrupling the volume on the + busiest path in the system and making proxy logs hard to read during an incident. + - **Proxytrace is documented as source-available, consistently.** The Docker Hub overview still declared the product *Proprietary*, contradicting the Elastic License 2.0 relicense in 1.5.0 — the first licensing statement most evaluators read. It now states the ELv2 terms, the README carries a diff --git a/Proxytrace.Common.Tests/AutofacExtensionsTests.cs b/Proxytrace.Common.Tests/AutofacExtensionsTests.cs new file mode 100644 index 000000000..366c38185 --- /dev/null +++ b/Proxytrace.Common.Tests/AutofacExtensionsTests.cs @@ -0,0 +1,70 @@ +using Autofac; +using AwesomeAssertions; +using Microsoft.Extensions.DependencyInjection; +using Proxytrace.Common.DependencyInjection; + +namespace Proxytrace.Common.Tests; + +[TestClass] +public sealed class AutofacExtensionsTests +{ + private interface IPlumbing; + + private sealed class SharedPlumbing : IPlumbing; + + private sealed class OtherPlumbing : IPlumbing; + + [TestMethod] + public void RegisterServiceCollection_WhenTwoModulesRegisterTheSameImplementation_PopulatesItOnce() + { + // Framework extension methods share their plumbing through TryAddEnumerable, which dedupes + // only within one IServiceCollection. Every RegisterServiceCollection call builds a fresh + // one, so without this the container ends up with a copy per caller — which is how a single + // upstream request came to be logged once per module that had called AddHttpClient (#451). + var builder = new ContainerBuilder(); + builder.RegisterServiceCollection(services => + services.AddSingleton()); + builder.RegisterServiceCollection(services => + services.AddSingleton()); + + using var container = builder.Build(); + + container.Resolve>().Should().ContainSingle() + .Which.Should().BeOfType(); + } + + [TestMethod] + public void RegisterServiceCollection_WithDistinctImplementations_KeepsEveryOne() + { + // Registering several implementations of one service is the whole point of IEnumerable + // resolution — only an identical (service, implementation, lifetime) triple is a duplicate. + var builder = new ContainerBuilder(); + builder.RegisterServiceCollection(services => + services.AddSingleton()); + builder.RegisterServiceCollection(services => + services.AddSingleton()); + + using var container = builder.Build(); + + container.Resolve>() + .Should().HaveCount(2) + .And.ContainItemsAssignableTo(); + } + + [TestMethod] + public void RegisterServiceCollection_WithInstanceRegistrations_LeavesThemAlone() + { + // Instance and factory descriptors are opaque — two of them are never provably the same + // registration, so they are populated exactly as written. + var first = new SharedPlumbing(); + var second = new SharedPlumbing(); + + var builder = new ContainerBuilder(); + builder.RegisterServiceCollection(services => services.AddSingleton(first)); + builder.RegisterServiceCollection(services => services.AddSingleton(second)); + + using var container = builder.Build(); + + container.Resolve>().Should().HaveCount(2); + } +} diff --git a/Proxytrace.Common/DependencyInjection/AutofacExtensions.cs b/Proxytrace.Common/DependencyInjection/AutofacExtensions.cs index bfc6056a4..8b37982a7 100644 --- a/Proxytrace.Common/DependencyInjection/AutofacExtensions.cs +++ b/Proxytrace.Common/DependencyInjection/AutofacExtensions.cs @@ -8,13 +8,63 @@ namespace Proxytrace.Common.DependencyInjection; public static class AutofacExtensions { + private const string PopulatedDescriptorsKey = "Proxytrace.ServiceCollection.PopulatedDescriptors"; + public static void RegisterServiceCollection(this ContainerBuilder builder, Action config) { var services = new ServiceCollection(); config(services); + DropAlreadyPopulated(builder, services); builder.Populate(services); } - + + /// + /// Removes descriptors that an earlier call already + /// populated into this container, so registering the same concrete implementation twice does not + /// leave two copies behind. + /// + /// + /// Framework extension methods share their plumbing through TryAdd/TryAddEnumerable, + /// which dedupes only within *one* . Every call here builds a + /// fresh collection, so each one re-adds that plumbing and Populate faithfully registers + /// all of it. Four modules calling AddHttpClient therefore put four + /// IHttpMessageHandlerBuilderFilters in the container, and the logging handler each one + /// contributes wrapped every outgoing request — so a single upstream LLM call was logged four + /// times, on the hottest path in the system (#451). + /// + /// Only type-based registrations are compared: an identical (service, implementation, lifetime) + /// triple can never mean two *different* things, whereas instance- and factory-based descriptors + /// are opaque and are always populated as written. Genuine multi-registrations of one service + /// (the point of IEnumerable<T> resolution) use distinct implementation types and are + /// untouched. + /// + private static void DropAlreadyPopulated(ContainerBuilder builder, IServiceCollection services) + { + if (!builder.Properties.TryGetValue(PopulatedDescriptorsKey, out object? stored) + || stored is not HashSet<(Type Service, Type Implementation, ServiceLifetime Lifetime)> populated) + { + populated = []; + builder.Properties[PopulatedDescriptorsKey] = populated; + } + + for (int i = services.Count - 1; i >= 0; i--) + { + ServiceDescriptor descriptor = services[i]; + + // Keyed descriptors throw on the non-keyed accessors; they are rare and always explicit, + // so leave them alone rather than reaching for their keyed counterparts. + if (descriptor.IsKeyedService || descriptor.ImplementationType is not { } implementation) + { + continue; + } + + if (!populated.Add((descriptor.ServiceType, implementation, descriptor.Lifetime))) + { + services.RemoveAt(i); + } + } + } + public static IReadOnlyCollection GetImplementations( this Type type, Assembly? assembly = null) diff --git a/Proxytrace.Proxy.Tests/HttpClientRegistrationTests.cs b/Proxytrace.Proxy.Tests/HttpClientRegistrationTests.cs new file mode 100644 index 000000000..620f62535 --- /dev/null +++ b/Proxytrace.Proxy.Tests/HttpClientRegistrationTests.cs @@ -0,0 +1,58 @@ +using Autofac; +using AwesomeAssertions; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Http; +using Proxytrace.Common.DependencyInjection; + +namespace Proxytrace.Proxy.Tests; + +/// +/// Guards the registration shape behind #451: one upstream LLM call was emitting four identical sets +/// of System.Net.Http.HttpClient.openai.* log lines — four handler instances logging one +/// request, on the hottest path in the system. AddHttpClient shares its plumbing through +/// TryAddEnumerable, which dedupes only within a single ; the +/// API host composes four modules (Api, Application, Licensing, Proxy) that each call it on their own +/// collection, so the container ended up with one logging filter per module. +/// +[TestClass] +public sealed class HttpClientRegistrationTests +{ + [TestMethod] + public void RegisterServiceCollection_WithHttpClientsFromSeveralModules_RegistersOneLoggingFilter() + { + var builder = new ContainerBuilder(); + + // Stands in for the four modules that each register their own named clients. + builder.RegisterServiceCollection(services => services.AddHttpClient("openai")); + builder.RegisterServiceCollection(services => services.AddHttpClient("passthrough")); + builder.RegisterServiceCollection(services => services.AddHttpClient("license-server")); + builder.RegisterServiceCollection(services => services.AddHttpClient("self")); + + using var container = builder.Build(); + + var filters = container.Resolve>().ToList(); + + // One of each kind the framework ships (logging, metrics) — not one set per module. Every + // duplicate logging filter wraps the request in another logging handler. + filters.Should().OnlyHaveUniqueItems(); + filters.Select(f => f.GetType()).Should().OnlyHaveUniqueItems(); + } + + [TestMethod] + public void RegisterServiceCollection_WithHttpClientsFromSeveralModules_KeepsEveryNamedClient() + { + // Deduplicating the shared plumbing must not touch the per-name configuration, which is what + // makes a named client actually usable — those are instance descriptors, not type ones. + var builder = new ContainerBuilder(); + builder.RegisterServiceCollection(services => + services.AddHttpClient("openai", client => client.Timeout = TimeSpan.FromMinutes(5))); + builder.RegisterServiceCollection(services => + services.AddHttpClient("passthrough", client => client.Timeout = TimeSpan.FromMinutes(3))); + + using var container = builder.Build(); + var factory = container.Resolve(); + + factory.CreateClient("openai").Timeout.Should().Be(TimeSpan.FromMinutes(5)); + factory.CreateClient("passthrough").Timeout.Should().Be(TimeSpan.FromMinutes(3)); + } +} diff --git a/Proxytrace.Storage.Tests/CachedRepositoryTests.cs b/Proxytrace.Storage.Tests/CachedRepositoryTests.cs index 374caa6f1..258fb9b5d 100644 --- a/Proxytrace.Storage.Tests/CachedRepositoryTests.cs +++ b/Proxytrace.Storage.Tests/CachedRepositoryTests.cs @@ -224,6 +224,51 @@ public async Task UpdateAsync_InvalidatesCacheUnconditionally() cache.TryGet(created.Id).Should().BeNull("the write must invalidate the cache entry"); } + [TestMethod] + public async Task UpdateAsync_WhenAConcurrentReaderRepopulatesMidTransaction_TheEntryIsDroppedAfterCommit() + { + // The race behind #450: invalidation ran inside the still-open transaction, and CanUseCache + // suppresses the cache for the *writing* flow only (ambient.IsActive is AsyncLocal). Between + // that invalidation and the commit, a reader on another flow could miss the cache, read the + // pre-commit row and Set() it back — with nothing invalidating afterwards, the stale entity + // and its stale concurrency token were served until the 5-minute TTL expired, failing every + // write made against it in between. + IServiceProvider services = GetServices(); + var repository = services.GetRequiredService>(); + var generator = services.GetRequiredService>(); + var createExisting = services.GetRequiredService(); + var cache = services.GetRequiredService>(); + var transaction = services.GetRequiredService(); + + IModel created = await generator.CreateAsync(CancellationToken); + + await transaction.InvokeAsync(async () => + { + await repository.UpdateAsync(createExisting("after-update", created), CancellationToken); + + // Suppressing the ExecutionContext flow keeps the ambient transaction's AsyncLocal out of + // the spawned task, so that read sees CanUseCache as true and repopulates the cache — + // exactly what the racing reader does. + Task concurrentRead; + using (ExecutionContext.SuppressFlow()) + { + // Started inside the suppression and awaited outside it: AsyncFlowControl must be + // disposed on the thread that created it, which an await in between cannot promise. + concurrentRead = Task.Run(() => repository.FindAsync(created.Id, CancellationToken)); + } + + await concurrentRead; + + cache.TryGet(created.Id).Should().NotBeNull("the concurrent reader is expected to have repopulated the cache"); + }); + + cache.TryGet(created.Id).Should().BeNull("committing must invalidate again, dropping whatever the reader cached"); + + IModel reloaded = await repository.FindAsync(created.Id, CancellationToken) + ?? throw new InvalidOperationException("Expected the updated model to be readable."); + reloaded.Name.Should().Be("after-update"); + } + private sealed class FakeTimeProvider : TimeProvider { private DateTimeOffset now; diff --git a/Proxytrace.Storage/Internal/AbstractRepository.cs b/Proxytrace.Storage/Internal/AbstractRepository.cs index 53df4d43f..0694e5c3e 100644 --- a/Proxytrace.Storage/Internal/AbstractRepository.cs +++ b/Proxytrace.Storage/Internal/AbstractRepository.cs @@ -50,11 +50,40 @@ protected void Notify(Guid id, EntityChangeType change) } /// - /// Invalidate a single cached entity. Use after bypass writes that do not go through - /// the standard Add/Update path. + /// Invalidate a single cached entity — now, and again once the outermost transaction commits. + /// Use after any write, including bypass writes that do not go through the standard Add/Update + /// path. /// - protected void InvalidateCacheEntry(Guid id) - => cache?.Invalidate(id); + /// + /// Invalidating only inside the transaction leaves a window. suppresses + /// the cache for the *writing* flow only — ambient.IsActive is AsyncLocal — so + /// between the invalidation and the commit a concurrent reader on another flow can miss the + /// cache, read the still **pre-commit** row and Set() it back. Nothing invalidated again + /// afterwards, so that stale entity was served until the 5-minute TTL expired. It carries a stale + /// UpdatedAt, which is the optimistic-concurrency token, so every write made against it in + /// the meantime failed the pre-check in — turning a millisecond + /// race into minutes of failing writes on hot, cached, ingest-mutated entities like + /// IAgent (#450). Repeating the invalidation after the commit closes the window. + /// + protected void InvalidateCacheEntry(Guid id) + { + cache?.Invalidate(id); + + if (ambient.IsActive) + ambient.RegisterPostCommit(() => cache?.Invalidate(id)); + } + + /// + /// Drop the whole cache — now, and again once the outermost transaction commits, for the reason + /// described on . + /// + protected void InvalidateCache() + { + cache?.InvalidateAll(); + + if (ambient.IsActive) + ambient.RegisterPostCommit(() => cache?.InvalidateAll()); + } // The cache must never be read from or populated while an ambient transaction is active: // values read inside a transaction can reflect uncommitted writes, and populating from a @@ -285,7 +314,7 @@ private async Task AddCoreAsync( TStoredEntity stored = await mapper.Map(entity, cancellationToken); EntityEntry entry = context.Set().Add(stored); await context.SaveChangesAsync(cancellationToken); - cache?.Invalidate(entity.Id); + InvalidateCacheEntry(entity.Id); return await mapper.Map(entry.Entity, cancellationToken); } @@ -332,7 +361,7 @@ await transaction.InvokeAsync(async () => foreach (TDomainEntity entity in entities) { - cache?.Invalidate(entity.Id); + InvalidateCacheEntry(entity.Id); Notify(entity.Id, EntityChangeType.Added); } } @@ -417,7 +446,7 @@ private async Task UpdateCoreAsync( { throw new OptimisticConcurrencyException(entity.Id, typeof(TDomainEntity), ex); } - cache?.Invalidate(entity.Id); + InvalidateCacheEntry(entity.Id); return await this.GetAsync(entity.Id, cancellationToken); } @@ -454,7 +483,7 @@ public virtual async Task RemoveAsync(Guid id, CancellationToken cancellat // matches the version we loaded — treat it as "not removed by us" rather than throwing. return false; } - cache?.Invalidate(id); + InvalidateCacheEntry(id); return true; }); @@ -474,7 +503,7 @@ public async Task RemoveAllAsync(CancellationToken cancellationToken = default) Guid[] ids = await set.AsNoTracking().Select(e => e.Id).ToArrayAsync(cancellationToken); set.RemoveRange(set); await context.SaveChangesAsync(cancellationToken); - cache?.InvalidateAll(); + InvalidateCache(); return ids; }); diff --git a/Proxytrace.Storage/Internal/Entities/Agent/AgentRepository.cs b/Proxytrace.Storage/Internal/Entities/Agent/AgentRepository.cs index 83d939890..80dbcbc68 100644 --- a/Proxytrace.Storage/Internal/Entities/Agent/AgentRepository.cs +++ b/Proxytrace.Storage/Internal/Entities/Agent/AgentRepository.cs @@ -169,10 +169,23 @@ private async Task PersistWithInitialVersionAsync(IAgent agent, Cancella }); InvalidateCacheEntry(agentId); - versionCache?.InvalidateAll(); + InvalidateVersionCache(); return await this.GetAsync(agentId, cancellationToken); } + /// + /// Drops the agent-version cache now and again after the outermost transaction commits — the + /// window described on + /// applies to this second cache too when the write is nested in a larger logical unit. + /// + private void InvalidateVersionCache() + { + versionCache?.InvalidateAll(); + + if (ambient.IsActive) + ambient.RegisterPostCommit(() => versionCache?.InvalidateAll()); + } + private Task SetCurrentVersionIdAsync(Guid agentId, Guid versionId, CancellationToken cancellationToken) => transaction.InvokeAsync(async () => { diff --git a/docs/architecture.md b/docs/architecture.md index c3b98ce92..a2aac2346 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -70,6 +70,8 @@ Your Agent ──► Proxytrace.Proxy.Api ──► Upstream LLM provider DI is wired with Autofac. Each project ships a `Module : Autofac.Module` (`Proxytrace.Domain.Module`, `Proxytrace.Application.Module`, `Proxytrace.Storage.Module`, `Proxytrace.Infrastructure.Module`, `Proxytrace.Serialization.Module`, `Proxytrace.Common.Module`, `Proxytrace.Api.Module`, `Proxytrace.Proxy.Module` (pipeline lib), `Proxytrace.Proxy.Api.Module` (standalone host), `Proxytrace.Testing.Module`). `Proxytrace.Domain.Module` and `Proxytrace.Storage.Module` discover entities, generators, configurations, and repositories by reflection — no manual registrations for the standard entity pattern. The API serves the compiled React app from `wwwroot/` in production. +**Bridging to `IServiceCollection`.** Modules that need Microsoft-DI extension methods (`AddHttpClient`, `AddMemoryCache`, …) call `builder.RegisterServiceCollection(services => …)`, which fills a fresh `ServiceCollection` and `Populate`s it into Autofac. Those extension methods share their plumbing through `TryAdd`/`TryAddEnumerable`, which dedupes only **within one collection** — so every caller re-adds it and `Populate` faithfully registers each copy. Four modules calling `AddHttpClient` (Api, Application, Licensing, Proxy) therefore put four `IHttpMessageHandlerBuilderFilter`s in the container, and each one's logging handler wrapped every outgoing request: one upstream LLM call, logged four times ([#451](https://github.com/SyntaktikEU/Proxytrace/issues/451)). `RegisterServiceCollection` now drops descriptors whose (service, implementation, lifetime) triple an earlier call already populated into the same container — an identical type-based registration can never mean two different things, while genuine multi-registrations use distinct implementation types and instance/factory descriptors are left alone. + `Proxytrace.Application.Module` registers the hosted services for ingestion + test running plus the optimization sub-module. `Proxytrace.Storage.Module` takes a `Func` (the configuration is auto-detected by `Proxytrace.Api.Module`) plus a `registerApplicationServices` flag (default `true`). **The `registerApplicationServices` flag.** When `true` — the API/app host and the test/perf harnesses (`Storage.Tests`, `Domain.Tests`, `Application.Tests`, the perf harness) — `Storage.Module` registers Storage's own startup/initialization hosted services: the DB-initializer (`IDatabaseInitializer`) plus the secret/preview backfill services. The standalone **proxy host** (`Proxytrace.Proxy.Api`) passes `false`: it attaches to an already-migrated database read-only and runs no schema init or backfills. Since [#270](https://github.com/SyntaktikEU/Proxytrace/issues/270), `Storage.Module` no longer references or registers `Application.Module` (the flag's name is historical) — each composition root that needs the Application graph (the API host plus the four `Storage.Tests` / `Domain.Tests` / `Application.Tests` / perf harnesses) registers `Application.Module` **and** the at-rest secret seam (`Infrastructure.Security.SecretProtectionModule`) explicitly. The API root's registrations are idempotent (the `IfNotRegistered`/`builder.Properties` guards make any double registration a no-op). diff --git a/docs/database.md b/docs/database.md index 88a333ed3..5891d503c 100644 --- a/docs/database.md +++ b/docs/database.md @@ -329,6 +329,28 @@ Two precision details (see `ConcurrencyTokenExtensions`): > own value-equality concurrency-token check on save, which is why the microsecond realignment above > must be skipped on the in-memory provider. Like the `Restrict`/`Cascade` FK semantics above, treat > lost-update enforcement as Postgres-only. + +## Entity cache invalidation happens twice: in the write, and after the commit + +`[Cacheable]` domain types get an `IEntityCache` (5-minute TTL, write-through invalidation) that +`AbstractRepository` reads through. `CanUseCache` refuses to read from — or populate — the cache while +an ambient transaction is active, because a value read mid-transaction may reflect uncommitted writes. +That suppression is **per async flow**: `ambient.IsActive` is backed by an `AsyncLocal`, so it applies +only to the flow that opened the transaction. + +Invalidation therefore cannot be a single call inside the write. Between an in-transaction +`Invalidate` and the commit, a reader on any *other* flow sees no ambient transaction, misses the +cache, reads the still **pre-commit** row and `Set()`s it back — and nothing invalidated afterwards, so +that stale entity was served for up to the full TTL. The stale copy carries a stale `UpdatedAt`, which +is the optimistic-concurrency token, so every write attempted against it failed the pre-check above: +a millisecond-wide race turned into minutes of failing writes on hot, cached, ingest-mutated entities +like `IAgent` (#450). + +`AbstractRepository.InvalidateCacheEntry` / `InvalidateCache` therefore invalidate **now and again on +commit**, queuing the second call through `AmbientDbContext.RegisterPostCommit` — the same deferral +`Notify` uses for change events. Every write path (add, add-range, update, upsert, remove, +remove-all, archive/unarchive, and bypass writes such as `AgentRepository.SetCurrentVersionIdAsync`) +goes through those two helpers; do not call `cache?.Invalidate(...)` directly. The `AddEmailSettings` migration adds the `EmailSettingsEntity` table: the single-row operator SMTP/email configuration (mirrors the `StoredLicenseEntity` single-row pattern). Columns: `Id` uuid PK, `Enabled` boolean, `SmtpHost` / `FromAddress` / `FromName` non-nullable text, `SmtpPort`