From 7832e66f00be1243f1400bf1c1c0807a70ceeef3 Mon Sep 17 00:00:00 2001 From: Andrei Stefan Date: Fri, 20 Mar 2020 17:29:06 +0200 Subject: [PATCH 1/3] * add buffered debug output option that will flush the output printer after each debug message when enabled (disabled by default) * upon connection time and debug classes initialization, log in debug output information about OS, JVM and default JVM timezone --- .../elasticsearch/xpack/sql/jdbc/Debug.java | 45 ++++++++++--------- .../xpack/sql/jdbc/DebugLog.java | 30 ++++++++++++- .../xpack/sql/jdbc/JdbcConfiguration.java | 12 ++++- .../sql/jdbc/JdbcConfigurationTests.java | 17 +++++++ 4 files changed, 81 insertions(+), 23 deletions(-) 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 index cb10395e3925c..464a7eafb32eb 100644 --- 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,17 +113,16 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte synchronized (Debug.class) { log = OUTPUT_MANAGED.get(managedPrinter); if (log == null) { - log = new DebugLog(managedPrinter); + log = new DebugLog(managedPrinter, info.debugBuffered()); OUTPUT_MANAGED.put(managedPrinter, log); } - return log; } } String out = info.debugOut(); // System.out/err can be changed so do some checks - if ("err".equals(out)) { + if (log == null && "err".equals(out)) { PrintStream sys = stderr(); if (SYS_ERR == null) { @@ -135,12 +134,12 @@ 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 = new DebugLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8)), info.debugBuffered()); } - return ERR; + log = ERR; } - if ("out".equals(out)) { + if (log == null && "out".equals(out)) { PrintStream sys = stdout(); if (SYS_OUT == null) { @@ -154,25 +153,31 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte } if (OUT == null) { - OUT = new DebugLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8))); + OUT = new DebugLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8)), info.debugBuffered()); } - return OUT; + log = OUT; } - synchronized (Debug.class) { - log = OUTPUT_CACHE.get(out); - if (log == null) { - // must be local file - try { - PrintWriter print = new PrintWriter(Files.newBufferedWriter(Paths.get("").resolve(out), StandardCharsets.UTF_8)); - log = new DebugLog(print); - OUTPUT_CACHE.put(out, log); - OUTPUT_REFS.put(out, Integer.valueOf(0)); - } catch (Exception ex) { - throw new JdbcException(ex, "Cannot open debug output [" + out + "]"); + if (log == null) { + synchronized (Debug.class) { + log = OUTPUT_CACHE.get(out); + if (log == null) { + // must be local file + try { + PrintWriter print = new PrintWriter(Files.newBufferedWriter(Paths.get("").resolve(out), StandardCharsets.UTF_8)); + log = new DebugLog(print, info.debugBuffered()); + OUTPUT_CACHE.put(out, log); + OUTPUT_REFS.put(out, Integer.valueOf(0)); + } catch (Exception ex) { + throw new JdbcException(ex, "Cannot open debug output [" + out + "]"); + } } + OUTPUT_REFS.put(out, Integer.valueOf(OUTPUT_REFS.get(out).intValue() + 1)); } - OUTPUT_REFS.put(out, Integer.valueOf(OUTPUT_REFS.get(out).intValue() + 1)); + } + + if (log != null) { + log.logSystemInfo(); } return log; 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 index e439502e971fa..090581b1c2cf8 100644 --- 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 debugBuffered; - DebugLog(PrintWriter print) { + DebugLog(PrintWriter print, boolean debugBuffered) { this.print = print; + this.debugBuffered = debugBuffered; } void logMethod(Method m, Object[] args) { @@ -31,9 +33,11 @@ void logMethod(Method m, Object[] args) { m.getName(), //array(m.getParameterTypes()), array(args)); + if (debugBuffered == false) { + 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 (debugBuffered == false) { + 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 locale: %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 index 8fd4c6119b434..6e412c3593e95 100644 --- 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_BUFFERED = "debug.buffered"; + // can be buffered/immediate + static final String DEBUG_BUFFERED_DEFAULT = "true"; + 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 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_BUFFERED)); 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 debugBuffered; // mutable ones private ZoneId zoneId; @@ -158,6 +163,7 @@ 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.debugBuffered = parseValue(DEBUG_BUFFERED, props.getProperty(DEBUG_BUFFERED, DEBUG_BUFFERED_DEFAULT), Boolean::parseBoolean); this.zoneId = parseValue(TIME_ZONE, props.getProperty(TIME_ZONE, TIME_ZONE_DEFAULT), s -> TimeZone.getTimeZone(s).toZoneId().normalized()); @@ -184,6 +190,10 @@ public String debugOut() { return debugOut; } + public boolean debugBuffered() { + return debugBuffered; + } + 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 index 9b7eb9262aac1..616fd481e45ab 100644 --- 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 testDebugBuffered() throws Exception { + JdbcConfiguration ci = ci("jdbc:es://a:1/?debug=true&debug.buffered=false"); + assertThat(ci.baseUri().toString(), is("http://a:1/")); + assertThat(ci.debug(), is(true)); + assertThat(ci.debugBuffered(), is(false)); + + ci = ci("jdbc:es://a:1/?debug=true&debug.buffered=true"); + assertThat(ci.baseUri().toString(), is("http://a:1/")); + assertThat(ci.debug(), is(true)); + assertThat(ci.debugBuffered(), 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.debugBuffered(), is(true)); + } + 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()); From a3d71402d8c23fc8b5b9cf925619226661eb7775 Mon Sep 17 00:00:00 2001 From: Andrei Stefan Date: Fri, 20 Mar 2020 17:41:02 +0200 Subject: [PATCH 2/3] locale -> timezone --- .../main/java/org/elasticsearch/xpack/sql/jdbc/DebugLog.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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 index 090581b1c2cf8..95a0010337880 100644 --- 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 @@ -77,7 +77,7 @@ void logSystemInfo() { System.getProperty("java.vm.version")); print.println(); time = System.currentTimeMillis(); - print.printf(Locale.ROOT, HEADER + "JVM default locale: %s", + print.printf(Locale.ROOT, HEADER + "JVM default timezone: %s", time, time, time, java.util.TimeZone.getDefault().toString()); print.println(); From 686f64bc2d8963d9183f8c229ae1ccc8bf0c9057 Mon Sep 17 00:00:00 2001 From: Andrei Stefan Date: Mon, 23 Mar 2020 18:23:52 +0200 Subject: [PATCH 3/3] Address reviews --- .../elasticsearch/xpack/sql/jdbc/Debug.java | 48 +++++++++---------- .../xpack/sql/jdbc/DebugLog.java | 10 ++-- .../xpack/sql/jdbc/JdbcConfiguration.java | 15 +++--- .../sql/jdbc/JdbcConfigurationTests.java | 12 ++--- 4 files changed, 43 insertions(+), 42 deletions(-) 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 index 464a7eafb32eb..7f4385fe01518 100644 --- 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,7 +113,7 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte synchronized (Debug.class) { log = OUTPUT_MANAGED.get(managedPrinter); if (log == null) { - log = new DebugLog(managedPrinter, info.debugBuffered()); + log = createLog(managedPrinter, info.flushAlways()); OUTPUT_MANAGED.put(managedPrinter, log); } } @@ -122,7 +122,7 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte String out = info.debugOut(); // System.out/err can be changed so do some checks - if (log == null && "err".equals(out)) { + if ("err".equals(out)) { PrintStream sys = stderr(); if (SYS_ERR == null) { @@ -134,12 +134,12 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte ERR = null; } if (ERR == null) { - ERR = new DebugLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8)), info.debugBuffered()); + ERR = createLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8)), info.flushAlways()); } - log = ERR; + return ERR; } - if (log == null && "out".equals(out)) { + if ("out".equals(out)) { PrintStream sys = stdout(); if (SYS_OUT == null) { @@ -153,33 +153,33 @@ private static DebugLog logger(JdbcConfiguration info, PrintWriter managedPrinte } if (OUT == null) { - OUT = new DebugLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8)), info.debugBuffered()); + OUT = createLog(new PrintWriter(new OutputStreamWriter(sys, StandardCharsets.UTF_8)), info.flushAlways()); } - log = OUT; + return OUT; } - if (log == null) { - synchronized (Debug.class) { - log = OUTPUT_CACHE.get(out); - if (log == null) { - // must be local file - try { - PrintWriter print = new PrintWriter(Files.newBufferedWriter(Paths.get("").resolve(out), StandardCharsets.UTF_8)); - log = new DebugLog(print, info.debugBuffered()); - OUTPUT_CACHE.put(out, log); - OUTPUT_REFS.put(out, Integer.valueOf(0)); - } catch (Exception ex) { - throw new JdbcException(ex, "Cannot open debug output [" + out + "]"); - } + synchronized (Debug.class) { + log = OUTPUT_CACHE.get(out); + if (log == null) { + // must be local file + try { + PrintWriter print = new PrintWriter(Files.newBufferedWriter(Paths.get("").resolve(out), StandardCharsets.UTF_8)); + log = createLog(print, info.flushAlways()); + OUTPUT_CACHE.put(out, log); + OUTPUT_REFS.put(out, Integer.valueOf(0)); + } catch (Exception ex) { + throw new JdbcException(ex, "Cannot open debug output [" + out + "]"); } - OUTPUT_REFS.put(out, Integer.valueOf(OUTPUT_REFS.get(out).intValue() + 1)); } + OUTPUT_REFS.put(out, Integer.valueOf(OUTPUT_REFS.get(out).intValue() + 1)); } - if (log != null) { - log.logSystemInfo(); - } + return log; + } + private static DebugLog createLog(PrintWriter print, boolean flushAlways) { + DebugLog log = new DebugLog(print, flushAlways); + log.logSystemInfo(); return log; } 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 index 95a0010337880..c3f5598d16261 100644 --- 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,11 +17,11 @@ final class DebugLog { private static final String HEADER = "%tF/%tT.%tL - "; final PrintWriter print; - private boolean debugBuffered; + private boolean flushAlways; - DebugLog(PrintWriter print, boolean debugBuffered) { + DebugLog(PrintWriter print, boolean flushAlways) { this.print = print; - this.debugBuffered = debugBuffered; + this.flushAlways = flushAlways; } void logMethod(Method m, Object[] args) { @@ -33,7 +33,7 @@ void logMethod(Method m, Object[] args) { m.getName(), //array(m.getParameterTypes()), array(args)); - if (debugBuffered == false) { + if (flushAlways) { print.flush(); } } @@ -48,7 +48,7 @@ void logResult(Method m, Object[] args, Object r) { //array(m.getParameterTypes()), array(args), r); - if (debugBuffered == false) { + if (flushAlways) { print.flush(); } } 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 index 6e412c3593e95..04ba6046229b1 100644 --- 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,9 +47,9 @@ public class JdbcConfiguration extends ConnectionConfiguration { // can be out/err/url static final String DEBUG_OUTPUT_DEFAULT = "err"; - static final String DEBUG_BUFFERED = "debug.buffered"; + static final String DEBUG_FLUSH_ALWAYS = "debug.flushAlways"; // can be buffered/immediate - static final String DEBUG_BUFFERED_DEFAULT = "true"; + static final String DEBUG_FLUSH_ALWAYS_DEFAULT = "false"; public static final String TIME_ZONE = "timezone"; // follow the JDBC spec and use the JVM default... @@ -67,7 +67,7 @@ public class JdbcConfiguration extends ConnectionConfiguration { // options that don't change at runtime private static final Set OPTION_NAMES = new LinkedHashSet<>( - Arrays.asList(TIME_ZONE, FIELD_MULTI_VALUE_LENIENCY, INDEX_INCLUDE_FROZEN, DEBUG, DEBUG_OUTPUT, DEBUG_BUFFERED)); + Arrays.asList(TIME_ZONE, FIELD_MULTI_VALUE_LENIENCY, INDEX_INCLUDE_FROZEN, DEBUG, DEBUG_OUTPUT, DEBUG_FLUSH_ALWAYS)); static { // trigger version initialization @@ -80,7 +80,7 @@ public class JdbcConfiguration extends ConnectionConfiguration { // immutable properties private final boolean debug; private final String debugOut; - private final boolean debugBuffered; + private final boolean flushAlways; // mutable ones private ZoneId zoneId; @@ -163,7 +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.debugBuffered = parseValue(DEBUG_BUFFERED, props.getProperty(DEBUG_BUFFERED, DEBUG_BUFFERED_DEFAULT), Boolean::parseBoolean); + 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()); @@ -190,8 +191,8 @@ public String debugOut() { return debugOut; } - public boolean debugBuffered() { - return debugBuffered; + public boolean flushAlways() { + return flushAlways; } public TimeZone timeZone() { 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 index 616fd481e45ab..680b1eebe4883 100644 --- 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,21 +75,21 @@ public void testDebugOut() throws Exception { assertThat(ci.debugOut(), is("jdbc.out")); } - public void testDebugBuffered() throws Exception { - JdbcConfiguration ci = ci("jdbc:es://a:1/?debug=true&debug.buffered=false"); + 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.debugBuffered(), is(false)); + assertThat(ci.flushAlways(), is(false)); - ci = ci("jdbc:es://a:1/?debug=true&debug.buffered=true"); + 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.debugBuffered(), 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.debugBuffered(), is(true)); + assertThat(ci.flushAlways(), is(false)); } public void testTypeInParam() throws Exception {