Feature/issue 1971 correlation id logging

config/packages/ci/monolog.yaml

@@ -0,0 +1,10 @@
+monolog:
+    handlers:
+        test_log_handler:
+            type: service
+            id: OpenConext\EngineBlockFunctionalTestingBundle\Log\TestLogHandler
+        test_log_file:
+            type: stream
+            path: '/tmp/eb-fixtures/log-records.ndjson'
+            level: debug
+            formatter: monolog.formatter.json

config/packages/test/monolog.yaml

@@ -12,3 +12,4 @@ monolog:
             type:   stream
             path:   "%kernel.logs_dir%/%kernel.environment%.log"
             level:  DEBUG
+

config/services/ci/services.yml

@@ -154,3 +154,6 @@ services:
         arguments:
             - "@request_stack"
             - "%global.site_notice.allowed.tags%"
+
+    OpenConext\EngineBlockFunctionalTestingBundle\Log\TestLogHandler:
+        public: true

config/services/compat.yml

@@ -59,3 +59,9 @@ services:
     engineblock.compat.attribute_release_policy_enforcer:
         public: false
         class: EngineBlock_Arp_AttributeReleasePolicyEnforcer
+
+    EngineBlock_Saml2_AuthnRequestSessionRepository:
+        class: EngineBlock_Saml2_AuthnRequestSessionRepository
+        public: true
+        arguments:
+            - '@request_stack'

config/services/logging.yml

@@ -30,6 +30,12 @@ services:
         tags:
             - { name: monolog.processor }
 
+    OpenConext\EngineBlock\Logger\Processor\CorrelationIdProcessor:
+        arguments:
+            - '@OpenConext\EngineBlock\Request\CurrentCorrelationId'
+        tags:
+            - { name: monolog.processor }
+
     OpenConext\EngineBlock\Logger\Processor\SessionIdProcessor:
         tags:
             - { name: monolog.processor }

config/services/services.yml

@@ -68,6 +68,20 @@ services:
             - '@OpenConext\EngineBlock\Request\UniqidGenerator'
         public: true
 
+    OpenConext\EngineBlock\Request\CurrentCorrelationId:
+        public: true
+
+    OpenConext\EngineBlock\Request\CorrelationIdRepository:
+        public: true
+        arguments:
+            - '@request_stack'
+
+    OpenConext\EngineBlock\Request\CorrelationIdService:
+        public: true
+        arguments:
+            - '@OpenConext\EngineBlock\Request\CorrelationIdRepository'
+            - '@OpenConext\EngineBlock\Request\CurrentCorrelationId'
+
     OpenConext\EngineBlockBundle\Security\Http\EntryPoint\JsonBasicAuthenticationEntryPoint:
         arguments:
             - 'engine-api.%domain%'

config/services_ci.yaml

@@ -68,6 +68,11 @@ services:
     OpenConext\EngineBlockFunctionalTestingBundle\Features\Context\MinkContext:
         tags: ['fob.context']
 
+    OpenConext\EngineBlockFunctionalTestingBundle\Features\Context\LoggingContext:
+        arguments:
+            $logFile: '/tmp/eb-fixtures/log-records.ndjson'
+        tags: ['fob.context']
+
     OpenConext\EngineBlockFunctionalTestingBundle\Fixtures\SbsClientStateManager:
         arguments:
             - "@engineblock.functional_testing.data_store.sbs_client_state_mananger"

languages/messages.en.php

@@ -49,6 +49,7 @@
 
         // Feedback
     'requestId'             => 'UR ID',
+    'correlationId'         => 'CID',
     'identityProvider'      => 'IdP',
     'serviceProvider'       => 'SP',
     'serviceProviderName'   => 'SP Name',

languages/messages.nl.php

@@ -49,6 +49,7 @@
 
      // Feedback
     'requestId'             => 'UR ID',
+    'correlationId'         => 'CID',
     'identityProvider'      => 'IdP',
     'serviceProvider'       => 'SP',
     'serviceProviderName'   => 'SP Name',

library/EngineBlock/Application/DiContainer.php

@@ -613,4 +613,9 @@ public function getNameIdSubstituteResolver()
     {
         return new EngineBlock_Arp_NameIdSubstituteResolver($this->container->get('engineblock.compat.logger'));
     }
+
+    public function getAuthnRequestSessionRepository(): EngineBlock_Saml2_AuthnRequestSessionRepository
+    {
+        return $this->container->get(EngineBlock_Saml2_AuthnRequestSessionRepository::class);
+    }
 }

library/EngineBlock/ApplicationSingleton.php

@@ -269,6 +269,11 @@ public function collectFeedbackInfo(Throwable $exception)
         $feedbackInfo['ipAddress'] = $this->getClientIpAddress();
         $feedbackInfo['artCode'] = Art::forException($exception);
 
+        $currentCorrelationId = $this->getDiContainerRuntime()->currentCorrelationId->correlationId;
+        if ($currentCorrelationId !== null) {
+            $feedbackInfo['correlationId'] = $currentCorrelationId;
+        }
+
         // @todo  reset this when login is succesful
         // Find the current identity provider
         $spEntityId = $_SESSION['originalServiceProvider'] ?? $_SESSION['currentServiceProvider'] ?? null;

library/EngineBlock/Corto/Module/Service/AssertionConsumer.php

@@ -19,6 +19,7 @@
 use OpenConext\EngineBlock\Metadata\Entity\ServiceProvider;
 use OpenConext\EngineBlock\Metadata\Factory\Factory\ServiceProviderFactory;
 use OpenConext\EngineBlock\Metadata\X509\KeyPairFactory;
+use OpenConext\EngineBlock\Request\CorrelationIdServiceInterface;
 use OpenConext\EngineBlock\Service\ProcessingStateHelperInterface;
 use OpenConext\EngineBlock\Stepup\StepupGatewayCallOutHelper;
 use OpenConext\EngineBlockBundle\Authentication\AuthenticationState;
@@ -59,13 +60,19 @@ class EngineBlock_Corto_Module_Service_AssertionConsumer implements EngineBlock_
      */
     private $_serviceProviderFactory;
 
+    /**
+     * @var CorrelationIdServiceInterface
+     */
+    private $_correlationIdService;
+
     public function __construct(
         EngineBlock_Corto_ProxyServer $server,
         EngineBlock_Corto_XmlToArray $xmlConverter,
         Session $session,
         ProcessingStateHelperInterface $processingStateHelper,
         StepupGatewayCallOutHelper $stepupGatewayCallOutHelper,
-        ServiceProviderFactory $serviceProviderFactory
+        ServiceProviderFactory $serviceProviderFactory,
+        CorrelationIdServiceInterface $correlationIdService
     )
     {
         $this->_server = $server;
@@ -74,6 +81,7 @@ public function __construct(
         $this->_processingStateHelper = $processingStateHelper;
         $this->_stepupGatewayCallOutHelper = $stepupGatewayCallOutHelper;
         $this->_serviceProviderFactory = $serviceProviderFactory;
+        $this->_correlationIdService = $correlationIdService;
     }
 
     /**
@@ -89,6 +97,9 @@ public function serve($serviceName, Request $httpRequest)
         $receivedRequest = $this->_server->getReceivedRequestFromResponse($receivedResponse);
 
         $application = EngineBlock_ApplicationSingleton::getInstance();
+
+        $correlationIdService = $this->_correlationIdService;
+        $correlationIdService->resolve($receivedResponse->getInResponseTo());
         $log = $application->getLogInstance();
 
         if(!$receivedRequest instanceof EngineBlock_Saml2_AuthnRequestAnnotationDecorator){

library/EngineBlock/Corto/Module/Service/ContinueToIdp.php

@@ -85,7 +85,8 @@ public function serve($serviceName, Request $httpRequest)
             );
         }
 
-        $authnRequestRepository = new EngineBlock_Saml2_AuthnRequestSessionRepository($this->_server->getLogger());
+
+        $authnRequestRepository =  EngineBlock_ApplicationSingleton::getInstance()->getDiContainer()->getAuthnRequestSessionRepository();
         $request = $authnRequestRepository->findRequestById($id);
 
         if (!$request) {
@@ -94,6 +95,9 @@ public function serve($serviceName, Request $httpRequest)
             );
         }
 
+        $correlationIdService = EngineBlock_ApplicationSingleton::getInstance()->getDiContainerRuntime()->correlationIdService;
+        $correlationIdService->resolve($id);
+
         // Flush log if SP or IdP has additional logging enabled
         if ($request->isDebugRequest()) {
             $sp = $this->getEngineSpRole($this->_server);

library/EngineBlock/Corto/Module/Service/ProcessConsent.php

@@ -17,6 +17,7 @@
  */
 
 use OpenConext\EngineBlock\Authentication\Value\ConsentType;
+use OpenConext\EngineBlock\Request\CorrelationIdServiceInterface;
 use OpenConext\EngineBlock\Service\AuthenticationStateHelperInterface;
 use OpenConext\EngineBlock\Service\ProcessingStateHelperInterface;
 use SAML2\Constants;
@@ -51,26 +52,34 @@ class EngineBlock_Corto_Module_Service_ProcessConsent
      */
     private $_processingStateHelper;
 
+    /**
+     * @var CorrelationIdServiceInterface
+     */
+    private $_correlationIdService;
+
     /**
      * @param EngineBlock_Corto_ProxyServer $server
      * @param EngineBlock_Corto_XmlToArray $xmlConverter
      * @param EngineBlock_Corto_Model_Consent_Factory $consentFactory
      * @param AuthenticationStateHelperInterface $stateHelper
      * @param ProcessingStateHelperInterface $processingStateHelper
+     * @param CorrelationIdServiceInterface $correlationIdService
      */
     public function __construct(
         EngineBlock_Corto_ProxyServer $server,
         EngineBlock_Corto_XmlToArray $xmlConverter,
         EngineBlock_Corto_Model_Consent_Factory $consentFactory,
         AuthenticationStateHelperInterface $stateHelper,
-        ProcessingStateHelperInterface $processingStateHelper
+        ProcessingStateHelperInterface $processingStateHelper,
+        CorrelationIdServiceInterface $correlationIdService
     )
     {
         $this->_server = $server;
         $this->_xmlConverter = $xmlConverter;
         $this->_consentFactory = $consentFactory;
         $this->_authenticationStateHelper = $stateHelper;
         $this->_processingStateHelper = $processingStateHelper;
+        $this->_correlationIdService = $correlationIdService;
     }
 
     /**
@@ -85,6 +94,9 @@ public function serve($serviceName, Request $httpRequest)
         $response = $processStep->getResponse();
 
         $request = $this->_server->getReceivedRequestFromResponse($response);
+
+        $this->_correlationIdService->resolve($request->getId());
+
         $serviceProvider = $this->_server->getRepository()->fetchServiceProviderByEntityId($request->getIssuer()->getValue());
 
         $destinationMetadata = EngineBlock_SamlHelper::getDestinationSpMetadata(

library/EngineBlock/Corto/Module/Service/ProvideConsent.php

@@ -19,6 +19,7 @@
 use OpenConext\EngineBlock\Authentication\Value\ConsentType;
 use OpenConext\EngineBlock\Metadata\Entity\IdentityProvider;
 use OpenConext\EngineBlock\Metadata\Entity\ServiceProvider;
+use OpenConext\EngineBlock\Request\CorrelationIdServiceInterface;
 use OpenConext\EngineBlock\Service\AuthenticationStateHelperInterface;
 use OpenConext\EngineBlock\Service\Consent\ConsentServiceInterface;
 use OpenConext\EngineBlock\Service\ProcessingStateHelperInterface;
@@ -67,6 +68,8 @@ class EngineBlock_Corto_Module_Service_ProvideConsent
 
     private DiscoverySelectionService $discoverySelectionService;
 
+    private CorrelationIdServiceInterface $_correlationIdService;
+
     public function __construct(
         EngineBlock_Corto_ProxyServer $server,
         EngineBlock_Corto_XmlToArray $xmlConverter,
@@ -75,7 +78,8 @@ public function __construct(
         AuthenticationStateHelperInterface $authStateHelper,
         Environment $twig,
         ProcessingStateHelperInterface $processingStateHelper,
-        DiscoverySelectionService $discoverySelectionService
+        DiscoverySelectionService $discoverySelectionService,
+        CorrelationIdServiceInterface $correlationIdService
     )
     {
         $this->_server = $server;
@@ -87,6 +91,7 @@ public function __construct(
         $this->_processingStateHelper = $processingStateHelper;
         $this->logger = EngineBlock_ApplicationSingleton::getLog();
         $this->discoverySelectionService = $discoverySelectionService;
+        $this->_correlationIdService = $correlationIdService;
     }
 
     /**
@@ -100,14 +105,17 @@ public function serve($serviceName, Request $httpRequest)
 
         $receivedRequest = $this->_server->getReceivedRequestFromResponse($response);
 
+        $correlationIdService = $this->_correlationIdService;
+        $correlationIdService->resolve($receivedRequest->getId());
+
         // update previous response with current response
         $this->_processingStateHelper->updateStepResponseByRequestId(
             $receivedRequest->getId(),
             ProcessingStateHelperInterface::STEP_CONSENT,
             $response
         );
 
-        $request = $this->_server->getReceivedRequestFromResponse($response);
+        $request = $receivedRequest;
         $serviceProvider = $this->_server->getRepository()->fetchServiceProviderByEntityId($request->getIssuer()->getValue());
         $spMetadataChain = EngineBlock_SamlHelper::getSpRequesterChain(
             $serviceProvider,

library/EngineBlock/Corto/Module/Service/SingleSignOn.php

@@ -74,6 +74,7 @@ public function __construct(
     public function serve($serviceName, Request $httpRequest)
     {
         $application = EngineBlock_ApplicationSingleton::getInstance();
+        $container = $application->getDiContainer();
 
         $log = $this->_server->getLogger();
 
@@ -203,9 +204,9 @@ public function serve($serviceName, Request $httpRequest)
         // Multiple IdPs found...
 
         // Auto-select IdP when 'feature_enable_sso_notification' is enabled and send AuthenticationRequest on success
-        if ($application->getDiContainer()->getFeatureConfiguration()->isEnabled("eb.enable_sso_notification")) {
-            $idpEntityId = $application->getDiContainer()->getSsoNotificationService()->
-                handleSsoNotification($application->getDiContainer()->getSymfonyRequest()->cookies, $this->_server);
+        if ($container->getFeatureConfiguration()->isEnabled("eb.enable_sso_notification")) {
+            $idpEntityId = $container->getSsoNotificationService()->
+                handleSsoNotification($container->getSymfonyRequest()->cookies, $this->_server);
 
             if (!empty($idpEntityId)) {
                 try {
@@ -221,8 +222,8 @@ public function serve($serviceName, Request $httpRequest)
         }
 
         // Auto-select IdP when 'wayf.rememberChoice' feature is enabled and is allowed for the current request
-        if (($application->getDiContainer()->getRememberChoice() === true) && !($request->getForceAuthn() || $request->isDebugRequest())) {
-            $cookies = $application->getDiContainer()->getSymfonyRequest()->cookies->all();
+        if (($container->getRememberChoice() === true) && !($request->getForceAuthn() || $request->isDebugRequest())) {
+            $cookies = $container->getSymfonyRequest()->cookies->all();
             if (array_key_exists('rememberchoice', $cookies)) {
                 $remembered = json_decode($cookies['rememberchoice']);
                 if (array_search($remembered, $candidateIDPs) !== false) {
@@ -241,9 +242,13 @@ public function serve($serviceName, Request $httpRequest)
             return;
         }
 
-        $authnRequestRepository = new EngineBlock_Saml2_AuthnRequestSessionRepository($log);
+        $authnRequestRepository = $application->getDiContainer()->getAuthnRequestSessionRepository();
         $authnRequestRepository->store($request);
 
+        $correlationIdService = $application->getDiContainerRuntime()->correlationIdService;
+        $correlationIdService->mint($request->getId());
+        $correlationIdService->resolve($request->getId());
+
         // Show WAYF
         $log->info("Multiple candidate IdPs: redirecting to WAYF");
         $this->_showWayf($request, $candidateIDPs);

library/EngineBlock/Corto/Module/Service/SramInterrupt.php

@@ -50,6 +50,8 @@ public function serve($serviceName, Request $httpRequest): void
     {
         $id = $httpRequest->get('ID');
 
+        EngineBlock_ApplicationSingleton::getInstance()->getDiContainerRuntime()->correlationIdService->resolve($id);
+
         $nextProcessStep = $this->_processingStateHelper->getStepByRequestId(
             $id,
             ProcessingStateHelperInterface::STEP_SRAM

library/EngineBlock/Corto/Module/Service/StepupAssertionConsumer.php

@@ -115,6 +115,8 @@ public function serve($serviceName, Request $httpRequest)
             $log->warning('After failed Stepup authentication set LoA to Loa1', ['result' => $mappedLoa]);
         }
 
+        $application->getDiContainerRuntime()->correlationIdService->resolve($receivedRequest->getId());
+
         if ($checkResponseSignature) {
             $this->_server->checkResponseSignatureMethods($receivedResponse);
         }

library/EngineBlock/Corto/Module/Services.php

@@ -87,15 +87,17 @@ private function factoryService($className, EngineBlock_Corto_ProxyServer $serve
                     $diContainer->getAuthenticationStateHelper(),
                     $diContainerRuntime->twig,
                     $diContainer->getProcessingStateHelper(),
-                    $diContainer->getDiscoverySelectionService()
+                    $diContainer->getDiscoverySelectionService(),
+                    $diContainerRuntime->correlationIdService,
                 );
             case EngineBlock_Corto_Module_Service_ProcessConsent::class :
                 return new EngineBlock_Corto_Module_Service_ProcessConsent(
                     $server,
                     $diContainer->getXmlConverter(),
                     $diContainer->getConsentFactory(),
                     $diContainer->getAuthenticationStateHelper(),
-                    $diContainer->getProcessingStateHelper()
+                    $diContainer->getProcessingStateHelper(),
+                    $diContainerRuntime->correlationIdService,
                 );
             case EngineBlock_Corto_Module_Service_SramInterrupt::class :
                 return new EngineBlock_Corto_Module_Service_SramInterrupt(
@@ -110,7 +112,8 @@ private function factoryService($className, EngineBlock_Corto_ProxyServer $serve
                     $diContainer->getSession(),
                     $diContainer->getProcessingStateHelper(),
                     $diContainer->getStepupGatewayCallOutHelper(),
-                    $diContainer->getServiceProviderFactory()
+                    $diContainer->getServiceProviderFactory(),
+                    $diContainerRuntime->correlationIdService,
                 );
             case EngineBlock_Corto_Module_Service_ProcessedAssertionConsumer::class :
                 return new EngineBlock_Corto_Module_Service_ProcessedAssertionConsumer(