ApplicationInsights-Java icon indicating copy to clipboard operation
ApplicationInsights-Java copied to clipboard
verified publisher icon microsoft

Handled / catched exceptions are getting into Azure Application Insights

Open chhauss-a opened this issue 1 year ago • 12 comments

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

chhauss-a avatar Aug 14 '24 08:08 chhauss-a

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

heyams avatar Aug 15 '24 17:08 heyams

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 avatar Aug 16 '24 06:08 chhauss-a

Any updates on this issue so far?

chhauss-a avatar Oct 22 '24 13:10 chhauss-a

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 avatar Oct 22 '24 19:10 trask

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

trask avatar Oct 22 '24 19:10 trask

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!

chhauss-a avatar Oct 24 '24 08:10 chhauss-a

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
    }
  }
}

trask avatar Oct 24 '24 21:10 trask

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.

chhauss-a avatar Oct 25 '24 06:10 chhauss-a

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?

trask avatar Oct 25 '24 22:10 trask

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?

chhauss-a avatar Oct 28 '24 10:10 chhauss-a

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?

trask avatar Oct 28 '24 15:10 trask

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

chhauss-a avatar Nov 18 '24 07:11 chhauss-a