James Pretorius created LOG4J2-511:
--------------------------------------
Summary: Referenced appenders on async appender are shutdown
prematurely
Key: LOG4J2-511
URL: https://issues.apache.org/jira/browse/LOG4J2-511
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-beta9
Environment: Windows 7 x64
JRE1.6
Reporter: James Pretorius
It would appear that an appender referenced by an async appender can be
shutdown prior to the buffer being flushed in the async appender.
The following errors are logged at JVM shutdown and I've noticed the last log
entry destined for "Database Log Appender" doesn't make it into the table.
Removing the Database Async Appender and going directly to the Database Routing
Appender results in a clean exit.
{panel:title=Log Entries|borderStyle=dashed|borderColor=#ccc}2014-01-24
14:30:50,322 DEBUG Shutting down JDBCDatabaseManager jdbcManager\{
description=Database Log Appender, bufferSize=50,
connectionSource=driverManager\{ url=jdbc:<Removed>, username=<Removed>,
passwordHash=<Removed>\}, tableName=<Removed>, columns=[ \{ name=WorkerID,
layout=%map\{worker.id\}, literal=null, timestamp=false \}, \{ name=Queue,
layout=%map\{queue.id\}, literal=null, timestamp=false \}, \{ name=UnitID,
layout=%map\{unit.id\}, literal=null, timestamp=false \}, \{ name=UnitType,
layout=%map\{unit.type\}, literal=null, timestamp=false \}, \{
name=AuditSource, layout=%map\{audit.source\}, literal=null, timestamp=false
\}, \{ name=AuditCategory, layout=%map\{audit.category\}, literal=null,
timestamp=false \}, \{ name=AuditEvent, layout=%map\{audit.event\},
literal=null, timestamp=false \}, \{ name=AuditDetail,
layout=%map\{audit.detail\}, literal=null, timestamp=false \}, \{
name=AuditDateTime, layout=null, literal=null, timestamp=true \} ] \}
2014-01-24 14:30:52,994 ERROR Attempted to append to non-started appender
Database Routing Appender
2014-01-24 14:30:52,995 ERROR Attempted to append to non-started appender
Database Log Appender
2014-01-24 14:30:53,095 DEBUG Shutting down JDBCDatabaseManager jdbcManager\{
description=Database Queue Appender , bufferSize=0,
connectionSource=driverManager\{ url=jdbc:<Removed>, username=<Removed>,
passwordHash=<Removed> \}, tableName=<Removed>, columns=[ \{ name=WorkerID,
layout=%map\{worker.id\}, literal=null, timestamp=false \}, \{ name=Name,
layout=%map\{queue.id\}, literal=null, timestamp=false \}, \{ name=Threads,
layout=%map\{queue.threads\}, literal=null, timestamp=false \}, \{
name=CreateDateTime, layout=null, literal=null, timestamp=true \} ] \}
2014-01-24 14:30:53,193 DEBUG Shutting down JDBCDatabaseManager jdbcManager\{
description=Database Unit Appender, bufferSize=0,
connectionSource=driverManager\{ url=jdbc:<Removed>, username=<Removed>,
passwordHash=<Removed> \}, tableName=<Removed>, columns=[ \{ name=WorkerID,
layout=%map\{worker.id\}, literal=null, timestamp=false \}, \{ name=UnitID,
layout=%map\{unit.id\}, literal=null, timestamp=false \}, \{ name=UnitType,
layout=%map\{unit.type\}, literal=null, timestamp=false \}, \{ name=Queue,
layout=%map\{queue.id\}, literal=null, timestamp=false \}, \{
name=Configuration, layout=%map\{unit.config\}, literal=null, timestamp=false
\}, \{ name=CreateDateTime, layout=null, literal=null, timestamp=true \} ] \}
2014-01-24 14:30:53,279 DEBUG Shutting down JDBCDatabaseManager jdbcManager\{
description=Database Worker Appender, bufferSize=0,
connectionSource=driverManager\{ url=jdbc:<Removed>, username=<Removed>,
passwordHash=d<Removed> \}, tableName=<Removed>, columns=[ \{ name=WorkerID,
layout=%map\{worker.id\}, literal=null, timestamp=false \}, \{ name=ParentID,
layout=%map\{worker.parentId\}, literal=null, timestamp=false \}, \{ name=Path,
layout=%map\{worker.locationPath\}, literal=null, timestamp=false \}, \{
name=ExecutedBy, layout=%map\{worker.executedBy\}, literal=null,
timestamp=false \}, \{ name=Type, layout=%map\{application.name\},
literal=null, timestamp=false \}, \{ name=Version,
layout=%map\{application.version\}, literal=null, timestamp=false \}, \{
name=Name, layout=%map\{worker.name\}, literal=null, timestamp=false \}, \{
name=Configuration, layout=%map\{worker.config\}, literal=null, timestamp=false
\}, \{ name=CreateDateTime, layout=null, literal=null, timestamp=true \} ] \}
2014-01-24 14:30:53,367 DEBUG Shutting down RandomAccessFileManager
<Removed>.log
2014-01-24 14:30:53,368 DEBUG Shutting down OutputStreamManager SYSTEM_OUT
{panel}
Below is the config in use, there is a lot of noise in there - the main entries
we're interested in is the "Database Async Appender" and its subordinates
{code:javascript}
{
"configuration": {
"status": "trace",
"name": "Logging Config",
"verbose": "false",
"appenders": {
"appender": [
{
"type": "Console",
"name": "Console Appender",
"target": "SYSTEM_OUT",
"PatternLayout": {
"pattern": "%date{dd MMM yyyy HH:mm:ss,SSS}
%level{FATAL=Fatal, WARN=Warning, DEBUG=Debug, ERROR=Error, TRACE=Trace,
INFO=Info}: [%map{type} : %map{id}] - %map{audit.detail} %exception%n"
}
},
{
"type": "Routing",
"name": "File Routing Appender",
"MapFilter": {
"onMatch": "ACCEPT",
"onMisMatch": "DENY",
"keyValuePair": [
{
"key": "audit.file.enabled",
"value": "true"
}
]
},
"Routes": {
"pattern": "$${map:audit.file.enabled}",
"Route": [
{
"key": "true",
"RandomAccessFile": {
"name": "RandomAccessFile Appender",
"fileName": "${map:audit.filepath}",
"PatternLayout": {
"pattern": "%date{dd MMM yyyy
HH:mm:ss,SSS} %level{WARN=Warning, DEBUG=Debug, ERROR=Error, TRACE=Trace,
INFO=Info}: [%map{type} : %map{id}] - %map{audit.detail} %exception%n"
}
}
}
]
}
},
{
"type": "Routing",
"name": "SMTP Routing Appender",
"Routes": {
"pattern": "$${map:notification.smtp.enabled}",
"Route": [
{
"key": "true",
"SMTP": {
"name": "SMTP Appender",
"bufferSize": "500",
"to": "${map:notification.smtp.to}",
"from": "${map:notification.smtp.from}",
"smtpHost": "${map:notification.smtp.host}",
"smtpPort": "25",
"subject":
"${map:notification.smtp.subject}",
"PatternLayout": {
"pattern": "%map{audit.detail}"
},
"Filters": {
"MarkerFilter": {
"marker": "notification.smtp.send",
"onMatch": "ACCEPT",
"onMisMatch": "DENY"
}
}
}
}
]
}
},
{
"type": "Routing",
"name": "Database Routing Appender",
"MapFilter": {
"onMatch": "ACCEPT",
"onMisMatch": "DENY",
"keyValuePair": [
{
"key": "audit.database.enabled",
"value": "true"
}
]
},
"Routes": {
"pattern": "$${map:audit.database.table}",
"Route": [
{
"key": "WORKER",
"JDBC": {
"name": "Database Worker Appender",
"bufferSize": "0",
"DriverManager": {
"url":
"jdbc:sqlserver://${map:audit.database.server};instancename=${map:audit.database.instance};portNumber=${map:audit.database.port};${map:audit.database.security};database=${map:audit.database.database}"
},
"tableName": "<Removed>",
"Column": [
{
"name": "WorkerID",
"pattern": "%map{worker.id}"
},
{
"name": "ParentID",
"pattern": "%map{worker.parentId}"
},
{
"name": "Path",
"pattern":
"%map{worker.locationPath}"
},
{
"name": "ExecutedBy",
"pattern": "%map{worker.executedBy}"
},
{
"name": "Type",
"pattern": "%map{application.name}"
},
{
"name": "Version",
"pattern":
"%map{application.version}"
},
{
"name": "Name",
"pattern": "%map{worker.name}"
},
{
"name": "Configuration",
"pattern": "%map{worker.config}"
},
{
"name": "CreateDateTime",
"isEventTimestamp": "true"
}
]
}
},
{
"key": "QUEUE",
"JDBC": {
"name": "Database Queue Appender ",
"bufferSize": "0",
"DriverManager": {
"url":
"jdbc:sqlserver://${map:audit.database.server};instancename=${map:audit.database.instance};portNumber=${map:audit.database.port};${map:audit.database.security};database=${map:audit.database.database}"
},
"tableName": "<Removed>",
"Column": [
{
"name": "WorkerID",
"pattern": "%map{worker.id}"
},
{
"name": "Name",
"pattern": "%map{queue.id}"
},
{
"name": "Threads",
"pattern": "%map{queue.threads}"
},
{
"name": "CreateDateTime",
"isEventTimestamp": "true"
}
]
}
},
{
"key": "UNIT",
"JDBC": {
"name": "Database Unit Appender",
"bufferSize": "0",
"DriverManager": {
"url":
"jdbc:sqlserver://${map:audit.database.server};instancename=${map:audit.database.instance};portNumber=${map:audit.database.port};${map:audit.database.security};database=${map:audit.database.database}"
},
"tableName": "<Removed>",
"Column": [
{
"name": "WorkerID",
"pattern": "%map{worker.id}"
},
{
"name": "UnitID",
"pattern": "%map{unit.id}"
},
{
"name": "UnitType",
"pattern": "%map{unit.type}"
},
{
"name": "Queue",
"pattern": "%map{queue.id}"
},
{
"name": "Configuration",
"pattern": "%map{unit.config}"
},
{
"name": "CreateDateTime",
"isEventTimestamp": "true"
}
]
}
},
{
"key": "LOG",
"JDBC": {
"name": "Database Log Appender",
"bufferSize": "50",
"DriverManager": {
"url":
"jdbc:sqlserver://${map:audit.database.server};instancename=${map:audit.database.instance};portNumber=${map:audit.database.port};${map:audit.database.security};database=${map:audit.database.database}"
},
"tableName": "<Removed>",
"Column": [
{
"name": "WorkerID",
"pattern": "%map{worker.id}"
},
{
"name": "Queue",
"pattern": "%map{queue.id}"
},
{
"name": "UnitID",
"pattern": "%map{unit.id}"
},
{
"name": "UnitType",
"pattern": "%map{unit.type}"
},
{
"name": "AuditSource",
"pattern": "%map{audit.source}"
},
{
"name": "AuditCategory",
"pattern": "%map{audit.category}"
},
{
"name": "AuditEvent",
"pattern": "%map{audit.event}"
},
{
"name": "AuditDetail",
"pattern": "%map{audit.detail}"
},
{
"name": "AuditDateTime",
"isEventTimestamp": "true"
}
]
}
}
]
}
},
{
"type": "Async",
"name": "File Async Appender",
"errorRef": "Console Appender",
"AppenderRef": {
"ref": "File Routing Appender"
}
},
{
"type": "Async",
"name": "Database Async Appender",
"errorRef": "Console Appender",
"AppenderRef": {
"ref": "Database Routing Appender"
}
}
]
},
"loggers": {
"logger": [
{
"name": "boa",
"additivity": "true",
"level": "debug",
"AppenderRef": {
"ref": "Database Async Appender"
}
},
{
"name": "dm",
"additivity": "true",
"level": "debug",
"AppenderRef": {
"ref": "Database Async Appender"
}
},
{
"name": "boa.scheduler.logger",
"additivity": "false",
"level": "info",
"AppenderRef": {
"ref": "Database Async Appender",
"Filters": {
"MarkerFilter": {
"marker": "database.summary.update",
"onMatch": "ACCEPT",
"onMisMatch": "DENY"
}
}
}
},
{
"name": "boa.notification.EmailNotifier",
"level": "info",
"additivity": "false",
"AppenderRef": {
"ref": "SMTP Routing Appender",
"MapFilter": {
"onMatch": "ACCEPT",
"onMisMatch": "DENY",
"keyValuePair": [
{
"key": "notification.smtp.enabled",
"value": "true"
}
]
}
}
}
],
"root": {
"AppenderRef": {
"ref": "Console Appender",
"level": "debug"
},
"appender-ref": {
"ref": "File Async Appender",
"level": "info"
}
}
}
}
}
{code}
Possibly, much like a RoutingAppender, you could wrap the appenders the
AsyncAppender refers to and then change the stop() method on the AsyncAppender
to empty the queue before sending a stop signal to the referenced appenders.
Sample config entry below to help explain my 2 cents above:
{code:javascript}
"appenders": {
"appender": [
{
"type": "Console",
"name": "Console Appender",
"target": "SYSTEM_OUT",
"PatternLayout": {
"pattern": "%date{dd MMM yyyy HH:mm:ss,SSS}
%level{FATAL=Fatal, WARN=Warning, DEBUG=Debug, ERROR=Error, TRACE=Trace,
INFO=Info}: [%map{type} : %map{id}] - %map{audit.detail} %exception%n"
}
},
{
"type": "Async",
"name": "File Async Appender",
"errorRef": "Console Appender",
"appenders": {
"appender": [
{
"type": "Routing",
"name": "File Routing Appender",
"MapFilter": {
"onMatch": "ACCEPT",
"onMisMatch": "DENY",
"keyValuePair": [
{
"key": "audit.file.enabled",
"value": "true"
}
]
},
"Routes": {
"pattern": "$${map:audit.file.enabled}",
"Route": [
{
"key": "true",
"RandomAccessFile": {
"name": "RandomAccessFile Appender",
"fileName": "${map:audit.filepath}",
"PatternLayout": {
"pattern": "%date{dd MMM yyyy
HH:mm:ss,SSS} %level{WARN=Warning, DEBUG=Debug, ERROR=Error, TRACE=Trace,
INFO=Info}: [%map{type} : %map{id}] - %map{audit.detail} %exception%n"
}
}
}
]
}
}
]
}
}
]
}
{code}
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
