Some logging to do with call_with_passes

src/_zkapauthorizer/_plugin.py

@@ -45,11 +45,6 @@ from twisted.internet.defer import (
     succeed,
 )
 
-from eliot import (
-    MessageType,
-    Field,
-)
-
 from allmydata.interfaces import (
     IFoolscapStoragePlugin,
     IAnnounceableStorageServer,
@@ -69,6 +64,10 @@ from .api import (
     ZKAPAuthorizerStorageClient,
 )
 
+from .eliot import (
+    GET_PASSES,
+)
+
 from .model import (
     VoucherStore,
 )
@@ -91,24 +90,6 @@ 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):

src/_zkapauthorizer/_storage_client.py

@@ -20,6 +20,10 @@ This is the client part of a storage access protocol.  The server part is
 implemented in ``_storage_server.py``.
 """
 
+from __future__ import (
+    absolute_import,
+)
+
 from functools import (
     partial,
     wraps,
@@ -30,6 +34,11 @@ import attr
 from zope.interface import (
     implementer,
 )
+
+from eliot.twisted import (
+    DeferredContext,
+)
+
 from twisted.internet.defer import (
     inlineCallbacks,
     returnValue,
@@ -39,6 +48,11 @@ from allmydata.interfaces import (
     IStorageServer,
 )
 
+from .eliot import (
+    SIGNATURE_CHECK_FAILED,
+    CALL_WITH_PASSES,
+)
+
 from .storage_common import (
     MorePassesRequired,
     pass_value_attribute,
@@ -51,7 +65,6 @@ from .storage_common import (
     get_required_new_passes_for_mutable_write,
 )
 
-
 class IncorrectStorageServerReference(Exception):
     """
     A Foolscap remote object which should reference a ZKAPAuthorizer storage
@@ -93,7 +106,8 @@ def call_with_passes(method, num_passes, get_passes):
     """
     def get_more_passes(reason):
         reason.trap(MorePassesRequired)
-        if len(reason.value.signature_check_failed) == 0:
+        num_failed = len(reason.value.signature_check_failed)
+        if num_failed == 0:
             # If no signature checks failed then the call just didn't supply
             # enough passes.  The exception tells us how many passes we should
             # spend so we could try again with that number of passes but for
@@ -102,18 +116,23 @@ def call_with_passes(method, num_passes, get_passes):
             # this case is somewhat suspicious.  Err on the side of lack of
             # service instead of burning extra passes.
             return reason
-        new_passes = get_passes(len(reason.value.signature_check_failed))
+        SIGNATURE_CHECK_FAILED.log(count=num_failed)
+        new_passes = get_passes(num_failed)
         for idx, new_pass in zip(reason.value.signature_check_failed, new_passes):
             passes[idx] = new_pass
         return go(passes)
 
     def go(passes):
-        d = maybeDeferred(method, passes)
+        # Capture the Eliot context for the errback.
+        d = DeferredContext(maybeDeferred(method, passes))
         d.addErrback(get_more_passes)
-        return d
+        # Return the underlying Deferred without finishing the action.
+        return d.result
 
-    passes = get_passes(num_passes)
-    return go(passes)
+    with CALL_WITH_PASSES(count=num_passes).context():
+        passes = get_passes(num_passes)
+        # Finish the Eliot action when this is done.
+        return DeferredContext(go(passes)).addActionFinish()
 
 
 def with_rref(f):

src/_zkapauthorizer/eliot.py

+# Copyright 2020 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 field, message, and action definitions for ZKAPAuthorizer.
+"""
+
+from __future__ import (
+    absolute_import,
+)
+
+from eliot import (
+    Field,
+    MessageType,
+    ActionType,
+)
+
+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.",
+)
+
+SIGNATURE_CHECK_FAILED = MessageType(
+    u"zkapauthorizer:storage-client:signature-check-failed",
+    [PASS_COUNT],
+    u"Some passes the client tried to use were rejected for having invalid signatures.",
+)
+
+CALL_WITH_PASSES = ActionType(
+    u"zkapauthorizer:storage-client:call-with-passes",
+    [PASS_COUNT],
+    [],
+    u"A storage operation is being started which may spend some passes.",
+)