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

          James Pretorius created issue -
          Hide
          Remko Popma added a comment -

          I haven't looked at this in detail yet but I suspect we need to stop appenders in a certain order. (Perhaps in two phases: first stop only the AsyncAppenders, then, after a short wait, loop again over all appenders and stop the remaining ones.)

          Show
          Remko Popma added a comment - I haven't looked at this in detail yet but I suspect we need to stop appenders in a certain order. (Perhaps in two phases: first stop only the AsyncAppenders, then, after a short wait, loop again over all appenders and stop the remaining ones.)
          Hide
          Andre Bogus added a comment -

          This may be related to LOG4J2-392

          Show
          Andre Bogus added a comment - This may be related to LOG4J2-392
          Hide
          James Pretorius added a comment -

          The below code (completely untested) would tie up with the config revision I was talking about earlier i.e. wrapping the referenced appenders in the async appender (much like a routing appender's referenced appenders).

          AsyncAppender.java
            public void stop()
            {
              super.stop();
              this.thread.shutdown();
              try {
                this.thread.join();
              } catch (InterruptedException ex) {
                LOGGER.warn("Interrupted while stopping AsyncAppender {}", new Object[] { getName() });
              }
              Map map = this.config.getAppenders();
              for (AppenderRef appenderRef : this.appenderRefs) {
                if (map.containsKey(appenderRef.getRef())) {
                  ((Appender)map.get(appenderRef.getRef())).stop();
                }
                else {
                  LOGGER.error("No appender named {} was configured", new Object[] { appenderRef });
                }
              }
            }
          
          log4j2.json snippet
            "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"
                                                      }
                                                  }
                                              }
                                          ]
                                      }
                                  }
                              ]
                          }
                      }
                  ]
              }
          
          Show
          James Pretorius added a comment - The below code (completely untested) would tie up with the config revision I was talking about earlier i.e. wrapping the referenced appenders in the async appender (much like a routing appender's referenced appenders). AsyncAppender.java public void stop() { super .stop(); this .thread.shutdown(); try { this .thread.join(); } catch (InterruptedException ex) { LOGGER.warn( "Interrupted while stopping AsyncAppender {}" , new Object [] { getName() }); } Map map = this .config.getAppenders(); for (AppenderRef appenderRef : this .appenderRefs) { if (map.containsKey(appenderRef.getRef())) { ((Appender)map.get(appenderRef.getRef())).stop(); } else { LOGGER.error( "No appender named {} was configured" , new Object [] { appenderRef }); } } } log4j2.json snippet "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" } } } ] } } ] } } ] }
          Hide
          Remko Popma added a comment -

          Andre, I agree that this issue and LOG4J2-392 may have the same underlying cause.

          James, I'm thinking to modify BaseConfiguration.stop() to ensure that all loggers and appenders are stopped in this order:

          1. AsyncLogger Disruptor thread (but this may not be possible yet until we have a solution for LOG4J2-493)
          2. AsyncLoggerConfig Disruptor thread(s)
          3. AsyncAppender(s)
          4. other appenders
          5. non-async LoggerConfigs
          6. root LoggerConfig (if non-async)
          Show
          Remko Popma added a comment - Andre, I agree that this issue and LOG4J2-392 may have the same underlying cause. James, I'm thinking to modify BaseConfiguration.stop() to ensure that all loggers and appenders are stopped in this order: AsyncLogger Disruptor thread (but this may not be possible yet until we have a solution for LOG4J2-493 ) AsyncLoggerConfig Disruptor thread(s) AsyncAppender(s) other appenders non-async LoggerConfigs root LoggerConfig (if non-async)
          Remko Popma made changes -
          Field Original Value New Value
          Assignee Remko Popma [ remkop@yahoo.com ]
          Hide
          Remko Popma added a comment -

          I've made the above-mentioned change to BaseConfiguration.stop() (all except stopping the singleton AsyncLogger Disruptor thread) in revision 1565254.

          Please verify and close.

          Show
          Remko Popma added a comment - I've made the above-mentioned change to BaseConfiguration.stop() (all except stopping the singleton AsyncLogger Disruptor thread) in revision 1565254. Please verify and close.
          Remko Popma made changes -
          Link This issue duplicates LOG4J2-392 [ LOG4J2-392 ]
          Remko Popma made changes -
          Status Open [ 1 ] Resolved [ 5 ]
          Fix Version/s 2.0-rc1 [ 12325011 ]
          Resolution Fixed [ 1 ]
          Hide
          James Pretorius added a comment -

          Thanks Remko

          Show
          James Pretorius added a comment - Thanks Remko
          Hide
          Remko Popma added a comment -

          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.

          Show
          Remko Popma added a comment - 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.
          James Pretorius made changes -
          Status Resolved [ 5 ] Closed [ 6 ]

            People

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

              Dates

              • Created:
                Updated:
                Resolved:

                Development