[jira] [Created] (LOGCXX-507) Data race on LevelPtr when using the async appender

["Hreniuc Cristi (Jira)" <lo...@logging.apache.org>]

Hreniuc Cristi created LOGCXX-507:
-------------------------------------

             Summary: 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


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)