search

datasharingframework / dsf

A distributed process engine based on the BPMN 2.0 and FHIR R4 standards
https://dsf.dev
Apache License 2.0
13 stars 7 forks source link

401 Unauthorized BPE to FHIR communication #109

Closed t4deon closed 1 year ago

t4deon commented 1 year ago

Hi,

I'm trying to setup DSF 1.2.0 on a single machine for testing purposes. I followed the instructions, created certificates signed by my own CA (so not DFN) and also enabled OIDC. OIDC works like a charm for the FHIR server. However, I'm running into a persistent 401 Unauthorized in the communication between the BPE and FHIR server. (logs see below). I didn't add any process plugins.

Docker compose files: FHIR:

version: '3.8'
services:
  proxy:
    image: ghcr.io/datasharingframework/fhir_proxy:1.2.0
    restart: on-failure
    ports:
      - 127.0.0.1:80:80
      - 443:443
    secrets:
      - ssl_certificate_file.pem
      - ssl_certificate_key_file.pem
      - ssl_ca_certificate_file.pem
    environment:
      TZ: Europe/Berlin
      HTTPS_SERVER_NAME_PORT: localhost:443
      APP_SERVER_IP: fhirserver
      SSL_CERTIFICATE_FILE: /run/secrets/ssl_certificate_file.pem
      SSL_CERTIFICATE_KEY_FILE: /run/secrets/ssl_certificate_key_file.pem
      SSL_CA_CERTIFICATE_FILE: /run/secrets/ssl_ca_certificate_file.pem
      SSL_VERIFY_CLIENT: optional
    networks:
      - frontend
    depends_on:
      - fhirserver
  fhirserver:
    image: ghcr.io/datasharingframework/fhir:1.2.0
    restart: on-failure
    secrets:
      - db_liquibase.password
      - db_user.password
      - db_user_permanent_delete.password
      - app_client_trust_certificates.pem
      - app_client_certificate.pem
      - app_client_certificate_private_key.pem
      - ssl_ca_certificate_file.pem
    volumes:
      - type: bind
        source: ./log
        target: /opt/fhir/log
    environment:
      TZ: Europe/Berlin
      DEV_DSF_SERVER_AUTH_TRUST_CLIENT_CERTIFICATE_CAS:  /run/secrets/ssl_ca_certificate_file.pem
      DEV_DSF_FHIR_DB_LIQUIBASE_PASSWORD_FILE: /run/secrets/db_liquibase.password
      DEV_DSF_FHIR_DB_USER_PASSWORD_FILE: /run/secrets/db_user.password
      DEV_DSF_FHIR_DB_USER_PERMANENT_DELETE_PASSWORD_FILE: /run/secrets/db_user_permanent_delete.password
      DEV_DSF_FHIR_CLIENT_TRUST_SERVER_CERTIFICATE_CAS: /run/secrets/app_client_trust_certificates.pem
      DEV_DSF_FHIR_CLIENT_CERTIFICATE: /run/secrets/app_client_certificate.pem
      DEV_DSF_FHIR_CLIENT_CERTIFICATE_PRIVATE_KEY: /run/secrets/app_client_certificate_private_key.pem
      DEV_DSF_FHIR_DB_URL: jdbc:postgresql://db_fhir/fhir
      DEV_DSF_FHIR_SERVER_ORGANIZATION_IDENTIFIER_VALUE: localhost
      DEV_DSF_FHIR_SERVER_BASE_URL: https://localhost/fhir
      DEV_DSF_FHIR_SERVER_ORGANIZATION_THUMBPRINT: ceed89db7ea1f84d18e676c6e3d8347b683cc49c2080112e7966e9d3239d401dd40d52b6bae433aff10c5c0a0b7556fda7007824ac85702898eb3f9df9279a88
      DEV_DSF_FHIR_SERVER_ROLECONFIG: |
        - admin:
            email:
              - ...
            dsf-role:
              - READ
              - SEARCH
              - HISTORY
              - CREATE
              - WEBSOCKET
              - DELETE
      DEV_DSF_SERVER_AUTH_OIDC_AUTHORIZATION_CODE_FLOW: 'true'
      DEV_DSF_SERVER_AUTH_OIDC_BEARER_TOKEN: 'true'
      DEV_DSF_SERVER_AUTH_OIDC_PROVIDER_REALM_BASE_URL: https://.../auth/realms/master
      DEV_DSF_SERVER_AUTH_OIDC_CLIENT_ID: ...
      DEV_DSF_SERVER_AUTH_OIDC_CLIENT_SECRET: ...
    networks:
      - frontend
      - backend
    depends_on:
      - db_fhir

  db_fhir:
    image: postgres:15
    restart: on-failure
    healthcheck:
      test: ["CMD-SHELL", "pg_isready -U liquibase_user -d fhir"]
      interval: 10s
      timeout: 5s
      retries: 5
    volumes:
      - type: bind
        source: ./postgres-data
        target: /var/lib/postgresql/data
    environment:
      TZ: Europe/Berlin
      POSTGRES_PASSWORD_FILE: /run/secrets/db_liquibase.password
      POSTGRES_USER: liquibase_user
      POSTGRES_DB: fhir
    networks:
      - backend
    secrets:
      - db_liquibase.password

secrets:
  ssl_certificate_file.pem:
    file: ./secrets/ssl_certificate_file.pem
  ssl_certificate_key_file.pem:
    file: ./secrets/ssl_certificate_key_file.pem
  ssl_ca_certificate_file.pem:
    file: ./secrets/ssl_ca_certificate_file.pem
  db_liquibase.password:
    file: ./secrets/db_liquibase.password
  db_user.password:
    file: ./secrets/db_user.password
  db_user_permanent_delete.password:
    file: ./secrets/db_user_permanent_delete.password

  app_client_trust_certificates.pem:
    file: ./secrets/ssl_root_ca_certificate_file.pem
  app_client_certificate.pem:
    file: ./secrets/client_certificate.pem
  app_client_certificate_private_key.pem:
    file: ./secrets/client_certificate_private_key.pem
networks:
  frontend:
    name: dsf-frontend
  backend:
    name: dsf-backend

BPE:

version: '3.8'
services:
  app:
    image: ghcr.io/datasharingframework/bpe:1.2.0
    restart: on-failure
    secrets:
      - db_liquibase.password
      - db_user.password
      - db_user_camunda.password
      - app_client_trust_certificates.pem
      - app_client_certificate.pem
      - app_client_certificate_private_key.pem
      - ssl_ca_certificate_file.pem
    volumes:
      - type: bind
        source: ./process
        target: /opt/bpe/process
        read_only: true
      - type: bind
        source: ./log
        target: /opt/bpe/log
      - type: bind
        source: ./cache
        target: /opt/bpe/cache
    environment:
      TZ: Europe/Berlin
      DEV_DSF_SERVER_AUTH_TRUST_CLIENT_CERTIFICATE_CAS: /run/secrets/ssl_ca_certificate_file.pem
      DEV_DSF_BPE_DB_LIQUIBASE_PASSWORD_FILE: /run/secrets/db_liquibase.password
      DEV_DSF_BPE_DB_USER_PASSWORD_FILE: /run/secrets/db_user.password
      DEV_DSF_BPE_DB_USER_CAMUNDA_PASSWORD_FILE: /run/secrets/db_user_camunda.password
      DEV_DSF_BPE_FHIR_CLIENT_TRUST_SERVER_CERTIFICATE_CAS: /run/secrets/app_client_trust_certificates.pem
      DEV_DSF_BPE_FHIR_CLIENT_CERTIFICATE: /run/secrets/app_client_certificate.pem
      DEV_DSF_BPE_FHIR_CLIENT_CERTIFICATE_PRIVATE_KEY: /run/secrets/app_client_certificate_private_key.pem
      DEV_DSF_BPE_DB_URL: jdbc:postgresql://db/bpe
      DEV_DSF_BPE_FHIR_SERVER_BASE_URL: https://proxy/fhir
      DEV_DSF_BPE_FHIR_SERVER_ORGANIZATION_IDENTIFIER_VALUE: localhost
      DEV_DSF_SERVER_AUTH_OIDC_AUTHORIZATION_CODE_FLOW: 'true'
      DEV_DSF_SERVER_AUTH_OIDC_BEARER_TOKEN: 'true'
      DEV_DSF_SERVER_AUTH_OIDC_PROVIDER_REALM_BASE_URL: https://.../auth/realms/master
      DEV_DSF_SERVER_AUTH_OIDC_CLIENT_ID: ...
      DEV_DSF_SERVER_AUTH_OIDC_CLIENT_SECRET: ...
    networks:
      - backend
      - frontend
    depends_on:
      - db
  db:
    image: postgres:15
    restart: on-failure
    healthcheck:
      test: ["CMD-SHELL", "pg_isready -U liquibase_user -d bpe"]
      interval: 10s
      timeout: 5s
      retries: 5
    volumes:
      - type: bind
        source: ./postgres-data
        target: /var/lib/postgresql/data
    environment:
      TZ: Europe/Berlin
      POSTGRES_PASSWORD_FILE: /run/secrets/db_liquibase.password
      POSTGRES_USER: liquibase_user
      POSTGRES_DB: bpe
    networks:
      - backend
    secrets:
      - db_liquibase.password

secrets:
  db_liquibase.password:
    file: ./secrets/db_liquibase.password
  db_user.password:
    file: ./secrets/db_user.password
  db_user_camunda.password:
    file: ./secrets/db_user_camunda.password
  app_client_trust_certificates.pem:
    file: ./secrets/ssl_root_ca_certificate_file.pem
  app_client_certificate.pem:
    file: ./secrets/client_certificate.pem
  app_client_certificate_private_key.pem:
    file: ./secrets/client_certificate_private_key.pem
  ssl_ca_certificate_file.pem:
    file: ./secrets/ssl_ca_certificate_file.pem

networks:
  backend:
    name: dsf-backend
    external: true
  frontend:
    name: dsf-frontend
    external: true

Log BPE:

2023-09-29 08:40:38,424 [main] INFO  dev.dsf.tools.db.DbMigrator - Executing DB migration ...
2023-09-29 08:40:38,886 [main] DEBUG dev.dsf.tools.db.DbMigrator - UPDATE SUMMARY
2023-09-29 08:40:38,886 [main] DEBUG dev.dsf.tools.db.DbMigrator - Run:                          0
2023-09-29 08:40:38,886 [main] DEBUG dev.dsf.tools.db.DbMigrator - Previously run:               6
2023-09-29 08:40:38,887 [main] DEBUG dev.dsf.tools.db.DbMigrator - Filtered out:                 0
2023-09-29 08:40:38,887 [main] DEBUG dev.dsf.tools.db.DbMigrator - -------------------------------
2023-09-29 08:40:38,887 [main] DEBUG dev.dsf.tools.db.DbMigrator - Total change sets:            6
2023-09-29 08:40:38,887 [main] INFO  dev.dsf.tools.db.DbMigrator - Executing DB migration [Done]
2023-09-29 08:40:39,138 [main] DEBUG dev.dsf.common.jetty.JettyServer - Java classpath: [...]
2023-09-29 08:40:39,138 [main] DEBUG dev.dsf.common.jetty.JettyServer - Resources for jetty: [file:///opt/bpe/lib/dsf-bpe-server-1.2.0.jar]
2023-09-29 08:40:39,138 [main] DEBUG dev.dsf.common.jetty.JettyServer - Init parameters: {}
2023-09-29 08:40:39,147 [main] INFO  dev.dsf.common.config.AbstractJettyConfig - OIDC authorization code flow enabled
2023-09-29 08:40:39,148 [main] INFO  dev.dsf.common.config.AbstractJettyConfig - OIDC bearer token enabled
2023-09-29 08:40:39,151 [main] INFO  dev.dsf.common.auth.ClientCertificateAuthenticator - Using [CN=Root CA, O=Root CA] to validate client certificates
2023-09-29 08:40:39,154 [main] INFO  dev.dsf.common.jetty.JettyServer - Starting jetty server ...
2023-09-29 08:40:39,154 [main] INFO  org.eclipse.jetty.server.Server - jetty-11.0.16; built: 2023-08-25T19:43:30.438Z; git: bedff458c4dd1a716d59e17b8cb0d2042eeab291; jvm 17.0.8+7-LTS
2023-09-29 08:40:39,243 [main] INFO  org.eclipse.jetty.server.handler.ContextHandler.bpe - 1 Spring WebApplicationInitializers detected on classpath
2023-09-29 08:40:39,257 [main] INFO  org.eclipse.jetty.server.session.DefaultSessionIdManager - Session workerName=node0
2023-09-29 08:40:39,374 [main] INFO  org.eclipse.jetty.server.handler.ContextHandler.bpe - Initializing Spring root WebApplicationContext
2023-09-29 08:40:39,507 [main] INFO  dev.dsf.bpe.spring.config.PropertiesConfig - Concurrency config: {process-threads: 12, engine-core-pool: 4, engine-queue: 40, engine-max-pool: 10}
2023-09-29 08:40:39,509 [main] INFO  dev.dsf.common.config.ProxyConfigImpl - Forward proxy config: {url: null, username: null, password: null, no-proxy: []}
2023-09-29 08:40:39,509 [main] INFO  dev.dsf.bpe.spring.config.FhirClientConfig - Local webservice client config: {trustStorePath: /run/secrets/app_client_trust_certificates.pem, certificatePath: /run/secrets/app_client_certificate.pem, privateKeyPath: /run/secrets/app_client_certificate_private_key.pem, privateKeyPassword: null, url: https://proxy/fhir, proxy: disabled}
2023-09-29 08:40:39,509 [main] INFO  dev.dsf.bpe.spring.config.FhirClientConfig - Local websocket client config: {trustStorePath: /run/secrets/app_client_trust_certificates.pem, certificatePath: /run/secrets/app_client_certificate.pem, privateKeyPath: /run/secrets/app_client_certificate_private_key.pem, privateKeyPassword: null, url: wss://proxy/fhir/ws, proxy: disabled}
2023-09-29 08:40:39,510 [main] INFO  dev.dsf.bpe.spring.config.FhirClientConfig - Remote webservice client config: {trustStorePath: /run/secrets/app_client_trust_certificates.pem, certificatePath: /run/secrets/app_client_certificate.pem, privateKeyPath: /run/secrets/app_client_certificate_private_key.pem, privateKeyPassword: null, proxy: disabled}
2023-09-29 08:40:39,512 [main] INFO  dev.dsf.bpe.spring.config.MailConfig - Mail client config: SMTP client not configured, sending mails to debug log, configure at least SMTP server host and port
2023-09-29 08:40:41,601 [main] INFO  dev.dsf.tools.build.BuildInfoReaderImpl - System default timezone: Europe/Berlin
2023-09-29 08:40:41,603 [main] INFO  dev.dsf.tools.build.BuildInfoReaderImpl - Artifact: dsf-bpe-server-jetty, version: 1.2.0, build: 2023-09-12T23:05:56+02:00, branch: main, commit: 5694d7d764779890202623cd0012ee494a28dbc3
2023-09-29 08:40:41,603 [main] INFO  dev.dsf.bpe.spring.config.PostStartupConfig - Deploying process plugins ...
2023-09-29 08:40:41,604 [main] DEBUG dev.dsf.fhir.client.AbstractFhirWebserviceClientJerseyWithRetry - First try ...
2023-09-29 08:40:41,878 [main] DEBUG dev.dsf.fhir.client.FhirWebserviceClientJersey - HTTP 401: Unauthorized
2023-09-29 08:40:41,882 [main] WARN  dev.dsf.fhir.client.FhirWebserviceClientJersey - OperationOutcome: 
2023-09-29 08:40:41,883 [main] ERROR org.springframework.web.context.ContextLoader - Context initialization failed
jakarta.ws.rs.WebApplicationException: 
    at dev.dsf.fhir.client.FhirWebserviceClientJersey.handleError(FhirWebserviceClientJersey.java:102) ~[dsf-fhir-webservice-client-1.2.0.jar:1.2.0]
    at dev.dsf.fhir.client.FhirWebserviceClientJersey.searchWithStrictHandling(FhirWebserviceClientJersey.java:687) ~[dsf-fhir-webservice-client-1.2.0.jar:1.2.0]
    at dev.dsf.fhir.client.BasicFhirWebserviceCientWithRetryImpl.lambda$searchWithStrictHandling$7(BasicFhirWebserviceCientWithRetryImpl.java:70) ~[dsf-fhir-webservice-client-1.2.0.jar:1.2.0]
    at dev.dsf.fhir.client.AbstractFhirWebserviceClientJerseyWithRetry.retry(AbstractFhirWebserviceClientJerseyWithRetry.java:43) ~[dsf-fhir-webservice-client-1.2.0.jar:1.2.0]
    at dev.dsf.fhir.client.BasicFhirWebserviceCientWithRetryImpl.searchWithStrictHandling(BasicFhirWebserviceCientWithRetryImpl.java:70) ~[dsf-fhir-webservice-client-1.2.0.jar:1.2.0]
    at dev.dsf.bpe.plugin.ProcessPluginManagerImpl.getLocalOrganizationIdentifierValue(ProcessPluginManagerImpl.java:118) ~[dsf-bpe-server-1.2.0.jar:1.2.0]
    at dev.dsf.bpe.plugin.ProcessPluginManagerImpl.loadAndDeployPlugins(ProcessPluginManagerImpl.java:83) ~[dsf-bpe-server-1.2.0.jar:1.2.0]
    at dev.dsf.bpe.spring.config.PostStartupConfig.onContextRefreshedEvent(PostStartupConfig.java:28) ~[dsf-bpe-server-1.2.0.jar:1.2.0]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
    at org.springframework.context.event.ApplicationListenerMethodAdapter.doInvoke(ApplicationListenerMethodAdapter.java:348) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.event.ApplicationListenerMethodAdapter.processEvent(ApplicationListenerMethodAdapter.java:233) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.event.ApplicationListenerMethodAdapter.onApplicationEvent(ApplicationListenerMethodAdapter.java:165) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:437) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:370) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:961) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:611) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:394) ~[spring-web-6.0.11.jar:6.0.11]
    at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:274) [spring-web-6.0.11.jar:6.0.11]
    at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:102) [spring-web-6.0.11.jar:6.0.11]
    at org.eclipse.jetty.server.handler.ContextHandler.callContextInitialized(ContextHandler.java:1046) [jetty-server-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.servlet.ServletContextHandler.callContextInitialized(ServletContextHandler.java:624) [jetty-servlet-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.server.handler.ContextHandler.contextInitialized(ContextHandler.java:983) [jetty-server-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.servlet.ServletHandler.initialize(ServletHandler.java:740) [jetty-servlet-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:392) [jetty-servlet-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1305) [jetty-webapp-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:902) [jetty-server-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.servlet.ServletContextHandler.doStart(ServletContextHandler.java:306) [jetty-servlet-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:533) [jetty-webapp-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) [jetty-util-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171) [jetty-util-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.server.Server.start(Server.java:470) [jetty-server-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114) [jetty-util-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89) [jetty-server-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.server.Server.doStart(Server.java:415) [jetty-server-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) [jetty-util-11.0.16.jar:11.0.16]
    at dev.dsf.common.jetty.JettyServer.start(JettyServer.java:231) [dsf-common-jetty-1.2.0.jar:1.2.0]
    at dev.dsf.bpe.BpeJettyServer.main(BpeJettyServer.java:35) [dsf_bpe.jar:1.2.0]
2023-09-29 08:40:41,887 [main] WARN  org.eclipse.jetty.webapp.WebAppContext - Failed startup of context o.e.j.w.WebAppContext@3bc57af4{/bpe,null,UNAVAILABLE}
jakarta.ws.rs.WebApplicationException: 
    at dev.dsf.fhir.client.FhirWebserviceClientJersey.handleError(FhirWebserviceClientJersey.java:102) ~[dsf-fhir-webservice-client-1.2.0.jar:1.2.0]
    at dev.dsf.fhir.client.FhirWebserviceClientJersey.searchWithStrictHandling(FhirWebserviceClientJersey.java:687) ~[dsf-fhir-webservice-client-1.2.0.jar:1.2.0]
    at dev.dsf.fhir.client.BasicFhirWebserviceCientWithRetryImpl.lambda$searchWithStrictHandling$7(BasicFhirWebserviceCientWithRetryImpl.java:70) ~[dsf-fhir-webservice-client-1.2.0.jar:1.2.0]
    at dev.dsf.fhir.client.AbstractFhirWebserviceClientJerseyWithRetry.retry(AbstractFhirWebserviceClientJerseyWithRetry.java:43) ~[dsf-fhir-webservice-client-1.2.0.jar:1.2.0]
    at dev.dsf.fhir.client.BasicFhirWebserviceCientWithRetryImpl.searchWithStrictHandling(BasicFhirWebserviceCientWithRetryImpl.java:70) ~[dsf-fhir-webservice-client-1.2.0.jar:1.2.0]
    at dev.dsf.bpe.plugin.ProcessPluginManagerImpl.getLocalOrganizationIdentifierValue(ProcessPluginManagerImpl.java:118) ~[dsf-bpe-server-1.2.0.jar:1.2.0]
    at dev.dsf.bpe.plugin.ProcessPluginManagerImpl.loadAndDeployPlugins(ProcessPluginManagerImpl.java:83) ~[dsf-bpe-server-1.2.0.jar:1.2.0]
    at dev.dsf.bpe.spring.config.PostStartupConfig.onContextRefreshedEvent(PostStartupConfig.java:28) ~[dsf-bpe-server-1.2.0.jar:1.2.0]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
    at org.springframework.context.event.ApplicationListenerMethodAdapter.doInvoke(ApplicationListenerMethodAdapter.java:348) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.event.ApplicationListenerMethodAdapter.processEvent(ApplicationListenerMethodAdapter.java:233) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.event.ApplicationListenerMethodAdapter.onApplicationEvent(ApplicationListenerMethodAdapter.java:165) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:437) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:370) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:961) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:611) ~[spring-context-6.0.11.jar:6.0.11]
    at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:394) ~[spring-web-6.0.11.jar:6.0.11]
    at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:274) ~[spring-web-6.0.11.jar:6.0.11]
    at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:102) ~[spring-web-6.0.11.jar:6.0.11]
    at org.eclipse.jetty.server.handler.ContextHandler.callContextInitialized(ContextHandler.java:1046) ~[jetty-server-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.servlet.ServletContextHandler.callContextInitialized(ServletContextHandler.java:624) ~[jetty-servlet-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.server.handler.ContextHandler.contextInitialized(ContextHandler.java:983) ~[jetty-server-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.servlet.ServletHandler.initialize(ServletHandler.java:740) ~[jetty-servlet-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:392) ~[jetty-servlet-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1305) ~[jetty-webapp-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:902) ~[jetty-server-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.servlet.ServletContextHandler.doStart(ServletContextHandler.java:306) ~[jetty-servlet-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:533) [jetty-webapp-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) [jetty-util-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171) [jetty-util-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.server.Server.start(Server.java:470) [jetty-server-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114) [jetty-util-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89) [jetty-server-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.server.Server.doStart(Server.java:415) [jetty-server-11.0.16.jar:11.0.16]
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93) [jetty-util-11.0.16.jar:11.0.16]
    at dev.dsf.common.jetty.JettyServer.start(JettyServer.java:231) [dsf-common-jetty-1.2.0.jar:1.2.0]
    at dev.dsf.bpe.BpeJettyServer.main(BpeJettyServer.java:35) [dsf_bpe.jar:1.2.0]
2023-09-29 08:40:41,889 [main] INFO  dev.dsf.common.jetty.JettyServer - Stopping jetty server ...
2023-09-29 08:40:41,889 [main] INFO  org.eclipse.jetty.server.Server - Stopped Server@18ff1520{STOPPING}[11.0.16,sto=0]
2023-09-29 08:40:41,892 [main] INFO  org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.w.WebAppContext@3bc57af4{/bpe,null,STOPPED}
2023-09-29 08:40:41,894 [Thread-0] INFO  dev.dsf.common.jetty.JettyServer - Stopping jetty server ...

Log FHIR:

2023-09-29 08:49:46,629 [main] INFO  dev.dsf.tools.db.DbMigrator - Executing DB migration ...
2023-09-29 08:49:47,910 [main] DEBUG dev.dsf.tools.db.DbMigrator - UPDATE SUMMARY
2023-09-29 08:49:47,910 [main] DEBUG dev.dsf.tools.db.DbMigrator - Run:                          0
2023-09-29 08:49:47,911 [main] DEBUG dev.dsf.tools.db.DbMigrator - Previously run:              82
2023-09-29 08:49:47,911 [main] DEBUG dev.dsf.tools.db.DbMigrator - Filtered out:                 0
2023-09-29 08:49:47,911 [main] DEBUG dev.dsf.tools.db.DbMigrator - -------------------------------
2023-09-29 08:49:47,911 [main] DEBUG dev.dsf.tools.db.DbMigrator - Total change sets:           82
2023-09-29 08:49:47,911 [main] INFO  dev.dsf.tools.db.DbMigrator - Executing DB migration [Done]
2023-09-29 08:49:48,160 [main] DEBUG dev.dsf.common.jetty.JettyServer - Java classpath: [lib/jakarta.activation-api-2.1.2.jar, lib/unbescape-1.1.6.RELEASE.jar, lib/spring-beans-6.0.11.jar, lib/gson-2.10.1.jar, lib/log4j-api-2.20.0.jar, lib/spring-aop-6.0.11.jar, lib/dsf-common-status-1.2.0.jar, lib/caffeine-2.7.0.jar, lib/jetty-plus-11.0.16.jar, lib/httpclient-4.5.14.jar, lib/jakarta.activation-1.2.1.jar, lib/asm-9.5.jar, lib/dsf-fhir-validation-1.2.0.jar, lib/commons-codec-1.16.0.jar, lib/snakeyaml-2.2.jar, lib/spring-jcl-6.0.11.jar, lib/txw2-4.0.3.jar, lib/bcprov-jdk18on-1.76.jar, lib/jersey-container-servlet-3.1.3.jar, lib/jetty-jakarta-servlet-api-5.0.2.jar, lib/jakarta.inject-api-2.0.1.jar, lib/spring-context-6.0.11.jar, lib/xpp3-1.1.4c.jar, lib/jersey-media-json-jackson-3.1.3.jar, lib/javassist-3.29.2-GA.jar, lib/commons-text-1.10.0.jar, lib/jersey-container-servlet-core-3.1.3.jar, lib/websocket-core-common-11.0.16.jar, lib/jetty-io-11.0.16.jar, lib/websocket-jakarta-server-11.0.16.jar, lib/org.hl7.fhir.convertors-5.1.0.jar, lib/dsf-common-config-1.2.0.jar, lib/xpp3_xpath-1.1.4c.jar, lib/commons-pool2-2.11.1.jar, lib/liquibase-core-4.23.1.jar, lib/spring-core-6.0.11.jar, lib/osgi-resource-locator-1.0.3.jar, lib/jetty-alpn-client-11.0.16.jar, lib/org.hl7.fhir.dstu2016may-5.1.0.jar, lib/spring-web-6.0.11.jar, lib/log4j-core-2.20.0.jar, lib/checker-qual-3.31.0.jar, lib/dsf-fhir-rest-adapter-1.2.0.jar, lib/jetty-http-11.0.16.jar, lib/opencsv-5.7.1.jar, lib/org.hl7.fhir.validation-5.1.0.jar, lib/jetty-server-11.0.16.jar, lib/jetty-openid-11.0.16.jar, lib/jetty-util-ajax-11.0.16.jar, lib/error_prone_annotations-2.3.3.jar, lib/crypto-utils-3.8.0.jar, lib/postgresql-42.6.0.jar, lib/jaxb-core-4.0.3.jar, lib/jakarta.annotation-api-2.1.1.jar, lib/micrometer-observation-1.10.9.jar, lib/commons-logging-1.2.jar, lib/dsf-fhir-webservice-client-1.2.0.jar, lib/javax.activation-api-1.2.0.jar, lib/jersey-media-jaxb-3.1.3.jar, lib/websocket-core-server-11.0.16.jar, lib/dsf-fhir-auth-1.2.0.jar, lib/org.hl7.fhir.r5-5.1.0.jar, lib/org.hl7.fhir.dstu3-5.1.0.jar, lib/jersey-entity-filtering-3.1.3.jar, lib/org.hl7.fhir.dstu2-5.1.0.jar, lib/jackson-databind-2.15.2.jar, lib/dsf-tools-build-info-reader-1.2.0.jar, lib/ognl-3.3.4.jar, lib/attoparser-2.0.7.RELEASE.jar, lib/asm-tree-9.5.jar, lib/jul-to-slf4j-2.0.9.jar, lib/ucum-1.0.2.jar, lib/jersey-server-3.1.3.jar, lib/jakarta.transaction-api-1.3.1.jar, lib/hapi-fhir-structures-r5-5.1.0.jar, lib/Saxon-HE-9.5.1-5.jar, lib/commons-dbcp2-2.10.0.jar, lib/jakarta.xml.bind-api-4.0.0.jar, lib/jackson-annotations-2.15.2.jar, lib/dsf-tools-db-migration-1.2.0.jar, lib/micrometer-commons-1.10.9.jar, lib/dsf-tools-docker-secrets-reader-1.2.0.jar, lib/org.hl7.fhir.utilities-5.1.0.jar, lib/jetty-client-11.0.16.jar, lib/websocket-servlet-11.0.16.jar, lib/websocket-jakarta-client-11.0.16.jar, lib/jsr305-3.0.2.jar, lib/thymeleaf-3.1.2.RELEASE.jar, lib/hk2-utils-3.0.4.jar, lib/org.hl7.fhir.r4-5.1.0.jar, lib/jakarta.servlet-api-6.0.0.jar, lib/bcutil-jdk18on-1.76.jar, lib/spring-expression-6.0.11.jar, lib/websocket-jakarta-common-11.0.16.jar, lib/bcpkix-jdk18on-1.76.jar, lib/spring-websocket-6.0.11.jar, lib/jersey-apache-connector-3.1.3.jar, lib/hapi-fhir-base-5.1.0.jar, lib/jakarta.ws.rs-api-3.1.0.jar, lib/jetty-annotations-11.0.16.jar, lib/listenablefuture-9999.0-empty-to-avoid-conflict-with-guava.jar, lib/jetty-util-11.0.16.jar, lib/hapi-fhir-structures-r4-5.1.0.jar, lib/guava-32.1.2-jre.jar, lib/jackson-core-2.15.2.jar, lib/hk2-api-3.0.4.jar, lib/dsf-common-jetty-1.2.0.jar, lib/aopalliance-repackaged-3.0.4.jar, lib/websocket-core-client-11.0.16.jar, lib/jersey-common-3.1.3.jar, lib/jetty-xml-11.0.16.jar, lib/jetty-jndi-11.0.16.jar, lib/hk2-locator-3.0.4.jar, lib/hapi-fhir-validation-5.1.0.jar, lib/jcl-over-slf4j-2.0.9.jar, lib/commons-io-2.13.0.jar, lib/jackson-module-jakarta-xmlbind-annotations-2.14.1.jar, lib/jakarta.validation-api-3.0.2.jar, lib/java-jwt-4.4.0.jar, lib/jersey-hk2-3.1.3.jar, lib/istack-commons-runtime-4.1.2.jar, lib/hapi-fhir-validation-resources-r4-5.1.0.jar, lib/jakarta.mail-1.6.7.jar, lib/jetty-security-11.0.16.jar, lib/jetty-servlet-11.0.16.jar, lib/commons-compress-1.24.0.jar, lib/jersey-client-3.1.3.jar, lib/jakarta.websocket-api-2.1.1.jar, lib/log4j-slf4j2-impl-2.20.0.jar, lib/dsf-common-documentation-1.2.0.jar, lib/commons-collections4-4.4.jar, lib/asm-commons-9.5.jar, lib/jakarta.websocket-client-api-2.1.1.jar, lib/dsf-fhir-server-1.2.0.jar, lib/hapi-fhir-validation-resources-r5-5.1.0.jar, lib/commons-lang3-3.12.0.jar, lib/j2objc-annotations-2.8.jar, lib/jaxb-api-2.3.1.jar, lib/jetty-webapp-11.0.16.jar, lib/dsf-common-auth-1.2.0.jar, lib/slf4j-api-2.0.9.jar, lib/httpcore-4.4.16.jar, lib/failureaccess-1.0.1.jar, lib/hapi-fhir-converter-5.1.0.jar, lib/jaxb-runtime-4.0.3.jar, dsf_fhir.jar]
2023-09-29 08:49:48,160 [main] DEBUG dev.dsf.common.jetty.JettyServer - Resources for jetty: [file:///opt/fhir/lib/dsf-fhir-server-1.2.0.jar]
2023-09-29 08:49:48,161 [main] DEBUG dev.dsf.common.jetty.JettyServer - Init parameters: {}
2023-09-29 08:49:48,172 [main] INFO  dev.dsf.common.config.AbstractJettyConfig - OIDC authorization code flow enabled
2023-09-29 08:49:48,173 [main] INFO  dev.dsf.common.config.AbstractJettyConfig - OIDC bearer token enabled
2023-09-29 08:49:48,178 [main] INFO  dev.dsf.common.auth.ClientCertificateAuthenticator - Using [CN=Root CA, O=Root CA] to validate client certificates
2023-09-29 08:49:48,181 [main] INFO  dev.dsf.common.jetty.JettyServer - Starting jetty server ...
2023-09-29 08:49:48,181 [main] INFO  org.eclipse.jetty.server.Server - jetty-11.0.16; built: 2023-08-25T19:43:30.438Z; git: bedff458c4dd1a716d59e17b8cb0d2042eeab291; jvm 17.0.8+7-LTS
2023-09-29 08:49:48,280 [main] INFO  org.eclipse.jetty.server.handler.ContextHandler.fhir - 1 Spring WebApplicationInitializers detected on classpath
2023-09-29 08:49:48,329 [main] INFO  org.eclipse.jetty.server.session.DefaultSessionIdManager - Session workerName=node0
2023-09-29 08:49:48,468 [main] INFO  org.eclipse.jetty.server.handler.ContextHandler.fhir - Initializing Spring root WebApplicationContext
2023-09-29 08:49:48,686 [main] INFO  dev.dsf.common.config.ProxyConfigImpl - Forward proxy config: {url: null, username: null, password: null, no-proxy: []}
2023-09-29 08:49:48,686 [main] INFO  dev.dsf.fhir.spring.config.ClientConfig - Remote webservice client config: {trustStorePath: /run/secrets/app_client_trust_certificates.pem, certificatePath: /run/secrets/app_client_certificate.pem, privateKeyPath: /run/secrets/app_client_certificate_private_key.pem, privateKeyPassword: null, proxy: disabled, no_proxy: []}
2023-09-29 08:49:48,794 [main] INFO  dev.dsf.fhir.spring.config.AuthenticationConfig - Role config: {[name=admin, thumbprints=[], emails=[...], tokenRoles=[], tokenGroups=[], dsfRoles=[READ, SEARCH, HISTORY, CREATE, WEBSOCKET, DELETE], practitionerRoles=[]]}
[...]
2023-09-29 08:49:52,570 [main] INFO  dsf-audit-logger - Create of CodeSystem for identity 'initial.data.loader' via bundle at index 0 successful, status: 200 OK
[...]
2023-09-29 08:49:52,578 [main] INFO  dev.dsf.fhir.service.InitialDataLoaderImpl - https://localhost/fhir/CodeSystem/cb67e856-0c65-4871-8e6e-11895e7369e8/_history/1 200 OK
[...]
2023-09-29 08:49:52,587 [main] INFO  dev.dsf.fhir.spring.config.InitialDataLoaderConfig - Loading data from external bundle ...
2023-09-29 08:49:52,593 [main] DEBUG dev.dsf.fhir.service.InitialDataLoaderImpl - Executing command list for bundle with 2 entries
2023-09-29 08:49:53,653 [main] DEBUG dev.dsf.fhir.dao.command.TransactionCommandList - Running pre-execute of command dev.dsf.fhir.dao.command.UpdateCommand for entry at index 0
2023-09-29 08:49:53,656 [main] DEBUG dev.dsf.fhir.dao.command.TransactionCommandList - Running pre-execute of command dev.dsf.fhir.dao.command.UpdateCommand for entry at index 1
2023-09-29 08:49:53,657 [main] DEBUG dev.dsf.fhir.dao.command.TransactionCommandList - Running pre-execute of command dev.dsf.fhir.dao.command.CheckReferencesCommand for entry at index 0
2023-09-29 08:49:53,657 [main] DEBUG dev.dsf.fhir.dao.command.TransactionCommandList - Running pre-execute of command dev.dsf.fhir.dao.command.CheckReferencesCommand for entry at index 1
2023-09-29 08:49:53,657 [main] DEBUG dev.dsf.fhir.dao.command.TransactionCommandList - Running execute of command dev.dsf.fhir.dao.command.UpdateCommand for entry at index 0
2023-09-29 08:49:53,660 [main] DEBUG dev.dsf.fhir.dao.jdbc.AbstractResourceDaoJdbc - Organization with IdPart d330c0a6-dd6f-4687-afbf-3d745bf4d42d found
2023-09-29 08:49:54,163 [main] INFO  dev.dsf.fhir.authorization.AbstractMetaTagAuthorizationRule - Update of Organization/d330c0a6-dd6f-4687-afbf-3d745bf4d42d/_history/3 authorized for identity 'initial.data.loader'
2023-09-29 08:49:54,165 [main] INFO  dsf-audit-logger - Update of Organization/d330c0a6-dd6f-4687-afbf-3d745bf4d42d/_history/3 allowed for identity 'initial.data.loader' via bundle at index 0, reason: Identity is local identity and has role UPDATE
2023-09-29 08:49:54,166 [main] DEBUG dev.dsf.fhir.dao.jdbc.AbstractResourceDaoJdbc - Latest version for Organization with IdPart d330c0a6-dd6f-4687-afbf-3d745bf4d42d is 3
2023-09-29 08:49:54,185 [main] DEBUG dev.dsf.fhir.dao.jdbc.AbstractResourceDaoJdbc - Organization with IdPart d330c0a6-dd6f-4687-afbf-3d745bf4d42d updated, new version 4
2023-09-29 08:49:54,185 [main] DEBUG dev.dsf.fhir.dao.command.TransactionCommandList - Running execute of command dev.dsf.fhir.dao.command.UpdateCommand for entry at index 1
2023-09-29 08:49:54,187 [main] DEBUG dev.dsf.fhir.dao.jdbc.AbstractResourceDaoJdbc - Endpoint with IdPart adc6d35d-ef67-4512-ad92-eee515f2d7dd found
2023-09-29 08:49:54,320 [main] INFO  dev.dsf.fhir.authorization.AbstractMetaTagAuthorizationRule - Update of Endpoint/adc6d35d-ef67-4512-ad92-eee515f2d7dd/_history/3 authorized for identity 'initial.data.loader'
2023-09-29 08:49:54,320 [main] INFO  dsf-audit-logger - Update of Endpoint/adc6d35d-ef67-4512-ad92-eee515f2d7dd/_history/3 allowed for identity 'initial.data.loader' via bundle at index 1, reason: Identity is local identity and has role UPDATE
2023-09-29 08:49:54,332 [main] DEBUG dev.dsf.fhir.dao.jdbc.AbstractResourceDaoJdbc - Latest version for Endpoint with IdPart adc6d35d-ef67-4512-ad92-eee515f2d7dd is 3
2023-09-29 08:49:54,334 [main] DEBUG dev.dsf.fhir.dao.jdbc.AbstractResourceDaoJdbc - Endpoint with IdPart adc6d35d-ef67-4512-ad92-eee515f2d7dd updated, new version 4
2023-09-29 08:49:54,334 [main] DEBUG dev.dsf.fhir.dao.command.TransactionCommandList - Running execute of command dev.dsf.fhir.dao.command.CheckReferencesCommand for entry at index 0
2023-09-29 08:49:54,335 [main] DEBUG dev.dsf.fhir.dao.command.TransactionCommandList - Running execute of command dev.dsf.fhir.dao.command.CheckReferencesCommand for entry at index 1
2023-09-29 08:49:54,335 [main] DEBUG dev.dsf.fhir.dao.command.TransactionCommandList - Running post-execute of command dev.dsf.fhir.dao.command.UpdateCommand for entry at index 0
2023-09-29 08:49:54,336 [main] DEBUG dev.dsf.fhir.dao.jdbc.AbstractResourceDaoJdbc - Organization with IdPart d330c0a6-dd6f-4687-afbf-3d745bf4d42d found
2023-09-29 08:49:54,337 [main] DEBUG dev.dsf.fhir.dao.command.TransactionCommandList - Running post-execute of command dev.dsf.fhir.dao.command.UpdateCommand for entry at index 1
2023-09-29 08:49:54,337 [main] DEBUG dev.dsf.fhir.dao.jdbc.AbstractResourceDaoJdbc - Endpoint with IdPart adc6d35d-ef67-4512-ad92-eee515f2d7dd found
2023-09-29 08:49:54,338 [main] DEBUG dev.dsf.fhir.dao.command.TransactionCommandList - Running post-execute of command dev.dsf.fhir.dao.command.CheckReferencesCommand for entry at index 0
2023-09-29 08:49:54,338 [main] DEBUG dev.dsf.fhir.dao.command.TransactionCommandList - Running post-execute of command dev.dsf.fhir.dao.command.CheckReferencesCommand for entry at index 1
2023-09-29 08:49:54,338 [main] DEBUG dev.dsf.fhir.dao.command.TransactionCommandList - Committing DB transaction
2023-09-29 08:49:54,338 [main] DEBUG dev.dsf.fhir.dao.command.TransactionCommandList - Committing events
2023-09-29 08:49:54,339 [main] INFO  dsf-audit-logger - Update of Organization for identity 'initial.data.loader' via bundle at index 0 successful, status: 200 OK
2023-09-29 08:49:54,339 [pool-2-thread-1] INFO  dev.dsf.fhir.subscription.WebSocketSubscriptionManagerImpl - Refreshing subscriptions
2023-09-29 08:49:54,339 [main] INFO  dsf-audit-logger - Update of Endpoint for identity 'initial.data.loader' via bundle at index 1 successful, status: 200 OK
2023-09-29 08:49:54,339 [main] INFO  dev.dsf.fhir.service.InitialDataLoaderImpl - https://localhost/fhir/Organization/d330c0a6-dd6f-4687-afbf-3d745bf4d42d/_history/4 200 OK
2023-09-29 08:49:54,339 [main] INFO  dev.dsf.fhir.service.InitialDataLoaderImpl - https://localhost/fhir/Endpoint/adc6d35d-ef67-4512-ad92-eee515f2d7dd/_history/4 200 OK
2023-09-29 08:49:54,339 [main] INFO  dev.dsf.fhir.service.InitialDataMigratorImpl - Executing initial data migration jobs ...
2023-09-29 08:49:54,339 [main] INFO  dev.dsf.fhir.service.InitialDataMigratorImpl - Executing initial data migration jobs [Done]
2023-09-29 08:49:54,340 [main] INFO  dev.dsf.tools.build.BuildInfoReaderImpl - System default timezone: Europe/Berlin
2023-09-29 08:49:54,341 [pool-2-thread-1] DEBUG dev.dsf.fhir.subscription.WebSocketSubscriptionManagerImpl - Current active subscription-ids (after refreshing): [940d1a10-de20-483d-88b0-303dd5fffc9e, 77e02944-d425-46e8-8025-32136ce62429]
2023-09-29 08:49:54,342 [pool-2-thread-1] DEBUG dev.dsf.fhir.subscription.WebSocketSubscriptionManagerImpl - handling event ResourceUpdatedEvent for resource of type Organization with id d330c0a6-dd6f-4687-afbf-3d745bf4d42d
2023-09-29 08:49:54,342 [pool-2-thread-1] DEBUG dev.dsf.fhir.subscription.WebSocketSubscriptionManagerImpl - No subscriptions for event ResourceUpdatedEvent for resource of type Organization with id d330c0a6-dd6f-4687-afbf-3d745bf4d42d
2023-09-29 08:49:54,342 [pool-2-thread-1] DEBUG dev.dsf.fhir.subscription.WebSocketSubscriptionManagerImpl - handling event ResourceUpdatedEvent for resource of type Endpoint with id adc6d35d-ef67-4512-ad92-eee515f2d7dd
2023-09-29 08:49:54,342 [pool-2-thread-1] DEBUG dev.dsf.fhir.subscription.WebSocketSubscriptionManagerImpl - No subscriptions for event ResourceUpdatedEvent for resource of type Endpoint with id adc6d35d-ef67-4512-ad92-eee515f2d7dd
2023-09-29 08:49:54,342 [main] INFO  dev.dsf.tools.build.BuildInfoReaderImpl - Artifact: dsf-fhir-server-jetty, version: 1.2.0, build: 2023-09-12T23:06:47+02:00, branch: main, commit: 5694d7d764779890202623cd0012ee494a28dbc3
2023-09-29 08:49:54,427 [main] DEBUG dev.dsf.fhir.FhirJerseyApplication - Registering bean 'activityDefinitionService' as singleton resource with path '/fhir/ActivityDefinition'
[...]
2023-09-29 08:49:54,889 [main] INFO  org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.w.WebAppContext@26e185e2{/fhir,null,AVAILABLE}
2023-09-29 08:49:54,889 [main] INFO  org.eclipse.jetty.webapp.WebAppContext - WebApp@1289587756 at http://ServerConnector@22ac51f4{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}/fhir
2023-09-29 08:49:54,889 [main] INFO  org.eclipse.jetty.webapp.WebAppContext - WebApp@1289587756 at http://ServerConnector@19ff9bdf{HTTP/1.1, (http/1.1)}{127.0.0.1:10000}/fhir
2023-09-29 08:49:54,891 [main] INFO  org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@22ac51f4{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2023-09-29 08:49:54,892 [main] INFO  org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@19ff9bdf{HTTP/1.1, (http/1.1)}{127.0.0.1:10000}
2023-09-29 08:49:54,893 [main] INFO  org.eclipse.jetty.server.Server - Started Server@4f18356b{STARTING}[11.0.16,sto=0] @9177ms
2023-09-29 08:50:09,617 [jetty-server-22] WARN  dev.dsf.common.jetty.ForwardedSecureRequestCustomizer - X-ClientCert header does not start with -----BEGIN CERTIFICATE----- or -----BEGIN%20CERTIFICATE-----%0A
2023-09-29 08:50:14,801 [jetty-server-23] WARN  dev.dsf.common.jetty.ForwardedSecureRequestCustomizer - X-ClientCert header does not start with -----BEGIN CERTIFICATE----- or -----BEGIN%20CERTIFICATE-----%0A
2023-09-29 08:50:19,950 [jetty-server-24] WARN  dev.dsf.common.jetty.ForwardedSecureRequestCustomizer - X-ClientCert header does not start with -----BEGIN CERTIFICATE----- or -----BEGIN%20CERTIFICATE-----%0A
2023-09-29 08:50:25,196 [jetty-server-41] WARN  dev.dsf.common.jetty.ForwardedSecureRequestCustomizer - X-ClientCert header does not start with -----BEGIN CERTIFICATE----- or -----BEGIN%20CERTIFICATE-----%0A

(Please ignore the time stamps)

A look at the code would suggest that the client certificate is never sent by the BPE.

If I unset SSL_VERIFY_CLIENT, the BPE throws a broken pipe exception instead of a jakarta.ws.rs.WebApplicationException.

Any help in resolving this would be appreciated! Thanks!

hhund commented 1 year ago

Hi @t4deon,

when I set SSL_VERIFY_CLIENT: optional in the dsf-docker-test-setup it still works and the BPE authenticates using the client certificate.

Generally speaking a client certificate is only send during the TLS handshake, if the servers send a request for client certificates with it's "Server Hello" message and the client has a client certificate that matches one of the "Acceptable client certificate CA names". If you want to see if proxy is sending the correct hello message, try openssl s_client --connect proxy::443 and check if the issuer of your client certificate matches on of the CAs listed as Acceptable client certificate CA names. The SSL_CA_DN_REQUEST_FILE variable determines what CA-Names are send, but if it is not set, all entries from SSL_CA_CERTIFICATE_FILE are used.

Make sure that your BPE is talking to reverse proxy and not the FHIR app server directly.

Not necessarily an error, but usually the FHIR and BPE environment variables DEV_DSF_FHIR_SERVER_BASE_URL and DEV_DSF_BPE_FHIR_SERVER_BASE_URL have the same value.

In case you don't want to further debug you're own setup, have a look at our single organization test setup at dsf-docker-test-setup. To use the setup:

  1. Clone the main branch
  2. Build the DSF so all FHIR bundle and certificates are generated: mvn install -DskipTests To use the DSF FHIR server web UI a client certificate is generated at dsf-tools\dsf-tools-test-data-generator\cert\Webbrowser_Test_User\Webbrowser_Test_User_certificate.p12
  3. Build local docker images with dsf-docker-test-setup\docker-build.sh (or modify the compose files to use the images from ghcr.io)
  4. Add 127.0.0.1 fhir to your OS hosts file, to access the FHIR server via a web browser.
  5. Start the DSF FHIR server at dsf-docker-test-setup/fhir via docker compose up
  6. Start the DSF BPE server at dsf-docker-test-setup/bpe via docker compose up

If you need a test setup with OIDC enabled, have a look at dsf-docker-test-setup-3dic-ttp. This setup simulates four organisations but they can be started individually if you only need one.

t4deon commented 1 year ago

Hi @hhund,

thanks for the explanations. The problem was an improperly closed certificate chain. Now it works!