Significant progress on #121

py_src/base.py

@@ -16,9 +16,11 @@
 
 from collections import namedtuple
 from itertools import chain
+from logging import (getLogger, INFO, DEBUG)
 
 from .utils import (
-    getUTC, intersect, get_lan_ip, get_socket, sanitize_packet, inherit_doc)
+    getUTC, intersect, get_lan_ip, get_socket, sanitize_packet, inherit_doc,
+    log_entry)
 
 protocol_version = "0.5"
 node_policy_version = "607"
@@ -573,6 +575,7 @@ def len(self):
 
 class base_connection(object):
     """The base class for a connection"""
+    @log_entry('py2p.base.base_connection.__init__', DEBUG)
     def __init__(self, sock, server, outgoing=False):
         """Sets up a connection to another peer-to-peer socket
 
@@ -744,6 +747,7 @@ def __print__(self, *args, **kargs):
 
 class base_daemon(object):
     """The base class for a daemon"""
+    @log_entry('py2p.base.base_daemon.__init__', DEBUG)
     def __init__(self, addr, port, server):
         """Sets up a daemon process for your peer-to-peer socket
 
@@ -764,6 +768,11 @@ def __init__(self, addr, port, server):
         self.sock.settimeout(0.1)
         self.exceptions = []
         self.alive = True
+        self._logger = getLogger(
+            '{}.{}.{}'.format(
+                self.__class__.__module__,
+                self.__class__.__name__,
+                self.server.id))
         self.main_thread = threading.current_thread()
         self.daemon = threading.Thread(target=self.mainloop)
         self.daemon.start()
@@ -828,6 +837,7 @@ def __print__(self, *args, **kargs):
 
 class base_socket(object):
     """The base class for a peer-to-peer socket abstractor"""
+    @log_entry('py2p.base.base_socket.__init__', DEBUG)
     def __init__(self, addr, port, prot=default_protocol, out_addr=None,
                  debug_level=0):
         """Initializes a peer to peer socket
@@ -861,6 +871,11 @@ def __init__(self, addr, port, prot=default_protocol, out_addr=None,
         info = (str(self.out_addr).encode(), prot.id, user_salt)
         h = hashlib.sha384(b''.join(info))
         self.id = to_base_58(int(h.hexdigest(), 16))
+        self._logger = getLogger(
+            '{}.{}.{}'.format(
+                self.__class__.__module__,
+                self.__class__.__name__,
+                self.id))
         self.__handlers = []
         self.__closed = False
 
@@ -1051,15 +1066,20 @@ def reply(self, *args):
                        prefixed with base.flags.whisper, so the other end will
                        receive ``[base.flags.whisper, *args]``
         """
+        self.server._logger.debug('Initiating a direct reply to message ID {}'.format(self.id))
         if self.server.routing_table.get(self.sender):
             self.server.routing_table.get(self.sender).send(
                 flags.whisper, flags.whisper, *args)
         else:
+            self.server._logger.debug('Requesting connection for direct reply '
+                                      'to message ID {}'.format(self.id))
             request_hash = hashlib.sha384(
                 self.sender + to_base_58(getUTC())).hexdigest()
             request_id = to_base_58(int(request_hash, 16))
             self.server.send(request_id, self.sender, type=flags.request)
             self.server.requests[request_id] = (flags.whisper, flags.whisper) + tuple(args)
-            print("You aren't connected to the original sender. This reply "
-                  "is not guarunteed, but we're trying to make a connection"
-                  " and put the message through.")
+            self.server._logger.critical("You aren't connected to the original "
+                                         "sender. This reply is not guarunteed,"
+                                         " but we're trying to make a "
+                                         "connection and put the message "
+                                         "through.")

py_src/chord.py

@@ -14,6 +14,8 @@
 
 from itertools import chain
 
+from logging import (DEBUG, INFO)
+
 try:
     from .cbase import protocol
 except:
@@ -25,7 +27,8 @@
 from .mesh import (
     mesh_connection, mesh_daemon, mesh_socket)
 from .utils import (
-    inherit_doc, getUTC, get_socket, intersect, awaiting_value, most_common)
+    inherit_doc, getUTC, get_socket, intersect, awaiting_value, most_common,
+    log_entry)
 
 max_outgoing = 4
 default_protocol = protocol('chord', "Plaintext")  # SSL")
@@ -69,6 +72,7 @@ class chord_connection(mesh_connection):
     """The class for chord connection abstraction. This inherits from
     :py:class:`py2p.mesh.mesh_connection`
     """
+    @log_entry('py2p.chord.chord_connection.__init__', DEBUG)
     @inherit_doc(mesh_connection.__init__)
     def __init__(self, *args, **kwargs):
         super(chord_connection, self).__init__(*args, **kwargs)
@@ -90,6 +94,7 @@ class chord_daemon(mesh_daemon):
     """The class for chord daemon.
     This inherits from :py:class:`py2p.mesh.mesh_daemon`
     """
+    @log_entry('py2p.chord.chord_daemon.__init__', DEBUG)
     @inherit_doc(mesh_daemon.__init__)
     def __init__(self, *args, **kwargs):
         super(chord_daemon, self).__init__(*args, **kwargs)
@@ -104,6 +109,7 @@ def handle_accept(self):
 
 class chord_socket(mesh_socket):
     """The class for chord socket abstraction. This inherits from :py:class:`py2p.mesh.mesh_socket`"""
+    @log_entry('py2p.chord.chord_socket.__init__', DEBUG)
     @inherit_doc(mesh_socket.__init__)
     def __init__(self, addr, port, prot=default_protocol, out_addr=None, debug_level=0):
         if not hasattr(self, 'daemon'):
@@ -380,6 +386,7 @@ def __getitem__(self, key, timeout=10):
         """
         if not isinstance(key, (bytes, bytearray)):
             key = str(key).encode()
+        self._logger.debug('Getting value of {}'.format(key))
         keys = get_hashes(key)
         vals = [self.__lookup(method, x) for method, x in zip(hashes, keys)]
         common, count = most_common(vals)
@@ -458,6 +465,7 @@ def __setitem__(self, key, value):
             key = str(key).encode()
         if not isinstance(value, (bytes, bytearray)):
             value = str(value).encode()
+        self._logger.debug('Setting value of {} to {}'.format(key, value))
         keys = get_hashes(key)
         for method, x in zip(hashes, keys):
             self.__store(method, x, value)
@@ -584,6 +592,7 @@ def __connect(self, addr, port, id=None):
     def join(self):
         """Tells the node to start seeding the chord table"""
         # for handler in self.awaiting_ids:
+        self._logger.debug('Joining the network data store')
         self.leeching = False
         for handler in tuple(self.routing_table.values()) + tuple(self.awaiting_ids):
             self._send_handshake(handler)
@@ -592,6 +601,7 @@ def join(self):
 
     def unjoin(self):
         """Tells the node to stop seeding the chord table"""
+        self._logger.debug('Unjoining the network data store')
         self.leeching = True
         for handler in tuple(self.routing_table.values()) + tuple(self.awaiting_ids):
             self._send_handshake(handler)
@@ -614,6 +624,7 @@ def connect(self, *args, **kwargs):
 
     def keys(self):
         """Returns an iterator of the underlying :py:class:`dict`'s keys"""
+        self._logger.debug('Retrieving all keys')
         return (key for key in self.__keys if key in self.__keys)
 
     @inherit_doc(keys)
@@ -623,42 +634,40 @@ def __iter__(self):
     def values(self):
         """Returns:
             an iterator of the underlying :py:class:`dict`'s values
-
         Raises:
             KeyError:       If the key does not have a majority-recognized
                                 value
             socket.timeout: See KeyError
         """
+        self._logger.debug('Retrieving all values')
         return (self[key] for key in self.keys())
 
     def items(self):
         """Returns:
             an iterator of the underlying :py:class:`dict`'s items
-
         Raises:
             KeyError:       If the key does not have a majority-recognized
                                 value
             socket.timeout: See KeyError
         """
+        self._logger.debug('Retrieving all items')
         return ((key, self[key]) for key in self.keys())
 
     def pop(self, key, *args):
         """Returns a value, with the side effect of deleting that association
-
         Args:
             Key:        The key you wish to look up. Must be a :py:class:`str`
                             or :py:class:`bytes`-like object
             ifError:    The value you wish to return on Exception
                             (default: raise an Exception)
-
         Returns:
             The value of the supplied key, or ``ifError``
-
         Raises:
             KeyError:       If the key does not have a majority-recognized
                                 value
             socket.timeout: See KeyError
         """
+        self._logger.debug('Popping key {}'.format(key))
         if len(args):
             ret = self.get(key, args[0])
             if ret != args[0]:
@@ -671,26 +680,24 @@ def pop(self, key, *args):
     def popitem(self):
         """Returns an association, with the side effect of deleting that
         association
-
         Returns:
             An arbitrary association
-
         Raises:
             KeyError:       If the key does not have a majority-recognized
                                 value
             socket.timeout: See KeyError
         """
+        self._logger.debug('Popping an item')
         key, value = next(self.items())
         del self[key]
         return (key, value)
 
     def copy(self):
         """Returns a :py:class:`dict` copy of this DHT
-
         .. warning::
-
             This is a *very* slow operation. It's a far better idea to use
             :py:meth:`~py2p.chord.chord_socket.items`, as this produces an
             iterator. That should even out lag times
         """
+        self._logger.debug('Producing a dictionary copy')
         return dict(self.items())

py_src/mesh.py

@@ -13,6 +13,7 @@
 
 from collections import deque
 from itertools import chain
+from logging import (INFO, DEBUG)
 
 try:
     from .cbase import protocol
@@ -22,7 +23,7 @@
     flags, compression, to_base_58, from_base_58, base_connection, message,
     base_daemon, base_socket, InternalMessage, json_compressions)
 from .utils import (
-    getUTC, get_socket, intersect, inherit_doc)
+    getUTC, get_socket, intersect, inherit_doc, log_entry)
 
 max_outgoing = 4
 default_protocol = protocol('mesh', "Plaintext")  # SSL")
@@ -96,6 +97,7 @@ class mesh_daemon(base_daemon):
     """The class for mesh daemon.
     This inherits from :py:class:`py2p.base.base_daemon`
     """
+    @log_entry('py2p.mesh.mesh_daemon', DEBUG)
     @inherit_doc(base_daemon.__init__)
     def __init__(self, *args, **kwargs):
         super(mesh_daemon, self).__init__(*args, **kwargs)
@@ -165,6 +167,7 @@ class mesh_socket(base_socket):
     """The class for mesh socket abstraction.
     This inherits from :py:class:`py2p.base.base_socket`
     """
+    @log_entry('py2p.mesh.mesh_socket', DEBUG)
     def __init__(self, addr, port, prot=default_protocol, out_addr=None,
                  debug_level=0):
         """Initializes a mesh socket

py_src/utils.py

@@ -1,18 +1,29 @@
 from __future__ import print_function
 from __future__ import with_statement
 
-import base64
 import calendar
 import os
-import shutil
 import socket
-import tempfile
 import time
 
-try:
-    import cPickle as pickle
-except ImportError:
-    import pickle
+from logging import (getLogger, INFO, DEBUG)
+
+
+def log_entry(name, level):
+
+    def annotation(function):
+        log = getLogger(name)
+
+        def caller(*args, **kwargs):
+            log.log(level, "Entering function {}".format(name))
+            function(*args, **kwargs)
+            log.log(level, "Exiting function {}".format(name))
+
+        return caller
+
+    metalogger = getLogger('py2p.utils.log_entry')
+    metalogger.info('Adding log handler to {} at level {}'.format(name, level))
+    return annotation
 
 
 def _doc_merger(parent, child):
@@ -24,10 +35,13 @@ def _doc_merger(parent, child):
 def inherit_doc(function):
     """A decorator which allows you to inherit docstrings from a specified
     function."""
+    logger = getLogger('py2p.utils.inherit_doc')
+    logger.info('Parsing documentation inheritence for {}'.format(function))
     try:
         from custom_inherit import doc_inherit
         return doc_inherit(function, _doc_merger)
     except:
+        logger.info('custom_inherit is not available. Using default documentation')
         return lambda x: x  # If unavailable, just return the function
 
 
@@ -37,7 +51,9 @@ def sanitize_packet(packet):
     """
     if isinstance(packet, type(u'')):
         return packet.encode('utf-8')
-    elif not isinstance(packet, (bytes, bytearray)):
+    elif isinstance(packet, bytearray):
+        return bytes(packet)
+    elif not isinstance(packet, bytes):
         return packet.encode('raw_unicode_escape')
     return packet