hierarchical logging: add numbered messages and parent= args

src/allmydata/mutable.py

@@ -3,10 +3,10 @@ import os, struct
 from itertools import islice
 from zope.interface import implements
 from twisted.internet import defer
-from twisted.python import failure, log
+from twisted.python import failure
 from foolscap.eventual import eventually
 from allmydata.interfaces import IMutableFileNode, IMutableFileURI
-from allmydata.util import hashutil, mathutil, idlib
+from allmydata.util import hashutil, mathutil, idlib, log
 from allmydata.uri import WriteableSSKFileURI
 from allmydata.Crypto.Cipher import AES
 from allmydata import hashtree, codec
@@ -205,13 +205,20 @@ class Retrieve:
         self._storage_index = filenode.get_storage_index()
         self._readkey = filenode.get_readkey()
         self._last_failure = None
+        self._log_number = None
+        self._log_prefix = prefix = idlib.b2a(self._storage_index)[:6]
+        num = self._node._client.log("Retrieve(%s): starting" % prefix)
+        self._log_number = num
 
     def log(self, msg):
-        prefix = idlib.b2a(self._node.get_storage_index())[:6]
-        self._node._client.log("Retrieve(%s): %s" % (prefix, msg))
+        prefix = self._log_prefix
+        num = self._node._client.log("Retrieve(%s): %s" % (prefix, msg),
+                                     parent=self._log_number)
+        return num
 
     def log_err(self, f):
-        log.err(f)
+        num = log.err(f, parent=self._log_number)
+        return num
 
     def retrieve(self):
         """Retrieve the filenode's current contents. Returns a Deferred that
@@ -252,8 +259,6 @@ class Retrieve:
         # 7: if we discover corrupt shares during the reconstruction process,
         #    remove that share from the sharemap.  and start step#6 again.
 
-        self.log("starting retrieval")
-
         initial_query_count = 5
         self._read_size = 2000
 
@@ -703,13 +708,20 @@ class Publish:
 
     def __init__(self, filenode):
         self._node = filenode
+        self._storage_index = self._node.get_storage_index()
+        self._log_prefix = prefix = idlib.b2a(self._storage_index)[:6]
+        num = self._node._client.log("Publish(%s): starting")
+        self._log_number = num
 
     def log(self, msg):
-        prefix = idlib.b2a(self._node.get_storage_index())[:6]
-        self._node._client.log("Publish(%s): %s" % (prefix, msg))
+        prefix = self._log_prefix
+        num = self._node._client.log("Publish(%s): %s" % (prefix, msg),
+                                     parent=self._log_number)
+        return num
 
     def log_err(self, f):
-        log.err(f)
+        num = log.err(f, parent=self._log_number)
+        return num
 
     def publish(self, newdata, wait_for_numpeers=None):
         """Publish the filenode's current contents.  Returns a Deferred that
@@ -745,9 +757,8 @@ class Publish:
         # 4a: may need to run recovery algorithm
         # 5: when enough responses are back, we're done
 
-        self.log("got enough peers, datalen is %s" % len(newdata))
+        self.log("starting publish, data is %r" % (newdata,))
 
-        self._storage_index = self._node.get_storage_index()
         self._writekey = self._node.get_writekey()
         assert self._writekey, "need write capability to publish"
 

src/allmydata/node.py

@@ -7,6 +7,7 @@ from twisted.python import log
 from twisted.application import service
 from twisted.internet import defer, reactor
 from foolscap import Tub, eventual
+from allmydata.util import log as tahoe_log
 from allmydata.util import iputil, observer, humanreadable
 from allmydata.util.assertutil import precondition
 from allmydata.logpublisher import LogPublisher
@@ -240,7 +241,7 @@ class Node(service.MultiService):
                     ob.formatTime = newmeth
         # TODO: twisted >2.5.0 offers maxRotatedFiles=50
 
-    def log(self, msg, src="", args=()):
+    def log(self, msg, src="", args=(), **kw):
         if src:
             logsrc = src
         else:
@@ -250,10 +251,9 @@ class Node(service.MultiService):
                 msg = msg % tuple(map(humanreadable.hr, args))
             except TypeError, e:
                 msg = "ERROR: output string '%s' contained invalid %% expansion, error: %s, args: %s\n" % (`msg`, e, `args`)
-
-        log.callWithContext({"system":logsrc},
-                            log.msg,
-                            (self.short_nodeid + ": " + humanreadable.hr(msg)))
+        msg = self.short_nodeid + ": " + humanreadable.hr(msg)
+        return log.callWithContext({"system":logsrc},
+                                   tahoe_log.msg, msg, **kw)
 
     def _setup_tub(self, local_addresses):
         # we can't get a dynamically-assigned portnum until our Tub is

src/allmydata/test/test_introducer.py

@@ -16,8 +16,8 @@ class MyNode(Referenceable):
     pass
 
 class LoggingMultiService(service.MultiService):
-    def log(self, msg):
-        log.msg(msg)
+    def log(self, msg, **kw):
+        log.msg(msg, **kw)
 
 class TestIntroducerNode(testutil.SignalMixin, unittest.TestCase):
     def test_loadable(self):

src/allmydata/test/test_mutable.py

@@ -111,7 +111,6 @@ class FakeClient:
         self._num_peers = num_peers
         self._peerids = [tagged_hash("peerid", "%d" % i)[:20]
                          for i in range(self._num_peers)]
-        self.introducer_client = FakeIntroducerClient()
     def log(self, msg):
         log.msg(msg)
 

src/allmydata/test/test_node.py

@@ -14,7 +14,7 @@ from allmydata.util import testutil, fileutil
 from allmydata import logpublisher
 
 class LoggingMultiService(service.MultiService):
-    def log(self, msg):
+    def log(self, msg, **kw):
         pass
 
 class TestNode(Node):

src/allmydata/test/test_util.py

@@ -4,8 +4,10 @@ def foo(): pass # keep the line number constant
 import os
 from twisted.trial import unittest
 
+from twisted.python import failure
+from twisted.python import log as twisted_log
 from allmydata.util import bencode, idlib, humanreadable, mathutil
-from allmydata.util import assertutil, fileutil, testutil
+from allmydata.util import assertutil, fileutil, testutil, log
 
 
 class IDLib(unittest.TestCase):
@@ -390,3 +392,55 @@ class PollMixinTests(unittest.TestCase):
         d = self.pm.poll(check_f=i.next,
                          pollinterval=0.1)
         return self._check(d)
+
+class SampleError(Exception):
+    pass
+
+class Log(unittest.TestCase):
+    def setUp(self):
+        self.catcher = []
+        twisted_log.addObserver(self.catcher.append)
+    def tearDown(self):
+        twisted_log.removeObserver(self.catcher.append)
+
+    def test_log(self):
+        num = log.msg("this is a message")
+        self.failUnless(isinstance(num, int))
+        log.msg("sub message", parent=num)
+        log.msg("numbered message", number=47)
+
+        f = failure.Failure(SampleError())
+        num2 = log.err(f)
+        log.err(f, parent=num2)
+        log.err(f, number=48)
+
+        logs = self.catcher[:]
+        self.flushLoggedErrors(SampleError)
+
+        self.failUnlessEqual(logs[0]['message'], ("this is a message",))
+        self.failUnlessEqual(logs[0]['number'], num)
+        self.failUnlessEqual(logs[0]['parent'], None)
+
+        self.failUnlessEqual(logs[1]['message'], ("sub message",))
+        self.failUnlessEqual(logs[1]['number'], num+1)
+        self.failUnlessEqual(logs[1]['parent'], num)
+
+        self.failUnlessEqual(logs[2]['message'], ("numbered message",))
+        self.failUnlessEqual(logs[2]['number'], 47)
+        self.failUnlessEqual(logs[2]['parent'], None)
+
+        self.failUnlessEqual(logs[3]['message'], ())
+        self.failUnlessEqual(logs[3]['failure'], f)
+        self.failUnlessEqual(logs[3]['number'], num2)
+        self.failUnlessEqual(logs[3]['parent'], None)
+
+        self.failUnlessEqual(logs[4]['message'], ())
+        self.failUnlessEqual(logs[4]['failure'], f)
+        self.failUnlessEqual(logs[4]['number'], num2+1)
+        self.failUnlessEqual(logs[4]['parent'], num2)
+
+        self.failUnlessEqual(logs[5]['message'], ())
+        self.failUnlessEqual(logs[5]['failure'], f)
+        self.failUnlessEqual(logs[5]['number'], 48)
+        self.failUnlessEqual(logs[5]['parent'], None)
+

src/allmydata/util/log.py

@@ -0,0 +1,27 @@
+
+import itertools
+from twisted.python import log
+
+counter = itertools.count()
+
+def msg(*message, **kw):
+    if 'number' not in kw:
+        number = counter.next()
+        kw['number'] = number
+    else:
+        number = kw['number']
+    if 'parent' not in kw:
+        kw['parent'] = None
+    log.msg(*message, **kw)
+    return number
+
+def err(*args, **kw):
+    if 'number' not in kw:
+        number = counter.next()
+        kw['number'] = number
+    else:
+        number = kw['number']
+    if 'parent' not in kw:
+        kw['parent'] = None
+    log.err(*args, **kw)
+    return number