Commit 85a4cc71 authored by Nick Craver's avatar Nick Craver Committed by Nick Craver

Tests: add "LogToConsole" config option, allowing instant console output as well

This helps for real-time output on long-running or hanging tests.
parent fc06d78c
......@@ -23,7 +23,7 @@ public void PingOnce()
var task = conn.PingAsync();
var duration = muxer.Wait(task);
Output.WriteLine("Ping took: " + duration);
Log("Ping took: " + duration);
Assert.True(duration.TotalMilliseconds > 0);
}
}
......@@ -256,7 +256,7 @@ public async Task GetWithExpiryWrongTypeAsync()
{
try
{
Output.WriteLine("Key: " + (string)key);
Log("Key: " + (string)key);
var async = await db.StringGetWithExpiryAsync(key).ForAwait();
}
catch (AggregateException e)
......@@ -296,12 +296,12 @@ public void TestQuit()
db.KeyDelete(key, CommandFlags.FireAndForget);
db.StringSet(key, key, flags: CommandFlags.FireAndForget);
GetServer(muxer).Execute("QUIT", null, CommandFlags.FireAndForget);
var watch = System.Diagnostics.Stopwatch.StartNew();
var watch = Stopwatch.StartNew();
Assert.Throws<RedisConnectionException>(() => db.Ping());
watch.Stop();
Output.WriteLine("Time to notice quit: {0}ms (any order)", watch.ElapsedMilliseconds);
System.Threading.Thread.Sleep(20);
System.Diagnostics.Debug.WriteLine("Pinging...");
Log("Time to notice quit: {0}ms (any order)", watch.ElapsedMilliseconds);
Thread.Sleep(20);
Debug.WriteLine("Pinging...");
Assert.Equal(key, (string)db.StringGet(key));
}
}
......@@ -322,7 +322,7 @@ public async Task TestSevered()
var watch = Stopwatch.StartNew();
db.Ping();
watch.Stop();
Output.WriteLine("Time to re-establish: {0}ms (any order)", watch.ElapsedMilliseconds);
Log("Time to re-establish: {0}ms (any order)", watch.ElapsedMilliseconds);
await Task.Delay(2000).ForAwait();
Debug.WriteLine("Pinging...");
Assert.Equal(key, db.StringGet(key));
......
......@@ -27,6 +27,23 @@ static BookSleeveTestBase()
};
}
protected void Log(string message)
{
Output.WriteLine(message);
if (TestConfig.Current.LogToConsole)
{
Console.WriteLine(message);
}
}
protected void Log(string message, params object[] args)
{
Output.WriteLine(message, args);
if (TestConfig.Current.LogToConsole)
{
Console.WriteLine(message, args);
}
}
protected static string Me([CallerFilePath] string filePath = null, [CallerMemberName] string caller = null) => TestBase.Me(filePath, caller);
internal static IServer GetServer(ConnectionMultiplexer conn) => conn.GetServer(conn.GetEndPoints()[0]);
......
......@@ -44,7 +44,7 @@ public void CanNotOpenNonsenseConnection_IP()
}
finally
{
Output.WriteLine(log.ToString());
Log(log.ToString());
}
});
}
......@@ -63,10 +63,10 @@ public async Task CanNotOpenNonsenseConnection_DNS()
}
finally
{
Output.WriteLine(log.ToString());
Log(log.ToString());
}
}).ForAwait();
Output.WriteLine(ex.ToString());
Log(ex.ToString());
}
[Fact]
......@@ -83,7 +83,7 @@ public void CreateDisconnectedNonsenseConnection_IP()
}
finally
{
Output.WriteLine(log.ToString());
Log(log.ToString());
}
}
......@@ -101,7 +101,7 @@ public void CreateDisconnectedNonsenseConnection_DNS()
}
finally
{
Output.WriteLine(log.ToString());
Log(log.ToString());
}
}
......
......@@ -69,11 +69,11 @@ public async Task ExecuteMassiveDelete()
}
watch.Stop();
long remaining = await conn.SetLengthAsync(key).ForAwait();
Output.WriteLine("From {0} to {1}; {2}ms", originally, remaining,
Log("From {0} to {1}; {2}ms", originally, remaining,
watch.ElapsedMilliseconds);
var counters = GetServer(muxer).GetCounters();
Output.WriteLine("Completions: {0} sync, {1} async", counters.Interactive.CompletedSynchronously, counters.Interactive.CompletedAsynchronously);
Log("Completions: {0} sync, {1} async", counters.Interactive.CompletedSynchronously, counters.Interactive.CompletedAsynchronously);
}
}
}
......
......@@ -42,7 +42,7 @@ public void VerifyPerformanceImprovement()
muxer.WaitAll(final);
timer.Stop();
asyncTimer = (int)timer.ElapsedMilliseconds;
Output.WriteLine("async to completion (local): {0}ms", timer.ElapsedMilliseconds);
Log("async to completion (local): {0}ms", timer.ElapsedMilliseconds);
for (int db = 0; db < 5; db++)
{
Assert.Equal(1000, (long)final[db].Result); // "async, db:" + db
......@@ -83,7 +83,7 @@ public void VerifyPerformanceImprovement()
}
timer.Stop();
sync = (int)timer.ElapsedMilliseconds;
Output.WriteLine("sync to completion (local): {0}ms", timer.ElapsedMilliseconds);
Log("sync to completion (local): {0}ms", timer.ElapsedMilliseconds);
for (int db = 0; db < 5; db++)
{
Assert.Equal("1000", final[db]); // "async, db:" + db
......@@ -91,9 +91,9 @@ public void VerifyPerformanceImprovement()
}
int effectiveAsync = ((10 * asyncTimer) + 3) / 10;
int effectiveSync = ((10 * sync) + (op * 3)) / 10;
Output.WriteLine("async to completion with assumed 0.3ms LAN latency: " + effectiveAsync);
Output.WriteLine("sync to completion with assumed 0.3ms LAN latency: " + effectiveSync);
Output.WriteLine("fire-and-forget: {0}ms sync vs {1}ms async ", syncFaF, asyncFaF);
Log("async to completion with assumed 0.3ms LAN latency: " + effectiveAsync);
Log("sync to completion with assumed 0.3ms LAN latency: " + effectiveSync);
Log("fire-and-forget: {0}ms sync vs {1}ms async ", syncFaF, asyncFaF);
Assert.True(effectiveAsync < effectiveSync, "Everything");
Assert.True(asyncFaF < syncFaF, "Fire and Forget");
}
......@@ -119,7 +119,7 @@ public async Task BasicStringGetPerf()
asyncVal = await db.StringGetAsync(key);
asyncTimer.Stop();
Output.WriteLine($"Sync: {syncTimer.ElapsedMilliseconds}; Async: {asyncTimer.ElapsedMilliseconds}");
Log($"Sync: {syncTimer.ElapsedMilliseconds}; Async: {asyncTimer.ElapsedMilliseconds}");
Assert.Equal("some value", syncVal);
Assert.Equal("some value", asyncVal);
// let's allow 20% async overhead
......
......@@ -71,7 +71,7 @@ private void TestMassivePublish(ISubscriber conn, string channel, string caption
conn.WaitAll(tasks);
withAsync.Stop();
Output.WriteLine("{2}: {0}ms (F+F) vs {1}ms (async)",
Log("{2}: {0}ms (F+F) vs {1}ms (async)",
withFAF.ElapsedMilliseconds, withAsync.ElapsedMilliseconds, caption);
// We've made async so far, this test isn't really valid anymore
// So let's check they're at least within a few seconds.
......@@ -97,7 +97,7 @@ public async Task PubSubGetAllAnyOrder()
{
data.Add(int.Parse(Encoding.UTF8.GetString(val)));
pulse = data.Count == count;
if ((data.Count % 100) == 99) Output.WriteLine(data.Count.ToString());
if ((data.Count % 100) == 99) Log(data.Count.ToString());
}
if (pulse)
{
......@@ -153,7 +153,7 @@ async Task RunLoop()
{
data.Add(i);
if (data.Count == count) break;
if ((data.Count % 100) == 99) Output.WriteLine(data.Count.ToString());
if ((data.Count % 100) == 99) Log(data.Count.ToString());
}
}
lock (syncLock)
......@@ -211,7 +211,7 @@ public async Task PubSubGetAllCorrectOrder_OnMessage_Sync()
{
data.Add(i);
if (data.Count == count) pulse = true;
if ((data.Count % 100) == 99) Output.WriteLine(data.Count.ToString());
if ((data.Count % 100) == 99) Log(data.Count.ToString());
}
if (pulse)
{
......@@ -271,7 +271,7 @@ public async Task PubSubGetAllCorrectOrder_OnMessage_Async()
{
data.Add(i);
if (data.Count == count) pulse = true;
if ((data.Count % 100) == 99) Output.WriteLine(data.Count.ToString());
if ((data.Count % 100) == 99) Log(data.Count.ToString());
}
if (pulse)
{
......
......@@ -116,7 +116,7 @@ public void HackyGetPerf()
redis.call('del', KEYS[1])
return timeTaken
", new RedisKey[] { key }, null);
Output.WriteLine(result.ToString());
Log(result.ToString());
Assert.True(result > 0);
}
}
......@@ -333,7 +333,7 @@ public void ChangeDbInScript()
muxer.GetDatabase(1).StringSet(key, "db 1");
muxer.GetDatabase(2).StringSet(key, "db 2");
Output.WriteLine("Key: " + key);
Log("Key: " + key);
var conn = muxer.GetDatabase(2);
var evalResult = conn.ScriptEvaluateAsync(@"redis.call('select', 1)
return redis.call('get','" + key +"')", null, null);
......
This diff is collapsed.
......@@ -26,7 +26,7 @@ public void TalkToNonsenseServer()
var log = new StringWriter();
using (var conn = ConnectionMultiplexer.Connect(config, log))
{
Output.WriteLine(log.ToString());
Log(log.ToString());
Assert.False(conn.IsConnected);
}
}
......@@ -41,7 +41,7 @@ public void TestManaulHeartbeat()
var before = muxer.OperationCount;
Output.WriteLine("sleeping to test heartbeat...");
Log("sleeping to test heartbeat...");
Thread.Sleep(TimeSpan.FromSeconds(5));
var after = muxer.OperationCount;
......@@ -120,7 +120,7 @@ public void ReadConfig()
{
using (var muxer = Create(allowAdmin: true))
{
Output.WriteLine("about to get config");
Log("about to get config");
var conn = GetAnyMaster(muxer);
var all = conn.ConfigGet();
Assert.True(all.Length > 0, "any");
......@@ -144,7 +144,7 @@ public void GetTime()
{
var server = GetAnyMaster(muxer);
var serverTime = server.Time();
Output.WriteLine(serverTime.ToString());
Log(serverTime.ToString());
var delta = Math.Abs((DateTime.UtcNow - serverTime).TotalSeconds);
Assert.True(delta < 5);
......@@ -174,16 +174,16 @@ public void GetInfo()
var server = GetAnyMaster(muxer);
var info1 = server.Info();
Assert.True(info1.Length > 5);
Output.WriteLine("All sections");
Log("All sections");
foreach (var group in info1)
{
Output.WriteLine(group.Key);
Log(group.Key);
}
var first = info1[0];
Output.WriteLine("Full info for: " + first.Key);
Log("Full info for: " + first.Key);
foreach (var setting in first)
{
Output.WriteLine("{0} ==> {1}", setting.Key, setting.Value);
Log("{0} ==> {1}", setting.Key, setting.Value);
}
var info2 = server.Info("cpu");
......@@ -253,7 +253,7 @@ public void TestAutomaticHeartbeat()
var before = innerMuxer.OperationCount;
Output.WriteLine("sleeping to test heartbeat...");
Log("sleeping to test heartbeat...");
Thread.Sleep(TimeSpan.FromSeconds(8));
var after = innerMuxer.OperationCount;
......
......@@ -18,9 +18,9 @@ public async Task NoticesConnectFail()
{
var server = conn.GetServer(conn.GetEndPoints()[0]);
conn.ConnectionFailed += (s, a) =>
Output.WriteLine("Disconnected: " + EndPointCollection.ToString(a.EndPoint));
Log("Disconnected: " + EndPointCollection.ToString(a.EndPoint));
conn.ConnectionRestored += (s, a) =>
Output.WriteLine("Reconnected: " + EndPointCollection.ToString(a.EndPoint));
Log("Reconnected: " + EndPointCollection.ToString(a.EndPoint));
// No need to delay, we're going to try a disconnected connection immediately so it'll fail...
conn.IgnoreConnect = true;
......@@ -32,7 +32,7 @@ public async Task NoticesConnectFail()
await Task.Delay(5000).ConfigureAwait(false);
var time = server.Ping();
Output.WriteLine(time.ToString());
Log(time.ToString());
}
}
#endif
......
......@@ -33,8 +33,8 @@ public void FailsWithinTimeout()
catch (RedisConnectionException)
{
var elapsed = sw.ElapsedMilliseconds;
Output.WriteLine("Elapsed time: " + elapsed);
Output.WriteLine("Timeout: " + timeout);
Log("Elapsed time: " + elapsed);
Log("Timeout: " + timeout);
Assert.True(elapsed < 9000, "Connect should fail within ConnectTimeout, ElapsedMs: " + elapsed);
}
}
......
......@@ -37,7 +37,7 @@ public void FastNoticesFailOnConnectingSyncComlpetion()
// should reconnect within 1 keepalive interval
muxer.AllowConnect = true;
Output.WriteLine("Waiting for reconnect");
Log("Waiting for reconnect");
Thread.Sleep(2000);
Assert.True(muxer.IsConnected);
......@@ -96,7 +96,7 @@ public void FastNoticesFailOnConnectingAsyncComlpetion()
// should reconnect within 1 keepalive interval
muxer.AllowConnect = true;
Output.WriteLine("Waiting for reconnect");
Log("Waiting for reconnect");
Thread.Sleep(2000);
Assert.True(muxer.IsConnected);
......
......@@ -19,12 +19,12 @@ public void ShutdownRaisesConnectionFailedAndRestore()
Stopwatch watch = Stopwatch.StartNew();
conn.ConnectionFailed += (sender, args) =>
{
Output.WriteLine(watch.Elapsed + ": failed: " + EndPointCollection.ToString(args.EndPoint) + "/" + args.ConnectionType);
Log(watch.Elapsed + ": failed: " + EndPointCollection.ToString(args.EndPoint) + "/" + args.ConnectionType);
Interlocked.Increment(ref failed);
};
conn.ConnectionRestored += (sender, args) =>
{
Output.WriteLine(watch.Elapsed + ": restored: " + EndPointCollection.ToString(args.EndPoint) + "/" + args.ConnectionType);
Log(watch.Elapsed + ": restored: " + EndPointCollection.ToString(args.EndPoint) + "/" + args.ConnectionType);
Interlocked.Increment(ref restored);
};
var db = conn.GetDatabase();
......
......@@ -58,7 +58,7 @@ public void TestBasicExpiryDateTime(bool disablePTimes, bool utc)
conn.KeyDelete(key, CommandFlags.FireAndForget);
var now = utc ? DateTime.UtcNow : DateTime.Now;
Output.WriteLine("Now: {0}", now);
Log("Now: {0}", now);
conn.StringSet(key, "new value", flags: CommandFlags.FireAndForget);
var a = conn.KeyTimeToLiveAsync(key);
conn.KeyExpire(key, now.AddHours(1), CommandFlags.FireAndForget);
......@@ -73,7 +73,7 @@ public void TestBasicExpiryDateTime(bool disablePTimes, bool utc)
Assert.Null(muxer.Wait(a));
var time = muxer.Wait(b);
Assert.NotNull(time);
Output.WriteLine("Time: {0}, Expected: {1}-{2}", time, TimeSpan.FromMinutes(59), TimeSpan.FromMinutes(60));
Log("Time: {0}, Expected: {1}-{2}", time, TimeSpan.FromMinutes(59), TimeSpan.FromMinutes(60));
Assert.True(time >= TimeSpan.FromMinutes(59));
Assert.True(time <= TimeSpan.FromMinutes(60));
Assert.Null(muxer.Wait(c));
......
......@@ -17,14 +17,14 @@ public Failover(ITestOutputHelper output) : base(output)
var shouldBeMaster = mutex.GetServer(TestConfig.Current.FailoverMasterServerAndPort);
if (shouldBeMaster.IsSlave)
{
Output.WriteLine(shouldBeMaster.EndPoint + " should be master, fixing...");
Log(shouldBeMaster.EndPoint + " should be master, fixing...");
shouldBeMaster.MakeMaster(ReplicationChangeOptions.SetTiebreaker);
}
var shouldBeReplica = mutex.GetServer(TestConfig.Current.FailoverSlaveServerAndPort);
if (!shouldBeReplica.IsSlave)
{
Output.WriteLine(shouldBeReplica.EndPoint + " should be a slave, fixing...");
Log(shouldBeReplica.EndPoint + " should be a slave, fixing...");
shouldBeReplica.SlaveOf(shouldBeMaster.EndPoint);
Thread.Sleep(2000);
}
......@@ -51,9 +51,9 @@ public async Task ConfigureAsync()
using (var muxer = Create())
{
Thread.Sleep(1000);
Output.WriteLine("About to reconfigure.....");
Log("About to reconfigure.....");
await muxer.ConfigureAsync().ForAwait();
Output.WriteLine("Reconfigured");
Log("Reconfigured");
}
}
......@@ -63,9 +63,9 @@ public void ConfigureSync()
using (var muxer = Create())
{
Thread.Sleep(1000);
Output.WriteLine("About to reconfigure.....");
Log("About to reconfigure.....");
muxer.Configure();
Output.WriteLine("Reconfigured");
Log("Reconfigured");
}
}
......@@ -79,7 +79,7 @@ public async Task ConfigVerifyReceiveConfigChangeBroadcast()
int total = 0;
receiver.ConfigurationChangedBroadcast += (s, a) =>
{
Output.WriteLine("Config changed: " + (a.EndPoint == null ? "(none)" : a.EndPoint.ToString()));
Log("Config changed: " + (a.EndPoint == null ? "(none)" : a.EndPoint.ToString()));
Interlocked.Increment(ref total);
};
// send a reconfigure/reconnect message
......@@ -208,20 +208,20 @@ public async Task SubscriptionsSurviveMasterSwitchAsync()
long masterChanged = 0, aCount = 0, bCount = 0;
a.ConfigurationChangedBroadcast += delegate
{
Output.WriteLine("A noticed config broadcast: " + Interlocked.Increment(ref masterChanged));
Log("A noticed config broadcast: " + Interlocked.Increment(ref masterChanged));
};
b.ConfigurationChangedBroadcast += delegate
{
Output.WriteLine("B noticed config broadcast: " + Interlocked.Increment(ref masterChanged));
Log("B noticed config broadcast: " + Interlocked.Increment(ref masterChanged));
};
subA.Subscribe(channel, (_, message) =>
{
Output.WriteLine("A got message: " + message);
Log("A got message: " + message);
Interlocked.Increment(ref aCount);
});
subB.Subscribe(channel, (_, message) =>
{
Output.WriteLine("B got message: " + message);
Log("B got message: " + message);
Interlocked.Increment(ref bCount);
});
......@@ -232,8 +232,8 @@ public async Task SubscriptionsSurviveMasterSwitchAsync()
var epA = subA.SubscribedEndpoint(channel);
var epB = subB.SubscribedEndpoint(channel);
Output.WriteLine("A: " + EndPointCollection.ToString(epA));
Output.WriteLine("B: " + EndPointCollection.ToString(epB));
Log("A: " + EndPointCollection.ToString(epA));
Log("B: " + EndPointCollection.ToString(epB));
subA.Publish(channel, "A1");
subB.Publish(channel, "B1");
subA.Ping();
......@@ -248,41 +248,41 @@ public async Task SubscriptionsSurviveMasterSwitchAsync()
Interlocked.Exchange(ref masterChanged, 0);
Interlocked.Exchange(ref aCount, 0);
Interlocked.Exchange(ref bCount, 0);
Output.WriteLine("Changing master...");
Log("Changing master...");
using (var sw = new StringWriter())
{
a.GetServer(TestConfig.Current.FailoverSlaveServerAndPort).MakeMaster(ReplicationChangeOptions.All, sw);
Output.WriteLine(sw.ToString());
Log(sw.ToString());
}
await Task.Delay(5000).ForAwait();
subA.Ping();
subB.Ping();
Output.WriteLine("Pausing...");
Output.WriteLine("A " + TestConfig.Current.FailoverMasterServerAndPort + " status: " + (a.GetServer(TestConfig.Current.FailoverMasterServerAndPort).IsSlave ? "Slave" : "Master"));
Output.WriteLine("A " + TestConfig.Current.FailoverSlaveServerAndPort + " status: " + (a.GetServer(TestConfig.Current.FailoverSlaveServerAndPort).IsSlave ? "Slave" : "Master"));
Output.WriteLine("B " + TestConfig.Current.FailoverMasterServerAndPort + " status: " + (b.GetServer(TestConfig.Current.FailoverMasterServerAndPort).IsSlave ? "Slave" : "Master"));
Output.WriteLine("B " + TestConfig.Current.FailoverSlaveServerAndPort + " status: " + (b.GetServer(TestConfig.Current.FailoverSlaveServerAndPort).IsSlave ? "Slave" : "Master"));
Log("Pausing...");
Log("A " + TestConfig.Current.FailoverMasterServerAndPort + " status: " + (a.GetServer(TestConfig.Current.FailoverMasterServerAndPort).IsSlave ? "Slave" : "Master"));
Log("A " + TestConfig.Current.FailoverSlaveServerAndPort + " status: " + (a.GetServer(TestConfig.Current.FailoverSlaveServerAndPort).IsSlave ? "Slave" : "Master"));
Log("B " + TestConfig.Current.FailoverMasterServerAndPort + " status: " + (b.GetServer(TestConfig.Current.FailoverMasterServerAndPort).IsSlave ? "Slave" : "Master"));
Log("B " + TestConfig.Current.FailoverSlaveServerAndPort + " status: " + (b.GetServer(TestConfig.Current.FailoverSlaveServerAndPort).IsSlave ? "Slave" : "Master"));
Assert.True(a.GetServer(TestConfig.Current.FailoverMasterServerAndPort).IsSlave, $"A Connection: {TestConfig.Current.FailoverMasterServerAndPort} should be a slave");
Assert.False(a.GetServer(TestConfig.Current.FailoverSlaveServerAndPort).IsSlave, $"A Connection: {TestConfig.Current.FailoverSlaveServerAndPort} should be a master");
Assert.True(b.GetServer(TestConfig.Current.FailoverMasterServerAndPort).IsSlave, $"B Connection: {TestConfig.Current.FailoverMasterServerAndPort} should be a slave");
Assert.False(b.GetServer(TestConfig.Current.FailoverSlaveServerAndPort).IsSlave, $"B Connection: {TestConfig.Current.FailoverSlaveServerAndPort} should be a master");
Output.WriteLine("Pause complete");
Output.WriteLine("A outstanding: " + a.GetCounters().TotalOutstanding);
Output.WriteLine("B outstanding: " + b.GetCounters().TotalOutstanding);
Log("Pause complete");
Log("A outstanding: " + a.GetCounters().TotalOutstanding);
Log("B outstanding: " + b.GetCounters().TotalOutstanding);
subA.Ping();
subB.Ping();
await Task.Delay(2000).ForAwait();
epA = subA.SubscribedEndpoint(channel);
epB = subB.SubscribedEndpoint(channel);
Output.WriteLine("A: " + EndPointCollection.ToString(epA));
Output.WriteLine("B: " + EndPointCollection.ToString(epB));
Output.WriteLine("A2 sent to: " + subA.Publish(channel, "A2"));
Output.WriteLine("B2 sent to: " + subB.Publish(channel, "B2"));
Log("A: " + EndPointCollection.ToString(epA));
Log("B: " + EndPointCollection.ToString(epB));
Log("A2 sent to: " + subA.Publish(channel, "A2"));
Log("B2 sent to: " + subB.Publish(channel, "B2"));
subA.Ping();
subB.Ping();
Output.WriteLine("Checking...");
Log("Checking...");
Assert.Equal(2, Interlocked.Read(ref aCount));
Assert.Equal(2, Interlocked.Read(ref bCount));
......@@ -291,7 +291,7 @@ public async Task SubscriptionsSurviveMasterSwitchAsync()
}
finally
{
Output.WriteLine("Restoring configuration...");
Log("Restoring configuration...");
try
{
a.GetServer(TestConfig.Current.FailoverMasterServerAndPort).MakeMaster(ReplicationChangeOptions.All);
......
......@@ -44,6 +44,7 @@ static TestConfig()
public class Config
{
public bool RunLongRunning { get; set; }
public bool LogToConsole { get; set; }
public string MasterServer { get; set; } = "127.0.0.1";
public int MasterPort { get; set; } = 6379;
......
......@@ -10,7 +10,8 @@ public class TextWriterOutputHelper : TextWriter
private StringBuilder Buffer { get; } = new StringBuilder(2048);
public override Encoding Encoding => Encoding.UTF8;
private readonly ITestOutputHelper Output;
public TextWriterOutputHelper(ITestOutputHelper outputHelper) => Output = outputHelper;
private readonly bool ToConsole;
public TextWriterOutputHelper(ITestOutputHelper outputHelper, bool echoToConsole) => (Output, ToConsole) = (outputHelper, echoToConsole);
public override void WriteLine(string value)
{
......@@ -57,6 +58,10 @@ private void FlushBuffer()
{
var text = Buffer.ToString();
Output.WriteLine(text);
if (ToConsole)
{
Console.WriteLine(text);
}
Buffer.Clear();
}
}
......
......@@ -35,7 +35,7 @@ public void ConfigurationOptions_UnspecifiedDefaultDb()
}
finally
{
Output.WriteLine(log.ToString());
Log(log.ToString());
}
}
......@@ -52,7 +52,7 @@ public void ConfigurationOptions_SpecifiedDefaultDb()
}
finally
{
Output.WriteLine(log.ToString());
Log(log.ToString());
}
}
}
......
......@@ -19,9 +19,9 @@ public async Task SetMembers()
{
conn.ConnectionFailed += (s, a) =>
{
Output.WriteLine(a.FailureType.ToString());
Output.WriteLine(a.Exception.Message);
Output.WriteLine(a.Exception.StackTrace);
Log(a.FailureType.ToString());
Log(a.Exception.Message);
Log(a.Exception.StackTrace);
};
var db = conn.GetDatabase();
......
......@@ -12,10 +12,10 @@ public void ShouldWorkWithoutEchoOrPing()
{
using(var conn = Create(proxy: Proxy.Twemproxy))
{
Output.WriteLine("config: " + conn.Configuration);
Log("config: " + conn.Configuration);
var db = conn.GetDatabase();
var time = db.Ping();
Output.WriteLine("ping time: " + time);
Log("ping time: " + time);
}
}
}
......
......@@ -29,7 +29,7 @@ public void Execute()
var watch = Stopwatch.StartNew();
var isOperationSuccessful = tran.Execute();
watch.Stop();
Output.WriteLine("{0}ms", watch.ElapsedMilliseconds);
Log("{0}ms", watch.ElapsedMilliseconds);
Assert.True(isOperationSuccessful);
}
}
......
......@@ -36,7 +36,7 @@ public async Task MassiveBulkOpsAsync(bool withContinuation)
}
Assert.Equal(AsyncOpsQty, await conn.StringGetAsync(key).ForAwait());
watch.Stop();
Output.WriteLine("{2}: Time for {0} ops: {1}ms ({3}, any order); ops/s: {4}", AsyncOpsQty, watch.ElapsedMilliseconds, Me(),
Log("{2}: Time for {0} ops: {1}ms ({3}, any order); ops/s: {4}", AsyncOpsQty, watch.ElapsedMilliseconds, Me(),
withContinuation ? "with continuation" : "no continuation", AsyncOpsQty / watch.Elapsed.TotalSeconds);
}
}
......@@ -67,11 +67,11 @@ public void MassiveBulkOpsSync(int threads)
int val = (int)conn.StringGet(key);
Assert.Equal(workPerThread * threads, val);
Output.WriteLine("{2}: Time for {0} ops on {3} threads: {1}ms (any order); ops/s: {4}",
Log("{2}: Time for {0} ops on {3} threads: {1}ms (any order); ops/s: {4}",
threads * workPerThread, timeTaken.TotalMilliseconds, Me(), threads, (workPerThread * threads) / timeTaken.TotalSeconds);
#if DEBUG
long newAlloc = ConnectionMultiplexer.GetResultBoxAllocationCount();
Output.WriteLine("ResultBox allocations: {0}", newAlloc - oldAlloc);
Log("ResultBox allocations: {0}", newAlloc - oldAlloc);
Assert.True(newAlloc - oldAlloc <= 2 * threads, "number of box allocations");
#endif
}
......@@ -104,12 +104,12 @@ public void MassiveBulkOpsFireAndForget(int threads)
var val = (long)conn.StringGet(key);
Assert.Equal(perThread * threads, val);
Output.WriteLine("{2}: Time for {0} ops over {4} threads: {1:###,###}ms (any order); ops/s: {3:###,###,##0}",
Log("{2}: Time for {0} ops over {4} threads: {1:###,###}ms (any order); ops/s: {3:###,###,##0}",
val, elapsed.TotalMilliseconds, Me(),
val / elapsed.TotalSeconds, threads);
#if DEBUG
long newAlloc = ConnectionMultiplexer.GetResultBoxAllocationCount();
Output.WriteLine("ResultBox allocations: {0}",
Log("ResultBox allocations: {0}",
newAlloc - oldAlloc);
Assert.True(newAlloc - oldAlloc <= 4);
#endif
......
......@@ -34,7 +34,7 @@ public void TestMultiNoTieBreak()
using (var log = new StringWriter())
using (var conn = Create(log: log, tieBreaker: ""))
{
Output.WriteLine(log.ToString());
Log(log.ToString());
Assert.Contains("Choosing master arbitrarily", log.ToString());
}
}
......@@ -72,7 +72,7 @@ public void TestMultiWithTiebreak(string a, string b, string elected)
using (var conn = Create(log: log, tieBreaker: TieBreak))
{
string text = log.ToString();
Output.WriteLine(text);
Log(text);
Assert.False(text.Contains("failed to nominate"), "failed to nominate");
if (elected != null)
{
......
......@@ -8,10 +8,9 @@
namespace StackExchange.Redis.Tests
{
public class Naming
public class Naming : TestBase
{
public ITestOutputHelper Output;
public Naming(ITestOutputHelper output) => Output = output;
public Naming(ITestOutputHelper output) : base(output) { }
[Theory]
[InlineData(typeof(IDatabase), false)]
......@@ -50,21 +49,21 @@ public void ShowReadOnlyOperations()
if (!isMasterOnly)
{
Output.WriteLine(val?.ToString());
Log(val?.ToString());
}
}
Output.WriteLine("master-only: {0}, vs master/slave: {1}", masterOnly.Count, masterSlave.Count);
Output.WriteLine("");
Output.WriteLine("master-only:");
Log("master-only: {0}, vs master/slave: {1}", masterOnly.Count, masterSlave.Count);
Log("");
Log("master-only:");
foreach (var val in masterOnly)
{
Output.WriteLine(val?.ToString());
Log(val?.ToString());
}
Output.WriteLine("");
Output.WriteLine("master/slave:");
Log("");
Log("master/slave:");
foreach (var val in masterSlave)
{
Output.WriteLine(val?.ToString());
Log(val?.ToString());
}
}
......@@ -169,7 +168,7 @@ public void CheckSyncAsyncMethodsMatch(Type from, Type to)
}
var pFrom = method.GetParameters();
Type[] args = pFrom.Select(x => x.ParameterType).ToArray();
Output.WriteLine("Checking: {0}.{1}", from.Name, method.Name);
Log("Checking: {0}.{1}", from.Name, method.Name);
Assert.Equal(typeof(CommandFlags), args.Last());
var found = to.GetMethod(huntName, flags, null, method.CallingConvention, args, null);
Assert.NotNull(found); // "Found " + name + ", no " + huntName
......@@ -183,7 +182,7 @@ public void CheckSyncAsyncMethodsMatch(Type from, Type to)
count++;
}
Output.WriteLine("Validated: {0} ({1} methods)", from.Name, count);
Log("Validated: {0} ({1} methods)", from.Name, count);
}
private static readonly Type ignoreType = typeof(ConnectionMultiplexer).Assembly.GetType("StackExchange.Redis.IgnoreNamePrefixAttribute");
......
......@@ -18,7 +18,7 @@ public void Execute()
{
var sub = conn.GetSubscriber();
var received = new List<int>();
Output.WriteLine("Subscribing...");
Log("Subscribing...");
const int COUNT = 1000;
sub.Subscribe("foo", (channel, message) =>
{
......@@ -31,8 +31,8 @@ public void Execute()
Thread.Sleep(1); // you kinda need to be slow, otherwise
// the pool will end up doing everything on one thread
});
Output.WriteLine("");
Output.WriteLine("Sending (any order)...");
Log("");
Log("Sending (any order)...");
lock (received)
{
received.Clear();
......@@ -45,23 +45,23 @@ public void Execute()
sub.Publish("foo", i);
}
Output.WriteLine("Allowing time for delivery etc...");
Log("Allowing time for delivery etc...");
var watch = Stopwatch.StartNew();
if (!Monitor.Wait(received, 10000))
{
Output.WriteLine("Timed out; expect less data");
Log("Timed out; expect less data");
}
watch.Stop();
Output.WriteLine("Checking...");
Log("Checking...");
lock (received)
{
Output.WriteLine("Received: {0} in {1}ms", received.Count, watch.ElapsedMilliseconds);
Log("Received: {0} in {1}ms", received.Count, watch.ElapsedMilliseconds);
int wrongOrder = 0;
for (int i = 0; i < Math.Min(COUNT, received.Count); i++)
{
if (received[i] != i) wrongOrder++;
}
Output.WriteLine("Out of order: " + wrongOrder);
Log("Out of order: " + wrongOrder);
}
}
}
......
......@@ -69,7 +69,7 @@ public void TestBasicPubSub(string channelPrefix, bool wildCard, string breaker)
}
else
{
Output.WriteLine((string)channel);
Log((string)channel);
}
}
}
......
......@@ -11,21 +11,21 @@ public class RealWorld : TestBase
[Fact]
public void WhyDoesThisNotWork()
{
Output.WriteLine("first:");
Log("first:");
var config = ConfigurationOptions.Parse("localhost:6379,localhost:6380,name=Core (Q&A),tiebreaker=:RedisMaster,abortConnect=False");
Assert.Equal(2, config.EndPoints.Count);
Output.WriteLine("Endpoint 0: {0} (AddressFamily: {1})", config.EndPoints[0], config.EndPoints[0].AddressFamily);
Output.WriteLine("Endpoint 1: {0} (AddressFamily: {1})", config.EndPoints[1], config.EndPoints[1].AddressFamily);
Log("Endpoint 0: {0} (AddressFamily: {1})", config.EndPoints[0], config.EndPoints[0].AddressFamily);
Log("Endpoint 1: {0} (AddressFamily: {1})", config.EndPoints[1], config.EndPoints[1].AddressFamily);
using (var conn = ConnectionMultiplexer.Connect("localhost:6379,localhost:6380,name=Core (Q&A),tiebreaker=:RedisMaster,abortConnect=False", Writer))
{
Output.WriteLine("");
Output.WriteLine("pausing...");
Log("");
Log("pausing...");
Thread.Sleep(200);
Output.WriteLine("second:");
Log("second:");
bool result = conn.Configure(Writer);
Output.WriteLine("Returned: {0}", result);
Log("Returned: {0}", result);
}
}
}
......
......@@ -33,11 +33,11 @@ public void ConnectToAzure(int? port, bool ssl)
}
options.Ssl = ssl;
options.Password = TestConfig.Current.AzureCachePassword;
Output.WriteLine(options.ToString());
Log(options.ToString());
using (var connection = ConnectionMultiplexer.Connect(options))
{
var ttl = connection.GetDatabase().Ping();
Output.WriteLine(ttl.ToString());
Log(ttl.ToString());
}
}
......@@ -83,23 +83,23 @@ public async Task ConnectToSSLServer(bool useSsl, bool specifyHost)
}
config.CertificateValidation += (sender, cert, chain, errors) =>
{
Output.WriteLine("errors: " + errors);
Output.WriteLine("cert issued to: " + cert.Subject);
Log("errors: " + errors);
Log("cert issued to: " + cert.Subject);
return true; // fingers in ears, pretend we don't know this is wrong
};
}
var configString = config.ToString();
Output.WriteLine("config: " + configString);
Log("config: " + configString);
var clone = ConfigurationOptions.Parse(configString);
Assert.Equal(configString, clone.ToString());
using (var log = new StringWriter())
using (var muxer = ConnectionMultiplexer.Connect(config, log))
{
Output.WriteLine("Connect log:");
Output.WriteLine(log.ToString());
Output.WriteLine("====");
Log("Connect log:");
Log(log.ToString());
Log("====");
muxer.ConnectionFailed += OnConnectionFailed;
muxer.InternalError += OnInternalError;
var db = muxer.GetDatabase();
......@@ -122,7 +122,7 @@ public async Task ConnectToSSLServer(bool useSsl, bool specifyHost)
}
catch (Exception ex)
{
Output.WriteLine($"Failure on i={i}: {ex.Message}");
Log($"Failure on i={i}: {ex.Message}");
throw;
}
}
......@@ -130,7 +130,7 @@ public async Task ConnectToSSLServer(bool useSsl, bool specifyHost)
long value = (long)await db.StringGetAsync(key);
watch.Stop();
Assert.Equal(AsyncLoop, value);
Output.WriteLine("F&F: {0} INCR, {1:###,##0}ms, {2} ops/s; final value: {3}",
Log("F&F: {0} INCR, {1:###,##0}ms, {2} ops/s; final value: {3}",
AsyncLoop,
(long)watch.ElapsedMilliseconds,
(long)(AsyncLoop / watch.Elapsed.TotalSeconds),
......@@ -158,7 +158,7 @@ private void TestConcurrent(IDatabase db, RedisKey key, int SyncLoop, int Thread
}, Threads, timeout: 45000);
value = (long)db.StringGet(key);
Assert.Equal(SyncLoop * Threads, value);
Output.WriteLine("Sync: {0} INCR using {1} threads, {2:###,##0}ms, {3} ops/s; final value: {4}",
Log("Sync: {0} INCR using {1} threads, {2:###,##0}ms, {3} ops/s; final value: {4}",
SyncLoop * Threads, Threads,
(long)time.TotalMilliseconds,
(long)((SyncLoop * Threads) / time.TotalSeconds),
......@@ -203,7 +203,7 @@ public void RedisLabsSSL()
Assert.Equal("abc", s);
var latency = db.Ping();
Output.WriteLine("RedisLabs latency: {0:###,##0.##}ms", latency.TotalMilliseconds);
Log("RedisLabs latency: {0:###,##0.##}ms", latency.TotalMilliseconds);
using (var file = File.Create("RedisLabs.zip"))
{
......@@ -256,7 +256,7 @@ public void RedisLabsEnvironmentVariableClientCertificate(bool setEnv)
Assert.Equal("abc", s);
var latency = db.Ping();
Output.WriteLine("RedisLabs latency: {0:###,##0.##}ms", latency.TotalMilliseconds);
Log("RedisLabs latency: {0:###,##0.##}ms", latency.TotalMilliseconds);
using (var file = File.Create("RedisLabs.zip"))
{
......
......@@ -117,7 +117,7 @@ public void ScanResume()
snapCursor = ((IScanningCursor)seq).Cursor;
snapOffset = ((IScanningCursor)seq).PageOffset;
snapPageSize = ((IScanningCursor)seq).PageSize;
Output.WriteLine($"i: {i}, Cursor: {snapCursor}, Offset: {snapOffset}, PageSize: {snapPageSize}");
Log($"i: {i}, Cursor: {snapCursor}, Offset: {snapOffset}, PageSize: {snapPageSize}");
}
if (i >= 57)
{
......@@ -125,7 +125,7 @@ public void ScanResume()
}
i++;
}
Output.WriteLine($"Expected: 43, Actual: {expected.Count}, Cursor: {snapCursor}, Offset: {snapOffset}, PageSize: {snapPageSize}");
Log($"Expected: 43, Actual: {expected.Count}, Cursor: {snapCursor}, Offset: {snapOffset}, PageSize: {snapPageSize}");
Assert.Equal(43, expected.Count);
Assert.NotEqual(0, snapCursor);
Assert.Equal(15, snapPageSize);
......
......@@ -141,7 +141,7 @@ public void CompareScriptToDirect()
Assert.Equal(LOOP, (long)scriptResult);
Assert.Equal(LOOP, directResult);
Output.WriteLine("script: {0}ms; direct: {1}ms",
Log("script: {0}ms; direct: {1}ms",
scriptTime.TotalMilliseconds,
directTime.TotalMilliseconds);
}
......
......@@ -35,11 +35,11 @@ public void MassiveBulkOpsFireAndForgetSecure()
int val = (int)conn.StringGet(key);
Assert.Equal(AsyncOpsQty, val);
watch.Stop();
Output.WriteLine("{2}: Time for {0} ops: {1}ms (any order); ops/s: {3}", AsyncOpsQty, watch.ElapsedMilliseconds, Me(),
Log("{2}: Time for {0} ops: {1}ms (any order); ops/s: {3}", AsyncOpsQty, watch.ElapsedMilliseconds, Me(),
AsyncOpsQty / watch.Elapsed.TotalSeconds);
#if DEBUG
long newAlloc = ConnectionMultiplexer.GetResultBoxAllocationCount();
Output.WriteLine("ResultBox allocations: {0}", newAlloc - oldAlloc);
Log("ResultBox allocations: {0}", newAlloc - oldAlloc);
Assert.True(newAlloc - oldAlloc <= 2, $"NewAllocs: {newAlloc}, OldAllocs: {oldAlloc}");
#endif
}
......@@ -51,7 +51,7 @@ public void CheckConfig()
var config = ConfigurationOptions.Parse(GetConfiguration());
foreach (var ep in config.EndPoints)
{
Output.WriteLine(ep.ToString());
Log(ep.ToString());
}
Assert.Single(config.EndPoints);
Assert.Equal("changeme", config.Password);
......@@ -83,7 +83,7 @@ public async Task ConnectWithWrongPassword(string password)
conn.GetDatabase().Ping();
}
}).ConfigureAwait(false);
Output.WriteLine("Exception: " + ex.Message);
Log("Exception: " + ex.Message);
Assert.StartsWith("It was not possible to connect to the redis server(s). There was an authentication failure; check that passwords (or client certificates) are configured correctly.", ex.Message);
}
}
......
......@@ -7,19 +7,17 @@
namespace StackExchange.Redis.Tests
{
public class Sentinel
public class Sentinel : TestBase
{
private string ServiceName => TestConfig.Current.SentinelSeviceName;
private ConnectionMultiplexer Conn { get; }
private IServer Server { get; }
protected StringWriter Log { get; }
protected StringWriter ConnectionLog { get; }
public ITestOutputHelper Output { get; }
public Sentinel(ITestOutputHelper output)
public Sentinel(ITestOutputHelper output) : base(output)
{
Output = output;
Log = new StringWriter();
ConnectionLog = new StringWriter();
Skip.IfNoConfig(nameof(TestConfig.Config.SentinelServer), TestConfig.Current.SentinelServer);
Skip.IfNoConfig(nameof(TestConfig.Config.SentinelSeviceName), TestConfig.Current.SentinelSeviceName);
......@@ -33,7 +31,7 @@ public Sentinel(ITestOutputHelper output)
ServiceName = TestConfig.Current.SentinelSeviceName,
SyncTimeout = 5000
};
Conn = ConnectionMultiplexer.Connect(options, Log);
Conn = ConnectionMultiplexer.Connect(options, ConnectionLog);
Thread.Sleep(3000);
Assert.True(Conn.IsConnected);
Server = Conn.GetServer(TestConfig.Current.SentinelServer, TestConfig.Current.SentinelPort);
......@@ -43,7 +41,7 @@ public Sentinel(ITestOutputHelper output)
public void PingTest()
{
var test = Server.Ping();
Output.WriteLine("ping took {0} ms", test.TotalMilliseconds);
Log("ping took {0} ms", test.TotalMilliseconds);
}
[Fact]
......@@ -53,7 +51,7 @@ public void SentinelGetMasterAddressByNameTest()
Assert.NotNull(endpoint);
var ipEndPoint = endpoint as IPEndPoint;
Assert.NotNull(ipEndPoint);
Output.WriteLine("{0}:{1}", ipEndPoint.Address, ipEndPoint.Port);
Log("{0}:{1}", ipEndPoint.Address, ipEndPoint.Port);
}
[Fact]
......@@ -77,7 +75,7 @@ public void SentinelMasterTest()
Assert.Equal(ServiceName, dict["name"]);
foreach (var kvp in dict)
{
Output.WriteLine("{0}:{1}", kvp.Key, kvp.Value);
Log("{0}:{1}", kvp.Key, kvp.Value);
}
}
......@@ -90,7 +88,7 @@ public void SentinelMastersTest()
{
foreach (var kvp in config)
{
Output.WriteLine("{0}:{1}", kvp.Key, kvp.Value);
Log("{0}:{1}", kvp.Key, kvp.Value);
}
}
}
......@@ -106,7 +104,7 @@ public void SentinelSlavesTest()
foreach (var config in slaveConfigs)
{
foreach (var kvp in config) {
Output.WriteLine("{0}:{1}", kvp.Key, kvp.Value);
Log("{0}:{1}", kvp.Key, kvp.Value);
}
}
}
......
......@@ -15,7 +15,7 @@ namespace StackExchange.Redis.Tests
{
public abstract class TestBase : IDisposable
{
protected ITestOutputHelper Output { get; }
private ITestOutputHelper Output { get; }
protected TextWriterOutputHelper Writer { get; }
protected static bool RunningInCI { get; } = Environment.GetEnvironmentVariable("APPVEYOR") != null;
protected virtual string GetConfiguration() => TestConfig.Current.MasterServerAndPort + "," + TestConfig.Current.SlaveServerAndPort;
......@@ -24,10 +24,27 @@ protected TestBase(ITestOutputHelper output)
{
Output = output;
Output.WriteFrameworkVersion();
Writer = new TextWriterOutputHelper(output);
Writer = new TextWriterOutputHelper(output, TestConfig.Current.LogToConsole);
ClearAmbientFailures();
}
protected void Log(string message)
{
Output.WriteLine(message);
if (TestConfig.Current.LogToConsole)
{
Console.WriteLine(message);
}
}
protected void Log(string message, params object[] args)
{
Output.WriteLine(message, args);
if (TestConfig.Current.LogToConsole)
{
Console.WriteLine(message, args);
}
}
protected void CollectGarbage()
{
for (int i = 0; i < 3; i++)
......@@ -142,14 +159,14 @@ public void Teardown()
{
foreach (var item in privateExceptions.Take(5))
{
Output.WriteLine(item);
Log(item);
}
}
lock (backgroundExceptions)
{
foreach (var item in backgroundExceptions.Take(5))
{
Output.WriteLine(item);
Log(item);
}
}
Assert.True(false, $"There were {privateFailCount} private and {sharedFailCount.Value} ambient exceptions; expected {expectedFailCount}.");
......@@ -245,7 +262,7 @@ protected IServer GetAnyMaster(ConnectionMultiplexer muxer)
{
Assert.True(false, "Failure: Be sure to call the TestBase constuctor like this: BasicOpsTests(ITestOutputHelper output) : base(output) { }");
}
Output.WriteLine("Connect took: " + watch.ElapsedMilliseconds + "ms");
Log("Connect took: " + watch.ElapsedMilliseconds + "ms");
var muxer = task.Result;
if (checkConnect && (muxer == null || !muxer.IsConnected))
{
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment