From cc1612aee5ff96aabeefc0387659cffcb1f5a809 Mon Sep 17 00:00:00 2001 From: Brian Warner 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