Merge lp:~cjwatson/launchpad/always-copy-packages-asynchronously-2 into lp:launchpad

[Colin Watson]

Remove the old synchronous package copy path in favour of PackageCopyJobs.

== Summary ==

This is my second attempt at https://code.launchpad.net/~cjwatson/launchpad/always-copy-packages-asynchronously/+merge/131837; Curtis reverted the previous attempt on my behalf since it broke buildbot.

== Proposed fix ==

The complicated bit here was fixing xx-copy-packages.txt, which is a long and horrible doctest built around synchronous copies. The bulk of the fix is fairly mechanical: run copy jobs after each copy operation in the UI. However, to make this work well, I needed to make PCJs say what they're copying in their debug output, as otherwise there was no way to get an accurate idea of which binaries were copied; this seems likely to be occasionally useful elsewhere anyway.

I also noticed that it was a bit odd that the old synchronous path named the target archive in its notification while the new asynchronous path doesn't, and this inconvenienced xx-copy-packages.txt a bit since it wanted to follow that link. I therefore added this to the asynchronous notification.

== Tests ==

bin/test -vvct lp.registry.browser.tests.test_distroseries -t soyuz

== Demo and Q/A ==

Verify that copies between PPAs using the web UI still work.

[Colin Watson (cjwatson)]

Don't review this yet - I made another mistake ...

[Colin Watson (cjwatson)]

OK, this should be worth reviewing again now.

[William Grant (wgrant)]

Unless I'm forgetting something, this eliminates the penultimate delayed copy callsite, the last being the API's Archive.syncSource(s). Do you have a strategy for the final excision of that callsite and the significant volume of called code?

240 + if dest_url is None:
241 + dest_url = escape(
242 + canonical_url(dest_archive) + '/+packages', quote=True)
243 +
244 + if dest_display_name is None:
245 + dest_display_name = escape(dest_archive.displayname)

This will probably double escape them; structured() escapes parameters itself. I'd also avoid talking about the escaping in the docstring, as one wouldn't normally expect a string to be passed through unescaped unless the docstring explicitly asked for HTML.

708 + for copy in copied_publications:
709 + self.logger.debug(copy.displayname)

What does the logging around this look like? AFAICT the job doesn't log much else, so it may seem somewhat of a non sequitur in the output.

review: Approve (code)

[Colin Watson (cjwatson)]

On Tue, Nov 13, 2012 at 05:49:20AM -0000, William Grant wrote:
> Unless I'm forgetting something, this eliminates the penultimate
> delayed copy callsite, the last being the API's Archive.syncSource(s).
> Do you have a strategy for the final excision of that callsite and the
> significant volume of called code?

Not only a strategy but a pending branch that I'll be ready to submit
shortly after this lands.

> This will probably double escape them; structured() escapes parameters
> itself. I'd also avoid talking about the escaping in the docstring, as
> one wouldn't normally expect a string to be passed through unescaped
> unless the docstring explicitly asked for HTML.

This mistake was because compose_synchronous_copy_feedback used
structured() in a slightly different way (with %-formatting rather than
passing separate replacement arguments, so structured() wouldn't have
handled escaping there). Fixed.

> What does the logging around this look like? AFAICT the job doesn't
> log much else, so it may seem somewhat of a non sequitur in the
> output.

I added an extra line of logging to alleviate confusion. (Of course, if
we actually want to see it routinely we'll need to change the PCJ runner
to log at DEBUG; should this be at INFO instead, or is it fine as it
is?)

=== modified file 'lib/lp/registry/browser/distroseries.py'
--- lib/lp/registry/browser/distroseries.py	2012-07-30 12:11:31 +0000
+++ lib/lp/registry/browser/distroseries.py	2012-11-13 09:52:27 +0000
@@ -960,15 +960,11 @@
 
         sponsored_person = data.get("sponsored_person")
 
-        # When syncing we *must* do it asynchronously so that a package
-        # copy job is created.  This gives the job a chance to inspect
-        # the copy and create a PackageUpload if required.
         if self.do_copy(
             'selected_differences', sources, self.context.main_archive,
             self.context, destination_pocket, include_binaries=False,
             dest_url=series_url, dest_display_name=series_title,
-            person=self.user, force_async=True,
-            sponsored_person=sponsored_person):
+            person=self.user, sponsored_person=sponsored_person):
             # The copy worked so we redirect back to show the results. Include
             # the query string so that the user ends up on the same batch page
             # with the same filtering parameters as before.

=== modified file 'lib/lp/registry/browser/tests/test_distroseries.py'
--- lib/lp/registry/browser/tests/test_distroseries.py	2012-09-28 06:25:44 +0000
+++ lib/lp/registry/browser/tests/test_distroseries.py	2012-11-13 09:52:27 +0000
@@ -2099,9 +2099,7 @@
         self.assertEqual(0, len(view.errors))
         notifications = view.request.response.notifications
         self.assertEqual(1, len(notifications))
-        self.assertIn(
-            "Requested sync of 1 package.",
-            notifications[0].message)
+        self.assertIn("Requested sync of 1 package", notifications[0].message)
         # 302 is a redirect back to the same page.
         self.assertEqual(302, view.request.response.getStatus())
 
@@ -2311,25 +2309,42 @@
             self.assertEqual(1, len(view.cached_differences.batch))
 
 
-class TestCopyAsynchronouslyMessage(TestCase):
+class TestCopyAsynchronouslyMessage(TestCaseWithFactory):
     """Test the helper function `copy_asynchronously_message`."""
 
+    layer = DatabaseFunctionalLayer
+
+    def setUp(self):
+        super(TestCopyAsynchronouslyMessage, self).setUp()
+        self.archive = self.factory.makeArchive()
+        self.series = self.factory.makeDistroSeries()
+        self.series_url = canonical_url(self.series)
+        self.series_title = self.series.displayname
+
+    def message(self, source_pubs_count):
+        return copy_asynchronously_message(
+            source_pubs_count, self.archive, dest_url=self.series_url,
+            dest_display_name=self.series_title)
+
     def test_zero_packages(self):
         self.assertEqual(
-            "Requested sync of 0 packages.",
-            copy_asynchronously_message(0).escapedtext)
+            'Requested sync of 0 packages to <a href="%s">%s</a>.' %
+                (self.series_url, self.series_title),
+            self.message(0).escapedtext)
 
     def test_one_package(self):
         self.assertEqual(
-            "Requested sync of 1 package.<br />Please "
-            "allow some time for this to be processed.",
-            copy_asynchronously_message(1).escapedtext)
+            'Requested sync of 1 package to <a href="%s">%s</a>.<br />'
+            'Please allow some time for this to be processed.' %
+                (self.series_url, self.series_title),
+            self.message(1).escapedtext)
 
     def test_multiple_packages(self):
         self.assertEqual(
-            "Requested sync of 5 packages.<br />Please "
-            "allow some time for these to be processed.",
-            copy_asynchronously_message(5).escapedtext)
+            'Requested sync of 5 packages to <a href="%s">%s</a>.<br />'
+            'Please allow some time for these to be processed.' %
+                (self.series_url, self.series_title),
+            self.message(5).escapedtext)
 
 
 class TestDistroSeriesNeedsPackagesView(TestCaseWithFactory):

=== modified file 'lib/lp/services/features/flags.py'
--- lib/lp/services/features/flags.py	2012-11-08 06:06:22 +0000
+++ lib/lp/services/features/flags.py	2012-11-13 09:52:27 +0000
@@ -154,12 +154,6 @@
      '',
      '',
      ''),
-    ('soyuz.derived_series.max_synchronous_syncs',
-     'int',
-     "How many package syncs may be done directly in a web request.",
-     '100',
-     '',
-     ''),
     ('soyuz.derived_series_sync.enabled',
      'boolean',
      'Enables syncing of packages on derivative distributions pages.',

=== modified file 'lib/lp/soyuz/browser/archive.py'
--- lib/lp/soyuz/browser/archive.py	2012-11-01 03:41:36 +0000
+++ lib/lp/soyuz/browser/archive.py	2012-11-13 09:52:27 +0000
@@ -92,11 +92,7 @@
     get_plural_text,
     get_user_agent_distroseries,
     )
-from lp.services.database.bulk import (
-    load,
-    load_related,
-    )
-from lp.services.features import getFeatureFlag
+from lp.services.database.bulk import load_related
 from lp.services.helpers import english_list
 from lp.services.job.model.job import Job
 from lp.services.librarian.browser import FileNavigationMixin
@@ -166,21 +162,8 @@
     Archive,
     validate_ppa,
     )
-from lp.soyuz.model.binarypackagename import BinaryPackageName
-from lp.soyuz.model.publishing import (
-    BinaryPackagePublishingHistory,
-    SourcePackagePublishingHistory,
-    )
-from lp.soyuz.scripts.packagecopier import (
-    check_copy_permissions,
-    do_copy,
-    )
-
-# Feature flag: up to how many package sync requests (inclusive) are to be
-# processed synchronously within the web request?
-# Set to -1 to disable synchronous syncs.
-FEATURE_FLAG_MAX_SYNCHRONOUS_SYNCS = (
-    'soyuz.derived_series.max_synchronous_syncs')
+from lp.soyuz.model.publishing import SourcePackagePublishingHistory
+from lp.soyuz.scripts.packagecopier import check_copy_permissions
 
 
 class ArchiveBadges(HasBadgeBase):
@@ -1256,63 +1239,6 @@
     _messageNoValue = _("vocabulary-copy-to-same-series", "The same series")
 
 
-def preload_binary_package_names(copies):
-    """Preload `BinaryPackageName`s to speed up display-name construction."""
-    bpn_ids = [
-        copy.binarypackagerelease.binarypackagenameID for copy in copies
-        if isinstance(copy, BinaryPackagePublishingHistory)]
-    load(BinaryPackageName, bpn_ids)
-
-
-def compose_synchronous_copy_feedback(copies, dest_archive, dest_url=None,
-                                      dest_display_name=None):
-    """Compose human-readable feedback after a synchronous copy."""
-    if dest_url is None:
-        dest_url = escape(
-            canonical_url(dest_archive) + '/+packages', quote=True)
-
-    if dest_display_name is None:
-        dest_display_name = escape(dest_archive.displayname)
-
-    if len(copies) == 0:
-        return structured(
-            '<p>All packages already copied to <a href="%s">%s</a>.</p>'
-            % (dest_url, dest_display_name))
-    else:
-        messages = []
-        messages.append(
-            '<p>Packages copied to <a href="%s">%s</a>:</p>'
-            % (dest_url, dest_display_name))
-        messages.append('<ul>')
-        messages.append("\n".join([
-            '<li>%s</li>' % escape(copy) for copy in copies]))
-        messages.append('</ul>')
-        return structured("\n".join(messages))
-
-
-def copy_synchronously(source_pubs, dest_archive, dest_series, dest_pocket,
-                       include_binaries, dest_url=None,
-                       dest_display_name=None, person=None,
-                       check_permissions=True):
-    """Copy packages right now.
-
-    :return: A `structured` with human-readable feedback about the
-        operation.
-    :raises CannotCopy: If `check_permissions` is True and the copy is
-        not permitted.
-    """
-    copies = do_copy(
-        source_pubs, dest_archive, dest_series, dest_pocket, include_binaries,
-        allow_delayed_copies=True, person=person,
-        check_permissions=check_permissions)
-
-    preload_binary_package_names(copies)
-
-    return compose_synchronous_copy_feedback(
-        [copy.displayname for copy in copies], dest_archive, dest_url,
-        dest_display_name)
-
-
 def copy_asynchronously(source_pubs, dest_archive, dest_series, dest_pocket,
                         include_binaries, dest_url=None,
                         dest_display_name=None, person=None,
@@ -1336,29 +1262,45 @@
             dest_pocket, include_binaries=include_binaries,
             package_version=spph.sourcepackagerelease.version,
             copy_policy=PackageCopyPolicy.INSECURE,
-            requester=person, sponsored=sponsored, unembargo=True)
-
-    return copy_asynchronously_message(len(source_pubs))
-
-
-def copy_asynchronously_message(source_pubs_count):
+            requester=person, sponsored=sponsored, unembargo=True,
+            source_distroseries=spph.distroseries, source_pocket=spph.pocket)
+
+    return copy_asynchronously_message(
+        len(source_pubs), dest_archive, dest_url, dest_display_name)
+
+
+def copy_asynchronously_message(source_pubs_count, dest_archive, dest_url=None,
+                                dest_display_name=None):
     """Return a message detailing the sync action.
 
     :param source_pubs_count: The number of source pubs requested for syncing.
+    :param dest_archive: The destination IArchive.
+    :param dest_url: The URL of the destination to display in the
+        notification box.  Defaults to the target archive.
+    :param dest_display_name: The text to use for the dest_url link.
+        Defaults to the target archive's display name.
     """
+    if dest_url is None:
+        dest_url = canonical_url(dest_archive) + '/+packages'
+
+    if dest_display_name is None:
+        dest_display_name = dest_archive.displayname
+
     package_or_packages = get_plural_text(
         source_pubs_count, "package", "packages")
     if source_pubs_count == 0:
         return structured(
-            "Requested sync of %s %s.",
-            source_pubs_count, package_or_packages)
+            'Requested sync of %s %s to <a href="%s">%s</a>.',
+            source_pubs_count, package_or_packages, dest_url,
+            dest_display_name)
     else:
         this_or_these = get_plural_text(
             source_pubs_count, "this", "these")
         return structured(
-            "Requested sync of %s %s.<br />"
+            'Requested sync of %s %s to <a href="%s">%s</a>.<br />'
             "Please allow some time for %s to be processed.",
-            source_pubs_count, package_or_packages, this_or_these)
+            source_pubs_count, package_or_packages, dest_url,
+            dest_display_name, this_or_these)
 
 
 def render_cannotcopy_as_html(cannotcopy_exception):
@@ -1385,28 +1327,14 @@
 class PackageCopyingMixin:
     """A mixin class that adds helpers for package copying."""
 
-    def canCopySynchronously(self, source_pubs):
-        """Can we afford to copy `source_pubs` synchronously?"""
-        # Fixed estimate: up to 100 packages can be copied in acceptable
-        # time.  Anything more than that and we go async.
-        limit = getFeatureFlag(FEATURE_FLAG_MAX_SYNCHRONOUS_SYNCS)
-        try:
-            limit = int(limit)
-        except:
-            limit = 100
-
-        return len(source_pubs) <= limit
-
     def do_copy(self, sources_field_name, source_pubs, dest_archive,
                 dest_series, dest_pocket, include_binaries,
                 dest_url=None, dest_display_name=None, person=None,
-                check_permissions=True, force_async=False,
-                sponsored_person=None):
+                check_permissions=True, sponsored_person=None):
         """Copy packages and add appropriate feedback to the browser page.
 
-        This may either copy synchronously, if there are few enough
-        requests to process right now; or asynchronously in which case
-        it will schedule jobs that will be processed by a script.
+        This will copy asynchronously, scheduling jobs that will be
+        processed by a script.
 
         :param sources_field_name: The name of the form field to set errors
             on when the copy fails
@@ -1425,30 +1353,18 @@
         :param person: The person requesting the copy.
         :param: check_permissions: boolean indicating whether or not the
             requester's permissions to copy should be checked.
-        :param force_async: Force the copy to create package copy jobs and
-            perform the copy asynchronously.
         :param sponsored_person: An IPerson representing the person being
-            sponsored (for asynchronous copies only).
+            sponsored.
 
         :return: True if the copying worked, False otherwise.
         """
-        assert force_async or not sponsored_person, (
-            "sponsored must be None for sync copies")
         try:
-            if (force_async == False and
-                    self.canCopySynchronously(source_pubs)):
-                notification = copy_synchronously(
-                    source_pubs, dest_archive, dest_series, dest_pocket,
-                    include_binaries, dest_url=dest_url,
-                    dest_display_name=dest_display_name, person=person,
-                    check_permissions=check_permissions)
-            else:
-                notification = copy_asynchronously(
-                    source_pubs, dest_archive, dest_series, dest_pocket,
-                    include_binaries, dest_url=dest_url,
-                    dest_display_name=dest_display_name, person=person,
-                    check_permissions=check_permissions,
-                    sponsored=sponsored_person)
+            notification = copy_asynchronously(
+                source_pubs, dest_archive, dest_series, dest_pocket,
+                include_binaries, dest_url=dest_url,
+                dest_display_name=dest_display_name, person=person,
+                check_permissions=check_permissions,
+                sponsored=sponsored_person)
         except CannotCopy as error:
             self.setFieldError(
                 sources_field_name, render_cannotcopy_as_html(error))

=== modified file 'lib/lp/soyuz/browser/tests/archive-views.txt'
--- lib/lp/soyuz/browser/tests/archive-views.txt	2012-10-29 16:52:31 +0000
+++ lib/lp/soyuz/browser/tests/archive-views.txt	2012-11-13 09:52:27 +0000
@@ -1342,9 +1342,8 @@
 Copy private files to public archives
 -------------------------------------
 
-Users are allowed to copy private sources into private PPAs, however
-it happens via 'delayed-copies' not the usual direct copying method.
-See more information in scripts/packagecopier.py
+Users are allowed to copy private sources into public PPAs.
+See more information in scripts/packagecopier.py.
 
 First we will enable Celso's private PPA.
 
@@ -1386,61 +1385,13 @@
     >>> len(view.errors)
     0
 
-The action is performed as a delayed-copy, and the user is informed of
+The action is performed as an asynchronous copy, and the user is informed of
 it via a page notification.
 
     >>> from lp.testing.pages import extract_text
     >>> for notification in view.request.response.notifications:
     ...     print extract_text(notification.message)
-    Packages copied to PPA for Ubuntu Team:
-    Delayed copy of foocomm - 2.0-1 (source)
-
-The delayed-copy request is waiting to be processed in the ACCEPTED
-upload queue.
-
-    >>> from lp.soyuz.interfaces.queue import IPackageUploadSet
-    >>> copy = getUtility(IPackageUploadSet).findSourceUpload(
-    ...     'foocomm', '2.0-1', ubuntu_team_ppa, ubuntu)
-
-    >>> print copy.status.name
-    ACCEPTED
-
-The action may also be performed asynchronously.
-
-    >>> from lp.services.features.testing import FeatureFixture
-    >>> from lp.soyuz.browser.archive import (
-    ...     FEATURE_FLAG_MAX_SYNCHRONOUS_SYNCS,
-    ...     )
-    >>> fixture = FeatureFixture({
-    ...     FEATURE_FLAG_MAX_SYNCHRONOUS_SYNCS: '0',
-    ...     })
-    >>> fixture.setUp()
-
-    >>> login('[e-mail]')
-    >>> async_private_source = test_publisher.createSource(
-    ...     cprov_private_ppa, 'foocomm', '1.0-1', new_version='3.0-1')
-    >>> transaction.commit()
-
-    >>> print async_private_source.displayname
-    foocomm 3.0-1 in hoary
-
-    >>> login('[e-mail]')
-    >>> view = create_initialized_view(
-    ...     cprov_private_ppa, name="+copy-packages",
-    ...     form={
-    ...         'field.selected_sources': [str(async_private_source.id)],
-    ...         'field.destination_archive': 'ubuntu-team/ppa',
-    ...         'field.destination_series': '',
-    ...         'field.include_binaries': 'REBUILD_SOURCES',
-    ...         'field.actions.copy': 'Copy',
-    ...         })
-
-    >>> len(view.errors)
-    0
-
-    >>> for notification in view.request.response.notifications:
-    ...     print extract_text(notification.message)
-    Requested sync of 1 package.
+    Requested sync of 1 package to PPA for Ubuntu Team.
     Please allow some time for this to be processed.
 
 There is one copy job waiting, which we run.
@@ -1463,14 +1414,14 @@
     >>> [copied_source] = ubuntu_team_ppa.getPublishedSources(
     ...     name="foocomm", exact_match=True)
     >>> print copied_source.displayname
-    foocomm 3.0-1 in hoary
+    foocomm 2.0-1 in hoary
 
 If we run the same copy again, it will fail.
 
     >>> view = create_initialized_view(
     ...     cprov_private_ppa, name="+copy-packages",
     ...     form={
-    ...         'field.selected_sources': [str(async_private_source.id)],
+    ...         'field.selected_sources': [str(private_source.id)],
     ...         'field.destination_archive': 'ubuntu-team/ppa',
     ...         'field.destination_series': '',
     ...         'field.include_binaries': 'REBUILD_SOURCES',
@@ -1495,12 +1446,10 @@
     >>> for job in ubuntu_team_ppa_view.package_copy_jobs:
     ...     print job.status.title, job.package_name, job.package_version
     ...     print job.error_message
-    Failed foocomm 3.0-1
-    foocomm 3.0-1 in hoary (same version already building in the destination
+    Failed foocomm 2.0-1
+    foocomm 2.0-1 in hoary (same version already building in the destination
     archive for Hoary)
 
-    >>> fixture.cleanUp()
-
 
 External dependencies validation
 ================================

=== modified file 'lib/lp/soyuz/browser/tests/test_package_copying_mixin.py'
--- lib/lp/soyuz/browser/tests/test_package_copying_mixin.py	2012-10-29 16:52:31 +0000
+++ lib/lp/soyuz/browser/tests/test_package_copying_mixin.py	2012-11-13 09:52:27 +0000
@@ -1,4 +1,4 @@
-# Copyright 2011 Canonical Ltd.  This software is licensed under the
+# Copyright 2011-2012 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 """Tests for `PackageCopyingMixin`."""
@@ -9,14 +9,9 @@
 from zope.security.proxy import removeSecurityProxy
 
 from lp.registry.interfaces.pocket import PackagePublishingPocket
-from lp.services.features.testing import FeatureFixture
 from lp.services.propertycache import cachedproperty
 from lp.soyuz.browser.archive import (
-    compose_synchronous_copy_feedback,
     copy_asynchronously,
-    copy_synchronously,
-    FEATURE_FLAG_MAX_SYNCHRONOUS_SYNCS,
-    PackageCopyingMixin,
     render_cannotcopy_as_html,
     )
 from lp.soyuz.enums import SourcePackageFormat
@@ -29,9 +24,7 @@
     TestCase,
     TestCaseWithFactory,
     )
-from lp.testing.fakemethod import FakeMethod
 from lp.testing.layers import LaunchpadFunctionalLayer
-from lp.testing.views import create_initialized_view
 
 
 def find_spph_copy(archive, spph):
@@ -41,40 +34,6 @@
         name=spr.sourcepackagename.name, version=spr.version).one()
 
 
-class FakeDistribution:
-    def __init__(self):
-        self.archive = FakeArchive()
-
-
-class FakeDistroSeries:
-    def __init__(self):
-        self.distribution = FakeDistribution()
-
-
-class FakeSPN:
-    name = "spn-name"
-
-
-class FakeSPR:
-    def __init__(self):
-        self.sourcepackagename = FakeSPN()
-        self.version = "1.0"
-
-
-class FakeArchive:
-    def __init__(self, displayname="archive-name"):
-        self.displayname = displayname
-
-
-class FakeSPPH:
-    def __init__(self, archive=None):
-        if archive is None:
-            archive = FakeArchive()
-        self.sourcepackagerelease = FakeSPR()
-        self.displayname = "spph-displayname"
-        self.archive = archive
-
-
 class TestPackageCopyingMixinLight(TestCase):
     """Test lightweight functions and methods.
 
@@ -83,25 +42,11 @@
 
     unique_number = 1
 
-    def getPocket(self):
-        """Return an arbitrary `PackagePublishingPocket`."""
-        return PackagePublishingPocket.SECURITY
-
     def getUniqueString(self):
         """Return an arbitrary string."""
         self.unique_number += 1
         return "string_%d_" % self.unique_number
 
-    def test_canCopySynchronously_allows_small_synchronous_copies(self):
-        # Small numbers of packages can be copied synchronously.
-        packages = [self.getUniqueString() for counter in range(3)]
-        self.assertTrue(PackageCopyingMixin().canCopySynchronously(packages))
-
-    def test_canCopySynchronously_disallows_large_synchronous_copies(self):
-        # Large numbers of packages must be copied asynchronously.
-        packages = [self.getUniqueString() for counter in range(300)]
-        self.assertFalse(PackageCopyingMixin().canCopySynchronously(packages))
-
     def test_render_cannotcopy_as_html_lists_errors(self):
         # render_cannotcopy_as_html includes a CannotCopy error message
         # into its HTML notice.
@@ -116,24 +61,6 @@
         self.assertNotIn(message, html_text)
         self.assertIn("x&lt;&gt;y", html_text)
 
-    def test_compose_synchronous_copy_feedback_escapes_archive_name(self):
-        # compose_synchronous_copy_feedback escapes archive displaynames.
-        archive = FakeArchive(displayname="a&b")
-        notice = compose_synchronous_copy_feedback(
-            ["hi"], archive, dest_url="/")
-        html_text = notice.escapedtext
-        self.assertNotIn("a&b", html_text)
-        self.assertIn("a&amp;b", html_text)
-
-    def test_compose_synchronous_copy_feedback_escapes_package_names(self):
-        # compose_synchronous_copy_feedback escapes package names.
-        archive = FakeArchive()
-        notice = compose_synchronous_copy_feedback(
-            ["x<y"], archive, dest_url="/")
-        html_text = notice.escapedtext
-        self.assertNotIn("x<y", html_text)
-        self.assertIn("x&lt;y", html_text)
-
 
 class TestPackageCopyingMixinIntegration(TestCaseWithFactory):
     """Integration tests for `PackageCopyingMixin`."""
@@ -180,36 +107,12 @@
             derived_series, SourcePackageFormat.FORMAT_1_0)
         return derived_series
 
-    def makeView(self):
-        """Create a `PackageCopyingMixin`-based view."""
-        return create_initialized_view(
-            self.makeDerivedSeries(), "+localpackagediffs")
-
     def getUploader(self, archive, spn):
         """Get person with upload rights for the given package and archive."""
         uploader = archive.owner
         removeSecurityProxy(archive).newPackageUploader(uploader, spn)
         return uploader
 
-    def test_canCopySynchronously_obeys_feature_flag(self):
-        packages = [self.getUniqueString() for counter in range(3)]
-        mixin = PackageCopyingMixin()
-        with FeatureFixture({FEATURE_FLAG_MAX_SYNCHRONOUS_SYNCS: 2}):
-            can_copy_synchronously = mixin.canCopySynchronously(packages)
-        self.assertFalse(can_copy_synchronously)
-
-    def test_copy_synchronously_copies_packages(self):
-        # copy_synchronously copies packages into the destination
-        # archive.
-        spph = self.makeSPPH()
-        dest_series = self.makeDerivedSeries()
-        archive = dest_series.distribution.main_archive
-        pocket = self.factory.getAnyPocket()
-        copy_synchronously(
-            [spph], archive, dest_series, pocket, include_binaries=False,
-            check_permissions=False)
-        self.assertNotEqual(None, find_spph_copy(archive, spph))
-
     def test_copy_asynchronously_does_not_copy_packages(self):
         # copy_asynchronously does not copy packages into the destination
         # archive; that happens later, asynchronously.
@@ -222,19 +125,6 @@
             check_permissions=False, person=self.factory.makePerson())
         self.assertEqual(None, find_spph_copy(archive, spph))
 
-    def test_copy_synchronously_lists_packages(self):
-        # copy_synchronously returns feedback that includes the names of
-        # packages it copied.
-        spph = self.makeSPPH()
-        dest_series = self.makeDerivedSeries()
-        pocket = self.factory.getAnyPocket()
-        notice = copy_synchronously(
-            [spph], dest_series.distribution.main_archive, dest_series,
-            pocket, include_binaries=False,
-            check_permissions=False).escapedtext
-        self.assertIn(
-            spph.sourcepackagerelease.sourcepackagename.name, notice)
-
     def test_copy_asynchronously_creates_copy_jobs(self):
         # copy_asynchronously creates PackageCopyJobs.
         spph = self.makeSPPH()
@@ -281,46 +171,6 @@
             [("one", spph_one.distroseries), ("two", spph_two.distroseries)],
             [(job.package_name, job.target_distroseries) for job in jobs])
 
-    def test_do_copy_goes_async_if_canCopySynchronously_says_so(self):
-        # The view opts for asynchronous copying if canCopySynchronously
-        # returns False.  This creates PackageCopyJobs.
-        spph = self.makeSPPH()
-        pocket = self.factory.getAnyPocket()
-        view = self.makeView()
-        dest_series = view.context
-        archive = dest_series.distribution.main_archive
-        view.canCopySynchronously = FakeMethod(result=False)
-        view.do_copy(
-            'selected_differences', [spph], archive, dest_series, pocket,
-            False, check_permissions=False, person=self.factory.makePerson())
-        jobs = list(getUtility(IPlainPackageCopyJobSource).getActiveJobs(
-            archive))
-        self.assertNotEqual([], jobs)
-
-    def test_copy_synchronously_may_allow_copy(self):
-        # In a normal working situation, copy_synchronously allows a
-        # copy.
-        spph = self.makeSPPH()
-        pocket = PackagePublishingPocket.RELEASE
-        dest_series = self.makeDerivedSeries()
-        dest_archive = dest_series.main_archive
-        spn = spph.sourcepackagerelease.sourcepackagename
-        notification = copy_synchronously(
-            [spph], dest_archive, dest_series, pocket, False,
-            person=self.getUploader(dest_archive, spn))
-        self.assertIn("Packages copied", notification.escapedtext)
-
-    def test_copy_synchronously_checks_permissions(self):
-        # Unless told not to, copy_synchronously does a permissions
-        # check.
-        spph = self.makeSPPH()
-        pocket = self.factory.getAnyPocket()
-        dest_series = self.makeDistroSeries()
-        self.assertRaises(
-            CannotCopy,
-            copy_synchronously,
-            [spph], dest_series.main_archive, dest_series, pocket, False)
-
     def test_copy_asynchronously_may_allow_copy(self):
         # In a normal working situation, copy_asynchronously allows a
         # copy.

=== modified file 'lib/lp/soyuz/model/packagecopyjob.py'
--- lib/lp/soyuz/model/packagecopyjob.py	2012-10-25 11:02:37 +0000
+++ lib/lp/soyuz/model/packagecopyjob.py	2012-11-13 09:52:27 +0000
@@ -187,6 +187,7 @@
 
     def __init__(self, job):
         self.context = job
+        self.logger = logging.getLogger()
 
     @classmethod
     def get(cls, job_id):
@@ -574,8 +575,7 @@
             # Remember the target archive purpose, as otherwise aborting the
             # transaction will forget it.
             target_archive_purpose = self.target_archive.purpose
-            logger = logging.getLogger()
-            logger.info("Job:\n%s\nraised CannotCopy:\n%s" % (self, e))
+            self.logger.info("Job:\n%s\nraised CannotCopy:\n%s" % (self, e))
             self.abort()  # Abort the txn.
             self.reportFailure(unicode(e))
 
@@ -671,6 +671,12 @@
             # does exist we need to make sure it gets moved to DONE.
             pu.setDone()
 
+        if copied_publications:
+            self.logger.debug(
+                "Packages copied to %s:" % self.target_archive.displayname)
+            for copy in copied_publications:
+                self.logger.debug(copy.displayname)
+
     def abort(self):
         """Abort work."""
         transaction.abort()

=== modified file 'lib/lp/soyuz/stories/ppa/xx-copy-packages.txt'
--- lib/lp/soyuz/stories/ppa/xx-copy-packages.txt	2012-09-27 02:53:00 +0000
+++ lib/lp/soyuz/stories/ppa/xx-copy-packages.txt	2012-11-13 09:52:27 +0000
@@ -137,6 +137,28 @@
     >>> flush_database_updates()
     >>> logout()
 
+Copying packages will create jobs.  Define a simple doctest-friendly runner.
+
+    >>> from zope.security.proxy import removeSecurityProxy
+    >>> from lp.services.log.logger import FakeLogger
+    >>> from lp.soyuz.interfaces.packagecopyjob import (
+    ...     IPlainPackageCopyJobSource,
+    ...     )
+
+    >>> def run_copy_jobs():
+    ...     login('[e-mail]')
+    ...     source = getUtility(IPlainPackageCopyJobSource)
+    ...     for job in removeSecurityProxy(source).iterReady():
+    ...         job.logger = FakeLogger()
+    ...         job.start(manage_transaction=True)
+    ...         try:
+    ...             job.run()
+    ...         except Exception:
+    ...             job.fail(manage_transaction=True)
+    ...         else:
+    ...             job.complete(manage_transaction=True)
+    ...     logout()
+
 Let's say James wants to rebuild the Celso's 'pmount' source in his PPA.
 
 He is a little confused by the number of packages presented by
@@ -235,8 +257,11 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    Packages copied to PPA for James Blackwell:
-    pmount 0.1-1 in hoary
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
+    DEBUG Packages copied to PPA for James Blackwell:
+    DEBUG pmount 0.1-1 in hoary
 
 James uses the link in the copy summary to go straight to the target
 PPA, his own. There he can see the just copied package as PENDING and
@@ -377,9 +402,10 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    There is 1 error.
-    The following source cannot be copied:
-    pmount 0.1-1 in hoary
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
+    INFO ... raised CannotCopy: pmount 0.1-1 in hoary
     (same version already building in the destination archive for Hoary)
 
 Now, knowing that pmount can only be copied within the same PPA if the
@@ -398,8 +424,10 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    There is 1 error.
-    The following source cannot be copied:
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
+    INFO ... raised CannotCopy:
     pmount 0.1-1 in hoary (source has no binaries to be copied)
 
 We will mark the pmount build completed, to emulate the situation
@@ -433,9 +461,10 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    There is 1 error.
-    The following source cannot be copied:
-    pmount 0.1-1 in hoary
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
+    INFO ... raised CannotCopy: pmount 0.1-1 in hoary
     (same version has unpublished binaries in the destination
     archive for Hoary, please wait for them to be published before
     copying)
@@ -453,8 +482,10 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    There is 1 error.
-    The following source cannot be copied:
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
+    INFO ... raised CannotCopy:
     pmount 0.1-1 in hoary (source has no binaries to be copied)
 
 We will build and publish the architecture independent binary for
@@ -491,9 +522,13 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    Packages copied to PPA for James Blackwell:
-    pmount 0.1-1 in grumpy
-    pmount-bin 0.1-1 in grumpy i386
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
+    DEBUG Packages copied to PPA for James Blackwell:
+    DEBUG pmount 0.1-1 in grumpy
+    DEBUG pmount-bin 0.1-1 in grumpy i386
+    >>> jblack_browser.open(jblack_browser.url)
 
 Note that only the i386 binary got copied to grumpy since it lacks
 hppa support.
@@ -519,9 +554,8 @@
     pmount - 0.1-1              Pending    Grumpy           Editors
     pmount - 0.1-1 (Newer...)   Pending    Hoary            Editors
 
-If James performs exactly the same copy procedure again, a message
-stating that all packages involved were already copied to the
-selected destination PPA will be rendered.
+If James performs exactly the same copy procedure again, no more packages
+will be copied.
 
     >>> jblack_browser.getControl(
     ...     name='field.selected_sources').value = [pmount_pub_id]
@@ -533,7 +567,9 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    All packages already copied to PPA for James Blackwell.
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
 
 After some time, James realises that pmount in hoary doesn't make much
 sense and simply deletes it, so his users won't be bothered by this
@@ -603,9 +639,10 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    There is 1 error.
-    The following source cannot be copied:
-    pmount 0.1-1 in hoary
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
+    INFO ... raised CannotCopy: pmount 0.1-1 in hoary
     (same version already has published binaries in the destination
     archive)
 
@@ -624,13 +661,16 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    Packages copied to PPA for James Blackwell:
-    pmount 0.1-1 in warty
-    pmount-bin 0.1-1 in warty hppa
-    pmount-bin 0.1-1 in warty i386
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
+    DEBUG Packages copied to PPA for James Blackwell:
+    DEBUG pmount 0.1-1 in warty
+    DEBUG pmount-bin 0.1-1 in warty hppa
+    DEBUG pmount-bin 0.1-1 in warty i386
+    >>> jblack_browser.open(jblack_browser.url)
 
-James sees the just-copied 'pmount' source in warty pending
-publication.
+James sees the just-copied 'pmount' source in warty pending publication.
 
     >>> print_ppa_packages(jblack_browser.contents)
     Source          Published   Status     Series           Section  Build
@@ -717,12 +757,16 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    Packages copied to PPA for James Blackwell Friends:
-    iceweasel 1.0 in hoary
-    mozilla-firefox 1.0 in hoary i386
-    pmount 0.1-1 in hoary
-    pmount 0.1-1 in hoary hppa
-    pmount 0.1-1 in hoary i386
+    Requested sync of 2 packages to PPA for James Blackwell Friends.
+    Please allow some time for these to be processed.
+    >>> run_copy_jobs()
+    DEBUG Packages copied to PPA for James Blackwell Friends:
+    DEBUG iceweasel 1.0 in hoary
+    DEBUG mozilla-firefox 1.0 in hoary i386
+    DEBUG Packages copied to PPA for James Blackwell Friends:
+    DEBUG pmount 0.1-1 in hoary
+    DEBUG pmount 0.1-1 in hoary hppa
+    DEBUG pmount 0.1-1 in hoary i386
 
 So happy-hacking for James Friends, Celso's 'iceweasel' and 'pmount'
 sources and binaries are copied to their PPA.
@@ -780,11 +824,12 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    There is 1 error.
-    The following sources cannot be copied:
-    iceweasel 1.0 in hoary
+    Requested sync of 2 packages to PPA for James Blackwell Friends.
+    Please allow some time for these to be processed.
+    >>> run_copy_jobs()
+    INFO ... raised CannotCopy: iceweasel 1.0 in hoary
     (same version already has published binaries in the destination archive)
-    pmount 0.1-1 in hoary
+    INFO ... raised CannotCopy: pmount 0.1-1 in hoary
     (same version already has published binaries in the destination archive)
 
 James goes wild and decided to create a new team PPA for his sandbox
@@ -850,12 +895,15 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    There is 1 error.
-    The following sources cannot be copied:
-    pmount 0.1-1 in grumpy
-    (same version already building in the destination archive for Warty)
-    pmount 0.1-1 in hoary
-    (same version already building in the  destination archive for Warty)
+    Requested sync of 3 packages to PPA for James Blackwell Sandbox.
+    Please allow some time for these to be processed.
+    >>> run_copy_jobs()
+    DEBUG Packages copied to PPA for James Blackwell Sandbox:
+    DEBUG pmount 0.1-1 in warty
+    INFO ... raised CannotCopy: pmount 0.1-1 in grumpy
+    (same version already building in the destination archive for Warty)
+    INFO ... raised CannotCopy: pmount 0.1-1 in hoary
+    (same version already building in the destination archive for Warty)
 
 Due to the copy error, nothing was copied to the destination PPA, not
 even the 'warty' source, which was not denied.
@@ -901,10 +949,14 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    Packages copied to PPA for James Blackwell:
-    pmount 0.1-1 in hoary
-    pmount-bin 0.1-1 in hoary hppa
-    pmount-bin 0.1-1 in hoary i386
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
+    DEBUG Packages copied to PPA for James Blackwell:
+    DEBUG pmount 0.1-1 in hoary
+    DEBUG pmount-bin 0.1-1 in hoary hppa
+    DEBUG pmount-bin 0.1-1 in hoary i386
+    >>> jblack_browser.open(jblack_browser.url)
 
     >>> print_ppa_packages(jblack_browser.contents)
     Source          Published   Status     Series           Section  Build
@@ -983,10 +1035,13 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    Packages copied to PPA for James Blackwell:
-    foo 2.0 in hoary
-    foo-bin 2.0 in hoary hppa
-    foo-bin 2.0 in hoary i386
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
+    DEBUG Packages copied to PPA for James Blackwell:
+    DEBUG foo 2.0 in hoary
+    DEBUG foo-bin 2.0 in hoary hppa
+    DEBUG foo-bin 2.0 in hoary i386
 
 James tries to copy some of Celso's packages that are older than
 the ones in his own PPA. He is not allowed to copy these older
@@ -1014,9 +1069,10 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    There is 1 error.
-    The following source cannot be copied:
-    foo 1.1 in hoary
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
+    INFO ... raised CannotCopy: foo 1.1 in hoary
     (version older than the foo 2.0 in hoary published in hoary)
 
 However if he copies it to another suite is just works (tm) since PPAs
@@ -1032,10 +1088,13 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    Packages copied to PPA for James Blackwell:
-    foo 1.1 in warty
-    foo-bin 1.1 in warty hppa
-    foo-bin 1.1 in warty i386
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
+    DEBUG Packages copied to PPA for James Blackwell:
+    DEBUG foo 1.1 in warty
+    DEBUG foo-bin 1.1 in warty hppa
+    DEBUG foo-bin 1.1 in warty i386
 
     >>> jblack_browser.open(
     ...     'http://launchpad.dev/~jblack/+archive/ppa/+packages')
@@ -1073,9 +1132,10 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    There is 1 error.
-    The following source cannot be copied:
-    foo 1.1 in hoary
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
+    INFO ... raised CannotCopy: foo 1.1 in hoary
     (a different source with the same version is published in the
     destination archive)
 
@@ -1108,8 +1168,10 @@
     >>> messages = get_feedback_messages(jblack_browser.contents)
     >>> for msg in messages:
     ...     print msg
-    There is 1 error.
-    The following source cannot be copied:
+    Requested sync of 1 package to PPA for James Blackwell.
+    Please allow some time for this to be processed.
+    >>> run_copy_jobs()
+    INFO ... raised CannotCopy:
     foo 9.9 in hoary (source has no binaries to be copied)
 
 No game, no matter what he tries, James can't break PPAs.