Skip to content
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

Jump to bottom

SQL: jdbc debugging enhancement #53880

Merged
merged 5 commits into from
Mar 24, 2020
Merged

SQL: jdbc debugging enhancement #53880

Show file tree
Hide file tree
Changes from all 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
15 changes: 10 additions & 5 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,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;
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.

}
}

Expand All @@ -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;
}
Expand All @@ -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;
}
Expand All @@ -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) {
Expand All @@ -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;
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 flushAlways;

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

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 (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",
Expand All @@ -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) {
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
13 changes: 12 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_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
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_FLUSH_ALWAYS));

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 flushAlways;

// mutable ones
private ZoneId zoneId;
Expand Down Expand Up @@ -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());
Expand All @@ -184,6 +191,10 @@ public String debugOut() {
return debugOut;
}

public boolean flushAlways() {
return flushAlways;
}

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