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

Error during the creation of the routes (IDSCP2 server) #17

Closed boxer-code closed 2 years ago

boxer-code commented 2 years ago

Hey everyone! I've run into an error during the start of the CamelContext at the trusted-connector of my self-hosted clearing-house. Do I have to start a seperate IDSCP2 server before starting the clearing-house or am I missing another step of the setup? The obtained logs that show the error are:

2022-04-08 13:48:46.802  INFO 1 --- [onPool-worker-3] o.a.c.management.JmxManagementStrategy   : JMX is enabled

2022-04-08 13:48:47.841 DEBUG 1 --- [onPool-worker-3] d.f.a.i.i.i.r.RaProverDriverRegistry     : Register 'Dummy' driver to RA prover registry

2022-04-08 13:48:47.847 DEBUG 1 --- [onPool-worker-3] d.f.a.i.i.i.r.RaVerifierDriverRegistry   : Register 'Dummy' driver to RA verifier registry

2022-04-08 13:48:48.659 DEBUG 1 --- [onPool-worker-3] d.f.a.i.c.i.server.Idscp2ServerEndpoint  : Starting IDSCP2 server endpoint idscp2server://0.0.0.0:29292?sslContextParameters=%23ChSslContext&useIdsMessages=true

2022-04-08 13:48:48.673  INFO 1 --- [onPool-worker-3] de.fhg.aisec.ids.TrustedConnector        : Found DAPS_URL env var, DAPS URL is overridden with http://omejdn:4567

2022-04-08 13:48:49.190 DEBUG 1 --- [onPool-worker-3] d.f.a.i.c.i.server.Idscp2ServerEndpoint  : Stopping IDSCP2 server endpoint idscp2server://0.0.0.0:29292?sslContextParameters=%23ChSslContext&useIdsMessages=true

2022-04-08 13:48:49.196 ERROR 1 --- [onPool-worker-3] o.a.c.impl.engine.AbstractCamelContext   : Error starting CamelContext (camel-2) due to exception thrown: Failed to start route CH_IDSCP2_ROUTE because of null

org.apache.camel.FailedToStartRouteException: Failed to start route CH_IDSCP2_ROUTE because of null

at org.apache.camel.impl.engine.RouteService.warmUp(RouteService.java:123) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.InternalRouteStartupManager.doWarmUpRoutes(InternalRouteStartupManager.java:306) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.InternalRouteStartupManager.safelyStartRouteServices(InternalRouteStartupManager.java:189) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.InternalRouteStartupManager.doStartOrResumeRoutes(InternalRouteStartupManager.java:147) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.AbstractCamelContext.doStartCamel(AbstractCamelContext.java:3299) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.AbstractCamelContext.doStartContext(AbstractCamelContext.java:2951) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.AbstractCamelContext.doStart(AbstractCamelContext.java:2902) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.support.service.BaseService.start(BaseService.java:119) ~[camel-api-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.AbstractCamelContext.start(AbstractCamelContext.java:2586) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.DefaultCamelContext.start(DefaultCamelContext.java:247) ~[camel-core-engine-3.14.0.jar:3.14.0]

at org.apache.camel.spring.SpringCamelContext.start(SpringCamelContext.java:119) ~[camel-spring-3.14.0.jar:3.14.0]

at org.apache.camel.spring.xml.CamelContextFactoryBean.start(CamelContextFactoryBean.java:425) ~[camel-spring-xml-3.14.0.jar:3.14.0]

at org.apache.camel.spring.xml.CamelContextFactoryBean.onApplicationEvent(CamelContextFactoryBean.java:480) ~[camel-spring-xml-3.14.0.jar:3.14.0]

at org.apache.camel.spring.xml.CamelContextFactoryBean.onApplicationEvent(CamelContextFactoryBean.java:99) ~[camel-spring-xml-3.14.0.jar:3.14.0]

at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:421) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:378) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:938) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:586) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.support.FileSystemXmlApplicationContext.<init>(FileSystemXmlApplicationContext.java:142) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.support.FileSystemXmlApplicationContext.<init>(FileSystemXmlApplicationContext.java:107) ~[spring-context-5.3.14.jar:5.3.14]

at de.fhg.aisec.ids.rm.XmlDeployWatcher.startXmlApplicationContext$lambda-0(XmlDeployWatcher.kt:51) ~[ids-route-manager-6.0.0.jar:na]

at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700) ~[na:na]

at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.exec(CompletableFuture.java:1692) ~[na:na]

at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) ~[na:na]

at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020) ~[na:na]

at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656) ~[na:na]

at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594) ~[na:na]

at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) ~[na:na]

Caused by: java.lang.NullPointerException: null

at de.fhg.aisec.ids.idscp2.default_drivers.daps.aisec_daps.AisecDapsDriver.createConnectorUUID(AisecDapsDriver.kt:137) ~[idscp2-0.9.0.jar:na]

at de.fhg.aisec.ids.idscp2.default_drivers.daps.aisec_daps.AisecDapsDriver.<init>(AisecDapsDriver.kt:90) ~[idscp2-0.9.0.jar:na]

at de.fhg.aisec.ids.camel.idscp2.server.Idscp2ServerEndpoint.doStart(Idscp2ServerEndpoint.kt:275) ~[camel-idscp2-0.9.0.jar:na]

at org.apache.camel.support.service.BaseService.start(BaseService.java:119) ~[camel-api-3.14.0.jar:3.14.0]

at org.apache.camel.support.service.ServiceHelper.startService(ServiceHelper.java:113) ~[camel-api-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.RouteService.doWarmUp(RouteService.java:184) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.RouteService.warmUp(RouteService.java:121) ~[camel-base-engine-3.14.0.jar:3.14.0]

... 30 common frames omitted

2022-04-08 13:48:49.198  INFO 1 --- [onPool-worker-3] o.a.c.impl.engine.AbstractCamelContext   : Apache Camel 3.14.0 (camel-2) shutting down (timeout:45s)

2022-04-08 13:48:49.211  INFO 1 --- [onPool-worker-3] o.a.c.impl.engine.AbstractCamelContext   : Routes stopped (total:6 stopped:6)

2022-04-08 13:48:49.211  INFO 1 --- [onPool-worker-3] o.a.c.impl.engine.AbstractCamelContext   :     Stopped CH_CREATE_PID (rest://post:/process/%7Bpid%7D)

2022-04-08 13:48:49.211  INFO 1 --- [onPool-worker-3] o.a.c.impl.engine.AbstractCamelContext   :     Stopped CH_LOG_PID (rest://post:/messages/log/%7Bpid%7D)

2022-04-08 13:48:49.211  INFO 1 --- [onPool-worker-3] o.a.c.impl.engine.AbstractCamelContext   :     Stopped CH_QUERY_PID_ID (rest://post:/messages/query/%7Bpid%7D/%7Bid%7D)

2022-04-08 13:48:49.211  INFO 1 --- [onPool-worker-3] o.a.c.impl.engine.AbstractCamelContext   :     Stopped CH_QUERY_PID (rest://post:/messages/query/%7Bpid%7D)

2022-04-08 13:48:49.211  INFO 1 --- [onPool-worker-3] o.a.c.impl.engine.AbstractCamelContext   :     Stopped CH_IDSCP2_ROUTE (idscp2server://0.0.0.0:29292)

2022-04-08 13:48:49.211  INFO 1 --- [onPool-worker-3] o.a.c.impl.engine.AbstractCamelContext   :     Stopped CH_MULTIPART_ROUTE (direct://multipart)

2022-04-08 13:48:49.220  INFO 1 --- [onPool-worker-3] o.a.c.impl.engine.AbstractCamelContext   : Apache Camel 3.14.0 (camel-2) shutdown in 22ms (uptime:963ms)

Thanks in advance!

kragall commented 2 years ago

Please add the version of the CH and TC you are currently working with

boxer-code commented 2 years ago

I'm working with the v0.7.6 of the CH (service and core) and the 6.0.0 version of the TC.

kragall commented 2 years ago

The idscp2 support is rather new in the CH and there's no "official" version of the TC that supports it, yet. Try using the "ch" version of the TC (fraunhoferaisec/trusted-connector-core:ch). That's a special tag created for the Clearing House until there's an official version of the TC.

boxer-code commented 2 years ago

I tried the "ch" version but it seems to still be the same error. Could there be something else missing in the setup? These are the obtained logs:

 2022-04-08 16:22:20.557 DEBUG 1 --- [onPool-worker-1] d.f.a.i.i.i.r.RaVerifierDriverRegistry   : Register 'Dummy' driver to RA verifier registry

2022-04-08 16:22:21.172 DEBUG 1 --- [onPool-worker-1] d.f.a.i.c.i.server.Idscp2ServerEndpoint  : Starting IDSCP2 server endpoint idscp2server://0.0.0.0:29292?sslContextParameters=%23ChSslContext&useIdsMessages=true

2022-04-08 16:22:21.180  INFO 1 --- [onPool-worker-1] de.fhg.aisec.ids.TrustedConnector        : Found DAPS_URL env var, DAPS URL is overridden with http://omejdn:4567

2022-04-08 16:22:21.828 DEBUG 1 --- [onPool-worker-1] d.f.a.i.c.i.server.Idscp2ServerEndpoint  : Stopping IDSCP2 server endpoint idscp2server://0.0.0.0:29292?sslContextParameters=%23ChSslContext&useIdsMessages=true

2022-04-08 16:22:21.841 ERROR 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   : Error starting CamelContext (camel-2) due to exception thrown: Failed to start route CH_IDSCP2_ROUTE because of null

org.apache.camel.FailedToStartRouteException: Failed to start route CH_IDSCP2_ROUTE because of null

at org.apache.camel.impl.engine.RouteService.warmUp(RouteService.java:123) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.InternalRouteStartupManager.doWarmUpRoutes(InternalRouteStartupManager.java:306) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.InternalRouteStartupManager.safelyStartRouteServices(InternalRouteStartupManager.java:189) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.InternalRouteStartupManager.doStartOrResumeRoutes(InternalRouteStartupManager.java:147) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.AbstractCamelContext.doStartCamel(AbstractCamelContext.java:3299) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.AbstractCamelContext.doStartContext(AbstractCamelContext.java:2951) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.AbstractCamelContext.doStart(AbstractCamelContext.java:2902) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.support.service.BaseService.start(BaseService.java:119) ~[camel-api-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.AbstractCamelContext.start(AbstractCamelContext.java:2586) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.DefaultCamelContext.start(DefaultCamelContext.java:247) ~[camel-core-engine-3.14.0.jar:3.14.0]

at org.apache.camel.spring.SpringCamelContext.start(SpringCamelContext.java:119) ~[camel-spring-3.14.0.jar:3.14.0]

at org.apache.camel.spring.xml.CamelContextFactoryBean.start(CamelContextFactoryBean.java:425) ~[camel-spring-xml-3.14.0.jar:3.14.0]

at org.apache.camel.spring.xml.CamelContextFactoryBean.onApplicationEvent(CamelContextFactoryBean.java:480) ~[camel-spring-xml-3.14.0.jar:3.14.0]

at org.apache.camel.spring.xml.CamelContextFactoryBean.onApplicationEvent(CamelContextFactoryBean.java:99) ~[camel-spring-xml-3.14.0.jar:3.14.0]

at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:421) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:378) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:938) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:586) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.support.FileSystemXmlApplicationContext.<init>(FileSystemXmlApplicationContext.java:142) ~[spring-context-5.3.14.jar:5.3.14]

at org.springframework.context.support.FileSystemXmlApplicationContext.<init>(FileSystemXmlApplicationContext.java:107) ~[spring-context-5.3.14.jar:5.3.14]

at de.fhg.aisec.ids.rm.XmlDeployWatcher.startXmlApplicationContext$lambda-0(XmlDeployWatcher.kt:51) ~[ids-route-manager-6.1.0.jar:na]

at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768) ~[na:na]

at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.exec(CompletableFuture.java:1760) ~[na:na]

at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:373) ~[na:na]

at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1182) ~[na:na]

at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1655) ~[na:na]

at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1622) ~[na:na]

at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:165) ~[na:na]

Caused by: java.lang.NullPointerException: Cannot invoke "org.bouncycastle.asn1.ASN1OctetString.getOctets()" because "akiOc" is null

at de.fhg.aisec.ids.idscp2.default_drivers.daps.aisec_daps.AisecDapsDriver.extractConnectorUUID(AisecDapsDriver.kt:195) ~[idscp2-0.9.2.jar:na]

at de.fhg.aisec.ids.idscp2.default_drivers.daps.aisec_daps.AisecDapsDriver.<init>(AisecDapsDriver.kt:99) ~[idscp2-0.9.2.jar:na]

at de.fhg.aisec.ids.camel.idscp2.server.Idscp2ServerEndpoint.doStart(Idscp2ServerEndpoint.kt:275) ~[camel-idscp2-0.9.2.jar:na]

at org.apache.camel.support.service.BaseService.start(BaseService.java:119) ~[camel-api-3.14.0.jar:3.14.0]

at org.apache.camel.support.service.ServiceHelper.startService(ServiceHelper.java:113) ~[camel-api-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.RouteService.doWarmUp(RouteService.java:184) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.RouteService.warmUp(RouteService.java:121) ~[camel-base-engine-3.14.0.jar:3.14.0]

... 30 common frames omitted

2022-04-08 16:22:21.850  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   : Apache Camel 3.14.0 (camel-2) shutting down (timeout:45s)

2022-04-08 16:22:21.874  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   : Routes stopped (total:6 stopped:6)

2022-04-08 16:22:21.874  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   :     Stopped CH_CREATE_PID (rest://post:/process/%7Bpid%7D)

2022-04-08 16:22:21.875  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   :     Stopped CH_LOG_PID (rest://post:/messages/log/%7Bpid%7D)

2022-04-08 16:22:21.875  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   :     Stopped CH_QUERY_PID_ID (rest://post:/messages/query/%7Bpid%7D/%7Bid%7D)

2022-04-08 16:22:21.875  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   :     Stopped CH_QUERY_PID (rest://post:/messages/query/%7Bpid%7D)

2022-04-08 16:22:21.875  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   :     Stopped CH_IDSCP2_ROUTE (idscp2server://0.0.0.0:29292)

2022-04-08 16:22:21.875  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   :     Stopped CH_MULTIPART_ROUTE (direct://multipart)

2022-04-08 16:22:21.892  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   : Apache Camel 3.14.0 (camel-2) shutdown in 42ms (uptime:1s54ms)
kragall commented 2 years ago

Could you add the configuration of your TC docker container?

boxer-code commented 2 years ago

Of course! My docker-compose to start the clearing-house-service looks like this:

version: '3.7'
services:
   clearing-house-mongo:
    image: mongo:latest
    container_name: "clearing-house-mongo"
    environment:
      MONGO_INITDB_DATABASE: process
    ports:
      - 27019:27017
    volumes:
      - mongodb_data_container3:/data/db
   clearing-house-api:
    build:
      context: .
      dockerfile: .\docker\clearing-house-api-multistage.Dockerfile
    container_name: "clearing-house-api"
    depends_on:
        - document-api
        - keyring-api
        - clearing-house-mongo
    environment:
        # Allowed levels: Off, Error, Warn, Info, Debug, Trace
        - API_LOG_LEVEL=Debug
    ports:
        - "8000:8000"
    volumes:
        - ./data/Rocket.toml:/server/Rocket.toml
        - ./data/keys:/server/keys
        - ./data/certs:/server/certs
   tc-core:
    container_name: "tc-core"
    image: fraunhoferaisec/trusted-connector-core:ch
    tty: true
    stdin_open: true
    volumes:
        - ./data/trusted-connector/allow-all-flows.pl:/root/deploy/allow-all-flows.pl
        - ./data/trusted-connector/tc-core.p12:/root/etc/keystore.p12
        - ./data/trusted-connector/truststore.p12:/root/etc/truststore.p12
        - ./data/trusted-connector/clearing-house-processors-0.7.6.jar:/root/jars/clearing-house-processors.jar
        - ./data/trusted-connector/routes/clearing-house-routes.xml:/root/deploy/clearing-house-routes.xml
        - //var/run/docker.sock://var/run/docker.sock
    environment:
        TC_DAPS_URL: http://omejdn:4567
    ports:
        - "7777:8080"
        - "8443:8443"
        - "9999:9999"

volumes: 
  mongodb_data_container3:

networks:
  default:
    external: 
      name: broker-localhost_default
kragall commented 2 years ago

Thank you, and another question: Could you temporarily remove the CH_IDSCP2_ROUTE (lines 84-136 in clearing-house-routes.xml) from your routes file and start the connector? Do all other routes then load correctly? Or do you get a similar error?

kragall commented 2 years ago

Just to clarify, what's happening in the routes:

  1. Line 31 defines the endpoint for the IDS multipart protocol, i.e. the TC listens on port 9999 for TLS connections sending data using the IDS multipart protocol
  2. Line 85 defines the endpoint for the idscp2 protocol, i.e. the TC listens on port 29292 for TLS connections sending data using the idscp2 protocol

So you don't need to start a separate IDSCP2 server. But you will only be able to communicate with the IDSCP2 routes of the CH using an IDSCP2 client.

boxer-code commented 2 years ago

Thank you for the explanation! When I remove the CH_IDSCP_ROUTE the other routes seems to be loaded correctly. The logs end with these lines:

2022-04-11 10:45:12.048  INFO 1 --- [           main] de.fhg.aisec.ids.rm.XmlDeployWatcher     : XML file deploy/clearing-house-routes.xml detected, creating XmlApplicationContext...

2022-04-11 10:45:14.428  INFO 1 --- [onPool-worker-1] .a.c.c.x.AbstractCamelContextFactoryBean : Using custom TypeConverterRegistry: org.apache.camel.impl.converter.DefaultTypeConverter@2f318c58

2022-04-11 10:45:14.450  INFO 1 --- [onPool-worker-1] .a.c.c.x.AbstractCamelContextFactoryBean : Using custom InterceptStrategy with id: idsCamelInterceptor and implementation: de.fhg.aisec.ids.dataflowcontrol.CamelInterceptor@2a19c36b

2022-04-11 10:45:14.536  INFO 1 --- [onPool-worker-1] o.a.c.management.JmxManagementStrategy   : JMX is enabled

2022-04-11 10:45:15.988  INFO 1 --- [onPool-worker-1] org.eclipse.jetty.util.log               : Logging initialized @24247ms to org.eclipse.jetty.util.log.Slf4jLog

2022-04-11 10:45:16.080  INFO 1 --- [onPool-worker-1] o.a.c.support.jsse.SSLContextParameters  : Available providers: SUN version 17.

2022-04-11 10:45:16.890  INFO 1 --- [onPool-worker-1] o.a.c.c.jetty9.JettyHttpComponent9       : Connector on port: 9999 is using includeCipherSuites: [] excludeCipherSuites: [^.*_(MD5|SHA|SHA1)$, ^TLS_RSA_.*$, ^SSL_.*$, ^.*_NULL_.*$, ^.*_anon_.*$] includeProtocols: [] excludeProtocols: [SSL, SSLv2, SSLv2Hello, SSLv3]

2022-04-11 10:45:16.950  INFO 1 --- [onPool-worker-1] org.eclipse.jetty.server.Server          : jetty-9.4.44.v20210927; built: 2021-09-27T23:02:44.612Z; git: 8da83308eeca865e495e53ef315a249d63ba9332; jvm 17.0.2+8-Debian-1deb11u1

2022-04-11 10:45:17.052  INFO 1 --- [onPool-worker-1] o.e.jetty.server.handler.ContextHandler  : Started o.e.j.s.ServletContextHandler@69a745e6{/,null,AVAILABLE}

2022-04-11 10:45:17.183  INFO 1 --- [onPool-worker-1] o.e.jetty.server.AbstractConnector       : Started ServerConnector@6d5307c3{ssl, (ssl, http/1.1)}{0.0.0.0:9999}

2022-04-11 10:45:17.184  INFO 1 --- [onPool-worker-1] org.eclipse.jetty.server.Server          : Started @25443ms

2022-04-11 10:45:17.197  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   : Routes startup (total:5 started:5)

2022-04-11 10:45:17.198  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   :     Started CH_MULTIPART_ROUTE (direct://multipart)

2022-04-11 10:45:17.198  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   :     Started CH_QUERY_PID (rest://post:/messages/query/%7Bpid%7D)

2022-04-11 10:45:17.198  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   :     Started CH_QUERY_PID_ID (rest://post:/messages/query/%7Bpid%7D/%7Bid%7D)

2022-04-11 10:45:17.198  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   :     Started CH_LOG_PID (rest://post:/messages/log/%7Bpid%7D)

2022-04-11 10:45:17.198  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   :     Started CH_CREATE_PID (rest://post:/process/%7Bpid%7D)

2022-04-11 10:45:17.198  INFO 1 --- [onPool-worker-1] o.a.c.impl.engine.AbstractCamelContext   : Apache Camel 3.14.0 (camel-2) started in 2s682ms (build:7ms init:997ms start:1s678ms)
boxer-code commented 2 years ago

I tried to use the CH without the idscp2 route but now I've run into a new error. Could that have any connection to the missing idscp2 route or should I open a new issue? The obtained logs of the trusted connector of the CH are:

2022-04-13 08:36:09.033 DEBUG 1 --- [qtp507002429-28] d.f.a.i.d.PolicyDecisionPoint            : Query for uncached label transformation: once(setof(S, action_service('From[rest://post:/messages/query/%7Bpid%7D?consumerComponentName=jetty&routeId=CH_QUERY_PID]', S), SC); SC = []),

collect_creates_labels(SC, ACraw), set_of(ACraw, Adds),

collect_removes_labels(SC, RCraw), set_of(RCraw, Removes).

2022-04-13 08:36:09.048 DEBUG 1 --- [qtp507002429-28] d.f.a.i.d.PolicyDecisionPoint            : Transformation: de.fhg.aisec.ids.api.policy.TransformationDecision@121836b4

2022-04-13 08:36:09.066 DEBUG 1 --- [qtp507002429-28] d.f.a.i.c.m.MultiPartStringParser        : Found header:

{

  "@context" : {

    "ids" : "https://w3id.org/idsa/core/",

    "idsc" : "https://w3id.org/idsa/code/"

  },

  "@type" : "ids:QueryMessage",

  "@id" : "https://w3id.org/idsa/autogen/queryMessage/0d60bc00-d480-4f52-b536-3f0b7d0af2a1",

  "ids:senderAgent" : {

    "@id" : "https://w3id.org/idsa/autogen/baseConnector/7b934432-a85e-41c5-9f65-669219dde4ea"

  },

  "ids:securityToken" : {

    "@type" : "ids:DynamicAttributeToken",

    "@id" : "https://w3id.org/idsa/autogen/dynamicAttributeToken/863ece2d-76e9-4522-a393-b4f9f9164026",

    "ids:tokenValue" : "eyJ0eXAiOiJKV1QiLCJraWQiOiJkZWZhdWx0IiwiYWxnIjoiUlMyNTYifQ.eyJzY29wZXMiOlsiaWRzYzpJRFNfQ09OTkVDVE9SX0FUVFJJQlVURVNfQUxMIl0sImF1ZCI6Imlkc2M6SURTX0NPTk5FQ1RPUlNfQUxMIiwiaXNzIjoiaHR0cDovL29tZWpkbjo0NTY3IiwibmJmIjoxNjQ5ODM4NjI5LCJpYXQiOjE2NDk4Mzg2MjksImp0aSI6Ik5EZ3pPVGcyT0RFM05qTTFOemd6T1RJNE9BPT0iLCJleHAiOjE2NDk4NDIyMjksInNlY3VyaXR5UHJvZmlsZSI6Imlkc2M6QkFTRV9TRUNVUklUWV9QUk9GSUxFIiwicmVmZXJyaW5nQ29ubmVjdG9yIjoiaHR0cDovL3Rlc3RiZWQxLmRlbW8iLCJAdHlwZSI6ImlkczpEYXRQYXlsb2FkIiwiQGNvbnRleHQiOiJodHRwczovL3czaWQub3JnL2lkc2EvY29udGV4dHMvY29udGV4dC5qc29ubGQiLCJ0cmFuc3BvcnRDZXJ0c1NoYTI1NiI6ImM2OGQ5ZTZiYTNmMTc5OWJjYmU1YmVjOWQ3ZDk4YjE1YjBlZjJmMjkyYzgwZjZiY2E5OTQxNzhhYTk1YWUxMGQiLCJzdWIiOiI2NjowNzpFRDpFNTo4MDpFNDoyOTo2RDoxRTpERDpGNzo0MzpDQTowRTpFQjozODozMjpDODozQTo0MzprZXlpZDowNzpGQzo5NToxNzpDNDo5NTpCOTpFNDpBRDowOTo1RjowNzoxRTpEMjoyMDo3NToyRDo4OTo2Njo4NSJ9.NTLTwUk6PXPFXsxXX2v_nDgmZVqc-e9dOsiw5wAANQjNR9YT3fSD4cTFI5KmkvxH0MDETYHLmrM1odYn009aHB9I9rD78Fq4Md-ful85rg8fjurLAd10-clwgSDgF3C5JsTTH4K1_dDgGHS25Y1DQ3OdRcKybKzHJUaE4L2I5WRZcdDhuckQcLlz_V-AQBijude5BmfmquI_JLtyZiEPrqQyPIzyn_VlFmZS-TVMiulKHRf0ojxNOQ70RlZfDWoriBbx-ik4ywj2_ToFpzmDfVRrkAM47uSOewMOXErcPq33QWSbkyWi1m1uLT3ynjXxcPOYNsfmrQmHcJomMIUVsg",

    "ids:tokenFormat" : {

      "@id" : "https://w3id.org/idsa/code/JWT"

    }

  },

  "ids:modelVersion" : "4.2.7",

  "ids:issued" : {

    "@value" : "2022-04-13T08:36:08.954Z",

    "@type" : "http://www.w3.org/2001/XMLSchema#dateTimeStamp"

  },

  "ids:issuerConnector" : {

    "@id" : "https://w3id.org/idsa/autogen/baseConnector/7b934432-a85e-41c5-9f65-669219dde4ea"

  },

  "ids:queryLanguage" : {

    "@id" : "https://w3id.org/idsa/code/SPARQL"

  },

  "ids:queryScope" : {

    "@id" : "https://w3id.org/idsa/code/ALL"

  },

  "ids:recipientScope" : {

    "@id" : "https://w3id.org/idsa/code/BROKER"

  }

}

2022-04-13 08:36:09.067 DEBUG 1 --- [qtp507002429-28] d.f.a.i.c.m.MultiPartStringParser        : Found body with Content-Type "null"

2022-04-13 08:36:09.636 ERROR 1 --- [qtp507002429-28] o.a.c.p.e.DefaultErrorHandler            : Failed delivery for (MessageId: 738CE156D3476E8-0000000000000001 on ExchangeId: 738CE156D3476E8-0000000000000001). Exhausted after delivery attempt: 1 caught: java.lang.NullPointerException: Cannot invoke "org.bouncycastle.asn1.ASN1OctetString.getOctets()" because "akiOc" is null

Message History (complete message history is disabled)

---------------------------------------------------------------------------------------------------------------------------------------

RouteId              ProcessorId          Processor                                                                        Elapsed (ms)

[CH_QUERY_PID      ] [CH_QUERY_PID      ] [from[jetty:https://0.0.0.0:9999/messages/query/%7Bpid%7D?httpMethodRestrict=PO] [       602]

...

[CH_MULTIPART_ROUTE] [process4          ] [ref:CHOutputProcessor                                                         ] [         0]

Stacktrace

---------------------------------------------------------------------------------------------------------------------------------------

java.lang.NullPointerException: Cannot invoke "org.bouncycastle.asn1.ASN1OctetString.getOctets()" because "akiOc" is null

at de.fhg.aisec.ids.idscp2.default_drivers.daps.aisec_daps.AisecDapsDriver.extractConnectorUUID(AisecDapsDriver.kt:195) ~[idscp2-0.9.2.jar:na]

at de.fhg.aisec.ids.idscp2.default_drivers.daps.aisec_daps.AisecDapsDriver.<init>(AisecDapsDriver.kt:99) ~[idscp2-0.9.2.jar:na]

at de.fhg.aisec.ids.clearinghouse.ClearingHouseOutputProcessor$Companion.processClearingHouseOutput(ClearingHouseOutputProcessor.kt:62) ~[clearing-house-processors.jar:na]

at de.fhg.aisec.ids.clearinghouse.ClearingHouseOutputProcessor.process(ClearingHouseOutputProcessor.kt:40) ~[clearing-house-processors.jar:na]

at org.apache.camel.support.processor.DelegateSyncProcessor.process(DelegateSyncProcessor.java:65) ~[camel-support-3.14.0.jar:3.14.0]

at org.apache.camel.support.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:104) ~[camel-support-3.14.0.jar:3.14.0]

at de.fhg.aisec.ids.dataflowcontrol.PolicyEnforcementPoint.process(PolicyEnforcementPoint.kt:281) ~[ids-dataflow-control-6.1.0.jar:na]

at org.apache.camel.support.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:104) ~[camel-support-3.14.0.jar:3.14.0]

at org.apache.camel.processor.errorhandler.RedeliveryErrorHandler$RedeliveryTask.doRun(RedeliveryErrorHandler.java:810) ~[camel-core-processor-3.14.0.jar:3.14.0]

at org.apache.camel.processor.errorhandler.RedeliveryErrorHandler$RedeliveryTask.run(RedeliveryErrorHandler.java:718) ~[camel-core-processor-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.DefaultReactiveExecutor$Worker.schedule(DefaultReactiveExecutor.java:187) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.DefaultReactiveExecutor.scheduleMain(DefaultReactiveExecutor.java:64) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.processor.Pipeline.process(Pipeline.java:184) ~[camel-core-processor-3.14.0.jar:3.14.0]

at org.apache.camel.impl.engine.CamelInternalProcessor.process(CamelInternalProcessor.java:398) ~[camel-base-engine-3.14.0.jar:3.14.0]

at org.apache.camel.component.jetty.CamelContinuationServlet.doService(CamelContinuationServlet.java:245) ~[camel-jetty-common-3.14.0.jar:3.14.0]

at org.apache.camel.http.common.CamelServlet.service(CamelServlet.java:130) ~[camel-http-common-3.14.0.jar:3.14.0]

at javax.servlet.http.HttpServlet.service(HttpServlet.java:584) ~[jakarta.servlet-api-4.0.4.jar:4.0.4]

at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:550) ~[jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) ~[jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:400) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:645) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:392) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555) ~[jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410) ~[jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164) ~[jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]

at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]

at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
kragall commented 2 years ago

It seems to be the same underlying problem and from what I can discern here, it's probably due to the certificates you are using. Either there's a configuration error or the certificate you are using differs from the "standard format" of certificates the DAPS is generating.

In both cases where you encountered the error, the underlying library of the trusted connector is not able to get the certificate of the "local" connector, i.e. the certificate of the Clearing House.

boxer-code commented 2 years ago

Thanks! I changed the certificate used by the trusted-connector and the error seems to be fixed.