Misaligned spans exception when used with spring-data-mongodb-reactive and spring-cloud-stream #1770

magnus-larsson · 2020-11-01T07:34:48Z

Versions used

Java: 1.8
Spring Boot: 2.4.0-M3
Spring Cloud: 2020.0.0-M4
Spring Cloud Sleuth: 3.0.0-M4

Description of the error

When Spring Cloud Sleuth is used together with Spring Data MongoDB Reactive and Spring Cloud Stream it throws Misaligned spans exceptions.
This is demonstrated by the GitHub project: [email protected]:magnus-larsson/ml-service-sleuth-issue.git

This project contains three tests:

createProductDirect - creates a document in MongoDB using Spring Data MongoDB Reactive
usingStreamWithoutMongoDb - tests Spring Cloud Stream without using MongoDB
createProductUsingStream - combines usage of Spring Cloud Stream and Spring Data MongoDB Reactive

Test 1 and 2 are ok, while test 3 throws an exception:

Misalignment: scoped span NoopSpan(57d50a0ff0504383/82431158846274f5) !=  current span LazySpan(57d50a0ff0504383/62a7279d555f7b0e)
java.lang.AssertionError: Misalignment: scoped span NoopSpan(57d50a0ff0504383/82431158846274f5) !=  current span LazySpan(57d50a0ff0504383/62a7279d555f7b0e)

Instructions to reproduce the error

git clone [email protected]:magnus-larsson/ml-service-sleuth-issue.git
cd ml-service-sleuth-issue
./gradlew test --info

The build will fail and in the log output you can find:

> Task :test FAILED

se.magnus.microservices.core.product.MLTests > createProductUsingStream() FAILED
    java.lang.AssertionError: Misalignment: scoped span NoopSpan(1f60cb80f1401bd6/f134e48ecd166acd) !=  current span LazySpan(1f60cb80f1401bd6/4f33d06bb34e1043)

To make the failing test run ok, one of the following changes can be made to build.gradle:

Remove spring-cloud-starter-sleuth from the dependencies
Change the Spring Boot version to 2.3.2.RELEASE and Spring Cloud version to Hoxton.SR6

The text was updated successfully, but these errors were encountered:

vvalencia-cl · 2020-11-25T16:43:24Z

Same problem here with the same description, but with newest versions:
JDK 11
Kotlin 1.4.10
Spring Boot 2.4.0
Spring Cloud 2020.0.0-M5

2020-11-25 13:20:29.872 ERROR [app-name_IS_UNDEFINED,abed631d3ccd39ee,f4002f5859cb9edc] 760757 --- [ntLoopGroup-3-4] a.w.r.e.AbstractErrorWebExceptionHandler : [816f22b]  500 Server Error for HTTP PUT "/v1/encodeTypes/code1"

java.lang.AssertionError: Misalignment: scoped span NoopSpan(c48b4623e96c2345/54c16ad747a5cbc9) !=  current span null
	at brave.propagation.ThreadLocalSpan.remove(ThreadLocalSpan.java:164)
	Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Error has been observed at the following site(s):
	|_ checkpoint ⇢ Handler cl.santander.txaudit.presentation.EncodeTypeController#update(String, UpdateEncodeTypeDto) [DispatcherHandler]
	|_ checkpoint ⇢ org.springframework.cloud.sleuth.instrument.web.TraceWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ org.springframework.boot.actuate.metrics.web.reactive.server.MetricsWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ HTTP PUT "/v1/encodeTypes/code1" [ExceptionHandlingWebHandler]
Stack trace:
		at brave.propagation.ThreadLocalSpan.remove(ThreadLocalSpan.java:164)
		at brave.mongodb.TraceMongoCommandListener.commandSucceeded(TraceMongoCommandListener.java:103)
		at com.mongodb.internal.connection.ProtocolHelper.sendCommandSucceededEvent(ProtocolHelper.java:289)
		at com.mongodb.internal.connection.LoggingCommandEventSender.sendSucceededEvent(LoggingCommandEventSender.java:142)

johanhaleby · 2020-12-09T07:49:06Z

We're also experiencing this problem, it is preventing us from upgrading to spring boot 2.4.0.

We're using:

JDK 14
Kotlin 1.4.21
Spring Boot 2.4.0
Spring Cloud 2020.0.0-M6
Gcp dependencies: 1.2.6.RELEASE
spring-cloud-starter-sleuth from Spring Cloud 2020.0.0-M6
spring-cloud-gcp-starter-trace from Spring Cloud 2020.0.0-M6
spring-boot-starter-data-mongodb-reactive

Caused by: java.lang.AssertionError: Misalignment: scoped span NoopSpan(25a281266543b1d3/cb424d6e4c2b7966) !=  current span null
	at brave.propagation.ThreadLocalSpan.remove(ThreadLocalSpan.java:164)
	Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Assembly trace from producer [reactor.core.publisher.MonoLift] :
	reactor.core.publisher.Mono.from(Mono.java:488)
	org.springframework.data.mongodb.core.ReactiveMongoTemplate.lambda$executeFindOneInternal$89(ReactiveMongoTemplate.java:2762)

Stack trace:

Stack trace:
		at brave.propagation.ThreadLocalSpan.remove(ThreadLocalSpan.java:164)
		at brave.mongodb.TraceMongoCommandListener.commandSucceeded(TraceMongoCommandListener.java:103)
		at com.mongodb.internal.connection.ProtocolHelper.sendCommandSucceededEvent(ProtocolHelper.java:289)
		at com.mongodb.internal.connection.LoggingCommandEventSender.sendSucceededEvent(LoggingCommandEventSender.java:142)
		at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:460)
		at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:440)
		at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback$MessageCallback.onResult(InternalStreamConnection.java:745)
		at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback$MessageCallback.onResult(InternalStreamConnection.java:712)
		at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:582)
		at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:579)
		at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:255)
		at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:214)
		at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:579)
		at com.mongodb.internal.connection.InternalStreamConnection.access$1100(InternalStreamConnection.java:78)
		at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:702)
		at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:687)
		at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:582)
		at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:579)
		at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:255)
		at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:214)
		at com.mongodb.connection.netty.NettyStream.handleReadResponse(NettyStream.java:285)
		at com.mongodb.connection.netty.NettyStream.access$800(NettyStream.java:69)
		at com.mongodb.connection.netty.NettyStream$InboundBufferHandler.channelRead0(NettyStream.java:344)
		at com.mongodb.connection.netty.NettyStream$InboundBufferHandler.channelRead0(NettyStream.java:341)
		at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
		at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
		at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
		at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
		at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
		at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
		at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
		at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
		at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
		at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
		at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
		at java.base/java.lang.Thread.run(Thread.java:832)

johanhaleby · 2020-12-09T13:29:35Z

Switching to spring-cloud-sleuth-otel solves the problem.

marcingrzejszczak · 2020-12-09T13:30:54Z

Of course it does cause it doesn't instrument mongo. You can remain with spring-cloud-starter-sleuth and just set spring.sleuth.mongodb.enabled=false and you'll disable it.

johanhaleby · 2020-12-09T13:56:41Z

@marcingrzejszczak Hehe ok, I didn't know that. But if so it makes sense :) Thanks for the pointer to the configuration property that allows us to disable it for mongodb.

jonatan-ivanov · 2020-12-10T02:17:22Z

@magnus-larsson Thank you for the description, the sample project, and the tests.
Could you please check what happens on your side if you use the latest spring-boot plugin (2.4.0) and spring-cloud (2020.0.0-M6)?

To me your test consistently passes after this change, I opened a PR in your repo so that you can see what changes I did on your project: magnus-larsson/ml-service-sleuth-issue#1

@vvalencia-cl @johanhaleby Could you please check what happens if you update to the latest versions (above)?

johanhaleby · 2020-12-10T06:04:28Z

@jonatan-ivanov Thanks for looking into this. But I have already tried with 2020.0.0-M6 and I get the same error (in my actual project). I'm using Maven though, with spring-boot-starter-parent version 2.4.0. Could that make a difference?

jonatan-ivanov · 2020-12-10T06:49:01Z

@johanhaleby I don't think the build system would make any difference (though I have seen "impossible" things happening before). But your project is definitely different, it could be another dependency issue (I'm suspicious). Could you please create a sample project that reproduces the issue that I can try debug and fix? What I have now is the sample project in the description which seems to be ok after upgrading the dependencies.

johanhaleby · 2020-12-10T06:50:20Z

It seems to work when I run ./gradlew test

marcingrzejszczak · 2020-12-10T08:28:09Z

If you check our documentation page - https://docs.spring.io/spring-cloud/docs/2020.0.0-M6/reference/html/ - you can see with which version of boot it was built (2.4.0).

BTW @johanhaleby since I have you here in Sleuth, can you check this issue in Rest Assured rest-assured/rest-assured#1341 ? :D

marcingrzejszczak · 2020-12-10T08:29:56Z

I closed it cause I understand that the problem can't be reproduced? If there's anyone that thinks that's not the case please comment.

johanhaleby · 2020-12-10T09:18:14Z

@marcingrzejszczak Oh sure! It's good that you ping me. I'm overwhelmed by emails and notifications from the rest assured project and it's easy for me to miss things. I'll try to cherry-pick it tomorrow and hopefully also make a new release.

In the future, feel free to email me directly if it's something important that's affecting the spring ecosystem that I need to fix (or if you just deem it important for other reasons) :) That goes for awaitility as well :).

marcingrzejszczak · 2020-12-10T09:22:56Z

@marcingrzejszczak Oh sure! It's good that you ping me. I'm overwhelmed by emails and notifications from the rest assured project and it's easy for me to miss things. I'll try to cherry-pick it tomorrow and hopefully also make a new release.

cc @snicoll , @wilkinsona - which version of RestAssured would it be best for Spring to have the fix. Just a reminder - we're talking about this issue in Spring (spring-projects/spring-framework#22788) that resulted in this fix for Rest Assured 4.3 (rest-assured/rest-assured#1341). Currently Spring uses 3.x so maybe a cherry pick to Rest Assured 3.x and 4.2 would be good? WDYT?

johanhaleby · 2020-12-10T09:25:19Z

I'm not maintaining 3.x anymore though :( Too much work for me, unfortunately.

marcingrzejszczak · 2020-12-10T09:29:31Z

Would 4.2 be possible? Cause @wilkinsona said Boot could bump to 4.2. There's an issue with bumping to 4.3 due to Groovy AFAIR

johanhaleby · 2020-12-10T15:05:28Z

Hmm, I don't think it would be much different to support 4.2 or 3.x. It would probably mean that the same amount of extra work for me. But I'll see what I can do. I've never done something like this in the ~10-year history of rest assured :)

spring-projects-issues added the waiting-for-triage label Nov 1, 2020

marcingrzejszczak added bug and removed waiting-for-triage labels Nov 1, 2020

jonatan-ivanov self-assigned this Dec 10, 2020

jonatan-ivanov mentioned this issue Dec 10, 2020

Update build.gradle magnus-larsson/ml-service-sleuth-issue#1

Merged

marcingrzejszczak added feedback-provided and removed bug labels Dec 10, 2020

marcingrzejszczak closed this as completed Dec 10, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Misaligned spans exception when used with spring-data-mongodb-reactive and spring-cloud-stream #1770

Misaligned spans exception when used with spring-data-mongodb-reactive and spring-cloud-stream #1770

magnus-larsson commented Nov 1, 2020 •

edited

Loading

vvalencia-cl commented Nov 25, 2020

Uh oh!

johanhaleby commented Dec 9, 2020

Uh oh!

johanhaleby commented Dec 9, 2020

Uh oh!

marcingrzejszczak commented Dec 9, 2020

Uh oh!

johanhaleby commented Dec 9, 2020 •

edited

Loading

Uh oh!

jonatan-ivanov commented Dec 10, 2020 •

edited

Loading

Uh oh!

johanhaleby commented Dec 10, 2020

Uh oh!

jonatan-ivanov commented Dec 10, 2020

Uh oh!

johanhaleby commented Dec 10, 2020

Uh oh!

marcingrzejszczak commented Dec 10, 2020

Uh oh!

marcingrzejszczak commented Dec 10, 2020

Uh oh!

johanhaleby commented Dec 10, 2020 •

edited

Loading

Uh oh!

marcingrzejszczak commented Dec 10, 2020

Uh oh!

johanhaleby commented Dec 10, 2020

Uh oh!

marcingrzejszczak commented Dec 10, 2020

Uh oh!

johanhaleby commented Dec 10, 2020

Uh oh!

Misaligned spans exception when used with spring-data-mongodb-reactive and spring-cloud-stream #1770

Misaligned spans exception when used with spring-data-mongodb-reactive and spring-cloud-stream #1770

Comments

magnus-larsson commented Nov 1, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Versions used

Description of the error

Instructions to reproduce the error

vvalencia-cl commented Nov 25, 2020

Uh oh!

johanhaleby commented Dec 9, 2020

Uh oh!

johanhaleby commented Dec 9, 2020

Uh oh!

marcingrzejszczak commented Dec 9, 2020

Uh oh!

johanhaleby commented Dec 9, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jonatan-ivanov commented Dec 10, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

johanhaleby commented Dec 10, 2020

Uh oh!

jonatan-ivanov commented Dec 10, 2020

Uh oh!

johanhaleby commented Dec 10, 2020

Uh oh!

marcingrzejszczak commented Dec 10, 2020

Uh oh!

marcingrzejszczak commented Dec 10, 2020

Uh oh!

johanhaleby commented Dec 10, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

marcingrzejszczak commented Dec 10, 2020

Uh oh!

johanhaleby commented Dec 10, 2020

Uh oh!

marcingrzejszczak commented Dec 10, 2020

Uh oh!

johanhaleby commented Dec 10, 2020

Uh oh!

magnus-larsson commented Nov 1, 2020 •

edited

Loading

johanhaleby commented Dec 9, 2020 •

edited

Loading

jonatan-ivanov commented Dec 10, 2020 •

edited

Loading

johanhaleby commented Dec 10, 2020 •

edited

Loading