Add smarter logging to tests

shana · shana · commit ae352efb7cbb · 2018-02-06T13:16:44.000+01:00
diff --git a/src/tests/IntegrationTests/Events/RepositoryManagerTests.cs b/src/tests/IntegrationTests/Events/RepositoryManagerTests.cs
@@ -1,13 +1,16 @@
 ﻿using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Linq;
+using System.Runtime.CompilerServices;
 using FluentAssertions;
 using GitHub.Unity;
 using NSubstitute;
 using NUnit.Framework;
 using TestUtils;
 using TestUtils.Events;
 using System.Threading.Tasks;
+using GitHub.Logging;
 
 namespace IntegrationTests
 {
@@ -23,10 +26,38 @@ public override void OnSetup()
             repositoryManagerEvents = new RepositoryManagerEvents();
         }
 
+        private void StartTest(out Stopwatch watch, out ILogging logger, [CallerMemberName] string testName = "test")
+        {
+            watch = new Stopwatch();
+            logger = LogHelper.GetLogger(testName);
+            logger.Trace("Starting test");
+        }
+
+        private void EndTest(ILogging logger)
+        {
+            logger.Trace("Ending test");
+        }
+
+        private void StartTrackTime(Stopwatch watch, ILogging logger, string message = "")
+        {
+            if (!String.IsNullOrEmpty(message))
+                logger.Trace(message);
+            watch.Reset();
+            watch.Start();
+        }
+
+        private void StopTrackTimeAndLog(Stopwatch watch, ILogging logger)
+        {
+            watch.Stop();
+            logger.Trace($"Time: {watch.ElapsedMilliseconds}");
+        }
+
         [Test]
         public void ShouldPerformBasicInitialize()
         {
-            Logger.Trace("Starting ShouldPerformBasicInitialize");
+            Stopwatch watch = null;
+            ILogging logger = null;
+            StartTest(out watch, out logger);
 
             try
             {
@@ -56,14 +87,16 @@ public void ShouldPerformBasicInitialize()
             }
             finally
             {
-                Logger.Trace("Ending ShouldPerformBasicInitialize");
+                EndTest(logger);
             }
         }
 
         [Test]
         public async Task ShouldDetectFileChanges()
         {
-            Logger.Trace("Starting ShouldDetectFileChanges");
+            Stopwatch watch = null;
+            ILogging logger = null;
+            StartTest(out watch, out logger);
 
             try
             {
@@ -90,8 +123,13 @@ public async Task ShouldDetectFileChanges()
 
                 await TaskManager.Wait();
 
+                StartTrackTime(watch, logger, "RepositoryManager.WaitForEvents()");
                 RepositoryManager.WaitForEvents();
+                StopTrackTimeAndLog(watch, logger);
+
+                StartTrackTime(watch, logger, "repositoryManagerEvents.WaitForNotBusy()");
                 repositoryManagerEvents.WaitForNotBusy();
+                StopTrackTimeAndLog(watch, logger);
 
                 repositoryManagerEvents.GitStatusUpdated.WaitOne(Timeout).Should().BeTrue();
 
@@ -106,14 +144,16 @@ public async Task ShouldDetectFileChanges()
             }
             finally
             {
-                Logger.Trace("Ending ShouldDetectFileChanges");
+                EndTest(logger);
             }
         }
 
         [Test]
         public async Task ShouldAddAndCommitFiles()
         {
-            Logger.Trace("Starting ShouldAddAndCommitFiles");
+            Stopwatch watch = null;
+            ILogging logger = null;
+            StartTest(out watch, out logger);
 
             try
             {
@@ -184,14 +224,16 @@ await RepositoryManager
             }
             finally
             {
-                Logger.Trace("Ending ShouldAddAndCommitFiles");
+                EndTest(logger);
             }
         }
 
         [Test]
         public async Task ShouldAddAndCommitAllFiles()
         {
-            Logger.Trace("Starting ShouldAddAndCommitAllFiles");
+            Stopwatch watch = null;
+            ILogging logger = null;
+            StartTest(out watch, out logger);
 
             try
             {
@@ -221,8 +263,13 @@ public async Task ShouldAddAndCommitAllFiles()
 
                 await TaskManager.Wait();
 
+                StartTrackTime(watch, logger, "RepositoryManager.WaitForEvents()");
                 RepositoryManager.WaitForEvents();
+                StopTrackTimeAndLog(watch, logger);
+
+                StartTrackTime(watch, logger, "repositoryManagerEvents.WaitForNotBusy()");
                 repositoryManagerEvents.WaitForNotBusy();
+                StopTrackTimeAndLog(watch, logger);
 
                 repositoryManagerEvents.GitStatusUpdated.WaitOne(Timeout).Should().BeTrue();
 
@@ -238,13 +285,21 @@ public async Task ShouldAddAndCommitAllFiles()
                 repositoryManagerListener.ClearReceivedCalls();
                 repositoryManagerEvents.Reset();
 
+                StartTrackTime(watch, logger, "CommitAllFiles");
                 await RepositoryManager
                     .CommitAllFiles("IntegrationTest Commit", string.Empty)
                     .StartAsAsync();
+
+                StopTrackTimeAndLog(watch, logger);
                 await TaskManager.Wait();
 
+                StartTrackTime(watch, logger, "RepositoryManager.WaitForEvents()");
                 RepositoryManager.WaitForEvents();
+                StopTrackTimeAndLog(watch, logger);
+
+                StartTrackTime(watch, logger, "repositoryManagerEvents.WaitForNotBusy()");
                 repositoryManagerEvents.WaitForNotBusy();
+                StopTrackTimeAndLog(watch, logger);
 
                 repositoryManagerEvents.GitStatusUpdated.WaitOne(Timeout).Should().BeTrue();
                 repositoryManagerEvents.GitStatusUpdated.WaitOne(Timeout).Should().BeTrue();
@@ -262,14 +317,16 @@ await RepositoryManager
             }
             finally
             {
-                Logger.Trace("Ending ShouldAddAndCommitAllFiles");
+                EndTest(logger);
             }
         }
 
         [Test]
         public async Task ShouldDetectBranchChange()
         {
-            Logger.Trace("Starting ShouldDetectBranchChange");
+            Stopwatch watch = null;
+            ILogging logger = null;
+            StartTest(out watch, out logger);
 
             try
             {
@@ -312,14 +369,16 @@ public async Task ShouldDetectBranchChange()
             }
             finally
             {
-                Logger.Trace("Ending ShouldDetectBranchChange");
+                EndTest(logger);
             }
         }
 
         [Test]
         public async Task ShouldDetectBranchDelete()
         {
-            Logger.Trace("Starting ShouldDetectBranchDelete");
+            Stopwatch watch = null;
+            ILogging logger = null;
+            StartTest(out watch, out logger);
 
             try
             {
@@ -364,14 +423,16 @@ public async Task ShouldDetectBranchDelete()
             }
             finally
             {
-                Logger.Trace("Ending ShouldDetectBranchDelete");
+                EndTest(logger);
             }
         }
 
         [Test]
         public async Task ShouldDetectBranchCreate()
         {
-            Logger.Trace("Starting ShouldDetectBranchCreate");
+            Stopwatch watch = null;
+            ILogging logger = null;
+            StartTest(out watch, out logger);
 
             try
             {
@@ -433,14 +494,16 @@ public async Task ShouldDetectBranchCreate()
             }
             finally
             {
-                Logger.Trace("Ending ShouldDetectBranchCreate");
+                EndTest(logger);
             }
         }
 
         [Test]
         public async Task ShouldDetectChangesToRemotes()
         {
-            Logger.Trace("Starting ShouldDetectChangesToRemotes");
+            Stopwatch watch = null;
+            ILogging logger = null;
+            StartTest(out watch, out logger);
 
             try
             {
@@ -509,14 +572,16 @@ public async Task ShouldDetectChangesToRemotes()
             }
             finally
             {
-                Logger.Trace("Ending ShouldDetectChangesToRemotes");
+                EndTest(logger);
             }
         }
 
         [Test]
         public async Task ShouldDetectChangesToRemotesWhenSwitchingBranches()
         {
-            Logger.Trace("Starting ShouldDetectChangesToRemotesWhenSwitchingBranches");
+            Stopwatch watch = null;
+            ILogging logger = null;
+            StartTest(out watch, out logger);
 
             try
             {
@@ -585,14 +650,16 @@ await RepositoryManager.SwitchBranch("branch2")
             }
             finally
             {
-                Logger.Trace("Ending ShouldDetectChangesToRemotesWhenSwitchingBranches");
+                EndTest(logger);
             }
         }
 
         [Test]
         public async Task ShouldDetectGitPull()
         {
-            Logger.Trace("Starting ShouldDetectGitPull");
+            Stopwatch watch = null;
+            ILogging logger = null;
+            StartTest(out watch, out logger);
 
             try
             {
@@ -634,14 +701,16 @@ public async Task ShouldDetectGitPull()
             }
             finally
             {
-                Logger.Trace("Ending ShouldDetectGitPull");
+                EndTest(logger);
             }
         }
 
         [Test]
         public async Task ShouldDetectGitFetch()
         {
-            Logger.Trace("Starting ShouldDetectGitFetch");
+            Stopwatch watch = null;
+            ILogging logger = null;
+            StartTest(out watch, out logger);
 
             try
             {
@@ -684,7 +753,7 @@ public async Task ShouldDetectGitFetch()
             }
             finally
             {
-                Logger.Trace("Ending ShouldDetectGitFetch");
+                EndTest(logger);
             }
         }
     }

Original file line number	Diff line number	Diff line change
`@@ -1,13 +1,16 @@`
`1`	`1`	`using System;`
`2`	`2`	`using System.Collections.Generic;`
	`3`	`+using System.Diagnostics;`
`3`	`4`	`using System.Linq;`
	`5`	`+using System.Runtime.CompilerServices;`
`4`	`6`	`using FluentAssertions;`
`5`	`7`	`using GitHub.Unity;`
`6`	`8`	`using NSubstitute;`
`7`	`9`	`using NUnit.Framework;`
`8`	`10`	`using TestUtils;`
`9`	`11`	`using TestUtils.Events;`
`10`	`12`	`using System.Threading.Tasks;`
	`13`	`+using GitHub.Logging;`
`11`	`14`
`12`	`15`	`namespace IntegrationTests`
`13`	`16`	`{`
`@@ -23,10 +26,38 @@ public override void OnSetup()`
`23`	`26`	`repositoryManagerEvents = new RepositoryManagerEvents();`
`24`	`27`	`}`
`25`	`28`
	`29`	`+ private void StartTest(out Stopwatch watch, out ILogging logger, [CallerMemberName] string testName = "test")`
	`30`	`+ {`
	`31`	`+ watch = new Stopwatch();`
	`32`	`+ logger = LogHelper.GetLogger(testName);`
	`33`	`+ logger.Trace("Starting test");`
	`34`	`+ }`
	`35`	`+`
	`36`	`+ private void EndTest(ILogging logger)`
	`37`	`+ {`
	`38`	`+ logger.Trace("Ending test");`
	`39`	`+ }`
	`40`	`+`
	`41`	`+ private void StartTrackTime(Stopwatch watch, ILogging logger, string message = "")`
	`42`	`+ {`
	`43`	`+ if (!String.IsNullOrEmpty(message))`
	`44`	`+ logger.Trace(message);`
	`45`	`+ watch.Reset();`
	`46`	`+ watch.Start();`
	`47`	`+ }`
	`48`	`+`
	`49`	`+ private void StopTrackTimeAndLog(Stopwatch watch, ILogging logger)`
	`50`	`+ {`
	`51`	`+ watch.Stop();`
	`52`	`+ logger.Trace($"Time: {watch.ElapsedMilliseconds}");`
	`53`	`+ }`
	`54`	`+`
`26`	`55`	`[Test]`
`27`	`56`	`public void ShouldPerformBasicInitialize()`
`28`	`57`	`{`
`29`		`- Logger.Trace("Starting ShouldPerformBasicInitialize");`
	`58`	`+ Stopwatch watch = null;`
	`59`	`+ ILogging logger = null;`
	`60`	`+ StartTest(out watch, out logger);`
`30`	`61`
`31`	`62`	`try`
`32`	`63`	`{`
`@@ -56,14 +87,16 @@ public void ShouldPerformBasicInitialize()`
`56`	`87`	`}`
`57`	`88`	`finally`
`58`	`89`	`{`
`59`		`- Logger.Trace("Ending ShouldPerformBasicInitialize");`
	`90`	`+ EndTest(logger);`
`60`	`91`	`}`
`61`	`92`	`}`
`62`	`93`
`63`	`94`	`[Test]`
`64`	`95`	`public async Task ShouldDetectFileChanges()`
`65`	`96`	`{`
`66`		`- Logger.Trace("Starting ShouldDetectFileChanges");`
	`97`	`+ Stopwatch watch = null;`
	`98`	`+ ILogging logger = null;`
	`99`	`+ StartTest(out watch, out logger);`
`67`	`100`
`68`	`101`	`try`
`69`	`102`	`{`
`@@ -90,8 +123,13 @@ public async Task ShouldDetectFileChanges()`
`90`	`123`
`91`	`124`	`await TaskManager.Wait();`
`92`	`125`
	`126`	`+ StartTrackTime(watch, logger, "RepositoryManager.WaitForEvents()");`
`93`	`127`	`RepositoryManager.WaitForEvents();`
	`128`	`+ StopTrackTimeAndLog(watch, logger);`
	`129`	`+`
	`130`	`+ StartTrackTime(watch, logger, "repositoryManagerEvents.WaitForNotBusy()");`
`94`	`131`	`repositoryManagerEvents.WaitForNotBusy();`
	`132`	`+ StopTrackTimeAndLog(watch, logger);`
`95`	`133`
`96`	`134`	`repositoryManagerEvents.GitStatusUpdated.WaitOne(Timeout).Should().BeTrue();`
`97`	`135`
`@@ -106,14 +144,16 @@ public async Task ShouldDetectFileChanges()`
`106`	`144`	`}`
`107`	`145`	`finally`
`108`	`146`	`{`
`109`		`- Logger.Trace("Ending ShouldDetectFileChanges");`
	`147`	`+ EndTest(logger);`
`110`	`148`	`}`
`111`	`149`	`}`
`112`	`150`
`113`	`151`	`[Test]`
`114`	`152`	`public async Task ShouldAddAndCommitFiles()`
`115`	`153`	`{`
`116`		`- Logger.Trace("Starting ShouldAddAndCommitFiles");`
	`154`	`+ Stopwatch watch = null;`
	`155`	`+ ILogging logger = null;`
	`156`	`+ StartTest(out watch, out logger);`
`117`	`157`
`118`	`158`	`try`
`119`	`159`	`{`
`@@ -184,14 +224,16 @@ await RepositoryManager`
`184`	`224`	`}`
`185`	`225`	`finally`
`186`	`226`	`{`
`187`		`- Logger.Trace("Ending ShouldAddAndCommitFiles");`
	`227`	`+ EndTest(logger);`
`188`	`228`	`}`
`189`	`229`	`}`
`190`	`230`
`191`	`231`	`[Test]`
`192`	`232`	`public async Task ShouldAddAndCommitAllFiles()`
`193`	`233`	`{`
`194`		`- Logger.Trace("Starting ShouldAddAndCommitAllFiles");`
	`234`	`+ Stopwatch watch = null;`
	`235`	`+ ILogging logger = null;`
	`236`	`+ StartTest(out watch, out logger);`
`195`	`237`
`196`	`238`	`try`
`197`	`239`	`{`
`@@ -221,8 +263,13 @@ public async Task ShouldAddAndCommitAllFiles()`
`221`	`263`
`222`	`264`	`await TaskManager.Wait();`
`223`	`265`
	`266`	`+ StartTrackTime(watch, logger, "RepositoryManager.WaitForEvents()");`
`224`	`267`	`RepositoryManager.WaitForEvents();`
	`268`	`+ StopTrackTimeAndLog(watch, logger);`
	`269`	`+`
	`270`	`+ StartTrackTime(watch, logger, "repositoryManagerEvents.WaitForNotBusy()");`
`225`	`271`	`repositoryManagerEvents.WaitForNotBusy();`
	`272`	`+ StopTrackTimeAndLog(watch, logger);`
`226`	`273`
`227`	`274`	`repositoryManagerEvents.GitStatusUpdated.WaitOne(Timeout).Should().BeTrue();`
`228`	`275`
`@@ -238,13 +285,21 @@ public async Task ShouldAddAndCommitAllFiles()`
`238`	`285`	`repositoryManagerListener.ClearReceivedCalls();`
`239`	`286`	`repositoryManagerEvents.Reset();`
`240`	`287`
	`288`	`+ StartTrackTime(watch, logger, "CommitAllFiles");`
`241`	`289`	`await RepositoryManager`
`242`	`290`	`.CommitAllFiles("IntegrationTest Commit", string.Empty)`
`243`	`291`	`.StartAsAsync();`
	`292`	`+`
	`293`	`+ StopTrackTimeAndLog(watch, logger);`
`244`	`294`	`await TaskManager.Wait();`
`245`	`295`
	`296`	`+ StartTrackTime(watch, logger, "RepositoryManager.WaitForEvents()");`
`246`	`297`	`RepositoryManager.WaitForEvents();`
	`298`	`+ StopTrackTimeAndLog(watch, logger);`
	`299`	`+`
	`300`	`+ StartTrackTime(watch, logger, "repositoryManagerEvents.WaitForNotBusy()");`
`247`	`301`	`repositoryManagerEvents.WaitForNotBusy();`
	`302`	`+ StopTrackTimeAndLog(watch, logger);`
`248`	`303`
`249`	`304`	`repositoryManagerEvents.GitStatusUpdated.WaitOne(Timeout).Should().BeTrue();`
`250`	`305`	`repositoryManagerEvents.GitStatusUpdated.WaitOne(Timeout).Should().BeTrue();`
`@@ -262,14 +317,16 @@ await RepositoryManager`
`262`	`317`	`}`
`263`	`318`	`finally`
`264`	`319`	`{`
`265`		`- Logger.Trace("Ending ShouldAddAndCommitAllFiles");`
	`320`	`+ EndTest(logger);`
`266`	`321`	`}`
`267`	`322`	`}`
`268`	`323`
`269`	`324`	`[Test]`
`270`	`325`	`public async Task ShouldDetectBranchChange()`
`271`	`326`	`{`
`272`		`- Logger.Trace("Starting ShouldDetectBranchChange");`
	`327`	`+ Stopwatch watch = null;`
	`328`	`+ ILogging logger = null;`
	`329`	`+ StartTest(out watch, out logger);`
`273`	`330`
`274`	`331`	`try`
`275`	`332`	`{`
`@@ -312,14 +369,16 @@ public async Task ShouldDetectBranchChange()`
`312`	`369`	`}`
`313`	`370`	`finally`
`314`	`371`	`{`
`315`		`- Logger.Trace("Ending ShouldDetectBranchChange");`
	`372`	`+ EndTest(logger);`
`316`	`373`	`}`
`317`	`374`	`}`
`318`	`375`
`319`	`376`	`[Test]`
`320`	`377`	`public async Task ShouldDetectBranchDelete()`
`321`	`378`	`{`
`322`		`- Logger.Trace("Starting ShouldDetectBranchDelete");`
	`379`	`+ Stopwatch watch = null;`
	`380`	`+ ILogging logger = null;`
	`381`	`+ StartTest(out watch, out logger);`
`323`	`382`
`324`	`383`	`try`
`325`	`384`	`{`
`@@ -364,14 +423,16 @@ public async Task ShouldDetectBranchDelete()`
`364`	`423`	`}`
`365`	`424`	`finally`
`366`	`425`	`{`
`367`		`- Logger.Trace("Ending ShouldDetectBranchDelete");`
	`426`	`+ EndTest(logger);`
`368`	`427`	`}`
`369`	`428`	`}`
`370`	`429`
`371`	`430`	`[Test]`
`372`	`431`	`public async Task ShouldDetectBranchCreate()`
`373`	`432`	`{`
`374`		`- Logger.Trace("Starting ShouldDetectBranchCreate");`
	`433`	`+ Stopwatch watch = null;`
	`434`	`+ ILogging logger = null;`
	`435`	`+ StartTest(out watch, out logger);`
`375`	`436`
`376`	`437`	`try`
`377`	`438`	`{`
`@@ -433,14 +494,16 @@ public async Task ShouldDetectBranchCreate()`
`433`	`494`	`}`
`434`	`495`	`finally`
`435`	`496`	`{`
`436`		`- Logger.Trace("Ending ShouldDetectBranchCreate");`
	`497`	`+ EndTest(logger);`
`437`	`498`	`}`
`438`	`499`	`}`
`439`	`500`
`440`	`501`	`[Test]`
`441`	`502`	`public async Task ShouldDetectChangesToRemotes()`
`442`	`503`	`{`
`443`		`- Logger.Trace("Starting ShouldDetectChangesToRemotes");`
	`504`	`+ Stopwatch watch = null;`
	`505`	`+ ILogging logger = null;`
	`506`	`+ StartTest(out watch, out logger);`
`444`	`507`
`445`	`508`	`try`
`446`	`509`	`{`
`@@ -509,14 +572,16 @@ public async Task ShouldDetectChangesToRemotes()`
`509`	`572`	`}`
`510`	`573`	`finally`
`511`	`574`	`{`
`512`		`- Logger.Trace("Ending ShouldDetectChangesToRemotes");`
	`575`	`+ EndTest(logger);`
`513`	`576`	`}`
`514`	`577`	`}`
`515`	`578`
`516`	`579`	`[Test]`
`517`	`580`	`public async Task ShouldDetectChangesToRemotesWhenSwitchingBranches()`
`518`	`581`	`{`
`519`		`- Logger.Trace("Starting ShouldDetectChangesToRemotesWhenSwitchingBranches");`
	`582`	`+ Stopwatch watch = null;`
	`583`	`+ ILogging logger = null;`
	`584`	`+ StartTest(out watch, out logger);`
`520`	`585`
`521`	`586`	`try`
`522`	`587`	`{`
`@@ -585,14 +650,16 @@ await RepositoryManager.SwitchBranch("branch2")`
`585`	`650`	`}`
`586`	`651`	`finally`
`587`	`652`	`{`
`588`		`- Logger.Trace("Ending ShouldDetectChangesToRemotesWhenSwitchingBranches");`
	`653`	`+ EndTest(logger);`
`589`	`654`	`}`
`590`	`655`	`}`
`591`	`656`
`592`	`657`	`[Test]`
`593`	`658`	`public async Task ShouldDetectGitPull()`
`594`	`659`	`{`
`595`		`- Logger.Trace("Starting ShouldDetectGitPull");`
	`660`	`+ Stopwatch watch = null;`
	`661`	`+ ILogging logger = null;`
	`662`	`+ StartTest(out watch, out logger);`
`596`	`663`
`597`	`664`	`try`
`598`	`665`	`{`
`@@ -634,14 +701,16 @@ public async Task ShouldDetectGitPull()`
`634`	`701`	`}`
`635`	`702`	`finally`
`636`	`703`	`{`
`637`		`- Logger.Trace("Ending ShouldDetectGitPull");`
	`704`	`+ EndTest(logger);`
`638`	`705`	`}`
`639`	`706`	`}`
`640`	`707`
`641`	`708`	`[Test]`
`642`	`709`	`public async Task ShouldDetectGitFetch()`
`643`	`710`	`{`
`644`		`- Logger.Trace("Starting ShouldDetectGitFetch");`
	`711`	`+ Stopwatch watch = null;`
	`712`	`+ ILogging logger = null;`
	`713`	`+ StartTest(out watch, out logger);`
`645`	`714`
`646`	`715`	`try`
`647`	`716`	`{`
`@@ -684,7 +753,7 @@ public async Task ShouldDetectGitFetch()`
`684`	`753`	`}`
`685`	`754`	`finally`
`686`	`755`	`{`
`687`		`- Logger.Trace("Ending ShouldDetectGitFetch");`
	`756`	`+ EndTest(logger);`
`688`	`757`	`}`
`689`	`758`	`}`
`690`	`759`	`}`