flow::log::Logger Class Reference

Interface that the user should implement, passing the implementing Logger into logging classes (Flow's own classes like net_flow::Node; and user's own logging classes) at construction (plus free/static logging functions). More...

#include <log.hpp>

Inheritance diagram for flow::log::Logger:

Collaboration diagram for flow::log::Logger:

Public Member Functions
virtual bool	should_log (Sev sev, const Component &component) const =0
	Given attributes of a hypothetical message that would be logged, return true if that message should be logged and false otherwise (e.g., if the verbosity of the message is above the current configured verbosity threshold for the Component specified). More...
virtual bool	logs_asynchronously () const =0
	Must return true if do_log() at least sometimes logs the given message and metadata (e.g., time stamp) after do_log() returns; false if this never occurs (i.e., it logs synchronously, always). More...
virtual void	do_log (Msg_metadata *metadata, util::String_view msg)=0
	Given a message and its severity, logs that message and possibly severity WITHOUT checking whether it should be logged (i.e., without performing logic that should_log() performs). More...
std::ostream *	this_thread_ostream () const
	Returns the stream dedicated to the executing thread and this Logger, so that the caller can apply state-setting formatters to it. More...
Public Member Functions inherited from flow::util::Null_interface
virtual	~Null_interface ()=0
	Boring virtual destructor. More...
Public Member Functions inherited from flow::util::Unique_id_holder
	Unique_id_holder ()
	Thread-safely construct an ID whose value is different from any other object of this class, past or future.
	Unique_id_holder (const Unique_id_holder &)
	This copy constructor is identical in behavior to Unique_id_holder(), the default ctor. More...
id_t	unique_id () const
	Raw unique ID identifying this object as well as any object of a derived type. More...
const Unique_id_holder &	operator= (const Unique_id_holder &) const
	This assignment operator is a const no-op. More...

Static Public Member Functions
static void	this_thread_set_logged_nickname (util::String_view thread_nickname=util::String_view(), Logger *logger_ptr=0, bool also_set_os_name=true)
	Sets or unsets the current thread's logging-worthy string name; optionally sets the OS thread name (such as visible in top output). More...
static std::ostream &	this_thread_logged_name_os_manip (std::ostream &os)
	ostream manipulator function that, if output via operator<< to an ostream, will cause the current thread's logging-worthy string name to be output to that stream. More...
static void	set_thread_info_in_msg_metadata (Msg_metadata *msg_metadata)
	Loads msg_metadata->m_call_thread_nickname (if set) or else msg_metadata->m_call_thread_id, based on whether/how this_thread_set_logged_nickname() was last called in the current thread. More...
static void	set_thread_info (std::string *call_thread_nickname, flow::util::Thread_id *call_thread_id)
	Same as set_thread_info_in_msg_metadata() but targets the given two variables as opposed to a Msg_metadata. More...
Static Public Member Functions inherited from flow::util::Unique_id_holder
static id_t	create_unique_id ()
	Short-hand for Unique_id_holder().unique_id(); useful when all you want is the unique integer itself. More...

Additional Inherited Members
Public Types inherited from flow::util::Unique_id_holder
using	id_t = uint64_t
	Raw integer type to uniquely identify a thing. 64-bit width should make overflow extremely hard to reach.

Detailed Description

Interface that the user should implement, passing the implementing Logger into logging classes (Flow's own classes like net_flow::Node; and user's own logging classes) at construction (plus free/static logging functions).

The class (or function) will then implicitly use that Logger in the logging apparatus (such as FLOW_LOG_...() macros) to log messages into the user's preferred logging output(s). One can think of the class implementing this interface as the glue between Flow logging and either the user's lower-level logging system or some output device (like console, files) directly.

The reason should_log() and do_log() are decoupled like this is for a fast implementation of the FLOW_LOG_...() macros (see FLOW_LOG_WITH_CHECKING() in particular).

There is also a small set of app-wide (static) utilities, including the ability to nickname any given thread, which causes that nickname (instead of the thread ID) to be logged in subsequent log messages.

Stream continuity (and threads)

As slightly advanced ostream users know, an ostream carries state that can be set via explicit method calls such as ostream::setf() and via "printing" manipulators such as std::hex to a given ostream. Regular values printed to ostream will come out differently depending on the current state (e.g., << 14 may show up as a decimal or a hex integer depending on preceding formatters). If you use these state-affecting features, be aware of the following semantics:

• The system works as if there is exactly one ostream for every distinct combination (logger, T), where:
  • logger is a distinct Logger object, as identified by the address in its Logger::this pointer.
  • T is a distinct thread such that the API user has previously, at least once, invoked a logging API that works with Logger ostreams – from that thread. (The APIs that qualify are essentially various APIs that actually log messages or attempt to set formatting for subsequent messages or are used to subsequently do either.)
• One can think of a given (logger, T) combo's ostream as being created on-demand the first time a given Logger logger attempts to do something logging-related from a given thread T. Subsequently, with that combo used again and again, the stream is internally looked up with high performance. The on-demand creation is slower but relatively rare given the low expected count of threads and Loggers.
• Any stream state change carried by a user API call for a given distinct (as defined above) stream S:
  • will persistently affect the subsequent output of any subsequent log message payload on stream S, including the same log message following the given state change, and including any subsequent log messages;
  • will not affect any stream other than S;
  • will not affect any intra-message prefixes or suffixes (such as originating file, function, line that may be inserted before every log message automatically) added by the Logger API implementation.
• There are essentially two ways to affect state of stream S. Either one must be invoked from the thread T pertaining to stream S, and the Logger object involved must also be the one pertaining to S.
  • The state change may be part of the sequence of operator<<() operands passed to a logging API. However, note that for it to take effect, it must not be filtered out by a Sev filter check (basically, the containing log message must actually end up in the log, not filtered away).
    • In this case, the state change must be via a manipulator formatter like std::setfill, std::hex, boost::chrono::seconds, etc.
  • The state change may be a direct call invoked on a given ostream S, where to get access to S one would call Logger::this_thread_ostream() to receive the pointer ‘&S’, for the current thread and the Logger on which the method is executed. Once you have S, you may call state manipulators such as S.setf(); or, again, manipulators via S << std::hex; and similar.
    • Using this_thread_ostream() for any purpose other than to change stream state (i.e., to output actual characters, like S << "Hello, world!";) will result in undefined behavior. Do not. Use logging APIs for that.
• Even if the Logger implementation uses ostream for ultimate output of characters (and it absolutely does not have to do any such thing), that ostream is totally orthogonal and irrelevant to the one being discussed here. E.g., Simple_ostream_logger may print to std::cout, but the formatters we are discussing affect a totally different, internal stream, not that std::cout. In fact, the internal stream is in memory, not file/console/whatever. I point this out only to avoid confusion.

Basic suggested strategy for implementing a Logger

The simplicity of the Logger interface, and the lack of mandatory rigidity in how one might configure it (particularly w/r/t per-Component verbosity and output format), assures the sky is the limit for how one implements their own custom Logger. However, in the absence of great reasons not to, we suggest one follows the lead of out-of-the-box existing Loggers in Flow, which adds a degree of rigidity as to the implementation but also seems to provide all the features seemingly commonly desired in practice. Namely, like (say) Simple_ostream_logger, Buffer_logger, and Async_file_logger, do this:

• Take a Config pointer at constructor and save it (do not copy the Config). (There are thread safety implications.)
• Internally use some kind of ostream-subclass member to a target device, if at all possible. (boost.asio will let you even write to network this way; but at least console output, file output, and memory string output are 100% practical via ostreams. Existing Loggers provide examples.)
• Internally use an Ostream_log_msg_writer to write to said ostream, the formatting thereof being configurable in a uniform way via the saved Config.
• Forward should_log() logic to the saved Config (Config::output_whether_should_log()), so that verbosity is flexibly but uniformly set via Config.
• It is up to the user, now, to set up the Config appropriately when passing it to your Logger subclass constructor. The user would simply follow the documentation for Config, and you need neither re-implement nor re-document configurability of your Logger.

Reminder: Config and Ostream_log_msg_writer are optional to use, and one can use one, both, or neither (though the latter itself does expect one of the former; of course you can just load up your own new Config, in case you don't want to use a user Config taken via your constructor API). However, unless there's something insufficient about them, various benefits abound in using both. Furthermore, if something is lacking, consider extending that system to the benefit of all/most other Loggers as opposed to throwing it away and re-implementing something new for just your new Logger.

Having decided on that stuff, you also need to decide whether you will write to the output device/whatever synchronously or asynchronously. To wit, the thread safety discussion:

Thread safety

The degree of thread safety for either of the 2 main operations is completely up to the subclass implementer. Informally, we suggest here that you think about this topic carefully. In particular, without locking, do_log() may run concurrently with itself from multiple threads; depending on the medium to which it is writing, this may result in corruption or ugly output or turn out fine, depending on how you define "fine." Whether this is a concern or not is up to you. Note, however, that in practice as of this writing at least one Flow module (flow::net_flow) will definitely potentially execute should_log() and do_log() concurrently with themselves from multiple threads on the same Logger. In general that should be expected in all but the simplest single-threaded apps.

Implementation suggestions for Logger subclasses with respect to thread safety: There are 2 likeliest patterns one can use.

1. One can use a mutex lock around actual writing to the target device. There's nothing inherently un-performant about this, in an of itself, and the implementation is incredibly simple. For example see Simple_ostream_logger. However, there is a significant performance danger if the device-writing itself can be both synchronous and slow. In particular, a file write (when flushing any buffer such as the internal one in FILE* or ofstream), which is likely after each message, is usually synchronous and can be sporadically slow (consider having to spin up a sleeping hard drive for instance). That would not only block the log-call-site thread but also any competing logging threads at that time. That is probably fine in many non-production scenarios, but in a production heavy-duty server it's not OK.
   • An informal suggestion: It is fine for console output, probably (standard out, standard err). Otherwise, particularly with files and synchronous networking, don't. Use the following instead:
2. One can avoid any such lock; instead the log-call-site thread can save the stuff to log (including the message and Msg_metadata passed to do_log()) and pass it to a dedicated thread (or pool thereof, etc.) in charge of asynchronously queueing up stuff to write to device and actually writing it in the order received at some later time (though typically fairly soon and definitely ASAP in most cases). This is a bit more complex, but with flow::async it's really pretty easy still. See the heavy-duty Async_file_logger for example.

Both general patterns are formally supported. To use pattern 1, have your Logger implementation's logs_asynchronously() return false. To use pattern 2, have it use true. The precise implications are documented in doc header of do_log().

Order of output requirements

We assume for this discussion that the notion of order of final output (to device/file/network/whatever) exists, and that the Logger implementation indeed safely outputs message M1 entirely before M2, or vice versa, for every pair of messages (in this context by message we mean message+metadata pair) ever passed to do_log(). With that assumption in effect (IF indeed it is), the present text requires that the following is guaranteed:

• In a given thread T, for a given Logger L, if L.do_log(M1); is called before L.do_log(M2), and both are successfully output by L, then the final output order must have M1 precede M2, not vice versa.
• If, instead, M1 is logged in thread T1, while M2 is logged in thread T2:
  • If the 2 do_log() calls are chronologically disjoint, then again the final output must also have M1 precede M2 if M1 went first; and vice versa.
  • If the 2 do_log() calls chronologically overlap, then either final output order is acceptable. (Ideally, it should reflect the order of entry to do_log() in the 2 threads, but it's formally optional. Informally this typically will happen anyway under most basic algorithms imaginable.)

Note that this is only tangentially related to any time stamps one might see in the final output.

See also notes on log output order in FLOW_LOG_WARNING() doc header (which applies to all log call sites). The behavior described there is a function of the underlying Logger following the above formal requirements for thread-safe Logger implementations.

Member Function Documentation

do_log()

virtual void flow::log::Logger::do_log ( Msg_metadata *  metadata, util::String_view  msg  )

pure virtual

Given a message and its severity, logs that message and possibly severity WITHOUT checking whether it should be logged (i.e., without performing logic that should_log() performs).

The logging is guaranteed to be synchronous if !logs_asynchronously(); but may be asynchronous otherwise (more on this below).

The convenience macros FLOW_LOG_...() combine this with should_log() to make it so that a message is only constructed if should_log() == true, and if so, constructs and logs it; otherwise almost no computing or storage resources are spent, and the message is not logged.

Expectations of what should or should not be included in msg are of some importance. They are as follows. To summarize, msg should include the message (as specified typically as the ARG_stream_fragment arg to FLOW_LOG_WARNING() and buddies); and *msg_metadata should include everything else. This design provides maximum flexibility to the Logger::do_log() implementation to structure the final output's contents (in the log file, or console, or wherever) as it sees fit, cosmetically and size-wise.

Note on trailing newline(s): msg must include any trailing newline(s) that are required to be output. By convention, do_log() itself will print a message terminator (often in fact a newline) after each message, if applicable. Hence typically there is no trailing newline at the end of most msgs, and one would include N of them if and only if one intentionally desires N trailing blank lines (possible but atypical).

Precise meaning of logs_asynchronously()

Let ASYNC = the value logs_asynchronously() returns (note for a given *this it must always be the same value by that API's contract). Then do_log() must act as follows:

• If ASYNC is false: Do not make a copy of msg; output it synchronously. Do not make a copy of *metadata. Do not delete metadata. Output any of its contents synchronously.
• If ASYNC is true: Optionally make a copy of msg, unless you are able to output it synchronously, in which case there is no need. Do not make a copy of *metadata. You must delete metadata at some point; failing to do so will leak it. (Note: We are intentionally avoiding using shared_ptr or even unique_ptr, for the perf savings, since logging is ubiquitous.) Output *metadata contents either synchronously or asynchronously.

The only formal requirement, however, is simply: You must delete metadata; at some future point <=iff=> ASYNC is true. The other requirements just above are informal but of no less import.

See also

Msg_metadata which includes stuff not to include in msg.

Parameters

metadata	All information to potentially log in addition to msg.
msg	The message. See details above. Short version: exclude anything from metadata; exclude any ever-present terminating newline.

Implemented in flow::log::Async_file_logger, flow::log::Buffer_logger, and flow::log::Simple_ostream_logger.

logs_asynchronously()

virtual bool flow::log::Logger::logs_asynchronously ( ) const

pure virtual

Must return true if do_log() at least sometimes logs the given message and metadata (e.g., time stamp) after do_log() returns; false if this never occurs (i.e., it logs synchronously, always).

do_log() doc header formally describes the implications of this.

This must always return the same value, for a given *this.

This method is intended for internal use by the flow::log system; informally it is not expected the user will call it. Technically there is no harm in doing so. (It would have been private but cannot due to certain C++ limitations, and certain contrived ways to do it are just not worth the trouble.)

See also

do_log().

Returns

See above.

Implemented in flow::log::Async_file_logger, flow::log::Buffer_logger, and flow::log::Simple_ostream_logger.

set_thread_info()

void flow::log::Logger::set_thread_info ( std::string *  call_thread_nickname, flow::util::Thread_id *  call_thread_id  )

static

Same as set_thread_info_in_msg_metadata() but targets the given two variables as opposed to a Msg_metadata.

Todo:

It would be more consistent to rename set_thread_info() to this_thread_set_info(), since it operates in thread-local fashion. This was a naming convention oversight.

Parameters

call_thread_nickname	Non-null pointer to value to modify. See above.
call_thread_id	Non-null pointer to value to modify. See above.

set_thread_info_in_msg_metadata()

void flow::log::Logger::set_thread_info_in_msg_metadata ( Msg_metadata *  msg_metadata )

static

Loads msg_metadata->m_call_thread_nickname (if set) or else msg_metadata->m_call_thread_id, based on whether/how this_thread_set_logged_nickname() was last called in the current thread.

The two members should be set to ther default-constructed values on entry to the present function.

Todo:

It would be more consistent to rename set_thread_info_in_msg_metadata() to this_thread_set_info_in_msg_metadata(), since it operates in thread-local fashion. This was a naming convention oversight.

Parameters

msg_metadata

Non-null pointer to structure to modify. See above.

should_log()

virtual bool flow::log::Logger::should_log ( Sev  sev, const Component &  component  ) const

pure virtual

Given attributes of a hypothetical message that would be logged, return true if that message should be logged and false otherwise (e.g., if the verbosity of the message is above the current configured verbosity threshold for the Component specified).

The convenience macros FLOW_LOG_...() combine this with do_log() to make it so that a message is only built if should_log() == true, and (if so) builds and logs it; otherwise almost no computing or storage resources are spent, and the message is neither built nor logged logged. The verb "to build message" here more formally means "to execute the `ostream<<` fragment passed to macro by writing characters to some internally maintained `ostream` accordingly."

Parameters

sev	Severity of the message.
component	Component of the message. Reminder: component.empty() == true is allowed; which isn't to say it will or won't result in this method returning true, but that it will return and not act in undefined fashion.

Returns

true if it should be logged; false if it should not.

Implemented in flow::log::Async_file_logger, flow::log::Buffer_logger, and flow::log::Simple_ostream_logger.

this_thread_logged_name_os_manip()

std::ostream & flow::log::Logger::this_thread_logged_name_os_manip ( std::ostream &  os )

static

ostream manipulator function that, if output via operator<< to an ostream, will cause the current thread's logging-worthy string name to be output to that stream.

See this_thread_set_logged_nickname() for details of what this string will actually be.

Recall that an ostream manipulator is invoked in the style of endl and flush; for example: cout << endl;. It is atypical to call it directly as opposed to via the overloaded "shift" operator.

Note that typically this is not invoked directly by the user but rather used in the FLOW_LOG_...() macros' implementation guts which is the original use case and hence reason for its existence. However, there's no rule against direct uses, and it could prove useful at some point. Any use beyond logging or debugging is not recommended however (in particular, do not use to make any algorithmic decisions).

This call is safe w/r/t concurrent execution with itself and this_thread_set_logged_nickname() in other thread(s).

Parameters

os	Stream to which to write thread's name.

Returns

os.

this_thread_ostream()

std::ostream * flow::log::Logger::this_thread_ostream

(

)

const

Returns the stream dedicated to the executing thread and this Logger, so that the caller can apply state-setting formatters to it.

If you write characters to it, or otherwise do anything othen than set formatting state, or try to affect buffering behavior, behavior is undefined. Usage example:

get_logger()->this_thread_ostream()->setf(std::fixed | std::right);
*(get_logger()->this_thread_ostream()) << std::setw(2);
// *get_logger()'s subsequent messages (such as the following) from the current thread will use above formatting.
FLOW_LOG_WARNING("Let's print a number with some formatting: " << 0.5);

Note that you could just as well apply the intended formatters via regular log statements. However, there are disadvantages to that approach – but they do not always apply. The disadvantages are listed below; but the short version is you should typically use the present method if and only if you are attempting to affect subsequent logging at large, not a particular fragment of a particular message.

Formally, the disadvantages of affecting formatting state of the underlying stream via log macros:

• If the log statement is ignored due to failing a filter check, then any formatters therein will also be ignored. (However, you could use a macro that bypasses such a check. On the other hand, stylistically one would typically only do that after checking the severity manually for performance of combining several log statements with equal severities. Using it just to apply formatters is stylistically dubious.)
• If you are trying to affect subsequent logging at large, you'd hypothetically use something like FLOW_LOG_INFO_WITHOUT_CHECKING(...formatter... << ...formatter... << ...);. This is stylistically dubious, because the lack of characters being output means the severity (INFO in this case) is disregarded and is a dummy value.
• While one can pass many formatters as << operator arguments, there are others than do not use that syntax. For example, ostream::setf() is a method of std::ostream. Thus the log macros do not help.

Recall that the stream involved is completely orthogonal to any underlying stream that may be ultimately output to by Logger for the actual, ultimate output of characters. E.g., if Logger happens to be Simple_ostream_logger targeted at std::cout, the above snippet would in no way touch std::cout formatting. In fact, Logger may not even use streams for output; that is an orthogonal implementation detail.

Returns

Pointer to stream; always the same value for a given thread and different among all distinct threads.

this_thread_set_logged_nickname()

void flow::log::Logger::this_thread_set_logged_nickname ( util::String_view  thread_nickname = util::String_view(), Logger *  logger_ptr = 0, bool  also_set_os_name = true  )

static

Sets or unsets the current thread's logging-worthy string name; optionally sets the OS thread name (such as visible in top output).

The logging-worthy name is always set or unset; the OS name is modified only if also_set_os_name == true arg is set. thread_nickname can thus be set to something more descriptive than any default, such as: "native_main" or "worker_port_2231."

• The logging-worthy thread string name is accessed as follows:
  • FLOW_LOG_*() macros pass it automatically to the appropriate log::Logger. All out-of-the-box Loggers will then log either the name set here (if not blank) or the thread ID (if blank). (Custom Loggers can ignore these data and not log them; but presumably most will at least optionally log them.)
  • It can also be obtained directly via this_thread_logged_name_os_manip(), set_thread_info(), or set_thread_info_in_msg_metadata().
• The OS thread name can be accessed in various ways; including in Linux:
  • ps H -C $cmd -o pid\ tid\ cmd\ comm # The comm column will be the thread name; set $proc = process name.
  • top -H (thread mode – or just top and press H key for the same effect).

More precisely, there are 3 states for each thread: before this_thread_set_logged_nickname() is called; after it is called with blank name; and after it's called non-blank name. The semantics are as follows:

• Logging-worthy thread string name:
  • Initial: As-if this_thread_set_logged_nickname() was already called with blank name (next bullet).
  • Blank: The thread string name becomes conceptually null; and the thread ID shall be used instead.
  • Non-blank: The thread string name becomes equal to thread_nickname.
• OS thread name:
  • Initial: ps, top, etc. will show the thread name as equal to the process name.
  • Blank: ps, top, etc. will show the thread name as the thread ID (truncated to N characters, though this is unlikely to be exceeded by real thread IDs).
  • Non-blank: ps, top, etc. will show the thread name as equal to thread_nickname (truncated to N characters).
  • Note: Because "Initial" and "Blank" are necessarily not the same, it is recommended to call this_thread_set_logged_nickname() around thread creation time even if thread_nickname is blank. Then ps, top, etc. output will still be useful and possible to cross-reference with log output, say.
  • Note: Truncation will be reverse, meaning – if necessary – leading characters will be eliminated. This, in practice, tends to at least help disambiguate in case of truncation.
  • Note: N is documented in man pthread_setname_np as 15 not counting the NUL terminator. Therefore ideally keep the thread_nickname.size() to at most N.

Performance

Subsequently obtaining the nickname involves a linear string copy; the cost of this is worth considering given that this is potentially done for every single log call site, if the nickname is indeed set. However, most string implementations provide an optimization that uses a union (or equivalent) technique to store short strings in the same place as the data members (pointer, size, capacity) required for long strings; meaning such short strings cost no more to copy than an empty one does. In gcc 5, this is 15 bytes or chars, but implementations vary.

Therefore, it is actively encouraged that you keep the length of thread_nickname low. "Low" depends on the compiler, but keeping it somewhere at or under 15 characters is likely good. If you do so, the effective cost (at a log call site) will be the same as if thread_nickname.empty(), so one could not do better. Note, also, that the OS-name (in Linux) max length happens to also be 15 (see N discussion above), so there is convenient synergy there.

Thready safety

This call is safe w/r/t concurrent execution with itself and this_thread_logged_name_os_manip() in other thread(s) for a given *this. It is thread-local in nature.

Naming rationale

this_thread_set_logged_nickname() is an incomplete name, in that it (optionally) also affects the OS thread name. The function was not renamed for compatibility reasons, as the technically incomplete name is in my (ygoldfel) opinion still acceptably descriptive.

Parameters

thread_nickname	New nickname of thread; or "" to request the thread to not be nicknamed (thread ID will be used). In the "" case, no particular thread ID format should ever be assumed; it may be OS-dependent; but it can be informally assumed to be useful for thread identification purposes (probably unique per thread and somewhat readable, etc.). The non-blank value is copied and saved.
logger_ptr	If non-null, this Logger will be used to log an INFO-severity message indicating the thread ID and new nickname (conceptually: [INFO] T...nickname...: Thread ...ID... has new nickname.). If null, nothing is logged.
also_set_os_name	If and only true, thread_nickname (whether blank or not) also affects the current OS thread name. Otherwise it is not affected.

Todo:

this_thread_set_logged_nickname() could take multiple Loggers, since it is an app-wide function and potentially would want to be reflected in multiple loggers. It could take a pair of iterators or a container (in both cases, of template argument type). Arguably, though, this is overkill; as (1) most code paths deal with only one get_logger()-owning object each; (2) naming of a thread is obvious enough in subsequent logs (hence this message only calls attention to that operation plus notes the thread ID before the nickname assignment, not necessarily the most critical of information). Certainly this zero-to-one-Logger version must continue to be available for syntactic-sugary convenience, even if the to-do is performed.

---

The documentation for this class was generated from the following files:

• log/log.hpp
• log/log.cpp