Merge lp:~mbp/bzr/340347-log-decorator into lp:~bzr/bzr/trunk-old

[Martin Pool]

[Martin Pool (mbp)]

Fixes this bug https://bugs.edge.launchpad.net/bzr/+bug/340347 in both ways: pack.py no longer insists on getting an iterator (because the readv docstring says it may be a list) and TransportLogDecorator gives back a generator if the underlying transport gives one. I added a test for the second; the first is not super easily testable and imo does not need one as it's a debugging aid that's failing.

One variable was named 'length' when it should be 'offset' so I fixed it.

Some errors for readv now give more information which may help with things like bug 360476.

I cut out the rate and time display from the log+ output becasue they're now redundant.

[John A Meinel (jameinel)]

        + """Construct a new ReadVFile wrapper.
44 +
45 + :seealso: make_readv_reader
46 +
47 + :param readv_result: the most recent readv result - list or generator
48 + """
49 + # we rely on its state as a generator to keep track of how much has
50 + # been used.
51 + if not getattr(readv_result, 'next'):
52 + readv_result = iter(readv_result)

You can just use:

readv_result = iter(readv_result)

If the object *is* an iterator it will just return self.

>>> def foo():
... for x in xrange(10):
... yield x
...
>>> f= foo()
>>> f
<generator object at 0x0238F0F8>
>>> y = iter(f)
>>> y
<generator object at 0x0238F0F8>
>>> iter(f) is f
True

I think it simplifies the code a bit.

224 def readv(self, relpath, offsets, adjust_for_latency=False,
225 upper_limit=None):
226 + # we override at the readv() level rather than _readv() so that any
227 + # latency adjustments will be done by the underlying transport
228 """See Transport.readv."""
229 self._trace(('readv', relpath, offsets, adjust_for_latency,
230 upper_limit))

^- A comment should come after the docstring IMO

Anyway, the changes seem fine. I would just do an unconditional iter(foo) to make it cleaner.

review: Approve

[Martin Pool (mbp)]

> ^- A comment should come after the docstring IMO
>
> Anyway, the changes seem fine. I would just do an unconditional iter(foo) to
> make it cleaner.

Good point. I had the idea it made a new object rather than returning foo.

Thanks

=== modified file 'NEWS'
--- NEWS	2009-07-01 19:06:14 +0000
+++ NEWS	2009-07-02 04:35:10 +0000
@@ -75,6 +75,13 @@
   transforms.
   (Craig Hewetson, Martin Pool, #218206)
 
+* The ``log+`` decorator, useful in debugging or profiling, could cause
+  "AttributeError: 'list' object has no attribute 'next'".  This is now
+  fixed.  The log decorator no longer shows the elapsed time or transfer
+  rate because they're available in the log prefixes and the transport
+  activity display respectively.
+  (Martin Pool, #340347)
+
 * Progress bars are now suppressed again when the environment variable
   ``BZR_PROGRESS_BAR`` is set to ``none``.
   (Martin Pool, #339385)

=== modified file 'bzrlib/pack.py'
--- bzrlib/pack.py	2009-06-20 01:17:38 +0000
+++ bzrlib/pack.py	2009-07-02 04:35:10 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2007 Canonical Ltd
+# Copyright (C) 2007, 2009 Canonical Ltd
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by
@@ -159,17 +159,32 @@
 
 
 class ReadVFile(object):
-    """Adapt a readv result iterator to a file like protocol."""
+    """Adapt a readv result iterator to a file like protocol.
+    
+    The readv result must support the iterator protocol returning (offset,
+    data_bytes) pairs.
+    """
+
+    # XXX: This could be a generic transport class, as other code may want to
+    # gradually consume the readv result.
 
     def __init__(self, readv_result):
+        """Construct a new ReadVFile wrapper.
+
+        :seealso: make_readv_reader
+
+        :param readv_result: the most recent readv result - list or generator
+        """
+        # readv can return a sequence or an iterator, but we require an
+        # iterator to know how much has been consumed.
+        readv_result = iter(readv_result)
         self.readv_result = readv_result
-        # the most recent readv result block
         self._string = None
 
     def _next(self):
         if (self._string is None or
             self._string.tell() == self._string_length):
-            length, data = self.readv_result.next()
+            offset, data = self.readv_result.next()
             self._string_length = len(data)
             self._string = StringIO(data)
 
@@ -177,7 +192,9 @@
         self._next()
         result = self._string.read(length)
         if len(result) < length:
-            raise errors.BzrError('request for too much data from a readv hunk.')
+            raise errors.BzrError('wanted %d bytes but next '
+                'hunk only contains %d: %r...' %
+                (length, len(result), result[:20]))
         return result
 
     def readline(self):
@@ -185,7 +202,8 @@
         self._next()
         result = self._string.readline()
         if self._string.tell() == self._string_length and result[-1] != '\n':
-            raise errors.BzrError('short readline in the readvfile hunk.')
+            raise errors.BzrError('short readline in the readvfile hunk: %r'
+                % (readline, ))
         return result
 
 

=== modified file 'bzrlib/tests/test_transport_log.py'
--- bzrlib/tests/test_transport_log.py	2009-03-23 14:59:43 +0000
+++ bzrlib/tests/test_transport_log.py	2009-07-02 04:35:11 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2004, 2005, 2006, 2007 Canonical Ltd
+# Copyright (C) 2004, 2005, 2006, 2007, 2009 Canonical Ltd
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by
@@ -18,9 +18,13 @@
 """Tests for log+ transport decorator."""
 
 
+import types
+
+
 from bzrlib.tests import TestCaseWithMemoryTransport
 from bzrlib.trace import mutter
 from bzrlib.transport import get_transport
+from bzrlib.transport.log import TransportLogDecorator
 
 
 class TestTransportLog(TestCaseWithMemoryTransport):
@@ -41,4 +45,35 @@
         # and they operate on the underlying transport
         self.assertTrue(base_transport.has('subdir'))
 
-
+    def test_log_readv(self):
+        # see <https://bugs.launchpad.net/bzr/+bug/340347>
+
+        # transports are not required to return a generator, but we
+        # specifically want to check that those that do cause it to be passed
+        # through, for the sake of minimum interference
+        base_transport = DummyReadvTransport()
+        # construct it directly to avoid needing the dummy transport to be
+        # registered etc
+        logging_transport = TransportLogDecorator(
+            'log+dummy:///', _decorated=base_transport)
+
+        result = base_transport.readv('foo', [(0, 10)])
+        # sadly there's no types.IteratorType, and GeneratorType is too
+        # specific
+        self.assertTrue(getattr(result, 'next'))
+
+        result = logging_transport.readv('foo', [(0, 10)])
+        self.assertTrue(getattr(result, 'next'))
+        self.assertEquals(list(result),
+            [(0, 'abcdefghij')])
+
+
+class DummyReadvTransport(object):
+
+    base = 'dummy:///'
+
+    def readv(self, filename, offset_length_pairs):
+        yield (0, 'abcdefghij')
+
+    def abspath(self, path):
+        return self.base + path

=== modified file 'bzrlib/transport/log.py'
--- bzrlib/transport/log.py	2009-03-23 14:59:43 +0000
+++ bzrlib/transport/log.py	2009-07-02 04:35:11 +0000
@@ -44,6 +44,9 @@
     and may be slow.
 
     Not all operations are logged yet.
+
+    See also TransportTraceDecorator, that records a machine-readable log in 
+    memory for eg testing.
     """
 
     def __init__(self, *args, **kw):
@@ -104,10 +107,15 @@
     def _show_result(self, before, methodname, result):
         result_len = None
         if isinstance(result, types.GeneratorType):
-            # eagerly pull in all the contents, so that we can measure how
-            # long it takes to get them.  this does make the behaviour a bit
-            # different, but we hope not noticably so
+            # We now consume everything from the generator so that we can show
+            # the results and the time it took to get them.  However, to keep
+            # compatibility with callers that may specifically expect a result
+            # (see <https://launchpad.net/bugs/340347>) we also return a new
+            # generator, reset to the starting position.
             result = list(result)
+            return_result = iter(result)
+        else:
+            return_result = result
         if isinstance(result, (cStringIO.OutputType, StringIO.StringIO)):
             val = repr(result.getvalue())
             result_len = len(val)
@@ -122,16 +130,17 @@
         else:
             shown_result = self._shorten(self._strip_tuple_parens(result))
         mutter("  --> %s" % shown_result)
-        # XXX: the time may be wrong when e.g. a generator object is returned from
-        # an http readv, if the object is returned before the bulk data
-        # is read.
-        elapsed = time.time() - before
-        if result_len and elapsed > 0:
-            # this is the rate of higher-level data, not the raw network speed
-            mutter("      %9.03fs %8dKB/s" % (elapsed, result_len/elapsed/1024))
-        else:
-            mutter("      %9.03fs" % (elapsed))
-        return result
+        # The log decorator no longer shows the elapsed time or transfer rate
+        # because they're available in the log prefixes and the transport
+        # activity display respectively.
+        if False:
+            elapsed = time.time() - before
+            if result_len and elapsed > 0:
+                # this is the rate of higher-level data, not the raw network speed
+                mutter("      %9.03fs %8dKB/s" % (elapsed, result_len/elapsed/1024))
+            else:
+                mutter("      %9.03fs" % (elapsed))
+        return return_result
 
     def _shorten(self, x):
         if len(x) > 70:

=== modified file 'bzrlib/transport/trace.py'
--- bzrlib/transport/trace.py	2009-03-23 14:59:43 +0000
+++ bzrlib/transport/trace.py	2009-07-02 04:35:11 +0000
@@ -33,6 +33,9 @@
     Not all operations are logged at this point, if you need an unlogged
     operation please add a test to the tests of this transport, for the logging
     of the operation you want logged.
+
+    See also TransportLogDecorator, that records a machine-readable log in 
+    memory for eg testing.
     """
 
     def __init__(self, url, _decorated=None, _from_transport=None):
@@ -126,7 +129,8 @@
 
     def readv(self, relpath, offsets, adjust_for_latency=False,
         upper_limit=None):
-        """See Transport.readv."""
+        # we override at the readv() level rather than _readv() so that any
+        # latency adjustments will be done by the underlying transport
         self._trace(('readv', relpath, offsets, adjust_for_latency,
             upper_limit))
         return self._decorated.readv(relpath, offsets, adjust_for_latency,