Adding extra information to logging calls

[cmeister2]

My use case for spdlog is for JSON formatting logs, before logging them to stdout. I've achieved this by having a custom formatter, coupled with the stdout sink.

However, it'd be great if I could pass down more information into the formatter from the log call, like you can in Python (with the "extra" keyword argument).

Would that be a useful addition to spdlog? If so, what would that look like - some kind of extra piece of information on the log_msg struct?

[gabime]

Could you provide an example ?

[cmeister2]

Sure. Let's say you want to add extra information to a JSON log. Normal json log looks like:
{"msg": "A log message"}

Now we want extra information in this log - say an ID and an associated value.
{"msg": "The system is now working", "id": "IDENTIFIER", "value": "1"}

I don't want to generate this JSON at the point of calling logger.log - I want the formatter to handle that for me if it needs to.

[stegvdm]

This request sounds something like the Attributes feature of Boost.Log (http://www.boost.org/doc/libs/1_63_0/libs/log/doc/html/log/detailed/attributes.html).

I know this because we are ex-Boost.Log users who migrated to a superior/easier/faster/cleaner logging library ;-)

I have a similar use case where we use spdlog to log string messages which are manipulated into json, which are buffered and sent asynchronously to a FluentD/td-agent daemon for logging in Kibana. We had a previous implementation in boost.log and used the Attributes feature to store extra metadata about each log message, some of which were needed for FluentD. This is the one feature that spdlog is missing imho.

I can see a use-case in spdlog for an optional (i.e. Off by default) extension to the detail::log_msg struct extension adding a (fixed-size?) list (std::vector?) of Attributes to each log message. A possible Attribute implementation could be based on std::variant (unfortunately the type is c++17 only). Somehow via the logger class one would write a log plus a map structure of extra Attribute key-value pairs.

However, I cannot speak for the library author(s) and don't know if people would generally find a 'Log Attributes' feature worthwhile and/or desirable.

[gabime]

@lion10243 Is this pull that achieves something similar ?

[stegvdm]

@gabime thanks for the suggestion - partially. The pattern formatters look useful, but what I'm really searching for is the ability to store metadata alongside the log message string in a type-safe union data structure, rather than embedding the metadata directly in the log message.

[gabime]

@lion10243 Could you provide an example of how such API might look like?

[stegvdm]

@gabime having looked at the logger.h code to see what would be possible, something like the following would perhaps be workable (without consideration of technical/performance cpp semantics etc)...

spdlog::get()->log(level::debug, {{"key1", 1234},{"key2","value"}}, "my {} msg with {} formatting, "empty", "dumb");

and inside the log() method the metadata would be assigned to log_msg struct, e.g.

details::log_msg log_msg(&_name, lvl); log_msg.attrs = meta_attrs;

Of course, something like log(level, msg, fmt, meta_attributes) would be perfect but doesn't unfortunately work with the templated varargs param for FMT lib.

[stegvdm]

@cmeister2 @gabime I've been playing with a prototype that implements an optional log record attribute map, when a feature in tweakme.h is enabled.

It's a std::map<std::string, variant>, where variant is std::variant (cpp17) or alternatively mpark::variant (cpp11, cpp14). The logger.h + detail/logger_impl.h classes were extended with extra log method signatures allowing an attribute map as parameter. The attribute values can be retrieved from the details::log_msg struct via a call to spdlog::attrval::get, which wraps the appropriate std::get or mpark::get depending on cpp version.

The "set" api currently looks like this (actual code from an app):
spdlog::attrmap_type ma { {"search_id", q->api_search_id()}, {"uuid", q->uuid()}, {"shop", q->shop_name()}, {"market", q->market().Name}, {"partner", q->partner().Name}, }; spdlog::get("shop")->info(ma, fmt, args...);

The "get" api currently looks like so:
auto iter = msg.attrs.find("partner"); if (iter != msg.attrs.end()) { auto& variant = iter->second; json["partner"] = spdlog::attrval::get<std::string>(variant); }

Files changed: common.h, logger.h, details/logger_impl.h
Code here: https://github.com/lion10243/spdlog/tree/logmsg-metadata/.

Feedback and opinions welcome :)

[arthur-tacca]

I would like something like this. spdlog is missing a few fields that seem like obvious necessary things to include in a log record, but I think "obvious and necessary" is going to be different for everyone so custom fields might help as a compromise.

Examples were asked for, so here are fields I would use:

• Thread name, but not linked to OS name of thread (see [Enhancement] Option to log thread name #686)
• A custom per-thread string that can be changed during the program run, to represent which network request is currently being handled (if this is a network server).
• Function name (obtained with __func__), but with a compile time option (so release builds don't end up having those string embedded in them). Assumes use of the SPDLOG_ macros.
• Log category, specified as a file-scope variable with a particular name, again assuming use of the SPDLOG_ macros. This is perhaps a request in its own right because it would be good to be able to choose different log levels for different categories (e.g. if you are looking for a bug one component that you can turn its log level up to trace). This is analogous to the logger name in Python logging (but seems to be a bit different from the intention of spdlog logger names).

[nuertey]

Arthur-tacca,
I have a response on issue #686 that is in answer to your comment. I think it will be of interest to the folks on this thread of discussion as well.

[NuSkooler]

And example I ran into today: I wanted to use the Windows Event Log sink, but have found that it's severely limited:

• All logs in the sink get exactly one event ID. Windows Event logs should ideally have unique ID (think error code assigned to the log)
• Event Logs contain a category. In the current implementation these are simply tied to the level, but an Event Log entry already also has a severity/level.

Another example I ran into a while back is (I think) similar to the wants above with JSON: Our logs have name/value fields in them. Currently this is serialized to a string, but ideally when our sink is SystemD/journal, keeping the fields intact as individual items would be great.

[NuSkooler]

@lion10243 any update on this? I looked at your changes here: v1.x...lion10243:logmsg-meta-attrs-v1

This seems worth looking into more if nothing else.

[stegvdm]

We had the same requirement as you; logging key-value pairs of data with each log message (which were subsequently serialized to a json object and emitted to a elasticsearch/kibana logging daemon so the key-value attributes could later be indexed and searched upon alongside the log message). I haven't touched that branch for a while as I stopped working for that project / employer. The underlying principal remains the same; store a key-value hashmap along with the string log message. Unfortunately, this use case for C++ logging still appears to be relatively niche. Bryan Ashby <[email protected]> schrieb am Di., 21. Juli 2020, 21:13:

…

@lion10243 <https://github.com/lion10243> any update on this? I looked at your changes here: v1.x...lion10243:logmsg-meta-attrs-v1 <v1.x...lion10243:logmsg-meta-attrs-v1> This seems worth looking into more if nothing else. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#617 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AIQVRS5QQ6SEWOUFAW2WKO3R4XSD7ANCNFSM4EMTAHJA> .

[stegvdm]

Hi @xukaren, Take a look in my branch here... https://github.com/lion10243/spdlog/tree/master/include/spdlog The map is defined in common.h like this: using attributes_type = std::map<std::string, attr_type> where attr_type is defined using a variant type: using attr_type = std::variant<bool, int, long, float, double, std::string>;. Look for code with preprocessor define SPDLOG_ENABLE_LOG_ATTRIBUTES. In my branch the 'log attributes' (the key-value data stored with every log message; I recall the term was borrowed from Boost Log) are passed as the first parameter, so: template <typename T> void info(attributes_type &ma, const T &msg);. And I recall we wrote something in the app like obj->log({"request":"type","rid":23423342}, "my log message"); I might take a look at my branch and see if i can update it to the latest spdlog version, when I have some time. I'm happy to help if you have more questions. Best regards, Steven Am Sa., 3. Okt. 2020 um 23:26 Uhr schrieb Karen Xu <[email protected]

…

: Hi @lion10243 <https://github.com/lion10243>, How exactly is the key-value hashmap done in C++? I've tried: std::unordered_map<std::string, std::string> m = { {"Name", "truffle"}, {"Price", "299.99"}, }; spdlog::info("Logging a Map ", m); which gives an error. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#617 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AIQVRSZAAM24NKZXRSMNBK3SI6JHLANCNFSM4EMTAHJA> .

[rmanyari]

I got a very similar use case as @lion10243 , that is, ship structured JSON logs to a messaging queue. Would you guys be open to a PR that adds this functionality? Something along the lines of what's in @lion10243 fork.

[bobhansen]

Like @lion10243, we added some extensions to add structured data in spdlog and a formatter to emit the logs. We've pushed the source up at https://github.com/bobhansen/structured_spdlog#using-structured-spdlog

In this implementation, we've tried to keep the memory allocations to a minimum and keep data on the stack, passed via initializer_lists. We also have a very nice affordance for accumulating context on the stack, so txn IDs at the like can be memoized once and all associated log statements will be indexable by the information.

@lion10243 - I also initially used std::variants, but for C++11 compatibility, I fell back to a union of fundamental types. I'm intrigued by your use of mpacks reference implementation.

@gabime is there interest in adding a similar capability to the core spdlog codebase (at least as a flagged option)? The fact that multiple people have implemented it independently is a pretty good signal that there's demand for it.

[gabime]

@bobhansen Nice work. From quick glance seems you've implemented 2 features: json formatting and context (which can be used with regular formatter as well?).
I need to think about it more. Seems both features are in demand but as 2 completely independent features of each other.
btw, does the context supported for async loggers?

[bobhansen]

Thanks!

Yes, the context is supported for async loggers. There are three classes of data that are emitted: fields passed into the log call (copied into a std::vector for async loggers), thread-local context (managed using a linked list of shared_ptrs to prevent copies), and logger-based fields (which includes both static fields like build number and pattern-based fields).

The json formatter works without the structured data, but is considerably less useful.

I added an extra %V pattern formatter for structured fields; it needs a little bit of love to be able to properly express things like padding, coloring, and separator. I think you would have much better intuition on that than I do. That (and a few more things) are called out in the TODO section at https://github.com/bobhansen/structured_spdlog/#structured-todos.

I just found out I work down the hall (virtually) from the author of the fmt library. I may hit him up for some suggestions on the field passing.

[gabime]

I just found out I work down the hall (virtually) from the author of the fmt library. I may hit him up for some suggestions on the field passing.

Thats cool. If you see him say Hi :)

[stegvdm]

Hi @bobhansen, late reply.... That's some nice work in your approach, I'm impressed. I'd definitely recommend anyone following this thread to take serious consideration of your work instead of my old branch, especially as yours focuses on raw performance and its up-to-date. I chose mpacks reference implementation as it provided the minimum c++11 compatibility, even though then the app we were building was c++14. Best regards, Steven bobhansen ***@***.***> schrieb am Do., 20. Jan. 2022, 18:46:

…

Like @lion10243 <https://github.com/lion10243>, we added some extensions to add structured data in spdlog and a formatter to emit the logs. We've pushed the source up at https://github.com/bobhansen/structured_spdlog#using-structured-spdlog In this implementation, we've tried to keep the memory allocations to a minimum and keep data on the stack, passed via initializer_lists. We also have a very nice affordance for accumulating context on the stack, so txn IDs at the like can be memoized once and all associated log statements will be indexable by the information. @lion10243 <https://github.com/lion10243> - I also initially used std::variants, but for C++11 compatibility, I fell back to a union of fundamental types. I'm intrigued by your use of mpacks reference implementation. @gabime <https://github.com/gabime> is there interest in adding a similar capability to the core spdlog codebase (at least as a flagged option)? The fact that multiple people have implemented it independently is a pretty good signal that there's demand for it. — Reply to this email directly, view it on GitHub <#617 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AIQVRS6SPRP77WGZMMSJKVDUXBC7LANCNFSM4EMTAHJA> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>. You are receiving this because you were mentioned.Message ID: ***@***.***>

[lp35]

Hi @bobhansen !

I was starting to implement the same code as you in the log_msg when I found your repo.
Your fork add a very nice feature to SPDLOG, that allows more control on log in program using modular architecture (like plugin for example!).

I think your code should be added to the main repository as it brings a really nice flexibility for not that much cost.

@gabime do you think this could be acceptable for to merge this in the master branch?

Cheers!

[bachittle]

I think that adding json support is overkill, as one could achieve a similar level of structured logging with a format like logfmt using the pattern matching already built into spdlog. For example:

std::string logfmt_pattern = "time=%Y-%m-%dT%H:%M:%S.%f%z, name=%n, level=%^%l%$, process=%P, thread=%t, message=\"%v\", ";

however, the attributes feature by form of initializer list is a good idea. I am tinkering with adding this in one of my forks for internal use, will see if its worth merging.

[bobhansen]

adding json support is overkill

For our use case, we needed to have dynamic structured logging ship out logs to a system like Prometheus, and for better or worse, json is today's universal language for data exchange.

Like many, I first tried to use a logfmt pattern to write out json, then someone put an unescaped quote into a field. Then I tried writing a custom formatter, with multiple fields encoded in a message, but that got out of hand and kept being mis-used. I eventually got to the solution in https://github.com/bobhansen/structured_spdlog, and it's been in high-volume production for the last year without too much complaint.

[gabime]

Implemented in pr #2907