THIS IS A TEST INSTANCE. ALL YOUR CHANGES WILL BE LOST!!!!
...
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:
| Code Block | ||
|---|---|---|
| ||
if (log.isDebugEnabled()) { |
...
log.debug("Hi, " + string1 + " " + string2); |
...
} |
Becomes:
| Code Block | ||
|---|---|---|
| ||
log.debug("Hi, {} {}", string1, string2); |
Example 2 has a parameter that involves making a costly call:
| Code Block | ||
|---|---|---|
| ||
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:
| Code Block | ||
|---|---|---|
| ||
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:
| Code Block | ||
|---|---|---|
| ||
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:
| Code Block | ||
|---|---|---|
| ||
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? (Kirk: probably not) This is primarily to satisfy:
8 Feature Interactions
8.1 GFSH
...
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)
...
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.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:
| Code Block | ||
|---|---|---|
| ||
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:
| Code Block |
|---|
String displayStatus(RemoteThread rThread, Object name) {
StringBuffer sb = new StringBuffer();
synchronized (this.suspendLock) {
...
}
return sb.toString();
} |
...
- wrap LocalizedStrings in LocalizedMessage:
| Code Block |
|---|
logger.error(LocalizedMessage.create(LocalizedStrings.DLockGrantor_PROCESSING_OF_POSTREMOTERELEASELOCK_THREW_UNEXPECTED_RUNTIMEEXCEPTION, e)); |