LoggerUTest.cxxtest

/*
 * 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