You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Robert Middleton (Jira)" <lo...@logging.apache.org> on 2020/12/26 17:06:00 UTC
[jira] [Comment Edited] (LOGCXX-507) Data race on LevelPtr when
using the async appender
[ https://issues.apache.org/jira/browse/LOGCXX-507?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17255066#comment-17255066 ]
Robert Middleton edited comment on LOGCXX-507 at 12/26/20, 5:05 PM:
--------------------------------------------------------------------
I tested this out today, and the data race is possibly a false positive. When I have a test with a release build of log4cxx(no fsanitize=thread), then I also get an error from tsan about a data race. However, when I do a build of log4cxx with fsanitize=thread, there is no error reported by tsan. According to the documentation([https://github.com/google/sanitizers/wiki/ThreadSanitizerCppManual#non-instrumented-code)|https://github.com/google/sanitizers/wiki/ThreadSanitizerCppManual#non-instrumented-code]
{quote}If some code (e.g. dynamic libraries) is not compiled with the flag, it can lead to false positive race reports, false negative race reports and/or missed stack frames in reports depending on the nature of non-instrumented code.
{quote}
I was also checking this on my c++11 branch, so it's also possible that I fixed something else that fixes the issue.
was (Author: rmiddleton):
I tested this out today, and the data race is possibly a false positive. When I have a test with a release build of log4cxx(no fsanitize=thread), then I also get an error from tsan about a data race. However, when I do a build of log4cxx with fsanitize=thread, there is no error reported by tsan. According to the [documentation|[https://github.com/google/sanitizers/wiki/ThreadSanitizerCppManual#non-instrumented-code:|https://github.com/google/sanitizers/wiki/ThreadSanitizerCppManual#non-instrumented-code]:]
{quote}If some code (e.g. dynamic libraries) is not compiled with the flag, it can lead to false positive race reports, false negative race reports and/or missed stack frames in reports depending on the nature of non-instrumented code.
{quote}
I was also checking this on my c++11 branch, so it's also possible that I fixed something else that fixes the issue.
> 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)