Error while renewing session: Invalid security token id 18, expected one of: [16, 17, 0]

[slokhorst]

I have a running client with subscription that does just fine. After a while, I get the following error and the client disconnects:

Exception raised while parsing message from server
Traceback (most recent call last):
  File "/lib/python3.8/site-packages/asyncua/client/ua_client.py", line 79, in _process_received_data
    msg = self._connection.receive_from_header_and_body(header, buf)
  File "/lib/python3.8/site-packages/asyncua/common/connection.py", line 323, in receive_from_header_and_body
    self._check_sym_header(security_header)
  File "/lib/python3.8/site-packages/asyncua/common/connection.py", line 282, in _check_sym_header
    raise ua.UaError(f"Invalid security token id {security_hdr.TokenId}, expected one of: {expected_tokens}")
asyncua.ua.uaerrors._base.UaError: Invalid security token id 18, expected one of: [16, 17, 0]
Error while renewing session
Traceback (most recent call last):
  File "/lib/python3.8/site-packages/asyncua/client/client.py", line 387, in _renew_channel_loop
    val = await self.nodes.server_state.read_value()
  File "/lib/python3.8/site-packages/asyncua/common/node.py", line 167, in read_value
    result = await self.read_data_value()
  File "/lib/python3.8/site-packages/asyncua/common/node.py", line 178, in read_data_value
    return await self.read_attribute(ua.AttributeIds.Value)
  File "/lib/python3.8/site-packages/asyncua/common/node.py", line 285, in read_attribute
    result = await self.server.read(params)
  File "/lib/python3.8/site-packages/asyncua/client/ua_client.py", line 353, in read
    data = await self.protocol.send_request(request)
  File "/lib/python3.8/site-packages/asyncua/client/ua_client.py", line 141, in send_request
    self._send_request(request, timeout, message_type),
  File "/lib/python3.8/site-packages/asyncua/client/ua_client.py", line 130, in _send_request
    self.transport.write(msg)
AttributeError: 'NoneType' object has no attribute 'write'

I'm connecting to a Siemens S7-1200 PLC's built-in OPC-UA server.

[swamper123]

I bet it is happening after ~ 1hr while you are connected the whole time with the Client?

[slokhorst]

It happened approximately 10 minutes after connecting.

[AndreasHeine]

which version of asyncua? does you just subscribe or do you poll also some data cyclic (is there frequent communication between client and server? or just some idle waiting for an datachangeevent for more then 10 min?)

[slokhorst]

python 3.8.6 asyncua 0.8.4

I setup a subscription and then only wait for datachangeevents. These come in approximately once per second. There's no active polling after the setup.

By the way, I've just updated to asyncua 0.9.0 and will report if the issue disappears or remains.

[AndreasHeine]

i tested it with 3.7.3 32bit and asyncua 0.8.4 and an s7-1500

i used this code sniped in an performence optimised way in production and it worked quite well with the s7-1500 (FW 2.6)

async def opcua_client():
    """
    -handles connect/disconnect/reconnect/subscribe/unsubscribe
    -connection-monitoring with cyclic read of the service-level
    """

    print(str(datetime.now()))

    client = Client(url=server_url)
    handler = SubscriptionHandler()
    subscription = None
    case = 1
    subscription_handle_list = []
    idx = 0
    while 1:
        if case == 1:
            #connect
            print("connecting...")
            try:
                await client.connect()
                await client.load_type_definitions()
                print("connected!")
                case = 2
            except:
                print("connection error!")
                case = 1
                await asyncio.sleep(5)
        elif case == 2:
            #subscribe all nodes and events
            print("subscribing nodes and events...")
            try:
                subscription = await client.create_subscription(50, handler)
                subscription_handle_list = []
                if nodes_to_subscribe:
                    for node in nodes_to_subscribe:
                    # for node in nodes_to_subscribe:
                        handle = await subscription.subscribe_data_change(client.get_node(node))
                        subscription_handle_list.append(handle)
                if events_to_subscribe:
                    for event in events_to_subscribe:
                        handle = await subscription.subscribe_events(event[0], event[1])
                        subscription_handle_list.append(handle)
                print("subscribed!")
                case = 3
            except:
                print("subscription error")
                case = 4
                await asyncio.sleep(0)
        elif case == 3:
            #running => read cyclic the service level if it fails disconnect and unsubscribe => wait 5s => connect
            try:
                if users == set():
                    datachange_notification_queue.clear()
                    event_notification_queue.clear()
                service_level = await client.get_node("ns=0;i=2267").get_value()
                if service_level >= 200:
                     case = 3
                 else:
                     case = 4
                await asyncio.sleep(5)
            except:
                case = 4
        elif case == 4:
            #disconnect clean = unsubscribe, delete subscription then disconnect
            print("unsubscribing...")
            try:
                if subscription_handle_list:
                    for handle in subscription_handle_list:
                        await subscription.unsubscribe(handle)
                await subscription.delete()
                print("unsubscribed!")
            except:
                print("unsubscribing error!")
                subscription = None
                subscription_handle_list = []
                await asyncio.sleep(0)
            print("disconnecting...")
            try:
                await client.disconnect()
            except:
                print("disconnection error!")
            case = 0
        else:
            print(str(datetime.now()))
            #wait
            #case = 1 ### i commented this line out to prevent reconnection attempt from application side ###
            await asyncio.sleep(5)

2020-10-14 14:11:27.813102 connecting... Requested session timeout to be 3600000ms, got 30000ms instead connected! subscribing nodes and events... subscribed!

now its 14:32 (14:32-14:11 = 21 min)

which firmeware is on the s7-1200 they changed alot with the last firmware releases!

[AndreasHeine]

made a seccond testrun

2020-10-14 14:47:28.187689 connecting... Requested session timeout to be 3600000ms, got 30000ms instead connected! subscribing nodes and events... subscribed!

now its 16:20 (German time by the way) so more then one hour...

[Randelung]

I have the same issue. It's always a triplet of "Invalid security token id n, expected one of [n-2, n-1, 0]". It's been working fine for the last six months, now suddenly I get the same kind of behavior. The time between errors doesn't seem to have any kind of pattern. It happens both on Windows and Linux. I'm working with different versions of WinCC OA. Both for 0.8.4 and 0.9.0 via pip.

I have subscriptions and I'm polling a node regularly.

I have a Wireshark capture for an immediate error (n=2), maybe that helps. Tested against WinCC OA 3.15p27. opcua.zip

[AndreasHeine]

@Randelung hard to guess you are using encryption...! do you have the same problem without encyption?

@slokhorst do you use encryption aswell?

[oroulet]

I just had a look at code. There is a possible race condition here if we get a new message BEFORE we got time to process the OpenSecureChannelResponse. It might well be the case in the log over. There are only a few milliseconds between the securechannel response and the next message. I am a bit unsure how to fix that in a clean way

[AndreasHeine]

do we have some sort of state of "OpenSecureChannelResponse"? which we can can check before process the msg?

[oroulet]

@Randelung @slokhorst try that one

https://github.com/FreeOpcUa/opcua-asyncio/pull/317

@AndreasHeine not sure. Since we using asyncio we know nothing happens in the background unless we await. But but I do not see where we have an await here... let's see if my ugly stuff abovee solves the issue for them.. obviously they reproduce easily

[AndreasHeine]

@oroulet unfortunately not:

INFO:asyncua.common.subscription:Publish callback called with result: PublishResult(SubscriptionId:849678161, AvailableSequenceNumbers:[20], MoreNotifications:False, NotificationMessage:NotificationMessage(SequenceNumber:20, PublishTime:2020-10-20 11:52:51.767937, NotificationData:[DataChangeNotification(MonitoredItems:[MonitoredItemNotification(ClientHandle:201, Value:DataValue(Value:Variant(val:2020-10-20 11:52:51.201502,type:VariantType.DateTime), StatusCode:StatusCode(Good), SourceTimestamp:2020-10-20 11:52:51.201503, ServerTimestamp:2020-10-20 11:52:51.201502))], DiagnosticInfos:[])]), Results:[StatusCode(Good)], DiagnosticInfos:[])
(Node(i=2258), datetime.datetime(2020, 10, 20, 11, 52, 51, 201502), DataChangeNotification(<asyncua.common.subscription.SubscriptionItemData object at 0x0441F730>, MonitoredItemNotification(ClientHandle:201, 
Value:DataValue(Value:Variant(val:2020-10-20 11:52:51.201502,type:VariantType.DateTime), StatusCode:StatusCode(Good), SourceTimestamp:2020-10-20 11:52:51.201503, ServerTimestamp:2020-10-20 11:52:51.201502))))
INFO:asyncua.client.ua_client.UASocketProtocol:open_secure_channel
INFO:asyncua.client.ua_client.UASocketProtocol:open_secure_channel
ERROR:asyncua.client.ua_client.UASocketProtocol:Exception raised while parsing message from server
Traceback (most recent call last):
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 79, in _process_received_data
    msg = self._connection.receive_from_header_and_body(header, buf)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\connection.py", line 338, in receive_from_header_and_body
    self._check_sym_header(security_header)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\connection.py", line 292, in _check_sym_header
    raise ua.UaError(f"Invalid security token id {security_hdr.TokenId}, expected one of: {expected_tokens}")
asyncua.ua.uaerrors._base.UaError: Invalid security token id 3, expected one of: [1, 2, 0]
INFO:asyncua.client.ua_client.UASocketProtocol:Request to close socket received
INFO:asyncua.client.ua_client.UASocketProtocol:Socket has closed connection
ERROR:asyncua.client.client:Error while renewing session
Traceback (most recent call last):
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\client.py", line 403, in _renew_channel_loop
    val = await self.nodes.server_state.read_value()
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 183, in read_value
    result = await self.read_data_value()
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 194, in read_data_value
    return await self.read_attribute(ua.AttributeIds.Value)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 307, in read_attribute
    result = await self.server.read(params)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 360, in read
    data = await self.protocol.send_request(request)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 147, in send_request
    raise ConnectionError("Connection is closed") from None
ConnectionError: Connection is closed
INFO:asyncua.client.ua_client.UASocketProtocol:open_secure_channel
ERROR:asyncua.client.client:Error while renewing session
Traceback (most recent call last):
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\client.py", line 402, in _renew_channel_loop
    await self.open_secure_channel(renew=True)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\client.py", line 294, in open_secure_channel
    result = await self.uaclient.open_secure_channel(params)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 281, in open_secure_channel
    return await self.protocol.open_secure_channel(params)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 211, in open_secure_channel
    self._send_request(request, message_type=ua.MessageType.SecureOpen),
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 130, in _send_request
    self.transport.write(msg)
AttributeError: 'NoneType' object has no attribute 'write'

[oroulet]

@AndreasHeine can you log with wireshark so we know what is send to us?

[AndreasHeine]

one sec. i am in a meeting ;)

[oroulet]

one sec has passed

[oroulet]

no hast. I have a backlog length near infinity anyway

[AndreasHeine]

@oroulet : trace1.zip

[AndreasHeine]

it does not happen without encryption so maybe its better looking there!? if its like you said:

There are only a few milliseconds between the securechannel response and the next message.

it could be that decryption takes that extra msec's!?

trace2.zip

[oroulet]

Sorry I misunderstood the code and my patch has an errore. That code is strange, most of that code is only for debugging...

I update the PR, can you try again @AndreasHeine ?

[AndreasHeine]

"one sec" (could be more!) ;)

[Randelung]

@Randelung hard to guess you are using encryption...! do you have the same problem without encyption?

But I'm not :O Everything is disabled by design... Why do you think it's encrypted?

[AndreasHeine]

@oroulet no! trace3.zip

@Randelung because i can only reproduce @slokhorst s error with encryption enabled! sadly i dont have wincc oa in the office so i only can test against Siemens S7-1500 OPC UA Server

[oroulet]

@AndreasHeine can you try to debug that stuff directly? add some prints in my changes to see if they are call at all. Maybe I still have a typo left. Is the error message different with my patch? Is "start_renewal" called? Does the error happens Dow manage to process the OpenSeureChannelResponse BEFORE the error? (add prints to know)

[AndreasHeine]

Is the error message different with my patch?

INFO:asyncua.common.subscription:Publish callback called with result: PublishResult(SubscriptionId:849678175, AvailableSequenceNumbers:[20], MoreNotifications:False, NotificationMessage:NotificationMessage(SequenceNumber:20, PublishTime:2020-10-20 13:43:02.289925, NotificationData:[DataChangeNotification(MonitoredItems:[MonitoredItemNotification(ClientHandle:201, Value:DataValue(Value:Variant(val:2020-10-20 13:43:02.201486,type:VariantType.DateTime), StatusCode:StatusCode(Good), SourceTimestamp:2020-10-20 13:43:02.201488, ServerTimestamp:2020-10-20 13:43:02.201486))], DiagnosticInfos:[])]), Results:[StatusCode(Good)], DiagnosticInfos:[])
(Node(i=2258), datetime.datetime(2020, 10, 20, 13, 43, 2, 201486), DataChangeNotification(<asyncua.common.subscription.SubscriptionItemData object at 0x04FB4DD0>, MonitoredItemNotification(ClientHandle:201, Value:DataValue(Value:Variant(val:2020-10-20 13:43:02.201486,type:VariantType.DateTime), StatusCode:StatusCode(Good), SourceTimestamp:2020-10-20 13:43:02.201488, ServerTimestamp:2020-10-20 13:43:02.201486)))) 
INFO:asyncua.client.ua_client.UASocketProtocol:open_secure_channel
INFO:asyncua.client.ua_client.UASocketProtocol:open_secure_channel
ERROR:asyncua.client.ua_client.UASocketProtocol:Exception raised while parsing message from server
Traceback (most recent call last):
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 79, in _process_received_data
    msg = self._connection.receive_from_header_and_body(header, buf)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\connection.py", line 345, in receive_from_header_and_body
    chunk = MessageChunk.from_header_and_body(self.security_policy, header, body)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\connection.py", line 58, in from_header_and_body
    signature)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\crypto\security_policies.py", line 162, in verify
    self.Verifier.verify(data, sig)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\crypto\security_policies.py", line 375, in verify
    raise uacrypto.InvalidSignature
AttributeError: module 'asyncua.crypto.uacrypto' has no attribute 'InvalidSignature'
INFO:asyncua.client.ua_client.UASocketProtocol:Request to close socket received
INFO:asyncua.client.ua_client.UASocketProtocol:Socket has closed connection
ERROR:asyncua.client.client:Error while renewing session
Traceback (most recent call last):
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\client.py", line 403, in _renew_channel_loop
    val = await self.nodes.server_state.read_value()
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 183, in read_value
    result = await self.read_data_value()
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 194, in read_data_value
    return await self.read_attribute(ua.AttributeIds.Value)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 307, in read_attribute
    result = await self.server.read(params)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 361, in read
    data = await self.protocol.send_request(request)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 147, in send_request
    raise ConnectionError("Connection is closed") from None
ConnectionError: Connection is closed
INFO:asyncua.client.ua_client.UASocketProtocol:open_secure_channel
ERROR:asyncua.client.client:Error while renewing session
Traceback (most recent call last):
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\client.py", line 402, in _renew_channel_loop
    await self.open_secure_channel(renew=True)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\client.py", line 294, in open_secure_channel
    result = await self.uaclient.open_secure_channel(params)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 282, in open_secure_channel
    return await self.protocol.open_secure_channel(params)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 212, in open_secure_channel
    self._send_request(request, message_type=ua.MessageType.SecureOpen),
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 130, in _send_request
    self.transport.write(msg)
AttributeError: 'NoneType' object has no attribute 'write'
ERROR:asyncio:Task exception was never retrieved
future: <Task finished coro=<Client._renew_channel_loop() done, defined at C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\client.py:390> exception=AttributeError("'NoneType' object has no attribute 'write'")>
Traceback (most recent call last):
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\client.py", line 402, in _renew_channel_loop
    await self.open_secure_channel(renew=True)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\client.py", line 294, in open_secure_channel
    result = await self.uaclient.open_secure_channel(params)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 282, in open_secure_channel
    return await self.protocol.open_secure_channel(params)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 212, in open_secure_channel
    self._send_request(request, message_type=ua.MessageType.SecureOpen),
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 130, in _send_request
    self.transport.write(msg)
AttributeError: 'NoneType' object has no attribute 'write'

Is "start_renewal" called? Does the error happens?

2xYes!

Dow manage to process the OpenSeureChannelResponse BEFORE the error? (add prints to know)

WIP

[oroulet]

looks like a different error now @AndreasHeine ! module 'asyncua.crypto.uacrypto' has no attribute 'InvalidSignature' Looks likee we pass the tokenid step but hang on something else...

[AndreasHeine]

i am not sure that some of the functions should not be async... need to look tomorow morning! maybe i test also with pthon-opcua.

[AndreasHeine]

small update: renewing session works with encryption in python-opcua!

[oroulet]

strange, the code is different but the logic is exactly the same...

[AndreasHeine]

maybe you see something i miss! it looks like it works only some times after adding some prints...

trace4.zip

DEBUG:asyncua.client.client:renewing channel
INFO:asyncua.client.ua_client.UASocketProtocol:open_secure_channel
before ua.OpenSecureChannelRequest()
after ua.OpenSecureChannelRequest()
SecureConnection start renewal!
after self._connection.start_renewal()
DEBUG:asyncua.client.ua_client.UASocketProtocol:Sending: OpenSecureChannelRequest(TypeId:i=446, RequestHeader:RequestHeader(AuthenticationToken:i=3062946907, Timestamp:2020-10-21 07:18:10.046276, RequestHandle:127, ReturnDiagnostics:0, AuditEntryId:None, TimeoutHint:1000, AdditionalHeader:ExtensionObject(TypeId:i=0, Encoding:0, None bytes)), Parameters:OpenSecureChannelParameters(ClientProtocolVersion:0, RequestType:1, SecurityMode:3, ClientNonce:b'\xa5Km\xbda\xf8*\x19r\x95\xc28\xa6\xd8x9w\xd9\xa3]B\xee\xfa\x02!M\xb6\xa0p\xb0\xab\xe0', RequestedLifetime:3600000))
MESSAGE: 127 Buffer(size:88, data:b'\x01\x00\xc1\x01\x91NThz\xa7\xd6\x01\x7f\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00_\x99\xe33\n\x00\x00\x00\x86MThz\xa7\xd6\x01\x80\xee6\x00 \x00\x00\x00Z\xcf\t\xac\xd9Lz\xfa+\x97g\xd3~^\x8f,wI;D7\x81\xcc\x1e\xf6\xb6p\x00\x03Nd\n')
ERROR:asyncua.client.ua_client.UASocketProtocol:Exception raised while parsing message from server
Traceback (most recent call last):
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 79, in _process_received_data
    msg = self._connection.receive_from_header_and_body(header, buf)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\connection.py", line 346, in receive_from_header_and_body
    chunk = MessageChunk.from_header_and_body(self.security_policy, header, body)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\connection.py", line 58, in from_header_and_body
    signature)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\crypto\security_policies.py", line 162, in verify
    self.Verifier.verify(data, sig)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\crypto\security_policies.py", line 375, in verify
    raise uacrypto.InvalidSignature
AttributeError: module 'asyncua.crypto.uacrypto' has no attribute 'InvalidSignature'
INFO:asyncua.client.ua_client.UASocketProtocol:Request to close socket received
INFO:asyncua.client.ua_client.UASocketProtocol:Socket has closed connection

ua_client.py

    def _process_received_data(self, data: bytes):
        """
        Try to parse received data as asyncua message. Data may be chunked but will be in correct order.
        See: https://docs.python.org/3/library/asyncio-protocol.html#asyncio.Protocol.data_received
        Reassembly is done by filling up a buffer until it verifies as a valid message (or a MessageChunk).
        """
        buf = ua.utils.Buffer(data)
        while True:
            try:
                try:
                    header = header_from_binary(buf)
                except ua.utils.NotEnoughData:
                    self.logger.debug('Not enough data while parsing header from server, waiting for more')
                    self.receive_buffer = data
                    return
                if len(buf) < header.body_size:
                    self.logger.debug(
                        'We did not receive enough data from server. Need %s got %s', header.body_size, len(buf)
                    )
                    self.receive_buffer = data
                    return
                msg = self._connection.receive_from_header_and_body(header, buf)
                self._process_received_message(msg)
                if not buf:
                    return
                # Buffer still has bytes left, try to process again
                data = bytes(buf)
            except Exception:
                self.logger.exception('Exception raised while parsing message from server')
                self.disconnect_socket()
                return

    def _process_received_message(self, msg):
        if msg is None:
            print("MESSAGA IS NONE!")
            pass
        elif isinstance(msg, ua.Message):
            print("MESSAGE:", str(msg.request_id()), str(msg.body()))
            self._call_callback(msg.request_id(), msg.body())
        elif isinstance(msg, ua.Acknowledge):
            print("MESSAGA IS ACK!")
            self._call_callback(0, msg)
        elif isinstance(msg, ua.ErrorMessage):
            print("MESSAGA IS ERR!")
            self.logger.fatal("Received an error: %r", msg)
            self._call_callback(0, ua.UaStatusCodeError(msg.Error.value))
        else:
            raise ua.UaError(f"Unsupported message type: {msg}")

[AndreasHeine]

error happens: Buffer still has bytes left, try to process again

[AndreasHeine]

without encryption: trace5.zip

DEBUG:asyncua.client.client:renewing channel
INFO:asyncua.client.ua_client.UASocketProtocol:open_secure_channel
before ua.OpenSecureChannelRequest()
after ua.OpenSecureChannelRequest()
SecureConnection start renewal!
after self._connection.start_renewal()
DEBUG:asyncua.client.ua_client.UASocketProtocol:Sending: OpenSecureChannelRequest(TypeId:i=446, RequestHeader:RequestHeader(AuthenticationToken:i=1857082371, Timestamp:2020-10-23 06:04:58.704426, RequestHandle:1530, ReturnDiagnostics:0, AuditEntryId:None, TimeoutHint:1000, AdditionalHeader:ExtensionObject(TypeId:i=0, Encoding:0, None bytes)), Parameters:OpenSecureChannelParameters(ClientProtocolVersion:0, RequestType:1, SecurityMode:1, ClientNonce:b'', RequestedLifetime:3600000))
MESSAGE: 1529 Buffer(size:57, data:b'\x01\x00\xc1\x01\x96=\xeb\x7f\x02\xa9\xd6\x01\xf9\x05\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00W\xa4\x9c\xc5z\x00\x00\x00\xef<\xeb\x7f\x02\xa9\xd6\x01\x80\xee6\x00\x01\x00\x00\x00\x01')
after result = await asyncio.wait_for(self._send_request(request, message_type=ua.MessageType.SecureOpen),self.timeout)
DEBUG:asyncua.client.ua_client.UaClient:read
DEBUG:asyncua.client.ua_client.UASocketProtocol:Sending: ReadRequest(TypeId:i=631, RequestHeader:RequestHeader(AuthenticationToken:i=1857082371, Timestamp:2020-10-23 06:04:58.707414, RequestHandle:1531, ReturnDiagnostics:0, AuditEntryId:None, TimeoutHint:4000, AdditionalHeader:ExtensionObject(TypeId:i=0, Encoding:0, None bytes)), Parameters:ReadParameters(MaxAge:0, TimestampsToReturn:0, NodesToRead:[ReadValueId(NodeId:i=2259, AttributeId:13, IndexRange:None, DataEncoding:QualifiedName(0:None))]))
MESSAGE: 1530 Buffer(size:57, data:b'\x01\x00\xc1\x01\xd0\xaf\xeb\x7f\x02\xa9\xd6\x01\xfa\x05\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00W\xa4\x9c\xc5{\x00\x00\x00?\xaf\xeb\x7f\x02\xa9\xd6\x01\x80\xee6\x00\x01\x00\x00\x00\x01')
ERROR:asyncua.client.ua_client.UASocketProtocol:Exception raised while parsing message from server
Traceback (most recent call last):
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 79, in _process_received_data
    msg = self._connection.receive_from_header_and_body(header, buf)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\connection.py", line 343, in receive_from_header_and_body
    self._check_sym_header(security_header)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\connection.py", line 297, in _check_sym_header
    raise ua.UaError(f"Invalid security token id {security_hdr.TokenId}, expected one of: {expected_tokens}")
asyncua.ua.uaerrors._base.UaError: Invalid security token id 123, expected one of: [121, 122, 0]
INFO:asyncua.client.ua_client.UASocketProtocol:Request to close socket received
after result = await asyncio.wait_for(self._send_request(request, message_type=ua.MessageType.SecureOpen),self.timeout)
DEBUG:asyncua.client.ua_client.UaClient:read
DEBUG:asyncua.client.ua_client.UASocketProtocol:Sending: ReadRequest(TypeId:i=631, RequestHeader:RequestHeader(AuthenticationToken:i=1857082371, Timestamp:2020-10-23 06:04:58.726346, RequestHandle:1532, ReturnDiagnostics:0, AuditEntryId:None, TimeoutHint:4000, AdditionalHeader:ExtensionObject(TypeId:i=0, Encoding:0, None bytes)), Parameters:ReadParameters(MaxAge:0, TimestampsToReturn:0, NodesToRead:[ReadValueId(NodeId:i=2259, AttributeId:13, IndexRange:None, DataEncoding:QualifiedName(0:None))]))
INFO:asyncua.client.ua_client.UASocketProtocol:Socket has closed connection
ERROR:asyncua.client.client:Error while renewing session
Traceback (most recent call last):
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\client.py", line 403, in _renew_channel_loop
    val = await self.nodes.server_state.read_value()
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 183, in read_value
    result = await self.read_data_value()
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 194, in read_data_value
    return await self.read_attribute(ua.AttributeIds.Value)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 307, in read_attribute
    result = await self.server.read(params)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 370, in read 
    data = await self.protocol.send_request(request)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 152, in send_request
    raise ConnectionError("Connection is closed") from None
ConnectionError: Connection is closed
ERROR:asyncio:Task exception was never retrieved
future: <Task finished coro=<Client._renew_channel_loop() done, defined at C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\client.py:390> exception=ConnectionError('Connection is closed')>
Traceback (most recent call last):
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\client.py", line 403, in _renew_channel_loop
    val = await self.nodes.server_state.read_value()
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 183, in read_value
    result = await self.read_data_value()
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 194, in read_data_value
    return await self.read_attribute(ua.AttributeIds.Value)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 307, in read_attribute
    result = await self.server.read(params)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 370, in read
    data = await self.protocol.send_request(request)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 152, in send_request
    raise ConnectionError("Connection is closed") from None
ConnectionError: Connection is closed
ERROR:asyncua.client.client:Error while renewing session
Traceback (most recent call last):
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\client.py", line 403, in _renew_channel_loop
    val = await self.nodes.server_state.read_value()
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 183, in read_value
    result = await self.read_data_value()
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 194, in read_data_value
    return await self.read_attribute(ua.AttributeIds.Value)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\common\node.py", line 307, in read_attribute
    result = await self.server.read(params)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 370, in read
    data = await self.protocol.send_request(request)
  File "C:\Users\HeineAn\AppData\Local\Programs\Python\Python37-32\lib\site-packages\asyncua\client\ua_client.py", line 152, in send_request
    raise ConnectionError("Connection is closed") from None
ConnectionError: Connection is closed

[AndreasHeine]

@oroulet our problem is that we make two opensecurechannel requests in short sequence!

[oroulet]

Interesting...

[AndreasHeine]

@oroulet do you know why the client have "renew channel loop"?

client.py:

    async def _renew_channel_loop(self):
        """
        Renew the SecureChannel before the SessionTimeout will happen.
        In theory we could do that only if no session activity
        but it does not cost much..
        """
        try:
            duration = min(self.session_timeout, self.secure_channel_timeout) * 0.7 / 1000
            while True:
                # 0.7 is from spec. 0.001 is because asyncio.sleep expects time in seconds
                await asyncio.sleep(duration)
                if not self.uaclient._connection._renewal_started: # just to figure out if there is an overlapping request
                    _logger.debug("renewing channel")
                    await self.open_secure_channel(renew=True)
                    val = await self.nodes.server_state.read_value()
                    _logger.debug("server state is: %s ", val)
        except asyncio.CancelledError:
            pass
        except:
            _logger.exception("Error while renewing session")
            raise

atm it runs with that (but its not a fix just a test) without issues but it renews channel only on session_timeout!?

[oroulet]

There is a" keep alive "loop

[oroulet]

In client.py

[AndreasHeine]

... fooled myself on the last ones... changed to much in sourcecode... i'll make a clean start on that!

[oroulet]

two questions

• How can renewing the channel two times create an issue? its should nto change anything
• Why do we renew two times. Looking at code we should sleep a quite long time before renewing
  async def _renew_channel_loop(self): """ Renew the SecureChannel before the SessionTimeout will happen. In theory we could do that only if no session activity but it does not cost much.. """ try: duration = min(self.session_timeout, self.secure_channel_timeout) * 0.7 / 1000 while True:

  0.7 is from spec. 0.001 is because asyncio.sleep expects time in seconds

          await asyncio.sleep(duration)
          _logger.debug("renewing channel")
          await self.open_secure_channel(renew=True)
          val = await self.nodes.server_state.read_value()
          _logger.debug("server state is: %s ", val)
  except asyncio.CancelledError:
      pass
  except:
      _logger.exception("Error while renewing session")
      raise

[oroulet]

Also I update the prosys example with crypto and made a session timeout every two seconds. The session got renewed without issues.... Does the script works for someone in that thread against your servers? do you have issues? https://github.com/FreeOpcUa/opcua-asyncio/compare/prosys?expand=1

I used opcua-asyncio master

[oroulet]

Anyway session renewal seems to work with and without encryption in a simple context, so there must be something special in for the failing clients... Not ideas what..

[Randelung]

I'll try again on Monday when I have access to the machine in question. Thanks for your effort so far. Anything I should be looking out for? Special options to set for logging that might help you?

[oroulet]

@Randelung The best is that you use the very simple script called client_to_prosys_crypto.py, change server address (even better disable crypto) then record the session with wireshark and attach it here And make sure you use opcua-asyncio from github master

[AndreasHeine]

@oroulet -double request was my fault!

-still getting invalid signature against prosys and siemens opc ua server (Sign&Encrypt Basic256Sha256) after 10-30min (clean install from github with your fix) without encryption is running atm

[Randelung]

OK so. Please excuse any weird passages or segue ways, I've been writing this post for an hour, revisiting results and changing the text.

First of all, I was able to reproduce the error on more machines than just the one from my colleague. Pure, freshly initialized WinCC OA projects as well as larger, existing projects can trigger this issue. I have a guess what the problem could be farther down.

I ran your example with one little change and it crashed like the other attempts.

ERROR:asyncua.client.ua_client.UASocketProtocol:Exception raised while parsing message from server
Traceback (most recent call last):
  File "..\asyncua\client\ua_client.py", line 79, in _process_received_data
    msg = self._connection.receive_from_header_and_body(header, buf)
  File "..\asyncua\common\connection.py", line 328, in receive_from_header_and_body
    self._check_sym_header(security_header)
  File "..\asyncua\common\connection.py", line 282, in _check_sym_header
    raise ua.UaError(f"Invalid security token id {security_hdr.TokenId}, expected one of: {expected_tokens}")
asyncua.ua.uaerrors._base.UaError: Invalid security token id 2, expected one of: [0, 1, 0]

prosys.zip The change was to take out the sleep between polls. See below.

(I also ran my application again using the github code and I still get the error pretty quickly. First try died at n = 3. gateway.zip)

Looking through the wireshark dump shows that I'm initializing using security policy None, as well as message security mode None. The 'secure channel' packets are just plaintext as far as I can tell, the URNs given in the first few packets are all visible in the byte representation in Wireshark (and so is the 2267 nodeId that I'm polling). There's no obvious signature anywhere. I'm pretty sure that this issue is not limited to active encryption/signature.

I just noticed something that might be interesting. After channel renewal the server switches token immediately despite having an open request with the old token. I don't know if that is expected behavior, but the first time the channel is renewed and DOESN'T crash, there isn't a response at all to the read request.

No reply:

Token 2 before renewal: Token 3 after renewal:

I am constantly blasting out read requests to the server service level node as fast as it will go (for now, later once a second), but that means there's constantly an outstanding read response. That means that chances are pretty good that the channel renewal will happen with such an outstanding response, which is why I see such a quick crash rate. It explains why it hasn't happened yet, since I've only recently implemented connection tracking using a poll (Andreas might remember my ticket). I've only found this passage in the spec, which would make the exchange valid:

The Client shall continue to accept the old SecurityToken until it receives the OpenSecureChannel response. The Server has to accept requests secured with the old SecurityToken until that SecurityToken expires or until it receives a Message from the Client secured with the new SecurityToken.

(https://reference.opcfoundation.org/v104/Core/docs/Part6/6.7.4/ in the big paragraph below the table.) It doesn't explicitly specify when the switch to a new token needs to happen or is allowed to happen, only the usage of the old token is regulated. However, since the worst case scenario would be a hard switch from one token to the next and accepting an old token for a period of time softens that a little, it's probably fair to say that the response that is being sent with the new token is valid and should be accepted.

A shot in the dark: Could it be that the async nature of the library makes it possible for the new token to not be applied yet when the response packet arrives? You mentioned that the sync version does not have this issue.

I hope I'm not repeating anything you already know... 😄

[swamper123]

I throw my 2 cents into the ring as well:

@Randelung

It doesn't explicitly specify when the switch to a new token needs to happen or is allowed to happen, only the usage of the old token is regulated.

There are two parameters existing in the OpenSecure Channel Parameters:

• requestesLifetime in the request

The requested lifetime, in milliseconds, for the new SecurityToken. Itspecifies when the Client expects to renew the SecureChannel by callingthe OpenSecureChannel Service again. If a SecureChannel is not renewed, then all Messages sent using the current SecurityTokens shallbe rejected by the receiver.Several cryptanalytic attacks become easier as more material encryptedwith a specific key is available. By limiting the amount of data processedusing a particular key, those attacks are made more difficult. Thereforethe volume of data exchanged between Client and Server must belimited by establishing a new SecurityToken after the lifetime.The setting of the requested lifetime depends on the expected number of exchanged messages and their size in the lifetime. A higher volume of data requires shorter lifetime.

• revisedLifetime in the response

The lifetime of the SecurityToken in milliseconds. The UTC expirationtime for the token may be calculated by adding the lifetime to the created At time

So there is a limit, but they are set by us....anywhere....

I just noticed something that might be interesting. After channel renewal the server switches token immediately despite having an open request with the old token. I don't know if that is expected behavior, but the first time the channel is renewed and DOESN'T crash, there isn't a response at all to the read request.

The missing response of your paket 568 is Paket 571 (see RequestHandle parameter). (if this was your missing one) From the specs:

The RevisedLifetime tells the Client when it shall renew the SecurityToken by sending another OpenSecureChannel request. The Client shall continue to accept the old SecurityToken until it receives the OpenSecureChannel response. The Server has to accept requests secured with the old SecurityToken until that SecurityToken expires or until it receives a Message from the Client secured with the new SecurityToken.

So it is okay that the Security Token is still the old one after OpenSecureChannelRequest, but it has to change when the OpenSecureChannelResponse was sent.

[swamper123]

A shot in the dark: Could it be that the async nature of the library makes it possible for the new token to not be applied yet when the response packet arrives? You mentioned that the sync version does not have this issue.

That this can be an asyncio issue may be possible, but then the better question would be "where would asyncio be the problem". Since I am lacking of matching SPS Hardware, I am not able to debug it myself (I may should ask if I get one in near future anyway...). I could imagine, that with an inconvenient order in the eventloop, a ReadResponse message with the new Token may be read, before the actual OpenSecureChannelResponse was executed. So on Wireshark this may be look right, but what the eventloop does, what Task is executed at the moment and how the order is, is unknown (if you know any trick to get these informations, please let us/me know).

[Randelung]

So I've been looking into the receive code on the client side and I gotta say it's kinda weird. There is no central buffer. Each call for data_received gets its own, which means that while the TCP packets are being processed in order, close sequential incoming packets will immediately enqueue execution, which means that the second packet will trigger its header parse etc. as soon as the future for open_channel is returned - without the open_channel method actually finishing first. Implementing a central buffer will make sure that telegrams are being processed in order and allow asyncio integration. Creating a new task after extending the buffer allows for the telegrams in the queue to be processed in order while giving access to asyncio.Locks. The lock allows the open channel reply to lock out the other telegrams until it's applied. The other telegrams then continue on where they left off (typical asyncio style).

[oroulet]

So I've been looking into the receive code on the client side and I gotta say it's kinda weird.

they are beeing processed in order yes.This is fine since packets are ordered when using TCP. There might be a theoretical issue if a packets requires a long processing and MUST be processed before another one. But as far as I know there is only one case and this is the secure open stuff. I opened a merge request to attempt to fix that race condition but as far as I know it did not help. so either there is a bug in my patch or it is something else...

I am a bit afraid of locking here, but maybe it is also possible to process the OpenSecureChannel immediatly in the receving loop...

[Randelung]

I understand if you're cautions with locks. Seems possible, the code after the future returns is all synchronous. I'll have another look tonight or something, probably make another pull request based on the original code. Which branch was the one that you attempted to fix the race condition? I based this PR on #320, so maybe your changes are already factored in.

[Randelung]

I'm about to push a new pull request with a different approach, just testing the pypy version, too.