[ https://issues.apache.org/jira/browse/LOG4J2-511?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13894638#comment-13894638 ]
Remko Popma commented on LOG4J2-511: ------------------------------------ James, if you verified that this solution works for you, please go ahead and close this issue. Of course if it did't work then don't hesitate to re-open it. > 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 > Fix For: 2.0-rc1 > > > 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-unsubscr...@logging.apache.org For additional commands, e-mail: log4j-dev-h...@logging.apache.org