Duration of request is wrong if method returns Mono (spring webflux controller)

[lmolkova]

Describe the bug
When Spring WebFlux controller returns Mono, the span for request ends immediately, but deferred/delayed mono still runs.

Steps to reproduce
Create a simple weblux app, here's controller code, full example:
mono-duration-bug.zip

@RestController
@RequestMapping("/hello")
public class HelloController {

    @GetMapping("/messages")
    public Mono<ResponseEntity<String>> get() {
        return Mono.delay(Duration.ofMillis(100)).then(Mono.just(ResponseEntity.ok("Hello")));
    }
}

What did you expect to see?
duration of hello/messages is longer - span ends after deferred mono ends.

What did you see instead?

What version are you using?
opentelemetry-javaagent - version: 1.6.2

Environment
Compiler: AdoptOpenJDK 16.0.1
OS: win10

[trask]

on the downside, this looks like a regression introduced in 1.6.0

on the (small) upside, it only seems to be a problem when pulling in both spring-boot-starter-webflux and spring-boot-starter-web

EDIT: the duplicate HelloController.get seems to exist even before 1.6.0 (and is also only triggered when pulling in both starters)

EDIT: the regression appears to be from #4078

EDIT: the regression appears to be coming from the tomcat instrumentation (or at least disabling the tomcat instrumentation makes the regression issue go away)

[iNikem]

Just to confirm, @lmolkova : do you want for Mono span to be a child of /hello/messages and a sibling of HelloControll.get controller span?

[lmolkova]

@iNikem

Just to confirm, @lmolkova : do you want for Mono span to be a child of /hello/messages and a sibling of HelloControll.get controller span?

I expect controller span to be a child of Server of /hello/messages. I don't have a mono span. ​And I just realized that I have two controller spans on my screenshot, but as you can see, I don't have anything beyond auto-instrumentation.

In a more complicated example, where I noticed the issue, I have correct nesting, wrong duration and still 2 controller spans

[trask]

I split out the duplicate controller span issue into #4360 so that I could mark PR #4339 as resolving this issue