Add logging in different places

src/netns/environ.py

@@ -56,8 +56,7 @@ except:
             "continue.")
 
 def execute(cmd):
-    # FIXME: create a global debug variable
-    #print "[pid %d]" % os.getpid(), " ".join(cmd)
+    debug("execute(%s)" % cmd)
     null = open("/dev/null", "r+")
     p = subprocess.Popen(cmd, stdout = null, stderr = subprocess.PIPE)
     out, err = p.communicate()
@@ -65,6 +64,7 @@ def execute(cmd):
         raise RuntimeError("Error executing `%s': %s" % (" ".join(cmd), err))
 
 def backticks(cmd):
+    debug("backticks(%s)" % cmd)
     p = subprocess.Popen(cmd, stdout = subprocess.PIPE,
             stderr = subprocess.PIPE)
     out, err = p.communicate()
@@ -132,3 +132,15 @@ def info(message):
     logger(LOG_INFO, message)
 def debug(message):
     logger(LOG_DEBUG, message)
+
+# Used to print extra info in nested exceptions
+def _custom_hook(t, v, tb): # pragma: no cover
+    if hasattr(v, "child_traceback"):
+        sys.stderr.write("Nested exception, original traceback " +
+                "(most recent call last):\n")
+        sys.stderr.write(v.child_traceback + ("-" * 70) + "\n")
+    sys.__excepthook__(t, v, tb)
+
+# XXX: somebody kill me, I deserve it :)
+sys.excepthook = _custom_hook
+

src/netns/interface.py

@@ -2,6 +2,7 @@
 
 import os, weakref
 import netns.iproute
+from netns.environ import *
 
 __all__ = ['NodeInterface', 'P2PInterface', 'ImportedInterface',
 'ImportedNodeInterface', 'Switch']
@@ -24,8 +25,11 @@ class Interface(object):
 
     def __init__(self, index):
         self._idx = index
+        debug("%s(0x%x).__init__(), index = %d" % (self.__class__.__name__,
+            id(self), index))
 
     def __del__(self):
+        debug("%s(0x%x).__del__()" % (self.__class__.__name__, id(self)))
         self.destroy()
 
     def destroy(self):
@@ -135,7 +139,9 @@ class NodeInterface(NSInterface):
         return self._control
 
     def destroy(self):
-        if self._slave:
+        if not self._slave:
+            return
+        debug("NodeInterface(0x%x).destroy()" % id(self))
         if self.index in self._slave.get_if_data():
             self._slave.del_if(self.index)
         self._slave = None
@@ -174,7 +180,9 @@ class P2PInterface(NSInterface):
         raise RuntimeError(P2PInterface.__init__.__doc__)
 
     def destroy(self):
-        if self._slave:
+        if not self._slave:
+            return
+        debug("P2PInterface(0x%x).destroy()" % id(self))
         if self.index in self._slave.get_if_data():
             self._slave.del_if(self.index)
         self._slave = None
@@ -206,6 +214,7 @@ class ImportedNodeInterface(NSInterface):
     def destroy(self): # override: restore as much as possible
         if not self._slave:
             return
+        debug("ImportedNodeInterface(0x%x).destroy()" % id(self))
         if self.index in self._slave.get_if_data():
             if self._migrate:
                 self._slave.change_netns(self.index, os.getpid())
@@ -235,7 +244,9 @@ class TapNodeInterface(NSInterface):
         return self._fd
 
     def destroy(self):
-        if self._fd:
+        if not self._fd:
+            return
+        debug("TapNodeInterface(0x%x).destroy()" % id(self))
         try:
             os.close(self._fd)
         except:
@@ -317,6 +328,7 @@ class ImportedInterface(ExternalInterface):
     # FIXME: register somewhere for destruction!
     def destroy(self): # override: restore as much as possible
         if self._original_state:
+            debug("ImportedInterface(0x%x).destroy()" % id(self))
             netns.iproute.set_if(self._original_state)
         self._original_state = None
 
@@ -368,6 +380,7 @@ class Switch(ExternalInterface):
     def destroy(self):
         if not self.index:
             return
+        debug("Switch(0x%x).destroy()" % id(self))
         self.up = False
         for p in self._ports.values():
             try:

src/netns/node.py

@@ -15,13 +15,12 @@ class Node(object):
         s = sorted(Node._nodes.items(), key = lambda x: x[0])
         return [x[1] for x in s]
 
-    def __init__(self, debug = 0, nonetns = False):
+    def __init__(self, nonetns = False):
         """Create a new node in the emulation. Implemented as a separate
         process in a new network name space. Requires root privileges to run.
 
         If keepns is true, the network name space is not created and can be
-        run as a normal user, for testing. If debug is true, details of the
-        communication protocol are printed on stderr."""
+        run as a normal user, for testing."""
 
         # Initialize attributes, in case something fails during __init__
         self._pid = self._slave = None
@@ -29,10 +28,10 @@ class Node(object):
         self._interfaces = weakref.WeakValueDictionary()
         self._auto_interfaces = [] # just to keep them alive!
 
-        fd, pid = _start_child(debug, nonetns)
+        fd, pid = _start_child(nonetns)
         self._pid = pid
-        self._debug = debug
-        self._slave = netns.protocol.Client(fd, fd, debug)
+        debug("Node(0x%x).__init__(), pid = %s" % (id(self), pid))
+        self._slave = netns.protocol.Client(fd, fd)
 
         Node._nodes[Node._nextnode] = self
         Node._nextnode += 1
@@ -42,14 +41,11 @@ class Node(object):
             self.get_interface("lo").up = True
 
     def __del__(self):
-        if self._debug: # pragma: no cover
-            sys.stderr.write("*** Node(%s) __del__\n" % self.pid)
+        debug("Node(0x%x).__del__()" % id(self))
         self.destroy()
 
     def destroy(self):
-        if self._debug: # pragma: no cover
-            sys.stderr.write("*** Node(%s) destroy\n" % self.pid)
-
+        debug("Node(0x%x).destroy()" % id(self))
         for p in self._processes.values():
             p.destroy()
         self._processes.clear()
@@ -126,8 +122,7 @@ class Node(object):
         # by the way, clean up _interfaces
         for i in list(self._interfaces): # copy before deleting!
             if i not in ifaces:
-                if self._debug:
-                    sys.stderr.write("WARNING: interface #%d went away.\n" % i)
+                notice("Node(0x%x): interface #%d went away." % (id(self), i))
                 self._interfaces[i].destroy()
                 del self._interfaces[i]
 
@@ -159,7 +154,7 @@ class Node(object):
 # Handle the creation of the child; parent gets (fd, pid), child creates and
 # runs a Server(); never returns.
 # Requires CAP_SYS_ADMIN privileges to run.
-def _start_child(debug, nonetns):
+def _start_child(nonetns):
     # Create socket pair to communicate
     (s0, s1) = socket.socketpair(socket.AF_UNIX, socket.SOCK_STREAM, 0)
     # Spawn a child that will run in a loop
@@ -171,7 +166,7 @@ def _start_child(debug, nonetns):
     # FIXME: clean up signal handers, atexit functions, etc.
     try:
         s0.close()
-        srv = netns.protocol.Server(s1, s1, debug)
+        srv = netns.protocol.Server(s1, s1)
         if not nonetns:
             # create new name space
             unshare.unshare(unshare.CLONE_NEWNET)

src/netns/protocol.py

@@ -3,6 +3,7 @@
 
 import base64, os, passfd, re, signal, sys, traceback, unshare
 import netns.subprocess_, netns.iproute
+from netns.environ import *
 
 try:
     from cPickle import loads, dumps
@@ -66,13 +67,12 @@ class Server(object):
     """Class that implements the communication protocol and dispatches calls
     to the required functions. Also works as the main loop for the slave
     process."""
-    def __init__(self, rfd, wfd, debug = 0):
+    def __init__(self, rfd, wfd):
+        debug("Server(0x%x).__init__()" % id(self))
         # Dictionary of valid commands
         self._commands = _proto_commands
         # Flag to stop the server
         self._closed = False
-        # Print debug info
-        self._debug = debug
         # Set to keep track of started processes
         self._children = set()
         # Buffer and flag for PROC mode
@@ -92,13 +92,11 @@ class Server(object):
         for i in range(len(clean) - 1):
             s = str(code) + "-" + clean[i] + "\n"
             self._wfd.write(s)
-            if self._debug > 1: # pragma: no cover
-                sys.stderr.write("<ans> %s" % s)
+            debug("<Reply> %s" % s)
 
         s = str(code) + " " + clean[-1] + "\n"
         self._wfd.write(s)
-        if self._debug > 1: # pragma: no cover
-            sys.stderr.write("<S> %s" % s)
+        debug("<Reply> %s" % s)
         return
 
     def readline(self):
@@ -107,8 +105,7 @@ class Server(object):
         if not line:
             self._closed = True
             return None
-        if self._debug > 1: # pragma: no cover
-            sys.stderr.write("<C> %s" % line)
+        debug("<Query> %s" % line)
         return line.rstrip()
 
     def readcmd(self):
@@ -183,8 +180,7 @@ class Server(object):
             j += 1
 
         func = getattr(self, funcname)
-        if self._debug > 2: # pragma: no cover
-            sys.stderr.write("<cmd> %s, args: %s\n" % (cmdname, args))
+        debug("Command: %s, args: %s" % (cmdname, args))
         return (func, cmdname, args)
 
     def run(self):
@@ -208,6 +204,7 @@ class Server(object):
             self._wfd.close()
         except:
             pass
+        debug("Server(0x%x) exiting" % id(self))
         # FIXME: cleanup
 
     # Commands implementation
@@ -397,16 +394,15 @@ class Server(object):
 class Client(object):
     """Client-side implementation of the communication protocol. Acts as a RPC
     service."""
-    def __init__(self, rfd, wfd, debug = 0):
-        self._debug = debug
+    def __init__(self, rfd, wfd):
+        debug("Client(0x%x).__init__()" % id(self))
         self._rfd = _get_file(rfd, "r")
         self._wfd = _get_file(wfd, "w")
         # Wait for slave to send banner
         self._read_and_check_reply()
 
     def __del__(self):
-        if self._debug:
-            sys.stderr.write("*** Client(%d) __del__\n" % id(self))
+        debug("Client(0x%x).__del__()" % id(self))
         self.shutdown()
 
     def _send_cmd(self, *args):
@@ -451,8 +447,7 @@ class Client(object):
         "Tell the client to quit."
         if not self._wfd:
             return
-        if self._debug:
-            sys.stderr.write("*** Client(%d) shutdown\n" % id(self))
+        debug("Client(0x%x).shutdown()" % id(self))
 
         self._send_cmd("QUIT")
         self._read_and_check_reply()

src/netns/subprocess_.py

@@ -409,14 +409,4 @@ try:
 except: # pragma: no cover
     MAXFD = 256
 
-# Used to print extra info in nested exceptions
-def _custom_hook(t, v, tb): # pragma: no cover
-    if hasattr(v, "child_traceback"):
-        sys.stderr.write("Nested exception, original traceback " +
-                "(most recent call last):\n")
-        sys.stderr.write(v.child_traceback + ("-" * 70) + "\n")
-    sys.__excepthook__(t, v, tb)
-
-# XXX: somebody kill me, I deserve it :)
-sys.excepthook = _custom_hook
 

test/test_core.py

@@ -4,6 +4,7 @@
 import grp, os, pwd, select, time, unittest
 import netns, test_util
 
+netns.environ.set_log_level(netns.environ.LOG_DEBUG)
 class TestConfigure(unittest.TestCase):
     def test_config_run_as_static(self):
         # Don't allow root as default user

test/test_protocol.py

@@ -35,7 +35,7 @@ class TestServer(unittest.TestCase):
         (s0, s1) = socket.socketpair(socket.AF_UNIX, socket.SOCK_STREAM, 0)
 
         def run_server():
-            netns.protocol.Server(s0, s0, debug = 0).run()
+            netns.protocol.Server(s0, s0).run()
         t = threading.Thread(target = run_server)
         t.start()
 
@@ -57,7 +57,7 @@ class TestServer(unittest.TestCase):
 
     def test_basic_stuff(self):
         (s0, s1) = socket.socketpair(socket.AF_UNIX, socket.SOCK_STREAM, 0)
-        srv = netns.protocol.Server(s0, s0, debug = 0)
+        srv = netns.protocol.Server(s0, s0)
         s1 = s1.makefile("r+", 1)
 
         def check_error(self, cmd, code = 500):

test/test_subprocess.py

@@ -123,7 +123,7 @@ class TestSubprocess(unittest.TestCase):
         self.assertEquals(wait(p), 0)
 
     def test_Subprocess_basic(self):
-        node = netns.Node(nonetns = True, debug = 0)
+        node = netns.Node(nonetns = True)
         # User does not exist
         self.assertRaises(ValueError, Subprocess, node,
                 ['/bin/sleep', '1000'], user = self.nouser)
@@ -179,7 +179,7 @@ class TestSubprocess(unittest.TestCase):
         self.assertEquals(p.wait(), -signal.SIGTERM)
 
     def test_Popen(self):
-        node = netns.Node(nonetns = True, debug = 0)
+        node = netns.Node(nonetns = True)
 
         # repeat test with Popen interface
         r0, w0 = os.pipe()
@@ -269,7 +269,7 @@ class TestSubprocess(unittest.TestCase):
         self.assertEquals(p.communicate(_longstring), (_longstring, ) * 2)
 
     def test_backticks(self):
-        node = netns.Node(nonetns = True, debug = 0)
+        node = netns.Node(nonetns = True)
         self.assertEquals(backticks(node, "echo hello world"), "hello world\n")
         self.assertEquals(backticks(node, r"echo hello\ \ world"),
                 "hello  world\n")
@@ -281,7 +281,7 @@ class TestSubprocess(unittest.TestCase):
         self.assertRaises(RuntimeError, backticks_raise, node, "kill $$")
 
     def test_system(self):
-        node = netns.Node(nonetns = True, debug = 0)
+        node = netns.Node(nonetns = True)
         self.assertEquals(system(node, "true"), 0)
         self.assertEquals(system(node, "false"), 1)