Merge pull request #134 from microsoft/users/jmyers/buildAndLog

jmyersmsft · web-flow · commit c0d83ec8ed65 · 2019-10-02T14:30:12.000-07:00
Build fixes and logging improvements, Includes some build changes from @zarenner
diff --git a/CredentialProvider.Microsoft.Tests/CredentialProvider.Microsoft.Tests.csproj b/CredentialProvider.Microsoft.Tests/CredentialProvider.Microsoft.Tests.csproj
@@ -1,7 +1,7 @@
-<Project Sdk="Microsoft.NET.Sdk">
+﻿<Project Sdk="Microsoft.NET.Sdk">
 
   <PropertyGroup>
-    <TargetFramework>net461</TargetFramework>
+    <TargetFrameworks>netcoreapp2.1;net461</TargetFrameworks>
 
     <IsPackable>false</IsPackable>
   </PropertyGroup>
@@ -12,6 +12,7 @@
     <PackageReference Include="Moq" Version="4.8.2" />
     <PackageReference Include="MSTest.TestAdapter" Version="1.2.1" />
     <PackageReference Include="MSTest.TestFramework" Version="1.2.1" />
+    <PackageReference Include="NuGet.Protocol" Version="5.3.0" />
   </ItemGroup>
 
   <ItemGroup>
diff --git a/CredentialProvider.Microsoft.Tests/Logging/LoggingTests.cs b/CredentialProvider.Microsoft.Tests/Logging/LoggingTests.cs
@@ -15,9 +15,9 @@ public class LoggingTests
         public void HumanFriendlyTextWriterLogger_EmitsLogLevelAndMessage()
         {
             mockWriter.Setup(x => x.WriteLine(It.IsAny<string>()));
-            HumanFriendlyTextWriterLogger logger = new HumanFriendlyTextWriterLogger(mockWriter.Object);
+            HumanFriendlyTextWriterLogger logger = new HumanFriendlyTextWriterLogger(mockWriter.Object, writesToConsole: false);
             logger.SetLogLevel(LogLevel.Error);
-            logger.Log(LogLevel.Error, "Something bad happened");
+            logger.Log(LogLevel.Error, allowOnConsole: true, "Something bad happened");
             mockWriter.Verify(x => x.WriteLine("[Error] [CredentialProvider]Something bad happened"));
         }
     }
diff --git a/CredentialProvider.Microsoft.VSIX/Microsoft.CredentialProvider.swixproj b/CredentialProvider.Microsoft.VSIX/Microsoft.CredentialProvider.swixproj
@@ -26,7 +26,7 @@
   <ItemGroup>
     <SigningTarget Include="$(OutDir)$(OutputName)"/>
     <FilesToSign Include="@(SigningTarget)">
-      <Authenticode>Vsix</Authenticode>
+      <Authenticode>VsixSHA2</Authenticode>
     </FilesToSign>
   </ItemGroup>
 
diff --git a/CredentialProvider.Microsoft.VSIX/Microsoft.CredentialProvider.swr b/CredentialProvider.Microsoft.VSIX/Microsoft.CredentialProvider.swr
@@ -15,7 +15,6 @@ folder InstallDir:\Common7\IDE\CommonExtensions\Microsoft\NuGet\Plugins\Credenti
   file source=$(PluginBinPath)\NuGet.Common.dll
   file source=$(PluginBinPath)\NuGet.Configuration.dll
   file source=$(PluginBinPath)\NuGet.Frameworks.dll
-  file source=$(PluginBinPath)\NuGet.Packaging.Core.dll
   file source=$(PluginBinPath)\NuGet.Packaging.dll
   file source=$(PluginBinPath)\NuGet.Protocol.dll
   file source=$(PluginBinPath)\NuGet.Versioning.dll
@@ -94,6 +93,7 @@ folder InstallDir:\Common7\IDE\CommonExtensions\Microsoft\NuGet\Plugins\Credenti
   file source=$(PluginBinPath)\System.Security.Cryptography.Csp.dll
   file source=$(PluginBinPath)\System.Security.Cryptography.Encoding.dll
   file source=$(PluginBinPath)\System.Security.Cryptography.Primitives.dll
+  file source=$(PluginBinPath)\System.Security.Cryptography.ProtectedData.dll
   file source=$(PluginBinPath)\System.Security.Cryptography.X509Certificates.dll
   file source=$(PluginBinPath)\System.Security.Principal.dll
   file source=$(PluginBinPath)\System.Security.SecureString.dll
diff --git a/CredentialProvider.Microsoft/CredentialProvider.Microsoft.csproj b/CredentialProvider.Microsoft/CredentialProvider.Microsoft.csproj
@@ -33,7 +33,7 @@
 
   <ItemGroup>
     <PackageReference Include="Microsoft.IdentityModel.Clients.ActiveDirectory" Version="3.19.4" />
-    <PackageReference Include="NuGet.Protocol" Version="5.2.0" />
+    <PackageReference Include="NuGet.Protocol" Version="5.3.0" />
     <PackageReference Include="PowerArgs" Version="3.0.0" />
   </ItemGroup>
 
@@ -65,11 +65,11 @@
 
   <ItemGroup>
     <FilesToSign Include="$(OutDir)/$(TargetFileName)">
-      <Authenticode>Microsoft</Authenticode>
+      <Authenticode>Microsoft400</Authenticode>
       <StrongName>StrongName</StrongName>
     </FilesToSign>
     <FilesToSign Include="$(IntermediateOutputPath)/$(TargetFileName)">
-      <Authenticode>Microsoft</Authenticode>
+      <Authenticode>Microsoft400</Authenticode>
       <StrongName>StrongName</StrongName>
     </FilesToSign>
   </ItemGroup>
diff --git a/CredentialProvider.Microsoft/Logging/ConsoleLoggers.cs b/CredentialProvider.Microsoft/Logging/ConsoleLoggers.cs
@@ -13,15 +13,15 @@ namespace NuGetCredentialProvider.Logging
     /// </summary>
     public class StandardOutputLogger : HumanFriendlyTextWriterLogger
     {
-        public StandardOutputLogger() : base(Console.Out) { }
+        public StandardOutputLogger() : base(Console.Out, writesToConsole: true) { }
     }
 
     /// <summary>
     /// Logs messages to standard error, with log level included
     /// </summary>
     public class StandardErrorLogger : HumanFriendlyTextWriterLogger
     {
-        public StandardErrorLogger() : base(Console.Error) { }
+        public StandardErrorLogger() : base(Console.Error, writesToConsole: true) { }
     }
 
     /// <summary>
@@ -31,7 +31,8 @@ public class HumanFriendlyTextWriterLogger : LoggerBase
     {
         private readonly TextWriter writer;
 
-        public HumanFriendlyTextWriterLogger(TextWriter writer)
+        public HumanFriendlyTextWriterLogger(TextWriter writer, bool writesToConsole)
+            : base(writesToConsole)
         {
             this.writer = writer;
         }
diff --git a/CredentialProvider.Microsoft/Logging/FileLogger.cs b/CredentialProvider.Microsoft/Logging/FileLogger.cs
diff --git a/CredentialProvider.Microsoft/Logging/ILogger.cs b/CredentialProvider.Microsoft/Logging/ILogger.cs
@@ -8,7 +8,7 @@ namespace NuGetCredentialProvider.Logging
 {
     public interface ILogger
     {
-        void Log(LogLevel level, string message);
+        void Log(LogLevel level, bool allowOnConsole, string message);
 
         void SetLogLevel(LogLevel newLogLevel);
     }
diff --git a/CredentialProvider.Microsoft/Logging/LogEveryMessageFileLogger.cs b/CredentialProvider.Microsoft/Logging/LogEveryMessageFileLogger.cs
@@ -0,0 +1,83 @@
+﻿// Copyright (c) Microsoft. All rights reserved.
+//
+// Licensed under the MIT license.
+
+using System;
+using System.Diagnostics;
+using System.IO;
+using System.Threading;
+using NuGet.Common;
+
+namespace NuGetCredentialProvider.Logging
+{
+    internal class LogEveryMessageFileLogger : ILogger
+    {
+        private static readonly int Pid = Process.GetCurrentProcess().Id;
+
+        private readonly string filePath;
+
+        internal LogEveryMessageFileLogger(string filePath)
+        {
+            this.filePath = filePath;
+            Log(LogLevel.Minimal, allowOnConsole: false, string.Format(Resources.LogStartsAt, DateTime.UtcNow.ToString("u")));
+        }
+
+        public void Log(LogLevel level, bool allowOnConsole, string message)
+        {
+            try
+            {
+                for (int i = 0; i < 3; ++i)
+                {
+                    try
+                    {
+                        File.AppendAllText(
+                            filePath,
+                            $"[{DateTime.UtcNow:HH:mm:ss.fff} {Pid,5} {GetLevelKeyword(level),7}] {message}\n");
+                        return;
+                    }
+                    catch (IOException)
+                    {
+                        // retry IOExceptions a couple of times. Could be another instance (or thread) of the plugin locking the file
+                        Thread.Sleep(TimeSpan.FromMilliseconds(20));
+                    }
+                }
+            }
+            catch
+            {
+                // don't crash the process just because logging failed.
+            }
+        }
+
+        private string GetLevelKeyword(LogLevel level)
+        {
+            switch (level)
+            {
+                case LogLevel.Debug:
+                    return "Debug";
+
+                case LogLevel.Verbose:
+                    return "Verbose";
+
+                case LogLevel.Information:
+                    return "Info";
+
+                case LogLevel.Minimal:
+                    return "Minimal";
+
+                case LogLevel.Warning:
+                    return "Warning";
+
+                case LogLevel.Error:
+                    return "Error";
+
+                default:
+                    throw new ArgumentOutOfRangeException(nameof(level), level, null);
+            }
+        }
+
+        void ILogger.SetLogLevel(LogLevel newLogLevel)
+        {
+            // no-op. This logger always logs all messages.
+        }
+    }
+}
diff --git a/CredentialProvider.Microsoft/Logging/LoggerBase.cs b/CredentialProvider.Microsoft/Logging/LoggerBase.cs
@@ -14,9 +14,20 @@ public abstract class LoggerBase : ILogger
         private LogLevel minLogLevel = LogLevel.Debug;
         private bool allowLogWrites = false;
         private ConcurrentQueue<Tuple<LogLevel, string, DateTime>> bufferedLogs = new ConcurrentQueue<Tuple<LogLevel, string, DateTime>>();
+        private readonly bool writesToConsole;
 
-        public void Log(LogLevel level, string message)
+        protected LoggerBase(bool writesToConsole)
         {
+            this.writesToConsole = writesToConsole;
+        }
+
+        public void Log(LogLevel level, bool allowOnConsole, string message)
+        {
+            if (writesToConsole && !allowOnConsole)
+            {
+                return;
+            }
+
             if (!allowLogWrites)
             {
                 // cheap reserve, if it swaps out after we add, meh, we miss one log
diff --git a/CredentialProvider.Microsoft/Logging/MultiLogger.cs b/CredentialProvider.Microsoft/Logging/MultiLogger.cs
@@ -11,11 +11,11 @@ internal class MultiLogger : List<ILogger>, ILogger
     {
         private LogLevel? minLogLevel = null;
 
-        public void Log(LogLevel level, string message)
+        public void Log(LogLevel level, bool allowOnConsole, string message)
         {
             foreach (var logger in this)
             {
-                logger.Log(level, message);
+                logger.Log(level, allowOnConsole, message);
             }
         }
 
diff --git a/CredentialProvider.Microsoft/Logging/PluginConnectionLogger.cs b/CredentialProvider.Microsoft/Logging/PluginConnectionLogger.cs
@@ -3,6 +3,7 @@
 // Licensed under the MIT license.
 
 using System.Threading;
+using System.Threading.Tasks;
 using NuGet.Common;
 using NuGet.Protocol.Plugins;
 
@@ -13,6 +14,7 @@ internal class PluginConnectionLogger : LoggerBase
         private readonly IConnection connection;
 
         internal PluginConnectionLogger(IConnection connection)
+            : base(writesToConsole: true)
         {
             this.connection = connection;
         }
@@ -21,9 +23,11 @@ protected override void WriteLog(LogLevel logLevel, string message)
         {
             // intentionally not awaiting here -- don't want to block forward progress just because we tried to log.
             connection.SendRequestAndReceiveResponseAsync<LogRequest, LogResponse>(
-                MessageMethod.Log,
-                new LogRequest(logLevel, $"    {message}"),
-                CancellationToken.None);
+                    MessageMethod.Log,
+                    new LogRequest(logLevel, $"    {message}"),
+                    CancellationToken.None)
+                // "observe" any exceptions to avoid unobserved exception escalation, which may terminate the process
+                .ContinueWith(x => x.Exception, TaskContinuationOptions.OnlyOnFaulted);
         }
     }
 }
diff --git a/CredentialProvider.Microsoft/Program.cs b/CredentialProvider.Microsoft/Program.cs
@@ -147,7 +147,10 @@ public static async Task<int> Main(string[] args)
                     {
                         // When restoring from multiple sources, one of the sources will throw an unhandled TaskCanceledException
                         // if it has been restored successfully from a different source.
-                        multiLogger.Log(LogLevel.Verbose, ex.ToString());
+
+                        // This is probably more confusing than interesting to users, but may be helpful in debugging,
+                        // so log the exception but not to the console.
+                        multiLogger.Log(LogLevel.Verbose, allowOnConsole:false, ex.ToString());
                     }
 
                     return 0;
@@ -227,7 +230,7 @@ internal static async Task RunNuGetPluginsAsync(IPlugin plugin, ILogger logger,
             }
         }
 
-        private static FileLogger GetFileLogger()
+        private static ILogger GetFileLogger()
         {
             var location = EnvUtil.FileLogLocation;
             if (string.IsNullOrEmpty(location))
@@ -236,10 +239,8 @@ private static FileLogger GetFileLogger()
             }
 
             Directory.CreateDirectory(Path.GetDirectoryName(location));
-            var fileLogger = new FileLogger(location);
-            fileLogger.SetLogLevel(NuGet.Common.LogLevel.Verbose);
 
-            return fileLogger;
+            return new LogEveryMessageFileLogger(location);
         }
     }
 }
diff --git a/CredentialProvider.Microsoft/RequestHandlers/RequestHandlerBase.cs b/CredentialProvider.Microsoft/RequestHandlers/RequestHandlerBase.cs
@@ -7,9 +7,10 @@
 using System.Threading;
 using System.Threading.Tasks;
 using Newtonsoft.Json;
+using NuGet.Common;
 using NuGet.Protocol.Plugins;
-using NuGetCredentialProvider.Logging;
 using NuGetCredentialProvider.Util;
+using ILogger = NuGetCredentialProvider.Logging.ILogger;
 
 namespace NuGetCredentialProvider.RequestHandlers
 {
@@ -24,7 +25,7 @@ internal abstract class RequestHandlerBase<TRequest, TResponse> : IRequestHandle
         /// <summary>
         /// Initializes a new instance of the <see cref="RequestHandlerBase{TRequest, TResponse}"/> class.
         /// </summary>
-        /// <param name="logger">A <see cref="ILogger"/> to use for logging.</param>
+        /// <param name="logger">A <see cref="Logging.ILogger"/> to use for logging.</param>
         protected RequestHandlerBase(ILogger logger)
         {
             Logger = logger ?? throw new ArgumentNullException(nameof(logger));
@@ -76,25 +77,22 @@ public async Task HandleResponseAsync(IConnection connection, Message message, I
 
                 Logger.Verbose(string.Format(Resources.TimeElapsedAfterSendingResponse, message.Type, message.Method, timer.ElapsedMilliseconds));
             }
-            catch (Exception ex) when (LogExceptionAndReturnFalse(ex))
+            catch (Exception ex)
             {
-                throw;
-            }
+                // don't report cancellations to the console during shutdown, they're most likely not interesting.
+                bool cancelingDuringShutdown = ex is OperationCanceledException && Program.IsShuttingDown;
 
-            bool LogExceptionAndReturnFalse(Exception ex)
-            {
-                // don't report cancellations during shutdown, they're most likely not interesting.
-                if (ex is OperationCanceledException && Program.IsShuttingDown && !Debugger.IsAttached)
+                if (cancelingDuringShutdown)
                 {
-                    Logger.Verbose(Resources.ShuttingDown);
-                    return false;
+                    Logger.Log(LogLevel.Verbose, allowOnConsole: false, Resources.WhileShuttingDown);
                 }
 
-                Logger.Verbose(string.Format(Resources.ResponseHandlerException, message.Method, message.RequestId));
-                Logger.Verbose(ex.ToString());
-                return false;
+                Logger.Log(LogLevel.Verbose, allowOnConsole: !cancelingDuringShutdown, string.Format(Resources.ResponseHandlerException, message.Method, message.RequestId));
+                Logger.Log(LogLevel.Verbose, allowOnConsole: !cancelingDuringShutdown, ex.ToString());
+
+                throw;
             }
-            
+
             timer.Stop();
         }
 
diff --git a/CredentialProvider.Microsoft/Resources.Designer.cs b/CredentialProvider.Microsoft/Resources.Designer.cs
diff --git a/CredentialProvider.Microsoft/Resources.resx b/CredentialProvider.Microsoft/Resources.resx
diff --git a/CredentialProvider.Microsoft/Util/ExtensionMethods.cs b/CredentialProvider.Microsoft/Util/ExtensionMethods.cs
diff --git a/build/build.yml b/build/build.yml

Original file line number	Diff line number	Diff line change
`@@ -15,9 +15,9 @@ public class LoggingTests`
`15`	`15`	`public void HumanFriendlyTextWriterLogger_EmitsLogLevelAndMessage()`
`16`	`16`	`{`
`17`	`17`	`mockWriter.Setup(x => x.WriteLine(It.IsAny<string>()));`
`18`		`- HumanFriendlyTextWriterLogger logger = new HumanFriendlyTextWriterLogger(mockWriter.Object);`
	`18`	`+ HumanFriendlyTextWriterLogger logger = new HumanFriendlyTextWriterLogger(mockWriter.Object, writesToConsole: false);`
`19`	`19`	`logger.SetLogLevel(LogLevel.Error);`
`20`		`- logger.Log(LogLevel.Error, "Something bad happened");`
	`20`	`+ logger.Log(LogLevel.Error, allowOnConsole: true, "Something bad happened");`
`21`	`21`	`mockWriter.Verify(x => x.WriteLine("[Error] [CredentialProvider]Something bad happened"));`
`22`	`22`	`}`
`23`	`23`	`}`
Original file line number	Diff line number	Diff line change
`@@ -13,15 +13,15 @@ namespace NuGetCredentialProvider.Logging`
`13`	`13`	`/// </summary>`
`14`	`14`	`public class StandardOutputLogger : HumanFriendlyTextWriterLogger`
`15`	`15`	`{`
`16`		`- public StandardOutputLogger() : base(Console.Out) { }`
	`16`	`+ public StandardOutputLogger() : base(Console.Out, writesToConsole: true) { }`
`17`	`17`	`}`
`18`	`18`
`19`	`19`	`/// <summary>`
`20`	`20`	`/// Logs messages to standard error, with log level included`
`21`	`21`	`/// </summary>`
`22`	`22`	`public class StandardErrorLogger : HumanFriendlyTextWriterLogger`
`23`	`23`	`{`
`24`		`- public StandardErrorLogger() : base(Console.Error) { }`
	`24`	`+ public StandardErrorLogger() : base(Console.Error, writesToConsole: true) { }`
`25`	`25`	`}`
`26`	`26`
`27`	`27`	`/// <summary>`
`@@ -31,7 +31,8 @@ public class HumanFriendlyTextWriterLogger : LoggerBase`
`31`	`31`	`{`
`32`	`32`	`private readonly TextWriter writer;`
`33`	`33`
`34`		`- public HumanFriendlyTextWriterLogger(TextWriter writer)`
	`34`	`+ public HumanFriendlyTextWriterLogger(TextWriter writer, bool writesToConsole)`
	`35`	`+ : base(writesToConsole)`
`35`	`36`	`{`
`36`	`37`	`this.writer = writer;`
`37`	`38`	`}`
Original file line number	Diff line number	Diff line change
`@@ -8,7 +8,7 @@ namespace NuGetCredentialProvider.Logging`
`8`	`8`	`{`
`9`	`9`	`public interface ILogger`
`10`	`10`	`{`
`11`		`- void Log(LogLevel level, string message);`
	`11`	`+ void Log(LogLevel level, bool allowOnConsole, string message);`
`12`	`12`
`13`	`13`	`void SetLogLevel(LogLevel newLogLevel);`
`14`	`14`	`}`