upload: improve logging

diff --git a/src/allmydata/encode.py b/src/allmydata/encode.py
index 3f51fae1a0b858b2942fab60d9859e6c9b14c781..2467aaf69e564cb2e336df37e522aa3f12cdc644 100644 (file)
--- a/src/allmydata/encode.py
+++ b/src/allmydata/encode.py
@@ -5,7 +5,7 @@ from twisted.internet import defer
 from foolscap import eventual
 from allmydata import uri
 from allmydata.hashtree import HashTree
-from allmydata.util import mathutil, hashutil, idlib
+from allmydata.util import mathutil, hashutil, idlib, log
 from allmydata.util.assertutil import _assert
 from allmydata.codec import CRSEncoder
 from allmydata.interfaces import IEncoder, IStorageBucketWriter, \
@@ -89,19 +89,19 @@ class Encoder(object):
         self._codec = None
         self._parent = parent
         if self._parent:
-            self._log_number = self._parent.log("starting Encoder %s" % self)
+            self._log_number = self._parent.log("creating Encoder %s" % self)
 
     def __repr__(self):
         if hasattr(self, "_storage_index"):
             return "<Encoder for %s>" % idlib.b2a(self._storage_index)[:6]
         return "<Encoder for unknown storage index>"
 
-    def log(self, msg, parent=None):
+    def log(self, *args, **kwargs):
         if not self._parent:
             return
-        if parent is None:
-            parent = self._log_number
-        return self._parent.log(msg, parent=parent)
+        if "parent" not in kwargs:
+            kwargs["parent"] = self._log_number
+        return self._parent.log(*args, **kwargs)
 
     def set_size(self, size):
         assert not self._codec
@@ -214,7 +214,8 @@ class Encoder(object):
         self.landlords = landlords.copy()
 
     def start(self):
-        self.log("starting")
+        if self._parent:
+            self._log_number = self._parent.log("%s starting" % (self,))
         #paddedsize = self._size + mathutil.pad_size(self._size, self.needed_shares)
         if not self._codec:
             self._setup_codec()
@@ -413,10 +414,10 @@ class Encoder(object):
             return defer.succeed(None)
         sh = self.landlords[shareid]
         lognum2 = self.log("put_block to %s" % self.landlords[shareid],
-                           parent=lognum)
+                           parent=lognum, level=log.NOISY)
         d = sh.put_block(segment_num, subshare)
         def _done(res):
-            self.log("put_block done", parent=lognum2)
+            self.log("put_block done", parent=lognum2, level=log.NOISY)
             return res
         d.addCallback(_done)
         d.addErrback(self._remove_shareholder, shareid,

diff --git a/src/allmydata/upload.py b/src/allmydata/upload.py
index a0ef6af7700ca4e0da9bcca0c08ba84d61981f33..3036d04b1584aa7c1d85397b7c2bf0b5f45cbcd7 100644 (file)
--- a/src/allmydata/upload.py
+++ b/src/allmydata/upload.py
@@ -105,12 +105,13 @@ class PeerTracker:
 
 class Tahoe2PeerSelector:
 
-    def __init__(self, upload_id):
+    def __init__(self, upload_id, logparent=None):
         self.upload_id = upload_id
         self.query_count, self.good_query_count, self.bad_query_count = 0,0,0
         self.error_count = 0
         self.num_peers_contacted = 0
         self.last_failure_msg = None
+        self._log_parent = log.msg("%s starting" % self, parent=logparent)
 
     def __repr__(self):
         return "<Tahoe2PeerSelector for upload %s>" % self.upload_id
@@ -131,6 +132,7 @@ class Tahoe2PeerSelector:
         # self.uncontacted_peers = list() # peers we haven't asked yet
         self.contacted_peers = [] # peers worth asking again
         self.contacted_peers2 = [] # peers that we have asked again
+        self._started_second_pass = False
         self.use_peers = set() # PeerTrackers that have shares assigned to them
         self.preexisting_shares = {} # sharenum -> PeerTracker holding the share
 
@@ -183,7 +185,8 @@ class Tahoe2PeerSelector:
                     self.query_count, self.num_peers_contacted,
                     self.good_query_count, self.bad_query_count,
                     self.error_count))
-            log.msg("peer selection successful for %s: %s" % (self, msg))
+            log.msg("peer selection successful for %s: %s" % (self, msg),
+                    parent=self._log_parent)
             return self.use_peers
 
         if self.uncontacted_peers:
@@ -200,6 +203,10 @@ class Tahoe2PeerSelector:
             return d
         elif self.contacted_peers:
             # ask a peer that we've already asked.
+            if not self._started_second_pass:
+                log.msg("starting second pass", parent=self._log_parent,
+                        level=log.NOISY)
+                self._started_second_pass = True
             num_shares = mathutil.div_ceil(len(self.homeless_shares),
                                            len(self.contacted_peers))
             peer = self.contacted_peers.pop(0)
@@ -232,7 +239,7 @@ class Tahoe2PeerSelector:
                 msg = "peer selection failed for %s: %s" % (self, msg)
                 if self.last_failure_msg:
                     msg += " (%s)" % (self.last_failure_msg,)
-                log.msg(msg)
+                log.msg(msg, level=log.UNUSUAL, parent=self._log_parent)
                 raise encode.NotEnoughPeersError(msg)
             else:
                 # we placed enough to be happy, so we're done
@@ -242,7 +249,8 @@ class Tahoe2PeerSelector:
         if isinstance(res, failure.Failure):
             # This is unusual, and probably indicates a bug or a network
             # problem.
-            log.msg("%s got error during peer selection: %s" % (peer, res))
+            log.msg("%s got error during peer selection: %s" % (peer, res),
+                    level=log.UNUSUAL, parent=self._log_parent)
             self.error_count += 1
             self.homeless_shares = list(shares_to_ask) + self.homeless_shares
             if (self.uncontacted_peers
@@ -260,6 +268,10 @@ class Tahoe2PeerSelector:
                 self.last_failure_msg = msg
         else:
             (alreadygot, allocated) = res
+            log.msg("response from peer %s: alreadygot=%s, allocated=%s"
+                    % (idlib.shortnodeid_b2a(peer.peerid),
+                       tuple(sorted(alreadygot)), tuple(sorted(allocated))),
+                    level=log.NOISY, parent=self._log_parent)
             progress = False
             for s in alreadygot:
                 self.preexisting_shares[s] = peer
@@ -428,10 +440,12 @@ class CHKUploader:
     def set_params(self, encoding_parameters):
         self._encoding_parameters = encoding_parameters
 
-    def log(self, msg, parent=None, **kwargs):
-        if parent is None:
-            parent = self._log_number
-        return self._client.log(msg, parent=parent, **kwargs)
+    def log(self, *args, **kwargs):
+        if "parent" not in kwargs:
+            kwargs["parent"] = self._log_number
+        if "facility" not in kwargs:
+            kwargs["facility"] = "tahoe.upload"
+        return self._client.log(*args, **kwargs)
 
     def start(self, uploadable):
         """Start uploading the file.
@@ -467,7 +481,7 @@ class CHKUploader:
         storage_index = encoder.get_param("storage_index")
         upload_id = idlib.b2a(storage_index)[:6]
         self.log("using storage index %s" % upload_id)
-        peer_selector = self.peer_selector_class(upload_id)
+        peer_selector = self.peer_selector_class(upload_id, self._log_number)
 
         share_size = encoder.get_param("share_size")
         block_size = encoder.get_param("block_size")