Details
Description
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.
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
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
{
"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"
}
}
}
}
}
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:
"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" } } } ] } } ] } } ] }
Attachments
Issue Links
- duplicates
-
LOG4J2-392 Intermittent errors with appenders
-
- Resolved
-
- is related to
-
-
- Closed
-