From 0dffa8fce1ecf47c4d658373c81d0d6a45fedec8 Mon Sep 17 00:00:00 2001 From: Allie Crevier Date: Tue, 22 Oct 2019 14:56:48 -0700 Subject: [PATCH 1/4] add logger and logging to proxy --- securedrop_proxy/entrypoint.py | 61 ++++++++++++++++++++++++++++++---- securedrop_proxy/main.py | 18 +++++++--- securedrop_proxy/proxy.py | 17 +++++++--- 3 files changed, 80 insertions(+), 16 deletions(-) diff --git a/securedrop_proxy/entrypoint.py b/securedrop_proxy/entrypoint.py index 2bf7211..250b465 100755 --- a/securedrop_proxy/entrypoint.py +++ b/securedrop_proxy/entrypoint.py @@ -6,18 +6,28 @@ # 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") def start(): + logging.info('Starting SecureDrop Proxy {}'.format(version)) + # a fresh, new proxy object p = proxy.Proxy() @@ -44,3 +54,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(sdc_home: str) -> 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(logging.DEBUG) + log.addHandler(handler) + + # override excepthook to capture a log of catastrophic failures. + sys.excepthook = excepthook diff --git a/securedrop_proxy/main.py b/securedrop_proxy/main.py index 2333bb1..6fadafa 100644 --- a/securedrop_proxy/main.py +++ b/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 diff --git a/securedrop_proxy/proxy.py b/securedrop_proxy/proxy.py index 9e0f3a1..6b50619 100644 --- a/securedrop_proxy/proxy.py +++ b/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") @@ -99,7 +103,7 @@ def handle_non_json_response(self): res = Response(self._presp.status_code) # Create a NamedTemporaryFile, we don't want - # to delete it after closing. + # to delete it after closign. fh = tempfile.NamedTemporaryFile(delete=False) for c in self._presp.iter_content(10): @@ -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 From ea7e87ac00c918862a61c11a3a3ebb4dd2325877 Mon Sep 17 00:00:00 2001 From: Allie Crevier Date: Tue, 22 Oct 2019 17:03:11 -0700 Subject: [PATCH 2/4] init logger --- securedrop_proxy/entrypoint.py | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/securedrop_proxy/entrypoint.py b/securedrop_proxy/entrypoint.py index 250b465..d5bb483 100755 --- a/securedrop_proxy/entrypoint.py +++ b/securedrop_proxy/entrypoint.py @@ -26,6 +26,16 @@ 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.info('Starting SecureDrop Proxy {}'.format(version)) # a fresh, new proxy object @@ -67,7 +77,7 @@ def excepthook(*exc_args): sys.exit(1) -def configure_logging(sdc_home: str) -> None: +def configure_logging() -> None: ''' All logging related settings are set up by this function. ''' From 5527347cde49cbc27b105e34e8dce07dd2e05152 Mon Sep 17 00:00:00 2001 From: Allie Crevier Date: Wed, 30 Oct 2019 17:33:13 -0700 Subject: [PATCH 3/4] add envvar for logging default to info --- securedrop_proxy/entrypoint.py | 3 ++- securedrop_proxy/proxy.py | 2 +- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/securedrop_proxy/entrypoint.py b/securedrop_proxy/entrypoint.py index d5bb483..f568983 100755 --- a/securedrop_proxy/entrypoint.py +++ b/securedrop_proxy/entrypoint.py @@ -23,6 +23,7 @@ DEFAULT_HOME = os.path.join(os.path.expanduser("~"), ".securedrop_proxy") +LOGLEVEL = os.environ.get('LOGLEVEL', 'info').upper() def start(): @@ -98,7 +99,7 @@ def configure_logging() -> None: # set up primary log log = logging.getLogger() - log.setLevel(logging.DEBUG) + log.setLevel(LOGLEVEL) log.addHandler(handler) # override excepthook to capture a log of catastrophic failures. diff --git a/securedrop_proxy/proxy.py b/securedrop_proxy/proxy.py index 6b50619..cc30b32 100644 --- a/securedrop_proxy/proxy.py +++ b/securedrop_proxy/proxy.py @@ -103,7 +103,7 @@ def handle_non_json_response(self): res = Response(self._presp.status_code) # Create a NamedTemporaryFile, we don't want - # to delete it after closign. + # to delete it after closing. fh = tempfile.NamedTemporaryFile(delete=False) for c in self._presp.iter_content(10): From 587ef0300a1697dfa7013ac5908e950d93e9652c Mon Sep 17 00:00:00 2001 From: Allie Crevier Date: Mon, 4 Nov 2019 13:10:18 -0800 Subject: [PATCH 4/4] change log info->debug --- securedrop_proxy/entrypoint.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/securedrop_proxy/entrypoint.py b/securedrop_proxy/entrypoint.py index f568983..33c84d5 100755 --- a/securedrop_proxy/entrypoint.py +++ b/securedrop_proxy/entrypoint.py @@ -37,7 +37,7 @@ def start(): print(e) return - logging.info('Starting SecureDrop Proxy {}'.format(version)) + logging.debug('Starting SecureDrop Proxy {}'.format(version)) # a fresh, new proxy object p = proxy.Proxy()