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

Proposed by Andrew Bennetts on 2010-03-05
Status: Merged
Approved by: Vincent Ladeuil on 2010-03-05
Approved revision: 5075
Merged at revision: not available
Proposed branch: lp:~spiv/bzr/finishLogFile-robustness-531746
Merge into: lp:bzr
Diff against target: 56 lines (+34/-1)
2 files modified
NEWS (+7/-0)
bzrlib/tests/__init__.py (+27/-1)
To merge this branch: bzr merge lp:~spiv/bzr/finishLogFile-robustness-531746
Reviewer Review Type Date Requested Status
Vincent Ladeuil 2010-03-05 Needs Fixing on 2010-03-05
Review via email: mp+20722@code.launchpad.net

Description of the change

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.)

To post a comment you must log in.
Vincent Ladeuil (vila) wrote :

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) wrote :

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

5076. By Andrew Bennetts on 2010-03-10

Write warnings to stderr if self._log_file.close fails, and add NEWS entry.

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'NEWS'
2--- NEWS 2010-03-07 03:04:12 +0000
3+++ NEWS 2010-03-10 06:05:37 +0000
4@@ -168,6 +168,13 @@
5 * Stop sending apport crash files to ``.cache`` in the directory from
6 which ``bzr selftest`` was run. (Martin Pool, #422350)
7
8+* Tests no longer fail if "close() called during concurrent
9+ operation on the same file object" occurs when closing the log file
10+ (which can happen if a thread tries to write to the log file at the
11+ wrong moment). An warning will be written to ``stderr`` when this
12+ happens, and another warning will be written if the log file could not
13+ be closed after retrying 100 times. (Andrew Bennetts, #531746)
14+
15 bzr 2.1.1
16 #########
17
18
19=== modified file 'bzrlib/tests/__init__.py'
20--- bzrlib/tests/__init__.py 2010-02-18 02:15:48 +0000
21+++ bzrlib/tests/__init__.py 2010-03-10 06:05:37 +0000
22@@ -1671,7 +1671,33 @@
23 unicodestr = log_contents.decode('utf8', 'replace')
24 log_contents = unicodestr.encode('utf8')
25 if not keep_log_file:
26- self._log_file.close()
27+ close_attempts = 0
28+ max_close_attempts = 100
29+ first_close_error = None
30+ while close_attempts < max_close_attempts:
31+ close_attempts += 1
32+ try:
33+ self._log_file.close()
34+ except IOError, ioe:
35+ if ioe.errno is None:
36+ # No errno implies 'close() called during
37+ # concurrent operation on the same file object', so
38+ # retry. Probably a thread is trying to write to
39+ # the log file.
40+ if first_close_error is None:
41+ first_close_error = ioe
42+ continue
43+ raise
44+ else:
45+ break
46+ if close_attempts > 1:
47+ sys.stderr.write(
48+ 'Unable to close log file on first attempt, '
49+ 'will retry: %s\n' % (first_close_error,))
50+ if close_attempts == max_close_attempts:
51+ sys.stderr.write(
52+ 'Unable to close log file after %d attempts.\n'
53+ % (max_close_attempts,))
54 self._log_file = None
55 # Permit multiple calls to get_log until we clean it up in
56 # finishLogFile