It would be really nice if fmtlog provided NDC functionality

[gh-andre]

Problem

NDC (Nested Diagnostic Context) is quite useful when a single work item generates multiple log messages in different application layers and lower layers may not have the context to allow correlating their log lines with those logged by layers above. Using thread ID for this is the only way and it makes log post-processing much more complex.

For example, if I use this format {YmdHMSF},{l},{s},{t}, and log messages throughout work item processing, I would have these log lines:

2022-12-23 14:21:11.312558137,INF,db_conn.cpp:123,115100,Querying user "user ABC"
2022-12-23 14:21:11.312558137,INF,work_handler.cpp:456,115100,Processed work 638a7572839595740869510a for ABC

Now if I need to troubleshoot an issue for this work item (638a7572839595740869510a), I need to find the last log line and then use thread ID 115100 to correlate all other log lines for this work item processing.

Suggestion

If fmtlog tracks a stack of string values (NDC), all related log lines can be connected by these values. NDC can be processed very efficiently in a high-performance logger with something like this.

• Add a new format specifier for NDC (e.g. {x})
• Add a thread_local vector for NDC strings that will serve as a stack
• Add a new class for callers to push individual NDC values on stack
• In logging methods, such as logOnce, if NDC stack is not empty, concatenate NDC strings with a space and store in a logger queue header, along with the formatted message
• In the poll method, if format has {x}, output concatenated NDC value in the position for {x}

From the fmtlog callers's perspective, it would look like this:

void work_handler(work_item& wi)
{
    fmtlog::ndc_frame work_ndc = fmtlog::ndc_begin(wi.get_id().to_string());
    const user_t *user = db_conn.find_user(wi.user_name());
    work(user, wi);
    logi("Processed work for {:s}", wi.user_name());
}
const user_t *db_conn::find_user(const std::string& user_name)
{
    fmtlog::ndc_frame db_conn_ndc = fmtlog::ndc_add(db.conn_id().to_string());
    logi("Querying user {:s}", user name);
    return db.query(...);
}

, and will produce something similar to this, given log format {YmdHMSF},{l},{s},{t},{x},, with 638a7572839595740869510a being the first NDC values and 7890 being the second one:

2022-12-23 14:21:11.312558137,INF,db_conn.cpp:123,115100,638a7572839595740869510a 7890,Querying user ABC
2022-12-23 14:21:11.312558137,INF,work_handler.cpp:456,115100,638a7572839595740869510a,Processed work for ABC

I implemented this approach in the application code and it produces the logs with NDC values, but I can only do it as a hack in how I intercept the message format and inject the NDC values. I think it would be useful for many fmtlog users if this functionality is implemented in fmtlog.

Notes

A couple of notes from my implementation.

• std::stack won't work here and std::vector is needed to be able to grab all NDC values to concatenate them.
• Using a space sounds like a reasonable concatenation character. Log4cxx also does it with a space.
• It's reasonable to restrict the number of NDC values to some limit, such as 4-5. This allows to avoid a loop to concatenate NDC values and just use something like ndc[0] + ' ' + ndc[1] + ' ' + ndc[2] for each supported NDC level.
• ndc_frame type would just push/pop NDC values in the constroctor/destructor and there's no need to expose push/pop to the application
• ndc_begin and ndc_add would construct ndc_frame and the former one also would ensure current stack is empty, so there are no orphaned NDC stacks.

This is log4cxx's page on NDC.

https://logging.apache.org/log4cxx/latest_stable/classlog4cxx_1_1NDC.html

I will note that log4cxx is not very efficient in handling NDC values and concatenate NDC strings on every push call and in each stack frame keep a full concatenated value.

[MengRao]

Thank you for the advice.

If I understand correctly, the NDC functionality adds some user defined context describtion in a thread local stack, and log statement should output this stack in the log header(If configured by setHeaderPattern). In terms of implementation, the stack can be passed as a vector to the log queue(as fmtlog already supports vector parameter).

Currently fmtlog only add one type of dynamic info for log header: timestamp, which most users would need it. Here the NDC would be the second type, which also must be encoded and passed through log queue for every log statement, the difference is that it might seldomly be used. So I suggest NDC be in the log body instead of log header, so those who don't need it won't be affected, and it should also be concise:

thread_local std::vector<int> ndc;

logi("{} other info...", ndc);

[gh-andre]

Thanks for responding.

Well, for those who want to implement this approach in their app code, I would suggest to use an NDC frame guard class instead of just a vector, which will ensure that the stack in the thread local storage is popped if an exception is thrown. This guard class would have a reference to the application logger, which would maintain the NDC stack and push/pop methods. This will keep the stack balanced.