[Log4cplus-devel] [ log4cplus-Bugs-3563699 ] Assertion fails when boost thread terminates on Linux

[SourceForge.net <no...@so...>]

Bugs item #3563699, was opened at 2012-08-31 04:55
Message generated for change (Settings changed) made by wilx
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=429073&aid=3563699&group_id=40830

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: None
Group: v1.1.x
>Status: Closed
Resolution: Fixed
Priority: 6
Private: No
Submitted By: gorpknalp (gorpknalp)
Assigned to: Václav Zeman (wilx)
Summary: Assertion fails when boost thread terminates on Linux

Initial Comment:
When a boost thread uses a logger, and then terminates (under normal conditions), an assertion fails. This problem does not happen on Windows 7, only on my Raspberry Pi.

Using:
- log4cplus 1.1.0-rc8
- CMake build type debug with CMAKE_CXX_FLAGS="-std=c++0x"
- OS: Raspbian (derived from Debian ARM)

Client application using:
- shared library
- without wchar_t
- Boost 1.49

Error message:
cachip: /home/pi/prog/log4cplus-1.1.0-rc8/src/global-init.cxx:296: void log4cplus::ptd_cleanup_func(void*): Assertion `arg == reinterpret_cast<void *>(1) || arg == internal::get_ptd ()' failed.

Stack trace:
#0  0x402d9bfc in raise () from /lib/arm-linux-gnueabihf/libc.so.6
#1  0x402dd97c in abort () from /lib/arm-linux-gnueabihf/libc.so.6
#2  0x00022a08 in ?? ()
#3  0x00022a08 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)


----------------------------------------------------------------------

Comment By: gorpknalp (gorpknalp)
Date: 2012-09-03 16:16

Message:
Yes, that new version solves the problem on the different Linux distros I'm
trying it on.

----------------------------------------------------------------------

Comment By: Václav Zeman (wilx)
Date: 2012-09-03 10:23

Message:
I have committed the patch to trunk.

----------------------------------------------------------------------

Comment By: Václav Zeman (wilx)
Date: 2012-09-03 07:57

Message:
Good detective work. I have been able to reproduce the problem and I think
that the additional patch (attached) does fix the whole issue. Though I
will retest on few more systems than Cygwin later today to make sure.
Please test it as well.

----------------------------------------------------------------------

Comment By: gorpknalp (gorpknalp)
Date: 2012-09-03 03:34

Message:
I lost my previous comment because fucking sourceforge logged me out while
I was writing it, so I'm sorry if this one is not very clear.

Please note that I can reproduce that bug on Ubuntu 12.04 too.

This patch does not fix the bug. However after some debugging session I
think I figured out the source:

http://linux.die.net/man/3/pthread_getspecific :
"Both pthread_getspecific() and pthread_setspecific() may be called from a
thread-specific data destructor function. A call to pthread_getspecific()
for the thread-specific data key being destroyed shall return the value
NULL"

This is consistent with what I'm seeing while debugging, which is:
- arg has the correct memory address
- tls_storage_key has the correct memory address
- tls_storage_key points to the value
- pthread_getspecific() returns 0 when given the correct tls_storage_key as
argument

So I think the second predicate of the assert() is not correct.

But I was wondering why it does not seem to happen often so I tried to dig
a bit in the code, and my best guess is that for some reason, most people
will end up with the first version of alloc_ptd() with the "special hack"
which makes the first predicate of the assert() return true. Moreover,
threadCleanup() doesn't fail because "delete ptd;" is deleting a null
pointer.

There's a strange line in ptd_cleanup_func(), "(void) arg;" does not seem
to do anything to me and I really wonder what it's doing there. Also, I
noticed that in threadCleanup() the last line is a call to
"internal::set_ptd (0);" and after that ptd_cleanup_func() will call
"thread::impl::tls_set_value (internal::tls_storage_key, 0));" so it seems
that the value of the key is set to 0 twice.

All of this in order to say that the thread cleanup code probably needs a
bit of cleanup too :)

----------------------------------------------------------------------

Comment By: Václav Zeman (wilx)
Date: 2012-08-31 05:33

Message:
This looks similar to the bug reported here:
https://sourceforge.net/tracker/?func=detail&aid=3467112&group_id=40830&atid=429075

I will apply the following change (later today, also attached). Please test
if it fixes your crash.

=== modified file 'src/global-init.cxx'
--- src/global-init.cxx	2012-08-29 18:59:41 +0000
+++ src/global-init.cxx	2012-08-31 12:16:36 +0000
@@ -293,7 +293,7 @@
     // Either it is a dummy value or it should be the per thread data
     // pointer we get from internal::get_ptd().
     assert (arg == reinterpret_cast<void *>(1)
-        || arg == internal::get_ptd ());
+        || arg == internal::get_ptd (false));
     (void)arg;
 
     threadCleanup ();


----------------------------------------------------------------------

Comment By: Václav Zeman (wilx)
Date: 2012-08-31 05:06

Message:
Never mind, I have missed that you have attached files to this report.

----------------------------------------------------------------------

Comment By: Václav Zeman (wilx)
Date: 2012-08-31 05:05

Message:
Thank you for the bug report. Is it easily reproducible? I have had
something similar reported before this one but I were not able to reproduce
it myself.

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=429073&aid=3563699&group_id=40830