Slf4j log error

В этой главе мы обсудим различные сообщения об ошибках или предупреждения, которые мы получаем при работе с SLF4J, и причины / значения этих сообщений.

Не удалось загрузить класс “org.slf4j.impl.StaticLoggerBinder”.

Это предупреждение, которое вызывается, если в пути к классам нет привязок SLF4J.

Ниже приводится полное предупреждение –

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further
details.

Чтобы решить эту проблему, необходимо добавить одну из привязок каркаса ведения журнала. Это объясняется в главе Hello World этого урока.

Примечание. Это происходит в версиях SLF4J между 1.6.0 и 1.8.0-бета2.

Поставщики SLF4J не найдены

В slf4j-1.8.0-beta2 вышеупомянутое предупреждение более ясно говорит, что «поставщики SLF4J не были найдены» .

Ниже приводится полное предупреждение –

SLF4J: No SLF4J providers were found.
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#noProviders for further details.

Classpath содержит привязки SLF4J для версий slf4j-api до 1.8

Если вы используете версию SLF4J 1.8 и у вас есть привязки предыдущих версий в classpath, но не привязки 1.8, вы увидите предупреждение, как показано ниже.

SLF4J: No SLF4J providers were found.
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#noProviders for further details.
SLF4J: Class path contains SLF4J bindings targeting slf4j-api versions prior to
1.8.
SLF4J: Ignoring binding found at
[jar:file:/C:/Users/Tutorialspoint/Desktop/Latest%20Tutorials/SLF4J%20Tutorial/
slf4j-1.7.25/slf4j-jdk14-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#ignoredBindings for an explanation.

NoClassDefFoundError: org / apache / commons / logging / LogFactory

Если вы работаете с slf4j-jcl и у вас есть только slf4j-jcl.jar в вашем пути к классам, вы получите исключение, такое как приведенное ниже.

Exception in thread "main" java.lang.NoClassDefFoundError:
org/apache/commons/logging/LogFactory
   at org.slf4j.impl.JCLLoggerFactory.getLogger(JCLLoggerFactory.java:77)
   at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358)
   at SLF4JExample.main(SLF4JExample.java:8)
Caused by: java.lang.ClassNotFoundException:
org.apache.commons.logging.LogFactory
   at java.net.URLClassLoader.findClass(Unknown Source)
   at java.lang.ClassLoader.loadClass(Unknown Source)
   at sun.misc.Launcher$AppClassLoader.loadClass(Unknown Source)
   at java.lang.ClassLoader.loadClass(Unknown Source)
   ... 3 more

Чтобы решить эту проблему, вам нужно добавить commons-logging.jar к вашему classpath.

Обнаружил как jcl-over-slf4j.jar, так и связанный slf4j-jcl.jar на пути к классам.

Привязка slf4j-jcl.jar перенаправляет вызовы регистратора slf4j в JCL, а jcl-over-slf4j.jar перенаправляет вызовы регистратора JCL в slf4j. Таким образом, вы не можете иметь оба в classpath вашего проекта. Если вы сделаете это, вы получите исключение, такое как приведенное ниже.

SLF4J: Detected both jcl-over-slf4j.jar AND bound slf4j-jcl.jar on the class
path, preempting StackOverflowError.
SLF4J: See also http://www.slf4j.org/codes.html#jclDelegationLoop for more
details.
Exception in thread "main" java.lang.ExceptionInInitializerError
   at org.slf4j.impl.StaticLoggerBinder.<init>(StaticLoggerBinder.java:71)
   at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:42)
   at org.slf4j.LoggerFactory.bind(LoggerFactory.java:150)
   at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:124)
   at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:412)
   at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:357)
   at SLF4JExample.main(SLF4JExample.java:8)
Caused by: java.lang.IllegalStateException: Detected both jcl-over-slf4j.jar
AND bound slf4j-jcl.jar on the class path, preempting StackOverflowError. See
also http://www.slf4j.org/codes.html#jclDelegationLoop for more details.
   at org.slf4j.impl.JCLLoggerFactory.<clinit>(JCLLoggerFactory.java:54)
   ... 7 more

Чтобы решить эту проблему, удалите любой из файлов JAR.

Обнаружено несоответствие имени регистратора

Вы можете создать объект Logger с помощью –

• Передача имени созданного регистратора в качестве аргумента методу getLogger () .

• Передача класса в качестве аргумента этому методу.

Передача имени созданного регистратора в качестве аргумента методу getLogger () .

Передача класса в качестве аргумента этому методу.

Если вы пытаетесь создать объект фабрики регистратора, передавая класс в качестве аргумента, и если вы установили системное свойство slf4j.detectLoggerNameMismatch в значение true, тогда имя класса, которое вы передаете в качестве аргумента методу getLogger () и используемый вами класс должен быть таким же, в противном случае вы получите следующее предупреждение –

«Обнаружено несоответствие имени регистратора.

Рассмотрим следующий пример.

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class SLF4JExample {
   public static void main(String[] args) {
      System.setProperty("slf4j.detectLoggerNameMismatch", "true");
      
      //Creating the Logger object
      Logger logger = LoggerFactory.getLogger(Sample.class);

      //Logging the information
      logger.info("Hi Welcome to Tutorilspoint");
   }
}

Здесь мы установили для свойства slf4j.detectLoggerNameMismatch значение true. Имя класса, которое мы использовали, – SLF4JExample, а имя класса, которое мы передали методу getLogger (), – Sample, так как они оба не равны, мы получим следующее предупреждение.

SLF4J: Detected logger name mismatch. Given name: "Sample"; computed name:
"SLF4JExample".
SLF4J: See http://www.slf4j.org/codes.html#loggerNameMismatch for an
explanation
Dec 10, 2018 12:43:00 PM SLF4JExample main
INFO: Hi Welcome to Tutorilspoint

Примечание – это происходит после slf4j 1.7.9

Classpath содержит несколько привязок SLF4J.

У вас должна быть только одна привязка в пути к классам. Если у вас есть несколько привязок, вы получите предупреждение с указанием привязок и их местоположения.

Предположим, что если у нас есть привязки slf4j-jdk14.jar и slf4j-nop.jar в пути к классам, мы получим следующее предупреждение.

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in
[jar:file:/C:/Users/Tutorialspoint/Desktop/Latest%20Tutorials/SLF4J%20Tutorial/
slf4j-1.7.25/slf4j-nop-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/C:/Users/Tutorialspoint/Desktop/Latest%20Tutorials/SLF4J%20Tutorial/
slf4j-1.7.25/slf4j-jdk14-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an
explanation.
SLF4J: Actual binding is of type [org.slf4j.helpers.NOPLoggerFactory]

Обнаружены оба log4j-over-slf4j.jar И привязанные slf4j-log4j12.jar на пути к классам

Чтобы перенаправить вызовы log4j logger в slf4j, вам нужно использовать привязку log4j-over-slf4j.jar, а если вы хотите перенаправить вызовы slf4j в log4j, вам необходимо использовать привязку slf4j-log4j12.jar .

Таким образом, вы не можете иметь оба в classpath. Если вы это сделаете, вы получите следующее исключение.

I know I said I’d work on logging APIs this week… but I’m still cleaning up some code before it’s ready to present. So this is an interlude post.

The question today is the deceptively simple «how do I log an exception», which turns out to be interesting on multiple levels.

Canonically, the way you log an exception in SLF4J is to log a domain specific message, and include the exception as the last parameter. You can include parameters and use SFL4J templates, so having multiple arguments is fine.

try {
parseXML();
} catch (Exception e) {
// documentId is a StructuredArgument for structured logging, e is used for stacktrace
logger.error("Parsing xml document failed!", kv("documentId", documentId), e);
}

However, this isn’t the end of the story. When you render the exception in an appender, you have to decide how to render the stacktrace. The stacktrace is typically voluable, and will cover most of your console and your file in stack trace elements.

org.xml.sax.SAXParseException: The element type "img" must be terminated by the matching end-tag "</img>".
	at org.apache.xerces.util.ErrorHandlerWrapper.createSAXParseException(Unknown Source)
	at org.apache.xerces.util.ErrorHandlerWrapper.fatalError(Unknown Source)
	at org.apache.xerces.impl.XMLErrorReporter.reportError(Unknown Source)
	at org.apache.xerces.impl.XMLErrorReporter.reportError(Unknown Source)
	at org.apache.xerces.impl.XMLErrorReporter.reportError(Unknown Source)
	at org.apache.xerces.impl.XMLScanner.reportFatalError(Unknown Source)
	at org.apache.xerces.impl.XMLDocumentFragmentScannerImpl.scanEndElement(Unknown Source)
	at org.apache.xerces.impl.XMLDocumentFragmentScannerImpl$FragmentContentDispatcher.dispatch(Unknown Source)
	at org.apache.xerces.impl.XMLDocumentFragmentScannerImpl.scanDocument(Unknown Source)
	at org.apache.xerces.parsers.XML11Configuration.parse(Unknown Source)
	at org.apache.xerces.parsers.XML11Configuration.parse(Unknown Source)
	at org.apache.xerces.parsers.XMLParser.parse(Unknown Source)
	at org.apache.xerces.parsers.AbstractSAXParser.parse(Unknown Source)
	at org.apache.xerces.jaxp.SAXParserImpl$JAXPSAXParser.parse(Unknown Source)
	at org.apache.xerces.jaxp.SAXParserImpl.parse(Unknown Source)
  ...

Typically, you don’t actually care about most of the stacktrace in this case. There’s nothing you can do about anything in the Xerces stack, and it’s not relevant. You care about the message in the exception. This is especially relevant in appenders where real estate (or disk space) is at a minimum: for example, the exception may not be written to the console at all.

So, if you want to see the message written as:

Parsing xml document my-photo-album failed, underlying cause was [The element type "img" must be terminated by the matching end-tag "</img>".]

Then you should call e.getMessage() and append only the message.

logger.error("Parsing xml document {} failed, underlying cause was [{}]", documentId, e.getMessage(), e);

I think this is common practice. I’ve only had two objections to the practice of adding e.getMessage when logging. The first objection was that the exception could come from an unknown source, and so the runtime cost of calling e.getMessage was unknown and could result in 20 MB of /dev/random data, if it didn’t risk crashing, halting, blocking, the program altogether.

This is not a theoretical problem! I’ve personally seen harmless code block entire applications because they called object.hashCode() and obj.equals only to discover that java.net.URL makes blocking network calls on hashCode and equals.

I think you have to trust that getMessage returns a message and is not pathological – if you don’t trust an exception to be safe, then the only information you can extract from it is that it exists and has a certain type: you can safely call e.getClass().getName() on it.

The other objection was that calling e.getMessage was duplicating information that was already in the stacktrace. I think this is a confusion: a message is domain specific diagnostic information for the user. A stacktrace consists of the message and stacktrace elements that are not domain-specific. Printing out the message is relevant even when the stack trace is not: it’s a summary.

However, this does point the way to a deficiency in using e.getMessage(): it doesn’t print out all the diagnostic information available to the stacktrace. Specifically, it doesn’t deal with chained exceptions, which may have several exceptions nested deep. Using e.getMessage() only prints out the top level – this is especially annoying when a useless java.util.concurrent.CompletionException hides the real exception underneath it.

What I’d like to see is something that runs through all the messages and sticks them together, without having to wade through stack trace elements. So if I write up something like this:

class Runner {
private final Logger logger = LoggerFactory.getLogger(this.getClass());
public void doError() {
Exception ex = generateException();
logger.error("I am an error", ex);
}
private Exception generateException() {
Random rnd = new java.util.Random();
int i = rnd.nextInt(10) + 1;
return nestException(null, i);
}
private Exception nestException(Exception ex, int i) {
if (i > 0) {
Exception nested = new RuntimeException("Level " + i, ex);
return nestException(nested, i - 1);
}
return ex;
}
}

Then I should get a message like this:

I am an error cause=[Level 1 > Level 2 > Level 3 > Level 4 > Level 5 > Level 6]

We can make everyone happy by rendering the message using a custom converter. This means that the cause happens automatically, on every exception, and by deferring rendering to another thread and managing the thread pool, we can also reduce the impact of blocking operations.

The converter looks like this:

public class ExceptionMessageConverter extends ThrowableHandlingConverter {
@Override
public String convert(ILoggingEvent event) {
Integer whitespace = getLeadingWhitespace();
if (whitespace < 0) {
addWarn("Cannot render whitespace less than 0!");
whitespace = 0;
}
Integer depth = getDepth();
if (depth < 1) {
addWarn("Cannot render depth less than 1!");
depth = 1;
}
String prefix = getPrefix();
String sep = getSeparator();
String suffix = getSuffix();
IThrowableProxy ex = event.getThrowableProxy();
if (ex == null) {
return "";
}
return processException(ex, whitespace, depth, prefix, sep, suffix);
}
// ...
protected String processException(IThrowableProxy throwableProxy,
Integer whitespace,
Integer depth,
String prefix, String sep, String suffix) {
String ws = String.join("", Collections.nCopies(whitespace, " "));
StringBuilder b = new StringBuilder(ws + prefix);
IThrowableProxy ex = throwableProxy;
for (int i = 0; i < depth; i++) {
b.append(ex.getMessage());
ex = ex.getCause();
if (ex == null || i + 1 == depth) break;
b.append(sep);
}
b.append(suffix);
return b.toString();
}
}

and the implementation looks like this.

"%message%exmessage{1, 10, cause=[}"

This covers getMessage, which is a strength, and it also means that rendering to console can be strictly line based, which means pasting things into Slack is that much easier.

However, this only covers getMessage. This doesn’t cover anything else. If the exception contains vital information but doesn’t put it in getMessage, then you’re essentially blind to it. This is especially annoying when it comes to the AWS Java API, because AWS exceptions are extremely rich in useful domain information – serviceException.isClockSkewException(), serviceException.isThrottlingException(), and serviceException.requestId() – but rely on the caller to know to extract and present this information.

So, if you want to render an AWS exception then you still have to call kv structured arguments to expose that information in a structured format.

This leads to an interesting set of problems. We want to extract relevant information from the exception and this is only available per exception type. This can be demonstrated with java.sql.SQLException:

public class Thrower {
private static final Logger logger = LoggerFactory.getLogger(Thrower.class);
public static void main(String[] progArgs) {
try {
doSomethingWithSQL();
} catch (BatchUpdateException e) {
Object[] args = ExceptionMapper.mapException(e);
logger.error("domain specific message" + ExceptionMapper.holder(args), args);
} catch (SQLException e) {
Object[] args = ExceptionMapper.mapException(e);
logger.error("domain specific message" + ExceptionMapper.holder(args), args);
}
}
static void doSomethingWithSQL() throws SQLException {
throw new BatchUpdateException();
}
}
class ExceptionMapper {
public static String holder(Object[] args) {
if (args == null || args.length == 0) {
return "";
}
return " params=[" + String.join(", ", Collections.nCopies(args.length - 1, "{}")) + "]";
}
public static Object[] mapException(BatchUpdateException e) {
return new Object[]{
kv("errorCode", e.getErrorCode()),
kv("sqlState", e.getSQLState()),
kv("updateCounts", e.getUpdateCounts()),
e
};
}
public static Object[] mapException(SQLException e) {
return new Object[]{
kv("errorCode", e.getErrorCode()),
kv("sqlState", e.getSQLState()),
e
};
}
}

This gives us a better result:

domain specific message params=[errorCode=0, sqlState=null, updateCounts=null] cause=[java.sql.BatchUpdateException]

This isn’t a complete solution, because it has the same problem as using e.getMessage() in that it still only renders the attributes of the top level exception. If there’s an SQLException halfway through the stack, you won’t see the error code or the SQL state. In order to do this properly, you’ll have to run the exception mapper through the complete chain and potentially namespace the key value pairs into the relevant exception context if the keys conflict.

Also, the multiple catch blocks for BatchUpdateException and SQLException are awkward. They are not disjoints, so you can’t use a union, and they must be defined in order. I’d much rather do this with Scala style pattern matching, or at least a Map<Class, ExceptionMapper> that could find the most specific exception.

Finally, this is a manual process. It has to be added as code to every logging statement, and can’t be added to third party code.

The correct place to put this would be a custom converter, but I don’t feel like getting into it now, and the tricky bit would be populating the mapping, which is domain specific. Still, I think this points out where exception logging could be made more useful.

One thing that popped up in this is that logstash-logback-encoder doesn’t provide a way to render an exception as structured data. This means that it’s not so easy to parse and extract message information from stacktraces. Theres no jq style slicing and dicing of JSON logs. At best, you have sed, awk, and regex.

There are libraries that do render exceptions as JSON: logback-steno represents exceptions as JSON, as does log4j2-logstash-layout.

Logback steno renders stacktraces as a multiline string inside of a JSON field, which I’m not so concerned about. Most of the tools that allow you to do something with stacktraces, i.e. the many companies devoted to error tracking and the IDEs like IntelliJ IDEA, all work by parsing and recognizing the stacktrace in the multiline text format. The log4j2-logstash-layout library does render stacktrace information as structured data, but I don’t know of anything that would consume it. As such, I don’t think there’s any advantage in representing a stack trace in JSON.

Introduction

Server logs are an important part of development, that record the activities or events that the system is performing at any given point in time.

Spring Boot makes use of Apache Commons’ Logging for its system logs by default. Additionally, by default you can use any of the logging frameworks under the SLF4J API such as Logback (which is the default), Log4J2, and Java Util Logging in Spring Boot.

Application logging is a powerful development tool that is important for production-level support and debugging. Each log entry contains information such as the timestamp, the actual method being called, a custom log message, and other contextual information. Each log entry also includes an identifier called a logging level.

In this tutorial, we’ll take a look at how to perform Logging in Spring Boot, using SLF4J, as well as log levels and the configuration required to customize them, and log groups.

Log Messages in Spring Boot

To enable logging in Spring, import Logger and LoggerFactory from the org.slf4j API library:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

Afterwards, declare a constant to store the logger service by instantiating a logger for the class using LoggerFactory:

private static final Logger log = LoggerFactory.getLogger(DemoService.class);

This log is usually defined at the very top of the global variable list, since it’s a constant. By providing the class you want to log, it’s fully set up and ready to be called with the provided messages.

Alternatively, you can just annotate the class with @Slf4j which will automatically generate a logger for the class without having to declare a constant. The annotation supplies a static variable called log which provides the logger utilities by default:

@Slf4j
@Service
public class DemoService {
    //...
}

Note: The most common identifier for the logger is log, though you’ll also see logger in a lot of cases. Really, you’re free to call it whatever you’d like, but log is succinct and saves you from writing a longer name due to frequent calls.

Logging in Spring Boot comprises of different levels. Every log has a degree of urgency or importance that is associated with a log level. Log levels are configured at runtime and each log request checks the log level to see if the request has equal or higher priority than the log level to be displayed.

If you try logging a message which is considered less important than some threshold, it just won’t be logged.

Take this block for example, with messages of log importance in descending order:

public void logLevelDisplay () {
    logger.error("Error message");
    logger.warn("Warning message");
    logger.info("Info message");
    logger.debug("Debug message");
    logger.trace("Trace message");
}

If no configurations are set in application.properties or elsewhere, the log level will default to INFO. So if we were to call the method logLevelDisplay(), it would output something like this:

2020-12-20 12:46:35.880  ERROR 47958 --- [nio-8080-exec-1] c.service.DemoService   : Error message
2020-12-20 12:46:52.976  WARN 47958 --- [nio-8080-exec-1 c.service.DemoService    : Warn message
2020-12-20 12:46:59.104  INFO 47958 --- [nio-8080-exec-1] c.service.DemoService    : Info message

The DEBUG and TRACE messages weren’t displayed because the application’s log level is set to INFO, which has a higher priority level than the two.

If the log level was set to ERROR, then only the error message would be displayed since it’s the highest log level of the 5 built-in levels.

This brings us to an important topic — log levels, which deserve an explanation of their own.

Log Levels in Spring Boot

Logging in Spring Boot comprises of different levels. Every log has a degree of urgency or importance that is associated with a log level. For example, Hibernate SQL queries are categorized as DEBUG, which is a low-urgency log level that is mainly invoked for debugging purposes.

Logging levels allows distinction between the following sample logs:

• Successfully updated User information: Updated name John to Jon.
• NullPointerException: id of User is null

The first log is a general informative type of message while the second log is a NullPointerException message.

These logs have different levels of urgency, and distinction between them using log levels is important for filtering out logs that don’t have to be output depending on the circumstance. If there’s a huge error going on, you don’t want it to be cluttered by a bunch of working, low-level INFO logs!

SLF4J provides 5 default logging levels in Spring boot:

ERROR — Error logs are serious issues that affect a significant part of the system or some part of your application has failed to operate. Exceptions are considered ERROR level logs. Other examples of error logs are database connection failures and configuration errors. ERROR logs are the most urgent default log level in SLF4J.

WARN — Warning logs are used to indicate potential problems that might cause errors and should be monitored in case they fail. Of course, the context of a warning is subjective to the developer and the situation so warning logs might vary from system to system.

INFO —INFO is the default logging level that is set by Spring Boot. If no configurations are made, the log level is automatically set to INFO. These types of logs are information that isn’t normally needed but is useful in situations like production code debugging or determining when certain data is manipulated.

DEBUG —DEBUG logs include more detailed, specific information that aren’t needed in normal situations. This is often set as a log level when a developer is trying to deep trace a problem or a bug that is hard to trace.

TRACE — TRACE is a more granular version of DEBUG. TRACE logs are exhaustive, imagine logging every single operation the system is doing, from starting a service, initializing new variables, and calling methods.

In order of urgency, ERROR is the most urgent while TRACE is the least urgent log. The default log level in Spring Boot is INFO when no manual configuration is set.

Configuring Log Levels in Spring Boot

Log levels can be set in the Spring environment by setting its configurations in application.properties.

The format to set the log level configuration is logging.level.[classpath] = [level]. The classpath is specified since different components of the application can be configured with different log levels, which is especially useful for code isolation and debugging.

To specify a log level for all classes that don’t have their own log level settings, the root logger can be set using logging.level.root.

In application.properties:

logging.level.root=INFO
logging.level.com.test=DEBUG
logging.level.com.service.DemoService=WARN

From this configuration, every class except DemoService and the classes under the com.test classpath will have their log levels set to INFO, while the test classes and DemoService have their own specified log levels.

Log Groups

Log groups is a useful way to set logger configurations to a group of classes with different classpaths. An example is if you want to set all the test class log levels to DEBUG in one go. This is possible using the configuration logging.group.[groupName]:

# Initialize log group
logging.group.test=com.test, com.test-prod, com.apptest

# Set log level to log group
logging.level.test=DEBUG

With this approach, you won’t have to individually set the log level of all related components all the time.

Conclusion

Knowing about the different log levels is important especially in situations like debugging in production.

Let’s say a major bug has been exposed in production, and the current logs do not have enough information to diagnose the root cause of the problem. By changing the log level to DEBUG or TRACE, the logs will show much-needed information to pinpoint crucial details that may lead towards the fix.

In Spring, the log level configurations can be set in the application.properties file which is processed during runtime. Spring supports 5 default log levels, ERROR, WARN, INFO, DEBUG, and TRACE, with INFO being the default log level configuration.