How come this stacktrace isn’t preceded by this line in the logs?

Dears,

I have this code: (Move.java)

public void execute(ArrayList<Move> performedMoves) {

    logger.debug(Thread.currentThread().getName() + " executing: from: " + from.getX() + ", " + from.getY() + " -> "
            + to.getX() + ", " + to.getY() + " p: " + piece.getShortDebug() + "->" + piece.executed + ", "
            + piece.rollbacked + ";" + "|" + piece.getCurrentPlace().getX() + ", "
            + piece.getCurrentPlace().getY());

    if (executed && !rollbacked) {

        throw new RuntimeException("this shouldn't be...");
    }

    //(more code)

    from.remove(piece); // line 111, throwing the exception

    to.setPiece(piece);

    piece.setCurrentPlace(to);

And this is the log:

2021-03-07 11:12:57 DEBUG Move:195 - Thread-3 rollBack: from: 0, 2 -> 1, 2 p: t->true, false|0, 2
2021-03-07 11:12:57 DEBUG Move:148 - Thread-3 rollBack: from: 2, 1 -> 1, 2 p: p->true, false|1, 2
2021-03-07 11:12:57 DEBUG Move:156 - Thread-3 false, false|1, 2
2021-03-07 11:12:57 DEBUG Move:168 - Thread-3 false, false|1, 2
2021-03-07 11:12:57 DEBUG Move:195 - Thread-3 rollBack: from: 2, 1 -> 1, 2 p: p->true, false|2, 1
Exception in thread "Thread-3" org.bamboomy.c44.board.IllegalPlaceException: this piece wasn't here :-( -> 2, 0 == 2, 9=>t->true, true
        at org.bamboomy.c44.board.Place.remove(Place.java:190)
        at org.bamboomy.c44.board.Move.execute(Move.java:111)
        at org.bamboomy.c44.board.Robot$Agent.evaluate(Robot.java:753)
        at org.bamboomy.c44.board.Robot$Agent.evaluate(Robot.java:772)
        at org.bamboomy.c44.board.Robot$Agent.evaluate(Robot.java:772)
        at org.bamboomy.c44.board.Robot$Agent.evaluate(Robot.java:772)
        at org.bamboomy.c44.board.Robot$Agent.run(Robot.java:608)
        at java.base/java.lang.Thread.run(Thread.java:834)
2021-03-07 11:12:58 DEBUG Robot:374 - 0:-1.7976931348623157E308
2021-03-07 11:12:58 DEBUG Robot:374 - 1:-1.7976931348623157E308

How come the stacktrace in the log is preceded by:

2021-03-07 11:12:57 DEBUG Move:195 - Thread-3 rollBack: from: 2, 1 -> 1, 2 p: p->true, false|2, 1

in stead of something like:

2021-03-07 11:12:57 DEBUG Move:195 - Thread-3 executing: from: 2, 1 -> 1, 2 p: p->true, false|2, 1

(the log entry just before the exception is thrown)?

(the “rollback” debug entry is done in another method in the same class)

also:

if for some synchronisation issue for example this log entry is swallowed (I presume it’s something like that): how can I force or flush the logger so I can have the output of that debug message?

It’s very valuable information and it would help me a lot in debugging a complex problem…

Thanks for reading/pointers…

S.

edit: I use log4j 1.2.17

and the logger is inited like this:

final static Logger logger = Logger.getLogger(Move.class);

Answer

That output is sent directly to System.err via the Thread::getUncaughtExceptionHandler.

Per OpenJDK ThreadGroup::uncaughtException

public void uncaughtException(Thread t, Throwable e) {
    if (parent != null) {
        parent.uncaughtException(t, e);
    } else {
        Thread.UncaughtExceptionHandler ueh =
            Thread.getDefaultUncaughtExceptionHandler();
        if (ueh != null) {
            ueh.uncaughtException(t, e);
        } else if (!(e instanceof ThreadDeath)) {
            System.err.print("Exception in thread ""
                             + t.getName() + "" ");
            e.printStackTrace(System.err);
        }
    }
}

This code is bypassing your logging framework and printing directly to System.err when an uncaught exception is thrown and escapes the run method of the current thread.

If you want the code to contain a timestamp you have to do one of the following:

  1. Implement a Thread.UncaughtExceptionHandler which logs to your logging framework. Then attach it to the all threads or a subset of threads when your application starts. Keep in mind that in environments with complex classloader structures this handler can pin the classloader and cause a memory leak. Good code hygiene would be to remove these handlers when your application is going to be shutdown.
  2. In your runnable or callable implementation catch Throwable and log it to your logging framework.

Leave a Reply

Your email address will not be published. Required fields are marked *