Improve logging functionality

The format of timestamps is now configurable via a new
--timestamp-format option. The default format is changed
to Unix epoch time with microsecond granularity.

Co-authored-by: Davide Pesavento <davidepesa@gmail.com>
Change-Id: I7dd7fb770becca7aa339e003b1111366f34ce925

AUTHORS.md

@@ -7,6 +7,7 @@ If you would like to become a contributor to the official repository, please fol
 * Jerald Paul Abraham <https://www2.cs.arizona.edu/~jeraldabraham>
 * Alexander Afanasyev <https://users.cs.fiu.edu/~afanasyev>
 * Jing Guan <http://jennica.space>
+* Alexander Lane <https://github.com/awlane>
 * Spencer Lee <https://www.linkedin.com/in/spenlee>
 * Eric Newberry <https://ericnewberry.com>
 * Davide Pesavento <https://github.com/Pesa>

README.md

@@ -29,30 +29,40 @@ sudo ./waf install
 ### `ndn-traffic-server`
 
     Usage: ndn-traffic-server [options] <Traffic_Configuration_File>
+
     Respond to Interests as per provided Traffic_Configuration_File.
     Multiple prefixes can be configured for handling.
     Set the environment variable NDN_TRAFFIC_LOGFOLDER to redirect output to a log file.
+
     Options:
-      -h [ --help ]           print this help message and exit
-      -c [ --count ] arg      maximum number of Interests to respond to
-      -d [ --delay ] arg (=0) wait this amount of milliseconds before responding to each Interest
-      -q [ --quiet ]          turn off logging of Interest reception/Data generation
+      -h [ --help ]                 print this help message and exit
+      -c [ --count ] arg            maximum number of Interests to respond to
+      -d [ --delay ] arg (=0)       wait this amount of milliseconds before responding to each Interest
+      -t [ --timestamp-format ] arg format string for timestamp output (see below)
+      -q [ --quiet ]                turn off logging of Interest reception and Data generation
 
 ### `ndn-traffic-client`
 
     Usage: ndn-traffic-client [options] <Traffic_Configuration_File>
+
     Generate Interest traffic as per provided Traffic_Configuration_File.
     Interests are continuously generated unless a total number is specified.
     Set the environment variable NDN_TRAFFIC_LOGFOLDER to redirect output to a log file.
+
     Options:
       -h [ --help ]                 print this help message and exit
       -c [ --count ] arg            total number of Interests to be generated
       -i [ --interval ] arg (=1000) Interest generation interval in milliseconds
-      -q [ --quiet ]                turn off logging of Interest generation/Data reception
+      -t [ --timestamp-format ] arg format string for timestamp output (see below)
+      -q [ --quiet ]                turn off logging of Interest generation and Data reception
+      -v [ --verbose ]              log additional per-packet information
 
 * These tools need not be used together and can be used individually as well.
 * Please refer to the sample configuration files provided for details on how to create your own.
 * Use the command line options shown above to adjust traffic configuration.
+* By default, timestamps are logged in Unix epoch format with microsecond granularity.
+  For custom output, the `--timestamp-format` option expects a format string using the syntax given in the
+  [Boost.Date_Time documentation](https://www.boost.org/doc/libs/1_71_0/doc/html/date_time/date_time_io.html#date_time.format_flags).
 
 ## Example
 

src/logger.hpp

@@ -1,6 +1,6 @@
 /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */
 /*
- * Copyright (c) 2014-2022, Arizona Board of Regents.
+ * Copyright (c) 2014-2023, Arizona Board of Regents.
  *
  * This program is free software: you can redistribute it and/or modify
  * it under the terms of the GNU General Public License as published by
@@ -24,9 +24,14 @@
 #include <cstdlib>
 #include <fstream>
 #include <string>
+#include <string_view>
 
-#include <boost/filesystem.hpp>
+#include <boost/container/static_vector.hpp>
 #include <boost/date_time/posix_time/posix_time.hpp>
+#include <boost/filesystem/operations.hpp>
+#include <boost/filesystem/path.hpp>
+
+#include <ndn-cxx/util/time.hpp>
 
 namespace ndntg {
 
@@ -34,40 +39,56 @@ class Logger
 {
 public:
   explicit
-  Logger(const std::string& module)
+  Logger(std::string_view module)
     : m_module(module)
   {
   }
 
   void
-  log(const std::string& logLine, bool printTime, bool printToConsole)
+  log(std::string_view logLine, bool printTimestamp, bool printToConsole)
   {
-    if (m_logLocation.length() > 0) {
-      if (printTime)
-        m_logFile << getTimestamp() << " - ";
-      m_logFile << logLine << std::endl;
-      m_logFile.flush();
-      if (printToConsole) {
-        if (printTime)
-          std::cout << getTimestamp() << " - ";
-        std::cout << logLine << std::endl;
+    boost::container::static_vector<std::reference_wrapper<std::ostream>, 2> destinations;
+    if (!m_logLocation.empty()) {
+      destinations.emplace_back(m_logFile);
+    }
+    if (m_logLocation.empty() || printToConsole) {
+      destinations.emplace_back(std::cout);
+    }
+
+    if (printTimestamp) {
+      if (m_wantUnixTime) {
+        using namespace ndn::time;
+        auto now = std::to_string(toUnixTimestamp<microseconds>(system_clock::now()).count() / 1e6);
+        for (auto dest : destinations) {
+          dest.get() << '[' << now << "] ";
+        }
+      }
+      else {
+        auto now = boost::posix_time::microsec_clock::local_time();
+        for (auto dest : destinations) {
+          dest.get() << '[' << now << "] ";
+        }
       }
     }
-    else {
-      if (printTime)
-        std::cout << getTimestamp() << " - ";
-      std::cout << logLine << std::endl;
+
+    for (auto dest : destinations) {
+      dest.get() << logLine << std::endl;
     }
   }
 
   void
-  initializeLog(const std::string& instanceId)
+  initialize(const std::string& instanceId, const std::string& timestampFormat)
   {
-    m_logLocation = "";
-    const char* envVar = std::getenv("NDN_TRAFFIC_LOGFOLDER");
-    if (envVar != nullptr)
-      m_logLocation = envVar;
+    m_wantUnixTime = timestampFormat.empty();
+    if (!timestampFormat.empty()) {
+      std::cout.imbue(std::locale(std::cout.getloc(),
+                                  new boost::posix_time::time_facet(timestampFormat.data())));
+    }
 
+    m_logLocation = "";
+    if (const char* envVar = std::getenv("NDN_TRAFFIC_LOGFOLDER"); envVar != nullptr) {
+      m_logLocation = envVar;
+    }
     if (m_logLocation.empty()) {
       std::cout << "Environment variable NDN_TRAFFIC_LOGFOLDER not set.\n"
                 << "Using default output for logging." << std::endl;
@@ -80,16 +101,20 @@ public:
         auto logfile = logdir / (m_module + '_' + instanceId + ".log");
         m_logFile.open(logfile.string(), std::ofstream::out | std::ofstream::trunc);
         if (m_logFile.is_open()) {
+          if (!timestampFormat.empty()) {
+            m_logFile.imbue(std::locale(m_logFile.getloc(),
+                                        new boost::posix_time::time_facet(timestampFormat.data())));
+          }
           std::cout << "Log file initialized: " << logfile << std::endl;
         }
         else {
-          std::cout << "ERROR: Unable to initialize a log file at: " << m_logLocation << std::endl
+          std::cout << "ERROR: Unable to initialize a log file at: " << m_logLocation << "\n"
                     << "Using default output for logging." << std::endl;
           m_logLocation = "";
         }
       }
       else {
-        std::cout << "NDN_TRAFFIC_LOGFOLDER should be a directory.\n"
+        std::cout << "NDN_TRAFFIC_LOGFOLDER is not a directory.\n"
                   << "Using default output for logging." << std::endl;
         m_logLocation = "";
       }
@@ -102,17 +127,10 @@ public:
   }
 
 private:
-  static std::string
-  getTimestamp()
-  {
-    auto now = boost::posix_time::second_clock::local_time();
-    return to_simple_string(now);
-  }
-
-private:
-  std::string m_module;
+  const std::string m_module;
   std::string m_logLocation;
   std::ofstream m_logFile;
+  bool m_wantUnixTime = true;
 };
 
 } // namespace ndntg

src/ndn-traffic-client.cpp

@@ -30,15 +30,14 @@
 #include <limits>
 #include <optional>
 #include <sstream>
-#include <string_view>
 #include <vector>
 
 #include <boost/asio/deadline_timer.hpp>
 #include <boost/asio/io_service.hpp>
 #include <boost/asio/signal_set.hpp>
+#include <boost/core/noncopyable.hpp>
 #include <boost/date_time/posix_time/posix_time.hpp>
 #include <boost/lexical_cast.hpp>
-#include <boost/noncopyable.hpp>
 #include <boost/program_options/options_description.hpp>
 #include <boost/program_options/parsers.hpp>
 #include <boost/program_options/variables_map.hpp>
@@ -54,11 +53,8 @@ class NdnTrafficClient : boost::noncopyable
 {
 public:
   explicit
-  NdnTrafficClient(const std::string& configFile)
-    : m_signalSet(m_ioService, SIGINT, SIGTERM)
-    , m_logger("NdnTrafficClient")
-    , m_face(m_ioService)
-    , m_configurationFile(configFile)
+  NdnTrafficClient(std::string configFile)
+    : m_configurationFile(std::move(configFile))
   {
   }
 
@@ -75,16 +71,28 @@ public:
     m_interestInterval = interval;
   }
 
+  void
+  setTimestampFormat(std::string format)
+  {
+    m_timestampFormat = std::move(format);
+  }
+
   void
   setQuietLogging()
   {
     m_wantQuiet = true;
   }
 
+  void
+  setVerboseLogging()
+  {
+    m_wantVerbose = true;
+  }
+
   int
   run()
   {
-    m_logger.initializeLog(std::to_string(ndn::random::generateWord32()));
+    m_logger.initialize(std::to_string(ndn::random::generateWord32()), m_timestampFormat);
 
     if (!readConfigurationFile(m_configurationFile, m_trafficPatterns, m_logger)) {
       return 2;
@@ -95,7 +103,7 @@ public:
       return 2;
     }
 
-    m_logger.log("Traffic configuration file processing completed.\n", true, false);
+    m_logger.log("Traffic configuration file processing completed\n", true, false);
     for (std::size_t i = 0; i < m_trafficPatterns.size(); i++) {
       m_logger.log("Traffic Pattern Type #" + std::to_string(i + 1), false, false);
       m_trafficPatterns[i].printTrafficConfiguration(m_logger);
@@ -246,7 +254,7 @@ private:
   {
     using std::to_string;
 
-    m_logger.log("\n\n== Interest Traffic Report ==\n", false, true);
+    m_logger.log("\n\n== Traffic Report ==\n", false, true);
     m_logger.log("Total Traffic Pattern Types = " + to_string(m_trafficPatterns.size()), false, true);
     m_logger.log("Total Interests Sent        = " + to_string(m_nInterestsSent), false, true);
     m_logger.log("Total Responses Received    = " + to_string(m_nInterestsReceived), false, true);
@@ -380,6 +388,7 @@ private:
   onData(const ndn::Interest&, const ndn::Data& data, int globalRef, int localRef,
          std::size_t patternId, const time::steady_clock::time_point& sentTime)
   {
+    auto now = time::steady_clock::now();
     auto logLine = "Data Received      - PatternType=" + std::to_string(patternId + 1) +
                    ", GlobalID=" + std::to_string(globalRef) +
                    ", LocalID=" + std::to_string(localRef) +
@@ -406,7 +415,12 @@ private:
       m_logger.log(logLine, true, false);
     }
 
-    double roundTripTime = (time::steady_clock::now() - sentTime).count() / 1000000.0;
+    double roundTripTime = (now - sentTime).count() / 1000000.0;
+    if (m_wantVerbose) {
+      auto rttLine = "RTT                - Name=" + data.getName().toUri() +
+                     ", RTT=" + std::to_string(roundTripTime) + "ms";
+      m_logger.log(rttLine, true, false);
+    }
     if (m_minimumInterestRoundTripTime > roundTripTime)
       m_minimumInterestRoundTripTime = roundTripTime;
     if (m_maximumInterestRoundTripTime < roundTripTime)
@@ -506,6 +520,7 @@ private:
         break;
       }
     }
+
     if (patternId == m_trafficPatterns.size()) {
       timer.expires_at(timer.expires_at() + boost::posix_time::millisec(m_interestInterval.count()));
       timer.async_wait([this, &timer] (auto&&...) { generateTraffic(timer); });
@@ -525,12 +540,13 @@ private:
   }
 
 private:
+  Logger m_logger{"NdnTrafficClient"};
   boost::asio::io_service m_ioService;
-  boost::asio::signal_set m_signalSet;
-  Logger m_logger;
-  ndn::Face m_face;
+  boost::asio::signal_set m_signalSet{m_ioService, SIGINT, SIGTERM};
+  ndn::Face m_face{m_ioService};
 
   std::string m_configurationFile;
+  std::string m_timestampFormat;
   std::optional<uint64_t> m_nMaximumInterests;
   time::milliseconds m_interestInterval = 1_s;
 
@@ -547,6 +563,7 @@ private:
   double m_totalInterestRoundTripTime = 0;
 
   bool m_wantQuiet = false;
+  bool m_wantVerbose = false;
   bool m_hasError = false;
 };
 
@@ -570,14 +587,17 @@ int
 main(int argc, char* argv[])
 {
   std::string configFile;
+  std::string timestampFormat;
 
   po::options_description visibleOptions("Options");
   visibleOptions.add_options()
     ("help,h",      "print this help message and exit")
-    ("count,c",     po::value<int>(), "total number of Interests to be generated")
+    ("count,c",     po::value<int64_t>(), "total number of Interests to be generated")
     ("interval,i",  po::value<ndn::time::milliseconds::rep>()->default_value(1000),
                     "Interest generation interval in milliseconds")
-    ("quiet,q",     po::bool_switch(), "turn off logging of Interest generation/Data reception")
+    ("timestamp-format,t", po::value<std::string>(&timestampFormat), "format string for timestamp output")
+    ("quiet,q",     po::bool_switch(), "turn off logging of Interest generation and Data reception")
+    ("verbose,v",   po::bool_switch(), "log additional per-packet information")
     ;
 
   po::options_description hiddenOptions;
@@ -615,12 +635,12 @@ main(int argc, char* argv[])
     return 2;
   }
 
-  ndntg::NdnTrafficClient client(configFile);
+  ndntg::NdnTrafficClient client(std::move(configFile));
 
   if (vm.count("count") > 0) {
-    int count = vm["count"].as<int>();
+    auto count = vm["count"].as<int64_t>();
     if (count < 0) {
-      std::cerr << "ERROR: the argument for option '--count' cannot be negative" << std::endl;
+      std::cerr << "ERROR: the argument for option '--count' cannot be negative\n";
       return 2;
     }
     client.setMaximumInterests(static_cast<uint64_t>(count));
@@ -629,15 +649,27 @@ main(int argc, char* argv[])
   if (vm.count("interval") > 0) {
     ndn::time::milliseconds interval(vm["interval"].as<ndn::time::milliseconds::rep>());
     if (interval <= 0_ms) {
-      std::cerr << "ERROR: the argument for option '--interval' must be positive" << std::endl;
+      std::cerr << "ERROR: the argument for option '--interval' must be positive\n";
       return 2;
     }
     client.setInterestInterval(interval);
   }
 
+  if (!timestampFormat.empty()) {
+    client.setTimestampFormat(std::move(timestampFormat));
+  }
+
   if (vm["quiet"].as<bool>()) {
+    if (vm["verbose"].as<bool>()) {
+      std::cerr << "ERROR: cannot set both '--quiet' and '--verbose'\n";
+      return 2;
+    }
     client.setQuietLogging();
   }
 
+  if (vm["verbose"].as<bool>()) {
+    client.setVerboseLogging();
+  }
+
   return client.run();
 }

src/ndn-traffic-server.cpp

@@ -1,6 +1,6 @@
 /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */
 /*
- * Copyright (c) 2014-2022, Arizona Board of Regents.
+ * Copyright (c) 2014-2023, Arizona Board of Regents.
  *
  * This program is free software: you can redistribute it and/or modify
  * it under the terms of the GNU General Public License as published by
@@ -31,18 +31,16 @@
 #include <limits>
 #include <optional>
 #include <sstream>
-#include <string_view>
 #include <vector>
 
 #include <boost/asio/io_service.hpp>
 #include <boost/asio/signal_set.hpp>
-#include <boost/noncopyable.hpp>
+#include <boost/core/noncopyable.hpp>
 #include <boost/program_options/options_description.hpp>
 #include <boost/program_options/parsers.hpp>
 #include <boost/program_options/variables_map.hpp>
 #include <boost/thread/thread.hpp>
 
-namespace po = boost::program_options;
 using namespace ndn::time_literals;
 using namespace std::string_literals;
 
@@ -54,11 +52,8 @@ class NdnTrafficServer : boost::noncopyable
 {
 public:
   explicit
-  NdnTrafficServer(const std::string& configFile)
-    : m_signalSet(m_ioService, SIGINT, SIGTERM)
-    , m_logger("NdnTrafficServer")
-    , m_face(m_ioService)
-    , m_configurationFile(configFile)
+  NdnTrafficServer(std::string configFile)
+    : m_configurationFile(std::move(configFile))
   {
   }
 
@@ -75,6 +70,12 @@ public:
     m_contentDelay = delay;
   }
 
+  void
+  setTimestampFormat(std::string format)
+  {
+    m_timestampFormat = std::move(format);
+  }
+
   void
   setQuietLogging()
   {
@@ -84,7 +85,7 @@ public:
   int
   run()
   {
-    m_logger.initializeLog(std::to_string(ndn::random::generateWord32()));
+    m_logger.initialize(std::to_string(ndn::random::generateWord32()), m_timestampFormat);
 
     if (!readConfigurationFile(m_configurationFile, m_trafficPatterns, m_logger)) {
       return 2;
@@ -95,7 +96,7 @@ public:
       return 2;
     }
 
-    m_logger.log("Traffic configuration file processing completed.\n", true, false);
+    m_logger.log("Traffic configuration file processing completed\n", true, false);
     for (std::size_t i = 0; i < m_trafficPatterns.size(); i++) {
       m_logger.log("Traffic Pattern Type #" + std::to_string(i + 1), false, false);
       m_trafficPatterns[i].printTrafficConfiguration(m_logger);
@@ -223,17 +224,19 @@ private:
   void
   logStatistics()
   {
-    m_logger.log("\n\n== Interest Traffic Report ==\n", false, true);
-    m_logger.log("Total Traffic Pattern Types = " +
-                 std::to_string(m_trafficPatterns.size()), false, true);
-    m_logger.log("Total Interests Received    = " +
-                 std::to_string(m_nInterestsReceived), false, true);
+    using std::to_string;
+
+    m_logger.log("\n\n== Traffic Report ==\n", false, true);
+    m_logger.log("Total Traffic Pattern Types = " + to_string(m_trafficPatterns.size()), false, true);
+    m_logger.log("Total Interests Received    = " + to_string(m_nInterestsReceived) + "\n", false, true);
 
     for (std::size_t patternId = 0; patternId < m_trafficPatterns.size(); patternId++) {
-      m_logger.log("\nTraffic Pattern Type #" + std::to_string(patternId + 1), false, true);
-      m_trafficPatterns[patternId].printTrafficConfiguration(m_logger);
+      const auto& pattern = m_trafficPatterns[patternId];
+
+      m_logger.log("Traffic Pattern Type #" + to_string(patternId + 1), false, true);
+      pattern.printTrafficConfiguration(m_logger);
       m_logger.log("Total Interests Received    = " +
-                   std::to_string(m_trafficPatterns[patternId].m_nInterestsReceived) + "\n", false, true);
+                   to_string(pattern.m_nInterestsReceived) + "\n", false, true);
     }
   }
 
@@ -286,10 +289,10 @@ private:
       pattern.m_nInterestsReceived++;
 
       if (!m_wantQuiet) {
-        auto logLine = "Interest received          - PatternType=" + std::to_string(patternId + 1) +
+        auto logLine = "Interest Received          - PatternType=" + std::to_string(patternId + 1) +
                        ", GlobalID=" + std::to_string(m_nInterestsReceived) +
                        ", LocalID=" + std::to_string(pattern.m_nInterestsReceived) +
-                       ", Name=" + pattern.m_name;
+                       ", Name=" + interest.getName().toUri();
         m_logger.log(logLine, true, false);
       }
 
@@ -332,13 +335,14 @@ private:
   }
 
 private:
+  Logger m_logger{"NdnTrafficServer"};
   boost::asio::io_service m_ioService;
-  boost::asio::signal_set m_signalSet;
-  Logger m_logger;
-  ndn::Face m_face;
+  boost::asio::signal_set m_signalSet{m_ioService, SIGINT, SIGTERM};
+  ndn::Face m_face{m_ioService};
   ndn::KeyChain m_keyChain;
 
   std::string m_configurationFile;
+  std::string m_timestampFormat;
   std::optional<uint64_t> m_nMaximumInterests;
   time::milliseconds m_contentDelay = 0_ms;
 
@@ -353,6 +357,8 @@ private:
 
 } // namespace ndntg
 
+namespace po = boost::program_options;
+
 static void
 usage(std::ostream& os, std::string_view programName, const po::options_description& desc)
 {
@@ -369,14 +375,16 @@ int
 main(int argc, char* argv[])
 {
   std::string configFile;
+  std::string timestampFormat;
 
   po::options_description visibleOptions("Options");
   visibleOptions.add_options()
     ("help,h",    "print this help message and exit")
-    ("count,c",   po::value<int>(), "maximum number of Interests to respond to")
+    ("count,c",   po::value<int64_t>(), "maximum number of Interests to respond to")
     ("delay,d",   po::value<ndn::time::milliseconds::rep>()->default_value(0),
                   "wait this amount of milliseconds before responding to each Interest")
-    ("quiet,q",   po::bool_switch(), "turn off logging of Interest reception/Data generation")
+    ("timestamp-format,t", po::value<std::string>(&timestampFormat), "format string for timestamp output")
+    ("quiet,q",   po::bool_switch(), "turn off logging of Interest reception and Data generation")
     ;
 
   po::options_description hiddenOptions;
@@ -414,12 +422,12 @@ main(int argc, char* argv[])
     return 2;
   }
 
-  ndntg::NdnTrafficServer server(configFile);
+  ndntg::NdnTrafficServer server(std::move(configFile));
 
   if (vm.count("count") > 0) {
-    int count = vm["count"].as<int>();
+    auto count = vm["count"].as<int64_t>();
     if (count < 0) {
-      std::cerr << "ERROR: the argument for option '--count' cannot be negative" << std::endl;
+      std::cerr << "ERROR: the argument for option '--count' cannot be negative\n";
       return 2;
     }
     server.setMaximumInterests(static_cast<uint64_t>(count));
@@ -428,12 +436,16 @@ main(int argc, char* argv[])
   if (vm.count("delay") > 0) {
     ndn::time::milliseconds delay(vm["delay"].as<ndn::time::milliseconds::rep>());
     if (delay < 0_ms) {
-      std::cerr << "ERROR: the argument for option '--delay' cannot be negative" << std::endl;
+      std::cerr << "ERROR: the argument for option '--delay' cannot be negative\n";
       return 2;
     }
     server.setContentDelay(delay);
   }
 
+  if (!timestampFormat.empty()) {
+    server.setTimestampFormat(std::move(timestampFormat));
+  }
+
   if (vm["quiet"].as<bool>()) {
     server.setQuietLogging();
   }