Consider adding 'correlation_id' and 'request_id' to request independent logs

[petar-iv]

Hi,

Use case: we have 2 applications - a producer and a consumer that communicate using messaging (like RabbitMQ).
When the consumer receives a message, this can trigger several async operations. Before fully processing the first message (during which the consumer application logs), a new message is received (which also logs). It would be handy to have the request_id in the logs so one can distinguish between logs logged during the processing of the first message and entries logged during the processing of the second message. Or in other words, messages can be treated as a kind of requests, but not an HTTP one.

Processing a message can be a part of a single transaction across multiple applications. It would be handy to have correlation_id in the request independent logs to distinguish between logs belonging to different transactions. The user will need a way to set it.

It is handy to have both request_id and correlation_id instead of just correlation_id for example, since (for some reason) the consumer may receive 2 messages that belong to the same logical transaction.

Regarding implementation - since the consumer application can receive 2 messages almost simultaneously and to process them (for example, every message triggers several async operations) almost simultaneously, then there need to be 2 different log objects and not a single one that is shared, because the different ids are state of the logger object.

I am not requesting such a feature, this is just something to consider.

Best regards
Petar

[christiand93]

Hello Petar,

if I got you right, this should already work.

You can use req.logMessage(...) instead of log.logMessage(...) and both request_id as well as correlation_id will be logged. This also works for async operations since each req object holds its own state (including request_id and correlation_id). It should even work, if an async operation belonging to a request logs messages after the response was sent.

app.get('/test', function (req, res) {
    var ctxLogger = req;
    asyncOperation(ctxLogger);
    asyncOperationWithCallback(function() {
         ctxLogger.logMessage("info", "Async operation finished");
    });
    ...
}

However in some cases it seems a bit ugly to forward the req object to (a)sync operations just for logging. It would be a possible solution to provide an additional logger object per request, which stores its context and allows logging.

Kind regards,
Christian

[KarstenSchnitter]

Hello Petar,

as I understand your description you are looking for a way to split correlation_ids while retaining the original source. In your example you start from a single transaction, that leads to multiple messages in your queue. You want to trace these messages and all downstream generated logs separately while still retaining the connection to their common source (the transaction).

                                    |----> message A 
                                    |       - writes log A-1 (C1)
                                    |       - writes log A-2 (C1)
transaction (correlation-id: C1)----|
                                    |----> message B
                                            - writes log B-1 (C1)
                                            - writes log B-2 (C1)

So the abstract problem is to introduce new groupings of logs (like correlation_id) while retaining the old ones. To me this becomes problematic, when recursion of this step occurs.
Let's say there is a downstream service, that handles message A and behaves in a similar fashion. It, too, wants to extend the present correlation ids to reflect different paths of processing.
In short for each correlation id there are potentially multiple further markers depending on the message path or as in your case different runs of multiple messages.

Currently our stack is unable to support such a feature besides the solution Christian mentioned. To have more general support, it would be a possibility to support an array of correlation_ids, where you could add additional ids (or labels) according to your needs. We could then support searches in Kibana for any of these given values. Would that be a useful approach to your problem?

[petar-iv]

Hi,

The illustration in the previous comment is pretty good. The only thing in addition is that the logs during the processing of message A can be mixed with the logs during the processing of message B. This is why we need to have a unique identifier that will be included in all the logs for message A and a different one for all the logs for message B to distinguish between the 2. The values are application-local (do not have meaning outside of the current application), they can be auto-generated or set explicitly (but still better be unique). Exactly the same as with request_id in the logs produced with req.logMessage(...) (because 2 HTTP requests can be processed almost simultaneously).

I do not understand the idea behind having an array with correlation ids.
I think correlation_id (as a property in the log entry) should have the same value for all logs across multiple applications that belong to the same logical transaction (apps can send the value to each other). And app should not extend a list of correlation ids. And its value should not be used to distinguish logs from parallel executions - the purpose of the property is different.

I think the situation is exactly the same as with HTTP requests and req.logMessage(...). The only difference is that the type of the request is not an HTTP one, but a message received from a producer application.

I see several relatively simple solutions (for all of these it should be possible to create a different logger when a new message arrives to preserve state. Also the property correlation_id is well named - keep it the same. Regarding the other one (with which we distinguish logs from different received messages):

• the property request_id can be reused - this is the most simple solution. The drawback is that the name suits HTTP requests very well, but probably is not that suitable for messaging.
• to use a different property (e.g. context_id). There are 2 possibilities here:
  • use the new property for logs for messages only and keep using request_id for logs for HTTP requests as it is now
  • use the new (more generic) property for all logs (including those bound to an HTTP request). This will make the output of the library consistent which I think is great, but it may require changes in Kibana, I am not into the details here. This solution is the one that appears most appealing to me.

By the way the same logic (as with messages) is applicable to job runs as well (that run according to a specified schedule, not because an HTTP request has arrived).

Let me know what your thoughts are.

Many thanks
Petar

[altenhof]

If I'm not completely mistaken, this reminds me of what OpenTracing is trying to address, i.e. have a transactional view on operations or requests that travel through a distributed system.

Looking at what they do, I think that the transaction would represent the top-level Span, and all requests would reference that top_level span using the ChildOf relation. Using parent-id and span-id , I would annotate the above diagram like this:

                                                |----> message A (starts span A as child of C1)
                                                |       - writes log A-1 (parent-id: C1, span-id: A)
                                                |       - writes log A-2 (parent-id: C1, span-id: A)
transaction (parent-id:<nil>, span-id: C1)------|
                                                |----> message B (starts span B as child of C1)
                                                       - writes log B-1 (parent-id: C1, span-id: B)
                                                       - writes log B-2 (parent-id: C1, span-id: B)

It certainly would need more time to think this through, but instinctively I would go for just two IDs, expressing the parent-child-relationship.

As Karsten already mentioned, we're not there yet, but it is certainly something we should consider as a future feature.