Exposing correlation ids for logging

googlegroup
1

Hi,

I have what I imagine to be a fairly common problem with microservices
setups - namely, that when logging events, I would like to be able to track
a particular request as it progresses through various RPC calls. The usual
way to do this would be to share a common correlation_id between calls, so
that the logging entry would look something like

CorrID: 12345abcde,Service: my-service, Msg: my logged message

However, to pass a common correlation_id amongst rpc creates a lot of
boilerplate - essentially each endpoint has to receive an extra
correlation_id argument, and remember to pass that argument to the next
call in the chain (and to every log event).

I noticed that a correlation_id is already passed by kombu as part of the
message properties, but I cannot see any way to get or set it with the
standard decorators. It appears to be used only to specify the reply queue.

So the question is, is there a nice way to get hold of the existing
correlation_id and pass it on, or to create a new message property with a
new correlation id, or is there a better way to solve this problem?

Thanks

2

Nameko already does most of this for you.

There is a notion of the "call id stack" on the WorkerContext
<https://github.com/nameko/nameko/blob/v2.5.3/nameko/containers.py#L56-L117&gt;\.
Each time an Entrypoint fires a "call id" is generated in the form
"service_name.method_name.uuid4". The WorkerContext stores the previous
call ids as a stack, so at any point you can can see the id of the *current*
call and those of its ancestors.

The worker context is passed into the dependency provider lifecycle methods
<https://github.com/nameko/nameko/blob/v2.5.3/nameko/extensions.py#L154-L192&gt; as
well as get_dependency
<https://github.com/nameko/nameko/blob/v2.5.3/nameko/extensions.py#L149-L153&gt;\.
A quick way to implement your example above would be:

import logging

from nameko.rpc import rpc
from nameko.extensions import DependencyProvider

logger = logging.getLogger(__name__)

class Logger(DependencyProvider):

    def get_dependency(self, worker_ctx):
        def log(msg):
            logger.info("%s: %s" % (worker_ctx.call_id, msg))
        return log

class Service:
    name = "my-service"

    log = Logger()

    @rpc
    def method(self):
        self.log("my logged message")

$ nameko shell
Nameko Python 2.7.10 (default, Jul 6 2015, 15:19:48)
[GCC 4.2.1 Compatible Apple LLVM 6.1.0 (clang-602.0.53)] shell on darwin
Broker: amqp://guest:guest@localhost

n.rpc['my-service'].method()

$ nameko run service
starting services: my-service
Connected to amqp://guest:**@127.0.0.1:5672//
my-service.method.755e1a77-6ef5-49ac-ac79-4137298ee053: my logged message

You'll also see the call id showing up if you use the nameko-sentry
<https://github.com/mattbennett/nameko-sentry&gt; extension.

The call id *stack* is much more powerful than simply logging the current
call id. We push the entire stack from every entrypoint into elasticsearch,
so we can query to trace any call back to its ancestors.

Also note that the call id applies for all entrypoint types whereas (as you
discovered) the correlation id is a detail of the RPC implementation.

···

On Monday, March 20, 2017 at 2:53:37 PM UTC, alexwhi...@googlemail.com wrote:

Hi,

I have what I imagine to be a fairly common problem with microservices
setups - namely, that when logging events, I would like to be able to track
a particular request as it progresses through various RPC calls. The usual
way to do this would be to share a common correlation_id between calls, so
that the logging entry would look something like

CorrID: 12345abcde,Service: my-service, Msg: my logged message

However, to pass a common correlation_id amongst rpc creates a lot of
boilerplate - essentially each endpoint has to receive an extra
correlation_id argument, and remember to pass that argument to the next
call in the chain (and to every log event).

I noticed that a correlation_id is already passed by kombu as part of the
message properties, but I cannot see any way to get or set it with the
standard decorators. It appears to be used only to specify the reply queue.

So the question is, is there a nice way to get hold of the existing
correlation_id and pass it on, or to create a new message property with a
new correlation id, or is there a better way to solve this problem?

Thanks

3

Thank you for the very comprehensive answer, that is exactly the sort of
thing I was looking for.

More impressed with this framework the more I use it, thank you for you
hard work!

···

On Monday, 20 March 2017 16:06:00 UTC, Matt Yule-Bennett wrote:

Nameko already does most of this for you.

There is a notion of the "call id stack" on the WorkerContext
<https://github.com/nameko/nameko/blob/v2.5.3/nameko/containers.py#L56-L117&gt;\.
Each time an Entrypoint fires a "call id" is generated in the form
"service_name.method_name.uuid4". The WorkerContext stores the previous
call ids as a stack, so at any point you can can see the id of the
*current* call and those of its ancestors.

The worker context is passed into the dependency provider lifecycle
methods
<https://github.com/nameko/nameko/blob/v2.5.3/nameko/extensions.py#L154-L192&gt; as
well as get_dependency
<https://github.com/nameko/nameko/blob/v2.5.3/nameko/extensions.py#L149-L153&gt;\.
A quick way to implement your example above would be:

import logging

from nameko.rpc import rpc
from nameko.extensions import DependencyProvider

logger = logging.getLogger(__name__)

class Logger(DependencyProvider):

    def get_dependency(self, worker_ctx):
        def log(msg):
            logger.info("%s: %s" % (worker_ctx.call_id, msg))
        return log

class Service:
    name = "my-service"

    log = Logger()

    @rpc
    def method(self):
        self.log("my logged message")

$ nameko shell
Nameko Python 2.7.10 (default, Jul 6 2015, 15:19:48)
[GCC 4.2.1 Compatible Apple LLVM 6.1.0 (clang-602.0.53)] shell on darwin
Broker: amqp://guest:guest@localhost
>>> n.rpc['my-service'].method()
>>>

$ nameko run service
starting services: my-service
Connected to amqp://guest:**@127.0.0.1:5672//
my-service.method.755e1a77-6ef5-49ac-ac79-4137298ee053: my logged message

You'll also see the call id showing up if you use the nameko-sentry
<https://github.com/mattbennett/nameko-sentry&gt; extension.

The call id *stack* is much more powerful than simply logging the current
call id. We push the entire stack from every entrypoint into elasticsearch,
so we can query to trace any call back to its ancestors.

Also note that the call id applies for all entrypoint types whereas (as
you discovered) the correlation id is a detail of the RPC implementation.

On Monday, March 20, 2017 at 2:53:37 PM UTC, alexwhi...@googlemail.com > wrote:

Hi,

I have what I imagine to be a fairly common problem with microservices
setups - namely, that when logging events, I would like to be able to track
a particular request as it progresses through various RPC calls. The usual
way to do this would be to share a common correlation_id between calls, so
that the logging entry would look something like

CorrID: 12345abcde,Service: my-service, Msg: my logged message

However, to pass a common correlation_id amongst rpc creates a lot of
boilerplate - essentially each endpoint has to receive an extra
correlation_id argument, and remember to pass that argument to the next
call in the chain (and to every log event).

I noticed that a correlation_id is already passed by kombu as part of the
message properties, but I cannot see any way to get or set it with the
standard decorators. It appears to be used only to specify the reply queue.

So the question is, is there a nice way to get hold of the existing
correlation_id and pass it on, or to create a new message property with a
new correlation id, or is there a better way to solve this problem?

Thanks