test(data/model): test action logging

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
 

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

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')