Connecting to a real PLC: UASocketProtocol:ServiceFault, BadSessionNotActivated

[hirsche]

Describe the bug

I am connecting to an OPC UA server of a B&R PLC but receiving the error: UASocketProtocol:ServiceFault (BadSessionNotActivated ...). The same code works fine when connecting to an opcua-asyncio server and not to the B&R PLC. However, the implementation of the B&R PLC seem also to be correct, because when connecting with UA Expert everything works as expected. Also, those PLCs are professional grade products which are up-to-date regarding the software stack.

Interestingly, when the PLC is configured to allow security None, also the opcua-asyncio client framework can access the real B&R PLC without any issues.

Any help would be really appreciated, although I know it might be difficult to reproduce without an actual B&R PLC. I've not yet access to the server logs. I will add them when available.

To Reproduce
Code to reproduce it is more or less the same like in client-with-encryption.py in the examples folder. Nevertheless, here is the code:

        client = Client(url=url)
        client.set_user('***')
        client.set_password('***')

        host_name = socket.gethostname()
        client_app_uri = f"urn:{host_name}:client"
        certificate: Path = Path(Path(__file__).parent.parent / "./key/cert.pem")
        private_key: Path = Path(Path(__file__).parent.parent / "./key/key.pem")

        client.application_uri = client_app_uri

        await setup_self_signed_certificate(private_key,
                                            certificate,
                                            client_app_uri,
                                            host_name,
                                            [ExtendedKeyUsageOID.CLIENT_AUTH],
                                            {
                                                'countryName': '***',
                                                'stateOrProvinceName': '***',
                                                'localityName': '***',
                                                'organizationName': '***',
                                                'commonName': '***'
                                            })

        await client.set_security(
            SecurityPolicyBasic256Sha256,
            private_key=str(private_key),
            certificate=str(certificate))

Expected behavior
A secure connection

Exception Stack

INFO:asyncua.client.ua_client.UaClient:activate_session
WARNING:asyncua.client.ua_client.UASocketProtocol:ServiceFault (BadSessionNotActivated, diagnostics: DiagnosticInfo(SymbolicId=None, NamespaceURI=None, Locale=None, LocalizedText=None, AdditionalInfo=None, InnerStatusCode=None, InnerDiagnosticInfo=None)) from server received  in response to ReadRequest
ERROR:asyncua.client.client:Error in watchdog loop
Traceback (most recent call last):
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\client\client.py", line 551, in _monitor_server_loop
    _ = await self.nodes.server_state.read_value()
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\common\node.py", line 207, in read_value
    result = await self.read_data_value()
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\common\node.py", line 220, in read_data_value
    return await self.read_attribute(ua.AttributeIds.Value, None, raise_on_bad_status)
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\common\node.py", line 342, in read_attribute
    result = await self.session.read(params)
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\client\ua_client.py", line 404, in read
    data = await self.protocol.send_request(request)
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\client\ua_client.py", line 172, in send_request
    self.check_answer(data, f" in response to {request.__class__.__name__}")
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\client\ua_client.py", line 181, in check_answer
    hdr.ServiceResult.check()
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\ua\uatypes.py", line 375, in check
    raise UaStatusCodeError(self.value)
asyncua.ua.uaerrors._auto.BadSessionNotActivated: The session cannot be used because ActivateSession has not been called.(BadSessionNotActivated)
INFO:asyncua.client.ua_client.UaClient:close_session
WARNING:asyncua.client.ua_client.UASocketProtocol:ServiceFault (BadSessionIdInvalid, diagnostics: DiagnosticInfo(SymbolicId=None, NamespaceURI=None, Locale=None, LocalizedText=None, AdditionalInfo=None, InnerStatusCode=None, InnerDiagnosticInfo=None)) from server received  in response to CloseSessionRequest
INFO:asyncua.client.ua_client.UASocketProtocol:close_secure_channel
INFO:asyncua.client.ua_client.UASocketProtocol:Request to close socket received
ERROR:mylogger:error
Traceback (most recent call last):
  File "C:\Users\eduar\scoop\apps\python310\current\lib\asyncio\tasks.py", line 456, in wait_for
    return fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\client\client.py", line 312, in connect
    await self.activate_session(username=self._username, password=self._password, certificate=self.user_certificate)
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\client\client.py", line 631, in activate_session
    return await self.uaclient.activate_session(params)
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\client\ua_client.py", line 346, in activate_session
    data = await self.protocol.send_request(request)
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\client\ua_client.py", line 167, in send_request
    data = await asyncio.wait_for(self._send_request(request, timeout, message_type), timeout if timeout else None)
  File "C:\Users\eduar\scoop\apps\python310\current\lib\asyncio\tasks.py", line 458, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\test-code\opc-ua-connect-bulk.py", line 76, in main
    async with client:
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\client\client.py", line 94, in __aenter__
    await self.connect()
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\client\client.py", line 315, in connect
    await self.close_session()
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\client\client.py", line 703, in close_session
    return await self.uaclient.close_session(True)
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\client\ua_client.py", line 366, in close_session
    data = await self.protocol.send_request(request)
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\client\ua_client.py", line 172, in send_request
    self.check_answer(data, f" in response to {request.__class__.__name__}")
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\client\ua_client.py", line 181, in check_answer
    hdr.ServiceResult.check()
  File "C:\Users\eduar\git\JRZ\streaming-based-ml\code\data-logger\venv\lib\site-packages\asyncua\ua\uatypes.py", line 375, in check
    raise UaStatusCodeError(self.value)
asyncua.ua.uaerrors._auto.BadSessionIdInvalid: The session id is not valid.(BadSessionIdInvalid)
INFO:asyncua.client.client:disconnect
INFO:asyncua.client.ua_client.UaClient:close_session
WARNING:asyncua.client.ua_client.UaClient:close_session but connection wasn't established
WARNING:asyncua.client.ua_client.UaClient:close_secure_channel was called but connection is closed
INFO:asyncua.client.ua_client.UASocketProtocol:Socket has closed connection

Version
Python-Version: 3.10.11 python-opcua: latest from master: asyncua @ git+https://github.com/FreeOpcUa/opcua-asyncio.git@master

[Roshtech21]

hello I have the same issue. Were you able to solve the problem?

[hirsche]

No, unfortunately not. For me, at that time, it was ok to connect non-secure.

[AndreasHeine]

according to the logs you code fails at activate session which is the step in which the user identity is provided (username and password) maybe some certificate stuff as well! so make sure: your cert is accepted by the plc (trusted list), the user/pw is correct.

[hoeflechner]

i ran into thesame issue. but the old sync library: https://github.com/FreeOpcUa/python-opcua works with almost thesame code (except all tha awaits...)

[rnestler]

I had similar issues on a system. Downgrading to 0.9.95 fixed it for us.

[mberetvas]

I am experiencing the same issue. When I investigated with Wireshark, I observed that the client (asyncua) sends an ActivateSessionRequest but does not wait for the ActivateSessionResponse from the server. Instead, it sends a ReadRequest almost 50 ms later, resulting in a BadSessionsNotActivated error.

I'm using the high level Client object, so I presume there is something wrong where it checks if the session is accepted or not.