Files
UA-.NETStandard/tests/Opc.Ua.Client.Tests/OpcUaClientCompatibilityLoggingTests.cs
Tim Jöhnk 5a6bbcce1c Add session and subscription ids to client and server request logging (#4189)
## Proposed changes

Request-path log messages in the client and server carry no session
context, which makes
them unusable for diagnosing an application that holds several sessions
at once — a
gateway, an aggregating client, or any host with more than one
connection. Lines like

    PUBLISH #4711 SENT
    NOTIFICATION RECEIVED: SubId=12, SeqNo=980
    Server Call=Publish, Id=8123

interleave across sessions in one log file with nothing to separate
them. The same applies
on the server side to messages that name a monitored item but not its
subscription.

This adds `SessionId` — and `SubscriptionId` where the call site has one
— to the existing
source-generated log messages in the client and server request paths.

Scope is deliberately narrow. The change touches **message templates and
parameter lists
only**:

- no new log statements, no changes to log levels, event ids or event
names
- no public API change: every changed method lives in an `internal
static partial class
  …Log` type
- no behavioural change beyond what is logged

11 source files and 1 test, +531/−259. 81 messages gain an id.

| Area | Files |
| --- | --- |
| Client | `Session/Session.cs`,
`Session/Subscription/ClassicSubscriptionEngine.cs`,
`Subscription/Classic/Subscription.cs`,
`Subscription/Classic/MonitoredItem.cs` |
| Server | `Server/StandardServer.cs`,
`Subscription/SubscriptionManager.cs`, `Subscription/Subscription.cs`,
`Subscription/SessionPublishQueue.cs`,
`Subscription/MonitoredItem/MonitoredItem.cs`,
`Subscription/MonitoredItem/QueueHandler/DataChangeQueueHandler.cs`,
`MonitoredItemQueueLog.cs` |

### Points worth a reviewer's attention

**Two legacy-contract events gain a field.**
`ClientEventSubscriptionState`
(`LegacySubscriptionStateId` / `"SubscriptionState"`) and
`ClientEventNotificationReceived`
(`LegacyNotificationReceivedId` / `"NotificationReceived"`) now carry
`SessionId`. Their
event ids, event names and levels are unchanged, and every property
`OpcUaClientCompatibilityLoggingTests` pins is still present — the test
is extended to pin
the new one as well. If you would rather the legacy-shaped events stay
byte-identical, say
so and I will drop the id from those two; the sibling non-legacy
messages at the same call
sites already carry it.

**`DEQUEUE VALUE` gains only `MonitoredItemId`, not a subscription id.**
Its message is
shared between `MonitoredItem` and `DataChangeQueueHandler`, and the
latter holds a
monitored item id but has no subscription or session in scope. The
message previously
identified nothing at all; adding the id it can actually supply seemed
better than
inventing a subscription id at one of the two call sites.

**`QUEUE OVERFLOW` in `SentMessageQueue` is left alone.** That class is
constructed with a
`Func<uint> subscriptionIdProvider` and no session, so there is no
session id to add. The
message already carries `SubId={SubscriptionId}`.

**Server trace states made consistent.** `Subscription.TraceState` has
four cases; `Deleted`
and `Config` already named their session, `Items` and
`Publish`/`Monitor` did not. All four
do now.

**One local added** in `Subscription.RestoreTriggeringAsync`: `ISession
session = Session;`
before the `foreach`. `Session?.SessionId` inside that loop does not
compile — `?.` is a
null test, so it resets the nullable flow state for `Session`, and the
`foreach` back-edge
carries that state to the top of the loop body, which makes the
pre-existing
`Session.SetTriggeringAsync(...)` a CS8602 error. Capturing the
reference once avoids
disturbing existing code and is more useful than `?.` anyway: it reports
the session the
call was actually made on rather than a blank.

**Publish responses are attributed to the session that sent the
request.** In
`ClassicSubscriptionEngine.OnPublishComplete` the added arguments read
the `sessionId`
parameter rather than `m_context.SessionId`, so a response arriving
after a reconnect is
still attributed to the session that produced it.

### Null-safety of the added arguments

Reviewed at every call site:

- Client `Subscription.Session` is `ISession?` and is cleared when a
subscription is removed
from its session, so those arguments are `Session?.SessionId` or read
from the captured
local. `[MemberNotNull]` on `VerifySession()` /
`VerifySessionAndSubscriptionState()`
satisfies the compiler but only describes the moment the guard returns,
not the state
after the following `await` — and several of these arguments sit in
`catch` blocks, where
  an NRE would have replaced a `ServiceResultException` and escaped.
- Client `Session` derives `SessionId` from `SessionClient`, which is
non-nullable.
- Server `OperationContext.SessionId` and `Subscription.SessionId`
already return `default`
  when there is no session, so those arguments cannot throw.
- Consequence worth knowing: when the server reaps expired
subscriptions,
`Subscription.DeleteAsync` synthesises an `OperationContext` with no
session, so
  `SessionId` logs empty on that path. That is expected, not a defect.

## Related Issues

None — no existing issue covers this. Happy to open one for tracking if
you prefer.

## Types of changes

- [x] Enhancement (non-breaking change which adds functionality)
- [ ] Bugfix (non-breaking change which fixes an issue)
- [ ] Test enhancement (non-breaking change to increase test coverage)
- [ ] Breaking change (fix or feature that would cause existing
functionality to not work as expected, requires version increase of
Nuget packages)
- [ ] Documentation Update (if none of the other choices apply)

## Checklist

- [x] I have read the
[CONTRIBUTING](https://github.com/OPCFoundation/UA-.NETStandard/blob/master/CONTRIBUTING.md)
doc.
- [x] I have signed the
[CLA](https://opcfoundation.org/license/cla/ContributorLicenseAgreementv1.0.pdf).
- [x] I ran tests locally with my changes, all passed.
- [ ] I fixed all failing tests in the CI pipelines.
- [ ] I fixed all introduced issues with CodeQL and LGTM.
- [x] I have added necessary documentation (if appropriate).

`Opc.Ua.Client` and `Opc.Ua.Server` build clean for every target
framework
(net472, net48, netstandard2.1, net8.0, net9.0, net10.0) with
`--no-incremental`:
0 errors, 0 warnings under the repository's `TreatWarningsAsErrors`.

Local results, Release/net8.0:

| Suite | Result |
| --- | --- |
| `Opc.Ua.Server.Tests` | 0 failed, 4024 passed, 5 skipped |
| `Opc.Ua.Subscriptions.Classic.Tests` | 0 failed, 32 passed, 0 skipped
|

`Opc.Ua.Client.Tests` and `Opc.Ua.Sessions.Tests` are still running
here; I will post their
results as a comment rather than hold the PR for them.

The test output also confirms the placeholders bind at runtime, which
compilation alone does
not show — for example, from the transfer tests:

[Opc.Ua.Client.ClassicSubscriptionEngine] Publish #31,
Reconnecting=False,
      Error: ... (BadNoSubscription), SessionId=ns=3;i=1187191890

No tests are added beyond the compatibility-test extension: the change
alters message
templates and arguments, which the suites otherwise do not assert on.
Happy to add coverage
if you would like a specific message pinned.

The CI and CodeQL boxes are left blank deliberately — per CONTRIBUTING
the pipelines do not
start for outside contributors until a maintainer comments `/azp run`,
so there is nothing
for me to act on yet.

## Further comments

**Why the generated log methods change signature.** With
`[LoggerMessage]` the message
template and its parameters are a single declaration, so adding an id to
a message
necessarily adds a parameter to the generated method. Every one of them
lives in an
`internal static partial class …Log` type, so none of it is public API.

**Scope is the classic session and subscription path.**
`ManagedSession`,
`DefaultSubscriptionEngine`, `MessageProcessor`,
`Subscription/SubscriptionManager.cs` and
`Subscription/MonitoredItemManager.cs` are untouched.

**Placeholders are appended rather than woven into existing message
text** so that log
scrapers matching on the leading part of a message keep working.

---------

Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-08 09:22:05 +02:00

120 lines
5.2 KiB
C#

/* ========================================================================
* 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);
var sessionId = new NodeId(4711u);
logger.ClientEventSubscriptionState(
"Publishing",
10,
lastNotificationTime,
3,
1000,
5,
true,
8,
sessionId);
logger.ClientEventNotification(42, "123");
logger.ClientEventNotificationReceived(10, 11, sessionId);
logger.ClientEventPublishStart(12, sessionId);
logger.ClientEventPublishStop(12, sessionId);
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);
Assert.That(
subscription.Properties["SessionId"]?.ToString(),
Is.EqualTo(sessionId.ToString()));
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));
Assert.That(
received.Properties["SessionId"]?.ToString(),
Is.EqualTo(sessionId.ToString()));
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;
}
}
}