Repository navigation
bug: Double Free On BufferedReader&FileIO? #4238
Description
Bug behavior
Added a is_drop field in PyInner. and found out both BufferedReader&FileIO gets double drop? Did some search on the code, no clue where misses a clone() to PyRef or PyObjectRef
Possible root of bug
a obscure memcpy on a struct containing a PyRef/PyObjectRef
Necessity of fixing the bug
Useful for writing garbage collecting, also prevent UB
Part of the log
the remaining of log file just basically repeats those lines. The command is just cargo run, and alright it did run, but with all those double drop:
log_buf.log
Details
[ERROR rustpython_vm::object::core] Double drop on PyRef, type="rustpython_vm::stdlib::io::_io::BufferedReader"
[ERROR rustpython_vm::object::core] Double drop on PyRef, type="rustpython_vm::stdlib::io::fileio::FileIO"
[ERROR rustpython_vm::object::core] Double drop on PyObjectRef, typeid=TypeId { t: 14576741135102236696 }, type=Some("rustpython_vm::stdlib::io::fileio::FileIO")
[ERROR rustpython_vm::object::core] Double drop on PyRef, type="rustpython_vm::stdlib::io::_io::BufferedReader"
backtrace= 0: <rustpython_vm::object::core::PyRef<T> as core::ops::drop::Drop>::drop
at vm/src/object/core.rs:979:17
1: core::ptr::drop_in_place<rustpython_vm::object::core::PyRef<rustpython_vm::stdlib::io::_io::BufferedReader>>
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/core/src/ptr/mod.rs:486:1
2: rustpython_vm::stdlib::io::_io::BufferedMixin::close
at vm/src/stdlib/io.rs:1575:9
3: core::ops::function::Fn::call
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/core/src/ops/function.rs:77:5
4: rustpython_vm::function::builtin::<impl rustpython_vm::function::builtin::sealed::PyNativeFuncInternal<(rustpython_vm::function::builtin::OwnedParam<T1>,),R,rustpython_vm::vm::VirtualMachine> for F>::call_
at vm/src/function/builtin.rs:79:17
5: <F as rustpython_vm::function::builtin::IntoPyNativeFunc<(T,R,VM)>>::call
at vm/src/function/builtin.rs:47:9
rustpython_vm::function::builtin::IntoPyNativeFunc::into_func::{{closure}}
at vm/src/function/builtin.rs:35:51
6: <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/alloc/src/boxed.rs:1886:9
7: <rustpython_vm::builtins::builtinfunc::PyBuiltinMethod as rustpython_vm::types::slot::Callable>::call
at vm/src/builtins/builtinfunc.rs:210:9
8: rustpython_vm::types::slot::Callable::slot_call
at vm/src/types/slot.rs:562:13
9: rustpython_vm::vm::vm_object::<impl rustpython_vm::vm::VirtualMachine>::_invoke
at vm/src/vm/vm_object.rs:176:30
10: rustpython_vm::vm::vm_object::<impl rustpython_vm::vm::VirtualMachine>::invoke
at vm/src/vm/vm_object.rs:189:9
rustpython_vm::vm::method::PyMethod::invoke
at vm/src/vm/method.rs:121:9
11: rustpython_vm::vm::vm_object::<impl rustpython_vm::vm::VirtualMachine>::call_method
at vm/src/vm/vm_object.rs:127:9
12: <rustpython_vm::stdlib::io::_io::_IOBase as rustpython_vm::types::slot::Destructor>::slot_del
at vm/src/stdlib/io.rs:541:21
13: rustpython_vm::object::core::PyObject::drop_slow_inner::call_slot_del::{{closure}}
at vm/src/object/core.rs:768:33
14: rustpython_vm::vm::thread::with_vm::{{closure}}
at vm/src/vm/thread.rs:38:14
15: std::thread::local::LocalKey<T>::try_with
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/std/src/thread/local.rs:445:16
16: std::thread::local::LocalKey<T>::with
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/std/src/thread/local.rs:421:9
17: rustpython_vm::vm::thread::with_vm
at vm/src/vm/thread.rs:27:5
18: rustpython_vm::object::core::PyObject::drop_slow_inner::call_slot_del
at vm/src/object/core.rs:766:23
19: rustpython_vm::object::core::PyObject::drop_slow_inner
at vm/src/object/core.rs:789:13
rustpython_vm::object::core::PyObject::drop_slow
at vm/src/object/core.rs:801:26
20: <rustpython_vm::object::core::PyObjectRef as core::ops::drop::Drop>::drop
at vm/src/object/core.rs:871:22
21: core::ptr::drop_in_place<rustpython_vm::object::core::PyObjectRef>
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/core/src/ptr/mod.rs:486:1
22: core::ptr::drop_in_place<core::option::Option<rustpython_vm::object::core::PyObjectRef>>
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/core/src/ptr/mod.rs:486:1
23: core::ptr::drop_in_place<[core::option::Option<rustpython_vm::object::core::PyObjectRef>]>
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/core/src/ptr/mod.rs:486:1
24: core::ptr::drop_in_place<alloc::boxed::Box<[core::option::Option<rustpython_vm::object::core::PyObjectRef>]>>
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/core/src/ptr/mod.rs:486:1
25: core::ptr::drop_in_place<core::cell::UnsafeCell<alloc::boxed::Box<[core::option::Option<rustpython_vm::object::core::PyObjectRef>]>>>
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/core/src/ptr/mod.rs:486:1
26: core::ptr::drop_in_place<lock_api::mutex::Mutex<parking_lot::raw_mutex::RawMutex,alloc::boxed::Box<[core::option::Option<rustpython_vm::object::core::PyObjectRef>]>>>
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/core/src/ptr/mod.rs:486:1
27: core::ptr::drop_in_place<rustpython_vm::frame::Frame>
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/core/src/ptr/mod.rs:486:1
28: core::ptr::drop_in_place<rustpython_vm::object::core::PyInner<rustpython_vm::frame::Frame>>
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/core/src/ptr/mod.rs:486:1
29: core::ptr::drop_in_place<alloc::boxed::Box<rustpython_vm::object::core::PyInner<rustpython_vm::frame::Frame>>>
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/core/src/ptr/mod.rs:486:1
30: core::mem::drop
at /rustc/e092d0b6b43f2de967af0887873151bb1c0b18d3/library/core/src/mem/mod.rs:974:24
31: rustpython_vm::object::core::drop_dealloc_obj
at vm/src/object/core.rs:89:5
32: rustpython_vm::object::core::PyObject::drop_slow
at vm/src/object/core.rs:807:9
Test Code
added is_drop field to PyInner<T> in core.rs
This is the git diff patch file(Also added a backtrace crate for debugging in this patch)
And here is core code to check double dropping:
Details
diff --git a/vm/src/object/core.rs b/vm/src/object/core.rs
index 19055df25..0eed91f4a 100644
--- a/vm/src/object/core.rs
+++ b/vm/src/object/core.rs
@@ -31,6 +31,7 @@ use std::{
any::TypeId,
borrow::Borrow,
cell::UnsafeCell,
+ collections::HashMap,
fmt,
marker::PhantomData,
mem::ManuallyDrop,
@@ -38,6 +39,11 @@ use std::{
ptr::{self, NonNull},
};
+use once_cell::sync::Lazy;
+
+pub static ID2TYPE: Lazy<PyMutex<HashMap<TypeId, String>>> =
+ Lazy::new(|| PyMutex::new(HashMap::new()));
+
// so, PyObjectRef is basically equivalent to `PyRc<PyInner<dyn PyObjectPayload>>`, except it's
// only one pointer in width rather than 2. We do that by manually creating a vtable, and putting
// a &'static reference to it inside the `PyRc` rather than adjacent to it, like trait objects do.
@@ -109,6 +115,7 @@ impl PyObjVTable {
#[repr(C)]
struct PyInner<T> {
ref_count: RefCount,
+ is_drop: PyMutex<bool>,
// TODO: move typeid into vtable once TypeId::of is const
typeid: TypeId,
vtable: &'static PyObjVTable,
@@ -433,6 +440,7 @@ impl<T: PyObjectPayload> PyInner<T> {
let member_count = typ.slots.member_count;
Box::new(PyInner {
ref_count: RefCount::new(),
+ is_drop: PyMutex::new(false),
typeid: TypeId::of::<T>(),
vtable: PyObjVTable::of::<T>(),
typ: PyAtomicRef::from(typ),
@@ -849,7 +857,15 @@ impl<'a, T: PyObjectPayload> From<&'a Py<T>> for &'a PyObject {
impl Drop for PyObjectRef {
#[inline]
fn drop(&mut self) {
+ if *self.0.is_drop.lock() {
+ error!(
+ "Double drop on PyObjectRef, typeid={:?}, type={:?}",
+ self.0.typeid,
+ ID2TYPE.lock().get(&self.0.typeid)
+ );
+ }
if self.0.ref_count.dec() {
+ *self.0.is_drop.lock() = true;
unsafe { PyObject::drop_slow(self.ptr) }
}
}
@@ -953,7 +969,21 @@ impl<T: PyObjectPayload> fmt::Debug for PyRef<T> {
impl<T: PyObjectPayload> Drop for PyRef<T> {
#[inline]
fn drop(&mut self) {
+ if *self.as_object().0.is_drop.lock() {
+ error!(
+ "Double drop on PyRef, type={:?}",
+ std::any::type_name::<T>()
+ );
+ }
+
+ let tid = TypeId::of::<T>();
+ ID2TYPE
+ .lock()
+ .entry(tid)
+ .or_insert_with(|| std::any::type_name::<T>().to_string());
+
if self.0.ref_count.dec() {
+ *self.0.is_drop.lock() = true;
unsafe { PyObject::drop_slow(self.ptr.cast::<PyObject>()) }
}
}
@@ -1136,6 +1166,7 @@ pub(crate) fn init_type_hierarchy() -> (PyTypeRef, PyTypeRef, PyTypeRef) {
let type_type_ptr = Box::into_raw(Box::new(partially_init!(
PyInner::<PyType> {
ref_count: RefCount::new(),
+ is_drop: PyMutex::new(false),
typeid: TypeId::of::<PyType>(),
vtable: PyObjVTable::of::<PyType>(),
dict: None,
@@ -1148,6 +1179,7 @@ pub(crate) fn init_type_hierarchy() -> (PyTypeRef, PyTypeRef, PyTypeRef) {
let object_type_ptr = Box::into_raw(Box::new(partially_init!(
PyInner::<PyType> {
ref_count: RefCount::new(),
+ is_drop: PyMutex::new(false),
typeid: TypeId::of::<PyType>(),
vtable: PyObjVTable::of::<PyType>(),
dict: None,
Activity
[-]Double Free On `BufferedReader`&`FileIO`?[/-][+]bug: Double Free On `BufferedReader`&`FileIO`?[/+]youknowone commentedon Oct 23, 2022
Double
__del__is legal by python spec, but double drop is not.Because you said it is done from frame's fastlocal, maybe it's related to this change? #3828
discord9 commentedon Oct 23, 2022
Added backtrace on every double drop, yes it seems mostly from fastlocals? This is the new log file:
log_buf.log
Edited: go through #3828 but still found it seems to be not relevant, I believe the bug trace back before #3828, because I found it in my gc branch even before #3828 is merged?(Into my gc branch I mean), I'm going to go back in commits and add this double drop check patch to find where it is?
Edited: found in #4242 this double drop bug still exist, havingn't check which commits introduce this bug, but it is always this two type
BufferedReader&FileIOthat's got double dropdiscord9 commentedon Oct 23, 2022
Do you think it is a good idea to add double drop checker in debug mode, if so, I might want to make a PR about that?
youknowone commentedon Oct 23, 2022
Sure, that will be helpful prevent it. I guess we can check similar bug with miri, but running miri is not easy as running debug mode.
cc @coolreader18
discord9 commentedon Oct 23, 2022
come up with #4242 (ah, double the answer to life, universe and everything that gets drop XD)
discord9 commentedon Oct 25, 2022
check.patch.txt
I apply this patch to the earliest commit that core.rs exist, and still found this bug, I think this trace back long way ago
youknowone commentedon Oct 26, 2022
io's classes differs from most of other rust-implemented types in RustPython because they use inheritance between rust-implemented types. maybe we made mistake somewhere around the point.
youknowone commentedon Oct 26, 2022
one thing to check? is it called from once as FileIO and another once as _RawIOBase?
discord9 commentedon Oct 27, 2022
From the backtrace of drop, I can see some is from
_IOBase::exitor_IOBase::flushsometime, this is the full log, with pointer logged too so one can distinguish different object, I log only the backtrace for every drop ofBufferedReaderbeing called:dbg.log
discord9 commentedon Oct 27, 2022
I do notice several copy_from_slice in io.rs I wonder if they might be the cause of this bug?
Edited: could be the problem of
PyBuffer, if it contains a PyObjectRef, and it gotscopy_from_slice, then the Ref Count could be off by onediscord9 commentedon Oct 27, 2022
It seems
RustPython/vm/src/stdlib/io.rs
Line 675 in 426f9f6
this line might cause missing ref count, if:
the struct being copied contains fields that's
PyObjectRef/PyRefthen the recorded ref count would be smaller than real ref count by one. This line was written two years ago, when our ref count system haven't being built, gonna experiment a little more with those lines to confirm if this guess is right?
@youknowone
Edited: to fix that, might need to
Traceevery PyObjectRef/PyRef a data type own, and call clone for them, thenManuallyDrop& forgot them?Edited1: still bugged on double drop
BufferedReadereven after manually clone and inc ref count for PyBufferEdited2: found out seems only
PyBytesuse thiscopy_from_sliceand it doesn't ownPyObjectRef/PyRefdiscord9 commentedon Oct 27, 2022
This is by no means my final solution, but I found if I elide a drop call in _IOBase then everything is going to be fine, no double drop or whatever (although I don't know whether there is leak in anywhere):
Edited: eliding
instance'drop() in_IOBase'sflushalso "works"youknowone commentedon Oct 27, 2022
Great! you discovered a deep side of the reason!
discord9 commentedon Oct 28, 2022
The first deref of a PyObjectRef/PyRef to a dropped object is from
_IOBase'sslot_delfunction, which, I assume, run _IOBase's__del__fn for BufferedReader? I think I might know what's wrong in here....Details
discord9 commentedon Oct 30, 2022
There is one extra call to
BufferedMixin'sclose()from Frame's fastlocal's drop, but still can't figure out why would the ref count be missingdiscord9 commentedon Nov 4, 2022
Turn out to be a false alarm, the bug is still in my gc code, so close this issue
youknowone commentedon Nov 5, 2022
Oh, thank you for confirming. I thought you watched it without gc. what's happened?
discord9 commentedon Nov 5, 2022
I set the is_drop flag too early,didn't realize drop might not happen if del resurrect a object, the actual drop might not happen...