You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Remko Popma (JIRA)" <ji...@apache.org> on 2014/02/06 14:46:10 UTC
[jira] [Assigned] (LOG4J2-511) Referenced appenders on async
appender are shutdown prematurely
[ https://issues.apache.org/jira/browse/LOG4J2-511?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Remko Popma reassigned LOG4J2-511:
----------------------------------
Assignee: Remko Popma
> 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
> Assignee: Remko Popma
> Labels: async, shutdown
>
> 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: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org