/*
* tests/util/LoggerUTest.cxxtest
*
* Copyright (C) 2002-2007 Novamente LLC
* Copyright (C) 2008 by OpenCog Foundation
* All Rights Reserved
*
* Written by Andre Senna <senna@vettalabs.com>
* Gustavo Gama <gama@vettalabs.com>
*
* This program is free software; you can redistribute it and/or modify
* it under the terms of the GNU Affero General Public License v3 as
* published by the Free Software Foundation and including the exceptions
* at http://opencog.org/wiki/Licenses
*
* This program is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
* GNU General Public License for more details.
*
* You should have received a copy of the GNU Affero General Public License
* along with this program; if not, write to:
* Free Software Foundation, Inc.,
* 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
*/
#include <unistd.h>
#include <cstdio>
#include <cstdlib>
#include <cstring>
#include <fstream>
#include <iostream>
#include <atomic>
#include <thread>
#include <opencog/util/Logger.h>
#include <opencog/util/random.h>
#include <cxxtest/TestSuite.h>
using namespace opencog;
class LoggerUTest : public CxxTest::TestSuite
{
public:
LoggerUTest() {}
void setUp() {}
void tearDown() {}
static std::string getLastLineFromFile(const std::string& filename) {
std::ifstream logfile(filename);
std::string line, resline;
if (logfile.is_open())
{
while (logfile.good())
{
getline(logfile, line);
if (!line.empty())
resline = line;
}
logfile.close();
}
return resline;
}
static std::string remove_timestamp(const std::string str) {
return str.substr(26);
}
void testLog()
{
char const * tmpdir;
char baselineFile[256];
char logFile[256];
tmpdir = getenv("TMPDIR");
if (tmpdir == nullptr) tmpdir = "/tmp";
strcpy(baselineFile, tmpdir);
strcpy(logFile, tmpdir);
strcat(baselineFile, "/testLogBaseline.txt");
strcat(logFile, "/testLog.txt");
Logger baseline(baselineFile, Logger::FINE, false);
Logger _logger(logFile, Logger::DEBUG, false);
_logger.fine("msg1");
_logger.debug("msg2");
baseline.debug("msg2");
_logger.info("msg3");
baseline.info("msg3");
// Must flush, as otherwise there is a race against the
// fopen()'s below.
_logger.flush();
baseline.flush();
FILE *f1 = fopen(baselineFile, "r");
FILE *f2 = fopen(logFile, "r");
TS_ASSERT(f1 != NULL);
TS_ASSERT(f2 != NULL);
int c1 = fgetc(f1);
while (c1 != EOF)
{
char c2 = fgetc(f2);
TS_ASSERT(c1 == c2);
c1 = fgetc(f1);
}
remove(baselineFile);
remove(logFile);
}
void testDefaultLogger()
{
logger().info("Running LoggerUTest");
}
unsigned int countLines(const char *filename)
{
unsigned int nLines = 0;
std::string line;
std::ifstream fin(filename);
while (fin.good() && std::getline(fin, line)) nLines++;
fin.close();
return nLines;
}
void logAllLevels(const char *filename,
const Logger::Level level,
const unsigned int nLines)
{
Logger _logger(filename, level);
_logger.error("message");
_logger.warn ("message");
_logger.info ("message");
_logger.debug("message");
_logger.fine ("message");
_logger.flush();
// Hmm. I don't get it. Logger::flush calls fdatasync(),
// apparently this is not enough to prevent a race condition
// between the logger write, and the read to count the lines.
// I really don't get it .. the fdatasync should have been enough.
// To work around this, force a sync() below to avoid spurious
// test-case failures.
sync();
int found = countLines(filename);
TS_ASSERT_LESS_THAN_EQUALS(nLines, found);
remove(filename);
}
void testLevels()
{
logAllLevels("LoggerUTest.none.log", Logger::NONE, 0);
logAllLevels("LoggerUTest.error.log", Logger::ERROR, 1);
logAllLevels("LoggerUTest.warn.log", Logger::WARN, 2);
logAllLevels("LoggerUTest.info.log", Logger::INFO, 3);
logAllLevels("LoggerUTest.debug.log", Logger::DEBUG, 4);
logAllLevels("LoggerUTest.fine.log", Logger::FINE, 5);
}
void testLazyLogger()
{
logger().set_level(Logger::DEBUG);
int i = 0;
LAZY_LOG_FINE << "i = " << ++i;
LAZY_LOG_DEBUG << "i = " << ++i;
LAZY_LOG_INFO << "i = " << ++i;
TS_ASSERT_EQUALS(i, 2);
}
void testComponentLogger()
{
logger().set_level(Logger::DEBUG);
logger().set_component("LoggerUTest");
logger().debug("message");
logger().flush();
std::string resline = getLastLineFromFile(logger().get_filename());
std::cout << "resline = " << resline << std::endl;
TS_ASSERT_EQUALS(remove_timestamp(resline), "[DEBUG] [LoggerUTest] message");
// Unset the component
logger().set_component("");
}
// Derive the factory logger, modify some parameters and use
// it. The new parameters do not affect the factory logger.
void testDerivedLogger()
{
Logger my_logger(logger());
my_logger.set_level(Logger::DEBUG);
my_logger.set_component("LoggerUTest");
my_logger.set_filename("__testDerivedLogger__.log");
// Log with the component logger
my_logger.debug("message");
my_logger.flush();
// Check that the factory logger still works
logger().info("factory message");
logger().flush();
std::string resline = getLastLineFromFile(my_logger.get_filename());
std::cout << "resline = " << resline << std::endl;
TS_ASSERT_EQUALS(remove_timestamp(resline), "[DEBUG] [LoggerUTest] message");
remove(my_logger.get_filename().c_str());
}
void testThreadIdLogging()
{
logger().set_level(Logger::DEBUG);
logger().set_thread_id_flag(true);
std::atomic<std::thread::id> thread_id;
std::thread thread([&thread_id]() {
thread_id.store(std::this_thread::get_id());
logger().debug("message");
});
thread.join();
logger().flush();
std::string resline = getLastLineFromFile(logger().get_filename());
std::cout << "resline = " << resline << std::endl;
std::ostringstream oss;
oss << "[DEBUG] [thread-" << thread_id.load() << "] message";
TS_ASSERT_EQUALS(remove_timestamp(resline), oss.str());
logger().set_thread_id_flag(false);
}
// Define a second logger, write some massive message on the first
// one, a small message on the second, and see if the message of
// the second scrumbles the first message or appears after it.
void testLoggerInteraction()
{
logger().set_level(Logger::DEBUG);
logger().set_timestamp_flag(false);
Logger my_logger;
my_logger.set_level(Logger::DEBUG);
my_logger.set_component("LoggerUTest");
my_logger.set_timestamp_flag(false);
// Make sure both loggers point to the same file (not really
// part of the test but better be safe than sorry)
TS_ASSERT_EQUALS(logger().get_filename(), my_logger.get_filename());
std::string gibberish(randstr("", 10000));
std::string message("message");
std::string prefix("[DEBUG] [LoggerUTest] ");
logger().debug(gibberish);
my_logger.debug(message);
logger().flush();
my_logger.flush();
std::string resline = getLastLineFromFile(my_logger.get_filename());
std::cout << "resline = " << resline << std::endl;
TS_ASSERT(resline == prefix + message);
}
// Define a second logger, enable stdout in one logger, and check
// whether the stdout in the other logger is left unchanged.
//
// TODO: re-enabled once fixed
void testLoggerStdoutFlagInteraction()
{
Logger my_logger;
// Set different stdout flags for my_logger and the default logger
logger().set_print_to_stdout_flag(false);
my_logger.set_print_to_stdout_flag(true);
// Make sure their flags differ
TS_ASSERT_DIFFERS(logger().get_print_to_stdout_flag(),
my_logger.get_print_to_stdout_flag());
}
}; // class