hotdust commented 5 years ago

Bug

If import opentracing-spring-cloud-jdbc-starter dependency, and configure driver-class-name: io.opentracing.contrib.jdbc.TracingDriver at the same time, then duplicated span will be generated.

version: master(0.2.5-SNAPSHOT)

Modification

  @Around("execution(java.sql.Connection *.getConnection(..)) && target(javax.sql.DataSource)")
  public Object getConnection(final ProceedingJoinPoint pjp) throws Throwable {
    Connection conn = (Connection) pjp.proceed();
    if (conn instanceof TracingConnection ||
        conn.isWrapperFor(TracingConnection.class)) {  // ******* added ******
      return conn;
    }
    String url = conn.getMetaData().getURL();
    ConnectionInfo connectionInfo = URLParser.parser(url);
    return new TracingConnection(conn, connectionInfo, withActiveSpanOnly, ignoredStatements);
  }

Both DruidDataSource and BasicDataSource works normally.

Evidence

Before:

After:

pavolloffay commented 5 years ago

@hotdust thanks for reporting? Do you want to report a fix for this?

hotdust commented 5 years ago

@pavolloffay thanks for reply. I made a PR(#211). Please check that PR when you have time.

pavolloffay commented 5 years ago

thanks @hotdust

bromine0x23 commented 5 years ago

This change cause Oracle JDBC Driver throw an exception

stack:

org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLException: Object does not wrap anything with requested interface
        at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:81)
        at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:323)
        at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.getProduct(DataSourceHealthIndicator.java:122)
        at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.doDataSourceHealthCheck(DataSourceHealthIndicator.java:109)
        at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.doHealthCheck(DataSourceHealthIndicator.java:104)
        at org.springframework.boot.actuate.health.AbstractHealthIndicator.health(AbstractHealthIndicator.java:84)
        at org.springframework.boot.actuate.health.HealthIndicatorReactiveAdapter.invoke(HealthIndicatorReactiveAdapter.java:48)
        at org.springframework.boot.actuate.health.HealthIndicatorReactiveAdapter.lambda$null$0(HealthIndicatorReactiveAdapter.java:43)
        at reactor.core.scheduler.ElasticScheduler$DirectScheduleTask.run(ElasticScheduler.java:291)
        at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50)
        at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.sql.SQLException: Object does not wrap anything with requested interface
        at oracle.jdbc.driver.OracleConnection.isWrapperFor(OracleConnection.java:251)
        at com.zaxxer.hikari.pool.ProxyConnection.isWrapperFor(ProxyConnection.java:443)
        at io.opentracing.contrib.spring.cloud.jdbc.JdbcAspect.getConnection(JdbcAspect.java:56)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688)
        at com.zaxxer.hikari.HikariDataSource$$EnhancerBySpringCGLIB$$933b2aca.getConnection(<generated>)
        at com.zaxxer.hikari.HikariDataSource$$FastClassBySpringCGLIB$$eeb1ae86.invoke(<generated>)
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:749)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
        at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:136)
        at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:124)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688)
        at com.zaxxer.hikari.HikariDataSource$$EnhancerBySpringCGLIB$$15fff85b.getConnection(<generated>)
        at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:157)
        at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:115)
        at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:78)
        ... 16 common frames omitted

The reason is that the OracleConnection#isWrapperFor throw exception if the given class parameter is not an interface

pavolloffay commented 5 years ago

@bromine0x23 is there a way to fix it for oracle driver?

bromine0x23 commented 5 years ago

@pavolloffay simply capture the exception?

The Oracle's implement is simple and like that (checked from ojdbc6#11.2.0.4 to ojdbc8#18.3):

public boolean isWrapperFor(Class<?> var1) throws SQLException {
    if (var1.isInterface()) {
        return var1.isInstance(this);
    } else {
        throw new SQLException();
    }
}

It seems there's no way to avoid the exception.

pavolloffay commented 5 years ago

We could capture it but I guess it would have a perf impact when running that code. It might be worth opening a bug against oracle.

boolean isWrapperFor(Class<?> iface)
              throws SQLException
Returns true if this either implements the interface argument or is directly or indirectly a wrapper for an object that does. Returns false otherwise. If this implements the interface then return true, else if this is a wrapper then return the result of recursively calling isWrapperFor on the wrapped object. If this does not implement the interface and is not a wrapper, return false. This method should be implemented as a low-cost operation compared to unwrap so that callers can use this method to avoid expensive unwrap calls that may fail. If this method returns true then calling unwrap with the same argument should succeed.
Parameters:
iface - a Class defining an interface.
Returns:
true if this implements the interface or directly or indirectly wraps an object that does.
Throws:
SQLException - if an error occurs while determining whether this is a wrapper for an object with the given interface.

bromine0x23 commented 5 years ago

I guess we use isWrapperFor in a wrong way, since the parameter iface require an interface.

birdli66 commented 5 years ago

Yes, I think you use it in a wrong way: The java.sql.Wrapper methods were introduced to unify jdbc and datasource to return the same physical connection.

You should just drop the bugfix you did here and tell the developer using your library to not use aspect-oriented approach with pointcut and manual configuration with TracingDriver at the same time (that certainly leads to 2 spans).

You should as a connection proxy also implement java.sql.Wrapper in the TracingFilter the same way the HikariProxyConnection does it:

   @Override
   public final boolean isWrapperFor(Class<?> iface) throws SQLException
   {
      return iface.isInstance(delegate) || (delegate != null && delegate.isWrapperFor(iface));
   }

Otherwise I can imagine, that the connection unification in the higher layers do not work out as expected and that can lead to very hard to locate problems.

birdli66 commented 5 years ago

If you want to keep this duplicate span detection: Workaround what drivers are doing by meeting their preconditons, in this case tagging your TracingFilter with a ITracingFilter and query for that. I do not like that much though so will not make a PR for that.

pavolloffay commented 5 years ago

@hotdust is there a particular reason why you directly configure driver-class-name: io.opentracing.contrib.jdbc.TracingDrive? Could you rely only on the aspect defined in this project?

birdli66 commented 5 years ago

@hotdust your problem made it into a bugfix affecting other solutions so you could at least answer the above question?

hotdust commented 5 years ago

@pavolloffay I am not familiar with github message. I'm very sorry for the very late reply.

1, > @hotdust is there a particular reason why you directly configure driver-class-name: io.opentracing.contrib.jdbc.TracingDrive? Could you rely only on the aspect defined in this project? Yes, I use aspect in prod environment. when researching jaeger, aspect was not worked for me at beginning, I tried to config TracingDriver. After both configuration worked for me, I found duplicate tracing issue.

2, Why I issue this problem? I read TracingRestTemplateCustomizerConfiguration sources. It prevent tracing being registered again after tracing added by TracingRestTemplateCustomizer. sources as following:

for (ClientHttpRequestInterceptor interceptor : interceptors) {
    if (interceptor instanceof TracingRestTemplateInterceptor) {
        return;
    }
}

I think that it's better Jdbc starter have same action, I issued problem.

3, I tested mysql jdbc driver, and didn't test oracle driver. I'm sorry for that.

birdli66 commented 5 years ago

Thx @hotdust, make sense...my conclusion:

Fix that breaks Oracle is not required anymore
Not relevant in this context (RestTemplate allows querying the interceptor chain, DataSource, where JdbcAspect is applied, does not)
You test what you use it for, Oracle needs to be at hand to rellay test it

Which means:

Reverting the change for Oracle is fine

To make it more robust, a duplicate check based on a tagging interface as mentioned would work as well e.g. something along this:


@Around("execution(java.sql.Connection *.getConnection(..)) && target(javax.sql.DataSource)")
public Object getConnection(final ProceedingJoinPoint pjp) throws Throwable {
 Connection conn = (Connection) pjp.proceed();

if (conn instanceof TracingConnection ||
conn.isWrapperFor(TracingConnection.class)) {
if (conn instanceof JdbcTracingConnection ||
conn.isWrapperFor(JdbcTracingConnectionIface.class)) { return conn; } String url = conn.getMetaData().getURL(); ConnectionInfo connectionInfo = URLParser.parser(url);
return new TracingConnection(conn, connectionInfo, withActiveSpanOnly, ignoredStatements);

return new JdbcTracingConnection(conn, connectionInfo, withActiveSpanOnly, ignoredStatements); }


We are using this based on java-spring-zipkin/0.2.0 which still depends on opentracing/0.31.0 and there is no release 0.3.0 of it depending on 0.32.0 (leads to an java.lang.NoSuchMethodError: io.opentracing.Tracer.activateSpan(Lio/opentracing/Span;)Lio/opentracing/Scope).

So: I can make a pull-request for the above change, but testing it in our setup needs java-spring-zipkin/0.3.0. Is that project dead or are you planning a release on that?

Reason why we choose zipkin: We are currently using the Tracing feature only for development and 'java -jar zikin.jar' is more convenient than 'docker run jaegertracing/all-in-one' for developers not running a docker infrastructure.

pavolloffay commented 5 years ago

@birdli66 feel free to open a PR.

About the zipkin project I am not sure, I would recommend pinging maintainers there.

hotdust commented 5 years ago

@birdli66 thanks for you advice and how to modify it. 1，> Not relevant in this context (RestTemplate allows querying the interceptor chain, DataSource, where JdbcAspect is applied, does not)

In my personal opinion, it's not concern to specific tech implement. it's better that xxx-starter have no side effect on project use it. maybe this is one of reason why springboot provide a lot of annotation(such as @ConditionalXXX).

2，about modification I have responsible to fix it, but there are some reason that I recommand revert code to previous version temporarily. (It's welcome anyone who want to fix it also.) (1) This is rare case that occurs duplicate tracing, and we can tell people how to avoid it. (2) I will take some time to research better way to fix it, and test with some db driver(mysql, oracle, PostgreSQL, and others). But there are more important bugs or requirements (such as #229, #85). I'm writing tracing component for Apache Dubbo RPC, and have nearly finished. If it's possible I would like to contribute it to opentracing project.

how about your opinion? @pavolloffay

birdli66 commented 5 years ago

I'm fine with the revert, we stay on 0.2.4 anyway because of the above 'Upgrade to opentracing/0.32.0 and spring-boot 2.x #8' issue. Will look at this again when opentracing project is more stable again.

ledor473 commented 4 years ago

@pavolloffay I think this bug can be closed now. Since the bug is still open, it caused some FUD for us, but it appears that the usage of isWrapperFor() method was replaced by WrapperProxy. isWrapper() which uses reflection instead of relying on the JDBC implementation.

pavolloffay commented 4 years ago

thanks @ledor473 , I am closing this

opentracing-contrib / java-spring-cloud

Bug Report jdbc generate duplicated span. like #203 #210

Bug

Modification

Evidence

Before:

After: