This issue has been recorded as bug #LOGCXX-194.
> -----Original Message----- > From: BUNBURY Myles > Sent: Monday, October 01, 2007 12:05 PM > To: Log4CXX User > Subject: RE: Log4cxx wilting under heavy load > > > -----Original Message----- > > From: Curt Arnold [mailto:[EMAIL PROTECTED] > > Sent: Friday, September 28, 2007 6:11 PM > > To: Log4CXX User > > Subject: Re: Log4cxx wilting under heavy load > > > > > > On Sep 28, 2007, at 4:27 PM, BUNBURY Myles wrote: > > > > > Log4cxx seems to wilt when under heavy load. > > > > > > With the syslog appender enabled, the application cores > when under > > > heavy load. > > > > > > When using a RollingFileAppender with an XMLLayout layout, my > > > output file gets garbled: > > > > > > <<<snip>>> > > > > > > <log4j:event logger="Gateway.AuthenticationServices/ > > > ANS_AuthenticationService.cpp" timestamp="1191005220721" > > > level="INFO" thread="0x61eb3b90"> > > > <log4j:message><![CDATA[No username/password token or SAML > > > assertion to process.]]></log4j:message> > > > </log4j:event> > > > <log4j:event logger="Gateway.MediationPipeline/ > > > MED_PipelineMessage.cpp" timestamp="1191005220721" level="INFO" > > > thread="0x61eb3b90"> > > > <log4j:message><![CDATA[No session policy set for > user/group .]]></ > > > log4j:message> > > > </log4j:event> > > > <log4j:event logger="Gateway.MediationPipeline/ > > > MED_PipelineMessage.cpp" timestamp="1191005220721" level="DEBUG" > > > thread="0x61eb3b90"> > > > <log4j:message><![CDATA[Using session #2 with session policy > > > DefaultPolicy.]]></log4j:message> > > > </log4j:event> > > > <log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp" > > > timestamp="1191005220729" level="WARN" thread="0x5ecaeb90"> > > > <log4j:message><![CDATA[Concurrent session limit reached. > > > Transaction is rejected.]]></log4j:message> > > > </log4j:event> > > > <log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp" > > > timestamp="1191005220729" level="ERROR" thread="0x5ecaeb90"> > > > <log4j:message><![CDATA[User session rejected - have > exceeded the > > > maximum number of concurrent sessions based on the > current license > > > (0 concurrent sessions allowed)]]></log4j:message> > > > </log4j:event> > > > ¦« " ´T# > > > ýÍÊ^˜ÌÊ^Ä °Ñ" > > > ôÌÊ^µ ‡·<T# > > > ÜÑ" > > > XÍÊ^ <T# > > > ÜÑ" > > > À4‡· dÐÊ^ÍÊ^§c ´T# > > > ð‡·°Ñ" > > > @ÍÊ^1Ö†· T# > > > ¸Ñ" > > > XÍÊ^ ôO ÔÑ" > > > |ó³ hÍÊ^ > > > Þ$z XÍÊ^p÷³ xÍÊ^/&L4# > > > z ¸ÍÊ^Z;'°Ñ" > > > ¸ÍÊ^ü( H4# > > > ðÍÊ^¸ÍÊ^13 Ì €ðÍÊ^ðÍÊ^ > > > > > > Þ$z ÏÊ^Äy dÐÊ^ðÍÊ^ ðÍÊ^ > > > ÏÊ^PÏÊ^XÏÊ^h ·‹· > > > 1191‘À‹·20729&ô €¼ÏÊ^(ÎÊ^®Ý‹· €È > > > €—ÎÊ^H€¼ÏÊ^H €@ € ô5 À > > > € €À € ¼ÏÊ^xÎÊ^ € > > > Ðõ‹··‹·ôO À € ˆÎÊ^@ €‹‚& > > > ·‹· X~—·¨ÎÊ^5 > > > ´ dÐÊ^Þ$¸ÎÊ^ H& çÎÊ^ÏÊ^^¥!øÎÊ^°# > > > ÏÊ^§c % > > > ôèÎÊ^ðÆ 0ÐÊ^'ÏÊ^øÎÊ^Ùà 'ÏÊ^'ÏÊ^ > > > (ÏÊ^žÇ 'ÏÊ^'ÏÊ^SÏÊ^ͦ!\sA > > > dÐÊ^(ÏÊ^%LRÏÊ^´ÏÊ^XÏÊ^ÖÇ RÏÊ^SÏÊ^RÏÊ^¶0 \sA > > > kÏÊ^XÏÊ^¶&$HsA > > > dÐÊ^ÈÏÊ^¦« 0ÐÊ^Þ > > > $xÏÊ^íà HÐÊ^ÿÿÿÿˆÏÊ^Ä HÐÊ^l4¸ÏÊ^6É HÐÊ^ > > > ó ôO l4z ÈÏÊ^e4 HÐÊ^dÐÊ^ÈÏÊ^uÉ HÐÊ^Þ > > > [EMAIL PROTECTED] HÒÊ^ÑÊ^ÿÿÿÿ‘â³ Z;'°Ñ" > > > j 8ÐÊ^ü( 0x5ecaeb90Ê^13 4€pÐÊ^pÐÊ^ Þ$z > > > HÐÊ^Í&ä6% > > > 4ÐÊ^4ÐÊ^ ˆÐÊ^ > > > * à6% > > > LÐÊ^LÐÊ^ Üí# > > > Ì €˜ÐÊ^<log4j:event logger="Gateway.SessionInfra/ > > > SI_SessionManager.cpp" timestamp="1191005220729" level="WARN" > > > thread="0x600b0b90"> > > > <log4j:message><![CDATA[Concurrent session limit reached. > > > Transaction is rejected.]]></log4j:message> > > > </log4j:event> > > > <log4j:event logger="Gateway.MediationPipeline/ > > > MED_PipelineMessage.cpp" timestamp="1191005220729" level="INFO" > > > thread="0x5ecaeb90"> > > > <log4j:message><![CDATA[Auth'ed user hitting dend. > Transaction is > > > rejected.]]></log4j:message> > > > </log4j:event> > > > <log4j:event logger="Gateway.MediationPipeline/ > > > MED_PipelineMessage.cpp" timestamp="1191005220729" level="INFO" > > > thread="0x5ecaeb90"> > > > <log4j:message><![CDATA[Auth'ed user hitting deny-all ws]]></ > > > log4j:message> > > > </log4j:event> > > > <log4j:event logger="Gateway.SessionInfra/SI_SessionManager.cpp" > > > timestamp="1191005220729" level="ERROR" thread="0x600b0b90"> > > > <log4j:message><![CDATA[User session rejected - have > exceeded the > > > maximum number of concurrent sessions based on the > current license > > > (0 concurrent sessions allowed)]]></log4j:message> > > > </log4j:event> > > > > > > <<<snip>>> > > > > > > This output was generated with ~150 threads throwing out error > > > messages in rapid succession. > > > > > > I have not noted these problems when treading lightly on > the system. > > > > > > At this point I'm suspicious that log4cxx is overflowing > some sort > > > of output buffer that's fills up due to the volume. I don't > > believe > > > it is a multithreading issue as I serialized the logging > calls in > > > my code with a mutex and did not note any change. > > > > > > Has anyone else noted something similiar? > > > > > > How is log4cxx supposed to behave when the logging volume > exceeds > > > its capacity to output those events? > > > > > > > There was a similar symptoms reported in https://issues.apache.org/ > > jira/browse/LOGCXX-186. That ended up being due to attempting to > > configure log4cxx simultaneously on multiple threads. I > assume that > > is not the case with you, but could you confirm that the problem > > persists if you configure and attempt a logging request prior to > > launching threads (assuming that your app is the one launching the > > threads). > > > > If that is not the case, then the previous bug report might be > > instructive to try to identify and fix the problem. The problems > > might be related, but perhaps not. I would focus on trying to > > identify the one that is most significant to you and then > see if any > > resolution fixed the other. > > > > I would suggest: > > > > 1. Make sure that you are using the most current SVN HEAD. > > > > 2. Making sure that configuration and some initial log > > requests occur > > before threads are launched. (previously mentioned). > > > > 3. Wrap the failing appender in the soon to be committed > rewrite of > > AsyncAppender (if not in the next hour or so, at least by mid-day > > tomorrow). AsyncAppender has been badly flawed. I'm just > about the > > commit a port of the log4j 1.2.14 AsyncAppender (which replaced an > > earlier log4j implementation that was badly flawed too). > > That should > > have the affect of bringing all appends on the underlying appender > > down to a common thread. Plus it would be a great stress > > test of all > > my new code (thanks for volunteering for testing). > > > > 4. Simplify, simplify. There are a couple of places that > corruption > > may be occurring. It could be an Appender problem, a Layout > > problem, > > a CharsetEncoder problem, a CharsetDecoder problem or some > > combination. Trying to isolate the problem makes resolution a lot > > easier. > > a) Setting LOG4CXX_LOGCHAR_IS_UTF8 would replace an > conversion > > between the local code page and UTF-8 with a straight copy. > > Eliminating a lot of complexity and potential source of problems. > > b) Replace the layout (if there is one) with something > > simpler. > > First try simplifying the pattern as much as possible like %m%n. > > c) See if the problem occurs with the simpler appenders > > (FileAppender instead of RollingFileAppender) or other unrelated > > appenders. > > > > 5. Attempt to recreate the problem in a sample app that you can > > attach to a bug report. Please specify all specifics of the > > configurations (operating system, compiler, type and number of > > processors, etc) that have been tested and whether they fail > > consistently, have not been observed to fail or somewhere > in between. > > > > 6. If you are running on a x86 Unix, valgrind could be useful to > > identify potential problems. I used the helgrind tool in earlier > > versions of valgrind (its been broken for a while, so had to > > build it > > from source) to identify potential race conditions. Other tools > > might be useful to identify the problem. > > > > Firstly, the relevant portions of the log4cxx.properties file > might be a useful reference: > > --- > log4j.appender.file=org.apache.log4j.RollingFileAppender > log4j.appender.file.File=${WSG_HOME}/grizzlyGW.log > log4j.appender.file.MaxFileSize=10000KB > log4j.appender.file.MaxBackupIndex=10 > log4j.appender.file.layout=org.apache.log4j.PatternLayout > log4j.appender.file.layout.ConversionPattern=%d{ISO8601} %5p > [%c] (%F:%L) %t: %m%n > > log4j.appender.XMLFile=org.apache.log4j.RollingFileAppender > log4j.appender.XMLFile.File=${WSG_HOME}/grizzlyGW.xml > log4j.appender.XMLFile.MaxFileSize=10000KB > log4j.appender.XMLFile.MaxBackupIndex=10 > log4j.appender.XMLFile.layout=org.apache.log4j.xml.XMLLayout > > log4j.appender.file2=org.apache.log4j.FileAppender > log4j.appender.file2.File=${WSG_HOME}/grizzlyGW2.log > log4j.appender.file2.layout=org.apache.log4j.PatternLayout > log4j.appender.file2.layout.ConversionPattern=%m%n > > log4j.appender.XMLFileGateway=org.apache.log4j.RollingFileAppender > log4j.appender.XMLFileGateway.File=${WSG_HOME}/grizzlyGW2.xml > log4j.appender.XMLFileGateway.MaxFileSize=10000KB > log4j.appender.XMLFileGateway.MaxBackupIndex=10 > log4j.appender.XMLFileGateway.layout=org.apache.log4j.xml.XMLLayout > > log4j.rootLogger=off, XMLFile > log4j.logger.Gateway=warn, file2 > --- > > The following were all done without syncronizing log messages > as I mentioned trying before. The log4cxx code was based on > revision #572744, with the modifications I mentioned in > LOGCXX-191 (pre-"official" fix). As the modifications relate > to the syslog appender, and are relatively minor, I doubt > that they are influencing the results outlined below since > syslog is not involved in my tests. > > I tried forcing a log message in the same thread that > configured the logging system, immediately after the > configuration was done and before any threads started > pounding away. I did not note any change in behaviour, so I > went back to what I had before. > > > I simplified things down to a FileAppender appender with a > PatternLayout layout set to '%m%n': > log4j.rootLogger=off > log4j.logger.Gateway=debug, file2 > > The corrupt output was not visible in the log. > > > I readded the XMLFile appender to the root logger: > log4j.rootLogger=off, XMLFile > log4j.logger.Gateway=debug, file2 > > The corrupt output was visible in both the XML and plaintext logs. > > > I removed the simplified plaintext appender: > log4j.rootLogger=off, XMLFile > log4j.logger.Gateway=debug > > The corrupt output was not visible in the log. > > > I removed the simplified plaintext appender: > log4j.rootLogger=off, XMLFile > log4j.logger.Gateway=debug, XMLFileGateway > > The corrupt output was visible in both XML logs. > > > At this point, I'm starting to think it's got something to do > with either having multiple appenders on the go, or simply > something bad in the XML layout that garbles things for > subsequent appenders. > > > I tried two plaintext appenders. I reduced the 'file' > appender to a simple FileAppender with a pattern layout of '%m%n': > log4j.rootLogger=off, file > log4j.logger.Gateway=debug, file2 > > The corrupt output was visible in both plaintext logs. > > > At this point, it seems to me that the verdict is in: there's > a bug that corrupts data when multiple appenders (regardless > of type) are present. > > > For amusement, I tried combining appenders on a single logger: > log4j.rootLogger=off, file, file2 > log4j.logger.Gateway=debug > > The corrupt output was not visible in the logs. > > > For more amusement, I tried combining appenders on a single > logger other than the root logger: > log4j.rootLogger=off > log4j.logger.Gateway=debug, file, file2 > > The corrupt output was not visible in the logs. > > > Since I'm guessing the 'OFF' level isn't used all that > commonly, I tried enabling the root logger with the appenders > on separate loggers: > log4j.rootLogger=info, file > log4j.logger.Gateway=debug, file2 > > The corrupt output was visible in both plaintext logs. > > > These extra tests confim my ealier verdict as to the cause. > > I will open a bug based on this information. I will post the > bug number to the user group when I have it. Further > information on this problem will be logged there. > > Next steps: > -Verify that the problem still exists in a clean copy of > SVN-HEAD. (I expect it does.) > -Determine whether the core dumps I experienced when using > the syslog appender are related to this same issue. > > > --- > > Myles Bunbury, P.Eng., BASc. > Software Development Engineering Specialist > Web Services Internal Venture > Alcatel-Lucent > > Phone: (613) 784-4325 > Fax: (613) 784-8944 > Web: www.alcatel-lucent.com
