Skip to content

Add session and subscription ids to client and server request logging - #4189

Open
TimJoehnk wants to merge 14 commits into
OPCFoundation:masterfrom
TimJoehnk:timjoehnk/session-subscription-log-correlation-master
Open

Add session and subscription ids to client and server request logging#4189
TimJoehnk wants to merge 14 commits into
OPCFoundation:masterfrom
TimJoehnk:timjoehnk/session-subscription-log-correlation-master

Conversation

@TimJoehnk

@TimJoehnk TimJoehnk commented Aug 5, 2026

Copy link
Copy Markdown
Contributor

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

  • 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

  • I have read the CONTRIBUTING doc.
  • I have signed the CLA.
  • 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.
  • 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.

TimJoehnk and others added 12 commits August 5, 2026 13:42
…de of the master port)

Ports the release/1.5.378 logging change to the master LoggerMessage idiom for the server request path: SessionPublishQueue (2), StandardServer (3) and Subscription (2). Each message gains the id as a source-generated log parameter.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Continues the master port: the eight MonitoredItem messages gain SubscriptionId (and MonitoredItemId on the publish message) as source-generated log parameters.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Completes the server side of the master port: ConditionRefresh, ConditionRefresh2, DeleteSubscriptions, SetPublishingMode, Publish ReceivedFromClient and Publish False Alarm gain the ids as source-generated log parameters.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Append SessionId to the 19 request-path log messages in the client
Session that did not carry it, so lines from concurrent sessions can be
told apart in a host that holds more than one connection.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Append SessionId to the 13 publish and republish path log messages in the
classic subscription engine. The publish response messages read the id
from the session the request was actually sent on, not from the current
context, so a response that arrives after a reconnect is still attributed
to the session that produced it.

The NOTIFICATION RECEIVED message keeps its legacy event id and event
name; only the message template gains the field.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Append SessionId to the 26 log messages in the classic client
subscription, and SubscriptionId to the four that named neither their
subscription nor its session (the state change callback exception, the
incoming message error, and the PublishStateChanged event error).

Subscription.Session is nullable and is cleared when a subscription is
removed from its session, so the added arguments are read as
Session?.SessionId. RestoreTriggeringAsync captures the reference once
before its loop instead: the null test in ?. resets the nullable flow
state, and the foreach back-edge would carry that to the existing
SetTriggeringAsync call at the top of the loop body. The captured local
also reports the session the call was actually made on rather than a
blank.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The three data change validation warnings named only the client handle,
which is unique per subscription and not per host, so two subscriptions
could produce the same MonitoredItemId in one log file.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Three server messages were missed in the earlier monitored item commit.
The two queue restore errors gain SubscriptionId.

DEQUEUE VALUE identified nothing at all, and its message is shared with
DataChangeQueueHandler, which holds a monitored item id but has no
subscription or session in scope, so it gains MonitoredItemId only
rather than a subscription id that would have to be faked at one of the
two call sites.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The Deleted and Config trace states already name their session; Items
and Publish/Monitor did not. All four now do.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
ClientEventsRetainLegacyContracts calls the two legacy-shaped client
events directly, so it needs the new argument. Their event ids, names and
levels are unchanged and every property the test already pinned is still
present; assert the new one too, so the field is covered by the same
contract test rather than only by the call sites.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
SubscriptionSubscriptionIdDelayedMessageSequenceNumber gained a sessionId
parameter earlier on this branch, but its only call site sits inside an
#if DEBUG block and was not updated, so Opc.Ua.Client failed to compile in
Debug with CS7036 while Release built clean.

The call sites for the other messages were found by changing a declaration
and letting the compiler list them, which cannot see code the active
configuration excludes. This is the only logger call under a preprocessor
guard whose symbol is not always defined; the two under #if OPCUA_V1_CLIENT
were checked, because that symbol is defined unconditionally in the project
file.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Four messages were left uncorrelated while their immediate neighbours were
enriched, which made the omissions look arbitrary:

- PUBLISH #{RequestHandle} SENT and RECEIVED, the two legacy publish events.
  SENT reads the engine context, RECEIVED reads the sessionId parameter of
  OnPublishComplete, so a response is attributed to the session that sent
  the request even after a reconnect.
- Server Call={RequestType}, Id={RequestId}, from the operation context.
- Keep alive read failed, which carries the same EndpointUrl and
  RequestCount fields as KEEP ALIVE LATE but had no session id, from the
  same instance property the neighbouring keep-alive message uses.

The first and third are two of the three lines used to motivate this change,
so they should not have been the ones left out.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

This PR improves diagnosability of interleaved client/server request-path logs by adding SessionId (and SubscriptionId where available) to existing source-generated logging templates and method signatures across the classic client session/subscription pipeline and key server subscription/publish paths. It also extends the compatibility logging test to pin the new legacy-event field.

Changes:

  • Append SessionId/SubscriptionId fields to existing [LoggerMessage] templates and generated method parameter lists (client + server).
  • Thread session/subscription IDs through various publish/notification/monitored-item logging call sites.
  • Update OpcUaClientCompatibilityLoggingTests to assert SessionId is present on legacy-contract events.

Reviewed changes

Copilot reviewed 12 out of 12 changed files in this pull request and generated 2 comments.

Show a summary per file
File Description
tests/Opc.Ua.Client.Tests/OpcUaClientCompatibilityLoggingTests.cs Extends legacy-contract event assertions to include SessionId.
src/Opc.Ua.Client/Session/Session.cs Adds SessionId context to session lifecycle and subscription transfer/reactivation logs.
src/Opc.Ua.Client/Session/Subscription/ClassicSubscriptionEngine.cs Adds SessionId to publish/notification legacy events and related request-path logs.
src/Opc.Ua.Client/Subscription/Classic/Subscription.cs Adds SessionId/SubscriptionId context to classic subscription logs and restores triggering with stable session reference.
src/Opc.Ua.Client/Subscription/Classic/MonitoredItem.cs Adds subscription/session context to monitored item timestamp/overflow warnings.
src/Opc.Ua.Server/Server/StandardServer.cs Adds SessionId to session activation/audit-adjacent logging and server-call compatibility event.
src/Opc.Ua.Server/Subscription/SubscriptionManager.cs Adds SessionId/SubscriptionId context to condition refresh, publish, and error logs.
src/Opc.Ua.Server/Subscription/Subscription.cs Adds session/subscription identifiers to transfer/invariant/state tracing logs.
src/Opc.Ua.Server/Subscription/SessionPublishQueue.cs Adds SessionId/SubscriptionId context to publish queue logs.
src/Opc.Ua.Server/Subscription/MonitoredItem/MonitoredItem.cs Adds SubscriptionId context to monitored item logs and related error paths.
src/Opc.Ua.Server/Subscription/MonitoredItem/QueueHandler/DataChangeQueueHandler.cs Adds monitored-item id to the shared dequeue-value log call.
src/Opc.Ua.Server/MonitoredItemQueueLog.cs Extends shared dequeue-value template/signature to include MonitoredItemId.

Comment thread src/Opc.Ua.Server/Subscription/MonitoredItem/MonitoredItem.cs
Comment thread src/Opc.Ua.Server/Subscription/SessionPublishQueue.cs
@marcschier marcschier added the needs changes PR needs more changes label Aug 6, 2026

@marcschier marcschier left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@TimJoehnk thanks for the contribution. Could you fix the build failures and address the copilot review comments?

TimJoehnk and others added 2 commits August 6, 2026 13:35
CompatibilityServerCall, ClientEventPublishStart and ClientEventPublishStop
gained a sessionId parameter in the previous commit, but their call sites
in the legacy-contract tests were not updated, so the solution build failed
and every downstream test job reported no results.

CI reported only the server one, because the build stopped there. The two
client call sites were queued behind it and would have failed the next run.

The server test now pins SessionId on the ServerCall event, matching what
the client test already does for SubscriptionState and NotificationReceived.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
- "Durable subscription was create" -> "was created". The template is
  already being edited here, and the correction changes no event id or
  parameter.
- PUBLISH Assigned To Subscription kept its trailing "." and now carries
  the session id as a separate sentence, instead of turning that "." into
  a ",". The point of appending is that a scraper matching the existing
  text keeps working, and rewriting the existing suffix broke that.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@marcschier

Copy link
Copy Markdown
Collaborator

/azp run

@azure-pipelines

Copy link
Copy Markdown
Azure Pipelines successfully started running 1 pipeline(s).

@marcschier marcschier added needs changes PR needs more changes and removed needs changes PR needs more changes labels Aug 6, 2026
@marcschier

Copy link
Copy Markdown
Collaborator

@TimJoehnk - sorry :-) can you see the test failures in the checks? If I need to restart them, let me know, else might need more fixes.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

needs changes PR needs more changes

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants