Crash when i use #define ELPP_THREAD_SAFE

[parikshitnangre]

I am facing crash when i use this macro. My code snippet looks like this -

define ELPP_THREAD_SAFE

define ELPP_NO_DEFAULT_LOG_FILE

include "../easylogging++.h"

when i build it, i get follwing warning -
easylogging++.h(1029): warning C4100: 'ms' : unreferenced formal parameter

and i am very sure crash is due to the macro. As when i comment the line, //#define ELPP_THREAD_SAFE, crash goes off.

Is it because of the above warning ?

So please suggest what should i change/add ? Also the macro is ELPP_THREAD_SAFE & not _ELPP_THREAD_SAFE, but many times in answers i found it as _ELPP_THREAD_SAFE.

[abumq]

Warning has nothing to do with crash

We've seen cases like this when u have macro in one file not in other. Why don't people define it as compiler option? I don't understand

[parikshitnangre]

still it is crashing when I am setting as compiler option in Project Properties-->C/C++ --> Preprocessor - ELPP_THREAD_SAFE

[abumq]

does it crash when you use macro (LOG(WARNING))?

[abumq]

can you run this sample? What platform are you using? (compiler and OS specifically)

[parikshitnangre]

i am using windows and when i used LOG(WARNING) it doesnt crash.

Now i tried this very liitle code - and its crashing -

#define ELPP_THREAD_SAFE

#include "easylogging++.h"

INITIALIZE_EASYLOGGINGPP
void main()
{
el::Logger* mainLogger = el::Loggers::getLogger("main");
mainLogger->warn("abc");
}

and when i comment the line #define ELPP_THREAD_SAFE, it works well.
Please tell me whats wrong.

[abumq]

try CLOG(WARN, "main") << "abc" instead of mainLogger->warn("abc")

[parikshitnangre]

i tried CLOG(WARN, "main") << "abc";

compile errors -
Error 1 error C2275: 'el::base::Writer' : illegal use of this type as an expression
Error 2 error C3861: 'CWARN': identifier not found

[abumq]

what compiler is it? have you tried the sample i asked you to run?

[abumq]

also can you try to getLogger("default") instead of getLogger("main") in your original sample?

If this works then you have problem with registering the logger. try using valgrind to find whether it's getting enough memory to register new logger

[parikshitnangre]

this code also crashing -
#define ELPP_THREAD_SAFE

#include "easylogging++.h"

INITIALIZE_EASYLOGGINGPP
void main()
{
el::Logger* mainLogger = el::Loggers::getLogger("default");
mainLogger->warn("abc");
}

[abumq]

hmm what about pthread.cc sample? what compiler is this? what version of c++? what windows? if you don't provide enough details i'm afraid i won't be able to help you

[parikshitnangre]

windows 7 service pack 1
when i use std::cout << __cplusplus << endl; the output was 199711
and i am using default compiler of Visual studio 2013

[parikshitnangre]

CLOG(WARNING, "main") << "abc"; worked well with #define ELPP_THREAD_SAFE.
But when i use mainLogger->warn("abc"); it crashes. Thanks for your help.

[RossBencina]

@mkhan3189 you ask "Why don't people define it as compiler option? I don't understand"

It's because the documentation does not even make it clear that these flags need to be #defined before including easylogging++.h and the documentation calls them "Configuration Macros" which is the wrong word for a pre-processor configuration constant, imho.

btw. I found this thread while trying to work out how to use these "macros"

[ghost]

I am re-opening this because I am also experiencing a crash when logging very
fast from many (~72) threads.

It seems to be some sort of race condition. What makes me say that is that when
I log the output to terminal, the program doesn't crash, but when I log to a file with
shell redirection, it does crash.

Platform: ubuntu 14.04 x86-64
CPU : 8 core Intel(R) Core(TM) i7-4910MQ CPU @ 2.90GHz
Compiler : clang++-3.6
Compile flags: -std=c++1 -g

This is not compiler-specific: the same crash also occurs
when compiling with g++ version 4.8.4

Here are the flags all my code is compiled with:

-D_ELPP_THREAD_SAFE=1
-D_ELPP_DEBUG_ERRORS=1
-D_ELPP_STACKTRACE_ON_CRASH=1
-D_ELPP_FORCE_USE_STD_THREAD=1
-D_ELPP_LOGGING_FLAGS_FROM_ARG=1

Here's how I initialize the logging library:

INITIALIZE_EASYLOGGINGPP
static const char *getThreadId() {
    static std::atomic_int pool;
    static thread_local char tid[11];
    if(0==tid[0]) {
        sprintf(tid, "%04d", pool++);
    }
    return tid;
}

static void initLogging(
    int  argc,
    char *argv[]
) {
    el::Configurations conf;
    conf.setGlobally(el::ConfigurationType::Format, "%datetime{%s.%g} %tid %levshort %loc %func: %msg");
    el::Helpers::installCustomFormatSpecifier(el::CustomFormatSpecifier("%tid", getThreadId));
    conf.set(el::Level::Trace,   el::ConfigurationType::Enabled, "0");
    conf.set(el::Level::Debug,   el::ConfigurationType::Enabled, "1");
    conf.set(el::Level::Verbose, el::ConfigurationType::Enabled, "0");
    conf.set(el::Level::Info,    el::ConfigurationType::Enabled, "1");
    conf.set(el::Level::Warning, el::ConfigurationType::Enabled, "1");
    conf.set(el::Level::Error,   el::ConfigurationType::Enabled, "1");
    conf.set(el::Level::Fatal,   el::ConfigurationType::Enabled, "1");
    conf.setGlobally(el::ConfigurationType::MillisecondsWidth, "6");
    el::Loggers::reconfigureAllLoggers(conf);
    START_EASYLOGGINGPP(argc, argv);
}

Here's a gdb stack dump of the crash

#0 0x000000000060a060 in el::base::DefaultLogDispatchCallback::dispatch(std::string&&) (this=0xa5af00,
logLine=<unknown type in /home/emogenet/cncsim/cncsim, CU 0x5649bd, DIE 0x796df1>) at ./Log.h:4205
#1 0x0000000000609e2a in el::base::DefaultLogDispatchCallback::handle (this=0xa5af00, data=0x7fffcf0f9a00)
at ./Log.h:4179
#2 0x000000000041a83f in el::base::LogDispatcher::dispatch (this=0x7fffcf0f9ad0) at ./Log.h:4486
#3 0x000000000041b67a in el::base::Writer::triggerDispatch (this=0x7fffcf0f9d40) at ./Log.h:5054
#4 0x000000000041b432 in el::base::Writer::processDispatch (this=0x7fffcf0f9d40) at ./Log.h:5037
#5 0x000000000041ab44 in el::base::Writer::~Writer (this=0x7fffcf0f9d40, __in_chrg=) at ./Log.h:4923
#6 0x000000000068993d in LoaderThread::run (this=0x1f55b00) at LoaderThread.h:58
#7 0x00007ffff6cd6f6f in ?? () from /home/emogenet/sw/qt-5.5.1/lib/libQt5Core.so.5
#8 0x0000003000c08182 in start_thread (arg=0x7fffcf0fa700) at pthread_create.c:312
#9 0x00000030004fa47d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Here's the offending line (line 4205) :

(gdb) l
4200 ELPP_INTERNAL_ERROR("Log file for [" << LevelHelper::convertToString(m_data->logMessage()->level()) << "] "
4201 << "has not been configured but [TO_FILE] is configured to TRUE. [Logger ID: "
4202 << m_data->logMessage()->logger()->id() << "]", false);
4203 }
4204 }
4205 if (m_data->logMessage()->logger()->m_typedConfigurations->toStandardOutput(m_data->logMessage()->level())) {
4206 if (ELPP->hasFlag(LoggingFlag::ColoredTerminalOutput))
4207 m_data->logMessage()->logger()->logBuilder()->convertToColoredOutput(&logLine, m_data->logMessage()->level());
4208 ELPP_COUT << ELPP_COUT_LINE(logLine);

Finally, to confirm the misbehavior, I ran it with valgrind.
It spits a whole bunch of "Invalid read of size 8":

==2935== Invalid read of size 8
==2935== at 0x607832: el::LogDispatchData::logMessage() const (Log.h:3343)
==2935== by 0x60A03D: el::base::DefaultLogDispatchCallback::dispatch(std::string&&) (Log.h:4205)
==2935== by 0x609E29: el::base::DefaultLogDispatchCallback::handle(el::LogDispatchData const_) (Log.h:4179)
==2935== by 0x41A83E: el::base::LogDispatcher::dispatch() (Log.h:4486)
==2935== by 0x41B679: el::base::Writer::triggerDispatch() (Log.h:5054)
==2935== by 0x41B431: el::base::Writer::processDispatch() (Log.h:5037)
==2935== by 0x41AB43: el::base::Writer::~Writer() (Log.h:4923)
==2935== by 0x615529: LoaderThread::LoaderThread(Eigen::Transform<float, 3, 2, 0> const&, std::string const&, STLObject__, unsigned char, unsigned char, unsigned char) (LoaderThread.h:41)
==2935== by 0x614B10: Piece::load() (Machine.cpp:33)
==2935== by 0x615397: Piece::draw() (Machine.h:34)
==2935== by 0x614F36: Part::draw() (Machine.cpp:64)
==2935== by 0x60233E: Machine::draw() (Machine.h:228)
==2935== Address 0x1bcc6a00 is not stack'd, malloc'd or (recently) free'd
==2935==
==2935== Invalid read of size 8
==2935== at 0x607832: el::LogDispatchData::logMessage() const (Log.h:3343)
==2935== by 0x60A057: el::base::DefaultLogDispatchCallback::dispatch(std::string&&) (Log.h:4205)
==2935== by 0x609E29: el::base::DefaultLogDispatchCallback::handle(el::LogDispatchData const_) (Log.h:4179)
==2935== by 0x41A83E: el::base::LogDispatcher::dispatch() (Log.h:4486)
==2935== by 0x41B679: el::base::Writer::triggerDispatch() (Log.h:5054)
==2935== by 0x41B431: el::base::Writer::processDispatch() (Log.h:5037)
==2935== by 0x41AB43: el::base::Writer::~Writer() (Log.h:4923)
==2935== by 0x615529: LoaderThread::LoaderThread(Eigen::Transform<float, 3, 2, 0> const&, std::string const&, STLObject**, unsigned char, unsigned char, unsigned char) (LoaderThread.h:41)
==2935== by 0x614B10: Piece::load() (Machine.cpp:33)
==2935== by 0x615397: Piece::draw() (Machine.h:34)
==2935== by 0x614F36: Part::draw() (Machine.cpp:64)
==2935== by 0x60233E: Machine::draw() (Machine.h:228)
==2935== Address 0x1bcc6a00 is not stack'd, malloc'd or (recently) free'd
==2935==

The offending line (3343) where the bad read occur:

inline const LogMessage* logMessage(void) const { return m_logMessage; }

[abumq]

Crash has nothing to do with thread as assert failure suggests, ypu remove file configuration somewhere but didnt unset to file config

If you look at this sample and uncomment lines in the end and run and if it crashes it's related to thread if not it's ur config that u change in one of the 72 threads

https://github.com/easylogging/easyloggingpp/blob/master/samples/STL/pthread.cpp

[ghost]

Crash has nothing to do with thread as assert failure suggests, ypu remove file configuration
somewhere but didnt unset to file config

I never change the logging configuration after I set it in the main.
I do not use external files for logging configuration, everything is done programatically.
The only thing I do in the threads is something like : LOG(DEBUG) << "hello";

If you look at this sample and uncomment lines in the end and run and if it crashes it's
related to thread if not it's ur config that u change in one of the 72 threads

I just downloaded the sample, and as you suggested, I uncommented the lines at the end
and compiled it. The sample program has the exact same problem mine has:
- when left to run to console, it does not crash
- when logging to a file via shell redirection, it crashes

Here's the stack dump under gdb:

#0 malloc_consolidate (av=av@entry=0x7ffff0000020) at malloc.c:4151
#1 0x000000300047fdf8 in _int_malloc (av=0x7ffff0000020, bytes=1024) at malloc.c:3423
#2 0x00000030004827b0 in __GI___libc_malloc (bytes=1024) at malloc.c:2891
#3 0x000000300ac5edad in operator new(unsigned long) () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#4 0x00000000004241e8 in __gnu_cxx::new_allocatorel::Configuration*::allocate (this=0x7ffff00017d8, __n=128) at /usr/include/c++/4.8/ext/new_allocator.h:104
#5 0x000000000041ebff in std::_Vector_base<el::Configuration*, std::allocatorel::Configuration* >::_M_allocate (this=0x7ffff00017d8, __n=128) at /usr/include/c++/4.8/bits/stl_vector.h:168
#6 0x0000000000419670 in std::vector<el::Configuration*, std::allocatorel::Configuration* >::_M_emplace_back_aux<el::Configuration* const&> (this=0x7ffff00017d8) at /usr/include/c++/4.8/bits/vector.tcc:404
#7 0x0000000000415475 in std::vector<el::Configuration*, std::allocatorel::Configuration* >::push_back (this=0x7ffff00017d8, __x=@0x7ffff7fbe830: 0x7ffff0000e30) at /usr/include/c++/4.8/bits/stl_vector.h:911
#8 0x0000000000413f2b in el::base::utils::RegistryWithPred<el::Configuration, el::Configuration::Predicate>::registerNew (this=0x7ffff00017c8, ptr=0x7ffff0000e30) at easylogging++.h:2075
#9 0x0000000000409f41 in el::Configurations::unsafeSet (this=0x7ffff00017c8, level=el::Level::Global, configurationType=el::ConfigurationType::Format, value="%datetime %level [%logger] %msg") at easylogging++.h:2821
#10 0x00000000004096db in el::Configurations::set (this=0x7ffff00017c8, level=el::Level::Global, configurationType=el::ConfigurationType::Format, value="%datetime %level [%logger] %msg") at easylogging++.h:2561
#11 0x0000000000409782 in el::Configurations::set (this=0x7ffff00017c8, conf=0x646f50) at easylogging++.h:2573
#12 0x0000000000409597 in el::Configurations::setFromBase (this=0x7ffff00017c8, base=0x646270) at easylogging++.h:2513
#13 0x000000000040d117 in el::Logger::configure (this=0x7ffff0001620, configurations=...) at easylogging++.h:3445
#14 0x000000000040cbc1 in el::Logger::Logger (this=0x7ffff0001620, id="logger3", configurations=..., logStreamsReference=0x6462a8) at easylogging++.h:3398
#15 0x000000000040dd7a in el::base::RegisteredLoggers::get (this=0x646220, id="logger3", forceCreation=true) at easylogging++.h:3638
#16 0x00000000004131e8 in el::Loggers::getLogger (identity="logger3", registerIfNotAvailable=true) at easylogging++.h:5787
#17 0x0000000000404237 in write (thrId=0x42c055) at z.cpp:76
#18 0x0000003000c08182 in start_thread (arg=0x7ffff7fbf700) at pthread_create.c:312
#19 0x00000030004fa47d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Here's valgrind:

==28925== Thread 4:
==28925== Invalid read of size 1
==28925== at 0x4A0B0E2: strlen (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==28925== by 0x300ACBBD34: std::basic_string<char, std::char_traits, std::allocator >::basic_string(char const_, std::allocator const&) (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.19)
==28925== by 0x410E36: el::base::DefaultLogBuilder::build(el::LogMessage const_, bool) const (easylogging++.h:4448)
==28925== by 0x40FF47: el::base::DefaultLogDispatchCallback::handle(el::LogDispatchData const_) (easylogging++.h:4179)
==28925== by 0x41168E: el::base::LogDispatcher::dispatch() (easylogging++.h:4486)
==28925== by 0x412631: el::base::Writer::triggerDispatch() (easylogging++.h:5054)
==28925== by 0x4122D2: el::base::Writer::processDispatch() (easylogging++.h:5026)
==28925== by 0x411ACA: el::base::Writer::~Writer() (easylogging++.h:4923)
==28925== by 0x403CD3: write(void_) (z.cpp:53)
==28925== by 0x3000C08181: start_thread (pthread_create.c:312)
==28925== by 0x30004FA47C: clone (clone.S:111)
==28925== Address 0x4c8bfd8 is 24 bytes inside a block of size 34 free'd
==28925== at 0x4A092BC: operator delete(void_) (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==28925== by 0x300ACBA32E: std::basic_string<char, std::char_traits, std::allocator >::~basic_string() (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.19)
==28925== by 0x404AA7: getThreadId_CustomVersion() (z.cpp:99)
==28925== by 0x41C9C4: std::Function_handler<char const (), char const* ()()>::M_invoke(std::Any_data const&) (functional:2057)
==28925== by 0x416DDD: std::function<char const ()>::operator()() const (functional:2471)
==28925== by 0x410E1A: el::base::DefaultLogBuilder::build(el::LogMessage const, bool) const (easylogging++.h:4448)
==28925== by 0x40FF47: el::base::DefaultLogDispatchCallback::handle(el::LogDispatchData const) (easylogging++.h:4179)
==28925== by 0x41168E: el::base::LogDispatcher::dispatch() (easylogging++.h:4486)
==28925== by 0x412631: el::base::Writer::triggerDispatch() (easylogging++.h:5054)
==28925== by 0x4122D2: el::base::Writer::processDispatch() (easylogging++.h:5026)
==28925== by 0x411ACA: el::base::Writer::~Writer() (easylogging++.h:4923)
==28925== by 0x403CD3: write(void*) (z.cpp:53)
==28925==

[robertthorn]

I am also having this problem running on Ubuntu 16.04 LTS. I am using G++ to compile. I am thinking it may be a compiler problem.

[lrodorigo]

I confirm the behaviour on Ubuntu 16.04LTS using GCC 5.4.0.
std::system_error on first log if using -DELPP_THREAD_SAFE

[alandefreitas]

I'm also having trouble with this. Here is my complete source code:

#define ELPP_THREAD_SAFE
#include "easylogging++.h"

INITIALIZE_EASYLOGGINGPP

int main(int argc, char **argv) {
    START_EASYLOGGINGPP(argc, argv);
    LOG(INFO) << "My first info log using default logger";
    return 0;
}

And this is what I get:

Process finished with exit code 11