Ticket #1118: debugging-1118-2.dpatch.txt

Sun Jul 18 16:03:56 MDT 2010  zooko@zooko.com
  * immutable: use PrefixingLogMixin to organize logging in Tahoe2PeerSelector and add more detailed messages about peer

New patches:

[immutable: use PrefixingLogMixin to organize logging in Tahoe2PeerSelector and add more detailed messages about peer
zooko@zooko.com**20100718220356
 Ignore-this: f0ff7ac3345ff269b7f5bedbbea208e
] {
hunk ./src/allmydata/immutable/upload.py 77
 # TODO: actual extensions are closer to 419 bytes, so we can probably lower
 # this.
 
+def pretty_print_shnum_to_servers(s):
+    return ', '.join([ "sh%s: %s" % (k, '+'.join([idlib.shortnodeid_b2a(x) for x in v])) for k, v in s.iteritems() ])
+
 class PeerTracker:
     def __init__(self, peerid, storage_server,
                  sharesize, blocksize, num_segments, num_share_hashes,
hunk ./src/allmydata/immutable/upload.py 150
         for writer in self.buckets.itervalues(): writer.abort()
 
 
-class Tahoe2PeerSelector:
+class Tahoe2PeerSelector(PrefixingLogMixin):
 
     def __init__(self, upload_id, logparent=None, upload_status=None):
         self.upload_id = upload_id
hunk ./src/allmydata/immutable/upload.py 161
         self.num_peers_contacted = 0
         self.last_failure_msg = None
         self._status = IUploadStatus(upload_status)
-        self._log_parent = log.msg("%s starting" % self, parent=logparent)
+        PrefixingLogMixin.__init__(self, 'tahoe.immutable.upload', logparent, prefix=upload_id)
+        self.log("starting", level=log.OPERATIONAL)
 
     def __repr__(self):
         return "<Tahoe2PeerSelector for upload %s>" % self.upload_id
hunk ./src/allmydata/immutable/upload.py 267
             ds.append(d)
             self.num_peers_contacted += 1
             self.query_count += 1
-            log.msg("asking peer %s for any existing shares for "
-                    "upload id %s"
-                    % (idlib.shortnodeid_b2a(peer.peerid), self.upload_id),
-                    level=log.NOISY, parent=self._log_parent)
+            self.log("asking peer %s for any existing shares" %
+                     (idlib.shortnodeid_b2a(peer.peerid),),
+                    level=log.NOISY)
         dl = defer.DeferredList(ds)
         dl.addCallback(lambda ign: self._loop())
         return dl
hunk ./src/allmydata/immutable/upload.py 281
         Tahoe2PeerSelector._existing_shares.
         """
         if isinstance(res, failure.Failure):
-            log.msg("%s got error during existing shares check: %s"
+            self.log("%s got error during existing shares check: %s"
                     % (idlib.shortnodeid_b2a(peer), res),
hunk ./src/allmydata/immutable/upload.py 283
-                    level=log.UNUSUAL, parent=self._log_parent)
+                    level=log.UNUSUAL)
             self.error_count += 1
             self.bad_query_count += 1
         else:
hunk ./src/allmydata/immutable/upload.py 290
             buckets = res
             if buckets:
                 self.peers_with_shares.add(peer)
-            log.msg("response from peer %s: alreadygot=%s"
+            self.log("response to get_buckets() from peer %s: alreadygot=%s"
                     % (idlib.shortnodeid_b2a(peer), tuple(sorted(buckets))),
hunk ./src/allmydata/immutable/upload.py 292
-                    level=log.NOISY, parent=self._log_parent)
+                    level=log.NOISY)
             for bucket in buckets:
                 self.preexisting_shares.setdefault(bucket, set()).add(peer)
                 if self.homeless_shares and bucket in self.homeless_shares:
hunk ./src/allmydata/immutable/upload.py 326
             merged = merge_peers(self.preexisting_shares, self.use_peers)
             effective_happiness = servers_of_happiness(merged)
             if self.servers_of_happiness <= effective_happiness:
-                msg = ("peer selection successful for %s: %s" % (self,
-                            self._get_progress_message()))
-                log.msg(msg, parent=self._log_parent)
+                msg = ("peer selection successful for %s: %s: %s" % (self,
+                            self._get_progress_message(), pretty_print_shnum_to_servers(merged)))
+                self.log(msg, level=log.OPERATIONAL)
                 return (self.use_peers, self.preexisting_shares)
             else:
                 # We're not okay right now, but maybe we can fix it by
hunk ./src/allmydata/immutable/upload.py 370
                                           self.needed_shares,
                                           self.servers_of_happiness,
                                           effective_happiness)
+                    self.log("server selection unsuccessful for %s: %s: %s" % (self, msg, self._get_progress_message(), pretty_print_shnum_to_servers(merged)), level=log.UNUSUAL)
                     return self._failed("%s (%s)" % (msg, self._get_progress_message()))
 
         if self.uncontacted_peers:
hunk ./src/allmydata/immutable/upload.py 393
         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,
+                self.log("starting second pass",
                         level=log.NOISY)
                 self._started_second_pass = True
             num_shares = mathutil.div_ceil(len(self.homeless_shares),
hunk ./src/allmydata/immutable/upload.py 431
                                 self._get_progress_message()))
                 if self.last_failure_msg:
                     msg += " (%s)" % (self.last_failure_msg,)
-                log.msg(msg, level=log.UNUSUAL, parent=self._log_parent)
+                self.log(msg, level=log.UNUSUAL)
                 return self._failed(msg)
             else:
                 # we placed enough to be happy, so we're done
hunk ./src/allmydata/immutable/upload.py 443
         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),
-                    level=log.UNUSUAL, parent=self._log_parent)
+            self.log("%s got error during peer selection: %s" % (peer, res),
+                    level=log.UNUSUAL)
             self.error_count += 1
             self.bad_query_count += 1
             self.homeless_shares = list(shares_to_ask) + self.homeless_shares
hunk ./src/allmydata/immutable/upload.py 463
                 self.last_failure_msg = msg
         else:
             (alreadygot, allocated) = res
-            log.msg("response from peer %s: alreadygot=%s, allocated=%s"
+            self.log("response to allocate_buckets() from peer %s: alreadygot=%s, allocated=%s"
                     % (idlib.shortnodeid_b2a(peer.peerid),
                        tuple(sorted(alreadygot)), tuple(sorted(allocated))),
hunk ./src/allmydata/immutable/upload.py 466
-                    level=log.NOISY, parent=self._log_parent)
+                    level=log.NOISY)
             progress = False
             for s in alreadygot:
                 self.preexisting_shares.setdefault(s, set()).add(peer.peerid)
hunk ./src/allmydata/storage/server.py 8
 
 from zope.interface import implements
 from allmydata.interfaces import RIStorageServer, IStatsProducer
-from allmydata.util import fileutil, log, time_format
+from allmydata.util import fileutil, idlib, log, time_format
 import allmydata # for __full_version__
 
 from allmydata.storage.common import si_b2a, si_a2b, storage_index_to_dir
hunk ./src/allmydata/storage/server.py 109
                                    expiration_sharetypes)
         self.lease_checker.setServiceParent(self)
 
+    def __repr__(self):
+        return "<StorageServer %s>" % (idlib.shortnodeid_b2a(self.my_nodeid),)
+
     def add_bucket_counter(self):
         statefile = os.path.join(self.storedir, "bucket_counter.state")
         self.bucket_counter = BucketCountingCrawler(self, statefile)
hunk ./src/allmydata/test/test_upload.py 736
     def _add_server(self, server_number, readonly=False):
         assert self.g, "I tried to find a grid at self.g, but failed"
         ss = self.g.make_server(server_number, readonly)
+        log.msg("just created a server, number: %s => %s" % (server_number, ss,))
         self.g.add_server(server_number, ss)
 
hunk ./src/allmydata/test/test_upload.py 739
-
     def _add_server_with_share(self, server_number, share_number=None,
                                readonly=False):
         self._add_server(server_number, readonly)
hunk ./src/allmydata/test/test_upload.py 799
         d.addCallback(_store_shares)
         return d
 
-
     def test_configure_parameters(self):
         self.basedir = self.mktemp()
         hooks = {0: self._set_up_nodes_extra_config}
}

Context:

[trivial: fix unused import (sorry about that, pyflakes)
zooko@zooko.com**20100718215133
 Ignore-this: c2414e443405072b51d552295f2c0e8c
] 
[tests, NEWS, CREDITS re: #1117
zooko@zooko.com**20100718203225
 Ignore-this: 1f08be2c692fb72cc0dd023259f11354
 Give Brian and Kevan promotions, move release date in NEWS to the 18th, commit Brian's test for #1117.
 fixes #1117
] 
[test/test_upload.py: test to see that aborted buckets are ignored by the storage server
Kevan Carstensen <kevan@isnotajoke.com>**20100716001046
 Ignore-this: cc075c24b1c86d737f3199af894cc780
] 
[test/test_storage.py: test for the new remote_abort semantics.
Kevan Carstensen <kevan@isnotajoke.com>**20100715232148
 Ignore-this: d3d6491f17bf670e770ca4b385007515
] 
[storage/immutable.py: make remote_abort btell the storage server about aborted buckets.
Kevan Carstensen <kevan@isnotajoke.com>**20100715232105
 Ignore-this: 16ab0090676355abdd5600ed44ff19c9
] 
[test/test_upload.py: changes to test plumbing for #1117 tests
Kevan Carstensen <kevan@isnotajoke.com>**20100715231820
 Ignore-this: 78a6d359d7bf8529d283e2815bf1e2de
 
     - Add a callRemoteOnly method to FakeBucketWriter.
     - Change the abort method in FakeBucketWriter to not return a
       RuntimeError.
] 
[immutable/upload.py: abort buckets if peer selection fails
Kevan Carstensen <kevan@isnotajoke.com>**20100715231714
 Ignore-this: 2a0b643a22284df292d8ed9d91b1fd37
] 
[test_encodingutil: correct an error in the previous patch to StdlibUnicode.test_open_representable.
david-sarah@jacaranda.org**20100718151420
 Ignore-this: af050955f623fbc0e4d78e15a0a8a144
] 
[NEWS: Forward-compatibility improvements for non-ASCII caps (#1051).
david-sarah@jacaranda.org**20100718143622
 Ignore-this: 1edfebc4bd38a3b5c35e75c99588153f
] 
[test_dirnode and test_web: don't use failUnlessReallyEqual in cases where the return type from simplejson.loads can vary between unicode and str. Use to_str when comparing URIs parsed from JSON.
david-sarah@jacaranda.org**20100718142915
 Ignore-this: c4e78ef4b1478dd400da71cf077ffa4a
] 
[test_encodingutil: StdlibUnicode.test_open_representable no longer uses a mock.
david-sarah@jacaranda.org**20100718125412
 Ignore-this: 4bf373a5e2dfe4209e5e364124af29a3
] 
[docs: add comment clarifying #1051
zooko@zooko.com**20100718053250
 Ignore-this: 6cfc0930434cbdbbc262dabb58f1505d
] 
[docs: update NEWS
zooko@zooko.com**20100718053225
 Ignore-this: 63d5c782ef84812e6d010f0590866831
] 
[Add tests of caps from the future that have non-ASCII characters in them (encoded as UTF-8). The changes to test_uri.py, test_client.py, and test_dirnode.py add tests of non-ASCII future caps in addition to the current tests. The changes to test_web.py just replace the tests of all-ASCII future caps with tests of non-ASCII future caps. We also change uses of failUnlessEqual to failUnlessReallyEqual, in order to catch cases where the type of a string is not as expected.
david-sarah@jacaranda.org**20100711200252
 Ignore-this: c2f193352369d32e06865f8f3e951894
] 
[Debian documentation update
jacob@appelbaum.net**20100305003004] 
[debian-docs-patch-final
jacob@appelbaum.net**20100304085955] 
[M-x whitespace-cleanup
zooko@zooko.com**20100718032739
 Ignore-this: babfd4af6ad2fc885c957fd5c8b10c3f
] 
[docs: tidy up NEWS a little
zooko@zooko.com**20100718032434
 Ignore-this: 54f2820fd1a37c8967609f6bfc4e5e18
] 
[benchmarking: update bench_dirnode.py to reflect the new directory interfaces
zooko@zooko.com**20100718031710
 Ignore-this: 368ba523dd3de80d9da29cd58afbe827
] 
[test_encodingutil: fix test_open_representable, which is only valid when run on a platform for which we know an unrepresentable filename.
david-sarah@jacaranda.org**20100718030333
 Ignore-this: c114d92c17714a5d4ae005c15267d60c
] 
[iputil.py: Add support for FreeBSD 7,8 and 9
francois@ctrlaltdel.ch**20100718022832
 Ignore-this: 1829b4cf4b91107f4cf87841e6167e99
 committed by: zooko@zooko.com
 date: 2010-07-17
 and I also patched: NEWS and CREDITS
] 
[NEWS: add snippet about #1083
zooko@zooko.com**20100718020653
 Ignore-this: d353a9d93cbc5a5e6ba4671f78d1e22b
] 
[fileutil: docstrings for non-obvious usage restrictions on methods of EncryptedTemporaryFile.
david-sarah@jacaranda.org**20100717054647
 Ignore-this: 46d8fc10782fa8ec2b6c5b168c841943
] 
[Move EncryptedTemporaryFile from SFTP frontend to allmydata.util.fileutil, and make the FTP frontend also use it (fixing #1083).
david-sarah@jacaranda.org**20100711213721
 Ignore-this: e452e8ca66391aa2a1a49afe0114f317
] 
[NEWS: reorder NEWS snippets to be in descending order of interestingness
zooko@zooko.com**20100718015929
 Ignore-this: 146c42e88a9555a868a04a69dd0e5326
] 
[Correct stringutils->encodingutil patch to be the newer version, rather than the old version that was committed in error.
david-sarah@jacaranda.org**20100718013435
 Ignore-this: c8940c4e1aa2e9acc80cd4fe54753cd8
] 
[test_cli.py: fix error that crept in when rebasing the patch for #1072.
david-sarah@jacaranda.org**20100718000123
 Ignore-this: 3e8f6cc3a27b747c708221dd581934f4
] 
[stringutils: add test for when sys.stdout has no encoding attribute (fixes #1099).
david-sarah@jacaranda.org**20100717045816
 Ignore-this: f28dce6940e909f12f354086d17db54f
] 
[CLI: add 'tahoe unlink' as an alias to 'tahoe rm', for forward-compatibility.
david-sarah@jacaranda.org**20100717220411
 Ignore-this: 3ecdde7f2d0498514cef32e118e0b855
] 
[minor code clean-up in dirnode.py
zooko@zooko.com**20100714060255
 Ignore-this: bb0ab2783203e605024b3e2f798256a1
 Impose micro-POLA by passing only the writekey instead of the whole node object to {{{_encrypt_rw_uri()}}}. Remove DummyImmutableFileNode in nodemaker.py, which is obviated by this. Add micro-optimization by precomputing the netstring of the empty string and branching on whether the writekey is present or not outside of {{{_encrypt_rw_uri()}}}. Add doc about writekey to docstring.
 fixes #967
] 
[Rename stringutils to encodingutil, and drop listdir_unicode and open_unicode (since the Python stdlib functions work fine with Unicode paths). Also move some utility functions to fileutil.
david-sarah@jacaranda.org**20100712003015
 Ignore-this: 103b809d180df17a7283077c3104c7be
] 
[Allow URIs passed in the initial JSON for t=mkdir-with-children, t=mkdir-immutable to be Unicode. Also pass the name of each child into nodemaker.create_from_cap for error reporting.
david-sarah@jacaranda.org**20100711195525
 Ignore-this: deac32d8b91ba26ede18905d3f7d2b93
] 
[docs: CREDITS and NEWS
zooko@zooko.com**20100714060150
 Ignore-this: dc83e612f77d69e50ee975f07f6b16fe
] 
[CREDITS: more creds for Kevan, plus utf-8 BOM
zooko@zooko.com**20100619045503
 Ignore-this: 72d02bdd7a0f324f1cee8cd399c7c6de
] 
[cli.py: make command descriptions consistently end with a full stop.
david-sarah@jacaranda.org**20100714014538
 Ignore-this: 9ee7fa29ca2d1631db4049c2a389a97a
] 
[SFTP: address some of the comments in zooko's review (#1106).
david-sarah@jacaranda.org**20100712025537
 Ignore-this: c3921638a2d4f1de2a776ae78e4dc37e
] 
[docs/logging.txt: note that setting flogging vars might affect tests with race conditions.
david-sarah@jacaranda.org**20100712050721
 Ignore-this: fc1609d215fcd5561a57fd1226206f27
] 
[test_storage.py: potential fix for failures when logging is enabled.
david-sarah@jacaranda.org**19700713040546
 Ignore-this: 5815693a0df3e64c52c3c6b7be2846c7
] 
[upcase_since_on_welcome
terrellrussell@gmail.com**20100708193903] 
[server_version_on_welcome_page.dpatch.txt
freestorm77@gmail.com**20100605191721
 Ignore-this: b450c76dc875f5ac8cca229a666cbd0a
 
 
 - The storage server version is 0 for all storage nodes in the Welcome Page
 
 
] 
[NEWS: add NEWS snippets about two recent patches
zooko@zooko.com**20100708162058
 Ignore-this: 6c9da6a0ad7351a960bdd60f81532899
] 
[directory_html_top_banner.dpatch
freestorm77@gmail.com**20100622205301
 Ignore-this: 1d770d975e0c414c996564774f049bca
 
 The div tag with the link "Return to Welcome page" on the directory.xhtml page is not correct
 
] 
[tahoe_css_toolbar.dpatch
freestorm77@gmail.com**20100622210046
 Ignore-this: 5b3ebb2e0f52bbba718a932f80c246c0
 
 CSS modification to be correctly diplayed with Internet Explorer 8
 
 The links on the top of page directory.xhtml are not diplayed in the same line as display with Firefox.
 
] 
[runnin_test_tahoe_css.dpatch
freestorm77@gmail.com**20100622214714
 Ignore-this: e0db73d68740aad09a7b9ae60a08c05c
 
 Runnin test for changes in tahoe.css file
 
] 
[runnin_test_directory_xhtml.dpatch
freestorm77@gmail.com**20100622201403
 Ignore-this: f8962463fce50b9466405cb59fe11d43
 
 Runnin test for diretory.xhtml top banner
 
] 
[stringutils.py: tolerate sys.stdout having no 'encoding' attribute.
david-sarah@jacaranda.org**20100626040817
 Ignore-this: f42cad81cef645ee38ac1df4660cc850
] 
[quickstart.html: python 2.5 -> 2.6 as recommended version
david-sarah@jacaranda.org**20100705175858
 Ignore-this: bc3a14645ea1d5435002966ae903199f
] 
[SFTP: don't call .stopProducing on the producer registered with OverwriteableFileConsumer (which breaks with warner's new downloader).
david-sarah@jacaranda.org**20100628231926
 Ignore-this: 131b7a5787bc85a9a356b5740d9d996f
] 
[docs/how_to_make_a_tahoe-lafs_release.txt: trivial correction, install.html should now be quickstart.html.
david-sarah@jacaranda.org**20100625223929
 Ignore-this: 99a5459cac51bd867cc11ad06927ff30
] 
[setup: in the Makefile, refuse to upload tarballs unless someone has passed the environment variable "BB_BRANCH" with value "trunk"
zooko@zooko.com**20100619034928
 Ignore-this: 276ddf9b6ad7ec79e27474862e0f7d6
] 
[trivial: tiny update to in-line comment
zooko@zooko.com**20100614045715
 Ignore-this: 10851b0ed2abfed542c97749e5d280bc
 (I'm actually committing this patch as a test of the new eager-annotation-computation of trac-darcs.)
] 
[docs: about.html link to home page early on, and be decentralized storage instead of cloud storage this time around
zooko@zooko.com**20100619065318
 Ignore-this: dc6db03f696e5b6d2848699e754d8053
] 
[docs: update about.html, especially to have a non-broken link to quickstart.html, and also to comment out the broken links to "for Paranoids" and "for Corporates"
zooko@zooko.com**20100619065124
 Ignore-this: e292c7f51c337a84ebfeb366fbd24d6c
] 
[TAG allmydata-tahoe-1.7.0
zooko@zooko.com**20100619052631
 Ignore-this: d21e27afe6d85e2e3ba6a3292ba2be1
] 
Patch bundle hash:
907c4692228657ec5455679c0a22c438f3ccba86