From 64a1779c6d23df5c4e1082f341a1a5e3cb1e2e94 Mon Sep 17 00:00:00 2001 From: "Harish S. Kulkarni" Date: Sat, 25 Jan 2020 16:49:23 -0800 Subject: [PATCH 1/9] Draft modification to get all channel output to go to test log when running tests --- .../Environment/ConsoleEnvironment.cs | 29 ++++++++--- src/Microsoft.ML.Data/MLContext.cs | 16 ++++-- .../SymSgdClassificationTrainer.cs | 2 + .../SymSGD/SymSGD-CV-breast-cancer-out.txt | 2 + .../SymSGD-TrainTest-breast-cancer-out.txt | 1 + .../BaseTestBaseline.cs | 7 ++- test/Microsoft.ML.TestFramework/TestLogger.cs | 51 +++++++++++++++++++ 7 files changed, 95 insertions(+), 13 deletions(-) create mode 100644 test/Microsoft.ML.TestFramework/TestLogger.cs diff --git a/src/Microsoft.ML.Core/Environment/ConsoleEnvironment.cs b/src/Microsoft.ML.Core/Environment/ConsoleEnvironment.cs index f4fa53d6c6..7204484345 100644 --- a/src/Microsoft.ML.Core/Environment/ConsoleEnvironment.cs +++ b/src/Microsoft.ML.Core/Environment/ConsoleEnvironment.cs @@ -26,6 +26,7 @@ private sealed class ConsoleWriter private readonly ConsoleEnvironment _parent; private readonly TextWriter _out; private readonly TextWriter _err; + private readonly TextWriter _test; private readonly bool _colorOut; private readonly bool _colorErr; @@ -35,7 +36,7 @@ private sealed class ConsoleWriter private const int _maxDots = 50; private int _dots; - public ConsoleWriter(ConsoleEnvironment parent, TextWriter outWriter, TextWriter errWriter) + public ConsoleWriter(ConsoleEnvironment parent, TextWriter outWriter, TextWriter errWriter, TextWriter testWriter = null) { Contracts.AssertValue(parent); Contracts.AssertValue(outWriter); @@ -44,6 +45,7 @@ public ConsoleWriter(ConsoleEnvironment parent, TextWriter outWriter, TextWriter _parent = parent; _out = outWriter; _err = errWriter; + _test = testWriter; _colorOut = outWriter == Console.Out; _colorErr = outWriter == Console.Error; @@ -86,10 +88,19 @@ public void PrintMessage(IMessageSource sender, ChannelMessage msg) string prefix = WriteAndReturnLinePrefix(msg.Sensitivity, wr); var commChannel = sender as PipeBase; if (commChannel?.Verbose == true) + { WriteHeader(wr, commChannel); + if (_test != null) + WriteHeader(_test, commChannel); + } if (msg.Kind == ChannelMessageKind.Warning) + { wr.Write("Warning: "); + _test?.Write("Warning: "); + } _parent.PrintMessageNormalized(wr, msg.Message, true, prefix); + if (_test != null) + _parent.PrintMessageNormalized(_test, msg.Message, true); if (toColor) Console.ResetColor(); } @@ -340,6 +351,9 @@ protected override void Dispose(bool disposing) private volatile ConsoleWriter _consoleWriter; private readonly MessageSensitivity _sensitivityFlags; + // This object is used to write to the test log along with the console if the host process is a test environment + private TextWriter _testWriter; + /// /// Create an ML.NET for local execution, with console feedback. /// @@ -348,10 +362,11 @@ protected override void Dispose(bool disposing) /// Allowed message sensitivity. /// Text writer to print normal messages to. /// Text writer to print error messages to. + /// Optional TextWriter to write messages if the host is a test environment. public ConsoleEnvironment(int? seed = null, bool verbose = false, MessageSensitivity sensitivity = MessageSensitivity.All, - TextWriter outWriter = null, TextWriter errWriter = null) - : this(RandomUtils.Create(seed), verbose, sensitivity, outWriter, errWriter) + TextWriter outWriter = null, TextWriter errWriter = null, TextWriter testWriter = null) + : this(RandomUtils.Create(seed), verbose, sensitivity, outWriter, errWriter, testWriter) { } @@ -364,14 +379,16 @@ public ConsoleEnvironment(int? seed = null, bool verbose = false, /// Allowed message sensitivity. /// Text writer to print normal messages to. /// Text writer to print error messages to. + /// Optional TextWriter to write messages if the host is a test environment. private ConsoleEnvironment(Random rand, bool verbose = false, MessageSensitivity sensitivity = MessageSensitivity.All, - TextWriter outWriter = null, TextWriter errWriter = null) + TextWriter outWriter = null, TextWriter errWriter = null, TextWriter testWriter = null) : base(rand, verbose, nameof(ConsoleEnvironment)) { Contracts.CheckValueOrNull(outWriter); Contracts.CheckValueOrNull(errWriter); - _consoleWriter = new ConsoleWriter(this, outWriter ?? Console.Out, errWriter ?? Console.Error); + _testWriter = testWriter; + _consoleWriter = new ConsoleWriter(this, outWriter ?? Console.Out, errWriter ?? Console.Error, testWriter); _sensitivityFlags = sensitivity; AddListener(PrintMessage); } @@ -444,7 +461,7 @@ public OutputRedirector(ConsoleEnvironment env, TextWriter newOutWriter, TextWri Contracts.AssertValue(newOutWriter); Contracts.AssertValue(newErrWriter); _root = env.Root; - _newConsoleWriter = new ConsoleWriter(_root, newOutWriter, newErrWriter); + _newConsoleWriter = new ConsoleWriter(_root, newOutWriter, newErrWriter, _root._testWriter); _oldConsoleWriter = Interlocked.Exchange(ref _root._consoleWriter, _newConsoleWriter); Contracts.AssertValue(_oldConsoleWriter); } diff --git a/src/Microsoft.ML.Data/MLContext.cs b/src/Microsoft.ML.Data/MLContext.cs index fc30ba9ca2..1a89141018 100644 --- a/src/Microsoft.ML.Data/MLContext.cs +++ b/src/Microsoft.ML.Data/MLContext.cs @@ -3,7 +3,6 @@ // See the LICENSE file in the project root for more information. using System; -using System.Collections.Generic; using Microsoft.ML.Data; using Microsoft.ML.Runtime; @@ -17,7 +16,7 @@ namespace Microsoft.ML public sealed class MLContext : IHostEnvironment { // REVIEW: consider making LocalEnvironment and MLContext the same class instead of encapsulation. - private readonly LocalEnvironment _env; + private readonly IHostEnvironment _env; /// /// Trainers and tasks specific to binary classification problems. @@ -83,6 +82,7 @@ public sealed class MLContext : IHostEnvironment /// Create the ML context. /// /// Seed for MLContext's random number generator. See the remarks for more details. + /// Host environment. /// /// Many operations in ML.NET require randomness, such as /// random data shuffling, random sampling, random parameter initialization, @@ -107,10 +107,16 @@ public sealed class MLContext : IHostEnvironment /// Also ML.NET trainers don't use randomness *after* the training is finished. /// So, the predictions from a loaded model don't depend on the seed value. /// - public MLContext(int? seed = null) + public MLContext(int? seed = null, IHostEnvironment env = null) { - _env = new LocalEnvironment(seed); - _env.AddListener(ProcessMessage); + if (env == null) + { + var localEnv = new LocalEnvironment(seed); + localEnv.AddListener(ProcessMessage); + _env = localEnv; + } + else + _env = env; BinaryClassification = new BinaryClassificationCatalog(_env); MulticlassClassification = new MulticlassClassificationCatalog(_env); diff --git a/src/Microsoft.ML.Mkl.Components/SymSgdClassificationTrainer.cs b/src/Microsoft.ML.Mkl.Components/SymSgdClassificationTrainer.cs index 2bd3335b42..2ce327b9ba 100644 --- a/src/Microsoft.ML.Mkl.Components/SymSgdClassificationTrainer.cs +++ b/src/Microsoft.ML.Mkl.Components/SymSgdClassificationTrainer.cs @@ -809,6 +809,8 @@ private TPredictor TrainCore(IChannel ch, RoleMappedData data, LinearModelParame if (stateGCHandle.IsAllocated) stateGCHandle.Free(); } + + ch.Info($"Bias: {bias}, Weights: [{String.Join(",", weights.DenseValues())}]"); return CreatePredictor(weights, bias); } diff --git a/test/BaselineOutput/Common/SymSGD/SymSGD-CV-breast-cancer-out.txt b/test/BaselineOutput/Common/SymSGD/SymSGD-CV-breast-cancer-out.txt index 9645346379..eeaf404fad 100644 --- a/test/BaselineOutput/Common/SymSGD/SymSGD-CV-breast-cancer-out.txt +++ b/test/BaselineOutput/Common/SymSGD/SymSGD-CV-breast-cancer-out.txt @@ -2,10 +2,12 @@ maml.exe CV tr=SymSGD{nt=1} threads=- norm=No dout=%Output% data=%Data% seed=1 Not adding a normalizer. Data fully loaded into memory. Initial learning rate is tuned to 100.000000 +Bias: -468.3528, Weights: [4.515409,75.74901,22.2914,-10.50209,-28.58107,44.81024,23.8734,13.20304,2.448269] Not training a calibrator because it is not needed. Not adding a normalizer. Data fully loaded into memory. Initial learning rate is tuned to 100.000000 +Bias: -484.2862, Weights: [-12.78704,140.4291,121.9383,37.5274,-129.8139,70.9061,-89.37057,81.64314,-32.32779] Not training a calibrator because it is not needed. Warning: The predictor produced non-finite prediction values on 8 instances during testing. Possible causes: abnormal data or the predictor is numerically unstable. TEST POSITIVE RATIO: 0.3785 (134.0/(134.0+220.0)) diff --git a/test/BaselineOutput/Common/SymSGD/SymSGD-TrainTest-breast-cancer-out.txt b/test/BaselineOutput/Common/SymSGD/SymSGD-TrainTest-breast-cancer-out.txt index d8b6a25d1f..3f95d64019 100644 --- a/test/BaselineOutput/Common/SymSGD/SymSGD-TrainTest-breast-cancer-out.txt +++ b/test/BaselineOutput/Common/SymSGD/SymSGD-TrainTest-breast-cancer-out.txt @@ -2,6 +2,7 @@ maml.exe TrainTest test=%Data% tr=SymSGD{nt=1} norm=No dout=%Output% data=%Data% Not adding a normalizer. Data fully loaded into memory. Initial learning rate is tuned to 100.000000 +Bias: -448.1, Weights: [-0.3852913,49.29393,-3.424153,16.76877,-25.15009,23.68305,-6.658058,13.76585,4.843107] Not training a calibrator because it is not needed. Warning: The predictor produced non-finite prediction values on 16 instances during testing. Possible causes: abnormal data or the predictor is numerically unstable. TEST POSITIVE RATIO: 0.3499 (239.0/(239.0+444.0)) diff --git a/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs b/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs index d0d453a763..9e5b53da61 100644 --- a/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs +++ b/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs @@ -75,6 +75,7 @@ protected BaseTestBaseline(ITestOutputHelper output) : base(output) // The writer to write to test log files. protected StreamWriter LogWriter; + protected TestLogger TestLogger; private protected ConsoleEnvironment _env; protected IHostEnvironment Env => _env; protected MLContext ML; @@ -97,9 +98,11 @@ protected override void Initialize() string logPath = Path.Combine(logDir, FullTestName + LogSuffix); LogWriter = OpenWriter(logPath); - _env = new ConsoleEnvironment(42, outWriter: LogWriter, errWriter: LogWriter) + + TestLogger = new TestLogger(Output); + _env = new ConsoleEnvironment(42, outWriter: LogWriter, errWriter: LogWriter, testWriter:TestLogger) .AddStandardComponents(); - ML = new MLContext(42); + ML = new MLContext(42, _env); ML.AddStandardComponents(); } diff --git a/test/Microsoft.ML.TestFramework/TestLogger.cs b/test/Microsoft.ML.TestFramework/TestLogger.cs new file mode 100644 index 0000000000..ba687919ad --- /dev/null +++ b/test/Microsoft.ML.TestFramework/TestLogger.cs @@ -0,0 +1,51 @@ +using System; +using System.Collections.Generic; +using System.ComponentModel.DataAnnotations; +using System.IO; +using System.Text; +using Xunit.Abstractions; + +namespace Microsoft.ML.TestFramework +{ + public sealed class TestLogger : TextWriter + { + private Encoding _encoding; + private ITestOutputHelper _testOutput; + + public override Encoding Encoding => _encoding; + + public TestLogger(ITestOutputHelper testOutput) + { + _testOutput = testOutput; + _encoding = new UnicodeEncoding(); + } + + public override void Write(char value) + { + _testOutput.WriteLine($"{value}"); + } + + public override void Write(string value) + { + if (value.EndsWith("\r\n")) + value = value.Substring(0, value.Length - 2); + _testOutput.WriteLine(value); + } + + public override void Write(string format, params object[] args) + { + if (format.EndsWith("\r\n")) + format = format.Substring(0, format.Length - 2); + + _testOutput.WriteLine(format, args); + } + + public override void Write(char[] buffer, int index, int count) + { + var span = buffer.AsSpan(index, count); + if ((span[count - 2] == '\r') && (span[count - 1] == '\n')) + span = span.Slice(0, count - 2); + _testOutput.WriteLine(span.ToString()); + } + } +} From da56102c401c83e22bcbd8769f0fc2545be557f0 Mon Sep 17 00:00:00 2001 From: "Harish S. Kulkarni" Date: Sat, 25 Jan 2020 17:58:28 -0800 Subject: [PATCH 2/9] Attempt to fix API compat issue --- src/Microsoft.ML.Data/MLContext.cs | 37 ++++++++++++++----- .../BaseTestBaseline.cs | 2 +- 2 files changed, 28 insertions(+), 11 deletions(-) diff --git a/src/Microsoft.ML.Data/MLContext.cs b/src/Microsoft.ML.Data/MLContext.cs index 1a89141018..a6766b6820 100644 --- a/src/Microsoft.ML.Data/MLContext.cs +++ b/src/Microsoft.ML.Data/MLContext.cs @@ -82,7 +82,6 @@ public sealed class MLContext : IHostEnvironment /// Create the ML context. /// /// Seed for MLContext's random number generator. See the remarks for more details. - /// Host environment. /// /// Many operations in ML.NET require randomness, such as /// random data shuffling, random sampling, random parameter initialization, @@ -107,16 +106,34 @@ public sealed class MLContext : IHostEnvironment /// Also ML.NET trainers don't use randomness *after* the training is finished. /// So, the predictions from a loaded model don't depend on the seed value. /// - public MLContext(int? seed = null, IHostEnvironment env = null) + public MLContext(int? seed = null) + { + var localEnv = new LocalEnvironment(seed); + localEnv.AddListener(ProcessMessage); + _env = localEnv; + + BinaryClassification = new BinaryClassificationCatalog(_env); + MulticlassClassification = new MulticlassClassificationCatalog(_env); + Regression = new RegressionCatalog(_env); + Clustering = new ClusteringCatalog(_env); + Ranking = new RankingCatalog(_env); + AnomalyDetection = new AnomalyDetectionCatalog(_env); + Forecasting = new ForecastingCatalog(_env); + Transforms = new TransformsCatalog(_env); + Model = new ModelOperationsCatalog(_env); + Data = new DataOperationsCatalog(_env); + } + + /// + /// Create the ML context with a specific environment + /// + /// Host environment. + /// Seed for MLContext's random number generator. See the remarks for more details. + /// + /// + public MLContext(IHostEnvironment env, int ? seed = null) { - if (env == null) - { - var localEnv = new LocalEnvironment(seed); - localEnv.AddListener(ProcessMessage); - _env = localEnv; - } - else - _env = env; + _env = env; BinaryClassification = new BinaryClassificationCatalog(_env); MulticlassClassification = new MulticlassClassificationCatalog(_env); diff --git a/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs b/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs index 9e5b53da61..26ba9af25a 100644 --- a/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs +++ b/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs @@ -102,7 +102,7 @@ protected override void Initialize() TestLogger = new TestLogger(Output); _env = new ConsoleEnvironment(42, outWriter: LogWriter, errWriter: LogWriter, testWriter:TestLogger) .AddStandardComponents(); - ML = new MLContext(42, _env); + ML = new MLContext(_env, 42); ML.AddStandardComponents(); } From ff3cc559c2044e6142aa38aef76695874ced6824 Mon Sep 17 00:00:00 2001 From: "Harish S. Kulkarni" Date: Sun, 26 Jan 2020 22:48:36 -0800 Subject: [PATCH 3/9] Reverted changes to MLContext and now using standard logging mechanism --- src/Microsoft.ML.Data/MLContext.cs | 31 +++---------------- .../BaseTestBaseline.cs | 12 +++++-- 2 files changed, 13 insertions(+), 30 deletions(-) diff --git a/src/Microsoft.ML.Data/MLContext.cs b/src/Microsoft.ML.Data/MLContext.cs index a6766b6820..fc30ba9ca2 100644 --- a/src/Microsoft.ML.Data/MLContext.cs +++ b/src/Microsoft.ML.Data/MLContext.cs @@ -3,6 +3,7 @@ // See the LICENSE file in the project root for more information. using System; +using System.Collections.Generic; using Microsoft.ML.Data; using Microsoft.ML.Runtime; @@ -16,7 +17,7 @@ namespace Microsoft.ML public sealed class MLContext : IHostEnvironment { // REVIEW: consider making LocalEnvironment and MLContext the same class instead of encapsulation. - private readonly IHostEnvironment _env; + private readonly LocalEnvironment _env; /// /// Trainers and tasks specific to binary classification problems. @@ -108,32 +109,8 @@ public sealed class MLContext : IHostEnvironment /// public MLContext(int? seed = null) { - var localEnv = new LocalEnvironment(seed); - localEnv.AddListener(ProcessMessage); - _env = localEnv; - - BinaryClassification = new BinaryClassificationCatalog(_env); - MulticlassClassification = new MulticlassClassificationCatalog(_env); - Regression = new RegressionCatalog(_env); - Clustering = new ClusteringCatalog(_env); - Ranking = new RankingCatalog(_env); - AnomalyDetection = new AnomalyDetectionCatalog(_env); - Forecasting = new ForecastingCatalog(_env); - Transforms = new TransformsCatalog(_env); - Model = new ModelOperationsCatalog(_env); - Data = new DataOperationsCatalog(_env); - } - - /// - /// Create the ML context with a specific environment - /// - /// Host environment. - /// Seed for MLContext's random number generator. See the remarks for more details. - /// - /// - public MLContext(IHostEnvironment env, int ? seed = null) - { - _env = env; + _env = new LocalEnvironment(seed); + _env.AddListener(ProcessMessage); BinaryClassification = new BinaryClassificationCatalog(_env); MulticlassClassification = new MulticlassClassificationCatalog(_env); diff --git a/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs b/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs index 26ba9af25a..5c66f50a32 100644 --- a/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs +++ b/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs @@ -74,8 +74,8 @@ protected BaseTestBaseline(ITestOutputHelper output) : base(output) private string _baselineBuildStringDir; // The writer to write to test log files. - protected StreamWriter LogWriter; protected TestLogger TestLogger; + protected StreamWriter LogWriter; private protected ConsoleEnvironment _env; protected IHostEnvironment Env => _env; protected MLContext ML; @@ -100,12 +100,18 @@ protected override void Initialize() LogWriter = OpenWriter(logPath); TestLogger = new TestLogger(Output); - _env = new ConsoleEnvironment(42, outWriter: LogWriter, errWriter: LogWriter, testWriter:TestLogger) + _env = new ConsoleEnvironment(42, outWriter: LogWriter, errWriter: LogWriter, testWriter: TestLogger) .AddStandardComponents(); - ML = new MLContext(_env, 42); + ML = new MLContext(42); + ML.Log += LogTestOutput; ML.AddStandardComponents(); } + private void LogTestOutput(object sender, LoggingEventArgs e) + { + Output.WriteLine(e.Message); + } + // This method is used by subclass to dispose of disposable objects // such as LocalEnvironment. // It is called as a first step in test clean up. From 02b572cf288b27a62adda6d0f1c86dc41c2d43ef Mon Sep 17 00:00:00 2001 From: "Harish S. Kulkarni" Date: Wed, 29 Jan 2020 16:00:38 -0800 Subject: [PATCH 4/9] Fixed span bounds checking --- test/Microsoft.ML.TestFramework/TestLogger.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/Microsoft.ML.TestFramework/TestLogger.cs b/test/Microsoft.ML.TestFramework/TestLogger.cs index ba687919ad..21781e94ad 100644 --- a/test/Microsoft.ML.TestFramework/TestLogger.cs +++ b/test/Microsoft.ML.TestFramework/TestLogger.cs @@ -43,7 +43,7 @@ public override void Write(string format, params object[] args) public override void Write(char[] buffer, int index, int count) { var span = buffer.AsSpan(index, count); - if ((span[count - 2] == '\r') && (span[count - 1] == '\n')) + if ((span.Length >= 2) && (span[count - 2] == '\r') && (span[count - 1] == '\n')) span = span.Slice(0, count - 2); _testOutput.WriteLine(span.ToString()); } From 55c0ef80b48579bc8c15781e6e1d7f1ab84c81f8 Mon Sep 17 00:00:00 2001 From: "Harish S. Kulkarni" Date: Wed, 29 Jan 2020 19:01:55 -0800 Subject: [PATCH 5/9] Added member variables to LoggingEventArgs to control logging --- src/Microsoft.ML.Data/LoggingEventArgs.cs | 24 +++++++++++++++++++ src/Microsoft.ML.Data/MLContext.cs | 4 +--- .../BaseTestBaseline.cs | 3 ++- 3 files changed, 27 insertions(+), 4 deletions(-) diff --git a/src/Microsoft.ML.Data/LoggingEventArgs.cs b/src/Microsoft.ML.Data/LoggingEventArgs.cs index 64468924fe..47882b5723 100644 --- a/src/Microsoft.ML.Data/LoggingEventArgs.cs +++ b/src/Microsoft.ML.Data/LoggingEventArgs.cs @@ -3,6 +3,7 @@ // See the LICENSE file in the project root for more information. using System; +using Microsoft.ML.Runtime; namespace Microsoft.ML { @@ -20,6 +21,29 @@ public LoggingEventArgs(string message) Message = message; } + /// + /// Initializes a new instane of class that includes the kind and source of the message + /// + /// The message being logged + /// The type of message + /// The source of the message + public LoggingEventArgs(string message, ChannelMessageKind kind, string source) + { + Message = message; + Kind = kind; + Source = source; + } + + /// + /// Gets the source component of the event + /// + public string Source { get; } + + /// + /// Gets the type of message + /// + public ChannelMessageKind Kind { get; } + /// /// Gets the message being logged. /// diff --git a/src/Microsoft.ML.Data/MLContext.cs b/src/Microsoft.ML.Data/MLContext.cs index fc30ba9ca2..5969552d53 100644 --- a/src/Microsoft.ML.Data/MLContext.cs +++ b/src/Microsoft.ML.Data/MLContext.cs @@ -131,9 +131,7 @@ private void ProcessMessage(IMessageSource source, ChannelMessage message) if (log == null) return; - var msg = $"[Source={source.FullName}, Kind={message.Kind}] {message.Message}"; - - log(this, new LoggingEventArgs(msg)); + log(this, new LoggingEventArgs(message.Message, message.Kind, source.FullName)); } string IExceptionContext.ContextDescription => _env.ContextDescription; diff --git a/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs b/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs index 5c66f50a32..88b467a2af 100644 --- a/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs +++ b/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs @@ -109,7 +109,8 @@ protected override void Initialize() private void LogTestOutput(object sender, LoggingEventArgs e) { - Output.WriteLine(e.Message); + var msg = $"[Source={e.Source}, Kind={e.Kind}] {e.Message}"; + Output.WriteLine(msg); } // This method is used by subclass to dispose of disposable objects From 5f016923f4c3a8f97e9832402afe24ecd70b7e94 Mon Sep 17 00:00:00 2001 From: "Harish S. Kulkarni" Date: Wed, 29 Jan 2020 20:28:34 -0800 Subject: [PATCH 6/9] Added a separate RawMessage variable to preserve the behavior of the original Message member --- src/Microsoft.ML.Data/LoggingEventArgs.cs | 8 +++++++- test/Microsoft.ML.TestFramework/BaseTestBaseline.cs | 3 +-- 2 files changed, 8 insertions(+), 3 deletions(-) diff --git a/src/Microsoft.ML.Data/LoggingEventArgs.cs b/src/Microsoft.ML.Data/LoggingEventArgs.cs index 47882b5723..302d7853c2 100644 --- a/src/Microsoft.ML.Data/LoggingEventArgs.cs +++ b/src/Microsoft.ML.Data/LoggingEventArgs.cs @@ -29,9 +29,10 @@ public LoggingEventArgs(string message) /// The source of the message public LoggingEventArgs(string message, ChannelMessageKind kind, string source) { - Message = message; + RawMessage = message; Kind = kind; Source = source; + Message = $"[Source={Source}, Kind={Kind}] {RawMessage}"; } /// @@ -48,5 +49,10 @@ public LoggingEventArgs(string message, ChannelMessageKind kind, string source) /// Gets the message being logged. /// public string Message { get; } + + /// + /// Gets the original message that doesn't include the source and kind + /// + public string RawMessage { get; } } } \ No newline at end of file diff --git a/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs b/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs index 88b467a2af..5c66f50a32 100644 --- a/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs +++ b/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs @@ -109,8 +109,7 @@ protected override void Initialize() private void LogTestOutput(object sender, LoggingEventArgs e) { - var msg = $"[Source={e.Source}, Kind={e.Kind}] {e.Message}"; - Output.WriteLine(msg); + Output.WriteLine(e.Message); } // This method is used by subclass to dispose of disposable objects From a9205930b7748093d85e1965ba3fbb18a4ed61ea Mon Sep 17 00:00:00 2001 From: "Harish S. Kulkarni" Date: Thu, 30 Jan 2020 12:48:19 -0800 Subject: [PATCH 7/9] Fixed crash in DnnRetrainTransformer during a netfx run of TensorFlowTransformMNISTLRTrainingTest --- src/Microsoft.ML.Vision/DnnRetrainTransform.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Microsoft.ML.Vision/DnnRetrainTransform.cs b/src/Microsoft.ML.Vision/DnnRetrainTransform.cs index 54715edf73..14cd254c4a 100644 --- a/src/Microsoft.ML.Vision/DnnRetrainTransform.cs +++ b/src/Microsoft.ML.Vision/DnnRetrainTransform.cs @@ -528,7 +528,7 @@ internal DnnRetrainTransformer(IHostEnvironment env, Session session, string[] o _env = env; _session = session; - _modelLocation = modelLocation; + _modelLocation = Path.IsPathRooted(modelLocation) ? modelLocation : Path.Combine(Directory.GetCurrentDirectory(), modelLocation); _isTemporarySavedModel = isTemporarySavedModel; _addBatchDimensionInput = addBatchDimensionInput; _inputs = inputColumnNames; From 6024eef4fc4ef4f1beb216e94ad393f2a23b4356 Mon Sep 17 00:00:00 2001 From: "Harish S. Kulkarni" Date: Thu, 30 Jan 2020 13:51:40 -0800 Subject: [PATCH 8/9] Added RetryFact attribute to UriLoaderTests.can_reload_model --- .../Microsoft.Extensions.ML.Tests.csproj | 1 + test/Microsoft.Extensions.ML.Tests/UriLoaderTests.cs | 3 ++- 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/test/Microsoft.Extensions.ML.Tests/Microsoft.Extensions.ML.Tests.csproj b/test/Microsoft.Extensions.ML.Tests/Microsoft.Extensions.ML.Tests.csproj index 2553a7b6a4..a997ae707b 100644 --- a/test/Microsoft.Extensions.ML.Tests/Microsoft.Extensions.ML.Tests.csproj +++ b/test/Microsoft.Extensions.ML.Tests/Microsoft.Extensions.ML.Tests.csproj @@ -9,6 +9,7 @@ + diff --git a/test/Microsoft.Extensions.ML.Tests/UriLoaderTests.cs b/test/Microsoft.Extensions.ML.Tests/UriLoaderTests.cs index 2d44c51caa..5c1a94643b 100644 --- a/test/Microsoft.Extensions.ML.Tests/UriLoaderTests.cs +++ b/test/Microsoft.Extensions.ML.Tests/UriLoaderTests.cs @@ -10,6 +10,7 @@ using Microsoft.Extensions.Options; using Microsoft.Extensions.Primitives; using Microsoft.ML; +using Microsoft.ML.TestFrameworkCommon.Attributes; using Xunit; namespace Microsoft.Extensions.ML @@ -29,7 +30,7 @@ public void throw_until_started() Assert.Throws(() => loaderUnderTest.GetReloadToken()); } - [Fact] + [RetryFact(MaxRetries = 3)] public void can_reload_model() { var services = new ServiceCollection() From ef0d1dc4d1b065ca216bc374a5ce00a3c935efb9 Mon Sep 17 00:00:00 2001 From: "Harish S. Kulkarni" Date: Fri, 31 Jan 2020 17:35:19 -0800 Subject: [PATCH 9/9] Added attribute to control logging at a per test level --- .../UriLoaderTests.cs | 2 +- .../BaseTestBaseline.cs | 3 ++- .../BaseTestClass.cs | 12 ++++++++++++ .../Attributes/LoggingLevelAttribute.cs | 18 ++++++++++++++++++ 4 files changed, 33 insertions(+), 2 deletions(-) create mode 100644 test/Microsoft.ML.TestFrameworkCommon/Attributes/LoggingLevelAttribute.cs diff --git a/test/Microsoft.Extensions.ML.Tests/UriLoaderTests.cs b/test/Microsoft.Extensions.ML.Tests/UriLoaderTests.cs index 83893965ae..99c9bcf68f 100644 --- a/test/Microsoft.Extensions.ML.Tests/UriLoaderTests.cs +++ b/test/Microsoft.Extensions.ML.Tests/UriLoaderTests.cs @@ -30,7 +30,7 @@ public void throw_until_started() Assert.Throws(() => loaderUnderTest.GetReloadToken()); } - [RetryFact(MaxRetries = 3)] + [Fact] public void can_reload_model() { var services = new ServiceCollection() diff --git a/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs b/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs index 5c66f50a32..8466a39854 100644 --- a/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs +++ b/test/Microsoft.ML.TestFramework/BaseTestBaseline.cs @@ -109,7 +109,8 @@ protected override void Initialize() private void LogTestOutput(object sender, LoggingEventArgs e) { - Output.WriteLine(e.Message); + if (e.Kind >= MessageKindToLog) + Output.WriteLine(e.Message); } // This method is used by subclass to dispose of disposable objects diff --git a/test/Microsoft.ML.TestFramework/BaseTestClass.cs b/test/Microsoft.ML.TestFramework/BaseTestClass.cs index b2ee70ea1e..40a1a01120 100644 --- a/test/Microsoft.ML.TestFramework/BaseTestClass.cs +++ b/test/Microsoft.ML.TestFramework/BaseTestClass.cs @@ -8,7 +8,10 @@ using System.Reflection; using System.Threading; using Microsoft.ML.Internal.Internallearn.Test; +using Microsoft.ML.Runtime; using Microsoft.ML.TestFrameworkCommon; +using Microsoft.ML.TestFrameworkCommon.Attributes; +using Xunit; using Xunit.Abstractions; namespace Microsoft.ML.TestFramework @@ -18,6 +21,8 @@ public class BaseTestClass : IDisposable public string TestName { get; set; } public string FullTestName { get; set; } + public ChannelMessageKind MessageKindToLog; + static BaseTestClass() { AppDomain.CurrentDomain.UnhandledException += (sender, e) => @@ -54,6 +59,13 @@ public BaseTestClass(ITestOutputHelper output) FullTestName = test.TestCase.TestMethod.TestClass.Class.Name + "." + test.TestCase.TestMethod.Method.Name; TestName = test.TestCase.TestMethod.Method.Name; + MessageKindToLog = ChannelMessageKind.Error; + var attributes = test.TestCase.TestMethod.Method.GetCustomAttributes(typeof(LogMessageKind)); + foreach (var attrib in attributes) + { + MessageKindToLog = attrib.GetNamedArgument("MessageKind"); + } + // write to the console when a test starts and stops so we can identify any test hangs/deadlocks in CI Console.WriteLine($"Starting test: {FullTestName}"); Initialize(); diff --git a/test/Microsoft.ML.TestFrameworkCommon/Attributes/LoggingLevelAttribute.cs b/test/Microsoft.ML.TestFrameworkCommon/Attributes/LoggingLevelAttribute.cs new file mode 100644 index 0000000000..54b434d5ad --- /dev/null +++ b/test/Microsoft.ML.TestFrameworkCommon/Attributes/LoggingLevelAttribute.cs @@ -0,0 +1,18 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Text; +using System.Threading.Tasks; +using Microsoft.ML.Runtime; + +namespace Microsoft.ML.TestFrameworkCommon.Attributes +{ + public sealed class LogMessageKind : Attribute + { + public ChannelMessageKind MessageKind { get; } + public LogMessageKind(ChannelMessageKind messageKind) + { + MessageKind = messageKind; + } + } +}