Lack of logging when signature verification fails

[tvdijen]

Scenario:

You're in the process of a certificate rollover, but you forget to update second_factor_test_idp_certificate in parameters.yml. You can log in to the self-service portal, but testing or self-vetting a token fail:

The logs, even in DEBUG-mode, will not give you any hints that a signature verification has failed:

SELFSERVICE[3074510]: {"channel":"request","level":"INFO","message":"Matched route \"ss_second_factor_test\".","context":{"route":"ss_second_factor_test","route_parameters":{"_route":"ss_second_factor_test","_controller":"SurfnetStepupSelfServiceSelfServiceBundle:Saml:testSecondFactor"},"request_uri":"https://selfservice.example.org/second-factor/test","method":"GET"},"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"edeabee9c58eea16777ddb4e7a1f1b50"}} SELFSERVICE[3074510]: {"channel":"security","level":"DEBUG","message":"Read existing security token from the session.","context":{"key":"_security_saml_based","token_class":"Surfnet\StepupSelfService\SelfServiceBundle\Security\Authentication\Token\SamlToken"},"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"edeabee9c58eea16777ddb4e7a1f1b50"}} SELFSERVICE[3074510]: {"channel":"app","level":"NOTICE","message":"Logged in user with a session within time limits detected, updating session state","context":[],"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"edeabee9c58eea16777ddb4e7a1f1b50"}} SELFSERVICE[3074510]: {"channel":"app","level":"NOTICE","message":"Starting second factor test","context":[],"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"edeabee9c58eea16777ddb4e7a1f1b50"}} SELFSERVICE[3074510]: {"channel":"app","level":"NOTICE","message":"Sending authentication request to the second factor test IDP","context":{"sari":"_52711d872d97f6938e690b57c09b030889dafdc78cec5ab9c41525090594"},"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"edeabee9c58eea16777ddb4e7a1f1b50"}} SELFSERVICE[3074510]: {"channel":"app","level":"DEBUG","message":"Locale cookie already set to \"en_GB\", nothing to do here","context":[],"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"edeabee9c58eea16777ddb4e7a1f1b50"}} SELFSERVICE[3074510]: {"channel":"security","level":"DEBUG","message":"Stored the security token in the session.","context":{"key":"_security_saml_based"},"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"edeabee9c58eea16777ddb4e7a1f1b50"}} SELFSERVICE[3074520]: {"channel":"request","level":"INFO","message":"Matched route \"selfservice_serviceprovider_consume_assertion\".","context":{"route":"selfservice_serviceprovider_consume_assertion","route_parameters":{"_route":"selfservice_serviceprovider_consume_assertion","_controller":"SurfnetStepupSelfServiceSelfServiceBundle:Saml:consumeAssertion"},"request_uri":"https://selfservice.example.org/authentication/consume-assertion","method":"POST"},"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"8faf611523c0476383a7ecfed8a57d08"}} SELFSERVICE[3074520]: {"channel":"security","level":"DEBUG","message":"Read existing security token from the session.","context":{"key":"_security_saml_based","token_class":"Surfnet\StepupSelfService\SelfServiceBundle\Security\Authentication\Token\SamlToken"},"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"8faf611523c0476383a7ecfed8a57d08"}} SELFSERVICE[3074520]: {"channel":"app","level":"NOTICE","message":"Logged in user with a session within time limits detected, updating session state","context":[],"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"8faf611523c0476383a7ecfed8a57d08"}} SELFSERVICE[3074520]: {"channel":"app","level":"NOTICE","message":"Received an authentication response for testing a second factor","context":[],"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"8faf611523c0476383a7ecfed8a57d08"}} SELFSERVICE[3074520]: {"channel":"app","level":"INFO","message":"SAMLResponse with id \"_601e9a9bcd28ab2b6ccf202383f49f71426b5311be78bc068d53bdfa3fef\" was not signed at root level, not attempting to verify the signature of the reponse itself","context":[],"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"8faf611523c0476383a7ecfed8a57d08"}} SELFSERVICE[3074520]: {"channel":"app","level":"INFO","message":"Verifying signature of Assertion with id \"_a107469f548f47b7ee86fce7dc1494d356c42f9282264fb955c45780a5bd\"","context":[],"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"8faf611523c0476383a7ecfed8a57d08"}} SELFSERVICE[3074520]: {"channel":"app","level":"DEBUG","message":"Validating the signed element with validator of type \"SAML2\Signature\PublicKeyValidator\"","context":[],"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"8faf611523c0476383a7ecfed8a57d08"}} SELFSERVICE[3074520]: {"channel":"app","level":"DEBUG","message":"Locale cookie already set to \"en_GB\", nothing to do here","context":[],"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"8faf611523c0476383a7ecfed8a57d08"}} SELFSERVICE[3074520]: {"channel":"security","level":"DEBUG","message":"Stored the security token in the session.","context":{"key":"_security_saml_based"},"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"8faf611523c0476383a7ecfed8a57d08"}} SELFSERVICE[3074513]: {"channel":"request","level":"INFO","message":"Matched route \"ss_second_factor_list\".","context":{"route":"ss_second_factor_list","route_parameters":{"_route":"ss_second_factor_list","_controller":"SurfnetStepupSelfServiceSelfServiceBundle:SecondFactor:list"},"request_uri":"https://selfservice.example.org/overview","method":"GET"},"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"465ab965318a35b8d20c323281ce5e12"}} SELFSERVICE[3074513]: {"channel":"security","level":"DEBUG","message":"Read existing security token from the session.","context":{"key":"_security_saml_based","token_class":"Surfnet\StepupSelfService\SelfServiceBundle\Security\Authentication\Token\SamlToken"},"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"465ab965318a35b8d20c323281ce5e12"}} SELFSERVICE[3074513]: {"channel":"app","level":"NOTICE","message":"Logged in user with a session within time limits detected, updating session state","context":[],"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"465ab965318a35b8d20c323281ce5e12"}} SELFSERVICE[3074513]: {"channel":"app","level":"DEBUG","message":"Locale cookie already set to \"en_GB\", nothing to do here","context":[],"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"465ab965318a35b8d20c323281ce5e12"}} SELFSERVICE[3074513]: {"channel":"security","level":"DEBUG","message":"Stored the security token in the session.","context":{"key":"_security_saml_based"},"extra":{"server":"selfservice.example.org","application":"self-service","request_id":"465ab965318a35b8d20c323281ce5e12"}}

It's telling us the signature is being verified, but not if it failed or passed. I now know it failed, but life's too short for this kind of debugging ;)

[thijskh]

Should be fixed in 9ead0d2.