From da150dc91b91a03e4f176886f43d1c7e157a560b Mon Sep 17 00:00:00 2001 From: ric-evans Date: Fri, 18 Oct 2024 15:36:37 -0500 Subject: [PATCH 1/8] Server: Be Explicit When/Why the Root Logger is Used --- rest_tools/server/server.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/rest_tools/server/server.py b/rest_tools/server/server.py index 035241c3..636fc9d7 100644 --- a/rest_tools/server/server.py +++ b/rest_tools/server/server.py @@ -3,7 +3,6 @@ """ # fmt:off -# pylint: skip-file import binascii import logging @@ -14,15 +13,16 @@ AsyncIOMainLoop().install() +LOGGER = logging.getLogger() # this stuff always needs to be logged -> use the 'root' logger def tornado_logger(handler): """Log tornado messages to root logger.""" if handler.get_status() < 400: - log_method = logging.debug + log_method = LOGGER.debug elif handler.get_status() < 500: - log_method = logging.warning + log_method = LOGGER.warning else: - log_method = logging.error + log_method = LOGGER.error request_time = 1000.0 * handler.request.request_time() log_method("%d %s %.2fms", handler.get_status(), handler._request_summary(), request_time) @@ -58,7 +58,7 @@ def startup(self, address='localhost', port=8080): address (str): bind address port (int): bind port """ - logging.warning('tornado bound to %s:%d', address, port) + LOGGER.warning('tornado bound to %s:%d', address, port) app = tornado.web.Application(self.routes, **self.app_args) From eff1285338fe94b7fe024e9b23c98c0fcb575296 Mon Sep 17 00:00:00 2001 From: ric-evans Date: Fri, 18 Oct 2024 15:50:37 -0500 Subject: [PATCH 2/8] replace "rest" logger with "rest_tools.server.handler" (__name__) --- rest_tools/server/handler.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rest_tools/server/handler.py b/rest_tools/server/handler.py index 7944878a..a4a140dc 100644 --- a/rest_tools/server/handler.py +++ b/rest_tools/server/handler.py @@ -27,7 +27,7 @@ from ..utils.json_util import json_decode from ..utils.pkce import PKCEMixin -LOGGER = logging.getLogger('rest') +LOGGER = logging.getLogger(__name__) def _log_auth_failed(e: Exception): From 4e5d007aef8cc80a1d1bc343193d35d9fc23f1b9 Mon Sep 17 00:00:00 2001 From: ric-evans Date: Fri, 18 Oct 2024 15:51:22 -0500 Subject: [PATCH 3/8] upgrade <400 status requests to use info logger --- rest_tools/server/server.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rest_tools/server/server.py b/rest_tools/server/server.py index 636fc9d7..69ec80b5 100644 --- a/rest_tools/server/server.py +++ b/rest_tools/server/server.py @@ -18,7 +18,7 @@ def tornado_logger(handler): """Log tornado messages to root logger.""" if handler.get_status() < 400: - log_method = LOGGER.debug + log_method = LOGGER.info elif handler.get_status() < 500: log_method = LOGGER.warning else: From dfa3a63728f6032183955f06e9fae53743ef4978 Mon Sep 17 00:00:00 2001 From: ric-evans Date: Fri, 18 Oct 2024 15:51:49 -0500 Subject: [PATCH 4/8] fix deprecated `warn()` --- rest_tools/server/handler.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rest_tools/server/handler.py b/rest_tools/server/handler.py index a4a140dc..b13b5918 100644 --- a/rest_tools/server/handler.py +++ b/rest_tools/server/handler.py @@ -168,7 +168,7 @@ def prepare(self): stat = self.route_stats[self.request.path] if stat.is_overloaded(): backoff = stat.get_backoff_time() - LOGGER.warn('Server is overloaded, backoff %r', backoff) + LOGGER.warning('Server is overloaded, backoff %r', backoff) self.set_header('Retry-After', backoff) raise tornado.web.HTTPError(503, reason="server overloaded") self.start_time = time.time() From cf4a42e1131e46295f42c86c5143923d2b42b4dd Mon Sep 17 00:00:00 2001 From: ric-evans Date: Fri, 18 Oct 2024 15:52:10 -0500 Subject: [PATCH 5/8] update start-of-request logging --- rest_tools/server/handler.py | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/rest_tools/server/handler.py b/rest_tools/server/handler.py index b13b5918..7c622b78 100644 --- a/rest_tools/server/handler.py +++ b/rest_tools/server/handler.py @@ -162,7 +162,13 @@ def get_current_user(self): @wtt.evented() def prepare(self): """Prepare before http-method request handlers.""" - LOGGER.debug(f"{self.request.method} [{self.__class__.__name__}]") + + # log at the very start of every new request + logging.info(">>> %s", self._request_summary()) # use the root logger + # ^^^ this mimics the log line that tornado provides at the end of a request: + # see rest_tools.server.tornado_logger(). + # ">>>" makes logs line-up (end-of-request log line uses http code: 200, 400, etc.) + LOGGER.debug(f"[{self.__class__.__name__}]") if self.route_stats is not None: stat = self.route_stats[self.request.path] From 2cb4164104d8b853913257e048bd23aa934ad0fd Mon Sep 17 00:00:00 2001 From: ric-evans Date: Fri, 18 Oct 2024 15:54:34 -0500 Subject: [PATCH 6/8] flake8 --- rest_tools/server/server.py | 1 + 1 file changed, 1 insertion(+) diff --git a/rest_tools/server/server.py b/rest_tools/server/server.py index 69ec80b5..eb4e217c 100644 --- a/rest_tools/server/server.py +++ b/rest_tools/server/server.py @@ -15,6 +15,7 @@ LOGGER = logging.getLogger() # this stuff always needs to be logged -> use the 'root' logger + def tornado_logger(handler): """Log tornado messages to root logger.""" if handler.get_status() < 400: From 6a5543c9e642fd8792bf2a0bf82a10ab96319cd8 Mon Sep 17 00:00:00 2001 From: ric-evans Date: Fri, 18 Oct 2024 16:11:26 -0500 Subject: [PATCH 7/8] prevent name overrides in decorator magic --- rest_tools/server/decorators.py | 53 ++++++++++++++++++--------------- 1 file changed, 29 insertions(+), 24 deletions(-) diff --git a/rest_tools/server/decorators.py b/rest_tools/server/decorators.py index 8fa56944..13cd79c7 100644 --- a/rest_tools/server/decorators.py +++ b/rest_tools/server/decorators.py @@ -16,6 +16,11 @@ LOGGER = logging.getLogger(__name__) +def _get_logger() -> logging.Logger: + """'LOGGER' is a common name, so it can get overridden during decorator magic.""" + return LOGGER + + ######################################################################################################################## @@ -63,7 +68,7 @@ async def wrapper(self, *args, **kwargs): except tornado.httpclient.HTTPError: raise # tornado can handle this except requests.exceptions.HTTPError as e: - LOGGER.warning('Error in website handler', exc_info=True) + _get_logger().warning('Error in website handler', exc_info=True) try: self.statsd.incr(self.__class__.__name__+'.error') except Exception: @@ -76,7 +81,7 @@ async def wrapper(self, *args, **kwargs): message = 'Error contacting backend in '+self.__class__.__name__ self.send_error(code, reason=message) except Exception: - LOGGER.warning('Error in website handler', exc_info=True) + _get_logger().warning('Error in website handler', exc_info=True) try: self.statsd.incr(self.__class__.__name__+'.error') except Exception: @@ -115,9 +120,9 @@ async def wrapper(self, *args, **kwargs): if roles and auth_role in roles: wtt.set_current_span_attribute('self.auth_data.roles', auth_role) else: - LOGGER.info('roles: %r', roles) - LOGGER.info('token_role: %r', auth_role) - LOGGER.info('role mismatch') + _get_logger().info('roles: %r', roles) + _get_logger().info('token_role: %r', auth_role) + _get_logger().info('role mismatch') raise tornado.web.HTTPError(403, reason="authorization failed") ret = method(self, *args, **kwargs) @@ -165,9 +170,9 @@ async def wrapper(self, *args, **kwargs): authorized = set(roles).intersection(auth_roles) if not authorized: - LOGGER.info('roles: %r', roles) - LOGGER.info('token_roles: %r', auth_roles) - LOGGER.info('role mismatch') + _get_logger().info('roles: %r', roles) + _get_logger().info('token_roles: %r', auth_roles) + _get_logger().info('role mismatch') raise tornado.web.HTTPError(403, reason="authorization failed") wtt.set_current_span_attribute('self.auth_data.roles', ','.join(sorted(authorized))) @@ -213,9 +218,9 @@ async def wrapper(self, *args, **kwargs): authorized = set(roles).intersection(auth_roles) if not authorized: - LOGGER.info('roles: %r', roles) - LOGGER.info('token_roles: %r', auth_roles) - LOGGER.info('role mismatch') + _get_logger().info('roles: %r', roles) + _get_logger().info('token_roles: %r', auth_roles) + _get_logger().info('role mismatch') raise tornado.web.HTTPError(403, reason="authorization failed") wtt.set_current_span_attribute('self.auth_data.roles', ','.join(sorted(authorized))) @@ -306,7 +311,7 @@ def eval_expression(token, e): prefix = prefix[1:] token_val = token.get(name.split('.')[-1], None) - LOGGER.debug('token_val = %r', token_val) + _get_logger().debug('token_val = %r', token_val) if token_val is None: return [] @@ -337,17 +342,17 @@ async def wrapper(self, *args, **kwargs): rolenames = [match.expand(name) for match in ret] authorized_roles.update(role for role in roles if role in rolenames) except Exception as exc: - LOGGER.warning('exception in role auth', exc_info=True) + _get_logger().warning('exception in role auth', exc_info=True) raise tornado.web.HTTPError(500, reason="internal server error") from exc if not authorized_roles: - LOGGER.debug('roles requested: %r', roles) - LOGGER.debug('role mismatch') + _get_logger().debug('roles requested: %r', roles) + _get_logger().debug('role mismatch') raise tornado.web.HTTPError(403, reason="authorization failed") - LOGGER.debug('roles requested: %r', roles) + _get_logger().debug('roles requested: %r', roles) authorized_roles = sorted(authorized_roles) - LOGGER.debug('roles authorized: %r', authorized_roles) + _get_logger().debug('roles authorized: %r', authorized_roles) wtt.set_current_span_attribute('self.auth_data.roles', ','.join(authorized_roles)) self.auth_roles = authorized_roles @@ -358,12 +363,12 @@ async def wrapper(self, *args, **kwargs): ret = eval_expression(self.auth_data, expression) authorized_groups.update(match.expand(name) for match in ret) except Exception as exc: - LOGGER.warning('exception in group auth', exc_info=True) + _get_logger().warning('exception in group auth', exc_info=True) raise tornado.web.HTTPError(500, reason="internal server error") from exc if authorized_groups: authorized_groups = sorted(authorized_groups) - LOGGER.debug('groups authorized: %r', authorized_groups) + _get_logger().debug('groups authorized: %r', authorized_groups) wtt.set_current_span_attribute('self.auth_data.groups', ','.join(authorized_groups)) self.auth_groups = authorized_groups @@ -394,7 +399,7 @@ def validate_request(openapi_spec: "OpenAPI"): def make_wrapper(method): # type: ignore[no-untyped-def] async def wrapper(zelf: tornado.web.RequestHandler, *args, **kwargs): # type: ignore[no-untyped-def] - LOGGER.info("validating with openapi spec") + _get_logger().info("validating with openapi spec") # NOTE - don't change data (unmarshal) b/c we are downstream of data separation try: # https://openapi-core.readthedocs.io/en/latest/validation.html @@ -402,7 +407,7 @@ async def wrapper(zelf: tornado.web.RequestHandler, *args, **kwargs): # type: i _http_server_request_to_openapi_request(zelf.request), ) except ValidationError as e: - LOGGER.error(f"invalid request: {e.__class__.__name__} - {e}") + _get_logger().error(f"invalid request: {e.__class__.__name__} - {e}") if isinstance( # look at the ORIGINAL exception that caused this error e.__context__, openapi_core.validation.schemas.exceptions.InvalidSchemaValue, @@ -416,15 +421,15 @@ async def wrapper(zelf: tornado.web.RequestHandler, *args, **kwargs): # type: i reason = str(e) # to client if os.getenv("CI"): # in prod, don't fill up logs w/ traces from invalid data - LOGGER.exception(e) + _get_logger().exception(e) raise tornado.web.HTTPError( status_code=400, log_message=f"{e.__class__.__name__}: {e}", # to stderr reason=reason, # to client ) except Exception as e: - LOGGER.error(f"unexpected exception: {e.__class__.__name__} - {e}") - LOGGER.exception(e) + _get_logger().error(f"unexpected exception: {e.__class__.__name__} - {e}") + _get_logger().exception(e) raise tornado.web.HTTPError( status_code=400, log_message=f"{e.__class__.__name__}: {e}", # to stderr From c61de1da2da76013277bcefc65bdd419f7103cfb Mon Sep 17 00:00:00 2001 From: ric-evans Date: Fri, 18 Oct 2024 16:19:04 -0500 Subject: [PATCH 8/8] Revert "prevent name overrides in decorator magic" This reverts commit 6a5543c9e642fd8792bf2a0bf82a10ab96319cd8. --- rest_tools/server/decorators.py | 53 +++++++++++++++------------------ 1 file changed, 24 insertions(+), 29 deletions(-) diff --git a/rest_tools/server/decorators.py b/rest_tools/server/decorators.py index 13cd79c7..8fa56944 100644 --- a/rest_tools/server/decorators.py +++ b/rest_tools/server/decorators.py @@ -16,11 +16,6 @@ LOGGER = logging.getLogger(__name__) -def _get_logger() -> logging.Logger: - """'LOGGER' is a common name, so it can get overridden during decorator magic.""" - return LOGGER - - ######################################################################################################################## @@ -68,7 +63,7 @@ async def wrapper(self, *args, **kwargs): except tornado.httpclient.HTTPError: raise # tornado can handle this except requests.exceptions.HTTPError as e: - _get_logger().warning('Error in website handler', exc_info=True) + LOGGER.warning('Error in website handler', exc_info=True) try: self.statsd.incr(self.__class__.__name__+'.error') except Exception: @@ -81,7 +76,7 @@ async def wrapper(self, *args, **kwargs): message = 'Error contacting backend in '+self.__class__.__name__ self.send_error(code, reason=message) except Exception: - _get_logger().warning('Error in website handler', exc_info=True) + LOGGER.warning('Error in website handler', exc_info=True) try: self.statsd.incr(self.__class__.__name__+'.error') except Exception: @@ -120,9 +115,9 @@ async def wrapper(self, *args, **kwargs): if roles and auth_role in roles: wtt.set_current_span_attribute('self.auth_data.roles', auth_role) else: - _get_logger().info('roles: %r', roles) - _get_logger().info('token_role: %r', auth_role) - _get_logger().info('role mismatch') + LOGGER.info('roles: %r', roles) + LOGGER.info('token_role: %r', auth_role) + LOGGER.info('role mismatch') raise tornado.web.HTTPError(403, reason="authorization failed") ret = method(self, *args, **kwargs) @@ -170,9 +165,9 @@ async def wrapper(self, *args, **kwargs): authorized = set(roles).intersection(auth_roles) if not authorized: - _get_logger().info('roles: %r', roles) - _get_logger().info('token_roles: %r', auth_roles) - _get_logger().info('role mismatch') + LOGGER.info('roles: %r', roles) + LOGGER.info('token_roles: %r', auth_roles) + LOGGER.info('role mismatch') raise tornado.web.HTTPError(403, reason="authorization failed") wtt.set_current_span_attribute('self.auth_data.roles', ','.join(sorted(authorized))) @@ -218,9 +213,9 @@ async def wrapper(self, *args, **kwargs): authorized = set(roles).intersection(auth_roles) if not authorized: - _get_logger().info('roles: %r', roles) - _get_logger().info('token_roles: %r', auth_roles) - _get_logger().info('role mismatch') + LOGGER.info('roles: %r', roles) + LOGGER.info('token_roles: %r', auth_roles) + LOGGER.info('role mismatch') raise tornado.web.HTTPError(403, reason="authorization failed") wtt.set_current_span_attribute('self.auth_data.roles', ','.join(sorted(authorized))) @@ -311,7 +306,7 @@ def eval_expression(token, e): prefix = prefix[1:] token_val = token.get(name.split('.')[-1], None) - _get_logger().debug('token_val = %r', token_val) + LOGGER.debug('token_val = %r', token_val) if token_val is None: return [] @@ -342,17 +337,17 @@ async def wrapper(self, *args, **kwargs): rolenames = [match.expand(name) for match in ret] authorized_roles.update(role for role in roles if role in rolenames) except Exception as exc: - _get_logger().warning('exception in role auth', exc_info=True) + LOGGER.warning('exception in role auth', exc_info=True) raise tornado.web.HTTPError(500, reason="internal server error") from exc if not authorized_roles: - _get_logger().debug('roles requested: %r', roles) - _get_logger().debug('role mismatch') + LOGGER.debug('roles requested: %r', roles) + LOGGER.debug('role mismatch') raise tornado.web.HTTPError(403, reason="authorization failed") - _get_logger().debug('roles requested: %r', roles) + LOGGER.debug('roles requested: %r', roles) authorized_roles = sorted(authorized_roles) - _get_logger().debug('roles authorized: %r', authorized_roles) + LOGGER.debug('roles authorized: %r', authorized_roles) wtt.set_current_span_attribute('self.auth_data.roles', ','.join(authorized_roles)) self.auth_roles = authorized_roles @@ -363,12 +358,12 @@ async def wrapper(self, *args, **kwargs): ret = eval_expression(self.auth_data, expression) authorized_groups.update(match.expand(name) for match in ret) except Exception as exc: - _get_logger().warning('exception in group auth', exc_info=True) + LOGGER.warning('exception in group auth', exc_info=True) raise tornado.web.HTTPError(500, reason="internal server error") from exc if authorized_groups: authorized_groups = sorted(authorized_groups) - _get_logger().debug('groups authorized: %r', authorized_groups) + LOGGER.debug('groups authorized: %r', authorized_groups) wtt.set_current_span_attribute('self.auth_data.groups', ','.join(authorized_groups)) self.auth_groups = authorized_groups @@ -399,7 +394,7 @@ def validate_request(openapi_spec: "OpenAPI"): def make_wrapper(method): # type: ignore[no-untyped-def] async def wrapper(zelf: tornado.web.RequestHandler, *args, **kwargs): # type: ignore[no-untyped-def] - _get_logger().info("validating with openapi spec") + LOGGER.info("validating with openapi spec") # NOTE - don't change data (unmarshal) b/c we are downstream of data separation try: # https://openapi-core.readthedocs.io/en/latest/validation.html @@ -407,7 +402,7 @@ async def wrapper(zelf: tornado.web.RequestHandler, *args, **kwargs): # type: i _http_server_request_to_openapi_request(zelf.request), ) except ValidationError as e: - _get_logger().error(f"invalid request: {e.__class__.__name__} - {e}") + LOGGER.error(f"invalid request: {e.__class__.__name__} - {e}") if isinstance( # look at the ORIGINAL exception that caused this error e.__context__, openapi_core.validation.schemas.exceptions.InvalidSchemaValue, @@ -421,15 +416,15 @@ async def wrapper(zelf: tornado.web.RequestHandler, *args, **kwargs): # type: i reason = str(e) # to client if os.getenv("CI"): # in prod, don't fill up logs w/ traces from invalid data - _get_logger().exception(e) + LOGGER.exception(e) raise tornado.web.HTTPError( status_code=400, log_message=f"{e.__class__.__name__}: {e}", # to stderr reason=reason, # to client ) except Exception as e: - _get_logger().error(f"unexpected exception: {e.__class__.__name__} - {e}") - _get_logger().exception(e) + LOGGER.error(f"unexpected exception: {e.__class__.__name__} - {e}") + LOGGER.exception(e) raise tornado.web.HTTPError( status_code=400, log_message=f"{e.__class__.__name__}: {e}", # to stderr