server logging

Author: DevAlone

config_examples/proxy_py.nginx.conf

@@ -4,5 +4,6 @@ server {
 
         location / {
                 proxy_pass http://127.0.0.1:55555;
+                proxy_set_header X-Real-IP $remote_addr;
         }
 }

server/api_v1/api_request_handler.py

@@ -1,15 +1,18 @@
+import aiohttp
+
+from server.base_app import BaseApp
 from .requests_to_models.request_parser import RequestParser, ParseError
 from .requests_to_models.request_executor import RequestExecutor, ExecutionError
 from proxy_py import settings
 
 
 class ApiRequestHandler:
-    def __init__(self, logger):
+    def __init__(self, app: BaseApp):
         self.request_parser = RequestParser(settings.PROXY_PROVIDER_SERVER_API_CONFIG)
         self.request_executor = RequestExecutor()
-        self._logger = logger
+        self.app = app
 
-    async def handle(self, client_address: tuple, post_data: dict):
+    async def handle(self, request: aiohttp.ClientRequest, post_data: dict):
         try:
             req_dict = self.request_parser.parse(post_data)
 
@@ -18,9 +21,9 @@ async def handle(self, client_address: tuple, post_data: dict):
             }
             response.update(await self.request_executor.execute(req_dict))
         except ParseError as ex:
-            self._logger.warning(
-                "Error during parsing request. \nClient: {} \nRequest: {} \nException: {}".format(
-                    client_address,
+            self.app.log_info(
+                request,
+                "Error during parsing request. Request: {} Exception: {}".format(
                     post_data,
                     ex
                 )
@@ -32,11 +35,12 @@ async def handle(self, client_address: tuple, post_data: dict):
                 'error_message': str(ex)
             }
         except ExecutionError as ex:
-            self._logger.warning(
-                "Error during execution request. \nClient: {} \nRequest: {} \nException: {}".format(
-                    client_address,
+            self.app.log_error(
+                request,
+                "Error during execution request. Request: {} Exception: {}".format(
                     post_data,
-                    ex)
+                    ex
+                )
             )
 
             response = {

server/api_v1/app.py

@@ -10,7 +10,7 @@ class App(BaseApp):
     def __init__(self, *args, **kwargs):
         super(App, self).__init__(*args, **kwargs)
 
-        self.request_handler = ApiRequestHandler(self.logger)
+        self.request_handler = ApiRequestHandler(self)
 
     async def setup_router(self):
         self.app.router.add_post('/', self.post)
@@ -32,7 +32,7 @@ async def post(self, request):
         try:
             data = json.loads(data.decode())
 
-            response = await self.request_handler.handle(client_address, data)
+            response = await self.request_handler.handle(request, data)
         except ValueError:
             response = {
                 'status': 'error',

server/api_v1/requests_to_models/request_parser.py

@@ -11,6 +11,9 @@ class RequestParser:
     ALLOWED_KEYS = {'model', 'method', 'fields', 'filter', 'order_by', 'limit', 'offset'}
     MAXIMUM_KEY_LENGTH = 64
     MAXIMUM_VALUE_LENGTH = 512
+    # TODO: move to settings
+    MINIMUM_LIMIT_VALUE = 1
+    MAXIMUM_LIMIT_VALUE = 1024
 
     def __init__(self, config):
         self.config = config
@@ -31,6 +34,9 @@ def parse(self, request: dict):
 
             self.validate_value(key, request[key])
 
+        if 'limit' not in request:
+            request['limit'] = self.MAXIMUM_LIMIT_VALUE
+
         return self.parse_dict(request)
 
     def validate_value(self, key: str, value):
@@ -60,6 +66,13 @@ def validate_value(self, key: str, value):
             self._validate_value_type(key, value, int)
             if value < 0:
                 raise ValidationError('Value of key "{}" should be positive'.format(key))
+
+            if key == 'limit' and (value < self.MINIMUM_LIMIT_VALUE or value > self.MAXIMUM_LIMIT_VALUE):
+                raise ValidationError(
+                    'Value of key limit should be from {} to {} (inclusive)'.format(
+                        self.MINIMUM_LIMIT_VALUE, self.MAXIMUM_LIMIT_VALUE
+                    )
+                )
         else:
             # It means I forget to add validation of field
             raise ValidationError('Server Error')

server/base_app.py

@@ -8,6 +8,7 @@
 import aiohttp
 import aiohttp_jinja2
 import jinja2
+import inspect
 
 
 class BaseApp:
@@ -34,3 +35,32 @@ async def setup_middlewares(self):
     @property
     def app(self):
         return self._app
+
+    def log_critical(self, *args, **kwargs):
+        self.log('critical', *args, **kwargs)
+
+    def log_error(self, *args, **kwargs):
+        self.log('error', *args, **kwargs)
+
+    def log_warning(self, *args, **kwargs):
+        self.log('warning', *args, **kwargs)
+
+    def log_info(self, *args, **kwargs):
+        self.log('info', *args, **kwargs)
+
+    def log_debug(self, *args, **kwargs):
+        self.log('debug', *args, **kwargs)
+
+    def log(self, level, request, message):
+        if settings.DEBUG:
+            client_host, client_port = request.transport.get_extra_info("peername")
+            client_ip = "{}:{}".format(client_host, client_port)
+        else:
+            # behind nginx or other reverse proxy
+            client_ip = str(request.headers.get('X-Real-IP', None))
+            if client_ip is None:
+                self.logger.error("Your reverse proxy doesn't present user's IP")
+
+        getattr(self.logger, level)(message, extra={
+            "client_ip": client_ip,
+        })

server/proxy_provider_server.py

@@ -1,3 +1,5 @@
+import json
+
 from proxy_py import settings
 from .base_app import BaseApp
 from .api_v1.app import App as ApiV1App
@@ -6,36 +8,32 @@
 
 import logging
 import aiohttp
-import jinja2
 import aiohttp_jinja2
 
 
-# TODO: refactor it
-_proxy_provider_server = None
-_logger = logging.getLogger('proxy_py/server')
-_logger.setLevel(logging.DEBUG)
-debug_file_handler = logging.FileHandler('logs/server.debug.log')
-debug_file_handler.setLevel(logging.DEBUG)
-error_file_handler = logging.FileHandler('logs/server.error.log')
-error_file_handler.setLevel(logging.ERROR)
-error_file_handler = logging.FileHandler('logs/server.warning.log')
-error_file_handler.setLevel(logging.WARNING)
-info_file_handler = logging.FileHandler('logs/server.log')
-info_file_handler.setLevel(logging.INFO)
+class ProxyProviderServer(BaseApp):
+    def __init__(self, host, port, processor):
+        logger = logging.getLogger("proxy_py/server")
 
-_logger.addHandler(debug_file_handler)
-_logger.addHandler(error_file_handler)
-_logger.addHandler(info_file_handler)
+        if settings.DEBUG:
+            logger.setLevel(logging.DEBUG)
+        else:
+            logger.setLevel(logging.INFO)
 
+        logger_file_handler = logging.FileHandler("logs/server.log")
+        logger_file_handler.setLevel(logging.DEBUG)
+        logger_file_handler.setFormatter(logging.Formatter(
+            "%(levelname)s ~ %(asctime)s ~ %(client_ip)s ~ %(message)s"
+        ))
 
-class ProxyProviderServer(BaseApp):
-    def __init__(self, host, port, processor):
+        logger.addHandler(logger_file_handler)
 
-        super(ProxyProviderServer, self).__init__(_logger)
+        super(ProxyProviderServer, self).__init__(logger)
 
         self._processor = processor
         self.host = host
         self.port = port
+        self._request_number = 0
 
     async def start(self, loop):
         await self.init()
@@ -63,10 +61,47 @@ async def setup_middlewares(self):
             500: self.handle_500,
         })
 
-        self._app.middlewares.append(error_middleware)
+        self.app.middlewares.append(error_middleware)
+        self.app.middlewares.append(self.logging_middleware)
+
+    @web.middleware
+    async def logging_middleware(self, request: aiohttp.ClientRequest, handler):
+        self._request_number += 1
+
+        current_request_number = self._request_number
+
+        request_data = {
+            "request_number": current_request_number,
+            "method": request.method,
+            "url": str(request.url),
+            "user-agent": request.headers.get("User-Agent", None),
+        }
+
+        if request.body_exists:
+            request_data["body"] = (await request.read()).decode()
+
+        self.log_info(request, "-> data={}".format(json.dumps(request_data)))
+
+        status_code = None
+
+        try:
+            response = await handler(request)
+            status_code = response.status
+        except web.web_exceptions.HTTPException as ex:
+            status_code = ex.status
+            raise ex
+        except BaseException as ex:
+            raise ex
+        finally:
+            self.log_info(request, "<- data={}".format(json.dumps({
+                "request_number": current_request_number,
+                "status_code": status_code,
+            })))
+
+        return response
 
     def error_pages_handler(self, overrides):
-        @aiohttp.web.middleware
+        @web.middleware
         async def middleware(request, handler):
             try:
                 response = await handler(request)