Received DataChangeNotification without Value has changed

[Scheibengraber]

Describe the bug

We receive data change notificications from a Siemens S7 1517 (Firmware 2.9.4) OPC UA server with asyncua version 1.1.5.

Console output:

C:\>python scratchfile_opcua_client.py
Requested session timeout to be 3600000ms, got 30000ms instead
Revised values returned differ from subscription values: CreateSubscriptionResult(SubscriptionId=3410194732, RevisedPublishingInterval=200.0, RevisedLifetimeCount=1000, RevisedMaxKeepAliveCount=150)
datachange_notification for node ns=5;i=6010: DataValue(Value=Variant(Value=False, VariantType=<VariantType.Boolean: 1>, Dimensions=None, is_array=False), StatusCode_=StatusCode(value=0), SourceTimestamp=datetime.datetime(2024, 7, 24, 15, 44, 11, 97178, tzinfo=datetime.timezone.utc), ServerTimestamp=datetime.datetime(2024, 7, 24, 15, 44, 11, 97178, tzinfo=datetime.timezone.utc), SourcePicoseconds=None, ServerPicoseconds=None)
datachange_notification for node ns=5;i=6010: DataValue(Value=Variant(Value=False, VariantType=<VariantType.Boolean: 1>, Dimensions=None, is_array=False), StatusCode_=StatusCode(value=0), SourceTimestamp=datetime.datetime(2024, 7, 24, 15, 49, 21, 96451, tzinfo=datetime.timezone.utc), ServerTimestamp=datetime.datetime(2024, 7, 24, 15, 49, 21, 96451, tzinfo=datetime.timezone.utc), SourcePicoseconds=None, ServerPicoseconds=None)

To Reproduce

You can use the following script to reproduce the issue. Please exchange the variables host, port and node id "ns=5;i=6010" with your node id in your OPCUA server.

"""OPCUA client"""
import asyncio
import logging

from typing import List

from asyncua import Client, Node, ua
from asyncua.ua.uatypes import StatusCode

NodeList = List[str]

LOGGER = logging.getLogger()


class SubscriptionHandler:
    """The SubscriptionHandler is used to handle the data that is received for the subscription."""

    async def datachange_notification(self, node: Node, value, data):
        """Callback for asyncua Subscription. This method will be called when the Client received a data change message from the Server."""
        LOGGER.error("datachange_notification for node %s: %s", node.nodeid.to_string(), data.monitored_item.Value)


async def start_sub():
    """Start subscription"""
    host = "10.18.168.71"
    port = 4840
    opcUrl = f"opc.tcp://{host}:{port}/"
    client = Client(url=opcUrl, timeout=10)
    params = ua.CreateSubscriptionParameters()
    params.RequestedPublishingInterval = 100
    params.RequestedLifetimeCount = 1000
    params.RequestedMaxKeepAliveCount = 10000
    params.MaxNotificationsPerPublish = 10000
    params.PublishingEnabled = True
    params.Priority = 0

    nodesToSub: List[Node] = []
    node = client.get_node(ua.NodeId.from_string("ns=5;i=6010"))
    nodesToSub.append(node)

    try:
        async with client:
            subscription = await client.create_subscription(params, SubscriptionHandler())
            results = await subscription.subscribe_data_change(nodes=nodesToSub, sampling_interval=10)
            for index, result in enumerate(results):
                nodeid = nodesToSub[index].nodeid.to_string()
                if isinstance(result, StatusCode):
                    LOGGER.error("Subscription error: %s", result.name)
                else:
                    LOGGER.info("Node %s was subscribed successfully.", nodeid)
            while True:
                await asyncio.sleep(1)
                await client.check_connection()  # Throws a exception if connection is lost
    except (ConnectionError, ua.UaError):
        LOGGER.error("Connection lost - reconnecting in 2 seconds")
        await asyncio.sleep(2)
    except asyncio.exceptions.TimeoutError:
        LOGGER.error("Timeout occured - reconnecting in 2 seconds")
        await asyncio.sleep(2)


async def main():
    """Entry point"""
    asyncList = [start_sub()]
    await asyncio.gather(*asyncList)


if __name__ == "__main__":
    asyncio.run(main())

Expected behavior

We would expect if there is no Value change that the datachange_notification callback isn't called. We subscribed the node with the FreeOpcUa client (python lib opcua-client 0.8.4), which has the same issue. The tool Unified Automation UaExpert (version 1.4.21 324) doesn't show a data change notification when we subscribe there the same node in these cases. So we can simply exclude that it is a issue on PLC side. We also assume that the FreeOpcUa client uses the library asyncua, because it has the same issue as our script.

Version

Python-Version: 3.8, 3.12
opcua-asyncio Version (e.g. master branch, 1.1.5):

[AndreasHeine]

you are using "subscribe_data_change" to add a MonitoredItem to the Subscription means a lot of defaults involved

The default for DataChangeFilter.Trigger should be 1 ("STATUS_VALUE") -> "Report a notification if either the StatusCode or the value change"

So from OPC UA Client side it should be only Notifications triggered by Value or StatusCode change in the Queue! The Client just empty's the Queue of Notifications... he can control which trigger to use... but in your case its already "STATUS_VALUE" which is the one you want...

Reference:
https://reference.opcfoundation.org/v105/Core/docs/Part4/7.22.2
https://reference.opcfoundation.org/Core/Part4/v105/docs/7.10#Table134

@oroulet our default is wrong should be 1 ("STATUS_VALUE") and not 0 ("STATUS") but in _subscribe we don't provide it anyways so its fine and not the reason for this issue!

-> https://github.com/FreeOpcUa/opcua-asyncio/blob/1d714983ea2de5760e3bc84fe336863427bf9050/asyncua/ua/uaprotocol_auto.py

[AndreasHeine]

however have you Traced the Boolean Tag in TIA-Portal does it really did not change? not even a PLC cycle? the reason why i ask is because the SamplingInterval can hide these fast changes some times... especially with Queuesize=1 and DiscardOldest (UaExpert defaults)

according to "sampling_interval=10" i doubt the plc can do that... but its just the requested interval it will get revised from the OPC UA Server:

the interesting part is that actually the Timestamp appears to have changed:

SourceTimestamp=datetime.datetime(2024, 7, 24, 15, 44, 11, 97178, tzinfo=datetime.timezone.utc)
SourceTimestamp=datetime.datetime(2024, 7, 24, 15, 49, 21, 96451, tzinfo=datetime.timezone.utc)

looks like the PLC treated the missing DataChangeFilter as "STATUS_VALUE_TIMESTAMP" !?
but i remember a Firmware from Siemens which had this Issue... but i cant tell you which one it was...

[Scheibengraber]

Thank you for your quick answer! I will run the tracing in the TIA portal next Monday and will report the results.

[Scheibengraber]

Today we ran the tracing in the TIA portal. There was no data change visible, but we received during the tracing again data change notifications in the asyncua OPC UA client.

As a next step we will upgrade the PLC to Siemens firmware V3.1.3.

[AndreasHeine]

@Scheibengraber could you be so kind and enable the debug logger in you python client and post the output here in a textfile?

i like to check the requests/responses of the creation of Subscription and MonitoredItems!

logging.basicConfig(level=logging.DEBUG)
_logger = logging.getLogger('asyncua')

[Scheibengraber]

test_opcua.txt

@AndreasHeine I have attached the output with log level DEBUG for the asyncua logger in this comment. You can also see that there are multiple data change notifications where the value of the bool node is always False. Thank you for having a deep look!

[AndreasHeine]

2024-07-29 10:23:37,249 DEBUG MainThread send_request:134 Sending: CreateMonitoredItemsRequest(TypeId=FourByteNodeId(Identifier=751, NamespaceIndex=0, NodeIdType=<NodeIdType.FourByte: 1>), RequestHeader=RequestHeader(AuthenticationToken=NodeId(Identifier=2657001393, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>), Timestamp=datetime.datetime(2024, 7, 29, 8, 23, 37, 249038, tzinfo=datetime.timezone.utc), RequestHandle=7, ReturnDiagnostics=0, AuditEntryId=None, TimeoutHint=10000, AdditionalHeader=ExtensionObject(TypeId=NodeId(Identifier=0, NamespaceIndex=0, NodeIdType=<NodeIdType.TwoByte: 0>), Body=None)), Parameters=CreateMonitoredItemsParameters(SubscriptionId=3160707932, TimestampsToReturn_=<TimestampsToReturn.Both: 2>, ItemsToCreate=[MonitoredItemCreateRequest(ItemToMonitor=ReadValueId(NodeId_=NodeId(Identifier=6010, NamespaceIndex=5, NodeIdType=<NodeIdType.Numeric: 2>), AttributeId=<AttributeIds.Value: 13>, IndexRange=None, DataEncoding=QualifiedName(NamespaceIndex=0, Name=None)), MonitoringMode_=<MonitoringMode.Reporting: 2>, RequestedParameters=MonitoringParameters(ClientHandle=201, SamplingInterval=10, Filter=ExtensionObject(TypeId=NodeId(Identifier=0, NamespaceIndex=0, NodeIdType=<NodeIdType.TwoByte: 0>), Body=None), QueueSize=0, DiscardOldest=True))]))

Filter=ExtensionObject(TypeId=NodeId(Identifier=0, NamespaceIndex=0, NodeIdType=<NodeIdType.TwoByte: 0>)

So the filter is empty -> which should force the server to use default-filter (STATUS_VALUE) ...

https://github.com/FreeOpcUa/opcua-asyncio/blob/1d714983ea2de5760e3bc84fe336863427bf9050/asyncua/ua/uaprotocol_auto.py#L8033C5-L8033C11

i am currently checking how a empty ExtensionObject is getting serialized...

[AndreasHeine]

Source: https://reference.opcfoundation.org/Core/Part4/v104/docs/5.12.2.2#_Ref104715274

Request:

Response:

looks ok so far...

[Scheibengraber]

After upgrading of the Siemens PLC to Firmware V3.1.3 the issue still exists.

[AndreasHeine]

hm thats bad... the client logic is kind of dumb tbh...

can you try to set it manually i updated an example how to set the filter manually:
https://github.com/AndreasHeine/opcua-tutorial/blob/70484d292619f9a3fa842b8352b4459c243baa53/client/subscribe.py#L63

[Scheibengraber]

Hello @AndreasHeine: it is working now. When I leave off the parameter sampling_interval then I have the issue. If I set it then it works as expected.

[AndreasHeine]

@Scheibengraber

the default is 0.0 in:

opcua-asyncio/asyncua/common/subscription.py

Line 255 in 1fe61df

async def subscribe_data_change(

which would be "0: Eventbased (as fast as possible)"

-1: Inherit from PublishInterval
0: Eventbased (as fast as possible)
x: requested samping time (might be revised by the server)

thats weird... the sampling interval has not much to do with the datachange trigger... but ok!

Reference:
https://reference.opcfoundation.org/Core/Part4/v104/docs/5.12.1.2

A Client shall define a sampling interval of 0 if it subscribes for Events.

@oroulet maybe 0.0 is not a good default value ^^