Use the logging module instead of just print

client.py

@@ -3,6 +3,7 @@
 import random # For simulation, not cryptography!
 import math
 import sys
+import logging
 
 import network
 import dirauth
@@ -74,7 +75,7 @@ class TelescopingCreatedHandler:
         self.idkey = self.channelmgr.guard.snipdict['idkey']
 
     def received_cell(self, circhandler, cell):
-        print("LOG: Received cell in TelescopingCreatedHandler")
+        logging.debug("Received cell in TelescopingCreatedHandler")
 
         secret = self.ntor.verify(cell.ntor_reply, self.onionkey, self.idkey)
         enckey = nacl.hash.sha256(secret + b'upstream')
@@ -112,7 +113,7 @@ class TelescopingExtendedHandler:
         self.ntor = ntor
 
     def received_cell(self, circhandler, cell):
-        print("LOG: Received cell in TelescopingExtendedHandler")
+        logging.debug("Received cell in TelescopingExtendedHandler")
 
         # Validate the SNIP
         dirauth.SNIP.verify(cell.snip, self.channelmgr.consensus,
@@ -132,16 +133,16 @@ class TelescopingExtendedHandler:
         circhandler.circuit_descs.append(cell.snip)
 
         # Are we done building the circuit?
-        print("WARNING: we may need another circhandler structure for snips")
+        logging.warning("we may need another circhandler structure for snips")
         if len(circhandler.circuit_descs) == 3:
-            print("Log: Circuit is long enough; exiting.")
+            logging.debug("Circuit is long enough; exiting.")
             # Yes!
             return
 
         nexthopidx = None
         while nexthopidx is None:
             nexthopidx = self.channelmgr.relaypicker.pick_weighted_relay_index()
-            print("WARNING: Unimplemented! Need to check if this idx is in the list of circhandlers idxs")
+            logging.warning("Unimplemented! Need to check if this idx is in the list of circhandlers idxs")
 
         # Construct the VanillaExtendCircuitCell
         ntor = relay.NTor(self.channelmgr.perfstats)
@@ -191,7 +192,7 @@ class ClientChannelManager(relay.ChannelManager):
             if self.guardaddr is not None:
                 break
 
-        print('chose guard=', self.guardaddr)
+        logging.debug('chose guard=%s', self.guardaddr)
 
     def test_guard_connection(self):
             # Connect to the guard
@@ -213,7 +214,7 @@ class ClientChannelManager(relay.ChannelManager):
         while True:
             if self.guardaddr is None:
                 #randomly-sample a guard
-                print("WARNING: Unimplemented! guard should be selected from any relays.")
+                logging.warning("Unimplemented! guard should be selected from any relays.")
                 self.guard = self.relaypicker.pick_weighted_relay()
                 # here, we have a SNIP instead of a relay descriptor
                 self.guardaddr = self.guard.snipdict['addr']
@@ -223,7 +224,7 @@ class ClientChannelManager(relay.ChannelManager):
             if self.guardaddr is not None:
                 break
 
-        print('chose guard=', self.guardaddr)
+        logging.debug('chose guard=%s', self.guardaddr)
 
     def ensure_guard(self):
         """Ensure that we have a channel to a guard."""
@@ -287,7 +288,7 @@ class ClientChannelManager(relay.ChannelManager):
         # was an error when establishing it, the circuit could already be
         # closed.
         if not guardchannel.is_circuit_open(circid):
-            print("ERR: Circuit was already closed, not sending bytes. circid: " + str(circid))
+            logging.debug("Circuit was already closed, not sending bytes. circid: " + str(circid))
             return None
 
         return circhandler
@@ -319,11 +320,11 @@ class ClientChannelManager(relay.ChannelManager):
         # was an error when establishing it, the circuit could already be
         # closed.
         if not guardchannel.is_circuit_open(circid):
-            print("ERR: Circuit was already closed, not sending bytes. circid: " + str(circid))
+            logging.debug("Circuit was already closed, not sending bytes. circid: " + str(circid))
             return None
 
         #TODO validate the Sphinx keys on reply
-        print("WARNING: Unimplemented! The client should validate the NTOR handshake using Sphinx operations here.")
+        logging.warning("Unimplemented! The client should validate the NTOR handshake using Sphinx operations here.")
 
         return circhandler
 
@@ -347,7 +348,7 @@ class ClientChannelManager(relay.ChannelManager):
     def received_msg(self, msg, peeraddr, channel):
         """Callback when a NetMsg not specific to a circuit is
         received."""
-        print("Client %s received msg %s from %s" % (self.myaddr, msg, peeraddr))
+        logging.debug("Client %s received msg %s from %s" % (self.myaddr, msg, peeraddr))
         if isinstance(msg, relay.RelayConsensusMsg) or \
                 isinstance(msg, relay.RelayConsensusDiffMsg):
             self.relaypicker = dirauth.Consensus.verify(msg.consensus,
@@ -358,9 +359,9 @@ class ClientChannelManager(relay.ChannelManager):
 
     def received_cell(self, circid, cell, peeraddr, channel):
         """Callback with a circuit-specific cell is received."""
-        print("Client %s received cell on circ %d: %s from %s" % (self.myaddr, circid, cell, peeraddr))
+        logging.debug("Client %s received cell on circ %d: %s from %s" % (self.myaddr, circid, cell, peeraddr))
         if isinstance(msg, relay.CloseCell):
-            print("Log: Client received close cell; closing circuit")
+            logging.debug("Log: Client received close cell; closing circuit")
             # TODO close cell
         return super().received_cell(circid, cell, peeraddr, channel)
 
@@ -409,15 +410,15 @@ class Client:
                 guardaddr = None
 
         if guardchannel is None:
-            print("In bootstrapping mode")
+            logging.debug("In bootstrapping mode")
             self.channelmgr.get_consensus_from_fallbackrelay()
-            print('client consensus=', self.channelmgr.consensus)
+            logging.debug('client consensus=%s', self.channelmgr.consensus)
             return
 
         if network.thenetwork.womode == network.WOMode.VANILLA:
             if self.channelmgr.consensus is not None and len(self.channelmgr.consensus.consdict['relays']) > 0:
                 guardchannel.send_msg(relay.RelayGetConsensusDiffMsg())
-                print('got consensus diff, client consensus=', self.channelmgr.consensus)
+                logging.debug('got consensus diff, client consensus=%s', self.channelmgr.consensus)
                 return
 
         # At this point, we are in one of the following scenarios:
@@ -427,7 +428,7 @@ class Client:
             #    consensus and needs to bootstrap it.
 
         guardchannel.send_msg(relay.RelayGetConsensusMsg())
-        print('client consensus=', self.channelmgr.consensus)
+        logging.debug('client consensus=%s', self.channelmgr.consensus)
 
     def newepoch(self, epoch):
         """Callback that fires at the start of each epoch"""
@@ -453,6 +454,8 @@ if __name__ == '__main__':
         print("must pass in network mode: options are vanilla, telescoping, or single-pass.")
         sys.exit(0)
 
+    logging.basicConfig(level=logging.DEBUG)
+
     network_mode = network.WOMode.string_to_type(sys.argv[1])
     if network_mode == -1:
         print("Not a valid network mode: " + network_mode)
@@ -460,6 +463,9 @@ if __name__ == '__main__':
 
     #TODO Add a command-line switch to set Merkle or Threshold
 
+    # Initialize the (non-cryptographic) random seed
+    random.seed(1)
+
     if network_mode == network.WOMode.VANILLA:
         network.thenetwork.set_wo_style(network.WOMode.VANILLA,
             network.SNIPAuthMode.NONE)

dirauth.py

@@ -3,6 +3,7 @@
 import random # For simulation, not cryptography!
 import bisect
 import math
+import logging
 
 import nacl.encoding
 import nacl.signing
@@ -262,7 +263,7 @@ class RelayPicker:
                 self.cdf.append(self.cdf[-1]+r.descdict['bw'])
             # Remove the last item, which should be the sum of all the bws
             self.cdf.pop()
-            print('cdf=', self.cdf)
+            logging.debug('cdf=%s', self.cdf)
         else:
             # Note that clients will call this with endive = None
             if self.endive is not None:
@@ -280,7 +281,7 @@ class RelayPicker:
                             self.merkletree.merkle_root)
             else:
                 self.cdf = None
-            print('cdf=', self.cdf)
+            logging.debug('cdf=%s', self.cdf)
 
     @staticmethod
     def get(consensus, endive = None):

network.py

@@ -2,6 +2,7 @@
 
 import random
 import pickle
+import logging
 from enum import Enum
 
 # Set this to True if you want the bytes sent and received to be added
@@ -219,9 +220,6 @@ class Network:
 # The singleton instance of Network
 thenetwork = Network()
 
-# Initialize the (non-cryptographic) random seed
-random.seed(1)
-
 class NetMsg:
     """The parent class of network messages.  Subclass this class to
     implement specific kinds of network messages."""
@@ -258,11 +256,11 @@ class Connection:
         self.peer = peer
 
     def closed(self):
-        print("connection closed with", self.peer)
+        logging.debug("connection closed with %s", self.peer)
         self.peer = None
 
     def close(self):
-        print("closing connection with", self.peer)
+        logging.debug("closing connection with %s", self.peer)
         self.peer.closed()
         self.peer = None
 
@@ -304,7 +302,7 @@ class ServerConnection(Connection):
         self.peer.received(netmsg)
 
     def received(self, client, netmsg):
-        print("received", netmsg, "from client", client)
+        logging.debug("received %s from client %s", netmsg, client)
 
 
 class Server:
@@ -334,7 +332,7 @@ class Server:
         """Callback invoked when a client connects to this server.
         This callback must create the Connection object that will be
         returned to the client."""
-        print("server", self, "conected to client", client)
+        logging.debug("server %s connected to client %s", self, client)
         serverconnection = ServerConnection()
         clientconnection = ClientConnection(serverconnection)
         serverconnection.peer = clientconnection
@@ -349,6 +347,9 @@ if __name__ == '__main__':
     assert(n1 != n2)
     print(n1, n2)
 
+    # Initialize the (non-cryptographic) random seed
+    random.seed(1)
+
     srv = Server("hello world server")
 
     thenetwork.printservers()

relay.py

@@ -3,6 +3,7 @@
 import random # For simulation, not cryptography!
 import math
 import sys
+import logging
 
 import nacl.utils
 import nacl.signing
@@ -446,7 +447,7 @@ class TelescopingExtendCircuitHandler:
         # Check to make sure that we aren't extending to ourselves. If we are,
         # close the circuit.
         if next_snip.snipdict["idkey"] == self.current_relay_idkey:
-            print("ERR: Client requested extending the circuit to a relay already in the path; aborting. my circid: " + str(circhandler.circid))
+            logging.debug("Client requested extending the circuit to a relay already in the path; aborting. my circid: %s", str(circhandler.circid))
             circhandler.close()
             return
 
@@ -495,7 +496,7 @@ class TelescopingCreatedRelayHandler:
         self.next_snip = next_snip
 
     def received_cell(self, circhandler, cell):
-        print("LOG: Handle a TelescopingCreatedCircui received by a relay")
+        logging.debug("Handle a TelescopingCreatedCircuit received by a relay")
         # Remove ourselves from handling a second
         # VanillaCreatedCircuitCell on this circuit
         circhandler.replace_celltype_handler(TelescopingCreatedCircuitCell, None)
@@ -551,7 +552,7 @@ class CircuitHandler:
         adjacent circuit, if present) and closes both."""
         adjcirchandler = self.adjacent_circuit_handler
         self.adjacent_circuit_handler = None
-        print("Log: CLosing circuit. circid: " + str(self.circid))
+        logging.debug("Closing circuit. circid: %s", str(self.circid))
         if adjcirchandler is not None:
             adjcirchandler.adjacent_circuit_handler = None
         self.closer()
@@ -575,7 +576,7 @@ class CircuitHandler:
         if isinstance(cell, EncryptedCell):
             cell = self.crypt_layer.decrypt_msg(cell)
 
-        print("CircuitHandler: %s received cell %s on circuit %d from %s" % (self.channel.channelmgr.myaddr, cell, self.circid, self.channel.peer.channelmgr.myaddr))
+        logging.debug("CircuitHandler: %s received cell %s on circuit %d from %s" % (self.channel.channelmgr.myaddr, cell, self.circid, self.channel.peer.channelmgr.myaddr))
 
         # If it's still encrypted, it's for sure meant for forwarding to
         # our adjacent hop, which had better exist.
@@ -590,12 +591,12 @@ class CircuitHandler:
 
             elif isinstance(cell, StringCell):
                 # Default handler; just print the message in the cell
-                print("CircuitHandler: %s received '%s' on circuit %d from %s" \
+                logging.debug("CircuitHandler: %s received '%s' on circuit %d from %s" \
                         % (self.channel.channelmgr.myaddr, cell,
                             self.circid, self.channel.peer.channelmgr.myaddr))
 
             elif isinstance(cell, CloseCell):
-                print("WARNING: Received CloseCell on circuit " + str(self.circid))
+                logging.debug("Received CloseCell on circuit %s", str(self.circid))
                 # Forward the CloseCell (without encryption) to the
                 # adjacent circuit, if any, and close both this and the
                 # adjacent circuit
@@ -656,7 +657,7 @@ class Channel(network.Connection):
         while self.circuithandlers:
             chitems = iter(self.circuithandlers.items())
             circid, circhandler = next(chitems)
-            print('closing circuit', circid)
+            logging.debug('closing circuit %s', circid)
             circhandler.close()
         self.closer()
         self.peer = None
@@ -704,7 +705,7 @@ class Channel(network.Connection):
 
     def received(self, peeraddr, msg):
         """Callback when a message is received from the network."""
-        print('Channel: %s received %s from %s' % (self.channelmgr.myaddr, msg, peeraddr))
+        logging.debug('Channel: %s received %s from %s' % (self.channelmgr.myaddr, msg, peeraddr))
         self.channelmgr.perfstats.bytes_received += msg.size()
         if isinstance(msg, CircuitCellMsg):
             circid, cell = msg.circid, msg.cell
@@ -733,7 +734,7 @@ class ChannelManager:
         while self.channels:
             channelitems = iter(self.channels.items())
             addr, channel = next(channelitems)
-            print('closing channel', addr, channel)
+            logging.debug('closing channel %s %s', addr, channel)
             channel.close()
 
     def add_channel(self, channel, peeraddr):
@@ -754,10 +755,10 @@ class ChannelManager:
             return self.channels[addr]
 
         # Create the new channel
-        print('getting channel from',self.myaddr,'to',addr)
+        logging.debug('getting channel from %s to %s',self.myaddr,addr)
         newchannel = network.thenetwork.connect(self.myaddr, addr,
                 self.perfstats)
-        print('got channel from',self.myaddr,'to',addr)
+        logging.debug('got channel from %s to %s',self.myaddr,addr)
         self.channels[addr] = newchannel
         newchannel.closer = lambda: self.channels.pop(addr)
         newchannel.channelmgr = self
@@ -767,11 +768,11 @@ class ChannelManager:
     def received_msg(self, msg, peeraddr, channel):
         """Callback when a NetMsg not specific to a circuit is
         received."""
-        print("ChannelManager: Node %s received msg %s from %s" % (self.myaddr, msg, peeraddr))
+        logging.debug("ChannelManager: Node %s received msg %s from %s" % (self.myaddr, msg, peeraddr))
 
     def received_cell(self, circid, cell, peeraddr, channel):
         """Callback with a circuit-specific cell is received."""
-        print("ChannelManager: Node %s received cell on circ %d: %s from %s" % (self.myaddr, circid, cell, peeraddr))
+        logging.debug("ChannelManager: Node %s received cell on circ %d: %s from %s" % (self.myaddr, circid, cell, peeraddr))
 
     def send_msg(self, msg, peeraddr):
         """Send a message to the peer with the given address."""
@@ -823,7 +824,7 @@ class RelayChannelManager(ChannelManager):
     def received_msg(self, msg, peeraddr, channel):
         """Callback when a NetMsg not specific to a circuit is
         received."""
-        print("RelayChannelManager: Node %s received msg %s from %s" % (self.myaddr, msg, peeraddr))
+        logging.debug("RelayChannelManager: Node %s received msg %s from %s" % (self.myaddr, msg, peeraddr))
         if isinstance(msg, RelayRandomHopMsg):
             if msg.ttl > 0:
                 # Pick a random next hop from the consensus
@@ -883,7 +884,7 @@ class RelayChannelManager(ChannelManager):
 
     def received_cell(self, circid, cell, peeraddr, channel):
         """Callback with a circuit-specific cell is received."""
-        print("RelayChannelManager: Node %s received cell on circ %d: %s from %s" % (self.myaddr, circid, cell, peeraddr))
+        logging.debug("RelayChannelManager: Node %s received cell on circ %d: %s from %s" % (self.myaddr, circid, cell, peeraddr))
         return super().received_cell(circid, cell, peeraddr, channel)
 
 
@@ -1013,6 +1014,9 @@ class Relay(network.Server):
 if __name__ == '__main__':
     perfstats = network.PerfStats(network.EntType.NONE)
 
+    # Initialize the (non-cryptographic) random seed
+    random.seed(1)
+
     network.thenetwork.set_wo_style(network.WOMode.TELESCOPING,
             network.SNIPAuthMode.MERKLE)