Add logging

common/logger.py

@@ -6,20 +6,26 @@
 
 
 class ThoasLogging:
-    def __init__(self, logging_file, logger_name="generic_logging"):
+    def __init__(self, logging_file=None, logger_name="generic_logging"):
 
         self.logger_name = logger_name
         self.logging_file = logging_file
-        self.logging_handler = logging.FileHandler(self.logging_file)
-
+        formatter = logging.Formatter(
+            "%(asctime)s %(name)-12s %(levelname)-8s %(message)s"
+        )
         logger = logging.getLogger(self.logger_name)
-        logger.addHandler(self.logging_handler)
 
-        # Set generic format
-        formatter = logging.Formatter("*****\n%(levelname)s \n%(message)s \n*****")
+        # uncomment these lines if you want to store the logs in .log file
+        # self.file_handler = logging.FileHandler(self.logging_file)
+        # self.file_handler.setFormatter(formatter)
+        # logger.addHandler(self.file_handler)
 
-        self.logging_handler.setFormatter(formatter)
-        self.logging_handler.setLevel(logging.INFO)
+        # print the logs out in the stdout
+        self.console_handler = logging.StreamHandler()
+
+        # Set generic format
+        self.console_handler.setFormatter(formatter)
+        logger.addHandler(self.console_handler)
 
     def url_logger(self, **kwargs):
 
@@ -47,6 +53,32 @@ def some_other_logger(self, message):
         self.logging_handler.setFormatter(formatter)
         logger.warning(message)
 
+    def log_client_info(self, log_scope):
+        """
+        Logs everything we would like to capture during the query execution
+            * HTTP code and message (TODO)
+            * Client IP address
+            * Referer and user-agent
+            * Method (POST, GET..)
+        log_scope: is and 'info.context['request'].scope' where all the info
+        mentioned above (and more!) are stored
+        """
+        method = log_scope.get("method")
+        # turn {"client": ("127.0.0.1", 58017)} to "127.0.0.1:58017"
+        client_ip_address = ":".join(map(str, log_scope["client"]))
+        user_agent = log_scope["headers"][1][1].decode().split("/")[0]
+        # referer may not exist, I'll keep it commented for now
+        # referer = log_scope["headers"][5][1].decode()
+
+        logger = logging.getLogger(self.logger_name)
+        logger.setLevel(logging.DEBUG)
+        logger.debug(
+            f"Client_IP: {client_ip_address} "
+            f"- Method: {method} "
+            f"- User_Agent: {user_agent} "
+            # f"- Referer: {referer}"
+        )
+
 
 class CommandLogger(monitoring.CommandListener):
     """Logger for MongoDB transactions"""
@@ -70,18 +102,18 @@ def started(self, event):
 
     def succeeded(self, event):
         self.log.debug(
-            "[Request id: %s] Command %s on server %s succeeded in %s microseconds",
+            "[Request id: %s] Command %s on server %s succeeded in %s milliseconds",
             event.request_id,
             event.command_name,
             event.connection_id,
-            event.duration_micros,
+            round(event.duration_micros / 1000000, 5),
         )
 
     def failed(self, event):
         self.log.debug(
-            "[Request id: %s] Command %s on server %s failed in %s microseconds",
+            "[Request id: %s] Command %s on server %s failed in %s milliseconds",
             event.request_id,
             event.command_name,
             event.connection_id,
-            event.duration_micros,
+            round(event.duration_micros / 1000000, 5),
         )

graphql_service/resolver/gene_model.py

@@ -17,6 +17,7 @@
 from ariadne import QueryType, ObjectType
 from graphql import GraphQLResolveInfo
 
+from common.logger import ThoasLogging
 from graphql_service.resolver.exceptions import (
     GeneNotFoundError,
     TranscriptNotFoundError,
@@ -86,6 +87,11 @@ def resolve_gene(
     result = collection.find_one(query)
     if not result:
         raise GeneNotFoundError(by_id=by_id)
+
+    if "request" in info.context:
+        logger = ThoasLogging(logger_name="client_info_logger")
+        logger.log_client_info(info.context["request"].scope)
+
     return result
 
 

graphql_service/resolver/tests/test_resolvers.py

@@ -24,11 +24,21 @@
 
 def create_info(collection):
     """
-    Factory for creating the mock  Info objects produced by graphql
+    Factory for creating the mock Info objects produced by graphql
     """
     info = Mock()
     request_mock = Mock()
-    request_mock.state = State()
+    request_mock.scope = {
+        "client": ("127.0.0.1", 58017),
+        "headers": [
+            (b"host", b"0.0.0.0:8000"),
+            (
+                b"user-agent",
+                b"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:109.0) Gecko/20100101 Firefox/112.0",
+            ),
+            (b"referer", b"http://0.0.0.0:8000/"),
+        ],
+    }
     info.context = {
         "stuff": "Nonsense",
         "mongo_db": collection,

graphql_service/server.py

@@ -48,17 +48,26 @@
 # Including the execution time in the response
 EXTENSIONS = [QueryExecutionTimeExtension]
 
+
+log = logging.getLogger("command_logger")
+
 if DEBUG_MODE:
-    log = logging.getLogger()
     log.setLevel(logging.DEBUG)
     logging.basicConfig(level=logging.DEBUG)
 
-    monitoring.register(CommandLogger(log))
-
     # Apollo Tracing extension will display information about which resolvers are used and their duration
     # https://ariadnegraphql.org/docs/apollo-tracing
     EXTENSIONS.append(ApolloTracingExtension)
 
+MONGO_CLIENT = db.MongoDbClient(os.environ)
+# Experimenting with query logging with debug mode off
+log.setLevel(logging.DEBUG)
+logging.basicConfig(
+    level=logging.DEBUG, format="%(asctime)s %(name)-12s %(levelname)-8s %(message)s"
+)
+
+monitoring.register(CommandLogger(log))
+
 MONGO_CLIENT = db.MongoDbClient(os.environ)
 
 GRPC_SERVER = db.GRPCServiceClient(os.environ)
@@ -151,7 +160,7 @@ def __init__(
         explorer_plugin: bool = True,
         default_query: str = DEFAULT_QUERY,
     ):
-        super(CustomExplorerGraphiQL, self).__init__()
+        super().__init__()
         self.parsed_html = render_template(
             CUSTOM_GRAPHIQL_HTML,
             {