Skip to content

Port LoggingTest improvements from #2087. #2126

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
Dimi1010 wants to merge 1 commit into
base: dev
Choose a base branch
from
+147 −96
Open

Port LoggingTest improvements from #2087. #2126

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
243 changes: 147 additions & 96 deletions Tests/Pcap++Test/Tests/LoggerTests.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -34,66 +34,86 @@ namespace pcpp
class LogPrinter
{
public:
static int lastLogLevelSeen;
static std::string* lastLogMessageSeen;
static std::string* lastFilenameSeen;
static std::string* lastMethodSeen;
static int lastLineSeen;

static void logPrinter(pcpp::Logger::LogLevel logLevel, const std::string& logMessage, const std::string& fileName,
const std::string& method, const int line)
struct LogInfo
{
LogPrinter::clean();
LogPrinter::lastLogLevelSeen = (int)logLevel;
LogPrinter::lastLogMessageSeen = new std::string(logMessage);
LogPrinter::lastFilenameSeen = new std::string(fileName);
LogPrinter::lastMethodSeen = new std::string(method);
LogPrinter::lastLineSeen = line;
int logLevel;
std::string message;
std::string filename;
std::string method;
int line;
};

LogPrinter()
{
// Huge reservation to avoid reallocations.
lastLog.message.reserve(1000);
lastLog.filename.reserve(1000);
lastLog.method.reserve(1000);
}

static void clean()
void onLogMessage(pcpp::Logger::LogLevel logLevel, const std::string& logMessage, const std::string& fileName,
const std::string& method, const int line)
{
LogPrinter::lastLogLevelSeen = 999;
LogPrinter::lastLineSeen = 99999;
if (LogPrinter::lastLogMessageSeen != nullptr)
{
delete LogPrinter::lastLogMessageSeen;
LogPrinter::lastLogMessageSeen = nullptr;
}
if (LogPrinter::lastFilenameSeen != nullptr)
{
delete LogPrinter::lastFilenameSeen;
LogPrinter::lastFilenameSeen = nullptr;
}
std::lock_guard<std::mutex> lock(LogPrinter::logPrinterMutex);

lastLogValid = true;
lastLog.logLevel = (int)logLevel;
lastLog.message = logMessage;
lastLog.filename = fileName;
lastLog.method = method;
lastLog.line = line;
}

if (LogPrinter::lastMethodSeen != nullptr)
void clean()
{
std::lock_guard<std::mutex> lock(logPrinterMutex);
lastLogValid = false;
}

LogInfo const* getLastLog() const
{
if (lastLogValid)
{
delete LogPrinter::lastMethodSeen;
LogPrinter::lastMethodSeen = nullptr;
return &lastLog;
}
return nullptr;
}
};

int LogPrinter::lastLogLevelSeen = 999;
std::string* LogPrinter::lastLogMessageSeen = nullptr;
std::string* LogPrinter::lastFilenameSeen = nullptr;
std::string* LogPrinter::lastMethodSeen = nullptr;
int LogPrinter::lastLineSeen = 99999;
private:
bool lastLogValid = false;
LogInfo lastLog;
std::mutex logPrinterMutex;
};

class MultiThreadLogCounter
{
public:
static const int ThreadCount = 5;
static int logMessageThreadCount[ThreadCount];
static void logPrinter(pcpp::Logger::LogLevel logLevel, const std::string& logMessage, const std::string& fileName,
const std::string& method, const int line)
// alignas(64) to avoid false sharing between threads when updating the logMessagesCount variable
struct alignas(64) ThreadLogCounter
{
int logMessagesCount = 0;
};

std::vector<ThreadLogCounter> counters;

MultiThreadLogCounter(size_t numThreads)
{
int threadId = logMessage[logMessage.length() - 1] - '0';
MultiThreadLogCounter::logMessageThreadCount[threadId]++;
counters.resize(numThreads);
}
};

int MultiThreadLogCounter::logMessageThreadCount[MultiThreadLogCounter::ThreadCount] = { 0, 0, 0, 0, 0 };
void onLogMessage(pcpp::Logger::LogLevel logLevel, const std::string& logMessage, const std::string& fileName,
const std::string& method, const int line)
{
if (logMessage.empty())
return;

int threadId = logMessage.back() - '0';
if (threadId < 0 || threadId >= counters.size())
return;

counters[threadId].logMessagesCount++;
}
};

// clang-format off
#if defined(_WIN32)
Expand Down Expand Up @@ -148,19 +168,19 @@ class LoggerCleaner
pcpp::Logger::getInstance().setAllModulesToLogLevel(pcpp::LogLevel::Info);
pcpp::Logger::getInstance().resetLogPrinter();
std::cout.clear();
LogPrinter::clean();
}
};

void printLogThread(int threadId)
void printLogThread(int threadId, int numMessages)
{
std::random_device rd;
std::mt19937 simpleRand(rd());
std::uniform_int_distribution<int> dist(1, 5);
std::ostringstream sstream;
sstream << threadId;
std::string threadIdAsString = sstream.str();
for (int i = 0; i < 1000; i++)

for (int i = 0; i < numMessages; i++)
{
pcpp::invokeErrorLog(threadIdAsString);
int sleepTime = dist(simpleRand);
Expand All @@ -170,16 +190,27 @@ void printLogThread(int threadId)

PTF_TEST_CASE(TestLoggerMultiThread)
{
constexpr int threadCount = 5;
MultiThreadLogCounter logCounter(threadCount);

// cppcheck-suppress unusedVariable
LoggerCleaner loggerCleaner;

std::thread threads[MultiThreadLogCounter::ThreadCount];
std::thread threads[threadCount];

pcpp::Logger::getInstance().setLogPrinter(&MultiThreadLogCounter::logPrinter);
// clang-format off
pcpp::Logger::getInstance().setLogPrinter([&](pcpp::Logger::LogLevel logLevel, const std::string& logMessage,
const std::string& fileName, const std::string& method, const int line) {
logCounter.onLogMessage(logLevel, logMessage, fileName, method, line);
});
// clang-format on

for (int i = 0; i < MultiThreadLogCounter::ThreadCount; i++)
constexpr int messagesPerThread = 1000;
const int expectedTotalMessages = messagesPerThread * threadCount;

for (int i = 0; i < threadCount; i++)
{
threads[i] = std::thread(printLogThread, i);
threads[i] = std::thread(printLogThread, i, messagesPerThread);
}

for (auto& thread : threads)
Expand All @@ -188,13 +219,13 @@ PTF_TEST_CASE(TestLoggerMultiThread)
}

int totalLogMessages = 0;
for (int logMessagesCount : MultiThreadLogCounter::logMessageThreadCount)
for (auto const& count : logCounter.counters)
{
// cppcheck-suppress useStlAlgorithm
totalLogMessages += logMessagesCount;
totalLogMessages += count.logMessagesCount;
}

PTF_ASSERT_EQUAL(totalLogMessages, 5000);
PTF_ASSERT_EQUAL(totalLogMessages, expectedTotalMessages);
} // TestLoggerMultiThread

PTF_TEST_CASE(TestLogger)
Expand All @@ -205,6 +236,8 @@ PTF_TEST_CASE(TestLogger)

auto& logger = Logger::getInstance();

LogPrinter logPrinter;

// cppcheck-suppress unusedVariable
LoggerCleaner loggerCleaner;

Expand All @@ -224,21 +257,26 @@ PTF_TEST_CASE(TestLogger)
}

// invoke debug and error logs - expect to see only the error log
logger.setLogPrinter(&LogPrinter::logPrinter);
logger.setLogPrinter([&](pcpp::Logger::LogLevel logLevel, const std::string& logMessage,
const std::string& fileName, const std::string& method, const int line) {
logPrinter.onLogMessage(logLevel, logMessage, fileName, method, line);
});

LogPrinter::LogInfo const* lastLog;

pcpp::invokeDebugLog();
PTF_ASSERT_EQUAL(LogPrinter::lastLogLevelSeen, 999);
PTF_ASSERT_EQUAL(LogPrinter::lastLineSeen, 99999);
PTF_ASSERT_NULL(LogPrinter::lastLogMessageSeen);
PTF_ASSERT_NULL(LogPrinter::lastFilenameSeen);
PTF_ASSERT_NULL(LogPrinter::lastMethodSeen);
lastLog = logPrinter.getLastLog();
PTF_ASSERT_NULL(lastLog);

pcpp::invokeErrorLog();
PTF_ASSERT_EQUAL(LogPrinter::lastLogLevelSeen, (int)LogLevel::Error);
PTF_ASSERT_EQUAL(*LogPrinter::lastLogMessageSeen, "error log");
PTF_ASSERT_EQUAL(getLowerCaseFileName(*LogPrinter::lastFilenameSeen), "loggertests.cpp");
PTF_ASSERT_EQUAL(getMethodWithoutNamespace(*LogPrinter::lastMethodSeen), "invokeErrorLog");
PTF_ASSERT_EQUAL(LogPrinter::lastLineSeen, PCPP_TEST_EXPECTED_ERROR_LOG_LINE);

lastLog = logPrinter.getLastLog();
PTF_ASSERT_NOT_NULL(lastLog);
PTF_ASSERT_EQUAL(lastLog->logLevel, (int)LogLevel::Error);
PTF_ASSERT_EQUAL(lastLog->message, "error log");
PTF_ASSERT_EQUAL(getLowerCaseFileName(lastLog->filename), "loggertests.cpp");
PTF_ASSERT_EQUAL(getMethodWithoutNamespace(lastLog->method), "invokeErrorLog");
PTF_ASSERT_EQUAL(lastLog->line, PCPP_TEST_EXPECTED_ERROR_LOG_LINE);

// change one module log level
logger.setLogLevel(pcpp::PacketLogModuleArpLayer, LogLevel::Debug);
Expand All @@ -247,25 +285,31 @@ PTF_TEST_CASE(TestLogger)

// invoke debug, warn and error logs - expect to see all
pcpp::invokeDebugLog();
PTF_ASSERT_EQUAL(LogPrinter::lastLogLevelSeen, (int)LogLevel::Debug);
PTF_ASSERT_EQUAL(*LogPrinter::lastLogMessageSeen, "debug log");
PTF_ASSERT_EQUAL(getLowerCaseFileName(*LogPrinter::lastFilenameSeen), "loggertests.cpp");
PTF_ASSERT_EQUAL(getMethodWithoutNamespace(*LogPrinter::lastMethodSeen), "invokeDebugLog");
PTF_ASSERT_EQUAL(LogPrinter::lastLineSeen, PCPP_TEST_EXPECTED_DEBUG_LOG_LINE);
lastLog = logPrinter.getLastLog();
PTF_ASSERT_NOT_NULL(lastLog);
PTF_ASSERT_EQUAL(lastLog->logLevel, (int)LogLevel::Debug);
PTF_ASSERT_EQUAL(lastLog->message, "debug log");
PTF_ASSERT_EQUAL(getLowerCaseFileName(lastLog->filename), "loggertests.cpp");
PTF_ASSERT_EQUAL(getMethodWithoutNamespace(lastLog->method), "invokeDebugLog");
PTF_ASSERT_EQUAL(lastLog->line, PCPP_TEST_EXPECTED_DEBUG_LOG_LINE);

pcpp::invokeWarnLog();
PTF_ASSERT_EQUAL(LogPrinter::lastLogLevelSeen, (int)LogLevel::Warn);
PTF_ASSERT_EQUAL(*LogPrinter::lastLogMessageSeen, "warn log");
PTF_ASSERT_EQUAL(getLowerCaseFileName(*LogPrinter::lastFilenameSeen), "loggertests.cpp");
PTF_ASSERT_EQUAL(getMethodWithoutNamespace(*LogPrinter::lastMethodSeen), "invokeWarnLog");
PTF_ASSERT_EQUAL(LogPrinter::lastLineSeen, PCPP_TEST_EXPECTED_WARN_LOG_LINE);
lastLog = logPrinter.getLastLog();
PTF_ASSERT_NOT_NULL(lastLog);
PTF_ASSERT_EQUAL(lastLog->logLevel, (int)LogLevel::Warn);
PTF_ASSERT_EQUAL(lastLog->message, "warn log");
PTF_ASSERT_EQUAL(getLowerCaseFileName(lastLog->filename), "loggertests.cpp");
PTF_ASSERT_EQUAL(getMethodWithoutNamespace(lastLog->method), "invokeWarnLog");
PTF_ASSERT_EQUAL(lastLog->line, PCPP_TEST_EXPECTED_WARN_LOG_LINE);

pcpp::invokeErrorLog();
PTF_ASSERT_EQUAL(LogPrinter::lastLogLevelSeen, (int)LogLevel::Error);
PTF_ASSERT_EQUAL(*LogPrinter::lastLogMessageSeen, "error log");
PTF_ASSERT_EQUAL(getLowerCaseFileName(*LogPrinter::lastFilenameSeen), "loggertests.cpp");
PTF_ASSERT_EQUAL(getMethodWithoutNamespace(*LogPrinter::lastMethodSeen), "invokeErrorLog");
PTF_ASSERT_EQUAL(LogPrinter::lastLineSeen, PCPP_TEST_EXPECTED_ERROR_LOG_LINE);
lastLog = logPrinter.getLastLog();
PTF_ASSERT_NOT_NULL(lastLog);
PTF_ASSERT_EQUAL(lastLog->logLevel, (int)LogLevel::Error);
PTF_ASSERT_EQUAL(lastLog->message, "error log");
PTF_ASSERT_EQUAL(getLowerCaseFileName(lastLog->filename), "loggertests.cpp");
PTF_ASSERT_EQUAL(getMethodWithoutNamespace(lastLog->method), "invokeErrorLog");
PTF_ASSERT_EQUAL(lastLog->line, PCPP_TEST_EXPECTED_ERROR_LOG_LINE);

// verify the last error message
PTF_ASSERT_EQUAL(logger.getLastError(), "error log");
Expand All @@ -288,25 +332,28 @@ PTF_TEST_CASE(TestLogger)

// invoke debug log - expect to see it
pcpp::invokeDebugLog();
PTF_ASSERT_EQUAL(LogPrinter::lastLogLevelSeen, (int)pcpp::Logger::Debug);
PTF_ASSERT_EQUAL(*LogPrinter::lastLogMessageSeen, "debug log");
PTF_ASSERT_EQUAL(getLowerCaseFileName(*LogPrinter::lastFilenameSeen), "loggertests.cpp");
PTF_ASSERT_EQUAL(getMethodWithoutNamespace(*LogPrinter::lastMethodSeen), "invokeDebugLog");
PTF_ASSERT_EQUAL(LogPrinter::lastLineSeen, PCPP_TEST_EXPECTED_DEBUG_LOG_LINE);
lastLog = logPrinter.getLastLog();
PTF_ASSERT_NOT_NULL(lastLog);
PTF_ASSERT_EQUAL(lastLog->logLevel, (int)pcpp::LogLevel::Debug);
PTF_ASSERT_EQUAL(lastLog->message, "debug log");
PTF_ASSERT_EQUAL(getLowerCaseFileName(lastLog->filename), "loggertests.cpp");
PTF_ASSERT_EQUAL(getMethodWithoutNamespace(lastLog->method), "invokeDebugLog");
PTF_ASSERT_EQUAL(lastLog->line, PCPP_TEST_EXPECTED_DEBUG_LOG_LINE);

// suppress logs
PTF_ASSERT_TRUE(logger.logsEnabled())
logger.suppressLogs();
PTF_ASSERT_FALSE(logger.logsEnabled())

// reset LogPrinter
LogPrinter::clean();
logPrinter.clean();

// invoke debug and error logs - expect to see none
pcpp::invokeDebugLog();
pcpp::invokeErrorLog();
PTF_ASSERT_EQUAL(LogPrinter::lastLogLevelSeen, 999);
PTF_ASSERT_NULL(LogPrinter::lastLogMessageSeen);

lastLog = logPrinter.getLastLog();
PTF_ASSERT_NULL(lastLog);

// invoke another error log - expect to see it as the last error message although logs are suppressed
pcpp::invokeErrorLog("2");
Expand All @@ -318,15 +365,18 @@ PTF_TEST_CASE(TestLogger)

// invoke error log - expect to see it
pcpp::invokeErrorLog();
PTF_ASSERT_EQUAL(LogPrinter::lastLogLevelSeen, static_cast<int>(pcpp::LogLevel::Error));
PTF_ASSERT_EQUAL(*LogPrinter::lastLogMessageSeen, "error log");
PTF_ASSERT_EQUAL(getLowerCaseFileName(*LogPrinter::lastFilenameSeen), "loggertests.cpp");
PTF_ASSERT_EQUAL(getMethodWithoutNamespace(*LogPrinter::lastMethodSeen), "invokeErrorLog");

lastLog = logPrinter.getLastLog();
PTF_ASSERT_NOT_NULL(lastLog);
PTF_ASSERT_EQUAL(lastLog->logLevel, static_cast<int>(pcpp::LogLevel::Error));
PTF_ASSERT_EQUAL(lastLog->message, "error log");
PTF_ASSERT_EQUAL(getLowerCaseFileName(lastLog->filename), "loggertests.cpp");
PTF_ASSERT_EQUAL(getMethodWithoutNamespace(lastLog->method), "invokeErrorLog");
PTF_ASSERT_EQUAL(logger.getLastError(), "error log");
PTF_ASSERT_EQUAL(LogPrinter::lastLineSeen, PCPP_TEST_EXPECTED_ERROR_LOG_LINE);
PTF_ASSERT_EQUAL(lastLog->line, PCPP_TEST_EXPECTED_ERROR_LOG_LINE);

// reset LogPrinter
LogPrinter::clean();
logPrinter.clean();

// reset the log printer
logger.resetLogPrinter();
Expand All @@ -338,6 +388,7 @@ PTF_TEST_CASE(TestLogger)
logger.setLogLevel(pcpp::PacketLogModuleArpLayer, pcpp::LogLevel::Debug);
pcpp::invokeDebugLog();
pcpp::invokeErrorLog();
PTF_ASSERT_EQUAL(LogPrinter::lastLogLevelSeen, 999);
PTF_ASSERT_NULL(LogPrinter::lastLogMessageSeen);

lastLog = logPrinter.getLastLog();
PTF_ASSERT_NULL(lastLog);
} // TestLogger