Inconsistent event notifications in 1.4.365.23

[einarmo]

Type of Issue
[X ] Bug [ ] Enhancement [ ] Compliance [ ] Question [ ] Help wanted

Describe the Issue

After updating to the latest version, a few of my tests related to events started failing. The issue appears to be that for some reason, events are not properly reported, or reported inconsistently. I'm running both client and server libraries.

I'd guess the issue is caused by 1102853 since that appears to be the only commit between the latest two versions that could be responsible, and it seems to be focused on values in monitored items, so it is not unthinkable that it may have caused issues with events.

To Reproduce

1. Subscribe to events on the server, this seems to happen independent of whether events are generated on the server node or on some other node. I tested both with and without filters.
2. Generate events on the node and wait for them to arrive.
3. Generate similar events again.
4. In my case, the second batch never arrives.

Expected behavior
All events should arrive on the client.

Environment (please complete the following information):
.NET Core 5.0, the issue occurs on both windows 10 and debian.

Additional context
This may be difficult to reproduce, but I don't really have time to put together a proper sample. I get completely consistent problems on 1.4.365.23, and none on 1.4.365.10. The issue does not seem to be present if only the client and core libraries are updated to .23, while the server library is kept at .10.

[mregen]

Hi @einarmo, just any additional information you could share would be great. Also wrt to a possible regression due to the hirestimer, is it enabled or disabled or could you check the tests for the hirestimer tests all pass on your platform?

[einarmo]

Hi @einarmo, just any additional information you could share would be great. Also wrt to a possible regression due to the hirestimer, is it enabled or disabled or could you check the tests for the hirestimer tests all pass on your platform?

I'll see if I can put together a proper sample for this issue. There is a lot of irrelevant complexity to the project my tests are for that I don't really want to share here. The project is an OPC-UA client, and the server this issue occurs on is just for testing. I'm using the ReportEvent method on the Server object in CustomNodeManager2 to trigger the events on the server.

I ran the tests for the timer now and they passed even targeting net5.0.

I assume the hirestimer is disabled on my project, as I haven't touched that configuration.

[einarmo]

While I still didn't manage to completely reproduce my issue, I have been able to narrow it down quite a bit. The following basic code fails only if the hi-res-clock is enabled, which it now is by default which explains why this issue only started appearing in my tests in this most recent version.

The following is a rough approximation of my tests. It doesn't behave exactly the same, but it does fail only if the hi-res-clock is enabled.

Code

class Program
{
    static void Main(string[] args)
    {
        try
        {
            Test().Wait();
        }
        catch (Exception ex)
        {
            Console.WriteLine($"Failed: {ex.Message}");
        }
    }
    static async Task Test()
    {
        var app = new ApplicationInstance();
        app.ConfigSectionName = "Opc.Ua.SampleServer";
        await app.LoadApplicationConfiguration("./Opc.Ua.SampleServer.Config.xml", false);
        await app.CheckApplicationInstanceCertificate(false, 0);
        var server = new TestServer();
        await app.Start(server);

        var clientApp = new ApplicationInstance
        {
            ApplicationName = "OPC-UA Test",
            ApplicationType = ApplicationType.Client,
            ConfigSectionName = "Opc.Ua.SampleClient"
        };
        var cfg = await clientApp.LoadApplicationConfiguration("Opc.Ua.SampleClient.Config.xml", false);
        await clientApp.CheckApplicationInstanceCertificate(false, 0);
        var selectedEndpoint = CoreClientUtils.SelectEndpoint("opc.tcp://localhost:51210/UA/SampleServer", false);
        var endpointConfiguration = EndpointConfiguration.Create(cfg);
        var endpoint = new ConfiguredEndpoint(null, selectedEndpoint, endpointConfiguration);

        var session = await Opc.Ua.Client.Session.Create(
            cfg,
            endpoint,
            false,
            "OPC-UA Test",
            0,
            new UserIdentity(new AnonymousIdentityToken()),
            null);

        var sub = new Opc.Ua.Client.Subscription(session.DefaultSubscription)
        {
            PublishingInterval = 1000,
            DisplayName = "Test Subscription"
        };

        bool gotEvent = false;

        void Notification(Opc.Ua.Client.MonitoredItem _, MonitoredItemNotificationEventArgs __)
        {
            Console.WriteLine("Received event");
            gotEvent = true;
        }

        var item = new Opc.Ua.Client.MonitoredItem
        {
            StartNodeId = ObjectIds.Server,
            AttributeId = Attributes.EventNotifier,
            SamplingInterval = 1000,
            Filter = null,
            NodeClass = NodeClass.Object,
            QueueSize = 100
        };
        item.Notification += Notification;

        sub.AddItem(item);
        session.AddSubscription(sub);
        sub.Create();

        await Task.Delay(100);

        for (int i = 0; i < 11; i++)
        {
            server.TriggerEvent();
        }

        for (int i = 0; i < 50; i++)
        {
            if (gotEvent) break;
            await Task.Delay(100);
        }

        if (!gotEvent) throw new Exception("Missed first event");

        gotEvent = false;

        for (int i = 0; i < 11; i++)
        {
            server.TriggerEvent();
        }

        for (int i = 0; i < 50; i++)
        {
            if (gotEvent) break;
            await Task.Delay(100);
        }

        if (!gotEvent) throw new Exception("Missed second event");
    }

}
class TestServer : StandardServer
{
    public void TriggerEvent()
    {
        var evt = new BaseEventState(null);
        evt.EventType = new PropertyState<NodeId>(evt) { Value = ObjectTypeIds.BaseEventType };
        evt.Initialize(ServerInternal.DefaultSystemContext, null, EventSeverity.High, new LocalizedText("Message"));
        ServerInternal.ReportEvent(evt);
    }
}

The config files are taken directly from the samples over in OPCFoundation/UA-.NETStandard-Samples, the only change is in the server config, modifying the DisableHiResClock option.

[AlinMoldovean]

Hello @einarmo ,

I cannot replicate the issue yet.
I am running tests with latest code from master branch and NuGet package version 1.4.365.48.
I tried with both <DisableHiResClock>false</DisableHiResClock> and <DisableHiResClock>true</DisableHiResClock>.

[einarmo]

Hi @AlinMoldovean, I tried again, running this on windows, using version 1.4.365.48. The code I posted above fails only if DisableHiResClock is set to false.

[AlinMoldovean]

Hi @einarmo ,
I could finally reproduce the case.
It seems that Publish responses are not returned by the Server.
Need to further investigate this...

[AlinMoldovean]

@einarmo , @MyLastAngel

The problem occurs in case you have different values for DisableHiResClock setting in Opc.Ua.SampleServer.Config.xml and Opc.Ua.SampleClient.Config.xml.
This seems to be caused by "private static HiResClock s_Default" being set from different threads after Server initialization.
The fix is to start the Server process after the Client, but we need to further check a final solution for this.

static async Task Test()
        {
                var clientApp = new ApplicationInstance {
                ApplicationName = "OPC-UA Test",
                ApplicationType = ApplicationType.Client,
                ConfigSectionName = "Opc.Ua.SampleClient"
            };
            var cfg = await clientApp.LoadApplicationConfiguration("Opc.Ua.SampleClient.Config.xml", false);
            await clientApp.CheckApplicationInstanceCertificate(false, 0);

            var app = new ApplicationInstance();
            app.ConfigSectionName = "Opc.Ua.SampleServer";
            await app.LoadApplicationConfiguration("./Opc.Ua.SampleServer.Config.xml", false);
            await app.CheckApplicationInstanceCertificate(false, 0);
            var server = new TestServer();
            await app.Start(server);

            var selectedEndpoint = CoreClientUtils.SelectEndpoint("opc.tcp://localhost:51210/UA/SampleServer", false);
            var endpointConfiguration = EndpointConfiguration.Create(cfg);
            var endpoint = new ConfiguredEndpoint(null, selectedEndpoint, endpointConfiguration);

A better approach in case you need to run both a UA Client and UA Server component in you application is to have a single ApplicationInstance with ApplicationType.ClientAndServer and a single configuration file.
An example ca be found in UA Sample Client project here:
https://github.com/OPCFoundation/UA-.NETStandard-Samples/blob/8e25524a1357e321f9c8498ba0f8ae12818d3958/Samples/Client.Net4/Program.cs#L45-L66

[einarmo]

@AlinMoldovean Thank you for the explanation. I understand why this happens now. Running two different config files probably isn't viable in my case, since the actual application I'm developing is a pure client, the server is just being used for testing, but knowing the cause makes it simple enough to fix either way.

That said, it seems to me like changing the default value of DisableHiResClock, which was what originally caused this issue for me, might cause more problems than it is worth. At the very least it should be mentioned in the change log. Was there a good reason for that change?

[MyLastAngel]

Hi everyone

Really, if HiResClock.Disabled = true and somewhere in runtime change to false, we lost all monitoredItems changes forever...

Maybe remove Disable flags? I think we dont get trouble with Stopwatch.GetTimestamp...

[AlinMoldovean]

That said, it seems to me like changing the default value of DisableHiResClock, which was what originally caused this issue for me, might cause more problems than it is worth. At the very least it should be mentioned in the change log. Was there a good reason for that change?

@einarmo ,

The change of default value for HiResClock was documented in the release notes of version 1.4.365.23: