Log4j 2
  1. Log4j 2
  2. LOG4J2-511

Referenced appenders on async appender are shutdown prematurely

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta9
    • Fix Version/s: 2.0-rc1
    • Component/s: Appenders
    • Labels:
    • Environment:

      Windows 7 x64
      JRE1.6

      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.

      Log Entries

      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"
                                                  }
                                              }
                                          }
                                      ]
                                  }
                              }
                          ]
                      }
                  }
              ]
          }
      

        Issue Links

          Activity

            People

            • Assignee:
              Remko Popma
              Reporter:
              James Pretorius
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development