No way to track requests through the logs

[baszoetekouw]

I would like to be able to follow a SAML login flow through the entire authentication flow by looking at the logs. I was hoping the request_id variable in the log message would allow me to do that, be unfortunately, that changes whenever EngineBlock receives a new HTTP request (e.g., when the user logs in at the IdP and sends a POST to the ACS andpoint, or when the user accepts a Consent).

Consider the following flow for a simple login of a fresh user on Profile:

request_id	session_id	message
69dcfdb20fd8b	2cd4ad0451f0963018297ac1d9f100a1	Received signed AuthnRequest from Issuer "https://profile.test2.surfconext.nl/authentication/metadata" with signature method algorithm "http://www.w3.org/2001/04/xmldsig-more#rsa-sha256"
69dcfdb20fd8b	2cd4ad0451f0963018297ac1d9f100a1	Calling service 'singleSignOnService'
69dcfdb20fd8b	2cd4ad0451f0963018297ac1d9f100a1	Getting request...
69dcfdb20fd8b	2cd4ad0451f0963018297ac1d9f100a1	Binding received unsigned SAML request from 'https://profile.test2.surfconext.nl/authentication/metadata'
69dcfdb20fd8b	2cd4ad0451f0963018297ac1d9f100a1	Fetching service provider matching request issuer 'https://profile.test2.surfconext.nl/authentication/metadata'
69dcfdb20fd8b	2cd4ad0451f0963018297ac1d9f100a1	Determining whether service provider in chain requires additional logging
69dcfdb20fd8b	2cd4ad0451f0963018297ac1d9f100a1	Activated additional logging for one or more SPs in the SP requester chain
69dcfdb20fd8b	2cd4ad0451f0963018297ac1d9f100a1	Raw HTTP request
69dcfdb20fd8b	2cd4ad0451f0963018297ac1d9f100a1	No IdP scoping required, 15 candidate IdPs
69dcfdb20fd8b	2cd4ad0451f0963018297ac1d9f100a1	Multiple candidate IdPs: redirecting to WAYF
69dcfdb20fd8b	2cd4ad0451f0963018297ac1d9f100a1	Done calling service 'singleSignOnService'
69dcfdb4e41fc	2cd4ad0451f0963018297ac1d9f100a1	Calling service 'continueToIdp'
69dcfdb4e41fc	2cd4ad0451f0963018297ac1d9f100a1	Activated additional logging for the SP or IdP
69dcfdb4e41fc	2cd4ad0451f0963018297ac1d9f100a1	Raw HTTP request
69dcfdb4e41fc	2cd4ad0451f0963018297ac1d9f100a1	HTTP-Post: Sending Message
69dcfdb4e41fc	2cd4ad0451f0963018297ac1d9f100a1	Done calling service 'continueToIdp'
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Calling service 'assertionConsumerService'
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Received response
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Attempting to verify the signature of SAMLResponse with id "_18f2d091-f2a7-4791-9024-504f19e6a25e"
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Verifying signature of Assertion with id "_8d721634-09bd-418f-89bb-c5c9f5455add"
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Received Assertion from Issuer "http://mock-idp" with signature method algorithms Response: "http://www.w3.org/2001/04/xmldsig-more#rsa-sha256" and Assertion: "http://www.w3.org/2001/04/xmldsig-more#rsa-sha256"
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Activated additional logging for the SP or IdP
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Raw HTTP request
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	No authn_context_class_ref_blacklist_regex found in the configuration, not validating AuthnContextClassRef
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	SP is not configured for MFA for IdP, or for transparant AuthnContext, skipping validation of AuthnContextClassRef
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Verifying if schacHomeOrganization is allowed by configured IdP shibmd:scopes
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	No shibmd:scope found in the IdP metadata, not verifying schacHomeOrganization
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Verifying if eduPersonPrincipalName is allowed by configured IdP shibmd:scopes
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	No shibmd:scope found in the IdP metadata, not verifying eduPersonPrincipalName
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Verifying if subject-id is allowed by configured IdP shibmd:scopes
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	No shibmd:scope found in the IdP metadata, not verifying subject-id
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Attribute Aggregation for https://profile.test2.surfconext.nl/authentication/metadata
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Applying attribute release policy for https://profile.test2.surfconext.nl/authentication/metadata
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	StepupDecision: no level set, no Stepup required
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Handle Consent authentication callout
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Using AssertionConsumerServiceLocation 'https://profile.test2.surfconext.nl/authentication/consume-assertion' and ProtocolBinding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST' from unsigned request, it's okay though, the ACSLocation and Binding were registered in the metadata
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Using AssertionConsumerServiceLocation 'https://profile.test2.surfconext.nl/authentication/consume-assertion' and ProtocolBinding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST' from unsigned request, it's okay though, the ACSLocation and Binding were registered in the metadata
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Using internal binding for destination /authentication/idp/provide-consent
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Calling service 'provideConsentService'
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Activated additional logging for one or more SPs in the SP requester chain, or the IdP
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Raw HTTP request
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Resolving a persistent nameId
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Attribute lookup failure 'name_id' has no 'Name' for language 'en'
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Done calling service 'provideConsentService'
69dcfdb71e93e	2cd4ad0451f0963018297ac1d9f100a1	Done calling service 'assertionConsumerService'
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	Calling service 'processConsentService'
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	Using internal binding for destination https://engine.test2.surfconext.nl/authentication/proxy/processed-assertion
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	Calling service 'processedAssertionConsumerService'
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	Activated additional logging for the SP or IdP
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	Raw HTTP request
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	Using AssertionConsumerServiceLocation 'https://profile.test2.surfconext.nl/authentication/consume-assertion' and ProtocolBinding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST' from unsigned request, it's okay though, the ACSLocation and Binding were registered in the metadata
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	Using AssertionConsumerServiceLocation 'https://profile.test2.surfconext.nl/authentication/consume-assertion' and ProtocolBinding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST' from unsigned request, it's okay though, the ACSLocation and Binding were registered in the metadata
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	No 'release-as' instructions to apply for https://profile.test2.surfconext.nl/authentication/metadata.
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	Executing the ApplyTrustedProxyBehavior output filter
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	Executing the AddIdentityAttributes output filter
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	Resolving a persistent nameId
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	Setting the NameId on the Assertion
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	Adding the EduPersonTargetedId on the Assertion
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	HTTP-Post: Sending Message
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	Done calling service 'processedAssertionConsumerService'
69dcfdb8a4c0f	2cd4ad0451f0963018297ac1d9f100a1	Done calling service 'processConsentService'

Here we see 4 different request_ids:

• processing the SAMLRequest
• processing the WAYF choice
• processing the SAMLResponse
• processing the Consent choice

This makes it impossible to follow the handling of this request through the system

Even though the session_id stays constant, this is also not useful, as the session is typically (much) longer than a single request. In practice, we see users logging in simultaneously or in quick succession on multiple services in the same session.

I see two possible solutions:

• reuse the request_id if a request is a continuation of a previous request with an existing request_id, or
• introduce a new correlation_id that is carries over between requests. This correlation_id should then also be output in .extras for all log entries, and also shown in error pages.

[baszoetekouw]

cmp the SARI implementation in Stepup.