Replace all Throwable.printStackTrace() with logging

[tfmorris]

In investigating #5354, I realized that this is just the tip of the iceberg and there are a large number of places (~100) in the code where a naked e.printStackTrace() call is used. These should all be converted to using logging so that they can be turned on/off, routed to log collectors, reformatted, etc.

By default they probably just need to replace with something like LOGGER.error("<Meaningful error message here>", e)

Note that there are also some calls to printStackTrace(PrintWriter s) which is used to get a formatted stack trace to forward to the front end. These are probably fine as is.

[wetneb]

One problem with LOGGER.error("<Meaningful error message here>", e) is that the stack trace is not logged, which can make it harder to debug problems. Is there any way to go through the logger but still have the stack trace?

[tfmorris]

You should get stack traces if a) you include a Throwable and b) your appender is configured to include stack traces (which is, I believe, the default). https://logging.apache.org/log4j/2.x/manual/layouts.html#PatternLayout

Can you give more details about the case where it's not behaving as you expect?

[wetneb]

With OpenRefine's current logger settings (when running the application), the line logger.error("exception caught", e) where e is an exception generates the following logging line:

10:18:30.424 [                   refine] exception caught  (5ms)

I cannot see any stack trace there.

[thadguidry]

It is getting swallowed likely. https://logging.apache.org/log4j/2.x/log4j-api/apidocs/src-html/org/apache/logging/log4j/Logger.html#line.85 Perhaps being explicit might push it out? Just set the level to trace using log method with a trace level explicity? https://logging.apache.org/log4j/2.x/log4j-api/apidocs/org/apache/logging/log4j/Logger.html#log-org.apache.logging.log4j.Level-java.lang.String-java.lang.Throwable-

Or this way now with Java 8:

With Java 8, the same effect can be achieved with a lambda expression:

 // Java-8 style optimization: no need to explicitly check the log level:
 // the lambda expression is not evaluated if the TRACE level is not enabled
 logger.trace("Some long-running operation returned {}", () -> expensiveOperation());

[daluu]

Interesting topic here, any updates or ETA to this?

[tfmorris]

Hi @daluu. Thanks for your interest. Some have been addressed, but most haven't and there is no ETA.

Do you have a specific interest related to this? Would it help you with debugging something or are you looking for a place to contribute?

[daluu]

I was just looking into the subject of sending the stack trace to logger and came across this GH issue was all, and there are different approaches to handling that as I've seen online. It's unfortunate that the logger may truncate the stack trace when you provide the throwable depending on logger config from what I read, it'd be nicer if you can tell the logger whether to care to truncate or not when you invoke the log statement.

For me I previously used and just settled with passing ExceptionUtils.getStackTrace(e) to the logger.

[thadguidry]

I don't think it HAS to truncate. I think there are options to control that. You just need to use best practices, which are documented here: https://logging.apache.org/log4j/2.x/manual/api.html

I.E.

Don’t use Throwable#getMessage()! This prevents the log event from getting enriched with the exception. /* BAD! */ LOGGER.info("failed", exception.getMessage()); /* BAD! */ LOGGER.info("failed for user ID `{}`: {}", userId, exception.getMessage());

instead

Pass exception as the last extra argument: /* GOOD */ LOGGER.error("failed", exception); /* GOOD */ LOGGER.error("failed for user ID `{}`", userId, exception);

[thadguidry]

You could also use Flow Tracing, alternatively, where it makes sense (and Logback helps a lot here): https://logging.apache.org/log4j/2.x/manual/flowtracing.html

[tfmorris]

This got kind of sidetracked by the stack trace discussion, but that problem has since been fixed in #6376.

I've also updated the original issue to clarify that logging is not always the right answer. Some of these cases are, even more critically, places where an error needs to be returned to the client/user.

Current counts are: core 25, main/server/openrefine 22, wikibase 8, database 20, grel 1