Skip to content

Commit baad08d

Browse files
johanibjohanib
committed
WIP - ???Actually check logs???
1 parent e5e4d1f commit baad08d

10 files changed

Lines changed: 218 additions & 79 deletions

File tree

‎config/packages/ci/monolog.yaml‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,3 +3,8 @@ monolog:
33
test_log_handler:
44
type: service
55
id: OpenConext\EngineBlockFunctionalTestingBundle\Log\TestLogHandler
6+
test_log_file:
7+
type: stream
8+
path: '/tmp/eb-fixtures/log-records.ndjson'
9+
level: debug
10+
formatter: monolog.formatter.json

‎config/services_ci.yaml‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -68,6 +68,11 @@ services:
6868
OpenConext\EngineBlockFunctionalTestingBundle\Features\Context\MinkContext:
6969
tags: ['fob.context']
7070

71+
OpenConext\EngineBlockFunctionalTestingBundle\Features\Context\LoggingContext:
72+
arguments:
73+
$logFile: '/tmp/eb-fixtures/log-records.ndjson'
74+
tags: ['fob.context']
75+
7176
OpenConext\EngineBlockFunctionalTestingBundle\Fixtures\SbsClientStateManager:
7277
arguments:
7378
- "@engineblock.functional_testing.data_store.sbs_client_state_mananger"

‎src/OpenConext/EngineBlockFunctionalTestingBundle/Features/Context/LoggingContext.php‎

Lines changed: 104 additions & 30 deletions
Original file line numberDiff line numberDiff line change
@@ -19,12 +19,12 @@
1919
namespace OpenConext\EngineBlockFunctionalTestingBundle\Features\Context;
2020

2121
use Behat\Behat\Context\Context;
22-
use OpenConext\EngineBlockFunctionalTestingBundle\Log\TestLogHandler;
23-
use PHPUnit\Framework\Assert;
22+
use Behat\Gherkin\Node\TableNode;
23+
use RuntimeException;
2424

2525
class LoggingContext implements Context
2626
{
27-
public function __construct(private readonly TestLogHandler $logHandler)
27+
public function __construct(private readonly string $logFile)
2828
{
2929
}
3030

@@ -33,41 +33,115 @@ public function __construct(private readonly TestLogHandler $logHandler)
3333
*/
3434
public function resetLogHandler(): void
3535
{
36-
$this->logHandler->reset();
36+
file_put_contents($this->logFile, '');
3737
}
3838

3939
/**
40-
* @Then each log record should contain a :field field
40+
* @Then the following log messages should have a correlation_id:
4141
*/
42-
public function eachLogRecordShouldContainField(string $field): void
42+
public function theFollowingLogMessagesShouldHaveACorrelationId(TableNode $table): void
4343
{
44-
$records = $this->logHandler->getRecords();
45-
46-
Assert::assertNotEmpty($records, 'No log records were captured during this scenario.');
47-
48-
foreach ($records as $index => $record) {
49-
Assert::assertArrayHasKey(
50-
$field,
51-
$record->extra,
52-
sprintf(
53-
'Log record #%d (channel=%s, message="%s") is missing extra field "%s".',
54-
$index,
55-
$record->channel,
56-
$record->message,
57-
$field,
58-
),
44+
$records = $this->readRecords();
45+
$allCorrelationIds = [];
46+
47+
foreach ($table->getColumnsHash() as $row) {
48+
$pattern = $row['message'];
49+
$isRegex = preg_match('/^\/.*\/$/', $pattern) === 1;
50+
51+
$matched = array_filter(
52+
$records,
53+
static fn(array $r) => $isRegex
54+
? preg_match($pattern, $r['message'] ?? '') === 1
55+
: ($r['message'] ?? '') === $pattern,
5956
);
6057

61-
Assert::assertNotNull(
62-
$record->extra[$field],
63-
sprintf(
64-
'Log record #%d (channel=%s, message="%s") has a null value for extra field "%s".',
65-
$index,
66-
$record->channel,
67-
$record->message,
68-
$field,
69-
),
58+
if (empty($matched)) {
59+
throw new RuntimeException(sprintf(
60+
'No log record matched message %s "%s".',
61+
$isRegex ? 'pattern' : 'string',
62+
$pattern,
63+
));
64+
}
65+
66+
foreach ($matched as $record) {
67+
$correlationId = $record['extra']['correlation_id'] ?? null;
68+
69+
if ($correlationId === null) {
70+
throw new RuntimeException(sprintf(
71+
'Log record matching "%s" (channel=%s) has a null correlation_id.',
72+
$pattern,
73+
$record['channel'] ?? '?',
74+
));
75+
}
76+
77+
$allCorrelationIds[] = $correlationId;
78+
}
79+
}
80+
81+
$distinct = array_unique($allCorrelationIds);
82+
83+
if (count($distinct) > 1) {
84+
throw new RuntimeException(sprintf(
85+
'Expected a single correlation_id across all matched log records, but found %d distinct values: %s.',
86+
count($distinct),
87+
implode(', ', $distinct),
88+
));
89+
}
90+
}
91+
92+
/**
93+
* @Then I dump the log records
94+
*/
95+
public function iDumpTheLogRecords(): void
96+
{
97+
$records = $this->readRecords();
98+
$rows = [];
99+
foreach ($records as $record) {
100+
$message = $record['message'] ?? '';
101+
if (mb_strlen($message) > 100) {
102+
$message = mb_substr($message, 0, 97) . '...';
103+
}
104+
$rows[] = sprintf(
105+
'| %-12s | %-9s | %-100s | %s |',
106+
$record['channel'] ?? '',
107+
$record['level_name'] ?? '',
108+
str_replace('|', '\\|', $message),
109+
$record['extra']['correlation_id'] ?? 'null',
70110
);
71111
}
112+
echo "\n" . implode("\n", $rows) . "\n";
113+
}
114+
115+
/**
116+
* Reads all records from the log file, decodes each JSON line, and returns only
117+
* records not belonging to the event channel (Symfony kernel internals).
118+
*
119+
* @return array<int, array<string, mixed>>
120+
*/
121+
private function readRecords(): array
122+
{
123+
$lines = file($this->logFile, FILE_IGNORE_NEW_LINES | FILE_SKIP_EMPTY_LINES);
124+
125+
if ($lines === false) {
126+
return [];
127+
}
128+
129+
$records = [];
130+
131+
foreach ($lines as $index => $line) {
132+
$record = json_decode($line, true);
133+
134+
if (!is_array($record)) {
135+
throw new RuntimeException(sprintf('Log record #%d could not be decoded as JSON.', $index));
136+
}
137+
138+
if (($record['channel'] ?? '') === 'event') {
139+
continue;
140+
}
141+
142+
$records[] = $record;
143+
}
144+
145+
return $records;
72146
}
73147
}

‎src/OpenConext/EngineBlockFunctionalTestingBundle/Features/CorrelationId.feature‎

Lines changed: 98 additions & 43 deletions
Original file line numberDiff line numberDiff line change
@@ -5,63 +5,118 @@ Feature:
55

66
Background:
77
Given an EngineBlock instance on "dev.openconext.local"
8-
And no registered SPs
9-
And no registered Idps
10-
And a Service Provider named "CorrId-SP"
8+
And no registered SPs
9+
And no registered Idps
10+
And a Service Provider named "CorrId-SP"
1111

12-
# ── WAYF path ──────────────────────────────────────────────────────────────
13-
# Two IdPs are registered, so the WAYF is shown after the initial SSO request.
14-
# The correlation ID is minted in SingleSignOn.serve(), propagated to
15-
# ContinueToIdp (user picks an IdP), then forwarded to the IdP request via
16-
# link(), and finally picked up in AssertionConsumer and ProvideConsent/
17-
# ProcessConsent. A complete round-trip through all four HTTP legs must
18-
# succeed without error.
1912
Scenario: A user authenticating via the WAYF completes the full four-leg flow
2013
Given an Identity Provider named "CorrId-IdP-A"
21-
And an Identity Provider named "CorrId-IdP-B"
14+
And an Identity Provider named "CorrId-IdP-B"
2215
When I log in at "CorrId-SP"
23-
And I select "CorrId-IdP-A" on the WAYF
24-
And I pass through EngineBlock
25-
And I pass through the IdP
26-
And I give my consent
27-
And I pass through EngineBlock
16+
And I select "CorrId-IdP-A" on the WAYF
17+
And I pass through EngineBlock
18+
And I pass through the IdP
19+
And I give my consent
20+
And I pass through EngineBlock
2821
Then the url should match "functional-testing/CorrId-SP/acs"
22+
#And I dump the log records
23+
And the following log messages should have a correlation_id:
24+
| message |
25+
| Multiple candidate IdPs: redirecting to WAYF |
26+
| Done calling service 'singleSignOnService' |
27+
| Done calling service 'continueToIdp' |
28+
| /Received Assertion from Issuer .*/ |
29+
| /SP is not configured for MFA for IdP, or for transparant AuthnContext, skipping validation .*/ |
30+
| Verifying if schacHomeOrganization is allowed by configured IdP shibmd:scopes |
31+
| No shibmd:scope found in the IdP metadata, not verifying schacHomeOrganization |
32+
| Verifying if eduPersonPrincipalName is allowed by configured IdP shibmd:scopes |
33+
| No shibmd:scope found in the IdP metadata, not verifying eduPersonPrincipalName |
34+
| Verifying if subject-id is allowed by configured IdP shibmd:scopes |
35+
| No shibmd:scope found in the IdP metadata, not verifying subject-id |
36+
| /No Attribute Aggregation for .*/ |
37+
| /No SBS interrupt for serviceProvider.*/ |
38+
| StepupDecision: determine highest LoA |
39+
| StepupDecision: no level set, no Stepup required |
40+
| Handle Consent authentication callout |
41+
| Using internal binding for destination /authentication/idp/provide-consent |
42+
| Calling service 'provideConsentService' |
43+
| Done calling service 'provideConsentService' |
44+
| Done calling service 'assertionConsumerService' |
45+
| /Using internal binding for destination https:\/\/engine.dev.openconext.local\/authenticati.*/ |
46+
| Calling service 'processedAssertionConsumerService' |
47+
| /No ARP available for https:\/\/engine.dev.openconext.local\/functional-testing\/CorrId-SP\/metadata. .*/ |
48+
| Executing the ApplyTrustedProxyBehavior output filter |
49+
| Executing the AddIdentityAttributes output filter |
50+
| Resolving a persistent nameId |
51+
| Setting the NameId on the Assertion |
52+
| Adding the EduPersonTargetedId on the Assertion |
53+
| /Attribute Denormalization: Adding alias 'urn:oid:0.9.2342.19200300.100.1.1' .*/ |
54+
| /Attribute Denormalization: Adding alias 'urn:oid:1.3.6.1.4.1.25178.1.2.9' for .*/ |
55+
| /Attribute Denormalization: Adding alias 'urn:oid:1.3.6.1.4.1.5923.1.1.1.10' for .*/ |
56+
| HTTP-Post: Sending Message |
57+
| Done calling service 'processedAssertionConsumerService' |
58+
| Done calling service 'processConsentService' |
2959

30-
# ── Direct path (no WAYF) ───────────────────────────────────────────────────
31-
# When only one IdP is available the WAYF is skipped; the correlation ID is
32-
# minted inside ProxyServer.sendAuthenticationRequest() and linked to the IdP
33-
# request. AssertionConsumer and consent legs must resolve it from the IdP
34-
# request ID stored in InResponseTo.
3560
Scenario: A user authenticating without the WAYF completes the full flow
3661
Given an Identity Provider named "CorrId-IdP-Only"
3762
When I log in at "CorrId-SP"
38-
And I pass through EngineBlock
39-
And I pass through the IdP
40-
And I give my consent
41-
And I pass through EngineBlock
63+
And I pass through EngineBlock
64+
And I pass through the IdP
65+
And I give my consent
66+
And I pass through EngineBlock
4267
Then the url should match "functional-testing/CorrId-SP/acs"
68+
And I dump the log records
69+
And the following log messages should have a correlation_id:
70+
| message |
71+
| HTTP-Post: Sending Message |
72+
| Done calling service 'singleSignOnService' |
73+
| /SP is not configured for MFA for IdP, or for transparant AuthnContext, skipping validation of .*/ |
74+
| Verifying if schacHomeOrganization is allowed by configured IdP shibmd:scopes |
75+
| No shibmd:scope found in the IdP metadata, not verifying schacHomeOrganization |
76+
| Verifying if eduPersonPrincipalName is allowed by configured IdP shibmd:scopes |
77+
| No shibmd:scope found in the IdP metadata, not verifying eduPersonPrincipalName |
78+
| Verifying if subject-id is allowed by configured IdP shibmd:scopes |
79+
| No shibmd:scope found in the IdP metadata, not verifying subject-id |
80+
| /No Attribute Aggregation for https:\/\/engine.dev.openconext.local\/functional-testing\/CorrId-S.*/ |
81+
| /No SBS interrupt for serviceProvider: https:\/\/engine.dev.openconext.local\/functional-testin.*/ |
82+
| StepupDecision: determine highest LoA |
83+
| StepupDecision: no level set, no Stepup required |
84+
| Handle Consent authentication callout |
85+
| Using internal binding for destination /authentication/idp/provide-consent |
86+
| Calling service 'provideConsentService' |
87+
| Done calling service 'provideConsentService' |
88+
| Done calling service 'assertionConsumerService' |
89+
| /Using internal binding for destination.*/ |
90+
| Calling service 'processedAssertionConsumerService' |
91+
| /No ARP available for https:\/\/engine.dev.openconext.local\/functional-testing\/CorrId-SP\/metadata. */ |
92+
| Executing the ApplyTrustedProxyBehavior output filter |
93+
| Executing the AddIdentityAttributes output filter |
94+
| Resolving a persistent nameId |
95+
| Setting the NameId on the Assertion |
96+
| Adding the EduPersonTargetedId on the Assertion |
97+
| /Attribute Denormalization: Adding alias 'urn:oid:0.9.2342.19200300.100.1.1'*/ |
98+
| /Attribute Denormalization: Adding alias 'urn:oid:1.3.6.1.4.1.25178.1.2.9' f*/ |
99+
| /Attribute Denormalization: Adding alias 'urn:oid:1.3.6.1.4.1.5923.1.1.1.10' */ |
100+
| login granted |
101+
| HTTP-Post: Sending Message |
102+
| Done calling service 'processedAssertionConsumerService' |
103+
| Done calling service 'processConsentService' |
43104

44-
# ── Concurrent flows ────────────────────────────────────────────────────────
45-
# Two simultaneous authentications in separate browser tabs share the same PHP
46-
# session. Each flow must mint its own correlation ID and the two IDs must
47-
# not bleed into each other. Both flows must complete successfully and land
48-
# on the correct SP ACS URL.
49-
# Requires the @functional tag to use the Chrome driver (browser tabs need JS).
50105
@functional
51106
Scenario: Two concurrent authentication flows each complete independently
52107
Given an Identity Provider named "CorrId-IdP-A"
53-
And an Identity Provider named "CorrId-IdP-B"
108+
And an Identity Provider named "CorrId-IdP-B"
54109
When I open 2 browser tabs identified by "Tab-A, Tab-B"
55-
And I switch to "Tab-A"
56-
And I log in at "CorrId-SP"
57-
And I select "CorrId-IdP-A" on the WAYF
58-
And I switch to "Tab-B"
59-
And I log in at "CorrId-SP"
60-
And I select "CorrId-IdP-B" on the WAYF
61-
And I pass through the IdP
62-
And I give my consent
110+
And I switch to "Tab-A"
111+
And I log in at "CorrId-SP"
112+
And I select "CorrId-IdP-A" on the WAYF
113+
And I switch to "Tab-B"
114+
And I log in at "CorrId-SP"
115+
And I select "CorrId-IdP-B" on the WAYF
116+
And I pass through the IdP
117+
And I give my consent
63118
Then the url should match "functional-testing/CorrId-SP/acs"
64-
And I switch to "Tab-A"
65-
And I pass through the IdP
66-
And I give my consent
119+
And I switch to "Tab-A"
120+
And I pass through the IdP
121+
And I give my consent
67122
Then the url should match "functional-testing/CorrId-SP/acs"

‎tests/behat.yml‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -44,7 +44,7 @@ default:
4444
- OpenConext\EngineBlockFunctionalTestingBundle\Features\Context\TranslationContext:
4545
mockTranslator: '@engineblock.functional_testing.mock.translator'
4646
- OpenConext\EngineBlockFunctionalTestingBundle\Features\Context\LoggingContext:
47-
logHandler: '@OpenConext\EngineBlockFunctionalTestingBundle\Log\TestLogHandler'
47+
logFile: '/tmp/eb-fixtures/log-records.ndjson'
4848
- OpenConext\EngineBlockFunctionalTestingBundle\Features\Context\MinkContext:
4949
functional:
5050
mink_session: chrome

‎tests/library/EngineBlock/Test/Saml2/AuthnRequestSessionRepositoryTest.php‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,7 @@
11
<?php
22

33
/**
4-
* Copyright 2010 SURFnet B.V.
4+
* Copyright 2026 SURFnet B.V.
55
*
66
* Licensed under the Apache License, Version 2.0 (the "License");
77
* you may not use this file except in compliance with the License.

‎tests/unit/OpenConext/EngineBlock/Logger/Processor/CorrelationIdProcessorTest.php‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,7 @@
11
<?php
22

33
/**
4-
* Copyright 2010 SURFnet B.V.
4+
* Copyright 2026 SURFnet B.V.
55
*
66
* Licensed under the Apache License, Version 2.0 (the "License");
77
* you may not use this file except in compliance with the License.

‎tests/unit/OpenConext/EngineBlock/Request/CorrelationIdFlowTest.php‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,7 @@
11
<?php
22

33
/**
4-
* Copyright 2010 SURFnet B.V.
4+
* Copyright 2026 SURFnet B.V.
55
*
66
* Licensed under the Apache License, Version 2.0 (the "License");
77
* you may not use this file except in compliance with the License.

‎tests/unit/OpenConext/EngineBlock/Request/CorrelationIdRepositoryTest.php‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,7 @@
11
<?php
22

33
/**
4-
* Copyright 2010 SURFnet B.V.
4+
* Copyright 2026 SURFnet B.V.
55
*
66
* Licensed under the Apache License, Version 2.0 (the "License");
77
* you may not use this file except in compliance with the License.

0 commit comments

Comments
 (0)