> -----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
