Merge lp:~spiv/bzr/finishLogFile-robustness-531746 into lp:bzr

[Andrew Bennetts]

This branch simply brute-forces away the traceback I reported in bug 531746.

I checked the C code for file.close, and I've verified by inspection that
 * IOError with .errno==None from file.close only occurs for the 'concurrent operation' error, and
 * it is safe to retry in this case, as no state relating to the file has been mutated.

Ideally perhaps we'd track down every single stray thread and make sure they are stopped before this point, but that's a rather daunting task.

(We may need to do some of that anyway soon, to track down and fix the thread leaks that cause 'cannot start new thread' errors, but we can at least squash this problem.)

[Vincent Ladeuil (vila)]

BB:tweak

I agree with the fix, but make it verbose, please, so we at least get
some indication that *something* occurred.

We'll probably want to get rid of that code in the future so a comment
mentioning the bug (or this merge proposal) will help get back the context
at that point.

review: Needs Fixing

[Vincent Ladeuil (vila)]

(Using review needsfixing, status approved to emulate BB:tweak).

=== modified file 'NEWS'
--- NEWS	2010-03-07 03:04:12 +0000
+++ NEWS	2010-03-10 06:05:37 +0000
@@ -168,6 +168,13 @@
 * Stop sending apport crash files to ``.cache`` in the directory from
   which ``bzr selftest`` was run.  (Martin Pool, #422350)
 
+* Tests no longer fail if "close() called during concurrent
+  operation on the same file object" occurs when closing the log file
+  (which can happen if a thread tries to write to the log file at the
+  wrong moment).  An warning will be written to ``stderr`` when this
+  happens, and another warning will be written if the log file could not
+  be closed after retrying 100 times.  (Andrew Bennetts, #531746)
+
 bzr 2.1.1
 #########
 

=== modified file 'bzrlib/tests/__init__.py'
--- bzrlib/tests/__init__.py	2010-02-18 02:15:48 +0000
+++ bzrlib/tests/__init__.py	2010-03-10 06:05:37 +0000
@@ -1671,7 +1671,33 @@
                 unicodestr = log_contents.decode('utf8', 'replace')
                 log_contents = unicodestr.encode('utf8')
             if not keep_log_file:
-                self._log_file.close()
+                close_attempts = 0
+                max_close_attempts = 100
+                first_close_error = None
+                while close_attempts < max_close_attempts:
+                    close_attempts += 1
+                    try:
+                        self._log_file.close()
+                    except IOError, ioe:
+                        if ioe.errno is None:
+                            # No errno implies 'close() called during
+                            # concurrent operation on the same file object', so
+                            # retry.  Probably a thread is trying to write to
+                            # the log file.
+                            if first_close_error is None:
+                                first_close_error = ioe
+                            continue
+                        raise
+                    else:
+                        break
+                if close_attempts > 1:
+                    sys.stderr.write(
+                        'Unable to close log file on first attempt, '
+                        'will retry: %s\n' % (first_close_error,))
+                    if close_attempts == max_close_attempts:
+                        sys.stderr.write(
+                            'Unable to close log file after %d attempts.\n'
+                            % (max_close_attempts,))
                 self._log_file = None
                 # Permit multiple calls to get_log until we clean it up in
                 # finishLogFile