mirror of
https://mau.dev/maunium/synapse.git
synced 2024-12-14 18:13:54 +01:00
Add debug for OIDC flow (#9307)
This commit is contained in:
parent
f20dadb649
commit
ce669863b9
2 changed files with 26 additions and 15 deletions
1
changelog.d/9307.misc
Normal file
1
changelog.d/9307.misc
Normal file
|
@ -0,0 +1 @@
|
||||||
|
Improve logging for OIDC login flow.
|
|
@ -123,7 +123,6 @@ class OidcHandler:
|
||||||
Args:
|
Args:
|
||||||
request: the incoming request from the browser.
|
request: the incoming request from the browser.
|
||||||
"""
|
"""
|
||||||
|
|
||||||
# The provider might redirect with an error.
|
# The provider might redirect with an error.
|
||||||
# In that case, just display it as-is.
|
# In that case, just display it as-is.
|
||||||
if b"error" in request.args:
|
if b"error" in request.args:
|
||||||
|
@ -137,8 +136,12 @@ class OidcHandler:
|
||||||
# either the provider misbehaving or Synapse being misconfigured.
|
# either the provider misbehaving or Synapse being misconfigured.
|
||||||
# The only exception of that is "access_denied", where the user
|
# The only exception of that is "access_denied", where the user
|
||||||
# probably cancelled the login flow. In other cases, log those errors.
|
# probably cancelled the login flow. In other cases, log those errors.
|
||||||
if error != "access_denied":
|
logger.log(
|
||||||
logger.error("Error from the OIDC provider: %s %s", error, description)
|
logging.INFO if error == "access_denied" else logging.ERROR,
|
||||||
|
"Received OIDC callback with error: %s %s",
|
||||||
|
error,
|
||||||
|
description,
|
||||||
|
)
|
||||||
|
|
||||||
self._sso_handler.render_error(request, error, description)
|
self._sso_handler.render_error(request, error, description)
|
||||||
return
|
return
|
||||||
|
@ -149,7 +152,7 @@ class OidcHandler:
|
||||||
# Fetch the session cookie
|
# Fetch the session cookie
|
||||||
session = request.getCookie(SESSION_COOKIE_NAME) # type: Optional[bytes]
|
session = request.getCookie(SESSION_COOKIE_NAME) # type: Optional[bytes]
|
||||||
if session is None:
|
if session is None:
|
||||||
logger.info("No session cookie found")
|
logger.info("Received OIDC callback, with no session cookie")
|
||||||
self._sso_handler.render_error(
|
self._sso_handler.render_error(
|
||||||
request, "missing_session", "No session cookie found"
|
request, "missing_session", "No session cookie found"
|
||||||
)
|
)
|
||||||
|
@ -169,7 +172,7 @@ class OidcHandler:
|
||||||
|
|
||||||
# Check for the state query parameter
|
# Check for the state query parameter
|
||||||
if b"state" not in request.args:
|
if b"state" not in request.args:
|
||||||
logger.info("State parameter is missing")
|
logger.info("Received OIDC callback, with no state parameter")
|
||||||
self._sso_handler.render_error(
|
self._sso_handler.render_error(
|
||||||
request, "invalid_request", "State parameter is missing"
|
request, "invalid_request", "State parameter is missing"
|
||||||
)
|
)
|
||||||
|
@ -183,14 +186,16 @@ class OidcHandler:
|
||||||
session, state
|
session, state
|
||||||
)
|
)
|
||||||
except (MacaroonDeserializationException, ValueError) as e:
|
except (MacaroonDeserializationException, ValueError) as e:
|
||||||
logger.exception("Invalid session")
|
logger.exception("Invalid session for OIDC callback")
|
||||||
self._sso_handler.render_error(request, "invalid_session", str(e))
|
self._sso_handler.render_error(request, "invalid_session", str(e))
|
||||||
return
|
return
|
||||||
except MacaroonInvalidSignatureException as e:
|
except MacaroonInvalidSignatureException as e:
|
||||||
logger.exception("Could not verify session")
|
logger.exception("Could not verify session for OIDC callback")
|
||||||
self._sso_handler.render_error(request, "mismatching_session", str(e))
|
self._sso_handler.render_error(request, "mismatching_session", str(e))
|
||||||
return
|
return
|
||||||
|
|
||||||
|
logger.info("Received OIDC callback for IdP %s", session_data.idp_id)
|
||||||
|
|
||||||
oidc_provider = self._providers.get(session_data.idp_id)
|
oidc_provider = self._providers.get(session_data.idp_id)
|
||||||
if not oidc_provider:
|
if not oidc_provider:
|
||||||
logger.error("OIDC session uses unknown IdP %r", oidc_provider)
|
logger.error("OIDC session uses unknown IdP %r", oidc_provider)
|
||||||
|
@ -565,6 +570,7 @@ class OidcProvider:
|
||||||
Returns:
|
Returns:
|
||||||
UserInfo: an object representing the user.
|
UserInfo: an object representing the user.
|
||||||
"""
|
"""
|
||||||
|
logger.debug("Using the OAuth2 access_token to request userinfo")
|
||||||
metadata = await self.load_metadata()
|
metadata = await self.load_metadata()
|
||||||
|
|
||||||
resp = await self._http_client.get_json(
|
resp = await self._http_client.get_json(
|
||||||
|
@ -572,6 +578,8 @@ class OidcProvider:
|
||||||
headers={"Authorization": ["Bearer {}".format(token["access_token"])]},
|
headers={"Authorization": ["Bearer {}".format(token["access_token"])]},
|
||||||
)
|
)
|
||||||
|
|
||||||
|
logger.debug("Retrieved user info from userinfo endpoint: %r", resp)
|
||||||
|
|
||||||
return UserInfo(resp)
|
return UserInfo(resp)
|
||||||
|
|
||||||
async def _parse_id_token(self, token: Token, nonce: str) -> UserInfo:
|
async def _parse_id_token(self, token: Token, nonce: str) -> UserInfo:
|
||||||
|
@ -600,17 +608,19 @@ class OidcProvider:
|
||||||
claims_cls = ImplicitIDToken
|
claims_cls = ImplicitIDToken
|
||||||
|
|
||||||
alg_values = metadata.get("id_token_signing_alg_values_supported", ["RS256"])
|
alg_values = metadata.get("id_token_signing_alg_values_supported", ["RS256"])
|
||||||
|
|
||||||
jwt = JsonWebToken(alg_values)
|
jwt = JsonWebToken(alg_values)
|
||||||
|
|
||||||
claim_options = {"iss": {"values": [metadata["issuer"]]}}
|
claim_options = {"iss": {"values": [metadata["issuer"]]}}
|
||||||
|
|
||||||
|
id_token = token["id_token"]
|
||||||
|
logger.debug("Attempting to decode JWT id_token %r", id_token)
|
||||||
|
|
||||||
# Try to decode the keys in cache first, then retry by forcing the keys
|
# Try to decode the keys in cache first, then retry by forcing the keys
|
||||||
# to be reloaded
|
# to be reloaded
|
||||||
jwk_set = await self.load_jwks()
|
jwk_set = await self.load_jwks()
|
||||||
try:
|
try:
|
||||||
claims = jwt.decode(
|
claims = jwt.decode(
|
||||||
token["id_token"],
|
id_token,
|
||||||
key=jwk_set,
|
key=jwk_set,
|
||||||
claims_cls=claims_cls,
|
claims_cls=claims_cls,
|
||||||
claims_options=claim_options,
|
claims_options=claim_options,
|
||||||
|
@ -620,13 +630,15 @@ class OidcProvider:
|
||||||
logger.info("Reloading JWKS after decode error")
|
logger.info("Reloading JWKS after decode error")
|
||||||
jwk_set = await self.load_jwks(force=True) # try reloading the jwks
|
jwk_set = await self.load_jwks(force=True) # try reloading the jwks
|
||||||
claims = jwt.decode(
|
claims = jwt.decode(
|
||||||
token["id_token"],
|
id_token,
|
||||||
key=jwk_set,
|
key=jwk_set,
|
||||||
claims_cls=claims_cls,
|
claims_cls=claims_cls,
|
||||||
claims_options=claim_options,
|
claims_options=claim_options,
|
||||||
claims_params=claims_params,
|
claims_params=claims_params,
|
||||||
)
|
)
|
||||||
|
|
||||||
|
logger.debug("Decoded id_token JWT %r; validating", claims)
|
||||||
|
|
||||||
claims.validate(leeway=120) # allows 2 min of clock skew
|
claims.validate(leeway=120) # allows 2 min of clock skew
|
||||||
return UserInfo(claims)
|
return UserInfo(claims)
|
||||||
|
|
||||||
|
@ -726,19 +738,18 @@ class OidcProvider:
|
||||||
"""
|
"""
|
||||||
# Exchange the code with the provider
|
# Exchange the code with the provider
|
||||||
try:
|
try:
|
||||||
logger.debug("Exchanging code")
|
logger.debug("Exchanging OAuth2 code for a token")
|
||||||
token = await self._exchange_code(code)
|
token = await self._exchange_code(code)
|
||||||
except OidcError as e:
|
except OidcError as e:
|
||||||
logger.exception("Could not exchange code")
|
logger.exception("Could not exchange OAuth2 code")
|
||||||
self._sso_handler.render_error(request, e.error, e.error_description)
|
self._sso_handler.render_error(request, e.error, e.error_description)
|
||||||
return
|
return
|
||||||
|
|
||||||
logger.debug("Successfully obtained OAuth2 access token")
|
logger.debug("Successfully obtained OAuth2 token data: %r", token)
|
||||||
|
|
||||||
# Now that we have a token, get the userinfo, either by decoding the
|
# Now that we have a token, get the userinfo, either by decoding the
|
||||||
# `id_token` or by fetching the `userinfo_endpoint`.
|
# `id_token` or by fetching the `userinfo_endpoint`.
|
||||||
if self._uses_userinfo:
|
if self._uses_userinfo:
|
||||||
logger.debug("Fetching userinfo")
|
|
||||||
try:
|
try:
|
||||||
userinfo = await self._fetch_userinfo(token)
|
userinfo = await self._fetch_userinfo(token)
|
||||||
except Exception as e:
|
except Exception as e:
|
||||||
|
@ -746,7 +757,6 @@ class OidcProvider:
|
||||||
self._sso_handler.render_error(request, "fetch_error", str(e))
|
self._sso_handler.render_error(request, "fetch_error", str(e))
|
||||||
return
|
return
|
||||||
else:
|
else:
|
||||||
logger.debug("Extracting userinfo from id_token")
|
|
||||||
try:
|
try:
|
||||||
userinfo = await self._parse_id_token(token, nonce=session_data.nonce)
|
userinfo = await self._parse_id_token(token, nonce=session_data.nonce)
|
||||||
except Exception as e:
|
except Exception as e:
|
||||||
|
|
Loading…
Reference in a new issue