Fraunhofer-AISEC / ids-clearing-house-service

This is an implementation of the IDS Clearing House
Apache License 2.0
0 stars 11 forks source link

CH integrated tests fail #29

Open christos-aslamatzidis opened 9 months ago

christos-aslamatzidis commented 9 months ago

Hello, My name is Christos Aslamatzidis from European Dynamics S.A. We try to test and configure the Clearing House Service because of the need to explore it and implement it in a project called Enershare.

So far, we have followed the documentation and we have deployed the CH. Our docker-compose.yaml is this :

version: "3.7"
services:
    tc-core-server:
        container_name: "tc-core-server"
        image: fraunhoferaisec/trusted-connector-core:7.2.0
        tty: true
        stdin_open: true
        volumes:
            - /var/run/docker.sock:/var/run/docker.sock
            - ./data/trusted-connector/application.yml:/root/etc/application.yml 
            - ./data/trusted-connector/allow-all-flows.pl:/root/deploy/allow-all-flows.pl
            - ./data/trusted-connector/server-keystore.p12:/root/etc/keystore.p12
            - ./data/trusted-connector/truststore.p12:/root/etc/truststore.p12
            - ./data/trusted-connector/clearing-house-processors-0.10.0.jar:/root/jars/clearing-house-processors.jar
            - ./data/trusted-connector/routes/clearing-house-routes.xml:/root/deploy/clearing-house-routes.xml
        environment:
            TC_DAPS_URL: https://daps-dev.aisec.fraunhofer.de/v4
            SERVICE_SHARED_SECRET: ${SERVICE_SHARED_SECRET}
            TC_CH_ISSUER_CONNECTOR: "https://w3id.org/idsa/core/issuerConnector"
            TC_CH_AGENT: "https://w3id.org/idsa/core/Agent"
            SERVICE_ID_TC: tc-core-server
            SERVICE_ID_LOG: logging-service
        ports:
            - "8443:8443"
            - "9999:9999"
            - "8080:8080"
            - "29292:29292"
        networks:
            - ch_network

    logging-service:
        container_name: "logging-service"
        image: "logging-service:latest"
        depends_on:
            - document-api
            - keyring-api
            - logging-service-mongo
        environment:
            # Allowed levels: Off, Error, Warn, Info, Debug, Trace
            - API_LOG_LEVEL=Debug
            - SERVICE_ID_LOG=logging-service
            - SERVICE_ID_DOC=document-api
            - SERVICE_ID_KEY=keyring-api
            - SHARED_SECRET=${SERVICE_SHARED_SECRET}
        ports:
            - "8000:8000"
        volumes:
            - ./data/Rocket.toml:/server/Rocket.toml
            - ./data/keys:/server/keys
            - ./data/certs:/server/certs
        networks:
            - ch_network

    document-api:
        container_name: "document-api"
        image: "document-api:latest"
        depends_on:
            - keyring-api
            - document-mongo
        environment:
            # Allowed levels: Off, Error, Warn, Info, Debug, Trace
            - API_LOG_LEVEL=Info
            - SERVICE_ID_LOG=logging-service
            - SERVICE_ID_DOC=document-api
            - SERVICE_ID_KEY=keyring-api
            - SHARED_SECRET=${SERVICE_SHARED_SECRET}
        ports:
            - "8001:8001"
        volumes:
            - ./data/document-api/Rocket.toml:/server/Rocket.toml
            - ./data/certs:/server/certs
        networks:
            - ch_network

    keyring-api:
        container_name: "keyring-api"
        image: "keyring-api:latest"
        depends_on:
            - keyring-mongo
        environment:
            # Allowed levels: Off, Error, Warn, Info, Debug, Trace
            - API_LOG_LEVEL=Info
            - SERVICE_ID_LOG=logging-service
            - SERVICE_ID_DOC=document-api
            - SERVICE_ID_KEY=keyring-api
            - SHARED_SECRET=${SERVICE_SHARED_SECRET}
        ports:
            - "8002:8002"
        volumes:
            - ./data/keyring-api/init_db:/server/init_db
            - ./data/keyring-api/Rocket.toml:/server/Rocket.toml
            - ./data/certs:/server/certs
        networks:
            - ch_network

    logging-service-mongo:
        container_name: "logging-service-mongo"
        image: mongo:latest
        environment: 
            MONGO_INITDB_DATABASE: process
        ports:
            - "27019:27017"
        volumes:
            - ./data/mongo/logging-service:/data/db    
        networks:
            - ch_network   

    document-mongo:
        container_name: "document-mongo"
        image: mongo:latest
        environment: 
            MONGO_INITDB_DATABASE: document
        ports:
            - "27017:27017"
        volumes:
            - ./data/mongo/document-api:/data/db    
        networks:
            - ch_network 

    keyring-mongo:
        container_name: "keyring-mongo"
        image: mongo:latest
        environment: 
            MONGO_INITDB_DATABASE: keyring
        ports:
            - "27018:27017"
        volumes:
            - ./data/mongo/keyring-api:/data/db    
        networks:
            - ch_network 
networks:
  ch_network:
    name: ch_network
    driver: bridge

Running the above docker-compose all containers start without issues. Our next though was to test our deployment using the integration tests that were provided in Clearing House Processors following the documentation

Please note that we have changed the host from

127.0.0.1 provider-core

to

127.0.0.1 tc-core-server

Watching Closely the code of clearing house we observe that provider-core has been replaced with tc-core-server. After this modification we were able to reach in some point our CH installation ; however integrated tests fail.

below are the logs of our tests: The common error is this:

 [Test worker] DEBUG de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver - Issue cached DAT: eyJ0eXAiOiJhdCtqd3QiLCJraWQiOiJiMjAzMWVmYWFkMTc4OWExZmQzNjFkYzQ1Y2E4N2FiNjk5MTE5NzlkYjIyMzFiNDc4NzJkMDJiOTU5MWZmMDk4IiwiYWxnIjoiUlMyNTYifQ.eyJzY29wZSI6Imlkc2M6SURTX0NPTk5FQ1RPUl9BVFRSSUJVVEVTX0FMTCIsImF1ZCI6WyJpZHNjOklEU19DT05ORUNUT1JTX0FMTCJdLCJpc3MiOiJodHRwczovL2RhcHMtZGV2LmFpc2VjLmZyYXVuaG9mZXIuZGUvdjQiLCJzdWIiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCIsIm5iZiI6MTcwMDc0OTA0MiwiaWF0IjoxNzAwNzQ5MDQyLCJqdGkiOiI3NzY1ZTJmMC02NWQ3LTRiNDctOWQ4Yi0xOGQxNWJhOTY1NDQiLCJleHAiOjE3MDA3NTI2NDIsImNsaWVudF9pZCI6IkQyOjcwOkZFOjdGOjMyOkJCOjM3OkJGOkRGOkY0OjA4OjM2OjZCOkYxOjlFOjdBOkVCOkE0OjJEOjJBOmtleWlkOkNCOjhDOkM3OkI2Ojg1Ojc5OkE4OjIzOkE2OkNCOjE1OkFCOjE3OjUwOjJGOkU2OjY1OjQzOjVEOkU4IiwidHJhbnNwb3J0Q2VydHNTaGEyNTYiOlsiYWQxN2UxNzg4ODE1MjA1YzIxNDk3ZTZkMzZhMzI0NDYxYzY5YTFiN2U1YzU1OGMzNzhmYjdkZjc5YzVmMDBhNyJdfQ.hFEw9Jiu407h5-rKmwZ9TWEbHJ2cGTmdSXDOReB8Tj3cXWZqS99qvYxGHFAi1q5o5pqtk0V6iw-gXirdbgbH25WwZ8Vz9poTCr2nUte_9FEdPNt1d2VXwhPET9HnyCFeU7JR_gOv1ey0lyg_UiPa1MDLYM5fBUGshVQv-oEQVRHj9vS2vSywvIDeGleIlZeBJkfOoizeNurjgj8LU9C0ftfWl08xV1gAjkiyj1Iglg0WbBrLjvkyrxz6DMZmldrLJjNGIJ7P06kFreIJImpvTqikIssXHC5M9bYkOt6OYe8I2KvL5kbntm31e_7GPFJqNB6OcFQdlrONZblBaFZgQg
[ForkJoinPool.commonPool-worker-1] DEBUG de.fhg.aisec.ids.idscp2.core.fsm.AsyncIdscp2Factory - Starting IDSCP2 handshake for future connection with id a6e4ef6c-51ce-4d1b-9d5f-9380b0ad6c6e
[ForkJoinPool.commonPool-worker-1] DEBUG de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver - Issue cached DAT: eyJ0eXAiOiJhdCtqd3QiLCJraWQiOiJiMjAzMWVmYWFkMTc4OWExZmQzNjFkYzQ1Y2E4N2FiNjk5MTE5NzlkYjIyMzFiNDc4NzJkMDJiOTU5MWZmMDk4IiwiYWxnIjoiUlMyNTYifQ.eyJzY29wZSI6Imlkc2M6SURTX0NPTk5FQ1RPUl9BVFRSSUJVVEVTX0FMTCIsImF1ZCI6WyJpZHNjOklEU19DT05ORUNUT1JTX0FMTCJdLCJpc3MiOiJodHRwczovL2RhcHMtZGV2LmFpc2VjLmZyYXVuaG9mZXIuZGUvdjQiLCJzdWIiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCIsIm5iZiI6MTcwMDc0OTA0MiwiaWF0IjoxNzAwNzQ5MDQyLCJqdGkiOiI3NzY1ZTJmMC02NWQ3LTRiNDctOWQ4Yi0xOGQxNWJhOTY1NDQiLCJleHAiOjE3MDA3NTI2NDIsImNsaWVudF9pZCI6IkQyOjcwOkZFOjdGOjMyOkJCOjM3OkJGOkRGOkY0OjA4OjM2OjZCOkYxOjlFOjdBOkVCOkE0OjJEOjJBOmtleWlkOkNCOjhDOkM3OkI2Ojg1Ojc5OkE4OjIzOkE2OkNCOjE1OkFCOjE3OjUwOjJGOkU2OjY1OjQzOjVEOkU4IiwidHJhbnNwb3J0Q2VydHNTaGEyNTYiOlsiYWQxN2UxNzg4ODE1MjA1YzIxNDk3ZTZkMzZhMzI0NDYxYzY5YTFiN2U1YzU1OGMzNzhmYjdkZjc5YzVmMDBhNyJdfQ.hFEw9Jiu407h5-rKmwZ9TWEbHJ2cGTmdSXDOReB8Tj3cXWZqS99qvYxGHFAi1q5o5pqtk0V6iw-gXirdbgbH25WwZ8Vz9poTCr2nUte_9FEdPNt1d2VXwhPET9HnyCFeU7JR_gOv1ey0lyg_UiPa1MDLYM5fBUGshVQv-oEQVRHj9vS2vSywvIDeGleIlZeBJkfOoizeNurjgj8LU9C0ftfWl08xV1gAjkiyj1Iglg0WbBrLjvkyrxz6DMZmldrLJjNGIJ7P06kFreIJImpvTqikIssXHC5M9bYkOt6OYe8I2KvL5kbntm31e_7GPFJqNB6OcFQdlrONZblBaFZgQg
[Thread-16] DEBUG de.fhg.aisec.ids.idscp2.defaultdrivers.securechannel.tls13.client.TLSClient - Client cannot send data because socket is not in running state anymore.
[ForkJoinPool.commonPool-worker-1] ERROR de.fhg.aisec.ids.clearinghouse.idscp2.Idscp2Client - Client endpoint error occurred
java.util.concurrent.CompletionException: de.fhg.aisec.ids.idscp2.api.error.Idscp2HandshakeException: Handshake failed
    at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:332)
    at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:347)
    at java.base/java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:708)
    at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
    at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162)
    at de.fhg.aisec.ids.idscp2.core.fsm.AsyncIdscp2Factory.initiateIdscp2Connection$lambda$0(AsyncIdscp2Factory.kt:97)
    at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1804)
    at java.base/java.util.concurrent.CompletableFuture$AsyncRun.exec(CompletableFuture.java:1796)
    at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:373)
    at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1182)
    at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1655)
    at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1622)
    at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:165)
Caused by: de.fhg.aisec.ids.idscp2.api.error.Idscp2HandshakeException: Handshake failed
    at de.fhg.aisec.ids.idscp2.core.fsm.FSMImpl.startIdscpHandshake(FSMImpl.kt:377)
    at de.fhg.aisec.ids.idscp2.core.fsm.AsyncIdscp2Factory.initiateIdscp2Connection$lambda$0(AsyncIdscp2Factory.kt:77)
    ... 7 more

java.lang.AssertionError
    at org.junit.Assert.fail(Assert.java:87)
    at org.junit.Assert.assertTrue(Assert.java:42)
    at org.junit.Assert.assertTrue(Assert.java:53)
    at de.fhg.aisec.ids.clearinghouse.idscp2.CreatePidTests$Companion.succCreatePid(CreatePidTests.kt:99)
    at de.fhg.aisec.ids.clearinghouse.idscp2.CreatePidTests$Companion.succCreatePid$default(CreatePidTests.kt:95)
    at de.fhg.aisec.ids.clearinghouse.idscp2.CreatePidTests.createPid2(CreatePidTests.kt:33)
    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
    at java.base/java.lang.reflect.Method.invoke(Method.java:577)
    at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:727)
    at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
    at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:217)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:213)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:138)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:68)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:107)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:88)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:54)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:67)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:52)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
    at org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
    at org.junit.platform.launcher.core.SessionPerRequestLauncher.execute(SessionPerRequestLauncher.java:53)
    at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.processAllTestClasses(JUnitPlatformTestClassProcessor.java:99)
    at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.access$000(JUnitPlatformTestClassProcessor.java:79)
    at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor.stop(JUnitPlatformTestClassProcessor.java:75)
    at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.stop(SuiteTestClassProcessor.java:61)
    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
    at java.base/java.lang.reflect.Method.invoke(Method.java:577)
    at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
    at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
    at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33)
    at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
    at jdk.proxy1/jdk.proxy1.$Proxy2.stop(Unknown Source)
    at org.gradle.api.internal.tasks.testing.worker.TestWorker$3.run(TestWorker.java:193)
    at org.gradle.api.internal.tasks.testing.worker.TestWorker.executeAndMaintainThreadName(TestWorker.java:129)
    at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:100)
    at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:60)
    at org.gradle.process.internal.worker.child.ActionExecutionWorker.execute(ActionExecutionWorker.java:56)
    at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:133)
    at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:71)
    at worker.org.gradle.process.internal.worker.GradleWorkerMain.run(GradleWorkerMain.java:69)
    at worker.org.gradle.process.internal.worker.GradleWorkerMain.main(GradleWorkerMain.java:74)

The logs of TC :

2023-11-23T14:17:38.735Z  INFO 1 --- [qtp629819946-43] .c.ClearingHouseInputValidationProcessor : idsmessage: https://w3id.org/idsa/autogen/logMessage/bd980ef3-8f3f-4dbf-a140-7c627a2c858d
2023-11-23T14:17:38.995Z  INFO 1 --- [qtp629819946-42] .c.ClearingHouseInputValidationProcessor : idsmessage: https://w3id.org/idsa/autogen/queryMessage/c565a02b-46c8-4183-899b-e5d31b4d5db6
2023-11-23T14:17:39.257Z  INFO 1 --- [qtp629819946-43] .c.ClearingHouseInputValidationProcessor : idsmessage: https://w3id.org/idsa/autogen/logMessage/364eb4aa-83d8-477b-b7c4-b2f9a9e2bdc2
2023-11-23T14:17:39.531Z  INFO 1 --- [qtp629819946-42] .c.ClearingHouseInputValidationProcessor : idsmessage: https://w3id.org/idsa/autogen/queryMessage/4232d151-95b9-45dd-be96-5f1bd8eb991a
2023-11-23T14:17:39.663Z  INFO 1 --- [qtp629819946-43] .c.ClearingHouseInputValidationProcessor : idsmessage: https://w3id.org/idsa/autogen/logMessage/67147dfd-58dd-42e5-a697-9090ff0b336d
2023-11-23T14:17:39.965Z  INFO 1 --- [qtp629819946-42] .c.ClearingHouseInputValidationProcessor : idsmessage: https://w3id.org/idsa/autogen/requestMessage/d0c24114-70a4-479c-a1ff-e95f96e87cd8
2023-11-23T14:17:40.049Z  INFO 1 --- [qtp629819946-43] .c.ClearingHouseInputValidationProcessor : idsmessage: https://w3id.org/idsa/autogen/queryMessage/d83cb4b3-df04-45f0-881e-c40ac897f28a
2023-11-23T14:17:40.212Z  INFO 1 --- [qtp629819946-42] .c.ClearingHouseInputValidationProcessor : idsmessage: https://w3id.org/idsa/autogen/logMessage/19935ab7-936f-4300-baff-f80115af9497
2023-11-23T14:17:40.627Z  INFO 1 --- [qtp629819946-43] CH_MULTIPART_ROUTE                       : ### Handle class java.lang.SecurityException ###
2023-11-23T14:17:40.636Z  INFO 1 --- [qtp629819946-43] CH_MULTIPART_ROUTE                       : ### Got java.lang.SecurityException: Access Token did not match presented certificate!
        at de.fhg.aisec.ids.camel.processors.multipart.IdsMultiPartInputProcessor.process(IdsMultiPartInputProcessor.kt:94)
        at org.apache.camel.support.processor.DelegateSyncProcessor.process(DelegateSyncProcessor.java:65)
        at org.apache.camel.support.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:104)
        at de.fhg.aisec.ids.dataflowcontrol.PolicyEnforcementPoint.process(PolicyEnforcementPoint.kt:169)
        at org.apache.camel.support.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:104)
        at org.apache.camel.processor.errorhandler.RedeliveryErrorHandler$RedeliveryTask.doRun(RedeliveryErrorHandler.java:818)
        at org.apache.camel.processor.errorhandler.RedeliveryErrorHandler$RedeliveryTask.run(RedeliveryErrorHandler.java:726)
        at org.apache.camel.impl.engine.DefaultReactiveExecutor$Worker.schedule(DefaultReactiveExecutor.java:189)
        at org.apache.camel.impl.engine.DefaultReactiveExecutor.scheduleMain(DefaultReactiveExecutor.java:61)
        at org.apache.camel.processor.Pipeline.process(Pipeline.java:182)
        at org.apache.camel.impl.engine.CamelInternalProcessor.process(CamelInternalProcessor.java:399)
        at org.apache.camel.component.jetty.CamelContinuationServlet.doService(CamelContinuationServlet.java:245)
        at org.apache.camel.http.common.CamelServlet.service(CamelServlet.java:130)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:554)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.Server.handle(Server.java:516)
        at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487)
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
        at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555)
        at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410)
        at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
        at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
        at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: de.fhg.aisec.ids.idscp2.api.error.DatException: Fingerprint of peer certificate (ad17e1788815205c21497e6d36a324461c69a1b7e5c558c378fb7df79c5f00a7) does not match any fingerprint from DAT ([bdc48d7e957b458639e02aa409cb9123956a4bb7565c97d6e03a59421208209c]).
        at de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver.innerVerifyToken(AisecDapsDriver.kt:483)
        at de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver.innerVerifyToken$default(AisecDapsDriver.kt:389)
        at de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver.verifyToken(AisecDapsDriver.kt:374)
        at de.fhg.aisec.ids.camel.processors.multipart.IdsMultiPartInputProcessor.process(IdsMultiPartInputProcessor.kt:88)
        ... 43 more

The logs of logging Service :

[2023-11-23][10:54:35][rocket::server][INFO] POST /process/mp-pid1_2068187009 application/json:
[2023-11-23][10:54:35][rocket::server::_][INFO] Matched: (create_process) POST /process/<pid> application/json
[2023-11-23][10:54:35][core_lib::api::crypto][DEBUG] ...received service header: "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhdWQiOiJsb2dnaW5nLXNlcnZpY2UiLCJpc3MiOiJ0Yy1jb3JlLXNlcnZlciIsImV4cCI6MTcwMDczNjkzNSwiaWF0IjoxNzAwNzM2ODc1LCJjbGllbnRfaWQiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCJ9.rIbETfsdOORvLf6BiMrG19Qg3IQblunoS0DrRKVIb24"
[2023-11-23][10:54:35][core_lib::api::crypto][DEBUG] ...retrieved claims and succeed
[2023-11-23][10:54:35][logging_service::db][DEBUG] Trying to get process with id mp-pid1_2068187009...
[2023-11-23][10:54:35][logging_service::logging_api][INFO] Requested pid 'mp-pid1_2068187009' will have 1 owners
[2023-11-23][10:54:35][logging_service::logging_api][INFO] Requested pid 'mp-pid1_2068187009' does not exist. Creating...
[2023-11-23][10:54:35][logging_service::db][DEBUG] Storing process with pid "mp-pid1_2068187009"...
[2023-11-23][10:54:35][logging_service::db][DEBUG] ...added new process: ObjectId("655f2f6b11c4644afc6f16d0")
[2023-11-23][10:54:35][rocket::server::_][INFO] Outcome: Success
[2023-11-23][10:54:35][rocket::server::_][INFO] Response succeeded.
[2023-11-23][10:54:37][rocket::server][INFO] POST /process/mp-pid2_2068187009 application/json:
[2023-11-23][10:54:37][rocket::server::_][INFO] Matched: (create_process) POST /process/<pid> application/json
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...received service header: "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhdWQiOiJsb2dnaW5nLXNlcnZpY2UiLCJpc3MiOiJ0Yy1jb3JlLXNlcnZlciIsImV4cCI6MTcwMDczNjkzNywiaWF0IjoxNzAwNzM2ODc3LCJjbGllbnRfaWQiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCJ9.L4y1v_R9EegA06A7wT5lFSb2XEmbczAUHvVvX8RppuM"
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...retrieved claims and succeed
[2023-11-23][10:54:37][logging_service::db][DEBUG] Trying to get process with id mp-pid2_2068187009...
[2023-11-23][10:54:37][logging_service::logging_api][INFO] Requested pid 'mp-pid2_2068187009' will have 2 owners
[2023-11-23][10:54:37][logging_service::logging_api][INFO] Requested pid 'mp-pid2_2068187009' does not exist. Creating...
[2023-11-23][10:54:37][logging_service::db][DEBUG] Storing process with pid "mp-pid2_2068187009"...
[2023-11-23][10:54:37][logging_service::db][DEBUG] ...added new process: ObjectId("655f2f6d11c4644afc6f16d1")
[2023-11-23][10:54:37][rocket::server::_][INFO] Outcome: Success
[2023-11-23][10:54:37][rocket::server::_][INFO] Response succeeded.
[2023-11-23][10:54:37][rocket::server][INFO] POST /process/mp-pid3_2068187009 application/json:
[2023-11-23][10:54:37][rocket::server::_][INFO] Matched: (create_process) POST /process/<pid> application/json
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...received service header: "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhdWQiOiJsb2dnaW5nLXNlcnZpY2UiLCJpc3MiOiJ0Yy1jb3JlLXNlcnZlciIsImV4cCI6MTcwMDczNjkzNywiaWF0IjoxNzAwNzM2ODc3LCJjbGllbnRfaWQiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCJ9.L4y1v_R9EegA06A7wT5lFSb2XEmbczAUHvVvX8RppuM"
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...retrieved claims and succeed
[2023-11-23][10:54:37][logging_service::db][DEBUG] Trying to get process with id mp-pid3_2068187009...
[2023-11-23][10:54:37][logging_service::logging_api][INFO] Requested pid 'mp-pid3_2068187009' will have 2 owners
[2023-11-23][10:54:37][logging_service::logging_api][INFO] Requested pid 'mp-pid3_2068187009' does not exist. Creating...
[2023-11-23][10:54:37][logging_service::db][DEBUG] Storing process with pid "mp-pid3_2068187009"...
[2023-11-23][10:54:37][logging_service::db][DEBUG] ...added new process: ObjectId("655f2f6d11c4644afc6f16d2")
[2023-11-23][10:54:37][rocket::server::_][INFO] Outcome: Success
[2023-11-23][10:54:37][rocket::server::_][INFO] Response succeeded.
[2023-11-23][10:54:37][rocket::server][INFO] POST /process/mp-pid4_2068187009 application/json:
[2023-11-23][10:54:37][rocket::server::_][INFO] Matched: (create_process) POST /process/<pid> application/json
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...received service header: "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhdWQiOiJsb2dnaW5nLXNlcnZpY2UiLCJpc3MiOiJ0Yy1jb3JlLXNlcnZlciIsImV4cCI6MTcwMDczNjkzNywiaWF0IjoxNzAwNzM2ODc3LCJjbGllbnRfaWQiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCJ9.L4y1v_R9EegA06A7wT5lFSb2XEmbczAUHvVvX8RppuM"
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...retrieved claims and succeed
[2023-11-23][10:54:37][logging_service::db][DEBUG] Trying to get process with id mp-pid4_2068187009...
[2023-11-23][10:54:37][logging_service::logging_api][INFO] Requested pid 'mp-pid4_2068187009' will have 2 owners
[2023-11-23][10:54:37][logging_service::logging_api][INFO] Requested pid 'mp-pid4_2068187009' does not exist. Creating...
[2023-11-23][10:54:37][logging_service::db][DEBUG] Storing process with pid "mp-pid4_2068187009"...
[2023-11-23][10:54:37][logging_service::db][DEBUG] ...added new process: ObjectId("655f2f6d11c4644afc6f16d3")
[2023-11-23][10:54:37][rocket::server::_][INFO] Outcome: Success
[2023-11-23][10:54:37][rocket::server::_][INFO] Response succeeded.
[2023-11-23][10:54:37][rocket::server][INFO] POST /process/mp-pid5_2068187009 application/json:
[2023-11-23][10:54:37][rocket::server::_][INFO] Matched: (create_process) POST /process/<pid> application/json
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...received service header: "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhdWQiOiJsb2dnaW5nLXNlcnZpY2UiLCJpc3MiOiJ0Yy1jb3JlLXNlcnZlciIsImV4cCI6MTcwMDczNjkzNywiaWF0IjoxNzAwNzM2ODc3LCJjbGllbnRfaWQiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCJ9.L4y1v_R9EegA06A7wT5lFSb2XEmbczAUHvVvX8RppuM"
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...retrieved claims and succeed
[2023-11-23][10:54:37][logging_service::db][DEBUG] Trying to get process with id mp-pid5_2068187009...
[2023-11-23][10:54:37][logging_service::logging_api][INFO] Requested pid 'mp-pid5_2068187009' will have 1 owners
[2023-11-23][10:54:37][logging_service::logging_api][INFO] Requested pid 'mp-pid5_2068187009' does not exist. Creating...
[2023-11-23][10:54:37][logging_service::db][DEBUG] Storing process with pid "mp-pid5_2068187009"...
[2023-11-23][10:54:37][logging_service::db][DEBUG] ...added new process: ObjectId("655f2f6d11c4644afc6f16d4")
[2023-11-23][10:54:37][rocket::server::_][INFO] Outcome: Success
[2023-11-23][10:54:37][rocket::server::_][INFO] Response succeeded.
[2023-11-23][10:54:37][rocket::server][INFO] POST /process/mp-pid5_2068187009 application/json:
[2023-11-23][10:54:37][rocket::server::_][INFO] Matched: (create_process) POST /process/<pid> application/json
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...received service header: "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhdWQiOiJsb2dnaW5nLXNlcnZpY2UiLCJpc3MiOiJ0Yy1jb3JlLXNlcnZlciIsImV4cCI6MTcwMDczNjkzNywiaWF0IjoxNzAwNzM2ODc3LCJjbGllbnRfaWQiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCJ9.L4y1v_R9EegA06A7wT5lFSb2XEmbczAUHvVvX8RppuM"
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...retrieved claims and succeed
[2023-11-23][10:54:37][logging_service::db][DEBUG] Trying to get process with id mp-pid5_2068187009...
[2023-11-23][10:54:37][logging_service::logging_api][WARN] Requested pid 'mp-pid5_2068187009' already exists.
[2023-11-23][10:54:37][rocket::server::_][INFO] Outcome: Success
[2023-11-23][10:54:37][rocket::server::_][INFO] Response succeeded.
[2023-11-23][10:54:37][rocket::server][INFO] POST /process/mp-pid6_2068187009 application/json:
[2023-11-23][10:54:37][rocket::server::_][INFO] Matched: (create_process) POST /process/<pid> application/json
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...received service header: "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhdWQiOiJsb2dnaW5nLXNlcnZpY2UiLCJpc3MiOiJ0Yy1jb3JlLXNlcnZlciIsImV4cCI6MTcwMDczNjkzNywiaWF0IjoxNzAwNzM2ODc3LCJjbGllbnRfaWQiOiIxMzowOToyRToxQzo1MDo5Qjo4Qjo3NzpERTowMToxRjozQjpCNTpFMDpEMjpDQzoxQjpDNTo4ODo5RTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCJ9.O9tCbjBZQB_th5tGcC6uMhyxUwvMb75LebqjA_ubgb8"
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...retrieved claims and succeed
[2023-11-23][10:54:37][logging_service::db][DEBUG] Trying to get process with id mp-pid6_2068187009...
[2023-11-23][10:54:37][logging_service::logging_api][INFO] Requested pid 'mp-pid6_2068187009' will have 1 owners
[2023-11-23][10:54:37][logging_service::logging_api][INFO] Requested pid 'mp-pid6_2068187009' does not exist. Creating...
[2023-11-23][10:54:37][logging_service::db][DEBUG] Storing process with pid "mp-pid6_2068187009"...
[2023-11-23][10:54:37][logging_service::db][DEBUG] ...added new process: ObjectId("655f2f6d11c4644afc6f16d5")
[2023-11-23][10:54:37][rocket::server::_][INFO] Outcome: Success
[2023-11-23][10:54:37][rocket::server::_][INFO] Response succeeded.
[2023-11-23][10:54:37][rocket::server][INFO] POST /process/mp-pid6_2068187009 application/json:
[2023-11-23][10:54:37][rocket::server::_][INFO] Matched: (create_process) POST /process/<pid> application/json
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...received service header: "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhdWQiOiJsb2dnaW5nLXNlcnZpY2UiLCJpc3MiOiJ0Yy1jb3JlLXNlcnZlciIsImV4cCI6MTcwMDczNjkzNywiaWF0IjoxNzAwNzM2ODc3LCJjbGllbnRfaWQiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCJ9.L4y1v_R9EegA06A7wT5lFSb2XEmbczAUHvVvX8RppuM"
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...retrieved claims and succeed
[2023-11-23][10:54:37][logging_service::db][DEBUG] Trying to get process with id mp-pid6_2068187009...
[2023-11-23][10:54:37][logging_service::logging_api][WARN] Requested pid 'mp-pid6_2068187009' already exists.
[2023-11-23][10:54:37][rocket::server::_][INFO] Outcome: Success
[2023-11-23][10:54:37][rocket::server::_][INFO] Response succeeded.
[2023-11-23][10:54:37][rocket::server][INFO] POST /process/mp-pid7_2068187009 application/json:
[2023-11-23][10:54:37][rocket::server::_][INFO] Matched: (create_process) POST /process/<pid> application/json
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...received service header: "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhdWQiOiJsb2dnaW5nLXNlcnZpY2UiLCJpc3MiOiJ0Yy1jb3JlLXNlcnZlciIsImV4cCI6MTcwMDczNjkzNywiaWF0IjoxNzAwNzM2ODc3LCJjbGllbnRfaWQiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCJ9.L4y1v_R9EegA06A7wT5lFSb2XEmbczAUHvVvX8RppuM"
[2023-11-23][10:54:37][core_lib::api::crypto][DEBUG] ...retrieved claims and succeed
[2023-11-23][10:54:37][logging_service::logging_api][ERROR] Error while creating process 'mp-pid7_2068187009': trailing comma at line 1 column 141
[2023-11-23][10:54:37][rocket::server::_][INFO] Outcome: Success
[2023-11-23][10:54:37][rocket::server::_][INFO] Response succeeded.
[2023-11-23][10:54:38][rocket::server][INFO] POST /process/mp-log1_2068187009 application/json:
[2023-11-23][10:54:38][rocket::server::_][INFO] Matched: (create_process) POST /process/<pid> application/json
[2023-11-23][10:54:38][core_lib::api::crypto][DEBUG] ...received service header: "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhdWQiOiJsb2dnaW5nLXNlcnZpY2UiLCJpc3MiOiJ0Yy1jb3JlLXNlcnZlciIsImV4cCI6MTcwMDczNjkzOCwiaWF0IjoxNzAwNzM2ODc4LCJjbGllbnRfaWQiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCJ9.y9kLbTA-zLEuuoFnM8xCeqBqaXimSkS7XODr4dxdFnM"
[2023-11-23][10:54:38][core_lib::api::crypto][DEBUG] ...retrieved claims and succeed
[2023-11-23][10:54:38][logging_service::db][DEBUG] Trying to get process with id mp-log1_2068187009...
[2023-11-23][10:54:38][logging_service::logging_api][INFO] Requested pid 'mp-log1_2068187009' will have 1 owners
[2023-11-23][10:54:38][logging_service::logging_api][INFO] Requested pid 'mp-log1_2068187009' does not exist. Creating...
[2023-11-23][10:54:38][logging_service::db][DEBUG] Storing process with pid "mp-log1_2068187009"...
[2023-11-23][10:54:38][logging_service::db][DEBUG] ...added new process: ObjectId("655f2f6e11c4644afc6f16d6")
[2023-11-23][10:54:38][rocket::server::_][INFO] Outcome: Success
[2023-11-23][10:54:38][rocket::server::_][INFO] Response succeeded.
[2023-11-23][10:54:38][rocket::server][INFO] POST /messages/log/mp-log1_2068187009 application/json:
[2023-11-23][10:54:38][rocket::server::_][INFO] Matched: (log) POST /messages/log/<pid> application/json
[2023-11-23][10:54:38][core_lib::api::crypto][DEBUG] ...received service header: "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhdWQiOiJsb2dnaW5nLXNlcnZpY2UiLCJpc3MiOiJ0Yy1jb3JlLXNlcnZlciIsImV4cCI6MTcwMDczNjkzOCwiaWF0IjoxNzAwNzM2ODc4LCJjbGllbnRfaWQiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCJ9.y9kLbTA-zLEuuoFnM8xCeqBqaXimSkS7XODr4dxdFnM"
[2023-11-23][10:54:38][core_lib::api::crypto][DEBUG] ...retrieved claims and succeed
[2023-11-23][10:54:38][logging_service::db][DEBUG] Trying to get process with id mp-log1_2068187009...
[2023-11-23][10:54:38][logging_service::logging_api][DEBUG] Requested pid 'mp-log1_2068187009' exists. Nothing to create.
[2023-11-23][10:54:38][logging_service::db][DEBUG] checking if user 'D2:70:FE:7F:32:BB:37:BF:DF:F4:08:36:6B:F1:9E:7A:EB:A4:2D:2A:keyid:CB:8C:C7:B6:85:79:A8:23:A6:CB:15:AB:17:50:2F:E6:65:43:5D:E8' is authorized to access 'mp-log1_2068187009'
[2023-11-23][10:54:38][logging_service::db][DEBUG] Trying to get process with id mp-log1_2068187009...
[2023-11-23][10:54:38][logging_service::logging_api][INFO] User authorized.
[2023-11-23][10:54:38][logging_service::logging_api][DEBUG] logging message for pid mp-log1_2068187009
[2023-11-23][10:54:38][logging_service::logging_api][DEBUG] transforming message to document...
[2023-11-23][10:54:38][logging_service::db][DEBUG] Getting transaction counter...
[2023-11-23][10:54:38][logging_service::logging_api][DEBUG] Storing document...
[2023-11-23][10:54:38][core_lib::api::client::document_api][DEBUG] created jwt: eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJkb2N1bWVudC1hcGkiLCJhdWQiOiJkb2N1bWVudC1hcGkiLCJleHAiOjE3MDA3MzcxNzgsImlhdCI6MTcwMDczNjg3OCwiY2xpZW50X2lkIjoiRDI6NzA6RkU6N0Y6MzI6QkI6Mzc6QkY6REY6RjQ6MDg6MzY6NkI6RjE6OUU6N0E6RUI6QTQ6MkQ6MkE6a2V5aWQ6Q0I6OEM6Qzc6QjY6ODU6Nzk6QTg6MjM6QTY6Q0I6MTU6QUI6MTc6NTA6MkY6RTY6NjU6NDM6NUQ6RTgifQ.zgxYVGk4_SHcePP7kXktT1rk01cCJmbNgN6iYkBMqaQ
[2023-11-23][10:54:38][core_lib::api::client::document_api][DEBUG] calling http://document-api:8001/doc
[2023-11-23][10:54:38][reqwest::connect][DEBUG] starting new connection: http://document-api:8001/
[2023-11-23][10:54:38][core_lib::api::client::document_api][DEBUG] Status Code: 201 Created
Payload: DocumentReceipt { timestamp: 1700736878, pid: "mp-log1_2068187009", doc_id: "2c921558-cfe4-4739-965a-ad93902497ef", chain_hash: "64BmuN2W5w9o7j9AQJ8SOqoJbEdA3bXWKMQpyoqhcAE/U/XUHMFNXqCz5dmQ5FhFVZxl5af5IScKd7AOyl9BXA==" }
[2023-11-23][10:54:38][logging_service::logging_api][DEBUG] Increase transaction counter
[2023-11-23][10:54:38][logging_service::db][DEBUG] Getting transaction counter...
[2023-11-23][10:54:38][logging_service::logging_api][DEBUG] Creating receipt...
[2023-11-23][10:54:38][logging_service::logging_api][DEBUG] ...done. Signing receipt...
decoded JWS:Decoded {
    header: Header {
        registered: RegisteredHeader {
            algorithm: PS512,
            media_type: None,
            content_type: None,
            web_key_url: None,
            web_key: None,
            key_id: Some(
                "ouZ96xIl3N3EN8X0CAjnwEurjhA2wx5RSbRowuNjo9w",
            ),
            x509_url: None,
            x509_chain: None,
            x509_fingerprint: None,
            critical: None,
        },
        private: Empty,
    },
    payload: DataTransaction {
        transaction_id: "00000140",
        timestamp: 1700736878,
        process_id: "mp-log1_2068187009",
        document_id: "2c921558-cfe4-4739-965a-ad93902497ef",
        payload: "VGhpcyBtZXNzYWdlIGlzIGxvZ2dlZA==",
        chain_hash: "64BmuN2W5w9o7j9AQJ8SOqoJbEdA3bXWKMQpyoqhcAE/U/XUHMFNXqCz5dmQ5FhFVZxl5af5IScKd7AOyl9BXA==",
        client_id: "D2:70:FE:7F:32:BB:37:BF:DF:F4:08:36:6B:F1:9E:7A:EB:A4:2D:2A:keyid:CB:8C:C7:B6:85:79:A8:23:A6:CB:15:AB:17:50:2F:E6:65:43:5D:E8",
        clearing_house_version: "0.10.0",
    },
}
[2023-11-23][10:54:38][rocket::server::_][INFO] Outcome: Success
[2023-11-23][10:54:38][rocket::server::_][INFO] Response succeeded.
[2023-11-23][10:54:38][rocket::server][INFO] POST /messages/log/mp-log2_2068187009 application/json:
[2023-11-23][10:54:38][rocket::server::_][INFO] Matched: (log) POST /messages/log/<pid> application/json
[2023-11-23][10:54:38][core_lib::api::crypto][DEBUG] ...received service header: "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJhdWQiOiJsb2dnaW5nLXNlcnZpY2UiLCJpc3MiOiJ0Yy1jb3JlLXNlcnZlciIsImV4cCI6MTcwMDczNjkzOCwiaWF0IjoxNzAwNzM2ODc4LCJjbGllbnRfaWQiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCJ9.y9kLbTA-zLEuuoFnM8xCeqBqaXimSkS7XODr4dxdFnM"
[2023-11-23][10:54:38][core_lib::api::crypto][DEBUG] ...retrieved claims and succeed
[2023-11-23][10:54:38][logging_service::db][DEBUG] Trying to get process with id mp-log2_2068187009...
[2023-11-23][10:54:38][logging_service::logging_api][INFO] Requested pid 'mp-log2_2068187009' does not exist. Creating...
[2023-11-23][10:54:38][logging_service::db][DEBUG] Storing process with pid "mp-log2_2068187009"...
[2023-11-23][10:54:38][logging_service::db][DEBUG] ...added new process: ObjectId("655f2f6e11c4644afc6f16d7")
[2023-11-23][10:54:38][logging_service::db][DEBUG] checking if user 'D2:70:FE:7F:32:BB:37:BF:DF:F4:08:36:6B:F1:9E:7A:EB:A4:2D:2A:keyid:CB:8C:C7:B6:85:79:A8:23:A6:CB:15:AB:17:50:2F:E6:65:43:5D:E8' is authorized to access 'mp-log2_2068187009'
[2023-11-23][10:54:38][logging_service::db][DEBUG] Trying to get process with id mp-log2_2068187009...
[2023-11-23][10:54:38][logging_service::logging_api][INFO] User authorized.
[2023-11-23][10:54:38][logging_service::logging_api][DEBUG] logging message for pid mp-log2_2068187009
[2023-11-23][10:54:38][logging_service::logging_api][DEBUG] transforming message to document...
[2023-11-23][10:54:38][logging_service::db][DEBUG] Getting transaction counter...
[2023-11-23][10:54:38][logging_service::logging_api][DEBUG] Storing document...
[2023-11-23][10:54:38][core_lib::api::client::document_api][DEBUG] created jwt: eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJkb2N1bWVudC1hcGkiLCJhdWQiOiJkb2N1bWVudC1hcGkiLCJleHAiOjE3MDA3MzcxNzgsImlhdCI6MTcwMDczNjg3OCwiY2xpZW50X2lkIjoiRDI6NzA6RkU6N0Y6MzI6QkI6Mzc6QkY6REY6RjQ6MDg6MzY6NkI6RjE6OUU6N0E6RUI6QTQ6MkQ6MkE6a2V5aWQ6Q0I6OEM6Qzc6QjY6ODU6Nzk6QTg6MjM6QTY6Q0I6MTU6QUI6MTc6NTA6MkY6RTY6NjU6NDM6NUQ6RTgifQ.zgxYVGk4_SHcePP7kXktT1rk01cCJmbNgN6iYkBMqaQ
[2023-11-23][10:54:38][core_lib::api::client::document_api][DEBUG] calling http://document-api:8001/doc
[2023-11-23][10:54:38][reqwest::connect][DEBUG] starting new connection: http://document-api:8001/
[2023-11-23][10:54:38][core_lib::api::client::document_api][DEBUG] Status Code: 201 Created
Payload: DocumentReceipt { timestamp: 1700736878, pid: "mp-log2_2068187009", doc_id: "862bf918-ea46-4eb7-b29f-c85c21398cf0", chain_hash: "5jnFaLJpxAsUkzjRQt+7HT1hHEVde5PLmlbDlMlV6RqJs0kIVC0qkiNOVhrWvZMUUfpc7Xz6BHAOAxg5Py9+eg==" }
[2023-11-23][10:54:38][logging_service::logging_api][DEBUG] Increase transaction counter
[2023-11-23][10:54:38][logging_service::db][DEBUG] Getting transaction counter...
[2023-11-23][10:54:38][logging_service::logging_api][DEBUG] Creating receipt...
[2023-11-23][10:54:38][logging_service::logging_api][DEBUG] ...done. Signing receipt...
decoded JWS:Decoded {
    header: Header {
        registered: RegisteredHeader {
            algorithm: PS512,
            media_type: None,
            content_type: None,
            web_key_url: None,
            web_key: None,
            key_id: Some(
                "ouZ96xIl3N3EN8X0CAjnwEurjhA2wx5RSbRowuNjo9w",
            ),
            x509_url: None,
            x509_chain: None,
            x509_fingerprint: None,
            critical: None,
        },
        private: Empty,
    },
    payload: DataTransaction {
        transaction_id: "00000141",
        timestamp: 1700736878,
        process_id: "mp-log2_2068187009",
        document_id: "862bf918-ea46-4eb7-b29f-c85c21398cf0",
        payload: "VGhpcyBtZXNzYWdlIGlzIGxvZ2dlZA==",
        chain_hash: "5jnFaLJpxAsUkzjRQt+7HT1hHEVde5PLmlbDlMlV6RqJs0kIVC0qkiNOVhrWvZMUUfpc7Xz6BHAOAxg5Py9+eg==",
        client_id: "D2:70:FE:7F:32:BB:37:BF:DF:F4:08:36:6B:F1:9E:7A:EB:A4:2D:2A:keyid:CB:8C:C7:B6:85:79:A8:23:A6:CB:15:AB:17:50:2F:E6:65:43:5D:E8",
        clearing_house_version: "0.10.0",
    },
}

The above logs are indicative parts of the our actual logs.
If you need entire logs please inform me.

What we are missing to pass the tests successfully?

In some point I can understand that the errors are relevant with certificates.

In docker-compose, we use service-keystore.p12 and truststore.p12 existing under clearing-house-processor in intTest folder. Also we have try both https://daps-dev.aisec.fraunhofer.de/ and https://daps.aisec.fraunhofer.de/ in many versions (v3 ,v4).

We will appreciate your help for resolving this issue and your support to make the next steps to be closer to a production CH environment.

Thank you in advance.

milux commented 9 months ago

Hello Christos, since the CH is not in particularly high demand these days, we do support on an best-effort basis here. It seems you invested quite some effort into debugging this, so I will try to invest some time to hopefully sort out this issue. I share your assumption about the certificate/DAT problem. At least one root problem seems to lie here: Caused by: de.fhg.aisec.ids.idscp2.api.error.DatException: Fingerprint of peer certificate (ad17e1788815205c21497e6d36a324461c69a1b7e5c558c378fb7df79c5f00a7) does not match any fingerprint from DAT ([bdc48d7e957b458639e02aa409cb9123956a4bb7565c97d6e03a59421208209c]). This error indicates a mismatch between the fingerprint of the client certificate and the fingerprint that was embedded into the issued DAT. You can "override" this fingerprint with that one of your custom transport certificate within the DAPS driver configuration. In the TC example XMLs you will find this:

    <bean id="rootDaps" class="de.fhg.aisec.ids.idscp2.beans.AisecDapsDriverFactoryBean">
        <property name="dapsUrl" value="${connector.daps-url}"/>
        <property name="dapsSslParameters" ref="rootClientSslContext" />
        <property name="transportCertificatesParameters" ref="rootClientSslContext" />
    </bean>

dapsSslParameters is used for authentication against the DAPS, whereas transportCertificatesParameters MAY refer to a different SSL context with your certificates for transport TLS. Typically, these are the same, but they can differ. In your case, they seem to do so, probably due to the changes you mentioned. You also have to "activate" this bean this for the MP protocol within /etc/application.yml like so:

ids-multipart:
  daps-bean-name: rootDaps

When doing this properly, the AISEC DAPS driver should pick up your transport certificate and include its actual fingerprint into the DAT request, hopefully resulting in a DAT with the right fingerprint. Good luck!

christos-aslamatzidis commented 9 months ago

Thank you for your quick response.

Under intTest folder there are two packages. One for idsp2 and one for multipart. Thanks to your advices and taking a close look at code of integration tests we manage to pass the tests are relevant to multipart. However, the tests are related to idscp2 communication failed again.

Logs from tests:

This warning is only printed once
[Test worker] DEBUG de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver - AKI: CB:8C:C7:B6:85:79:A8:23:A6:CB:15:AB:17:50:2F:E6:65:43:5D:E8
[Test worker] DEBUG de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver - SKI: D2:70:FE:7F:32:BB:37:BF:DF:F4:08:36:6B:F1:9E:7A:EB:A4:2D:2A
[Test worker] DEBUG de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver - AKI: CB:8C:C7:B6:85:79:A8:23:A6:CB:15:AB:17:50:2F:E6:65:43:5D:E8
[Test worker] DEBUG de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver - SKI: 13:09:2E:1C:50:9B:8B:77:DE:01:1F:3B:B5:E0:D2:CC:1B:C5:88:9E
[Test worker] DEBUG de.fhg.aisec.ids.idscp2.api.raregistry.RaProverDriverRegistry - Register 'Dummy2' driver to RA prover registry
[Test worker] DEBUG de.fhg.aisec.ids.idscp2.api.raregistry.RaVerifierDriverRegistry - Register 'Dummy2' driver to RA verifier registry
[Test worker] INFO de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver - Retrieving Dynamic Attribute Token from DAPS ...
[Test worker] DEBUG de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver - ConnectorUUID: D2:70:FE:7F:32:BB:37:BF:DF:F4:08:36:6B:F1:9E:7A:EB:A4:2D:2A:keyid:CB:8C:C7:B6:85:79:A8:23:A6:CB:15:AB:17:50:2F:E6:65:43:5D:E8
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver - Acquired DAT from https://daps-dev.aisec.fraunhofer.de/v4/token
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver - Received DAT from DAPS: eyJ0eXAiOiJhdCtqd3QiLCJraWQiOiJiMjAzMWVmYWFkMTc4OWExZmQzNjFkYzQ1Y2E4N2FiNjk5MTE5NzlkYjIyMzFiNDc4NzJkMDJiOTU5MWZmMDk4IiwiYWxnIjoiUlMyNTYifQ.eyJzY29wZSI6Imlkc2M6SURTX0NPTk5FQ1RPUl9BVFRSSUJVVEVTX0FMTCIsImF1ZCI6WyJpZHNjOklEU19DT05ORUNUT1JTX0FMTCJdLCJpc3MiOiJodHRwczovL2RhcHMtZGV2LmFpc2VjLmZyYXVuaG9mZXIuZGUvdjQiLCJzdWIiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCIsIm5iZiI6MTcwMTc2ODQxNywiaWF0IjoxNzAxNzY4NDE3LCJqdGkiOiJmZjI2YjBmNy1iMzNlLTRhM2UtYTJiMi1lYjVkOTg2NDYyNDAiLCJleHAiOjE3MDE3NzIwMTcsImNsaWVudF9pZCI6IkQyOjcwOkZFOjdGOjMyOkJCOjM3OkJGOkRGOkY0OjA4OjM2OjZCOkYxOjlFOjdBOkVCOkE0OjJEOjJBOmtleWlkOkNCOjhDOkM3OkI2Ojg1Ojc5OkE4OjIzOkE2OkNCOjE1OkFCOjE3OjUwOjJGOkU2OjY1OjQzOjVEOkU4IiwidHJhbnNwb3J0Q2VydHNTaGEyNTYiOlsiYWQxN2UxNzg4ODE1MjA1YzIxNDk3ZTZkMzZhMzI0NDYxYzY5YTFiN2U1YzU1OGMzNzhmYjdkZjc5YzVmMDBhNyJdfQ.r_WGnf6bAVAqxTFCsv-WRszjZXYX04aw5jeqbiMNbH1QVLTAGKCybLKTo95gOReU-wmLy0Ko5XeZ2OgiWynhbQ0y1t6gingVer_O9qL3uBQecbko9BnmM-F1wuY_8o2Gu1YtmU_7DFhayZ-GHooFghXuxK1YJ1h85hTft5r-cg6RG9X6RpVzjd2jOqW5NJDBmbVhd7HkOcQWaQ7AkbanZXScCbFz-zFFZG7oX46JyQZBhl6_dX03ByAifXOXDKk-HO-w4OPTPRywg0FcSnqpyliwaF6E2C22tZSLTxah8QF-bUwZH0WE-4NLJmCXbXBVTDW9aYvUVMH6GCK8yFNsig
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver - Verifying dynamic attribute token...
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwk.HttpsJwks - Refreshing/loading JWKS from https://daps-dev.aisec.fraunhofer.de/v4/jwks.json
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwk.HttpsJwks - Updated JWKS content from https://daps-dev.aisec.fraunhofer.de/v4/jwks.json will be cached for 86400 seconds until about Wed Dec 06 11:26:56 EET 2023 -> [org.jose4j.jwk.RsaJsonWebKey{kty=RSA, kid=b2031efaad1789a1fd361dc45ca87ab69911979db2231b47872d02b9591ff098, use=sig, n=tZN1bLgMYiINGbEGqRoEgXAB6XoKDSsVGOpjMmJonmJF5lJZVgvkHyCrt1gKFZ8malGLutxd8Bu1md5FwCJqkm9ZpbnSbttSlzrS4RfuV4W6Lk9Sx1pedwwKBfvRig0y7UXSB9PipqXx7aEmfZiq1zh69DFRr9ZDWtR9X08yDqBCT49sQH2Q2l0QZXe6MDUM_FLI7vYni5Xlb--HXggQAjWyWU7mRrd3fhQiJNN7xztUwo7wZ_kKehup1T_RYN8-3PACklXXHUoo3NqtnnIyNUEudsAeS4foGKE5iHDNkHJp4TImNkSKZ9JL_q1PjlgZUkbIh7zkmj4LENnEGJhE4Q, e=AQAB}]
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactoryFactory - Initializing jose4j (running with Java 18.0.2 from Amazon.com Inc. at /home/christos/.jdks/corretto-18.0.2 with [SUN version 18, SunRsaSign version 18, SunEC version 18, SunJSSE version 18, SunJCE version 18, SunJGSS version 18, SunSASL version 18, XMLDSig version 18, SunPCSC version 18, JdkLDAP version 18, JdkSASL version 18, SunPKCS11 version 18, BC version 1.7] security providers installed)...
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - org.jose4j.jws.UnsecuredNoneAlgorithm(none|null) registered for alg algorithm none
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - org.jose4j.jws.HmacUsingShaAlgorithm$HmacSha256(HS256|HmacSHA256) registered for alg algorithm HS256
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - org.jose4j.jws.HmacUsingShaAlgorithm$HmacSha384(HS384|HmacSHA384) registered for alg algorithm HS384
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - org.jose4j.jws.HmacUsingShaAlgorithm$HmacSha512(HS512|HmacSHA512) registered for alg algorithm HS512
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - org.jose4j.jws.EdDsaAlgorithm(EdDSA|EdDSA) registered for alg algorithm EdDSA
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - org.jose4j.jws.EcdsaUsingShaAlgorithm$EcdsaP256UsingSha256(ES256|SHA256withECDSA) registered for alg algorithm ES256
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - org.jose4j.jws.EcdsaUsingShaAlgorithm$EcdsaP384UsingSha384(ES384|SHA384withECDSA) registered for alg algorithm ES384
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - org.jose4j.jws.EcdsaUsingShaAlgorithm$EcdsaP521UsingSha512(ES512|SHA512withECDSA) registered for alg algorithm ES512
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jws.EcdsaUsingShaAlgorithm$EcdsaSECP256K1UsingSha256 - ES256K is not available due to org.jose4j.lang.JoseException: Problem creating signature.; caused by: java.security.SignatureException: Curve not supported: java.security.spec.ECParameterSpec@3ea5cbe7
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - ES256K is unavailable so will not be registered for alg algorithms.
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - org.jose4j.jws.RsaUsingShaAlgorithm$RsaSha256(RS256|SHA256withRSA) registered for alg algorithm RS256
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - org.jose4j.jws.RsaUsingShaAlgorithm$RsaSha384(RS384|SHA384withRSA) registered for alg algorithm RS384
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - org.jose4j.jws.RsaUsingShaAlgorithm$RsaSha512(RS512|SHA512withRSA) registered for alg algorithm RS512
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - org.jose4j.jws.RsaUsingShaAlgorithm$RsaPssSha256(PS256|RSASSA-PSS) registered for alg algorithm PS256
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - org.jose4j.jws.RsaUsingShaAlgorithm$RsaPssSha384(PS384|RSASSA-PSS) registered for alg algorithm PS384
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->JsonWebSignatureAlgorithm - org.jose4j.jws.RsaUsingShaAlgorithm$RsaPssSha512(PS512|RSASSA-PSS) registered for alg algorithm PS512
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactoryFactory - JWS signature algorithms: [none, HS256, HS384, HS512, EdDSA, ES256, ES384, ES512, RS256, RS384, RS512, PS256, PS384, PS512]
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.RsaKeyManagementAlgorithm$Rsa1_5(RSA1_5|RSA/ECB/PKCS1Padding) registered for alg algorithm RSA1_5
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.RsaKeyManagementAlgorithm$RsaOaep(RSA-OAEP|RSA/ECB/OAEPWithSHA-1AndMGF1Padding) registered for alg algorithm RSA-OAEP
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.RsaKeyManagementAlgorithm$RsaOaep256(RSA-OAEP-256|RSA/ECB/OAEPWithSHA-256AndMGF1Padding) registered for alg algorithm RSA-OAEP-256
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.DirectKeyManagementAlgorithm(dir|null) registered for alg algorithm dir
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.AesKeyWrapManagementAlgorithm$Aes128(A128KW|AESWrap) registered for alg algorithm A128KW
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.AesKeyWrapManagementAlgorithm$Aes192(A192KW|AESWrap) registered for alg algorithm A192KW
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.AesKeyWrapManagementAlgorithm$Aes256(A256KW|AESWrap) registered for alg algorithm A256KW
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.EcdhKeyAgreementAlgorithm(ECDH-ES|ECDH) registered for alg algorithm ECDH-ES
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.EcdhKeyAgreementWithAesKeyWrapAlgorithm$EcdhKeyAgreementWithAes128KeyWrapAlgorithm(ECDH-ES+A128KW|N/A) registered for alg algorithm ECDH-ES+A128KW
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.EcdhKeyAgreementWithAesKeyWrapAlgorithm$EcdhKeyAgreementWithAes192KeyWrapAlgorithm(ECDH-ES+A192KW|N/A) registered for alg algorithm ECDH-ES+A192KW
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.EcdhKeyAgreementWithAesKeyWrapAlgorithm$EcdhKeyAgreementWithAes256KeyWrapAlgorithm(ECDH-ES+A256KW|N/A) registered for alg algorithm ECDH-ES+A256KW
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.Pbes2HmacShaWithAesKeyWrapAlgorithm$HmacSha256Aes128(PBES2-HS256+A128KW|n/a) registered for alg algorithm PBES2-HS256+A128KW
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.Pbes2HmacShaWithAesKeyWrapAlgorithm$HmacSha384Aes192(PBES2-HS384+A192KW|n/a) registered for alg algorithm PBES2-HS384+A192KW
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.Pbes2HmacShaWithAesKeyWrapAlgorithm$HmacSha512Aes256(PBES2-HS512+A256KW|n/a) registered for alg algorithm PBES2-HS512+A256KW
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.AesGcmKeyEncryptionAlgorithm$Aes128Gcm(A128GCMKW|AES/GCM/NoPadding) registered for alg algorithm A128GCMKW
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.AesGcmKeyEncryptionAlgorithm$Aes192Gcm(A192GCMKW|AES/GCM/NoPadding) registered for alg algorithm A192GCMKW
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->KeyManagementAlgorithm - org.jose4j.jwe.AesGcmKeyEncryptionAlgorithm$Aes256Gcm(A256GCMKW|AES/GCM/NoPadding) registered for alg algorithm A256GCMKW
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactoryFactory - JWE key management algorithms: [RSA1_5, RSA-OAEP, RSA-OAEP-256, dir, A128KW, A192KW, A256KW, ECDH-ES, ECDH-ES+A128KW, ECDH-ES+A192KW, ECDH-ES+A256KW, PBES2-HS256+A128KW, PBES2-HS384+A192KW, PBES2-HS512+A256KW, A128GCMKW, A192GCMKW, A256GCMKW]
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->ContentEncryptionAlgorithm - org.jose4j.jwe.AesCbcHmacSha2ContentEncryptionAlgorithm$Aes128CbcHmacSha256(A128CBC-HS256|AES/CBC/PKCS5Padding) registered for enc algorithm A128CBC-HS256
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->ContentEncryptionAlgorithm - org.jose4j.jwe.AesCbcHmacSha2ContentEncryptionAlgorithm$Aes192CbcHmacSha384(A192CBC-HS384|AES/CBC/PKCS5Padding) registered for enc algorithm A192CBC-HS384
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->ContentEncryptionAlgorithm - org.jose4j.jwe.AesCbcHmacSha2ContentEncryptionAlgorithm$Aes256CbcHmacSha512(A256CBC-HS512|AES/CBC/PKCS5Padding) registered for enc algorithm A256CBC-HS512
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->ContentEncryptionAlgorithm - org.jose4j.jwe.AesGcmContentEncryptionAlgorithm$Aes128Gcm(A128GCM|AES/GCM/NoPadding) registered for enc algorithm A128GCM
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->ContentEncryptionAlgorithm - org.jose4j.jwe.AesGcmContentEncryptionAlgorithm$Aes192Gcm(A192GCM|AES/GCM/NoPadding) registered for enc algorithm A192GCM
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->ContentEncryptionAlgorithm - org.jose4j.jwe.AesGcmContentEncryptionAlgorithm$Aes256Gcm(A256GCM|AES/GCM/NoPadding) registered for enc algorithm A256GCM
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactoryFactory - JWE content encryption algorithms: [A128CBC-HS256, A192CBC-HS384, A256CBC-HS512, A128GCM, A192GCM, A256GCM]
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactory->CompressionAlgorithm - org.jose4j.zip.DeflateRFC1951CompressionAlgorithm@6617e8d1 registered for zip algorithm DEF
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactoryFactory - JWE compression algorithms: [DEF]
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG org.jose4j.jwa.AlgorithmFactoryFactory - Initialized jose4j in 51ms
[DefaultDispatcher-worker-3 @coroutine#5] DEBUG de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver - DAT is valid for 3601 seconds
[ForkJoinPool.commonPool-worker-1] DEBUG de.fhg.aisec.ids.idscp2.core.fsm.AsyncIdscp2Factory - Starting IDSCP2 handshake for future connection with id 13a593b7-d545-4aeb-97f9-3c6ee6f685cb
[ForkJoinPool.commonPool-worker-1] DEBUG de.fhg.aisec.ids.idscp2.daps.aisecdaps.AisecDapsDriver - Issue cached DAT: eyJ0eXAiOiJhdCtqd3QiLCJraWQiOiJiMjAzMWVmYWFkMTc4OWExZmQzNjFkYzQ1Y2E4N2FiNjk5MTE5NzlkYjIyMzFiNDc4NzJkMDJiOTU5MWZmMDk4IiwiYWxnIjoiUlMyNTYifQ.eyJzY29wZSI6Imlkc2M6SURTX0NPTk5FQ1RPUl9BVFRSSUJVVEVTX0FMTCIsImF1ZCI6WyJpZHNjOklEU19DT05ORUNUT1JTX0FMTCJdLCJpc3MiOiJodHRwczovL2RhcHMtZGV2LmFpc2VjLmZyYXVuaG9mZXIuZGUvdjQiLCJzdWIiOiJEMjo3MDpGRTo3RjozMjpCQjozNzpCRjpERjpGNDowODozNjo2QjpGMTo5RTo3QTpFQjpBNDoyRDoyQTprZXlpZDpDQjo4QzpDNzpCNjo4NTo3OTpBODoyMzpBNjpDQjoxNTpBQjoxNzo1MDoyRjpFNjo2NTo0Mzo1RDpFOCIsIm5iZiI6MTcwMTc2ODQxNywiaWF0IjoxNzAxNzY4NDE3LCJqdGkiOiJmZjI2YjBmNy1iMzNlLTRhM2UtYTJiMi1lYjVkOTg2NDYyNDAiLCJleHAiOjE3MDE3NzIwMTcsImNsaWVudF9pZCI6IkQyOjcwOkZFOjdGOjMyOkJCOjM3OkJGOkRGOkY0OjA4OjM2OjZCOkYxOjlFOjdBOkVCOkE0OjJEOjJBOmtleWlkOkNCOjhDOkM3OkI2Ojg1Ojc5OkE4OjIzOkE2OkNCOjE1OkFCOjE3OjUwOjJGOkU2OjY1OjQzOjVEOkU4IiwidHJhbnNwb3J0Q2VydHNTaGEyNTYiOlsiYWQxN2UxNzg4ODE1MjA1YzIxNDk3ZTZkMzZhMzI0NDYxYzY5YTFiN2U1YzU1OGMzNzhmYjdkZjc5YzVmMDBhNyJdfQ.r_WGnf6bAVAqxTFCsv-WRszjZXYX04aw5jeqbiMNbH1QVLTAGKCybLKTo95gOReU-wmLy0Ko5XeZ2OgiWynhbQ0y1t6gingVer_O9qL3uBQecbko9BnmM-F1wuY_8o2Gu1YtmU_7DFhayZ-GHooFghXuxK1YJ1h85hTft5r-cg6RG9X6RpVzjd2jOqW5NJDBmbVhd7HkOcQWaQ7AkbanZXScCbFz-zFFZG7oX46JyQZBhl6_dX03ByAifXOXDKk-HO-w4OPTPRywg0FcSnqpyliwaF6E2C22tZSLTxah8QF-bUwZH0WE-4NLJmCXbXBVTDW9aYvUVMH6GCK8yFNsig
[Thread-13] DEBUG de.fhg.aisec.ids.idscp2.defaultdrivers.securechannel.tls13.client.TLSClient - Client cannot send data because socket is not in running state anymore.
[ForkJoinPool.commonPool-worker-1] ERROR de.fhg.aisec.ids.clearinghouse.idscp2.Idscp2Client - Client endpoint error occurred
java.util.concurrent.CompletionException: de.fhg.aisec.ids.idscp2.api.error.Idscp2HandshakeException: Handshake failed
    at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:332)
    at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:347)
    at java.base/java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:708)
    at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
    at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162)
    at de.fhg.aisec.ids.idscp2.core.fsm.AsyncIdscp2Factory.initiateIdscp2Connection$lambda$0(AsyncIdscp2Factory.kt:97)
    at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1804)
    at java.base/java.util.concurrent.CompletableFuture$AsyncRun.exec(CompletableFuture.java:1796)
    at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:373)
    at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1182)
    at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1655)
    at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1622)
    at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:165)
Caused by: de.fhg.aisec.ids.idscp2.api.error.Idscp2HandshakeException: Handshake failed
    at de.fhg.aisec.ids.idscp2.core.fsm.FSMImpl.startIdscpHandshake(FSMImpl.kt:377)
    at de.fhg.aisec.ids.idscp2.core.fsm.AsyncIdscp2Factory.initiateIdscp2Connection$lambda$0(AsyncIdscp2Factory.kt:77)
    ... 7 more

java.lang.AssertionError
    at org.junit.Assert.fail(Assert.java:87)
    at org.junit.Assert.assertTrue(Assert.java:42)
    at org.junit.Assert.assertTrue(Assert.java:53)
    at de.fhg.aisec.ids.clearinghouse.idscp2.CreatePidTests$Companion.succCreatePid(CreatePidTests.kt:99)
    at de.fhg.aisec.ids.clearinghouse.idscp2.CreatePidTests$Companion.succCreatePid$default(CreatePidTests.kt:95)
    at de.fhg.aisec.ids.clearinghouse.idscp2.CreatePidTests.createPid1(CreatePidTests.kt:24)
    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
    at java.base/java.lang.reflect.Method.invoke(Method.java:577)
    at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:727)
    at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
    at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:217)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:213)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:138)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:68)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:107)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:88)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:54)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:67)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:52)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
    at org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
    at org.junit.platform.launcher.core.SessionPerRequestLauncher.execute(SessionPerRequestLauncher.java:53)
    at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.processAllTestClasses(JUnitPlatformTestClassProcessor.java:99)
    at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.access$000(JUnitPlatformTestClassProcessor.java:79)
    at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor.stop(JUnitPlatformTestClassProcessor.java:75)
    at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.stop(SuiteTestClassProcessor.java:61)
    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
    at java.base/java.lang.reflect.Method.invoke(Method.java:577)
    at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
    at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
    at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33)
    at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
    at jdk.proxy1/jdk.proxy1.$Proxy2.stop(Unknown Source)
    at org.gradle.api.internal.tasks.testing.worker.TestWorker$3.run(TestWorker.java:193)
    at org.gradle.api.internal.tasks.testing.worker.TestWorker.executeAndMaintainThreadName(TestWorker.java:129)
    at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:100)
    at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:60)
    at org.gradle.process.internal.worker.child.ActionExecutionWorker.execute(ActionExecutionWorker.java:56)
    at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:133)
    at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:71)
    at worker.org.gradle.process.internal.worker.GradleWorkerMain.run(GradleWorkerMain.java:69)
    at worker.org.gradle.process.internal.worker.GradleWorkerMain.main(GradleWorkerMain.java:74)

Logs from TC

java.util.concurrent.CompletionException: de.fhg.aisec.ids.idscp2.api.error.Idscp2Exception: TLS session was not valid
        at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:332) ~[na:na]
        at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:347) ~[na:na]
        at java.base/java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:708) ~[na:na]
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[na:na]
        at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162) ~[na:na]
        at de.fhg.aisec.ids.idscp2.defaultdrivers.securechannel.tls13.server.TLSServerThread.handshakeCompleted(TLSServerThread.kt:207) ~[idscp2-core-0.18.0.jar:na]
        at java.base/sun.security.ssl.TransportContext$NotifyHandshake$1.run(TransportContext.java:694) ~[na:na]
        at java.base/sun.security.ssl.TransportContext$NotifyHandshake$1.run(TransportContext.java:691) ~[na:na]
        at java.base/java.security.AccessController.doPrivileged(AccessController.java:399) ~[na:na]
        at java.base/sun.security.ssl.TransportContext$NotifyHandshake.run(TransportContext.java:691) ~[na:na]
        at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
Caused by: de.fhg.aisec.ids.idscp2.api.error.Idscp2Exception: TLS session was not valid
        at de.fhg.aisec.ids.idscp2.defaultdrivers.securechannel.tls13.server.TLSServerThread.handshakeCompleted(TLSServerThread.kt:208) ~[idscp2-core-0.18.0.jar:na]
        ... 5 common frames omitted
Caused by: javax.net.ssl.SSLPeerUnverifiedException: Hostname verification failed. Peer certificate does not belong to peer host
        at de.fhg.aisec.ids.idscp2.defaultdrivers.securechannel.tls13.TLSSessionVerificationHelper.verifyTlsSession(TLSSessionVerificationHelper.kt:135) ~[idscp2-core-0.18.0.jar:na]
        at de.fhg.aisec.ids.idscp2.defaultdrivers.securechannel.tls13.server.TLSServerThread.handshakeCompleted(TLSServerThread.kt:182) ~[idscp2-core-0.18.0.jar:na]
        ... 5 common frames omitted

The environment in which we conducted our attempts is an Ubuntu 20.04 instance running on WSL (Windows Subsystem for Linux).

kragall commented 9 months ago

The hostname verification failed. In the multipart-case no hostname verification is done to check whether or not the client is a valid connector. This is not the case with idscp2. The client is validated and it is checked that the hostname in the certificate of the client is correct.

Since this check was included in the TC the tests cannot be run as they are on a test setup. They require a registered connector with a valid hostname and domain, which makes running the idscp2 tests correctly rather difficult.