From 503c4cd235fa2b9e5d90ba120f836fb6db9594e8 Mon Sep 17 00:00:00 2001 From: EvB Date: Wed, 25 Jan 2017 11:38:30 -0500 Subject: [PATCH 1/6] feat(config.py): add setting for audit log strictness --- config.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/config.py b/config.py index 7220800c9..070ccbdb1 100644 --- a/config.py +++ b/config.py @@ -273,6 +273,10 @@ class DefaultConfig(object): SYSTEM_LOGS_FILE = "/var/log/syslog" SYSTEM_SERVICES_PATH = "conf/init/service/" + # Disallow all registry operations if unable to write to the audit log + # When disabled, registry pulls are allowed despite any failures to write to audit log + STRICT_AUDIT_LOG=true + # Services that should not be shown in the logs view. SYSTEM_SERVICE_BLACKLIST = [] From 6916d82e0d0b318d6fd411b996eaba26d2711f1c Mon Sep 17 00:00:00 2001 From: EvB Date: Wed, 15 Feb 2017 15:44:08 -0500 Subject: [PATCH 2/6] feat(endpoints/trackhelper): wrap log op for silent fails --- config.py | 5 ++--- data/model/log.py | 19 +++++++++++++++---- 2 files changed, 17 insertions(+), 7 deletions(-) diff --git a/config.py b/config.py index 070ccbdb1..26b60fa9e 100644 --- a/config.py +++ b/config.py @@ -273,9 +273,8 @@ class DefaultConfig(object): SYSTEM_LOGS_FILE = "/var/log/syslog" SYSTEM_SERVICES_PATH = "conf/init/service/" - # Disallow all registry operations if unable to write to the audit log - # When disabled, registry pulls are allowed despite any failures to write to audit log - STRICT_AUDIT_LOG=true + # Allow registry pulls when unable to write to the audit log + ALLOW_PULLS_WITHOUT_STRICT_LOGGING = False # Services that should not be shown in the logs view. SYSTEM_SERVICE_BLACKLIST = [] diff --git a/data/model/log.py b/data/model/log.py index eb52b96ef..92fc55e5e 100644 --- a/data/model/log.py +++ b/data/model/log.py @@ -1,13 +1,16 @@ import json +import logging from calendar import timegm -from peewee import JOIN_LEFT_OUTER, fn +from peewee import JOIN_LEFT_OUTER, fn, PeeweeException from datetime import datetime, timedelta from cachetools import lru_cache from data.database import LogEntry, LogEntryKind, User, RepositoryActionCount, db from data.model import config, user, DataModelException +logger = logging.getLogger(__name__) + def _logs_query(selections, start_time, end_time, performer=None, repository=None, namespace=None, ignore=None): joined = (LogEntry @@ -109,9 +112,17 @@ def log_action(kind_name, user_or_organization_name, performer=None, repository= kind = _get_log_entry_kind(kind_name) metadata_json = json.dumps(metadata, default=_json_serialize) - LogEntry.create(kind=kind, account=account, performer=performer, - repository=repository, ip=ip, metadata_json=metadata_json, - datetime=timestamp) + try: + LogEntry.create(kind=kind, account=account, performer=performer, + repository=repository, ip=ip, metadata_json=metadata_json, + datetime=timestamp) + except PeeweeException: + if kind_name is 'pull_repo' and config.app_config.get('ALLOW_PULLS_WITHOUT_STRICT_LOGGING'): + logger.warning('log_action failed: kind=%s account=%s user=%s repo=%s ip=%s metadata=%s', + kind_name, account, performer, repository, ip, metadata_json) + else: + raise + def get_stale_logs_start_id(): From 625bd66b4251fa562675703dc12b52f672b48a34 Mon Sep 17 00:00:00 2001 From: EvB Date: Mon, 27 Feb 2017 23:57:40 -0500 Subject: [PATCH 3/6] test(data/model): test action logging --- data/model/log.py | 8 +++++--- data/model/test/conftest.py | 25 ++++++++++++++++++++++++ data/model/test/test_log.py | 39 +++++++++++++++++++++++++++++++++++++ 3 files changed, 69 insertions(+), 3 deletions(-) create mode 100644 data/model/test/conftest.py create mode 100644 data/model/test/test_log.py diff --git a/data/model/log.py b/data/model/log.py index 92fc55e5e..aaaa2617d 100644 --- a/data/model/log.py +++ b/data/model/log.py @@ -116,10 +116,12 @@ def log_action(kind_name, user_or_organization_name, performer=None, repository= LogEntry.create(kind=kind, account=account, performer=performer, repository=repository, ip=ip, metadata_json=metadata_json, datetime=timestamp) - except PeeweeException: + except PeeweeException as ex: if kind_name is 'pull_repo' and config.app_config.get('ALLOW_PULLS_WITHOUT_STRICT_LOGGING'): - logger.warning('log_action failed: kind=%s account=%s user=%s repo=%s ip=%s metadata=%s', - kind_name, account, performer, repository, ip, metadata_json) + logger.warning('log_action failed', + extra={'exception': ex, 'action_kind': kind, 'account': account, + 'performer': performer, 'repository': repository, 'ip': ip, + 'metadata_json': metadata_json, 'datetime': timestamp}) else: raise diff --git a/data/model/test/conftest.py b/data/model/test/conftest.py new file mode 100644 index 000000000..6d03a577b --- /dev/null +++ b/data/model/test/conftest.py @@ -0,0 +1,25 @@ +import pytest + +from mock import patch, Mock +from data.model import config as _config +from data.model.log import log_action +from data.database import LogEntry + +@pytest.fixture(scope='function') +def app_config(request): + default_config = { + 'SERVICE_LOG_ACCOUNT_ID': 'TEST_ACCOUNT_ID', + 'ALLOW_PULLS_WITHOUT_STRICT_LOGGING': False} + with patch.dict(_config.app_config, default_config, clear=True): + yield _config.app_config + +@pytest.fixture() +def logentry_kind(): + kinds = {'pull_repo': 'pull_repo_kind', 'push_repo': 'push_repo_kind'} + with patch('data.model.log.get_log_entry_kinds', return_value=kinds, spec=True): + yield kinds + +@pytest.fixture() +def logentry(logentry_kind): + with patch('data.database.LogEntry.create', spec=True): + yield LogEntry diff --git a/data/model/test/test_log.py b/data/model/test/test_log.py new file mode 100644 index 000000000..39a2f7705 --- /dev/null +++ b/data/model/test/test_log.py @@ -0,0 +1,39 @@ +import pytest + +from data.model.log import log_action +from peewee import PeeweeException +from mock import Mock + +@pytest.mark.parametrize( 'unlogged_pulls_ok,action_kind,db_exception,throws', [ + (False, 'pull_repo', None, False), + (False, 'push_repo', None, False), + (False, 'pull_repo', PeeweeException, True), + (False, 'push_repo', PeeweeException, True), + (True, 'pull_repo', PeeweeException, False), + (True, 'push_repo', PeeweeException, True), + (True, 'pull_repo', Exception, True) +]) + +def test_log_action(unlogged_pulls_ok, action_kind, db_exception, throws, app_config, logentry): + log_args = { + 'performer': Mock(id='TEST_PERFORMER_ID'), + 'repository': Mock(id='TEST_REPO'), + 'ip': 'TEST_IP', + 'metadata': {'test_key': 'test_value'}, + 'timestamp': 'TEST_TIMESTAMP' + } + app_config['SERVICE_LOG_ACCOUNT_ID'] = 'TEST_ACCOUNT_ID' + + app_config['ALLOW_PULLS_WITHOUT_STRICT_LOGGING'] = unlogged_pulls_ok + + logentry.create.side_effect = db_exception + if throws: + with pytest.raises(db_exception): + log_action(action_kind, None, **log_args) + else: + log_action(action_kind, None, **log_args) + + logentry.create.assert_called_once_with(kind=action_kind+'_kind', account='TEST_ACCOUNT_ID', + performer='TEST_PERFORMER_ID', repository='TEST_REPO', + ip='TEST_IP', metadata_json='{"test_key": "test_value"}', + datetime='TEST_TIMESTAMP') From ea740d15bacfd94c64c1b5f7d7462d375290ab40 Mon Sep 17 00:00:00 2001 From: EvB Date: Tue, 7 Mar 2017 13:16:34 -0500 Subject: [PATCH 4/6] fix(model/log): log exception on swallowed db errors --- data/model/log.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/data/model/log.py b/data/model/log.py index aaaa2617d..60fec5fdb 100644 --- a/data/model/log.py +++ b/data/model/log.py @@ -118,7 +118,7 @@ def log_action(kind_name, user_or_organization_name, performer=None, repository= datetime=timestamp) except PeeweeException as ex: if kind_name is 'pull_repo' and config.app_config.get('ALLOW_PULLS_WITHOUT_STRICT_LOGGING'): - logger.warning('log_action failed', + logger.exception('log_action failed', extra={'exception': ex, 'action_kind': kind, 'account': account, 'performer': performer, 'repository': repository, 'ip': ip, 'metadata_json': metadata_json, 'datetime': timestamp}) From d0aaaaa1efc5137323f47fa41de1e021fd0be011 Mon Sep 17 00:00:00 2001 From: EvB Date: Mon, 13 Mar 2017 10:52:36 -0400 Subject: [PATCH 5/6] test(data/model/log): add more log_action tests temp --- data/model/log.py | 18 +++++---- data/model/test/conftest.py | 25 ------------ data/model/test/test_log.py | 79 ++++++++++++++++++++++++++++--------- 3 files changed, 71 insertions(+), 51 deletions(-) delete mode 100644 data/model/test/conftest.py diff --git a/data/model/log.py b/data/model/log.py index 60fec5fdb..fabecd317 100644 --- a/data/model/log.py +++ b/data/model/log.py @@ -112,16 +112,20 @@ def log_action(kind_name, user_or_organization_name, performer=None, repository= kind = _get_log_entry_kind(kind_name) metadata_json = json.dumps(metadata, default=_json_serialize) + log_data = { + 'kind': kind, + 'account': account, + 'performer': performer, + 'repository': repository, + 'ip': ip, + 'metadata_json': metadata_json, + 'datetime': timestamp + } try: - LogEntry.create(kind=kind, account=account, performer=performer, - repository=repository, ip=ip, metadata_json=metadata_json, - datetime=timestamp) + LogEntry.create(**log_data) except PeeweeException as ex: if kind_name is 'pull_repo' and config.app_config.get('ALLOW_PULLS_WITHOUT_STRICT_LOGGING'): - logger.exception('log_action failed', - extra={'exception': ex, 'action_kind': kind, 'account': account, - 'performer': performer, 'repository': repository, 'ip': ip, - 'metadata_json': metadata_json, 'datetime': timestamp}) + logger.exception('log_action failed', extra=({'exception': ex}).update(log_data)) else: raise diff --git a/data/model/test/conftest.py b/data/model/test/conftest.py deleted file mode 100644 index 6d03a577b..000000000 --- a/data/model/test/conftest.py +++ /dev/null @@ -1,25 +0,0 @@ -import pytest - -from mock import patch, Mock -from data.model import config as _config -from data.model.log import log_action -from data.database import LogEntry - -@pytest.fixture(scope='function') -def app_config(request): - default_config = { - 'SERVICE_LOG_ACCOUNT_ID': 'TEST_ACCOUNT_ID', - 'ALLOW_PULLS_WITHOUT_STRICT_LOGGING': False} - with patch.dict(_config.app_config, default_config, clear=True): - yield _config.app_config - -@pytest.fixture() -def logentry_kind(): - kinds = {'pull_repo': 'pull_repo_kind', 'push_repo': 'push_repo_kind'} - with patch('data.model.log.get_log_entry_kinds', return_value=kinds, spec=True): - yield kinds - -@pytest.fixture() -def logentry(logentry_kind): - with patch('data.database.LogEntry.create', spec=True): - yield LogEntry diff --git a/data/model/test/test_log.py b/data/model/test/test_log.py index 39a2f7705..f1d9fe3e5 100644 --- a/data/model/test/test_log.py +++ b/data/model/test/test_log.py @@ -1,39 +1,80 @@ import pytest +from data.database import LogEntry, User +from data.model import config as _config from data.model.log import log_action -from peewee import PeeweeException -from mock import Mock -@pytest.mark.parametrize( 'unlogged_pulls_ok,action_kind,db_exception,throws', [ +from mock import patch, Mock, DEFAULT, sentinel +from peewee import PeeweeException + + +@pytest.fixture(scope='function') +def app_config(): + with patch.dict(_config.app_config, {}, clear=True): + yield _config.app_config + +@pytest.fixture() +def logentry_kind(): + kinds = {'pull_repo': 'pull_repo_kind', 'push_repo': 'push_repo_kind'} + with patch('data.model.log.get_log_entry_kinds', return_value=kinds, spec=True): + yield kinds + +@pytest.fixture() +def logentry(logentry_kind): + with patch('data.database.LogEntry.create', spec=True): + yield LogEntry + +@pytest.fixture() +def user(): + with patch.multiple('data.database.User', username=DEFAULT, get=DEFAULT, select=DEFAULT) as user: + user['get'].return_value = Mock(id='mock_user_id') + user['select'].return_value.tuples.return_value.get.return_value = ['default_user_id'] + yield User + +@pytest.mark.parametrize('action_kind', [('pull'), ('oops')]) +def test_log_action_unknown_action(action_kind): + ''' test unknown action types throw an exception when logged ''' + with pytest.raises(Exception): + log_action(action_kind, None) + + +@pytest.mark.parametrize('user_or_org_name,account_id,account', [ + ('my_test_org', 'N/A', 'mock_user_id' ), + (None, 'test_account_id', 'test_account_id'), + (None, None, 'default_user_id') +]) +@pytest.mark.parametrize('unlogged_pulls_ok,action_kind,db_exception,throws', [ (False, 'pull_repo', None, False), (False, 'push_repo', None, False), - (False, 'pull_repo', PeeweeException, True), - (False, 'push_repo', PeeweeException, True), + (False, 'pull_repo', PeeweeException, True ), + (False, 'push_repo', PeeweeException, True ), + (True, 'pull_repo', PeeweeException, False), - (True, 'push_repo', PeeweeException, True), - (True, 'pull_repo', Exception, True) + (True, 'push_repo', PeeweeException, True ), + (True, 'pull_repo', Exception, True ), + (True, 'push_repo', Exception, True ) ]) - -def test_log_action(unlogged_pulls_ok, action_kind, db_exception, throws, app_config, logentry): +def test_log_action(user_or_org_name, account_id, account, unlogged_pulls_ok, action_kind, + db_exception, throws, app_config, logentry, user): log_args = { - 'performer': Mock(id='TEST_PERFORMER_ID'), - 'repository': Mock(id='TEST_REPO'), - 'ip': 'TEST_IP', - 'metadata': {'test_key': 'test_value'}, - 'timestamp': 'TEST_TIMESTAMP' + 'performer' : Mock(id='TEST_PERFORMER_ID'), + 'repository' : Mock(id='TEST_REPO'), + 'ip' : 'TEST_IP', + 'metadata' : { 'test_key' : 'test_value' }, + 'timestamp' : 'TEST_TIMESTAMP' } - app_config['SERVICE_LOG_ACCOUNT_ID'] = 'TEST_ACCOUNT_ID' - + app_config['SERVICE_LOG_ACCOUNT_ID'] = account_id app_config['ALLOW_PULLS_WITHOUT_STRICT_LOGGING'] = unlogged_pulls_ok logentry.create.side_effect = db_exception + if throws: with pytest.raises(db_exception): - log_action(action_kind, None, **log_args) + log_action(action_kind, user_or_org_name, **log_args) else: - log_action(action_kind, None, **log_args) + log_action(action_kind, user_or_org_name, **log_args) - logentry.create.assert_called_once_with(kind=action_kind+'_kind', account='TEST_ACCOUNT_ID', + logentry.create.assert_called_once_with(kind=action_kind+'_kind', account=account, performer='TEST_PERFORMER_ID', repository='TEST_REPO', ip='TEST_IP', metadata_json='{"test_key": "test_value"}', datetime='TEST_TIMESTAMP') From 20c4d971c487b002f9ef4b18f23ce24c067c3e94 Mon Sep 17 00:00:00 2001 From: EvB Date: Fri, 7 Apr 2017 11:39:54 -0400 Subject: [PATCH 6/6] refactor(model/log): pull allowed action types into constant --- data/model/log.py | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/data/model/log.py b/data/model/log.py index fabecd317..b8dd0328c 100644 --- a/data/model/log.py +++ b/data/model/log.py @@ -11,6 +11,8 @@ from data.model import config, user, DataModelException logger = logging.getLogger(__name__) +ACTIONS_ALLOWED_WITHOUT_AUDIT_LOGGING = ['pull_repo'] + def _logs_query(selections, start_time, end_time, performer=None, repository=None, namespace=None, ignore=None): joined = (LogEntry @@ -121,10 +123,12 @@ def log_action(kind_name, user_or_organization_name, performer=None, repository= 'metadata_json': metadata_json, 'datetime': timestamp } + try: LogEntry.create(**log_data) except PeeweeException as ex: - if kind_name is 'pull_repo' and config.app_config.get('ALLOW_PULLS_WITHOUT_STRICT_LOGGING'): + strict_logging_disabled = config.app_config.get('ALLOW_PULLS_WITHOUT_STRICT_LOGGING') + if strict_logging_disabled and kind_name in ACTIONS_ALLOWED_WITHOUT_AUDIT_LOGGING: logger.exception('log_action failed', extra=({'exception': ex}).update(log_data)) else: raise