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:29 UTC
[logging-log4cxx] 02/02: Time based tests kinda work with fake clock at this point
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"));