SQL: jdbc debugging enhancement (elastic#53880)

astefan · astefan · commit 7a2d15576dc8 · 2020-03-24T14:56:33.000+02:00
* add flush always output option that will flush the output printer after each debug message when enabled (disabled by default) * at debug output initializationtime, log debug output information about OS, JVM and default JVM timezone (cherry picked from commit b5db965)
diff --git a/x-pack/plugin/sql/jdbc/src/main/java/org/elasticsearch/xpack/sql/jdbc/Debug.java b/x-pack/plugin/sql/jdbc/src/main/java/org/elasticsearch/xpack/sql/jdbc/Debug.java
@@ -113,10 +113,9 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte
             synchronized (Debug.class) {
                 log = OUTPUT_MANAGED.get(managedPrinter);
                 if (log == null) {
-                    log = new DebugLog(managedPrinter);
+                    log = createLog(managedPrinter, info.flushAlways());
                     OUTPUT_MANAGED.put(managedPrinter, log);
                 }
-                return log;
             }
         }
 
@@ -135,7 +134,7 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte
                 ERR = null;
             }
             if (ERR == null) {
-                ERR = new DebugLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8)));
+                ERR = createLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8)), info.flushAlways());
             }
             return ERR;
         }
@@ -154,7 +153,7 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte
             }
 
             if (OUT == null) {
-                OUT = new DebugLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8)));
+                OUT = createLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8)), info.flushAlways());
             }
             return OUT;
         }
@@ -165,7 +164,7 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte
                 // must be local file
                 try {
                     PrintWriter print = new PrintWriter(Files.newBufferedWriter(Paths.get("").resolve(out), StandardCharsets.UTF_8));
-                    log = new DebugLog(print);
+                    log = createLog(print, info.flushAlways());
                     OUTPUT_CACHE.put(out, log);
                     OUTPUT_REFS.put(out, Integer.valueOf(0));
                 } catch (Exception ex) {
@@ -178,6 +177,12 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte
         return log;
     }
 
+    private static DebugLog createLog(PrintWriter print, boolean flushAlways) {
+        DebugLog log = new DebugLog(print, flushAlways);
+        log.logSystemInfo();
+        return log;
+    }
+
     static void release(JdbcConfiguration info) {
         if (!info.debug()) {
             return;
diff --git a/x-pack/plugin/sql/jdbc/src/main/java/org/elasticsearch/xpack/sql/jdbc/DebugLog.java b/x-pack/plugin/sql/jdbc/src/main/java/org/elasticsearch/xpack/sql/jdbc/DebugLog.java
@@ -17,9 +17,11 @@ final class DebugLog {
     private static final String HEADER = "%tF/%tT.%tL - ";
 
     final PrintWriter print;
+    private boolean flushAlways;
 
-    DebugLog(PrintWriter print) {
+    DebugLog(PrintWriter print, boolean flushAlways) {
         this.print = print;
+        this.flushAlways = flushAlways;
     }
 
     void logMethod(Method m, Object[] args) {
@@ -31,9 +33,11 @@ void logMethod(Method m, Object[] args) {
                 m.getName(),
                 //array(m.getParameterTypes()),
                 array(args));
+        if (flushAlways) {
+            print.flush();
+        }
     }
 
-
     void logResult(Method m, Object[] args, Object r) {
         long time = System.currentTimeMillis();
         print.printf(Locale.ROOT, HEADER + "%s#%s(%s) returned %s%n",
@@ -44,6 +48,9 @@ void logResult(Method m, Object[] args, Object r) {
                 //array(m.getParameterTypes()),
                 array(args),
                 r);
+        if (flushAlways) {
+            print.flush();
+        }
     }
 
     void logException(Method m, Object[] args, Throwable t) {
@@ -57,6 +64,25 @@ void logException(Method m, Object[] args, Throwable t) {
         print.flush();
     }
 
+    void logSystemInfo() {
+        long time = System.currentTimeMillis();
+        print.printf(Locale.ROOT, HEADER + "OS[%s/%s/%s], JVM[%s/%s/%s/%s]",
+                time, time, time,
+                System.getProperty("os.name"),
+                System.getProperty("os.version"),
+                System.getProperty("os.arch"),
+                System.getProperty("java.vm.vendor"),
+                System.getProperty("java.vm.name"),
+                System.getProperty("java.version"),
+                System.getProperty("java.vm.version"));
+        print.println();
+        time = System.currentTimeMillis();
+        print.printf(Locale.ROOT, HEADER + "JVM default timezone: %s",
+                time, time, time,
+                java.util.TimeZone.getDefault().toString());
+        print.println();
+        print.flush();
+    }
 
     private static String array(Object[] a) {
         if (a == null || a.length == 0) {
diff --git a/x-pack/plugin/sql/jdbc/src/main/java/org/elasticsearch/xpack/sql/jdbc/JdbcConfiguration.java b/x-pack/plugin/sql/jdbc/src/main/java/org/elasticsearch/xpack/sql/jdbc/JdbcConfiguration.java
@@ -47,6 +47,10 @@ public class JdbcConfiguration extends ConnectionConfiguration {
     // can be out/err/url
     static final String DEBUG_OUTPUT_DEFAULT = "err";
 
+    static final String DEBUG_FLUSH_ALWAYS = "debug.flushAlways";
+    // can be buffered/immediate
+    static final String DEBUG_FLUSH_ALWAYS_DEFAULT = "false";
+
     public static final String TIME_ZONE = "timezone";
     // follow the JDBC spec and use the JVM default...
     // to avoid inconsistency, the default is picked up once at startup and reused across connections
@@ -63,7 +67,7 @@ public class JdbcConfiguration extends ConnectionConfiguration {
 
     // options that don't change at runtime
     private static final Set<String> OPTION_NAMES = new LinkedHashSet<>(
-            Arrays.asList(TIME_ZONE, FIELD_MULTI_VALUE_LENIENCY, INDEX_INCLUDE_FROZEN, DEBUG, DEBUG_OUTPUT));
+            Arrays.asList(TIME_ZONE, FIELD_MULTI_VALUE_LENIENCY, INDEX_INCLUDE_FROZEN, DEBUG, DEBUG_OUTPUT, DEBUG_FLUSH_ALWAYS));
 
     static {
         // trigger version initialization
@@ -76,6 +80,7 @@ public class JdbcConfiguration extends ConnectionConfiguration {
     // immutable properties
     private final boolean debug;
     private final String debugOut;
+    private final boolean flushAlways;
 
     // mutable ones
     private ZoneId zoneId;
@@ -158,6 +163,8 @@ private JdbcConfiguration(URI baseURI, String u, Properties props) throws JdbcSQ
 
         this.debug = parseValue(DEBUG, props.getProperty(DEBUG, DEBUG_DEFAULT), Boolean::parseBoolean);
         this.debugOut = props.getProperty(DEBUG_OUTPUT, DEBUG_OUTPUT_DEFAULT);
+        this.flushAlways = parseValue(DEBUG_FLUSH_ALWAYS, props.getProperty(DEBUG_FLUSH_ALWAYS, DEBUG_FLUSH_ALWAYS_DEFAULT),
+                Boolean::parseBoolean);
 
         this.zoneId = parseValue(TIME_ZONE, props.getProperty(TIME_ZONE, TIME_ZONE_DEFAULT),
                 s -> TimeZone.getTimeZone(s).toZoneId().normalized());
@@ -184,6 +191,10 @@ public String debugOut() {
         return debugOut;
     }
 
+    public boolean flushAlways() {
+        return flushAlways;
+    }
+
     public TimeZone timeZone() {
         return zoneId != null ? TimeZone.getTimeZone(zoneId) : null;
     }
diff --git a/x-pack/plugin/sql/jdbc/src/test/java/org/elasticsearch/xpack/sql/jdbc/JdbcConfigurationTests.java b/x-pack/plugin/sql/jdbc/src/test/java/org/elasticsearch/xpack/sql/jdbc/JdbcConfigurationTests.java
@@ -75,6 +75,23 @@ public void testDebugOut() throws Exception {
         assertThat(ci.debugOut(), is("jdbc.out"));
     }
 
+    public void testDebugFlushAlways() throws Exception {
+        JdbcConfiguration ci = ci("jdbc:es://a:1/?debug=true&debug.flushAlways=false");
+        assertThat(ci.baseUri().toString(), is("http://a:1/"));
+        assertThat(ci.debug(), is(true));
+        assertThat(ci.flushAlways(), is(false));
+
+        ci = ci("jdbc:es://a:1/?debug=true&debug.flushAlways=true");
+        assertThat(ci.baseUri().toString(), is("http://a:1/"));
+        assertThat(ci.debug(), is(true));
+        assertThat(ci.flushAlways(), is(true));
+
+        ci = ci("jdbc:es://a:1/?debug=true");
+        assertThat(ci.baseUri().toString(), is("http://a:1/"));
+        assertThat(ci.debug(), is(true));
+        assertThat(ci.flushAlways(), is(false));
+    }
+
     public void testTypeInParam() throws Exception {
         Exception e = expectThrows(JdbcSQLException.class, () -> ci("jdbc:es://a:1/foo/bar/tar?debug=true&debug.out=jdbc.out"));
         assertEquals("Unknown parameter [debug.out]; did you mean [debug.output]", e.getMessage());

Original file line number	Diff line number	Diff line change
`@@ -113,10 +113,9 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte`
`113`	`113`	`synchronized (Debug.class) {`
`114`	`114`	`log = OUTPUT_MANAGED.get(managedPrinter);`
`115`	`115`	`if (log == null) {`
`116`		`- log = new DebugLog(managedPrinter);`
	`116`	`+ log = createLog(managedPrinter, info.flushAlways());`
`117`	`117`	`OUTPUT_MANAGED.put(managedPrinter, log);`
`118`	`118`	`}`
`119`		`- return log;`
`120`	`119`	`}`
`121`	`120`	`}`
`122`	`121`
`@@ -135,7 +134,7 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte`
`135`	`134`	`ERR = null;`
`136`	`135`	`}`
`137`	`136`	`if (ERR == null) {`
`138`		`- ERR = new DebugLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8)));`
	`137`	`+ ERR = createLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8)), info.flushAlways());`
`139`	`138`	`}`
`140`	`139`	`return ERR;`
`141`	`140`	`}`
`@@ -154,7 +153,7 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte`
`154`	`153`	`}`
`155`	`154`
`156`	`155`	`if (OUT == null) {`
`157`		`- OUT = new DebugLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8)));`
	`156`	`+ OUT = createLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8)), info.flushAlways());`
`158`	`157`	`}`
`159`	`158`	`return OUT;`
`160`	`159`	`}`
`@@ -165,7 +164,7 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte`
`165`	`164`	`// must be local file`
`166`	`165`	`try {`
`167`	`166`	`PrintWriter print = new PrintWriter(Files.newBufferedWriter(Paths.get("").resolve(out), StandardCharsets.UTF_8));`
`168`		`- log = new DebugLog(print);`
	`167`	`+ log = createLog(print, info.flushAlways());`
`169`	`168`	`OUTPUT_CACHE.put(out, log);`
`170`	`169`	`OUTPUT_REFS.put(out, Integer.valueOf(0));`
`171`	`170`	`} catch (Exception ex) {`
`@@ -178,6 +177,12 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte`
`178`	`177`	`return log;`
`179`	`178`	`}`
`180`	`179`
	`180`	`+ private static DebugLog createLog(PrintWriter print, boolean flushAlways) {`
	`181`	`+ DebugLog log = new DebugLog(print, flushAlways);`
	`182`	`+ log.logSystemInfo();`
	`183`	`+ return log;`
	`184`	`+ }`
	`185`	`+`
`181`	`186`	`static void release(JdbcConfiguration info) {`
`182`	`187`	`if (!info.debug()) {`
`183`	`188`	`return;`