6381464: SimpleFormatter should use one single line format

Summary: Define a new logging properties to support custom output format
Reviewed-by: alanb

src/share/classes/java/util/logging/LoggingProxyImpl.java

@@ -99,4 +99,9 @@ class LoggingProxyImpl implements LoggingProxy {
     public String getLevelName(Object level) {
         return ((Level) level).getName();
     }
+
+    @Override
+    public String getProperty(String key) {
+        return LogManager.getLogManager().getProperty(key);
+    }
 }

src/share/classes/java/util/logging/SimpleFormatter.java

@@ -29,31 +29,108 @@ package java.util.logging;
 import java.io.*;
 import java.text.*;
 import java.util.Date;
+import sun.util.logging.LoggingSupport;
 
 /**
- * Print a brief summary of the LogRecord in a human readable
+ * Print a brief summary of the {@code LogRecord} in a human readable
  * format.  The summary will typically be 1 or 2 lines.
  *
+ * <p>
+ * <a name="formatting">
+ * <b>Configuration:</b></a>
+ * The {@code SimpleFormatter} is initialized with the
+ * <a href="../Formatter.html#syntax">format string</a>
+ * specified in the {@code java.util.logging.SimpleFormatter.format}
+ * property to {@linkplain #format format} the log messages.
+ * This property can be defined
+ * in the {@linkplain LogManager#getProperty logging properties}
+ * configuration file
+ * or as a system property.  If this property is set in both
+ * the logging properties and system properties,
+ * the format string specified in the system property will be used.
+ * If this property is not defined or the given format string
+ * is {@linkplain java.util.IllegalFormatException illegal},
+ * the default format is implementation-specific.
+ *
  * @since 1.4
+ * @see java.util.Formatter
  */
 
 public class SimpleFormatter extends Formatter {
 
-    Date dat = new Date();
-    private final static String format = "{0,date} {0,time}";
-    private MessageFormat formatter;
-
-    private Object args[] = new Object[1];
-
-    // Line separator string.  This is the value of the line.separator
-    // property at the moment that the SimpleFormatter was created.
-    private String lineSeparator = java.security.AccessController.doPrivileged(
-               new sun.security.action.GetPropertyAction("line.separator"));
+    // format string for printing the log record
+    private static final String format = LoggingSupport.getSimpleFormat();
+    private final Date dat = new Date();
 
     /**
      * Format the given LogRecord.
      * <p>
-     * This method can be overridden in a subclass.
+     * The formatting can be customized by specifying the
+     * <a href="../Formatter.html#syntax">format string</a>
+     * in the <a href="#formatting">
+     * {@code java.util.logging.SimpleFormatter.format}</a> property.
+     * The given {@code LogRecord} will be formatted as if by calling:
+     * <pre>
+     *    {@link String#format String.format}(format, date, source, logger, level, message, thrown);
+     * </pre>
+     * where the arguments are:<br>
+     * <ol>
+     * <li>{@code format} - the {@link java.util.Formatter
+     *     java.util.Formatter} format string specified in the
+     *     {@code java.util.logging.SimpleFormatter.format} property
+     *     or the default format.</li>
+     * <li>{@code date} - a {@link Date} object representing
+     *     {@linkplain LogRecord#getMillis event time} of the log record.</li>
+     * <li>{@code source} - a string representing the caller, if available;
+     *     otherwise, the logger's name.</li>
+     * <li>{@code logger} - the logger's name.</li>
+     * <li>{@code level} - the {@linkplain Level#getLocalizedName
+     *     log level}.</li>
+     * <li>{@code message} - the formatted log message
+     *     returned from the {@link Formatter#formatMessage(LogRecord)}
+     *     method.  It uses {@link java.text.MessageFormat java.text}
+     *     formatting and does not use the {@code java.util.Formatter
+     *     format} argument.</li>
+     * <li>{@code thrown} - a string representing
+     *     the {@linkplain LogRecord#getThrown throwable}
+     *     associated with the log record and its backtrace
+     *     beginning with a newline character, if any;
+     *     otherwise, an empty string.</li>
+     * </ol>
+     *
+     * <p>Some example formats:<br>
+     * <ul>
+     * <li> {@code java.util.logging.SimpleFormatter.format="%4$s: %5$s [%1$tc]%n"}
+     *     <p>This prints 1 line with the log level ({@code 4$}),
+     *     the log message ({@code 5$}) and the timestamp ({@code 1$}) in
+     *     a square bracket.
+     *     <pre>
+     *     WARNING: warning message [Tue Mar 22 13:11:31 PDT 2011]
+     *     </pre></li>
+     * <li> {@code java.util.logging.SimpleFormatter.format="%1$tc %2$s%n%4$s: %5$s%6$s%n"}
+     *     <p>This prints 2 lines where the first line includes
+     *     the timestamp ({@code 1$}) and the source ({@code 2$});
+     *     the second line includes the log level ({@code 4$}) and
+     *     the log message ({@code 5$}) followed with the throwable
+     *     and its backtrace ({@code 6$}), if any:
+     *     <pre>
+     *     Tue Mar 22 13:11:31 PDT 2011 MyClass fatal
+     *     SEVERE: several message with an exception
+     *     java.lang.IllegalArgumentException: invalid argument
+     *             at MyClass.mash(MyClass.java:9)
+     *             at MyClass.crunch(MyClass.java:6)
+     *             at MyClass.main(MyClass.java:3)
+     *     </pre></li>
+     * <li> {@code java.util.logging.SimpleFormatter.format="%1$tb %1$td, %1$tY %1$tl:%1$tM:%1$tS %1$Tp %2$s%n%4$s: %5$s%n"}
+     *      <p>This prints 2 lines similar to the example above
+     *         with a different date/time formatting and does not print
+     *         the throwable and its backtrace:
+     *     <pre>
+     *     Mar 22, 2011 1:11:31 PM MyClass fatal
+     *     SEVERE: several message with an exception
+     *     </pre></li>
+     * </ul>
+     * <p>This method can also be overridden in a subclass.
      * It is recommended to use the {@link Formatter#formatMessage}
      * convenience method to localize and format the message field.
      *
@@ -61,42 +138,32 @@ public class SimpleFormatter extends Formatter {
      * @return a formatted log record
      */
     public synchronized String format(LogRecord record) {
-        StringBuffer sb = new StringBuffer();
-        // Minimize memory allocations here.
         dat.setTime(record.getMillis());
-        args[0] = dat;
-        StringBuffer text = new StringBuffer();
-        if (formatter == null) {
-            formatter = new MessageFormat(format);
-        }
-        formatter.format(args, text, null);
-        sb.append(text);
-        sb.append(" ");
+        String source;
         if (record.getSourceClassName() != null) {
-            sb.append(record.getSourceClassName());
-        } else {
-            sb.append(record.getLoggerName());
-        }
+            source = record.getSourceClassName();
             if (record.getSourceMethodName() != null) {
-            sb.append(" ");
-            sb.append(record.getSourceMethodName());
+               source += " " + record.getSourceMethodName();
+            }
+        } else {
+            source = record.getLoggerName();
         }
-        sb.append(lineSeparator);
         String message = formatMessage(record);
-        sb.append(record.getLevel().getLocalizedName());
-        sb.append(": ");
-        sb.append(message);
-        sb.append(lineSeparator);
+        String throwable = "";
         if (record.getThrown() != null) {
-            try {
             StringWriter sw = new StringWriter();
             PrintWriter pw = new PrintWriter(sw);
+            pw.println();
             record.getThrown().printStackTrace(pw);
             pw.close();
-                sb.append(sw.toString());
-            } catch (Exception ex) {
-            }
+            throwable = sw.toString();
         }
-        return sb.toString();
+        return String.format(format,
+                             dat,
+                             source,
+                             record.getLoggerName(),
+                             record.getLevel().getLocalizedName(),
+                             message,
+                             throwable);
     }
 }

src/share/classes/sun/util/logging/LoggingProxy.java

@@ -60,4 +60,7 @@ public interface LoggingProxy {
     public Object parseLevel(String levelName);
 
     public String getLevelName(Object level);
+
+    // return the logging property
+    public String getProperty(String key);
 }

src/share/classes/sun/util/logging/LoggingSupport.java

@@ -29,6 +29,7 @@ package sun.util.logging;
 import java.lang.reflect.Field;
 import java.security.AccessController;
 import java.security.PrivilegedAction;
+import java.util.Date;
 
 /**
  * Internal API to support JRE implementation to detect if the java.util.logging
@@ -138,4 +139,42 @@ public class LoggingSupport {
         ensureAvailable();
         return proxy.getLevelName(level);
     }
+
+    private static final String DEFAULT_FORMAT =
+        "%1$tb %1$td, %1$tY %1$tl:%1$tM:%1$tS %1$Tp %2$s%n%4$s: %5$s%6$s%n";
+
+    private static final String FORMAT_PROP_KEY = "java.util.logging.SimpleFormatter.format";
+    public static String getSimpleFormat() {
+        return getSimpleFormat(true);
+    }
+
+    // useProxy if true will cause initialization of
+    // java.util.logging and read its configuration
+    static String getSimpleFormat(boolean useProxy) {
+        String format =
+            AccessController.doPrivileged(
+                new PrivilegedAction<String>() {
+                    public String run() {
+                        return System.getProperty(FORMAT_PROP_KEY);
+                    }
+                });
+
+        if (useProxy && proxy != null && format == null) {
+            format = proxy.getProperty(FORMAT_PROP_KEY);
+        }
+
+        if (format != null) {
+            try {
+                // validate the user-defined format string
+                String.format(format, new Date(), "", "", "", "", "");
+            } catch (IllegalArgumentException e) {
+                // illegal syntax; fall back to the default format
+                format = DEFAULT_FORMAT;
+            }
+        } else {
+            format = DEFAULT_FORMAT;
+        }
+        return format;
+    }
+
 }

src/share/classes/sun/util/logging/PlatformLogger.java

@@ -316,12 +316,6 @@ public class PlatformLogger {
      */
     static class LoggerProxy {
         private static final PrintStream defaultStream = System.err;
-        private static final String lineSeparator = AccessController.doPrivileged(
-            new PrivilegedAction<String>() {
-                public String run() {
-                    return System.getProperty("line.separator");
-                }
-            });
 
         final String name;
         volatile int levelValue;
@@ -353,14 +347,14 @@ public class PlatformLogger {
             if (level < levelValue || levelValue == OFF) {
                 return;
             }
-            defaultStream.println(format(level, msg, null));
+            defaultStream.print(format(level, msg, null));
         }
 
         void doLog(int level, String msg, Throwable thrown) {
             if (level < levelValue || levelValue == OFF) {
                 return;
             }
-            defaultStream.println(format(level, msg, thrown));
+            defaultStream.print(format(level, msg, thrown));
         }
 
         void doLog(int level, String msg, Object... params) {
@@ -368,7 +362,7 @@ public class PlatformLogger {
                 return;
             }
             String newMsg = formatMessage(msg, params);
-            defaultStream.println(format(level, newMsg, null));
+            defaultStream.print(format(level, newMsg, null));
         }
 
         public boolean isLoggable(int level) {
@@ -378,12 +372,6 @@ public class PlatformLogger {
             return true;
         }
 
-        private static final String format = "{0,date} {0,time}";
-
-        private Object args[] = new Object[1];
-        private MessageFormat formatter;
-        private Date dat;
-
         // Copied from java.util.logging.Formatter.formatMessage
         private String formatMessage(String format, Object... parameters) {
             // Do the formatting.
@@ -408,37 +396,30 @@ public class PlatformLogger {
             }
         }
 
+        private static final String formatString =
+            LoggingSupport.getSimpleFormat(false); // don't check logging.properties
+
+        // minimize memory allocation
+        private Date date = new Date();
         private synchronized String format(int level, String msg, Throwable thrown) {
-            StringBuffer sb = new StringBuffer();
-            // Minimize memory allocations here.
-            if (dat == null) {
-                dat = new Date();
-                formatter = new MessageFormat(format);
-            }
-            dat.setTime(System.currentTimeMillis());
-            args[0] = dat;
-            StringBuffer text = new StringBuffer();
-            formatter.format(args, text, null);
-            sb.append(text);
-            sb.append(" ");
-            sb.append(getCallerInfo());
-            sb.append(lineSeparator);
-            sb.append(PlatformLogger.getLevelName(level));
-            sb.append(": ");
-            sb.append(msg);
+            date.setTime(System.currentTimeMillis());
+            String throwable = "";
             if (thrown != null) {
-                try {
                 StringWriter sw = new StringWriter();
                 PrintWriter pw = new PrintWriter(sw);
+                pw.println();
                 thrown.printStackTrace(pw);
                 pw.close();
-                    sb.append(sw.toString());
-                } catch (Exception ex) {
-                    throw new AssertionError(ex);
-                }
+                throwable = sw.toString();
             }
 
-            return sb.toString();
+            return String.format(formatString,
+                                 date,
+                                 getCallerInfo(),
+                                 name,
+                                 PlatformLogger.getLevelName(level),
+                                 msg,
+                                 throwable);
         }
 
         // Returns the caller's class and method's name; best effort

src/share/lib/logging.properties

@@ -43,6 +43,11 @@ java.util.logging.FileHandler.formatter = java.util.logging.XMLFormatter
 java.util.logging.ConsoleHandler.level = INFO
 java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
 
+# Example to customize the SimpleFormatter output format 
+# to print one-line log message like this:
+#     <level>: <log message> [<date/time>]
+#
+# java.util.logging.SimpleFormatter.format=%4$s: %5$s [%1$tc]%n
 
 ############################################################
 # Facility specific properties.

test/java/util/logging/SimpleFormatterFormat.java

+/*
+ * Copyright (c) 2011, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+
+/*
+ * @test
+ * @bug     6381464
+ * @summary Test the custom simple formatter output
+ *
+ * @run main/othervm SimpleFormatterFormat
+ */
+
+import java.io.*;
+import java.util.logging.*;
+import java.util.regex.*;
+
+public class SimpleFormatterFormat {
+    private static final String key = "java.util.logging.SimpleFormatter.format";
+    private static final String origFormat = System.getProperty(key);
+    private static final PrintStream err = System.err;
+    public static void main(String[] args) throws Exception {
+        try {
+            File dir = new File(System.getProperty("user.dir", "."));
+            File log = new File(dir, "simpleformat.txt");
+            java.nio.file.Files.deleteIfExists(log.toPath());
+            PrintStream logps = new PrintStream(log);
+            System.setProperty(key, "%3$s:%4$s: %5$s [%1$tc] source: %2$s%6$s%n");
+            writeLogRecords(logps);
+            checkLogRecords(log);
+        } finally {
+            if (origFormat == null) {
+                System.clearProperty(key);
+            } else {
+                System.setProperty(key, origFormat);
+            }
+            System.setErr(err);
+       }
+    }
+
+    private static String[] loggers = new String[] {
+        "test.foo",
+        "test.foo",
+        "test.bar",
+        "test.bar"
+    };
+    private static String[] messages = new String[] {
+        "severe hello world",
+        "warning lost connection",
+        "info welcome",
+        "warning exception thrown",
+    };
+    private static void writeLogRecords(PrintStream logps) throws Exception {
+        try {
+            System.setErr(logps);
+
+            Logger foo = Logger.getLogger("test.foo");
+            foo.log(Level.SEVERE, "{0} {1} {2}", new Object[] {"severe", "hello", "world"});
+            foo.warning(messages[1]);
+
+            Logger bar = Logger.getLogger("test.bar");
+            bar.finest("Dummy message");
+            bar.info(messages[2]);
+            bar.log(Level.WARNING, messages[3], new IllegalArgumentException());
+
+        } finally {
+            logps.flush();
+            logps.close();
+            System.setErr(err);
+        }
+    }
+
+    private static void checkLogRecords(File log) throws Exception {
+        System.out.println("Checking log records in file: " + log);
+        Pattern p = Pattern.compile("([\\.a-zA-Z:]+) (.*) \\[.*\\] source: (.*)");
+
+        try (FileInputStream in = new FileInputStream(log)) {
+            BufferedReader reader = new BufferedReader(new InputStreamReader(in));
+            String line;
+            int i = 0;
+            while (i < messages.length &&
+                      (line = reader.readLine()) != null) {
+                String expectedLogger = loggers[i];
+                String expectedMsg = messages[i];
+                i++;
+
+                line = line.trim();
+                System.out.println(line);
+
+                Matcher m = p.matcher(line);
+                if (!m.matches()) {
+                    throw new RuntimeException("Unexpected output format");
+                }
+                if (m.groupCount() != 3) {
+                    throw new RuntimeException("Unexpected group count = " +
+                        m.groupCount());
+                }
+                // verify logger name and level
+                String[] ss = m.group(1).split(":");
+                int len = ss.length;
+                if (len != 2) {
+                    throw new RuntimeException("Unexpected logger name and level" +
+                        m.group(1));
+                }
+
+                verify(expectedLogger, expectedMsg, ss[0], ss[1], m.group(2), m.group(3));
+            }
+
+            // expect IllegalArgumentException following it
+            line = reader.readLine().trim();
+            if (!line.equals("java.lang.IllegalArgumentException")) {
+                throw new RuntimeException("Invalid line: " + line);
+            }
+        }
+    }
+
+    private static void verify(String expectedLogger, String expectedMsg,
+                               String logger, String level,
+                               String msg, String source) {
+        if (!logger.equals(expectedLogger)) {
+            throw new RuntimeException("Unexpected logger: " + logger);
+        }
+        if (!msg.equals(expectedMsg)) {
+            throw new RuntimeException("Unexpected message: " + msg);
+        }
+
+        String[] ss = expectedMsg.split("\\s+");
+        String expectedLevel = ss[0].toUpperCase();
+        if (!level.equals(expectedLevel)) {
+            throw new RuntimeException("Unexpected level: " + level);
+        }
+
+        ss = source.split("\\s+");
+        int len = ss.length;
+        if (!(len == 2 &&
+              ss[0].equals("SimpleFormatterFormat") &&
+              ss[1].equals("writeLogRecords"))) {
+            throw new RuntimeException("Unexpected source: " + source);
+        }
+    }
+}

test/sun/util/logging/PlatformLoggerTest.java

@@ -26,10 +26,11 @@
  * @bug     6882376 6985460
  * @summary Test if java.util.logging.Logger is created before and after
  *          logging is enabled.  Also validate some basic PlatformLogger
- *          operations.
+ *          operations.  othervm mode to make sure java.util.logging
+ *          is not initialized.
  *
  * @compile -XDignore.symbol.file PlatformLoggerTest.java
- * @run main PlatformLoggerTest
+ * @run main/othervm PlatformLoggerTest
  */
 
 import java.util.logging.*;