Ticket #1170: comment-out-logging-in-immutable-download.dpatch.txt

File comment-out-logging-in-immutable-download.dpatch.txt, 35.4 KB (added by zooko, at 2010-08-20T16:46:42Z)
Line 
11 patch for repository zooko@tahoe-lafs.org:/home/source/darcs/tahoe-lafs/trunk:
2
3Fri Aug 20 08:18:28 MDT 2010  zooko@zooko.com
4  * comment-out almost all calls to log.msg() in immutable/downloader/
5  This is just for benchmarking purposes—to test the hypothesis that logging is slowing down the 1.8.0c2 downloader—and should not be committed to trunk.
6
7New patches:
8
9[comment-out almost all calls to log.msg() in immutable/downloader/
10zooko@zooko.com**20100820141828
11 Ignore-this: 5d6daf819ddbfe7a6d9537490da620e0
12 This is just for benchmarking purposes—to test the hypothesis that logging is slowing down the 1.8.0c2 downloader—and should not be committed to trunk.
13] {
14hunk ./src/allmydata/immutable/downloader/fetcher.py 49
15         self._running = True
16 
17     def stop(self):
18-        log.msg("SegmentFetcher(%s).stop" % self._node._si_prefix,
19-                level=log.NOISY, umid="LWyqpg")
20+        # log.msg("SegmentFetcher(%s).stop" % self._node._si_prefix,
21+        #         level=log.NOISY, umid="LWyqpg")
22         self._cancel_all_requests()
23         self._running = False
24         self._shares.clear() # let GC work # ??? XXX
25hunk ./src/allmydata/immutable/downloader/fetcher.py 118
26             # no more new shares are coming, and the remaining hopeful shares
27             # aren't going to be enough. boo!
28 
29-            log.msg("share states: %r" % (self._shares,),
30-                    level=log.NOISY, umid="0ThykQ")
31+            # log.msg("share states: %r" % (self._shares,),
32+            #         level=log.NOISY, umid="0ThykQ")
33             if self._count_shnums(AVAILABLE, PENDING, OVERDUE, COMPLETE) == 0:
34                 format = ("no shares (need %(k)d)."
35                           " Last failure: %(last_failure)s")
36hunk ./src/allmydata/immutable/downloader/fetcher.py 140
37                         "last_failure": self._last_failure,
38                         }
39                 error = NotEnoughSharesError
40-            log.msg(format=format, level=log.UNUSUAL, umid="1DsnTg", **args)
41+            # log.msg(format=format, level=log.UNUSUAL, umid="1DsnTg", **args)
42             e = error(format % args)
43             f = Failure(e)
44             self.stop()
45hunk ./src/allmydata/immutable/downloader/fetcher.py 207
46         # called by Shares, in response to our s.send_request() calls.
47         if not self._running:
48             return
49-        log.msg("SegmentFetcher(%s)._block_request_activity:"
50-                " Share(sh%d-on-%s) -> %s" %
51-                (self._node._si_prefix, shnum, share._peerid_s, state),
52-                level=log.NOISY, umid="vilNWA")
53+        # log.msg("SegmentFetcher(%s)._block_request_activity:"
54+        #         " Share(sh%d-on-%s) -> %s" %
55+        #         (self._node._si_prefix, shnum, share._peerid_s, state),
56+        #         level=log.NOISY, umid="vilNWA")
57         # COMPLETE, CORRUPT, DEAD, BADSEGNUM are terminal.
58         if state in (COMPLETE, CORRUPT, DEAD, BADSEGNUM):
59             self._share_observers.pop(share, None)
60hunk ./src/allmydata/immutable/downloader/finder.py 78
61 
62     # called by our parent CiphertextDownloader
63     def hungry(self):
64-        self.log(format="ShareFinder[si=%(si)s] hungry",
65-                 si=self._si_prefix, level=log.NOISY, umid="NywYaQ")
66+        # self.log(format="ShareFinder[si=%(si)s] hungry",
67+        #          si=self._si_prefix, level=log.NOISY, umid="NywYaQ")
68         self.start_finding_servers()
69         self._hungry = True
70         eventually(self.loop)
71hunk ./src/allmydata/immutable/downloader/finder.py 91
72                                   for s in self.undelivered_shares])
73         pending_s = ",".join([idlib.shortnodeid_b2a(rt.peerid)
74                               for rt in self.pending_requests]) # sort?
75-        self.log(format="ShareFinder loop: running=%(running)s"
76-                 " hungry=%(hungry)s, undelivered=%(undelivered)s,"
77-                 " pending=%(pending)s",
78-                 running=self.running, hungry=self._hungry,
79-                 undelivered=undelivered_s, pending=pending_s,
80-                 level=log.NOISY, umid="kRtS4Q")
81+        # self.log(format="ShareFinder loop: running=%(running)s"
82+        #          " hungry=%(hungry)s, undelivered=%(undelivered)s,"
83+        #          " pending=%(pending)s",
84+        #          running=self.running, hungry=self._hungry,
85+        #          undelivered=undelivered_s, pending=pending_s,
86+        #          level=log.NOISY, umid="kRtS4Q")
87         if not self.running:
88             return
89         if not self._hungry:
90hunk ./src/allmydata/immutable/downloader/finder.py 105
91             sh = self.undelivered_shares.pop(0)
92             # they will call hungry() again if they want more
93             self._hungry = False
94-            self.log(format="delivering Share(shnum=%(shnum)d, server=%(peerid)s)",
95-                     shnum=sh._shnum, peerid=sh._peerid_s,
96-                     level=log.NOISY, umid="2n1qQw")
97+            # self.log(format="delivering Share(shnum=%(shnum)d, server=%(peerid)s)",
98+            #          shnum=sh._shnum, peerid=sh._peerid_s,
99+            #          level=log.NOISY, umid="2n1qQw")
100             eventually(self.share_consumer.got_shares, [sh])
101             return
102 
103hunk ./src/allmydata/immutable/downloader/finder.py 135
104             # them will make progress
105             return
106 
107-        self.log(format="ShareFinder.loop: no_more_shares, ever",
108-                 level=log.UNUSUAL, umid="XjQlzg")
109+        # self.log(format="ShareFinder.loop: no_more_shares, ever",
110+        #          level=log.UNUSUAL, umid="XjQlzg")
111         # we've run out of servers (so we can't send any more requests), and
112         # we have nothing in flight. No further progress can be made. They
113         # are destined to remain hungry.
114hunk ./src/allmydata/immutable/downloader/finder.py 146
115         peerid, rref = server
116         req = RequestToken(peerid)
117         self.pending_requests.add(req)
118-        lp = self.log(format="sending DYHB to [%(peerid)s]",
119-                      peerid=idlib.shortnodeid_b2a(peerid),
120-                      level=log.NOISY, umid="Io7pyg")
121+        # lp = self.log(format="sending DYHB to [%(peerid)s]",
122+        #               peerid=idlib.shortnodeid_b2a(peerid),
123+        #               level=log.NOISY, umid="Io7pyg")
124+        lp = 'dummy'
125         d_ev = self._download_status.add_dyhb_sent(peerid, now())
126         # TODO: get the timer from a Server object, it knows best
127         self.overdue_timers[req] = reactor.callLater(self.OVERDUE_TIMEOUT,
128hunk ./src/allmydata/immutable/downloader/finder.py 181
129         d_ev.finished(shnums, now())
130         if buckets:
131             shnums_s = ",".join([str(shnum) for shnum in shnums])
132-            self.log(format="got shnums [%(shnums)s] from [%(peerid)s]",
133-                     shnums=shnums_s, peerid=idlib.shortnodeid_b2a(peerid),
134-                     level=log.NOISY, parent=lp, umid="0fcEZw")
135+            # self.log(format="got shnums [%(shnums)s] from [%(peerid)s]",
136+            #          shnums=shnums_s, peerid=idlib.shortnodeid_b2a(peerid),
137+            #          level=log.NOISY, parent=lp, umid="0fcEZw")
138         else:
139hunk ./src/allmydata/immutable/downloader/finder.py 185
140-            self.log(format="no shares from [%(peerid)s]",
141-                     peerid=idlib.shortnodeid_b2a(peerid),
142-                     level=log.NOISY, parent=lp, umid="U7d4JA")
143+            # self.log(format="no shares from [%(peerid)s]",
144+            #          peerid=idlib.shortnodeid_b2a(peerid),
145+            #          level=log.NOISY, parent=lp, umid="U7d4JA")
146+            pass
147         if self.node.num_segments is None:
148             best_numsegs = self.node.guessed_num_segments
149         else:
150hunk ./src/allmydata/immutable/downloader/finder.py 225
151 
152     def _got_error(self, f, peerid, req, d_ev, lp):
153         d_ev.finished("error", now())
154-        self.log(format="got error from [%(peerid)s]",
155-                 peerid=idlib.shortnodeid_b2a(peerid), failure=f,
156-                 level=log.UNUSUAL, parent=lp, umid="zUKdCw")
157+        # self.log(format="got error from [%(peerid)s]",
158+        #          peerid=idlib.shortnodeid_b2a(peerid), failure=f,
159+        #          level=log.UNUSUAL, parent=lp, umid="zUKdCw")
160 
161 
162hunk ./src/allmydata/immutable/downloader/node.py 84
163         # for each read() call. Segmentation and get_segment() messages are
164         # associated with the read() call, everything else is tied to the
165         # _Node's log entry.
166-        lp = log.msg(format="Immutable _Node(%(si)s) created: size=%(size)d,"
167-                     " guessed_segsize=%(guessed_segsize)d,"
168-                     " guessed_numsegs=%(guessed_numsegs)d",
169-                     si=self._si_prefix, size=verifycap.size,
170-                     guessed_segsize=self.guessed_segment_size,
171-                     guessed_numsegs=self.guessed_num_segments,
172-                     level=log.OPERATIONAL, umid="uJ0zAQ")
173-        self._lp = lp
174+        # lp = log.msg(format="Immutable _Node(%(si)s) created: size=%(size)d,"
175+        #              " guessed_segsize=%(guessed_segsize)d,"
176+        #              " guessed_numsegs=%(guessed_numsegs)d",
177+        #              si=self._si_prefix, size=verifycap.size,
178+        #              guessed_segsize=self.guessed_segment_size,
179+        #              guessed_numsegs=self.guessed_num_segments,
180+        #              level=log.OPERATIONAL, umid="uJ0zAQ")
181+        self._lp = lp = 'dummy'
182 
183         self._sharefinder = ShareFinder(storage_broker, verifycap, self,
184                                         self._download_status, lp)
185hunk ./src/allmydata/immutable/downloader/node.py 136
186         if read_ev is None:
187             read_ev = self._download_status.add_read_event(offset, size, now())
188 
189-        lp = log.msg(format="imm Node(%(si)s).read(%(offset)d, %(size)d)",
190-                     si=base32.b2a(self._verifycap.storage_index)[:8],
191-                     offset=offset, size=size,
192-                     level=log.OPERATIONAL, parent=self._lp, umid="l3j3Ww")
193+        # lp = log.msg(format="imm Node(%(si)s).read(%(offset)d, %(size)d)",
194+        #              si=base32.b2a(self._verifycap.storage_index)[:8],
195+        #              offset=offset, size=size,
196+        #              level=log.OPERATIONAL, parent=self._lp, umid="l3j3Ww")
197+        lp = 'dummy'
198         if self._history:
199             sp = self._history.stats_provider
200             sp.count("downloader.files_downloaded", 1) # really read() calls
201hunk ./src/allmydata/immutable/downloader/node.py 179
202         The Deferred can also errback with other fatal problems, such as
203         NotEnoughSharesError, NoSharesError, or BadCiphertextHashError.
204         """
205-        log.msg(format="imm Node(%(si)s).get_segment(%(segnum)d)",
206-                si=base32.b2a(self._verifycap.storage_index)[:8],
207-                segnum=segnum,
208-                level=log.OPERATIONAL, parent=logparent, umid="UKFjDQ")
209+        # log.msg(format="imm Node(%(si)s).get_segment(%(segnum)d)",
210+        #         si=base32.b2a(self._verifycap.storage_index)[:8],
211+        #         segnum=segnum,
212+        #         level=log.OPERATIONAL, parent=logparent, umid="UKFjDQ")
213         self._download_status.add_segment_request(segnum, now())
214         d = defer.Deferred()
215         c = Cancel(self._cancel_request)
216hunk ./src/allmydata/immutable/downloader/node.py 212
217         if self._active_segment is None and self._segment_requests:
218             segnum = self._segment_requests[0][0]
219             k = self._verifycap.needed_shares
220-            log.msg(format="%(node)s._start_new_segment: segnum=%(segnum)d",
221-                    node=repr(self), segnum=segnum,
222-                    level=log.NOISY, umid="wAlnHQ")
223+            # log.msg(format="%(node)s._start_new_segment: segnum=%(segnum)d",
224+            #         node=repr(self), segnum=segnum,
225+            #         level=log.NOISY, umid="wAlnHQ")
226             self._active_segment = fetcher = SegmentFetcher(self, segnum, k)
227             active_shares = [s for s in self._shares if s.is_alive()]
228             fetcher.add_shares(active_shares) # this triggers the loop
229hunk ./src/allmydata/immutable/downloader/node.py 233
230     # things called by our Share instances
231 
232     def validate_and_store_UEB(self, UEB_s):
233-        log.msg("validate_and_store_UEB",
234-                level=log.OPERATIONAL, parent=self._lp, umid="7sTrPw")
235+        # log.msg("validate_and_store_UEB",
236+        #         level=log.OPERATIONAL, parent=self._lp, umid="7sTrPw")
237         h = hashutil.uri_extension_hash(UEB_s)
238         if h != self._verifycap.uri_extension_hash:
239             raise BadHashError
240hunk ./src/allmydata/immutable/downloader/node.py 256
241 
242         # therefore, we ignore d['total_shares'] and d['needed_shares'].
243 
244-        log.msg(format="UEB=%(ueb)s, vcap=%(vcap)s",
245-                ueb=repr(d), vcap=self._verifycap.to_string(),
246-                level=log.NOISY, parent=self._lp, umid="cVqZnA")
247+        # log.msg(format="UEB=%(ueb)s, vcap=%(vcap)s",
248+        #         ueb=repr(d), vcap=self._verifycap.to_string(),
249+        #         level=log.NOISY, parent=self._lp, umid="cVqZnA")
250 
251         k, N = self._verifycap.needed_shares, self._verifycap.total_shares
252 
253hunk ./src/allmydata/immutable/downloader/node.py 271
254         self.num_segments = r["num_segments"]
255         self.block_size = r["block_size"]
256         self.tail_block_size = r["tail_block_size"]
257-        log.msg("actual sizes: %s" % (r,),
258-                level=log.NOISY, parent=self._lp, umid="PY6P5Q")
259+        # log.msg("actual sizes: %s" % (r,),
260+        #         level=log.NOISY, parent=self._lp, umid="PY6P5Q")
261         if (self.segment_size == self.guessed_segment_size
262             and self.num_segments == self.guessed_num_segments):
263hunk ./src/allmydata/immutable/downloader/node.py 275
264-            log.msg("my guess was right!",
265-                    level=log.NOISY, parent=self._lp, umid="x340Ow")
266+            # log.msg("my guess was right!",
267+            #         level=log.NOISY, parent=self._lp, umid="x340Ow")
268+            pass
269         else:
270hunk ./src/allmydata/immutable/downloader/node.py 279
271-            log.msg("my guess was wrong! Extra round trips for me.",
272-                    level=log.NOISY, parent=self._lp, umid="tb7RJw")
273+            # log.msg("my guess was wrong! Extra round trips for me.",
274+            #         level=log.NOISY, parent=self._lp, umid="tb7RJw")
275+            pass
276 
277         # zfec.Decode() instantiation is fast, but still, let's use the same
278         # codec instance for all but the last segment. 3-of-10 takes 15us on
279hunk ./src/allmydata/immutable/downloader/node.py 383
280                 (offset, segment, decodetime) = result
281                 ds.add_segment_delivery(segnum, now(),
282                                         offset, len(segment), decodetime)
283-            log.msg(format="delivering segment(%(segnum)d)",
284-                    segnum=segnum,
285-                    level=log.OPERATIONAL, parent=self._lp,
286-                    umid="j60Ojg")
287+            # log.msg(format="delivering segment(%(segnum)d)",
288+            #         segnum=segnum,
289+            #         level=log.OPERATIONAL, parent=self._lp,
290+            #         umid="j60Ojg")
291             for (d,c) in self._extract_requests(segnum):
292                 eventually(self._deliver, d, c, result)
293             self._active_segment = None
294hunk ./src/allmydata/immutable/downloader/node.py 444
295         except (BadHashError, NotEnoughHashesError):
296             format = ("hash failure in ciphertext_hash_tree:"
297                       " segnum=%(segnum)d, SI=%(si)s")
298-            log.msg(format=format, segnum=segnum, si=self._si_prefix,
299-                    failure=Failure(),
300-                    level=log.WEIRD, parent=self._lp, umid="MTwNnw")
301+            # log.msg(format=format, segnum=segnum, si=self._si_prefix,
302+            #         failure=Failure(),
303+            #         level=log.WEIRD, parent=self._lp, umid="MTwNnw")
304             # this is especially weird, because we made it past the share
305             # hash tree. It implies that we're using the wrong encoding, or
306             # that the uploader deliberately constructed a bad UEB.
307hunk ./src/allmydata/immutable/downloader/segmentation.py 74
308         else:
309             # this might be a guess
310             wanted_segnum = self._offset // segment_size
311-        log.msg(format="_fetch_next(offset=%(offset)d) %(guess)swants segnum=%(segnum)d",
312-                offset=self._offset, guess=guess_s, segnum=wanted_segnum,
313-                level=log.NOISY, parent=self._lp, umid="5WfN0w")
314+        # log.msg(format="_fetch_next(offset=%(offset)d) %(guess)swants segnum=%(segnum)d",
315+        #         offset=self._offset, guess=guess_s, segnum=wanted_segnum,
316+        #         level=log.NOISY, parent=self._lp, umid="5WfN0w")
317         self._active_segnum = wanted_segnum
318         d,c = n.get_segment(wanted_segnum, self._lp)
319         self._cancel_segment_request = c
320hunk ./src/allmydata/immutable/downloader/segmentation.py 96
321         self._cancel_segment_request = None
322         # we got file[segment_start:segment_start+len(segment)]
323         # we want file[self._offset:self._offset+self._size]
324-        log.msg(format="Segmentation got data:"
325-                " want [%(wantstart)d-%(wantend)d),"
326-                " given [%(segstart)d-%(segend)d), for segnum=%(segnum)d",
327-                wantstart=self._offset, wantend=self._offset+self._size,
328-                segstart=segment_start, segend=segment_start+len(segment),
329-                segnum=wanted_segnum,
330-                level=log.OPERATIONAL, parent=self._lp, umid="32dHcg")
331+        # log.msg(format="Segmentation got data:"
332+        #         " want [%(wantstart)d-%(wantend)d),"
333+        #         " given [%(segstart)d-%(segend)d), for segnum=%(segnum)d",
334+        #         wantstart=self._offset, wantend=self._offset+self._size,
335+        #         segstart=segment_start, segend=segment_start+len(segment),
336+        #         segnum=wanted_segnum,
337+        #         level=log.OPERATIONAL, parent=self._lp, umid="32dHcg")
338 
339         o = overlap(segment_start, len(segment),  self._offset, self._size)
340         # the overlap is file[o[0]:o[0]+o[1]]
341hunk ./src/allmydata/immutable/downloader/segmentation.py 108
342         if not o or o[0] != self._offset:
343             # we didn't get the first byte, so we can't use this segment
344-            log.msg("Segmentation handed wrong data:"
345-                    " want [%d-%d), given [%d-%d), for segnum=%d,"
346-                    " for si=%s"
347-                    % (self._offset, self._offset+self._size,
348-                       segment_start, segment_start+len(segment),
349-                       wanted_segnum, self._node._si_prefix),
350-                    level=log.UNUSUAL, parent=self._lp, umid="STlIiA")
351+            # log.msg("Segmentation handed wrong data:"
352+            #         " want [%d-%d), given [%d-%d), for segnum=%d,"
353+            #         " for si=%s"
354+            #         % (self._offset, self._offset+self._size,
355+            #            segment_start, segment_start+len(segment),
356+            #            wanted_segnum, self._node._si_prefix),
357+            #         level=log.UNUSUAL, parent=self._lp, umid="STlIiA")
358             # we may retry if the segnum we asked was based on a guess
359             raise WrongSegmentError("I was given the wrong data.")
360         offset_in_segment = self._offset - segment_start
361hunk ./src/allmydata/immutable/downloader/segmentation.py 138
362         return self._maybe_fetch_next()
363 
364     def _error(self, f):
365-        log.msg("Error in Segmentation", failure=f,
366-                level=log.WEIRD, parent=self._lp, umid="EYlXBg")
367+        # log.msg("Error in Segmentation", failure=f,
368+        #         level=log.WEIRD, parent=self._lp, umid="EYlXBg")
369         self._alive = False
370         self._hungry = False
371         self._deferred.errback(f)
372hunk ./src/allmydata/immutable/downloader/segmentation.py 145
373 
374     def stopProducing(self):
375-        log.msg("asked to stopProducing",
376-                level=log.NOISY, parent=self._lp, umid="XIyL9w")
377+        # log.msg("asked to stopProducing",
378+        #         level=log.NOISY, parent=self._lp, umid="XIyL9w")
379         self._hungry = False
380         self._alive = False
381         # cancel any outstanding segment request
382hunk ./src/allmydata/immutable/downloader/share.py 156
383          - state=DEAD, f=Failure: the server reported an error, this share
384                                   is unusable
385         """
386-        log.msg("%s.get_block(%d)" % (repr(self), segnum),
387-                level=log.NOISY, parent=self._lp, umid="RTo9MQ")
388+        # log.msg("%s.get_block(%d)" % (repr(self), segnum),
389+        #         level=log.NOISY, parent=self._lp, umid="RTo9MQ")
390         assert segnum >= 0
391         o = EventStreamObserver()
392         o.set_canceler(self, "_cancel_block_request")
393hunk ./src/allmydata/immutable/downloader/share.py 192
394             return
395         try:
396             # if any exceptions occur here, kill the download
397-            log.msg("%s.loop, reqs=[%s], pending=%s, received=%s,"
398-                    " unavailable=%s" %
399-                    (repr(self),
400-                     ",".join([str(req[0]) for req in self._requested_blocks]),
401-                     self._pending.dump(), self._received.dump(),
402-                     self._unavailable.dump() ),
403-                    level=log.NOISY, parent=self._lp, umid="BaL1zw")
404+            # log.msg("%s.loop, reqs=[%s], pending=%s, received=%s,"
405+            #         " unavailable=%s" %
406+            #         (repr(self),
407+            #          ",".join([str(req[0]) for req in self._requested_blocks]),
408+            #          self._pending.dump(), self._received.dump(),
409+            #          self._unavailable.dump() ),
410+            #         level=log.NOISY, parent=self._lp, umid="BaL1zw")
411             self._do_loop()
412             # all exception cases call self._fail(), which clears self._alive
413         except (BadHashError, NotEnoughHashesError, LayoutInvalid), e:
414hunk ./src/allmydata/immutable/downloader/share.py 214
415             #
416             # _satisfy_*() code which detects corruption should first call
417             # self._signal_corruption(), and then raise the exception.
418-            log.msg(format="corruption detected in %(share)s",
419-                    share=repr(self),
420-                    level=log.UNUSUAL, parent=self._lp, umid="gWspVw")
421+            # log.msg(format="corruption detected in %(share)s",
422+            #         share=repr(self),
423+            #         level=log.UNUSUAL, parent=self._lp, umid="gWspVw")
424             self._fail(Failure(e), log.UNUSUAL)
425         except DataUnavailable, e:
426             # Abandon this share.
427hunk ./src/allmydata/immutable/downloader/share.py 220
428-            log.msg(format="need data that will never be available"
429-                    " from %s: pending=%s, received=%s, unavailable=%s" %
430-                    (repr(self),
431-                     self._pending.dump(), self._received.dump(),
432-                     self._unavailable.dump() ),
433-                    level=log.UNUSUAL, parent=self._lp, umid="F7yJnQ")
434+            # log.msg(format="need data that will never be available"
435+            #         " from %s: pending=%s, received=%s, unavailable=%s" %
436+            #         (repr(self),
437+            #          self._pending.dump(), self._received.dump(),
438+            #          self._unavailable.dump() ),
439+            #         level=log.UNUSUAL, parent=self._lp, umid="F7yJnQ")
440             self._fail(Failure(e), log.UNUSUAL)
441         except BaseException:
442             self._fail(Failure())
443hunk ./src/allmydata/immutable/downloader/share.py 230
444             raise
445-        log.msg("%s.loop done, reqs=[%s], pending=%s, received=%s,"
446-                " unavailable=%s" %
447-                (repr(self),
448-                 ",".join([str(req[0]) for req in self._requested_blocks]),
449-                 self._pending.dump(), self._received.dump(),
450-                 self._unavailable.dump() ),
451-                level=log.NOISY, parent=self._lp, umid="9lRaRA")
452+        # log.msg("%s.loop done, reqs=[%s], pending=%s, received=%s,"
453+        #         " unavailable=%s" %
454+        #         (repr(self),
455+        #          ",".join([str(req[0]) for req in self._requested_blocks]),
456+        #          self._pending.dump(), self._received.dump(),
457+        #          self._unavailable.dump() ),
458+        #         level=log.NOISY, parent=self._lp, umid="9lRaRA")
459 
460     def _do_loop(self):
461         # we are (eventually) called after all state transitions:
462hunk ./src/allmydata/immutable/downloader/share.py 363
463                                   ] ):
464             offsets[field] = fields[i]
465         self.actual_offsets = offsets
466-        log.msg("actual offsets: data=%d, plaintext_hash_tree=%d, crypttext_hash_tree=%d, block_hashes=%d, share_hashes=%d, uri_extension=%d" % tuple(fields))
467+        # log.msg("actual offsets: data=%d, plaintext_hash_tree=%d, crypttext_hash_tree=%d, block_hashes=%d, share_hashes=%d, uri_extension=%d" % tuple(fields))
468         self._received.remove(0, 4) # don't need this anymore
469 
470         # validate the offsets a bit
471hunk ./src/allmydata/immutable/downloader/share.py 469
472         except (BadHashError, NotEnoughHashesError), e:
473             f = Failure(e)
474             hashnums = ",".join([str(n) for n in sorted(block_hashes.keys())])
475-            log.msg(format="hash failure in block_hashes=(%(hashnums)s),"
476-                    " from %(share)s",
477-                    hashnums=hashnums, shnum=self._shnum, share=repr(self),
478-                    failure=f, level=log.WEIRD, parent=self._lp, umid="yNyFdA")
479+            # log.msg(format="hash failure in block_hashes=(%(hashnums)s),"
480+            #         " from %(share)s",
481+            #         hashnums=hashnums, shnum=self._shnum, share=repr(self),
482+            #         failure=f, level=log.WEIRD, parent=self._lp, umid="yNyFdA")
483             hsize = max(0, max(needed_hashes)) * HASH_SIZE
484             self._signal_corruption(f, o_bh, hsize)
485             self.had_corruption = True
486hunk ./src/allmydata/immutable/downloader/share.py 497
487         except (BadHashError, NotEnoughHashesError), e:
488             f = Failure(e)
489             hashnums = ",".join([str(n) for n in sorted(hashes.keys())])
490-            log.msg(format="hash failure in ciphertext_hashes=(%(hashnums)s),"
491-                    " from %(share)s",
492-                    hashnums=hashnums, share=repr(self), failure=f,
493-                    level=log.WEIRD, parent=self._lp, umid="iZI0TA")
494+            # log.msg(format="hash failure in ciphertext_hashes=(%(hashnums)s),"
495+            #         " from %(share)s",
496+            #         hashnums=hashnums, share=repr(self), failure=f,
497+            #         level=log.WEIRD, parent=self._lp, umid="iZI0TA")
498             hsize = max(0, max(needed_hashes))*HASH_SIZE
499             self._signal_corruption(f, start, hsize)
500             self.had_corruption = True
501hunk ./src/allmydata/immutable/downloader/share.py 519
502 
503         block = self._received.pop(blockstart, blocklen)
504         if not block:
505-            log.msg("no data for block %s (want [%d:+%d])" % (repr(self),
506-                                                              blockstart, blocklen))
507+            # log.msg("no data for block %s (want [%d:+%d])" % (repr(self),
508+            #                                                   blockstart, blocklen))
509             return False
510hunk ./src/allmydata/immutable/downloader/share.py 522
511-        log.msg(format="%(share)s._satisfy_data_block [%(start)d:+%(length)d]",
512-                share=repr(self), start=blockstart, length=blocklen,
513-                level=log.NOISY, parent=self._lp, umid="uTDNZg")
514+        # log.msg(format="%(share)s._satisfy_data_block [%(start)d:+%(length)d]",
515+        #         share=repr(self), start=blockstart, length=blocklen,
516+        #         level=log.NOISY, parent=self._lp, umid="uTDNZg")
517         # this block is being retired, either as COMPLETE or CORRUPT, since
518         # no further data reads will help
519         assert self._requested_blocks[0][0] == segnum
520hunk ./src/allmydata/immutable/downloader/share.py 534
521             for o in observers:
522                 # goes to SegmentFetcher._block_request_activity
523                 o.notify(state=COMPLETE, block=block)
524+            # now clear our received data, to dodge the #1170 spans.py
525+            # complexity bug
526+            self._received = DataSpans()
527         except (BadHashError, NotEnoughHashesError), e:
528             # rats, we have a corrupt block. Notify our clients that they
529             # need to look elsewhere, and advise the server. Unlike
530hunk ./src/allmydata/immutable/downloader/share.py 543
531             # corruption in other parts of the share, this doesn't cause us
532             # to abandon the whole share.
533             f = Failure(e)
534-            log.msg(format="hash failure in block %(segnum)d, from %(share)s",
535-                    segnum=segnum, share=repr(self), failure=f,
536-                    level=log.WEIRD, parent=self._lp, umid="mZjkqA")
537+            # log.msg(format="hash failure in block %(segnum)d, from %(share)s",
538+            #         segnum=segnum, share=repr(self), failure=f,
539+            #         level=log.WEIRD, parent=self._lp, umid="mZjkqA")
540             for o in observers:
541                 o.notify(state=CORRUPT)
542             self._signal_corruption(f, blockstart, blocklen)
543hunk ./src/allmydata/immutable/downloader/share.py 609
544                     self._desire_block_hashes(desire, o, segnum)
545                     self._desire_data(desire, o, r, segnum, segsize)
546             else:
547-                log.msg("_desire: segnum(%d) looks wrong (numsegs=%d)"
548-                        % (segnum, r["num_segments"]),
549-                        level=log.UNUSUAL, parent=self._lp, umid="tuYRQQ")
550+                # log.msg("_desire: segnum(%d) looks wrong (numsegs=%d)"
551+                #         % (segnum, r["num_segments"]),
552+                #         level=log.UNUSUAL, parent=self._lp, umid="tuYRQQ")
553+                pass
554 
555hunk ./src/allmydata/immutable/downloader/share.py 614
556-        log.msg("end _desire: want_it=%s need_it=%s gotta=%s"
557-                % (want_it.dump(), need_it.dump(), gotta_gotta_have_it.dump()))
558+        # log.msg("end _desire: want_it=%s need_it=%s gotta=%s"
559+        #         % (want_it.dump(), need_it.dump(), gotta_gotta_have_it.dump()))
560         if self.actual_offsets:
561             return (want_it, need_it+gotta_gotta_have_it)
562         else:
563hunk ./src/allmydata/immutable/downloader/share.py 704
564 
565     def _send_requests(self, desired):
566         ask = desired - self._pending - self._received.get_spans()
567-        log.msg("%s._send_requests, desired=%s, pending=%s, ask=%s" %
568-                (repr(self), desired.dump(), self._pending.dump(), ask.dump()),
569-                level=log.NOISY, parent=self._lp, umid="E94CVA")
570+        # log.msg("%s._send_requests, desired=%s, pending=%s, ask=%s" %
571+        #         (repr(self), desired.dump(), self._pending.dump(), ask.dump()),
572+        #         level=log.NOISY, parent=self._lp, umid="E94CVA")
573         # XXX At one time, this code distinguished between data blocks and
574         # hashes, and made sure to send (small) requests for hashes before
575         # sending (big) requests for blocks. The idea was to make sure that
576hunk ./src/allmydata/immutable/downloader/share.py 718
577         for (start, length) in ask:
578             # TODO: quantize to reasonably-large blocks
579             self._pending.add(start, length)
580-            lp = log.msg(format="%(share)s._send_request"
581-                         " [%(start)d:+%(length)d]",
582-                         share=repr(self),
583-                         start=start, length=length,
584-                         level=log.NOISY, parent=self._lp, umid="sgVAyA")
585+            # lp = log.msg(format="%(share)s._send_request"
586+            #              " [%(start)d:+%(length)d]",
587+            #              share=repr(self),
588+            #              start=start, length=length,
589+            #              level=log.NOISY, parent=self._lp, umid="sgVAyA")
590+            lp = 'dummy'
591             req_ev = ds.add_request_sent(self._peerid, self._shnum,
592                                          start, length, now())
593             d = self._send_request(start, length)
594hunk ./src/allmydata/immutable/downloader/share.py 742
595         req_ev.finished(len(data), now())
596         if not self._alive:
597             return
598-        log.msg(format="%(share)s._got_data [%(start)d:+%(length)d] -> %(datalen)d",
599-                share=repr(self), start=start, length=length, datalen=len(data),
600-                level=log.NOISY, parent=lp, umid="5Qn6VQ")
601+        # log.msg(format="%(share)s._got_data [%(start)d:+%(length)d] -> %(datalen)d",
602+        #         share=repr(self), start=start, length=length, datalen=len(data),
603+        #         level=log.NOISY, parent=lp, umid="5Qn6VQ")
604         self._pending.remove(start, length)
605         self._received.add(start, data)
606 
607hunk ./src/allmydata/immutable/downloader/share.py 783
608 
609     def _got_error(self, f, start, length, req_ev, lp):
610         req_ev.finished("error", now())
611-        log.msg(format="error requesting %(start)d+%(length)d"
612-                " from %(server)s for si %(si)s",
613-                start=start, length=length,
614-                server=self._peerid_s, si=self._si_prefix,
615-                failure=f, parent=lp, level=log.UNUSUAL, umid="BZgAJw")
616+        # log.msg(format="error requesting %(start)d+%(length)d"
617+        #         " from %(server)s for si %(si)s",
618+        #         start=start, length=length,
619+        #         server=self._peerid_s, si=self._si_prefix,
620+        #         failure=f, parent=lp, level=log.UNUSUAL, umid="BZgAJw")
621         # retire our observers, assuming we won't be able to make any
622         # further progress
623         self._fail(f, log.UNUSUAL)
624hunk ./src/allmydata/util/spans.py 1
625-
626 class Spans:
627     """I represent a compressed list of booleans, one per index (an integer).
628     Typically, each index represents an offset into a large string, pointing
629hunk ./src/allmydata/util/spans.py 46
630             raise
631 
632     def add(self, start, length):
633+        assert isinstance(start, (int, long))
634+        assert isinstance(length, (int, long))
635         assert start >= 0
636         assert length > 0
637         #print " ADD [%d+%d -%d) to %s" % (start, length, start+length, self.dump())
638hunk ./src/allmydata/util/spans.py 259
639 
640     def get_spans(self):
641         """Return a Spans object with a bit set for each byte I hold"""
642-        return Spans([(start, len(data)) for (start,data) in self.spans])
643+        # return Spans([(start, len(data)) for (start,data) in self.spans])
644+        # XXX This is not the right long-term fix, because it depends on an undocumented
645+        # invariant of Spans.
646+        s = Spans()
647+        s._spans = [(start, len(data)) for (start,data) in self.spans]
648+        s._check()
649+        return s
650 
651     def assert_invariants(self):
652         if not self.spans:
653}
654
655Context:
656
657[docs: update NEWS a bit about New-Downloader
658zooko@zooko.com**20100819021446
659 Ignore-this: 31a6e2fb0a6e3d19f73481e99070da7a
660]
661[misc: add benchmarking tool for spans
662zooko@zooko.com**20100819021420
663 Ignore-this: 569327a1908a07e5fb634526bed515b2
664]
665[docs: doc of the download status page
666zooko@zooko.com**20100814054117
667 Ignore-this: a82ec33da3c39a7c0d47a7a6b5f81bbb
668 ref: http://tahoe-lafs.org/trac/tahoe-lafs/ticket/1169#comment:1
669]
670[docs: NEWS: edit English usage, remove ticket numbers for regressions vs. 1.7.1 that were fixed again before 1.8.0c2
671zooko@zooko.com**20100811071758
672 Ignore-this: 993f5a1e6a9535f5b7a0bd77b93b66d0
673]
674[docs: NEWS: more detail about new-downloader
675zooko@zooko.com**20100811071303
676 Ignore-this: 9f07da4dce9d794ce165aae287f29a1e
677]
678[TAG allmydata-tahoe-1.8.0c2
679david-sarah@jacaranda.org**20100810073847
680 Ignore-this: c37f732b0e45f9ebfdc2f29c0899aeec
681]
682Patch bundle hash:
6832417684bf6ac1e49b845f88704c36cedcc816f4f