Fix logging without format string (#871)

* Fix logging without format string
* Fix test to use Logrecord args instead of msg

CHANGELOG.md

@@ -7,11 +7,16 @@ The format is based on the [KeepAChangeLog] project.
 
 ## Unreleased
 
+### Changed
+
+- [#871]: Fix log messages without format string
+
 ### Removed
 
 - [#870]: Remove Python 3.7
 
 [#870]: https://github.com/CZ-NIC/pyoidc/pull/870
+[#871]: https://github.com/CZ-NIC/pyoidc/pull/871
 
 ## 1.6.1 [2023-07-13]
 - [#862] Fixed pydantic dependency

src/oic/extension/provider.py

@@ -744,7 +744,7 @@ def get_token_info(self, authn, req, endpoint):
         try:
             client_id = self.client_authn(self, req, authn)
         except FailedAuthentication as err:
-            logger.error(err)
+            logger.error("%s", err)
             error = TokenErrorResponse(
                 error="unauthorized_client", error_description="%s" % err
             )

src/oic/oauth2/base.py

@@ -150,7 +150,7 @@ def http_request(self, url: str, method="GET", **kwargs) -> requests.Response:
             try:
                 set_cookie(self.cookiejar, SimpleCookie(_cookie))
             except CookieError as err:
-                logger.error(err)
+                logger.error("%s", err)
                 raise NonFatalException(r, "{}".format(err))
         except (AttributeError, KeyError):
             pass

src/oic/oauth2/consumer.py

@@ -289,7 +289,7 @@ def handle_authorization_response(self, query="", **kwargs):
                     AuthorizationResponse, info=query, sformat="urlencoded"
                 )
             except Exception as err:
-                logger.error("%s" % err)
+                logger.error("%s", err)
                 raise
 
             if isinstance(aresp, Message):

src/oic/oauth2/provider.py

@@ -592,7 +592,7 @@ def auth_init(self, request):
         try:
             areq = self.server.parse_authorization_request(query=request)
         except (MissingRequiredValue, MissingRequiredAttribute, AuthzError) as err:
-            logger.debug("%s" % err)
+            logger.debug("%s", err)
             areq = request_class()
             areq.lax = True
             if isinstance(request, dict):
@@ -1015,7 +1015,7 @@ def token_endpoint(self, request="", authn="", dtype="urlencoded", **kwargs):
         try:
             client_id = self.client_authn(self, areq, authn)
         except (FailedAuthentication, AuthnFailure) as err:
-            logger.error(err)
+            logger.error("%s", err)
             error = TokenErrorResponse(
                 error="unauthorized_client", error_description="%s" % err
             )

src/oic/oic/__init__.py

@@ -1269,7 +1269,7 @@ def handle_registration_info(self, response):
             try:
                 resp.verify()
             except oauth2.message.MissingRequiredAttribute as err:
-                logger.error(err)
+                logger.error("%s", err)
                 raise RegistrationError(err)
             except Exception:
                 resp = ErrorResponse().deserialize(response.text, "json")
@@ -1677,7 +1677,7 @@ def parse_authorization_request(
         except Exception as err:
             if self.events:
                 self.events.store("Exception", err)
-            logger.error(err)
+            logger.error("%s", err)
             raise
 
         return _req

src/oic/oic/provider.py

@@ -874,7 +874,7 @@ def code_grant_type(self, areq):
         try:
             _tinfo = _sdb.upgrade_to_token(_access_code, issue_refresh=issue_refresh)
         except AccessCodeUsed as err:
-            logger.error("%s" % err)
+            logger.error("%s", err)
             # Should revoke the token issued to this access code
             _sdb.revoke_all_tokens(_access_code)
             return error_response("access_denied", descr="Access Code already used")
@@ -886,7 +886,7 @@ def code_grant_type(self, areq):
                     _info, client_info, areq, user_info=userinfo
                 )
             except (JWEException, NoSuitableSigningKeys) as err:
-                logger.warning(str(err))
+                logger.warning("%s", err)
                 return error_response(
                     "invalid_request", descr="Could not sign/encrypt id_token"
                 )
@@ -934,7 +934,7 @@ def refresh_token_grant_type(self, areq):
                     _info, client_info, areq, user_info=userinfo
                 )
             except (JWEException, NoSuitableSigningKeys) as err:
-                logger.warning(str(err))
+                logger.warning("%s", err)
                 return error_response(
                     "invalid_request", descr="Could not sign/encrypt id_token"
                 )
@@ -1376,7 +1376,7 @@ def _verify_sector_identifier(self, request):
         try:
             res = self.server.http_request(si_url)
         except RequestException as err:
-            logger.error(err)
+            logger.error("%s", err)
             res = None
 
         if not res:
@@ -1798,7 +1798,7 @@ def create_authn_response(self, areq, sid):
                         _sinfo, client_info, areq, user_info=user_info, **hargs
                     )
                 except (JWEException, NoSuitableSigningKeys) as err:
-                    logger.warning(str(err))
+                    logger.warning("%s", err)
                     return error_response(
                         "invalid_request", descr="Could not sign/encrypt id_token"
                     )
@@ -1935,7 +1935,7 @@ def verify_post_logout_redirect_uri(
                 return redirect_uri
         except Exception as exc:
             msg = "An error occurred while verifying redirect URI: %s"
-            logger.debug(msg, str(exc))
+            logger.debug(msg, exc)
 
         return None
 

src/oic/utils/authn/saml.py

@@ -368,7 +368,7 @@ def _redirect_to_auth(self, _cli, entity_id, query, end_point_index, vorg_name="
 
             logger.debug("ht_args: %s" % ht_args)
         except Exception as exc:
-            logger.exception(exc)
+            logger.exception("%s", exc)
             raise ServiceErrorException(
                 "Failed to construct the AuthnRequest: %s" % exc
             )

src/oic/utils/http_util.py

@@ -560,7 +560,7 @@ def wsgi_wrapper(environ, start_response, func, **kwargs):
         resp = args
         return resp(environ, start_response)
     except Exception as err:
-        logger.error("%s" % err)
+        logger.error("%s", err)
         raise
 
 

src/oic/utils/keyio.py

@@ -193,7 +193,7 @@ def do_remote(self):
             logger.debug("KeyBundle fetch keys from: %s", self.source)
             r = requests.get(self.source, timeout=self.timeout, **args)
         except Exception as err:
-            logger.error(err)
+            logger.error("%s", err)
             raise_exception(UpdateFailed, REMOTE_FAILED.format(self.source, str(err)))
 
         if r.status_code == 304:  # file has not changed

src/oic/utils/rp/__init__.py

@@ -134,7 +134,7 @@ def _do_code(self, response, authresp):
             msg = "Access token response: {}"
             logger.info(msg.format(sanitize(atresp)))
         except Exception as err:
-            logger.error("%s" % err)
+            logger.error("%s", err)
             raise
 
         if isinstance(atresp, ErrorResponse):

src/oic/utils/rp/oauth2.py

@@ -169,7 +169,7 @@ def callback(self, response, session, format="dict"):
                 )
                 logger.info("Access token response: {}".format(sanitize(atresp)))
             except Exception as err:
-                logger.error("%s" % err)
+                logger.error("%s", err)
                 raise
 
             if isinstance(atresp, ErrorResponse):

tests/test_oic_provider.py

@@ -1349,12 +1349,12 @@ def test_verify_sector_identifier_no_scheme(self):
 
         assert len(logcap.records) == 2
         # First log record is from server...
-        assert isinstance(logcap.records[1].msg, MissingSchema)
+        assert isinstance(logcap.records[1].args[0], MissingSchema)
         error = (
             "Invalid URL 'example.com': No scheme supplied. Perhaps you meant "
             "https://example.com?"
         )
-        assert str(logcap.records[1].msg) == error
+        assert logcap.records[1].getMessage() == error
 
     def test_verify_sector_identifier_nonreachable(self):
         rr = RegistrationRequest(
@@ -1386,7 +1386,7 @@ def test_verify_sector_identifier_error(self):
 
         assert len(logcap.records) == 2
         # First log record is from server...
-        assert logcap.records[1].msg == error
+        assert logcap.records[1].args[0] == error
 
     def test_verify_sector_identifier_malformed(self):
         rr = RegistrationRequest(