FreeOpcUa / python-opcua

LGPL Pure Python OPC-UA Client and Server
http://freeopcua.github.io/
GNU Lesser General Public License v3.0
1.37k stars 659 forks source link

concurrent.futures._base.TimeoutError #845

Open RensRoodt opened 5 years ago

RensRoodt commented 5 years ago

Hello All,

I'm using this python client, to connect with the a server on a PLC (beckhoff). when it runs for about a hour and 20 minutes, the client gets this error: Traceback (most recent call last): File "C:\Users\rens.op.het.rood\Desktop\Rens\ASML Softwarepack_01\GUI_ADS_OPCUA\SystemFunctions\GuiFunctions.py", line 953, in UpdateSystem self.ReadDasDigitalInfo() File "C:\Users\rens.op.het.rood\Desktop\Rens\ASML Softwarepack_01\GUI_ADS_OPCUA\SystemFunctions\GuiFunctions.py", line 1006, in ReadDasDigitalInfo result, TempCount = self.main.OpcUaConnect.get_value_WithNodeID(TmpAddr) File "C:\Users\rens.op.het.rood\Desktop\Rens\ASML Softwarepack_01\GUI_ADS_OPCUA\OPCUAInterface\UaClient.py", line 76, in get_value_WithNodeID value = var.get_value() File "C:\Python34\lib\site-packages\opcua\common\node.py", line 152, in get_value result = self.get_data_value() File "C:\Python34\lib\site-packages\opcua\common\node.py", line 161, in get_data_value return self.get_attribute(ua.AttributeIds.Value) File "C:\Python34\lib\site-packages\opcua\common\node.py", line 272, in get_attribute result = self.server.read(params) File "C:\Python34\lib\site-packages\opcua\client\ua_client.py", line 326, in read data = self._uasocket.send_request(request) File "C:\Python34\lib\site-packages\opcua\client\ua_client.py", line 78, in send_request data = future.result(self.timeout) File "C:\Python34\lib\concurrent\futures_base.py", line 404, in result raise TimeoutError() concurrent.futures._base.TimeoutError

In issue #526 this issue is discussed and a solution is provided: client = Client("", timeout=60*8) # 8 minutes

I tried this and the result is that the GUI (with OPC UA) freezes for 8 minutes, and then the same error appears. When I run the same test with the UA expert client the UA expert client stays connected. Do you guys have any idea in which direction I could look at to fixe this problem?

libra146 commented 5 years ago

You need to give the smallest code that can reproduce the problem.

oroulet commented 5 years ago

The error means that the server does not answer within a sensible amount of time.... Either your have a bad network or a bad server. Or you also get another error message from server you have not reported

RensRoodt commented 5 years ago

@oroulet The weird thing is that with the UA Expert cliënt i don't get the same problem. On the server side there are no errors reported.

oroulet commented 5 years ago

Maybe there is another error before? Can it be that the session is closed due to another thing?

RensRoodt commented 5 years ago

@oroulet sorry for the late response. i dit some tests, there are no errors before it disconnects. this is the code it gets kicked off every two seconds:

var = self.client.get_node(Nodeid) value = var.get_value()

visued commented 5 years ago

I am the same problem... @RensRoodt you find solution for this? Here in UAExpert no problems...

oroulet commented 5 years ago

There are some error messages missing here. Can you record a session using wireshark until this happens? And put log here

RensRoodt commented 5 years ago

@visued no not yet, what kind of server are you using?

@oroulet yes i will run the test, However when i run the code now it does not connect i get this error: Traceback (most recent call last): File "C:/Users/rens.op.het.rood/Desktop/Rens/GU_OPCUA_bfsr/OPCUA_VS_ADS.py", line 50, in ConnectToPLC self.OpcUaConnect.Connect() File "C:\Users\rens.op.het.rood\Desktop\Rens\GU_OPCUA_bfsr\OPCUAInterface\UaClient.py", line 61, in Connect self.client.connect() File "C:\Python34\lib\site-packages\opcua\client\client.py", line 255, in connect self.open_secure_channel() File "C:\Python34\lib\site-packages\opcua\client\client.py", line 306, in open_secure_channel result = self.uaclient.open_secure_channel(params) File "C:\Python34\lib\site-packages\opcua\client\ua_client.py", line 254, in open_secure_channel return self._uasocket.open_secure_channel(params) File "C:\Python34\lib\site-packages\opcua\client\ua_client.py", line 184, in open_secure_channel future = self._send_request(request, message_type=ua.MessageType.SecureOpen) File "C:\Python34\lib\site-packages\opcua\client\ua_client.py", line 61, in _send_request self._request_id += 1 AttributeError: 'UASocketClient' object has no attribute '_request_id'

connecting with UA expert works, i tried different PLC to connect with and same result. Can you tell me what this error means? i can also make a different issue out of this?

oroulet commented 5 years ago

@RensRoodt I cannot understand that error can happen self._request_id is initiliazed to 0 in constructor so it exists. Are you using an old version? try to update

oroulet commented 5 years ago

these lines have not been changed since 2015... so there is something really strange going on...

RensRoodt commented 5 years ago

@oroulet i think it's my mistake, i tried running on the laptop of a college, and it works fine. So i will look into my code.

RensRoodt commented 5 years ago

@oroulet i found it made an typeO i will runn the test today with wireshark

RensRoodt commented 5 years ago

Here is the wireshark file. i couldn't export the file sow i converted it into an textfile. OPCUA WIRESHARK.txt

the lastmessage is an request for the read function, no response was given.

oroulet commented 5 years ago

txt is very hard to read.... you do not it to export, just save data then upload here diretly or as zip if you get issues

RensRoodt commented 5 years ago

20192406_CaptureFile_OPCUA.zip here is the zip file

oroulet commented 5 years ago

OK there is absoluetely no info in there, but it looks like the session timeout is set to one hour (3600s * 1000) but we do not see any session renewal call, so there is definitely an issue somewhere. Can you use python-opcya from master and hardcode some value there-: https://github.com/FreeOpcUa/python-opcua/blob/master/opcua/client/client.py#L58 set it to one hour (3600) and try. if it works, there is abug somewhere and a PR is welcome

RensRoodt commented 5 years ago

i've run the test i get the same problem

okyame commented 5 years ago

I have the same issue, I think it's because at line https://github.com/FreeOpcUa/python-opcua/blob/7e3140e6269be97e1a8c25802b0c913f0aace585/opcua/client/client.py#L63 this function doesn't manage to renew the connection.

okyame commented 5 years ago

We have this comment on this function : https://github.com/FreeOpcUa/python-opcua/blob/7e3140e6269be97e1a8c25802b0c913f0aace585/opcua/client/ua_client.py#L180

    def open_secure_channel(self, params):
        self.logger.info("open_secure_channel")
        request = ua.OpenSecureChannelRequest()
        request.Parameters = params
        future = self._send_request(request, message_type=ua.MessageType.SecureOpen)

        # FIXME: we have a race condition here
        # we can get a packet with the new token id before we reach to store it..
        response = struct_from_binary(ua.OpenSecureChannelResponse, future.result(self.timeout))
        response.ResponseHeader.ServiceResult.check()
        self._connection.set_channel(response.Parameters)
return response.Parameters
okyame commented 5 years ago

I have this variables values before and after renew:

In function https://github.com/FreeOpcUa/python-opcua/blob/7e3140e6269be97e1a8c25802b0c913f0aace585/opcua/client/client.py#L295

BEFORE RENEW

=>params value:

 OpenSecureChannelParameters(ClientProtocolVersion:0, RequestType:SecurityTokenRequestType.Issue, SecurityMode:MessageSecurityMode.SignAndEncrypt, ClientNonce:b'\xf4~>\x03\xa6\x97xx#\xf8\xbd\x1f\xac\x88\xc4\x17R\x17\x9d\xc3{\xa1\xfb\xc51\xa1\x14A\\\xa6{c', RequestedLifetime:3600000)

=>nonce value:

b'\xf4~>\x03\xa6\x97xx#\xf8\xbd\x1f\xac\x88\xc4\x17R\x17\x9d\xc3{\xa1\xfb\xc51\xa1\x14A\\\xa6{c'

=>Result value: 

OpenSecureChannelResult(ServerProtocolVersion:0, SecurityToken:ChannelSecurityToken(ChannelId:30, TokenId:14, CreatedAt:2019-06-26 10:55:08.781629, RevisedLifetime:3600000), ServerNonce:b'\xc3\xc3o\'#Gnip\xe7.D\x81\xd7W\xcb@m\x92N\xf5\xbf\x82\xffZ\x17"Y\xae\x16\xd0|')

=>self.security_policy value: 

<opcua.crypto.security_policies.SecurityPolicyBasic256Sha256 object at 0x7ff2e2939d68>

=>self.secure_channel_timeout value: 

3600000

AFTER RENEW

=>params value:

OpenSecureChannelParameters(ClientProtocolVersion:0, RequestType:SecurityTokenRequestType.Renew, SecurityMode:MessageSecurityMode.SignAndEncrypt, ClientNonce:b'`\x11"\xe8\xd0\x86p\x06\xb8x\x0b\xc8D\xc7\xf8\xc0\x9e\xf9h\xf5\xf8\xfc\xfb\xca\x02\x93\x7f\xbbUD\nN', RequestedLifetime:3600000)

=>nonce value:

 b'`\x11"\xe8\xd0\x86p\x06\xb8x\x0b\xc8D\xc7\xf8\xc0\x9e\xf9h\xf5\xf8\xfc\xfb\xca\x02\x93\x7f\xbbUD\nN'

=>Result value: 

OpenSecureChannelResult(ServerProtocolVersion:0, SecurityToken:ChannelSecurityToken(ChannelId:30, TokenId:15, CreatedAt:2019-06-26 10:55:28.825645, RevisedLifetime:3600000), ServerNonce:b'W\x9f\xe4A\x7f\x01\xab\\+\n\xa1v\xc4\x9b\x08\x9708\xc3\x83\xde\xd6\x94\xd8 f\xbfI>:\xec\xad')

=>self.security_policy value:  

<opcua.crypto.security_policies.SecurityPolicyBasic256Sha256 object at 0x7ff2e2939d68>

=>self.secure_channel_timeout value: 

3600000
RensRoodt commented 5 years ago

okee looks the same the result? or am i not seeing something?

okyame commented 5 years ago

I notice that the client nonce, the server nonce and the TokenId are different.

okyame commented 5 years ago

And after the renew, client can't contact the server anymore.

oroulet commented 5 years ago

Yes after renew the token and nonce stuff should be different. That stuff used to work, I should have a look. We are also using it...

oroulet commented 5 years ago

And we have beckoff PLC

RensRoodt commented 5 years ago

we are also using Beckhoff. okee thank you @oroulet

RensRoodt commented 5 years ago

i have run some tests again could it be that the "try" is not called.

def run(self): self.logger.debug("starting keepalive thread with period of %s milliseconds", self.timeout) server_state = self.client.get_node(ua.FourByteNodeId(ua.ObjectIds.Server_ServerStatus_State)) while not self._dostop: with self._cond: self._cond.wait(self.timeout / 1000) if self._dostop: break self.logger.debug("renewing channel") try: self.client.open_secure_channel(renew=True) except concurrent.futures.TimeoutError: self.logger.debug("keepalive failed: timeout on open_secure_channel()") break val = server_state.get_value() self.logger.debug("server state is: %s ", val) self.logger.debug("keepalive thread has stopped")

this is in the client.py

okyame commented 5 years ago

The "try" block is called. As I already said: the "self.client.open_secure_channel(renew=True)" function doesn't work fine.

oroulet commented 5 years ago

Add a bunch of print there or use pdb must be possible to understand what is happening

oroulet commented 5 years ago

I just tested locally and the renew stuff is called and channel is renewed

oroulet commented 5 years ago

Works with prosys server too

RensRoodt commented 5 years ago

Sow the conclusion is that in your system it works fine?

oroulet commented 5 years ago

It seems to work. But I believe you, there is probably an issue, but it needs more investigation... Currently I do not know where to look. It seems to work fine with all tests I conducted. Also we use beckoff plcs and we have never had that issue

okyame commented 5 years ago

Hi,

I do some tests in order to reproduce the issue. And it appears only when a certificate is used.

Below the python code I used.

1) First test without certificate

Install the last release version with pip install opcua

The server side:

import sys
import time

from opcua import ua, Server

if __name__ == "__main__":

    # setup our server
    server = Server()
    server.set_endpoint("opc.tcp://0.0.0.0:4840/freeopcua/server/")

    # setup our own namespace, not really necessary but should as spec
    uri = "http://examples.freeopcua.github.io"
    idx = server.register_namespace(uri)

    # get Objects node, this is where we should put our nodes
    objects = server.get_objects_node()

    # populating our address space
    myobj = objects.add_object(idx, "MyObject")
    myvar = myobj.add_variable(idx, "MyVariable", 6.7)
    myvar.set_writable()    # Set MyVariable to be writable by clients

    # starting!
    server.start()

    try:
        count = 0
        while True:
            time.sleep(1)
            count += 0.1
            myvar.set_value(count)
    finally:
        #close connection, remove subcsriptions, etc
        server.stop()

Client side:

import sys
import time

from opcua import Client

if __name__ == "__main__":

    client = Client("opc.tcp://localhost:4840/freeopcua/server/")
    try:
        client.connect()

        root = client.get_root_node()

        while True:
            time.sleep(1)
            myvalue = root.get_child(["0:Objects", "2:MyObject", "2:MyVariable"]).get_value()
            print("myvar value is: ", myvalue)

    finally:
        client.disconnect()

2) Second test with certificate

Server side:

import sys
import time

from opcua import ua, Server

if __name__ == "__main__":

    # setup our server
    server = Server()
    server.set_endpoint("opc.tcp://0.0.0.0:48400/freeopcua/server/")

    server.load_certificate("certificate-example.der")
    server.load_private_key("private-key-example.pem")

    server.set_security_policy([
            # ua.SecurityPolicyType.NoSecurity,
            ua.SecurityPolicyType.Basic256Sha256_SignAndEncrypt,
            #ua.SecurityPolicyType.Basic256Sha256_Sign,
        ])

    server.set_security_IDs([
            # "Anonymous",
            "Basic256Sha256",
            #"Username"
        ])

    # setup our own namespace, not really necessary but should as spec
    uri = "http://examples.freeopcua.github.io"
    idx = server.register_namespace(uri)

    # get Objects node, this is where we should put our nodes
    objects = server.get_objects_node()

    # populating our address space
    myobj = objects.add_object(idx, "MyObject")
    myvar = myobj.add_variable(idx, "MyVariable", 6.7)
    myvar.set_writable()    # Set MyVariable to be writable by clients

    # starting!
    server.start()

    try:
        count = 0
        while True:
            time.sleep(1)
            count += 0.1
            myvar.set_value(count)
    finally:
        #close connection, remove subcsriptions, etc
        server.stop()

Client side:

import sys
import time

from opcua import Client

if __name__ == "__main__":

    client = Client("opc.tcp://localhost:48400/freeopcua/server/")
    client.load_client_certificate("certificate-example.der")
    client.load_private_key("private-key-example.pem")
    client.set_security_string('Basic256Sha256,SignAndEncrypt,certificate-example.der,private-key-example.pem')
    try:
        client.connect()

        root = client.get_root_node()

        while True:
            time.sleep(1)
            myvalue = root.get_child(["0:Objects", "2:MyObject", "2:MyVariable"]).get_value()
            print("myvar value is: ", myvalue)

    finally:
        client.disconnect()

@oroulet Did you use certificate when you did the test with prosys server? Can you check it? The issue appears after 45 minutes for me.

okyame commented 5 years ago

To wait for less time, you have to modify this line :

https://github.com/FreeOpcUa/python-opcua/blob/7e3140e6269be97e1a8c25802b0c913f0aace585/opcua/client/client.py#L58

For example self._cond.wait(60) to wait for 60 seconds.

okyame commented 5 years ago

Sorry, You have to comment time.sleep(1) too.

RensRoodt commented 5 years ago

@okyame do you still have this issue?

parthfsm commented 5 years ago

Hello,

I have been facing this issue for quite some time. I am working on three PLC's Allen Bradley, B&R and Mitsubishi. Some days during testing I get the concurrent.futures._base.TimeoutError. But it doesn't make sense because the requests i send are literally few seconds after I connect to my servers. I use the opcua python library. I have even kept the timeout for 15 minutes. But i face this error within few minutes of connecting.

mxbusch commented 4 years ago

Hey guys,

I am encountering the same error. Unfortunately, I wasn't able to locate the issue. I attached the resulting error below.

I am using a certificate. The client start fully functional, the issue appears about 1 - 45 minutes after I started the client.

Did anyone fixed this issue somehow?

I am thankful for every hint.

Best regards


Traceback (most recent call last):
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/client/ua_client.py", line 101, in _run
    self._receive()
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/client/ua_client.py", line 112, in _receive
    msg = self._connection.receive_from_socket(self._socket)
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/connection.py", line 363, in receive_from_socket
    return self.receive_from_header_and_body(header, ua.utils.Buffer(body))
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/connection.py", line 328, in receive_from_header_and_body
    self._check_sym_header(security_header)
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/connection.py", line 273, in _check_sym_header
    raise ua.UaError("Invalid security token id {}, expected {} or {}"
opcua.ua.uaerrors._base.UaError: Invalid security token id 7, expected 6 or 0
Protocol Error
Traceback (most recent call last):
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/client/ua_client.py", line 101, in _run
    self._receive()
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/client/ua_client.py", line 112, in _receive
    msg = self._connection.receive_from_socket(self._socket)
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/connection.py", line 363, in receive_from_socket
    return self.receive_from_header_and_body(header, ua.utils.Buffer(body))
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/connection.py", line 335, in receive_from_header_and_body
    return self._receive(chunk)
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/connection.py", line 366, in _receive
    self._check_incoming_chunk(msg)
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/connection.py", line 309, in _check_incoming_chunk
    raise ua.UaError(
opcua.ua.uaerrors._base.UaError: Wrong sequence 358 -> 360 (server bug or replay attack)
Protocol Error
Traceback (most recent call last):
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/client/ua_client.py", line 101, in _run
    self._receive()
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/client/ua_client.py", line 112, in _receive
    msg = self._connection.receive_from_socket(self._socket)
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/connection.py", line 363, in receive_from_socket
    return self.receive_from_header_and_body(header, ua.utils.Buffer(body))
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/connection.py", line 335, in receive_from_header_and_body
    return self._receive(chunk)
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/connection.py", line 366, in _receive
    self._check_incoming_chunk(msg)
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/connection.py", line 309, in _check_incoming_chunk
    raise ua.UaError(
opcua.ua.uaerrors._base.UaError: Wrong sequence 358 -> 361 (server bug or replay attack)
Exception in thread Thread-3:
Traceback (most recent call last):
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/client/client.py", line 68, in run
    val = server_state.get_value()
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/node.py", line 153, in get_value
    result = self.get_data_value()
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/node.py", line 162, in get_data_value
    return self.get_attribute(ua.AttributeIds.Value)
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/node.py", line 273, in get_attribute
    result = self.server.read(params)
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/client/ua_client.py", line 337, in read
    data = self._uasocket.send_request(request)
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/client/ua_client.py", line 83, in send_request
    data = future.result(self.timeout)
  File "/home/master/anaconda3/envs/projectname/lib/python3.8/concurrent/futures/_base.py", line 441, in result
    raise TimeoutError()
concurrent.futures._base.TimeoutError
oroulet commented 4 years ago

I got hot by that one selv: File "/home/master/anaconda3/envs/projectname/lib/python3.8/site-packages/opcua/common/connection.py", line 309, in _check_incoming_chunk raise ua.UaError( opcua.ua.uaerrors._base.UaError: Wrong sequence 358 -> 361

So it looks like I will need to have a look... But this is hard to reproduce... Seems to be rather random

SebastianDD commented 4 years ago

So I would also add my experiences to this topic I followed the last months.

I got the same kind of error, when running an opc server with client with certificate enabled after 3/4 of the session timeout.

Additionally I got a TimeoutError when requesting the childs of a node from client-side while the client was started and subscribed to nodes.

ERROR:opcua.common.subscription:Exception calling data change handler Traceback (most recent call last): ...

File "P:\project\subfolders\DataHandler.py", line 174, in get_customized_server_vars all_observed_nodes = self.opc_client.get_server_vars(dir_name)

File "P:\project\subfolders\OPCClient.py", line 196, in get_server_vars obj = self.root.get_child(["0:Objects", ("{}:" + child).format(self.idx)])

File "P:\project\venv\lib\site-packages\opcua\common\node.py", line 469, in get_child result = self.server.translate_browsepaths_to_nodeids([bpath])

File "P:\project\venv\lib\site-packages\opcua\client\ua_client.py", line 417, in translate_browsepaths_to_nodeids data = self._uasocket.send_request(request)

File "P:\project\venv\lib\site-packages\opcua\client\ua_client.py", line 83, in send_request data = future.result(self.timeout)

File "C:\Python37\lib\concurrent\futures\_base.py", line 434, in result raise TimeoutError() concurrent.futures._base.TimeoutError

mxbusch commented 4 years ago

@oroulet

So it looks like I will need to have a look... But this is hard to reproduce... Seems to be rather random

Thank you very much! :-)

Yes, it seems quite random to me too, although I also witnessed (as the others before) that the error seems to appear later when I increase the timeout time in python-opcua/opcua/client/client.py, Line 58: self._cond.wait(self.timeout / 1000) and earlier, when I decrease the timeout time.

If you need additional info regarding my setup or the code in order to locate the issue, please let me know 👍

ghost commented 4 years ago

Hi @mxbuschi

Can you share your code? I am also facing the same error.

oroulet commented 4 years ago

But one again the timeout error does not mean much. There is always another underlying error that breaks the connection

mxbusch commented 4 years ago

@juhiajmera13 : My depicted error appeares also when I use the exemplary client code, just changed the connection parameters for my server. From the error message you posted in the other thread (#948), I am not completely sure that you are facing the same error (at least I am not receiving any "broken pipe" error)? Are you able to connect to your server and are you the receiving data?

ghost commented 4 years ago

@mxbuschi , yes I am. I am receiving data but not for a long time. using this thread, I had changed the self._cond.wait(self.timeout / 1000) as well. Now my code again broke and the error is as following:

Traceback (most recent call last): File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/client/ua_client.py", line 101, in _run self._receive() File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/client/ua_client.py", line 121, in _receive self._call_callback(0, ua.UaStatusCodeError(msg.Error.value)) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/client/ua_client.py", line 131, in _call_callback .format(request_id, self._callbackmap.keys()) opcua.ua.uaerrors._base.UaError: No future object found for request: 0, callbacks in list are dict_keys([7543, 8372, 8649]) Traceback (most recent call last): File "/home/puneedge1/PycharmProjects/FoF/subscriptionV1.py", line 68, in nodeValue = nodeNum.get_value() File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/node.py", line 153, in get_value result = self.get_data_value() File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/node.py", line 162, in get_data_value return self.get_attribute(ua.AttributeIds.Value) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/node.py", line 273, in get_attribute result = self.server.read(params) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/client/ua_client.py", line 337, in read data = self._uasocket.send_request(request) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/client/ua_client.py", line 83, in send_request data = future.result(self.timeout) File "/usr/lib/python3.6/concurrent/futures/_base.py", line 430, in result raise CancelledError() concurrent.futures._base.CancelledError

ghost commented 4 years ago

@oroulet : Not sure what does this error mean. My client code is breaking again and again and I am not able to log the data from the machine, whereas the data on UAExpert is coming perfectly without any error.

ghost commented 4 years ago

This is what I have got now, after changing the time to 60 in self._cond.wait(60). The error is:

Protocol Error Traceback (most recent call last): File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/client/ua_client.py", line 101, in _run self._receive() File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/client/ua_client.py", line 112, in _receive msg = self._connection.receive_from_socket(self._socket) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/connection.py", line 363, in receive_from_socket return self.receive_from_header_and_body(header, ua.utils.Buffer(body)) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/connection.py", line 328, in receive_from_header_and_body self._check_sym_header(security_header) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/connection.py", line 276, in _check_sym_header self.next_security_token.TokenId)) opcua.ua.uaerrors._base.UaError: Invalid security token id 3, expected 2 or 0 Protocol Error Traceback (most recent call last): File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/client/ua_client.py", line 101, in _run self._receive() File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/client/ua_client.py", line 112, in _receive msg = self._connection.receive_from_socket(self._socket) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/connection.py", line 363, in receive_from_socket return self.receive_from_header_and_body(header, ua.utils.Buffer(body)) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/connection.py", line 335, in receive_from_header_and_body return self._receive(chunk) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/connection.py", line 366, in _receive self._check_incoming_chunk(msg) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/connection.py", line 311, in _check_incoming_chunk .format(self._peer_sequence_number, num)) opcua.ua.uaerrors._base.UaError: Wrong sequence 602 -> 604 (server bug or replay attack) Traceback (most recent call last): File "/home/puneedge1/PycharmProjects/FoF/subscriptionV1.py", line 68, in nodeValue = nodeNum.get_value() File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/node.py", line 153, in get_value result = self.get_data_value() File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/node.py", line 162, in get_data_value return self.get_attribute(ua.AttributeIds.Value) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/node.py", line 273, in get_attribute result = self.server.read(params) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/client/ua_client.py", line 337, in read data = self._uasocket.send_request(request) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/client/ua_client.py", line 83, in send_request data = future.result(self.timeout) File "/usr/lib/python3.6/concurrent/futures/_base.py", line 434, in result raise TimeoutError() concurrent.futures._base.TimeoutError Exception in thread Thread-2: Traceback (most recent call last): File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner self.run() File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/client/client.py", line 68, in run val = server_state.get_value() File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/node.py", line 153, in get_value result = self.get_data_value() File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/node.py", line 162, in get_data_value return self.get_attribute(ua.AttributeIds.Value) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/common/node.py", line 273, in get_attribute result = self.server.read(params) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/client/ua_client.py", line 337, in read data = self._uasocket.send_request(request) File "/home/puneedge1/PycharmProjects/FoF/venv/lib/python3.6/site-packages/opcua/client/ua_client.py", line 83, in send_request data = future.result(self.timeout) File "/usr/lib/python3.6/concurrent/futures/_base.py", line 434, in result raise TimeoutError() concurrent.futures._base.TimeoutError

mxbusch commented 4 years ago

@oroulet

But one again the timeout error does not mean much. There is always another underlying error that breaks the connection

If you have any ideas or assumtions where or when the issue arises, I am happy to go into debugging specific functions or provide any logs :-)

oroulet commented 4 years ago

@mxbuschi the interesting part of the stack over is this: opcua.ua.uaerrors._base.UaError: Wrong sequence 602 -> 604 (server bug or replay attack) you need to find out where in the code this is coming from (The chunk management code in that file: ./opcua/common/connection.py:), add more debug and try to understand it. I did not write that code and I would really like to understand why this message pops up sometimes (and breaks the connection) This is a tcp connection between client and server so the order of messages is ensured, in theory we cannot loose a message either, so I do no not understand why some messaged are not received. Maybe there is a bug in the counter...