hierarchical logging: add numbered messages and parent= args

diff --git a/src/allmydata/mutable.py b/src/allmydata/mutable.py
index 3fbe6fb9f4c9c66aec46253ddcaa1a9494b7574f..661afc49335a207a8aedb405b005ebaaf2de45e1 100644 (file)
--- a/src/allmydata/mutable.py
+++ b/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 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 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
 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._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):
 
     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):
 
     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
 
     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.
 
         # 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
 
         initial_query_count = 5
         self._read_size = 2000
 


@@ -703,13 +708,20 @@ class Publish:
 
     def __init__(self, filenode):
         self._node = filenode
 
     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):
 
     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):
 
     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
 
     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
 
         # 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"
 
         self._writekey = self._node.get_writekey()
         assert self._writekey, "need write capability to publish"
 

diff --git a/src/allmydata/node.py b/src/allmydata/node.py
index 99b559f2b81efcd2a6e2619714dc751c5fb46fff..ff1345c26fba2144ebcfef8ca45fa892e22e2f83 100644 (file)
--- a/src/allmydata/node.py
+++ b/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 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
 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
 
                     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:
         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`)
                 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
 
     def _setup_tub(self, local_addresses):
         # we can't get a dynamically-assigned portnum until our Tub is

diff --git a/src/allmydata/test/test_introducer.py b/src/allmydata/test/test_introducer.py
index aebd94500b85bcbbb57da884b4cd0dba49ed94d0..35e805be221b1ea1e63a3d5e6112aff527f32527 100644 (file)
--- a/src/allmydata/test/test_introducer.py
+++ b/src/allmydata/test/test_introducer.py
@@ -16,8 +16,8 @@ class MyNode(Referenceable):
     pass
 
 class LoggingMultiService(service.MultiService):
     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):
 
 class TestIntroducerNode(testutil.SignalMixin, unittest.TestCase):
     def test_loadable(self):

diff --git a/src/allmydata/test/test_mutable.py b/src/allmydata/test/test_mutable.py
index ca4e7ae6b559643a77fb6f13c407c63fea931743..eda4ec29d15126f33aec98f70eb2825d61b79930 100644 (file)
--- a/src/allmydata/test/test_mutable.py
+++ b/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._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)
 
     def log(self, msg):
         log.msg(msg)
 

diff --git a/src/allmydata/test/test_node.py b/src/allmydata/test/test_node.py
index c66a76f3df41138c5ce65dd699966d9767a8990b..702288ac7a7116dab2cef9ca43b59e150ea21430 100644 (file)
--- a/src/allmydata/test/test_node.py
+++ b/src/allmydata/test/test_node.py
@@ -14,7 +14,7 @@ from allmydata.util import testutil, fileutil
 from allmydata import logpublisher
 
 class LoggingMultiService(service.MultiService):
 from allmydata import logpublisher
 
 class LoggingMultiService(service.MultiService):

-    def log(self, msg):
+    def log(self, msg, **kw):

         pass
 
 class TestNode(Node):
         pass
 
 class TestNode(Node):

diff --git a/src/allmydata/test/test_util.py b/src/allmydata/test/test_util.py
index 284bf5e5f82384743d8fc3258678d45424786a7f..eaaf636d3019fae9a77fb145a5510f776513de36 100644 (file)
--- a/src/allmydata/test/test_util.py
+++ b/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
 
 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 bencode, idlib, humanreadable, mathutil

-from allmydata.util import assertutil, fileutil, testutil
+from allmydata.util import assertutil, fileutil, testutil, log

 
 
 class IDLib(unittest.TestCase):
 
 
 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)
         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)
+

diff --git a/src/allmydata/util/log.py b/src/allmydata/util/log.py
new file mode 100644 (file)
index 0000000..77a0d8d
--- /dev/null
+++ b/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