diff --git a/rest_tools/server/handler.py b/rest_tools/server/handler.py index 7944878a..7c622b78 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): @@ -162,13 +162,19 @@ 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] 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() diff --git a/rest_tools/server/server.py b/rest_tools/server/server.py index 035241c3..eb4e217c 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,17 @@ 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.info 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 +59,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)