Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

[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 this issue Jun 12, 2024 · 4 comments
Open

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

AleksanderBrzozowski opened this issue Jun 12, 2024 · 4 comments
Labels
waiting-for-triage

Comments

@AleksanderBrzozowski
Copy link
Contributor

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

  • Micrometer version: I've pulled the latest version of repository from main branch. I assume it is based on 1.13.1
  • Micrometer registry [e.g. prometheus]
  • OS: macOS
  • Java version: [e.g. output of java -version]

To Reproduce
How to reproduce the bug:

see [commit]((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
Copy link
Contributor

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

@AleksanderBrzozowski
Copy link
Contributor Author

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
Copy link
Contributor Author

@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
Copy link
Contributor

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
waiting-for-triage
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@marcingrzejszczak @AleksanderBrzozowski