test_close_open_print_buffered(test_file) sometimes crashes

[ocean-city]

BPO	9295
Nosy	@pitrou, @florentx
Files	py26_debug_threaded_close.patch: patch to see what's happening py26_experimental_patch_on_fileobject.patch: Patch to workaround the crash py27_fix_threaded_file_close.patch: final proposal

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2010-10-28.16:13:16.074>
created_at = <Date 2010-07-18.14:59:34.504>
labels = ['interpreter-core', 'OS-windows', 'type-crash']
title = 'test_close_open_print_buffered(test_file) sometimes crashes'
updated_at = <Date 2010-10-28.16:13:16.073>
user = 'https://bugs.python.org/ocean-city'

bugs.python.org fields:

activity = <Date 2010-10-28.16:13:16.073>
actor = 'pitrou'
assignee = 'none'
closed = True
closed_date = <Date 2010-10-28.16:13:16.074>
closer = 'pitrou'
components = ['Interpreter Core', 'Windows']
creation = <Date 2010-07-18.14:59:34.504>
creator = 'ocean-city'
dependencies = []
files = ['18050', '18052', '18826']
hgrepos = []
issue_num = 9295
keywords = ['patch', 'buildbot']
message_count = 18.0
messages = ['110652', '110655', '110656', '110659', '110666', '110667', '110669', '110670', '110671', '110672', '110705', '113536', '113537', '113551', '113961', '116005', '119792', '119799']
nosy_count = 3.0
nosy_names = ['pitrou', 'ocean-city', 'flox']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'crash'
url = 'https://bugs.python.org/issue9295'
versions = ['Python 2.7']

[ocean-city]

I noticed test_close_open_print_buffered(test_file) sometimes crashes on release26-maint branch. This is most problamatic part in my python2.6 test survey on VC6 + Win2K.

Here is stacktrace.

_write_lk(int 6, const void * 0x00b49240, unsigned int 11) line 155 + 3 bytes
_write(int 6, const void * 0x00b49240, unsigned int 11) line 79 + 17 bytes
_flush(_iobuf * 0x102618e8) line 162 + 23 bytes
_fclose_lk(_iobuf * 0x102618e8) line 130 + 9 bytes
fclose(_iobuf * 0x102618e8) line 67 + 9 bytes
close_the_file(PyFileObject * 0x00a9e6b8) line 370 + 7 bytes
file_close(PyFileObject * 0x00a9e6b8) line 570 + 9 bytes
call_function(_object * * * 0x00fdf350, int 11134648) line 3734 + 204 bytes
PyEval_EvalFrameEx(_frame * 0x00b33d50, int 131) line 2414
(snip)

Python crashes when MSVCRT touches internal buffer of file object via flush() in close().

I think this is multi-threading bug related to internal buffer of file object. I'll post more.

[ocean-city]

I saw value of local variable *thread* was 5384 and internal buffer's
address was 0x102618c8 (sorry, this is another stacktrace which differs
from previous one)

thread(5384) func(file_close): enter....
thread(5384) func(close_the_file): enter....
thread(5384) func(close_the_file): file(00A1FB18) address(00B18FD0): local_close enter...
thread(5376) func(file_close): enter....
thread(5376) func(close_the_file): enter....
thread(5376) func(close_the_file): leave....
thread(5376) func(file_close): file(00A1FB18) address(00B18FD0): PyMem_Free
thread(5376) func(file_close): leave....

Thread 5384 entered close_the_file() and ran local_close() and allowed
another thread to run. Before this, fp->f_fp was set to NULL. Thread 5376
entered close_the_file() and see fp->f_fp is NULL, and returned immediately
and freed fp->f_setbuf. Interesting point is, thread 5384 was still running
close(2), so flush(2) called by this function touched this buffer and crashed.

[ocean-city]

I created a patch to workaround this crash. But I saw another problamatic phenomenon "Error without exception set".

I confirmed PyErr_Occurred() returns TRUE when leaving file_close() on error, but I gave up.

test_close_open_print_buffered (__main__.FileThreadingTests) ... close failed in
 file object destructor:
IOError: [Errno 0] Error
Exception in thread Thread-1:
Traceback (most recent call last):
  File "e:\python-dev\release26-maint\lib\threading.py", line 532, in __bootstra
p_inner
    self.run()
  File "e:\python-dev\release26-maint\lib\threading.py", line 484, in run
    self.__target(*self.__args, **self.__kwargs)
  File "test_custom.py", line 94, in worker
    f()
  File "test_custom.py", line 88, in <lambda>
    lambda: self._close_and_reopen_file(),
  File "test_custom.py", line 54, in _close_and_reopen_file
    self._close_file()
  File "test_custom.py", line 49, in _close_file
    self.f.close()
SystemError: error return without exception set

Qclose failed in file object destructor:

IOError: [Errno 0] Error
Exception in thread Thread-4:
Traceback (most recent call last):
  File "e:\python-dev\release26-maint\lib\threading.py", line 532, in __bootstra
p_inner
    self.run()
  File "e:\python-dev\release26-maint\lib\threading.py", line 484, in run
    self.__target(*self.__args, **self.__kwargs)
  File "test_custom.py", line 94, in worker
    f()
  File "test_custom.py", line 88, in <lambda>
    lambda: self._close_and_reopen_file(),
  File "test_custom.py", line 54, in _close_and_reopen_file
    self._close_file()
  File "test_custom.py", line 49, in _close_file
    self.f.close()
SystemError: error return without exception set

4271 88.3166 ok

----------------------------------------------------------------------
Ran 1 test in 6.579s

OK

[pitrou]

The proposed resolution is wrong. As the comment says, there is a specific reason why f->fp is NULLed at this point.

It appears that maybe MSVCRT is not entirely thread-safe with respect to buffered file I/O. Perhaps the test can simply be disabled under Windows. Is test_close_open_print_buffered the only test that fails?

[ocean-city]

Maybe I am wrong, but when another thread calls File.close(), there is no system call on the code path, so I think still crash can happen nevertheless system call is thread safe.

[pitrou]

Maybe I am wrong, but when another thread calls File.close(), there is
no system call on the code path,

There is, and that's precisely what's the various tests test for.
(closing a file from a thread while it's being used from another thread)

[ocean-city]

Hmm, correct me if following understanding is wrong somewhere...

1. File.close() is actually file_close(), and is calling close_the_file().
2. Returns immediately because local_fp == f->f_fp is already NULL.
   The return value is None.
3. sts is non-NULL, so PyMem_Free(f->f_setbuf) happens.
4. There is no system call for FILE object, so thread won't wait for close(2) completion.

Maybe can we fix this issue by the patch like this? I moved PyMem_Free
into close_the_file(), and called it only when close operation
succeeded.

Index: Objects/fileobject.c
===================================================================

--- Objects/fileobject.c	(revision 82910)
+++ Objects/fileobject.c	(working copy)
@@ -371,9 +371,14 @@
             Py_END_ALLOW_THREADS
             if (sts == EOF)
                 return PyErr_SetFromErrno(PyExc_IOError);
-            if (sts != 0)
+            if (sts != 0) {
+                PyMem_Free(f->f_setbuf);
+                f->f_setbuf = NULL;
                 return PyInt_FromLong((long)sts);
+            }
         }
+        PyMem_Free(f->f_setbuf);
+        f->f_setbuf = NULL;
     }
     Py_RETURN_NONE;
 }
@@ -567,12 +572,7 @@
 static PyObject *
 file_close(PyFileObject *f)
 {
-    PyObject *sts = close_the_file(f);
-    if (sts) {
-        PyMem_Free(f->f_setbuf);
-        f->f_setbuf = NULL;
-    }
-    return sts;
+    return close_the_file(f);
 }

[ocean-city]

I forgot to mention that I didn't see any "Error without exception set" by my last patch. I agree f->f_fp = NULL; is needed there. ;-)

[pitrou]

Hmm, correct me if following understanding is wrong somewhere...

1. File.close() is actually file_close(), and is calling close_the_file().
2. Returns immediately because local_fp == f->f_fp is already NULL.
   The return value is None.

I don't understand why you say that. Why is f->f_fp already NULL while
close() still hasn't been called?

By the way, is it 2.6-specific or does it also happen on 2.7?

[pitrou]

Does the following patch solve your issue?

Index: Python/ceval.c
===================================================================

--- Python/ceval.c	(révision 82959)
+++ Python/ceval.c	(copie de travail)
@@ -1763,6 +1763,8 @@
                If __getattr__ raises an exception, w will
                be freed, so we need to prevent that temporarily. */
             Py_XINCREF(w);
+            if (PyFile_Check(w))
+                PyFile_IncUseCount((PyFileObject *) w);
             if (w != NULL && PyFile_SoftSpace(w, 0))
                 err = PyFile_WriteString(" ", w);
             if (err == 0)
@@ -1790,6 +1792,8 @@
                 else
                     PyFile_SoftSpace(w, 1);
             }
+            if (PyFile_Check(w))
+                PyFile_DecUseCount((PyFileObject *) w);
             Py_XDECREF(w);
             Py_DECREF(v);
             Py_XDECREF(stream);

[ocean-city]

Does the following patch solve your issue?

I tried, but it still crashed. I could reproduce the crash by following
script. It crashed also on Python2.7, but it doesn't crash on Python3.
And when I used io.open() instead of builtin open(), it doesn't crash
even on Python2.x. (Probably because io.open implements buffer protocol
by itself)

//////////////////////////////////////////////////////

import threading
import sys

if sys.version_info.major == 3:
    xrange = range

def main():
    size = 1024 * 1024 # large enough
    f = open("__temp__.tmp", "w", size)
    for _ in xrange(size):
        f.write("c")
    t1 = threading.Thread(target=f.close)
    t2 = threading.Thread(target=f.close)
    t1.start()
    t2.start()
    t1.join()
    t2.join()

if __name__ == '__main__':
    main()

//////////////////////////////////////////////////////

I lied a bit on msg110655. close(2) is not used, that is actually
fclose(). I didn't notice the variable *close* was declared as
the parameter of fill_file_fields().

[ocean-city]

I cannot crash python by above patch anymore... Strange.

Is test_close_open_print_buffered the only test that fails?

It seem to be.

Is freeing the memory allocated for setvbuf() while close() running in another thread really safe?

[ocean-city]

• above patch
  + above script