ostream_log_msg_writer.hpp

Go to the documentation of this file.

/* Flow
 * Copyright 2023 Akamai Technologies, Inc.
 *
 * Licensed under the Apache License, Version 2.0 (the
 * "License"); you may not use this file except in
 * compliance with the License.  You may obtain a copy
 * of the License at
 *
 *   https://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in
 * writing, software distributed under the License is
 * distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR
 * CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing
 * permissions and limitations under the License. */
 
/// @file
#pragma once
 
#include "flow/log/log_fwd.hpp"
/* Subtlety: The following is technically not required -- log_fwd.hpp is enough to fwd-declare Config, and we
 * only mention Config* here.  However in practice we are likely indirectly included by a *_logger.hpp, and guys such
 * as (e.g.) Simple_ostream_logger all take Config* as ctor arg, and in practice the user almost always will want
 * to instantiate a Config and thus require the following header file.  Of course, we could just make them
 * #include it themselves, and generally that is fine/good/a goal of _fwd.hpp pattern.  (Even if the user is
 * directly using Ostream_log_msg_writer, the same reasoning applies: probably they need to instantiate a Config.)
 * So just for convenience for the vast majority of users, just give 'em this.  (Truthfully this is partially to
 * avoid breaking some user code written before the _fwd.hpp pattern was applied to Flow.  However in my (ygoldfel)
 * opinion it would still be a decent argument even without that. */
#include "flow/log/config.hpp"
#include <array>
// Normally we use boost.chrono in Flow; see explanation in class doc header below re. why std::chrono here.
#include <chrono>
#include <ostream>
#include <boost/io/ios_state.hpp>
#include <vector>
 
namespace flow::log
{
 
// Types.
 
/**
 * Utility class, each object of which wraps a given `ostream` and outputs discrete messages to it adorned with time
 * stamps and other formatting such as separating newlines.  A Config object controls certain aspects of its behavior;
 * pass this to the constructor.  The Config may come from the user as passed to the Logger (if any) using `*this`;
 * or that Logger (if any) can make its own from scratch.
 *
 * It is assumed that between the first and last calls to log() no other code whatsoever writes to the underlying
 * stream (as passed to ctor) at any point -- including any formatters.  At `*this` destruction formatter state
 * is restored.
 *
 * ### Rationale ###
 * This optional (but recommended for most Logger implementations, though technically not limited to their use)
 * utility class typically sits between some "physical" output medium -- a buffer in memory, a file, etc. --
 * that can be written to using an `ostream` (e.g., `std::ostringstream`, util::String_ostream, `std::ofstream`);
 * and a Logger implementation that promises to output log messages to that output medium.  When Logger::do_log()
 * is called, the message string passed to it will contain the user's original message plus various Msg_metadata
 * nuggets (like time stamp, severity, source code location) either generated by FLOW_LOG_WITHOUT_CHECKING()
 * implementation or provided by user.  The idea is the Logger is to decide on the output format of the various
 * metadata plus the message.  Therefore, the present class outputs all those pieces (as appropriate) plus
 * separating newlines.  Any Logger is free to use any format it wants; and some `Logger`s might not even generate
 * any output character stream but rather forward everything elsewhere (maybe even over the network); but
 * Ostream_log_msg_writer provides a reasonable output format to a character stream, to be used or not as desired.
 *
 * ### Thread safety ###
 * For a given `*this`, the class is not safe for concurrent calls to log().  The using code must provide any such
 * guarantees.
 *
 * See thread safety notes and to-dos regarding config in Simple_ostream_logger doc header.  These apply here also.
 *
 * @internal
 * Impl notes
 * ----------
 * ### Human-readable time stamps, caching ###
 * At least optionally, log() adds a human-readable time stamp readout with the date, time (including seconds.usec
 * or better), and time zone.  Just getting that in a decent, predictable form, without localized weirdness, and
 * with sub-second precision can be non-trivial; `std::chrono` does not do it as of C++17; boost.chrono does but
 * only as of a certain quietly added features called time-point I/O v2 (as opposed to v1).  That in itself was
 * workable; however:
 *
 * When logging volume is very high, processor use by logging can be high, and as a percentage of cycles used,
 * we noticed that a high proportion was used in formatting the `time_point` into the `ostream` by boost.chrono.
 * Therefore we eventually moved to fmt, an output formatting library that is lightning-fast and whose API is
 * now folded into C++20 standard lib (as of this writing we are on C++17); not unlike boost.chrono long ago became
 * `std::chrono`.  fmt provides flexibly formattable `time_point` output as well, so we can get everything we want
 * just how we want it (in contrast with boost.chrono where it was merely a stroke of luck that the output
 * was acceptable).
 *
 * Moreover, we accomplish a slight additional speedup by *caching* the formatted output across log() calls;
 * in each log() printing it up to but excluding seconds; then adding the seconds plus sub-seconds in a separate,
 * less expensive fmt call.  The cached output needs to be updated once the previous cached value is no longer
 * applicable even up to the precision that is actually used.
 *
 * ### Why standard library time-points instead of boost.chrono? ###
 * In the rest of Flow we tend to prefer boost.chrono to `std::chrono`; they are extremely similar, but
 * boost.chrono adds a few features including some extra clocks which are useful.  However fmt accepts `std::chrono`
 * time points, so for this specific purpose we store an `std::chrono` time point in Msg_metadata.  At that point
 * it was also reasonable to just use `std::chrono` for other time-related needs in this small class.
 */
class Ostream_log_msg_writer :
  private boost::noncopyable
{
public:
  // Types.
 
  // Constructors/destructor.
 
  /**
   * Constructs object wrapping the given `ostream`.  Does not write any characters to stream (so, for instance,
   * if it happens to be an `ofstream` then it is fine if it's not yet open or even associated with a path).  It may
   * however do stateful things such as format setting.
   *
   * If any non-default formatting has been applied to `os`, subsequent behavior is undefined.
   *
   * @param config
   *        Controls behavior of `*this`.  See thread safety notes in class doc header.
   *        This is saved *by reference* inside `*this`; it must remain valid through the last log() call.
   * @param os
   *        Stream to which to write subsequently via log().
   */
  explicit Ostream_log_msg_writer(const Config& config, std::ostream& os);
 
  /// Restores formatting state of `os` to how it was before entry to constructor.
  ~Ostream_log_msg_writer() noexcept;
 
  // Methods.
 
  /**
   * Logs to the wrapped `ostream` the given message and associated metadata like severity and time stamp; plus
   * a newline.
   *
   * @param metadata
   *        See `*metadata` in Logger::do_log().
   * @param msg
   *        The message.  No terminating newline is assumed (though there is no rule against it; but
   *        if one is present, a blank line will appear in wrapped `ostream`).
   */
  void log(const Msg_metadata& metadata, util::String_view msg);
 
private:
 
  // Types.
 
  /// Short-hand for an `ostream` state saver.
  using Ostream_state = boost::io::ios_all_saver;
 
  // Methods.
 
  /**
   * log() implementation with time stamp = seconds.microseconds since Epoch.
   *
   * @param metadata
   *        See log().
   * @param msg
   *        See log().
   */
  void do_log_with_epoch_time_stamp(const Msg_metadata& metadata, util::String_view msg);
 
  /**
   * log() implementation with time stamp = date/time with microsecond+ resolution/time zone, in
   * current OS time zone.
   *
   * @param metadata
   *        See log().
   * @param msg
   *        See log().
   */
  void do_log_with_human_friendly_time_stamp(const Msg_metadata& metadata, util::String_view msg);
 
  /**
   * Remainder of log() functionality after either do_log_with_epoch_time_stamp() or
   * do_log_with_human_friendly_time_stamp(), once either has logged the time stamp.
   *
   * @param metadata
   *        See log().
   * @param msg
   *        See log().
   */
  void log_past_time_stamp(const Msg_metadata& metadata, util::String_view msg);
 
  // Constants.
 
  /// Mapping from Sev to its brief string description.
  static const std::vector<util::String_view> S_SEV_STRS;
 
  /// Jan 1, 1970, 00:00.
  static const boost::chrono::system_clock::time_point S_POSIX_EPOCH;
 
  /// Example human-readable time stamp output, up to but excluding seconds, for compile-time size calculations.
  static constexpr util::String_view S_HUMAN_FRIENDLY_TIME_STAMP_MIN_SZ_TEMPLATE{"2024-02-05 22:09:"};
 
  /**
   * Example human-readable time stamp output, starting with seconds, for compile-time size calculations.
   *
   * ### Subtlety ###
   * fmt docs say `%S` will use the precision "available"; in practice in our tested Linuxes it is
   * nanoseconds; in the past I (ygoldfel) have also seen microseconds printed in this situation; might be
   * some artifact of an internal time-formatting system API; whatever.  However, it is unlikely it will in
   * practice be better than nanoseconds; hence for our size-reserving purposes the template string with
   * nanoseconds should suffice.
   *
   * (It also says that if there is no sub-second value, then it won't print the sub-second portion; but this
   * appears to be poorly worded documentation: It prints `.000000000` just fine.)
   */
  static constexpr util::String_view S_HUMAN_FRIENDLY_TIME_STAMP_REST_SZ_TEMPLATE{"31.357246045 +0000 "};
 
  // Data.
 
  /// Reference to the config object passed to constructor.  See notes on thread safety.
  const Config& m_config;
 
  /// Pointer to function that log() will forward to when invoked.
  const Function<void (Ostream_log_msg_writer*, const Msg_metadata&, util::String_view)> m_do_log_func;
 
  /// Reference to stream to which to log messages.
  std::ostream& m_os;
 
  /// Formatter state of #m_os at construction.  Used at least in destructor (as of this writing) to restore it.
  Ostream_state m_clean_os_state;
 
  /// Buffer storing the last log() time stamp in human-friendly form, including a NUL at the end.
  std::array<char, S_HUMAN_FRIENDLY_TIME_STAMP_MIN_SZ_TEMPLATE.size()
                   + S_HUMAN_FRIENDLY_TIME_STAMP_REST_SZ_TEMPLATE.size() + 1>
    m_last_human_friendly_time_stamp_str;
 
  /// Length of string in #m_last_human_friendly_time_stamp_str (excluding any NUL).
  size_t m_last_human_friendly_time_stamp_str_sz;
 
  /**
   * As used in the caching-for-perf algorithm in do_log_with_human_friendly_time_stamp(),
   * this is the seconds-precision version of high-precision Msg_metadata::m_called_when, when
   * do_log_with_human_friendly_time_stamp() last had to perform full formatted-output into
   * #m_last_human_friendly_time_stamp_str.
   */
  std::chrono::time_point<std::chrono::system_clock, std::chrono::seconds> m_cached_rounded_time_stamp;
}; // class Ostream_log_msg_writer
 
} // namespace flow::log