G3log placeholder thread ID formatting (#248)

* Added thread ID configurable through API calls. Left to do g3sinks, documentation and some corner test cases for CHECK, LOG(FATAL) and FATAL signal

* improve test script, break if error

* easier to use API. Api docs added

* Update API.markdown

* Update API.markdown

* Update API.markdown

* updated readme with details for overriding default for "full details"

* updated custom sink with custom formatting example
This commit is contained in:
Kjell Hedström 2018-03-08 09:16:12 -07:00 committed by GitHub
parent f2b860a2b4
commit 14db37ad23
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
13 changed files with 363 additions and 69 deletions

View File

@ -7,6 +7,12 @@ Most of the API that you need for using g3log is described in this readme. For m
* disable/enabled levels at runtime
* custom logging levels
* Sink [creation](#sink_creation) and utilization
* Custom [log formatting](#log_formatting)
* Overriding the Default File Sink's file header
* Overriding the Default FileSink's log formatting
* Adding thread ID to the log formatting
* Override log formatting in a default and custom sinks
* Override the log formatting in the default sink
* LOG [flushing](#log_flushing)
* G3log and G3Sinks [usage example](#g3log-and-sink-usage-code-example)
* Support for [dynamic message sizing](#dynamic_message_sizing)
@ -107,10 +113,91 @@ With the default id left as is (i.e. "g3log") a creation of the logger in the un
```
The resulting filename would be something like:
```
./(ReplaceLogFile).g3log.20160217-001406.log
./(ReplaceLogFile).g3log.20160217-001406.log
```
## Custom LOG <a name="log_formatting">formatting</a>
### Overriding the Default File Sink's file header
The default file header can be customized in the default file sink in calling
```
FileSink::overrideLogHeader(std::string);
```
### Overriding the Default FileSink's log formatting
The default log formatting is defined in `LogMessage.hpp`
```
static std::string DefaultLogDetailsToString(const LogMessage& msg);
```
### Adding thread ID to the log formatting
An "all details" log formatting function is also defined - this one also adds the "calling thread's ID"
```
static std::string FullLogDetailsToString(const LogMessage& msg);
```
### Override log formatting in default and custom sinks
The default log formatting look can be overriden by any sink.
If the sink receiving function calls `toString()` then the default log formatting will be used.
If the sink receiving function calls `toString(&XFunc)` then the `XFunc`will be used instead (see `LogMessage.h/cpp` for code details if it is not clear). (`XFunc` is a place holder for *your* formatting function of choice).
The API for the function-ptr to pass in is
```
std::string (*) (const LogMessage&)
```
or for short as defined in `LogMessage.h`
```
using LogDetailsFunc = std::string (*) (const LogMessage&);
```
### Override the log formatting in the default sink
For convenience the *Default* sink has a function
for doing exactly this
```
void overrideLogDetails(LogMessage::LogDetailsFunc func);
```
Example code for replacing the default log formatting for "full details" formatting (it adds thread ID)
```
auto worker = g3::LogWorker::createLogWorker();
auto handle= worker->addDefaultLogger(argv[0], path_to_log_file);
g3::initializeLogging(worker.get());
handle->call(&g3::FileSink::overrideLogDetails, &LogMessage::FullLogDetailsToString);
```
See [test_message.cpp](http://www.github.com/KjellKod/g3log/test_unit/test_message.cpp) for details and testing
Example code for overloading the formatting of a custom sink. The log formatting function will be passed into the
`LogMessage::toString(...)` this will override the default log formatting
Example
```
namespace {
std::string MyCustomFormatting(const LogMessage& msg) {
... how you want it ...
}
}
void MyCustomSink::ReceiveLogEntry(LogMessageMover message) {
std::string formatted = message.get().toString(&MyCustomFormatting) << std::flush;
}
...
...
auto worker = g3::LogWorker::createLogWorker();
auto sinkHandle = worker->addSink(std::make_unique<MyCustomSink>(),
&MyCustomSink::ReceiveLogMessage);
// ReceiveLogMessage(...) will used the custom formatting function "MyCustomFormatting(...)
```
## LOG <a name="log_flushing">flushing</a>
The default file sink will flush each log entry as it comes in. For different flushing policies please take a look at g3sinks [logrotate and LogRotateWithFilters](http://www.github.com/KjellKod/g3sinks/logrotate).

View File

@ -39,6 +39,17 @@ int main(int argc, char **argv)
auto handle= worker->addDefaultLogger(argv[0], path_to_log_file);
g3::initializeLogging(worker.get());
std::future<std::string> log_file_name = handle->call(&g3::FileSink::fileName);
// Exmple of overriding the default formatting of log entry
auto changeFormatting = handle->call(&g3::FileSink::overrideLogDetails, g3::LogMessage::FullLogDetailsToString);
const std::string newHeader = "\t\tLOG format: [YYYY/MM/DD hh:mm:ss uuu* LEVEL THREAD_ID FILE->FUNCTION:LINE] message\n\t\t(uuu*: microseconds fractions of the seconds value)\n\n";
// example of ovrriding the default formatting of header
auto changeHeader = handle->call(&g3::FileSink::overrideLogHeader, newHeader);
changeFormatting.wait();
changeHeader.wait();
std::cout << "* This is an example of g3log. It WILL exit by a failed CHECK(...)" << std::endl;
std::cout << "* that acts as a FATAL trigger. Please see the generated log and " << std::endl;
std::cout << "* compare to the code at:\n* \t g3log/test_example/main_contract.cpp" << std::endl;

View File

@ -12,5 +12,5 @@ cmake -DCMAKE_CXX_FLAGS=-std=c++14 -DADD_G3LOG_UNIT_TEST=ON ..
makeArg=`grep -c ^processor /proc/cpuinfo`
make -j$makeArg
../scripts/runAllTests.sh
/bin/bash ../scripts/runAllTests.sh

View File

@ -1,12 +1,30 @@
#!/bin/bash
set -ev
set -x
set -v
#set -x
./test_concept_sink && \
./test_cpp_future_concepts && \
./test_dynamic_loaded_shared_lib | true && \
./test_filechange && \
./test_io && \
./test_sink && \
./test_message
test_execs=`find ./test_* -perm /u=x`
echo "Tests to run: $test_execs"
while read -r testsuite; do
./"$testsuite"
if [ "$?" -ne 0 ]; then
echo "Aborting. \"$testsuite\" had failing test(s)"
exit 1
fi
done <<< "$test_execs"
#option 2
#find ./test_* -perm /u=x -exec '{}' ';'
# option 3
#./test_concept_sink && \
#./test_cpp_future_concepts && \
#./test_dynamic_loaded_shared_lib | true && \
#./test_filechange && \
#./test_io && \
#./test_sink && \
#./test_message

View File

@ -14,11 +14,13 @@
namespace g3 {
using namespace internal;
FileSink::FileSink(const std::string &log_prefix, const std::string &log_directory, const std::string& logger_id)
: _log_file_with_path(log_directory)
: _log_details_func(&LogMessage::DefaultLogDetailsToString)
,_log_file_with_path(log_directory)
, _log_prefix_backup(log_prefix)
, _outptr(new std::ofstream)
, _header("\t\tLOG format: [YYYY/MM/DD hh:mm:ss uuu* LEVEL FILE->FUNCTION:LINE] messagen\n\t\t(uuu*: microseconds fractions of the seconds value)\n\n")
, _firstEntry(true)
{
_log_prefix_backup = prefixSanityFix(log_prefix);
if (!isValidFilename(_log_prefix_backup)) {
@ -36,7 +38,7 @@ namespace g3 {
_outptr = createLogFile(_log_file_with_path);
}
assert(_outptr && "cannot open log file at startup");
addLogFileHeader();
}
@ -52,8 +54,13 @@ namespace g3 {
// The actual log receiving function
void FileSink::fileWrite(LogMessageMover message) {
if (_firstEntry ) {
addLogFileHeader();
_firstEntry = false;
}
std::ofstream &out(filestream());
out << message.get().toString() << std::flush;
out << message.get().toString(_log_details_func) << std::flush;
}
std::string FileSink::changeLogFile(const std::string &directory, const std::string &logger_id) {
@ -87,8 +94,17 @@ namespace g3 {
std::string FileSink::fileName() {
return _log_file_with_path;
}
void FileSink::addLogFileHeader() {
filestream() << header();
void FileSink::overrideLogDetails(LogMessage::LogDetailsFunc func) {
_log_details_func = func;
}
void FileSink::overrideLogHeader(const std::string& change) {
_header = change;
}
void FileSink::addLogFileHeader() {
filestream() << header(_header);
}
} // g3

View File

@ -76,13 +76,12 @@ namespace g3 {
return path;
}
std::string header() {
std::string header(const std::string& headerFormat) {
std::ostringstream ss_entry;
// Day Month Date Time Year: is written as "%a %b %d %H:%M:%S %Y" and formatted output as : Wed Sep 19 08:28:16 2012
auto now = std::chrono::system_clock::now();
ss_entry << "\t\tg3log created log at: " << g3::localtime_formatted(now, "%a %b %d %H:%M:%S %Y") << "\n";
ss_entry << "\t\tLOG format: [YYYY/MM/DD hh:mm:ss uuu* LEVEL FILE->FUNCTION:LINE] message";
ss_entry << "\t\t(uuu*: microseconds fractions of the seconds value)\n\n";
ss_entry << headerFormat;
return ss_entry.str();
}

View File

@ -21,12 +21,18 @@ namespace g3 {
void fileWrite(LogMessageMover message);
std::string changeLogFile(const std::string &directory, const std::string &logger_id);
std::string fileName();
void overrideLogDetails(LogMessage::LogDetailsFunc func);
void overrideLogHeader(const std::string& change);
private:
LogMessage::LogDetailsFunc _log_details_func;
std::string _log_file_with_path;
std::string _log_prefix_backup; // needed in case of future log file changes of directory
std::unique_ptr<std::ofstream> _outptr;
std::string _header;
bool _firstEntry;
void addLogFileHeader();
std::ofstream &filestream() {

View File

@ -73,11 +73,11 @@ struct LogCapture {
std::ostringstream _stream;
std::string _stack_trace;
const char *_file;
const char* _file;
const int _line;
const char *_function;
const char* _function;
const LEVELS &_level;
const char *_expression;
const char* _expression;
const g3::SignalType _fatal_signal;
};

View File

@ -67,7 +67,6 @@ namespace g3 {
std::string threadID() const;
std::string toString() const;
void setExpression(const std::string expression) {
_expression = expression;
}
@ -76,17 +75,45 @@ namespace g3 {
LogMessage& operator=(LogMessage other);
LogMessage(const std::string& file, const int line, const std::string& function, const LEVELS& level);
LogMessage(std::string file, const int line, std::string function, const LEVELS level);
explicit LogMessage(const std::string& fatalOsSignalCrashMessage);
LogMessage(const LogMessage& other);
LogMessage(LogMessage&& other);
virtual ~LogMessage() {}
// helper log printing functions used by "toString()"
static std::string splitFileName(const std::string& str);
static std::string fatalSignalToString(const LogMessage& msg);
// windows only: fatalExceptionToString
static std::string fatalExceptionToString(const LogMessage& msg);
static std::string fatalLogToString(const LogMessage& msg);
static std::string fatalCheckToString(const LogMessage& msg);
static std::string normalToString(const LogMessage& msg);
// the default formatting option
static std::string DefaultLogDetailsToString(const LogMessage& msg);
// this function can be used by the logging sink to add thread ID
// see this concept and it is easy to make your own custom formatting
static std::string FullLogDetailsToString(const LogMessage& msg);
using LogDetailsFunc = std::string (*) (const LogMessage&);
std::string toString(LogDetailsFunc formattingFunc = DefaultLogDetailsToString) const;
void overrideLogDetailsFunc(LogDetailsFunc func) const;
//
// Complete access to the raw data in case the helper functions above
// are not enough.
//
mutable LogDetailsFunc _logDetailsToStringFunc;
g3::high_resolution_time_point _timestamp;
std::thread::id _call_thread_id;
std::string _file;
@ -113,6 +140,7 @@ namespace g3 {
};
/** Trigger for flushing the message queue and exiting the application

View File

@ -11,37 +11,20 @@
#include "g3log/time.hpp"
#include <mutex>
namespace {
std::string splitFileName(const std::string& str) {
size_t found;
found = str.find_last_of("(/\\");
return str.substr(found + 1);
}
} // anonymous
namespace g3 {
// helper for setting the normal log details in an entry
std::string LogDetailsToString(const LogMessage& msg) {
std::string out;
out.append(msg.timestamp() + "\t"
+ msg.level() + " [" + msg.file() + "->" + msg.function() + ":" + msg.line() + "]\t");
return out;
std::string LogMessage::splitFileName(const std::string& str) {
size_t found;
found = str.find_last_of("(/\\");
return str.substr(found + 1);
}
// helper for normal
std::string normalToString(const LogMessage& msg) {
auto out = LogDetailsToString(msg);
out.append(msg.message() + '\n');
return out;
}
// helper for fatal signal
std::string fatalSignalToString(const LogMessage& msg) {
std::string LogMessage::fatalSignalToString(const LogMessage& msg) {
std::string out; // clear any previous text and formatting
out.append(msg.timestamp()
+ "\n\n***** FATAL SIGNAL RECEIVED ******* \n"
@ -51,7 +34,7 @@ namespace g3 {
// helper for fatal exception (windows only)
std::string fatalExceptionToString(const LogMessage& msg) {
std::string LogMessage::fatalExceptionToString(const LogMessage& msg) {
std::string out; // clear any previous text and formatting
out.append(msg.timestamp()
+ "\n\n***** FATAL EXCEPTION RECEIVED ******* \n"
@ -61,48 +44,94 @@ namespace g3 {
// helper for fatal LOG
std::string fatalLogToString(const LogMessage& msg) {
auto out = LogDetailsToString(msg);
std::string LogMessage::fatalLogToString(const LogMessage& msg) {
auto out = msg._logDetailsToStringFunc(msg);
static const std::string fatalExitReason = {"EXIT trigger caused by LOG(FATAL) entry: "};
out.append("\n\t*******\t " + fatalExitReason + "\n\t" + '"' + msg.message() + '"');
return out;
}
// helper for fatal CHECK
std::string fatalCheckToString(const LogMessage& msg) {
auto out = LogDetailsToString(msg);
std::string LogMessage::fatalCheckToString(const LogMessage& msg) {
auto out = msg._logDetailsToStringFunc(msg);
static const std::string contractExitReason = {"EXIT trigger caused by broken Contract:"};
out.append("\n\t*******\t " + contractExitReason + " CHECK(" + msg.expression() + ")\n\t"
+ '"' + msg. message() + '"');
return out;
}
// helper for setting the normal log details in an entry
std::string LogMessage::DefaultLogDetailsToString(const LogMessage& msg) {
std::string out;
out.append(msg.timestamp() + "\t"
+ msg.level()
+ " ["
+ msg.file()
+ "->"
+ msg.function()
+ ":" + msg.line() + "]\t");
return out;
}
std::string LogMessage::FullLogDetailsToString(const LogMessage& msg) {
std::string out;
out.append(msg.timestamp() + "\t"
+ msg.level()
+ " ["
+ msg.threadID()
+ " "
+ msg.file()
+ "->"+ msg.function()
+ ":" + msg.line() + "]\t");
return out;
}
// helper for normal
std::string LogMessage::normalToString(const LogMessage& msg) {
auto out = msg._logDetailsToStringFunc(msg);
out.append(msg.message() + '\n');
return out;
}
// end static functions section
void LogMessage::overrideLogDetailsFunc(LogDetailsFunc func) const{
_logDetailsToStringFunc = func;
}
// Format the log message according to it's type
std::string LogMessage::toString() const {
std::string LogMessage::toString(LogDetailsFunc formattingFunc) const {
overrideLogDetailsFunc(formattingFunc);
if (false == wasFatal()) {
return normalToString(*this);
return LogMessage::normalToString(*this);
}
const auto level_value = _level.value;
if (internal::FATAL_SIGNAL.value == _level.value) {
return fatalSignalToString(*this);
return LogMessage::fatalSignalToString(*this);
}
if (internal::FATAL_EXCEPTION.value == _level.value) {
return fatalExceptionToString(*this);
return LogMessage::fatalExceptionToString(*this);
}
if (FATAL.value == _level.value) {
return fatalLogToString(*this);
return LogMessage::fatalLogToString(*this);
}
if (internal::CONTRACT.value == level_value) {
return fatalCheckToString(*this);
return LogMessage::fatalCheckToString(*this);
}
// What? Did we hit a custom made level?
auto out = LogDetailsToString(*this);
auto out = _logDetailsToStringFunc(*this);
static const std::string errorUnknown = {"UNKNOWN or Custom made Log Message Type"};
out.append("\t*******" + errorUnknown + "\n\t" + message() + '\n');
return out;
@ -123,14 +152,14 @@ namespace g3 {
}
LogMessage::LogMessage(const std::string& file, const int line,
const std::string& function, const LEVELS& level)
: _timestamp(std::chrono::high_resolution_clock::now())
LogMessage::LogMessage(std::string file, const int line,
std::string function, const LEVELS level)
: _logDetailsToStringFunc(LogMessage::DefaultLogDetailsToString)
, _timestamp(std::chrono::high_resolution_clock::now())
, _call_thread_id(std::this_thread::get_id())
, _file(LogMessage::splitFileName(file))
#if defined(G3_LOG_FULL_FILENAME)
, _file(file)
#else
, _file(splitFileName(file))
#endif
, _file_path(file)
, _line(line)
@ -145,7 +174,8 @@ namespace g3 {
}
LogMessage::LogMessage(const LogMessage& other)
: _timestamp(other._timestamp)
: _logDetailsToStringFunc(other._logDetailsToStringFunc)
, _timestamp(other._timestamp)
, _call_thread_id(other._call_thread_id)
, _file(other._file)
, _file_path(other._file_path)
@ -157,7 +187,8 @@ namespace g3 {
}
LogMessage::LogMessage(LogMessage&& other)
: _timestamp(other._timestamp)
: _logDetailsToStringFunc(other._logDetailsToStringFunc)
, _timestamp(other._timestamp)
, _call_thread_id(other._call_thread_id)
, _file(std::move(other._file))
, _file_path(std::move(other._file_path))

View File

@ -103,12 +103,14 @@ namespace g3 {
using namespace g3;
using namespace g3::internal;
TEST(ConceptSink, CreateHandle) {
Worker worker;
auto handle = worker.addSink(CoutSink::createSink(), &CoutSink::save);
ASSERT_NE(nullptr, handle.get());
}
TEST(ConceptSink, OneSink__VerifyMsgIn) {
Worker worker;
auto handle = worker.addSink(CoutSink::createSink(), &CoutSink::save);

View File

@ -13,15 +13,110 @@
#include <ctime>
#include <cstdlib>
#include <g3log/generated_definitions.hpp>
#include <testing_helpers.h>
#include <g3log/filesink.hpp>
namespace {
// https://www.epochconverter.com/
// epoc value for: Thu, 27 Apr 2017 06:22:49 GMT
time_t k2017_April_27th = 1493274147;
auto kTimePoint_2017_April_27th = std::chrono::system_clock::from_time_t(k2017_April_27th);
std::chrono::time_point<std::chrono::system_clock> k1970_January_1st = {};
const std::string kFile = __FILE__;
const int kLine = 123;
const std::string kFunction = "MyTest::Foo";
const LEVELS kLevel = INFO;
const std::string testdirectory = "./";
}
TEST(Message, DefaultLogDetals_toString) {
using namespace g3;
LogMessage msg{kFile, kLine, kFunction, kLevel};
auto details = LogMessage::DefaultLogDetailsToString(msg);
auto details2 = msg._logDetailsToStringFunc(msg);
EXPECT_EQ(details, details2);
}
TEST(Message, Default_toString) {
using namespace g3;
LogMessage msg{kFile, kLine, kFunction, kLevel};
auto details = LogMessage::DefaultLogDetailsToString(msg);
auto output = msg.toString();
testing_helpers::verifyContent(output, details);
}
TEST(Message, UseOverride_4_DetailsWithThreadID_toString) {
using namespace g3;
LogMessage msg{kFile, kLine, kFunction, kLevel};
msg.overrideLogDetailsFunc(&LogMessage::FullLogDetailsToString);
auto output = msg.toString();
std::ostringstream thread_id_oss;
thread_id_oss << std::this_thread::get_id();
testing_helpers::verifyContent(output, thread_id_oss.str());
testing_helpers::verifyContent(output, kFile);
testing_helpers::verifyContent(output, kLevel.text);
testing_helpers::verifyContent(output, kFunction);
testing_helpers::verifyContent(output, std::to_string(kLine));
std::cout << output << std::endl;
}
TEST(Message, UseLogCall_4_DetailsWithThreadID_toString) {
using namespace g3;
LogMessage msg{kFile, kLine, kFunction, kLevel};
auto output = msg.toString(&LogMessage::FullLogDetailsToString);
std::ostringstream thread_id_oss;
thread_id_oss << std::this_thread::get_id();
testing_helpers::verifyContent(output, thread_id_oss.str());
testing_helpers::verifyContent(output, kFile);
testing_helpers::verifyContent(output, kLevel.text);
testing_helpers::verifyContent(output, kFunction);
testing_helpers::verifyContent(output, std::to_string(kLine));
std::cout << output << std::endl;
}
TEST(Message, DefaultFormattingToLogFile) {
using namespace g3;
std::string file_content;
{
testing_helpers::RestoreFileLogger logger(testdirectory);
LOG(WARNING) << "testing";
logger.reset(); // force flush of logger (which will trigger a shutdown)
file_content = testing_helpers::readFileToText(logger.logFile()); // logger is already reset
}
std::ostringstream thread_id_oss;
thread_id_oss << " [" << std::this_thread::get_id() << " ";
EXPECT_FALSE(testing_helpers::verifyContent(file_content, thread_id_oss.str()));
}
TEST(Message, FullFormattingToLogFile) {
using namespace g3;
std::string file_content;
{
testing_helpers::RestoreFileLogger logger(testdirectory);
logger._handle->call(&FileSink::overrideLogDetails, &LogMessage::FullLogDetailsToString);
LOG(WARNING) << "testing";
logger.reset(); // force flush of logger (which will trigger a shutdown)
file_content = testing_helpers::readFileToText(logger.logFile()); // logger is already reset
}
std::ostringstream thread_id_oss;
thread_id_oss << " [" << std::this_thread::get_id() << " ";
EXPECT_TRUE(testing_helpers::verifyContent(file_content, thread_id_oss.str()));
}
TEST(Message, CppSupport) {
// ref: http://www.cplusplus.com/reference/clibrary/ctime/strftime/
// ref: http://en.cppreference.com/w/cpp/io/manip/put_time
@ -105,6 +200,8 @@ TEST(Message, GetFractional_All) {
EXPECT_EQ(fractional, expected);
}
TEST(Message, FractionalToString_SizeCheck) {
auto value = g3::internal::to_string(kTimePoint_2017_April_27th, g3::internal::Fractional::Nanosecond);
EXPECT_EQ("000000000", value);
@ -189,7 +286,6 @@ TEST(Message, localtime_formatted) {
}
#endif // timezone
#if defined(CHANGE_G3LOG_DEBUG_TO_DBUG)
TEST(Level, G3LogDebug_is_DBUG) {
LOG(DBUG) << "DBUG equals G3LOG_DEBUG";

View File

@ -104,7 +104,7 @@ struct RestoreFileLogger {
std::string resetAndRetrieveContent();
private:
std::unique_ptr<g3::SinkHandle<g3::FileSink>> _handle;
std::string _log_file;
};