From fdb726095aeae5084e94ad3b60d57fb9f058146c Mon Sep 17 00:00:00 2001
From: jMyles <justin@justinholmes.com>
Date: Sun, 26 Jul 2020 18:55:11 -0700
Subject: [PATCH] Some more debug-level logs instead of prints.

---
 nucypher/characters/base.py                               | 1 +
 nucypher/characters/lawful.py                             | 3 ++-
 nucypher/network/nodes.py                                 | 6 +++---
 nucypher/policy/policies.py                               | 5 ++++-
 tests/fixtures.py                                         | 3 ++-
 tests/integration/learning/test_firstula_circumstances.py | 1 +
 6 files changed, 13 insertions(+), 6 deletions(-)

diff --git a/nucypher/characters/base.py b/nucypher/characters/base.py
index 570a1febc..f123db90f 100644
--- a/nucypher/characters/base.py
+++ b/nucypher/characters/base.py
@@ -559,4 +559,5 @@ class Character(Learner):
         return controller
 
     def disenchant(self):
+        self.log.debug(f"Disenchanting {self}")
         Learner.stop_learning_loop(self)
diff --git a/nucypher/characters/lawful.py b/nucypher/characters/lawful.py
index 61c13d594..68df5f1de 100644
--- a/nucypher/characters/lawful.py
+++ b/nucypher/characters/lawful.py
@@ -445,7 +445,7 @@ class Alice(Character, BlockchainPolicyAuthor):
         return controller
 
     def disenchant(self):
-        print(f"disenchanting {self}")
+        self.log.debug(f"disenchanting {self}")
         super().disenchant()
         self.publication_threadpool.stop()
 
@@ -1253,6 +1253,7 @@ class Ursula(Teacher, Character, Worker):
 
     def stop(self, halt_reactor: bool = False) -> None:
         """Stop services"""
+        self.log.debug(f"---------Stopping {self}")
         self._availability_tracker.stop()
         self.stop_learning_loop()
         if not self.federated_only:
diff --git a/nucypher/network/nodes.py b/nucypher/network/nodes.py
index cef2d9837..5afa23bde 100644
--- a/nucypher/network/nodes.py
+++ b/nucypher/network/nodes.py
@@ -519,7 +519,7 @@ class Learner:
 
         import datetime
 
-        print(f"+++++++++++{self} deferring learning cycle at {datetime.datetime.now()}")
+        self.log.debug(f"+++++++++++{self} deferring learning cycle at {datetime.datetime.now()}")
 
         # while self._learning_deferred is not None:
         #     print(f"^^^^^^^^^{self} waiting at {datetime.datetime.now()}")
@@ -531,9 +531,9 @@ class Learner:
         self._learning_deferred = Deferred(canceller=self._discovery_canceller)  # TODO: No longer relevant.
 
         def _discover_or_abort(_first_result):
-            print(f"========={self} learning at {datetime.datetime.now()}")
+            self.log.debug(f"========={self} learning at {datetime.datetime.now()}")
             result = self.learn_from_teacher_node(eager=False, canceller=self._discovery_canceller)
-            print(f"///////////{self} finished learning at {datetime.datetime.now()}")
+            self.log.debug(f"///////////{self} finished learning at {datetime.datetime.now()}")
             return result
 
         self._learning_deferred.addCallback(_discover_or_abort)
diff --git a/nucypher/policy/policies.py b/nucypher/policy/policies.py
index ab9cfcc47..a2afcdf7a 100644
--- a/nucypher/policy/policies.py
+++ b/nucypher/policy/policies.py
@@ -166,6 +166,7 @@ class BlockchainArrangement(Arrangement):
 
 
 class PolicyPayloadMutex(DeferredList):
+    log = Logger("Policy")
 
     def __init__(self, deferredList, percent_to_complete_before_release=5, *args, **kwargs):
         self.percent_to_complete_before_release = percent_to_complete_before_release
@@ -185,7 +186,9 @@ class PolicyPayloadMutex(DeferredList):
         """
         https://www.youtube.com/watch?v=OkSLswPSq2o
         """
-        return self._policy_locking_queue.get()
+        _ = self._policy_locking_queue.get()  # Interesting opportuntiy to pass some data, like the list of contacted nodes above.
+        self.log.debug(f"{self.finishedCount} nodes were contacted while blocking for a little while.")
+        return
 
 
 class Policy(ABC):
diff --git a/tests/fixtures.py b/tests/fixtures.py
index a7de74425..feafdbee2 100644
--- a/tests/fixtures.py
+++ b/tests/fixtures.py
@@ -118,7 +118,7 @@ from umbral.signing import Signer
 
 test_logger = Logger("test-logger")
 
-defer.setDebugging(True)
+# defer.setDebugging(True)
 
 #
 # Temporary
@@ -386,6 +386,7 @@ def federated_ursulas(ursula_federated_test_config):
     yield _ursulas
 
     for port in _ports_to_remove:
+        test_logger.debug(f"Removing {port} ({MOCK_KNOWN_URSULAS_CACHE[port]}).")
         del MOCK_KNOWN_URSULAS_CACHE[port]
 
     for u in _ursulas:
diff --git a/tests/integration/learning/test_firstula_circumstances.py b/tests/integration/learning/test_firstula_circumstances.py
index 52b76d729..241149129 100644
--- a/tests/integration/learning/test_firstula_circumstances.py
+++ b/tests/integration/learning/test_firstula_circumstances.py
@@ -30,6 +30,7 @@ def test_proper_seed_node_instantiation(lonely_ursula_maker):
     any_other_ursula = _lonely_ursula_maker(seed_nodes=[firstula_as_seed_node], domains=["useless domain"]).pop()
 
     assert not any_other_ursula.known_nodes
+    # print(f"**********************Starting {any_other_ursula} loop")
     any_other_ursula.start_learning_loop(now=True)
     assert firstula in any_other_ursula.known_nodes