Logging in Java and in general: Best Practices?

问题:

Sometimes when I see my logging code I wonder if I am doing it right. There might be no definitive answer to that, but I have the following concerns:

Library Classes

I have several library classes which might log some INFO messages. Fatal Errors are reported as exceptions. Currently I have a static logger instance in my classes with the class name as the logging name. (Log4j's: Logger.getLogger(MyClass.class))

Is this the right way? Maybe the user of this library class doesn't want any messages from my implementation or wants to redirect them to an application specific log. Should I allow the user to set a logger from the "outside world"? How do you handle such cases?

General logs

In some applications my classes might want to write a log message to a specific log not identified by the class' name. (I.e.: HTTP Request log) What is the best way to do such a thing? A lookup service comes to mind...

回答1:

Your conventions are pretty standard and quite fine (imho).

The one thing to watch is memory fragmentation from excessive unnedded debug calls so, with Log4J (and most other Java logging frameworks), you end up with something like this:

if (log.isDebugEnabled()) {
  log.debug("...");
}

because constructing that log message (that you probably aren't using) could be expensive, especially if done thousands or millions of times.

Your INFO level logging shouldn't be too "chatty" (and from what you say, it sounds like it isn't). INFO messages should be generally meaningful and significant, like the application being started and stopped. Things that you might want to know if you encounter a problem. Debug/fine level logging is more used for when you actually have a problem you're trying to diagnose. Debug/fine logging is typically only turned on when needed. Info is typically on all the time.

If someone doesn't want specific INFO messages from your classes, they are of course free to change your log4j configuration to not get them. Log4j is beautifully straightforward in this department (as opposed to Java 1.4 logging).

As for your HTTP thing, I've generally not found that to be an issue with Java logging because typically a single class is responsible for what you're interested in so you only need to put it in one place. In the (rare in my experience) when you want common log messages across seemingly unrelated classes, just put in some token that can easily be grepped for.

回答2:

In @cletus' answer, he wrote of the problem of

if (log.isDebugEnabled()) {
  log.debug("val is " + value);
}

which might be overcome by using SL4J. It provides a formatting help

log.debug("val is {}", value);

where the message is only constructed if the level is debug.

So, nowaday, using SL4J and its companion logger, Logback, is advised for performance and stability reasons.

回答3:

With respect to instantiating loggers, I have had some success using an Eclipse Java Template for setting up my loggers:

private static Logger log = Logger.getLogger(${enclosing_type}.class);

This avoids the problem of a JVM mucking about with your stack trace, and reduces (trivially, perhaps) the overhead from creating the stack trace in the first place.

The great thing about using a template like this is that you can share it with your team if you want to set a consistent standard across the board for loggers.

It looks like IntelliJ supports the same concept for a template variable representing the name of the enclosing type. I don't see a way to do it easily in NetBeans.

回答4:

The following is the guidelines I follow in all my projects to ensure good performance. I have come to form this set of guidelines based on the inputs from various sources in the internet.

As on today, I believe Log4j 2 is by far the best option for logging in Java.

The benchmarks are available here. The practice that I follow to get the best performance is as follows:

1. I avoid using SLF4J at the moment for the following reasons:
   • It has some concurrency issues with Markers which I want to use to manage the logging of SQL statements (Markers not as powerful as slf4j - Refer to the first comment by Ralph Goers)
   • It does not support the Java 8 Lambda which, again, I want to use for better performance (Support the lambda expression in the Logger)
2. Do all regular logging using asynchronous logger for better performance
3. Log error messages in a separate file using synchronous logger because we want to see the error messages as soon as it occurs
4. Do not use location information, such as filename, class name, method name, line number in regular logging because in order to derive those information, the framework takes a snapshot of the stack and walk through it. This impacts the performance. Hence use the location information only in the error log and not in the regular log
5. For the purpose of tracking individual requests handled by separate threads, consider using thread context and random UUID as explained here
6. Since we are logging errors in a separate file, it is very important that we log the context information also in the error log. For e.g. if the application encountered an error while processing a file, print the filename and the file record being processed in the error log file along with the stacktrace
7. Log file should be grep-able and easy to understand. For e.g. if an application processes customer records in multiple files, each log message should be like below:

12:01:00,127 INFO FILE_NAME=file1.txt - Processing starts
12:01:00,127 DEBUG FILE_NAME=file1.txt, CUSTOMER_ID=756
12:01:00,129 INFO FILE_NAME=file1.txt - Processing ends

8. Log all SQL statements using an SQL marker as shown below and use a filter to enable or disable it:

private static final Marker sqlMarker = 
  MarkerManager.getMarker("SQL");

private void method1() {
    logger.debug(sqlMarker, "SELECT * FROM EMPLOYEE");
}

9. Log all parameters using Java 8 Lambdas. This will save the application from formatting message when the given log level is disabled:

int i=5, j=10;
logger.info("Sample output {}, {}", ()->i, ()->j);

10. Do not use String concatenation. Use parameterized message as shown above

11. Use dynamic reloading of logging configuration so that the application automatically reloads the changes in the logging configuration without the need of application restart

12. Do not use printStackTrace() or System.out.println()

13. The application should shut down the logger before exiting:

LogManager.shutdown();

14. Finally, for everybody’s reference, I use the following configuration:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration monitorinterval="300" status="info" strict="true">
    <Properties>
        <Property name="filePath">${env:LOG_ROOT}/SAMPLE</Property>
        <Property name="filename">${env:LOG_ROOT}/SAMPLE/sample
        </Property>
        <property name="logSize">10 MB</property>
    </Properties>
    <Appenders>
        <RollingFile name="RollingFileRegular" fileName="${filename}.log"
            filePattern="${filePath}/sample-%d{yyyy-dd-MM}-%i.log">
            <Filters>
                <MarkerFilter marker="SQL" onMatch="DENY"
                    onMismatch="NEUTRAL" />
            </Filters>
            <PatternLayout>
                <Pattern>%d{HH:mm:ss,SSS} %m%n
                </Pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy
                    interval="1" modulate="true" />
                <SizeBasedTriggeringPolicy
                    size="${logSize}" />

            </Policies>
        </RollingFile>
        <RollingFile name="RollingFileError" 
            fileName="${filename}_error.log"
            filePattern="${filePath}/sample_error-%d{yyyy-dd-MM}-%i.log"
            immediateFlush="true">
            <PatternLayout>
                <Pattern>%d{HH:mm:ss,SSS} %p %c{1.}[%L] [%t] %m%n
                </Pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy
                    interval="1" modulate="true" />
                <SizeBasedTriggeringPolicy
                    size="${logSize}" />
            </Policies>
        </RollingFile>
    </Appenders>
    <Loggers>
        <AsyncLogger name="com"
            level="trace">
            <AppenderRef ref="RollingFileRegular"/>
        </AsyncLogger>
        <Root includeLocation="true" level="trace">
            <AppenderRef ref="RollingFileError" level="error" />
        </Root>
    </Loggers>
</Configuration>

15. The required Maven dependencies are here:

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-api</artifactId>
    <version>2.8.1</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.8.1</version>
</dependency>
<dependency>
    <groupId>com.lmax</groupId>
    <artifactId>disruptor</artifactId>
    <version>3.3.6</version>
</dependency>
<!-- (Optional)To be used when working 
with the applications using Log4j 1.x -->
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-1.2-api</artifactId>
    <version>2.8.1</version>
</dependency>

回答5:

The preferred option for the kind of log4j configuration you're describing is to use the log4j configuration file. This allows users of your implementation to do exactly what you're asking for, since they can override your configuration later on with something more suitable for their own implementation. See here for a very thorough primer.

回答6:

I have probably stolen this from somewhere, but it's nice.

It reduces the risk of mixing up loggers when copying and pasti^h^h^h refactoring, and it's less to type.

In your code:

private final static Logger logger = LoggerFactory.make();

...and in LoggerFactory:

public static Logger make() {
    Throwable t = new Throwable();
    StackTraceElement directCaller = t.getStackTrace()[1];
    return Logger.getLogger(directCaller.getClassName());
}

(Note that the stackdump is done during initialisation. The stacktrace will probably not be optimized away by the JVM but there are actually no guarantees)

回答7:

I'm reviewing log-levels of an application and I'm currently detecting a pattern:

private static final Logger logger = Logger.getLogger(Things.class)

public void bla() {
  logger.debug("Starting " + ...)
  // Do stuff
  ...
  logger.debug("Situational")

  // Algorithms
  for(Thing t : things) {
    logger.trace(...)
  }

  // Breaking happy things
  if(things.isEmpty){
    logger.warn("Things shouldn't be empty!")
  }

  // Catching things
  try {
    ...
  } catch(Exception e) {
    logger.error("Something bad happened")
  }

  logger.info("Completed "+...)
}

A log4j2-file defines a socket-appender, with a fail-over file-appender. And a console-appender. Sometimes I use log4j2 Markers when the situation requires it.

Thought an extra perspective might help.

回答8:

As an addition, I think it's important to mean Simple Logging Facade for Java (SLF4J) (http://www.slf4j.org/). Due to some issues of using different logging frameworks in diversified parts of a big project, SLF4J is the de facto standard to solve a problem to manage these parts successfully, isn't it?

The second one notion: it's seems that some old-school tasks can be substituted by Aspect-Oriented-Programming, Spring frmwrk has it's own implementation, AOP-approach for logging considered here at StackOverflow and here on Spring blog.