From cc1612aee5ff96aabeefc0387659cffcb1f5a809 Mon Sep 17 00:00:00 2001
From: Brian Warner <warner@allmydata.com>
Date: Mon, 19 Nov 2007 18:23:18 -0700
Subject: [PATCH] hierarchical logging: add numbered messages and parent= args
---
src/allmydata/mutable.py | 35 +++++++++++------
src/allmydata/node.py | 10 ++---
src/allmydata/test/test_introducer.py | 4 +-
src/allmydata/test/test_mutable.py | 1 -
src/allmydata/test/test_node.py | 2 +-
src/allmydata/test/test_util.py | 56 ++++++++++++++++++++++++++-
src/allmydata/util/log.py | 27 +++++++++++++
7 files changed, 113 insertions(+), 22 deletions(-)
create mode 100644 src/allmydata/util/log.py
diff --git a/src/allmydata/mutable.py b/src/allmydata/mutable.py
index 3fbe6fb9..661afc49 100644
--- 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 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"
diff --git a/src/allmydata/node.py b/src/allmydata/node.py
index 99b559f2..ff1345c2 100644
--- 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 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
diff --git a/src/allmydata/test/test_introducer.py b/src/allmydata/test/test_introducer.py
index aebd9450..35e805be 100644
--- 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):
- 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):
diff --git a/src/allmydata/test/test_mutable.py b/src/allmydata/test/test_mutable.py
index ca4e7ae6..eda4ec29 100644
--- 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.introducer_client = FakeIntroducerClient()
def log(self, msg):
log.msg(msg)
diff --git a/src/allmydata/test/test_node.py b/src/allmydata/test/test_node.py
index c66a76f3..702288ac 100644
--- 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):
- def log(self, msg):
+ def log(self, msg, **kw):
pass
class TestNode(Node):
diff --git a/src/allmydata/test/test_util.py b/src/allmydata/test/test_util.py
index 284bf5e5..eaaf636d 100644
--- 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
+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)
+
diff --git a/src/allmydata/util/log.py b/src/allmydata/util/log.py
new file mode 100644
index 00000000..77a0d8d0
--- /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
--
2.45.2