DEV Community

Cover image for Structured Concurrency in Practice: CoroutineScope vs StructuredTaskScope [Part 3]
Filip Egeric
Filip Egeric

Posted on

Structured Concurrency in Practice: CoroutineScope vs StructuredTaskScope [Part 3]

#springboot #kotlin #java #logging

This post series assumes familiarity with Kotlin, Java, and Spring Boot.

No AI was used during the writing of this post series.

What happened to our logs?

In Part 2 we completed the entire solution, both the happy path and the sad paths. Here's what we ended up with:

@RestController
@RequestMapping("/books")
class BooksController(
    private val booksRepository: BooksRepository,
    private val reviewsService: ReviewsService,
) {
    private val log = LoggerFactory.getLogger(BooksController::class.java)

    @GetMapping("/{id}")
    fun fetchBook(@PathVariable id: Long): Book = runBlocking(Dispatchers.IO) {
        log.info("[START] $id")

        val book = async { findBook(id) }
        val reviews = async { fetchReviewsFor(id) }

        book.await()
            .copy(reviews = reviews.await())
            .also { log.info("[SUCCESS] Returning ${it.id}") }
    }

    private suspend fun findBook(id: Long) = runInterruptible {
        booksRepository.findById(id) ?: throw BookNotFoundException(id)
    }

    private suspend fun fetchReviewsFor(id: Long) = runInterruptible {
        reviewsService.fetchReviewsFor(id)
    }
}
Enter fullscreen mode Exit fullscreen mode

And calling the endpoint (happy path) would produce the following logs:

10:50:07.596 [DefaultDispatcher-worker-1] [] INFO  c.b.b.BooksController - [START] 3
10:50:07.599 [DefaultDispatcher-worker-2] [] INFO  c.b.r.ReviewsService - [START] Fetching reviews for book with id 3
10:50:07.599 [DefaultDispatcher-worker-3] [] INFO  c.b.b.BooksRepository - [START] Fetching book with id 3
10:50:08.604 [DefaultDispatcher-worker-2] [] INFO  c.b.r.ReviewsService - [DONE] Fetched reviews for book with id 3
10:50:08.632 [DefaultDispatcher-worker-3] [] INFO  c.b.b.BooksRepository - [DONE] Fetched book with id 3
10:50:08.633 [DefaultDispatcher-worker-3] [] INFO  c.b.b.BooksController - [SUCCESS] Returning 3
Enter fullscreen mode Exit fullscreen mode

And the logs before we introduced structured concurrency:

10:51:22.063 [tomcat-handler-0] [requestId=djm] INFO  c.b.b.BooksController - [START] 3
10:51:22.064 [tomcat-handler-0] [requestId=djm] INFO  c.b.b.BooksRepository - [START] Fetching book with id 3
10:51:23.086 [tomcat-handler-0] [requestId=djm] INFO  c.b.b.BooksRepository - [DONE] Fetched book with id 3
10:51:23.086 [tomcat-handler-0] [requestId=djm] INFO  c.b.r.ReviewsService - [START] Fetching reviews for book with id 3
10:51:24.093 [tomcat-handler-0] [requestId=djm] INFO  c.b.r.ReviewsService - [DONE] Fetched reviews for book with id 3
10:51:24.094 [tomcat-handler-0] [requestId=djm] INFO  c.b.b.BooksController - [SUCCESS] Returning 3
Enter fullscreen mode Exit fullscreen mode

A few things that were excluded in the previous parts of the series are the thread id ([tomcat-handler-0] or [DefaultDispatcher-worker-1]) and the [requestId=djm].

Comparing the logs from before and after introducing structured concurrency, we can notice that [requestId=djm] disappeared.

To understand why this happened, we need to take a look into the implementation.

Servlet Filter and MDC

A feature of our app that we didn't show so far is that it adds a unique request id to each request. This is achieved by implementing jakarta.servlet.Filter:

private const val REQUEST_ID_KEY = "requestId"

@Component
class RequestIdFilter : Filter {

    override fun doFilter(
        request: ServletRequest,
        response: ServletResponse,
        filterChain: FilterChain,
    ) {
        val requestId = generateRequestId()
        MDC.put(REQUEST_ID_KEY, requestId)
        filterChain.doFilter(request, response)
    }
}
Enter fullscreen mode Exit fullscreen mode

We are using Logback for logging and MDC is a way to have some additional context with each log statement. The implementation of MDC is using ThreadLocal under the hood, we'll see a bit later why this is important.

Thanks to this RequestIdFilter, we get this requestId in our logs:

10:51:22.063 [tomcat-handler-0] [requestId=djm] INFO  c.b.b.BooksController - [START] 3
Enter fullscreen mode Exit fullscreen mode

It won't show up there automatically however, we have to configure it in logback.xml (%X):

<pattern>%d{HH:mm:ss.SSS} [%thread] [%X] %-5level %logger{12} - %msg%n</pattern>
Enter fullscreen mode Exit fullscreen mode

But where did it disappear?

After introducing structured concurrency with coroutines, our logs look like this:

10:50:07.596 [DefaultDispatcher-worker-1] [] INFO  c.b.b.BooksController - [START] 3
Enter fullscreen mode Exit fullscreen mode

The [requestId=djm] part is gone.

As mentioned above, the implementation of MDC is using ThreadLocal as a storage, but when using coroutines, thread switching can happen whenever a suspension point is reached. Once the thread is switched, the MDC is empty.

There's an easy way to fix this, but it's important to understand why it's happening in the first place.

Because it's a common problem and a lot of people use MDC, there is an official library that can help us:

implementation("org.jetbrains.kotlinx:kotlinx-coroutines-slf4j:$coroutinesVersion")
Enter fullscreen mode Exit fullscreen mode

In order to utilize it, all we have to do is add it to runBlocking:

import kotlinx.coroutines.slf4j.MDCContext
...
@GetMapping("/{id}")
fun fetchBook(@PathVariable id: Long): Book = runBlocking(Dispatchers.IO + MDCContext()) { ...
Enter fullscreen mode Exit fullscreen mode

After adding this, here's how our logs look like:

11:08:32.406 [DefaultDispatcher-worker-1] [requestId=wor] INFO  c.b.b.BooksController - [START] 3
11:08:32.409 [DefaultDispatcher-worker-2] [requestId=wor] INFO  c.b.r.ReviewsService - [START] Fetching reviews for book with id 3
11:08:32.409 [DefaultDispatcher-worker-3] [requestId=wor] INFO  c.b.b.BooksRepository - [START] Fetching book with id 3
11:08:33.416 [DefaultDispatcher-worker-2] [requestId=wor] INFO  c.b.r.ReviewsService - [DONE] Fetched reviews for book with id 3
11:08:33.445 [DefaultDispatcher-worker-3] [requestId=wor] INFO  c.b.b.BooksRepository - [DONE] Fetched book with id 3
11:08:33.446 [DefaultDispatcher-worker-3] [requestId=wor] INFO  c.b.b.BooksController - [SUCCESS] Returning 3
Enter fullscreen mode Exit fullscreen mode

This seems like a lot. Is there a better way?

Java is (slowly) introducing a new API for structured concurrency: StructuredTaskScope that looks promising and can also help us solve the problem we've so far solved with kotlin coroutines.

Read about it in the next part.

Top comments (0)