multithread issue

[Brian <za...@gmail.com>]

I have an application that uses multiple loggers (15), each owned by a
different thread, that is writing to a different file.  Executing the
application starts the logger but soon the application cores.  I wrote a
test application to rule out my code and I still see the same problem.  (I
am also seeing logs with bad output)  This works fine on Windows but in
Linux it cores. This is being run on a multiprocessor box with no hyper
threading.

Has anyone else seen this problem?  I also tried the test program with
org.apache.log4j.FileAppender.

Thanks
  Brian


#include <iostream>
#include <pthread.h>
#include <sstream>
#include <log4cxx/logger.h>
#include <log4cxx/propertyconfigurator.h>
#include <log4cxx/helpers/exception.h>

struct Data
{
    int count;
};

void* LogThread(void* args)
{
    Data* d = (Data*)args;

    // Build Logger Name
    std::ostringstream temp;
    temp << "TestLogger" << d->count;
    std::string loggerName(temp.str());
    std::cout << "getting logger = " << loggerName << std::endl;

    log4cxx::LoggerPtr logger;
    try
    {
        // Get Logger
        logger = log4cxx::Logger::getLogger(loggerName);
    }
    catch(...)
    {
        std::cout << "Failed to get logger = " << loggerName << std::endl;
        return 0;
    }

    while(1)
    {
        logger->debug(loggerName);
        logger->debug("This is a test of the emergency broadcast system.
This is only a test");
        logger->debug("This is a test of the emergency broadcast system.
This is only a test");
        logger->debug("This is a test of the emergency broadcast system.
This is only a test");
        logger->debug("This is a test of the emergency broadcast system.
This is only a test");
        logger->debug("This is a test of the emergency broadcast system.
This is only a test");
        logger->debug("This is a test of the emergency broadcast system.
This is only a test");
        logger->debug("This is a test of the emergency broadcast system.
This is only a test");

        usleep(5);
    }

    return 0;
}

int main(void)
{
    for(int count = 0; count < 10; count++)
    {
        Data* d = new Data();
        d->count = count;

        pthread_t newThread;
        pthread_create(&newThread, NULL, &LogThread, d);
        sleep(1);
    }

    std::string input;
    std::cout << "Waiting for input to exit" << std::endl;
    std::cin >> input;

    return 0;
}

####################################################
# log4j.properties for Generic Application
#
# NOTE:  It doesn't hurt anything to have superfluous
#        entries for loggers that will not be used.
####################################################
log4j.rootLogger=DEBUG
log4j.logger.TestLogger0=DEBUG,Drw.TestLogger0
log4j.logger.TestLogger1=DEBUG,Drw.TestLogger1
log4j.logger.TestLogger2=DEBUG,Drw.TestLogger2
log4j.logger.TestLogger3=DEBUG,Drw.TestLogger3
log4j.logger.TestLogger4=DEBUG ,Drw.TestLogger4
log4j.logger.TestLogger5=DEBUG,Drw.TestLogger5
log4j.logger.TestLogger6=DEBUG,Drw.TestLogger6
log4j.logger.TestLogger7=DEBUG,Drw.TestLogger7
log4j.logger.TestLogger8=DEBUG,Drw.TestLogger8
log4j.logger.TestLogger9=DEBUG ,Drw.TestLogger9

log4j.appender.Drw.TestLogger0=org.apache.log4j.RollingFileAppender
log4j.appender.Drw.TestLogger0.File=TestLogger0.log
log4j.appender.Drw.TestLogger0.Append=true
log4j.appender.Drw.TestLogger0.MaxFileSize=100mb
log4j.appender.Drw.TestLogger0.MaxBackupIndex=3
log4j.appender.Drw.TestLogger0.layout=org.apache.log4j.PatternLayout
log4j.appender.Drw.TestLogger0.layout.ConversionPattern=%d{dd/MM/yyyyHH:mm:ss,SSS}
[%p] %m%n

log4j.appender.Drw.TestLogger1=org.apache.log4j.RollingFileAppender
log4j.appender.Drw.TestLogger1.File=TestLogger1.log
log4j.appender.Drw.TestLogger1.Append=true
log4j.appender.Drw.TestLogger1.MaxFileSize=100mb
log4j.appender.Drw.TestLogger1.MaxBackupIndex=3
log4j.appender.Drw.TestLogger1.layout=org.apache.log4j.PatternLayout
log4j.appender.Drw.TestLogger1.layout.ConversionPattern=%d{dd/MM/yyyyHH:mm:ss,SSS}
[%p] %m%n

... TestLogger 0 - 9

Re: multithread issue

[Curt Arnold <ca...@apache.org>]

On Aug 21, 2007, at 12:15 PM, Brian wrote:

> I have an application that uses multiple loggers (15), each owned  
> by a different thread, that is writing to a different file.   
> Executing the application starts the logger but soon the  
> application cores.  I wrote a test application to rule out my code  
> and I still see the same problem.  (I am also seeing logs with bad  
> output)  This works fine on Windows but in Linux it cores. This is  
> being run on a multiprocessor box with no hyper threading.
>
> Has anyone else seen this problem?  I also tried the test program  
> with org.apache.log4j.FileAppender.
>
> Thanks
>   Brian

Sorry about the long delay.  I finally built your test on Linux and  
got an immediate segfault in the first initialization of LoggerPtr.   
The reason this is occurring on Linux and not Windows is the  
implementation of apr_atomic_xchg32 on Windows delegates to a Windows  
API method which will work if called before APR initialization and  
the Linux implementation requires that APR be initialized.  The  
implementation of a LoggerPtr isn't sufficient to trigger APR  
initialization.

If instead of

log4cxx::LoggerPtr logger;
     try
     {
         // Get Logger
         logger = log4cxx::Logger::getLogger(loggerName);
     }
     catch(...)
     {
         std::cout << "Failed to get logger = " << loggerName <<  
std::endl;
         return 0;
     }

I did:

log4cxx::LoggerPtr logger(log4cxx::Logger::getLogger(loggerName));


I no longer got an immediate segfault as the call to getLogger() will  
trigger the call to load APR before the LoggerPtr constructor calls  
apr_atomic_xchg32.  With that change, I still got an segfault on  
application shutdown.  I didn't trace that issue down, but it appears  
likely due to APR being de-initialized when the thread that  
originally initialized it went out of scope, leaving the other  
threads using a non-functioning APR.  That problem could be addressed  
by initializing APR in the main thread (likely by calling  
Logger::getLogger in either a constructor of a static object).

Basically, log4cxx is safe to use on multi-threads, but it isn't safe  
to initialize or configure on an arbitrary thread.  Apps near to do  
something to trigger initialization and configuration either on  
module load time (happens automatically with a static LoggerPtr  
instance) or on the main thread.