Commit a8ed348f authored by Peter Jankuliak's avatar Peter Jankuliak
Browse files

Enable logging to file using the CENO extension

parents b57d0294 27f8b1b9
......@@ -8,8 +8,9 @@ using namespace ouinet;
#define _LOGPFX "DHT Groups: "
#define _DEBUG(...) LOG_DEBUG(_LOGPFX, __VA_ARGS__)
#define _WARN(...) LOG_WARN(_LOGPFX, __VA_ARGS__)
#define _WARN(...) LOG_WARN(_LOGPFX, __VA_ARGS__)
#define _ERROR(...) LOG_ERROR(_LOGPFX, __VA_ARGS__)
#define _INFO(...) LOG_INFO(_LOGPFX, __VA_ARGS__)
using asio::yield_context;
namespace file_io = util::file_io;
......@@ -187,7 +188,7 @@ void DhtGroups::add( const GroupName& group_name
, Cancel& cancel
, yield_context yield)
{
_WARN("Adding: ", group_name, " -> ", item_name);
_INFO("Adding: ", group_name, " -> ", item_name);
fs::path group_p = group_path(group_name);
if (fs::exists(group_p)) {
......
......@@ -86,7 +86,8 @@ static const fs::path OUINET_CA_KEY_FILE = "ssl-ca-key.pem";
static const fs::path OUINET_CA_DH_FILE = "ssl-ca-dh.pem";
static bool log_transactions() {
return logger.get_threshold() <= DEBUG;
return logger.get_threshold() <= DEBUG
|| logger.get_log_file() != nullptr;
}
//------------------------------------------------------------------------------
......@@ -840,11 +841,11 @@ public:
, cc(client_state.get_executor(), OUINET_CLIENT_SERVER_STRING)
{
cc.fetch_fresh = [&] (const Request& rq, Cancel& cancel, Yield yield) {
return fetch_fresh(rq, cancel, yield);
return fetch_fresh(rq, cancel, yield.tag("fresh"));
};
cc.fetch_stored = [&] (const Request& rq, const std::string& dht_group, Cancel& cancel, Yield yield) {
return fetch_stored(rq, dht_group, cancel, yield);
return fetch_stored(rq, dht_group, cancel, yield.tag("cache"));
};
cc.max_cached_age(client_state._config.max_cached_age());
......@@ -853,8 +854,17 @@ public:
Session fetch_fresh(const Request& request, Cancel& cancel, Yield yield) {
namespace err = asio::error;
if (!client_state._config.is_injector_access_enabled())
if (log_transactions()) {
yield.log("start");
}
if (!client_state._config.is_injector_access_enabled()) {
if (log_transactions()) {
yield.log("disabled");
}
return or_throw<Session>(yield, err::operation_not_supported);
}
sys::error_code ec;
auto s = client_state.fetch_fresh_through_simple_proxy( request
......@@ -864,9 +874,9 @@ public:
if (log_transactions()) {
if (!ec) {
yield.log("Fetched fresh success, status: ", s.response_header().result());
yield.log("finish: ", ec.message(), ", status: ", s.response_header().result());
} else {
yield.log("Fetched fresh error: ", ec.message());
yield.log("finish: ", ec.message());
}
}
......@@ -876,7 +886,7 @@ public:
CacheEntry
fetch_stored(const Request& request, const std::string& dht_group, Cancel& cancel, Yield yield) {
if (log_transactions()) {
yield.log("Fetching from cache");
yield.log("start");
}
sys::error_code ec;
......@@ -886,8 +896,8 @@ public:
, cancel
, yield[ec]);
if (ec && log_transactions()) {
yield.log("Fetched from cache error: ", ec.message());
if (log_transactions()) {
yield.log("finish: ", ec.message(), " canceled: ", bool(cancel));
}
return or_throw(yield, ec, move(r));
......@@ -937,6 +947,12 @@ public:
case fresh_channel::origin: {
auto rq_ = rq;
auto y = yield.tag("origin");
if (log_transactions()) {
y.log("start");
}
if (r == fresh_channel::secure_origin
&& rq_.target().starts_with("http://")) {
auto target = rq_.target().to_string();
......@@ -944,21 +960,38 @@ public:
rq_.target(move(target));
}
auto session = client_state.fetch_fresh_from_origin(rq_, yield[ec]);
auto session = client_state.fetch_fresh_from_origin(rq_, y[ec]);
if (log_transactions()) {
y.log("fetch: ", ec.message());
}
if (ec) break;
session.flush_response(con, cancel, yield[ec]);
session.flush_response(con, cancel, y[ec]);
if (log_transactions()) {
y.log("flush: ", ec.message());
}
bool keep_alive = !ec && rq_.keep_alive() && session.keep_alive();
if (!keep_alive) {
session.close();
con.close();
}
return or_throw(yield, ec, keep_alive);
return or_throw(y, ec, keep_alive);
}
case fresh_channel::proxy: {
auto y = yield.tag("proxy");
if (log_transactions()) {
y.log("start");
}
if (!client_state._config.is_proxy_access_enabled()) {
if (log_transactions()) {
y.log("disabled");
}
continue;
}
......@@ -966,16 +999,24 @@ public:
if (rq.target().starts_with("https://")) {
session = client_state.fetch_fresh_through_connect_proxy
(rq, cancel, yield[ec]);
(rq, cancel, y[ec]);
}
else {
session = client_state.fetch_fresh_through_simple_proxy
(rq, false, cancel, yield[ec]);
(rq, false, cancel, y[ec]);
}
if (log_transactions()) {
y.log("Proxy fetch: ", ec.message());
}
if (ec) break;
session.flush_response(con, cancel, yield[ec]);
session.flush_response(con, cancel, y[ec]);
if (log_transactions()) {
y.log("flush: ", ec.message());
}
bool keep_alive = !ec && rq.keep_alive() && session.keep_alive();
if (!keep_alive) {
......@@ -985,15 +1026,21 @@ public:
return or_throw(yield, ec, keep_alive);
}
case fresh_channel::injector: {
auto y = yield.tag("injector");
sys::error_code fresh_ec;
sys::error_code cache_ec;
auto s = cc.fetch(rq, meta.dht_group, fresh_ec, cache_ec, cancel, yield[ec]);
if (log_transactions()) {
y.log("start");
}
auto s = cc.fetch(rq, meta.dht_group, fresh_ec, cache_ec, cancel, y[ec]);
if (log_transactions()) {
yield.log("cc.fetch ec:", ec.message(),
" fresh_ec:", fresh_ec.message(),
" cache_ec:", cache_ec.message());
y.log("cc.fetch ec:", ec.message(),
" fresh_ec:", fresh_ec.message(),
" cache_ec:", cache_ec.message());
}
if (ec) break;
......@@ -1001,8 +1048,8 @@ public:
auto& rsh = s.response_header();
if (log_transactions()) {
yield.log("Response header:");
yield.log(rsh);
y.log("Response header:");
y.log(rsh);
}
assert(!fresh_ec || !cache_ec); // At least one success
......@@ -1010,7 +1057,9 @@ public:
auto injector_error = rsh[http_::response_error_hdr];
if (!injector_error.empty()) {
yield.log("Error from injector: ", injector_error);
if (log_transactions()) {
y.log("Error from injector: ", injector_error);
}
ec = asio::error::invalid_argument;
break;
}
......@@ -1039,8 +1088,8 @@ public:
auto key = key_from_http_req(rq); assert(key);
AsyncQueueReader rr(qst);
sys::error_code ec;
auto y = yield.detach(yield_);
cache->store(*key, *meta.dht_group, rr, cancel, y[ec]);
auto y_ = y.detach(yield_);
cache->store(*key, *meta.dht_group, rr, cancel, y_[ec]);
}));
}
......@@ -1073,6 +1122,11 @@ public:
s.close();
con.close();
}
if (log_transactions()) {
y.log("finish: ", ec.message());
}
return or_throw(yield, ec, keep_alive);
}
}
......@@ -1502,7 +1556,7 @@ void Client::State::serve_request( GenericStream&& con
auto meta = UserAgentMetaData::extract(req);
bool keep_alive
= cache_control.fetch(con, req, meta, yield[ec].tag("cache_control.fetch"));
= cache_control.fetch(con, req, meta, yield[ec].tag("fetch"));
if (ec) {
if (log_transactions()) {
......
......@@ -12,6 +12,7 @@
#include <boost/asio/ip/address.hpp>
#include <boost/optional/optional_io.hpp>
#include <boost/date_time/posix_time/posix_time.hpp>
#include <boost/filesystem.hpp>
#include <boost/format.hpp>
#include <boost/regex.hpp>
#include <network/uri.hpp>
......@@ -142,6 +143,24 @@ void ClientFrontEnd::handle_ca_pem( const Request& req, Response& res, stringstr
ss << ca.pem_certificate();
}
static void enable_log_to_file(const std::string& path) {
logger.log_to_file(path);
}
static void disable_log_to_file() {
logger.log_to_file("");
}
static void load_log_file(stringstream& out_ss) {
std::fstream* logfile = logger.get_log_file();
if (logfile == nullptr) return;
logfile->flush();
logfile->seekg(0);
std::copy( istreambuf_iterator<char>(*logfile)
, istreambuf_iterator<char>()
, ostreambuf_iterator<char>(out_ss));
}
void ClientFrontEnd::handle_portal( ClientConfig& config
, const Request& req, Response& res, stringstream& ss
, cache::bep5_http::Client* bep5_cache)
......@@ -193,6 +212,17 @@ void ClientFrontEnd::handle_portal( ClientConfig& config
else if (target.find("?distributed_cache=disable") != string::npos) {
config.is_cache_access_enabled(false);
}
else if (target.find("?logfile=enable") != string::npos) {
enable_log_to_file((config.repo_root()/"log.txt").string());
}
else if (target.find("?logfile=disable") != string::npos) {
disable_log_to_file();
}
else if (target.find("?logfile=get") != string::npos) {
load_log_file(ss);
res.set(http::field::content_type, "text/plain");
return;
}
// Redirect back to the portal.
ss << "<!DOCTYPE html>\n"
......@@ -288,7 +318,8 @@ void ClientFrontEnd::handle_status( ClientConfig& config
{"injector_access", config.is_injector_access_enabled()},
{"distributed_cache", config.is_cache_access_enabled()},
{"ouinet_version", Version::VERSION_NAME},
{"ouinet_build_id", Version::BUILD_ID}
{"ouinet_build_id", Version::BUILD_ID},
{"logfile", logger.get_log_file() != nullptr}
};
if (udp_port) {
......
......@@ -21,16 +21,18 @@
#include <string>
#include <iostream>
#include <fstream>
#include <iomanip> // std::setprecision
#include <boost/system/error_code.hpp>
#include <boost/filesystem.hpp>
#include "namespaces.h"
#include "logger.h"
static const long LOG_FILE_MAX_SIZE = 15 * 1024 * 1024;
const std::string log_level_announce[] = {"SILLY" , "DEBUG" , "VERBOSE" , "INFO" , "WARN" , "ERROR" , "ABORT"};
const std::string log_level_color_prefix[] = {"\033[1;35;47m", "\033[1;32m", "\033[1;37m", "\033[1;34m", "\033[90;103m", "\033[31;40m", "\033[1;31;40m"};
#ifndef __ANDROID__
const bool log_level_colored_msg[] = {true , false , false , false , true , true , true};
#endif // ifndef __ANDROID__
log_level_t default_log_level() {
return INFO;
......@@ -38,53 +40,99 @@ log_level_t default_log_level() {
Logger logger(default_log_level());
void Logger::initiate_textual_conversions()
/************************* Time Functions **************************/
static
int timeval_subtract(struct timeval *x, struct timeval *y, struct timeval *result) {
/* Perform the carry for the later subtraction by updating y. */
if (x->tv_usec < y->tv_usec) {
int nsec = (y->tv_usec - x->tv_usec) / 1000000 + 1;
y->tv_usec -= 1000000 * nsec;
y->tv_sec += nsec;
}
if (x->tv_usec - y->tv_usec > 1000000) {
int nsec = (x->tv_usec - y->tv_usec) / 1000000;
y->tv_usec += 1000000 * nsec;
y->tv_sec -= nsec;
}
/* Compute the time remaining to wait.
tv_usec is certainly positive. */
result->tv_sec = x->tv_sec - y->tv_sec;
result->tv_usec = x->tv_usec - y->tv_usec;
/* Return 1 if result is negative. */
return x->tv_sec < y->tv_sec;
}
struct timeval log_ts_base;
/** Get a timestamp, as a floating-point number of seconds. */
static double log_get_timestamp()
{
struct timeval now, delta;
gettimeofday(&now, 0);
timeval_subtract(&now, &log_ts_base, &delta);
return delta.tv_sec + double(delta.tv_usec) / 1e6;
}
/*********************** Time Functions END ************************/
// Standard constructor
// Threshold adopts a default level of DEBUG if an invalid threshold is provided.
Logger::Logger(log_level_t threshold)
{
initiate_textual_conversions();
if (threshold < SILLY || threshold > ERROR) {
this->threshold = default_log_level();
} else {
this->threshold = threshold;
}
log_to_stderr = true;
log_to_file = false;
log_filename = "";
log_ts_base = {0, 0};
//gettimeofday(&log_ts_base, 0);
}
// Standard destructor
Logger::~Logger()
void Logger::log_to_file(std::string fname)
{
if (log_file.is_open()) {
log_file.close();
using std::ios;
if (fname.empty()) {
if (!log_filename.empty()) {
ouinet::sys::error_code ignored_ec;
ouinet::fs::remove(log_filename, ignored_ec);
}
log_file = boost::none;
return;
}
}
// Configure the logger to log to stderr and/or to a file.
void Logger::config(bool log_stderr, bool log_to_file, std::string fname)
{
log_to_stderr = log_stderr;
this->log_to_file = log_to_file;
if (log_to_file) {
if (log_filename != fname || !log_file) {
log_filename = fname;
log_file.open(log_filename, std::ios::out | std::ios::app);
} else {
if (log_file.is_open()) {
log_file.close();
log_file = std::fstream();
if (ouinet::fs::exists(log_filename)) {
log_file->open(log_filename, ios::in | ios::out | ios::ate);
} else {
// `trunc` causes the file to be created
log_file->open(log_filename, ios::in | ios::out | ios::trunc);
}
if (!log_file->is_open()) {
std::cerr << "Failed to open log file " << fname << "\n";
log_filename = "";
log_file = boost::none;
} else {
static const char* start_s = "\nOUINET START\n";
*log_file << start_s;
}
}
}
std::fstream* Logger::get_log_file() {
if (!log_file) return nullptr;
return &*log_file;
}
// Update the logger's threshold.
// If an invalid level is provided, do not update.
void Logger::set_threshold(log_level_t level)
......@@ -99,79 +147,128 @@ bool Logger::would_log(log_level_t level) const
return get_threshold() <= level;
}
namespace {
struct Printer {
using string_view = boost::string_view;
log_level_t level;
bool with_color;
boost::optional<double> ts;
string_view msg;
string_view fun;
Printer(log_level_t level, bool with_color, boost::optional<double> ts, string_view msg, string_view fun)
: level(level)
, with_color(with_color)
, ts(ts)
, msg(msg)
, fun(fun)
{}
friend std::ostream& operator<<(std::ostream& os, const Printer& p) {
static const char* color_end = "\033[0m";
if (p.ts) {
// Prevent scientific notation
os << std::fixed << std::showpoint << std::setprecision(4);
os << *p.ts << ": ";
}
if (p.with_color) {
os << log_level_color_prefix[p.level];
}
os << "[" << log_level_announce[p.level];
if (log_level_colored_msg[p.level] || !p.with_color) {
os << "] ";
} else {
os << "]" << color_end << " ";
}
if (!p.fun.empty()) {
os << p.fun << ": ";
}
os << p.msg;
if (p.with_color && log_level_colored_msg[p.level]) {
os << color_end;
}
return os;
}
};
}
// Standard log function. Prints nice colors for each level.
void Logger::log(log_level_t level, std::string msg, std::string function_name)
void Logger::log(log_level_t level, const std::string& msg, boost::string_view function_name)
{
if (level < SILLY || level > ABORT || level < threshold) {
return;
}
msg = (function_name.empty()) ? msg : function_name + ": " + msg;
std::string message_prefix = "[" + log_level_announce[level];
#ifndef __ANDROID__
message_prefix = log_level_color_prefix[level] + message_prefix + "]";
if (log_level_colored_msg[level])
message_prefix += " ";
else
message_prefix += "\033[0m ";
#ifdef __ANDROID__
const bool android = true;
#else
message_prefix = message_prefix + "] ";
#endif // ifndef __ANDROID__
msg = message_prefix + msg;
#ifndef __ANDROID__
if (log_level_colored_msg[level])
msg += "\033[0m";
const bool android = false;
#endif
//time stamp
if (_stamp_with_time) {
msg = std::to_string(log_get_timestamp()) + ": " + msg;
}
bool with_color = !android;
boost::optional<double> ts;
if (_stamp_with_time || log_file) ts = log_get_timestamp();
if (log_to_stderr) {
std::cerr << msg << std::endl;
//std::cerr.flush();
if (_stamp_with_time)
std::cerr << Printer(level, with_color, ts, msg, function_name) << "\n";
else
std::cerr << Printer(level, with_color, boost::none, msg, function_name) << "\n";
}
if (log_to_file && log_file.is_open()) {
log_file << msg << std::endl;
if (log_file && log_file->is_open()) {
*log_file << Printer(level, false, ts, msg, function_name) << "\n";
if (log_file->tellp() > LOG_FILE_MAX_SIZE) {
log_file->seekp(0);
}
}
}
// Convenience methods
void Logger::silly(std::string msg, std::string function_name)
void Logger::silly(const std::string& msg, boost::string_view function_name)
{
log(SILLY, msg, function_name);
}
void Logger::debug(std::string msg, std::string function_name)
void Logger::debug(const std::string& msg, boost::string_view function_name)
{
log(DEBUG, msg, function_name);
}
void Logger::verbose(std::string msg, std::string function_name)
void Logger::verbose(const std::string& msg, boost::string_view function_name)
{
log(VERBOSE, msg, function_name);
}
void Logger::info(std::string msg, std::string function_name)
void Logger::info(const std::string& msg, boost::string_view function_name)
{
log(INFO, msg, function_name);
}
void Logger::warn(std::string msg, std::string function_name)
void Logger::warn(const std::string& msg, boost::string_view function_name)
{
log(WARN, msg, function_name);
}
void Logger::error(std::string msg, std::string function_name)
void Logger::error(const std::string& msg, boost::string_view function_name)
{
log(ERROR, msg, function_name);
}
void Logger::abort(std::string msg, std::string function_name)
void Logger::abort(const std::string& msg, boost::string_view function_name)
{
log(ABORT, msg, function_name);
exit(1);
......@@ -183,13 +280,3 @@ void Logger::assert_or_die(bool expr, std::string failure_message, std::string f
abort(failure_message, function_name);
}
/** Get a timestamp, as a floating-point number of seconds. */