FreeOpcUa / opcua-asyncio

OPC UA library for python >= 3.7
GNU Lesser General Public License v3.0
1.12k stars 361 forks source link

We did not receive enough data from server. #1301

Open MatheusLucasAndrade opened 1 year ago

MatheusLucasAndrade commented 1 year ago

Describe the bug
We have a python application that communicates through OPC-UA protocol. In this scenario the python application consumes from IGS (Industrial Gateway Server 7) which is a OPC-UA server. All tags in IGS have a good health status as follow at the screenshot below:

image

After some uncertain time we are facing some problems like reported below:

INFO:asyncua.common.subscription:Publish callback called with result: PublishResult(SubscriptionId=115803, AvailableSequenceNumbers=[14908], MoreNotifications=False, NotificationMessage_=NotificationMessage(SequenceNumber=14908, PublishTime=datetime.datetime(2023, 2, 27, 21, 52, 57, 396516), NotificationData=[DataChangeNotification(MonitoredItems=[MonitoredItemNotification(ClientHandle=223, Value=DataValue(Value=Variant(Value=0.771728515625, VariantType=<VariantType.Float: 10>, Dimensions=None, is_array=False), StatusCode_=StatusCode(value=0), SourceTimestamp=datetime.datetime(2023, 2, 27, 21, 52, 57, 365274), ServerTimestamp=datetime.datetime(2023, 2, 27, 21, 52, 57, 365274), SourcePicoseconds=None, ServerPicoseconds=None))], DiagnosticInfos=[])]), Results=[StatusCode(value=0)], DiagnosticInfos=[]) DEBUG:asyncua.client.ua_client.UaClient:ReadResponse(TypeId=NodeId(Identifier=634, NamespaceIndex=0, NodeIdType=<NodeIdType.FourByte: 1>), ResponseHeader_=ResponseHeader(Timestamp=datetime.datetime(2023, 2, 27, 21, 52, 57, 318387), RequestHandle=16829, ServiceResult=StatusCode(value=0), ServiceDiagnostics=DiagnosticInfo(SymbolicId=None, NamespaceURI=None, Locale=None, LocalizedText=None, AdditionalInfo=None, InnerStatusCode=None, InnerDiagnosticInfo=None), StringTable=[], AdditionalHeader=ExtensionObject(TypeId=NodeId(Identifier=0, NamespaceIndex=0, NodeIdType=<NodeIdType.TwoByte: 0>), Body=None)), Results=[DataValue(Value=Variant(Value=0, VariantType=<VariantType.Int32: 6>, Dimensions=None, is_array=False), StatusCode_=StatusCode(value=0), SourceTimestamp=datetime.datetime(2023, 2, 10, 11, 52, 54, 435066), ServerTimestamp=None, SourcePicoseconds=None, ServerPicoseconds=None)], DiagnosticInfos=[]) DEBUG:asyncua.client.ua_client.UASocketProtocol:We did not receive enough data from server. Need 62 got 4 DEBUG:asyncua.client.ua_client.UASocketProtocol:Sending: ReadRequest(TypeId=FourByteNodeId(Identifier=631, NamespaceIndex=0, NodeIdType=<NodeIdType.FourByte: 1>), RequestHeader_=RequestHeader(AuthenticationToken=NodeId(Identifier=4017216385, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>), Timestamp=datetime.datetime(2023, 2, 27, 21, 59, 27, 355048), RequestHandle=16829, ReturnDiagnostics=0, AuditEntryId=None, TimeoutHint=4000, AdditionalHeader=ExtensionObject(TypeId=NodeId(Identifier=0, NamespaceIndex=0, NodeIdType=<NodeIdType.TwoByte: 0>), Body=None)), Parameters=ReadParameters(MaxAge=0, TimestampsToReturn_=<TimestampsToReturn.Source: 0>, NodesToRead=[ReadValueId(NodeId_=NodeId(Identifier=2259, NamespaceIndex=0, NodeIdType=<NodeIdType.FourByte: 1>), AttributeId=<AttributeIds.Value: 13>, IndexRange=None, DataEncoding=QualifiedName(NamespaceIndex=0, Name=None))])) DEBUG:asyncua.client.ua_client.UaClient:read

DEBUG:asyncua.client.ua_client.UASocketProtocol: We did not receive enough data from server. Need 62 got 4 DEBUG:asyncua.client.ua_client.UASocketProtocol: We did not receive enough data from server. Need 124 got 80 DEBUG:asyncua.client.ua_client.UASocketProtocol: We did not receive enough data from server. Need 50 got 15

After getting these errors the subscribe method stop working and then no more tags are collected. In addition we have tested the same IGS setup with node-red which works properly during our tests

async def connect(self):
        if not self.opc_sub_handler:
            self.opc_sub_handler = OpcuaSubHandler(
                callback=self.callback_function,
                opc_ua_host_address=self.opc_ua_host_address,
                fault_callback=self.fault_callback,
                heart_beat_ms=self.heartbeat_ms,
                tags=self.tags)
        task = asyncio.create_task(self.opc_sub_handler.subscribe())
        return task

async def subscribe(self):
        try:
            await self.client.connect()
            subscription = await self.client.create_subscription(period=self.polling_interval, handler=self)
            self.__instance_nodes(self.client)
            server_time_node = self.client.get_node(self.ping_node_address)
            await subscription.subscribe_data_change(self.nodes)
            while True:
                await server_time_node.read_value()
                await self.client.check_connection()
                await asyncio.sleep(self.heart_beat_ms)
        except Exception as exception:
            await self.client.disconnect()
            self.fault(exception)

To Reproduce
Due uncertain time it's hard to reproduce this behavior. This uncertain time can be since minutes to days.

Expected behavior
Expected behavior would be not stoping the subscribe method.

Version
Python-Version: 3.11
opcua-asyncio Version: 1.0.1:

schroeder- commented 1 year ago

Really hard to check this. But from the log, the server send a smaller packet than it declares in it's header. I think the only we way to help you is to get a wireshark trace. Or you can share a test server which i can test against.