From a0227a42a78a61d886748a1c618a90b06ef84791 Mon Sep 17 00:00:00 2001 From: 573dev <> Date: Wed, 14 Oct 2020 22:47:35 -0500 Subject: [PATCH] Add some logging action --- TODO.txt | 3 +- v8_server/__init__.py | 83 ++++++++++++++++++++++++++++++++++++++++- v8_server/utils/xml.py | 30 +++++++-------- v8_server/view/index.py | 32 ++++++++++------ 4 files changed, 119 insertions(+), 29 deletions(-) diff --git a/TODO.txt b/TODO.txt index fb7d673..bb2e045 100644 --- a/TODO.txt +++ b/TODO.txt @@ -1 +1,2 @@ -- Implement proper logging (is there some sort of flask logging, or should I just log to a file?) +- Logging is implemented, so lets throw some logs around perhaps +- Fix the issue where the log directory probably shouldn't be a relative path diff --git a/v8_server/__init__.py b/v8_server/__init__.py index 7b116af..2f39f81 100644 --- a/v8_server/__init__.py +++ b/v8_server/__init__.py @@ -1,8 +1,10 @@ +import logging import os +from logging.config import dictConfig from pathlib import Path from typing import Optional, Union -from flask import Flask +from flask import Flask, has_request_context, request from v8_server.config import Development, Production from v8_server.utils.flask import generate_secret_key @@ -10,6 +12,85 @@ from v8_server.utils.flask import generate_secret_key from .version import __version__ +class RequestFormatter(logging.Formatter): + def format(self, record): + encrypted = "None" + compressed = "None" + method = None + + if has_request_context(): + method = request.method + headers = request.headers + + if "x-eamuse-info" in headers: + encrypted = headers["x-eamuse-info"] + if "x-compress" in headers: + compressed = headers["x-compress"] + + record.encrypted = encrypted + record.compressed = "None" if compressed == "none" else compressed + record.method = method + + return super().format(record) + + +# Define the logger +dictConfig( + { + "version": 1, + "formatters": { + "default": { + "format": "[ %(asctime)s | %(levelname)-8s | %(name)s ]\n%(message)s" + }, + "detailed": { + "()": RequestFormatter, + "format": ( + "[ %(asctime)s | %(levelname)-8s | %(method)-4s | %(encrypted)-15s " + "| %(compressed)-4s | %(name)s ]\n%(message)s" + ), + }, + }, + "handlers": { + "wsgi": { + "class": "logging.StreamHandler", + "stream": "ext://flask.logging.wsgi_errors_stream", + "formatter": "default", + }, + "debugfile": { + "class": "logging.handlers.TimedRotatingFileHandler", + "filename": "logs/debug.log", + "formatter": "default", + "when": "midnight", + }, + "requestsfile": { + "class": "logging.handlers.TimedRotatingFileHandler", + "filename": "logs/requests.log", + "formatter": "detailed", + "when": "midnight", + }, + "allfile": { + "class": "logging.handlers.TimedRotatingFileHandler", + "filename": "logs/all.log", + "formatter": "detailed", + "when": "midnight", + }, + "werkzeugfile": { + "class": "logging.handlers.TimedRotatingFileHandler", + "filename": "logs/werkzeug.log", + "formatter": "detailed", + "when": "midnight", + }, + }, + "loggers": { + "": {"handlers": ["wsgi", "allfile"]}, + "v8_server": {"level": "DEBUG", "handlers": ["debugfile"]}, + "requests": {"level": "DEBUG", "handlers": ["requestsfile"]}, + "werkzeug": {"level": "DEBUG", "handlers": ["werkzeugfile"]}, + }, + } +) +logging.getLogger("").setLevel(logging.INFO) + # Set the proper config values config: Optional[Union[Production, Development]] = None if os.environ.get("ENV", "dev") == "prod": diff --git a/v8_server/utils/xml.py b/v8_server/utils/xml.py index 8022ece..11c4a67 100644 --- a/v8_server/utils/xml.py +++ b/v8_server/utils/xml.py @@ -1,3 +1,4 @@ +import logging from binascii import unhexlify from pathlib import Path from random import randint @@ -14,6 +15,9 @@ from v8_server.utils.eamuse import get_timestamp from v8_server.utils.lz77 import Lz77 +logger = logging.getLogger(__name__) +rlogger = logging.getLogger("requests") + EAMUSE_CONFIG = {"encrypted": False, "compressed": False} REQUESTS_PATH = Path("./requests") @@ -52,19 +56,15 @@ def eamuse_read_xml(request: Request) -> Tuple[str, str, str, str, str]: with output_filename.open("w") as f: f.write(xml_text.decode("UTF-8")) - model = root.attrib["model"] - module = root[0].tag - method = root[0].attrib["method"] if "method" in root[0].attrib else None - command = root[0].attrib["command"] if "command" in root[0].attrib else None + model = str(root.attrib["model"]) + module = str(root[0].tag) + method = str(root[0].attrib["method"] if "method" in root[0].attrib else None) + command = str(root[0].attrib["command"] if "command" in root[0].attrib else None) - print( - "---- Read Request ----\n" - f"Headers: [{dict(headers)}]\n" - f" Model: [{model}]\n" - f" Module: [{module}]\n" - f" Method: [{method}]\n" - f"Command: [{command}]\n" - " Data:\n" + rlogger.debug( + "---- Request ----\n" + f"[ {'Model':^20} | {'Module':^15} | {'Method':^15} | {'Command':^20} ]\n" + f"[ {model:^20} | {module:^15} | {method:^15} | {command:^20} ]\n" f"{xml_text.decode('UTF-8')[:-1]}\n" ) @@ -110,11 +110,9 @@ def eamuse_prepare_xml(xml: str) -> Tuple[bytes, Dict[str, str]]: else: data = xml_bin - print( - "---- Write Response ----\n" - " Data: [\n" + rlogger.debug( + "---- Response ----\n" f"{ET.tostring(xml_root, pretty_print=True).decode('UTF-8')[:-1]}\n" - f"Headers: [{headers}]\n" ) return data, headers diff --git a/v8_server/view/index.py b/v8_server/view/index.py index c71f610..8b20be6 100644 --- a/v8_server/view/index.py +++ b/v8_server/view/index.py @@ -15,16 +15,21 @@ def catch_all(path: str) -> str: This is currently my catch all route, for whenever a new endpoint pops up that isn't implemented """ - d = f""" - {request.args!r} - {request.form!r} - {request.files!r} - {request.values!r} - {request.json!r} - {request.data!r} - {request.headers!r} - """ - print(d) + headers = request.headers + + header_str = "" + for header in headers: + header_str += f"{header[0]:>15}: {header[1]}\n" + + args = "None" if len(request.args) == 0 else request.args + data = request.data + d = ( + "*** Unknown Request ***\n" + f" Args: {args}\n" + f" Data Length: {len(data)}\n" + f"{header_str[:-1]}\n" + ) + app.logger.debug(d) return "You want path: %s" % path @@ -140,6 +145,11 @@ def package() -> Tuple[bytes, Dict[str, str]]: @app.route("/local/service", methods=["POST"]) def local() -> Tuple[bytes, Dict[str, str]]: + """ + This is probably a big chunk of implementation. Handle all "local" service requests + which might have a whole bunch of stuff going on + """ + xml, model, module, method, command = eamuse_read_xml(request) if module == "shopinfo": @@ -155,7 +165,7 @@ def local() -> Tuple[bytes, Dict[str, str]]: ) elif module == "demodata": if method == "get": - response = E.response() + response = E.response(E.demodata()) else: response = base_response(module)