From 760ee9fe36182ccaaf556c0f229464e4d218792c Mon Sep 17 00:00:00 2001 From: Ferdinand Thiessen Date: Sun, 13 Feb 2022 23:01:49 +0100 Subject: [PATCH] fix(cli): Fix logging when setting verbosity on the cli --- README.md | 6 +++++ flaschengeist/__init__.py | 7 +++--- flaschengeist/app.py | 14 +++++------ flaschengeist/cli/__init__.py | 40 ++++++++++++++++++++++++++----- flaschengeist/cli/run_cmd.py | 6 ++--- flaschengeist/config.py | 41 ++++++++++++++++++-------------- flaschengeist/flaschengeist.toml | 21 +++++++++------- flaschengeist/logging.toml | 18 +++++--------- 8 files changed, 94 insertions(+), 59 deletions(-) diff --git a/README.md b/README.md index 4c766fb..08aa09f 100644 --- a/README.md +++ b/README.md @@ -79,6 +79,12 @@ Then you can install the database tables and initial entries: $ flaschengeist install ### Run +Flaschengeist provides a CLI, based on the flask CLI, respectivly called `flaschengeist`. + +⚠️ When using the CLI for running Flaschengeist, please note that logging will happen as configured, +with the difference of the main logger will be forced to output to `stderr` and the logging level +of the CLI will override the logging level you have configured for the main logger. + $ flaschengeist run or with debug messages: diff --git a/flaschengeist/__init__.py b/flaschengeist/__init__.py index 8a5e19e..76909c4 100644 --- a/flaschengeist/__init__.py +++ b/flaschengeist/__init__.py @@ -1,12 +1,11 @@ """Flaschengeist""" import logging -import pkg_resources +from importlib.metadata import version from pathlib import Path -from werkzeug.local import LocalProxy -__version__ = pkg_resources.get_distribution("flaschengeist").version +__version__ = version("flaschengeist") _module_path = Path(__file__).parent __pdoc__ = {} -logger: logging.Logger = LocalProxy(lambda: logging.getLogger(__name__)) +logger = logging.getLogger(__name__) __pdoc__["logger"] = "Flaschengeist's logger instance (`werkzeug.local.LocalProxy`)" diff --git a/flaschengeist/app.py b/flaschengeist/app.py index 6cd99c5..86d35a6 100644 --- a/flaschengeist/app.py +++ b/flaschengeist/app.py @@ -1,6 +1,6 @@ import enum - import pkg_resources + from flask import Flask, current_app from flask_cors import CORS from datetime import datetime, date @@ -8,11 +8,11 @@ from flask.json import JSONEncoder, jsonify from sqlalchemy.exc import OperationalError from werkzeug.exceptions import HTTPException -from . import logger -from .plugins import AuthPlugin -from flaschengeist.config import config, configure_app -from flaschengeist.controller import roleController +from flaschengeist import logger from flaschengeist.utils.hook import Hook +from flaschengeist.plugins import AuthPlugin +from flaschengeist.controller import roleController +from flaschengeist.config import config, configure_app class CustomJSONEncoder(JSONEncoder): @@ -95,7 +95,7 @@ def install_all(): roleController.create_permissions(plugin.permissions) -def create_app(test_config=None, cli=False): +def create_app(test_config=None): app = Flask(__name__) app.json_encoder = CustomJSONEncoder CORS(app) @@ -103,7 +103,7 @@ def create_app(test_config=None, cli=False): with app.app_context(): from flaschengeist.database import db - configure_app(app, test_config, cli) + configure_app(app, test_config) db.init_app(app) __load_plugins(app) diff --git a/flaschengeist/cli/__init__.py b/flaschengeist/cli/__init__.py index 945a80b..e86e60c 100644 --- a/flaschengeist/cli/__init__.py +++ b/flaschengeist/cli/__init__.py @@ -1,7 +1,14 @@ +from os import environ +import sys import click +import logging + from flask.cli import FlaskGroup, with_appcontext +from flaschengeist import logger from flaschengeist.app import create_app -from flaschengeist.config import configure_logger + +LOGGING_MIN = 5 # TRACE (custom) +LOGGING_MAX = logging.ERROR def get_version(ctx, param, value): @@ -23,19 +30,37 @@ def get_version(ctx, param, value): ctx.exit() +def configure_logger(level): + """Reconfigure main logger""" + global logger + + # Handle TRACE -> meaning enable debug even for werkzeug + if level == 5: + level = 10 + logging.getLogger("werkzeug").setLevel(level) + + logger.setLevel(level) + environ["FG_LOGGING"] = logging.getLevelName(level) + for h in logger.handlers: + if isinstance(h, logging.StreamHandler) and h.name == "wsgi": + h.setLevel(level) + h.setStream(sys.stderr) + + @with_appcontext def verbosity(ctx, param, value): - """Toggle verbosity between WARNING <-> DEBUG""" + """Callback: Toggle verbosity between ERROR <-> TRACE""" + if not value or ctx.resilient_parsing: return - configure_logger(cli=30 - max(0, min(value * 10, 20))) + configure_logger(LOGGING_MAX - max(LOGGING_MIN, min(value * 10, LOGGING_MAX - LOGGING_MIN))) @click.group( cls=FlaskGroup, add_version_option=False, add_default_commands=False, - create_app=lambda: create_app(cli=30), + create_app=create_app, ) @click.option( "--version", @@ -59,12 +84,15 @@ def cli(): def main(*args, **kwargs): - from .plugin_cmd import plugin + # from .plugin_cmd import plugin from .export_cmd import export from .docs_cmd import docs from .run_cmd import run - cli.add_command(plugin) + # Override logging level + environ.setdefault("FG_LOGGING", logging.getLevelName(LOGGING_MAX)) + + # cli.add_command(plugin) cli.add_command(export) cli.add_command(docs) cli.add_command(run) diff --git a/flaschengeist/cli/run_cmd.py b/flaschengeist/cli/run_cmd.py index 5f0eec3..ddca7c8 100644 --- a/flaschengeist/cli/run_cmd.py +++ b/flaschengeist/cli/run_cmd.py @@ -28,13 +28,11 @@ class PrefixMiddleware(object): @click.pass_context def run(ctx, host, port, debug): """Run Flaschengeist using a development server.""" - from flaschengeist.config import config, configure_logger + from flaschengeist.config import config - # re configure logger, as we are no logger in CLI mode - configure_logger() current_app.wsgi_app = PrefixMiddleware(current_app.wsgi_app, prefix=config["FLASCHENGEIST"].get("root", "")) if debug: environ["FLASK_DEBUG"] = "1" environ["FLASK_ENV"] = "development" - ctx.invoke(run_command, host=host, port=port, debugger=debug) + ctx.invoke(run_command, reload=True, host=host, port=port, debugger=debug) diff --git a/flaschengeist/config.py b/flaschengeist/config.py index 5b7031c..9cf3b69 100644 --- a/flaschengeist/config.py +++ b/flaschengeist/config.py @@ -41,36 +41,41 @@ def read_configuration(test_config): update_dict(config, test_config) -def configure_logger(cli=False): - global config +def configure_logger(): + """Configure the logger + + force_console: Force a console handler + """ + + def set_level(level): + # TRACE means even with werkzeug's request traces + if isinstance(level, str) and level.lower() == "trace": + level = "DEBUG" + logger_config["loggers"]["werkzeug"] = {"level": level} + logger_config["loggers"]["flaschengeist"] = {"level": level} + logger_config["handlers"]["wsgi"]["level"] = level + # Read default config logger_config = toml.load(_module_path / "logging.toml") - if "LOGGING" in config: # Override with user config update_dict(logger_config, config.get("LOGGING")) # Check for shortcuts - if "level" in config["LOGGING"] or isinstance(cli, int): - level = cli if cli and isinstance(cli, int) else config["LOGGING"]["level"] - logger_config["loggers"]["flaschengeist"] = {"level": level} - logger_config["handlers"]["console"]["level"] = level - logger_config["handlers"]["file"]["level"] = level - if cli is True or not config["LOGGING"].get("console", True): - logger_config["handlers"]["console"]["level"] = "CRITICAL" - if not cli and isinstance(config["LOGGING"].get("file", False), str): - logger_config["root"]["handlers"].append("file") - logger_config["handlers"]["file"]["filename"] = config["LOGGING"]["file"] - Path(config["LOGGING"]["file"]).parent.mkdir(parents=True, exist_ok=True) - else: - del logger_config["handlers"]["file"] + if "level" in config["LOGGING"]: + set_level(config["LOGGING"]["level"]) + + # Override logging, used e.g. by CLI + if "FG_LOGGING" in os.environ: + set_level(os.environ.get("FG_LOGGING", "CRITICAL")) + logging.config.dictConfig(logger_config) -def configure_app(app, test_config=None, cli=False): +def configure_app(app, test_config=None): global config read_configuration(test_config) - configure_logger(cli) + configure_logger() # Always enable this builtin plugins! update_dict( diff --git a/flaschengeist/flaschengeist.toml b/flaschengeist/flaschengeist.toml index d1351a7..e2d6dc4 100644 --- a/flaschengeist/flaschengeist.toml +++ b/flaschengeist/flaschengeist.toml @@ -19,15 +19,20 @@ secret_key = "V3ryS3cr3t" [LOGGING] # You can override all settings from the logging.toml here -# E.g. override the formatters etc -# -# Logging level, possible: DEBUG INFO WARNING ERROR +# Default: Logging to WSGI stream (commonly stderr) + +# Logging level, possible: TRACE DEBUG INFO WARNING ERROR CRITICAL +# On TRACE level additionally every request will get logged level = "DEBUG" -# Logging to a file is simple, just add the path -# file = "/tmp/flaschengeist-debug.log" -file = false -# Uncomment to disable console logging -# console = false + +# If you want the logger to log to a file, you could use: +#[LOGGING.handlers.file] +# class = "logging.handlers.WatchedFileHandler" +# level = "WARNING" +# formatter = "extended" +# encoding = "utf8" +# filename = "flaschengeist.log" + [DATABASE] # engine = "mysql" (default) diff --git a/flaschengeist/logging.toml b/flaschengeist/logging.toml index 3891623..fb7b02f 100644 --- a/flaschengeist/logging.toml +++ b/flaschengeist/logging.toml @@ -6,22 +6,16 @@ disable_existing_loggers = false [formatters] [formatters.simple] - format = "%(asctime)s - %(levelname)s - %(message)s" + format = "[%(asctime)s] %(levelname)s - %(message)s" [formatters.extended] - format = "%(asctime)s — %(filename)s - %(funcName)s - %(lineno)d - %(threadName)s - %(name)s — %(levelname)s — %(message)s" + format = "[%(asctime)s] %(levelname)s %(filename)s - %(funcName)s - %(lineno)d - %(threadName)s - %(name)s — %(message)s" [handlers] - [handlers.console] + [handlers.wsgi] + stream = "ext://flask.logging.wsgi_errors_stream" class = "logging.StreamHandler" - level = "DEBUG" formatter = "simple" - stream = "ext://sys.stderr" - [handlers.file] - class = "logging.handlers.WatchedFileHandler" - level = "WARNING" - formatter = "extended" - encoding = "utf8" - filename = "flaschengeist.log" + level = "DEBUG" [loggers] [loggers.werkzeug] @@ -29,4 +23,4 @@ disable_existing_loggers = false [root] level = "WARNING" - handlers = ["console"] \ No newline at end of file + handlers = ["wsgi"] \ No newline at end of file