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

@@ -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"]

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

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

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

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:

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()])

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):

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,15 +174,15 @@ def showautologinsettings():
 
 @app.route("/signout.html")
 def signout():
-    logger.info("Signout messaging displayed.")
+    app.logger.info("Signout messaging displayed.")
     return render_template("signout.html")
 
 
 @app.route("/dashboard")
 @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"]

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

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"}