Support user-defined verbosity formats

* Add `fair::Logger::DefineVerbosity(...)` API
* Add documentation to README
* Optionally support `BOOST_PRETTY_FUNCTION`
This commit is contained in:
Dennis Klein 2018-09-21 19:53:18 +02:00 committed by Alexey Rybalchenko
parent 7d0411b939
commit 3e1de0a17b
5 changed files with 409 additions and 62 deletions

View File

@ -22,6 +22,15 @@ message(STATUS "${BWhite}${PROJECT_NAME}${CR} ${FairLogger_GIT_VERSION} from ${F
set_fairlogger_defaults()
include(CTest)
option(USE_BOOST_PRETTY_FUNCTION "Use Boost BOOST_PRETTY_FUNCTION macro" OFF)
################################################################################
# Dependency ###################################################################
if(USE_BOOST_PRETTY_FUNCTION)
find_package(Boost REQUIRED)
endif()
################################################################################
@ -37,6 +46,11 @@ add_library(FairLogger
logger/Logger.h
)
if(USE_BOOST_PRETTY_FUNCTION)
target_link_libraries(FairLogger PUBLIC Boost::boost)
target_compile_definitions(FairLogger PUBLIC FAIRLOGGER_USE_BOOST_PRETTY_FUNCTION)
endif()
target_include_directories(FairLogger
PUBLIC
$<BUILD_INTERFACE:${CMAKE_SOURCE_DIR}/logger>

138
README.md
View File

@ -41,6 +41,144 @@ On command line:
* `-DDISABLE_COLOR=ON` disables coloured console output.
* `-DBUILD_TESTING=OFF` disables building of unit tests.
* `-DUSE_BOOST_PRETTY_FUNCTION=ON` enables usage of `BOOST_PRETTY_FUNCTION` macro.
## Documentation
## 1. General
All log calls go through the provided LOG(severity) macro. Output through this macro is thread-safe. Logging is done to cout, file output and/or custom sinks.
## 2. Severity
The log severity is controlled via:
```C++
fair::Logger::SetConsoleSeverity("<severity level>");
// and/or
fair::Logger::SetFileSeverity("<severity level>");
// and/or
fair::Logger::SetCustomSeverity("<customSinkName>", "<severity level>");
```
where severity level is one of the following:
```C++
"nolog",
"fatal",
"error",
"warn",
"state",
"info",
"debug",
"debug1",
"debug2",
"debug3",
"debug4",
"trace",
```
Logger will log the chosen severity and all above it (except "nolog", which deactivates logging for that sink completely). Fatal severity is always logged.
## 3. Verbosity
The log verbosity is controlled via:
```C++
fair::Logger::SetVerbosity("<verbosity level>");
```
it is same for all sinks, and is one of the following values: `verylow`, `low`, `medium`, `high`, `veryhigh`, which translates to following output:
```
verylow: message
low: [severity] message
medium: [HH:MM:SS][severity] message
high: [process name][HH:MM:SS:µS][severity] message
veryhigh: [process name][HH:MM:SS:µS][severity][file:line:function] message
```
When running a FairMQ device, the log severity can be simply provided via `--verbosity <level>` cmd option.
The user may customize the existing verbosities or any of `user1`, `user2`, `user3`, `user4` verbosities via:
```C++
void fair::Logger::DefineVerbosity(fair::Verbosity, fair::VerbositySpec);
void fair::Logger::DefineVerbosity("<verbosity level>", fair::VerbositySpec);
```
The `fair::Logger::VerbositySpec` object can e.g. be created like this:
```C++
auto spec = fair::VerbositySpec::Make(VerbositySpec::Info::timestamp_s,
VerbositySpec::Info::process_name);
// results in [HH:MM:SS][process name] message
```
| **Argument** | **Result** |
| --- | --- |
| `fair::VerbositySpec::Info::process_name` | `[process name]` |
| `fair::VerbositySpec::Info::timestamp_s` | `[HH:MM:SS]` |
| `fair::VerbositySpec::Info::timestamp_us` | `[HH:MM:SS:µS]` |
| `fair::VerbositySpec::Info::severity` | `[severity]` |
| `fair::VerbositySpec::Info::file` | `[file]` |
| `fair::VerbositySpec::Info::file_line` | `[file:line]` |
| `fair::VerbositySpec::Info::file_line_function` | `[file:line:function]` |
### 3.1 `BOOST_PRETTY_FUNCTION` support
By default, the `veryhigh` verbosity prints the function name from which the `LOG` macro was invoked. If you desire a more verbose function signature including the full namespace, return value and function arguments, you can enable support for `BOOST_PRETTY_FUNCTION`
* **globally** by compiling FairLogger with the CMake option `-DUSE_BOOST_PRETTY_FUNCTION=ON`, or
* **per translation unit** by defining `FAIRLOGGER_USE_BOOST_PRETTY_FUNCTION` before including the FairLogger header, e.g.
```C++
#define FAIRLOGGER_USE_BOOST_PRETTY_FUNCTION
#include <Logger.h>
```
In the latter case, the user needs to take care of adding the boost include path to the compiler search path manually (e.g. `-I/path/to/boost/include`).
## 4. Color
Colored output on console can be activated with:
```C++
Logger::SetConsoleColor(true);
```
When running a FairMQ device, the log color (console) can be simply provided via `--color <true/false>` cmd option (default is true).
## 5. File output
Output to file can be enabled via:
```C++
Logger::InitFileSink("<severity level>", "test_log", true);
```
which will add output to "test_log" filename (if third parameter is `true` it will add timestamp to the file name) with `<severity level>` severity.
When running a FairMQ device, the log file can be simply provided via `--log-to-file <filename_prefix>` cmd option (this will also turn off console output).
## 5.5 Custom sinks
Custom sinks can be added via `Logger::AddCustomSink("sink name", "<severity>", callback)` method.
Here is an example adding a custom sink for all severities ("trace" and above). It has access to the log content and meta data. Custom log calls are also thread-safe.
```C++
Logger::AddCustomSink("MyCustomSink", "trace", [](const string& content, const LogMetaData& metadata)
{
cout << "content: " << content << endl;
cout << "available metadata: " << endl;
cout << "std::time_t timestamp: " << metadata.timestamp << endl;
cout << "std::chrono::microseconds us: " << metadata.us.count() << endl;
cout << "std::string process_name: " << metadata.process_name << endl;
cout << "std::string file: " << metadata.file << endl;
cout << "std::string line: " << metadata.line << endl;
cout << "std::string func: " << metadata.func << endl;
cout << "std::string severity_name: " << metadata.severity_name << endl;
cout << "fair::Severity severity: " << static_cast<int>(metadata.severity) << endl;
});
```
If only output from custom sinks is desirable, console/file sinks must be deactivated by setting their severity to `"nolog"`.
## License

View File

@ -143,16 +143,20 @@ const string Logger::fProcessName = "?";
const unordered_map<string, Verbosity> Logger::fVerbosityMap =
{
{ "veryhigh", Verbosity::veryhigh },
{ "high", Verbosity::high },
{ "medium", Verbosity::medium },
{ "low", Verbosity::low },
{ "verylow", Verbosity::verylow },
{ "VERYHIGH", Verbosity::veryhigh },
{ "HIGH", Verbosity::high },
{ "MEDIUM", Verbosity::medium },
{ "LOW", Verbosity::low },
{ "VERYLOW", Verbosity::verylow }
{ "veryhigh", Verbosity::veryhigh },
{ "high", Verbosity::high },
{ "medium", Verbosity::medium },
{ "low", Verbosity::low },
{ "verylow", Verbosity::verylow },
{ "VERYHIGH", Verbosity::veryhigh },
{ "HIGH", Verbosity::high },
{ "MEDIUM", Verbosity::medium },
{ "LOW", Verbosity::low },
{ "VERYLOW", Verbosity::verylow },
{ "user1", Verbosity::user1 },
{ "user2", Verbosity::user2 },
{ "user3", Verbosity::user3 },
{ "user4", Verbosity::user4 }
};
const unordered_map<string, Severity> Logger::fSeverityMap =
@ -212,6 +216,34 @@ const array<string, 5> Logger::fVerbosityNames =
}
};
std::map<Verbosity, VerbositySpec> Logger::fVerbosities =
{
{ Verbosity::verylow, VerbositySpec::Make()
},
{ Verbosity::low, VerbositySpec::Make(VerbositySpec::Info::severity)
},
{ Verbosity::medium, VerbositySpec::Make(VerbositySpec::Info::timestamp_s,
VerbositySpec::Info::severity)
},
{ Verbosity::high, VerbositySpec::Make(VerbositySpec::Info::process_name,
VerbositySpec::Info::timestamp_s,
VerbositySpec::Info::severity)
},
{ Verbosity::veryhigh, VerbositySpec::Make(VerbositySpec::Info::process_name,
VerbositySpec::Info::timestamp_s,
VerbositySpec::Info::severity,
VerbositySpec::Info::file_line_function)
},
{ Verbosity::user1, VerbositySpec::Make(VerbositySpec::Info::severity)
},
{ Verbosity::user2, VerbositySpec::Make(VerbositySpec::Info::severity)
},
{ Verbosity::user3, VerbositySpec::Make(VerbositySpec::Info::severity)
},
{ Verbosity::user4, VerbositySpec::Make(VerbositySpec::Info::severity)
}
};
string Logger::SeverityName(Severity severity)
{
return fSeverityNames.at(static_cast<size_t>(severity));
@ -440,6 +472,23 @@ Verbosity Logger::GetVerbosity()
return fVerbosity;
}
void Logger::DefineVerbosity(const Verbosity verbosity, const VerbositySpec spec)
{
fVerbosities[verbosity] = spec;
}
void Logger::DefineVerbosity(const std::string& verbosityStr, const VerbositySpec spec)
{
if (fVerbosityMap.count(verbosityStr))
{
DefineVerbosity(fVerbosityMap.at(verbosityStr), spec);
}
else
{
LOG(error) << "Unknown verbosity: '" << verbosityStr;
}
}
void Logger::SetConsoleColor(const bool colored)
{
fColored = colored;
@ -583,57 +632,99 @@ Logger& Logger::Log()
}
}
auto spec = fVerbosities[fVerbosity];
if ((!fColored && LoggingToConsole()) || LoggingToFile())
{
if (fVerbosity >= Verbosity::high)
bool append_space = false;
for (const auto info : spec.fOrder)
{
fBWOut << "[" << fMetaData.process_name << "]"
<< "[" << tsstr << "." << setw(6) << setfill('0') << fMetaData.us.count() << "]";
}
else if (fVerbosity == Verbosity::medium)
{
fBWOut << "[" << tsstr << "]";
switch (info)
{
case VerbositySpec::Info::process_name:
fBWOut << "[" << fMetaData.process_name << "]";
append_space = true;
break;
case VerbositySpec::Info::timestamp_us:
fBWOut << "[" << tsstr << "." << setw(6) << setfill('0') << fMetaData.us.count() << "]";
append_space = true;
break;
case VerbositySpec::Info::timestamp_s:
fBWOut << "[" << tsstr << "]";
append_space = true;
break;
case VerbositySpec::Info::severity:
fBWOut << "[" << fMetaData.severity_name << "]";
append_space = true;
break;
case VerbositySpec::Info::file_line_function:
fBWOut << "[" << fMetaData.file << ":" << fMetaData.line << ":" << fMetaData.func << "]";
append_space = true;
break;
case VerbositySpec::Info::file_line:
fBWOut << "[" << fMetaData.file << ":" << fMetaData.line << "]";
append_space = true;
break;
case VerbositySpec::Info::file:
fBWOut << "[" << fMetaData.file << "]";
append_space = true;
break;
default:
break;
}
}
if (fVerbosity > Verbosity::verylow)
{
fBWOut << "[" << fMetaData.severity_name << "]";
}
if (fVerbosity == Verbosity::veryhigh)
{
fBWOut << "[" << fMetaData.file << ":" << fMetaData.line << ":" << fMetaData.func << "]";
}
if (fVerbosity != Verbosity::verylow)
if (append_space)
{
fBWOut << " ";
}
}
if (fColored && (LoggingToConsole()))
if (fColored && LoggingToConsole())
{
if (fVerbosity >= Verbosity::high)
bool append_space = false;
for (const auto info : spec.fOrder)
{
fColorOut << "[" << ColorOut(Color::fgBlue, fMetaData.process_name) << "]"
<< "[" << startColor(Color::fgCyan) << tsstr << "." << setw(6) << setfill('0') << fMetaData.us.count() << endColor() << "]";
}
else if (fVerbosity == Verbosity::medium)
{
fColorOut << "[" << startColor(Color::fgCyan) << tsstr << endColor() << "]";
switch (info)
{
case VerbositySpec::Info::process_name:
fColorOut << "[" << ColorOut(Color::fgBlue, fMetaData.process_name) << "]";
append_space = true;
break;
case VerbositySpec::Info::timestamp_us:
fColorOut << "[" << startColor(Color::fgCyan) << tsstr << "."
<< setw(6) << setfill('0') << fMetaData.us.count() << endColor() << "]";
append_space = true;
break;
case VerbositySpec::Info::timestamp_s:
fColorOut << "[" << startColor(Color::fgCyan) << tsstr << endColor() << "]";
append_space = true;
break;
case VerbositySpec::Info::severity:
fColorOut << "[" << ColoredSeverityWriter(fMetaData.severity) << "]";
append_space = true;
break;
case VerbositySpec::Info::file_line_function:
fColorOut << "[" << ColorOut(Color::fgBlue, fMetaData.file) << ":"
<< ColorOut(Color::fgYellow, fMetaData.line) << ":"
<< ColorOut(Color::fgBlue, fMetaData.func) << "]";
append_space = true;
break;
case VerbositySpec::Info::file_line:
fColorOut << "[" << ColorOut(Color::fgBlue, fMetaData.file) << ":"
<< ColorOut(Color::fgYellow, fMetaData.line) << "]";
append_space = true;
break;
case VerbositySpec::Info::file:
fColorOut << "[" << ColorOut(Color::fgBlue, fMetaData.file) << "]";
append_space = true;
break;
default:
break;
}
}
if (fVerbosity > Verbosity::verylow)
{
fColorOut << "[" << ColoredSeverityWriter(fMetaData.severity) << "]";
}
if (fVerbosity == Verbosity::veryhigh)
{
fColorOut << "[" << ColorOut(Color::fgBlue, fMetaData.file) << ":" << ColorOut(Color::fgYellow, fMetaData.line) << ":" << ColorOut(Color::fgBlue, fMetaData.func) << "]";
}
if (fVerbosity != Verbosity::verylow)
if (append_space)
{
fColorOut << " ";
}

View File

@ -18,11 +18,19 @@
#include <string>
#include <unordered_map>
#include <functional>
#include <unordered_map>
#include <map>
#include <chrono>
#include <mutex>
#include <utility> // pair
#include <time.h> // time_t
#include <array>
#include <type_traits>
#include <cassert>
#include <algorithm>
#ifdef FAIRLOGGER_USE_BOOST_PRETTY_FUNCTION
#include <boost/current_function.hpp>
#endif
namespace fair
{
@ -76,7 +84,64 @@ enum class Verbosity : int
LOW = low,
MEDIUM = medium,
HIGH = high,
VERYHIGH = veryhigh
VERYHIGH = veryhigh,
// extra slots for user-defined verbosities:
user1,
user2,
user3,
user4,
};
struct VerbositySpec
{
enum class Info : int
{
__empty__ = 0, // used to initialize order array
process_name, // [process name]
timestamp_s, // [HH:MM:SS]
timestamp_us, // [HH:MM:SS:µS]
severity, // [severity]
file, // [file]
file_line, // [file:line]
file_line_function, // [file:line:function]
__max__ // needs to be last in enum
};
std::array<Info, static_cast<int>(Info::__max__)> fOrder;
VerbositySpec() : fOrder({Info::__empty__}) {}
template<typename ... Ts>
static VerbositySpec Make(Ts ... options)
{
static_assert(sizeof...(Ts) < static_cast<int>(Info::__max__),
"Maximum number of VerbositySpec::Info parameters exceeded.");
return Make(VerbositySpec(), 0, options...);
}
private:
template<typename T, typename ... Ts>
static VerbositySpec Make(VerbositySpec spec, int i, T option, Ts ... options)
{
static_assert(std::is_same<T, Info>::value,
"Only arguments of type VerbositySpec::Info are allowed.");
assert(option > Info::__empty__);
assert(option < Info::__max__);
if (std::find(spec.fOrder.begin(), spec.fOrder.end(), option) == spec.fOrder.end()) {
spec.fOrder[i] = option;
++i;
}
return Make(spec, i, options ...);
}
static VerbositySpec Make(VerbositySpec spec, int)
{
return spec;
}
};
// non-std exception to avoid undesirable catches - fatal should exit in a way we want.
@ -138,6 +203,8 @@ class Logger
static void SetVerbosity(const Verbosity verbosity);
static void SetVerbosity(const std::string& verbosityStr);
static Verbosity GetVerbosity();
static void DefineVerbosity(const Verbosity, VerbositySpec);
static void DefineVerbosity(const std::string& verbosityStr, VerbositySpec);
static void SetConsoleColor(const bool colored = true);
@ -217,6 +284,8 @@ class Logger
bool LoggingCustom(const Severity) const;
static void UpdateMinSeverity();
static std::map<Verbosity, VerbositySpec> fVerbosities;
};
} // namespace fair
@ -224,9 +293,15 @@ class Logger
#define IMP_CONVERTTOSTRING(s) # s
#define CONVERTTOSTRING(s) IMP_CONVERTTOSTRING(s)
#ifdef FAIRLOGGER_USE_BOOST_PRETTY_FUNCTION
#define LOG(severity) \
for (bool fairLOggerunLikelyvariable = false; fair::Logger::Logging(fair::Severity::severity) && !fairLOggerunLikelyvariable; fairLOggerunLikelyvariable = true) \
fair::Logger(fair::Severity::severity, __FILE__, CONVERTTOSTRING(__LINE__), BOOST_CURRENT_FUNCTION).Log()
#else
#define LOG(severity) \
for (bool fairLOggerunLikelyvariable = false; fair::Logger::Logging(fair::Severity::severity) && !fairLOggerunLikelyvariable; fairLOggerunLikelyvariable = true) \
fair::Logger(fair::Severity::severity, __FILE__, CONVERTTOSTRING(__LINE__), __FUNCTION__).Log()
#endif
// with custom file, line, function
#define LOGD(severity, file, line, function) \

View File

@ -18,6 +18,9 @@
using namespace std;
using namespace fair;
namespace test
{
void printEverySeverity()
{
static int i = 1;
@ -35,25 +38,39 @@ void printEverySeverity()
LOG(trace) << "trace message " << i++;
}
}
void printAllVerbositiesWithSeverity(Severity sev)
{
Logger::SetConsoleSeverity(sev);
cout << endl << "cout: >>> testing severity '" << Logger::SeverityName(sev) << "' with 'verylow' verbosity..." << endl;
Logger::SetVerbosity(Verbosity::verylow);
printEverySeverity();
test::printEverySeverity();
cout << endl << "cout: >>> testing severity '" << Logger::SeverityName(sev) << "' with 'low' verbosity..." << endl;
Logger::SetVerbosity(Verbosity::low);
printEverySeverity();
test::printEverySeverity();
cout << endl << "cout: >>> testing severity '" << Logger::SeverityName(sev) << "' with 'medium' verbosity..." << endl;
Logger::SetVerbosity(Verbosity::medium);
printEverySeverity();
test::printEverySeverity();
cout << endl << "cout: >>> testing severity '" << Logger::SeverityName(sev) << "' with 'high' verbosity..." << endl;
Logger::SetVerbosity(Verbosity::high);
printEverySeverity();
test::printEverySeverity();
cout << endl << "cout: >>> testing severity '" << Logger::SeverityName(sev) << "' with 'veryhigh' verbosity..." << endl;
Logger::SetVerbosity(Verbosity::veryhigh);
printEverySeverity();
test::printEverySeverity();
cout << endl << "cout: >>> testing severity '" << Logger::SeverityName(sev) << "' with 'user1' verbosity..." << endl;
Logger::SetVerbosity(Verbosity::user1);
test::printEverySeverity();
cout << endl << "cout: >>> testing severity '" << Logger::SeverityName(sev) << "' with 'user2' verbosity..." << endl;
Logger::SetVerbosity(Verbosity::user2);
test::printEverySeverity();
cout << endl << "cout: >>> testing severity '" << Logger::SeverityName(sev) << "' with 'user3' verbosity..." << endl;
Logger::SetVerbosity(Verbosity::user3);
test::printEverySeverity();
cout << endl << "cout: >>> testing severity '" << Logger::SeverityName(sev) << "' with 'user4' verbosity..." << endl;
Logger::SetVerbosity(Verbosity::user4);
test::printEverySeverity();
}
void silentlyPrintAllVerbositiesWithSeverity(Severity sev)
@ -61,21 +78,34 @@ void silentlyPrintAllVerbositiesWithSeverity(Severity sev)
Logger::SetConsoleSeverity(sev);
Logger::SetVerbosity(Verbosity::verylow);
printEverySeverity();
test::printEverySeverity();
Logger::SetVerbosity(Verbosity::low);
printEverySeverity();
test::printEverySeverity();
Logger::SetVerbosity(Verbosity::medium);
printEverySeverity();
test::printEverySeverity();
Logger::SetVerbosity(Verbosity::high);
printEverySeverity();
test::printEverySeverity();
Logger::SetVerbosity(Verbosity::veryhigh);
printEverySeverity();
test::printEverySeverity();
Logger::SetVerbosity(Verbosity::user1);
test::printEverySeverity();
Logger::SetVerbosity(Verbosity::user2);
test::printEverySeverity();
Logger::SetVerbosity(Verbosity::user3);
test::printEverySeverity();
Logger::SetVerbosity(Verbosity::user4);
test::printEverySeverity();
}
int main()
{
Logger::SetConsoleColor(true);
auto spec = VerbositySpec::Make(VerbositySpec::Info::file_line_function,
VerbositySpec::Info::process_name,VerbositySpec::Info::process_name);
cout << "Defining custom verbosity \"user2\"" << endl;
Logger::DefineVerbosity(Verbosity::user2, spec);
cout << "cout: testing severities..." << endl;
printAllVerbositiesWithSeverity(Severity::trace);
@ -133,7 +163,7 @@ int main()
cout << "cout: ----------------------------" << endl;
cout << "cout: open log file with severity 'error'" << endl;
Logger::InitFileSink(Severity::error, "test_log", true);
printEverySeverity();
test::printEverySeverity();
cout << "cout: closing log file" << endl;
Logger::RemoveFileSink();
@ -158,7 +188,7 @@ int main()
cout << "CustomSink: \tfair::Severity severity: " << static_cast<int>(metadata.severity) << endl;
});
printEverySeverity();
test::printEverySeverity();
cout << endl << "cout: removing custom sink with info severity" << endl;
@ -166,6 +196,5 @@ int main()
Logger::RemoveCustomSink("CustomSink");
Logger::RemoveCustomSink("bla");
return 0;
}