[ace-bugs] ACE_Logging_Strategy core-dumps in memcpy due to assuming tellp() is thread safe

[Milan Cvetkovic]

ACE VERSION: 6.0.1
ACE VERSION: 6.1.5

HOST MACHINE and OPERATING SYSTEM:
Linux Debian 6.0 on x86_64

COMPILER NAME AND VERSION (AND PATCHLEVEL):
g++-4.4.5

THE $ACE_ROOT/ace/config.h FILE:
#include "config-linux.h"

THE $ACE_ROOT/include/makeinclude/platform_macros.GNU FILE:
buildbits ?= 64
include ${ACE_ROOT}/include/makeinclude/platform_linux.GNU

CONTENTS OF
$ACE_ROOT/bin/MakeProjectCreator/config/default.features: (unmodified)

AREA/CLASS/EXAMPLE AFFECTED:
ACE_Logging_Strategy

DOES THE PROBLEM AFFECT:
EXECUTION? YES

SYNOPSIS: Race condition in ACE_Logging_Strategy::handle_timeout
results in occasional core dumps, and random file lengths

DESCRIPTION:

We use ACE_Logging_Strategy to limit log file size to 100MB, and default
10 minute file-size-polling interval.

Our program is multi-threaded with very low activity - there are couple
of timers running, and they keep invoking ACE_TRACE. We notice that
files are prematurely being rotated, with sizes much smaller than the
100MB configured size.

Also, there are occasional core dumps (see stack trace attached).

Looking at ACE_Logging_Strategy::handle_timeout function, I notice that
the test for the file length is invoked while Log_Msg is *not* being locked.

401#if defined (ACE_LACKS_IOSTREAM_TOTALLY)
402 if ((size_t) ACE_OS::ftell (this->log_msg_->msg_ostream ()) >
this->max_size_)
403#else
404 if ((size_t) this->log_msg_->msg_ostream ()->tellp () >
this->max_size_)
405#endif /* ACE_LACKS_IOSTREAM_TOTALLY */
406 {
407 // Lock out any other logging.

408 if (this->log_msg_->acquire ())
409 ACE_ERROR_RETURN ((LM_ERROR,
410 ACE_TEXT ("Cannot acquire lock!\n")),
411 -1);


Line 404: invoking tellp() on ostream is not thread safe - it actually
invokes setpos. tellp() returns implementation specific streampos, which
may not be an integer, but can be constructed from (-1), since in case
tellp() fails, it will return streampos(-1).

WORKAROUND:
Derive MyLoggingStrategy from ACE_Logging_Strategy, enclose
Logging_Straregy::handle_timeout into MyLoggingStrategy::handle_timeout,
and invoke this->log_msg_->acquire() before invoking
ACE_Logging_Strategy::handle_timeout

REPEAT BY:
Sample test program shows that tellp() is not thread safe.
One thread writes messages to a file, other thread runs tellp(). Must be
run on a machine with more than one CPU. It core dumps in less than 5 sec.

PROPOSED FIX:
Attachments:

- stack trace of our application with ace-6.0.1
- sample code for tellp not being thread safe
- attached patch for Logging_Strategy.cpp for ace-6.1.5

Thanks, Milan

[Johnny Willemsen]

Hi,

Thanks for the PRF form. Thanks for all input, could you take the unit
test and rewrite it as an ACE test (just take ACE/tests/OS_Test.cpp) and
add your new test code and just run it for some time, also just call
activate explicitly from the main? Than we can add that as new unit test
with your patch to ACE.

Best regards,

Johnny

> _______________________________________________
> ace-bugs mailing list
> ace-...@list.isis.vanderbilt.edu
> http://list.isis.vanderbilt.edu/mailman/listinfo/ace-bugs
>

[Milan Cvetkovic]

Well, the patch I sent earlier is not quite good, since it does not
properly unlock the mutex.

I am resending the patch for Logging_Strategy.cpp. This time I used
ACE_GUARD_RETURN to make sure the lock really gets released.

Also, I rewrote test so it uses ACE_Logging_Strategy. To make it fail,
it was enough to try to log 100000 lines while invoking tellp() very
fast in another thread. Log_Rotation.cpp should be placed in
$ACE_ROOT/tests/Log_Rotation.cpp. You may have to tweak the file
parameters passed to ACE_Logging_Strategy::init, in particular '-s'
currently creates files in current working directory, rather than
$ACE_ROOT/tests/log.


Milan.

[Johnny Willemsen]

Hi,

Thanks, can you put this in bugzilla, than I can integrate this later

Johnny

> <Log_Rotation.cpp>
> <Logging_Strategy.cpp.patch>

[Milan Cvetkovic]

http://bugzilla.dre.vanderbilt.edu/show_bug.cgi?id=4077