Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Handled / catched exceptions are getting into Azure Application Insights #3838

Open
chhauss-a opened this issue Aug 14, 2024 · 12 comments
Open
Assignees

Comments

@chhauss-a
Copy link

Expected behavior

We have a handled exception in our application. When that exception is thrown and catched we should not see the occurrence of that exception in Application Insights.

Actual behavior

The thrown and catched exception is displayed in our Application Insights.

To Reproduce

  1. Create a new Spring Boot application with a scheduled task and use ShedLock to synchronize that task over multiple containers running in parallel with mongoDB setup (cosmos db)
// Run every 15 minutes (xx:00, xx:15, xx:30, xx:45)
@Scheduled(cron = "0 */15 * * * *")
@SchedulerLock(name = "uniqueString", lockAtMostFor = "14m", lockAtLeastFor = "14m")
public void myScheduledTask() {
    service.runTask();
}
  1. Setup the MongoLockProvider for ShedLock
@Bean
public LockProvider lockProvider(final MongoClient mongo) {
    return new MongoLockProvider(mongo.getDatabase(mongoDatabaseName));
}
  1. Setup Application Insights for the Spring Boot application
  2. Run the application with 2 containers in parallel (in our case in a container app)
  3. Observe the Application Insights Exceptions: Every time the task is scheduled ShedLock will try to lock the task in both containers. That means every time one of the containers will receive an duplicate key exception that is catched within the MongoLockProvider. These exceptions are shown in Application Insights.

System information

Please provide the following information:

  • SDK Version: Java SDK 21-temurin
  • OS type and version: eclipse-temurin:21-jre-alpine docker image
  • Application Server type and version (if applicable): Azure Container App
  • Using spring-boot? Yes with Spring-Boot-Starter-Parent v3.3.2
  • Additional relevant libraries (with version, if applicable): ShedLock v5.14.0 => net.javacrumbs.shedlock -> shedlock-spring & shedlock-provider-mongo
@heyams
Copy link
Contributor

heyams commented Aug 15, 2024

@chhauss-a can you share the stack trace where the exception is being thrown and where it's caught?

@chhauss-a
Copy link
Author

Hey @heyams , thanks for looking into this issue!

The exception that is thrown is the following:

com.mongodb.MongoCommandException: Command failed with error 11000 (DuplicateKey): 'E11000 duplicate key error collection: <our-collection>.shedLock. Failed _id or unique index constraint.' on server <our-server>. The full response is {"ok": 0.0, "errmsg": "E11000 duplicate key error collection: <our-collection>.shedLock. Failed _id or unique index constraint.", "code": 11000, "codeName": "DuplicateKey"}
	at com.mongodb.internal.connection.ProtocolHelper.getCommandFailureException(ProtocolHelper.java:205)
	at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:454)
	at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:372)
	at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:114)
	at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:765)
	at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:76)
	at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:209)
	at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:115)
	at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:83)
	at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:74)
	at com.mongodb.internal.connection.DefaultServer$OperationCountTrackingConnection.command(DefaultServer.java:299)
	at com.mongodb.internal.operation.SyncOperationHelper.lambda$executeRetryableWrite$9(SyncOperationHelper.java:243)
	at com.mongodb.internal.operation.SyncOperationHelper.lambda$withSourceAndConnection$0(SyncOperationHelper.java:127)
	at com.mongodb.internal.operation.SyncOperationHelper.withSuppliedResource(SyncOperationHelper.java:152)
	at com.mongodb.internal.operation.SyncOperationHelper.lambda$withSourceAndConnection$1(SyncOperationHelper.java:126)
	at com.mongodb.internal.operation.SyncOperationHelper.withSuppliedResource(SyncOperationHelper.java:152)
	at com.mongodb.internal.operation.SyncOperationHelper.withSourceAndConnection(SyncOperationHelper.java:125)
	at com.mongodb.internal.operation.SyncOperationHelper.lambda$executeRetryableWrite$10(SyncOperationHelper.java:229)
	at com.mongodb.internal.operation.SyncOperationHelper.lambda$decorateWriteWithRetries$11(SyncOperationHelper.java:283)
	at com.mongodb.internal.async.function.RetryingSyncSupplier.get(RetryingSyncSupplier.java:67)
	at com.mongodb.internal.operation.SyncOperationHelper.executeRetryableWrite(SyncOperationHelper.java:255)
	at com.mongodb.internal.operation.BaseFindAndModifyOperation.execute(BaseFindAndModifyOperation.java:79)
	at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:173)
	at com.mongodb.client.internal.MongoCollectionImpl.executeFindOneAndUpdate(MongoCollectionImpl.java:761)
	at com.mongodb.client.internal.MongoCollectionImpl.findOneAndUpdate(MongoCollectionImpl.java:741)
	at net.javacrumbs.shedlock.provider.mongo.MongoLockProvider.lock(MongoLockProvider.java:107)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Unknown Source)
	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:354)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:216)
	at jdk.proxy3/jdk.proxy3.$Proxy169.lock(Unknown Source)
	at net.javacrumbs.shedlock.core.DefaultLockingTaskExecutor.executeWithLock(DefaultLockingTaskExecutor.java:63)
	at net.javacrumbs.shedlock.spring.aop.MethodProxyScheduledLockAdvisor$LockingInterceptor.invoke(MethodProxyScheduledLockAdvisor.java:79)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:768)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:720)
	at <our-package-name>.<our-scheduling-class>$$SpringCGLIB$$0.<our-method-name>(<generated>)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Unknown Source)
	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
	at org.springframework.scheduling.support.ScheduledMethodRunnable.runInternal(ScheduledMethodRunnable.java:130)
	at org.springframework.scheduling.support.ScheduledMethodRunnable.lambda$run$2(ScheduledMethodRunnable.java:124)
	at io.micrometer.observation.Observation.observe(Observation.java:499)
	at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:124)
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
	at java.base/java.lang.VirtualThread.run(Unknown Source)

The MongoLockProvider that I have mentioned above is catching the MongoServerException which the MongoCommandExceptions extends.

@chhauss-a
Copy link
Author

Any updates on this issue so far?

@trask
Copy link
Member

trask commented Oct 22, 2024

hi @chhauss-a! sorry for the delay, and thanks for the stack trace, can you do one more thing for us and enable self-diagnostic debug logging (e.g. env var APPLICATIONINSIGHTS_SELF_DIAGNOSTICS_LEVEL=debug)?

this should show us which span that exception is being captured against which should help us narrow it down

@trask
Copy link
Member

trask commented Oct 22, 2024

(specifically, if you can share any relevant exporting span: ... and exporting log: ... lines from the self-diagnostic debug log)

@chhauss-a
Copy link
Author

chhauss-a commented Oct 24, 2024

Hey @trask,
thanks for looking into that issue.

I have activated the diagnostic logs and this is the output from this morning, when both revisions wanted to get the lock:

This is the revision that seems to have aquired the lock first:

2024-10-24T08:00:00.241596844Z 2024-10-24 08:00:00.241Z DEBUG c.m.a.a.i.exporter.AgentSpanExporter - exporting span: SpanData{spanContext=ImmutableSpanContext{traceId=a015e31780105a2e3eae1572dbd31638, spanId=d9fb5b02ff75f250, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, resource=Resource{schemaUrl=null, attributes={service.name="app-<our-service-name>", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.35.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=io.opentelemetry.mongo-3.1, version=2.1.0-alpha, schemaUrl=null, attributes={}}, name=findAndModify mongodb-<our-service-name>.shedLock, kind=CLIENT, startEpochNanos=1729756800002158191, endEpochNanos=1729756800150209848, attributes=AttributesMap{data={db.name=mongodb-<our-service-name>, thread.name=scheduling-95, db.operation=findAndModify, db.mongodb.collection=shedLock, db.system=mongodb, db.statement={"findAndModify": "shedLock", "query": {"$and": [{"_id": "?"}, {"lockUntil": {"$lte": "?"}}]}, "new": "?", "upsert": "?", "update": {"$set": {"lockUntil": "?", "lockedAt": "?", "lockedBy": "?"}}, "$db": "?", "lsid": {"id": "?"}}, server.port=10255, applicationinsights.internal.item_count=1, thread.id=18509, db.connection_string=mongodb://cosmos-<our-service-name>-westeurope.mongo.cosmos.azure.com:10255, server.address=cosmos-<our-service-name>-westeurope.mongo.cosmos.azure.com}, capacity=128, totalAddedValues=11}, totalAttributeCount=11, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=UNSET, description=}, hasEnded=true}
2024-10-24T08:00:00.241654191Z 2024-10-24 08:00:00.241Z DEBUG c.m.a.a.i.exporter.AgentLogExporter - exporting log: SdkLogRecordData{resource=Resource{schemaUrl=null, attributes={service.name="app-<our-service-name>", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.35.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=<our-scheduled-service>, version=null, schemaUrl=null, attributes={}}, timestampEpochNanos=1729756800150000000, observedTimestampEpochNanos=1729756800150527996, spanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, severity=DEBUG, severityText=DEBUG, body=AnyValueBody{Going to run scheduled service}, attributes={thread.id=18509, thread.name="scheduling-95"}, totalAttributeCount=2}
2024-10-24T08:00:00.241703193Z 2024-10-24 08:00:00.241Z DEBUG c.m.a.a.i.exporter.AgentSpanExporter - exporting span: SpanData{spanContext=ImmutableSpanContext{traceId=a0b46ea33596893ce5e810ab45e4dc72, spanId=49eebf7357862439, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, resource=Resource{schemaUrl=null, attributes={service.name="app-<our-service-name>", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.35.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=io.opentelemetry.mongo-3.1, version=2.1.0-alpha, schemaUrl=null, attributes={}}, name=find mongodb-<our-service-name>.<our-scheduled-service-class>, kind=CLIENT, startEpochNanos=1729756800153151780, endEpochNanos=1729756800189503628, attributes=AttributesMap{data={db.name=mongodb-<our-service-name>, thread.name=scheduling-95, db.operation=find, db.mongodb.collection=<our-scheduled-service-class>, db.system=mongodb, db.statement={"find": "<our-scheduled-service-class>", "filter": {"numberOfAttempts": {"$lte": "?"}}, "$db": "?", "lsid": {"id": "?"}}, server.port=10255, applicationinsights.internal.item_count=1, thread.id=18509, db.connection_string=mongodb://cosmos-<our-service-name>-westeurope.mongo.cosmos.azure.com:10255, server.address=cosmos-<our-service-name>-westeurope.mongo.cosmos.azure.com}, capacity=128, totalAddedValues=11}, totalAttributeCount=11, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=UNSET, description=}, hasEnded=true}
2024-10-24T08:00:00.241714905Z 2024-10-24 08:00:00.241Z DEBUG c.m.a.a.i.exporter.AgentSpanExporter - exporting span: SpanData{spanContext=ImmutableSpanContext{traceId=db75a6f913e4bbc2a6bfaafc229f7226, spanId=c88d48329b8735dd, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, resource=Resource{schemaUrl=null, attributes={service.name="app-<our-service-name>", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.35.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=io.opentelemetry.mongo-3.1, version=2.1.0-alpha, schemaUrl=null, attributes={}}, name=findAndModify mongodb-<our-service-name>.shedLock, kind=CLIENT, startEpochNanos=1729756800190077865, endEpochNanos=1729756800193707507, attributes=AttributesMap{data={db.name=mongodb-<our-service-name>, thread.name=scheduling-95, db.operation=findAndModify, db.mongodb.collection=shedLock, db.system=mongodb, db.statement={"findAndModify": "shedLock", "query": {"_id": "?"}, "new": "?", "update": {"$set": {"lockUntil": "?"}}, "$db": "?", "lsid": {"id": "?"}}, server.port=10255, applicationinsights.internal.item_count=1, thread.id=18509, db.connection_string=mongodb://cosmos-<our-service-name>-westeurope.mongo.cosmos.azure.com:10255, server.address=cosmos-<our-service-name>-westeurope.mongo.cosmos.azure.com}, capacity=128, totalAddedValues=11}, totalAttributeCount=11, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=UNSET, description=}, hasEnded=true}

And this is the revision, that came seconds and therefor could not aquire the lock:

2024-10-24T07:59:55.950873020Z 2024-10-24 07:59:55.950Z DEBUG c.m.a.a.i.exporter.AgentSpanExporter - exporting span: SpanData{spanContext=ImmutableSpanContext{traceId=7a26fdfad314a53ee9d6cf02803cf6b3, spanId=4a7d51b6b5017862, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, resource=Resource{schemaUrl=null, attributes={service.name="app-<our-service-name>", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.35.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=io.opentelemetry.tomcat-10.0, version=2.1.0-alpha, schemaUrl=null, attributes={}}, name=GET /api/status/health/**, kind=SERVER, startEpochNanos=1729756795867241839, endEpochNanos=1729756795868154499, attributes=AttributesMap{data={url.scheme=http, thread.name=tomcat-handler-18032, network.protocol.version=1.1, server.port=8080, applicationinsights.internal.item_count=1, thread.id=18480, applicationinsights.internal.is_pre_aggregated=true, user_agent.original=kube-probe/1.29, http.response.status_code=200, http.route=/api/status/health/**, network.peer.port=50054, http.request.method=GET, url.path=/api/status/health/readiness, network.peer.address=100.100.1.243, server.address=100.100.2.35, client.address=100.100.1.243}, capacity=128, totalAddedValues=16}, totalAttributeCount=16, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=UNSET, description=}, hasEnded=true}

2024-10-24T08:00:00.253849885Z 2024-10-24 08:00:00.253Z DEBUG c.m.a.a.i.exporter.AgentSpanExporter - exporting span: SpanData{spanContext=ImmutableSpanContext{traceId=aa7a70a178dbc2defb51afb4800685f5, spanId=d95ca82fc664484f, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, resource=Resource{schemaUrl=null, attributes={service.name="app-<our-service-name>", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.35.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=io.opentelemetry.mongo-3.1, version=2.1.0-alpha, schemaUrl=null, attributes={}}, name=findAndModify mongodb-<our-service-name>.shedLock, kind=CLIENT, startEpochNanos=1729756800001797030, endEpochNanos=1729756800179691397, attributes=AttributesMap{data={db.name=mongodb-<our-service-name>, thread.name=scheduling-95, db.operation=findAndModify, db.mongodb.collection=shedLock, db.system=mongodb, db.statement={"findAndModify": "shedLock", "query": {"$and": [{"_id": "?"}, {"lockUntil": {"$lte": "?"}}]}, "new": "?", "upsert": "?", "update": {"$set": {"lockUntil": "?", "lockedAt": "?", "lockedBy": "?"}}, "$db": "?", "lsid": {"id": "?"}}, server.port=10255, applicationinsights.internal.item_count=1, thread.id=18482, db.connection_string=mongodb://cosmos-<our-service-name>-westeurope.mongo.cosmos.azure.com:10255, server.address=cosmos-<our-service-name>-westeurope.mongo.cosmos.azure.com}, capacity=128, totalAddedValues=11}, totalAttributeCount=11, events=[ImmutableExceptionEventData{epochNanos=1729756800179673854, exception=com.mongodb.MongoCommandException: Command failed with error 11000 (DuplicateKey): 'E11000 duplicate key error collection: mongodb-<our-service-name>.shedLock. Failed _id or unique index constraint.' on server cosmos-<our-service-name>-westeurope.mongo.cosmos.azure.com:10255. The full response is {"ok": 0.0, "errmsg": "E11000 duplicate key error collection: mongodb-<our-service-name>.shedLock. Failed _id or unique index constraint.", "code": 11000, "codeName": "DuplicateKey"}, additionalAttributes={}, spanLimits=SpanLimitsValue{maxNumberOfAttributes=128, maxNumberOfEvents=128, maxNumberOfLinks=128, maxNumberOfAttributesPerEvent=128, maxNumberOfAttributesPerLink=128, maxAttributeValueLength=2147483647}}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=ERROR, description=}, hasEnded=true}

2024-10-24T08:00:00.344173417Z 2024-10-24 08:00:00.343Z DEBUG c.a.m.o.e.i.p.TelemetryItemExporter - sending telemetry to ingestion service:
2024-10-24T08:00:00.344224964Z {"ver":1,"name":"Metric","time":"2024-10-24T08:00:00.343Z","iKey":"e7991cba-ca8a-46c8-8ce5-c1c06fb0a317","tags":{"ai.internal.sdkVersion":"java:3.5.1","ai.cloud.roleInstance":"ca-<our-service-name>--dqu6lrv-6c74b59bf7-rcz89","ai.cloud.role":"app-<our-service-name>"},"data":{"baseType":"MetricData","baseData":{"ver":2,"metrics":[{"name":"_OTELRESOURCE_","value":0.0}],"properties":{"telemetry.sdk.language":"java","service.name":"app-<our-service-name>","service.instance.id":"ca-<our-service-name>--dqu6lrv-6c74b59bf7-rcz89","telemetry.sdk.version":"1.35.0","telemetry.sdk.name":"opentelemetry"}}}}
2024-10-24T08:00:00.344246163Z {"ver":1,"name":"Request","time":"2024-10-24T07:59:55.867Z","sampleRate":100.0,"iKey":"e7991cba-ca8a-46c8-8ce5-c1c06fb0a317","tags":{"ai.internal.sdkVersion":"java:3.5.1","ai.operation.id":"cc88993af2e47dd6662eb349c4bd90f9","ai.cloud.roleInstance":"ca-<our-service-name>--dqu6lrv-6c74b59bf7-rcz89","ai.operation.name":"GET /api/status/health/**","ai.location.ip":"100.100.1.243","ai.cloud.role":"app-<our-service-name>","ai.user.userAgent":"kube-probe/1.29"},"data":{"baseType":"RequestData","baseData":{"ver":2,"id":"079413be61fb3c41","name":"GET /api/status/health/**","duration":"00:00:00.000894","success":true,"responseCode":"200","url":"http://100.100.2.35:8080/api/status/health/liveness","properties":{"_MS.ProcessedByMetricExtractors":"True"}}}}
2024-10-24T08:00:00.344253637Z {"ver":1,"name":"Request","time":"2024-10-24T07:59:55.867Z","sampleRate":100.0,"iKey":"e7991cba-ca8a-46c8-8ce5-c1c06fb0a317","tags":{"ai.internal.sdkVersion":"java:3.5.1","ai.operation.id":"7a26fdfad314a53ee9d6cf02803cf6b3","ai.cloud.roleInstance":"ca-<our-service-name>--dqu6lrv-6c74b59bf7-rcz89","ai.operation.name":"GET /api/status/health/**","ai.location.ip":"100.100.1.243","ai.cloud.role":"app-<our-service-name>","ai.user.userAgent":"kube-probe/1.29"},"data":{"baseType":"RequestData","baseData":{"ver":2,"id":"4a7d51b6b5017862","name":"GET /api/status/health/**","duration":"00:00:00.000912","success":true,"responseCode":"200","url":"http://100.100.2.35:8080/api/status/health/readiness","properties":{"_MS.ProcessedByMetricExtractors":"True"}}}}
2024-10-24T08:00:00.344261692Z {"ver":1,"name":"RemoteDependency","time":"2024-10-24T08:00:00.001Z","sampleRate":100.0,"iKey":"e7991cba-ca8a-46c8-8ce5-c1c06fb0a317","tags":{"ai.internal.sdkVersion":"java:3.5.1","ai.operation.id":"aa7a70a178dbc2defb51afb4800685f5","ai.cloud.roleInstance":"ca-<our-service-name>--dqu6lrv-6c74b59bf7-rcz89","ai.cloud.role":"app-<our-service-name>"},"data":{"baseType":"RemoteDependencyData","baseData":{"ver":2,"id":"d95ca82fc664484f","name":"findAndModify mongodb-<our-service-name>.shedLock","data":"{\"findAndModify\": \"shedLock\", \"query\": {\"$and\": [{\"_id\": \"?\"}, {\"lockUntil\": {\"$lte\": \"?\"}}]}, \"new\": \"?\", \"upsert\": \"?\", \"update\": {\"$set\": {\"lockUntil\": \"?\", \"lockedAt\": \"?\", \"lockedBy\": \"?\"}}, \"$db\": \"?\", \"lsid\": {\"id\": \"?\"}}","type":"mongodb","target":"cosmos-<our-service-name>-westeurope.mongo.cosmos.azure.com:10255 | mongodb-<our-service-name>","duration":"00:00:00.177894","success":false}}}

2024-10-24T08:00:00.344284344Z {"ver":1,"name":"Exception","time":"2024-10-24T08:00:00.179Z","sampleRate":100.0,"iKey":"e7991cba-ca8a-46c8-8ce5-c1c06fb0a317","tags":{"ai.internal.sdkVersion":"java:3.5.1","ai.operation.id":"aa7a70a178dbc2defb51afb4800685f5","ai.cloud.roleInstance":"ca-<our-service-name>--dqu6lrv-6c74b59bf7-rcz89","ai.cloud.role":"app-<our-service-name>","ai.operation.parentId":"d95ca82fc664484f"},"data":{"baseType":"ExceptionData","baseData":{"ver":2,"exceptions":[{"typeName":"com.mongodb.MongoCommandException","message":"Command failed with error 11000 (DuplicateKey): 'E11000 duplicate key error collection: mongodb-<our-service-name>.shedLock. Failed _id or unique index constraint.' on server cosmos-<our-service-name>-westeurope.mongo.cosmos.azure.com:10255. The full response is {\"ok\": 0.0, \"errmsg\": \"E11000 duplicate key error collection: mongodb-<our-service-name>.shedLock. Failed _id or unique index constraint.\", \"code\": 11000, \"codeName\": \"DuplicateKey\"}","stack":"com.mongodb.MongoCommandException: Command failed with error 11000 (DuplicateKey): 'E11000 duplicate key error collection: mongodb-<our-service-name>.shedLock. Failed _id or unique index constraint.' on server cosmos-<our-service-name>-westeurope.mongo.cosmos.azure.com:10255. The full response is {\"ok\": 0.0, \"errmsg\": \"E11000 duplicate key error collection: mongodb-<our-service-name>.shedLock. Failed _id or unique index constraint.\", \"code\": 11000, \"codeName\": \"DuplicateKey\"}\n\tat com.mongodb.internal.connection.ProtocolHelper.getCommandFailureException(ProtocolHelper.java:205)\n\tat com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:431)\n\tat com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:354)\n\tat com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:114)\n\tat com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:743)\n\tat com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:76)\n\tat com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:209)\n\tat com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:115)\n\tat com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:83)\n\tat com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:74)\n\tat com.mongodb.internal.connection.DefaultServer$OperationCountTrackingConnection.command(DefaultServer.java:299)\n\tat com.mongodb.internal.operation.SyncOperationHelper.lambda$executeRetryableWrite$9(SyncOperationHelper.java:240)\n\tat com.mongodb.internal.operation.SyncOperationHelper.lambda$withSourceAndConnection$0(SyncOperationHelper.java:124)\n\tat com.mongodb.internal.operation.SyncOperationHelper.withSuppliedResource(SyncOperationHelper.java:149)\n\tat com.mongodb.internal.operation.SyncOperationHelper.lambda$withSourceAndConnection$1(SyncOperationHelper.java:123)\n\tat com.mongodb.internal.operation.SyncOperationHelper.withSuppliedResource(SyncOperationHelper.java:149)\n\tat com.mongodb.internal.operation.SyncOperationHelper.withSourceAndConnection(SyncOperationHelper.java:122)\n\tat com.mongodb.internal.operation.SyncOperationHelper.lambda$executeRetryableWrite$10(SyncOperationHelper.java:226)\n\tat com.mongodb.internal.operation.SyncOperationHelper.lambda$decorateWriteWithRetries$11(SyncOperationHelper.java:280)\n\tat com.mongodb.internal.async.function.RetryingSyncSupplier.get(RetryingSyncSupplier.java:67)\n\tat com.mongodb.internal.operation.SyncOperationHelper.executeRetryableWrite(SyncOperationHelper.java:252)\n\tat com.mongodb.internal.operation.BaseFindAndModifyOperation.execute(BaseFindAndModifyOperation.java:79)\n\tat com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:173)\n\tat com.mongodb.client.internal.MongoCollectionImpl.executeFindOneAndUpdate(MongoCollectionImpl.java:760)\n\tat com.mongodb.client.internal.MongoCollectionImpl.findOneAndUpdate(MongoCollectionImpl.java:740)\n\tat net.javacrumbs.shedlock.provider.mongo.MongoLockProvider.lock(MongoLockProvider.java:107)\n\tat java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Unknown Source)\n\tat java.base/java.lang.reflect.Method.invoke(Unknown Source)\n\tat org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:355)\n\tat org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:216)\n\tat jdk.proxy3/jdk.proxy3.$Proxy170.lock(Unknown Source)\n\tat net.javacrumbs.shedlock.core.DefaultLockingTaskExecutor.executeWithLock(DefaultLockingTaskExecutor.java:63)\n\tat net.javacrumbs.shedlock.spring.aop.MethodProxyScheduledLockAdvisor$LockingInterceptor.invoke(MethodProxyScheduledLockAdvisor.java:79)\n\tat org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)\n\tat org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:768)\n\tat org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:720)\n\tat <our-scheduler-class>$$SpringCGLIB$$0.<our-scheduler-method>(<generated>)\n\tat java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Unknown Source)\n\tat java.base/java.lang.reflect.Method.invoke(Unknown Source)\n\tat org.springframework.scheduling.support.ScheduledMethodRunnable.runInternal(ScheduledMethodRunnable.java:130)\n\tat org.springframework.scheduling.support.ScheduledMethodRunnable.lambda$run$2(ScheduledMethodRunnable.java:124)\n\tat io.micrometer.observation.Observation.observe(Observation.java:499)\n\tat org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:124)\n\tat org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)\n\tat java.base/java.lang.VirtualThread.run(Unknown Source)\n"}]}}}

2024-10-24T08:00:05.958302848Z 2024-10-24 08:00:05.958Z DEBUG c.m.a.a.i.exporter.AgentSpanExporter - exporting span: SpanData{spanContext=ImmutableSpanContext{traceId=652cddaacf92402690c2b53978ca4542, spanId=0559bd082dd3db38, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, resource=Resource{schemaUrl=null, attributes={service.name="app-<our-service-name>", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.35.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=io.opentelemetry.tomcat-10.0, version=2.1.0-alpha, schemaUrl=null, attributes={}}, name=GET /api/status/health/**, kind=SERVER, startEpochNanos=1729756805867104237, endEpochNanos=1729756805867972526, attributes=AttributesMap{data={url.scheme=http, thread.name=tomcat-handler-18035, network.protocol.version=1.1, server.port=8080, applicationinsights.internal.item_count=1, thread.id=18484, applicationinsights.internal.is_pre_aggregated=true, user_agent.original=kube-probe/1.29, http.response.status_code=200, http.route=/api/status/health/**, network.peer.port=48804, http.request.method=GET, url.path=/api/status/health/liveness, network.peer.address=100.100.1.243, server.address=100.100.2.35, client.address=100.100.1.243}, capacity=128, totalAddedValues=16}, totalAttributeCount=16, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=UNSET, description=}, hasEnded=true}
2024-10-24T08:00:05.958344496Z 2024-10-24 08:00:05.958Z DEBUG c.m.a.a.i.exporter.AgentSpanExporter - exporting span: SpanData{spanContext=ImmutableSpanContext{traceId=85f4bfdffaa5da047ea192168b9d1c01, spanId=87d8218d7477c873, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, resource=Resource{schemaUrl=null, attributes={service.name="app-<our-service-name>", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.35.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=io.opentelemetry.tomcat-10.0, version=2.1.0-alpha, schemaUrl=null, attributes={}}, name=GET /api/status/health/**, kind=SERVER, startEpochNanos=1729756805867104239, endEpochNanos=1729756805867972508, attributes=AttributesMap{data={url.scheme=http, thread.name=tomcat-handler-18034, network.protocol.version=1.1, server.port=8080, applicationinsights.internal.item_count=1, thread.id=18483, applicationinsights.internal.is_pre_aggregated=true, user_agent.original=kube-probe/1.29, http.response.status_code=200, http.route=/api/status/health/**, network.peer.port=48802, http.request.method=GET, url.path=/api/status/health/readiness, network.peer.address=100.100.1.243, server.address=100.100.2.35, client.address=100.100.1.243}, capacity=128, totalAddedValues=16}, totalAttributeCount=16, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=UNSET, description=}, hasEnded=true}

Looking forward to hear from you!

@trask
Copy link
Member

trask commented Oct 24, 2024

hi @chhauss-a, I'm surprised not to see any spans captured for the spring @Scheduled method (with InstrumentationScopeName io.opentelemetry.spring-scheduling-3.1)

the reason this is relevant is that if the failing mongo span had a parent span, then we wouldn't capture the exception, since we can rely on it either being handled, or captured on the parent span

have you by any chance turned off the spring scheduling instrumentation? e.g.

{
  "instrumentation": {
    "springScheduling": {
      "enabled": false
    }
  }
}

@chhauss-a
Copy link
Author

Hey @trask, I can confirm that io.opentelemetry.spring-scheduling is nowhere to be found in the logs, neither a couple minutes before and after the scheduled task.

We also haven't touched the spring scheduling instrumentation, so if it is turned on by default it should be. Does it make sense to set it to true anyway? Can I just set it in the application.properties?

If I can gather any other insights to help solve this issue please just ask.

@trask
Copy link
Member

trask commented Oct 25, 2024

hi @chhauss-a, I tried, but I'm unable to reproduce what you are seeing

can you look at https://github.com/trask/sched-lock-example?

in that case, the Java agent captures the spring scheduling span, and because it is present, it doesn't capture the exception on the underlying database span

i'm hoping you can tweak my example in a way that can exhibit the issue you're seeing?

@chhauss-a
Copy link
Author

Hey @@trask,

thanks for sharing your example. I've seen that you have added the application insights as dependency to the pom.xml. We do not have that. To build the container with our application we use a docker image that we build the following way:

FROM eclipse-temurin:21-jre-alpine

EXPOSE 8080

RUN addgroup -S myuser && adduser -S myuser -G myuser

RUN apk -U add wget --no-cache && \
    wget https://github.com/microsoft/ApplicationInsights-Java/releases/download/3.5.1/applicationinsights-agent-3.5.1.jar && \
    mv applicationinsights-agent-3.5.1.jar applicationinsights-agent.jar

USER myuser

ENTRYPOINT ["java", "-javaagent:applicationinsights-agent.jar", "-jar"]

Maybe that makes a difference?

@trask
Copy link
Member

trask commented Oct 28, 2024

thanks for sharing your example. I've seen that you have added the application insights as dependency to the pom.xml

that's just being used to tell maven to download the agent jar to the target/ directory

it's still run the same way: java -javaagent:target/agent/applicationinsights-agent.jar -jar target/app.jar

and won't make a difference.

can you create a small repro (or modify mine) in a way that allows us to reproduce and debug the issue you're seeing?

@chhauss-a
Copy link
Author

Hey @trask ,
sorry for the late reply. I will send you an small example when I find the time to create it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants