Merge lp:~jtv/launchpad/bug-427278 into lp:launchpad

[Jeroen T. Vermeulen]

Avoid long idle-in-transaction periods in translations-to-branch export.

[Jeroen T. Vermeulen (jtv)]

= Bug 427278 =

Second attempt; previously accidentally proposed for merging into db-devel (the default) which polluted the diff with whatever skew there happened to be between devel and db-devel.

Translations exports to bzr branches can sometimes keep transactions open for a while. There's no particular reason to go that far, and it's Not Nice. We've had the script idle-killed a few times.

We've done several things that prevented a repetition:

1. We no longer export all translations for a template; now we only do ones that have changed since the last export. Makes the exports a lot faster.

2. The deadline for long transactions was extended, and obviously that's pretty effective at stopping the alarm bells from ringing. But ideal it is not.

3. The branch you see here makes the script commit more often around the likely pain points.

There's really only one catch: DirectBranchCommit checks the branch for conflicting changes. For that it needs to compare the latest revision in the branch to the last_scanned_id as stored in the database when the DirectBranchCommit was constructed. So instead of getting the last_scanned_id at the point where it's referenced, DirectBranchCommit will now retrieve and store it at construction time. This should also close off a race condition that may or may not exist in the case where database transactions are committed while a DirectBranchCommit is active.

Passing a transaction into DirectBranchCommit.commit, as I do here, is a bit weird. There are reasons for it:

 * Operations that access branch storage can take a long time, but don't need database access. That makes them excellent points to close off any ongoing transaction. The framework starts new transactions on demand, and that's going to happen only after the bzr operation completes. Until that time, the committer avoids being "idle in transaction" on the database.

 * Nowadays txn is global, so we could just "import transaction" and "transaction.commit()". But passing it as an object makes it easy to mock transactions in tests. Also, passing a boolean is slightly more error-prone. Named parameters are a big improvement--"dbc.commit(message, commit=True)"--but still relatively sensitive to mistakes.

 * Passing the transaction object to commit rather than the constructor makes it clear that you're not giving out a blanket license to commit. The DirectBranchCommit can commit only inside that one particular method call. Don't hide transaction boundaries in the program flow.

A lot of the actual diff went into nicer logging.

== Test, demo & Q/A ==

Test:
{{{
./bin/test -vv -t 'translations.*to.*branch' -t 'direct.*branch.*commit'
}}}

Create a branch on staging, and set it as the productseries branch and the translations export branch for some project. Enable translations and two-way bzr synchronization. Push a template to the branch.

Watch the project's import queue; wait for the template to be imported. Then translate a string in the template. Watch the revision log for the branch; an automatic translations commit should appear there within the hour.

No lint.

Jeroen

[Graham Binns (gmb)]

review: Approve (code)

=== modified file 'lib/lp/code/model/directbranchcommit.py'
--- lib/lp/code/model/directbranchcommit.py	2009-09-09 20:03:19 +0000
+++ lib/lp/code/model/directbranchcommit.py	2009-11-26 21:25:26 +0000
@@ -74,6 +74,8 @@
         self.db_branch = db_branch
         self.to_mirror = to_mirror
 
+        self.last_scanned_id = self.db_branch.last_scanned_id
+
         if committer is None:
             committer = db_branch.owner
         self.committer = committer
@@ -172,12 +174,18 @@
         assert self.is_locked, "Getting revision on un-locked branch."
         last_revision = None
         last_revision = self.bzrbranch.last_revision()
-        if last_revision != self.db_branch.last_scanned_id:
+        if last_revision != self.last_scanned_id:
             raise ConcurrentUpdateError(
                 "Branch has been changed.  Not committing.")
 
-    def commit(self, commit_message):
-        """Commit to branch."""
+    def commit(self, commit_message, txn=None):
+        """Commit to branch.
+
+        :param commit_message: Message for branch's commit log.
+        :param txn: Transaction to commit.  Can be helpful in avoiding
+            long idle times in database transactions.  May be committed
+            more than once.
+        """
         assert self.is_open, "Committing closed DirectBranchCommit."
         assert self.is_locked, "Not locked at commit time."
 
@@ -185,6 +193,9 @@
         try:
             self._checkForRace()
 
+            if txn:
+                txn.commit()
+
             rev_id = self.revision_tree.get_revision_id()
             if rev_id == NULL_REVISION:
                 if list(self.transform_preview.iter_changes()) == []:
@@ -193,6 +204,9 @@
                 self.bzrbranch, commit_message)
             IMasterObject(self.db_branch).requestMirror()
 
+            if txn:
+                txn.commit()
+
         finally:
             self.unlock()
             self.is_open = False

=== modified file 'lib/lp/code/tests/test_directbranchcommit.py'
--- lib/lp/code/tests/test_directbranchcommit.py	2009-10-02 09:48:30 +0000
+++ lib/lp/code/tests/test_directbranchcommit.py	2009-11-26 21:25:26 +0000
@@ -37,7 +37,7 @@
 
         self.committer = DirectBranchCommit(self.db_branch)
         if update_last_scanned_id:
-            self.db_branch.last_scanned_id = (
+            self.committer.last_scanned_id = (
                 self.committer.bzrbranch.last_revision())
 
     def _tearDownCommitter(self):

=== modified file 'lib/lp/translations/doc/translations-export-to-branch.txt'
--- lib/lp/translations/doc/translations-export-to-branch.txt	2009-10-20 06:03:46 +0000
+++ lib/lp/translations/doc/translations-export-to-branch.txt	2009-11-26 21:25:26 +0000
@@ -45,7 +45,7 @@
     ...         if self.simulate_race:
     ...             raise ConcurrentUpdateError("Simulated race condition.")
     ...
-    ...     def commit(self, message=None):
+    ...     def commit(self, message=None, txn=None):
     ...         self._checkForRace()
     ...         self.logger.info("Committed %d file(s)." % self.written_files)
     ...
@@ -129,11 +129,11 @@
 
     >>> transaction.commit()
     >>> script = MockExportTranslationsToBranch(
-    ...     'export-to-branch', test_args=['-vv'])
+    ...     'export-to-branch', test_args=[])
     >>> script.main()
     INFO Exporting to translations branches.
     INFO Exporting Gazblachko trunk series.
-    DEBUG No previous translations commit found.
+    DEBUG ...
     INFO Writing file 'po/main/nl.po':
     INFO # ...
     msgid ""
@@ -143,6 +143,7 @@
     msgid "maingazpot msgid"
     msgstr "maingazpot msgstr"
     <BLANKLINE>
+    DEBUG ...
     INFO Writing file 'po/module/nl.po':
     INFO # ...
     msgid ""
@@ -152,6 +153,8 @@
     <BLANKLINE>
     msgid "gazmod msgid"
     msgstr "gazmod msgstr"
+    <BLANKLINE>
+    DEBUG ...
     INFO Committed 2 file(s).
     INFO Unlock.
     INFO Processed 1 item(s); 0 failure(s).
@@ -186,6 +189,7 @@
     >>> script.main()
     INFO Exporting to translations branches.
     INFO Exporting Gazblachko trunk series.
+    DEBUG ....
     DEBUG Last commit was at ....
     INFO Unlock.
     INFO Processed 1 item(s); 0 failure(s).
@@ -197,6 +201,7 @@
     >>> script.main()
     INFO Exporting to translations branches.
     INFO Exporting Gazblachko trunk series.
+    DEBUG ....
     DEBUG Last commit was at ...
     INFO Writing file 'po/main/nl.po':
     INFO ...
@@ -228,11 +233,14 @@
     >>> script.main()
     INFO Exporting to translations branches.
     INFO Exporting Gazblachko trunk series.
+    DEBUG ....
     DEBUG No previous translations commit found.
+    DEBUG ....
     INFO Writing file 'po/main/nl.po':
     ...
     msgstr "gazmod msgstr"
     <BLANKLINE>
+    DEBUG ...
     INFO Unlock.
     ERROR Failure: Simulated race condition.
     INFO Processed 1 item(s); 1 failure(s).

=== modified file 'lib/lp/translations/scripts/translations_to_branch.py'
--- lib/lp/translations/scripts/translations_to_branch.py	2009-10-20 06:03:46 +0000
+++ lib/lp/translations/scripts/translations_to_branch.py	2009-11-26 21:25:26 +0000
@@ -119,7 +119,7 @@
     def _commit(self, source, committer):
         """Commit changes to branch.  Check for race conditions."""
         self._checkForObjections(source)
-        committer.commit(self.commit_message)
+        committer.commit(self.commit_message, txn=self.txn)
 
     def _isTranslationsCommit(self, revision):
         """Is `revision` an automatic translations commit?"""
@@ -159,6 +159,9 @@
         self._checkForObjections(source)
 
         committer = self._prepareBranchCommit(source.translations_branch)
+        self.logger.debug("Created DirectBranchCommit.")
+        if self.txn:
+            self.txn.commit()
 
         bzr_branch = committer.bzrbranch
 
@@ -185,15 +188,17 @@
                 base_path = os.path.dirname(template.path)
 
                 for pofile in template.pofiles:
-
                     has_changed = (
                         changed_since is None or
                         pofile.date_changed > changed_since)
                     if not has_changed:
                         continue
 
+                    language_code = pofile.getFullLanguageCode()
+                    self.logger.debug("Exporting %s." % language_code)
+
                     pofile_path = os.path.join(
-                        base_path, pofile.getFullLanguageCode() + '.po')
+                        base_path, language_code + '.po')
                     pofile_contents = pofile.export()
 
                     committer.writeFile(pofile_path, pofile_contents)
@@ -210,6 +215,7 @@
                     template.clearPOFileCache()
 
             if change_count > 0:
+                self.logger.debug("Writing to branch.")
                 self._commit(source, committer)
         finally:
             committer.unlock()
@@ -231,13 +237,14 @@
                 raise
             except Exception, e:
                 items_failed += 1
-                self.logger.error("Failure: %s" % e)
+                message = unicode(e)
+                if message == u'':
+                    message = e.__class__.__name__
+                self.logger.error("Failure: %s" % message)
                 if self.txn:
                     self.txn.abort()
 
             items_done += 1
-            if self.txn:
-                self.txn.begin()
 
         self.logger.info("Processed %d item(s); %d failure(s)." % (
             items_done, items_failed))

=== modified file 'lib/lp/translations/utilities/gettext_po_exporter.py'
--- lib/lp/translations/utilities/gettext_po_exporter.py	2009-11-02 00:10:05 +0000
+++ lib/lp/translations/utilities/gettext_po_exporter.py	2009-11-26 21:25:26 +0000
@@ -14,6 +14,7 @@
     'GettextPOExporter',
     ]
 
+import logging
 import os
 
 from zope.interface import implements
@@ -344,8 +345,20 @@
                         raise UnicodeEncodeError(
                             '%s:\n%s' % (file_path, str(error)))
 
-                    # This message cannot be represented in current encoding,
-                    # change to UTF-8 and try again.
+                    # This message cannot be represented in the current
+                    # encoding.
+                    if translation_file.path:
+                        file_description = translation_file.path
+                    elif translation_file.language_code:
+                        file_description = (
+                            "%s translation" % translation_file.language_code)
+                    else:
+                        file_description = "template"
+                    logging.info(
+                        "Can't represent %s as %s; using UTF-8 instead." % (
+                            file_description,
+                            translation_file.header.charset.upper()))
+
                     old_charset = translation_file.header.charset
                     translation_file.header.charset = 'UTF-8'
                     # We need to update the header too.