http-client-branch: HPACK.Logger uses DebugLogger http-client-branch
authordfuchs
Wed, 08 Nov 2017 18:11:00 +0000
branchhttp-client-branch
changeset 55790 d73370fdf575
parent 55789 b3562d42f3b1
child 55791 4849d9e433be
http-client-branch: HPACK.Logger uses DebugLogger
src/jdk.incubator.httpclient/share/classes/jdk/incubator/http/internal/common/DebugLogger.java
src/jdk.incubator.httpclient/share/classes/jdk/incubator/http/internal/common/Utils.java
src/jdk.incubator.httpclient/share/classes/jdk/incubator/http/internal/hpack/HPACK.java
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/src/jdk.incubator.httpclient/share/classes/jdk/incubator/http/internal/common/DebugLogger.java	Wed Nov 08 18:11:00 2017 +0000
@@ -0,0 +1,252 @@
+/*
+ * Copyright (c) 2015, 2016, 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.  Oracle designates this
+ * particular file as subject to the "Classpath" exception as provided
+ * by Oracle in the LICENSE file that accompanied this code.
+ *
+ * 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.
+ */
+package jdk.incubator.http.internal.common;
+
+import java.io.PrintStream;
+import java.util.Objects;
+import java.util.ResourceBundle;
+import java.util.function.Supplier;
+import java.lang.System.Logger;
+
+/**
+ * A {@code System.Logger} that forwards all messages to an underlying
+ * {@code System.Logger}, after adding some decoration.
+ * The logger also has the ability to additionally send the logged messages
+ * to System.err or System.out, whether the underlying logger is activated or not.
+ * In addition instance of {@code DebugLogger} support both
+ * {@link String#format(String, Object...)} and
+ * {@link java.text.MessageFormat#format(String, Object...)} formatting.
+ * String-like formatting is enabled by the presence of "%s" or "%d" in the format
+ * string. MessageFormat-like formatting is enabled by the presence of "{0" or "{1".
+ * <p>
+ * See {@link Utils#getDebugLogger(Supplier, boolean)} and
+ * {@link Utils#getHpackLogger(Supplier, boolean)}.
+ */
+class DebugLogger implements Logger {
+    // deliberately not in the same subtree than standard loggers.
+    final static String HTTP_NAME  = "jdk.internal.httpclient.debug";
+    final static String HPACK_NAME = "jdk.internal.httpclient.hpack.debug";
+    final static Logger HTTP = System.getLogger(HTTP_NAME);
+    final static Logger HPACK = System.getLogger(HPACK_NAME);
+    final static long START_NANOS = System.nanoTime();
+
+    private final Supplier<String> dbgTag;
+    private final Level errLevel;
+    private final Level outLevel;
+    private final Logger logger;
+    private final boolean debugOn;
+    private final boolean traceOn;
+
+    /**
+     * Create a logger for debug traces.The logger should only be used
+     * with levels whose severity is {@code <= DEBUG}.
+     *
+     * By default, this logger will forward all messages logged to the supplied
+     * {@code logger}.
+     * But in addition, if the message severity level is {@code >=} to
+     * the provided {@code errLevel} it will print the messages on System.err,
+     * and if the message severity level is {@code >=} to
+     * the provided {@code outLevel} it will also print the messages on System.out.
+     * <p>
+     * The logger will add some decoration to the printed message, in the form of
+     * {@code <Level>:[<thread-name>] [<elapsed-time>] <dbgTag>: <formatted message>}
+     *
+     * @apiNote To obtain a logger that will always print things on stderr in
+     *          addition to forwarding to the internal logger, use
+     *          {@code new DebugLogger(logger, this::dbgTag, Level.OFF, Level.ALL);}.
+     *          To obtain a logger that will only forward to the internal logger,
+     *          use {@code new DebugLogger(logger, this::dbgTag, Level.OFF, Level.OFF);}.
+     *
+     * @param logger The internal logger to which messages will be forwarded.
+     *               This should be either {@link #HPACK} or {@link #HTTP};
+     *
+     * @param dbgTag A lambda that returns a string that identifies the caller
+     *               (e.g: "SocketTube(3)", or "Http2Connection(SocketTube(3))")
+     * @param outLevel The level above which messages will be also printed on
+     *               System.out (in addition to being forwarded to the internal logger).
+     * @param errLevel The level above which messages will be also printed on
+     *               System.err (in addition to being forwarded to the internal logger).
+     *
+     * @return A logger for HTTP internal debug traces
+     */
+    private DebugLogger(Logger logger,
+                Supplier<String> dbgTag,
+                Level outLevel,
+                Level errLevel) {
+        this.dbgTag = dbgTag;
+        this.errLevel = errLevel;
+        this.outLevel = outLevel;
+        this.logger = Objects.requireNonNull(logger);
+        // support only static configuration.
+        this.debugOn = isEnabled(Level.DEBUG);
+        this.traceOn = isEnabled(Level.TRACE);
+    }
+
+    @Override
+    public String getName() {
+        return logger.getName();
+    }
+
+    private boolean isEnabled(Level level) {
+        if (level == Level.OFF) return false;
+        int severity = level.getSeverity();
+        return severity >= errLevel.getSeverity()
+                || severity >= outLevel.getSeverity()
+                || logger.isLoggable(level);
+    }
+
+    @Override
+    public boolean isLoggable(Level level) {
+        // fast path, we assume these guys never change.
+        // support only static configuration.
+        if (level == Level.DEBUG) return debugOn;
+        if (level == Level.TRACE) return traceOn;
+        return isEnabled(level);
+    }
+
+    @Override
+    public void log(Level level, ResourceBundle unused,
+                    String format, Object... params) {
+        // fast path, we assume these guys never change.
+        // support only static configuration.
+        if (level == Level.DEBUG && !debugOn) return;
+        if (level == Level.TRACE && !traceOn) return;
+
+        int severity = level.getSeverity();
+        if (errLevel != Level.OFF
+                && errLevel.getSeverity() <= severity) {
+            print(System.err, level, format, params, null);
+        }
+        if (outLevel != Level.OFF
+                && outLevel.getSeverity() <= severity) {
+            print(System.out, level, format, params, null);
+        }
+        if (logger.isLoggable(level)) {
+            logger.log(level, unused,
+                    getFormat(new StringBuilder(), format, params).toString(),
+                    params);
+        }
+    }
+
+    @Override
+    public void log(Level level, ResourceBundle unused, String msg,
+                    Throwable thrown) {
+        // fast path, we assume these guys never change.
+        if (level == Level.DEBUG && !debugOn) return;
+        if (level == Level.TRACE && !traceOn) return;
+
+        if (errLevel != Level.OFF
+                && errLevel.getSeverity() <= level.getSeverity()) {
+            print(System.err, level, msg, null, thrown);
+        }
+        if (outLevel != Level.OFF
+                && outLevel.getSeverity() <= level.getSeverity()) {
+            print(System.out, level, msg, null, thrown);
+        }
+        if (logger.isLoggable(level)) {
+            logger.log(level, unused,
+                    getFormat(new StringBuilder(), msg, null).toString(),
+                    thrown);
+        }
+    }
+
+    private void print(PrintStream out, Level level, String msg,
+                       Object[] params, Throwable t) {
+        StringBuilder sb = new StringBuilder();
+        sb.append(level.name()).append(':').append(' ');
+        sb = format(sb, msg, params);
+        if (t != null) sb.append(' ').append(t.toString());
+        out.println(sb.toString());
+        if (t != null) {
+            t.printStackTrace(out);
+        }
+    }
+
+    private StringBuilder decorate(StringBuilder sb, String msg) {
+        String tag = dbgTag == null ? null : dbgTag.get();
+        String res = msg == null ? "" : msg;
+        long elapsed = System.nanoTime() - START_NANOS;
+        long nanos =  elapsed % 1000_000;
+        long millis = elapsed / 1000_000;
+        long secs   = millis / 1000;
+        sb.append('[').append(Thread.currentThread().getName()).append(']')
+                .append(' ').append('[');
+        if (secs > 0) {
+            sb.append(secs).append('s');
+        }
+        millis = millis % 1000;
+        if (millis > 0) {
+            if (secs > 0) sb.append(' ');
+            sb.append(millis).append("ms");
+        }
+        sb.append(']').append(' ');
+        if (tag != null) {
+            sb.append(tag).append(' ');
+        }
+        sb.append(res);
+        return sb;
+    }
+
+
+    private StringBuilder getFormat(StringBuilder sb, String format, Object[] params) {
+        if (format == null || params == null || params.length == 0) {
+            return decorate(sb, format);
+        } else if (format.contains("{0}") || format.contains("{1}")) {
+            return decorate(sb, format);
+        } else if (format.contains("%s") || format.contains("%d")) {
+            try {
+                return decorate(sb, String.format(format, params));
+            } catch (Throwable t) {
+                return decorate(sb, format);
+            }
+        } else {
+            return decorate(sb, format);
+        }
+    }
+
+    private StringBuilder format(StringBuilder sb, String format, Object[] params) {
+        if (format == null || params == null || params.length == 0) {
+            return decorate(sb, format);
+        } else if (format.contains("{0}") || format.contains("{1}")) {
+            return decorate(sb, java.text.MessageFormat.format(format, params));
+        } else if (format.contains("%s") || format.contains("%d")) {
+            try {
+                return decorate(sb, String.format(format, params));
+            } catch (Throwable t) {
+                return decorate(sb, format);
+            }
+        } else {
+            return decorate(sb, format);
+        }
+    }
+
+    public static DebugLogger createHttpLogger(Supplier<String> dbgTag, Level outLevel, Level errLevel) {
+        return new DebugLogger(HTTP, dbgTag, outLevel, errLevel);
+    }
+
+    public static DebugLogger createHpackLogger(Supplier<String> dbgTag, Level outLevel, Level errLevel) {
+        return new DebugLogger(HPACK, dbgTag, outLevel, errLevel);
+    }
+}
--- a/src/jdk.incubator.httpclient/share/classes/jdk/incubator/http/internal/common/Utils.java	Wed Nov 08 17:14:43 2017 +0000
+++ b/src/jdk.incubator.httpclient/share/classes/jdk/incubator/http/internal/common/Utils.java	Wed Nov 08 18:11:00 2017 +0000
@@ -622,7 +622,7 @@
      * @return A logger for HTTP internal debug traces
      */
     static Logger getDebugLogger(Supplier<String> dbgTag, Level errLevel) {
-        return new DebugLogger(DebugLogger.HTTP, dbgTag, Level.OFF, errLevel);
+        return DebugLogger.createHttpLogger(dbgTag, Level.OFF, errLevel);
     }
 
     /**
@@ -677,7 +677,7 @@
     public static Logger getHpackLogger(Supplier<String> dbgTag) {
         Level errLevel = Level.OFF;
         Level outLevel = DEBUG_HPACK ? Level.ALL : Level.OFF;
-        return new DebugLogger(DebugLogger.HPACK, dbgTag, outLevel, errLevel);
+        return DebugLogger.createHpackLogger(dbgTag, outLevel, errLevel);
     }
 
     /**
@@ -708,9 +708,9 @@
      *
      * @return A logger for HPACK internal debug traces
      */
-    static Logger getHpackLogger(Supplier<String> dbgTag, Level outLevel) {
+    public static Logger getHpackLogger(Supplier<String> dbgTag, Level outLevel) {
         Level errLevel = Level.OFF;
-        return new DebugLogger(DebugLogger.HPACK, dbgTag, outLevel, errLevel);
+        return DebugLogger.createHpackLogger(dbgTag, outLevel, errLevel);
     }
 
     /**
@@ -746,174 +746,4 @@
         return getHpackLogger(dbgTag, outLevel);
     }
 
-
-
-    private static final class DebugLogger implements System.Logger {
-
-        // deliberately not in the same subtree than standard loggers.
-        final static String HTTP_NAME  = "jdk.internal.httpclient.debug";
-        final static String HPACK_NAME = "jdk.internal.httpclient.hpack.debug";
-        final static Logger HTTP = System.getLogger(HTTP_NAME);
-        final static Logger HPACK = System.getLogger(HPACK_NAME);
-        final static long START_NANOS = System.nanoTime();
-
-        final Supplier<String> dbgTag;
-        final Level errLevel;
-        final Level outLevel;
-        final Logger logger;
-        final boolean debugOn;
-        final boolean traceOn;
-
-        DebugLogger(Logger logger,
-                    Supplier<String> dbgTag,
-                    Level outLevel,
-                    Level errLevel) {
-            this.dbgTag = dbgTag;
-            this.errLevel = errLevel;
-            this.outLevel = outLevel;
-            this.logger = logger;
-            // support only static configuration.
-            this.debugOn = isEnabled(Level.DEBUG);
-            this.traceOn = isEnabled(Level.TRACE);
-        }
-
-        @Override
-        public String getName() {
-            return logger.getName();
-        }
-
-        private boolean isEnabled(Level level) {
-            if (level == Level.OFF) return false;
-            int severity = level.getSeverity();
-            return severity >= errLevel.getSeverity()
-                    || severity >= outLevel.getSeverity()
-                    || logger.isLoggable(level);
-        }
-
-        @Override
-        public boolean isLoggable(Level level) {
-            // fast path, we assume these guys never change.
-            // support only static configuration.
-            if (level == Level.DEBUG) return debugOn;
-            if (level == Level.TRACE) return traceOn;
-            return isEnabled(level);
-        }
-
-        @Override
-        public void log(Level level, ResourceBundle unused,
-                        String format, Object... params) {
-            // fast path, we assume these guys never change.
-            // support only static configuration.
-            if (level == Level.DEBUG && !debugOn) return;
-            if (level == Level.TRACE && !traceOn) return;
-
-            int severity = level.getSeverity();
-            if (errLevel != Level.OFF
-                    && errLevel.getSeverity() <= severity) {
-                print(System.err, level, format, params, null);
-            }
-            if (outLevel != Level.OFF
-                    && outLevel.getSeverity() <= severity) {
-                print(System.out, level, format, params, null);
-            }
-            if (logger.isLoggable(level)) {
-                logger.log(level, unused,
-                           getFormat(new StringBuilder(), format, params).toString(),
-                           params);
-            }
-        }
-
-        @Override
-        public void log(Level level, ResourceBundle unused, String msg,
-                        Throwable thrown) {
-            // fast path, we assume these guys never change.
-            if (level == Level.DEBUG && !debugOn) return;
-            if (level == Level.TRACE && !traceOn) return;
-
-            if (errLevel != Level.OFF
-                    && errLevel.getSeverity() <= level.getSeverity()) {
-                print(System.err, level, msg, null, thrown);
-            }
-            if (outLevel != Level.OFF
-                    && outLevel.getSeverity() <= level.getSeverity()) {
-                print(System.out, level, msg, null, thrown);
-            }
-            if (logger.isLoggable(level)) {
-                logger.log(level, unused,
-                           getFormat(new StringBuilder(), msg, null).toString(),
-                           thrown);
-            }
-        }
-
-        private void print(PrintStream out, Level level, String msg,
-                           Object[] params, Throwable t) {
-            StringBuilder sb = new StringBuilder();
-            sb.append(level.name()).append(':').append(' ');
-            sb = format(sb, msg, params);
-            if (t != null) sb.append(' ').append(t.toString());
-            out.println(sb.toString());
-            if (t != null) {
-                t.printStackTrace(out);
-            }
-        }
-
-        private StringBuilder decorate(StringBuilder sb, String msg) {
-            String tag = dbgTag == null ? null : dbgTag.get();
-            String res = msg == null ? "" : msg;
-            long elapsed = System.nanoTime() - START_NANOS;
-            long nanos =  elapsed % 1000_000;
-            long millis = elapsed / 1000_000;
-            long secs   = millis / 1000;
-            sb.append('[').append(Thread.currentThread().getName()).append(']')
-                    .append(' ').append('[');
-            if (secs > 0) {
-                sb.append(secs).append('s');
-            }
-            millis = millis % 1000;
-            if (millis > 0) {
-                if (secs > 0) sb.append(' ');
-                sb.append(millis).append("ms");
-            }
-            sb.append(']').append(' ');
-            if (tag != null) {
-                sb.append(tag).append(' ');
-            }
-            sb.append(res);
-            return sb;
-        }
-
-
-        private StringBuilder getFormat(StringBuilder sb, String format, Object[] params) {
-            if (format == null || params == null || params.length == 0) {
-                return decorate(sb, format);
-            } else if (format.contains("{0}") || format.contains("{1}")) {
-                return decorate(sb, format);
-            } else if (format.contains("%s") || format.contains("%d")) {
-                try {
-                    return decorate(sb, String.format(format, params));
-                } catch (Throwable t) {
-                    return decorate(sb, format);
-                }
-            } else {
-                return decorate(sb, format);
-            }
-        }
-
-        private StringBuilder format(StringBuilder sb, String format, Object[] params) {
-            if (format == null || params == null || params.length == 0) {
-                return decorate(sb, format);
-            } else if (format.contains("{0}") || format.contains("{1}")) {
-                return decorate(sb, java.text.MessageFormat.format(format, params));
-            } else if (format.contains("%s") || format.contains("%d")) {
-                try {
-                    return decorate(sb, String.format(format, params));
-                } catch (Throwable t) {
-                    return decorate(sb, format);
-                }
-            } else {
-                return decorate(sb, format);
-            }
-        }
-
-    }
 }
--- a/src/jdk.incubator.httpclient/share/classes/jdk/incubator/http/internal/hpack/HPACK.java	Wed Nov 08 17:14:43 2017 +0000
+++ b/src/jdk.incubator.httpclient/share/classes/jdk/incubator/http/internal/hpack/HPACK.java	Wed Nov 08 18:11:00 2017 +0000
@@ -24,6 +24,7 @@
  */
 package jdk.incubator.http.internal.hpack;
 
+import jdk.incubator.http.internal.common.Utils;
 import jdk.incubator.http.internal.hpack.HPACK.Logger.Level;
 import jdk.internal.vm.annotation.Stable;
 
@@ -31,6 +32,7 @@
 import java.security.PrivilegedAction;
 import java.util.Arrays;
 import java.util.Map;
+import java.util.ResourceBundle;
 import java.util.function.Supplier;
 
 import static java.lang.String.format;
@@ -61,11 +63,13 @@
             Level l = logLevels.get(upperCasedValue);
             if (l == null) {
                 LOGGER = new RootLogger(NONE);
-                LOGGER.log(() -> format("%s value '%s' not recognized (use %s); logging disabled",
-                                        PROPERTY, value, logLevels.keySet().stream().collect(joining(", "))));
+                LOGGER.log(System.Logger.Level.INFO,
+                        () -> format("%s value '%s' not recognized (use %s); logging disabled",
+                                     PROPERTY, value, logLevels.keySet().stream().collect(joining(", "))));
             } else {
                 LOGGER = new RootLogger(l);
-                LOGGER.log(() -> format("logging level %s", l));
+                LOGGER.log(System.Logger.Level.DEBUG,
+                        () -> format("logging level %s", l));
             }
         }
     }
@@ -80,21 +84,25 @@
      * The purpose of this logger is to provide means of diagnosing issues _in
      * the HPACK implementation_. It's not a general purpose logger.
      */
-    public static class Logger {
+    // implements System.Logger to make it possible to skip this class
+    // when looking for the Caller.
+    public static class Logger implements System.Logger {
 
         /**
          * Log detail level.
          */
         public enum Level {
 
-            NONE(0),
-            NORMAL(1),
-            EXTRA(2);
+            NONE(0, System.Logger.Level.OFF),
+            NORMAL(1, System.Logger.Level.DEBUG),
+            EXTRA(2, System.Logger.Level.TRACE);
 
             private final int level;
+            final System.Logger.Level systemLevel;
 
-            Level(int i) {
+            Level(int i, System.Logger.Level system) {
                 level = i;
+                systemLevel = system;
             }
 
             public final boolean implies(Level other) {
@@ -103,91 +111,66 @@
         }
 
         private final String name;
-        @Stable
-        private final Logger[] path; /* A path to parent: [root, ..., parent, this] */
+        private final Level level;
+        private final String path;
+        private final System.Logger logger;
 
-        private Logger(Logger[] path, String name) {
-            Logger[] p = Arrays.copyOfRange(path, 0, path.length + 1);
-            p[path.length] = this;
+        private Logger(String path, String name, Level level) {
+            this(path, name, level, null);
+        }
+
+        private Logger(String p, String name, Level level, System.Logger logger) {
             this.path = p;
             this.name = name;
+            this.level = level;
+            this.logger = Utils.getHpackLogger(path::toString, level.systemLevel);
+        }
+
+        public final String getName() {
+            return name;
         }
 
-        protected final String getName() {
-            return name;
+        @Override
+        public boolean isLoggable(System.Logger.Level level) {
+            return logger.isLoggable(level);
         }
+
+        @Override
+        public void log(System.Logger.Level level, ResourceBundle bundle, String msg, Throwable thrown) {
+            logger.log(level, bundle, msg,thrown);
+        }
+
+        @Override
+        public void log(System.Logger.Level level, ResourceBundle bundle, String format, Object... params) {
+            logger.log(level, bundle, format, params);
+        }
+
         /*
          * Usual performance trick for logging, reducing performance overhead in
          * the case where logging with the specified level is a NOP.
          */
 
         public boolean isLoggable(Level level) {
-            return isLoggable(path, level);
-        }
-
-        public void log(Level level, Supplier<? extends CharSequence> s) {
-            log(path, level, s);
-        }
-
-        public Logger subLogger(String name) {
-            return new Logger(path, name);
+            return this.level.implies(level);
         }
 
-        protected boolean isLoggable(Logger[] path, Level level) {
-            return parent().isLoggable(path, level);
+        public void log(Level level, Supplier<String> s) {
+            if (this.level.implies(level)) {
+                logger.log(level.systemLevel, s);
+            }
+        }
+        
+        public Logger subLogger(String name) {
+            return new Logger(path + "/" + name, name, level);
         }
 
-        protected void log(Logger[] path,
-                           Level level,
-                           Supplier<? extends CharSequence> s) {
-            parent().log(path, level, s);
-        }
-
-        protected final Logger parent() {
-            return path[path.length - 2];
-        }
     }
 
     private static final class RootLogger extends Logger {
 
-        private final Level level;
-        @Stable
-        private final Logger[] path = { this };
-
         protected RootLogger(Level level) {
-            super(new Logger[]{ }, "hpack");
-            this.level = level;
-        }
-
-        @Override
-        protected boolean isLoggable(Logger[] path, Level level) {
-            return this.level.implies(level);
-        }
-
-        @Override
-        public void log(Level level, Supplier<? extends CharSequence> s) {
-            log(path, level, s);
+            super("hpack", "hpack", level);
         }
 
-        @Override
-        protected void log(Logger[] path,
-                           Level level,
-                           Supplier<? extends CharSequence> s) {
-            if (this.level.implies(level)) {
-                log(path, s);
-            }
-        }
-
-        public void log(Supplier<? extends CharSequence> s) {
-            log(path, s);
-        }
-
-        private void log(Logger[] path, Supplier<? extends CharSequence> s) {
-            StringBuilder b = new StringBuilder();
-            for (Logger p : path) {
-                b.append('/').append(p.getName());
-            }
-            System.out.println(b.toString() + ' ' + s.get());
-        }
     }
 }