Prefix log entries with current user's username.

buildout.d/versions.cfg

@@ -7,7 +7,7 @@ buildout-versions = 1.7
 flake8 = 1.5
 jarn.mkrelease = 3.7
 mock = 1.0.1
-niteoweb.ipn.core = 1.1
+niteoweb.ipn.core = 1.3
 niteoweb.loginas = 0.2
 plone.app.debugtoolbar = 1.0a2
 Products.Clouseau = 1.0

docs/CHANGELOG.rst

@@ -1,6 +1,13 @@
 Changelog
 =========
 
+1.2 (Unreleased)
+----------------
+
+- Prefix log entries with current user's username.
+  [zupo]
+
+
 1.1 (2013-01-02)
 ----------------
 

src/niteoweb/ipn/jvzoo/jvzoo.py

@@ -38,7 +38,7 @@ def render(self):
         # check for POST request
         if not self.request.form:
             msg = 'No POST request.'
-            logger.warning(msg)
+            logger.warning("{0}: {1}".format(api.user.get_current(), msg))
             return msg
 
         # prepare values
@@ -50,14 +50,16 @@ def render(self):
             # verify and parse post
             self._verify_POST(params)
             data = self._parse_POST(params)
-            logger.info("POST successfully parsed for '%s'." % data['email'])
+            logger.info("{0}: POST successfully parsed for '{1}'.".format(
+                api.user.get_current(), data['email']))
 
             # call appropriate action in niteoweb.ipn.core
             ipn = getAdapter(self.context, IIPN)
             trans_type = data['trans_type']
             if trans_type in self.TYPES_TO_ACTIONS:
                 action = self.TYPES_TO_ACTIONS[trans_type]
-                logger.info("Calling '%s' in niteoweb.ipn.core." % action)
+                logger.info("{0}: Calling '{1}' in niteoweb.ipn.core.".format(
+                    api.user.get_current(), action))
                 params = {
                     'email': data['email'],
                     'product_id': data['product_id'],
@@ -72,19 +74,19 @@ def render(self):
 
         except KeyError as ex:
             msg = "POST parameter missing: %s" % ex
-            logger.warning(msg)
+            logger.warning("{0}: {1}".format(api.user.get_current(), msg))
             transaction.abort()
             return msg
 
         except AssertionError:
             msg = "Checksum verification failed."
-            logger.warning(msg)
+            logger.warning("{0}: {1}".format(api.user.get_current(), msg))
             transaction.abort()
             return msg
 
         except Exception as ex:
             msg = "POST handling failed: %s" % ex
-            logger.warning(msg)
+            logger.warning("{0}: {1}".format(api.user.get_current(), msg))
             transaction.abort()
             return msg
 

src/niteoweb/ipn/jvzoo/tests/test_jvzoo.py

@@ -29,18 +29,19 @@ def tearDown(self):
         """Clean up after yourself."""
         log.clear()
 
-    def _assert_log_record(self, level, msg):
+    def _assert_log_record(self, level, user, msg):
         """Utility method for testing log output."""
         self.assertEqual(log.records[0].name, 'niteoweb.ipn.jvzoo')
         self.assertEqual(log.records[0].levelname, level)
-        self.assertEqual(log.records[0].getMessage(), msg,)
+        self.assertEqual(log.records[0].getMessage(), "{0}: {1}".format(
+            user, msg))
         log.records.pop(0)
 
     def test_call_with_no_POST(self):
         """Test @@jvzoo's response when POST is empty."""
         html = self.view()
         self.failUnless('No POST request.' in html)
-        self._assert_log_record('WARNING', 'No POST request.')
+        self._assert_log_record('WARNING', 'test_user_1_', "No POST request.")
 
     def test_call_with_missing_parameter(self):
         """Test @@jvzoo's response when POST is missing a parameter."""
@@ -59,6 +60,7 @@ def test_call_with_missing_parameter(self):
         self.assertEqual(len(log.records), 1)
         self._assert_log_record(
             'WARNING',
+            'test_user_1_',
             "POST parameter missing: 'cverify'",
         )
 
@@ -77,6 +79,7 @@ def test_call_with_missing_secret_key(self):
         self.assertEqual(len(log.records), 1)
         self._assert_log_record(
             'WARNING',
+            'test_user_1_',
             "POST handling failed: JVZoo secret-key is not set.",
         )
 
@@ -98,6 +101,7 @@ def test_call_with_invalid_checksum(self, verify_post):
         self.assertEqual(len(log.records), 1)
         self._assert_log_record(
             'WARNING',
+            'test_user_1_',
             "Checksum verification failed.",
         )
 
@@ -119,6 +123,7 @@ def test_call_with_internal_exception(self, verify_post):
         self.assertEqual(len(log.records), 1)
         self._assert_log_record(
             'WARNING',
+            'test_user_1_',
             "POST handling failed: Internal foo.",
         )
 
@@ -148,11 +153,13 @@ def test_call_with_valid_POST(self, parse_post, verify_post):
 
         self._assert_log_record(
             'INFO',
+            'test_user_1_',
             "POST successfully parsed for 'new@test.com'.",
         )
 
         self._assert_log_record(
             'INFO',
+            'test_user_1_',
             "Calling 'enable_member' in niteoweb.ipn.core.",
         )
 
@@ -197,55 +204,72 @@ def test_SALE(self):
 
         # test log output
         msg = log.records[1].getMessage()
-        self.assertEqual(msg, "Calling 'enable_member' in niteoweb.ipn.core.")
+        self.assertEqual(
+            msg, "test_user_1_: Calling 'enable_member' in niteoweb.ipn.core.")
 
     def test_BILL(self):
         """Test BILL Transaction Type."""
         self._simulate_transaction(trans_type='BILL')
 
         # test log output
         msg = log.records[1].getMessage()
-        self.assertEqual(msg, "Calling 'enable_member' in niteoweb.ipn.core.")
+        self.assertEqual(
+            msg, "test_user_1_: Calling 'enable_member' in niteoweb.ipn.core.")
 
     def test_RFND(self):
         """Test RFND Transaction Type."""
         self._simulate_transaction(trans_type='RFND')
 
         # test log output
         msg = log.records[1].getMessage()
-        self.assertEqual(msg, "Calling 'disable_member' in niteoweb.ipn.core.")
+        self.assertEqual(
+            msg,
+            "test_user_1_: Calling 'disable_member' in niteoweb.ipn.core.",
+        )
 
     def test_CGBK(self):
         """Test CGBK Transaction Type."""
         self._simulate_transaction(trans_type='CGBK')
 
         # test log output
         msg = log.records[1].getMessage()
-        self.assertEqual(msg, "Calling 'disable_member' in niteoweb.ipn.core.")
+        self.assertEqual(
+            msg,
+            "test_user_1_: Calling 'disable_member' in niteoweb.ipn.core.",
+        )
 
     def test_INSF(self):
         """Test INSF Transaction Type."""
         self._simulate_transaction(trans_type='INSF')
 
         # test log output
         msg = log.records[1].getMessage()
-        self.assertEqual(msg, "Calling 'disable_member' in niteoweb.ipn.core.")
+        self.assertEqual(
+            msg,
+            "test_user_1_: Calling 'disable_member' in niteoweb.ipn.core.",
+        )
 
     def test_CANCEL_REBILL(self):
         """Test CANCEL-REBILL Transaction Type."""
         self._simulate_transaction(trans_type='CANCEL-REBILL')
 
         # test log output
         msg = log.records[1].getMessage()
-        self.assertEqual(msg, "Calling 'disable_member' in niteoweb.ipn.core.")
+        self.assertEqual(
+            msg,
+            "test_user_1_: Calling 'disable_member' in niteoweb.ipn.core.",
+        )
 
     def test_UNCANCEL_REBILL(self):
         """Test UNCANCEL-REBILL Transaction Type."""
         self._simulate_transaction(trans_type='UNCANCEL-REBILL')
 
         # test log output
         msg = log.records[1].getMessage()
-        self.assertEqual(msg, "Calling 'enable_member' in niteoweb.ipn.core.")
+        self.assertEqual(
+            msg,
+            "test_user_1_: Calling 'enable_member' in niteoweb.ipn.core.",
+        )
 
 
 class TestUtils(IntegrationTestCase):