failing tests

[oroulet]

does anyone knows why CI tests are failing. they pass locally on my PC

[schroeder-]

Same for me.

[oroulet]

they do not seem to always fail on same line.. Some of them seem to hang forever and some seems to fail in different tests in crypto tests . that is going to be hard to debug..

[oroulet]

at least that test is the one failing or haning in 3 out of 4 failing tests:

• ests/test_crypto_connect.py::test_secure_channel_key_expiration[srv_crypto_one_cert0] PASSED

=================================== FAILURES ===================================
___________ test_secure_channel_key_expiration[srv_crypto_one_cert1] ___________

srv_crypto_one_cert = (OPC UA Server(opc.tcp://127.0.0.1:48516), '/home/runner/work/opcua-asyncio/opcua-asyncio/examples/certificate-3072-example.der')
mocker = <pytest_mock.plugin.MockerFixture object at 0x7f3b70d04250>

    async def test_secure_channel_key_expiration(srv_crypto_one_cert, mocker):
        timeout = 1
        _, cert = srv_crypto_one_cert
        clt = Client(uri_crypto_cert)
        clt.secure_channel_timeout = timeout * 1000
        user_cert = uacrypto.CertProperties(peer_creds['certificate'], "DER")
        user_key = uacrypto.CertProperties(
            path=peer_creds['private_key'],
            extension="PEM",
        )
        server_cert = uacrypto.CertProperties(cert)
        await clt.set_security(
            security_policies.SecurityPolicyBasic256Sha256,
            user_cert,
            user_key,
            server_certificate=server_cert,
            mode=ua.MessageSecurityMode.SignAndEncrypt
        )
        async with clt:
            assert clt.uaclient.security_policy.symmetric_cryptography.Prev_Verifier is None
            assert clt.uaclient.security_policy.symmetric_cryptography.Prev_Decryptor is None
    
            await asyncio.sleep(timeout)
            sym_crypto = clt.uaclient.security_policy.symmetric_cryptography
            prev_verifier = sym_crypto.Prev_Verifier
            prev_decryptor = sym_crypto.Prev_Decryptor
>           assert isinstance(prev_verifier, Verifier)
E           assert False
E            +  where False = isinstance(None, Verifier)

tests/test_crypto_connect.py:313: AssertionError
------------------------------ Captured log setup ------------------------------
INFO     asyncua.server.internal_session:internal_session.py:45 Created internal session Internal
INFO     asyncua.server.address_space:address_space.py:292 add_node: while adding node NumericNodeId(Identifier=15957, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>), requested parent node NumericNodeId(Identifier=11715, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>) does not exists
INFO     asyncua.server.address_space:address_space.py:292 add_node: while adding node NumericNodeId(Identifier=15958, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>), requested parent node NumericNodeId(Identifier=15957, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>) does not exists
INFO     asyncua.server.address_space:address_space.py:292 add_node: while adding node NumericNodeId(Identifier=15959, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>), requested parent node NumericNodeId(Identifier=15957, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>) does not exists
INFO     asyncua.server.address_space:address_space.py:292 add_node: while adding node NumericNodeId(Identifier=15960, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>), requested parent node NumericNodeId(Identifier=15957, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>) does not exists
INFO     asyncua.server.address_space:address_space.py:292 add_node: while adding node NumericNodeId(Identifier=15961, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>), requested parent node NumericNodeId(Identifier=15957, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>) does not exists
INFO     asyncua.server.address_space:address_space.py:292 add_node: while adding node NumericNodeId(Identifier=15962, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>), requested parent node NumericNodeId(Identifier=15957, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>) does not exists
INFO     asyncua.server.address_space:address_space.py:292 add_node: while adding node NumericNodeId(Identifier=15963, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>), requested parent node NumericNodeId(Identifier=15957, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>) does not exists
INFO     asyncua.server.address_space:address_space.py:292 add_node: while adding node NumericNodeId(Identifier=15964, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>), requested parent node NumericNodeId(Identifier=15957, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>) does not exists
INFO     asyncua.server.address_space:address_space.py:292 add_node: while adding node NumericNodeId(Identifier=16134, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>), requested parent node NumericNodeId(Identifier=15957, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>) does not exists
INFO     asyncua.server.address_space:address_space.py:292 add_node: while adding node NumericNodeId(Identifier=16135, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>), requested parent node NumericNodeId(Identifier=15957, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>) does not exists
INFO     asyncua.server.address_space:address_space.py:292 add_node: while adding node NumericNodeId(Identifier=16136, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>), requested parent node NumericNodeId(Identifier=15957, NamespaceIndex=0, NodeIdType=<NodeIdType.Numeric: 2>) does not exists
WARNING  asyncio:base_events.py:1782 Executing <Task pending coro=<_wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/site-packages/pytest_asyncio/plugin.py:275> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/futures.py:351, <TaskWakeupMethWrapper object at 0x7f3b6e4cd450>()] created at /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py:395> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py:157] created at /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py:566> took 2.357 seconds
WARNING  asyncio:base_events.py:1782 Executing <Task pending coro=<_wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/site-packages/pytest_asyncio/plugin.py:275> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/futures.py:351, <TaskWakeupMethWrapper object at 0x7f3b6f49c850>()] created at /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py:395> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py:157] created at /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py:566> took 0.130 seconds
INFO     asyncua.server.internal_server:internal_server.py:172 starting internal server
INFO     asyncio:base_events.py:1414 <Server sockets=[<socket.socket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 48516)>]> is serving
INFO     asyncua.server.binary_server_asyncio:binary_server_asyncio.py:138 Listening on 127.0.0.1:48516
------------------------------ Captured log call -------------------------------
INFO     asyncua.client.client:client.py:273 connect
INFO     asyncua.client.ua_client.UaClient:ua_client.py:281 opening connection
INFO     asyncua.server.binary_server_asyncio:binary_server_asyncio.py:40 New connection from ('127.0.0.1', 52736)
INFO     asyncua.client.ua_client.UASocketProtocol:ua_client.py:212 open_secure_channel
INFO     asyncua.client.ua_client.UaClient:ua_client.py:311 create_session
INFO     asyncua.server.uaprocessor:uaprocessor.py:168 Create session request (None)
INFO     asyncua.server.internal_session:internal_session.py:45 Created internal session ('127.0.0.1', 52736)
INFO     asyncua.server.internal_session:internal_session.py:55 Create session request
INFO     asyncua.server.internal_server:internal_server.py:204 get endpoint
INFO     asyncua.client.client:client.py:101 find_endpoint [EndpointDescription(EndpointUrl='opc.tcp://127.0.0.1:48516', Server=ApplicationDescription(ApplicationUri='urn:freeopcua:python:server', ProductUri='urn:freeopcua.github.io:python:server', ApplicationName=LocalizedText(Locale=None, Text='FreeOpcUa Python Server'), ApplicationType_=<ApplicationType.ClientAndServer: 2>, GatewayServerUri=None, DiscoveryProfileUri=None, DiscoveryUrls=['opc.tcp://127.0.0.1:48516']), ServerCertificate=b'0\x82\x04k0\x82\x02\xd3\xa0\x03\x02\x01\x02\x02\x14\n\x86\xf9uy\x08\xea\xb6\xf5_S6\x0b+\x11H1F\'\xc00\r\x06\t*\x86H\x86\xf7\r\x01\x01\x0b\x05\x000E1\x0b0\t\x06\x03U\x04\x06\x13\x02AU1\x130\x11\x06\x03U\x04\x08\x0c\nSome-State1!0\x1f\x06\x03U\x04\n\x0c\x18Internet Widgits Pty Ltd0\x1e\x17\r200225030457Z\x17\r291114030457Z0E1\x0b0\t\x06\x03U\x04\x06\x13\x02AU1\x130\x11\x06\x03U\x04\x08\x0c\nSome-State1!0\x1f\x06\x03U\x04\n\x0c\x18Internet Widgits Pty Ltd0\x82\x01\xa20\r\x06\t*\x86H\x86\xf7\r\x01\x01\x01\x05\x00\x03\x82\x01\x8f\x000\x82\x01\x8a\x02\x82\x01\x81\x00\xbd\x80\xa3cH\xc6\xdc\xb2I\x1aU0\x14\x07\xa0\x02MM\x0e\xae5\xa1Z\x03#S:I\xf3\xa4,\xa0/\xc0\xc1\x8f\xce\x9b\xf0w\x8d:\x10\xae\x9a\xdb@4\x08\xf8\xb1\xf5\x07\xad\xd2\x8c{U5\xfbn\xf8\xe4\xf2[\xb2\xab\xac\xb4\xfa\xd2\xcer\xce\xb8\xcd\xd3\xaa \x00\x95(T\xc4\xfb\xde\x0c\xdf\x9a]\x05O\x0e\xba&$\xcdLZ\xec>L\xa2rcp\xe5\xba\x19\xb4(\xb8\xfct\x8dz\xd1qy\xd5\x0f]"\xe3%\xe2j\xa3\x9eh\xaaS\x13\x1e\x02>\xd7\xd5\xa9\xf8\x82\xc2D\xab\xd4\xa6f\xed\xe2`T\xc4q\xd7\x94\xcfwt\xe3\xb0\xeaL`\x12\x05\x93*\xa6T\xc8\xfb$\xf8\t\x8d#nI\xde\xb6\x10\xad\xab\xa8\x8a\xc7\xa7\xdf\x97"\xec\xe6\x0eX\xcb\x1f\xd3c\xbeq\xa5_\xcc\x15G\xae\xbc6;L`\xbe\xbf\x9cLL\xd6\x8cL6\x90k\xa1\xb0\x9d\xbca0\x83\xf3\x18\xc6\x15\x04\xb1>I\'\xbdpGm\xa5\x13\x95\x9a\xd4K\xb5\x07\xd7F\x1f\x90\xfaS\xad\x96\xd3\x08\xf5Z\x1b\xc6~\xe7\x85\xc5B]\xbe\x9b\xf8\xfa\xaf\xcfB\x05\xc0\xa3\x05X\xfc\x9e.>$\x1d\x06"\xf5Z\xd5#\xe9\xa4\x03\x92\xa6$+\xa8Hf\xd3]\x15x\x9c\xffo\x83\xee;\xeeY\xf70\\W\xce\xf0\xb4J\xc0\x1f7`\xf3KN\x1fL\xe1y\xc2\x04\xd8c\xe2\x0c"z\xb9\x1f\xf1\xfb\x00\x90\x85\xe5_\x19\x13\xa2w98\x1b>\xbb@\x8d\xf7\x8a\xafm/\xe4l#\xbbS\xdcr\xa6\xe5\x0e\xbbq\xe0M\xd3k\x02\x03\x01\x00\x01\xa3S0Q0\x1d\x06\x03U\x1d\x0e\x04\x16\x04\x14,\x08\x1d\xdd\x12\xb2\xca\xb7(\xee\xa0L\xe84\xc3\x82\xe7\x02\xe3\xaa0\x1f\x06\x03U\x1d#\x04\x180\x16\x80\x14,\x08\x1d\xdd\x12\xb2\xca\xb7(\xee\xa0L\xe84\xc3\x82\xe7\x02\xe3\xaa0\x0f\x06\x03U\x1d\x13\x01\x01\xff\x04\x050\x03\x01\x01\xff0\r\x06\t*\x86H\x86\xf7\r\x01\x01\x0b\x05\x00\x03\x82\x01\x81\x00$\xa6\xb8\x06\x08\xc6\xa3\xe6\xc7\x8f\xc4\x94\xd5\x04):\x80i\xbfU\xc7\xbcY#\x96Zq\x82\xc9\x17Tc.\xb0\x99e\x95\xda\xcc}\xf7\xca\xc9\xfb\xe4\x8f,\xdd\xc3\xa7\xa9\x93:\xfd\xd9\'\xdb##\x8f\xd6l\xdeM\xf6\xe2G\xea\\*\xba\xa24\xa1)\xfa\xf2\x1aI\x18\xb2\x17\xbb\x15\xa3\x94\x9c\x80\xb4\xb6\x92\\\x94\xe0\x87\x861o\x1c%\xb1\xbd\xc1\xc6\xb6\x0b-##br\xece\xfey!\xa2\xf4U(\xe5\xa82\x95\x9e\x19\xbe\xae\xfa>\xeb\xab{\xf0\xba\x90\x04V\x82\xfe\x7f\x0b\x00d\n\xa0\xf6&\xd3\x82\xe9\x19\x8e\xf5\xbb\x12\xf5\x87I\x8cf-\x1a\xb7(\xc9\x1a\x99(\xba/\x8f\xd7\r\x14Q\xb8\xfe\xfa\xa4\xbdGL\xda:3\x1c\x80/%\x94\xcfQ\xc7\xe5\xf3C\x0b\x045\x19\xed\xee\x88M\x91W\x1e2K(M\xfea\\\xa3\x87{\x92\xf1-\x86]\xb6\x13\xb4\x01\xb3\x85\x06\xfd\xdf]\xf9%\xe8\x11\xc1\'\x13A3\x9e#u\xb5*\x81\xddn.\x11\x0e0\xdd\r\x87\xc1`\xd4\xfdEx\xf6=\xd9-\xca\xd6\xe1o\xb6\xe2%\xc0Nn\xcf]\xbc0\xf8l6\xc6\xb3l\x9a\xea\x9a\x9d\xf2\x80\xdb\x03)\xe1}?\x10w\xc9\x83\xfb\xdf\xc7)\xd6\xee\x8f\xba\x9e\xd4\x8a\xe0K\xc3\xc7\x81M\x9f\xe5\xd6\x87\xee0\xe1\x98\xf6\xa7\xff\xd8\xda\xd4"0S$w$p^\x82\xff\n\'\xc5\x88\x06G\xa8\x86-Xd\xb1\x15\xd0%\n\xcc\x9f:z\xd7pt\xea9\x813o\xb8\xe0A\x84\x8ci\xd2a\xed\xe9$\x82', SecurityMode=<MessageSecurityMode.SignAndEncrypt: 3>, SecurityPolicyUri='http://opcfoundation.org/UA/SecurityPolicy#Basic256Sha256', UserIdentityTokens=[UserTokenPolicy(PolicyId='anonymous', TokenType=<UserTokenType.Anonymous: 0>, IssuedTokenType=None, IssuerEndpointUrl=None, SecurityPolicyUri=None), UserTokenPolicy(PolicyId='certificate_basic256sha256', TokenType=<UserTokenType.Certificate: 2>, IssuedTokenType=None, IssuerEndpointUrl=None, SecurityPolicyUri=None), UserTokenPolicy(PolicyId='username', TokenType=<UserTokenType.UserName: 1>, IssuedTokenType=None, IssuerEndpointUrl=None, SecurityPolicyUri=None)], TransportProfileUri='http://opcfoundation.org/UA-Profile/Transport/uatcp-uasc-uabinary', SecurityLevel=0)] <MessageSecurityMode.SignAndEncrypt: 3> 'http://opcfoundation.org/UA/SecurityPolicy#Basic256Sha256'
INFO     asyncua.client.ua_client.UaClient:ua_client.py:323 activate_session
INFO     asyncua.server.uaprocessor:uaprocessor.py:200 Activate session request (None)
INFO     asyncua.server.internal_session:internal_session.py:77 activate session
INFO     asyncua.server.internal_session:internal_session.py:109 Activated internal session ('127.0.0.1', 52736) for user User(role=<UserRole.Admin: 0>, name='test1')
INFO     asyncua.client.ua_client.UASocketProtocol:ua_client.py:212 open_secure_channel
INFO     asyncua.server.uaprocessor:uaprocessor.py:217 Read request (User(role=<UserRole.Admin: 0>, name='test1'))
INFO     asyncua.server.uaprocessor:uaprocessor.py:217 Read request (User(role=<UserRole.Admin: 0>, name='test1'))
INFO     asyncua.client.client:client.py:300 disconnect
INFO     asyncua.client.ua_client.UaClient:ua_client.py:333 close_session
INFO     asyncua.server.uaprocessor:uaprocessor.py:188 Close session request (None)
INFO     asyncua.server.internal_session:internal_session.py:68 close session ('127.0.0.1', 52736)
INFO     asyncua.server.subscription_service:subscription_service.py:59 delete subscriptions: []
INFO     asyncua.server.uaprocessor:uaprocessor.py:196 sending close session response (None)
INFO     asyncua.client.ua_client.UASocketProtocol:ua_client.py:230 close_secure_channel
INFO     asyncua.client.ua_client.UASocketProtocol:ua_client.py:194 Request to close socket received
INFO     asyncua.client.ua_client.UASocketProtocol:ua_client.py:51 Socket has closed connection
---------------------------- Captured log teardown -----------------------------
INFO     asyncua.server.binary_server_asyncio:binary_server_asyncio.py:99 processor returned False, we close connection from ('127.0.0.1', 52736)
INFO     asyncua.server.binary_server_asyncio:binary_server_asyncio.py:142 Closing asyncio socket server
INFO     asyncua.server.binary_server_asyncio:binary_server_asyncio.py:49 Lost connection from ('127.0.0.1', 52736), None
INFO     asyncua.server.uaprocessor:uaprocessor.py:486 Cleanup client connection: ('127.0.0.1', 52736)
INFO     asyncua.server.internal_session:internal_session.py:68 close session ('127.0.0.1', 52736)
INFO     asyncua.server.subscription_service:subscription_service.py:59 delete subscriptions: []
INFO     asyncua.server.internal_server:internal_server.py:183 stopping internal server
INFO     asyncua.server.internal_session:internal_session.py:68 close session Internal
INFO     asyncua.server.subscription_service:subscription_service.py:59 delete subscriptions: []
=========================== short test summary info ============================
FAILED tests/test_crypto_connect.py::test_secure_channel_key_expiration[srv_crypto_one_cert1]
============= 1 failed, 607 passed, 9 skipped in 339.09s (0:05:39) =============
Error: Process completed with exit code 1.

[oroulet]

let's see if diaabling that test changes something.. #1022