Add securedrop-proxy logging

securedrop_proxy/entrypoint.py

@@ -6,18 +6,39 @@
 # called with exactly one argument: the path to its config file. See
 # the README for configuration options.
 
-import sys
 import json
-import uuid
+import logging
+import os
 import subprocess
+import sys
+import uuid
+
+from logging.handlers import TimedRotatingFileHandler
 
-from . import proxy
-from . import config
-from . import callbacks
-from . import main
+from securedrop_proxy import callbacks
+from securedrop_proxy import config
+from securedrop_proxy import main
+from securedrop_proxy import proxy
+from securedrop_proxy.version import version
+
+
+DEFAULT_HOME = os.path.join(os.path.expanduser("~"), ".securedrop_proxy")
+LOGLEVEL = os.environ.get('LOGLEVEL', 'info').upper()
 
 
 def start():
+    '''
+    Set up a new proxy object with an error handler, configuration that we read from  argv[1], and
+    the original user request from STDIN.
+    '''
+    try:
+        configure_logging()
+    except Exception as e:
+        print(e)
+        return
+
+    logging.debug('Starting SecureDrop Proxy {}'.format(version))
+
     # a fresh, new proxy object
     p = proxy.Proxy()
 
@@ -44,3 +65,42 @@ def start():
     incoming = "\n".join(incoming)
 
     main.__main__(incoming, p)
+
+
+def excepthook(*exc_args):
+    '''
+    This function is called in the event of a catastrophic failure.
+    Log exception and exit cleanly.
+    '''
+    logging.error('Unrecoverable error', exc_info=(exc_args))
+    sys.__excepthook__(*exc_args)
+    print('')  # force terminal prompt on to a new line
+    sys.exit(1)
+
+
+def configure_logging() -> None:
+    '''
+    All logging related settings are set up by this function.
+    '''
+    log_folder = os.path.join(DEFAULT_HOME, 'logs')
+    if not os.path.exists(log_folder):
+        os.makedirs(log_folder)
+
+    log_file = os.path.join(DEFAULT_HOME, 'logs', 'proxy.log')
+
+    # set logging format
+    log_fmt = ('%(asctime)s - %(name)s:%(lineno)d(%(funcName)s) %(levelname)s: %(message)s')
+    formatter = logging.Formatter(log_fmt)
+
+    # define log handlers such as for rotating log files
+    handler = TimedRotatingFileHandler(log_file)
+    handler.setFormatter(formatter)
+    handler.setLevel(logging.DEBUG)
+
+    # set up primary log
+    log = logging.getLogger()
+    log.setLevel(LOGLEVEL)
+    log.addHandler(handler)
+
+    # override excepthook to capture a log of catastrophic failures.
+    sys.excepthook = excepthook

securedrop_proxy/main.py

@@ -1,24 +1,33 @@
 import json
+import logging
 
 from securedrop_proxy import callbacks
 from securedrop_proxy import proxy
 
 
+logger = logging.getLogger(__name__)
+
+
 def __main__(incoming, p):
-    # deserialize incoming request
+    '''
+    Deserialize incoming request in order to build and send a proxy request.
+    '''
+    logging.debug('Creating request to be sent by proxy')
+
     client_req = None
     try:
         client_req = json.loads(incoming)
-    except json.decoder.JSONDecodeError:
+    except json.decoder.JSONDecodeError as e:
+        logging.error(e)
         p.simple_error(400, 'Invalid JSON in request')
         p.on_done(p.res)
 
-    # build request oject
     req = proxy.Req()
     try:
         req.method = client_req['method']
         req.path_query = client_req['path_query']
-    except KeyError:
+    except KeyError as e:
+        logging.error(e)
         p.simple_error(400, 'Missing keys in request')
         p.on_done(p.res)
 
@@ -28,7 +37,6 @@ def __main__(incoming, p):
     if "body" in client_req:
         req.body = client_req['body']
 
-    # complete proxy object
     p.req = req
     p.on_save = callbacks.on_save
     p.on_done = callbacks.on_done

securedrop_proxy/proxy.py

@@ -1,12 +1,16 @@
-import requests
 import furl
-import tempfile
 import json
+import logging
+import requests
+import tempfile
 import werkzeug
 
 import securedrop_proxy.version as version
 
 
+logger = logging.getLogger(__name__)
+
+
 class Req:
     def __init__(self):
         self.method = ""
@@ -71,7 +75,7 @@ def prep_request(self):
         try:
             url = furl.furl("{}://{}:{}/{}".format(scheme, host, port, path))
         except Exception as e:
-
+            logging.error(e)
             self.simple_error(500, "Proxy error while generating URL to request")
             raise ValueError("Error generating URL from provided values")
 
@@ -114,6 +118,7 @@ def handle_non_json_response(self):
         self.res = res
 
     def handle_response(self):
+        logging.debug('Handling response')
 
         ctype = werkzeug.http.parse_options_header(self._presp.headers["content-type"])
 
@@ -134,11 +139,13 @@ def proxy(self):
                 raise ValueError("Request callback is not set.")
 
             self.prep_request()
+            logging.debug('Sending request')
             s = requests.Session()
             self._presp = s.send(self._prepared_request)
             self.handle_response()
 
-        except ValueError:
+        except ValueError as e:
+            logging.error(e)
 
             # effectively a 4xx error
             # we have set self.response to indicate an error