diff --git a/src/chocolatey.tests/MockLogger.cs b/src/chocolatey.tests/MockLogger.cs index 5f31300805..cb96721e45 100644 --- a/src/chocolatey.tests/MockLogger.cs +++ b/src/chocolatey.tests/MockLogger.cs @@ -35,6 +35,7 @@ public class MockLogger : Mock, ILog, ILog { public MockLogger() { + LoggerNames = new HashSet(); } public void reset() @@ -42,6 +43,7 @@ public void reset() Messages.Clear(); this.ResetCalls(); LogMessagesToConsole = false; + LoggerNames.Clear(); } public bool contains_message(string expectedMessage) @@ -91,6 +93,8 @@ public int contains_message_count(string expectedMessage, LogLevel level) private readonly Lazy>> _messages = new Lazy>>(); + public HashSet LoggerNames { get; private set; } + public ConcurrentDictionary> Messages { get { return _messages.Value; } @@ -103,6 +107,7 @@ public IList MessagesFor(LogLevel logLevel) public void InitializeFor(string loggerName) { + LoggerNames.Add(loggerName); } public void LogMessage(LogLevel logLevel, string message) diff --git a/src/chocolatey.tests/TinySpec.cs b/src/chocolatey.tests/TinySpec.cs index 18673218ab..17f60ac42c 100644 --- a/src/chocolatey.tests/TinySpec.cs +++ b/src/chocolatey.tests/TinySpec.cs @@ -227,6 +227,15 @@ public SourcePriorityAttribute() { } } + + [AttributeUsage(AttributeTargets.Class | AttributeTargets.Method, AllowMultiple = false)] + public sealed class LoggingAttribute : CategoryAttribute + { + public LoggingAttribute() + : base("Logging") + { + } + } } // ReSharper restore InconsistentNaming diff --git a/src/chocolatey.tests/chocolatey.tests.csproj b/src/chocolatey.tests/chocolatey.tests.csproj index 0e43a12a06..54958b3368 100644 --- a/src/chocolatey.tests/chocolatey.tests.csproj +++ b/src/chocolatey.tests/chocolatey.tests.csproj @@ -77,27 +77,49 @@ MinimumRecommendedRules.ruleset + + ..\packages\Chocolatey.NuGet.Commands.3.0.0-alpha-20221213-80\lib\net472\Chocolatey.NuGet.Commands.dll + ..\packages\Chocolatey.NuGet.Common.3.0.0-alpha-20221213-80\lib\net472\Chocolatey.NuGet.Common.dll ..\packages\Chocolatey.NuGet.Configuration.3.0.0-alpha-20221213-80\lib\net472\Chocolatey.NuGet.Configuration.dll + + ..\packages\Chocolatey.NuGet.Credentials.3.0.0-alpha-20221213-80\lib\net472\Chocolatey.NuGet.Credentials.dll + + + ..\packages\Chocolatey.NuGet.DependencyResolver.Core.3.0.0-alpha-20221213-80\lib\net472\Chocolatey.NuGet.DependencyResolver.Core.dll + ..\packages\Chocolatey.NuGet.Frameworks.3.0.0-alpha-20221213-80\lib\net472\Chocolatey.NuGet.Frameworks.dll + + ..\packages\Chocolatey.NuGet.LibraryModel.3.0.0-alpha-20221213-80\lib\net472\Chocolatey.NuGet.LibraryModel.dll + + + ..\packages\Chocolatey.NuGet.PackageManagement.3.0.0-alpha-20221213-80\lib\net472\Chocolatey.NuGet.PackageManagement.dll + ..\packages\Chocolatey.NuGet.Packaging.3.0.0-alpha-20221213-80\lib\net472\Chocolatey.NuGet.Packaging.dll + + ..\packages\Chocolatey.NuGet.ProjectModel.3.0.0-alpha-20221213-80\lib\net472\Chocolatey.NuGet.ProjectModel.dll + ..\packages\Chocolatey.NuGet.Protocol.3.0.0-alpha-20221213-80\lib\net472\Chocolatey.NuGet.Protocol.dll + + ..\packages\Chocolatey.NuGet.Resolver.3.0.0-alpha-20221213-80\lib\net472\Chocolatey.NuGet.Resolver.dll + ..\packages\Chocolatey.NuGet.Versioning.3.0.0-alpha-20221213-80\lib\net472\Chocolatey.NuGet.Versioning.dll ..\packages\log4net.2.0.12\lib\net45\log4net.dll + ..\packages\Microsoft.Web.Xdt.3.1.0\lib\net40\Microsoft.Web.XmlTransform.dll @@ -117,6 +139,7 @@ ..\packages\SimpleInjector.2.8.3\lib\net45\SimpleInjector.dll + @@ -153,6 +176,8 @@ + + diff --git a/src/chocolatey.tests/infrastructure.app/nuget/ChocolateyNuGetProjectContextSpecs.cs b/src/chocolatey.tests/infrastructure.app/nuget/ChocolateyNuGetProjectContextSpecs.cs new file mode 100644 index 0000000000..4b6b8d8432 --- /dev/null +++ b/src/chocolatey.tests/infrastructure.app/nuget/ChocolateyNuGetProjectContextSpecs.cs @@ -0,0 +1,151 @@ +// Copyright © 2022-Present Chocolatey Software, Inc +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +namespace chocolatey.tests.infrastructure.app.nuget +{ + using chocolatey.infrastructure.app.configuration; + using chocolatey.infrastructure.app.nuget; + using Moq; + using NuGet.Common; + using NuGet.ProjectManagement; + using NUnit.Framework; + using Should; + + public class ChocolateyNuGetProjectContextSpecs + { + public abstract class ChocolateyNuGetProjectContextSpecsBase : TinySpec + { + protected ChocolateyConfiguration Configuration; + protected Mock Logger = new Mock(); + protected ChocolateyNuGetProjectContext Service; + + public override void Context() + { + Configuration = new ChocolateyConfiguration(); + Service = new ChocolateyNuGetProjectContext(Configuration, Logger.Object); + } + } + + [Categories.Logging, Parallelizable(ParallelScope.Self)] + public class when_calling_logging_methods_the_passed_in_logger_is_used : ChocolateyNuGetProjectContextSpecsBase + { + public override void Because() + { } + + public override void BeforeEachSpec() + { + base.BeforeEachSpec(); + + Logger.ResetCalls(); + } + + [Fact] + public void should_log_debug_information_in_child_logger() + { + Service.Log(MessageLevel.Debug, "Some {0} message", "DEBUG"); + + Logger.Verify(l => l.LogDebug("Some DEBUG message"), Times.Once); + + // TODO: Uncomment once Moq is upgrade to v4.8 or later. + //Logger.VerifyNoOtherCalls(); + } + + [Fact] + public void should_log_error_information_in_child_logger() + { + Service.Log(MessageLevel.Error, "Some {0} message", "ERROR"); + + Logger.Verify(l => l.LogError("Some ERROR message"), Times.Once); + + // TODO: Uncomment once Moq is upgrade to v4.8 or later. + //Logger.VerifyNoOtherCalls(); + } + + [Fact] + public void should_log_info_information_in_child_logger() + { + Service.Log(MessageLevel.Info, "Some {0} message", "INFO"); + + Logger.Verify(l => l.LogInformation("Some INFO message"), Times.Once); + + // TODO: Uncomment once Moq is upgrade to v4.8 or later. + //Logger.VerifyNoOtherCalls(); + } + + [TestCase(LogLevel.Debug)] + public void should_log_to_child_logger_and_pass_along_original_message(LogLevel logLevel) + { + var logMessage = new LogMessage(logLevel, "My awesome message"); + + Service.Log(logMessage); + + Logger.Verify(l => l.Log(logMessage), Times.Once); + + // TODO: Uncomment once Moq is upgrade to v4.8 or later. + //Logger.VerifyNoOtherCalls(); + } + + [Fact] + public void should_log_warning_information_in_child_logger() + { + Service.Log(MessageLevel.Warning, "Some {0} message", "WARNING"); + + Logger.Verify(l => l.LogWarning("Some WARNING message"), Times.Once); + + // TODO: Uncomment once Moq is upgrade to v4.8 or later. + //Logger.VerifyNoOtherCalls(); + } + + [Fact] + public void should_report_errors_to_child_logger() + { + Service.ReportError("Some kind of error!"); + + Logger.Verify(l => l.LogError("Some kind of error!"), Times.Once); + + // TODO: Uncomment once Moq is upgrade to v4.8 or later. + //Logger.VerifyNoOtherCalls(); + } + + [Fact] + public void should_report_errors_with_message_to_child_logger() + { + var logMessage = new LogMessage(LogLevel.Debug, "Some message"); + + Service.ReportError(logMessage); + + Logger.Verify(l => l.Log(logMessage), Times.Once); + + // TODO: Uncomment once Moq is upgrade to v4.8 or later. + //Logger.VerifyNoOtherCalls(); + } + + [Fact] + public void should_report_warning_when_resolving_file_conflicts() + { + var message = "Some kind of message"; + + var result = Service.ResolveFileConflict(message); + + result.ShouldEqual(FileConflictAction.OverwriteAll); + + Logger.Verify(l => l.LogWarning("File conflict, overwriting all: Some kind of message"), Times.Once); + + // TODO: Uncomment once Moq is upgrade to v4.8 or later. + //Logger.VerifyNoOtherCalls(); + } + } + } +} diff --git a/src/chocolatey.tests/infrastructure.app/nuget/ChocolateyNugetLoggerSpecs.cs b/src/chocolatey.tests/infrastructure.app/nuget/ChocolateyNugetLoggerSpecs.cs new file mode 100644 index 0000000000..a4832e804c --- /dev/null +++ b/src/chocolatey.tests/infrastructure.app/nuget/ChocolateyNugetLoggerSpecs.cs @@ -0,0 +1,391 @@ +// Copyright © 2022-Present Chocolatey Software, Inc +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +namespace chocolatey.tests.infrastructure.app.nuget +{ + using System; + using System.Threading.Tasks; + using chocolatey.infrastructure.app.nuget; + using NuGet.Common; + using NUnit.Framework; + using Should; + + using LogLevel = chocolatey.tests.LogLevel; + using NuGetLogLevel = NuGet.Common.LogLevel; + + public class ChocolateyNugetLoggerSpecs + { + [Categories.Logging] + public class when_calling_log_level_methods_should_log_with_appropriate_log_type : TinySpec + { + private ILogger _logger; + + public override void Because() + { + } + + public override void BeforeEachSpec() + { + base.BeforeEachSpec(); + MockLogger.reset(); + } + + public override void Context() + { + _logger = new ChocolateyNugetLogger(); + } + + [Fact] + public void should_log_debug_level_with_nuget_prefix_on_all_lines_when_calling_LogDebug() + { + const string testMessage = "This should be a debug message.\r\nThis is the second line after CRLF line ending.\nThis is the third line after LF line ending."; + var expectedMessage = "[NuGet] This should be a debug message.{0}[NuGet] This is the second line after CRLF line ending.{0}[NuGet] This is the third line after LF line ending.".format_with(Environment.NewLine); + + _logger.LogDebug(testMessage); + + var loggerName = LogLevel.Debug.to_string(); + MockLogger.LoggerNames.Count.ShouldEqual(1); + MockLogger.LoggerNames.ShouldContain(typeof(ChocolateyNugetLogger).FullName); + MockLogger.Messages.Keys.ShouldContain(loggerName); + MockLogger.Messages[loggerName].ShouldContain(expectedMessage); + } + + [Fact] + public void should_log_debug_level_with_nuget_prefix_when_calling_LogDebug() + { + const string testMessage = "This should be a debug message"; + const string expectedMessage = "[NuGet] " + testMessage; + + _logger.LogDebug(testMessage); + + var loggerName = LogLevel.Debug.to_string(); + MockLogger.LoggerNames.Count.ShouldEqual(1); + MockLogger.LoggerNames.ShouldContain(typeof(ChocolateyNugetLogger).FullName); + MockLogger.Messages.Keys.ShouldContain(loggerName); + MockLogger.Messages[loggerName].ShouldContain(expectedMessage); + } + + [Fact] + public void should_log_error_level_with_nuget_prefix_on_all_lines_when_calling_LogError() + { + const string testMessage = "This should be a error message.\r\nThis is the second line after CRLF line ending.\nThis is the third line after LF line ending."; + var expectedMessage = "[NuGet] This should be a error message.{0}[NuGet] This is the second line after CRLF line ending.{0}[NuGet] This is the third line after LF line ending.".format_with(Environment.NewLine); + + _logger.LogError(testMessage); + + var loggerName = LogLevel.Error.to_string(); + MockLogger.LoggerNames.Count.ShouldEqual(1); + MockLogger.LoggerNames.ShouldContain(typeof(ChocolateyNugetLogger).FullName); + MockLogger.Messages.Keys.ShouldContain(loggerName); + MockLogger.Messages[loggerName].ShouldContain(expectedMessage); + } + + [Fact] + public void should_log_error_level_with_nuget_prefix_when_calling_LogError() + { + const string testMessage = "This should be a error message"; + const string expectedMessage = "[NuGet] " + testMessage; + + _logger.LogError(testMessage); + + var loggerName = LogLevel.Error.to_string(); + MockLogger.LoggerNames.Count.ShouldEqual(1); + MockLogger.LoggerNames.ShouldContain(typeof(ChocolateyNugetLogger).FullName); + MockLogger.Messages.Keys.ShouldContain(loggerName); + MockLogger.Messages[loggerName].ShouldContain(expectedMessage); + } + + [TestCase(NuGetLogLevel.Debug, LogLevel.Debug, "Test debug message", "[NuGet] Test debug message")] + [TestCase(NuGetLogLevel.Error, LogLevel.Error, "Test error message", "[NuGet] Test error message")] + [TestCase(NuGetLogLevel.Minimal, LogLevel.Info, "Test informational message", "[NuGet] Test informational message")] + [TestCase(NuGetLogLevel.Warning, LogLevel.Warn, "Test warning message", "[NuGet] Test warning message")] + public void should_log_expected_log_level_when_calling_Log_with_log_message(NuGetLogLevel nugetLogLevel, LogLevel logLevel, string testMessage, string expectedMessage) + { + _logger.Log(new LogMessage(nugetLogLevel, testMessage)); + MockLogger.LoggerNames.Count.ShouldEqual(1); + MockLogger.LoggerNames.ShouldContain(typeof(ChocolateyNugetLogger).FullName); + MockLogger.Messages.Keys.ShouldContain(logLevel.to_string()); + MockLogger.Messages[logLevel.to_string()].ShouldContain(expectedMessage); + } + + [TestCase(NuGetLogLevel.Debug, LogLevel.Debug, "Test debug message", "[NuGet] Test debug message")] + [TestCase(NuGetLogLevel.Error, LogLevel.Error, "Test error message", "[NuGet] Test error message")] + [TestCase(NuGetLogLevel.Minimal, LogLevel.Info, "Test informational message", "[NuGet] Test informational message")] + [TestCase(NuGetLogLevel.Warning, LogLevel.Warn, "Test warning message", "[NuGet] Test warning message")] + public void should_log_expected_log_level_when_calling_Log_with_nuget_log_level(NuGetLogLevel nugetLogLevel, LogLevel logLevel, string testMessage, string expectedMessage) + { + _logger.Log(nugetLogLevel, testMessage); + MockLogger.LoggerNames.Count.ShouldEqual(1); + MockLogger.LoggerNames.ShouldContain(typeof(ChocolateyNugetLogger).FullName); + MockLogger.Messages.Keys.ShouldContain(logLevel.to_string()); + MockLogger.Messages[logLevel.to_string()].ShouldContain(expectedMessage); + } + + [TestCase(NuGetLogLevel.Debug, LogLevel.Debug, "Test debug message", "[NuGet] Test debug message")] + [TestCase(NuGetLogLevel.Error, LogLevel.Error, "Test error message", "[NuGet] Test error message")] + [TestCase(NuGetLogLevel.Minimal, LogLevel.Info, "Test informational message", "[NuGet] Test informational message")] + [TestCase(NuGetLogLevel.Warning, LogLevel.Warn, "Test warning message", "[NuGet] Test warning message")] + public async Task should_log_expected_log_level_when_calling_LogAsync_with_nuget_log_level(NuGetLogLevel nugetLogLevel, LogLevel logLevel, string testMessage, string expectedMessage) + { + await _logger.LogAsync(nugetLogLevel, testMessage); + MockLogger.LoggerNames.Count.ShouldEqual(1); + MockLogger.LoggerNames.ShouldContain(typeof(ChocolateyNugetLogger).FullName); + MockLogger.Messages.Keys.ShouldContain(logLevel.to_string()); + MockLogger.Messages[logLevel.to_string()].ShouldContain(expectedMessage); + } + + [TestCase(NuGetLogLevel.Debug, LogLevel.Debug, "Test debug message", "[NuGet] Test debug message")] + [TestCase(NuGetLogLevel.Error, LogLevel.Error, "Test error message", "[NuGet] Test error message")] + [TestCase(NuGetLogLevel.Minimal, LogLevel.Info, "Test informational message", "[NuGet] Test informational message")] + [TestCase(NuGetLogLevel.Warning, LogLevel.Warn, "Test warning message", "[NuGet] Test warning message")] + public async Task should_log_expected_log_level_when_calling_LogAsync_with_nuget_log_message(NuGetLogLevel nugetLogLevel, LogLevel logLevel, string testMessage, string expectedMessage) + { + await _logger.LogAsync(new LogMessage(nugetLogLevel, testMessage)); + MockLogger.LoggerNames.Count.ShouldEqual(1); + MockLogger.LoggerNames.ShouldContain(typeof(ChocolateyNugetLogger).FullName); + MockLogger.Messages.Keys.ShouldContain(logLevel.to_string()); + MockLogger.Messages[logLevel.to_string()].ShouldContain(expectedMessage); + } + + [Fact] + public void should_log_info_level_with_nuget_prefix_on_all_lines_when_calling_LogInformationSummary() + { + const string testMessage = "This should be a error message.\r\nThis is the second line after CRLF line ending.\nThis is the third line after LF line ending."; + var expectedMessage = "[NuGet] This should be a error message.{0}[NuGet] This is the second line after CRLF line ending.{0}[NuGet] This is the third line after LF line ending.".format_with(Environment.NewLine); + + _logger.LogInformationSummary(testMessage); + + var loggerName = LogLevel.Info.to_string(); + MockLogger.LoggerNames.Count.ShouldEqual(1); + MockLogger.LoggerNames.ShouldContain(typeof(ChocolateyNugetLogger).FullName); + MockLogger.Messages.Keys.ShouldContain(loggerName); + MockLogger.Messages[loggerName].ShouldContain(expectedMessage); + } + + [Fact] + public void should_log_info_level_with_nuget_prefix_when_calling_LogInformationSummary() + { + const string testMessage = "This should be a informational message"; + const string expectedMessage = "[NuGet] " + testMessage; + + _logger.LogInformationSummary(testMessage); + + var loggerName = LogLevel.Info.to_string(); + MockLogger.LoggerNames.Count.ShouldEqual(1); + MockLogger.LoggerNames.ShouldContain(typeof(ChocolateyNugetLogger).FullName); + MockLogger.Messages.Keys.ShouldContain(loggerName); + MockLogger.Messages[loggerName].ShouldContain(expectedMessage); + } + + [TestCase(NuGetLogLevel.Verbose, "Test verbose message", "[NuGet] Test verbose message")] + [TestCase(NuGetLogLevel.Information, "Test informational verbose message", "[NuGet] Test informational verbose message")] + public void should_log_verbose_level_when_calling_Log_with_nuget_log_level(NuGetLogLevel nuGetLogLevel, string testMessage, string expectedMessage) + { + _logger.Log(nuGetLogLevel, testMessage); + MockLogger.LoggerNames.Count.ShouldEqual(2); + MockLogger.LoggerNames.ShouldContain("Verbose"); + MockLogger.Messages.Keys.ShouldContain("Info"); + MockLogger.Messages["Info"].ShouldContain(expectedMessage); + } + + [TestCase(NuGetLogLevel.Verbose, "Test verbose message", "[NuGet] Test verbose message")] + [TestCase(NuGetLogLevel.Information, "Test informational verbose message", "[NuGet] Test informational verbose message")] + public void should_log_verbose_level_when_calling_Log_with_nuget_log_message(NuGetLogLevel nuGetLogLevel, string testMessage, string expectedMessage) + { + _logger.Log(new LogMessage(nuGetLogLevel, testMessage)); + MockLogger.LoggerNames.Count.ShouldEqual(2); + MockLogger.LoggerNames.ShouldContain("Verbose"); + MockLogger.Messages.Keys.ShouldContain("Info"); + MockLogger.Messages["Info"].ShouldContain(expectedMessage); + } + + [TestCase(NuGetLogLevel.Verbose, "Test verbose message", "[NuGet] Test verbose message")] + [TestCase(NuGetLogLevel.Information, "Test informational verbose message", "[NuGet] Test informational verbose message")] + public async Task should_log_verbose_level_when_calling_LogAsync_with_nuget_log_level(NuGetLogLevel nuGetLogLevel, string testMessage, string expectedMessage) + { + await _logger.LogAsync(nuGetLogLevel, testMessage); + MockLogger.LoggerNames.Count.ShouldEqual(2); + MockLogger.LoggerNames.ShouldContain("Verbose"); + MockLogger.Messages.Keys.ShouldContain("Info"); + MockLogger.Messages["Info"].ShouldContain(expectedMessage); + } + + [TestCase(NuGetLogLevel.Verbose, "Test verbose message", "[NuGet] Test verbose message")] + [TestCase(NuGetLogLevel.Information, "Test informational verbose message", "[NuGet] Test informational verbose message")] + public async Task should_log_verbose_level_when_calling_LogAsync_with_nuget_log_message(NuGetLogLevel nuGetLogLevel, string testMessage, string expectedMessage) + { + await _logger.LogAsync(new LogMessage(nuGetLogLevel, testMessage)); + MockLogger.LoggerNames.Count.ShouldEqual(2); + MockLogger.LoggerNames.ShouldContain("Verbose"); + MockLogger.Messages.Keys.ShouldContain("Info"); + MockLogger.Messages["Info"].ShouldContain(expectedMessage); + } + + [Fact] + public void should_log_verbose_level_with_nuget_prefix_on_all_lines_when_calling_LogInformation() + { + const string testMessage = "This should be a informational verbose message.\r\nThis is the second line after CRLF line ending.\nThis is the third line after LF line ending."; + var expectedMessage = "[NuGet] This should be a informational verbose message.{0}[NuGet] This is the second line after CRLF line ending.{0}[NuGet] This is the third line after LF line ending.".format_with(Environment.NewLine); + + _logger.LogInformation(testMessage); + + var loggerName = LogLevel.Info.to_string(); + MockLogger.LoggerNames.Count.ShouldEqual(2); + MockLogger.LoggerNames.ShouldContain("Verbose"); + MockLogger.Messages.Keys.ShouldContain(loggerName); + MockLogger.Messages[loggerName].ShouldContain(expectedMessage); + } + + [Fact] + public void should_log_verbose_level_with_nuget_prefix_on_all_lines_when_calling_LogMinimal() + { + const string testMessage = "This should be a error message.\r\nThis is the second line after CRLF line ending.\nThis is the third line after LF line ending."; + var expectedMessage = "[NuGet] This should be a error message.{0}[NuGet] This is the second line after CRLF line ending.{0}[NuGet] This is the third line after LF line ending.".format_with(Environment.NewLine); + + _logger.LogMinimal(testMessage); + + var loggerName = LogLevel.Info.to_string(); + MockLogger.LoggerNames.Count.ShouldEqual(2); + MockLogger.LoggerNames.ShouldContain("Verbose"); + MockLogger.Messages.Keys.ShouldContain(loggerName); + MockLogger.Messages[loggerName].ShouldContain(expectedMessage); + } + + [Fact] + public void should_log_verbose_level_with_nuget_prefix_on_all_lines_when_calling_LogVerbose() + { + const string testMessage = "This should be a verbose message.\r\nThis is the second line after CRLF line ending.\nThis is the third line after LF line ending."; + var expectedMessage = "[NuGet] This should be a verbose message.{0}[NuGet] This is the second line after CRLF line ending.{0}[NuGet] This is the third line after LF line ending.".format_with(Environment.NewLine); + + _logger.LogVerbose(testMessage); + + var loggerName = LogLevel.Info.to_string(); + MockLogger.LoggerNames.Count.ShouldEqual(2); + MockLogger.LoggerNames.ShouldContain("Verbose"); + MockLogger.Messages.Keys.ShouldContain(loggerName); + MockLogger.Messages[loggerName].ShouldContain(expectedMessage); + } + + [Fact] + public void should_log_verbose_level_with_nuget_prefix_when_calling_LogInformation() + { + const string testMessage = "This should be a informational verbose message"; + const string expectedMessage = "[NuGet] " + testMessage; + + _logger.LogInformation(testMessage); + + var loggerName = LogLevel.Info.to_string(); + MockLogger.LoggerNames.Count.ShouldEqual(2); + MockLogger.LoggerNames.ShouldContain("Verbose"); + MockLogger.Messages.Keys.ShouldContain(loggerName); + MockLogger.Messages[loggerName].ShouldContain(expectedMessage); + } + + [Fact] + public void should_log_verbose_level_with_nuget_prefix_when_calling_LogMinimal() + { + const string testMessage = "This should be a informational message"; + const string expectedMessage = "[NuGet] " + testMessage; + + _logger.LogMinimal(testMessage); + + var loggerName = LogLevel.Info.to_string(); + MockLogger.LoggerNames.Count.ShouldEqual(2); + MockLogger.LoggerNames.ShouldContain("Verbose"); + MockLogger.Messages.Keys.ShouldContain(loggerName); + MockLogger.Messages[loggerName].ShouldContain(expectedMessage); + } + + [Fact] + public void should_log_verbose_level_with_nuget_prefix_when_calling_LogVerbose() + { + const string testMessage = "This should be a verbose message"; + const string expectedMessage = "[NuGet] " + testMessage; + + _logger.LogVerbose(testMessage); + + var loggerName = LogLevel.Info.to_string(); + MockLogger.LoggerNames.Count.ShouldEqual(2); + MockLogger.LoggerNames.ShouldContain("Verbose"); + MockLogger.Messages.Keys.ShouldContain(loggerName); + MockLogger.Messages[loggerName].ShouldContain(expectedMessage); + } + + [Fact] + public void should_log_warn_level_with_nuget_prefix_on_all_lines_when_calling_LogWarning() + { + const string testMessage = "This should be a warning message.\r\nThis is the second line after CRLF line ending.\nThis is the third line after LF line ending."; + var expectedMessage = "[NuGet] This should be a warning message.{0}[NuGet] This is the second line after CRLF line ending.{0}[NuGet] This is the third line after LF line ending.".format_with(Environment.NewLine); + + _logger.LogWarning(testMessage); + + var loggerName = LogLevel.Warn.to_string(); + MockLogger.LoggerNames.Count.ShouldEqual(1); + MockLogger.LoggerNames.ShouldContain(typeof(ChocolateyNugetLogger).FullName); + MockLogger.Messages.Keys.ShouldContain(loggerName); + MockLogger.Messages[loggerName].ShouldContain(expectedMessage); + } + + [Fact] + public void should_log_warn_level_with_nuget_prefix_when_calling_LogWarning() + { + const string testMessage = "This should be a warning message"; + const string expectedMessage = "[NuGet] " + testMessage; + + _logger.LogWarning(testMessage); + + var loggerName = LogLevel.Warn.to_string(); + MockLogger.LoggerNames.Count.ShouldEqual(1); + MockLogger.LoggerNames.ShouldContain(typeof(ChocolateyNugetLogger).FullName); + MockLogger.Messages.Keys.ShouldContain(loggerName); + MockLogger.Messages[loggerName].ShouldContain(expectedMessage); + } + + [TestCase("")] + [TestCase(" ")] + public void should_not_output_whitespace_only_line_in_multiline_logging(string testType) + { + var testValue = "I will be containing\n{0}\nsome whitespace".format_with(testType); + var expectedValue = "[NuGet] I will be containing{0}[NuGet]{0}[NuGet] some whitespace".format_with(Environment.NewLine); + + _logger.Log(NuGetLogLevel.Minimal, testValue); + MockLogger.Messages.Keys.ShouldContain("Info"); + MockLogger.Messages["Info"].ShouldContain(expectedValue); + } + + [TestCase(null)] + [TestCase("")] + [TestCase(" ")] + public void should_only_output_prefix_for_null_or_empty_values(string testValue) + { + _logger.Log(NuGetLogLevel.Minimal, testValue); + + MockLogger.Messages.Keys.ShouldContain("Info"); + MockLogger.Messages["Info"].ShouldContain("[NuGet]"); + } + + [TestCase("\n\n\n\n\n")] + [TestCase("\r\n\r\n\r\n\r\n\r\n")] + public void should_only_output_prefixes_on_every_line(string testValue) + { + var expectedValue = "[NuGet]{0}[NuGet]{0}[NuGet]{0}[NuGet]{0}[NuGet]".format_with(Environment.NewLine); + + _logger.Log(NuGetLogLevel.Information, testValue); + MockLogger.Messages.Keys.ShouldContain("Info"); + MockLogger.Messages["Info"].ShouldContain(expectedValue); + } + } + } +} diff --git a/src/chocolatey.tests/packages.config b/src/chocolatey.tests/packages.config index 7eda096783..30e7907527 100644 --- a/src/chocolatey.tests/packages.config +++ b/src/chocolatey.tests/packages.config @@ -1,12 +1,20 @@  + + + + + + + + diff --git a/src/chocolatey/infrastructure.app/nuget/ChocolateyNuGetProjectContext.cs b/src/chocolatey/infrastructure.app/nuget/ChocolateyNuGetProjectContext.cs index b69cdef48f..b50e293d6c 100644 --- a/src/chocolatey/infrastructure.app/nuget/ChocolateyNuGetProjectContext.cs +++ b/src/chocolatey/infrastructure.app/nuget/ChocolateyNuGetProjectContext.cs @@ -17,6 +17,8 @@ namespace chocolatey.infrastructure.app.nuget public class ChocolateyNuGetProjectContext : INuGetProjectContext { + private readonly ILogger _logger; + public ChocolateyNuGetProjectContext(ChocolateyConfiguration config, ILogger logger) { //TODO, set client policy correctly here with settings, fix in chocolatey implementation of ISettings for this purpose @@ -28,6 +30,7 @@ public ChocolateyNuGetProjectContext(ChocolateyConfiguration config, ILogger log clientPolicyContext, logger ); + _logger = logger; } private PackageExtractionContext _extractionContext; @@ -37,78 +40,38 @@ public void Log(MessageLevel level, string message, params object[] args) switch (level) { case MessageLevel.Debug: - this.Log().Debug("[NuGet] " + message, args); + _logger.LogDebug(message.format_with(args)); break; case MessageLevel.Info: - this.Log().Info("[NuGet] " + message, args); + _logger.LogInformation(message.format_with(args)); break; case MessageLevel.Warning: - this.Log().Warn("[NuGet] " + message, args); + _logger.LogWarning(message.format_with(args)); break; case MessageLevel.Error: - this.Log().Error("[NuGet] " + message, args); + _logger.LogError(message.format_with(args)); break; } } public void Log(ILogMessage message) { - switch (message.Level) - { - case LogLevel.Debug: - this.Log().Debug("[NuGet] " + message.Message); - break; - case LogLevel.Warning: - this.Log().Warn("[NuGet] " + message.Message); - break; - case LogLevel.Error: - this.Log().Error("[NuGet] " + message.Message); - break; - case LogLevel.Verbose: - this.Log().Info(ChocolateyLoggers.Verbose, "[NuGet] " + message.Message); - break; - case LogLevel.Information: - this.Log().Info(ChocolateyLoggers.Verbose, "[NuGet] " + message.Message); - break; - case LogLevel.Minimal: - this.Log().Info("[NuGet] " + message.Message); - break; - } + _logger.Log(message); } public void ReportError(string message) { - this.Log().Error("[NuGet] " + message); + _logger.LogError(message); } public void ReportError(ILogMessage message) { - switch (message.Level) - { - case LogLevel.Debug: - this.Log().Debug("[NuGet] " + message.Message); - break; - case LogLevel.Warning: - this.Log().Warn("[NuGet] " + message.Message); - break; - case LogLevel.Error: - this.Log().Error("[NuGet] " + message.Message); - break; - case LogLevel.Verbose: - this.Log().Info(ChocolateyLoggers.Verbose, "[NuGet] " + message.Message); - break; - case LogLevel.Information: - this.Log().Info(ChocolateyLoggers.Verbose, "[NuGet] " + message.Message); - break; - case LogLevel.Minimal: - this.Log().Info("[NuGet] " + message.Message); - break; - } + _logger.Log(message); } public FileConflictAction ResolveFileConflict(string message) { - this.Log().Warn("[NuGet] File conflict, overwriting all: " + message); + _logger.LogWarning("File conflict, overwriting all: {0}".format_with(message)); return FileConflictAction.OverwriteAll; } diff --git a/src/chocolatey/infrastructure.app/nuget/ChocolateyNugetLogger.cs b/src/chocolatey/infrastructure.app/nuget/ChocolateyNugetLogger.cs index 20352df206..6c5c17033c 100644 --- a/src/chocolatey/infrastructure.app/nuget/ChocolateyNugetLogger.cs +++ b/src/chocolatey/infrastructure.app/nuget/ChocolateyNugetLogger.cs @@ -1,4 +1,4 @@ -// Copyright © 2017 - 2021 Chocolatey Software, Inc +// Copyright © 2017 - 2022 Chocolatey Software, Inc // Copyright © 2011 - 2017 RealDimensions Software, LLC // // Licensed under the Apache License, Version 2.0 (the "License"); @@ -16,6 +16,9 @@ namespace chocolatey.infrastructure.app.nuget { + using System; + using System.IO; + using System.Text; using System.Threading.Tasks; using logging; using NuGet.Common; @@ -26,140 +29,129 @@ public sealed class ChocolateyNugetLogger : ILogger { public void LogDebug(string message) { - this.Log().Debug("[NuGet] " + message); + Log(LogLevel.Debug, message); } public void LogVerbose(string message) { - this.Log().Info(ChocolateyLoggers.Verbose, "[NuGet] " + message); + Log(LogLevel.Verbose, message); } public void LogWarning(string message) { - this.Log().Warn("[NuGet] " + message); + Log(LogLevel.Warning, message); } public void LogError(string message) { - this.Log().Error("[NuGet] " + message); + Log(LogLevel.Error, message); } public void LogMinimal(string message) { - this.Log().Info( "[NuGet] " + message); + // We log this as informational as we do not want + // the output being shown to the user by default. + // This includes information such as the time taken + // to resolve dependencies, where the package was added + // and so on. + Log(LogLevel.Information, message); } public void LogInformation(string message) { - this.Log().Info("[NuGet] " + message); + // We log this as informational as we do not want + // the output being shown to the user by default. + // This includes information such as the time taken + // to resolve dependencies, where the package was added + // and so on. + Log(LogLevel.Information, message); } public void LogInformationSummary(string message) { - this.Log().Info("[NuGet] " + message); + // We log it as minimal as we want the output to + // be shown as an informational message in this case. + Log(LogLevel.Minimal, message); } public void Log(LogLevel level, string message) { + var prefixedMessage = prefix_all_lines("[NuGet]", message); + switch (level) { case LogLevel.Debug: - this.Log().Debug("[NuGet] " + message); + this.Log().Debug(prefixedMessage); break; case LogLevel.Warning: - this.Log().Warn("[NuGet] " + message); + this.Log().Warn(prefixedMessage); break; case LogLevel.Error: - this.Log().Error("[NuGet] " + message); + this.Log().Error(prefixedMessage); break; case LogLevel.Verbose: - this.Log().Info(ChocolateyLoggers.Verbose, "[NuGet] " + message); + this.Log().Info(ChocolateyLoggers.Verbose, prefixedMessage); break; case LogLevel.Information: - this.Log().Info(ChocolateyLoggers.Verbose, "[NuGet] " + message); + this.Log().Info(ChocolateyLoggers.Verbose, prefixedMessage); break; case LogLevel.Minimal: - this.Log().Info("[NuGet] " + message); + this.Log().Info(prefixedMessage); break; + + default: + throw new ArgumentOutOfRangeException(nameof(level)); } } public Task LogAsync(LogLevel level, string message) { - switch (level) - { - case LogLevel.Debug: - this.Log().Debug("[NuGet] " + message); - break; - case LogLevel.Warning: - this.Log().Warn("[NuGet] " + message); - break; - case LogLevel.Error: - this.Log().Error("[NuGet] " + message); - break; - case LogLevel.Verbose: - this.Log().Info(ChocolateyLoggers.Verbose, "[NuGet] " + message); - break; - case LogLevel.Information: - this.Log().Info(ChocolateyLoggers.Verbose, "[NuGet] " + message); - break; - case LogLevel.Minimal: - this.Log().Info("[NuGet] " + message); - break; - } + Log(level, message); return Task.CompletedTask; } public void Log(ILogMessage log) { - switch (log.Level) - { - case LogLevel.Debug: - this.Log().Debug("[NuGet] " + log.Message); - break; - case LogLevel.Warning: - this.Log().Warn("[NuGet] " + log.Message); - break; - case LogLevel.Error: - this.Log().Error("[NuGet] " + log.Message); - break; - case LogLevel.Verbose: - this.Log().Info(ChocolateyLoggers.Verbose, "[NuGet] " + log.Message); - break; - case LogLevel.Information: - this.Log().Info(ChocolateyLoggers.Verbose, "[NuGet] " + log.Message); - break; - case LogLevel.Minimal: - this.Log().Info("[NuGet] " + log.Message); - break; - } + Log(log.Level, log.Message); } public Task LogAsync(ILogMessage log) { - switch (log.Level) + return LogAsync(log.Level, log.Message); + } + + private static string prefix_all_lines(string prefix, string message) + { + if (message == null || (string.IsNullOrWhiteSpace(message) && message.IndexOf('\n') < 0)) { - case LogLevel.Debug: - this.Log().Debug("[NuGet] " + log.Message); - break; - case LogLevel.Warning: - this.Log().Warn("[NuGet] " + log.Message); - break; - case LogLevel.Error: - this.Log().Error("[NuGet] " + log.Message); - break; - case LogLevel.Verbose: - this.Log().Info(ChocolateyLoggers.Verbose, "[NuGet] " + log.Message); - break; - case LogLevel.Information: - this.Log().Info(ChocolateyLoggers.Verbose, "[NuGet] " + log.Message); - break; - case LogLevel.Minimal: - this.Log().Info("[NuGet] " + log.Message); - break; + return prefix; } - return Task.CompletedTask; + else if (message.IndexOf('\n') < 0) + { + return "{0} {1}".format_with(prefix, message); + } + + var builder = new StringBuilder(message.Length); + using (var reader = new StringReader(message)) + { + string line; + while ((line = reader.ReadLine()) != null) + { + builder.Append(prefix); + + if (!string.IsNullOrWhiteSpace(line)) + { + builder.Append(' ').Append(line); + } + + builder.AppendLine(); + } + } + + // We specify the length we want, to ensure that we doesn't add any + // new newlines to the output. + return builder.ToString(0, builder.Length - Environment.NewLine.Length); } }