Log request issues

flaskr/__init__.py

@@ -3,15 +3,19 @@
 """
 
 import os
-from flask import Flask, current_app
 import click
+import logging
+import structlog
+from logging import StreamHandler
+from logging.handlers import RotatingFileHandler
+from structlog.processors import JSONRenderer, TimeStamper
+from structlog.stdlib import ProcessorFormatter
+from structlog.dev import ConsoleRenderer
+from flask import Flask, current_app
 from flask.cli import with_appcontext
 from flask_cors import CORS
 from flask_migrate import Migrate
 from flask_sqlalchemy import SQLAlchemy
-import logging
-from logging.handlers import RotatingFileHandler
-import sys
 
 from dotenv import load_dotenv
 
@@ -29,6 +33,76 @@ class EnvironmentException(Exception):
 # Create a new sql alchemy database object
 db = SQLAlchemy()
 
+# --- Log setup utilities ---
+
+# We definitely want the log file to include bad request warnings, so the log
+# level has to be at least that low
+file_log_level = logging.WARNING
+
+# If we're in development, the console log level is either DEBUG or INFO,
+# depending on whether debugging is turned on. If we're not in development,
+# there's no console log, so the console log level is effectively infinite
+def console_log_level(environment):
+  return (
+    (
+      logging.DEBUG if config[environment].DEBUG else
+      logging.INFO
+    ) if config[environment].DEVELOPMENT else
+    float('inf')
+  )
+
+def create_file_handler():
+  # Create a file handler, which writes to rotating files api.log, api.log.1, ..., api.log.5
+  handler = RotatingFileHandler('api.log', maxBytes=10**7, backupCount=5)
+
+  # Add a JSON formatter
+  formatter = ProcessorFormatter(
+    processors = [
+      ProcessorFormatter.remove_processors_meta,
+      TimeStamper(fmt='iso', utc=False),
+      JSONRenderer(sort_keys=True)
+    ]
+  )
+  handler.setFormatter(formatter)
+
+  # Set log level
+  handler.setLevel(file_log_level)
+
+  return handler
+
+def create_console_handler(environment):
+  # Create a stream handler that writes to stderr
+  handler = StreamHandler()
+
+  # Add a console formatter
+  formatter = ProcessorFormatter(
+    processors = [
+      ProcessorFormatter.remove_processors_meta,
+      TimeStamper(fmt='iso', utc=False),
+      ConsoleRenderer()
+    ]
+  )
+  handler.setFormatter(formatter)
+
+  # Print everything, or almost everything, in the console
+  handler.setLevel(console_log_level(environment))
+
+  return handler
+
+# This factory calls up the logger that will be stored in current_app.logger
+##class BackscopeLoggerFactory(structlog.stdlib.LoggerFactory):
+##  def __init__(self, default_name, **kwargs):
+##    super().__init__(**kwargs)
+##    self.default_name = default_name
+##  
+##  def __call__(self, name=None, *args) -> logging.Logger:
+##    if name is None:
+##      name = self.default_name
+##    print('factory made: ', super().__call__(name, *args))
+##    return super().__call__(name, *args)
+
+# --- App creation ---
+
 # To choose the environment, we look for settings in the following order:
 #  (1) Function parameter
 #  (2) .env
@@ -37,12 +111,57 @@ def create_app(environment=None, oeis_scheme='https', oeis_hostport='oeis.org'):
     if environment is None:
       # Get app type from .env if provided. Otherwise, use 'development'
       environment = os.environ.get('APP_ENVIRONMENT', 'development')
-
-    # Initial app and configuration
+
+    # --- Set up logging ---
+    #
+    # To access `app.logger` before `app` is created, we take advantage of
+    # knowing that `app` will use the `__name__` logger. we set `app.logger` to
+    # the most verbose level so that each handler can do its own filtering
+    #
+    # "When you want to configure logging for your project, you should do it as
+    # soon as possible when the program starts. If app.logger is accessed before
+    # logging is configured, it will add a default handler. If possible,
+    # configure logging before creating the application object"
+    #
+    #   https://flask.palletsprojects.com/en/2.3.x/logging/
+
+    # For explicit logging, we'll use a structured logger that feeds into the
+    # basic logger. The structured logger will be current_app.structlogger, and
+    # the basic logger will be current_app.logger
+    structlog.configure(
+      processors=[
+        structlog.stdlib.filter_by_level,
+        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
+      ],
+      ##logger_factory=BackscopeLoggerFactory(__name__)
+      logger_factory=structlog.stdlib.LoggerFactory()
+    )
+    ##structlogger = structlog.get_logger(__name__)
+
+    # Create file handler
+    file_handler = create_file_handler()
+
+    # Set up the basic logger
+    min_level = min(file_log_level, console_log_level(environment))
+    ##logging.basicConfig(
+      ##level=min_level
+      ##level=min(file_log_level, console_log_level(environment))
+    ##)
+    basic_logger = logging.getLogger(__name__)
+    basic_logger.setLevel(min_level)
+    basic_logger.addHandler(file_handler)
+    if config[environment].DEVELOPMENT:
+      # in development, also log to the console, with higher verbosity
+      basic_logger.addHandler(create_console_handler(environment))
+
+    # Create app
     app = Flask(__name__, instance_relative_config=True)
-
+
+    # Add structured logger
+    app.structlogger = structlog.get_logger(__name__)
+
     # Upload config from config.py
-    if environment == 'development': CORS(app)
+    if config[environment].DEVELOPMENT: CORS(app)
     if config[environment].TESTING and config[environment].SQLALCHEMY_DATABASE_URI is None:
       ## this is a really convoluted way of throwing an exception when you try
       ## to run tests without specifying the test database, but allowing the
@@ -58,28 +177,20 @@ def create_app(environment=None, oeis_scheme='https', oeis_hostport='oeis.org'):
     app.config['oeis_scheme'] = oeis_scheme
     app.config['oeis_hostport'] = oeis_hostport
 
-    # Logging
-    file_handler = RotatingFileHandler('api.log', maxBytes=10000, backupCount=1)
-    file_handler.setLevel(logging.INFO)
-    app.logger.addHandler(file_handler)
-    stdout = logging.StreamHandler(sys.stdout)
-    stdout.setLevel(logging.DEBUG)
-    app.logger.addHandler(stdout)
-
     # Initialize the application
     db.init_app(app)
     Migrate(app, db)
-
+    
     # Add a command line interface to the application
     app.cli.add_command(clear_database_command)
-
+    
     # The nscope endpoint application
     from flaskr import nscope
-
+    
     # The executor and blueprint are specified via nscope
     nscope.executor.init_app(app)
     app.register_blueprint(nscope.bp)
-
+    
     # The primary application
     return app
 

flaskr/config.py

@@ -40,12 +40,14 @@ class Config:
     DOC_PASSWORD = 'password'
 
     DEBUG = False
+    DEVELOPMENT = False
     TESTING = False
     PRODUCTION = False
 
 
 class DevConfig(Config):
     DEBUG = True
+    DEVELOPMENT = True
 
 
 class TestConfig(Config):

flaskr/nscope/test/abstract_endpoint_test.py

@@ -1,4 +1,5 @@
 import unittest
+from structlog.testing import capture_logs
 import sys
 from flaskr import create_app, db, clear_database
 import flaskr.nscope.views as views
@@ -59,7 +60,7 @@ def test_endpoint(self):
     # "The test client makes requests to the application without running a live
     # server." the `with` block runs teardown
     #   https://github.com/pallets/flask/issues/2949
-    with self.app.test_client() as client:
+    with self.app.test_client() as client, capture_logs() as log_output:
       if self.verbose:
         print("  Testing response")
 
@@ -80,4 +81,8 @@ def test_endpoint(self):
           f"'{response_type.__name__}'"
         )
 
+      # check logs
+      if hasattr(self, 'expected_log_output'):
+        self.assertEqual(log_output, self.expected_log_output)
+
       # TO DO: test background work

flaskr/nscope/test/test_logging.py

@@ -0,0 +1,28 @@
+import unittest
+from flaskr import create_app, db, clear_database
+from structlog.testing import capture_logs
+
+
+class LoggingTest(unittest.TestCase):
+  expected_log_output = [{'log_level': 'error', 'event': 'Error message'}]
+
+  def setUp(self):
+    self.app = create_app('testing')
+    self.ctx = self.app.app_context()
+    with self.ctx:
+      clear_database()
+
+  def tearDown(self):
+    # clear database
+    db.session.remove()
+    with self.ctx:
+      db.drop_all()
+
+  def test_logging(self):
+    with capture_logs() as log_output:
+      self.app.structlogger.error('Error message')
+      self.assertEqual(log_output, self.expected_log_output)
+
+
+if __name__ == "__main__":
+    unittest.main()

flaskr/nscope/test/test_lookup_errors.py

@@ -8,8 +8,11 @@
 #   https://oeis.org/wiki/A-numbers
 #
 class TestNonexistentSequence(abstract_endpoint_test.AbstractEndpointTest):
-  endpoint = "http://localhost:5000/api/get_oeis_values/A000000/12"
+  endpoint = 'http://localhost:5000/api/get_oeis_values/A000000/12'
   expected_response = "Error: B-file for ID 'A000000' not found in OEIS."
+  expected_log_output = [
+    {'log_level': 'error', 'event': 'request issue', 'tags': ['http error']}
+  ]
 
 
 if __name__ == "__main__":