diff --git a/common/logger.py b/common/logger.py index cb9286ce..19f078eb 100644 --- a/common/logger.py +++ b/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), ) diff --git a/graphql_service/resolver/gene_model.py b/graphql_service/resolver/gene_model.py index 1439c564..b1f1f9c3 100644 --- a/graphql_service/resolver/gene_model.py +++ b/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 diff --git a/graphql_service/resolver/tests/test_resolvers.py b/graphql_service/resolver/tests/test_resolvers.py index 43f6667b..f437d11e 100644 --- a/graphql_service/resolver/tests/test_resolvers.py +++ b/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, diff --git a/graphql_service/server.py b/graphql_service/server.py index df003702..c51aac12 100644 --- a/graphql_service/server.py +++ b/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, {