1 Introduction

This document describes the modernization of GemFire logging to use Log4J 2. This will introduce usage of categories and markers to the product which will have a major impact on improving debugging by engineering as well as customers. It will also greatly improve our integration in other environments such as Tomcat/TC-Server.

GemFire releases 1 through 3 were a much smaller product with a much smaller localized team. LogWriter and its limitations were sufficient for that team and the much smaller original feature set. Enabling FINE wouldn’t fill your disk and it facilitated debugging sufficiently. GemFire 1 was also released at a time before the current logging libraries were created. We now have multiple teams separated geographically, and the size of the product has grown exponentially. GemFire has simply outgrown the usefulness of the old LogWriter logging. In order to debug and grow the logging to be useful again, we need to adopt one of the new logging libraries with categories, mapped diagnostic contexts, markers and filters.

Driving requirements: a) improve debugging by introducing full-qualified class name categories, mapped diagnostic contexts, markers, filters, flow tracing, static loggers and other features missing in GemFire logging, b) improve integration with customer applications and deployment environments such as Tomcat/tcServer, c) provide industry standard logging API as requested by many customers and field engineers, d) improve code maintenance by replacing deficient proprietary logging with free, open-source, modern logging library, e) select the best performing library that meets the requirements.

2 Bugs and Feature Requests 

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

    • 2.1 #47722 G0 Configurable option of appending to log file or creating new file
    • 2.2 #50483 F0 log file size does not account for user/application logging
    • 2.3 #51111 F0 Web application (Tomcat) logging goes to gemfire log
    • 2.4 #47910 R2 <Regression> ConcurrentModificationException in createLogWriter during locator startup.
    • 2.5 #51207 F2 Improve logging configuration for libraries
    • 2.6 #40414 R3 i18n changes (toLocalizedString) causes ports, ids to be formatted with commas
    • 2.7 #43396 R3 Remove dead messages from LocalizedStrings and fix any obvious typos
    • 2.8 #51197 C2 A log file name with no '.log' extension causes the gfxd connect to fail after the first time
    • 2.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.

Removing OSProcess.redirectCOutput makes #50483 irrelevant. See 7.10.1.

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

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:
final Logger log = LogManager.getLogger(getClass());
final Logger log = LogManager.getLogger(); // automatically uses getClass()
  • MDC -- Mapped Diagnostic Context which is an optional ThreadLocal map of value(s) that can be used for detailed debugging and tracing

5 Selection of Log4J 2

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.

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

There are plenty of good articles to follow-up with including Apache Log4j 2.0 - Worth the Upgrade?

6 Overview

Summary of the changes:

6.1 GemFire product code will be updated to use a Logger defined in every class or each class’s root ancestor using the fully-qualified class name as the name of its Logger. This is the industry standard in Java logging and it provides categorical control over logging which dramatically improves debugging for engineering, support and customers.

6.2 Custom log levels introduce too great of a performance impact, so FINEST and FINER will map to TRACE, FINE will map to DEBUG statements previously logged at CONFIG will be logged at INFO.

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.4 Markers will be used to further organize logging by component or service layer in order to facilitate filtering and debugging beyond what is already provided by fully-qualified class name categories. Markers can extend other Markers, but a log statement cannot specify two unrelated Markers. I propose adding an interface to com.gemstone.gemfire.logging which defines all of our product Markers with extensive javadocs so that users can a) be aware of the Markers so they know what they can filter on, b) log with our Markers if they so desire. TODO: specify a possible set of Markers in section 6

6.5 The old LogWriter API and logging properties in gemfire.properties will be deprecated. Current product defaults have these disabled except to stdout so those defaults will remain unchanged. If someone is determined to use those old properties then they can can still enable logging of LogWriter to file. The InternalDistributedSystem will register a LogWriterAppender which is configured with the appropriate “log-” properties. Because this is a Log4J 2 appender, the filtering by categories, markers, etc will allow the user to control its output more thoroughly.

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 (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.

6.7 GemFire will have an absolute required dependency on the Log4J 2 API jar which is currently log4j-api-2.0.2.jar. The default GemFire log4j2.xml includes configuration of appenders and pattern layout that duplicates the old syntax of GemFire LogWriter output, Alerting, Security, file rolling, etc. These details require that we use and implement classes, including custom layouts and appenders, that make use of the Log4J 2 Core jar which is currently log4j-core-2.0.2.jar. We hope to have an optional (though highly recommended) dependency on the Core jar. Even if we are able to have an optional dependency on this jar, it will be necessary in order to get any logging output that resembles the legacy output format. The reason is that the product code will be changed to use Log4J 2 Loggers directly rather than some facade that can optionally adapt to either old LogWriter or new Log4J 2 with the LogWriterAppender. We did some performance testing and found that such a facade introduces a drop in performance.

7 Architectural Description

7.1 Overview of Architecture

GemFire product code will be updated to use a private static Logger defined in every class using the fully-qualified class name as the name of its Logger. Example:

private static final Logger log = LogService.getLogger();

In some special cases it might be beneficial to define a non-static Logger in a superclass and allow subclasses to use it:

protected final Logger log = LogService.getLogger(getClass());

Customer APIs that return LogWriter will be deprecated and return an instance of LogWriterLogger which delegates to a Logger named “com.gemstone.gemfire”.

If the deprecated logging configuration log-file, log-file-size-limit, log-disk-space-limit are set, then GemFire will register a LogWriterAppender that is configured with these properties.

Everything in this overview will be detailed further below.

7.2 Configuration of Log4J 2

GemFire will be using Log4J 2 and will simply allow Logging to be configured in the way that users configure Log4J 2, which is done with a log4j2.xml file.

Default log4j2.xml for GemFire will maintain the pre-existing format of logging messages.

Logging will append to stdout and one or more Appenders that GemFire registers internally for Alerting, legacy “log-” logging, Security, etc. By default Log4J 2 will not be logging to a file. This can be enabled by replacing or editing the log4j2.xml file. The legacy logging properties “log-” will configure the LogWriterAppender which uses the ManagerLogWriter to log to file.

User documentation will specify and provide examples of recommended log4j2.xml settings.

Documentation should recommend file rolling will be enabled “OnStartup” using OnStartupTriggeringPolicy. This means that at process startup, log file will roll to create a new one which will have the banner logged to it same as always. Additional trigger policy and rolling details as provided by Log4J 2 should be covered.

Appenders section in default log4j2.xml is simple:

<Appenders>
 <Console name="STDOUT" target="SYSTEM_OUT">
   <PatternLayout pattern="${gemfire-pattern}"/>
 </Console>
</Appenders>

PatternLayout requires a custom com.gemstone.gemfire.logging.internal.log4j.ThreadIdPatternConverter class that extends LogEventPatternConverter so that we can provide the ThreadId which is part of the log line of the old LogWriter format.

The default GemFire PatternLayout looks like (TODO: add in Marker and LoggerName):

<Property name="gemfire-pattern">[%level{lowerCase=true} %date{yyyy/MM/dd HH:mm:ss.SSS z} &lt;%thread&gt; tid=%tid] %message%n%throwable%n</Property>

The legacy GemFire PatternLayout is only used for LogWriterAppender when “log-” properties are configured and looks like:

<Property name="logwriter-gemfire-pattern">[%level{TRACE=finer, DEBUG=fine, INFO=info, WARN=warning, ERROR=error, FATAL=severe} %date{yyyy/MM/dd HH:mm:ss.SSS z} &lt;%thread&gt; tid=%tid] %message%n%throwable%n</Property>

The default Loggers section for GemFire loggers looks like:

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

Example of adding a log4j2 RollingFileAppender to enable logging to a file with rolling support instead of relying on the LogWriterAppender that provides backwards compatibility:

<RollingFile name="ROLLINGFILE" fileName="server1.log"
    filePattern="server1-%i.log">
 <PatternLayout>
   <pattern>${gemfire-pattern}</pattern>
 </PatternLayout>
 <Policies>
   <OnStartupTriggeringPolicy />
   <SizeBasedTriggeringPolicy size="2 GB"/>
 </Policies>
 <DefaultRolloverStrategy max="20"/>
</RollingFile>

GFSH command “alter runtime” allows the “log-level” and several other gemfire properties to be altered at runtime. This will control the “log-level” of the LogWriterAppender only.

New GFSH command “alter logging” will need to be introduced eventually that will allow either remote manipulation of a process’s log4j2.xml or the log4j2 MBean. This would allow the user to enable/disable markers and filters as well as altering logging level per appenders or categories. I think this is not absolutely required for initial release but is a nice-to-have if there is time.

7.3 Deprecated Logging Configuration

Configuration of Logging via gemfire.properties or DistributionConfig will be deprecated. This includes log-file, log-level, log-file-size-limit, log-disk-space-limit. These will be used to configure and control the LogWriterAppender going forward.

Reasons for having these properties control LogWriterAppender only: a) supporting two different ways to configure Log4J 2 is complicated both for the user and requires too many weeks of effort for engineering to build a custom Configuration plugin, 2) trying to apply log-disk-space-limit and the pre-existing naming of rolled log files would require writing our own custom Appender, Strategy, etc. with the Core API which is extensive work (and starts to make the logging system look like something proprietary again), 3) the logging library needs to be configured when classes are loaded in order to allow classes to have static or member logger fields -- GemFire allows configuration of log-file early or late, during DistributedSystem.connect(Properties config) -- there are also no APIs for changing the configuration at runtime (user is expected to alter the log4j2.xml for runtime changes). The Core API does expose the ability to create a custom Configuration plugin but again, that would increase the scope of this effort.

Since the log-file, log-level, log-file-size-limit, log-disk-space-limit configuration options are all disabled by default, we can keep this default. If the user prefers to use the LogWriterAppender, they can simply avoid adding a FileAppender to the log4j2.xml. The LogWriterAppender is configured with these properties and the log-level can be altered at runtime. Although deprecated, these configuration options would remain in place for at least one major release of GemFire before being removed.

It would theoretically be possible to enable deprecated logging to file while also logging to a file via Log4J 2. This could be done by using the LogWriterAppender and adding one or more FileAppenders to the log4j2.xml This would obviously be discouraged in product documentation and release notes, but I’ll specify basic unit test coverage for this.

Remove all system properties previously used for controlling scope of logging, such as those used for DEBUG or VERBOSE logging in specific code areas such as DistributionManager or DistributedLockService. We will replace this with Markers and FQCN-based Categories.

7.4 Logging API

The existing API is com.gemstone.gemfire.LogWriter. Since this is an interface, we can easily return to the user an instance of com.gemstone.gemfire.logging.internal.log4j.LogWriterLogger which adapts the LogWriter calls to Logger calls. Everything on the LogWriter class will be deprecated as well as any APIs that return a LogWriter to the user. The “log-” logging gemfire properties will also be deprecated.

The user should instead of a Logger from Log4J 2 or even one of the other Logging APIs such as SLF4J. Log4J 2 includes optional jars for using Log4J 2 as the backend to other APIs such as SLF4J, Commons Logging or java.util.logging.

The new package com.gemstone.gemfire.logging would provide a package.html and some sort of interface that defines constants for the Markers we use in the product source code. This would include much of the same info as they would also find in the user documentation.

7.5 Management Alerts

The AlertAppender is automatically registered internally to handle creation of Alerts based on Alert Level if one or more Alert Listeners are defined in the cluster.

It might be nice to redefine Alerts as something defined by an Alert Marker rather than by the Alert Level. This isn’t a high priority and could be addressed in a later release.

7.6 Message Parameterization

Log statements should be updated to remove conditionals such as isFineEnabled() in favor of Log4J 2’s parameterization but only if the parameters are not costly method calls.

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

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

Becomes:

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:

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.

Release notes need to announce that GemFire is no longer redirecting stdout/stderr. Some documentation either in these notes or in user docs should recommend the user use OS pipe/redirect as needed. If spec review decides that we should keep a mechanism to enable OSProcess.redirectCOutput then this could be documented in user docs or communicated directly to just those customers who actually require that behavior -- in general it causes trouble for the majority of customers so it should not be on by default.

Maybe recommend having a dedicated log4j2.xml in the working directory of each server and locator. This way FileAppender can have a log file name specific to the process and logging for that process can be individually controlled with its log4j2.xml.

Avoid configuring gemfire.properties to enable LogWriterAppender AND configuring log4j2.xml to enable FileAppender. GemFire would be logging the same messages to both files. This is redundant and there should be no valid reason why a user would need to do this. Note: a user may want to define multiple FileAppenders in order to log different components, layers, third-party services each to their own dedicated log files. But that’s different and is an advanced use of Log4J 2 that we don’t to go into much detail about. We may wish to document how to configure log4j2.xml such that GemFire logs to a dedicated log file separate from that of the application or environment.

Recommend having application use Loggers from log4j-api-2.0.2.jar with log4j-core-2.0.2.jar as the backend which we’ll be optimizing heavily for. In particular, this is going perform better than having an application using Loggers from slf4j-api-1.7.7.jar with the log4j-slf4j-impl-2.0.2.jar that allows slf4j to use log4j-core-2.0.2.jar as its backend. This is really only an issue if you a LOT of log statements such as one or more per cache operation.

Recommend using just enough log statements in the application to provide sufficiently for debugging. Excessive number of log statements, even at a disabled log level, are ultimately going to affect performance.

Document performance impact of using “monitorInterval” attribute on <Configuration> in log4j2.xml which enables auto-reconfig. This results in log4j2’s XmlConfiguration class creating and using a FileConfigurationMonitor. GemFire might inject an alternate implementation of this monitor which fixes the performance or we will recommend not using “monitorInterval”. The user could still use the Log4J 2 MBean to control configuration at runtime without enabling auto-reconfig for the config file.

13 Notes

LogWriterAppender will use legacy pattern layout that prints old GemFire log levels instead of Log4J 2 log levels unless perf tests reveal that this is too costly. Also need to do some performance testing to see what the impact is for having a detailed pattern layout.

Look into updating native client with log4net? It’s actually unrelated to log4j but should discuss with Vishal.

Should we not search for the log4j2.xml in defaultConfigs? GemFire doesn't use any of the other files in that directory during runtime.

Specify most useful appenders in log4j2.xml but do not attach them to loggers -- this shows user what is possible and some recommended uses of logging. Follow-up by determining if specifying appenders has any overhead without being attached to loggers.

Add coding standards:

    • remove all conditional gates for log levels above INFO

    • convert all string concat to parameterization

    • always get Logger through LogService: private static final Logger logger = LogService.getLogger();

    • keep conditional gate below INFO only if parameters incur perf penalty. (Should we ever use conditionals on INFO level??). Example: 

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();
}
    • wrap LocalizedStrings in LocalizedMessage: 
logger.error(LocalizedMessage.create(LocalizedStrings.DLockGrantor_PROCESSING_OF_POSTREMOTERELEASELOCK_THREW_UNEXPECTED_RUNTIMEEXCEPTION, e));