Skip to content

SQL: jdbc debugging enhancement #53880

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 5 commits into from
Mar 24, 2020
Merged

SQL: jdbc debugging enhancement #53880

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
7832e66
* add buffered debug output option that will flush the output printer
astefan Mar 20, 2020
c3f59d3
Merge branch 'master' of https://github.com/elastic/elasticsearch int…
astefan Mar 20, 2020
a3d7140
locale -> timezone
astefan Mar 20, 2020
686f64b
Address reviews
astefan Mar 23, 2020
0808286
Merge branch 'master' of https://github.com/elastic/elasticsearch int…
astefan Mar 23, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
45 changes: 25 additions & 20 deletions x-pack/plugin/sql/jdbc/src/main/java/org/elasticsearch/xpack/sql/jdbc/Debug.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The method changes make it more complicated and hard to follow - there's this log ==null being repeated which begs the question, what happens it if it initialized?
I think the method is good as it is - it creates a logger or returns one that already exists. Either wrap this method in another one that calls logSystemInfo (rename the existing method into something like createLogger and then logger calls createLogger().logSystemInfo or wrap that at the consumer site - inside proxy.

However currently the systemInfo is being called per each Connection which I think is excessive - we want the system information to be once per log, at the beginning.
In which case, the system info should called when a new log is created, essentially after each new DebugLog.
To keep things incapsulated, instead of calling the constructor, one could call a method createLog which internally calls new DebugLog and right after calls logSystemInfo.
This way any other initialization that would need to occur, would happen in that method regardless of the actual method taking place and only once per logger.
It might make sense to call flush after logging the system info.

}
}

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) {
Expand All @@ -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) {
Expand All @@ -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;
Expand Down
30 changes: 28 additions & 2 deletions x-pack/plugin/sql/jdbc/src/main/java/org/elasticsearch/xpack/sql/jdbc/DebugLog.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,9 +17,11 @@ final class DebugLog {
private static final String HEADER = "%tF/%tT.%tL - ";

final PrintWriter print;
private boolean debugBuffered;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No need to keep the prefix debug as this is a DebugXXX class.


DebugLog(PrintWriter print) {
DebugLog(PrintWriter print, boolean debugBuffered) {
this.print = print;
this.debugBuffered = debugBuffered;
}

void logMethod(Method m, Object[] args) {
Expand All @@ -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",
Expand All @@ -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) {
Expand All @@ -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) {
Expand Down
12 changes: 11 additions & 1 deletion x-pack/plugin/sql/jdbc/src/main/java/org/elasticsearch/xpack/sql/jdbc/JdbcConfiguration.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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_BUFFERED));

static {
// trigger version initialization
Expand All @@ -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;
Expand Down Expand Up @@ -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());
Expand All @@ -184,6 +190,10 @@ public String debugOut() {
return debugOut;
}

public boolean debugBuffered() {
return debugBuffered;
}

public TimeZone timeZone() {
return zoneId != null ? TimeZone.getTimeZone(zoneId) : null;
}
Expand Down
17 changes: 17 additions & 0 deletions ...lugin/sql/jdbc/src/test/java/org/elasticsearch/xpack/sql/jdbc/JdbcConfigurationTests.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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");
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think debug.flushAlways or debug.noBuffer is more meaningful. I also like the consistency of the options - by default they are false and need to be turn on through true.
That is the default (false) is to always buffer but true would yield an immediate flush.

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());
Expand Down