fix(cli): Fix logging when setting verbosity on the cli

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:
 

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`)"

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)
 

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)

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)

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(

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)

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"]
+  handlers = ["wsgi"]