log4j:ERROR Attempted to append to closed appender named [system]

[Elie Wildman <El...@nmss.com>]

During load testing we are seeing the following error appear from time to 
time:

log4j:ERROR Attempted to append to closed appender named [system]

We are using Orion app server.

We have a grinder script which runs a load test on our application.  This 
error does not seem to appear during regular  use.

When I turned on debugging, I noticed some strange behavoir in the output. 
Basically, I could watch the config file be parsed. Upon completion 
"Finished configuring" would appear. However sometimes the output seems to 
become mixed. I see appenders appearing multiple times or not at all, and 
"Finished Configuring" never appeared. This was always followed shortly by 
the above error appearing.

Any help is much appreciated.


Below is our configuration file and a snippet of a log file catching 
stdout and stderr from orion.

# Set root logger level to DEBUG and its only appender to System.
log4j.rootLogger=WARN, BaseSystem

log4j.appender.BaseSystem=org.apache.log4j.DailyRollingFileAppender
log4j.appender.BaseSystem.File=/opt/hs-data/raid/log/sam/system.log
log4j.appender.BaseSystem.DatePattern='.'yyyy-MM-dd
log4j.appender.BaseSystem.layout=org.apache.log4j.PatternLayout
log4j.appender.BaseSystem.layout.ConversionPattern=%d{ISO8601};%p;%m%n

# System Log File
log4j.logger.SystemLog=INFO, System
log4j.additivity.SystemLog=false
log4j.appender.System=org.apache.log4j.DailyRollingFileAppender
log4j.appender.System.File=/opt/hs-data/raid/log/sam/sam_system.log
log4j.appender.System.DatePattern='.'yyyy-MM-dd
log4j.appender.System.layout=org.apache.log4j.PatternLayout
log4j.appender.System.layout.ConversionPattern=%d{ISO8601};%p;%m%n

# Subscriber Log File
log4j.logger.SubscriberLog=EVENT, Subscriber, System
log4j.additivity.SubscriberLog=false
log4j.appender.Subscriber=org.apache.log4j.DailyRollingFileAppender
log4j.appender.Subscriber.File=/opt/hs-data/raid/log/sam/subscriber.log
log4j.appender.Subscriber.DatePattern='.'yyyy-MM-dd
log4j.appender.Subscriber.layout=org.apache.log4j.PatternLayout
log4j.appender.Subscriber.layout.ConversionPattern=%d{ISO8601};%p;%m%n

# Authentication Log File
log4j.logger.AuthenticationLog=EVENT, Authentication, System
log4j.additivity.AuthenticationLog=false
log4j.appender.Authentication=org.apache.log4j.DailyRollingFileAppender
log4j.appender.Authentication.File=/opt/hs-data/raid/log/sam/auth.log
log4j.appender.Authentication.DatePattern='.'yyyy-MM-dd
log4j.appender.Authentication.layout=org.apache.log4j.PatternLayout
log4j.appender.Authentication.layout.ConversionPattern=%d{ISO8601};%p;%m%n

# Administrative Log File
log4j.logger.AdministrativeLog=EVENT, Administrative
log4j.additivity.AdministrativeLog=false
log4j.appender.Administrative=org.apache.log4j.DailyRollingFileAppender
log4j.appender.Administrative.File=/opt/hs-data/raid/log/sam/admin.log
log4j.appender.Administrative.DatePattern='.'yyyy-MM-dd
log4j.appender.Administrative.layout=org.apache.log4j.PatternLayout
log4j.appender.Administrative.layout.ConversionPattern=%d{ISO8601};%p;%m%n

# A1 is set to be a ConsoleAppender.
log4j.appender.A1=org.apache.log4j.ConsoleAppender
# A1 uses PatternLayout.
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
#log4j.appender.A1.layout.ConversionPattern=%-4r;%t;%-5p;%c;%x;%m%n
log4j.appender.A1.layout.ConversionPattern=%d{ISO8601};%p;%m%n

orion output follows....

Orion/2.0.2 initialized
log4j: Parsing for [root] with value=[WARN, BaseSystem].
log4j: Level token is [WARN].
log4j: Category root set to WARN
log4j: Parsing appender named "BaseSystem".
log4j: Parsing layout options for "BaseSystem".
log4j: Setting property [conversionPattern] to [%d{ISO8601};%p;%m%n].
log4j: End of parsing for "BaseSystem".
log4j: Setting property [file] to [/opt/hs-data/raid/log/sam/system.log].
log4j: Setting property [datePattern] to ['.'yyyy-MM-dd].
log4j: setFile called: /opt/hs-data/raid/log/sam/system.log, true
log4j: setFile ended
log4j: Appender [BaseSystem] to be rolled at midnight.
log4j: Parsed "BaseSystem" options.
log4j: Parsing for [SubscriberLog] with value=[EVENT, Subscriber, System].
log4j: Level token is [EVENT].
log4j: Category SubscriberLog set to DEBUG
log4j: Parsing appender named "Subscriber".
log4j: Parsing layout options for "Subscriber".
log4j: Setting property [conversionPattern] to [%d{ISO8601};%p;%m%n].
log4j: End of parsing for "Subscriber".
log4j: Setting property [file] to 
[/opt/hs-data/raid/log/sam/subscriber.log].
log4j: Setting property [datePattern] to ['.'yyyy-MM-dd].
log4j: setFile called: /opt/hs-data/raid/log/sam/subscriber.log, true
log4j: setFile ended
log4j: Appender [Subscriber] to be rolled at midnight.
log4j: Parsed "Subscriber" options.
log4j: Parsing appender named "System".
log4j: Parsing layout options for "System".
log4j: Setting property [conversionPattern] to [%d{ISO8601};%p;%m%n].
log4j: End of parsing for "System".
log4j: Setting property [file] to 
[/opt/hs-data/raid/log/sam/sam_system.log].
log4j: Setting property [datePattern] to ['.'yyyy-MM-dd].
log4j: setFile called: /opt/hs-data/raid/log/sam/sam_system.log, true
log4j: setFile ended
log4j: Appender [System] to be rolled at midnight.
log4j: Parsed "System" options.
log4j: Handling log4j.additivity.SubscriberLog=[false]
log4j: Setting additivity for "SubscriberLog" to false
log4j: Parsing for [SystemLog] with value=[INFO, System].
log4j: Level token is [INFO].
log4j: Category SystemLog set to INFO
log4j: Parsing appender named "System".
log4j: Appender "System" was already parsed.
log4j: Handling log4j.additivity.SystemLog=[false]
log4j: Setting additivity for "SystemLog" to false
log4j: Parsing for [AuthenticationLog] with value=[EVENT, Authentication, 
System].
log4j: Level token is [EVENT].
log4j: Category AuthenticationLog set to DEBUG
log4j: Parsing appender named "Authentication".
log4j: Parsing layout options for "Authentication".
log4j: Setting property [conversionPattern] to [%d{ISO8601};%p;%m%n].
log4j: End of parsing for "Authentication".
log4j: Setting property [datePattern] to ['.'yyyy-MM-dd].
log4j: Setting property [file] to [/opt/hs-data/raid/log/sam/auth.log].
log4j: setFile called: /opt/hs-data/raid/log/sam/auth.log, true
log4j: setFile ended
log4j: Appender [Authentication] to be rolled at midnight.
log4j: Parsed "Authentication" options.
log4j: Parsing appender named "System".
log4j: Appender "System" was already parsed.
log4j: Handling log4j.additivity.AuthenticationLog=[false]
log4j: Setting additivity for "AuthenticationLog" to false
log4j: Parsing for [AdministrativeLog] with value=[EVENT, Administrative].
log4j: Level token is [EVENT].
log4j: Category AdministrativeLog set to DEBUG
log4j: Parsing appender named "Administrative".
log4j: Parsing layout options for "Administrative".
log4j: Setting property [conversionPattern] to [%d{ISO8601};%p;%m%n].
log4j: End of parsing for "Administrative".
log4j: Setting property [datePattern] to ['.'yyyy-MM-dd].
log4j: Setting property [file] to [/opt/hs-data/raid/log/sam/admin.log].
log4j: setFile called: /opt/hs-data/raid/log/sam/admin.log, true
log4j: setFile ended
log4j: Appender [Administrative] to be rolled at midnight.
log4j: Parsed "Administrative" options.
log4j: Handling log4j.additivity.AdministrativeLog=[false]
log4j: Setting additivity for "AdministrativeLog" to false
log4j: Finished configuring.

---------------------------------------------------------
bad parse
----------------------------------------------------------
log4j: Parsing for [root] with value=[WARN, BaseSystem].
log4j: Level token is [WARN].
log4j: Category root set to WARN
log4j: Parsing appender named "BaseSystem".
log4j: Parsing layout options for "BaseSystem".
log4j: Setting property [conversionPattern] to [%d{ISO8601};%p;%m%n].
log4j: End of parsing for "BaseSystem".
log4j: Setting property [file] to [/opt/hs-data/raid/log/sam/system.log].
log4j: Setting property [datePattern] to ['.'yyyy-MM-dd].
log4j: setFile called: /opt/hs-data/raid/log/sam/system.log, true
log4j: setFile ended
log4j: Appender [BaseSystem] to be rolled at midnight.
log4j: Parsed "BaseSystem" options.
log4j: Parsing for [SubscriberLog] with value=[EVENT, Subscriber, System].
log4j: Level token is [EVENT].
log4j: Category SubscriberLog set to DEBUG
log4j: Parsing appender named "Subscriber".
log4j: Parsing layout options for "Subscriber".
log4j: Setting property [conversionPattern] to [%d{ISO8601};%p;%m%n].
log4j: End of parsing for "Subscriber".
log4j: Setting property [file] to 
[/opt/hs-data/raid/log/sam/subscriber.log].
log4j: Setting property [datePattern] to ['.'yyyy-MM-dd].
log4j: setFile called: /opt/hs-data/raid/log/sam/subscriber.log, true
log4j: setFile ended
log4j: Appender [Subscriber] to be rolled at midnight.
log4j: Parsed "Subscriber" options.
log4j: Parsing appender named "System".
log4j: Parsing layout options for "System".
log4j: Setting property [conversionPattern] to [%d{ISO8601};%p;%m%n].
log4j: End of parsing for "System".
log4j: Setting property [file] to 
[/opt/hs-data/raid/log/sam/sam_system.log].
log4j: Setting property [datePattern] to ['.'yyyy-MM-dd].
log4j: setFile called: /opt/hs-data/raid/log/sam/sam_system.log, true
log4j: setFile ended
log4j: Appender [System] to be rolled at midnight.
log4j: Parsed "System" options.
log4j: Handling log4j.additivity.SubscriberLog=[false]
log4j: Parsing for [root] with value=[WARN, BaseSystem].
log4j: Level token is [WARN].
log4j: Category root set to WARN
log4j: Parsing appender named "BaseSystem".
log4j: Parsing layout options for "BaseSystem".
log4j: Setting property [conversionPattern] to [%d{ISO8601};%p;%m%n].
log4j: End of parsing for "BaseSystem".
log4j: Setting property [file] to [/opt/hs-data/raid/log/sam/system.log].
log4j: Setting property [datePattern] to ['.'yyyy-MM-dd].
log4j: setFile called: /opt/hs-data/raid/log/sam/system.log, true
log4j: setFile ended
log4j: Appender [BaseSystem] to be rolled at midnight.
log4j: Parsed "BaseSystem" options.
log4j: Setting additivity for "SubscriberLog" to false
log4j: Parsing for [SubscriberLog] with value=[EVENT, Subscriber, System].
log4j: Level token is [EVENT].
log4j: Category SubscriberLog set to DEBUG
log4j: Parsing appender named "Subscriber".
log4j: Parsing layout options for "Subscriber".
log4j: Setting property [conversionPattern] to [%d{ISO8601};%p;%m%n].
log4j: End of parsing for "Subscriber".
log4j: Setting property [file] to 
[/opt/hs-data/raid/log/sam/subscriber.log].
log4j: Setting property [datePattern] to ['.'yyyy-MM-dd].
log4j: setFile called: /opt/hs-data/raid/log/sam/subscriber.log, true
log4j: setFile ended
log4j: Appender [Subscriber] to be rolled at midnight.
log4j: Parsed "Subscriber" options.
log4j: Parsing appender named "System".
log4j: Parsing layout options for "System".
log4j: Setting property [conversionPattern] to [%d{ISO8601};%p;%m%n].
log4j: End of parsing for "System".
log4j: Setting property [file] to 
[/opt/hs-data/raid/log/sam/sam_system.log].
log4j: Setting property [datePattern] to ['.'yyyy-MM-dd].
log4j: setFile called: /opt/hs-data/raid/log/sam/sam_system.log, true
log4j: setFile ended
log4j: Appender [System] to be rolled at midnight.
log4j: Parsed "System" options.
log4j: Handling log4j.additivity.SubscriberLog=[false]
log4j: Setting additivity for "SubscriberLog" to false
log4j: Parsing for [SystemLog] with value=[INFO, System].
log4j: Level token is [INFO].
log4j: Category SystemLog set to INFO
log4j: Parsing appender named "System".
log4j: Appender "System" was already parsed.
log4j: Handling log4j.additivity.SystemLog=[false]
log4j: Setting additivity for "SystemLog" to false
log4j: Parsing for [AuthenticationLog] with value=[EVENT, Authentication, 
System].
log4j: Level token is [EVENT].
log4j: Category AuthenticationLog set to DEBUG
log4j: Parsing appender named "Authentication".
log4j: Parsing layout options for "Authentication".
log4j: Setting property [conversionPattern] to [%d{ISO8601};%p;%m%n].
log4j: End of parsing for "Authentication".
log4j: Setting property [datePattern] to ['.'yyyy-MM-dd].
log4j: Setting property [file] to [/opt/hs-data/raid/log/sam/auth.log].
log4j: setFile called: /opt/hs-data/raid/log/sam/auth.log, true
log4j: setFile ended
log4j: Appender [Authentication] to be rolled at midnight.
log4j: Parsed "Authentication" options.
log4j: Parsing appender named "System".
log4j: Appender "System" was already parsed.
log4j: Handling log4j.additivity.AuthenticationLog=[false]
log4j: Setting additivity for "AuthenticationLog" to false
log4j: Parsing for [AdministrativeLog] with value=[EVENT, Administrative].
log4j: Level token is [EVENT].
log4j: Category AdministrativeLog set to DEBUG
log4j: Parsing appender named "Administrative".
log4j: Parsing layout options for "Administrative".
log4j: Setting property [conversionPattern] to [%d{ISO8601};%p;%m%n].
log4j: End of parsing for "Administrative".
log4j: Setting property [datePattern] to ['.'yyyy-MM-dd].
log4j: Setting property [file] to [/opt/hs-data/raid/log/sam/admin.log].
log4j: setFile called: /opt/hs-data/raid/log/sam/admin.log, true
log4j: setFile ended
log4j: Appender [Administrative] to be rolled at midnight.
log4j: Parsed "Administrative" options.
log4j: Handling log4j.additivity.AdministrativeLog=[false]
log4j: Setting additivity for "AdministrativeLog" to false
log4j: Finished configuring.
log4j: Parsing for [SystemLog] with value=[INFO, System].
log4j: Level token is [INFO].
log4j: Category SystemLog set to INFO
log4j: Parsing appender named "System".
log4j: Appender "System" was already parsed.
log4j: Handling log4j.additivity.SystemLog=[false]
log4j: Setting additivity for "SystemLog" to false
log4j:ERROR Attempted to append to closed appender named [System].