After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 698305 - cache-test refcounting test fails sporadically
cache-test refcounting test fails sporadically
Status: RESOLVED FIXED
Product: libsoup
Classification: Core
Component: Misc
unspecified
Other Linux
: Normal normal
: ---
Assigned To: libsoup-maint@gnome.bugs
libsoup-maint@gnome.bugs
Depends on:
Blocks:
 
 
Reported: 2013-04-18 14:30 UTC by Dan Winship
Modified: 2013-08-23 17:36 UTC
See Also:
GNOME target: ---
GNOME version: ---



Description Dan Winship 2013-04-18 14:30:23 UTC
If you run cache-test repeatedly, it will eventually fail with:

  ...
  Cache refcounting tests
   Checking that the base stream is properly unref'ed
  leaked GInputStream!
Comment 1 Martin Pitt 2013-05-15 11:09:40 UTC
This seems to happen quite a lot on slow architectures (we have regular build failures in Debian/Ubuntu due to this). I have a really hard time reproducing this on my fast desktop machine (takes 150 repetitions and more), and in 300 iterations I hit it just once on my nexus 7 (arm). OTOH it is quite easy to reproduce on Debian's mips porter box, only takes two or three tries.

However, at first sight this doesn't look timing related. None of this happens asynchronously, does it? GWeakNotifys are called synchronously, unreffing happens synchronously, and the test doesn't even have a GMainLoop. Are you aware of anything async in the test or libsoup which could perhaps grab a second ref to stream?

Could this be a race condition with memory allocation/alignment? I tried to declare the base_stream pointer as "volatile", but that didn't help.
Comment 2 Martin Pitt 2013-05-15 11:16:45 UTC
(In reply to comment #1)

> Are you aware of anything async in the test or libsoup which could perhaps
> grab a second ref to stream?

I tested that theory, that's not it. G_IS_OBJECT(stream) is true right before g_object_unref (stream) and false afterwards, so that _unref call indeed was the last instance.
Comment 3 Martin Pitt 2013-05-15 11:55:24 UTC
stepping through with gdb shows that the soup threads end at different times here. In the working case, one gets

------------ 8< --------------
604             stream = soup_test_request_send (SOUP_REQUEST (req), NULL, flags, &error);
(gdb)
[New Thread 0x2c687450 (LWP 7413)]
605             if (!stream) {
(gdb)
613             base_stream = g_filter_input_stream_get_base_stream (G_FILTER_INPUT_STREAM (stream));
(gdb)
614             g_object_add_weak_pointer (G_OBJECT (base_stream), (gpointer *)&base_stream);
(gdb)
616             g_clear_object (&req);
(gdb) p base_stream
$1 = (GInputStream *) 0x557a80
(gdb) p stream
$2 = (GInputStream *) 0x613f20
(gdb) n
617             debug_printf (1, "before unref: is object: %i, base stream: %p\n", G_IS_OBJECT(stream), base_stream);
(gdb) n
[Thread 0x2c687450 (LWP 7413) exited]
before unref: is object: 1, base stream: 0x557a80
618             g_object_unref (stream);
(gdb) n
619             debug_printf (1, "after unref: is object: %i, base stream: %p\n", G_IS_OBJECT(stream), base_stream);
(gdb) n
after unref: is object: 0, base stream: (nil)
621             debug_printf (1, " Checking that the base stream is properly unref'ed\n");
------------ 8< --------------

i. e. the thread ends before the g_object_unref(), then base_stream gets NULLed properly.

But in the failing case we get:

------------ 8< --------------
613             base_stream = g_filter_input_stream_get_base_stream (G_FILTER_INPUT_STREAM (stream));
(gdb) n
614             g_object_add_weak_pointer (G_OBJECT (base_stream), (gpointer *)&base_stream);
(gdb) n
616             g_clear_object (&req);
(gdb) n
617             debug_printf (1, "before unref: is object: %i, base stream: %p\n", G_IS_OBJECT(stream), base_stream);
(gdb) n
before unref: is object: 1, base stream: 0x48b680
618             g_object_unref (stream);
(gdb) 
619             debug_printf (1, "after unref: is object: %i, base stream: %p\n", G_IS_OBJECT(stream), base_stream); 
(gdb) 
after unref: is object: 0, base stream: 0x48b680
621             debug_printf (1, " Checking that the base stream is properly unref'ed\n");
(gdb) p base_stream
$3 = (GInputStream *) 0x48b680
(gdb) n
 Checking that the base stream is properly unref'ed
[Thread 0x2c687450 (LWP 8102) exited]
622             if (base_stream) {
------------ 8< --------------

I. e. the soup thread ends after the _unref().

g_object_add_weak_pointer()'s documentation says

  Note that as with g_object_weak_ref(), the weak references created by this method are not thread-safe: they cannot safely be used in one thread if the object's last g_object_unref() might happen in another thread. Use GWeakRef if thread-safety is required.

Now, it doesn't look like the unref would happen in another thread, but maybe that other thread still has some references?
Comment 4 Dan Winship 2013-05-17 11:03:37 UTC
> Now, it doesn't look like the unref would happen in another thread, but maybe
> that other thread still has some references?

Yeah, seems like this is probably somehow related to the cancel_request_thread() created by soup_test_request_send(), but I tried a few obvious-looking fixes (notably changing the g_thread_unref() to g_thread_join()) and they didn't fix it...
Comment 5 Dan Winship 2013-08-23 17:36:00 UTC
OK, I changed the test to wait for the stream to be destroyed, rather
than asserting that it already has been.