[LOGCXX-507] Data race on LevelPtr when using the async appender

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 0.10.0, 0.11.0
• Fix Version/s: 0.12.0
• Component/s: Core
• Assignee: Unassigned
• Reporter: Hreniuc Cristi
• Created: 09/Oct/19 22:34
• Updated: 23/Mar/21 01:13
• Resolved: 23/Mar/21 01:13

Description

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:

 

 

#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;
}

 

 

Having this config file:

 

// 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>

Will generate this output from thread sanitizer:

// 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

 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:

 

#1 main /mnt/projects/cvs_util_user/main.cpp:18

is this:

loggerMyMain->forcedLog(::log4cxx::Level::getInfo(), oss_.str(oss_ << "Test message"), LOG4CXX_LOCATION);

 

First he main looked like this:

int main()
{ 
  DOMConfigurator::configure("loggers_config.xml");
  LoggerPtr loggerMyMain( Logger::getLogger( "messages" ) );
  LOG4CXX_INFO(loggerMyMain, "First message");
  sleep(3);  return 0;
}

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?