@@ -123,7 +123,6 @@ async def handle_oidc_callback(self, request: SynapseRequest) -> None:
123123 Args:
124124 request: the incoming request from the browser.
125125 """
126-
127126 # The provider might redirect with an error.
128127 # In that case, just display it as-is.
129128 if b"error" in request .args :
@@ -137,8 +136,12 @@ async def handle_oidc_callback(self, request: SynapseRequest) -> None:
137136 # either the provider misbehaving or Synapse being misconfigured.
138137 # The only exception of that is "access_denied", where the user
139138 # probably cancelled the login flow. In other cases, log those errors.
140- if error != "access_denied" :
141- logger .error ("Error from the OIDC provider: %s %s" , error , description )
139+ logger .log (
140+ logging .INFO if error == "access_denied" else logging .ERROR ,
141+ "Received OIDC callback with error: %s %s" ,
142+ error ,
143+ description ,
144+ )
142145
143146 self ._sso_handler .render_error (request , error , description )
144147 return
@@ -149,7 +152,7 @@ async def handle_oidc_callback(self, request: SynapseRequest) -> None:
149152 # Fetch the session cookie
150153 session = request .getCookie (SESSION_COOKIE_NAME ) # type: Optional[bytes]
151154 if session is None :
152- logger .info ("No session cookie found " )
155+ logger .info ("Received OIDC callback, with no session cookie" )
153156 self ._sso_handler .render_error (
154157 request , "missing_session" , "No session cookie found"
155158 )
@@ -169,7 +172,7 @@ async def handle_oidc_callback(self, request: SynapseRequest) -> None:
169172
170173 # Check for the state query parameter
171174 if b"state" not in request .args :
172- logger .info ("State parameter is missing " )
175+ logger .info ("Received OIDC callback, with no state parameter " )
173176 self ._sso_handler .render_error (
174177 request , "invalid_request" , "State parameter is missing"
175178 )
@@ -183,14 +186,16 @@ async def handle_oidc_callback(self, request: SynapseRequest) -> None:
183186 session , state
184187 )
185188 except (MacaroonDeserializationException , ValueError ) as e :
186- logger .exception ("Invalid session" )
189+ logger .exception ("Invalid session for OIDC callback " )
187190 self ._sso_handler .render_error (request , "invalid_session" , str (e ))
188191 return
189192 except MacaroonInvalidSignatureException as e :
190- logger .exception ("Could not verify session" )
193+ logger .exception ("Could not verify session for OIDC callback " )
191194 self ._sso_handler .render_error (request , "mismatching_session" , str (e ))
192195 return
193196
197+ logger .info ("Received OIDC callback for IdP %s" , session_data .idp_id )
198+
194199 oidc_provider = self ._providers .get (session_data .idp_id )
195200 if not oidc_provider :
196201 logger .error ("OIDC session uses unknown IdP %r" , oidc_provider )
@@ -565,13 +570,16 @@ async def _fetch_userinfo(self, token: Token) -> UserInfo:
565570 Returns:
566571 UserInfo: an object representing the user.
567572 """
573+ logger .debug ("Using the OAuth2 access_token to request userinfo" )
568574 metadata = await self .load_metadata ()
569575
570576 resp = await self ._http_client .get_json (
571577 metadata ["userinfo_endpoint" ],
572578 headers = {"Authorization" : ["Bearer {}" .format (token ["access_token" ])]},
573579 )
574580
581+ logger .debug ("Retrieved user info from userinfo endpoint: %r" , resp )
582+
575583 return UserInfo (resp )
576584
577585 async def _parse_id_token (self , token : Token , nonce : str ) -> UserInfo :
@@ -600,17 +608,19 @@ async def _parse_id_token(self, token: Token, nonce: str) -> UserInfo:
600608 claims_cls = ImplicitIDToken
601609
602610 alg_values = metadata .get ("id_token_signing_alg_values_supported" , ["RS256" ])
603-
604611 jwt = JsonWebToken (alg_values )
605612
606613 claim_options = {"iss" : {"values" : [metadata ["issuer" ]]}}
607614
615+ id_token = token ["id_token" ]
616+ logger .debug ("Attempting to decode JWT id_token %r" , id_token )
617+
608618 # Try to decode the keys in cache first, then retry by forcing the keys
609619 # to be reloaded
610620 jwk_set = await self .load_jwks ()
611621 try :
612622 claims = jwt .decode (
613- token [ " id_token" ] ,
623+ id_token ,
614624 key = jwk_set ,
615625 claims_cls = claims_cls ,
616626 claims_options = claim_options ,
@@ -620,13 +630,15 @@ async def _parse_id_token(self, token: Token, nonce: str) -> UserInfo:
620630 logger .info ("Reloading JWKS after decode error" )
621631 jwk_set = await self .load_jwks (force = True ) # try reloading the jwks
622632 claims = jwt .decode (
623- token [ " id_token" ] ,
633+ id_token ,
624634 key = jwk_set ,
625635 claims_cls = claims_cls ,
626636 claims_options = claim_options ,
627637 claims_params = claims_params ,
628638 )
629639
640+ logger .debug ("Decoded id_token JWT %r; validating" , claims )
641+
630642 claims .validate (leeway = 120 ) # allows 2 min of clock skew
631643 return UserInfo (claims )
632644
@@ -726,27 +738,25 @@ async def handle_oidc_callback(
726738 """
727739 # Exchange the code with the provider
728740 try :
729- logger .debug ("Exchanging code" )
741+ logger .debug ("Exchanging OAuth2 code for a token " )
730742 token = await self ._exchange_code (code )
731743 except OidcError as e :
732- logger .exception ("Could not exchange code" )
744+ logger .exception ("Could not exchange OAuth2 code" )
733745 self ._sso_handler .render_error (request , e .error , e .error_description )
734746 return
735747
736- logger .debug ("Successfully obtained OAuth2 access token" )
748+ logger .debug ("Successfully obtained OAuth2 token data: %r" , token )
737749
738750 # Now that we have a token, get the userinfo, either by decoding the
739751 # `id_token` or by fetching the `userinfo_endpoint`.
740752 if self ._uses_userinfo :
741- logger .debug ("Fetching userinfo" )
742753 try :
743754 userinfo = await self ._fetch_userinfo (token )
744755 except Exception as e :
745756 logger .exception ("Could not fetch userinfo" )
746757 self ._sso_handler .render_error (request , "fetch_error" , str (e ))
747758 return
748759 else :
749- logger .debug ("Extracting userinfo from id_token" )
750760 try :
751761 userinfo = await self ._parse_id_token (token , nonce = session_data .nonce )
752762 except Exception as e :
0 commit comments