TCA#append(LogEvent) throws IllegalStateException after LineReader#readLine(String)

[FerusGrim]

During normal logging, no issues seem to appear.

However, when submitting a message, this stacktrace is always thrown:

2017-06-25 23:40:29,706 main ERROR An exception occurred processing Appender Console java.lang.IllegalStateException
    at org.jline.reader.impl.LineReaderImpl.callWidget(LineReaderImpl.java:636)
    at net.minecrell.terminalconsole.TerminalConsoleAppender.append(TerminalConsoleAppender.java:269)
    at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:433)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:403)
    at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
    at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2091)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1993)
    at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1852)
    at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:179)
    at tech.ferus.dungeonbot.DungeonBot.shutdown(DungeonBot.java:75)
    at tech.ferus.dungeonbot.commands.ConsoleListener.startReader(ConsoleListener.java:71)
    at tech.ferus.dungeonbot.Launcher.main(Launcher.java:115)

The stacktrace seems to be referring to:

reader.callWidget(LineReader.CLEAR);

When that line is commented out, the same error occurs but then points to:

reader.callWidget(LineReader.REDRAW_LINE);

And then:

reader.callWidget(LineReader.REDISPLAY);

It may be more apt to say that any calls to LineReader#callWidget(String) are resulting in an IllegalStateException.

It's worth noting, however, that the command/input DOES get processed correctly.

[FerusGrim]

Just for further clarification, the error is more specifically occurring at where TCA#append(LogEvent) calls to LineReaderImpl#callWidget(String), at this line:

        if (!reading) {
            throw new IllegalStateException();
        }

So... for whatever reason, the implementation of LineReader is declaring that it's NOT reading?

[FerusGrim]

In case this an error on my part, somehow, here is my related code:

https://gist.github.com/FerusGrim/cc20a87f7529012ca154539de1a1047a

[stephan-gh]

You need to remove the reader from TerminalConsoleAppender before writing to the logger again. Normally, this is handled by the finally block, however the problem here is the way you shutdown the application, directly in the console thread. It should work if you add TerminalConsoleAppender.setReader(null) directly before the logger call in the catch block of UserInterruptException: https://gist.github.com/FerusGrim/cc20a87f7529012ca154539de1a1047a#file-consolelistener-java-L47

Edit: Same applies for your call above in https://gist.github.com/FerusGrim/cc20a87f7529012ca154539de1a1047a#file-consolelistener-java-L42. I recommend that you never execute commands/the shutdown on the console thread but just set an indication for the main/another thread that a command was executed (e.g. a queue). This will make sure that the console is always available for command input without delays.

This should fix the error in most cases. I'm aware that there are some race conditions in which it is possible that the reader is still registered in the illegal state when a new message is sent but I haven't found a simple solution for that yet.

[FerusGrim]

Yup! The above definitely fixes it.

For future reference: (TL;DR of @Minecrell's post)

• Executions should be done on another thread.
• If Logging on the same thread, make sure to hit TerminalConsoleAppender.setReader(null)
• Minecrell is amazing. <3

[stephan-gh]

@FerusGrim Thanks for the summary! :)

[stephan-gh]

Note: With TCA 1.1.0 it is no longer necessary to temporarily call TerminalConsoleAppender.setReader(null) when running the command on the same thread. You should only call it if you no longer need the LineReader so it can be destroyed by GC.