diff --git a/api/src/main/java/org/teiid/logging/LogManager.java b/api/src/main/java/org/teiid/logging/LogManager.java index 621194bcf3..1044476adb 100644 --- a/api/src/main/java/org/teiid/logging/LogManager.java +++ b/api/src/main/java/org/teiid/logging/LogManager.java @@ -374,14 +374,16 @@ public static void log(int msgLevel, String context, Throwable e, Object... mess logListener.log(msgLevel, context, e, message); } - public static void setLogListener(Logger listener) { - logListener.shutdown(); + public static Logger setLogListener(Logger listener) { + Logger old = logListener; + logListener.shutdown(); if (listener != null) { logListener = listener; } else { logListener = new JavaLogger(); } + return old; } /** diff --git a/client/pom.xml b/client/pom.xml index e1c2d84b8e..632ffacfb7 100644 --- a/client/pom.xml +++ b/client/pom.xml @@ -67,6 +67,30 @@ org.jboss.modules jboss-modules + + + io.opentracing.contrib + opentracing-concurrent + + + + io.opentracing + opentracing-api + + + + io.opentracing + opentracing-noop + + + + io.opentracing + opentracing-util + + + io.opentracing + opentracing-mock + test \ No newline at end of file diff --git a/client/src/main/java/org/teiid/client/RequestMessage.java b/client/src/main/java/org/teiid/client/RequestMessage.java index 6832881357..0491e82950 100644 --- a/client/src/main/java/org/teiid/client/RequestMessage.java +++ b/client/src/main/java/org/teiid/client/RequestMessage.java @@ -27,7 +27,9 @@ import java.io.Serializable; import java.util.Arrays; import java.util.Collections; +import java.util.HashMap; import java.util.List; +import java.util.Map; import org.teiid.core.TeiidProcessingException; import org.teiid.core.util.ExternalizeUtil; @@ -40,6 +42,8 @@ */ public class RequestMessage implements Externalizable { + private static final String SPAN_CONTEXT = "spanContext"; //$NON-NLS-1$ + private static final RequestOptions DEFAULT_REQUEST_OPTIONS = new RequestOptions(); public static final int DEFAULT_FETCH_SIZE = 2048; @@ -98,6 +102,8 @@ public enum ShowPlan { private boolean sync; private RequestOptions requestOptions; private Object command; + + private Map properties; public RequestMessage() { } @@ -370,6 +376,7 @@ public void readExternal(ObjectInput in) throws IOException, this.autoGeneratedKeys = (options & 1) == 1; //8.4 property this.delaySerialization = (options & 2) == 2; + this.properties = ExternalizeUtil.readMap(in); } catch (OptionalDataException e) { } catch (EOFException e) { } @@ -405,6 +412,7 @@ public void writeExternal(ObjectOutput out) throws IOException { options |= 2; } out.writeByte(options); + ExternalizeUtil.writeMap(out, properties); } public RequestOptions getRequestOptions() { @@ -433,5 +441,23 @@ public boolean isDelaySerialization() { public void setDelaySerialization(boolean delaySerialization) { this.delaySerialization = delaySerialization; } + + public void setSpanContext(String string) { + if (this.properties == null) { + this.properties = new HashMap(); + } + if (string == null) { + this.properties.remove(SPAN_CONTEXT); + } else { + properties.put(SPAN_CONTEXT, string); + } + } + + public String getSpanContext() { + if (this.properties == null) { + return null; + } + return this.properties.get(SPAN_CONTEXT); + } } diff --git a/client/src/main/java/org/teiid/jdbc/StatementImpl.java b/client/src/main/java/org/teiid/jdbc/StatementImpl.java index 8be8d378cd..b5fc22792b 100644 --- a/client/src/main/java/org/teiid/jdbc/StatementImpl.java +++ b/client/src/main/java/org/teiid/jdbc/StatementImpl.java @@ -55,6 +55,7 @@ import org.teiid.core.util.SqlUtil; import org.teiid.core.util.StringUtil; import org.teiid.jdbc.EnhancedTimer.Task; +import org.teiid.jdbc.tracing.TracingHelper; import org.teiid.net.TeiidURL; @@ -548,6 +549,12 @@ public void onCompletion(ResultsFuture future) { final RequestMessage reqMessage = createRequestMessage(commands, isBatchedCommand, resultsMode); reqMessage.setReturnAutoGeneratedKeys(autoGenerateKeys); reqMessage.setRequestOptions(options); + if (this.driverConnection.getServerConnection() != null && !this.driverConnection.getServerConnection().isLocal()) { + String spanContext = TracingHelper.getSpanContext(); + if (spanContext != null) { + reqMessage.setSpanContext(spanContext); + } + } ResultsFuture pendingResult = execute(reqMessage, synch); final ResultsFuture result = new ResultsFuture(); pendingResult.addCompletionListener(new ResultsFuture.CompletionListener() { diff --git a/client/src/main/java/org/teiid/jdbc/tracing/GlobalTracerInjector.java b/client/src/main/java/org/teiid/jdbc/tracing/GlobalTracerInjector.java new file mode 100644 index 0000000000..410b585ae5 --- /dev/null +++ b/client/src/main/java/org/teiid/jdbc/tracing/GlobalTracerInjector.java @@ -0,0 +1,83 @@ +/* + * Copyright Red Hat, Inc. and/or its affiliates + * and other contributors as indicated by the @author tags and + * the COPYRIGHT.txt file distributed with this work. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.teiid.jdbc.tracing; + +import java.util.HashMap; +import java.util.Map; + +import org.teiid.jdbc.tracing.TracingHelper.Injector; + +import io.opentracing.Span; +import io.opentracing.Tracer; +import io.opentracing.propagation.Format.Builtin; +import io.opentracing.propagation.TextMapInjectAdapter; +import io.opentracing.util.GlobalTracer; + +/** + * Uses the opentracing library to create a json string representation of the span context + * and provides a way to manipulate a static tracer without using the GlobalTracer registration + */ +public class GlobalTracerInjector implements Injector { + + private static Tracer TRACER = GlobalTracer.get(); + + @Override + public String getSpanContext() { + return getSpanContext(TRACER); + } + + protected static String getSpanContext(Tracer tracer) { + Span span = tracer.activeSpan(); + if (span == null) { + return null; + } + Map spanMap = new HashMap(); + tracer.inject(span.context(), Builtin.TEXT_MAP, new TextMapInjectAdapter(spanMap)); + + //simple json creation + StringBuilder json = new StringBuilder(); + json.append('{'); + boolean first = true; + for (Map.Entry entry : spanMap.entrySet()) { + if (!first) { + json.append(','); + } else { + first = false; + } + json.append('"').append(entry.getKey().replace("\"", "\\\"")) //$NON-NLS-1$ //$NON-NLS-2$ + .append("\":\"") //$NON-NLS-1$ + .append(entry.getValue().replace("\"", "\\\"")).append('"'); //$NON-NLS-1$ //$NON-NLS-2$ + } + json.append('}'); + return json.toString(); + } + + /* + * Used to workaround that the GlobalTracer can only be registered once. + */ + + public static Tracer getTracer() { + return TRACER; + } + + public static void setTracer(Tracer tracer) { + TRACER = tracer; + } + +} diff --git a/client/src/main/java/org/teiid/jdbc/tracing/TracingHelper.java b/client/src/main/java/org/teiid/jdbc/tracing/TracingHelper.java new file mode 100644 index 0000000000..a79a1d00be --- /dev/null +++ b/client/src/main/java/org/teiid/jdbc/tracing/TracingHelper.java @@ -0,0 +1,59 @@ +/* + * Copyright Red Hat, Inc. and/or its affiliates + * and other contributors as indicated by the @author tags and + * the COPYRIGHT.txt file distributed with this work. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.teiid.jdbc.tracing; + +import java.util.logging.Level; +import java.util.logging.Logger; + +import org.teiid.core.util.ReflectionHelper; + +/** + * Used to reflection load logic that is dependent upon the opentracing library, or provide a dummy implementation + */ +public class TracingHelper { + + public interface Injector { + String getSpanContext(); + } + + private static Logger logger = Logger.getLogger("org.teiid.jdbc"); //$NON-NLS-1$ + + private static Injector INJECTOR; + + public static String getSpanContext() { + if (INJECTOR == null) { + try { + INJECTOR = (Injector) ReflectionHelper.create("org.teiid.jdbc.tracing.GlobalTracerInjector", null, TracingHelper.class.getClassLoader()); //$NON-NLS-1$ + } catch (Throwable e) { //must catch both Error and Exception + logger.log(Level.FINE, "Unable to load opentracing libraries, propagation will not be used", e); //$NON-NLS-1$ + } + if (INJECTOR == null) { + INJECTOR = new Injector() { + + @Override + public String getSpanContext() { + return null; + } + }; + } + } + return INJECTOR.getSpanContext(); + } + +} diff --git a/client/src/test/java/org/teiid/client/TestRequestMessage.java b/client/src/test/java/org/teiid/client/TestRequestMessage.java index 929ac351e6..2f141b9fa4 100644 --- a/client/src/test/java/org/teiid/client/TestRequestMessage.java +++ b/client/src/test/java/org/teiid/client/TestRequestMessage.java @@ -60,6 +60,7 @@ public static RequestMessage example() { message.setRowLimit(1313); message.setReturnAutoGeneratedKeys(true); message.setDelaySerialization(true); + message.setSpanContext("foo"); return message; } @@ -83,6 +84,7 @@ public static RequestMessage example() { assertEquals(1313, copy.getRowLimit()); assertTrue(copy.isReturnAutoGeneratedKeys()); assertTrue(copy.isDelaySerialization()); + assertEquals("foo", copy.getSpanContext()); } @Test public void testInvalidTxnAutoWrap() { diff --git a/client/src/test/java/org/teiid/jdbc/tracing/TestTracing.java b/client/src/test/java/org/teiid/jdbc/tracing/TestTracing.java new file mode 100644 index 0000000000..17d410a058 --- /dev/null +++ b/client/src/test/java/org/teiid/jdbc/tracing/TestTracing.java @@ -0,0 +1,42 @@ +/* + * Copyright Red Hat, Inc. and/or its affiliates + * and other contributors as indicated by the @author tags and + * the COPYRIGHT.txt file distributed with this work. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.teiid.jdbc.tracing; + +import static org.junit.Assert.*; + +import org.junit.Test; + +import io.opentracing.Scope; +import io.opentracing.mock.MockTracer; + +@SuppressWarnings("nls") +public class TestTracing { + + @Test public void testSpanContextInjection() { + MockTracer tracer = new MockTracer(); + assertNull(GlobalTracerInjector.getSpanContext(tracer)); + Scope ignored = tracer.buildSpan("x").startActive(true); + try { + assertEquals("{\"spanid\":\"2\",\"traceid\":\"1\"}", GlobalTracerInjector.getSpanContext(tracer)); + } finally { + ignored.close(); + } + } + +} diff --git a/engine/pom.xml b/engine/pom.xml index 4ed81b9b72..64afd6da8a 100644 --- a/engine/pom.xml +++ b/engine/pom.xml @@ -145,7 +145,28 @@ com.io7m.xom xom - + + + io.opentracing.contrib + opentracing-concurrent + + + + io.opentracing + opentracing-api + + + + io.opentracing + opentracing-util + + + + io.opentracing + opentracing-mock + test + + diff --git a/engine/src/main/java/org/teiid/dqp/internal/datamgr/ConnectorManager.java b/engine/src/main/java/org/teiid/dqp/internal/datamgr/ConnectorManager.java index 083467f17b..3960724a3f 100644 --- a/engine/src/main/java/org/teiid/dqp/internal/datamgr/ConnectorManager.java +++ b/engine/src/main/java/org/teiid/dqp/internal/datamgr/ConnectorManager.java @@ -23,7 +23,9 @@ import java.lang.reflect.Method; import java.lang.reflect.Proxy; import java.util.Arrays; +import java.util.HashMap; import java.util.List; +import java.util.Map; import java.util.concurrent.ConcurrentHashMap; import javax.naming.InitialContext; @@ -45,12 +47,18 @@ import org.teiid.query.optimizer.capabilities.BasicSourceCapabilities; import org.teiid.query.optimizer.capabilities.SourceCapabilities; import org.teiid.query.sql.lang.Command; +import org.teiid.query.util.TeiidTracingUtil; import org.teiid.query.validator.ValidatorReport; import org.teiid.resource.spi.WrappedConnection; import org.teiid.translator.ExecutionContext; import org.teiid.translator.ExecutionFactory; +import org.teiid.translator.Translator; import org.teiid.translator.TranslatorException; +import io.opentracing.Span; +import io.opentracing.log.Fields; +import io.opentracing.tag.Tags; + /** * The ConnectorManager manages an {@link ExecutionFactory} @@ -61,6 +69,7 @@ public class ConnectorManager { private static final String JAVA_CONTEXT = "java:/"; //$NON-NLS-1$ private final String translatorName; + private String translatorType; private final String connectionName; private final String jndiName; private final List id; @@ -94,6 +103,10 @@ public ConnectorManager(String translatorName, String connectionName, ExecutionF this.executionFactory = ef; this.id = Arrays.asList(translatorName, connectionName); if (ef != null) { + Translator annotation = ef.getClass().getAnnotation(Translator.class); + if (annotation != null) { + this.translatorType = annotation.name(); + } ClassLoader originalCL = Thread.currentThread().getContextClassLoader(); try { Thread.currentThread().setContextClassLoader(ef.getClass().getClassLoader()); @@ -262,15 +275,15 @@ public void stop() { } } - void logSRCCommand(AtomicRequestMessage qr, ExecutionContext context, Event cmdStatus, Long finalRowCnt, Long cpuTime) { - logSRCCommand(qr, context, cmdStatus, finalRowCnt, cpuTime, null); + void logSRCCommand(ConnectorWorkItem cwi, AtomicRequestMessage qr, ExecutionContext context, Event cmdStatus, Long finalRowCnt, Long cpuTime) { + logSRCCommand(cwi, qr, context, cmdStatus, finalRowCnt, cpuTime, null); } /** * Add begin point to transaction monitoring table. * @param qr Request that contains the MetaMatrix command information in the transaction. */ - void logSRCCommand(AtomicRequestMessage qr, ExecutionContext context, Event cmdStatus, Long finalRowCnt, Long cpuTime, Object[] command) { + void logSRCCommand(ConnectorWorkItem cwi, AtomicRequestMessage qr, ExecutionContext context, Event cmdStatus, Long finalRowCnt, Long cpuTime, Object[] command) { if (!LogManager.isMessageToBeRecorded(LogConstants.CTX_COMMANDLOGGING_SOURCE, MessageLevel.DETAIL)) { return; } @@ -293,12 +306,40 @@ void logSRCCommand(AtomicRequestMessage qr, ExecutionContext context, Event cmdS CommandLogMessage message = null; if (cmdStatus == Event.NEW) { message = new CommandLogMessage(System.currentTimeMillis(), qr.getRequestID().toString(), sid.getNodeID(), transactionID, modelName, translatorName, qr.getWorkContext().getSessionId(), principal, sqlStr, context); + Span span = TeiidTracingUtil.getInstance().buildSourceSpan(message, translatorType); + cwi.setTracingSpan(span); } else { message = new CommandLogMessage(System.currentTimeMillis(), qr.getRequestID().toString(), sid.getNodeID(), transactionID, modelName, translatorName, qr.getWorkContext().getSessionId(), principal, finalRowCnt, cmdStatus, context, cpuTime); if (cmdStatus == Event.SOURCE) { message.setSourceCommand(command); } + Span span = cwi.getTracingSpan(); + if (span != null) { + switch (cmdStatus) { + case SOURCE: + if (command != null) { + Map map = new HashMap(); + map.put("source-command", Arrays.toString(command)); //$NON-NLS-1$ + span.log(map); + } + break; + case CANCEL: + span.log("cancel"); //$NON-NLS-1$ + break; + case END: + span.finish(); + break; + case ERROR: + Tags.ERROR.set(span, true); + Map map = new HashMap(); + map.put(Fields.EVENT, "error"); //$NON-NLS-1$ + span.log(map); + break; + default: + break; + } + } } LogManager.log(MessageLevel.DETAIL, LogConstants.CTX_COMMANDLOGGING_SOURCE, message); } diff --git a/engine/src/main/java/org/teiid/dqp/internal/datamgr/ConnectorWorkItem.java b/engine/src/main/java/org/teiid/dqp/internal/datamgr/ConnectorWorkItem.java index 6fd0253d87..84bc0dc45f 100644 --- a/engine/src/main/java/org/teiid/dqp/internal/datamgr/ConnectorWorkItem.java +++ b/engine/src/main/java/org/teiid/dqp/internal/datamgr/ConnectorWorkItem.java @@ -74,11 +74,15 @@ import org.teiid.query.sql.lang.StoredProcedure; import org.teiid.query.sql.symbol.Expression; import org.teiid.query.util.CommandContext; +import org.teiid.query.util.TeiidTracingUtil; import org.teiid.resource.spi.WrappedConnection; import org.teiid.translator.*; import org.teiid.translator.ExecutionFactory.TransactionSupport; import org.teiid.util.XMLInputStream; +import io.opentracing.Scope; +import io.opentracing.Span; + public class ConnectorWorkItem implements ConnectorWork { /* Permanent state members */ @@ -123,6 +127,8 @@ public class ConnectorWorkItem implements ConnectorWork { private boolean unmodifiableList; + private Span span; + ConnectorWorkItem(AtomicRequestMessage message, ConnectorManager manager) throws TeiidComponentException { this.id = message.getAtomicRequestID(); this.requestMsg = message; @@ -201,7 +207,7 @@ public void cancel(boolean abnormal) { Execution ex = this.execution; if(ex != null) { if (abnormal) { - this.manager.logSRCCommand(this.requestMsg, this.securityContext, Event.CANCEL, -1l, null); + this.manager.logSRCCommand(this, this.requestMsg, this.securityContext, Event.CANCEL, -1l, null); } ex.cancel(); LogManager.logDetail(LogConstants.CTX_CONNECTOR, QueryPlugin.Util.getString("DQPCore.The_atomic_request_has_been_cancelled", this.id)); //$NON-NLS-1$ @@ -226,13 +232,20 @@ public synchronized AtomicResultsMessage more() throws TranslatorException { throw handleError(this.conversionError); } LogManager.logDetail(LogConstants.CTX_CONNECTOR, new Object[] {this.id, "Processing MORE request"}); //$NON-NLS-1$ + Scope scope = null; try { timer.start(); + if (span != null) { + scope = TeiidTracingUtil.getInstance().activateSpan(span); + } return handleBatch(); } catch (Throwable t) { throw handleError(t); } finally { timer.stop(); + if (scope != null) { + scope.close(); + } } } @@ -246,8 +259,12 @@ public synchronized void close() { return; //already closed } LogManager.logDetail(LogConstants.CTX_CONNECTOR, new Object[] {this.id, "Processing Close :", this.requestMsg.getCommand()}); //$NON-NLS-1$ + Scope scope = null; try { timer.start(); + if (this.span != null) { + scope = TeiidTracingUtil.getInstance().activateSpan(this.span); + } if (execution != null) { execution.close(); LogManager.logDetail(LogConstants.CTX_CONNECTOR, new Object[] {this.id, "Closed execution"}); //$NON-NLS-1$ @@ -268,7 +285,10 @@ public synchronized void close() { LogManager.logDetail(LogConstants.CTX_CONNECTOR, new Object[] {this.id, "Closed connection"}); //$NON-NLS-1$ } Long time = timer.stop(); - manager.logSRCCommand(this.requestMsg, this.securityContext, Event.END, this.rowCount, time); + manager.logSRCCommand(this, this.requestMsg, this.securityContext, Event.END, this.rowCount, time); + if (scope != null) { + scope.close(); + } } } @@ -284,7 +304,7 @@ private TranslatorException handleError(Throwable t) { if (isCancelled.get()) { LogManager.logDetail(LogConstants.CTX_CONNECTOR, msg); } else { - manager.logSRCCommand(this.requestMsg, this.securityContext, Event.ERROR, null, null); + manager.logSRCCommand(this, this.requestMsg, this.securityContext, Event.ERROR, null, null); Throwable toLog = t; if (this.requestMsg.getCommandContext().getOptions().isSanitizeMessages() && !LogManager.isMessageToBeRecorded(LogConstants.CTX_CONNECTOR, MessageLevel.DETAIL)) { @@ -306,6 +326,7 @@ public synchronized void execute() throws TranslatorException { if(isCancelled()) { throw new TranslatorException(QueryPlugin.Event.TEIID30476, QueryPlugin.Util.gs(QueryPlugin.Event.TEIID30476)); } + Scope scope = null; timer.start(); try { if (this.execution == null) { @@ -352,7 +373,10 @@ public synchronized void execute() throws TranslatorException { LogManager.logDetail(LogConstants.CTX_CONNECTOR, new Object[] {this.requestMsg.getAtomicRequestID(), "Obtained execution"}); //$NON-NLS-1$ //Log the Source Command (Must be after obtaining the execution context) - manager.logSRCCommand(this.requestMsg, this.securityContext, Event.NEW, null, null); + manager.logSRCCommand(this, this.requestMsg, this.securityContext, Event.NEW, null, null); + if (this.span != null) { + scope = TeiidTracingUtil.getInstance().activateSpan(this.span); + } } // Execute query this.execution.execute(); @@ -361,6 +385,9 @@ public synchronized void execute() throws TranslatorException { throw handleError(t); } finally { timer.stop(); + if (scope != null) { + scope.close(); + } } } @@ -770,7 +797,15 @@ public boolean equals(Object obj) { } public void logCommand(Object... command) { - this.manager.logSRCCommand(this.requestMsg, securityContext, Event.SOURCE, null, null, command); + this.manager.logSRCCommand(this, this.requestMsg, securityContext, Event.SOURCE, null, null, command); } + public void setTracingSpan(Span span) { + this.span = span; + } + + public Span getTracingSpan() { + return span; + } + } \ No newline at end of file diff --git a/engine/src/main/java/org/teiid/dqp/internal/process/DQPConfiguration.java b/engine/src/main/java/org/teiid/dqp/internal/process/DQPConfiguration.java index a0ead196ac..bd602e6cc4 100644 --- a/engine/src/main/java/org/teiid/dqp/internal/process/DQPConfiguration.java +++ b/engine/src/main/java/org/teiid/dqp/internal/process/DQPConfiguration.java @@ -22,8 +22,11 @@ import org.teiid.PreParser; import org.teiid.client.RequestMessage; import org.teiid.core.util.PropertiesUtils; +import org.teiid.jdbc.tracing.GlobalTracerInjector; import org.teiid.query.util.Options; +import io.opentracing.Tracer; +import io.opentracing.contrib.concurrent.TracedRunnable; public class DQPConfiguration{ @@ -176,7 +179,14 @@ public long getQueryTimeout() { } public TeiidExecutor getTeiidExecutor() { - return new ThreadReuseExecutor(DQPConfiguration.PROCESS_PLAN_QUEUE_NAME, getMaxThreads()); + return new ThreadReuseExecutor(DQPConfiguration.PROCESS_PLAN_QUEUE_NAME, getMaxThreads()) { + Tracer tracer = GlobalTracerInjector.getTracer(); + @Override + public void execute(Runnable command) { + super.execute(tracer.activeSpan() == null ? command : + new TracedRunnable(command, tracer)); + } + }; } public void setPreParser(PreParser preParser) { diff --git a/engine/src/main/java/org/teiid/dqp/internal/process/DQPCore.java b/engine/src/main/java/org/teiid/dqp/internal/process/DQPCore.java index 47dfdc8076..f4ecccd4d8 100644 --- a/engine/src/main/java/org/teiid/dqp/internal/process/DQPCore.java +++ b/engine/src/main/java/org/teiid/dqp/internal/process/DQPCore.java @@ -23,6 +23,7 @@ import java.util.Arrays; import java.util.Collection; import java.util.Collections; +import java.util.HashMap; import java.util.LinkedList; import java.util.List; import java.util.Map; @@ -72,6 +73,7 @@ import org.teiid.events.EventDistributor; import org.teiid.jdbc.EnhancedTimer; import org.teiid.jdbc.LocalProfile; +import org.teiid.jdbc.tracing.GlobalTracerInjector; import org.teiid.logging.CommandLogMessage; import org.teiid.logging.CommandLogMessage.Event; import org.teiid.logging.LogConstants; @@ -85,6 +87,12 @@ import org.teiid.query.tempdata.TempTableStore.TransactionMode; import org.teiid.query.util.CommandContext; import org.teiid.query.util.Options; +import org.teiid.query.util.TeiidTracingUtil; + +import io.opentracing.Span; +import io.opentracing.contrib.concurrent.TracedExecutorService; +import io.opentracing.log.Fields; +import io.opentracing.tag.Tags; /** * Implements the core DQP processing. @@ -602,6 +610,7 @@ void logMMCommand(RequestWorkItem workItem, Event status, Long rowCount, Long cp CommandLogMessage message = null; if (status == Event.NEW) { message = new CommandLogMessage(System.currentTimeMillis(), rID.toString(), txnID, workContext.getSessionId(), appName, workContext.getUserName(), workContext.getVdbName(), workContext.getVdbVersion(), msg.getCommandString(), cpuTime); + workItem.setTracingSpan(TeiidTracingUtil.getInstance().buildSpan(message, msg.getSpanContext())); } else { QueryProcessor qp = workItem.getProcessor(); PlanNode plan = null; @@ -609,6 +618,29 @@ void logMMCommand(RequestWorkItem workItem, Event status, Long rowCount, Long cp plan = qp.getProcessorPlan().getDescriptionProperties(); } message = new CommandLogMessage(System.currentTimeMillis(), rID.toString(), txnID, workContext.getSessionId(), workContext.getUserName(), workContext.getVdbName(), workContext.getVdbVersion(), rowCount, status, plan); + Span span = workItem.getTracingSpan(); + if (span != null) { + switch (status) { + case PLAN: + span.log("planning complete"); //$NON-NLS-1$ + break; + case CANCEL: + span.log("cancel"); //$NON-NLS-1$ + break; + case END: + span.finish(); + break; + case ERROR: + Tags.ERROR.set(span, true); + Map map = new HashMap(); + map.put(Fields.EVENT, "error"); //$NON-NLS-1$ + span.log(map); + break; + default: + //nothing + break; + } + } } LogManager.log(status == Event.PLAN?MessageLevel.TRACE:MessageLevel.DETAIL, LogConstants.CTX_COMMANDLOGGING, message); } @@ -645,7 +677,7 @@ public void start(DQPConfiguration theConfig) { this.processWorkerPool = config.getTeiidExecutor(); //we don't want cancellations waiting on normal processing, so they get a small dedicated pool //TODO: overflow to the worker pool - timeoutExecutor = ExecutorUtils.newFixedThreadPool(3, "Server Side Timeout"); //$NON-NLS-1$ + timeoutExecutor = new TracedExecutorService(ExecutorUtils.newFixedThreadPool(3, "Server Side Timeout"), GlobalTracerInjector.getTracer()); //$NON-NLS-1$ this.cancellationTimer = new EnhancedTimer(timeoutExecutor, timeoutExecutor); this.maxActivePlans = config.getMaxActivePlans(); diff --git a/engine/src/main/java/org/teiid/dqp/internal/process/RequestWorkItem.java b/engine/src/main/java/org/teiid/dqp/internal/process/RequestWorkItem.java index 0dfe649be1..dcb1a4f67c 100644 --- a/engine/src/main/java/org/teiid/dqp/internal/process/RequestWorkItem.java +++ b/engine/src/main/java/org/teiid/dqp/internal/process/RequestWorkItem.java @@ -90,6 +90,9 @@ import org.teiid.query.util.CommandContext; import org.teiid.query.util.GeneratedKeysImpl; import org.teiid.query.util.Options; +import org.teiid.query.util.TeiidTracingUtil; + +import io.opentracing.Span; /** * Compiles results and other information for the client. There is quite a bit of logic @@ -228,6 +231,8 @@ private enum TransactionState {NONE, ACTIVE, DONE} private long planningEnd; private ThreadCpuTimer timer = new ThreadCpuTimer(); + + private Span span; public RequestWorkItem(DQPCore dqpCore, RequestMessage requestMsg, Request request, ResultsReceiver receiver, RequestID requestID, DQPWorkContext workContext) { this.requestMsg = requestMsg; @@ -268,6 +273,10 @@ protected boolean isDoneProcessing() { @Override public void run() { + io.opentracing.Scope scope = null; + if (this.span != null) { + scope = TeiidTracingUtil.getInstance().activateSpan(this.span); + } hasThread = true; timer.start(); LogManager.putMdc(REQUEST_KEY, requestID.toString()); @@ -300,6 +309,9 @@ public void run() { timer.stop(); LogManager.removeMdc(REQUEST_KEY); hasThread = false; + if (scope != null) { + scope.close(); + } } } @@ -1256,6 +1268,9 @@ public boolean isCloseRequested() { } public void requestMore(int batchFirst, int batchLast, ResultsReceiver receiver) { + if (span != null) { + span.log("requested more results"); //$NON-NLS-1$ + } this.requestResults(batchFirst, batchLast, receiver); this.doMoreWork(); } @@ -1401,4 +1416,12 @@ public RequestID getRequestID() { return requestID; } + public void setTracingSpan(Span span) { + this.span = span; + } + + public Span getTracingSpan() { + return this.span; + } + } \ No newline at end of file diff --git a/engine/src/main/java/org/teiid/query/util/TeiidTracingUtil.java b/engine/src/main/java/org/teiid/query/util/TeiidTracingUtil.java new file mode 100644 index 0000000000..c0cd41ed82 --- /dev/null +++ b/engine/src/main/java/org/teiid/query/util/TeiidTracingUtil.java @@ -0,0 +1,148 @@ +/* + * Copyright 2017-2018 The OpenTracing Authors + * Copyright Red Hat, Inc. and/or its affiliates + * and other contributors as indicated by the @author tags and + * the COPYRIGHT.txt file distributed with this work. + * + * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except + * in compliance with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software distributed under the License + * is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express + * or implied. See the License for the specific language governing permissions and limitations under + * the License. + */ +package org.teiid.query.util; + +import java.util.Map; + +import org.teiid.jdbc.tracing.GlobalTracerInjector; +import org.teiid.json.simple.JSONParser; +import org.teiid.json.simple.ParseException; +import org.teiid.json.simple.SimpleContentHandler; +import org.teiid.logging.CommandLogMessage; +import org.teiid.logging.LogConstants; +import org.teiid.logging.LogManager; + +import io.opentracing.Scope; +import io.opentracing.Span; +import io.opentracing.SpanContext; +import io.opentracing.Tracer; +import io.opentracing.propagation.Format.Builtin; +import io.opentracing.propagation.TextMapExtractAdapter; +import io.opentracing.tag.Tags; + +public class TeiidTracingUtil { + + private boolean withActiveSpanOnly; + private Tracer tracer = GlobalTracerInjector.getTracer(); + + private static TeiidTracingUtil INSTANCE = new TeiidTracingUtil(); + + public static TeiidTracingUtil getInstance() { + INSTANCE.tracer = GlobalTracerInjector.getTracer(); + return INSTANCE; + } + + /** + * For use by tests - GlobalTracer is not directly test friendly as the registration can only happen once. + */ + void setTracer(Tracer tracer) { + this.tracer = tracer; + } + + public void setWithActiveSpanOnly(boolean withActiveSpanOnly) { + this.withActiveSpanOnly = withActiveSpanOnly; + } + + /** + * Build a {@link Span} from the {@link CommandLogMessage} and incoming span context + * @param message + * @param spanContextJson + * @return + */ + public Span buildSpan(CommandLogMessage msg, String spanContextJson) { + if (withActiveSpanOnly && tracer.activeSpan() == null && spanContextJson == null) { + return null; + } + + Tracer.SpanBuilder spanBuilder = tracer + .buildSpan("USER COMMAND") //$NON-NLS-1$ + .withTag(Tags.SPAN_KIND.getKey(), Tags.SPAN_KIND_SERVER); + + if (spanContextJson != null) { + SpanContext parent = extractSpanContext(spanContextJson); + if (parent != null) { + spanBuilder.asChildOf(parent); + } else if (withActiveSpanOnly) { + return null; + } + } + + Span span = spanBuilder.start(); + + Tags.COMPONENT.set(span, "java-teiid"); //$NON-NLS-1$ + + Tags.DB_STATEMENT.set(span, msg.getSql()); + Tags.DB_TYPE.set(span, "teiid"); //$NON-NLS-1$ + Tags.DB_INSTANCE.set(span, msg.getVdbName()); + Tags.DB_USER.set(span, msg.getPrincipal()); + + span.setTag("teiid-session", msg.getSessionID()); //$NON-NLS-1$ + span.setTag("teiid-request", msg.getRequestID()); //$NON-NLS-1$ + + return span; + } + + /** + * Build a {@link Span} from the {@link CommandLogMessage} and translator type + * @param msg + * @param translatorType + * @return + */ + public Span buildSourceSpan(CommandLogMessage msg, String translatorType) { + if (tracer.activeSpan() == null) { + return null; + } + + Tracer.SpanBuilder spanBuilder = tracer + .buildSpan("SRC COMMAND") //$NON-NLS-1$ + .withTag(Tags.SPAN_KIND.getKey(), Tags.SPAN_KIND_CLIENT); + + Span span = spanBuilder.start(); + + Tags.COMPONENT.set(span, "java-teiid-connector"); //$NON-NLS-1$ + + Tags.DB_STATEMENT.set(span, msg.getSql()); + Tags.DB_TYPE.set(span, translatorType); + Tags.DB_USER.set(span, msg.getPrincipal()); + + span.setTag("teiid-source-request", msg.getSourceCommandID()); //$NON-NLS-1$ + + return span; + } + + public Scope activateSpan(Span span) { + if (tracer.activeSpan() == span) { + //when a workitem adds itself to a queue the span will already be active + return null; + } + return tracer.scopeManager().activate(span, false); + } + + protected SpanContext extractSpanContext(String spanContextJson) { + try { + JSONParser parser = new JSONParser(); + SimpleContentHandler sch = new SimpleContentHandler(); + parser.parse(spanContextJson, sch); + Map result = (Map) sch.getResult(); + return tracer.extract(Builtin.TEXT_MAP, new TextMapExtractAdapter(result)); + } catch (IllegalArgumentException | ClassCastException | ParseException e) { + LogManager.logDetail(LogConstants.CTX_DQP, e, "Could not extract the span context"); //$NON-NLS-1$ + return null; + } + } + +} \ No newline at end of file diff --git a/engine/src/test/java/org/teiid/query/util/TestTeiidTracingUtil.java b/engine/src/test/java/org/teiid/query/util/TestTeiidTracingUtil.java new file mode 100644 index 0000000000..587a257956 --- /dev/null +++ b/engine/src/test/java/org/teiid/query/util/TestTeiidTracingUtil.java @@ -0,0 +1,49 @@ +/* + * Copyright Red Hat, Inc. and/or its affiliates + * and other contributors as indicated by the @author tags and + * the COPYRIGHT.txt file distributed with this work. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.teiid.query.util; + +import static org.junit.Assert.*; + +import org.junit.Test; +import org.teiid.logging.CommandLogMessage; + +import io.opentracing.Span; +import io.opentracing.SpanContext; +import io.opentracing.mock.MockTracer; + +@SuppressWarnings("nls") +public class TestTeiidTracingUtil { + + @Test public void testTracing() { + TeiidTracingUtil ttu = new TeiidTracingUtil(); + MockTracer tracer = new MockTracer(); + ttu.setTracer(tracer); + assertNotNull(ttu.extractSpanContext("{\"spanid\":\"1\",\"traceid\":\"2\"}")); + SpanContext spanContext = ttu.extractSpanContext("corrupted"); + assertNull(spanContext); + assertNull(tracer.activeSpan()); //should be null, no side effect just from extract + + Span span = ttu.buildSpan(new CommandLogMessage(0, "", null, null, null, null, null, null, "", null), null); + assertNotNull(span); + + span = ttu.buildSpan(new CommandLogMessage(0, "", null, null, null, null, null, null, "", null), "{\"spanid\":\"1\",\"traceid\":\"2\"}"); + assertNotNull(span); + } + +} diff --git a/pom.xml b/pom.xml index 85f6e0288c..10c66aa861 100644 --- a/pom.xml +++ b/pom.xml @@ -32,6 +32,9 @@ into a new release of the bom. --> + 0.1.0 + 0.31.0 + scm:git:git://github.com/teiid/teiid.git @@ -612,6 +615,38 @@ teiid-data-quality ${project.version} + + + io.opentracing.contrib + opentracing-concurrent + ${version.opentracing.concurrent} + + + + io.opentracing + opentracing-api + ${version.opentracing} + + + + io.opentracing + opentracing-noop + ${version.opentracing} + + + + io.opentracing + opentracing-util + ${version.opentracing} + + + + io.opentracing + opentracing-mock + ${version.opentracing} + test + + diff --git a/runtime/pom.xml b/runtime/pom.xml index 1662a576c5..f5ad89f4c6 100644 --- a/runtime/pom.xml +++ b/runtime/pom.xml @@ -137,16 +137,10 @@ picketbox test - diff --git a/runtime/src/test/java/org/teiid/runtime/TestEmbeddedServer.java b/runtime/src/test/java/org/teiid/runtime/TestEmbeddedServer.java index 7d82e164b7..353f7ffd94 100644 --- a/runtime/src/test/java/org/teiid/runtime/TestEmbeddedServer.java +++ b/runtime/src/test/java/org/teiid/runtime/TestEmbeddedServer.java @@ -76,10 +76,14 @@ import org.teiid.jdbc.SQLStates; import org.teiid.jdbc.TeiidDriver; import org.teiid.jdbc.TeiidSQLException; +import org.teiid.jdbc.tracing.GlobalTracerInjector; import org.teiid.language.Command; import org.teiid.language.Literal; import org.teiid.language.QueryExpression; import org.teiid.language.visitor.CollectorVisitor; +import org.teiid.logging.LogConstants; +import org.teiid.logging.Logger; +import org.teiid.logging.MessageLevel; import org.teiid.metadata.Column; import org.teiid.metadata.MetadataException; import org.teiid.metadata.MetadataFactory; @@ -87,6 +91,7 @@ import org.teiid.metadata.RuntimeMetadata; import org.teiid.metadata.Table; import org.teiid.query.sql.symbol.Reference; +import org.teiid.query.util.TeiidTracingUtil; import org.teiid.runtime.EmbeddedServer.ConnectionFactoryProvider; import org.teiid.translator.DataNotAvailableException; import org.teiid.translator.ExecutionContext; @@ -101,6 +106,11 @@ import org.teiid.transport.SocketConfiguration; import org.teiid.transport.WireProtocol; +import io.opentracing.Scope; +import io.opentracing.mock.MockSpan; +import io.opentracing.mock.MockTracer; +import io.opentracing.util.GlobalTracer; + @SuppressWarnings("nls") public class TestEmbeddedServer { @Translator (name="y") @@ -2470,5 +2480,95 @@ public void loadMetadata(MetadataFactory factory, rs.close(); assertEquals(100, count); } + + @Test public void testOpenTracing() throws Exception { + MockTracer tracer = new MockTracer(); + GlobalTracerInjector.setTracer(tracer); + TeiidTracingUtil.getInstance().setWithActiveSpanOnly(true); + Logger logger = Mockito.mock(Logger.class); + Mockito.stub(logger.isEnabled(LogConstants.CTX_COMMANDLOGGING, MessageLevel.DETAIL)).toReturn(true); + Mockito.stub(logger.isEnabled(LogConstants.CTX_COMMANDLOGGING_SOURCE, MessageLevel.DETAIL)).toReturn(true); + Logger old = org.teiid.logging.LogManager.setLogListener(logger); + try { + SocketConfiguration s = new SocketConfiguration(); + InetSocketAddress addr = new InetSocketAddress(0); + s.setBindAddress(addr.getHostName()); + s.setPortNumber(addr.getPort()); + s.setProtocol(WireProtocol.teiid); + EmbeddedConfiguration config = new EmbeddedConfiguration(); + config.addTransport(s); + es.start(config); + + HardCodedExecutionFactory hcef = new HardCodedExecutionFactory(); + hcef.addData("SELECT t1.col_t1 FROM t1", Arrays.asList(Arrays.asList("a"))); + hcef.addData("SELECT t2.col_t2 FROM t2", Arrays.asList(Arrays.asList("b"))); + es.addTranslator("y", hcef); + + ModelMetaData mmd = new ModelMetaData(); + mmd.setName("y"); + mmd.addSourceMetadata("ddl", "create foreign table t1(col_t1 varchar) options (cardinality 20); " + + "create foreign table t2(col_t2 varchar) options (cardinality 20);"); + mmd.addSourceMapping("y", "y", null); + es.deployVDB("x", mmd); + Connection c = es.getDriver().connect("jdbc:teiid:x;", null); + Statement stmt = c.createStatement(); + + ResultSet rs = stmt.executeQuery("select * from t1 union all select * from t2"); + while (rs.next()) { + + } + stmt.close(); + + List spans = tracer.finishedSpans(); + assertEquals(0, spans.size()); + + try (Scope ignored = tracer.buildSpan("some operation").startActive(true)) { + assertNotNull(tracer.activeSpan()); + stmt = c.createStatement(); + //execute with an active span + rs = stmt.executeQuery("select * from t1 union all select * from t2"); + while (rs.next()) { + + } + stmt.close(); + } + + spans = tracer.finishedSpans(); + + //parent span started here, and a child span for the query execution, 2 source queries + assertEquals(spans.toString(), 4, spans.size()); + + tracer.reset(); + + //remote propagation + Connection remote = TeiidDriver.getInstance().connect("jdbc:teiid:x@mm://"+addr.getHostName()+":"+es.transports.get(0).getPort(), null); + + try (Scope ignored = tracer.buildSpan("some remote operation").startActive(true)) { + assertNotNull(tracer.activeSpan()); + stmt = remote.createStatement(); + //execute with an active span + rs = stmt.executeQuery("select * from t1 union all select * from t2"); + while (rs.next()) { + + } + stmt.close(); + } + + //this isn't ideal, but close is an async event + for (int i = 0; i < 1000; i++) { + spans = tracer.finishedSpans(); + if (spans.size() == 2) { + break; + } + Thread.sleep(10); + } + + //parent span started here, and a child span for the query execution, 2 source queries + assertEquals(4, spans.size()); + } finally { + GlobalTracerInjector.setTracer(GlobalTracer.get()); + org.teiid.logging.LogManager.setLogListener(old); + } + } } diff --git a/settings.xml b/settings.xml index 193e82e2d8..8c29eee191 100644 --- a/settings.xml +++ b/settings.xml @@ -6,6 +6,15 @@ http://maven.apache.org/xsd/settings-1.0.0.xsd"> jboss-public-repository + + central + Maven Central + http://repo.maven.apache.org/maven2/ + + false + never + + jboss-public-repository-group JBoss Public Maven Repository Group diff --git a/teiid-feature-pack/client-feature-pack/src/main/resources/modules/system/layers/dv/io/opentracing/main/module.xml b/teiid-feature-pack/client-feature-pack/src/main/resources/modules/system/layers/dv/io/opentracing/main/module.xml new file mode 100644 index 0000000000..478e938f2a --- /dev/null +++ b/teiid-feature-pack/client-feature-pack/src/main/resources/modules/system/layers/dv/io/opentracing/main/module.xml @@ -0,0 +1,14 @@ + + + + + + + + + + + + + + diff --git a/teiid-feature-pack/client-feature-pack/src/main/resources/modules/system/layers/dv/org/jboss/teiid/client/main/module.xml b/teiid-feature-pack/client-feature-pack/src/main/resources/modules/system/layers/dv/org/jboss/teiid/client/main/module.xml index 5b455a22a7..b939fa2f83 100644 --- a/teiid-feature-pack/client-feature-pack/src/main/resources/modules/system/layers/dv/org/jboss/teiid/client/main/module.xml +++ b/teiid-feature-pack/client-feature-pack/src/main/resources/modules/system/layers/dv/org/jboss/teiid/client/main/module.xml @@ -16,5 +16,6 @@ + \ No newline at end of file diff --git a/teiid-feature-pack/wildfly-integration-feature-pack/src/main/resources/content/docs/teiid/teiid-releasenotes.html b/teiid-feature-pack/wildfly-integration-feature-pack/src/main/resources/content/docs/teiid/teiid-releasenotes.html index 73505dd74d..35bd98c827 100644 --- a/teiid-feature-pack/wildfly-integration-feature-pack/src/main/resources/content/docs/teiid/teiid-releasenotes.html +++ b/teiid-feature-pack/wildfly-integration-feature-pack/src/main/resources/content/docs/teiid/teiid-releasenotes.html @@ -28,6 +28,7 @@

Highlights

  • TEIID-5356 Improved column metadata with DDL views - and other metadata fixes such as TEIID-5361 and TEIID-5359
  • TEIID-3439 Added support for table aliases to contain a period '.' character
  • Various SQL compatibility issues to support JOQL
    • +
  • TEIIDTOOLS-437 OpenTracing integration for remote JDBC clients. Further automatic integration will be provided via Thorntail.

    • Compatibility Issues

    diff --git a/teiid-feature-pack/wildfly-integration-feature-pack/src/main/resources/modules/system/layers/dv/org/jboss/teiid/main/module.xml b/teiid-feature-pack/wildfly-integration-feature-pack/src/main/resources/modules/system/layers/dv/org/jboss/teiid/main/module.xml index c98644bb68..39ba9a734c 100644 --- a/teiid-feature-pack/wildfly-integration-feature-pack/src/main/resources/modules/system/layers/dv/org/jboss/teiid/main/module.xml +++ b/teiid-feature-pack/wildfly-integration-feature-pack/src/main/resources/modules/system/layers/dv/org/jboss/teiid/main/module.xml @@ -53,7 +53,6 @@ - @@ -67,5 +66,7 @@ + +