Reduce precision of common timer test

Ideally timers would be perfectly accurate and we could sleep for 1.0 seconds,
but on OSX in particular they could fire 50-100 ms late (I've seen 4 ms in
practice) and we don't want the tests to fail because of this, because we don't
really need that kind of precision in practice. So we reduce the timer
intervals by 100ms to be safe.

Increase logging level and add timestamps in testcommon.  Should help to debug
frequent test failures such as Condition [t2.HasExpired()] on OSX hosts on
Travis.

Add a SettingsGuard to the Console logger for its specific settings, such as
showing times and microseconds.

(cherry picked from commit a5e6cff1d435329b0121417ed9509e315ce0edd5)
(cherry picked from commit 8d02eebce553ed822e0fcd60d6e319384e15ba4b)

2 files changed, 80 insertions, 41 deletions

diff --git a/lib/common/Logging.h b/lib/common/Logging.h
index 01358617..3dc3e69c 100644
--- a/lib/common/Logging.h
+++ b/lib/common/Logging.h
@@ -295,6 +295,32 @@ class Console : public Logger
 	static void SetShowTimeMicros(bool enabled);
 	static void SetShowPID(bool enabled);
 	static bool GetShowTag() { return sShowTag; }
+
+	class SettingsGuard
+	{
+		private:
+		bool mShowTag;
+		bool mShowTime;
+		bool mShowTimeMicros;
+		bool mShowPID;
+		std::string mTag;
+		public:
+		SettingsGuard()
+		: mShowTag(Console::sShowTag),
+		  mShowTime(Console::sShowTime),
+		  mShowTimeMicros(Console::sShowTimeMicros),
+		  mShowPID(Console::sShowPID),
+		  mTag(Console::sTag)
+		{ }
+		~SettingsGuard()
+		{
+			Console::SetShowTag(mShowTag);
+			Console::SetShowTime(mShowTime);
+			Console::SetShowTimeMicros(mShowTimeMicros);
+			Console::SetShowPID(mShowPID);
+			Console::sTag = mTag;
+		}
+	};
 };
 
 // --------------------------------------------------------------------------
diff --git a/test/common/testcommon.cpp b/test/common/testcommon.cpp
index fbdf8d9c..bd75ac37 100644
--- a/test/common/testcommon.cpp
+++ b/test/common/testcommon.cpp
@@ -344,47 +344,60 @@ int test(int argc, const char *argv[])
 
 	Timers::Init();
 
-	Timer t0(0, "t0"); // should never expire
-	Timer t1(1000, "t1");
-	Timer t2(2000, "t2");
-	Timer t3(3000, "t3");
-	
-	TEST_THAT(!t0.HasExpired());
-	TEST_THAT(!t1.HasExpired());
-	TEST_THAT(!t2.HasExpired());
-	TEST_THAT(!t3.HasExpired());
-	
-	safe_sleep(1);
-	TEST_THAT(!t0.HasExpired());
-	TEST_THAT(t1.HasExpired());
-	TEST_THAT(!t2.HasExpired());
-	TEST_THAT(!t3.HasExpired());
-	
-	safe_sleep(1);
-	TEST_THAT(!t0.HasExpired());
-	TEST_THAT(t1.HasExpired());
-	TEST_THAT(t2.HasExpired());
-	TEST_THAT(!t3.HasExpired());
-
-	// Try both ways of resetting an existing timer.
-	t1 = Timer(1000, "t1a");
-	t2.Reset(2000);
-	TEST_THAT(!t0.HasExpired());
-	TEST_THAT(!t1.HasExpired());
-	TEST_THAT(!t2.HasExpired());
-	TEST_THAT(!t3.HasExpired());
-	
-	safe_sleep(1);
-	TEST_THAT(!t0.HasExpired());
-	TEST_THAT(t1.HasExpired());
-	TEST_THAT(!t2.HasExpired());
-	TEST_THAT(t3.HasExpired());
-
-	safe_sleep(1);
-	TEST_THAT(!t0.HasExpired());
-	TEST_THAT(t1.HasExpired());
-	TEST_THAT(t2.HasExpired());
-	TEST_THAT(t3.HasExpired());
+	// Ideally timers would be perfectly accurate and we could sleep for 1.0 seconds, but
+	// on OSX in particular they could fire 50-100 ms late (I've seen 4 ms in practice)
+	// and we don't want the tests to fail because of this, because we don't really need
+	// that kind of precision in practice. So we reduce the timer intervals by 100ms to
+	// be safe.
+
+	{
+		Logger::LevelGuard temporary_verbosity(Logging::GetConsole(), Log::TRACE);
+		Console::SettingsGuard save_old_settings;
+		Console::SetShowTime(true);
+		Console::SetShowTimeMicros(true);
+
+		Timer t0(0, "t0"); // should never expire
+		Timer t1(900, "t1");
+		Timer t2(1900, "t2");
+		Timer t3(2900, "t3");
+
+		TEST_THAT(!t0.HasExpired());
+		TEST_THAT(!t1.HasExpired());
+		TEST_THAT(!t2.HasExpired());
+		TEST_THAT(!t3.HasExpired());
+		safe_sleep(1);
+
+		TEST_THAT(!t0.HasExpired());
+		TEST_THAT(t1.HasExpired());
+		TEST_THAT(!t2.HasExpired());
+		TEST_THAT(!t3.HasExpired());
+
+		safe_sleep(1);
+		TEST_THAT(!t0.HasExpired());
+		TEST_THAT(t1.HasExpired());
+		TEST_THAT(t2.HasExpired());
+		TEST_THAT(!t3.HasExpired());
+
+		// Try both ways of resetting an existing timer.
+		t1 = Timer(900, "t1a");
+		t2.Reset(1900);
+		TEST_THAT(!t0.HasExpired());
+		TEST_THAT(!t1.HasExpired());
+		TEST_THAT(!t2.HasExpired());
+		TEST_THAT(!t3.HasExpired());
+
+		safe_sleep(1);
+		TEST_THAT(!t0.HasExpired());
+		TEST_THAT(t1.HasExpired());
+		TEST_THAT(!t2.HasExpired());
+		TEST_THAT(t3.HasExpired());
+
+		safe_sleep(1);
+		TEST_THAT(!t0.HasExpired());
+		TEST_THAT(t1.HasExpired());
+		TEST_THAT(t2.HasExpired());
+		TEST_THAT(t3.HasExpired());
+	}
 
 	// Leave timers initialised for rest of test.
 	// Test main() will cleanup after test finishes.