From e7b13e727a976e3a3cc4bbc30164fb1247cb1407 Mon Sep 17 00:00:00 2001 From: Leo Hemsted Date: Mon, 31 Jul 2017 13:28:34 +0100 Subject: [PATCH] don't capture logs directly from stdout previously in run_app_paas.sh, we captured stdout from the app and piped that into the log file. However, this came up with a bunch of problems, mainly: * exceptions with stack traces often weren't formatted properly, and kibana could not parse them * celery logs were duplicated - we'd collect both the json logs and the human readable stdout logs. instead, with the updated utils library, we can use that to log json straight to the appropriate directory directly. --- app/cloudfoundry_config.py | 2 +- app/config.py | 4 ++-- requirements.txt | 2 +- scripts/run_app_paas.sh | 9 +++------ tests/app/test_cloudfoundry_config.py | 2 +- tests/app/test_config.py | 21 --------------------- 6 files changed, 8 insertions(+), 32 deletions(-) diff --git a/app/cloudfoundry_config.py b/app/cloudfoundry_config.py index 293f0cd2c..c890a8333 100644 --- a/app/cloudfoundry_config.py +++ b/app/cloudfoundry_config.py @@ -18,7 +18,7 @@ def set_config_env_vars(vcap_services): vcap_application = json.loads(os.environ['VCAP_APPLICATION']) os.environ['NOTIFY_ENVIRONMENT'] = vcap_application['space_name'] - os.environ['LOGGING_STDOUT_JSON'] = '1' + os.environ['NOTIFY_LOG_PATH'] = '/home/vcap/logs/app.log' # Notify common config for s in vcap_services['user-provided']: diff --git a/app/config.py b/app/config.py index 12d52df9b..c05b96660 100644 --- a/app/config.py +++ b/app/config.py @@ -95,7 +95,6 @@ class Config(object): # Logging DEBUG = False - LOGGING_STDOUT_JSON = os.getenv('LOGGING_STDOUT_JSON') == '1' ########################### # Default config values ### @@ -106,7 +105,7 @@ class Config(object): AWS_REGION = 'eu-west-1' INVITATION_EXPIRATION_DAYS = 2 NOTIFY_APP_NAME = 'api' - NOTIFY_LOG_PATH = '/var/log/notify/application.log' + NOTIFY_LOG_PATH = None SQLALCHEMY_COMMIT_ON_TEARDOWN = False SQLALCHEMY_RECORD_QUERIES = True SQLALCHEMY_TRACK_MODIFICATIONS = True @@ -277,6 +276,7 @@ class Config(object): ###################### class Development(Config): + NOTIFY_LOG_PATH = 'application.log' SQLALCHEMY_ECHO = False NOTIFY_EMAIL_DOMAIN = 'notify.tools' CSV_UPLOAD_BUCKET_NAME = 'development-notifications-csv-upload' diff --git a/requirements.txt b/requirements.txt index 5b011f57c..6c2d839b5 100644 --- a/requirements.txt +++ b/requirements.txt @@ -28,6 +28,6 @@ notifications-python-client>=3.1,<3.2 awscli>=1.11,<1.12 awscli-cwlogs>=1.4,<1.5 -git+https://github.com/alphagov/notifications-utils.git@17.8.0#egg=notifications-utils==17.8.0 +git+https://github.com/alphagov/notifications-utils.git@18.0.0#egg=notifications-utils==18.0.0 git+https://github.com/alphagov/boto.git@2.43.0-patch3#egg=boto==2.43.0-patch3 diff --git a/scripts/run_app_paas.sh b/scripts/run_app_paas.sh index 2ac52c388..2112e4789 100755 --- a/scripts/run_app_paas.sh +++ b/scripts/run_app_paas.sh @@ -52,11 +52,9 @@ function on_exit { kill 0 } -function start_appplication { - exec "$@" 2>&1 | while read line; do echo $line; echo $line >> /home/vcap/logs/app.log.`date +%Y-%m-%d`; done & - LOGGER_PID=$! +function start_application { + exec "$@" & APP_PID=`jobs -p` - echo "Logger process pid: ${LOGGER_PID}" echo "Application process pid: ${APP_PID}" } @@ -69,7 +67,6 @@ function start_aws_logs_agent { function run { while true; do kill -0 ${APP_PID} 2&>/dev/null || break - kill -0 ${LOGGER_PID} 2&>/dev/null || break kill -0 ${AWSLOGS_AGENT_PID} 2&>/dev/null || start_aws_logs_agent sleep 1 done @@ -84,7 +81,7 @@ trap "on_exit" EXIT configure_aws_logs # The application has to start first! -start_appplication "$@" +start_application "$@" start_aws_logs_agent diff --git a/tests/app/test_cloudfoundry_config.py b/tests/app/test_cloudfoundry_config.py index 15ff3dd55..a393fc8bb 100644 --- a/tests/app/test_cloudfoundry_config.py +++ b/tests/app/test_cloudfoundry_config.py @@ -122,8 +122,8 @@ def test_extract_cloudfoundry_config_populates_other_vars(): extract_cloudfoundry_config() assert os.environ['SQLALCHEMY_DATABASE_URI'] == 'postgres uri' - assert os.environ['LOGGING_STDOUT_JSON'] == '1' assert os.environ['NOTIFY_ENVIRONMENT'] == '🚀🌌' + assert os.environ['NOTIFY_LOG_PATH'] == '/home/vcap/logs/app.log' @pytest.mark.usefixtures('os_environ', 'cloudfoundry_environ') diff --git a/tests/app/test_config.py b/tests/app/test_config.py index 63a9bff9a..c1e1cbeee 100644 --- a/tests/app/test_config.py +++ b/tests/app/test_config.py @@ -57,24 +57,3 @@ def test_load_config_if_cloudfoundry_not_available(monkeypatch, reload_config): def test_cloudfoundry_config_has_different_defaults(): # these should always be set on Sandbox assert config.Sandbox.REDIS_ENABLED is False - - -def test_logging_stdout_json_defaults_to_off(reload_config): - os.environ.pop('LOGGING_STDOUT_JSON', None) - assert config.Config.LOGGING_STDOUT_JSON is False - - -def test_logging_stdout_json_sets_to_off_if_not_recognised(reload_config): - os.environ['LOGGING_STDOUT_JSON'] = 'foo' - - importlib.reload(config) - - assert config.Config.LOGGING_STDOUT_JSON is False - - -def test_logging_stdout_json_sets_to_on_if_set_to_1(reload_config): - os.environ['LOGGING_STDOUT_JSON'] = '1' - - importlib.reload(config) - - assert config.Config.LOGGING_STDOUT_JSON is True