/* * Licensed to the Apache Software Foundation (ASF) under one or more * contributor license agreements. See the NOTICE file distributed with * this work for additional information regarding copyright ownership. * The ASF licenses this file to You under the Apache License, Version 2.0 * (the "License"); you may not use this file except in compliance with * the License. You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ #include #include #include #include #include #include #include #include #include #include #include "../util/compare.h" #include "../logunit.h" #include #include #ifndef INT64_C #define INT64_C(x) x ## LL #endif // We often need one and the same date pattern, but in different contexts, to either easily embed it // into other string literals or as an object. While macros are hard to debug, embedding into string // literals is easier this way, because the compiler can automatically collaps them, and if we have // one macro already, a second for a similar purpose shouldn't hurt as well. #define DATE_PATTERN "yyyy-MM-dd_HH_mm_ss" #define DATE_PATTERN_STR LogString(LOG4CXX_STR("yyyy-MM-dd_HH_mm_ss")) #define PATTERN_LAYOUT LOG4CXX_STR("%c{1} - %m%n") using namespace log4cxx; using namespace log4cxx::helpers; using namespace log4cxx::rolling; /** * A rather exhaustive set of tests. Tests include leaving the ActiveFileName * argument blank, or setting it, with and without compression, and tests * with or without stopping/restarting the RollingFileAppender. * * The regression tests log a few times using a RollingFileAppender. Then, * they predict the names of the files which sould be generated and compare * them with witness files. * *
         Compression    ActiveFileName  Stop/Restart
 Test1      NO              BLANK          NO
 Test2      NO              BLANK          YES
 Test3      YES             BLANK          NO
 Test4      NO                SET          YES
 Test5      NO                SET          NO
 Test6      YES               SET          NO
 * 
*/ LOGUNIT_CLASS(TimeBasedRollingTest) { LOGUNIT_TEST_SUITE(TimeBasedRollingTest); LOGUNIT_TEST(test1); LOGUNIT_TEST(test2); LOGUNIT_TEST(test3); LOGUNIT_TEST(test4); LOGUNIT_TEST(test5); LOGUNIT_TEST(test6); LOGUNIT_TEST(test7); LOGUNIT_TEST_SUITE_END(); private: static LoggerPtr logger; /** * Currently running test. *

* Number of currently running test, used e.g. for some generic code in {@link setUp()}. *

*/ size_t num_test; /** * Build file names with timestamps. *

* This method builds some file names based on a hard coded date pattern, while the important * thing is that the used time is "now" for the first and one additional second into the future * for each subsequent file name. The method is used to build names which are expected to get * created by loggers afterwards, so the existence of those files can be checked easily. *

*

* The given {@code prefix} is for the file name only, we hard code "output" as directory. *

*

* Using {@code startInFuture} the caller can specify if the first created file name uses "now" * or already starts one second in the future. This depends on what the caller wants to check: * If it is the existence of specially named files and the caller uses some generic log file to * start with, it's most likely that the first file name to checks needs to be in the future, * because new files are only created with subsequent log statements. The first goes to the * generically named file, afterwards the test sleeps a bit and the next statement is creating * the first file to check for. During the time between those two calls the current second and * therefore "now" could have easily past and the first file name will never be found, because * the rolling appender creates it with a newer "now", at least one second in the future. *

* @param[in,out] pool * @param[in] prefix * @param[in] fileNames * param[in,opt] withCompression * param[in,opt] startInFuture */ template void buildTsFileNames( Pool& pool, const logchar* prefix, LogString (&fileNames)[N], bool withCompression = false, bool startInFuture = false) { SimpleDateFormat sdf(DATE_PATTERN_STR); apr_time_t now(apr_time_now()); LogString ext(withCompression ? LOG4CXX_STR(".gz") : LOG4CXX_STR("")); now += startInFuture ? APR_USEC_PER_SEC : 0; for (size_t i = 0; i < N; ++i) { fileNames[i].assign(LogString(LOG4CXX_STR("output/")) + prefix); sdf.format(fileNames[i], now, pool); fileNames[i].append(ext); now += APR_USEC_PER_SEC; } } /** * Log some msg and sleep. *

* Most tests need to log some message to some files and sleep afterwards, to spread the msgs * over time and timestamp based named files. This method handles this for all tests to not need * to replicate the same code AND deals with the fact that the logigng statements should contain * the original src function and line. For that to work each caller needs to provide us the * additional information and we redefine LOG4CXX_LOCATION to use that provided data instead of * that from the compiler when a log statement is issued. While this is a bit ugly, because we * need to duplicate the definition of LOG4CXX_LOCATION, it is easier than to duplicate the code * for logging and sleeping per test in this file. *

*

* The given wait factor is always multiplied with 1 second and the result is waited for, so a * caller needs to e.g. provide {@code 0.5} if it needs log statements to distribute over given * files, resulting in two statements per file. If the caller needs indivdual file to check for * their existence, {@code 1} can be provided, which ensures that we wait for at least the next * second. *

*

* It is important the the caller provides aus with {@code __LOG4CXX_FUNC__} instead of only * {@code __FUNC__} or such, because the latter is compiler specific and log4cxx already deals * with such things. *

*

* We had macro wrappers around this method dealing with such things in the past, but as args * where added, those become more and more difficult to maintain properly and therefore removed. *

* @param[in,out] pool * @param[in] howOften * @param[in] srcFunc * @param[in] srcLine * @param[in,opt] startWith * @param[in] waitFactor */ void logMsgAndSleep(Pool& pool, size_t howOften, std::string srcFunc, size_t srcLine, size_t startWith = 0, float waitFactor = 0.5) { #undef LOG4CXX_LOCATION #define LOG4CXX_LOCATION ::log4cxx::spi::LocationInfo( \ __FILE__, \ srcFunc.c_str(), \ srcLine) for (size_t i = startWith; i < startWith + howOften; ++i) { std::string message("Hello---"); message.append(pool.itoa(i)); LOG4CXX_DEBUG(logger, message); apr_sleep(APR_USEC_PER_SEC * waitFactor); } #undef LOG4CXX_LOCATION #define LOG4CXX_LOCATION ::log4cxx::spi::LocationInfo( \ __FILE__, \ __LOG4CXX_FUNC__, \ __LINE__) } /** * Check witness by comparing file contents. *

* This method checks the witness for some test by comparing the contents of the given file used * by that test. To find the corresponding witness, the prefix of the test needs to be provided, * which is some unique part of the file name to use, while we hard code the parent dir and * other non changing parts of the name. *

*

* We don't use a wrapper macro this time because the src line should have the same name in all * compilers and is easily to add for the caller. *

* @param[in,out] pool * @param[in] prefix * @param[in] fileName * @param[in] witnessIdx * @param[in] srcLine */ void compareWitness( Pool& pool, const logchar* prefix, const LogString& fileName, size_t witnessIdx, size_t srcLine) { LogString witness(LOG4CXX_STR("witness/rolling/tbr-")); witness.append(prefix); StringHelper::toString(witnessIdx, pool, witness); LOGUNIT_ASSERT_SRCL(Compare::compare(fileName, File(witness)), srcLine); } /** * Check witnesses by comparing file contents. *

* This method is a wrapper around {@link compareWitness}, used to iterate over all files from a * given test. *

* @param[in,out] pool * @param[in] prefix * @param[in] fileNames * @param[in] srcLine */ template void compareWitnesses( Pool& pool, const logchar* prefix, LogString (&fileNames)[N], size_t srcLine) { for (int i = 0; i < N; ++i) { this->compareWitness(pool, prefix, fileNames[i], i, srcLine); } } /** * Check existing files. *

* This method checks that the first N - 1 files of the given array actually exist and compares * the last one by content to some witness. *

*

* We don't use a wrapper macro this time because the src line schould have the same name in all * compilers and is easily to add for the caller. *

* @param[in,out] pool * @param[in] prefix * @param[in] fileNames * @param[in] srcLine */ template void checkFilesExist( Pool& pool, const logchar* prefix, LogString (&fileNames)[N], size_t srcLine) { for (int i = 0; i < N - 1; ++i) { LOGUNIT_ASSERT_EQUAL_SRCL(true, File(fileNames[0]).exists(pool), srcLine); } this->compareWitness(pool, prefix, fileNames[N - 1], N - 1, srcLine); } /** * Let the current second pass. *

* This method assures that the current second and some additional time gets passed before * returning. *

* @param[in,opt] millis */ void delayUntilNextSecond(size_t millis = 100) { apr_time_t now = apr_time_now(); apr_time_t next = ((now / APR_USEC_PER_SEC) + 1) * APR_USEC_PER_SEC + millis * 1000L; apr_sleep(next - now); } /** * Let the current second pass with some msg. *

* This method works exactly like {@link delayUntilNextSecond(size_t)}, but additionally prints * a message before and after the wait on STDOUT for debugging purposes. *

* @param[in,opt] millis */ void delayUntilNextSecondWithMsg(size_t millis = 100) { std::cout << "Waiting until next second and " << millis << " millis."; delayUntilNextSecond(millis); std::cout << "Done waiting." << std::endl; } /** * Delete generic log files. *

* Some tests use generic log file names which may already be available during subsequent calls * to the test and influence their behavior, e.g. because RollingFileAppender uses the last * modification time of already existing files to create their internal names. Such a date may * be from the arbitrary past, but ost of the test assumes operations like rollovers within few * seconds around "new". Thos assumptions will fail for older existing files. So this method can * be called during {@link setUp()} of an test to clear such generically named files for each * test. We currently only care about {@code output/testxy.log}. *

* @param[in] num_test */ void deleteGenericLogFilePerTest(size_t num_test) { Pool pool; LogString path(LOG4CXX_STR("output/test")); StringHelper::toString(num_test, pool, path); path.append(LOG4CXX_STR(".log")); File(path).deleteFile(pool); } /** * Setup for internal test call. *

* This method has a similar intention like {@link setUp()}, only that it focusses on internal * calls of the tests, where we don't need to create some loggers and such, but may need to * delete some files etc. to make tests work. *

* @param[in] num_test */ void internalSetUp(size_t num_test) { this->deleteGenericLogFilePerTest(num_test); } /** * Counterpart for {@like internalSetUp(size_t)}. *

* Counterpart for {@like internalSetUp(size_t)}. *

*/ void internalTearDown() { // Nothing to do currently. } public: /** * Extract number of current test. *

* {@code setUp()} needs the number of the current runnign test for some generic work and this * is the only place where we can extract and save it in the instance. *

*/ void setCase(abts_case* tc) { LogUnit::TestFixture::setCase(tc); this->num_test = tc->suite->num_test; } void setUp() { LoggerPtr root(Logger::getRootLogger()); root->addAppender( new ConsoleAppender( new PatternLayout( LOG4CXX_STR("%d{ABSOLUTE} [%t] %level %c{2}#%M:%L - %m%n")))); this->internalSetUp(this->num_test); } void tearDown() { this->internalTearDown(); LogManager::shutdown(); } /** * Test rolling without compression, activeFileName left blank, no stop/start */ void test1() { Pool pool; const size_t nrOfFileNames = 4; LogString fileNames[nrOfFileNames]; PatternLayoutPtr layout( new PatternLayout(PATTERN_LAYOUT)); RollingFileAppenderPtr rfa( new RollingFileAppender()); rfa->setLayout(layout); TimeBasedRollingPolicyPtr tbrp(new TimeBasedRollingPolicy()); tbrp->setFileNamePattern(LOG4CXX_STR("output/test1-%d{" DATE_PATTERN "}")); tbrp->activateOptions(pool); rfa->setRollingPolicy(tbrp); rfa->activateOptions(pool); logger->addAppender(rfa); this->buildTsFileNames(pool, LOG4CXX_STR("test1-"), fileNames); this->delayUntilNextSecondWithMsg(); this->logMsgAndSleep( pool, nrOfFileNames + 1, __LOG4CXX_FUNC__, __LINE__); this->compareWitnesses( pool, LOG4CXX_STR("test1."), fileNames, __LINE__); } /** * No compression, with stop/restart, activeFileName left blank */ void test2() { Pool pool; const size_t nrOfFileNames = 4; LogString fileNames[nrOfFileNames]; PatternLayoutPtr layout1(new PatternLayout(PATTERN_LAYOUT)); RollingFileAppenderPtr rfa1( new RollingFileAppender()); rfa1->setLayout(layout1); TimeBasedRollingPolicyPtr tbrp1(new TimeBasedRollingPolicy()); tbrp1->setFileNamePattern(LOG4CXX_STR("output/test2-%d{" DATE_PATTERN "}")); tbrp1->activateOptions(pool); rfa1->setRollingPolicy(tbrp1); rfa1->activateOptions(pool); logger->addAppender(rfa1); this->buildTsFileNames(pool, LOG4CXX_STR("test2-"), fileNames); this->delayUntilNextSecondWithMsg(); this->logMsgAndSleep(pool, 3, __LOG4CXX_FUNC__, __LINE__); logger->removeAppender(rfa1); rfa1->close(); PatternLayoutPtr layout2(new PatternLayout(PATTERN_LAYOUT)); RollingFileAppenderPtr rfa2( new RollingFileAppender()); rfa2->setLayout(layout2); TimeBasedRollingPolicyPtr tbrp2 = new TimeBasedRollingPolicy(); tbrp2->setFileNamePattern(LOG4CXX_STR("output/test2-%d{" DATE_PATTERN "}")); tbrp2->activateOptions(pool); rfa2->setRollingPolicy(tbrp2); rfa2->activateOptions(pool); logger->addAppender(rfa2); this->logMsgAndSleep( pool, 2, __LOG4CXX_FUNC__, __LINE__, 3); this->compareWitnesses( pool, LOG4CXX_STR("test2."), fileNames, __LINE__); } /** * With compression, activeFileName left blank, no stop/restart */ void test3() { Pool pool; const size_t nrOfFileNames = 4; LogString fileNames[nrOfFileNames]; PatternLayoutPtr layout( new PatternLayout(PATTERN_LAYOUT)); RollingFileAppenderPtr rfa( new RollingFileAppender()); rfa->setAppend(false); rfa->setLayout(layout); TimeBasedRollingPolicyPtr tbrp = new TimeBasedRollingPolicy(); tbrp->setFileNamePattern(LogString(LOG4CXX_STR("output/test3-%d{" DATE_PATTERN "}.gz"))); tbrp->activateOptions(pool); rfa->setRollingPolicy(tbrp); rfa->activateOptions(pool); logger->addAppender(rfa); this->buildTsFileNames(pool, LOG4CXX_STR("test3-"), fileNames, true); fileNames[3].resize(fileNames[3].size() - 3); this->delayUntilNextSecondWithMsg(); this->logMsgAndSleep( pool, nrOfFileNames + 1, __LOG4CXX_FUNC__, __LINE__); this->checkFilesExist( pool, LOG4CXX_STR("test3."), fileNames, __LINE__); } /** * Without compression, activeFileName set, with stop/restart */ void test4() { Pool pool; const size_t nrOfFileNames = 4; LogString fileNames[nrOfFileNames]; PatternLayoutPtr layout1(new PatternLayout(PATTERN_LAYOUT)); RollingFileAppenderPtr rfa1( new RollingFileAppender()); rfa1->setLayout(layout1); TimeBasedRollingPolicyPtr tbrp1 = new TimeBasedRollingPolicy(); rfa1->setFile(LOG4CXX_STR("output/test4.log")); tbrp1->setFileNamePattern(LOG4CXX_STR("output/test4-%d{" DATE_PATTERN "}")); tbrp1->activateOptions(pool); rfa1->setRollingPolicy(tbrp1); rfa1->activateOptions(pool); logger->addAppender(rfa1); this->buildTsFileNames(pool, LOG4CXX_STR("test4-"), fileNames); fileNames[3].assign(rfa1->getFile()); this->delayUntilNextSecondWithMsg(); this->logMsgAndSleep(pool, 3, __LOG4CXX_FUNC__, __LINE__); logger->removeAppender(rfa1); rfa1->close(); PatternLayoutPtr layout2(new PatternLayout(PATTERN_LAYOUT)); RollingFileAppenderPtr rfa2( new RollingFileAppender()); rfa2->setLayout(layout2); TimeBasedRollingPolicyPtr tbrp2 = new TimeBasedRollingPolicy(); tbrp2->setFileNamePattern(LOG4CXX_STR("output/test4-%d{" DATE_PATTERN "}")); rfa2->setFile(fileNames[3]); tbrp2->activateOptions(pool); rfa2->setRollingPolicy(tbrp2); rfa2->activateOptions(pool); logger->addAppender(rfa2); this->logMsgAndSleep( pool, 2, __LOG4CXX_FUNC__, __LINE__, 3); this->compareWitnesses( pool, LOG4CXX_STR("test4."), fileNames, __LINE__); } /** * No compression, activeFileName set, without stop/restart */ void test5() { Pool pool; const size_t nrOfFileNames = 4; LogString fileNames[nrOfFileNames]; PatternLayoutPtr layout( new PatternLayout(PATTERN_LAYOUT)); RollingFileAppenderPtr rfa( new RollingFileAppender()); rfa->setLayout(layout); TimeBasedRollingPolicyPtr tbrp = new TimeBasedRollingPolicy(); tbrp->setFileNamePattern(LOG4CXX_STR("output/test5-%d{" DATE_PATTERN "}")); rfa->setFile(LOG4CXX_STR("output/test5.log")); tbrp->activateOptions(pool); rfa->setRollingPolicy(tbrp); rfa->activateOptions(pool); logger->addAppender(rfa); this->buildTsFileNames(pool, LOG4CXX_STR("test5-"), fileNames); fileNames[3].assign(rfa->getFile()); this->delayUntilNextSecondWithMsg(); this->logMsgAndSleep( pool, nrOfFileNames + 1, __LOG4CXX_FUNC__, __LINE__); this->compareWitnesses( pool, LOG4CXX_STR("test5."), fileNames, __LINE__); } /** * With compression, activeFileName set, no stop/restart, */ void test6() { Pool pool; const size_t nrOfFileNames = 4; LogString fileNames[nrOfFileNames]; PatternLayoutPtr layout( new PatternLayout(PATTERN_LAYOUT)); RollingFileAppenderPtr rfa( new RollingFileAppender()); rfa->setAppend(false); rfa->setLayout(layout); TimeBasedRollingPolicyPtr tbrp = new TimeBasedRollingPolicy(); tbrp->setFileNamePattern(LogString(LOG4CXX_STR("output/test6-%d{" DATE_PATTERN "}.gz"))); rfa->setFile(LOG4CXX_STR("output/test6.log")); tbrp->activateOptions(pool); rfa->setRollingPolicy(tbrp); rfa->activateOptions(pool); logger->addAppender(rfa); this->buildTsFileNames(pool, LOG4CXX_STR("test6-"), fileNames, true); fileNames[3].assign(rfa->getFile()); this->delayUntilNextSecondWithMsg(); this->logMsgAndSleep( pool, nrOfFileNames + 1, __LOG4CXX_FUNC__, __LINE__); this->checkFilesExist( pool, LOG4CXX_STR("test6."), fileNames, __LINE__); } /** * Repeat some test with generic file name.s *

* This test calls some tests which use generic file names and will only work properly if those * got deleted before running the test during setup. *

*/ void test7() { typedef void (TimeBasedRollingTest::*Test)(); typedef std::vector Tests; Tests tests(10); size_t numTest = 0; tests.at(4) = &TimeBasedRollingTest::test4; tests.at(5) = &TimeBasedRollingTest::test5; tests.at(6) = &TimeBasedRollingTest::test6; for (size_t numTest = 1; numTest < tests.size(); ++numTest) { Test test(tests.at(numTest)); if (!test) { continue; } this->internalSetUp(numTest); (this->*test)(); this->internalTearDown(); } } }; LoggerPtr TimeBasedRollingTest::logger(Logger::getLogger("org.apache.log4j.TimeBasedRollingTest")); LOGUNIT_TEST_SUITE_REGISTRATION(TimeBasedRollingTest);