public void Logger_BulkMessageLimit_VerboseNotFiltered()
{
const string testName = "Logger_BulkMessageLimit_InfoNotFiltered";
int n = 10000;
TraceLogger.BulkMessageInterval = TimeSpan.FromMilliseconds(5);
int logCode1 = 1;
int expectedLogMessages1 = n + 2;
int expectedBulkLogMessages1 = 0;
TestLogConsumer logConsumer = new TestLogConsumer(output);
TraceLogger.LogConsumers.Add(logConsumer);
TraceLogger logger1 = TraceLogger.GetLogger(testName);
// Write log messages to logger #1
for (int i = 0; i < n; i++)
{
logger1.Verbose(logCode1, "Verbose message " + (i + 1) + " to logger1");
}
// Wait until the BulkMessageInterval time interval expires before writing the final log message - should cause any pending message flush);
Thread.Sleep(TraceLogger.BulkMessageInterval);
Thread.Sleep(1);
logger1.Info(logCode1, "Penultimate message to logger1");
logger1.Info(logCode1, "Final message to logger1");
Assert.AreEqual(expectedBulkLogMessages1, logConsumer.GetEntryCount(logCode1 + TraceLogger.BulkMessageSummaryOffset),
"Should see {0} bulk message entries via logger#1", expectedBulkLogMessages1);
Assert.AreEqual(expectedLogMessages1, logConsumer.GetEntryCount(logCode1),
"Should see {0} real entries in total via logger#1", expectedLogMessages1);
}
public void Logger_MessageSizeLimit()
{
const string testName = "Logger_MessageSizeLimit";
TestLogConsumer logConsumer = new TestLogConsumer(output);
TraceLogger.LogConsumers.Add(logConsumer);
TraceLogger logger1 = TraceLogger.GetLogger(testName);
StringBuilder sb = new StringBuilder();
while (sb.Length <= TraceLogger.MAX_LOG_MESSAGE_SIZE)
{
sb.Append("1234567890");
}
string longString = sb.ToString();
Assert.IsTrue(longString.Length > TraceLogger.MAX_LOG_MESSAGE_SIZE);
int logCode1 = 1;
logger1.Info(logCode1, longString);
Assert.AreEqual(1, logConsumer.GetEntryCount(logCode1), "Should see original log message entry");
Assert.AreEqual(1, logConsumer.GetEntryCount((int)ErrorCode.Logger_LogMessageTruncated), "Should also see 'Message truncated' message");
}
public void Logger_Stats_MessageSizeLimit()
{
const string testName = "Logger_Stats_MessageSizeLimit";
TestLogConsumer logConsumer = new TestLogConsumer();
TraceLogger.LogConsumers.Add(logConsumer);
TraceLogger logger1 = TraceLogger.GetLogger(testName);
const string StatsCounterBaseName = "LoggerTest.Stats.Size";
for (int i = 1; i <= 1000; i++)
{
StatisticName counterName = new StatisticName(StatsCounterBaseName + "." + i);
CounterStatistic ctr = CounterStatistic.FindOrCreate(counterName);
ctr.IncrementBy(i);
}
LogStatistics statsLogger = new LogStatistics(TimeSpan.Zero, true);
statsLogger.DumpCounters().Wait();
int count = logConsumer.GetEntryCount((int)ErrorCode.PerfCounterDumpAll);
Console.WriteLine(count + " stats log message entries written");
Assert.IsTrue(count > 1, "Should be some stats log message entries - saw " + count);
Assert.AreEqual(0, logConsumer.GetEntryCount((int)ErrorCode.Logger_LogMessageTruncated), "Should not see any 'Message truncated' message");
}
public void Logger_BulkMessageLimit_DifferentLoggers()
{
int n = 10000;
TraceLogger.BulkMessageInterval = TimeSpan.FromMilliseconds(50);
int logCode1 = 1;
int logCode2 = 2;
int expectedLogMessages1 = TraceLogger.BulkMessageLimit + 2 + 1;
int expectedLogMessages2 = TraceLogger.BulkMessageLimit + 2;
int expectedBulkLogMessages1 = 0;
int expectedBulkLogMessages2 = 1;
TestLogConsumer logConsumer = new TestLogConsumer(output);
TraceLogger.LogConsumers.Add(logConsumer);
TraceLogger logger1 = TraceLogger.GetLogger("logger1");
TraceLogger logger2 = TraceLogger.GetLogger("logger2");
// Write log messages to logger #1
for (int i = 0; i < TraceLogger.BulkMessageLimit; i++)
{
logger1.Warn(logCode1, "Message " + (i + 1) + " to logger1");
}
// Write to logger#2 using same logCode -- This should NOT trigger the bulk message for logCode1
logger2.Warn(logCode1, "Use same logCode to logger2");
// Wait until the BulkMessageInterval time interval expires before writing the final log message - should cause any pending message flush);
Thread.Sleep(TraceLogger.BulkMessageInterval);
Thread.Sleep(1);
// Write log messages to logger #2
for (int i = 0; i < n; i++)
{
logger2.Warn(logCode2, "Message " + (i + 1) + " to logger2");
}
// Wait until the BulkMessageInterval time interval expires before writing the final log message - should cause any pending message flush);
Thread.Sleep(TraceLogger.BulkMessageInterval);
Thread.Sleep(1);
logger1.Info(logCode1, "Penultimate message to logger1");
logger2.Info(logCode2, "Penultimate message to logger2");
logger1.Info(logCode1, "Final message to logger1");
logger2.Info(logCode2, "Final message to logger2");
Assert.AreEqual(expectedBulkLogMessages1, logConsumer.GetEntryCount(logCode1 + TraceLogger.BulkMessageSummaryOffset),
"Should see {0} bulk message entries via logger#1", expectedBulkLogMessages1);
Assert.AreEqual(expectedBulkLogMessages2, logConsumer.GetEntryCount(logCode2 + TraceLogger.BulkMessageSummaryOffset),
"Should see {0} bulk message entries via logger#2", expectedBulkLogMessages2);
Assert.AreEqual(expectedLogMessages1, logConsumer.GetEntryCount(logCode1),
"Should see {0} real entries in total via logger#1", expectedLogMessages1);
Assert.AreEqual(expectedLogMessages2, logConsumer.GetEntryCount(logCode2),
"Should see {0} real entries in total via logger#2", expectedLogMessages2);
Assert.AreEqual(0, logConsumer.GetEntryCount(logCode1 - 1), "Should not see any other entries -1");
Assert.AreEqual(0, logConsumer.GetEntryCount(logCode2 + 1), "Should not see any other entries +1");
}
public void Logger_Perf_Logger_Dummy()
{
const string testName = "Logger_Perf_Logger_Dummy";
TimeSpan target = TimeSpan.FromMilliseconds(30);
int n = 10000;
int logCode = TestUtils.Random.Next(100000);
ILogConsumer logConsumer = new TestLogConsumer(output);
TraceLogger.LogConsumers.Add(logConsumer);
TraceLogger.BulkMessageInterval = target;
TraceLogger logger = TraceLogger.GetLogger(testName);
RunLoggerPerfTest(testName, n, logCode, target, logger);
}
private void RunTestForLogFiltering(string testName, int n, int finalLogCode, int mainLogCode, int expectedMainLogMessages, int expectedFinalLogMessages, int expectedBulkLogMessages)
{
Assert.IsTrue(finalLogCode != (mainLogCode - 1), "Test code constraint -1");
TestLogConsumer logConsumer = new TestLogConsumer(output);
TraceLogger.LogConsumers.Add(logConsumer);
TraceLogger logger = TraceLogger.GetLogger(testName);
var stopwatch = new Stopwatch();
stopwatch.Start();
for (int i = 0; i < n; i++)
{
logger.Warn(mainLogCode, "msg " + i);
}
// Wait until the BulkMessageInterval time interval expires before wring the final log message - should cause bulk message flush);
TimeSpan delay = TraceLogger.BulkMessageInterval - stopwatch.Elapsed;
if (delay > TimeSpan.Zero)
{
output.WriteLine("Sleeping for " + delay);
Thread.Sleep(delay);
}
Thread.Sleep(10);
logger.Info(finalLogCode, "Final msg");
Assert.AreEqual(expectedMainLogMessages, logConsumer.GetEntryCount(mainLogCode),
"Should see {0} real entries in total", expectedMainLogMessages);
if (mainLogCode != finalLogCode)
{
Assert.AreEqual(expectedFinalLogMessages, logConsumer.GetEntryCount(finalLogCode),
"Should see {0} final entry", expectedFinalLogMessages);
}
Assert.AreEqual(expectedBulkLogMessages, logConsumer.GetEntryCount(mainLogCode + TraceLogger.BulkMessageSummaryOffset),
"Should see {0} bulk message entries", expectedBulkLogMessages);
Assert.AreEqual(0, logConsumer.GetEntryCount(mainLogCode - 1), "Should not see any other entries -1");
}
public void Logger_Stats_MessageSizeLimit()
{
const string testName = "Logger_Stats_MessageSizeLimit";
TestLogConsumer logConsumer = new TestLogConsumer(output);
LogManager.LogConsumers.Add(logConsumer);
Logger logger1 = LogManager.GetLogger(testName);
const string StatsCounterBaseName = "LoggerTest.Stats.Size";
var createdCounters = new List <string>();
try
{
for (int i = 1; i <= 1000; i++)
{
string name = StatsCounterBaseName + "." + i;
StatisticName counterName = new StatisticName(name);
CounterStatistic ctr = CounterStatistic.FindOrCreate(counterName);
ctr.IncrementBy(i);
createdCounters.Add(name);
}
LogStatistics statsLogger = new LogStatistics(TimeSpan.Zero, true);
statsLogger.DumpCounters().Wait();
int count = logConsumer.GetEntryCount((int)ErrorCode.PerfCounterDumpAll);
output.WriteLine(count + " stats log message entries written");
Assert.True(count > 1, "Should be some stats log message entries - saw " + count);
Assert.Equal(0, logConsumer.GetEntryCount((int)ErrorCode.Logger_LogMessageTruncated)); // "Should not see any 'Message truncated' message"
}
finally
{
createdCounters.ForEach(name => CounterStatistic.Delete(name));
}
}
private static void RunTestForLogFiltering(string testName, int n, int finalLogCode, int mainLogCode, int expectedMainLogMessages, int expectedFinalLogMessages, int expectedBulkLogMessages)
{
Assert.IsTrue(finalLogCode != (mainLogCode - 1), "Test code constraint -1");
TestLogConsumer logConsumer = new TestLogConsumer();
TraceLogger.LogConsumers.Add(logConsumer);
TraceLogger logger = TraceLogger.GetLogger(testName);
var stopwatch = new Stopwatch();
stopwatch.Start();
for (int i = 0; i < n; i++)
{
logger.Warn(mainLogCode, "msg " + i);
}
// Wait until the BulkMessageInterval time interval expires before wring the final log message - should cause bulk message flush);
TimeSpan delay = TraceLogger.BulkMessageInterval - stopwatch.Elapsed;
if (delay > TimeSpan.Zero)
{
Console.WriteLine("Sleeping for " + delay);
Thread.Sleep(delay);
}
Thread.Sleep(10);
logger.Info(finalLogCode, "Final msg");
Assert.AreEqual(expectedMainLogMessages, logConsumer.GetEntryCount(mainLogCode),
"Should see {0} real entries in total", expectedMainLogMessages);
if (mainLogCode != finalLogCode)
{
Assert.AreEqual(expectedFinalLogMessages, logConsumer.GetEntryCount(finalLogCode),
"Should see {0} final entry", expectedFinalLogMessages);
}
Assert.AreEqual(expectedBulkLogMessages, logConsumer.GetEntryCount(mainLogCode + TraceLogger.BulkMessageSummaryOffset),
"Should see {0} bulk message entries", expectedBulkLogMessages);
Assert.AreEqual(0, logConsumer.GetEntryCount(mainLogCode - 1), "Should not see any other entries -1");
}
public void Logger_Perf_Logger_Dummy()
{
const string testName = "Logger_Perf_Logger_Dummy";
TimeSpan target = TimeSpan.FromMilliseconds(30);
int n = 10000;
int logCode = random.Next(100000);
ILogConsumer logConsumer = new TestLogConsumer();
TraceLogger.LogConsumers.Add(logConsumer);
TraceLogger.BulkMessageInterval = target;
TraceLogger logger = TraceLogger.GetLogger(testName);
RunLoggerPerfTest(testName, n, logCode, target, logger);
}
public void Logger_Stats_MessageSizeLimit()
{
const string testName = "Logger_Stats_MessageSizeLimit";
TestLogConsumer logConsumer = new TestLogConsumer();
TraceLogger.LogConsumers.Add(logConsumer);
TraceLogger logger1 = TraceLogger.GetLogger(testName);
const string StatsCounterBaseName = "LoggerTest.Stats.Size";
for (int i = 1; i <= 1000; i++)
{
StatisticName counterName = new StatisticName(StatsCounterBaseName + "." + i);
CounterStatistic ctr = CounterStatistic.FindOrCreate(counterName);
ctr.IncrementBy(i);
}
LogStatistics statsLogger = new LogStatistics(TimeSpan.Zero, true);
statsLogger.DumpCounters().Wait();
int count = logConsumer.GetEntryCount((int)ErrorCode.PerfCounterDumpAll);
Console.WriteLine(count + " stats log message entries written");
Assert.IsTrue(count > 1, "Should be some stats log message entries - saw " + count);
Assert.AreEqual(0, logConsumer.GetEntryCount((int)ErrorCode.Logger_LogMessageTruncated), "Should not see any 'Message truncated' message");
}
public void Logger_MessageSizeLimit()
{
const string testName = "Logger_MessageSizeLimit";
TestLogConsumer logConsumer = new TestLogConsumer();
TraceLogger.LogConsumers.Add(logConsumer);
TraceLogger logger1 = TraceLogger.GetLogger(testName);
StringBuilder sb = new StringBuilder();
while (sb.Length <= TraceLogger.MAX_LOG_MESSAGE_SIZE)
{
sb.Append("1234567890");
}
string longString = sb.ToString();
Assert.IsTrue(longString.Length > TraceLogger.MAX_LOG_MESSAGE_SIZE);
int logCode1 = 1;
logger1.Info(logCode1, longString);
Assert.AreEqual(1, logConsumer.GetEntryCount(logCode1), "Should see original log message entry");
Assert.AreEqual(1, logConsumer.GetEntryCount((int)ErrorCode.Logger_LogMessageTruncated), "Should also see 'Message truncated' message");
}
public void Logger_BulkMessageLimit_VerboseNotFiltered()
{
const string testName = "Logger_BulkMessageLimit_InfoNotFiltered";
int n = 10000;
TraceLogger.BulkMessageInterval = TimeSpan.FromMilliseconds(5);
int logCode1 = 1;
int expectedLogMessages1 = n + 2;
int expectedBulkLogMessages1 = 0;
TestLogConsumer logConsumer = new TestLogConsumer();
TraceLogger.LogConsumers.Add(logConsumer);
TraceLogger logger1 = TraceLogger.GetLogger(testName);
// Write log messages to logger #1
for (int i = 0; i < n; i++)
{
logger1.Verbose(logCode1, "Verbose message " + (i + 1) + " to logger1");
}
// Wait until the BulkMessageInterval time interval expires before writing the final log message - should cause any pending message flush);
Thread.Sleep(TraceLogger.BulkMessageInterval);
Thread.Sleep(1);
logger1.Info(logCode1, "Penultimate message to logger1");
logger1.Info(logCode1, "Final message to logger1");
Assert.AreEqual(expectedBulkLogMessages1, logConsumer.GetEntryCount(logCode1 + TraceLogger.BulkMessageSummaryOffset),
"Should see {0} bulk message entries via logger#1", expectedBulkLogMessages1);
Assert.AreEqual(expectedLogMessages1, logConsumer.GetEntryCount(logCode1),
"Should see {0} real entries in total via logger#1", expectedLogMessages1);
}
public void Logger_BulkMessageLimit_DifferentLoggers()
{
int n = 10000;
TraceLogger.BulkMessageInterval = TimeSpan.FromMilliseconds(50);
int logCode1 = 1;
int logCode2 = 2;
int expectedLogMessages1 = TraceLogger.BulkMessageLimit + 2 + 1;
int expectedLogMessages2 = TraceLogger.BulkMessageLimit + 2;
int expectedBulkLogMessages1 = 0;
int expectedBulkLogMessages2 = 1;
TestLogConsumer logConsumer = new TestLogConsumer();
TraceLogger.LogConsumers.Add(logConsumer);
TraceLogger logger1 = TraceLogger.GetLogger("logger1");
TraceLogger logger2 = TraceLogger.GetLogger("logger2");
// Write log messages to logger #1
for (int i = 0; i < TraceLogger.BulkMessageLimit; i++)
{
logger1.Warn(logCode1, "Message " + (i + 1) + " to logger1");
}
// Write to logger#2 using same logCode -- This should NOT trigger the bulk message for logCode1
logger2.Warn(logCode1, "Use same logCode to logger2");
// Wait until the BulkMessageInterval time interval expires before writing the final log message - should cause any pending message flush);
Thread.Sleep(TraceLogger.BulkMessageInterval);
Thread.Sleep(1);
// Write log messages to logger #2
for (int i = 0; i < n; i++)
{
logger2.Warn(logCode2, "Message " + (i+1) + " to logger2" );
}
// Wait until the BulkMessageInterval time interval expires before writing the final log message - should cause any pending message flush);
Thread.Sleep(TraceLogger.BulkMessageInterval);
Thread.Sleep(1);
logger1.Info(logCode1, "Penultimate message to logger1");
logger2.Info(logCode2, "Penultimate message to logger2");
logger1.Info(logCode1, "Final message to logger1");
logger2.Info(logCode2, "Final message to logger2");
Assert.AreEqual(expectedBulkLogMessages1, logConsumer.GetEntryCount(logCode1 + TraceLogger.BulkMessageSummaryOffset),
"Should see {0} bulk message entries via logger#1", expectedBulkLogMessages1);
Assert.AreEqual(expectedBulkLogMessages2, logConsumer.GetEntryCount(logCode2 + TraceLogger.BulkMessageSummaryOffset),
"Should see {0} bulk message entries via logger#2", expectedBulkLogMessages2);
Assert.AreEqual(expectedLogMessages1, logConsumer.GetEntryCount(logCode1),
"Should see {0} real entries in total via logger#1", expectedLogMessages1);
Assert.AreEqual(expectedLogMessages2, logConsumer.GetEntryCount(logCode2),
"Should see {0} real entries in total via logger#2", expectedLogMessages2);
Assert.AreEqual(0, logConsumer.GetEntryCount(logCode1 - 1), "Should not see any other entries -1");
Assert.AreEqual(0, logConsumer.GetEntryCount(logCode2 + 1), "Should not see any other entries +1");
}