How do I prevent log4cplus log messages within log messages?

Question

I have the following (simplified) code in my C++ program:

std::string DataRequest::toString() const {
LOG4CPLUS_TRACE(logger,
        LOG4CPLUS_TEXT("symbol=" << m_contract.symbol));

std::ostringstream oss;
oss << "id=" << reqId
    << ",symbol=" << m_contract.symbol;
return oss.str();
}

and

int DataService::requestData(
    DataRequest request) {

LOG4CPLUS_INFO(logger, LOG4CPLUS_TEXT("requestData: " << request.toString()));
}

This code then produces the log message:

TRACE symbol=AAA
INFO  symbol=AAArequestData: id=1,symbol=AAA

however I was expecting

TRACE symbol=AAA
INFO  requestData: id=1,symbol=AAA

Since there is a log4cplus message being generated within a log4cplus message it appears to be concatenating the two messages into a single message. Is this normal behaviour? Is there a solution to force each message to be generated independently?

wilx · Accepted Answer · 2013-01-02T11:35:23.380

This is wrong code

LOG4CPLUS_TRACE(logger,
        LOG4CPLUS_TEXT("symbol=" << m_contract.symbol));

it should read

LOG4CPLUS_TRACE(logger,
        LOG4CPLUS_TEXT("symbol=") << m_contract.symbol);

instead.

As for the concatenated messages, what output layout are you using? If it is the pattern layout, then you should add the %n formatter at the very end of the format string.

EDIT:

Unfortunately I am still getting the having the problem that the log messages are being concatenated. I think this has to do with the fact that the call request.toString() in the log message itself also has a call to a log message but for some reason the two messages are being printed together even after the code fix. :(

Ah, I misunderstood the problem, initially. So, you are logging a second event while you are preparing first. The issue is that the formatting is done to a thread-local ostringstream. The thread-local ostringstream is used as a performance enhancement. (The ostringstream does not have to be constructed and destructed on each logged message.)

For immediate work around, you have two options. First, you stop this nested logging. Second, you "fix" LOG4CPLUS_*() macros to not use the thread-local ostringstream or you roll your own logging macros. Either should not be that hard.

Long term, I can add a special case to the logging macros that would make them use fresh ostringstream each time to allow your use case.

EDIT 2:

I have filled a bug report and attached a patch that implements a work-around. See https://sourceforge.net/p/log4cplus/bugs/153/.

I am using `log4cplus.appender.LogFile.layout=log4cplus::PatternLayout` and `log4cplus.appender.LogFile.layout.ConversionPattern=%D{%Y-%m-%d %H:%M:%S,%q} %-5p [%T] [%c{2}] [%l] [%M] %x - %m %n`. All of my other log messages are being printed correctly. It is just the one case above in which a call to a function which also has a log message causes the two messages to be concatenated. I'll try again with the code fix you suggested to see if that might fix the problem. — kmccoy, Jan 01 '13 at 05:49
Unfortunately I am still getting the having the problem that the log messages are being concatenated. I think this has to do with the fact that the call `request.toString()` in the log message itself also has a call to a log message but for some reason the two messages are being printed together even after the code fix. :( — kmccoy, Jan 01 '13 at 10:30
@kmccoy: I have implemented a work-around, see the bug report linked in the answer. — wilx, Jan 02 '13 at 11:35

How do I prevent log4cplus log messages within log messages?

1 Answers1