diff --git a/docs/docs/operator/migration.mdx b/docs/docs/operator/migration.mdx index 2198c4e8f..bc323848f 100644 --- a/docs/docs/operator/migration.mdx +++ b/docs/docs/operator/migration.mdx @@ -230,6 +230,19 @@ constructed it directly are affected. **Migration:** pass the concrete controller type when constructing `Reconciler` yourself, or rely on the SDK's registration. +### Entity logging scopes are created through a factory + +`ResourceWatcher`, `EntityQueueBackgroundService` and their leader-/scope-aware +derivations take an additional `IEntityLoggingScopeFactory` argument. The factory applies all +registered enrichers while creating the scope (see +[Logging](./observability/logging#enriching-scopes-with-custom-fields)). + +**Migration:** resolve `IEntityLoggingScopeFactory` through dependency injection. Use its +`CreateFor(...)` methods to create an enriched scope, and pass the factory when directly constructing or +subclassing the watcher and queue types. `EntityLoggingScope.CreateFor(...)` remains available for standalone, +unenriched scopes. The default factory is registered automatically per entity type and is a no-op beyond the +built-in fields when no enrichers are configured. + ### New in v13 (non-breaking) - **Scoped leader election**: `LeaderElectionType.Scoped` partitions responsibility across diff --git a/docs/docs/operator/observability/logging.mdx b/docs/docs/operator/observability/logging.mdx index 0a9ed7967..b03d98e82 100644 --- a/docs/docs/operator/observability/logging.mdx +++ b/docs/docs/operator/observability/logging.mdx @@ -6,40 +6,104 @@ sidebar_position: 1 # Logging -## Logging with `ILogger` and Scopes +## Logging with `ILogger` and scopes -This project uses Microsoft's [`ILogger`](https://learn.microsoft.com/en-us/dotnet/core/extensions/logging) interface for logging. It provides a standardized and extensible way to capture events within the application. +KubeOps uses Microsoft's [`ILogger`](https://learn.microsoft.com/en-us/dotnet/core/extensions/logging) abstraction. +Application code can use the same logging pipeline by injecting a category logger such as +`ILogger`. Using _scopes_ enables hierarchical organization of log messages and allows contextual information to be attached to each entry. -### ILogger Basics +### `ILogger` basics -The `ILogger` interface is part of [`Microsoft.Extensions.Logging`](https://www.nuget.org/packages/Microsoft.Extensions.Logging) and provides methods to log messages at various severity levels (e.g., `Information`, `Warning`, `Error`). +The default application builders (`WebApplication.CreateBuilder` and `Host.CreateApplicationBuilder`) register +logging automatically. For a manually assembled service collection, call `services.AddLogging()`. -Logging can be enabled using either `WebApplication.CreateBuilder`, `Host.CreateDefaultBuilder`, or the `AddLogging` extension method on the `IServiceCollection`. - -You can log from your code by injecting `ILogger` (or a similar type) into your component. - -### Using Scopes +### Entity scopes Scopes define a logical boundary in which all log entries are automatically enriched with contextual metadata. This is especially useful for correlating logs related to a specific request or operation. -By default, two components start a new scope for each operation they perform: +Two operator components create entity scopes: -- The [ResourceWatcher](https://github.com/dotnet/dotnet-operator-sdk/blob/main/src/KubeOps.Operator/Watcher/ResourceWatcher%7BTEntity%7D.cs) opens a scope for every watch event received from the Kubernetes API server. -- The [EntityQueueBackgroundService](https://github.com/dotnet/dotnet-operator-sdk/blob/main/src/KubeOps.Operator/Queue/EntityQueueBackgroundService%7BTEntity%7D.cs) opens a scope for every queue entry it processes before invoking the reconciler. +- `ResourceWatcher` opens a scope around every watch event received from the Kubernetes API server, + including bookmark events. +- `EntityQueueBackgroundService` opens one scope around every dequeued entry. The scope is built from the + entity snapshot stored in the queue and covers lock handling, entity loading, reconciliation, retry scheduling, + and skips. A later retry is a new queue entry and therefore receives a new scope. Both scopes carry the same fields: -- `EventType`: Type of the reconciliation operation (`Added`, `Modified`, `Deleted`) -- `ReconciliationTriggerSource`: Origin of the reconciliation request (`ApiServer` for watch events, `Operator` for internal retries and periodic requeues) -- `Kind`: Custom Resource Definition (CRD) kind -- `Namespace`: CRD namespace -- `Name`: CRD name -- `Uid`: CRD unique identifier -- `ResourceVersion`: CRD resource version +- `EventType`: watch/reconciliation operation (`Added`, `Modified`, `Deleted`, or `Bookmark` for watch scopes) +- `ReconciliationTriggerSource`: `ApiServer` for watch-derived work, or `Operator` for a delayed requeue requested + by a reconciler. Error retries and lock-conflict requeues preserve the trigger source of the original entry +- `Kind`: Kubernetes object kind +- `Namespace`: Kubernetes object namespace +- `Name`: Kubernetes object name +- `Uid`: Kubernetes object UID +- `ResourceVersion`: Kubernetes object resource version + +For `Added` and `Modified` entries, the queue service still loads the current object from the API server before +dispatching it to the reconciler. The logging scope deliberately remains based on the queued event snapshot. Its +`ResourceVersion` and entity-derived custom fields therefore describe the event that caused the queue entry, not +necessarily the newer object instance passed to the reconciler. Controllers that need a scope based on the current +object can create one explicitly through `IEntityLoggingScopeFactory`. + +### Enriching scopes with custom fields -You can create additional scopes in your code using `logger.BeginScope(state)`, where `state` can be either a string or a custom object. +The built-in fields can be extended with custom structured properties on both watch and reconcile scopes. +Implement `IEntityLoggingScopeEnricher` for the entity type and register it on the operator builder: + +```csharp +public sealed class DemoEnricher : IEntityLoggingScopeEnricher +{ + public void Enrich( + V1DemoEntity entity, + EntityLoggingPhase phase, + IDictionary properties) + { + properties.TryAdd("Owner", entity.Spec.Owner); + properties.TryAdd("Phase", phase); + } +} +``` + +```csharp +builder.AddEntityLoggingScopeEnricher(); +``` + +Inject `IEntityLoggingScopeFactory` when application code needs the same enriched scope: + +```csharp +public sealed class DemoService( + ILogger logger, + IEntityLoggingScopeFactory scopeFactory) +{ + public void LogWatchEvent(WatchEventType eventType, V1DemoEntity entity) + { + using var scope = logger.BeginScope(scopeFactory.CreateFor(eventType, entity)); + logger.LogInformation("Processing an application-defined watch event."); + } +} +``` + +Semantics and constraints: + +- **Lifetime**: enrichers are registered and resolved as singletons and must be thread-safe because watch and + reconciliation scopes can be created concurrently. +- **Synchronous hot path**: `Enrich` is called whenever an entity scope is built: once per watch event and once per + dequeued reconciliation entry. Enrichers must be synchronous, cheap, side-effect free, and only read from the + supplied `entity`; do not perform I/O or call the Kubernetes API. +- **Phase**: `phase` is either `Watch` or `Reconcile`, so an enricher can contribute + phase-specific data. +- **Order and add-only semantics**: enrichers run in registration order. Contributions are merged with + first-writer-wins semantics, so enrichers cannot change or remove the built-in identification fields or + properties contributed by an earlier enricher. +- **Error isolation**: if an enricher throws, the failure is logged and skipped; the remaining enrichers + still run and watching/reconciliation is never interrupted. + +`EntityLoggingScope.CreateFor(...)` remains available for standalone scopes that only need the seven built-in +fields. It does not resolve dependency injection and therefore does not run registered enrichers; use +`IEntityLoggingScopeFactory` when enrichment is required. To include scopes in the logging output, they must be explicitly enabled either via configuration or code: @@ -60,29 +124,26 @@ To include scopes in the logging output, they must be explicitly enabled either } ``` -**Programmatic configuration:** +**Programmatic console configuration:** ```csharp -builder - .ConfigureLogging((hostBuilderContext, loggingBuilder) => - { - loggingBuilder - .AddSimpleConsole(options => options.IncludeScopes = true); - }); +builder.Logging.AddSimpleConsole(options => options.IncludeScopes = true); ``` :::tip -To enable scopes with OpenTelemetry, configure it as follows: +For the OpenTelemetry logging provider, enable scope capture when registering the provider: -```json -"OpenTelemetry": { - "IncludeScopes": true, - "ParseStateValues": true, - "IncludeFormattedMessage": true -} +```csharp +builder.Logging.AddOpenTelemetry(options => +{ + options.IncludeScopes = true; + options.ParseStateValues = true; + options.IncludeFormattedMessage = true; +}); ``` -The scope state must be an `IReadOnlyDictionary` to ensure correct serialization and inclusion in log entries. +This registers the provider; configure an exporter separately. Projects using `KubeOps.Aspire` can instead call +`AddKubeOpsServiceDefaults()`, which enables OpenTelemetry scope capture as part of the service defaults. ::: :::tip diff --git a/src/KubeOps.Abstractions/Builder/EntityLoggingScopeEnricherBuilderExtensions.cs b/src/KubeOps.Abstractions/Builder/EntityLoggingScopeEnricherBuilderExtensions.cs new file mode 100644 index 000000000..f880c9cdf --- /dev/null +++ b/src/KubeOps.Abstractions/Builder/EntityLoggingScopeEnricherBuilderExtensions.cs @@ -0,0 +1,34 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information. + +using k8s; +using k8s.Models; + +using KubeOps.Abstractions.Logging; + +using Microsoft.Extensions.DependencyInjection; + +namespace KubeOps.Abstractions.Builder; + +/// +/// Registration helpers for implementations that contribute +/// additional structured properties to the logging scope surrounding every watch event and reconciliation. +/// +public static class EntityLoggingScopeEnricherBuilderExtensions +{ + /// + /// Registers a logging scope enricher applied to scopes created for . + /// + /// The entity type the enricher applies to. + /// The enricher implementation. + /// The operator builder. + /// The same builder for chaining. + public static IOperatorBuilder AddEntityLoggingScopeEnricher(this IOperatorBuilder builder) + where TEntity : IKubernetesObject + where TEnricher : class, IEntityLoggingScopeEnricher + { + builder.Services.AddSingleton, TEnricher>(); + return builder; + } +} diff --git a/src/KubeOps.Abstractions/Logging/EntityLoggingPhase.cs b/src/KubeOps.Abstractions/Logging/EntityLoggingPhase.cs new file mode 100644 index 000000000..288b7bbba --- /dev/null +++ b/src/KubeOps.Abstractions/Logging/EntityLoggingPhase.cs @@ -0,0 +1,18 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information. + +namespace KubeOps.Abstractions.Logging; + +/// +/// Identifies the pipeline stage in which an entity logging scope is being created, allowing +/// enrichers to contribute different properties for a watch event than for a reconciliation. +/// +public enum EntityLoggingPhase +{ + /// The scope is created while ingesting a watch event from the API server. + Watch, + + /// The scope is created while reconciling a queued entity. + Reconcile, +} diff --git a/src/KubeOps.Abstractions/Logging/IEntityLoggingScopeEnricher.cs b/src/KubeOps.Abstractions/Logging/IEntityLoggingScopeEnricher.cs new file mode 100644 index 000000000..56636b48b --- /dev/null +++ b/src/KubeOps.Abstractions/Logging/IEntityLoggingScopeEnricher.cs @@ -0,0 +1,27 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information. + +using k8s; +using k8s.Models; + +namespace KubeOps.Abstractions.Logging; + +/// +/// Contributes additional structured properties to logging scopes created for . +/// Enrichers can add properties, but cannot change or remove existing properties. +/// +/// The entity type this enricher applies to. +/// +/// Register via builder.AddEntityLoggingScopeEnricher<TEntity, TEnricher>(). Enrichers are resolved +/// as singletons, may be invoked concurrently, and run synchronously on the hot path. +/// +public interface IEntityLoggingScopeEnricher + where TEntity : IKubernetesObject +{ + /// Adds properties to the logging scope being built for . + /// The concrete entity the scope is being created for. + /// The pipeline stage in which the scope is being created. + /// The properties contributed by this enricher. + void Enrich(TEntity entity, EntityLoggingPhase phase, IDictionary properties); +} diff --git a/src/KubeOps.Operator/Builder/OperatorBuilder.cs b/src/KubeOps.Operator/Builder/OperatorBuilder.cs index bd81d609d..fe173327a 100644 --- a/src/KubeOps.Operator/Builder/OperatorBuilder.cs +++ b/src/KubeOps.Operator/Builder/OperatorBuilder.cs @@ -343,6 +343,11 @@ private void AddOperatorBase() Services.AddSingleton(typeof(IEntityLabelSelector<>), typeof(DefaultEntityLabelSelector<>)); Services.AddSingleton(typeof(IEntityFieldSelector<>), typeof(DefaultEntityFieldSelector<>)); + // The factory is the public scope-creation boundary. It delegates enrichment to a no-op pipeline + // when no IEntityLoggingScopeEnricher is registered. + Services.TryAddSingleton(typeof(EntityLoggingScopeEnricherPipeline<>)); + Services.TryAddSingleton(typeof(IEntityLoggingScopeFactory<>), typeof(EntityLoggingScopeFactory<>)); + if (Settings.LeaderElectionType == LeaderElectionType.Single) { Services.AddLeaderElection(); diff --git a/src/KubeOps.Operator/Logging/EntityLoggingScope.cs b/src/KubeOps.Operator/Logging/EntityLoggingScope.cs index c82169ed0..8f767a4fa 100644 --- a/src/KubeOps.Operator/Logging/EntityLoggingScope.cs +++ b/src/KubeOps.Operator/Logging/EntityLoggingScope.cs @@ -7,6 +7,7 @@ using k8s; using k8s.Models; +using KubeOps.Abstractions.Logging; using KubeOps.Abstractions.Reconciliation; namespace KubeOps.Operator.Logging; @@ -31,47 +32,30 @@ private EntityLoggingScope(IReadOnlyDictionary state) private IReadOnlyDictionary Values { get; } /// - /// Creates a new instance of for the provided Kubernetes entity and event type. + /// Creates an unenriched logging scope for the provided Kubernetes watch event. /// - /// - /// The type of the Kubernetes entity. Must implement . - /// - /// - /// The type of the watch event for the entity (e.g., Added, Modified, Deleted, or Bookmark). - /// - /// - /// The Kubernetes entity associated with the logging scope. This includes metadata such as Kind, Namespace, Name, UID, and ResourceVersion. - /// - /// - /// A new instance containing contextual key-value pairs - /// related to the event type and the provided Kubernetes entity. - /// + /// The Kubernetes entity type. + /// The watch event type. + /// The entity associated with the event. + /// A logging scope containing the built-in identification fields. public static EntityLoggingScope CreateFor(WatchEventType eventType, TEntity entity) where TEntity : IKubernetesObject - => CreateLoggingScope(eventType.ToString(), ReconciliationTriggerSource.ApiServer, entity); + => CreateUnenriched(eventType.ToString(), ReconciliationTriggerSource.ApiServer, entity); /// - /// Creates a new instance of for the given Kubernetes entity and reconciliation operation type. + /// Creates an unenriched logging scope for the provided reconciliation. /// - /// - /// The type of the Kubernetes entity. Must implement . - /// - /// - /// The type of reconciliation operation for the entity (e.g., Added, Modified, or Deleted). - /// - /// - /// The source of the reconciliation trigger (e.g., ApiServer, Operator). This provides additional context for the logging scope. - /// - /// - /// The Kubernetes entity associated with the logging scope. This includes metadata such as Kind, Namespace, Name, UID, and ResourceVersion. - /// - /// - /// A new instance containing contextual key-value pairs - /// related to the reconciliation operation type and the provided Kubernetes entity. - /// - public static EntityLoggingScope CreateFor(ReconciliationType eventType, ReconciliationTriggerSource reconciliationTriggerSource, TEntity entity) + /// The Kubernetes entity type. + /// The reconciliation operation type. + /// The source that triggered the reconciliation. + /// The entity associated with the reconciliation. + /// A logging scope containing the built-in identification fields. + public static EntityLoggingScope CreateFor( + ReconciliationType eventType, + ReconciliationTriggerSource reconciliationTriggerSource, + TEntity entity) where TEntity : IKubernetesObject - => CreateLoggingScope(eventType.ToString(), reconciliationTriggerSource, entity); + => CreateUnenriched(eventType.ToString(), reconciliationTriggerSource, entity); /// public IEnumerator> GetEnumerator() @@ -85,17 +69,46 @@ public override string ToString() IEnumerator IEnumerable.GetEnumerator() => GetEnumerator(); - private static EntityLoggingScope CreateLoggingScope(string eventType, ReconciliationTriggerSource triggerSource, TEntity entity) + internal static EntityLoggingScope Create( + string eventType, + ReconciliationTriggerSource triggerSource, + TEntity entity, + EntityLoggingPhase phase, + EntityLoggingScopeEnricherPipeline enrichers) where TEntity : IKubernetesObject - => new( - new Dictionary(7) - { - { "EventType", eventType }, - { "ReconciliationTriggerSource", triggerSource }, - { nameof(entity.Kind), entity.Kind }, - { "Namespace", entity.Namespace() }, - { "Name", entity.Name() }, - { "Uid", entity.Uid() }, - { "ResourceVersion", entity.ResourceVersion() }, - }); + { + var items = new Dictionary(7); + SetBuiltInProperties(items, eventType, triggerSource, entity); + + enrichers.Enrich(entity, phase, items); + + return new(items); + } + + private static EntityLoggingScope CreateUnenriched( + string eventType, + ReconciliationTriggerSource triggerSource, + TEntity entity) + where TEntity : IKubernetesObject + { + var items = new Dictionary(7); + SetBuiltInProperties(items, eventType, triggerSource, entity); + return new(items); + } + + private static void SetBuiltInProperties( + IDictionary items, + string eventType, + ReconciliationTriggerSource triggerSource, + TEntity entity) + where TEntity : IKubernetesObject + { + items["EventType"] = eventType; + items["ReconciliationTriggerSource"] = triggerSource; + items[nameof(entity.Kind)] = entity.Kind; + items["Namespace"] = entity.Namespace(); + items["Name"] = entity.Name(); + items["Uid"] = entity.Uid(); + items["ResourceVersion"] = entity.ResourceVersion(); + } } diff --git a/src/KubeOps.Operator/Logging/EntityLoggingScopeEnricherPipeline.cs b/src/KubeOps.Operator/Logging/EntityLoggingScopeEnricherPipeline.cs new file mode 100644 index 000000000..ef7f60e89 --- /dev/null +++ b/src/KubeOps.Operator/Logging/EntityLoggingScopeEnricherPipeline.cs @@ -0,0 +1,61 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information. + +using k8s; +using k8s.Models; + +using KubeOps.Abstractions.Logging; + +using Microsoft.Extensions.Logging; + +namespace KubeOps.Operator.Logging; + +/// +/// Applies registered enrichers in order (so the first enricher that contributes a key wins) and isolates +/// individual failures so logging-scope enrichment cannot take down a watch or reconciliation. +/// +/// The entity type this pipeline enriches scopes for. +internal sealed partial class EntityLoggingScopeEnricherPipeline( + IEnumerable> entityEnrichers, + ILogger> logger) + where TEntity : IKubernetesObject +{ + private readonly IEntityLoggingScopeEnricher[] _entityEnrichers = entityEnrichers.ToArray(); + + public void Enrich(TEntity entity, EntityLoggingPhase phase, IDictionary items) + { + if (_entityEnrichers.Length == 0) + { + return; + } + + var pendingItems = new Dictionary(); + + foreach (var enricher in _entityEnrichers) + { + try + { + enricher.Enrich(entity, phase, pendingItems); + foreach (var item in pendingItems) + { + items.TryAdd(item.Key, item.Value); + } + } + catch (Exception exception) + { + LogEnricherFailed(exception, enricher.GetType().FullName ?? enricher.GetType().Name); + } + finally + { + pendingItems.Clear(); + } + } + } + + [LoggerMessage( + EventId = 0, + Level = LogLevel.Warning, + Message = "Entity logging scope enricher '{Enricher}' threw and was skipped.")] + private partial void LogEnricherFailed(Exception exception, string enricher); +} diff --git a/src/KubeOps.Operator/Logging/EntityLoggingScopeFactory.cs b/src/KubeOps.Operator/Logging/EntityLoggingScopeFactory.cs new file mode 100644 index 000000000..e053c9d55 --- /dev/null +++ b/src/KubeOps.Operator/Logging/EntityLoggingScopeFactory.cs @@ -0,0 +1,36 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information. + +using k8s; +using k8s.Models; + +using KubeOps.Abstractions.Logging; +using KubeOps.Abstractions.Reconciliation; + +namespace KubeOps.Operator.Logging; + +internal sealed class EntityLoggingScopeFactory( + EntityLoggingScopeEnricherPipeline enrichers) + : IEntityLoggingScopeFactory + where TEntity : IKubernetesObject +{ + public EntityLoggingScope CreateFor(WatchEventType eventType, TEntity entity) + => EntityLoggingScope.Create( + eventType.ToString(), + ReconciliationTriggerSource.ApiServer, + entity, + EntityLoggingPhase.Watch, + enrichers); + + public EntityLoggingScope CreateFor( + ReconciliationType eventType, + ReconciliationTriggerSource reconciliationTriggerSource, + TEntity entity) + => EntityLoggingScope.Create( + eventType.ToString(), + reconciliationTriggerSource, + entity, + EntityLoggingPhase.Reconcile, + enrichers); +} diff --git a/src/KubeOps.Operator/Logging/IEntityLoggingScopeFactory.cs b/src/KubeOps.Operator/Logging/IEntityLoggingScopeFactory.cs new file mode 100644 index 000000000..bbf56ee5b --- /dev/null +++ b/src/KubeOps.Operator/Logging/IEntityLoggingScopeFactory.cs @@ -0,0 +1,35 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information. + +using k8s; +using k8s.Models; + +using KubeOps.Abstractions.Reconciliation; + +namespace KubeOps.Operator.Logging; + +/// +/// Creates consistently enriched logging scopes for watch events and reconciliations of +/// . +/// +/// The Kubernetes entity type the factory creates scopes for. +public interface IEntityLoggingScopeFactory + where TEntity : IKubernetesObject +{ + /// Creates a logging scope for a Kubernetes watch event. + /// The watch event type. + /// The entity associated with the event. + /// The enriched logging scope. + EntityLoggingScope CreateFor(WatchEventType eventType, TEntity entity); + + /// Creates a logging scope for a reconciliation. + /// The reconciliation operation type. + /// The source that triggered the reconciliation. + /// The entity being reconciled. + /// The enriched logging scope. + EntityLoggingScope CreateFor( + ReconciliationType eventType, + ReconciliationTriggerSource reconciliationTriggerSource, + TEntity entity); +} diff --git a/src/KubeOps.Operator/Queue/EntityQueueBackgroundService{TEntity}.cs b/src/KubeOps.Operator/Queue/EntityQueueBackgroundService{TEntity}.cs index 3b40bccfa..f6dadd05e 100644 --- a/src/KubeOps.Operator/Queue/EntityQueueBackgroundService{TEntity}.cs +++ b/src/KubeOps.Operator/Queue/EntityQueueBackgroundService{TEntity}.cs @@ -66,6 +66,7 @@ public class EntityQueueBackgroundService( IReconciler reconciler, IEntityReconcileCoordinator coordinator, ILogger> logger, + IEntityLoggingScopeFactory scopeFactory, OperatorMetrics? metrics = null) : RestartableHostedService, IEntityQueueConsumer where TEntity : IKubernetesObject { @@ -216,7 +217,11 @@ private async Task ProcessEntryWithSemaphoreReleaseAsync(QueueEntry ent private async Task ProcessEntryAsync(QueueEntry entry, CancellationToken cancellationToken) { using var activity = activitySource.StartActivity($"""Processing queued "{entry.ReconciliationType}" event for "{entry.Entity.ToIdentifierString()}".""", ActivityKind.Consumer); - using var scope = logger.BeginScope(EntityLoggingScope.CreateFor(entry.ReconciliationType, entry.ReconciliationTriggerSource, entry.Entity)); + using var scope = logger.BeginScope( + scopeFactory.CreateFor( + entry.ReconciliationType, + entry.ReconciliationTriggerSource, + entry.Entity)); try { diff --git a/src/KubeOps.Operator/Queue/LeaderAwareEntityQueueBackgroundService{TEntity}.cs b/src/KubeOps.Operator/Queue/LeaderAwareEntityQueueBackgroundService{TEntity}.cs index 8e2e3ee24..5b31d3c53 100644 --- a/src/KubeOps.Operator/Queue/LeaderAwareEntityQueueBackgroundService{TEntity}.cs +++ b/src/KubeOps.Operator/Queue/LeaderAwareEntityQueueBackgroundService{TEntity}.cs @@ -12,6 +12,7 @@ using KubeOps.Abstractions.Reconciliation; using KubeOps.KubernetesClient; using KubeOps.Operator.LeaderElection; +using KubeOps.Operator.Logging; using KubeOps.Operator.Metrics; using Microsoft.Extensions.Logging; @@ -55,6 +56,7 @@ public class LeaderAwareEntityQueueBackgroundService( IEntityReconcileCoordinator coordinator, ILogger> logger, LeaderElector elector, + IEntityLoggingScopeFactory scopeFactory, OperatorMetrics? metrics = null) : EntityQueueBackgroundService( activitySource, @@ -64,6 +66,7 @@ public class LeaderAwareEntityQueueBackgroundService( reconciler, coordinator, logger, + scopeFactory, metrics), ILeaderAwareEntityQueueConsumer where TEntity : IKubernetesObject { diff --git a/src/KubeOps.Operator/Queue/ScopeAwareEntityQueueBackgroundService{TEntity}.cs b/src/KubeOps.Operator/Queue/ScopeAwareEntityQueueBackgroundService{TEntity}.cs index 0804565e6..77edbcb61 100644 --- a/src/KubeOps.Operator/Queue/ScopeAwareEntityQueueBackgroundService{TEntity}.cs +++ b/src/KubeOps.Operator/Queue/ScopeAwareEntityQueueBackgroundService{TEntity}.cs @@ -11,6 +11,7 @@ using KubeOps.Abstractions.LeaderElection; using KubeOps.Abstractions.Reconciliation; using KubeOps.KubernetesClient; +using KubeOps.Operator.Logging; using KubeOps.Operator.Metrics; using Microsoft.Extensions.Logging; @@ -32,6 +33,7 @@ public class ScopeAwareEntityQueueBackgroundService( IEntityReconcileCoordinator coordinator, ILogger> logger, ILeadershipScope leadershipScope, + IEntityLoggingScopeFactory scopeFactory, OperatorMetrics? metrics = null) : EntityQueueBackgroundService( activitySource, @@ -41,6 +43,7 @@ public class ScopeAwareEntityQueueBackgroundService( reconciler, coordinator, logger, + scopeFactory, metrics) where TEntity : IKubernetesObject { diff --git a/src/KubeOps.Operator/Watcher/LeaderAwareResourceWatcher{TEntity}.cs b/src/KubeOps.Operator/Watcher/LeaderAwareResourceWatcher{TEntity}.cs index 098b37e03..3046eb6a8 100644 --- a/src/KubeOps.Operator/Watcher/LeaderAwareResourceWatcher{TEntity}.cs +++ b/src/KubeOps.Operator/Watcher/LeaderAwareResourceWatcher{TEntity}.cs @@ -12,6 +12,7 @@ using KubeOps.Abstractions.Entities; using KubeOps.KubernetesClient; using KubeOps.Operator.LeaderElection; +using KubeOps.Operator.Logging; using KubeOps.Operator.Metrics; using KubeOps.Operator.Queue; @@ -31,6 +32,7 @@ public class LeaderAwareResourceWatcher( IEntityFieldSelector fieldSelector, IKubernetesClient client, LeaderElector elector, + IEntityLoggingScopeFactory scopeFactory, string cachePartition = "", OperatorMetrics? metrics = null) : ResourceWatcher( @@ -42,6 +44,7 @@ public class LeaderAwareResourceWatcher( labelSelector, fieldSelector, client, + scopeFactory, cachePartition, metrics) where TEntity : IKubernetesObject diff --git a/src/KubeOps.Operator/Watcher/LeaderAwareSharedResourceWatcher{TEntity}.cs b/src/KubeOps.Operator/Watcher/LeaderAwareSharedResourceWatcher{TEntity}.cs index f319e5a07..9fbcb6118 100644 --- a/src/KubeOps.Operator/Watcher/LeaderAwareSharedResourceWatcher{TEntity}.cs +++ b/src/KubeOps.Operator/Watcher/LeaderAwareSharedResourceWatcher{TEntity}.cs @@ -11,6 +11,7 @@ using KubeOps.Abstractions.Builder; using KubeOps.Abstractions.Entities; using KubeOps.KubernetesClient; +using KubeOps.Operator.Logging; using KubeOps.Operator.Metrics; using KubeOps.Operator.Queue; @@ -36,6 +37,7 @@ internal sealed class LeaderAwareSharedResourceWatcher( IKubernetesClient client, LeaderElector elector, SharedPipelineDispatcher dispatcher, + IEntityLoggingScopeFactory scopeFactory, OperatorMetrics? metrics = null) : LeaderAwareResourceWatcher( activitySource, @@ -47,6 +49,7 @@ internal sealed class LeaderAwareSharedResourceWatcher( fieldSelector, client, elector, + scopeFactory, cachePartition: string.Empty, metrics) where TEntity : IKubernetesObject diff --git a/src/KubeOps.Operator/Watcher/ResourceWatcher{TEntity}.cs b/src/KubeOps.Operator/Watcher/ResourceWatcher{TEntity}.cs index 9ed8690f9..0d3f21838 100644 --- a/src/KubeOps.Operator/Watcher/ResourceWatcher{TEntity}.cs +++ b/src/KubeOps.Operator/Watcher/ResourceWatcher{TEntity}.cs @@ -36,6 +36,7 @@ public class ResourceWatcher( IEntityLabelSelector labelSelector, IEntityFieldSelector fieldSelector, IKubernetesClient client, + IEntityLoggingScopeFactory scopeFactory, string cachePartition = "", OperatorMetrics? metrics = null) : RestartableHostedService, ISharedWatchDedup @@ -181,7 +182,7 @@ protected override async Task ExecuteAsync(CancellationToken cancellationToken) cancellationToken: cancellationToken)) { using var activity = activitySource.StartActivity($"""processing "{type}" event""", ActivityKind.Consumer); - using var scope = logger.BeginScope(EntityLoggingScope.CreateFor(type, entity)); + using var scope = logger.BeginScope(scopeFactory.CreateFor(type, entity)); metrics?.RecordWatchEvent(typeof(TEntity).Name, type.ToMetricString()); diff --git a/src/KubeOps.Operator/Watcher/ScopeAwareResourceWatcher{TEntity}.cs b/src/KubeOps.Operator/Watcher/ScopeAwareResourceWatcher{TEntity}.cs index 131bc39f2..e3ba74791 100644 --- a/src/KubeOps.Operator/Watcher/ScopeAwareResourceWatcher{TEntity}.cs +++ b/src/KubeOps.Operator/Watcher/ScopeAwareResourceWatcher{TEntity}.cs @@ -37,6 +37,7 @@ public class ScopeAwareResourceWatcher( IEntityFieldSelector fieldSelector, IKubernetesClient client, ILeadershipScope leadershipScope, + IEntityLoggingScopeFactory scopeFactory, string cachePartition = "", OperatorMetrics? metrics = null) : ResourceWatcher( @@ -48,6 +49,7 @@ public class ScopeAwareResourceWatcher( labelSelector, fieldSelector, client, + scopeFactory, cachePartition, metrics) where TEntity : IKubernetesObject diff --git a/src/KubeOps.Operator/Watcher/ScopeAwareSharedResourceWatcher{TEntity}.cs b/src/KubeOps.Operator/Watcher/ScopeAwareSharedResourceWatcher{TEntity}.cs index 3156dad15..f13ca42bb 100644 --- a/src/KubeOps.Operator/Watcher/ScopeAwareSharedResourceWatcher{TEntity}.cs +++ b/src/KubeOps.Operator/Watcher/ScopeAwareSharedResourceWatcher{TEntity}.cs @@ -11,6 +11,7 @@ using KubeOps.Abstractions.Entities; using KubeOps.Abstractions.LeaderElection; using KubeOps.KubernetesClient; +using KubeOps.Operator.Logging; using KubeOps.Operator.Metrics; using KubeOps.Operator.Queue; @@ -37,6 +38,7 @@ internal sealed class ScopeAwareSharedResourceWatcher( IKubernetesClient client, ILeadershipScope leadershipScope, SharedPipelineDispatcher dispatcher, + IEntityLoggingScopeFactory scopeFactory, OperatorMetrics? metrics = null) : ScopeAwareResourceWatcher( activitySource, @@ -48,6 +50,7 @@ internal sealed class ScopeAwareSharedResourceWatcher( fieldSelector, client, leadershipScope, + scopeFactory, cachePartition: string.Empty, metrics) where TEntity : IKubernetesObject diff --git a/src/KubeOps.Operator/Watcher/SharedResourceWatcher{TEntity}.cs b/src/KubeOps.Operator/Watcher/SharedResourceWatcher{TEntity}.cs index 653469b55..88fb7bcf1 100644 --- a/src/KubeOps.Operator/Watcher/SharedResourceWatcher{TEntity}.cs +++ b/src/KubeOps.Operator/Watcher/SharedResourceWatcher{TEntity}.cs @@ -10,6 +10,7 @@ using KubeOps.Abstractions.Builder; using KubeOps.Abstractions.Entities; using KubeOps.KubernetesClient; +using KubeOps.Operator.Logging; using KubeOps.Operator.Metrics; using KubeOps.Operator.Queue; @@ -39,6 +40,7 @@ internal sealed class SharedResourceWatcher( IEntityFieldSelector fieldSelector, IKubernetesClient client, SharedPipelineDispatcher dispatcher, + IEntityLoggingScopeFactory scopeFactory, OperatorMetrics? metrics = null) : ResourceWatcher( activitySource, @@ -49,6 +51,7 @@ internal sealed class SharedResourceWatcher( labelSelector, fieldSelector, client, + scopeFactory, cachePartition: string.Empty, metrics) where TEntity : IKubernetesObject diff --git a/test/KubeOps.Operator.Test/Builder/OperatorBuilderRegistrationValidation.Test.cs b/test/KubeOps.Operator.Test/Builder/OperatorBuilderRegistrationValidation.Test.cs index 53abe1a92..ca12361ee 100644 --- a/test/KubeOps.Operator.Test/Builder/OperatorBuilderRegistrationValidation.Test.cs +++ b/test/KubeOps.Operator.Test/Builder/OperatorBuilderRegistrationValidation.Test.cs @@ -607,15 +607,15 @@ public Task> FinalizeAsync // Test doubles for a user-provided Custom watcher / queue consumer. Validation inspects the service // descriptors only (it never constructs these), so the null base arguments are never dereferenced. private sealed class CustomWatcher() : ResourceWatcher( - null!, null!, null!, null!, null!, null!, null!, null!); + null!, null!, null!, null!, null!, null!, null!, null!, null!); private sealed class CustomConsumer() : EntityQueueBackgroundService( - null!, null!, null!, null!, null!, null!, null!); + null!, null!, null!, null!, null!, null!, null!, null!); // A leadership-aware consumer (implements ILeaderAwareEntityQueueConsumer via the base class). private sealed class CustomLeaderAwareConsumer() : LeaderAwareEntityQueueBackgroundService( - null!, null!, null!, null!, null!, null!, null!, null!); + null!, null!, null!, null!, null!, null!, null!, null!, null!); // A custom queue that does NOT implement ISuspendableEntityQueue. Validation inspects the registration // descriptor only and never constructs it, so the members can throw. diff --git a/test/KubeOps.Operator.Test/Logging/EntityLoggingScopeEnricher.Test.cs b/test/KubeOps.Operator.Test/Logging/EntityLoggingScopeEnricher.Test.cs new file mode 100644 index 000000000..9d44897fc --- /dev/null +++ b/test/KubeOps.Operator.Test/Logging/EntityLoggingScopeEnricher.Test.cs @@ -0,0 +1,482 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the Apache 2.0 License. +// See the LICENSE file in the project root for more information. + +using System.Diagnostics; +using System.Runtime.CompilerServices; + +using FluentAssertions; + +using k8s; +using k8s.Models; + +using KubeOps.Abstractions.Builder; +using KubeOps.Abstractions.Entities; +using KubeOps.Abstractions.Logging; +using KubeOps.Abstractions.Reconciliation; +using KubeOps.KubernetesClient; +using KubeOps.Operator.Builder; +using KubeOps.Operator.Logging; +using KubeOps.Operator.Queue; +using KubeOps.Operator.Test.TestEntities; +using KubeOps.Operator.Watcher; + +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; + +using Moq; + +using ZiggyCreatures.Caching.Fusion; + +namespace KubeOps.Operator.Test.Logging; + +[Trait("Area", "Logging")] +public sealed class EntityLoggingScopeEnricherTest +{ + private static V1OperatorIntegrationTestEntity Entity => new("name", "username", "ns"); + + [Fact] + public void Pipeline_Applies_Registered_Enrichers() + { + var pipeline = Pipeline([ + new SetTypedEnricher("first", _ => "value"), + new SetTypedEnricher("second", e => e.Metadata.Name), + ]); + + var items = FreshItems(); + pipeline.Enrich(Entity, EntityLoggingPhase.Reconcile, items); + + items["first"].Should().Be("value"); + items["second"].Should().Be("name"); + } + + [Fact] + public void Pipeline_Uses_First_Writer_Wins() + { + var pipeline = Pipeline([ + new SetTypedEnricher("shared", _ => "first"), + new SetTypedEnricher("shared", _ => "second"), + ]); + + var items = FreshItems(); + pipeline.Enrich(Entity, EntityLoggingPhase.Reconcile, items); + + items["shared"].Should().Be("first"); + } + + [Fact] + public void Enricher_Cannot_Override_Builtin_Key() + { + var pipeline = Pipeline([new SetTypedEnricher("Name", _ => "overridden")]); + + var scope = Factory(pipeline).CreateFor(WatchEventType.Modified, Entity); + var items = scope.ToDictionary(kvp => kvp.Key, kvp => kvp.Value); + + items["Name"].Should().Be("name"); + items.Should().ContainKeys("EventType", "Kind", "Namespace", "Uid", "ResourceVersion"); + } + + [Theory] + [InlineData(EntityLoggingPhase.Watch)] + [InlineData(EntityLoggingPhase.Reconcile)] + public void Pipeline_Passes_The_Current_Phase_To_Enrichers(EntityLoggingPhase phase) + { + EntityLoggingPhase? observed = null; + var pipeline = Pipeline([ + new DelegatingTypedEnricher((_, currentPhase, _) => + observed = currentPhase), + ]); + + pipeline.Enrich(Entity, phase, FreshItems()); + + observed.Should().Be(phase); + } + + [Fact] + public void A_Throwing_Enricher_Is_Isolated_And_Following_Enrichers_Still_Run() + { + var pipeline = Pipeline([ + new ThrowingAfterAddEnricher(), + new SetTypedEnricher("after", _ => "ran"), + ]); + + var items = FreshItems(); + var act = () => pipeline.Enrich(Entity, EntityLoggingPhase.Reconcile, items); + + act.Should().NotThrow(); + items.Should().NotContainKey("partial"); + items["after"].Should().Be("ran"); + } + + [Fact] + public void CreateFor_Enriches_The_Watch_Scope() + { + var pipeline = Pipeline([new SetTypedEnricher("custom", _ => "value")]); + + var scope = Factory(pipeline).CreateFor(WatchEventType.Added, Entity); + + scope.ToDictionary(kvp => kvp.Key, kvp => kvp.Value)["custom"].Should().Be("value"); + } + + [Fact] + public void CreateFor_With_Empty_Pipeline_Preserves_The_Unenriched_Scope() + { + var expected = EntityLoggingScope.CreateFor( + ReconciliationType.Modified, + ReconciliationTriggerSource.ApiServer, + Entity).ToDictionary(); + var scope = Factory(Pipeline([])).CreateFor( + ReconciliationType.Modified, + ReconciliationTriggerSource.ApiServer, + Entity).ToDictionary(); + + scope.Should().Equal(expected); + } + + [Fact] + public async Task ResourceWatcher_Forwards_The_Pipeline_To_The_Watch_Scope() + { + var entity = Entity; + var pipeline = Pipeline([new SetTypedEnricher("watch-custom", _ => "value")]); + var logger = new CapturingLogger>(); + var client = new Mock(); + client + .Setup(c => c.WatchAsync( + "unit-test", + null, + null, + null, + true, + It.IsAny())) + .Returns( + (_, _, _, _, _, cancellationToken) => WatchOnce(entity, cancellationToken)); + + var cacheProvider = new Mock(); + cacheProvider.Setup(c => c.GetCache(It.IsAny())).Returns(Mock.Of()); + + await using var watcher = new ResourceWatcher( + new ActivitySource("test"), + logger, + cacheProvider.Object, + Mock.Of>(), + new OperatorSettingsBuilder { Namespace = "unit-test" }.Build(), + new DefaultEntityLabelSelector(), + new DefaultEntityFieldSelector(), + client.Object, + scopeFactory: Factory(pipeline)); + + await watcher.StartAsync(TestContext.Current.CancellationToken); + var scope = await logger.ScopeCaptured.Task.WaitAsync( + TimeSpan.FromSeconds(5), TestContext.Current.CancellationToken); + await watcher.StopAsync(TestContext.Current.CancellationToken); + + scope["watch-custom"].Should().Be("value"); + } + + [Fact] + public async Task EntityQueueBackgroundService_Enriches_The_Reconcile_Scope_With_The_Queued_Snapshot() + { + var queuedEntity = new V1ConfigMap + { + Kind = V1ConfigMap.KubeKind, + Metadata = new() + { + Name = "name", + NamespaceProperty = "ns", + Uid = Guid.NewGuid().ToString(), + ResourceVersion = "1", + }, + }; + var currentEntity = new V1ConfigMap + { + Kind = V1ConfigMap.KubeKind, + Metadata = new() + { + Name = "name", + NamespaceProperty = "ns", + Uid = queuedEntity.Metadata.Uid, + ResourceVersion = "2", + }, + }; + var enrichmentCount = 0; + var pipeline = new EntityLoggingScopeEnricherPipeline( + [new DelegatingTypedEnricher((entity, _, properties) => + { + enrichmentCount++; + properties.TryAdd("reconcile-custom", entity.ResourceVersion()); + })], + NullLogger>.Instance); + var client = new Mock(); + client + .Setup(c => c.GetAsync("name", "ns", It.IsAny())) + .ReturnsAsync(currentEntity); + var reconciler = new Mock>(); + reconciler + .Setup(r => r.Reconcile(It.IsAny>(), It.IsAny())) + .ReturnsAsync(ReconciliationResult.Success(currentEntity)); + + var logger = new ScopeRecordingLogger>(); + var settings = new OperatorSettingsBuilder().Build(); + await using var service = new EntityQueueBackgroundService( + new ActivitySource("test"), + client.Object, + settings, + new SingleEntryQueue( + new(queuedEntity, ReconciliationType.Modified, ReconciliationTriggerSource.ApiServer, RetryCount: 0)), + reconciler.Object, + new EntityReconcileCoordinator(settings), + logger, + scopeFactory: new EntityLoggingScopeFactory(pipeline)); + + await service.StartAsync(TestContext.Current.CancellationToken); + var scope = await logger.StartingReconciliationScope.Task.WaitAsync( + TimeSpan.FromSeconds(5), TestContext.Current.CancellationToken); + await service.StopAsync(TestContext.Current.CancellationToken); + + scope["ResourceVersion"].Should().Be("1"); + scope["reconcile-custom"].Should().Be("1"); + enrichmentCount.Should().Be(1); + reconciler.Verify( + r => r.Reconcile( + It.Is>(c => ReferenceEquals(c.Entity, currentEntity)), + It.IsAny()), + Times.Once); + } + + [Fact] + public async Task EntityQueueBackgroundService_Keeps_NotFound_Skip_Log_In_The_Snapshot_Scope() + { + var queuedEntity = new V1ConfigMap + { + Kind = V1ConfigMap.KubeKind, + Metadata = new() + { + Name = "name", + NamespaceProperty = "ns", + Uid = Guid.NewGuid().ToString(), + ResourceVersion = "1", + }, + }; + var pipeline = new EntityLoggingScopeEnricherPipeline( + [new DelegatingTypedEnricher((entity, _, properties) => + properties.TryAdd("reconcile-custom", entity.ResourceVersion()))], + NullLogger>.Instance); + var client = new Mock(); + client + .Setup(c => c.GetAsync("name", "ns", It.IsAny())) + .ReturnsAsync((V1ConfigMap?)null); + var logger = new ScopeRecordingLogger>(); + var settings = new OperatorSettingsBuilder().Build(); + await using var service = new EntityQueueBackgroundService( + new ActivitySource("test"), + client.Object, + settings, + new SingleEntryQueue( + new(queuedEntity, ReconciliationType.Modified, ReconciliationTriggerSource.ApiServer, RetryCount: 0)), + Mock.Of>(), + new EntityReconcileCoordinator(settings), + logger, + scopeFactory: new EntityLoggingScopeFactory(pipeline)); + + await service.StartAsync(TestContext.Current.CancellationToken); + var scope = await logger.NotFoundScope.Task.WaitAsync( + TimeSpan.FromSeconds(5), TestContext.Current.CancellationToken); + await service.StopAsync(TestContext.Current.CancellationToken); + + scope["ResourceVersion"].Should().Be("1"); + scope["reconcile-custom"].Should().Be("1"); + } + + [Fact] + public void Builder_Registers_A_Factory_That_Composes_The_Configured_Enrichers() + { + var services = new ServiceCollection(); + services.AddLogging(); + var builder = new OperatorBuilder(services, new OperatorSettingsBuilder().WithName("test").Build()); + + builder.AddEntityLoggingScopeEnricher(); + + using var provider = services.BuildServiceProvider(); + var factory = provider.GetRequiredService>(); + var items = factory + .CreateFor(ReconciliationType.Modified, ReconciliationTriggerSource.ApiServer, Entity) + .ToDictionary(); + + items.Should().ContainKey("registered-typed"); + } + + private static Dictionary FreshItems() => new(); + + private static async IAsyncEnumerable<(WatchEventType Type, V1OperatorIntegrationTestEntity Entity)> WatchOnce( + V1OperatorIntegrationTestEntity entity, + [EnumeratorCancellation] CancellationToken cancellationToken) + { + yield return (WatchEventType.Modified, entity); + await Task.Delay(Timeout.InfiniteTimeSpan, cancellationToken); + } + + private static EntityLoggingScopeEnricherPipeline Pipeline( + IEnumerable> enrichers) + => new(enrichers, NullLogger>.Instance); + + private static EntityLoggingScopeFactory Factory( + EntityLoggingScopeEnricherPipeline pipeline) + => new(pipeline); + + private sealed class ThrowingAfterAddEnricher + : IEntityLoggingScopeEnricher + { + public void Enrich( + V1OperatorIntegrationTestEntity entity, + EntityLoggingPhase phase, + IDictionary properties) + { + properties.TryAdd("partial", "discarded"); + throw new InvalidOperationException("boom"); + } + } + + private sealed class SetTypedEnricher(string key, Func value) + : IEntityLoggingScopeEnricher + { + public void Enrich( + V1OperatorIntegrationTestEntity entity, + EntityLoggingPhase phase, + IDictionary properties) => + properties.TryAdd(key, value(entity)); + } + + private sealed class DelegatingTypedEnricher( + Action> action) + : IEntityLoggingScopeEnricher + where TEntity : IKubernetesObject + { + public void Enrich( + TEntity entity, + EntityLoggingPhase phase, + IDictionary properties) => + action(entity, phase, properties); + } + + private sealed class TypedRegisteredEnricher : IEntityLoggingScopeEnricher + { + public void Enrich( + V1OperatorIntegrationTestEntity entity, + EntityLoggingPhase phase, + IDictionary properties) => + properties.TryAdd("registered-typed", true); + } + + private sealed class CapturingLogger : ILogger + { + public TaskCompletionSource> ScopeCaptured { get; } = + new(TaskCreationOptions.RunContinuationsAsynchronously); + + public IDisposable BeginScope(TState state) + where TState : notnull + { + if (state is IEnumerable> values) + { + ScopeCaptured.TrySetResult(values.ToDictionary()); + } + + return EmptyDisposable.Instance; + } + + public bool IsEnabled(LogLevel logLevel) => false; + + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + { + } + } + + private sealed class ScopeRecordingLogger : ILogger + { + private readonly AsyncLocal?> _currentScope = new(); + + public TaskCompletionSource> StartingReconciliationScope { get; } = + new(TaskCreationOptions.RunContinuationsAsynchronously); + + public TaskCompletionSource> NotFoundScope { get; } = + new(TaskCreationOptions.RunContinuationsAsynchronously); + + public IDisposable BeginScope(TState state) + where TState : notnull + { + var previousScope = _currentScope.Value; + _currentScope.Value = state is IEnumerable> values + ? values.ToDictionary() + : null; + return new ScopeRestorer(() => _currentScope.Value = previousScope); + } + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + { + if (_currentScope.Value is not { } scope) + { + return; + } + + var message = formatter(state, exception); + if (message.StartsWith("Starting reconciliation", StringComparison.Ordinal)) + { + StartingReconciliationScope.TrySetResult(scope); + } + + if (message.Contains("was not found", StringComparison.Ordinal)) + { + NotFoundScope.TrySetResult(scope); + } + } + } + + private sealed class ScopeRestorer(Action restore) : IDisposable + { + public void Dispose() => restore(); + } + + private sealed class SingleEntryQueue(QueueEntry entry) : ITimedEntityQueue + where TEntity : IKubernetesObject + { + public Task Enqueue( + TEntity entity, + ReconciliationType type, + ReconciliationTriggerSource reconciliationTriggerSource, + TimeSpan queueIn, + int retryCount, + CancellationToken cancellationToken) => Task.FromResult(true); + + public async IAsyncEnumerator> GetAsyncEnumerator( + CancellationToken cancellationToken = default) + { + yield return entry; + await Task.Delay(Timeout.InfiniteTimeSpan, cancellationToken); + } + + public void Dispose() + { + } + } + + private sealed class EmptyDisposable : IDisposable + { + public static EmptyDisposable Instance { get; } = new(); + + public void Dispose() + { + } + } +} diff --git a/test/KubeOps.Operator.Test/Queue/EntityQueueBackgroundService.Test.cs b/test/KubeOps.Operator.Test/Queue/EntityQueueBackgroundService.Test.cs index ec9f4b21b..c00905a57 100644 --- a/test/KubeOps.Operator.Test/Queue/EntityQueueBackgroundService.Test.cs +++ b/test/KubeOps.Operator.Test/Queue/EntityQueueBackgroundService.Test.cs @@ -11,6 +11,7 @@ using KubeOps.Abstractions.Builder; using KubeOps.Abstractions.Reconciliation; using KubeOps.KubernetesClient; +using KubeOps.Operator.Logging; using KubeOps.Operator.Metrics; using KubeOps.Operator.Queue; @@ -163,6 +164,7 @@ private static EntityQueueBackgroundService CreateService( reconcilerMock.Object, new EntityReconcileCoordinator(effectiveSettings), Mock.Of>>(), + Mock.Of>(), metrics); // Keep the drain bound short so tests that intentionally block a worker across StopAsync/dispose don't @@ -317,7 +319,8 @@ public async Task Restart_Does_Not_Dispose_CancellationTokenSource_Still_Used_By queue, reconcilerMock.Object, new EntityReconcileCoordinator(settings), - Mock.Of>>()) + Mock.Of>>(), + Mock.Of>()) { // The BarrierQueue ignores cancellation, so bound the stop/dispose drain short. DrainGracePeriod = TimeSpan.FromMilliseconds(200), diff --git a/test/KubeOps.Operator.Test/Queue/LeaderAwareEntityQueueBackgroundService.Test.cs b/test/KubeOps.Operator.Test/Queue/LeaderAwareEntityQueueBackgroundService.Test.cs index b4998cf95..7481563ff 100644 --- a/test/KubeOps.Operator.Test/Queue/LeaderAwareEntityQueueBackgroundService.Test.cs +++ b/test/KubeOps.Operator.Test/Queue/LeaderAwareEntityQueueBackgroundService.Test.cs @@ -12,6 +12,7 @@ using KubeOps.Abstractions.Builder; using KubeOps.Abstractions.Reconciliation; using KubeOps.KubernetesClient; +using KubeOps.Operator.Logging; using KubeOps.Operator.Metrics; using KubeOps.Operator.Queue; using KubeOps.Operator.Test.TestEntities; @@ -418,6 +419,7 @@ public TestableService( new OperatorSettingsBuilder { Namespace = "unit-test" }.Build()), logger, elector, + Mock.Of>(), metrics) { _elector = elector; diff --git a/test/KubeOps.Operator.Test/Queue/ScopeAwareEntityQueueBackgroundService.Test.cs b/test/KubeOps.Operator.Test/Queue/ScopeAwareEntityQueueBackgroundService.Test.cs index afd199a6a..ab35081fb 100644 --- a/test/KubeOps.Operator.Test/Queue/ScopeAwareEntityQueueBackgroundService.Test.cs +++ b/test/KubeOps.Operator.Test/Queue/ScopeAwareEntityQueueBackgroundService.Test.cs @@ -13,6 +13,7 @@ using KubeOps.Abstractions.LeaderElection; using KubeOps.Abstractions.Reconciliation; using KubeOps.KubernetesClient; +using KubeOps.Operator.Logging; using KubeOps.Operator.Queue; using KubeOps.Operator.Test.TestEntities; @@ -175,11 +176,12 @@ private sealed class TestableService( reconciler, Mock.Of>(), Mock.Of>>(), - leadershipScope) + leadershipScope, + Mock.Of>()) { public Task> InvokeReconcileSingleAsync( QueueEntry entry, - CancellationToken cancellationToken) - => ReconcileSingleAsync(entry, cancellationToken); + CancellationToken cancellationToken) => + ReconcileSingleAsync(entry, cancellationToken); } } diff --git a/test/KubeOps.Operator.Test/Watcher/LeaderAwareResourceWatcher.Test.cs b/test/KubeOps.Operator.Test/Watcher/LeaderAwareResourceWatcher.Test.cs index 8823c5a02..701cf0105 100644 --- a/test/KubeOps.Operator.Test/Watcher/LeaderAwareResourceWatcher.Test.cs +++ b/test/KubeOps.Operator.Test/Watcher/LeaderAwareResourceWatcher.Test.cs @@ -12,6 +12,7 @@ using KubeOps.Abstractions.Entities; using KubeOps.KubernetesClient; using KubeOps.Operator.Constants; +using KubeOps.Operator.Logging; using KubeOps.Operator.Queue; using KubeOps.Operator.Test.TestEntities; using KubeOps.Operator.Watcher; @@ -275,7 +276,8 @@ public TestableLeaderAwareResourceWatcher( new DefaultEntityLabelSelector(), new DefaultEntityFieldSelector(), client, - elector) + elector, + Mock.Of>()) { _elector = elector; } diff --git a/test/KubeOps.Operator.Test/Watcher/ResourceWatcher{TEntity}.Test.cs b/test/KubeOps.Operator.Test/Watcher/ResourceWatcher{TEntity}.Test.cs index 6902df8e8..b53d0b4ea 100644 --- a/test/KubeOps.Operator.Test/Watcher/ResourceWatcher{TEntity}.Test.cs +++ b/test/KubeOps.Operator.Test/Watcher/ResourceWatcher{TEntity}.Test.cs @@ -744,7 +744,16 @@ private sealed class TestableResourceWatcher( IEntityLabelSelector labelSelector, IEntityFieldSelector fieldSelector, IKubernetesClient client) - : ResourceWatcher(activitySource, logger, cacheProvider, queue, settings, labelSelector, fieldSelector, client) + : ResourceWatcher( + activitySource, + logger, + cacheProvider, + queue, + settings, + labelSelector, + fieldSelector, + client, + Mock.Of>()) { public Task InvokeOnEventAsync(WatchEventType eventType, V1OperatorIntegrationTestEntity entity, CancellationToken cancellationToken) => OnEventAsync(eventType, entity, cancellationToken); diff --git a/test/KubeOps.Operator.Test/Watcher/ScopeAwareResourceWatcher.Test.cs b/test/KubeOps.Operator.Test/Watcher/ScopeAwareResourceWatcher.Test.cs index c8c95dfef..975a66121 100644 --- a/test/KubeOps.Operator.Test/Watcher/ScopeAwareResourceWatcher.Test.cs +++ b/test/KubeOps.Operator.Test/Watcher/ScopeAwareResourceWatcher.Test.cs @@ -16,6 +16,7 @@ using KubeOps.KubernetesClient; using KubeOps.Operator.Builder; using KubeOps.Operator.Constants; +using KubeOps.Operator.Logging; using KubeOps.Operator.Queue; using KubeOps.Operator.Test.TestEntities; using KubeOps.Operator.Watcher; @@ -468,7 +469,8 @@ private sealed class TestableWatcher( labelSelector, fieldSelector, client, - leadershipScope) + leadershipScope, + Mock.Of>()) { public Task InvokeOnEventAsync( WatchEventType eventType, diff --git a/test/KubeOps.Operator.Test/Watcher/ScopeAwareSharedResourceWatcher.Test.cs b/test/KubeOps.Operator.Test/Watcher/ScopeAwareSharedResourceWatcher.Test.cs index 0b240431f..572ef89ec 100644 --- a/test/KubeOps.Operator.Test/Watcher/ScopeAwareSharedResourceWatcher.Test.cs +++ b/test/KubeOps.Operator.Test/Watcher/ScopeAwareSharedResourceWatcher.Test.cs @@ -15,6 +15,7 @@ using KubeOps.Abstractions.LeaderElection; using KubeOps.Abstractions.Reconciliation; using KubeOps.KubernetesClient; +using KubeOps.Operator.Logging; using KubeOps.Operator.Queue; using KubeOps.Operator.Test.TestEntities; using KubeOps.Operator.Watcher; @@ -120,7 +121,8 @@ private ScopeAwareSharedResourceWatcher CreateW Mock.Of>(), Mock.Of(), Mock.Of(), - dispatcher); + dispatcher, + Mock.Of>()); } private static V1OperatorIntegrationTestEntity CreateEntity() =>