diff --git a/docs/DeveloperGuide.md b/docs/DeveloperGuide.md index 7ab356d5df..7fbbf1f2ad 100644 --- a/docs/DeveloperGuide.md +++ b/docs/DeveloperGuide.md @@ -127,6 +127,16 @@ Each project owns exactly one event-id class, named `EventIds`, i The token prefix is required because the stack uses `InternalsVisibleTo`: two `internal` classes with the same name in the same namespace collide across an IVT boundary (`CS0436`). The class holds one `public const int` offset per log class. Offsets are assigned in class-alphabetical order starting at 0; each block reserves at least five spare slots for future messages and is then rounded up to the next multiple of ten, so ids stay documented and managed in one place. Every log method sets `EventId = EventIds. + `. +##### Narrow exception: retained EventSource-compatibility ids + +The four legacy `System.Diagnostics.Tracing.EventSource` providers (`OPC-UA-Core`, `OPC-UA-Client`, `OPC-UA-Server`, `Opc.Ua.ChannelManager`) were removed and replaced with `[LoggerMessage]` equivalents. Their compatibility log methods are a deliberate, narrow exception to the convention above: each keeps the exact numeric id, event name, level, message template, and structured fields the corresponding ETW event had, so consumers can preserve event identity when they migrate from ETW to `ILogger`. Concretely: + +- The compatibility log class uses the **old provider name as its `ILogger` category** (e.g. `"OPC-UA-Core"`, `"Opc.Ua.ChannelManager"`) instead of the typed, per-class category used elsewhere in the project. +- `EventId` resolves to the **literal legacy numeric id** (e.g. `10` for `OPC-UA-Core`'s former `ServiceCallStart`) rather than a normal per-class offset. Keep these values in the affected project's `EventIds.cs`; compatibility ids are scoped to their own logger category, so they may intentionally overlap ordinary per-assembly values. +- Every compatibility method sets `EventName` explicitly (`[LoggerMessage(EventId = 10, EventName = "ServiceCallStart", Level = LogLevel.Trace, Message = "...")]`) so `EventId.Name` matches the original ETW event name exactly. +- ETW-only metadata (provider GUID, `Task`, `Keywords`, manifest) is **not** retained because there is no `ILogger` equivalent. +- Do **not** use this pattern for new log messages. It exists only to preserve the event identities that previously shipped through the four EventSource providers; see [Diagnostics.md](Diagnostics.md#high-speed-logging-and-source-generators) and [migrate/2.0.x/telemetry.md](migrate/2.0.x/telemetry.md) for the full removal/compatibility mapping. + #### Log class convention - **One log class per file**, named `Log`, `internal static partial`, appended at the end of the file inside the same namespace. @@ -174,7 +184,7 @@ logger.ReadArrayZeroDimension(index, dimensions); - [ ] Placeholders are named and match parameter names; no interpolation. - [ ] Parameter types match the arguments; nullable only where needed; no `object`. - [ ] Expensive arguments are guarded with `IsEnabled`; cheap ones are not. -- [ ] `EventId` uses the project's `EventIds` offset (or a literal range for a shared/linked file). +- [ ] `EventId` uses the project's `EventIds` offset (or a literal range for a shared/linked file, or a literal legacy id with an explicit `EventName` for a retained EventSource-compatibility message — see [the narrow exception](#narrow-exception-retained-eventsource-compatibility-ids)). - [ ] When testing with a mocked `ILogger`, stub `IsEnabled(...) => true` and match on `EventId.Name`, not the (empty) source-generated state `ToString()`. ### Other common tasks diff --git a/docs/Diagnostics.md b/docs/Diagnostics.md index 7fe700e2e0..f3dd3cb9bf 100644 --- a/docs/Diagnostics.md +++ b/docs/Diagnostics.md @@ -360,11 +360,7 @@ Client transport channel manager — defined in | `opc.ua.channel.refcount` | ObservableGauge<long> | — | `endpoint` | Reference count per channel entry. | | `opc.ua.channel.participants` | ObservableGauge<long> | — | `endpoint` | Participant count per channel entry. | -Note: the `participant` tag carries the **kind prefix only** -(`Session`, `Discovery`, etc.). The per-instance participant id is -deliberately omitted to keep metric cardinality bounded; the full id -is available on the related Activity tags and EventSource events for -correlation. +Note: the `participant` tag carries the **kind prefix only** (`Session`, `Discovery`, etc.). The per-instance participant id is deliberately omitted to keep metric cardinality bounded; the full id is available on the related Activity tags and on the structured logs emitted under the `Opc.Ua.ChannelManager` logger category for correlation (see [Sessions.md](Sessions.md#diagnostics-surface-contract--what-tags-and-structured-log-fields-carry)). Client request duration — defined in `ClientBase.cs`: diff --git a/docs/Sessions.md b/docs/Sessions.md index 815659e21f..b4e0107d41 100644 --- a/docs/Sessions.md +++ b/docs/Sessions.md @@ -655,36 +655,37 @@ ManagedSession session = await new ManagedSessionBuilder(configuration, telemetr For migration notes on the budget-aware APIs, see [the migration guide](MigrationGuide.md#shared-reconnect-budget-for-managedsession-and-the-channel-manager). -### Diagnostics surface contract — what tags and EventSource fields carry +### Diagnostics surface contract — what tags and structured log fields carry -The channel manager emits diagnostics through three independent -channels: `System.Diagnostics.Activity` tags (distributed tracing), -the `Opc.Ua.ChannelManager` `EventSource` (ETW / `dotnet-trace`), and -`System.Diagnostics.Metrics` instruments. Tag and field values surfaced -through any of these are restricted to **OPC UA-protocol-level fields -only**: +The channel manager emits diagnostics through three independent channels: `System.Diagnostics.Activity` tags (distributed tracing), structured `ILogger` logs under the `Opc.Ua.ChannelManager` category, and `System.Diagnostics.Metrics` instruments. The channel manager previously emitted its own `Opc.Ua.ChannelManager` `EventSource` (ETW / `dotnet-trace`); that provider is removed. The structured logs are the replacement — same category name, same event identities — routed through `Microsoft.Extensions.Logging` / OpenTelemetry logging instead of ETW. + +Each event kept its original `EventId` and `EventName` on the `[LoggerMessage]` replacement, so tooling matching on the numeric id or name keeps working: + +| EventId | EventName | Level | Message template | +|---|---|---|---| +| 1 | `ChannelOpened` | Information | `Channel opened. Endpoint={Endpoint}, Reverse={Reverse}, Refcount={Refcount}, Participants={ParticipantCount}` | +| 2 | `ChannelClosed` | Information | `Channel closed. Endpoint={Endpoint}, Reason={Reason}, Refcount={Refcount}, Participants={ParticipantCount}` | +| 3 | `StateChanged` | Information | `State changed. Endpoint={Endpoint}, Previous={PreviousState}, New={NewState}, Attempt={ReconnectAttempt}, Status={StatusCode}, ErrorMessage={ErrorMessage}` | +| 4 | `ReconnectStarted` | Information | `Reconnect started. Endpoint={Endpoint}, AttemptCount={AttemptCount}` | +| 5 | `ReconnectCompleted` | Information | `Reconnect completed. Endpoint={Endpoint}, AttemptCount={AttemptCount}, Outcome={Outcome}` | +| 6 | `ReconnectFailed` | Warning | `Reconnect failed. Endpoint={Endpoint}, Attempt={Attempt}, Outcome={Outcome}, Status={StatusCode}, ErrorMessage={ErrorMessage}` | +| 7 | `ParticipantAttached` | Information | `Participant attached. Endpoint={Endpoint}, Participant={ParticipantId}, Refcount={Refcount}, Participants={ParticipantCount}` | +| 8 | `ParticipantDetached` | Information | `Participant detached. Endpoint={Endpoint}, Participant={ParticipantId}, Refcount={Refcount}, Participants={ParticipantCount}` | + +Tag and structured-field values surfaced through Activity tags or these logs are restricted to **OPC UA-protocol-level fields only**: - `StatusCode` (numeric / symbolic), e.g. `BadSecureChannelClosed` - `ServiceResult.SymbolicId` - `ServiceResult.LocalizedText.Text` — the operator-facing message -Notably, the following are **never** sent to Activity tags or to -`EventSource` events: +Notably, the following are **never** sent to Activity tags or to the `Opc.Ua.ChannelManager` structured logs above: - The full `ServiceResult.ToString()` serialization -- `ServiceResult.AdditionalInfo` — typically carries inner-exception - messages, file paths, internal IDs -- `Exception.StackTrace`, `Exception.Message`, or any other inner .NET - exception detail +- `ServiceResult.AdditionalInfo` — typically carries inner-exception messages, file paths, internal IDs +- `Exception.StackTrace`, `Exception.Message`, or any other inner .NET exception detail - `Inner` recursion into `ServiceResult.InnerResult` -This keeps internal client/server diagnostics out of distributed -tracing backends where operators with telemetry-read access (but no -production-debug access) should not be able to read internal failure -detail. Full failure context — including stack traces and -`AdditionalInfo` — flows only through the local `ILogger.LogDebug` -path on the manager, where it stays under the host's log-access -controls. +This keeps internal client/server diagnostics out of distributed tracing and logging backends where operators with telemetry-read access (but no production-debug access) should not be able to read internal failure detail. Full failure context — including stack traces and `AdditionalInfo` — flows only through a separate, local `ILogger.LogDebug` call on the manager, where it stays under the host's log-access controls; it is never folded into the `Opc.Ua.ChannelManager`-category events listed above. The metric tag set is also bounded for routine operation: @@ -696,22 +697,11 @@ The metric tag set is also bounded for routine operation: | `opc.ua.channel.gate.wait` | `endpoint` | | `opc.ua.channel.participant.timeout.count` / `opc.ua.channel.participant.recreate.count` | `endpoint`, `participant` (+ `success` on recreate) | -`outcome` is one of `success`, `transient-failure`, `policy-exhausted`, -`fatal-channel`. `reason` is one of `lease-released`, -`manager-disposed`, `faulted`. `endpoint` cardinality is bounded by the -number of distinct OPC UA endpoint URLs the application connects to. - -> The `participant` tag carries the **kind prefix** of the -> participant identifier (e.g. `"Session"`, `"Client"`), not the -> per-instance suffix. This keeps cardinality bounded by the small set -> of participant kinds rather than growing with every session / -> reconnect-storm participant ever created. The full per-instance -> `IReconnectParticipant.Id` is preserved on Activity tags and -> EventSource events so individual sessions remain correlatable in -> distributed traces. Custom participants that don't use the -> "kind-`-`-instance" naming convention contribute their full id to -> the tag, so prefer the prefix-then-suffix shape for new participant -> types. +`outcome` is one of `success`, `transient-failure`, `policy-exhausted`, `fatal-channel`. `reason` is one of `lease-released`, `manager-disposed`, `faulted`. `endpoint` cardinality is bounded by the number of distinct OPC UA endpoint URLs the application connects to. + +> The `participant` tag carries the **kind prefix** of the participant identifier (e.g. `"Session"`, `"Client"`), not the per-instance suffix. This keeps cardinality bounded by the small set of participant kinds rather than growing with every session / reconnect-storm participant ever created. The full per-instance `IReconnectParticipant.Id` is preserved on Activity tags and on the `Opc.Ua.ChannelManager` structured logs above so individual sessions remain correlatable in distributed traces. Custom participants that don't use the "kind-`-`-instance" naming convention contribute their full id to the tag, so prefer the prefix-then-suffix shape for new participant types. + +For the removal of the old `EventSource` providers (including this one) and migration guidance for `EventListener` / `dotnet-trace` consumers, see [migrate/2.0.x/telemetry.md](migrate/2.0.x/telemetry.md#etw-eventsource-provider-removal). ### DI registration diff --git a/docs/migrate/2.0.x/telemetry.md b/docs/migrate/2.0.x/telemetry.md index f3388ae9c5..b73a27745e 100644 --- a/docs/migrate/2.0.x/telemetry.md +++ b/docs/migrate/2.0.x/telemetry.md @@ -223,6 +223,82 @@ obtained from `ITelemetryContext.CreateLogger()`. --- +## ETW `EventSource` provider removal + +> **When to read this:** Read this if your application or tooling attaches an `EventListener`, `dotnet-trace`, PerfView, or any other ETW consumer to one of the stack's `System.Diagnostics.Tracing.EventSource` providers, or if it sets `ClientTraceFlags.EventLog` on a client. + +The stack shipped four internal `EventSource` providers for high-performance tracing. All four are **removed** in 2.0; there is no compile-time or runtime fallback. Their events are replaced one-for-one by `[LoggerMessage]`-generated `ILogger` calls that preserve the original numeric `EventId`, `EventId.Name`, mapped level, message template, and structured fields, so the *event identity* survives even though the transport changes from ETW to `Microsoft.Extensions.Logging` / OpenTelemetry logging. + +| Removed provider (ETW name) | Assembly | Replacement `ILogger` category | +|---|---|---| +| `OPC-UA-Core` | `Opc.Ua.Core` | `OPC-UA-Core` | +| `OPC-UA-Client` | `Opc.Ua.Client` | `OPC-UA-Client` | +| `OPC-UA-Server` | `Opc.Ua.Server` | `OPC-UA-Server` | +| `Opc.Ua.ChannelManager` | `Opc.Ua.Core` (client channel manager) | `Opc.Ua.ChannelManager` | + +The replacement logger category is always the **exact old ETW provider name**, not the assembly's usual typed category. Migrated filters can therefore keep the same identifying string (for example, `AddFilter("OPC-UA-Client", LogLevel.Trace)`) after they move from an ETW provider subscription to `ILogger` configuration. `EventLevel` mapped to `LogLevel` on a like-for-like basis (`Verbose` → `Trace`, `Informational` → `Information`, `Warning` → `Warning`, `Error`/`Critical` → `Error`/`Critical`). See [DeveloperGuide.md — narrow exception: retained EventSource-compatibility ids](../../DeveloperGuide.md#narrow-exception-retained-eventsource-compatibility-ids) for the authoring-side rules and [Sessions.md — diagnostics surface contract](../../Sessions.md#diagnostics-surface-contract--what-tags-and-structured-log-fields-carry) for the full `Opc.Ua.ChannelManager` event table. + +The `OPC-UA-Server` compatibility category remains opt-in like the retired EventSource provider. Enable that category at `Trace` to receive its records, including the `ServerCall` and `SessionState` records whose retained legacy level is `Information`. A global `Information` minimum therefore does not emit a record for every server request. + +**Not retained:** the ETW provider GUID, `EventTask`/`EventKeywords` definitions, and the ETW manifest. There is no `ILogger` equivalent for these, and providers/consumers that depended on them (raw ETW session subscribers keyed by provider GUID, manifest-based decoders) must move to `Microsoft.Extensions.Logging` category/event-name filtering instead. + +### `ClientTraceFlags.EventLog` removed (source breaking) + +`ClientTraceFlags.EventLog` — the flag that routed `ClientBase` request/response tracing to the (now-removed) `OPC-UA-Core` `EventSource` — is **removed**. Code that references it fails to compile: + +```csharp +// OLD - no longer compiles (ClientTraceFlags.EventLog removed) +client.ActivityTraceFlags = ClientTraceFlags.Log | ClientTraceFlags.EventLog; + +// NEW - ClientTraceFlags.Log alone now emits the canonical OPC-UA-Core +// compatibility events (same EventId / EventName / message as the old +// EventLog flag); the separate per-call ClientBase structured logs that +// ClientTraceFlags.Log used to emit are replaced by these events +client.ActivityTraceFlags = ClientTraceFlags.Log; +``` + +`ClientTraceFlags.Log` now emits the canonical `OPC-UA-Core` request events (`ServiceCallStart` / `ServiceCallStop` / `ServiceCallBadStop`) through the `OPC-UA-Core` logger category, so existing filters or dashboards keyed on those event names keep matching without further changes. The separate `SendResponse` compatibility event is emitted by `TcpServerChannel` under the same category and is not controlled by `ClientTraceFlags`. There is no separate flag for the compatibility events; remove any reference to `ClientTraceFlags.EventLog` from your code. + +This consolidation also adopts the legacy event levels and fields: request start/stop move from `Information` to `Trace`, failure moves from `Error` to `Warning`, and the former per-call elapsed-time field is no longer part of these log records (request duration remains available through `opc.ua.client.request.duration`). Configure the `OPC-UA-Core` category at `Trace` if you need successful request start/stop records. + +### Migrating `EventListener` / `dotnet-trace` consumers + +If your code or tooling previously attached to one of the four providers, replace it with the `Microsoft.Extensions.Logging` / OpenTelemetry logging equivalent: + +```csharp +// OLD - ETW EventListener attached to a stack provider (removed in 2.0) +public sealed class ClientEventListener : EventListener +{ + protected override void OnEventSourceCreated(EventSource source) + { + if (source.Name == "OPC-UA-Client") + { + EnableEvents(source, EventLevel.Verbose); + } + } + + protected override void OnEventWritten(EventWrittenEventArgs e) + { + Console.WriteLine($"{e.EventName}: {string.Join(", ", e.Payload ?? [])}"); + } +} + +// NEW - ILoggerProvider filtered to the same category name +builder.Services.AddLogging(b => b + .AddFilter("OPC-UA-Client", LogLevel.Trace) + .AddConsole()); + +// NEW - OpenTelemetry Logs SDK, same category +builder.Services.AddOpenTelemetry().WithLogging(l => l + .AddProcessor(/* your exporter of choice */)); +``` + +`dotnet-trace` / PerfView users who captured `OPC-UA-Core`, `OPC-UA-Client`, `OPC-UA-Server`, or `Opc.Ua.ChannelManager` as ETW providers should instead configure an `ILoggerProvider` (Console, OpenTelemetry OTLP, Application Insights, etc.) filtered to the matching category name, or use the [`Microsoft-Extensions-Logging` ETW provider](https://learn.microsoft.com/dotnet/core/diagnostics/logging-tracing) that `dotnet-trace` already understands for standard `ILogger` output, if ETW-shaped capture is still required. + +> **Out of scope.** The OPC UA information-model `EventSourceRegistry` / `HasEventSource` reference type (`Opc.Ua.Server.Fluent`, used for Alarms & Conditions modelling) and the BCL's own `System.Buffers.ArrayPoolEventSource` are unrelated to this removal — neither is a stack-owned ETW provider, and neither is affected by this migration. + +--- + ## Migration utilities To aid migration the stack provides: @@ -253,6 +329,7 @@ test time. - [`docs/Diagnostics.md`](../../Diagnostics.md) — full end-state usage and extensibility guidance for `ITelemetryContext` (custom contexts, OpenTelemetry wiring, metrics inventory). +- [`docs/Sessions.md` — diagnostics surface contract](../../Sessions.md#diagnostics-surface-contract--what-tags-and-structured-log-fields-carry) — full `Opc.Ua.ChannelManager` compatibility event table and safe-field policy. +- [`docs/DeveloperGuide.md` — narrow exception: retained EventSource-compatibility ids](../../DeveloperGuide.md#narrow-exception-retained-eventsource-compatibility-ids) — authoring rules for the retained compatibility ids. - [2.0 migration index](README.md) — analyzer quick-start + symptom → sub-doc table. - [Migration Guide](../../MigrationGuide.md) — landing page across versions. - diff --git a/src/Opc.Ua.Client/EventIds.cs b/src/Opc.Ua.Client/EventIds.cs index 63ec8c5eb2..f45037bc3f 100644 --- a/src/Opc.Ua.Client/EventIds.cs +++ b/src/Opc.Ua.Client/EventIds.cs @@ -61,5 +61,27 @@ internal static class ClientEventIds public const int SubscriptionManager = 440; public const int WebApiTransportChannel = 480; public const int WebApiWssTransportChannel = 490; + + /// + /// The category name that + /// preserves the identity of the legacy "OPC-UA-Client" EventSource provider + /// (Guid 8CFA469E-18C6-480F-9B74-B005DACDE3D3). Loggers created for this + /// category emit only the compatibility events below, using the + /// + /// EventId/EventName pairs that match the removed EventSource. + /// + public const string LegacyCategoryName = "OPC-UA-Client"; + + /// + /// Legacy EventSource-compatible event ids 1-5, preserved for consumers that migrate + /// from the removed provider to source-generated ILogger logging. These ids + /// intentionally overlap the ordinary per-class offsets declared above because they + /// are only emitted through the dedicated logger. + /// + public const int LegacySubscriptionStateId = 1; + public const int LegacyNotificationId = 2; + public const int LegacyNotificationReceivedId = 3; + public const int LegacyPublishStartId = 4; + public const int LegacyPublishStopId = 5; } } diff --git a/src/Opc.Ua.Client/OpcUaClientEventSource.cs b/src/Opc.Ua.Client/OpcUaClientEventSource.cs deleted file mode 100644 index 663d4cdce0..0000000000 --- a/src/Opc.Ua.Client/OpcUaClientEventSource.cs +++ /dev/null @@ -1,149 +0,0 @@ -/* ======================================================================== - * Copyright (c) 2005-2025 The OPC Foundation, Inc. All rights reserved. - * - * OPC Foundation MIT License 1.00 - * - * Permission is hereby granted, free of charge, to any person - * obtaining a copy of this software and associated documentation - * files (the "Software"), to deal in the Software without - * restriction, including without limitation the rights to use, - * copy, modify, merge, publish, distribute, sublicense, and/or sell - * copies of the Software, and to permit persons to whom the - * Software is furnished to do so, subject to the following - * conditions: - * - * The above copyright notice and this permission notice shall be - * included in all copies or substantial portions of the Software. - * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, - * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES - * OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND - * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT - * HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, - * WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING - * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR - * OTHER DEALINGS IN THE SOFTWARE. - * - * The complete license agreement can be found here: - * http://opcfoundation.org/License/MIT/1.00/ - * ======================================================================*/ - -using System; -using System.Diagnostics.Tracing; - -namespace Opc.Ua.Client -{ - /// - /// EventSource for client. - /// - public static partial class CoreClientUtils - { - /// - /// The EventSource log interface. - /// - internal static OpcUaClientEventSource EventLog { get; } = new OpcUaClientEventSource(); - } - - /// - /// Event source for high performance logging. - /// - [EventSource(Name = "OPC-UA-Client", Guid = "8CFA469E-18C6-480F-9B74-B005DACDE3D3")] - internal class OpcUaClientEventSource : EventSource - { - internal const int SubscriptionStateId = 1; - internal const int NotificationId = SubscriptionStateId + 1; - internal const int NotificationReceivedId = NotificationId + 1; - internal const int PublishStartId = NotificationReceivedId + 1; - internal const int PublishStopId = PublishStartId + 1; - - /// - /// The state of the client subscription. - /// - [Event( - SubscriptionStateId, - Message = "Subscription {0}, Id={1}, LastNotificationTime={2:HH:mm:ss}, " + - "GoodPublishRequestCount={3}, PublishingInterval={4}, KeepAliveCount={5}, " + - "PublishingEnabled={6}, MonitoredItemCount={7}", - Level = EventLevel.Verbose)] - public void SubscriptionState( - string context, - uint id, - DateTime lastNotificationTime, - int goodPublishRequestCount, - double currentPublishingInterval, - uint currentKeepAliveCount, - bool currentPublishingEnabled, - uint monitoredItemCount) - { - WriteEvent( - SubscriptionStateId, - context, - id, - lastNotificationTime, - goodPublishRequestCount, - currentPublishingInterval, - currentKeepAliveCount, - currentPublishingEnabled, - monitoredItemCount); - } - - /// - /// The notification message. Called internally to convert wrapped value. - /// - [Event( - NotificationId, - Message = "Notification: ClientHandle={0}, Value={1}", - Level = EventLevel.Verbose)] - public void Notification(int clientHandle, string value) - { - if (IsEnabled()) - { - WriteEvent(NotificationId, clientHandle, value); - } - } - - /// - /// A notification received in Publish complete. - /// - [Event( - NotificationReceivedId, - Message = "NOTIFICATION RECEIVED: SubId={0}, SeqNo={1}", - Level = EventLevel.Verbose)] - public void NotificationReceived(int subscriptionId, int sequenceNumber) - { - if (IsEnabled()) - { - WriteEvent(NotificationReceivedId, subscriptionId, sequenceNumber); - } - } - - /// - /// A Publish begin received. - /// - [Event( - PublishStartId, - Message = "PUBLISH #{0} SENT", - Level = EventLevel.Verbose)] - public void PublishStart(int requestHandle) - { - if (IsEnabled()) - { - WriteEvent(PublishStartId, requestHandle); - } - } - - /// - /// A Publish complete received. - /// - [Event( - PublishStopId, - Message = "PUBLISH #{0} RECEIVED", - Level = EventLevel.Verbose)] - public void PublishStop(int requestHandle) - { - if (IsEnabled()) - { - WriteEvent(PublishStopId, requestHandle); - } - } - } -} diff --git a/src/Opc.Ua.Client/Session/Session.ChannelManager.cs b/src/Opc.Ua.Client/Session/Session.ChannelManager.cs index 1fa988145c..4b11f64162 100644 --- a/src/Opc.Ua.Client/Session/Session.ChannelManager.cs +++ b/src/Opc.Ua.Client/Session/Session.ChannelManager.cs @@ -49,8 +49,8 @@ public partial class Session : IReconnectParticipant, IRecreateAwareReconnectPar /// per-kind cardinality (one series per "Session", "Client", /// …) instead of accumulating one permanent series per session /// instance. The full per-instance identifier is preserved on - /// distributed-trace Activity tags and EventSource events so - /// individual sessions remain correlatable in traces. + /// distributed-trace Activity tags and structured channel-manager + /// logs so individual sessions remain correlatable. /// public string ParticipantId { get; } = "Session-" + Guid.NewGuid().ToString("N"); diff --git a/src/Opc.Ua.Client/Session/Subscription/ClassicSubscriptionEngine.cs b/src/Opc.Ua.Client/Session/Subscription/ClassicSubscriptionEngine.cs index f391577a21..597d41d79b 100644 --- a/src/Opc.Ua.Client/Session/Subscription/ClassicSubscriptionEngine.cs +++ b/src/Opc.Ua.Client/Session/Subscription/ClassicSubscriptionEngine.cs @@ -60,6 +60,8 @@ public ClassicSubscriptionEngine( ?? throw new ArgumentNullException(nameof(context)); m_logger = context.Telemetry .CreateLogger(); + m_eventLogger = context.Telemetry + .CreateLogger(ClientEventIds.LegacyCategoryName); m_minPublishRequestCount = kDefaultPublishRequestCount; m_maxPublishRequestCount = kMaxPublishRequestCountMax; m_timeProvider = timeProvider ?? TimeProvider.System; @@ -267,9 +269,7 @@ internal bool BeginPublish(int timeout) Utils.IncrementIdentifier(ref PublishCounter) }; - m_logger.PUBLISHRequestHandleSENT(requestHeader.RequestHandle); - CoreClientUtils.EventLog.PublishStart( - (int)requestHeader.RequestHandle); + m_eventLogger.ClientEventPublishStart((int)requestHeader.RequestHandle); try { @@ -318,9 +318,7 @@ private void OnPublishComplete( requestHeader.RequestHandle, DataTypes.PublishRequest); - m_logger.PUBLISHRequestHandleRECEIVED(requestHeader.RequestHandle); - CoreClientUtils.EventLog.PublishStop( - (int)requestHeader.RequestHandle); + m_eventLogger.ClientEventPublishStop((int)requestHeader.RequestHandle); // Bail out early if the session has been disposed. if (m_context.Disposed) @@ -400,10 +398,7 @@ private void OnPublishComplete( return; } - m_logger.NOTIFICATIONRECEIVEDSubIdSubscriptionIdSeqNoSequenceNumber( - subscriptionId, - notificationMessage.SequenceNumber); - CoreClientUtils.EventLog.NotificationReceived( + m_eventLogger.ClientEventNotificationReceived( (int)subscriptionId, (int)notificationMessage.SequenceNumber); @@ -1013,6 +1008,7 @@ private bool BelowPublishRequestLimit(int requestCount) private const int kPublishRequestSequenceNumberOutdatedThreshold = 100; private readonly ISubscriptionEngineContext m_context; private readonly ILogger m_logger; + private readonly ILogger m_eventLogger; private readonly TimeProvider m_timeProvider; private readonly object m_acknowledgementsToSendLock = new(); private List m_acknowledgementsToSend = []; @@ -1044,17 +1040,23 @@ internal static partial class ClassicSubscriptionEngineLog Message = "Publish skipped due to session lost connection. Last successful keepalive: {LastKeepAlive}")] public static partial void PublishSkippedSessionLostConnectionLast(this ILogger logger, DateTime lastKeepAlive); - [LoggerMessage(EventId = ClientEventIds.ClassicSubscriptionEngine + 4, Level = LogLevel.Trace, + [LoggerMessage( + EventId = ClientEventIds.LegacyPublishStartId, + EventName = "PublishStart", + Level = LogLevel.Trace, Message = "PUBLISH #{RequestHandle} SENT")] - public static partial void PUBLISHRequestHandleSENT(this ILogger logger, uint requestHandle); + public static partial void ClientEventPublishStart(this ILogger logger, int requestHandle); [LoggerMessage(EventId = ClientEventIds.ClassicSubscriptionEngine + 5, Level = LogLevel.Error, Message = "Unexpected error sending publish request.")] public static partial void UnexpectedErrorSendingPublishRequest(this ILogger logger, Exception? exception); - [LoggerMessage(EventId = ClientEventIds.ClassicSubscriptionEngine + 6, Level = LogLevel.Trace, + [LoggerMessage( + EventId = ClientEventIds.LegacyPublishStopId, + EventName = "PublishStop", + Level = LogLevel.Trace, Message = "PUBLISH #{RequestHandle} RECEIVED")] - public static partial void PUBLISHRequestHandleRECEIVED(this ILogger logger, uint requestHandle); + public static partial void ClientEventPublishStop(this ILogger logger, int requestHandle); [LoggerMessage(EventId = ClientEventIds.ClassicSubscriptionEngine + 7, Level = LogLevel.Warning, Message = "Publish response discarded because session id changed: Old {PreviousSessionId} != New" + @@ -1064,12 +1066,15 @@ public static partial void PublishResponseDiscardedSessionIdChanged( NodeId? previousSessionId, NodeId? sessionId); - [LoggerMessage(EventId = ClientEventIds.ClassicSubscriptionEngine + 8, Level = LogLevel.Trace, + [LoggerMessage( + EventId = ClientEventIds.LegacyNotificationReceivedId, + EventName = "NotificationReceived", + Level = LogLevel.Trace, Message = "NOTIFICATION RECEIVED: SubId={SubscriptionId}, SeqNo={SequenceNumber}")] - public static partial void NOTIFICATIONRECEIVEDSubIdSubscriptionIdSeqNoSequenceNumber( + public static partial void ClientEventNotificationReceived( this ILogger logger, - uint subscriptionId, - uint sequenceNumber); + int subscriptionId, + int sequenceNumber); [LoggerMessage(EventId = ClientEventIds.ClassicSubscriptionEngine + 9, Level = LogLevel.Warning, Message = "No new publish sent because of reconnect in progress.")] diff --git a/src/Opc.Ua.Client/Subscription/Classic/MonitoredItem.cs b/src/Opc.Ua.Client/Subscription/Classic/MonitoredItem.cs index c4313ff547..ea41227ad1 100644 --- a/src/Opc.Ua.Client/Subscription/Classic/MonitoredItem.cs +++ b/src/Opc.Ua.Client/Subscription/Classic/MonitoredItem.cs @@ -1124,6 +1124,7 @@ public MonitoredItemDataCache(ITelemetryContext? telemetry, uint queueSize = 1) { QueueSize = queueSize; m_logger = telemetry.CreateLogger(); + m_eventLogger = telemetry.CreateLogger(ClientEventIds.LegacyCategoryName); if (queueSize > 1) { m_values = new ConcurrentQueue(); @@ -1176,18 +1177,13 @@ public void OnNotification(MonitoredItemNotification notification) { LastValue = notification.Value; - if (CoreClientUtils.EventLog.IsEnabled()) + if (m_eventLogger.IsEnabled(LogLevel.Trace)) { - CoreClientUtils.EventLog.Notification( + m_eventLogger.ClientEventNotification( (int)notification.ClientHandle, LastValue.WrappedValue.ToString()); } - m_logger.NotificationClientHandleClientHandleValueValueSourceTime( - notification.ClientHandle, - notification.Value.WrappedValue, - notification.Value.SourceTimestamp); - if (m_values != null) { m_values.Enqueue(notification.Value); @@ -1245,6 +1241,7 @@ public void SetQueueSize(uint queueSize) private ConcurrentQueue? m_values; private readonly ILogger m_logger; + private readonly ILogger m_eventLogger; } /// @@ -1356,13 +1353,15 @@ public static partial void OverflowBitSetDataChangeServerTimestamp( Variant value, uint monitoredItemId); - [LoggerMessage(EventId = ClientEventIds.MonitoredItem + 3, Level = LogLevel.Debug, - Message = "Notification: ClientHandle={ClientHandle}, Value={Value}, SourceTime={SourceTime}")] - public static partial void NotificationClientHandleClientHandleValueValueSourceTime( + [LoggerMessage( + EventId = ClientEventIds.LegacyNotificationId, + EventName = "Notification", + Level = LogLevel.Trace, + Message = "Notification: ClientHandle={ClientHandle}, Value={Value}")] + public static partial void ClientEventNotification( this ILogger logger, - uint clientHandle, - Variant value, - DateTimeUtc sourceTime); + int clientHandle, + string value); [LoggerMessage(EventId = ClientEventIds.MonitoredItem + 4, Level = LogLevel.Information, Message = "Dropped value: ClientHandle={ClientHandle}, Value={Value}, SourceTime={SourceTime}")] diff --git a/src/Opc.Ua.Client/Subscription/Classic/Subscription.cs b/src/Opc.Ua.Client/Subscription/Classic/Subscription.cs index e96f991624..92de6c0494 100644 --- a/src/Opc.Ua.Client/Subscription/Classic/Subscription.cs +++ b/src/Opc.Ua.Client/Subscription/Classic/Subscription.cs @@ -83,6 +83,7 @@ public Subscription(ITelemetryContext telemetry, SubscriptionOptions? options, m_timeProvider = timeProvider ?? TimeProvider.System; Telemetry = telemetry ?? AmbientMessageContext.Telemetry; m_logger = Telemetry.CreateLogger(); + m_eventLogger = Telemetry.CreateLogger(ClientEventIds.LegacyCategoryName); State = options ?? new SubscriptionOptions(); DefaultItem = CreateMonitoredItem(); } @@ -102,6 +103,7 @@ public Subscription(Subscription template, bool copyEventHandlers = false) m_telemetry = template.m_telemetry; m_timeProvider = template.m_timeProvider; m_logger = template.m_logger; + m_eventLogger = template.m_eventLogger; State = template.State; Handle = template.Handle; DefaultItem = CreateMonitoredItem(template.DefaultItem.State); @@ -740,6 +742,7 @@ internal set { m_telemetry = value; m_logger = value.CreateLogger(); + m_eventLogger = value.CreateLogger(ClientEventIds.LegacyCategoryName); } } @@ -2324,17 +2327,7 @@ private async Task PublishResponseMessageWorkerAsync(CancellationToken ct) /// internal void TraceState(string context) { - CoreClientUtils.EventLog.SubscriptionState( - context, - Id, - new DateTime(m_lastNotificationTime), - Session?.GoodPublishRequestCount ?? 0, - CurrentPublishingInterval, - CurrentKeepAliveCount, - CurrentPublishingEnabled, - MonitoredItemCount); - - m_logger.SubscriptionContextIdSubscriptionIdLastNotificationTimeLastNotificationTime( + m_eventLogger.ClientEventSubscriptionState( context, Id, new DateTime(m_lastNotificationTime), @@ -3296,6 +3289,7 @@ private void PublishingStateChanged( private LinkedList? m_incomingMessages; private ITelemetryContext? m_telemetry; private ILogger m_logger; + private ILogger m_eventLogger; /// /// A message received from the server cached until is processed or discarded. @@ -3716,21 +3710,23 @@ public static partial void SubscriptionIdSubscriptionIdPublishTaskTaskIdX82( uint subscriptionId, int? taskId); - [LoggerMessage(EventId = ClientEventIds.Subscription + 21, Level = LogLevel.Information, - Message = "Subscription {Context}, Id={SubscriptionId}," + - " LastNotificationTime={LastNotificationTime:HH:mm:ss}," + - " GoodPublishRequestCount={GoodPublishRequestCount}," + - " PublishingInterval={PublishingInterval}, KeepAliveCount={KeepAliveCount}," + - " PublishingEnabled={PublishingEnabled}, MonitoredItemCount={MonitoredItemCount}")] - public static partial void SubscriptionContextIdSubscriptionIdLastNotificationTimeLastNotificationTime( + [LoggerMessage( + EventId = ClientEventIds.LegacySubscriptionStateId, + EventName = "SubscriptionState", + Level = LogLevel.Trace, + Message = "Subscription {Context}, Id={Id}, LastNotificationTime={LastNotificationTime:HH:mm:ss}, " + + "GoodPublishRequestCount={GoodPublishRequestCount}, PublishingInterval={CurrentPublishingInterval}, " + + "KeepAliveCount={CurrentKeepAliveCount}, PublishingEnabled={CurrentPublishingEnabled}, " + + "MonitoredItemCount={MonitoredItemCount}")] + public static partial void ClientEventSubscriptionState( this ILogger logger, string context, - uint subscriptionId, + uint id, DateTime lastNotificationTime, int goodPublishRequestCount, - double publishingInterval, - uint keepAliveCount, - bool publishingEnabled, + double currentPublishingInterval, + uint currentKeepAliveCount, + bool currentPublishingEnabled, uint monitoredItemCount); [LoggerMessage(EventId = ClientEventIds.Subscription + 22, Level = LogLevel.Information, diff --git a/src/Opc.Ua.Core/EventIds.cs b/src/Opc.Ua.Core/EventIds.cs index 9e8f9a65c1..f45a4b8dc6 100644 --- a/src/Opc.Ua.Core/EventIds.cs +++ b/src/Opc.Ua.Core/EventIds.cs @@ -41,6 +41,24 @@ namespace Opc.Ua /// internal static class CoreEventIds { + // Compatibility events retain their former EventSource ids. They are scoped by + // their dedicated ILogger categories and intentionally overlap the per-class ids below. + public const string CoreCompatibilityCategory = "OPC-UA-Core"; + public const int CoreServiceCallStart = 10; + public const int CoreServiceCallStop = 11; + public const int CoreServiceCallBadStop = 12; + public const int CoreSendResponse = 14; + + public const string ChannelManagerCompatibilityCategory = "Opc.Ua.ChannelManager"; + public const int ChannelManagerChannelOpened = 1; + public const int ChannelManagerChannelClosed = 2; + public const int ChannelManagerStateChanged = 3; + public const int ChannelManagerReconnectStarted = 4; + public const int ChannelManagerReconnectCompleted = 5; + public const int ChannelManagerReconnectFailed = 6; + public const int ChannelManagerParticipantAttached = 7; + public const int ChannelManagerParticipantDetached = 8; + public const int ApplicationConfiguration = 0; public const int AsyncResultBase = 10; public const int Audit = 20; diff --git a/src/Opc.Ua.Core/Stack/Client/Channels/ClientChannelManager.cs b/src/Opc.Ua.Core/Stack/Client/Channels/ClientChannelManager.cs index 505257fa28..46ae8be596 100644 --- a/src/Opc.Ua.Core/Stack/Client/Channels/ClientChannelManager.cs +++ b/src/Opc.Ua.Core/Stack/Client/Channels/ClientChannelManager.cs @@ -89,12 +89,15 @@ public ClientChannelManager( ApplicationConfiguration configuration, ITransportChannelBindings? channelFactory = null, ChannelManagerOptions? options = null) + : this( + configuration, + GetConfigurationTelemetry(configuration), + channelFactory, + reconnectPolicy: null, + timeProvider: null, + options, + enableGeneralTelemetry: false) { - Configuration = configuration; - ChannelBindings = channelFactory; - m_options = options ?? new ChannelManagerOptions(); - m_certRotation = new ClientChannelManagerCertRotation(this); - WireCertificateRotation(); } /// @@ -457,15 +460,45 @@ public ClientChannelManager( IChannelReconnectPolicy? reconnectPolicy = null, TimeProvider? timeProvider = null, ChannelManagerOptions? options = null) - : this(configuration, channelFactory, options) + : this( + configuration, + telemetry, + channelFactory, + reconnectPolicy, + timeProvider, + options, + enableGeneralTelemetry: true) { - Logger = telemetry?.CreateLogger(); - m_meter = telemetry?.CreateMeter(); - m_metrics = m_meter != null - ? new ClientChannelManagerMetrics(this, m_meter) - : null; + } + + private ClientChannelManager( + ApplicationConfiguration configuration, + ITelemetryContext? telemetry, + ITransportChannelBindings? channelFactory, + IChannelReconnectPolicy? reconnectPolicy, + TimeProvider? timeProvider, + ChannelManagerOptions? options, + bool enableGeneralTelemetry) + { + Configuration = configuration ?? throw new ArgumentNullException(nameof(configuration)); + ChannelBindings = channelFactory; + m_options = options ?? new ChannelManagerOptions(); + m_diagnostics = new ClientChannelManagerDiagnostics( + TelemetryExtensions.CreateLogger( + telemetry, + CoreEventIds.ChannelManagerCompatibilityCategory)); + if (enableGeneralTelemetry) + { + Logger = TelemetryExtensions.CreateLogger(telemetry); + m_meter = telemetry?.CreateMeter(); + m_metrics = m_meter != null + ? new ClientChannelManagerMetrics(this, m_meter) + : null; + } ReconnectPolicy = reconnectPolicy ?? new ExponentialBackoffChannelReconnectPolicy(); TimeProvider = timeProvider ?? TimeProvider.System; + m_certRotation = new ClientChannelManagerCertRotation(this); + WireCertificateRotation(); } /// @@ -1264,6 +1297,14 @@ private static DefaultTransportBindingRegistry GetDefaultBindingsLazy() return s_defaultBindings.Value; } + private static ITelemetryContext? GetConfigurationTelemetry( + ApplicationConfiguration configuration) + { + return (configuration ?? throw new ArgumentNullException(nameof(configuration))) + .CreateMessageContext() + .Telemetry; + } + [System.Diagnostics.CodeAnalysis.UnconditionalSuppressMessage( "Trimming", "IL2026", Justification = "Pre-DI fallback path only; DI consumers receive an explicit registry.")] @@ -1276,7 +1317,7 @@ private static DefaultTransportBindingRegistry CreateDefaultBindingsRegistry() CreateDefaultBindingsRegistry, LazyThreadSafetyMode.ExecutionAndPublication); - private readonly ClientChannelManagerDiagnostics m_diagnostics = new(); + private readonly ClientChannelManagerDiagnostics m_diagnostics; } /// diff --git a/src/Opc.Ua.Core/Stack/Client/Channels/Internal/ClientChannelManagerDiagnostics.cs b/src/Opc.Ua.Core/Stack/Client/Channels/Internal/ClientChannelManagerDiagnostics.cs index ad07fab123..03c3222fcd 100644 --- a/src/Opc.Ua.Core/Stack/Client/Channels/Internal/ClientChannelManagerDiagnostics.cs +++ b/src/Opc.Ua.Core/Stack/Client/Channels/Internal/ClientChannelManagerDiagnostics.cs @@ -27,16 +27,17 @@ * http://opcfoundation.org/License/MIT/1.00/ * ======================================================================*/ +using System; using System.Collections.Generic; using System.Diagnostics; -using System.Diagnostics.Tracing; +using Microsoft.Extensions.Logging; using ChannelCloseReason = Opc.Ua.ClientChannelManager.ChannelCloseReason; namespace Opc.Ua { /// - /// Emits OPC UA channel-manager diagnostic signals (Activities and an - /// ) for the client channel manager. + /// Emits OPC UA channel-manager diagnostic signals through Activities and + /// structured logs for the client channel manager. /// /// /// @@ -48,12 +49,17 @@ namespace Opc.Ua /// and inner .NET exception /// data such as messages, file paths and stack traces — are emitted /// only via local ILogger debug logs, never through Activity - /// tags or EventSource events, to avoid leaking internal diagnostics + /// tags or structured compatibility logs, to avoid leaking internal diagnostics /// to external tracing backends. /// /// internal sealed class ClientChannelManagerDiagnostics { + public ClientChannelManagerDiagnostics(ILogger logger) + { + m_logger = logger ?? throw new ArgumentNullException(nameof(logger)); + } + public IReadOnlyList GetDiagnostics(ChannelEntry[] snapshot) { var diagnostics = new ManagedChannelDiagnostic[snapshot.Length]; @@ -66,7 +72,6 @@ public IReadOnlyList GetDiagnostics(ChannelEntry[] sna } private const string kReconnectOutcomeSuccess = "success"; - private const string kChannelManagerDiagnosticsName = "Opc.Ua.ChannelManager"; private const string kReconnectActivityName = "OpcUaChannelReconnect"; public Activity? StartReconnectActivity(ChannelEntry entry) @@ -76,7 +81,7 @@ public IReadOnlyList GetDiagnostics(ChannelEntry[] sna ActivityKind.Internal); activity?.SetTag("endpoint", entry.EndpointUrl); activity?.SetTag("reverse", entry.IsReverse); - s_eventSource.ReconnectStarted(entry.EndpointUrl, 0); + m_logger.ChannelManagerReconnectStarted(entry.EndpointUrl, 0); return activity; } @@ -90,24 +95,39 @@ public void CompleteReconnectActivity( activity?.SetTag("endpoint", entry.EndpointUrl); activity?.SetTag("attempt.count", attemptCount); activity?.SetTag("outcome", outcome); - if (error != null) + string statusCode = string.Empty; + string errorMessage = string.Empty; + if (error != null && activity != null) { - activity?.SetTag("error.status_code", GetStatusCode(error)); - activity?.SetTag("error.message", GetSafeErrorMessage(error)); + statusCode = GetStatusCode(error); + errorMessage = GetSafeErrorMessage(error); + activity.SetTag("error.status_code", statusCode); + activity.SetTag("error.message", errorMessage); } if (outcome == kReconnectOutcomeSuccess) { - s_eventSource.ReconnectCompleted(entry.EndpointUrl, attemptCount, outcome); + m_logger.ChannelManagerReconnectCompleted(entry.EndpointUrl, attemptCount, outcome); + return; + } + + if (!m_logger.IsEnabled(LogLevel.Warning)) + { return; } - s_eventSource.ReconnectFailed( + if (error != null && activity == null) + { + statusCode = GetStatusCode(error); + errorMessage = GetSafeErrorMessage(error); + } + + m_logger.ChannelManagerReconnectFailed( entry.EndpointUrl, attemptCount, outcome, - GetStatusCode(error), - GetSafeErrorMessage(error)); + statusCode, + errorMessage); } public void EmitReconnectFailed( @@ -116,7 +136,12 @@ public void EmitReconnectFailed( string outcome, ServiceResult? error) { - s_eventSource.ReconnectFailed( + if (!m_logger.IsEnabled(LogLevel.Warning)) + { + return; + } + + m_logger.ChannelManagerReconnectFailed( entry.EndpointUrl, attempt, outcome, @@ -126,7 +151,12 @@ public void EmitReconnectFailed( public void EmitStateChanged(ChannelEntry entry, ChannelStateChange change) { - s_eventSource.StateChanged( + if (!m_logger.IsEnabled(LogLevel.Information)) + { + return; + } + + m_logger.ChannelManagerStateChanged( entry.EndpointUrl, change.PreviousState.ToString(), change.NewState.ToString(), @@ -137,7 +167,7 @@ public void EmitStateChanged(ChannelEntry entry, ChannelStateChange change) public void EmitChannelOpened(ChannelEntry entry) { - s_eventSource.ChannelOpened( + m_logger.ChannelManagerChannelOpened( entry.EndpointUrl, entry.IsReverse, entry.RefCount, @@ -146,7 +176,12 @@ public void EmitChannelOpened(ChannelEntry entry) public void EmitChannelClosed(ChannelEntry entry, ChannelCloseReason reason) { - s_eventSource.ChannelClosed( + if (!m_logger.IsEnabled(LogLevel.Information)) + { + return; + } + + m_logger.ChannelManagerChannelClosed( entry.EndpointUrl, GetCloseReason(reason), entry.RefCount, @@ -159,7 +194,7 @@ public void EmitParticipantAttached( int refCount, int participantCount) { - s_eventSource.ParticipantAttached( + m_logger.ChannelManagerParticipantAttached( entry.EndpointUrl, participantId, refCount, @@ -172,7 +207,7 @@ public void EmitParticipantDetached( int refCount, int participantCount) { - s_eventSource.ParticipantDetached( + m_logger.ChannelManagerParticipantDetached( entry.EndpointUrl, participantId, refCount, @@ -186,7 +221,7 @@ private static string GetStatusCode(ServiceResult? error) /// /// Returns a SAFE error message suitable for distributed-tracing - /// tags and EventSource events. Only OPC UA-protocol-level fields + /// tags and structured compatibility logs. Only OPC UA-protocol-level fields /// are surfaced: if /// present, otherwise . The /// full (including @@ -221,136 +256,117 @@ private static string GetCloseReason(ChannelCloseReason reason) }; } - private sealed class ChannelManagerEventSource : EventSource - { - public const int ChannelOpenedId = 1; - public const int ChannelClosedId = ChannelOpenedId + 1; - public const int StateChangedId = ChannelClosedId + 1; - public const int ReconnectStartedId = StateChangedId + 1; - public const int ReconnectCompletedId = ReconnectStartedId + 1; - public const int ReconnectFailedId = ReconnectCompletedId + 1; - public const int ParticipantAttachedId = ReconnectFailedId + 1; - public const int ParticipantDetachedId = ParticipantAttachedId + 1; - - public ChannelManagerEventSource() - : base(kChannelManagerDiagnosticsName) - { - } + private static readonly ActivitySource s_activitySource = new( + CoreEventIds.ChannelManagerCompatibilityCategory); - [Event( - ChannelOpenedId, - Message = "Channel opened. Endpoint={0}, Reverse={1}, Refcount={2}, Participants={3}", - Level = EventLevel.Informational)] - public void ChannelOpened( - string endpoint, - bool reverse, - int refcount, - int participantCount) - { - WriteEvent(ChannelOpenedId, endpoint, reverse, refcount, participantCount); - } + private readonly ILogger m_logger; + } - [Event( - ChannelClosedId, - Message = "Channel closed. Endpoint={0}, Reason={1}, Refcount={2}, Participants={3}", - Level = EventLevel.Informational)] - public void ChannelClosed( - string endpoint, - string reason, - int refcount, - int participantCount) - { - WriteEvent(ChannelClosedId, endpoint, reason, refcount, participantCount); - } + /// + /// Source-generated compatibility log messages formerly emitted by Opc.Ua.ChannelManager EventSource. + /// + internal static partial class ClientChannelManagerDiagnosticsLog + { + [LoggerMessage( + EventId = CoreEventIds.ChannelManagerChannelOpened, + EventName = "ChannelOpened", + Level = LogLevel.Information, + Message = "Channel opened. Endpoint={Endpoint}, Reverse={Reverse}, " + + "Refcount={Refcount}, Participants={ParticipantCount}")] + public static partial void ChannelManagerChannelOpened( + this ILogger logger, + string endpoint, + bool reverse, + int refcount, + int participantCount); - [Event( - StateChangedId, - Message = "State changed. Endpoint={0}, Previous={1}, New={2}, Attempt={3}, Status={4}", - Level = EventLevel.Informational)] - public void StateChanged( - string endpoint, - string previousState, - string newState, - int reconnectAttempt, - string statusCode, - string errorMessage) - { - WriteEvent( - StateChangedId, - endpoint, - previousState, - newState, - reconnectAttempt, - statusCode, - errorMessage); - } + [LoggerMessage( + EventId = CoreEventIds.ChannelManagerChannelClosed, + EventName = "ChannelClosed", + Level = LogLevel.Information, + Message = "Channel closed. Endpoint={Endpoint}, Reason={Reason}, " + + "Refcount={Refcount}, Participants={ParticipantCount}")] + public static partial void ChannelManagerChannelClosed( + this ILogger logger, + string endpoint, + string reason, + int refcount, + int participantCount); - [Event( - ReconnectStartedId, - Message = "Reconnect started. Endpoint={0}, AttemptCount={1}", - Level = EventLevel.Informational)] - public void ReconnectStarted(string endpoint, int attemptCount) - { - WriteEvent(ReconnectStartedId, endpoint, attemptCount); - } + [LoggerMessage( + EventId = CoreEventIds.ChannelManagerStateChanged, + EventName = "StateChanged", + Level = LogLevel.Information, + Message = "State changed. Endpoint={Endpoint}, Previous={PreviousState}, New={NewState}, " + + "Attempt={ReconnectAttempt}, Status={StatusCode}, ErrorMessage={ErrorMessage}")] + public static partial void ChannelManagerStateChanged( + this ILogger logger, + string endpoint, + string previousState, + string newState, + int reconnectAttempt, + string statusCode, + string errorMessage); - [Event( - ReconnectCompletedId, - Message = "Reconnect completed. Endpoint={0}, AttemptCount={1}, Outcome={2}", - Level = EventLevel.Informational)] - public void ReconnectCompleted(string endpoint, int attemptCount, string outcome) - { - WriteEvent(ReconnectCompletedId, endpoint, attemptCount, outcome); - } + [LoggerMessage( + EventId = CoreEventIds.ChannelManagerReconnectStarted, + EventName = "ReconnectStarted", + Level = LogLevel.Information, + Message = "Reconnect started. Endpoint={Endpoint}, AttemptCount={AttemptCount}")] + public static partial void ChannelManagerReconnectStarted( + this ILogger logger, + string endpoint, + int attemptCount); - [Event( - ReconnectFailedId, - Message = "Reconnect failed. Endpoint={0}, Attempt={1}, Outcome={2}, Status={3}", - Level = EventLevel.Warning)] - public void ReconnectFailed( - string endpoint, - int attempt, - string outcome, - string statusCode, - string errorMessage) - { - WriteEvent( - ReconnectFailedId, - endpoint, - attempt, - outcome, - statusCode, - errorMessage); - } + [LoggerMessage( + EventId = CoreEventIds.ChannelManagerReconnectCompleted, + EventName = "ReconnectCompleted", + Level = LogLevel.Information, + Message = "Reconnect completed. Endpoint={Endpoint}, AttemptCount={AttemptCount}, Outcome={Outcome}")] + public static partial void ChannelManagerReconnectCompleted( + this ILogger logger, + string endpoint, + int attemptCount, + string outcome); - [Event( - ParticipantAttachedId, - Message = "Participant attached. Endpoint={0}, Participant={1}, Refcount={2}, Participants={3}", - Level = EventLevel.Informational)] - public void ParticipantAttached( - string endpoint, - string participantId, - int refcount, - int participantCount) - { - WriteEvent(ParticipantAttachedId, endpoint, participantId, refcount, participantCount); - } + [LoggerMessage( + EventId = CoreEventIds.ChannelManagerReconnectFailed, + EventName = "ReconnectFailed", + Level = LogLevel.Warning, + Message = "Reconnect failed. Endpoint={Endpoint}, Attempt={Attempt}, Outcome={Outcome}, " + + "Status={StatusCode}, ErrorMessage={ErrorMessage}")] + public static partial void ChannelManagerReconnectFailed( + this ILogger logger, + string endpoint, + int attempt, + string outcome, + string statusCode, + string errorMessage); - [Event( - ParticipantDetachedId, - Message = "Participant detached. Endpoint={0}, Participant={1}, Refcount={2}, Participants={3}", - Level = EventLevel.Informational)] - public void ParticipantDetached( - string endpoint, - string participantId, - int refcount, - int participantCount) - { - WriteEvent(ParticipantDetachedId, endpoint, participantId, refcount, participantCount); - } - } + [LoggerMessage( + EventId = CoreEventIds.ChannelManagerParticipantAttached, + EventName = "ParticipantAttached", + Level = LogLevel.Information, + Message = "Participant attached. Endpoint={Endpoint}, Participant={ParticipantId}, " + + "Refcount={Refcount}, Participants={ParticipantCount}")] + public static partial void ChannelManagerParticipantAttached( + this ILogger logger, + string endpoint, + string participantId, + int refcount, + int participantCount); - private static readonly ActivitySource s_activitySource = new(kChannelManagerDiagnosticsName); - private static readonly ChannelManagerEventSource s_eventSource = new(); + [LoggerMessage( + EventId = CoreEventIds.ChannelManagerParticipantDetached, + EventName = "ParticipantDetached", + Level = LogLevel.Information, + Message = "Participant detached. Endpoint={Endpoint}, Participant={ParticipantId}, " + + "Refcount={Refcount}, Participants={ParticipantCount}")] + public static partial void ChannelManagerParticipantDetached( + this ILogger logger, + string endpoint, + string participantId, + int refcount, + int participantCount); } } diff --git a/src/Opc.Ua.Core/Stack/Client/Channels/Internal/ClientChannelManagerMetrics.cs b/src/Opc.Ua.Core/Stack/Client/Channels/Internal/ClientChannelManagerMetrics.cs index e8c2a89c38..1505e85495 100644 --- a/src/Opc.Ua.Core/Stack/Client/Channels/Internal/ClientChannelManagerMetrics.cs +++ b/src/Opc.Ua.Core/Stack/Client/Channels/Internal/ClientChannelManagerMetrics.cs @@ -188,7 +188,7 @@ private static TagList CreateEndpointParticipantSuccessTags( /// tag at per-kind cardinality instead of accumulating one /// permanent time-series per participant instance in metric /// backends. The full per-instance ID is preserved on Activity - /// tags and EventSource events for correlation. + /// tags and structured channel-manager logs for correlation. /// private static string GetParticipantKind(string participantId) { diff --git a/src/Opc.Ua.Core/Stack/Client/ClientBase.cs b/src/Opc.Ua.Core/Stack/Client/ClientBase.cs index a1e524d554..2a3e4f3d99 100644 --- a/src/Opc.Ua.Core/Stack/Client/ClientBase.cs +++ b/src/Opc.Ua.Core/Stack/Client/ClientBase.cs @@ -51,6 +51,7 @@ public class ClientBase : IClientBase public ClientBase(ITransportChannel channel, ITelemetryContext telemetry) { m_logger = telemetry.CreateLogger(); + m_eventLogger = telemetry.CreateLogger(CoreEventIds.CoreCompatibilityCategory); m_meter = telemetry.CreateMeter(); if (channel == null) @@ -389,11 +390,7 @@ protected virtual void UpdateRequestHeader( if ((ActivityTraceFlags & ClientTraceFlags.Log) != 0) { - m_logger.ClientBaseLogMessage0(serviceName, request.RequestHeader.RequestHandle); - } - if ((ActivityTraceFlags & ClientTraceFlags.EventLog) != 0) - { - Utils.EventLog.ServiceCallStart( + m_eventLogger.CoreServiceCallStart( serviceName, (int)request.RequestHeader.RequestHandle, incrementedCount); @@ -491,33 +488,18 @@ protected virtual void RequestCompleted( var timestamp = (DateTime?)request?.RequestHeader?.Timestamp; TimeSpan? duration = timestamp != null ? DateTime.UtcNow - timestamp.Value : null; if ((ActivityTraceFlags & ClientTraceFlags.Log) != 0) - { - if (ServiceResult.IsGood(statusCode)) - { - m_logger.ClientBaseLogMessage1(serviceName, requestHandle, duration); - } - else - { - m_logger.ClientBaseLogMessage2( - serviceName, - requestHandle, - statusCode, - duration); - } - } - if ((ActivityTraceFlags & ClientTraceFlags.EventLog) != 0) { if (statusCode != StatusCodes.Good) { - Utils.EventLog.ServiceCallBadStop( + m_eventLogger.CoreServiceCallBadStop( serviceName, (int)requestHandle, - (int)statusCode.Code, - pendingRequestCount); + pendingRequestCount, + (int)statusCode.Code); } else { - Utils.EventLog.ServiceCallStop( + m_eventLogger.CoreServiceCallStop( serviceName, (int)requestHandle, pendingRequestCount); @@ -843,6 +825,7 @@ private Histogram GetDurationInstrument(Meter meter) #pragma warning disable IDE1006 // Naming Styles protected readonly ILogger m_logger; #pragma warning restore IDE1006 // Naming Styles + private readonly ILogger m_eventLogger; private readonly Meter m_meter; private ITransportChannel? m_channel; private readonly ConcurrentDictionary> m_instruments = []; @@ -875,12 +858,7 @@ public enum ClientTraceFlags /// /// Write the activity as a record to the log /// - Log = 0x4, - - /// - /// Write activity to event log (legacy) - /// - EventLog = 0x10 + Log = 0x4 } /// @@ -888,29 +866,41 @@ public enum ClientTraceFlags /// internal static partial class ClientBaseLog { - [LoggerMessage(EventId = CoreEventIds.ClientBase + 0, Level = LogLevel.Information, - Message = "{Activity}#{Handle} started...")] - public static partial void ClientBaseLogMessage0( + [LoggerMessage( + EventId = CoreEventIds.CoreServiceCallStart, + EventName = "ServiceCallStart", + Level = LogLevel.Trace, + Message = "{ServiceName} Called. RequestHandle={RequestHandle}, PendingRequestCount={PendingRequestCount}")] + public static partial void CoreServiceCallStart( this ILogger logger, - string activity, - uint handle); - - [LoggerMessage(EventId = CoreEventIds.ClientBase + 1, Level = LogLevel.Information, - Message = "{Activity}#{Handle} success received after {Elapsed}.")] - public static partial void ClientBaseLogMessage1( + string serviceName, + int requestHandle, + int pendingRequestCount); + + [LoggerMessage( + EventId = CoreEventIds.CoreServiceCallStop, + EventName = "ServiceCallStop", + Level = LogLevel.Trace, + Message = "{ServiceName} Completed. RequestHandle={RequestHandle}, " + + "PendingRequestCount={PendingRequestCount}")] + public static partial void CoreServiceCallStop( this ILogger logger, - string activity, - uint handle, - global::System.TimeSpan? elapsed); - - [LoggerMessage(EventId = CoreEventIds.ClientBase + 2, Level = LogLevel.Error, - Message = "{Activity}#{Handle} failed with {StatusCode} in {Elapsed}.")] - public static partial void ClientBaseLogMessage2( + string serviceName, + int requestHandle, + int pendingRequestCount); + + [LoggerMessage( + EventId = CoreEventIds.CoreServiceCallBadStop, + EventName = "ServiceCallBadStop", + Level = LogLevel.Warning, + Message = "{ServiceName} Completed. RequestHandle={RequestHandle}, " + + "PendingRequestCount={PendingRequestCount}, StatusCode={StatusCode}")] + public static partial void CoreServiceCallBadStop( this ILogger logger, - string activity, - uint handle, - global::Opc.Ua.StatusCode statusCode, - global::System.TimeSpan? elapsed); + string serviceName, + int requestHandle, + int pendingRequestCount, + int statusCode); } } diff --git a/src/Opc.Ua.Core/Stack/Tcp/TcpServerChannel.cs b/src/Opc.Ua.Core/Stack/Tcp/TcpServerChannel.cs index 8130740d08..08a905ad01 100644 --- a/src/Opc.Ua.Core/Stack/Tcp/TcpServerChannel.cs +++ b/src/Opc.Ua.Core/Stack/Tcp/TcpServerChannel.cs @@ -91,6 +91,7 @@ public TcpServerChannel( timeProvider) { m_logger = telemetry.CreateLogger(); + m_eventLogger = telemetry.CreateLogger(CoreEventIds.CoreCompatibilityCategory); m_queuedResponses = []; } @@ -1385,11 +1386,7 @@ public void SendResponse(uint requestId, IServiceResponse response) "Cannot send response over a closed channel."); } - Utils.EventLog.SendResponse((int)ChannelId, (int)requestId); - // trace logger: - // "ChannelId {ChannelId}: SendResponse {RequestId}", - // ChannelId, - // requestId); + m_eventLogger.CoreSendResponse((int)ChannelId, (int)requestId); BufferCollection? buffers = null; try @@ -1497,6 +1494,7 @@ private bool ValidateDiscoveryServiceCall( } private readonly ILogger m_logger; + private readonly ILogger m_eventLogger; private SortedDictionary m_queuedResponses; private ReverseConnectAsyncResult? m_pendingReverseHello; private byte[]? m_oscRequestSignature; @@ -1624,6 +1622,16 @@ public static partial void TcpServerLog17( this ILogger logger, global::System.Exception? exception); + [LoggerMessage( + EventId = CoreEventIds.CoreSendResponse, + EventName = "SendResponse", + Level = LogLevel.Trace, + Message = "ChannelId {ChannelId}: SendResponse {RequestId}")] + public static partial void CoreSendResponse( + this ILogger logger, + int channelId, + int requestId); + } } diff --git a/src/Opc.Ua.Core/Types/Utils/LoggerUtils.cs b/src/Opc.Ua.Core/Types/Utils/LoggerUtils.cs index 01f5f55e72..153ee26874 100644 --- a/src/Opc.Ua.Core/Types/Utils/LoggerUtils.cs +++ b/src/Opc.Ua.Core/Types/Utils/LoggerUtils.cs @@ -59,11 +59,6 @@ namespace Opc.Ua /// public static partial class Utils { - /// - /// The high performance EventSource log interface. - /// - internal static OpcUaCoreEventSource EventLog { get; } = new(); - /// /// Global default logger provider /// diff --git a/src/Opc.Ua.Core/Types/Utils/OpcUaCoreEventSource.cs b/src/Opc.Ua.Core/Types/Utils/OpcUaCoreEventSource.cs deleted file mode 100644 index 79103d12a9..0000000000 --- a/src/Opc.Ua.Core/Types/Utils/OpcUaCoreEventSource.cs +++ /dev/null @@ -1,137 +0,0 @@ -/* ======================================================================== - * Copyright (c) 2005-2025 The OPC Foundation, Inc. All rights reserved. - * - * OPC Foundation MIT License 1.00 - * - * Permission is hereby granted, free of charge, to any person - * obtaining a copy of this software and associated documentation - * files (the "Software"), to deal in the Software without - * restriction, including without limitation the rights to use, - * copy, modify, merge, publish, distribute, sublicense, and/or sell - * copies of the Software, and to permit persons to whom the - * Software is furnished to do so, subject to the following - * conditions: - * - * The above copyright notice and this permission notice shall be - * included in all copies or substantial portions of the Software. - * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, - * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES - * OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND - * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT - * HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, - * WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING - * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR - * OTHER DEALINGS IN THE SOFTWARE. - * - * The complete license agreement can be found here: - * http://opcfoundation.org/License/MIT/1.00/ - * ======================================================================*/ - -using System.Diagnostics.Tracing; - -namespace Opc.Ua -{ - /// - /// Event source for high performance logging. - /// - [EventSource(Name = "OPC-UA-Core", Guid = "753029BC-A4AA-4440-8668-290D0692A72B")] - internal sealed class OpcUaCoreEventSource : EventSource - { - /// - /// The core event ids. - /// - internal const int ServiceCallStartId = 10; - internal const int ServiceCallStopId = ServiceCallStartId + 1; - internal const int ServiceCallBadStopId = ServiceCallStopId + 1; - internal const int SubscriptionStateId = ServiceCallBadStopId + 1; - internal const int SendResponseId = SubscriptionStateId + 1; - - /// - /// The task definitions. - /// - public static class Tasks - { - /// - /// Service Call Activity. - /// - public const EventTask ServiceCallTask = (EventTask)1; - } - - /// - /// The keywords for message filters. - /// - public static class Keywords - { - /// - /// Services events. - /// - public const EventKeywords Services = (EventKeywords)2; - } - - /// - /// A server service call message. - /// - [Event( - ServiceCallStartId, - Keywords = Keywords.Services, - Message = "{0} Called. RequestHandle={1}, PendingRequestCount={2}", - Level = EventLevel.Verbose, - Task = Tasks.ServiceCallTask - )] - public void ServiceCallStart(string serviceName, int requestHandle, int pendingRequestCount) - { - WriteEvent(ServiceCallStartId, serviceName, requestHandle, pendingRequestCount); - } - - /// - /// The server service completed message. - /// - [Event( - ServiceCallStopId, - Keywords = Keywords.Services, - Message = "{0} Completed. RequestHandle={1}, PendingRequestCount={2}", - Level = EventLevel.Verbose, - Task = Tasks.ServiceCallTask - )] - public void ServiceCallStop(string serviceName, int requestHandle, int pendingRequestCount) - { - WriteEvent(ServiceCallStopId, serviceName, requestHandle, pendingRequestCount); - } - - /// - /// A service message completed with a bad status code. - /// - [Event( - ServiceCallBadStopId, - Keywords = Keywords.Services, - Message = "{0} Completed. RequestHandle={1}, PendingRequestCount={2}, StatusCode={3}", - Level = EventLevel.Warning, - Task = Tasks.ServiceCallTask - )] - public void ServiceCallBadStop( - string serviceName, - int requestHandle, - int statusCode, - int pendingRequestCount) - { - WriteEvent( - ServiceCallBadStopId, - serviceName, - requestHandle, - pendingRequestCount, - statusCode); - } - - /// - /// The send response of a server channel. - /// - [Event( - SendResponseId, - Message = "ChannelId {0}: SendResponse {1}", - Level = EventLevel.Verbose)] - public void SendResponse(int channelId, int requestId) - { - WriteEvent(SendResponseId, channelId, requestId); - } - } -} diff --git a/src/Opc.Ua.Server/EventIds.cs b/src/Opc.Ua.Server/EventIds.cs index bf1c33386b..75fa74719c 100644 --- a/src/Opc.Ua.Server/EventIds.cs +++ b/src/Opc.Ua.Server/EventIds.cs @@ -82,4 +82,23 @@ internal static class ServerEventIds public const int TrustList = 540; public const int UserManagementBinding = 550; } + + /// + /// Retained event ids for the removed "OPC-UA-Server" EventSource provider. + /// + /// + /// See docs/DeveloperGuide.md, "Narrow exception: retained EventSource-compatibility + /// ids". These are the literal legacy numeric ids, scoped to the "OPC-UA-Server" + /// category, so they intentionally + /// overlap the ordinary per-class offsets in above. Id 1 + /// (the legacy SendResponse event) was never implemented by the provider and is + /// intentionally left unused. + /// + internal static class ServerCompatibilityEventIds + { + public const string CategoryName = "OPC-UA-Server"; + public const int ServerCall = 2; + public const int SessionState = 3; + public const int MonitoredItemReady = 4; + } } diff --git a/src/Opc.Ua.Server/Server/OpcUaServerEventSource.cs b/src/Opc.Ua.Server/Server/OpcUaServerEventSource.cs deleted file mode 100644 index 1eed0e188a..0000000000 --- a/src/Opc.Ua.Server/Server/OpcUaServerEventSource.cs +++ /dev/null @@ -1,115 +0,0 @@ -/* ======================================================================== - * Copyright (c) 2005-2025 The OPC Foundation, Inc. All rights reserved. - * - * OPC Foundation MIT License 1.00 - * - * Permission is hereby granted, free of charge, to any person - * obtaining a copy of this software and associated documentation - * files (the "Software"), to deal in the Software without - * restriction, including without limitation the rights to use, - * copy, modify, merge, publish, distribute, sublicense, and/or sell - * copies of the Software, and to permit persons to whom the - * Software is furnished to do so, subject to the following - * conditions: - * - * The above copyright notice and this permission notice shall be - * included in all copies or substantial portions of the Software. - * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, - * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES - * OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND - * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT - * HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, - * WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING - * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR - * OTHER DEALINGS IN THE SOFTWARE. - * - * The complete license agreement can be found here: - * http://opcfoundation.org/License/MIT/1.00/ - * ======================================================================*/ - -using System.Diagnostics.Tracing; - -namespace Opc.Ua.Server -{ - /// - /// The local EventSource for the server library. - /// - public static partial class ServerUtils - { - /// - /// The EventSource log interface. - /// - internal static OpcUaServerEventSource EventLog { get; } = new OpcUaServerEventSource(); - } - - /// - /// Event source for high performance logging. - /// - [EventSource(Name = "OPC-UA-Server", Guid = "86FF2AAB-8FF6-46CB-8CE3-E0211950B30C")] - internal sealed class OpcUaServerEventSource : EventSource - { - /// - /// client event ids - /// - private const int kSendResponseId = 1; - private const int kServerCallId = kSendResponseId + 1; - private const int kSessionStateId = kServerCallId + 1; - private const int kMonitoredItemReadyId = kSessionStateId + 1; - - /// - /// A server call message, called from ServerCallNative. Do not call directly.. - /// - [Event( - kServerCallId, - Message = "Server Call={0}, Id={1}", - Level = EventLevel.Informational)] - public void ServerCall(string requestType, uint requestId) - { - if (IsEnabled()) - { - WriteEvent(kServerCallId, requestType, requestId); - } - } - - /// - /// The state of the session. - /// - [Event( - kSessionStateId, - Message = "Session {0}, Id={1}, Name={2}, ChannelId={3}, User={4}", - Level = EventLevel.Informational)] - public void SessionState( - string context, - string sessionId, - string sessionName, - string secureChannelId, - string identity) - { - if (IsEnabled()) - { - WriteEvent( - kSessionStateId, - context, - sessionId, - sessionName, - secureChannelId, - identity); - } - } - - /// - /// The state of the server session. - /// - [Event( - kMonitoredItemReadyId, - Message = "IsReadyToPublish[{0}] {1}", - Level = EventLevel.Verbose)] - public void MonitoredItemReady(uint id, string state) - { - if (IsEnabled()) - { - WriteEvent(kMonitoredItemReadyId, id, state); - } - } - } -} diff --git a/src/Opc.Ua.Server/Server/StandardServer.cs b/src/Opc.Ua.Server/Server/StandardServer.cs index b35b05fe63..8335712d7a 100644 --- a/src/Opc.Ua.Server/Server/StandardServer.cs +++ b/src/Opc.Ua.Server/Server/StandardServer.cs @@ -64,6 +64,8 @@ public StandardServer(ITelemetryContext telemetry, TimeProvider? timeProvider) : base(telemetry) { TimeProvider = timeProvider ?? TimeProvider.System; + m_eventLogger = telemetry.CreateLogger( + ServerCompatibilityEventIds.CategoryName); } /// @@ -3029,16 +3031,15 @@ protected virtual async ValueTask ValidateRequestAsync( OperationContext context = await ServerInternal.SessionManager .ValidateRequestAsync(requestHeader, secureChannelContext, requestType, requestLifetime).ConfigureAwait(false); - if (ServerUtils.EventLog.IsEnabled()) + if (m_eventLogger.IsEventLogEnabled()) { string? requestTypeString = Enum.GetName( #if !NET8_0_OR_GREATER typeof(RequestType), #endif context.RequestType); - ServerUtils.EventLog.ServerCall(requestTypeString!, context.RequestId); + m_eventLogger.CompatibilityServerCall(requestTypeString!, context.RequestId); } - m_logger.ServerCallRequestTypeIdRequestId(context.RequestType, context.RequestId); // notify the request manager. ServerInternal.RequestManager.RequestReceived(context); @@ -4519,6 +4520,7 @@ private OperationLimitsState OperationLimits private ServerRateLimitOptions? m_rateLimitOptions; private IServerRateLimiterProvider? m_rateLimiterProvider; private bool m_ownsRateLimiterProvider; + private readonly ILogger m_eventLogger; /// /// The interval at which the @@ -4643,11 +4645,14 @@ public static partial void RegisterServerFailedTryingAgainInRegistrationInterval Message = "Server - Enter {State} state.")] public static partial void ServerEnterStateState(this ILogger logger, ServerState state); - [LoggerMessage(EventId = ServerEventIds.StandardServer + 12, Level = LogLevel.Trace, + [LoggerMessage( + EventId = ServerCompatibilityEventIds.ServerCall, + EventName = "ServerCall", + Level = LogLevel.Information, Message = "Server Call={RequestType}, Id={RequestId}")] - public static partial void ServerCallRequestTypeIdRequestId( + public static partial void CompatibilityServerCall( this ILogger logger, - RequestType requestType, + string requestType, uint requestId); [LoggerMessage(EventId = ServerEventIds.StandardServer + 13, Level = LogLevel.Error, diff --git a/src/Opc.Ua.Server/ServerUtils.cs b/src/Opc.Ua.Server/ServerUtils.cs index e6809f414e..cbee8dc491 100644 --- a/src/Opc.Ua.Server/ServerUtils.cs +++ b/src/Opc.Ua.Server/ServerUtils.cs @@ -510,5 +510,18 @@ public static DiagnosticInfo CreateDiagnosticInfo( context.StringTable, logger); } + + /// + /// Returns whether compatibility logging for the retired + /// "OPC-UA-Server" EventSource provider is enabled. + /// + /// + /// Requiring the Trace log level keeps these events opt-in even + /// when their retained legacy record level is Information. + /// + internal static bool IsEventLogEnabled(this ILogger eventLogger) + { + return eventLogger.IsEnabled(LogLevel.Trace); + } } } diff --git a/src/Opc.Ua.Server/Session/Session.cs b/src/Opc.Ua.Server/Session/Session.cs index bfe2fcaa82..01849c29de 100644 --- a/src/Opc.Ua.Server/Session/Session.cs +++ b/src/Opc.Ua.Server/Session/Session.cs @@ -151,6 +151,8 @@ public Session( ?? (server as ITimeProviderProvider)?.TimeProvider ?? TimeProvider.System; m_logger = server.Telemetry.CreateLogger(); + m_eventLogger = server.Telemetry.CreateLogger( + ServerCompatibilityEventIds.CategoryName); ClientNonce = clientNonce; m_serverNonce = serverNonce; m_sessionName = sessionName; @@ -814,17 +816,14 @@ public ValueTask LoadMirroredContinuationPointsAsync( /// internal void TraceState(string context) { - string sessionId = Id.ToString(); + if (!m_eventLogger.IsEventLogEnabled()) + { + return; + } - // Legacy event source logging - ServerUtils.EventLog.SessionState( - context, - sessionId, - m_sessionName, - SecureChannelId, - Identity?.DisplayName ?? "(none)"); + string sessionId = Id.ToString(); - m_logger.SessionContextIdSessionIdNameNameChannelId( + m_eventLogger.CompatibilitySessionState( context, sessionId, m_sessionName, @@ -1321,6 +1320,7 @@ private void UpdateDiagnosticCounters( private readonly Lock m_lock = new(); private readonly ILogger m_logger; + private readonly ILogger m_eventLogger; private readonly IServerInternal m_server; private readonly TimeProvider m_timeProvider; private readonly string m_sessionName; @@ -1340,15 +1340,19 @@ private void UpdateDiagnosticCounters( /// internal static partial class SessionLog { - [LoggerMessage(EventId = ServerEventIds.Session + 0, Level = LogLevel.Information, - Message = "Session {Context}, Id={SessionId}, Name={Name}, ChannelId={ChannelId}, User={User}")] - public static partial void SessionContextIdSessionIdNameNameChannelId( + [LoggerMessage( + EventId = ServerCompatibilityEventIds.SessionState, + EventName = "SessionState", + Level = LogLevel.Information, + Message = "Session {Context}, Id={SessionId}, Name={SessionName}, ChannelId={SecureChannelId}, " + + "User={Identity}")] + public static partial void CompatibilitySessionState( this ILogger logger, string context, - string? sessionId, - string? name, - string channelId, - string? user); + string sessionId, + string sessionName, + string secureChannelId, + string identity); } } diff --git a/src/Opc.Ua.Server/Subscription/MonitoredItem/MonitoredItem.cs b/src/Opc.Ua.Server/Subscription/MonitoredItem/MonitoredItem.cs index 081c4d9001..ea43f1d41e 100644 --- a/src/Opc.Ua.Server/Subscription/MonitoredItem/MonitoredItem.cs +++ b/src/Opc.Ua.Server/Subscription/MonitoredItem/MonitoredItem.cs @@ -413,21 +413,18 @@ public bool IsReadyToPublish // check if not ready to publish in case it doesn't ResendData if (!m_readyToPublish) { - //ServerUtils.EventLog.MonitoredItemReady(Id, "FALSE"); return false; } // check if it has been triggered. if (MonitoringMode != MonitoringMode.Disabled && m_triggered) { - //ServerUtils.EventLog.MonitoredItemReady(Id, "TRIGGERED"); return true; } // check if monitoring was turned off. if (MonitoringMode != MonitoringMode.Reporting) { - //ServerUtils.EventLog.MonitoredItemReady(Id, "FALSE"); return false; } @@ -438,13 +435,9 @@ public bool IsReadyToPublish if (m_nextSamplingTime > now) { - //ServerUtils.EventLog.MonitoredItemReady( - // Id, - // Utils.Format("FALSE {0}ms", m_nextSamplingTime - now)); return false; } } - //ServerUtils.EventLog.MonitoredItemReady(Id, "NORMAL"); return true; } } @@ -2102,6 +2095,15 @@ public static partial void QUEUEVALUEMonitoredItemIdValueValueCODECode( Message = "MONITORED ITEM: Publish(QueueSize={QueueSize})")] public static partial void MONITOREDITEMPublishQueueSizeQueueSize(this ILogger logger, int queueSize); + [LoggerMessage( + EventId = ServerCompatibilityEventIds.MonitoredItemReady, + EventName = "MonitoredItemReady", + Level = LogLevel.Trace, + Message = "IsReadyToPublish[{Id}] {State}")] + public static partial void CompatibilityMonitoredItemReady( + this ILogger logger, + uint id, + string state); [LoggerMessage(EventId = ServerEventIds.MonitoredItem + 7, Level = LogLevel.Error, Message = "Failed to restore queue for monitored item with id {MonitoredItemId}")] diff --git a/tests/Opc.Ua.Client.Tests/OpcUaClientCompatibilityLoggingTests.cs b/tests/Opc.Ua.Client.Tests/OpcUaClientCompatibilityLoggingTests.cs new file mode 100644 index 0000000000..ca447fd46b --- /dev/null +++ b/tests/Opc.Ua.Client.Tests/OpcUaClientCompatibilityLoggingTests.cs @@ -0,0 +1,111 @@ +/* ======================================================================== + * Copyright (c) 2005-2026 The OPC Foundation, Inc. All rights reserved. + * + * OPC Foundation MIT License 1.00 + * + * Permission is hereby granted, free of charge, to any person + * obtaining a copy of this software and associated documentation + * files (the "Software"), to deal in the Software without + * restriction, including without limitation the rights to use, + * copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the + * Software is furnished to do so, subject to the following + * conditions: + * + * The above copyright notice and this permission notice shall be + * included in all copies or substantial portions of the Software. + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, + * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES + * OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND + * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT + * HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, + * WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR + * OTHER DEALINGS IN THE SOFTWARE. + * + * The complete license agreement can be found here: + * http://opcfoundation.org/License/MIT/1.00/ + * ======================================================================*/ + +using System; +using System.Linq; +using Microsoft.Extensions.Logging; +using NUnit.Framework; +using Opc.Ua.Tests; + +namespace Opc.Ua.Client.Tests +{ + [TestFixture] + [Category("Logging")] + [Parallelizable] + public sealed class OpcUaClientCompatibilityLoggingTests + { + [Test] + public void ClientEventsRetainLegacyContracts() + { + using var provider = new RecordingLoggerProvider(); + ITelemetryContext telemetry = DefaultTelemetry.Create( + builder => builder + .SetMinimumLevel(LogLevel.Trace) + .AddProvider(provider)); + ILogger logger = telemetry.CreateLogger(ClientEventIds.LegacyCategoryName); + var lastNotificationTime = new DateTime(2026, 7, 19, 8, 30, 0, DateTimeKind.Utc); + + logger.ClientEventSubscriptionState( + "Publishing", + 10, + lastNotificationTime, + 3, + 1000, + 5, + true, + 8); + logger.ClientEventNotification(42, "123"); + logger.ClientEventNotificationReceived(10, 11); + logger.ClientEventPublishStart(12); + logger.ClientEventPublishStop(12); + + RecordedLogRecord subscription = AssertRecord( + provider, + ClientEventIds.LegacySubscriptionStateId, + "SubscriptionState"); + Assert.That(subscription.Properties["Context"], Is.EqualTo("Publishing")); + Assert.That(subscription.Properties["Id"], Is.EqualTo(10u)); + Assert.That(subscription.Properties, Contains.Key("LastNotificationTime")); + Assert.That(subscription.Message, Does.Contain("08:30:00")); + Assert.That(subscription.Properties["CurrentPublishingInterval"], Is.EqualTo(1000d)); + Assert.That(subscription.Properties["CurrentKeepAliveCount"], Is.EqualTo(5u)); + Assert.That(subscription.Properties["CurrentPublishingEnabled"], Is.True); + + RecordedLogRecord notification = AssertRecord( + provider, + ClientEventIds.LegacyNotificationId, + "Notification"); + Assert.That(notification.Properties["ClientHandle"], Is.EqualTo(42)); + Assert.That(notification.Properties["Value"], Is.EqualTo("123")); + + RecordedLogRecord received = AssertRecord( + provider, + ClientEventIds.LegacyNotificationReceivedId, + "NotificationReceived"); + Assert.That(received.Properties["SubscriptionId"], Is.EqualTo(10)); + Assert.That(received.Properties["SequenceNumber"], Is.EqualTo(11)); + + AssertRecord(provider, ClientEventIds.LegacyPublishStartId, "PublishStart"); + AssertRecord(provider, ClientEventIds.LegacyPublishStopId, "PublishStop"); + } + + private static RecordedLogRecord AssertRecord( + RecordingLoggerProvider provider, + int eventId, + string eventName) + { + RecordedLogRecord record = provider.Records.Single(candidate => + candidate.CategoryName == ClientEventIds.LegacyCategoryName && + candidate.EventId.Id == eventId); + Assert.That(record.EventId.Name, Is.EqualTo(eventName)); + Assert.That(record.LogLevel, Is.EqualTo(LogLevel.Trace)); + return record; + } + } +} diff --git a/tests/Opc.Ua.Client.Tests/Stack/Client/ClientChannelManagerManagedTests.cs b/tests/Opc.Ua.Client.Tests/Stack/Client/ClientChannelManagerManagedTests.cs index d4ab6b7625..76561e031f 100644 --- a/tests/Opc.Ua.Client.Tests/Stack/Client/ClientChannelManagerManagedTests.cs +++ b/tests/Opc.Ua.Client.Tests/Stack/Client/ClientChannelManagerManagedTests.cs @@ -35,13 +35,13 @@ using System.Collections.Generic; using System.Diagnostics; using System.Diagnostics.Metrics; -using System.Diagnostics.Tracing; using System.Globalization; using System.Linq; using System.Reflection; using System.Text; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Time.Testing; using Moq; using NUnit.Framework; @@ -1146,10 +1146,11 @@ public async Task ActivitySpanIsRecordedForReconnectAsync() [Test] [NonParallelizable] - public async Task EventSourceFiresStateTransitionsAsync() + public async Task StructuredLogsCaptureStateTransitionsAsync() { - using var listener = new ChannelEventListener(); - ITelemetryContext telemetry = NUnitTelemetryContext.Create(); + using var loggerProvider = new RecordingLoggerProvider(); + ITelemetryContext telemetry = DefaultTelemetry.Create( + builder => builder.AddProvider(loggerProvider)); (ClientChannelManager sut, Certificate serverCert, Mock chMock) = CreateMockedSut(telemetry); try { @@ -1166,22 +1167,29 @@ public async Task EventSourceFiresStateTransitionsAsync() await sut.ReconnectAsync(ch, default).ConfigureAwait(false); ch.Dispose(); - // ch.Dispose() is non-blocking; the ParticipantDetached - // and ChannelClosed EventSource events fire from the - // background teardown task, so poll for them before the - // hard assertions. + // ch.Dispose() is non-blocking; teardown logs are emitted by + // the background cleanup task. await WaitForConditionAsync( - () => listener.EventNames.Contains("ParticipantDetached") && - listener.EventNames.Contains("ChannelClosed"), + () => loggerProvider.Records.Any(record => + record.EventId.Name == "ParticipantDetached") && + loggerProvider.Records.Any(record => + record.EventId.Name == "ChannelClosed"), "ParticipantDetached + ChannelClosed events").ConfigureAwait(false); - Assert.That(listener.EventNames, Does.Contain("StateChanged"), listener.FormatEvents()); - Assert.That(listener.EventNames, Does.Contain("ReconnectStarted"), listener.FormatEvents()); - Assert.That(listener.EventNames, Does.Contain("ReconnectCompleted"), listener.FormatEvents()); - Assert.That(listener.EventNames, Does.Contain("ParticipantAttached"), listener.FormatEvents()); - Assert.That(listener.EventNames, Does.Contain("ParticipantDetached"), listener.FormatEvents()); - Assert.That(listener.EventNames, Does.Contain("ChannelOpened"), listener.FormatEvents()); - Assert.That(listener.EventNames, Does.Contain("ChannelClosed"), listener.FormatEvents()); + RecordedLogRecord[] records = loggerProvider.Records + .Where(record => record.CategoryName == "Opc.Ua.ChannelManager") + .ToArray(); + string formatted = string.Join( + Environment.NewLine, + records.Select(record => $"{record.EventId.Name} {record.Message}")); + string?[] eventNames = records.Select(record => record.EventId.Name).ToArray(); + Assert.That(eventNames, Does.Contain("StateChanged"), formatted); + Assert.That(eventNames, Does.Contain("ReconnectStarted"), formatted); + Assert.That(eventNames, Does.Contain("ReconnectCompleted"), formatted); + Assert.That(eventNames, Does.Contain("ParticipantAttached"), formatted); + Assert.That(eventNames, Does.Contain("ParticipantDetached"), formatted); + Assert.That(eventNames, Does.Contain("ChannelOpened"), formatted); + Assert.That(eventNames, Does.Contain("ChannelClosed"), formatted); } finally { @@ -1323,7 +1331,7 @@ public async Task ReconnectAsyncSwapsFaultedLeaseEntryAsync() [Test] public async Task ReconnectAsyncWithBudgetShrinksDelayToFitRemainingAsync() { - var timeProvider = new FakeTimeProvider(); + var timeProvider = new ObservableFakeTimeProvider(); var reconnectPolicy = new ExponentialBackoffChannelReconnectPolicy { MinDelay = TimeSpan.FromSeconds(10), @@ -1349,6 +1357,9 @@ public async Task ReconnectAsyncWithBudgetShrinksDelayToFitRemainingAsync() Task reconnectTask = sut.ReconnectAsync(ch, budget, default).AsTask(); await reconnecting.Task.WaitAsync(TimeSpan.FromSeconds(5)).ConfigureAwait(false); + await timeProvider.WaitForTimerCreatedAsync(1) + .WaitAsync(TimeSpan.FromSeconds(5)) + .ConfigureAwait(false); Assert.That(reconnectTask.IsCompleted, Is.False); @@ -1905,72 +1916,6 @@ public void Dispose() TaskCreationOptions.RunContinuationsAsynchronously); } - private sealed class ChannelEventListener : EventListener - { - public ConcurrentQueue Events { get; } = new(); - - public IEnumerable EventNames => Events.Select(e => e.Name); - - public string FormatEvents() - { - var builder = new StringBuilder(); - // ConcurrentQueue enumeration is snapshot-stable so it - // races safely with concurrent EventWritten callbacks - // arriving on the EventSource's worker thread. - foreach (ChannelEventRecord record in Events) - { - builder.Append(record.Name); - if (record.Payload.Count > 0) - { - builder.Append(' ') - .AppendJoin( - ", ", - record.Payload.Select(p => $"{p.Key}={p.Value}")); - } - builder.AppendLine(); - } - return builder.ToString(); - } - - protected override void OnEventSourceCreated(EventSource eventSource) - { - if (eventSource.Name == "Opc.Ua.ChannelManager") - { - EnableEvents(eventSource, EventLevel.LogAlways); - } - } - - protected override void OnEventWritten(EventWrittenEventArgs eventData) - { - string name = eventData.EventName ?? eventData.EventId.ToString(CultureInfo.InvariantCulture); - var payload = new Dictionary(); - IList? payloadValues = eventData.Payload; - IList? payloadNames = eventData.PayloadNames; - if (payloadValues != null) - { - for (int i = 0; i < payloadValues.Count; i++) - { - string key = payloadNames?[i] ?? i.ToString(CultureInfo.InvariantCulture); - payload[key] = payloadValues[i]; - } - } - Events.Enqueue(new ChannelEventRecord(name, payload)); - } - } - - private sealed class ChannelEventRecord - { - public ChannelEventRecord(string name, Dictionary payload) - { - Name = name; - Payload = payload; - } - - public string Name { get; } - - public Dictionary Payload { get; } - } - private sealed class ChannelMetricListener : IDisposable { public ChannelMetricListener() @@ -2123,5 +2068,43 @@ public ValueTask OnReconnectAsync( return new ValueTask(result); } } + + private sealed class ObservableFakeTimeProvider : FakeTimeProvider + { + public override ITimer CreateTimer( + TimerCallback callback, + object? state, + TimeSpan dueTime, + TimeSpan period) + { + ITimer timer = base.CreateTimer(callback, state, dueTime, period); + int timerNumber = Interlocked.Increment(ref m_timerCount); + if (timerNumber == 1) + { + m_firstTimerCreated.TrySetResult(true); + } + else if (timerNumber == 2) + { + m_secondTimerCreated.TrySetResult(true); + } + return timer; + } + + public Task WaitForTimerCreatedAsync(int timerNumber) + { + return timerNumber switch + { + 1 => m_firstTimerCreated.Task, + 2 => m_secondTimerCreated.Task, + _ => throw new ArgumentOutOfRangeException(nameof(timerNumber)) + }; + } + + private readonly TaskCompletionSource m_firstTimerCreated = new( + TaskCreationOptions.RunContinuationsAsynchronously); + private readonly TaskCompletionSource m_secondTimerCreated = new( + TaskCreationOptions.RunContinuationsAsynchronously); + private int m_timerCount; + } } } diff --git a/tests/Opc.Ua.Core.Tests/Stack/Client/ClientBaseTests.cs b/tests/Opc.Ua.Core.Tests/Stack/Client/ClientBaseTests.cs index db0e636b71..75ce6b6858 100644 --- a/tests/Opc.Ua.Core.Tests/Stack/Client/ClientBaseTests.cs +++ b/tests/Opc.Ua.Core.Tests/Stack/Client/ClientBaseTests.cs @@ -41,6 +41,7 @@ using Microsoft.Extensions.Logging; using Moq; using NUnit.Framework; +using Opc.Ua.Tests; namespace Opc.Ua.Core.Tests.Stack.Client { @@ -56,16 +57,18 @@ public class ClientBaseTests { private Mock? m_transportChannelMock; private Mock? m_messageContextMock; - private TestLoggerProvider? m_loggerProvider; + private RecordingLoggerProvider? m_loggerProvider; private TestMeterListener? m_meterListener; private ITelemetryContext? m_telemetry; [SetUp] public void SetUp() { - m_loggerProvider = new TestLoggerProvider(); + m_loggerProvider = new RecordingLoggerProvider(); m_telemetry = DefaultTelemetry.Create( - configure => configure.AddProvider(m_loggerProvider)); + configure => configure + .SetMinimumLevel(LogLevel.Trace) + .AddProvider(m_loggerProvider)); m_messageContextMock = new Mock(); m_messageContextMock .Setup(m => m.Telemetry) @@ -129,7 +132,7 @@ public void ActivityTraceFlags_None_ShouldNotRecordAnything() sut.TestRequestCompleted(request, response, "Read"); // Assert - Assert.That(m_loggerProvider!.LogEntries, Is.Empty); + Assert.That(m_loggerProvider!.Records, Is.Empty); Assert.That(m_meterListener!.RecordedMeasurements, Is.Empty); } @@ -168,8 +171,8 @@ public void ActivityTraceFlags_Metrics_ShouldRecordMetricsOnly() Assert.That(measurement.Value, Is.EqualTo(sw.Elapsed.TotalSeconds).Within(0.03)); // Assert - no logs should be recorded - Assert.That(m_loggerProvider!.LogEntries - .Count(e => e.Contains("Read", StringComparison.Ordinal)), Is.Zero); + Assert.That(m_loggerProvider!.Records + .Count(record => record.Message.Contains("Read", StringComparison.Ordinal)), Is.Zero); } [Test] @@ -193,14 +196,16 @@ public void ActivityTraceFlags_Log_ShouldRecordLogsOnly() sut.TestUpdateRequestHeader(request, true, "Read"); sut.TestRequestCompleted(request, response, "Read"); - // Assert - logs should be recorded - Assert.That(m_loggerProvider!.LogEntries, Has.Count.GreaterThan(0)); - Assert.That(m_loggerProvider.LogEntries.Any(e => - e.Contains("Read", StringComparison.Ordinal) && - e.Contains("started", StringComparison.Ordinal)), Is.True); - Assert.That(m_loggerProvider.LogEntries.Any(e => - e.Contains("Read", StringComparison.Ordinal) && - e.Contains("success", StringComparison.Ordinal)), Is.True); + // Assert - compatibility logs should be recorded + Assert.That(m_loggerProvider!.Records, Has.Count.EqualTo(2)); + Assert.That(m_loggerProvider.Records.Any(record => + record.CategoryName == CoreEventIds.CoreCompatibilityCategory && + record.EventId.Id == CoreEventIds.CoreServiceCallStart && + record.EventId.Name == "ServiceCallStart"), Is.True); + Assert.That(m_loggerProvider.Records.Any(record => + record.CategoryName == CoreEventIds.CoreCompatibilityCategory && + record.EventId.Id == CoreEventIds.CoreServiceCallStop && + record.EventId.Name == "ServiceCallStop"), Is.True); // Assert - no metrics should be recorded Assert.That(m_meterListener!.RecordedMeasurements, Is.Empty); @@ -250,31 +255,6 @@ public void ActivityTraceFlags_Traces_ShouldAddActivityEvents() activityListener.Dispose(); } - [Test] - public void ActivityTraceFlags_EventLog_ShouldLogToEventLog() - { - // Arrange - using var sut = new TestableClientBase(m_transportChannelMock!.Object, m_telemetry!); - sut.ActivityTraceFlags = ClientTraceFlags.EventLog; - - var request = new ReadRequest { RequestHeader = new RequestHeader() }; - var response = new ReadResponse - { - ResponseHeader = new ResponseHeader - { - RequestHandle = request.RequestHeader.RequestHandle, - ServiceResult = StatusCodes.Good - } - }; - - // Act - sut.TestUpdateRequestHeader(request, true, "Read"); - sut.TestRequestCompleted(request, response, "Read"); - - // Assert - EventLog calls are not easily testable, but we ensure no exceptions are thrown - Assert.Pass("EventLog flag processed without exceptions"); - } - [Test] public void ActivityTraceFlags_MetricsAndLog_ShouldRecordBoth() { @@ -301,7 +281,7 @@ public void ActivityTraceFlags_MetricsAndLog_ShouldRecordBoth() // Assert - both metrics and logs should be recorded Assert.That(m_meterListener.RecordedMeasurements, Is.Not.Empty); - Assert.That(m_loggerProvider!.LogEntries, Is.Not.Empty); + Assert.That(m_loggerProvider!.Records, Is.Not.Empty); } [Test] @@ -346,8 +326,7 @@ public void ActivityTraceFlags_AllFlags_ShouldRecordEverything() sut.ActivityTraceFlags = ClientTraceFlags.Metrics | ClientTraceFlags.Traces | - ClientTraceFlags.Log | - ClientTraceFlags.EventLog; + ClientTraceFlags.Log; var request = new ReadRequest { RequestHeader = new RequestHeader() }; var response = new ReadResponse @@ -371,7 +350,7 @@ public void ActivityTraceFlags_AllFlags_ShouldRecordEverything() } // Assert - all should be recorded Assert.That(m_meterListener.RecordedMeasurements, Is.Not.Empty); - Assert.That(m_loggerProvider!.LogEntries, Is.Not.Empty); + Assert.That(m_loggerProvider!.Records, Is.Not.Empty); Assert.That(activityListener.RecordedEvents, Is.Not.Empty); activityListener.Dispose(); @@ -399,9 +378,13 @@ public void RequestCompleted_WithBadStatusCode_ShouldLogError() sut.TestRequestCompleted(request, response, "Read"); // Assert - Assert.That(m_loggerProvider!.LogEntries.Any(e => - e.Contains("failed", StringComparison.Ordinal) && - e.Contains("BadTimeout", StringComparison.Ordinal)), Is.True); + RecordedLogRecord record = m_loggerProvider!.Records.Single(candidate => + candidate.CategoryName == CoreEventIds.CoreCompatibilityCategory && + candidate.EventId.Id == CoreEventIds.CoreServiceCallBadStop); + Assert.That(record.EventId.Name, Is.EqualTo("ServiceCallBadStop")); + Assert.That( + record.Properties["StatusCode"], + Is.EqualTo(unchecked((int)StatusCodes.BadTimeout.Code))); } [Test] @@ -534,53 +517,6 @@ public static void TestValidateResponse(ResponseHeader header) .GetValue(this); } - /// - /// Test logger provider for capturing log entries. - /// - private sealed class TestLoggerProvider : ILoggerProvider - { - public List LogEntries { get; } = []; - - public ILogger CreateLogger(string categoryName) - { - return new TestLogger(this); - } - - public void Dispose() - { - } - - private sealed class TestLogger : ILogger - { - private readonly TestLoggerProvider m_provider; - - public TestLogger(TestLoggerProvider provider) - { - m_provider = provider; - } - - 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) - { - m_provider.LogEntries.Add(formatter(state, exception)); - } - } - } - /// /// Test meter listener for capturing recorded measurements. /// diff --git a/tests/Opc.Ua.Core.Tests/Stack/Client/ClientChannelManagerManagedTests.cs b/tests/Opc.Ua.Core.Tests/Stack/Client/ClientChannelManagerManagedTests.cs index 9d4f8cdbac..6541089c9f 100644 --- a/tests/Opc.Ua.Core.Tests/Stack/Client/ClientChannelManagerManagedTests.cs +++ b/tests/Opc.Ua.Core.Tests/Stack/Client/ClientChannelManagerManagedTests.cs @@ -35,13 +35,13 @@ using System.Collections.Generic; using System.Diagnostics; using System.Diagnostics.Metrics; -using System.Diagnostics.Tracing; using System.Globalization; using System.Linq; using System.Reflection; using System.Text; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Time.Testing; using Moq; using NUnit.Framework; @@ -835,10 +835,11 @@ public async Task ActivitySpanIsRecordedForReconnectAsync() [Test] [NonParallelizable] - public async Task EventSourceFiresStateTransitionsAsync() + public async Task StructuredLogsCaptureStateTransitionsAsync() { - using var listener = new ChannelEventListener(); - ITelemetryContext telemetry = NUnitTelemetryContext.Create(); + using var loggerProvider = new RecordingLoggerProvider(); + ITelemetryContext telemetry = DefaultTelemetry.Create( + builder => builder.AddProvider(loggerProvider)); (ClientChannelManager sut, Certificate serverCert, Mock chMock) = CreateMockedSut(telemetry); try { @@ -855,22 +856,29 @@ public async Task EventSourceFiresStateTransitionsAsync() await sut.ReconnectAsync(ch, default).ConfigureAwait(false); ch.Dispose(); - // ch.Dispose() is non-blocking; the ParticipantDetached - // and ChannelClosed EventSource events fire from the - // background teardown task, so poll for them before the - // hard assertions. + // ch.Dispose() is non-blocking; teardown logs are emitted by + // the background cleanup task. await WaitForConditionAsync( - () => listener.EventNames.Contains("ParticipantDetached") && - listener.EventNames.Contains("ChannelClosed"), + () => loggerProvider.Records.Any(record => + record.EventId.Name == "ParticipantDetached") && + loggerProvider.Records.Any(record => + record.EventId.Name == "ChannelClosed"), "ParticipantDetached + ChannelClosed events").ConfigureAwait(false); - Assert.That(listener.EventNames, Does.Contain("StateChanged"), listener.FormatEvents()); - Assert.That(listener.EventNames, Does.Contain("ReconnectStarted"), listener.FormatEvents()); - Assert.That(listener.EventNames, Does.Contain("ReconnectCompleted"), listener.FormatEvents()); - Assert.That(listener.EventNames, Does.Contain("ParticipantAttached"), listener.FormatEvents()); - Assert.That(listener.EventNames, Does.Contain("ParticipantDetached"), listener.FormatEvents()); - Assert.That(listener.EventNames, Does.Contain("ChannelOpened"), listener.FormatEvents()); - Assert.That(listener.EventNames, Does.Contain("ChannelClosed"), listener.FormatEvents()); + RecordedLogRecord[] records = loggerProvider.Records + .Where(record => record.CategoryName == "Opc.Ua.ChannelManager") + .ToArray(); + string formatted = string.Join( + Environment.NewLine, + records.Select(record => $"{record.EventId.Name} {record.Message}")); + string?[] eventNames = records.Select(record => record.EventId.Name).ToArray(); + Assert.That(eventNames, Does.Contain("StateChanged"), formatted); + Assert.That(eventNames, Does.Contain("ReconnectStarted"), formatted); + Assert.That(eventNames, Does.Contain("ReconnectCompleted"), formatted); + Assert.That(eventNames, Does.Contain("ParticipantAttached"), formatted); + Assert.That(eventNames, Does.Contain("ParticipantDetached"), formatted); + Assert.That(eventNames, Does.Contain("ChannelOpened"), formatted); + Assert.That(eventNames, Does.Contain("ChannelClosed"), formatted); } finally { @@ -913,8 +921,11 @@ public async Task GetChannelDiagnosticsReturnsSnapshot() } [Test] + [NonParallelizable] public async Task ReconnectAsyncWithBudgetStopsWhenExhaustedAsync() { + using var listener = new ChannelActivityListener(); + ITelemetryContext telemetry = NUnitTelemetryContext.Create(logLevel: LogLevel.Critical); var timeProvider = new FakeTimeProvider(); var reconnectPolicy = new ExponentialBackoffChannelReconnectPolicy { @@ -922,7 +933,7 @@ public async Task ReconnectAsyncWithBudgetStopsWhenExhaustedAsync() MaxDelay = TimeSpan.Zero }; (ClientChannelManager sut, Certificate serverCert, Mock chMock) = - CreateMockedSut(reconnectPolicy: reconnectPolicy, timeProvider: timeProvider); + CreateMockedSut(telemetry, reconnectPolicy, timeProvider); try { ConfiguredEndpoint endpoint = GetTestEndpoint(serverCert); @@ -936,6 +947,16 @@ public async Task ReconnectAsyncWithBudgetStopsWhenExhaustedAsync() Assert.That(ex, Is.Not.Null); Assert.That(ex!.StatusCode, Is.EqualTo(StatusCodes.BadSecureChannelClosed)); Assert.That(ch.State, Is.EqualTo(ChannelState.Faulted)); + Activity activity = await listener + .WaitForStoppedActivityAsync("OpcUaChannelReconnect") + .ConfigureAwait(false); + var tags = activity.TagObjects.ToDictionary(t => t.Key, t => t.Value); + Assert.That(tags["attempt.count"], Is.Zero); + Assert.That(tags["outcome"], Is.EqualTo("policy-exhausted")); + Assert.That(tags["error.status_code"], Is.EqualTo("BadSecureChannelClosed")); + Assert.That( + tags["error.message"], + Is.EqualTo("Channel reconnect policy exhausted after 0 attempts.")); chMock.Verify(c => c.ReconnectAsync( It.IsAny(), It.IsAny()), @@ -1033,7 +1054,7 @@ await timeProvider.WaitForTimerCreatedAsync(2) [Test] public async Task ReconnectAsyncWithBudgetShrinksDelayToFitRemainingAsync() { - var timeProvider = new FakeTimeProvider(); + var timeProvider = new ObservableFakeTimeProvider(); var reconnectPolicy = new ExponentialBackoffChannelReconnectPolicy { MinDelay = TimeSpan.FromSeconds(10), @@ -1059,6 +1080,9 @@ public async Task ReconnectAsyncWithBudgetShrinksDelayToFitRemainingAsync() Task reconnectTask = sut.ReconnectAsync(ch, budget, default).AsTask(); await reconnecting.Task.WaitAsync(TimeSpan.FromSeconds(5)).ConfigureAwait(false); + await timeProvider.WaitForTimerCreatedAsync(1) + .WaitAsync(TimeSpan.FromSeconds(5)) + .ConfigureAwait(false); Assert.That(reconnectTask.IsCompleted, Is.False); @@ -1259,72 +1283,6 @@ public void Dispose() TaskCreationOptions.RunContinuationsAsynchronously); } - private sealed class ChannelEventListener : EventListener - { - public ConcurrentQueue Events { get; } = new(); - - public IEnumerable EventNames => Events.Select(e => e.Name); - - public string FormatEvents() - { - var builder = new StringBuilder(); - // ConcurrentQueue enumeration is snapshot-stable so it - // races safely with concurrent EventWritten callbacks - // arriving on the EventSource's worker thread. - foreach (ChannelEventRecord record in Events) - { - builder.Append(record.Name); - if (record.Payload.Count > 0) - { - builder.Append(' '); - builder.Append(string.Join( - ", ", - record.Payload.Select(p => $"{p.Key}={p.Value}"))); - } - builder.AppendLine(); - } - return builder.ToString(); - } - - protected override void OnEventSourceCreated(EventSource eventSource) - { - if (eventSource.Name == "Opc.Ua.ChannelManager") - { - EnableEvents(eventSource, EventLevel.LogAlways); - } - } - - protected override void OnEventWritten(EventWrittenEventArgs eventData) - { - string name = eventData.EventName ?? eventData.EventId.ToString(CultureInfo.InvariantCulture); - var payload = new Dictionary(); - IList? payloadValues = eventData.Payload; - IList? payloadNames = eventData.PayloadNames; - if (payloadValues != null) - { - for (int i = 0; i < payloadValues.Count; i++) - { - string key = payloadNames?[i] ?? i.ToString(CultureInfo.InvariantCulture); - payload[key] = payloadValues[i]; - } - } - Events.Enqueue(new ChannelEventRecord(name, payload)); - } - } - - private sealed class ChannelEventRecord - { - public ChannelEventRecord(string name, Dictionary payload) - { - Name = name; - Payload = payload; - } - - public string Name { get; } - - public Dictionary Payload { get; } - } - private sealed class ChannelMetricListener : IDisposable { public ChannelMetricListener() diff --git a/tests/Opc.Ua.Core.Tests/Types/Utils/OpcUaCompatibilityLoggingTests.cs b/tests/Opc.Ua.Core.Tests/Types/Utils/OpcUaCompatibilityLoggingTests.cs new file mode 100644 index 0000000000..048409ee49 --- /dev/null +++ b/tests/Opc.Ua.Core.Tests/Types/Utils/OpcUaCompatibilityLoggingTests.cs @@ -0,0 +1,195 @@ +/* ======================================================================== + * Copyright (c) 2005-2026 The OPC Foundation, Inc. All rights reserved. + * + * OPC Foundation MIT License 1.00 + * + * Permission is hereby granted, free of charge, to any person + * obtaining a copy of this software and associated documentation + * files (the "Software"), to deal in the Software without + * restriction, including without limitation the rights to use, + * copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the + * Software is furnished to do so, subject to the following + * conditions: + * + * The above copyright notice and this permission notice shall be + * included in all copies or substantial portions of the Software. + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, + * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES + * OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND + * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT + * HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, + * WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR + * OTHER DEALINGS IN THE SOFTWARE. + * + * The complete license agreement can be found here: + * http://opcfoundation.org/License/MIT/1.00/ + * ======================================================================*/ + +using System; +using System.Linq; +using Microsoft.Extensions.Logging; +using NUnit.Framework; +using Opc.Ua.Bindings; +using Opc.Ua.Tests; + +namespace Opc.Ua.Core.Tests.Types.UtilsTests +{ + [TestFixture] + [Category("Logging")] + [Parallelizable] + public sealed class OpcUaCompatibilityLoggingTests + { + [Test] + public void CoreEventsRetainLegacyContracts() + { + using var provider = new RecordingLoggerProvider(); + ITelemetryContext telemetry = DefaultTelemetry.Create( + builder => builder + .SetMinimumLevel(LogLevel.Trace) + .AddProvider(provider)); + ILogger logger = telemetry.CreateLogger(CoreEventIds.CoreCompatibilityCategory); + + logger.CoreServiceCallStart("Read", 11, 2); + logger.CoreServiceCallStop("Read", 11, 1); + logger.CoreServiceCallBadStop("Write", 12, 3, 0x1234); + logger.CoreSendResponse(7, 99); + + RecordedLogRecord start = AssertRecord( + provider, + CoreEventIds.CoreCompatibilityCategory, + CoreEventIds.CoreServiceCallStart, + "ServiceCallStart", + LogLevel.Trace); + Assert.That(start.Properties["ServiceName"], Is.EqualTo("Read")); + Assert.That(start.Properties["RequestHandle"], Is.EqualTo(11)); + Assert.That(start.Properties["PendingRequestCount"], Is.EqualTo(2)); + + RecordedLogRecord stop = AssertRecord( + provider, + CoreEventIds.CoreCompatibilityCategory, + CoreEventIds.CoreServiceCallStop, + "ServiceCallStop", + LogLevel.Trace); + Assert.That(stop.Properties["PendingRequestCount"], Is.EqualTo(1)); + + RecordedLogRecord badStop = AssertRecord( + provider, + CoreEventIds.CoreCompatibilityCategory, + CoreEventIds.CoreServiceCallBadStop, + "ServiceCallBadStop", + LogLevel.Warning); + Assert.That(badStop.Properties["PendingRequestCount"], Is.EqualTo(3)); + Assert.That(badStop.Properties["StatusCode"], Is.EqualTo(0x1234)); + + RecordedLogRecord response = AssertRecord( + provider, + CoreEventIds.CoreCompatibilityCategory, + CoreEventIds.CoreSendResponse, + "SendResponse", + LogLevel.Trace); + Assert.That(response.Properties["ChannelId"], Is.EqualTo(7)); + Assert.That(response.Properties["RequestId"], Is.EqualTo(99)); + } + + [Test] + public void ChannelManagerEventsRetainLegacyContracts() + { + using var provider = new RecordingLoggerProvider(); + ITelemetryContext telemetry = DefaultTelemetry.Create( + builder => builder + .SetMinimumLevel(LogLevel.Trace) + .AddProvider(provider)); + ILogger logger = telemetry.CreateLogger(CoreEventIds.ChannelManagerCompatibilityCategory); + + logger.ChannelManagerChannelOpened("opc.tcp://server", true, 1, 2); + logger.ChannelManagerChannelClosed("opc.tcp://server", "faulted", 0, 0); + logger.ChannelManagerStateChanged( + "opc.tcp://server", + "Ready", + "Reconnecting", + 3, + "BadTimeout", + "Timed out"); + logger.ChannelManagerReconnectStarted("opc.tcp://server", 0); + logger.ChannelManagerReconnectCompleted("opc.tcp://server", 2, "success"); + logger.ChannelManagerReconnectFailed( + "opc.tcp://server", + 4, + "policy-exhausted", + "BadTimeout", + "Timed out"); + logger.ChannelManagerParticipantAttached("opc.tcp://server", "Session-1", 1, 1); + logger.ChannelManagerParticipantDetached("opc.tcp://server", "Session-1", 0, 0); + + AssertRecord( + provider, + CoreEventIds.ChannelManagerCompatibilityCategory, + CoreEventIds.ChannelManagerChannelOpened, + "ChannelOpened", + LogLevel.Information); + AssertRecord( + provider, + CoreEventIds.ChannelManagerCompatibilityCategory, + CoreEventIds.ChannelManagerChannelClosed, + "ChannelClosed", + LogLevel.Information); + RecordedLogRecord stateChanged = AssertRecord( + provider, + CoreEventIds.ChannelManagerCompatibilityCategory, + CoreEventIds.ChannelManagerStateChanged, + "StateChanged", + LogLevel.Information); + Assert.That(stateChanged.Properties["StatusCode"], Is.EqualTo("BadTimeout")); + Assert.That(stateChanged.Properties["ErrorMessage"], Is.EqualTo("Timed out")); + AssertRecord( + provider, + CoreEventIds.ChannelManagerCompatibilityCategory, + CoreEventIds.ChannelManagerReconnectStarted, + "ReconnectStarted", + LogLevel.Information); + AssertRecord( + provider, + CoreEventIds.ChannelManagerCompatibilityCategory, + CoreEventIds.ChannelManagerReconnectCompleted, + "ReconnectCompleted", + LogLevel.Information); + RecordedLogRecord reconnectFailed = AssertRecord( + provider, + CoreEventIds.ChannelManagerCompatibilityCategory, + CoreEventIds.ChannelManagerReconnectFailed, + "ReconnectFailed", + LogLevel.Warning); + Assert.That(reconnectFailed.Properties["StatusCode"], Is.EqualTo("BadTimeout")); + Assert.That(reconnectFailed.Properties["ErrorMessage"], Is.EqualTo("Timed out")); + AssertRecord( + provider, + CoreEventIds.ChannelManagerCompatibilityCategory, + CoreEventIds.ChannelManagerParticipantAttached, + "ParticipantAttached", + LogLevel.Information); + AssertRecord( + provider, + CoreEventIds.ChannelManagerCompatibilityCategory, + CoreEventIds.ChannelManagerParticipantDetached, + "ParticipantDetached", + LogLevel.Information); + } + + private static RecordedLogRecord AssertRecord( + RecordingLoggerProvider provider, + string categoryName, + int eventId, + string eventName, + LogLevel logLevel) + { + RecordedLogRecord record = provider.Records.Single(candidate => + candidate.CategoryName == categoryName && + candidate.EventId.Id == eventId); + Assert.That(record.EventId.Name, Is.EqualTo(eventName)); + Assert.That(record.LogLevel, Is.EqualTo(logLevel)); + return record; + } + } +} diff --git a/tests/Opc.Ua.Server.Tests/OpcUaServerCompatibilityLoggingTests.cs b/tests/Opc.Ua.Server.Tests/OpcUaServerCompatibilityLoggingTests.cs new file mode 100644 index 0000000000..0b5aa067c7 --- /dev/null +++ b/tests/Opc.Ua.Server.Tests/OpcUaServerCompatibilityLoggingTests.cs @@ -0,0 +1,120 @@ +/* ======================================================================== + * Copyright (c) 2005-2026 The OPC Foundation, Inc. All rights reserved. + * + * OPC Foundation MIT License 1.00 + * + * Permission is hereby granted, free of charge, to any person + * obtaining a copy of this software and associated documentation + * files (the "Software"), to deal in the Software without + * restriction, including without limitation the rights to use, + * copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the + * Software is furnished to do so, subject to the following + * conditions: + * + * The above copyright notice and this permission notice shall be + * included in all copies or substantial portions of the Software. + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, + * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES + * OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND + * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT + * HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, + * WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR + * OTHER DEALINGS IN THE SOFTWARE. + * + * The complete license agreement can be found here: + * http://opcfoundation.org/License/MIT/1.00/ + * ======================================================================*/ + +using System.Linq; +using Microsoft.Extensions.Logging; +using NUnit.Framework; +using Opc.Ua.Tests; + +namespace Opc.Ua.Server.Tests +{ + [TestFixture] + [Category("Logging")] + [Parallelizable] + public sealed class OpcUaServerCompatibilityLoggingTests + { + [Test] + public void ServerEventsRetainLegacyContracts() + { + using var provider = new RecordingLoggerProvider(); + ITelemetryContext telemetry = DefaultTelemetry.Create( + builder => builder + .SetMinimumLevel(LogLevel.Trace) + .AddProvider(provider)); + ILogger logger = telemetry.CreateLogger( + ServerCompatibilityEventIds.CategoryName); + + Assert.That(logger.IsEventLogEnabled(), Is.True); + + logger.CompatibilityServerCall("Browse", 99); + logger.CompatibilitySessionState("Activated", "sid", "sname", "chan", "ident"); + logger.CompatibilityMonitoredItemReady(123, "publishing"); + + RecordedLogRecord serverCall = AssertRecord( + provider, + ServerCompatibilityEventIds.ServerCall, + "ServerCall", + LogLevel.Information); + Assert.That(serverCall.Properties["RequestType"], Is.EqualTo("Browse")); + Assert.That(serverCall.Properties["RequestId"], Is.EqualTo(99u)); + + RecordedLogRecord sessionState = AssertRecord( + provider, + ServerCompatibilityEventIds.SessionState, + "SessionState", + LogLevel.Information); + Assert.That(sessionState.Properties["Context"], Is.EqualTo("Activated")); + Assert.That(sessionState.Properties["Identity"], Is.EqualTo("ident")); + + RecordedLogRecord monitoredItem = AssertRecord( + provider, + ServerCompatibilityEventIds.MonitoredItemReady, + "MonitoredItemReady", + LogLevel.Trace); + Assert.That(monitoredItem.Properties["Id"], Is.EqualTo(123u)); + Assert.That(monitoredItem.Properties["State"], Is.EqualTo("publishing")); + } + + [Test] + public void ServerEventsRemainDisabledAtInformationLevel() + { + using var provider = new RecordingLoggerProvider(); + ITelemetryContext telemetry = DefaultTelemetry.Create( + builder => builder + .SetMinimumLevel(LogLevel.Information) + .AddProvider(provider)); + ILogger logger = telemetry.CreateLogger( + ServerCompatibilityEventIds.CategoryName); + + Assert.That(logger.IsEventLogEnabled(), Is.False); + + if (logger.IsEventLogEnabled()) + { + logger.CompatibilityServerCall("Browse", 99); + logger.CompatibilitySessionState("Activated", "sid", "sname", "chan", "ident"); + } + + Assert.That(provider.Records, Is.Empty); + } + + private static RecordedLogRecord AssertRecord( + RecordingLoggerProvider provider, + int eventId, + string eventName, + LogLevel logLevel) + { + RecordedLogRecord record = provider.Records.Single(candidate => + candidate.CategoryName == ServerCompatibilityEventIds.CategoryName && + candidate.EventId.Id == eventId); + Assert.That(record.EventId.Name, Is.EqualTo(eventName)); + Assert.That(record.LogLevel, Is.EqualTo(logLevel)); + return record; + } + } +} diff --git a/tests/Opc.Ua.Server.Tests/OpcUaServerEventSourceTests.cs b/tests/Opc.Ua.Server.Tests/OpcUaServerEventSourceTests.cs deleted file mode 100644 index 0baa97bd22..0000000000 --- a/tests/Opc.Ua.Server.Tests/OpcUaServerEventSourceTests.cs +++ /dev/null @@ -1,139 +0,0 @@ -/* ======================================================================== - * Copyright (c) 2005-2025 The OPC Foundation, Inc. All rights reserved. - * - * OPC Foundation MIT License 1.00 - * - * Permission is hereby granted, free of charge, to any person - * obtaining a copy of this software and associated documentation - * files (the "Software"), to deal in the Software without - * restriction, including without limitation the rights to use, - * copy, modify, merge, publish, distribute, sublicense, and/or sell - * copies of the Software, and to permit persons to whom the - * Software is furnished to do so, subject to the following - * conditions: - * - * The above copyright notice and this permission notice shall be - * included in all copies or substantial portions of the Software. - * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, - * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES - * OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND - * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT - * HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, - * WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING - * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR - * OTHER DEALINGS IN THE SOFTWARE. - * - * The complete license agreement can be found here: - * http://opcfoundation.org/License/MIT/1.00/ - * ======================================================================*/ - -using System.Collections.Generic; -using System.Diagnostics.Tracing; -using System.Threading; -using NUnit.Framework; - -namespace Opc.Ua.Server.Tests -{ - /// - /// Deterministic, offline unit tests for . - /// - [TestFixture] - [Category("OpcUaServerEventSource")] - [NonParallelizable] - public class OpcUaServerEventSourceTests - { - [Test] - public void EventLogIsAvailableWithExpectedName() - { - OpcUaServerEventSource eventLog = ServerUtils.EventLog; - - Assert.That(eventLog, Is.Not.Null); - Assert.That(eventLog.Name, Is.EqualTo("OPC-UA-Server")); - } - - [Test] - public void EventMethodsDoNotThrowWhenNoListenerAttached() - { - OpcUaServerEventSource eventLog = ServerUtils.EventLog; - - Assert.DoesNotThrow(() => eventLog.ServerCall("Read", 42)); - Assert.DoesNotThrow( - () => eventLog.SessionState("Created", "s1", "name", "ch1", "user")); - Assert.DoesNotThrow(() => eventLog.MonitoredItemReady(7, "ready")); - } - - [Test] - public void ServerCallWritesEventWhenEnabled() - { - using var listener = new CollectingEventListener(ServerUtils.EventLog); - - ServerUtils.EventLog.ServerCall("Browse", 99); - - EventWrittenEventArgs written = listener.FindEvent("ServerCall"); - Assert.That(written, Is.Not.Null); - Assert.That(written.Payload[0], Is.EqualTo("Browse")); - Assert.That(written.Payload, Has.Count.EqualTo(2)); - } - - [Test] - public void SessionStateWritesEventWhenEnabled() - { - using var listener = new CollectingEventListener(ServerUtils.EventLog); - - ServerUtils.EventLog.SessionState("Activated", "sid", "sname", "chan", "ident"); - - EventWrittenEventArgs written = listener.FindEvent("SessionState"); - Assert.That(written, Is.Not.Null); - Assert.That(written.Payload[0], Is.EqualTo("Activated")); - Assert.That(written.Payload[4], Is.EqualTo("ident")); - } - - [Test] - public void MonitoredItemReadyWritesEventWhenEnabled() - { - using var listener = new CollectingEventListener(ServerUtils.EventLog); - - ServerUtils.EventLog.MonitoredItemReady(123, "publishing"); - - EventWrittenEventArgs written = listener.FindEvent("MonitoredItemReady"); - Assert.That(written, Is.Not.Null); - Assert.That(written.Payload, Has.Count.EqualTo(2)); - Assert.That(written.Payload[1], Is.EqualTo("publishing")); - } - - private sealed class CollectingEventListener : EventListener - { - private readonly EventSource m_source; - private readonly List m_events = []; - private readonly Lock m_lock = new(); - - public CollectingEventListener(EventSource source) - { - m_source = source; - EnableEvents(source, EventLevel.Verbose); - } - - public EventWrittenEventArgs FindEvent(string eventName) - { - lock (m_lock) - { - return m_events.Find(e => e.EventName == eventName); - } - } - - protected override void OnEventWritten(EventWrittenEventArgs eventData) - { - lock (m_lock) - { - m_events.Add(eventData); - } - } - - public override void Dispose() - { - DisableEvents(m_source); - base.Dispose(); - } - } - } -} diff --git a/tests/Opc.Ua.Stress.Tests/Channels/Chaos/AcceptButStallChaosTests.cs b/tests/Opc.Ua.Stress.Tests/Channels/Chaos/AcceptButStallChaosTests.cs index f884cc5ef8..6618e24a3f 100644 --- a/tests/Opc.Ua.Stress.Tests/Channels/Chaos/AcceptButStallChaosTests.cs +++ b/tests/Opc.Ua.Stress.Tests/Channels/Chaos/AcceptButStallChaosTests.cs @@ -29,6 +29,7 @@ using System; using System.Globalization; +using System.Runtime.CompilerServices; using System.Threading; using System.Threading.Tasks; using NUnit.Framework; @@ -63,24 +64,25 @@ public async Task SessionRecoversFromAcceptButStallAsync(CancellationToken ct) int seed = TestRunSeed.Get(); TestContext.Out.WriteLine(FormattableString.Invariant($"L3-A4 seed={seed}")); - TcpChaosProxy? proxy = null; - ClientChannelManager? manager = null; ManagedSessionType? session = null; + using MetricsCollector collector = new(); + TcpChaosProxy proxy = await TcpChaosProxy + .StartAsync(ServerUrl, telemetry: Telemetry) + .ConfigureAwait(false); + await using ConfiguredAsyncDisposable proxyAsyncDisposable = proxy.ConfigureAwait(false); + ClientChannelManager manager = CreateChannelManager( + new ExponentialBackoffChannelReconnectPolicy + { + MinDelay = TimeSpan.FromMilliseconds(500), + MaxDelay = TimeSpan.FromSeconds(5), + MaxAttempts = 10 + }, + collector.Telemetry); + await using ConfiguredAsyncDisposable managerAsyncDisposable = manager.ConfigureAwait(false); + try { - proxy = await TcpChaosProxy - .StartAsync(ServerUrl, telemetry: Telemetry) - .ConfigureAwait(false); - manager = CreateChannelManager( - new ExponentialBackoffChannelReconnectPolicy - { - MinDelay = TimeSpan.FromMilliseconds(500), - MaxDelay = TimeSpan.FromSeconds(5), - MaxAttempts = 10 - }); - using MetricsCollector collector = new(); - ConfiguredEndpoint endpoint = await GetEndpointAsync(SecurityPolicies.None, proxy.LocalUrl) .ConfigureAwait(false); endpoint.EndpointUrl = proxy.LocalUrl; @@ -142,19 +144,9 @@ await session.ReadValueAsync(VariableIds.Server_ServerStatus_CurrentTime, ct) } finally { - proxy?.StallForwarding = false; + proxy.StallForwarding = false; await CloseAndDisposeAsync(session).ConfigureAwait(false); - - if (manager != null) - { - await manager.DisposeAsync().ConfigureAwait(false); - } - - if (proxy != null) - { - await proxy.DisposeAsync().ConfigureAwait(false); - } } } diff --git a/tests/Opc.Ua.Stress.Tests/Channels/Chaos/BlockAcceptChaosTests.cs b/tests/Opc.Ua.Stress.Tests/Channels/Chaos/BlockAcceptChaosTests.cs index 19922260ea..b0ae16858f 100644 --- a/tests/Opc.Ua.Stress.Tests/Channels/Chaos/BlockAcceptChaosTests.cs +++ b/tests/Opc.Ua.Stress.Tests/Channels/Chaos/BlockAcceptChaosTests.cs @@ -69,13 +69,15 @@ public async Task SessionSurvivesMixedDropAndBlockAcceptAsync(CancellationToken .ConfigureAwait(false); try { + using var collector = new MetricsCollector(); ClientChannelManager manager = CreateChannelManager( new ExponentialBackoffChannelReconnectPolicy { MinDelay = TimeSpan.FromMilliseconds(200), MaxDelay = TimeSpan.FromSeconds(2), MaxAttempts = 20 - }); + }, + collector.Telemetry); try { ConfiguredEndpoint endpoint = await GetEndpointAsync(SecurityPolicies.None, proxy.LocalUrl) @@ -125,7 +127,6 @@ async Task DispatchChaosEventAsync(ChaosEvent chaosEvent, CancellationToken work await runner.StartAsync(ct).ConfigureAwait(false); try { - using var collector = new MetricsCollector(); ChaosSchedule schedule = CreateMixedDropAndBlockAcceptSchedule(seed); var dispatcher = new ChaosScheduleRunner(schedule, DispatchChaosEventAsync); try diff --git a/tests/Opc.Ua.Stress.Tests/Channels/Chaos/TransparentReconnectChaosTests.cs b/tests/Opc.Ua.Stress.Tests/Channels/Chaos/TransparentReconnectChaosTests.cs index aa661d6358..5a3a187303 100644 --- a/tests/Opc.Ua.Stress.Tests/Channels/Chaos/TransparentReconnectChaosTests.cs +++ b/tests/Opc.Ua.Stress.Tests/Channels/Chaos/TransparentReconnectChaosTests.cs @@ -74,10 +74,10 @@ public async Task SingleSessionSurvivesPeriodicDropsAsync(CancellationToken ct) TcpChaosProxy proxy = await TcpChaosProxy.StartAsync(ServerUrl, telemetry: Telemetry) .ConfigureAwait(false); await using ConfiguredAsyncDisposable proxyAsyncDisposable = proxy.ConfigureAwait(false); - ClientChannelManager manager = CreateChannelManager(CreateTightReconnectPolicy()); + using MetricsCollector collector = new(); + ClientChannelManager manager = CreateChannelManager(CreateTightReconnectPolicy(), collector.Telemetry); await using ConfiguredAsyncDisposable managerAsyncDisposable = manager.ConfigureAwait(false); LeakCounters.Snapshot before = LeakCounters.Capture(manager); - using MetricsCollector collector = new(); ConfiguredEndpoint endpoint = await GetProxyEndpointAsync(proxy.LocalUrl).ConfigureAwait(false); ManagedSessionType? session = null; @@ -206,10 +206,10 @@ public async Task SharedChannelCoalescesPeriodicDropsAsync(CancellationToken ct) TcpChaosProxy proxy = await TcpChaosProxy.StartAsync(ServerUrl, telemetry: Telemetry) .ConfigureAwait(false); await using ConfiguredAsyncDisposable proxyAsyncDisposable = proxy.ConfigureAwait(false); - ClientChannelManager manager = CreateChannelManager(CreateTightReconnectPolicy()); + using MetricsCollector collector = new(); + ClientChannelManager manager = CreateChannelManager(CreateTightReconnectPolicy(), collector.Telemetry); await using ConfiguredAsyncDisposable managerAsyncDisposable = manager.ConfigureAwait(false); LeakCounters.Snapshot before = LeakCounters.Capture(manager); - using MetricsCollector collector = new(); ConfiguredEndpoint endpoint = await GetProxyEndpointAsync(proxy.LocalUrl).ConfigureAwait(false); var sessions = new List(SharedSessionCount); diff --git a/tests/Opc.Ua.Stress.Tests/Channels/Helpers/MetricsCollector.cs b/tests/Opc.Ua.Stress.Tests/Channels/Helpers/MetricsCollector.cs index 7c06614c66..f901f9f8b3 100644 --- a/tests/Opc.Ua.Stress.Tests/Channels/Helpers/MetricsCollector.cs +++ b/tests/Opc.Ua.Stress.Tests/Channels/Helpers/MetricsCollector.cs @@ -32,15 +32,25 @@ using System.Collections.ObjectModel; using System.Diagnostics; using System.Diagnostics.Metrics; -using System.Diagnostics.Tracing; using System.Globalization; using System.Threading; +using Microsoft.Extensions.Logging; +using Opc.Ua.Tests; namespace Opc.Ua.Stress.Tests.Channels.Helpers { /// - /// Collects channel-manager metrics and EventSource records during stress tests. + /// Collects channel-manager metrics and structured diagnostic-log records during stress tests. /// + /// + /// Structured channel-manager records are captured through a dedicated + /// () that owns a + /// . Call sites must construct the + /// under test with + /// so its structured logs flow into this collector; the wiring is explicit + /// and is torn down when the collector is disposed, rather than being + /// registered permanently into a shared logger factory. + /// public sealed class MetricsCollector : IDisposable { /// @@ -48,7 +58,9 @@ public sealed class MetricsCollector : IDisposable /// public MetricsCollector() { - m_eventListener = new ChannelManagerEventListener(this); + m_loggerProvider = new RecordingLoggerProvider(); + m_telemetry = DefaultTelemetry.Create( + builder => builder.AddProvider(m_loggerProvider)); m_meterListener = new MeterListener { InstrumentPublished = (instrument, listener) => @@ -66,6 +78,13 @@ public MetricsCollector() m_meterListener.Start(); } + /// + /// Gets the telemetry context that call sites must pass into the + /// under test so its structured + /// channel-manager logs are captured by this collector. + /// + public ITelemetryContext Telemetry => m_telemetry; + /// /// Gets the measurements captured so far. /// @@ -81,12 +100,13 @@ public IReadOnlyList Measurements } /// - /// Gets the EventSource records captured so far. + /// Gets the structured channel-manager log records captured so far. /// public IReadOnlyList Events { get { + CaptureNewLogRecords(); lock (m_lock) { return [.. m_events]; @@ -136,7 +156,7 @@ public TMetric GetMetric(string name) } /// - /// Counts EventSource records with the supplied event name. + /// Counts structured channel-manager log records with the supplied event name. /// /// The event name. /// The number of matching records. @@ -148,6 +168,8 @@ public int CountEvents(string eventName) throw new ArgumentNullException(nameof(eventName)); } + CaptureNewLogRecords(); + int count = 0; lock (m_lock) { @@ -172,7 +194,7 @@ public void RecordObservableInstruments() } /// - /// Stops collecting metrics and events. + /// Stops collecting metrics and structured channel-manager logs. /// public void Dispose() { @@ -187,7 +209,8 @@ public void Dispose() } m_meterListener.Dispose(); - m_eventListener.Dispose(); + (m_telemetry as IDisposable)?.Dispose(); + m_loggerProvider.Dispose(); GC.SuppressFinalize(this); } @@ -205,10 +228,10 @@ public record MetricMeasurement( DateTimeOffset Timestamp); /// - /// A captured EventSource record. + /// A captured structured channel-manager log record. /// - /// The event name. - /// The event payload keyed by payload name. + /// The EventId.Name of the log record. + /// The structured log properties keyed by name. /// The capture timestamp. public record EventRecord( string Name, @@ -287,75 +310,68 @@ private void AddMeasurement( } } - private void AddEvent(EventWrittenEventArgs eventData) + /// + /// Converts any not-yet-observed records + /// belonging to the channel-manager category into + /// instances, stamping each with the time it was first observed. + /// + private void CaptureNewLogRecords() { - string name = eventData.EventName ?? eventData.EventId.ToString(CultureInfo.InvariantCulture); - var payload = new Dictionary(); - ReadOnlyCollection? payloadValues = eventData.Payload; - ReadOnlyCollection? payloadNames = eventData.PayloadNames; - if (payloadValues != null) + IReadOnlyList records = m_loggerProvider.Records; + lock (m_lock) { - for (int i = 0; i < payloadValues.Count; i++) + if (m_disposed) { - string key = payloadNames != null && i < payloadNames.Count - ? payloadNames[i] - : i.ToString(CultureInfo.InvariantCulture); - payload[key] = payloadValues[i]; + return; } - } - var record = new EventRecord( - name, - new ReadOnlyDictionary(payload), - TimeProvider.System.GetUtcNow()); - lock (m_lock) - { - if (!m_disposed) + for (int i = m_capturedLogRecordCount; i < records.Count; i++) { - m_events.Add(record); + RecordedLogRecord record = records[i]; + if (!string.Equals(record.CategoryName, ChannelManagerName, StringComparison.Ordinal)) + { + continue; + } + + string name = record.EventId.Name ?? + record.EventId.Id.ToString(CultureInfo.InvariantCulture); + m_events.Add( + new EventRecord( + name, + CreatePayload(record.Properties), + TimeProvider.System.GetUtcNow())); } + + m_capturedLogRecordCount = records.Count; } } - private sealed class ChannelManagerEventListener : EventListener + private static ReadOnlyDictionary CreatePayload( + IReadOnlyDictionary properties) { - public ChannelManagerEventListener(MetricsCollector owner) + var payload = new Dictionary(properties.Count, StringComparer.Ordinal); + foreach (KeyValuePair property in properties) { - m_owner = owner; - foreach (EventSource eventSource in EventSource.GetSources()) + if (string.Equals(property.Key, "{OriginalFormat}", StringComparison.Ordinal)) { - EnableIfChannelManager(eventSource); + continue; } - } - - protected override void OnEventSourceCreated(EventSource eventSource) - { - EnableIfChannelManager(eventSource); - } - - protected override void OnEventWritten(EventWrittenEventArgs eventData) - { - m_owner?.AddEvent(eventData); - } - private void EnableIfChannelManager(EventSource eventSource) - { - if (string.Equals(eventSource.Name, ChannelManagerName, StringComparison.Ordinal)) - { - EnableEvents(eventSource, EventLevel.LogAlways); - } + payload[property.Key] = property.Value; } - private readonly MetricsCollector? m_owner; + return new ReadOnlyDictionary(payload); } private const string ChannelManagerName = "Opc.Ua.ChannelManager"; private const string ChannelMetricPrefix = "opc.ua.channel."; private readonly Lock m_lock = new(); private readonly MeterListener m_meterListener; - private readonly ChannelManagerEventListener m_eventListener; + private readonly RecordingLoggerProvider m_loggerProvider; + private readonly ITelemetryContext m_telemetry; private readonly List m_measurements = []; private readonly List m_events = []; + private int m_capturedLogRecordCount; private bool m_disposed; } } diff --git a/tests/Opc.Ua.Stress.Tests/Channels/Integration/CertRotationLiveTests.cs b/tests/Opc.Ua.Stress.Tests/Channels/Integration/CertRotationLiveTests.cs index b96149a92b..c8ecd9e6fb 100644 --- a/tests/Opc.Ua.Stress.Tests/Channels/Integration/CertRotationLiveTests.cs +++ b/tests/Opc.Ua.Stress.Tests/Channels/Integration/CertRotationLiveTests.cs @@ -71,7 +71,8 @@ public async Task L2Cert1RotateCertificateWhileSessionsActiveReconnectsSharedCha MinDelay = TimeSpan.Zero, MaxDelay = TimeSpan.Zero, MaxAttempts = 3 - }); + }, + metrics.Telemetry); ConfiguredEndpoint endpoint = await GetEndpointAsync(SecurityPolicies.Basic256Sha256) .ConfigureAwait(false); var sessions = new List(SessionCount); @@ -119,7 +120,8 @@ public async Task L2Cert2RotateCertificateDuringServerRestartRecoversSharedChann MinDelay = TimeSpan.FromMilliseconds(100), MaxDelay = TimeSpan.FromMilliseconds(500), MaxAttempts = 120 - }); + }, + metrics.Telemetry); ConfiguredEndpoint endpoint = await GetEndpointAsync(SecurityPolicies.Basic256Sha256) .ConfigureAwait(false); var sessions = new List(SessionCount); diff --git a/tests/Opc.Ua.Stress.Tests/Channels/Integration/FailoverLeaseSwapTests.cs b/tests/Opc.Ua.Stress.Tests/Channels/Integration/FailoverLeaseSwapTests.cs index adc7ffe343..e331164e26 100644 --- a/tests/Opc.Ua.Stress.Tests/Channels/Integration/FailoverLeaseSwapTests.cs +++ b/tests/Opc.Ua.Stress.Tests/Channels/Integration/FailoverLeaseSwapTests.cs @@ -59,8 +59,8 @@ public sealed class FailoverLeaseSwapTests : IntegrationTestBase [CancelAfter(180_000)] public async Task FailoverWithKeyChangeSwapsLeaseRefcountsAsync(CancellationToken ct) { - await using ClientChannelManager manager = CreateChannelManager(); using var metrics = new MetricsCollector(); + await using ClientChannelManager manager = CreateChannelManager(telemetry: metrics.Telemetry); ConfiguredEndpoint endpointA = await GetEndpointAsync(SecurityPolicies.None) .ConfigureAwait(false); ConfiguredEndpoint endpointB = await GetEndpointAsync(SecurityPolicies.Basic256Sha256) diff --git a/tests/Opc.Ua.Stress.Tests/Channels/Integration/IntegrationTestBase.cs b/tests/Opc.Ua.Stress.Tests/Channels/Integration/IntegrationTestBase.cs index 17f276107d..fe1bc5fd32 100644 --- a/tests/Opc.Ua.Stress.Tests/Channels/Integration/IntegrationTestBase.cs +++ b/tests/Opc.Ua.Stress.Tests/Channels/Integration/IntegrationTestBase.cs @@ -69,11 +69,12 @@ public override Task OneTimeTearDownAsync() } protected ClientChannelManager CreateChannelManager( - IChannelReconnectPolicy? reconnectPolicy = null) + IChannelReconnectPolicy? reconnectPolicy = null, + ITelemetryContext? telemetry = null) { return new ClientChannelManager( ClientFixture.Config, - Telemetry, + telemetry ?? Telemetry, reconnectPolicy: reconnectPolicy); } diff --git a/tests/Opc.Ua.Stress.Tests/Channels/Integration/ServerOutageRecoveryTests.cs b/tests/Opc.Ua.Stress.Tests/Channels/Integration/ServerOutageRecoveryTests.cs index 2e4ad02304..29df4fb74e 100644 --- a/tests/Opc.Ua.Stress.Tests/Channels/Integration/ServerOutageRecoveryTests.cs +++ b/tests/Opc.Ua.Stress.Tests/Channels/Integration/ServerOutageRecoveryTests.cs @@ -57,10 +57,10 @@ public sealed class ServerOutageRecoveryTests : IntegrationTestBase public async Task SingleSessionRecoversAfterServerRestartAsync( CancellationToken ct) { - ClientChannelManager manager = CreateChannelManager(CreateTightReconnectPolicy()); + using MetricsCollector collector = new(); + ClientChannelManager manager = CreateChannelManager(CreateTightReconnectPolicy(), collector.Telemetry); try { - using MetricsCollector collector = new(); LeakCounters.Snapshot before = LeakCounters.Capture(manager); ConfiguredEndpoint endpoint = await GetEndpointAsync(SecurityPolicies.None) .ConfigureAwait(false); @@ -128,10 +128,10 @@ await WaitForQuiescence.EntryGoneAsync(manager, key, DefaultWait, ct) public async Task MultipleSessionsRecoverAfterServerRestartAsync( CancellationToken ct) { - ClientChannelManager manager = CreateChannelManager(CreateTightReconnectPolicy()); + using MetricsCollector collector = new(); + ClientChannelManager manager = CreateChannelManager(CreateTightReconnectPolicy(), collector.Telemetry); try { - using MetricsCollector collector = new(); LeakCounters.Snapshot before = LeakCounters.Capture(manager); ConfiguredEndpoint endpoint = await GetEndpointAsync(SecurityPolicies.None) .ConfigureAwait(false); diff --git a/tests/Opc.Ua.Stress.Tests/Channels/Soak/CombinatorialMatrixTests.cs b/tests/Opc.Ua.Stress.Tests/Channels/Soak/CombinatorialMatrixTests.cs index 234b32aa80..dd940d1243 100644 --- a/tests/Opc.Ua.Stress.Tests/Channels/Soak/CombinatorialMatrixTests.cs +++ b/tests/Opc.Ua.Stress.Tests/Channels/Soak/CombinatorialMatrixTests.cs @@ -123,9 +123,9 @@ public async Task CombinatorialMatrixAsync( .ConfigureAwait(false); await using ConfiguredAsyncDisposable proxyAsyncDisposable = proxy.ConfigureAwait(false); - ClientChannelManager manager = CreateChannelManager(CreateMatrixReconnectPolicy()); - await using ConfiguredAsyncDisposable managerAsyncDisposable = manager.ConfigureAwait(false); using MetricsCollector collector = new(); + ClientChannelManager manager = CreateChannelManager(CreateMatrixReconnectPolicy(), collector.Telemetry); + await using ConfiguredAsyncDisposable managerAsyncDisposable = manager.ConfigureAwait(false); ConfiguredEndpoint endpoint = await GetProxyEndpointAsync(proxy.LocalUrl).ConfigureAwait(false); var sessions = new List(sessionCount); diff --git a/tests/Opc.Ua.Stress.Tests/Channels/Soak/LongSoakTests.cs b/tests/Opc.Ua.Stress.Tests/Channels/Soak/LongSoakTests.cs index f9755ecd23..59e180d1a6 100644 --- a/tests/Opc.Ua.Stress.Tests/Channels/Soak/LongSoakTests.cs +++ b/tests/Opc.Ua.Stress.Tests/Channels/Soak/LongSoakTests.cs @@ -74,9 +74,9 @@ public async Task SixtyMinuteRandomizedChaosSoakAsync(CancellationToken ct) .ConfigureAwait(false); await using ConfiguredAsyncDisposable proxyAsyncDisposable = proxy.ConfigureAwait(false); - ClientChannelManager manager = CreateChannelManager(CreateSoakReconnectPolicy()); - await using ConfiguredAsyncDisposable managerAsyncDisposable = manager.ConfigureAwait(false); using MetricsCollector collector = new(); + ClientChannelManager manager = CreateChannelManager(CreateSoakReconnectPolicy(), collector.Telemetry); + await using ConfiguredAsyncDisposable managerAsyncDisposable = manager.ConfigureAwait(false); ConfiguredEndpoint endpoint = await GetProxyEndpointAsync(proxy.LocalUrl).ConfigureAwait(false); var sessions = new List(SessionCount); diff --git a/tests/Opc.Ua.Stress.Tests/README.md b/tests/Opc.Ua.Stress.Tests/README.md index 92494e8cc9..ac280b9b11 100644 --- a/tests/Opc.Ua.Stress.Tests/README.md +++ b/tests/Opc.Ua.Stress.Tests/README.md @@ -41,5 +41,4 @@ Every chaos test prints its seed at start. Re-run a failed chaos case with the p ## Inspecting failures Chaos failures should include the printed seed in the NUnit output. Use the same seed to reproduce the schedule. -When a test uses `MetricsCollector`, inspect the dumped channel-manager metrics and EventSource records in the -failure output before changing production code or widening timing windows. +When a test uses `MetricsCollector`, inspect the dumped channel-manager metrics and structured log records in the failure output before changing production code or widening timing windows. diff --git a/tests/Opc.Ua.Test.Common/RecordingLoggerProvider.cs b/tests/Opc.Ua.Test.Common/RecordingLoggerProvider.cs new file mode 100644 index 0000000000..acbe3df8f4 --- /dev/null +++ b/tests/Opc.Ua.Test.Common/RecordingLoggerProvider.cs @@ -0,0 +1,198 @@ +/* ======================================================================== + * Copyright (c) 2005-2026 The OPC Foundation, Inc. All rights reserved. + * + * OPC Foundation MIT License 1.00 + * + * Permission is hereby granted, free of charge, to any person + * obtaining a copy of this software and associated documentation + * files (the "Software"), to deal in the Software without + * restriction, including without limitation the rights to use, + * copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the + * Software is furnished to do so, subject to the following + * conditions: + * + * The above copyright notice and this permission notice shall be + * included in all copies or substantial portions of the Software. + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, + * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES + * OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND + * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT + * HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, + * WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR + * OTHER DEALINGS IN THE SOFTWARE. + * + * The complete license agreement can be found here: + * http://opcfoundation.org/License/MIT/1.00/ + * ======================================================================*/ + +#nullable enable + +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using Microsoft.Extensions.Logging; + +namespace Opc.Ua.Tests +{ + /// + /// Thread-safe logger provider for asserting structured log contracts. + /// + public sealed class RecordingLoggerProvider : ILoggerProvider + { + /// + /// Initializes a recording provider. + /// + /// The minimum level to capture. + public RecordingLoggerProvider(LogLevel minimumLevel = LogLevel.Trace) + { + MinimumLevel = minimumLevel; + } + + /// + /// Gets or sets the minimum captured log level. + /// + public LogLevel MinimumLevel { get; set; } + + /// + /// Gets a snapshot of the captured records. + /// + public IReadOnlyList Records => m_records.ToArray(); + + /// + public ILogger CreateLogger(string categoryName) + { + return new RecordingLogger(this, categoryName); + } + + /// + public void Dispose() + { + } + + private sealed class RecordingLogger : ILogger + { + public RecordingLogger(RecordingLoggerProvider provider, string categoryName) + { + m_provider = provider; + m_categoryName = categoryName; + } + + /// + public IDisposable BeginScope(TState state) + where TState : notnull + { + return EmptyScope.Instance; + } + + /// + public bool IsEnabled(LogLevel logLevel) + { + return logLevel >= m_provider.MinimumLevel && + logLevel != LogLevel.None; + } + + /// + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + { + if (!IsEnabled(logLevel)) + { + return; + } + + var properties = new Dictionary(StringComparer.Ordinal); + if (state is IEnumerable> values) + { + foreach (KeyValuePair value in values) + { + properties[value.Key] = value.Value; + } + } + + m_provider.m_records.Enqueue( + new RecordedLogRecord( + m_categoryName, + logLevel, + eventId, + formatter(state, exception), + properties, + exception)); + } + + private readonly RecordingLoggerProvider m_provider; + private readonly string m_categoryName; + } + + private sealed class EmptyScope : IDisposable + { + public static EmptyScope Instance { get; } = new(); + + public void Dispose() + { + } + } + + private readonly ConcurrentQueue m_records = new(); + } + + /// + /// A structured log record captured by . + /// + public sealed class RecordedLogRecord + { + /// + /// Initializes a captured log record. + /// + public RecordedLogRecord( + string categoryName, + LogLevel logLevel, + EventId eventId, + string message, + IReadOnlyDictionary properties, + Exception? exception) + { + CategoryName = categoryName; + LogLevel = logLevel; + EventId = eventId; + Message = message; + Properties = properties; + Exception = exception; + } + + /// + /// Gets the logger category. + /// + public string CategoryName { get; } + + /// + /// Gets the log level. + /// + public LogLevel LogLevel { get; } + + /// + /// Gets the event identity. + /// + public EventId EventId { get; } + + /// + /// Gets the formatted message. + /// + public string Message { get; } + + /// + /// Gets the structured log properties. + /// + public IReadOnlyDictionary Properties { get; } + + /// + /// Gets the associated exception. + /// + public Exception? Exception { get; } + } +}