From 0c08cfe65276ea62808fd833253acdc7529244d0 Mon Sep 17 00:00:00 2001 From: Jake Watkins Date: Fri, 23 Aug 2024 09:34:30 -0400 Subject: [PATCH] Improve logging with Google Cloud Logs The primary purpose here is to improve logging to GCP by changing the logging formatter from plaintext to json. The python logging config is now unified under logging.ini for both the flask application and gunicorn. Other changes are listed here: * Limits everret config sources to ENV only to avoid confusion * Removes sso-dashboard logger in favor of the root logger * Log Levels set to INFO unless SSO-DASHBOARD_DEBUG is set True * Adds a flask handler for uncaught Exceptions --- Dockerfile | 2 +- clouddeploy/sso-dashboard-dev.template.yaml | 14 ++---- clouddeploy/sso-dashboard-prod.template.yaml | 12 ++--- .../sso-dashboard-staging.template.yaml | 12 ++--- compose.yml | 3 -- dashboard/__init__.py | 14 +----- dashboard/api/idp.py | 2 +- dashboard/app.py | 36 ++++++++++----- dashboard/config.py | 14 +++--- dashboard/logging.ini | 45 +++++++++++++++++++ dashboard/logging.yml | 23 ---------- dashboard/models/tile.py | 20 +++++---- dashboard/models/user.py | 2 +- dashboard/oidc_auth.py | 2 +- dashboard/op/yaml_loader.py | 2 +- 15 files changed, 103 insertions(+), 100 deletions(-) create mode 100644 dashboard/logging.ini delete mode 100644 dashboard/logging.yml diff --git a/Dockerfile b/Dockerfile index dcbf9331..38b67886 100644 --- a/Dockerfile +++ b/Dockerfile @@ -32,4 +32,4 @@ ENTRYPOINT ["gunicorn", "dashboard.app:app"] # by cloud deploy. In general, these should match the # args used in cloud deploy dev environment # Default command arguments -CMD ["--worker-class", "gevent", "--bind", "0.0.0.0:8000", "--workers=2", "--max-requests=1000", "--max-requests-jitter=50", "--graceful-timeout=30", "--timeout=60", "--log-level=debug", "--error-logfile=-", "--reload", "--reload-extra-file=/dashboard/data/apps.yml"] +CMD ["--worker-class=gevent", "--bind=0.0.0.0:8000", "--workers=3", "--graceful-timeout=30", "--timeout=60", "--log-config=dashboard/logging.ini", "--reload", "--reload-extra-file=/dashboard/data/apps.yml"] diff --git a/clouddeploy/sso-dashboard-dev.template.yaml b/clouddeploy/sso-dashboard-dev.template.yaml index 12e76e3f..2aaa2c32 100644 --- a/clouddeploy/sso-dashboard-dev.template.yaml +++ b/clouddeploy/sso-dashboard-dev.template.yaml @@ -33,18 +33,14 @@ spec: - name: 'sso-dashboard' image: 'app' command: - - gunicorn + - 'gunicorn' - 'dashboard.app:app' args: - - '--worker-class' - - gevent - - '--bind' - - '0.0.0.0:8000' + - '--worker-class=gevent' + - '--bind=0.0.0.0:8000' - '--workers=3' - '--graceful-timeout=30' - '--timeout=60' - - '--log-level=debug' - - '--error-logfile=-' - '--reload' - '--reload-extra-file=/dashboard/data/apps.yml' ports: @@ -54,7 +50,7 @@ spec: - name: 'TARGET' value: 'Staging' - name: SSO-DASHBOARD_DEBUG - value: False + value: True - name: SSO-DASHBOARD_TESTING value: False - name: SSO-DASHBOARD_CSRF_ENABLED @@ -65,8 +61,6 @@ spec: value: 86400 - name: SSO-DASHBOARD_SESSION_COOKIE_HTTPONLY value: True - - name: SSO-DASHBOARD_LOGGER_NAME - value: sso-dashboard - name: SSO-DASHBOARD_PREFERRED_URL_SCHEME value: https - name: SSO-DASHBOARD_OIDC_CLIENT_ID diff --git a/clouddeploy/sso-dashboard-prod.template.yaml b/clouddeploy/sso-dashboard-prod.template.yaml index a342a394..77f8c32d 100644 --- a/clouddeploy/sso-dashboard-prod.template.yaml +++ b/clouddeploy/sso-dashboard-prod.template.yaml @@ -33,18 +33,14 @@ spec: - name: 'sso-dashboard' image: 'app' command: - - gunicorn + - 'gunicorn' - 'dashboard.app:app' args: - - '--worker-class' - - gevent - - '--bind' - - '0.0.0.0:8000' + - '--worker-class=gevent' + - '--bind=0.0.0.0:8000' - '--workers=3' - '--graceful-timeout=30' - '--timeout=60' - - '--log-level=debug' - - '--error-logfile=-' - '--reload' - '--reload-extra-file=/dashboard/data/apps.yml' ports: @@ -65,8 +61,6 @@ spec: value: 86400 - name: SSO-DASHBOARD_SESSION_COOKIE_HTTPONLY value: True - - name: SSO-DASHBOARD_LOGGER_NAME - value: sso-dashboard - name: SSO-DASHBOARD_PREFERRED_URL_SCHEME value: https - name: SSO-DASHBOARD_OIDC_CLIENT_ID diff --git a/clouddeploy/sso-dashboard-staging.template.yaml b/clouddeploy/sso-dashboard-staging.template.yaml index 57942679..0ca8c75a 100644 --- a/clouddeploy/sso-dashboard-staging.template.yaml +++ b/clouddeploy/sso-dashboard-staging.template.yaml @@ -33,18 +33,14 @@ spec: - name: 'sso-dashboard' image: 'app' command: - - gunicorn + - 'gunicorn' - 'dashboard.app:app' args: - - '--worker-class' - - gevent - - '--bind' - - '0.0.0.0:8000' + - '--worker-class=gevent' + - '--bind=0.0.0.0:8000' - '--workers=3' - '--graceful-timeout=30' - '--timeout=60' - - '--log-level=debug' - - '--error-logfile=-' - '--reload' - '--reload-extra-file=/dashboard/data/apps.yml' ports: @@ -65,8 +61,6 @@ spec: value: 86400 - name: SSO-DASHBOARD_SESSION_COOKIE_HTTPONLY value: True - - name: SSO-DASHBOARD_LOGGER_NAME - value: sso-dashboard - name: SSO-DASHBOARD_PREFERRED_URL_SCHEME value: https - name: SSO-DASHBOARD_OIDC_CLIENT_ID diff --git a/compose.yml b/compose.yml index 23b0f666..b24bfe22 100644 --- a/compose.yml +++ b/compose.yml @@ -5,9 +5,6 @@ services: sso-dashboard: build: . env_file: envfile - environment: - - FLASK_DEBUG=True - - FLASK_APP=dashboard/app.py ports: - 8000:8000 volumes: diff --git a/dashboard/__init__.py b/dashboard/__init__.py index 59977584..aacc051b 100644 --- a/dashboard/__init__.py +++ b/dashboard/__init__.py @@ -2,7 +2,6 @@ from everett.manager import ConfigManager from everett.manager import ConfigOSEnv -from everett.ext.inifile import ConfigIniEnv # -*- coding: utf-8 -*- @@ -17,15 +16,4 @@ def get_config(): - return ConfigManager( - [ - ConfigIniEnv( - [ - os.environ.get("DASHBOARD_CONFIG_INI"), - "~/.sso-dashboard.ini", - "/etc/sso-dashboard.ini", - ] - ), - ConfigOSEnv(), - ] - ) + return ConfigManager([ConfigOSEnv()]) diff --git a/dashboard/api/idp.py b/dashboard/api/idp.py index 17b072ca..145221a8 100644 --- a/dashboard/api/idp.py +++ b/dashboard/api/idp.py @@ -7,7 +7,7 @@ from jose import jwt from dashboard.api.exceptions import AuthError -logger = logging.getLogger(__name__) +logger = logging.getLogger() class AuthorizeAPI(object): diff --git a/dashboard/app.py b/dashboard/app.py index 3100c87b..0d8cb3d6 100644 --- a/dashboard/app.py +++ b/dashboard/app.py @@ -1,10 +1,11 @@ """SSO Dashboard App File.""" import json -import logging.config +import logging import mimetypes import os import redis +import traceback import yaml from flask import Flask @@ -37,17 +38,14 @@ from dashboard.models.tile import CDNTransfer -logging.basicConfig(level=logging.INFO) +logging.config.fileConfig("dashboard/logging.ini") -with open("dashboard/logging.yml", "r") as log_config: - config_yml = log_config.read() - config_dict = yaml.safe_load(config_yml) - logging.config.dictConfig(config_dict) - -logger = logging.getLogger("sso-dashboard") +if config.Config(None).settings.DEBUG: + # Set the log level to DEBUG for all defined loggers + for logger_name in logging.root.manager.loggerDict.keys(): + logging.getLogger(logger_name).setLevel("DEBUG") app = Flask(__name__) -everett_config = get_config() talisman = Talisman(app, content_security_policy=DASHBOARD_CSP, force_https=False) @@ -116,13 +114,27 @@ def claim(): return redirect("https://github.com/mozilla-iam/cis/blob/master/cis/schema.json", code=302) +# Flask Error Handlers @app.errorhandler(404) def page_not_found(error): if request.url is not None: - logger.error("A 404 has been generated for {route}".format(route=request.url)) + app.logger.error("A 404 has been generated for {route}".format(route=request.url)) return render_template("404.html"), 404 +@app.errorhandler(Exception) +def handle_exception(e): + + # Capture the traceback + tb_str = traceback.format_exc() + + # Log the error with traceback + app.logger.error("An error occurred: %s\n%s", str(e), tb_str) + + response = {"error": "An internal error occurred", "message": str(e)} + return jsonify(response), 500 + + @app.route("/forbidden") def forbidden(): """Route to render error page.""" @@ -162,7 +174,7 @@ def showautologinsettings(): @app.route("/signout.html") def signout(): - logger.info("Signout messaging displayed.") + app.logger.info("Signout messaging displayed.") return render_template("signout.html") @@ -170,7 +182,7 @@ def signout(): @oidc.oidc_auth("default") def dashboard(): """Primary dashboard the users will interact with.""" - logger.info("User: {} authenticated proceeding to dashboard.".format(session.get("id_token")["sub"])) + app.logger.info("User: {} authenticated proceeding to dashboard.".format(session.get("id_token")["sub"])) # TODO: Refactor rules later to support full id_conformant session session["userinfo"]["user_id"] = session.get("id_token")["sub"] diff --git a/dashboard/config.py b/dashboard/config.py index 40362382..9d79633d 100644 --- a/dashboard/config.py +++ b/dashboard/config.py @@ -21,18 +21,18 @@ def _init_env(self): class DefaultConfig(object): """Defaults for the configuration objects.""" - DEBUG = bool(CONFIG("debug", namespace="sso-dashboard", default="True")) - TESTING = bool(CONFIG("testing", namespace="sso-dashboard", default="False")) - PROPAGATE_EXCEPTIONS = bool(CONFIG("propagate_exceptions", namespace="sso-dashboard", default="True")) + DEBUG = bool(CONFIG("debug", namespace="sso-dashboard", parser=bool, default="False")) + TESTING = bool(CONFIG("testing", namespace="sso-dashboard", parser=bool, default="False")) - CSRF_ENABLED = bool(CONFIG("csrf_enabled", default="True")) - PERMANENT_SESSION = bool(CONFIG("permanent_session", namespace="sso-dashboard", default="True")) + CSRF_ENABLED = bool(CONFIG("csrf_enabled", parser=bool, default="True")) + PERMANENT_SESSION = bool(CONFIG("permanent_session", namespace="sso-dashboard", parser=bool, default="True")) seconds = int(CONFIG("permanent_session_lifetime", namespace="sso-dashboard", default="86400")) PERMANENT_SESSION_LIFETIME = datetime.timedelta(seconds=seconds) SESSION_COOKIE_SAMESITE = CONFIG("session_cookie_samesite", namespace="sso-dashboard", default="lax") - SESSION_COOKIE_HTTPONLY = bool(CONFIG("session_cookie_httponly", namespace="sso-dashboard", default="True")) - LOGGER_NAME = CONFIG("logger_name", namespace="sso-dashboard", default="sso-dashboard") + SESSION_COOKIE_HTTPONLY = bool( + CONFIG("session_cookie_httponly", namespace="sso-dashboard", parser=bool, default="True") + ) SECRET_KEY = CONFIG("secret_key", namespace="sso-dashboard") SERVER_NAME = CONFIG("server_name", namespace="sso-dashboard", default="localhost:8000") diff --git a/dashboard/logging.ini b/dashboard/logging.ini new file mode 100644 index 00000000..48b3aa57 --- /dev/null +++ b/dashboard/logging.ini @@ -0,0 +1,45 @@ +[loggers] +keys=root,gunicorn.error,gunicorn.access,flask_app,werkzeug + +[handlers] +keys=console + +[formatters] +keys=json + +[logger_root] +level=INFO +handlers=console +disable_existing_loggers=False + +[logger_gunicorn.error] +level=INFO +qualname=gunicorn.error +propagate=0 +handlers=console + +[logger_gunicorn.access] +level=INFO +qualname=gunicorn.access +propagate=0 +handlers=console + +[logger_flask_app] +level=INFO +qualname=flask_app +propagate=0 +handlers=console + +[logger_werkzeug] +level=INFO +qualname=werkzeug +propagate=0 +handlers=console + +[handler_console] +class=logging.StreamHandler +formatter=json +args=(sys.stderr,) + +[formatter_json] +format={"time": "%(asctime)s", "level": "%(levelname)s", "process_id": %(process)d, "message": "%(message)s", "name": "%(filename)s:%(name)s:%(funcName)s:%(lineno)s"} diff --git a/dashboard/logging.yml b/dashboard/logging.yml deleted file mode 100644 index b0a4d8bc..00000000 --- a/dashboard/logging.yml +++ /dev/null @@ -1,23 +0,0 @@ -# Default AWS Config -version: 1 -disable_existing_loggers: False -formatters: - json: - format: "[%(asctime)s] %(process)d %(levelname)s %(name)s:%(funcName)s:%(lineno)s - %(message)s" - plaintext: - format: "[%(asctime)s] %(process)d %(levelname)s %(name)s:%(funcName)s:%(lineno)s - %(message)s" -handlers: - console: - (): logging.StreamHandler - level: DEBUG - formatter: plaintext - stream: ext://sys.stdout -loggers: - sso-dashboard: - handlers: [console] - __main__: - handlers: [console] - root: - handlers: [console] - requests: - handlers: [console] diff --git a/dashboard/models/tile.py b/dashboard/models/tile.py index 21e11a12..95655ff4 100644 --- a/dashboard/models/tile.py +++ b/dashboard/models/tile.py @@ -5,7 +5,7 @@ import urllib3 from urllib3.exceptions import HTTPError -logger = logging.getLogger(__name__) +logger = logging.getLogger() class CDNTransfer(object): @@ -32,7 +32,7 @@ def is_updated(self): response = http.request("HEAD", self.url) if response.headers["ETag"] != self._etag(): - logger.error("Etags do not match") + logger.warning("Etags do not match") return True else: return False @@ -49,10 +49,12 @@ def _etag(self): this_dir = os.path.dirname(__file__) filename = os.path.join(this_dir, "../data/{name}").format(name="apps.yml-etag") try: - return open(filename, "r").read() + with open(filename, "r") as f: + etag = f.read() + return etag except Exception as e: """If the etag file is not found return a default etag.""" - logger.info("Error fetching etag: {e}".format(e=e)) + logger.warning("Error fetching etag: {e}".format(e=e)) # Return a fake ETag if etag file doesn't exist return "12345678" @@ -61,18 +63,19 @@ def _download_config(self): http = urllib3.PoolManager() try: + logger.info("Downloading apps.yml from CDN") response = http.request("GET", self.url) if response.status != 200: raise HTTPError(f"HTTP request failed with status {response.status}") except HTTPError as e: - print(f"Rrequest for apps.yml failed: {e}") + logger.error("Request for apps.yml failed: %s", str(e)) raise this_dir = os.path.dirname(__file__) filename = os.path.join(this_dir, "../data/{name}").format(name="apps.yml") try: - # As soon as this file is closed, gunicorn should reload the works + # As soon as this file is closed, gunicorn should reload the workers with open(filename, "wb") as file: file.write(response.data) # Ensure all data is flushed to disk @@ -84,7 +87,7 @@ def _download_config(self): self._update_etag(response.headers["ETag"]) except Exception as e: # Handle potential errors - print(f"An error occurred while attempting to write apps.yml: {e}") + logger.error("An error occurred while attempting to write apps.yml: %s", str(e)) raise def _load_apps_yml(self): @@ -92,6 +95,7 @@ def _load_apps_yml(self): this_dir = os.path.dirname(__file__) filename = os.path.join(this_dir, "../data/{name}").format(name="apps.yml") with open(filename, "r") as file: + logger.info("Loading apps.yml from disk") self.apps_yml = file.read() def sync_config(self): @@ -102,7 +106,6 @@ def sync_config(self): logger.info("Config file is updated fetching new config.") self._download_config() except Exception as e: - print(e) logger.error("Problem fetching config file {error}".format(error=e)) # Load the apps.yml file into self.apps_list @@ -111,7 +114,6 @@ def sync_config(self): if not self.apps_yml: self._load_apps_yml() except Exception as e: - print(e) logger.error("Problem loading the config file {error}".format(error=e)) diff --git a/dashboard/models/user.py b/dashboard/models/user.py index 2e6ae4b3..7ff11750 100644 --- a/dashboard/models/user.py +++ b/dashboard/models/user.py @@ -5,7 +5,7 @@ from faker import Faker fake = Faker() -logger = logging.getLogger(__name__) +logger = logging.getLogger() class User(object): diff --git a/dashboard/oidc_auth.py b/dashboard/oidc_auth.py index 127ddee9..fe7d1305 100644 --- a/dashboard/oidc_auth.py +++ b/dashboard/oidc_auth.py @@ -10,7 +10,7 @@ from flask_pyoidc.provider_configuration import ClientMetadata from flask_pyoidc.provider_configuration import ProviderConfiguration -logger = logging.getLogger(__name__) +logger = logging.getLogger() class OpenIDConnect(object): diff --git a/dashboard/op/yaml_loader.py b/dashboard/op/yaml_loader.py index 6d171743..ac1a348b 100644 --- a/dashboard/op/yaml_loader.py +++ b/dashboard/op/yaml_loader.py @@ -4,7 +4,7 @@ import yaml -logger = logging.getLogger(__name__) +logger = logging.getLogger() class Application: