You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by rm...@apache.org on 2022/03/25 01:23:27 UTC
[logging-log4cxx] branch LOGCXX-527 created (now 8377e42)
This is an automated email from the ASF dual-hosted git repository.
rmiddleton pushed a change to branch LOGCXX-527
in repository https://gitbox.apache.org/repos/asf/logging-log4cxx.git.
at 8377e42 Time based tests kinda work with fake clock at this point
This branch includes the following new commits:
new ed867ee Print out failing sub-tests
new 8377e42 Time based tests kinda work with fake clock at this point
The 2 revisions listed above as "new" are entirely new to this
repository and will be described in separate emails. The revisions
listed as "add" were already present in the repository and have only
been added to this reference.
[logging-log4cxx] 01/02: Print out failing sub-tests
Posted by rm...@apache.org.
This is an automated email from the ASF dual-hosted git repository.
rmiddleton pushed a commit to branch LOGCXX-527
in repository https://gitbox.apache.org/repos/asf/logging-log4cxx.git
commit ed867eef9b52054e9c991b3c9e4c92120862be96
Author: Robert Middleton <ro...@rm5248.com>
AuthorDate: Thu Mar 24 21:00:12 2022 -0400
Print out failing sub-tests
---
src/test/cpp/abts.cpp | 21 ++++++++++++---------
src/test/cpp/abts.h | 6 ++++--
src/test/cpp/logunit.cpp | 6 +++---
src/test/cpp/logunit.h | 2 +-
4 files changed, 20 insertions(+), 15 deletions(-)
diff --git a/src/test/cpp/abts.cpp b/src/test/cpp/abts.cpp
index 5524c9b..c26ebd8 100644
--- a/src/test/cpp/abts.cpp
+++ b/src/test/cpp/abts.cpp
@@ -101,14 +101,14 @@ static void end_suite(abts_suite* suite)
fflush(stdout);
}
- if (last->failed == 0)
+ if (last->failed.size() == 0)
{
fprintf(stdout, "SUCCESS\n");
fflush(stdout);
}
else
{
- fprintf(stdout, "FAILED %d of %d\n", last->failed, last->num_test);
+ fprintf(stdout, "FAILED %d of %d\n", last->failed.size(), last->num_test);
fflush(stdout);
}
}
@@ -129,7 +129,7 @@ abts_suite* abts_add_suite(abts_suite* suite, const char* suite_name_full)
subsuite = (sub_suite*) malloc(sizeof(*subsuite));
subsuite->num_test = 0;
- subsuite->failed = 0;
+ subsuite->failed.clear();
subsuite->next = NULL;
/* suite_name_full may be an absolute path depending on __FILE__
* expansion */
@@ -189,7 +189,7 @@ abts_suite* abts_add_suite(abts_suite* suite, const char* suite_name_full)
return suite;
}
-void abts_run_test(abts_suite* ts, test_func f, void* value)
+void abts_run_test(abts_suite* ts, const char* name, test_func f, void* value)
{
abts_case tc;
sub_suite* ss;
@@ -211,7 +211,7 @@ void abts_run_test(abts_suite* ts, test_func f, void* value)
if (tc.failed)
{
- ss->failed++;
+ ss->failed.push_back(name);
}
}
@@ -227,7 +227,7 @@ static int report(abts_suite* suite)
for (dptr = suite->head; dptr; dptr = dptr->next)
{
- count += dptr->failed;
+ count += dptr->failed.size();
}
if (list_tests)
@@ -247,11 +247,14 @@ static int report(abts_suite* suite)
while (dptr != NULL)
{
- if (dptr->failed != 0)
+ if (dptr->failed.size() != 0)
{
- float percent = ((float)dptr->failed / (float)dptr->num_test);
+ float percent = ((float)dptr->failed.size() / (float)dptr->num_test);
fprintf(stdout, "%-15s\t\t%5d\t%4d\t%6.2f%%\n", dptr->name,
- dptr->num_test, dptr->failed, percent * 100);
+ dptr->num_test, dptr->failed.size(), percent * 100);
+ for( const char* failed_name : dptr->failed ){
+ fprintf(stdout, " %s\n", failed_name );
+ }
}
dptr = dptr->next;
diff --git a/src/test/cpp/abts.h b/src/test/cpp/abts.h
index 616250b..c3fb6f6 100644
--- a/src/test/cpp/abts.h
+++ b/src/test/cpp/abts.h
@@ -17,6 +17,8 @@
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
+#include <vector>
+#include <string>
#include <apr.h>
@@ -40,7 +42,7 @@ struct sub_suite
{
const char* name;
int num_test;
- int failed;
+ std::vector<const char*> failed;
int not_run;
int not_impl;
struct sub_suite* next;
@@ -66,7 +68,7 @@ typedef void (*test_func)(abts_case* tc, void* data);
#define ADD_SUITE(suite) abts_add_suite(suite, __FILE__);
abts_suite* abts_add_suite(abts_suite* suite, const char* suite_name);
-void abts_run_test(abts_suite* ts, test_func f, void* value);
+void abts_run_test(abts_suite* ts, const char* name, test_func f, void* value);
void abts_log_message(const char* fmt, ...);
void abts_int_equal(abts_case* tc, const int expected, const int actual, int lineno);
diff --git a/src/test/cpp/logunit.cpp b/src/test/cpp/logunit.cpp
index 6d57a64..24331f7 100644
--- a/src/test/cpp/logunit.cpp
+++ b/src/test/cpp/logunit.cpp
@@ -253,9 +253,9 @@ LogUnit::TestSuite::TestSuite(const char* fname) : filename(fname), disabled(fal
#endif
}
-void LogUnit::TestSuite::addTest(const char*, test_func func)
+void LogUnit::TestSuite::addTest(const char* test_name, test_func func)
{
- test_funcs.push_back(func);
+ test_funcs.push_back({test_name,func});
}
std::string LogUnit::TestSuite::getName() const
@@ -281,7 +281,7 @@ abts_suite* TestSuite::run(abts_suite* suite) const
iter != test_funcs.end();
iter++)
{
- abts_run_test(suite, *iter, NULL);
+ abts_run_test(suite, iter->first, *iter->second, NULL);
}
return suite;
diff --git a/src/test/cpp/logunit.h b/src/test/cpp/logunit.h
index 8987e15..6b8fbe3 100644
--- a/src/test/cpp/logunit.h
+++ b/src/test/cpp/logunit.h
@@ -182,7 +182,7 @@ class TestSuite
private:
TestSuite(const TestSuite&);
TestSuite& operator=(const TestSuite&);
- typedef std::vector<test_func> TestList;
+ typedef std::vector<std::pair<const char*,test_func>> TestList;
TestList test_funcs;
std::string filename;
bool disabled;
[logging-log4cxx] 02/02: Time based tests kinda work with fake clock at this point
Posted by rm...@apache.org.
This is an automated email from the ASF dual-hosted git repository.
rmiddleton pushed a commit to branch LOGCXX-527
in repository https://gitbox.apache.org/repos/asf/logging-log4cxx.git
commit 8377e4239ce0ed46217ec59bd445de7a4ad65f0e
Author: Robert Middleton <ro...@rm5248.com>
AuthorDate: Thu Mar 24 21:23:14 2022 -0400
Time based tests kinda work with fake clock at this point
---
src/main/cpp/aprinitializer.cpp | 3 +-
src/main/cpp/date.cpp | 18 +++++++++++-
src/main/cpp/htmllayout.cpp | 3 +-
src/main/cpp/loggingevent.cpp | 3 +-
src/main/cpp/timebasedrollingpolicy.cpp | 21 +++++--------
src/main/include/log4cxx/helpers/date.h | 22 +++++++++++++-
.../log4cxx/rolling/timebasedrollingpolicy.h | 1 +
src/test/cpp/rolling/timebasedrollingtest.cpp | 34 +++++++++++++++-------
8 files changed, 76 insertions(+), 29 deletions(-)
diff --git a/src/main/cpp/aprinitializer.cpp b/src/main/cpp/aprinitializer.cpp
index 0bd91d2..cbaeb77 100644
--- a/src/main/cpp/aprinitializer.cpp
+++ b/src/main/cpp/aprinitializer.cpp
@@ -26,6 +26,7 @@
#include <apr_thread_mutex.h>
#include <apr_thread_proc.h>
#include <log4cxx/helpers/filewatchdog.h>
+#include <log4cxx/helpers/date.h>
using namespace log4cxx::helpers;
using namespace log4cxx;
@@ -46,7 +47,7 @@ APRInitializer::APRInitializer() : p(0), startTime(0), tlsKey(0)
apr_initialize();
apr_pool_create(&p, NULL);
apr_atomic_init(p);
- startTime = apr_time_now();
+ startTime = Date::currentTime();
#if APR_HAS_THREADS
apr_status_t stat = apr_threadkey_private_create(&tlsKey, tlsDestruct, p);
assert(stat == APR_SUCCESS);
diff --git a/src/main/cpp/date.cpp b/src/main/cpp/date.cpp
index a1ea7ce..e3968bc 100644
--- a/src/main/cpp/date.cpp
+++ b/src/main/cpp/date.cpp
@@ -18,6 +18,7 @@
#include <log4cxx/helpers/date.h>
#include <apr_time.h>
+#define LOG4CXX_USEC_PER_SEC 1000000LL
#ifndef INT64_C
#define INT64_C(x) x ## LL
#endif
@@ -27,7 +28,10 @@ using namespace log4cxx::helpers;
IMPLEMENT_LOG4CXX_OBJECT(Date)
-Date::Date() : time(apr_time_now())
+
+Date::GetCurrentTimeFn Date::getCurrentTimeFn = Date::getCurrentTimeStd;
+
+Date::Date() : time(getCurrentTimeFn())
{
}
@@ -54,3 +58,15 @@ log4cxx_time_t Date::getNextSecond() const
{
return ((time / APR_USEC_PER_SEC) + 1) * APR_USEC_PER_SEC;
}
+
+void Date::setGetCurrentTimeFunction(GetCurrentTimeFn fn){
+ getCurrentTimeFn = fn;
+}
+
+log4cxx_time_t Date::currentTime(){
+ return getCurrentTimeFn();
+}
+
+log4cxx_time_t Date::getCurrentTimeStd(){
+ return std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::system_clock::now().time_since_epoch()).count();
+}
diff --git a/src/main/cpp/htmllayout.cpp b/src/main/cpp/htmllayout.cpp
index f63e78e..70726a7 100644
--- a/src/main/cpp/htmllayout.cpp
+++ b/src/main/cpp/htmllayout.cpp
@@ -24,6 +24,7 @@
#include <log4cxx/helpers/iso8601dateformat.h>
#include <log4cxx/helpers/stringhelper.h>
#include <log4cxx/helpers/transcoder.h>
+#include <log4cxx/helpers/date.h>
#include <apr_time.h>
#include <apr_strings.h>
@@ -185,7 +186,7 @@ void HTMLLayout::appendHeader(LogString& output, Pool& p)
output.append(LOG4CXX_EOL);
output.append(LOG4CXX_STR("Log session start time "));
- dateFormat.format(output, apr_time_now(), p);
+ dateFormat.format(output, Date::currentTime(), p);
output.append(LOG4CXX_STR("<br>"));
output.append(LOG4CXX_EOL);
diff --git a/src/main/cpp/loggingevent.cpp b/src/main/cpp/loggingevent.cpp
index eb59e2f..54d4506 100644
--- a/src/main/cpp/loggingevent.cpp
+++ b/src/main/cpp/loggingevent.cpp
@@ -37,6 +37,7 @@
#include <log4cxx/helpers/bytebuffer.h>
#include <log4cxx/logger.h>
#include <log4cxx/private/log4cxx_private.h>
+#include <log4cxx/helpers/date.h>
using namespace log4cxx;
using namespace log4cxx::spi;
@@ -75,7 +76,7 @@ LoggingEvent::LoggingEvent(
ndcLookupRequired(true),
mdcCopyLookupRequired(true),
message(message1),
- timeStamp(apr_time_now()),
+ timeStamp(Date::currentTime()),
locationInfo(locationInfo1),
threadName(getCurrentThreadName()),
threadUserName(getCurrentThreadUserName())
diff --git a/src/main/cpp/timebasedrollingpolicy.cpp b/src/main/cpp/timebasedrollingpolicy.cpp
index c81f09d..cd1fe90 100644
--- a/src/main/cpp/timebasedrollingpolicy.cpp
+++ b/src/main/cpp/timebasedrollingpolicy.cpp
@@ -34,12 +34,6 @@
#include <log4cxx/rolling/rollingfileappenderskeleton.h>
#include<iostream>
-#ifndef INT64_C
- #define INT64_C(x) x ## LL
-#endif
-
-#include <apr_time.h>
-
using namespace log4cxx;
using namespace log4cxx::rolling;
using namespace log4cxx::helpers;
@@ -202,9 +196,8 @@ void TimeBasedRollingPolicy::activateOptions(log4cxx::helpers::Pool& pool)
throw IllegalStateException();
}
- apr_time_t n = apr_time_now();
LogString buf;
- ObjectPtr obj(new Date(n));
+ ObjectPtr obj(new Date());
formatFileName(obj, buf, pool);
lastFileName = buf;
@@ -268,8 +261,9 @@ RolloverDescriptionPtr TimeBasedRollingPolicy::initialize(
const bool append,
Pool& pool)
{
- apr_time_t n = apr_time_now();
- nextCheck = ((n / APR_USEC_PER_SEC) + 1) * APR_USEC_PER_SEC;
+ Date now;
+ log4cxx_time_t n = now.getTime();
+ nextCheck = now.getNextSecond();
File currentFile(currentActiveFile);
@@ -299,8 +293,9 @@ RolloverDescriptionPtr TimeBasedRollingPolicy::rollover(
const bool append,
Pool& pool)
{
- apr_time_t n = apr_time_now();
- nextCheck = ((n / APR_USEC_PER_SEC) + 1) * APR_USEC_PER_SEC;
+ Date now;
+ log4cxx_time_t n = now.getTime();
+ nextCheck = now.getNextSecond();
LogString buf;
ObjectPtr obj(new Date(n));
@@ -419,6 +414,6 @@ bool TimeBasedRollingPolicy::isTriggeringEvent(
return ((apr_time_now()) > nextCheck) || (!bAlreadyInitialized);
#else
- return apr_time_now() > nextCheck;
+ return Date::currentTime() > nextCheck;
#endif
}
diff --git a/src/main/include/log4cxx/helpers/date.h b/src/main/include/log4cxx/helpers/date.h
index facace7..c031531 100644
--- a/src/main/include/log4cxx/helpers/date.h
+++ b/src/main/include/log4cxx/helpers/date.h
@@ -20,7 +20,7 @@
#include <log4cxx/helpers/object.h>
#include <log4cxx/log4cxx.h>
-
+#include <functional>
namespace log4cxx
{
@@ -36,6 +36,13 @@ class LOG4CXX_EXPORT Date : public Object
{
const log4cxx_time_t time;
+ /**
+ * A function that will return the current time(in microseconds) when called
+ */
+ typedef std::function<log4cxx_time_t()> GetCurrentTimeFn;
+
+ static log4cxx_time_t getCurrentTimeStd();
+
public:
DECLARE_LOG4CXX_OBJECT(Date)
BEGIN_LOG4CXX_CAST_MAP()
@@ -60,6 +67,19 @@ class LOG4CXX_EXPORT Date : public Object
static log4cxx_time_t getMicrosecondsPerDay();
static log4cxx_time_t getMicrosecondsPerSecond();
+ static log4cxx_time_t currentTime();
+
+ static GetCurrentTimeFn getCurrentTimeFn;
+
+ /**
+ * Set the function that is used to get the current time.
+ * This is used only for testing purposes and should never be called
+ * under normal circumstances.
+ *
+ * @param fn
+ */
+ static void setGetCurrentTimeFunction(GetCurrentTimeFn fn);
+
};
LOG4CXX_PTR_DEF(Date);
diff --git a/src/main/include/log4cxx/rolling/timebasedrollingpolicy.h b/src/main/include/log4cxx/rolling/timebasedrollingpolicy.h
index ddeacf5..7c82e3d 100755
--- a/src/main/include/log4cxx/rolling/timebasedrollingpolicy.h
+++ b/src/main/include/log4cxx/rolling/timebasedrollingpolicy.h
@@ -25,6 +25,7 @@
#include <log4cxx/writerappender.h>
#include <log4cxx/helpers/outputstream.h>
#include <apr_mmap.h>
+#include <functional>
#if defined(_MSC_VER)
#pragma warning ( push )
diff --git a/src/test/cpp/rolling/timebasedrollingtest.cpp b/src/test/cpp/rolling/timebasedrollingtest.cpp
index 706cb3d..9fadd16 100644
--- a/src/test/cpp/rolling/timebasedrollingtest.cpp
+++ b/src/test/cpp/rolling/timebasedrollingtest.cpp
@@ -24,6 +24,7 @@
#include <log4cxx/patternlayout.h>
#include <log4cxx/rolling/timebasedrollingpolicy.h>
#include <log4cxx/helpers/simpledateformat.h>
+#include <log4cxx/helpers/date.h>
#include <iostream>
#include <log4cxx/helpers/stringhelper.h>
#include "../util/compare.h"
@@ -91,6 +92,8 @@ private:
*/
size_t num_test;
+ log4cxx_time_t current_time;
+
/**
* Build file names with timestamps.
* <p>
@@ -127,7 +130,7 @@ private:
bool startInFuture = false)
{
SimpleDateFormat sdf(DATE_PATTERN_STR);
- apr_time_t now(apr_time_now());
+ log4cxx_time_t now(current_time);
LogString ext(withCompression ? LOG4CXX_STR(".gz") : LOG4CXX_STR(""));
now += startInFuture ? APR_USEC_PER_SEC : 0;
@@ -197,7 +200,7 @@ private:
message.append(pool.itoa(i));
LOG4CXX_DEBUG(logger, message);
- apr_sleep(APR_USEC_PER_SEC * waitFactor);
+ current_time += (APR_USEC_PER_SEC * waitFactor);
}
#undef LOG4CXX_LOCATION
@@ -299,12 +302,9 @@ private:
* </p>
* @param[in,opt] millis
*/
- void delayUntilNextSecond(size_t millis = 100)
+ void delayUntilNextSecond()
{
- 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);
+ current_time += APR_USEC_PER_SEC;
}
/**
@@ -315,11 +315,10 @@ private:
* </p>
* @param[in,opt] millis
*/
- void delayUntilNextSecondWithMsg(size_t millis = 100)
+ void delayUntilNextSecondWithMsg()
{
- std::cout << "Waiting until next second and " << millis << " millis.";
- delayUntilNextSecond(millis);
- std::cout << "Done waiting." << std::endl;
+ std::cout << "Advancing one second\n";
+ delayUntilNextSecond();
}
/**
@@ -385,6 +384,11 @@ public:
this->num_test = tc->suite->num_test;
}
+ log4cxx_time_t currentTime()
+ {
+ return current_time;
+ }
+
void setUp()
{
LoggerPtr root(Logger::getRootLogger());
@@ -393,6 +397,11 @@ public:
PatternLayoutPtr(new PatternLayout(
LOG4CXX_STR("%d{ABSOLUTE} [%t] %level %c{2}#%M:%L - %m%n"))))));
this->internalSetUp(this->num_test);
+// current_time = log4cxx::helpers::Date::currentTime(); // Start at "about" now.
+// current_time -= (current_time % APR_USEC_PER_SEC); // Go to the top of the second
+// current_time++; // Need to not be at the top of a second for rollover logic to work correctly
+ current_time = 1; // Start at about unix epoch
+ log4cxx::helpers::Date::setGetCurrentTimeFunction( std::bind( &TimeBasedRollingTest::currentTime, this ) );
}
void tearDown()
@@ -427,6 +436,7 @@ public:
this->compareWitnesses( pool, LOG4CXX_STR("test1."), fileNames, __LINE__);
}
+
/**
* No compression, with stop/restart, activeFileName left blank
*/
@@ -469,6 +479,7 @@ public:
this->compareWitnesses( pool, LOG4CXX_STR("test2."), fileNames, __LINE__);
}
+
/**
* With compression, activeFileName left blank, no stop/restart
*/
@@ -674,6 +685,7 @@ public:
LOGUNIT_ASSERT_EQUAL(true, File(fileNames[x]).exists(pool));
}
}
+
};
LoggerPtr TimeBasedRollingTest::logger(Logger::getLogger("org.apache.log4j.TimeBasedRollingTest"));