help/validateLogCalls.txt

Using log calls
===============

There are several gotchas when logging. In particular, methods
are called and strings are concatenated that have variables
and objects can be constructed even if the logging level
is more restrictive than the call. For instance, if the logging
level is WARN, then a call like:
log.trace("something {}", some_object.toString())
will cause some_object.toString() to be called, then the resulting
string is passed to log.trace() where the log level is evaluated
and the logging call may be aborted. Any method called explicitly
as part of a logging call is executed regardless of whether the
message will be logged or not.

This can be very expensive as per measurements with Java Flight
Recorder. It's particularly egregious when complex operations
are performed for, say, debug or trace levels, which
are rarely reported.

Here are a few patterns that generate useless strings/objects:

- log.info("some stuff " + some_object) will concatenate the
  some_object.toString() and create a new string. The only
  exception is if "some_object" is a literal string.

- log.info("some stuff {}", object.method()) will execute the
  method.

- log.info("some stuff {}", object.toString()) will execute
  the toString and then may throw the results away.
  log.info("some stuff{}", object)
  is safe, the object's toString() method is called only after
  the log/do not log decision has been made.

-----------
NOTES:

- If you're creating a logging call that has no choice but to
  do something expensive, surround it with "if (log.is*Enabled)".
  Validation will flag any situation where the level in the "if"
  clause does not match the level of the actual call.

- Logging calls can take a bare exception, but do not
  use the braces if you want the stack trace! So
  log.info("stuff {}", exception) will not print the full stack,
  log.info("stuff ", exception) _will_ print the full stack.
  log.info("stuff {} ", some_object, exception) will print "stuff + the result
  of the object's toString() method" plus the full stack. If you're puzzled
  as to why so many logging calls don't have a matching number of curly-braces
  and parameters, this is usually why.

- When slf4j supports lambdas in logging calls (log4j2 does now),
  we can use lambdas rather than "if log.is*Enabled". slf4j 2.0
  will when released. This will probably mean this check has to be re-worked
  to avoid false flags

- warn, error, and fatal level messages are NOT flagged for explicit,
  function calls, but will be flagged if they contain plusses that aren't
  simple concatenation. This last is something of a style check.

- You can get into some pretty convolued consructs trying to pass some of these
  checks. Adding //nowarn, with or without spaces will cause the line to pass
  no matter what. Please use this hack sparingly and be conscientious about
  surrounding with 'if (log.is*Enabled)'.

- String constants may be added with '+', but they _must_ be literal strings.
  The compiler is smart enough to concatenate them when compiling. For example:
  log.info("some {} "+ "more nonsense {}", object1, object2) is fine
  log.info("some{} " + " more nonsense " + object1, object2) is NOT fine (note
  the plus in front of object1).

For a fuller discussion, see LUCENE-7788 and the other JIRAs linked
from there.