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.39k stars 966 forks source link

[gRPC + coroutines] Observation to which we're restoring is not the same as the one set as this scope's parent observation #5221

Open AleksanderBrzozowski opened 2 weeks ago

AleksanderBrzozowski commented 2 weeks ago

Describe the bug

Some time ago, I added a change to the micrometer that allowed to pass Observation to a gRPC server using kotlin coroutines, see here.

Recently, a new spring boot was released that contains latest changes in micrometer. I tried to use the new Observation propagation feature, but I observed this strange error:

Observation <{name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}> to which we're restoring is not the same as the one set as this scope's parent observation <null>. Most likely a manually created Observation has a scope opened that was never closed. This may lead to thread polluting and memory leaks.

Unfortunately, it seems that the changes that I made are not working as expected. I've prepared a commit that reproduces the issue, see here.

Here are the logs from test execution:

08:42:57.370 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - START - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.373 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.417 [single-thread] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.417 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.418 [single-thread] TRACE i.m.o.c.ObservationThreadLocalAccessor - Called setValue(...) for Observation <{name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}> and opened scope <io.micrometer.observation.SimpleObservation$SimpleScope@36ccb495>
08:42:57.418 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.419 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.428 [single-thread] TRACE i.m.o.c.ObservationThreadLocalAccessor - Calling restore()
08:42:57.428 [single-thread] TRACE i.m.o.c.ObservationThreadLocalAccessor - Closing current scope <io.micrometer.observation.SimpleObservation$SimpleScope@36ccb495>
08:42:57.428 [single-thread] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.428 [single-thread] TRACE i.m.o.c.ObservationThreadLocalAccessor - After closing scope, current one is <null>
08:42:57.445 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - EVENT - MESSAGE_RECEIVED, name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.446 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.446 [single-thread] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.446 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.446 [single-thread] TRACE i.m.o.c.ObservationThreadLocalAccessor - Called setValue(...) for Observation <{name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}> and opened scope <io.micrometer.observation.SimpleObservation$SimpleScope@2c61eea3>
08:42:57.447 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.448 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.450 [single-thread @coroutine#1] INFO  i.m.o.ObservationTextPublisher - START - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
08:42:57.451 [single-thread @coroutine#1] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
08:42:57.453 [single-thread] TRACE i.m.o.c.ObservationThreadLocalAccessor - Calling restore()
08:42:57.453 [single-thread] TRACE i.m.o.c.ObservationThreadLocalAccessor - Closing current scope <io.micrometer.observation.SimpleObservation$SimpleScope@5ef5ac59>
08:42:57.453 [single-thread] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
08:42:57.453 [single-thread] TRACE i.m.o.c.ObservationThreadLocalAccessor - After closing scope, current one is <io.micrometer.observation.SimpleObservation$SimpleScope@2c61eea3>
08:42:57.454 [single-thread] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.454 [single-thread] TRACE i.m.o.c.ObservationThreadLocalAccessor - Called setValue(...) for Observation <{name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}> and opened scope <io.micrometer.observation.SimpleObservation$SimpleScope@5af7507e>
08:42:57.454 [single-thread @coroutine#1] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
08:42:57.455 [single-thread @coroutine#1] INFO  i.m.o.ObservationTextPublisher -  STOP - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
08:42:57.456 [single-thread @coroutine#1] INFO  i.m.o.ObservationTextPublisher - EVENT - MESSAGE_SENT, name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.458 [single-thread] TRACE i.m.o.c.ObservationThreadLocalAccessor - Calling restore(...) with Observation <{name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}> and scope <io.micrometer.observation.SimpleObservation$SimpleScope@2c61eea3>
08:42:57.458 [single-thread] WARN  i.m.o.c.ObservationThreadLocalAccessor - Observation <{name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}> to which we're restoring is not the same as the one set as this scope's parent observation <null>. Most likely a manually created Observation has a scope opened that was never closed. This may lead to thread polluting and memory leaks.
08:42:57.458 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.459 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:42:57.469 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  STOP - name='grpc.server', contextualName='grpc.testing.SimpleService/UnaryRpc', error='null', lowCardinalityKeyValues=[grpc.status_code='OK', rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null

Environment

To Reproduce How to reproduce the bug:

see [commit]((https://github.com/micrometer-metrics/micrometer/compare/main...AleksanderBrzozowski:micrometer:support-observation-propagation-for-kotlin-coroutines-grpc-server)

Expected behavior

Seems that the issue is related to ObservationThreadLocalAccessor.restore function.

Additional context

When observation is not being restored, because a coroutine is not restored, but a new one is started, the issue doesn't happen, see below logs:

08:51:26.445 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - START - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.475 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.579 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.579 [DefaultDispatcher-worker-1] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.580 [DefaultDispatcher-worker-1] TRACE i.m.o.c.ObservationThreadLocalAccessor - Called setValue(...) for Observation <{name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}> and opened scope <io.micrometer.observation.SimpleObservation$SimpleScope@7af88c8e>
08:51:26.582 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.582 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.593 [DefaultDispatcher-worker-1] TRACE i.m.o.c.ObservationThreadLocalAccessor - Calling restore()
08:51:26.593 [DefaultDispatcher-worker-1] TRACE i.m.o.c.ObservationThreadLocalAccessor - Closing current scope <io.micrometer.observation.SimpleObservation$SimpleScope@7af88c8e>
08:51:26.594 [DefaultDispatcher-worker-1] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.594 [DefaultDispatcher-worker-1] TRACE i.m.o.c.ObservationThreadLocalAccessor - After closing scope, current one is <null>
08:51:26.597 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - EVENT - MESSAGE_RECEIVED, name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.598 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.599 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.599 [DefaultDispatcher-worker-1] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.599 [DefaultDispatcher-worker-1] TRACE i.m.o.c.ObservationThreadLocalAccessor - Called setValue(...) for Observation <{name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}> and opened scope <io.micrometer.observation.SimpleObservation$SimpleScope@2411ebb5>
08:51:26.599 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.600 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.601 [DefaultDispatcher-worker-1 @coroutine#1] INFO  i.m.o.ObservationTextPublisher - START - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
08:51:26.601 [DefaultDispatcher-worker-1 @coroutine#1] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
08:51:26.604 [DefaultDispatcher-worker-1] TRACE i.m.o.c.ObservationThreadLocalAccessor - Calling restore()
08:51:26.604 [DefaultDispatcher-worker-1] TRACE i.m.o.c.ObservationThreadLocalAccessor - Closing current scope <io.micrometer.observation.SimpleObservation$SimpleScope@33b13c25>
08:51:26.604 [DefaultDispatcher-worker-1] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
08:51:26.604 [DefaultDispatcher-worker-1] TRACE i.m.o.c.ObservationThreadLocalAccessor - After closing scope, current one is <io.micrometer.observation.SimpleObservation$SimpleScope@2411ebb5>
08:51:26.604 [DefaultDispatcher-worker-2] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.604 [DefaultDispatcher-worker-2] TRACE i.m.o.c.ObservationThreadLocalAccessor - Called setValue(...) for Observation <{name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}> and opened scope <io.micrometer.observation.SimpleObservation$SimpleScope@34003baf>
08:51:26.605 [DefaultDispatcher-worker-2 @coroutine#1] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
08:51:26.605 [DefaultDispatcher-worker-2 @coroutine#1] INFO  i.m.o.ObservationTextPublisher -  STOP - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
08:51:26.606 [DefaultDispatcher-worker-2 @coroutine#1] INFO  i.m.o.ObservationTextPublisher - EVENT - MESSAGE_SENT, name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.608 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.608 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.608 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  STOP - name='grpc.server', contextualName='grpc.testing.SimpleService/UnaryRpc', error='null', lowCardinalityKeyValues=[grpc.status_code='OK', rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.609 [DefaultDispatcher-worker-2] TRACE i.m.o.c.ObservationThreadLocalAccessor - Calling restore()
08:51:26.609 [DefaultDispatcher-worker-2] TRACE i.m.o.c.ObservationThreadLocalAccessor - Closing current scope <io.micrometer.observation.SimpleObservation$SimpleScope@2411ebb5>
08:51:26.609 [DefaultDispatcher-worker-2] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='grpc.testing.SimpleService/UnaryRpc', error='null', lowCardinalityKeyValues=[grpc.status_code='OK', rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
08:51:26.609 [DefaultDispatcher-worker-2] TRACE i.m.o.c.ObservationThreadLocalAccessor - After closing scope, current one is <null>
marcingrzejszczak commented 2 weeks ago

So we have GRPC and Kotlin here. Can you try to isolate the problem e.g. only to Grpc or Kotlin?

AleksanderBrzozowski commented 2 weeks ago

I can't reproduce this issue using gRPC or Kotlin coroutines, unfortunately 😞

I added additional logging, and I found scope which is not being closed:

11:39:54.875 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - START - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.878 [grpc-default-executor-0] INFO  i.m.o.SimpleObservation$SimpleScope - Scope opened: io.micrometer.observation.SimpleObservation$SimpleScope@5f9d2dc9
11:39:54.878 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.901 [grpc-default-executor-0] DEBUG i.m.o.SimpleObservation$SimpleScope - Closing scope: io.micrometer.observation.SimpleObservation$SimpleScope@5f9d2dc9
11:39:54.902 [single-thread] INFO  i.m.o.SimpleObservation$SimpleScope - Scope opened: io.micrometer.observation.SimpleObservation$SimpleScope@335435f0
11:39:54.902 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.902 [single-thread] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.903 [grpc-default-executor-0] INFO  i.m.o.SimpleObservation$SimpleScope - Scope opened: io.micrometer.observation.SimpleObservation$SimpleScope@2018ec54
11:39:54.903 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.904 [grpc-default-executor-0] DEBUG i.m.o.SimpleObservation$SimpleScope - Closing scope: io.micrometer.observation.SimpleObservation$SimpleScope@2018ec54
11:39:54.904 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.912 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - EVENT - MESSAGE_RECEIVED, name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.912 [grpc-default-executor-0] INFO  i.m.o.SimpleObservation$SimpleScope - Scope opened: io.micrometer.observation.SimpleObservation$SimpleScope@4fe8e027
11:39:54.912 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.912 [single-thread] DEBUG i.m.o.SimpleObservation$SimpleScope - Closing scope: io.micrometer.observation.SimpleObservation$SimpleScope@335435f0
11:39:54.913 [single-thread] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.913 [single-thread] INFO  i.m.o.SimpleObservation$SimpleScope - Scope opened: io.micrometer.observation.SimpleObservation$SimpleScope@33f78a04
11:39:54.913 [grpc-default-executor-0] DEBUG i.m.o.SimpleObservation$SimpleScope - Closing scope: io.micrometer.observation.SimpleObservation$SimpleScope@4fe8e027
11:39:54.913 [single-thread] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.913 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.913 [grpc-default-executor-0] INFO  i.m.o.SimpleObservation$SimpleScope - Scope opened: io.micrometer.observation.SimpleObservation$SimpleScope@1df02ef1
11:39:54.913 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.914 [grpc-default-executor-0] DEBUG i.m.o.SimpleObservation$SimpleScope - Closing scope: io.micrometer.observation.SimpleObservation$SimpleScope@1df02ef1
11:39:54.914 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.915 [single-thread @coroutine#1] INFO  i.m.o.ObservationTextPublisher - START - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
11:39:54.915 [single-thread @coroutine#1] INFO  i.m.o.SimpleObservation$SimpleScope - Scope opened: io.micrometer.observation.SimpleObservation$SimpleScope@77b3ffa1
11:39:54.915 [single-thread @coroutine#1] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
11:39:54.917 [single-thread] DEBUG i.m.o.SimpleObservation$SimpleScope - Closing scope: io.micrometer.observation.SimpleObservation$SimpleScope@77b3ffa1
11:39:54.917 [single-thread] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
11:39:54.918 [single-thread] INFO  i.m.o.SimpleObservation$SimpleScope - Scope opened: io.micrometer.observation.SimpleObservation$SimpleScope@1629599e
11:39:54.918 [single-thread] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.918 [single-thread @coroutine#1] DEBUG i.m.o.SimpleObservation$SimpleScope - Closing scope: io.micrometer.observation.SimpleObservation$SimpleScope@77b3ffa1
11:39:54.918 [single-thread @coroutine#1] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
11:39:54.919 [single-thread @coroutine#1] INFO  i.m.o.ObservationTextPublisher -  STOP - name='test', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[], map=[], parentObservation={name=grpc.server(null), error=null, context=name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}
11:39:54.920 [single-thread @coroutine#1] INFO  i.m.o.ObservationTextPublisher - EVENT - MESSAGE_SENT, name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.921 [grpc-default-executor-0] INFO  i.m.o.SimpleObservation$SimpleScope - Scope opened: io.micrometer.observation.SimpleObservation$SimpleScope@45459493
11:39:54.922 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  OPEN - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.922 [grpc-default-executor-0] DEBUG i.m.o.SimpleObservation$SimpleScope - Closing scope: io.micrometer.observation.SimpleObservation$SimpleScope@45459493
11:39:54.922 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher - CLOSE - name='grpc.server', contextualName='null', error='null', lowCardinalityKeyValues=[rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.922 [grpc-default-executor-0] INFO  i.m.o.ObservationTextPublisher -  STOP - name='grpc.server', contextualName='grpc.testing.SimpleService/UnaryRpc', error='null', lowCardinalityKeyValues=[grpc.status_code='OK', rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null
11:39:54.922 [single-thread] WARN  i.m.o.c.ObservationThreadLocalAccessor - Observation <{name=grpc.server(grpc.testing.SimpleService/UnaryRpc), error=null, context=name='grpc.server', contextualName='grpc.testing.SimpleService/UnaryRpc', error='null', lowCardinalityKeyValues=[grpc.status_code='OK', rpc.method='UnaryRpc', rpc.service='grpc.testing.SimpleService', rpc.type='UNARY'], highCardinalityKeyValues=[], map=[], parentObservation=null}> to which we're restoring is not the same as the one set as this scope's parent observation <null>. Most likely a manually created Observation has a scope opened that was never closed. This may lead to thread polluting and memory leaks.

This is the one:

11:39:54.918 [single-thread] INFO  i.m.o.SimpleObservation$SimpleScope - Scope opened: io.micrometer.observation.SimpleObservation$SimpleScope@1629599e
AleksanderBrzozowski commented 5 days ago

@marcingrzejszczak Any ideas what we can do to debug this issue? I am happy to help, but I need to know where to start 🙂

marcingrzejszczak commented 5 days ago

These kind of problems are the most difficult ones to debug. What you can do is to put a breakpoint inside the SimpleScope that will print the stacktrace when reached. That way you will know who opened the scope and not closed it.