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
diff --git a/src/logger.hpp b/src/logger.hpp
index 7952b1c..d9be745 100644
--- a/src/logger.hpp
+++ b/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 @@
{
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 @@
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 @@
}
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
diff --git a/src/ndn-traffic-client.cpp b/src/ndn-traffic-client.cpp
index fd5d1ed..c9e9f34 100644
--- a/src/ndn-traffic-client.cpp
+++ b/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 @@
{
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))
{
}
@@ -76,15 +72,27 @@
}
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 @@
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 @@
{
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 @@
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 @@
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 @@
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:
+ 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 @@
double m_totalInterestRoundTripTime = 0;
bool m_wantQuiet = false;
+ bool m_wantVerbose = false;
bool m_hasError = false;
};
@@ -570,14 +587,17 @@
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>(×tampFormat), "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 @@
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 @@
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();
}
diff --git a/src/ndn-traffic-server.cpp b/src/ndn-traffic-server.cpp
index 6525b7a..3556efe 100644
--- a/src/ndn-traffic-server.cpp
+++ b/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 @@
{
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))
{
}
@@ -76,6 +71,12 @@
}
void
+ setTimestampFormat(std::string format)
+ {
+ m_timestampFormat = std::move(format);
+ }
+
+ void
setQuietLogging()
{
m_wantQuiet = true;
@@ -84,7 +85,7 @@
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 @@
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 @@
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 @@
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:
+ 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 @@
} // 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 @@
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>(×tampFormat), "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 @@
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 @@
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();
}