Bug 63335

Summary: OneLineFormatter will append new space so that the exception stacktrace is shifted but it will not do that for all lines
Product: Tomcat 8 Reporter: jchobantonov
Component: CatalinaAssignee: Tomcat Developers Mailing List <dev>
Status: RESOLVED FIXED    
Severity: normal    
Priority: P2    
Version: 8.5.x-trunk   
Target Milestone: ----   
Hardware: PC   
OS: All   

Description jchobantonov 2019-04-10 15:57:38 UTC
OneLineFormatter will print log message and if there is exception it will prepend the exception stacktrace with a space but the issue is that a stack trace will look like this:
Sample Logging Message
<space here>Exception in thread "main" java.lang.NullPointerException
        at com.example.myproject.Book.getTitle(Book.java:16)
        at com.example.myproject.Author.getBookTitles(Author.java:25)
        at com.example.myproject.Bootstrap.main(Bootstrap.java:14)

So now all lines after the message are having a space in front and we could tell that the log message spawns multiple lines because the log message start with a space
The issue is when there is a cause to the exception then the stacktrace will look like this:
Sample Logging Message
<space here>Exception in thread "main" java.lang.NullPointerException
        at com.example.myproject.Book.getTitle(Book.java:16)
        at com.example.myproject.Author.getBookTitles(Author.java:25)
        at com.example.myproject.Bootstrap.main(Bootstrap.java:14)
Caused by: java.lang.NullPointerException
        at com.example.myproject.Book.getId(Book.java:22)
        at com.example.myproject.Author.getBookIds(Author.java:36)
        ... 1 more

So the "Caused by" will not be shifted with one space to the right
More over if the message or the exception itself have new line in their string message then we will end up with more than one line so the OneLineFormatter as a name is misleading at best

Also the configuration of the OneLineFormatter is limited - one could only specify the format of the date and that's all - it is much better to use the configuration of the java's SimpleFormatter and just extend it to support the thread name as 8'th parameter
Here is such ExtendedSimpleFormatter class as example that will use SimpleFormatter message log format pattern and replace newlines with newlines + space in log messages so that we could implement log message continuation logic in things like elasticseach's filebeat - knowing that if a new line starts with space it is continuation of the previous line.
Here is the source of the ExtendedSimpleFormatter that you could use and it was based on OneLineFormatter in parts:


package org.apache.juli;
import java.io.PrintWriter;
import java.io.StringWriter;
import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;
import java.util.Date;
import java.util.LinkedHashMap;
import java.util.Map;
import java.util.logging.Formatter;
import java.util.logging.LogManager;
import java.util.logging.LogRecord;

public class ExtendedSimpleFormatter extends Formatter {

    private static final String format = LogManager.getLogManager().getProperty(ExtendedSimpleFormatter.class.getName() + ".format");

    private static final String SEARCH_NEW_LINE = "\n";
    private static final String REPLACE_NEW_LINE = "\n ";
    private static final String NEW_LINE_PREFIX = System.lineSeparator() + " ";
    
    private final Date date = new Date();

    private static final String UNKNOWN_THREAD_NAME = "Unknown thread with ID ";
    private static final Object threadMxBeanLock = new Object();
    private static volatile ThreadMXBean threadMxBean = null;
    private static final int THREAD_NAME_CACHE_SIZE = 10000;
    private static ThreadLocal<ThreadNameCache> threadNameCache = new ThreadLocal<ThreadNameCache>() {
        @Override
        protected ThreadNameCache initialValue() {
            return new ThreadNameCache(THREAD_NAME_CACHE_SIZE);
        }
    };
    
    public synchronized String format(LogRecord record) {
        date.setTime(record.getMillis());
        String source;
        if (record.getSourceClassName() != null) {
            source = record.getSourceClassName();
            if (record.getSourceMethodName() != null) {
               source += "." + record.getSourceMethodName();
            }
        } else {
            source = record.getLoggerName();
        }
        String message = formatMessage(record);
        if (message == null) {
            message = "";
        }
        
        //replace newline with NEW_LINE_REPLACEMENT in order to distinguish regular log messages from message continuation
        message = replace(message, SEARCH_NEW_LINE, REPLACE_NEW_LINE);
        
        String throwable = "";
        if (record.getThrown() != null) {
            StringWriter sw = new StringWriter();
            PrintWriter pw = new PrintWriter(sw);
            record.getThrown().printStackTrace(pw);
            pw.close();
            throwable = sw.toString().trim();
            
            //replace newline with NEW_LINE_REPLACEMENT in order to distinguish regular log messages from message continuation
            throwable = NEW_LINE_PREFIX + replace(throwable, SEARCH_NEW_LINE, REPLACE_NEW_LINE);
        }
        
        String threadName = "";
        if (Thread.currentThread().getId() == record.getThreadID() && record.getThreadID() < (Integer.MAX_VALUE / 2)) {
            threadName = Thread.currentThread().getName();
        } else {
            threadName = getThreadName(record.getThreadID());
        }        
        
        return String.format(format,
                             date,
                             source,
                             record.getLoggerName(),
                             record.getLevel().getLocalizedName(),
                             message,
                             throwable,
                             threadName);
    }
    
    /*
     * LogRecord has threadID but no thread name.
     * LogRecord uses an int for thread ID but thread IDs are longs.
     * If the real thread ID > (Integer.MAXVALUE / 2) LogRecord uses it's own
     * ID in an effort to avoid clashes due to overflow.
     */    
    private static String getThreadName(int logRecordThreadId) {
        Map<Integer,String> cache = threadNameCache.get();
        String result = null;

        if (logRecordThreadId > (Integer.MAX_VALUE / 2)) {
            result = cache.get(Integer.valueOf(logRecordThreadId));
        }

        if (result != null) {
            return result;
        }

        if (logRecordThreadId >= (Integer.MAX_VALUE / 2)) {
            result = UNKNOWN_THREAD_NAME + logRecordThreadId;
        } else {
            // Double checked locking OK as threadMxBean is volatile
            if (threadMxBean == null) {
                synchronized (threadMxBeanLock) {
                    if (threadMxBean == null) {
                        threadMxBean = ManagementFactory.getThreadMXBean();
                    }
                }
            }
            ThreadInfo threadInfo =
                    threadMxBean.getThreadInfo(logRecordThreadId);
            if (threadInfo == null) {
                return Long.toString(logRecordThreadId);
            }
            result = threadInfo.getThreadName();
        }

        cache.put(Integer.valueOf(logRecordThreadId), result);

        return result;
    }
    

    private static class ThreadNameCache extends LinkedHashMap<Integer,String> {

        private static final long serialVersionUID = 1L;

        private final int cacheSize;

        public ThreadNameCache(int cacheSize) {
            this.cacheSize = cacheSize;
        }

        @Override
        protected boolean removeEldestEntry(Map.Entry<Integer, String> eldest) {
            return (size() > cacheSize);
        }
    }
    
    private static String replace(String text, String searchString, String replacement) {
        if (text == null || text.length() == 0 || searchString == null || searchString.length() == 0 || replacement == null) {
            return text;
        }
        int start = 0;
        int end = text.indexOf(searchString, start);
        if (end == -1) {
            return text;
        }
        final int replLength = searchString.length();
        int increase = replacement.length() - replLength;
        increase = increase < 0 ? 0 : increase;
        increase *= 16;
        final StringBuilder buf = new StringBuilder(text.length() + increase);
        while (end != -1) {
            buf.append(text, start, end).append(replacement);
            start = end + replLength;
            end = text.indexOf(searchString, start);
        }
        buf.append(text, start, text.length());
        return buf.toString();
    }
}

and here is how to configure it in logging.properties file:
java.util.logging.ConsoleHandler.formatter = org.apache.juli.ExtendedSimpleFormatter
org.apache.juli.ExtendedSimpleFormatter.format = %1$tY-%1$tm-%1$td %1$tH:%1$tM:%1$tS.%1$tL %4$s [%7$s] %2$s %5$s%6$s%n

the format is using the java's standard SimpleFormat but with the extension that we provide thread name as well as parameter 7: %7
Comment 1 Mark Thomas 2019-04-29 21:27:02 UTC
The OneLineFormatter has been fixed so it always indents all parts of a stacktrace. I have also removed the additional blank line added after a stack trace.

Fixed in:
- master for 9.0.20 onwards
- 8.5.x for 8.5.41 onwards
- 7.0.x for 7.0.95 onwards

I haven't added the ExtendedSimpleFormatter as there does not appear to be sufficient demand for it at this time.