[
https://issues.apache.org/jira/browse/LOGCXX-507?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16948866#comment-16948866
]
Hreniuc Cristi commented on LOGCXX-507:
---------------------------------------
{quote}Doesn't tell me much. What does the warning actually tell me? Is T1
freeing some instance already freed by another thread? Sounds like a problem
with ownership or reference counting of the underlying pointer?
{quote}
I noticed that the sanitizer output got a little bit messed up when I pasted it
here, I've updated the description(I've formatted the sanitizer output).
{quote}Is T1 freeing some instance already freed by another thread? Sounds like
a problem with ownership or reference counting of the underlying pointer?
{quote}
The things that I understand from the output of the sanitizer are these:
- The thread created for the writing operation calls delete on a level object.
- The main thread calls the destructor of levelPtr(I think.... I do not
understand why it that a read, maybe because it tries to read the underlying
level object?..).
After thinking about it now, I don't know for sure what happens here....
> Data race on LevelPtr when using the async appender
> ---------------------------------------------------
>
> Key: LOGCXX-507
> URL: https://issues.apache.org/jira/browse/LOGCXX-507
> Project: Log4cxx
> Issue Type: Bug
> Components: Core
> Affects Versions: 0.10.0, 0.11.0
> Reporter: Hreniuc Cristi
> Priority: Major
>
> We are using log4cxx from this commit(master branch):
> [https://github.com/apache/logging-log4cxx/commit/c60dda4770ce848403f475ab9fa6accd8173d2d8]
>
> We started using the Async Appender, unitl now we were using the
> FileAppender. But when we ran our app with sanitizers, we noticed that there
> are some data races.
> For example this code:
>
>
> {code:c++}
> #include <unistd.h>
> #include <log4cxx/logger.h>
> #include <log4cxx/xml/domconfigurator.h>
> using namespace std;using namespace ::log4cxx;
> using namespace ::log4cxx::helpers;
> using namespace ::log4cxx::xml;int main()
> {
> DOMConfigurator::configure("loggers_config.xml");
>
> LoggerPtr loggerMyMain( Logger::getLogger( "messages" ) );
>
> if (loggerMyMain->isInfoEnabled())
> {
> ::log4cxx::helpers::MessageBuffer oss_;
> loggerMyMain->forcedLog(::log4cxx::Level::getInfo(), oss_.str(oss_ <<
> "Test message"), LOG4CXX_LOCATION);
> }
> sleep(3);
> return 0;
> }
> {code}
>
>
> Having this config file:
>
> {code:xml}
> // code placeholder
> <?xml version="1.0" encoding="UTF-8" ?>
> <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/";>
> <appender name="Async" class="org.apache.log4j.AsyncAppender">
> <param name="Blocking" value="true" />
> <appender-ref ref="main_appender" />
> </appender>
> <!-- Output the log message to log file -->
> <appender name="main_appender" class="org.apache.log4j.FileAppender">
> <param name="file" value="logging_server_logs.log" />
> <param name="append" value="true" />
> <layout class="org.apache.log4j.PatternLayout">
> <param name="ConversionPattern"
> value="%m%n" />
> </layout>
> </appender>
>
>
> <logger name="messages" additivity="false">
> <level value ="debug" /> <!-- Log values with level higher than ... -->
> <appender-ref ref="Async"/>
> </logger>
> </log4j:configuration>
> {code}
> Will generate this output from thread sanitizer:
> {code:bash}
> // code placeholder
> ==================
> WARNING: ThreadSanitizer: data race (pid=23758)
> Write of size 8 at 0x7b1000000280 by thread T1:
> #0 operator delete(void*, unsigned long)
> /opt/gcc/gcc-9.2.0-build/../gcc-9.2.0-src/libsanitizer/tsan/tsan_new_delete.cc:149
> (cvs_util_user+0x5885b2)
> #1 log4cxx::Level::~Level() ../../../src/main/include/log4cxx/level.h:49
> (cvs_util_user+0x5dbcf2)
>
> #2 log4cxx::spi::LoggingEvent::~LoggingEvent()
> /hypervisor/.conan/data/log4cxx/5.11.0.0/cvs/stable/build/5e77f70d43214358e7c5b69f26dc7e51b4c696d2/logging-log4cxx/src/main/cpp/loggingevent.cpp:84
> (cvs_util_user+0x5e4106)
> Previous read of size 8 at 0x7b1000000280 by main thread:
> #0 log4cxx::helpers::ObjectPtrT<log4cxx::Level>::~ObjectPtrT()
> /hypervisor/.conan/data/log4cxx/5.11.0.0/cvs/stable/package/5e77f70d43214358e7c5b69f26dc7e51b4c696d2/include/log4cxx/helpers/objectptr.h:108
> (cvs_util_user+0x5c9a4c)
> #1 main /mnt/projects/cvs_util_user/main.cpp:18 (cvs_util_user+0x5c98f6)
> Thread T1 (tid=23760, running) created by main thread at:
> #0 pthread_create
> /opt/gcc/gcc-9.2.0-build/../gcc-9.2.0-src/libsanitizer/tsan/tsan_interceptors.cc:964
> (cvs_util_user+0x542e7b)
>
> #1 apr_thread_create threadproc/unix/thread.c:179 (cvs_util_user+0x6b1e91)
> #2 __libc_start_main <null> (libc.so.6+0x22494)
> SUMMARY: ThreadSanitizer: data race
> /opt/gcc/gcc-9.2.0-build/../gcc-9.2.0-src/libsanitizer/tsan/tsan_new_delete.cc:149
> in operator delete(void*, unsigned long)
> ==================
> ThreadSanitizer: reported 1 warnings
> {code}
> Note: In that output you will notice "log4cxx/5.11.0.0", we are using conan
> and we added the `5` before. But the version we are using is the one from the
> commit specified at the beginning.
>
> The line mentioned in the output called:
>
> {code:c++}
> #1 main /mnt/projects/cvs_util_user/main.cpp:18
> {code}
> is this:
> {code:c++}
> loggerMyMain->forcedLog(::log4cxx::Level::getInfo(), oss_.str(oss_ << "Test
> message"), LOG4CXX_LOCATION);
> {code}
>
> First he main looked like this:
> {code:c++}
> int main()
> {
> DOMConfigurator::configure("loggers_config.xml");
> LoggerPtr loggerMyMain( Logger::getLogger( "messages" ) );
> LOG4CXX_INFO(loggerMyMain, "First message");
> sleep(3); return 0;
> }
> {code}
> And the data race was at "LOG4CXX_INFO" line, but I wanted to see exactly
> where is the problem, that's why I've expanded the macro.
>
> Has anyone encountered this problem?
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
