Merge pull request #4 from mpistrang/master

Add debug logging to `signing_time_is_valid`

applepay/utils.py

@@ -1,9 +1,13 @@
 import base64
 from datetime import timedelta
+import logging
 
 from asn1crypto import cms
 
 
+logger = logging.getLogger(__name__)
+
+
 def retrieve_signature_signing_time(signature):
     """ Return the 'signingTime' CMS attribute from the detached PKCS signature.
 
@@ -50,4 +54,15 @@ def signing_time_is_valid(signature, current_time, threshold):
     unexpected format, inconsistent with the CMS 'ContentInfo' object.
     """
     signing_time = retrieve_signature_signing_time(signature)
-    return timedelta(0) <= (current_time - signing_time) <= threshold
+    is_valid = timedelta(0) <= (current_time - signing_time) <= threshold
+    logger.debug((
+        "Signing time is {is_valid}. "
+        "Signing time: {signing_time:%Y-%m-%d %H:%M:%S %Z}, "
+        "Current time: {current_time:%Y-%m-%d %H:%M:%S %Z}, "
+        "Threshold: {threshold}.").format(
+        is_valid='valid' if is_valid else 'invalid',
+        signing_time=signing_time,
+        current_time=current_time,
+        threshold=threshold)
+    )
+    return is_valid

setup.py

@@ -12,7 +12,7 @@
     packages=['applepay', 'tests'],
     install_requires=['asn1crypto>=0.21.0', 'cryptography>=1.7.2'],
     setup_requires=['pytest-runner>=2.0,<3dev'],
-    tests_require=['pytest>=3.0.6', 'pytz==2016.10'],
+    tests_require=['pytest>=3.0.6', 'pytz==2016.10', 'pytest-capturelog>=0.7'],
     classifiers=[
         "Development Status :: 4 - Beta",
         "Topic :: Utilities",

tests/applepay_test.py

@@ -1,4 +1,5 @@
 from datetime import datetime, timedelta
+import logging
 
 import pytest
 from pytz import utc
@@ -91,3 +92,37 @@ def test_signing_time_equals_current_time(token_fixture):
 
     # then the token should be considered valid.
     assert valid is True
+
+
+def test_valid_signing_time_data_is_logged(token_fixture, caplog):
+    # Given: a valid signature for a current time and threshold
+    signature = token_fixture['signature']
+    current_time = datetime(2014, 10, 27, 20, 51, 43, tzinfo=utc)
+    threshold = timedelta(hours=1)
+
+    # When we attempt to validate the signing time against the threshold,
+    with caplog.atLevel(logging.DEBUG):
+        applepay_utils.signing_time_is_valid(signature, current_time, threshold)
+
+    # Then a new debug log is captured
+    records = caplog.records()
+    assert len(records) == 1
+    assert records[0].name == 'applepay.utils'
+    assert records[0].message == 'Signing time is valid. Signing time: 2014-10-27 19:51:43 UTC+00:00, Current time: 2014-10-27 20:51:43 UTC, Threshold: 1:00:00.'
+
+
+def test_invalid_signing_time_data_is_logged(token_fixture, caplog):
+    # Given: a invalid signature for a current time and threshold
+    signature = token_fixture['signature']
+    current_time = datetime(2010, 1, 2, 5, 22, 13, tzinfo=utc)
+    threshold = timedelta(hours=1)
+
+    # When we attempt to validate the signing time against the threshold,
+    with caplog.atLevel(logging.DEBUG):
+        applepay_utils.signing_time_is_valid(signature, current_time, threshold)
+
+    # Then a new debug log is captured
+    records = caplog.records()
+    assert len(records) == 1
+    assert records[0].name == 'applepay.utils'
+    assert records[0].message == 'Signing time is invalid. Signing time: 2014-10-27 19:51:43 UTC+00:00, Current time: 2010-01-02 05:22:13 UTC, Threshold: 1:00:00.'