Java autoinstrumentation agent and MongoDB double traces

[dzydzany]

Discussed in #6384

^{Originally posted by dzydzany July 29, 2022}
Hello,

I am seeing double traces of MongoDB calls with different span ids and different execution times at one of our services. I am attaching the screenshot here. I am using version 1.16.0, and also I've tested with 1.15.0 These are configuration switches:
"-Dotel.exporter.otlp.endpoint=http://otel-collector:4317",
"-Dotel.service.name=backend",
"-javaagent:opentelemetry-javaagent.jar"

You can also notice for the other callbacks that all are double, just not expanded in the screenshot.

These are the versions of Spring and MongoDB connector:

springBootVersion = '2.5.14'

These are the code samples of connector

package com.clockify.adapter.mongodb.connectors;

import com.mongodb.ConnectionString;
import com.mongodb.client.MongoClients;
import org.apache.commons.lang3.StringUtils;import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.stereotype.Service;

import javax.annotation.PostConstruct;
import javax.annotation.PreDestroy;

@Service
public class ClockifyConnectorMongoDB extends ConnectorMongoDB {

    @Value("${database.mongoDb.clockify.url}")
    private String url;

    @Value("${database.mongoDb.clockifySpare.url}")
    private String spareUrl;

    private final static Logger LOG = LoggerFactory.getLogger(ClockifyConnectorMongoDB.class);

    @PostConstruct
    private void init() {
        LOG.info("Creating new Mongo Client.");
        this.mongoClient = MongoClients.create(new ConnectionString(url));

        if (!StringUtils.isEmpty(spareUrl)) {
            this.spareDatabaseClient = MongoClients.create(new ConnectionString(spareUrl));
        } else {
            this.spareDatabaseClient = MongoClients.create(new ConnectionString(url));
        }

        this.databaseName  = new ConnectionString(url).getDatabase();
    }


    @PreDestroy
    private void cleanup() {
        mongoClient.close();
    }
}

package com.clockify.adapter.mongodb.connectors;

import com.mongodb.ReadPreference;
import com.mongodb.client.ClientSession;
import com.mongodb.client.MongoClient;
import com.mongodb.client.MongoCollection;
import com.mongodb.client.MongoDatabase;
import com.mongodb.client.gridfs.GridFSBucket;
import com.mongodb.client.gridfs.GridFSBuckets;
import org.bson.Document;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public abstract class ConnectorMongoDB {
    private final static Logger LOG = LoggerFactory.getLogger(ConnectorMongoDB.class);

    protected MongoClient mongoClient;
    protected String databaseName;
    protected MongoClient spareDatabaseClient;

    public MongoDatabase getDatabase() {
        return mongoClient.getDatabase(getDatabaseName());
    }

    public MongoCollection<Document> getCollection(final String collection) {
        return getDatabase().getCollection(collection);
    }

    public ReadPreference getDefaultReadPreference() {
        return mongoClient.getDatabase(getDatabaseName()).getReadPreference();
    }

    public ReadPreference getSpareReadPreference() {
        return spareDatabaseClient.getDatabase(getDatabaseName()).getReadPreference();
    }

    public String getDatabaseName() {
        return databaseName;
    }

    public ClientSession openSession(){
        return mongoClient.startSession();
    }

    public GridFSBucket getGridFS(final String collection) {
        return GridFSBuckets.create(getDatabase(), collection);
    }
}

We are using MongoDB 4.4 in cluster mode.

Thank you.

[mateuszrzeszutek]

Hey @dzydzany ,
Can you post an example mongo call that generates the double spans? E.g. like a query or something.
Or, if it is feasible for you, a repro scenario -- this would be very valuable for us.

[dzydzany]

Ah sorry,

Using com/mongodb/client/MongoCollection.java
Executing query:

new Document("id-field", 123)

and applying filter find by id:

FindIterable<TDocument> find(Bson filter);

I am terribly sorry that I cannot provide you with a complete example of the code, but this should be a simple enough query for testing. But, practically any MongoDB query produces double spans.

Thank you!

[trask]

I am terribly sorry that I cannot provide you with a complete example of the code, but this should be a simple enough query for testing. But, practically any MongoDB query produces double spans.

there are lots of mongodb instrumentation tests, and they don't exhibit this issue, so there may be something subtle in the way you are using mongodb that the tests do not account for, which is why repros are really helpful

[laurit]

This happens because your application includes both the older mongo-java-driver and newer mongodb-driver-core. These drivers contain the same classes, they can not be used at the same time. Choose which you want to use and remove the other.
It is a weakness in the agent, the way we detect which library version is present and choose how to instrument it isn't able to cope when there are multiple versions of the same library present. We have separate instrumentations for mongo 3.8+ and mongo 4.0+ ideally we should apply only one of them but here the agent gets confused and applies both which causes double tracing. At least that is my guess.

[dzydzany]

@laurit Thank you. We are inspecting to see if this is the case. And will let you know as soon as we test it out.

[sankala-dremio]

We are noticing similar issue and depending on the result set, the Spans seem to explode. We are using org.mongodb:mongodb-driver-legacy:jar:4.3.4:compile

[dzydzany]

I just want to confirm that the issue looks resolved. I have tested with opentelemetry-javaagent-1.17.0-20220813.012152-45.jar
Thank you very much!