6934: Improve and test logging

diff --git a/sdk/pam/arvados_pam/__init__.py b/sdk/pam/arvados_pam/__init__.py
index b7361f56d9ddabb0330b91ee7bde81e2d98e3219..c002f3e105e92f0f2b203f11ae7eb0fe96650e8a 100644 (file)
--- a/sdk/pam/arvados_pam/__init__.py
+++ b/sdk/pam/arvados_pam/__init__.py
@@ -91,9 +91,7 @@ class AuthEvent(object):
         else:
             log_token = '<invalid>'
 
-        log_label = [self.client_host, self.api_host, self.vm_uuid, self.username, log_token]
-        if self.vm_uuid:
-            log_label += [self.vm_uuid]
+        log_label = [self.service, self.api_host, self.vm_uuid, self.client_host, self.username, log_token]
         if self.user:
             log_label += [self.user.get('uuid'), self.user.get('full_name')]
         return str(log_label) + ': ' + outcome

diff --git a/sdk/pam/tests/test_pam.py b/sdk/pam/tests/test_pam.py
index 1eb436a2c452ac5bd7c8ac7f4d4a1ce546fffe40..70956c9f7e15aaab0e72b39b32789ab73f0c6058 100644 (file)
--- a/sdk/pam/tests/test_pam.py
+++ b/sdk/pam/tests/test_pam.py
@@ -3,6 +3,7 @@
 import arvados
 import arvados_pam
 import mock
+import re
 import StringIO
 import unittest
 
@@ -74,10 +75,19 @@ class AuthTest(unittest.TestCase):
             filters=[['hostname','=',cfg['virtual_machine_hostname']]])
         self.api.assert_called_with(
             'v1', host=cfg['ARVADOS_API_HOST'], token=self.request['token'], cache=None)
+        self.assertEqual(1, len(self.syslogged))
+        for i in ['test_service',
+                  self.request['username'],
+                  self.config['test_service']['ARVADOS_API_HOST'],
+                  self.response['virtual_machines']()['items'][0]['uuid']]:
+            self.assertRegexpMatches(self.syslogged[0], re.escape(i))
+        self.assertRegexpMatches(self.syslogged[0], re.escape(self.request['token'][0:15]), 'token prefix not logged')
+        self.assertNotRegexpMatches(self.syslogged[0], re.escape(self.request['token'][15:30]), 'too much token logged')
 
     def test_fail_vm_lookup(self):
         self.response['virtual_machines'] = self._raise
         self.assertFalse(self.attempt())
+        self.assertRegexpMatches(self.syslogged[0], 'Test-induced failure')
 
     def test_vm_hostname_not_found(self):
         self.response['virtual_machines'] = lambda: {
@@ -156,5 +166,11 @@ class AuthTest(unittest.TestCase):
         self.addCleanup(patcher.stop)
         self.api.side_effect = [self.api_client]
 
+        self.syslogged = []
+        patcher = mock.patch('syslog.syslog')
+        self.syslog = patcher.start()
+        self.addCleanup(patcher.stop)
+        self.syslog.side_effect = lambda s: self.syslogged.append(s)
+
     def _raise(self, exception=Exception("Test-induced failure"), *args, **kwargs):
         raise exception