Moving some logging into the helpers

test/DeploymentHelpers/Common/DeploymentParameters.cs

@@ -85,5 +85,17 @@ namespace DeploymentHelpers
         /// For any application level cleanup to be invoked after performing host cleanup.
         /// </summary>
         public Action<DeploymentParameters> UserAdditionalCleanup { get; set; }
+
+        public override string ToString()
+        {
+            return string.Format(
+                    "[Variation] :: ServerType={0}, Runtime={1}, Arch={2}, BaseUrlHint={3}, Publish={4}, NoSource={5}",
+                    ServerType, 
+                    RuntimeFlavor, 
+                    RuntimeArchitecture, 
+                    ApplicationBaseUriHint,
+                    PublishApplicationBeforeDeployment, 
+                    PublishWithNoSource);
+        }
     }
 }

test/DeploymentHelpers/Deployers/ApplicationDeployer.cs

@@ -21,6 +21,8 @@ namespace DeploymentHelpers
 
         protected ILogger Logger { get; private set; }
 
+        protected Stopwatch StopWatch { get; private set; } = new Stopwatch();
+
         public abstract DeploymentResult Deploy();
 
         public ApplicationDeployer(
@@ -140,19 +142,38 @@ namespace DeploymentHelpers
                 startInfo.Environment;
 #endif
 
-            environment["ASPNET_ENV"] = DeploymentParameters.EnvironmentName;
+            SetEnvironmentVariable(environment, "ASPNET_ENV", DeploymentParameters.EnvironmentName);
 
             // Work around for https://github.com/aspnet/dnx/issues/1515
             if (DeploymentParameters.PublishWithNoSource)
             {
-                environment.Remove("DNX_PACKAGES");
+                SetEnvironmentVariable(environment, "DNX_PACKAGES", null);
             }
 
-            environment.Remove("DNX_DEFAULT_LIB");
+            SetEnvironmentVariable(environment, "DNX_DEFAULT_LIB", null);
 
             foreach (var environmentVariable in DeploymentParameters.EnvironmentVariables)
             {
-                environment[environmentVariable.Key] = environmentVariable.Value;
+                SetEnvironmentVariable(environment, environmentVariable.Key, environmentVariable.Value);
+            }
+        }
+
+#if DNX451
+        protected void SetEnvironmentVariable(System.Collections.Specialized.StringDictionary environment, string name, string value)
+        {
+#elif DNXCORE50
+        protected void SetEnvironmentVariable(System.Collections.Generic.IDictionary<string, string> environment, string name, string value)
+        {
+#endif
+            if (value == null)
+            {
+                Logger.LogInformation("Removing environment variable {name}", name);
+                environment.Remove(name);
+            }
+            else
+            {
+                Logger.LogInformation("SET {name}={value}", name, value);
+                environment[name] = value;
             }
         }
 
@@ -184,6 +205,18 @@ namespace DeploymentHelpers
             }
         }
 
+        protected void StartTimer()
+        {
+            Logger.LogInformation("Deploying {VariationDetails}", DeploymentParameters.ToString());
+            StopWatch.Start();
+        }
+
+        protected void StopTimer()
+        {
+            StopWatch.Stop();
+            Logger.LogInformation("[Time]: Total time taken for this test variation '{t}' seconds", StopWatch.Elapsed.TotalSeconds);
+        }
+
         public abstract void Dispose();
     }
 }

test/DeploymentHelpers/Deployers/IISDeployer.cs

@@ -24,6 +24,9 @@ namespace DeploymentHelpers
 
         public override DeploymentResult Deploy()
         {
+            // Start timer
+            StartTimer();
+
             // Only supports publish and run on IIS.
             DeploymentParameters.PublishApplicationBeforeDeployment = true;
 
@@ -93,6 +96,8 @@ namespace DeploymentHelpers
 
             CleanPublishedOutput();
             InvokeUserApplicationCleanup();
+
+            StopTimer();
         }
 
         private class IISApplication

test/DeploymentHelpers/Deployers/IISExpressDeployer.cs

@@ -22,6 +22,9 @@ namespace DeploymentHelpers
 
         public override DeploymentResult Deploy()
         {
+            // Start timer
+            StartTimer();
+
             DeploymentParameters.DnxRuntime = PopulateChosenRuntimeInformation();
 
             if (DeploymentParameters.PublishApplicationBeforeDeployment)
@@ -91,11 +94,11 @@ namespace DeploymentHelpers
 
             // IIS express figures out the DNX from %PATH%.
 #if DNX451
-            startInfo.EnvironmentVariables["PATH"] = ChosenRuntimePath + ";" + startInfo.EnvironmentVariables["PATH"];
+            SetEnvironmentVariable(startInfo.EnvironmentVariables, "PATH", ChosenRuntimePath + ";" + startInfo.EnvironmentVariables["PATH"]);
-            startInfo.EnvironmentVariables["DNX_APPBASE"] = DeploymentParameters.ApplicationPath;
+            SetEnvironmentVariable(startInfo.EnvironmentVariables, "DNX_APPBASE", DeploymentParameters.ApplicationPath);
 #elif DNXCORE50
-            startInfo.Environment["PATH"] = ChosenRuntimePath + ";" + startInfo.Environment["PATH"];
+            SetEnvironmentVariable(startInfo.Environment, "PATH", ChosenRuntimePath + ";" + startInfo.Environment["PATH"]);
-            startInfo.Environment["DNX_APPBASE"] = DeploymentParameters.ApplicationPath;
+            SetEnvironmentVariable(startInfo.Environment, "DNX_APPBASE", DeploymentParameters.ApplicationPath);
 #endif
 
             _hostProcess = Process.Start(startInfo);
@@ -194,6 +197,8 @@ namespace DeploymentHelpers
             }
 
             InvokeUserApplicationCleanup();
+
+            StopTimer();
         }
     }
 }

test/DeploymentHelpers/Deployers/MonoDeployer.cs

@@ -21,6 +21,9 @@ namespace DeploymentHelpers
 
         public override DeploymentResult Deploy()
         {
+            // Start timer
+            StartTimer();
+
             var path = Environment.GetEnvironmentVariable("PATH");
             var runtimeBin = path.Split(new char[] { ':' }, StringSplitOptions.RemoveEmptyEntries).
                 Where(c => c.Contains("dnx-mono")).FirstOrDefault();
@@ -97,6 +100,8 @@ namespace DeploymentHelpers
             }
 
             InvokeUserApplicationCleanup();
+
+            StopTimer();
         }
     }
 }

test/DeploymentHelpers/Deployers/SelfHostDeployer.cs

@@ -20,6 +20,9 @@ namespace DeploymentHelpers
 
         public override DeploymentResult Deploy()
         {
+            // Start timer
+            StartTimer();
+
             DeploymentParameters.DnxRuntime = PopulateChosenRuntimeInformation();
 
             if (DeploymentParameters.PublishApplicationBeforeDeployment)
@@ -81,6 +84,8 @@ namespace DeploymentHelpers
             }
 
             InvokeUserApplicationCleanup();
+
+            StopTimer();
         }
     }
 }

test/E2ETests/NtlmAuthentationTest.cs

@@ -1,6 +1,5 @@
 using System;
 using System.Collections.Generic;
-using System.Diagnostics;
 using System.IO;
 using System.Net.Http;
 using DeploymentHelpers;
@@ -26,14 +25,8 @@ namespace E2ETests
 
             using (logger.BeginScope("NtlmAuthenticationTest"))
             {
-                var stopwatch = Stopwatch.StartNew();
-
-                logger.LogInformation("Variation Details : HostType = {hostType}, RuntimeFlavor = {flavor}, Architecture = {arch}, applicationBaseUrl = {appBase}",
-                    serverType, runtimeFlavor, architecture, applicationBaseUrl);
-
                 var musicStoreDbName = Guid.NewGuid().ToString().Replace("-", string.Empty);
                 var connectionString = string.Format(DbUtils.CONNECTION_STRING_FORMAT, musicStoreDbName);
-                logger.LogInformation("Pointing MusicStore DB to '{connString}'", connectionString);
 
                 var deploymentParameters = new DeploymentParameters(Helpers.GetApplicationPath(), serverType, runtimeFlavor, architecture)
                 {
@@ -53,7 +46,9 @@ namespace E2ETests
 
                 // Override the connection strings using environment based configuration
                 deploymentParameters.EnvironmentVariables
-                    .Add(new KeyValuePair<string, string>("SQLAZURECONNSTR_DefaultConnection", connectionString));
+                    .Add(new KeyValuePair<string, string>(
+                        "SQLAZURECONNSTR_DefaultConnection",
+                        string.Format(DbUtils.CONNECTION_STRING_FORMAT, musicStoreDbName)));
 
                 bool testSuccessful = false;
 
@@ -72,16 +67,12 @@ namespace E2ETests
                         return response;
                     }, logger: logger, cancellationToken: deploymentResult.HostShutdownToken);
 
-                    logger.LogInformation("[Time]: Approximate time taken for application initialization : '{t}' seconds", stopwatch.Elapsed.TotalSeconds);
-
                     var validator = new Validator(httpClient, httpClientHandler, logger, deploymentResult);
                     validator.VerifyNtlmHomePage(response);
 
                     //Should be able to access the store as the Startup adds necessary permissions for the current user
                     validator.AccessStoreWithPermissions();
 
-                    stopwatch.Stop();
-                    logger.LogInformation("[Time]: Total time taken for this test variation '{t}' seconds", stopwatch.Elapsed.TotalSeconds);
                     testSuccessful = true;
                 }
 

test/E2ETests/OpenIdConnectTests.cs

@@ -1,6 +1,5 @@
 using System;
 using System.Collections.Generic;
-using System.Diagnostics;
 using System.Net.Http;
 using DeploymentHelpers;
 using Microsoft.AspNet.Testing.xunit;
@@ -37,14 +36,8 @@ namespace E2ETests
 
             using (logger.BeginScope("OpenIdConnectTestSuite"))
             {
-                var stopwatch = Stopwatch.StartNew();
-
-                logger.LogInformation("Variation Details : HostType = {hostType}, DonetFlavor = {flavor}, Architecture = {arch}, applicationBaseUrl = {appBase}",
-                    serverType, runtimeFlavor, architecture, applicationBaseUrl);
-
                 var musicStoreDbName = Guid.NewGuid().ToString().Replace("-", string.Empty);
                 var connectionString = string.Format(DbUtils.CONNECTION_STRING_FORMAT, musicStoreDbName);
-                logger.LogInformation("Pointing MusicStore DB to '{connString}'", connectionString);
 
                 var deploymentParameters = new DeploymentParameters(Helpers.GetApplicationPath(), serverType, runtimeFlavor, architecture)
                 {
@@ -62,7 +55,9 @@ namespace E2ETests
 
                 // Override the connection strings using environment based configuration
                 deploymentParameters.EnvironmentVariables
-                    .Add(new KeyValuePair<string, string>("SQLAZURECONNSTR_DefaultConnection", connectionString));
+                    .Add(new KeyValuePair<string, string>(
+                        "SQLAZURECONNSTR_DefaultConnection",
+                        string.Format(DbUtils.CONNECTION_STRING_FORMAT, musicStoreDbName)));
 
                 bool testSuccessful = false;
 
@@ -81,16 +76,12 @@ namespace E2ETests
                         return response;
                     }, logger: logger, cancellationToken: deploymentResult.HostShutdownToken);
 
-                    logger.LogInformation("[Time]: Approximate time taken for application initialization : '{t}' seconds", stopwatch.Elapsed.TotalSeconds);
-
                     var validator = new Validator(httpClient, httpClientHandler, logger, deploymentResult);
                     validator.VerifyHomePage(response);
 
                     // OpenIdConnect login.
                     validator.LoginWithOpenIdConnect();
 
-                    stopwatch.Stop();
-                    logger.LogInformation("[Time]: Total time taken for this test variation '{t}' seconds", stopwatch.Elapsed.TotalSeconds);
                     testSuccessful = true;
                 }
 

test/E2ETests/PublishAndRunTests.cs

@@ -1,6 +1,5 @@
 using System;
 using System.Collections.Generic;
-using System.Diagnostics;
 using System.IO;
 using System.Net.Http;
 using DeploymentHelpers;
@@ -58,14 +57,8 @@ namespace E2ETests
 
             using (logger.BeginScope("Publish_And_Run_Tests"))
             {
-                var stopwatch = Stopwatch.StartNew();
-
-                logger.LogInformation("Variation Details : HostType = {hostType}, RuntimeFlavor = {flavor}, Architecture = {arch}, applicationBaseUrl = {appBase}",
-                    serverType, runtimeFlavor, architecture, applicationBaseUrl);
-
                 var musicStoreDbName = Guid.NewGuid().ToString().Replace("-", string.Empty);
                 var connectionString = string.Format(DbUtils.CONNECTION_STRING_FORMAT, musicStoreDbName);
-                logger.LogInformation("Pointing MusicStore DB to '{connString}'", connectionString);
 
                 var deploymentParameters = new DeploymentParameters(Helpers.GetApplicationPath(), serverType, runtimeFlavor, architecture)
                 {
@@ -84,7 +77,9 @@ namespace E2ETests
 
                 // Override the connection strings using environment based configuration
                 deploymentParameters.EnvironmentVariables
-                    .Add(new KeyValuePair<string, string>("SQLAZURECONNSTR_DefaultConnection", connectionString));
+                    .Add(new KeyValuePair<string, string>(
+                        "SQLAZURECONNSTR_DefaultConnection",
+                        string.Format(DbUtils.CONNECTION_STRING_FORMAT, musicStoreDbName)));
 
                 bool testSuccessful = false;
 
@@ -104,8 +99,6 @@ namespace E2ETests
                         return response;
                     }, logger: logger, cancellationToken: deploymentResult.HostShutdownToken);
 
-                    logger.LogInformation("[Time]: Approximate time taken for application initialization : '{t}' seconds", stopwatch.Elapsed.TotalSeconds);
-
                     var validator = new Validator(httpClient, httpClientHandler, logger, deploymentResult);
                     validator.VerifyHomePage(response);
 
@@ -120,8 +113,6 @@ namespace E2ETests
                         }
                     }
 
-                    stopwatch.Stop();
-                    logger.LogInformation("[Time]: Total time taken for this test variation '{t}' seconds.", stopwatch.Elapsed.TotalSeconds);
                     testSuccessful = true;
                 }
 

test/E2ETests/SmokeTests.cs

@@ -1,6 +1,5 @@
 using System;
 using System.Collections.Generic;
-using System.Diagnostics;
 using System.Net.Http;
 using DeploymentHelpers;
 using Microsoft.AspNet.Testing.xunit;
@@ -124,14 +123,7 @@ namespace E2ETests
 
             using (logger.BeginScope("SmokeTestSuite"))
             {
-                var stopwatch = Stopwatch.StartNew();
-
-                logger.LogInformation("Variation Details : HostType = {hostType}, DonetFlavor = {flavor}, Architecture = {arch}, applicationBaseUrl = {appBase}",
-                    serverType, donetFlavor, architecture, applicationBaseUrl);
-
                 var musicStoreDbName = Guid.NewGuid().ToString().Replace("-", string.Empty);
-                var connectionString = string.Format(DbUtils.CONNECTION_STRING_FORMAT, musicStoreDbName);
-                logger.LogInformation("Pointing MusicStore DB to '{connString}'", connectionString);
 
                 var deploymentParameters = new DeploymentParameters(Helpers.GetApplicationPath(), serverType, donetFlavor, architecture)
                 {
@@ -152,7 +144,9 @@ namespace E2ETests
 
                 // Override the connection strings using environment based configuration
                 deploymentParameters.EnvironmentVariables
-                    .Add(new KeyValuePair<string, string>("SQLAZURECONNSTR_DefaultConnection", connectionString));
+                    .Add(new KeyValuePair<string, string>(
+                        "SQLAZURECONNSTR_DefaultConnection",
+                        string.Format(DbUtils.CONNECTION_STRING_FORMAT, musicStoreDbName)));
 
                 bool testSuccessful = false;
 
@@ -173,8 +167,6 @@ namespace E2ETests
                         return response;
                     }, logger: logger, cancellationToken: deploymentResult.HostShutdownToken);
 
-                    logger.LogInformation("[Time]: Approximate time taken for application initialization : '{t}' seconds", stopwatch.Elapsed.TotalSeconds);
-
                     var validator = new Validator(httpClient, httpClientHandler, logger, deploymentResult);
 
                     validator.VerifyHomePage(response);
@@ -260,8 +252,6 @@ namespace E2ETests
                     // MicrosoftAccountLogin
                     validator.LoginWithMicrosoftAccount();
 
-                    stopwatch.Stop();
-                    logger.LogInformation("[Time]: Total time taken for this test variation '{t}' seconds", stopwatch.Elapsed.TotalSeconds);
                     testSuccessful = true;
                 }