Page History

...

This section lists the Bugs and Feature Requests that also need to be addressed as part of this overall effort:

• • 2.
1 #47722
• • 1 #47722 G0 Configurable option of appending to log file or creating new file
  • 2.
2 #50483
• • 2 #50483 F0 log file size does not account for user/application logging
  • 2.
3 #51111
• • 3 #51111 F0 Web application (Tomcat) logging goes to gemfire log
  • 2.
4 #47910
• • 4 #47910 R2 <Regression> ConcurrentModificationException in createLogWriter during locator startup.
  • 2.
5 #51207
• • 5 #51207 F2 Improve logging configuration for libraries
  • 2.
6 #40414
• • 6 #40414 R3 i18n changes (toLocalizedString) causes ports, ids to be formatted with commas
  • 2.
7 #43396
• • 7 #43396 R3 Remove dead messages from LocalizedStrings and fix any obvious typos
  • 2.
8 #51197
• • 8 #51197 C2 A log file name with no '.log' extension causes the gfxd connect to fail after the first time
  • 2.
9 #45796
• • 9 #45796 F3 Feature Request:Adding a Functionality to Make Logging Custom Filter Available in Gemfire

Introducing Log4J 2 as our underlying logging library satisfies 2.1. #47722 and 2.5. #51207. In addition it makes 2.4. #47910 go away.

...

TODO: verify that Log4J 2 fulfills all of #48796 as well. Log4J 2 certainly provides robust filtering but does it support java.util.logging.Filters also?

3 Related Documents

• Logging Thoughts
• Logging Backlog (do we have a better tool than a spreadsheet?)

4 Terminology

• FQCN -- Fully-qualified class name which is used as the name of the logger that is declared at the top of the class or the class’s root ancestor. Example:

...

Log4J 2 is a complete overhaul of Log4J incorporating the best changes introduced by SLF4J. It separates the library into two primary jars: log4j2-api and log4j2-core. Log4J 2 provides a much more versatile library than SLF4J and is much more customizable. Our selection is driven by the need to customize logging and its reported performance characteristics. We are not advocating async loggers which are present in some form in both Log4J 2 and LogBack. Log4J 2 improves performance dramatically over Log4J 1.x as well as SLF4J. For reasons of customization we had to select Log4J 2 and its performance helped solidify that decision. For reasons of customization we had to select Log4J 2 and its performance helped solidify that decision.

Note that Log4J2 was chosen for the logging backend instead of LogBack because Log4J2 processes disabled DEBUG statements faster at INFO level than LogBack does. When comparing logging throughput at DEBUG level, LogBack was slightly faster, but when comparing overall impact to application performance Log4J2 was faster. In other words, GemFire using Log4J2 out-performed GemFire using LogBack at INFO level or above. Since INFO level or above is expected for production systems, Log4J2 was chosen over SLF4J and LogBack. GemFire code base will use Log4J2 API while the custom logging appenders for LogWriter-style rolling and Alerts will use Log4J2 Core.

For more information, please see The Logging Olympics – A Race Between Today’s Top 5 Java Logging Frameworks

...

6.3 Log statements should be updated to use Log4J 2’s parameterization:

if (log.isDebugEnabled()) {   
  log.debug("Hi, " + string1 + " " + string2);
}

...

 Becomes:

...

log.debug("Hi, {} {}", string1, string2);

...

See 7.6. for more details.

...

6.6 By default the new Log4J 2 logging will be enabled for logging to stdout. The standard way of configuring Log4J 2 is with a log4j2.xml and we won’t change that. GemFire will include a copy of its default log4j2.xml configuration of Log4J 2 in GEMFIRE/defaultConfigs with a PatternLayout that makes the log message format the same as what LogWriter produces. The com.gemstone.gemfire.internal.logging.log4j package will include a copy of that same log4j2.xml as a resource to use if no other configuration is available. If user has already configured Log4J 2 then the user’s configuration will be used. If it has not been configured then the search order of precedence will be a) specified by user with the standard Log4J 2 system property, b) current working directory of the GemFire process, c) GEMFIRE/defaultConfigs (KIRK: delete this from search path but leave it there as an example), d) com.gemstone.gemfire.logging.internal.log4j.log4j2-default.xml resource inside the gemfire.jar.

...

<Logger name="com.gemstone.gemfire" level="INFO" additivity="false">
  <AppenderRef ref="STDOUT"/>
</Logger>

...

Example 1 has simple parameters that do not involve a costly method call: 

if (log.isDebugEnabled()) {   
  log.debug("Hi, " + string1 + " " + string2);
}

...

Example 2 has a parameter that involves making a costly call:

if (log.isDebugEnabled()) {   
  log.debug("Hi, " + obj.getSynchronizedData());
}

Becomes the following because without the conditional getSynchronizedData would incur a serial performance hit even when debug is not enabled:

if (log.isDebugEnabled()) { // protects against making costly call
  log.debug("Hi, {}", obj.getSynchronizedData());
}

Note, the Log4J 2 implementation for handling parameters is highly optimized and much faster than using java.util.Formatter or java.text.MessageFormat.

7.7 Component Markers

Markers can extend other Markers. They can also be used in multiple classes and multiple packages. This provides an easy, fast way of filtering that isn’t limited to FQCN. They can also be used to trigger custom behavior in appenders.

We would remove ComponentLogWriter and replace it with usage of Markers.

Example of defining Markers that have a hierarchical relationship:

static final Marker SQL_MARKER = MarkerManager.getMarker("SQL");
static final Marker UPDATE_MARKER = MarkerManager.getMarker("SQL_UPDATE").addParents(SQL_MARKER);
static final Marker QUERY_MARKER = MarkerManager.getMarker("SQL_QUERY").addParents(SQL_MARKER);

TODO: Proposed Markers (we should refine this list and add any that are missing):

• • • DLS or DISTRIBUTED_LOCK_SERVICE

...

• • • PERSISTENCE

...

• • • MEMBERSHIP or GMS

...

• • • CLIENT

...

• • • SERVER

• • • REGION

TODO: The above proposed Markers are much more coarse-grained than the example. Maybe we should attempt to be more fine-grained as well. This may require help from people who are the domain experts of various code areas.

Note that a Marker can have multiple parent Markers. Example:

static final Marker DLS_MESSAGE_MARKER = MarkerManager.getMarker("DLS_MESSAGE").addParents(MESSAGE_MARKER, DLS_MARKER);

See also:

• • http://stackoverflow.com/questions/16813032/what-is-markers-in-java-logging-frameworks-and-that-is-a-reason-to-use-them

...

• • http://stackoverflow.com/questions/4165558/best-practices-for-using-markers-in-slf4j-logback

7.8 LogWriterAppender

The LogWriterAppender is not registered by default. It is registered internally (separately from log4j2.xml) only when a “log-file” has been specified. It then uses the deprecated “log-” logging gemfire properties for its configuration. It will roll and purge files just as the ManagerLogWriter does in previous releases. Because it’s plugged into Log4J 2, it is affected by Logger log levels based on FQCN, filters and Markers. Thus a user could continue to use the deprecated legacy logging, but still benefit from better debugging with the features of Log4J 2.

7.9 SecurityLogAppender 

We’d like to use a SECURITY Marker on the existing log statements that go to the SecurityLogWriter. The LogWriterAppender could potentially be registered a second time using the “security-log-” configuration and filter out anything that isn’t using the SECURITY Marker or a dedicated SecurityLogWriterAppender depending on what we find.

A SecurityLogWriterAppender or LogWriterAppender would be registered internally without relying on log4j2.xml.

7.10 Additional Product Changes

7.10.1 Removal of OSProcess.redirectCOutput. We will remove the default use of this. The LogWriterAppender will not have stdout and stderr redirected to. Should we retain this and only enable it based on an undocumented system property? (

...

probably not) This is primarily to satisfy:

• • #51111 F0 Web application (Tomcat) logging goes to gemfire log

• • #50483 F0 log file size does not account for user/application logging

8 Feature Interactions

8.1 GFSH

8.1.1 Existing commands remain relatively unchanged for now. The commands for starting a server or locator will auto-configure the “log-file” (based on member name) which enables the LogWriterAppender. This should be revisited and revised to provide richer support for Log4J 2 in the future. Should we automatically place a default log4j2.xml in the directory of the server or locator being started? This would be the easiest way to change the launchers to use Log4J 2 directly instead of through the deprecated “log-” properties for LogWriterAppender.

8.1.2 The “alter runtime” command currently allows “log-level” to be altered at runtime. This will remain unchanged and provide the control for the logging level of the LogWriterAppender. We can change this to set the overall log level for com.gemstone.gemfire in Log4J 2 as well as setting the log-level on the LogWriterAppender. Note that the Log4J 2 MBean allows extensive configuration at runtime as well, so we could tie into that as well.

8.1.3 Follow-up work should include defining a new command “alter logging” with ability to manipulate levels per FQCN category, configuration of Markers, filters, etc. This could manipulate the log4j2.xml in that member’s directory or possibly the Log4J 2 MBean.

8.2 JMX

8.2.1 Log4J 2 exposes its own MBeans. I’m inclined to leave it at that and not attempt to federate or rollup these in any way.

8.3 Pulse

8.3.1 Needs some further investigation, but I suspect that no changes are needed unless we are somehow displaying information about the location of log files that members are writing to.

8.4 Old DEBUG and VERBOSE system properties, etc

8.4.1 Any of these that were not exposed to customers or documented should simply be deleted and replaced by proper usage of FQCN logger names and Markers. We might also make a case-by-case decision about whether or not it was a documented “internal” user-exposed interface that is allowed to go away without deprecation. That would be the easiest and preferred approach.

8.5 Statistics archive file rolling and purging

8.5.1 The LogWriterAppender will rename rolling files and purge them in the same way that Statistics archive files are handled. If this consistency is desired, then the user may wish to continue using the LogWriterAppender until we can come up with future changes to Statistics that allows us to roll and purge those files consistently with the way RollingFileAppender works. Part of that effort could include synchronized triggering of the rolling which users and internal engineers have asked for. See also #42263 stat archive rolling should use a stable file name for the most recent archive just like logging does now which indicates that Statistics archive rolling may not currently be consistent or bug free.

9 Performance Requirements

9.1 Logging needs to have a negligible performance impact on GemFire when log levels are turned up to info or above and no special filtering is in use.

9.2 Investigate custom RollingFileAppender which is not multi-process safe but performs better (without synchronization locking). This might be a good way to increase performance when a customer is using RollingFileAppender. It would be a customized Appender implementation with a name something like FastRollingFileAppender.

9.3 We have micro-benchmarks showing the differences between LogWriter, Logger/Log4J2, Logger/LogBack, and LogWriterLogger (adapts LogWriter calls to Logger/Log4J2). This includes log statements and isEnabled calls for log levels that are enabled as well as disabled. The results show that Log4J 2’s FileAppender is faster at logging enabled messages than LogWriter but slower than LogWriter at processing messages for a disabled log level.

9.4 We have identified one performance problem so far in Log4J 2 which is caused by the way FileConfigurationMonitor is implemented. If <Configuration> attribute “monitorInterval” is specified in log4j2.xml then a FileConfigurationMonitor is used inline with every log statement or isEnabled check to see if the config has changed. This should instead be done by a background thread and we have found a way to provide our own implementation of this class by setting a Log4J 2 system property. It would be a good idea to also submit this to the Log4J 2 project after we’ve completed implementing and testing it.

9.5 Smoke perf tests for DLS (which has a very large number of fine level log statements) after converting the DLS package to use Log4J 2 Logger instead of our temporary LogWriter adapter shows that the performance is approximately the same as it is on cedar when the log level is configured at info level.

9.6 Excessive isFineEnabled() calls should be replaced by one such call stored in a boolean variable that is then used to control logging elsewhere in the method. This can be used to dramatically improve the performance impact of logging in any class that has substantial trace and debug calls.

10 Testing

10.1 Test use of defaults (logging goes to stdout)

10.2 Test recommended usage (process in dedicated subdir with log4j2.xml altered to specify a log file)

10.3 Test deprecated usage of LogWriter properties (“log-file” specified in gemfire.properties)

10.4 Test deprecated usage of LogWriter properties (“log-file” specified in gemfire.properties) alongside Log4J 2 (log4j2.xml altered to specify a log file) -- documentation will advise NOT doing this but we need to know what it does

10.5 Test deprecated usage of LogWriter properties alongside Log4J 2, such that both are configured to log to same file (yikes!) -- this is probably a product-breaking situation that we need to handle gracefully

10.6 Test filtering based on Markers and specifying levels by FQCN Category.

10.7 Integration testing within Apache, tcServer, CloudFoundry(?). Include use of Log4J 1.x, Log4J 2 and/or LogBack backends.

10.7.1 Test environment using Log4J 1.x or SLF4J as its logger API, while also running GemFire in either a) using both log4j-api-2.0.2.jar with log4j-core-2.0.2.jar, or b) using log4j-api-2.0.2.jar with a bridge allowing GemFire logging backend to be something else (warning: none of our formatting or optimizations will work!)

10.7.2 Test environment using Log4J 1.x or SLF4J as its logger API, GemFire using log4j-api-2.0.2.jar and then using log4j-core-2.0.2.jar with additional bridge jars in order to use Log4J 2 as the backend for everything (optimal for GemFire, should be ok for Tomcat and other products)

11 Use Cases

11.1 Logging with log4j2.xml-configured FileAppender only (Recommended)

11.2 Logging with gemfire.properties-configured LogWriterAppender only (Deprecated)

11.3 Logging with both log4j2.xml-configured FileAppender and gemfire.properties-configured LogWriterAppender (Not Recommended)

This is redundant and there should not be any valid reason why a user would need to do this. Documentation should discourage user from doing this. We could investigate doing something in code to prevent startup. Maybe we could just log a warning if both types of appenders are logging to files.

11.3.1 Note: a user may want to define multiple FileAppenders in order to log different components, layers, third-party services to their own dedicated log files. But that’s different and is an advanced use of Log4J 2 (and should NOT involve LogWriterAppender) that we don’t need to specifically test for. We may, however, wish to document how to configure log4j2.xml such that GemFire logs to a dedicated log file separate from the application or environment.

11.3.2 Note: We are currently running DUnit in Eclipse such that Dan’s DUnitLauncher is configure log4j2 to direct all JVMs to write to a single log file, and this seems to be working well.

11.4 Use of GemFire with its new logging within an application that is already using Log4J 1.x, SLF4J and/or Log4J 2. Two variations here: a) GemFire using Log4J 2 for its backend while other code is using other backends, b) GemFire using LogBack or Log4J 1.x as the backend.

11.5 Use of the Log4J 2 bridge JARs for the various third-party libraries in GEMFIRE/lib that utilize other logging libraries such as Log4J 1x, Commons Logging, JUL and SLF4J. This causes all the logging APIs in the JVM to use the Log4J 2 backend. TODO: this needs more clarification.

12 Documentation

Release notes need to announce the logging changes and point to user docs about logging.

...

if (logger.isDebugEnabled()) {
  logger.debug("[DLockGrantor.acquireSuspendLockPermission] new status  permitLockRequest = {}{}", permitLockRequest, displayStatus(rThread, null));
}

In the above, displayStatus(rThread, null) is very expensive because it hits a synchronization:

String displayStatus(RemoteThread rThread, Object name) {
  StringBuffer sb = new StringBuffer();
  synchronized (this.suspendLock) {
    ...
  }
  return sb.toString();
}

...