Emit an Eliot message when spending happens at the lowest level

setup.cfg

@@ -33,6 +33,7 @@ packages =
 install_requires =
     attrs
     zope.interface
+    eliot
     aniso8601
     python-challenge-bypass-ristretto
     # Inherit our Twisted dependency from tahoe-lafs so we don't accidentally

src/_zkapauthorizer/_plugin.py

@@ -45,6 +45,11 @@ from twisted.internet.defer import (
     succeed,
 )
 
+from eliot import (
+    MessageType,
+    Field,
+)
+
 from allmydata.interfaces import (
     IFoolscapStoragePlugin,
     IAnnounceableStorageServer,
@@ -83,6 +88,24 @@ from .lease_maintenance import (
 
 _log = Logger()
 
+PRIVACYPASS_MESSAGE = Field(
+    u"message",
+    unicode,
+    u"The PrivacyPass request-binding data associated with a pass.",
+)
+
+PASS_COUNT = Field(
+    u"count",
+    int,
+    u"A number of passes.",
+)
+
+GET_PASSES = MessageType(
+    u"zkapauthorizer:get-passes",
+    [PRIVACYPASS_MESSAGE, PASS_COUNT],
+    u"Passes are being spent.",
+)
+
 @implementer(IAnnounceableStorageServer)
 @attr.s
 class AnnounceableStorageServer(object):
@@ -167,7 +190,12 @@ class ZKAPAuthorizer(object):
         extract_unblinded_tokens = self._get_store(node_config).extract_unblinded_tokens
         def get_passes(message, count):
             unblinded_tokens = extract_unblinded_tokens(count)
-            return redeemer.tokens_to_passes(message, unblinded_tokens)
+            passes = redeemer.tokens_to_passes(message, unblinded_tokens)
+            GET_PASSES.log(
+                message=message,
+                count=count,
+            )
+            return passes
 
         return ZKAPAuthorizerStorageClient(
             get_rref,

src/_zkapauthorizer/tests/eliot.py

+# Copyright 2019 PrivateStorage.io, LLC
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+"""
+Eliot testing helpers.
+"""
+
+from __future__ import (
+    absolute_import,
+)
+
+from functools import (
+    wraps,
+)
+
+from unittest import (
+    SkipTest,
+)
+
+from eliot import (
+    MemoryLogger,
+)
+
+from eliot.testing import (
+    swap_logger,
+    check_for_errors,
+)
+
+# validate_logging and capture_logging copied from Eliot around 1.11.  We
+# can't upgrade past 1.7 because we're not Python 3 compatible.
+def validate_logging(assertion, *assertionArgs, **assertionKwargs):
+    def decorator(function):
+        @wraps(function)
+        def wrapper(self, *args, **kwargs):
+            skipped = False
+
+            kwargs["logger"] = logger = MemoryLogger()
+            self.addCleanup(check_for_errors, logger)
+            # TestCase runs cleanups in reverse order, and we want this to
+            # run *before* tracebacks are checked:
+            if assertion is not None:
+                self.addCleanup(
+                    lambda: skipped
+                    or assertion(self, logger, *assertionArgs, **assertionKwargs)
+                )
+            try:
+                return function(self, *args, **kwargs)
+            except SkipTest:
+                skipped = True
+                raise
+
+        return wrapper
+
+    return decorator
+
+
+def capture_logging(assertion, *assertionArgs, **assertionKwargs):
+    """
+    Capture and validate all logging that doesn't specify a L{Logger}.
+
+    See L{validate_logging} for details on the rest of its behavior.
+    """
+
+    def decorator(function):
+        @validate_logging(assertion, *assertionArgs, **assertionKwargs)
+        @wraps(function)
+        def wrapper(self, *args, **kwargs):
+            logger = kwargs["logger"]
+            previous_logger = swap_logger(logger)
+
+            def cleanup():
+                swap_logger(previous_logger)
+
+            self.addCleanup(cleanup)
+            return function(self, *args, **kwargs)
+
+        return wrapper
+
+    return decorator

src/_zkapauthorizer/tests/test_plugin.py

@@ -41,7 +41,12 @@ from testtools import (
 from testtools.matchers import (
     Always,
     Contains,
+    Equals,
     AfterPreprocessing,
+    MatchesAll,
+    HasLength,
+    AllMatch,
+    ContainsDict,
 )
 from testtools.twistedsupport import (
     succeeded,
@@ -79,6 +84,10 @@ from allmydata.client import (
     create_client_from_config,
 )
 
+from eliot.testing import (
+    LoggedMessage,
+)
+
 from twisted.python.filepath import (
     FilePath,
 )
@@ -95,6 +104,10 @@ from twisted.plugins.zkapauthorizer import (
     storage_server,
 )
 
+from .._plugin import (
+    GET_PASSES,
+)
+
 from ..foolscap import (
     RIPrivacyPassAuthorizedStorageServer,
 )
@@ -110,6 +123,7 @@ from ..controller import (
 from ..storage_common import (
     BYTES_PER_PASS,
     required_passes,
+    allocate_buckets_message,
 )
 from .._storage_client import (
     IncorrectStorageServerReference,
@@ -143,6 +157,11 @@ from .foolscap import (
     DummyReferenceable,
 )
 
+from .eliot import (
+    capture_logging,
+)
+
+
 
 SIGNING_KEY_PATH = FilePath(__file__).sibling(u"testing-signing.key")
 
@@ -386,18 +405,20 @@ class ClientPluginTests(TestCase):
         )
 
     @given(
-        tahoe_configs_with_dummy_redeemer,
-        datetimes(),
-        announcements(),
-        vouchers(),
-        storage_indexes(),
-        lease_renew_secrets(),
-        lease_cancel_secrets(),
-        sharenum_sets(),
-        sizes(),
+        get_config=tahoe_configs_with_dummy_redeemer,
+        now=datetimes(),
+        announcement=announcements(),
+        voucher=vouchers(),
+        storage_index=storage_indexes(),
+        renew_secret=lease_renew_secrets(),
+        cancel_secret=lease_cancel_secrets(),
+        sharenums=sharenum_sets(),
+        size=sizes(),
     )
+    @capture_logging(lambda self, logger: logger.validate())
     def test_unblinded_tokens_extracted(
             self,
+            logger,
             get_config,
             now,
             announcement,
@@ -419,11 +440,12 @@ class ClientPluginTests(TestCase):
         )
 
         store = VoucherStore.from_node_config(node_config, lambda: now)
+        expected_pass_cost = required_passes(BYTES_PER_PASS, [size] * len(sharenums))
         controller = PaymentController(
             store,
             DummyRedeemer(),
             # Give it enough for the allocate_buckets call below.
-            required_passes(BYTES_PER_PASS, [size] * len(sharenums)),
+            expected_pass_cost,
         )
         # Get a token inserted into the store.
         redeeming = controller.redeem(voucher)
@@ -455,6 +477,23 @@ class ClientPluginTests(TestCase):
             raises(NotEnoughTokens),
         )
 
+        messages = LoggedMessage.of_type(logger.messages, GET_PASSES)
+        self.assertThat(
+            messages,
+            MatchesAll(
+                HasLength(1),
+                AllMatch(
+                    AfterPreprocessing(
+                        lambda logged_message: logged_message.message,
+                        ContainsDict({
+                            u"message": Equals(allocate_buckets_message(storage_index)),
+                            u"count": Equals(expected_pass_cost),
+                        }),
+                    ),
+                ),
+            ),
+        )
+
 
 class ClientResourceTests(TestCase):
     """

zkapauthorizer.nix

 { lib
 , buildPythonPackage, sphinx, git
-, attrs, zope_interface, aniso8601, twisted, tahoe-lafs, challenge-bypass-ristretto, treq
+, attrs, zope_interface, eliot, aniso8601, twisted, tahoe-lafs, challenge-bypass-ristretto, treq
 , fixtures, testtools, hypothesis, pyflakes, coverage
 , hypothesisProfile ? null
 , collectCoverage ? false
@@ -31,6 +31,7 @@ buildPythonPackage rec {
     attrs
     zope_interface
     aniso8601
+    eliot
     twisted
     tahoe-lafs
     challenge-bypass-ristretto