Uncaught ServiceResultException: BadSubscriptionIdInvalid when creating multiple subscriptions

[woutervd3]

Type of issue

• Bug
• Enhancement
• Compliance
• Question
• Help wanted

Current Behavior

We're creating multiple subscriptions in a session (per 1000 monitored items) using the client library. When creating e.g. 6 subscriptions we see logs:

- Subscription CREATED, Id=4, LastNotificationTime=06:49:48, GoodPublishRequestCount=1, PublishingInterval=100, KeepAliveCount=10, PublishingEnabled=True, MonitoredItemCount=1000
- Subscription CREATED, Id=5, LastNotificationTime=06:49:49, GoodPublishRequestCount=2, PublishingInterval=100, KeepAliveCount=10, PublishingEnabled=True, MonitoredItemCount=1000
- Subscription CREATED, Id=6, LastNotificationTime=06:49:51, GoodPublishRequestCount=3, PublishingInterval=100, KeepAliveCount=10, PublishingEnabled=True, MonitoredItemCount=1000
-  Subscription CREATED, Id=7, LastNotificationTime=06:49:52, GoodPublishRequestCount=4, PublishingInterval=100, KeepAliveCount=10, PublishingEnabled=True, MonitoredItemCount=1000
- Received Publish Response for Unknown SubscriptionId=8. Deleting abandoned subscription from server.
- Deleting server subscription for SubscriptionId=8
- fail: Microsoft.Extensions.Hosting.Internal.Host[9]
      BackgroundService failed
      Opc.Ua.ServiceResultException: BadSubscriptionIdInvalid
         at Opc.Ua.ClientBase.ValidateResponse(ResponseHeader header)
         at Opc.Ua.SessionClient.CreateMonitoredItems(RequestHeader requestHeader, UInt32 subscriptionId, TimestampsToReturn timestampsToReturn, MonitoredItemCreateRequestCollection itemsToCreate, MonitoredItemCreateResultCollection& results, DiagnosticInfoCollection& diagnosticInfos)
         at Opc.Ua.SessionClientBatched.CreateMonitoredItems(RequestHeader requestHeader, UInt32 subscriptionId, TimestampsToReturn timestampsToReturn, MonitoredItemCreateRequestCollection itemsToCreate, MonitoredItemCreateResultCollection& results, DiagnosticInfoCollection& diagnosticInfos)
         at Opc.Ua.Client.Subscription.CreateItems()
         at Opc.Ua.Client.Subscription.Create()
- Subscription PUBLISHING STOPPED, Id=8, LastNotificationTime=06:49:53, GoodPublishRequestCount=4, PublishingInterval=100, KeepAliveCount=10, PublishingEnabled=True, MonitoredItemCount=1000
- Subscription PUBLISHING STOPPED, Id=8, LastNotificationTime=06:49:53, GoodPublishRequestCount=6, PublishingInterval=100, KeepAliveCount=10, PublishingEnabled=True, MonitoredItemCount=1000
- Unexpected error sending publish request.
      Opc.Ua.ServiceResultException: BadConnectionClosed
         at Opc.Ua.Bindings.UaSCUaBinaryClientChannel.BeginSendRequest(IServiceRequest request, Int32 timeout, AsyncCallback callback, Object state)
         at Opc.Ua.Bindings.UaSCUaBinaryTransportChannel.BeginSendRequest(IServiceRequest request, AsyncCallback callback, Object callbackData)
         at Opc.Ua.SessionClient.BeginPublish(RequestHeader requestHeader, SubscriptionAcknowledgementCollection subscriptionAcknowledgements, AsyncCallback callback, Object asyncState)
         at Opc.Ua.Client.Session.BeginPublish(Int32 timeout)
-  Publish abandoned after error because session id changed: Old ns=1;g=c5cc3489-70b9-4b48-859f-e73029bb1f90 != New (null)
- ChannelId 1688135334: CLIENTCHANNEL SOCKET CLOSED: 00AD8B02
-  Publish #49, Subscription count = 0, Error: Channel has been closed.
-  Publish #53, Subscription count = 0, Error: Channel has been closed.
- ....

In the server's logs (KEPServerEX) we see normal behaviour (see screenshots below), every CreateSubscriptionRequest is answered with a good CreateSubscriptionResponse, only then we see a DeleteSubscriptionRequest (which is answered with a good DeleteSubscriptionResponse as well) for the last confirmed create.

CreateSubscriptionRequest :

CreateSubscriptionResponse:

DeleteSubscriptionRequest:

DeleteSubscriptionResponse:

Sometimes the application does succeed in creating all subscriptions.

Expected Behavior

I don't expect to see any unknown subscription Id's while creating new subscriptions. If they do happen, I expect a successful delete of a subscription to not throw exceptions.

Steps To Reproduce

I have not created an isolated project to reproduce this yet, but what we're doing:

1. create a session
2. Add some Handlers (SubscriptionsChanged, KeepAlive, SessionClosing, PublishError, Notification)
3. create a list of subscriptions, each with x amount of monitoredItems (with subscription.AddItems()). Add handlers for FastDataChangeCallback, StateChanged, PublishStatusChanged and Notification of each item.
4. add each subscription to the session with session.AddSubscription(subscription)
5. create each subscription server-side with subscription.Create()

Environment

- OS: Ubuntu
- Environment: Visual Studio 2022, application running in container
- Runtime: .NET 8
- Nuget Version: 1.5.374.124
- Component: Opc.Ua.Client
- Server: KepServerEX 6.14 (V6.14.263.0)
- Client: UA-.NETStandard library

Anything else?

No response

[Yamahari]

I am using version 1.5.376.213 and I am having a very similar issue.
For testing purposes I am creating a subscription, reading 5 values from it and deleting it, immediately followed by the next iteration of exactly that again.
At some point the creation of the subscription fails with "BadSubscriptionIdInvalid"; non-deterministically, but as soon as the 2nd iteration.
I have to implement either a delay of 100 ms between the delete and the subscription creation or a retry mechanism, both of which seem to fix the problem but are both very annoying and should not be necessary?

[romanett]

@Yamahari I tried to reproduce this with the ConsoleReferenceClient by calling ClientSamples.SubscribeToDataChanges and could not reproduce it. I delete every subscription before creating a new one. Do you have the creation running in parallel, so that at some point multiple subscriptions exist. Could you provide a modified ConsoleReferenceClient that shows your behaviour to reproduce the issue?

[romanett]

Are you using session.addSubscription & Session.removeSubscription to handle the cration & removal of subsrciptions? This is needed for proper handling

[Yamahari]

The creation/deletion is run asynchronously, here's a redacted excerpt from my code that shows how it works now with the delay and retry added, removing both the delay and retry introduces the bug:

public abstract class StreamHandler(/**/) : IAsyncDisposable
{
    // ...

    protected Channel<(NodeKey, Variant)> Channel { get; } = // ...

    public async IAsyncEnumerable<(NodeKey, Variant)> GetAsyncEnumerator([EnumeratorCancellation] CancellationToken cancellationToken = default)
    {
        while (await Channel.Reader.WaitToReadAsync(cancellationToken))
        {
            while (Channel.Reader.TryRead(out var item))
            {
                yield return item;
            }
        }
    }

    public abstract ValueTask DisposeAsync();
}


public class PLCStreamHandler : StreamHandler
{
    private readonly Session _session;
    private readonly Subscription _subscription;

    public static async Task<PLCStreamHandler?> CreateAsync(
        /**/,
        float _period,
        Session session,
        /**/
        CancellationToken ct = default)
    {
        var period = (int)(_period * 1000);
        const int maxRetries = 3;
        int attempt = 0;

        while (true)
        {
            attempt++;

            var subscription = new Subscription(session.DefaultSubscription)
            {
                PublishingInterval = period,
                TimestampsToReturn = TimestampsToReturn.Neither,
            };

            var streamHandler = new PLCStreamHandler(/**/, session, /**/, subscription);

            session.AddSubscription(subscription);
            await subscription.CreateAsync(ct).ConfigureAwait(false);

            await Task.Delay(100, ct); // allow for subscription to be finished on server?

            if (!subscription.Created)
            {
                // Only clean up this subscription
                try
                {
                    await subscription.DeleteAsync(false, ct);
                    session.RemoveSubscription(subscription);
                }
                catch
                {
                    // Ignore errors during cleanup
                }

                if (attempt >= maxRetries)
                {
                    return null;
                }

                continue;
            }

            foreach (/**/)
            {
                var nodeId = // ...

                var item = new MonitoredItem(subscription.DefaultItem)
                {
                    StartNodeId = nodeId,
                    AttributeId = Attributes.Value,
                    MonitoringMode = MonitoringMode.Reporting,
                    SamplingInterval = period,
                    QueueSize = 1,
                    DiscardOldest = true,
                    Handle = /**/
                };

                subscription.AddItem(item);
            }

            subscription.FastDataChangeCallback = streamHandler.FastDataChangeCallback;

            await subscription.ApplyChangesAsync(ct);

            bool allItemsCreated = subscription.MonitoredItems.All(item => item.Created);

            if (subscription.Created && allItemsCreated)
            {
                return streamHandler;
            }
            else
            {
                try
                {
                    await subscription.DeleteAsync(false, ct);
                    session.RemoveSubscription(subscription);
                }
                catch
                {
                    // Ignore errors during cleanup
                }

                if (attempt >= maxRetries)
                {
                    return null;
                }
            }
        }
    }

    private PLCStreamHandler(/**/, Session session, /**/, Subscription subscription) : base(/**/)
    {
        _session = session;
        _subscription = subscription;
		// ...
    }

    public record MonitoredItemHandle(/**/);

    private void FastDataChangeCallback(Subscription subscription, DataChangeNotification notification, IList<string> stringTable)
    {
        // ...
    }

    public override async ValueTask DisposeAsync()
    {
        try
        {

            if (_subscription != null)
            {
                await _subscription.DeleteAsync(false);
                _session.RemoveSubscription(_subscription);
                // _subscription.Dispose();
            }
        }
        catch
        {
            return;
        }
    }
};

The client requests a stream from the server which uses the async enumerator to stream the notifications to the client (using GRPC).
Indeed it is possibly, that the first stream handler might not be fully disposed yet when the next request to the GRPC server is made.
The client just stop consuming the GRPC stream which triggers the clean-up on the server-side, but meanwhile the client is possibly sending another request already.

[romanett]

@Yamahari thank you for the information this Helps a lot. Can you also provide the Stacktrace where exactly the BadSubscriptionIdInvalid SRE is thrown?

[Yamahari]

No active exception is thrown the application just kept running. The symptom was that the change callback was never called and the client got stuck waiting forever. I debugged and saw that the status of the monitored items is BadSubscriptionIdInvalid when this happens which should not be possible after the subscription has been created successfully?

[romanett]

@Yamahari Okay this is important. Unfortunately I cannot reproduce this. by adapting the Client Test Code to your Service Calls. Can you maybe provide a modified ReferenceClient in a git fork of the Stack that shows this behaviour?

[romanett]

@woutervd3
@Yamahari

Thank you for reporting this.
It is a client issue.

If a publish response is received before the CreateSubscriptionResponse the subscription is closed by the client before the monitored items are created.

I will propose a fix.