Cannot capture spans when the method arguments include Kotlin value classes

[sato9818]

Describe the bug

I am trying to capture spans for specific methods using the Java agent feature described here. However, I am encountering issues when the method arguments include Kotlin value classes, as the spans are not captured properly.

Steps to reproduce

@JvmInline
value class UserId(val id: Int)

package com.example.trace.grpc.usecase

import com.example.trace.grpc.domain.model.User
import com.example.trace.grpc.domain.model.UserId
import com.example.trace.grpc.repository.UserRepository
import org.springframework.stereotype.Component

@Component
class GetUserUseCase(
    private val userRepository: UserRepository
) {
    suspend fun getUser(userId: Int): User {
        return userRepository.getUser(userId)
    }

    suspend fun getUserWithValueClass(userId: UserId): User {
        return userRepository.getUser(userId.id)
    }
}

otel.instrumentation.methods.include=com.example.trace.grpc.usecase.GetUserUseCase[getUser,getUserWithValueClass]

We can capture a span for the getUser method but not for the getUserWithValueClass method.

Expected behavior

We expect to capture spans even when the method arguments include Kotlin value classes."

Actual behavior

We can't capture the spans when the method arguments include Kotlin value classes.

Javaagent or library instrumentation version

javaagent: v2.11.0

Environment

JDK: Temurin 21.0.5+11
Kotlin: 2.1.0

Additional context

No response

[laurit]

@sato9818 could you provide a minimal sample app that reproduces the issue

[breedx-splk]

Yeah this is lacking some details. "We can't capture spans" is too vague.

1. How are you trying to capture spans? Using the @WithSpan annotation? Custom instrumentation? Something else?
2. When it doesn't work, what's the result? Just nothing captured or an exception or ? Any hints in the logs?

[sato9818]

I was trying to capture spans using otel.instrumentation.methods.include option, as described here.

Here is the minimal sample app: https://github.com/sato9818/trace-example.
To reproduce the issue, run BootRun using the command:

./gradlew app:grpc-spring-server:bootRun

Then send a request with:

grpcurl -d '{"user_id":"0101"}' -plaintext localhost:9090 com.example.trace.v1.UserService.GetUser

The following logs are produced by the OpenTelemetry agent:

[otel.javaagent 2025-01-20 09:33:27:264 +0900] [DefaultDispatcher-worker-1] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'UserRepository.getUser' : 4a55ce73c9779f7c11f5514e87185dbb f6e7924771d76b12 INTERNAL [tracer: io.opentelemetry.methods:2.11.0-alpha] AttributesMap{data={code.function=getUser, thread.id=54, code.namespace=com.example.trace.grpc.repository.UserRepository, thread.name=DefaultDispatcher-worker-1}, capacity=128, totalAddedValues=4}
[otel.javaagent 2025-01-20 09:33:27:265 +0900] [DefaultDispatcher-worker-1] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'GetUserUseCase.getUser' : 4a55ce73c9779f7c11f5514e87185dbb 5db0a4de95693d0a INTERNAL [tracer: io.opentelemetry.methods:2.11.0-alpha] AttributesMap{data={code.function=getUser, thread.id=54, code.namespace=com.example.trace.grpc.usecase.GetUserUseCase, thread.name=DefaultDispatcher-worker-1}, capacity=128, totalAddedValues=4}
[otel.javaagent 2025-01-20 09:33:27:267 +0900] [DefaultDispatcher-worker-1] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'UserRepository.getUser' : 4a55ce73c9779f7c11f5514e87185dbb 35c5b1b840876aee INTERNAL [tracer: io.opentelemetry.methods:2.11.0-alpha] AttributesMap{data={code.function=getUser, thread.id=54, code.namespace=com.example.trace.grpc.repository.UserRepository, thread.name=DefaultDispatcher-worker-1}, capacity=128, totalAddedValues=4}
[otel.javaagent 2025-01-20 09:33:27:267 +0900] [DefaultDispatcher-worker-1] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'UserService.getUser' : 4a55ce73c9779f7c11f5514e87185dbb 4c20b7b510853ff4 INTERNAL [tracer: io.opentelemetry.methods:2.11.0-alpha] AttributesMap{data={code.function=getUser, thread.id=54, code.namespace=com.example.trace.grpc.service.UserService, thread.name=DefaultDispatcher-worker-1}, capacity=128, totalAddedValues=4}
[otel.javaagent 2025-01-20 09:33:27:272 +0900] [grpc-default-executor-0] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'com.example.trace.v1.UserService/GetUser' : 4a55ce73c9779f7c11f5514e87185dbb 6526477107bab4c5 SERVER [tracer: io.opentelemetry.grpc-1.6:2.11.0-alpha] AttributesMap{data={rpc.service=com.example.trace.v1.UserService, thread.id=53, rpc.method=GetUser, server.address=localhost, server.port=9090, network.peer.port=54120, rpc.grpc.status_code=0, network.peer.address=127.0.0.1, rpc.system=grpc, thread.name=grpc-default-executor-0, network.type=ipv4}, capacity=128, totalAddedValues=11}
[otel.javaagent 2025-01-20 09:33:27:272 +0900] [grpc-default-executor-0] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo' : 760b4c190df0175721a941ca6d5dfe51 95f73526942fd026 SERVER [tracer: io.opentelemetry.grpc-1.6:2.11.0-alpha] AttributesMap{data={rpc.service=grpc.reflection.v1alpha.ServerReflection, thread.id=53, rpc.method=ServerReflectionInfo, server.address=localhost, server.port=9090, network.peer.port=54120, rpc.grpc.status_code=0, network.peer.address=127.0.0.1, rpc.system=grpc, thread.name=grpc-default-executor-0, network.type=ipv4}, capacity=128, totalAddedValues=11}

Despite calling GetUserUseCase.getUserWithValueClass during the request, the associated span is not captured in the logs.

[laurit]

otel.instrumentation.methods.include matches based on class and method name as they appear in class bytecode. If you add Exception().printStackTrace() to https://github.com/sato9818/trace-example/blob/421d4d557327d278fb9762421ab60cc767de434f/app/grpc-spring-server/src/main/kotlin/com/example/trace/grpc/usecase/GetUserUseCase.kt#L17 you'll see

java.lang.Exception
        at com.example.trace.grpc.usecase.GetUserUseCase.getUserWithValueClass-Nvd1TFQ$suspendImpl(GetUserUseCase.kt:17)
        at com.example.trace.grpc.usecase.GetUserUseCase.getUserWithValueClass-Nvd1TFQ(GetUserUseCase.kt)
        at com.example.trace.grpc.service.UserService.getUser$suspendImpl(UserService.kt:22)
        at com.example.trace.grpc.service.UserService.getUser(UserService.kt)

With java the mapping from source to bytecode is usually straightforward, with other jvm languages there may be surprises. See https://kotlinlang.org/docs/inline-classes.html#mangling and https://kotlinlang.org/docs/inline-classes.html#calling-from-java-code
Also note that since you wish to capture spans for suspend methods you'll have to consider how these methods are compiled and executed. A call to suspend method exits at the suspension point and is called again to resume the method. Since the instrumentation creates a span for each method call you will end up with more spans than what you'd expect by just looking at the kotlin code. For @WithSpan we attempted to provide a better handing that would create a single span for the method instead of creating a new span each time the method resumes. Unfortunately there is an open issue that demonstrates that it does not work correctly. Currently your best bet for tracing these methods is doing the instrumentation in code.

[sato9818]

Thank you very much for your detailed investigation!
Is this #12837 the issue you mentioned for @WithSpan?

[laurit]

Thank you very much for your detailed investigation! Is this #12837 the issue you mentioned for @WithSpan?

yes

[sato9818]

I'll keep track on the issue!