search

micrometer-metrics / micrometer

An application observability facade for the most popular observability tools. Think SLF4J, but for observability.
https://micrometer.io
Apache License 2.0
4.45k stars 979 forks source link

Parallelization issues in getLowCardinalityKeyValues #4356

Open roookeee opened 10 months ago

roookeee commented 10 months ago

Describe the bug We recently updated to Spring Boot 3.x which changed its metric tagging to be based on the micrometer Observation object. We are only creating one custom tag with a custom Spring @Bean which was migrated to an ObservationFilter: 

@Bean
fun warmupTagObservationFilter(executor: WarmupExecutor): ObservationFilter = ObservationFilter {
    if (it is ServerRequestObservationContext) {
        it.addLowCardinalityKeyValue(KeyValue.of("warmup", "${executor.isInWarmup()}"))
    } else {
        it
    }
}

We are getting the following errors (see collapsible sections below) once in a while which are suspected to be HTTP connection abortions as they happen rarely and are not correlated to service load.

java.lang.ArrayIndexOutOfBoundsException · Index 6 out of bounds for length 6 ``` java.lang.ArrayIndexOutOfBoundsException · Index 6 out of bounds for length 6 LinkedHashMap.java:555 java.util.LinkedHashMap.valuesToArray LinkedHashMap.java:639 java.util.LinkedHashMap$LinkedValues.toArray KeyValues.java:268 io.micrometer.common.KeyValues.of Observation.java:1148 io.micrometer.observation.Observation$Context.getLowCardinalityKeyValues DefaultMeterObservationHandler.java:87 io.micrometer.core.instrument.observation.DefaultMeterObservationHandler.createTags DefaultMeterObservationHandler.java:63 io.micrometer.core.instrument.observation.DefaultMeterObservationHandler.onStop TracingAwareMeterObservationHandler.java:84 io.micrometer.tracing.handler.TracingAwareMeterObservationHandler.onStop ObservationHandler.java:197 io.micrometer.observation.ObservationHandler$FirstMatchingCompositeObservationHandler.onStop SimpleObservation.java:276 io.micrometer.observation.SimpleObservation.lambda$notifyOnObservationStopped$0 ArrayDeque.java:772 java.util.ArrayDeque$DescendingIterator.forEachRemaining SimpleObservation.java:276 io.micrometer.observation.SimpleObservation.notifyOnObservationStopped SimpleObservation.java:196 io.micrometer.observation.SimpleObservation.stop ServerHttpObservationFilter.java:129 org.springframework.web.filter.reactive.ServerHttpObservationFilter.onTerminalSignal ServerHttpObservationFilter.java:117 org.springframework.web.filter.reactive.ServerHttpObservationFilter.lambda$filter$2 FluxDoOnEach.java:186 reactor.core.publisher.FluxDoOnEach$DoOnEachSubscriber.onError FluxDoOnEach.java:218 reactor.core.publisher.FluxDoOnEach$DoOnEachSubscriber.onComplete FluxOnAssembly.java:549 reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onComplete MonoFlatMap.java:250 reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete MonoFlatMap.java:324 reactor.core.publisher.MonoFlatMap$FlatMapInner.onComplete MonoFlatMap.java:250 reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete MonoFlatMap.java:324 reactor.core.publisher.MonoFlatMap$FlatMapInner.onComplete FluxOnAssembly.java:549 reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onComplete FluxContextWrite.java:126 reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onComplete MonoFlatMap.java:250 reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete MonoFlatMap.java:324 reactor.core.publisher.MonoFlatMap$FlatMapInner.onComplete FluxContextWrite.java:126 reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onComplete MonoPeekTerminal.java:299 reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onComplete MonoFlatMap.java:250 reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete MonoFlatMap.java:324 reactor.core.publisher.MonoFlatMap$FlatMapInner.onComplete FluxPeekFuseable.java:277 reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onComplete MonoPeekTerminal.java:299 reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onComplete MonoIgnoreElements.java:89 reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onComplete FluxConcatArray.java:230 reactor.core.publisher.FluxConcatArray$ConcatArraySubscriber.onComplete FluxConcatArray.java:78 reactor.core.publisher.FluxConcatArray.subscribe InternalMonoOperator.java:64 reactor.core.publisher.InternalMonoOperator.subscribe MonoFlatMap.java:165 reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext FluxContextWrite.java:107 reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext Operators.java:2545 reactor.core.publisher.Operators$ScalarSubscription.request FluxContextWrite.java:136 reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request MonoFlatMap.java:194 reactor.core.publisher.MonoFlatMap$FlatMapMain.request MonoPeekTerminal.java:139 reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.request FluxContextWrite.java:136 reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request MonoFlatMap.java:291 reactor.core.publisher.MonoFlatMap$FlatMapInner.onSubscribe FluxContextWrite.java:101 reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onSubscribe MonoPeekTerminal.java:152 reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onSubscribe MonoFlatMap.java:117 reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe FluxContextWrite.java:101 reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onSubscribe MonoJust.java:55 reactor.core.publisher.MonoJust.subscribe InternalMonoOperator.java:64 reactor.core.publisher.InternalMonoOperator.subscribe MonoFlatMap.java:165 reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext FluxSwitchIfEmpty.java:74 reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext Operators.java:2811 reactor.core.publisher.Operators$MonoInnerProducerBase.complete MonoSingle.java:180 reactor.core.publisher.MonoSingle$SingleSubscriber.onComplete FluxMapFuseable.java:152 reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onComplete Operators.java:2547 reactor.core.publisher.Operators$ScalarSubscription.request FluxMapFuseable.java:171 reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request MonoSingle.java:103 reactor.core.publisher.MonoSingle$SingleSubscriber.doOnRequest Operators.java:2878 reactor.core.publisher.Operators$MonoInnerProducerBase.request Operators.java:2341 reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set Operators.java:2215 reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe MonoSingle.java:115 reactor.core.publisher.MonoSingle$SingleSubscriber.onSubscribe FluxMapFuseable.java:96 reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe MonoJust.java:55 reactor.core.publisher.MonoJust.subscribe FluxFromMonoOperator.java:83 reactor.core.publisher.FluxFromMonoOperator.subscribe FluxDeferContextual.java:57 reactor.core.publisher.FluxDeferContextual.subscribe InternalMonoOperator.java:64 reactor.core.publisher.InternalMonoOperator.subscribe MonoFlatMap.java:165 reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext FluxMap.java:122 reactor.core.publisher.FluxMap$MapSubscriber.onNext MonoCreate.java:172 reactor.core.publisher.MonoCreate$DefaultMonoSink.success Mono.kt:101 kotlinx.coroutines.reactor.MonoCoroutine.onCompleted AbstractCoroutine.kt:93 kotlinx.coroutines.AbstractCoroutine.onCompletionInternal JobSupport.kt:294 kotlinx.coroutines.JobSupport.tryFinalizeSimpleState JobSupport.kt:856 kotlinx.coroutines.JobSupport.tryMakeCompleting JobSupport.kt:828 kotlinx.coroutines.JobSupport.makeCompletingOnce$kotlinx_coroutines_core AbstractCoroutine.kt:100 kotlinx.coroutines.AbstractCoroutine.resumeWith ContinuationImpl.kt:46 kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith Scopes.kt:33 kotlinx.coroutines.internal.ScopeCoroutine.afterResume AbstractCoroutine.kt:102 kotlinx.coroutines.AbstractCoroutine.resumeWith ContinuationImpl.kt:46 kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith DispatchedTask.kt:234 kotlinx.coroutines.DispatchedTaskKt.resume DispatchedTask.kt:190 kotlinx.coroutines.DispatchedTaskKt.resumeUnconfined DispatchedTask.kt:161 kotlinx.coroutines.DispatchedTaskKt.dispatch CancellableContinuationImpl.kt:397 kotlinx.coroutines.CancellableContinuationImpl.dispatchResume CancellableContinuationImpl.kt:431 kotlinx.coroutines.CancellableContinuationImpl.resumeImpl CancellableContinuationImpl.kt:420 kotlinx.coroutines.CancellableContinuationImpl.resumeImpl$default CancellableContinuationImpl.kt:328 kotlinx.coroutines.CancellableContinuationImpl.resumeWith Future.kt:188 kotlinx.coroutines.future.ContinuationConsumer.accept Future.kt:180 kotlinx.coroutines.future.ContinuationConsumer.accept CompletableFuture.java:863 java.util.concurrent.CompletableFuture.uniWhenComplete CompletableFuture.java:841 java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire CompletableFuture.java:510 java.util.concurrent.CompletableFuture.postComplete CompletableFuture.java:2147 java.util.concurrent.CompletableFuture.complete AbstractAsyncExecutionStrategy.java:38 graphql.execution.AbstractAsyncExecutionStrategy.lambda$handleResults$0 CompletableFuture.java:863 java.util.concurrent.CompletableFuture.uniWhenComplete CompletableFuture.java:887 java.util.concurrent.CompletableFuture.uniWhenCompleteStage CompletableFuture.java:2325 java.util.concurrent.CompletableFuture.whenComplete AsyncExecutionStrategy.java:72 graphql.execution.AsyncExecutionStrategy.lambda$execute$1 CompletableFuture.java:863 java.util.concurrent.CompletableFuture.uniWhenComplete CompletableFuture.java:841 java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire CompletableFuture.java:510 java.util.concurrent.CompletableFuture.postComplete CompletableFuture.java:2147 java.util.concurrent.CompletableFuture.complete Async.java:87 graphql.execution.Async$Single.lambda$await$1 CompletableFuture.java:863 java.util.concurrent.CompletableFuture.uniWhenComplete CompletableFuture.java:841 java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire CompletableFuture.java:510 java.util.concurrent.CompletableFuture.postComplete CompletableFuture.java:2147 java.util.concurrent.CompletableFuture.complete DataLoaderHelper.java:259 org.dataloader.DataLoaderHelper.lambda$dispatchQueueBatch$2 CompletableFuture.java:646 java.util.concurrent.CompletableFuture$UniApply.tryFire CompletableFuture.java:510 java.util.concurrent.CompletableFuture.postComplete CompletableFuture.java:1773 java.util.concurrent.CompletableFuture$AsyncSupply.run ThreadPoolExecutor.java:1136 java.util.concurrent.ThreadPoolExecutor.runWorker ThreadPoolExecutor.java:635 java.util.concurrent.ThreadPoolExecutor$Worker.run Thread.java:840 java.lang.Thread.run ```
java.lang.NullPointerException · Cannot invoke "java.lang.Comparable.compareTo(Object)" because "a[runHi]" is null ``` java.lang.NullPointerException · Cannot invoke "java.lang.Comparable.compareTo(Object)" because "a[runHi]" is null ComparableTimSort.java:325 java.util.ComparableTimSort.countRunAndMakeAscending ComparableTimSort.java:188 java.util.ComparableTimSort.sort Arrays.java:1041 java.util.Arrays.sort KeyValues.java:47 io.micrometer.common.KeyValues. KeyValues.java:268 io.micrometer.common.KeyValues.of Observation.java:1148 io.micrometer.observation.Observation$Context.getLowCardinalityKeyValues DefaultMeterObservationHandler.java:87 io.micrometer.core.instrument.observation.DefaultMeterObservationHandler.createTags DefaultMeterObservationHandler.java:63 io.micrometer.core.instrument.observation.DefaultMeterObservationHandler.onStop TracingAwareMeterObservationHandler.java:84 io.micrometer.tracing.handler.TracingAwareMeterObservationHandler.onStop ObservationHandler.java:197 io.micrometer.observation.ObservationHandler$FirstMatchingCompositeObservationHandler.onStop SimpleObservation.java:276 io.micrometer.observation.SimpleObservation.lambda$notifyOnObservationStopped$0 ArrayDeque.java:772 java.util.ArrayDeque$DescendingIterator.forEachRemaining SimpleObservation.java:276 io.micrometer.observation.SimpleObservation.notifyOnObservationStopped SimpleObservation.java:196 io.micrometer.observation.SimpleObservation.stop ServerHttpObservationFilter.java:129 org.springframework.web.filter.reactive.ServerHttpObservationFilter.onTerminalSignal ServerHttpObservationFilter.java:117 org.springframework.web.filter.reactive.ServerHttpObservationFilter.lambda$filter$2 FluxDoOnEach.java:186 reactor.core.publisher.FluxDoOnEach$DoOnEachSubscriber.onError FluxDoOnEach.java:218 reactor.core.publisher.FluxDoOnEach$DoOnEachSubscriber.onComplete FluxOnAssembly.java:549 reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onComplete MonoFlatMap.java:250 reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete MonoFlatMap.java:324 reactor.core.publisher.MonoFlatMap$FlatMapInner.onComplete MonoFlatMap.java:250 reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete MonoFlatMap.java:324 reactor.core.publisher.MonoFlatMap$FlatMapInner.onComplete FluxOnAssembly.java:549 reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onComplete FluxContextWrite.java:126 reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onComplete MonoFlatMap.java:250 reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete MonoFlatMap.java:324 reactor.core.publisher.MonoFlatMap$FlatMapInner.onComplete FluxContextWrite.java:126 reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onComplete MonoPeekTerminal.java:299 reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onComplete MonoFlatMap.java:250 reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete MonoFlatMap.java:324 reactor.core.publisher.MonoFlatMap$FlatMapInner.onComplete FluxPeekFuseable.java:277 reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onComplete MonoPeekTerminal.java:299 reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onComplete MonoIgnoreElements.java:89 reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onComplete FluxConcatArray.java:230 reactor.core.publisher.FluxConcatArray$ConcatArraySubscriber.onComplete FluxConcatArray.java:78 reactor.core.publisher.FluxConcatArray.subscribe InternalMonoOperator.java:64 reactor.core.publisher.InternalMonoOperator.subscribe MonoFlatMap.java:165 reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext FluxContextWrite.java:107 reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext Operators.java:2545 reactor.core.publisher.Operators$ScalarSubscription.request FluxContextWrite.java:136 reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request MonoFlatMap.java:194 reactor.core.publisher.MonoFlatMap$FlatMapMain.request MonoPeekTerminal.java:139 reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.request FluxContextWrite.java:136 reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request MonoFlatMap.java:291 reactor.core.publisher.MonoFlatMap$FlatMapInner.onSubscribe FluxContextWrite.java:101 reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onSubscribe MonoPeekTerminal.java:152 reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onSubscribe MonoFlatMap.java:117 reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe FluxContextWrite.java:101 reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onSubscribe MonoJust.java:55 reactor.core.publisher.MonoJust.subscribe InternalMonoOperator.java:64 reactor.core.publisher.InternalMonoOperator.subscribe MonoFlatMap.java:165 reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext FluxSwitchIfEmpty.java:74 reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext Operators.java:2811 reactor.core.publisher.Operators$MonoInnerProducerBase.complete MonoSingle.java:180 reactor.core.publisher.MonoSingle$SingleSubscriber.onComplete FluxMapFuseable.java:152 reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onComplete Operators.java:2547 reactor.core.publisher.Operators$ScalarSubscription.request FluxMapFuseable.java:171 reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request MonoSingle.java:103 reactor.core.publisher.MonoSingle$SingleSubscriber.doOnRequest Operators.java:2878 reactor.core.publisher.Operators$MonoInnerProducerBase.request Operators.java:2341 reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set Operators.java:2215 reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe MonoSingle.java:115 reactor.core.publisher.MonoSingle$SingleSubscriber.onSubscribe FluxMapFuseable.java:96 reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe MonoJust.java:55 reactor.core.publisher.MonoJust.subscribe FluxFromMonoOperator.java:83 reactor.core.publisher.FluxFromMonoOperator.subscribe FluxDeferContextual.java:57 reactor.core.publisher.FluxDeferContextual.subscribe InternalMonoOperator.java:64 reactor.core.publisher.InternalMonoOperator.subscribe MonoFlatMap.java:165 reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext FluxMap.java:122 reactor.core.publisher.FluxMap$MapSubscriber.onNext MonoCreate.java:172 reactor.core.publisher.MonoCreate$DefaultMonoSink.success Mono.kt:101 kotlinx.coroutines.reactor.MonoCoroutine.onCompleted AbstractCoroutine.kt:93 kotlinx.coroutines.AbstractCoroutine.onCompletionInternal JobSupport.kt:294 kotlinx.coroutines.JobSupport.tryFinalizeSimpleState JobSupport.kt:856 kotlinx.coroutines.JobSupport.tryMakeCompleting JobSupport.kt:828 kotlinx.coroutines.JobSupport.makeCompletingOnce$kotlinx_coroutines_core AbstractCoroutine.kt:100 kotlinx.coroutines.AbstractCoroutine.resumeWith ContinuationImpl.kt:46 kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith Scopes.kt:33 kotlinx.coroutines.internal.ScopeCoroutine.afterResume AbstractCoroutine.kt:102 kotlinx.coroutines.AbstractCoroutine.resumeWith ContinuationImpl.kt:46 kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith DispatchedTask.kt:234 kotlinx.coroutines.DispatchedTaskKt.resume DispatchedTask.kt:190 kotlinx.coroutines.DispatchedTaskKt.resumeUnconfined DispatchedTask.kt:161 kotlinx.coroutines.DispatchedTaskKt.dispatch CancellableContinuationImpl.kt:397 kotlinx.coroutines.CancellableContinuationImpl.dispatchResume CancellableContinuationImpl.kt:431 kotlinx.coroutines.CancellableContinuationImpl.resumeImpl CancellableContinuationImpl.kt:420 kotlinx.coroutines.CancellableContinuationImpl.resumeImpl$default CancellableContinuationImpl.kt:328 kotlinx.coroutines.CancellableContinuationImpl.resumeWith Future.kt:188 kotlinx.coroutines.future.ContinuationConsumer.accept Future.kt:180 kotlinx.coroutines.future.ContinuationConsumer.accept CompletableFuture.java:863 java.util.concurrent.CompletableFuture.uniWhenComplete CompletableFuture.java:841 java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire CompletableFuture.java:510 java.util.concurrent.CompletableFuture.postComplete CompletableFuture.java:2147 java.util.concurrent.CompletableFuture.complete AbstractAsyncExecutionStrategy.java:38 graphql.execution.AbstractAsyncExecutionStrategy.lambda$handleResults$0 CompletableFuture.java:863 java.util.concurrent.CompletableFuture.uniWhenComplete CompletableFuture.java:887 java.util.concurrent.CompletableFuture.uniWhenCompleteStage CompletableFuture.java:2325 java.util.concurrent.CompletableFuture.whenComplete AsyncExecutionStrategy.java:72 graphql.execution.AsyncExecutionStrategy.lambda$execute$1 CompletableFuture.java:863 java.util.concurrent.CompletableFuture.uniWhenComplete CompletableFuture.java:841 java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire CompletableFuture.java:510 java.util.concurrent.CompletableFuture.postComplete CompletableFuture.java:2147 java.util.concurrent.CompletableFuture.complete Async.java:87 graphql.execution.Async$Single.lambda$await$1 CompletableFuture.java:863 java.util.concurrent.CompletableFuture.uniWhenComplete CompletableFuture.java:841 java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire CompletableFuture.java:510 java.util.concurrent.CompletableFuture.postComplete CompletableFuture.java:2147 java.util.concurrent.CompletableFuture.complete DataLoaderHelper.java:259 org.dataloader.DataLoaderHelper.lambda$dispatchQueueBatch$2 CompletableFuture.java:646 java.util.concurrent.CompletableFuture$UniApply.tryFire CompletableFuture.java:510 java.util.concurrent.CompletableFuture.postComplete CompletableFuture.java:1773 java.util.concurrent.CompletableFuture$AsyncSupply.run ThreadPoolExecutor.java:1136 java.util.concurrent.ThreadPoolExecutor.runWorker ThreadPoolExecutor.java:635 java.util.concurrent.ThreadPoolExecutor$Worker.run Thread.java:840 java.lang.Thread.run ```

We dug a bit and determined that the index out of bounds error can only error when addLowCardinalityKeyValue and getLowCardinalityKeyValues are called in parallel, see the following micrometer Observation.Context.getLowCardinalityKeyValues() codeflow and inline comments:

// note: these are excerpts from micrometer and java stdlib classes

public KeyValues Observation.Context.getLowCardinalityKeyValues() {
            return KeyValues.of(this.lowCardinalityKeyValues.values());
}

public static KeyValues of(@Nullable Iterable<? extends KeyValue> keyValues) {
    // other branches omitted
    else if (keyValues instanceof Collection) {
        Collection<? extends KeyValue> keyValuesCollection = (Collection<? extends KeyValue>) keyValues;
        return new KeyValues(keyValuesCollection.toArray(new KeyValue[0]));
    }
    // other branches omitted
}

public <T> T[] LinkedHashMap$LinkedValues.toArray(T[] a) {
  // prepareArray creates an appropriately sized array as a 0 length array was passed
  return valuesToArray(prepareArray(a));
}

@Override
final <T> T[] LinkedHashMap.valuesToArray(T[] a) {
    Object[] r = a;
    int idx = 0;
    // this can only index out of bound when prepareArray returned an array of size X and the map was modified after prepareArray was called
    for (LinkedHashMap.Entry<K,V> e = head; e != null; e = e.after) {
        r[idx++] = e.value;
    }
    return a;
}

We found a closed issue for the other error, but that issue was closed without solving the error for us.

Environment

Minimal reproducer We are trying to create a minimal producer but this error is only occuring 10 times over a period of 24 hours with a constant load of > 300 requests / second and peak load of around 1500 requests / second (across 4 instances of our service).

Expected behavior Addind custom tags via a ObservationFilter should not create errors.

Additional context We currently expect this issue to occur when an inflight http request of a client is terminated abnormally. We want to tag such failing requests and their metrics anyways. We just thought this might help find the root cause.

jonatan-ivanov commented 10 months ago

Observation.Context is not thread-safe (it shouldn't be), its methods should not be called concurrently.

We are trying to create a minimal producer

That would be appreciated.

Addind custom tags via a ObservationFilter should not create errors.

I doubt this is caused by the filter. Check what happens when you stop an Observation: the filter is called first then the handlers are notified sequentially. This cannot happen concurrently.

I think this is caused by something adding a KeyValue to the LinkedHashMap in Observation.Context concurrently from another thread outside of Micrometer.

Could you please upgrade Spring and Micrometer first and check if it is still an issue?

AndreasEK commented 10 months ago

Hi @jonatan-ivanov , thank's for taking a look at this. I'm a colleague of roookeee, who is ooo today, so let me jump in. As far as I understand the issue, the Observation.Context is (a) added a custom tag via the filter, while at the same time the client connection crashed, so (b) the observation is stopped.

=> Both the NullPointerException and the IndexOutOfBounds originated from: ServerHttpObservationFilter.java:129 org.springframework.web.filter.reactive.ServerHttpObservationFilter.onTerminalSignal

I understand this is a super rare case, and thus we only see this phenomenon a few times a day. My assumption is, that the onTerminalSignal is running in another thread than the observation, hence it can happen that both are modifying/reading the underlying LinkedHashMap simultaneously.

Are there other means for us to make sure that usage pattern cannot happen? Like injecting a ConcurrentHashMap, overriding the SimpleObserver, … ?

github-actions[bot] commented 9 months ago

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

github-actions[bot] commented 8 months ago

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.