16a6c8299Sjmmv // Copyright 2011 Google Inc.
26a6c8299Sjmmv // All rights reserved.
36a6c8299Sjmmv //
46a6c8299Sjmmv // Redistribution and use in source and binary forms, with or without
56a6c8299Sjmmv // modification, are permitted provided that the following conditions are
66a6c8299Sjmmv // met:
76a6c8299Sjmmv //
86a6c8299Sjmmv // * Redistributions of source code must retain the above copyright
96a6c8299Sjmmv //   notice, this list of conditions and the following disclaimer.
106a6c8299Sjmmv // * Redistributions in binary form must reproduce the above copyright
116a6c8299Sjmmv //   notice, this list of conditions and the following disclaimer in the
126a6c8299Sjmmv //   documentation and/or other materials provided with the distribution.
136a6c8299Sjmmv // * Neither the name of Google Inc. nor the names of its contributors
146a6c8299Sjmmv //   may be used to endorse or promote products derived from this software
156a6c8299Sjmmv //   without specific prior written permission.
166a6c8299Sjmmv //
176a6c8299Sjmmv // THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
186a6c8299Sjmmv // "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
196a6c8299Sjmmv // LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
206a6c8299Sjmmv // A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
216a6c8299Sjmmv // OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
226a6c8299Sjmmv // SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
236a6c8299Sjmmv // LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
246a6c8299Sjmmv // DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
256a6c8299Sjmmv // THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
266a6c8299Sjmmv // (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
276a6c8299Sjmmv // OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
286a6c8299Sjmmv 
296a6c8299Sjmmv #include "utils/logging/operations.hpp"
306a6c8299Sjmmv 
316a6c8299Sjmmv extern "C" {
326a6c8299Sjmmv #include <unistd.h>
336a6c8299Sjmmv }
346a6c8299Sjmmv 
356a6c8299Sjmmv #include <fstream>
366a6c8299Sjmmv #include <stdexcept>
376a6c8299Sjmmv #include <string>
386a6c8299Sjmmv #include <utility>
396a6c8299Sjmmv #include <vector>
406a6c8299Sjmmv 
416a6c8299Sjmmv #include "utils/datetime.hpp"
426a6c8299Sjmmv #include "utils/format/macros.hpp"
436a6c8299Sjmmv #include "utils/optional.ipp"
446a6c8299Sjmmv #include "utils/sanity.hpp"
456a6c8299Sjmmv 
466a6c8299Sjmmv namespace datetime = utils::datetime;
476a6c8299Sjmmv namespace fs = utils::fs;
486a6c8299Sjmmv namespace logging = utils::logging;
496a6c8299Sjmmv 
506a6c8299Sjmmv using utils::none;
516a6c8299Sjmmv using utils::optional;
526a6c8299Sjmmv 
536a6c8299Sjmmv 
546a6c8299Sjmmv /// The general idea for the application-wide logging goes like this:
556a6c8299Sjmmv ///
566a6c8299Sjmmv /// 1. The application starts.  Logging is initialized to capture _all_ log
576a6c8299Sjmmv /// messages into memory regardless of their level by issuing a call to the
586a6c8299Sjmmv /// set_inmemory() function.
596a6c8299Sjmmv ///
606a6c8299Sjmmv /// 2. The application offers the user a way to select the logging level and a
616a6c8299Sjmmv /// file into which to store the log.
626a6c8299Sjmmv ///
636a6c8299Sjmmv /// 3. The application calls set_persistency providing a new log level and a log
646a6c8299Sjmmv /// file.  This must be done as early as possible, to minimize the chances of an
656a6c8299Sjmmv /// early crash not capturing any logs.
666a6c8299Sjmmv ///
676a6c8299Sjmmv /// 4. At this point, any log messages stored into memory are flushed to disk
686a6c8299Sjmmv /// respecting the provided log level.
696a6c8299Sjmmv ///
706a6c8299Sjmmv /// 5. The internal state of the logging module is updated to only capture
716a6c8299Sjmmv /// messages that are of the provided log level (or below) and is configured to
726a6c8299Sjmmv /// directly send messages to disk.
736a6c8299Sjmmv ///
746a6c8299Sjmmv /// The call to set_inmemory() should only be performed by the user-facing
756a6c8299Sjmmv /// application.  Tests should skip this call so that the logging messages go to
766a6c8299Sjmmv /// stderr by default, thus generating a useful log to debug the tests.
776a6c8299Sjmmv 
786a6c8299Sjmmv 
796a6c8299Sjmmv namespace {
806a6c8299Sjmmv 
816a6c8299Sjmmv 
826a6c8299Sjmmv /// Current log level.
836a6c8299Sjmmv static logging::level log_level = logging::level_debug;
846a6c8299Sjmmv 
856a6c8299Sjmmv 
866a6c8299Sjmmv /// Indicates whether set_persistency() will be called automatically or not.
876a6c8299Sjmmv static bool auto_set_persistency = true;
886a6c8299Sjmmv 
896a6c8299Sjmmv 
906a6c8299Sjmmv /// First time recorded by the logging module.
916a6c8299Sjmmv static optional< datetime::timestamp > first_timestamp = none;
926a6c8299Sjmmv 
936a6c8299Sjmmv 
946a6c8299Sjmmv /// In-memory record of log entries before persistency is enabled.
956a6c8299Sjmmv static std::vector< std::pair< logging::level, std::string > > backlog;
966a6c8299Sjmmv 
976a6c8299Sjmmv 
986a6c8299Sjmmv /// Stream to the currently open log file.
99*ab619639Slukem static std::unique_ptr< std::ofstream > logfile;
1006a6c8299Sjmmv 
1016a6c8299Sjmmv 
1026a6c8299Sjmmv /// Constant string to strftime to format timestamps.
1036a6c8299Sjmmv static const char* timestamp_format = "%Y%m%d-%H%M%S";
1046a6c8299Sjmmv 
1056a6c8299Sjmmv 
1066a6c8299Sjmmv /// Converts a level to a printable character.
1076a6c8299Sjmmv ///
1086a6c8299Sjmmv /// \param level The level to convert.
1096a6c8299Sjmmv ///
1106a6c8299Sjmmv /// \return The printable character, to be used in log messages.
1116a6c8299Sjmmv static char
level_to_char(const logging::level level)1126a6c8299Sjmmv level_to_char(const logging::level level)
1136a6c8299Sjmmv {
1146a6c8299Sjmmv     switch (level) {
1156a6c8299Sjmmv     case logging::level_error: return 'E';
1166a6c8299Sjmmv     case logging::level_warning: return 'W';
1176a6c8299Sjmmv     case logging::level_info: return 'I';
1186a6c8299Sjmmv     case logging::level_debug: return 'D';
1196a6c8299Sjmmv     default: UNREACHABLE;
1206a6c8299Sjmmv     }
1216a6c8299Sjmmv }
1226a6c8299Sjmmv 
1236a6c8299Sjmmv 
1246a6c8299Sjmmv }  // anonymous namespace
1256a6c8299Sjmmv 
1266a6c8299Sjmmv 
1276a6c8299Sjmmv /// Generates a standard log name.
1286a6c8299Sjmmv ///
1296a6c8299Sjmmv /// This always adds the same timestamp to the log name for a particular run.
1306a6c8299Sjmmv /// Also, the timestamp added to the file name corresponds to the first
1316a6c8299Sjmmv /// timestamp recorded by the module; it does not necessarily contain the
1326a6c8299Sjmmv /// current value of "now".
1336a6c8299Sjmmv ///
1346a6c8299Sjmmv /// \param logdir The path to the directory in which to place the log.
1356a6c8299Sjmmv /// \param progname The name of the program that is generating the log.
1366a6c8299Sjmmv fs::path
generate_log_name(const fs::path & logdir,const std::string & progname)1376a6c8299Sjmmv logging::generate_log_name(const fs::path& logdir, const std::string& progname)
1386a6c8299Sjmmv {
1396a6c8299Sjmmv     if (!first_timestamp)
1406a6c8299Sjmmv         first_timestamp = datetime::timestamp::now();
1416a6c8299Sjmmv     // Update doc/troubleshooting.texi if you change the name format.
1426a6c8299Sjmmv     return logdir / (F("%s.%s.log") % progname %
1436a6c8299Sjmmv                      first_timestamp.get().strftime(timestamp_format));
1446a6c8299Sjmmv }
1456a6c8299Sjmmv 
1466a6c8299Sjmmv 
1476a6c8299Sjmmv /// Logs an entry to the log file.
1486a6c8299Sjmmv ///
1496a6c8299Sjmmv /// If the log is not yet set to persistent mode, the entry is recorded in the
1506a6c8299Sjmmv /// in-memory backlog.  Otherwise, it is just written to disk.
1516a6c8299Sjmmv ///
1526a6c8299Sjmmv /// \param message_level The level of the entry.
1536a6c8299Sjmmv /// \param file The file from which the log message is generated.
1546a6c8299Sjmmv /// \param line The line from which the log message is generated.
1556a6c8299Sjmmv /// \param user_message The raw message to store.
1566a6c8299Sjmmv void
log(const level message_level,const char * file,const int line,const std::string & user_message)1576a6c8299Sjmmv logging::log(const level message_level, const char* file, const int line,
1586a6c8299Sjmmv              const std::string& user_message)
1596a6c8299Sjmmv {
1606a6c8299Sjmmv     const datetime::timestamp now = datetime::timestamp::now();
1616a6c8299Sjmmv     if (!first_timestamp)
1626a6c8299Sjmmv         first_timestamp = now;
1636a6c8299Sjmmv 
1646a6c8299Sjmmv     if (auto_set_persistency) {
1656a6c8299Sjmmv         // These values are hardcoded here for testing purposes.  The
1666a6c8299Sjmmv         // application should call set_inmemory() by itself during
1676a6c8299Sjmmv         // initialization to avoid this, so that it has explicit control on how
1686a6c8299Sjmmv         // the call to set_persistency() happens.
1696a6c8299Sjmmv         set_persistency("debug", fs::path("/dev/stderr"));
1706a6c8299Sjmmv         auto_set_persistency = false;
1716a6c8299Sjmmv     }
1726a6c8299Sjmmv 
1736a6c8299Sjmmv     if (message_level > log_level)
1746a6c8299Sjmmv         return;
1756a6c8299Sjmmv 
1766a6c8299Sjmmv     // Update doc/troubleshooting.texi if you change the log format.
1776a6c8299Sjmmv     const std::string message = F("%s %s %s %s:%s: %s") %
1786a6c8299Sjmmv         now.strftime(timestamp_format) % level_to_char(message_level) %
1796a6c8299Sjmmv         ::getpid() % file % line % user_message;
1806a6c8299Sjmmv     if (logfile.get() == NULL)
1816a6c8299Sjmmv         backlog.push_back(std::make_pair(message_level, message));
1826a6c8299Sjmmv     else {
1836a6c8299Sjmmv         INV(backlog.empty());
1846a6c8299Sjmmv         (*logfile) << message << '\n';
1856a6c8299Sjmmv         (*logfile).flush();
1866a6c8299Sjmmv     }
1876a6c8299Sjmmv }
1886a6c8299Sjmmv 
1896a6c8299Sjmmv 
1906a6c8299Sjmmv /// Sets the logging to record messages in memory for later flushing.
1916a6c8299Sjmmv void
set_inmemory(void)1926a6c8299Sjmmv logging::set_inmemory(void)
1936a6c8299Sjmmv {
1946a6c8299Sjmmv     auto_set_persistency = false;
1956a6c8299Sjmmv }
1966a6c8299Sjmmv 
1976a6c8299Sjmmv 
1986a6c8299Sjmmv /// Makes the log persistent.
1996a6c8299Sjmmv ///
2006a6c8299Sjmmv /// Calling this function flushes the in-memory log, if any, to disk and sets
2016a6c8299Sjmmv /// the logging module to send log entries to disk from this point onwards.
2026a6c8299Sjmmv /// There is no way back, and the caller program should execute this function as
2036a6c8299Sjmmv /// early as possible to ensure that a crash at startup does not discard too
2046a6c8299Sjmmv /// many useful log entries.
2056a6c8299Sjmmv ///
2066a6c8299Sjmmv /// Any log entries above the provided new_level are discarded.
2076a6c8299Sjmmv ///
2086a6c8299Sjmmv /// \param new_level The new log level.
2096a6c8299Sjmmv /// \param path The file to write the logs to.
2106a6c8299Sjmmv ///
2116a6c8299Sjmmv /// \throw std::range_error If the given log level is invalid.
2126a6c8299Sjmmv /// \throw std::runtime_error If the given file cannot be created.
2136a6c8299Sjmmv void
set_persistency(const std::string & new_level,const fs::path & path)2146a6c8299Sjmmv logging::set_persistency(const std::string& new_level, const fs::path& path)
2156a6c8299Sjmmv {
2166a6c8299Sjmmv     auto_set_persistency = false;
2176a6c8299Sjmmv 
2186a6c8299Sjmmv     PRE(logfile.get() == NULL);
2196a6c8299Sjmmv 
2206a6c8299Sjmmv     // Update doc/troubleshooting.info if you change the log levels.
2216a6c8299Sjmmv     if (new_level == "debug")
2226a6c8299Sjmmv         log_level = level_debug;
2236a6c8299Sjmmv     else if (new_level == "error")
2246a6c8299Sjmmv         log_level = level_error;
2256a6c8299Sjmmv     else if (new_level == "info")
2266a6c8299Sjmmv         log_level = level_info;
2276a6c8299Sjmmv     else if (new_level == "warning")
2286a6c8299Sjmmv         log_level = level_warning;
2296a6c8299Sjmmv     else
2306a6c8299Sjmmv         throw std::range_error(F("Unrecognized log level '%s'") % new_level);
2316a6c8299Sjmmv 
2326a6c8299Sjmmv     logfile.reset(new std::ofstream(path.c_str()));
2336a6c8299Sjmmv     if (!(*logfile))
2346a6c8299Sjmmv         throw std::runtime_error(F("Failed to create log file %s") % path);
2356a6c8299Sjmmv 
2366a6c8299Sjmmv     for (std::vector< std::pair< logging::level, std::string > >::const_iterator
2376a6c8299Sjmmv          iter = backlog.begin(); iter != backlog.end(); iter++) {
2386a6c8299Sjmmv         if ((*iter).first <= log_level)
2396a6c8299Sjmmv             (*logfile) << (*iter).second << '\n';
2406a6c8299Sjmmv     }
2416a6c8299Sjmmv     (*logfile).flush();
2426a6c8299Sjmmv     backlog.clear();
2436a6c8299Sjmmv }
244