Flow 1.0.2
Flow project: Full implementation reference.
Public Member Functions | Static Public Member Functions | Static Private Attributes | List of all members
flow::log::Logger Class Referenceabstract

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:
[legend]
Collaboration diagram for flow::log::Logger:
[legend]

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. More...
 
 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_holderoperator= (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...
 

Static Private Attributes

static boost::thread_specific_ptr< std::string > s_this_thread_nickname_ptr
 Thread-local storage for each thread's logged name (null pointer, which is default, means no nickname stored). 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. More...
 

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:

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:

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:

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.

Definition at line 1287 of file log.hpp.

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
metadataAll information to potentially log in addition to msg.
msgThe 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, flow::log::Serial_file_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.)

The "certain C++ limitations" are that FLOW_LOG_WITHOUT_CHECKING() must access it, but it is a macro and cannot be involved in friendship. A contrived way to resolve it would be to make some detail/ helper free function the friend, which would call this method, and invoke that free function from the macro. All that just to move a harmless thing into private – I think not worth it, but an argument could be made.

See also
do_log().
Returns
See above.

Implemented in flow::log::Async_file_logger, flow::log::Buffer_logger, flow::log::Serial_file_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_nicknameNon-null pointer to value to modify. See above.
call_thread_idNon-null pointer to value to modify. See above.

Definition at line 125 of file log.cpp.

References s_this_thread_nickname_ptr.

Referenced by set_thread_info_in_msg_metadata().

Here is the caller graph for this function:

◆ 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_metadataNon-null pointer to structure to modify. See above.

Definition at line 144 of file log.cpp.

References flow::log::Msg_metadata::m_call_thread_id, flow::log::Msg_metadata::m_call_thread_nickname, and set_thread_info().

Here is the call graph for this function:

◆ 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
sevSeverity of the message.
componentComponent 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, flow::log::Serial_file_logger, and flow::log::Simple_ostream_logger.

Referenced by flow::async::asio_exec_ctx_post(), flow::perf::Checkpointing_timer::Checkpointing_timer(), flow::net_flow::Low_lvl_packet::create_from_raw_data_packet(), flow::util::Basic_blob< Allocator, S_SHARING_ALLOWED >::emplace_copy(), flow::util::Basic_blob< Allocator, S_SHARING_ALLOWED >::make_zero(), flow::util::Basic_blob< Allocator, S_SHARING_ALLOWED >::reserve(), flow::util::Basic_blob< Allocator, S_SHARING_ALLOWED >::share(), flow::util::Basic_blob< Allocator, S_SHARING_ALLOWED >::share_after_split_equally_impl(), flow::util::Basic_blob< Allocator, S_SHARING_ALLOWED >::share_after_split_left(), flow::util::Basic_blob< Allocator, S_SHARING_ALLOWED >::share_after_split_right(), flow::net_flow::Drop_timer::start_timer(), flow::util::Basic_blob< Allocator, S_SHARING_ALLOWED >::sub_copy(), and flow::util::Basic_blob< Allocator, S_SHARING_ALLOWED >::swap_impl().

Here is the caller graph for this function:

◆ 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
osStream to which to write thread's name.
Returns
os.

Definition at line 108 of file log.cpp.

References s_this_thread_nickname_ptr.

◆ 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);
#define FLOW_LOG_WARNING(ARG_stream_fragment)
Logs a WARNING message into flow::log::Logger *get_logger() with flow::log::Component get_log_compone...
Definition: log.hpp:152

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.

Definition at line 150 of file log.cpp.

References flow::log::Thread_local_string_appender::appender_ostream(), and flow::log::Thread_local_string_appender::get_this_thread_string_appender().

Referenced by flow::log::beautify_chrono_logger_this_thread().

Here is the call graph for this function:
Here is the caller graph for this function:

◆ 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:
  • 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_nicknameNew 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_ptrIf 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_nameIf 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.

Definition at line 36 of file log.cpp.

References FLOW_ERROR_SYS_ERROR_LOG_WARNING, FLOW_LOG_INFO, FLOW_LOG_SET_CONTEXT, FLOW_LOG_WARNING, flow::util::ostream_op_string(), and s_this_thread_nickname_ptr.

Here is the call graph for this function:

Member Data Documentation

◆ s_this_thread_nickname_ptr

boost::thread_specific_ptr< std::string > flow::log::Logger::s_this_thread_nickname_ptr
staticprivate

Thread-local storage for each thread's logged name (null pointer, which is default, means no nickname stored).

Definition at line 1561 of file log.hpp.

Referenced by set_thread_info(), this_thread_logged_name_os_manip(), and this_thread_set_logged_nickname().


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