Merge pull request #124 from python-ellar/request_logging_debug

Added some log debug

Author: eadwinCode

.coveragerc

@@ -5,6 +5,7 @@ exclude_lines =
     def __str__
     if self.debug:
     if settings.DEBUG
+    if t.TYPE_CHECKING
     raise AssertionError
     raise NotImplementedError
     if 0:

ellar/common/constants.py

@@ -128,7 +128,7 @@ def __deepcopy__(
 
 NOT_SET: Any = NOT_SET_TYPE()
 
-
+ELLAR_LOG_FMT_STRING = "%(levelname)s: [%(name)s] %(message)s"
 DEFAULT_LOGGING = {
     "version": 1,
     "disable_existing_loggers": False,
@@ -142,6 +142,10 @@ def __deepcopy__(
             "()": "uvicorn.logging.AccessFormatter",
             "fmt": '%(levelprefix)s %(client_addr)s - "%(request_line)s" %(status_code)s',
         },
+        "ellar-formatter": {
+            "()": "logging.Formatter",
+            "fmt": ELLAR_LOG_FMT_STRING,
+        },
     },
     "handlers": {
         "default": {
@@ -154,6 +158,11 @@ def __deepcopy__(
             "class": "logging.StreamHandler",
             "stream": "ext://sys.stdout",
         },
+        "ellar-default": {
+            "formatter": "ellar-formatter",
+            "class": "logging.StreamHandler",
+            "stream": "ext://sys.stdout",
+        },
         "console": {
             "class": "logging.StreamHandler",
         },
@@ -163,7 +172,12 @@ def __deepcopy__(
         "uvicorn.error": {"level": "INFO"},
         "uvicorn.access": {"handlers": ["access"], "level": "INFO", "propagate": False},
         "ellar": {
-            "handlers": ["default"],
+            "handlers": ["ellar-default"],
+            "level": "INFO",
+            "propagate": False,
+        },
+        "ellar.request": {
+            "handlers": ["ellar-default"],
             "level": "INFO",
             "propagate": False,
         },

ellar/common/decorators/controller.py

@@ -16,6 +16,7 @@
 from ellar.common.logger import logger
 from ellar.common.models import ControllerBase, ControllerType
 from ellar.di import RequestScope, injectable
+from ellar.di.scopes import DIScope
 from ellar.reflect import REFLECT_TYPE, reflect
 
 from ..routing.controller import (
@@ -76,6 +77,7 @@ def Controller(
     *,
     name: t.Optional[str] = None,
     include_in_schema: bool = True,
+    scope: t.Optional[t.Union[t.Type[DIScope], DIScope]] = RequestScope,
 ) -> t.Union[t.Type[ControllerBase], t.Callable[..., t.Any], t.Any]:
     """
     ========= CLASS DECORATOR ==============
@@ -84,6 +86,7 @@ def Controller(
     :param prefix: Route Prefix default=[ControllerName]
     :param name: route name prefix for url reversing, eg name:route_name default=''
     :param include_in_schema: include controller in OPENAPI schema
+    :param scope: Controller Instance Lifetime scope
     :return: t.Type[ControllerBase]
     """
     _prefix: t.Optional[t.Any] = prefix if prefix is not None else NOT_SET
@@ -134,7 +137,8 @@ def _decorator(cls: t.Type) -> t.Type[ControllerBase]:
         ) and not hasattr(cls, "__CONTROLLER_WATERMARK__"):
             reflect.define_metadata(CONTROLLER_WATERMARK, True, _controller_type)
             reflect_all_controller_type_routes(_controller_type)
-            injectable(RequestScope)(cls)
+
+            injectable(scope or RequestScope)(cls)
 
             for key in CONTROLLER_METADATA.keys:
                 reflect.define_metadata(key, kwargs[key], _controller_type)

ellar/common/logger.py

@@ -1,3 +1,4 @@
 import logging
 
 logger = logging.getLogger("ellar")
+request_logger = logging.getLogger("ellar.request")

ellar/common/params/args/resolver_generators.py

@@ -16,7 +16,7 @@
 
 class BulkArgsResolverGenerator:
     """
-    This class splits Schema into different ModelFields to he resolved independently and computed back later.
+    This class splits Schema into different ModelFields to be resolved independently and computed back later.
     class ASchema(BaseModel):
         A: int
         B: int

ellar/common/params/resolvers/bulk_parameter.py

@@ -1,6 +1,7 @@
 import typing as t
 
 from ellar.common.interfaces import IExecutionContext
+from ellar.common.logger import request_logger
 from pydantic.error_wrappers import ErrorWrapper
 from pydantic.fields import ModelField
 
@@ -28,6 +29,9 @@ def get_model_fields(self) -> t.List[ModelField]:
     async def resolve_handle(
         self, ctx: IExecutionContext, *args: t.Any, **kwargs: t.Any
     ) -> t.Tuple:
+        request_logger.debug(
+            f"Resolving Bulk Path Parameters - '{self.__class__.__name__}'"
+        )
         values: t.Dict[str, t.Any] = {}
         errors: t.List[ErrorWrapper] = []
 
@@ -67,6 +71,9 @@ def __init__(self, *args: t.Any, is_grouped: bool = False, **kwargs: t.Any):
     async def resolve_grouped_fields(
         self, ctx: IExecutionContext, body: t.Any
     ) -> t.Tuple:
+        request_logger.debug(
+            f"Resolving Form Grouped Field - '{self.__class__.__name__}'"
+        )
         value, resolver_errors = await self._get_resolver_data(ctx, body)
         if resolver_errors:
             return value, resolver_errors
@@ -100,6 +107,7 @@ async def _get_resolver_data(self, ctx: IExecutionContext, body: t.Any) -> t.Tup
     async def resolve_handle(
         self, ctx: IExecutionContext, *args: t.Any, **kwargs: t.Any
     ) -> t.Tuple:
+        request_logger.debug(f"Resolving Form Parameters - '{self.__class__.__name__}'")
         _body = await self.get_request_body(ctx)
         if self._resolvers:
             return await self._use_resolver(ctx, _body)
@@ -112,6 +120,9 @@ class BulkBodyParameterResolver(BodyParameterResolver, BulkParameterResolver):
     async def resolve_handle(
         self, ctx: IExecutionContext, *args: t.Any, **kwargs: t.Any
     ) -> t.Tuple:
+        request_logger.debug(
+            f"Resolving Request Body Parameters - '{self.__class__.__name__}'"
+        )
         _body = await self.get_request_body(ctx)
         values, errors = await super(BulkBodyParameterResolver, self).resolve_handle(
             ctx, *args, body=_body, **kwargs

ellar/common/params/resolvers/non_parameter/base.py

@@ -2,7 +2,7 @@
 from abc import ABC, abstractmethod
 
 from ellar.common.interfaces import IExecutionContext
-from ellar.common.logger import logger
+from ellar.common.logger import request_logger
 from ellar.common.types import T
 from pydantic.error_wrappers import ErrorWrapper
 
@@ -73,7 +73,7 @@ async def resolve(
             value = await self.get_value(ctx)
             return {self.parameter_name: value}, []
         except Exception as ex:
-            logger.error(
+            request_logger.error(
                 f"Unable to resolve `{self.lookup_connection_field}` in connection \nErrorMessage: {ex}"
             )
             return {}, [ErrorWrapper(ex, loc=str(self.parameter_name))]

ellar/common/params/resolvers/parameter.py

@@ -12,6 +12,7 @@
 from ellar.common.datastructures import UploadFile
 from ellar.common.exceptions import RequestValidationError
 from ellar.common.interfaces import IExecutionContext
+from ellar.common.logger import request_logger
 from pydantic.error_wrappers import ErrorWrapper
 from pydantic.fields import Undefined
 from pydantic.utils import lenient_issubclass
@@ -32,6 +33,9 @@ def get_received_parameter(
     async def resolve_handle(
         self, ctx: IExecutionContext, *args: t.Any, **kwargs: t.Any
     ) -> t.Tuple:
+        request_logger.debug(
+            f"Resolving Header Parameters - '{self.__class__.__name__}'"
+        )
         received_params = self.get_received_parameter(ctx=ctx)
         if (
             self.model_field.shape in sequence_shapes
@@ -80,6 +84,7 @@ def get_received_parameter(cls, ctx: IExecutionContext) -> t.Mapping[str, t.Any]
         return connection.path_params
 
     async def resolve_handle(self, ctx: IExecutionContext, **kwargs: t.Any) -> t.Tuple:
+        request_logger.debug(f"Resolving Path Parameters - '{self.__class__.__name__}'")
         received_params = self.get_received_parameter(ctx=ctx)
         value = received_params.get(str(self.model_field.alias))
         self.assert_field_info()
@@ -103,6 +108,9 @@ class WsBodyParameterResolver(BaseRouteParameterResolver):
     async def resolve_handle(
         self, ctx: IExecutionContext, *args: t.Any, body: t.Any, **kwargs: t.Any
     ) -> t.Tuple:
+        request_logger.debug(
+            f"Resolving Websocket Body Parameters - '{self.__class__.__name__}'"
+        )
         embed = getattr(self.model_field.field_info, "embed", False)
         received_body = {self.model_field.alias: body}
         loc = ("body",)
@@ -123,6 +131,9 @@ def __init__(self, *args: t.Any, **kwargs: t.Any):
         super().__init__(*args, **kwargs)
 
     async def get_request_body(self, ctx: IExecutionContext) -> t.Any:
+        request_logger.debug(
+            f"Resolving Request Body Parameters - '{self.__class__.__name__}'"
+        )
         try:
             request = ctx.switch_to_http_connection().get_request()
             body_bytes = await request.body()
@@ -142,8 +153,10 @@ async def get_request_body(self, ctx: IExecutionContext) -> t.Any:
                     body_bytes = json_body
             return body_bytes
         except json.JSONDecodeError as e:
+            request_logger.error("JSONDecodeError: ", exc_info=True)
             raise RequestValidationError([ErrorWrapper(e, ("body", e.pos))]) from e
-        except Exception as e:  # pragma: no cover
+        except Exception as e:
+            request_logger.error("Unable to parse the body: ", exc_info=e)
             raise HTTPException(
                 status_code=400, detail="There was an error parsing the body"
             ) from e
@@ -170,11 +183,15 @@ async def process_and_validate(
         return values, errors_
 
     async def get_request_body(self, ctx: IExecutionContext) -> t.Any:
+        request_logger.debug(
+            f"Resolving Request Form Parameters - '{self.__class__.__name__}'"
+        )
         try:
             request = ctx.switch_to_http_connection().get_request()
             body_bytes = await request.form()
             return body_bytes
         except Exception as e:
+            request_logger.error("Unable to parse the body: ", exc_info=True)
             raise HTTPException(
                 status_code=400, detail="There was an error parsing the body"
             ) from e

ellar/common/responses/models/base.py

@@ -5,6 +5,7 @@
 from ellar.common.exceptions import RequestValidationError
 from ellar.common.helper.modelfield import create_model_field
 from ellar.common.interfaces import IExecutionContext, IResponseModel
+from ellar.common.logger import request_logger
 from ellar.common.serializer import SerializerFilter, serialize_object
 from ellar.reflect import reflect
 from pydantic import BaseModel
@@ -25,7 +26,21 @@ def serialize_if_pydantic_object(obj: t.Any) -> t.Any:
 
 
 class ResponseModelField(ModelField):
+    """
+    A representation of response schema defined in route function
+
+        @get('/', response={200: ASchema, 404: ErrorSchema})
+        def example():
+            pass
+
+    During module building, `ASchema` and `ErrorSchema` will be converted to ResponseModelField
+    types for the of validation and OPENAPI documentation
+    """
+
     def validate_object(self, obj: t.Any) -> t.Any:
+        request_logger.debug(
+            f"Validating Response Object - '{self.__class__.__name__}'"
+        )
         values, error = self.validate(obj, {}, loc=(self.alias,))
         if error:
             _errors = list(error) if isinstance(error, list) else [error]
@@ -35,6 +50,7 @@ def validate_object(self, obj: t.Any) -> t.Any:
     def serialize(
         self, obj: t.Any, serializer_filter: t.Optional[SerializerFilter] = None
     ) -> t.Union[t.List[t.Dict], t.Dict, t.Any]:
+        request_logger.debug(f"Serializing Response Data - '{self.__class__.__name__}'")
         try:
             values = self.validate_object(obj=obj)
         except RequestValidationError:
@@ -47,6 +63,21 @@ def serialize(
 
 
 class BaseResponseModel(IResponseModel, ABC):
+    """
+    A base model representation of endpoint response. It provides essential information about a response type, just as
+    it is defined on the endpoint, the status code and schema plus description for OPENAPI documentation.
+
+    For example:
+
+        @get('/', response={200: ASchema, 404: ErrorSchema})
+        def example():
+            pass
+
+    From the Above example, two response models will be generated.
+    - response model for 200 status and ASchema and
+    - response model for 400 status and ErrorSchema
+    """
+
     __slots__ = (
         "_response_type",
         "_media_type",
@@ -121,7 +152,10 @@ def serialize(
     def create_response(
         self, context: IExecutionContext, response_obj: t.Any, status_code: int
     ) -> Response:
-        """Cant create custom responses, Please override this function to create a custom response"""
+        """Please override this function to create a custom response"""
+        request_logger.debug(
+            f"Creating Response from returned Handler value - '{self.__class__.__name__}'"
+        )
         response_args, headers = self.get_context_response(
             context=context, status_code=status_code
         )
@@ -154,6 +188,16 @@ def get_context_response(
 
 
 class ResponseModel(BaseResponseModel):
+    """
+    Handles endpoint models with Response Type as schema
+
+        from starlette.responses import PlainTextResponse
+
+        @get('/', response={200: PlainTextResponse})
+        def example():
+            pass
+    """
+
     def serialize(
         self,
         response_obj: t.Any,

ellar/common/responses/models/file.py

@@ -2,6 +2,7 @@
 from enum import Enum
 
 from ellar.common.interfaces import IExecutionContext
+from ellar.common.logger import request_logger
 from ellar.common.serializer import Serializer, SerializerFilter, serialize_object
 
 from ..response_types import FileResponse, Response, StreamingResponse
@@ -40,6 +41,9 @@ def __init__(self, *args: t.Any, **kwargs: t.Any) -> None:
     def create_response(
         self, context: IExecutionContext, response_obj: t.Any, status_code: int
     ) -> Response:
+        request_logger.debug(
+            f"Creating Response from returned Handler value - '{self.__class__.__name__}'"
+        )
         response_args, headers = self.get_context_response(
             context=context, status_code=status_code
         )
@@ -82,6 +86,10 @@ def get_model_field(self) -> t.Optional[t.Union[ResponseModelField, t.Any]]:
     def create_response(
         self, context: IExecutionContext, response_obj: t.Any, status_code: int
     ) -> Response:
+        request_logger.debug(
+            f"Creating Response from returned Handler value - '{self.__class__.__name__}'"
+        )
+
         response_args, headers = self.get_context_response(
             context=context, status_code=status_code
         )