Merge lp:~facundo/ubuntuone-client/aq-memory-improvements into lp:ubuntuone-client

[Facundo Batista]

Stop storing wrapped functions in every queued command.

Stop storing wrapped functions in every queued command.

For this, I heavily refactored the demark method. Tests included.

Also, fixed mklog to log correctly (and a little speedup).

[John O'Brien (jdobrien)]

looks good, and all tests pass.... InlineCallbacks FTW!

review: Approve

[Guillermo Gonzalez (verterok)]

looks good!

review: Approve

[dobey (dobey)]

The attempt to merge lp:~facundo/ubuntuone-client/aq-memory-improvements into lp:ubuntuone-client failed.Below is the output from the failed tests.

/usr/bin/gnome-autogen.sh
checking for autoconf >= 2.53...
  testing autoconf2.50... not found.
  testing autoconf... found 2.67
checking for automake >= 1.10...
  testing automake-1.11... found 1.11.1
checking for libtool >= 1.5...
  testing libtoolize... found 2.2.6b
checking for intltool >= 0.30...
  testing intltoolize... found 0.41.1
checking for pkg-config >= 0.14.0...
  testing pkg-config... found 0.25
Checking for required M4 macros...
Checking for forbidden M4 macros...
Processing ./configure.ac
Running libtoolize...
libtoolize: putting auxiliary files in `.'.
libtoolize: copying file `./ltmain.sh'
libtoolize: putting macros in AC_CONFIG_MACRO_DIR, `m4'.
libtoolize: copying file `m4/libtool.m4'
libtoolize: copying file `m4/ltoptions.m4'
libtoolize: copying file `m4/ltsugar.m4'
libtoolize: copying file `m4/ltversion.m4'
libtoolize: copying file `m4/lt~obsolete.m4'
Running intltoolize...
Running aclocal-1.11...
Running autoconf...
Running autoheader...
Running automake-1.11...
Running ./configure --with-protocol=/var/cache/tarmac/ubuntuone-storage-protocol/trunk ...
checking for a BSD-compatible install... /usr/bin/install -c
checking whether build environment is sane... yes
checking for a thread-safe mkdir -p... /bin/mkdir -p
checking for gawk... gawk
checking whether make sets $(MAKE)... yes
checking for style of include used by make... GNU
checking for gcc... gcc
checking whether the C compiler works... yes
checking for C compiler default output file name... a.out
checking for suffix of executables...
checking whether we are cross compiling... no
checking for suffix of object files... o
checking whether we are using the GNU C compiler... yes
checking whether gcc accepts -g... yes
checking for gcc option to accept ISO C89... none needed
checking dependency style of gcc... gcc3
checking for library containing strerror... none required
checking for gcc... (cached) gcc
checking whether we are using the GNU C compiler... (cached) yes
checking whether gcc accepts -g... (cached) yes
checking for gcc option to accept ISO C89... (cached) none needed
checking dependency style of gcc... (cached) gcc3
checking build system type... i686-pc-linux-gnu
checking host system type... i686-pc-linux-gnu
checking for a sed that does not truncate output... /bin/sed
checking for grep that handles long lines and -e... /bin/grep
checking for egrep... /bin/grep -E
checking for fgrep... /bin/grep -F
checking for ld used by gcc... /usr/bin/ld
checking if the linker (/usr/bin/ld) is GNU ld... yes
checking for BSD- or MS-compatible name lister (nm)... /usr/bin/nm -B
checking the name lister (/usr/bin/nm -B) interface... BSD nm
checking whether ln -s works... yes
checking the maximum length of command line arguments... 1572864
checking whether the shell understands some XSI constructs... yes
checking whether the shell understands "+="... yes
checking for /usr/bin/ld option to reload object files... -r
checking for objdump... objdump
checking how to recognize dependent libraries... pass_all
checking for ar... ar
check...

[dobey (dobey)]

This should fix the dbus-docs failing problem during make dist:

=== modified file 'Makefile.am'
--- Makefile.am 2010-07-15 22:03:27 +0000
+++ Makefile.am 2010-08-23 14:35:33 +0000
@@ -76,7 +76,7 @@ test-coverage: logging.conf $(clientdefs

 check: lint test Makefile

-docs: Makefile
+docs: $(clientdefs_DATA) Makefile
  $(mkdir_p) docs
  if test "x$(builddir)" != "x$(srcdir)" -a -f "$(srcdir)/docs/syncdaemon_dbus_api.txt"; then \
   $(LN_S) "$(top_srcdir)/docs/syncdaemon_dbus_api.txt" "docs/syncdaemon_dbus_api.txt"; \

=== modified file 'tests/syncdaemon/test_action_queue.py'
--- tests/syncdaemon/test_action_queue.py	2010-08-17 14:23:31 +0000
+++ tests/syncdaemon/test_action_queue.py	2010-08-20 22:22:40 +0000
@@ -55,6 +55,7 @@
     DeltaList,
 )
 from ubuntuone.syncdaemon.event_queue import EventQueue, EVENTS
+from ubuntuone.syncdaemon.marker import MDMarker
 
 
 PATH = u'~/Documents/pdfs/moño/'
@@ -1058,6 +1059,7 @@
     def setUp(self):
         """Set up."""
         res = super(ActionQueueCommandTestCase, self).setUp()
+        self.handler.setLevel(logging.DEBUG)
 
         class MyCommand(ActionQueueCommand):
             logged_attrs = ('a', 'b', 'c', 'd')
@@ -1067,6 +1069,7 @@
 
         request_queue = RequestQueue(name='fu', action_queue=self.action_queue)
         self.cmd = MyCommand(request_queue)
+        self.cmd.start_unqueued()  # just for it to create its logger
 
         return res
 
@@ -1075,35 +1078,101 @@
         d = self.cmd.to_dict()
         self.assertEqual(d, dict(a=3, b='foo', c=u'año', d=None))
 
-    def test_unwrap_no_results(self):
-        """Test unwrap with no results."""
-        r = self.cmd.unwrap([])
-        self.assertEqual(r, [])
-
-    def test_unwrap_one_result_ok(self):
-        """Test unwrap with one result ok."""
-        r = self.cmd.unwrap([(True, 'foo')])
-        self.assertEqual(r, ['foo'])
-
-    def test_unwrap_result_None(self):
-        """Test unwrap with None a valid result."""
-        r = self.cmd.unwrap([None])
-        self.assertEqual(r, [])
-
-    def test_unwrap_result_failed(self):
-        """Test unwrap with a not ok result."""
-        r = self.cmd.unwrap([(False, 'failure')])
-        self.assertEqual(r, 'failure')
-
-    def test_unwrap_mixed_results_ok(self):
-        """Test unwrap with different results no failure."""
-        r = self.cmd.unwrap([(True, 'foo'), None, (True, 'bar')])
-        self.assertEqual(r, ['foo', 'bar'])
-
-    def test_unwrap_mixed_results_failure(self):
-        """Test unwrap with different results one failure."""
-        r = self.cmd.unwrap([(True, 'foo'), (False, 'fail'), (True, 'bar')])
-        self.assertEqual(r, 'fail')
+    @defer.inlineCallbacks
+    def test_demark_not_marker(self):
+        """Test demark with not a marker."""
+        result = yield self.cmd.demark('not a marker')
+        self.assertEqual(result, ['not a marker'])
+
+    @defer.inlineCallbacks
+    def test_demark_with_marker_future(self):
+        """Test demark with a marker not ready.
+
+        Here, on purpose, set up everything and trigger later.
+        """
+        marker = MDMarker('foo')
+        d = self.cmd.demark(marker)
+
+        self.action_queue.uuid_map.set(marker, 'node_id')
+        result = yield d
+        self.assertEqual(result, ['node_id'])
+        self.assertTrue(self.handler.check_debug(
+                        "waiting for the real value of 'foo'"))
+
+    @defer.inlineCallbacks
+    def test_demark_with_marker_ready(self):
+        """Test demark with a marker that had data."""
+        marker = MDMarker('foo')
+        self.action_queue.uuid_map.set(marker, 'node_id')
+        result = yield self.cmd.demark(marker)
+        self.assertEqual(result, ['node_id'])
+        self.assertTrue(self.handler.check_debug(
+                        "waiting for the real value of 'foo'"))
+
+    @defer.inlineCallbacks
+    def test_demark_mixed_markers(self):
+        """Test demark with both a marker and not."""
+        # call demark with both
+        marker = MDMarker('foo')
+        self.action_queue.uuid_map.set(marker, 'node_id')
+        result = yield self.cmd.demark('notamarker', marker)
+
+        # check
+        self.assertEqual(result, ['notamarker', 'node_id'])
+        self.assertTrue(self.handler.check_debug(
+                        "waiting for the real value of 'foo'"))
+        self.assertFalse(self.handler.check_debug(
+                         "waiting for the real value of 'notamarker'"))
+
+    @defer.inlineCallbacks
+    def test_demark_marker_ready_got_ok(self):
+        """Test demark getting a marker triggered ok now."""
+        marker = MDMarker('foo')
+        self.action_queue.uuid_map.set(marker, 'node_id')
+        result = yield self.cmd.demark(marker)
+        self.assertEqual(result, ['node_id'])
+        self.assertTrue(self.handler.check_debug("got 'foo'"))
+
+    @defer.inlineCallbacks
+    def test_demark_marker_future_got_ok(self):
+        """Test demark getting a marker triggered ok later."""
+        # don't have the info now
+        marker = MDMarker('foo')
+        d = self.cmd.demark(marker)
+        self.assertFalse(self.handler.check_debug("got 'foo'"))
+
+        # set and check
+        self.action_queue.uuid_map.set(marker, 'node_id')
+        result = yield d
+        self.assertEqual(result, ['node_id'])
+        self.assertTrue(self.handler.check_debug("got 'foo'"))
+
+    @defer.inlineCallbacks
+    def test_demark_marker_ready_got_failure(self):
+        """Test demark getting a marker triggered with failure now."""
+        marker = MDMarker('foo')
+        self.action_queue.uuid_map.err(marker, Failure(Exception('bad')))
+        try:
+            yield self.cmd.demark(marker)
+        except Exception, e:
+            self.assertEqual(str(e), 'bad')
+            self.assertTrue(self.handler.check_error("failed 'foo'"))
+
+    @defer.inlineCallbacks
+    def test_demark_marker_future_got_failure(self):
+        """Test demark getting a marker triggered with failure later."""
+        # don't have the info now
+        marker = MDMarker('foo')
+        d = self.cmd.demark(marker)
+        self.assertFalse(self.handler.check_error("failed 'foo'"))
+
+        # set the marker and check
+        self.action_queue.uuid_map.err(marker, Failure(Exception('bad')))
+        try:
+            yield d
+        except Exception, e:
+            self.assertEqual(str(e), 'bad')
+            self.assertTrue(self.handler.check_error("failed 'foo'"))
 
 
 class CreateUDFTestCase(ConnectedBaseTestCase):

=== modified file 'ubuntuone/syncdaemon/action_queue.py'
--- ubuntuone/syncdaemon/action_queue.py	2010-08-17 14:23:31 +0000
+++ ubuntuone/syncdaemon/action_queue.py	2010-08-20 22:22:40 +0000
@@ -254,7 +254,7 @@
         try:
             if upload.cancelled:
                 raise UploadCompressionCancelled("Cancelled")
-            upload.log.debug('compressing', filename)
+            upload.log.debug('compressing: %r', filename)
             # we need to compress the file completely to figure out its
             # compressed size. So streaming is out :(
             if upload.tempfile_factory is None:
@@ -519,8 +519,7 @@
         self.map = {}
 
     def get(self, key):
-        """
-        Get the value for the given key.
+        """Get the value for the given key.
 
         This always returns a deferred; when we already know the value
         we return a `succeed`, and if we don't know the value because
@@ -537,9 +536,9 @@
         return d
 
     def set(self, key, value):
-        """
-        We've got the value for a key! Write it down in the map, and
-        fire the waiting deferreds.
+        """We've got the value for a key!
+
+        Write it down in the map, and fire the waiting deferreds.
         """
         if key not in self.map:
             self.map[key] = value
@@ -550,18 +549,18 @@
                 raise KeyError("key is taken -- dunno what to do")
 
     def err(self, key, failure):
-        """
-        Something went terribly wrong in the process of getting a
-        value. Break the news to the waiting deferreds.
+        """Something went terribly wrong in the process of getting a value.
+
+        Break the news to the waiting deferreds.
         """
         self.failed[key] = failure.getErrorMessage()
         for d in self.waiting.pop(key, ()):
             d.errback(failure)
 
     def resolve_maybe(self, key):
-        """
-        Return either the mapping of key (if key has been resolved),
-        or key itself (if not).
+        """Return either the mapping of key, or key itself.
+
+        The former if key has been resolved, the later if not.
         """
         return self.map.get(key, key)
 
@@ -1238,43 +1237,24 @@
     def check_conditions(self):
         """Check conditions on which the command may be waiting."""
 
+    @defer.inlineCallbacks
     def demark(self, *maybe_markers):
         """Arrange to have maybe_markers realized."""
-        l = []
+        results = []
         for marker in maybe_markers:
             if IMarker.providedBy(marker):
-                self.log.debug('waiting until we know the real value of %r',
-                               marker)
-                d = self.action_queue.uuid_map.get(marker)
-                d.addCallbacks(passit(lambda _:
-                                      self.log.debug('got %r', marker)),
-                               passit(lambda f:
-                                      self.log.error('failed %r', marker)))
+                self.log.debug("waiting for the real value of '%s'", marker)
+                try:
+                    result = yield self.action_queue.uuid_map.get(marker)
+                except:
+                    self.log.error("failed '%s'", marker)
+                    raise
+                else:
+                    self.log.debug("got '%s'", marker)
+                    results.append(result)
             else:
-                d = defer.succeed(marker)
-            l.append(d)
-        dl = defer.DeferredList(l, fireOnOneErrback=True, consumeErrors=True)
-        dl.addCallbacks(self.unwrap, lambda f: f.value.subFailure)
-
-        return dl
-
-    @staticmethod
-    def unwrap(results):
-        """Unpack the values from the result of a DeferredList.
-
-        If there's a failure, return it instead.
-        """
-        values = []
-        for result in results:
-            # result can be none if one of the callbacks failed
-            # before the others were ready
-            if result is not None:
-                is_ok, value = result
-                if not is_ok:
-                    # a failure!
-                    return value
-                values.append(value)
-        return values
+                results.append(marker)
+        defer.returnValue(results)
 
     def end_callback(self, arg):
         """It worked!"""
@@ -1288,9 +1268,9 @@
         """It failed!"""
         error_message = failure.getErrorMessage()
         if failure.check(*self.suppressed_error_messages):
-            self.log.warn('failure', error_message)
+            self.log.warn('failure: %s', error_message)
         else:
-            self.log.error('failure', error_message)
+            self.log.error('failure: %s', error_message)
             self.log.debug('traceback follows:\n\n' + failure.getTraceback())
         was_running = self.running
         self.cleanup()
@@ -1984,7 +1964,7 @@
                     cmd.volume_id == self.volume_id:
                 # other GetDeltaFromScratch for same volume! skip self
                 m = "GetDeltaFromScratch already queued, not queueing self"
-                self.log.debug(m, cmd)
+                self.log.debug(m)
                 return
 
         # no similar command

=== modified file 'ubuntuone/syncdaemon/logger.py'
--- ubuntuone/syncdaemon/logger.py	2010-07-27 17:15:58 +0000
+++ ubuntuone/syncdaemon/logger.py	2010-08-20 22:22:40 +0000
@@ -23,7 +23,6 @@
 import os
 import zlib
 
-from itertools import imap
 from ubuntuone.logger import (
     LOGFOLDER,
     _DEBUG_LOG_LEVEL,
@@ -65,33 +64,36 @@
         self.zipped_desc = zlib.compress(desc, 9)
         self.logger = _logger
 
-    @property
-    def desc(self):
-        return zlib.decompress(self.zipped_desc)
-
     def _log(self, logger_func, *args):
-        """
-        Generalized form of the different logging functions.
-        """
-        logger_func(self.desc + " ".join(imap(str, args)))
+        """Generalized form of the different logging methods."""
+        desc = zlib.decompress(self.zipped_desc)
+        text = desc + args[0]
+        logger_func(text, *args[1:])
+
     def debug(self, *args):
         """Log at level DEBUG"""
         self._log(self.logger.debug, *args)
+
     def info(self, *args):
         """Log at level INFO"""
         self._log(self.logger.info, *args)
+
     def warn(self, *args):
         """Log at level WARN"""
         self._log(self.logger.warn, *args)
+
     def error(self, *args):
         """Log at level ERROR"""
         self._log(self.logger.error, *args)
+
     def exception(self, *args):
         """Log an exception"""
         self._log(self.logger.exception, *args)
+
     def note(self, *args):
         """Log at NOTE level (high-priority info) """
         self._log(self.logger.high, *args)
+
     def trace(self, *args):
         """Log at level TRACE"""
         self._log(self.logger.trace, *args)